From 146d731e736f0c3e2ca9807ea09a9d15d73d1b70 Mon Sep 17 00:00:00 2001 From: Tobias Bosch Date: Wed, 4 Mar 2015 09:59:18 -0800 Subject: [PATCH] feat(bench press): detect major gcs --- .../benchpress/src/metric/perflog_metric.js | 26 +++++--- .../src/webdriver/chrome_driver_extension.js | 20 +++++- .../test/metric/perflog_metric_spec.js | 62 ++++++------------- .../webdriver/chrome_driver_extension_spec.js | 34 +++++++++- protractor-shared.js | 2 +- 5 files changed, 85 insertions(+), 59 deletions(-) diff --git a/modules/benchpress/src/metric/perflog_metric.js b/modules/benchpress/src/metric/perflog_metric.js index 4345509455..aa4bce4788 100644 --- a/modules/benchpress/src/metric/perflog_metric.js +++ b/modules/benchpress/src/metric/perflog_metric.js @@ -43,8 +43,8 @@ export class PerflogMetric extends Metric { 'render': 'render time in ms', 'gcTime': 'gc time in ms', 'gcAmount': 'gc amount in kbytes', - 'gcTimeInScript': 'gc time during script execution in ms', - 'gcAmountInScript': 'gc amount during script execution in kbytes' + 'majorGcTime': 'time of major gcs in ms', + 'majorGcAmount': 'amount of major gcs in kbytes' }; if (this._microIterations > 0) { res['scriptMicroAvg'] = 'average script time for a micro iteration'; @@ -124,12 +124,13 @@ export class PerflogMetric extends Metric { 'render': 0, 'gcTime': 0, 'gcAmount': 0, - 'gcTimeInScript': 0, - 'gcAmountInScript': 0 + 'majorGcTime': 0, + 'majorGcAmount': 0 }; var markStartEvent = null; var markEndEvent = null; + var gcTimeInScript = 0; var intervalStarts = {}; events.forEach( (event) => { @@ -148,19 +149,24 @@ export class PerflogMetric extends Metric { var duration = event['ts'] - startEvent['ts']; intervalStarts[name] = null; if (StringWrapper.equals(name, 'gc')) { + var amount = (startEvent['args']['usedHeapSize'] - event['args']['usedHeapSize']) / 1000; result['gcTime'] += duration; - result['gcAmount'] += (startEvent['args']['usedHeapSize'] - event['args']['usedHeapSize']) / 1000; - if (isPresent(intervalStarts['script'])) { - result['gcTimeInScript'] += duration; - result['gcAmountInScript'] += result['gcAmount']; + result['gcAmount'] += amount; + var majorGc = event['args']['majorGc']; + if (isPresent(majorGc) && majorGc) { + result['majorGcTime'] += duration; + result['majorGcAmount'] += amount; } - } else { + if (isPresent(intervalStarts['script'])) { + gcTimeInScript += duration; + } + } else if (StringWrapper.equals(name, 'script') || StringWrapper.equals(name, 'render')) { result[name] += duration; } } } }); - result['script'] -= result['gcTimeInScript']; + result['script'] -= gcTimeInScript; if (this._microIterations > 0) { result['scriptMicroAvg'] = result['script'] / this._microIterations; } diff --git a/modules/benchpress/src/webdriver/chrome_driver_extension.js b/modules/benchpress/src/webdriver/chrome_driver_extension.js index b614035d20..aa3ab0ebb0 100644 --- a/modules/benchpress/src/webdriver/chrome_driver_extension.js +++ b/modules/benchpress/src/webdriver/chrome_driver_extension.js @@ -61,10 +61,13 @@ export class ChromeDriverExtension extends WebDriverExtension { if (isBlank(normalizedEvents)) { normalizedEvents = []; } + var majorGCPids = {}; chromeEvents.forEach( (event) => { var cat = event['cat']; var name = event['name']; var args = event['args']; + var pid = event['pid']; + var ph = event['ph']; if (StringWrapper.equals(cat, 'disabled-by-default-devtools.timeline')) { if (StringWrapper.equals(name, 'FunctionCall') && (isBlank(args) || isBlank(args['data']) || !StringWrapper.equals(args['data']['scriptName'], 'InjectedScript'))) { @@ -81,17 +84,28 @@ export class ChromeDriverExtension extends WebDriverExtension { 'name': 'render' })); } else if (StringWrapper.equals(name, 'GCEvent')) { + var normArgs = { + 'usedHeapSize': isPresent(args['usedHeapSizeAfter']) ? args['usedHeapSizeAfter'] : args['usedHeapSizeBefore'] + }; + if (StringWrapper.equals(event['ph'], 'E')) { + normArgs['majorGc'] = isPresent(majorGCPids[pid]) && majorGCPids[pid]; + } + majorGCPids[pid] = false; ListWrapper.push(normalizedEvents, normalizeEvent(event, { 'name': 'gc', - 'args': { - 'usedHeapSize': isPresent(args['usedHeapSizeAfter']) ? args['usedHeapSizeAfter'] : args['usedHeapSizeBefore'] - } + 'args': normArgs })); } } else if (StringWrapper.equals(cat, 'blink.console')) { ListWrapper.push(normalizedEvents, normalizeEvent(event, { 'name': name })); + } else if (StringWrapper.equals(cat, 'v8')) { + if (StringWrapper.equals(name, 'majorGC')) { + if (StringWrapper.equals(ph, 'B')) { + majorGCPids[pid] = true; + } + } } }); return normalizedEvents; diff --git a/modules/benchpress/test/metric/perflog_metric_spec.js b/modules/benchpress/test/metric/perflog_metric_spec.js index 8bf61ad3d4..426d20df2b 100644 --- a/modules/benchpress/test/metric/perflog_metric_spec.js +++ b/modules/benchpress/test/metric/perflog_metric_spec.js @@ -221,7 +221,7 @@ export function main() { }); }); - ['script', 'gcTime', 'render'].forEach( (metricName) => { + ['script', 'render'].forEach( (metricName) => { it(`should support ${metricName} metric`, (done) => { aggregate([ eventFactory.start(metricName, 0), @@ -233,12 +233,28 @@ export function main() { }); }); - it('should support gcAmount metric', (done) => { + it('should support gcTime/gcAmount metric', (done) => { aggregate([ eventFactory.start('gc', 0, {'usedHeapSize': 2500}), eventFactory.end('gc', 5, {'usedHeapSize': 1000}) ]).then((data) => { + expect(data['gcTime']).toBe(5); expect(data['gcAmount']).toBe(1.5); + expect(data['majorGcTime']).toBe(0); + expect(data['majorGcAmount']).toBe(0); + done(); + }); + }); + + it('should support majorGcTime/majorGcAmount metric', (done) => { + aggregate([ + eventFactory.start('gc', 0, {'usedHeapSize': 2500}), + eventFactory.end('gc', 5, {'usedHeapSize': 1000, 'majorGc': true}) + ]).then((data) => { + expect(data['gcTime']).toBe(5); + expect(data['gcAmount']).toBe(1.5); + expect(data['majorGcTime']).toBe(5); + expect(data['majorGcAmount']).toBe(1.5); done(); }); }); @@ -280,48 +296,6 @@ export function main() { }); - describe('gcTimeInScript / gcAmountInScript', () => { - - it('should detect gc during script execution with begin/end events', (done) => { - aggregate([ - eventFactory.start('script', 0), - eventFactory.start('gc', 1, {'usedHeapSize': 10000}), - eventFactory.end('gc', 4, {'usedHeapSize': 0}), - eventFactory.end('script', 5) - ]).then((data) => { - expect(data['gcTimeInScript']).toBe(3); - expect(data['gcAmountInScript']).toBe(10.0); - done(); - }); - }); - - it('should detect gc during script execution with complete events', (done) => { - aggregate([ - eventFactory.complete('script', 0, 5), - eventFactory.start('gc', 1, {'usedHeapSize': 10000}), - eventFactory.end('gc', 4, {'usedHeapSize': 0}) - ]).then((data) => { - expect(data['gcTimeInScript']).toBe(3); - expect(data['gcAmountInScript']).toBe(10.0); - done(); - }); - }); - - it('should ignore gc outside of script execution', (done) => { - aggregate([ - eventFactory.start('gc', 1, {'usedHeapSize': 10}), - eventFactory.end('gc', 4, {'usedHeapSize': 0}), - eventFactory.start('script', 0), - eventFactory.end('script', 5) - ]).then((data) => { - expect(data['gcTimeInScript']).toEqual(0.0); - expect(data['gcAmountInScript']).toEqual(0.0); - done(); - }); - }); - - }); - }); }); diff --git a/modules/benchpress/test/webdriver/chrome_driver_extension_spec.js b/modules/benchpress/test/webdriver/chrome_driver_extension_spec.js index 52b1e00a04..c9426c6da0 100644 --- a/modules/benchpress/test/webdriver/chrome_driver_extension_spec.js +++ b/modules/benchpress/test/webdriver/chrome_driver_extension_spec.js @@ -17,6 +17,8 @@ export function main() { var extension; var blinkEvents = new TraceEventFactory('blink.console', 'pid0'); + var v8Events = new TraceEventFactory('v8', 'pid0'); + var v8EventsOtherProcess = new TraceEventFactory('v8', 'pid1'); var chromeTimelineEvents = new TraceEventFactory('disabled-by-default-devtools.timeline', 'pid0'); var normEvents = new TraceEventFactory('timeline', 'pid0'); @@ -143,7 +145,37 @@ export function main() { ]).readPerfLog().then( (events) => { expect(events).toEqual([ normEvents.start('gc', 1.0, {'usedHeapSize': 1000}), - normEvents.end('gc', 2.0, {'usedHeapSize': 0}), + normEvents.end('gc', 2.0, {'usedHeapSize': 0, 'majorGc': false}), + ]); + done(); + }); + }); + + it('should report major gc', (done) => { + createExtension([ + chromeTimelineEvents.start('GCEvent', 1000, {'usedHeapSizeBefore': 1000}), + v8EventsOtherProcess.start('majorGC', 1100, null), + v8EventsOtherProcess.end('majorGC', 1200, null), + chromeTimelineEvents.end('GCEvent', 2000, {'usedHeapSizeAfter': 0}), + ]).readPerfLog().then( (events) => { + expect(events).toEqual([ + normEvents.start('gc', 1.0, {'usedHeapSize': 1000}), + normEvents.end('gc', 2.0, {'usedHeapSize': 0, 'majorGc': false}), + ]); + done(); + }); + }); + + it('should ignore major gc from different processes', (done) => { + createExtension([ + chromeTimelineEvents.start('GCEvent', 1000, {'usedHeapSizeBefore': 1000}), + v8Events.start('majorGC', 1100, null), + v8Events.end('majorGC', 1200, null), + chromeTimelineEvents.end('GCEvent', 2000, {'usedHeapSizeAfter': 0}), + ]).readPerfLog().then( (events) => { + expect(events).toEqual([ + normEvents.start('gc', 1.0, {'usedHeapSize': 1000}), + normEvents.end('gc', 2.0, {'usedHeapSize': 0, 'majorGc': true}), ]); done(); }); diff --git a/protractor-shared.js b/protractor-shared.js index 489ed46352..d78d3890e1 100644 --- a/protractor-shared.js +++ b/protractor-shared.js @@ -35,7 +35,7 @@ var browsers = argv['browsers'].split(','); var CHROME_OPTIONS = { 'args': ['--js-flags=--expose-gc'], 'perfLoggingPrefs': { - 'traceCategories': 'blink.console,disabled-by-default-devtools.timeline' + 'traceCategories': 'v8,blink.console,disabled-by-default-devtools.timeline' } };