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     case gcm::UnregistrationRequest::REACHED_MAX_RETRIES:
 137       return "REACHED_MAX_RETRIES";
 138     default:
 139       NOTREACHED();
 140       return "UNKNOWN_STATUS";
 141   }
 142 }
 143
 144 }  // namespace
 145
 146 GCMStatsRecorderImpl::GCMStatsRecorderImpl()
 147     : is_recording_(false),
 148       delegate_(NULL),
 149       data_message_received_since_connected_(false),
 150       received_data_message_burst_size_(0) {
 151 }
 152
 153 GCMStatsRecorderImpl::~GCMStatsRecorderImpl() {
 154 }
 155
 156 void GCMStatsRecorderImpl::SetRecording(bool recording) {
 157   is_recording_ = recording;
 158 }
 159
 160 void GCMStatsRecorderImpl::SetDelegate(Delegate* delegate) {
 161   delegate_ = delegate;
 162 }
 163
 164 void GCMStatsRecorderImpl::Clear() {
 165   checkin_activities_.clear();
 166   connection_activities_.clear();
 167   registration_activities_.clear();
 168   receiving_activities_.clear();
 169   sending_activities_.clear();
 170 }
 171
 172 void GCMStatsRecorderImpl::NotifyActivityRecorded() {
 173   if (delegate_)
 174     delegate_->OnActivityRecorded();
 175 }
 176
 177 void GCMStatsRecorderImpl::RecordCheckin(
 178     const std::string& event,
 179     const std::string& details) {
 180   CheckinActivity data;
 181   CheckinActivity* inserted_data = InsertCircularBuffer(
 182       &checkin_activities_, data);
 183   inserted_data->event = event;
 184   inserted_data->details = details;
 185   NotifyActivityRecorded();
 186 }
 187
 188 void GCMStatsRecorderImpl::RecordCheckinInitiated(uint64 android_id) {
 189   if (!is_recording_)
 190     return;
 191   RecordCheckin("Checkin initiated",
 192                 base::StringPrintf("Android Id: %" PRIu64, android_id));
 193 }
 194
 195 void GCMStatsRecorderImpl::RecordCheckinDelayedDueToBackoff(int64 delay_msec) {
 196   if (!is_recording_)
 197     return;
 198   RecordCheckin("Checkin backoff",
 199                 base::StringPrintf("Delayed for %" PRId64 " msec",
 200                                    delay_msec));
 201 }
 202
 203 void GCMStatsRecorderImpl::RecordCheckinSuccess() {
 204   if (!is_recording_)
 205     return;
 206   RecordCheckin("Checkin succeeded", std::string());
 207 }
 208
 209 void GCMStatsRecorderImpl::RecordCheckinFailure(std::string status,
 210                                             bool will_retry) {
 211   if (!is_recording_)
 212     return;
 213   RecordCheckin("Checkin failed", base::StringPrintf(
 214       "%s.%s",
 215       status.c_str(),
 216       will_retry ? " Will retry." : "Will not retry."));
 217 }
 218
 219 void GCMStatsRecorderImpl::RecordConnection(
 220     const std::string& event,
 221     const std::string& details) {
 222   ConnectionActivity data;
 223   ConnectionActivity* inserted_data = InsertCircularBuffer(
 224       &connection_activities_, data);
 225   inserted_data->event = event;
 226   inserted_data->details = details;
 227   NotifyActivityRecorded();
 228 }
 229
 230 void GCMStatsRecorderImpl::RecordConnectionInitiated(const std::string& host) {
 231   last_connection_initiation_time_ = base::TimeTicks::Now();
 232   last_connection_success_time_ = base::TimeTicks();
 233   data_message_received_since_connected_ = false;
 234   if (!is_recording_)
 235     return;
 236   RecordConnection("Connection initiated", host);
 237 }
 238
 239 void GCMStatsRecorderImpl::RecordConnectionDelayedDueToBackoff(
 240     int64 delay_msec) {
 241   if (!is_recording_)
 242     return;
 243   RecordConnection("Connection backoff",
 244                    base::StringPrintf("Delayed for %" PRId64 " msec",
 245                                       delay_msec));
 246 }
 247
 248 void GCMStatsRecorderImpl::RecordConnectionSuccess() {
 249   DCHECK(!last_connection_initiation_time_.is_null());
 250   UMA_HISTOGRAM_MEDIUM_TIMES(
 251       "GCM.ConnectionLatency",
 252       (base::TimeTicks::Now() - last_connection_initiation_time_));
 253   last_connection_success_time_ = base::TimeTicks::Now();
 254   last_connection_initiation_time_ = base::TimeTicks();
 255   if (!is_recording_)
 256     return;
 257   RecordConnection("Connection succeeded", std::string());
 258 }
 259
 260 void GCMStatsRecorderImpl::RecordConnectionFailure(int network_error) {
 261   if (!is_recording_)
 262     return;
 263   RecordConnection("Connection failed",
 264                    base::StringPrintf("With network error %d", network_error));
 265 }
 266
 267 void GCMStatsRecorderImpl::RecordConnectionResetSignaled(
 268       ConnectionFactory::ConnectionResetReason reason) {
 269   if (!is_recording_)
 270     return;
 271   RecordConnection("Connection reset",
 272                    GetConnectionResetReasonString(reason));
 273 }
 274
 275 void GCMStatsRecorderImpl::RecordRegistration(
 276     const std::string& app_id,
 277     const std::string& source,
 278     const std::string& event,
 279     const std::string& details) {
 280   RegistrationActivity data;
 281   RegistrationActivity* inserted_data = InsertCircularBuffer(
 282       &registration_activities_, data);
 283   inserted_data->app_id = app_id;
 284   inserted_data->source = source;
 285   inserted_data->event = event;
 286   inserted_data->details = details;
 287   NotifyActivityRecorded();
 288 }
 289
 290 void GCMStatsRecorderImpl::RecordRegistrationSent(
 291     const std::string& app_id,
 292     const std::string& sender_ids) {
 293   UMA_HISTOGRAM_COUNTS("GCM.RegistrationRequest", 1);
 294   if (!is_recording_)
 295     return;
 296   RecordRegistration(app_id, sender_ids,
 297                      "Registration request sent", std::string());
 298 }
 299
 300 void GCMStatsRecorderImpl::RecordRegistrationResponse(
 301     const std::string& app_id,
 302     const std::string& source,
 303     RegistrationRequest::Status status) {
 304   if (!is_recording_)
 305     return;
 306   RecordRegistration(app_id, source,
 307                      "Registration response received",
 308                      GetRegistrationStatusString(status));
 309 }
 310
 311 void GCMStatsRecorderImpl::RecordRegistrationRetryDelayed(
 312     const std::string& app_id,
 313     const std::string& source,
 314     int64 delay_msec,
 315     int retries_left) {
 316   if (!is_recording_)
 317     return;
 318   RecordRegistration(
 319       app_id,
 320       source,
 321       "Registration retry delayed",
 322       base::StringPrintf("Delayed for %" PRId64 " msec, retries left: %d",
 323                          delay_msec,
 324                          retries_left));
 325 }
 326
 327 void GCMStatsRecorderImpl::RecordUnregistrationSent(
 328     const std::string& app_id, const std::string& source) {
 329   UMA_HISTOGRAM_COUNTS("GCM.UnregistrationRequest", 1);
 330   if (!is_recording_)
 331     return;
 332   RecordRegistration(app_id, source, "Unregistration request sent",
 333                      std::string());
 334 }
 335
 336 void GCMStatsRecorderImpl::RecordUnregistrationResponse(
 337     const std::string& app_id,
 338     const std::string& source,
 339     UnregistrationRequest::Status status) {
 340   if (!is_recording_)
 341     return;
 342   RecordRegistration(app_id,
 343                      source,
 344                      "Unregistration response received",
 345                      GetUnregistrationStatusString(status));
 346 }
 347
 348 void GCMStatsRecorderImpl::RecordUnregistrationRetryDelayed(
 349     const std::string& app_id,
 350     const std::string& source,
 351     int64 delay_msec,
 352     int retries_left) {
 353   if (!is_recording_)
 354     return;
 355   RecordRegistration(
 356       app_id,
 357       source,
 358       "Unregistration retry delayed",
 359       base::StringPrintf("Delayed for %" PRId64 " msec, retries left: %d",
 360                          delay_msec,
 361                          retries_left));
 362 }
 363
 364 void GCMStatsRecorderImpl::RecordReceiving(
 365     const std::string& app_id,
 366     const std::string& from,
 367     int message_byte_size,
 368     const std::string& event,
 369     const std::string& details) {
 370   ReceivingActivity data;
 371   ReceivingActivity* inserted_data = InsertCircularBuffer(
 372       &receiving_activities_, data);
 373   inserted_data->app_id = app_id;
 374   inserted_data->from = from;
 375   inserted_data->message_byte_size = message_byte_size;
 376   inserted_data->event = event;
 377   inserted_data->details = details;
 378   NotifyActivityRecorded();
 379 }
 380
 381 void GCMStatsRecorderImpl::RecordDataMessageReceived(
 382     const std::string& app_id,
 383     const std::string& from,
 384     int message_byte_size,
 385     bool to_registered_app,
 386     ReceivedMessageType message_type) {
 387   if (to_registered_app)
 388     UMA_HISTOGRAM_COUNTS("GCM.DataMessageReceived", 1);
 389
 390   base::TimeTicks new_timestamp = base::TimeTicks::Now();
 391   if (last_received_data_message_burst_start_time_.is_null()) {
 392     last_received_data_message_burst_start_time_ = new_timestamp;
 393     last_received_data_message_time_within_burst_ = new_timestamp;
 394     received_data_message_burst_size_ = 1;
 395   } else if ((new_timestamp - last_received_data_message_burst_start_time_) >=
 396              base::TimeDelta::FromSeconds(
 397                  RECEIVED_DATA_MESSAGE_BURST_LENGTH_SECONDS)) {
 398     UMA_HISTOGRAM_LONG_TIMES(
 399         "GCM.DataMessageBurstReceivedInterval",
 400         (new_timestamp - last_received_data_message_burst_start_time_));
 401     UMA_HISTOGRAM_COUNTS("GCM.ReceivedDataMessageBurstSize",
 402                          received_data_message_burst_size_);
 403     last_received_data_message_burst_start_time_ = new_timestamp;
 404     last_received_data_message_time_within_burst_ = new_timestamp;
 405     received_data_message_burst_size_ = 1;
 406   } else {
 407     UMA_HISTOGRAM_TIMES(
 408         "GCM.ReceivedDataMessageIntervalWithinBurst",
 409         (new_timestamp - last_received_data_message_time_within_burst_));
 410     last_received_data_message_time_within_burst_ = new_timestamp;
 411     ++received_data_message_burst_size_;
 412   }
 413   if (!data_message_received_since_connected_) {
 414     DCHECK(!last_connection_success_time_.is_null());
 415     UMA_HISTOGRAM_TIMES("GCM.FirstReceivedDataMessageLatencyAfterConnection",
 416                         (new_timestamp - last_connection_success_time_));
 417     data_message_received_since_connected_ = true;
 418   }
 419
 420   if (!is_recording_)
 421     return;
 422   if (!to_registered_app) {
 423     RecordReceiving(app_id,
 424                     from,
 425                     message_byte_size,
 426                     "Data msg received",
 427                     "No such registered app found");
 428   } else {
 429     switch(message_type) {
 430       case GCMStatsRecorderImpl::DATA_MESSAGE:
 431         RecordReceiving(app_id, from, message_byte_size, "Data msg received",
 432                         std::string());
 433         break;
 434       case GCMStatsRecorderImpl::DELETED_MESSAGES:
 435         RecordReceiving(app_id, from, message_byte_size, "Data msg received",
 436                         "Message has been deleted on server");
 437         break;
 438       default:
 439         NOTREACHED();
 440     }
 441   }
 442 }
 443
 444 void GCMStatsRecorderImpl::CollectActivities(
 445     RecordedActivities* recorder_activities) const {
 446   recorder_activities->checkin_activities.insert(
 447       recorder_activities->checkin_activities.begin(),
 448       checkin_activities_.begin(),
 449       checkin_activities_.end());
 450   recorder_activities->connection_activities.insert(
 451       recorder_activities->connection_activities.begin(),
 452       connection_activities_.begin(),
 453       connection_activities_.end());
 454   recorder_activities->registration_activities.insert(
 455       recorder_activities->registration_activities.begin(),
 456       registration_activities_.begin(),
 457       registration_activities_.end());
 458   recorder_activities->receiving_activities.insert(
 459       recorder_activities->receiving_activities.begin(),
 460       receiving_activities_.begin(),
 461       receiving_activities_.end());
 462   recorder_activities->sending_activities.insert(
 463       recorder_activities->sending_activities.begin(),
 464       sending_activities_.begin(),
 465       sending_activities_.end());
 466 }
 467
 468 void GCMStatsRecorderImpl::RecordSending(const std::string& app_id,
 469                                          const std::string& receiver_id,
 470                                          const std::string& message_id,
 471                                          const std::string& event,
 472                                          const std::string& details) {
 473   SendingActivity data;
 474   SendingActivity* inserted_data = InsertCircularBuffer(
 475       &sending_activities_, data);
 476   inserted_data->app_id = app_id;
 477   inserted_data->receiver_id = receiver_id;
 478   inserted_data->message_id = message_id;
 479   inserted_data->event = event;
 480   inserted_data->details = details;
 481   NotifyActivityRecorded();
 482 }
 483
 484 void GCMStatsRecorderImpl::RecordDataSentToWire(
 485     const std::string& app_id,
 486     const std::string& receiver_id,
 487     const std::string& message_id,
 488     int queued) {
 489   if (!is_recording_)
 490     return;
 491   RecordSending(app_id, receiver_id, message_id, "Data msg sent to wire",
 492                 base::StringPrintf("Msg queued for %d seconds", queued));
 493 }
 494
 495 void GCMStatsRecorderImpl::RecordNotifySendStatus(
 496     const std::string& app_id,
 497     const std::string& receiver_id,
 498     const std::string& message_id,
 499     gcm::MCSClient::MessageSendStatus status,
 500     int byte_size,
 501     int ttl) {
 502   UMA_HISTOGRAM_ENUMERATION("GCM.SendMessageStatus", status,
 503                             gcm::MCSClient::SEND_STATUS_COUNT);
 504   if (!is_recording_)
 505     return;
 506   RecordSending(
 507       app_id,
 508       receiver_id,
 509       message_id,
 510       base::StringPrintf("SEND status: %s",
 511                          GetMessageSendStatusString(status).c_str()),
 512       base::StringPrintf("Msg size: %d bytes, TTL: %d", byte_size, ttl));
 513 }
 514
 515 void GCMStatsRecorderImpl::RecordIncomingSendError(
 516     const std::string& app_id,
 517     const std::string& receiver_id,
 518     const std::string& message_id) {
 519   UMA_HISTOGRAM_COUNTS("GCM.IncomingSendErrors", 1);
 520   if (!is_recording_)
 521     return;
 522   RecordSending(app_id, receiver_id, message_id, "Received 'send error' msg",
 523                 std::string());
 524 }
 525
 526 }  // namespace gcm