blob: 4e66607218c5ec3eb8c3ee9ac3f68a416b890a28 [file] [log] [blame]
license.botbf09a502008-08-24 00:55:551// Copyright (c) 2006-2008 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.
initial.commit09911bf2008-07-26 23:55:294
5
6
7//------------------------------------------------------------------------------
8// Description of the life cycle of a instance of MetricsService.
9//
10// OVERVIEW
11//
12// A MetricsService instance is typically created at application startup. It
13// is the central controller for the acquisition of log data, and the automatic
14// transmission of that log data to an external server. Its major job is to
15// manage logs, grouping them for transmission, and transmitting them. As part
16// of its grouping, MS finalizes logs by including some just-in-time gathered
17// memory statistics, snapshotting the current stats of numerous histograms,
18// closing the logs, translating to XML text, and compressing the results for
19// transmission. Transmission includes submitting a compressed log as data in a
[email protected]281d2882009-01-20 20:32:4220// URL-post, and retransmitting (or retaining at process termination) if the
initial.commit09911bf2008-07-26 23:55:2921// attempted transmission failed. Retention across process terminations is done
22// using the the PrefServices facilities. The format for the retained
23// logs (ones that never got transmitted) is always the uncompressed textual
24// representation.
25//
[email protected]281d2882009-01-20 20:32:4226// Logs fall into one of two categories: "initial logs," and "ongoing logs."
27// There is at most one initial log sent for each complete run of the chromium
initial.commit09911bf2008-07-26 23:55:2928// product (from startup, to browser shutdown). An initial log is generally
29// transmitted some short time (1 minute?) after startup, and includes stats
30// such as recent crash info, the number and types of plugins, etc. The
[email protected]281d2882009-01-20 20:32:4231// external server's response to the initial log conceptually tells this MS if
32// it should continue transmitting logs (during this session). The server
33// response can actually be much more detailed, and always includes (at a
34// minimum) how often additional ongoing logs should be sent.
initial.commit09911bf2008-07-26 23:55:2935//
36// After the above initial log, a series of ongoing logs will be transmitted.
37// The first ongoing log actually begins to accumulate information stating when
38// the MS was first constructed. Note that even though the initial log is
39// commonly sent a full minute after startup, the initial log does not include
40// much in the way of user stats. The most common interlog period (delay)
[email protected]0b33f80b2008-12-17 21:34:3641// is 20 minutes. That time period starts when the first user action causes a
initial.commit09911bf2008-07-26 23:55:2942// logging event. This means that if there is no user action, there may be long
[email protected]281d2882009-01-20 20:32:4243// periods without any (ongoing) log transmissions. Ongoing logs typically
initial.commit09911bf2008-07-26 23:55:2944// contain very detailed records of user activities (ex: opened tab, closed
45// tab, fetched URL, maximized window, etc.) In addition, just before an
46// ongoing log is closed out, a call is made to gather memory statistics. Those
47// memory statistics are deposited into a histogram, and the log finalization
48// code is then called. In the finalization, a call to a Histogram server
49// acquires a list of all local histograms that have been flagged for upload
[email protected]281d2882009-01-20 20:32:4250// to the UMA server. The finalization also acquires a the most recent number
51// of page loads, along with any counts of renderer or plugin crashes.
initial.commit09911bf2008-07-26 23:55:2952//
53// When the browser shuts down, there will typically be a fragment of an ongoing
54// log that has not yet been transmitted. At shutdown time, that fragment
55// is closed (including snapshotting histograms), and converted to text. Note
56// that memory stats are not gathered during shutdown, as gathering *might* be
57// too time consuming. The textual representation of the fragment of the
58// ongoing log is then stored persistently as a string in the PrefServices, for
59// potential transmission during a future run of the product.
60//
61// There are two slightly abnormal shutdown conditions. There is a
62// "disconnected scenario," and a "really fast startup and shutdown" scenario.
63// In the "never connected" situation, the user has (during the running of the
64// process) never established an internet connection. As a result, attempts to
65// transmit the initial log have failed, and a lot(?) of data has accumulated in
66// the ongoing log (which didn't yet get closed, because there was never even a
67// contemplation of sending it). There is also a kindred "lost connection"
68// situation, where a loss of connection prevented an ongoing log from being
69// transmitted, and a (still open) log was stuck accumulating a lot(?) of data,
70// while the earlier log retried its transmission. In both of these
71// disconnected situations, two logs need to be, and are, persistently stored
72// for future transmission.
73//
74// The other unusual shutdown condition, termed "really fast startup and
75// shutdown," involves the deliberate user termination of the process before
76// the initial log is even formed or transmitted. In that situation, no logging
77// is done, but the historical crash statistics remain (unlogged) for inclusion
78// in a future run's initial log. (i.e., we don't lose crash stats).
79//
80// With the above overview, we can now describe the state machine's various
81// stats, based on the State enum specified in the state_ member. Those states
82// are:
83//
84// INITIALIZED, // Constructor was called.
[email protected]28ab7f92009-01-06 21:39:0485// PLUGIN_LIST_REQUESTED, // Waiting for plugin list to be loaded.
initial.commit09911bf2008-07-26 23:55:2986// PLUGIN_LIST_ARRIVED, // Waiting for timer to send initial log.
87// INITIAL_LOG_READY, // Initial log generated, and waiting for reply.
88// SEND_OLD_INITIAL_LOGS, // Sending unsent logs from previous session.
89// SENDING_OLD_LOGS, // Sending unsent logs from previous session.
90// SENDING_CURRENT_LOGS, // Sending standard current logs as they accrue.
91//
92// In more detail, we have:
93//
94// INITIALIZED, // Constructor was called.
95// The MS has been constructed, but has taken no actions to compose the
96// initial log.
97//
[email protected]28ab7f92009-01-06 21:39:0498// PLUGIN_LIST_REQUESTED, // Waiting for plugin list to be loaded.
initial.commit09911bf2008-07-26 23:55:2999// Typically about 30 seconds after startup, a task is sent to a second thread
100// to get the list of plugins. That task will (when complete) make an async
101// callback (via a Task) to indicate the completion.
102//
103// PLUGIN_LIST_ARRIVED, // Waiting for timer to send initial log.
104// The callback has arrived, and it is now possible for an initial log to be
105// created. This callback typically arrives back less than one second after
106// the task is dispatched.
107//
108// INITIAL_LOG_READY, // Initial log generated, and waiting for reply.
109// This state is entered only after an initial log has been composed, and
110// prepared for transmission. It is also the case that any previously unsent
111// logs have been loaded into instance variables for possible transmission.
112//
113// SEND_OLD_INITIAL_LOGS, // Sending unsent logs from previous session.
114// This state indicates that the initial log for this session has been
115// successfully sent and it is now time to send any "initial logs" that were
116// saved from previous sessions. Most commonly, there are none, but all old
117// logs that were "initial logs" must be sent before this state is exited.
118//
119// SENDING_OLD_LOGS, // Sending unsent logs from previous session.
120// This state indicates that there are no more unsent initial logs, and now any
121// ongoing logs from previous sessions should be transmitted. All such logs
122// will be transmitted before exiting this state, and proceeding with ongoing
123// logs from the current session (see next state).
124//
125// SENDING_CURRENT_LOGS, // Sending standard current logs as they accrue.
[email protected]0b33f80b2008-12-17 21:34:36126// Current logs are being accumulated. Typically every 20 minutes a log is
initial.commit09911bf2008-07-26 23:55:29127// closed and finalized for transmission, at the same time as a new log is
128// started.
129//
130// The progression through the above states is simple, and sequential, in the
131// most common use cases. States proceed from INITIAL to SENDING_CURRENT_LOGS,
132// and remain in the latter until shutdown.
133//
134// The one unusual case is when the user asks that we stop logging. When that
135// happens, any pending (transmission in progress) log is pushed into the list
136// of old unsent logs (the appropriate list, depending on whether it is an
137// initial log, or an ongoing log). An addition, any log that is currently
138// accumulating is also finalized, and pushed into the unsent log list. With
[email protected]281d2882009-01-20 20:32:42139// those pushes performed, we regress back to the SEND_OLD_INITIAL_LOGS state in
initial.commit09911bf2008-07-26 23:55:29140// case the user enables log recording again during this session. This way
141// anything we have "pushed back" will be sent automatically if/when we progress
142// back to SENDING_CURRENT_LOG state.
143//
144// Also note that whenever the member variables containing unsent logs are
145// modified (i.e., when we send an old log), we mirror the list of logs into
146// the PrefServices. This ensures that IF we crash, we won't start up and
147// retransmit our old logs again.
148//
149// Due to race conditions, it is always possible that a log file could be sent
150// twice. For example, if a log file is sent, but not yet acknowledged by
151// the external server, and the user shuts down, then a copy of the log may be
152// saved for re-transmission. These duplicates could be filtered out server
[email protected]281d2882009-01-20 20:32:42153// side, but are not expected to be a significant problem.
initial.commit09911bf2008-07-26 23:55:29154//
155//
156//------------------------------------------------------------------------------
157
[email protected]dc6f4962009-02-13 01:25:50158#if defined(OS_WIN)
initial.commit09911bf2008-07-26 23:55:29159#include <windows.h>
[email protected]dc6f4962009-02-13 01:25:50160#endif
initial.commit09911bf2008-07-26 23:55:29161
[email protected]cd1adc22009-01-16 01:29:22162#include "chrome/browser/metrics/metrics_service.h"
initial.commit09911bf2008-07-26 23:55:29163
[email protected]690a99c2009-01-06 16:48:45164#include "base/file_path.h"
initial.commit09911bf2008-07-26 23:55:29165#include "base/histogram.h"
166#include "base/path_service.h"
[email protected]dc6f4962009-02-13 01:25:50167#include "base/platform_thread.h"
initial.commit09911bf2008-07-26 23:55:29168#include "base/string_util.h"
169#include "base/task.h"
[email protected]d8e41ed2008-09-11 15:22:32170#include "chrome/browser/bookmarks/bookmark_model.h"
initial.commit09911bf2008-07-26 23:55:29171#include "chrome/browser/browser.h"
172#include "chrome/browser/browser_list.h"
173#include "chrome/browser/browser_process.h"
174#include "chrome/browser/load_notification_details.h"
175#include "chrome/browser/memory_details.h"
initial.commit09911bf2008-07-26 23:55:29176#include "chrome/browser/profile.h"
[email protected]8c8657d62009-01-16 18:31:26177#include "chrome/browser/renderer_host/render_process_host.h"
[email protected]d54e03a52009-01-16 00:31:04178#include "chrome/browser/search_engines/template_url.h"
179#include "chrome/browser/search_engines/template_url_model.h"
[email protected]a27a9382009-02-11 23:55:10180#include "chrome/common/child_process_info.h"
initial.commit09911bf2008-07-26 23:55:29181#include "chrome/common/chrome_paths.h"
[email protected]252873ef2008-08-04 21:59:45182#include "chrome/common/libxml_utils.h"
[email protected]bfd04a62009-02-01 18:16:56183#include "chrome/common/notification_service.h"
initial.commit09911bf2008-07-26 23:55:29184#include "chrome/common/pref_names.h"
185#include "chrome/common/pref_service.h"
[email protected]e09ba552009-02-05 03:26:29186#include "chrome/common/render_messages.h"
initial.commit09911bf2008-07-26 23:55:29187#include "googleurl/src/gurl.h"
188#include "net/base/load_flags.h"
189#include "third_party/bzip2/bzlib.h"
190
[email protected]dc6f4962009-02-13 01:25:50191#if defined(OS_POSIX)
192// TODO(port): Move these headers above as they are ported.
193#include "chrome/common/temp_scaffolding_stubs.h"
194#else
195#include "chrome/browser/plugin_service.h"
196#include "chrome/installer/util/google_update_settings.h"
197#endif
198
[email protected]e1acf6f2008-10-27 20:43:33199using base::Time;
200using base::TimeDelta;
201
initial.commit09911bf2008-07-26 23:55:29202// Check to see that we're being called on only one thread.
203static bool IsSingleThreaded();
204
205static const char kMetricsURL[] =
[email protected]0acdfc42009-01-30 01:13:22206 "https://clients4.google.com/firefox/metrics/collect";
initial.commit09911bf2008-07-26 23:55:29207
208static const char kMetricsType[] = "application/vnd.mozilla.metrics.bz2";
209
210// The delay, in seconds, after startup before sending the first log message.
[email protected]252873ef2008-08-04 21:59:45211static const int kInitialInterlogDuration = 60; // one minute
212
213// The default maximum number of events in a log uploaded to the UMA server.
[email protected]0b33f80b2008-12-17 21:34:36214static const int kInitialEventLimit = 2400;
[email protected]68475e602008-08-22 03:21:15215
216// If an upload fails, and the transmission was over this byte count, then we
217// will discard the log, and not try to retransmit it. We also don't persist
218// the log to the prefs for transmission during the next chrome session if this
219// limit is exceeded.
220static const int kUploadLogAvoidRetransmitSize = 50000;
initial.commit09911bf2008-07-26 23:55:29221
222// When we have logs from previous Chrome sessions to send, how long should we
223// delay (in seconds) between each log transmission.
224static const int kUnsentLogDelay = 15; // 15 seconds
225
226// Minimum time a log typically exists before sending, in seconds.
227// This number is supplied by the server, but until we parse it out of a server
228// response, we use this duration to specify how long we should wait before
229// sending the next log. If the channel is busy, such as when there is a
230// failure during an attempt to transmit a previous log, then a log may wait
231// (and continue to accrue now log entries) for a much greater period of time.
[email protected]0eb34fee2009-01-21 08:04:38232static const int kMinSecondsPerLog = 20 * 60; // Twenty minutes.
initial.commit09911bf2008-07-26 23:55:29233
initial.commit09911bf2008-07-26 23:55:29234// When we don't succeed at transmitting a log to a server, we progressively
235// wait longer and longer before sending the next log. This backoff process
236// help reduce load on the server, and makes the amount of backoff vary between
237// clients so that a collision (server overload?) on retransmit is less likely.
238// The following is the constant we use to expand that inter-log duration.
239static const double kBackoff = 1.1;
240// We limit the maximum backoff to be no greater than some multiple of the
241// default kMinSecondsPerLog. The following is that maximum ratio.
242static const int kMaxBackoff = 10;
243
244// Interval, in seconds, between state saves.
245static const int kSaveStateInterval = 5 * 60; // five minutes
246
247// The number of "initial" logs we're willing to save, and hope to send during
248// a future Chrome session. Initial logs contain crash stats, and are pretty
249// small.
250static const size_t kMaxInitialLogsPersisted = 20;
251
252// The number of ongoing logs we're willing to save persistently, and hope to
[email protected]281d2882009-01-20 20:32:42253// send during a this or future sessions. Note that each log may be pretty
initial.commit09911bf2008-07-26 23:55:29254// large, as presumably the related "initial" log wasn't sent (probably nothing
255// was, as the user was probably off-line). As a result, the log probably kept
256// accumulating while the "initial" log was stalled (pending_), and couldn't be
257// sent. As a result, we don't want to save too many of these mega-logs.
258// A "standard shutdown" will create a small log, including just the data that
259// was not yet been transmitted, and that is normal (to have exactly one
260// ongoing_log_ at startup).
[email protected]281d2882009-01-20 20:32:42261static const size_t kMaxOngoingLogsPersisted = 8;
initial.commit09911bf2008-07-26 23:55:29262
263
264// Handles asynchronous fetching of memory details.
265// Will run the provided task after finished.
266class MetricsMemoryDetails : public MemoryDetails {
267 public:
268 explicit MetricsMemoryDetails(Task* completion) : completion_(completion) {}
269
270 virtual void OnDetailsAvailable() {
271 MessageLoop::current()->PostTask(FROM_HERE, completion_);
272 }
273
274 private:
275 Task* completion_;
276 DISALLOW_EVIL_CONSTRUCTORS(MetricsMemoryDetails);
277};
278
279class MetricsService::GetPluginListTaskComplete : public Task {
280 virtual void Run() {
281 g_browser_process->metrics_service()->OnGetPluginListTaskComplete();
282 }
283};
284
285class MetricsService::GetPluginListTask : public Task {
286 public:
287 explicit GetPluginListTask(MessageLoop* callback_loop)
288 : callback_loop_(callback_loop) {}
289
290 virtual void Run() {
291 std::vector<WebPluginInfo> plugins;
292 PluginService::GetInstance()->GetPlugins(false, &plugins);
293
294 callback_loop_->PostTask(FROM_HERE, new GetPluginListTaskComplete());
295 }
296
297 private:
298 MessageLoop* callback_loop_;
299};
300
301// static
302void MetricsService::RegisterPrefs(PrefService* local_state) {
303 DCHECK(IsSingleThreaded());
304 local_state->RegisterStringPref(prefs::kMetricsClientID, L"");
305 local_state->RegisterStringPref(prefs::kMetricsClientIDTimestamp, L"0");
306 local_state->RegisterStringPref(prefs::kStabilityLaunchTimeSec, L"0");
307 local_state->RegisterStringPref(prefs::kStabilityLastTimestampSec, L"0");
308 local_state->RegisterStringPref(prefs::kStabilityUptimeSec, L"0");
309 local_state->RegisterBooleanPref(prefs::kStabilityExitedCleanly, true);
310 local_state->RegisterBooleanPref(prefs::kStabilitySessionEndCompleted, true);
311 local_state->RegisterIntegerPref(prefs::kMetricsSessionID, -1);
312 local_state->RegisterIntegerPref(prefs::kStabilityLaunchCount, 0);
313 local_state->RegisterIntegerPref(prefs::kStabilityCrashCount, 0);
314 local_state->RegisterIntegerPref(prefs::kStabilityIncompleteSessionEndCount,
315 0);
316 local_state->RegisterIntegerPref(prefs::kStabilityPageLoadCount, 0);
317 local_state->RegisterIntegerPref(prefs::kSecurityRendererOnSboxDesktop, 0);
318 local_state->RegisterIntegerPref(prefs::kSecurityRendererOnDefaultDesktop, 0);
319 local_state->RegisterIntegerPref(prefs::kStabilityRendererCrashCount, 0);
320 local_state->RegisterIntegerPref(prefs::kStabilityRendererHangCount, 0);
[email protected]e73c01972008-08-13 00:18:24321 local_state->RegisterIntegerPref(prefs::kStabilityBreakpadRegistrationFail,
322 0);
323 local_state->RegisterIntegerPref(prefs::kStabilityBreakpadRegistrationSuccess,
324 0);
325 local_state->RegisterIntegerPref(prefs::kStabilityDebuggerPresent, 0);
326 local_state->RegisterIntegerPref(prefs::kStabilityDebuggerNotPresent, 0);
327
initial.commit09911bf2008-07-26 23:55:29328 local_state->RegisterDictionaryPref(prefs::kProfileMetrics);
329 local_state->RegisterIntegerPref(prefs::kNumBookmarksOnBookmarkBar, 0);
330 local_state->RegisterIntegerPref(prefs::kNumFoldersOnBookmarkBar, 0);
331 local_state->RegisterIntegerPref(prefs::kNumBookmarksInOtherBookmarkFolder,
332 0);
333 local_state->RegisterIntegerPref(prefs::kNumFoldersInOtherBookmarkFolder, 0);
334 local_state->RegisterIntegerPref(prefs::kNumKeywords, 0);
335 local_state->RegisterListPref(prefs::kMetricsInitialLogs);
336 local_state->RegisterListPref(prefs::kMetricsOngoingLogs);
337}
338
339MetricsService::MetricsService()
[email protected]d01b8732008-10-16 02:18:07340 : recording_active_(false),
341 reporting_active_(false),
342 user_permits_upload_(false),
343 server_permits_upload_(true),
344 state_(INITIALIZED),
initial.commit09911bf2008-07-26 23:55:29345 pending_log_(NULL),
346 pending_log_text_(""),
347 current_fetch_(NULL),
348 current_log_(NULL),
[email protected]d01b8732008-10-16 02:18:07349 idle_since_last_transmission_(false),
initial.commit09911bf2008-07-26 23:55:29350 next_window_id_(0),
351 log_sender_factory_(this),
352 state_saver_factory_(this),
353 logged_samples_(),
[email protected]252873ef2008-08-04 21:59:45354 interlog_duration_(TimeDelta::FromSeconds(kInitialInterlogDuration)),
[email protected]d01b8732008-10-16 02:18:07355 log_event_limit_(kInitialEventLimit),
initial.commit09911bf2008-07-26 23:55:29356 timer_pending_(false) {
357 DCHECK(IsSingleThreaded());
358 InitializeMetricsState();
359}
360
361MetricsService::~MetricsService() {
362 SetRecording(false);
[email protected]d8bc79bf2009-01-28 01:17:58363 if (pending_log_) {
364 delete pending_log_;
365 pending_log_ = NULL;
366 }
367 if (current_log_) {
368 delete current_log_;
369 current_log_ = NULL;
370 }
initial.commit09911bf2008-07-26 23:55:29371}
372
[email protected]d01b8732008-10-16 02:18:07373void MetricsService::SetUserPermitsUpload(bool enabled) {
374 HandleIdleSinceLastTransmission(false);
375 user_permits_upload_ = enabled;
376}
377
378void MetricsService::Start() {
379 SetRecording(true);
380 SetReporting(true);
381}
382
383void MetricsService::StartRecordingOnly() {
384 SetRecording(true);
385 SetReporting(false);
386}
387
388void MetricsService::Stop() {
389 SetReporting(false);
390 SetRecording(false);
391}
392
initial.commit09911bf2008-07-26 23:55:29393void MetricsService::SetRecording(bool enabled) {
394 DCHECK(IsSingleThreaded());
395
[email protected]d01b8732008-10-16 02:18:07396 if (enabled == recording_active_)
initial.commit09911bf2008-07-26 23:55:29397 return;
398
399 if (enabled) {
400 StartRecording();
401 ListenerRegistration(true);
402 } else {
403 // Turn off all observers.
404 ListenerRegistration(false);
405 PushPendingLogsToUnsentLists();
406 DCHECK(!pending_log());
407 if (state_ > INITIAL_LOG_READY && unsent_logs())
408 state_ = SEND_OLD_INITIAL_LOGS;
409 }
[email protected]d01b8732008-10-16 02:18:07410 recording_active_ = enabled;
initial.commit09911bf2008-07-26 23:55:29411}
412
[email protected]d01b8732008-10-16 02:18:07413bool MetricsService::recording_active() const {
initial.commit09911bf2008-07-26 23:55:29414 DCHECK(IsSingleThreaded());
[email protected]d01b8732008-10-16 02:18:07415 return recording_active_;
initial.commit09911bf2008-07-26 23:55:29416}
417
[email protected]d01b8732008-10-16 02:18:07418void MetricsService::SetReporting(bool enable) {
419 if (reporting_active_ != enable) {
420 reporting_active_ = enable;
421 if (reporting_active_)
initial.commit09911bf2008-07-26 23:55:29422 StartLogTransmissionTimer();
423 }
[email protected]d01b8732008-10-16 02:18:07424}
425
426bool MetricsService::reporting_active() const {
427 DCHECK(IsSingleThreaded());
428 return reporting_active_;
initial.commit09911bf2008-07-26 23:55:29429}
430
431void MetricsService::Observe(NotificationType type,
432 const NotificationSource& source,
433 const NotificationDetails& details) {
434 DCHECK(current_log_);
435 DCHECK(IsSingleThreaded());
436
437 if (!CanLogNotification(type, source, details))
438 return;
439
[email protected]bfd04a62009-02-01 18:16:56440 switch (type.value) {
441 case NotificationType::USER_ACTION:
initial.commit09911bf2008-07-26 23:55:29442 current_log_->RecordUserAction(*Details<const wchar_t*>(details).ptr());
443 break;
444
[email protected]bfd04a62009-02-01 18:16:56445 case NotificationType::BROWSER_OPENED:
446 case NotificationType::BROWSER_CLOSED:
initial.commit09911bf2008-07-26 23:55:29447 LogWindowChange(type, source, details);
448 break;
449
[email protected]bfd04a62009-02-01 18:16:56450 case NotificationType::TAB_PARENTED:
451 case NotificationType::TAB_CLOSING:
initial.commit09911bf2008-07-26 23:55:29452 LogWindowChange(type, source, details);
453 break;
454
[email protected]bfd04a62009-02-01 18:16:56455 case NotificationType::LOAD_STOP:
initial.commit09911bf2008-07-26 23:55:29456 LogLoadComplete(type, source, details);
457 break;
458
[email protected]bfd04a62009-02-01 18:16:56459 case NotificationType::LOAD_START:
initial.commit09911bf2008-07-26 23:55:29460 LogLoadStarted();
461 break;
462
[email protected]bfd04a62009-02-01 18:16:56463 case NotificationType::RENDERER_PROCESS_TERMINATED:
initial.commit09911bf2008-07-26 23:55:29464 if (!*Details<bool>(details).ptr())
465 LogRendererCrash();
466 break;
467
[email protected]bfd04a62009-02-01 18:16:56468 case NotificationType::RENDERER_PROCESS_HANG:
initial.commit09911bf2008-07-26 23:55:29469 LogRendererHang();
470 break;
471
[email protected]bfd04a62009-02-01 18:16:56472 case NotificationType::RENDERER_PROCESS_IN_SBOX:
initial.commit09911bf2008-07-26 23:55:29473 LogRendererInSandbox(*Details<bool>(details).ptr());
474 break;
475
[email protected]a27a9382009-02-11 23:55:10476 case NotificationType::CHILD_PROCESS_HOST_CONNECTED:
477 case NotificationType::CHILD_PROCESS_CRASHED:
478 case NotificationType::CHILD_INSTANCE_CREATED:
479 LogChildProcessChange(type, source, details);
initial.commit09911bf2008-07-26 23:55:29480 break;
481
[email protected]bfd04a62009-02-01 18:16:56482 case NotificationType::TEMPLATE_URL_MODEL_LOADED:
initial.commit09911bf2008-07-26 23:55:29483 LogKeywords(Source<TemplateURLModel>(source).ptr());
484 break;
485
[email protected]bfd04a62009-02-01 18:16:56486 case NotificationType::OMNIBOX_OPENED_URL:
initial.commit09911bf2008-07-26 23:55:29487 current_log_->RecordOmniboxOpenedURL(
488 *Details<AutocompleteLog>(details).ptr());
489 break;
490
[email protected]bfd04a62009-02-01 18:16:56491 case NotificationType::BOOKMARK_MODEL_LOADED:
[email protected]d8e41ed2008-09-11 15:22:32492 LogBookmarks(Source<Profile>(source)->GetBookmarkModel());
initial.commit09911bf2008-07-26 23:55:29493 break;
494
495 default:
496 NOTREACHED();
497 break;
498 }
[email protected]d01b8732008-10-16 02:18:07499
500 HandleIdleSinceLastTransmission(false);
501
502 if (current_log_)
[email protected]281d2882009-01-20 20:32:42503 DLOG(INFO) << "METRICS: NUMBER OF EVENTS = " << current_log_->num_events();
[email protected]d01b8732008-10-16 02:18:07504}
505
506void MetricsService::HandleIdleSinceLastTransmission(bool in_idle) {
507 // If there wasn't a lot of action, maybe the computer was asleep, in which
508 // case, the log transmissions should have stopped. Here we start them up
509 // again.
[email protected]cac78842008-11-27 01:02:20510 if (!in_idle && idle_since_last_transmission_)
511 StartLogTransmissionTimer();
512 idle_since_last_transmission_ = in_idle;
initial.commit09911bf2008-07-26 23:55:29513}
514
515void MetricsService::RecordCleanShutdown() {
516 RecordBooleanPrefValue(prefs::kStabilityExitedCleanly, true);
517}
518
519void MetricsService::RecordStartOfSessionEnd() {
520 RecordBooleanPrefValue(prefs::kStabilitySessionEndCompleted, false);
521}
522
523void MetricsService::RecordCompletedSessionEnd() {
524 RecordBooleanPrefValue(prefs::kStabilitySessionEndCompleted, true);
525}
526
[email protected]e73c01972008-08-13 00:18:24527void MetricsService:: RecordBreakpadRegistration(bool success) {
[email protected]68475e602008-08-22 03:21:15528 if (!success)
[email protected]e73c01972008-08-13 00:18:24529 IncrementPrefValue(prefs::kStabilityBreakpadRegistrationFail);
530 else
531 IncrementPrefValue(prefs::kStabilityBreakpadRegistrationSuccess);
532}
533
534void MetricsService::RecordBreakpadHasDebugger(bool has_debugger) {
535 if (!has_debugger)
536 IncrementPrefValue(prefs::kStabilityDebuggerNotPresent);
537 else
[email protected]68475e602008-08-22 03:21:15538 IncrementPrefValue(prefs::kStabilityDebuggerPresent);
[email protected]e73c01972008-08-13 00:18:24539}
540
initial.commit09911bf2008-07-26 23:55:29541//------------------------------------------------------------------------------
542// private methods
543//------------------------------------------------------------------------------
544
545
546//------------------------------------------------------------------------------
547// Initialization methods
548
549void MetricsService::InitializeMetricsState() {
550 PrefService* pref = g_browser_process->local_state();
551 DCHECK(pref);
552
553 client_id_ = WideToUTF8(pref->GetString(prefs::kMetricsClientID));
554 if (client_id_.empty()) {
555 client_id_ = GenerateClientID();
556 pref->SetString(prefs::kMetricsClientID, UTF8ToWide(client_id_));
557
558 // Might as well make a note of how long this ID has existed
559 pref->SetString(prefs::kMetricsClientIDTimestamp,
560 Int64ToWString(Time::Now().ToTimeT()));
561 }
562
563 // Update session ID
564 session_id_ = pref->GetInteger(prefs::kMetricsSessionID);
565 ++session_id_;
566 pref->SetInteger(prefs::kMetricsSessionID, session_id_);
567
initial.commit09911bf2008-07-26 23:55:29568 // Stability bookkeeping
[email protected]e73c01972008-08-13 00:18:24569 IncrementPrefValue(prefs::kStabilityLaunchCount);
initial.commit09911bf2008-07-26 23:55:29570
[email protected]e73c01972008-08-13 00:18:24571 if (!pref->GetBoolean(prefs::kStabilityExitedCleanly)) {
572 IncrementPrefValue(prefs::kStabilityCrashCount);
initial.commit09911bf2008-07-26 23:55:29573 }
[email protected]e73c01972008-08-13 00:18:24574
575 // This will be set to 'true' if we exit cleanly.
initial.commit09911bf2008-07-26 23:55:29576 pref->SetBoolean(prefs::kStabilityExitedCleanly, false);
577
[email protected]e73c01972008-08-13 00:18:24578 if (!pref->GetBoolean(prefs::kStabilitySessionEndCompleted)) {
579 IncrementPrefValue(prefs::kStabilityIncompleteSessionEndCount);
initial.commit09911bf2008-07-26 23:55:29580 }
581 // This is marked false when we get a WM_ENDSESSION.
582 pref->SetBoolean(prefs::kStabilitySessionEndCompleted, true);
583
584 int64 last_start_time =
585 StringToInt64(pref->GetString(prefs::kStabilityLaunchTimeSec));
586 int64 last_end_time =
587 StringToInt64(pref->GetString(prefs::kStabilityLastTimestampSec));
588 int64 uptime =
589 StringToInt64(pref->GetString(prefs::kStabilityUptimeSec));
590
591 if (last_start_time && last_end_time) {
592 // TODO(JAR): Exclude sleep time. ... which must be gathered in UI loop.
593 uptime += last_end_time - last_start_time;
594 pref->SetString(prefs::kStabilityUptimeSec, Int64ToWString(uptime));
595 }
596 pref->SetString(prefs::kStabilityLaunchTimeSec,
597 Int64ToWString(Time::Now().ToTimeT()));
598
599 // Save profile metrics.
600 PrefService* prefs = g_browser_process->local_state();
601 if (prefs) {
602 // Remove the current dictionary and store it for use when sending data to
603 // server. By removing the value we prune potentially dead profiles
604 // (and keys). All valid values are added back once services startup.
605 const DictionaryValue* profile_dictionary =
606 prefs->GetDictionary(prefs::kProfileMetrics);
607 if (profile_dictionary) {
608 // Do a deep copy of profile_dictionary since ClearPref will delete it.
609 profile_dictionary_.reset(static_cast<DictionaryValue*>(
610 profile_dictionary->DeepCopy()));
611 prefs->ClearPref(prefs::kProfileMetrics);
612 }
613 }
614
615 // Kick off the process of saving the state (so the uptime numbers keep
616 // getting updated) every n minutes.
617 ScheduleNextStateSave();
618}
619
620void MetricsService::OnGetPluginListTaskComplete() {
621 DCHECK(state_ == PLUGIN_LIST_REQUESTED);
622 if (state_ == PLUGIN_LIST_REQUESTED)
623 state_ = PLUGIN_LIST_ARRIVED;
624}
625
626std::string MetricsService::GenerateClientID() {
[email protected]dc6f4962009-02-13 01:25:50627#if defined(OS_WIN)
initial.commit09911bf2008-07-26 23:55:29628 const int kGUIDSize = 39;
629
630 GUID guid;
631 HRESULT guid_result = CoCreateGuid(&guid);
632 DCHECK(SUCCEEDED(guid_result));
633
634 std::wstring guid_string;
635 int result = StringFromGUID2(guid,
636 WriteInto(&guid_string, kGUIDSize), kGUIDSize);
637 DCHECK(result == kGUIDSize);
638
639 return WideToUTF8(guid_string.substr(1, guid_string.length() - 2));
[email protected]dc6f4962009-02-13 01:25:50640#else
641 // TODO(port): Implement for Mac and linux.
642 NOTIMPLEMENTED();
643 return std::string();
644#endif
initial.commit09911bf2008-07-26 23:55:29645}
646
647
648//------------------------------------------------------------------------------
649// State save methods
650
651void MetricsService::ScheduleNextStateSave() {
652 state_saver_factory_.RevokeAll();
653
654 MessageLoop::current()->PostDelayedTask(FROM_HERE,
655 state_saver_factory_.NewRunnableMethod(&MetricsService::SaveLocalState),
656 kSaveStateInterval * 1000);
657}
658
659void MetricsService::SaveLocalState() {
660 PrefService* pref = g_browser_process->local_state();
661 if (!pref) {
662 NOTREACHED();
663 return;
664 }
665
666 RecordCurrentState(pref);
667 pref->ScheduleSavePersistentPrefs(g_browser_process->file_thread());
668
[email protected]281d2882009-01-20 20:32:42669 // TODO(jar): Does this run down the batteries????
initial.commit09911bf2008-07-26 23:55:29670 ScheduleNextStateSave();
671}
672
673
674//------------------------------------------------------------------------------
675// Recording control methods
676
677void MetricsService::StartRecording() {
678 if (current_log_)
679 return;
680
681 current_log_ = new MetricsLog(client_id_, session_id_);
682 if (state_ == INITIALIZED) {
683 // We only need to schedule that run once.
684 state_ = PLUGIN_LIST_REQUESTED;
685
686 // Make sure the plugin list is loaded before the inital log is sent, so
687 // that the main thread isn't blocked generating the list.
688 g_browser_process->file_thread()->message_loop()->PostDelayedTask(FROM_HERE,
689 new GetPluginListTask(MessageLoop::current()),
[email protected]252873ef2008-08-04 21:59:45690 kInitialInterlogDuration * 1000 / 2);
initial.commit09911bf2008-07-26 23:55:29691 }
692}
693
694void MetricsService::StopRecording(MetricsLog** log) {
695 if (!current_log_)
696 return;
697
[email protected]68475e602008-08-22 03:21:15698 // TODO(jar): Integrate bounds on log recording more consistently, so that we
699 // can stop recording logs that are too big much sooner.
[email protected]d01b8732008-10-16 02:18:07700 if (current_log_->num_events() > log_event_limit_) {
[email protected]68475e602008-08-22 03:21:15701 UMA_HISTOGRAM_COUNTS(L"UMA.Discarded Log Events",
702 current_log_->num_events());
703 current_log_->CloseLog();
704 delete current_log_;
[email protected]294638782008-09-24 00:22:41705 current_log_ = NULL;
[email protected]68475e602008-08-22 03:21:15706 StartRecording(); // Start trivial log to hold our histograms.
707 }
708
[email protected]0b33f80b2008-12-17 21:34:36709 // Put incremental data (histogram deltas, and realtime stats deltas) at the
[email protected]147bbc0b2009-01-06 19:37:40710 // end of all log transmissions (initial log handles this separately).
initial.commit09911bf2008-07-26 23:55:29711 // Don't bother if we're going to discard current_log_.
[email protected]0b33f80b2008-12-17 21:34:36712 if (log) {
[email protected]54131d252009-02-09 05:49:22713 // TODO(jar): when initial logs and ongoing logs have equal survivability,
714 // uncomment the following line to expedite stability data uploads.
715 // current_log_->RecordIncrementalStabilityElements();
initial.commit09911bf2008-07-26 23:55:29716 RecordCurrentHistograms();
[email protected]0b33f80b2008-12-17 21:34:36717 }
initial.commit09911bf2008-07-26 23:55:29718
719 current_log_->CloseLog();
[email protected]cac78842008-11-27 01:02:20720 if (log)
initial.commit09911bf2008-07-26 23:55:29721 *log = current_log_;
[email protected]cac78842008-11-27 01:02:20722 else
initial.commit09911bf2008-07-26 23:55:29723 delete current_log_;
initial.commit09911bf2008-07-26 23:55:29724 current_log_ = NULL;
725}
726
727void MetricsService::ListenerRegistration(bool start_listening) {
[email protected]bfd04a62009-02-01 18:16:56728 AddOrRemoveObserver(this, NotificationType::BROWSER_OPENED, start_listening);
729 AddOrRemoveObserver(this, NotificationType::BROWSER_CLOSED, start_listening);
730 AddOrRemoveObserver(this, NotificationType::USER_ACTION, start_listening);
731 AddOrRemoveObserver(this, NotificationType::TAB_PARENTED, start_listening);
732 AddOrRemoveObserver(this, NotificationType::TAB_CLOSING, start_listening);
733 AddOrRemoveObserver(this, NotificationType::LOAD_START, start_listening);
734 AddOrRemoveObserver(this, NotificationType::LOAD_STOP, start_listening);
735 AddOrRemoveObserver(this, NotificationType::RENDERER_PROCESS_IN_SBOX,
initial.commit09911bf2008-07-26 23:55:29736 start_listening);
[email protected]bfd04a62009-02-01 18:16:56737 AddOrRemoveObserver(this, NotificationType::RENDERER_PROCESS_TERMINATED,
initial.commit09911bf2008-07-26 23:55:29738 start_listening);
[email protected]bfd04a62009-02-01 18:16:56739 AddOrRemoveObserver(this, NotificationType::RENDERER_PROCESS_HANG,
740 start_listening);
[email protected]a27a9382009-02-11 23:55:10741 AddOrRemoveObserver(this, NotificationType::CHILD_PROCESS_HOST_CONNECTED,
[email protected]bfd04a62009-02-01 18:16:56742 start_listening);
[email protected]a27a9382009-02-11 23:55:10743 AddOrRemoveObserver(this, NotificationType::CHILD_INSTANCE_CREATED,
[email protected]bfd04a62009-02-01 18:16:56744 start_listening);
[email protected]a27a9382009-02-11 23:55:10745 AddOrRemoveObserver(this, NotificationType::CHILD_PROCESS_CRASHED,
[email protected]bfd04a62009-02-01 18:16:56746 start_listening);
747 AddOrRemoveObserver(this, NotificationType::TEMPLATE_URL_MODEL_LOADED,
748 start_listening);
749 AddOrRemoveObserver(this, NotificationType::OMNIBOX_OPENED_URL,
750 start_listening);
751 AddOrRemoveObserver(this, NotificationType::BOOKMARK_MODEL_LOADED,
752 start_listening);
initial.commit09911bf2008-07-26 23:55:29753}
754
755// static
756void MetricsService::AddOrRemoveObserver(NotificationObserver* observer,
[email protected]cac78842008-11-27 01:02:20757 NotificationType type,
758 bool is_add) {
initial.commit09911bf2008-07-26 23:55:29759 NotificationService* service = NotificationService::current();
760
[email protected]cac78842008-11-27 01:02:20761 if (is_add)
initial.commit09911bf2008-07-26 23:55:29762 service->AddObserver(observer, type, NotificationService::AllSources());
[email protected]cac78842008-11-27 01:02:20763 else
initial.commit09911bf2008-07-26 23:55:29764 service->RemoveObserver(observer, type, NotificationService::AllSources());
initial.commit09911bf2008-07-26 23:55:29765}
766
767void MetricsService::PushPendingLogsToUnsentLists() {
768 if (state_ < INITIAL_LOG_READY)
[email protected]28ab7f92009-01-06 21:39:04769 return; // We didn't and still don't have time to get plugin list etc.
initial.commit09911bf2008-07-26 23:55:29770
771 if (pending_log()) {
772 PreparePendingLogText();
773 if (state_ == INITIAL_LOG_READY) {
774 // We may race here, and send second copy of initial log later.
775 unsent_initial_logs_.push_back(pending_log_text_);
[email protected]d01b8732008-10-16 02:18:07776 state_ = SEND_OLD_INITIAL_LOGS;
initial.commit09911bf2008-07-26 23:55:29777 } else {
[email protected]281d2882009-01-20 20:32:42778 // TODO(jar): Verify correctness in other states, including sending unsent
779 // iniitial logs.
[email protected]68475e602008-08-22 03:21:15780 PushPendingLogTextToUnsentOngoingLogs();
initial.commit09911bf2008-07-26 23:55:29781 }
782 DiscardPendingLog();
783 }
784 DCHECK(!pending_log());
785 StopRecording(&pending_log_);
786 PreparePendingLogText();
[email protected]68475e602008-08-22 03:21:15787 PushPendingLogTextToUnsentOngoingLogs();
initial.commit09911bf2008-07-26 23:55:29788 DiscardPendingLog();
789 StoreUnsentLogs();
790}
791
[email protected]68475e602008-08-22 03:21:15792void MetricsService::PushPendingLogTextToUnsentOngoingLogs() {
[email protected]d01b8732008-10-16 02:18:07793 // If UMA response told us not to upload, there's no need to save the pending
794 // log. It wasn't supposed to be uploaded anyway.
795 if (!server_permits_upload_)
796 return;
797
[email protected]dc6f4962009-02-13 01:25:50798 if (pending_log_text_.length() >
799 static_cast<size_t>(kUploadLogAvoidRetransmitSize)) {
[email protected]68475e602008-08-22 03:21:15800 UMA_HISTOGRAM_COUNTS(L"UMA.Large Accumulated Log Not Persisted",
801 static_cast<int>(pending_log_text_.length()));
802 return;
803 }
804 unsent_ongoing_logs_.push_back(pending_log_text_);
805}
806
initial.commit09911bf2008-07-26 23:55:29807//------------------------------------------------------------------------------
808// Transmission of logs methods
809
810void MetricsService::StartLogTransmissionTimer() {
[email protected]d01b8732008-10-16 02:18:07811 // If we're not reporting, there's no point in starting a log transmission
812 // timer.
813 if (!reporting_active())
814 return;
815
initial.commit09911bf2008-07-26 23:55:29816 if (!current_log_)
817 return; // Recorder is shutdown.
[email protected]d01b8732008-10-16 02:18:07818
819 // If there is already a timer running, we leave it running.
820 // If timer_pending is true because the fetch is waiting for a response,
821 // we return for now and let the response handler start the timer.
822 if (timer_pending_)
initial.commit09911bf2008-07-26 23:55:29823 return;
[email protected]d01b8732008-10-16 02:18:07824
[email protected]d01b8732008-10-16 02:18:07825 // Before starting the timer, set timer_pending_ to true.
initial.commit09911bf2008-07-26 23:55:29826 timer_pending_ = true;
[email protected]d01b8732008-10-16 02:18:07827
828 // Right before the UMA transmission gets started, there's one more thing we'd
829 // like to record: the histogram of memory usage, so we spawn a task to
830 // collect the memory details and when that task is finished, we arrange for
831 // TryToStartTransmission to take over.
initial.commit09911bf2008-07-26 23:55:29832 MessageLoop::current()->PostDelayedTask(FROM_HERE,
833 log_sender_factory_.
834 NewRunnableMethod(&MetricsService::CollectMemoryDetails),
835 static_cast<int>(interlog_duration_.InMilliseconds()));
836}
837
838void MetricsService::TryToStartTransmission() {
839 DCHECK(IsSingleThreaded());
840
[email protected]d01b8732008-10-16 02:18:07841 // This function should only be called via timer, so timer_pending_
842 // should be true.
843 DCHECK(timer_pending_);
844 timer_pending_ = false;
initial.commit09911bf2008-07-26 23:55:29845
846 DCHECK(!current_fetch_.get());
initial.commit09911bf2008-07-26 23:55:29847
[email protected]d01b8732008-10-16 02:18:07848 // If we're getting no notifications, then the log won't have much in it, and
849 // it's possible the computer is about to go to sleep, so don't upload and
850 // don't restart the transmission timer.
851 if (idle_since_last_transmission_)
852 return;
853
854 // If somehow there is a fetch in progress, we return setting timer_pending_
855 // to true and hope things work out.
856 if (current_fetch_.get()) {
857 timer_pending_ = true;
858 return;
859 }
860
861 // If uploads are forbidden by UMA response, there's no point in keeping
862 // the current_log_, and the more often we delete it, the less likely it is
863 // to expand forever.
864 if (!server_permits_upload_ && current_log_) {
865 StopRecording(NULL);
866 StartRecording();
867 }
initial.commit09911bf2008-07-26 23:55:29868
869 if (!current_log_)
870 return; // Logging was disabled.
[email protected]d01b8732008-10-16 02:18:07871 if (!reporting_active())
initial.commit09911bf2008-07-26 23:55:29872 return; // Don't do work if we're not going to send anything now.
873
[email protected]d01b8732008-10-16 02:18:07874 MakePendingLog();
initial.commit09911bf2008-07-26 23:55:29875
[email protected]d01b8732008-10-16 02:18:07876 // MakePendingLog should have put something in the pending log, if it didn't,
877 // we start the timer again, return and hope things work out.
878 if (!pending_log()) {
879 StartLogTransmissionTimer();
880 return;
881 }
initial.commit09911bf2008-07-26 23:55:29882
[email protected]d01b8732008-10-16 02:18:07883 // If we're not supposed to upload any UMA data because the response or the
884 // user said so, cancel the upload at this point, but start the timer.
885 if (!TransmissionPermitted()) {
886 DiscardPendingLog();
887 StartLogTransmissionTimer();
888 return;
889 }
initial.commit09911bf2008-07-26 23:55:29890
[email protected]d01b8732008-10-16 02:18:07891 PrepareFetchWithPendingLog();
892
893 if (!current_fetch_.get()) {
894 // Compression failed, and log discarded :-/.
895 DiscardPendingLog();
896 StartLogTransmissionTimer(); // Maybe we'll do better next time
897 // TODO(jar): If compression failed, we should have created a tiny log and
898 // compressed that, so that we can signal that we're losing logs.
899 return;
900 }
901
902 DCHECK(!timer_pending_);
903
904 // The URL fetch is a like timer in that after a while we get called back
905 // so we set timer_pending_ true just as we start the url fetch.
906 timer_pending_ = true;
907 current_fetch_->Start();
908
909 HandleIdleSinceLastTransmission(true);
910}
911
912
913void MetricsService::MakePendingLog() {
914 if (pending_log())
915 return;
916
917 switch (state_) {
918 case INITIALIZED:
919 case PLUGIN_LIST_REQUESTED: // We should be further along by now.
920 DCHECK(false);
921 return;
922
923 case PLUGIN_LIST_ARRIVED:
924 // We need to wait for the initial log to be ready before sending
925 // anything, because the server will tell us whether it wants to hear
926 // from us.
927 PrepareInitialLog();
928 DCHECK(state_ == PLUGIN_LIST_ARRIVED);
929 RecallUnsentLogs();
930 state_ = INITIAL_LOG_READY;
931 break;
932
933 case SEND_OLD_INITIAL_LOGS:
[email protected]cac78842008-11-27 01:02:20934 if (!unsent_initial_logs_.empty()) {
935 pending_log_text_ = unsent_initial_logs_.back();
936 break;
937 }
[email protected]d01b8732008-10-16 02:18:07938 state_ = SENDING_OLD_LOGS;
939 // Fall through.
initial.commit09911bf2008-07-26 23:55:29940
[email protected]d01b8732008-10-16 02:18:07941 case SENDING_OLD_LOGS:
942 if (!unsent_ongoing_logs_.empty()) {
943 pending_log_text_ = unsent_ongoing_logs_.back();
944 break;
945 }
946 state_ = SENDING_CURRENT_LOGS;
947 // Fall through.
948
949 case SENDING_CURRENT_LOGS:
950 StopRecording(&pending_log_);
951 StartRecording();
952 break;
953
954 default:
955 DCHECK(false);
956 return;
957 }
958
959 DCHECK(pending_log());
960}
961
962bool MetricsService::TransmissionPermitted() const {
963 // If the user forbids uploading that's they're business, and we don't upload
964 // anything. If the server forbids uploading, that's our business, so we take
965 // that to mean it forbids current logs, but we still send up the inital logs
966 // and any old logs.
[email protected]d01b8732008-10-16 02:18:07967 if (!user_permits_upload_)
968 return false;
[email protected]cac78842008-11-27 01:02:20969 if (server_permits_upload_)
[email protected]d01b8732008-10-16 02:18:07970 return true;
initial.commit09911bf2008-07-26 23:55:29971
[email protected]cac78842008-11-27 01:02:20972 switch (state_) {
973 case INITIAL_LOG_READY:
974 case SEND_OLD_INITIAL_LOGS:
975 case SENDING_OLD_LOGS:
976 return true;
977
978 case SENDING_CURRENT_LOGS:
979 default:
980 return false;
[email protected]8c8824b2008-09-20 01:55:50981 }
initial.commit09911bf2008-07-26 23:55:29982}
983
984void MetricsService::CollectMemoryDetails() {
985 Task* task = log_sender_factory_.
986 NewRunnableMethod(&MetricsService::TryToStartTransmission);
987 MetricsMemoryDetails* details = new MetricsMemoryDetails(task);
988 details->StartFetch();
989
990 // Collect WebCore cache information to put into a histogram.
991 for (RenderProcessHost::iterator it = RenderProcessHost::begin();
992 it != RenderProcessHost::end(); ++it) {
993 it->second->Send(new ViewMsg_GetCacheResourceStats());
994 }
995}
996
997void MetricsService::PrepareInitialLog() {
998 DCHECK(state_ == PLUGIN_LIST_ARRIVED);
999 std::vector<WebPluginInfo> plugins;
1000 PluginService::GetInstance()->GetPlugins(false, &plugins);
1001
1002 MetricsLog* log = new MetricsLog(client_id_, session_id_);
1003 log->RecordEnvironment(plugins, profile_dictionary_.get());
1004
1005 // Histograms only get written to current_log_, so setup for the write.
1006 MetricsLog* save_log = current_log_;
1007 current_log_ = log;
1008 RecordCurrentHistograms(); // Into current_log_... which is really log.
1009 current_log_ = save_log;
1010
1011 log->CloseLog();
1012 DCHECK(!pending_log());
1013 pending_log_ = log;
1014}
1015
1016void MetricsService::RecallUnsentLogs() {
1017 DCHECK(unsent_initial_logs_.empty());
1018 DCHECK(unsent_ongoing_logs_.empty());
1019
1020 PrefService* local_state = g_browser_process->local_state();
1021 DCHECK(local_state);
1022
1023 ListValue* unsent_initial_logs = local_state->GetMutableList(
1024 prefs::kMetricsInitialLogs);
1025 for (ListValue::iterator it = unsent_initial_logs->begin();
1026 it != unsent_initial_logs->end(); ++it) {
[email protected]5e324b72008-12-18 00:07:591027 std::string log;
1028 (*it)->GetAsString(&log);
1029 unsent_initial_logs_.push_back(log);
initial.commit09911bf2008-07-26 23:55:291030 }
1031
1032 ListValue* unsent_ongoing_logs = local_state->GetMutableList(
1033 prefs::kMetricsOngoingLogs);
1034 for (ListValue::iterator it = unsent_ongoing_logs->begin();
1035 it != unsent_ongoing_logs->end(); ++it) {
[email protected]5e324b72008-12-18 00:07:591036 std::string log;
1037 (*it)->GetAsString(&log);
1038 unsent_ongoing_logs_.push_back(log);
initial.commit09911bf2008-07-26 23:55:291039 }
1040}
1041
1042void MetricsService::StoreUnsentLogs() {
1043 if (state_ < INITIAL_LOG_READY)
1044 return; // We never Recalled the prior unsent logs.
1045
1046 PrefService* local_state = g_browser_process->local_state();
1047 DCHECK(local_state);
1048
1049 ListValue* unsent_initial_logs = local_state->GetMutableList(
1050 prefs::kMetricsInitialLogs);
1051 unsent_initial_logs->Clear();
1052 size_t start = 0;
1053 if (unsent_initial_logs_.size() > kMaxInitialLogsPersisted)
1054 start = unsent_initial_logs_.size() - kMaxInitialLogsPersisted;
1055 for (size_t i = start; i < unsent_initial_logs_.size(); ++i)
1056 unsent_initial_logs->Append(
[email protected]5e324b72008-12-18 00:07:591057 Value::CreateStringValue(unsent_initial_logs_[i]));
initial.commit09911bf2008-07-26 23:55:291058
1059 ListValue* unsent_ongoing_logs = local_state->GetMutableList(
1060 prefs::kMetricsOngoingLogs);
1061 unsent_ongoing_logs->Clear();
1062 start = 0;
1063 if (unsent_ongoing_logs_.size() > kMaxOngoingLogsPersisted)
1064 start = unsent_ongoing_logs_.size() - kMaxOngoingLogsPersisted;
1065 for (size_t i = start; i < unsent_ongoing_logs_.size(); ++i)
1066 unsent_ongoing_logs->Append(
[email protected]5e324b72008-12-18 00:07:591067 Value::CreateStringValue(unsent_ongoing_logs_[i]));
initial.commit09911bf2008-07-26 23:55:291068}
1069
1070void MetricsService::PreparePendingLogText() {
1071 DCHECK(pending_log());
1072 if (!pending_log_text_.empty())
1073 return;
1074 int original_size = pending_log_->GetEncodedLogSize();
1075 pending_log_->GetEncodedLog(WriteInto(&pending_log_text_, original_size),
1076 original_size);
1077}
1078
[email protected]d01b8732008-10-16 02:18:071079void MetricsService::PrepareFetchWithPendingLog() {
initial.commit09911bf2008-07-26 23:55:291080 DCHECK(pending_log());
1081 DCHECK(!current_fetch_.get());
1082 PreparePendingLogText();
1083 DCHECK(!pending_log_text_.empty());
1084
1085 // Allow security conscious users to see all metrics logs that we send.
1086 LOG(INFO) << "METRICS LOG: " << pending_log_text_;
1087
1088 std::string compressed_log;
[email protected]cac78842008-11-27 01:02:201089 if (!Bzip2Compress(pending_log_text_, &compressed_log)) {
initial.commit09911bf2008-07-26 23:55:291090 NOTREACHED() << "Failed to compress log for transmission.";
1091 DiscardPendingLog();
1092 StartLogTransmissionTimer(); // Maybe we'll do better on next log :-/.
1093 return;
1094 }
[email protected]cac78842008-11-27 01:02:201095
initial.commit09911bf2008-07-26 23:55:291096 current_fetch_.reset(new URLFetcher(GURL(kMetricsURL), URLFetcher::POST,
1097 this));
1098 current_fetch_->set_request_context(Profile::GetDefaultRequestContext());
1099 current_fetch_->set_upload_data(kMetricsType, compressed_log);
initial.commit09911bf2008-07-26 23:55:291100}
1101
1102void MetricsService::DiscardPendingLog() {
1103 if (pending_log_) { // Shutdown might have deleted it!
1104 delete pending_log_;
1105 pending_log_ = NULL;
1106 }
1107 pending_log_text_.clear();
1108}
1109
1110// This implementation is based on the Firefox MetricsService implementation.
1111bool MetricsService::Bzip2Compress(const std::string& input,
1112 std::string* output) {
1113 bz_stream stream = {0};
1114 // As long as our input is smaller than the bzip2 block size, we should get
1115 // the best compression. For example, if your input was 250k, using a block
1116 // size of 300k or 500k should result in the same compression ratio. Since
1117 // our data should be under 100k, using the minimum block size of 100k should
1118 // allocate less temporary memory, but result in the same compression ratio.
1119 int result = BZ2_bzCompressInit(&stream,
1120 1, // 100k (min) block size
1121 0, // quiet
1122 0); // default "work factor"
1123 if (result != BZ_OK) { // out of memory?
1124 return false;
1125 }
1126
1127 output->clear();
1128
1129 stream.next_in = const_cast<char*>(input.data());
1130 stream.avail_in = static_cast<int>(input.size());
1131 // NOTE: we don't need a BZ_RUN phase since our input buffer contains
1132 // the entire input
1133 do {
1134 output->resize(output->size() + 1024);
1135 stream.next_out = &((*output)[stream.total_out_lo32]);
1136 stream.avail_out = static_cast<int>(output->size()) - stream.total_out_lo32;
1137 result = BZ2_bzCompress(&stream, BZ_FINISH);
1138 } while (result == BZ_FINISH_OK);
1139 if (result != BZ_STREAM_END) // unknown failure?
1140 return false;
1141 result = BZ2_bzCompressEnd(&stream);
1142 DCHECK(result == BZ_OK);
1143
1144 output->resize(stream.total_out_lo32);
1145
1146 return true;
1147}
1148
1149static const char* StatusToString(const URLRequestStatus& status) {
1150 switch (status.status()) {
1151 case URLRequestStatus::SUCCESS:
1152 return "SUCCESS";
1153
1154 case URLRequestStatus::IO_PENDING:
1155 return "IO_PENDING";
1156
1157 case URLRequestStatus::HANDLED_EXTERNALLY:
1158 return "HANDLED_EXTERNALLY";
1159
1160 case URLRequestStatus::CANCELED:
1161 return "CANCELED";
1162
1163 case URLRequestStatus::FAILED:
1164 return "FAILED";
1165
1166 default:
1167 NOTREACHED();
1168 return "Unknown";
1169 }
1170}
1171
1172void MetricsService::OnURLFetchComplete(const URLFetcher* source,
1173 const GURL& url,
1174 const URLRequestStatus& status,
1175 int response_code,
1176 const ResponseCookies& cookies,
1177 const std::string& data) {
1178 DCHECK(timer_pending_);
1179 timer_pending_ = false;
1180 DCHECK(current_fetch_.get());
1181 current_fetch_.reset(NULL); // We're not allowed to re-use it.
1182
1183 // Confirm send so that we can move on.
[email protected]281d2882009-01-20 20:32:421184 LOG(INFO) << "METRICS RESPONSE CODE: " << response_code << " status=" <<
[email protected]cac78842008-11-27 01:02:201185 StatusToString(status);
[email protected]252873ef2008-08-04 21:59:451186
[email protected]0eb34fee2009-01-21 08:04:381187 // Provide boolean for error recovery (allow us to ignore response_code).
[email protected]dc6f4962009-02-13 01:25:501188 bool discard_log = false;
[email protected]0eb34fee2009-01-21 08:04:381189
[email protected]68475e602008-08-22 03:21:151190 if (response_code != 200 &&
[email protected]dc6f4962009-02-13 01:25:501191 pending_log_text_.length() >
1192 static_cast<size_t>(kUploadLogAvoidRetransmitSize)) {
[email protected]68475e602008-08-22 03:21:151193 UMA_HISTOGRAM_COUNTS(L"UMA.Large Rejected Log was Discarded",
1194 static_cast<int>(pending_log_text_.length()));
[email protected]0eb34fee2009-01-21 08:04:381195 discard_log = true;
1196 } else if (response_code == 400) {
1197 // Bad syntax. Retransmission won't work.
1198 UMA_HISTOGRAM_COUNTS(L"UMA.Unacceptable_Log_Discarded", state_);
1199 discard_log = true;
[email protected]68475e602008-08-22 03:21:151200 }
1201
[email protected]0eb34fee2009-01-21 08:04:381202 if (response_code != 200 && !discard_log) {
[email protected]281d2882009-01-20 20:32:421203 LOG(INFO) << "METRICS: transmission attempt returned a failure code: "
1204 << response_code << ". Verify network connectivity";
[email protected]252873ef2008-08-04 21:59:451205 HandleBadResponseCode();
[email protected]0eb34fee2009-01-21 08:04:381206 } else { // Successful receipt (or we are discarding log).
[email protected]281d2882009-01-20 20:32:421207 LOG(INFO) << "METRICS RESPONSE DATA: " << data;
initial.commit09911bf2008-07-26 23:55:291208 switch (state_) {
1209 case INITIAL_LOG_READY:
1210 state_ = SEND_OLD_INITIAL_LOGS;
1211 break;
1212
1213 case SEND_OLD_INITIAL_LOGS:
1214 DCHECK(!unsent_initial_logs_.empty());
1215 unsent_initial_logs_.pop_back();
1216 StoreUnsentLogs();
1217 break;
1218
1219 case SENDING_OLD_LOGS:
1220 DCHECK(!unsent_ongoing_logs_.empty());
1221 unsent_ongoing_logs_.pop_back();
1222 StoreUnsentLogs();
1223 break;
1224
1225 case SENDING_CURRENT_LOGS:
1226 break;
1227
1228 default:
1229 DCHECK(false);
1230 break;
1231 }
[email protected]d01b8732008-10-16 02:18:071232
initial.commit09911bf2008-07-26 23:55:291233 DiscardPendingLog();
[email protected]29be92552008-08-07 22:49:271234 // Since we sent a log, make sure our in-memory state is recorded to disk.
1235 PrefService* local_state = g_browser_process->local_state();
1236 DCHECK(local_state);
1237 if (local_state)
1238 local_state->ScheduleSavePersistentPrefs(
1239 g_browser_process->file_thread());
[email protected]252873ef2008-08-04 21:59:451240
[email protected]147bbc0b2009-01-06 19:37:401241 // Provide a default (free of exponetial backoff, other varances) in case
1242 // the server does not specify a value.
1243 interlog_duration_ = TimeDelta::FromSeconds(kMinSecondsPerLog);
1244
[email protected]252873ef2008-08-04 21:59:451245 GetSettingsFromResponseData(data);
[email protected]252873ef2008-08-04 21:59:451246 // Override server specified interlog delay if there are unsent logs to
[email protected]29be92552008-08-07 22:49:271247 // transmit.
initial.commit09911bf2008-07-26 23:55:291248 if (unsent_logs()) {
1249 DCHECK(state_ < SENDING_CURRENT_LOGS);
1250 interlog_duration_ = TimeDelta::FromSeconds(kUnsentLogDelay);
initial.commit09911bf2008-07-26 23:55:291251 }
1252 }
[email protected]252873ef2008-08-04 21:59:451253
initial.commit09911bf2008-07-26 23:55:291254 StartLogTransmissionTimer();
1255}
1256
[email protected]252873ef2008-08-04 21:59:451257void MetricsService::HandleBadResponseCode() {
[email protected]281d2882009-01-20 20:32:421258 LOG(INFO) << "Verify your metrics logs are formatted correctly. "
[email protected]cac78842008-11-27 01:02:201259 "Verify server is active at " << kMetricsURL;
[email protected]252873ef2008-08-04 21:59:451260 if (!pending_log()) {
[email protected]281d2882009-01-20 20:32:421261 LOG(INFO) << "METRICS: Recorder shutdown during log transmission.";
[email protected]252873ef2008-08-04 21:59:451262 } else {
1263 // Send progressively less frequently.
1264 DCHECK(kBackoff > 1.0);
1265 interlog_duration_ = TimeDelta::FromMicroseconds(
1266 static_cast<int64>(kBackoff * interlog_duration_.InMicroseconds()));
1267
1268 if (kMaxBackoff * TimeDelta::FromSeconds(kMinSecondsPerLog) <
[email protected]cac78842008-11-27 01:02:201269 interlog_duration_) {
[email protected]252873ef2008-08-04 21:59:451270 interlog_duration_ = kMaxBackoff *
1271 TimeDelta::FromSeconds(kMinSecondsPerLog);
[email protected]cac78842008-11-27 01:02:201272 }
[email protected]252873ef2008-08-04 21:59:451273
[email protected]281d2882009-01-20 20:32:421274 LOG(INFO) << "METRICS: transmission retry being scheduled in " <<
[email protected]252873ef2008-08-04 21:59:451275 interlog_duration_.InSeconds() << " seconds for " <<
1276 pending_log_text_;
initial.commit09911bf2008-07-26 23:55:291277 }
initial.commit09911bf2008-07-26 23:55:291278}
1279
[email protected]252873ef2008-08-04 21:59:451280void MetricsService::GetSettingsFromResponseData(const std::string& data) {
1281 // We assume that the file is structured as a block opened by <response>
[email protected]d01b8732008-10-16 02:18:071282 // and that inside response, there is a block opened by tag <chrome_config>
1283 // other tags are ignored for now except the content of <chrome_config>.
[email protected]281d2882009-01-20 20:32:421284 LOG(INFO) << "METRICS: getting settings from response data: " << data;
[email protected]d01b8732008-10-16 02:18:071285
[email protected]252873ef2008-08-04 21:59:451286 int data_size = static_cast<int>(data.size());
1287 if (data_size < 0) {
[email protected]281d2882009-01-20 20:32:421288 LOG(INFO) << "METRICS: server response data bad size: " << data_size <<
[email protected]cac78842008-11-27 01:02:201289 "; aborting extraction of settings";
[email protected]252873ef2008-08-04 21:59:451290 return;
1291 }
[email protected]cac78842008-11-27 01:02:201292 xmlDocPtr doc = xmlReadMemory(data.c_str(), data_size, "", NULL, 0);
[email protected]252873ef2008-08-04 21:59:451293 DCHECK(doc);
[email protected]d01b8732008-10-16 02:18:071294 // If the document is malformed, we just use the settings that were there.
1295 if (!doc) {
[email protected]281d2882009-01-20 20:32:421296 LOG(INFO) << "METRICS: reading xml from server response data failed";
[email protected]252873ef2008-08-04 21:59:451297 return;
[email protected]d01b8732008-10-16 02:18:071298 }
[email protected]252873ef2008-08-04 21:59:451299
[email protected]d01b8732008-10-16 02:18:071300 xmlNodePtr top_node = xmlDocGetRootElement(doc), chrome_config_node = NULL;
1301 // Here, we find the chrome_config node by name.
[email protected]252873ef2008-08-04 21:59:451302 for (xmlNodePtr p = top_node->children; p; p = p->next) {
[email protected]d01b8732008-10-16 02:18:071303 if (xmlStrEqual(p->name, BAD_CAST "chrome_config")) {
1304 chrome_config_node = p;
[email protected]252873ef2008-08-04 21:59:451305 break;
1306 }
1307 }
1308 // If the server data is formatted wrong and there is no
1309 // config node where we expect, we just drop out.
[email protected]d01b8732008-10-16 02:18:071310 if (chrome_config_node != NULL)
1311 GetSettingsFromChromeConfigNode(chrome_config_node);
[email protected]252873ef2008-08-04 21:59:451312 xmlFreeDoc(doc);
1313}
1314
[email protected]d01b8732008-10-16 02:18:071315void MetricsService::GetSettingsFromChromeConfigNode(
1316 xmlNodePtr chrome_config_node) {
1317 // Iterate through all children of the config node.
1318 for (xmlNodePtr current_node = chrome_config_node->children;
1319 current_node;
1320 current_node = current_node->next) {
1321 // If we find the upload tag, we appeal to another function
1322 // GetSettingsFromUploadNode to read all the data in it.
[email protected]252873ef2008-08-04 21:59:451323 if (xmlStrEqual(current_node->name, BAD_CAST "upload")) {
[email protected]d01b8732008-10-16 02:18:071324 GetSettingsFromUploadNode(current_node);
[email protected]252873ef2008-08-04 21:59:451325 continue;
1326 }
1327 }
1328}
initial.commit09911bf2008-07-26 23:55:291329
[email protected]d01b8732008-10-16 02:18:071330void MetricsService::InheritedProperties::OverwriteWhereNeeded(
1331 xmlNodePtr node) {
1332 xmlChar* salt_value = xmlGetProp(node, BAD_CAST "salt");
1333 if (salt_value) // If the property isn't there, xmlGetProp returns NULL.
1334 salt = atoi(reinterpret_cast<char*>(salt_value));
1335 // If the property isn't there, we keep the value the property had before
1336
1337 xmlChar* denominator_value = xmlGetProp(node, BAD_CAST "denominator");
1338 if (denominator_value)
1339 denominator = atoi(reinterpret_cast<char*>(denominator_value));
1340}
1341
1342void MetricsService::GetSettingsFromUploadNode(xmlNodePtr upload_node) {
1343 InheritedProperties props;
1344 GetSettingsFromUploadNodeRecursive(upload_node, props, "", true);
1345}
1346
[email protected]cac78842008-11-27 01:02:201347void MetricsService::GetSettingsFromUploadNodeRecursive(
1348 xmlNodePtr node,
1349 InheritedProperties props,
1350 std::string path_prefix,
1351 bool uploadOn) {
[email protected]d01b8732008-10-16 02:18:071352 props.OverwriteWhereNeeded(node);
1353
1354 // The bool uploadOn is set to true if the data represented by current
1355 // node should be uploaded. This gets inherited in the tree; the children
1356 // of a node that has already been rejected for upload get rejected for
1357 // upload.
1358 uploadOn = uploadOn && NodeProbabilityTest(node, props);
1359
1360 // The path is a / separated list of the node names ancestral to the current
1361 // one. So, if you want to check if the current node has a certain name,
1362 // compare to name. If you want to check if it is a certan tag at a certain
1363 // place in the tree, compare to the whole path.
1364 std::string name = std::string(reinterpret_cast<const char*>(node->name));
1365 std::string path = path_prefix + "/" + name;
1366
1367 if (path == "/upload") {
1368 xmlChar* upload_interval_val = xmlGetProp(node, BAD_CAST "interval");
1369 if (upload_interval_val) {
1370 interlog_duration_ = TimeDelta::FromSeconds(
1371 atoi(reinterpret_cast<char*>(upload_interval_val)));
1372 }
1373
1374 server_permits_upload_ = uploadOn;
1375 }
1376 if (path == "/upload/logs") {
1377 xmlChar* log_event_limit_val = xmlGetProp(node, BAD_CAST "event_limit");
1378 if (log_event_limit_val)
1379 log_event_limit_ = atoi(reinterpret_cast<char*>(log_event_limit_val));
1380 }
1381 if (name == "histogram") {
1382 xmlChar* type_value = xmlGetProp(node, BAD_CAST "type");
1383 if (type_value) {
1384 std::string type = (reinterpret_cast<char*>(type_value));
1385 if (uploadOn)
1386 histograms_to_upload_.insert(type);
1387 else
1388 histograms_to_omit_.insert(type);
1389 }
1390 }
1391 if (name == "log") {
1392 xmlChar* type_value = xmlGetProp(node, BAD_CAST "type");
1393 if (type_value) {
1394 std::string type = (reinterpret_cast<char*>(type_value));
1395 if (uploadOn)
1396 logs_to_upload_.insert(type);
1397 else
1398 logs_to_omit_.insert(type);
1399 }
1400 }
1401
1402 // Recursive call. If the node is a leaf i.e. if it ends in a "/>", then it
1403 // doesn't have children, so node->children is NULL, and this loop doesn't
1404 // call (that's how the recursion ends).
1405 for (xmlNodePtr child_node = node->children;
[email protected]cac78842008-11-27 01:02:201406 child_node;
1407 child_node = child_node->next) {
[email protected]d01b8732008-10-16 02:18:071408 GetSettingsFromUploadNodeRecursive(child_node, props, path, uploadOn);
1409 }
1410}
1411
1412bool MetricsService::NodeProbabilityTest(xmlNodePtr node,
[email protected]cac78842008-11-27 01:02:201413 InheritedProperties props) const {
[email protected]d01b8732008-10-16 02:18:071414 // Default value of probability on any node is 1, but recall that
1415 // its parents can already have been rejected for upload.
1416 double probability = 1;
1417
1418 // If a probability is specified in the node, we use it instead.
1419 xmlChar* probability_value = xmlGetProp(node, BAD_CAST "probability");
1420 if (probability_value)
[email protected]0b33f80b2008-12-17 21:34:361421 probability = atoi(reinterpret_cast<char*>(probability_value));
[email protected]d01b8732008-10-16 02:18:071422
1423 return ProbabilityTest(probability, props.salt, props.denominator);
1424}
1425
1426bool MetricsService::ProbabilityTest(double probability,
1427 int salt,
1428 int denominator) const {
1429 // Okay, first we figure out how many of the digits of the
1430 // client_id_ we need in order to make a nice pseudorandomish
1431 // number in the range [0,denominator). Too many digits is
1432 // fine.
[email protected]d01b8732008-10-16 02:18:071433
1434 // n is the length of the client_id_ string
1435 size_t n = client_id_.size();
1436
1437 // idnumber is a positive integer generated from the client_id_.
1438 // It plus salt is going to give us our pseudorandom number.
1439 int idnumber = 0;
1440 const char* client_id_c_str = client_id_.c_str();
1441
1442 // Here we hash the relevant digits of the client_id_
1443 // string somehow to get a big integer idnumber (could be negative
1444 // from wraparound)
1445 int big = 1;
[email protected]cac78842008-11-27 01:02:201446 for (size_t j = n - 1; j >= 0; --j) {
1447 idnumber += static_cast<int>(client_id_c_str[j]) * big;
[email protected]d01b8732008-10-16 02:18:071448 big *= 10;
1449 }
1450
1451 // Mod id number by denominator making sure to get a non-negative
1452 // answer.
[email protected]cac78842008-11-27 01:02:201453 idnumber = ((idnumber % denominator) + denominator) % denominator;
[email protected]d01b8732008-10-16 02:18:071454
[email protected]cac78842008-11-27 01:02:201455 // ((idnumber + salt) % denominator) / denominator is in the range [0,1]
[email protected]d01b8732008-10-16 02:18:071456 // if it's less than probability we call that an affirmative coin
1457 // toss.
[email protected]cac78842008-11-27 01:02:201458 return static_cast<double>((idnumber + salt) % denominator) <
1459 probability * denominator;
[email protected]d01b8732008-10-16 02:18:071460}
1461
initial.commit09911bf2008-07-26 23:55:291462void MetricsService::LogWindowChange(NotificationType type,
1463 const NotificationSource& source,
1464 const NotificationDetails& details) {
[email protected]534e54b2008-08-13 15:40:091465 int controller_id = -1;
1466 uintptr_t window_or_tab = source.map_key();
initial.commit09911bf2008-07-26 23:55:291467 MetricsLog::WindowEventType window_type;
1468
1469 // Note: since we stop all logging when a single OTR session is active, it is
1470 // possible that we start getting notifications about a window that we don't
1471 // know about.
[email protected]534e54b2008-08-13 15:40:091472 if (window_map_.find(window_or_tab) == window_map_.end()) {
1473 controller_id = next_window_id_++;
1474 window_map_[window_or_tab] = controller_id;
initial.commit09911bf2008-07-26 23:55:291475 } else {
[email protected]534e54b2008-08-13 15:40:091476 controller_id = window_map_[window_or_tab];
initial.commit09911bf2008-07-26 23:55:291477 }
[email protected]534e54b2008-08-13 15:40:091478 DCHECK(controller_id != -1);
initial.commit09911bf2008-07-26 23:55:291479
[email protected]bfd04a62009-02-01 18:16:561480 switch (type.value) {
1481 case NotificationType::TAB_PARENTED:
1482 case NotificationType::BROWSER_OPENED:
initial.commit09911bf2008-07-26 23:55:291483 window_type = MetricsLog::WINDOW_CREATE;
1484 break;
1485
[email protected]bfd04a62009-02-01 18:16:561486 case NotificationType::TAB_CLOSING:
1487 case NotificationType::BROWSER_CLOSED:
[email protected]534e54b2008-08-13 15:40:091488 window_map_.erase(window_map_.find(window_or_tab));
initial.commit09911bf2008-07-26 23:55:291489 window_type = MetricsLog::WINDOW_DESTROY;
1490 break;
1491
1492 default:
1493 NOTREACHED();
[email protected]68d74f02009-02-13 01:36:501494 return;
initial.commit09911bf2008-07-26 23:55:291495 }
1496
[email protected]534e54b2008-08-13 15:40:091497 // TODO(brettw) we should have some kind of ID for the parent.
1498 current_log_->RecordWindowEvent(window_type, controller_id, 0);
initial.commit09911bf2008-07-26 23:55:291499}
1500
1501void MetricsService::LogLoadComplete(NotificationType type,
1502 const NotificationSource& source,
1503 const NotificationDetails& details) {
1504 if (details == NotificationService::NoDetails())
1505 return;
1506
[email protected]68475e602008-08-22 03:21:151507 // TODO(jar): There is a bug causing this to be called too many times, and
1508 // the log overflows. For now, we won't record these events.
1509 UMA_HISTOGRAM_COUNTS(L"UMA.LogLoadComplete called", 1);
1510 return;
1511
initial.commit09911bf2008-07-26 23:55:291512 const Details<LoadNotificationDetails> load_details(details);
[email protected]534e54b2008-08-13 15:40:091513 int controller_id = window_map_[details.map_key()];
1514 current_log_->RecordLoadEvent(controller_id,
initial.commit09911bf2008-07-26 23:55:291515 load_details->url(),
1516 load_details->origin(),
1517 load_details->session_index(),
1518 load_details->load_time());
1519}
1520
[email protected]e73c01972008-08-13 00:18:241521void MetricsService::IncrementPrefValue(const wchar_t* path) {
1522 PrefService* pref = g_browser_process->local_state();
1523 DCHECK(pref);
1524 int value = pref->GetInteger(path);
1525 pref->SetInteger(path, value + 1);
1526}
1527
initial.commit09911bf2008-07-26 23:55:291528void MetricsService::LogLoadStarted() {
[email protected]e73c01972008-08-13 00:18:241529 IncrementPrefValue(prefs::kStabilityPageLoadCount);
[email protected]0b33f80b2008-12-17 21:34:361530 // We need to save the prefs, as page load count is a critical stat, and it
1531 // might be lost due to a crash :-(.
initial.commit09911bf2008-07-26 23:55:291532}
1533
1534void MetricsService::LogRendererInSandbox(bool on_sandbox_desktop) {
1535 PrefService* prefs = g_browser_process->local_state();
1536 DCHECK(prefs);
[email protected]e73c01972008-08-13 00:18:241537 if (on_sandbox_desktop)
1538 IncrementPrefValue(prefs::kSecurityRendererOnSboxDesktop);
1539 else
1540 IncrementPrefValue(prefs::kSecurityRendererOnDefaultDesktop);
initial.commit09911bf2008-07-26 23:55:291541}
1542
1543void MetricsService::LogRendererCrash() {
[email protected]e73c01972008-08-13 00:18:241544 IncrementPrefValue(prefs::kStabilityRendererCrashCount);
initial.commit09911bf2008-07-26 23:55:291545}
1546
1547void MetricsService::LogRendererHang() {
[email protected]e73c01972008-08-13 00:18:241548 IncrementPrefValue(prefs::kStabilityRendererHangCount);
initial.commit09911bf2008-07-26 23:55:291549}
1550
[email protected]a27a9382009-02-11 23:55:101551void MetricsService::LogChildProcessChange(
1552 NotificationType type,
1553 const NotificationSource& source,
1554 const NotificationDetails& details) {
1555 const std::wstring& child_name =
1556 Details<ChildProcessInfo>(details)->name();
initial.commit09911bf2008-07-26 23:55:291557
[email protected]a27a9382009-02-11 23:55:101558 if (child_process_stats_buffer_.find(child_name) ==
1559 child_process_stats_buffer_.end()) {
1560 child_process_stats_buffer_[child_name] = ChildProcessStats();
initial.commit09911bf2008-07-26 23:55:291561 }
1562
[email protected]a27a9382009-02-11 23:55:101563 ChildProcessStats& stats = child_process_stats_buffer_[child_name];
[email protected]bfd04a62009-02-01 18:16:561564 switch (type.value) {
[email protected]a27a9382009-02-11 23:55:101565 case NotificationType::CHILD_PROCESS_HOST_CONNECTED:
initial.commit09911bf2008-07-26 23:55:291566 stats.process_launches++;
1567 break;
1568
[email protected]a27a9382009-02-11 23:55:101569 case NotificationType::CHILD_INSTANCE_CREATED:
initial.commit09911bf2008-07-26 23:55:291570 stats.instances++;
1571 break;
1572
[email protected]a27a9382009-02-11 23:55:101573 case NotificationType::CHILD_PROCESS_CRASHED:
initial.commit09911bf2008-07-26 23:55:291574 stats.process_crashes++;
1575 break;
1576
1577 default:
[email protected]bfd04a62009-02-01 18:16:561578 NOTREACHED() << "Unexpected notification type " << type.value;
initial.commit09911bf2008-07-26 23:55:291579 return;
1580 }
1581}
1582
1583// Recursively counts the number of bookmarks and folders in node.
[email protected]d8e41ed2008-09-11 15:22:321584static void CountBookmarks(BookmarkNode* node, int* bookmarks, int* folders) {
initial.commit09911bf2008-07-26 23:55:291585 if (node->GetType() == history::StarredEntry::URL)
1586 (*bookmarks)++;
1587 else
1588 (*folders)++;
1589 for (int i = 0; i < node->GetChildCount(); ++i)
1590 CountBookmarks(node->GetChild(i), bookmarks, folders);
1591}
1592
[email protected]d8e41ed2008-09-11 15:22:321593void MetricsService::LogBookmarks(BookmarkNode* node,
initial.commit09911bf2008-07-26 23:55:291594 const wchar_t* num_bookmarks_key,
1595 const wchar_t* num_folders_key) {
1596 DCHECK(node);
1597 int num_bookmarks = 0;
1598 int num_folders = 0;
1599 CountBookmarks(node, &num_bookmarks, &num_folders);
1600 num_folders--; // Don't include the root folder in the count.
1601
1602 PrefService* pref = g_browser_process->local_state();
1603 DCHECK(pref);
1604 pref->SetInteger(num_bookmarks_key, num_bookmarks);
1605 pref->SetInteger(num_folders_key, num_folders);
1606}
1607
[email protected]d8e41ed2008-09-11 15:22:321608void MetricsService::LogBookmarks(BookmarkModel* model) {
initial.commit09911bf2008-07-26 23:55:291609 DCHECK(model);
1610 LogBookmarks(model->GetBookmarkBarNode(),
1611 prefs::kNumBookmarksOnBookmarkBar,
1612 prefs::kNumFoldersOnBookmarkBar);
1613 LogBookmarks(model->other_node(),
1614 prefs::kNumBookmarksInOtherBookmarkFolder,
1615 prefs::kNumFoldersInOtherBookmarkFolder);
1616 ScheduleNextStateSave();
1617}
1618
1619void MetricsService::LogKeywords(const TemplateURLModel* url_model) {
1620 DCHECK(url_model);
1621
1622 PrefService* pref = g_browser_process->local_state();
1623 DCHECK(pref);
1624 pref->SetInteger(prefs::kNumKeywords,
1625 static_cast<int>(url_model->GetTemplateURLs().size()));
1626 ScheduleNextStateSave();
1627}
1628
1629void MetricsService::RecordPluginChanges(PrefService* pref) {
1630 ListValue* plugins = pref->GetMutableList(prefs::kStabilityPluginStats);
1631 DCHECK(plugins);
1632
1633 for (ListValue::iterator value_iter = plugins->begin();
1634 value_iter != plugins->end(); ++value_iter) {
1635 if (!(*value_iter)->IsType(Value::TYPE_DICTIONARY)) {
1636 NOTREACHED();
1637 continue;
1638 }
1639
1640 DictionaryValue* plugin_dict = static_cast<DictionaryValue*>(*value_iter);
[email protected]a27a9382009-02-11 23:55:101641 std::wstring plugin_name;
1642 plugin_dict->GetString(prefs::kStabilityPluginName, &plugin_name);
1643 if (plugin_name.empty()) {
initial.commit09911bf2008-07-26 23:55:291644 NOTREACHED();
1645 continue;
1646 }
1647
[email protected]a27a9382009-02-11 23:55:101648 if (child_process_stats_buffer_.find(plugin_name) ==
1649 child_process_stats_buffer_.end())
initial.commit09911bf2008-07-26 23:55:291650 continue;
1651
[email protected]a27a9382009-02-11 23:55:101652 ChildProcessStats stats = child_process_stats_buffer_[plugin_name];
initial.commit09911bf2008-07-26 23:55:291653 if (stats.process_launches) {
1654 int launches = 0;
1655 plugin_dict->GetInteger(prefs::kStabilityPluginLaunches, &launches);
1656 launches += stats.process_launches;
1657 plugin_dict->SetInteger(prefs::kStabilityPluginLaunches, launches);
1658 }
1659 if (stats.process_crashes) {
1660 int crashes = 0;
1661 plugin_dict->GetInteger(prefs::kStabilityPluginCrashes, &crashes);
1662 crashes += stats.process_crashes;
1663 plugin_dict->SetInteger(prefs::kStabilityPluginCrashes, crashes);
1664 }
1665 if (stats.instances) {
1666 int instances = 0;
1667 plugin_dict->GetInteger(prefs::kStabilityPluginInstances, &instances);
1668 instances += stats.instances;
1669 plugin_dict->SetInteger(prefs::kStabilityPluginInstances, instances);
1670 }
1671
[email protected]a27a9382009-02-11 23:55:101672 child_process_stats_buffer_.erase(plugin_name);
initial.commit09911bf2008-07-26 23:55:291673 }
1674
1675 // Now go through and add dictionaries for plugins that didn't already have
1676 // reports in Local State.
[email protected]a27a9382009-02-11 23:55:101677 for (std::map<std::wstring, ChildProcessStats>::iterator cache_iter =
1678 child_process_stats_buffer_.begin();
1679 cache_iter != child_process_stats_buffer_.end(); ++cache_iter) {
1680 std::wstring plugin_name = cache_iter->first;
1681 ChildProcessStats stats = cache_iter->second;
initial.commit09911bf2008-07-26 23:55:291682 DictionaryValue* plugin_dict = new DictionaryValue;
1683
[email protected]a27a9382009-02-11 23:55:101684 plugin_dict->SetString(prefs::kStabilityPluginName, plugin_name);
initial.commit09911bf2008-07-26 23:55:291685 plugin_dict->SetInteger(prefs::kStabilityPluginLaunches,
1686 stats.process_launches);
1687 plugin_dict->SetInteger(prefs::kStabilityPluginCrashes,
1688 stats.process_crashes);
1689 plugin_dict->SetInteger(prefs::kStabilityPluginInstances,
1690 stats.instances);
1691 plugins->Append(plugin_dict);
1692 }
[email protected]a27a9382009-02-11 23:55:101693 child_process_stats_buffer_.clear();
initial.commit09911bf2008-07-26 23:55:291694}
1695
1696bool MetricsService::CanLogNotification(NotificationType type,
1697 const NotificationSource& source,
1698 const NotificationDetails& details) {
1699 // We simply don't log anything to UMA if there is a single off the record
1700 // session visible. The problem is that we always notify using the orginal
1701 // profile in order to simplify notification processing.
1702 return !BrowserList::IsOffTheRecordSessionActive();
1703}
1704
1705void MetricsService::RecordBooleanPrefValue(const wchar_t* path, bool value) {
1706 DCHECK(IsSingleThreaded());
1707
1708 PrefService* pref = g_browser_process->local_state();
1709 DCHECK(pref);
1710
1711 pref->SetBoolean(path, value);
1712 RecordCurrentState(pref);
1713}
1714
1715void MetricsService::RecordCurrentState(PrefService* pref) {
1716 pref->SetString(prefs::kStabilityLastTimestampSec,
1717 Int64ToWString(Time::Now().ToTimeT()));
1718
1719 RecordPluginChanges(pref);
1720}
1721
1722void MetricsService::RecordCurrentHistograms() {
1723 DCHECK(current_log_);
1724
1725 StatisticsRecorder::Histograms histograms;
1726 StatisticsRecorder::GetHistograms(&histograms);
1727 for (StatisticsRecorder::Histograms::iterator it = histograms.begin();
1728 histograms.end() != it;
[email protected]cac78842008-11-27 01:02:201729 ++it) {
initial.commit09911bf2008-07-26 23:55:291730 if ((*it)->flags() & kUmaTargetedHistogramFlag)
[email protected]0b33f80b2008-12-17 21:34:361731 // TODO(petersont): Only record historgrams if they are not precluded by
1732 // the UMA response data.
[email protected]d01b8732008-10-16 02:18:071733 // Bug http://code.google.com/p/chromium/issues/detail?id=2739.
initial.commit09911bf2008-07-26 23:55:291734 RecordHistogram(**it);
1735 }
1736}
1737
1738void MetricsService::RecordHistogram(const Histogram& histogram) {
1739 // Get up-to-date snapshot of sample stats.
1740 Histogram::SampleSet snapshot;
1741 histogram.SnapshotSample(&snapshot);
1742
1743 const std::string& histogram_name = histogram.histogram_name();
1744
1745 // Find the already sent stats, or create an empty set.
1746 LoggedSampleMap::iterator it = logged_samples_.find(histogram_name);
1747 Histogram::SampleSet* already_logged;
1748 if (logged_samples_.end() == it) {
1749 // Add new entry
1750 already_logged = &logged_samples_[histogram.histogram_name()];
1751 already_logged->Resize(histogram); // Complete initialization.
1752 } else {
1753 already_logged = &(it->second);
1754 // Deduct any stats we've already logged from our snapshot.
1755 snapshot.Subtract(*already_logged);
1756 }
1757
1758 // snapshot now contains only a delta to what we've already_logged.
1759
1760 if (snapshot.TotalCount() > 0) {
1761 current_log_->RecordHistogramDelta(histogram, snapshot);
1762 // Add new data into our running total.
1763 already_logged->Add(snapshot);
1764 }
1765}
1766
1767void MetricsService::AddProfileMetric(Profile* profile,
1768 const std::wstring& key,
1769 int value) {
1770 // Restriction of types is needed for writing values. See
1771 // MetricsLog::WriteProfileMetrics.
1772 DCHECK(profile && !key.empty());
1773 PrefService* prefs = g_browser_process->local_state();
1774 DCHECK(prefs);
1775
1776 // Key is stored in prefs, which interpret '.'s as paths. As such, key
1777 // shouldn't have any '.'s in it.
1778 DCHECK(key.find(L'.') == std::wstring::npos);
1779 // The id is most likely an email address. We shouldn't send it to the server.
1780 const std::wstring id_hash =
1781 UTF8ToWide(MetricsLog::CreateBase64Hash(WideToUTF8(profile->GetID())));
1782 DCHECK(id_hash.find('.') == std::string::npos);
1783
1784 DictionaryValue* prof_prefs = prefs->GetMutableDictionary(
1785 prefs::kProfileMetrics);
1786 DCHECK(prof_prefs);
1787 const std::wstring pref_key = std::wstring(prefs::kProfilePrefix) + id_hash +
1788 L"." + key;
1789 prof_prefs->SetInteger(pref_key.c_str(), value);
1790}
1791
1792static bool IsSingleThreaded() {
[email protected]dc6f4962009-02-13 01:25:501793 static PlatformThreadId thread_id = 0;
initial.commit09911bf2008-07-26 23:55:291794 if (!thread_id)
[email protected]dc6f4962009-02-13 01:25:501795 thread_id = PlatformThread::CurrentId();
1796 return PlatformThread::CurrentId() == thread_id;
initial.commit09911bf2008-07-26 23:55:291797}