281137 - Add profiling column for functions excluding other functions running

Status: RESOLVED FIXED

(Other Applications Graveyard :: Venkman JS Debugger, enhancement)

Description

[Alex Vincent [:WeirdAl]]

When Venkman profiles an application where function call other functions, it's
impossible to tell how long we spent in the caller function as opposed to the
callee without examining the source code of the caller.  We may not even know
from a profile run which is the caller and which is the callee.

This becomes troublesome when we try to profile a full-size application to
determine which functions are bottlenecks.  There could be a stack of thirty
JavaScript functions or more at any given time.  Thus it is equally troublesome
to determine just how long it takes for the application to execute its JS code.
 (My company is asking me to figure out how much time we spend in JS execution.)

This bug is an RFE to record two timings for each JS function:  one including
calls to other functions, and one excluding them.  Assigning to silver per
#developers, with cc to rginda.

Possibly related to bug 204628, so cc'ing pschwartau as well.

Comment 1

[Alex Vincent [:WeirdAl]]

Attachment: testcase

Testcase steps:
(1) about:config, set dom.max_script_run_time to 1000000 or some other high
value.	(Just in case.)
(2) Open JavaScript Debugger.
(3) Debug > Exclude Browser Files
(4) Profile > Clear Profile Data
(5) Profile > Collect Profile Data checked.
(6) Open Mozilla Navigator window.
(7) Load the testcase.
(8) Click the button labeled "Delay browser for five seconds."	You may get
multiple unresponsive script warnings.	Just click Continue through all of
them; they're irrelevant to the test.
(9) Switch to JavaScript Debugger window, Profile > Collect Profile Data
unchecked.
(10) Profile > Save Profile Data, save as .csv, open in your favorite
spreadsheet program.

Expected results:
Total time column will have in two rows a value over 5000.
A second column will have only one of the two rows with a value over 5000; the
other will be very close to zero.

Actual results:
Total time column will have in two rows a value over 5000.

Comment 2

[James Ross]

Preliminary jsd changes: http://twpol.dyndns.org/temp/jsd_real_time.patch

Comment 3

[James Ross]

Attachment: jsd part of the changes

Comment 4

[James Ross]

Attachment: Venkman part of the changes

Comment 5

[James Ross]

Comment on attachment 173487 [details] [diff] [review]
jsd part of the changes

Ok, ignore the timeout stuff, that's slipped through from a different bug. :)

Comment 6

[Alex Vincent [:WeirdAl]]

A few concerns about these patches:

* jsdebug.h has javadoc-like comments.  Your jsd patch excludes them for the
added functions.

* The UI changes all assume "#define JSD_PROFILE_EXCLUDE_CALLS 1".  If that's
not defined, you may create a ton of strict warnings referring to things like
jsdScript.totalRealExecutionTime being undefined.

* The IDL file changes assume "#define JSD_PROFILE_EXCLUDE_CALLS 1".  I'm still
learning IDL, but if it's not defined, then could we have an exception or for
trying to access the properties the IDL file adds?

* And, of course, the timeout code leakage.

Who should review this?

Comment 7

[James Ross]

(In reply to comment #6)
> A few concerns about these patches:
> 
[snip annoying comments on unfinished code]
> 
> Who should review this?

No-one, currently, because it is only "what I have here". It is not meant to be
considered finished in any way at all, especially WRT comments and the #define(s).

Comment 8

[James Ross]

Ok, so I've sorted out some stuff, and probably want the next version to get
some real review. The big question is, what should this stuff be called?

Currently I'm calling it "minRealExecution" and such, but I'm not sure 'real'
quite conveys what it really is (time spent just in that function, i.e.
excluding time spent in any called functions).

Comment 9

[Robert Ginda]

The perl profiler doesn't have a catchy name, but...

       -E   (default)  Display all subroutine times exclusive of child subrou-
            tine times.

So maybe "exclusive" or a short synonym like "own" or "solo" would be good to
work in there.

Comment 10

[James Ross]

Attachment: Patch v2: jsd part

Comment 11

[James Ross]

Attachment: Patch v2: Venkman part

Comment 12

[James Ross]

Also not I've fixed the 0ms time bug (probably showing up in bug 204628 if
nowhere else), where if a call takes 0ms then the next one overwrites the min
time even if it took longer.

