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).

Can you not use the dtrace hooks?

(In reply to comment #1) > Can you not use the dtrace hooks? No. We need something cross-platform

Do you mean a callback on every entry/exit of a JS function? That would be easy, I think.

(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.

I whipped up a first cut before this got assigned. :-)

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

Last nit tonight: s/enter/entering/ for the callback's bool parameter. /be

this certainly would be helpful. dave, any chance this can get some cycles and closed out?

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)

(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.

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.

This script will generate a call-ranking and call-stack output from the raw patch output.

I think we need to add a JS_Execute callback and land this. This will be very beneficial to our startup effort.

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 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.

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.

Update patch for 192. Adds code to catch script enter/exits too

So how is this better than the debugger function hook, exactly?

(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.

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?

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.

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?

(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.

(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?

Mark says this is on hold for a couple of weeks.

uncommented the code to use a file arg, works a-ok.

Unbitrotted this again.

Can we just get this landed with a build flag, defaulting to off, and figure the rest out later?

Guess I can't obsolete patches yet.

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?

(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.

(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?

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.

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.

(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.

Beefed up the test, added JSContext* parameter, addressed Brendan's JS* namespace comment. Still no JS_Execute callback; will do that next.

(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.

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.

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.

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 :)

(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

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

(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.

(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.

(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.

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.

Merge with DTrace code. Also fix the case where isEmpty() when trace is on.

(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.)

(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).

(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

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.

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.

(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 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 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.

this is going to rock. Thanks a bunch for this, Steve!

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.

This needs to be understood. Seems like a tiny testcase you can run in the shell with TMFLAGS set to help diagnose. /be

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.)

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.

(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.

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.

This is an interdiff from the patch that dmandelin r+'d, in case it assists review.

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?

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.

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.

Shark/vtune/jscall/dtrace are all the same thing. "Here is event X along with paramters Y and Z, go tell someone."

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.)

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.

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).

The fatvals landing bitrotted this. Here's a new version that applies to either tracemonkey or mozilla-central right now.

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

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.

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?

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.

(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.

What does usage look like in the final version of this?

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.

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.