It would be great if I could go from a 'Function call' timeline entry to a call stack showing me what code caused that event. Nick pointed out today that just knowing the function's name isn't enough if frameworks are used eg jquery event bindings.

We should have stack trace information for this. The marker details view needs a lot of love in general.

Ironically, we do not have stacks for JS markers. Tom, is this something you could look at?

There is no JS stack when you enter or leave JS, there is only a JS stack when you are inside JS. I think you have a false assumption...

That surprisingly makes sense. I guess what I'd assume we'd have is similar information to the flamegraph. I wonder if we could link these together somehow?

What would make sense is to try to capture any async stack that is going to be applied when entering JS. What is needed to make this work is to fetch the async stack from nsDocShell::NotifyJSRunToCompletionStart. However, this can only work if the async stack is registered before the AutoEntryScript is instantiated, and it isn't obvious to me that this is true. If it is not the case -- that is, if the AutoEntryScript is created first and then the async stack is set -- then some additional mechanism will be needed to get the async stack to the timeline marker. This also came up in https://bugzilla.mozilla.org/show_bug.cgi?id=1050500#c9 It's possible that the patch to add the needed infrastructure for source location information to Javascript markers (a dependency of bug 1050500, though not noted there yet) would also show how to solve the async stack issue.

(In reply to Tom Tromey :tromey from comment #5) > However, this can only work if the async stack is registered before > the AutoEntryScript is instantiated, and it isn't obvious to me that this is > true. E.g., consider this: https://bugzilla.mozilla.org/attachment.cgi?id=8589919&action=diff#a/dom/base/nsGlobalWindow.cpp_sec6 Here the async cause is being instantiated after the AutoEntryScript.

Tom, to make sure I understand, take the following code: ``` button.addEventListener("click", function handleClick () { setTimeout(openModal, 100); }); function openModal () { // stuff } ``` In this case, we'd have 2 JS markers -- one for the DOM event entry point, and another for the setTimeout entry point. For the setTimeout marker, we'd be able to get the async stack (`clickHandler()`), but we'd need to have async stacks on? Is there still overhead for async stack info?

(In reply to Jordan Santell [:jsantell] [@jsantell] from comment #7) > In this case, we'd have 2 JS markers -- one for the DOM event entry point, > and another for the setTimeout entry point. Yes. > For the setTimeout marker, we'd > be able to get the async stack (`clickHandler()`), but we'd need to have > async stacks on? Yes. This requires some instrumentation in the platform to capture stacks at the appropriate spot (when setTimeout is called) and then apply them as async stacks again later (when the timeout happens and the callback is invoked). One way to do this is to instrument each separate spot. Another way to do this might be to instrument CallbackObject to deal with the stack. That might be enough to instrument the most interesting parts of platform. Conceptually what this feature and what bug 1050500 share is that they want a sort of access to the "future stack frame" -- a callback has happened, we're about to enter JS, and what we'd like is access to the very next stack frame that will be created. If you want to see async stacks in action today, you can make a simple example using promises. These have already been instrumented and their stacks will show up in the timeline. > Is there still overhead for async stack info? Yes, see bug 1152893.

Removing this from devedition/perf-tool-v2 as we're still unclear what this means, async stacks have overhead, and like fitzgen said, doesn't really make sense to have a "stack" trace here as it unwinds, but maybe something we can do with async stacks. Either way, this is still a bit unclear, and we can always do something like jump to the flame chart of the same time duration, which seems to get information desired in a JS marker (essentially tracing function calls).

Oops, I forgot about this when I filed 1165446. From that bug: Javascript markers in the timeline should capture any pending async stack and attach it to the marker data. Note that this can't be done using CaptureCurrentStack, because at the point at which the marker is created, the view of the stack is inconsistent, in the sense that whether the newest frame is visible depends on whether the caller is JIT code. See bug 1050500 for some history. I think a viable plan is to modify AutoEntryMonitor so that the async stack and async cause are passed to the Entry method.

This isn't as simple as just grabbing the async stack. Instead we need the logic from SavedStacks::adoptAsyncStack.

Initial patch. I *think* this ought to work ok, but it crashes. After discussing with Nick it seems like an instance of bug 1157456.

This is unblocked now and seems to work. However, it exposed an oddity of how async stacks are represented. Suppose we have a frame that has an async parent. The parent will be on the frame -- but the async cause will be on the parent frame, like: newestFrame: {line, column, source, ..., asyncParent: nextFrame } nextFrame: { line, column, source, ..., asyncCause: "setTimeout handler" } Additionally, the async cause is part of a frame's identity: https://dxr.mozilla.org/mozilla-central/source/js/src/vm/SavedStacks.cpp#155 This seems strange for two reasons. First, for the patch in this bug, it means that we can't simply capture the pending async stack and use it on the timeline. Instead we must do something like SavedStacks::adoptAsyncStack and set the async cause on the newest frame of the captured stack. Second, it seems to me that while a given frame can have just a single async cause and async parent, a parent frame can have many async children with different causes. For example a function could call setTimeout and make a Promise -- yielding two different async causes. In the current design this would appear to be two different frames. It seems to me that the best route forward would be to move the async cause to the child frame. This enables more sharing and is more consistent as well. Failing that I will need to expose something like adoptAsyncStack for use by this patch. Nick, NI'ing you to see what you think.

> Additionally, the async cause is part of a frame's identity This has to be the case, otherwise the hashconsing would give you a frame that happened to have (or lack) an async cause when you didn't (or did) expect one. > Second, it seems to me that while a given frame can have just a single async cause > and async parent, a parent frame can have many async children with different causes. > For example a function could call setTimeout and make a Promise -- yielding two > different async causes. In the current design this would appear to > be two different frames. > > It seems to me that the best route forward would be to move the async cause to > the child frame. This enables more sharing and is more consistent as well. Agreed. Having the asyncCause on the same frame that has the async parent makes more sense than what we have now to me. I think I brought this up in the original bug that added async stacks support, and I remember Paolo had Reasons, but I don't remember them. I'd *really* like to avoid exposing something like adoptAsyncStack: it defeats the purpose of all this hashconsing we have gone to lengths for.

(In reply to Nick Fitzgerald [:fitzgen][:nf] from comment #15) > > It seems to me that the best route forward would be to move the async cause to > > the child frame. This enables more sharing and is more consistent as well. > > Agreed. Having the asyncCause on the same frame that has the async parent > makes more sense than what we have now to me. I think I brought this up in > the original bug that added async stacks support, and I remember Paolo had > Reasons, but I don't remember them. These seem on point: https://bugzilla.mozilla.org/show_bug.cgi?id=1083359#c78 https://bugzilla.mozilla.org/show_bug.cgi?id=1083359#c91 https://bugzilla.mozilla.org/show_bug.cgi?id=1083359#c93 I think even after this I still don't understand why the cause has to be on the parent frame, though. Wouldn't it work either way? > I'd *really* like to avoid exposing something like adoptAsyncStack: it > defeats the purpose of all this hashconsing we have gone to lengths for. The duplication is already happening for other code paths. And, I think we can limit it to a single frame in this case, so maybe not too bad. But I think it's worth trying to move asyncCause first.

With regard to the original question, it helps to think of the async cause as an edge on the graph of stack frames, in other words it is a property of the link between two frames, rather than the frame itself. As such, it can be represented on either of the linked frames. We put it on the stack frame that represents the point where the call is initiated. In fact, in the case of Promises, we want to clearly demarcate the point where the Promise object has been constructed - multiple "then" functions for the same Promise will point back to the same creation point, sharing the async parent frame. Note that "setTimeout handler" as an asyncCause is incorrect: it should read "setTimeout". This way, it's immediately clear that going to the source of a stack frame with an async cause takes you to the function call that caused the async behavior. The fact that the async cause does not appear on the same frame as the async parent is just an artifact of the way the stack is represented. If you imagine you use an array to represent stack frames instead, for example with stack[0] being the oldest and stack[n] being the newest, then parent/asyncParent disappears and the apparent oddity with it. (In reply to Tom Tromey :tromey from comment #14) > For example a function could call setTimeout and make a Promise -- yielding > two different async causes. In the current design this would appear to > be two different frames. That's normal, just like the same function can invoke two other sync functions. Probably the frames will have different line numbers as well. > It seems to me that the best route forward would be to move the async cause > to the child frame. Even if we wanted to do that (and I think we don't), this would involve a complete rewrite of the principal filtering (chrome frames must be made invisible to content, but still retain the information about the link being async) which is a major endeavor. (In reply to Tom Tromey :tromey from comment #16) > The duplication is already happening for other code paths. > And, I think we can limit it to a single frame in this case, Note that early incarnations of the original Async Stacks patch (before we decided to set the async cause at capture time rather than at handler call time) included a fairly simple function to change the async cause on a given frame, returning the newly created frame. I've not looked at the patch in depth since I'm not familiar with timeline markers, but from the discussion it seems you may want something like that here.

New version using a wrapper around adoptAsyncStack. Includes a test case now.

Comment on attachment 8627832 [details] [diff] [review] capture async stack frames on Javascript timeline markers This will need review from smaug for docshell changes but before that I would like to make sure I've done all the stack bits correctly...

Comment on attachment 8627832 [details] [diff] [review] capture async stack frames on Javascript timeline markers Review of attachment 8627832 [details] [diff] [review]: ----------------------------------------------------------------- ::: js/src/jsapi.h @@ +5290,5 @@ > > /* > + * This is a utility function for preparing an async stack to be used > + * by some other object. In ordinary cases you should not call this, > + * but instead should call CaptureCurrentStack. This should totally explain what non-ordinary cases are then. This comment basically just tells me "here be dragons, don't use this" which isn't really that useful for someone wondering why it *is* used in some given place. @@ +5293,5 @@ > + * by some other object. In ordinary cases you should not call this, > + * but instead should call CaptureCurrentStack. > + * > + * Here |asyncStack| is the async stack to prepare. It is recreated > + * in |cx|, and the newest frame is given |asyncCause| as its "copied into |cx|'s current compartment" ? Should definitely mention "compartment", not sure if "copied into" is better than "recreated in". Aside: why is it necessary to adopt the async stack instead of use a wrapper around it and avoid the copy? I remember asking about this before, but I can't remember your answer, sorry! It seems like working with wrappers is easier and more performant, if we can get away with it, we should.

(In reply to Nick Fitzgerald [:fitzgen][:nf] from comment #20) > Aside: why is it necessary to adopt the async stack instead of use a wrapper > around it and avoid the copy? I remember asking about this before, but I > can't remember your answer, sorry! It seems like working with wrappers is > easier and more performant, if we can get away with it, we should. I remember you asking but I don't know if I answered. I don't know the answer, but my reasoning for this approach is that I would have used CaptureCurrentStack here if that were possible[1]; and CaptureCurrentStack requires this call; and I don't know of any particular difference at this point that would make it ok *not* to adopt the stack. [1] It is not due to differences between the JIT and interpreter when calling into the AutoEntryMonitor; specifically, in the JIT case the new frame hasn't been pushed yet, while in the interpreter case, it has.

(In reply to Tom Tromey :tromey from comment #21) > I don't know the answer, but my reasoning for this approach is that > I would have used CaptureCurrentStack here if that were possible[1]; > and CaptureCurrentStack requires this call; and I don't know of any > particular difference at this point that would make it ok *not* to > adopt the stack. > > [1] It is not due to differences between the JIT and interpreter when > calling into the AutoEntryMonitor; specifically, in the JIT case the > new frame hasn't been pushed yet, while in the interpreter case, it has. The reason that SavedStacks::insertFrames adopts the async stack into the current compartment is two-fold: 1. We don't want to keep alive an unbounded number of async stack frames. 2. There is a requirement that a SavedFrame's parent and asyncParent be same compartment. I think it could be nice to lift (2), at least for async parents. Either way, it isn't clear to me that either of those things apply here, and so if we can get away without coping the stack, that seems like a clear win. I guess it is fine as a follow up, if you really want to get this functionality landed first.

(In reply to Nick Fitzgerald [:fitzgen][:nf] from comment #22) > 2. There is a requirement that a SavedFrame's parent and asyncParent be same > compartment. > > I think it could be nice to lift (2), at least for async parents. We discussed this on irc and the conclusion was: <fitzgen_irccloud> tromey: as I think about it more, I think the issue is that a SavedFrame's parent reserved slot expects a SavedFrame object, but there are assertion failures if you put a non-same-compartment thing in a reserved slot, so we would need to do a lot of manual wrapping and unwrapping, which is error prone (and sec-bug prone) [10:56] ... and this remains an issue for the async stack -- since we have to copy over the newest frame to add the asyncCause, and then the above applies to any frames older than this.

Updated comment and rebased.

Comment on attachment 8628406 [details] [diff] [review] capture async stack frames on Javascript timeline markers > nsDocShell::NotifyJSRunToCompletionStart(const char* aReason, > const char16_t* aFunctionName, > const char16_t* aFilename, >- const uint32_t aLineNumber) >+ const uint32_t aLineNumber, >+ JS::Handle<JS::Value> asyncStack, >+ JS::Handle<JS::Value> asyncCause) aFoo >--- a/docshell/base/nsIDocShell.idl >+++ b/docshell/base/nsIDocShell.idl >@@ -1026,17 +1026,19 @@ interface nsIDocShell : nsIDocShellTreeItem update uuid > private: > // A subclass of AutoEntryMonitor that notifies the docshell. > class DocshellEntryMonitor : public JS::dbg::AutoEntryMonitor > { > public: > DocshellEntryMonitor(JSContext* aCx, const char* aReason); > >- void Entry(JSContext* aCx, JSFunction* aFunction) override >+ void Entry(JSContext* aCx, JSFunction* aFunction, >+ JS::HandleValue asyncStack, JS::HandleString asyncCause) override > { >- Entry(aCx, aFunction, nullptr); >+ Entry(aCx, aFunction, nullptr, asyncStack, asyncCause); > } > >- void Entry(JSContext* aCx, JSScript* aScript) override >+ void Entry(JSContext* aCx, JSScript* aScript, >+ JS::HandleValue asyncStack, JS::HandleString asyncCause) override > { >- Entry(aCx, nullptr, aScript); >+ Entry(aCx, nullptr, aScript, asyncStack, asyncCause); > } > > void Exit(JSContext* aCx) override; > > private: >- void Entry(JSContext* aCx, JSFunction* aFunction, JSScript* aScript); >+ void Entry(JSContext* aCx, JSFunction* aFunction, JSScript* aScript, >+ JS::HandleValue asyncStack, JS::HandleString asyncCause); JS::Handle<JS::Value>, not JS::HandleValue outside JS engine. (I thought js engine was also moving away from HandleFoo stuff) Arguments should be named aFoo ... the rest is js/* stuff But please explain why we don't need to care about compartments here. Is it ok to be in any compartment when JS::CaptureAsyncStack is called?

(In reply to Olli Pettay [:smaug] from comment #25) > aFoo Sorry about that. I have this problem whenever I cross the spidermonkey/gecko barrier. I'll try to remember next time. > But please explain why we don't need to care about compartments here. > Is it ok to be in any compartment when JS::CaptureAsyncStack is called? I think the code starting from nsDocShell::PopProfileTimelineMarkers (which is what calls AddDetails, which is what calls CaptureAsyncStack) is consistent in its choice of context to use, and thus, IIUC, its choice of compartment. CaptureAsyncStack copies the saved stack trace into the appropriate compartment.

Address initial review comments.

Comment on attachment 8628477 [details] [diff] [review] capture async stack frames on Javascript timeline markers Review of attachment 8628477 [details] [diff] [review]: ----------------------------------------------------------------- r=me for the js bits ::: js/public/Debug.h @@ +360,5 @@ > // actual closure we are running, but only the canonical function object to > // which the script refers. > + virtual void Entry(JSContext* cx, JSFunction* function, > + HandleValue asyncStack, > + HandleString asyncCause) = 0; Let's say something about these new parameters in the comment above. ::: js/src/jsapi.h @@ +5338,5 @@ > + * |cx|'s current compartment, and the newest frame is given > + * |asyncCause| as its asynchronous cause. If |maxFrameCount| is > + * non-zero, capture at most the youngest |maxFrameCount| frames. The > + * new stack object is written to |stackp|. Returns true on success, > + * or sets an exception and returns |false| on error. Thanks for writing this comment, its a big improvement over the last iteration.

Comment on attachment 8628477 [details] [diff] [review] capture async stack frames on Javascript timeline markers Given that paolo implemented adoptAsyncStack, I'd prefer if he could verify whether we need to enter some particular compartment before calling it. It is not obvious from the code. Don't use JS::HandleValue outside JS engine. With those , r+

Comment on attachment 8628477 [details] [diff] [review] capture async stack frames on Javascript timeline markers As far as I can tell, you don't need to enter a specific compartment when using adoptAsyncStack. I'd suggest renaming the function chain leading to adoptAsyncStack, for example I think "Current" in SaveCurrentStack is misleading. I'd include Adopt in the names. It's a shame we cannot use CaptureCurrentStack here - might be worth looking into invoking the callback later in the Activation process, so that this becomes possible. Also, a reminder that we might want to remove the " handler" / " callback" part from the causeName (that ends up hidden in the waterfall view anyways) and maybe just use the asyncCause from the stack frame there. I didn't see a test case for the "script" path in the Activation code (as opposed to the "function" path). Can we have one?

(In reply to :Paolo Amadini from comment #30) > I'd suggest renaming the function chain leading to adoptAsyncStack, for > example I think "Current" in SaveCurrentStack is misleading. That is a pre-existing name, not something introduced in this patch. > I'd include Adopt in the names. Not sure if you still want this given the above. I avoided it because it didn't seem obviously better, to me, than "CaptureAsyncStack"; particularly because the latter is analogous to the existing "CaptureCurrentStack". > It's a shame we cannot use CaptureCurrentStack here - might be worth looking > into invoking the callback later in the Activation process, so that this > becomes possible. See https://bugzilla.mozilla.org/show_bug.cgi?id=1050500#c52 > I didn't see a test case for the "script" path in the Activation code (as > opposed to the "function" path). Can we have one? I'll try to write one.

(In reply to Tom Tromey :tromey from comment #31) > > I'd suggest renaming the function chain leading to adoptAsyncStack, for > > example I think "Current" in SaveCurrentStack is misleading. > > That is a pre-existing name, not something introduced in this patch. I totally messed up what I was writing, sorry. I think "Save" in "saveAsyncStack" and "Capture" in "CaptureAsyncStack" are misleading, as they're not saving or capturing the stack... they make it look similar to "saveCurrentStack" and "CaptureCurrentStack" that are indeed about stack capturing. > it didn't seem obviously better, to me, than "CaptureAsyncStack"; > particularly > because the latter is analogous to the existing "CaptureCurrentStack". Yeah, names are analogous but they do different things. The former doesn't capture the stack, it copies an existing one (if necessary) and rewrites the last frame.

(In reply to :Paolo Amadini from comment #32) > I totally messed up what I was writing, sorry. I think "Save" in > "saveAsyncStack" and "Capture" in "CaptureAsyncStack" are misleading, as > they're not saving or capturing the stack... they make it look similar to > "saveCurrentStack" and "CaptureCurrentStack" that are indeed about stack > capturing. Using "adoptAsyncStack" is a bit weird because there is already a function of that name in SavedStacks, and I didn't want to overload; especially not with one overload public and one private. Nick suggested CopyAsyncStack, so that's what I went with.

Rebased. Renamed some functions. Added a script test. Fixed a couple of minor things found by testing a debug build locally.

Fixlet for check_spidermonkey_style error.

Comment on attachment 8634301 [details] [diff] [review] capture async stack frames on Javascript timeline markers Carrying over r+

Backed out for various crashes as shown in bug 1184752. https://hg.mozilla.org/integration/mozilla-inbound/rev/7a5dd58d1b3d

Rebased. This moves things around a bit due to the timeline marker refactorings, but doesn't substantially change anything, so I'm carrying over the r+.

Rebased.

I've done several try runs with this and I can't reproduce the crashes that caused it to be backed out. (That last run looks pretty crashy but I am seeing those crashes without this patch...) My theory is that this patch exposed some latent bug that was fixed some other way. I don't have much support for this theory other than the fact that I can't reproduce the crashes, though. Still, I'd like to re-request landing.

Hi Tom, this failed to apply: Hunk #1 succeeded at 39 with fuzz 1 (offset -3 lines). patching file docshell/base/timeline/JavascriptTimelineMarker.h Hunk #1 FAILED at 15 1 out of 1 hunks FAILED -- saving rejects to file docshell/base/timeline/JavascriptTimelineMarker.h.rej patching file js/src/jsapi.cpp Hunk #2 FAILED at 6328 1 out of 2 hunks FAILED -- saving rejects to file js/src/jsapi.cpp.rej patch failed, unable to continue (try -v) patch failed, rejects left in working directory errors during apply, please fix and refresh Bug-1160307---capture-async-stack-frames-on-Javasc.patch

Rebased.

I've rebased, so let's please try that again.