new_audit(bootup-time): Bootup time per script #3563

wardpeet · 2017-10-14T15:07:40Z

show bootup time per script

Fixes part of #3105

wardpeet · 2017-10-14T16:03:03Z

Devtools is not giving me parse time of scripts :(
I can look in the trace for v8.parseOnBackground?

Also when scripts are not moved to v8.parseOnBackground than I can't seem to find any parse event.

any idea @paulirish ?

paulirish

generally the correct model, but some small suggestions. holler on IM if you have questions

paulirish · 2017-10-16T17:45:57Z

lighthouse-core/audits/bootup-time.js

+    const timelineModel = new DevtoolsTimelineModel(trace);
+    const bottomUpByName = timelineModel.bottomUpGroupBy('URL');
+    const result = new Map();
+    bottomUpByName.children.forEach((value, url) => {


a bit of bikeshedding?

value ==> perUrlNode ?

paulirish · 2017-10-16T18:03:54Z

lighthouse-core/audits/bootup-time.js

+        return;
+      }
+
+      const evaluateTime = value.children.get('EvaluateScript:@' + url) || {};


we could do this but i'd rather iterate over the perUrlNode children (which would be perTaskPerUrlNode i guess)...

so iterate over them.. then grab perTaskPerUrlNode.event.name. This should give you v8.compile and EvaluateScript. We can then reuse this stuff:

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

Lines 17 to 98 in 5fbff87

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,

};

and we'll want any children with events of name in the 3 script*categories. (also note: many of those task names are for instant events so they have 0 duration. ;)

we can exclude GC from the report for now but might as well collect it here and put in extInfo ? or ignore it and leave a comment saying so..

paulirish · 2017-10-17T01:29:18Z

Also when scripts are not moved to v8.parseOnBackground than I can't seem to find any parse event.

perhaps they are on a different thread? (tid)? that would usually exclude them.

wardpeet · 2017-10-17T04:49:52Z

perhaps they are on a different thread? (tid)? that would usually exclude them.
yes indeed, not on the main thread which is good but should I also try to include it in the report?

Not all scripts are parsed on the parser thread (only the once that have async/defer). When they're not it seems like there is no parse time registered in the trace, it's probably included in compile time of the script?

patrickhulce · 2017-10-17T16:45:48Z

lighthouse-core/audits/bootup-time.js

+    const tableDetails = BootupTime.makeTableDetails(headings, results);
+
+    return {
+      score: totalBootupTime < 4000,


4s is quite generous, did we consider using a numeric instead of binary score to allow nuance?

patrickhulce · 2017-10-17T16:46:58Z

lighthouse-core/audits/bootup-time.js

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


are we doing this in a lot of places/should it be a computed artifact?

Are you referring to make a computed artifact requestExecutionTimingsByUrl(trace) or rather have a computed artifact requestExecutionTimings(trace, 'URL')

the idea is to make DTM a computed artifact.

we were also discussing doing a deepFreeze (from https://developer.mozilla.org/en-US/docs/Web/JavaScript/Reference/Global_Objects/Object/freeze) on the trace data before sending it into devtools.

so it wont mutate.

if there are problems with this we could just deepFreeze each event in the traceEvents array. should be fine.

should i do it in this PR? or just a followup?

filed here #3702

brendankenny · 2017-10-31T20:56:07Z

lighthouse-core/audits/bootup-time.js

+const WebInspector = require('../lib/web-inspector');
+const Util = require('../report/v2/renderer/util.js');
+
+const group = {


could pull these two objects into a lib/traces/trace-event-groups.js or something so that they can be used across audits

paulirish

spoiler alert: I implemented all my suggestions in #3703

wdyt? can you review?

one of the major things is only showing the scripting categories, not every kind of task we can associate with the scriptURL. that means our header array is now fixed.

paulirish · 2017-10-31T22:28:03Z

lighthouse-core/test/audits/bootup-time-test.js

+    assert.equal(Math.round(output.rawValue), 176);
+
+    const valueOf = name => output.extendedInfo.value[name];
+    assert.deepEqual(valueOf('https://www.google-analytics.com/analytics.js'), {'Evaluate Script': 40.1, 'Compile Script': 9.6, 'Recalculate Style': 0.2});


It was kind of confusing that our extendedInfo reported tasks, but the UI reported taskGroups. I don't have a strong opinion on what should be exposed in extendedInfo. Maybe we just leave extendedInfo empty this time? In the tests we could assert against the table details instead.

it might be confusing indeed but isn't it handy to show the raw information somewhere in the json report so people who want to use it can use it? Or isn't that why extendedInfo exists?

paulirish · 2017-10-31T22:34:27Z

lighthouse-core/audits/bootup-time.js

+    ];
+
+    // Group tasks per url
+    const groupsPerUrl = Array.from(bootupTimings).map(([url, durations]) => {


this loop groups individual tasks into taskGroups. I figured this could be a lot simpler if we just do the same thing up inside the inner getExecutionTimingsByURL loop. that's what you'll see in #3703

paulirish · 2017-10-31T22:35:28Z

lighthouse-core/audits/bootup-time.js

+      perUrlNode.children.forEach((perTaskPerUrlNode) => {
+        const taskGroup = WebInspector.TimelineUIUtils.eventStyle(perTaskPerUrlNode.event);
+        tasks[taskGroup.title] = tasks[taskGroup.title] || 0;
+        tasks[taskGroup.title] += Number((perTaskPerUrlNode.selfTime || 0).toFixed(1));


i felt weird about this rounding here as we're summing, so i moved it to outside of the loop.

paulirish · 2017-10-31T22:35:42Z

lighthouse-core/audits/bootup-time.js

+   */
+  static getExecutionTimingsByURL(trace) {
+    const timelineModel = new DevtoolsTimelineModel(trace);
+    const bottomUpByName = timelineModel.bottomUpGroupBy('URL');


bottomUpByURL

paulirish · 2017-11-16T08:10:49Z

I own landing this now. No more work needed from you, @wardpeet. :)

Still need a little more work on #3703 then we're good with both.

wardpeet added 2 commits October 14, 2017 16:54

Add bootup-time audit

062d826

Add unit tests for bootup-time

965b960

paulirish reviewed Oct 16, 2017

View reviewed changes

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

patrickhulce reviewed Oct 17, 2017

View reviewed changes

paulirish added the waiting4committer label Oct 17, 2017

wardpeet requested a review from brendankenny as a code owner October 21, 2017 12:46

wardpeet added 4 commits October 21, 2017 15:32

Review fixes

e619d86

Updated unit tests

cf47eaf

Remove test-config

a824a66

Fix linting

8ec5fb3

wardpeet force-pushed the feature/bootup-time branch from bb663e2 to 8ec5fb3 Compare October 21, 2017 13:33

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

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 reviewed Oct 31, 2017

View reviewed changes

paulirish mentioned this pull request Oct 31, 2017

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

Closed

paulirish requested changes Oct 31, 2017

View reviewed changes

paulirish added waiting4committer and removed waiting4reviewer labels Nov 1, 2017

Remove . from failuredescription

b30bc13

devtools-bot 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

paulirish merged commit 05cea61 into master Nov 17, 2017

brendankenny deleted the feature/bootup-time branch November 17, 2017 21:31

dependencies bot 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

paulirish mentioned this pull request Mar 9, 2018

RFC: V8 Performance Insights #1158

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

new_audit(bootup-time): Bootup time per script #3563

new_audit(bootup-time): Bootup time per script #3563

wardpeet commented Oct 14, 2017 •

edited

Loading

wardpeet commented Oct 14, 2017

paulirish left a comment

paulirish Oct 16, 2017

paulirish Oct 16, 2017

paulirish Oct 16, 2017

paulirish commented Oct 17, 2017

wardpeet commented Oct 17, 2017

patrickhulce Oct 17, 2017

patrickhulce Oct 17, 2017

wardpeet Oct 19, 2017

paulirish Oct 20, 2017 •

edited

Loading

wardpeet Oct 24, 2017

paulirish Nov 17, 2017

brendankenny Oct 31, 2017

paulirish left a comment

paulirish Oct 31, 2017

wardpeet Nov 3, 2017

paulirish Oct 31, 2017

paulirish Oct 31, 2017

paulirish Oct 31, 2017

paulirish commented Nov 16, 2017

	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,
	};

new_audit(bootup-time): Bootup time per script #3563

new_audit(bootup-time): Bootup time per script #3563

Conversation

wardpeet commented Oct 14, 2017 • edited Loading

wardpeet commented Oct 14, 2017

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

Choose a reason for hiding this comment

paulirish commented Oct 17, 2017

wardpeet commented Oct 17, 2017

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

paulirish Oct 20, 2017 • edited Loading

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

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

paulirish commented Nov 16, 2017

wardpeet commented Oct 14, 2017 •

edited

Loading

paulirish Oct 20, 2017 •

edited

Loading