Bug 815418: Telemetry for failed profile lock attempts; r=vladan
☠☠ backed out by 4f18799588dc ☠ ☠
authorAaron Klotz <aklotz@mozilla.com>
Thu, 10 Jan 2013 12:50:51 -0500
changeset 118443 23bb4a03ef347a8326e3eeff9075c5a54950a32f
parent 118442 8fd79d4c7b17173480f0583b36c4b7d6640145a6
child 118444 71d3013257a93ca78723d954825399f9a49b6ac8
push id24166
push userMs2ger@gmail.com
push dateFri, 11 Jan 2013 13:57:41 +0000
treeherdermozilla-central@63c4b0f66a0c [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersvladan
bugs815418
milestone21.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 815418: Telemetry for failed profile lock attempts; r=vladan
toolkit/components/telemetry/Histograms.json
toolkit/components/telemetry/Telemetry.cpp
toolkit/components/telemetry/Telemetry.h
toolkit/components/telemetry/tests/unit/test_TelemetryPing.js
toolkit/xre/nsAppRunner.cpp
--- a/toolkit/components/telemetry/Histograms.json
+++ b/toolkit/components/telemetry/Histograms.json
@@ -2565,10 +2565,15 @@
     "n_buckets": 50,
     "description": "Time spent on an initially failed cert verification in libpix mode (ms)"
   },
   "SSL_INITIAL_FAILED_CERT_VALIDATION_TIME_CLASSIC" : {
     "kind": "exponential",
     "high": "60000",
     "n_buckets": 50,
     "description": "Time spent on an initially failed cert  verification in classic mode (ms)"
+  },
+  "STARTUP_PROFILE_LOCK_FAILURES": {
+    "kind": "enumerated",
+    "n_values": 11,
+    "description": "The user's profile was unable to be locked, preventing startup"
   }
 }
--- a/toolkit/components/telemetry/Telemetry.cpp
+++ b/toolkit/components/telemetry/Telemetry.cpp
@@ -25,24 +25,27 @@
 #include "mozilla/ModuleUtils.h"
 #include "nsIXPConnect.h"
 #include "mozilla/Services.h"
 #include "jsapi.h"
 #include "jsfriendapi.h"
 #include "nsStringGlue.h"
 #include "nsITelemetry.h"
 #include "nsIFile.h"
+#include "nsIFileStreams.h"
 #include "nsIMemoryReporter.h"
+#include "nsISeekableStream.h"
 #include "Telemetry.h" 
 #include "nsTHashtable.h"
 #include "nsHashKeys.h"
 #include "nsBaseHashtable.h"
 #include "nsXULAppAPI.h"
 #include "nsThreadUtils.h"
 #include "nsNetCID.h"
+#include "nsNetUtil.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/mozPoisonWrite.h"
 
@@ -720,45 +723,107 @@ ReadLastShutdownDuration(const char *fil
   fclose(f);
   if (r != 1) {
     return 0;
   }
 
   return shutdownTime;
 }
 
