From 06d04002fd1ad841b069bcc8094db6f190f3cb48 Mon Sep 17 00:00:00 2001 From: Mike Giambalvo Date: Thu, 24 May 2018 13:58:00 -0700 Subject: [PATCH] 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 --- .../src/webdriver/chrome_driver_extension.ts | 17 +++++++++++--- .../webdriver/chrome_driver_extension_spec.ts | 22 ++++++++++--------- 2 files changed, 26 insertions(+), 13 deletions(-) diff --git a/packages/benchpress/src/webdriver/chrome_driver_extension.ts b/packages/benchpress/src/webdriver/chrome_driver_extension.ts index c255f2ff33..066958afd0 100644 --- a/packages/benchpress/src/webdriver/chrome_driver_extension.ts +++ b/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 { - 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}; diff --git a/packages/benchpress/test/webdriver/chrome_driver_extension_spec.ts b/packages/benchpress/test/webdriver/chrome_driver_extension_spec.ts index 640143b541..dbe3f589b9 100644 --- a/packages/benchpress/test/webdriver/chrome_driver_extension_spec.ts +++ b/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( - [['logs', 'performance'], ['executeScript', `console.time('someName');`]]); + expect(log).toEqual([ + ['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( - [['executeScript', `console.timeEnd('name1');console.time('name2');`]]); + expect(log).toEqual([[ + 'executeScript', `performance.mark('name1-bpend');performance.mark('name2-bpstart');` + ]]); async.done(); }); }));