From 7d5e06ef6497d4f65a7e844f031573f32b08cd28 Mon Sep 17 00:00:00 2001 From: Brendan Kenny Date: Wed, 24 May 2017 00:06:05 -0700 Subject: [PATCH 1/2] add streaming trace writer in saveAssets --- lighthouse-core/gather/driver.js | 2 +- lighthouse-core/lib/asset-saver.js | 86 +++++++++++++-- lighthouse-core/test/lib/asset-saver-test.js | 108 ++++++++++++++++--- 3 files changed, 171 insertions(+), 25 deletions(-) diff --git a/lighthouse-core/gather/driver.js b/lighthouse-core/gather/driver.js index 5f3e380324d3..c7ef7902758a 100644 --- a/lighthouse-core/gather/driver.js +++ b/lighthouse-core/gather/driver.js @@ -25,7 +25,7 @@ const _uniq = arr => Array.from(new Set(arr)); class Driver { static get MAX_WAIT_FOR_FULLY_LOADED() { - return 30 * 1000; + return 60 * 1000; } /** diff --git a/lighthouse-core/lib/asset-saver.js b/lighthouse-core/lib/asset-saver.js index 6fe6ef920182..14aaa64d8de8 100644 --- a/lighthouse-core/lib/asset-saver.js +++ b/lighthouse-core/lib/asset-saver.js @@ -7,6 +7,7 @@ const fs = require('fs'); const log = require('lighthouse-logger'); +const stream = require('stream'); const stringifySafe = require('json-stringify-safe'); const Metrics = require('./traces/pwmetrics-events'); @@ -102,6 +103,68 @@ function prepareAssets(artifacts, audits) { .then(_ => assets); } +/** + * Generates a JSON representation of traceData line-by-line to avoid OOM due to + * very large traces. + * @param {{traceEvents: !Array}} traceData + * @return {!Iterator} + */ +function* traceJsonGenerator(traceData) { + const keys = Object.keys(traceData); + + yield '{\n'; + + // Stringify and emit trace events separately to avoid a giant string in memory. + yield '"traceEvents": [\n'; + if (traceData.traceEvents.length > 0) { + const eventsIterator = traceData.traceEvents[Symbol.iterator](); + // Emit first item manually to avoid a trailing comma. + const firstEvent = eventsIterator.next().value; + yield ` ${JSON.stringify(firstEvent)}`; + for (const event of eventsIterator) { + yield `,\n ${JSON.stringify(event)}`; + } + } + yield '\n]'; + + // Emit the rest of the object (usually just `metadata`) + if (keys.length > 1) { + for (const key of keys) { + if (key === 'traceEvents') continue; + + yield `,\n"${key}": ${JSON.stringify(traceData[key], null, 2)}`; + } + } + + yield '}\n'; +} + +/** + * Save a trace as JSON by streaming to disk at traceFilename. + * @param {{traceEvents: !Array}} traceData + * @param {string} traceFilename + * @return {!Promise} + */ +function saveTrace(traceData, traceFilename) { + return new Promise((resolve, reject) => { + const traceIter = traceJsonGenerator(traceData); + // A stream that pulls in the next traceJsonGenerator chunk as writeStream + // reads from it. Closes stream with null when iteration is complete. + const traceStream = new stream.Readable({ + read() { + const next = traceIter.next(); + this.push(next.done ? null : next.value); + } + }); + + const writeStream = fs.createWriteStream(traceFilename); + writeStream.on('finish', resolve); + writeStream.on('error', reject); + + traceStream.pipe(writeStream); + }); +} + /** * Writes trace(s) and associated screenshot(s) to disk. * @param {!Artifacts} artifacts @@ -111,28 +174,31 @@ function prepareAssets(artifacts, audits) { */ function saveAssets(artifacts, audits, pathWithBasename) { return prepareAssets(artifacts, audits).then(assets => { - assets.forEach((data, index) => { - const traceFilename = `${pathWithBasename}-${index}.trace.json`; - fs.writeFileSync(traceFilename, JSON.stringify(data.traceData, null, 2)); - log.log('trace file saved to disk', traceFilename); - + return Promise.all(assets.map((data, index) => { const devtoolsLogFilename = `${pathWithBasename}-${index}.devtoolslog.json`; fs.writeFileSync(devtoolsLogFilename, JSON.stringify(data.devtoolsLog, null, 2)); - log.log('devtools log saved to disk', devtoolsLogFilename); + log.log('saveAssets', 'devtools log saved to disk: ' + devtoolsLogFilename); const screenshotsHTMLFilename = `${pathWithBasename}-${index}.screenshots.html`; fs.writeFileSync(screenshotsHTMLFilename, data.screenshotsHTML); - log.log('screenshots saved to disk', screenshotsHTMLFilename); + log.log('saveAssets', 'screenshots saved to disk: ' + screenshotsHTMLFilename); const screenshotsJSONFilename = `${pathWithBasename}-${index}.screenshots.json`; fs.writeFileSync(screenshotsJSONFilename, JSON.stringify(data.screenshots, null, 2)); - log.log('screenshots saved to disk', screenshotsJSONFilename); - }); + log.log('saveAssets', 'screenshots saved to disk: ' + screenshotsJSONFilename); + + const streamTraceFilename = `${pathWithBasename}-${index}.trace.json`; + log.log('saveAssets', 'streaming trace file to disk: ' + streamTraceFilename); + return saveTrace(data.traceData, streamTraceFilename).then(_ => { + log.log('saveAssets', 'trace file streamed to disk: ' + streamTraceFilename); + }); + })); }); } module.exports = { saveArtifacts, saveAssets, - prepareAssets + prepareAssets, + saveTrace }; diff --git a/lighthouse-core/test/lib/asset-saver-test.js b/lighthouse-core/test/lib/asset-saver-test.js index 16202f3cf103..f0c93872bb38 100644 --- a/lighthouse-core/test/lib/asset-saver-test.js +++ b/lighthouse-core/test/lib/asset-saver-test.js @@ -15,6 +15,7 @@ const traceEvents = require('../fixtures/traces/progressive-app.json'); const dbwTrace = require('../fixtures/traces/dbw_tester.json'); const dbwResults = require('../fixtures/dbw_tester-perf-results.json'); const Audit = require('../../audits/audit.js'); +const fullTraceObj = require('../fixtures/traces/progressive-app-m60.json'); /* eslint-env mocha */ describe('asset-saver helper', () => { @@ -34,24 +35,26 @@ describe('asset-saver helper', () => { }); describe('saves files', function() { - const artifacts = { - devtoolsLogs: { - [Audit.DEFAULT_PASS]: [{message: 'first'}, {message: 'second'}] - }, - traces: { - [Audit.DEFAULT_PASS]: { - traceEvents - } - }, - requestScreenshots: () => Promise.resolve(screenshotFilmstrip) - }; + before(() => { + const artifacts = { + devtoolsLogs: { + [Audit.DEFAULT_PASS]: [{message: 'first'}, {message: 'second'}] + }, + traces: { + [Audit.DEFAULT_PASS]: { + traceEvents + } + }, + requestScreenshots: () => Promise.resolve(screenshotFilmstrip) + }; - assetSaver.saveAssets(artifacts, dbwResults.audits, process.cwd() + '/the_file'); + return assetSaver.saveAssets(artifacts, dbwResults.audits, process.cwd() + '/the_file'); + }); - it('trace file saved to disk with data', () => { + it('trace file saved to disk with only trace events', () => { const traceFilename = 'the_file-0.trace.json'; const traceFileContents = fs.readFileSync(traceFilename, 'utf8'); - assert.ok(traceFileContents.length > 3000000); + assert.deepStrictEqual(JSON.parse(traceFileContents), {traceEvents}); fs.unlinkSync(traceFilename); }); @@ -97,4 +100,81 @@ describe('asset-saver helper', () => { }); }); }); + + describe('saveTrace', () => { + const traceFilename = 'test-trace-0.json'; + + afterEach(() => { + fs.unlinkSync(traceFilename); + }); + + it('correctly saves a trace with metadata to disk', () => { + return assetSaver.saveTrace(fullTraceObj, traceFilename) + .then(_ => { + const traceFileContents = fs.readFileSync(traceFilename, 'utf8'); + assert.deepStrictEqual(JSON.parse(traceFileContents), fullTraceObj); + }); + }); + + it('correctly saves a trace with no trace events to disk', () => { + const trace = { + traceEvents: [], + metadata: { + 'clock-domain': 'MAC_MACH_ABSOLUTE_TIME', + 'cpu-family': 6, + 'cpu-model': 70, + 'cpu-stepping': 1, + 'field-trials': [], + } + }; + + return assetSaver.saveTrace(trace, traceFilename) + .then(_ => { + const traceFileContents = fs.readFileSync(traceFilename, 'utf8'); + assert.deepStrictEqual(JSON.parse(traceFileContents), trace); + }); + }); + + it('correctly saves a trace with multiple extra properties to disk', () => { + const trace = { + traceEvents, + metadata: fullTraceObj.metadata, + someProp: 555, + anotherProp: { + unlikely: { + nested: [ + 'value' + ] + } + }, + }; + + return assetSaver.saveTrace(trace, traceFilename) + .then(_ => { + const traceFileContents = fs.readFileSync(traceFilename, 'utf8'); + assert.deepStrictEqual(JSON.parse(traceFileContents), trace); + }); + }); + + it('can save traces over 256MB (slow)', () => { + // Create a trace that wil be longer than 256MB when stringified, the hard + // limit of a string in v8. + // https://mobile.twitter.com/bmeurer/status/879276976523157505 + const baseEventsLength = JSON.stringify(traceEvents).length; + const countNeeded = Math.ceil(Math.pow(2, 28) / baseEventsLength); + let longTraceEvents = []; + for (let i = 0; i < countNeeded; i++) { + longTraceEvents = longTraceEvents.concat(traceEvents); + } + const trace = { + traceEvents: longTraceEvents + }; + + return assetSaver.saveTrace(trace, traceFilename) + .then(_ => { + const fileStats = fs.lstatSync(traceFilename); + assert.ok(fileStats.size > Math.pow(2, 28)); + }); + }); + }); }); From 5363ba39fe93368200377eb5d14cf6cfee576e49 Mon Sep 17 00:00:00 2001 From: Paul Irish Date: Fri, 23 Jun 2017 16:44:49 -0700 Subject: [PATCH 2/2] add streaming json parser --- lighthouse-core/gather/driver.js | 9 +- lighthouse-core/lib/traces/trace-parser.js | 70 +++++++++++++++ lighthouse-core/lib/web-inspector.js | 5 ++ .../test/lib/traces/trace-parser-test.js | 90 +++++++++++++++++++ 4 files changed, 170 insertions(+), 4 deletions(-) create mode 100644 lighthouse-core/lib/traces/trace-parser.js create mode 100644 lighthouse-core/test/lib/traces/trace-parser-test.js diff --git a/lighthouse-core/gather/driver.js b/lighthouse-core/gather/driver.js index c7ef7902758a..d2154553dfc4 100644 --- a/lighthouse-core/gather/driver.js +++ b/lighthouse-core/gather/driver.js @@ -10,6 +10,7 @@ const emulation = require('../lib/emulation'); const Element = require('../lib/element'); const EventEmitter = require('events').EventEmitter; const URL = require('../lib/url-shim'); +const TraceParser = require('../lib/traces/trace-parser'); const log = require('lighthouse-logger'); const DevtoolsLog = require('./devtools-log'); @@ -25,7 +26,7 @@ const _uniq = arr => Array.from(new Set(arr)); class Driver { static get MAX_WAIT_FOR_FULLY_LOADED() { - return 60 * 1000; + return 30 * 1000; } /** @@ -801,7 +802,7 @@ class Driver { _readTraceFromStream(streamHandle) { return new Promise((resolve, reject) => { let isEOF = false; - let result = ''; + const parser = new TraceParser(); const readArguments = { handle: streamHandle.stream @@ -812,11 +813,11 @@ class Driver { return; } - result += response.data; + parser.parseChunk(response.data); if (response.eof) { isEOF = true; - return resolve(JSON.parse(result)); + return resolve(parser.getTrace()); } return this.sendCommand('IO.read', readArguments).then(onChunkRead); diff --git a/lighthouse-core/lib/traces/trace-parser.js b/lighthouse-core/lib/traces/trace-parser.js new file mode 100644 index 000000000000..681057bfdd2a --- /dev/null +++ b/lighthouse-core/lib/traces/trace-parser.js @@ -0,0 +1,70 @@ +/** + * @license Copyright 2017 Google Inc. All Rights Reserved. + * Licensed under the Apache License, Version 2.0 (the "License"); you may not use this file except in compliance with the License. You may obtain a copy of the License at http://www.apache.org/licenses/LICENSE-2.0 + * Unless required by applicable law or agreed to in writing, software distributed under the License is distributed on an "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the License for the specific language governing permissions and limitations under the License. + */ +'use strict'; + +const WebInspector = require('../web-inspector'); + +/** + * Traces > 256MB hit limits in V8, so TraceParser will parse the trace events stream as it's + * received. We use DevTools' TimelineLoader for the heavy lifting, as it has a fast trace-specific + * streaming JSON parser. + * The resulting trace doesn't include the "metadata" property, as it's excluded via DevTools' + * implementation. + */ +class TraceParser { + constructor() { + this.traceEvents = []; + + this.tracingModel = { + reset: _ => this._reset(), + addEvents: evts => this._addEvents(evts), + }; + + const delegateMock = { + loadingProgress: _ => {}, + loadingStarted: _ => {}, + loadingComplete: success => { + if (!success) throw new Error('Parsing problem'); + } + }; + this.loader = new WebInspector.TimelineLoader(this.tracingModel, delegateMock); + } + + /** + * Reset the trace events array + */ + _reset() { + this.traceEvents = []; + } + + /** + * Adds parsed trace events to array + * @param {!Array} evts + */ + _addEvents(evts) { + this.traceEvents.push(...evts); + } + + /** + * Receive chunk of streamed trace + * @param {string} data + */ + parseChunk(data) { + this.loader.write(data); + } + + /** + * Returns entire trace + * @return {{traceEvents: !Array}} + */ + getTrace() { + return { + traceEvents: this.traceEvents + }; + } +} + +module.exports = TraceParser; diff --git a/lighthouse-core/lib/web-inspector.js b/lighthouse-core/lib/web-inspector.js index 1877b0a72b56..44d390dccf8d 100644 --- a/lighthouse-core/lib/web-inspector.js +++ b/lighthouse-core/lib/web-inspector.js @@ -176,6 +176,11 @@ module.exports = (function() { require('chrome-devtools-frontend/front_end/timeline_model/TimelineModel.js'); require('chrome-devtools-frontend/front_end/ui_lazy/SortableDataGrid.js'); require('chrome-devtools-frontend/front_end/timeline/TimelineTreeView.js'); + + // used for streaming json parsing + require('chrome-devtools-frontend/front_end/common/TextUtils.js'); + require('chrome-devtools-frontend/front_end/timeline/TimelineLoader.js'); + require('chrome-devtools-frontend/front_end/timeline_model/TimelineProfileTree.js'); require('chrome-devtools-frontend/front_end/components_lazy/FilmStripModel.js'); require('chrome-devtools-frontend/front_end/timeline_model/TimelineIRModel.js'); diff --git a/lighthouse-core/test/lib/traces/trace-parser-test.js b/lighthouse-core/test/lib/traces/trace-parser-test.js new file mode 100644 index 000000000000..2f48234c0db2 --- /dev/null +++ b/lighthouse-core/test/lib/traces/trace-parser-test.js @@ -0,0 +1,90 @@ +/** + * @license Copyright 2017 Google Inc. All Rights Reserved. + * Licensed under the Apache License, Version 2.0 (the "License"); you may not use this file except in compliance with the License. You may obtain a copy of the License at http://www.apache.org/licenses/LICENSE-2.0 + * Unless required by applicable law or agreed to in writing, software distributed under the License is distributed on an "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the License for the specific language governing permissions and limitations under the License. + */ +'use strict'; + +const TraceParser = require('../../../lib/traces/trace-parser'); +const fs = require('fs'); +const assert = require('assert'); + + +/* eslint-env mocha */ +describe('traceParser parser', () => { + it('returns preact trace data the same as JSON.parse', (done) => { + const filename = '../../fixtures/traces/progressive-app-m60.json'; + const readStream = fs.createReadStream(__dirname + '/' + filename, { + encoding: 'utf-8', + // devtools sends traces in 10mb chunks, but this trace is 12MB so we'll do a few chunks + highWaterMark: 4 * 1024 * 1024 + }); + const parser = new TraceParser(); + + readStream.on('data', (chunk) => { + parser.parseChunk(chunk); + }); + readStream.on('end', () => { + const streamedTrace = parser.getTrace(); + const readTrace = require(filename); + + assert.equal(streamedTrace.traceEvents.length, readTrace.traceEvents.length); + assert.deepStrictEqual(streamedTrace.traceEvents, readTrace.traceEvents); + + done(); + }); + }); + + + it('parses a trace > 256mb (slow)', () => { + const parser = new TraceParser(); + let bytesRead = 0; + // FYI: this trace doesn't have a traceEvents property ;) + const events = require('../../fixtures/traces/devtools-homepage-w-screenshots-trace.json'); + + /** + * This function will synthesize a trace that's over 256 MB. To do that, we'll take an existing + * trace and repeat the same events again and again until we've gone over 256 MB. + * Note: We repeat all but the last event, as it's the CpuProfile event, and it triggers + * specific handling in the devtools streaming parser. + * Once we reach > 256 MB, we add in the CpuProfile event. + */ + function buildAndParse256mbTrace() { + const stripOuterBrackets = str => str.replace(/^\[/, '').replace(/\]$/, ''); + const partialEventsStr = events => stripOuterBrackets(JSON.stringify(events)); + const traceEventsStr = partialEventsStr(events.slice(0, events.length-2)) + ','; + + // read the trace intro + parser.parseChunk(`{"traceEvents": [${traceEventsStr}`); + bytesRead += traceEventsStr.length; + + // just keep reading until we've gone over 256 MB + // 256 MB is hard limit of a string in v8 + // https://mobile.twitter.com/bmeurer/status/879276976523157505 + while (bytesRead <= (Math.pow(2, 28)) - 16) { + parser.parseChunk(traceEventsStr); + bytesRead += traceEventsStr.length; + } + + // the CPU Profiler event is last (and big), inject it just once + const lastEventStr = partialEventsStr(events.slice(-1)); + parser.parseChunk(lastEventStr + ']}'); + bytesRead += lastEventStr.length; + } + + buildAndParse256mbTrace(); + const streamedTrace = parser.getTrace(); + + assert.ok(bytesRead > 256 * 1024 * 1024, `${bytesRead} bytes read`); + assert.strictEqual(bytesRead, 270179102, `${bytesRead} bytes read`); + + // if > 256 MB are read we should have ~480,000 trace events + assert.ok(streamedTrace.traceEvents.length > 400 * 1000, 'not >400,000 trace events'); + assert.ok(streamedTrace.traceEvents.length > events.length * 5, 'not way more trace events'); + assert.strictEqual(streamedTrace.traceEvents.length, 480151); + + assert.deepStrictEqual( + streamedTrace.traceEvents[events.length - 2], + events[0]); + }); +});