[PP] Handle multiple async task runs caused by the same schedule event

Before this CL we assumed that every async task run event was connected
via Perfetto's flow API to its corresponding scheduling event. However,
because for async tasks the flow id is created based on its memory
address, if a single scheduling task causes multiple "run" events, each
of them  will appear as parent of the subsequent one (since they
will all have the same flow id).

To fix this, when we detect a schedule event to be the async parent of
a run event, we cache it. This way, when we detect the same run event to
be the async parent of another run, we can assign the original schedule
event as its effective async parent event

This fixes a bug in itself and will also be used to improve how we build
async stack traces for trace entries (that will happen in a follow up).

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

Author: and-oli

front_end/models/trace/handlers/AsyncJSCallsHandler.test.ts

@@ -157,6 +157,35 @@ describe('AsyncJSCallsHandler', function() {
       assert.strictEqual(testRunEntryPoints?.[0], firstJSTaskRunEntryPoint);
       assert.strictEqual(testRunEntryPoints?.[1], secondJSTaskRunEntryPoint);
     });
+
+    it('assigns the right scheduled events to an event that scheduled multiple tasks', async function() {
+      const jsTaskScheduler = makeProfileCall('setInterval', 0, 30, pid, tid);
+      const asyncTaskScheduled =
+          makeCompleteEvent(Trace.Types.Events.Name.DEBUGGER_ASYNC_TASK_SCHEDULED, 0, 0, cat, pid, tid);
+
+      // Simulate two async task runs caused by the same scheduled event.
+      const asyncTaskRun1 = makeCompleteEvent(Trace.Types.Events.Name.DEBUGGER_ASYNC_TASK_RUN, 60, 100, cat, tid, pid);
+      const jsTaskRunEntryPoint1 = makeCompleteEvent(Trace.Types.Events.Name.FUNCTION_CALL, 70, 20, cat, tid, pid);
+
+      const asyncTaskRun2 = makeCompleteEvent(Trace.Types.Events.Name.DEBUGGER_ASYNC_TASK_RUN, 260, 100, cat, tid, pid);
+      const jsTaskRunEntryPoint2 = makeCompleteEvent(Trace.Types.Events.Name.FUNCTION_CALL, 270, 20, cat, tid, pid);
+
+      // Create flow events in the same way perfetto does for traces (as separate pairs).
+      // schedule -> run 1, run 1 -> run 2.
+      const flowEvents = [
+        ...makeFlowEvents([asyncTaskScheduled, asyncTaskRun1], 0), ...makeFlowEvents([asyncTaskRun1, asyncTaskRun2], 1)
+      ];
+      const rendererEvents = [
+        jsTaskScheduler, asyncTaskScheduled, asyncTaskRun1, jsTaskRunEntryPoint1, asyncTaskRun2, jsTaskRunEntryPoint2
+      ];
+      const allEvents = [...rendererEvents, ...flowEvents];
+
+      const asyncCallStacksData = await buildAsyncJSCallsHandlerData(allEvents);
+      const testRunEntryPoints = asyncCallStacksData.schedulerToRunEntryPoints.get(jsTaskScheduler);
+      assert.strictEqual(testRunEntryPoints?.length, 2);
+      assert.strictEqual(testRunEntryPoints?.[0], jsTaskRunEntryPoint1);
+      assert.strictEqual(testRunEntryPoints?.[1], jsTaskRunEntryPoint2);
+    });
   });
   describe('Resolving async JS tasks to schedulers', function() {
     it('associates an async JS task to its scheduler', async function() {
@@ -207,5 +236,42 @@ describe('AsyncJSCallsHandler', function() {
       testScheduler = asyncCallStacksData.asyncCallToScheduler.get(asyncJSTask2)?.scheduler;
       assert.isUndefined(testScheduler);
     });
+    it('returns the right scheduler for a task with multiple run events', async function() {
+      const jsTaskScheduler = makeProfileCall('setInterval', 0, 50, pid, tid);
+      const asyncTaskScheduled =
+          makeCompleteEvent(Trace.Types.Events.Name.DEBUGGER_ASYNC_TASK_SCHEDULED, 0, 0, cat, pid, tid) as
+          Trace.Types.Events.DebuggerAsyncTaskScheduled;
+      asyncTaskScheduled.args.taskName = 'interval';
+
+      // Simulate two async task runs caused by the same scheduled event.
+      const asyncTaskRun1 = makeCompleteEvent(Trace.Types.Events.Name.DEBUGGER_ASYNC_TASK_RUN, 60, 100, cat, tid, pid);
+      const jsTaskRunEntryPoint1 = makeCompleteEvent(Trace.Types.Events.Name.FUNCTION_CALL, 70, 20, cat, tid, pid);
+      const asyncJSTask1 = makeProfileCall('scheduledFunction1', 71, 10, pid, tid);
+
+      const asyncTaskRun2 = makeCompleteEvent(Trace.Types.Events.Name.DEBUGGER_ASYNC_TASK_RUN, 160, 100, cat, tid, pid);
+      const jsTaskRunEntryPoint2 = makeCompleteEvent(Trace.Types.Events.Name.FUNCTION_CALL, 170, 20, cat, tid, pid);
+      const asyncJSTask2 = makeProfileCall('scheduledFunction2', 171, 10, pid, tid);
+
+      // Create flow events in the same way perfetto does for traces (as separate pairs).
+      // schedule -> run 1, run 1 -> run 2.
+      const flowEvents = [
+        ...makeFlowEvents([asyncTaskScheduled, asyncTaskRun1], 0), ...makeFlowEvents([asyncTaskRun1, asyncTaskRun2], 1)
+      ];
+      const rendererEvents = [
+        jsTaskScheduler, asyncTaskScheduled, asyncTaskRun1, jsTaskRunEntryPoint1, asyncJSTask1, asyncTaskRun2,
+        jsTaskRunEntryPoint2, asyncJSTask2
+      ];
+      const allEvents = [...rendererEvents, ...flowEvents];
+
+      const asyncCallStacksData = await buildAsyncJSCallsHandlerData(allEvents);
+      let testScheduler = asyncCallStacksData.asyncCallToScheduler.get(asyncJSTask1);
+      assert.strictEqual(testScheduler?.scheduler, jsTaskScheduler);
+      assert.strictEqual(testScheduler?.taskName, asyncTaskScheduled.args.taskName);
+
+      testScheduler = asyncCallStacksData.asyncCallToScheduler.get(asyncJSTask2);
+      assert.strictEqual(testScheduler?.scheduler, jsTaskScheduler);
+      assert.strictEqual(testScheduler?.taskName, asyncTaskScheduled.args.taskName);
+    });
+
   });
 });