+const int32_t kMaxFailedProfileLockFileSize = 10;
+
+bool
+GetFailedLockCount(nsIInputStream* inStream, unsigned int &result)
+{
+  nsAutoCString bufStr;
+  nsresult rv;
+  rv = NS_ReadInputStreamToString(inStream, bufStr, kMaxFailedProfileLockFileSize);
+  // It's reasonable to hit EOF here so we need to check for NS_ERROR_UNEXPECTED
+  if (NS_FAILED(rv) && rv != NS_ERROR_UNEXPECTED) {
+    return false;
+  }
+  result = bufStr.ToInteger(&rv);
+  return NS_SUCCEEDED(rv) && result > 0;
+}
+
+nsresult
+GetFailedProfileLockFile(nsIFile* *aFile, nsIFile* aProfileDir = nullptr)
+{
+  nsresult rv;
+  if (aProfileDir) {
+    rv = aProfileDir->Clone(aFile);
+  } else {
+    rv = NS_GetSpecialDirectory(NS_APP_USER_PROFILE_50_DIR, aFile);
+  }
+  NS_ENSURE_SUCCESS(rv, rv);
+
+  (*aFile)->AppendNative(NS_LITERAL_CSTRING("Telemetry.FailedProfileLocks.txt"));
+  return NS_OK;
+}
+
 class nsFetchTelemetryData : public nsRunnable
 {
 public:
-  nsFetchTelemetryData(const char *aFilename) :
-    mFilename(aFilename), mTelemetry(TelemetryImpl::sTelemetry) {
+  nsFetchTelemetryData(const char* aShutdownTimeFilename,
+                       nsIFile* aFailedProfileLockFile)
+    : mShutdownTimeFilename(aShutdownTimeFilename),
+      mFailedProfileLockFile(aFailedProfileLockFile),
+      mTelemetry(TelemetryImpl::sTelemetry)
+  {
   }
 
 private:
-  const char *mFilename;
+  const char* mShutdownTimeFilename;
+  nsCOMPtr<nsIFile> mFailedProfileLockFile;
   nsCOMPtr<TelemetryImpl> mTelemetry;
 
 public:
   void MainThread() {
     mTelemetry->mCachedTelemetryData = true;
     for (unsigned int i = 0, n = mTelemetry->mCallbacks.Count(); i < n; ++i) {
       mTelemetry->mCallbacks[i]->Complete();
     }
     mTelemetry->mCallbacks.Clear();
   }
 
   NS_IMETHOD Run() {
-    mTelemetry->mLastShutdownTime = ReadLastShutdownDuration(mFilename);
+    uint32_t failedLockCount;
+    nsresult rv = LoadFailedLockCount(failedLockCount);
+    NS_ENSURE_SUCCESS(rv, rv);
+    if (failedLockCount) {
+      Telemetry::Accumulate(Telemetry::STARTUP_PROFILE_LOCK_FAILURES,
+                            failedLockCount);
+    }
+    mTelemetry->mLastShutdownTime = 
+      ReadLastShutdownDuration(mShutdownTimeFilename);
     mTelemetry->ReadLateWritesStacks();
     nsCOMPtr<nsIRunnable> e =
       NS_NewRunnableMethod(this, &nsFetchTelemetryData::MainThread);
     NS_ENSURE_STATE(e);
     NS_DispatchToMainThread(e, NS_DISPATCH_NORMAL);
     return NS_OK;
   }
+
+private:
+  nsresult
+  LoadFailedLockCount(uint32_t& failedLockCount)
+  {
+    failedLockCount = 0;
+    nsCOMPtr<nsIInputStream> inStream;
+    nsresult rv;
+    rv = NS_NewLocalFileInputStream(getter_AddRefs(inStream),
+                                    mFailedProfileLockFile,
+                                    PR_RDONLY);
+    NS_ENSURE_SUCCESS(rv, rv);
+    NS_ENSURE_STATE(GetFailedLockCount(inStream, failedLockCount));
+    inStream->Close();
+
+    mFailedProfileLockFile->Remove(false);
+    return NS_OK;
+  }
 };
 
 static TimeStamp gRecordedShutdownStartTime;
 static bool gAlreadyFreedShutdownTimeFileName = false;
 static char *gRecordedShutdownTimeFileName = nullptr;
 
 static char *
 GetShutdownTimeFileName()
@@ -830,25 +895,34 @@ TelemetryImpl::AsyncFetchTelemetryData(n
     do_GetService(NS_STREAMTRANSPORTSERVICE_CONTRACTID);
   if (!targetThread) {
     mCachedTelemetryData = true;
     aCallback->Complete();
     return NS_OK;
   }
 
   // We have to get the filename from the main thread.
-  const char *filename = GetShutdownTimeFileName();
-  if (!filename) {
+  const char *shutdownTimeFilename = GetShutdownTimeFileName();
+  if (!shutdownTimeFilename) {
+    mCachedTelemetryData = true;
+    aCallback->Complete();
+    return NS_OK;
+  }
+
+  nsCOMPtr<nsIFile> failedProfileLockFile;
+  nsresult rv = GetFailedProfileLockFile(getter_AddRefs(failedProfileLockFile));
+  if (NS_FAILED(rv)) {
     mCachedTelemetryData = true;
     aCallback->Complete();
     return NS_OK;
   }
 
   mCallbacks.AppendObject(aCallback);
-  nsCOMPtr<nsIRunnable> event = new nsFetchTelemetryData(filename);
+  nsCOMPtr<nsIRunnable> event = new nsFetchTelemetryData(shutdownTimeFilename,
+                                                         failedProfileLockFile);
 
   targetThread->Dispatch(event, NS_DISPATCH_NORMAL);
   return NS_OK;
 }
 
 TelemetryImpl::TelemetryImpl():
 mHistogramMap(Telemetry::HistogramCount),
 mCanRecord(XRE_GetProcessType() == GeckoProcessType_Default),
@@ -2228,16 +2302,66 @@ GetStackAndModules(const std::vector<uin
     };
     Ret.AddModule(module);
   }
 #endif
 
   return Ret;
 }
 
