Bug 815709 - Shutdown time is read in the main thread. r=vladan.
authorRafael Ávila de Espíndola <respindola@mozilla.org>
Thu, 13 Dec 2012 23:13:03 -0500
changeset 125131 babbf864b10cdc15338cfead5ef2c61026113873
parent 125130 f752f9d2563112b93940247dcec848035ae1fb78
child 125132 916f6915112da1ba473cf32e29b65cf408b5875b
push id2151
push userlsblakk@mozilla.com
push dateTue, 19 Feb 2013 18:06:57 +0000
treeherdermozilla-beta@4952e88741ec [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersvladan
bugs815709
milestone20.0a1
first release with
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
last release without
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
Bug 815709 - Shutdown time is read in the main thread. r=vladan.
browser/modules/test/browser_TelemetryTimestamps.js
toolkit/components/telemetry/Telemetry.cpp
toolkit/components/telemetry/TelemetryPing.js
toolkit/components/telemetry/nsITelemetry.idl
toolkit/components/telemetry/tests/unit/test_TelemetryPing.js
toolkit/content/aboutTelemetry.js
--- a/browser/modules/test/browser_TelemetryTimestamps.js
+++ b/browser/modules/test/browser_TelemetryTimestamps.js
@@ -4,16 +4,25 @@
 function getSimpleMeasurementsFromTelemetryPing() {
   const TelemetryPing = Cc["@mozilla.org/base/telemetry-ping;1"].getService(Ci.nsITelemetryPing);
   let ping = TelemetryPing.getPayload();
 
   return ping.simpleMeasurements;
 }
 
 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);
   let TelemetryTimestamps = tmp.TelemetryTimestamps;
   let now = Date.now();
   TelemetryTimestamps.add("foo");
   ok(TelemetryTimestamps.get().foo, "foo was added");
   ok(TelemetryTimestamps.get().foo >= now, "foo has a reasonable value");
--- a/toolkit/components/telemetry/Telemetry.cpp
+++ b/toolkit/components/telemetry/Telemetry.cpp
@@ -19,16 +19,17 @@
 #include "nsIFile.h"
 #include "nsIMemoryReporter.h"
 #include "Telemetry.h" 
 #include "nsTHashtable.h"
 #include "nsHashKeys.h"
 #include "nsBaseHashtable.h"
 #include "nsXULAppAPI.h"
 #include "nsThreadUtils.h"
+#include "nsNetCID.h"
 #include "plstr.h"
 #include "nsAppDirectoryServiceDefs.h"
 #include "mozilla/ProcessedStack.h"
 #include "mozilla/Mutex.h"
 #include "mozilla/FileUtils.h"
 #include "mozilla/Preferences.h"
 #include "mozilla/Attributes.h"
 #include "mozilla/Likely.h"
@@ -314,16 +315,18 @@ private:
   nsTHashtable<nsCStringHashKey> mTrackedDBs;
   Mutex mHashMutex;
   HangReports mHangReports;
   Mutex mHangReportsMutex;
   nsIMemoryReporter *mMemoryReporter;
 
   bool mCachedShutdownTime;
   uint32_t mLastShutdownTime;
+  std::vector<nsCOMPtr<nsIReadShutdownTimeCallback> > mCallbacks;
+  friend class nsReadShutdownTime;
 };
 
 TelemetryImpl*  TelemetryImpl::sTelemetry = NULL;
 
 NS_MEMORY_REPORTER_MALLOC_SIZEOF_FUN(TelemetryMallocSizeOf, "telemetry")
 
 size_t
 TelemetryImpl::SizeOfIncludingThis(nsMallocSizeOfFun aMallocSizeOf)
@@ -681,16 +684,63 @@ WrapAndReturnHistogram(Histogram *h, JSC
         && JS_DefineFunction(cx, obj, "clear", JSHistogram_Clear, 0, 0))) {
     return NS_ERROR_FAILURE;
   }
   *ret = OBJECT_TO_JSVAL(obj);
   JS_SetPrivate(obj, h);
   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<TelemetryImpl> 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<nsIRunnable> 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;
 
 static char *
 GetShutdownTimeFileName()
 {
   if (gAlreadyFreedShutdownTimeFileName) {
@@ -713,51 +763,74 @@ GetShutdownTimeFileName()
   }
 
   return gRecordedShutdownTimeFileName;
 }
 
 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();
-
-    if (!filename) {
-      *aResult = 0;
-      return NS_OK;
-    }
+  *aResult = mLastShutdownTime;
+  return NS_OK;
+}
 
