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 16namespace gcm { 17 18const uint32 MAX_LOGGED_ACTIVITY_COUNT = 100; 19const int64 RECEIVED_DATA_MESSAGE_BURST_LENGTH_SECONDS = 2; 20 21namespace { 22 23// Insert an item to the front of deque while maintaining the size of the deque. 24// Overflow item is discarded. 25template <typename T> 26T* 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. 36std::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. 61std::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. 82std::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. 113std::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 144GCMStatsRecorderImpl::GCMStatsRecorderImpl() 145 : is_recording_(false), 146 delegate_(NULL), 147 data_message_received_since_connected_(false), 148 received_data_message_burst_size_(0) { 149} 150 151GCMStatsRecorderImpl::~GCMStatsRecorderImpl() { 152} 153 154void GCMStatsRecorderImpl::SetRecording(bool recording) { 155 is_recording_ = recording; 156} 157 158void GCMStatsRecorderImpl::SetDelegate(Delegate* delegate) { 159 delegate_ = delegate; 160} 161 162void GCMStatsRecorderImpl::Clear() { 163 checkin_activities_.clear(); 164 connection_activities_.clear(); 165 registration_activities_.clear(); 166 receiving_activities_.clear(); 167 sending_activities_.clear(); 168} 169 170void GCMStatsRecorderImpl::NotifyActivityRecorded() { 171 if (delegate_) 172 delegate_->OnActivityRecorded(); 173} 174 175void 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 186void 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 193void 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 201void GCMStatsRecorderImpl::RecordCheckinSuccess() { 202 if (!is_recording_) 203 return; 204 RecordCheckin("Checkin succeeded", std::string()); 205} 206 207void 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 217void 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 228void 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 237void 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 246void 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 258void 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 265void GCMStatsRecorderImpl::RecordConnectionResetSignaled( 266 ConnectionFactory::ConnectionResetReason reason) { 267 if (!is_recording_) 268 return; 269 RecordConnection("Connection reset", 270 GetConnectionResetReasonString(reason)); 271} 272 273void 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 ®istration_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 288void 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 298void 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 309void 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 320void 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 329void 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 340void 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 352void 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 369void 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 432void 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 456void 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 472void 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 483void 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 503void 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 515