diff --git a/security/manager/ssl/src/SSLServerCertVerification.cpp b/security/manager/ssl/src/SSLServerCertVerification.cpp index c03f003b30e3..0cb3f51bf3cb 100644 --- a/security/manager/ssl/src/SSLServerCertVerification.cpp +++ b/security/manager/ssl/src/SSLServerCertVerification.cpp @@ -105,6 +105,8 @@ #include "nsNSSShutDown.h" #include "mozilla/Assertions.h" +#include "mozilla/Mutex.h" +#include "mozilla/Telemetry.h" #include "nsIThreadPool.h" #include "nsXPCOMCIDInternal.h" #include "nsComponentManagerUtils.h" @@ -133,6 +135,12 @@ 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 @@ -148,6 +156,7 @@ nsIThreadPool * gCertVerificationThreadPool = nullptr; 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. @@ -218,7 +227,9 @@ public: SSLServerCertVerificationResult(TransportSecurityInfo * infoObject, PRErrorCode errorCode, - SSLErrorMessageType errorMessageType = + Telemetry::ID telemetryID = Telemetry::HistogramCount, + uint32_t telemetryValue = -1, + SSLErrorMessageType errorMessageType = PlainErrorMessage); void Dispatch(); @@ -227,6 +238,8 @@ private: public: const PRErrorCode mErrorCode; const SSLErrorMessageType mErrorMessageType; + const Telemetry::ID mTelemetryID; + const uint32_t mTelemetryValue; }; class CertErrorRunnable : public SyncRunnableBase @@ -393,6 +406,8 @@ CertErrorRunnable::CheckCertOverrides() SSLServerCertVerificationResult *result = new SSLServerCertVerificationResult(mInfoObject, errorCodeToReport, + Telemetry::HistogramCount, + -1, OverridableCertErrorMessage); LogInvalidCertError(mInfoObject, @@ -627,6 +642,7 @@ private: const RefPtr mInfoObject; const ScopedCERTCertificate mCert; const uint32_t mProviderFlags; + const TimeStamp mJobStartTime; }; SSLServerCertVerificationJob::SSLServerCertVerificationJob( @@ -636,6 +652,7 @@ SSLServerCertVerificationJob::SSLServerCertVerificationJob( , mInfoObject(infoObject) , mCert(CERT_DupCertificate(cert)) , mProviderFlags(providerFlags) + , mJobStartTime(TimeStamp::Now()) { } @@ -1050,13 +1067,38 @@ SSLServerCertVerificationJob::Run() 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 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 runnable(CreateCertErrorRunnable( error, mInfoObject, mCert, mFdForLogging, mProviderFlags)); @@ -1274,11 +1316,19 @@ void EnsureServerVerificationInitialized() 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 @@ -1298,6 +1348,9 @@ 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); diff --git a/toolkit/components/telemetry/Histograms.json b/toolkit/components/telemetry/Histograms.json index a66ba9d7be4c..18ca9ff877d8 100644 --- a/toolkit/components/telemetry/Histograms.json +++ b/toolkit/components/telemetry/Histograms.json @@ -2505,5 +2505,29 @@ "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)" } }