Refine NetworkTimeTracker histograms

components/network_time/network_time_tracker.cc

 // Copyright 2014 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 "components/network_time/network_time_tracker.h"
 
 #include <stdint.h>
 #include <string>
 #include <utility>
 
@@ skipping 170 matching lines @@
     std::unique_ptr<base::Clock> clock,
     std::unique_ptr<base::TickClock> tick_clock,
     PrefService* pref_service,
     scoped_refptr<net::URLRequestContextGetter> getter)
     : server_url_(kTimeServiceURL),
       max_response_size_(1024),
       backoff_(base::TimeDelta::FromMinutes(kBackoffMinutes)),
       getter_(std::move(getter)),
       clock_(std::move(clock)),
       tick_clock_(std::move(tick_clock)),
-      pref_service_(pref_service) {
+      pref_service_(pref_service),
+      time_query_failed_(false) {
   const base::DictionaryValue* time_mapping =
       pref_service_->GetDictionary(prefs::kNetworkTimeMapping);
   double time_js = 0;
   double ticks_js = 0;
   double network_time_js = 0;
   double uncertainty_js = 0;
   if (time_mapping->GetDouble(kPrefTime, &time_js) &&
       time_mapping->GetDouble(kPrefTicks, &ticks_js) &&
       time_mapping->GetDouble(kPrefUncertainty, &uncertainty_js) &&
       time_mapping->GetDouble(kPrefNetworkTime, &network_time_js)) {
@@ skipping 101 matching lines @@
   DCHECK(timer_.IsRunning());
   return timer_.GetCurrentDelay();
 }
 
 NetworkTimeTracker::NetworkTimeResult NetworkTimeTracker::GetNetworkTime(
     base::Time* network_time,
     base::TimeDelta* uncertainty) const {
   DCHECK(thread_checker_.CalledOnValidThread());
   DCHECK(network_time);
   if (network_time_at_last_measurement_.is_null()) {
-    return NETWORK_TIME_NO_SYNC;
+    if (time_query_failed_) {
+      // Time query attempts have been made in the past and failed.
+      if (time_fetcher_) {
+        // A fetch (not the first attempt) is in progress.
+        return NETWORK_TIME_SUBSEQUENT_SYNC_PENDING;
+      } else {
+        return NETWORK_TIME_NO_SUCCESSFUL_SYNC;
+      }
+    } else {
+      // No time queries have happened yet.
+      if (time_fetcher_) {
+        return NETWORK_TIME_FIRST_SYNC_PENDING;
+      } else {
+        return NETWORK_TIME_NO_SYNC_ATTEMPT;
+      }
+    }
   }
   DCHECK(!ticks_at_last_measurement_.is_null());
   DCHECK(!time_at_last_measurement_.is_null());
   base::TimeDelta tick_delta =
       tick_clock_->NowTicks() - ticks_at_last_measurement_;
   base::TimeDelta time_delta = clock_->Now() - time_at_last_measurement_;
   if (time_delta.InMilliseconds() < 0) {  // Has wall clock run backward?
     DVLOG(1) << "Discarding network time due to wall clock running backward";
     UMA_HISTOGRAM_CUSTOM_TIMES(
         "NetworkTimeTracker.WallClockRanBackwards", time_delta.magnitude(),
@@ skipping 69 matching lines @@
 
   time_fetcher_->Start();
   fetch_started_ = tick_clock_->NowTicks();
 
   timer_.Stop();  // Restarted in OnURLFetchComplete().
 }
 
 bool NetworkTimeTracker::UpdateTimeFromResponse() {
   if (time_fetcher_->GetStatus().status() != net::URLRequestStatus::SUCCESS ||
       time_fetcher_->GetResponseCode() != 200) {
+    time_query_failed_ = true;
     DVLOG(1) << "fetch failed, status=" << time_fetcher_->GetStatus().status()
              << ",code=" << time_fetcher_->GetResponseCode();
     // The error code is negated because net errors are negative, but
     // the corresponding histogram enum is positive.
     UMA_HISTOGRAM_SPARSE_SLOWLY("NetworkTimeTracker.UpdateTimeFetchFailed",
                                 -time_fetcher_->GetStatus().error());
     return false;
   }
 
   std::string response_body;
   if (!time_fetcher_->GetResponseAsString(&response_body)) {
     DVLOG(1) << "failed to get response";
+    time_query_failed_ = true;
     return false;
   }
   DCHECK(query_signer_);
   if (!query_signer_->ValidateResponse(response_body,
                                        GetServerProof(time_fetcher_.get()))) {
     DVLOG(1) << "invalid signature";
+    time_query_failed_ = true;
     RecordFetchValidHistogram(false);
     return false;
   }
   response_body = response_body.substr(5);  // Skips leading )]}'\n
   std::unique_ptr<base::Value> value = base::JSONReader::Read(response_body);
   if (!value) {
     DVLOG(1) << "bad JSON";
+    time_query_failed_ = true;
     RecordFetchValidHistogram(false);
     return false;
   }
   const base::DictionaryValue* dict;
   if (!value->GetAsDictionary(&dict)) {
     DVLOG(1) << "not a dictionary";
+    time_query_failed_ = true;
     RecordFetchValidHistogram(false);
     return false;
   }
   double current_time_millis;
   if (!dict->GetDouble("current_time_millis", &current_time_millis)) {
     DVLOG(1) << "no current_time_millis";
+    time_query_failed_ = true;
     RecordFetchValidHistogram(false);
     return false;
   }
 
   RecordFetchValidHistogram(true);
 
   // There is a "server_nonce" key here too, but it serves no purpose other than
   // to make the server's response unpredictable.
   base::Time current_time = base::Time::FromJsTime(current_time_millis);
   base::TimeDelta resolution =
       base::TimeDelta::FromMilliseconds(1) +
       base::TimeDelta::FromSeconds(kTimeServerMaxSkewSeconds);
   base::TimeDelta latency = tick_clock_->NowTicks() - fetch_started_;
+  UMA_HISTOGRAM_TIMES("NetworkTimeTracker.TimeQueryLatency", latency);
   UpdateNetworkTime(current_time, resolution, latency, tick_clock_->NowTicks());
   return true;
 }
 
 void NetworkTimeTracker::OnURLFetchComplete(const net::URLFetcher* source) {
   DCHECK(thread_checker_.CalledOnValidThread());
   DCHECK(time_fetcher_);
   DCHECK_EQ(source, time_fetcher_.get());
 
   // After completion of a query, whether succeeded or failed, go to sleep for a
   // long time.
   if (!UpdateTimeFromResponse()) {  // On error, back off.

[mab, 2016/10/14 06:35:01]

Could you set time_query_failed_ here?

[estark, 2016/10/14 07:23:46]

Oh, yes, that's much better, thanks. Done.

     if (backoff_ < base::TimeDelta::FromDays(2)) {
       backoff_ *= 2;
     }
   } else {
     backoff_ = base::TimeDelta::FromMinutes(kBackoffMinutes);
   }
   QueueCheckTime(backoff_);
   time_fetcher_.reset();
   if (run_loop_for_testing_ != nullptr)
     run_loop_for_testing_->QuitWhenIdle();
@@ skipping 14 matching lines @@
   base::Time network_time;
   if (GetNetworkTime(&network_time, nullptr) != NETWORK_TIME_AVAILABLE) {
     return true;
   }
 
   // Otherwise, make the decision at random.
   return base::RandDouble() < RandomQueryProbability();
 }
 
 }  // namespace network_time