Skip to content

Commit

Permalink
core(tracehouse): sort trace events by nesting order (#9230)
Browse files Browse the repository at this point in the history
  • Loading branch information
@patrickhulce
patrickhulce authored Aug 5, 2019
1 parent 252232d commit 959c499
Show file tree
Hide file tree
Showing 3 changed files with 318 additions and 33 deletions.
142 changes: 134 additions & 8 deletions lighthouse-core/lib/tracehouse/trace-processor.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -62,10 +62,114 @@ class TraceProcessor {
}

/**
* This method sorts a group of trace events that have the same timestamp. We want to...
*
* 1. Put E events first, we finish off our existing events before we start new ones.
* 2. Order B/X events by their duration, we want parents to start before child events.
* 3. If we don't have any of this to go on, just use the position in the original array (stable sort).
*
* Note that the typical group size with the same timestamp will be quite small (<10 or so events),
* and the number of groups typically ~1% of total trace, so the same ultra-performance-sensitive consideration
* given to functions that run on entire traces does not necessarily apply here.
*
* @param {number[]} tsGroupIndices
* @param {number[]} timestampSortedIndices
* @param {number} indexOfTsGroupIndicesStart
* @param {LH.TraceEvent[]} traceEvents
* @return {number[]}
*/
static _sortTimestampEventGroup(
tsGroupIndices,
timestampSortedIndices,
indexOfTsGroupIndicesStart,
traceEvents
) {
/*
* We have two different sets of indices going on here.
* 1. There's the index for an element of `traceEvents`, referred to here as an `ArrayIndex`.
* `timestampSortedIndices` is an array of `ArrayIndex` elements.
* 2. There's the index for an element of `timestampSortedIndices`, referred to here as a `TsIndex`.
* A `TsIndex` is therefore an index to an element which is itself an index.
*
* These two helper functions help resolve this layer of indirection.
* Our final return value is an array of `ArrayIndex` in their final sort order.
*/
/** @param {number} i */
const lookupArrayIndexByTsIndex = i => timestampSortedIndices[i];
/** @param {number} i */
const lookupEventByTsIndex = i => traceEvents[lookupArrayIndexByTsIndex(i)];

/** @type {Array<number>} */
const eEventIndices = [];
/** @type {Array<number>} */
const bxEventIndices = [];
/** @type {Array<number>} */
const otherEventIndices = [];

for (const tsIndex of tsGroupIndices) {
// See comment above for the distinction between `tsIndex` and `arrayIndex`.
const arrayIndex = lookupArrayIndexByTsIndex(tsIndex);
const event = lookupEventByTsIndex(tsIndex);
if (event.ph === 'E') eEventIndices.push(arrayIndex);
else if (event.ph === 'X' || event.ph === 'B') bxEventIndices.push(arrayIndex);
else otherEventIndices.push(arrayIndex);
}

/** @type {Map<number, number>} */
const effectiveDuration = new Map();
for (const index of bxEventIndices) {
const event = traceEvents[index];
if (event.ph === 'X') {
effectiveDuration.set(index, event.dur);
} else {
// Find the next available 'E' event *after* the current group of events that matches our name, pid, and tid.
let duration = Number.MAX_SAFE_INTEGER;
// To find the next "available" 'E' event, we need to account for nested events of the same name.
let additionalNestedEventsWithSameName = 0;
const startIndex = indexOfTsGroupIndicesStart + tsGroupIndices.length;
for (let j = startIndex; j < timestampSortedIndices.length; j++) {
const potentialMatchingEvent = lookupEventByTsIndex(j);
const eventMatches = potentialMatchingEvent.name === event.name &&
potentialMatchingEvent.pid === event.pid &&
potentialMatchingEvent.tid === event.tid;

// The event doesn't match, just skip it.
if (!eventMatches) continue;

if (potentialMatchingEvent.ph === 'E' && additionalNestedEventsWithSameName === 0) {
// It's the next available 'E' event for us, so set the duration and break the loop.
duration = potentialMatchingEvent.ts - event.ts;
break;
} else if (potentialMatchingEvent.ph === 'E') {
// It's an 'E' event but for a nested event. Decrement our counter and move on.
additionalNestedEventsWithSameName--;
} else if (potentialMatchingEvent.ph === 'B') {
// It's a nested 'B' event. Increment our counter and move on.
additionalNestedEventsWithSameName++;
}
}

effectiveDuration.set(index, duration);
}
}

bxEventIndices.sort((indexA, indexB) => ((effectiveDuration.get(indexB) || 0) -
(effectiveDuration.get(indexA) || 0) || (indexA - indexB)));

otherEventIndices.sort((indexA, indexB) => indexA - indexB);

return [...eEventIndices, ...bxEventIndices, ...otherEventIndices];
}

/**
* Sorts and filters trace events by timestamp and respecting the nesting structure inherent to
* parent/child event relationships.
*
* @param {LH.TraceEvent[]} traceEvents
* @param {(e: LH.TraceEvent) => boolean} filter
*/
static _filteredStableSort(traceEvents, filter) {
static filteredTraceSort(traceEvents, filter) {
// create an array of the indices that we want to keep
const indices = [];
for (let srcIndex = 0; srcIndex < traceEvents.length; srcIndex++) {
Expand All @@ -74,11 +178,33 @@ class TraceProcessor {
}
}

// sort by ts, if there's no ts difference sort by index
indices.sort((indexA, indexB) => {
const result = traceEvents[indexA].ts - traceEvents[indexB].ts;
return result ? result : indexA - indexB;
});
// Sort by ascending timestamp first.
indices.sort((indexA, indexB) => traceEvents[indexA].ts - traceEvents[indexB].ts);

// Now we find groups with equal timestamps and order them by their nesting structure.
for (let i = 0; i < indices.length - 1; i++) {
const ts = traceEvents[indices[i]].ts;
const tsGroupIndices = [i];
for (let j = i + 1; j < indices.length; j++) {
if (traceEvents[indices[j]].ts !== ts) break;
tsGroupIndices.push(j);
}

// We didn't find any other events with the same timestamp, just keep going.
if (tsGroupIndices.length === 1) continue;

// Sort the group by other criteria and replace our index array with it.
const finalIndexOrder = TraceProcessor._sortTimestampEventGroup(
tsGroupIndices,
indices,
i,
traceEvents
);
indices.splice(i, finalIndexOrder.length, ...finalIndexOrder);
// We just sorted this set of identical timestamps, so skip over the rest of the group.
// -1 because we already have i++.
i += tsGroupIndices.length - 1;
}

// create a new array using the target indices from previous sort step
const sorted = [];
Expand Down Expand Up @@ -352,7 +478,7 @@ class TraceProcessor {
static computeTraceOfTab(trace) {
// Parse the trace for our key events and sort them by timestamp. Note: sort
// *must* be stable to keep events correctly nested.
const keyEvents = this._filteredStableSort(trace.traceEvents, e => {
const keyEvents = this.filteredTraceSort(trace.traceEvents, e => {
return e.cat.includes('blink.user_timing') ||
e.cat.includes('loading') ||
e.cat.includes('devtools.timeline') ||
Expand Down Expand Up @@ -406,7 +532,7 @@ class TraceProcessor {
// subset all trace events to just our tab's process (incl threads other than main)
// stable-sort events to keep them correctly nested.
const processEvents = TraceProcessor
._filteredStableSort(trace.traceEvents, e => e.pid === mainFrameIds.pid);
.filteredTraceSort(trace.traceEvents, e => e.pid === mainFrameIds.pid);

const mainThreadEvents = processEvents
.filter(e => e.tid === mainFrameIds.tid);
Expand Down
70 changes: 70 additions & 0 deletions lighthouse-core/test/lib/tracehouse/main-thread-tasks-test.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -198,6 +198,76 @@ describe('Main Thread Tasks', () => {
});
});

it('should handle nested events *starting* at the same timestamp correctly', () => {
const traceEvents = [
...boilerplateTrace,
{ph: 'B', name: 'TaskB', pid, tid, ts: baseTs, args},
{ph: 'B', name: 'TaskC', pid, tid, ts: baseTs, args},
{ph: 'X', name: 'TaskA', pid, tid, ts: baseTs, dur: 100e3, args},
{ph: 'E', name: 'TaskB', pid, tid, ts: baseTs + 50e3, args},
{ph: 'E', name: 'TaskC', pid, tid, ts: baseTs + 25e3, args},
{ph: 'X', name: 'TaskD', pid, tid, ts: baseTs + 100e3, dur: 100e3, args},
];

traceEvents.forEach(evt => Object.assign(evt, {cat: 'devtools.timeline'}));

const tasks = run({traceEvents});
expect(tasks).toMatchObject([
{event: {name: 'TaskA'}, parent: undefined, startTime: 0, endTime: 100},
{event: {name: 'TaskB'}, parent: {event: {name: 'TaskA'}}, startTime: 0, endTime: 50},
{event: {name: 'TaskC'}, parent: {event: {name: 'TaskB'}}, startTime: 0, endTime: 25},
{event: {name: 'TaskD'}, parent: undefined, startTime: 100, endTime: 200},
]);
});

it('should handle nested events *ending* at the same timestamp correctly', () => {
const traceEvents = [
...boilerplateTrace,
{ph: 'B', name: 'TaskA', pid, tid, ts: baseTs, args},
{ph: 'X', name: 'TaskB', pid, tid, ts: baseTs + 50e3, dur: 50e3, args},
{ph: 'B', name: 'TaskC', pid, tid, ts: baseTs + 75e3, args},
{ph: 'X', name: 'TaskD', pid, tid, ts: baseTs + 100e3, dur: 100e3, args},
{ph: 'E', name: 'TaskA', pid, tid, ts: baseTs + 100e3, args},
{ph: 'E', name: 'TaskC', pid, tid, ts: baseTs + 100e3, args},
];

traceEvents.forEach(evt => Object.assign(evt, {cat: 'devtools.timeline'}));

const tasks = run({traceEvents});
expect(tasks).toMatchObject([
{event: {name: 'TaskA'}, parent: undefined, startTime: 0, endTime: 100},
{event: {name: 'TaskB'}, parent: {event: {name: 'TaskA'}}, startTime: 50, endTime: 100},
{event: {name: 'TaskC'}, parent: {event: {name: 'TaskB'}}, startTime: 75, endTime: 100},
{event: {name: 'TaskD'}, parent: undefined, startTime: 100, endTime: 200},
]);
});

it('should handle nested events of the same name', () => {
/*
An artistic rendering of the below trace:
█████████████████████████████TaskANested██████████████████████████████████████████████
████████████████TaskB███████████████████
████TaskANested██████
*/
const traceEvents = [
...boilerplateTrace,
{ph: 'B', name: 'TaskANested', pid, tid, ts: baseTs, args},
{ph: 'X', name: 'TaskB', pid, tid, ts: baseTs, dur: 50e3, args},
{ph: 'B', name: 'TaskANested', pid, tid, ts: baseTs + 25e3, args},
{ph: 'E', name: 'TaskANested', pid, tid, ts: baseTs + 45e3, args},
{ph: 'E', name: 'TaskANested', pid, tid, ts: baseTs + 100e3, args},
];

traceEvents.forEach(evt => Object.assign(evt, {cat: 'devtools.timeline'}));

const tasks = run({traceEvents});
expect(tasks).toMatchObject([
{event: {name: 'TaskANested'}, parent: undefined, startTime: 0, endTime: 100},
{event: {name: 'TaskB'}, parent: {event: {name: 'TaskANested'}}, startTime: 0, endTime: 50},
{event: {name: 'TaskANested'}, parent: {event: {name: 'TaskB'}}, startTime: 25, endTime: 45},
]);
});

const invalidEventSets = [
[
// TaskA overlaps with TaskB, X first
Expand Down
Loading

0 comments on commit 959c499

Please sign in to comment.