Bug 136351 – Web Inspector: timelines should not count time elapsed while paused in the debugger

• Component: Web Inspector
• Status: RESOLVED FIXED

[Brian Burg]

The timeline is basically useless if you pause in the debugger while recording, as it does not pause the elapsed timer while the debugger is paused.

[Radar WebKit Bug Importer]

<rdar://problem/18167351>

[Brian Burg]

Created attachment 238617 [details]
WIP

[Timothy Hatcher]

Comment on attachment 238617 [details]
WIP

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

> Source/WebCore/inspector/InspectorResourceAgent.cpp:287
> +double InspectorResourceAgent::timestamp()
> +{
> +    // If the timeline agent is recording now, use its stopwatch. Otherwise, just report 0.0
> +    // since the timestamps are only used to accurately graph records on the timeline.
> +    if (InspectorTimelineAgent* timelineAgent = m_instrumentingAgents->inspectorTimelineAgent())
> +        return timelineAgent->timestamp();
> +
> +    return 0.0;
> +}

Some how I feel we use those timestamps other times for Resources. But I don't know…

> Source/WebCore/inspector/InspectorTimelineAgent.h:203
> +    // Returns the elapsed time from a monotonic stopwatch that starts with timeline recording and
> +    // pauses when the debugger pauses or execution is otherwise suspended.
> +    double timestamp();

Such win in this patch!

> Source/WebInspectorUI/UserInterface/Controllers/TimelineManager.js:170
> +            // FIXME: compatibility: old versions pass milliseconds since epoch,
> +            // while trunk uses seconds elapsed since start of recording.
> +            var startTime = recordPayload.startTime;
> +            var endTime = recordPayload.endTime;

Should be easy to convert the old. We just need to subtract the records from the startTime of the first record if greater than epoch?

We will need to address this.

[Brian Burg]