+void
+WriteFailedProfileLock(nsIFile* aProfileDir)
+{
+  nsCOMPtr<nsIFile> file;
+  nsresult rv = GetFailedProfileLockFile(getter_AddRefs(file), aProfileDir);
+  NS_ENSURE_SUCCESS_VOID(rv);
+  int64_t fileSize = 0;
+  rv = file->GetFileSize(&fileSize);
+  // It's expected that the file might not exist yet
+  if (NS_FAILED(rv) && rv != NS_ERROR_FILE_NOT_FOUND) {
+    return;
+  }
+  nsCOMPtr<nsIFileStream> fileStream;
+  rv = NS_NewLocalFileStream(getter_AddRefs(fileStream), file,
+                             PR_RDWR | PR_CREATE_FILE, 0640);
+  NS_ENSURE_SUCCESS_VOID(rv);
+  NS_ENSURE_TRUE_VOID(fileSize <= kMaxFailedProfileLockFileSize);
+  unsigned int failedLockCount = 0;
+  if (fileSize > 0) {
+    nsCOMPtr<nsIInputStream> inStream = do_QueryInterface(fileStream);
+    NS_ENSURE_TRUE_VOID(inStream);
+    if (!GetFailedLockCount(inStream, failedLockCount)) {
+      failedLockCount = 0;
+    }
+  }
+  ++failedLockCount;
+  nsAutoCString bufStr;
+  bufStr.AppendInt(static_cast<int>(failedLockCount));
+  nsCOMPtr<nsISeekableStream> seekStream = do_QueryInterface(fileStream);
+  NS_ENSURE_TRUE_VOID(seekStream);
+  // If we read in an existing failed lock count, we need to reset the file ptr
+  if (fileSize > 0) {
+    rv = seekStream->Seek(nsISeekableStream::NS_SEEK_SET, 0);
+    NS_ENSURE_SUCCESS_VOID(rv);
+  }
+  nsCOMPtr<nsIOutputStream> outStream = do_QueryInterface(fileStream);
+  uint32_t bytesLeft = bufStr.Length();
+  const char* bytes = bufStr.get();
+  do {
+    uint32_t written = 0;
+    rv = outStream->Write(bytes, bytesLeft, &written);
+    if (NS_FAILED(rv)) {
+      break;
+    }
+    bytes += written;
+    bytesLeft -= written;
+  } while (bytesLeft > 0);
+  seekStream->SetEOF();
+}
+
 } // namespace Telemetry
 } // namespace mozilla
 
 NSMODULE_DEFN(nsTelemetryModule) = &kTelemetryModule;
 
 /**
  * The XRE_TelemetryAdd function is to be used by embedding applications
  * that can't use mozilla::Telemetry::Accumulate() directly.
--- a/toolkit/components/telemetry/Telemetry.h
+++ b/toolkit/components/telemetry/Telemetry.h
@@ -161,11 +161,18 @@ class ProcessedStack;
  * @param callStack - Array of PCs from the hung call stack
  * @param moduleMap - Array of info about modules in memory (for symbolication)
  */
 #if defined(MOZ_ENABLE_PROFILER_SPS)
 void RecordChromeHang(uint32_t duration,
                       ProcessedStack &aStack);
 #endif
 
