Bug 799267 - Telemetry for Cert Verification (PKIX and classic) in SSLServerCertVerification r=bsmith
☠☠ backed out by 21bd64a6b46d ☠ ☠
authorCamilo Viecco <cviecco@mozilla.com>
Wed, 19 Dec 2012 13:05:43 -0800
changeset 125651 851fd44eeb42b81c822a40e6baf60d16056b90cd
parent 125650 8c794d4722f7e8022a9ab80075c98afdd5677032
child 125652 4fcba9b6e0f8770cf9615e89c8b7de6f27f88b1b
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)
reviewersbsmith
bugs799267
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 799267 - Telemetry for Cert Verification (PKIX and classic) in SSLServerCertVerification r=bsmith
security/manager/ssl/src/SSLServerCertVerification.cpp
toolkit/components/telemetry/Histograms.json
--- a/security/manager/ssl/src/SSLServerCertVerification.cpp
+++ b/security/manager/ssl/src/SSLServerCertVerification.cpp
@@ -100,16 +100,18 @@
 #include "nsIStrictTransportSecurityService.h"
 #include "nsNSSComponent.h"
 #include "nsNSSCleaner.h"
 #include "nsRecentBadCerts.h"
 #include "nsNSSIOLayer.h"
 #include "nsNSSShutDown.h"
 
 #include "mozilla/Assertions.h"
+#include "mozilla/Mutex.h"
+#include "mozilla/Telemetry.h"
 #include "nsIThreadPool.h"
 #include "nsXPCOMCIDInternal.h"
 #include "nsComponentManagerUtils.h"
 #include "nsServiceManagerUtils.h"
 #include "nsIConsoleService.h"
 #include "PSMRunnable.h"
 #include "ScopedNSSTypes.h"
 #include "SharedSSLState.h"
