From 83657dceff1d5275c36cc0eb5d66622ca769933e Mon Sep 17 00:00:00 2001 From: anthony Date: Tue, 26 Jan 2016 12:04:18 -0500 Subject: [PATCH 1/7] Show BHR child hangs in Statuser. --- data/panel.html | 5 +- data/panel.js | 13 +- index.js | 377 +++++++++++++++++++++++++++++------------------- 3 files changed, 240 insertions(+), 155 deletions(-) diff --git a/data/panel.html b/data/panel.html index bff6810..fa506b3 100644 --- a/data/panel.html +++ b/data/panel.html @@ -54,6 +54,9 @@ color: white; z-index: 1; } + .childHang .controls { + background: #5555AA; + } .controls .duration { font-size: 12px; } @@ -127,6 +130,6 @@

MOST RECENT HANGS

--> -

Hang uptimes correspond to the X axis in the Gecko Profiler addon timeline.

+

Entries with a grey sidebar are parent process hangs, while entries with a blue sidebar are child process hangs. Hang uptimes correspond to the X axis in the Gecko Profiler addon timeline.

\ No newline at end of file diff --git a/data/panel.js b/data/panel.js index ab84cd0..9d3e9dc 100644 --- a/data/panel.js +++ b/data/panel.js @@ -53,16 +53,20 @@ self.port.on("warning", function(warningType) { case null: banner.style.display = "none"; break; + case "unavailableChildBHR": + banner.innerHTML = "CHILD PROCESS BACKGROUND HANG REPORTING UNAVAILABLE; CHECK FIREFOX VERSION, ENABLE BHR, AND RESTART FIREFOX"; + banner.style.display = "block"; + break; case "unavailableBHR": - banner.innerHTML = "BACKGROUND HANG REPORTING UNAVAILABLE; ENABLE BHR AND RESTART FIREFOX"; + banner.innerHTML = "BACKGROUND HANG REPORTING UNAVAILABLE; CHECK FIREFOX VERSION, ENABLE BHR, AND RESTART FIREFOX"; banner.style.display = "block"; break; case "unavailableEventLoopLags": - banner.innerHTML = "EVENTLOOP_UI_ACTIVITY_EXP_MS HISTOGRAM UNAVAILABLE; CHECK FIREFOX VERSION"; + banner.innerHTML = "EVENTLOOP_UI_ACTIVITY_EXP_MS HISTOGRAM UNAVAILABLE; CHECK FIREFOX VERSION AND ENABLE TELEMETRY"; banner.style.display = "block"; break; case "unavailableInputEventResponseLags": - banner.innerHTML = "INPUT_EVENT_RESPONSE_MS HISTOGRAM UNAVAILABLE; CHECK FIREFOX VERSION"; + banner.innerHTML = "INPUT_EVENT_RESPONSE_MS HISTOGRAM UNAVAILABLE; CHECK FIREFOX VERSION AND ENABLE TELEMETRY"; banner.style.display = "block"; break; default: @@ -78,6 +82,9 @@ function setHangs(hangs) { hangs.reverse().forEach(hang => { // create an entry for the hang var entry = document.createElement("div"); + if (hang.isChild) { + entry.className = "childHang"; + } var contents = document.createElement("pre"); contents.className = "stack"; contents.appendChild(document.createTextNode(hang.stack)); diff --git a/index.js b/index.js index 93b7811..bcfc421 100644 --- a/index.js +++ b/index.js @@ -3,9 +3,14 @@ var ss = require("sdk/simple-storage"); var clipboard = require("sdk/clipboard"); var windowUtils = require("sdk/window/utils"); +const {Cc, Ci, Cu} = require("chrome"); +Cu.import("resource://gre/modules/Services.jsm"); +Cu.import("resource://gre/modules/TelemetrySession.jsm"); +let gOS = Cc["@mozilla.org/observer-service;1"].getService(Ci.nsIObserverService); + // load and validate settings var gMode = ss.storage.mode; -if (gMode !== "threadHangs" && gMode !== "eventLoopLags" && gMode !== "inputEventResponseLags") { +if (["threadHangs", "eventLoopLags", "inputEventResponseLags"].indexOf(gMode) < 0) { gMode = "threadHangs"; } var gPlaySound = ss.storage.playSound; @@ -17,9 +22,10 @@ if (typeof gHangThreshold !== "number" || gHangThreshold < 1) { gHangThreshold = 126; } -const { setInterval } = require("sdk/timers"); +const { setTimeout } = require("sdk/timers"); const { ActionButton } = require("sdk/ui/button/action"); +// define all the SVG icons const ANIMATE_TEMPLATE = ''; const ANIMATE_ROTATE_SVG = '' + ' { resolve(cachedPreviousChildHangs); }); + } + lastChildHangsRetrievedTime = Date.now(); + return TelemetrySession.getChildThreadHangs().then((hangs) => { + cachedPreviousChildHangs = hangs; + return hangs; + }); +} + // returns the number of Gecko hangs, and the computed minimum threshold for those hangs (which is a value >= gHangThreshold) -function numGeckoHangs() { - var hangs; +function getHangs() { switch(gMode) { case "threadHangs": - hangs = numGeckoThreadHangs(); - panel.port.emit("warning", hangs === null ? "unavailableBHR" : null); - return hangs + return numGeckoThreadHangs(); case "eventLoopLags": - hangs = numEventLoopLags(); - panel.port.emit("warning", hangs === null ? "unavailableEventLoopLags" : null); - return hangs; + return numEventLoopLags(); case "inputEventResponseLags": - hangs = numInputEventResponseLags(); - panel.port.emit("warning", hangs === null ? "unavailableInputEventResponseLags" : null); - return hangs; + return numInputEventResponseLags(); default: console.warn("Unknown mode: ", gMode); - return {numHangs: null, minBucketLowerBound: 0}; + return new Promise((resolve) => { + resolve({numHangs: null, minBucketLowerBound: 0}); + }); } } -function numGeckoThreadHangs() { - let geckoThread = Services.telemetry.threadHangStats.find(thread => - thread.name == "Gecko" - ); +function numGeckoThreadHangs(includeChildHangs = true) { + if (includeChildHangs && !TelemetrySession.getChildThreadHangs) { + panel.port.emit("warning", "unavailableChildBHR"); + return new Promise((resolve) => { resolve({numHangs: null, minBucketLowerBound: 0}); }); + } + + let geckoThread = Services.telemetry.threadHangStats.find(thread => thread.name == "Gecko"); if (!geckoThread || !geckoThread.activity.counts) { - console.warn("Lolwhut? No Gecko thread? No hangs?"); - return {numHangs: null, minBucketLowerBound: 0}; + panel.port.emit("warning", "unavailableBHR"); + return new Promise((resolve) => { resolve({numHangs: null, minBucketLowerBound: 0}); }); } - // see the NOTE in mostRecentHangs() for caveats when using the activity.counts histogram - // to summarize, the ranges are the inclusive upper bound of the histogram rather than the inclusive lower bound - let numHangs = 0; - let minBucketLowerBound = Infinity; - geckoThread.activity.counts.forEach((count, i) => { - var lowerBound = geckoThread.activity.ranges[i - 1] + 1; - if (lowerBound >= gHangThreshold) { - numHangs += count; - minBucketLowerBound = Math.min(minBucketLowerBound, lowerBound); + + return new Promise((resolve) => { + if (includeChildHangs) { + getChildThreadHangs().then((hangs) => { + // accumulate all of the counts in the child processes with the counts in the parent process + let counts = geckoThread.activity.counts.slice(0); + hangs.forEach((threadHangStats) => { + let childGeckoThread = threadHangStats.find(thread => thread.name == "Gecko_Child"); + if (childGeckoThread && childGeckoThread.activity.counts) { + childGeckoThread.activity.counts.forEach((count, i) => { counts[i] += count; }); + } + }); + resolve(counts); + }); + } else { // Just use the parent process stats + resolve(geckoThread.activity.counts); } + }).then((counts) => { + // see the NOTE in mostRecentHangs() for caveats when using the activity.counts histogram + // to summarize, the ranges are the inclusive upper bound of the histogram rather than the inclusive lower bound + let numHangs = 0; + let minBucketLowerBound = Infinity; + counts.forEach((count, i) => { + var lowerBound = geckoThread.activity.ranges[i - 1] + 1; + if (lowerBound >= gHangThreshold) { + numHangs += count; + minBucketLowerBound = Math.min(minBucketLowerBound, lowerBound); + } + }); + panel.port.emit("warning", null); + return {numHangs: numHangs, minBucketLowerBound: minBucketLowerBound}; }); - return {numHangs: numHangs, minBucketLowerBound: minBucketLowerBound}; } function numEventLoopLags() { - try { - var snapshot = Services.telemetry.getHistogramById("EVENTLOOP_UI_ACTIVITY_EXP_MS").snapshot(); - } catch (e) { // histogram doesn't exist, the Firefox version is likely older than 45.0a1 - return {numHangs: null, minBucketLowerBound: 0}; - } - let numHangs = 0; - let minBucketLowerBound = Infinity; - for (let i = 0; i < snapshot.ranges.length; ++i) { - if (snapshot.ranges[i] >= gHangThreshold) { - numHangs += snapshot.counts[i]; - minBucketLowerBound = Math.min(minBucketLowerBound, snapshot.ranges[i]); + return new Promise((resolve) => { + try { + var snapshot = Services.telemetry.getHistogramById("EVENTLOOP_UI_ACTIVITY_EXP_MS").snapshot(); + } catch (e) { // histogram doesn't exist, the Firefox version is likely older than 45.0a1 + panel.port.emit("warning", "unavailableEventLoopLags"); + resolve({numHangs: null, minBucketLowerBound: 0}); } - } - return {numHangs: numHangs, minBucketLowerBound: minBucketLowerBound}; + let numHangs = 0; + let minBucketLowerBound = Infinity; + for (let i = 0; i < snapshot.ranges.length; ++i) { + if (snapshot.ranges[i] >= gHangThreshold) { + numHangs += snapshot.counts[i]; + minBucketLowerBound = Math.min(minBucketLowerBound, snapshot.ranges[i]); + } + } + panel.port.emit("warning", null); + resolve({numHangs: numHangs, minBucketLowerBound: minBucketLowerBound}); + }); } function numInputEventResponseLags() { - try { - var snapshot = Services.telemetry.getHistogramById("INPUT_EVENT_RESPONSE_MS").snapshot(); - } catch (e) { // histogram doesn't exist, the Firefox version is likely older than 46.0a1 - return {numHangs: null, minBucketLowerBound: 0}; - } - let numHangs = 0; - let minBucketLowerBound = Infinity; - for (let i = 0; i < snapshot.ranges.length; ++i) { - if (snapshot.ranges[i] > gHangThreshold) { - result += snapshot.counts[i]; - minBucketLowerBound = Math.min(minBucketLowerBound, snapshot.ranges[i]); + return new Promise((resolve) => { + try { + var snapshot = Services.telemetry.getHistogramById("INPUT_EVENT_RESPONSE_MS").snapshot(); + } catch (e) { // histogram doesn't exist, the Firefox version is likely older than 46.0a1 + panel.port.emit("warning", "unavailableInputEventResponseLags"); + resolve({numHangs: null, minBucketLowerBound: 0}); } + let numHangs = 0; + let minBucketLowerBound = Infinity; + for (let i = 0; i < snapshot.ranges.length; ++i) { + if (snapshot.ranges[i] > gHangThreshold) { + result += snapshot.counts[i]; + minBucketLowerBound = Math.min(minBucketLowerBound, snapshot.ranges[i]); + } + } + panel.port.emit("warning", null); + resolve({numHangs: numHangs, minBucketLowerBound: minBucketLowerBound}); + }); +} + +// Returns an array of the most recent BHR hangs +var previousCountsMap = {}; // this is a mapping from stack traces (as strings) to corresponding histogram counts +var cachedRecentHangs = []; +let lastMostRecentHangsTime = getUptime(); +function mostRecentHangs(includeChildHangs = true) { + if (includeChildHangs && !TelemetrySession.getChildThreadHangs) { + return new Promise((resolve) => { resolve({numHangs: null, minBucketLowerBound: 0}); }); + } + + let geckoThread = Services.telemetry.threadHangStats.find(thread => thread.name == "Gecko"); + if (!geckoThread || !geckoThread.activity.counts) { + return new Promise((resolve) => { resolve({numHangs: null, minBucketLowerBound: 0}); }); } - return {numHangs: numHangs, minBucketLowerBound: minBucketLowerBound}; + + return new Promise((resolve) => { + if (includeChildHangs) { + getChildThreadHangs().then((hangs) => { + // accumulate all of the counts in the child processes with the counts in the parent process + let childHangEntries = []; + hangs.forEach((threadHangStats) => { + let childGeckoThread = threadHangStats.find(thread => thread.name == "Gecko_Child"); + if (childGeckoThread && childGeckoThread.activity.counts) { + childHangEntries = childHangEntries.concat(childGeckoThread.hangs); + } + }); + resolve([geckoThread.hangs, childHangEntries]); + }); + } else { // Just use the parent process stats + resolve([geckoThread.hangs, []]); + } + }).then(hangInfo => { + [hangEntries, childHangEntries] = hangInfo; + console.error(childHangEntries) + let timestamp = (new Date()).getTime(); // note that this timestamp will only be as accurate as the interval at which this function is called + let uptime = getUptime(); // this value matches the X axis in the timeline for the Gecko Profiler addon + + // diff the current hangs with the previous hangs to figure out what changed in this call, if anything + // hangs list will only ever grow: https://dxr.mozilla.org/mozilla-central/source/xpcom/threads/BackgroundHangMonitor.cpp#440 + // therefore, we only need to check current stacks against previous stacks - there is no need for a 2 way diff + // hangs are identified by their stack traces: https://dxr.mozilla.org/mozilla-central/source/toolkit/components/telemetry/Telemetry.cpp#4316 + function diffHangEntry(hangEntry, isChild) { + var stack = hangEntry.stack.slice(0).reverse().join("\n"); + var ranges = hangEntry.histogram.ranges.concat([Infinity]); + var counts = hangEntry.histogram.counts; + var previousCounts = previousCountsMap.hasOwnProperty(stack) ? previousCountsMap[stack] : []; + + // diff this hang histogram with the previous hang histogram + counts.forEach((count, i) => { + var previousCount = previousCounts[i] || 0; + /* + NOTE: when you access the thread hangs, the ranges are actually the inclusive upper bounds of the buckets rather than the inclusive lower bound like other histograms. + Basically, when we access the buckets of a TimeHistogram in JS, it has a 0 prepended to the ranges; in C++, the indices behave as all other histograms do. + + For example, bucket 7 actually represents hangs of duration 64ms to 127ms, inclusive. For most other exponential histograms, this would be 128ms to 255ms. + + References: + * mozilla::Telemetry::CreateJSTimeHistogram - http://mxr.mozilla.org/mozilla-central/source/toolkit/components/telemetry/Telemetry.cpp#2947 + * mozilla::Telemetry::TimeHistogram - http://mxr.mozilla.org/mozilla-central/source/toolkit/components/telemetry/ThreadHangStats.h#25 + */ + while (count > previousCount) { // each additional count here is a new hang with this stack and a duration in this bucket's range + let lowerBound = ranges[i - 1] + 1; + if (lowerBound >= gHangThreshold) { + cachedRecentHangs.push({ + stack: stack, lowerBound: lowerBound, upperBound: ranges[i], + timestamp: timestamp, uptime: uptime, previousUptime: lastMostRecentHangsTime, + isChild: isChild, + }); + if (cachedRecentHangs.length > 10) { // only keep the last 10 items + cachedRecentHangs.shift(); + } + } + count --; + } + }); + + // the hang entry is not mutated when new instances of this hang come in + // since we aren't using this entry in the previous hangs anymore, we can just set it in the previous hangs + previousCountsMap[stack] = counts; + } + hangEntries.forEach(entry => { diffHangEntry(entry, false); }); + childHangEntries.forEach(entry => { diffHangEntry(entry, true); }); + lastMostRecentHangsTime = uptime; + return cachedRecentHangs; + }); } var soundPlayerPage = require("sdk/page-worker").Page({ @@ -238,68 +364,12 @@ function getUptime() { } } -// Returns an array of the most recent BHR hangs -var previousCountsMap = {}; // this is a mapping from stack traces (as strings) to corresponding histogram counts -var recentHangs = []; -let lastMostRecentHangsTime = getUptime(); -function mostRecentHangs() { - let geckoThread = Services.telemetry.threadHangStats.find(thread => - thread.name == "Gecko" - ); - if (!geckoThread) { - console.warn("Uh oh, there doesn't seem to be a thread with name \"Gecko\"!"); - return []; - } - - var timestamp = (new Date()).getTime(); // note that this timestamp will only be as accurate as the interval at which this function is called - var uptime = getUptime(); // this value matches the X axis in the timeline for the Gecko Profiler addon - - // diff the current hangs with the previous hangs to figure out what changed in this call, if anything - // hangs list will only ever grow: https://dxr.mozilla.org/mozilla-central/source/xpcom/threads/BackgroundHangMonitor.cpp#440 - // therefore, we only need to check current stacks against previous stacks - there is no need for a 2 way diff - // hangs are identified by their stack traces: https://dxr.mozilla.org/mozilla-central/source/toolkit/components/telemetry/Telemetry.cpp#4316 - geckoThread.hangs.forEach(hangEntry => { - var stack = hangEntry.stack.slice(0).reverse().join("\n"); - var ranges = hangEntry.histogram.ranges.concat([Infinity]); - var counts = hangEntry.histogram.counts; - var previousCounts = previousCountsMap.hasOwnProperty(stack) ? previousCountsMap[stack] : []; - - // diff this hang histogram with the previous hang histogram - counts.forEach((count, i) => { - var previousCount = previousCounts[i] || 0; - /* - NOTE: when you access the thread hangs, the ranges are actually the inclusive upper bounds of the buckets rather than the inclusive lower bound like other histograms. - Basically, when we access the buckets of a TimeHistogram in JS, it has a 0 prepended to the ranges; in C++, the indices behave as all other histograms do. - - For example, bucket 7 actually represents hangs of duration 64ms to 127ms, inclusive. For most other exponential histograms, this would be 128ms to 255ms. - - References: - * mozilla::Telemetry::CreateJSTimeHistogram - http://mxr.mozilla.org/mozilla-central/source/toolkit/components/telemetry/Telemetry.cpp#2947 - * mozilla::Telemetry::TimeHistogram - http://mxr.mozilla.org/mozilla-central/source/toolkit/components/telemetry/ThreadHangStats.h#25 - */ - while (count > previousCount) { // each additional count here is a new hang with this stack and a duration in this bucket's range - let lowerBound = ranges[i - 1] + 1; - if (lowerBound >= gHangThreshold) { - recentHangs.push({stack: stack, lowerBound: lowerBound, upperBound: ranges[i], timestamp: timestamp, uptime: uptime, previousUptime: lastMostRecentHangsTime}); - if (recentHangs.length > 10) { // only keep the last 10 items - recentHangs.shift(); - } - } - count --; - } - }); - - // the hang entry is not mutated when new instances of this hang come in - // since we aren't using this entry in the previous hangs anymore, we can just set it in the previous hangs - previousCountsMap[stack] = counts; - }); - lastMostRecentHangsTime = uptime; - return recentHangs; -} - -const BADGE_COLOURS = ["red", "blue", "brown", "black"]; +let numHangs = null; +let computedThreshold = 0; let numHangsObserved = 0; let prevNumHangs = null; +let baseNumHangs = 0; // the number of hangs at the time the counter was last reset +const BADGE_COLOURS = ["red", "blue", "brown", "black"]; function updateBadge() { if (numHangs === null) { button.badge = "?" @@ -317,43 +387,48 @@ function updateBadge() { } } -// reset the current hang stacks so we only show the new ones coming in -mostRecentHangs(); -recentHangs = []; - -const CHECK_FOR_HANG_INTERVAL = 400; // in millis -let { numHangs: numHangs, minBucketLowerBound: computedThreshold } = numGeckoHangs(); // note: this will be null if the hang counter is not available -let baseNumHangs = 0; // the number of hangs at the time the counter was last reset -setInterval(() => { - let { numHangs: hangCount, minBucketLowerBound: lower } = numGeckoHangs(); - if (hangCount !== numHangs) { - numHangs = hangCount; - updateBadge(); - let hangs = mostRecentHangs(); - panel.port.emit("set-hangs", hangs); - if (hangs.length > 0) { - button.label = "Most recent hang stack:\n\n" + hangs[hangs.length - 1].stack; - } else { - button.label = "No recent hang stacks."; - } - //exports.observe(undefined, "thread-hang"); - } - if (lower !== computedThreshold) { // update the computed threshold - computedThreshold = lower; - panel.port.emit("set-computed-threshold", computedThreshold); - } -}, CHECK_FOR_HANG_INTERVAL); -clearCount(); - function clearCount() { baseNumHangs = numHangs; numHangsObserved = 0; + computedThreshold = 0; + cachedRecentHangs = []; // empty out the list of hangs updateBadge(); panel.port.emit("set-computed-threshold", computedThreshold); panel.port.emit("set-hangs", []); // clear the panel's list of hangs - recentHangs = []; // empty out the list of hangs } +const CHECK_FOR_HANG_INTERVAL = 400; // in millis +function update() { + getHangs().then((result) => { + let { numHangs: hangCount, minBucketLowerBound: lower } = result; // note: numHangs will be null if the hang counter is not available + if (lower !== computedThreshold) { // update the computed threshold + computedThreshold = lower; + panel.port.emit("set-computed-threshold", computedThreshold); + } + if (hangCount !== numHangs) { // new hangs detected + numHangs = hangCount; + updateBadge(); + mostRecentHangs().then((recentHangs) => { + panel.port.emit("set-hangs", recentHangs); + if (recentHangs.length > 0) { + button.label = "Most recent hang stack:\n\n" + recentHangs[recentHangs.length - 1].stack; + } else { + button.label = "No recent hang stacks."; + } + setTimeout(update, CHECK_FOR_HANG_INTERVAL); + }); + } else { + setTimeout(update, CHECK_FOR_HANG_INTERVAL); + } + }); +} +getHangs().then((result) => { + let { numHangs: hangCount, minBucketLowerBound: lower } = result; // note: numHangs will be null if the hang counter is not available + [numHangs, computedThreshold] = [hangCount, lower]; + clearCount(); + setTimeout(update, CHECK_FOR_HANG_INTERVAL); // we set the timeouts each time to not back up the queue of child thread hang stats requests when the browser is really slow +}); + /* Enable this rAF loop to verify that the hangs reported are roughly equal * to the number of hangs observed from script. In Nightly 45, they were. var prevFrameTime = Cu.now(); From 239f4edb82da7b487b47d958e45f164eb1fc432d Mon Sep 17 00:00:00 2001 From: anthony Date: Fri, 29 Jan 2016 12:12:36 -0500 Subject: [PATCH 2/7] Add showing child hangs as another mode --- data/panel.html | 20 ++++++++++++------ data/panel.js | 12 +++++++++++ index.js | 56 ++++++++++++++++++++++++++++++++++--------------- 3 files changed, 65 insertions(+), 23 deletions(-) diff --git a/data/panel.html b/data/panel.html index fa506b3..f53e40f 100644 --- a/data/panel.html +++ b/data/panel.html @@ -10,6 +10,9 @@ font-family: monospace; font-size: 12px; } + h1 { + margin: 0; + } a { color: inherit; } @@ -47,7 +50,7 @@ } .controls { display: table-cell; - width: 150px; + width: 130px; padding: 5px 10px; text-align: right; background: #888; @@ -60,7 +63,7 @@ .controls .duration { font-size: 12px; } - .controls .time, .controls .uptime { + .controls .time { margin-top: 5px; } .controls .copyButton { @@ -89,10 +92,11 @@

STATUSER SETTINGS

The icon is a red square when the user is active, a blue circle when the user is inactive, and turns into a yellow square when there is a page loading in any tab.

-
+
+

-

Statuser can count hangs on the main thread, lags on the event loop, or spikes in input event response time. Changing this setting will reset the hang counter.

+

Statuser can count Gecko thread hangs for the parent process, Gecko thread hangs for both parent process and content processes, lags on the event loop, or spikes in input event response time. Changing this setting will reset the hang counter.

@@ -111,7 +115,10 @@

STATUSER SETTINGS

On E10S builds, Statuser will only measure main thread hangs.

MOST RECENT HANGS

-

The stack traces displayed here are are Background Hang Reporter pseudo-stacks. Only the 10 most recent stack traces are shown. Stack traces are only captured for hangs of 128ms or greater.

+
+ +

Statuser will show either hang stacks from the parent process only, or the parent process plus all the child processes.

+
+

The stack traces displayed here are are Background Hang Reporter pseudo-stacks. Only the 10 most recent stack traces are shown. Stack traces are only captured for hangs of 128ms or greater.

Entries with a grey sidebar are parent process hangs, while entries with a blue sidebar are child process hangs. Hang uptimes correspond to the X axis in the Gecko Profiler addon timeline.

\ No newline at end of file diff --git a/data/panel.js b/data/panel.js index 9d3e9dc..16436ef 100644 --- a/data/panel.js +++ b/data/panel.js @@ -1,7 +1,11 @@ // emit events on the panel's port for corresponding actions +var countThreadHangsParentOnly = document.getElementById("countThreadHangsParentOnly"); var countThreadHangs = document.getElementById("countThreadHangs"); var countEventLoopLags = document.getElementById("countEventLoopLags"); var countInputEventResponseLags = document.getElementById("countInputEventResponseLags"); +countThreadHangsParentOnly.addEventListener("click", function() { + self.port.emit("mode-changed", "threadHangsParentOnly"); +}); countThreadHangs.addEventListener("click", function() { self.port.emit("mode-changed", "threadHangs"); }); @@ -25,13 +29,21 @@ hangThreshold.addEventListener("change", function(event) { document.getElementById("clearCount").addEventListener("click", function() { self.port.emit("clear-count"); }); +var includeChildHangs = document.getElementById("includeChildHangs"); +includeChildHangs.addEventListener("change", function(event) { + self.port.emit("include-child-hangs-changed", event.target.checked); +}); // listen to re-emitted show event from main script self.port.on("show", function(currentSettings) { // populate the settings dialog with the current value of the settings playSound.checked = currentSettings.playSound; hangThreshold.value = currentSettings.hangThreshold; + includeChildHangs.checked = currentSettings.includeChildHangs; switch (currentSettings.mode) { + case "threadHangsParentOnly": + document.getElementById("countThreadHangsParentOnly").checked = true; + break; case "threadHangs": document.getElementById("countThreadHangs").checked = true; break; diff --git a/index.js b/index.js index bcfc421..7d9f6fc 100644 --- a/index.js +++ b/index.js @@ -10,8 +10,8 @@ let gOS = Cc["@mozilla.org/observer-service;1"].getService(Ci.nsIObserverService // load and validate settings var gMode = ss.storage.mode; -if (["threadHangs", "eventLoopLags", "inputEventResponseLags"].indexOf(gMode) < 0) { - gMode = "threadHangs"; +if (["threadHangsParentOnly", "threadHangs", "eventLoopLags", "inputEventResponseLags"].indexOf(gMode) < 0) { + gMode = "threadHangsParentOnly"; } var gPlaySound = ss.storage.playSound; if (typeof gPlaySound !== "boolean") { @@ -21,6 +21,10 @@ var gHangThreshold = ss.storage.hangThreshold; // ms over which a bucket must st if (typeof gHangThreshold !== "number" || gHangThreshold < 1) { gHangThreshold = 126; } +var gIncludeChildHangs = ss.storage.includeChildHangs; +if (typeof gIncludeChildHangs !== "boolean") { + gIncludeChildHangs = false; +} const { setTimeout } = require("sdk/timers"); const { ActionButton } = require("sdk/ui/button/action"); @@ -78,9 +82,10 @@ var panel = require("sdk/panel").Panel({ function showPanel() { panel.show({position: button}); panel.port.emit("show", { // emit event on the panel's port so the script inside knows it's shown + mode: gMode, playSound: gPlaySound, hangThreshold: gHangThreshold, - mode: gMode, + includeChildHangs: gIncludeChildHangs, }); } @@ -108,6 +113,12 @@ panel.port.on("clear-count", function() { clearCount(); }); +// toggle whether child hangs are included +panel.port.on("include-child-hangs-changed", function(includeChildHangs) { + gIncludeChildHangs = includeChildHangs; + ss.storage.includeChildHangs = includeChildHangs; +}); + // copy a value to the clipboard panel.port.on("copy", function(value) { clipboard.set(value); @@ -142,7 +153,8 @@ var gBrowser = windowUtils.getMostRecentBrowserWindow().getBrowser(); gBrowser.addTabsProgressListener(webProgressListener); // function that retrieves the current child hangs and caches it for a short duration -// caching this is useful since each call has to go through the events queue +// caching this is useful since each call has to go through the event queue of both parent and child processes, +// which can be relatively slow if any of the queues are backed up let cachedPreviousChildHangs = null; let lastChildHangsRetrievedTime = -Infinity; function getChildThreadHangs() { @@ -159,8 +171,10 @@ function getChildThreadHangs() { // returns the number of Gecko hangs, and the computed minimum threshold for those hangs (which is a value >= gHangThreshold) function getHangs() { switch(gMode) { + case "threadHangsParentOnly": + return numGeckoThreadHangs(false); case "threadHangs": - return numGeckoThreadHangs(); + return numGeckoThreadHangs(true); case "eventLoopLags": return numEventLoopLags(); case "inputEventResponseLags": @@ -213,7 +227,6 @@ function numGeckoThreadHangs(includeChildHangs = true) { minBucketLowerBound = Math.min(minBucketLowerBound, lowerBound); } }); - panel.port.emit("warning", null); return {numHangs: numHangs, minBucketLowerBound: minBucketLowerBound}; }); } @@ -255,23 +268,24 @@ function numInputEventResponseLags() { minBucketLowerBound = Math.min(minBucketLowerBound, snapshot.ranges[i]); } } - panel.port.emit("warning", null); resolve({numHangs: numHangs, minBucketLowerBound: minBucketLowerBound}); }); } -// Returns an array of the most recent BHR hangs +// Returns an array of the most recent BHR hangs, or null on error var previousCountsMap = {}; // this is a mapping from stack traces (as strings) to corresponding histogram counts var cachedRecentHangs = []; let lastMostRecentHangsTime = getUptime(); function mostRecentHangs(includeChildHangs = true) { - if (includeChildHangs && !TelemetrySession.getChildThreadHangs) { - return new Promise((resolve) => { resolve({numHangs: null, minBucketLowerBound: 0}); }); + if (includeChildHangs && TelemetrySession.getChildThreadHangs === undefined) { + panel.port.emit("warning", "unavailableChildBHR"); + return new Promise((resolve) => { resolve(null); }); } let geckoThread = Services.telemetry.threadHangStats.find(thread => thread.name == "Gecko"); if (!geckoThread || !geckoThread.activity.counts) { - return new Promise((resolve) => { resolve({numHangs: null, minBucketLowerBound: 0}); }); + panel.port.emit("warning", "unavailableBHR"); + return new Promise((resolve) => { resolve(null); }); } return new Promise((resolve) => { @@ -292,7 +306,6 @@ function mostRecentHangs(includeChildHangs = true) { } }).then(hangInfo => { [hangEntries, childHangEntries] = hangInfo; - console.error(childHangEntries) let timestamp = (new Date()).getTime(); // note that this timestamp will only be as accurate as the interval at which this function is called let uptime = getUptime(); // this value matches the X axis in the timeline for the Gecko Profiler addon @@ -408,16 +421,25 @@ function update() { if (hangCount !== numHangs) { // new hangs detected numHangs = hangCount; updateBadge(); - mostRecentHangs().then((recentHangs) => { - panel.port.emit("set-hangs", recentHangs); - if (recentHangs.length > 0) { - button.label = "Most recent hang stack:\n\n" + recentHangs[recentHangs.length - 1].stack; + mostRecentHangs(gIncludeChildHangs).then((recentHangs) => { + if (numHangs === null || recentHangs === null) { + panel.port.emit("set-hangs", []); + button.label = "Could not retrieve hang stacks."; } else { - button.label = "No recent hang stacks."; + panel.port.emit("warning", null); // hide the warning banner if it's shown, since we've successfully updated + panel.port.emit("set-hangs", recentHangs); + if (recentHangs.length > 0) { + button.label = "Most recent hang stack:\n\n" + recentHangs[recentHangs.length - 1].stack; + } else { + button.label = "No recent hang stacks."; + } } setTimeout(update, CHECK_FOR_HANG_INTERVAL); }); } else { + if (numHangs !== null) { + panel.port.emit("warning", null); // hide the warning banner if it's shown, since we've successfully updated + } setTimeout(update, CHECK_FOR_HANG_INTERVAL); } }); From 45be2bdffdb7149cf5d659daa71bb564bb89e1ce Mon Sep 17 00:00:00 2001 From: anthony Date: Fri, 29 Jan 2016 15:09:05 -0500 Subject: [PATCH 3/7] Implement feedback from code review --- index.js | 96 +++++++++++++++++++++++++++----------------------------- 1 file changed, 46 insertions(+), 50 deletions(-) diff --git a/index.js b/index.js index 7d9f6fc..982356c 100644 --- a/index.js +++ b/index.js @@ -159,7 +159,7 @@ let cachedPreviousChildHangs = null; let lastChildHangsRetrievedTime = -Infinity; function getChildThreadHangs() { if (Date.now() - lastChildHangsRetrievedTime < 300) { - return new Promise((resolve) => { resolve(cachedPreviousChildHangs); }); + return Promise.resolve(cachedPreviousChildHangs); } lastChildHangsRetrievedTime = Date.now(); return TelemetrySession.getChildThreadHangs().then((hangs) => { @@ -181,22 +181,20 @@ function getHangs() { return numInputEventResponseLags(); default: console.warn("Unknown mode: ", gMode); - return new Promise((resolve) => { - resolve({numHangs: null, minBucketLowerBound: 0}); - }); + return Promise.resolve({numHangs: null, minBucketLowerBound: 0}); } } function numGeckoThreadHangs(includeChildHangs = true) { if (includeChildHangs && !TelemetrySession.getChildThreadHangs) { panel.port.emit("warning", "unavailableChildBHR"); - return new Promise((resolve) => { resolve({numHangs: null, minBucketLowerBound: 0}); }); + return Promise.resolve({numHangs: null, minBucketLowerBound: 0}); } let geckoThread = Services.telemetry.threadHangStats.find(thread => thread.name == "Gecko"); if (!geckoThread || !geckoThread.activity.counts) { panel.port.emit("warning", "unavailableBHR"); - return new Promise((resolve) => { resolve({numHangs: null, minBucketLowerBound: 0}); }); + return Promise.resolve({numHangs: null, minBucketLowerBound: 0}); } return new Promise((resolve) => { @@ -232,60 +230,56 @@ function numGeckoThreadHangs(includeChildHangs = true) { } function numEventLoopLags() { - return new Promise((resolve) => { - try { - var snapshot = Services.telemetry.getHistogramById("EVENTLOOP_UI_ACTIVITY_EXP_MS").snapshot(); - } catch (e) { // histogram doesn't exist, the Firefox version is likely older than 45.0a1 - panel.port.emit("warning", "unavailableEventLoopLags"); - resolve({numHangs: null, minBucketLowerBound: 0}); - } - let numHangs = 0; - let minBucketLowerBound = Infinity; - for (let i = 0; i < snapshot.ranges.length; ++i) { - if (snapshot.ranges[i] >= gHangThreshold) { - numHangs += snapshot.counts[i]; - minBucketLowerBound = Math.min(minBucketLowerBound, snapshot.ranges[i]); - } + try { + var snapshot = Services.telemetry.getHistogramById("EVENTLOOP_UI_ACTIVITY_EXP_MS").snapshot(); + } catch (e) { // histogram doesn't exist, the Firefox version is likely older than 45.0a1 + panel.port.emit("warning", "unavailableEventLoopLags"); + return Promise.resolve({numHangs: null, minBucketLowerBound: 0}); + } + let numHangs = 0; + let minBucketLowerBound = Infinity; + for (let i = 0; i < snapshot.ranges.length; ++i) { + if (snapshot.ranges[i] >= gHangThreshold) { + numHangs += snapshot.counts[i]; + minBucketLowerBound = Math.min(minBucketLowerBound, snapshot.ranges[i]); } - panel.port.emit("warning", null); - resolve({numHangs: numHangs, minBucketLowerBound: minBucketLowerBound}); - }); + } + panel.port.emit("warning", null); + return Promise.resolve({numHangs: numHangs, minBucketLowerBound: minBucketLowerBound}); } function numInputEventResponseLags() { - return new Promise((resolve) => { - try { - var snapshot = Services.telemetry.getHistogramById("INPUT_EVENT_RESPONSE_MS").snapshot(); - } catch (e) { // histogram doesn't exist, the Firefox version is likely older than 46.0a1 - panel.port.emit("warning", "unavailableInputEventResponseLags"); - resolve({numHangs: null, minBucketLowerBound: 0}); - } - let numHangs = 0; - let minBucketLowerBound = Infinity; - for (let i = 0; i < snapshot.ranges.length; ++i) { - if (snapshot.ranges[i] > gHangThreshold) { - result += snapshot.counts[i]; - minBucketLowerBound = Math.min(minBucketLowerBound, snapshot.ranges[i]); - } + try { + var snapshot = Services.telemetry.getHistogramById("INPUT_EVENT_RESPONSE_MS").snapshot(); + } catch (e) { // histogram doesn't exist, the Firefox version is likely older than 46.0a1 + panel.port.emit("warning", "unavailableInputEventResponseLags"); + return Promise.resolve({numHangs: null, minBucketLowerBound: 0}); + } + let numHangs = 0; + let minBucketLowerBound = Infinity; + for (let i = 0; i < snapshot.ranges.length; ++i) { + if (snapshot.ranges[i] > gHangThreshold) { + result += snapshot.counts[i]; + minBucketLowerBound = Math.min(minBucketLowerBound, snapshot.ranges[i]); } - resolve({numHangs: numHangs, minBucketLowerBound: minBucketLowerBound}); - }); + } + return Promise.resolve({numHangs: numHangs, minBucketLowerBound: minBucketLowerBound}); } // Returns an array of the most recent BHR hangs, or null on error -var previousCountsMap = {}; // this is a mapping from stack traces (as strings) to corresponding histogram counts -var cachedRecentHangs = []; +let previousCountsMap = {}; // this is a mapping from stack traces (as strings) to corresponding histogram counts +let cachedRecentHangs = []; let lastMostRecentHangsTime = getUptime(); function mostRecentHangs(includeChildHangs = true) { if (includeChildHangs && TelemetrySession.getChildThreadHangs === undefined) { panel.port.emit("warning", "unavailableChildBHR"); - return new Promise((resolve) => { resolve(null); }); + return Promise.resolve(null); } let geckoThread = Services.telemetry.threadHangStats.find(thread => thread.name == "Gecko"); if (!geckoThread || !geckoThread.activity.counts) { panel.port.emit("warning", "unavailableBHR"); - return new Promise((resolve) => { resolve(null); }); + return Promise.resolve(null); } return new Promise((resolve) => { @@ -401,7 +395,7 @@ function updateBadge() { } function clearCount() { - baseNumHangs = numHangs; + baseNumHangs = prevNumHangs = numHangs; numHangsObserved = 0; computedThreshold = 0; cachedRecentHangs = []; // empty out the list of hangs @@ -412,8 +406,7 @@ function clearCount() { const CHECK_FOR_HANG_INTERVAL = 400; // in millis function update() { - getHangs().then((result) => { - let { numHangs: hangCount, minBucketLowerBound: lower } = result; // note: numHangs will be null if the hang counter is not available + getHangs().then(({numHangs: hangCount, minBucketLowerBound: lower}) => { if (lower !== computedThreshold) { // update the computed threshold computedThreshold = lower; panel.port.emit("set-computed-threshold", computedThreshold); @@ -444,11 +437,14 @@ function update() { } }); } -getHangs().then((result) => { - let { numHangs: hangCount, minBucketLowerBound: lower } = result; // note: numHangs will be null if the hang counter is not available +getHangs().then(({numHangs: hangCount, minBucketLowerBound: lower}) => { [numHangs, computedThreshold] = [hangCount, lower]; - clearCount(); - setTimeout(update, CHECK_FOR_HANG_INTERVAL); // we set the timeouts each time to not back up the queue of child thread hang stats requests when the browser is really slow + + // Call the function once to initialize previousCountsMap properly + mostRecentHangs(gIncludeChildHangs).then(() => { + clearCount(); + setTimeout(update, CHECK_FOR_HANG_INTERVAL); // we set the timeouts each time to not back up the queue of child thread hang stats requests when the browser is really slow + }); }); /* Enable this rAF loop to verify that the hangs reported are roughly equal From 0c30fe933c2abd8cd162ab5acb80c74d94075be2 Mon Sep 17 00:00:00 2001 From: anthony Date: Mon, 1 Feb 2016 11:39:39 -0500 Subject: [PATCH 4/7] Add child hangs only mode --- data/panel.html | 6 +++-- data/panel.js | 12 +++++++++ index.js | 66 ++++++++++++++++++++++++++++++++----------------- 3 files changed, 60 insertions(+), 24 deletions(-) diff --git a/data/panel.html b/data/panel.html index f53e40f..7865482 100644 --- a/data/panel.html +++ b/data/panel.html @@ -93,10 +93,11 @@

STATUSER SETTINGS

The icon is a red square when the user is active, a blue circle when the user is inactive, and turns into a yellow square when there is a page loading in any tab.


+


-

Statuser can count Gecko thread hangs for the parent process, Gecko thread hangs for both parent process and content processes, lags on the event loop, or spikes in input event response time. Changing this setting will reset the hang counter.

+

Statuser can count Gecko thread hangs for the parent process/child process/both, lags on the event loop, or spikes in input event response time. Changing this setting will reset the hang counter.

@@ -117,7 +118,8 @@

STATUSER SETTINGS

MOST RECENT HANGS

-

Statuser will show either hang stacks from the parent process only, or the parent process plus all the child processes.

+ +

Statuser will show either hang stacks from the parent process only, child processes only, or the parent process plus child processes.

diff --git a/data/panel.js b/data/panel.js index 16436ef..dd8c9bc 100644 --- a/data/panel.js +++ b/data/panel.js @@ -1,11 +1,15 @@ // emit events on the panel's port for corresponding actions var countThreadHangsParentOnly = document.getElementById("countThreadHangsParentOnly"); +var countThreadHangsChildOnly = document.getElementById("countThreadHangsChildOnly"); var countThreadHangs = document.getElementById("countThreadHangs"); var countEventLoopLags = document.getElementById("countEventLoopLags"); var countInputEventResponseLags = document.getElementById("countInputEventResponseLags"); countThreadHangsParentOnly.addEventListener("click", function() { self.port.emit("mode-changed", "threadHangsParentOnly"); }); +countThreadHangsChildOnly.addEventListener("click", function() { + self.port.emit("mode-changed", "threadHangsChildOnly"); +}); countThreadHangs.addEventListener("click", function() { self.port.emit("mode-changed", "threadHangs"); }); @@ -30,9 +34,13 @@ document.getElementById("clearCount").addEventListener("click", function() { self.port.emit("clear-count"); }); var includeChildHangs = document.getElementById("includeChildHangs"); +var includeParentHangs = document.getElementById("includeParentHangs"); includeChildHangs.addEventListener("change", function(event) { self.port.emit("include-child-hangs-changed", event.target.checked); }); +includeParentHangs.addEventListener("change", function(event) { + self.port.emit("include-parent-hangs-changed", event.target.checked); +}); // listen to re-emitted show event from main script self.port.on("show", function(currentSettings) { @@ -40,10 +48,14 @@ self.port.on("show", function(currentSettings) { playSound.checked = currentSettings.playSound; hangThreshold.value = currentSettings.hangThreshold; includeChildHangs.checked = currentSettings.includeChildHangs; + includeParentHangs.checked = currentSettings.includeParentHangs; switch (currentSettings.mode) { case "threadHangsParentOnly": document.getElementById("countThreadHangsParentOnly").checked = true; break; + case "threadHangsChildOnly": + document.getElementById("countThreadHangsChildOnly").checked = true; + break; case "threadHangs": document.getElementById("countThreadHangs").checked = true; break; diff --git a/index.js b/index.js index 982356c..50ef31f 100644 --- a/index.js +++ b/index.js @@ -10,7 +10,7 @@ let gOS = Cc["@mozilla.org/observer-service;1"].getService(Ci.nsIObserverService // load and validate settings var gMode = ss.storage.mode; -if (["threadHangsParentOnly", "threadHangs", "eventLoopLags", "inputEventResponseLags"].indexOf(gMode) < 0) { +if (["threadHangsParentOnly", "threadHangsChildOnly", "threadHangs", "eventLoopLags", "inputEventResponseLags"].indexOf(gMode) < 0) { gMode = "threadHangsParentOnly"; } var gPlaySound = ss.storage.playSound; @@ -25,6 +25,10 @@ var gIncludeChildHangs = ss.storage.includeChildHangs; if (typeof gIncludeChildHangs !== "boolean") { gIncludeChildHangs = false; } +var gIncludeParentHangs = ss.storage.includeParentHangs; +if (typeof gIncludeParentHangs !== "boolean") { + gIncludeParentHangs = true; +} const { setTimeout } = require("sdk/timers"); const { ActionButton } = require("sdk/ui/button/action"); @@ -86,6 +90,7 @@ function showPanel() { playSound: gPlaySound, hangThreshold: gHangThreshold, includeChildHangs: gIncludeChildHangs, + includeParentHangs: gIncludeParentHangs, }); } @@ -113,11 +118,15 @@ panel.port.on("clear-count", function() { clearCount(); }); -// toggle whether child hangs are included +// toggle whether different types of hangs are included panel.port.on("include-child-hangs-changed", function(includeChildHangs) { gIncludeChildHangs = includeChildHangs; ss.storage.includeChildHangs = includeChildHangs; }); +panel.port.on("include-parent-hangs-changed", function(includeParentHangs) { + gIncludeParentHangs = includeParentHangs; + ss.storage.includeParentHangs = includeParentHangs; +}); // copy a value to the clipboard panel.port.on("copy", function(value) { @@ -172,9 +181,11 @@ function getChildThreadHangs() { function getHangs() { switch(gMode) { case "threadHangsParentOnly": - return numGeckoThreadHangs(false); + return numGeckoThreadHangs(false, true); + case "threadHangsChildOnly": + return numGeckoThreadHangs(true, false); case "threadHangs": - return numGeckoThreadHangs(true); + return numGeckoThreadHangs(true, true); case "eventLoopLags": return numEventLoopLags(); case "inputEventResponseLags": @@ -185,33 +196,36 @@ function getHangs() { } } -function numGeckoThreadHangs(includeChildHangs = true) { +function numGeckoThreadHangs(includeChildHangs, includeParentHangs) { if (includeChildHangs && !TelemetrySession.getChildThreadHangs) { panel.port.emit("warning", "unavailableChildBHR"); return Promise.resolve({numHangs: null, minBucketLowerBound: 0}); } - let geckoThread = Services.telemetry.threadHangStats.find(thread => thread.name == "Gecko"); - if (!geckoThread || !geckoThread.activity.counts) { - panel.port.emit("warning", "unavailableBHR"); - return Promise.resolve({numHangs: null, minBucketLowerBound: 0}); + let counts = []; + if (includeParentHangs) { + geckoThread = Services.telemetry.threadHangStats.find(thread => thread.name == "Gecko"); + if (!geckoThread || !geckoThread.activity.counts) { + panel.port.emit("warning", "unavailableBHR"); + return Promise.resolve({numHangs: null, minBucketLowerBound: 0}); + } + counts = geckoThread.activity.counts.slice(0); } return new Promise((resolve) => { if (includeChildHangs) { getChildThreadHangs().then((hangs) => { // accumulate all of the counts in the child processes with the counts in the parent process - let counts = geckoThread.activity.counts.slice(0); hangs.forEach((threadHangStats) => { let childGeckoThread = threadHangStats.find(thread => thread.name == "Gecko_Child"); if (childGeckoThread && childGeckoThread.activity.counts) { - childGeckoThread.activity.counts.forEach((count, i) => { counts[i] += count; }); + childGeckoThread.activity.counts.forEach((count, i) => { counts[i] = (counts[i] || 0) + count; }); } }); resolve(counts); }); } else { // Just use the parent process stats - resolve(geckoThread.activity.counts); + resolve(counts); } }).then((counts) => { // see the NOTE in mostRecentHangs() for caveats when using the activity.counts histogram @@ -270,16 +284,20 @@ function numInputEventResponseLags() { let previousCountsMap = {}; // this is a mapping from stack traces (as strings) to corresponding histogram counts let cachedRecentHangs = []; let lastMostRecentHangsTime = getUptime(); -function mostRecentHangs(includeChildHangs = true) { +function mostRecentHangs(includeChildHangs, includeParentHangs) { if (includeChildHangs && TelemetrySession.getChildThreadHangs === undefined) { panel.port.emit("warning", "unavailableChildBHR"); return Promise.resolve(null); } - let geckoThread = Services.telemetry.threadHangStats.find(thread => thread.name == "Gecko"); - if (!geckoThread || !geckoThread.activity.counts) { - panel.port.emit("warning", "unavailableBHR"); - return Promise.resolve(null); + let parentHangs = []; + if (includeParentHangs) { + let geckoThread = Services.telemetry.threadHangStats.find(thread => thread.name == "Gecko"); + if (!geckoThread || !geckoThread.hangs) { + panel.port.emit("warning", "unavailableBHR"); + return Promise.resolve(null); + } + parentHangs = geckoThread.hangs; } return new Promise((resolve) => { @@ -293,13 +311,13 @@ function mostRecentHangs(includeChildHangs = true) { childHangEntries = childHangEntries.concat(childGeckoThread.hangs); } }); - resolve([geckoThread.hangs, childHangEntries]); + resolve([parentHangs, childHangEntries]); }); } else { // Just use the parent process stats - resolve([geckoThread.hangs, []]); + resolve([parentHangs, []]); } }).then(hangInfo => { - [hangEntries, childHangEntries] = hangInfo; + [parentHangEntries, childHangEntries] = hangInfo; let timestamp = (new Date()).getTime(); // note that this timestamp will only be as accurate as the interval at which this function is called let uptime = getUptime(); // this value matches the X axis in the timeline for the Gecko Profiler addon @@ -346,8 +364,12 @@ function mostRecentHangs(includeChildHangs = true) { // since we aren't using this entry in the previous hangs anymore, we can just set it in the previous hangs previousCountsMap[stack] = counts; } - hangEntries.forEach(entry => { diffHangEntry(entry, false); }); + + // diff the hang entries with their previous counts + // this mutates cachedRecentHangs so that it contains the differences + parentHangEntries.forEach(entry => { diffHangEntry(entry, false); }); childHangEntries.forEach(entry => { diffHangEntry(entry, true); }); + lastMostRecentHangsTime = uptime; return cachedRecentHangs; }); @@ -441,7 +463,7 @@ getHangs().then(({numHangs: hangCount, minBucketLowerBound: lower}) => { [numHangs, computedThreshold] = [hangCount, lower]; // Call the function once to initialize previousCountsMap properly - mostRecentHangs(gIncludeChildHangs).then(() => { + mostRecentHangs(gIncludeChildHangs, gIncludeParentHangs).then(() => { clearCount(); setTimeout(update, CHECK_FOR_HANG_INTERVAL); // we set the timeouts each time to not back up the queue of child thread hang stats requests when the browser is really slow }); From 341749ee1ff3c92cf15e4e3f0a44f14f06280af5 Mon Sep 17 00:00:00 2001 From: anthony Date: Mon, 1 Feb 2016 17:36:17 -0500 Subject: [PATCH 5/7] Various fixes: * Switching modes now clears the hang count properly. * Fix the input event response lag detection. * Fix warning banner being hidden when it should be shown in certain cases. --- index.js | 34 ++++++++++++++++------------------ 1 file changed, 16 insertions(+), 18 deletions(-) diff --git a/index.js b/index.js index 50ef31f..fd97924 100644 --- a/index.js +++ b/index.js @@ -60,6 +60,8 @@ const YELLOW_SVG = RED_SVG.replace('red', 'yellow'); var mBaseSVG = RED_SVG; var mAnimateSVG = ''; +let numHangs = null; + var button = ActionButton({ id: "active-button", badge: 0, @@ -94,11 +96,14 @@ function showPanel() { }); } -// switch modes between thread hang detection and event loop lag detection +// switch modes between different detection types panel.port.on("mode-changed", function(mode) { gMode = mode; ss.storage.mode = mode; - clearCount(); + getHangs().then(({numHangs: hangCount, minBucketLowerBound: lower}) => { + numHangs = hangCount; + clearCount(); + }); }); // toggle notification sound on and off @@ -273,7 +278,7 @@ function numInputEventResponseLags() { let minBucketLowerBound = Infinity; for (let i = 0; i < snapshot.ranges.length; ++i) { if (snapshot.ranges[i] > gHangThreshold) { - result += snapshot.counts[i]; + numHangs += snapshot.counts[i]; minBucketLowerBound = Math.min(minBucketLowerBound, snapshot.ranges[i]); } } @@ -393,7 +398,6 @@ function getUptime() { } } -let numHangs = null; let computedThreshold = 0; let numHangsObserved = 0; let prevNumHangs = null; @@ -436,25 +440,19 @@ function update() { if (hangCount !== numHangs) { // new hangs detected numHangs = hangCount; updateBadge(); - mostRecentHangs(gIncludeChildHangs).then((recentHangs) => { - if (numHangs === null || recentHangs === null) { - panel.port.emit("set-hangs", []); - button.label = "Could not retrieve hang stacks."; - } else { + mostRecentHangs(gIncludeChildHangs, gIncludeParentHangs).then((recentHangs) => { + if (hangCount !== null && recentHangs !== null) { panel.port.emit("warning", null); // hide the warning banner if it's shown, since we've successfully updated - panel.port.emit("set-hangs", recentHangs); - if (recentHangs.length > 0) { - button.label = "Most recent hang stack:\n\n" + recentHangs[recentHangs.length - 1].stack; - } else { - button.label = "No recent hang stacks."; - } + } + panel.port.emit("set-hangs", recentHangs || []); + if (recentHangs.length > 0) { + button.label = "Most recent hang stack:\n\n" + recentHangs[recentHangs.length - 1].stack; + } else { + button.label = "No recent hang stacks."; } setTimeout(update, CHECK_FOR_HANG_INTERVAL); }); } else { - if (numHangs !== null) { - panel.port.emit("warning", null); // hide the warning banner if it's shown, since we've successfully updated - } setTimeout(update, CHECK_FOR_HANG_INTERVAL); } }); From e579baf3d5b4e6d2304a937ce0408f6e8bf65501 Mon Sep 17 00:00:00 2001 From: anthony Date: Tue, 2 Feb 2016 13:39:21 -0500 Subject: [PATCH 6/7] Implement fixes and feedback: * Use Promise.reject() to simplify error handling. * Clear hangs on update to prevent flashes of incorrect numbers upon switching modes or clearing the count. * Use constants and update comments as appropriate. * Handle ranges better in child-only mode, to fix computed thresholds. As these all work together, I've put them in one commit. --- index.js | 96 ++++++++++++++++++++++++++++++++++++-------------------- 1 file changed, 62 insertions(+), 34 deletions(-) diff --git a/index.js b/index.js index fd97924..0ce5bad 100644 --- a/index.js +++ b/index.js @@ -61,6 +61,7 @@ var mBaseSVG = RED_SVG; var mAnimateSVG = ''; let numHangs = null; +let shouldClearHangs = true; var button = ActionButton({ id: "active-button", @@ -100,10 +101,7 @@ function showPanel() { panel.port.on("mode-changed", function(mode) { gMode = mode; ss.storage.mode = mode; - getHangs().then(({numHangs: hangCount, minBucketLowerBound: lower}) => { - numHangs = hangCount; - clearCount(); - }); + shouldClearHangs = true; // specify that the count should be cleared on the next update }); // toggle notification sound on and off @@ -171,8 +169,10 @@ gBrowser.addTabsProgressListener(webProgressListener); // which can be relatively slow if any of the queues are backed up let cachedPreviousChildHangs = null; let lastChildHangsRetrievedTime = -Infinity; +const cacheThreadHangsDuration = 300; function getChildThreadHangs() { - if (Date.now() - lastChildHangsRetrievedTime < 300) { + if (Date.now() - lastChildHangsRetrievedTime < cacheThreadHangsDuration) { + // the thread hangs have been retrieved very recently, so we can just return those results again return Promise.resolve(cachedPreviousChildHangs); } lastChildHangsRetrievedTime = Date.now(); @@ -182,7 +182,7 @@ function getChildThreadHangs() { }); } -// returns the number of Gecko hangs, and the computed minimum threshold for those hangs (which is a value >= gHangThreshold) +// returns a promise resolving to the number of Gecko hangs, and the computed minimum threshold for those hangs (which is a value >= gHangThreshold) function getHangs() { switch(gMode) { case "threadHangsParentOnly": @@ -197,24 +197,26 @@ function getHangs() { return numInputEventResponseLags(); default: console.warn("Unknown mode: ", gMode); - return Promise.resolve({numHangs: null, minBucketLowerBound: 0}); + return Promise.reject(); } } function numGeckoThreadHangs(includeChildHangs, includeParentHangs) { if (includeChildHangs && !TelemetrySession.getChildThreadHangs) { panel.port.emit("warning", "unavailableChildBHR"); - return Promise.resolve({numHangs: null, minBucketLowerBound: 0}); + return Promise.reject(); } let counts = []; + let ranges = []; if (includeParentHangs) { geckoThread = Services.telemetry.threadHangStats.find(thread => thread.name == "Gecko"); if (!geckoThread || !geckoThread.activity.counts) { panel.port.emit("warning", "unavailableBHR"); - return Promise.resolve({numHangs: null, minBucketLowerBound: 0}); + return Promise.reject(); } counts = geckoThread.activity.counts.slice(0); + ranges = geckoThread.activity.ranges; } return new Promise((resolve) => { @@ -225,20 +227,23 @@ function numGeckoThreadHangs(includeChildHangs, includeParentHangs) { let childGeckoThread = threadHangStats.find(thread => thread.name == "Gecko_Child"); if (childGeckoThread && childGeckoThread.activity.counts) { childGeckoThread.activity.counts.forEach((count, i) => { counts[i] = (counts[i] || 0) + count; }); + if (ranges.length === 0) { + ranges = childGeckoThread.activity.ranges; + } } }); - resolve(counts); + resolve(); }); } else { // Just use the parent process stats - resolve(counts); + resolve(); } - }).then((counts) => { + }).then(() => { // see the NOTE in mostRecentHangs() for caveats when using the activity.counts histogram // to summarize, the ranges are the inclusive upper bound of the histogram rather than the inclusive lower bound let numHangs = 0; let minBucketLowerBound = Infinity; counts.forEach((count, i) => { - var lowerBound = geckoThread.activity.ranges[i - 1] + 1; + var lowerBound = ranges[i - 1] + 1; if (lowerBound >= gHangThreshold) { numHangs += count; minBucketLowerBound = Math.min(minBucketLowerBound, lowerBound); @@ -253,7 +258,7 @@ function numEventLoopLags() { var snapshot = Services.telemetry.getHistogramById("EVENTLOOP_UI_ACTIVITY_EXP_MS").snapshot(); } catch (e) { // histogram doesn't exist, the Firefox version is likely older than 45.0a1 panel.port.emit("warning", "unavailableEventLoopLags"); - return Promise.resolve({numHangs: null, minBucketLowerBound: 0}); + return Promise.reject(); } let numHangs = 0; let minBucketLowerBound = Infinity; @@ -263,7 +268,6 @@ function numEventLoopLags() { minBucketLowerBound = Math.min(minBucketLowerBound, snapshot.ranges[i]); } } - panel.port.emit("warning", null); return Promise.resolve({numHangs: numHangs, minBucketLowerBound: minBucketLowerBound}); } @@ -272,7 +276,7 @@ function numInputEventResponseLags() { var snapshot = Services.telemetry.getHistogramById("INPUT_EVENT_RESPONSE_MS").snapshot(); } catch (e) { // histogram doesn't exist, the Firefox version is likely older than 46.0a1 panel.port.emit("warning", "unavailableInputEventResponseLags"); - return Promise.resolve({numHangs: null, minBucketLowerBound: 0}); + return Promise.reject(); } let numHangs = 0; let minBucketLowerBound = Infinity; @@ -285,14 +289,14 @@ function numInputEventResponseLags() { return Promise.resolve({numHangs: numHangs, minBucketLowerBound: minBucketLowerBound}); } -// Returns an array of the most recent BHR hangs, or null on error +// returns a promise resolving to an array of the most recent BHR hangs let previousCountsMap = {}; // this is a mapping from stack traces (as strings) to corresponding histogram counts let cachedRecentHangs = []; let lastMostRecentHangsTime = getUptime(); function mostRecentHangs(includeChildHangs, includeParentHangs) { if (includeChildHangs && TelemetrySession.getChildThreadHangs === undefined) { panel.port.emit("warning", "unavailableChildBHR"); - return Promise.resolve(null); + return Promise.reject(); } let parentHangs = []; @@ -300,7 +304,7 @@ function mostRecentHangs(includeChildHangs, includeParentHangs) { let geckoThread = Services.telemetry.threadHangStats.find(thread => thread.name == "Gecko"); if (!geckoThread || !geckoThread.hangs) { panel.port.emit("warning", "unavailableBHR"); - return Promise.resolve(null); + return Promise.reject(); } parentHangs = geckoThread.hangs; } @@ -438,34 +442,58 @@ function update() { panel.port.emit("set-computed-threshold", computedThreshold); } if (hangCount !== numHangs) { // new hangs detected - numHangs = hangCount; - updateBadge(); mostRecentHangs(gIncludeChildHangs, gIncludeParentHangs).then((recentHangs) => { - if (hangCount !== null && recentHangs !== null) { - panel.port.emit("warning", null); // hide the warning banner if it's shown, since we've successfully updated + numHangs = hangCount; + if (shouldClearHangs) { + clearCount(); + recentHangs = []; // clear the current list of hangs, which we received before clearing the counts + shouldClearHangs = false; } - panel.port.emit("set-hangs", recentHangs || []); + updateBadge(); + + // update the button label if (recentHangs.length > 0) { + // show the hang stack in the button tooltip button.label = "Most recent hang stack:\n\n" + recentHangs[recentHangs.length - 1].stack; } else { button.label = "No recent hang stacks."; } + + panel.port.emit("warning", null); + panel.port.emit("set-hangs", recentHangs); + setTimeout(update, CHECK_FOR_HANG_INTERVAL); + }, () => { // failed to retrieve hangs + numHangs = hangCount; + if (shouldClearHangs) { + clearCount(); + shouldClearHangs = false; + } + updateBadge(); + + // update the button label + button.label = "Could not retrieve hang stacks."; + + panel.port.emit("set-hangs", []); setTimeout(update, CHECK_FOR_HANG_INTERVAL); }); - } else { + } else { // no new hangs + if (shouldClearHangs) { + clearCount(); + updateBadge(); + shouldClearHangs = false; + } setTimeout(update, CHECK_FOR_HANG_INTERVAL); } + }, () => { + if (numHangs !== null) { + computedThreshold = 0; + panel.port.emit("set-computed-threshold", 0); + numHangs = null; + updateBadge(); + } }); } -getHangs().then(({numHangs: hangCount, minBucketLowerBound: lower}) => { - [numHangs, computedThreshold] = [hangCount, lower]; - - // Call the function once to initialize previousCountsMap properly - mostRecentHangs(gIncludeChildHangs, gIncludeParentHangs).then(() => { - clearCount(); - setTimeout(update, CHECK_FOR_HANG_INTERVAL); // we set the timeouts each time to not back up the queue of child thread hang stats requests when the browser is really slow - }); -}); +update(); /* Enable this rAF loop to verify that the hangs reported are roughly equal * to the number of hangs observed from script. In Nightly 45, they were. From 2e7971522e16e4c70b78a88025972d58988788c3 Mon Sep 17 00:00:00 2001 From: anthony Date: Fri, 5 Feb 2016 15:30:10 -0500 Subject: [PATCH 7/7] Make the types of hang stacks that show up dependent on the mode. --- data/panel.html | 5 ----- data/panel.js | 10 ---------- index.js | 40 +++++++++++++++++----------------------- 3 files changed, 17 insertions(+), 38 deletions(-) diff --git a/data/panel.html b/data/panel.html index 7865482..c8a9b13 100644 --- a/data/panel.html +++ b/data/panel.html @@ -116,11 +116,6 @@

STATUSER SETTINGS

On E10S builds, Statuser will only measure main thread hangs.

MOST RECENT HANGS

-
- - -

Statuser will show either hang stacks from the parent process only, child processes only, or the parent process plus child processes.

-