+/**
+ * Record a failed attempt at locking the user's profile.
+ *
+ * @param aProfileDir The profile directory whose lock attempt failed
+ */
+void WriteFailedProfileLock(nsIFile* aProfileDir);
+
 } // namespace Telemetry
 } // namespace mozilla
 #endif // Telemetry_h__
--- a/toolkit/components/telemetry/tests/unit/test_TelemetryPing.js
+++ b/toolkit/components/telemetry/tests/unit/test_TelemetryPing.js
@@ -22,16 +22,17 @@ const PATH = "/submit/telemetry/test-pin
 const SERVER = "http://localhost:4444";
 const IGNORE_HISTOGRAM = "test::ignore_me";
 const IGNORE_HISTOGRAM_TO_CLONE = "MEMORY_HEAP_ALLOCATED";
 const IGNORE_CLONED_HISTOGRAM = "test::ignore_me_also";
 const ADDON_NAME = "Telemetry test addon";
 const ADDON_HISTOGRAM = "addon-histogram";
 const FLASH_VERSION = "1.1.1.1";
 const SHUTDOWN_TIME = 10000;
+const FAILED_PROFILE_LOCK_ATTEMPTS = 2;
 
 // Constants from prio.h for nsIFileOutputStream.init
 const PR_WRONLY = 0x2;
 const PR_CREATE_FILE = 0x8;
 const PR_TRUNCATE = 0x20;
 const RW_OWNER = 0600;
 
 const BinaryInputStream = Components.Constructor(
@@ -187,16 +188,17 @@ function checkPayload(request, reason, s
     do_check_true(payload.simpleMeasurements.startupSessionRestoreReadBytes > 0);
     do_check_true(payload.simpleMeasurements.startupSessionRestoreWriteBytes > 0);
   }
 
   const TELEMETRY_PING = "TELEMETRY_PING";
   const TELEMETRY_SUCCESS = "TELEMETRY_SUCCESS";
   const TELEMETRY_TEST_FLAG = "TELEMETRY_TEST_FLAG";
   const READ_SAVED_PING_SUCCESS = "READ_SAVED_PING_SUCCESS";
+  const STARTUP_PROFILE_LOCK_FAILURES = "STARTUP_PROFILE_LOCK_FAILURES";
   do_check_true(TELEMETRY_PING in payload.histograms);
   do_check_true(READ_SAVED_PING_SUCCESS in payload.histograms);
   let rh = Telemetry.registeredHistograms;
   for (let name in rh) {
     if (/SQLITE/.test(name) && name in payload.histograms) {
       do_check_true(("STARTUP_" + name) in payload.histograms); 
     }
   }
@@ -227,16 +229,35 @@ function checkPayload(request, reason, s
     sum_squares_hi: 0
   };
   let tc = payload.histograms[TELEMETRY_SUCCESS];
   do_check_eq(uneval(tc), uneval(expected_tc));
 
   let h = payload.histograms[READ_SAVED_PING_SUCCESS];
   do_check_eq(h.values[0], 1);
 
+  if (reason == "saved-session") {
+    const expected_profile_lock_failures = {
+      range: [1, 11],
+      bucket_count: 12,
+      histogram_type: 1,
+      values: {1:0, 2:1, 3:0},
+      sum: 2,
+      sum_squares_lo: 4,
+      sum_squares_hi: 0
+    };
+    let profile_lock_failures = payload.histograms[STARTUP_PROFILE_LOCK_FAILURES];
+    do_check_eq(uneval(profile_lock_failures),
+                uneval(expected_profile_lock_failures));
+    let profileDirectory = Services.dirsvc.get("ProfD", Ci.nsIFile);
+    let failedProfileLocksFile = profileDirectory.clone();
+    failedProfileLocksFile.append("Telemetry.FailedProfileLocks.txt");
+    do_check_true(!failedProfileLocksFile.exists());
+  }
+
   // The ping should include data from memory reporters.  We can't check that
   // this data is correct, because we can't control the values returned by the
   // memory reporters.  But we can at least check that the data is there.
   //
   // It's important to check for the presence of reporters with a mix of units,
   // because TelemetryPing has separate logic for each one.  But we can't
   // currently check UNITS_COUNT_CUMULATIVE or UNITS_PERCENTAGE because
   // Telemetry doesn't touch a memory reporter with these units that's
@@ -434,30 +455,41 @@ function writeStringToFile(file, content
 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 write_fake_failedprofilelocks_file() {
+  let profileDirectory = Services.dirsvc.get("ProfD", Ci.nsIFile);
+  let file = profileDirectory.clone();
+  file.append("Telemetry.FailedProfileLocks.txt");
+  let contents = "" + FAILED_PROFILE_LOCK_ATTEMPTS;
+  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 previously failed to lock a profile a couple times.
+  write_fake_failedprofilelocks_file();
+
   // Make it look like we've shutdown before.
   write_fake_shutdown_file();
 
   Telemetry.asyncFetchTelemetryData(function () {
     actualTest();
   });
 }
 
--- a/toolkit/xre/nsAppRunner.cpp
+++ b/toolkit/xre/nsAppRunner.cpp
@@ -21,16 +21,17 @@
 #endif // MOZ_WIDGET_QT
 
 #include "mozilla/dom/ContentParent.h"
 #include "mozilla/dom/ContentChild.h"
 
 #include "mozilla/Util.h"
 #include "mozilla/Attributes.h"
 #include "mozilla/Likely.h"
+#include "mozilla/Telemetry.h"
 
 #include "nsAppRunner.h"
 #include "mozilla/AppData.h"
 #include "nsUpdateDriver.h"
 #include "ProfileReset.h"
 
 #ifdef MOZ_INSTRUMENT_EVENT_LOOP
 #include "EventTracer.h"
@@ -1704,16 +1705,18 @@ ProfileLockedDialog(nsIFile* aProfileDir
                     nsINativeAppSupport* aNative, nsIProfileLock* *aResult)
 {
   nsresult rv;
 
   ScopedXPCOMStartup xpcom;
   rv = xpcom.Initialize();
   NS_ENSURE_SUCCESS(rv, rv);
 
+  mozilla::Telemetry::WriteFailedProfileLock(aProfileDir);
+
   rv = xpcom.SetWindowCreator(aNative);
   NS_ENSURE_SUCCESS(rv, NS_ERROR_FAILURE);
 
   { //extra scoping is needed so we release these components before xpcom shutdown
     nsCOMPtr<nsIStringBundleService> sbs =
       mozilla::services::GetStringBundleService();
     NS_ENSURE_TRUE(sbs, NS_ERROR_FAILURE);
 
@@ -3491,16 +3494,19 @@ XREMain::XRE_mainStartup(bool* aExitFlag
   NS_ENSURE_SUCCESS(rv, 1);
 
   rv = mProfileLock->GetLocalDirectory(getter_AddRefs(mProfLD));
   NS_ENSURE_SUCCESS(rv, 1);
 
   rv = mDirProvider.SetProfile(mProfD, mProfLD);
   NS_ENSURE_SUCCESS(rv, 1);
 
+  mozilla::Telemetry::Accumulate(
+      mozilla::Telemetry::STARTUP_PROFILE_LOCK_FAILURES, 0);
+
   //////////////////////// NOW WE HAVE A PROFILE ////////////////////////
 
 #ifdef MOZ_CRASHREPORTER
   if (mAppData->flags & NS_XRE_ENABLE_CRASH_REPORTER)
       MakeOrSetMinidumpPath(mProfD);
 #endif
 
   nsAutoCString version;