Last Comment Bug 388564 - (jsdtrace) [RFE] JavaScript Tracing Framework
(jsdtrace)
: [RFE] JavaScript Tracing Framework
Status: RESOLVED FIXED
:
Product: Core
Classification: Components
Component: JavaScript Engine (show other bugs)
: unspecified
: Sun Solaris
: P1 normal (vote)
: mozilla1.9beta1
Assigned To: Johnny Stenback (:jst, jst@mozilla.com)
:
: Jason Orendorff [:jorendorff]
Mentors:
Depends on: dtrace 1046224
Blocks:
  Show dependency treegraph
 
Reported: 2007-07-18 05:39 PDT by Padraig O'Briain
Modified: 2014-07-30 09:42 PDT (History)
12 users (show)
bob: in‑testsuite-
bob: in‑litmus-
See Also:
Crash Signature:
(edit)
QA Whiteboard:
Iteration: ---
Points: ---
Has Regression Range: ---
Has STR: ---


Attachments
JavaScript probes v3 (16.31 KB, patch)
2007-07-18 05:51 PDT, Padraig O'Briain
no flags Details | Diff | Splinter Review
JavaScript probes v4 (16.33 KB, patch)
2007-07-24 02:52 PDT, Padraig O'Briain
no flags Details | Diff | Splinter Review
JavaScript probes v5 (18.23 KB, patch)
2007-07-25 07:39 PDT, Padraig O'Briain
no flags Details | Diff | Splinter Review
JavaScript probes v6 (23.29 KB, patch)
2007-08-16 06:19 PDT, Padraig O'Briain
no flags Details | Diff | Splinter Review
JavaScript probes v7 (26.68 KB, patch)
2007-08-20 02:28 PDT, Padraig O'Briain
no flags Details | Diff | Splinter Review
JavaScript probes v8 (26.63 KB, patch)
2007-08-21 03:21 PDT, Padraig O'Briain
no flags Details | Diff | Splinter Review
JavaScript probes v9 (26.85 KB, patch)
2007-08-22 01:27 PDT, Padraig O'Briain
no flags Details | Diff | Splinter Review
JavaScript probes (26.80 KB, patch)
2007-08-24 07:48 PDT, Padraig O'Briain
no flags Details | Diff | Splinter Review
JavaScript Probes v11 (28.41 KB, patch)
2007-08-30 19:25 PDT, John Rice
no flags Details | Diff | Splinter Review
js_timedfuncflow.d (821 bytes, text/plain)
2007-09-01 22:16 PDT, Robert Sayre
no flags Details
JavaScript probes v12 (25.31 KB, patch)
2007-09-04 07:53 PDT, Padraig O'Briain
no flags Details | Diff | Splinter Review
Same as v12, but updated to current trunk. (29.17 KB, patch)
2007-10-02 15:24 PDT, Johnny Stenback (:jst, jst@mozilla.com)
no flags Details | Diff | Splinter Review
v12 + anonymous function name recovery + bogo-null test removal + style nits (29.35 KB, patch)
2007-10-05 13:59 PDT, Brendan Eich [:brendan]
sayrer: review+
Details | Diff | Splinter Review
v12++, for checkin, I hope (29.34 KB, patch)
2007-10-07 22:16 PDT, Brendan Eich [:brendan]
brendan: review+
igor: review+
Details | Diff | Splinter Review
v12+++, for checkin (24.28 KB, patch)
2007-10-15 17:32 PDT, Johnny Stenback (:jst, jst@mozilla.com)
no flags Details | Diff | Splinter Review
283967: v12++++, for checkin (26.71 KB, patch)
2007-10-16 15:19 PDT, Johnny Stenback (:jst, jst@mozilla.com)
ted: review+
ted: approval1.9+
Details | Diff | Splinter Review

Description Padraig O'Briain 2007-07-18 05:39:42 PDT
User-Agent:       Mozilla/5.0 (X11; U; SunOS sun4u; en-US; rv:1.8.1.1) Gecko/20070129 Firefox/2.0.0.1
Build Identifier: Mozilla/5.0 (X11; U; SunOS sun4u; en-US; rv:1.8.1.1) Gecko/20070129 Firefox/2.0.0.1

This is a proposal to implement Dtrace probes for JavaScript.

https://bugzilla.mozilla.org/show_bug.cgi?id=370906

It provides Brendan Gregg's mozilla javascript probes as described at:
http://blogs.sun.com/brendan/entry/dtrace_meets_javascript
And demo'ed at: http://frsun.downloads.edgesuite.net/sun/07C00953/index.html






Reproducible: Always

Steps to Reproduce:
1.
2.
3.
Comment 1 Padraig O'Briain 2007-07-18 05:45:18 PDT
Following is a proposal raised by Brendan Gregg on May 23rd. Hope to get some feedback from
you guys here.

"
The DTrace patches currently provide this,

        trace_mozilla:::layout*
        trace_mozilla:::js_*

we think that this approach is better (of course, your opinion counts as well),

        mozilla:::layout*
        javascript:::*

(we do get fussy over conventions, as it would be nice if different providers
looked similar).

Reasons for each (and you are welcome to point out problems with this):

mozilla:::layout* - "mozilla" won't clash with anything else - use it! We want
to tell customers "this is the mozilla provider", not "this is the mozilla
provider called trace_mozilla". And if other people write their own mozilla
providers for different versions? No problem - so long as they export the same
layout* probes. As a user writing a DTrace script, I should be able to write
stable mozilla::: scripts that run on different mozilla versions, because they
are exporting the same interface.

javascript:::* - because it is the javascript provider, period. What about
opera and other browsers? Since the javascript provider will be stable, they
can export to the exact same namespace with the exact same probes. So long as
the javascript provider exports no mozilla implementation specifics, which I
don't think it does.

The mental connection I had to make, was that entirerly different engines
(mozilla versions, firefox/opera), can export the same stable provider and be
used in parallel on the same system. Sounds a bit frightening, but it works
fine.

Bryan Cantrill just ran the following script with ruby running,

        # dtrace -n 'function-entry { trace(copyinstr(arg0)); }'

and was suprised to see results that looked like javascript. He was running the
old javascript bits, and his probe was matching crazy,

        javascript*:::function-entry
        ruby*:::function-entry

crazy! different implementations, same probename and args. but it emphasised
that this is doable.
"

Comment from Bredndan Gregg on May 31st:

I've attached a patch for the latest version of the JavaScript probes.
The new additions are,

   * the ability to identify anonymous functions (js_function-info)
   * access to function entry arguments (js_function-args)
   * access to function return value (js_function-rval)

I was finding that the JavaScript provider was only helping with about
4 problems out of 10 (still, better than nothing). The improvements that
I added should take that to around 8 out of 10 - so it is now proving to
be really useful.

Anyhow, here are some before and after screenshots,                             

Old,

# ./js_funcflow.d
C TIME                  FILE                     -- FUNC
1 2007 May 31 06:07:13  clock2.html              -> startTime
1 2007 May 31 06:07:13  clock2.html                -> getHours
1 2007 May 31 06:07:13  clock2.html                <- getHours
1 2007 May 31 06:07:13  clocklib.js                -> padLibZero
1 2007 May 31 06:07:13  clocklib.js                <- padLibZero
1 2007 May 31 06:07:13  clock2.html                -> getMinutes
1 2007 May 31 06:07:13  clock2.html                <- getMinutes
1 2007 May 31 06:07:13  clocklib.js                -> padLibZero
1 2007 May 31 06:07:13  clocklib.js                <- padLibZero
1 2007 May 31 06:07:13  clock2.html                -> getSeconds
1 2007 May 31 06:07:13  clock2.html                <- getSeconds
1 2007 May 31 06:07:13  clocklib.js                -> padLibZero
1 2007 May 31 06:07:13  clocklib.js                <- padLibZero
1 2007 May 31 06:07:13  clock2.html                -> getElementById
1 2007 May 31 06:07:13  clock2.html                <- getElementById
1 2007 May 31 06:07:13  clock2.html                -> setTimeout
1 2007 May 31 06:07:13  clock2.html                <- setTimeout
1 2007 May 31 06:07:13  clock2.html              <- startTime
^C

New,

# ./js_argflow.d
C TIME                  FILE                 -- FUNC()
1 2007 May 31 06:07:34  clock2.html           -> startTime()
1 2007 May 31 06:07:34  clock2.html             -> getHours()
1 2007 May 31 06:07:34  clock2.html             <- startTime:9 = 0x80000000
1 2007 May 31 06:07:34  clocklib.js             -> padLibZero(0x6)
1 2007 May 31 06:07:34  clocklib.js             <- padLibZero:3 = 0x955fd70
1 2007 May 31 06:07:34  clock2.html             -> getMinutes()
1 2007 May 31 06:07:34  clock2.html             <- startTime:10 = 0x80000000
1 2007 May 31 06:07:34  clocklib.js             -> padLibZero(0x7)
1 2007 May 31 06:07:34  clocklib.js             <- padLibZero:3 = 0x955fd50
1 2007 May 31 06:07:34  clock2.html             -> getSeconds()
1 2007 May 31 06:07:34  clock2.html             <- startTime:11 = 0x80000000
1 2007 May 31 06:07:34  clocklib.js             -> padLibZero(0x22)
1 2007 May 31 06:07:34  clocklib.js             <- padLibZero:4 = 0x22
1 2007 May 31 06:07:34  clock2.html             -> getElementById()
1 2007 May 31 06:07:34  clock2.html             <- startTime:12 = 0x80000000
1 2007 May 31 06:07:34  clock2.html             -> setTimeout()
1 2007 May 31 06:07:34  clock2.html             <- startTime:13 = 0x80000000
1 2007 May 31 06:07:34  clock2.html           <- startTime:13 = 0x80000000
^C


Old,

# ./js_funccalls.d
Tracing... Hit Ctrl-C to end.
^C
 FILE                             FUNC                                    CALLS
 clock2.html                      getElementById                              1
 clock2.html                      getHours                                    1
 clock2.html                      getMinutes                                  1
 clock2.html                      getSeconds                                  1
 clock2.html                      setTimeout                                  1
 clock2.html                      startTime                                   1
 clocklib.js                      padLibZero                                  3

New,

# ./js_funcinfo.d
Tracing... Hit Ctrl-C to end.
^C
 BASE[FILE:LINE]         FUNCNAME             RUN[FILE:LINE]             CALLS
 clock2.html:7           getElementById       clock2.html:12                 1
 clock2.html:7           getHours             clock2.html:9                  1
 clock2.html:7           getMinutes           clock2.html:10                 1
 clock2.html:7           getSeconds           clock2.html:11                 1
 clock2.html:7           setTimeout           clock2.html:13                 1
 clock2.html:7           startTime            clock2.html:13                 1
 clocklib.js:2           padLibZero           clock2.html:10                 1
 clocklib.js:2           padLibZero           clock2.html:11                 1
 clocklib.js:2           padLibZero           clock2.html:9                  1


