From 6842e2d6cc141f4074e937bc2ba5a141d412077e Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Rafael=20=C3=81vila=20de=20Esp=C3=ADndola?= Date: Thu, 13 Dec 2012 23:13:03 -0500 Subject: [PATCH] Bug 815709 - Shutdown time is read in the main thread. r=vladan. --HG-- extra : rebase_source : c6105cd172f16e187f279b88785bba5cefb2b174 --- .../test/browser_TelemetryTimestamps.js | 9 ++ toolkit/components/telemetry/Telemetry.cpp | 129 ++++++++++++++---- toolkit/components/telemetry/TelemetryPing.js | 8 ++ toolkit/components/telemetry/nsITelemetry.idl | 12 ++ .../tests/unit/test_TelemetryPing.js | 10 +- toolkit/content/aboutTelemetry.js | 26 ++-- 6 files changed, 154 insertions(+), 40 deletions(-) diff --git a/browser/modules/test/browser_TelemetryTimestamps.js b/browser/modules/test/browser_TelemetryTimestamps.js index fbc716270c2..9919f7dbebb 100644 --- a/browser/modules/test/browser_TelemetryTimestamps.js +++ b/browser/modules/test/browser_TelemetryTimestamps.js @@ -9,6 +9,15 @@ function getSimpleMeasurementsFromTelemetryPing() { } function test() { + waitForExplicitFinish() + const Telemetry = Services.telemetry; + Telemetry.asyncReadShutdownTime(function () { + actualTest(); + finish(); + }); +} + +function actualTest() { // Test the module logic let tmp = {}; Cu.import("resource:///modules/TelemetryTimestamps.jsm", tmp); diff --git a/toolkit/components/telemetry/Telemetry.cpp b/toolkit/components/telemetry/Telemetry.cpp index fb8ea4ed824..8099ada3f0d 100644 --- a/toolkit/components/telemetry/Telemetry.cpp +++ b/toolkit/components/telemetry/Telemetry.cpp @@ -24,6 +24,7 @@ #include "nsBaseHashtable.h" #include "nsXULAppAPI.h" #include "nsThreadUtils.h" +#include "nsNetCID.h" #include "plstr.h" #include "nsAppDirectoryServiceDefs.h" #include "mozilla/ProcessedStack.h" @@ -319,6 +320,8 @@ private: bool mCachedShutdownTime; uint32_t mLastShutdownTime; + std::vector > mCallbacks; + friend class nsReadShutdownTime; }; TelemetryImpl* TelemetryImpl::sTelemetry = NULL; @@ -686,6 +689,53 @@ WrapAndReturnHistogram(Histogram *h, JSContext *cx, jsval *ret) return NS_OK; } +static uint32_t +ReadLastShutdownDuration(const char *filename) { + FILE *f = fopen(filename, "r"); + if (!f) { + return 0; + } + + int shutdownTime; + int r = fscanf(f, "%d\n", &shutdownTime); + fclose(f); + if (r != 1) { + return 0; + } + + return shutdownTime; +} + +class nsReadShutdownTime : public nsRunnable +{ +public: + nsReadShutdownTime(const char *aFilename) : + mFilename(aFilename), mTelemetry(TelemetryImpl::sTelemetry) { + } + +private: + const char *mFilename; + nsCOMPtr mTelemetry; + +public: + void MainThread() { + mTelemetry->mCachedShutdownTime = true; + for (unsigned int i = 0, n = mTelemetry->mCallbacks.size(); i < n; ++i) { + mTelemetry->mCallbacks[i]->Complete(); + } + mTelemetry->mCallbacks.clear(); + } + + NS_IMETHOD Run() { + mTelemetry->mLastShutdownTime = ReadLastShutdownDuration(mFilename); + nsCOMPtr e = + NS_NewRunnableMethod(this, &nsReadShutdownTime::MainThread); + NS_ENSURE_STATE(e); + NS_DispatchToMainThread(e, NS_DISPATCH_NORMAL); + return NS_OK; + } +}; + static TimeStamp gRecordedShutdownStartTime; static bool gAlreadyFreedShutdownTimeFileName = false; static char *gRecordedShutdownTimeFileName = nullptr; @@ -718,41 +768,64 @@ GetShutdownTimeFileName() NS_IMETHODIMP TelemetryImpl::GetLastShutdownDuration(uint32_t *aResult) { - // We make this check so that GetShutdownTimeFileName() doesn't get - // called; calling that function without telemetry enabled violates - // assumptions that the write-the-shutdown-timestamp machinery makes. - if (!Telemetry::CanRecord()) { + // The user must call ReadShutdownTime first. We return zero instead of + // reporting a failure so that the rest of telemetry can uniformly handle + // the read not being available yet. + if (!mCachedShutdownTime) { *aResult = 0; return NS_OK; } - if (!mCachedShutdownTime) { - const char *filename = GetShutdownTimeFileName(); + *aResult = mLastShutdownTime; + return NS_OK; +} - if (!filename) { - *aResult = 0; - return NS_OK; - } - - FILE *f = fopen(filename, "r"); - if (!f) { - *aResult = 0; - return NS_OK; - } - - int shutdownTime; - int r = fscanf(f, "%d\n", &shutdownTime); - fclose(f); - if (r != 1) { - *aResult = 0; - return NS_OK; - } - - mLastShutdownTime = shutdownTime; - mCachedShutdownTime = true; +NS_IMETHODIMP +TelemetryImpl::AsyncReadShutdownTime(nsIReadShutdownTimeCallback *aCallback) +{ + // We have finished reading the data already, just call the callback. + if (mCachedShutdownTime) { + aCallback->Complete(); + return NS_OK; } - *aResult = mLastShutdownTime; + // We already have a read request running, just remember the callback. + if (!mCallbacks.empty()) { + mCallbacks.push_back(aCallback); + return NS_OK; + } + + // We make this check so that GetShutdownTimeFileName() doesn't get + // called; calling that function without telemetry enabled violates + // assumptions that the write-the-shutdown-timestamp machinery makes. + if (!Telemetry::CanRecord()) { + mCachedShutdownTime = true; + aCallback->Complete(); + return NS_OK; + } + + // Send the read to a background thread provided by the stream transport + // service to avoid a read in the main thread. + nsCOMPtr targetThread = + do_GetService(NS_STREAMTRANSPORTSERVICE_CONTRACTID); + if (!targetThread) { + mCachedShutdownTime = true; + aCallback->Complete(); + return NS_OK; + } + + // We have to get the filename from the main thread. + const char *filename = GetShutdownTimeFileName(); + if (!filename) { + mCachedShutdownTime = true; + aCallback->Complete(); + return NS_OK; + } + + mCallbacks.push_back(aCallback); + nsCOMPtr event = new nsReadShutdownTime(filename); + + targetThread->Dispatch(event, NS_DISPATCH_NORMAL); return NS_OK; } diff --git a/toolkit/components/telemetry/TelemetryPing.js b/toolkit/components/telemetry/TelemetryPing.js index f43feb17fe9..0183e0762e7 100644 --- a/toolkit/components/telemetry/TelemetryPing.js +++ b/toolkit/components/telemetry/TelemetryPing.js @@ -75,6 +75,8 @@ const MEM_HISTOGRAMS = { // start asynchronous tasks to gather data. On the next idle the data is sent. const IDLE_TIMEOUT_SECONDS = 5 * 60; +const SHUTDOWN_TIME_READ_DELAY_MS = 5413; + var gLastMemoryPoll = null; let gWasDebuggerAttached = false; @@ -1025,6 +1027,12 @@ TelemetryPing.prototype = { break; case "xul-window-visible": Services.obs.removeObserver(this, "xul-window-visible"); + + let timer = Cc["@mozilla.org/timer;1"].createInstance(Ci.nsITimer); + timer.initWithCallback(function() { + Telemetry.asyncReadShutdownTime(function () { + }); + }, SHUTDOWN_TIME_READ_DELAY_MS, Ci.nsITimer.TYPE_ONE_SHOT); this._hasXulWindowVisibleObserver = false; var counters = processInfo.getCounters(); if (counters) { diff --git a/toolkit/components/telemetry/nsITelemetry.idl b/toolkit/components/telemetry/nsITelemetry.idl index 016b37835fd..932d4cb27aa 100644 --- a/toolkit/components/telemetry/nsITelemetry.idl +++ b/toolkit/components/telemetry/nsITelemetry.idl @@ -6,6 +6,12 @@ #include "nsISupports.idl" #include "nsIFile.idl" +[scriptable,function, uuid(5c25e4b0-398f-11e2-81c1-0800200c9a66)] +interface nsIReadShutdownTimeCallback : nsISupports +{ + void complete(); +}; + [scriptable, uuid(420ebbd5-efe3-42f2-8a13-f695e0fdcca0)] interface nsITelemetry : nsISupports { @@ -185,4 +191,10 @@ interface nsITelemetry : nsISupports */ [implicit_jscontext] readonly attribute jsval addonHistogramSnapshots; + + /** + * Read how long the previous run took to shutdown. After the callback is + * called the data is available in lastShutdownDuration. + */ + void asyncReadShutdownTime(in nsIReadShutdownTimeCallback aCallback); }; diff --git a/toolkit/components/telemetry/tests/unit/test_TelemetryPing.js b/toolkit/components/telemetry/tests/unit/test_TelemetryPing.js index 425dc6ca1a1..c531cde01fd 100644 --- a/toolkit/components/telemetry/tests/unit/test_TelemetryPing.js +++ b/toolkit/components/telemetry/tests/unit/test_TelemetryPing.js @@ -444,6 +444,7 @@ function write_fake_shutdown_file() { } function run_test() { + do_test_pending(); try { var gfxInfo = Cc["@mozilla.org/gfx/info;1"].getService(Ci.nsIGfxInfoDebug); gfxInfo.spoofVendorID("0xabcd"); @@ -458,7 +459,13 @@ function run_test() { // Make it look like we've shutdown before. write_fake_shutdown_file(); - + + Telemetry.asyncReadShutdownTime(function () { + actualTest(); + }); +} + +function actualTest() { // try to make LightweightThemeManager do stuff let gInternalManager = Cc["@mozilla.org/addons/integration;1"] .getService(Ci.nsIObserver) @@ -478,4 +485,5 @@ function run_test() { do_test_pending(); // ensure that test runs to completion do_register_cleanup(function () do_check_true(gFinished)); + do_test_finished(); } diff --git a/toolkit/content/aboutTelemetry.js b/toolkit/content/aboutTelemetry.js index 4c5bdf65b86..9a15de88b86 100644 --- a/toolkit/content/aboutTelemetry.js +++ b/toolkit/content/aboutTelemetry.js @@ -711,7 +711,22 @@ function onLoad() { showEmptySectionMessage("histograms-section"); } + // Show addon histogram data + histograms = Telemetry.addonHistogramSnapshots; + if (Object.keys(histograms).length) { + let addonDiv = document.getElementById("addon-histograms"); + for (let [name, hgram] of Iterator(histograms)) { + Histogram.render(addonDiv, "ADDON_" + name, hgram); + } + } else { + showEmptySectionMessage("addon-histograms-section"); + } + // Get the Telemetry Ping payload + Telemetry.asyncReadShutdownTime(displayPingData); +} + +function displayPingData(ping) { let ping = TelemetryPing.getPayload(); // Show simple measurements @@ -727,17 +742,6 @@ function onLoad() { } else { showEmptySectionMessage("system-info-section"); } - - // Show addon histogram data - histograms = Telemetry.addonHistogramSnapshots; - if (Object.keys(histograms).length) { - let addonDiv = document.getElementById("addon-histograms"); - for (let [name, hgram] of Iterator(histograms)) { - Histogram.render(addonDiv, "ADDON_" + name, hgram); - } - } else { - showEmptySectionMessage("addon-histograms-section"); - } } window.addEventListener("load", onLoad, false);