(In reply to comment #3)
> (From update of attachment 238617 [details])
> View in context: https://bugs.webkit.org/attachment.cgi?id=238617&action=review
> 
> > Source/WebCore/inspector/InspectorResourceAgent.cpp:287
> > +double InspectorResourceAgent::timestamp()
> > +{
> > +    // If the timeline agent is recording now, use its stopwatch. Otherwise, just report 0.0
> > +    // since the timestamps are only used to accurately graph records on the timeline.
> > +    if (InspectorTimelineAgent* timelineAgent = m_instrumentingAgents->inspectorTimelineAgent())
> > +        return timelineAgent->timestamp();
> > +
> > +    return 0.0;
> > +}
> 
> Some how I feel we use those timestamps other times for Resources. But I don't know…

I did not believe it at first, but I have not found any regressions. The actual wall-clock times are included and displayed as HTTP headers/resource load timing.

[Brian Burg]

Created attachment 238789 [details]
Patch

[WebKit Commit Bot]

Attachment 238789 [details] did not pass style-queue:


ERROR: Source/JavaScriptCore/profiler/ProfileGenerator.cpp:50:  Wrong number of spaces before statement. (expected: 8)  [whitespace/indent] [4]
Total errors found: 1 in 22 files


If any of these errors are false positives, please file a bug against check-webkit-style.

[Timothy Hatcher]

Comment on attachment 238789 [details]
Patch

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

> Source/WebInspectorUI/UserInterface/Controllers/TimelineManager.js:134
> +        this._capturingStartedTimestamp = Date.now();

The device time might be drastically different from the local machine's time. So this has a high likelihood of never meeting the "recordPayload.startTime > this._capturingStartedTimestamp" check in processRecord. Even if the device time and local machine time are in sync, the protocol delay can cause the backend times to be a few ms earlier, so the first few records would have bad time values.

The Timeline rulers and graphs simply us TimelineRecording.startTime, which is the earliest record startTime seen. It should always be the first record. So maybe in processRecord, just do something like:

if (isNaN(this._capturingStartedTimestamp))
    this._capturingStartedTimestamp = recordPayload.startTime;

[Brian Burg]

(In reply to comment #7)
> (From update of attachment 238789 [details])
> View in context: https://bugs.webkit.org/attachment.cgi?id=238789&action=review
> 
> > Source/WebInspectorUI/UserInterface/Controllers/TimelineManager.js:134
> > +        this._capturingStartedTimestamp = Date.now();
> 
> The device time might be drastically different from the local machine's time. So this has a high likelihood of never meeting the "recordPayload.startTime > this._capturingStartedTimestamp" check in processRecord. Even if the device time and local machine time are in sync, the protocol delay can cause the backend times to be a few ms earlier, so the first few records would have bad time values.
> 
> The Timeline rulers and graphs simply us TimelineRecording.startTime, which is the earliest record startTime seen. It should always be the first record. So maybe in processRecord, just do something like:
> 
> if (isNaN(this._capturingStartedTimestamp))
>     this._capturingStartedTimestamp = recordPayload.startTime;

It's always safe to subtract the first timestamp from subsequent ones to (possibly no-op) compute the elapsed time. But, how do we know whether to divide by 1000? Hardcoding something like |if (this._capturingStartedTimestamp > 100.0) startTime /= 1000;| seems kinda hacky.

[Brian Burg]

Created attachment 238862 [details]
WIP - try to fix windows build

[Brian Burg]

Created attachment 239068 [details]
Proposed Fix (+legacy backend code path)

[WebKit Commit Bot]

Attachment 239068 [details] did not pass style-queue:


ERROR: Source/JavaScriptCore/profiler/ProfileGenerator.cpp:50:  Wrong number of spaces before statement. (expected: 8)  [whitespace/indent] [4]
Total errors found: 1 in 22 files


If any of these errors are false positives, please file a bug against check-webkit-style.

[Timothy Hatcher]

Comment on attachment 239068 [details]
Proposed Fix (+legacy backend code path)

Not sure what is up with Windows…

[Brian Burg]

(In reply to comment #12)
> (From update of attachment 239068 [details])
> Not sure what is up with Windows…

Unnecessary WTF_EXPORT_PRIVATE since everything is in the header now. Will remove before landing.

[Brian Burg]

Created attachment 239217 [details]
Try windows fix again

[WebKit Commit Bot]

Attachment 239217 [details] did not pass style-queue:


ERROR: Source/JavaScriptCore/profiler/ProfileGenerator.cpp:50:  Wrong number of spaces before statement. (expected: 8)  [whitespace/indent] [4]
Total errors found: 1 in 22 files


If any of these errors are false positives, please file a bug against check-webkit-style.

[WebKit Commit Bot]

Comment on attachment 239217 [details]
Try windows fix again

Clearing flags on attachment: 239217

Committed r174319: <http://trac.webkit.org/changeset/174319>

[WebKit Commit Bot]

All reviewed patches have been landed.  Closing bug.

[Brian Burg]

Reverted r174319 for reason:

Causes assertions in fast/profiler tests. Needs nontrivial investigation, will take offline.

Committed r174322: <http://trac.webkit.org/changeset/174322>

[Brian Burg]

Created attachment 239446 [details]
Patch (Fixed test regressions)

[WebKit Commit Bot]

Attachment 239446 [details] did not pass style-queue:


ERROR: Source/JavaScriptCore/profiler/ProfileGenerator.cpp:50:  Wrong number of spaces before statement. (expected: 8)  [whitespace/indent] [4]
Total errors found: 1 in 23 files


If any of these errors are false positives, please file a bug against check-webkit-style.

[Brian Burg]

Comment on attachment 239446 [details]
Patch (Fixed test regressions)

Relative to the patch that was rolled out, this patch simplifies Stopwatch so reset() doesn't need to be called before start()---the stopwatch constructor returns an object in a valid state. Also, fix some uses of one-off stopwatches for profiling through console.profile (used in tests) and JSStartProfiling.

[Timothy Hatcher]

Comment on attachment 239446 [details]
Patch (Fixed test regressions)

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

> Source/WebCore/inspector/InspectorTimelineAgent.cpp:194
> +    // Use an independent stopwatch for console-initiated profiling, since the user will expect it
> +    // to be relative to when their command was issued.

How does this affect the UI?

> Source/WebInspectorUI/UserInterface/Controllers/TimelineManager.js:176
> +            // COMPATIBILITY (iOS8): old versions use milliseconds since the epoch, rather
> +            // than seconds elapsed since timeline capturing started. We approximate the latter by
> +            // subtracting the start timestamp, as old versions did not use monotonic times.
> +            if (isNaN(this._legacyFirstRecordTimestamp))
> +                this._legacyFirstRecordTimestamp = recordPayload.startTime;

What about iOS 8 and earlier with WebInspector.ProfileNodeCall times?

[Brian Burg]

Comment on attachment 239446 [details]
Patch (Fixed test regressions)

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

>> Source/WebInspectorUI/UserInterface/Controllers/TimelineManager.js:176
>> +                this._legacyFirstRecordTimestamp = recordPayload.startTime;
> 
> What about iOS 8 and earlier with WebInspector.ProfileNodeCall times?

Double checking, but looks like there are a few regressions with this patch when inspecting iOS 8. Now that I can directly test this use case, I'll post a revised patch.

[Brian Burg]

Another regression: probe samples come with timestamps, but currently they aren't synced to the timeline's sense of elapsed time. It is not as easy to plumb the Stopwatch to InspectorDebuggerAgent.

I think it may make sense to move the shared Stopwatch instance (or a getElapsedTime() method) to the InspectorEnvironment since it is used by 4 agents (CSS, Debugger, Page, Timeline). Depending on environment type, the stopwatch could come from Timeline agent (WebCore) or from a JSGlobalObjectInspectorController (JSC).

We don't need to worry about computing elapsed time for resources when the timelines agent is unavailable, because this is only surfaced in the UI through the timelines UI and the default dashboard's time-to-load-event ticker (which uses data gathered by an auto-capturing timeline started on page load).

What do you think?

[Brian Burg]

Created attachment 239660 [details]
Revised approach

This patch is up for review but still has some legacy regressions. Investigating those is somewhat blocked by remote inspector crashing often. Please look at design changes in the attached patch. Namely, moving the shared stopwatch to InspectorEnvironment.

[WebKit Commit Bot]

Attachment 239660 [details] did not pass style-queue:


ERROR: Source/JavaScriptCore/inspector/JSGlobalObjectInspectorController.cpp:47:  Alphabetical sorting problem.  [build/include_order] [4]
ERROR: Source/JavaScriptCore/profiler/ProfileGenerator.cpp:50:  Wrong number of spaces before statement. (expected: 8)  [whitespace/indent] [4]
Total errors found: 2 in 36 files


If any of these errors are false positives, please file a bug against check-webkit-style.

[Brian Burg]

Created attachment 240077 [details]
Patch

[WebKit Commit Bot]

Attachment 240077 [details] did not pass style-queue:


ERROR: Source/JavaScriptCore/inspector/JSGlobalObjectInspectorController.cpp:47:  Alphabetical sorting problem.  [build/include_order] [4]
ERROR: Source/JavaScriptCore/profiler/ProfileGenerator.cpp:50:  Wrong number of spaces before statement. (expected: 8)  [whitespace/indent] [4]
Total errors found: 2 in 37 files


If any of these errors are false positives, please file a bug against check-webkit-style.

[Brian Burg]

Latest patch is confirmed to work for iOS 8. It moves the legacy first timestamp to be per-TimelineRecording, since these could be arbitrarily delayed from one another. Elapsed time should be relative to the start of a recording.

Note that for legacy backends, elapsed time will revert to its previous behavior: there will be gaps in the timeline when the debugger pauses. We can't do much about that, and it's fine.

On my device there are weird issues with remote inspection hanging after an auto-captured timeline recording, but this happens with a nightly build without these changes. I could not trigger any wrong-timestamp bugs.

[Timothy Hatcher]

Comment on attachment 240077 [details]
Patch

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

> Source/WebInspectorUI/UserInterface/Controllers/TimelineManager.js:124
> +    computeElapsedTime: function(timestamp)

This function sounds more like a duration calculation taking a start and stop time. Maybe computeRelativeTime?

> Source/WebInspectorUI/UserInterface/Controllers/TimelineManager.js:127
> +        if (!this._activeRecording)
> +            return;

Be explicit here:
return 0; ?
return undefined; ?

> Source/WebInspectorUI/UserInterface/Models/TimelineRecording.js:183
> +    computeElapsedTime: function(timestamp)

Ditto re: computeRelativeTime?

[Brian Burg]

Comment on attachment 240077 [details]
Patch

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

>> Source/WebInspectorUI/UserInterface/Controllers/TimelineManager.js:124
>> +    computeElapsedTime: function(timestamp)
> 
> This function sounds more like a duration calculation taking a start and stop time. Maybe computeRelativeTime?

It is! The start time is implicit. It's either 0.0 or the legacy first timestamp for the timeline recording.

>> Source/WebInspectorUI/UserInterface/Controllers/TimelineManager.js:127
>> +            return;
> 
> Be explicit here:
> return 0; ?
> return undefined; ?

oops

[Brian Burg]

Committed r175203: <http://trac.webkit.org/changeset/175203>

[Alexey Proskuryakov]

This made a number of Inspector tests assert:

https://build.webkit.org/results/Apple%20Mavericks%20Debug%20WK2%20(Tests)/r175204%20(7622)/results.html

[Brian Burg]

Reopening to attach new patch.

[Brian Burg]

Created attachment 240460 [details]
Patch

[Brian Burg]

Committed r175206: <http://trac.webkit.org/changeset/175206>

Somehow I missed the (unusual for the UI) situation uncovered by inspector-protocol/debugger, where we never start the environment stopwatch then hit a breakpoint. The debugger should check first before calling stop() to respect its precondition.

[Brian Burg]

*** Bug 136797 has been marked as a duplicate of this bug. ***

[Brian Burg]

*** Bug 135612 has been marked as a duplicate of this bug. ***