Bug 815709 - Shutdown time is read in the main thread. r=vladan.

--HG--
extra : rebase_source : c6105cd172f16e187f279b88785bba5cefb2b174

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);

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<nsCOMPtr<nsIReadShutdownTimeCallback> > 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<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;
@@ -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<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;
 }
 

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) {

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

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();
 }

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);