Last Comment Bug 507012 - Need an efficient and convenient execution tracing API for profiling
: Need an efficient and convenient execution tracing API for profiling
Status: RESOLVED FIXED
[ts][hud][fixed-in-tracemonkey]
: dev-doc-complete
Product: Core
Classification: Components
Component: JavaScript Engine (show other bugs)
: Trunk
: x86 Linux
: -- normal with 1 vote (vote)
: ---
Assigned To: Steve Fink [:sfink] [:s:]
:
:
Mentors:
: 534075 (view as bug list)
Depends on:
Blocks: 447581 459117 466739 550242 558200 580055 584175
  Show dependency treegraph
 
Reported: 2009-07-28 14:20 PDT by (dormant account)
Modified: 2011-03-08 10:43 PST (History)
34 users (show)
See Also:
Crash Signature:
(edit)
QA Whiteboard:
Iteration: ---
Points: ---
Has Regression Range: ---
Has STR: ---
-


Attachments
First cut (4.88 KB, patch)
2009-07-28 17:38 PDT, David Mandelin [:dmandelin]
no flags Details | Diff | Splinter Review
patch 2 (unbitrotted) (8.46 KB, patch)
2009-10-29 22:45 PDT, Mark Finkle (:mfinkle) (use needinfo?)
no flags Details | Diff | Splinter Review
patch (m-192) (12.04 KB, patch)
2009-11-20 12:06 PST, Mark Finkle (:mfinkle) (use needinfo?)
no flags Details | Diff | Splinter Review
simplistic python script top generate call ranking and call stack (2.82 KB, text/plain)
2009-12-08 09:59 PST, Mark Finkle (:mfinkle) (use needinfo?)
no flags Details
patch 2 (192) (13.00 KB, patch)
2009-12-14 10:53 PST, Mark Finkle (:mfinkle) (use needinfo?)
no flags Details | Diff | Splinter Review
simplistic python script top generate call ranking and call stack (2.84 KB, text/x-python)
2010-01-14 16:58 PST, Dietrich Ayala (:dietrich)
no flags Details
patch 2 (unbitrotted again) (8.31 KB, patch)
2010-03-15 14:51 PDT, Dave Townsend [:mossop]
no flags Details | Diff | Splinter Review
patch 2 (and yet again) (4.84 KB, patch)
2010-06-16 15:03 PDT, Steve Fink [:sfink] [:s:]
no flags Details | Diff | Splinter Review
Cleaned up, added test (7.65 KB, patch)
2010-06-17 16:01 PDT, Steve Fink [:sfink] [:s:]
no flags Details | Diff | Splinter Review
Latest JS function call entry/exit callback (8.25 KB, patch)
2010-06-21 13:52 PDT, Steve Fink [:sfink] [:s:]
no flags Details | Diff | Splinter Review
Sample callback controlled by env vars (1.46 KB, patch)
2010-06-21 13:58 PDT, Steve Fink [:sfink] [:s:]
no flags Details | Diff | Splinter Review
JS function call entry/exit callback (10.10 KB, patch)
2010-06-22 13:43 PDT, Steve Fink [:sfink] [:s:]
no flags Details | Diff | Splinter Review
Sample callback controlled by JS_LOG (1.45 KB, patch)
2010-06-22 13:45 PDT, Steve Fink [:sfink] [:s:]
no flags Details | Diff | Splinter Review
JS function call entry/exit callback (10.40 KB, patch)
2010-06-24 12:24 PDT, Steve Fink [:sfink] [:s:]
no flags Details | Diff | Splinter Review
Sample callback controlled by NSPR_LOG_MODULES=JSDiagnostics:5 (1.48 KB, patch)
2010-06-24 12:26 PDT, Steve Fink [:sfink] [:s:]
no flags Details | Diff | Splinter Review
JS function call entry/exit callback, ifdef MOZ_TRACE_JSCALLS (11.54 KB, patch)
2010-06-29 14:31 PDT, Steve Fink [:sfink] [:s:]
dmandelin: review+
Details | Diff | Splinter Review
JS function call entry/exit callback, updated to tip with minor mods (19.26 KB, patch)
2010-07-19 14:26 PDT, Steve Fink [:sfink] [:s:]
no flags Details | Diff | Splinter Review
JS function call entry/exit callback (19.30 KB, patch)
2010-07-29 13:46 PDT, Steve Fink [:sfink] [:s:]
no flags Details | Diff | Splinter Review
interdiff from last r+'d patch (manually generated) (8.50 KB, patch)
2010-07-29 13:48 PDT, Steve Fink [:sfink] [:s:]
dmandelin: review+
Details | Diff | Splinter Review
JS function call entry/exit callback, updated for fatvals (19.31 KB, patch)
2010-08-02 16:45 PDT, Steve Fink [:sfink] [:s:]
no flags Details | Diff | Splinter Review
JS function call entry/exit callback (20.08 KB, patch)
2010-08-03 14:22 PDT, Steve Fink [:sfink] [:s:]
dmandelin: review+
sayrer: approval2.0+
Details | Diff | Splinter Review
JS function call entry/exit callback, updated to tip and w/ FIXME comment (19.31 KB, patch)
2010-08-09 13:21 PDT, Steve Fink [:sfink] [:s:]
dmandelin: review+
sayrer: approval2.0+
Details | Diff | Splinter Review

