[RPP] Speed up flows handler

By checking that we only assign events to flows once given a flow
binding tuple (a token that allows us to match events to flows,
consisting of the event's ts, cat, pid and tid).

Perfetto's trace event format [1] only considers the first event that
matches a given binding before assigning an event to a flow. By being
consistent with this behavior we are able to skip subsequent events with
a matching binding and save quite some time on traces with many repeated
flow binding tuples.

To prevent further regressions, added a perf test case that consistently
fails on the previous state.

[1] https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU/preview?tab=t.0#heading=h.4qqub5rv9ybk

Fixed: 382545507
Change-Id: I33d0ab6e167549a6499eaf6499b5a5f10d777336
Reviewed-on: https://chromium-review.googlesource.com/c/devtools/devtools-frontend/+/6097891
Auto-Submit: Andres Olivares <[email protected]>
Reviewed-by: Adam Raine <[email protected]>
Commit-Queue: Andres Olivares <[email protected]>

Author: and-oli

front_end/core/platform/MapUtilities.ts

@@ -85,7 +85,7 @@ export class Multimap<K, V> {
 export function getWithDefault<K extends {}, V>(
     map: WeakMap<K, V>|Map<K, V>, key: K, defaultValueFactory: (key?: K) => V): V {
   let value = map.get(key);
-  if (!value) {
+  if (value === undefined || value === null) {
     value = defaultValueFactory(key);
     map.set(key, value);
   }

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

@@ -96,7 +96,7 @@ describe('AsyncJSCallsHandler', function() {
        async function() {
          const jsTaskScheduler = makeCompleteEvent(Trace.Types.Events.Name.FUNCTION_CALL, 0, 30, cat, tid, pid);
          const asyncTaskScheduled =
-             makeCompleteEvent(Trace.Types.Events.Name.DEBUGGER_ASYNC_TASK_SCHEDULED, 0, 0, cat, pid, tid);
+             makeCompleteEvent(Trace.Types.Events.Name.DEBUGGER_ASYNC_TASK_SCHEDULED, 5, 0, cat, pid, tid);
 
          const asyncTaskRun =
              makeCompleteEvent(Trace.Types.Events.Name.DEBUGGER_ASYNC_TASK_RUN, 60, 100, cat, tid, pid);
@@ -122,7 +122,7 @@ describe('AsyncJSCallsHandler', function() {
       const jsTaskScheduler = makeCompleteEvent(Trace.Types.Events.Name.FUNCTION_CALL, 0, 30, cat, tid, pid);
       // Two asyncTaskScheduled events right under the function call.
       const asyncTaskScheduled1 =
-          makeCompleteEvent(Trace.Types.Events.Name.DEBUGGER_ASYNC_TASK_SCHEDULED, 0, 0, cat, pid, tid);
+          makeCompleteEvent(Trace.Types.Events.Name.DEBUGGER_ASYNC_TASK_SCHEDULED, 5, 0, cat, pid, tid);
 
       const asyncTaskScheduled2 =
           makeCompleteEvent(Trace.Types.Events.Name.DEBUGGER_ASYNC_TASK_SCHEDULED, 10, 0, cat, pid, tid);

front_end/models/trace/handlers/FlowsHandler.ts

@@ -1,6 +1,7 @@
 // Copyright 2024 The Chromium Authors. All rights reserved.
 // 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 * as Types from '../types/types.js';
 
 // A flow is a logic connection between trace events. We display this
@@ -23,9 +24,28 @@ import * as Types from '../types/types.js';
 // flows with the timestamps of each phase. Then, we place trace events
 // in the flows where their corresponding phase events were placed (if
 // there are any corresponding flow phase events at all).
-const flowDataByGroupToken = new Map<string, {flowId: number, times: Types.Timing.MicroSeconds[]}>();
-const flowPhaseBindingTokenToFlowId = new Map<string, Set<number>>();
-const flowsById = new Map<number, {times: Types.Timing.MicroSeconds[], events: Types.Events.Event[]}>();
+const flowDataByGroupToken = new Map<string, number>();
+
+type EventFlowData = {
+  flows: Set<number>,
+  bindingParsed: boolean,
+};
+type FlowBindingTuple =
+    Map<Types.Timing.MicroSeconds, Map<Types.Events.ProcessID, Map<Types.Events.ThreadID, Map<string, EventFlowData>>>>;
+
+// Given a trace event's flow binding tuple (timestamp, process id,
+// thread id and category) we determine if there is any flow data bound
+// to it by using this map's content. It's built when processing flow
+// events in a trace.
+// An alternative to having a map of four levels is having single map
+// from a string token built from concatenating the binding data to the
+// corresponding flow data. However, this token would be calculated for
+// every event in a trace, resulting in a lot of memory overhead and
+// major GC triggering. So we are trading off readability for
+// performance.
+const boundFlowData: FlowBindingTuple = new Map();
+
+const flowsById = new Map<number, Map<Types.Timing.MicroSeconds, Types.Events.Event>>();
 const flowEvents: Types.Events.FlowEvent[] = [];
 const nonFlowEvents: Types.Events.Event[] = [];
 let flows: Types.Events.Event[][] = [];
@@ -35,7 +55,7 @@ export function reset(): void {
   flowEvents.length = 0;
   nonFlowEvents.length = 0;
   flowDataByGroupToken.clear();
-  flowPhaseBindingTokenToFlowId.clear();
+  boundFlowData.clear();
   flowsById.clear();
 }
 
@@ -48,22 +68,21 @@ export function handleEvent(event: Types.Events.Event): void {
 }
 
 function processNonFlowEvent(event: Types.Events.Event): void {
-  const flowPhaseBindingToken = flowPhaseBindingTokenForEvent(event);
-  const flowIds = flowPhaseBindingTokenToFlowId.get(flowPhaseBindingToken);
-  if (!flowIds) {
+  const flowDataForEvent = boundFlowData.get(event.ts)?.get(event.pid)?.get(event.tid)?.get(event.cat);
+  if (!flowDataForEvent) {
     return;
   }
-  for (const flowId of flowIds) {
-    const flow = flowsById.get(flowId);
-    if (!flow) {
-      continue;
-    }
-    const timeIndex = flow.times.indexOf(event.ts);
-    if (timeIndex < 0) {
-      continue;
-    }
-    flow.events[timeIndex] = event;
+  const {flows, bindingParsed} = flowDataForEvent;
+  if (bindingParsed) {
+    // We only consider the first event for a given flow binding tuple.
+    return;
   }
+  for (const flowId of flows) {
+    const flow = Platform.MapUtilities.getWithDefault(
+        flowsById, flowId, () => new Map<Types.Timing.MicroSeconds, Types.Events.Event>());
+    flow.set(event.ts, event);
+  }
+  flowDataForEvent.bindingParsed = true;
 }
 
 /**
@@ -76,51 +95,53 @@ function processFlowEvent(flowPhaseEvent: Types.Events.FlowEvent): void {
   const flowGroup = flowGroupTokenForFlowPhaseEvent(flowPhaseEvent);
   switch (flowPhaseEvent.ph) {
     case (Types.Events.Phase.FLOW_START): {
-      const flowMetadata = {flowId: flowPhaseEvent.id, times: [flowPhaseEvent.ts]};
-      flowDataByGroupToken.set(flowGroup, flowMetadata);
-      addFlowIdToFlowPhaseBinding(flowPhaseBindingTokenForEvent(flowPhaseEvent), flowMetadata.flowId);
+      const flowMetadata = {flowId: flowPhaseEvent.id, times: new Map([[flowPhaseEvent.ts, undefined]])};
+      flowDataByGroupToken.set(flowGroup, flowPhaseEvent.id);
+      addFlowIdToEventBinding(flowPhaseEvent, flowMetadata.flowId);
       return;
     }
     case (Types.Events.Phase.FLOW_STEP): {
-      const flow = flowDataByGroupToken.get(flowGroup);
-      if (!flow || flow.times.length < 0) {
+      const flowId = flowDataByGroupToken.get(flowGroup);
+      if (flowId === undefined) {
         // Found non-start flow event with no corresponding start flow,
-        // start event. Quietly ignore problematic event.
+        // start event. Quietly ignore the problematic event.
         return;
       }
-      addFlowIdToFlowPhaseBinding(flowPhaseBindingTokenForEvent(flowPhaseEvent), flow.flowId);
-      flow.times.push(flowPhaseEvent.ts);
+      addFlowIdToEventBinding(flowPhaseEvent, flowId);
       return;
     }
     case (Types.Events.Phase.FLOW_END): {
-      const flow = flowDataByGroupToken.get(flowGroup);
-      if (!flow || flow.times.length < 0) {
+      const flowId = flowDataByGroupToken.get(flowGroup);
+      if (flowId === undefined) {
         // Found non-start flow event with no corresponding start flow,
-        // start event. Quietly ignore problematic event.
+        // start event. Quietly ignore the problematic event.
         return;
       }
-      addFlowIdToFlowPhaseBinding(flowPhaseBindingTokenForEvent(flowPhaseEvent), flow.flowId);
-      flow.times.push(flowPhaseEvent.ts);
-      flowsById.set(flow.flowId, {times: flow.times, events: []});
+      addFlowIdToEventBinding(flowPhaseEvent, flowId);
       // We don't need this data anymore as the flow has been finished,
       // so we can drop it.
       flowDataByGroupToken.delete(flowGroup);
     }
   }
 }
 
+type MapValueType<T extends Map<unknown, unknown>> = NonNullable<ReturnType<T['get']>>;
 /**
  * A single trace event can belong to multiple flows. This method
- * tracks which flows (flowId) an event belongs to (given
- * its flow phase binding token).
+ * tracks which flows (flowId) an event belongs to given its flow
+ * binding tuple (made of its ts, pid, tid and cat).
  */
-function addFlowIdToFlowPhaseBinding(flowPhaseBinding: string, flowId: number): void {
-  let flowIds = flowPhaseBindingTokenToFlowId.get(flowPhaseBinding);
-  if (!flowIds) {
-    flowIds = new Set();
-  }
-  flowIds.add(flowId);
-  flowPhaseBindingTokenToFlowId.set(flowPhaseBinding, flowIds);
+function addFlowIdToEventBinding(event: Types.Events.Event, flowId: number): void {
+  const flowsByPid =
+      Platform.MapUtilities.getWithDefault<Types.Timing.MicroSeconds, MapValueType<typeof boundFlowData>>(
+          boundFlowData, event.ts, () => new Map());
+  const flowsByTid = Platform.MapUtilities.getWithDefault<Types.Events.ProcessID, MapValueType<typeof flowsByPid>>(
+      flowsByPid, event.pid, () => new Map());
+  const flowsByCat = Platform.MapUtilities.getWithDefault<Types.Events.ThreadID, MapValueType<typeof flowsByTid>>(
+      flowsByTid, event.tid, () => new Map());
+  const flowData =
+      Platform.MapUtilities.getWithDefault(flowsByCat, event.cat, () => ({flows: new Set(), bindingParsed: false}));
+  flowData.flows.add(flowId);
 }
 
 /**
@@ -138,29 +159,14 @@ function flowGroupTokenForFlowPhaseEvent(event: Types.Events.FlowEvent): string
   return `${event.cat}${ID_COMPONENT_SEPARATOR}${event.name}${ID_COMPONENT_SEPARATOR}${event.id}`;
 }
 
-/**
- * A flow phase binding is a token that allows us to associate a flow
- * phase event to its corresponding event. This association indicates
- * what role a trace event plays in a flow.
- * We can assign a trace event with a flow phase when its category,
- * thread id, process id and timestamp matches those of a flow phase
- * event.
- */
-function flowPhaseBindingTokenForEvent(event: Types.Events.Event): string {
-  // This function is called many times (one per event) and creating a
-  // string every time can trigger GC. If this becomes a problem, a
-  // possible optimization is to use a multi-key map with the
-  // binding token components, a trade off between memory performance
-  // and readability.
-  return `${event.cat}${ID_COMPONENT_SEPARATOR}${event.tid}${ID_COMPONENT_SEPARATOR}${event.pid}${
-      ID_COMPONENT_SEPARATOR}${event.ts}`;
-}
-
 export async function finalize(): Promise<void> {
   // Order is important: flow events need to be handled first.
   flowEvents.forEach(processFlowEvent);
   nonFlowEvents.forEach(processNonFlowEvent);
-  flows = [...flowsById.values()].map(f => f.events).filter(flow => flow.length > 1);
+  flows = [...flowsById.values()]
+              .map(flowMapping => [...flowMapping.values()])
+              .map(flow => flow.filter(event => event !== undefined))
+              .filter(flow => flow.length > 1);
 }
 
 export function data(): {flows: Types.Events.Event[][]} {

front_end/panels/timeline/fixtures/traces/BUILD.gn

@@ -20,6 +20,7 @@ copy_to_gen("traces") {
     "cls-multiple-frames.json.gz",
     "cls-no-nav.json.gz",
     "cls-single-frame.json.gz",
+    "dom-size-long.json.gz",
     "dom-size.json.gz",
     "enhanced-traces.json.gz",
     "extension-tracks-and-marks.json.gz",

front_end/panels/timeline/fixtures/traces/README.md

@@ -229,6 +229,9 @@ Generate from a recording of [this HTML file](https://gist.github.com/adamraine/
 5. Click the button once
 6. End recording
 
+### dom-size-long
+Contains a trace from a site with a large DOM. It also happens to have many flows with duplicated flow bindings, so it's useful to test the FlowsHandler remains quick.
+
 ### lcp-multiple-frames
 
 Generated from [lcp-iframes story](https://github.com/ChromeDevTools/performance-stories/tree/main/lcp-iframes).

front_end/panels/timeline/fixtures/traces/dom-size-long.json.gz

@@ -5,8 +5,8 @@ These are performance tests that run benchmarks of automated userflows. The resu
 The tests are run on devtools CI on the "Standalone Linux" bot. The result of each run is [uploaded](https://source.chromium.org/chromium/infra/infra_superproject/+/main:build/recipes/recipes/devtools/devtools-frontend.py?q=publish_performance_benchmarks) to Skia Perf  so that the benchmarks can be monitored in [devtools own dashboard instance](https://devtools-frontend-perf.corp.goog/e/) .
 
 
-## Quick links
-* [Performance panel "TraceLoad" benchmark dashboard](https://devtools-frontend-perf.corp.goog/e/?queries=stats%3Dmean%26test%3DTraceLoad)
-* [DevTools "BootPerf" benchmark dashboard](https://devtools-frontend-perf.corp.goog/e/?queries=test%3DBootPerf)
-* [Peak of the GCS bucket where data is stored](https://pantheon.corp.google.com/storage/browser/devtools-frontend-perf/ingest/2024/10/08/08/client.devtools-frontend.integration/Stand-alone%20Linux/performance-tests?pageState=(%22StorageObjectListTable%22:(%22f%22:%22%255B%255D%22))&e=-13802955&mods=component_inspector&project=skia-public) (you need the "Storage Object Viewer" role for your account. You can ask the [Chrome Browser Infra team](https://g3doc.corp.google.com/company/teams/chrome/ops/engprod/browser_infra/index.md?cl=head) to grant you access).
+## Quick links (copy and paste)
+* Performance panel "TraceLoad" benchmark dashboard: https://devtools-frontend-perf.corp.goog/e/?queries=stats%3Dmean%26test%3DTraceLoad
+* DevTools "BootPerf" benchmark dashboard: https://devtools-frontend-perf.corp.goog/e/?queries=test%3DBootPerf)
+* Peak of the GCS bucket where data is stored: https://pantheon.corp.google.com/storage/browser/devtools-frontend-perf/ingest/2024/10/08/08/client.devtools-frontend.integration/Stand-alone%20Linux/performance-tests?pageState=(%22StorageObjectListTable%22:(%22f%22:%22%255B%255D%22))&e=-13802955&mods=component_inspector&project=skia-public) (you need the "Storage Object Viewer" role for your account. You can ask the [Chrome Browser Infra team](https://g3doc.corp.google.com/company/teams/chrome/ops/engprod/browser_infra/index.md?cl=head) to grant you access).
 

test/perf/README.md

@@ -34,21 +34,20 @@ async function timeFixture(fixture: string): Promise<number> {
 
 describe('Performance panel trace load performance', () => {
   const allTestValues: {name: string, values: number[]}[] = [];
-
   // Slow test
-  describe.skip('[crbug.com/383713603]: Total trace load time', () => {
+  describe.skip('[crbug.com/383713603]: Large CPU profile load benchmark', () => {
     beforeEach(async () => {
       // Reload devtools to get a fresh version of the panel on each
       // run and prevent a skew due to caching, etc.
       await reloadDevTools();
     });
     const RUNS = 10;
     const testValues = {
-      name: 'TraceLoad',
+      name: 'LargeCPULoad',
       values: [] as number[],
     };
     for (let run = 1; run <= RUNS; run++) {
-      it(`run ${run}/${RUNS}`, async function() {
+      it('run large cpu profile benchmark', async function() {
         this.timeout(20_000);
         const duration = await timeFixture('large-profile.cpuprofile');
         // Ensure only 2 decimal places.
@@ -61,6 +60,31 @@ describe('Performance panel trace load performance', () => {
     });
   });
 
+  describe('Large DOM trace load benchmark', () => {
+    beforeEach(async () => {
+      // Reload devtools to get a fresh version of the panel on each
+      // run and prevent a skew due to caching, etc.
+      await reloadDevTools();
+    });
+    const RUNS = 10;
+    const testValues = {
+      name: 'LargeDOMTraceLoad',
+      values: [] as number[],
+    };
+    for (let run = 1; run <= RUNS; run++) {
+      it('run large dom trace load benchmark', async function() {
+        this.timeout(8_000);
+        const duration = await timeFixture('dom-size-long.json');
+        // Ensure only 2 decimal places.
+        const timeTaken = Number(duration.toFixed(2));
+        testValues.values.push(timeTaken);
+      });
+    }
+    after(() => {
+      allTestValues.push(testValues);
+    });
+  });
+
   after(async () => {
     // Calculate statistics for each benchmark.
     for (const testValues of allTestValues) {
@@ -96,10 +120,10 @@ describe('Performance panel trace load performance', () => {
       addBenchmarkResult(benchmark);
       /* eslint-disable no-console */
       console.log(`Benchmark name: ${testValues.name}`);
-      console.log(`Mean boot time: ${meanMeasure}ms`);
-      console.log(`50th percentile boot time: ${percentile50}ms`);
-      console.log(`90th percentile boot time: ${percentile90}ms`);
-      console.log(`99th percentile boot time: ${percentile99}ms`);
+      console.log(`Mean time: ${meanMeasure}ms`);
+      console.log(`50th percentile time: ${percentile50}ms`);
+      console.log(`90th percentile time: ${percentile90}ms`);
+      console.log(`99th percentile time: ${percentile99}ms`);
       /* eslint-enable no-console */
     }
   });