Support console timestamp measurements with performance.now() timestamps

Relevant Chromium CL: https://chromium-review.googlesource.com/c/chromium/src/+/6311629

Bug: 399851200
Change-Id: I082d27bf0b791a439748f5c100bb791c1588145e
Reviewed-on: https://chromium-review.googlesource.com/c/devtools/devtools-frontend/+/6308724
Reviewed-by: Nancy Li <[email protected]>
Commit-Queue: Nancy Li <[email protected]>
Auto-Submit: Andres Olivares <[email protected]>

Author: and-oli

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

@@ -14,8 +14,8 @@ export interface PerformanceAPIExtensionTestData {
 
 export interface ConsoleAPIExtensionTestData {
   name: string;
-  start?: string;
-  end?: string;
+  start?: string|number;
+  end?: string|number;
   track?: string;
   trackGroup?: string;
   color?: string;
@@ -59,13 +59,13 @@ function makeTimingEventWithPerformanceExtensionData(
 function makeTimingEventWithConsoleExtensionData({name, ts, start, end, track, trackGroup, color}:
                                                      ConsoleAPIExtensionTestData): Trace.Types.Events.ConsoleTimeStamp {
   return {
-    cat: 'disabled-by-default-v8.inspector',
+    cat: 'devtools.timeline',
     pid: Trace.Types.Events.ProcessID(2017),
     tid: Trace.Types.Events.ThreadID(259),
     name: Trace.Types.Events.Name.CONSOLE_TIME_STAMP,
     args: {
       data: {
-        name,
+        message: name,
         start,
         end,
         track,
@@ -74,7 +74,7 @@ function makeTimingEventWithConsoleExtensionData({name, ts, start, end, track, t
       }
     },
     ts: Trace.Types.Timing.Micro(ts),
-    ph: Trace.Types.Events.Phase.COMPLETE,
+    ph: Trace.Types.Events.Phase.INSTANT,
 
   };
 }
@@ -441,7 +441,7 @@ describe('ExtensionTraceDataHandler', function() {
         assert.deepEqual(Object.keys(fourthTrackData.entriesByTrack), ['Ungrouped Track 2']);
         assert.deepEqual(Object.values(fourthTrackData.entriesByTrack).map(entries => entries.length), [2]);
       });
-      it('calculates self time sub track by sub track', async function() {
+      it('calculates self time sub track by sub track for events added with the performance API', async function() {
         const extensionDevToolsObjects: PerformanceAPIExtensionTestData[] = [
           // Track group 1
           {
@@ -622,6 +622,20 @@ describe('ExtensionTraceDataHandler', function() {
           end: 'Mark 4',
           ts: 300,
         },
+        // numeric start and end
+        {
+          track: 'Custom track 1',
+          name: 'Measure 6',
+          start: 300,
+          end: 400,
+          ts: 300,
+        },
+        {
+          track: 'Custom track 1',
+          name: 'Measure 7',
+          start: 350,
+          ts: 400,
+        }
       ];
       return createTraceExtensionDataFromConsoleAPITestInput(extensionData);
     }
@@ -632,23 +646,26 @@ describe('ExtensionTraceDataHandler', function() {
       });
       it('parses track data correctly', async () => {
         assert.lengthOf(extensionHandlerOutput.extensionTrackData, 3);
-
-        assert.strictEqual(extensionHandlerOutput.extensionTrackData[0].name, 'Custom track 3');
-        assert.lengthOf(extensionHandlerOutput.extensionTrackData[0].entriesByTrack['Custom track 3'], 2);
-        assert.strictEqual(
-            extensionHandlerOutput.extensionTrackData[0].entriesByTrack['Custom track 3'][0].name, 'Measure 3');
-        assert.strictEqual(
-            extensionHandlerOutput.extensionTrackData[0].entriesByTrack['Custom track 3'][1].name, 'Measure 4');
-
-        assert.strictEqual(extensionHandlerOutput.extensionTrackData[1].name, 'Custom track 1');
-        assert.lengthOf(extensionHandlerOutput.extensionTrackData[1].entriesByTrack['Custom track 1'], 1);
-        assert.strictEqual(
-            extensionHandlerOutput.extensionTrackData[1].entriesByTrack['Custom track 1'][0].name, 'Measure 1');
-
-        assert.strictEqual(extensionHandlerOutput.extensionTrackData[2].name, 'Custom track 2');
-        assert.lengthOf(extensionHandlerOutput.extensionTrackData[2].entriesByTrack['Custom track 2'], 1);
-        assert.strictEqual(
-            extensionHandlerOutput.extensionTrackData[2].entriesByTrack['Custom track 2'][0].name, 'Measure 2');
+        const expectedData: Record<string, Array<{name: string, ts: number, dur: number}>> = {
+          'Custom track 3': [{name: 'Measure 3', ts: 100, dur: 200}, {name: 'Measure 4', ts: 100, dur: 100}],
+          'Custom track 1': [
+            {name: 'Measure 1', ts: 100, dur: 100}, {name: 'Measure 6', ts: 300, dur: 100},
+            {name: 'Measure 7', ts: 350, dur: 50}
+          ],
+          'Custom track 2': [{name: 'Measure 2', ts: 100, dur: 100}]
+        };
+        for (let i = 0; i < extensionHandlerOutput.extensionTrackData.length; i++) {
+          const track = extensionHandlerOutput.extensionTrackData[i];
+          assert.strictEqual(track.name, Object.keys(expectedData)[i]);
+          const actualTrackData = track.entriesByTrack[track.name];
+          const expectedTrackData = expectedData[track.name];
+          for (let j = 0; j < actualTrackData.length; j++) {
+            const {name, ts, dur} = actualTrackData[j];
+            assert.strictEqual(name, expectedTrackData[j].name);
+            assert.strictEqual(ts, expectedTrackData[j].ts);
+            assert.strictEqual(dur, expectedTrackData[j].dur);
+          }
+        }
       });
       it('parses synthetic console timings for the timings track', async () => {
         assert.lengthOf(extensionHandlerOutput.syntheticConsoleEntriesForTimingsTrack, 1);
@@ -735,7 +752,7 @@ describe('ExtensionTraceDataHandler', function() {
         assert.deepEqual(Object.keys(fourthTrackData.entriesByTrack), ['Ungrouped Track 2']);
         assert.deepEqual(Object.values(fourthTrackData.entriesByTrack).map(entries => entries.length), [2]);
       });
-      it('calculates self time sub track by sub track', async function() {
+      it('calculates self time sub track by sub track for events added with the console API', async function() {
         const extensionDevToolsObjects: ConsoleAPIExtensionTestData[] = [
           // Track group 1
           {
@@ -792,6 +809,13 @@ describe('ExtensionTraceDataHandler', function() {
             start: 'F',
             ts: 80,
           },
+          {
+            trackGroup: 'Group 1',
+            track: 'Track 1',
+            name: 'Measurement 5',
+            start: 75,
+            ts: 80,
+          },
           {
             name: 'G',
             ts: 0,
@@ -848,7 +872,8 @@ describe('ExtensionTraceDataHandler', function() {
           {name: 'Measurement 1', selfTime: 40},
           {name: 'Measurement 2', selfTime: 20},
           {name: 'Measurement 3', selfTime: 30},
-          {name: 'Measurement 4', selfTime: 10},
+          {name: 'Measurement 4', selfTime: 5},
+          {name: 'Measurement 5', selfTime: 5},
         ]);
 
         const testDataTrack2 = trackGroupData.entriesByTrack['Track 2'].map(entry => {

front_end/models/trace/handlers/ExtensionTraceDataHandler.ts

@@ -85,22 +85,27 @@ export function extractConsoleAPIExtensionEntries(): void {
     if (!currentTimeStamp.args.data) {
       continue;
     }
-    const timeStampName = String(currentTimeStamp.args.data.name);
+    const timeStampName = String(currentTimeStamp.args.data.name ?? currentTimeStamp.args.data.message);
     timeStampByName.set(timeStampName, currentTimeStamp);
     const extensionData = extensionDataInConsoleTimeStamp(currentTimeStamp);
-    const startName = currentTimeStamp.args.data.start;
-    const endName = currentTimeStamp.args.data.end;
-    if (!extensionData && !startName && !endName) {
+    const start = currentTimeStamp.args.data.start;
+    const end = currentTimeStamp.args.data.end;
+    if (!extensionData && !start && !end) {
       continue;
     }
-    const startTimeStamp = startName ? timeStampByName.get(String(startName)) : undefined;
-    const endTimeStamp = endName ? timeStampByName.get(String(endName)) : undefined;
-    if (endTimeStamp && !startTimeStamp) {
+    // If the start or end is a number, it's assumed to be a timestamp
+    // from the tracing clock, so we use that directly, otherwise we
+    // assume it's the label of a previous console timestamp, in which
+    // case we use its corresponding timestamp.
+    const startTimeStamp =
+        typeof start === 'number' ? Types.Timing.Micro(start) : timeStampByName.get(String(start))?.ts;
+    const endTimeStamp = typeof end === 'number' ? Types.Timing.Micro(end) : timeStampByName.get(String(end))?.ts;
+    if (endTimeStamp !== undefined && startTimeStamp === undefined) {
       // Invalid data
       continue;
     }
-    const entryStartTime = startTimeStamp?.ts ?? currentTimeStamp.ts;
-    const entryEndTime = endTimeStamp?.ts ?? currentTimeStamp.ts;
+    const entryStartTime = startTimeStamp ?? currentTimeStamp.ts;
+    const entryEndTime = endTimeStamp ?? currentTimeStamp.ts;
     if (extensionData) {
       const unregisteredExtensionEntry: Omit<Types.Extensions.SyntheticExtensionTrackEntry, '_tag'> = {
         ...currentTimeStamp,
@@ -110,6 +115,7 @@ export function extractConsoleAPIExtensionEntries(): void {
         rawSourceEvent: currentTimeStamp,
         dur: Types.Timing.Micro(entryEndTime - entryStartTime),
         ts: entryStartTime,
+        ph: Types.Events.Phase.COMPLETE,
       };
       const extensionEntry =
           Helpers.SyntheticEvents.SyntheticEventsManager.getActiveManager()

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

@@ -177,9 +177,9 @@ describeWithEnvironment('UserTimingsHandler', function() {
     describe('console.timestamp events parsing', function() {
       it('parses console.timestamp events correctly', async function() {
         assert.lengthOf(timingsData.timestampEvents, 3);
-        assert.strictEqual(timingsData.timestampEvents[0].args.data?.name, 'a timestamp');
-        assert.strictEqual(timingsData.timestampEvents[1].args.data?.name, 'another timestamp');
-        assert.strictEqual(timingsData.timestampEvents[2].args.data?.name, 'yet another timestamp');
+        assert.strictEqual(timingsData.timestampEvents[0].args.data?.message, 'a timestamp');
+        assert.strictEqual(timingsData.timestampEvents[1].args.data?.message, 'another timestamp');
+        assert.strictEqual(timingsData.timestampEvents[2].args.data?.message, 'yet another timestamp');
       });
     });
   });

front_end/models/trace/helpers/SamplesIntegrator.test.ts

@@ -5,7 +5,7 @@
 import type * as Protocol from '../../../generated/protocol.js';
 import * as CPUProfile from '../../../models/cpu_profile/cpu_profile.js';
 import {describeWithEnvironment} from '../../../testing/EnvironmentHelpers.js';
-import {makeCompleteEvent} from '../../../testing/TraceHelpers.js';
+import {makeCompleteEvent, makeInstantEvent} from '../../../testing/TraceHelpers.js';
 import {TraceLoader} from '../../../testing/TraceLoader.js';
 import * as Trace from '../trace.js';
 
@@ -272,8 +272,8 @@ describeWithEnvironment('SamplesIntegrator', function() {
       const evaluateScript = makeCompleteEvent(Trace.Types.Events.Name.EVALUATE_SCRIPT, 0, 500);
       const v8Run = makeCompleteEvent('v8.run', 10, 490);
       const consoleTimeStamp =
-          makeCompleteEvent(Trace.Types.Events.Name.CONSOLE_TIME_STAMP, 350, 10) as Trace.Types.Events.ConsoleTimeStamp;
-      consoleTimeStamp.args = {data: {name: 'A timestamp', sampleTraceId: traceId}};
+          makeInstantEvent(Trace.Types.Events.Name.CONSOLE_TIME_STAMP, 350) as Trace.Types.Events.ConsoleTimeStamp;
+      consoleTimeStamp.args = {data: {message: 'A timestamp', sampleTraceId: traceId}};
       const traceEvents = [evaluateScript, v8Run, consoleTimeStamp];
       const constructedCalls = integrator.buildProfileCalls(traceEvents);
       assert.lengthOf(constructedCalls, 4);

front_end/models/trace/helpers/SamplesIntegrator.ts

@@ -126,7 +126,7 @@ export class SamplesIntegrator {
       // Because instant trace events have no duration, they don't provide
       // useful information for possible changes in the duration of calls
       // in the JS stack.
-      if (event.ph === Types.Events.Phase.INSTANT) {
+      if (event.ph === Types.Events.Phase.INSTANT && !extractSampleTraceId(event)) {
         continue;
       }
       if (stack.length === 0) {

front_end/models/trace/types/TraceEvents.ts

@@ -1424,14 +1424,15 @@ export interface ConsoleTimeEnd extends PairableAsyncEnd {
 export type ConsoleTime = ConsoleTimeBegin|ConsoleTimeEnd;
 
 export interface ConsoleTimeStamp extends Event {
-  cat: 'disabled-by-default-v8.inspector';
+  cat: 'devtools.timeline';
   name: Name.CONSOLE_TIME_STAMP;
-  ph: Phase.COMPLETE;
+  ph: Phase.INSTANT;
   args: Args&{
     data?: ArgsData & {
       // The console.timeStamp allows to pass integers as values as well
       // as strings
-      name: string | number,
+      message: string,
+      name?: string|number,
       start?: string|number,
       end?: string|number,
       track?: string|number,
@@ -2323,7 +2324,7 @@ export function isConsoleTime(event: Event): event is ConsoleTime {
 }
 
 export function isConsoleTimeStamp(event: Event): event is ConsoleTimeStamp {
-  return event.ph === Phase.COMPLETE && event.name === Name.CONSOLE_TIME_STAMP;
+  return event.ph === Phase.INSTANT && event.name === Name.CONSOLE_TIME_STAMP;
 }
 
 export function isUserTimingMeasure(event: Event): event is UserTimingMeasure {
@@ -2988,7 +2989,7 @@ export const enum Name {
   CONSOLE_TIME = 'ConsoleTime',
   USER_TIMING = 'UserTiming',
   INTERACTIVE_TIME = 'InteractiveTime',
-  CONSOLE_TIME_STAMP = 'V8Console::TimeStamp',
+  CONSOLE_TIME_STAMP = 'TimeStamp',
 
   /* Frames */
   BEGIN_FRAME = 'BeginFrame',

front_end/panels/timeline/TimelineUIUtils.ts

@@ -661,7 +661,7 @@ export class TimelineUIUtils {
       return title;
     }
     if (Trace.Types.Events.isConsoleTimeStamp(event) && event.args.data) {
-      return i18nString(UIStrings.sS, {PH1: title, PH2: event.args.data.name});
+      return i18nString(UIStrings.sS, {PH1: title, PH2: event.args.data.name ?? event.args.data.message});
     }
     if (Trace.Types.Events.isAnimation(event) && event.args.data.name) {
       return i18nString(UIStrings.sS, {PH1: title, PH2: event.args.data.name});

front_end/panels/timeline/TimingsTrackAppender.ts

@@ -244,7 +244,7 @@ export class TimingsTrackAppender implements TrackAppender {
       }
     }
     if (Trace.Types.Events.isConsoleTimeStamp(event)) {
-      return `TimeStamp: ${event.args.data?.name ?? '(name unknown)'}`;
+      return `TimeStamp: ${event.args.data?.message ?? '(name unknown)'}`;
     }
     if (Trace.Types.Events.isPerformanceMark(event)) {
       return `[mark]: ${event.name}`;