diff --git a/lighthouse-cli/test/fixtures/tricky-main-thread-consumer.js b/lighthouse-cli/test/fixtures/tricky-main-thread-consumer.js new file mode 100644 index 000000000000..f233672fe338 --- /dev/null +++ b/lighthouse-cli/test/fixtures/tricky-main-thread-consumer.js @@ -0,0 +1,20 @@ +/** + * @license Copyright 2019 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'; + +/* eslint-disable */ + +if (window.location.search.includes('setTimeout')) { + window.library.setTimeout(() => { + window.library.stall(3050); + }, 0); +} + +if (window.location.search.includes('fetch')) { + window.library.fetch('http://localhost:10200/tricky-main-thread.html').then(() => { + window.library.stall(3050); + }); +} diff --git a/lighthouse-cli/test/fixtures/tricky-main-thread-library.js b/lighthouse-cli/test/fixtures/tricky-main-thread-library.js new file mode 100644 index 000000000000..a8cc4a3dd01d --- /dev/null +++ b/lighthouse-cli/test/fixtures/tricky-main-thread-library.js @@ -0,0 +1,37 @@ +/** + * @license Copyright 2019 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'; + +/* eslint-disable */ + +window.library = {}; +window.library.setTimeout = (fn, time) => { + setTimeout(() => { + window.library.stall(50); + console.log('Custom timeout hook'); + fn(); + }, time); +}; + +window.library.fetch = (...args) => { + console.log('Custom fetch hook 1'); + return fetch(...args).then(response => { + console.log('Custom fetch hook 2'); + window.library.stall(50); + return response; + }); +}; + +/** + * Stalls the main thread for timeInMs + */ +window.library.stall = function(timeInMs) { + const start = performance.now(); + while (performance.now() - start < timeInMs) { + for (let i = 0; i < 1000000; i++) ; + } +}; + diff --git a/lighthouse-cli/test/fixtures/tricky-main-thread.html b/lighthouse-cli/test/fixtures/tricky-main-thread.html new file mode 100644 index 000000000000..6238a0df59b3 --- /dev/null +++ b/lighthouse-cli/test/fixtures/tricky-main-thread.html @@ -0,0 +1,8 @@ + + + + Just try and figure out my scripts + + + + diff --git a/lighthouse-cli/test/smokehouse/tricky-metrics/expectations.js b/lighthouse-cli/test/smokehouse/tricky-metrics/expectations.js index 07d165fcc17b..8a67e4228b87 100644 --- a/lighthouse-cli/test/smokehouse/tricky-metrics/expectations.js +++ b/lighthouse-cli/test/smokehouse/tricky-metrics/expectations.js @@ -6,7 +6,7 @@ 'use strict'; /** - * Expected Lighthouse audit values for tricky TTI tests + * Expected Lighthouse audit values for tricky metrics tests */ module.exports = [ { @@ -32,4 +32,37 @@ module.exports = [ }, }, }, + { + requestedUrl: 'http://localhost:10200/tricky-main-thread.html?setTimeout', + finalUrl: 'http://localhost:10200/tricky-main-thread.html?setTimeout', + audits: { + 'bootup-time': { + details: { + items: { + 0: { + url: /main-thread-consumer/, + scripting: '>1000', + }, + }, + }, + }, + }, + }, + { + requestedUrl: 'http://localhost:10200/tricky-main-thread.html?fetch', + finalUrl: 'http://localhost:10200/tricky-main-thread.html?fetch', + audits: { + 'bootup-time': { + details: { + items: { + 0: { + // TODO: requires async stacks, https://github.com/GoogleChrome/lighthouse/pull/5504 + // url: /main-thread-consumer/, + scripting: '>1000', + }, + }, + }, + }, + }, + }, ]; diff --git a/lighthouse-core/audits/bootup-time.js b/lighthouse-core/audits/bootup-time.js index 1c74d3ac0141..3891f717dfb9 100644 --- a/lighthouse-core/audits/bootup-time.js +++ b/lighthouse-core/audits/bootup-time.js @@ -22,7 +22,7 @@ const UIStrings = { 'You may find delivering smaller JS payloads helps with this. [Learn ' + 'more](https://developers.google.com/web/tools/lighthouse/audits/bootup).', /** Label for the total time column in a data table; entries will be the number of milliseconds spent executing per resource loaded by the page. */ - columnTotal: 'Total', + columnTotal: 'Total CPU Time', /** Label for a time column in a data table; entries will be the number of milliseconds spent evaluating script for every script loaded by the page. */ columnScriptEval: 'Script Evaluation', /** Label for a time column in a data table; entries will be the number of milliseconds spent parsing script files for every script loaded by the page. */ @@ -89,8 +89,9 @@ class BootupTime extends Audit { for (const task of tasks) { const jsURL = task.attributableURLs.find(url => jsURLs.has(url)); const fallbackURL = task.attributableURLs[0]; - const attributableURL = jsURL || fallbackURL; - if (!attributableURL || attributableURL === 'about:blank') continue; + let attributableURL = jsURL || fallbackURL; + // If we can't find what URL was responsible for this execution, just attribute it to the root page. + if (!attributableURL || attributableURL === 'about:blank') attributableURL = 'Other'; const timingByGroupId = result.get(attributableURL) || {}; const originalTime = timingByGroupId[task.group.id] || 0; @@ -122,27 +123,27 @@ class BootupTime extends Audit { let totalBootupTime = 0; const results = Array.from(executionTimings) .map(([url, timingByGroupId]) => { - // Add up the totalBootupTime for all the taskGroups - let bootupTimeForURL = 0; + // Add up the totalExecutionTime for all the taskGroups + let totalExecutionTimeForURL = 0; for (const [groupId, timespanMs] of Object.entries(timingByGroupId)) { timingByGroupId[groupId] = timespanMs * multiplier; - bootupTimeForURL += timespanMs * multiplier; - } - - // Add up all the execution time of shown URLs - if (bootupTimeForURL >= context.options.thresholdInMs) { - totalBootupTime += bootupTimeForURL; + totalExecutionTimeForURL += timespanMs * multiplier; } const scriptingTotal = timingByGroupId[taskGroups.scriptEvaluation.id] || 0; const parseCompileTotal = timingByGroupId[taskGroups.scriptParseCompile.id] || 0; + // Add up all the JavaScript time of shown URLs + if (totalExecutionTimeForURL >= context.options.thresholdInMs) { + totalBootupTime += scriptingTotal + parseCompileTotal; + } + hadExcessiveChromeExtension = hadExcessiveChromeExtension || (url.startsWith('chrome-extension:') && scriptingTotal > 100); return { url: url, - total: bootupTimeForURL, + total: totalExecutionTimeForURL, // Highlight the JavaScript task costs scripting: scriptingTotal, scriptParseCompile: parseCompileTotal, diff --git a/lighthouse-core/computed/main-thread-tasks.js b/lighthouse-core/computed/main-thread-tasks.js index 5b18eb33b1c5..e66eab62cdbd 100644 --- a/lighthouse-core/computed/main-thread-tasks.js +++ b/lighthouse-core/computed/main-thread-tasks.js @@ -41,6 +41,8 @@ const TraceOfTab = require('./trace-of-tab.js'); * @prop {TaskGroup} group */ +/** @typedef {{timers: Map}} PriorTaskData */ + class MainThreadTasks { /** * @param {LH.TraceEvent} event @@ -71,15 +73,24 @@ class MainThreadTasks { /** * @param {LH.TraceEvent[]} mainThreadEvents + * @param {PriorTaskData} priorTaskData * @return {TaskNode[]} */ - static _createTasksFromEvents(mainThreadEvents) { + static _createTasksFromEvents(mainThreadEvents, priorTaskData) { /** @type {TaskNode[]} */ const tasks = []; /** @type {TaskNode|undefined} */ let currentTask; for (const event of mainThreadEvents) { + // Save the timer data, TimerInstall events are instant events `ph === 'I'` so process them first. + if (event.name === 'TimerInstall' && currentTask) { + /** @type {string} */ + // @ts-ignore - timerId exists when name is TimerInstall + const timerId = event.args.data.timerId; + priorTaskData.timers.set(timerId, currentTask); + } + // Only look at X (Complete), B (Begin), and E (End) events as they have most data if (event.ph !== 'X' && event.ph !== 'B' && event.ph !== 'E') continue; @@ -141,11 +152,13 @@ class MainThreadTasks { /** * @param {TaskNode} task * @param {string[]} parentURLs + * @param {PriorTaskData} priorTaskData */ - static _computeRecursiveAttributableURLs(task, parentURLs) { + static _computeRecursiveAttributableURLs(task, parentURLs, priorTaskData) { const argsData = task.event.args.data || {}; const stackFrameURLs = (argsData.stackTrace || []).map(entry => entry.url); + /** @type {Array} */ let taskURLs = []; switch (task.event.name) { /** @@ -161,6 +174,15 @@ class MainThreadTasks { case 'v8.compileModule': taskURLs = [task.event.args.fileName].concat(stackFrameURLs); break; + case 'TimerFire': { + /** @type {string} */ + // @ts-ignore - timerId exists when name is TimerFire + const timerId = task.event.args.data.timerId; + const timerInstallerTaskNode = priorTaskData.timers.get(timerId); + if (!timerInstallerTaskNode) break; + taskURLs = timerInstallerTaskNode.attributableURLs.concat(stackFrameURLs); + break; + } default: taskURLs = stackFrameURLs; break; @@ -178,7 +200,7 @@ class MainThreadTasks { task.attributableURLs = attributableURLs; task.children.forEach(child => - MainThreadTasks._computeRecursiveAttributableURLs(child, attributableURLs)); + MainThreadTasks._computeRecursiveAttributableURLs(child, attributableURLs, priorTaskData)); } /** @@ -196,14 +218,16 @@ class MainThreadTasks { * @return {TaskNode[]} */ static getMainThreadTasks(traceEvents) { - const tasks = MainThreadTasks._createTasksFromEvents(traceEvents); + const timers = new Map(); + const priorTaskData = {timers}; + const tasks = MainThreadTasks._createTasksFromEvents(traceEvents, priorTaskData); // Compute the recursive properties we couldn't compute earlier, starting at the toplevel tasks for (const task of tasks) { if (task.parent) continue; MainThreadTasks._computeRecursiveSelfTime(task); - MainThreadTasks._computeRecursiveAttributableURLs(task, []); + MainThreadTasks._computeRecursiveAttributableURLs(task, [], priorTaskData); MainThreadTasks._computeRecursiveTaskGroup(task); } diff --git a/lighthouse-core/lib/i18n/en-US.json b/lighthouse-core/lib/i18n/en-US.json index e0d76a9b7875..020a7576f368 100644 --- a/lighthouse-core/lib/i18n/en-US.json +++ b/lighthouse-core/lib/i18n/en-US.json @@ -432,7 +432,7 @@ "description": "Label for a time column in a data table; entries will be the number of milliseconds spent parsing script files for every script loaded by the page." }, "lighthouse-core/audits/bootup-time.js | columnTotal": { - "message": "Total", + "message": "Total CPU Time", "description": "Label for the total time column in a data table; entries will be the number of milliseconds spent executing per resource loaded by the page." }, "lighthouse-core/audits/bootup-time.js | description": { diff --git a/lighthouse-core/test/audits/bootup-time-test.js b/lighthouse-core/test/audits/bootup-time-test.js index ca240f3abd06..a91cb3be5e22 100644 --- a/lighthouse-core/test/audits/bootup-time-test.js +++ b/lighthouse-core/test/audits/bootup-time-test.js @@ -32,12 +32,13 @@ describe('Performance: bootup-time audit', () => { return BootupTime.audit(artifacts, {options: auditOptions, computedCache}).then(output => { assert.deepEqual(roundedValueOf(output, 'https://pwa.rocks/script.js'), {scripting: 31.8, scriptParseCompile: 1.3, total: 36.8}); - assert.deepEqual(roundedValueOf(output, 'https://www.googletagmanager.com/gtm.js?id=GTM-Q5SW'), {scripting: 96.9, scriptParseCompile: 6.5, total: 104.4}); + assert.deepEqual(roundedValueOf(output, 'https://www.googletagmanager.com/gtm.js?id=GTM-Q5SW'), {scripting: 97.2, scriptParseCompile: 6.5, total: 104.7}); assert.deepEqual(roundedValueOf(output, 'https://www.google-analytics.com/plugins/ua/linkid.js'), {scripting: 25.2, scriptParseCompile: 1.2, total: 26.4}); assert.deepEqual(roundedValueOf(output, 'https://www.google-analytics.com/analytics.js'), {scripting: 40.6, scriptParseCompile: 9.6, total: 53.4}); + assert.deepEqual(roundedValueOf(output, 'Other'), {scripting: 11.7, scriptParseCompile: 0, total: 1123.8}); // eslint-disable-line max-len - assert.equal(Math.round(output.rawValue), 221); - assert.equal(output.details.items.length, 4); + assert.equal(Math.round(output.rawValue), 225); + assert.equal(output.details.items.length, 5); assert.equal(output.score, 1); }); }, 10000); @@ -55,9 +56,9 @@ describe('Performance: bootup-time audit', () => { assert.deepEqual(roundedValueOf(output, 'https://pwa.rocks/script.js'), {scripting: 95.3, scriptParseCompile: 3.9, total: 110.5}); - assert.equal(output.details.items.length, 7); + assert.equal(output.details.items.length, 8); assert.equal(output.score, 0.98); - assert.equal(Math.round(output.rawValue), 709); + assert.equal(Math.round(output.rawValue), 720); }); it('should get no data when no events are present', () => { diff --git a/lighthouse-core/test/results/sample_v2.json b/lighthouse-core/test/results/sample_v2.json index b47b0931de26..0fcfd0576260 100644 --- a/lighthouse-core/test/results/sample_v2.json +++ b/lighthouse-core/test/results/sample_v2.json @@ -689,7 +689,7 @@ "description": "Consider reducing the time spent parsing, compiling, and executing JS. You may find delivering smaller JS payloads helps with this. [Learn more](https://developers.google.com/web/tools/lighthouse/audits/bootup).", "score": 0.92, "scoreDisplayMode": "numeric", - "rawValue": 1150.932, + "rawValue": 1150.573, "displayValue": "1.2 s", "details": { "type": "table", @@ -703,7 +703,7 @@ "key": "total", "granularity": 1, "itemType": "ms", - "text": "Total" + "text": "Total CPU Time" }, { "key": "scripting", @@ -725,6 +725,12 @@ "scripting": 957.494, "scriptParseCompile": 2.777 }, + { + "url": "Other", + "total": 391.76699999999977, + "scripting": 17.790999999999997, + "scriptParseCompile": 0.092 + }, { "url": "http://localhost:10200/zone.js", "total": 101.21099999999998, @@ -739,7 +745,7 @@ } ], "summary": { - "wastedMs": 1150.932 + "wastedMs": 1150.573 } } }, @@ -4437,7 +4443,7 @@ }, { "values": { - "timeInMs": 1150.932 + "timeInMs": 1150.573 }, "path": "audits[bootup-time].displayValue" } diff --git a/proto/sample_v2_round_trip.json b/proto/sample_v2_round_trip.json index fa934a87a3a3..6206919c8fa5 100644 --- a/proto/sample_v2_round_trip.json +++ b/proto/sample_v2_round_trip.json @@ -84,7 +84,7 @@ "granularity": 1.0, "itemType": "ms", "key": "total", - "text": "Total" + "text": "Total CPU Time" }, { "granularity": 1.0, @@ -106,6 +106,12 @@ "total": 966.9800000000001, "url": "http://localhost:10200/dobetterweb/dbw_tester.html" }, + { + "scriptParseCompile": 0.092, + "scripting": 17.790999999999997, + "total": 391.76699999999977, + "url": "Other" + }, { "scriptParseCompile": 1.674, "scripting": 89.50799999999998, @@ -120,7 +126,7 @@ } ], "summary": { - "wastedMs": 1150.932 + "wastedMs": 1150.573 }, "type": "table" },