Skip to content

Commit be61c3b

Browse files
and-oliDevtools-frontend LUCI CQ
and-oli
authored and
Devtools-frontend LUCI CQ
committed
Improve extraction of stack trace for extension events
The stack trace is computed from the profile call that made the call to the extension API. Before https://crrev.com/6252783, we could not determine with certainty which profile call called the API for extension entries added with performance.measure, since we didn't have a trace event representing the API call. With the new event parsed in that CL we can determine which call it is by looking at the event's hierarchy and finding the first profile call ancestor. Bug: 395845218 Change-Id: If9ab0e69c0737f5dbf7e49bc13543544a5b35c51 Reviewed-on: https://chromium-review.googlesource.com/c/devtools/devtools-frontend/+/6252828 Commit-Queue: Andres Olivares <[email protected]> Reviewed-by: Nancy Li <[email protected]>
1 parent 29356d2 commit be61c3b

File tree

7 files changed

+162
-184
lines changed

7 files changed

+162
-184
lines changed

‎front_end/models/trace/extras/StackTraceForEvent.test.ts‎

Lines changed: 23 additions & 79 deletions
Original file line numberDiff line numberDiff line change
@@ -165,95 +165,39 @@ describeWithEnvironment('StackTraceForTraceEvent', function() {
165165
]);
166166
bottomFrame.functionName = originalName;
167167
});
168-
it('correctly builds the stack trace of an extension entry', async function() {
169-
const jsCall = parsedTrace.Renderer.allTraceEntries.find(
170-
e => Trace.Types.Events.isProfileCall(e) && e.callFrame.functionName === 'baz') as
171-
Trace.Types.Events.SyntheticProfileCall |
172-
undefined;
173-
assert.exists(jsCall);
174-
const stackTraceForExtensionProfileCall = Trace.Extras.StackTraceForEvent.get(jsCall, parsedTrace);
175-
assert.exists(stackTraceForExtensionProfileCall);
176-
177-
// Create an extension entry right next to our profile call (based
178-
// on its callTime property).
179-
// Test the profile call's stack strace is returned as the
180-
// extension entry's stack trace.
181-
const mockExtensionEntry = {
182-
cat: 'devtools.extension',
183-
ts: jsCall.ts,
184-
pid: jsCall.pid,
185-
tid: jsCall.tid,
186-
rawSourceEvent: {
187-
cat: 'blink.user_timing',
188-
args: {stackTrace: [{functionName: jsCall.callFrame.functionName}], callTime: jsCall.ts - 1},
189-
ph: Trace.Types.Events.Phase.ASYNC_NESTABLE_START,
190-
},
191-
} as Trace.Types.Extensions.SyntheticExtensionEntry;
192-
const stackTraceForExtensionEntry = Trace.Extras.StackTraceForEvent.get(mockExtensionEntry, parsedTrace);
193-
assert.exists(stackTraceForExtensionEntry);
194-
195-
assert.strictEqual(stackTraceForExtensionEntry, stackTraceForExtensionProfileCall);
196-
});
197-
it('uses the stack trace of the profile call that contains an extension entry call time', async function() {
198-
const bar = parsedTrace.Renderer.allTraceEntries.find(
199-
e => Trace.Types.Events.isProfileCall(e) && e.callFrame.functionName === 'bar') as
200-
Trace.Types.Events.SyntheticProfileCall |
201-
undefined;
202-
assert.exists(bar);
203-
const stackTraceForExtensionProfileCall = Trace.Extras.StackTraceForEvent.get(bar, parsedTrace);
204-
assert.exists(stackTraceForExtensionProfileCall);
205-
206-
// Create an extension entry contained by the profile call (based on
207-
// its callTime property).
208-
// Test the profile call's stack strace is returned as
209-
// the extension entry's stack trace.
210-
const mockExtensionEntry = {
211-
cat: 'devtools.extension',
212-
ts: bar.ts,
213-
pid: bar.pid,
214-
tid: bar.tid,
215-
rawSourceEvent: {
216-
cat: 'blink.user_timing',
217-
args: {stackTrace: [{functionName: bar.callFrame.functionName}], callTime: bar.ts + 1},
218-
ph: Trace.Types.Events.Phase.ASYNC_NESTABLE_START,
219-
},
220-
} as Trace.Types.Extensions.SyntheticExtensionEntry;
221-
const stackTraceForExtensionEntry = Trace.Extras.StackTraceForEvent.get(mockExtensionEntry, parsedTrace);
222-
assert.exists(stackTraceForExtensionEntry);
223-
224-
assert.strictEqual(stackTraceForExtensionEntry, stackTraceForExtensionProfileCall);
225-
});
226-
227-
it('picks the stack trace of the closest profile call when no profile call contains the extension entry call time',
168+
it('uses the stack trace of the profile call that contains an the raw trace event of the extension entry call',
228169
async function() {
229-
const bazCalls = parsedTrace.Renderer.allTraceEntries.filter(
230-
e => Trace.Types.Events.isProfileCall(e) && e.callFrame.functionName === 'baz');
231-
const firstBaz = bazCalls.at(0);
232-
assert.exists(firstBaz);
233-
const secondBaz = bazCalls.at(1) as Trace.Types.Events.SyntheticProfileCall;
234-
assert.exists(secondBaz);
235-
const middlePoint = (secondBaz.ts + firstBaz.ts) / 2;
236-
237-
const stackTraceForSecondBaz = Trace.Extras.StackTraceForEvent.get(secondBaz, parsedTrace);
238-
assert.exists(stackTraceForSecondBaz);
239-
240-
// Create an extension entry contained closer to the second
241-
// baz call (based on its callTime property).
242-
// Test the stack trace of baz is used for it.
170+
const jsCall = parsedTrace.Renderer.allTraceEntries.find(
171+
e => Trace.Types.Events.isProfileCall(e) && e.callFrame.functionName === 'baz') as
172+
Trace.Types.Events.SyntheticProfileCall |
173+
undefined;
174+
assert.exists(jsCall);
175+
const stackTraceForExtensionProfileCall = Trace.Extras.StackTraceForEvent.get(jsCall, parsedTrace);
176+
const measureTraceId = [...parsedTrace.UserTimings.measureTraceByTraceId.keys()].at(0);
177+
if (!measureTraceId) {
178+
throw new Error('Performance measure trace was not found');
179+
}
180+
181+
assert.exists(stackTraceForExtensionProfileCall);
182+
183+
// Create an extension entry right next to our profile call (based
184+
// on its callTime property).
185+
// Test the profile call's stack strace is returned as the
186+
// extension entry's stack trace.
243187
const mockExtensionEntry = {
244188
cat: 'devtools.extension',
245-
ts: middlePoint,
246-
pid: secondBaz.pid,
247-
tid: secondBaz.tid,
189+
ts: jsCall.ts,
190+
pid: jsCall.pid,
191+
tid: jsCall.tid,
248192
rawSourceEvent: {
249193
cat: 'blink.user_timing',
250-
args: {stackTrace: [{functionName: secondBaz.callFrame.functionName}], callTime: middlePoint + 1},
194+
args: {stackTrace: [{functionName: jsCall.callFrame.functionName}], traceId: measureTraceId},
251195
ph: Trace.Types.Events.Phase.ASYNC_NESTABLE_START,
252196
},
253197
} as Trace.Types.Extensions.SyntheticExtensionEntry;
254198
const stackTraceForExtensionEntry = Trace.Extras.StackTraceForEvent.get(mockExtensionEntry, parsedTrace);
255199
assert.exists(stackTraceForExtensionEntry);
256200

257-
assert.strictEqual(stackTraceForExtensionEntry, stackTraceForSecondBaz);
201+
assert.deepEqual(stackTraceForExtensionEntry, stackTraceForExtensionProfileCall);
258202
});
259203
});

