1 // Copyright 2014 The Chromium Authors. All rights reserved.
2 // Use of this source code is governed by a BSD-style license that can be
3 // found in the LICENSE file.
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 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.
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.
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.
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 // states, 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 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.
87 // In more detail, we have:
89 // INITIALIZED, // Constructor was called.
90 // The MS has been constructed, but has taken no actions to compose the
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
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.
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.
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.
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
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
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.
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
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
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.
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.
162 //------------------------------------------------------------------------------
164 #include "components/metrics/metrics_service.h"
168 #include "base/bind.h"
169 #include "base/callback.h"
170 #include "base/metrics/histogram.h"
171 #include "base/metrics/histogram_base.h"
172 #include "base/metrics/histogram_samples.h"
173 #include "base/metrics/sparse_histogram.h"
174 #include "base/metrics/statistics_recorder.h"
175 #include "base/prefs/pref_registry_simple.h"
176 #include "base/prefs/pref_service.h"
177 #include "base/strings/string_number_conversions.h"
178 #include "base/strings/utf_string_conversions.h"
179 #include "base/threading/platform_thread.h"
180 #include "base/threading/thread.h"
181 #include "base/threading/thread_restrictions.h"
182 #include "base/time/time.h"
183 #include "base/tracked_objects.h"
184 #include "base/values.h"
185 #include "components/metrics/metrics_log.h"
186 #include "components/metrics/metrics_log_manager.h"
187 #include "components/metrics/metrics_log_uploader.h"
188 #include "components/metrics/metrics_pref_names.h"
189 #include "components/metrics/metrics_reporting_scheduler.h"
190 #include "components/metrics/metrics_service_client.h"
191 #include "components/metrics/metrics_state_manager.h"
192 #include "components/variations/entropy_provider.h"
198 // Check to see that we're being called on only one thread.
199 bool IsSingleThreaded() {
200 static base::PlatformThreadId thread_id
= 0;
202 thread_id
= base::PlatformThread::CurrentId();
203 return base::PlatformThread::CurrentId() == thread_id
;
206 // The delay, in seconds, after starting recording before doing expensive
207 // initialization work.
208 #if defined(OS_ANDROID) || defined(OS_IOS)
209 // On mobile devices, a significant portion of sessions last less than a minute.
210 // Use a shorter timer on these platforms to avoid losing data.
211 // TODO(dfalcantara): To avoid delaying startup, tighten up initialization so
212 // that it occurs after the user gets their initial page.
213 const int kInitializationDelaySeconds
= 5;
215 const int kInitializationDelaySeconds
= 30;
218 // The maximum number of events in a log uploaded to the UMA server.
219 const int kEventLimit
= 2400;
221 // If an upload fails, and the transmission was over this byte count, then we
222 // will discard the log, and not try to retransmit it. We also don't persist
223 // the log to the prefs for transmission during the next chrome session if this
224 // limit is exceeded.
225 const size_t kUploadLogAvoidRetransmitSize
= 100 * 1024;
227 // Interval, in minutes, between state saves.
228 const int kSaveStateIntervalMinutes
= 5;
230 // The metrics server's URL.
231 const char kServerUrl
[] = "https://clients4.google.com/uma/v2";
233 // The MIME type for the uploaded metrics data.
234 const char kMimeType
[] = "application/vnd.chrome.uma";
236 enum ResponseStatus
{
239 BAD_REQUEST
, // Invalid syntax or log too large.
241 NUM_RESPONSE_STATUSES
244 ResponseStatus
ResponseCodeToStatus(int response_code
) {
245 switch (response_code
) {
253 return UNKNOWN_FAILURE
;
257 void MarkAppCleanShutdownAndCommit(PrefService
* local_state
) {
258 local_state
->SetBoolean(metrics::prefs::kStabilityExitedCleanly
, true);
259 local_state
->SetInteger(metrics::prefs::kStabilityExecutionPhase
,
260 MetricsService::SHUTDOWN_COMPLETE
);
261 // Start writing right away (write happens on a different thread).
262 local_state
->CommitPendingWrite();
268 SyntheticTrialGroup::SyntheticTrialGroup(uint32 trial
, uint32 group
) {
273 SyntheticTrialGroup::~SyntheticTrialGroup() {
277 MetricsService::ShutdownCleanliness
MetricsService::clean_shutdown_status_
=
278 MetricsService::CLEANLY_SHUTDOWN
;
280 MetricsService::ExecutionPhase
MetricsService::execution_phase_
=
281 MetricsService::UNINITIALIZED_PHASE
;
284 void MetricsService::RegisterPrefs(PrefRegistrySimple
* registry
) {
285 DCHECK(IsSingleThreaded());
286 metrics::MetricsStateManager::RegisterPrefs(registry
);
287 MetricsLog::RegisterPrefs(registry
);
289 registry
->RegisterInt64Pref(metrics::prefs::kInstallDate
, 0);
291 registry
->RegisterInt64Pref(metrics::prefs::kStabilityLaunchTimeSec
, 0);
292 registry
->RegisterInt64Pref(metrics::prefs::kStabilityLastTimestampSec
, 0);
293 registry
->RegisterStringPref(metrics::prefs::kStabilityStatsVersion
,
295 registry
->RegisterInt64Pref(metrics::prefs::kStabilityStatsBuildTime
, 0);
296 registry
->RegisterBooleanPref(metrics::prefs::kStabilityExitedCleanly
, true);
297 registry
->RegisterIntegerPref(metrics::prefs::kStabilityExecutionPhase
,
298 UNINITIALIZED_PHASE
);
299 registry
->RegisterBooleanPref(metrics::prefs::kStabilitySessionEndCompleted
,
301 registry
->RegisterIntegerPref(metrics::prefs::kMetricsSessionID
, -1);
303 registry
->RegisterListPref(metrics::prefs::kMetricsInitialLogs
);
304 registry
->RegisterListPref(metrics::prefs::kMetricsOngoingLogs
);
306 registry
->RegisterInt64Pref(metrics::prefs::kUninstallLaunchCount
, 0);
307 registry
->RegisterInt64Pref(metrics::prefs::kUninstallMetricsUptimeSec
, 0);
310 MetricsService::MetricsService(metrics::MetricsStateManager
* state_manager
,
311 metrics::MetricsServiceClient
* client
,
312 PrefService
* local_state
)
313 : log_manager_(local_state
, kUploadLogAvoidRetransmitSize
),
314 histogram_snapshot_manager_(this),
315 state_manager_(state_manager
),
317 local_state_(local_state
),
318 recording_active_(false),
319 reporting_active_(false),
320 test_mode_active_(false),
322 has_initial_stability_log_(false),
323 log_upload_in_progress_(false),
324 idle_since_last_transmission_(false),
326 self_ptr_factory_(this),
327 state_saver_factory_(this) {
328 DCHECK(IsSingleThreaded());
329 DCHECK(state_manager_
);
331 DCHECK(local_state_
);
333 // Set the install date if this is our first run.
334 int64 install_date
= local_state_
->GetInt64(metrics::prefs::kInstallDate
);
335 if (install_date
== 0) {
336 local_state_
->SetInt64(metrics::prefs::kInstallDate
,
337 base::Time::Now().ToTimeT());
341 MetricsService::~MetricsService() {
345 void MetricsService::InitializeMetricsRecordingState() {
346 InitializeMetricsState();
348 base::Closure callback
= base::Bind(&MetricsService::StartScheduledUpload
,
349 self_ptr_factory_
.GetWeakPtr());
350 scheduler_
.reset(new MetricsReportingScheduler(callback
));
353 void MetricsService::Start() {
354 HandleIdleSinceLastTransmission(false);
359 bool MetricsService::StartIfMetricsReportingEnabled() {
360 const bool enabled
= state_manager_
->IsMetricsReportingEnabled();
366 void MetricsService::StartRecordingForTests() {
367 test_mode_active_
= true;
372 void MetricsService::Stop() {
373 HandleIdleSinceLastTransmission(false);
378 void MetricsService::EnableReporting() {
379 if (reporting_active_
)
381 reporting_active_
= true;
382 StartSchedulerIfNecessary();
385 void MetricsService::DisableReporting() {
386 reporting_active_
= false;
389 std::string
MetricsService::GetClientId() {
390 return state_manager_
->client_id();
393 int64
MetricsService::GetInstallDate() {
394 return local_state_
->GetInt64(metrics::prefs::kInstallDate
);
397 scoped_ptr
<const base::FieldTrial::EntropyProvider
>
398 MetricsService::CreateEntropyProvider() {
399 // TODO(asvitkine): Refactor the code so that MetricsService does not expose
401 return state_manager_
->CreateEntropyProvider();
404 void MetricsService::EnableRecording() {
405 DCHECK(IsSingleThreaded());
407 if (recording_active_
)
409 recording_active_
= true;
411 state_manager_
->ForceClientIdCreation();
412 client_
->SetMetricsClientId(state_manager_
->client_id());
413 if (!log_manager_
.current_log())
416 for (size_t i
= 0; i
< metrics_providers_
.size(); ++i
)
417 metrics_providers_
[i
]->OnRecordingEnabled();
419 base::RemoveActionCallback(action_callback_
);
420 action_callback_
= base::Bind(&MetricsService::OnUserAction
,
421 base::Unretained(this));
422 base::AddActionCallback(action_callback_
);
425 void MetricsService::DisableRecording() {
426 DCHECK(IsSingleThreaded());
428 if (!recording_active_
)
430 recording_active_
= false;
432 base::RemoveActionCallback(action_callback_
);
434 for (size_t i
= 0; i
< metrics_providers_
.size(); ++i
)
435 metrics_providers_
[i
]->OnRecordingDisabled();
437 PushPendingLogsToPersistentStorage();
440 bool MetricsService::recording_active() const {
441 DCHECK(IsSingleThreaded());
442 return recording_active_
;
445 bool MetricsService::reporting_active() const {
446 DCHECK(IsSingleThreaded());
447 return reporting_active_
;
450 void MetricsService::RecordDelta(const base::HistogramBase
& histogram
,
451 const base::HistogramSamples
& snapshot
) {
452 log_manager_
.current_log()->RecordHistogramDelta(histogram
.histogram_name(),
456 void MetricsService::InconsistencyDetected(
457 base::HistogramBase::Inconsistency problem
) {
458 UMA_HISTOGRAM_ENUMERATION("Histogram.InconsistenciesBrowser",
459 problem
, base::HistogramBase::NEVER_EXCEEDED_VALUE
);
462 void MetricsService::UniqueInconsistencyDetected(
463 base::HistogramBase::Inconsistency problem
) {
464 UMA_HISTOGRAM_ENUMERATION("Histogram.InconsistenciesBrowserUnique",
465 problem
, base::HistogramBase::NEVER_EXCEEDED_VALUE
);
468 void MetricsService::InconsistencyDetectedInLoggedCount(int amount
) {
469 UMA_HISTOGRAM_COUNTS("Histogram.InconsistentSnapshotBrowser",
473 void MetricsService::HandleIdleSinceLastTransmission(bool in_idle
) {
474 // If there wasn't a lot of action, maybe the computer was asleep, in which
475 // case, the log transmissions should have stopped. Here we start them up
477 if (!in_idle
&& idle_since_last_transmission_
)
478 StartSchedulerIfNecessary();
479 idle_since_last_transmission_
= in_idle
;
482 void MetricsService::OnApplicationNotIdle() {
483 if (recording_active_
)
484 HandleIdleSinceLastTransmission(false);
487 void MetricsService::RecordStartOfSessionEnd() {
489 RecordBooleanPrefValue(metrics::prefs::kStabilitySessionEndCompleted
, false);
492 void MetricsService::RecordCompletedSessionEnd() {
494 RecordBooleanPrefValue(metrics::prefs::kStabilitySessionEndCompleted
, true);
497 #if defined(OS_ANDROID) || defined(OS_IOS)
498 void MetricsService::OnAppEnterBackground() {
501 MarkAppCleanShutdownAndCommit(local_state_
);
503 // At this point, there's no way of knowing when the process will be
504 // killed, so this has to be treated similar to a shutdown, closing and
505 // persisting all logs. Unlinke a shutdown, the state is primed to be ready
506 // to continue logging and uploading if the process does return.
507 if (recording_active() && state_
>= SENDING_INITIAL_STABILITY_LOG
) {
508 PushPendingLogsToPersistentStorage();
509 // Persisting logs closes the current log, so start recording a new log
510 // immediately to capture any background work that might be done before the
511 // process is killed.
516 void MetricsService::OnAppEnterForeground() {
517 local_state_
->SetBoolean(metrics::prefs::kStabilityExitedCleanly
, false);
518 StartSchedulerIfNecessary();
521 void MetricsService::LogNeedForCleanShutdown(PrefService
* local_state
) {
522 local_state
->SetBoolean(metrics::prefs::kStabilityExitedCleanly
, false);
523 // Redundant setting to be sure we call for a clean shutdown.
524 clean_shutdown_status_
= NEED_TO_SHUTDOWN
;
526 #endif // defined(OS_ANDROID) || defined(OS_IOS)
529 void MetricsService::SetExecutionPhase(ExecutionPhase execution_phase
,
530 PrefService
* local_state
) {
531 execution_phase_
= execution_phase
;
532 local_state
->SetInteger(metrics::prefs::kStabilityExecutionPhase
,
536 void MetricsService::RecordBreakpadRegistration(bool success
) {
538 IncrementPrefValue(metrics::prefs::kStabilityBreakpadRegistrationFail
);
540 IncrementPrefValue(metrics::prefs::kStabilityBreakpadRegistrationSuccess
);
543 void MetricsService::RecordBreakpadHasDebugger(bool has_debugger
) {
545 IncrementPrefValue(metrics::prefs::kStabilityDebuggerNotPresent
);
547 IncrementPrefValue(metrics::prefs::kStabilityDebuggerPresent
);
550 //------------------------------------------------------------------------------
552 //------------------------------------------------------------------------------
555 //------------------------------------------------------------------------------
556 // Initialization methods
558 void MetricsService::InitializeMetricsState() {
559 local_state_
->SetString(metrics::prefs::kStabilityStatsVersion
,
560 client_
->GetVersionString());
561 local_state_
->SetInt64(metrics::prefs::kStabilityStatsBuildTime
,
562 MetricsLog::GetBuildTime());
564 log_manager_
.LoadPersistedUnsentLogs();
566 session_id_
= local_state_
->GetInteger(metrics::prefs::kMetricsSessionID
);
568 if (!local_state_
->GetBoolean(metrics::prefs::kStabilityExitedCleanly
)) {
569 IncrementPrefValue(metrics::prefs::kStabilityCrashCount
);
570 // Reset flag, and wait until we call LogNeedForCleanShutdown() before
572 local_state_
->SetBoolean(metrics::prefs::kStabilityExitedCleanly
, true);
574 // TODO(rtenneti): On windows, consider saving/getting execution_phase from
576 int execution_phase
=
577 local_state_
->GetInteger(metrics::prefs::kStabilityExecutionPhase
);
578 UMA_HISTOGRAM_SPARSE_SLOWLY("Chrome.Browser.CrashedExecutionPhase",
581 // If the previous session didn't exit cleanly, then prepare an initial
582 // stability log if UMA is enabled.
583 if (state_manager_
->IsMetricsReportingEnabled())
584 PrepareInitialStabilityLog();
587 // Update session ID.
589 local_state_
->SetInteger(metrics::prefs::kMetricsSessionID
, session_id_
);
591 // Stability bookkeeping
592 IncrementPrefValue(metrics::prefs::kStabilityLaunchCount
);
594 DCHECK_EQ(UNINITIALIZED_PHASE
, execution_phase_
);
595 SetExecutionPhase(START_METRICS_RECORDING
, local_state_
);
597 if (!local_state_
->GetBoolean(
598 metrics::prefs::kStabilitySessionEndCompleted
)) {
599 IncrementPrefValue(metrics::prefs::kStabilityIncompleteSessionEndCount
);
600 // This is marked false when we get a WM_ENDSESSION.
601 local_state_
->SetBoolean(metrics::prefs::kStabilitySessionEndCompleted
,
605 // Call GetUptimes() for the first time, thus allowing all later calls
606 // to record incremental uptimes accurately.
607 base::TimeDelta ignored_uptime_parameter
;
608 base::TimeDelta startup_uptime
;
609 GetUptimes(local_state_
, &startup_uptime
, &ignored_uptime_parameter
);
610 DCHECK_EQ(0, startup_uptime
.InMicroseconds());
611 // For backwards compatibility, leave this intact in case Omaha is checking
612 // them. metrics::prefs::kStabilityLastTimestampSec may also be useless now.
613 // TODO(jar): Delete these if they have no uses.
614 local_state_
->SetInt64(metrics::prefs::kStabilityLaunchTimeSec
,
615 base::Time::Now().ToTimeT());
617 // Bookkeeping for the uninstall metrics.
618 IncrementLongPrefsValue(metrics::prefs::kUninstallLaunchCount
);
620 // Kick off the process of saving the state (so the uptime numbers keep
621 // getting updated) every n minutes.
622 ScheduleNextStateSave();
625 void MetricsService::OnUserAction(const std::string
& action
) {
626 if (!ShouldLogEvents())
629 log_manager_
.current_log()->RecordUserAction(action
);
630 HandleIdleSinceLastTransmission(false);
633 void MetricsService::FinishedGatheringInitialMetrics() {
634 DCHECK_EQ(INIT_TASK_SCHEDULED
, state_
);
635 state_
= INIT_TASK_DONE
;
637 // Create the initial log.
638 if (!initial_metrics_log_
.get()) {
639 initial_metrics_log_
= CreateLog(MetricsLog::ONGOING_LOG
);
640 NotifyOnDidCreateMetricsLog();
643 scheduler_
->InitTaskComplete();
646 void MetricsService::GetUptimes(PrefService
* pref
,
647 base::TimeDelta
* incremental_uptime
,
648 base::TimeDelta
* uptime
) {
649 base::TimeTicks now
= base::TimeTicks::Now();
650 // If this is the first call, init |first_updated_time_| and
651 // |last_updated_time_|.
652 if (last_updated_time_
.is_null()) {
653 first_updated_time_
= now
;
654 last_updated_time_
= now
;
656 *incremental_uptime
= now
- last_updated_time_
;
657 *uptime
= now
- first_updated_time_
;
658 last_updated_time_
= now
;
660 const int64 incremental_time_secs
= incremental_uptime
->InSeconds();
661 if (incremental_time_secs
> 0) {
662 int64 metrics_uptime
=
663 pref
->GetInt64(metrics::prefs::kUninstallMetricsUptimeSec
);
664 metrics_uptime
+= incremental_time_secs
;
665 pref
->SetInt64(metrics::prefs::kUninstallMetricsUptimeSec
, metrics_uptime
);
669 void MetricsService::AddObserver(MetricsServiceObserver
* observer
) {
670 DCHECK(thread_checker_
.CalledOnValidThread());
671 observers_
.AddObserver(observer
);
674 void MetricsService::RemoveObserver(MetricsServiceObserver
* observer
) {
675 DCHECK(thread_checker_
.CalledOnValidThread());
676 observers_
.RemoveObserver(observer
);
679 void MetricsService::NotifyOnDidCreateMetricsLog() {
680 DCHECK(thread_checker_
.CalledOnValidThread());
682 MetricsServiceObserver
, observers_
, OnDidCreateMetricsLog());
683 for (size_t i
= 0; i
< metrics_providers_
.size(); ++i
)
684 metrics_providers_
[i
]->OnDidCreateMetricsLog();
687 //------------------------------------------------------------------------------
688 // State save methods
690 void MetricsService::ScheduleNextStateSave() {
691 state_saver_factory_
.InvalidateWeakPtrs();
693 base::MessageLoop::current()->PostDelayedTask(FROM_HERE
,
694 base::Bind(&MetricsService::SaveLocalState
,
695 state_saver_factory_
.GetWeakPtr()),
696 base::TimeDelta::FromMinutes(kSaveStateIntervalMinutes
));
699 void MetricsService::SaveLocalState() {
700 RecordCurrentState(local_state_
);
702 // TODO(jar):110021 Does this run down the batteries????
703 ScheduleNextStateSave();
707 //------------------------------------------------------------------------------
708 // Recording control methods
710 void MetricsService::OpenNewLog() {
711 DCHECK(!log_manager_
.current_log());
713 log_manager_
.BeginLoggingWithLog(CreateLog(MetricsLog::ONGOING_LOG
));
714 NotifyOnDidCreateMetricsLog();
715 if (state_
== INITIALIZED
) {
716 // We only need to schedule that run once.
717 state_
= INIT_TASK_SCHEDULED
;
719 base::MessageLoop::current()->PostDelayedTask(
721 base::Bind(&MetricsService::StartGatheringMetrics
,
722 self_ptr_factory_
.GetWeakPtr()),
723 base::TimeDelta::FromSeconds(kInitializationDelaySeconds
));
727 void MetricsService::StartGatheringMetrics() {
728 client_
->StartGatheringMetrics(
729 base::Bind(&MetricsService::FinishedGatheringInitialMetrics
,
730 self_ptr_factory_
.GetWeakPtr()));
733 void MetricsService::CloseCurrentLog() {
734 if (!log_manager_
.current_log())
737 // TODO(jar): Integrate bounds on log recording more consistently, so that we
738 // can stop recording logs that are too big much sooner.
739 if (log_manager_
.current_log()->num_events() > kEventLimit
) {
740 UMA_HISTOGRAM_COUNTS("UMA.Discarded Log Events",
741 log_manager_
.current_log()->num_events());
742 log_manager_
.DiscardCurrentLog();
743 OpenNewLog(); // Start trivial log to hold our histograms.
746 // Put incremental data (histogram deltas, and realtime stats deltas) at the
747 // end of all log transmissions (initial log handles this separately).
748 // RecordIncrementalStabilityElements only exists on the derived
750 MetricsLog
* current_log
= log_manager_
.current_log();
752 std::vector
<variations::ActiveGroupId
> synthetic_trials
;
753 GetCurrentSyntheticFieldTrials(&synthetic_trials
);
754 current_log
->RecordEnvironment(
755 metrics_providers_
.get(), synthetic_trials
, GetInstallDate());
756 base::TimeDelta incremental_uptime
;
757 base::TimeDelta uptime
;
758 GetUptimes(local_state_
, &incremental_uptime
, &uptime
);
759 current_log
->RecordStabilityMetrics(metrics_providers_
.get(),
760 incremental_uptime
, uptime
);
762 RecordCurrentHistograms();
763 current_log
->RecordGeneralMetrics(metrics_providers_
.get());
765 log_manager_
.FinishCurrentLog();
768 void MetricsService::PushPendingLogsToPersistentStorage() {
769 if (state_
< SENDING_INITIAL_STABILITY_LOG
)
770 return; // We didn't and still don't have time to get plugin list etc.
773 log_manager_
.PersistUnsentLogs();
775 // If there was a staged and/or current log, then there is now at least one
776 // log waiting to be uploaded.
777 if (log_manager_
.has_unsent_logs())
778 state_
= SENDING_OLD_LOGS
;
781 //------------------------------------------------------------------------------
782 // Transmission of logs methods
784 void MetricsService::StartSchedulerIfNecessary() {
785 // Never schedule cutting or uploading of logs in test mode.
786 if (test_mode_active_
)
789 // Even if reporting is disabled, the scheduler is needed to trigger the
790 // creation of the initial log, which must be done in order for any logs to be
791 // persisted on shutdown or backgrounding.
792 if (recording_active() &&
793 (reporting_active() || state_
< SENDING_INITIAL_STABILITY_LOG
)) {
798 void MetricsService::StartScheduledUpload() {
799 // If we're getting no notifications, then the log won't have much in it, and
800 // it's possible the computer is about to go to sleep, so don't upload and
801 // stop the scheduler.
802 // If recording has been turned off, the scheduler doesn't need to run.
803 // If reporting is off, proceed if the initial log hasn't been created, since
804 // that has to happen in order for logs to be cut and stored when persisting.
805 // TODO(stuartmorgan): Call Stop() on the scheduler when reporting and/or
806 // recording are turned off instead of letting it fire and then aborting.
807 if (idle_since_last_transmission_
||
808 !recording_active() ||
809 (!reporting_active() && state_
>= SENDING_INITIAL_STABILITY_LOG
)) {
811 scheduler_
->UploadCancelled();
815 // If the callback was to upload an old log, but there no longer is one,
816 // just report success back to the scheduler to begin the ongoing log
818 // TODO(stuartmorgan): Consider removing the distinction between
819 // SENDING_OLD_LOGS and SENDING_CURRENT_LOGS to simplify the state machine
820 // now that the log upload flow is the same for both modes.
821 if (state_
== SENDING_OLD_LOGS
&& !log_manager_
.has_unsent_logs()) {
822 state_
= SENDING_CURRENT_LOGS
;
823 scheduler_
->UploadFinished(true /* healthy */, false /* no unsent logs */);
826 // If there are unsent logs, send the next one. If not, start the asynchronous
827 // process of finalizing the current log for upload.
828 if (state_
== SENDING_OLD_LOGS
) {
829 DCHECK(log_manager_
.has_unsent_logs());
830 log_manager_
.StageNextLogForUpload();
833 client_
->CollectFinalMetrics(
834 base::Bind(&MetricsService::OnFinalLogInfoCollectionDone
,
835 self_ptr_factory_
.GetWeakPtr()));
839 void MetricsService::OnFinalLogInfoCollectionDone() {
840 // If somehow there is a log upload in progress, we return and hope things
841 // work out. The scheduler isn't informed since if this happens, the scheduler
842 // will get a response from the upload.
843 DCHECK(!log_upload_in_progress_
);
844 if (log_upload_in_progress_
)
847 // Abort if metrics were turned off during the final info gathering.
848 if (!recording_active()) {
850 scheduler_
->UploadCancelled();
856 // If logs shouldn't be uploaded, stop here. It's important that this check
857 // be after StageNewLog(), otherwise the previous logs will never be loaded,
858 // and thus the open log won't be persisted.
859 // TODO(stuartmorgan): This is unnecessarily complicated; restructure loading
860 // of previous logs to not require running part of the upload logic.
861 // http://crbug.com/157337
862 if (!reporting_active()) {
864 scheduler_
->UploadCancelled();
871 void MetricsService::StageNewLog() {
872 if (log_manager_
.has_staged_log())
877 case INIT_TASK_SCHEDULED
: // We should be further along by now.
882 if (has_initial_stability_log_
) {
883 // There's an initial stability log, ready to send.
884 log_manager_
.StageNextLogForUpload();
885 has_initial_stability_log_
= false;
886 state_
= SENDING_INITIAL_STABILITY_LOG
;
888 PrepareInitialMetricsLog();
889 state_
= SENDING_INITIAL_METRICS_LOG
;
893 case SENDING_OLD_LOGS
:
894 NOTREACHED(); // Shouldn't be staging a new log during old log sending.
897 case SENDING_CURRENT_LOGS
:
900 log_manager_
.StageNextLogForUpload();
908 DCHECK(log_manager_
.has_staged_log());
911 void MetricsService::PrepareInitialStabilityLog() {
912 DCHECK_EQ(INITIALIZED
, state_
);
913 DCHECK_NE(0, local_state_
->GetInteger(metrics::prefs::kStabilityCrashCount
));
915 scoped_ptr
<MetricsLog
> initial_stability_log(
916 CreateLog(MetricsLog::INITIAL_STABILITY_LOG
));
918 // Do not call NotifyOnDidCreateMetricsLog here because the stability
919 // log describes stats from the _previous_ session.
921 if (!initial_stability_log
->LoadSavedEnvironmentFromPrefs())
924 log_manager_
.PauseCurrentLog();
925 log_manager_
.BeginLoggingWithLog(initial_stability_log
.Pass());
927 // Note: Some stability providers may record stability stats via histograms,
928 // so this call has to be after BeginLoggingWithLog().
929 log_manager_
.current_log()->RecordStabilityMetrics(
930 metrics_providers_
.get(), base::TimeDelta(), base::TimeDelta());
931 RecordCurrentStabilityHistograms();
933 // Note: RecordGeneralMetrics() intentionally not called since this log is for
934 // stability stats from a previous session only.
936 log_manager_
.FinishCurrentLog();
937 log_manager_
.ResumePausedLog();
939 // Store unsent logs, including the stability log that was just saved, so
940 // that they're not lost in case of a crash before upload time.
941 log_manager_
.PersistUnsentLogs();
943 has_initial_stability_log_
= true;
946 void MetricsService::PrepareInitialMetricsLog() {
947 DCHECK(state_
== INIT_TASK_DONE
|| state_
== SENDING_INITIAL_STABILITY_LOG
);
949 std::vector
<variations::ActiveGroupId
> synthetic_trials
;
950 GetCurrentSyntheticFieldTrials(&synthetic_trials
);
951 initial_metrics_log_
->RecordEnvironment(metrics_providers_
.get(),
954 base::TimeDelta incremental_uptime
;
955 base::TimeDelta uptime
;
956 GetUptimes(local_state_
, &incremental_uptime
, &uptime
);
958 // Histograms only get written to the current log, so make the new log current
959 // before writing them.
960 log_manager_
.PauseCurrentLog();
961 log_manager_
.BeginLoggingWithLog(initial_metrics_log_
.Pass());
963 // Note: Some stability providers may record stability stats via histograms,
964 // so this call has to be after BeginLoggingWithLog().
965 MetricsLog
* current_log
= log_manager_
.current_log();
966 current_log
->RecordStabilityMetrics(metrics_providers_
.get(),
967 base::TimeDelta(), base::TimeDelta());
968 RecordCurrentHistograms();
970 current_log
->RecordGeneralMetrics(metrics_providers_
.get());
972 log_manager_
.FinishCurrentLog();
973 log_manager_
.ResumePausedLog();
975 // Store unsent logs, including the initial log that was just saved, so
976 // that they're not lost in case of a crash before upload time.
977 log_manager_
.PersistUnsentLogs();
979 DCHECK(!log_manager_
.has_staged_log());
980 log_manager_
.StageNextLogForUpload();
983 void MetricsService::SendStagedLog() {
984 DCHECK(log_manager_
.has_staged_log());
985 if (!log_manager_
.has_staged_log())
988 DCHECK(!log_upload_in_progress_
);
989 log_upload_in_progress_
= true;
991 if (!log_uploader_
) {
992 log_uploader_
= client_
->CreateUploader(
993 kServerUrl
, kMimeType
,
994 base::Bind(&MetricsService::OnLogUploadComplete
,
995 self_ptr_factory_
.GetWeakPtr()));
998 const std::string hash
=
999 base::HexEncode(log_manager_
.staged_log_hash().data(),
1000 log_manager_
.staged_log_hash().size());
1001 bool success
= log_uploader_
->UploadLog(log_manager_
.staged_log(), hash
);
1002 UMA_HISTOGRAM_BOOLEAN("UMA.UploadCreation", success
);
1004 // Skip this upload and hope things work out next time.
1005 log_manager_
.DiscardStagedLog();
1006 scheduler_
->UploadCancelled();
1007 log_upload_in_progress_
= false;
1011 HandleIdleSinceLastTransmission(true);
1015 void MetricsService::OnLogUploadComplete(int response_code
) {
1016 DCHECK(log_upload_in_progress_
);
1017 log_upload_in_progress_
= false;
1019 // Log a histogram to track response success vs. failure rates.
1020 UMA_HISTOGRAM_ENUMERATION("UMA.UploadResponseStatus.Protobuf",
1021 ResponseCodeToStatus(response_code
),
1022 NUM_RESPONSE_STATUSES
);
1024 bool upload_succeeded
= response_code
== 200;
1026 // Provide boolean for error recovery (allow us to ignore response_code).
1027 bool discard_log
= false;
1028 const size_t log_size
= log_manager_
.staged_log().length();
1029 if (!upload_succeeded
&& log_size
> kUploadLogAvoidRetransmitSize
) {
1030 UMA_HISTOGRAM_COUNTS("UMA.Large Rejected Log was Discarded",
1031 static_cast<int>(log_size
));
1033 } else if (response_code
== 400) {
1034 // Bad syntax. Retransmission won't work.
1038 if (upload_succeeded
|| discard_log
) {
1039 log_manager_
.DiscardStagedLog();
1040 // Store the updated list to disk now that the removed log is uploaded.
1041 log_manager_
.PersistUnsentLogs();
1044 if (!log_manager_
.has_staged_log()) {
1046 case SENDING_INITIAL_STABILITY_LOG
:
1047 PrepareInitialMetricsLog();
1049 state_
= SENDING_INITIAL_METRICS_LOG
;
1052 case SENDING_INITIAL_METRICS_LOG
:
1053 state_
= log_manager_
.has_unsent_logs() ? SENDING_OLD_LOGS
1054 : SENDING_CURRENT_LOGS
;
1057 case SENDING_OLD_LOGS
:
1058 if (!log_manager_
.has_unsent_logs())
1059 state_
= SENDING_CURRENT_LOGS
;
1062 case SENDING_CURRENT_LOGS
:
1070 if (log_manager_
.has_unsent_logs())
1071 DCHECK_LT(state_
, SENDING_CURRENT_LOGS
);
1074 // Error 400 indicates a problem with the log, not with the server, so
1075 // don't consider that a sign that the server is in trouble.
1076 bool server_is_healthy
= upload_succeeded
|| response_code
== 400;
1077 // Don't notify the scheduler that the upload is finished if we've only sent
1078 // the initial stability log, but not yet the initial metrics log (treat the
1079 // two as a single unit of work as far as the scheduler is concerned).
1080 if (state_
!= SENDING_INITIAL_METRICS_LOG
) {
1081 scheduler_
->UploadFinished(server_is_healthy
,
1082 log_manager_
.has_unsent_logs());
1085 if (server_is_healthy
)
1086 client_
->OnLogUploadComplete();
1089 void MetricsService::IncrementPrefValue(const char* path
) {
1090 int value
= local_state_
->GetInteger(path
);
1091 local_state_
->SetInteger(path
, value
+ 1);
1094 void MetricsService::IncrementLongPrefsValue(const char* path
) {
1095 int64 value
= local_state_
->GetInt64(path
);
1096 local_state_
->SetInt64(path
, value
+ 1);
1099 bool MetricsService::UmaMetricsProperlyShutdown() {
1100 CHECK(clean_shutdown_status_
== CLEANLY_SHUTDOWN
||
1101 clean_shutdown_status_
== NEED_TO_SHUTDOWN
);
1102 return clean_shutdown_status_
== CLEANLY_SHUTDOWN
;
1105 void MetricsService::RegisterSyntheticFieldTrial(
1106 const SyntheticTrialGroup
& trial
) {
1107 for (size_t i
= 0; i
< synthetic_trial_groups_
.size(); ++i
) {
1108 if (synthetic_trial_groups_
[i
].id
.name
== trial
.id
.name
) {
1109 if (synthetic_trial_groups_
[i
].id
.group
!= trial
.id
.group
) {
1110 synthetic_trial_groups_
[i
].id
.group
= trial
.id
.group
;
1111 synthetic_trial_groups_
[i
].start_time
= base::TimeTicks::Now();
1117 SyntheticTrialGroup trial_group
= trial
;
1118 trial_group
.start_time
= base::TimeTicks::Now();
1119 synthetic_trial_groups_
.push_back(trial_group
);
1122 void MetricsService::RegisterMetricsProvider(
1123 scoped_ptr
<metrics::MetricsProvider
> provider
) {
1124 DCHECK_EQ(INITIALIZED
, state_
);
1125 metrics_providers_
.push_back(provider
.release());
1128 void MetricsService::CheckForClonedInstall(
1129 scoped_refptr
<base::SingleThreadTaskRunner
> task_runner
) {
1130 state_manager_
->CheckForClonedInstall(task_runner
);
1133 void MetricsService::GetCurrentSyntheticFieldTrials(
1134 std::vector
<variations::ActiveGroupId
>* synthetic_trials
) {
1135 DCHECK(synthetic_trials
);
1136 synthetic_trials
->clear();
1137 const MetricsLog
* current_log
= log_manager_
.current_log();
1138 for (size_t i
= 0; i
< synthetic_trial_groups_
.size(); ++i
) {
1139 if (synthetic_trial_groups_
[i
].start_time
<= current_log
->creation_time())
1140 synthetic_trials
->push_back(synthetic_trial_groups_
[i
].id
);
1144 scoped_ptr
<MetricsLog
> MetricsService::CreateLog(MetricsLog::LogType log_type
) {
1145 return make_scoped_ptr(new MetricsLog(state_manager_
->client_id(),
1152 void MetricsService::RecordCurrentHistograms() {
1153 DCHECK(log_manager_
.current_log());
1154 histogram_snapshot_manager_
.PrepareDeltas(
1155 base::Histogram::kNoFlags
, base::Histogram::kUmaTargetedHistogramFlag
);
1158 void MetricsService::RecordCurrentStabilityHistograms() {
1159 DCHECK(log_manager_
.current_log());
1160 histogram_snapshot_manager_
.PrepareDeltas(
1161 base::Histogram::kNoFlags
, base::Histogram::kUmaStabilityHistogramFlag
);
1164 void MetricsService::LogCleanShutdown() {
1165 // Redundant hack to write pref ASAP.
1166 MarkAppCleanShutdownAndCommit(local_state_
);
1168 // Redundant setting to assure that we always reset this value at shutdown
1169 // (and that we don't use some alternate path, and not call LogCleanShutdown).
1170 clean_shutdown_status_
= CLEANLY_SHUTDOWN
;
1172 RecordBooleanPrefValue(metrics::prefs::kStabilityExitedCleanly
, true);
1173 local_state_
->SetInteger(metrics::prefs::kStabilityExecutionPhase
,
1174 MetricsService::SHUTDOWN_COMPLETE
);
1177 bool MetricsService::ShouldLogEvents() {
1178 // We simply don't log events to UMA if there is a single incognito
1179 // session visible. The problem is that we always notify using the orginal
1180 // profile in order to simplify notification processing.
1181 return !client_
->IsOffTheRecordSessionActive();
1184 void MetricsService::RecordBooleanPrefValue(const char* path
, bool value
) {
1185 DCHECK(IsSingleThreaded());
1186 local_state_
->SetBoolean(path
, value
);
1187 RecordCurrentState(local_state_
);
1190 void MetricsService::RecordCurrentState(PrefService
* pref
) {
1191 pref
->SetInt64(metrics::prefs::kStabilityLastTimestampSec
,
1192 base::Time::Now().ToTimeT());
1195 } // namespace metrics