fix(benchpress): Use performance.mark() instead of console.time() (#24114)

Previously, benchpress would use `console.time()` and
`console.timeEnd()` to measure the start and end of a test in the
performance log. This used to work over navigations - if you called
`console.time(id)` then navigated to a different page, calling
`console.timeEnd(id)` would still insert an event in the performance
log.

As of Chrome 65, this is no longer the case. `console.timeEnd(id)` will
simply not insert an event in the performance log unless
`console.time(id)` was called on the same page. Likewise, using
`performance.measure()` does not work if the starting mark was on a
different page.

This simple workaround uses `performance.mark()` to insert events in the
performance log at the start and end of the test. Benchpress looks for
'-bpstart' and '-bpend' in the name of the performance mark, and
normalizes that to the start and end events expected by PerflogMetric

PR Close #24114

packages/benchpress/src/webdriver/chrome_driver_extension.ts

@@ -58,13 +58,13 @@ export class ChromeDriverExtension extends WebDriverExtension {
       // so that the chrome buffer does not fill up.
       await this._driver.logs('performance');
     }
-    return this._driver.executeScript(`console.time('${name}');`);
+    return this._driver.executeScript(`performance.mark('${name}-bpstart');`);
   }
 
   timeEnd(name: string, restartName: string|null = null): Promise<any> {
-    let script = `console.timeEnd('${name}');`;
+    let script = `performance.mark('${name}-bpend');`;
     if (restartName) {
-      script += `console.time('${restartName}');`;
+      script += `performance.mark('${restartName}-bpstart');`;
     }
     return this._driver.executeScript(script);
   }
@@ -109,6 +109,8 @@ export class ChromeDriverExtension extends WebDriverExtension {
     const args = event['args'];
     if (this._isEvent(categories, name, ['blink.console'])) {
       return normalizeEvent(event, {'name': name});
+    } else if (this._isEvent(categories, name, ['blink.user_timing'])) {
+      return normalizeEvent(event, {'name': name});
     } else if (this._isEvent(
                    categories, name, ['benchmark'],
                    'BenchmarkInstrumentation::ImplThreadRenderingStats')) {
@@ -201,6 +203,15 @@ function normalizeEvent(chromeEvent: {[key: string]: any}, data: PerfLogEvent):
   } else if (ph === 'R') {
     // mark events from navigation timing
     ph = 'I';
+    // Chrome 65+ doesn't allow user timing measurements across page loads.
+    // Instead, we use performance marks with special names.
+    if (chromeEvent['name'].match(/-bpstart/)) {
+      data['name'] = chromeEvent['name'].slice(0, -8);
+      ph = 'B';
+    } else if (chromeEvent['name'].match(/-bpend$/)) {
+      data['name'] = chromeEvent['name'].slice(0, -6);
+      ph = 'E';
+    }
   }
   const result: {[key: string]: any} =
       {'pid': chromeEvent['pid'], 'ph': ph, 'cat': 'timeline', 'ts': chromeEvent['ts'] / 1000};

packages/benchpress/test/webdriver/chrome_driver_extension_spec.ts

@@ -61,16 +61,17 @@ import {TraceEventFactory} from '../trace_event_factory';
          });
        }));
 
-    it('should clear the perf logs and mark the timeline via console.time() on the first call',
+    it('should clear the perf logs and mark the timeline via performance.mark() on the first call',
        inject([AsyncTestCompleter], (async: AsyncTestCompleter) => {
          createExtension().timeBegin('someName').then(() => {
-           expect(log).toEqual(
+           expect(log).toEqual([
-               [['logs', 'performance'], ['executeScript', `console.time('someName');`]]);
+             ['logs', 'performance'], ['executeScript', `performance.mark('someName-bpstart');`]
+           ]);
            async.done();
          });
        }));
 
-    it('should mark the timeline via console.time() on the second call',
+    it('should mark the timeline via performance.mark() on the second call',
        inject([AsyncTestCompleter], (async: AsyncTestCompleter) => {
          const ext = createExtension();
          ext.timeBegin('someName')
@@ -79,24 +80,25 @@ import {TraceEventFactory} from '../trace_event_factory';
                ext.timeBegin('someName');
              })
              .then(() => {
-               expect(log).toEqual([['executeScript', `console.time('someName');`]]);
+               expect(log).toEqual([['executeScript', `performance.mark('someName-bpstart');`]]);
                async.done();
              });
        }));
 
-    it('should mark the timeline via console.timeEnd()',
+    it('should mark the timeline via performance.mark()',
        inject([AsyncTestCompleter], (async: AsyncTestCompleter) => {
          createExtension().timeEnd('someName', null).then((_) => {
-           expect(log).toEqual([['executeScript', `console.timeEnd('someName');`]]);
+           expect(log).toEqual([['executeScript', `performance.mark('someName-bpend');`]]);
            async.done();
          });
        }));
 
-    it('should mark the timeline via console.time() and console.timeEnd()',
+    it('should mark the timeline via performance.mark() with start and end of a test',
        inject([AsyncTestCompleter], (async: AsyncTestCompleter) => {
          createExtension().timeEnd('name1', 'name2').then((_) => {
-           expect(log).toEqual(
+           expect(log).toEqual([[
-               [['executeScript', `console.timeEnd('name1');console.time('name2');`]]);
+             'executeScript', `performance.mark('name1-bpend');performance.mark('name2-bpstart');`
+           ]]);
            async.done();
          });
        }));