front_end/models/trace/handlers/AsyncJSCallsHandler.ts

@@ -9,12 +9,16 @@ import {data as flowsHandlerData} from './FlowsHandler.js';
 import {data as rendererHandlerData} from './RendererHandler.js';
 
 const schedulerToRunEntryPoints = new Map<Types.Events.Event, Types.Events.Event[]>();
+
+const taskScheduleForTaskRunEvent =
+    new Map<Types.Events.DebuggerAsyncTaskRun, Types.Events.DebuggerAsyncTaskScheduled>();
 const asyncCallToScheduler =
     new Map<Types.Events.SyntheticProfileCall, {taskName: string, scheduler: Types.Events.Event}>();
 
 export function reset(): void {
   schedulerToRunEntryPoints.clear();
   asyncCallToScheduler.clear();
+  taskScheduleForTaskRunEvent.clear();
 }
 
 export function handleEvent(_: Types.Events.Event): void {
@@ -25,17 +29,48 @@ export async function finalize(): Promise<void> {
   const {entryToNode} = rendererHandlerData();
   // Process async task flows
   for (const flow of flows) {
-    const asyncTaskScheduled = flow.at(0);
-    if (!asyncTaskScheduled || !Types.Events.isDebuggerAsyncTaskScheduled(asyncTaskScheduled)) {
+    let maybeAsyncTaskScheduled = flow.at(0);
+    if (!maybeAsyncTaskScheduled) {
       continue;
     }
-    const taskName = asyncTaskScheduled.args.taskName;
+    if (Types.Events.isDebuggerAsyncTaskRun(maybeAsyncTaskScheduled)) {
+      // Sometimes a AsyncTaskRun event run can incorrectly appear as
+      // initiated by another AsyncTaskRun from Perfetto's flows
+      // perspective.
+      // For example, in this snippet:
+      //
+      // const myTask = console.createTask('hola'); // creates an AsyncTaskSchedule
+      // myTask.run(something); // creates an AsyncTaskRun
+      // myTask.run(somethingElse); // creates an AsyncTaskRun
+      //
+      // or also in this one
+      //
+      // setInterval(something); // creates multiple connected AsyncTaskRun.
+      //
+      // Because the flow id is created based on the task's memory address,
+      // the three events will end up belonging to the same flow (even if
+      // in the frontend we receive it as pairs), and elements in a flow
+      // are connected to their immediately consecutive neighbor.
+      //
+      // To ensure we use the right Schedule event, if the "initiating"
+      // portion of the flow is a Run event, we look for any corresponding
+      // Schedule event that we might have found before.
+      maybeAsyncTaskScheduled = taskScheduleForTaskRunEvent.get(maybeAsyncTaskScheduled);
+    }
+    if (!maybeAsyncTaskScheduled || !Types.Events.isDebuggerAsyncTaskScheduled(maybeAsyncTaskScheduled)) {
+      continue;
+    }
+    const taskName = maybeAsyncTaskScheduled.args.taskName;
     const asyncTaskRun = flow.at(1);
     if (!asyncTaskRun || !Types.Events.isDebuggerAsyncTaskRun(asyncTaskRun)) {
       // Unexpected flow shape, ignore.
       continue;
     }
-    const asyncCaller = findNearestJSAncestor(asyncTaskScheduled, entryToNode);
+    // Cache the Schedule event for this Run for future reference.
+    taskScheduleForTaskRunEvent.set(asyncTaskRun, maybeAsyncTaskScheduled);
+
+    // Get the JS call scheduled the task.
+    const asyncCaller = findNearestJSAncestor(maybeAsyncTaskScheduled, entryToNode);
     if (!asyncCaller) {
       // Unexpected async call trace data shape, ignore.
       continue;

front_end/testing/TraceHelpers.ts

@@ -301,12 +301,12 @@ export function makeFlowPhaseEvent(
  * flow. `events` must be ordered.
  */
 export function makeFlowEvents(events: Trace.Types.Events.Event[], flowId = 0): Trace.Types.Events.FlowEvent[] {
-  const lastEvent = events.at(-1);
   const firstEvent = events.at(0);
+  const lastEvent = events.at(-1);
   if (!lastEvent || !firstEvent) {
     return [];
   }
-  const flowName = events[0].name;
+  const flowName = firstEvent.name;
   const flowStart = makeFlowPhaseEvent(
       flowName, firstEvent.ts, firstEvent.cat, Trace.Types.Events.Phase.FLOW_START, flowId, firstEvent.pid,
       firstEvent.tid);