‎front_end/models/trace/extras/StackTraceForEvent.ts‎

Lines changed: 28 additions & 45 deletions
Original file line numberDiff line numberDiff line change
@@ -2,10 +2,9 @@
22
// Use of this source code is governed by a BSD-style license that can be
33
// found in the LICENSE file.
44

5-
import * as Platform from '../../../core/platform/platform.js';
65
import type * as Protocol from '../../../generated/protocol.js';
76
import type * as Handlers from '../handlers/handlers.js';
8-
import * as Helpers from '../helpers/helpers.js';
7+
import type * as Helpers from '../helpers/helpers.js';
98
import * as Types from '../types/types.js';
109

1110
export const stackTraceForEventInTrace =
@@ -36,6 +35,8 @@ export function get(event: Types.Events.Event, parsedTrace: Handlers.Types.Parse
3635
result = getForProfileCall(event, parsedTrace);
3736
} else if (Types.Extensions.isSyntheticExtensionEntry(event)) {
3837
result = getForExtensionEntry(event, parsedTrace);
38+
} else if (Types.Events.isUserTiming(event)) {
39+
result = getForUserTiming(event, parsedTrace);
3940
}
4041
if (result) {
4142
cacheForTrace.set(event, result);
@@ -114,54 +115,36 @@ function getForProfileCall(
114115
*/
115116
function getForExtensionEntry(event: Types.Extensions.SyntheticExtensionEntry, parsedTrace: Handlers.Types.ParsedTrace):
116117
Protocol.Runtime.StackTrace|null {
117-
const eventCallPoint = Helpers.Trace.getZeroIndexedStackTraceForEvent(event)?.[0];
118-
if (!eventCallPoint) {
119-
return null;
120-
}
121-
const eventCallTime = Types.Events.isPerformanceMeasureBegin(event.rawSourceEvent) ?
122-
event.rawSourceEvent.args.callTime :
123-
Types.Events.isPerformanceMark(event.rawSourceEvent) ?
124-
event.rawSourceEvent.args.data?.callTime :
125-
// event added with console.timeStamp: take the original event's
126-
// ts.
127-
event.rawSourceEvent.ts;
128-
if (eventCallTime === undefined) {
129-
return null;
118+
return getForUserTiming(event.rawSourceEvent, parsedTrace);
119+
}
120+
121+
/**
122+
* Finds the JS call in which the user timing API was called and returns
123+
* its stack trace.
124+
*/
125+
function getForUserTiming(
126+
event: Types.Events.UserTiming|Types.Events.ConsoleTimeStamp,
127+
parsedTrace: Handlers.Types.ParsedTrace): Protocol.Runtime.StackTrace|null {
128+
let rawEvent: Types.Events.Event|undefined = event;
129+
if (Types.Events.isPerformanceMeasureBegin(event)) {
130+
if (event.args.traceId === undefined) {
131+
return null;
132+
}
133+
rawEvent = parsedTrace.UserTimings.measureTraceByTraceId.get(event.args.traceId);
130134
}
131-
const callsInThread = parsedTrace.Renderer.processes.get(event.pid)?.threads.get(event.tid)?.profileCalls;
132-
if (!callsInThread) {
135+
if (!rawEvent) {
133136
return null;
134137
}
135-
const matchByName = callsInThread.filter(e => {
136-
return e.callFrame.functionName === eventCallPoint.functionName;
137-
});
138-
139-
const lastCallBeforeEventIndex =
140-
Platform.ArrayUtilities.nearestIndexFromEnd(matchByName, profileCall => profileCall.ts <= eventCallTime);
141-
const firstCallAfterEventIndex =
142-
Platform.ArrayUtilities.nearestIndexFromBeginning(matchByName, profileCall => profileCall.ts >= eventCallTime);
143-
const lastCallBeforeEvent = typeof lastCallBeforeEventIndex === 'number' && matchByName.at(lastCallBeforeEventIndex);
144-
const firstCallAfterEvent = typeof firstCallAfterEventIndex === 'number' && matchByName.at(firstCallAfterEventIndex);
145-
146-
let closestMatchingProfileCall: Types.Events.SyntheticProfileCall;
147-
if (!lastCallBeforeEvent && !firstCallAfterEvent) {
148-
return null;
138+
// Look for the nearest profile call ancestor of the event tracing
139+
// the call to the API.
140+
let node: Helpers.TreeHelpers.TraceEntryNode|undefined|null = parsedTrace.Renderer.entryToNode.get(rawEvent);
141+
while (node && !Types.Events.isProfileCall(node.entry)) {
142+
node = node.parent;
149143
}
150-
if (!lastCallBeforeEvent) {
151-
// Per the check above firstCallAfterEvent is guaranteed to exist
152-
// but ts is unaware, so we cast the type.
153-
closestMatchingProfileCall = firstCallAfterEvent as Types.Events.SyntheticProfileCall;
154-
} else if (!firstCallAfterEvent) {
155-
closestMatchingProfileCall = lastCallBeforeEvent;
156-
} else if (Helpers.Trace.eventContainsTimestamp(lastCallBeforeEvent, eventCallTime)) {
157-
closestMatchingProfileCall = lastCallBeforeEvent;
158-
} // pick the closest when the choice isn't clear.
159-
else if (eventCallTime - lastCallBeforeEvent.ts < firstCallAfterEvent.ts - eventCallTime) {
160-
closestMatchingProfileCall = lastCallBeforeEvent;
161-
} else {
162-
closestMatchingProfileCall = firstCallAfterEvent;
144+
if (node && Types.Events.isProfileCall(node.entry)) {
145+
return get(node.entry, parsedTrace);
163146
}
164-
return get(closestMatchingProfileCall, parsedTrace);
147+
return null;
165148
}
166149
/**
167150
* Determines if a function is a native JS API (like setTimeout,

‎front_end/models/trace/helpers/Trace.ts‎

Lines changed: 3 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -39,12 +39,6 @@ export function stackTraceInEvent(event: Types.Events.Event): Types.Events.CallF
3939
if (Types.Events.isUpdateLayoutTree(event)) {
4040
return event.args.beginData?.stackTrace || null;
4141
}
42-
if (Types.Extensions.isSyntheticExtensionEntry(event)) {
43-
return stackTraceInEvent(event.rawSourceEvent);
44-
}
45-
if (Types.Events.isSyntheticUserTiming(event)) {
46-
return stackTraceInEvent(event.rawSourceEvent);
47-
}
4842
if (Types.Events.isFunctionCall(event)) {
4943
const data = event.args.data;
5044
if (!data) {
@@ -687,5 +681,8 @@ export function extractSampleTraceId(event: Types.Events.Event): number|null {
687681
if (Types.Events.isConsoleRunTask(event) || Types.Events.isConsoleTimeStamp(event)) {
688682
return event.args?.data?.sampleTraceId || null;
689683
}
684+
if (Types.Events.isUserTimingMeasure(event)) {
685+
return event.args.sampleTraceId;
686+
}
690687
return null;
691688
}

‎front_end/models/trace/types/TraceEvents.ts‎

Lines changed: 0 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -1385,7 +1385,6 @@ export type PairableUserTiming = UserTiming&PairableAsync;
13851385
export interface PerformanceMeasureBegin extends PairableUserTiming {
13861386
args: Args&{
13871387
detail?: string,
1388-
stackTrace?: CallFrame[],
13891388
callTime?: Micro,
13901389
traceId?: number,
13911390
};
@@ -1399,7 +1398,6 @@ export interface PerformanceMark extends UserTiming {
13991398
args: Args&{
14001399
data?: ArgsData & {
14011400
detail?: string,
1402-
stackTrace?: CallFrame[],
14031401
callTime?: Micro,
14041402
},
14051403
};

0 commit comments

Comments
 (0)