Add NetworkTimeTracker UMA 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>
 
 #include "base/feature_list.h"
 #include "base/i18n/time_formatting.h"
 #include "base/json/json_reader.h"
 #include "base/logging.h"
 #include "base/message_loop/message_loop.h"
+#include "base/metrics/histogram_macros.h"
+#include "base/metrics/sparse_histogram.h"
 #include "base/rand_util.h"
 #include "base/run_loop.h"
 #include "base/strings/string_number_conversions.h"
 #include "base/strings/utf_string_conversions.h"
 #include "base/time/tick_clock.h"
 #include "build/build_config.h"
 #include "components/client_update_protocol/ecdsa.h"
 #include "components/network_time/network_time_pref_names.h"
 #include "components/prefs/pref_registry_simple.h"
 #include "components/prefs/pref_service.h"
@@ skipping 334 matching lines @@
   time_fetcher_->SaveResponseWithWriter(
       std::unique_ptr<net::URLFetcherResponseWriter>(
           new SizeLimitingStringWriter(max_response_size_)));
   DCHECK(getter_);
   time_fetcher_->SetRequestContext(getter_.get());
   // Not expecting any cookies, but just in case.
   time_fetcher_->SetLoadFlags(net::LOAD_BYPASS_CACHE | net::LOAD_DISABLE_CACHE |
                               net::LOAD_DO_NOT_SAVE_COOKIES |
                               net::LOAD_DO_NOT_SEND_COOKIES |
                               net::LOAD_DO_NOT_SEND_AUTH_DATA);
+
+  UMA_HISTOGRAM_BOOLEAN("NetworkTimeTracker.UpdateTimeFetchAttempted", true);

[mab, 2016/07/26 21:05:48]

Is a Boolean the idiomatic way to count things?

[estark, 2016/07/26 21:21:27]

