new_audit(mainthread-work-breakdown): Audit for page-execution-timings by wardpeet · Pull Request #3520 · GoogleChrome/lighthouse

wardpeet · 2017-10-10T15:12:14Z

Credits go to @addyosmani to do the heavy lifting #1695

wardpeet · 2017-10-10T15:13:12Z

I'm not sure how to unit test this? should I record a trace and run it against it or mock devtoolsModel?

Mocking devtoolsModel looks easier

wardpeet · 2017-10-10T15:43:57Z

I'd prefer to make sure this includes everything. But in order to help clarify script costs.. I see two solutions here:

Add a TaskCategory column that would help clarify Script vs Paint, etc.

Add a color chip next to the titles.. All yellow/orange would be quick to notice.

How do I add a color ship? Change the category renderer?

wardpeet · 2017-10-10T15:51:57Z

Example report:
paulirish.com

m.nieuwsblad.be

paulirish · 2017-10-10T20:54:29Z

lighthouse-core/audits/page-execution-timings.js

+const Util = require('../report/v2/renderer/util');
+const DevtoolsTimelineModel = require('../lib/traces/devtools-timeline-model');
+
+const timelineCategories = [


Let's go with an enum for the groups:

const timelineGroups = { JavaScript: 'JavaScript', PaintLayout: 'Paint/Layout', DOMCSS: 'DOM/CSS'. Images: 'Images' }; const timelineCategories = { 'Compile Script': timelineGroups.JavaScript }, 'Evaluate Script': timelineGroups.JavaScript }, 'Run Microtasks': timelineGroups.JavaScript }, 'Minor GC': timelineGroups.JavaScript }, ... };

I've just updated https://docs.google.com/spreadsheets/d/1jqbSfdkB5RMtuifJwQsGb70WUUhWvzir7hq41wYHXsU/edit#gid=0 with the latest and greatest.

and for convenience.. here's the categories lookup:

const group = { loading: 'Network request loading', parseHTML: 'Parsing DOM', styleLayout: 'Style & Layout', compositing: 'Compositing', painting: 'Paint', gpu: 'GPU', scripting: 'Script Evaluation', scriptParseCompile: 'Script Parsing & Compile', scriptGC: 'Garbage collection', other: 'Other', images: 'Images', }; const taskToGroup = { 'Animation': group.painting, 'Async Task': group.other, 'Frame Start': group.painting, 'Frame Start (main thread)': group.painting, 'Cancel Animation Frame': group.scripting, 'Cancel Idle Callback': group.scripting, 'Compile Script': group.scriptParseCompile, 'Composite Layers': group.compositing, 'Console Time': group.scripting, 'Image Decode': group.images, 'Draw Frame': group.painting, 'Embedder Callback': group.scripting, 'Evaluate Script': group.scripting, 'Event': group.scripting, 'Animation Frame Fired': group.scripting, 'Fire Idle Callback': group.scripting, 'Function Call': group.scripting, 'DOM GC': group.scriptGC, 'GC Event': group.scriptGC, 'GPU': group.gpu, 'Hit Test': group.compositing, 'Invalidate Layout': group.styleLayout, 'JS Frame': group.scripting, 'Input Latency': group.scripting, 'Layout': group.styleLayout, 'Major GC': group.scriptGC, 'DOMContentLoaded event': group.scripting, 'First paint': group.painting, 'FMP': group.painting, 'FMP candidate': group.painting, 'Load event': group.scripting, 'Minor GC': group.scriptGC, 'Paint': group.painting, 'Paint Image': group.images, 'Paint Setup': group.painting, 'Parse Stylesheet': group.parseHTML, 'Parse HTML': group.parseHTML, 'Parse Script': group.scriptParseCompile, 'Other': group.other, 'Rasterize Paint': group.painting, 'Recalculate Style': group.styleLayout, 'Request Animation Frame': group.scripting, 'Request Idle Callback': group.scripting, 'Request Main Thread Frame': group.painting, 'Image Resize': group.images, 'Finish Loading': group.loading, 'Receive Data': group.loading, 'Receive Response': group.loading, 'Send Request': group.loading, 'Run Microtasks': group.scripting, 'Schedule Style Recalculation': group.styleLayout, 'Scroll': group.compositing, 'Task': group.other, 'Timer Fired': group.scripting, 'Install Timer': group.scripting, 'Remove Timer': group.scripting, 'Timestamp': group.scripting, 'Update Layer': group.compositing, 'Update Layer Tree': group.compositing, 'User Timing': group.scripting, 'Create WebSocket': group.scripting, 'Destroy WebSocket': group.scripting, 'Receive WebSocket Handshake': group.scripting, 'Send WebSocket Handshake': group.scripting, 'XHR Load': group.scripting, 'XHR Ready State Change': group.scripting, }

