Timing of functions, not just the count

[Raymond Camden]

I notice that one of the features will tell you how many times a function has been called. Is there any way to get *timings* for functions calls? So for example, imagine a simple process that hits Mongo to get db, then uses http to get something, and then renders a view. I'd like to know how long the call to Mongo took, how long the http call took, and how long it took to render the view. 

[Joel Brandt]

Hey Raymond,

This is an interesting idea (and something we don't currently support -- so the answer to your question is currently "no").

I think there's really (at least) two separate use cases here:

1. Understanding the execution time of a synchronous series of function calls (e.g. how long did it take to compute fibonacci(10) recursively).

2. Understanding how much time is there between the start of an asynchronous operation and the time the callback is called / event is generated that indicates completion.

In the scenario you've outlined, most of the things that take a long time (e.g. querying mongodb) are asynchronous and not implemented in JS. So, the amount of time that _JavaScript_ is executing will likely be very small. It seems to me that the thing you'd care about is "how long was it between when I called out to mongo and when I got the response?"

Do I have that right?

Thanks for your thoughts!

-- Joel

On Wed, Aug 28, 2013 at 3:57 AM, Raymond Camden <raymon...@gmail.com> wrote:

I notice that one of the features will tell you how many times a function has been called. Is there any way to get *timings* for functions calls? So for example, imagine a simple process that hits Mongo to get db, then uses http to get something, and then renders a view. I'd like to know how long the call to Mongo took, how long the http call took, and how long it took to render the view. 

--
You received this message because you are subscribed to the Google Groups "Theseus Discuss" group.
To unsubscribe from this group and stop receiving emails from it, send an email to theseus-discu...@googlegroups.com.
For more options, visit https://groups.google.com/groups/opt_out.

[Tom Lieber]

The way to get that information is to click the call counts for the parent and callback functions, then subtract the time the callback was called from the time the parent was called (both times are shown in the log). It's on my to-do list to do that subtraction automatically and show the time difference in the log.

It seems like there's probably something Theseus could show in the source code that summarizes time differences for what appear to be callback functions, but I haven't thought through it yet. Would you mind sharing what you're interested in the duration of mongo calls for specifically?

On Wed, Aug 28, 2013 at 3:57 AM, Raymond Camden <raymon...@gmail.com> wrote:

I notice that one of the features will tell you how many times a function has been called. Is there any way to get *timings* for functions calls? So for example, imagine a simple process that hits Mongo to get db, then uses http to get something, and then renders a view. I'd like to know how long the call to Mongo took, how long the http call took, and how long it took to render the view. 

--

You received this message because you are subscribed to the Google Groups "Theseus Discuss" group.
To unsubscribe from this group and stop receiving emails from it, send an email to theseus-discu...@googlegroups.com.
For more options, visit https://groups.google.com/groups/opt_out.

--
Tom Lieber
http://AllTom.com/
http://infinite-sketchpad.com/

[Raymond Camden]

Hey Joel, Tom, thanks for the feedback. What I'm looking for is something I've used in ColdFusion for some time now. (And yea, I know a J2EE app is somewhat different, but it is a web app, and damnit, I want it to be the same. ;) Given a request, CF can give you a nice report broken down to all the major aspects of that call. You get a nice tabular report with highlights on things that are especially slow.

Imagine you have a request that calls some function to generate data. You call it N times in a request. You notice that the request is taking 2-3 seconds to run so you enable the timing stuff in CF. In the report you can see the function calls along with the arguments passed to it. Imagine our function takes a number argument. You would be able to see that when you called the function with n<10, it ran pretty fast, less then 10ms. But for some reason when n=10, the function took 1000ms. 

Just having that type of data then can lead me to go look at my function and do some tuning where I see how the function behaves based on the arguments passed in.

As for the database layer, there may be certain selects that are performing super slow (I used Mongo above, but I'm really thinking DB calls in general, which tend to be a slow part of web apps). Being able to see that this query ran at X ms could help me figure out which queries need tuning and which don't.

To Joel's specific question, "It seems to me that the thing you'd care about is "how long was it between when I called out to mongo and when I got the response?"", absolutely, yes.

Btw, I can share a screenshot of the CF output if you guys want to get an idea. 

On Wed, Aug 28, 2013 at 9:21 AM, Tom Lieber <t...@alltom.com> wrote:

The way to get that information is to click the call counts for the parent and callback functions, then subtract the time the callback was called from the time the parent was called (both times are shown in the log). It's on my to-do list to do that subtraction automatically and show the time difference in the log.

It seems like there's probably something Theseus could show in the source code that summarizes time differences for what appear to be callback functions, but I haven't thought through it yet. Would you mind sharing what you're interested in the duration of mongo calls for specifically?

On Wed, Aug 28, 2013 at 3:57 AM, Raymond Camden <raymon...@gmail.com> wrote:

I notice that one of the features will tell you how many times a function has been called. Is there any way to get *timings* for functions calls? So for example, imagine a simple process that hits Mongo to get db, then uses http to get something, and then renders a view. I'd like to know how long the call to Mongo took, how long the http call took, and how long it took to render the view. 

--

You received this message because you are subscribed to the Google Groups "Theseus Discuss" group.
To unsubscribe from this group and stop receiving emails from it, send an email to theseus-discu...@googlegroups.com.
For more options, visit https://groups.google.com/groups/opt_out.

--
Tom Lieber
http://AllTom.com/
http://infinite-sketchpad.com/

--
===========================================================================
Raymond Camden, Adobe Developer Evangelist

Email : raymon...@gmail.com
Blog : www.raymondcamden.com
Twitter: cfjedimaster

[Tom Lieber]

Generating a performance report sounds out of scope for Theseus, but like something that would be easy to do with fondue (the instrumentation library Theseus is based on). If you look at the node-theseus source, you can see how easy it is to turn on instrumentation, run some code, then read the data out. This might be something you could prototype in a day, and if you made it, the report would show you exactly the info you want! (When I needed to investigate a bottleneck in my code, I made a janky but functional profiler with fondue in an hour or so.) I can get you started on this if you'd like.

As for being able to eyeball "slow" callbacks as you're skimming code, that's on my list, but probably not coming too soon.

[Raymond Camden]

Sounds fine to me (I mean me building a nice report). But to be clear, you think it is a bit too early now for that, right?

[Tom Lieber]

Yeah, it's like 8am here, I'm barely dressed. But fondue is up to the task, it's API is just under-documented (something I'll fix sooner if there's interest in using it).

[Raymond Camden]

No rush for me I guess. But when it does get a bit easier, I'd love to try something. Again, I think the idea of a red flag ("Hey dude, this one freaking call it taking 90% of your time") could be pretty useful. It is in CF dev.

You received this message because you are subscribed to a topic in the Google Groups "Theseus Discuss" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/theseus-discuss/nyw8eGS6Enk/unsubscribe.
To unsubscribe from this group and all its topics, send an email to theseus-discu...@googlegroups.com.

For more options, visit https://groups.google.com/groups/opt_out.

--