Bug 163230 – Web Inspector: Debugger should have an option for showing asynchronous call stacks

• Status: RESOLVED
• Resolution: FIXED
• Component: Web Inspector

[Matt Baker]

Summary:
Debugger should have an option for showing asynchronous call stacks. Currently when stepping through a callback function that was passed to requestAnimationFrame, setTimeout, etc, it isn't possible to view call frames prior to the callback.

For example:

1: function bar() {
2:    debugger;
3: }
4: function foo() {
5:    requestAnimationFrame(bar);
6: }
7: foo();

The debugger will pause on line 2, and show the call stack:
0: bar()

But it would be better to show:
0: bar()
1: requestAnimationFrame
2: foo()

Notes:
In this example, frame 0 is a normal call frame, frame 1 is an "asynchronous boundary", and frame 2 is an asynchronous frame. An asynchronous boundary shouldn't be selectable in the UI, serving only to show a boundary between the normal call stack and the asynchronous call stack. An asynchronous call frame should be selectable, but shouldn't become the active call frame. Instead we should just jump to the source code location.

[Radar WebKit Bug Importer]

<rdar://problem/28698683>

[Matt Baker]

Created attachment 291129 [details]
Patch

[Matt Baker]

Comment on attachment 291129 [details]
Patch

This is a WIP. Needs tests, and InspectorDebuggerAgent is pretty hacked together.

[Matt Baker]

Created attachment 291130 [details]
[Image] setTimeout call stack

[Matt Baker]

Created attachment 291131 [details]
[Video] requestAnimationFrame stepping

[Timothy Hatcher]

Very cool!

We likely want a divider of some sort between the active stack and the async stack. Also, I am not sure it needs to be a togglable button, why not on all the time?

[Build Bot]

Comment on attachment 291129 [details]
Patch

Attachment 291129 [details] did not pass mac-debug-ews (mac):
Output: http://webkit-queues.webkit.org/results/2257187

New failing tests:
imported/w3c/web-platform-tests/html/semantics/embedded-content/the-canvas-element/security.dataURI.html

[Build Bot]

Created attachment 291148 [details]
Archive of layout-test-results from ews117 for mac-yosemite

The attached test failures were seen while running run-webkit-tests on the mac-debug-ews.
Bot: ews117  Port: mac-yosemite  Platform: Mac OS X 10.10.5

[Joseph Pecoraro]

(In reply to comment #6)
> Very cool!

Yes, this is awesome!!!

> We likely want a divider of some sort between the active stack and the async stack.

I agree.

Currently whenever you select a CallFrame in the Call Stack we set the Quick Console to evaluate in that CallFrame's context. That is even the case for Tail Deleted Call Frames in ES6. However, for these Async CallFrames, the call frame has gone away. So while we take the user to the right location, we don't put them into a place where they can evaluate in that context. I see from the video that selecting an Async CallFrame doesn't change the ">" indicator, so that is good. But I do think there needs to be some small more visible separator between the live and dead async call frames instead of just an unselectable call frame. Maybe styling this tree element differently would be enough.

> Also, I am not sure it needs to be a togglable button, why not on all the time?

Depending on the performance / memory cost of this, we might want to keep something in the protocol so that while the Timeline is running we don't record async call frames. However, I suspect this won't be a problem in most cases.

[Joseph Pecoraro]

Comment on attachment 291129 [details]
Patch

View in context: https://bugs.webkit.org/attachment.cgi?id=291129&action=review

r- because this needs tests and should be easily testable!

> Source/JavaScriptCore/inspector/agents/InspectorDebuggerAgent.cpp:138
> +    m_asyncCallStackEnabled = active;

This can bail if the value is not changing.

This state should return to the default value (false) somewhere. InspectorDebuggerAgent::disable seems appropriate. It may want to just call setAsyncCallStackActive(ignored, false) so as to get the same clearing behavior.

> Source/JavaScriptCore/inspector/agents/InspectorDebuggerAgent.cpp:836
> +    auto asyncCallFrames = Inspector::Protocol::Array<Inspector::Protocol::Console::CallFrame>::create();

AsyncCallFrames are optional we could avoid sending an empty array when there aren't async call frames.

> Source/JavaScriptCore/inspector/agents/InspectorDebuggerAgent.cpp:837
> +    if (m_currentAsyncCallbackIdentifier.first != static_cast<unsigned>(AsynchronousCallType::None)) {

m_currentAsyncCallbackIdentifier could be an Optional, in which case not having a value would be enough instead of using a "None" enum value and having to check for it.

> Source/JavaScriptCore/inspector/agents/InspectorDebuggerAgent.h:58
> +enum class AsynchronousCallType : unsigned {
> +    None,
> +    RequestAnimationFrame,
> +    Timer,
> +};

This is a great start! Eventually there will be more we will certainly want. Here are a few big ones:

    • Promise resolution (when a Promise resolved or rejected)
    • XMLHttpRequest / Fetch start (when an Async network request started, XHR.send, window.fetch)

On top of this, there are lots of other opportunities which you've probably seen:
https://www.html5rocks.com/en/tutorials/developertools/async-call-stack/

> Source/JavaScriptCore/inspector/agents/InspectorDebuggerAgent.h:73
> +    void setAsyncCallStackActive(ErrorString&, bool active) final;

In Blink they use a protocol command: Debugger.setAsyncCallStackDepth, where 0 means disabled, and >0 means active. I imagine there could be scenarios, especially with Promises, where async call stacks would grow infinitely. Having a maximum sounds like it could be useful.

> Source/JavaScriptCore/inspector/agents/InspectorDebuggerAgent.h:165
> +    typedef std::pair<unsigned, int> AsyncCallbackIdentifier;

Can this pair just be std::pair<AsynchronousCallType, int>? The coercion to/from unsigned seems unnecessary.

Or perhaps keeping it pair<unsigned, int> / pair<String, int> but using protocol generated values since having types named "RequestAnimationFrame" in JavaScriptCore is weird as it is a Web feature not a JavaScript feature.

You can get protocol generated values with:

    // Debugger.json
    "types": [
        ...
        {
            "id": "AsyncCallType",
            "type": "string",
            "enum": ["timer", "requestAnimationFrame", "other"],
            "description": "..."
        },
        ...
    ]

Which exposes size_t enum values (which could be cast to unsigned):

    Inspector::Protocol::Debugger::AsyncCallType::Timer
    Inspector::Protocol::Debugger::AsyncCallType::RequestAnimationFrame
    Inspector::Protocol::Debugger::AsyncCallType::Other

And their String values via:

    Inspector::Protocol::InspectorHelpers::getEnumConstantValue(<type-above>)

> Source/JavaScriptCore/inspector/protocol/Debugger.json:138
> +            "name": "setAsyncCallStackActive",

These protocol changes need tests.

> Source/WebInspectorUI/UserInterface/Controllers/DebuggerManager.js:72
> +            this._asyncCallStackEnabledSetting = new WebInspector.Setting("async-call-stack-enabled", false);

This is a useful feature that should definitely be enabled by default!

> Source/WebInspectorUI/UserInterface/Controllers/DebuggerManager.js:540
> +        this._asyncStackTrace = asyncStackTracePayload ? WebInspector.StackTrace.fromPayload(asyncStackTracePayload) : null;
>          this._activeCallFrame = this._callFrames[0];

`this._asyncStackTrace` should be initialized in the constructor and cleared when we are not paused (like this._activeCallFrame). Probably in _didResumeInternal.

> Source/WebInspectorUI/UserInterface/Views/DebuggerSidebarPanel.js:108
> +            let asyncStackTraceImage = {src: "Images/AsyncStackTrace.svg", width: 16, height: 16};

What does this show for the GTK port which doesn't have this image yet?

[Matt Baker]

Comment on attachment 291129 [details]
Patch

View in context: https://bugs.webkit.org/attachment.cgi?id=291129&action=review

>> Source/JavaScriptCore/inspector/agents/InspectorDebuggerAgent.h:58
>> +};
> 
> This is a great start! Eventually there will be more we will certainly want. Here are a few big ones:
> 
>     • Promise resolution (when a Promise resolved or rejected)
>     • XMLHttpRequest / Fetch start (when an Async network request started, XHR.send, window.fetch)
> 
> On top of this, there are lots of other opportunities which you've probably seen:
> https://www.html5rocks.com/en/tutorials/developertools/async-call-stack/

Saw them :)

I planned for additional scenarios to be handled in follow up patches.

>> Source/JavaScriptCore/inspector/agents/InspectorDebuggerAgent.h:73
>> +    void setAsyncCallStackActive(ErrorString&, bool active) final;
> 
> In Blink they use a protocol command: Debugger.setAsyncCallStackDepth, where 0 means disabled, and >0 means active. I imagine there could be scenarios, especially with Promises, where async call stacks would grow infinitely. Having a maximum sounds like it could be useful.

This seems like a better approach.

>> Source/WebInspectorUI/UserInterface/Controllers/DebuggerManager.js:72
>> +            this._asyncCallStackEnabledSetting = new WebInspector.Setting("async-call-stack-enabled", false);
> 
> This is a useful feature that should definitely be enabled by default!