That is one super-handy category break-down!

where do you get that list when I capture a trace I can only find a handful of them

paulirish · 2017-10-10T22:00:58Z

lighthouse-core/audits/page-execution-timings.js

+    const executionTimings = PageExecutionTimings.getExecutionTimingsByCategory(trace);
+    let totalExecutionTime = 0;
+
+    const results = timelineCategories.map(category => {


feels better to loop over your real results instead of iterating the lookup.
with the categories i shared above.. you have constant time lookup:

Array.from(executionTimings).map(([eventName, duration]) => { totalExecutionTime += duration; return { category: eventName, group: taskToGroup[eventName], duration: Util.formatMilliseconds(duration, 1), }; });

nice! much better actually 👍

paulirish · 2017-10-10T23:04:46Z

lighthouse-core/audits/page-execution-timings.js

+   * @param {!Array<TraceEvent>=} trace
+   * @param {!WebInspector.TimelineProfileTree.Node} A grouped and sorted tree
+   */
+  static getTimingsByCategory(trace) {


this is pretty straightforward. you might as well inline this stuff into your getExecutionTimingsByCategory method

will switch back to the old way, I tried override that methode to mock DevtoolsTimeLinemodel

patrickhulce · 2017-10-13T15:44:43Z

lighthouse-core/test/audits/page-execution-timings-test.js

+// sadly require(file) is not working correctly.
+// traceParser parser returns preact trace data the same as JSON.parse
+// fails when require is used
+const readFile = (file, cb) => {


and readFileSync doesn't work either!? geez what's going on with these files 😆

Readfilesync prolly works too. I bet devtoolstimeline changes the trace

Ah ok, require caches the same object so you're probably right, could we switch to readfilesync then for brevity?

wardpeet · 2017-10-14T12:15:48Z

I think this audit is good to go, only have my doubts about the meta data.
score is always false so we show it as a perf Diagnostic

benschwarz · 2017-10-14T12:37:24Z

@wardpeet - “executiontime” should be two words 👍

Looking really, really good otherwise.

wardpeet · 2017-10-16T15:31:13Z

@brendankenny should I add it to any of the real url smoketests?

brendankenny

review!

brendankenny · 2017-10-17T23:18:49Z

lighthouse-core/audits/page-execution-timings.js

+ */
+
+/**
+ * @fileoverview Audit a page to see if it does not use <link> that block first paint.


need to update :P

brendankenny · 2017-10-17T23:19:23Z

lighthouse-core/audits/page-execution-timings.js

+const Util = require('../report/v2/renderer/util');
+const DevtoolsTimelineModel = require('../lib/traces/devtools-timeline-model');
+
+const group = {


add some brief comments to these to explain what they are?

brendankenny · 2017-10-17T23:25:12Z

lighthouse-core/audits/page-execution-timings.js

+
+    const result = new Map();
+    bottomUpByName.children.forEach((value, key) =>
+      result.set(key, Number(value.selfTime.toFixed(1))));


rounding doesn't look necessary here? Seems like it should only happen for parts of the audit result meant for display (and duration is sent to Util.formatMilliseconds taking care of that)

brendankenny · 2017-10-17T23:25:32Z

lighthouse-core/audits/page-execution-timings.js

+    const bottomUpByName = timelineModel.bottomUpGroupBy('EventName');
+
+    const result = new Map();
+    bottomUpByName.children.forEach((value, key) =>


maybe s/key/eventName to give a local hint on what the keys are?

brendankenny · 2017-10-17T23:25:37Z

lighthouse-core/audits/page-execution-timings.js

+
+  /**
+   * @param {!Array<TraceEvent>=} trace
+   * @return {!Map<string, Number>}


lowercase number

brendankenny · 2017-10-17T23:26:26Z

lighthouse-core/audits/page-execution-timings.js

+  }
+
+  /**
+   * @param {!Array<TraceEvent>=} trace


I believe this isn't optional? (no =)

brendankenny · 2017-10-17T23:28:55Z

lighthouse-core/audits/page-execution-timings.js

+  static get meta() {
+    return {
+      category: 'Performance',
+      name: 'page-execution-timings',


thinking about hypothetical futures, should we keep this more scoped in name? load-execution-timings or trace-group-timings or...something :) @paulirish

mainthread-work-breakdown ?

brendankenny · 2017-10-18T00:09:15Z

lighthouse-core/audits/page-execution-timings.js

+   * @return {!Map<string, Number>}
+   */
+  static getExecutionTimingsByCategory(trace) {
+    const timelineModel = new DevtoolsTimelineModel(trace);


is it possible to limit to events before TTCI? Not sure how to do this with DevtoolsTimelineModel

is it possible to limit to events before TTCI? Not sure how to do this with DevtoolsTimelineModel

discussed offline. this could be done in a followup.. it wouldn't make a huge difference though it will be nice.

brendankenny · 2017-10-18T00:12:10Z

lighthouse-core/test/audits/page-execution-timings-test.js

+const fs = require('fs');
+const assert = require('assert');
+
+// sadly require(file) is not working correctly.


this is a bit worrying because it means DevtoolsTimelineModel will be changing the main trace as well. Looking at the test diff, it looks like it's only changing column/line numbers (to make them 0-indexed) but that's still not great :)

Talking here we were thinking about either Object.freeze or cloning options. Not sure what's best from a performance perspective, though.

yes exactly just numbers are changing.

cloning would probably take a while as you'll need a deep clone which can be pretty heavy. Will object.freeze work with timeline as they won't be able to edit the values.

I can poke around to see what works

paulirish

once this comes back we're good!

paulirish · 2017-10-31T23:32:44Z

lighthouse-core/audits/mainthread-work-breakdown.js

+    });
+
+    const headings = [
+      {key: 'category', itemType: 'text', text: 'Category'},


'Category' => 'Work'

paulirish · 2017-10-31T23:32:56Z

lighthouse-core/audits/mainthread-work-breakdown.js

+
+    const headings = [
+      {key: 'category', itemType: 'text', text: 'Category'},
+      {key: 'group', itemType: 'text', text: 'Task Category'},


let's have this be the first column.

'Task Category' => 'Category'

paulirish · 2017-10-31T23:57:56Z

lighthouse-core/test/audits/mainthread-work-breakdown-test.js

+    // end acceptable trace
+
+    // siteWithRedirects trace
+    artifacts = {


can you break these apart into individual it()s?

right now i want to run the middle one :))

paulirish · 2017-10-31T23:58:10Z

lighthouse-core/test/audits/mainthread-work-breakdown-test.js

+    }
+    // end load trace
+
+    done();


afaik you dont need done since this isn't async

paulirish · 2017-11-01T00:20:02Z

lighthouse-core/audits/mainthread-work-breakdown.js

+      {key: 'group', itemType: 'text', text: 'Task Category'},
+      {key: 'duration', itemType: 'text', text: 'Time spent'},
+    ];
+    const tableDetails = PageExecutionTimings.makeTableDetails(headings, results);


can you sort this data?

the bottomupbyname was already sorted by Duration so we dont need to do that, but let's sort by each group's total time spent.

so basically we'll have all the Script Evaluation work (as that will likely be the top one), with its tasks then sorted in decreasing order of time, then the rest of the groups.

before and after:

(different data)

here's the patch for all this work:

diff --git a/lighthouse-core/audits/mainthread-work-breakdown.js b/lighthouse-core/audits/mainthread-work-breakdown.js index 0dd563e4..c3fd7461 100644 --- a/lighthouse-core/audits/mainthread-work-breakdown.js +++ b/lighthouse-core/audits/mainthread-work-breakdown.js @@ -139,22 +139,31 @@ class PageExecutionTimings extends Audit { let totalExecutionTime = 0; const extendedInfo = {}; + const categoryTotals = {}; + const results = Array.from(executionTimings).map(([eventName, duration]) => { totalExecutionTime += duration; extendedInfo[eventName] = duration; + const groupName = taskToGroup[eventName]; + + const catTotal = categoryTotals[groupName] || 0; + categoryTotals[groupName] = catTotal + duration; return { category: eventName, - group: taskToGroup[eventName], + group: groupName, duration: Util.formatMilliseconds(duration, 1), }; }); const headings = [ - {key: 'category', itemType: 'text', text: 'Category'}, - {key: 'group', itemType: 'text', text: 'Task Category'}, + {key: 'group', itemType: 'text', text: 'Category'}, + {key: 'category', itemType: 'text', text: 'Work'}, {key: 'duration', itemType: 'text', text: 'Time spent'}, ]; + + results.stableSort((a, b) => categoryTotals[b.group] - categoryTotals[a.group]); const tableDetails = PageExecutionTimings.makeTableDetails(headings, results); return {

i swear at some point ill stop editing your PRs but i enjoy them so much i want to try some things out! :) sorry!

no problem! Makes my job much easier anyway so keep editing away! 😄 💯 Also I learn different techniques so it's a win for me as well!

addyosmani · 2017-11-14T00:07:15Z

Let's get a check in on whether this is good to go from @paulirish when he returns. I believe this was good mentioned as good to land the last sprint review we completed.

addyosmani

LGTM pending sign-off from @brendankenny and @paulirish

paulirish

we're good on my end.

@brendankenny you want to take another look?

brendankenny · 2017-11-17T23:32:22Z

We should definitely prioritize #3702

brendankenny

LGTM! Excited to see this in action

wardpeet changed the title ~~feat(page-execution-timings): Audit for page-execution-timings~~ new-audit(page-execution-timings): Audit for page-execution-timings Oct 10, 2017

wardpeet force-pushed the feature/page-execution-timings branch from f1257b0 to 06b4bf8 Compare October 10, 2017 20:07

paulirish requested changes Oct 10, 2017

View reviewed changes

addyosmani mentioned this pull request Oct 11, 2017

audit: JavaScript boot-up time is high ⏱ #3105

Closed

paulirish changed the title ~~new-audit(page-execution-timings): Audit for page-execution-timings~~ new_audit(page-execution-timings): Audit for page-execution-timings Oct 11, 2017

paulirish mentioned this pull request Oct 12, 2017

feat: Page execution timings (don't merge) #1695

Closed

wardpeet added 6 commits October 13, 2017 08:15

feat(page-execution-timings): Audit for page-execution-timings

b2f6e0d

Add category group

8fbe712

Add extra timing categories

9ed9d5d

Review changes

36a6848

Add unit test from trace

2e0f830

wardpeet force-pushed the feature/page-execution-timings branch from ce147f2 to 7c99f86 Compare October 13, 2017 15:14

Review fixes & unit tests

b1d5507

wardpeet force-pushed the feature/page-execution-timings branch from 7c99f86 to b1d5507 Compare October 13, 2017 15:18

Remove test config

475b7f9

patrickhulce reviewed Oct 13, 2017

View reviewed changes

Use readFileSync instead of async

aa89302

Fix spelling mistake

5fbff87

paulirish modified the milestones: Sprint Uno: Oct 2-13, Sprint Dos: Oct 16-27 Oct 16, 2017

paulirish added the waiting4review label Oct 17, 2017

brendankenny suggested changes Oct 18, 2017

View reviewed changes

devtools-bot added waiting4reviewer and removed waiting4committer labels Oct 19, 2017

Add more traces

6c99af6

paulirish modified the milestones: Sprint Dos: Oct 16-27, Sprint Tres: Oct 30 - Nov 12 Oct 30, 2017

paulirish self-assigned this Oct 31, 2017

brendankenny changed the title ~~new_audit(page-execution-timings): Audit for page-execution-timings~~ new_audit(mainthread-work-breakdown): Audit for page-execution-timings Oct 31, 2017

paulirish mentioned this pull request Oct 31, 2017

Stop DevtoolsTimelineModel from mutating trace; move to computed artifact #3702

Closed

paulirish reviewed Nov 1, 2017

View reviewed changes

paulirish added waiting4committer and removed waiting4reviewer labels Nov 1, 2017

wardpeet added 2 commits November 3, 2017 14:32

Apply paul's patch

f8a8fb2

Fix unit tests

be50e65

wardpeet added waiting4reviewer and removed waiting4committer labels Nov 6, 2017

vinamratasingal-zz modified the milestones: Sprint Tres: Oct 30 - Nov 12, Sprint Quatro: November 13-26 Nov 13, 2017

addyosmani approved these changes Nov 14, 2017

View reviewed changes

paulirish approved these changes Nov 16, 2017

View reviewed changes

Merge branch 'master' into feature/page-execution-timings

836f756

GoogleChrome deleted a comment from googlebot Nov 17, 2017

paulirish assigned brendankenny and unassigned paulirish Nov 17, 2017

brendankenny approved these changes Nov 17, 2017

View reviewed changes

brendankenny merged commit 2a4f6bf into master Nov 17, 2017

brendankenny deleted the feature/page-execution-timings branch November 17, 2017 23:33

ghost mentioned this pull request Dec 17, 2017

Update lighthouse in / from 2.5.0 to 2.7.0 chauncey-garrett/dotfiles#57

Open

paulirish removed the waiting4reviewer label Mar 6, 2018

Conversation

wardpeet commented Oct 10, 2017

Uh oh!

wardpeet commented Oct 10, 2017

Uh oh!

wardpeet commented Oct 10, 2017 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

wardpeet commented Oct 10, 2017

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

wardpeet Oct 12, 2017 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

wardpeet commented Oct 14, 2017

Uh oh!

benschwarz commented Oct 14, 2017

Uh oh!

wardpeet commented Oct 16, 2017

Uh oh!

brendankenny left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

paulirish Oct 18, 2017 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

paulirish left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

wardpeet commented Oct 10, 2017 •

edited

Loading

wardpeet Oct 12, 2017 •

edited

Loading

paulirish Oct 18, 2017 •

edited

Loading

wardpeet Nov 3, 2017 •

edited

Loading

addyosmani commented Nov 14, 2017 •

edited

Loading