To take the provider further (and to solve 10 out of 10 problems), may
require some moderate code changes to libmozjs for the following features,

        * stack traces (perhaps by integrating with jsd)

        * objects as debug strings (more jsd integration?)

And so these may be best for version 3 of this provider - which would be after
the existing JavaScript probes are integrated (assuming that they ever are). I
would also welcome a Mozilla developer who is more familiar with js/src and
js/jsd to take ownership of the JavaScript provider and to build on the work
I've done so far.

Lastly, I am really hoping that we can call these probes "javascript:::*" and
not "trace_mozilla:::js_*" - as this is the "JavaScript" provider. It would
require hand generation of the header files rather than "dtrace -h", so that
the code macros can remain of the style "TRACE_MOZILLA_JS_FUNCTION_ENTRY"
(which is perfectly fine). I think the initial change from "javascript:::*" to
"trace_mozilla:::js_*" was a side effect of changing the macros, but a side
effect that we can avoid by not auto generating mozilla-trace.h.

Comment 2 Padraig O'Briain 2007-07-18 05:51:21 PDT
Created attachment 272776 [details] [diff] [review]
JavaScript probes v3

This is the same patch as JavaScript probes v3 https://bugzilla.mozilla.org/show_bug.cgi?id=370906

It has not addressed Brendan's namespace concerns.
Comment 3 Alfred Peng 2007-07-23 06:32:05 PDT
Brian, could you take some time to take a look at this Javascript patch?
Comment 4 Brian Crowder 2007-07-23 08:47:58 PDT
Alfred:  I will work today on getting an environment set up where I can actually use and test the patch.
Comment 5 Padraig O'Briain 2007-07-24 02:52:12 PDT
Created attachment 273562 [details] [diff] [review]
JavaScript probes v4

This corrects an error in the previous patch for object creation.
Comment 6 Padraig O'Briain 2007-07-25 07:39:29 PDT
Created attachment 273783 [details] [diff] [review]
JavaScript probes v5

This patch creates JavaScript probes with the names desired by Brendan Gregg.

The probes are defined in javascript-trace.d file in js/src directory as there seem to be problems when two Dtrace providers are specified in the same file.
Comment 7 Padraig O'Briain 2007-08-16 06:19:49 PDT
Created attachment 276948 [details] [diff] [review]
JavaScript probes v6

This patch replaces v5. It is updated so that it applies to CVS HEAD as of this morning.
Comment 8 Brian Crowder 2007-08-17 13:18:11 PDT
The patch looks okay overall.  We had talked about changing this label:

+#ifdef INCLUDE_MOZILLA_DTRACE
+out:
+    if (JAVASCRIPT_EXECUTE_DONE_ENABLED())
+        jsdtrace_execute_done(script);
+#endif

to instead be "dtraceout:" or something, to make it look less like spidermonkey code?  Also, a couple of the newly contributed modules seem to lack tri-license headers; can you add these?

I'll keep looking at and playing with this over the next couple days.