Description (dormant account) 2009-07-28 14:20:05 PDT
JSD is pretty terrible, but it is the only portable way to figure out what's happening in JS at the moment.

From discussion with Andreas, sounds like it's possible add a JS api to invoke functions on enter/exit with some piece of information indicating which function is being called.

This is important, because currently there is no way for extension authors to figure out what sort of performance impact their code has(especially on Fennec).
Comment 1 Blake Kaplan (:mrbkap) 2009-07-28 14:38:16 PDT
Can you not use the dtrace hooks?
Comment 2 (dormant account) 2009-07-28 14:48:37 PDT
(In reply to comment #1)
> Can you not use the dtrace hooks?

No. We need something cross-platform
Comment 3 David Mandelin [:dmandelin] 2009-07-28 14:59:10 PDT
Do you mean a callback on every entry/exit of a JS function? That would be easy, I think.
Comment 4 (dormant account) 2009-07-28 15:01:04 PDT
(In reply to comment #3)
> Do you mean a callback on every entry/exit of a JS function? That would be
> easy, I think.

Yes.
Comment 5 David Mandelin [:dmandelin] 2009-07-28 17:38:26 PDT
Created attachment 391245 [details] [diff] [review]
First cut

I whipped up a first cut before this got assigned. :-)
Comment 6 Brendan Eich [:brendan] 2009-07-28 23:30:29 PDT
Nit: JSFunctionCallback for poor-man's namespacing by prefixing in js{api,pubtd,etc}.h.

Some JSBool usage should be bool in the non-API signatures.

/be
Comment 7 Brendan Eich [:brendan] 2009-07-28 23:35:41 PDT
Last nit tonight: s/enter/entering/ for the callback's bool parameter.

/be
Comment 8 Dietrich Ayala (:dietrich) 2009-10-14 16:10:05 PDT
this certainly would be helpful. dave, any chance this can get some cycles and closed out?
Comment 9 Mark Finkle (:mfinkle) (use needinfo?) 2009-10-29 22:45:24 PDT
Created attachment 409287 [details] [diff] [review]
patch 2 (unbitrotted)

Updated to trunk. Took me a while to realize jsops.cpp was being included and that I needed to move a hunk of the patch there. Tested and seems to be working ok.

I added JS_GetFunctionName to the default test output in this patch. I also changed:

typedef void (*FunctionCallback)(JSFunction *fun, bool enter);

to typedef void (*FunctionCallback)(JSFunction *fun, JSBool entering);

the 'bool' was causing some compile errors. The 'enter' was one of Brendan's review comments. I have too little JSAPI context to understand the other comments. Please expand the explanations a bit and I'll get the changes in the patch.

My next patch should also (hopefully) integrate this mechanism with the JSD profiling system too. That way JSD profiling might be able to profile traced functions (? - I making a big assumption here)
Comment 10 (dormant account) 2009-10-30 06:29:36 PDT
(In reply to comment #9)

> My next patch should also (hopefully) integrate this mechanism with the JSD
> profiling system too. That way JSD profiling might be able to profile traced
> functions (? - I making a big assumption here)

The point of this api is to move away from restrictions imposed on JSD. The reason we can't use JSD is because JSD makes too many gurantees about being able to modify the js environment, etc when a callback is called. On the other hand this api doesn't not provide such gurantees it's strictly for profiling.
Comment 11 Mark Finkle (:mfinkle) (use needinfo?) 2009-11-20 12:06:59 PST
Created attachment 413678 [details] [diff] [review]
patch (m-192)

This patch is against mozilla-192 and it refactors the doFunctionCallbacks to be called when dTrace callbacks are called.

using this patch, I get a complete profile (no missing enters or exits). I wrote a simple python script to process the output of this patch into a call time ranking profile and a call stack profile.
Comment 12 Mark Finkle (:mfinkle) (use needinfo?) 2009-12-08 09:59:37 PST
Created attachment 416584 [details]
simplistic python script top generate call ranking and call stack

This script will generate a call-ranking and call-stack output from the raw patch output.
Comment 13 (dormant account) 2009-12-08 14:46:14 PST
I think we need to add a JS_Execute callback and land this. This will be very beneficial to our startup effort.
Comment 14 Robert Strong [:rstrong] (use needinfo to contact me) 2009-12-09 10:33:37 PST
Comment on attachment 413678 [details] [diff] [review]
patch (m-192)

>+static JSBool
>+doFunctionCallback(JSContext *cx, JSFunction *fun, JSBool enter)
>+{
>+    cx->doFunctionCallback(fun, enter);
>+    return true;
>+}
>+
>+JS_DEFINE_CALLINFO_3(static, BOOL, doFunctionCallback, CONTEXT, FUNCTION, BOOL, 0, 0)
I had to make this declaration a FASTCALL for it to compile on Windows
Comment 15 (dormant account) 2009-12-10 17:01:36 PST
*** Bug 534075 has been marked as a duplicate of this bug. ***
Comment 16 (dormant account) 2009-12-10 18:58:11 PST
Comment on attachment 413678 [details] [diff] [review]
patch (m-192)


>+    void doFunctionCallback(JSFunction *fun, JSBool entering) {
>+        if (!fun) return;
>+        JSScript* script = FUN_SCRIPT(fun);
>+        fprintf(stderr, "function: %p %s %d %s %d %d %lld\n", fun, (script ? script->filename : "na"), (script ? script->lineno : -1), JS_GetFunctionName(fun), FUN_INTERPRETED(fun), entering, JS_Now());
>+        if (functionCallback)
>+            functionCallback(fun, entering);

So it seems to me that the correct approach, would be to do a 
if (PR_GetEnv("jsfunctionlogorsomething")) 
  JS_SetFunctionCallback(something_that_does_your_printf); 


in XRE_main.

In fact, bz just enlightened me about pr_logging, we really should be logging these via PR_Log() since that can be redirected to a file, filtered/etc.
Comment 17 Rob Campbell [:rc] (:robcee) 2009-12-10 20:32:15 PST
yes, this sounds extremely useful. At some point we can take whatever logging this produces and dump it someplace more visible if we don't want to use stderr for output. thanks for the cc.
Comment 18 Mark Finkle (:mfinkle) (use needinfo?) 2009-12-14 10:53:02 PST
Created attachment 417510 [details] [diff] [review]
patch 2 (192)

Update patch for 192. Adds code to catch script enter/exits too
Comment 19 Boris Zbarsky [:bz] (still a bit busy) 2009-12-14 22:50:05 PST
So how is this better than the debugger function hook, exactly?
Comment 20 Mark Finkle (:mfinkle) (use needinfo?) 2009-12-14 22:51:44 PST
(In reply to comment #19)
> So how is this better than the debugger function hook, exactly?

Currently, the debugger kills tracing, doesn't it? Profiling untraced JS is no fun.
Comment 21 Boris Zbarsky [:bz] (still a bit busy) 2009-12-14 23:06:25 PST
Well, more precisely the js engine turns off tracing if the debugger function hook is installed.  But this proposed hook does exactly what the debugger function hook does, no?  Why would it be ok to not disable tracing if it's installed?
Comment 22 Andreas Gal :gal 2009-12-14 23:13:26 PST
The current debugger hook exports interpreter frames to the client. That kills tracing. In reality we just care to know in what function we are in. So the root problem is the debugger API. Its super generic. We should offer a narrower API, i.e. notify me about the call stack, but I don't care about arguments or variables etc. That we can do on or off trace.
Comment 23 Boris Zbarsky [:bz] (still a bit busy) 2009-12-14 23:20:21 PST
Ah, so the issue is the fp argument to JSInterpreterHook.  OK.  And yeah, a debugger does need arguments and variables.

I do think we need a decent profiling API that can be used even when trace is on (and stop overloading the debugger API with profiling stuff).  Is that what this bug is about?  Or is it actually about debugging of some sort, per summary?
Comment 24 (dormant account) 2009-12-23 15:09:52 PST
(In reply to comment #23)

> I do think we need a decent profiling API that can be used even when trace is
> on (and stop overloading the debugger API with profiling stuff).  Is that what
> this bug is about? 

Yes. It would be nice if we could land this in the near future.
Comment 25 Dietrich Ayala (:dietrich) 2010-01-11 14:34:05 PST
(In reply to comment #23)
> I do think we need a decent profiling API that can be used even when trace is
> on (and stop overloading the debugger API with profiling stuff).  Is that what
> this bug is about?  Or is it actually about debugging of some sort, per
> summary?

This bug is about profiling, so far as I've been following it. See comment #10.

Mark: what else needs to be done to get this on trunk?
Comment 26 Dietrich Ayala (:dietrich) 2010-01-14 10:45:11 PST
Mark says this is on hold for a couple of weeks.
Comment 27 Dietrich Ayala (:dietrich) 2010-01-14 16:58:28 PST
Created attachment 421729 [details]
simplistic python script top generate call ranking and call stack

uncommented the code to use a file arg, works a-ok.
Comment 28 Dave Townsend [:mossop] 2010-03-15 14:51:37 PDT
Created attachment 432665 [details] [diff] [review]
patch 2 (unbitrotted again)

Unbitrotted this again.
Comment 29 Dietrich Ayala (:dietrich) 2010-03-16 09:23:15 PDT
Can we just get this landed with a build flag, defaulting to off, and figure the rest out later?
Comment 30 Steve Fink [:sfink] [:s:] 2010-06-16 15:03:33 PDT
Created attachment 451724 [details] [diff] [review]
patch 2 (and yet again)

Guess I can't obsolete patches yet.
Comment 31 Steve Fink [:sfink] [:s:] 2010-06-17 16:01:08 PDT
Created attachment 452115 [details] [diff] [review]
Cleaned up, added test

Added a test, took out the debugging code. I'm a bit confused about the discussion in this bug about things like stderr vs PR_Log though. Why would this callback do anything by default? Shouldn't it be fully up to whoever set the callback? Or am I missing something?
Comment 32 (dormant account) 2010-06-17 16:03:41 PDT
(In reply to comment #31)
> Created an attachment (id=452115) [details]
> Cleaned up, added test
> 
> Added a test, took out the debugging code. I'm a bit confused about the
> discussion in this bug about things like stderr vs PR_Log though. Why would
> this callback do anything by default? Shouldn't it be fully up to whoever set
> the callback? Or am I missing something?

The printf thing was a convenience thing for lazy hackers. I'm with you on this : this callback should not do anything by default.
Comment 33 Mark Finkle (:mfinkle) (use needinfo?) 2010-06-17 20:24:19 PDT
(In reply to comment #32)
> (In reply to comment #31)

> > Added a test, took out the debugging code. I'm a bit confused about the
> > discussion in this bug about things like stderr vs PR_Log though. Why would
> > this callback do anything by default? Shouldn't it be fully up to whoever set
> > the callback? Or am I missing something?
> 
> The printf thing was a convenience thing for lazy hackers. I'm with you on this
> : this callback should not do anything by default.

I'm one of those lazy hackers and I do not want to add code to make this work. Why can't we add a build flag to spew the output to stderr? or to a file?

What kind of work should I have to do to get output?
Comment 34 (dormant account) 2010-06-17 22:44:10 PDT
You can add some code to mozilla/fennec to register a callback that would do the printfs. I see no point in spidermonkey shipping with precanned printfs.
Comment 35 Steve Fink [:sfink] [:s:] 2010-06-17 23:14:39 PDT
Exactly what I was about to say.

The printf that I removed was really only good for debugging the mechanism -- it prevented the optimization (pessimization limiter?) of omitting the callback invocation sequence in JITted code when no callback is active. A sample function would not interfere.

Yes, this could just set a flag instead of accepting a callback, which would invalidate that argument. But I intend to use this as a more general profiling API entry point that could be available in a release build for creating developer tools. I wouldn't want the printf for that use case. See bug 558200.
Comment 36 Mark Finkle (:mfinkle) (use needinfo?) 2010-06-18 06:31:50 PDT
(In reply to comment #34)
> You can add some code to mozilla/fennec to register a callback that would do
> the printfs. I see no point in spidermonkey shipping with precanned printfs.

That's a great idea, but let's see some code to do it.
Comment 37 Steve Fink [:sfink] [:s:] 2010-06-21 13:52:56 PDT
Created attachment 452843 [details] [diff] [review]
Latest JS function call entry/exit callback

Beefed up the test, added JSContext* parameter, addressed Brendan's JS* namespace comment. Still no JS_Execute callback; will do that next.
Comment 38 Steve Fink [:sfink] [:s:] 2010-06-21 13:58:41 PDT
Created attachment 452844 [details] [diff] [review]
Sample callback controlled by env vars

(In reply to comment #36)
> (In reply to comment #34)
> > You can add some code to mozilla/fennec to register a callback that would do
> > the printfs. I see no point in spidermonkey shipping with precanned printfs.
> 
> That's a great idea, but let's see some code to do it.

I am totally out of my depth here, but after wandering around the tree for a while, I found a potential place where this might belong. Mark, would this work for you? It uses JS_LOG(), so it prefixes each line with some messy thread info and it intermingles the output with the rest of the JSDiagnostics logging.

Let me know if this wasn't at all what you meant. I'm just barely getting to know the codebase, so I may be out in left field.
Comment 39 Steve Fink [:sfink] [:s:] 2010-06-22 13:43:07 PDT
Created attachment 453163 [details] [diff] [review]
JS function call entry/exit callback

Matched DTrace annotations, added JS_Execute. (Also note that my previous patch was the result of a mangled patch queue and did not contain all of my changes.)

One caveat with this version: I tested it with startup/log into gmail/shutdown, and the enters/exits match with a single exception, which is an enter for the empty script singleton without a corresponding exit.
Comment 40 Steve Fink [:sfink] [:s:] 2010-06-22 13:45:01 PDT
Created attachment 453164 [details] [diff] [review]
Sample callback controlled by JS_LOG

Updated to latest version of patch. Quote the function names, because a number of them contain embedded spaces which makes parsing the output unnecessarily difficult. Add a workaround for the empty script singleton problem.
Comment 41 Mark Finkle (:mfinkle) (use needinfo?) 2010-06-22 13:51:57 PDT
Steve - As long as there is a way to enable just the profile output, so we can capture it for post processing, I should be happy :)
Comment 42 Brendan Eich [:brendan] 2010-06-22 14:51:11 PDT
(In reply to comment #40)
> Add a workaround for the empty script singleton problem.

No workaround, just avoid entering before a script->isEmpty() test that guards an early return that bypasses leaving. I can't tell where you're doing this from the patch and context, but it should be easy to spot by searching for isEmpty().

/be
Comment 43 Brendan Eich [:brendan] 2010-06-22 14:59:21 PDT
Between DTrace, cx->debugHooks, and now this bug's patch, we have two too many mechanisms. We don't want more overhead on these formerly critical paths (the TM and JM JITs may not be preserve any of these -- TM sure isn't). Cc'ing some JS teammates.

/be
Comment 44 Robert Sayre 2010-06-22 15:22:25 PDT
(In reply to comment #43)
> Between DTrace, cx->debugHooks, and now this bug's patch, we have two too many
> mechanisms.

At the very least, the DTrace:: interface should be generalized to a Probe:: interface that's fleshed out at compile time. This bug's patch and Dtrace should hook in there. That way we only have one line at the probe site.
Comment 45 Steve Fink [:sfink] [:s:] 2010-06-22 16:31:15 PDT
(In reply to comment #43)
> Between DTrace, cx->debugHooks, and now this bug's patch, we have two too many
> mechanisms. We don't want more overhead on these formerly critical paths (the
> TM and JM JITs may not be preserve any of these -- TM sure isn't). Cc'ing some
> JS teammates.

The hook in this patch will survive TM. Or rather, this patch includes code specifically for TM to allow it to work. I assume JM will not work, though.

I didn't know about the debugHooks one. I'll go dig into that.

Does the DTrace:: stuff also work with SystemTap (user-space probes)?

I'll take a stab at unifying the DTrace and doFunctionCallback approaches. Can't speak for debugHooks yet. Hopefully inserting a DTrace probe point into TM JITted code isn't too nasty; I don't want to fall back to putting the DTrace probe into the callback, since right now the TM can completely optimize away the callback if it isn't being used.
Comment 46 Andrew Sutherland [:asuth] 2010-06-24 12:07:54 PDT
(In reply to comment #45)
> (In reply to comment #43)
> Does the DTrace:: stuff also work with SystemTap (user-space probes)?

SystemTap pretends to be dtrace for the purposes of user-space static probes.  It provides a 'dtrace' file and everything.  On Fedora, this does require installing the systemtap-sdt-devel package.
Comment 47 Steve Fink [:sfink] [:s:] 2010-06-24 12:16:42 PDT
I have a version that does a basic merge between this patch and the dtrace stuff. I ran into bug 577403 in attempting to carry it further.

But currently dtrace is getting passed fp, and the original point of this patch was to add a probe that didn't kill tracing. If JAVASCRIPT_FUNCTION_ENTRY_ENABLED(), then fp is used only for fp->script->filename. I know too little of js internals to answer this for myself, but could this be replaced with FUN_SCRIPT(fun)->filename instead?

If JAVASCRIPT_FUNCTION_ARGS_ENABLED(), then fp is obviously needed. But if FUN_SCRIPT(fun) is ok, then we could kill tracing only for some configurations of dtrace.

The range of overheads possible., as I see it, from cheapest to most expensive:

1. Function entry/exit callback only.
1a. Callback is not defined, so the only overhead is a pointer check (and an inline method call, but the optimizer should have no trouble there.)
1b. Callback is defined, so it can do arbitrarily slow (or fast) things, but won't kill tracing. (User is free to shoot foot with cx parameter.)

2. DTrace (INCLUDE_MOZILLA_DTRACE) with only JAVASCRIPT_FUNCTION_ENTRY_ENABLED(). Does not kill tracing, but does call JS_GetFunctionName(), which I believe does some slow string stuff.

3. DTrace with other stuff enabled. Or debugHook defined. Both kill tracing.

Obviously, I'm lying; I could #ifdef the function callbacks as well.

What's necessary to land this? I can rename the dtrace stuff, now that I've polluted it with my callback.
Comment 48 Steve Fink [:sfink] [:s:] 2010-06-24 12:24:33 PDT
Created attachment 453816 [details] [diff] [review]
JS function call entry/exit callback

Merge with DTrace code. Also fix the case where isEmpty() when trace is on.
Comment 49 Steve Fink [:sfink] [:s:] 2010-06-24 12:26:07 PDT
Created attachment 453818 [details] [diff] [review]
Sample callback controlled by NSPR_LOG_MODULES=JSDiagnostics:5
Comment 50 Steve Fink [:sfink] [:s:] 2010-06-24 12:28:32 PDT
(In reply to comment #46)
> (In reply to comment #45)
> > (In reply to comment #43)
> > Does the DTrace:: stuff also work with SystemTap (user-space probes)?
> 
> SystemTap pretends to be dtrace for the purposes of user-space static probes. 
> It provides a 'dtrace' file and everything.  On Fedora, this does require
> installing the systemtap-sdt-devel package.

Yep, so I figured out. And immediately hit bug 574403 (which I misnumbered above.)
Comment 51 (dormant account) 2010-06-24 12:37:43 PDT
(In reply to comment #47)
> I have a version that does a basic merge between this patch and the dtrace
> stuff. I ran into bug 577403 in attempting to carry it further.

Don't bother with dtrace emu on Linux. In my experience systemtap barely works for userspace tracing. This is bound to be broken.

> 
> What's necessary to land this? I can rename the dtrace stuff, now that I've
> polluted it with my callback.

I think trying to fold this in with dtrace is out of scope for this bug. Right now we need an internal hook that doesn't mess with tracing. Given that dtrace support isn't even built by default I don't think it's appropriate to integrate code with that at this stage(Might be a reasonable refactoring once this functionality is landed).
Comment 52 Brendan Eich [:brendan] 2010-06-24 13:58:11 PDT
(In reply to comment #47)
> If JAVASCRIPT_FUNCTION_ARGS_ENABLED(), then fp is obviously needed. But if
> FUN_SCRIPT(fun) is ok, then we could kill tracing only for some configurations
> of dtrace.

Good point -- you can use script, not fp, or even script->filename, which is in stable storage, cached to coalesce shared filenames, and GC'ed. That reminds me, you need to avoid holding a weak ref to the script or its filename. What ensures that you don't?

Re: comment 51: DTrace unification is not what I asked for, but what is not out of scope in this bug, if its patch is to land, is to avoid adding yet another mandatory conditional log/trace/observe/debug hook on fast paths.

/be
Comment 53 Steve Fink [:sfink] [:s:] 2010-06-29 14:31:35 PDT
Created attachment 454970 [details] [diff] [review]
JS function call entry/exit callback, ifdef MOZ_TRACE_JSCALLS

Ok, how about this one. For now, it adds --enable-trace-jscalls. We
can argue about making it the default once we have performance numbers
and compelling user-visible consumers.

In the code, this merges the dtrace and jscall tracing, so a single
probe is visible. I haven't bothered to rename jsdtracef.h; I can do that if the approach is acceptable.

If this is enabled at runtime but no callback has been registered,
this will have zero impact while running on trace, and will cost a
pair of pointer tests when running interpreted and while compiling a
trace.

The overhead is additive with dtrace when dtrace is enabled, but I see
no good way around that: dtrace is intended for an external consumer,
and even if we figured out some clever way to get the dtrace
information back into the process for an internal about:whyslow page,
it isn't portable. (inactive dtrace overhead should be pretty darn
small; I think it's supposed to be a NOP that gets dynamically
rewritten when you turn a probe on. It does break inlining in some
cases, but I think we only have it in functions that aren't going to
get inlined anyway.)

I don't know how to merge this with debughooks, because they are incompatible with TM. I could add traceable versions of JSDebugHooks.executeHook and .callHook to the JSDebugHooks struct, but I'd end up testing for both versions so the total overhead wouldn't change. Code-wise, it would also conflate debugging and profiling.

In brief: this bug is for a portable profiling mechanism that is compatible with TM. dtrace isn't portable and is at best partially compatible with TM. debughooks are incompatible with TM. Eventually, I'd like to see the mechanism in this bug enabled for release builds for use in web developer tools, but in the absence of those tools I won't fight for turning this on yet.
Comment 54 (dormant account) 2010-06-29 14:47:13 PDT
I don't think you can merge with jsd. The fact that jsd allows the consumer to do anything makes it a high-overhead api that disables JITing... which is why we are adding this new api.
Comment 55 Steve Fink [:sfink] [:s:] 2010-06-29 16:30:11 PDT
(In reply to comment #54)
> I don't think you can merge with jsd. The fact that jsd allows the consumer to
> do anything makes it a high-overhead api that disables JITing... which is why
> we are adding this new api.

Oh, I agree. I was just enumerating the specific reasons why -- namely, just what you said, except that you could sort of do it if you added some lightweight, profiling-only entries to JSDebugHooks. But you wouldn't want to, because that would mix up the heavyweight trace-killing jsd stuff with the lightweight trace-compatible profiling stuff, and wouldn't reduce the overhead anyway.

Sorry; I'm too verbose. Makes it harder to follow.
Comment 56 Brendan Eich [:brendan] 2010-07-12 14:16:35 PDT
Comment on attachment 454970 [details] [diff] [review]
JS function call entry/exit callback, ifdef MOZ_TRACE_JSCALLS

>+void funcTransition(const JSFunction *, const JSScript*, const JSContext* cx,

Nit: house style always breaks function definition return type after any *, &, or const in the declarator mode (complex declarators requiring parens around such get typedef'ed away).

>+// Not strictly necessary, but part of the test attempts to check
>+// whether these callbacks still trigger when traced, so force
>+// JSOPTION_JIT just to be sure. Once the method jit and tracing jit
>+// are integrated, this'll probably have to change (and we'll probably
>+// want to test in all modes.)
>+virtual JSContext * createContext() {

Nit again, plus no space after * in declarator, and { on its own line.

>+#ifdef MOZ_TRACE_JSCALLS
>+typedef void (*JSFunctionCallback)(const JSFunction *fun,
>+                                   const JSScript *scr,
>+                                   const JSContext *cx,
>+                                   JSBool entering);

The formals can fit on one line.

Use script not scr -- canonical variable naming plus grep -w or equivalent = win.

>@@ -1874,6 +1874,19 @@ struct JSContext
> #endif
>     }
> 
>+#ifdef MOZ_TRACE_JSCALLS
>+    /* Function entry/exit debugging callback. */
>+    JSFunctionCallback    functionCallback;
>+
>+    void doFunctionCallback(const JSFunction *fun,
>+                            const JSScript *scr,
>+                            JSBool entering) const
>+    {

In C++ classes we try to fit type, declarator, formals, and { all on same line if possible. Looks possible here.

I need to tag-out of the ring here, though, since nits are the least of the issues. A JM hacker should tag in and we should figure out how to do right by the requirements of this bug for JM as well as TM and the interpreter. Cool that you patched TM, still not sure we want to swallow brute-force overhead here.

For js::dbg2 (see bug 570650) the debugger hooks solution uses recompilation, for zero overhead when not debugging. Seems applicable here too.

/be
Comment 57 David Mandelin [:dmandelin] 2010-07-12 15:45:43 PDT
Comment on attachment 454970 [details] [diff] [review]
JS function call entry/exit callback, ifdef MOZ_TRACE_JSCALLS

As long as we're enabling/disabling this via a build switch, it seems fine, and should extend to JM easily in the same way.

Run-time enabling/disabling would be nice, but I don't see how to get that to work with tracing. I assume that for now Taras wants to run this with TM, in which case this is the right approach.
Comment 58 Rob Campbell [:rc] (:robcee) 2010-07-13 11:26:39 PDT
this is going to rock. Thanks a bunch for this, Steve!
Comment 59 Steve Fink [:sfink] [:s:] 2010-07-19 14:26:03 PDT
Created attachment 458426 [details] [diff] [review]
JS function call entry/exit callback, updated to tip with minor mods

Spent the last week getting try server access and then trying to get this patch through it. Encountered numerous problems, only one related to this patch. (The rest were problems that occurred with or without this patch applied.)

This is the patch updated to the tip, with some comment changes and one significant change: I've added a way to retrieve the current function pointer, just to make it vaguely possible to stack callbacks.

The one problem encountered on the try server is that OS X opt (and only OS X opt -- OS X debug and 11 other builds are ok) is failing the new test, because g() is not running on trace in this code:

  function g() { ++x; }
  for (i = 0; i < 50; ++i) { g(); }

In the callback for the entry to g, I am counting the number of times it is traced vs untraced. Everywhere but OS X has untraced_enters < total_enters. OS X has untraced_enters == total_enters, which seems to imply that it is unable to run it JITted.

Should we block landing it for this? (The exact same pattern happened on two different try pushes, btw, so it wasn't a completely one-time thing.) How can I investigate further? I don't have access to an OS X machine other than the try system.
Comment 60 Brendan Eich [:brendan] 2010-07-19 14:55:35 PDT
This needs to be understood. Seems like a tiny testcase you can run in the shell with TMFLAGS set to help diagnose.

/be
Comment 61 Steve Fink [:sfink] [:s:] 2010-07-20 15:03:34 PDT
Unfortunately, the problem does not reproduce with a manual build on an OS X box, and it seems like jsapi-tests are not bundled up with try server builds, so I can't just run the actual failing binary. I'm looking into other ways to tackle it. (Also, I cannot reproduce with a tiny testcase.)
Comment 62 Steve Fink [:sfink] [:s:] 2010-07-28 11:51:15 PDT
The problem is specific to emulated ppc binaries on a 32-bit x86. See bug 582693. I am unable to generate those binaries on the macosx machines I have access to without a workaround; see bug 582690. I'm not yet clear on whether this (no JIT on opt builds for emulated ppc) is expected behavior or not. If so, I may just need to disable this test. But the opt-only thing is weird, and I don't want to jump to conclusions.
Comment 63 Mike Shaver (:shaver -- probably not reading bugmail closely) 2010-07-28 11:53:27 PDT
(In reply to comment #62)
> I'm not yet clear on whether
> this (no JIT on opt builds for emulated ppc) is expected behavior or not.

Yep, we have never had a JIT on PPC, and I don't think we intend to start any time soon.
Comment 64 Steve Fink [:sfink] [:s:] 2010-07-29 13:46:05 PDT
Created attachment 461324 [details] [diff] [review]
JS function call entry/exit callback

Sorry to throw an approved patch back for review, but here's the latest. Unfortunately, interdiff will fail because the last patch bitrotted, but I'll attach a manual interdiff. Changes:

1. Cosmetic cleanups
2. Addition of JS_GetFunctionCallback() so that multiple users have some hope of peacefully coexisting (added test for this too)
3. Make the test no longer require that code be JITted if tracing is not enabled. (Fixes test failure on emulated ppc.)

This passed the try server, as long as I ignore the random timeouts that I seem to get over there these days.
Comment 65 Steve Fink [:sfink] [:s:] 2010-07-29 13:48:00 PDT
Created attachment 461325 [details] [diff] [review]
interdiff from last r+'d patch (manually generated)

This is an interdiff from the patch that dmandelin r+'d, in case it assists review.
Comment 66 Andreas Gal :gal 2010-07-29 13:58:25 PDT
This adds the 4th way of profiling in our code. dtrace, shark, vtune, jscall. Do we want to file a bug to reduce this to maybe ... mhm ... one central API?
Comment 67 Mike Shaver (:shaver -- probably not reading bugmail closely) 2010-07-29 14:02:17 PDT
See comment 44.  I don't think the shark/vtune APIs are really similar at all to the jscall/dtrace ones, but some consolidation could be useful.
Comment 68 Steve Fink [:sfink] [:s:] 2010-07-29 14:19:06 PDT
The patch implements the suggestion in comment 44 (though without renaming away from dtrace): it merges the static probe point into one and picks jscall and/or dtrace stuff at compile time.

dtrace is intended for an external consumer, and is not portable. debughooks are incompatible with TM. I could add traceable versions of JSDebugHooks.executeHook and .callHook, but I'd end up testing for both versions so the total overhead wouldn't change. Code-wise, it would also conflate debugging and profiling.

I haven't looked at shark or vtune, but they also lose out on portability.
Comment 69 Andreas Gal :gal 2010-07-29 14:31:10 PDT
Shark/vtune/jscall/dtrace are all the same thing. "Here is event X along with paramters Y and Z, go tell someone."
Comment 70 Steve Fink [:sfink] [:s:] 2010-07-29 14:53:56 PDT
With one small caveat: some are "go tell someone", some are more "tell anyone who asks". But yes, they're pretty much the same.

I'm all for your comment 66 -- file a separate bug for unification. This comment thread is too long already.

I am requesting blocking2.0 because it will help with performance profiling, particularly for mobile, and it would be helpful to have it in FF4 from the beginning. (See bug 580063 for another piece of profiling infrastructure, and bug 580055 and bug 558200 for example users.)
Comment 71 Andreas Gal :gal 2010-07-29 14:58:43 PDT
I am not opposed to a post-landing unification, but this is strictly redundant with jsdv2 as well, so lets make sure brendan is ok with the additional API surface.
Comment 72 Steve Fink [:sfink] [:s:] 2010-07-30 11:52:27 PDT
This should really go into a separate bug, but I started trawling through the source to compare/contrast all of the various profiler/debugger/whatever hooks. It got kind of long, so see https://wiki.mozilla.org/Sfink/JS_Profiling-Related_APIs (and feel free to add/comment).
Comment 73 Steve Fink [:sfink] [:s:] 2010-08-02 16:45:36 PDT
Created attachment 462253 [details] [diff] [review]
JS function call entry/exit callback, updated for fatvals

The fatvals landing bitrotted this. Here's a new version that applies to either tracemonkey or mozilla-central right now.
Comment 74 Brendan Eich [:brendan] 2010-08-03 13:34:33 PDT
Gal summons me but I already summoned dmandelin for his r+ in lieu of me, so let us not go in circles.

We absolutely need the followup bug (cite it in a FIXME comment so people can find it when they "WTF!" at the plethora of probes in our code).

/be
Comment 75 Steve Fink [:sfink] [:s:] 2010-08-03 14:22:59 PDT
Created attachment 462525 [details] [diff] [review]
JS function call entry/exit callback

Added link to bug 584175. Marked as requesting review but nothing has really changed. This is the same as last r=dmandelin + adjust for fatvals + comment change.
Comment 76 Steve Fink [:sfink] [:s:] 2010-08-09 13:21:27 PDT
Created attachment 464144 [details] [diff] [review]
JS function call entry/exit callback, updated to tip and w/ FIXME comment

Updated to tip (it needed it to apply) and added the FIXME comment requested. dmandelin, this is now approved for landing, so maybe you can spend your life doing something other than marking this r+ over and over. Better yet, apply it quick so it doesn't bitrot again.

Oh, crud, the approval bit is attached to the patch too. Sayrer?
Comment 77 David Mandelin [:dmandelin] 2010-08-09 13:39:23 PDT
http://hg.mozilla.org/tracemonkey/rev/dfd97ce2b199
Comment 78 Rob Campbell [:rc] (:robcee) 2010-08-10 06:49:08 PDT
we should probably file a separate bug to get this on the Console team's plate. I'd love to have access to this in the Console and I'm sure others would as well.

cc'ing ddahl.
Comment 79 (dormant account) 2010-08-10 10:58:52 PDT
(In reply to comment #78)
> we should probably file a separate bug to get this on the Console team's plate.
> I'd love to have access to this in the Console and I'm sure others would as
> well.
> 
> cc'ing ddahl.

What Console wants is a higher level api ie bug 558200, or bug 580055. Steve's work in those bugs should result in something that should be easy for Console to consume.
Comment 81 Dietrich Ayala (:dietrich) 2010-08-17 22:43:29 PDT
What does usage look like in the final version of this?
Comment 82 Eric Shepherd [:sheppy] 2011-03-08 06:40:16 PST
Documentation:

https://developer.mozilla.org/En/SpiderMonkey/JSAPI_User_Guide#Function_tracing

https://developer.mozilla.org/en/SpiderMonkey/JSAPI_Reference/JS_SetFunctionCallback
https://developer.mozilla.org/en/SpiderMonkey/JSAPI_Reference/JS_GetFunctionCallback

It would be helpful if someone could do a technical review of this material. In particular, the code sample has *not* been tested yet.
Comment 83 Steve Fink [:sfink] [:s:] 2011-03-08 10:43:55 PST
Thanks! It looks good to me. I went through and made some updates. Mainly by saying that this isn't all that useful for debuggers since the callback fires at odd times when you can't trust the state of anything. I updated the code sample too, which made me regret using 'const'. It builds now, though it isn't as pretty. Note that bug 580055 actually has some sample code using this.

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