@@ -128,31 +130,38 @@ namespace mozilla { namespace psm {
 namespace {
 
 NS_DEFINE_CID(kNSSComponentCID, NS_NSSCOMPONENT_CID);
 
 NSSCleanupAutoPtrClass_WithParam(PLArenaPool, PORT_FreeArena, FalseParam, false)
 
 // do not use a nsCOMPtr to avoid static initializer/destructor
 nsIThreadPool * gCertVerificationThreadPool = nullptr;
+
+// We avoid using a mutex for the success case to avoid lock-related
+// performance issues. However, we do use a lock in the error case to simplify
+// the code, since performance in the error case is not important.
+Mutex *gSSLVerificationTelemetryMutex = nullptr;
+
 } // unnamed namespace
 
 // Called when the socket transport thread starts, to initialize the SSL cert
 // verification thread pool. By tying the thread pool startup/shutdown directly
 // to the STS thread's lifetime, we ensure that they are *always* available for
 // SSL connections and that there are no races during startup and especially
 // shutdown. (Previously, we have had multiple problems with races in PSM
 // background threads, and the race-prevention/shutdown logic used there is
 // brittle. Since this service is critical to things like downloading updates,
 // we take no chances.) Also, by doing things this way, we avoid the need for
 // locks, since gCertVerificationThreadPool is only ever accessed on the socket
 // transport thread.
 void
 InitializeSSLServerCertVerificationThreads()
 {
+  gSSLVerificationTelemetryMutex = new Mutex("SSLVerificationTelemetryMutex");
   // TODO: tuning, make parameters preferences
   // XXX: instantiate nsThreadPool directly, to make this more bulletproof.
   // Currently, the nsThreadPool.h header isn't exported for us to do so.
   nsresult rv = CallCreateInstance(NS_THREADPOOL_CONTRACTID,
                                    &gCertVerificationThreadPool);
   if (NS_FAILED(rv)) {
     NS_WARNING("Failed to create SSL cert verification threads.");
     return;
@@ -213,25 +222,29 @@ LogInvalidCertError(TransportSecurityInf
 // descriptor that is waiting for this result.
 class SSLServerCertVerificationResult : public nsRunnable
 {
 public:
   NS_DECL_NSIRUNNABLE
 
   SSLServerCertVerificationResult(TransportSecurityInfo * infoObject,
                                   PRErrorCode errorCode,
-                                  SSLErrorMessageType errorMessageType = 
+                                  Telemetry::ID telemetryID = Telemetry::HistogramCount,
+                                  uint32_t telemetryValue = -1,
+                                  SSLErrorMessageType errorMessageType =
                                       PlainErrorMessage);
 
   void Dispatch();
 private:
   const RefPtr<TransportSecurityInfo> mInfoObject;
 public:
   const PRErrorCode mErrorCode;
   const SSLErrorMessageType mErrorMessageType;
+  const Telemetry::ID mTelemetryID;
+  const uint32_t mTelemetryValue;
 };
 
 class CertErrorRunnable : public SyncRunnableBase
 {
  public:
   CertErrorRunnable(const void * fdForLogging,
                     nsIX509Cert * cert,
                     TransportSecurityInfo * infoObject,
@@ -388,16 +401,18 @@ CertErrorRunnable::CheckCertOverrides()
   PRErrorCode errorCodeToReport = mErrorCodeTrust    ? mErrorCodeTrust
                                 : mErrorCodeMismatch ? mErrorCodeMismatch
                                 : mErrorCodeExpired  ? mErrorCodeExpired
                                 : mDefaultErrorCodeToReport;
                                 
   SSLServerCertVerificationResult *result = 
     new SSLServerCertVerificationResult(mInfoObject, 
                                         errorCodeToReport,
+                                        Telemetry::HistogramCount,
+                                        -1,
                                         OverridableCertErrorMessage);
 
   LogInvalidCertError(mInfoObject,
                       nsDependentCString(mInfoObject->GetHostName()),
                       hostWithPortString,
                       port,
                       result->mErrorCode,
                       result->mErrorMessageType,
@@ -622,25 +637,27 @@ private:
   SSLServerCertVerificationJob(const void * fdForLogging,
                                TransportSecurityInfo * infoObject, 
                                CERTCertificate * cert,
                                uint32_t providerFlags);
   const void * const mFdForLogging;
   const RefPtr<TransportSecurityInfo> mInfoObject;
   const ScopedCERTCertificate mCert;
   const uint32_t mProviderFlags;
+  const TimeStamp mJobStartTime;
 };
 
 SSLServerCertVerificationJob::SSLServerCertVerificationJob(
     const void * fdForLogging, TransportSecurityInfo * infoObject,
     CERTCertificate * cert, uint32_t providerFlags)
   : mFdForLogging(fdForLogging)
   , mInfoObject(infoObject)
   , mCert(CERT_DupCertificate(cert))
   , mProviderFlags(providerFlags)
+  , mJobStartTime(TimeStamp::Now())
 {
 }
 
 SECStatus
 PSM_SSL_PKIX_AuthCertificate(CERTCertificate *peerCert, void * pinarg,
                              const char * hostname)
 {
     SECStatus          rv;
@@ -1045,23 +1062,48 @@ SSLServerCertVerificationJob::Run()
   if (mInfoObject->isAlreadyShutDown()) {
     error = SEC_ERROR_USER_CANCELLED;
   } else {
     // Reset the error code here so we can detect if AuthCertificate fails to
     // set the error code if/when it fails.
     PR_SetError(0, 0); 
     SECStatus rv = AuthCertificate(mInfoObject, mCert, mProviderFlags);
     if (rv == SECSuccess) {
+      uint32_t interval = (uint32_t) ((TimeStamp::Now() - mJobStartTime).ToMilliseconds());
+      Telemetry::ID telemetryID;
+      if(nsNSSComponent::globalConstFlagUsePKIXVerification){
+        telemetryID = Telemetry::SSL_SUCCESFUL_CERT_VALIDATION_TIME_LIBPKIX;
+      }
+      else{
+        telemetryID = Telemetry::SSL_SUCCESFUL_CERT_VALIDATION_TIME_CLASSIC;
+      }
       RefPtr<SSLServerCertVerificationResult> restart(
-        new SSLServerCertVerificationResult(mInfoObject, 0));
+        new SSLServerCertVerificationResult(mInfoObject, 0,
+                                            telemetryID, interval));
       restart->Dispatch();
       return NS_OK;
     }
 
+    // Note: the interval is not calculated once as PR_GetError MUST be called
+    // before any other  function call
     error = PR_GetError();
+    {
+      TimeStamp now = TimeStamp::Now();
+      Telemetry::ID telemetryID;
+      if(nsNSSComponent::globalConstFlagUsePKIXVerification){
+        telemetryID = Telemetry::SSL_INITIAL_FAILED_CERT_VALIDATION_TIME_LIBPKIX;
+      }
+      else{
+        telemetryID = Telemetry::SSL_INITIAL_FAILED_CERT_VALIDATION_TIME_CLASSIC;
+      }
+      MutexAutoLock telemetryMutex(*gSSLVerificationTelemetryMutex);
+      Telemetry::AccumulateTimeDelta(telemetryID,
+                                     mJobStartTime,
+                                     now);
+    }
     if (error != 0) {
       RefPtr<CertErrorRunnable> runnable(CreateCertErrorRunnable(
         error, mInfoObject, mCert, mFdForLogging, mProviderFlags));
       if (!runnable) {
         // CreateCertErrorRunnable set a new error code
         error = PR_GetError(); 
       } else {
         // We must block the the socket transport service thread while the
@@ -1269,21 +1311,29 @@ void EnsureServerVerificationInitialized
 
   RefPtr<InitializeIdentityInfo> initJob = new InitializeIdentityInfo();
   if (gCertVerificationThreadPool)
     gCertVerificationThreadPool->Dispatch(initJob, NS_DISPATCH_NORMAL);
 }
 
 SSLServerCertVerificationResult::SSLServerCertVerificationResult(
         TransportSecurityInfo * infoObject, PRErrorCode errorCode,
+        Telemetry::ID telemetryID, uint32_t telemetryValue,
         SSLErrorMessageType errorMessageType)
   : mInfoObject(infoObject)
   , mErrorCode(errorCode)
   , mErrorMessageType(errorMessageType)
+  , mTelemetryID(telemetryID)
+  , mTelemetryValue(telemetryValue)
 {
+// We accumulate telemetry for (only) successful validations on the main thread
+// to avoid adversely affecting performance by acquiring the mutex that we use
+// when accumulating the telemetry for unsuccessful validations. Unsuccessful
+// validations times are accumulated elsewhere.
+MOZ_ASSERT(telemetryID == Telemetry::HistogramCount || errorCode == 0);
 }
 
 void
 SSLServerCertVerificationResult::Dispatch()
 {
   nsresult rv;
   nsCOMPtr<nsIEventTarget> stsTarget
     = do_GetService(NS_SOCKETTRANSPORTSERVICE_CONTRACTID, &rv);
@@ -1293,15 +1343,18 @@ SSLServerCertVerificationResult::Dispatc
   NS_ASSERTION(NS_SUCCEEDED(rv), 
                "Failed to dispatch SSLServerCertVerificationResult");
 }
 
 NS_IMETHODIMP
 SSLServerCertVerificationResult::Run()
 {
   // TODO: Assert that we're on the socket transport thread
+  if (mTelemetryID != Telemetry::HistogramCount) {
+     Telemetry::Accumulate(mTelemetryID, mTelemetryValue);
+  }
   // XXX: This cast will be removed by the next patch
   ((nsNSSSocketInfo *) mInfoObject.get())
     ->SetCertVerificationResult(mErrorCode, mErrorMessageType);
   return NS_OK;
 }
 
 } } // namespace mozilla::psm
--- a/toolkit/components/telemetry/Histograms.json
+++ b/toolkit/components/telemetry/Histograms.json
@@ -2500,10 +2500,34 @@
     "n_buckets": 15,
     "description": "Time (ms) it takes to figure out extension last modified time"
   },
   "TELEMETRY_MEMORY_REPORTER_MS": {
     "kind": "exponential",
     "high": "5000",
     "n_buckets": 10,
     "description": "Time (ms) it takes to run memory reporters when sending a telemetry ping"
+  },
+  "SSL_SUCCESFUL_CERT_VALIDATION_TIME_LIBPKIX" : {
+    "kind": "exponential",
+    "high": "60000",
+    "n_buckets": 50,
+    "description": "Time spent on a successful cert verification in libpix mode (ms)"
+  },
+  "SSL_SUCCESFUL_CERT_VALIDATION_TIME_CLASSIC" : {
+    "kind": "exponential",
+    "high": "60000",
+    "n_buckets": 50,
+    "description": "Time spent on a successful cert  verification in classic mode (ms)"
+  },
+  "SSL_INITIAL_FAILED_CERT_VALIDATION_TIME_LIBPKIX" : {
+    "kind": "exponential",
+    "high": "60000",
+    "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)"
   }
 }