[RPP] Show full stack traces for extension events

The StackTraceForEvent helper now supports extension entries, and its
output is used in their details. Just like with profile calls, we want
the full stack trace, including async calls. For this reason we don't
use only the stack trace available in the trace event, since that
contains only the synchronous function. Frameworks and third parties in
general use async tasks schedulers, meaning that to improve attribution
to authored source code in extension entries support for async call
stacks is needed.

To build the async call stack of an extension entry, we look for the JS
function call (ProfileCall) where the call to the API was made (aka the
call point to performance.mark/measure), then take the callstack of this
profile call as the call stack of the extension entry. The assignment of
the profile call to the extension entry is done based on the (sync)
stack trace available in the extension entry trace event and on the time
the API was called, this data is used to look for the closest matching
profile call.

Bug: 381861194
Change-Id: Ia3cfa9d12ecc6d6d7fcabb9faaa0e0f39613dab6
Reviewed-on: https://chromium-review.googlesource.com/c/devtools/devtools-frontend/+/6084695
Commit-Queue: Andres Olivares <[email protected]>
Reviewed-by: Jack Franklin <[email protected]>

Author: and-oli

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

@@ -165,4 +165,95 @@ describeWithEnvironment('StackTraceForTraceEvent', function() {
     ]);
     bottomFrame.functionName = originalName;
   });
+  it('correctly builds the stack trace of an extension entry', async function() {
+    const jsCall = parsedTrace.Renderer.allTraceEntries.find(
+                       e => Trace.Types.Events.isProfileCall(e) && e.callFrame.functionName === 'baz') as
+            Trace.Types.Events.SyntheticProfileCall |
+        undefined;
+    assert.exists(jsCall);
+    const stackTraceForExtensionProfileCall = Trace.Extras.StackTraceForEvent.get(jsCall, parsedTrace);
+    assert.exists(stackTraceForExtensionProfileCall);
+
+    // Create an extension entry right next to our profile call (based
+    // on its callTime property).
+    // Test the profile call's stack strace is returned as the
+    // extension entry's stack trace.
+    const mockExtensionEntry = {
+      cat: 'devtools.extension',
+      ts: jsCall.ts,
+      pid: jsCall.pid,
+      tid: jsCall.tid,
+      rawSourceEvent: {
+        cat: 'blink.user_timing',
+        args: {stackTrace: [{functionName: jsCall.callFrame.functionName}], callTime: jsCall.ts - 1},
+        ph: Trace.Types.Events.Phase.ASYNC_NESTABLE_START,
+      },
+    } as Trace.Types.Extensions.SyntheticExtensionEntry;
+    const stackTraceForExtensionEntry = Trace.Extras.StackTraceForEvent.get(mockExtensionEntry, parsedTrace);
+    assert.exists(stackTraceForExtensionEntry);
+
+    assert.strictEqual(stackTraceForExtensionEntry, stackTraceForExtensionProfileCall);
+  });
+  it('uses the stack trace of the profile call that contains an extension entry call time', async function() {
+    const bar = parsedTrace.Renderer.allTraceEntries.find(
+                    e => Trace.Types.Events.isProfileCall(e) && e.callFrame.functionName === 'bar') as
+            Trace.Types.Events.SyntheticProfileCall |
+        undefined;
+    assert.exists(bar);
+    const stackTraceForExtensionProfileCall = Trace.Extras.StackTraceForEvent.get(bar, parsedTrace);
+    assert.exists(stackTraceForExtensionProfileCall);
+
+    // Create an extension entry contained by the profile call (based on
+    // its callTime property).
+    // Test the profile call's stack strace is returned as
+    // the extension entry's stack trace.
+    const mockExtensionEntry = {
+      cat: 'devtools.extension',
+      ts: bar.ts,
+      pid: bar.pid,
+      tid: bar.tid,
+      rawSourceEvent: {
+        cat: 'blink.user_timing',
+        args: {stackTrace: [{functionName: bar.callFrame.functionName}], callTime: bar.ts + 1},
+        ph: Trace.Types.Events.Phase.ASYNC_NESTABLE_START,
+      },
+    } as Trace.Types.Extensions.SyntheticExtensionEntry;
+    const stackTraceForExtensionEntry = Trace.Extras.StackTraceForEvent.get(mockExtensionEntry, parsedTrace);
+    assert.exists(stackTraceForExtensionEntry);
+
+    assert.strictEqual(stackTraceForExtensionEntry, stackTraceForExtensionProfileCall);
+  });
+
+  it('picks the stack trace of the closest profile call when no profile call contains the extension entry call time',
+     async function() {
+       const bazCalls = parsedTrace.Renderer.allTraceEntries.filter(
+           e => Trace.Types.Events.isProfileCall(e) && e.callFrame.functionName === 'baz');
+       const firstBaz = bazCalls.at(0);
+       assert.exists(firstBaz);
+       const secondBaz = bazCalls.at(1) as Trace.Types.Events.SyntheticProfileCall;
+       assert.exists(secondBaz);
+       const middlePoint = (secondBaz.ts + firstBaz.ts) / 2;
+
+       const stackTraceForSecondBaz = Trace.Extras.StackTraceForEvent.get(secondBaz, parsedTrace);
+       assert.exists(stackTraceForSecondBaz);
+
+       // Create an extension entry contained closer to the second
+       // baz call (based on its callTime property).
+       // Test the stack trace of baz is used for it.
+       const mockExtensionEntry = {
+         cat: 'devtools.extension',
+         ts: middlePoint,
+         pid: secondBaz.pid,
+         tid: secondBaz.tid,
+         rawSourceEvent: {
+           cat: 'blink.user_timing',
+           args: {stackTrace: [{functionName: secondBaz.callFrame.functionName}], callTime: middlePoint + 1},
+           ph: Trace.Types.Events.Phase.ASYNC_NESTABLE_START,
+         },
+       } as Trace.Types.Extensions.SyntheticExtensionEntry;
+       const stackTraceForExtensionEntry = Trace.Extras.StackTraceForEvent.get(mockExtensionEntry, parsedTrace);
+       assert.exists(stackTraceForExtensionEntry);
+
+       assert.strictEqual(stackTraceForExtensionEntry, stackTraceForSecondBaz);
+     });
 });

