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.
5 //------------------------------------------------------------------------------
6 // Description of the life cycle of a instance of MetricsService.
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.
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 the chromium
26 // product (from startup, to browser shutdown). An initial log is generally
27 // transmitted some short time (1 minute?) after startup, and includes stats
28 // such as recent crash info, the number and types of plugins, etc. The
29 // external server's response to the initial log conceptually tells this MS if
30 // it should continue transmitting logs (during this session). The server
31 // response can actually be much more detailed, and always includes (at a
32 // minimum) how often additional ongoing logs should be sent.
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 a the most recent number
49 // of page loads, along with any counts of renderer or plugin crashes.
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
53 // is closed (including snapshotting histograms), and persisted, for
54 // potential transmission during a future run of the product.
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.
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).
75 // With the above overview, we can now describe the state machine's various
76 // stats, based on the State enum specified in the state_ member. Those states
79 // INITIALIZED, // Constructor was called.
80 // INIT_TASK_SCHEDULED, // Waiting for deferred init tasks to complete.
81 // INIT_TASK_DONE, // Waiting for timer to send initial log.
82 // INITIAL_LOG_READY, // Initial log generated, and waiting for reply.
83 // SENDING_OLD_LOGS, // Sending unsent logs from previous session.
84 // SENDING_CURRENT_LOGS, // Sending standard current logs as they accrue.
86 // In more detail, we have:
88 // INITIALIZED, // Constructor was called.
89 // The MS has been constructed, but has taken no actions to compose the
92 // INIT_TASK_SCHEDULED, // Waiting for deferred init tasks to complete.
93 // Typically about 30 seconds after startup, a task is sent to a second thread
94 // (the file thread) to perform deferred (lower priority and slower)
95 // initialization steps such as getting the list of plugins. That task will
96 // (when complete) make an async callback (via a Task) to indicate the
99 // INIT_TASK_DONE, // Waiting for timer to send initial log.
100 // The callback has arrived, and it is now possible for an initial log to be
101 // created. This callback typically arrives back less than one second after
102 // the deferred init task is dispatched.
104 // INITIAL_LOG_READY, // Initial log generated, and waiting for reply.
105 // This state is entered only after an initial log has been composed, and
106 // prepared for transmission. It is also the case that any previously unsent
107 // logs have been loaded into instance variables for possible transmission.
109 // SENDING_OLD_LOGS, // Sending unsent logs from previous session.
110 // This state indicates that the initial log for this session has been
111 // successfully sent and it is now time to send any logs that were
112 // saved from previous sessions. All such logs will be transmitted before
113 // exiting this state, and proceeding with ongoing logs from the current session
116 // SENDING_CURRENT_LOGS, // Sending standard current logs as they accrue.
117 // Current logs are being accumulated. Typically every 20 minutes a log is
118 // closed and finalized for transmission, at the same time as a new log is
121 // The progression through the above states is simple, and sequential, in the
122 // most common use cases. States proceed from INITIAL to SENDING_CURRENT_LOGS,
123 // and remain in the latter until shutdown.
125 // The one unusual case is when the user asks that we stop logging. When that
126 // happens, any staged (transmission in progress) log is persisted, and any log
127 // that is currently accumulating is also finalized and persisted. We then
128 // regress back to the SEND_OLD_LOGS state in case the user enables log
129 // recording again during this session. This way anything we have persisted
130 // will be sent automatically if/when we progress back to SENDING_CURRENT_LOG
133 // Another similar case is on mobile, when the application is backgrounded and
134 // then foregrounded again. Backgrounding created new "old" stored logs, so the
135 // state drops back from SENDING_CURRENT_LOGS to SENDING_OLD_LOGS so those logs
138 // Also note that whenever we successfully send an old log, we mirror the list
139 // of logs into the PrefService. This ensures that IF we crash, we won't start
140 // up and retransmit our old logs again.
142 // Due to race conditions, it is always possible that a log file could be sent
143 // twice. For example, if a log file is sent, but not yet acknowledged by
144 // the external server, and the user shuts down, then a copy of the log may be
145 // saved for re-transmission. These duplicates could be filtered out server
146 // side, but are not expected to be a significant problem.
149 //------------------------------------------------------------------------------
151 #include "chrome/browser/metrics/metrics_service.h"
155 #include "base/bind.h"
156 #include "base/callback.h"
157 #include "base/command_line.h"
158 #include "base/guid.h"
159 #include "base/md5.h"
160 #include "base/metrics/histogram.h"
161 #include "base/metrics/sparse_histogram.h"
162 #include "base/metrics/statistics_recorder.h"
163 #include "base/prefs/pref_registry_simple.h"
164 #include "base/prefs/pref_service.h"
165 #include "base/prefs/scoped_user_pref_update.h"
166 #include "base/rand_util.h"
167 #include "base/strings/string_number_conversions.h"
168 #include "base/strings/utf_string_conversions.h"
169 #include "base/threading/platform_thread.h"
170 #include "base/threading/thread.h"
171 #include "base/threading/thread_restrictions.h"
172 #include "base/tracked_objects.h"
173 #include "base/values.h"
174 #include "chrome/browser/browser_process.h"
175 #include "chrome/browser/chrome_notification_types.h"
176 #include "chrome/browser/extensions/extension_service.h"
177 #include "chrome/browser/extensions/process_map.h"
178 #include "chrome/browser/io_thread.h"
179 #include "chrome/browser/memory_details.h"
180 #include "chrome/browser/metrics/compression_utils.h"
181 #include "chrome/browser/metrics/metrics_log.h"
182 #include "chrome/browser/metrics/metrics_log_serializer.h"
183 #include "chrome/browser/metrics/metrics_reporting_scheduler.h"
184 #include "chrome/browser/metrics/time_ticks_experiment_win.h"
185 #include "chrome/browser/metrics/tracking_synchronizer.h"
186 #include "chrome/browser/net/http_pipelining_compatibility_client.h"
187 #include "chrome/browser/net/network_stats.h"
188 #include "chrome/browser/omnibox/omnibox_log.h"
189 #include "chrome/browser/profiles/profile.h"
190 #include "chrome/browser/ui/browser_list.h"
191 #include "chrome/browser/ui/browser_otr_state.h"
192 #include "chrome/browser/ui/search/search_tab_helper.h"
193 #include "chrome/common/chrome_constants.h"
194 #include "chrome/common/chrome_result_codes.h"
195 #include "chrome/common/chrome_switches.h"
196 #include "chrome/common/crash_keys.h"
197 #include "chrome/common/metrics/caching_permuted_entropy_provider.h"
198 #include "chrome/common/metrics/metrics_log_manager.h"
199 #include "chrome/common/net/test_server_locations.h"
200 #include "chrome/common/pref_names.h"
201 #include "chrome/common/render_messages.h"
202 #include "components/variations/entropy_provider.h"
203 #include "content/public/browser/child_process_data.h"
204 #include "content/public/browser/histogram_fetcher.h"
205 #include "content/public/browser/load_notification_details.h"
206 #include "content/public/browser/notification_service.h"
207 #include "content/public/browser/plugin_service.h"
208 #include "content/public/browser/render_process_host.h"
209 #include "content/public/browser/user_metrics.h"
210 #include "content/public/browser/web_contents.h"
211 #include "content/public/common/process_type.h"
212 #include "content/public/common/webplugininfo.h"
213 #include "net/base/load_flags.h"
214 #include "net/url_request/url_fetcher.h"
216 // TODO(port): port browser_distribution.h.
217 #if !defined(OS_POSIX)
218 #include "chrome/installer/util/browser_distribution.h"
221 #if defined(OS_CHROMEOS)
222 #include "chrome/browser/chromeos/external_metrics.h"
223 #include "chromeos/system/statistics_provider.h"
227 #include <windows.h> // Needed for STATUS_* codes
228 #include "base/win/registry.h"
231 #if !defined(OS_ANDROID)
232 #include "chrome/browser/service/service_process_control.h"
236 using content::BrowserThread;
237 using content::ChildProcessData;
238 using content::LoadNotificationDetails;
239 using content::PluginService;
243 // Check to see that we're being called on only one thread.
244 bool IsSingleThreaded() {
245 static base::PlatformThreadId thread_id = 0;
247 thread_id = base::PlatformThread::CurrentId();
248 return base::PlatformThread::CurrentId() == thread_id;
251 // The delay, in seconds, after starting recording before doing expensive
252 // initialization work.
253 #if defined(OS_ANDROID) || defined(OS_IOS)
254 // On mobile devices, a significant portion of sessions last less than a minute.
255 // Use a shorter timer on these platforms to avoid losing data.
256 // TODO(dfalcantara): To avoid delaying startup, tighten up initialization so
257 // that it occurs after the user gets their initial page.
258 const int kInitializationDelaySeconds = 5;
260 const int kInitializationDelaySeconds = 30;
263 // This specifies the amount of time to wait for all renderers to send their
265 const int kMaxHistogramGatheringWaitDuration = 60000; // 60 seconds.
267 // The maximum number of events in a log uploaded to the UMA server.
268 const int kEventLimit = 2400;
270 // If an upload fails, and the transmission was over this byte count, then we
271 // will discard the log, and not try to retransmit it. We also don't persist
272 // the log to the prefs for transmission during the next chrome session if this
273 // limit is exceeded.
274 const size_t kUploadLogAvoidRetransmitSize = 50000;
276 // Interval, in minutes, between state saves.
277 const int kSaveStateIntervalMinutes = 5;
279 enum ResponseStatus {
282 BAD_REQUEST, // Invalid syntax or log too large.
284 NUM_RESPONSE_STATUSES
287 ResponseStatus ResponseCodeToStatus(int response_code) {
288 switch (response_code) {
293 case net::URLFetcher::RESPONSE_CODE_INVALID:
296 return UNKNOWN_FAILURE;
300 // The argument used to generate a non-identifying entropy source. We want no
301 // more than 13 bits of entropy, so use this max to return a number in the range
302 // [0, 7999] as the entropy source (12.97 bits of entropy).
303 const int kMaxLowEntropySize = 8000;
305 // Default prefs value for prefs::kMetricsLowEntropySource to indicate that the
306 // value has not yet been set.
307 const int kLowEntropySourceNotSet = -1;
309 // Generates a new non-identifying entropy source used to seed persistent
311 int GenerateLowEntropySource() {
312 return base::RandInt(0, kMaxLowEntropySize - 1);
315 // Converts an exit code into something that can be inserted into our
316 // histograms (which expect non-negative numbers less than MAX_INT).
317 int MapCrashExitCodeForHistogram(int exit_code) {
319 // Since |abs(STATUS_GUARD_PAGE_VIOLATION) == MAX_INT| it causes problems in
320 // histograms.cc. Solve this by remapping it to a smaller value, which
321 // hopefully doesn't conflict with other codes.
322 if (exit_code == STATUS_GUARD_PAGE_VIOLATION)
323 return 0x1FCF7EC3; // Randomly picked number.
326 return std::abs(exit_code);
329 void MarkAppCleanShutdownAndCommit() {
330 PrefService* pref = g_browser_process->local_state();
331 pref->SetBoolean(prefs::kStabilityExitedCleanly, true);
332 pref->SetInteger(prefs::kStabilityExecutionPhase,
333 MetricsService::CLEAN_SHUTDOWN);
334 // Start writing right away (write happens on a different thread).
335 pref->CommitPendingWrite();
341 MetricsService::ShutdownCleanliness MetricsService::clean_shutdown_status_ =
342 MetricsService::CLEANLY_SHUTDOWN;
344 MetricsService::ExecutionPhase MetricsService::execution_phase_ =
345 MetricsService::CLEAN_SHUTDOWN;
347 // This is used to quickly log stats from child process related notifications in
348 // MetricsService::child_stats_buffer_. The buffer's contents are transferred
349 // out when Local State is periodically saved. The information is then
350 // reported to the UMA server on next launch.
351 struct MetricsService::ChildProcessStats {
353 explicit ChildProcessStats(int process_type)
354 : process_launches(0),
358 process_type(process_type) {}
360 // This constructor is only used by the map to return some default value for
361 // an index for which no value has been assigned.
363 : process_launches(0),
367 process_type(content::PROCESS_TYPE_UNKNOWN) {}
369 // The number of times that the given child process has been launched
370 int process_launches;
372 // The number of times that the given child process has crashed
375 // The number of instances of this child process that have been created.
376 // An instance is a DOM object rendered by this child process during a page
380 // The number of times there was an error loading an instance of this child
387 // Handles asynchronous fetching of memory details.
388 // Will run the provided task after finished.
389 class MetricsMemoryDetails : public MemoryDetails {
391 explicit MetricsMemoryDetails(const base::Closure& callback)
392 : callback_(callback) {}
394 virtual void OnDetailsAvailable() OVERRIDE {
395 base::MessageLoop::current()->PostTask(FROM_HERE, callback_);
399 virtual ~MetricsMemoryDetails() {}
401 base::Closure callback_;
402 DISALLOW_COPY_AND_ASSIGN(MetricsMemoryDetails);
406 void MetricsService::RegisterPrefs(PrefRegistrySimple* registry) {
407 DCHECK(IsSingleThreaded());
408 registry->RegisterStringPref(prefs::kMetricsClientID, std::string());
409 registry->RegisterIntegerPref(prefs::kMetricsLowEntropySource,
410 kLowEntropySourceNotSet);
411 registry->RegisterInt64Pref(prefs::kMetricsClientIDTimestamp, 0);
412 registry->RegisterInt64Pref(prefs::kStabilityLaunchTimeSec, 0);
413 registry->RegisterInt64Pref(prefs::kStabilityLastTimestampSec, 0);
414 registry->RegisterStringPref(prefs::kStabilityStatsVersion, std::string());
415 registry->RegisterInt64Pref(prefs::kStabilityStatsBuildTime, 0);
416 registry->RegisterBooleanPref(prefs::kStabilityExitedCleanly, true);
417 registry->RegisterIntegerPref(prefs::kStabilityExecutionPhase,
419 registry->RegisterBooleanPref(prefs::kStabilitySessionEndCompleted, true);
420 registry->RegisterIntegerPref(prefs::kMetricsSessionID, -1);
421 registry->RegisterIntegerPref(prefs::kStabilityLaunchCount, 0);
422 registry->RegisterIntegerPref(prefs::kStabilityCrashCount, 0);
423 registry->RegisterIntegerPref(prefs::kStabilityIncompleteSessionEndCount, 0);
424 registry->RegisterIntegerPref(prefs::kStabilityPageLoadCount, 0);
425 registry->RegisterIntegerPref(prefs::kStabilityRendererCrashCount, 0);
426 registry->RegisterIntegerPref(prefs::kStabilityExtensionRendererCrashCount,
428 registry->RegisterIntegerPref(prefs::kStabilityRendererHangCount, 0);
429 registry->RegisterIntegerPref(prefs::kStabilityChildProcessCrashCount, 0);
430 registry->RegisterIntegerPref(prefs::kStabilityBreakpadRegistrationFail, 0);
431 registry->RegisterIntegerPref(prefs::kStabilityBreakpadRegistrationSuccess,
433 registry->RegisterIntegerPref(prefs::kStabilityDebuggerPresent, 0);
434 registry->RegisterIntegerPref(prefs::kStabilityDebuggerNotPresent, 0);
435 #if defined(OS_CHROMEOS)
436 registry->RegisterIntegerPref(prefs::kStabilityOtherUserCrashCount, 0);
437 registry->RegisterIntegerPref(prefs::kStabilityKernelCrashCount, 0);
438 registry->RegisterIntegerPref(prefs::kStabilitySystemUncleanShutdownCount, 0);
439 #endif // OS_CHROMEOS
441 registry->RegisterListPref(prefs::kMetricsInitialLogs);
442 registry->RegisterListPref(prefs::kMetricsOngoingLogs);
444 registry->RegisterInt64Pref(prefs::kInstallDate, 0);
445 registry->RegisterInt64Pref(prefs::kUninstallMetricsPageLoadCount, 0);
446 registry->RegisterInt64Pref(prefs::kUninstallLaunchCount, 0);
447 registry->RegisterInt64Pref(prefs::kUninstallMetricsUptimeSec, 0);
448 registry->RegisterInt64Pref(prefs::kUninstallLastLaunchTimeSec, 0);
449 registry->RegisterInt64Pref(prefs::kUninstallLastObservedRunTimeSec, 0);
453 void MetricsService::DiscardOldStabilityStats(PrefService* local_state) {
454 local_state->SetBoolean(prefs::kStabilityExitedCleanly, true);
455 local_state->SetInteger(prefs::kStabilityExecutionPhase, CLEAN_SHUTDOWN);
456 local_state->SetBoolean(prefs::kStabilitySessionEndCompleted, true);
458 local_state->SetInteger(prefs::kStabilityIncompleteSessionEndCount, 0);
459 local_state->SetInteger(prefs::kStabilityBreakpadRegistrationSuccess, 0);
460 local_state->SetInteger(prefs::kStabilityBreakpadRegistrationFail, 0);
461 local_state->SetInteger(prefs::kStabilityDebuggerPresent, 0);
462 local_state->SetInteger(prefs::kStabilityDebuggerNotPresent, 0);
464 local_state->SetInteger(prefs::kStabilityLaunchCount, 0);
465 local_state->SetInteger(prefs::kStabilityCrashCount, 0);
467 local_state->SetInteger(prefs::kStabilityPageLoadCount, 0);
468 local_state->SetInteger(prefs::kStabilityRendererCrashCount, 0);
469 local_state->SetInteger(prefs::kStabilityRendererHangCount, 0);
471 local_state->SetInt64(prefs::kStabilityLaunchTimeSec, 0);
472 local_state->SetInt64(prefs::kStabilityLastTimestampSec, 0);
474 local_state->ClearPref(prefs::kStabilityPluginStats);
476 local_state->ClearPref(prefs::kMetricsInitialLogs);
477 local_state->ClearPref(prefs::kMetricsOngoingLogs);
480 MetricsService::MetricsService()
481 : recording_active_(false),
482 reporting_active_(false),
483 test_mode_active_(false),
485 low_entropy_source_(kLowEntropySourceNotSet),
486 idle_since_last_transmission_(false),
488 self_ptr_factory_(this),
489 state_saver_factory_(this),
490 waiting_for_asynchronous_reporting_step_(false),
491 num_async_histogram_fetches_in_progress_(0),
492 entropy_source_returned_(LAST_ENTROPY_NONE) {
493 DCHECK(IsSingleThreaded());
494 InitializeMetricsState();
496 base::Closure callback = base::Bind(&MetricsService::StartScheduledUpload,
497 self_ptr_factory_.GetWeakPtr());
498 scheduler_.reset(new MetricsReportingScheduler(callback));
499 log_manager_.set_log_serializer(new MetricsLogSerializer());
500 log_manager_.set_max_ongoing_log_store_size(kUploadLogAvoidRetransmitSize);
502 BrowserChildProcessObserver::Add(this);
505 MetricsService::~MetricsService() {
508 BrowserChildProcessObserver::Remove(this);
511 void MetricsService::Start() {
512 HandleIdleSinceLastTransmission(false);
517 void MetricsService::StartRecordingForTests() {
518 test_mode_active_ = true;
523 void MetricsService::Stop() {
524 HandleIdleSinceLastTransmission(false);
529 void MetricsService::EnableReporting() {
530 if (reporting_active_)
532 reporting_active_ = true;
533 StartSchedulerIfNecessary();
536 void MetricsService::DisableReporting() {
537 reporting_active_ = false;
540 std::string MetricsService::GetClientId() {
544 scoped_ptr<const base::FieldTrial::EntropyProvider>
545 MetricsService::CreateEntropyProvider(bool reporting_will_be_enabled) {
546 // For metrics reporting-enabled users, we combine the client ID and low
547 // entropy source to get the final entropy source. Otherwise, only use the low
549 // This has two useful properties:
550 // 1) It makes the entropy source less identifiable for parties that do not
551 // know the low entropy source.
552 // 2) It makes the final entropy source resettable.
553 const int low_entropy_source_value = GetLowEntropySource();
554 UMA_HISTOGRAM_SPARSE_SLOWLY("UMA.LowEntropySourceValue",
555 low_entropy_source_value);
556 if (reporting_will_be_enabled) {
557 if (entropy_source_returned_ == LAST_ENTROPY_NONE)
558 entropy_source_returned_ = LAST_ENTROPY_HIGH;
559 DCHECK_EQ(LAST_ENTROPY_HIGH, entropy_source_returned_);
560 const std::string high_entropy_source =
561 client_id_ + base::IntToString(low_entropy_source_value);
562 return scoped_ptr<const base::FieldTrial::EntropyProvider>(
563 new metrics::SHA1EntropyProvider(high_entropy_source));
566 if (entropy_source_returned_ == LAST_ENTROPY_NONE)
567 entropy_source_returned_ = LAST_ENTROPY_LOW;
568 DCHECK_EQ(LAST_ENTROPY_LOW, entropy_source_returned_);
570 #if defined(OS_ANDROID) || defined(OS_IOS)
571 return scoped_ptr<const base::FieldTrial::EntropyProvider>(
572 new metrics::CachingPermutedEntropyProvider(
573 g_browser_process->local_state(),
574 low_entropy_source_value,
575 kMaxLowEntropySize));
577 return scoped_ptr<const base::FieldTrial::EntropyProvider>(
578 new metrics::PermutedEntropyProvider(low_entropy_source_value,
579 kMaxLowEntropySize));
583 void MetricsService::ForceClientIdCreation() {
584 if (!client_id_.empty())
586 PrefService* pref = g_browser_process->local_state();
587 client_id_ = pref->GetString(prefs::kMetricsClientID);
588 if (!client_id_.empty())
591 client_id_ = GenerateClientID();
592 pref->SetString(prefs::kMetricsClientID, client_id_);
594 // Might as well make a note of how long this ID has existed
595 pref->SetString(prefs::kMetricsClientIDTimestamp,
596 base::Int64ToString(Time::Now().ToTimeT()));
599 void MetricsService::EnableRecording() {
600 DCHECK(IsSingleThreaded());
602 if (recording_active_)
604 recording_active_ = true;
606 ForceClientIdCreation();
607 crash_keys::SetClientID(client_id_);
608 if (!log_manager_.current_log())
611 SetUpNotifications(®istrar_, this);
612 content::RemoveActionCallback(action_callback_);
613 action_callback_ = base::Bind(&MetricsService::OnUserAction,
614 base::Unretained(this));
615 content::AddActionCallback(action_callback_);
618 void MetricsService::DisableRecording() {
619 DCHECK(IsSingleThreaded());
621 if (!recording_active_)
623 recording_active_ = false;
625 content::RemoveActionCallback(action_callback_);
626 registrar_.RemoveAll();
627 PushPendingLogsToPersistentStorage();
628 DCHECK(!log_manager_.has_staged_log());
631 bool MetricsService::recording_active() const {
632 DCHECK(IsSingleThreaded());
633 return recording_active_;
636 bool MetricsService::reporting_active() const {
637 DCHECK(IsSingleThreaded());
638 return reporting_active_;
642 void MetricsService::SetUpNotifications(
643 content::NotificationRegistrar* registrar,
644 content::NotificationObserver* observer) {
645 registrar->Add(observer, chrome::NOTIFICATION_BROWSER_OPENED,
646 content::NotificationService::AllBrowserContextsAndSources());
647 registrar->Add(observer, chrome::NOTIFICATION_BROWSER_CLOSED,
648 content::NotificationService::AllSources());
649 registrar->Add(observer, chrome::NOTIFICATION_TAB_PARENTED,
650 content::NotificationService::AllSources());
651 registrar->Add(observer, chrome::NOTIFICATION_TAB_CLOSING,
652 content::NotificationService::AllSources());
653 registrar->Add(observer, content::NOTIFICATION_LOAD_START,
654 content::NotificationService::AllSources());
655 registrar->Add(observer, content::NOTIFICATION_LOAD_STOP,
656 content::NotificationService::AllSources());
657 registrar->Add(observer, content::NOTIFICATION_RENDERER_PROCESS_CLOSED,
658 content::NotificationService::AllSources());
659 registrar->Add(observer, content::NOTIFICATION_RENDERER_PROCESS_HANG,
660 content::NotificationService::AllSources());
661 registrar->Add(observer, chrome::NOTIFICATION_OMNIBOX_OPENED_URL,
662 content::NotificationService::AllSources());
665 void MetricsService::BrowserChildProcessHostConnected(
666 const content::ChildProcessData& data) {
667 GetChildProcessStats(data).process_launches++;
670 void MetricsService::BrowserChildProcessCrashed(
671 const content::ChildProcessData& data) {
672 GetChildProcessStats(data).process_crashes++;
673 // Exclude plugin crashes from the count below because we report them via
674 // a separate UMA metric.
675 if (!IsPluginProcess(data.process_type))
676 IncrementPrefValue(prefs::kStabilityChildProcessCrashCount);
679 void MetricsService::BrowserChildProcessInstanceCreated(
680 const content::ChildProcessData& data) {
681 GetChildProcessStats(data).instances++;
684 void MetricsService::Observe(int type,
685 const content::NotificationSource& source,
686 const content::NotificationDetails& details) {
687 DCHECK(log_manager_.current_log());
688 DCHECK(IsSingleThreaded());
690 if (!CanLogNotification())
694 case chrome::NOTIFICATION_BROWSER_OPENED:
695 case chrome::NOTIFICATION_BROWSER_CLOSED:
696 case chrome::NOTIFICATION_TAB_PARENTED:
697 case chrome::NOTIFICATION_TAB_CLOSING:
698 case content::NOTIFICATION_LOAD_STOP:
699 // These notifications are currently used only to break out of idle mode.
702 case content::NOTIFICATION_LOAD_START: {
703 content::NavigationController* controller =
704 content::Source<content::NavigationController>(source).ptr();
705 content::WebContents* web_contents = controller->GetWebContents();
706 LogLoadStarted(web_contents);
710 case content::NOTIFICATION_RENDERER_PROCESS_CLOSED: {
711 content::RenderProcessHost::RendererClosedDetails* process_details =
713 content::RenderProcessHost::RendererClosedDetails>(
715 content::RenderProcessHost* host =
716 content::Source<content::RenderProcessHost>(source).ptr();
718 host, process_details->status, process_details->exit_code);
722 case content::NOTIFICATION_RENDERER_PROCESS_HANG:
726 case chrome::NOTIFICATION_OMNIBOX_OPENED_URL: {
727 MetricsLog* current_log =
728 static_cast<MetricsLog*>(log_manager_.current_log());
730 current_log->RecordOmniboxOpenedURL(
731 *content::Details<OmniboxLog>(details).ptr());
740 HandleIdleSinceLastTransmission(false);
743 void MetricsService::HandleIdleSinceLastTransmission(bool in_idle) {
744 // If there wasn't a lot of action, maybe the computer was asleep, in which
745 // case, the log transmissions should have stopped. Here we start them up
747 if (!in_idle && idle_since_last_transmission_)
748 StartSchedulerIfNecessary();
749 idle_since_last_transmission_ = in_idle;
752 void MetricsService::RecordStartOfSessionEnd() {
754 RecordBooleanPrefValue(prefs::kStabilitySessionEndCompleted, false);
757 void MetricsService::RecordCompletedSessionEnd() {
759 RecordBooleanPrefValue(prefs::kStabilitySessionEndCompleted, true);
762 #if defined(OS_ANDROID) || defined(OS_IOS)
763 void MetricsService::OnAppEnterBackground() {
766 MarkAppCleanShutdownAndCommit();
768 // At this point, there's no way of knowing when the process will be
769 // killed, so this has to be treated similar to a shutdown, closing and
770 // persisting all logs. Unlinke a shutdown, the state is primed to be ready
771 // to continue logging and uploading if the process does return.
772 if (recording_active() && state_ >= INITIAL_LOG_READY) {
773 PushPendingLogsToPersistentStorage();
774 // Persisting logs closes the current log, so start recording a new log
775 // immediately to capture any background work that might be done before the
776 // process is killed.
781 void MetricsService::OnAppEnterForeground() {
782 PrefService* pref = g_browser_process->local_state();
783 pref->SetBoolean(prefs::kStabilityExitedCleanly, false);
784 pref->SetInteger(prefs::kStabilityExecutionPhase, execution_phase_);
786 StartSchedulerIfNecessary();
789 void MetricsService::LogNeedForCleanShutdown() {
790 PrefService* pref = g_browser_process->local_state();
791 pref->SetBoolean(prefs::kStabilityExitedCleanly, false);
792 pref->SetInteger(prefs::kStabilityExecutionPhase, execution_phase_);
793 // Redundant setting to be sure we call for a clean shutdown.
794 clean_shutdown_status_ = NEED_TO_SHUTDOWN;
796 #endif // defined(OS_ANDROID) || defined(OS_IOS)
798 void MetricsService::RecordBreakpadRegistration(bool success) {
800 IncrementPrefValue(prefs::kStabilityBreakpadRegistrationFail);
802 IncrementPrefValue(prefs::kStabilityBreakpadRegistrationSuccess);
805 void MetricsService::RecordBreakpadHasDebugger(bool has_debugger) {
807 IncrementPrefValue(prefs::kStabilityDebuggerNotPresent);
809 IncrementPrefValue(prefs::kStabilityDebuggerPresent);
813 void MetricsService::CountBrowserCrashDumpAttempts() {
814 // Open the registry key for iteration.
815 base::win::RegKey regkey;
816 if (regkey.Open(HKEY_CURRENT_USER,
817 chrome::kBrowserCrashDumpAttemptsRegistryPath,
818 KEY_ALL_ACCESS) != ERROR_SUCCESS) {
822 // The values we're interested in counting are all prefixed with the version.
823 base::string16 chrome_version(base::ASCIIToUTF16(chrome::kChromeVersion));
825 // Track a list of values to delete. We don't modify the registry key while
826 // we're iterating over its values.
827 typedef std::vector<base::string16> StringVector;
828 StringVector to_delete;
830 // Iterate over the values in the key counting dumps with and without crashes.
831 // We directly walk the values instead of using RegistryValueIterator in order
832 // to read all of the values as DWORDS instead of strings.
835 int dumps_with_crash = 0;
836 int dumps_with_no_crash = 0;
837 for (int i = regkey.GetValueCount() - 1; i >= 0; --i) {
838 if (regkey.GetValueNameAt(i, &name) == ERROR_SUCCESS &&
839 StartsWith(name, chrome_version, false) &&
840 regkey.ReadValueDW(name.c_str(), &value) == ERROR_SUCCESS) {
841 to_delete.push_back(name);
843 ++dumps_with_no_crash;
849 // Delete the registry keys we've just counted.
850 for (StringVector::iterator i = to_delete.begin(); i != to_delete.end(); ++i)
851 regkey.DeleteValue(i->c_str());
853 // Capture the histogram samples.
854 if (dumps_with_crash != 0)
855 UMA_HISTOGRAM_COUNTS("Chrome.BrowserDumpsWithCrash", dumps_with_crash);
856 if (dumps_with_no_crash != 0)
857 UMA_HISTOGRAM_COUNTS("Chrome.BrowserDumpsWithNoCrash", dumps_with_no_crash);
858 int total_dumps = dumps_with_crash + dumps_with_no_crash;
859 if (total_dumps != 0)
860 UMA_HISTOGRAM_COUNTS("Chrome.BrowserCrashDumpAttempts", total_dumps);
862 #endif // defined(OS_WIN)
864 //------------------------------------------------------------------------------
866 //------------------------------------------------------------------------------
869 //------------------------------------------------------------------------------
870 // Initialization methods
872 void MetricsService::InitializeMetricsState() {
873 #if defined(OS_POSIX)
874 network_stats_server_ = chrome_common_net::kEchoTestServerLocation;
875 http_pipelining_test_server_ = chrome_common_net::kPipelineTestServerBaseUrl;
877 BrowserDistribution* dist = BrowserDistribution::GetDistribution();
878 network_stats_server_ = dist->GetNetworkStatsServer();
879 http_pipelining_test_server_ = dist->GetHttpPipeliningTestServer();
882 PrefService* pref = g_browser_process->local_state();
885 if ((pref->GetInt64(prefs::kStabilityStatsBuildTime)
886 != MetricsLog::GetBuildTime()) ||
887 (pref->GetString(prefs::kStabilityStatsVersion)
888 != MetricsLog::GetVersionString())) {
889 // This is a new version, so we don't want to confuse the stats about the
890 // old version with info that we upload.
891 DiscardOldStabilityStats(pref);
892 pref->SetString(prefs::kStabilityStatsVersion,
893 MetricsLog::GetVersionString());
894 pref->SetInt64(prefs::kStabilityStatsBuildTime,
895 MetricsLog::GetBuildTime());
899 session_id_ = pref->GetInteger(prefs::kMetricsSessionID);
901 pref->SetInteger(prefs::kMetricsSessionID, session_id_);
903 // Stability bookkeeping
904 IncrementPrefValue(prefs::kStabilityLaunchCount);
906 if (!pref->GetBoolean(prefs::kStabilityExitedCleanly)) {
907 IncrementPrefValue(prefs::kStabilityCrashCount);
908 // Reset flag, and wait until we call LogNeedForCleanShutdown() before
910 pref->SetBoolean(prefs::kStabilityExitedCleanly, true);
912 // TODO(rtenneti): On windows, consider saving/getting execution_phase from
914 int execution_phase = pref->GetInteger(prefs::kStabilityExecutionPhase);
915 UMA_HISTOGRAM_SPARSE_SLOWLY("Chrome.Browser.ExecutionPhase",
917 pref->SetInteger(prefs::kStabilityExecutionPhase, CLEAN_SHUTDOWN);
921 CountBrowserCrashDumpAttempts();
922 #endif // defined(OS_WIN)
924 if (!pref->GetBoolean(prefs::kStabilitySessionEndCompleted)) {
925 IncrementPrefValue(prefs::kStabilityIncompleteSessionEndCount);
926 // This is marked false when we get a WM_ENDSESSION.
927 pref->SetBoolean(prefs::kStabilitySessionEndCompleted, true);
930 // Initialize uptime counters.
931 const base::TimeDelta startup_uptime = GetIncrementalUptime(pref);
932 DCHECK_EQ(0, startup_uptime.InMicroseconds());
933 // For backwards compatibility, leave this intact in case Omaha is checking
934 // them. prefs::kStabilityLastTimestampSec may also be useless now.
935 // TODO(jar): Delete these if they have no uses.
936 pref->SetInt64(prefs::kStabilityLaunchTimeSec, Time::Now().ToTimeT());
938 // Bookkeeping for the uninstall metrics.
939 IncrementLongPrefsValue(prefs::kUninstallLaunchCount);
941 // Get stats on use of command line.
942 const CommandLine* command_line(CommandLine::ForCurrentProcess());
943 size_t common_commands = 0;
944 if (command_line->HasSwitch(switches::kUserDataDir)) {
946 UMA_HISTOGRAM_COUNTS_100("Chrome.CommandLineDatDirCount", 1);
949 if (command_line->HasSwitch(switches::kApp)) {
951 UMA_HISTOGRAM_COUNTS_100("Chrome.CommandLineAppModeCount", 1);
954 size_t switch_count = command_line->GetSwitches().size();
955 UMA_HISTOGRAM_COUNTS_100("Chrome.CommandLineFlagCount", switch_count);
956 UMA_HISTOGRAM_COUNTS_100("Chrome.CommandLineUncommonFlagCount",
957 switch_count - common_commands);
959 // Kick off the process of saving the state (so the uptime numbers keep
960 // getting updated) every n minutes.
961 ScheduleNextStateSave();
965 void MetricsService::InitTaskGetHardwareClass(
966 base::WeakPtr<MetricsService> self,
967 base::MessageLoopProxy* target_loop) {
968 DCHECK(BrowserThread::CurrentlyOn(BrowserThread::FILE));
970 std::string hardware_class;
971 #if defined(OS_CHROMEOS)
972 chromeos::system::StatisticsProvider::GetInstance()->GetMachineStatistic(
973 "hardware_class", &hardware_class);
974 #endif // OS_CHROMEOS
976 target_loop->PostTask(FROM_HERE,
977 base::Bind(&MetricsService::OnInitTaskGotHardwareClass,
978 self, hardware_class));
981 void MetricsService::OnInitTaskGotHardwareClass(
982 const std::string& hardware_class) {
983 DCHECK_EQ(INIT_TASK_SCHEDULED, state_);
984 hardware_class_ = hardware_class;
986 #if defined(ENABLE_PLUGINS)
987 // Start the next part of the init task: loading plugin information.
988 PluginService::GetInstance()->GetPlugins(
989 base::Bind(&MetricsService::OnInitTaskGotPluginInfo,
990 self_ptr_factory_.GetWeakPtr()));
992 std::vector<content::WebPluginInfo> plugin_list_empty;
993 OnInitTaskGotPluginInfo(plugin_list_empty);
994 #endif // defined(ENABLE_PLUGINS)
997 void MetricsService::OnInitTaskGotPluginInfo(
998 const std::vector<content::WebPluginInfo>& plugins) {
999 DCHECK_EQ(INIT_TASK_SCHEDULED, state_);
1002 // Schedules a task on a blocking pool thread to gather Google Update
1003 // statistics (requires Registry reads).
1004 BrowserThread::PostBlockingPoolTask(
1006 base::Bind(&MetricsService::InitTaskGetGoogleUpdateData,
1007 self_ptr_factory_.GetWeakPtr(),
1008 base::MessageLoop::current()->message_loop_proxy()));
1012 void MetricsService::InitTaskGetGoogleUpdateData(
1013 base::WeakPtr<MetricsService> self,
1014 base::MessageLoopProxy* target_loop) {
1015 GoogleUpdateMetrics google_update_metrics;
1017 #if defined(OS_WIN) && defined(GOOGLE_CHROME_BUILD)
1018 const bool system_install = GoogleUpdateSettings::IsSystemInstall();
1020 google_update_metrics.is_system_install = system_install;
1021 google_update_metrics.last_started_au =
1022 GoogleUpdateSettings::GetGoogleUpdateLastStartedAU(system_install);
1023 google_update_metrics.last_checked =
1024 GoogleUpdateSettings::GetGoogleUpdateLastChecked(system_install);
1025 GoogleUpdateSettings::GetUpdateDetailForGoogleUpdate(
1027 &google_update_metrics.google_update_data);
1028 GoogleUpdateSettings::GetUpdateDetail(
1030 &google_update_metrics.product_data);
1031 #endif // defined(OS_WIN) && defined(GOOGLE_CHROME_BUILD)
1033 target_loop->PostTask(FROM_HERE,
1034 base::Bind(&MetricsService::OnInitTaskGotGoogleUpdateData,
1035 self, google_update_metrics));
1038 void MetricsService::OnInitTaskGotGoogleUpdateData(
1039 const GoogleUpdateMetrics& google_update_metrics) {
1040 DCHECK_EQ(INIT_TASK_SCHEDULED, state_);
1042 google_update_metrics_ = google_update_metrics;
1044 // Start the next part of the init task: fetching performance data. This will
1045 // call into |FinishedReceivingProfilerData()| when the task completes.
1046 chrome_browser_metrics::TrackingSynchronizer::FetchProfilerDataAsynchronously(
1047 self_ptr_factory_.GetWeakPtr());
1050 void MetricsService::OnUserAction(const std::string& action) {
1051 if (!CanLogNotification())
1054 log_manager_.current_log()->RecordUserAction(action.c_str());
1055 HandleIdleSinceLastTransmission(false);
1058 void MetricsService::ReceivedProfilerData(
1059 const tracked_objects::ProcessDataSnapshot& process_data,
1061 DCHECK_EQ(INIT_TASK_SCHEDULED, state_);
1063 // Upon the first callback, create the initial log so that we can immediately
1064 // save the profiler data.
1065 if (!initial_log_.get())
1066 initial_log_.reset(new MetricsLog(client_id_, session_id_));
1068 initial_log_->RecordProfilerData(process_data, process_type);
1071 void MetricsService::FinishedReceivingProfilerData() {
1072 DCHECK_EQ(INIT_TASK_SCHEDULED, state_);
1073 state_ = INIT_TASK_DONE;
1076 base::TimeDelta MetricsService::GetIncrementalUptime(PrefService* pref) {
1077 base::TimeTicks now = base::TimeTicks::Now();
1078 // If this is the first call, init |last_updated_time_|.
1079 if (last_updated_time_.is_null())
1080 last_updated_time_ = now;
1081 const base::TimeDelta incremental_time = now - last_updated_time_;
1082 last_updated_time_ = now;
1084 const int64 incremental_time_secs = incremental_time.InSeconds();
1085 if (incremental_time_secs > 0) {
1086 int64 metrics_uptime = pref->GetInt64(prefs::kUninstallMetricsUptimeSec);
1087 metrics_uptime += incremental_time_secs;
1088 pref->SetInt64(prefs::kUninstallMetricsUptimeSec, metrics_uptime);
1091 return incremental_time;
1094 int MetricsService::GetLowEntropySource() {
1095 // Note that the default value for the low entropy source and the default pref
1096 // value are both kLowEntropySourceNotSet, which is used to identify if the
1097 // value has been set or not.
1098 if (low_entropy_source_ != kLowEntropySourceNotSet)
1099 return low_entropy_source_;
1101 PrefService* local_state = g_browser_process->local_state();
1102 const CommandLine* command_line(CommandLine::ForCurrentProcess());
1103 // Only try to load the value from prefs if the user did not request a reset.
1104 // Otherwise, skip to generating a new value.
1105 if (!command_line->HasSwitch(switches::kResetVariationState)) {
1106 int value = local_state->GetInteger(prefs::kMetricsLowEntropySource);
1107 // Old versions of the code would generate values in the range of [1, 8192],
1108 // before the range was switched to [0, 8191] and then to [0, 7999]. Map
1109 // 8192 to 0, so that the 0th bucket remains uniform, while re-generating
1110 // the low entropy source for old values in the [8000, 8191] range.
1113 // If the value is outside the [0, kMaxLowEntropySize) range, re-generate
1115 if (value >= 0 && value < kMaxLowEntropySize) {
1116 low_entropy_source_ = value;
1117 UMA_HISTOGRAM_BOOLEAN("UMA.GeneratedLowEntropySource", false);
1118 return low_entropy_source_;
1122 UMA_HISTOGRAM_BOOLEAN("UMA.GeneratedLowEntropySource", true);
1123 low_entropy_source_ = GenerateLowEntropySource();
1124 local_state->SetInteger(prefs::kMetricsLowEntropySource, low_entropy_source_);
1125 metrics::CachingPermutedEntropyProvider::ClearCache(local_state);
1127 return low_entropy_source_;
1131 std::string MetricsService::GenerateClientID() {
1132 return base::GenerateGUID();
1135 //------------------------------------------------------------------------------
1136 // State save methods
1138 void MetricsService::ScheduleNextStateSave() {
1139 state_saver_factory_.InvalidateWeakPtrs();
1141 base::MessageLoop::current()->PostDelayedTask(FROM_HERE,
1142 base::Bind(&MetricsService::SaveLocalState,
1143 state_saver_factory_.GetWeakPtr()),
1144 base::TimeDelta::FromMinutes(kSaveStateIntervalMinutes));
1147 void MetricsService::SaveLocalState() {
1148 PrefService* pref = g_browser_process->local_state();
1154 RecordCurrentState(pref);
1156 // TODO(jar):110021 Does this run down the batteries????
1157 ScheduleNextStateSave();
1161 //------------------------------------------------------------------------------
1162 // Recording control methods
1164 void MetricsService::OpenNewLog() {
1165 DCHECK(!log_manager_.current_log());
1167 log_manager_.BeginLoggingWithLog(new MetricsLog(client_id_, session_id_),
1168 MetricsLogManager::ONGOING_LOG);
1169 if (state_ == INITIALIZED) {
1170 // We only need to schedule that run once.
1171 state_ = INIT_TASK_SCHEDULED;
1173 // Schedules a task on the file thread for execution of slower
1174 // initialization steps (such as plugin list generation) necessary
1175 // for sending the initial log. This avoids blocking the main UI
1177 BrowserThread::PostDelayedTask(
1178 BrowserThread::FILE,
1180 base::Bind(&MetricsService::InitTaskGetHardwareClass,
1181 self_ptr_factory_.GetWeakPtr(),
1182 base::MessageLoop::current()->message_loop_proxy()),
1183 base::TimeDelta::FromSeconds(kInitializationDelaySeconds));
1187 void MetricsService::CloseCurrentLog() {
1188 if (!log_manager_.current_log())
1191 // TODO(jar): Integrate bounds on log recording more consistently, so that we
1192 // can stop recording logs that are too big much sooner.
1193 if (log_manager_.current_log()->num_events() > kEventLimit) {
1194 UMA_HISTOGRAM_COUNTS("UMA.Discarded Log Events",
1195 log_manager_.current_log()->num_events());
1196 log_manager_.DiscardCurrentLog();
1197 OpenNewLog(); // Start trivial log to hold our histograms.
1200 // Adds to ongoing logs.
1201 log_manager_.current_log()->set_hardware_class(hardware_class_);
1203 // Put incremental data (histogram deltas, and realtime stats deltas) at the
1204 // end of all log transmissions (initial log handles this separately).
1205 // RecordIncrementalStabilityElements only exists on the derived
1206 // MetricsLog class.
1207 MetricsLog* current_log =
1208 static_cast<MetricsLog*>(log_manager_.current_log());
1209 DCHECK(current_log);
1210 current_log->RecordEnvironmentProto(plugins_, google_update_metrics_);
1211 PrefService* pref = g_browser_process->local_state();
1212 current_log->RecordIncrementalStabilityElements(plugins_,
1213 GetIncrementalUptime(pref));
1214 RecordCurrentHistograms();
1216 log_manager_.FinishCurrentLog();
1219 void MetricsService::PushPendingLogsToPersistentStorage() {
1220 if (state_ < INITIAL_LOG_READY)
1221 return; // We didn't and still don't have time to get plugin list etc.
1223 if (log_manager_.has_staged_log()) {
1224 // We may race here, and send second copy of the log later.
1225 MetricsLogManager::StoreType store_type;
1226 if (current_fetch_.get())
1227 store_type = MetricsLogManager::PROVISIONAL_STORE;
1229 store_type = MetricsLogManager::NORMAL_STORE;
1230 log_manager_.StoreStagedLogAsUnsent(store_type);
1232 DCHECK(!log_manager_.has_staged_log());
1236 // If there was a staged and/or current log, then there is now at least one
1237 // log waiting to be uploaded.
1238 if (log_manager_.has_unsent_logs())
1239 state_ = SENDING_OLD_LOGS;
1242 //------------------------------------------------------------------------------
1243 // Transmission of logs methods
1245 void MetricsService::StartSchedulerIfNecessary() {
1246 // Never schedule cutting or uploading of logs in test mode.
1247 if (test_mode_active_)
1250 // Even if reporting is disabled, the scheduler is needed to trigger the
1251 // creation of the initial log, which must be done in order for any logs to be
1252 // persisted on shutdown or backgrounding.
1253 if (recording_active() && (reporting_active() || state_ < INITIAL_LOG_READY))
1254 scheduler_->Start();
1257 void MetricsService::StartScheduledUpload() {
1258 // If we're getting no notifications, then the log won't have much in it, and
1259 // it's possible the computer is about to go to sleep, so don't upload and
1260 // stop the scheduler.
1261 // If recording has been turned off, the scheduler doesn't need to run.
1262 // If reporting is off, proceed if the initial log hasn't been created, since
1263 // that has to happen in order for logs to be cut and stored when persisting.
1264 // TODO(stuartmorgan): Call Stop() on the schedule when reporting and/or
1265 // recording are turned off instead of letting it fire and then aborting.
1266 if (idle_since_last_transmission_ ||
1267 !recording_active() ||
1268 (!reporting_active() && state_ >= INITIAL_LOG_READY)) {
1270 scheduler_->UploadCancelled();
1274 // If the callback was to upload an old log, but there no longer is one,
1275 // just report success back to the scheduler to begin the ongoing log
1277 // TODO(stuartmorgan): Consider removing the distinction between
1278 // SENDING_OLD_LOGS and SENDING_CURRENT_LOGS to simplify the state machine
1279 // now that the log upload flow is the same for both modes.
1280 if (state_ == SENDING_OLD_LOGS && !log_manager_.has_unsent_logs()) {
1281 state_ = SENDING_CURRENT_LOGS;
1282 scheduler_->UploadFinished(true /* healthy */, false /* no unsent logs */);
1285 // If there are unsent logs, send the next one. If not, start the asynchronous
1286 // process of finalizing the current log for upload.
1287 if (state_ == SENDING_OLD_LOGS) {
1288 DCHECK(log_manager_.has_unsent_logs());
1289 log_manager_.StageNextLogForUpload();
1292 StartFinalLogInfoCollection();
1296 void MetricsService::StartFinalLogInfoCollection() {
1297 // Begin the multi-step process of collecting memory usage histograms:
1298 // First spawn a task to collect the memory details; when that task is
1299 // finished, it will call OnMemoryDetailCollectionDone. That will in turn
1300 // call HistogramSynchronization to collect histograms from all renderers and
1301 // then call OnHistogramSynchronizationDone to continue processing.
1302 DCHECK(!waiting_for_asynchronous_reporting_step_);
1303 waiting_for_asynchronous_reporting_step_ = true;
1305 base::Closure callback =
1306 base::Bind(&MetricsService::OnMemoryDetailCollectionDone,
1307 self_ptr_factory_.GetWeakPtr());
1309 scoped_refptr<MetricsMemoryDetails> details(
1310 new MetricsMemoryDetails(callback));
1311 details->StartFetch(MemoryDetails::UPDATE_USER_METRICS);
1313 // Collect WebCore cache information to put into a histogram.
1314 for (content::RenderProcessHost::iterator i(
1315 content::RenderProcessHost::AllHostsIterator());
1316 !i.IsAtEnd(); i.Advance())
1317 i.GetCurrentValue()->Send(new ChromeViewMsg_GetCacheResourceStats());
1320 void MetricsService::OnMemoryDetailCollectionDone() {
1321 DCHECK(IsSingleThreaded());
1322 // This function should only be called as the callback from an ansynchronous
1324 DCHECK(waiting_for_asynchronous_reporting_step_);
1326 // Create a callback_task for OnHistogramSynchronizationDone.
1327 base::Closure callback = base::Bind(
1328 &MetricsService::OnHistogramSynchronizationDone,
1329 self_ptr_factory_.GetWeakPtr());
1331 base::TimeDelta timeout =
1332 base::TimeDelta::FromMilliseconds(kMaxHistogramGatheringWaitDuration);
1334 DCHECK_EQ(num_async_histogram_fetches_in_progress_, 0);
1336 #if defined(OS_ANDROID)
1337 // Android has no service process.
1338 num_async_histogram_fetches_in_progress_ = 1;
1340 num_async_histogram_fetches_in_progress_ = 2;
1341 // Run requests to service and content in parallel.
1342 if (!ServiceProcessControl::GetInstance()->GetHistograms(callback, timeout)) {
1343 // Assume |num_async_histogram_fetches_in_progress_| is not changed by
1344 // |GetHistograms()|.
1345 DCHECK_EQ(num_async_histogram_fetches_in_progress_, 2);
1346 // Assign |num_async_histogram_fetches_in_progress_| above and decrement it
1347 // here to make code work even if |GetHistograms()| fired |callback|.
1348 --num_async_histogram_fetches_in_progress_;
1350 #endif // OS_ANDROID
1352 // Set up the callback to task to call after we receive histograms from all
1353 // child processes. Wait time specifies how long to wait before absolutely
1354 // calling us back on the task.
1355 content::FetchHistogramsAsynchronously(base::MessageLoop::current(), callback,
1359 void MetricsService::OnHistogramSynchronizationDone() {
1360 DCHECK(IsSingleThreaded());
1361 // This function should only be called as the callback from an ansynchronous
1363 DCHECK(waiting_for_asynchronous_reporting_step_);
1364 DCHECK_GT(num_async_histogram_fetches_in_progress_, 0);
1366 // Check if all expected requests finished.
1367 if (--num_async_histogram_fetches_in_progress_ > 0)
1370 waiting_for_asynchronous_reporting_step_ = false;
1371 OnFinalLogInfoCollectionDone();
1374 void MetricsService::OnFinalLogInfoCollectionDone() {
1375 // If somehow there is a fetch in progress, we return and hope things work
1376 // out. The scheduler isn't informed since if this happens, the scheduler
1377 // will get a response from the upload.
1378 DCHECK(!current_fetch_.get());
1379 if (current_fetch_.get())
1382 // Abort if metrics were turned off during the final info gathering.
1383 if (!recording_active()) {
1385 scheduler_->UploadCancelled();
1391 // If logs shouldn't be uploaded, stop here. It's important that this check
1392 // be after StageNewLog(), otherwise the previous logs will never be loaded,
1393 // and thus the open log won't be persisted.
1394 // TODO(stuartmorgan): This is unnecessarily complicated; restructure loading
1395 // of previous logs to not require running part of the upload logic.
1396 // http://crbug.com/157337
1397 if (!reporting_active()) {
1399 scheduler_->UploadCancelled();
1406 void MetricsService::StageNewLog() {
1407 if (log_manager_.has_staged_log())
1412 case INIT_TASK_SCHEDULED: // We should be further along by now.
1416 case INIT_TASK_DONE:
1417 PrepareInitialLog();
1418 DCHECK_EQ(INIT_TASK_DONE, state_);
1419 log_manager_.LoadPersistedUnsentLogs();
1420 state_ = INITIAL_LOG_READY;
1423 case SENDING_OLD_LOGS:
1424 NOTREACHED(); // Shouldn't be staging a new log during old log sending.
1427 case SENDING_CURRENT_LOGS:
1430 log_manager_.StageNextLogForUpload();
1438 DCHECK(log_manager_.has_staged_log());
1441 void MetricsService::PrepareInitialLog() {
1442 DCHECK_EQ(INIT_TASK_DONE, state_);
1444 DCHECK(initial_log_.get());
1445 initial_log_->set_hardware_class(hardware_class_);
1446 PrefService* pref = g_browser_process->local_state();
1447 initial_log_->RecordEnvironment(plugins_, google_update_metrics_,
1448 GetIncrementalUptime(pref));
1450 // Histograms only get written to the current log, so make the new log current
1451 // before writing them.
1452 log_manager_.PauseCurrentLog();
1453 log_manager_.BeginLoggingWithLog(initial_log_.release(),
1454 MetricsLogManager::INITIAL_LOG);
1455 RecordCurrentHistograms();
1456 log_manager_.FinishCurrentLog();
1457 log_manager_.ResumePausedLog();
1459 DCHECK(!log_manager_.has_staged_log());
1460 log_manager_.StageNextLogForUpload();
1463 void MetricsService::StoreUnsentLogs() {
1464 if (state_ < INITIAL_LOG_READY)
1465 return; // We never Recalled the prior unsent logs.
1467 log_manager_.PersistUnsentLogs();
1470 void MetricsService::SendStagedLog() {
1471 DCHECK(log_manager_.has_staged_log());
1473 PrepareFetchWithStagedLog();
1475 bool upload_created = (current_fetch_.get() != NULL);
1476 UMA_HISTOGRAM_BOOLEAN("UMA.UploadCreation", upload_created);
1477 if (!upload_created) {
1478 // Compression failed, and log discarded :-/.
1479 // Skip this upload and hope things work out next time.
1480 log_manager_.DiscardStagedLog();
1481 scheduler_->UploadCancelled();
1485 DCHECK(!waiting_for_asynchronous_reporting_step_);
1486 waiting_for_asynchronous_reporting_step_ = true;
1488 current_fetch_->Start();
1490 HandleIdleSinceLastTransmission(true);
1493 void MetricsService::PrepareFetchWithStagedLog() {
1494 DCHECK(log_manager_.has_staged_log());
1496 // Prepare the protobuf version.
1497 DCHECK(!current_fetch_.get());
1498 if (log_manager_.has_staged_log()) {
1499 current_fetch_.reset(net::URLFetcher::Create(
1500 GURL(kServerUrl), net::URLFetcher::POST, this));
1501 current_fetch_->SetRequestContext(
1502 g_browser_process->system_request_context());
1504 std::string log_text = log_manager_.staged_log_text();
1505 std::string compressed_log_text;
1506 bool compression_successful = chrome::GzipCompress(log_text,
1507 &compressed_log_text);
1508 DCHECK(compression_successful);
1509 if (compression_successful) {
1510 current_fetch_->SetUploadData(kMimeType, compressed_log_text);
1511 // Tell the server that we're uploading gzipped protobufs.
1512 current_fetch_->SetExtraRequestHeaders("content-encoding: gzip");
1513 const std::string hash =
1514 base::HexEncode(log_manager_.staged_log_hash().data(),
1515 log_manager_.staged_log_hash().size());
1516 DCHECK(!hash.empty());
1517 current_fetch_->AddExtraRequestHeader("X-Chrome-UMA-Log-SHA1: " + hash);
1518 UMA_HISTOGRAM_PERCENTAGE(
1519 "UMA.ProtoCompressionRatio",
1520 100 * compressed_log_text.size() / log_text.size());
1521 UMA_HISTOGRAM_CUSTOM_COUNTS(
1522 "UMA.ProtoGzippedKBSaved",
1523 (log_text.size() - compressed_log_text.size()) / 1024,
1527 // We already drop cookies server-side, but we might as well strip them out
1528 // client-side as well.
1529 current_fetch_->SetLoadFlags(net::LOAD_DO_NOT_SAVE_COOKIES |
1530 net::LOAD_DO_NOT_SEND_COOKIES);
1534 void MetricsService::OnURLFetchComplete(const net::URLFetcher* source) {
1535 DCHECK(waiting_for_asynchronous_reporting_step_);
1537 // We're not allowed to re-use the existing |URLFetcher|s, so free them here.
1538 // Note however that |source| is aliased to the fetcher, so we should be
1539 // careful not to delete it too early.
1540 DCHECK_EQ(current_fetch_.get(), source);
1541 scoped_ptr<net::URLFetcher> s(current_fetch_.Pass());
1543 int response_code = source->GetResponseCode();
1545 // Log a histogram to track response success vs. failure rates.
1546 UMA_HISTOGRAM_ENUMERATION("UMA.UploadResponseStatus.Protobuf",
1547 ResponseCodeToStatus(response_code),
1548 NUM_RESPONSE_STATUSES);
1550 // If the upload was provisionally stored, drop it now that the upload is
1551 // known to have gone through.
1552 log_manager_.DiscardLastProvisionalStore();
1554 bool upload_succeeded = response_code == 200;
1556 // Provide boolean for error recovery (allow us to ignore response_code).
1557 bool discard_log = false;
1558 const size_t log_size = log_manager_.staged_log_text().length();
1559 if (!upload_succeeded && log_size > kUploadLogAvoidRetransmitSize) {
1560 UMA_HISTOGRAM_COUNTS("UMA.Large Rejected Log was Discarded",
1561 static_cast<int>(log_size));
1563 } else if (response_code == 400) {
1564 // Bad syntax. Retransmission won't work.
1568 if (upload_succeeded || discard_log)
1569 log_manager_.DiscardStagedLog();
1571 waiting_for_asynchronous_reporting_step_ = false;
1573 if (!log_manager_.has_staged_log()) {
1575 case INITIAL_LOG_READY:
1576 state_ = log_manager_.has_unsent_logs() ? SENDING_OLD_LOGS
1577 : SENDING_CURRENT_LOGS;
1580 case SENDING_OLD_LOGS:
1581 // Store the updated list to disk now that the removed log is uploaded.
1583 if (!log_manager_.has_unsent_logs())
1584 state_ = SENDING_CURRENT_LOGS;
1587 case SENDING_CURRENT_LOGS:
1595 if (log_manager_.has_unsent_logs())
1596 DCHECK_LT(state_, SENDING_CURRENT_LOGS);
1599 // Error 400 indicates a problem with the log, not with the server, so
1600 // don't consider that a sign that the server is in trouble.
1601 bool server_is_healthy = upload_succeeded || response_code == 400;
1602 scheduler_->UploadFinished(server_is_healthy, log_manager_.has_unsent_logs());
1604 // Collect network stats if UMA upload succeeded.
1605 IOThread* io_thread = g_browser_process->io_thread();
1606 if (server_is_healthy && io_thread) {
1607 chrome_browser_net::CollectNetworkStats(network_stats_server_, io_thread);
1608 chrome_browser_net::CollectPipeliningCapabilityStatsOnUIThread(
1609 http_pipelining_test_server_, io_thread);
1611 chrome::CollectTimeTicksStats();
1616 void MetricsService::IncrementPrefValue(const char* path) {
1617 PrefService* pref = g_browser_process->local_state();
1619 int value = pref->GetInteger(path);
1620 pref->SetInteger(path, value + 1);
1623 void MetricsService::IncrementLongPrefsValue(const char* path) {
1624 PrefService* pref = g_browser_process->local_state();
1626 int64 value = pref->GetInt64(path);
1627 pref->SetInt64(path, value + 1);
1630 void MetricsService::LogLoadStarted(content::WebContents* web_contents) {
1631 content::RecordAction(content::UserMetricsAction("PageLoad"));
1632 HISTOGRAM_ENUMERATION("Chrome.UmaPageloadCounter", 1, 2);
1633 IncrementPrefValue(prefs::kStabilityPageLoadCount);
1634 IncrementLongPrefsValue(prefs::kUninstallMetricsPageLoadCount);
1635 // We need to save the prefs, as page load count is a critical stat, and it
1636 // might be lost due to a crash :-(.
1639 void MetricsService::LogRendererCrash(content::RenderProcessHost* host,
1640 base::TerminationStatus status,
1642 Profile* profile = Profile::FromBrowserContext(host->GetBrowserContext());
1643 ExtensionService* service = profile->GetExtensionService();
1644 bool was_extension_process =
1645 service && service->process_map()->Contains(host->GetID());
1646 if (status == base::TERMINATION_STATUS_PROCESS_CRASHED ||
1647 status == base::TERMINATION_STATUS_ABNORMAL_TERMINATION) {
1648 if (was_extension_process) {
1649 IncrementPrefValue(prefs::kStabilityExtensionRendererCrashCount);
1651 UMA_HISTOGRAM_SPARSE_SLOWLY("CrashExitCodes.Extension",
1652 MapCrashExitCodeForHistogram(exit_code));
1654 IncrementPrefValue(prefs::kStabilityRendererCrashCount);
1656 UMA_HISTOGRAM_SPARSE_SLOWLY("CrashExitCodes.Renderer",
1657 MapCrashExitCodeForHistogram(exit_code));
1660 UMA_HISTOGRAM_PERCENTAGE("BrowserRenderProcessHost.ChildCrashes",
1661 was_extension_process ? 2 : 1);
1662 } else if (status == base::TERMINATION_STATUS_PROCESS_WAS_KILLED) {
1663 UMA_HISTOGRAM_PERCENTAGE("BrowserRenderProcessHost.ChildKills",
1664 was_extension_process ? 2 : 1);
1665 } else if (status == base::TERMINATION_STATUS_STILL_RUNNING) {
1666 UMA_HISTOGRAM_PERCENTAGE("BrowserRenderProcessHost.DisconnectedAlive",
1667 was_extension_process ? 2 : 1);
1671 void MetricsService::LogRendererHang() {
1672 IncrementPrefValue(prefs::kStabilityRendererHangCount);
1675 bool MetricsService::UmaMetricsProperlyShutdown() {
1676 CHECK(clean_shutdown_status_ == CLEANLY_SHUTDOWN ||
1677 clean_shutdown_status_ == NEED_TO_SHUTDOWN);
1678 return clean_shutdown_status_ == CLEANLY_SHUTDOWN;
1681 void MetricsService::LogCleanShutdown() {
1682 // Redundant hack to write pref ASAP.
1683 MarkAppCleanShutdownAndCommit();
1685 // Redundant setting to assure that we always reset this value at shutdown
1686 // (and that we don't use some alternate path, and not call LogCleanShutdown).
1687 clean_shutdown_status_ = CLEANLY_SHUTDOWN;
1689 RecordBooleanPrefValue(prefs::kStabilityExitedCleanly, true);
1690 PrefService* pref = g_browser_process->local_state();
1691 pref->SetInteger(prefs::kStabilityExecutionPhase,
1692 MetricsService::CLEAN_SHUTDOWN);
1695 #if defined(OS_CHROMEOS)
1696 void MetricsService::LogChromeOSCrash(const std::string &crash_type) {
1697 if (crash_type == "user")
1698 IncrementPrefValue(prefs::kStabilityOtherUserCrashCount);
1699 else if (crash_type == "kernel")
1700 IncrementPrefValue(prefs::kStabilityKernelCrashCount);
1701 else if (crash_type == "uncleanshutdown")
1702 IncrementPrefValue(prefs::kStabilitySystemUncleanShutdownCount);
1704 NOTREACHED() << "Unexpected Chrome OS crash type " << crash_type;
1705 // Wake up metrics logs sending if necessary now that new
1706 // log data is available.
1707 HandleIdleSinceLastTransmission(false);
1709 #endif // OS_CHROMEOS
1711 void MetricsService::LogPluginLoadingError(const base::FilePath& plugin_path) {
1712 content::WebPluginInfo plugin;
1714 content::PluginService::GetInstance()->GetPluginInfoByPath(plugin_path,
1717 ChildProcessStats& stats = child_process_stats_buffer_[plugin.name];
1718 // Initialize the type if this entry is new.
1719 if (stats.process_type == content::PROCESS_TYPE_UNKNOWN) {
1720 // The plug-in process might not actually of type PLUGIN (which means
1721 // NPAPI), but we only care that it is *a* plug-in process.
1722 stats.process_type = content::PROCESS_TYPE_PLUGIN;
1724 DCHECK(IsPluginProcess(stats.process_type));
1726 stats.loading_errors++;
1729 MetricsService::ChildProcessStats& MetricsService::GetChildProcessStats(
1730 const content::ChildProcessData& data) {
1731 const string16& child_name = data.name;
1732 if (!ContainsKey(child_process_stats_buffer_, child_name)) {
1733 child_process_stats_buffer_[child_name] =
1734 ChildProcessStats(data.process_type);
1736 return child_process_stats_buffer_[child_name];
1739 void MetricsService::RecordPluginChanges(PrefService* pref) {
1740 ListPrefUpdate update(pref, prefs::kStabilityPluginStats);
1741 ListValue* plugins = update.Get();
1744 for (ListValue::iterator value_iter = plugins->begin();
1745 value_iter != plugins->end(); ++value_iter) {
1746 if (!(*value_iter)->IsType(Value::TYPE_DICTIONARY)) {
1751 DictionaryValue* plugin_dict = static_cast<DictionaryValue*>(*value_iter);
1752 std::string plugin_name;
1753 plugin_dict->GetString(prefs::kStabilityPluginName, &plugin_name);
1754 if (plugin_name.empty()) {
1759 // TODO(viettrungluu): remove conversions
1760 string16 name16 = UTF8ToUTF16(plugin_name);
1761 if (child_process_stats_buffer_.find(name16) ==
1762 child_process_stats_buffer_.end()) {
1766 ChildProcessStats stats = child_process_stats_buffer_[name16];
1767 if (stats.process_launches) {
1769 plugin_dict->GetInteger(prefs::kStabilityPluginLaunches, &launches);
1770 launches += stats.process_launches;
1771 plugin_dict->SetInteger(prefs::kStabilityPluginLaunches, launches);
1773 if (stats.process_crashes) {
1775 plugin_dict->GetInteger(prefs::kStabilityPluginCrashes, &crashes);
1776 crashes += stats.process_crashes;
1777 plugin_dict->SetInteger(prefs::kStabilityPluginCrashes, crashes);
1779 if (stats.instances) {
1781 plugin_dict->GetInteger(prefs::kStabilityPluginInstances, &instances);
1782 instances += stats.instances;
1783 plugin_dict->SetInteger(prefs::kStabilityPluginInstances, instances);
1785 if (stats.loading_errors) {
1786 int loading_errors = 0;
1787 plugin_dict->GetInteger(prefs::kStabilityPluginLoadingErrors,
1789 loading_errors += stats.loading_errors;
1790 plugin_dict->SetInteger(prefs::kStabilityPluginLoadingErrors,
1794 child_process_stats_buffer_.erase(name16);
1797 // Now go through and add dictionaries for plugins that didn't already have
1798 // reports in Local State.
1799 for (std::map<string16, ChildProcessStats>::iterator cache_iter =
1800 child_process_stats_buffer_.begin();
1801 cache_iter != child_process_stats_buffer_.end(); ++cache_iter) {
1802 ChildProcessStats stats = cache_iter->second;
1804 // Insert only plugins information into the plugins list.
1805 if (!IsPluginProcess(stats.process_type))
1808 // TODO(viettrungluu): remove conversion
1809 std::string plugin_name = UTF16ToUTF8(cache_iter->first);
1811 DictionaryValue* plugin_dict = new DictionaryValue;
1813 plugin_dict->SetString(prefs::kStabilityPluginName, plugin_name);
1814 plugin_dict->SetInteger(prefs::kStabilityPluginLaunches,
1815 stats.process_launches);
1816 plugin_dict->SetInteger(prefs::kStabilityPluginCrashes,
1817 stats.process_crashes);
1818 plugin_dict->SetInteger(prefs::kStabilityPluginInstances,
1820 plugin_dict->SetInteger(prefs::kStabilityPluginLoadingErrors,
1821 stats.loading_errors);
1822 plugins->Append(plugin_dict);
1824 child_process_stats_buffer_.clear();
1827 bool MetricsService::CanLogNotification() {
1828 // We simply don't log anything to UMA if there is a single incognito
1829 // session visible. The problem is that we always notify using the orginal
1830 // profile in order to simplify notification processing.
1831 return !chrome::IsOffTheRecordSessionActive();
1834 void MetricsService::RecordBooleanPrefValue(const char* path, bool value) {
1835 DCHECK(IsSingleThreaded());
1837 PrefService* pref = g_browser_process->local_state();
1840 pref->SetBoolean(path, value);
1841 RecordCurrentState(pref);
1844 void MetricsService::RecordCurrentState(PrefService* pref) {
1845 pref->SetInt64(prefs::kStabilityLastTimestampSec, Time::Now().ToTimeT());
1847 RecordPluginChanges(pref);
1851 bool MetricsService::IsPluginProcess(int process_type) {
1852 return (process_type == content::PROCESS_TYPE_PLUGIN ||
1853 process_type == content::PROCESS_TYPE_PPAPI_PLUGIN ||
1854 process_type == content::PROCESS_TYPE_PPAPI_BROKER);
1857 #if defined(OS_CHROMEOS)
1858 void MetricsService::StartExternalMetrics() {
1859 external_metrics_ = new chromeos::ExternalMetrics;
1860 external_metrics_->Start();
1865 bool MetricsServiceHelper::IsMetricsReportingEnabled() {
1866 bool result = false;
1867 const PrefService* local_state = g_browser_process->local_state();
1869 const PrefService::Preference* uma_pref =
1870 local_state->FindPreference(prefs::kMetricsReportingEnabled);
1872 bool success = uma_pref->GetValue()->GetAsBoolean(&result);