Bug 178302 – Web Inspector: Canvas2D Profiling: highlight expensive context commands in the captured command log

• Component: Web Inspector
• Status: RESOLVED FIXED

[Blaze Burg]

Some commands monopolize draw time, like blurs or blitting a large image. We should consider showing the time required for each draw call. For expensive or even frame budget-busting calls, these should be easy to find and fix in a captured trace.

[Blaze Burg]

<rdar://problem/33158849>

[Devin Rousso]

Created attachment 324056 [details]
Patch

We currently don\'t have a way to capture the time taken in WebCore for each recording action as CallTracer is only called right before the action is performed.  Due to this limitation, I have elected to calculate the time in the frontend by using `performance.now()`.  If we decide to move this timing to WebCore, we would need to modify the bingings generator to support an additional CallTracer function that is called right after the action is performed.

[Devin Rousso]

Created attachment 324057 [details]
[Image] After Patch is applied

[Devin Rousso]

Created attachment 324060 [details]
Patch

[Devin Rousso]

Comment on attachment 324060 [details]
Patch

Whoops.  Used `-m` instead of `--comment` :P

[Matt Baker]

(In reply to Devin Rousso from comment #3)
> Created attachment 324057 [details]
> [Image] After Patch is applied

Neat! What about a warning icon for frames that exceed the 60fps (~16ms) budget?

[Matt Baker]

(In reply to Matt Baker from comment #6)
> (In reply to Devin Rousso from comment #3)
> > Created attachment 324057 [details]
> > [Image] After Patch is applied
> 
> Neat! What about a warning icon for frames that exceed the 60fps (~16ms)
> budget?

This might be something we should do on a per-frame basis, since a frame in the canvas recording is tied to an HTMLCanvasElement::paint. I'm not sure we can show useful warnings per-action, although any action that takes ~16ms will clearly blow the frame budget.

[Devin Rousso]

Created attachment 324088 [details]
Alternative

Along the lines of <https://bugs.webkit.org/show_bug.cgi?id=178302#c7>, here is another approach that calculates the time per frame in WebCore, instead of the frontend.  This is not entirely accurate, however, as it also includes any additional logic that occurs during the frame (such as the recording itself), so it may be less accurate

[Devin Rousso]

Created attachment 324089 [details]
[Image] After Alternative is applied

[Blaze Burg]

Comment on attachment 324088 [details]
Alternative

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

r=me with some naming nits. Please re-EWS since this patch is old.

> Source/WebCore/inspector/InspectorCanvas.cpp:174
>  void InspectorCanvas::markNewFrame()

Please rename to "finalizeFrame" or something, now that it's called at the end of a frame.

> Source/WebCore/inspector/InspectorCanvas.cpp:177
> +        static_cast<Inspector::Protocol::Recording::Frame*>(m_frames->get(m_frames->length() - 1).get())->setTime(monotonicallyIncreasingTimeMS() - m_currentFrameStartTime);

Please break up this long line. How are you sure that m_frames->length() is nonzero?

> Source/WebInspectorUI/UserInterface/Models/RecordingFrame.js:55
> +    get time() { return this._time; }

I'd prefer we call this duration throughout. Does 'time' refer to duration, start time, or end time? I don't know.

[Devin Rousso]

Comment on attachment 324088 [details]
Alternative

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

I am hesitant to land this change as it isn't a truly accurate representation of the amount of time it takes per frame.  The act of recording the actions in a frame will change the amount of code executed, thereby changing the amount of time taken for the frame.  I think the number generated is still useful, such as for extremely expensive operations, but I am not sure about the validity.  I think I'll just land it for now and see how accurate it is as I use it.  :/

>> Source/WebCore/inspector/InspectorCanvas.cpp:174
>>  void InspectorCanvas::markNewFrame()
> 
> Please rename to "finalizeFrame" or something, now that it's called at the end of a frame.

It already was called at the end of a frame, but I do agree that it could use a better name.

>> Source/WebCore/inspector/InspectorCanvas.cpp:177
>> +        static_cast<Inspector::Protocol::Recording::Frame*>(m_frames->get(m_frames->length() - 1).get())->setTime(monotonicallyIncreasingTimeMS() - m_currentFrameStartTime);
> 
> Please break up this long line. How are you sure that m_frames->length() is nonzero?

`m_currentActions` is the Inspector::Protocol::Array that is used by the most recent Inspector::Protocol::Recording::Frame, so in order for it to be nonzero then `m_frames` must also be valid.  This logic is inside InspectorCanvas::recordAction.

>> Source/WebInspectorUI/UserInterface/Models/RecordingFrame.js:55
>> +    get time() { return this._time; }
> 
> I'd prefer we call this duration throughout. Does 'time' refer to duration, start time, or end time? I don't know.

Duration would be a better name.

[Devin Rousso]

Created attachment 325865 [details]
Patch

[WebKit Commit Bot]

Comment on attachment 325865 [details]
Patch

Clearing flags on attachment: 325865

Committed r224389: <https://trac.webkit.org/changeset/224389>

[WebKit Commit Bot]

All reviewed patches have been landed.  Closing bug.