Skip to content

Commit

Permalink
Add patch to fix accumulated negative deltas (#305)
Browse files Browse the repository at this point in the history
## Context

Hi! I'm working on an experimental React [concurrent mode profiler](https://react-scheduling-profiler.vercel.app) in partnership with the React core team, and we're using a [custom build of Speedscope](taneliang/speedscope@master...taneliang:fork-for-scheduling-profiler) that exposes Speedscope's internals to support our custom flamechart rendering. Specifically, Speedscope is used to import and process Chrome profiles, which are then fed to our rendering code that draws everything to a canvas.

Here's a screenshot of our app for context. The stuff above the thick gray bar is React data (some React Fiber lanes, React events, and other user timing marks), and a flamechart is drawn below.

![image](https://user-images.githubusercontent.com/12784593/89261576-e2e3b600-d660-11ea-9b90-6c6991d061d6.png)

## Problem

Early on, we had [an issue](MLH-Fellowship/scheduling-profiler-prototype#42) where our flamechart was not aligned with the React data. The discrepancy between the flamechart frames and our React data grew over the time of the profile.

We tracked down the cause to #80, which resolves #70. It seems like zeroing out those negative time deltas resulted in the accumulation of errors over the time of these profiles, which resulted in the very visible misalignment in our profiler.

I am confident that the React data's timestamps are correct because they are obtained from User Timing marks, which have absolute timestamps and are thus independent of any `timeDelta` stuff. This would mean that Speedscope is likely displaying incorrect timestamps for Chrome profiles.

## Solution

This PR takes a different approach to solving the negative `timeDelta` problem: we add a `lastElapsed` variable as a sort of backstop, preventing `elapsed` from traveling backwards in time, while still ensuring that `elapsed` is always accurate.

We've been using this patch in our custom build for about a month now and it seems to work well.
  • Loading branch information
taneliang committed Aug 5, 2020
1 parent 9452aea commit a0b3fe8
Show file tree
Hide file tree
Showing 2 changed files with 29 additions and 17 deletions.
18 changes: 9 additions & 9 deletions src/import/__snapshots__/chrome.test.ts.snap
Expand Up @@ -633,16 +633,16 @@ Object {
"line": 0,
"name": "(anonymous)",
"selfWeight": 0,
"totalWeight": 2591,
"totalWeight": 2524,
},
Frame {
"col": -1,
"file": "",
"key": "Worker::-1:-1",
"line": -1,
"name": "Worker",
"selfWeight": 873,
"totalWeight": 2591,
"selfWeight": 806,
"totalWeight": 2524,
},
Frame {
"col": 29,
Expand Down Expand Up @@ -731,7 +731,7 @@ Object {
"(program) 11.20ms",
" 296.00碌s",
"(program) 1.90ms",
"(anonymous);Worker 873.00碌s",
"(anonymous);Worker 806.00碌s",
"(anonymous);Worker;(program) 1.72ms",
" 670.00碌s",
"(program) 28.45ms",
Expand Down Expand Up @@ -1305,7 +1305,7 @@ Object {
"line": 0,
"name": "(anonymous)",
"selfWeight": 542,
"totalWeight": 6218,
"totalWeight": 6115,
},
Frame {
"col": 25,
Expand All @@ -1314,16 +1314,16 @@ Object {
"line": 30,
"name": "insertTextScript",
"selfWeight": 392,
"totalWeight": 977,
"totalWeight": 874,
},
Frame {
"col": 25,
"file": "chrome-extension://denbgaamihkadbghdceggmchnflmhpmk/contentScript.js",
"key": "insertHeaderNode:chrome-extension://denbgaamihkadbghdceggmchnflmhpmk/contentScript.js:57:25",
"line": 57,
"name": "insertHeaderNode",
"selfWeight": 292,
"totalWeight": 585,
"selfWeight": 189,
"totalWeight": 482,
},
Frame {
"col": undefined,
Expand Down Expand Up @@ -1558,7 +1558,7 @@ Object {
"(anonymous);(anonymous);(anonymous);(program) 27.49ms",
"(anonymous) 542.00碌s",
"(anonymous);insertTextScript 392.00碌s",
"(anonymous);insertTextScript;insertHeaderNode 292.00碌s",
"(anonymous);insertTextScript;insertHeaderNode 189.00碌s",
"(anonymous);insertTextScript;insertHeaderNode;appendChild;(anonymous);(anonymous) 148.00碌s",
"(anonymous);insertTextScript;insertHeaderNode;appendChild 145.00碌s",
"(anonymous);listenForMessage;get webstore 148.00碌s",
Expand Down
28 changes: 20 additions & 8 deletions src/import/chrome.ts
Expand Up @@ -224,6 +224,9 @@ export function importFromChromeCPUProfile(chromeProfile: CPUProfile): Profile {
// Ref: https://github.com/v8/v8/blob/44bd8fd7/src/inspector/js_protocol.json#L1485
let elapsed = chromeProfile.timeDeltas[0]

// Prevents negative time deltas from causing bad data.
let lastElapsed = elapsed

let lastNodeId = NaN

// The chrome CPU profile format doesn't collapse identical samples. We'll do that
Expand All @@ -232,21 +235,30 @@ export function importFromChromeCPUProfile(chromeProfile: CPUProfile): Profile {
const nodeId = chromeProfile.samples[i]
if (nodeId != lastNodeId) {
samples.push(nodeId)
sampleTimes.push(elapsed)
if (elapsed < lastElapsed) {
sampleTimes.push(lastElapsed)
} else {
sampleTimes.push(elapsed)
lastElapsed = elapsed
}
}

if (i === chromeProfile.samples.length - 1) {
if (!isNaN(lastNodeId)) {
samples.push(lastNodeId)
sampleTimes.push(elapsed)
if (elapsed < lastElapsed) {
sampleTimes.push(lastElapsed)
} else {
sampleTimes.push(elapsed)
lastElapsed = elapsed
}
}
} else {
let timeDelta = chromeProfile.timeDeltas[i + 1]
if (timeDelta < 0) {
// This is super noisy, but can be helpful when debugging strange data
// console.warn('Substituting zero for unexpected time delta:', timeDelta, 'at index', i)
timeDelta = 0
}
const timeDelta = chromeProfile.timeDeltas[i + 1]
// This is super noisy, but can be helpful when debugging strange data
// if (timeDelta < 0) {
// console.warn('Substituting zero for unexpected time delta:', timeDelta, 'at index', i)
// }

elapsed += timeDelta
lastNodeId = nodeId
Expand Down

0 comments on commit a0b3fe8

Please sign in to comment.