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_macros.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& senders,
 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 = senders;
 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::string& senders,
 301     RegistrationRequest::Status status) {
 302   if (!is_recording_)
 303     return;
 304   RecordRegistration(app_id, senders,
 305                      "Registration response received",
 306                      GetRegistrationStatusString(status));
 307 }
 308
 309 void GCMStatsRecorderImpl::RecordRegistrationRetryRequested(
 310     const std::string& app_id,
 311     const std::string& senders,
 312     int retries_left) {
 313   if (!is_recording_)
 314     return;
 315   RecordRegistration(app_id, senders,
 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     int retries_left) {
 344   if (!is_recording_)
 345     return;
 346   RecordRegistration(
 347       app_id,
 348       std::string(),
 349       "Unregistration retry delayed",
 350       base::StringPrintf("Delayed for %" PRId64 " msec, retries left: %d",
 351                          delay_msec,
 352                          retries_left));
 353 }
 354
 355 void GCMStatsRecorderImpl::RecordReceiving(
 356     const std::string& app_id,
 357     const std::string& from,
 358     int message_byte_size,
 359     const std::string& event,
 360     const std::string& details) {
 361   ReceivingActivity data;
 362   ReceivingActivity* inserted_data = InsertCircularBuffer(
 363       &receiving_activities_, data);
 364   inserted_data->app_id = app_id;
 365   inserted_data->from = from;
 366   inserted_data->message_byte_size = message_byte_size;
 367   inserted_data->event = event;
 368   inserted_data->details = details;
 369   NotifyActivityRecorded();
 370 }
 371
 372 void GCMStatsRecorderImpl::RecordDataMessageReceived(
 373     const std::string& app_id,
 374     const std::string& from,
 375     int message_byte_size,
 376     bool to_registered_app,
 377     ReceivedMessageType message_type) {
 378   if (to_registered_app)
 379     UMA_HISTOGRAM_COUNTS("GCM.DataMessageReceived", 1);
 380
 381   base::TimeTicks new_timestamp = base::TimeTicks::Now();
 382   if (last_received_data_message_burst_start_time_.is_null()) {
 383     last_received_data_message_burst_start_time_ = new_timestamp;
 384     last_received_data_message_time_within_burst_ = new_timestamp;
 385     received_data_message_burst_size_ = 1;
 386   } else if ((new_timestamp - last_received_data_message_burst_start_time_) >=
 387              base::TimeDelta::FromSeconds(
 388                  RECEIVED_DATA_MESSAGE_BURST_LENGTH_SECONDS)) {
 389     UMA_HISTOGRAM_LONG_TIMES(
 390         "GCM.DataMessageBurstReceivedInterval",
 391         (new_timestamp - last_received_data_message_burst_start_time_));
 392     UMA_HISTOGRAM_COUNTS("GCM.ReceivedDataMessageBurstSize",
 393                          received_data_message_burst_size_);
 394     last_received_data_message_burst_start_time_ = new_timestamp;
 395     last_received_data_message_time_within_burst_ = new_timestamp;
 396     received_data_message_burst_size_ = 1;
 397   } else {
 398     UMA_HISTOGRAM_TIMES(
 399         "GCM.ReceivedDataMessageIntervalWithinBurst",
 400         (new_timestamp - last_received_data_message_time_within_burst_));
 401     last_received_data_message_time_within_burst_ = new_timestamp;
 402     ++received_data_message_burst_size_;
 403   }
 404   if (!data_message_received_since_connected_) {
 405     DCHECK(!last_connection_success_time_.is_null());
 406     UMA_HISTOGRAM_TIMES("GCM.FirstReceivedDataMessageLatencyAfterConnection",
 407                         (new_timestamp - last_connection_success_time_));
 408     data_message_received_since_connected_ = true;
 409   }
 410
 411   if (!is_recording_)
 412     return;
 413   if (!to_registered_app) {
 414     RecordReceiving(app_id,
 415                     from,
 416                     message_byte_size,
 417                     "Data msg received",
 418                     "No such registered app found");
 419   } else {
 420     switch(message_type) {
 421       case GCMStatsRecorderImpl::DATA_MESSAGE:
 422         RecordReceiving(app_id, from, message_byte_size, "Data msg received",
 423                         std::string());
 424         break;
 425       case GCMStatsRecorderImpl::DELETED_MESSAGES:
 426         RecordReceiving(app_id, from, message_byte_size, "Data msg received",
 427                         "Message has been deleted on server");
 428         break;
 429       default:
 430         NOTREACHED();
 431     }
 432   }
 433 }
 434
 435 void GCMStatsRecorderImpl::CollectActivities(
 436     RecordedActivities* recorder_activities) const {
 437   recorder_activities->checkin_activities.insert(
 438       recorder_activities->checkin_activities.begin(),
 439       checkin_activities_.begin(),
 440       checkin_activities_.end());
 441   recorder_activities->connection_activities.insert(
 442       recorder_activities->connection_activities.begin(),
 443       connection_activities_.begin(),
 444       connection_activities_.end());
 445   recorder_activities->registration_activities.insert(
 446       recorder_activities->registration_activities.begin(),
 447       registration_activities_.begin(),
 448       registration_activities_.end());
 449   recorder_activities->receiving_activities.insert(
 450       recorder_activities->receiving_activities.begin(),
 451       receiving_activities_.begin(),
 452       receiving_activities_.end());
 453   recorder_activities->sending_activities.insert(
 454       recorder_activities->sending_activities.begin(),
 455       sending_activities_.begin(),
 456       sending_activities_.end());
 457 }
 458
 459 void GCMStatsRecorderImpl::RecordSending(const std::string& app_id,
 460                                          const std::string& receiver_id,
 461                                          const std::string& message_id,
 462                                          const std::string& event,
 463                                          const std::string& details) {
 464   SendingActivity data;
 465   SendingActivity* inserted_data = InsertCircularBuffer(
 466       &sending_activities_, data);
 467   inserted_data->app_id = app_id;
 468   inserted_data->receiver_id = receiver_id;
 469   inserted_data->message_id = message_id;
 470   inserted_data->event = event;
 471   inserted_data->details = details;
 472   NotifyActivityRecorded();
 473 }
 474
 475 void GCMStatsRecorderImpl::RecordDataSentToWire(
 476     const std::string& app_id,
 477     const std::string& receiver_id,
 478     const std::string& message_id,
 479     int queued) {
 480   if (!is_recording_)
 481     return;
 482   RecordSending(app_id, receiver_id, message_id, "Data msg sent to wire",
 483                 base::StringPrintf("Msg queued for %d seconds", queued));
 484 }
 485
 486 void GCMStatsRecorderImpl::RecordNotifySendStatus(
 487     const std::string& app_id,
 488     const std::string& receiver_id,
 489     const std::string& message_id,
 490     gcm::MCSClient::MessageSendStatus status,
 491     int byte_size,
 492     int ttl) {
 493   UMA_HISTOGRAM_ENUMERATION("GCM.SendMessageStatus", status,
 494                             gcm::MCSClient::SEND_STATUS_COUNT);
 495   if (!is_recording_)
 496     return;
 497   RecordSending(
 498       app_id,
 499       receiver_id,
 500       message_id,
 501       base::StringPrintf("SEND status: %s",
 502                          GetMessageSendStatusString(status).c_str()),
 503       base::StringPrintf("Msg size: %d bytes, TTL: %d", byte_size, ttl));
 504 }
 505
 506 void GCMStatsRecorderImpl::RecordIncomingSendError(
 507     const std::string& app_id,
 508     const std::string& receiver_id,
 509     const std::string& message_id) {
 510   UMA_HISTOGRAM_COUNTS("GCM.IncomingSendErrors", 1);
 511   if (!is_recording_)
 512     return;
 513   RecordSending(app_id, receiver_id, message_id, "Received 'send error' msg",
 514                 std::string());
 515 }
 516
 517 }  // namespace gcm