Record latencies of connection and arrival of first message in UMA

components/gcm_driver/gcm_stats_recorder_impl.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/gcm_driver/gcm_stats_recorder_impl.h"
 
 #include <deque>
 #include <vector>
 
 #include "base/format_macros.h"
@@ skipping 125 matching lines @@
     default:
       NOTREACHED();
       return "UNKNOWN_STATUS";
   }
 }
 
 }  // namespace
 
 GCMStatsRecorderImpl::GCMStatsRecorderImpl()
     : is_recording_(false),
-      delegate_(NULL) {
+      delegate_(NULL),
+      data_message_received_since_connected_(false) {
 }
 
 GCMStatsRecorderImpl::~GCMStatsRecorderImpl() {
 }
 
 void GCMStatsRecorderImpl::SetRecording(bool recording) {
   is_recording_ = recording;
 }
 
 void GCMStatsRecorderImpl::SetDelegate(Delegate* delegate) {
@@ skipping 60 matching lines @@
     const std::string& details) {
   ConnectionActivity data;
   ConnectionActivity* inserted_data = InsertCircularBuffer(
       &connection_activities_, data);
   inserted_data->event = event;
   inserted_data->details = details;
   NotifyActivityRecorded();
 }
 
 void GCMStatsRecorderImpl::RecordConnectionInitiated(const std::string& host) {
+  last_connection_initiation_time_ = base::Time::Now();

[jar (doing other things), 2014/07/30 21:25:06]

I'd strongly suggest using TimeTicks rather than Time.  This ensures that your
clock is monotonic, and won't jump around as folks change their clocks.

[juyik, 2014/07/31 20:55:34]

Done.

+  last_connection_success_time_ = base::Time();
+  data_message_received_since_connected_ = false;
   if (!is_recording_)
     return;
   RecordConnection("Connection initiated", host);
 }
 
 void GCMStatsRecorderImpl::RecordConnectionDelayedDueToBackoff(
     int64 delay_msec) {
   if (!is_recording_)
     return;
   RecordConnection("Connection backoff",
                    base::StringPrintf("Delayed for %" PRId64 " msec",
                                       delay_msec));
 }
 
 void GCMStatsRecorderImpl::RecordConnectionSuccess() {
+  DCHECK(!last_connection_initiation_time_.is_null());
+  UMA_HISTOGRAM_COUNTS(

[jar (doing other things), 2014/07/30 21:25:06]

nit: use UMA_HISTOGRAM_TIMES() and it will take care of the conversion from a
TimeDelta (the difference of two times) to milliseconds.

If you expect the duration to potentially be larger than 10 seconds... then
better yet would be UMA_HISTOGRAM_LONG_TIMES() which will get you up to several
minutes nicely.

If you really want a wider range, then UMA_HISTOGRAM_CUSTOM_TIMES() will give
you more flexibility, but don't go for much more than 50 buckets, and certainly
not more than 100.

[juyik, 2014/07/31 20:55:34]

Done.

+      "GCM.ConnectionLatency",
+      (base::Time::Now() - last_connection_initiation_time_).InMilliseconds());
+  last_connection_success_time_ = base::Time::Now();
+  last_connection_initiation_time_ = base::Time();
   if (!is_recording_)
     return;
   RecordConnection("Connection succeeded", std::string());
 }
 
 void GCMStatsRecorderImpl::RecordConnectionFailure(int network_error) {
   if (!is_recording_)
     return;
   RecordConnection("Connection failed",
                    base::StringPrintf("With network error %d", network_error));
@@ skipping 117 matching lines @@
     last_received_data_message_burst_start_time_ = new_timestamp;
   } else if ((new_timestamp - last_received_data_message_burst_start_time_) >=
              base::TimeDelta::FromSeconds(
                  RECEIVED_DATA_MESSAGE_BURST_LENGTH_SECONDS)) {
     UMA_HISTOGRAM_COUNTS(
         "GCM.DataMessageBurstReceivedIntervalSeconds",
         (new_timestamp - last_received_data_message_burst_start_time_)
             .InSeconds());
     last_received_data_message_burst_start_time_ = new_timestamp;
   }
+  if (!data_message_received_since_connected_) {
+    DCHECK(!last_connection_success_time_.is_null());
+    UMA_HISTOGRAM_COUNTS(
+        "GCM.FirstReceivedDataMessageLatencyAfterConnection",
+        (new_timestamp - last_connection_success_time_).InMilliseconds());
+    data_message_received_since_connected_ = true;
+  }
 
   if (!is_recording_)
     return;
   if (!to_registered_app) {
     RecordReceiving(app_id, from, message_byte_size, "Data msg received",
                     to_registered_app ? std::string() :
                                         "No such registered app found");
   } else {
     switch(message_type) {
       case GCMStatsRecorderImpl::DATA_MESSAGE:
@@ skipping 86 matching lines @@
     const std::string& receiver_id,
     const std::string& message_id) {
   UMA_HISTOGRAM_COUNTS("GCM.IncomingSendErrors", 1);
   if (!is_recording_)
     return;
   RecordSending(app_id, receiver_id, message_id, "Received 'send error' msg",
                 std::string());
 }
 
 }  // namespace gcm