core(tracehouse): improve CPU profiler timing refinement #11608
Conversation
| // The FunctionCall at the next level, should be a child of Foo execution | ||
| {startTime: 10, endTime: 25}, | ||
| // The FunctionCall at the next level, should be a child of Foo execution | ||
| {startTime: 12, endTime: 22}, |
There was a problem hiding this comment.
super nit: not sure if this timing is accurately represented in the artistic representation
There was a problem hiding this comment.
oh you're right they should be nested nice catch :)
when I first read the super nit I thought it was talking about the scale of █ and I was like oh boy talk about "super nit" 🤣 but nah this isn't even a nit, very good comment 💯
| // We may have overshot a little from last time, so back up to find the real starting index. | ||
| let startIndex = initialIndex; | ||
| while (startIndex > 0) { | ||
| const task = knownTasks[startIndex]; | ||
| if (task && task[type] < earliestPossibleTimestamp) break; | ||
| startIndex--; | ||
| } | ||
|
|
There was a problem hiding this comment.
Is there a test case covering this situation?
There was a problem hiding this comment.
yes, if we were to comment this out the (root) and (program) timestamps would not align in "should create events while aware of other tasks"
which is actually how I caught this bug, tests ftw! :)
| @@ -44,7 +44,8 @@ describe('CPU Profiler Model', () => { | |||
| }; | |||
| }); | |||
|
|
|||
| describe('#_findEffectiveTimestamp', () => { | |||
| // TODO: re-enable these before landing, if structure looks good | |||
| {ph: 'E', ts: ts(45e3), args: {data: {callFrame: {functionName: 'Foo'}}}}, | ||
| {ph: 'B', ts: ts(55e3), args: {data: {callFrame: {functionName: 'Bar'}}}}, | ||
| {ph: 'E', ts: ts(85e3), args: {data: {callFrame: {functionName: 'Bar'}}}}, | ||
| {ph: 'E', ts: ts(103e3), args: {data: {callFrame: {functionName: '(root)'}}}}, |
There was a problem hiding this comment.
(root) from the cpu sampler takes the full duration.
but then the tasks above indicate we had 3 toplevel RunTasks.
how does that work?
There was a problem hiding this comment.
From some real traces that's how it appears to work in practice with (idle) filling in the time in between the toplevel tasks. I can add another test for multiple roots though 👍
There was a problem hiding this comment.
yeah it seems like (root), (idle) and (program) are are basically unlike the rest of the nodes in a cpu profile, so it feels like they dont belong as trace events.
There was a problem hiding this comment.
yeah the integration PR I have where I have been finding the other failure modes filters those out :)
| {ph: 'E', ts: ts(45e3), args: {data: {callFrame: {functionName: 'Foo'}}}}, | ||
| {ph: 'B', ts: ts(55e3), args: {data: {callFrame: {functionName: 'Bar'}}}}, | ||
| {ph: 'E', ts: ts(85e3), args: {data: {callFrame: {functionName: 'Bar'}}}}, | ||
| {ph: 'E', ts: ts(103e3), args: {data: {callFrame: {functionName: '(root)'}}}}, |
There was a problem hiding this comment.
yeah it seems like (root), (idle) and (program) are are basically unlike the rest of the nodes in a cpu profile, so it feels like they dont belong as trace events.
that's step 3 :) |
patrickhulce
force-pushed
the
cpu_profiler_task_conflicts_part_b
branch
from
741dafd
to
05bf8d0
Compare
Summary
Step 3 of ?? in the innocuous issue #8526 turned multi-quarter effort :)
This step further improves the timing data from CPU profiler samples by moving our
_findEffectiveTimestampimprovements to a second pass that can utilize the pair of sampler events (which is required to understand parent/child relationships).Next 4 steps in this saga...
main-thread-taskscomputed artifactRelated Issues/PRs
ref #8526
Ultimately I'll want @paulirish to give this a final sign off but in the meantime I'd love for your eyes on this too @adamraine :)