front_end/models/trace/extras/StackTraceForEvent.ts

@@ -2,9 +2,10 @@
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
+import * as Platform from '../../../core/platform/platform.js';
 import type * as Protocol from '../../../generated/protocol.js';
 import type * as Handlers from '../handlers/handlers.js';
-import type * as Helpers from '../helpers/helpers.js';
+import * as Helpers from '../helpers/helpers.js';
 import * as Types from '../types/types.js';
 
 export const stackTraceForEventInTrace =
@@ -24,11 +25,15 @@ export function get(event: Types.Events.Event, parsedTrace: Handlers.Types.Parse
   if (resultFromCache) {
     return resultFromCache;
   }
-  if (!Types.Events.isProfileCall(event)) {
-    return null;
+  let result: Protocol.Runtime.StackTrace|null = null;
+  if (Types.Events.isProfileCall(event)) {
+    result = getForProfileCall(event, parsedTrace);
+  } else if (Types.Extensions.isSyntheticExtensionEntry(event)) {
+    result = getForExtensionEntry(event, parsedTrace);
+  }
+  if (result) {
+    cacheForTrace.set(event, result);
   }
-  const result = getForProfileCall(event, parsedTrace);
-  cacheForTrace.set(event, result);
   return result;
 }
 
@@ -95,6 +100,59 @@ function getForProfileCall(
   }
   return topStackTrace;
 }
