1 // Copyright (c) 2012 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 //------------------------------------------------------------------------------ 6 // Description of the life cycle of a instance of MetricsService. 7 // 8 // OVERVIEW 9 // 10 // A MetricsService instance is typically created at application startup. It is 11 // the central controller for the acquisition of log data, and the automatic 12 // transmission of that log data to an external server. Its major job is to 13 // manage logs, grouping them for transmission, and transmitting them. As part 14 // of its grouping, MS finalizes logs by including some just-in-time gathered 15 // memory statistics, snapshotting the current stats of numerous histograms, 16 // closing the logs, translating to protocol buffer format, and compressing the 17 // results for transmission. Transmission includes submitting a compressed log 18 // as data in a URL-post, and retransmitting (or retaining at process 19 // termination) if the attempted transmission failed. Retention across process 20 // terminations is done using the the PrefServices facilities. The retained logs 21 // (the ones that never got transmitted) are compressed and base64-encoded 22 // before being persisted. 23 // 24 // Logs fall into one of two categories: "initial logs," and "ongoing logs." 25 // There is at most one initial log sent for each complete run of Chrome (from 26 // startup, to browser shutdown). An initial log is generally transmitted some 27 // short time (1 minute?) after startup, and includes stats such as recent crash 28 // info, the number and types of plugins, etc. The external server's response 29 // to the initial log conceptually tells this MS if it should continue 30 // transmitting logs (during this session). The server response can actually be 31 // much more detailed, and always includes (at a minimum) how often additional 32 // ongoing logs should be sent. 33 // 34 // After the above initial log, a series of ongoing logs will be transmitted. 35 // The first ongoing log actually begins to accumulate information stating when 36 // the MS was first constructed. Note that even though the initial log is 37 // commonly sent a full minute after startup, the initial log does not include 38 // much in the way of user stats. The most common interlog period (delay) 39 // is 30 minutes. That time period starts when the first user action causes a 40 // logging event. This means that if there is no user action, there may be long 41 // periods without any (ongoing) log transmissions. Ongoing logs typically 42 // contain very detailed records of user activities (ex: opened tab, closed 43 // tab, fetched URL, maximized window, etc.) In addition, just before an 44 // ongoing log is closed out, a call is made to gather memory statistics. Those 45 // memory statistics are deposited into a histogram, and the log finalization 46 // code is then called. In the finalization, a call to a Histogram server 47 // acquires a list of all local histograms that have been flagged for upload 48 // to the UMA server. The finalization also acquires the most recent number 49 // of page loads, along with any counts of renderer or plugin crashes. 50 // 51 // When the browser shuts down, there will typically be a fragment of an ongoing 52 // log that has not yet been transmitted. At shutdown time, that fragment is 53 // closed (including snapshotting histograms), and persisted, for potential 54 // transmission during a future run of the product. 55 // 56 // There are two slightly abnormal shutdown conditions. There is a 57 // "disconnected scenario," and a "really fast startup and shutdown" scenario. 58 // In the "never connected" situation, the user has (during the running of the 59 // process) never established an internet connection. As a result, attempts to 60 // transmit the initial log have failed, and a lot(?) of data has accumulated in 61 // the ongoing log (which didn't yet get closed, because there was never even a 62 // contemplation of sending it). There is also a kindred "lost connection" 63 // situation, where a loss of connection prevented an ongoing log from being 64 // transmitted, and a (still open) log was stuck accumulating a lot(?) of data, 65 // while the earlier log retried its transmission. In both of these 66 // disconnected situations, two logs need to be, and are, persistently stored 67 // for future transmission. 68 // 69 // The other unusual shutdown condition, termed "really fast startup and 70 // shutdown," involves the deliberate user termination of the process before 71 // the initial log is even formed or transmitted. In that situation, no logging 72 // is done, but the historical crash statistics remain (unlogged) for inclusion 73 // in a future run's initial log. (i.e., we don't lose crash stats). 74 // 75 // With the above overview, we can now describe the state machine's various 76 // states, based on the State enum specified in the state_ member. Those states 77 // are: 78 // 79 // INITIALIZED, // Constructor was called. 80 // INIT_TASK_SCHEDULED, // Waiting for deferred init tasks to finish. 81 // INIT_TASK_DONE, // Waiting for timer to send initial log. 82 // SENDING_INITIAL_STABILITY_LOG, // Initial stability log being sent. 83 // SENDING_INITIAL_METRICS_LOG, // Initial metrics log being sent. 84 // SENDING_OLD_LOGS, // Sending unsent logs from previous session. 85 // SENDING_CURRENT_LOGS, // Sending ongoing logs as they acrue. 86 // 87 // In more detail, we have: 88 // 89 // INITIALIZED, // Constructor was called. 90 // The MS has been constructed, but has taken no actions to compose the 91 // initial log. 92 // 93 // INIT_TASK_SCHEDULED, // Waiting for deferred init tasks to finish. 94 // Typically about 30 seconds after startup, a task is sent to a second thread 95 // (the file thread) to perform deferred (lower priority and slower) 96 // initialization steps such as getting the list of plugins. That task will 97 // (when complete) make an async callback (via a Task) to indicate the 98 // completion. 99 // 100 // INIT_TASK_DONE, // Waiting for timer to send initial log. 101 // The callback has arrived, and it is now possible for an initial log to be 102 // created. This callback typically arrives back less than one second after 103 // the deferred init task is dispatched. 104 // 105 // SENDING_INITIAL_STABILITY_LOG, // Initial stability log being sent. 106 // During initialization, if a crash occurred during the previous session, an 107 // initial stability log will be generated and registered with the log manager. 108 // This state will be entered if a stability log was prepared during metrics 109 // service initialization (in InitializeMetricsRecordingState()) and is waiting 110 // to be transmitted when it's time to send up the first log (per the reporting 111 // scheduler). If there is no initial stability log (e.g. there was no previous 112 // crash), then this state will be skipped and the state will advance to 113 // SENDING_INITIAL_METRICS_LOG. 114 // 115 // SENDING_INITIAL_METRICS_LOG, // Initial metrics log being sent. 116 // This state is entered after the initial metrics log has been composed, and 117 // prepared for transmission. This happens after SENDING_INITIAL_STABILITY_LOG 118 // if there was an initial stability log (see above). It is also the case that 119 // any previously unsent logs have been loaded into instance variables for 120 // possible transmission. 121 // 122 // SENDING_OLD_LOGS, // Sending unsent logs from previous session. 123 // This state indicates that the initial log for this session has been 124 // successfully sent and it is now time to send any logs that were 125 // saved from previous sessions. All such logs will be transmitted before 126 // exiting this state, and proceeding with ongoing logs from the current session 127 // (see next state). 128 // 129 // SENDING_CURRENT_LOGS, // Sending standard current logs as they accrue. 130 // Current logs are being accumulated. Typically every 20 minutes a log is 131 // closed and finalized for transmission, at the same time as a new log is 132 // started. 133 // 134 // The progression through the above states is simple, and sequential, in the 135 // most common use cases. States proceed from INITIAL to SENDING_CURRENT_LOGS, 136 // and remain in the latter until shutdown. 137 // 138 // The one unusual case is when the user asks that we stop logging. When that 139 // happens, any staged (transmission in progress) log is persisted, and any log 140 // that is currently accumulating is also finalized and persisted. We then 141 // regress back to the SEND_OLD_LOGS state in case the user enables log 142 // recording again during this session. This way anything we have persisted 143 // will be sent automatically if/when we progress back to SENDING_CURRENT_LOG 144 // state. 145 // 146 // Another similar case is on mobile, when the application is backgrounded and 147 // then foregrounded again. Backgrounding created new "old" stored logs, so the 148 // state drops back from SENDING_CURRENT_LOGS to SENDING_OLD_LOGS so those logs 149 // will be sent. 150 // 151 // Also note that whenever we successfully send an old log, we mirror the list 152 // of logs into the PrefService. This ensures that IF we crash, we won't start 153 // up and retransmit our old logs again. 154 // 155 // Due to race conditions, it is always possible that a log file could be sent 156 // twice. For example, if a log file is sent, but not yet acknowledged by 157 // the external server, and the user shuts down, then a copy of the log may be 158 // saved for re-transmission. These duplicates could be filtered out server 159 // side, but are not expected to be a significant problem. 160 // 161 // 162 //------------------------------------------------------------------------------ 163 164 #include "chrome/browser/metrics/metrics_service.h" 165 166 #include <algorithm> 167 168 #include "base/bind.h" 169 #include "base/callback.h" 170 #include "base/command_line.h" 171 #include "base/guid.h" 172 #include "base/md5.h" 173 #include "base/metrics/histogram.h" 174 #include "base/metrics/sparse_histogram.h" 175 #include "base/metrics/statistics_recorder.h" 176 #include "base/prefs/pref_registry_simple.h" 177 #include "base/prefs/pref_service.h" 178 #include "base/prefs/scoped_user_pref_update.h" 179 #include "base/rand_util.h" 180 #include "base/strings/string_number_conversions.h" 181 #include "base/strings/utf_string_conversions.h" 182 #include "base/threading/platform_thread.h" 183 #include "base/threading/thread.h" 184 #include "base/threading/thread_restrictions.h" 185 #include "base/tracked_objects.h" 186 #include "base/values.h" 187 #include "chrome/browser/browser_process.h" 188 #include "chrome/browser/chrome_notification_types.h" 189 #include "chrome/browser/extensions/extension_service.h" 190 #include "chrome/browser/io_thread.h" 191 #include "chrome/browser/memory_details.h" 192 #include "chrome/browser/metrics/compression_utils.h" 193 #include "chrome/browser/metrics/metrics_log.h" 194 #include "chrome/browser/metrics/metrics_log_serializer.h" 195 #include "chrome/browser/metrics/metrics_reporting_scheduler.h" 196 #include "chrome/browser/metrics/time_ticks_experiment_win.h" 197 #include "chrome/browser/metrics/tracking_synchronizer.h" 198 #include "chrome/common/metrics/variations/variations_util.h" 199 #include "chrome/browser/net/http_pipelining_compatibility_client.h" 200 #include "chrome/browser/net/network_stats.h" 201 #include "chrome/browser/omnibox/omnibox_log.h" 202 #include "chrome/browser/profiles/profile.h" 203 #include "chrome/browser/ui/browser_list.h" 204 #include "chrome/browser/ui/browser_otr_state.h" 205 #include "chrome/browser/ui/search/search_tab_helper.h" 206 #include "chrome/common/chrome_constants.h" 207 #include "chrome/common/chrome_result_codes.h" 208 #include "chrome/common/chrome_switches.h" 209 #include "chrome/common/crash_keys.h" 210 #include "chrome/common/metrics/caching_permuted_entropy_provider.h" 211 #include "chrome/common/metrics/metrics_log_manager.h" 212 #include "chrome/common/net/test_server_locations.h" 213 #include "chrome/common/pref_names.h" 214 #include "chrome/common/render_messages.h" 215 #include "components/variations/entropy_provider.h" 216 #include "components/variations/metrics_util.h" 217 #include "content/public/browser/child_process_data.h" 218 #include "content/public/browser/histogram_fetcher.h" 219 #include "content/public/browser/load_notification_details.h" 220 #include "content/public/browser/notification_service.h" 221 #include "content/public/browser/plugin_service.h" 222 #include "content/public/browser/render_process_host.h" 223 #include "content/public/browser/user_metrics.h" 224 #include "content/public/browser/web_contents.h" 225 #include "content/public/common/process_type.h" 226 #include "content/public/common/webplugininfo.h" 227 #include "extensions/browser/process_map.h" 228 #include "net/base/load_flags.h" 229 #include "net/url_request/url_fetcher.h" 230 231 // TODO(port): port browser_distribution.h. 232 #if !defined(OS_POSIX) 233 #include "chrome/installer/util/browser_distribution.h" 234 #endif 235 236 #if defined(OS_CHROMEOS) 237 #include "chrome/browser/chromeos/external_metrics.h" 238 #include "chromeos/system/statistics_provider.h" 239 #endif 240 241 #if defined(OS_WIN) 242 #include <windows.h> // Needed for STATUS_* codes 243 #include "base/win/registry.h" 244 #endif 245 246 #if !defined(OS_ANDROID) 247 #include "chrome/browser/service_process/service_process_control.h" 248 #endif 249 250 using base::Time; 251 using content::BrowserThread; 252 using content::ChildProcessData; 253 using content::LoadNotificationDetails; 254 using content::PluginService; 255 256 namespace { 257 258 // Check to see that we're being called on only one thread. 259 bool IsSingleThreaded() { 260 static base::PlatformThreadId thread_id = 0; 261 if (!thread_id) 262 thread_id = base::PlatformThread::CurrentId(); 263 return base::PlatformThread::CurrentId() == thread_id; 264 } 265 266 // The delay, in seconds, after starting recording before doing expensive 267 // initialization work. 268 #if defined(OS_ANDROID) || defined(OS_IOS) 269 // On mobile devices, a significant portion of sessions last less than a minute. 270 // Use a shorter timer on these platforms to avoid losing data. 271 // TODO(dfalcantara): To avoid delaying startup, tighten up initialization so 272 // that it occurs after the user gets their initial page. 273 const int kInitializationDelaySeconds = 5; 274 #else 275 const int kInitializationDelaySeconds = 30; 276 #endif 277 278 // This specifies the amount of time to wait for all renderers to send their 279 // data. 280 const int kMaxHistogramGatheringWaitDuration = 60000; // 60 seconds. 281 282 // The maximum number of events in a log uploaded to the UMA server. 283 const int kEventLimit = 2400; 284 285 // If an upload fails, and the transmission was over this byte count, then we 286 // will discard the log, and not try to retransmit it. We also don't persist 287 // the log to the prefs for transmission during the next chrome session if this 288 // limit is exceeded. 289 const size_t kUploadLogAvoidRetransmitSize = 50000; 290 291 // Interval, in minutes, between state saves. 292 const int kSaveStateIntervalMinutes = 5; 293 294 enum ResponseStatus { 295 UNKNOWN_FAILURE, 296 SUCCESS, 297 BAD_REQUEST, // Invalid syntax or log too large. 298 NO_RESPONSE, 299 NUM_RESPONSE_STATUSES 300 }; 301 302 ResponseStatus ResponseCodeToStatus(int response_code) { 303 switch (response_code) { 304 case 200: 305 return SUCCESS; 306 case 400: 307 return BAD_REQUEST; 308 case net::URLFetcher::RESPONSE_CODE_INVALID: 309 return NO_RESPONSE; 310 default: 311 return UNKNOWN_FAILURE; 312 } 313 } 314 315 // The argument used to generate a non-identifying entropy source. We want no 316 // more than 13 bits of entropy, so use this max to return a number in the range 317 // [0, 7999] as the entropy source (12.97 bits of entropy). 318 const int kMaxLowEntropySize = 8000; 319 320 // Default prefs value for prefs::kMetricsLowEntropySource to indicate that the 321 // value has not yet been set. 322 const int kLowEntropySourceNotSet = -1; 323 324 // Generates a new non-identifying entropy source used to seed persistent 325 // activities. 326 int GenerateLowEntropySource() { 327 return base::RandInt(0, kMaxLowEntropySize - 1); 328 } 329 330 // Converts an exit code into something that can be inserted into our 331 // histograms (which expect non-negative numbers less than MAX_INT). 332 int MapCrashExitCodeForHistogram(int exit_code) { 333 #if defined(OS_WIN) 334 // Since |abs(STATUS_GUARD_PAGE_VIOLATION) == MAX_INT| it causes problems in 335 // histograms.cc. Solve this by remapping it to a smaller value, which 336 // hopefully doesn't conflict with other codes. 337 if (exit_code == STATUS_GUARD_PAGE_VIOLATION) 338 return 0x1FCF7EC3; // Randomly picked number. 339 #endif 340 341 return std::abs(exit_code); 342 } 343 344 void MarkAppCleanShutdownAndCommit() { 345 PrefService* pref = g_browser_process->local_state(); 346 pref->SetBoolean(prefs::kStabilityExitedCleanly, true); 347 pref->SetInteger(prefs::kStabilityExecutionPhase, 348 MetricsService::SHUTDOWN_COMPLETE); 349 // Start writing right away (write happens on a different thread). 350 pref->CommitPendingWrite(); 351 } 352 353 // Returns whether initial stability metrics should be sent in a separate log. 354 bool SendSeparateInitialStabilityLog() { 355 return base::FieldTrialList::FindFullName("UMAStability") == "SeparateLog"; 356 } 357 358 } // namespace 359 360 361 SyntheticTrialGroup::SyntheticTrialGroup(uint32 trial, 362 uint32 group, 363 base::TimeTicks start) 364 : start_time(start) { 365 id.name = trial; 366 id.group = group; 367 } 368 369 SyntheticTrialGroup::~SyntheticTrialGroup() { 370 } 371 372 // static 373 MetricsService::ShutdownCleanliness MetricsService::clean_shutdown_status_ = 374 MetricsService::CLEANLY_SHUTDOWN; 375 376 MetricsService::ExecutionPhase MetricsService::execution_phase_ = 377 MetricsService::UNINITIALIZED_PHASE; 378 379 // This is used to quickly log stats from child process related notifications in 380 // MetricsService::child_stats_buffer_. The buffer's contents are transferred 381 // out when Local State is periodically saved. The information is then 382 // reported to the UMA server on next launch. 383 struct MetricsService::ChildProcessStats { 384 public: 385 explicit ChildProcessStats(int process_type) 386 : process_launches(0), 387 process_crashes(0), 388 instances(0), 389 loading_errors(0), 390 process_type(process_type) {} 391 392 // This constructor is only used by the map to return some default value for 393 // an index for which no value has been assigned. 394 ChildProcessStats() 395 : process_launches(0), 396 process_crashes(0), 397 instances(0), 398 loading_errors(0), 399 process_type(content::PROCESS_TYPE_UNKNOWN) {} 400 401 // The number of times that the given child process has been launched 402 int process_launches; 403 404 // The number of times that the given child process has crashed 405 int process_crashes; 406 407 // The number of instances of this child process that have been created. 408 // An instance is a DOM object rendered by this child process during a page 409 // load. 410 int instances; 411 412 // The number of times there was an error loading an instance of this child 413 // process. 414 int loading_errors; 415 416 int process_type; 417 }; 418 419 // Handles asynchronous fetching of memory details. 420 // Will run the provided task after finished. 421 class MetricsMemoryDetails : public MemoryDetails { 422 public: 423 explicit MetricsMemoryDetails(const base::Closure& callback) 424 : callback_(callback) {} 425 426 virtual void OnDetailsAvailable() OVERRIDE { 427 base::MessageLoop::current()->PostTask(FROM_HERE, callback_); 428 } 429 430 private: 431 virtual ~MetricsMemoryDetails() {} 432 433 base::Closure callback_; 434 DISALLOW_COPY_AND_ASSIGN(MetricsMemoryDetails); 435 }; 436 437 // static 438 void MetricsService::RegisterPrefs(PrefRegistrySimple* registry) { 439 DCHECK(IsSingleThreaded()); 440 registry->RegisterStringPref(prefs::kMetricsClientID, std::string()); 441 registry->RegisterIntegerPref(prefs::kMetricsLowEntropySource, 442 kLowEntropySourceNotSet); 443 registry->RegisterInt64Pref(prefs::kMetricsClientIDTimestamp, 0); 444 registry->RegisterInt64Pref(prefs::kStabilityLaunchTimeSec, 0); 445 registry->RegisterInt64Pref(prefs::kStabilityLastTimestampSec, 0); 446 registry->RegisterStringPref(prefs::kStabilityStatsVersion, std::string()); 447 registry->RegisterInt64Pref(prefs::kStabilityStatsBuildTime, 0); 448 registry->RegisterBooleanPref(prefs::kStabilityExitedCleanly, true); 449 registry->RegisterIntegerPref(prefs::kStabilityExecutionPhase, 450 UNINITIALIZED_PHASE); 451 registry->RegisterBooleanPref(prefs::kStabilitySessionEndCompleted, true); 452 registry->RegisterIntegerPref(prefs::kMetricsSessionID, -1); 453 registry->RegisterIntegerPref(prefs::kStabilityLaunchCount, 0); 454 registry->RegisterIntegerPref(prefs::kStabilityCrashCount, 0); 455 registry->RegisterIntegerPref(prefs::kStabilityIncompleteSessionEndCount, 0); 456 registry->RegisterIntegerPref(prefs::kStabilityPageLoadCount, 0); 457 registry->RegisterIntegerPref(prefs::kStabilityRendererCrashCount, 0); 458 registry->RegisterIntegerPref(prefs::kStabilityExtensionRendererCrashCount, 459 0); 460 registry->RegisterIntegerPref(prefs::kStabilityRendererHangCount, 0); 461 registry->RegisterIntegerPref(prefs::kStabilityChildProcessCrashCount, 0); 462 registry->RegisterIntegerPref(prefs::kStabilityBreakpadRegistrationFail, 0); 463 registry->RegisterIntegerPref(prefs::kStabilityBreakpadRegistrationSuccess, 464 0); 465 registry->RegisterIntegerPref(prefs::kStabilityDebuggerPresent, 0); 466 registry->RegisterIntegerPref(prefs::kStabilityDebuggerNotPresent, 0); 467 #if defined(OS_CHROMEOS) 468 registry->RegisterIntegerPref(prefs::kStabilityOtherUserCrashCount, 0); 469 registry->RegisterIntegerPref(prefs::kStabilityKernelCrashCount, 0); 470 registry->RegisterIntegerPref(prefs::kStabilitySystemUncleanShutdownCount, 0); 471 #endif // OS_CHROMEOS 472 473 registry->RegisterStringPref(prefs::kStabilitySavedSystemProfile, 474 std::string()); 475 registry->RegisterStringPref(prefs::kStabilitySavedSystemProfileHash, 476 std::string()); 477 478 registry->RegisterListPref(prefs::kMetricsInitialLogs); 479 registry->RegisterListPref(prefs::kMetricsOngoingLogs); 480 481 registry->RegisterInt64Pref(prefs::kInstallDate, 0); 482 registry->RegisterInt64Pref(prefs::kUninstallMetricsPageLoadCount, 0); 483 registry->RegisterInt64Pref(prefs::kUninstallLaunchCount, 0); 484 registry->RegisterInt64Pref(prefs::kUninstallMetricsUptimeSec, 0); 485 registry->RegisterInt64Pref(prefs::kUninstallLastLaunchTimeSec, 0); 486 registry->RegisterInt64Pref(prefs::kUninstallLastObservedRunTimeSec, 0); 487 } 488 489 // static 490 void MetricsService::DiscardOldStabilityStats(PrefService* local_state) { 491 local_state->SetBoolean(prefs::kStabilityExitedCleanly, true); 492 local_state->SetInteger(prefs::kStabilityExecutionPhase, UNINITIALIZED_PHASE); 493 local_state->SetBoolean(prefs::kStabilitySessionEndCompleted, true); 494 495 local_state->SetInteger(prefs::kStabilityIncompleteSessionEndCount, 0); 496 local_state->SetInteger(prefs::kStabilityBreakpadRegistrationSuccess, 0); 497 local_state->SetInteger(prefs::kStabilityBreakpadRegistrationFail, 0); 498 local_state->SetInteger(prefs::kStabilityDebuggerPresent, 0); 499 local_state->SetInteger(prefs::kStabilityDebuggerNotPresent, 0); 500 501 local_state->SetInteger(prefs::kStabilityLaunchCount, 0); 502 local_state->SetInteger(prefs::kStabilityCrashCount, 0); 503 504 local_state->SetInteger(prefs::kStabilityPageLoadCount, 0); 505 local_state->SetInteger(prefs::kStabilityRendererCrashCount, 0); 506 local_state->SetInteger(prefs::kStabilityRendererHangCount, 0); 507 508 local_state->SetInt64(prefs::kStabilityLaunchTimeSec, 0); 509 local_state->SetInt64(prefs::kStabilityLastTimestampSec, 0); 510 511 local_state->ClearPref(prefs::kStabilityPluginStats); 512 513 local_state->ClearPref(prefs::kMetricsInitialLogs); 514 local_state->ClearPref(prefs::kMetricsOngoingLogs); 515 } 516 517 MetricsService::MetricsService() 518 : recording_active_(false), 519 reporting_active_(false), 520 test_mode_active_(false), 521 state_(INITIALIZED), 522 has_initial_stability_log_(false), 523 low_entropy_source_(kLowEntropySourceNotSet), 524 idle_since_last_transmission_(false), 525 session_id_(-1), 526 next_window_id_(0), 527 self_ptr_factory_(this), 528 state_saver_factory_(this), 529 waiting_for_asynchronous_reporting_step_(false), 530 num_async_histogram_fetches_in_progress_(0), 531 entropy_source_returned_(LAST_ENTROPY_NONE) { 532 DCHECK(IsSingleThreaded()); 533 534 log_manager_.set_log_serializer(new MetricsLogSerializer); 535 log_manager_.set_max_ongoing_log_store_size(kUploadLogAvoidRetransmitSize); 536 537 BrowserChildProcessObserver::Add(this); 538 } 539 540 MetricsService::~MetricsService() { 541 DisableRecording(); 542 543 BrowserChildProcessObserver::Remove(this); 544 } 545 546 void MetricsService::InitializeMetricsRecordingState( 547 ReportingState reporting_state) { 548 InitializeMetricsState(reporting_state); 549 550 base::Closure callback = base::Bind(&MetricsService::StartScheduledUpload, 551 self_ptr_factory_.GetWeakPtr()); 552 scheduler_.reset(new MetricsReportingScheduler(callback)); 553 } 554 555 void MetricsService::Start() { 556 HandleIdleSinceLastTransmission(false); 557 EnableRecording(); 558 EnableReporting(); 559 } 560 561 void MetricsService::StartRecordingForTests() { 562 test_mode_active_ = true; 563 EnableRecording(); 564 DisableReporting(); 565 } 566 567 void MetricsService::Stop() { 568 HandleIdleSinceLastTransmission(false); 569 DisableReporting(); 570 DisableRecording(); 571 } 572 573 void MetricsService::EnableReporting() { 574 if (reporting_active_) 575 return; 576 reporting_active_ = true; 577 StartSchedulerIfNecessary(); 578 } 579 580 void MetricsService::DisableReporting() { 581 reporting_active_ = false; 582 } 583 584 std::string MetricsService::GetClientId() { 585 return client_id_; 586 } 587 588 scoped_ptr<const base::FieldTrial::EntropyProvider> 589 MetricsService::CreateEntropyProvider(ReportingState reporting_state) { 590 // For metrics reporting-enabled users, we combine the client ID and low 591 // entropy source to get the final entropy source. Otherwise, only use the low 592 // entropy source. 593 // This has two useful properties: 594 // 1) It makes the entropy source less identifiable for parties that do not 595 // know the low entropy source. 596 // 2) It makes the final entropy source resettable. 597 const int low_entropy_source_value = GetLowEntropySource(); 598 UMA_HISTOGRAM_SPARSE_SLOWLY("UMA.LowEntropySourceValue", 599 low_entropy_source_value); 600 if (reporting_state == REPORTING_ENABLED) { 601 if (entropy_source_returned_ == LAST_ENTROPY_NONE) 602 entropy_source_returned_ = LAST_ENTROPY_HIGH; 603 DCHECK_EQ(LAST_ENTROPY_HIGH, entropy_source_returned_); 604 const std::string high_entropy_source = 605 client_id_ + base::IntToString(low_entropy_source_value); 606 return scoped_ptr<const base::FieldTrial::EntropyProvider>( 607 new metrics::SHA1EntropyProvider(high_entropy_source)); 608 } 609 610 if (entropy_source_returned_ == LAST_ENTROPY_NONE) 611 entropy_source_returned_ = LAST_ENTROPY_LOW; 612 DCHECK_EQ(LAST_ENTROPY_LOW, entropy_source_returned_); 613 614 #if defined(OS_ANDROID) || defined(OS_IOS) 615 return scoped_ptr<const base::FieldTrial::EntropyProvider>( 616 new metrics::CachingPermutedEntropyProvider( 617 g_browser_process->local_state(), 618 low_entropy_source_value, 619 kMaxLowEntropySize)); 620 #else 621 return scoped_ptr<const base::FieldTrial::EntropyProvider>( 622 new metrics::PermutedEntropyProvider(low_entropy_source_value, 623 kMaxLowEntropySize)); 624 #endif 625 } 626 627 void MetricsService::ForceClientIdCreation() { 628 if (!client_id_.empty()) 629 return; 630 PrefService* pref = g_browser_process->local_state(); 631 client_id_ = pref->GetString(prefs::kMetricsClientID); 632 if (!client_id_.empty()) 633 return; 634 635 client_id_ = GenerateClientID(); 636 pref->SetString(prefs::kMetricsClientID, client_id_); 637 638 // Might as well make a note of how long this ID has existed 639 pref->SetString(prefs::kMetricsClientIDTimestamp, 640 base::Int64ToString(Time::Now().ToTimeT())); 641 } 642 643 void MetricsService::EnableRecording() { 644 DCHECK(IsSingleThreaded()); 645 646 if (recording_active_) 647 return; 648 recording_active_ = true; 649 650 ForceClientIdCreation(); 651 crash_keys::SetClientID(client_id_); 652 if (!log_manager_.current_log()) 653 OpenNewLog(); 654 655 SetUpNotifications(®istrar_, this); 656 content::RemoveActionCallback(action_callback_); 657 action_callback_ = base::Bind(&MetricsService::OnUserAction, 658 base::Unretained(this)); 659 content::AddActionCallback(action_callback_); 660 } 661 662 void MetricsService::DisableRecording() { 663 DCHECK(IsSingleThreaded()); 664 665 if (!recording_active_) 666 return; 667 recording_active_ = false; 668 669 content::RemoveActionCallback(action_callback_); 670 registrar_.RemoveAll(); 671 PushPendingLogsToPersistentStorage(); 672 DCHECK(!log_manager_.has_staged_log()); 673 } 674 675 bool MetricsService::recording_active() const { 676 DCHECK(IsSingleThreaded()); 677 return recording_active_; 678 } 679 680 bool MetricsService::reporting_active() const { 681 DCHECK(IsSingleThreaded()); 682 return reporting_active_; 683 } 684 685 // static 686 void MetricsService::SetUpNotifications( 687 content::NotificationRegistrar* registrar, 688 content::NotificationObserver* observer) { 689 registrar->Add(observer, chrome::NOTIFICATION_BROWSER_OPENED, 690 content::NotificationService::AllBrowserContextsAndSources()); 691 registrar->Add(observer, chrome::NOTIFICATION_BROWSER_CLOSED, 692 content::NotificationService::AllSources()); 693 registrar->Add(observer, chrome::NOTIFICATION_TAB_PARENTED, 694 content::NotificationService::AllSources()); 695 registrar->Add(observer, chrome::NOTIFICATION_TAB_CLOSING, 696 content::NotificationService::AllSources()); 697 registrar->Add(observer, content::NOTIFICATION_LOAD_START, 698 content::NotificationService::AllSources()); 699 registrar->Add(observer, content::NOTIFICATION_LOAD_STOP, 700 content::NotificationService::AllSources()); 701 registrar->Add(observer, content::NOTIFICATION_RENDERER_PROCESS_CLOSED, 702 content::NotificationService::AllSources()); 703 registrar->Add(observer, content::NOTIFICATION_RENDER_WIDGET_HOST_HANG, 704 content::NotificationService::AllSources()); 705 registrar->Add(observer, chrome::NOTIFICATION_OMNIBOX_OPENED_URL, 706 content::NotificationService::AllSources()); 707 } 708 709 void MetricsService::BrowserChildProcessHostConnected( 710 const content::ChildProcessData& data) { 711 GetChildProcessStats(data).process_launches++; 712 } 713 714 void MetricsService::BrowserChildProcessCrashed( 715 const content::ChildProcessData& data) { 716 GetChildProcessStats(data).process_crashes++; 717 // Exclude plugin crashes from the count below because we report them via 718 // a separate UMA metric. 719 if (!IsPluginProcess(data.process_type)) 720 IncrementPrefValue(prefs::kStabilityChildProcessCrashCount); 721 } 722 723 void MetricsService::BrowserChildProcessInstanceCreated( 724 const content::ChildProcessData& data) { 725 GetChildProcessStats(data).instances++; 726 } 727 728 void MetricsService::Observe(int type, 729 const content::NotificationSource& source, 730 const content::NotificationDetails& details) { 731 DCHECK(log_manager_.current_log()); 732 DCHECK(IsSingleThreaded()); 733 734 if (!CanLogNotification()) 735 return; 736 737 switch (type) { 738 case chrome::NOTIFICATION_BROWSER_OPENED: 739 case chrome::NOTIFICATION_BROWSER_CLOSED: 740 case chrome::NOTIFICATION_TAB_PARENTED: 741 case chrome::NOTIFICATION_TAB_CLOSING: 742 case content::NOTIFICATION_LOAD_STOP: 743 // These notifications are currently used only to break out of idle mode. 744 break; 745 746 case content::NOTIFICATION_LOAD_START: { 747 content::NavigationController* controller = 748 content::Source<content::NavigationController>(source).ptr(); 749 content::WebContents* web_contents = controller->GetWebContents(); 750 LogLoadStarted(web_contents); 751 break; 752 } 753 754 case content::NOTIFICATION_RENDERER_PROCESS_CLOSED: { 755 content::RenderProcessHost::RendererClosedDetails* process_details = 756 content::Details< 757 content::RenderProcessHost::RendererClosedDetails>( 758 details).ptr(); 759 content::RenderProcessHost* host = 760 content::Source<content::RenderProcessHost>(source).ptr(); 761 LogRendererCrash( 762 host, process_details->status, process_details->exit_code); 763 } 764 break; 765 766 case content::NOTIFICATION_RENDER_WIDGET_HOST_HANG: 767 LogRendererHang(); 768 break; 769 770 case chrome::NOTIFICATION_OMNIBOX_OPENED_URL: { 771 MetricsLog* current_log = 772 static_cast<MetricsLog*>(log_manager_.current_log()); 773 DCHECK(current_log); 774 current_log->RecordOmniboxOpenedURL( 775 *content::Details<OmniboxLog>(details).ptr()); 776 break; 777 } 778 779 default: 780 NOTREACHED(); 781 break; 782 } 783 784 HandleIdleSinceLastTransmission(false); 785 } 786 787 void MetricsService::HandleIdleSinceLastTransmission(bool in_idle) { 788 // If there wasn't a lot of action, maybe the computer was asleep, in which 789 // case, the log transmissions should have stopped. Here we start them up 790 // again. 791 if (!in_idle && idle_since_last_transmission_) 792 StartSchedulerIfNecessary(); 793 idle_since_last_transmission_ = in_idle; 794 } 795 796 void MetricsService::RecordStartOfSessionEnd() { 797 LogCleanShutdown(); 798 RecordBooleanPrefValue(prefs::kStabilitySessionEndCompleted, false); 799 } 800 801 void MetricsService::RecordCompletedSessionEnd() { 802 LogCleanShutdown(); 803 RecordBooleanPrefValue(prefs::kStabilitySessionEndCompleted, true); 804 } 805 806 #if defined(OS_ANDROID) || defined(OS_IOS) 807 void MetricsService::OnAppEnterBackground() { 808 scheduler_->Stop(); 809 810 MarkAppCleanShutdownAndCommit(); 811 812 // At this point, there's no way of knowing when the process will be 813 // killed, so this has to be treated similar to a shutdown, closing and 814 // persisting all logs. Unlinke a shutdown, the state is primed to be ready 815 // to continue logging and uploading if the process does return. 816 if (recording_active() && state_ >= SENDING_INITIAL_STABILITY_LOG) { 817 PushPendingLogsToPersistentStorage(); 818 // Persisting logs closes the current log, so start recording a new log 819 // immediately to capture any background work that might be done before the 820 // process is killed. 821 OpenNewLog(); 822 } 823 } 824 825 void MetricsService::OnAppEnterForeground() { 826 PrefService* pref = g_browser_process->local_state(); 827 pref->SetBoolean(prefs::kStabilityExitedCleanly, false); 828 829 StartSchedulerIfNecessary(); 830 } 831 #else 832 void MetricsService::LogNeedForCleanShutdown() { 833 PrefService* pref = g_browser_process->local_state(); 834 pref->SetBoolean(prefs::kStabilityExitedCleanly, false); 835 // Redundant setting to be sure we call for a clean shutdown. 836 clean_shutdown_status_ = NEED_TO_SHUTDOWN; 837 } 838 #endif // defined(OS_ANDROID) || defined(OS_IOS) 839 840 // static 841 void MetricsService::SetExecutionPhase(ExecutionPhase execution_phase) { 842 execution_phase_ = execution_phase; 843 PrefService* pref = g_browser_process->local_state(); 844 pref->SetInteger(prefs::kStabilityExecutionPhase, execution_phase_); 845 } 846 847 void MetricsService::RecordBreakpadRegistration(bool success) { 848 if (!success) 849 IncrementPrefValue(prefs::kStabilityBreakpadRegistrationFail); 850 else 851 IncrementPrefValue(prefs::kStabilityBreakpadRegistrationSuccess); 852 } 853 854 void MetricsService::RecordBreakpadHasDebugger(bool has_debugger) { 855 if (!has_debugger) 856 IncrementPrefValue(prefs::kStabilityDebuggerNotPresent); 857 else 858 IncrementPrefValue(prefs::kStabilityDebuggerPresent); 859 } 860 861 #if defined(OS_WIN) 862 void MetricsService::CountBrowserCrashDumpAttempts() { 863 // Open the registry key for iteration. 864 base::win::RegKey regkey; 865 if (regkey.Open(HKEY_CURRENT_USER, 866 chrome::kBrowserCrashDumpAttemptsRegistryPath, 867 KEY_ALL_ACCESS) != ERROR_SUCCESS) { 868 return; 869 } 870 871 // The values we're interested in counting are all prefixed with the version. 872 base::string16 chrome_version(base::ASCIIToUTF16(chrome::kChromeVersion)); 873 874 // Track a list of values to delete. We don't modify the registry key while 875 // we're iterating over its values. 876 typedef std::vector<base::string16> StringVector; 877 StringVector to_delete; 878 879 // Iterate over the values in the key counting dumps with and without crashes. 880 // We directly walk the values instead of using RegistryValueIterator in order 881 // to read all of the values as DWORDS instead of strings. 882 base::string16 name; 883 DWORD value = 0; 884 int dumps_with_crash = 0; 885 int dumps_with_no_crash = 0; 886 for (int i = regkey.GetValueCount() - 1; i >= 0; --i) { 887 if (regkey.GetValueNameAt(i, &name) == ERROR_SUCCESS && 888 StartsWith(name, chrome_version, false) && 889 regkey.ReadValueDW(name.c_str(), &value) == ERROR_SUCCESS) { 890 to_delete.push_back(name); 891 if (value == 0) 892 ++dumps_with_no_crash; 893 else 894 ++dumps_with_crash; 895 } 896 } 897 898 // Delete the registry keys we've just counted. 899 for (StringVector::iterator i = to_delete.begin(); i != to_delete.end(); ++i) 900 regkey.DeleteValue(i->c_str()); 901 902 // Capture the histogram samples. 903 if (dumps_with_crash != 0) 904 UMA_HISTOGRAM_COUNTS("Chrome.BrowserDumpsWithCrash", dumps_with_crash); 905 if (dumps_with_no_crash != 0) 906 UMA_HISTOGRAM_COUNTS("Chrome.BrowserDumpsWithNoCrash", dumps_with_no_crash); 907 int total_dumps = dumps_with_crash + dumps_with_no_crash; 908 if (total_dumps != 0) 909 UMA_HISTOGRAM_COUNTS("Chrome.BrowserCrashDumpAttempts", total_dumps); 910 } 911 #endif // defined(OS_WIN) 912 913 //------------------------------------------------------------------------------ 914 // private methods 915 //------------------------------------------------------------------------------ 916 917 918 //------------------------------------------------------------------------------ 919 // Initialization methods 920 921 void MetricsService::InitializeMetricsState(ReportingState reporting_state) { 922 #if defined(OS_POSIX) 923 network_stats_server_ = chrome_common_net::kEchoTestServerLocation; 924 http_pipelining_test_server_ = chrome_common_net::kPipelineTestServerBaseUrl; 925 #else 926 BrowserDistribution* dist = BrowserDistribution::GetDistribution(); 927 network_stats_server_ = dist->GetNetworkStatsServer(); 928 http_pipelining_test_server_ = dist->GetHttpPipeliningTestServer(); 929 #endif 930 931 PrefService* pref = g_browser_process->local_state(); 932 DCHECK(pref); 933 934 // TODO(asvitkine): Kill this logic when SendSeparateInitialStabilityLog() is 935 // is made the default behavior. 936 if ((pref->GetInt64(prefs::kStabilityStatsBuildTime) 937 != MetricsLog::GetBuildTime()) || 938 (pref->GetString(prefs::kStabilityStatsVersion) 939 != MetricsLog::GetVersionString())) { 940 // This is a new version, so we don't want to confuse the stats about the 941 // old version with info that we upload. 942 DiscardOldStabilityStats(pref); 943 pref->SetString(prefs::kStabilityStatsVersion, 944 MetricsLog::GetVersionString()); 945 pref->SetInt64(prefs::kStabilityStatsBuildTime, 946 MetricsLog::GetBuildTime()); 947 } 948 949 session_id_ = pref->GetInteger(prefs::kMetricsSessionID); 950 951 if (!pref->GetBoolean(prefs::kStabilityExitedCleanly)) { 952 IncrementPrefValue(prefs::kStabilityCrashCount); 953 // Reset flag, and wait until we call LogNeedForCleanShutdown() before 954 // monitoring. 955 pref->SetBoolean(prefs::kStabilityExitedCleanly, true); 956 957 // TODO(rtenneti): On windows, consider saving/getting execution_phase from 958 // the registry. 959 int execution_phase = pref->GetInteger(prefs::kStabilityExecutionPhase); 960 UMA_HISTOGRAM_SPARSE_SLOWLY("Chrome.Browser.CrashedExecutionPhase", 961 execution_phase); 962 963 // If the previous session didn't exit cleanly, then prepare an initial 964 // stability log if UMA is enabled. 965 bool reporting_will_be_enabled = (reporting_state == REPORTING_ENABLED); 966 if (reporting_will_be_enabled && SendSeparateInitialStabilityLog()) 967 PrepareInitialStabilityLog(); 968 } 969 970 // Update session ID. 971 ++session_id_; 972 pref->SetInteger(prefs::kMetricsSessionID, session_id_); 973 974 // Stability bookkeeping 975 IncrementPrefValue(prefs::kStabilityLaunchCount); 976 977 DCHECK_EQ(UNINITIALIZED_PHASE, execution_phase_); 978 SetExecutionPhase(START_METRICS_RECORDING); 979 980 #if defined(OS_WIN) 981 CountBrowserCrashDumpAttempts(); 982 #endif // defined(OS_WIN) 983 984 if (!pref->GetBoolean(prefs::kStabilitySessionEndCompleted)) { 985 IncrementPrefValue(prefs::kStabilityIncompleteSessionEndCount); 986 // This is marked false when we get a WM_ENDSESSION. 987 pref->SetBoolean(prefs::kStabilitySessionEndCompleted, true); 988 } 989 990 // Initialize uptime counters. 991 const base::TimeDelta startup_uptime = GetIncrementalUptime(pref); 992 DCHECK_EQ(0, startup_uptime.InMicroseconds()); 993 // For backwards compatibility, leave this intact in case Omaha is checking 994 // them. prefs::kStabilityLastTimestampSec may also be useless now. 995 // TODO(jar): Delete these if they have no uses. 996 pref->SetInt64(prefs::kStabilityLaunchTimeSec, Time::Now().ToTimeT()); 997 998 // Bookkeeping for the uninstall metrics. 999 IncrementLongPrefsValue(prefs::kUninstallLaunchCount); 1000 1001 // Get stats on use of command line. 1002 const CommandLine* command_line(CommandLine::ForCurrentProcess()); 1003 size_t common_commands = 0; 1004 if (command_line->HasSwitch(switches::kUserDataDir)) { 1005 ++common_commands; 1006 UMA_HISTOGRAM_COUNTS_100("Chrome.CommandLineDatDirCount", 1); 1007 } 1008 1009 if (command_line->HasSwitch(switches::kApp)) { 1010 ++common_commands; 1011 UMA_HISTOGRAM_COUNTS_100("Chrome.CommandLineAppModeCount", 1); 1012 } 1013 1014 size_t switch_count = command_line->GetSwitches().size(); 1015 UMA_HISTOGRAM_COUNTS_100("Chrome.CommandLineFlagCount", switch_count); 1016 UMA_HISTOGRAM_COUNTS_100("Chrome.CommandLineUncommonFlagCount", 1017 switch_count - common_commands); 1018 1019 // Kick off the process of saving the state (so the uptime numbers keep 1020 // getting updated) every n minutes. 1021 ScheduleNextStateSave(); 1022 } 1023 1024 // static 1025 void MetricsService::InitTaskGetHardwareClass( 1026 base::WeakPtr<MetricsService> self, 1027 base::MessageLoopProxy* target_loop) { 1028 DCHECK(BrowserThread::CurrentlyOn(BrowserThread::FILE)); 1029 1030 std::string hardware_class; 1031 #if defined(OS_CHROMEOS) 1032 chromeos::system::StatisticsProvider::GetInstance()->GetMachineStatistic( 1033 "hardware_class", &hardware_class); 1034 #endif // OS_CHROMEOS 1035 1036 target_loop->PostTask(FROM_HERE, 1037 base::Bind(&MetricsService::OnInitTaskGotHardwareClass, 1038 self, hardware_class)); 1039 } 1040 1041 void MetricsService::OnInitTaskGotHardwareClass( 1042 const std::string& hardware_class) { 1043 DCHECK_EQ(INIT_TASK_SCHEDULED, state_); 1044 hardware_class_ = hardware_class; 1045 1046 #if defined(ENABLE_PLUGINS) 1047 // Start the next part of the init task: loading plugin information. 1048 PluginService::GetInstance()->GetPlugins( 1049 base::Bind(&MetricsService::OnInitTaskGotPluginInfo, 1050 self_ptr_factory_.GetWeakPtr())); 1051 #else 1052 std::vector<content::WebPluginInfo> plugin_list_empty; 1053 OnInitTaskGotPluginInfo(plugin_list_empty); 1054 #endif // defined(ENABLE_PLUGINS) 1055 } 1056 1057 void MetricsService::OnInitTaskGotPluginInfo( 1058 const std::vector<content::WebPluginInfo>& plugins) { 1059 DCHECK_EQ(INIT_TASK_SCHEDULED, state_); 1060 plugins_ = plugins; 1061 1062 // Schedules a task on a blocking pool thread to gather Google Update 1063 // statistics (requires Registry reads). 1064 BrowserThread::PostBlockingPoolTask( 1065 FROM_HERE, 1066 base::Bind(&MetricsService::InitTaskGetGoogleUpdateData, 1067 self_ptr_factory_.GetWeakPtr(), 1068 base::MessageLoop::current()->message_loop_proxy())); 1069 } 1070 1071 // static 1072 void MetricsService::InitTaskGetGoogleUpdateData( 1073 base::WeakPtr<MetricsService> self, 1074 base::MessageLoopProxy* target_loop) { 1075 GoogleUpdateMetrics google_update_metrics; 1076 1077 #if defined(OS_WIN) && defined(GOOGLE_CHROME_BUILD) 1078 const bool system_install = GoogleUpdateSettings::IsSystemInstall(); 1079 1080 google_update_metrics.is_system_install = system_install; 1081 google_update_metrics.last_started_au = 1082 GoogleUpdateSettings::GetGoogleUpdateLastStartedAU(system_install); 1083 google_update_metrics.last_checked = 1084 GoogleUpdateSettings::GetGoogleUpdateLastChecked(system_install); 1085 GoogleUpdateSettings::GetUpdateDetailForGoogleUpdate( 1086 system_install, 1087 &google_update_metrics.google_update_data); 1088 GoogleUpdateSettings::GetUpdateDetail( 1089 system_install, 1090 &google_update_metrics.product_data); 1091 #endif // defined(OS_WIN) && defined(GOOGLE_CHROME_BUILD) 1092 1093 target_loop->PostTask(FROM_HERE, 1094 base::Bind(&MetricsService::OnInitTaskGotGoogleUpdateData, 1095 self, google_update_metrics)); 1096 } 1097 1098 void MetricsService::OnInitTaskGotGoogleUpdateData( 1099 const GoogleUpdateMetrics& google_update_metrics) { 1100 DCHECK_EQ(INIT_TASK_SCHEDULED, state_); 1101 1102 google_update_metrics_ = google_update_metrics; 1103 1104 // Start the next part of the init task: fetching performance data. This will 1105 // call into |FinishedReceivingProfilerData()| when the task completes. 1106 chrome_browser_metrics::TrackingSynchronizer::FetchProfilerDataAsynchronously( 1107 self_ptr_factory_.GetWeakPtr()); 1108 } 1109 1110 void MetricsService::OnUserAction(const std::string& action) { 1111 if (!CanLogNotification()) 1112 return; 1113 1114 log_manager_.current_log()->RecordUserAction(action.c_str()); 1115 HandleIdleSinceLastTransmission(false); 1116 } 1117 1118 void MetricsService::ReceivedProfilerData( 1119 const tracked_objects::ProcessDataSnapshot& process_data, 1120 int process_type) { 1121 DCHECK_EQ(INIT_TASK_SCHEDULED, state_); 1122 1123 // Upon the first callback, create the initial log so that we can immediately 1124 // save the profiler data. 1125 if (!initial_metrics_log_.get()) 1126 initial_metrics_log_.reset(new MetricsLog(client_id_, session_id_)); 1127 1128 initial_metrics_log_->RecordProfilerData(process_data, process_type); 1129 } 1130 1131 void MetricsService::FinishedReceivingProfilerData() { 1132 DCHECK_EQ(INIT_TASK_SCHEDULED, state_); 1133 state_ = INIT_TASK_DONE; 1134 scheduler_->InitTaskComplete(); 1135 } 1136 1137 base::TimeDelta MetricsService::GetIncrementalUptime(PrefService* pref) { 1138 base::TimeTicks now = base::TimeTicks::Now(); 1139 // If this is the first call, init |last_updated_time_|. 1140 if (last_updated_time_.is_null()) 1141 last_updated_time_ = now; 1142 const base::TimeDelta incremental_time = now - last_updated_time_; 1143 last_updated_time_ = now; 1144 1145 const int64 incremental_time_secs = incremental_time.InSeconds(); 1146 if (incremental_time_secs > 0) { 1147 int64 metrics_uptime = pref->GetInt64(prefs::kUninstallMetricsUptimeSec); 1148 metrics_uptime += incremental_time_secs; 1149 pref->SetInt64(prefs::kUninstallMetricsUptimeSec, metrics_uptime); 1150 } 1151 1152 return incremental_time; 1153 } 1154 1155 int MetricsService::GetLowEntropySource() { 1156 // Note that the default value for the low entropy source and the default pref 1157 // value are both kLowEntropySourceNotSet, which is used to identify if the 1158 // value has been set or not. 1159 if (low_entropy_source_ != kLowEntropySourceNotSet) 1160 return low_entropy_source_; 1161 1162 PrefService* local_state = g_browser_process->local_state(); 1163 const CommandLine* command_line(CommandLine::ForCurrentProcess()); 1164 // Only try to load the value from prefs if the user did not request a reset. 1165 // Otherwise, skip to generating a new value. 1166 if (!command_line->HasSwitch(switches::kResetVariationState)) { 1167 int value = local_state->GetInteger(prefs::kMetricsLowEntropySource); 1168 // Old versions of the code would generate values in the range of [1, 8192], 1169 // before the range was switched to [0, 8191] and then to [0, 7999]. Map 1170 // 8192 to 0, so that the 0th bucket remains uniform, while re-generating 1171 // the low entropy source for old values in the [8000, 8191] range. 1172 if (value == 8192) 1173 value = 0; 1174 // If the value is outside the [0, kMaxLowEntropySize) range, re-generate 1175 // it below. 1176 if (value >= 0 && value < kMaxLowEntropySize) { 1177 low_entropy_source_ = value; 1178 UMA_HISTOGRAM_BOOLEAN("UMA.GeneratedLowEntropySource", false); 1179 return low_entropy_source_; 1180 } 1181 } 1182 1183 UMA_HISTOGRAM_BOOLEAN("UMA.GeneratedLowEntropySource", true); 1184 low_entropy_source_ = GenerateLowEntropySource(); 1185 local_state->SetInteger(prefs::kMetricsLowEntropySource, low_entropy_source_); 1186 metrics::CachingPermutedEntropyProvider::ClearCache(local_state); 1187 1188 return low_entropy_source_; 1189 } 1190 1191 // static 1192 std::string MetricsService::GenerateClientID() { 1193 return base::GenerateGUID(); 1194 } 1195 1196 //------------------------------------------------------------------------------ 1197 // State save methods 1198 1199 void MetricsService::ScheduleNextStateSave() { 1200 state_saver_factory_.InvalidateWeakPtrs(); 1201 1202 base::MessageLoop::current()->PostDelayedTask(FROM_HERE, 1203 base::Bind(&MetricsService::SaveLocalState, 1204 state_saver_factory_.GetWeakPtr()), 1205 base::TimeDelta::FromMinutes(kSaveStateIntervalMinutes)); 1206 } 1207 1208 void MetricsService::SaveLocalState() { 1209 PrefService* pref = g_browser_process->local_state(); 1210 if (!pref) { 1211 NOTREACHED(); 1212 return; 1213 } 1214 1215 RecordCurrentState(pref); 1216 1217 // TODO(jar):110021 Does this run down the batteries???? 1218 ScheduleNextStateSave(); 1219 } 1220 1221 1222 //------------------------------------------------------------------------------ 1223 // Recording control methods 1224 1225 void MetricsService::OpenNewLog() { 1226 DCHECK(!log_manager_.current_log()); 1227 1228 log_manager_.BeginLoggingWithLog(new MetricsLog(client_id_, session_id_), 1229 MetricsLog::ONGOING_LOG); 1230 if (state_ == INITIALIZED) { 1231 // We only need to schedule that run once. 1232 state_ = INIT_TASK_SCHEDULED; 1233 1234 // Schedules a task on the file thread for execution of slower 1235 // initialization steps (such as plugin list generation) necessary 1236 // for sending the initial log. This avoids blocking the main UI 1237 // thread. 1238 BrowserThread::PostDelayedTask( 1239 BrowserThread::FILE, 1240 FROM_HERE, 1241 base::Bind(&MetricsService::InitTaskGetHardwareClass, 1242 self_ptr_factory_.GetWeakPtr(), 1243 base::MessageLoop::current()->message_loop_proxy()), 1244 base::TimeDelta::FromSeconds(kInitializationDelaySeconds)); 1245 } 1246 } 1247 1248 void MetricsService::CloseCurrentLog() { 1249 if (!log_manager_.current_log()) 1250 return; 1251 1252 // TODO(jar): Integrate bounds on log recording more consistently, so that we 1253 // can stop recording logs that are too big much sooner. 1254 if (log_manager_.current_log()->num_events() > kEventLimit) { 1255 UMA_HISTOGRAM_COUNTS("UMA.Discarded Log Events", 1256 log_manager_.current_log()->num_events()); 1257 log_manager_.DiscardCurrentLog(); 1258 OpenNewLog(); // Start trivial log to hold our histograms. 1259 } 1260 1261 // Adds to ongoing logs. 1262 log_manager_.current_log()->set_hardware_class(hardware_class_); 1263 1264 // Put incremental data (histogram deltas, and realtime stats deltas) at the 1265 // end of all log transmissions (initial log handles this separately). 1266 // RecordIncrementalStabilityElements only exists on the derived 1267 // MetricsLog class. 1268 MetricsLog* current_log = 1269 static_cast<MetricsLog*>(log_manager_.current_log()); 1270 DCHECK(current_log); 1271 std::vector<chrome_variations::ActiveGroupId> synthetic_trials; 1272 GetCurrentSyntheticFieldTrials(&synthetic_trials); 1273 current_log->RecordEnvironment(plugins_, google_update_metrics_, 1274 synthetic_trials); 1275 PrefService* pref = g_browser_process->local_state(); 1276 current_log->RecordStabilityMetrics(GetIncrementalUptime(pref), 1277 MetricsLog::ONGOING_LOG); 1278 1279 RecordCurrentHistograms(); 1280 1281 log_manager_.FinishCurrentLog(); 1282 } 1283 1284 void MetricsService::PushPendingLogsToPersistentStorage() { 1285 if (state_ < SENDING_INITIAL_STABILITY_LOG) 1286 return; // We didn't and still don't have time to get plugin list etc. 1287 1288 if (log_manager_.has_staged_log()) { 1289 // We may race here, and send second copy of the log later. 1290 MetricsLogManager::StoreType store_type; 1291 if (current_fetch_.get()) 1292 store_type = MetricsLogManager::PROVISIONAL_STORE; 1293 else 1294 store_type = MetricsLogManager::NORMAL_STORE; 1295 log_manager_.StoreStagedLogAsUnsent(store_type); 1296 } 1297 DCHECK(!log_manager_.has_staged_log()); 1298 CloseCurrentLog(); 1299 log_manager_.PersistUnsentLogs(); 1300 1301 // If there was a staged and/or current log, then there is now at least one 1302 // log waiting to be uploaded. 1303 if (log_manager_.has_unsent_logs()) 1304 state_ = SENDING_OLD_LOGS; 1305 } 1306 1307 //------------------------------------------------------------------------------ 1308 // Transmission of logs methods 1309 1310 void MetricsService::StartSchedulerIfNecessary() { 1311 // Never schedule cutting or uploading of logs in test mode. 1312 if (test_mode_active_) 1313 return; 1314 1315 // Even if reporting is disabled, the scheduler is needed to trigger the 1316 // creation of the initial log, which must be done in order for any logs to be 1317 // persisted on shutdown or backgrounding. 1318 if (recording_active() && 1319 (reporting_active() || state_ < SENDING_INITIAL_STABILITY_LOG)) { 1320 scheduler_->Start(); 1321 } 1322 } 1323 1324 void MetricsService::StartScheduledUpload() { 1325 // If we're getting no notifications, then the log won't have much in it, and 1326 // it's possible the computer is about to go to sleep, so don't upload and 1327 // stop the scheduler. 1328 // If recording has been turned off, the scheduler doesn't need to run. 1329 // If reporting is off, proceed if the initial log hasn't been created, since 1330 // that has to happen in order for logs to be cut and stored when persisting. 1331 // TODO(stuartmorgan): Call Stop() on the schedule when reporting and/or 1332 // recording are turned off instead of letting it fire and then aborting. 1333 if (idle_since_last_transmission_ || 1334 !recording_active() || 1335 (!reporting_active() && state_ >= SENDING_INITIAL_STABILITY_LOG)) { 1336 scheduler_->Stop(); 1337 scheduler_->UploadCancelled(); 1338 return; 1339 } 1340 1341 // If the callback was to upload an old log, but there no longer is one, 1342 // just report success back to the scheduler to begin the ongoing log 1343 // callbacks. 1344 // TODO(stuartmorgan): Consider removing the distinction between 1345 // SENDING_OLD_LOGS and SENDING_CURRENT_LOGS to simplify the state machine 1346 // now that the log upload flow is the same for both modes. 1347 if (state_ == SENDING_OLD_LOGS && !log_manager_.has_unsent_logs()) { 1348 state_ = SENDING_CURRENT_LOGS; 1349 scheduler_->UploadFinished(true /* healthy */, false /* no unsent logs */); 1350 return; 1351 } 1352 // If there are unsent logs, send the next one. If not, start the asynchronous 1353 // process of finalizing the current log for upload. 1354 if (state_ == SENDING_OLD_LOGS) { 1355 DCHECK(log_manager_.has_unsent_logs()); 1356 log_manager_.StageNextLogForUpload(); 1357 SendStagedLog(); 1358 } else { 1359 StartFinalLogInfoCollection(); 1360 } 1361 } 1362 1363 void MetricsService::StartFinalLogInfoCollection() { 1364 // Begin the multi-step process of collecting memory usage histograms: 1365 // First spawn a task to collect the memory details; when that task is 1366 // finished, it will call OnMemoryDetailCollectionDone. That will in turn 1367 // call HistogramSynchronization to collect histograms from all renderers and 1368 // then call OnHistogramSynchronizationDone to continue processing. 1369 DCHECK(!waiting_for_asynchronous_reporting_step_); 1370 waiting_for_asynchronous_reporting_step_ = true; 1371 1372 base::Closure callback = 1373 base::Bind(&MetricsService::OnMemoryDetailCollectionDone, 1374 self_ptr_factory_.GetWeakPtr()); 1375 1376 scoped_refptr<MetricsMemoryDetails> details( 1377 new MetricsMemoryDetails(callback)); 1378 details->StartFetch(MemoryDetails::UPDATE_USER_METRICS); 1379 1380 // Collect WebCore cache information to put into a histogram. 1381 for (content::RenderProcessHost::iterator i( 1382 content::RenderProcessHost::AllHostsIterator()); 1383 !i.IsAtEnd(); i.Advance()) 1384 i.GetCurrentValue()->Send(new ChromeViewMsg_GetCacheResourceStats()); 1385 } 1386 1387 void MetricsService::OnMemoryDetailCollectionDone() { 1388 DCHECK(IsSingleThreaded()); 1389 // This function should only be called as the callback from an ansynchronous 1390 // step. 1391 DCHECK(waiting_for_asynchronous_reporting_step_); 1392 1393 // Create a callback_task for OnHistogramSynchronizationDone. 1394 base::Closure callback = base::Bind( 1395 &MetricsService::OnHistogramSynchronizationDone, 1396 self_ptr_factory_.GetWeakPtr()); 1397 1398 base::TimeDelta timeout = 1399 base::TimeDelta::FromMilliseconds(kMaxHistogramGatheringWaitDuration); 1400 1401 DCHECK_EQ(num_async_histogram_fetches_in_progress_, 0); 1402 1403 #if defined(OS_ANDROID) 1404 // Android has no service process. 1405 num_async_histogram_fetches_in_progress_ = 1; 1406 #else // OS_ANDROID 1407 num_async_histogram_fetches_in_progress_ = 2; 1408 // Run requests to service and content in parallel. 1409 if (!ServiceProcessControl::GetInstance()->GetHistograms(callback, timeout)) { 1410 // Assume |num_async_histogram_fetches_in_progress_| is not changed by 1411 // |GetHistograms()|. 1412 DCHECK_EQ(num_async_histogram_fetches_in_progress_, 2); 1413 // Assign |num_async_histogram_fetches_in_progress_| above and decrement it 1414 // here to make code work even if |GetHistograms()| fired |callback|. 1415 --num_async_histogram_fetches_in_progress_; 1416 } 1417 #endif // OS_ANDROID 1418 1419 // Set up the callback to task to call after we receive histograms from all 1420 // child processes. Wait time specifies how long to wait before absolutely 1421 // calling us back on the task. 1422 content::FetchHistogramsAsynchronously(base::MessageLoop::current(), callback, 1423 timeout); 1424 } 1425 1426 void MetricsService::OnHistogramSynchronizationDone() { 1427 DCHECK(IsSingleThreaded()); 1428 // This function should only be called as the callback from an ansynchronous 1429 // step. 1430 DCHECK(waiting_for_asynchronous_reporting_step_); 1431 DCHECK_GT(num_async_histogram_fetches_in_progress_, 0); 1432 1433 // Check if all expected requests finished. 1434 if (--num_async_histogram_fetches_in_progress_ > 0) 1435 return; 1436 1437 waiting_for_asynchronous_reporting_step_ = false; 1438 OnFinalLogInfoCollectionDone(); 1439 } 1440 1441 void MetricsService::OnFinalLogInfoCollectionDone() { 1442 // If somehow there is a fetch in progress, we return and hope things work 1443 // out. The scheduler isn't informed since if this happens, the scheduler 1444 // will get a response from the upload. 1445 DCHECK(!current_fetch_.get()); 1446 if (current_fetch_.get()) 1447 return; 1448 1449 // Abort if metrics were turned off during the final info gathering. 1450 if (!recording_active()) { 1451 scheduler_->Stop(); 1452 scheduler_->UploadCancelled(); 1453 return; 1454 } 1455 1456 StageNewLog(); 1457 1458 // If logs shouldn't be uploaded, stop here. It's important that this check 1459 // be after StageNewLog(), otherwise the previous logs will never be loaded, 1460 // and thus the open log won't be persisted. 1461 // TODO(stuartmorgan): This is unnecessarily complicated; restructure loading 1462 // of previous logs to not require running part of the upload logic. 1463 // http://crbug.com/157337 1464 if (!reporting_active()) { 1465 scheduler_->Stop(); 1466 scheduler_->UploadCancelled(); 1467 return; 1468 } 1469 1470 SendStagedLog(); 1471 } 1472 1473 void MetricsService::StageNewLog() { 1474 if (log_manager_.has_staged_log()) 1475 return; 1476 1477 switch (state_) { 1478 case INITIALIZED: 1479 case INIT_TASK_SCHEDULED: // We should be further along by now. 1480 NOTREACHED(); 1481 return; 1482 1483 case INIT_TASK_DONE: 1484 if (has_initial_stability_log_) { 1485 // There's an initial stability log, ready to send. 1486 log_manager_.StageNextLogForUpload(); 1487 has_initial_stability_log_ = false; 1488 // Note: No need to call LoadPersistedUnsentLogs() here because unsent 1489 // logs have already been loaded by PrepareInitialStabilityLog(). 1490 state_ = SENDING_INITIAL_STABILITY_LOG; 1491 } else { 1492 // TODO(asvitkine): When the field trial is removed, the |log_type| 1493 // arg should be removed and PrepareInitialMetricsLog() should always 1494 // use ONGOING_LOG. Use INITIAL_LOG only to match to the old behavior 1495 // when the field trial is off. 1496 MetricsLog::LogType log_type = SendSeparateInitialStabilityLog() ? 1497 MetricsLog::ONGOING_LOG : MetricsLog::INITIAL_LOG; 1498 PrepareInitialMetricsLog(log_type); 1499 // Load unsent logs (if any) from local state. 1500 log_manager_.LoadPersistedUnsentLogs(); 1501 state_ = SENDING_INITIAL_METRICS_LOG; 1502 } 1503 break; 1504 1505 case SENDING_OLD_LOGS: 1506 NOTREACHED(); // Shouldn't be staging a new log during old log sending. 1507 return; 1508 1509 case SENDING_CURRENT_LOGS: 1510 CloseCurrentLog(); 1511 OpenNewLog(); 1512 log_manager_.StageNextLogForUpload(); 1513 break; 1514 1515 default: 1516 NOTREACHED(); 1517 return; 1518 } 1519 1520 DCHECK(log_manager_.has_staged_log()); 1521 } 1522 1523 void MetricsService::PrepareInitialStabilityLog() { 1524 DCHECK_EQ(INITIALIZED, state_); 1525 PrefService* pref = g_browser_process->local_state(); 1526 DCHECK_NE(0, pref->GetInteger(prefs::kStabilityCrashCount)); 1527 1528 scoped_ptr<MetricsLog> initial_stability_log( 1529 new MetricsLog(client_id_, session_id_)); 1530 if (!initial_stability_log->LoadSavedEnvironmentFromPrefs()) 1531 return; 1532 initial_stability_log->RecordStabilityMetrics(base::TimeDelta(), 1533 MetricsLog::INITIAL_LOG); 1534 log_manager_.LoadPersistedUnsentLogs(); 1535 1536 log_manager_.PauseCurrentLog(); 1537 log_manager_.BeginLoggingWithLog(initial_stability_log.release(), 1538 MetricsLog::INITIAL_LOG); 1539 log_manager_.FinishCurrentLog(); 1540 log_manager_.ResumePausedLog(); 1541 1542 // Store unsent logs, including the stability log that was just saved, so 1543 // that they're not lost in case of a crash before upload time. 1544 log_manager_.PersistUnsentLogs(); 1545 1546 has_initial_stability_log_ = true; 1547 } 1548 1549 void MetricsService::PrepareInitialMetricsLog(MetricsLog::LogType log_type) { 1550 DCHECK(state_ == INIT_TASK_DONE || state_ == SENDING_INITIAL_STABILITY_LOG); 1551 initial_metrics_log_->set_hardware_class(hardware_class_); 1552 1553 std::vector<chrome_variations::ActiveGroupId> synthetic_trials; 1554 GetCurrentSyntheticFieldTrials(&synthetic_trials); 1555 initial_metrics_log_->RecordEnvironment(plugins_, google_update_metrics_, 1556 synthetic_trials); 1557 PrefService* pref = g_browser_process->local_state(); 1558 initial_metrics_log_->RecordStabilityMetrics(GetIncrementalUptime(pref), 1559 log_type); 1560 1561 // Histograms only get written to the current log, so make the new log current 1562 // before writing them. 1563 log_manager_.PauseCurrentLog(); 1564 log_manager_.BeginLoggingWithLog(initial_metrics_log_.release(), log_type); 1565 RecordCurrentHistograms(); 1566 log_manager_.FinishCurrentLog(); 1567 log_manager_.ResumePausedLog(); 1568 1569 DCHECK(!log_manager_.has_staged_log()); 1570 log_manager_.StageNextLogForUpload(); 1571 } 1572 1573 void MetricsService::SendStagedLog() { 1574 DCHECK(log_manager_.has_staged_log()); 1575 1576 PrepareFetchWithStagedLog(); 1577 1578 bool upload_created = (current_fetch_.get() != NULL); 1579 UMA_HISTOGRAM_BOOLEAN("UMA.UploadCreation", upload_created); 1580 if (!upload_created) { 1581 // Compression failed, and log discarded :-/. 1582 // Skip this upload and hope things work out next time. 1583 log_manager_.DiscardStagedLog(); 1584 scheduler_->UploadCancelled(); 1585 return; 1586 } 1587 1588 DCHECK(!waiting_for_asynchronous_reporting_step_); 1589 waiting_for_asynchronous_reporting_step_ = true; 1590 1591 current_fetch_->Start(); 1592 1593 HandleIdleSinceLastTransmission(true); 1594 } 1595 1596 void MetricsService::PrepareFetchWithStagedLog() { 1597 DCHECK(log_manager_.has_staged_log()); 1598 1599 // Prepare the protobuf version. 1600 DCHECK(!current_fetch_.get()); 1601 if (log_manager_.has_staged_log()) { 1602 current_fetch_.reset(net::URLFetcher::Create( 1603 GURL(kServerUrl), net::URLFetcher::POST, this)); 1604 current_fetch_->SetRequestContext( 1605 g_browser_process->system_request_context()); 1606 1607 std::string log_text = log_manager_.staged_log_text(); 1608 std::string compressed_log_text; 1609 bool compression_successful = chrome::GzipCompress(log_text, 1610 &compressed_log_text); 1611 DCHECK(compression_successful); 1612 if (compression_successful) { 1613 current_fetch_->SetUploadData(kMimeType, compressed_log_text); 1614 // Tell the server that we're uploading gzipped protobufs. 1615 current_fetch_->SetExtraRequestHeaders("content-encoding: gzip"); 1616 const std::string hash = 1617 base::HexEncode(log_manager_.staged_log_hash().data(), 1618 log_manager_.staged_log_hash().size()); 1619 DCHECK(!hash.empty()); 1620 current_fetch_->AddExtraRequestHeader("X-Chrome-UMA-Log-SHA1: " + hash); 1621 UMA_HISTOGRAM_PERCENTAGE( 1622 "UMA.ProtoCompressionRatio", 1623 100 * compressed_log_text.size() / log_text.size()); 1624 UMA_HISTOGRAM_CUSTOM_COUNTS( 1625 "UMA.ProtoGzippedKBSaved", 1626 (log_text.size() - compressed_log_text.size()) / 1024, 1627 1, 2000, 50); 1628 } 1629 1630 // We already drop cookies server-side, but we might as well strip them out 1631 // client-side as well. 1632 current_fetch_->SetLoadFlags(net::LOAD_DO_NOT_SAVE_COOKIES | 1633 net::LOAD_DO_NOT_SEND_COOKIES); 1634 } 1635 } 1636 1637 void MetricsService::OnURLFetchComplete(const net::URLFetcher* source) { 1638 DCHECK(waiting_for_asynchronous_reporting_step_); 1639 1640 // We're not allowed to re-use the existing |URLFetcher|s, so free them here. 1641 // Note however that |source| is aliased to the fetcher, so we should be 1642 // careful not to delete it too early. 1643 DCHECK_EQ(current_fetch_.get(), source); 1644 scoped_ptr<net::URLFetcher> s(current_fetch_.Pass()); 1645 1646 int response_code = source->GetResponseCode(); 1647 1648 // Log a histogram to track response success vs. failure rates. 1649 UMA_HISTOGRAM_ENUMERATION("UMA.UploadResponseStatus.Protobuf", 1650 ResponseCodeToStatus(response_code), 1651 NUM_RESPONSE_STATUSES); 1652 1653 // If the upload was provisionally stored, drop it now that the upload is 1654 // known to have gone through. 1655 log_manager_.DiscardLastProvisionalStore(); 1656 1657 bool upload_succeeded = response_code == 200; 1658 1659 // Provide boolean for error recovery (allow us to ignore response_code). 1660 bool discard_log = false; 1661 const size_t log_size = log_manager_.staged_log_text().length(); 1662 if (!upload_succeeded && log_size > kUploadLogAvoidRetransmitSize) { 1663 UMA_HISTOGRAM_COUNTS("UMA.Large Rejected Log was Discarded", 1664 static_cast<int>(log_size)); 1665 discard_log = true; 1666 } else if (response_code == 400) { 1667 // Bad syntax. Retransmission won't work. 1668 discard_log = true; 1669 } 1670 1671 if (upload_succeeded || discard_log) 1672 log_manager_.DiscardStagedLog(); 1673 1674 waiting_for_asynchronous_reporting_step_ = false; 1675 1676 if (!log_manager_.has_staged_log()) { 1677 switch (state_) { 1678 case SENDING_INITIAL_STABILITY_LOG: 1679 // Store the updated list to disk now that the removed log is uploaded. 1680 log_manager_.PersistUnsentLogs(); 1681 PrepareInitialMetricsLog(MetricsLog::ONGOING_LOG); 1682 SendStagedLog(); 1683 state_ = SENDING_INITIAL_METRICS_LOG; 1684 break; 1685 1686 case SENDING_INITIAL_METRICS_LOG: 1687 // The initial metrics log never gets persisted to local state, so it's 1688 // not necessary to call log_manager_.PersistUnsentLogs() here. 1689 // TODO(asvitkine): It should be persisted like the initial stability 1690 // log and old unsent logs. http://crbug.com/328417 1691 state_ = log_manager_.has_unsent_logs() ? SENDING_OLD_LOGS 1692 : SENDING_CURRENT_LOGS; 1693 break; 1694 1695 case SENDING_OLD_LOGS: 1696 // Store the updated list to disk now that the removed log is uploaded. 1697 log_manager_.PersistUnsentLogs(); 1698 if (!log_manager_.has_unsent_logs()) 1699 state_ = SENDING_CURRENT_LOGS; 1700 break; 1701 1702 case SENDING_CURRENT_LOGS: 1703 break; 1704 1705 default: 1706 NOTREACHED(); 1707 break; 1708 } 1709 1710 if (log_manager_.has_unsent_logs()) 1711 DCHECK_LT(state_, SENDING_CURRENT_LOGS); 1712 } 1713 1714 // Error 400 indicates a problem with the log, not with the server, so 1715 // don't consider that a sign that the server is in trouble. 1716 bool server_is_healthy = upload_succeeded || response_code == 400; 1717 // Don't notify the scheduler that the upload is finished if we've only sent 1718 // the initial stability log, but not yet the initial metrics log (treat the 1719 // two as a single unit of work as far as the scheduler is concerned). 1720 if (state_ != SENDING_INITIAL_METRICS_LOG) { 1721 scheduler_->UploadFinished(server_is_healthy, 1722 log_manager_.has_unsent_logs()); 1723 } 1724 1725 // Collect network stats if UMA upload succeeded. 1726 IOThread* io_thread = g_browser_process->io_thread(); 1727 if (server_is_healthy && io_thread) { 1728 chrome_browser_net::CollectNetworkStats(network_stats_server_, io_thread); 1729 chrome_browser_net::CollectPipeliningCapabilityStatsOnUIThread( 1730 http_pipelining_test_server_, io_thread); 1731 #if defined(OS_WIN) 1732 chrome::CollectTimeTicksStats(); 1733 #endif 1734 } 1735 } 1736 1737 void MetricsService::IncrementPrefValue(const char* path) { 1738 PrefService* pref = g_browser_process->local_state(); 1739 DCHECK(pref); 1740 int value = pref->GetInteger(path); 1741 pref->SetInteger(path, value + 1); 1742 } 1743 1744 void MetricsService::IncrementLongPrefsValue(const char* path) { 1745 PrefService* pref = g_browser_process->local_state(); 1746 DCHECK(pref); 1747 int64 value = pref->GetInt64(path); 1748 pref->SetInt64(path, value + 1); 1749 } 1750 1751 void MetricsService::LogLoadStarted(content::WebContents* web_contents) { 1752 content::RecordAction(content::UserMetricsAction("PageLoad")); 1753 HISTOGRAM_ENUMERATION("Chrome.UmaPageloadCounter", 1, 2); 1754 IncrementPrefValue(prefs::kStabilityPageLoadCount); 1755 IncrementLongPrefsValue(prefs::kUninstallMetricsPageLoadCount); 1756 // We need to save the prefs, as page load count is a critical stat, and it 1757 // might be lost due to a crash :-(. 1758 } 1759 1760 void MetricsService::LogRendererCrash(content::RenderProcessHost* host, 1761 base::TerminationStatus status, 1762 int exit_code) { 1763 Profile* profile = Profile::FromBrowserContext(host->GetBrowserContext()); 1764 ExtensionService* service = profile->GetExtensionService(); 1765 bool was_extension_process = 1766 service && service->process_map()->Contains(host->GetID()); 1767 if (status == base::TERMINATION_STATUS_PROCESS_CRASHED || 1768 status == base::TERMINATION_STATUS_ABNORMAL_TERMINATION) { 1769 if (was_extension_process) { 1770 IncrementPrefValue(prefs::kStabilityExtensionRendererCrashCount); 1771 1772 UMA_HISTOGRAM_SPARSE_SLOWLY("CrashExitCodes.Extension", 1773 MapCrashExitCodeForHistogram(exit_code)); 1774 } else { 1775 IncrementPrefValue(prefs::kStabilityRendererCrashCount); 1776 1777 UMA_HISTOGRAM_SPARSE_SLOWLY("CrashExitCodes.Renderer", 1778 MapCrashExitCodeForHistogram(exit_code)); 1779 } 1780 1781 UMA_HISTOGRAM_PERCENTAGE("BrowserRenderProcessHost.ChildCrashes", 1782 was_extension_process ? 2 : 1); 1783 } else if (status == base::TERMINATION_STATUS_PROCESS_WAS_KILLED) { 1784 UMA_HISTOGRAM_PERCENTAGE("BrowserRenderProcessHost.ChildKills", 1785 was_extension_process ? 2 : 1); 1786 } else if (status == base::TERMINATION_STATUS_STILL_RUNNING) { 1787 UMA_HISTOGRAM_PERCENTAGE("BrowserRenderProcessHost.DisconnectedAlive", 1788 was_extension_process ? 2 : 1); 1789 } 1790 } 1791 1792 void MetricsService::LogRendererHang() { 1793 IncrementPrefValue(prefs::kStabilityRendererHangCount); 1794 } 1795 1796 bool MetricsService::UmaMetricsProperlyShutdown() { 1797 CHECK(clean_shutdown_status_ == CLEANLY_SHUTDOWN || 1798 clean_shutdown_status_ == NEED_TO_SHUTDOWN); 1799 return clean_shutdown_status_ == CLEANLY_SHUTDOWN; 1800 } 1801 1802 void MetricsService::RegisterSyntheticFieldTrial( 1803 const SyntheticTrialGroup& trial) { 1804 for (size_t i = 0; i < synthetic_trial_groups_.size(); ++i) { 1805 if (synthetic_trial_groups_[i].id.name == trial.id.name) { 1806 if (synthetic_trial_groups_[i].id.group != trial.id.group) { 1807 synthetic_trial_groups_[i].id.group = trial.id.group; 1808 synthetic_trial_groups_[i].start_time = trial.start_time; 1809 } 1810 return; 1811 } 1812 } 1813 1814 SyntheticTrialGroup trial_group( 1815 trial.id.name, trial.id.group, base::TimeTicks::Now()); 1816 synthetic_trial_groups_.push_back(trial_group); 1817 } 1818 1819 void MetricsService::GetCurrentSyntheticFieldTrials( 1820 std::vector<chrome_variations::ActiveGroupId>* synthetic_trials) { 1821 DCHECK(synthetic_trials); 1822 synthetic_trials->clear(); 1823 const MetricsLog* current_log = 1824 static_cast<const MetricsLog*>(log_manager_.current_log()); 1825 for (size_t i = 0; i < synthetic_trial_groups_.size(); ++i) { 1826 if (synthetic_trial_groups_[i].start_time <= current_log->creation_time()) 1827 synthetic_trials->push_back(synthetic_trial_groups_[i].id); 1828 } 1829 } 1830 1831 void MetricsService::LogCleanShutdown() { 1832 // Redundant hack to write pref ASAP. 1833 MarkAppCleanShutdownAndCommit(); 1834 1835 // Redundant setting to assure that we always reset this value at shutdown 1836 // (and that we don't use some alternate path, and not call LogCleanShutdown). 1837 clean_shutdown_status_ = CLEANLY_SHUTDOWN; 1838 1839 RecordBooleanPrefValue(prefs::kStabilityExitedCleanly, true); 1840 PrefService* pref = g_browser_process->local_state(); 1841 pref->SetInteger(prefs::kStabilityExecutionPhase, 1842 MetricsService::SHUTDOWN_COMPLETE); 1843 } 1844 1845 #if defined(OS_CHROMEOS) 1846 void MetricsService::LogChromeOSCrash(const std::string &crash_type) { 1847 if (crash_type == "user") 1848 IncrementPrefValue(prefs::kStabilityOtherUserCrashCount); 1849 else if (crash_type == "kernel") 1850 IncrementPrefValue(prefs::kStabilityKernelCrashCount); 1851 else if (crash_type == "uncleanshutdown") 1852 IncrementPrefValue(prefs::kStabilitySystemUncleanShutdownCount); 1853 else 1854 NOTREACHED() << "Unexpected Chrome OS crash type " << crash_type; 1855 // Wake up metrics logs sending if necessary now that new 1856 // log data is available. 1857 HandleIdleSinceLastTransmission(false); 1858 } 1859 #endif // OS_CHROMEOS 1860 1861 void MetricsService::LogPluginLoadingError(const base::FilePath& plugin_path) { 1862 content::WebPluginInfo plugin; 1863 bool success = 1864 content::PluginService::GetInstance()->GetPluginInfoByPath(plugin_path, 1865 &plugin); 1866 DCHECK(success); 1867 ChildProcessStats& stats = child_process_stats_buffer_[plugin.name]; 1868 // Initialize the type if this entry is new. 1869 if (stats.process_type == content::PROCESS_TYPE_UNKNOWN) { 1870 // The plug-in process might not actually of type PLUGIN (which means 1871 // NPAPI), but we only care that it is *a* plug-in process. 1872 stats.process_type = content::PROCESS_TYPE_PLUGIN; 1873 } else { 1874 DCHECK(IsPluginProcess(stats.process_type)); 1875 } 1876 stats.loading_errors++; 1877 } 1878 1879 MetricsService::ChildProcessStats& MetricsService::GetChildProcessStats( 1880 const content::ChildProcessData& data) { 1881 const base::string16& child_name = data.name; 1882 if (!ContainsKey(child_process_stats_buffer_, child_name)) { 1883 child_process_stats_buffer_[child_name] = 1884 ChildProcessStats(data.process_type); 1885 } 1886 return child_process_stats_buffer_[child_name]; 1887 } 1888 1889 void MetricsService::RecordPluginChanges(PrefService* pref) { 1890 ListPrefUpdate update(pref, prefs::kStabilityPluginStats); 1891 ListValue* plugins = update.Get(); 1892 DCHECK(plugins); 1893 1894 for (ListValue::iterator value_iter = plugins->begin(); 1895 value_iter != plugins->end(); ++value_iter) { 1896 if (!(*value_iter)->IsType(Value::TYPE_DICTIONARY)) { 1897 NOTREACHED(); 1898 continue; 1899 } 1900 1901 DictionaryValue* plugin_dict = static_cast<DictionaryValue*>(*value_iter); 1902 std::string plugin_name; 1903 plugin_dict->GetString(prefs::kStabilityPluginName, &plugin_name); 1904 if (plugin_name.empty()) { 1905 NOTREACHED(); 1906 continue; 1907 } 1908 1909 // TODO(viettrungluu): remove conversions 1910 base::string16 name16 = UTF8ToUTF16(plugin_name); 1911 if (child_process_stats_buffer_.find(name16) == 1912 child_process_stats_buffer_.end()) { 1913 continue; 1914 } 1915 1916 ChildProcessStats stats = child_process_stats_buffer_[name16]; 1917 if (stats.process_launches) { 1918 int launches = 0; 1919 plugin_dict->GetInteger(prefs::kStabilityPluginLaunches, &launches); 1920 launches += stats.process_launches; 1921 plugin_dict->SetInteger(prefs::kStabilityPluginLaunches, launches); 1922 } 1923 if (stats.process_crashes) { 1924 int crashes = 0; 1925 plugin_dict->GetInteger(prefs::kStabilityPluginCrashes, &crashes); 1926 crashes += stats.process_crashes; 1927 plugin_dict->SetInteger(prefs::kStabilityPluginCrashes, crashes); 1928 } 1929 if (stats.instances) { 1930 int instances = 0; 1931 plugin_dict->GetInteger(prefs::kStabilityPluginInstances, &instances); 1932 instances += stats.instances; 1933 plugin_dict->SetInteger(prefs::kStabilityPluginInstances, instances); 1934 } 1935 if (stats.loading_errors) { 1936 int loading_errors = 0; 1937 plugin_dict->GetInteger(prefs::kStabilityPluginLoadingErrors, 1938 &loading_errors); 1939 loading_errors += stats.loading_errors; 1940 plugin_dict->SetInteger(prefs::kStabilityPluginLoadingErrors, 1941 loading_errors); 1942 } 1943 1944 child_process_stats_buffer_.erase(name16); 1945 } 1946 1947 // Now go through and add dictionaries for plugins that didn't already have 1948 // reports in Local State. 1949 for (std::map<base::string16, ChildProcessStats>::iterator cache_iter = 1950 child_process_stats_buffer_.begin(); 1951 cache_iter != child_process_stats_buffer_.end(); ++cache_iter) { 1952 ChildProcessStats stats = cache_iter->second; 1953 1954 // Insert only plugins information into the plugins list. 1955 if (!IsPluginProcess(stats.process_type)) 1956 continue; 1957 1958 // TODO(viettrungluu): remove conversion 1959 std::string plugin_name = UTF16ToUTF8(cache_iter->first); 1960 1961 DictionaryValue* plugin_dict = new DictionaryValue; 1962 1963 plugin_dict->SetString(prefs::kStabilityPluginName, plugin_name); 1964 plugin_dict->SetInteger(prefs::kStabilityPluginLaunches, 1965 stats.process_launches); 1966 plugin_dict->SetInteger(prefs::kStabilityPluginCrashes, 1967 stats.process_crashes); 1968 plugin_dict->SetInteger(prefs::kStabilityPluginInstances, 1969 stats.instances); 1970 plugin_dict->SetInteger(prefs::kStabilityPluginLoadingErrors, 1971 stats.loading_errors); 1972 plugins->Append(plugin_dict); 1973 } 1974 child_process_stats_buffer_.clear(); 1975 } 1976 1977 bool MetricsService::CanLogNotification() { 1978 // We simply don't log anything to UMA if there is a single incognito 1979 // session visible. The problem is that we always notify using the orginal 1980 // profile in order to simplify notification processing. 1981 return !chrome::IsOffTheRecordSessionActive(); 1982 } 1983 1984 void MetricsService::RecordBooleanPrefValue(const char* path, bool value) { 1985 DCHECK(IsSingleThreaded()); 1986 1987 PrefService* pref = g_browser_process->local_state(); 1988 DCHECK(pref); 1989 1990 pref->SetBoolean(path, value); 1991 RecordCurrentState(pref); 1992 } 1993 1994 void MetricsService::RecordCurrentState(PrefService* pref) { 1995 pref->SetInt64(prefs::kStabilityLastTimestampSec, Time::Now().ToTimeT()); 1996 1997 RecordPluginChanges(pref); 1998 } 1999 2000 // static 2001 bool MetricsService::IsPluginProcess(int process_type) { 2002 return (process_type == content::PROCESS_TYPE_PLUGIN || 2003 process_type == content::PROCESS_TYPE_PPAPI_PLUGIN || 2004 process_type == content::PROCESS_TYPE_PPAPI_BROKER); 2005 } 2006 2007 #if defined(OS_CHROMEOS) 2008 void MetricsService::StartExternalMetrics() { 2009 external_metrics_ = new chromeos::ExternalMetrics; 2010 external_metrics_->Start(); 2011 } 2012 #endif 2013 2014 // static 2015 bool MetricsServiceHelper::IsMetricsReportingEnabled() { 2016 bool result = false; 2017 const PrefService* local_state = g_browser_process->local_state(); 2018 if (local_state) { 2019 const PrefService::Preference* uma_pref = 2020 local_state->FindPreference(prefs::kMetricsReportingEnabled); 2021 if (uma_pref) { 2022 bool success = uma_pref->GetValue()->GetAsBoolean(&result); 2023 DCHECK(success); 2024 } 2025 } 2026 return result; 2027 } 2028