The consensus seems to be that this should always be enabled (and turned off in the backend during timeline recording). If so, this code will be removed. We will probably want to retain a protocol method to allow for changing the stack depth via the Settings tab in the future.

[Matt Baker]

Created attachment 294182 [details]
[Image] new divider item UI

I'm pretty happy with how this feels as a non-clickable separator for the async portion of the stack.

[Matt Baker]

Created attachment 294184 [details]
[Image] more UI

[Nikita Vasilyev]

Created attachment 294192 [details]
[Animated GIF] Thin separator

(In reply to comment #13)
> Created attachment 294184 [details]
> [Image] more UI

Looks good!

A couple of suggestions:

1. Use a 0.5px border line on Retina. Section borders are 0.5px, I think the divider line should be the same width.

2. Add some spacing to the sides of the divider line to make it clear that it's part of a section, and not a new section.

[Matt Baker]

(In reply to comment #14)
> Created attachment 294192 [details]
> [Animated GIF] Thin separator
> 
> (In reply to comment #13)
> > Created attachment 294184 [details]
> > [Image] more UI
> 
> Looks good!
> 
> A couple of suggestions:
> 
> 1. Use a 0.5px border line on Retina. Section borders are 0.5px, I think the
> divider line should be the same width.
> 
> 2. Add some spacing to the sides of the divider line to make it clear that
> it's part of a section, and not a new section.

I agree with both, nice suggestions.

[Matt Baker]

Created attachment 294219 [details]
Patch

[Build Bot]

Comment on attachment 294219 [details]
Patch

Attachment 294219 [details] did not pass mac-ews (mac):
Output: http://webkit-queues.webkit.org/results/2481339

New failing tests:
inspector/debugger/async-call-stack.html

[Build Bot]

Created attachment 294223 [details]
Archive of layout-test-results from ews101 for mac-yosemite

The attached test failures were seen while running run-webkit-tests on the mac-ews.
Bot: ews101  Port: mac-yosemite  Platform: Mac OS X 10.10.5

[Build Bot]

Comment on attachment 294219 [details]
Patch

Attachment 294219 [details] did not pass mac-wk2-ews (mac-wk2):
Output: http://webkit-queues.webkit.org/results/2481348

New failing tests:
inspector/debugger/async-call-stack.html

[Build Bot]

Created attachment 294225 [details]
Archive of layout-test-results from ews107 for mac-yosemite-wk2

The attached test failures were seen while running run-webkit-tests on the mac-wk2-ews.
Bot: ews107  Port: mac-yosemite-wk2  Platform: Mac OS X 10.10.5

[Matt Baker]

(In reply to comment #20)
> Created attachment 294225 [details]
> Archive of layout-test-results from ews107 for mac-yosemite-wk2
> 
> The attached test failures were seen while running run-webkit-tests on the
> mac-wk2-ews.
> Bot: ews107  Port: mac-yosemite-wk2  Platform: Mac OS X 10.10.5

All tests should pass once this lands:
https://bugs.webkit.org/show_bug.cgi?id=161951

[Build Bot]

Comment on attachment 294219 [details]
Patch

Attachment 294219 [details] did not pass mac-debug-ews (mac):
Output: http://webkit-queues.webkit.org/results/2484232

New failing tests:
inspector/debugger/async-call-stack.html

[Build Bot]

Created attachment 294248 [details]
Archive of layout-test-results from ews114 for mac-yosemite

The attached test failures were seen while running run-webkit-tests on the mac-debug-ews.
Bot: ews114  Port: mac-yosemite  Platform: Mac OS X 10.10.5

[Matt Baker]

Created attachment 294259 [details]
[Image] UI from patch

Changes that made it into the patch:
- Dividers are now 0.5 px on retina
- 2px of spacing between divider lines and the icon & label

Things that didn't:
- Dashed divider: looked not-so-good, and too closely resembles Xcode's call stack tree divider. Xcode uses the dashed divider as a placeholder meaning "items were filtered/omitted", not to divide the tree into sections.
- Spacing between left and right edge of the tree element and the divider lines. This would require some CSS magic, or a different approach to creating the lines. May investigate in the future.

[Nikita Vasilyev]

Comment on attachment 294219 [details]
Patch

View in context: https://bugs.webkit.org/attachment.cgi?id=294219&action=review

> Source/WebInspectorUI/UserInterface/Views/CallFrameTreeElement.css:67
> +@media (-webkit-min-device-pixel-ratio: 2) {

The media query block isn't necessary. 0.5px rounds up to 1px. It used to round down to 0, but it was changed this year.

[Devin Rousso]

Comment on attachment 294219 [details]
Patch

View in context: https://bugs.webkit.org/attachment.cgi?id=294219&action=review

First off, this is omega-cool (☞ﾟヮﾟ)☞  Huge fan of this idea and I think it looks straight out of Star Trek :D

> Source/WebInspectorUI/UserInterface/Views/CallFrameTreeElement.css:64
> +    background-color: var(--border-color);

NIT: you may want to add a `vertical-align` of 1px or something, because I am seeing the line be slightly off vertically.

> Source/WebInspectorUI/UserInterface/Views/Variables.css:56
> +    --text-color-medium: hsl(0, 0%, 50%);

This seems like a weird name.  Maybe `--text-color-grey-medium`

[Joseph Pecoraro]

Comment on attachment 294219 [details]
Patch

View in context: https://bugs.webkit.org/attachment.cgi?id=294219&action=review

r- because of the >1 Boundary case. The patch itself is very clean and easy to read though, so I suspect it shouldn't be hard to extend this to the N case.

> Source/JavaScriptCore/inspector/agents/InspectorDebuggerAgent.cpp:146
> +    m_asyncCallStackDepth = depth;
> +    if (!m_asyncCallStackDepth)

Style: newline between these, they are separate thoughts.

> Source/JavaScriptCore/inspector/agents/InspectorDebuggerAgent.cpp:228
> +    RefPtr<ScriptCallStack> callStack = createScriptCallStack(exec, m_asyncCallStackDepth);
> +    if (callStack && callStack->size()) {
> +        AsyncCallData data = {
> +            createScriptCallStack(exec, m_asyncCallStackDepth),
> +            singleShot
> +        };
> +        m_asyncCallIdentifierToData.set(std::make_pair(asyncCallType, callbackIdentifier), data);
> +    }

I don't see how this will stack to >1 call stack. It seems the AsyncCallData would need the currentAsyncCallIdentifier right now, in order to get the previous async call stack for the current call stack being scheduled.

For example if I have:

    <script>
    function entry() { setInterval(intervalFired, 100); }
    function intervalFired() { setTimeout(timerFired, 10); }
    function timerFired() { debugger; }
    entry()
    </script>

I would want my call stack to include the entire async call stack, for the local "setTimeout" and its parent "setInterval":

    [ƒ] timerFired
    [N] -- setTimeout -------
    [ƒ] intervalFired
    [N] -- setInterval -------
    [ƒ] entry

Right now m_currentAsyncCallIdentifier will get us the current AsyncCallData, but we won't be able to got further and get it's parent.

> Source/JavaScriptCore/inspector/agents/InspectorDebuggerAgent.h:96
> +    void didScheduleAsyncCall(JSC::ExecState*, int asyncCallIdentifier, int callbackIdentifier, bool singleShot);
> +    void didCancelAsyncCall(int asyncCallIdentifier, int callbackIdentifier);
> +    void willDispatchAsyncCall(int asyncCallIdentifier, int callbackIdentifier);

Nit: `asyncCallIdentifier` => `asyncCallType`

> Source/JavaScriptCore/inspector/agents/InspectorDebuggerAgent.h:163
> +    typedef HashMap<AsyncCallIdentifier, RefPtr<ScriptCallStack>> AsyncCallIdentifierToScriptCallStack;

Nit: Unused

> Source/JavaScriptCore/inspector/agents/InspectorDebuggerAgent.h:170
> +    typedef HashMap<AsyncCallIdentifier, AsyncCallData> AsyncCallIdentifierToCallData;

Style: I find it easier to just inline this at the member. The intermediate typedef just means we have to do two searches instead of 1 to find what the type is. Now that we have `auto` we rarely need this helper to simplify typing of ::iterator.

> Source/JavaScriptCore/inspector/protocol/Debugger.json:140
> +            "name": "setAsyncCallStackDepth",
> +            "parameters": [

Style: On new commands we've been putting the description immediately after the `name`. The style makes the JSON much easier to read.

> Source/JavaScriptCore/inspector/protocol/Debugger.json:332
> +                { "name": "asyncCallFrames", "type": "array", "items": { "$ref": "Console.CallFrame" }, "optional": true, "description": "Call stack at the time the virtual machine scheduled the asyncronous callback." }

Heh, this description sounds weird. "At the time the virtual machine" should be less implementation specific and more JavaScript catered. "Call stack from the point where this asynchronous operation was scheduled" or something generic like that.

> Source/WebCore/inspector/InspectorInstrumentation.cpp:88
> +    AsyncCallTypeTimer

Style: Add the trailing comma, we expect this list to grow.

Maybe we should explicitly put the type as int, since we cast to int going into JavaScriptCore. Even better if `enum class AsyncCallType : int {}` works with implicitly casting to int (I'm not sure though). The enum class would eliminate the name duplication.

> Source/WebInspectorUI/UserInterface/Controllers/DebuggerManager.js:78
> +        // COMPATIBILITY (iOS 10): Debugger.setAsyncCallStackDepth did not exist yet.
> +        if (DebuggerAgent.setAsyncCallStackDepth) {

Lets put this after DebuggerAgent.setPauseOnAssertions.

We will also need to do this in DebuggerManager.prototype.initializeTarget, to set the same value in Workers when they connect. There we won't need the if check.

> Source/WebInspectorUI/UserInterface/Controllers/DebuggerManager.js:279
> +    get asyncCallStackDepth() { return this._asyncCallStackDepthSetting.value; }

Style: If there is a getter / setter like this I suggest we don't make the getter a single line. I don't know how others feel about this though.

> Source/WebInspectorUI/UserInterface/Controllers/DebuggerManager.js:287
> +        DebuggerAgent.setAsyncCallStackDepth(this._asyncCallStackDepthSetting.value);

This should update all targets:

    for (let target of WebInspector.targets)
        target.DebuggerAgent.setAsyncCallStackDepth(...)

> Source/WebInspectorUI/UserInterface/Models/DebuggerData.js:49
> +    get asyncCallFrames() { return this._asyncStackTrace ? this._asyncStackTrace.callFrames : null; }

Just keep this asyncStackTrace, and let clients deal with digging into the call frames?

> Source/WebInspectorUI/UserInterface/Views/CallFrameTreeElement.js:57
> +    get isAsyncBoundaryCallFrame() { return this._isAsyncBoundaryCallFrame; }

Style: Same comment here about multiline.

Having thought about this a bit more, perhaps this should just be a constructor parameter.

    • Is there any reason we would not know this at construction time?
    • Is there any reason we would want to change this after construction?

> Source/WebInspectorUI/UserInterface/Views/CallFrameTreeElement.js:65
> +        this._isAsyncBoundaryCallFrame = x;
> +        if (this._isAsyncBoundaryCallFrame)

Style: Newline between these. They are separate thoughts.

> Source/WebInspectorUI/UserInterface/Views/CallFrameTreeElement.js:71
> +        this._updateSubtitle();

I actually don't see how the subtitle can change. Perhaps this can move back into the constructor?

> Source/WebInspectorUI/UserInterface/Views/DebuggerSidebarPanel.js:660
> +        let asyncBoundaryCallFrame = asyncCallFrames[0];
> +        console.assert(asyncBoundaryCallFrame.nativeCode);

Ahh, interesting. We might want to consider if we need to make this more general before committing a first version where we may need to change.

    • This requires a Console.CallFrame be the boundary.
        - works great for JS function boundaries (setTimeout, rAF, dispatchEvent, Promises, etc)
    • How would we handle async/await boundaries?
        - Now it is not so much a function as language construct
        - For comparison this is what Chrome does: https://twitter.com/umaar/status/793777970599104512?lang=en

This could work with a Console.CallFrame if we provided a fake functionName, but that seems hacky.

Further, I don't see how this would handle the >1 boundary case. (... setInterval | ... setTimeout | ... current).

Blink uses a linked list of StackTraces where each StackTrace may have a description (to solve the async case). I like the StackTrace linked list approach. I'm not sure I like "description". I'd rather something that explicitly says the boundary ("topCallFrameIsBoundary" for your cases, and "boundaryAwaitFunctionName" for the async/await cases). Just brainstorming here.
https://github.com/v8/v8/blob/master/src/inspector/js_protocol.json#L200

> LayoutTests/ChangeLog:13
> +        * inspector/debugger/async-call-stack-expected.txt: Added.
> +        * inspector/debugger/async-call-stack.html: Added.

I think we need at least one test for a >1 Async Call Stack boundary. r- until then or if you can convince me it should be a followup. But I think it should probably come at the same time as the initial patch given it introduces protocol changes already. I'm happy to review larger patches =)

> LayoutTests/inspector/debugger/async-call-stack.html:89
> +    function setup(resolve) {
> +        InspectorTest.log("Save DebuggerManager.asyncCallStackDepth");
> +        window.__savedCallStackDepth = WebInspector.debuggerManager.asyncCallStackDepth;
> +        resolve();
> +    }

No need to do window.__savedCallStackDepth right? You could just use a local variable? Alternatively TestCase setup/teardown could pass the testCase as a parameter and you could store state on the test case itself!

[Joseph Pecoraro]

Comment on attachment 294219 [details]
Patch

View in context: https://bugs.webkit.org/attachment.cgi?id=294219&action=review

>> LayoutTests/inspector/debugger/async-call-stack.html:89
>> +    }
> 
> No need to do window.__savedCallStackDepth right? You could just use a local variable? Alternatively TestCase setup/teardown could pass the testCase as a parameter and you could store state on the test case itself!

By local I meant closure variable. Outside of `setup` and `teardown` but inside of `test`.

[Matt Baker]

Comment on attachment 294219 [details]
Patch

View in context: https://bugs.webkit.org/attachment.cgi?id=294219&action=review

>> Source/JavaScriptCore/inspector/agents/InspectorDebuggerAgent.cpp:228
>> +    }
> 
> I don't see how this will stack to >1 call stack. It seems the AsyncCallData would need the currentAsyncCallIdentifier right now, in order to get the previous async call stack for the current call stack being scheduled.
> 
> For example if I have:
> 
>     <script>
>     function entry() { setInterval(intervalFired, 100); }
>     function intervalFired() { setTimeout(timerFired, 10); }
>     function timerFired() { debugger; }
>     entry()
>     </script>
> 
> I would want my call stack to include the entire async call stack, for the local "setTimeout" and its parent "setInterval":
> 
>     [ƒ] timerFired
>     [N] -- setTimeout -------
>     [ƒ] intervalFired
>     [N] -- setInterval -------
>     [ƒ] entry
> 
> Right now m_currentAsyncCallIdentifier will get us the current AsyncCallData, but we won't be able to got further and get it's parent.

New AsyncCallData definition:

struct AsyncCallData {
    RefPtr<ScriptCallStack> callStack;
    Optional<AsyncCallIdentifier> parentAsyncCallIdentifier { Nullopt };
    bool singleShot { true };
    int referenceCount { 0 };
};

>> Source/JavaScriptCore/inspector/agents/InspectorDebuggerAgent.h:96
>> +    void willDispatchAsyncCall(int asyncCallIdentifier, int callbackIdentifier);
> 
> Nit: `asyncCallIdentifier` => `asyncCallType`

Nice catch, was still using old name!

>> Source/WebCore/inspector/InspectorInstrumentation.cpp:88
>> +    AsyncCallTypeTimer
> 
> Style: Add the trailing comma, we expect this list to grow.
> 
> Maybe we should explicitly put the type as int, since we cast to int going into JavaScriptCore. Even better if `enum class AsyncCallType : int {}` works with implicitly casting to int (I'm not sure though). The enum class would eliminate the name duplication.

An implicit conversion from an enum class (even with a type) isn't possible.

>> Source/WebInspectorUI/UserInterface/Controllers/DebuggerManager.js:279
>> +    get asyncCallStackDepth() { return this._asyncCallStackDepthSetting.value; }
> 
> Style: If there is a getter / setter like this I suggest we don't make the getter a single line. I don't know how others feel about this though.

I've been finding it awkward, and would be glad to adopt the convention:

"If one part of the getter / setter is multiline, both parts should be."

>> Source/WebInspectorUI/UserInterface/Views/CallFrameTreeElement.js:57
>> +    get isAsyncBoundaryCallFrame() { return this._isAsyncBoundaryCallFrame; }
> 
> Style: Same comment here about multiline.
> 
> Having thought about this a bit more, perhaps this should just be a constructor parameter.
> 
>     • Is there any reason we would not know this at construction time?
>     • Is there any reason we would want to change this after construction?

It doesn't ever change, and removing the property simplifies a lot of stuff.

[Matt Baker]

Comment on attachment 294219 [details]
Patch

View in context: https://bugs.webkit.org/attachment.cgi?id=294219&action=review

>> Source/WebInspectorUI/UserInterface/Views/CallFrameTreeElement.css:64
>> +    background-color: var(--border-color);
> 
> NIT: you may want to add a `vertical-align` of 1px or something, because I am seeing the line be slightly off vertically.

Good eye. `vertical-align: middle` fixes it.

>> Source/WebInspectorUI/UserInterface/Views/CallFrameTreeElement.css:67
>> +@media (-webkit-min-device-pixel-ratio: 2) {
> 
> The media query block isn't necessary. 0.5px rounds up to 1px. It used to round down to 0, but it was changed this year.

Nice.

>> Source/WebInspectorUI/UserInterface/Views/Variables.css:56
>> +    --text-color-medium: hsl(0, 0%, 50%);
> 
> This seems like a weird name.  Maybe `--text-color-grey-medium`

We could include others too:

--text-color-gray-light
--text-color-gray-medium
--text-color-gray-dark

I don't know how crazy we want to get with this (pretty crazy if it were up to me 😬).

>>> LayoutTests/inspector/debugger/async-call-stack.html:89
>>> +    }
>> 
>> No need to do window.__savedCallStackDepth right? You could just use a local variable? Alternatively TestCase setup/teardown could pass the testCase as a parameter and you could store state on the test case itself!
> 
> By local I meant closure variable. Outside of `setup` and `teardown` but inside of `test`.

Seems appropriate to move state into the test case.

[Matt Baker]

Comment on attachment 294219 [details]
Patch

View in context: https://bugs.webkit.org/attachment.cgi?id=294219&action=review

>> Source/WebInspectorUI/UserInterface/Views/DebuggerSidebarPanel.js:660
>> +        console.assert(asyncBoundaryCallFrame.nativeCode);
> 
> Ahh, interesting. We might want to consider if we need to make this more general before committing a first version where we may need to change.
> 
>     • This requires a Console.CallFrame be the boundary.
>         - works great for JS function boundaries (setTimeout, rAF, dispatchEvent, Promises, etc)
>     • How would we handle async/await boundaries?
>         - Now it is not so much a function as language construct
>         - For comparison this is what Chrome does: https://twitter.com/umaar/status/793777970599104512?lang=en
> 
> This could work with a Console.CallFrame if we provided a fake functionName, but that seems hacky.
> 
> Further, I don't see how this would handle the >1 boundary case. (... setInterval | ... setTimeout | ... current).
> 
> Blink uses a linked list of StackTraces where each StackTrace may have a description (to solve the async case). I like the StackTrace linked list approach. I'm not sure I like "description". I'd rather something that explicitly says the boundary ("topCallFrameIsBoundary" for your cases, and "boundaryAwaitFunctionName" for the async/await cases). Just brainstorming here.
> https://github.com/v8/v8/blob/master/src/inspector/js_protocol.json#L200

Currently the >1 boundary case was being handled by traversing the AsyncCallData structures (via AsyncCallData.parentAsyncCallIdentifier) and pushing call frames from each into a single array. This requires that the VM's top call frame be the native boundary, which is the case for timers and requestAnimationFrame, but might require synthesizing a Console.CallFrame in other cases. There is another side effect of this design, which is that the stack depth setting value *includes* the boundary frame. In the case of async/await, a synthesized frame eats into that budget, which feels wrong.

I like the idea of having a linked list of stack trace protocol objects, but am uncertain about the best way to handle the boundary information. I actually like having a "description" field:

"types": [
    {
        "id": "AsyncCallStack",
        "description": "The head of a linked list of AsyncCallStack objects."
        "type": "object",
        "properties": [
            { "name": "description", "type": "string" },
            { "name": "callFrames", "type": "array", "items": { "$ref": "Console.CallFrame" } },
            { "name": "nextAsyncCallStack", "$ref": "AsyncCallStack", "optional": true }
        ]
    }
],
"events": [
    {
        "name": "paused",
        "parameters": [
            ...
            { "name": "asyncCallStack", "$ref": "AsyncCallStack", "optional": true }
        ]
    }
]

[Timothy Hatcher]

I like the divider with the text, but I think the line is a bit too low. It should be higher to visually center better with the text and icon.

[Matt Baker]

(In reply to comment #32)
> I like the divider with the text, but I think the line is a bit too low. It
> should be higher to visually center better with the text and icon.

Yep, vertical-align: middle fixes it.

[Matt Baker]

Created attachment 294998 [details]
Patch

[Matt Baker]

Created attachment 294999 [details]
Patch

[Build Bot]

Comment on attachment 294999 [details]
Patch

Attachment 294999 [details] did not pass mac-wk2-ews (mac-wk2):
Output: http://webkit-queues.webkit.org/results/2528379

Number of test failures exceeded the failure limit.

[Build Bot]

Created attachment 295005 [details]
Archive of layout-test-results from ews107 for mac-yosemite-wk2

The attached test failures were seen while running run-webkit-tests on the mac-wk2-ews.
Bot: ews107  Port: mac-yosemite-wk2  Platform: Mac OS X 10.10.5

[Build Bot]

Comment on attachment 294999 [details]
Patch

Attachment 294999 [details] did not pass mac-debug-ews (mac):
Output: http://webkit-queues.webkit.org/results/2528347

Number of test failures exceeded the failure limit.

[Build Bot]

Created attachment 295006 [details]
Archive of layout-test-results from ews114 for mac-yosemite

The attached test failures were seen while running run-webkit-tests on the mac-debug-ews.
Bot: ews114  Port: mac-yosemite  Platform: Mac OS X 10.10.5

[Matt Baker]

The failure in resources-in-worker.html is real, not sure about others. Fixing.

[Build Bot]

Comment on attachment 294999 [details]
Patch

Attachment 294999 [details] did not pass mac-ews (mac):
Output: http://webkit-queues.webkit.org/results/2528445

Number of test failures exceeded the failure limit.

[Build Bot]

Created attachment 295007 [details]
Archive of layout-test-results from ews101 for mac-yosemite

The attached test failures were seen while running run-webkit-tests on the mac-ews.
Bot: ews101  Port: mac-yosemite  Platform: Mac OS X 10.10.5

[Matt Baker]

Created attachment 295008 [details]
Patch

[Build Bot]

Comment on attachment 295008 [details]
Patch

Attachment 295008 [details] did not pass mac-ews (mac):
Output: http://webkit-queues.webkit.org/results/2528643

New failing tests:
http/tests/inspector/network/xhr-request-data-encoded-correctly.html
inspector/worker/resources-in-worker.html
http/tests/inspector/network/copy-as-curl.html
inspector/debugger/csp-exceptions.html

[Build Bot]

Created attachment 295010 [details]
Archive of layout-test-results from ews102 for mac-yosemite

The attached test failures were seen while running run-webkit-tests on the mac-ews.
Bot: ews102  Port: mac-yosemite  Platform: Mac OS X 10.10.5

[Build Bot]

Comment on attachment 295008 [details]
Patch

Attachment 295008 [details] did not pass mac-wk2-ews (mac-wk2):
Output: http://webkit-queues.webkit.org/results/2528726

New failing tests:
http/tests/inspector/network/xhr-request-data-encoded-correctly.html
inspector/worker/resources-in-worker.html
http/tests/inspector/network/copy-as-curl.html
inspector/debugger/csp-exceptions.html

[Build Bot]

Created attachment 295015 [details]
Archive of layout-test-results from ews105 for mac-yosemite-wk2

The attached test failures were seen while running run-webkit-tests on the mac-wk2-ews.
Bot: ews105  Port: mac-yosemite-wk2  Platform: Mac OS X 10.10.5

[Build Bot]

Comment on attachment 295008 [details]
Patch

Attachment 295008 [details] did not pass mac-debug-ews (mac):
Output: http://webkit-queues.webkit.org/results/2528721

New failing tests:
http/tests/inspector/network/xhr-request-data-encoded-correctly.html
inspector/worker/resources-in-worker.html
http/tests/inspector/network/copy-as-curl.html
inspector/debugger/csp-exceptions.html

[Build Bot]

Created attachment 295017 [details]
Archive of layout-test-results from ews114 for mac-yosemite

The attached test failures were seen while running run-webkit-tests on the mac-debug-ews.
Bot: ews114  Port: mac-yosemite  Platform: Mac OS X 10.10.5

[Joseph Pecoraro]

Comment on attachment 295008 [details]
Patch

View in context: https://bugs.webkit.org/attachment.cgi?id=295008&action=review

> Source/JavaScriptCore/ChangeLog:44
> +        (Inspector::InspectorDebuggerAgent::clearAsyncCallStackData):

clearAsyncCallStackData should also be called in InspectorDebuggerAgent::didClearGlobalObject. Otherwise when the user navigates between pages with Web Inspector open we would keep around the previous page's async call data for no reason.

> Source/JavaScriptCore/inspector/agents/InspectorDebuggerAgent.cpp:145
> +    if (m_asyncCallStackDepth == depth)
> +        return;
> +
> +    m_asyncCallStackDepth = depth;

Lets produce a warning about negative values. Currently the protocol doesn't handle unsigned types, so a bad frontend could send us a negative depth.

    if (depth < 0) {
        errorString = ASCIILiteral("...");
        return;
    }

> Source/JavaScriptCore/inspector/agents/InspectorDebuggerAgent.cpp:220
> +    while (iterator != m_asyncCallIdentifierToData.end()) {

It may be worth putting end into a local. I'm not sure how smart compilers will be about this given `find` is used in the loop and is not const.

> Source/JavaScriptCore/inspector/agents/InspectorDebuggerAgent.cpp:227
> +        auto firstNonNativeCallFrame = callData.callStack->firstNonNativeCallFrame();
> +        bool topCallFrameIsNative = !firstNonNativeCallFrame || !firstNonNativeCallFrame->isEqual(callData.callStack->at(0));

This may potentially iterate the entire call stack instead of simply checking the top frame. I'd suggest adding ScriptCallFrame::isNative and using it here (and inside firstNonNativeCallFrame for consistency).

> Source/JavaScriptCore/inspector/agents/InspectorDebuggerAgent.cpp:241
> +        if (previousStackTrace)
> +            previousStackTrace->setParentStackTrace(WTFMove(stackTrace));
> +
> +        if (!callData.parentAsyncCallIdentifier)
> +            break;
> +
> +        previousStackTrace = stackTrace;

Is `stackTrace` safe to use if we did a WTFMove of it above? Is this only a problem with unique_ptr?

> Source/JavaScriptCore/inspector/agents/InspectorDebuggerAgent.cpp:272
> +        createScriptCallStack(exec, m_asyncCallStackDepth),

Just use `callStack`, we shouldn't need to create it again!

> Source/JavaScriptCore/inspector/agents/InspectorDebuggerAgent.cpp:275
> +    };

I think we start the reference count at 1 instead of 0. That seems clearer to me.

> Source/JavaScriptCore/inspector/agents/InspectorDebuggerAgent.cpp:286
> +    const auto asyncCallIdentifier = std::make_pair(asyncCallType, callbackIdentifier);
> +    auto asyncCallData = m_asyncCallIdentifierToData.take(asyncCallIdentifier);

This `take` seems aggressive. We should be decrementing the reference count and using the reference count to know when to remove something.

For example, if I have a repeating async task that eventually gets cancelled, there may have been another async task spawned that still references the since cancelled stack:

    1. function startInterval() {
    2.     let interval = setInterval(function intervalFired() {
    3.         setTimeout(timerFired, 1000);
    4.         clearInterval(interval);
    5.     }, 100);
    6. }
    7. function timerFired() {
    8.     debugger;
    9. }
   10. startInterval();

Here inside timerFired I'd like to see frames like:

    timerFired
    -- setTimeout ----
    intervalFired
    -- setInterval ----
    startInterval

But by doing the `take` here for `clearInterval` then I think we would have lost the bottom two frames.

Note that even if you don't `take` here, swapping lines 3 and 4 would also have led to the poor behavior. The solution to that would be reffing and dereffing the current identifier in willDispatch and didDispatch.

> Source/JavaScriptCore/inspector/agents/InspectorDebuggerAgent.cpp:298
> +    m_currentAsyncCallIdentifier = std::make_pair(asyncCallType, callbackIdentifier);

What happens if we are paused, in a nested run loop, and run some asynchronous code?

It seems we would end up losing the original m_currentAsyncCallIdentifier.

Using the previous example. While paused in `timerFired` WebCore would have done willDispatchAsyncCall(TimerFired, <id>). Now, while paused in the debugger if we run the following in the console:

    setTimeout(() => { console.log("oops"); }, 10);

Then when this timer fires it will schedule/willDispatch/didDispatch and end up clearing m_currentAsyncCallIdentifier.

If we then continue the program, didDispatchAsyncCall will have a Nullopt m_currentAsyncCallIdentifier. Which would ASSERT and maybe crash in Release builds.

It seems there are two solutions to this.

    1. Only have a single m_currentAsyncCallIdentifier.
        - This would not record async call data for things run in the inspector while paused
        - This would mean an early return here in willDispatch if m_currentAsyncCallIdentifier has a value

    2. Keep a stack of currentAsyncCallIdentifiers (or at least a set of 2 for the nested run loop case)

Given the complexity and obscurity of (2), I think (1) would be fine.

> Source/JavaScriptCore/inspector/agents/InspectorDebuggerAgent.cpp:306
> +    auto identifier = m_currentAsyncCallIdentifier.value();

We should probably check if there is a value to be safe. I can't think of any case other then the nested run loop mentioned above.

> Source/JavaScriptCore/inspector/agents/InspectorDebuggerAgent.cpp:1151
> +    if (!asyncCallData.singleShot || asyncCallData.referenceCount)

If we used reference count starting at 1, then I don't think we would need to check singleShot here (which is confusing).

> Source/JavaScriptCore/inspector/protocol/Console.json:41
> +                { "name": "topCallFrameIsBoundary", "type": "boolean" },

This should have a description.

> Source/WebInspectorUI/UserInterface/Controllers/DebuggerManager.js:99
> +            this._asyncCallStackDepthSetting = new WebInspector.Setting("async-call-stack-depth", 200);

We should always have the member variable, so it should be outside of this block. Preferably up above with other Settings to keep this block of code all about initializing the backend's DebuggerAgent states.

> Source/WebInspectorUI/UserInterface/Controllers/DebuggerManager.js:296
> +        this._asyncCallStackDepthSetting.value = x

Style: Semicolon and newline

> Source/WebInspectorUI/UserInterface/Models/ConsoleMessage.js:52
> -        this._stackTrace = WebInspector.StackTrace.fromPayload(this._target, stackTrace || []);
> +        this._stackTrace = WebInspector.StackTrace.fromPayload(this._target, {callFrames});

I don't think this is compatible with older backends. If you were to remotely inspect an iOS 9 or iOS 10 device they would still be sending a StackTrace object. ConsoleObserver -> LogManager.messageWasAdded -> new ConsoleMessage means that `stackTrace` here would still be an Object there and not an Array.

> Source/WebInspectorUI/UserInterface/Views/CallFrameTreeElement.js:42
> +            this.selectable = false;

I wonder if we should make this selectable. Selecting it would show its location at least right? I made ThreadTreeElement and IdleTreeElement selectable for more expected keyboard navigation.

> Source/WebInspectorUI/UserInterface/Views/DebuggerSidebarPanel.js:783
> +            for (let i = 1; i < currentStackTrace.callFrames.length; ++i)

This start index should be 0 || 1 based on topCallFrameIsBoundary.

> LayoutTests/inspector/debugger/async-stack-trace-expected.txt:4
> +== Running test suite: AsyncStackTrace

Great test! It will be very easy to add new `simple` tests!

> LayoutTests/inspector/debugger/async-stack-trace-expected.txt:12
> +PASS: Should have boolean value `topCallFrameIsBoundary`.
> +PASS: Top frame should be native code.
> +PASS: Top frame should have no location.

I find it more readable to just JSON dump the objects. Then when/if the tests fail you can see the exact properties that changed. It will also mean we can verify here that Foo.RequestAnimationFrame actually has requestAnimationFrame at the top.

[Matt Baker]

Comment on attachment 295008 [details]
Patch

View in context: https://bugs.webkit.org/attachment.cgi?id=295008&action=review

>> Source/JavaScriptCore/inspector/agents/InspectorDebuggerAgent.cpp:286
>> +    auto asyncCallData = m_asyncCallIdentifierToData.take(asyncCallIdentifier);
> 
> This `take` seems aggressive. We should be decrementing the reference count and using the reference count to know when to remove something.
> 
> For example, if I have a repeating async task that eventually gets cancelled, there may have been another async task spawned that still references the since cancelled stack:
> 
>     1. function startInterval() {
>     2.     let interval = setInterval(function intervalFired() {
>     3.         setTimeout(timerFired, 1000);
>     4.         clearInterval(interval);
>     5.     }, 100);
>     6. }
>     7. function timerFired() {
>     8.     debugger;
>     9. }
>    10. startInterval();
> 
> Here inside timerFired I'd like to see frames like:
> 
>     timerFired
>     -- setTimeout ----
>     intervalFired
>     -- setInterval ----
>     startInterval
> 
> But by doing the `take` here for `clearInterval` then I think we would have lost the bottom two frames.
> 
> Note that even if you don't `take` here, swapping lines 3 and 4 would also have led to the poor behavior. The solution to that would be reffing and dereffing the current identifier in willDispatch and didDispatch.

By reffing and dereffing in willDispatch and didDispatch, and setting the initial ref count to zero for single-shot tasks and one for repeating tasks, we eliminate the need to retain the single-shot flag!

>> Source/JavaScriptCore/inspector/agents/InspectorDebuggerAgent.cpp:298
>> +    m_currentAsyncCallIdentifier = std::make_pair(asyncCallType, callbackIdentifier);
> 
> What happens if we are paused, in a nested run loop, and run some asynchronous code?
> 
> It seems we would end up losing the original m_currentAsyncCallIdentifier.
> 
> Using the previous example. While paused in `timerFired` WebCore would have done willDispatchAsyncCall(TimerFired, <id>). Now, while paused in the debugger if we run the following in the console:
> 
>     setTimeout(() => { console.log("oops"); }, 10);
> 
> Then when this timer fires it will schedule/willDispatch/didDispatch and end up clearing m_currentAsyncCallIdentifier.
> 
> If we then continue the program, didDispatchAsyncCall will have a Nullopt m_currentAsyncCallIdentifier. Which would ASSERT and maybe crash in Release builds.
> 
> It seems there are two solutions to this.
> 
>     1. Only have a single m_currentAsyncCallIdentifier.
>         - This would not record async call data for things run in the inspector while paused
>         - This would mean an early return here in willDispatch if m_currentAsyncCallIdentifier has a value
> 
>     2. Keep a stack of currentAsyncCallIdentifiers (or at least a set of 2 for the nested run loop case)
> 
> Given the complexity and obscurity of (2), I think (1) would be fine.

I'm fine with (1).

> Source/JavaScriptCore/inspector/agents/InspectorDebuggerAgent.cpp:1141
> +void InspectorDebuggerAgent::releaseAsyncCallData(const AsyncCallIdentifier& identifier)

Renaming to `derefAsyncCallData` and adding a corresponding `refAsyncCallData`.

>> Source/JavaScriptCore/inspector/agents/InspectorDebuggerAgent.cpp:1151
>> +    if (!asyncCallData.singleShot || asyncCallData.referenceCount)
> 
> If we used reference count starting at 1, then I don't think we would need to check singleShot here (which is confusing).

We can treat all call data uniformly and remove the `singleShot` property by using a starting reference count of zero for single-shot tasks and 1 for repeating tasks.

> Source/JavaScriptCore/inspector/protocol/Debugger.json:139
> +            "name": "setAsyncCallStackDepth",

Renaming to "setAsyncStackTraceDepth" for consistency.

[Matt Baker]

Comment on attachment 295008 [details]
Patch

View in context: https://bugs.webkit.org/attachment.cgi?id=295008&action=review

> Source/JavaScriptCore/inspector/agents/InspectorDebuggerAgent.cpp:1149
> +    asyncCallData.referenceCount = std::min(asyncCallData.referenceCount - 1, 0);

This should be std::max.

[Matt Baker]

Updated test output:

Tests for async stack traces.


== Running test suite: AsyncStackTrace
-- Running test case: CheckAsyncStackTrace.RequestAnimationFrame
PAUSE #1
CALL STACK:
0: [F] pauseThenFinishTest
-- [N] requestAnimationFrame ----
1: [F] testRequestAnimationFrame
2: [P] Global Code

-- Running test case: CheckAsyncStackTrace.SetTimeout
PAUSE #1
CALL STACK:
0: [F] pauseThenFinishTest
-- [N] setTimeout ----
1: [F] testSetTimeout
2: [P] Global Code

-- Running test case: CheckAsyncStackTrace.SetInterval
PAUSE #1
CALL STACK:
0: [F] intervalFired
-- [N] setInterval ----
1: [F] testSetInterval
2: [P] Global Code
PAUSE #2
CALL STACK:
0: [F] intervalFired
-- [N] setInterval ----
1: [F] testSetInterval
2: [P] Global Code
PAUSE #3
CALL STACK:
0: [F] intervalFired
-- [N] setInterval ----
1: [F] testSetInterval
2: [P] Global Code

-- Running test case: CheckAsyncStackTrace.ChainedRequestAnimationFrame
PAUSE #1
CALL STACK:
0: [F] pauseThenFinishTest
-- [N] requestAnimationFrame ----
1: [F] testRequestAnimationFrame
-- [N] requestAnimationFrame ----
2: [F] testChainedRequestAnimationFrame
3: [P] Global Code

-- Running test case: CheckAsyncStackTrace.ReferenceCounting
PAUSE #1
CALL STACK:
0: [F] pauseThenFinishTest
-- [N] setTimeout ----
1: [F] intervalFired
-- [N] setInterval ----
2: [F] testReferenceCounting
3: [P] Global Code
-- Running test setup.
Save DebuggerManager.asyncStackTraceDepth

-- Running test case: AsyncStackTrace.DisableStackTrace
PASS: Async stack trace should be null.
-- Running test teardown.
Restore DebuggerManager.asyncStackTraceDepth
-- Running test setup.
Save DebuggerManager.asyncStackTraceDepth

-- Running test case: AsyncStackTrace.SetStackTraceDepth
PASS: Number of call frames should be equal to the depth setting.
-- Running test teardown.
Restore DebuggerManager.asyncStackTraceDepth

[Matt Baker]

Created attachment 295136 [details]
Patch

[Build Bot]

Comment on attachment 295136 [details]
Patch

Attachment 295136 [details] did not pass mac-wk2-ews (mac-wk2):
Output: http://webkit-queues.webkit.org/results/2535577

New failing tests:
http/tests/inspector/network/xhr-request-data-encoded-correctly.html
inspector/worker/resources-in-worker.html
http/tests/inspector/network/copy-as-curl.html
inspector/debugger/csp-exceptions.html

[Build Bot]

Created attachment 295138 [details]
Archive of layout-test-results from ews107 for mac-yosemite-wk2

The attached test failures were seen while running run-webkit-tests on the mac-wk2-ews.
Bot: ews107  Port: mac-yosemite-wk2  Platform: Mac OS X 10.10.5

[Build Bot]

Comment on attachment 295136 [details]
Patch

Attachment 295136 [details] did not pass mac-debug-ews (mac):
Output: http://webkit-queues.webkit.org/results/2535567

New failing tests:
inspector/script-profiler/event-type-Other.html
inspector/worker/resources-in-worker.html
inspector/debugger/csp-exceptions.html
http/tests/inspector/network/xhr-request-data-encoded-correctly.html
http/tests/inspector/network/copy-as-curl.html
inspector/debugger/sourceURL-repeated-identical-executions.html

[Build Bot]

Created attachment 295140 [details]
Archive of layout-test-results from ews116 for mac-yosemite

The attached test failures were seen while running run-webkit-tests on the mac-debug-ews.
Bot: ews116  Port: mac-yosemite  Platform: Mac OS X 10.10.5

[Matt Baker]

Created attachment 295164 [details]
Patch

[Matt Baker]

(In reply to comment #50)
> Comment on attachment 295008 [details]
> Patch
> 
> View in context:
> https://bugs.webkit.org/attachment.cgi?id=295008&action=review
> 
> > Source/WebInspectorUI/UserInterface/Models/ConsoleMessage.js:52
> > -        this._stackTrace = WebInspector.StackTrace.fromPayload(this._target, stackTrace || []);
> > +        this._stackTrace = WebInspector.StackTrace.fromPayload(this._target, {callFrames});
> 
> I don't think this is compatible with older backends. If you were to
> remotely inspect an iOS 9 or iOS 10 device they would still be sending a
> StackTrace object. ConsoleObserver -> LogManager.messageWasAdded -> new
> ConsoleMessage means that `stackTrace` here would still be an Object there
> and not an Array.

StackTrace was previously defined as:

{
    "id": "StackTrace",
    "type": "array",
    "items": { "$ref": "CallFrame" },
    "description": "Call frames for assertions or error messages."
}

and included in ConsoleMessage as the property:

{ "name": "stackTrace", "$ref": "StackTrace" }

which is now defined "inline" as:

{ "name": "stackTrace", "type": "array", "items": { "$ref": "CallFrame" } }

Won't these be identical?

[Build Bot]

Comment on attachment 295164 [details]
Patch

Attachment 295164 [details] did not pass mac-debug-ews (mac):
Output: http://webkit-queues.webkit.org/results/2537864

New failing tests:
inspector/debugger/sourceURL-repeated-identical-executions.html

[Build Bot]

Created attachment 295170 [details]
Archive of layout-test-results from ews114 for mac-yosemite

The attached test failures were seen while running run-webkit-tests on the mac-debug-ews.
Bot: ews114  Port: mac-yosemite  Platform: Mac OS X 10.10.5

[Joseph Pecoraro]

Comment on attachment 295164 [details]
Patch

View in context: https://bugs.webkit.org/attachment.cgi?id=295164&action=review

r=me, but please be sure to test console.error on iOS 10 and make sure that works. If you want me to review changes I'd be happy to.

> Source/JavaScriptCore/inspector/agents/InspectorDebuggerAgent.cpp:274
> +    AsyncCallData data = {
> +        callStack,
> +        m_currentAsyncCallIdentifier,
> +        singleShot ? 0 : 1
> +    };

Nit: This seems to cause GTK and Windows compilers to fail. Maybe we should just give this a constructor (lame, I know).

I'm still iffy about starting a ref count at zero like this, but I understand the code below. It still would work if you started at one and did a "hasOneRef" check in a few places below, but at this point that might be more complex.

> Source/JavaScriptCore/inspector/protocol/Console.json:19
> -                { "name": "stackTrace", "$ref": "StackTrace", "optional": true, "description": "JavaScript stack trace for assertions and error messages." },
> +                { "name": "stackTrace", "type": "array", "items": { "$ref": "CallFrame" }, "optional": true, "description": "JavaScript stack trace for assertions and error messages." },

This still needs to be handled for backwards compatibility in the frontend.

> Source/JavaScriptCore/inspector/protocol/Console.json:41
> +                { "name": "topCallFrameIsBoundary", "type": "boolean", "description": "Whether the first item in <code>callFrames</code> is the native function that scheduled the asynchronous operation (e.g. setTimeout)." },

This could be optional and only set if true. That seems to be a common pattern for us. Not sure if it has much merit, but it reduces JSON stringification and message size.

> Source/WebInspectorUI/UserInterface/Controllers/DebuggerManager.js:508
> +        DebuggerAgent.setAsyncStackTraceDepth(this._asyncStackTraceDepthSetting.value);

I'm giddy with how nice this code looks =)

> Source/WebInspectorUI/UserInterface/Models/ConsoleMessage.js:53
> +        callFrames = callFrames || [];
> +        this._stackTrace = WebInspector.StackTrace.fromPayload(this._target, {callFrames});

I don't think this fixes the backwards compatibility issue. I would suggest the following approach.

Inside ConsoleObserver:

    messageAdded(message)
    {
        ...

        // COMPATIBILITY (iOS 10): StackTrace used to be an array of call frames but is now
        // a stack trace object. If this is an array modernize it to a stack trace payload.
        let stackTrace = message.stackTrace;
        if (stackTrace && Array.isArray(stackTrace))
            stackTrace = {callFrames: stackTrace, topCallFrameIsBoundary: false};

        WebInspector.logManager.messageWasAdded(this.target, message.source, message.level, message.text, message.type, message.url, message.line, message.column || 0, message.repeatCount, message.parameters, stackTrace, message.networkRequestId);
    }

Note I put `topCallFrameIsBoundary: false` because it is currently not marked as optional in the protocol.

Now here inside ConsoleMessage you could use the name "stackTrace" and be accurate that it is a Console.StackTrace payload (or missing). You'd need to handle that correctly from then on.

> Source/WebInspectorUI/UserInterface/Models/StackTrace.js:172
> +    get topCallFrameIsBoundary() { return this._topCallFrameIsBoundary; }
> +    get parentStackTrace() { return this._parentStackTrace; }

Style: Put the one line getters up above the multi-line computed getters. Here you can make `get callFrames()` one line and match the order in the constructor.

> LayoutTests/inspector/debugger/async-stack-trace-expected.txt:11
> +CALL STACK:
> +0: [F] pauseThenFinishTest
> +-- [N] requestAnimationFrame ----
> +1: [F] testRequestAnimationFrame
> +2: [P] Global Code

Fantastic! I find this much easier to read and more descriptive then the previous test.

> LayoutTests/inspector/debugger/async-stack-trace-expected.txt:49
> +CALL STACK:
> +0: [F] pauseThenFinishTest
> +-- [N] requestAnimationFrame ----
> +1: [F] testRequestAnimationFrame
> +-- [N] requestAnimationFrame ----
> +2: [F] testChainedRequestAnimationFrame
> +3: [P] Global Code

One worry I have is that with async call stacks enabled on a page that is constantly running chained request animation frames we will keep an ever growing list of async call stacks:

For example:

    function draw() {
        ...
        requestAnimationFrame(draw);
    }

    requestAnimationFrame(draw);

Unless there is a cancel or early return inside draw, then we will have a list that grows forever.

I'm wonder if you have considered any solutions to this.

[Joseph Pecoraro]

Comment on attachment 295164 [details]
Patch

View in context: https://bugs.webkit.org/attachment.cgi?id=295164&action=review

>> Source/WebInspectorUI/UserInterface/Models/ConsoleMessage.js:53
>> +        this._stackTrace = WebInspector.StackTrace.fromPayload(this._target, {callFrames});
> 
> I don't think this fixes the backwards compatibility issue. I would suggest the following approach.
> 
> Inside ConsoleObserver:
> 
>     messageAdded(message)
>     {
>         ...
> 
>         // COMPATIBILITY (iOS 10): StackTrace used to be an array of call frames but is now
>         // a stack trace object. If this is an array modernize it to a stack trace payload.
>         let stackTrace = message.stackTrace;
>         if (stackTrace && Array.isArray(stackTrace))
>             stackTrace = {callFrames: stackTrace, topCallFrameIsBoundary: false};
> 
>         WebInspector.logManager.messageWasAdded(this.target, message.source, message.level, message.text, message.type, message.url, message.line, message.column || 0, message.repeatCount, message.parameters, stackTrace, message.networkRequestId);
>     }
> 
> Note I put `topCallFrameIsBoundary: false` because it is currently not marked as optional in the protocol.
> 
> Now here inside ConsoleMessage you could use the name "stackTrace" and be accurate that it is a Console.StackTrace payload (or missing). You'd need to handle that correctly from then on.

I read the protocol change incorrectly.

This used to be an object and is now an array.

So my example code is _wrong_, but I do think it is the right approach. Checking for the old type and converting to the new type here in the Observer.

[Joseph Pecoraro]

Comment on attachment 295164 [details]
Patch

View in context: https://bugs.webkit.org/attachment.cgi?id=295164&action=review

>>> Source/WebInspectorUI/UserInterface/Models/ConsoleMessage.js:53
>>> +        this._stackTrace = WebInspector.StackTrace.fromPayload(this._target, {callFrames});
>> 
>> I don't think this fixes the backwards compatibility issue. I would suggest the following approach.
>> 
>> Inside ConsoleObserver:
>> 
>>     messageAdded(message)
>>     {
>>         ...
>> 
>>         // COMPATIBILITY (iOS 10): StackTrace used to be an array of call frames but is now
>>         // a stack trace object. If this is an array modernize it to a stack trace payload.
>>         let stackTrace = message.stackTrace;
>>         if (stackTrace && Array.isArray(stackTrace))
>>             stackTrace = {callFrames: stackTrace, topCallFrameIsBoundary: false};
>> 
>>         WebInspector.logManager.messageWasAdded(this.target, message.source, message.level, message.text, message.type, message.url, message.line, message.column || 0, message.repeatCount, message.parameters, stackTrace, message.networkRequestId);
>>     }
>> 
>> Note I put `topCallFrameIsBoundary: false` because it is currently not marked as optional in the protocol.
>> 
>> Now here inside ConsoleMessage you could use the name "stackTrace" and be accurate that it is a Console.StackTrace payload (or missing). You'd need to handle that correctly from then on.
> 
> I read the protocol change incorrectly.
> 
> This used to be an object and is now an array.
> 
> So my example code is _wrong_, but I do think it is the right approach. Checking for the old type and converting to the new type here in the Observer.

I continue to misread what happened.

This used to be an array and is now an array. =/

So I think your code is correct and you can disregard these comments.

[Matt Baker]

Comment on attachment 295164 [details]
Patch

View in context: https://bugs.webkit.org/attachment.cgi?id=295164&action=review

>> Source/JavaScriptCore/inspector/agents/InspectorDebuggerAgent.cpp:274
>> +    };
> 
> Nit: This seems to cause GTK and Windows compilers to fail. Maybe we should just give this a constructor (lame, I know).
> 
> I'm still iffy about starting a ref count at zero like this, but I understand the code below. It still would work if you started at one and did a "hasOneRef" check in a few places below, but at this point that might be more complex.

How would a setTimer work if we started its ref count at 1?

schedule setTimer -> create AsyncCallData (count = 1)
will dispatch setTimer -> ref (count = 2)
did dispatch setTimer -> deref (count = 1)

Unless clearTimer is called the AsyncCallData is immortal.

>> Source/JavaScriptCore/inspector/protocol/Console.json:41
>> +                { "name": "topCallFrameIsBoundary", "type": "boolean", "description": "Whether the first item in <code>callFrames</code> is the native function that scheduled the asynchronous operation (e.g. setTimeout)." },
> 
> This could be optional and only set if true. That seems to be a common pattern for us. Not sure if it has much merit, but it reduces JSON stringification and message size.

I'm in favor of making it optional.

>> LayoutTests/inspector/debugger/async-stack-trace-expected.txt:49
>> +3: [P] Global Code
> 
> One worry I have is that with async call stacks enabled on a page that is constantly running chained request animation frames we will keep an ever growing list of async call stacks:
> 
> For example:
> 
>     function draw() {
>         ...
>         requestAnimationFrame(draw);
>     }
> 
>     requestAnimationFrame(draw);
> 
> Unless there is a cancel or early return inside draw, then we will have a list that grows forever.
> 
> I'm wonder if you have considered any solutions to this.

We could include a `weight` field in AsyncCallData, equal to the number of call frames in all its linked stack traces. If adding a new stack to the list would cause the weight to exceed the depth setting, remove the oldest StackTrace (or part of it). The difficulty is that since stack traces can share nodes, the set of stack traces forms a tree. For example:

function draw() {
    requestAnimationFrame(draw);
    if (once) {
        once = false;
        foo();
    }
}

function foo() {
    setTimeout(..., 1000);
}

requestAnimationFrame(draw);

After a few calls to draw, two paths exist through the tree of AsyncCallData objects:

["Global Code", requestAnimationFrame] --> [draw, requestAnimationFrame] --> ...
                                       \-> [foo, setTimeout]

Remving the oldest node from the first path once it reaches the weight limit would impact the second path, which is under the limit. Instead we could just drop the oldest reference, deref it, and remove it only if the ref count drops to zero.

[Matt Baker]

Removing call frames from the oldest node in a stack trace to accommodate new call frames won't work, since mutating a node with a ref count > 1 affects other stack traces. However, removing the node from the stack trace will result in poor behavior when the node's weight is close to the depth setting value. A combination of both approaches seems like the best option:

w₀ = weight of the entire stack trace
wₓ = weight of the oldest node in stack trace
D = maximum stack trace depth 

1) Add new node to stack trace, recalculate w₀.
2) If w₀ <= D, we're done!
3) r = D - w₀. If r >= wₓ, remove the oldest node from the stack trace. Goto step 2.

This results in stack traces that, in the worst case scenario, can have w₀ = (2 * D) - 1.

[Matt Baker]

Corrected version:

1) Add new node to stack trace.
2) Recalculate w₀. If w₀ <= D, we're done!
3) r = D - w₀. If r >= wₓ, remove the oldest node from the stack trace. Goto step 2.

[Joseph Pecoraro]

(In reply to comment #66)
> Comment on attachment 295164 [details]
> Patch
> 
> View in context:
> https://bugs.webkit.org/attachment.cgi?id=295164&action=review
> 
> >> Source/JavaScriptCore/inspector/agents/InspectorDebuggerAgent.cpp:274
> >> +    };
> > 
> > Nit: This seems to cause GTK and Windows compilers to fail. Maybe we should just give this a constructor (lame, I know).
> > 
> > I'm still iffy about starting a ref count at zero like this, but I understand the code below. It still would work if you started at one and did a "hasOneRef" check in a few places below, but at this point that might be more complex.
> 
> How would a setTimer work if we started its ref count at 1?
> 
> schedule setTimer -> create AsyncCallData (count = 1)
> will dispatch setTimer -> ref (count = 2)
> did dispatch setTimer -> deref (count = 1)

DebuggerAgent always owns a single reference. So it would know to only release things that have a single ref left (its own). The code would be identical to what you have now except instead of starting at 0 or 1 we would start at 1 and 2 and instead of removing at 0 we would remove at 1. But we get to remove the max() code when dereffing which is just weird.

  schedule one shot timer - create - 1
  will dispatch - ref - 2
  did dispatch - deref - 1 => remove

  schedule one shot timer - create - 1
  cancel timer - deref - 1 => remove

  schedule repeat timer - create - 2
  will dispatch - ref - 3
  did dispatch - deref - 2
  cancel - deref - 1 => remove

Since ref count should never go below 1 now, we could convert it to unsigned if we wanted.

I'm fine either way.

[Matt Baker]

Created attachment 295233 [details]
Patch

[Matt Baker]

I'll file a follow-up to address infinitely growing stack traces. The solution proposed above is on the right track, but would produce incorrect results.

[Build Bot]

Comment on attachment 295233 [details]
Patch

Attachment 295233 [details] did not pass mac-debug-ews (mac):
Output: http://webkit-queues.webkit.org/results/2540382

New failing tests:
inspector/script-profiler/event-type-Other.html
inspector/debugger/sourceURL-repeated-identical-executions.html

[Build Bot]

Created attachment 295245 [details]
Archive of layout-test-results from ews117 for mac-yosemite

The attached test failures were seen while running run-webkit-tests on the mac-debug-ews.
Bot: ews117  Port: mac-yosemite  Platform: Mac OS X 10.10.5

[Matt Baker]

Both tests are crashing the same way. DebuggerAgent is trying to ref an async call it isn't tracking:

Thread 0 Crashed:: Dispatch queue: com.apple.main-thread
0   com.apple.JavaScriptCore      	0x00000001114b5107 WTFCrash + 39
1   com.apple.JavaScriptCore      	0x0000000110d1e960 Inspector::InspectorDebuggerAgent::refAsyncCallData(std::__1::pair<int, int> const&) + 192
2   com.apple.JavaScriptCore      	0x0000000110d1ee2d Inspector::InspectorDebuggerAgent::willDispatchAsyncCall(int, int) + 285
3   com.apple.WebCore             	0x0000000117879a58 WebCore::InspectorInstrumentation::willFireTimerImpl(WebCore::InstrumentingAgents&, int, WebCore::ScriptExecutionContext&) + 136 (InspectorInstrumentation.cpp:450)
...

[Joseph Pecoraro]

(In reply to comment #74)
> Both tests are crashing the same way. DebuggerAgent is trying to ref an
> async call it isn't tracking:
> 
> Thread 0 Crashed:: Dispatch queue: com.apple.main-thread
> 0   com.apple.JavaScriptCore      	0x00000001114b5107 WTFCrash + 39
> 1   com.apple.JavaScriptCore      	0x0000000110d1e960
> Inspector::InspectorDebuggerAgent::refAsyncCallData(std::__1::pair<int, int>
> const&) + 192
> 2   com.apple.JavaScriptCore      	0x0000000110d1ee2d
> Inspector::InspectorDebuggerAgent::willDispatchAsyncCall(int, int) + 285
> 3   com.apple.WebCore             	0x0000000117879a58
> WebCore::InspectorInstrumentation::willFireTimerImpl(WebCore::
> InstrumentingAgents&, int, WebCore::ScriptExecutionContext&) + 136
> (InspectorInstrumentation.cpp:450)
> ...

This seems possible if we open Web Inspector AFTER it was scheduled. Then Web Inspector would just see the dispatch without having scheduled it.

[Matt Baker]

Ah ha! One test explicitly disables breakpoints, the other uses the script profiler which disables breakpoints. I missed a places where this check needs to be made in the backend before updating state related to async calls.

Fixing.

[Matt Baker]

Created attachment 295256 [details]
Patch

[Matt Baker]

(In reply to comment #76)
> Ah ha! One test explicitly disables breakpoints, the other uses the script
> profiler which disables breakpoints. I missed a places where this check
> needs to be made in the backend before updating state related to async calls.
> 
> Fixing.

Not entirely accurate. When async stack traces are temporarily disabled because breakpoints are inactive, we still want to clean up state in didCancelAsyncCall and didDispatchAsyncCall.

The bug was in willDispatchAsyncCall, which needs to check that data exists for an async call before proceeding. Calls scheduled before opening the Inspector (thanks Joe!) or while breakpoints were inactive aren't tracked by DebuggerAgent.

[Joseph Pecoraro]

Where are the EWS bubbles for this most recent patch?

[Matt Baker]

(In reply to comment #79)
> Where are the EWS bubbles for this most recent patch?

I see them. They're all green.

[Joseph Pecoraro]

Comment on attachment 295256 [details]
Patch

View in context: https://bugs.webkit.org/attachment.cgi?id=295256&action=review

r=me

> Source/JavaScriptCore/inspector/agents/InspectorDebuggerAgent.cpp:258
> +    if (!m_asyncStackTraceDepth || !m_scriptDebugServer.breakpointsActive())
> +        return;

Nit: I find these "if (a || b) return" bails harder to read then if they were separated out individually. It is especially relevant in this code because each function has a different set of conditions but they all share one of the conditions. But I'll leave that up to you.

> Source/WebInspectorUI/UserInterface/Models/StackTrace.js:170
> +

Style: // Public

[Matt Baker]

Comment on attachment 295256 [details]
Patch

View in context: https://bugs.webkit.org/attachment.cgi?id=295256&action=review

>> Source/JavaScriptCore/inspector/agents/InspectorDebuggerAgent.cpp:258
>> +        return;
> 
> Nit: I find these "if (a || b) return" bails harder to read then if they were separated out individually. It is especially relevant in this code because each function has a different set of conditions but they all share one of the conditions. But I'll leave that up to you.

Makes sense, will fix before landing!

>> Source/WebInspectorUI/UserInterface/Models/StackTrace.js:170
>> +
> 
> Style: // Public

It's on line 138

[Matt Baker]

Created attachment 295541 [details]
Patch for landing

[WebKit Commit Bot]

Comment on attachment 295541 [details]
Patch for landing

Rejecting attachment 295541 [details] from commit-queue.

Failed to run "['/Volumes/Data/EWS/WebKit/Tools/Scripts/webkit-patch', '--status-host=webkit-queues.webkit.org', '--bot-id=webkit-cq-01', 'build', '--no-clean', '--no-update', '--build-style=release', '--port=mac']" exit_code: 2 cwd: /Volumes/Data/EWS/WebKit

Last 500 characters of output:
rce/JavaScriptCore/runtime/IntlNumberFormat.cpp -o /Volumes/Data/EWS/WebKit/WebKitBuild/JavaScriptCore.build/Release/JavaScriptCore.build/Objects-normal/x86_64/IntlNumberFormat.o

** BUILD FAILED **


The following build commands failed:
	CompileC /Volumes/Data/EWS/WebKit/WebKitBuild/JavaScriptCore.build/Release/JavaScriptCore.build/Objects-normal/x86_64/InspectorDebuggerAgent.o inspector/agents/InspectorDebuggerAgent.cpp normal x86_64 c++ com.apple.compilers.llvm.clang.1_0.compiler
(1 failure)

Full output: http://webkit-queues.webkit.org/results/2585431

[Matt Baker]

Fixing.

[Matt Baker]

Need to update for https://bugs.webkit.org/show_bug.cgi?id=164199.

[Matt Baker]

Created attachment 295565 [details]
Patch for landing

[WebKit Commit Bot]

Comment on attachment 295565 [details]
Patch for landing

Clearing flags on attachment: 295565

Committed r209062: <http://trac.webkit.org/changeset/209062>

[WebKit Commit Bot]

All reviewed patches have been landed.  Closing bug.