I'm also giving Padraig O'Briain ownership of the bug.
Comment 9 Brian Crowder 2007-08-17 13:23:08 PDT
Yesterday, we talked about adding a notion of levels of dtrace functionality.  One thing we considered as a candidate for this was the line-number tracking on opcodes (I don't see that in this patch, it must be a relatively new feature Brendan was demonstrating here yesterday).  I'm just noting the idea here for future reference.
Comment 10 Padraig O'Briain 2007-08-20 02:28:27 PDT
Created attachment 277369 [details] [diff] [review]
JavaScript probes v7

I have changes out: to tracout: as per comment 8 and added license headers to jsdtracef.c and jsdtracef.h.
Comment 11 Brendan Eich [:brendan] 2007-08-20 13:47:25 PDT
Comment on attachment 277369 [details] [diff] [review]
JavaScript probes v7

I didn't review everything, but please fix this and anything like it elsewhere in the patch:

>-            if (!frame.vars)
>+#ifdef INCLUDE_MOZILLA_DTRACE
>+            if (!frame.vars) {
>+                ok = JS_FALSE;
>+                goto dtraceout;
>+            }
>+#else
>+            if (!frame.vars) {
>                 return JS_FALSE;
>+            }
>+#endif

Please do not duplicate code in new #ifdefs. This should look like

            if (!frame.vars) {
#ifdef INCLUDE_MOZILLA_DTRACE
                ok = JS_FALSE;
                goto dtraceout;
#else
                return JS_FALSE;
#endif
            }

If possible, go further and make an unifdef'd out: label that you can use either way. If the only effect is to penalize cycle costs handling rare errors, no worries. The source clutter effects are less than the above.

/be
Comment 12 Padraig O'Briain 2007-08-21 03:21:32 PDT
Created attachment 277521 [details] [diff] [review]
JavaScript probes v8

This patch addresses the issue raied in comment #11.

I have not been able to make an unifdef'd dtraceout: label.
Comment 13 Brian Crowder 2007-08-21 09:20:36 PDT
Would be nice if you can make jst's review tool happy, also:
http://beaufour.dk/jst-review/?patch=277521 , it finds some whitespace nits and so on.  Sorry I didn't show you this earlier (should check it for the other dtrace patch, as well).
Comment 14 Brendan Eich [:brendan] 2007-08-21 10:53:29 PDT
IIRC the jst review simulacrum wants overbracing of single-line then and else clauses, but SpiderMonkey overbraces single-line then and else clauses only if the other clause or the condition is multiline. Comments taking lines count as lines.

/be
Comment 15 Brendan Gregg 2007-08-21 15:49:27 PDT
(In reply to comment #9)
> Yesterday, we talked about adding a notion of levels of dtrace functionality. 
> One thing we considered as a candidate for this was the line-number tracking on
> opcodes (I don't see that in this patch, it must be a relatively new feature
> Brendan was demonstrating here yesterday).  I'm just noting the idea here for
> future reference.

Yes, this is something for us to think about. Please allow me to discuss DTrace overheads, which will be relevant for mozilla performance tracing in general.

DTrace Overheads
----------------

Firstly, in DTrace, all probes are only active when enabled (when one or more people are running DTrace scripts that traces them; when they hit Ctrl-C, the probes are automatically disabled). Optimisations exist to reduce this enabled overhead, such as in-kernel buffering. 

When probes are not enabled (eg, when a regular user is using the browser), dynamic probes add zero overhead (eg, the "pid" and "fbt" DTrace providers, as no CPU instructions are changed), and static probes add a near-zero overhead (such as this JavaScript provider and Mozilla providers). This JavaScript provider uses static probes so that a stable and high level abstraction can be provided.

This "not enabled" overhead is more important, as this is the common case (everyone hits this who is using the browser on Solaris, MacOS, etc).

The not enabled overhead is near-zero for at least two reasons:

   1. "is-enabled" macros (eg, JAVASCRIPT_FUNCTION_RETURN_ENABLED()). These are only true when someone is using the probes, and allow us to run expensive functions such as JS_PCToLineNumber() *only* when a DTrace user has enabled the probes. The actual overhead of performing the is-enabled test is a few register based CPU instructions. The following is for AMD64,

libmozjs.so`js_NewObject+0x18:  xorl   %eax,%eax
libmozjs.so`js_NewObject+0x1a:  nop    
libmozjs.so`js_NewObject+0x1b:  nop    
libmozjs.so`js_NewObject+0x1c:  nop    
libmozjs.so`js_NewObject+0x1d:  testl  %eax,%eax
libmozjs.so`js_NewObject+0x1f:  je     +0x11    <libmozjs.so`js_NewObject+0x32>

The final jump-if-equal will always be true, which skips the DTrace function call and continues with the original code at js_NewObject+0x32. When someone uses DTrace to trace this probe, DTrace dynamically patches the CPU instructions so that the final test will fail, and the DTrace probe is executed.

   2. The actual probes (eg, JAVASCRIPT_FUNCTION_RETURN()) and their related code have been hidden in seperate functions (eg, jsdtrace_function_return()), so that the compiler doesn't optimize for the additional lump of code (which is rarely run) at the expense of the JavaScript engine (which is always run).

So, for the existing proposed providers, there isn't a need for levels of DTrace support (such as debug levels), since the not-enabled probe effect is near-zero, and the enabled probe effect is only paid for the probes that you use in your DTrace scripts; so, effectively, there already are multiple levels of debugging - depending on which probes the end user turns on and off as needed.

...

Recently I added a probe called "line", which I showed to Brian, and it isn't part of the JavaScript probe patch yet. This might be an exception to the rule (the rule being - don't worry about adding probes!).

The line probe fires whenever a JavaScript opcode is processed (DO_OP()), and provides the line number. (It may be better called "op" rather than "line", we have just been using "line" for a similar probe in other providers).

The "line" probe lets you do things such as frequency count JavaScript operation call by filename and line number,

# dtrace -n 'javascript*:::line { @[copyinstr(arg0), arg1] = count(); } END { printa("%60s:%-6d %@8d\n", @); }'
[...]
                  chrome://global/content/bindings/popup.xml:186         528
                chrome://global/content/bindings/toolbar.xml:289         530
                    chrome://browser/content/places/menu.xml:117         592
                    chrome://browser/content/places/menu.xml:107         612
                chrome://global/content/bindings/toolbar.xml:290         636
                  chrome://global/content/bindings/popup.xml:192         643
                  chrome://global/content/bindings/popup.xml:183         704
                  chrome://global/content/bindings/popup.xml:191         717
                chrome://global/content/bindings/general.xml:0           752
                  chrome://global/content/bindings/popup.xml:181        1815
                  chrome://global/content/bindings/popup.xml:182        2552

Ok, in the short interval that I was tracing, line 182 of popup.xml called 2552 JavaScript operations, followed by line 181 at 1815 operations. This is a quick and handy way to trace where time (generally) is spent in JavaScript.

The problem with the line probe is this,

# dtrace -n 'javascript*:::line { @ = count();  } tick-1sec { printa("%@d", @); clear(@); }'
dtrace: description 'javascript*:::line ' matched 3 probes
CPU     ID                    FUNCTION:NAME
  1   2877                       :tick-1sec 90
  1   2877                       :tick-1sec 138683
  1   2877                       :tick-1sec 63430
  1   2877                       :tick-1sec 66582
  1   2877                       :tick-1sec 16243
  1   2877                       :tick-1sec 19732
  1   2877                       :tick-1sec 112812
  1   2877                       :tick-1sec 18778
  1   2877                       :tick-1sec 143686
  1   2877                       :tick-1sec 5945
  1   2877                       :tick-1sec 3668

The above traced how many JavaScript operations per second were called for a very busy AJAX application. We peaked at about 150,000 - which is a lot of events. It would probably be higher if DTrace wasn't runing (Heisenberg).

So, the earlier overheads mentioned (5 register based CPU instructions plus slightly lengthening instruction paths) - multiply that by, say, 200,000 for a worst case of not-enabled overhead.

My 2GHz AMD64 would probably (I'd need to spend quality time with the CPU user manuals + testing to confirm) spend around 0.5 ns per register based instruction (there may be optimisations for multiple sequential nops - so those three nops may be executed as one - I might need more than just the public CPU manuals to confirm that :). So, the worst case 5 instructions multiplied by 200000, gives us an estimated 0.5 ms of CPU time. A worst case hit of 0.05%.

Now that we expect the worst case not-enabled overhead to be measurable, albiet small, it needs more careful consideration. Should we put this line probe in its own debug level? Or is a worst case 0.05% overhead worth the ability to turn on line tracing, such as in the above example? If you know of an app that draws 1 millions ops per second - would 0.25% overhead be worth it?

Since I've already used the line probe to find real performance issues in code - I already feel that these less than 1% overheads are worth it. Of course, it's up to the Mozilla guys.

cheers,

Brendan
Comment 16 Padraig O'Briain 2007-08-22 01:27:37 PDT
Created attachment 277686 [details] [diff] [review]
JavaScript probes v9

Do I need to make changes based on comment #14?

This patch passes jst-review.
Comment 17 Alfred Peng 2007-08-22 04:37:23 PDT
(In reply to comment #16)
The following two pattern seems not so Mozilla style. Should we align the parameters when making a new line?

>+jsdtrace_function_info(JSContext *cx, JSStackFrame *fp, JSStackFrame *dfp,
>+    JSFunction *fun)

>+ probe function__args(char *, char *, char *, int, void *, void *, void *,
>+     void *, void *, void *);

(In reply to comment #15)
> Yes, this is something for us to think about. Please allow me to discuss DTrace
> overheads, which will be relevant for mozilla performance tracing in general.

This is really nice explanation!

> Since I've already used the line probe to find real performance issues in code
> - I already feel that these less than 1% overheads are worth it. Of course,
> it's up to the Mozilla guys.

Any use cases to find the performance issue with line probe could be shared? That could help the Mac/Solaris guys to make the choice.
Comment 18 Padraig O'Briain 2007-08-24 07:48:55 PDT
Created attachment 278056 [details] [diff] [review]
JavaScript probes

Updated patch to apply to CVS HEAD
Comment 19 Robert Sayre 2007-08-28 19:54:31 PDT
Comment on attachment 278056 [details] [diff] [review]
JavaScript probes

This is working great for me, but the function probes are missing a handy instrumentation point in XPConnect:

http://bonsai.mozilla.org/cvsblame.cgi?file=mozilla/js/src/xpconnect/src/xpcwrappedjsclass.cpp&rev=1.104#1457
Comment 20 John Rice 2007-08-30 19:25:22 PDT
Created attachment 279045 [details] [diff] [review]
JavaScript Probes v11

Updated patch to fix bug in patch where not all function entries were being caught
Comment 21 Robert Sayre 2007-09-01 22:16:14 PDT
Created attachment 279296 [details]
js_timedfuncflow.d

The latest tracing patch seems to misreport built-ins such as Array.push and Regex.match. The script I used is attached.

We get expected results with this testcase:

<html>
<script>
function dtraceStart(){}
function dtraceStop(){}

function a(){}
function b(){ a() }
function c(){ b() }

function testCase() {
  a();
  b();
  c();
}

dtraceStart();
testCase();
dtraceStop();
</script>
</html>

DELTA(ns)    FILE                     FUNCTION
938          test2.html               |<- dtraceStart
13572        test2.html               |-> testCase
11235        test2.html               |  -> a
7343         test2.html               |  <- a
7864         test2.html               |  -> b
7275         test2.html               |    -> a
7174         test2.html               |    <- a
7074         test2.html               |  <- b
7514         test2.html               |  -> c
6909         test2.html               |    -> b
6915         test2.html               |      -> a
7028         test2.html               |      <- a
7043         test2.html               |    <- b
6979         test2.html               |  <- c
7069         test2.html               |<- testCase
7551         test2.html               |-> dtraceStop

but not this one:

<html>
<script>
function dtraceStart(){}
function dtraceStop(){}

function testCase() {
  var testArray = ["001.uri", "002.uri", "003.uri", "004.uri"];
  var nums = []; 
  for (var i = 0; i < testArray.length; i++) {
    var match = /^(\d+)\.uri$/.exec(testArray[i]);
    if (!match)
      continue;
    else
      nums.push(match[1]);
  }
}

dtraceStart();
testCase();
dtraceStop();
</script>
</html>

DELTA(ns)    FILE                     FUNCTION
1061         test.html                |<- dtraceStart
13929        test.html                |-> testCase
100422       test.html                |  -> exec
23263        test.html                |    -> push
10050        test.html                |      -> exec
14839        test.html                |        -> push
8687         test.html                |          -> exec
14261        test.html                |            -> push
9086         test.html                |              -> exec
14434        test.html                |                -> push
9249         test.html                |                <- testCase
9145         test.html                |                -> dtraceStop
Comment 22 Padraig O'Briain 2007-09-03 05:34:51 PDT
Rogbert,

Are you saying that this is a regression caused by the latest patch or did this problem also occur with the previous versio0n of the patch?
Comment 23 Brian Crowder 2007-09-03 15:38:42 PDT
This is probably not a regression, but just a bug the patch has always had.
Comment 24 Brendan Gregg 2007-09-03 16:01:13 PDT
(In reply to comment #21)

G'Day Robert,

Looks like something slipped recently; here is output from an older build of the provider on those scripts,

DELTA(ns)    FILE                     FUNCTION
1371         flowbug.html             |<- dtraceStart
21742        flowbug.html             |-> testCase
169923       flowbug.html             |  -> exec
32491        flowbug.html             |  <- exec
10423        flowbug.html             |  -> push
12454        flowbug.html             |  <- push
10214        flowbug.html             |  -> exec
22452        flowbug.html             |  <- exec
9532         flowbug.html             |  -> push
12120        flowbug.html             |  <- push
9664         flowbug.html             |  -> exec
22272        flowbug.html             |  <- exec
9384         flowbug.html             |  -> push
11839        flowbug.html             |  <- push
9702         flowbug.html             |  -> exec
21774        flowbug.html             |  <- exec
9449         flowbug.html             |  -> push
11929        flowbug.html             |  <- push
10290        flowbug.html             |<- testCase
10406        flowbug.html             |-> dtraceStop

Thanks for spotting it. This shouldn't be too hard to track down...
Comment 25 Padraig O'Briain 2007-09-04 07:10:20 PDT
I think I have found the problem at about line 4150 of js/src/jsinterp.c:

                    START_FAST_CALL(fp);
                    ok = ((JSFastNative) fun->u.n.native)(cx, argc, vp);
                    END_FAST_CALL(fp);
There needs to catch this function exit.

I will upload patch when I have tested it. 
Comment 26 Padraig O'Briain 2007-09-04 07:53:49 PDT
Created attachment 279603 [details] [diff] [review]
JavaScript probes v12

This patch fixes the problem reported by Robert Sayre.
Comment 27 Johnny Stenback (:jst, jst@mozilla.com) 2007-10-02 15:24:48 PDT
Created attachment 283261 [details] [diff] [review]
Same as v12, but updated to current trunk.

Brendan Gregg, please have a look at this and let me know if I messed up in merging this. Looks like it's working here, but I don't know the details of what this should do yet so I might have overlooked something.
Comment 28 Brendan Gregg 2007-10-05 13:36:07 PDT
G'Day Johnny,

The update looks good - thanks. I've tested it (from a build that Alfred posted to http://ftp.mozilla.org/pub/mozilla.org/firefox/nightly/contrib/2007-10-05-09-trunk/dtrace/), and ran it through a bunch of scripts; they worked the same as the previous patch.
Comment 29 Brendan Eich [:brendan] 2007-10-05 13:59:19 PDT
Created attachment 283755 [details] [diff] [review]
v12 + anonymous function name recovery + bogo-null test removal + style nits

I'll land this if it's good, and rely on Rob to provide fixes if I botched something -- sorry I can't test atm.

/be
Comment 30 Brendan Eich [:brendan] 2007-10-05 14:03:15 PDT
Comment on attachment 283755 [details] [diff] [review]
v12 + anonymous function name recovery + bogo-null test removal + style nits

Igor, could you approve the changes I made to avoid over-#ifdef'ing for dtrace? Thanks,

/be
Comment 31 Brendan Eich [:brendan] 2007-10-05 14:11:13 PDT
Padraig, I hope you don't mind my stealing this bug to help get anonymous function naming improved, and help get the patch checked in. Please feel free to review my changes as well.

I removed unnecessary null tests for arguments to jsdtrace_*, based on /a priori/ rules inside SpiderMonkey. We don't generally bother with assertions for such must-be-non-null cases, since a null pointer deref in a debugger is better than an assertbotch, and a release-mode crash (to be avoided by testing, of course) is not exploitable.

In a few places I avoided a layer of JS_* API wrapping, e.g. js_GetStringBytes instead of JS_GetStringBytes. In that particular case, the latter is not just a forwarding wrapper: it also null-tests the return from the former and returns "" to censor the null. I don't know enough about dtrace to say for sure, but from what I can see just in this patch, passing NULL/0 back to the provider hook must be ok even now, since it happens in other places.

For this particular case, js_GetStringBytes returns null only for out-of-memory (null return from malloc and kin), so this is a rare event and probably painful to dtrace usefully (but dtrace might be helpful in such extreme debugging sport scenarios, so I want to get it right).

/be
Comment 32 Brendan Gregg 2007-10-05 15:06:37 PDT
Brendan, thanks for the help!

I've been meaning to comment about the interface of function-args and function-rval - two extra probes that I added a few months ago. They have proved a littly annoying to use in practise, and I think it might be worth changing their interface at some point.

This isn't urgent, and it doesn't affect many people since these particular probes aren't frequently used yet (and the 14 JavaScript tracing scripts I just added to the DTraceToolkit[1] doesn't use them either).

So function-args was to provide some debugging visibility for function arguments; and function-rval was for the return value. DTrace speaks C and the JavaScript engine uses its own JavaScript object types, so I wrote a function in jsdtracef.c called jsdtrace_jsvaltovoid() which returns a C-friendlier of these objects (ie, int, double, char *).

In practice, I want to be able to easily trace the arguments and return values of many functions at a time - without having to keep looking up JavaScript code to see what to use in printf (was that argument %d or %s?). I've been thinking it would be much easier if they were all returned as strings, so that they could always be printed as such. Objects could also be returned as strings as well - by using existing or writing additional object to string code (so long as it doesn't fire additionally traced JavaScript functions to do that conversion).

Returning all args as strings was recently demonstrated by the Shell and Tcl providers ([2], [3]), which I've found to work very well. Sorry for trying to be too clever earlier; as a debugger, I think the useability gain of having everything as strings outweighs the value of being able to occasionally use ints as ints within DTrace scripts.

This would change jsdtrace_jsvaltovoid() to jsdtrace_jsvaltostring(), and potentially include additional object to string code (I might already have some I can use). Having object visibility as strings would be awsome.

Anyhow, this is just a suggestion which shouldn't stall anyone from integrating the current JavaScript DTrace provider, which is hugely useful as is. :)

[1] http://www.opensolaris.org/os/community/dtrace/dtracetoolkit
[3] http://www.opensolaris.org/os/community/dtrace/shells
[2] http://wiki.tcl.tk/19923
Comment 33 Brendan Eich [:brendan] 2007-10-05 16:21:20 PDT
(In reply to comment #32)
> Brendan, thanks for the help!

No problem -- dtrace has been a huge help for us, from what I can see. Sayrer has been helping front-end hackers identify JS performance problems with it, which would be hard to find otherwise.

> This isn't urgent, and it doesn't affect many people since these particular
> probes aren't frequently used yet (and the 14 JavaScript tracing scripts I just
> added to the DTraceToolkit[1] doesn't use them either).

Please feel free to file followup bugs if you think they'll ripen soon.

> So function-args was to provide some debugging visibility for function
> arguments; and function-rval was for the return value. DTrace speaks C and the
> JavaScript engine uses its own JavaScript object types, so I wrote a function
> in jsdtracef.c called jsdtrace_jsvaltovoid() which returns a C-friendlier of
> these objects (ie, int, double, char *).

Just FYI, JSVAL_TO_DOUBLE untags a jsdouble (double) pointer, so jsdtrace_jsvaltovoid in all patches here has been tracing a pointer into an 8-byte allocation in the JS GC heap. I didn't change that, but I did fix the comment to say |double *|.

> In practice, I want to be able to easily trace the arguments and return values
> of many functions at a time - without having to keep looking up JavaScript code
> to see what to use in printf (was that argument %d or %s?). I've been thinking
> it would be much easier if they were all returned as strings, so that they
> could always be printed as such. Objects could also be returned as strings as
> well - by using existing or writing additional object to string code (so long
> as it doesn't fire additionally traced JavaScript functions to do that
> conversion).

That's the real trick ;-). JS is full of opportunities to reenter the interpreter via toString or valueOf. And you don't really want megabytes of object initialiser reconstruction via uneval/toSource. So what to format for most objects? A fixed "[object %s]", clasp->name format a la the default Object.prototype.toString is lacking in detail and identity discrimination, while wasting precious chars on boilerplate.

Also, without a change to the char * return value (which btw makes us cast away const a lot -- fixable by const-ipating dtrace some day?), this change would seem to mean allocating strings a lot. I'm concerned about this based on sayrer testifying that he saw performance perturbed by a probe that malloc'ed.

> This would change jsdtrace_jsvaltovoid() to jsdtrace_jsvaltostring(), and
> potentially include additional object to string code (I might already have some
> I can use). Having object visibility as strings would be awsome.

We could use a spec for how to format objects as strings to maximize dtrace utility, and other language engines' experiences could help a lot.

I still would rather scalar types not have to go through string conversion, or allocating string conversion at any rate.

> Anyhow, this is just a suggestion which shouldn't stall anyone from integrating
> the current JavaScript DTrace provider, which is hugely useful as is. :)

Right -- again please file followup bugs if you like.

/be
Comment 34 Robert Sayre 2007-10-07 12:50:26 PDT
Comment on attachment 283755 [details] [diff] [review]
v12 + anonymous function name recovery + bogo-null test removal + style nits

>Index: jsdtracef.c
>===================================================================
>+
>+      case JSTYPE_STRING:
>+        return (void *)js_GetStringBytes(JSVAL_TO_STRING(argval));

Need a cx arg here. Patch works well.
Comment 35 Brendan Eich [:brendan] 2007-10-07 22:16:52 PDT
Created attachment 283967 [details] [diff] [review]
v12++, for checkin, I hope

Thanks, Rob -- still looking for Igor's r+.

/be
Comment 36 Igor Bukanov 2007-10-07 23:11:43 PDT
Comment on attachment 283967 [details] [diff] [review]
v12++, for checkin, I hope

>Index: Makefile.in
>===================================================================
>RCS file: /cvsroot/mozilla/js/src/Makefile.in,v
>retrieving revision 3.111
>diff -p -u -8 -r3.111 Makefile.in
>--- Makefile.in	5 Sep 2007 15:56:56 -0000	3.111
>+++ Makefile.in	8 Oct 2007 05:14:31 -0000
>@@ -98,16 +98,21 @@ CSRCS		= \
> 		jsscript.c \
> 		jsstr.c \
> 		jsutil.c \
> 		jsxdrapi.c \
> 		jsxml.c \
> 		prmjtime.c \
> 		$(NULL)
> 
>+ifdef HAVE_DTRACE
>+CSRCS 		+= \
>+		jsdtracef.c
>+endif
>+
> EXPORTS		= \
> 		jsautocfg.h \
> 		jsautokw.h \
> 		js.msg \
> 		jsapi.h \
> 		jsarray.h \
> 		jsarena.h \
> 		jsatom.h \
>@@ -147,16 +152,23 @@ EXPORTS		= \
> 		jsstddef.h \
> 		jsstr.h \
> 		jstypes.h \
> 		jsutil.h \
> 		jsxdrapi.h \
> 		jsxml.h \
> 		$(NULL)
> 
>+ifdef HAVE_DTRACE
>+EXPORTS 	+= \
>+		jsdtracef.h \
>+		javascript-trace.h \
>+		$(NULL)
>+endif
>+
> ifeq (,$(filter-out WINNT WINCE,$(OS_ARCH)))
> EXPORTS		+= jscpucfg.h
> endif
> 
> JS_SAFE_ARENA	= 1
> 
> DASH_R		= -r
> 
>@@ -197,16 +209,27 @@ JSJAVA_CFLAGS	= \
> 		-I$(topsrcdir)/sun-java/include \
> 		$(JSJAVA_STUBHEADERS)
> 
> # Define keyword generator before rules.mk, see bug 323979 comment 50
> 
> HOST_SIMPLE_PROGRAMS += host_jskwgen$(HOST_BIN_SUFFIX)
> GARBAGE += jsautokw.h host_jskwgen$(HOST_BIN_SUFFIX)
> 
>+
>+ifdef HAVE_DTRACE
>+DTRACE_PROBE_OBJ = $(LIBRARY_NAME)-dtrace.$(OBJ_SUFFIX)
>+MOZILLA_DTRACE_SRC = $(srcdir)/javascript-trace.d
>+
>+javascript-trace.h: $(srcdir)/javascript-trace.d
>+	dtrace -h -s $(srcdir)/javascript-trace.d -o javascript-trace.h.in
>+	sed 's/if _DTRACE_VERSION/ifdef INCLUDE_MOZILLA_DTRACE/' \
>+	    javascript-trace.h.in > javascript-trace.h
>+endif
>+
> include $(topsrcdir)/config/rules.mk
> 
> DEFINES		+= -DEXPORT_JS_API 
> 
> INCLUDES	+= -I$(srcdir)
> 
> # MSVC '-Gy' cc flag and '/OPT:REF' linker flag cause JS_GetArgument and
> # JS_GetLocalVariable to be folded to the same address by the linker, 
>Index: javascript-trace.d
>===================================================================
>RCS file: javascript-trace.d
>diff -N javascript-trace.d
>--- /dev/null	1 Jan 1970 00:00:00 -0000
>+++ javascript-trace.d	8 Oct 2007 05:14:31 -0000
>@@ -0,0 +1,71 @@
>+/* -*- Mode: C++; tab-width: 2; indent-tabs-mode: nil; c-basic-offset: 2 -*- */
>+/* ***** BEGIN LICENSE BLOCK *****
>+ * Version: MPL 1.1/GPL 2.0/LGPL 2.1
>+ *
>+ * The contents of this file are subject to the Mozilla Public License Version
>+ * 1.1 (the "License"); you may not use this file except in compliance with
>+ * the License. You may obtain a copy of the License at
>+ * http://www.mozilla.org/MPL/
>+ *
>+ * Software distributed under the License is distributed on an "AS IS" basis,
>+ * WITHOUT WARRANTY OF ANY KIND, either express or implied. See the License
>+ * for the specific language governing rights and limitations under the
>+ * License.
>+ *
>+ * Copyright (C) 2007  Sun Microsystems, Inc. All Rights Reserved.
>+ *
>+ * Alternatively, the contents of this file may be used under the terms of
>+ * either the GNU General Public License Version 2 or later (the "GPL"), or
>+ * the GNU Lesser General Public License Version 2.1 or later (the "LGPL"),
>+ * in which case the provisions of the GPL or the LGPL are applicable instead
>+ * of those above. If you wish to allow use of your version of this file only
>+ * under the terms of either the GPL or the LGPL, and not to allow others to
>+ * use your version of this file under the terms of the MPL, indicate your
>+ * decision by deleting the provisions above and replace them with the notice
>+ * and other provisions required by the GPL or the LGPL. If you do not delete
>+ * the provisions above, a recipient may use your version of this file under
>+ * the terms of any one of the MPL, the GPL or the LGPL.
>+ *
>+ * ***** END LICENSE BLOCK ***** */
>+
>+/*
>+ * javascript provider probes
>+ *
>+ * function-entry       (filename, classname, funcname)
>+ * function-info        (filename, classname, funcname, lineno,
>+ *                      runfilename, runlineno)
>+ * function-args        (filename, classname, funcname, argc, argv, argv0,
>+ *                      argv1, argv2, argv3, argv4)
>+ * function-rval        (filename, classname, funcname, lineno, rval, rval0)
>+ * function-return      (filename, classname, funcname)
>+ * object-create-start  (filename, classname)
>+ * object-create        (filename, classname, *object, rlineno)
>+ * object-create-done   (filename, classname)
>+ * object-finalize      (NULL, classname, *object)
>+ * execute-start        (filename, lineno)
>+ * execute-done         (filename, lineno)
>+ */
>+
>+provider javascript {
>+ probe function__entry(char *, char *, char *);
>+ probe function__info(char *, char *, char *, int, char *, int);
>+ probe function__args(char *, char *, char *, int, void *, void *, void *,
>+     void *, void *, void *);
>+ probe function__rval(char *, char *, char *, int, void *, void *);
>+ probe function__return(char *, char *, char *);
>+ probe object__create__start(char *, char *);
>+ probe object__create__done(char *, char *);
>+ probe object__create(char *, char *, uintptr_t, int);
>+ probe object__finalize(char *, char *, uintptr_t);
>+ probe execute__start(char *, int);
>+ probe execute__done(char *, int);
>+};
>+
>+/*
>+#pragma D attributes Unstable/Unstable/Common provider mozilla provider
>+#pragma D attributes Private/Private/Unknown provider mozilla module
>+#pragma D attributes Private/Private/Unknown provider mozilla function
>+#pragma D attributes Unstable/Unstable/Common provider mozilla name
>+#pragma D attributes Unstable/Unstable/Common provider mozilla args
>+*/
>+
>Index: jsdtracef.c
>===================================================================
>RCS file: jsdtracef.c
>diff -N jsdtracef.c
>--- /dev/null	1 Jan 1970 00:00:00 -0000
>+++ jsdtracef.c	8 Oct 2007 05:14:31 -0000
>@@ -0,0 +1,311 @@
>+/* -*- Mode: C; tab-width: 8; indent-tabs-mode: nil; c-basic-offset: 4 -*-
>+ * vim: set ts=8 sw=4 et tw=80:
>+ *
>+ * ***** BEGIN LICENSE BLOCK *****
>+ * Version: MPL 1.1/GPL 2.0/LGPL 2.1
>+ *
>+ * The contents of this file are subject to the Mozilla Public License Version
>+ * 1.1 (the "License"); you may not use this file except in compliance with
>+ * the License. You may obtain a copy of the License at
>+ * http://www.mozilla.org/MPL/
>+ *
>+ * Software distributed under the License is distributed on an "AS IS" basis,
>+ * WITHOUT WARRANTY OF ANY KIND, either express or implied. See the License
>+ * for the specific language governing rights and limitations under the
>+ * License.
>+ *
>+ * Copyright (C) 2007  Sun Microsystems, Inc. All Rights Reserved.
>+ *
>+ * Contributor(s):
>+ *      Brendan Eich <brendan@mozilla.org>
>+ *
>+ * Alternatively, the contents of this file may be used under the terms of
>+ * either of the GNU General Public License Version 2 or later (the "GPL"),
>+ * or the GNU Lesser General Public License Version 2.1 or later (the "LGPL"),
>+ * in which case the provisions of the GPL or the LGPL are applicable instead
>+ * of those above. If you wish to allow use of your version of this file only
>+ * under the terms of either the GPL or the LGPL, and not to allow others to
>+ * use your version of this file under the terms of the MPL, indicate your
>+ * decision by deleting the provisions above and replace them with the notice
>+ * and other provisions required by the GPL or the LGPL. If you do not delete
>+ * the provisions above, a recipient may use your version of this file under
>+ * the terms of any one of the MPL, the GPL or the LGPL.
>+ *
>+ * ***** END LICENSE BLOCK ***** */
>+
>+#include "jsapi.h"
>+#include "jsutil.h"
>+#include "jsatom.h"
>+#include "jscntxt.h"
>+#include "jsdbgapi.h"
>+#include "jsfun.h"
>+#include "jsinterp.h"
>+#include "jsobj.h"
>+#include "jsscript.h"
>+#include "jsstr.h"
>+
>+#include "jsdtracef.h"
>+#include <sys/types.h>
>+
>+#define TYPEOF(cx,v)    (JSVAL_IS_NULL(v) ? JSTYPE_NULL : JS_TypeOfValue(cx,v))
>+
>+static char dempty[] = "<null>";
>+
>+char *
>+jsdtrace_filename(JSStackFrame *fp)
>+{
>+    while (fp && fp->script == NULL)
>+        fp = fp->down;
>+    return (fp && fp->script && fp->script->filename)
>+           ? (char *)fp->script->filename
>+           : dempty;
>+}
>+
>+int
>+jsdtrace_linenumber(JSContext *cx, JSStackFrame *fp)
>+{
>+    while (fp && fp->script == NULL)
>+        fp = fp->down;
>+    return (fp && fp->script && fp->pc)
>+           ? js_PCToLineNumber(cx, fp->script, fp->pc)
>+           : -1;
>+}
>+
>+/*
>+ * This function is used to convert function arguments and return value (jsval)
>+ * into the following based on each value's type tag:
>+ *
>+ *      jsval      returned
>+ *      -------------------
>+ *      STRING  -> char *
>+ *      INT     -> int
>+ *      DOUBLE  -> double *
>+ *      BOOLEAN -> int
>+ *      OBJECT  -> void *
>+ *
>+ * All are presented as void * for DTrace consumers to use, after shifting or
>+ * masking out the JavaScript type bits. This allows D scripts to use ints and
>+ * booleans directly and copyinstr() for string arguments, when types are known
>+ * beforehand.
>+ *
>+ * This is used by the function-args and function-rval probes, which also
>+ * provide raw (unmasked) jsvals should type info be useful from D scripts.
>+ */
>+void *
>+jsdtrace_jsvaltovoid(JSContext *cx, jsval argval)
>+{
>+    JSType type = TYPEOF(cx, argval);
>+
>+    switch (type) {
>+      case JSTYPE_NULL:
>+      case JSTYPE_VOID:
>+        return JS_TYPE_STR(type);
>+
>+      case JSTYPE_BOOLEAN:
>+        return (void *)JSVAL_TO_BOOLEAN(argval);
>+
>+      case JSTYPE_STRING:
>+        return (void *)js_GetStringBytes(cx, JSVAL_TO_STRING(argval));
>+
>+      case JSTYPE_NUMBER:
>+        if (JSVAL_IS_INT(argval))
>+            return (void *)JSVAL_TO_INT(argval);
>+        return JSVAL_TO_DOUBLE(argval);
>+
>+      default:
>+        return JSVAL_TO_GCTHING(argval);
>+    }
>+    /* NOTREACHED */
>+}
>+
>+char *
>+jsdtrace_function_name(JSContext *cx, JSStackFrame *fp, JSFunction *fun)
>+{
>+    JSAtom *atom;
>+    JSScript *script;
>+    jsbytecode *pc;
>+    char *name;
>+
>+    atom = fun->atom;
>+    if (!atom) {
>+        if (fp->fun != fun || !fp->down)
>+            return dempty;
>+
>+        script = fp->down->script;
>+        pc = fp->down->pc;
>+        if (!script || !pc)
>+            return dempty;
>+
>+        /*
>+         * An anonymous function called from an active script or interpreted
>+         * function: try to fetch the variable or property name by which the
>+         * anonymous function was invoked. First handle call ops by recovering
>+         * the generating pc for the callee expression at argv[-2].
>+         */
>+        switch ((JSOp) *pc) {
>+          case JSOP_CALL:
>+          case JSOP_EVAL:
>+            JS_ASSERT(fp->argv == fp->down->sp - (int)GET_ARGC(pc));
>+
>+            pc = (jsbytecode *) fp->argv[-2 - (int)script->depth];
>+
>+            /*
>+             * Be paranoid about bugs to-do with generating pc storage when
>+             * attempting to descend into the operand stack basement.
>+             */
>+            if ((uintptr_t)(pc - script->code) >= script->length)
>+                return dempty;
>+            break;
>+        }
>+
>+        switch ((JSOp) *pc) {
>+          case JSOP_CALLNAME:
>+          case JSOP_CALLPROP:
>+          case JSOP_NAME:
>+          case JSOP_SETNAME:
>+          case JSOP_GETPROP:
>+          case JSOP_SETPROP:
>+            GET_ATOM_FROM_BYTECODE(script, pc, 0, atom);
>+            break;
>+
>+          case JSOP_CALLELEM:
>+          case JSOP_GETELEM:
>+          case JSOP_SETELEM:
>+          case JSOP_CALLGVAR:
>+          case JSOP_GETGVAR:
>+          case JSOP_SETGVAR:
>+          case JSOP_CALLVAR:
>+          case JSOP_CALLARG:
>+          case JSOP_CALLLOCAL:
>+            /* FIXME: try to recover a name from these ops. */
>+            /* FALL THROUGH */
>+
>+          default:
>+            return dempty;
>+        }
>+    }
>+
>+    name = (char *)js_GetStringBytes(cx, ATOM_TO_STRING(atom));
>+    return name ? name : dempty;
>+}
>+
>+/*
>+ * These functions call the DTrace macros for the JavaScript USDT probes.
>+ * Originally this code was inlined in the JavaScript code; however since
>+ * a number of operations are called, these have been placed into functions
>+ * to reduce any negative compiler optimization effect that the addition of
>+ * a number of usually unused lines of code would cause.
>+ */
>+void
>+jsdtrace_function_entry(JSContext *cx, JSStackFrame *fp, JSFunction *fun)
>+{
>+    JAVASCRIPT_FUNCTION_ENTRY(
>+        jsdtrace_filename(fp),
>+        fun->clasp ? (char *)fun->clasp->name : dempty,
>+        jsdtrace_function_name(cx, fp, fun)
>+    );
>+}
>+
>+void
>+jsdtrace_function_info(JSContext *cx, JSStackFrame *fp, JSStackFrame *dfp,
>+                       JSFunction *fun)
>+{
>+    JAVASCRIPT_FUNCTION_INFO(
>+        jsdtrace_filename(fp),
>+        fun->clasp ? (char *)fun->clasp->name : dempty,
>+        jsdtrace_function_name(cx, fp, fun),
>+        fp->script->lineno,
>+        jsdtrace_filename(dfp),
>+        jsdtrace_linenumber(cx, dfp)
>+    );
>+}
>+
>+void
>+jsdtrace_function_args(JSContext *cx, JSStackFrame *fp, JSFunction *fun)
>+{
>+    JAVASCRIPT_FUNCTION_ARGS(
>+        jsdtrace_filename(fp),
>+        fun->clasp ? (char *)fun->clasp->name : dempty,
>+        jsdtrace_function_name(cx, fp, fun),
>+        fp->argc, (void *)fp->argv,
>+        (fp->argc > 0) ? jsdtrace_jsvaltovoid(cx, fp->argv[0]) : 0,
>+        (fp->argc > 1) ? jsdtrace_jsvaltovoid(cx, fp->argv[1]) : 0,
>+        (fp->argc > 2) ? jsdtrace_jsvaltovoid(cx, fp->argv[2]) : 0,
>+        (fp->argc > 3) ? jsdtrace_jsvaltovoid(cx, fp->argv[3]) : 0,
>+        (fp->argc > 4) ? jsdtrace_jsvaltovoid(cx, fp->argv[4]) : 0
>+    );
>+}
>+
>+void
>+jsdtrace_function_rval(JSContext *cx, JSStackFrame *fp, JSFunction *fun)
>+{
>+    JAVASCRIPT_FUNCTION_RVAL(
>+        jsdtrace_filename(fp),
>+        fun->clasp ? (char *)fun->clasp->name : dempty,
>+        jsdtrace_function_name(cx, fp, fun),
>+        jsdtrace_linenumber(cx, fp), (void *)fp->rval,
>+        jsdtrace_jsvaltovoid(cx, fp->rval)
>+    );
>+}
>+
>+void
>+jsdtrace_function_return(JSContext *cx, JSStackFrame *fp, JSFunction *fun)
>+{
>+    JAVASCRIPT_FUNCTION_RETURN(
>+        jsdtrace_filename(fp),
>+        fun->clasp ? (char *)fun->clasp->name : dempty,
>+        jsdtrace_function_name(cx, fp, fun)
>+    );
>+}
>+
>+void
>+jsdtrace_object_create_start(JSStackFrame *fp, JSClass *clasp)
>+{
>+    JAVASCRIPT_OBJECT_CREATE_START(jsdtrace_filename(fp), (char *)clasp->name);
>+}
>+
>+void
>+jsdtrace_object_create_done(JSStackFrame *fp, JSClass *clasp)
>+{
>+    JAVASCRIPT_OBJECT_CREATE_DONE(jsdtrace_filename(fp), (char *)clasp->name);
>+}
>+
>+void
>+jsdtrace_object_create(JSContext *cx, JSClass *clasp, JSObject *obj)
>+{
>+    JAVASCRIPT_OBJECT_CREATE(
>+        jsdtrace_filename(cx->fp),
>+        (char *)clasp->name,
>+        (uintptr_t)obj,
>+        jsdtrace_linenumber(cx, cx->fp)
>+    );
>+}
>+
>+void
>+jsdtrace_object_finalize(JSObject *obj)
>+{
>+    JSClass *clasp;
>+
>+    clasp = LOCKED_OBJ_GET_CLASS(obj);
>+
>+    /* the first arg is NULL - reserved for future use (filename?) */
>+    JAVASCRIPT_OBJECT_FINALIZE(NULL, (char *)clasp->name, (uintptr_t)obj);
>+}
>+
>+void
>+jsdtrace_execute_start(JSScript *script)
>+{
>+    JAVASCRIPT_EXECUTE_START(
>+        script->filename ? (char *)script->filename : dempty,
>+        script->lineno
>+    );
>+}
>+
>+void
>+jsdtrace_execute_done(JSScript *script)
>+{
>+    JAVASCRIPT_EXECUTE_DONE(
>+        script->filename ? (char *)script->filename : dempty,
>+        script->lineno
>+    );
>+}
>Index: jsdtracef.h
>===================================================================
>RCS file: jsdtracef.h
>diff -N jsdtracef.h
>--- /dev/null	1 Jan 1970 00:00:00 -0000
>+++ jsdtracef.h	8 Oct 2007 05:14:31 -0000
>@@ -0,0 +1,77 @@
>+/* -*- Mode: C; tab-width: 8; indent-tabs-mode: nil; c-basic-offset: 4 -*-
>+ * vim: set ts=8 sw=4 et tw=80:
>+ *
>+ * ***** BEGIN LICENSE BLOCK *****
>+ * Version: MPL 1.1/GPL 2.0/LGPL 2.1
>+ *
>+ * The contents of this file are subject to the Mozilla Public License Version
>+ * 1.1 (the "License"); you may not use this file except in compliance with
>+ * the License. You may obtain a copy of the License at
>+ * http://www.mozilla.org/MPL/
>+ *
>+ * Software distributed under the License is distributed on an "AS IS" basis,
>+ * WITHOUT WARRANTY OF ANY KIND, either express or implied. See the License
>+ * for the specific language governing rights and limitations under the
>+ * License.
>+ *
>+ * Copyright (C) 2007  Sun Microsystems, Inc. All Rights Reserved.
>+ *
>+ * Contributor(s):
>+ *      Brendan Eich <brendan@mozilla.org>
>+ *
>+ * Alternatively, the contents of this file may be used under the terms of
>+ * either of the GNU General Public License Version 2 or later (the "GPL"),
>+ * or the GNU Lesser General Public License Version 2.1 or later (the "LGPL"),
>+ * in which case the provisions of the GPL or the LGPL are applicable instead
>+ * of those above. If you wish to allow use of your version of this file only
>+ * under the terms of either the GPL or the LGPL, and not to allow others to
>+ * use your version of this file under the terms of the MPL, indicate your
>+ * decision by deleting the provisions above and replace them with the notice
>+ * and other provisions required by the GPL or the LGPL. If you do not delete
>+ * the provisions above, a recipient may use your version of this file under
>+ * the terms of any one of the MPL, the GPL or the LGPL.
>+ *
>+ * ***** END LICENSE BLOCK ***** */
>+
>+#include "javascript-trace.h"
>+#include "jspubtd.h"
>+#include "jsprvtd.h"
>+
>+#ifndef _JSDTRACEF_H
>+#define _JSDTRACEF_H
>+
>+extern void
>+jsdtrace_function_entry(JSContext *cx, JSStackFrame *fp, JSFunction *fun);
>+
>+extern void
>+jsdtrace_function_info(JSContext *cx, JSStackFrame *fp, JSStackFrame *dfp,
>+                       JSFunction *fun);
>+
>+extern void
>+jsdtrace_function_args(JSContext *cx, JSStackFrame *fp, JSFunction *fun);
>+
>+extern void
>+jsdtrace_function_rval(JSContext *cx, JSStackFrame *fp, JSFunction *fun);
>+
>+extern void
>+jsdtrace_function_return(JSContext *cx, JSStackFrame *fp, JSFunction *fun);
>+
>+extern void
>+jsdtrace_object_create_start(JSStackFrame *fp, JSClass *clasp);
>+
>+extern void
>+jsdtrace_object_create_done(JSStackFrame *fp, JSClass *clasp);
>+
>+extern void
>+jsdtrace_object_create(JSContext *cx, JSClass *clasp, JSObject *obj);
>+
>+extern void
>+jsdtrace_object_finalize(JSObject *obj);
>+
>+extern void
>+jsdtrace_execute_start(JSScript *script);
>+
>+extern void
>+jsdtrace_execute_done(JSScript *script);
>+
>+#endif /* _JSDTRACE_H */
>Index: jsinterp.c
>===================================================================
>RCS file: /cvsroot/mozilla/js/src/jsinterp.c,v
>retrieving revision 3.376
>diff -p -u -8 -r3.376 jsinterp.c
>--- jsinterp.c	20 Sep 2007 21:49:26 -0000	3.376
>+++ jsinterp.c	8 Oct 2007 05:14:37 -0000
>@@ -64,16 +64,20 @@
> #include "jsnum.h"
> #include "jsobj.h"
> #include "jsopcode.h"
> #include "jsscan.h"
> #include "jsscope.h"
> #include "jsscript.h"
> #include "jsstr.h"
> 
>+#ifdef INCLUDE_MOZILLA_DTRACE
>+#include "jsdtracef.h"
>+#endif
>+
> #if JS_HAS_XML_SUPPORT
> #include "jsxml.h"
> #endif
> 
> /*
>  * Stack macros and functions.  These all use a local variable, jsval *sp, to
>  * point to the next free stack slot.  SAVE_SP must be called before any call
>  * to a function that may invoke the interpreter.  RESTORE_SP must be called
>@@ -1528,16 +1532,21 @@ js_Execute(JSContext *cx, JSObject *chai
>            JSStackFrame *down, uintN flags, jsval *result)
> {
>     JSInterpreterHook hook;
>     void *hookData, *mark;
>     JSStackFrame *oldfp, frame;
>     JSObject *obj, *tmp;
>     JSBool ok;
> 
>+#ifdef INCLUDE_MOZILLA_DTRACE
>+    if (JAVASCRIPT_EXECUTE_START_ENABLED())
>+        jsdtrace_execute_start(script);
>+#endif
>+
>     hook = cx->debugHooks->executeHook;
>     hookData = mark = NULL;
>     oldfp = cx->fp;
>     frame.script = script;
>     if (down) {
>         /* Propagate arg/var state for eval and the debugger API. */
>         frame.callobj = down->callobj;
>         frame.argsobj = down->argsobj;
>@@ -1564,18 +1573,20 @@ js_Execute(JSContext *cx, JSObject *chai
>         frame.thisp = chain;
>         frame.argc = 0;
>         frame.argv = NULL;
>         frame.nvars = script->ngvars;
>         if (script->regexpsOffset != 0)
>             frame.nvars += JS_SCRIPT_REGEXPS(script)->length;
>         if (frame.nvars != 0) {
>             frame.vars = js_AllocRawStack(cx, frame.nvars, &mark);
>-            if (!frame.vars)
>-                return JS_FALSE;
>+            if (!frame.vars) {
>+                ok = JS_FALSE;
>+                goto out;
>+            }
>             memset(frame.vars, 0, frame.nvars * sizeof(jsval));
>         } else {
>             frame.vars = NULL;
>         }
>         frame.annotation = NULL;
>         frame.sharpArray = NULL;
>     }
>     frame.rval = JSVAL_VOID;
>@@ -1632,16 +1643,21 @@ js_Execute(JSContext *cx, JSObject *chai
>     cx->fp = oldfp;
> 
>     if (oldfp && oldfp != down) {
>         JS_ASSERT(cx->dormantFrameChain == oldfp);
>         cx->dormantFrameChain = oldfp->dormantNext;
>         oldfp->dormantNext = NULL;
>     }
> 
>+out:
>+#ifdef INCLUDE_MOZILLA_DTRACE
>+    if (JAVASCRIPT_EXECUTE_DONE_ENABLED())
>+        jsdtrace_execute_done(script);
>+#endif
>     return ok;
> }
> 
> #if JS_HAS_EXPORT_IMPORT
> /*
>  * If id is JSVAL_VOID, import all exported properties from obj.
>  */
> static JSBool
>@@ -2609,16 +2625,24 @@ interrupt:
>                     ok &= js_PutCallObject(cx, fp);
>                 }
> 
>                 if (fp->argsobj) {
>                     SAVE_SP_AND_PC(fp);
>                     ok &= js_PutArgsObject(cx, fp);
>                 }
> 
>+#ifdef INCLUDE_MOZILLA_DTRACE
>+                /* DTrace function return, inlines */
>+                if (JAVASCRIPT_FUNCTION_RVAL_ENABLED())
>+                    jsdtrace_function_rval(cx, fp, fp->fun);
>+                if (JAVASCRIPT_FUNCTION_RETURN_ENABLED())
>+                    jsdtrace_function_return(cx, fp, fp->fun);
>+#endif
>+
>                 /* Restore context version only if callee hasn't set version. */
>                 if (JS_LIKELY(cx->version == currentVersion)) {
>                     currentVersion = ifp->callerVersion;
>                     if (currentVersion != cx->version)
>                         js_SetVersion(cx, currentVersion);
>                 }
> 
>                 /* Store the return value in the caller's operand frame. */
>@@ -4033,31 +4057,53 @@ interrupt:
>                     cx->fp = fp = &newifp->frame;
>                     pc = script->code;
> #if !JS_THREADED_INTERP
>                     endpc = pc + script->length;
> #endif
>                     inlineCallCount++;
>                     JS_RUNTIME_METER(rt, inlineCalls);
> 
>+#ifdef INCLUDE_MOZILLA_DTRACE
>+                    /* DTrace function entry, inlines */
>+                    if (JAVASCRIPT_FUNCTION_ENTRY_ENABLED())
>+                        jsdtrace_function_entry(cx, fp, fun);
>+                    if (JAVASCRIPT_FUNCTION_INFO_ENABLED())
>+                        jsdtrace_function_info(cx, fp, fp->down, fun);
>+                    if (JAVASCRIPT_FUNCTION_ARGS_ENABLED())
>+                        jsdtrace_function_args(cx, fp, fun);
>+#endif
>+
>                     /* Load first op and dispatch it (safe since JSOP_STOP). */
>                     op = (JSOp) *pc;
>                     DO_OP();
> 
>                   bad_inline_call:
>                     RESTORE_SP(fp);
>                     JS_ASSERT(fp->pc == pc);
>                     script = fp->script;
>                     depth = (jsint) script->depth;
>                     atoms = script->atomMap.vector;
>                     js_FreeRawStack(cx, newmark);
>                     ok = JS_FALSE;
>                     goto out;
>                 }
> 
>+#ifdef INCLUDE_MOZILLA_DTRACE
>+                /* DTrace function entry, non-inlines */
>+                if (VALUE_IS_FUNCTION(cx, lval)) {
>+                    if (JAVASCRIPT_FUNCTION_ENTRY_ENABLED())
>+                        jsdtrace_function_entry(cx, fp, fun);
>+                    if (JAVASCRIPT_FUNCTION_INFO_ENABLED())
>+                        jsdtrace_function_info(cx, fp, fp, fun);
>+                    if (JAVASCRIPT_FUNCTION_ARGS_ENABLED())
>+                        jsdtrace_function_args(cx, fp, fun);
>+                }
>+#endif
>+
>                 if (fun->flags & JSFUN_FAST_NATIVE) {
>                     uintN nargs = JS_MAX(argc, fun->u.n.minargs);
> 
>                     nargs += fun->u.n.extra;
>                     if (argc < nargs) {
>                         /*
>                          * If we can't fit missing args and local roots in
>                          * this frame's operand stack, take the slow path.
>@@ -4075,26 +4121,43 @@ interrupt:
>                         } while (--nargs != 0);
>                         SAVE_SP(fp);
>                     }
> 
>                     JS_ASSERT(!JSVAL_IS_PRIMITIVE(vp[1]) ||
>                               PRIMITIVE_THIS_TEST(fun, vp[1]));
> 
>                     ok = ((JSFastNative) fun->u.n.native)(cx, argc, vp);
>+#ifdef INCLUDE_MOZILLA_DTRACE
>+                    if (VALUE_IS_FUNCTION(cx, lval)) {
>+                        if (JAVASCRIPT_FUNCTION_RVAL_ENABLED())
>+                            jsdtrace_function_rval(cx, fp, fun);
>+                        if (JAVASCRIPT_FUNCTION_RETURN_ENABLED())
>+                            jsdtrace_function_return(cx, fp, fun);
>+                    }
>+#endif
>                     if (!ok)
>                         goto out;
>                     sp = vp + 1;
>                     vp[-depth] = (jsval)pc;
>                     goto end_call;
>                 }
>             }
> 
>           do_invoke:
>             ok = js_Invoke(cx, argc, vp, 0);
>+#ifdef INCLUDE_MOZILLA_DTRACE
>+            /* DTrace function return, non-inlines */
>+            if (VALUE_IS_FUNCTION(cx, lval)) {
>+                if (JAVASCRIPT_FUNCTION_RVAL_ENABLED())
>+                    jsdtrace_function_rval(cx, fp, fun);
>+                if (JAVASCRIPT_FUNCTION_RETURN_ENABLED())
>+                    jsdtrace_function_return(cx, fp, fun);
>+            }
>+#endif
>             sp = vp + 1;
>             vp[-depth] = (jsval)pc;
>             LOAD_INTERRUPT_HANDLER(cx);
>             if (!ok)
>                 goto out;
>             JS_RUNTIME_METER(rt, nonInlineCalls);
> 
>           end_call:
>Index: jsobj.c
>===================================================================
>RCS file: /cvsroot/mozilla/js/src/jsobj.c,v
>retrieving revision 3.387
>diff -p -u -8 -r3.387 jsobj.c
>--- jsobj.c	1 Oct 2007 19:11:41 -0000	3.387
>+++ jsobj.c	8 Oct 2007 05:14:40 -0000
>@@ -78,16 +78,20 @@
> #if JS_HAS_XML_SUPPORT
> #include "jsxml.h"
> #endif
> 
> #if JS_HAS_XDR
> #include "jsxdrapi.h"
> #endif
> 
>+#ifdef INCLUDE_MOZILLA_DTRACE
>+#include "jsdtracef.h"
>+#endif
>+
> #ifdef JS_THREADSAFE
> #define NATIVE_DROP_PROPERTY js_DropProperty
> 
> extern void
> js_DropProperty(JSContext *cx, JSObject *obj, JSProperty *prop);
> #else
> #define NATIVE_DROP_PROPERTY NULL
> #endif
>@@ -2433,42 +2437,47 @@ js_NewObject(JSContext *cx, JSClass *cla
>     jsid id;
>     JSObject *obj;
>     JSObjectOps *ops;
>     JSObjectMap *map;
>     JSClass *protoclasp;
>     uint32 nslots, i;
>     JSTempValueRooter tvr;
> 
>+#ifdef INCLUDE_MOZILLA_DTRACE
>+    if (JAVASCRIPT_OBJECT_CREATE_START_ENABLED())
>+        jsdtrace_object_create_start(cx->fp, clasp);
>+#endif
>+
>     /* Bootstrap the ur-object, and make it the default prototype object. */
>     if (!proto) {
>         if (!js_GetClassId(cx, clasp, &id))
>-            return NULL;
>+            goto earlybad;
>         if (!js_GetClassPrototype(cx, parent, id, &proto))
>-            return NULL;
>+            goto earlybad;
>         if (!proto &&
>             !js_GetClassPrototype(cx, parent, INT_TO_JSID(JSProto_Object),
>                                   &proto)) {
>-            return NULL;
>+            goto earlybad;
>         }
>     }
> 
>     /* Always call the class's getObjectOps hook if it has one. */
>     ops = clasp->getObjectOps
>           ? clasp->getObjectOps(cx, clasp)
>           : &js_ObjectOps;
> 
>     /*
>      * Allocate a zeroed object from the GC heap.  Do this *after* any other
>      * GC-thing allocations under js_GetClassPrototype or clasp->getObjectOps,
>      * to avoid displacing the newborn root for obj.
>      */
>     obj = (JSObject *) js_NewGCThing(cx, GCX_OBJECT, sizeof(JSObject));
>     if (!obj)
>-        return NULL;
>+        goto earlybad;
> 
>     /*
>      * Initialize all JSObject fields before doing any operation that can
>      * potentially trigger GC.
>      */
>     obj->map = NULL;
>     obj->dslots = NULL;
> 
>@@ -2543,21 +2552,36 @@ js_NewObject(JSContext *cx, JSClass *cla
>         cx->debugHooks->objectHook(cx, obj, JS_TRUE,
>                                    cx->debugHooks->objectHookData);
>         JS_UNKEEP_ATOMS(cx->runtime);
>     }
> 
> out:
>     JS_POP_TEMP_ROOT(cx, &tvr);
>     cx->weakRoots.newborn[GCX_OBJECT] = obj;
>+#ifdef INCLUDE_MOZILLA_DTRACE
>+    if (JAVASCRIPT_OBJECT_CREATE_ENABLED())
>+        jsdtrace_object_create(cx, clasp, obj);
>+    if (JAVASCRIPT_OBJECT_CREATE_DONE_ENABLED())
>+        jsdtrace_object_create_done(cx->fp, clasp);
>+#endif
>     return obj;
> 
> bad:
>     obj = NULL;
>     goto out;
>+
>+earlybad:
>+#ifdef INCLUDE_MOZILLA_DTRACE
>+    if (JAVASCRIPT_OBJECT_CREATE_ENABLED())
>+        jsdtrace_object_create(cx, clasp, NULL);
>+    if (JAVASCRIPT_OBJECT_CREATE_DONE_ENABLED())
>+        jsdtrace_object_create_done(cx->fp, clasp);
>+#endif
>+    return NULL;
> }
> 
> JS_BEGIN_EXTERN_C
> 
> JS_STATIC_DLL_CALLBACK(JSObject *)
> js_InitNullClass(JSContext *cx, JSObject *obj)
> {
>     JS_ASSERT(0);
>@@ -2796,16 +2820,21 @@ js_FinalizeObject(JSContext *cx, JSObjec
>     if (cx->debugHooks->objectHook) {
>         cx->debugHooks->objectHook(cx, obj, JS_FALSE,
>                                    cx->debugHooks->objectHookData);
>     }
> 
>     /* Finalize obj first, in case it needs map and slots. */
>     GC_AWARE_GET_CLASS(cx, obj)->finalize(cx, obj);
> 
>+#ifdef INCLUDE_MOZILLA_DTRACE
>+    if (JAVASCRIPT_OBJECT_FINALIZE_ENABLED())
>+        jsdtrace_object_finalize(obj);
>+#endif
>+
>     /* Drop map and free slots. */
>     js_DropObjectMap(cx, map, obj);
>     FreeSlots(cx, obj);
> }
> 
> /* XXXbe if one adds props, deletes earlier props, adds more, the last added
>          won't recycle the deleted props' slots. */
> JSBool
Comment 37 Alfred Peng 2007-10-08 16:40:03 PDT
(In reply to comment #33)
> No problem -- dtrace has been a huge help for us, from what I can see. Sayrer
> has been helping front-end hackers identify JS performance problems with it,
> which would be hard to find otherwise.

brendan/rob, could some pointers be given to those performance problems(bug number?) that we could take a look at?
Comment 38 Brendan Gregg 2007-10-10 15:10:42 PDT
(In reply to comment #33)
> (In reply to comment #32)
> 
> > This isn't urgent, and it doesn't affect many people since these particular
> > probes aren't frequently used yet (and the 14 JavaScript tracing scripts I just
> > added to the DTraceToolkit[1] doesn't use them either).
> 
> Please feel free to file followup bugs if you think they'll ripen soon.

Ok; I only know of 1 possible bug, and 2 possible enhancements which I can enter as seperate bugs. As a summary heads-up,

1. bug: the function-args/rval probes (discussed in comments #32 and #33), sometimes show no arguments when it should show some. I think a recent performance enhancement has changed how args are processed, and the probe needs to be tweaked to reflect that.

2. enhancement: Mixed C++/JavaScript stack traces. DTrace can print stack traces for any event; however JavaScript shows up in the stack like this,

              libmozjs.so`js_Invoke+0xa78
              libmozjs.so`js_Interpret+0x4d32
              libmozjs.so`js_Execute+0x32f

it may be possible for DTrace to print an annotated stack output with JavaScript function names, just as is possible with the DTrace Python and Java providers. (and it would be totally awsome. :)

3. enhancement: line/operation probe. Some other language providers have a probe for instruction or operation tracing. I experimented with this for JavaScript, and was able to dynamically fetch opcode counts by filename and line, to identify JavaScript hotspots. The performance effect, both enabled and not-enabled, for this incredibly frequent probe will need measuring and consideration.

Anyhow, I will enter these as seperate bugs so that people can discuss, approve or disapprove of the enhancements.

> > So function-args was to provide some debugging visibility for function
> > arguments; and function-rval was for the return value. DTrace speaks C and the
> > JavaScript engine uses its own JavaScript object types, so I wrote a function
> > in jsdtracef.c called jsdtrace_jsvaltovoid() which returns a C-friendlier of
> > these objects (ie, int, double, char *).
> 
> Just FYI, JSVAL_TO_DOUBLE untags a jsdouble (double) pointer, so
> jsdtrace_jsvaltovoid in all patches here has been tracing a pointer into an
> 8-byte allocation in the JS GC heap. I didn't change that, but I did fix the
> comment to say |double *|.

Cool, thanks. :)

> > In practice, I want to be able to easily trace the arguments and return values
> > of many functions at a time - without having to keep looking up JavaScript code
> > to see what to use in printf (was that argument %d or %s?). I've been thinking
> > it would be much easier if they were all returned as strings, so that they
> > could always be printed as such. Objects could also be returned as strings as
> > well - by using existing or writing additional object to string code (so long
> > as it doesn't fire additionally traced JavaScript functions to do that
> > conversion).
> 
> That's the real trick ;-). JS is full of opportunities to reenter the
> interpreter via toString or valueOf. And you don't really want megabytes of
> object initialiser reconstruction via uneval/toSource. So what to format for
> most objects? A fixed "[object %s]", clasp->name format a la the default
> Object.prototype.toString is lacking in detail and identity discrimination,
> while wasting precious chars on boilerplate.
> 
> Also, without a change to the char * return value (which btw makes us cast away
> const a lot -- fixable by const-ipating dtrace some day?), this change would
> seem to mean allocating strings a lot. I'm concerned about this based on sayrer
> testifying that he saw performance perturbed by a probe that malloc'ed.

Ahh - the DTrace probes will malloc() various arguments, such as when calling JS_GetFunctionName() for the function name argument. ((and I just confirmed that using,

# dtrace -n '
pid$target::JS_GetFunctionName:entry { self->ok = 1; }
pid$target::JS_GetFunctionName:return { self->ok = 0; }
pid$target::malloc:entry /self->ok/ { ustack(); }
' -p `pgrep -n firefox-bin`
dtrace: description 'pid$target::JS_GetFunctionName:entry,pid$target::JS_GetFunctionName:return ' matched 4 probes
CPU     ID                    FUNCTION:NAME
  1  78211                     malloc:entry 
              libc.so.1`malloc
              libmozjs.so`js_GetStringBytes+0x239
              libmozjs.so`JS_GetFunctionName+0x28
              libmozjs.so`jsdtrace_function_entry+0x34
              libmozjs.so`js_Interpret+0x52b1
              libmozjs.so`js_Invoke+0xac0
              libmozjs.so`fun_apply+0x1a5
              libmozjs.so`js_Interpret+0x4ca1
              libmozjs.so`js_Invoke+0xac0
              libxul.so`__1cTnsXPCWrappedJSClassKCallMethod6MpnOnsXPCWrapped...
[...]
))

This data is used by a DTrace probe immediately and then left for GC to pick up later. Since DTrace immediately copies the data into a kernel buffer, then there is no reason to leave these around for the GC - potentially perturbing performance when probes are enabled.

So, is there a GC function that can free an object immediately? This could be called at the end of each DTrace probe function in jsdtracef.c, so that anything a DTrace probe malloc()s is freed moments afterwards. I didn't see anything in jsgc.c to free an object...

As for dtrace probe definitions becomming const-ipated - yes, it is a little annoying to have to cast away const, and there has been a bug raised for this (http://bugs.opensolaris.org/view_bug.do?bug_id=6460581). There was a reason DTrace drops const for now, which I can't remember at the moment (I need to ask the author who is out of the office today). 

> > This would change jsdtrace_jsvaltovoid() to jsdtrace_jsvaltostring(), and
> > potentially include additional object to string code (I might already have some
> > I can use). Having object visibility as strings would be awsome.
> 
> We could use a spec for how to format objects as strings to maximize dtrace
> utility, and other language engines' experiences could help a lot.

Sounds like a good idea. DTrace does truncate strings (the length is tunable), so part of the spec could be how to print truncated object-as-strings.

> I still would rather scalar types not have to go through string conversion, or
> allocating string conversion at any rate.

Ok, fair enough. And keeping the scalar types as-is allows them to be used in DTrace math expressions and predicates.

Brendan(@Sun)
Comment 39 Brendan Eich [:brendan] 2007-10-10 15:46:36 PDT
(In reply to comment #38)
> Ok; I only know of 1 possible bug, and 2 possible enhancements which I can
> enter as seperate bugs. As a summary heads-up, [snip]

Thanks, I will see to these sooner or later.

> Ahh - the DTrace probes will malloc() various arguments, such as when calling
> JS_GetFunctionName() for the function name argument. ((and I just confirmed
> that using, [snip]
> This data is used by a DTrace probe immediately and then left for GC to pick up
> later. Since DTrace immediately copies the data into a kernel buffer, then
> there is no reason to leave these around for the GC - potentially perturbing
> performance when probes are enabled.

The deflated string cache won't have an entry GC'ed until the JSString whose address indexes the entry is itself GC'ed, which won't happen until that function becomes garbage. So this malloc is a one-time-per-traced-function hit. We could avoid it, though: can we dtrace UTF-16 strings?

> So, is there a GC function that can free an object immediately? This could be
> called at the end of each DTrace probe function in jsdtracef.c, so that
> anything a DTrace probe malloc()s is freed moments afterwards. I didn't see
> anything in jsgc.c to free an object...

For now it's better to let the deflated string cache hold the decimated bytes that came from the function's name-string(-atom). We want to rehit the cache. But if we could just dtrace UTF-16, we could avoid any allocation.

/be
Comment 40 Robert Sayre 2007-10-12 17:36:58 PDT
(In reply to comment #37)
> (In reply to comment #33)
> > No problem -- dtrace has been a huge help for us, from what I can see. Sayrer
> > has been helping front-end hackers identify JS performance problems with it,
> > which would be hard to find otherwise.
> 
> brendan/rob, could some pointers be given to those performance problems(bug
> number?) that we could take a look at?
> 

I know about these:

Bug 398824.
Bug 398807.
Bug 398300.
Bug 398360. 
Bug 399265.
Bug 398950.
Bug 399403.
Bug 398965.
Bug 398344.
Comment 41 Myk Melez [:myk] [@mykmelez] 2007-10-12 17:45:41 PDT
(In reply to comment #40)
> (In reply to comment #37)
> > brendan/rob, could some pointers be given to those performance problems(bug
> > number?) that we could take a look at?
> > 
> 
> I know about these:

There's also bug 385224.
Comment 42 Johnny Stenback (:jst, jst@mozilla.com) 2007-10-15 17:32:59 PDT
Created attachment 285023 [details] [diff] [review]
v12+++, for checkin

Same as v12++, but with a change to Makefile.in to not have javascript-trace.h be the default build target, and also merged to trunk.
Comment 43 Johnny Stenback (:jst, jst@mozilla.com) 2007-10-16 14:47:12 PDT
Comment on attachment 285023 [details] [diff] [review]
v12+++, for checkin

This patch is no good, the build stuff aint right. I've got a new version coming here that adds back the DTRACE_PROBE_OBJ target to rules.mk that was removed in some of the later attachments to bug 370906 even though building a standalone library like the JS engine does depend on that target being there.
Comment 44 Johnny Stenback (:jst, jst@mozilla.com) 2007-10-16 15:19:52 PDT
Created attachment 285156 [details] [diff] [review]
283967: v12++++, for checkin

This one restores the $(DTRACE_PROBE_OBJ) target declaration in rules.mk that was originally part of the dtrace framework patch but was removed at a later stage in thinking it wasn't needed. Well, it is needed in this case, where we're building a library from object files rather than linking together a bunch of other libs. This also renames NEED_DTRACE_PROBE_OBJ in rules.mk to DTRACE_LIB_DEPENDENT (feel free to suggest better names) and makes that be just a boolean variable and DTRACE_PROBE_OBJ is used in that case as well to denote what dtrace probe object to use.

This patch doesn't change the JS probe code at all, only monkeys around with the build system part of this change.
Comment 45 Ted Mielczarek [:ted.mielczarek] 2007-10-16 15:22:39 PDT
Comment on attachment 285156 [details] [diff] [review]
283967: v12++++, for checkin

r+a=me on the rules.mk changes.
Comment 46 Brendan Eich [:brendan] 2007-10-16 15:32:21 PDT
a=me for the js parts, natch. Thanks to jst for taking over here.

/be
Comment 47 Alfred Peng 2007-10-19 15:26:15 PDT
Fix checked in on the trunk. Marking bug FIXED, let's take followup work in new bugs. Thanks to everyone for all the hard work to get this into the tree!
Comment 48 Johnny Stenback (:jst, jst@mozilla.com) 2007-10-19 15:35:09 PDT
Um, that comment was from me, Alfred just hadn't been logged out on my computer apparently :)

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