Record latencies of connection and arrival of first message in UMA

This gives an idea how long it took a connection to complete as well
as the arrival of data messages.

Also records received GCM data burst size and intervals in UMA, and
added previously left-out xml description for another UMA metric.

jar: please review histograms.xml

BUG=386273

Review URL: https://codereview.chromium.org/409653004

git-svn-id: svn://svn.chromium.org/chrome/trunk/src@287645 0039d316-1c4b-4281-b951-d872f2087c98

components/gcm_driver/gcm_client_impl_unittest.cc

@@ -471,6 +471,8 @@ void GCMClientImplTest::StartGCMClient() {
 }
 
 void GCMClientImplTest::ReceiveMessageFromMCS(const MCSMessage& message) {
+  gcm_client_->recorder_.RecordConnectionInitiated(std::string());
+  gcm_client_->recorder_.RecordConnectionSuccess();
   gcm_client_->OnMessageReceivedFromMCS(message);
 }
 

components/gcm_driver/gcm_stats_recorder_impl.cc

@@ -143,7 +143,9 @@ std::string GetUnregistrationStatusString(
 
 GCMStatsRecorderImpl::GCMStatsRecorderImpl()
     : is_recording_(false),
-      delegate_(NULL) {
+      delegate_(NULL),
+      data_message_received_since_connected_(false),
+      received_data_message_burst_size_(0) {
 }
 
 GCMStatsRecorderImpl::~GCMStatsRecorderImpl() {
@@ -224,6 +226,9 @@ void GCMStatsRecorderImpl::RecordConnection(
 }
 
 void GCMStatsRecorderImpl::RecordConnectionInitiated(const std::string& host) {
+  last_connection_initiation_time_ = base::TimeTicks::Now();
+  last_connection_success_time_ = base::TimeTicks();
+  data_message_received_since_connected_ = false;
   if (!is_recording_)
     return;
   RecordConnection("Connection initiated", host);
@@ -239,6 +244,12 @@ void GCMStatsRecorderImpl::RecordConnectionDelayedDueToBackoff(
 }
 
 void GCMStatsRecorderImpl::RecordConnectionSuccess() {
+  DCHECK(!last_connection_initiation_time_.is_null());
+  UMA_HISTOGRAM_MEDIUM_TIMES(
+      "GCM.ConnectionLatency",
+      (base::TimeTicks::Now() - last_connection_initiation_time_));
+  last_connection_success_time_ = base::TimeTicks::Now();
+  last_connection_initiation_time_ = base::TimeTicks();
   if (!is_recording_)
     return;
   RecordConnection("Connection succeeded", std::string());
@@ -364,25 +375,44 @@ void GCMStatsRecorderImpl::RecordDataMessageReceived(
   if (to_registered_app)
     UMA_HISTOGRAM_COUNTS("GCM.DataMessageReceived", 1);
 
-  base::Time new_timestamp = base::Time::Now();
+  base::TimeTicks new_timestamp = base::TimeTicks::Now();
   if (last_received_data_message_burst_start_time_.is_null()) {
     last_received_data_message_burst_start_time_ = new_timestamp;
+    last_received_data_message_time_within_burst_ = new_timestamp;
+    received_data_message_burst_size_ = 1;
   } 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());
+    UMA_HISTOGRAM_LONG_TIMES(
+        "GCM.DataMessageBurstReceivedInterval",
+        (new_timestamp - last_received_data_message_burst_start_time_));
+    UMA_HISTOGRAM_COUNTS("GCM.ReceivedDataMessageBurstSize",
+                         received_data_message_burst_size_);
     last_received_data_message_burst_start_time_ = new_timestamp;
+    last_received_data_message_time_within_burst_ = new_timestamp;
+    received_data_message_burst_size_ = 1;
+  } else {
+    UMA_HISTOGRAM_TIMES(
+        "GCM.ReceivedDataMessageIntervalWithinBurst",
+        (new_timestamp - last_received_data_message_time_within_burst_));
+    last_received_data_message_time_within_burst_ = new_timestamp;
+    ++received_data_message_burst_size_;
+  }
+  if (!data_message_received_since_connected_) {
+    DCHECK(!last_connection_success_time_.is_null());
+    UMA_HISTOGRAM_TIMES("GCM.FirstReceivedDataMessageLatencyAfterConnection",
+                        (new_timestamp - last_connection_success_time_));
+    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");
+    RecordReceiving(app_id,
+                    from,
+                    message_byte_size,
+                    "Data msg received",
+                    "No such registered app found");
   } else {
     switch(message_type) {
       case GCMStatsRecorderImpl::DATA_MESSAGE:

components/gcm_driver/gcm_stats_recorder_impl.h

@@ -147,7 +147,12 @@ class GCMStatsRecorderImpl : public GCMStatsRecorder {
   std::deque<ReceivingActivity> receiving_activities_;
   std::deque<SendingActivity> sending_activities_;
 
-  base::Time last_received_data_message_burst_start_time_;
+  base::TimeTicks last_connection_initiation_time_;
+  base::TimeTicks last_connection_success_time_;
+  bool data_message_received_since_connected_;
+  base::TimeTicks last_received_data_message_burst_start_time_;
+  base::TimeTicks last_received_data_message_time_within_burst_;
+  int64 received_data_message_burst_size_;
 
   DISALLOW_COPY_AND_ASSIGN(GCMStatsRecorderImpl);
 };

components/gcm_driver/gcm_stats_recorder_impl_unittest.cc

@@ -485,6 +485,8 @@ TEST_F(GCMStatsRecorderImplTest, RegistrationTest) {
 }
 
 TEST_F(GCMStatsRecorderImplTest, RecordReceivingTest) {
+  recorder_.RecordConnectionInitiated(std::string());
+  recorder_.RecordConnectionSuccess();
   recorder_.RecordDataMessageReceived(kAppId, kFrom, kByteSize, true,
                                       GCMStatsRecorder::DATA_MESSAGE);
   VerifyRecordedReceivingCount(1);

tools/metrics/histograms/histograms.xml

@@ -8403,6 +8403,14 @@ Therefore, the affected-histogram name has to have at least one dot in it.
   <summary>Net error results from GCM connection attempts.</summary>
 </histogram>
 
+<histogram name="GCM.ConnectionLatency" units="milliseconds">
+  <owner>juyik@chromium.org</owner>
+  <summary>
+    The time between the initiation of a connection and the successful
+    completion of it.
+  </summary>
+</histogram>
+
 <histogram name="GCM.ConnectionResetReason" enum="GCMConnectionResetReason">
   <owner>zea@chromium.org</owner>
   <summary>Reasons for GCM connection resets.</summary>
@@ -8424,6 +8432,22 @@ Therefore, the affected-histogram name has to have at least one dot in it.
   </summary>
 </histogram>
 
+<histogram name="GCM.DataMessageBurstReceivedInterval" units="milliseconds">
+  <owner>juyik@chromium.org</owner>
+  <summary>
+    Interval between two successive received data message bursts.
+  </summary>
+</histogram>
+
+<histogram name="GCM.FirstReceivedDataMessageLatencyAfterConnection"
+    units="milliseconds">
+  <owner>juyik@chromium.org</owner>
+  <summary>
+    The time between the successful completion of the connection and the arrival
+    of the first data message.
+  </summary>
+</histogram>
+
 <histogram name="GCM.LoadSucceeded" enum="BooleanSuccess">
   <owner>zea@chromium.org</owner>
   <summary>
@@ -8458,6 +8482,19 @@ Therefore, the affected-histogram name has to have at least one dot in it.
   </summary>
 </histogram>
 
+<histogram name="GCM.ReceivedDataMessageBurstSize" units="messages">
+  <owner>juyik@chromium.org</owner>
+  <summary>Number of messages in a received GCM data message burst.</summary>
+</histogram>
+
+<histogram name="GCM.ReceivedDataMessageIntervalWithinBurstMs"
+    units="milliseconds">
+  <owner>juyik@chromium.org</owner>
+  <summary>
+    Interval between messages within a received GCM data message burst.
+  </summary>
+</histogram>
+
 <histogram name="GCM.RegistrationCompleteTime" units="milliseconds">
   <owner>jianli@chromium.org</owner>
   <summary>