Add Net.CertVerifier_First_Job_Latency metric.

net/cert/multi_threaded_cert_verifier.cc

 // Copyright (c) 2012 The Chromium Authors. All rights reserved.
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
 #include "net/cert/multi_threaded_cert_verifier.h"
 
 #include <algorithm>
 
 #include "base/bind.h"
 #include "base/bind_helpers.h"
@@ skipping 302 matching lines @@
   CertVerifyResult verify_result_;
 
   DISALLOW_COPY_AND_ASSIGN(CertVerifierWorker);
 };
 
 // A CertVerifierJob is a one-to-one counterpart of a CertVerifierWorker. It
 // lives only on the CertVerifier's origin message loop.
 class CertVerifierJob {
  public:
   CertVerifierJob(CertVerifierWorker* worker,
+                  bool is_first_job,
                   const BoundNetLog& net_log)
       : start_time_(base::TimeTicks::Now()),
         worker_(worker),
+        is_first_job_(is_first_job),
         net_log_(net_log) {
     net_log_.BeginEvent(
         NetLog::TYPE_CERT_VERIFIER_JOB,
         base::Bind(&NetLogX509CertificateCallback,
                    base::Unretained(worker_->certificate())));
   }
 
   ~CertVerifierJob() {
     if (worker_) {
       net_log_.AddEvent(NetLog::TYPE_CANCELLED);
       net_log_.EndEvent(NetLog::TYPE_CERT_VERIFIER_JOB);
       worker_->Cancel();
       DeleteAllCanceled();
     }
   }
 
   void AddRequest(CertVerifierRequest* request) {
     request->net_log().AddEvent(
         NetLog::TYPE_CERT_VERIFIER_REQUEST_BOUND_TO_JOB,
         net_log_.source().ToEventParametersCallback());
 
     requests_.push_back(request);
   }
 
   void HandleResult(
       const MultiThreadedCertVerifier::CachedResult& verify_result) {
     worker_ = NULL;
     net_log_.EndEvent(NetLog::TYPE_CERT_VERIFIER_JOB);
+    base::TimeDelta latency = base::TimeTicks::Now() - start_time_;
     UMA_HISTOGRAM_CUSTOM_TIMES("Net.CertVerifier_Job_Latency",
-                               base::TimeTicks::Now() - start_time_,
+                               latency,
                                base::TimeDelta::FromMilliseconds(1),
                                base::TimeDelta::FromMinutes(10),
                                100);
+    if (is_first_job_) {
+      UMA_HISTOGRAM_CUSTOM_TIMES("Net.CertVerifier_First_Job_Latency",
+                                 latency,
+                                 base::TimeDelta::FromMilliseconds(1),
+                                 base::TimeDelta::FromMinutes(10),
+                                 100);
+    }
     PostAll(verify_result);
   }
 
  private:
   void PostAll(const MultiThreadedCertVerifier::CachedResult& verify_result) {
     std::vector<CertVerifierRequest*> requests;
     requests_.swap(requests);
 
     for (std::vector<CertVerifierRequest*>::iterator
          i = requests.begin(); i != requests.end(); i++) {
       (*i)->Post(verify_result);
       // Post() causes the CertVerifierRequest to delete itself.
     }
   }
 
   void DeleteAllCanceled() {
     for (std::vector<CertVerifierRequest*>::iterator
          i = requests_.begin(); i != requests_.end(); i++) {
       if ((*i)->canceled()) {
         delete *i;
       } else {
         LOG(DFATAL) << "CertVerifierRequest leaked!";
       }
     }
   }
 
   const base::TimeTicks start_time_;
   std::vector<CertVerifierRequest*> requests_;
   CertVerifierWorker* worker_;
+  bool is_first_job_;
   const BoundNetLog net_log_;
 };
 
 MultiThreadedCertVerifier::MultiThreadedCertVerifier(
     CertVerifyProc* verify_proc)
     : cache_(kMaxCacheEntries),
       requests_(0),
       cache_hits_(0),
       inflight_joins_(0),
       verify_proc_(verify_proc),
@@ skipping 58 matching lines @@
     // Need to make a new request.
     CertVerifierWorker* worker =
         new CertVerifierWorker(verify_proc_.get(),
                                cert,
                                hostname,
                                flags,
                                crl_set,
                                additional_trust_anchors,
                                this);
     job = new CertVerifierJob(
-        worker,
+        worker, requests_ == 1,
         BoundNetLog::Make(net_log.net_log(), NetLog::SOURCE_CERT_VERIFIER_JOB));
     if (!worker->Start()) {
       delete job;
       delete worker;
       *out_req = NULL;
       // TODO(wtc): log to the NetLog.
       LOG(ERROR) << "CertVerifierWorker couldn't be started.";
       return ERR_INSUFFICIENT_RESOURCES;  // Just a guess.
     }
     inflight_.insert(std::make_pair(key, job));
@@ skipping 65 matching lines @@
   cache_.Put(
       key, cached_result, CacheValidityPeriod(now),
       CacheValidityPeriod(now, now + base::TimeDelta::FromSeconds(kTTLSecs)));
 
   std::map<RequestParams, CertVerifierJob*>::iterator j;
   j = inflight_.find(key);
   if (j == inflight_.end()) {
     NOTREACHED();
     return;
   }
   CertVerifierJob* job = j->second;

[Ryan Sleevi, 2014/04/08 20:19:01]

Rather than at a bool member to the CertVerifierJob (which will increase the
time of all jobs), why not store the time&first job in the CertVerifier, and do
the comparison here in HandleResult? That will reduce the run-time memory
overhead, and still offer the same run-time CPU overhead (a comparison to a
pointer, with presumably a sentinel/dead value to indicate you've recorded
things)

[davidben, 2014/04/08 23:33:21]

Done.

   inflight_.erase(j);
 
   job->HandleResult(cached_result);
   delete job;
 }
 
 void MultiThreadedCertVerifier::OnCACertChanged(
     const X509Certificate* cert) {
   DCHECK(CalledOnValidThread());
 
   ClearCache();
 }
 
 }  // namespace net