components/gcm_driver/gcm_stats_recorder_impl.cc

   1 // Copyright 2014 The Chromium Authors. All rights reserved.
   2 // Use of this source code is governed by a BSD-style license that can be
   3 // found in the LICENSE file.
   4
   5 #include "components/gcm_driver/gcm_stats_recorder_impl.h"
   6
   7 #include <deque>
   8 #include <vector>
   9
  10 #include "base/format_macros.h"
  11 #include "base/logging.h"
  12 #include "base/metrics/histogram.h"
  13 #include "base/strings/string_util.h"
  14 #include "base/strings/stringprintf.h"
  15
  16 namespace gcm {
  17
  18 const uint32 MAX_LOGGED_ACTIVITY_COUNT = 100;
  19 const int64 RECEIVED_DATA_MESSAGE_BURST_LENGTH_SECONDS = 2;
  20
  21 namespace {
  22
  23 // Insert an item to the front of deque while maintaining the size of the deque.
  24 // Overflow item is discarded.
  25 template <typename T>
  26 T* InsertCircularBuffer(std::deque<T>* q, const T& item) {
  27   DCHECK(q);
  28   q->push_front(item);
  29   if (q->size() > MAX_LOGGED_ACTIVITY_COUNT) {
  30     q->pop_back();
  31   }
  32   return &q->front();
  33 }
  34
  35 // Helper for getting string representation of the MessageSendStatus enum.
  36 std::string GetMessageSendStatusString(
  37     gcm::MCSClient::MessageSendStatus status) {
  38   switch (status) {
  39     case gcm::MCSClient::QUEUED:
  40       return "QUEUED";
  41     case gcm::MCSClient::SENT:
  42       return "SENT";
  43     case gcm::MCSClient::QUEUE_SIZE_LIMIT_REACHED:
  44       return "QUEUE_SIZE_LIMIT_REACHED";
  45     case gcm::MCSClient::APP_QUEUE_SIZE_LIMIT_REACHED:
  46       return "APP_QUEUE_SIZE_LIMIT_REACHED";
  47     case gcm::MCSClient::MESSAGE_TOO_LARGE:
  48       return "MESSAGE_TOO_LARGE";
  49     case gcm::MCSClient::NO_CONNECTION_ON_ZERO_TTL:
  50       return "NO_CONNECTION_ON_ZERO_TTL";
  51     case gcm::MCSClient::TTL_EXCEEDED:
  52       return "TTL_EXCEEDED";
  53     default:
  54       NOTREACHED();
  55       return "UNKNOWN";
  56   }
  57 }
  58
  59 // Helper for getting string representation of the
  60 // ConnectionFactory::ConnectionResetReason enum.
  61 std::string GetConnectionResetReasonString(
  62     gcm::ConnectionFactory::ConnectionResetReason reason) {
  63   switch (reason) {
  64     case gcm::ConnectionFactory::LOGIN_FAILURE:
  65       return "LOGIN_FAILURE";
  66     case gcm::ConnectionFactory::CLOSE_COMMAND:
  67       return "CLOSE_COMMAND";
  68     case gcm::ConnectionFactory::HEARTBEAT_FAILURE:
  69       return "HEARTBEAT_FAILURE";
  70     case gcm::ConnectionFactory::SOCKET_FAILURE:
  71       return "SOCKET_FAILURE";
  72     case gcm::ConnectionFactory::NETWORK_CHANGE:
  73       return "NETWORK_CHANGE";
  74     default:
  75       NOTREACHED();
  76       return "UNKNOWN_REASON";
  77   }
  78 }
  79
  80 // Helper for getting string representation of the RegistrationRequest::Status
  81 // enum.
  82 std::string GetRegistrationStatusString(
  83     gcm::RegistrationRequest::Status status) {
  84   switch (status) {
  85     case gcm::RegistrationRequest::SUCCESS:
  86       return "SUCCESS";
  87     case gcm::RegistrationRequest::INVALID_PARAMETERS:
  88       return "INVALID_PARAMETERS";
  89     case gcm::RegistrationRequest::INVALID_SENDER:
  90       return "INVALID_SENDER";
  91     case gcm::RegistrationRequest::AUTHENTICATION_FAILED:
  92       return "AUTHENTICATION_FAILED";
  93     case gcm::RegistrationRequest::DEVICE_REGISTRATION_ERROR:
  94       return "DEVICE_REGISTRATION_ERROR";
  95     case gcm::RegistrationRequest::UNKNOWN_ERROR:
  96       return "UNKNOWN_ERROR";
  97     case gcm::RegistrationRequest::URL_FETCHING_FAILED:
  98       return "URL_FETCHING_FAILED";
  99     case gcm::RegistrationRequest::HTTP_NOT_OK:
 100       return "HTTP_NOT_OK";
 101     case gcm::RegistrationRequest::RESPONSE_PARSING_FAILED:
 102       return "RESPONSE_PARSING_FAILED";
 103     case gcm::RegistrationRequest::REACHED_MAX_RETRIES:
 104       return "REACHED_MAX_RETRIES";
 105     default:
 106       NOTREACHED();
 107       return "UNKNOWN_STATUS";
 108   }
 109 }
 110
 111 // Helper for getting string representation of the RegistrationRequest::Status
 112 // enum.
 113 std::string GetUnregistrationStatusString(
 114     gcm::UnregistrationRequest::Status status) {
 115   switch (status) {
 116     case gcm::UnregistrationRequest::SUCCESS:
 117       return "SUCCESS";
 118     case gcm::UnregistrationRequest::URL_FETCHING_FAILED:
 119       return "URL_FETCHING_FAILED";
 120     case gcm::UnregistrationRequest::NO_RESPONSE_BODY:
 121       return "NO_RESPONSE_BODY";
 122     case gcm::UnregistrationRequest::RESPONSE_PARSING_FAILED:
 123       return "RESPONSE_PARSING_FAILED";
 124     case gcm::UnregistrationRequest::INCORRECT_APP_ID:
 125       return "INCORRECT_APP_ID";
 126     case gcm::UnregistrationRequest::INVALID_PARAMETERS:
 127       return "INVALID_PARAMETERS";
 128     case gcm::UnregistrationRequest::SERVICE_UNAVAILABLE:
 129       return "SERVICE_UNAVAILABLE";
 130     case gcm::UnregistrationRequest::INTERNAL_SERVER_ERROR:
 131       return "INTERNAL_SERVER_ERROR";
 132     case gcm::UnregistrationRequest::HTTP_NOT_OK:
 133       return "HTTP_NOT_OK";
 134     case gcm::UnregistrationRequest::UNKNOWN_ERROR:
 135       return "UNKNOWN_ERROR";
 136     default:
 137       NOTREACHED();
 138       return "UNKNOWN_STATUS";
 139   }
 140 }
 141
 142 }  // namespace
 143
 144 GCMStatsRecorderImpl::GCMStatsRecorderImpl()
 145     : is_recording_(false),
 146       delegate_(NULL),
 147       data_message_received_since_connected_(false),
 148       received_data_message_burst_size_(0) {
 149 }
 150
 151 GCMStatsRecorderImpl::~GCMStatsRecorderImpl() {
 152 }
 153
 154 void GCMStatsRecorderImpl::SetRecording(bool recording) {
 155   is_recording_ = recording;
 156 }
 157
 158 void GCMStatsRecorderImpl::SetDelegate(Delegate* delegate) {
 159   delegate_ = delegate;
 160 }
 161
 162 void GCMStatsRecorderImpl::Clear() {
 163   checkin_activities_.clear();
 164   connection_activities_.clear();
 165   registration_activities_.clear();
 166   receiving_activities_.clear();
 167   sending_activities_.clear();
 168 }
 169
 170 void GCMStatsRecorderImpl::NotifyActivityRecorded() {
 171   if (delegate_)
 172     delegate_->OnActivityRecorded();
 173 }
 174
 175 void GCMStatsRecorderImpl::RecordCheckin(
 176     const std::string& event,
 177     const std::string& details) {
 178   CheckinActivity data;
 179   CheckinActivity* inserted_data = InsertCircularBuffer(
 180       &checkin_activities_, data);
 181   inserted_data->event = event;
 182   inserted_data->details = details;
 183   NotifyActivityRecorded();
 184 }
 185
 186 void GCMStatsRecorderImpl::RecordCheckinInitiated(uint64 android_id) {
 187   if (!is_recording_)
 188     return;
 189   RecordCheckin("Checkin initiated",
 190                 base::StringPrintf("Android Id: %" PRIu64, android_id));
 191 }
 192
 193 void GCMStatsRecorderImpl::RecordCheckinDelayedDueToBackoff(int64 delay_msec) {
 194   if (!is_recording_)
 195     return;
 196   RecordCheckin("Checkin backoff",
 197                 base::StringPrintf("Delayed for %" PRId64 " msec",
 198                                    delay_msec));
 199 }
 200
 201 void GCMStatsRecorderImpl::RecordCheckinSuccess() {
 202   if (!is_recording_)
 203     return;
 204   RecordCheckin("Checkin succeeded", std::string());
 205 }
 206
 207 void GCMStatsRecorderImpl::RecordCheckinFailure(std::string status,
 208                                             bool will_retry) {
 209   if (!is_recording_)
 210     return;
 211   RecordCheckin("Checkin failed", base::StringPrintf(
 212       "%s.%s",
 213       status.c_str(),
 214       will_retry ? " Will retry." : "Will not retry."));
 215 }
 216
 217 void GCMStatsRecorderImpl::RecordConnection(
 218     const std::string& event,
 219     const std::string& details) {
 220   ConnectionActivity data;
 221   ConnectionActivity* inserted_data = InsertCircularBuffer(
 222       &connection_activities_, data);
 223   inserted_data->event = event;
 224   inserted_data->details = details;
 225   NotifyActivityRecorded();
 226 }
 227
 228 void GCMStatsRecorderImpl::RecordConnectionInitiated(const std::string& host) {
 229   last_connection_initiation_time_ = base::TimeTicks::Now();
 230   last_connection_success_time_ = base::TimeTicks();
 231   data_message_received_since_connected_ = false;
 232   if (!is_recording_)
 233     return;
 234   RecordConnection("Connection initiated", host);
 235 }
 236
 237 void GCMStatsRecorderImpl::RecordConnectionDelayedDueToBackoff(
 238     int64 delay_msec) {
 239   if (!is_recording_)
 240     return;
 241   RecordConnection("Connection backoff",
 242                    base::StringPrintf("Delayed for %" PRId64 " msec",
 243                                       delay_msec));
 244 }
 245
 246 void GCMStatsRecorderImpl::RecordConnectionSuccess() {
 247   DCHECK(!last_connection_initiation_time_.is_null());
 248   UMA_HISTOGRAM_MEDIUM_TIMES(
 249       "GCM.ConnectionLatency",
 250       (base::TimeTicks::Now() - last_connection_initiation_time_));
 251   last_connection_success_time_ = base::TimeTicks::Now();
 252   last_connection_initiation_time_ = base::TimeTicks();
 253   if (!is_recording_)
 254     return;
 255   RecordConnection("Connection succeeded", std::string());
 256 }
 257
 258 void GCMStatsRecorderImpl::RecordConnectionFailure(int network_error) {
 259   if (!is_recording_)
 260     return;
 261   RecordConnection("Connection failed",
 262                    base::StringPrintf("With network error %d", network_error));
 263 }
 264
 265 void GCMStatsRecorderImpl::RecordConnectionResetSignaled(
 266       ConnectionFactory::ConnectionResetReason reason) {
 267   if (!is_recording_)
 268     return;
 269   RecordConnection("Connection reset",
 270                    GetConnectionResetReasonString(reason));
 271 }
 272
 273 void GCMStatsRecorderImpl::RecordRegistration(
 274     const std::string& app_id,
 275     const std::string& sender_ids,
 276     const std::string& event,
 277     const std::string& details) {
 278   RegistrationActivity data;
 279   RegistrationActivity* inserted_data = InsertCircularBuffer(
 280       &registration_activities_, data);
 281   inserted_data->app_id = app_id;
 282   inserted_data->sender_ids = sender_ids;
 283   inserted_data->event = event;
 284   inserted_data->details = details;
 285   NotifyActivityRecorded();
 286 }
 287
 288 void GCMStatsRecorderImpl::RecordRegistrationSent(
 289     const std::string& app_id,
 290     const std::string& sender_ids) {
 291   UMA_HISTOGRAM_COUNTS("GCM.RegistrationRequest", 1);
 292   if (!is_recording_)
 293     return;
 294   RecordRegistration(app_id, sender_ids,
 295                      "Registration request sent", std::string());
 296 }
 297
 298 void GCMStatsRecorderImpl::RecordRegistrationResponse(
 299     const std::string& app_id,
 300     const std::vector<std::string>& sender_ids,
 301     RegistrationRequest::Status status) {
 302   if (!is_recording_)
 303     return;
 304   RecordRegistration(app_id, JoinString(sender_ids, ","),
 305                      "Registration response received",
 306                      GetRegistrationStatusString(status));
 307 }
 308
 309 void GCMStatsRecorderImpl::RecordRegistrationRetryRequested(
 310     const std::string& app_id,
 311     const std::vector<std::string>& sender_ids,
 312     int retries_left) {
 313   if (!is_recording_)
 314     return;
 315   RecordRegistration(app_id, JoinString(sender_ids, ","),
 316                      "Registration retry requested",
 317                      base::StringPrintf("Retries left: %d", retries_left));
 318 }
 319
 320 void GCMStatsRecorderImpl::RecordUnregistrationSent(
 321     const std::string& app_id) {
 322   UMA_HISTOGRAM_COUNTS("GCM.UnregistrationRequest", 1);
 323   if (!is_recording_)
 324     return;
 325   RecordRegistration(app_id, std::string(), "Unregistration request sent",
 326                      std::string());
 327 }
 328
 329 void GCMStatsRecorderImpl::RecordUnregistrationResponse(
 330     const std::string& app_id,
 331     UnregistrationRequest::Status status) {
 332   if (!is_recording_)
 333     return;
 334   RecordRegistration(app_id,
 335                      std::string(),
 336                      "Unregistration response received",
 337                      GetUnregistrationStatusString(status));
 338 }
 339
 340 void GCMStatsRecorderImpl::RecordUnregistrationRetryDelayed(
 341     const std::string& app_id,
 342     int64 delay_msec) {
 343   if (!is_recording_)
 344     return;
 345   RecordRegistration(app_id,
 346                      std::string(),
 347                      "Unregistration retry delayed",
 348                      base::StringPrintf("Delayed for %" PRId64 " msec",
 349                                         delay_msec));
 350 }
 351
 352 void GCMStatsRecorderImpl::RecordReceiving(
 353     const std::string& app_id,
 354     const std::string& from,
 355     int message_byte_size,
 356     const std::string& event,
 357     const std::string& details) {
 358   ReceivingActivity data;
 359   ReceivingActivity* inserted_data = InsertCircularBuffer(
 360       &receiving_activities_, data);
 361   inserted_data->app_id = app_id;
 362   inserted_data->from = from;
 363   inserted_data->message_byte_size = message_byte_size;
 364   inserted_data->event = event;
 365   inserted_data->details = details;
 366   NotifyActivityRecorded();
 367 }
 368
 369 void GCMStatsRecorderImpl::RecordDataMessageReceived(
 370     const std::string& app_id,
 371     const std::string& from,
 372     int message_byte_size,
 373     bool to_registered_app,
 374     ReceivedMessageType message_type) {
 375   if (to_registered_app)
 376     UMA_HISTOGRAM_COUNTS("GCM.DataMessageReceived", 1);
 377
 378   base::TimeTicks new_timestamp = base::TimeTicks::Now();
 379   if (last_received_data_message_burst_start_time_.is_null()) {
 380     last_received_data_message_burst_start_time_ = new_timestamp;
 381     last_received_data_message_time_within_burst_ = new_timestamp;
 382     received_data_message_burst_size_ = 1;
 383   } else if ((new_timestamp - last_received_data_message_burst_start_time_) >=
 384              base::TimeDelta::FromSeconds(
 385                  RECEIVED_DATA_MESSAGE_BURST_LENGTH_SECONDS)) {
 386     UMA_HISTOGRAM_LONG_TIMES(
 387         "GCM.DataMessageBurstReceivedInterval",
 388         (new_timestamp - last_received_data_message_burst_start_time_));
 389     UMA_HISTOGRAM_COUNTS("GCM.ReceivedDataMessageBurstSize",
 390                          received_data_message_burst_size_);
 391     last_received_data_message_burst_start_time_ = new_timestamp;
 392     last_received_data_message_time_within_burst_ = new_timestamp;
 393     received_data_message_burst_size_ = 1;
 394   } else {
 395     UMA_HISTOGRAM_TIMES(
 396         "GCM.ReceivedDataMessageIntervalWithinBurst",
 397         (new_timestamp - last_received_data_message_time_within_burst_));
 398     last_received_data_message_time_within_burst_ = new_timestamp;
 399     ++received_data_message_burst_size_;
 400   }
 401   if (!data_message_received_since_connected_) {
 402     DCHECK(!last_connection_success_time_.is_null());
 403     UMA_HISTOGRAM_TIMES("GCM.FirstReceivedDataMessageLatencyAfterConnection",
 404                         (new_timestamp - last_connection_success_time_));
 405     data_message_received_since_connected_ = true;
 406   }
 407
 408   if (!is_recording_)
 409     return;
 410   if (!to_registered_app) {
 411     RecordReceiving(app_id,
 412                     from,
 413                     message_byte_size,
 414                     "Data msg received",
 415                     "No such registered app found");
 416   } else {
 417     switch(message_type) {
 418       case GCMStatsRecorderImpl::DATA_MESSAGE:
 419         RecordReceiving(app_id, from, message_byte_size, "Data msg received",
 420                         std::string());
 421         break;
 422       case GCMStatsRecorderImpl::DELETED_MESSAGES:
 423         RecordReceiving(app_id, from, message_byte_size, "Data msg received",
 424                         "Message has been deleted on server");
 425         break;
 426       default:
 427         NOTREACHED();
 428     }
 429   }
 430 }
 431
 432 void GCMStatsRecorderImpl::CollectActivities(
 433     RecordedActivities* recorder_activities) const {
 434   recorder_activities->checkin_activities.insert(
 435       recorder_activities->checkin_activities.begin(),
 436       checkin_activities_.begin(),
 437       checkin_activities_.end());
 438   recorder_activities->connection_activities.insert(
 439       recorder_activities->connection_activities.begin(),
 440       connection_activities_.begin(),
 441       connection_activities_.end());
 442   recorder_activities->registration_activities.insert(
 443       recorder_activities->registration_activities.begin(),
 444       registration_activities_.begin(),
 445       registration_activities_.end());
 446   recorder_activities->receiving_activities.insert(
 447       recorder_activities->receiving_activities.begin(),
 448       receiving_activities_.begin(),
 449       receiving_activities_.end());
 450   recorder_activities->sending_activities.insert(
 451       recorder_activities->sending_activities.begin(),
 452       sending_activities_.begin(),
 453       sending_activities_.end());
 454 }
 455
 456 void GCMStatsRecorderImpl::RecordSending(const std::string& app_id,
 457                                          const std::string& receiver_id,
 458                                          const std::string& message_id,
 459                                          const std::string& event,
 460                                          const std::string& details) {
 461   SendingActivity data;
 462   SendingActivity* inserted_data = InsertCircularBuffer(
 463       &sending_activities_, data);
 464   inserted_data->app_id = app_id;
 465   inserted_data->receiver_id = receiver_id;
 466   inserted_data->message_id = message_id;
 467   inserted_data->event = event;
 468   inserted_data->details = details;
 469   NotifyActivityRecorded();
 470 }
 471
 472 void GCMStatsRecorderImpl::RecordDataSentToWire(
 473     const std::string& app_id,
 474     const std::string& receiver_id,
 475     const std::string& message_id,
 476     int queued) {
 477   if (!is_recording_)
 478     return;
 479   RecordSending(app_id, receiver_id, message_id, "Data msg sent to wire",
 480                 base::StringPrintf("Msg queued for %d seconds", queued));
 481 }
 482
 483 void GCMStatsRecorderImpl::RecordNotifySendStatus(
 484     const std::string& app_id,
 485     const std::string& receiver_id,
 486     const std::string& message_id,
 487     gcm::MCSClient::MessageSendStatus status,
 488     int byte_size,
 489     int ttl) {
 490   UMA_HISTOGRAM_ENUMERATION("GCM.SendMessageStatus", status,
 491                             gcm::MCSClient::SEND_STATUS_COUNT);
 492   if (!is_recording_)
 493     return;
 494   RecordSending(
 495       app_id,
 496       receiver_id,
 497       message_id,
 498       base::StringPrintf("SEND status: %s",
 499                          GetMessageSendStatusString(status).c_str()),
 500       base::StringPrintf("Msg size: %d bytes, TTL: %d", byte_size, ttl));
 501 }
 502
 503 void GCMStatsRecorderImpl::RecordIncomingSendError(
 504     const std::string& app_id,
 505     const std::string& receiver_id,
 506     const std::string& message_id) {
 507   UMA_HISTOGRAM_COUNTS("GCM.IncomingSendErrors", 1);
 508   if (!is_recording_)
 509     return;
 510   RecordSending(app_id, receiver_id, message_id, "Received 'send error' msg",
 511                 std::string());
 512 }
 513
 514 }  // namespace gcm