+
+/**
+ * Finds the JS call in which an extension entry was injected (the
+ * code location that called the extension API), and returns its stack
+ * trace.
+ */
+function getForExtensionEntry(event: Types.Extensions.SyntheticExtensionEntry, parsedTrace: Handlers.Types.ParsedTrace):
+    Protocol.Runtime.StackTrace|null {
+  const eventCallPoint = Helpers.Trace.getZeroIndexedStackTraceForEvent(event)?.[0];
+  if (!eventCallPoint) {
+    return null;
+  }
+  const eventCallTime = Types.Events.isPerformanceMeasureBegin(event.rawSourceEvent) ?
+      event.rawSourceEvent.args.callTime :
+      event.rawSourceEvent.args.data?.callTime;
+  if (eventCallTime === undefined) {
+    return null;
+  }
+  const callsInThread = parsedTrace.Renderer.processes.get(event.pid)?.threads.get(event.tid)?.profileCalls;
+  if (!callsInThread) {
+    return null;
+  }
+  const matchByName = callsInThread.filter(e => {
+    return e.callFrame.functionName === eventCallPoint.functionName;
+  });
+
+  const lastCallBeforeEventIndex =
+      Platform.ArrayUtilities.nearestIndexFromEnd(matchByName, profileCall => profileCall.ts <= eventCallTime);
+  const firstCallAfterEventIndex =
+      Platform.ArrayUtilities.nearestIndexFromBeginning(matchByName, profileCall => profileCall.ts >= eventCallTime);
+  const lastCallBeforeEvent = typeof lastCallBeforeEventIndex === 'number' && matchByName.at(lastCallBeforeEventIndex);
+  const firstCallAfterEvent = typeof firstCallAfterEventIndex === 'number' && matchByName.at(firstCallAfterEventIndex);
+
+  let closestMatchingProfileCall: Types.Events.SyntheticProfileCall;
+  if (!lastCallBeforeEvent && !firstCallAfterEvent) {
+    return null;
+  }
+  if (!lastCallBeforeEvent) {
+    // Per the check above firstCallAfterEvent is guaranteed to exist
+    // but ts is unaware, so we cast the type.
+    closestMatchingProfileCall = firstCallAfterEvent as Types.Events.SyntheticProfileCall;
+  } else if (!firstCallAfterEvent) {
+    closestMatchingProfileCall = lastCallBeforeEvent;
+  } else if (Helpers.Trace.eventContainsTimestamp(lastCallBeforeEvent, eventCallTime)) {
+    closestMatchingProfileCall = lastCallBeforeEvent;
+  }  // pick the closest when the choice isn't clear.
+  else if (eventCallTime - lastCallBeforeEvent.ts < firstCallAfterEvent.ts - eventCallTime) {
+    closestMatchingProfileCall = lastCallBeforeEvent;
+  } else {
+    closestMatchingProfileCall = firstCallAfterEvent;
+  }
+  return get(closestMatchingProfileCall, parsedTrace);
+}
 /**
  * Determines if a function is a native JS API (like setTimeout,
  * requestAnimationFrame, consoleTask.run. etc.). This is useful to

front_end/models/trace/handlers/ExtensionTraceDataHandler.ts

@@ -55,8 +55,8 @@ export function extractExtensionEntries(timings: (Types.Events.SyntheticUserTimi
     const extensionSyntheticEntry = {
       name: timing.name,
       ph: Types.Events.Phase.COMPLETE,
-      pid: Types.Events.ProcessID(0),
-      tid: Types.Events.ThreadID(0),
+      pid: timing.pid,
+      tid: timing.tid,
       ts: timing.ts,
       dur: timing.dur as Types.Timing.MicroSeconds,
       cat: 'devtools.extension',

front_end/models/trace/helpers/Trace.ts

@@ -11,7 +11,6 @@ import * as Types from '../types/types.js';
 import {SyntheticEventsManager} from './SyntheticEvents.js';
 import {eventTimingsMicroSeconds} from './Timing.js';
 
-type MatchedPairType<T extends Types.Events.PairableAsync> = Types.Events.SyntheticEventPair<T>;
 type MatchingPairableAsyncEvents = {
   begin: Types.Events.PairableAsyncBegin|null,
   end: Types.Events.PairableAsyncEnd|null,
@@ -179,8 +178,8 @@ export function getNavigationForTraceEvent(
   return navigations[eventNavigationIndex];
 }
 
-export function extractId(event: Types.Events.PairableAsync|MatchedPairType<Types.Events.PairableAsync>): string|
-    undefined {
+export function extractId(event: Types.Events.PairableAsync|
+                          Types.Events.SyntheticEventPair<Types.Events.PairableAsync>): string|undefined {
   return event.id ?? event.id2?.global ?? event.id2?.local;
 }
 
@@ -288,9 +287,9 @@ export function createSortedSyntheticEvents<T extends Types.Events.PairableAsync
       end: Types.Events.PairableAsyncEnd | null,
       instant?: Types.Events.PairableAsyncInstant[],
     }>,
-    syntheticEventCallback?: (syntheticEvent: MatchedPairType<T>) => void,
-    ): MatchedPairType<T>[] {
-  const syntheticEvents: MatchedPairType<T>[] = [];
+    syntheticEventCallback?: (syntheticEvent: Types.Events.SyntheticEventPair<T>) => void,
+    ): Types.Events.SyntheticEventPair<T>[] {
+  const syntheticEvents: Types.Events.SyntheticEventPair<T>[] = [];
   for (const [id, eventsTriplet] of matchedPairs.entries()) {
     const beginEvent = eventsTriplet.begin;
     const endEvent = eventsTriplet.end;
@@ -311,7 +310,7 @@ export function createSortedSyntheticEvents<T extends Types.Events.PairableAsync
       beginEvent: Types.Events.PairableAsyncBegin,
       endEvent: Types.Events.PairableAsyncEnd|null,
       instantEvents?: Types.Events.PairableAsyncInstant[],
-    }): data is MatchedPairType<T>['args']['data'] {
+    }): data is Types.Events.SyntheticEventPair<T>['args']['data'] {
       const instantEventsMatch = data.instantEvents ? data.instantEvents.some(e => id === getSyntheticId(e)) : false;
       const endEventMatch = data.endEvent ? id === getSyntheticId(data.endEvent) : false;
       return Boolean(id) && (instantEventsMatch || endEventMatch);
@@ -321,8 +320,8 @@ export function createSortedSyntheticEvents<T extends Types.Events.PairableAsync
     }
     const targetEvent = endEvent || beginEvent;
 
-    const event = SyntheticEventsManager.registerSyntheticEvent<MatchedPairType<T>>({
-      rawSourceEvent: beginEvent,
+    const event = SyntheticEventsManager.registerSyntheticEvent<Types.Events.SyntheticEventPair<T>>({
+      rawSourceEvent: triplet.beginEvent,
       cat: targetEvent.cat,
       ph: targetEvent.ph,
       pid: targetEvent.pid,
@@ -352,8 +351,8 @@ export function createSortedSyntheticEvents<T extends Types.Events.PairableAsync
 }
 
 export function createMatchedSortedSyntheticEvents<T extends Types.Events.PairableAsync>(
-    unpairedAsyncEvents: T[],
-    syntheticEventCallback?: (syntheticEvent: MatchedPairType<T>) => void): MatchedPairType<T>[] {
+    unpairedAsyncEvents: T[], syntheticEventCallback?: (syntheticEvent: Types.Events.SyntheticEventPair<T>) => void):
+    Types.Events.SyntheticEventPair<T>[] {
   const matchedPairs = matchEvents(unpairedAsyncEvents);
   const syntheticEvents = createSortedSyntheticEvents<T>(matchedPairs, syntheticEventCallback);
   return syntheticEvents;
@@ -652,3 +651,7 @@ export function nodeIdForInvalidationEvent(event: Types.Events.InvalidationTrack
     null {
   return event.args.data.nodeId ?? null;
 }
+
+export function eventContainsTimestamp(event: Types.Events.Event, ts: Types.Timing.MicroSeconds): boolean {
+  return event.ts <= ts && event.ts + (event.dur || 0) >= ts;
+}

front_end/models/trace/types/Extensions.ts

@@ -2,7 +2,7 @@
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
-import type {Args, Event, Phase, SyntheticBased} from './TraceEvents.js';
+import type {Args, Event, PerformanceMark, PerformanceMeasureBegin, Phase, SyntheticBased} from './TraceEvents.js';
 
 export type ExtensionEntryType = 'track-entry'|'marker';
 
@@ -57,14 +57,15 @@ export interface ExtensionMarkerPayload extends ExtensionDataPayloadBase {
 /**
  * Synthetic events created for extension tracks.
  */
