blob: 2906ef3e0dfe4729b76a540e23004494ec7761e1 [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"
[email protected]fd49e2d2009-02-20 17:21:30176#include "chrome/browser/plugin_service.h"
initial.commit09911bf2008-07-26 23:55:29177#include "chrome/browser/profile.h"
[email protected]8c8657d62009-01-16 18:31:26178#include "chrome/browser/renderer_host/render_process_host.h"
[email protected]d54e03a52009-01-16 00:31:04179#include "chrome/browser/search_engines/template_url.h"
180#include "chrome/browser/search_engines/template_url_model.h"
[email protected]a27a9382009-02-11 23:55:10181#include "chrome/common/child_process_info.h"
initial.commit09911bf2008-07-26 23:55:29182#include "chrome/common/chrome_paths.h"
[email protected]252873ef2008-08-04 21:59:45183#include "chrome/common/libxml_utils.h"
[email protected]bfd04a62009-02-01 18:16:56184#include "chrome/common/notification_service.h"
initial.commit09911bf2008-07-26 23:55:29185#include "chrome/common/pref_names.h"
186#include "chrome/common/pref_service.h"
[email protected]e09ba552009-02-05 03:26:29187#include "chrome/common/render_messages.h"
initial.commit09911bf2008-07-26 23:55:29188#include "googleurl/src/gurl.h"
189#include "net/base/load_flags.h"
190#include "third_party/bzip2/bzlib.h"
191
[email protected]dc6f4962009-02-13 01:25:50192#if defined(OS_POSIX)
193// TODO(port): Move these headers above as they are ported.
194#include "chrome/common/temp_scaffolding_stubs.h"
195#else
[email protected]dc6f4962009-02-13 01:25:50196#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.
[email protected]f5d0e152009-02-19 21:54:37642 // Rather than actually implementing a random source, might this be a good
643 // time to implement http://code.google.com/p/chromium/issues/detail?id=2278
644 // ? I think so!
[email protected]dc6f4962009-02-13 01:25:50645 NOTIMPLEMENTED();
646 return std::string();
647#endif
initial.commit09911bf2008-07-26 23:55:29648}
649
650
651//------------------------------------------------------------------------------
652// State save methods
653
654void MetricsService::ScheduleNextStateSave() {
655 state_saver_factory_.RevokeAll();
656
657 MessageLoop::current()->PostDelayedTask(FROM_HERE,
658 state_saver_factory_.NewRunnableMethod(&MetricsService::SaveLocalState),
659 kSaveStateInterval * 1000);
660}
661
662void MetricsService::SaveLocalState() {
663 PrefService* pref = g_browser_process->local_state();
664 if (!pref) {
665 NOTREACHED();
666 return;
667 }
668
669 RecordCurrentState(pref);
670 pref->ScheduleSavePersistentPrefs(g_browser_process->file_thread());
671
[email protected]281d2882009-01-20 20:32:42672 // TODO(jar): Does this run down the batteries????
initial.commit09911bf2008-07-26 23:55:29673 ScheduleNextStateSave();
674}
675
676
677//------------------------------------------------------------------------------
678// Recording control methods
679
680void MetricsService::StartRecording() {
681 if (current_log_)
682 return;
683
684 current_log_ = new MetricsLog(client_id_, session_id_);
685 if (state_ == INITIALIZED) {
686 // We only need to schedule that run once.
687 state_ = PLUGIN_LIST_REQUESTED;
688
689 // Make sure the plugin list is loaded before the inital log is sent, so
690 // that the main thread isn't blocked generating the list.
691 g_browser_process->file_thread()->message_loop()->PostDelayedTask(FROM_HERE,
692 new GetPluginListTask(MessageLoop::current()),
[email protected]252873ef2008-08-04 21:59:45693 kInitialInterlogDuration * 1000 / 2);
initial.commit09911bf2008-07-26 23:55:29694 }
695}
696
697void MetricsService::StopRecording(MetricsLog** log) {
698 if (!current_log_)
699 return;
700
[email protected]68475e602008-08-22 03:21:15701 // TODO(jar): Integrate bounds on log recording more consistently, so that we
702 // can stop recording logs that are too big much sooner.
[email protected]d01b8732008-10-16 02:18:07703 if (current_log_->num_events() > log_event_limit_) {
[email protected]68475e602008-08-22 03:21:15704 UMA_HISTOGRAM_COUNTS(L"UMA.Discarded Log Events",
705 current_log_->num_events());
706 current_log_->CloseLog();
707 delete current_log_;
[email protected]294638782008-09-24 00:22:41708 current_log_ = NULL;
[email protected]68475e602008-08-22 03:21:15709 StartRecording(); // Start trivial log to hold our histograms.
710 }
711
[email protected]0b33f80b2008-12-17 21:34:36712 // Put incremental data (histogram deltas, and realtime stats deltas) at the
[email protected]147bbc0b2009-01-06 19:37:40713 // end of all log transmissions (initial log handles this separately).
initial.commit09911bf2008-07-26 23:55:29714 // Don't bother if we're going to discard current_log_.
[email protected]0b33f80b2008-12-17 21:34:36715 if (log) {
[email protected]54131d252009-02-09 05:49:22716 // TODO(jar): when initial logs and ongoing logs have equal survivability,
717 // uncomment the following line to expedite stability data uploads.
718 // current_log_->RecordIncrementalStabilityElements();
initial.commit09911bf2008-07-26 23:55:29719 RecordCurrentHistograms();
[email protected]0b33f80b2008-12-17 21:34:36720 }
initial.commit09911bf2008-07-26 23:55:29721
722 current_log_->CloseLog();
[email protected]cac78842008-11-27 01:02:20723 if (log)
initial.commit09911bf2008-07-26 23:55:29724 *log = current_log_;
[email protected]cac78842008-11-27 01:02:20725 else
initial.commit09911bf2008-07-26 23:55:29726 delete current_log_;
initial.commit09911bf2008-07-26 23:55:29727 current_log_ = NULL;
728}
729
730void MetricsService::ListenerRegistration(bool start_listening) {
[email protected]bfd04a62009-02-01 18:16:56731 AddOrRemoveObserver(this, NotificationType::BROWSER_OPENED, start_listening);
732 AddOrRemoveObserver(this, NotificationType::BROWSER_CLOSED, start_listening);
733 AddOrRemoveObserver(this, NotificationType::USER_ACTION, start_listening);
734 AddOrRemoveObserver(this, NotificationType::TAB_PARENTED, start_listening);
735 AddOrRemoveObserver(this, NotificationType::TAB_CLOSING, start_listening);
736 AddOrRemoveObserver(this, NotificationType::LOAD_START, start_listening);
737 AddOrRemoveObserver(this, NotificationType::LOAD_STOP, start_listening);
738 AddOrRemoveObserver(this, NotificationType::RENDERER_PROCESS_IN_SBOX,
initial.commit09911bf2008-07-26 23:55:29739 start_listening);
[email protected]bfd04a62009-02-01 18:16:56740 AddOrRemoveObserver(this, NotificationType::RENDERER_PROCESS_TERMINATED,
initial.commit09911bf2008-07-26 23:55:29741 start_listening);
[email protected]bfd04a62009-02-01 18:16:56742 AddOrRemoveObserver(this, NotificationType::RENDERER_PROCESS_HANG,
743 start_listening);
[email protected]a27a9382009-02-11 23:55:10744 AddOrRemoveObserver(this, NotificationType::CHILD_PROCESS_HOST_CONNECTED,
[email protected]bfd04a62009-02-01 18:16:56745 start_listening);
[email protected]a27a9382009-02-11 23:55:10746 AddOrRemoveObserver(this, NotificationType::CHILD_INSTANCE_CREATED,
[email protected]bfd04a62009-02-01 18:16:56747 start_listening);
[email protected]a27a9382009-02-11 23:55:10748 AddOrRemoveObserver(this, NotificationType::CHILD_PROCESS_CRASHED,
[email protected]bfd04a62009-02-01 18:16:56749 start_listening);
750 AddOrRemoveObserver(this, NotificationType::TEMPLATE_URL_MODEL_LOADED,
751 start_listening);
752 AddOrRemoveObserver(this, NotificationType::OMNIBOX_OPENED_URL,
753 start_listening);
754 AddOrRemoveObserver(this, NotificationType::BOOKMARK_MODEL_LOADED,
755 start_listening);
initial.commit09911bf2008-07-26 23:55:29756}
757
758// static
759void MetricsService::AddOrRemoveObserver(NotificationObserver* observer,
[email protected]cac78842008-11-27 01:02:20760 NotificationType type,
761 bool is_add) {
initial.commit09911bf2008-07-26 23:55:29762 NotificationService* service = NotificationService::current();
763
[email protected]cac78842008-11-27 01:02:20764 if (is_add)
initial.commit09911bf2008-07-26 23:55:29765 service->AddObserver(observer, type, NotificationService::AllSources());
[email protected]cac78842008-11-27 01:02:20766 else
initial.commit09911bf2008-07-26 23:55:29767 service->RemoveObserver(observer, type, NotificationService::AllSources());
initial.commit09911bf2008-07-26 23:55:29768}
769
770void MetricsService::PushPendingLogsToUnsentLists() {
771 if (state_ < INITIAL_LOG_READY)
[email protected]28ab7f92009-01-06 21:39:04772 return; // We didn't and still don't have time to get plugin list etc.
initial.commit09911bf2008-07-26 23:55:29773
774 if (pending_log()) {
775 PreparePendingLogText();
776 if (state_ == INITIAL_LOG_READY) {
777 // We may race here, and send second copy of initial log later.
778 unsent_initial_logs_.push_back(pending_log_text_);
[email protected]d01b8732008-10-16 02:18:07779 state_ = SEND_OLD_INITIAL_LOGS;
initial.commit09911bf2008-07-26 23:55:29780 } else {
[email protected]281d2882009-01-20 20:32:42781 // TODO(jar): Verify correctness in other states, including sending unsent
782 // iniitial logs.
[email protected]68475e602008-08-22 03:21:15783 PushPendingLogTextToUnsentOngoingLogs();
initial.commit09911bf2008-07-26 23:55:29784 }
785 DiscardPendingLog();
786 }
787 DCHECK(!pending_log());
788 StopRecording(&pending_log_);
789 PreparePendingLogText();
[email protected]68475e602008-08-22 03:21:15790 PushPendingLogTextToUnsentOngoingLogs();
initial.commit09911bf2008-07-26 23:55:29791 DiscardPendingLog();
792 StoreUnsentLogs();
793}
794
[email protected]68475e602008-08-22 03:21:15795void MetricsService::PushPendingLogTextToUnsentOngoingLogs() {
[email protected]d01b8732008-10-16 02:18:07796 // If UMA response told us not to upload, there's no need to save the pending
797 // log. It wasn't supposed to be uploaded anyway.
798 if (!server_permits_upload_)
799 return;
800
[email protected]dc6f4962009-02-13 01:25:50801 if (pending_log_text_.length() >
802 static_cast<size_t>(kUploadLogAvoidRetransmitSize)) {
[email protected]68475e602008-08-22 03:21:15803 UMA_HISTOGRAM_COUNTS(L"UMA.Large Accumulated Log Not Persisted",
804 static_cast<int>(pending_log_text_.length()));
805 return;
806 }
807 unsent_ongoing_logs_.push_back(pending_log_text_);
808}
809
initial.commit09911bf2008-07-26 23:55:29810//------------------------------------------------------------------------------
811// Transmission of logs methods
812
813void MetricsService::StartLogTransmissionTimer() {
[email protected]d01b8732008-10-16 02:18:07814 // If we're not reporting, there's no point in starting a log transmission
815 // timer.
816 if (!reporting_active())
817 return;
818
initial.commit09911bf2008-07-26 23:55:29819 if (!current_log_)
820 return; // Recorder is shutdown.
[email protected]d01b8732008-10-16 02:18:07821
822 // If there is already a timer running, we leave it running.
823 // If timer_pending is true because the fetch is waiting for a response,
824 // we return for now and let the response handler start the timer.
825 if (timer_pending_)
initial.commit09911bf2008-07-26 23:55:29826 return;
[email protected]d01b8732008-10-16 02:18:07827
[email protected]d01b8732008-10-16 02:18:07828 // Before starting the timer, set timer_pending_ to true.
initial.commit09911bf2008-07-26 23:55:29829 timer_pending_ = true;
[email protected]d01b8732008-10-16 02:18:07830
831 // Right before the UMA transmission gets started, there's one more thing we'd
832 // like to record: the histogram of memory usage, so we spawn a task to
833 // collect the memory details and when that task is finished, we arrange for
834 // TryToStartTransmission to take over.
initial.commit09911bf2008-07-26 23:55:29835 MessageLoop::current()->PostDelayedTask(FROM_HERE,
836 log_sender_factory_.
837 NewRunnableMethod(&MetricsService::CollectMemoryDetails),
838 static_cast<int>(interlog_duration_.InMilliseconds()));
839}
840
841void MetricsService::TryToStartTransmission() {
842 DCHECK(IsSingleThreaded());
843
[email protected]d01b8732008-10-16 02:18:07844 // This function should only be called via timer, so timer_pending_
845 // should be true.
846 DCHECK(timer_pending_);
847 timer_pending_ = false;
initial.commit09911bf2008-07-26 23:55:29848
849 DCHECK(!current_fetch_.get());
initial.commit09911bf2008-07-26 23:55:29850
[email protected]d01b8732008-10-16 02:18:07851 // If we're getting no notifications, then the log won't have much in it, and
852 // it's possible the computer is about to go to sleep, so don't upload and
853 // don't restart the transmission timer.
854 if (idle_since_last_transmission_)
855 return;
856
857 // If somehow there is a fetch in progress, we return setting timer_pending_
858 // to true and hope things work out.
859 if (current_fetch_.get()) {
860 timer_pending_ = true;
861 return;
862 }
863
864 // If uploads are forbidden by UMA response, there's no point in keeping
865 // the current_log_, and the more often we delete it, the less likely it is
866 // to expand forever.
867 if (!server_permits_upload_ && current_log_) {
868 StopRecording(NULL);
869 StartRecording();
870 }
initial.commit09911bf2008-07-26 23:55:29871
872 if (!current_log_)
873 return; // Logging was disabled.
[email protected]d01b8732008-10-16 02:18:07874 if (!reporting_active())
initial.commit09911bf2008-07-26 23:55:29875 return; // Don't do work if we're not going to send anything now.
876
[email protected]d01b8732008-10-16 02:18:07877 MakePendingLog();
initial.commit09911bf2008-07-26 23:55:29878
[email protected]d01b8732008-10-16 02:18:07879 // MakePendingLog should have put something in the pending log, if it didn't,
880 // we start the timer again, return and hope things work out.
881 if (!pending_log()) {
882 StartLogTransmissionTimer();
883 return;
884 }
initial.commit09911bf2008-07-26 23:55:29885
[email protected]d01b8732008-10-16 02:18:07886 // If we're not supposed to upload any UMA data because the response or the
887 // user said so, cancel the upload at this point, but start the timer.
888 if (!TransmissionPermitted()) {
889 DiscardPendingLog();
890 StartLogTransmissionTimer();
891 return;
892 }
initial.commit09911bf2008-07-26 23:55:29893
[email protected]d01b8732008-10-16 02:18:07894 PrepareFetchWithPendingLog();
895
896 if (!current_fetch_.get()) {
897 // Compression failed, and log discarded :-/.
898 DiscardPendingLog();
899 StartLogTransmissionTimer(); // Maybe we'll do better next time
900 // TODO(jar): If compression failed, we should have created a tiny log and
901 // compressed that, so that we can signal that we're losing logs.
902 return;
903 }
904
905 DCHECK(!timer_pending_);
906
907 // The URL fetch is a like timer in that after a while we get called back
908 // so we set timer_pending_ true just as we start the url fetch.
909 timer_pending_ = true;
910 current_fetch_->Start();
911
912 HandleIdleSinceLastTransmission(true);
913}
914
915
916void MetricsService::MakePendingLog() {
917 if (pending_log())
918 return;
919
920 switch (state_) {
921 case INITIALIZED:
922 case PLUGIN_LIST_REQUESTED: // We should be further along by now.
923 DCHECK(false);
924 return;
925
926 case PLUGIN_LIST_ARRIVED:
927 // We need to wait for the initial log to be ready before sending
928 // anything, because the server will tell us whether it wants to hear
929 // from us.
930 PrepareInitialLog();
931 DCHECK(state_ == PLUGIN_LIST_ARRIVED);
932 RecallUnsentLogs();
933 state_ = INITIAL_LOG_READY;
934 break;
935
936 case SEND_OLD_INITIAL_LOGS:
[email protected]cac78842008-11-27 01:02:20937 if (!unsent_initial_logs_.empty()) {
938 pending_log_text_ = unsent_initial_logs_.back();
939 break;
940 }
[email protected]d01b8732008-10-16 02:18:07941 state_ = SENDING_OLD_LOGS;
942 // Fall through.
initial.commit09911bf2008-07-26 23:55:29943
[email protected]d01b8732008-10-16 02:18:07944 case SENDING_OLD_LOGS:
945 if (!unsent_ongoing_logs_.empty()) {
946 pending_log_text_ = unsent_ongoing_logs_.back();
947 break;
948 }
949 state_ = SENDING_CURRENT_LOGS;
950 // Fall through.
951
952 case SENDING_CURRENT_LOGS:
953 StopRecording(&pending_log_);
954 StartRecording();
955 break;
956
957 default:
958 DCHECK(false);
959 return;
960 }
961
962 DCHECK(pending_log());
963}
964
965bool MetricsService::TransmissionPermitted() const {
966 // If the user forbids uploading that's they're business, and we don't upload
967 // anything. If the server forbids uploading, that's our business, so we take
968 // that to mean it forbids current logs, but we still send up the inital logs
969 // and any old logs.
[email protected]d01b8732008-10-16 02:18:07970 if (!user_permits_upload_)
971 return false;
[email protected]cac78842008-11-27 01:02:20972 if (server_permits_upload_)
[email protected]d01b8732008-10-16 02:18:07973 return true;
initial.commit09911bf2008-07-26 23:55:29974
[email protected]cac78842008-11-27 01:02:20975 switch (state_) {
976 case INITIAL_LOG_READY:
977 case SEND_OLD_INITIAL_LOGS:
978 case SENDING_OLD_LOGS:
979 return true;
980
981 case SENDING_CURRENT_LOGS:
982 default:
983 return false;
[email protected]8c8824b2008-09-20 01:55:50984 }
initial.commit09911bf2008-07-26 23:55:29985}
986
987void MetricsService::CollectMemoryDetails() {
988 Task* task = log_sender_factory_.
989 NewRunnableMethod(&MetricsService::TryToStartTransmission);
990 MetricsMemoryDetails* details = new MetricsMemoryDetails(task);
991 details->StartFetch();
992
993 // Collect WebCore cache information to put into a histogram.
994 for (RenderProcessHost::iterator it = RenderProcessHost::begin();
995 it != RenderProcessHost::end(); ++it) {
996 it->second->Send(new ViewMsg_GetCacheResourceStats());
997 }
998}
999
1000void MetricsService::PrepareInitialLog() {
1001 DCHECK(state_ == PLUGIN_LIST_ARRIVED);
1002 std::vector<WebPluginInfo> plugins;
1003 PluginService::GetInstance()->GetPlugins(false, &plugins);
1004
1005 MetricsLog* log = new MetricsLog(client_id_, session_id_);
1006 log->RecordEnvironment(plugins, profile_dictionary_.get());
1007
1008 // Histograms only get written to current_log_, so setup for the write.
1009 MetricsLog* save_log = current_log_;
1010 current_log_ = log;
1011 RecordCurrentHistograms(); // Into current_log_... which is really log.
1012 current_log_ = save_log;
1013
1014 log->CloseLog();
1015 DCHECK(!pending_log());
1016 pending_log_ = log;
1017}
1018
1019void MetricsService::RecallUnsentLogs() {
1020 DCHECK(unsent_initial_logs_.empty());
1021 DCHECK(unsent_ongoing_logs_.empty());
1022
1023 PrefService* local_state = g_browser_process->local_state();
1024 DCHECK(local_state);
1025
1026 ListValue* unsent_initial_logs = local_state->GetMutableList(
1027 prefs::kMetricsInitialLogs);
1028 for (ListValue::iterator it = unsent_initial_logs->begin();
1029 it != unsent_initial_logs->end(); ++it) {
[email protected]5e324b72008-12-18 00:07:591030 std::string log;
1031 (*it)->GetAsString(&log);
1032 unsent_initial_logs_.push_back(log);
initial.commit09911bf2008-07-26 23:55:291033 }
1034
1035 ListValue* unsent_ongoing_logs = local_state->GetMutableList(
1036 prefs::kMetricsOngoingLogs);
1037 for (ListValue::iterator it = unsent_ongoing_logs->begin();
1038 it != unsent_ongoing_logs->end(); ++it) {
[email protected]5e324b72008-12-18 00:07:591039 std::string log;
1040 (*it)->GetAsString(&log);
1041 unsent_ongoing_logs_.push_back(log);
initial.commit09911bf2008-07-26 23:55:291042 }
1043}
1044
1045void MetricsService::StoreUnsentLogs() {
1046 if (state_ < INITIAL_LOG_READY)
1047 return; // We never Recalled the prior unsent logs.
1048
1049 PrefService* local_state = g_browser_process->local_state();
1050 DCHECK(local_state);
1051
1052 ListValue* unsent_initial_logs = local_state->GetMutableList(
1053 prefs::kMetricsInitialLogs);
1054 unsent_initial_logs->Clear();
1055 size_t start = 0;
1056 if (unsent_initial_logs_.size() > kMaxInitialLogsPersisted)
1057 start = unsent_initial_logs_.size() - kMaxInitialLogsPersisted;
1058 for (size_t i = start; i < unsent_initial_logs_.size(); ++i)
1059 unsent_initial_logs->Append(
[email protected]5e324b72008-12-18 00:07:591060 Value::CreateStringValue(unsent_initial_logs_[i]));
initial.commit09911bf2008-07-26 23:55:291061
1062 ListValue* unsent_ongoing_logs = local_state->GetMutableList(
1063 prefs::kMetricsOngoingLogs);
1064 unsent_ongoing_logs->Clear();
1065 start = 0;
1066 if (unsent_ongoing_logs_.size() > kMaxOngoingLogsPersisted)
1067 start = unsent_ongoing_logs_.size() - kMaxOngoingLogsPersisted;
1068 for (size_t i = start; i < unsent_ongoing_logs_.size(); ++i)
1069 unsent_ongoing_logs->Append(
[email protected]5e324b72008-12-18 00:07:591070 Value::CreateStringValue(unsent_ongoing_logs_[i]));
initial.commit09911bf2008-07-26 23:55:291071}
1072
1073void MetricsService::PreparePendingLogText() {
1074 DCHECK(pending_log());
1075 if (!pending_log_text_.empty())
1076 return;
1077 int original_size = pending_log_->GetEncodedLogSize();
1078 pending_log_->GetEncodedLog(WriteInto(&pending_log_text_, original_size),
1079 original_size);
1080}
1081
[email protected]d01b8732008-10-16 02:18:071082void MetricsService::PrepareFetchWithPendingLog() {
initial.commit09911bf2008-07-26 23:55:291083 DCHECK(pending_log());
1084 DCHECK(!current_fetch_.get());
1085 PreparePendingLogText();
1086 DCHECK(!pending_log_text_.empty());
1087
1088 // Allow security conscious users to see all metrics logs that we send.
1089 LOG(INFO) << "METRICS LOG: " << pending_log_text_;
1090
1091 std::string compressed_log;
[email protected]cac78842008-11-27 01:02:201092 if (!Bzip2Compress(pending_log_text_, &compressed_log)) {
initial.commit09911bf2008-07-26 23:55:291093 NOTREACHED() << "Failed to compress log for transmission.";
1094 DiscardPendingLog();
1095 StartLogTransmissionTimer(); // Maybe we'll do better on next log :-/.
1096 return;
1097 }
[email protected]cac78842008-11-27 01:02:201098
initial.commit09911bf2008-07-26 23:55:291099 current_fetch_.reset(new URLFetcher(GURL(kMetricsURL), URLFetcher::POST,
1100 this));
1101 current_fetch_->set_request_context(Profile::GetDefaultRequestContext());
1102 current_fetch_->set_upload_data(kMetricsType, compressed_log);
initial.commit09911bf2008-07-26 23:55:291103}
1104
1105void MetricsService::DiscardPendingLog() {
1106 if (pending_log_) { // Shutdown might have deleted it!
1107 delete pending_log_;
1108 pending_log_ = NULL;
1109 }
1110 pending_log_text_.clear();
1111}
1112
1113// This implementation is based on the Firefox MetricsService implementation.
1114bool MetricsService::Bzip2Compress(const std::string& input,
1115 std::string* output) {
1116 bz_stream stream = {0};
1117 // As long as our input is smaller than the bzip2 block size, we should get
1118 // the best compression. For example, if your input was 250k, using a block
1119 // size of 300k or 500k should result in the same compression ratio. Since
1120 // our data should be under 100k, using the minimum block size of 100k should
1121 // allocate less temporary memory, but result in the same compression ratio.
1122 int result = BZ2_bzCompressInit(&stream,
1123 1, // 100k (min) block size
1124 0, // quiet
1125 0); // default "work factor"
1126 if (result != BZ_OK) { // out of memory?
1127 return false;
1128 }
1129
1130 output->clear();
1131
1132 stream.next_in = const_cast<char*>(input.data());
1133 stream.avail_in = static_cast<int>(input.size());
1134 // NOTE: we don't need a BZ_RUN phase since our input buffer contains
1135 // the entire input
1136 do {
1137 output->resize(output->size() + 1024);
1138 stream.next_out = &((*output)[stream.total_out_lo32]);
1139 stream.avail_out = static_cast<int>(output->size()) - stream.total_out_lo32;
1140 result = BZ2_bzCompress(&stream, BZ_FINISH);
1141 } while (result == BZ_FINISH_OK);
1142 if (result != BZ_STREAM_END) // unknown failure?
1143 return false;
1144 result = BZ2_bzCompressEnd(&stream);
1145 DCHECK(result == BZ_OK);
1146
1147 output->resize(stream.total_out_lo32);
1148
1149 return true;
1150}
1151
1152static const char* StatusToString(const URLRequestStatus& status) {
1153 switch (status.status()) {
1154 case URLRequestStatus::SUCCESS:
1155 return "SUCCESS";
1156
1157 case URLRequestStatus::IO_PENDING:
1158 return "IO_PENDING";
1159
1160 case URLRequestStatus::HANDLED_EXTERNALLY:
1161 return "HANDLED_EXTERNALLY";
1162
1163 case URLRequestStatus::CANCELED:
1164 return "CANCELED";
1165
1166 case URLRequestStatus::FAILED:
1167 return "FAILED";
1168
1169 default:
1170 NOTREACHED();
1171 return "Unknown";
1172 }
1173}
1174
1175void MetricsService::OnURLFetchComplete(const URLFetcher* source,
1176 const GURL& url,
1177 const URLRequestStatus& status,
1178 int response_code,
1179 const ResponseCookies& cookies,
1180 const std::string& data) {
1181 DCHECK(timer_pending_);
1182 timer_pending_ = false;
1183 DCHECK(current_fetch_.get());
1184 current_fetch_.reset(NULL); // We're not allowed to re-use it.
1185
1186 // Confirm send so that we can move on.
[email protected]281d2882009-01-20 20:32:421187 LOG(INFO) << "METRICS RESPONSE CODE: " << response_code << " status=" <<
[email protected]cac78842008-11-27 01:02:201188 StatusToString(status);
[email protected]252873ef2008-08-04 21:59:451189
[email protected]0eb34fee2009-01-21 08:04:381190 // Provide boolean for error recovery (allow us to ignore response_code).
[email protected]dc6f4962009-02-13 01:25:501191 bool discard_log = false;
[email protected]0eb34fee2009-01-21 08:04:381192
[email protected]68475e602008-08-22 03:21:151193 if (response_code != 200 &&
[email protected]dc6f4962009-02-13 01:25:501194 pending_log_text_.length() >
1195 static_cast<size_t>(kUploadLogAvoidRetransmitSize)) {
[email protected]68475e602008-08-22 03:21:151196 UMA_HISTOGRAM_COUNTS(L"UMA.Large Rejected Log was Discarded",
1197 static_cast<int>(pending_log_text_.length()));
[email protected]0eb34fee2009-01-21 08:04:381198 discard_log = true;
1199 } else if (response_code == 400) {
1200 // Bad syntax. Retransmission won't work.
1201 UMA_HISTOGRAM_COUNTS(L"UMA.Unacceptable_Log_Discarded", state_);
1202 discard_log = true;
[email protected]68475e602008-08-22 03:21:151203 }
1204
[email protected]0eb34fee2009-01-21 08:04:381205 if (response_code != 200 && !discard_log) {
[email protected]281d2882009-01-20 20:32:421206 LOG(INFO) << "METRICS: transmission attempt returned a failure code: "
1207 << response_code << ". Verify network connectivity";
[email protected]252873ef2008-08-04 21:59:451208 HandleBadResponseCode();
[email protected]0eb34fee2009-01-21 08:04:381209 } else { // Successful receipt (or we are discarding log).
[email protected]281d2882009-01-20 20:32:421210 LOG(INFO) << "METRICS RESPONSE DATA: " << data;
initial.commit09911bf2008-07-26 23:55:291211 switch (state_) {
1212 case INITIAL_LOG_READY:
1213 state_ = SEND_OLD_INITIAL_LOGS;
1214 break;
1215
1216 case SEND_OLD_INITIAL_LOGS:
1217 DCHECK(!unsent_initial_logs_.empty());
1218 unsent_initial_logs_.pop_back();
1219 StoreUnsentLogs();
1220 break;
1221
1222 case SENDING_OLD_LOGS:
1223 DCHECK(!unsent_ongoing_logs_.empty());
1224 unsent_ongoing_logs_.pop_back();
1225 StoreUnsentLogs();
1226 break;
1227
1228 case SENDING_CURRENT_LOGS:
1229 break;
1230
1231 default:
1232 DCHECK(false);
1233 break;
1234 }
[email protected]d01b8732008-10-16 02:18:071235
initial.commit09911bf2008-07-26 23:55:291236 DiscardPendingLog();
[email protected]29be92552008-08-07 22:49:271237 // Since we sent a log, make sure our in-memory state is recorded to disk.
1238 PrefService* local_state = g_browser_process->local_state();
1239 DCHECK(local_state);
1240 if (local_state)
1241 local_state->ScheduleSavePersistentPrefs(
1242 g_browser_process->file_thread());
[email protected]252873ef2008-08-04 21:59:451243
[email protected]147bbc0b2009-01-06 19:37:401244 // Provide a default (free of exponetial backoff, other varances) in case
1245 // the server does not specify a value.
1246 interlog_duration_ = TimeDelta::FromSeconds(kMinSecondsPerLog);
1247
[email protected]252873ef2008-08-04 21:59:451248 GetSettingsFromResponseData(data);
[email protected]252873ef2008-08-04 21:59:451249 // Override server specified interlog delay if there are unsent logs to
[email protected]29be92552008-08-07 22:49:271250 // transmit.
initial.commit09911bf2008-07-26 23:55:291251 if (unsent_logs()) {
1252 DCHECK(state_ < SENDING_CURRENT_LOGS);
1253 interlog_duration_ = TimeDelta::FromSeconds(kUnsentLogDelay);
initial.commit09911bf2008-07-26 23:55:291254 }
1255 }
[email protected]252873ef2008-08-04 21:59:451256
initial.commit09911bf2008-07-26 23:55:291257 StartLogTransmissionTimer();
1258}
1259
[email protected]252873ef2008-08-04 21:59:451260void MetricsService::HandleBadResponseCode() {
[email protected]281d2882009-01-20 20:32:421261 LOG(INFO) << "Verify your metrics logs are formatted correctly. "
[email protected]cac78842008-11-27 01:02:201262 "Verify server is active at " << kMetricsURL;
[email protected]252873ef2008-08-04 21:59:451263 if (!pending_log()) {
[email protected]281d2882009-01-20 20:32:421264 LOG(INFO) << "METRICS: Recorder shutdown during log transmission.";
[email protected]252873ef2008-08-04 21:59:451265 } else {
1266 // Send progressively less frequently.
1267 DCHECK(kBackoff > 1.0);
1268 interlog_duration_ = TimeDelta::FromMicroseconds(
1269 static_cast<int64>(kBackoff * interlog_duration_.InMicroseconds()));
1270
1271 if (kMaxBackoff * TimeDelta::FromSeconds(kMinSecondsPerLog) <
[email protected]cac78842008-11-27 01:02:201272 interlog_duration_) {
[email protected]252873ef2008-08-04 21:59:451273 interlog_duration_ = kMaxBackoff *
1274 TimeDelta::FromSeconds(kMinSecondsPerLog);
[email protected]cac78842008-11-27 01:02:201275 }
[email protected]252873ef2008-08-04 21:59:451276
[email protected]281d2882009-01-20 20:32:421277 LOG(INFO) << "METRICS: transmission retry being scheduled in " <<
[email protected]252873ef2008-08-04 21:59:451278 interlog_duration_.InSeconds() << " seconds for " <<
1279 pending_log_text_;
initial.commit09911bf2008-07-26 23:55:291280 }
initial.commit09911bf2008-07-26 23:55:291281}
1282
[email protected]252873ef2008-08-04 21:59:451283void MetricsService::GetSettingsFromResponseData(const std::string& data) {
1284 // We assume that the file is structured as a block opened by <response>
[email protected]d01b8732008-10-16 02:18:071285 // and that inside response, there is a block opened by tag <chrome_config>
1286 // other tags are ignored for now except the content of <chrome_config>.
[email protected]281d2882009-01-20 20:32:421287 LOG(INFO) << "METRICS: getting settings from response data: " << data;
[email protected]d01b8732008-10-16 02:18:071288
[email protected]252873ef2008-08-04 21:59:451289 int data_size = static_cast<int>(data.size());
1290 if (data_size < 0) {
[email protected]281d2882009-01-20 20:32:421291 LOG(INFO) << "METRICS: server response data bad size: " << data_size <<
[email protected]cac78842008-11-27 01:02:201292 "; aborting extraction of settings";
[email protected]252873ef2008-08-04 21:59:451293 return;
1294 }
[email protected]cac78842008-11-27 01:02:201295 xmlDocPtr doc = xmlReadMemory(data.c_str(), data_size, "", NULL, 0);
[email protected]252873ef2008-08-04 21:59:451296 DCHECK(doc);
[email protected]d01b8732008-10-16 02:18:071297 // If the document is malformed, we just use the settings that were there.
1298 if (!doc) {
[email protected]281d2882009-01-20 20:32:421299 LOG(INFO) << "METRICS: reading xml from server response data failed";
[email protected]252873ef2008-08-04 21:59:451300 return;
[email protected]d01b8732008-10-16 02:18:071301 }
[email protected]252873ef2008-08-04 21:59:451302
[email protected]d01b8732008-10-16 02:18:071303 xmlNodePtr top_node = xmlDocGetRootElement(doc), chrome_config_node = NULL;
1304 // Here, we find the chrome_config node by name.
[email protected]252873ef2008-08-04 21:59:451305 for (xmlNodePtr p = top_node->children; p; p = p->next) {
[email protected]d01b8732008-10-16 02:18:071306 if (xmlStrEqual(p->name, BAD_CAST "chrome_config")) {
1307 chrome_config_node = p;
[email protected]252873ef2008-08-04 21:59:451308 break;
1309 }
1310 }
1311 // If the server data is formatted wrong and there is no
1312 // config node where we expect, we just drop out.
[email protected]d01b8732008-10-16 02:18:071313 if (chrome_config_node != NULL)
1314 GetSettingsFromChromeConfigNode(chrome_config_node);
[email protected]252873ef2008-08-04 21:59:451315 xmlFreeDoc(doc);
1316}
1317
[email protected]d01b8732008-10-16 02:18:071318void MetricsService::GetSettingsFromChromeConfigNode(
1319 xmlNodePtr chrome_config_node) {
1320 // Iterate through all children of the config node.
1321 for (xmlNodePtr current_node = chrome_config_node->children;
1322 current_node;
1323 current_node = current_node->next) {
1324 // If we find the upload tag, we appeal to another function
1325 // GetSettingsFromUploadNode to read all the data in it.
[email protected]252873ef2008-08-04 21:59:451326 if (xmlStrEqual(current_node->name, BAD_CAST "upload")) {
[email protected]d01b8732008-10-16 02:18:071327 GetSettingsFromUploadNode(current_node);
[email protected]252873ef2008-08-04 21:59:451328 continue;
1329 }
1330 }
1331}
initial.commit09911bf2008-07-26 23:55:291332
[email protected]d01b8732008-10-16 02:18:071333void MetricsService::InheritedProperties::OverwriteWhereNeeded(
1334 xmlNodePtr node) {
1335 xmlChar* salt_value = xmlGetProp(node, BAD_CAST "salt");
1336 if (salt_value) // If the property isn't there, xmlGetProp returns NULL.
1337 salt = atoi(reinterpret_cast<char*>(salt_value));
1338 // If the property isn't there, we keep the value the property had before
1339
1340 xmlChar* denominator_value = xmlGetProp(node, BAD_CAST "denominator");
1341 if (denominator_value)
1342 denominator = atoi(reinterpret_cast<char*>(denominator_value));
1343}
1344
1345void MetricsService::GetSettingsFromUploadNode(xmlNodePtr upload_node) {
1346 InheritedProperties props;
1347 GetSettingsFromUploadNodeRecursive(upload_node, props, "", true);
1348}
1349
[email protected]cac78842008-11-27 01:02:201350void MetricsService::GetSettingsFromUploadNodeRecursive(
1351 xmlNodePtr node,
1352 InheritedProperties props,
1353 std::string path_prefix,
1354 bool uploadOn) {
[email protected]d01b8732008-10-16 02:18:071355 props.OverwriteWhereNeeded(node);
1356
1357 // The bool uploadOn is set to true if the data represented by current
1358 // node should be uploaded. This gets inherited in the tree; the children
1359 // of a node that has already been rejected for upload get rejected for
1360 // upload.
1361 uploadOn = uploadOn && NodeProbabilityTest(node, props);
1362
1363 // The path is a / separated list of the node names ancestral to the current
1364 // one. So, if you want to check if the current node has a certain name,
1365 // compare to name. If you want to check if it is a certan tag at a certain
1366 // place in the tree, compare to the whole path.
1367 std::string name = std::string(reinterpret_cast<const char*>(node->name));
1368 std::string path = path_prefix + "/" + name;
1369
1370 if (path == "/upload") {
1371 xmlChar* upload_interval_val = xmlGetProp(node, BAD_CAST "interval");
1372 if (upload_interval_val) {
1373 interlog_duration_ = TimeDelta::FromSeconds(
1374 atoi(reinterpret_cast<char*>(upload_interval_val)));
1375 }
1376
1377 server_permits_upload_ = uploadOn;
1378 }
1379 if (path == "/upload/logs") {
1380 xmlChar* log_event_limit_val = xmlGetProp(node, BAD_CAST "event_limit");
1381 if (log_event_limit_val)
1382 log_event_limit_ = atoi(reinterpret_cast<char*>(log_event_limit_val));
1383 }
1384 if (name == "histogram") {
1385 xmlChar* type_value = xmlGetProp(node, BAD_CAST "type");
1386 if (type_value) {
1387 std::string type = (reinterpret_cast<char*>(type_value));
1388 if (uploadOn)
1389 histograms_to_upload_.insert(type);
1390 else
1391 histograms_to_omit_.insert(type);
1392 }
1393 }
1394 if (name == "log") {
1395 xmlChar* type_value = xmlGetProp(node, BAD_CAST "type");
1396 if (type_value) {
1397 std::string type = (reinterpret_cast<char*>(type_value));
1398 if (uploadOn)
1399 logs_to_upload_.insert(type);
1400 else
1401 logs_to_omit_.insert(type);
1402 }
1403 }
1404
1405 // Recursive call. If the node is a leaf i.e. if it ends in a "/>", then it
1406 // doesn't have children, so node->children is NULL, and this loop doesn't
1407 // call (that's how the recursion ends).
1408 for (xmlNodePtr child_node = node->children;
[email protected]cac78842008-11-27 01:02:201409 child_node;
1410 child_node = child_node->next) {
[email protected]d01b8732008-10-16 02:18:071411 GetSettingsFromUploadNodeRecursive(child_node, props, path, uploadOn);
1412 }
1413}
1414
1415bool MetricsService::NodeProbabilityTest(xmlNodePtr node,
[email protected]cac78842008-11-27 01:02:201416 InheritedProperties props) const {
[email protected]d01b8732008-10-16 02:18:071417 // Default value of probability on any node is 1, but recall that
1418 // its parents can already have been rejected for upload.
1419 double probability = 1;
1420
1421 // If a probability is specified in the node, we use it instead.
1422 xmlChar* probability_value = xmlGetProp(node, BAD_CAST "probability");
1423 if (probability_value)
[email protected]0b33f80b2008-12-17 21:34:361424 probability = atoi(reinterpret_cast<char*>(probability_value));
[email protected]d01b8732008-10-16 02:18:071425
1426 return ProbabilityTest(probability, props.salt, props.denominator);
1427}
1428
1429bool MetricsService::ProbabilityTest(double probability,
1430 int salt,
1431 int denominator) const {
1432 // Okay, first we figure out how many of the digits of the
1433 // client_id_ we need in order to make a nice pseudorandomish
1434 // number in the range [0,denominator). Too many digits is
1435 // fine.
[email protected]d01b8732008-10-16 02:18:071436
1437 // n is the length of the client_id_ string
1438 size_t n = client_id_.size();
1439
1440 // idnumber is a positive integer generated from the client_id_.
1441 // It plus salt is going to give us our pseudorandom number.
1442 int idnumber = 0;
1443 const char* client_id_c_str = client_id_.c_str();
1444
1445 // Here we hash the relevant digits of the client_id_
1446 // string somehow to get a big integer idnumber (could be negative
1447 // from wraparound)
1448 int big = 1;
[email protected]cac78842008-11-27 01:02:201449 for (size_t j = n - 1; j >= 0; --j) {
1450 idnumber += static_cast<int>(client_id_c_str[j]) * big;
[email protected]d01b8732008-10-16 02:18:071451 big *= 10;
1452 }
1453
1454 // Mod id number by denominator making sure to get a non-negative
1455 // answer.
[email protected]cac78842008-11-27 01:02:201456 idnumber = ((idnumber % denominator) + denominator) % denominator;
[email protected]d01b8732008-10-16 02:18:071457
[email protected]cac78842008-11-27 01:02:201458 // ((idnumber + salt) % denominator) / denominator is in the range [0,1]
[email protected]d01b8732008-10-16 02:18:071459 // if it's less than probability we call that an affirmative coin
1460 // toss.
[email protected]cac78842008-11-27 01:02:201461 return static_cast<double>((idnumber + salt) % denominator) <
1462 probability * denominator;
[email protected]d01b8732008-10-16 02:18:071463}
1464
initial.commit09911bf2008-07-26 23:55:291465void MetricsService::LogWindowChange(NotificationType type,
1466 const NotificationSource& source,
1467 const NotificationDetails& details) {
[email protected]534e54b2008-08-13 15:40:091468 int controller_id = -1;
1469 uintptr_t window_or_tab = source.map_key();
initial.commit09911bf2008-07-26 23:55:291470 MetricsLog::WindowEventType window_type;
1471
1472 // Note: since we stop all logging when a single OTR session is active, it is
1473 // possible that we start getting notifications about a window that we don't
1474 // know about.
[email protected]534e54b2008-08-13 15:40:091475 if (window_map_.find(window_or_tab) == window_map_.end()) {
1476 controller_id = next_window_id_++;
1477 window_map_[window_or_tab] = controller_id;
initial.commit09911bf2008-07-26 23:55:291478 } else {
[email protected]534e54b2008-08-13 15:40:091479 controller_id = window_map_[window_or_tab];
initial.commit09911bf2008-07-26 23:55:291480 }
[email protected]534e54b2008-08-13 15:40:091481 DCHECK(controller_id != -1);
initial.commit09911bf2008-07-26 23:55:291482
[email protected]bfd04a62009-02-01 18:16:561483 switch (type.value) {
1484 case NotificationType::TAB_PARENTED:
1485 case NotificationType::BROWSER_OPENED:
initial.commit09911bf2008-07-26 23:55:291486 window_type = MetricsLog::WINDOW_CREATE;
1487 break;
1488
[email protected]bfd04a62009-02-01 18:16:561489 case NotificationType::TAB_CLOSING:
1490 case NotificationType::BROWSER_CLOSED:
[email protected]534e54b2008-08-13 15:40:091491 window_map_.erase(window_map_.find(window_or_tab));
initial.commit09911bf2008-07-26 23:55:291492 window_type = MetricsLog::WINDOW_DESTROY;
1493 break;
1494
1495 default:
1496 NOTREACHED();
[email protected]68d74f02009-02-13 01:36:501497 return;
initial.commit09911bf2008-07-26 23:55:291498 }
1499
[email protected]534e54b2008-08-13 15:40:091500 // TODO(brettw) we should have some kind of ID for the parent.
1501 current_log_->RecordWindowEvent(window_type, controller_id, 0);
initial.commit09911bf2008-07-26 23:55:291502}
1503
1504void MetricsService::LogLoadComplete(NotificationType type,
1505 const NotificationSource& source,
1506 const NotificationDetails& details) {
1507 if (details == NotificationService::NoDetails())
1508 return;
1509
[email protected]68475e602008-08-22 03:21:151510 // TODO(jar): There is a bug causing this to be called too many times, and
1511 // the log overflows. For now, we won't record these events.
1512 UMA_HISTOGRAM_COUNTS(L"UMA.LogLoadComplete called", 1);
1513 return;
1514
initial.commit09911bf2008-07-26 23:55:291515 const Details<LoadNotificationDetails> load_details(details);
[email protected]534e54b2008-08-13 15:40:091516 int controller_id = window_map_[details.map_key()];
1517 current_log_->RecordLoadEvent(controller_id,
initial.commit09911bf2008-07-26 23:55:291518 load_details->url(),
1519 load_details->origin(),
1520 load_details->session_index(),
1521 load_details->load_time());
1522}
1523
[email protected]e73c01972008-08-13 00:18:241524void MetricsService::IncrementPrefValue(const wchar_t* path) {
1525 PrefService* pref = g_browser_process->local_state();
1526 DCHECK(pref);
1527 int value = pref->GetInteger(path);
1528 pref->SetInteger(path, value + 1);
1529}
1530
initial.commit09911bf2008-07-26 23:55:291531void MetricsService::LogLoadStarted() {
[email protected]e73c01972008-08-13 00:18:241532 IncrementPrefValue(prefs::kStabilityPageLoadCount);
[email protected]0b33f80b2008-12-17 21:34:361533 // We need to save the prefs, as page load count is a critical stat, and it
1534 // might be lost due to a crash :-(.
initial.commit09911bf2008-07-26 23:55:291535}
1536
1537void MetricsService::LogRendererInSandbox(bool on_sandbox_desktop) {
1538 PrefService* prefs = g_browser_process->local_state();
1539 DCHECK(prefs);
[email protected]e73c01972008-08-13 00:18:241540 if (on_sandbox_desktop)
1541 IncrementPrefValue(prefs::kSecurityRendererOnSboxDesktop);
1542 else
1543 IncrementPrefValue(prefs::kSecurityRendererOnDefaultDesktop);
initial.commit09911bf2008-07-26 23:55:291544}
1545
1546void MetricsService::LogRendererCrash() {
[email protected]e73c01972008-08-13 00:18:241547 IncrementPrefValue(prefs::kStabilityRendererCrashCount);
initial.commit09911bf2008-07-26 23:55:291548}
1549
1550void MetricsService::LogRendererHang() {
[email protected]e73c01972008-08-13 00:18:241551 IncrementPrefValue(prefs::kStabilityRendererHangCount);
initial.commit09911bf2008-07-26 23:55:291552}
1553
[email protected]a27a9382009-02-11 23:55:101554void MetricsService::LogChildProcessChange(
1555 NotificationType type,
1556 const NotificationSource& source,
1557 const NotificationDetails& details) {
1558 const std::wstring& child_name =
1559 Details<ChildProcessInfo>(details)->name();
initial.commit09911bf2008-07-26 23:55:291560
[email protected]a27a9382009-02-11 23:55:101561 if (child_process_stats_buffer_.find(child_name) ==
1562 child_process_stats_buffer_.end()) {
1563 child_process_stats_buffer_[child_name] = ChildProcessStats();
initial.commit09911bf2008-07-26 23:55:291564 }
1565
[email protected]a27a9382009-02-11 23:55:101566 ChildProcessStats& stats = child_process_stats_buffer_[child_name];
[email protected]bfd04a62009-02-01 18:16:561567 switch (type.value) {
[email protected]a27a9382009-02-11 23:55:101568 case NotificationType::CHILD_PROCESS_HOST_CONNECTED:
initial.commit09911bf2008-07-26 23:55:291569 stats.process_launches++;
1570 break;
1571
[email protected]a27a9382009-02-11 23:55:101572 case NotificationType::CHILD_INSTANCE_CREATED:
initial.commit09911bf2008-07-26 23:55:291573 stats.instances++;
1574 break;
1575
[email protected]a27a9382009-02-11 23:55:101576 case NotificationType::CHILD_PROCESS_CRASHED:
initial.commit09911bf2008-07-26 23:55:291577 stats.process_crashes++;
1578 break;
1579
1580 default:
[email protected]bfd04a62009-02-01 18:16:561581 NOTREACHED() << "Unexpected notification type " << type.value;
initial.commit09911bf2008-07-26 23:55:291582 return;
1583 }
1584}
1585
1586// Recursively counts the number of bookmarks and folders in node.
[email protected]d8e41ed2008-09-11 15:22:321587static void CountBookmarks(BookmarkNode* node, int* bookmarks, int* folders) {
initial.commit09911bf2008-07-26 23:55:291588 if (node->GetType() == history::StarredEntry::URL)
1589 (*bookmarks)++;
1590 else
1591 (*folders)++;
1592 for (int i = 0; i < node->GetChildCount(); ++i)
1593 CountBookmarks(node->GetChild(i), bookmarks, folders);
1594}
1595
[email protected]d8e41ed2008-09-11 15:22:321596void MetricsService::LogBookmarks(BookmarkNode* node,
initial.commit09911bf2008-07-26 23:55:291597 const wchar_t* num_bookmarks_key,
1598 const wchar_t* num_folders_key) {
1599 DCHECK(node);
1600 int num_bookmarks = 0;
1601 int num_folders = 0;
1602 CountBookmarks(node, &num_bookmarks, &num_folders);
1603 num_folders--; // Don't include the root folder in the count.
1604
1605 PrefService* pref = g_browser_process->local_state();
1606 DCHECK(pref);
1607 pref->SetInteger(num_bookmarks_key, num_bookmarks);
1608 pref->SetInteger(num_folders_key, num_folders);
1609}
1610
[email protected]d8e41ed2008-09-11 15:22:321611void MetricsService::LogBookmarks(BookmarkModel* model) {
initial.commit09911bf2008-07-26 23:55:291612 DCHECK(model);
1613 LogBookmarks(model->GetBookmarkBarNode(),
1614 prefs::kNumBookmarksOnBookmarkBar,
1615 prefs::kNumFoldersOnBookmarkBar);
1616 LogBookmarks(model->other_node(),
1617 prefs::kNumBookmarksInOtherBookmarkFolder,
1618 prefs::kNumFoldersInOtherBookmarkFolder);
1619 ScheduleNextStateSave();
1620}
1621
1622void MetricsService::LogKeywords(const TemplateURLModel* url_model) {
1623 DCHECK(url_model);
1624
1625 PrefService* pref = g_browser_process->local_state();
1626 DCHECK(pref);
1627 pref->SetInteger(prefs::kNumKeywords,
1628 static_cast<int>(url_model->GetTemplateURLs().size()));
1629 ScheduleNextStateSave();
1630}
1631
1632void MetricsService::RecordPluginChanges(PrefService* pref) {
1633 ListValue* plugins = pref->GetMutableList(prefs::kStabilityPluginStats);
1634 DCHECK(plugins);
1635
1636 for (ListValue::iterator value_iter = plugins->begin();
1637 value_iter != plugins->end(); ++value_iter) {
1638 if (!(*value_iter)->IsType(Value::TYPE_DICTIONARY)) {
1639 NOTREACHED();
1640 continue;
1641 }
1642
1643 DictionaryValue* plugin_dict = static_cast<DictionaryValue*>(*value_iter);
[email protected]a27a9382009-02-11 23:55:101644 std::wstring plugin_name;
1645 plugin_dict->GetString(prefs::kStabilityPluginName, &plugin_name);
1646 if (plugin_name.empty()) {
initial.commit09911bf2008-07-26 23:55:291647 NOTREACHED();
1648 continue;
1649 }
1650
[email protected]a27a9382009-02-11 23:55:101651 if (child_process_stats_buffer_.find(plugin_name) ==
1652 child_process_stats_buffer_.end())
initial.commit09911bf2008-07-26 23:55:291653 continue;
1654
[email protected]a27a9382009-02-11 23:55:101655 ChildProcessStats stats = child_process_stats_buffer_[plugin_name];
initial.commit09911bf2008-07-26 23:55:291656 if (stats.process_launches) {
1657 int launches = 0;
1658 plugin_dict->GetInteger(prefs::kStabilityPluginLaunches, &launches);
1659 launches += stats.process_launches;
1660 plugin_dict->SetInteger(prefs::kStabilityPluginLaunches, launches);
1661 }
1662 if (stats.process_crashes) {
1663 int crashes = 0;
1664 plugin_dict->GetInteger(prefs::kStabilityPluginCrashes, &crashes);
1665 crashes += stats.process_crashes;
1666 plugin_dict->SetInteger(prefs::kStabilityPluginCrashes, crashes);
1667 }
1668 if (stats.instances) {
1669 int instances = 0;
1670 plugin_dict->GetInteger(prefs::kStabilityPluginInstances, &instances);
1671 instances += stats.instances;
1672 plugin_dict->SetInteger(prefs::kStabilityPluginInstances, instances);
1673 }
1674
[email protected]a27a9382009-02-11 23:55:101675 child_process_stats_buffer_.erase(plugin_name);
initial.commit09911bf2008-07-26 23:55:291676 }
1677
1678 // Now go through and add dictionaries for plugins that didn't already have
1679 // reports in Local State.
[email protected]a27a9382009-02-11 23:55:101680 for (std::map<std::wstring, ChildProcessStats>::iterator cache_iter =
1681 child_process_stats_buffer_.begin();
1682 cache_iter != child_process_stats_buffer_.end(); ++cache_iter) {
1683 std::wstring plugin_name = cache_iter->first;
1684 ChildProcessStats stats = cache_iter->second;
initial.commit09911bf2008-07-26 23:55:291685 DictionaryValue* plugin_dict = new DictionaryValue;
1686
[email protected]a27a9382009-02-11 23:55:101687 plugin_dict->SetString(prefs::kStabilityPluginName, plugin_name);
initial.commit09911bf2008-07-26 23:55:291688 plugin_dict->SetInteger(prefs::kStabilityPluginLaunches,
1689 stats.process_launches);
1690 plugin_dict->SetInteger(prefs::kStabilityPluginCrashes,
1691 stats.process_crashes);
1692 plugin_dict->SetInteger(prefs::kStabilityPluginInstances,
1693 stats.instances);
1694 plugins->Append(plugin_dict);
1695 }
[email protected]a27a9382009-02-11 23:55:101696 child_process_stats_buffer_.clear();
initial.commit09911bf2008-07-26 23:55:291697}
1698
1699bool MetricsService::CanLogNotification(NotificationType type,
1700 const NotificationSource& source,
1701 const NotificationDetails& details) {
1702 // We simply don't log anything to UMA if there is a single off the record
1703 // session visible. The problem is that we always notify using the orginal
1704 // profile in order to simplify notification processing.
1705 return !BrowserList::IsOffTheRecordSessionActive();
1706}
1707
1708void MetricsService::RecordBooleanPrefValue(const wchar_t* path, bool value) {
1709 DCHECK(IsSingleThreaded());
1710
1711 PrefService* pref = g_browser_process->local_state();
1712 DCHECK(pref);
1713
1714 pref->SetBoolean(path, value);
1715 RecordCurrentState(pref);
1716}
1717
1718void MetricsService::RecordCurrentState(PrefService* pref) {
1719 pref->SetString(prefs::kStabilityLastTimestampSec,
1720 Int64ToWString(Time::Now().ToTimeT()));
1721
1722 RecordPluginChanges(pref);
1723}
1724
1725void MetricsService::RecordCurrentHistograms() {
1726 DCHECK(current_log_);
1727
1728 StatisticsRecorder::Histograms histograms;
1729 StatisticsRecorder::GetHistograms(&histograms);
1730 for (StatisticsRecorder::Histograms::iterator it = histograms.begin();
1731 histograms.end() != it;
[email protected]cac78842008-11-27 01:02:201732 ++it) {
initial.commit09911bf2008-07-26 23:55:291733 if ((*it)->flags() & kUmaTargetedHistogramFlag)
[email protected]0b33f80b2008-12-17 21:34:361734 // TODO(petersont): Only record historgrams if they are not precluded by
1735 // the UMA response data.
[email protected]d01b8732008-10-16 02:18:071736 // Bug http://code.google.com/p/chromium/issues/detail?id=2739.
initial.commit09911bf2008-07-26 23:55:291737 RecordHistogram(**it);
1738 }
1739}
1740
1741void MetricsService::RecordHistogram(const Histogram& histogram) {
1742 // Get up-to-date snapshot of sample stats.
1743 Histogram::SampleSet snapshot;
1744 histogram.SnapshotSample(&snapshot);
1745
1746 const std::string& histogram_name = histogram.histogram_name();
1747
1748 // Find the already sent stats, or create an empty set.
1749 LoggedSampleMap::iterator it = logged_samples_.find(histogram_name);
1750 Histogram::SampleSet* already_logged;
1751 if (logged_samples_.end() == it) {
1752 // Add new entry
1753 already_logged = &logged_samples_[histogram.histogram_name()];
1754 already_logged->Resize(histogram); // Complete initialization.
1755 } else {
1756 already_logged = &(it->second);
1757 // Deduct any stats we've already logged from our snapshot.
1758 snapshot.Subtract(*already_logged);
1759 }
1760
1761 // snapshot now contains only a delta to what we've already_logged.
1762
1763 if (snapshot.TotalCount() > 0) {
1764 current_log_->RecordHistogramDelta(histogram, snapshot);
1765 // Add new data into our running total.
1766 already_logged->Add(snapshot);
1767 }
1768}
1769
1770void MetricsService::AddProfileMetric(Profile* profile,
1771 const std::wstring& key,
1772 int value) {
1773 // Restriction of types is needed for writing values. See
1774 // MetricsLog::WriteProfileMetrics.
1775 DCHECK(profile && !key.empty());
1776 PrefService* prefs = g_browser_process->local_state();
1777 DCHECK(prefs);
1778
1779 // Key is stored in prefs, which interpret '.'s as paths. As such, key
1780 // shouldn't have any '.'s in it.
1781 DCHECK(key.find(L'.') == std::wstring::npos);
1782 // The id is most likely an email address. We shouldn't send it to the server.
1783 const std::wstring id_hash =
1784 UTF8ToWide(MetricsLog::CreateBase64Hash(WideToUTF8(profile->GetID())));
1785 DCHECK(id_hash.find('.') == std::string::npos);
1786
1787 DictionaryValue* prof_prefs = prefs->GetMutableDictionary(
1788 prefs::kProfileMetrics);
1789 DCHECK(prof_prefs);
1790 const std::wstring pref_key = std::wstring(prefs::kProfilePrefix) + id_hash +
1791 L"." + key;
1792 prof_prefs->SetInteger(pref_key.c_str(), value);
1793}
1794
1795static bool IsSingleThreaded() {
[email protected]dc6f4962009-02-13 01:25:501796 static PlatformThreadId thread_id = 0;
initial.commit09911bf2008-07-26 23:55:291797 if (!thread_id)
[email protected]dc6f4962009-02-13 01:25:501798 thread_id = PlatformThread::CurrentId();
1799 return PlatformThread::CurrentId() == thread_id;
initial.commit09911bf2008-07-26 23:55:291800}