I have been told that it is, though admittedly I can't remember who told me that
and don't think it's documented anywhere. There are other examples of this,
though
(https://cs.chromium.org/chromium/src/chrome/browser/chromeos/first_run/first_...,
https://cs.chromium.org/chromium/src/chrome/browser/extensions/api/gcm/gcm_ap...,
https://cs.chromium.org/chromium/src/chrome/browser/extensions/chrome_content...,
https://cs.chromium.org/chromium/src/chrome/browser/profiles/profile_manager....).

[mab, 2016/07/27 02:47:56]

Ack.

+
   time_fetcher_->Start();
   fetch_started_ = tick_clock_->NowTicks();
 
   timer_.Stop();  // Restarted in OnURLFetchComplete().
 }
 
 bool NetworkTimeTracker::UpdateTimeFromResponse() {
-  if (time_fetcher_->GetStatus().status() != net::URLRequestStatus::SUCCESS &&
+  if (time_fetcher_->GetStatus().status() != net::URLRequestStatus::SUCCESS ||

[mab, 2016/07/26 21:05:48]

Yikes, good catch.

[mab, 2016/07/28 06:58:54]

(I take it your metrics would have caught this bug?)

[estark, 2016/07/28 18:27:58]

Presumably, yeah -- one of the tests I added failed.

       time_fetcher_->GetResponseCode() != 200) {
     DVLOG(1) << "fetch failed, status=" << time_fetcher_->GetStatus().status()
              << ",code=" << time_fetcher_->GetResponseCode();
+    UMA_HISTOGRAM_SPARSE_SLOWLY("NetworkTimeTracker.UpdateTimeFetchFailed",
+                                -time_fetcher_->GetStatus().error());

[mab, 2016/07/26 21:05:48]

Why negative?  Is that the convention for errors?

Is error() well-defined for all cases?

[estark, 2016/07/26 21:21:26]

Net error codes are negative (see net/base/net_error_list.h) but histograms.xml
defines a parallel enum that is positive
(https://cs.chromium.org/chromium/src/tools/metrics/histograms/histograms.xml?...).

:(

I'll add a comment.
Believe so. It will be net::OK in some cases (e.g. connection succeeded but
server responded with a 500) but I think that's okay. If we are getting large
numbers of UpdateTimeFetchFailed with net::OK as the error code, then I think we
should be able to diagnose on the server what non-200 status codes it's sending.

[mab, 2016/07/27 02:47:56]

OK, SG.

     return false;
   }
 
+  UMA_HISTOGRAM_BOOLEAN("NetworkTimeTracker.UpdateTimeFetchSucceeded", true);

[mab, 2016/07/26 21:05:48]

I think you could get away with having just one histogram that records just one
outcome (including success) per attempt.  That feels easier to read.

In particular, do you have a theory about how an attempt would be started
without subsequently invoking UpdateTimeFromResponse()?  Or is part of the goal
here to detect whether this is happening?  It would be nice to be explicit about
this detail.

[estark, 2016/07/26 21:21:26]

By "just one histogram", do you mean collapsing UpdateTimeFetchAttempted and
UpdateTimeFetchSucceeded into one, or collapsing all 4 into one (including
UpdateTimeFetchFailed and UpdateTimeFetchValid)? If the latter, I'm not sure how
I would collapse UpdateTimeFetchFailed and continue to record the error code.

I could collapse UpdateTimeFetchSucceeded and UpdateTimeFetchValid into one very
easily, I should at the very least do that.
 
As for why I separated Attempted and Succeeded, I was thinking that a request
could hang in some way that messes things up, e.g. we are issuing a query before
the previous one finishes or something like that. Do you think that sounds
remotely plausible? If so I'll leave them separate but add a comment about why
they are separate.

[mab, 2016/07/27 02:47:56]

I meant collapse all 4 into one.  Is the problem that there is no way to reserve
values outside the space of valid error() codes, to represent various the
various non-transport-error possibilities?  Or is just that this would be ugly? 
(I don't reject these arguments; just want to understand what you're saying.)

To your second point: I'm trying to imagine what we could learn from the
numbers.  It seems implausible that Succeeded would be greater than Attempted. 
They might be ~equal.  Or, possibly, Attempted might be greater than Failed +
Succeeded by enough that it's weird.

I guess I don't object to checking for that possibility, but I posit that this
can only be the result of a logic error.  (And your comment makes me think you
may agree with this.)  If so, perhaps it makes sense to remove the Attempted
counter in the future if we don't see the condition it's looking for.

[estark, 2016/07/27 17:50:56]

Yeah, I don't know of any way to do that... but a metrics owner will have to
approve the histograms.xml changes so maybe they will come along and enlighten
me. :)
That sounds reasonable, and yes I think I agree with you that it would be a
logic error. How about we put it on Canary for a few days and then remove it if
it's not interesting?

[mab, 2016/07/28 06:58:55]

Sure.  Can you document that intent somewhere outside this CL?

[estark, 2016/07/28 18:27:58]

Filed https://crbug.com/632419

+
   std::string response_body;
   if (!time_fetcher_->GetResponseAsString(&response_body)) {
     DVLOG(1) << "failed to get response";
     return false;
   }
   DCHECK(query_signer_);
   if (!query_signer_->ValidateResponse(response_body,
                                        GetServerProof(time_fetcher_.get()))) {
     DVLOG(1) << "invalid signature";
     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";
     return false;
   }
   const base::DictionaryValue* dict;
   if (!value->GetAsDictionary(&dict)) {
     DVLOG(1) << "not a dictionary";
     return false;
   }
   double current_time_millis;
   if (!dict->GetDouble("current_time_millis", &current_time_millis)) {
     DVLOG(1) << "no current_time_millis";
     return false;
   }
+
+  UMA_HISTOGRAM_BOOLEAN("NetworkTimeTracker.UpdateTimeFetchValid", 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_;
   UpdateNetworkTime(current_time, resolution, latency, tick_clock_->NowTicks());
   return true;
 }
@@ skipping 35 matching lines @@
   base::Time network_time;
   if (!GetNetworkTime(&network_time, nullptr)) {
     return true;
   }
 
   // Otherwise, make the decision at random.
   return base::RandDouble() < RandomQueryProbability();
 }
 
 }  // namespace network_time