-export interface SyntheticExtensionTrackEntry extends SyntheticBased<Phase.COMPLETE> {
+export interface SyntheticExtensionTrackEntry extends
+    SyntheticBased<Phase.COMPLETE, PerformanceMeasureBegin|PerformanceMark> {
   args: Args&ExtensionTrackEntryPayload;
 }
 
 /**
  * Synthetic events created for extension marks.
  */
-export interface SyntheticExtensionMarker extends SyntheticBased<Phase.COMPLETE> {
+export interface SyntheticExtensionMarker extends SyntheticBased<Phase.COMPLETE, PerformanceMark> {
   args: Args&ExtensionMarkerPayload;
 }
 

front_end/models/trace/types/TraceEvents.ts

@@ -1338,6 +1338,7 @@ export interface PerformanceMeasureBegin extends PairableUserTiming {
   args: Args&{
     detail?: string,
     stackTrace?: CallFrame[],
+    callTime?: MicroSeconds,
   };
   ph: Phase.ASYNC_NESTABLE_START;
 }
@@ -1350,6 +1351,7 @@ export interface PerformanceMark extends UserTiming {
     data?: ArgsData & {
       detail?: string,
       stackTrace?: CallFrame[],
+      callTime?: MicroSeconds,
     },
   };
   ph: Phase.INSTANT|Phase.MARK|Phase.ASYNC_NESTABLE_INSTANT;
@@ -1482,9 +1484,9 @@ export function isPipelineReporter(event: Event): event is PipelineReporter {
 // because synthetic events need to be registered in order to resolve
 // serialized event keys into event objects, so we ensure events are
 // registered at the time they are created by the SyntheticEventsManager.
-export interface SyntheticBased<Ph extends Phase = Phase> extends Event {
+export interface SyntheticBased<Ph extends Phase = Phase, T extends Event = Event> extends Event {
   ph: Ph;
-  rawSourceEvent: Event;
+  rawSourceEvent: T;
   _tag: 'SyntheticEntryTag';
 }
 
@@ -1495,8 +1497,8 @@ export function isSyntheticBased(event: Event): event is SyntheticBased {
 // Nestable async events with a duration are made up of two distinct
 // events: the begin, and the end. We need both of them to be able to
 // display the right information, so we create these synthetic events.
-export interface SyntheticEventPair<T extends PairableAsync = PairableAsync> extends SyntheticBased {
-  rawSourceEvent: Event;
+export interface SyntheticEventPair<T extends PairableAsync = PairableAsync> extends SyntheticBased<Phase, T> {
+  rawSourceEvent: T;
   name: T['name'];
   cat: T['cat'];
   id?: string;
@@ -2221,6 +2223,10 @@ export function isPerformanceMeasure(event: Event): event is PerformanceMeasure
   return isUserTiming(event) && isPhaseAsync(event.ph);
 }
 
+export function isPerformanceMeasureBegin(event: Event): event is PerformanceMeasureBegin {
+  return isPerformanceMeasure(event) && event.ph === Phase.ASYNC_NESTABLE_START;
+}
+
 export function isPerformanceMark(event: Event): event is PerformanceMark {
   return isUserTiming(event) && (event.ph === Phase.MARK || event.ph === Phase.INSTANT);
 }