Bug 142029 – Web Inspector: Show rendering frames (and FPS) in Layout and Rendering timeline

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

[Matt Baker]

Created attachment 247359 [details]
frame rate timeline mockup

It would be helpful to developers debugging rendering performance issues for the layout and rendering timeline to show a frame graph rather than a bar graph. Each frame should be divided horizontally into colored regions, indicating the time spent on different tasks: scripting (purple), layout/painting (red), other (gray).

[Radar WebKit Bug Importer]

<rdar://problem/19961762>

[Matt Baker]

Created attachment 247457 [details]
Quick demo to visualize run-loop executions in Timelines, alongside layout and rendering records.

[Matt Baker]

Created attachment 247463 [details]
Demo to visualize run-loop executions in the Layout and Rendering Timeline.

[Timothy Hatcher]

Created attachment 247485 [details]
Semi-working WIP patch

This fixes a bug in Matt's patch. We were not using CFRunLoopObserver correctly.

[Timothy Hatcher]

Created attachment 247486 [details]
Picture with the patch

This slows down really bad on graphic intense sites.

[Matt Baker]

Created attachment 247728 [details]
WIP with updated run loop observers

Frame start based on kCFRunLoopBeforeTimers. Styles, Layout, and Paint events consistently fall with frame bounds.

[Timothy Hatcher]

Can you post a picture? I see a lot of interesting new code!

You might have want to use my RunLoopObserver changes so there isn't Mac code in InspectorTimelineAgent.

[Timothy Hatcher]

Comment on attachment 247728 [details]
WIP with updated run loop observers

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

> Source/WebCore/inspector/InspectorTimelineAgent.cpp:146
> +    m_frameStartObserver = CFRunLoopObserverCreateWithHandler(NULL, kCFRunLoopBeforeTimers, YES, 0, ^(CFRunLoopObserverRef observer, CFRunLoopActivity activity)
> +    {
> +        UNUSED_PARAM(observer);
> +        UNUSED_PARAM(activity);
> +        if (!m_enabled)
> +            return;
> +
> +        ASSERT(!m_didStartRecordingRunLoop);
> +        pushCurrentRecord(InspectorObject::create(), TimelineRecordType::RunLoop, false, nullptr);
> +        m_didStartRecordingRunLoop = true;
> +    });
> +    CFRunLoopAddObserver(CFRunLoopGetMain(), m_frameStartObserver, kCFRunLoopCommonModes);
> +
> +    m_frameStopObserver = CFRunLoopObserverCreateWithHandler(NULL, kCFRunLoopBeforeWaiting | kCFRunLoopExit, YES, frameStopRunLoopOrder, ^(CFRunLoopObserverRef observer, CFRunLoopActivity activity)
> +    {
> +        UNUSED_PARAM(observer);
> +        UNUSED_PARAM(activity);
> +        if (!m_enabled || !m_didStartRecordingRunLoop)
> +            return;
> +
> +        didCompleteCurrentRecord(TimelineRecordType::RunLoop);
> +        m_didStartRecordingRunLoop = false;
> +    });
> +    CFRunLoopAddObserver(CFRunLoopGetMain(), m_frameStopObserver, kCFRunLoopCommonModes);

This should go back to using platform/RunLoopObserver.cpp. We shouldn't add Mac code to this cross platform file. See my WIP for a way to extend WebCore::RunLoopObserver.

[Timothy Hatcher]

The bracketing looks good to me with the latest patch. Maybe split the backend and fronted changes?

[Matt Baker]

Created attachment 248296 [details]
Patch

[Matt Baker]

Created attachment 248297 [details]
Backend

[Matt Baker]

Created attachment 248299 [details]
Frontend

[Matt Baker]

Created attachment 248300 [details]
Backend

[Timothy Hatcher]

Comment on attachment 248300 [details]
Backend

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

Looks good. Lets get the changes we need into Platform/RunLoopObserver.cpp.