Comment 13

[Robert Ginda]

Comment on attachment 175856 [details] [diff] [review]
Patch v2: Venkman part

r=rginda

Comment 14

[Mike Shaver (:shaver emeritus)]

Comment on attachment 175854 [details] [diff] [review]
Patch v2: jsd part

> struct JSDProfileData
> {
>+    JSDProfileData* caller;
>     int64    lastCallStart;
>+    int64    runningTime;

Pls reindent the struct def'n to maintain purity of whitespace alignment.

>+                        /* If we last returned from a function (as opposed to
>+                         * having last entered this function), we need to inc.
>+                         * the running total by the time delta since the last
>+                         * return, and use the running total instead of the
>+                         * delta calculated above. */
>+                        if (!JSLL_IS_ZERO(jsdc->lastReturnTime))
>+                        {
>+                            // Add last chunk to running time, and use total
>+                            // running time as 'delta'.
>+                            JSLL_SUB(ll_delta, now, jsdc->lastReturnTime);
>+                            pdata->runningTime += ll_delta;
>+                            JSLL_L2D(delta, pdata->runningTime);
>+                            delta /= 1000.0;
>+                        }

Can we rejig this logic such that we don't compute the first delta and then
throw it away, in this case?

>+                        pdata->totalOwnExecutionTime += delta;
>+                        /* See minExecutionTime comment above. */
>+                        if ((0 == pdata->callCount) ||
>+                            delta < pdata->minOwnExecutionTime)
>+                        {
>+                            pdata->minOwnExecutionTime = delta;
>+                        }

That brace wants to be on the previous line, if I read this
file's style correctly.

r=shaver with the nits fixed, and I'd be willing to re-review if you
re-structure
the delta-computation logic to avoid discarding the computation.

Comment 15

[James Ross]

I'm a little confused by the delta comments; the previous delta is used prior to
being replaced. The code does this:

  delta = {time since this function started}
  totalRunTime += delta
  {update min/max run times}
  if { we returned from a nested call during this function }
    delta = {time since that return}
  ownRunTime += delta
  {update own min/max run times}

Should I add/change the comments to make this clearer? (or did I miss it?)

Comment 16

[James Ross]

CCing shaver so he knows about my previous comment. :)

Comment 17

[Mike Shaver (:shaver emeritus)]

No, you're right; I must have missed the earlier use, though it's plainly there
in the diff!  Sorry about that.

Comment 18

[Dan Mosedale (:dmosedale, :dmose)]

Comment on attachment 175856 [details] [diff] [review]
Patch v2: Venkman part

sr=dmose

Comment 19

[Dan Mosedale (:dmosedale, :dmose)]

Comment on attachment 175854 [details] [diff] [review]
Patch v2: jsd part

sr=dmose

Comment 20

[timeless]

Comment on attachment 175854 [details] [diff] [review]
Patch v2: jsd part

mozilla/js/jsd/idl/jsdIDebuggerService.idl	1.32
mozilla/js/jsd/jsdebug.h	3.19
mozilla/js/jsd/jsdebug.c	3.15
mozilla/js/jsd/jsd_xpc.cpp	1.72
mozilla/js/jsd/jsd_step.c	3.13
mozilla/js/jsd/jsd_scpt.c	3.13
mozilla/js/jsd/jsd.h	3.19
mozilla/js/jsd/jsd_step.c	3.14
mozilla/js/jsd/jsd_step.c	3.15

Comment 21

[timeless]

Comment on attachment 175856 [details] [diff] [review]
Patch v2: Venkman part

mozilla/extensions/venkman/resources/locale/en-US/venkman.properties	1.57
mozilla/extensions/venkman/resources/locale/en-US/profile.xml.tpl	1.2
mozilla/extensions/venkman/resources/locale/en-US/profile.txt.tpl	1.2
mozilla/extensions/venkman/resources/locale/en-US/profile.csv.tpl	1.2
mozilla/extensions/venkman/resources/content/venkman-profiler.js	1.7

Comment 22

[Alex Vincent [:WeirdAl]]

Isn't this fixed?  :)

Comment 23

[James Ross]

Belated FIXED.