Bug 178302

Summary: Web Inspector: Canvas2D Profiling: highlight expensive context commands in the captured command log
Product: WebKit Reporter: Blaze 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

Blaze Burg
Reported 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.
Attachments
Patch (7.32 KB, patch)
2017-10-17 14:26 PDT, Devin Rousso
no flags
[Image] After Patch is applied (691.65 KB, image/png)
2017-10-17 14:26 PDT, Devin Rousso
no flags
Patch (7.34 KB, patch)
2017-10-17 14:29 PDT, Devin Rousso
no flags
Alternative (84.14 KB, patch)
2017-10-17 19:48 PDT, Devin Rousso
no flags
[Image] After Alternative is applied (159.66 KB, image/png)
2017-10-17 19:48 PDT, Devin Rousso
no flags
Patch (94.91 KB, patch)
2017-11-02 23:20 PDT, Devin Rousso
no flags
Blaze Burg
Comment 1 2017-10-13 17:07:27 PDT
Devin Rousso
Comment 2 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.
Devin Rousso
Comment 3 2017-10-17 14:26:18 PDT
Created attachment 324057 [details] [Image] After Patch is applied
Devin Rousso
Comment 4 2017-10-17 14:29:33 PDT
Devin Rousso
Comment 5 2017-10-17 14:30:31 PDT
Comment on attachment 324060 [details] Patch Whoops. Used `-m` instead of `--comment` :P
Matt Baker
Comment 6 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?
Matt Baker
Comment 7 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.
Devin Rousso
Comment 8 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
Devin Rousso
Comment 9 2017-10-17 19:48:45 PDT
Created attachment 324089 [details] [Image] After Alternative is applied
Blaze Burg
Comment 10 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.
Devin Rousso
Comment 11 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.
Devin Rousso
Comment 12 2017-11-02 23:20:07 PDT
WebKit Commit Bot
Comment 13 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>
WebKit Commit Bot
Comment 14 2017-11-03 00:04:28 PDT
All reviewed patches have been landed. Closing bug.
Note You need to log in before you can comment on or make changes to this bug.