-    FILE *f = fopen(filename, "r");
-    if (!f) {
-      *aResult = 0;
-      return NS_OK;
-    }
+NS_IMETHODIMP
+TelemetryImpl::AsyncReadShutdownTime(nsIReadShutdownTimeCallback *aCallback)
+{
+  // We have finished reading the data already, just call the callback.
+  if (mCachedShutdownTime) {
+    aCallback->Complete();
+    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;
+  // We already have a read request running, just remember the callback.
+  if (!mCallbacks.empty()) {
+    mCallbacks.push_back(aCallback);
+    return NS_OK;
   }
 
-  *aResult = mLastShutdownTime;
+  // 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<nsIEventTarget> 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<nsIRunnable> event = new nsReadShutdownTime(filename);
+
+  targetThread->Dispatch(event, NS_DISPATCH_NORMAL);
   return NS_OK;
 }
 
 TelemetryImpl::TelemetryImpl():
 mHistogramMap(Telemetry::HistogramCount),
 mCanRecord(XRE_GetProcessType() == GeckoProcessType_Default),
 mHashMutex("Telemetry::mHashMutex"),
 mHangReportsMutex("Telemetry::mHangReportsMutex"),
--- a/toolkit/components/telemetry/TelemetryPing.js
+++ b/toolkit/components/telemetry/TelemetryPing.js
@@ -70,16 +70,18 @@ const MEM_HISTOGRAMS = {
   "ghost-windows": "GHOST_WINDOWS"
 };
 
 // Seconds of idle time before pinging.
 // On idle-daily a gather-telemetry notification is fired, during it probes can
 // 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;
 
 function getLocale() {
   return Cc["@mozilla.org/chrome/chrome-registry;1"].
          getService(Ci.nsIXULChromeRegistry).
          getSelectedLocale('global');
@@ -1020,16 +1022,22 @@ TelemetryPing.prototype = {
       if (aData == "enter") {
         this.detachObservers()
       } else {
         this.attachObservers()
       }
       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) {
         [this._startupIO.startupWindowVisibleReadBytes, 
           this._startupIO.startupWindowVisibleWriteBytes] = counters;
       }
       break;
     case "sessionstore-windows-restored":
--- a/toolkit/components/telemetry/nsITelemetry.idl
+++ b/toolkit/components/telemetry/nsITelemetry.idl
@@ -1,16 +1,22 @@
 /* -*- Mode: C++; c-basic-offset: 2; indent-tabs-mode: nil; tab-width: 8 -*- */
 /* This Source Code Form is subject to the terms of the Mozilla Public
  * License, v. 2.0. If a copy of the MPL was not distributed with this
  * file, You can obtain one at http://mozilla.org/MPL/2.0/. */
 
 #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
 {
   /**
    * Histogram types:
    * HISTOGRAM_EXPONENTIAL - buckets increase exponentially
    * HISTOGRAM_LINEAR - buckets increase linearly
    * HISTOGRAM_BOOLEAN - For storing 0/1 values
@@ -180,9 +186,15 @@ interface nsITelemetry : nsISupports
    * { addon-id1 : data1, ... }
    *
    * where data is an object whose properties are the names of the
    * addon's histograms and whose corresponding values are as in
    * histogramSnapshots.
    */
   [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);
 };
--- a/toolkit/components/telemetry/tests/unit/test_TelemetryPing.js
+++ b/toolkit/components/telemetry/tests/unit/test_TelemetryPing.js
@@ -439,31 +439,38 @@ function write_fake_shutdown_file() {
   let profileDirectory = Services.dirsvc.get("ProfD", Ci.nsIFile);
   let file = profileDirectory.clone();
   file.append("Telemetry.ShutdownTime.txt");
   let contents = "" + SHUTDOWN_TIME;
   writeStringToFile(file, contents);
 }
 
 function run_test() {
+  do_test_pending();
   try {
     var gfxInfo = Cc["@mozilla.org/gfx/info;1"].getService(Ci.nsIGfxInfoDebug);
     gfxInfo.spoofVendorID("0xabcd");
     gfxInfo.spoofDeviceID("0x1234");
   } catch (x) {
     // If we can't test gfxInfo, that's fine, we'll note it later.
   }
 
   // Addon manager needs a profile directory
   do_get_profile();
   createAppInfo("xpcshell@tests.mozilla.org", "XPCShell", "1", "1.9.2");
 
   // 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)
                          .QueryInterface(Ci.nsITimerCallback);
 
   gInternalManager.observe(null, "addons-startup", null);
   LightweightThemeManager.currentTheme = dummyTheme("1234");
 
@@ -473,9 +480,10 @@ function run_test() {
   runInvalidJSONTest();
 
   Services.obs.addObserver(nonexistentServerObserver, "telemetry-test-xhr-complete", false);
   telemetry_ping();
   // spin the event loop
   do_test_pending();
   // ensure that test runs to completion
   do_register_cleanup(function () do_check_true(gFinished));
+  do_test_finished();
 }
--- a/toolkit/content/aboutTelemetry.js
+++ b/toolkit/content/aboutTelemetry.js
@@ -706,38 +706,42 @@ function onLoad() {
     let hgramDiv = document.getElementById("histograms");
     for (let [name, hgram] of Iterator(histograms)) {
       Histogram.render(hgramDiv, name, hgram);
     }
   } else {
     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
   if (Object.keys(ping.simpleMeasurements).length) {
     KeyValueTable.render("simple-measurements-table", ping.simpleMeasurements);
   } else {
     showEmptySectionMessage("simple-measurements-section");
   }
 
   // Show basic system info gathered
   if (Object.keys(ping.info).length) {
     KeyValueTable.render("system-info-table", ping.info);
   } 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);