Bug 178302

Summary: Web Inspector: Canvas2D Profiling: highlight expensive context commands in the captured command log
Product: WebKit Reporter: BJ Burg <bburg>
Component: Web InspectorAssignee: Devin Rousso <hi>
Status: RESOLVED FIXED    
Severity: Normal CC: bburg, buildbot, commit-queue, hi, inspector-bugzilla-changes, joepeck, keith_miller, mark.lam, mattbaker, msaboff, saam, webkit-bug-importer
Priority: P2 Keywords: InRadar
Version: WebKit Nightly Build   
Hardware: All   
OS: All   
Bug Depends on:    
Bug Blocks: 173807, 175485    
Attachments:
Description Flags
Patch
none
[Image] After Patch is applied
none
Patch
none
Alternative
none
[Image] After Alternative is applied
none
Patch none

Description BJ Burg 2017-10-13 17:07:10 PDT
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.
Comment 1 BJ Burg 2017-10-13 17:07:27 PDT
<rdar://problem/33158849>
Comment 2 Devin Rousso 2017-10-17 14:26:00 PDT
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.
Comment 3 Devin Rousso 2017-10-17 14:26:18 PDT
Created attachment 324057 [details]
[Image] After Patch is applied
Comment 4 Devin Rousso 2017-10-17 14:29:33 PDT
Created attachment 324060 [details]
Patch
Comment 5 Devin Rousso 2017-10-17 14:30:31 PDT
Comment on attachment 324060 [details]
Patch

Whoops.  Used `-m` instead of `--comment` :P
Comment 6 Matt Baker 2017-10-17 14:54:40 PDT
(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?
Comment 7 Matt Baker 2017-10-17 15:54:42 PDT
(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.
Comment 8 Devin Rousso 2017-10-17 19:48:26 PDT
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
Comment 9 Devin Rousso 2017-10-17 19:48:45 PDT
Created attachment 324089 [details]
[Image] After Alternative is applied
Comment 10 BJ Burg 2017-11-02 14:45:53 PDT
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.
Comment 11 Devin Rousso 2017-11-02 18:21:46 PDT
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.
Comment 12 Devin Rousso 2017-11-02 23:20:07 PDT
Created attachment 325865 [details]
Patch
Comment 13 WebKit Commit Bot 2017-11-03 00:04:26 PDT
Comment on attachment 325865 [details]
Patch

Clearing flags on attachment: 325865

Committed r224389: <https://trac.webkit.org/changeset/224389>
Comment 14 WebKit Commit Bot 2017-11-03 00:04:28 PDT
All reviewed patches have been landed.  Closing bug.