Currently markers do show up for requestAnimationFrame, but they are always labeled "Javascript". I think it would be nice to do two additional things here. 1. Give each call into Javascript a name determined by the call point in the browser. That way a marker could show up as "Javascript (requestAnimationFrame)". See bug 971673 and bug 961325. 2. Record the name and location of the function that is about to be called. This could show up in the sidebar so a user could click to see the code that was invoked. I think both these features would require examining all the users of AutoEntryScript. See also https://bugzilla.mozilla.org/show_bug.cgi?id=1110276&mark=3-5#c3

The patch in bug 1006291 would give you the first JS line that will be executed by an event. The only reason I haven't landed it is because we were thinking only about (1) above back then, but if (2) is actually needed, I believe we can just land it.

(In reply to Panos Astithas [:past] from comment #2) > The patch in bug 1006291 would give you the first JS line that will be > executed by an event. The only reason I haven't landed it is because we were > thinking only about (1) above back then, but if (2) is actually needed, I > believe we can just land it. I think #2 would be very useful and that the patch is exactly what is needed. I would love it if it went in. With that patch in place I think making #2 work is a simple matter of updating nsDocShell::NotifyJSRunToCompletionStop to record the entry point information in the marker.

I spoke too soon. I tried the patch and it doesn't quite do what I want. The patch works by marking some frames as entry points. Then other code can retrieve the current entry point by unwinding the stack to the nearest frame marked as such. What I think we need for this bug, instead, is a way to find the source location of an object at (or near) the moment it is going to be invoked.

It turns out that the information to implement #2 was relatively near one important user of AutoEntryScript. This is sufficient at least to get the function name for the Javascript marker that occurs when a DOM event is emitted. This patch depends on the patch for bug 1104213. After playing with this a bit, it seems like it would be nicer if we could collapse a "DOMEvent" marker with the corresponding "Javascript" marker. They pretty much measure the same thing but come from different spots in the platform and carry different detail data.

Now with a test case.

(In reply to Tom Tromey :tromey from comment #4) > I spoke too soon. I tried the patch and it doesn't quite do what I want. > > The patch works by marking some frames as entry points. Then other code > can retrieve the current entry point by unwinding the stack to the nearest > frame marked as such. Yes, I should have mentioned that the patch provided an API that this other patch in bug 961325 would use: https://bug961325.bugzilla.mozilla.org/attachment.cgi?id=8433491 This one provides a debugger API getter property, but also lower-level machinery that may be of use here. That patch, however, is now obsolete and Jim has a new approach in bug 961326, which I don't know if it relies on bug 1006291 or not. But it seems like you already found a working solution, so never mind!

(In reply to Panos Astithas [:past] from comment #7) > Yes, I should have mentioned that the patch provided an API that this other > patch in bug 961325 would use: > > https://bug961325.bugzilla.mozilla.org/attachment.cgi?id=8433491 Thanks once again. And, I'm sorry I missed that one! > This one provides a debugger API getter property, but also lower-level > machinery that may be of use here. That patch, however, is now obsolete and > Jim has a new approach in bug 961326, which I don't know if it relies on bug > 1006291 or not. > > But it seems like you already found a working solution, so never mind! I think it's better to use these two patches, because they solve both parts of the problem.

Also, now that we have async stacks (see bug 1083359) and these are being expanded (e.g., see bug 1142577), it would be good to capture these on the Javascript markers as well. https://dxr.mozilla.org/mozilla-central/source/js/src/jsapi.cpp#4462 is relevant.

Moving into the Profiler component. Filter on GUTHRIE'S WAVY CAKES.

For execution reasons, we don't need all the magic in bug 961325. I've filed bug 1152577 to serve as a clearer statement of what's needed.

This patch depends on the patch in bug 1152577. It adds the entry reason to the Javsacript timeline marker. This doesn't obsolete the earlier patch, as that one was about adding the to-be-called function information.

This adds the entry reason to the timeline marker and arranges for it to be displayed in the sidebar. This is item #1 from comment #2.

Noticed a formatting nit just after uploading. Will requisition rubber duck.

Comment on attachment 8594763 [details] [diff] [review] add entry reason to timeline marker Review of attachment 8594763 [details] [diff] [review]: ----------------------------------------------------------------- R+ for the changes in browser/devtools -- should give the tests in browser/devtools/performance and browser/devtools/shared a run to make sure too

Screenshot showing how this is displayed.

One issue with this patch is that it is not i18n-friendly. The cause names are just strings coded directly in the source and are not translated.

Yeah, that image show "extra words" that'll probably need translated. Is it possible to just have "setTimeout" for example, without the "handler"? What are the possible causes?

(In reply to Jordan Santell [:jsantell] [@jsantell] from comment #20) > Yeah, that image show "extra words" that'll probably need translated. Is it > possible to just have "setTimeout" for example, without the "handler"? What > are the possible causes? There are many possible reasons; either grep for AutoEntryScript or see https://bugzilla.mozilla.org/attachment.cgi?id=8591091&action=diff It may not be possible to actually get all of these to show up in the timeline (but it doesn't matter, lots of them can). I'm not sure of a good way to solve the future-proofing problem here, namely noticing new or changed entry reason strings and updating our message catalog. There's nsIStringBundle but it doesn't seem like a great solution here.

Marking leave-open because there is another patch to come later.

Jim, is there a bug for the other dependency of this bug? That is the part about getting location information for the to-be-invoked code.

Yes, I'm working on this right now.

So, one of the challenges of getting this right is that there are many ways to invoke JavaScript that are not JS::Call or JS::Evaluate or JS_ExecuteScript. Any attempt to access a property of a JavaScript object could potentially invoke getters or setters of accessor properties. Any operation on properties at all could invoke traps if the object is a proxy. And I imagine valueOf and toString methods probably come into play at some point as well. In other words, there are many JSAPI calls that can run JS, but where the caller can't reasonably anticipate which JS is going to run (short of re-implementing the property access, proxy, and type conversion logic, which is horrible, per spec). So SpiderMonkey has to help out, and tell us which code is going to run. Any time SpiderMonkey begins running JS code, it creates an instance of the js::Activation class. An Activation holds a contiguous bunch of stack frames, all of the same type; it has derived classes InterpreterActivation, JitActivation, and AsmJSActivation, specialized for each of SpiderMonkey's stack frame representations. The reason we care is that: 1) SpiderMonkey never runs JS without an Activation; this is the right bottleneck for us to instrument. 2) Activations are created and popped rarely, only on transitions between C++ and JS, or between implementation techniques (interpreter; jit; AsmJS); so lightly instrumenting them should not impact performance. 3) A fresh Activation is always created when we enter JS from some JSAPI call; we are guaranteed to catch all the JS execution we're interested in. So that's the strategy. Our tactics would be (oh, aren't these military metaphors STIRRING!): - Add a public RAII class that registers a hook with the JSRuntime that can be told about the immediate JS invocations. (There may be more than one.) - Add an argument to js::Activation's constructor providing the script or function we're entering. Normally, this argument is ignored, but *if* the JSRuntime hook described above is present, we pass our new entry script / function to it. - The js::Activation constructor *saves* the hook in a member, and *clears* it from the JSRuntime. The js::Activation destructor *restores* the hook. This ensures that only invocations with no older JS frames within the scope of our RAII class get reported; inner invocations see a null hook. - Make js::Activation's derived classes pass the entry script/function. They all know this information anyway. Then, in Gecko, we must: - Add an instance of the RAII class to AutoEntryScript, or otherwise tie the two together. I think I have some unlanded but approved patches that will help with this. (I know you hate me. I accept your hatred.) - Write a hook suitable for the js::Activation constructor to call that adds the entry point information to the timeline.

Tom, there are two questions for you: - One subtlety of the plan above is that a single AutoEntryScript could, potentially, invoke JS multiple times. So we may have several "js entry" / "js exit" pairs within a single "JavaScript" TRACING_INTERVAL_START / TRACING_INTERVAL_END pair. The details will be up to the hook Gecko provides. Will that be okay for the timeline consumers? - Is it possible for the Timeline to own rooted JavaScript objects? If it can, then we can simply record the actual JSScript / JSFunction that was entered, and extract its name and source location as necessary. If it can't, then the hook will probably need to extract that data itself at recording time. Either way I don't think it's hard; I'm just trying to pin down what the data will look like in the timeline.

(In reply to Jim Blandy :jimb from comment #29) > Tom, there are two questions for you: > > - One subtlety of the plan above is that a single AutoEntryScript could, > potentially, invoke JS multiple times. So we may have several "js entry" / > "js exit" pairs within a single "JavaScript" TRACING_INTERVAL_START / > TRACING_INTERVAL_END pair. The details will be up to the hook Gecko > provides. Will that be okay for the timeline consumers? I think it is fine. I think we have a few options, like simply emitting nested markers and relying on some coming front end changes to display them nicely; or emitting separate markers for each entry. > - Is it possible for the Timeline to own rooted JavaScript objects? If it > can, then we can simply record the actual JSScript / JSFunction that was > entered, and extract its name and source location as necessary. If it can't, > then the hook will probably need to extract that data itself at recording > time. Either way I don't think it's hard; I'm just trying to pin down what > the data will look like in the timeline. TimelineMarker already has a PersistentRooted member, so one more won't hurt. I tend to think we'll extract exactly what we need when we create the marker, but it is still fine for the JS layer to be written in any way that is convenient.

Perfect - thanks!

Okay, here's a work-in-progress patch that adds a reporting API to SpiderMonkey. See the comments in js/public/Debug.h, and example usage in js/src/shell/js.cpp. No tests yet; haven't tried the JIT cases yet. But the interpreter stuff seems to work.

Comment on attachment 8603180 [details] [diff] [review] Add SpiderMonkey API for reporting JavaScript entry points. Review of attachment 8603180 [details] [diff] [review]: ----------------------------------------------------------------- I can't do a very careful review of this, as I don't have enough knowledge. I found one little nit, maybe not actionable. I suppose the idea for wiring it up to the timeline would be to put a Maybe<subclass-of-AutoReportEntryPoints> into AutoEntryScript and then emplace it when mDocShellForJSRunToCompletion is not NULL? Or is there another plan that makes sense? It occurs to me that this hook could also capture a pending async stack, which would also be quite useful. ::: js/src/shell/js.cpp @@ +4567,5 @@ > + if (!obj) > + return false; > + > + char *filename = log[i].filename.get(); > + RootedString string(cx, Atomize(cx, filename, strlen(filename))); It seems like using Atomize would cause a new instance of bug 987069. Though of course as that isn't fixed yet maybe there is nothing to do here.

(In reply to Tom Tromey :tromey from comment #34) > I suppose the idea for wiring it up to the timeline would be to put a > Maybe<subclass-of-AutoReportEntryPoints> into AutoEntryScript and > then emplace it when mDocShellForJSRunToCompletion is not NULL? > > Or is there another plan that makes sense? Apologies, I see now that you mentioned this in comment #28.

Here's a revised patch, with tests. Some things have been renamed, hopefully for the better.

Try push: https://treeherder.mozilla.org/#/jobs?repo=try&revision=fcdef4d392ec

(In reply to Jim Blandy :jimb from comment #36) > Created attachment 8603569 [details] [diff] [review] > Add SpiderMonkey API for reporting JavaScript entry points. > > Here's a revised patch, with tests. Some things have been renamed, hopefully > for the better. One thing that came up in a different patch was that for stack classes like AutoEntryMonitor, it's good to delete the copy constructor and operator=.

Comment on attachment 8603569 [details] [diff] [review] Add SpiderMonkey API for reporting JavaScript entry points. Review of attachment 8603569 [details] [diff] [review]: ----------------------------------------------------------------- Looks pretty good. I would like to know the answer to the "This is clever" comment below before r+. ::: js/public/Debug.h @@ +344,5 @@ > + // AutoEntryMonitor's scope to the following member functions, which the > + // embedding is expected to override. > + > + // We have begun executing |function|. Note that |function| may not be the > + // actual closure we are running, but only the static function object to nit: static -> canonical ::: js/src/jit-test/tests/profiler/AutoEntryMonitor-01.js @@ +6,5 @@ > + print(uneval(params)); > + print(uneval(entryPoints(params))); > + assertEq(arraysEqual(entryPoints(params), expected), true); > + > + // Warm up the function a bit, so Ion will compile it, and try again. Nit: 10 is the Baseline threshold, not Ion. With --tbpl this test will also be run with eager compilation anyhow. ::: js/src/jit/JitCompartment.h @@ +47,5 @@ > unsigned maxArgc; > unsigned numActualArgs; > unsigned osrNumStackValues; > > + RootedScript entryScript; This field isn't necessary. The entry script can be pulled out from the calleeToken. See js::jit::ScriptFromCalleeToken. ::: js/src/shell/js.cpp @@ +4524,5 @@ > + void Entry(JSContext* cx, JSFunction* function) override { > + RootedString displayId(cx, JS_GetFunctionDisplayId(function)); > + if (displayId) { > + UniqueChars displayIdStr(JS_EncodeStringToUTF8(cx, displayId)); > + oom = !displayId || !log.append(mozilla::Move(displayIdStr)); !displayIdStr ::: js/src/vm/DebuggerMemory.cpp @@ +190,5 @@ > if (!obj) > return false; > > // Don't pop the AllocationSite yet. The queue's links are followed by > + // the GC to find the AllocationSite, but are not barriered, so we must but who was barry? ::: js/src/vm/Stack-inl.h @@ +851,5 @@ > kind_(kind) > { > cx->runtime_->asyncStackForNewActivations = nullptr; > cx->runtime_->asyncCauseForNewActivations = nullptr; > + cx->runtime_->entryMonitor = nullptr; This is clever. I imagine what this nulling is intended to prevent is reporting inner activations, which are not entry points, as entry points. I don't know how AutoEntryMonitor is intended to be used in Gecko. What about stacks like the following? AutoEntryMonitor outerMonitor; Activation outerAct; AutoEntryMonitor innerMonitor; Activation innerAct; That is, what's preventing innerMonitor being set despite there already being an activation on the stack? Would it be simpler to never null out entryMonitor on the runtime, but only invoke Entry on the first activation? @@ +905,5 @@ > + if (entryFrame->isFunctionFrame()) > + entryMonitor_->Entry(cx_, entryFrame->fun()); > + else > + entryMonitor_->Entry(cx_, entryFrame->script()); > + Nit: extra newline ::: js/src/vm/Stack.cpp @@ +1414,5 @@ > + > + if (entryMonitor_) { > + MOZ_ASSERT(entryScript); > + > + JSFunction *fun = entryScript->functionNonDelazifying(); Nit: JSFunction* fun @@ +1415,5 @@ > + if (entryMonitor_) { > + MOZ_ASSERT(entryScript); > + > + JSFunction *fun = entryScript->functionNonDelazifying(); > + if (fun) Per above, you can use the callee token here, with CalleeTokenIsFunction and CalleeTokenTo{Script,Function}.

(In reply to Shu-yu Guo [:shu] from comment #39) > nit: static -> canonical Fixed, thanks. > Nit: 10 is the Baseline threshold, not Ion. With --tbpl this test will also > be run with eager compilation anyhow. Clarified comment, thanks. My understanding is that even with the eager flags, it still takes more than one call for a function to be JITted. > This field isn't necessary. The entry script can be pulled out from the > calleeToken. See js::jit::ScriptFromCalleeToken. Perfect. I've simplified the patch accordingly, and used CalleeToken in the JitActivation constructor as well. > !displayIdStr Fixed, thanks. > but who was barry? He's just this guy, you know? He was a rising star in Illinois politics; people really thought he was going to amount to something. > This is clever. > > I imagine what this nulling is intended to prevent is reporting inner > activations, which are not entry points, as entry points. Right! > I don't know how AutoEntryMonitor is intended to be used in Gecko. What > about stacks like the following? > > AutoEntryMonitor outerMonitor; > Activation outerAct; > AutoEntryMonitor innerMonitor; > Activation innerAct; The outer monitor is supposed to receive the entry points that outerAct executes, and the inner monitor is supposed to receive those from innerAct. I've added a test case for this; it passes. > Nit: extra newline Fixed, thanks. > Nit: JSFunction* fun Fixed, thanks. > Per above, you can use the callee token here, with CalleeTokenIsFunction and > CalleeTokenTo{Script,Function}. Yes, this is a great simplification. Revised patch up in a bit.

(In reply to Jim Blandy :jimb from comment #40) > > I don't know how AutoEntryMonitor is intended to be used in Gecko. What > > about stacks like the following? > > > > AutoEntryMonitor outerMonitor; > > Activation outerAct; > > AutoEntryMonitor innerMonitor; > > Activation innerAct; > > The outer monitor is supposed to receive the entry points that outerAct > executes, and the inner monitor is supposed to receive those from innerAct. > I've added a test case for this; it passes. > The point of this example was that innerAct isn't an entry point, but innerMonitor was allowed to be instantiated despite there already being an outerAct. Should this situation be allowed?

(In reply to Tom Tromey :tromey from comment #34) > It occurs to me that this hook could also capture a pending async stack, > which would also be quite useful. I see now that there is no need to do this. When Entry is called, it seems the new stack frame is already in place, and so any async stack has been incorporated into it.

When I first wrote this patch, I added a new method to nsIDocShell and then added calls to this from the new DocshellEntryMonitor. The implementation of the new method made a TRACING_TIMESTAMP marker. This worked fine, but it has a downside: every call into JS shows as two markers in the timeline. We could of course implement marker folding (bug 1152421) or we could treat Javascript markers like Paint markers and fold them into their parent markers. However, it was much simpler to add an Exit method to AutoEntryMonitor and then simply make each entry a new marker. This works great because the Javascript marker already attempts to capture the stack trace. Because AutoEntryMonitor is notified after the new frame has been set up, any async stack is already accounted for, and no new code is needed either in docshell or in the front end to make this work nicely -- the entry point is displayed automatically. Jim, I wonder what you think of this addition.

(In reply to Shu-yu Guo [:shu] from comment #42) > The point of this example was that innerAct isn't an entry point, but > innerMonitor was allowed to be instantiated despite there already being an > outerAct. Should this situation be allowed? Yes, that situation should definitely be allowed, and that behavior is desirable. Gecko is only going to instantiate AutoEntryMonitor in places that are considered JavaScript entry points, so if we have nested monitors, those are situations in which Gecko developers would expect to see nested JS entry.

(In reply to Tom Tromey :tromey from comment #44) > However, it was much simpler to add an Exit method to AutoEntryMonitor > and then simply make each entry a new marker. This works great > because the Javascript marker already attempts to capture the stack > trace. Because AutoEntryMonitor is notified after the new frame has > been set up, any async stack is already accounted for, and no new code > is needed either in docshell or in the front end to make this work > nicely -- the entry point is displayed automatically. Have you verified that the callee stack frame is indeed captured when we traverse the stack within a monitor's Entry calls? I would have expected that it would not yet exist. I wasn't actually anticipating that one would try to capture the stack from an Entry call. If it works, I guess that's all right. Certainly using JS::dbg::AutoEntryMonitor::Entry to create timeline markers instead of the AutoEntryScript constructor is a good idea. For example, there are cases where we instantiate an AutoEntryScript, but then never actually run any JavaScript; using AutoEntryMonitor::Entry, we get no markers for such a situation.

Comment on attachment 8605309 [details] [diff] [review] notify timeline of JS entries from AutoEntryMonitor Review of attachment 8605309 [details] [diff] [review]: ----------------------------------------------------------------- ::: js/public/Debug.h @@ +354,5 @@ > // JSAPI equivalent.) > virtual void Entry(JSContext* cx, JSScript* script) = 0; > + > + // Execution of the function or script has ended. > + virtual void Exit(JSContext* cx) = 0; Actually, let's provide an empty body for this as a default, instead of = 0. (I think the Entry cases should not have a default, because I'm worried someone might override one overloading but forget about the other, and then miss entries.) ::: js/src/shell/js.cpp @@ +4540,5 @@ > oom = !label || !log.append(mozilla::Move(label)); > } > > + void Exit(JSContext* cx) override { > + } Then this can be dropped. ::: js/src/vm/Stack-inl.h @@ +913,5 @@ > InterpreterActivation::~InterpreterActivation() > { > + if (entryMonitor_) { > + entryMonitor_->Exit(cx_); > + } No curlies are needed here, in SpiderMonkey style. ::: js/src/vm/Stack.cpp @@ +1426,5 @@ > jit::JitActivation::~JitActivation() > { > + if (entryMonitor_) { > + entryMonitor_->Exit(cx_); > + } No curlies here either.

(In reply to Jim Blandy :jimb from comment #46) > Have you verified that the callee stack frame is indeed captured when we > traverse the stack within a monitor's Entry calls? I would have expected > that it would not yet exist. I wasn't actually anticipating that one would > try to capture the stack from an Entry call. Yeah, I tried it. I found out about this because I was tracking down how to capture the async stack at this point, and then realized that I didn't need to. I'll write a test case for my patch.

Revised to incorporate the matching "Exit" notification that Tom suggested.

(In reply to Tom Tromey :tromey from comment #48) > (In reply to Jim Blandy :jimb from comment #46) > > > Have you verified that the callee stack frame is indeed captured when we > > traverse the stack within a monitor's Entry calls? I would have expected > > that it would not yet exist. I wasn't actually anticipating that one would > > try to capture the stack from an Entry call. > > Yeah, I tried it. > I found out about this because I was tracking down how to capture the async > stack at this point, and then realized that I didn't need to. Shu, would you expect this to work for JitActivations too? It seems to me that, given when Entry is called at present, the new callee frame would be there for InterpreterActivations, but just from inspection I would think that JitActivations would miss it.

... or perhaps we could just have a test that verifies that it works.

(In reply to Jim Blandy :jimb from comment #50) > (In reply to Tom Tromey :tromey from comment #48) > > (In reply to Jim Blandy :jimb from comment #46) > > > > > Have you verified that the callee stack frame is indeed captured when we > > > traverse the stack within a monitor's Entry calls? I would have expected > > > that it would not yet exist. I wasn't actually anticipating that one would > > > try to capture the stack from an Entry call. > > > > Yeah, I tried it. > > I found out about this because I was tracking down how to capture the async > > stack at this point, and then realized that I didn't need to. > > Shu, would you expect this to work for JitActivations too? It seems to me > that, given when Entry is called at present, the new callee frame would be > there for InterpreterActivations, but just from inspection I would think > that JitActivations would miss it. That's my reading as well, that JitActivations would miss the about-to-be-entered frame. Since activations are C++ RAII things, the JITs must push the activation before jumping into JIT code. Walking the JIT stack depends on a "jitTop" pointer, which, since we haven't jumped into the new JIT frame yet, will either be null or the _previous_ jitTop from the last JIT->C++ re-entry.

Yeah, the test I wrote up verifies this. The stack that's visible within an Entry call varies depending on whether we're in the interpreter or not. This should be documented, at the very least.

(In reply to Tom Tromey :tromey from comment #48) > Yeah, I tried it. > I found out about this because I was tracking down how to capture the async > stack at this point, and then realized that I didn't need to. > > I'll write a test case for my patch. So, in summary: your tests only worked because your callee wasn't JITted yet.

(In reply to Jim Blandy :jimb from comment #54) > So, in summary: your tests only worked because your callee wasn't JITted yet. Bummer, but that makes sense. Will calling CaptureCurrentStack at this point always see any pending async stack?

(In reply to Tom Tromey :tromey from comment #56) > (In reply to Jim Blandy :jimb from comment #54) > > > So, in summary: your tests only worked because your callee wasn't JITted yet. > > Bummer, but that makes sense. > Will calling CaptureCurrentStack at this point always see any > pending async stack? Well, duh, that won't work, because we'll get different stacks depending on whether the code is compiled. Maybe I can fetch the async stack directly from the context instead. Ideally for my purposes, AutoEntryMonitor would have a consistent view of the stack.

(In reply to Tom Tromey :tromey from comment #57) > Maybe I can fetch the async stack directly from the context instead. The Activation constructor resets this. Perhaps instead we can pass the async stack and cause to Entry.

(In reply to Tom Tromey :tromey from comment #58) > (In reply to Tom Tromey :tromey from comment #57) > > > Maybe I can fetch the async stack directly from the context instead. > > The Activation constructor resets this. > Perhaps instead we can pass the async stack and cause to Entry. It resets it in the Runtime after saving it... in itself! So the async stack, if any, would be readily available to pass to Entry. Is the async stack really what you want, though? I guess it's better than nothing...

Comment on attachment 8605388 [details] [diff] [review] Add SpiderMonkey API for reporting JavaScript entry points. >diff --git a/js/public/Debug.h b/js/public/Debug.h [...] >+ // Execution of the function or script has ended. >+ virtual void Exit(JSContext* cx) { } >+}; >diff --git a/js/src/shell/js.cpp b/js/src/shell/js.cpp [...] >+ void Exit(JSContext* cx) { >+ MOZ_ASSERT(enteredWithoutExit); >+ enteredWithoutExit = false; >+ } This "Exit()" override here was missing an 'override' annotation, which causes clang 3.6 & newer to spam a "-Winconsistent-missing-override" build warning, which busts --enable-warnings-as-errors builds (with clang 3.6+). I pushed a followup to add that keyword, with blanket r+ that ehsan granted me for fixes of this sort over in bug 1126447 comment 2: https://hg.mozilla.org/integration/mozilla-inbound/rev/212cc3156d16

(In reply to Jim Blandy :jimb from comment #59) > Is the async stack really what you want, though? I guess it's better than > nothing... What I'd really like is to be able to get the stack from Entry -- including the frame that is in the process of being pushed. This would be the most convenient thing by far. Getting the async stack is the second-best approach. I think the async stack plus the arguments to Entry give me basically the same information, just in a less convenient form. My current patch is making a phony stack-frame-like-object from the data passed to Entry, and then exposing this to the timeline as an object that looks like a stack frame. For async stacks my thought was to chain the async stack onto this phony frame.

https://hg.mozilla.org/mozilla-central/rev/3a464761991d https://hg.mozilla.org/mozilla-central/rev/212cc3156d16

Here's the patch. This patch works by making a phony stack entry describing the function-to-be-called. This is a bit peculiar, but I think it makes sense. Also, while this patch doesn't include any async stack on the marker, this approach makes it simple to add this later. There are some oddities I have noticed with this patch, though. It works fine for function calls, but in the "script" case, sometimes the results are less than useful. Most of the time this happens because the new data describes what is going to be called. So for example if you have a <script> element, the stack will just say "whatever.js:1" -- this is an accurate description of what happened, but maybe not what the user really wanted. For this class of problem, async stacks may help in some cases; and if not, in other cases we could go a bit further, if needed, and make another stack frame describing the script's introduction point. The other thing I have noticed has to do with strange line numbers. I have a .html file with <body onload="onload()">. In the timeline this turns into a stack of "onload index.html:1". The body element doesn't appear on line 1. Presumably that "1" is relative to the location of the <body>. But I don't know if there is a good way to discern this at the relevant spot.

(In reply to Tom Tromey :tromey from comment #63) > The other thing I have noticed has to do with strange line numbers. I > have a .html file with <body onload="onload()">. In the timeline > this turns into a stack of "onload index.html:1". > > The body element doesn't appear on line 1. Presumably that "1" is > relative to the location of the <body>. But I don't know if there is > a good way to discern this at the relevant spot. A quick experiment in the debugger shows that this problem is not unique to my patch. That is, I can see it easily in the debugger stack trace. I will file a separate bug about this.

(In reply to Tom Tromey :tromey from comment #64) > A quick experiment in the debugger shows that this problem is not unique > to my patch. That is, I can see it easily in the debugger stack trace. > I will file a separate bug about this. This is already filed as bug 771490.

Here's a new version that I think is slightly cleaner. It avoids keeping state in the AutoEntryMonitor (that was a relic of an older approach) and it checks GetRecordProfileTimelineMarkers in order to avoid unnecessary work in the Entry method.

I wanted to note that I left out async stacks because they aren't used in many places in the platform yet; and, because we'd like this patch in devedition-40, it seems better to keep it as simple as possible.

Comment on attachment 8606431 [details] [diff] [review] add callee information to Javascript timeline markers > private: >+ // A subclass of AutoEntryMonitor that notifies the docshell. >+ class DocshellEntryMonitor : public ::JS::dbg::AutoEntryMonitor { Not sure why ::JS::dbg and why not JS::dbg { goes to its own line >+ public: >+ DocshellEntryMonitor(JSContext* aCx, const char* aReason); >+ >+ void Entry(JSContext* aCx, JSFunction* aFunction) override { { goes to its own line >+ void Entry(JSContext* aCx, JSScript* aScript) override { ditto >- virtual void AddDetails(mozilla::dom::ProfileTimelineMarker& aMarker) override >+ virtual void AddDetails(JSContext* aCx, >+ mozilla::dom::ProfileTimelineMarker& aMarker) >+ override I would put override at the end of the previous line

Fixed formatting issues.

There was a regression detected with the first patch. Is this something expected and is there something we can do about it? AWFY detected a regression/improvement on: --- Mac OS X 10.10 32-bit (Mac Pro, shell) - misc: bugs-608733-trace-compiler: 3.08% (regression) Recorded range: http://hg.mozilla.org/integration/mozilla-inbound/pushloghtml?fromchange=16da13eaaa02&tochange=74f120732c62 More details: http://arewefastyet.com/regressions/#/regression/1512878 ---- Mac OS X 10.10 64-bit (Mac Pro, shell) - misc: bugs-608733-trace-compiler: 3.62% (regression) Recorded range: http://hg.mozilla.org/integration/mozilla-inbound/pushloghtml?fromchange=7fcf6bf43eda&tochange=e0231e8d2cdf More details: http://arewefastyet.com/regressions/#/regression/1510896

Add a missing null check.

(In reply to Hannes Verschore [:h4writer] from comment #71) > There was a regression detected with the first patch. Is this something > expected and is there something we can do about it? No, this is not expected. The hottest path I think this patch touches is in creating instances of js::Activation subclasses. But if that is really 3% of a benchmark's time, that's got to be one very strange benchmark; Activation transitions ought to be rare. Bug 608733 includes the benchmark. I can do a comparison to verify the problem.

Rebased. This required a tiny change to RestyleTracker to add the new parameter to AddDetails. This version also tries to avoid the rooting hazards pointed out by the try build.

(In reply to Jim Blandy :jimb from comment #74) > (In reply to Hannes Verschore [:h4writer] from comment #71) > > There was a regression detected with the first patch. Is this something > > expected and is there something we can do about it? > > No, this is not expected. > > The hottest path I think this patch touches is in creating instances of > js::Activation subclasses. But if that is really 3% of a benchmark's time, > that's got to be one very strange benchmark; Activation transitions ought to > be rare. > > Bug 608733 includes the benchmark. I can do a comparison to verify the > problem. The benchmark is available here: https://github.com/h4writer/arewefastyet/blob/master/benchmarks/misc/tests/assorted/misc-bugs-608733-trace-compiler.js Yeah. I don't think it should create a lot of js::Activation subclasses. Though I haven't ever checked that benchmark in the profiler ever. A comparison to verify would be awesome. Thanks!

Hoist gc roots even higher.

Comment on attachment 8608086 [details] [diff] [review] add callee information to Javascript timeline markers It was unclear to me if the rooting changes, and the change to RestyleTracker, were substantial enough to warrant another review. So, I'm erring on the safe side.

(In reply to Hannes Verschore [:h4writer] from comment #77) I ran changesets 16da13eaaa02 (pre) and 3a464761991d (post) under valgrind --tool=cachegrind with address space randomization disabled, using both the benchmark attached to bug 608733 and the arewefastyet version, which seem to differ mostly in the type of arrays used for memory and registers. Instruction counts were very reproducible (often identical, or differing in tens of instructions out of half a billion). I compared the two with cg_diff, and saw differences on the order of .2%, mostly in hash table searches; the "post" version actually executed fewer instructions. I've included the beginning of the comparison below, showing the biggest changes. A 3.62% increase in instruction count would be on the order of 21 million instructions. There's nothing even close to that going on here. So I am at a loss to account for the behavior observed by arewefastyet. -------------------------------------------------------------------------------- Files compared: roc.cg.post1; roc.cg.pre1 Command: /home/jimb/moz/dbg/js/src/obj~/js/src/js --no-threads -f /home/jimb/moz/benchmark-roc/misc-bugs-608733-trace-compiler.js; /home/jimb/moz/dbg/js/src/obj~/js/src/js --no-threads -f /home/jimb/moz/benchmark-roc/misc-bugs-608733-trace-compiler.js Data file: roc.cg.diff Events recorded: Ir I1mr ILmr Dr D1mr DLmr Dw D1mw DLmw Events shown: Ir I1mr ILmr Dr D1mr DLmr Dw D1mw DLmw Event sort order: Ir I1mr ILmr Dr D1mr DLmr Dw D1mw DLmw Thresholds: 0.1 100 100 100 100 100 100 100 100 Include dirs: User annotated: Auto-annotation: off -------------------------------------------------------------------------------- Ir I1mr ILmr Dr D1mr DLmr Dw D1mw DLmw -------------------------------------------------------------------------------- -13,427 9,393 25 -6,218 -5 -67 -1,130 265 -84 PROGRAM TOTALS -------------------------------------------------------------------------------- Ir I1mr ILmr Dr D1mr DLmr Dw D1mw DLmw file:function -------------------------------------------------------------------------------- 22,573 750 1 1,382 7 0 898 -4 0 /home/jimb/moz/dbg/js/src/opt~/js/src/../../dist/include/js/HashTable.h:js::EmptyShape::getInitialShape(js::ExclusiveContext*, js::Class const*, js::TaggedProto, unsigned long, unsigned int) -10,201 -335 0 -1,871 -190 -5 -6 6 0 /home/jimb/moz/dbg/js/src/vm/Shape.cpp:js::ShapeTable::search(jsid, bool) -6,348 3 0 -904 0 0 0 0 0 /home/jimb/moz/dbg/js/src/opt~/js/src/../../dist/include/mozilla/HashFunctions.h:js::Atomize(js::ExclusiveContext*, char const*, unsigned long, js::InternBehavior) -5,664 9 0 -1,886 -49 10 -24 0 0 /home/jimb/moz/dbg/js/src/vm/Shape.h:js::ShapeTable::search(jsid, bool) -2,810 6 1 -125 15 0 -118 -3 0 /home/jimb/moz/dbg/js/src/opt~/js/src/../../dist/include/js/HashTable.h:js::jit::ValueNumberer::leader(js::jit::MDefinition*) -2,579 -201 -7 -1,712 9 -1 -15 23 0 /home/jimb/moz/dbg/js/src/vm/Interpreter.cpp:Interpret(JSContext*, js::RunState&) 2,421 85 5 1,614 1 0 0 0 0 /home/jimb/moz/dbg/js/src/vm/NativeObject.h:Interpret(JSContext*, js::RunState&) -1,321 5 2 60 12 4 0 0 0 /usr/src/debug////////glibc-2.20/string/../sysdeps/x86_64/strcmp.S:__strcmp_ssse3 -1,242 -129 -3 -552 -12 0 -460 -11 0 /home/jimb/moz/dbg/js/src/vm/Stack.cpp:js::jit::JitActivation::JitActivation(JSContext*, void*, bool) -1,188 -89 -3 -249 -56 0 -644 -18 0 /home/jimb/moz/dbg/js/src/vm/Stack-inl.h:js::jit::JitActivation::JitActivation(JSContext*, void*, bool)

Hannes, how should we proceed from here?

(In reply to Jim Blandy :jimb from comment #81) > I compared the two with cg_diff, and saw differences on the order of .2%, Sorry --- that should be .002%.

(In reply to Jim Blandy :jimb from comment #83) > Hannes, how should we proceed from here? Given the analysis it is clear that the fault isn't an increase in instruction count. As a result this is probably a perturbed alignment issue. Given that Activation has a new field it is quite possible. So there isn't really something we can do. Currently we align ionmonkey stuff on 16bits, since it wasn't worth to go 32bits even when we sometimes have things like this happening. I'm gonna mark the regression as wontfix. Thanks

Comment on attachment 8608086 [details] [diff] [review] add callee information to Javascript timeline markers I wish callers would ensure the parameters to stay alive, but if that is not how AutoEntryMonitor works, then it is.

(In reply to Pulsebot from comment #87) > https://hg.mozilla.org/integration/fx-team/rev/23e8df452487 This is causing "TypeError: frame is undefined: MarkerDetails.prototype.renderStackTrace@resource://gre/modules/commonjs/toolkit/loader.js -> resource:///modules/devtools/shared/timeline/marker-details.js:114:11" logspam in all m-dt runs.

(A subsequent patch landed so that error will occur in marker-details.js:206 now) What scenario would `frames[frameIndex]` result in no found frame? If this is expected, can just abort and be an easy fix but not sure if something more sinister is at play

(In reply to Ryan VanderMeulen [:RyanVM UTC-4] from comment #88) > (In reply to Pulsebot from comment #87) > > https://hg.mozilla.org/integration/fx-team/rev/23e8df452487 > > This is causing "TypeError: frame is undefined: > MarkerDetails.prototype.renderStackTrace@resource://gre/modules/commonjs/ > toolkit/loader.js -> > resource:///modules/devtools/shared/timeline/marker-details.js:114:11" > logspam in all m-dt runs. I found the problem & I'm working on a fix.

The bug here is that we feed a "phony" stack frame to stack.js. However, this frame does not have |parent|, |asyncParent| or |asyncCause| properties -- causing stack.js to emit something odd, and then later provoking an exception in marker-details.js. This patch fixes the problem by arranging to always have these fields on ProfileTimelineStackFrame. Currently none of these fields are ever set. So, this might seem like a hack. And it kind of is -- except that in the future we'll want to add asyncParent and asyncCause anyway, to attach async stacks to this object, so we might as well do it now.

I don't understand why adding those to the dictionary helps.

Is this to emulate http://mxr.mozilla.org/mozilla-central/source/toolkit/devtools/server/actors/utils/stack.js#107? Well, why only those properties then?

Comment on attachment 8609590 [details] [diff] [review] add fields to ProfileTimelineStackFrame Oh, we do have the other properties. Fine.

Adding the intermittent when frame is undefined here

The hazard build pointed out that this now needed a bit of additional rooting.

Comment on attachment 8610571 [details] [diff] [review] add fields to ProfileTimelineStackFrame Carrying over the r+.

landed attachment 8610571 [details] [diff] [review] https://hg.mozilla.org/integration/fx-team/rev/fadac2ce2915

Comment on attachment 8605388 [details] [diff] [review] Add SpiderMonkey API for reporting JavaScript entry points. Approval Request Comment [Feature/regressing bug #]: 1167252, the new performance tool [User impact if declined]: Won't ship the performance tool [Describe test coverage new/current, TreeHerder]: There are try pushes in Bug 1167252 with all patches needing uplift [Risks and why]: Requesting uplift for the accumulated changes in the performance tool since the 40 merge date, so these changes haven't had the full 6 weeks to bake. Risks are generally contained within devtools, specifically within the performance panel. [String/UUID change made/needed]: None

Comment on attachment 8608086 [details] [diff] [review] add callee information to Javascript timeline markers Approval Request Comment [Feature/regressing bug #]: 1167252, the new performance tool [User impact if declined]: Won't ship the performance tool [Describe test coverage new/current, TreeHerder]: There are try pushes in Bug 1167252 with all patches needing uplift [Risks and why]: Requesting uplift for the accumulated changes in the performance tool since the 40 merge date, so these changes haven't had the full 6 weeks to bake. Risks are generally contained within devtools, specifically within the performance panel. [String/UUID change made/needed]: The uuid on `interface nsIDocShell : nsIDocShellTreeItem` has changed

Comment on attachment 8610571 [details] [diff] [review] add fields to ProfileTimelineStackFrame Approval Request Comment [Feature/regressing bug #]: 1167252, the new performance tool [User impact if declined]: Won't ship the performance tool [Describe test coverage new/current, TreeHerder]: There are try pushes in Bug 1167252 with all patches needing uplift [Risks and why]: Requesting uplift for the accumulated changes in the performance tool since the 40 merge date, so these changes haven't had the full 6 weeks to bake. Risks are generally contained within devtools, specifically within the performance panel. [String/UUID change made/needed]: None

https://hg.mozilla.org/releases/mozilla-aurora/rev/50a6675e974b https://hg.mozilla.org/releases/mozilla-aurora/rev/1ff6d58a4e0a https://hg.mozilla.org/releases/mozilla-aurora/rev/98b12f19c7b3 https://hg.mozilla.org/releases/mozilla-aurora/rev/087c3f171562

Note: I had verbal confirmation for these uplifts from Sylvestre even before he's flagged them as a+. See https://bugzilla.mozilla.org/show_bug.cgi?id=1167252#c26

Comment on attachment 8605388 [details] [diff] [review] Add SpiderMonkey API for reporting JavaScript entry points. Change approved to skip one train as part of the spring campaign.

Comment on attachment 8610571 [details] [diff] [review] add fields to ProfileTimelineStackFrame Change approved to skip one train as part of the spring campaign.

Comment on attachment 8608086 [details] [diff] [review] add callee information to Javascript timeline markers Change approved to skip one train as part of the spring campaign.

Verified fixed on Aurora 40.0a2 (2015-06-04), using Windows 7 (x64), Ubuntu 14.04 (x64) and Mac OS X 10.8.5. Function names are now shown in the waterfall for javascript markers, each with a stack available in the sidebar, e.g. http://i.imgur.com/0WUPtmL.png.