Last Comment Bug 470116 - Component for timing execution of js and others
: Component for timing execution of js and others
Status: NEW
:
Product: Core
Classification: Components
Component: XPCOM (show other bugs)
: unspecified
: x86 Linux
: -- normal with 1 vote (vote)
: ---
Assigned To: (dormant account)
:
Mentors:
Depends on:
Blocks: 459117 463298
  Show dependency treegraph
 
Reported: 2008-12-17 15:04 PST by (dormant account)
Modified: 2010-02-08 10:39 PST (History)
10 users (show)
See Also:
Crash Signature:
(edit)
QA Whiteboard:
Iteration: ---
Points: ---
Has Regression Range: ---
Has STR: ---


Attachments
timing component (15.89 KB, patch)
2008-12-17 15:53 PST, (dormant account)
no flags Details | Diff | Splinter Review
timing component (17.34 KB, patch)
2008-12-17 15:57 PST, (dormant account)
no flags Details | Diff | Splinter Review
timing componentb (18.34 KB, patch)
2009-01-06 11:35 PST, (dormant account)
no flags Details | Diff | Splinter Review
timing component(using tls) (19.15 KB, patch)
2009-01-22 09:38 PST, (dormant account)
no flags Details | Diff | Splinter Review
I found these probes to be useful...esp EndPageLoad (3.02 KB, patch)
2009-01-22 09:39 PST, (dormant account)
no flags Details | Diff | Splinter Review
spidermonkey...tell jsd when a a fastcall is being executed (7.03 KB, patch)
2009-01-22 09:41 PST, (dormant account)
no flags Details | Diff | Splinter Review
script to sum up execution times...for quick log analysis (2.68 KB, patch)
2009-01-22 12:47 PST, (dormant account)
no flags Details | Diff | Splinter Review
latest component diff (19.82 KB, patch)
2009-07-22 11:59 PDT, (dormant account)
no flags Details | Diff | Splinter Review
latest component diff (25.55 KB, patch)
2009-10-02 15:29 PDT, (dormant account)
no flags Details | Diff | Splinter Review

Description (dormant account) 2008-12-17 15:04:46 PST

    
Comment 1 (dormant account) 2008-12-17 15:53:50 PST
Created attachment 353562 [details] [diff] [review]
timing component

This registers early on and starts timing js calls..Any call slower than 1ms is flagged. 
Calls are printed out to console in a "stack" form. This is achieved with a counter(gMeasureDepth) which tracks nesting level(not thread safe). Any suggestions would be appreciated.
Sample output:
496ms     CallHook (anonymous) chrome://browser/content/WidgetStack.js:1177 1.1ms
500ms     CallHook (anonymous) chrome://browser/content/WidgetStack.js:1177 1.3ms
500ms      CallHook (anonymous) chrome://browser/content/WidgetStack.js:1281 1.3ms
500ms     CallHook (anonymous) chrome://browser/content/WidgetStack.js:1177 1.6ms
500ms    CallHook (anonymous) chrome://browser/content/WidgetStack.js:308 6.2ms
500ms   CallHook WidgetStack chrome://browser/content/WidgetStack.js:255 6.2ms
Comment 2 (dormant account) 2008-12-17 15:57:40 PST
Created attachment 353565 [details] [diff] [review]
timing component

missed a file
Comment 3 Curtis Bartley [:cbartley] 2008-12-17 16:06:53 PST
(In reply to comment #1)
> Created an attachment (id=353562) [details]
> timing component
> 
> This registers early on and starts timing js calls..Any call slower than 1ms is
> flagged. 
> Calls are printed out to console in a "stack" form. This is achieved with a
> counter(gMeasureDepth) which tracks nesting level(not thread safe). Any
> suggestions would be appreciated.

Is it possible to just walk the JS stack frames up to the root and count them to compute the stack depth?  I know you can do this from JS so I assume it's possible from C++ as well.  This will be a little bit slower, but it ought to be threadsafe.  Just a thought.
Comment 4 (dormant account) 2008-12-17 16:22:14 PST
i'd rather use tls or something for the counter, since it's handy to be able to place these into C++ code and see when they are called from js
Comment 5 (dormant account) 2009-01-06 11:35:54 PST
Created attachment 355626 [details] [diff] [review]
timing componentb

This version should work pretty well. It still doesn't do TLS, but I haven't had to time stuff across threads yet, so it's ok.
To use set MOZ_STOPWATCH environment variable, when it's not set the component doesn't do anything.
Comment 6 (dormant account) 2009-01-22 09:38:21 PST
Created attachment 358203 [details] [diff] [review]
timing component(using tls)
Comment 7 (dormant account) 2009-01-22 09:39:20 PST
Created attachment 358204 [details] [diff] [review]
I found these probes to be useful...esp EndPageLoad
Comment 8 (dormant account) 2009-01-22 09:41:42 PST
Created attachment 358206 [details] [diff] [review]
spidermonkey...tell jsd when a a fastcall is being executed

This is a little bit of a hack. It enables the timing component to be notified when a fastcall is run. This is useful when there is dom code(which often uses fastcalls) where a dom method is taking up most of the time, but it's unclear which. This made solving the resize issue much easier.
Comment 9 (dormant account) 2009-01-22 12:47:17 PST
Created attachment 358261 [details] [diff] [review]
script to sum up execution times...for quick log analysis

This is another convenience, to use it get a log for something you want to analyze fennec js overhead in, then run the script. This does a frequency count and duration of js function calls.
Comment 10 (dormant account) 2009-07-22 11:59:28 PDT
Created attachment 390036 [details] [diff] [review]
latest component diff

This one logs to per-thread files
Comment 11 (dormant account) 2009-10-02 15:29:05 PDT
Created attachment 404348 [details] [diff] [review]
latest component diff

Note You need to log in before you can comment on or make changes to this bug.