> Source/WebCore/inspector/InspectorTimelineAgent.cpp:126
> +    m_frameStartObserver = CFRunLoopObserverCreateWithHandler(NULL, kCFRunLoopBeforeTimers, YES, 0, ^(CFRunLoopObserverRef observer, CFRunLoopActivity activity)

This needs to use platform abstractions. We can't put Mac code here.

[Matt Baker]

Created attachment 248526 [details]
Backend

Updated to use RunLoopObserver.

[Matt Baker]

Created attachment 248527 [details]
Frontend

All runloop records with children are now included, not just those with Layout events. Frames that exceed 16 ms are displayed with a 16 ms frame width, and shorter frames are as wide as their duration. Dropped frames appear following any frame that exceeded 16 ms. Frames are combined and averaged when their displayed size drops below a minimum threshold. A new CSS style class is added to combined frames containing one or more dropped frames, so that we can style this in the future.

[Timothy Hatcher]

Comment on attachment 248526 [details]
Backend

Nice an clean! Check out the build errors on EWS though.

[Joseph Pecoraro]

Comment on attachment 248526 [details]
Backend

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

This would need a ChangeLog as well.

> Source/WebCore/inspector/InspectorTimelineAgent.cpp:80
> +static const CFIndex frameStopRunLoopOrder = (CFIndex)RunLoopObserver::WellKnownRunLoopOrders::CoreAnimationCommit + 1;
> +
> +static CFRunLoopRef currentRunLoop()
> +{
> +#if PLATFORM(IOS)
> +    // A race condition during WebView deallocation can lead to a crash if the layer sync run loop
> +    // observer is added to the main run loop <rdar://problem/9798550>. However, for responsiveness,
> +    // we still allow this, see <rdar://problem/7403328>. Since the race condition and subsequent
> +    // crash are especially troublesome for iBooks, we never allow the observer to be added to the
> +    // main run loop in iBooks.
> +    if (applicationIsIBooksOnIOS())
> +        return WebThreadRunLoop();
> +#endif
> +    return CFRunLoopGetCurrent();
> +}

These uses of CF must be behind PLATFORM(COCOA) or other ports will break.

That said, it is unusual to have platform specific code and types inside WebCore/inspector. It would be nice if this was abstracted away. Otherwise, if platform specific code could show up all over the place and be difficult to maintain.

Typically this is done by adding a WebCore/platform file with a null implementation for ports that haven't yet implemented it, and port specific implementations for those that do support it.

For example, "Locale":

  ./text/LocaleNone.cpp
  ./text/LocaleICU.h
  ./text/mac/LocaleMac.h
  ./text/win/LocaleWin.h

That said, maybe the abstraction doesn't need to be a RunLoopObserver, but just a

> Source/WebCore/inspector/InspectorTimelineAgent.cpp:162
> +    m_frameStartObserver = RunLoopObserver::create(0, [this]() {
> +        if (!m_enabled)
> +            return;
> +
> +        ASSERT(!m_didStartRecordingRunLoop);
> +        pushCurrentRecord(InspectorObject::create(), TimelineRecordType::RunLoop, false, nullptr);
> +        m_didStartRecordingRunLoop = true;
> +    });
> +
> +    m_frameStopObserver = RunLoopObserver::create(frameStopRunLoopOrder, [this]() {
> +        if (!m_enabled || !m_didStartRecordingRunLoop)
> +            return;
> +
> +        didCompleteCurrentRecord(TimelineRecordType::RunLoop);
> +        m_didStartRecordingRunLoop = false;
> +    });

Does this gracefully handle nested runloops (e.g. pausing in the Web Inspector)?

I feel like currently this would assert as soon as you nest.

    - Entry
    - BeforeTimers
      => run your observer
    - BeforeSources
      => run JavaScript and trigger Pause, run Nested Run Loop

        - Entry
        - BeforeTimers
        => run your observer, I expect the first time it will ASSERT that !didStart, in a Release build it would open a RunLoop record
        - BeforeSources
        => run JavaScript... eventually unpause
        - BeforeWaiting
        => complete the last record
        - AfterWaiting
        - Exit

    - BeforeWaiting
    => bail, because !didStartRecording
    - AfterWaiting
    - Exit

> Source/WebCore/inspector/InspectorTimelineAgent.cpp:165
> +    m_frameStartObserver->schedule(currentRunLoop(), kCFRunLoopBeforeTimers);
> +    m_frameStopObserver->schedule(currentRunLoop());

Not having "kCFRunLoopBeforeWaiting | kCFRunLoopExit" at the call sight makes this really hard to follow.

> Source/WebCore/inspector/InspectorTimelineAgent.cpp:191
> +    m_frameStartObserver->invalidate();
> +    m_frameStartObserver.reset();
> +    m_frameStopObserver->invalidate();
> +    m_frameStopObserver.reset();

I think we have been preferring "= nullptr" instead of ".reset()" with unique_ptr.

[Joseph Pecoraro]

Comment on attachment 248527 [details]
Frontend

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

Not a full review.

> Source/WebInspectorUI/UserInterface/Controllers/TimelineManager.js:226
> +                    return;

This should probably return null instead of just undefined.

> Source/WebInspectorUI/UserInterface/Controllers/TimelineManager.js:230
> +                    var childRecord = processRecord.call(this, childRecordPayload, recordPayload);

Maybe processRecord should be promoted to a member function instead of this inline function. I don't think it has closure information.

> Source/WebInspectorUI/UserInterface/Controllers/TimelineManager.js:231
> +                    if (!childRecord)

I have a feeling null is not expected. Lets console.assert(), and knowing the childRecordPayload would prove useful in debugging this. Otherwise we silently drop records.

> Source/WebInspectorUI/UserInterface/Controllers/TimelineManager.js:238
> +                if (children.length)
> +                    return new WebInspector.RunLoopTimelineRecord(startTime, endTime, children);
>  

This unexpectedly falls through if !children.length. Maybe return a new RunLoopTimelineRecord regardless of whether or not the children list is empty or not. Not to mention, RunLoopTimelineRecord's constructor defaults to an empty list of children so it must be fine.

> Source/WebInspectorUI/UserInterface/Controllers/TimelineManager.js:321
> +                console.log("RequestAnimationFrame", startTime, endTime)

Debugging.

> Source/WebInspectorUI/UserInterface/Controllers/TimelineManager.js:336
> +        function processEvent(recordPayload, parentRecordPayload)

Likewise this could be a member function.

> Source/WebInspectorUI/UserInterface/Controllers/TimelineManager.js:343
> +            var startTime = this.activeRecording.computeElapsedTime(recordPayload.startTime);
> +            var endTime = this.activeRecording.computeElapsedTime(recordPayload.endTime);
> +            var callFrames = this._callFramesFromPayload(recordPayload.stackTrace);
> +
> +            var significantCallFrame = null;
> +            if (callFrames) {

And we should try to avoid this duplicated code if possible.

> Source/WebInspectorUI/UserInterface/Models/RunLoopTimelineRecord.js:61
> +    durationForRecords: function(recordType)

Lets adopt the new method syntax for 2015 files:

    durationForRecords(recordType)

> Source/WebInspectorUI/UserInterface/Views/RunLoopTimelineOverviewGraph.js:72
> +        this._framesPerSecondDividers = new Map;

I have been going with "Map.prototype.clear()".

> Source/WebInspectorUI/UserInterface/Views/TimelineOverview.js:84
> +WebInspector.TimelineOverview.MinimumSecondsPerPixel = 0.0001;

Whoa.

> Source/WebInspectorUI/UserInterface/Views/TimelineOverviewGraph.js:44
> +        if (timelineType === WebInspector.TimelineRecord.Type.RunLoop)
> +            return new WebInspector.RunLoopTimelineOverviewGraph(timeline);

Is it useful to have this if the port does not support RunLoops?

> Source/WebInspectorUI/UserInterface/Views/TimelineRecordFrame.js:33
> +    this.records = records;

This irks me... I think we can assume we will never call this with a single record.

> Source/WebInspectorUI/UserInterface/Views/TimelineRecordFrame.js:40
> +WebInspector.TimelineRecordFrame.StyleClassName = "timeline-record-frame";
> +WebInspector.TimelineRecordFrame.FrameStyleClassName = "frame";
> +WebInspector.TimelineRecordFrame.IncludesDroppedStyleClassName = "includes-dropped";

Honestly, I've just been using style names inline now. Unless they repeat quite a bit. I find they are often, 1-off, so why have a long property name for them. Donna what Tim's thoughts are on this.

> Source/WebInspectorUI/UserInterface/Views/TimelineRecordFrame.js:47
> +WebInspector.TimelineRecordFrame.createCombinedFrames  = function(records, secondsPerPixel, graphDataSource, createFrameCallback)

Nit: "  =" => " ="

> Source/WebInspectorUI/UserInterface/Views/TimelineRecordTreeElement.js:103
> +        title = WebInspector.RunLoopTimelineRecord.DisplayName;

I think you should just inline the DisplayName here. And it should be a UIString:

    title = WebInspector.UIString("Runloop Executed");

[Matt Baker]

Created attachment 248781 [details]
Backend

[Matt Baker]

Created attachment 248782 [details]
Frontend

[Matt Baker]

Created attachment 248807 [details]
Example frame data 1

Data captured during page load

[Matt Baker]

Created attachment 248810 [details]
Example frame data 2

Data captured while hovering page elements

[Matt Baker]

Created attachment 248811 [details]
Example frame data 3

Data captured while scrolling, hovering page elements

[Matt Baker]

Created attachment 248816 [details]
Backend

[Matt Baker]

Created attachment 248821 [details]
Backend

[Matt Baker]

Created attachment 248822 [details]
Frontend

[Timothy Hatcher]

Comment on attachment 248821 [details]
Backend

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

> Source/WebCore/inspector/InspectorTimelineAgent.cpp:86
> +#if PLATFORM(COCOA)
> +static const CFIndex frameStopRunLoopOrder = (CFIndex)RunLoopObserver::WellKnownRunLoopOrders::CoreAnimationCommit + 1;
> +
> +static CFRunLoopRef currentRunLoop()
> +{
> +#if PLATFORM(IOS)
> +    // A race condition during WebView deallocation can lead to a crash if the layer sync run loop
> +    // observer is added to the main run loop <rdar://problem/9798550>. However, for responsiveness,
> +    // we still allow this, see <rdar://problem/7403328>. Since the race condition and subsequent
> +    // crash are especially troublesome for iBooks, we never allow the observer to be added to the
> +    // main run loop in iBooks.
> +    if (applicationIsIBooksOnIOS())
> +        return WebThreadRunLoop();
> +#endif
> +    return CFRunLoopGetCurrent();
> +}
> +#endif

This could really move to RunLoopObserver.cpp and just pass nullptr for the runloop to get the default via this code.

> Source/WebCore/platform/cf/RunLoopObserver.cpp:55
>      if (!runLoop)
>          runLoop = CFRunLoopGetCurrent();

…replacing this code.

[Timothy Hatcher]

Comment on attachment 248822 [details]
Frontend

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

> Source/WebInspectorUI/UserInterface/Models/RunLoopTimelineRecord.js:68
> +                if (currentValue.usesActiveStartTime)

In practice you won't see these. But it is good to be safe.

> Source/WebInspectorUI/UserInterface/Models/TimelineRecord.js:50
> +    RunLoop: "timeline-record-type-runloop"

This should really just replace the Layout timeline graph. You can do that in a follow up. I don't want to hold up landing this.

[Matt Baker]

Comment on attachment 248821 [details]
Backend

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

>> Source/WebCore/inspector/InspectorTimelineAgent.cpp:86
>> +#endif
> 
> This could really move to RunLoopObserver.cpp and just pass nullptr for the runloop to get the default via this code.

This code was originally copied from LayerFlushSchedulerMac and could probably be removed altogether. The comment indicates that it is specified to layer code, and isn't relevant to TimelineAgent.

[WebKit Commit Bot]

Comment on attachment 248821 [details]
Backend

Clearing flags on attachment: 248821

Committed r181625: <http://trac.webkit.org/changeset/181625>

[WebKit Commit Bot]

Comment on attachment 248822 [details]
Frontend

Clearing flags on attachment: 248822

Committed r181626: <http://trac.webkit.org/changeset/181626>

[WebKit Commit Bot]

All reviewed patches have been landed.  Closing bug.

[Joseph Pecoraro]

(In reply to comment #18)
> > Source/WebCore/inspector/InspectorTimelineAgent.cpp:162
> > +    m_frameStartObserver = RunLoopObserver::create(0, [this]() {
> > +        if (!m_enabled)
> > +            return;
> > +
> > +        ASSERT(!m_didStartRecordingRunLoop);
> > +        pushCurrentRecord(InspectorObject::create(), TimelineRecordType::RunLoop, false, nullptr);
> > +        m_didStartRecordingRunLoop = true;
> > +    });
> > +
> > +    m_frameStopObserver = RunLoopObserver::create(frameStopRunLoopOrder, [this]() {
> > +        if (!m_enabled || !m_didStartRecordingRunLoop)
> > +            return;
> > +
> > +        didCompleteCurrentRecord(TimelineRecordType::RunLoop);
> > +        m_didStartRecordingRunLoop = false;
> > +    });
> 
> Does this gracefully handle nested runloops (e.g. pausing in the Web
> Inspector)?
> 
> I feel like currently this would assert as soon as you nest.
> 
>     - Entry
>     - BeforeTimers
>       => run your observer
>     - BeforeSources
>       => run JavaScript and trigger Pause, run Nested Run Loop
> 
>         - Entry
>         - BeforeTimers
>         => run your observer, I expect the first time it will ASSERT that
> !didStart, in a Release build it would open a RunLoop record
>         - BeforeSources
>         => run JavaScript... eventually unpause
>         - BeforeWaiting
>         => complete the last record
>         - AfterWaiting
>         - Exit
> 
>     - BeforeWaiting
>     => bail, because !didStartRecording
>     - AfterWaiting
>     - Exit

I think tests are seeing exactly this ASSERT scenario if we run inspector tests that have nested run loops in debug builds.

[Joseph Pecoraro]

For example, running:

    LayoutTests/inspector/timeline/debugger-paused-while-recording.html

In debug will hit an ASSERT. I'll follow up with you directly.