core(perf): add timing instrumentation to measure runtime perf #3745

paulirish · 2017-11-03T20:40:26Z

This work fixes #2304 (and is mentioned in #3719)

We make use of marky which generates user timing entries for our instrumentation. We then use a variant of tdresser/performance-observer-tracing to create a trace from those measures.

usage:

$ lighthouse https://flipkart.com --output=json --output-path=flipkart.json

# ........

$ yarn timing flipkart.json

  > Timing trace file saved to: /Users/paulirish/code/lighthouse/flipkart.json.run-timing.trace.json
  > Open this file in chrome://tracing

✨  Done in 0.23s.

Since lighthouse-logger gets some changes you'll need to npm link it to absorb them.

Here's the trace in the screenshot f you want to poke around it: flipkart.json.run-timing.trace.json.txt

patrickhulce

awesome awesome stuff 💣 ⏲ 💥

patrickhulce · 2017-11-03T20:49:45Z

lighthouse-core/gather/driver.js

@@ -97,7 +97,9 @@ class Driver {
 * @return {!Promise<null>}
 */
 connect() {
- return this._connection.connect();
+ const status = {str: 'Connecting to browser', id: 'connect'};
+ log.log('status', status.str, status.id);


log.time?

patrickhulce · 2017-11-03T20:51:44Z

lighthouse-core/config/config.js

@@ -269,6 +269,7 @@ class Config {
 * @param {string=} configPath The absolute path to the config file, if there is one.
 */
 constructor(configJSON, configPath) {
+ log.marky.mark('config-create');


i'd prefer log.time here :)

patrickhulce · 2017-11-03T20:54:59Z

lighthouse-logger/index.js

@@ -104,6 +106,16 @@ class Log {
 Log._logToStdErr(`${prefix}:${level || ''}`, [method, snippet]);
 }

+ static time({str, id, args=[]}, level='log') {


how do you feel about msg instead of str?

patrickhulce · 2017-11-03T20:58:21Z

lighthouse-core/index.js

- lighthouseResults.timing.total = endTime - startTime;
+ lighthouseResults.timing.total = totalEntry.duration;
+
+ fs.writeFileSync('generateTrace.html', `


seems like it needs fixin :)

patrickhulce · 2017-11-03T20:58:33Z

lighthouse-core/index.js

@@ -35,15 +37,25 @@ module.exports = function(url, flags = {}, configJSON) {
 // Use ConfigParser to generate a valid config file
 const config = new Config(configJSON, flags.configPath);

+ log.marky.mark('ConnectionSetup');


patrickhulce · 2017-11-03T20:58:44Z

lighthouse-core/runner.js

@@ -25,13 +25,15 @@ class Runner {

 // List of top-level warnings for this Lighthouse run.
 const lighthouseRunWarnings = [];
+ log.marky.mark('runner.run');


patrickhulce · 2017-11-03T21:06:24Z

lighthouse-core/runner.js

@@ -151,6 +160,12 @@ class Runner {
 score = report.score;
 }

+ log.timeEnd(status);
+ const timings = {};


nit: let's just keep as timing

patrickhulce · 2017-11-03T21:08:33Z

lighthouse-core/scripts/generate-lh-timing-trace.js

+
+ const jsonStr = `
+ { "traceEvents": [
+ ${events.map(evt => JSON.stringify(evt)).join(',\n')}


haha how about JSON.stringify({traceEvents: events}, null, 2) :)

well the benefit of stringifying them individually is 1 line per trace event:

sooooooo........

alright alright

paulirish · 2017-11-04T00:29:00Z

updated.

patrickhulce · 2017-11-06T18:18:06Z

lighthouse-core/gather/gather-runner.js

@@ -234,13 +252,20 @@ class GatherRunner {
 .then(_ => recordTrace && driver.beginTrace(options.flags))
 // Navigate.
 .then(_ => GatherRunner.loadPage(driver, options))
- .then(_ => log.log('statusEnd', status));
+ .then(_ => log.timeEnd(status, 'log'));


the level is log? that's weird haha

shrug. i suppose its equivalent level is actually "info"/"informational", but that's otherwise hidden as an implementation detail of lighthouse-logger.

patrickhulce

impl looks good to me!

It might be worth noodling on the timing IDs so a hierarchy is a little more self-evident.

a sample of what this might look like with namespaces colon/hyphen concatenated?

lh:init:config:create
lh:gather:beforePass:Styles
lh:audit:unused-css-rules

lh
|- init
    |- config
    |- connect
|- runner
    |- gathering
    |- auditing
|- gather
    |- setup
    |- beforePass:<gatherer name>
    |- load
    |- pass:<gatherer name>
    |- afterPass:<gatherer name>
    |- <gatherer name> *not part of trace, just timing object*
|- audit
    |- <audit name>
|- report
    |- ...
|- cleanup

patrickhulce · 2017-11-06T21:21:02Z

lighthouse-logger/package.json

@@ -3,6 +3,7 @@
 "version": "1.0.1",
 "license": "Apache-2.0",
 "dependencies": {
- "debug": "^2.6.8"
+ "debug": "^2.6.8",
+ "marky": "^1.2.0"


lighthouse depends on lighthouse-logger explicitly so we don't need to update root package.json too or should we add in root too?

paulirish · 2017-11-15T20:56:11Z

add checks for asserting nesting & never-ending trace events

paulirish · 2017-11-18T00:40:10Z

updated based on feedback.

zoom

sorted by selftime

example generated trace: example.timing.json.zip

patrickhulce

lgtm!

still somewhat nervous about the marky dep being in logger, we'll need to publish logger and bump our dep on it before publishing next LH I guess?

patrickhulce · 2017-11-18T05:35:46Z

lighthouse-core/scripts/generate-lh-timing-trace.js

@@ -0,0 +1,134 @@
+/**
+ * @license Copyright 2016 Google Inc. All Rights Reserved.


patrickhulce · 2017-11-18T05:39:13Z

lighthouse-core/config/config.js

@@ -269,6 +269,8 @@ class Config {
 * @param {string=} configPath The absolute path to the config file, if there is one.
 */
 constructor(configJSON, configPath) {
+ const status = {msg: 'Create config', id: 'config-create'};


lh:init:config maybe?

brendankenny

this is looking good.

I'm still wondering about nesting, though. It seems like that's ok (vs overlapping)? e.g. a gatherer time is inside gatherRunner is inside runner is inside total

If that's ok, should we rely more on nesting for naming context rather than do it manually? e.g. a gatherer doesn't need all of lh:gather:pass:gather-name because it's already nested in those things.

brendankenny · 2017-11-20T21:24:00Z

lighthouse-logger/index.js

@@ -207,5 +219,6 @@ class Log {
 }

 Log.events = new Emitter();
+Log.marky = marky;


since marky is a singleton which will persist between runs, maybe we should wrap in a method on Log to also clear? like

static getTimeEntries() { const entries = marky.getEntries(); marky.clear(); return entries; }

brendankenny · 2017-11-20T21:48:32Z

lighthouse-core/runner.js

@@ -71,6 +74,8 @@ class Runner {
 if (validPassesAndAudits) {
 // Set up the driver and run gatherers.
 opts.driver = opts.driverMock || new Driver(connection);
+ run = run.then(_ => log.timeEnd(runnerStatus));


doesn't this need to end in all execution paths?

brendankenny · 2017-11-20T22:18:07Z

lighthouse-core/scripts/generate-lh-timing-trace.js

+const path = require('path');
+
+/**
+ * Technically, it's fine for usertiming measures to overlap, however non-async events make


I'm not sure I understand overlapping vs async events here. Seems like they are separate concerns?

brendankenny · 2017-11-20T22:20:38Z

lighthouse-core/scripts/generate-lh-timing-trace.js

+ traceFilePath = path.resolve(process.cwd(), 'run-timing.trace.json');
+ }
+ fs.writeFileSync(traceFilePath, jsonStr, 'utf8');
+ process.stdout.write(`


any reason not to use console.log? (with eslint line disable)

brendankenny · 2017-11-20T22:20:57Z

lighthouse-core/scripts/generate-lh-timing-trace.js

+ */
+function saveTraceFromCLI() {
+ const printErrorAndQuit = msg => {
+ process.stderr.write(`ERROR:


console.error?

brendankenny · 2017-11-20T22:22:33Z

lighthouse-core/scripts/generate-lh-timing-trace.js

+ * Takes filename of LHR object. The primary entrypoint on CLI
+ */
+function saveTraceFromCLI() {
+ const printErrorAndQuit = msg => {


pull out as a top level function?

brendankenny

should smoke tests assert at least some timing stuff exists? Or one of the runner/index tests that runs (but no gathering) has all the timings that make sense? It seems like it could be easy to lose a time or a timeEnd or misplace in a promise chain or something, and not notice it happened

brendankenny · 2017-11-20T22:31:15Z

lighthouse-core/scripts/generate-lh-timing-trace.js

@@ -0,0 +1,134 @@
+/**


needs tests :)

paulirish · 2018-03-14T18:36:42Z

Since we're taking a closer look at the LHR these days.. here's what the timing object looks as of this branch:

Looking at it with today's eyes, I have two proposals:

remove 'entryType' from the entries
only ship a few select high-level timings we'd be comfortable including in LHR-Lite (v1 or v2) (e.g. loadBlank, loadTargetPage, gathering, auditing, total). This means these other timings are not AS accessible via JSON_EXTRACT, though it may be doable?. (No idea if bigquery supports that).

patrickhulce · 2018-06-22T18:16:13Z

brendankenny

⏱ 📏 :its_happening:
Last bit, otherwise LGTM!

brendankenny · 2018-10-18T22:52:53Z

lighthouse-core/runner.js

+
+ // Summarize all the timings and drop onto the LHR
+ try {
+ log.timeEnd(runnerStatus);


marky looks like it will only throw if runnerStatus.id hadn't been started, but that looks like that isn't possible here. Still need the try/catch?

I think it was happening in a -GA run?

brendankenny · 2018-10-18T22:56:46Z

lighthouse-core/scripts/generate-timing-trace.js

@@ -0,0 +1,57 @@
+/**


we should really organize scripts/ at some point, but not necessary in this PR :)

brendankenny · 2018-10-18T22:58:45Z

lighthouse-core/scripts/generate-timing-trace.js

+
+const fs = require('fs');
+const path = require('path');
+const {createTraceString} = require('../lib/timing-trace-saver');


can this and timing-trace-saver.js just be the same file? (we can do in a follow up)

it was at one point, but i separated it to write tests.
i mean i guess we could have lighthouse-core/test/scripts/... but it seemed weird. :)

typings/artifacts.d.ts

brendankenny · 2018-10-18T23:03:20Z

lighthouse-core/lib/asset-saver.js

+ // Any Timing entries in saved artifacts will have a different timeOrigin than the auditing phase
+ // The `gather` prop is read later in generate-timing-trace and they're added to a separate track of trace events
+ artifacts.Timing.forEach(entry => (entry.gather = true));
+ }


should this happen in gather-runner.js? After line 399

We only want to break the trace into two tracks if they're done at different times. (Classic -G then -A workflow)

So that's why we assign here to force a diff track.

paulirish

thx patrick very much for pushing this!

paulirish · 2018-10-19T00:17:09Z

lighthouse-core/scripts/generate-timing-trace.js

+
+const fs = require('fs');
+const path = require('path');
+const {createTraceString} = require('../lib/timing-trace-saver');


it was at one point, but i separated it to write tests.
i mean i guess we could have lighthouse-core/test/scripts/... but it seemed weird. :)

paulirish · 2018-10-19T00:18:50Z

lighthouse-core/runner.js

+
+ // Summarize all the timings and drop onto the LHR
+ try {
+ log.timeEnd(runnerStatus);


I think it was happening in a -GA run?

patrickhulce · 2018-10-19T00:51:23Z

no problemo @paulirish I'll let you finish up :)

Co-Authored-By: paulirish <paul.irish@gmail.com>

connorjclark · 2018-10-24T20:10:41Z

RE: Error: Failed to execute \'measure\' on \'Performance\': The mark \'start lh:runner:run\' does not exist.

Marky did us wrong :'(

Marky is stubbing a global "performance" variable: lighthouse/node_modules/marky/dist/marky.js

One glaring difference ...

performance is defined (browser)

exports.clear = function () {
perf.clearMarks();
perf.clearMeasures();
};

not defined (node)

exports.clear = function () { entries = []; };

gather-runner clears the marks before the first runner mark ends. Hence the error.

Expose time entires in lighthouse-logger
Don't clear the marks in gather-runner. Do extra processing in runner to dedupe marks.

connorjclark · 2018-10-24T21:13:28Z

Sent a PR to marky.

paulirish · 2018-10-25T01:19:00Z

lgtm

brendankenny

last things, then LGTM ⏱⏲⌚️:)

brendankenny · 2018-10-25T03:39:12Z

package.json

@@ -53,6 +53,8 @@
 "fast": "yarn start --disable-device-emulation --throttlingMethod=provided",
 "deploy-viewer": "cd lighthouse-viewer && gulp deploy",
 "bundlesize": "bundlesize",
+ "plots-smoke": "bash plots/test/smoke.sh",
+ "timing": "node lighthouse-core/scripts/generate-timing-trace.js",


can we call this something more? timing-trace?

brendankenny · 2018-10-25T03:39:56Z

lighthouse-core/runner.js

@@ -119,6 +121,11 @@ class Runner {
 categories = ReportScoring.scoreAllCategories(runOpts.config.categories, resultsById);
 }

+ log.timeEnd(resultsStatus);
+
+ // Summarize all the timings and drop onto the LHR


should drop this comment now

brendankenny · 2018-10-25T03:52:23Z

lighthouse-core/runner.js

+ ...timingEntriesFromArtifacts,
+ ...timingEntriesFromRunner,
+ ].map(entry => /** @type {[string, PerformanceEntry]} */ ([entry.name, entry]));
+ const timingEntries = Array.from(new Map(timingEntriesKeyValues).values());


would be good to get a comment in here about why we're doing this/need to do this. Basically this handles both the auditMode case where gatherer entries need to be merged in and the gather/audit case where timingEntriesFromRunner contains all entries from this run, including those also in timingEntriesFromArtifacts

brendankenny · 2018-10-25T03:57:21Z

typings/artifacts.d.ts

@@ -304,6 +306,16 @@ declare global {
 }[];
 }

+ export interface MeasureEntry {


we should maybe make this

export interface MeasureEntry extends PerformanceEntry { /** Whether timing entry was collected during artifact gathering. */ gather?: boolean; }

to make the intended interchangeability clearer

connorjclark · 2018-10-25T17:30:54Z

@brendankenny done

brendankenny

waiting for the green, but LGTM!

@paulirish we should probably add a "how to profile" section to CONTRIBUTING or wherever, but can do that at a later time :)

brendankenny · 2018-10-25T18:15:47Z

:rip_van_winkle:

patrickhulce · 2018-10-25T19:11:25Z

this merge deserves its own partay

paulirish added internals OYB labels Nov 3, 2017

paulirish requested a review from patrickhulce November 3, 2017 20:40

paulirish requested a review from brendankenny as a code owner November 3, 2017 20:40

patrickhulce previously requested changes Nov 3, 2017

View reviewed changes

paulirish added the waiting4reviewer label Nov 4, 2017

patrickhulce reviewed Nov 6, 2017

View reviewed changes

paulirish added waiting4committer and removed waiting4reviewer labels Nov 15, 2017

paulirish force-pushed the timing branch from 2c2eed9 to deaa11b Compare November 18, 2017 00:37

paulirish added waiting4reviewer and removed waiting4committer labels Nov 18, 2017

patrickhulce reviewed Nov 18, 2017

View reviewed changes

brendankenny mentioned this pull request Nov 20, 2017

core(dtm-gatherer): Stop DevtoolsTimelineModel from mutating trace #3855

Merged

brendankenny requested changes Nov 20, 2017

View reviewed changes

brendankenny reviewed Nov 20, 2017

View reviewed changes

lighthouse-core/scripts/generate-lh-timing-trace.js Outdated

@@ -0,0 +1,134 @@

/**

Copy link

Member

brendankenny Nov 20, 2017

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

needs tests :)

patrickhulce added waiting4committer and removed waiting4reviewer labels Dec 14, 2017

paulirish mentioned this pull request Mar 14, 2018

Fetch the gatheredTimestamp #4753

Closed

paulirish added 3 commits June 22, 2018 15:45

core(perf): add instrumentation to measure LH runtime perf

b8830cb

gatherEntries and no more .timing.total

df7e1b4

fixup typing of traces.

f1a2909

paulirish force-pushed the timing branch from deaa11b to f1a2909 Compare June 22, 2018 16:59

feedback.

c46548d

patrickhulce added 2 commits October 17, 2018 20:49

Merge branch 'master' into timing

88c888b

more feedback

bcfaf7c

brendankenny approved these changes Oct 18, 2018

View reviewed changes

paulirish commented Oct 19, 2018

View reviewed changes

brendankenny and others added 4 commits October 18, 2018 18:17

Update typings/artifacts.d.ts

c72ac0c

Co-Authored-By: paulirish <paul.irish@gmail.com>

Update artifacts.d.ts

274693a

drop try/catch

bd03859

Merge branch 'master' into timing

011f272

connorjclark mentioned this pull request Oct 24, 2018

lighthouse-logger improvments #6313

Closed

2 tasks

use status object

434f788

connorjclark mentioned this pull request Oct 24, 2018

misc(logger): isVerbose(), getTimeEntries() #6383

Merged

paulirish mentioned this pull request Oct 24, 2018

deps(logger): bump version for publish #6385

Closed

connorjclark added 3 commits October 24, 2018 17:30

Merge branch 'master' into timing

2ba317f

update lh logger. dedupe time measures

8c7b0a2

better code

508506a

brendankenny approved these changes Oct 25, 2018

View reviewed changes

pr changes

4a2e662

brendankenny removed the waiting4committer label Oct 25, 2018

brendankenny approved these changes Oct 25, 2018

View reviewed changes

brendankenny merged commit 888bd6d into master Oct 25, 2018

brendankenny deleted the timing branch October 25, 2018 18:15

paulirish mentioned this pull request Oct 25, 2018

docs: add primer on viewing the timing data #6393

Merged

brendankenny mentioned this pull request Jan 30, 2019

misc(logger): 1.3.0, package types, timeDecorate, add tests #6740

Closed

		@@ -0,0 +1,134 @@
		/**
		* @license Copyright 2016 Google Inc. All Rights Reserved.

core(perf): add timing instrumentation to measure runtime perf #3745

core(perf): add timing instrumentation to measure runtime perf #3745

Conversation

paulirish commented Nov 3, 2017

patrickhulce left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

paulirish commented Nov 4, 2017

Choose a reason for hiding this comment

Choose a reason for hiding this comment

patrickhulce left a comment • edited Loading

Choose a reason for hiding this comment

patrickhulce Nov 6, 2017 • edited Loading

Choose a reason for hiding this comment

paulirish commented Nov 15, 2017 • edited Loading

paulirish commented Nov 18, 2017

patrickhulce left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

brendankenny left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

brendankenny left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

paulirish commented Mar 14, 2018

patrickhulce commented Jun 22, 2018

brendankenny left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

paulirish left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

patrickhulce commented Oct 19, 2018

connorjclark commented Oct 24, 2018 • edited Loading

connorjclark commented Oct 24, 2018

paulirish commented Oct 25, 2018

brendankenny left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

connorjclark commented Oct 25, 2018

brendankenny left a comment

Choose a reason for hiding this comment

brendankenny commented Oct 25, 2018

patrickhulce commented Oct 25, 2018

patrickhulce left a comment •

edited

Loading

patrickhulce Nov 6, 2017 •

edited

Loading

paulirish commented Nov 15, 2017 •

edited

Loading

connorjclark commented Oct 24, 2018 •

edited

Loading