blob: 7c400c3870d181247c6b313ab1f87547748c5a65 [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
jar@chromium.org281d2882009-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//
jar@chromium.org281d2882009-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
jar@chromium.org281d2882009-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)
jar@google.com0b33f80b2008-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
jar@chromium.org281d2882009-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
jar@chromium.org281d2882009-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.
avi@google.com28ab7f92009-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//
avi@google.com28ab7f92009-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.
jar@google.com0b33f80b2008-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
jar@chromium.org281d2882009-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
jar@chromium.org281d2882009-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
158#include <windows.h>
159
ben@chromium.orgcd1adc22009-01-16 01:29:22160#include "chrome/browser/metrics/metrics_service.h"
initial.commit09911bf2008-07-26 23:55:29161
avi@google.com690a99c2009-01-06 16:48:45162#include "base/file_path.h"
initial.commit09911bf2008-07-26 23:55:29163#include "base/histogram.h"
164#include "base/path_service.h"
165#include "base/string_util.h"
166#include "base/task.h"
sky@google.comd8e41ed2008-09-11 15:22:32167#include "chrome/browser/bookmarks/bookmark_model.h"
initial.commit09911bf2008-07-26 23:55:29168#include "chrome/browser/browser.h"
169#include "chrome/browser/browser_list.h"
170#include "chrome/browser/browser_process.h"
171#include "chrome/browser/load_notification_details.h"
172#include "chrome/browser/memory_details.h"
173#include "chrome/browser/plugin_process_info.h"
174#include "chrome/browser/plugin_service.h"
175#include "chrome/browser/profile.h"
brettw@chromium.org8c8657d62009-01-16 18:31:26176#include "chrome/browser/renderer_host/render_process_host.h"
ben@chromium.orgd54e03a52009-01-16 00:31:04177#include "chrome/browser/search_engines/template_url.h"
178#include "chrome/browser/search_engines/template_url_model.h"
initial.commit09911bf2008-07-26 23:55:29179#include "chrome/common/chrome_paths.h"
petersont@google.com252873ef2008-08-04 21:59:45180#include "chrome/common/libxml_utils.h"
brettw@chromium.orgbfd04a62009-02-01 18:16:56181#include "chrome/common/notification_service.h"
initial.commit09911bf2008-07-26 23:55:29182#include "chrome/common/pref_names.h"
183#include "chrome/common/pref_service.h"
jam@chromium.orge09ba552009-02-05 03:26:29184#include "chrome/common/render_messages.h"
rahulk@google.com6e93e522008-08-14 19:28:17185#include "chrome/installer/util/google_update_settings.h"
initial.commit09911bf2008-07-26 23:55:29186#include "googleurl/src/gurl.h"
187#include "net/base/load_flags.h"
188#include "third_party/bzip2/bzlib.h"
189
dsh@google.come1acf6f2008-10-27 20:43:33190using base::Time;
191using base::TimeDelta;
192
initial.commit09911bf2008-07-26 23:55:29193// Check to see that we're being called on only one thread.
194static bool IsSingleThreaded();
195
196static const char kMetricsURL[] =
wtc@chromium.org0acdfc42009-01-30 01:13:22197 "https://clients4.google.com/firefox/metrics/collect";
initial.commit09911bf2008-07-26 23:55:29198
199static const char kMetricsType[] = "application/vnd.mozilla.metrics.bz2";
200
201// The delay, in seconds, after startup before sending the first log message.
petersont@google.com252873ef2008-08-04 21:59:45202static const int kInitialInterlogDuration = 60; // one minute
203
204// The default maximum number of events in a log uploaded to the UMA server.
jar@google.com0b33f80b2008-12-17 21:34:36205static const int kInitialEventLimit = 2400;
jar@google.com68475e602008-08-22 03:21:15206
207// If an upload fails, and the transmission was over this byte count, then we
208// will discard the log, and not try to retransmit it. We also don't persist
209// the log to the prefs for transmission during the next chrome session if this
210// limit is exceeded.
211static const int kUploadLogAvoidRetransmitSize = 50000;
initial.commit09911bf2008-07-26 23:55:29212
213// When we have logs from previous Chrome sessions to send, how long should we
214// delay (in seconds) between each log transmission.
215static const int kUnsentLogDelay = 15; // 15 seconds
216
217// Minimum time a log typically exists before sending, in seconds.
218// This number is supplied by the server, but until we parse it out of a server
219// response, we use this duration to specify how long we should wait before
220// sending the next log. If the channel is busy, such as when there is a
221// failure during an attempt to transmit a previous log, then a log may wait
222// (and continue to accrue now log entries) for a much greater period of time.
jar@chromium.org0eb34fee2009-01-21 08:04:38223static const int kMinSecondsPerLog = 20 * 60; // Twenty minutes.
initial.commit09911bf2008-07-26 23:55:29224
initial.commit09911bf2008-07-26 23:55:29225// When we don't succeed at transmitting a log to a server, we progressively
226// wait longer and longer before sending the next log. This backoff process
227// help reduce load on the server, and makes the amount of backoff vary between
228// clients so that a collision (server overload?) on retransmit is less likely.
229// The following is the constant we use to expand that inter-log duration.
230static const double kBackoff = 1.1;
231// We limit the maximum backoff to be no greater than some multiple of the
232// default kMinSecondsPerLog. The following is that maximum ratio.
233static const int kMaxBackoff = 10;
234
235// Interval, in seconds, between state saves.
236static const int kSaveStateInterval = 5 * 60; // five minutes
237
238// The number of "initial" logs we're willing to save, and hope to send during
239// a future Chrome session. Initial logs contain crash stats, and are pretty
240// small.
241static const size_t kMaxInitialLogsPersisted = 20;
242
243// The number of ongoing logs we're willing to save persistently, and hope to
jar@chromium.org281d2882009-01-20 20:32:42244// send during a this or future sessions. Note that each log may be pretty
initial.commit09911bf2008-07-26 23:55:29245// large, as presumably the related "initial" log wasn't sent (probably nothing
246// was, as the user was probably off-line). As a result, the log probably kept
247// accumulating while the "initial" log was stalled (pending_), and couldn't be
248// sent. As a result, we don't want to save too many of these mega-logs.
249// A "standard shutdown" will create a small log, including just the data that
250// was not yet been transmitted, and that is normal (to have exactly one
251// ongoing_log_ at startup).
jar@chromium.org281d2882009-01-20 20:32:42252static const size_t kMaxOngoingLogsPersisted = 8;
initial.commit09911bf2008-07-26 23:55:29253
254
255// Handles asynchronous fetching of memory details.
256// Will run the provided task after finished.
257class MetricsMemoryDetails : public MemoryDetails {
258 public:
259 explicit MetricsMemoryDetails(Task* completion) : completion_(completion) {}
260
261 virtual void OnDetailsAvailable() {
262 MessageLoop::current()->PostTask(FROM_HERE, completion_);
263 }
264
265 private:
266 Task* completion_;
267 DISALLOW_EVIL_CONSTRUCTORS(MetricsMemoryDetails);
268};
269
270class MetricsService::GetPluginListTaskComplete : public Task {
271 virtual void Run() {
272 g_browser_process->metrics_service()->OnGetPluginListTaskComplete();
273 }
274};
275
276class MetricsService::GetPluginListTask : public Task {
277 public:
278 explicit GetPluginListTask(MessageLoop* callback_loop)
279 : callback_loop_(callback_loop) {}
280
281 virtual void Run() {
282 std::vector<WebPluginInfo> plugins;
283 PluginService::GetInstance()->GetPlugins(false, &plugins);
284
285 callback_loop_->PostTask(FROM_HERE, new GetPluginListTaskComplete());
286 }
287
288 private:
289 MessageLoop* callback_loop_;
290};
291
292// static
293void MetricsService::RegisterPrefs(PrefService* local_state) {
294 DCHECK(IsSingleThreaded());
295 local_state->RegisterStringPref(prefs::kMetricsClientID, L"");
296 local_state->RegisterStringPref(prefs::kMetricsClientIDTimestamp, L"0");
297 local_state->RegisterStringPref(prefs::kStabilityLaunchTimeSec, L"0");
298 local_state->RegisterStringPref(prefs::kStabilityLastTimestampSec, L"0");
299 local_state->RegisterStringPref(prefs::kStabilityUptimeSec, L"0");
300 local_state->RegisterBooleanPref(prefs::kStabilityExitedCleanly, true);
301 local_state->RegisterBooleanPref(prefs::kStabilitySessionEndCompleted, true);
302 local_state->RegisterIntegerPref(prefs::kMetricsSessionID, -1);
303 local_state->RegisterIntegerPref(prefs::kStabilityLaunchCount, 0);
304 local_state->RegisterIntegerPref(prefs::kStabilityCrashCount, 0);
305 local_state->RegisterIntegerPref(prefs::kStabilityIncompleteSessionEndCount,
306 0);
307 local_state->RegisterIntegerPref(prefs::kStabilityPageLoadCount, 0);
308 local_state->RegisterIntegerPref(prefs::kSecurityRendererOnSboxDesktop, 0);
309 local_state->RegisterIntegerPref(prefs::kSecurityRendererOnDefaultDesktop, 0);
310 local_state->RegisterIntegerPref(prefs::kStabilityRendererCrashCount, 0);
311 local_state->RegisterIntegerPref(prefs::kStabilityRendererHangCount, 0);
cpu@google.come73c01972008-08-13 00:18:24312 local_state->RegisterIntegerPref(prefs::kStabilityBreakpadRegistrationFail,
313 0);
314 local_state->RegisterIntegerPref(prefs::kStabilityBreakpadRegistrationSuccess,
315 0);
316 local_state->RegisterIntegerPref(prefs::kStabilityDebuggerPresent, 0);
317 local_state->RegisterIntegerPref(prefs::kStabilityDebuggerNotPresent, 0);
318
initial.commit09911bf2008-07-26 23:55:29319 local_state->RegisterDictionaryPref(prefs::kProfileMetrics);
320 local_state->RegisterIntegerPref(prefs::kNumBookmarksOnBookmarkBar, 0);
321 local_state->RegisterIntegerPref(prefs::kNumFoldersOnBookmarkBar, 0);
322 local_state->RegisterIntegerPref(prefs::kNumBookmarksInOtherBookmarkFolder,
323 0);
324 local_state->RegisterIntegerPref(prefs::kNumFoldersInOtherBookmarkFolder, 0);
325 local_state->RegisterIntegerPref(prefs::kNumKeywords, 0);
326 local_state->RegisterListPref(prefs::kMetricsInitialLogs);
327 local_state->RegisterListPref(prefs::kMetricsOngoingLogs);
328}
329
330MetricsService::MetricsService()
petersont@google.comd01b8732008-10-16 02:18:07331 : recording_active_(false),
332 reporting_active_(false),
333 user_permits_upload_(false),
334 server_permits_upload_(true),
335 state_(INITIALIZED),
initial.commit09911bf2008-07-26 23:55:29336 pending_log_(NULL),
337 pending_log_text_(""),
338 current_fetch_(NULL),
339 current_log_(NULL),
petersont@google.comd01b8732008-10-16 02:18:07340 idle_since_last_transmission_(false),
initial.commit09911bf2008-07-26 23:55:29341 next_window_id_(0),
342 log_sender_factory_(this),
343 state_saver_factory_(this),
344 logged_samples_(),
petersont@google.com252873ef2008-08-04 21:59:45345 interlog_duration_(TimeDelta::FromSeconds(kInitialInterlogDuration)),
petersont@google.comd01b8732008-10-16 02:18:07346 log_event_limit_(kInitialEventLimit),
initial.commit09911bf2008-07-26 23:55:29347 timer_pending_(false) {
348 DCHECK(IsSingleThreaded());
349 InitializeMetricsState();
350}
351
352MetricsService::~MetricsService() {
353 SetRecording(false);
kuchhal@chromium.orgd8bc79bf2009-01-28 01:17:58354 if (pending_log_) {
355 delete pending_log_;
356 pending_log_ = NULL;
357 }
358 if (current_log_) {
359 delete current_log_;
360 current_log_ = NULL;
361 }
initial.commit09911bf2008-07-26 23:55:29362}
363
petersont@google.comd01b8732008-10-16 02:18:07364void MetricsService::SetUserPermitsUpload(bool enabled) {
365 HandleIdleSinceLastTransmission(false);
366 user_permits_upload_ = enabled;
367}
368
369void MetricsService::Start() {
370 SetRecording(true);
371 SetReporting(true);
372}
373
374void MetricsService::StartRecordingOnly() {
375 SetRecording(true);
376 SetReporting(false);
377}
378
379void MetricsService::Stop() {
380 SetReporting(false);
381 SetRecording(false);
382}
383
initial.commit09911bf2008-07-26 23:55:29384void MetricsService::SetRecording(bool enabled) {
385 DCHECK(IsSingleThreaded());
386
petersont@google.comd01b8732008-10-16 02:18:07387 if (enabled == recording_active_)
initial.commit09911bf2008-07-26 23:55:29388 return;
389
390 if (enabled) {
391 StartRecording();
392 ListenerRegistration(true);
393 } else {
394 // Turn off all observers.
395 ListenerRegistration(false);
396 PushPendingLogsToUnsentLists();
397 DCHECK(!pending_log());
398 if (state_ > INITIAL_LOG_READY && unsent_logs())
399 state_ = SEND_OLD_INITIAL_LOGS;
400 }
petersont@google.comd01b8732008-10-16 02:18:07401 recording_active_ = enabled;
initial.commit09911bf2008-07-26 23:55:29402}
403
petersont@google.comd01b8732008-10-16 02:18:07404bool MetricsService::recording_active() const {
initial.commit09911bf2008-07-26 23:55:29405 DCHECK(IsSingleThreaded());
petersont@google.comd01b8732008-10-16 02:18:07406 return recording_active_;
initial.commit09911bf2008-07-26 23:55:29407}
408
petersont@google.comd01b8732008-10-16 02:18:07409void MetricsService::SetReporting(bool enable) {
410 if (reporting_active_ != enable) {
411 reporting_active_ = enable;
412 if (reporting_active_)
initial.commit09911bf2008-07-26 23:55:29413 StartLogTransmissionTimer();
414 }
petersont@google.comd01b8732008-10-16 02:18:07415}
416
417bool MetricsService::reporting_active() const {
418 DCHECK(IsSingleThreaded());
419 return reporting_active_;
initial.commit09911bf2008-07-26 23:55:29420}
421
422void MetricsService::Observe(NotificationType type,
423 const NotificationSource& source,
424 const NotificationDetails& details) {
425 DCHECK(current_log_);
426 DCHECK(IsSingleThreaded());
427
428 if (!CanLogNotification(type, source, details))
429 return;
430
brettw@chromium.orgbfd04a62009-02-01 18:16:56431 switch (type.value) {
432 case NotificationType::USER_ACTION:
initial.commit09911bf2008-07-26 23:55:29433 current_log_->RecordUserAction(*Details<const wchar_t*>(details).ptr());
434 break;
435
brettw@chromium.orgbfd04a62009-02-01 18:16:56436 case NotificationType::BROWSER_OPENED:
437 case NotificationType::BROWSER_CLOSED:
initial.commit09911bf2008-07-26 23:55:29438 LogWindowChange(type, source, details);
439 break;
440
brettw@chromium.orgbfd04a62009-02-01 18:16:56441 case NotificationType::TAB_PARENTED:
442 case NotificationType::TAB_CLOSING:
initial.commit09911bf2008-07-26 23:55:29443 LogWindowChange(type, source, details);
444 break;
445
brettw@chromium.orgbfd04a62009-02-01 18:16:56446 case NotificationType::LOAD_STOP:
initial.commit09911bf2008-07-26 23:55:29447 LogLoadComplete(type, source, details);
448 break;
449
brettw@chromium.orgbfd04a62009-02-01 18:16:56450 case NotificationType::LOAD_START:
initial.commit09911bf2008-07-26 23:55:29451 LogLoadStarted();
452 break;
453
brettw@chromium.orgbfd04a62009-02-01 18:16:56454 case NotificationType::RENDERER_PROCESS_TERMINATED:
initial.commit09911bf2008-07-26 23:55:29455 if (!*Details<bool>(details).ptr())
456 LogRendererCrash();
457 break;
458
brettw@chromium.orgbfd04a62009-02-01 18:16:56459 case NotificationType::RENDERER_PROCESS_HANG:
initial.commit09911bf2008-07-26 23:55:29460 LogRendererHang();
461 break;
462
brettw@chromium.orgbfd04a62009-02-01 18:16:56463 case NotificationType::RENDERER_PROCESS_IN_SBOX:
initial.commit09911bf2008-07-26 23:55:29464 LogRendererInSandbox(*Details<bool>(details).ptr());
465 break;
466
brettw@chromium.orgbfd04a62009-02-01 18:16:56467 case NotificationType::PLUGIN_PROCESS_HOST_CONNECTED:
468 case NotificationType::PLUGIN_PROCESS_CRASHED:
469 case NotificationType::PLUGIN_INSTANCE_CREATED:
initial.commit09911bf2008-07-26 23:55:29470 LogPluginChange(type, source, details);
471 break;
472
brettw@chromium.orgbfd04a62009-02-01 18:16:56473 case NotificationType::TEMPLATE_URL_MODEL_LOADED:
initial.commit09911bf2008-07-26 23:55:29474 LogKeywords(Source<TemplateURLModel>(source).ptr());
475 break;
476
brettw@chromium.orgbfd04a62009-02-01 18:16:56477 case NotificationType::OMNIBOX_OPENED_URL:
initial.commit09911bf2008-07-26 23:55:29478 current_log_->RecordOmniboxOpenedURL(
479 *Details<AutocompleteLog>(details).ptr());
480 break;
481
brettw@chromium.orgbfd04a62009-02-01 18:16:56482 case NotificationType::BOOKMARK_MODEL_LOADED:
sky@google.comd8e41ed2008-09-11 15:22:32483 LogBookmarks(Source<Profile>(source)->GetBookmarkModel());
initial.commit09911bf2008-07-26 23:55:29484 break;
485
486 default:
487 NOTREACHED();
488 break;
489 }
petersont@google.comd01b8732008-10-16 02:18:07490
491 HandleIdleSinceLastTransmission(false);
492
493 if (current_log_)
jar@chromium.org281d2882009-01-20 20:32:42494 DLOG(INFO) << "METRICS: NUMBER OF EVENTS = " << current_log_->num_events();
petersont@google.comd01b8732008-10-16 02:18:07495}
496
497void MetricsService::HandleIdleSinceLastTransmission(bool in_idle) {
498 // If there wasn't a lot of action, maybe the computer was asleep, in which
499 // case, the log transmissions should have stopped. Here we start them up
500 // again.
pkasting@chromium.orgcac78842008-11-27 01:02:20501 if (!in_idle && idle_since_last_transmission_)
502 StartLogTransmissionTimer();
503 idle_since_last_transmission_ = in_idle;
initial.commit09911bf2008-07-26 23:55:29504}
505
506void MetricsService::RecordCleanShutdown() {
507 RecordBooleanPrefValue(prefs::kStabilityExitedCleanly, true);
508}
509
510void MetricsService::RecordStartOfSessionEnd() {
511 RecordBooleanPrefValue(prefs::kStabilitySessionEndCompleted, false);
512}
513
514void MetricsService::RecordCompletedSessionEnd() {
515 RecordBooleanPrefValue(prefs::kStabilitySessionEndCompleted, true);
516}
517
cpu@google.come73c01972008-08-13 00:18:24518void MetricsService:: RecordBreakpadRegistration(bool success) {
jar@google.com68475e602008-08-22 03:21:15519 if (!success)
cpu@google.come73c01972008-08-13 00:18:24520 IncrementPrefValue(prefs::kStabilityBreakpadRegistrationFail);
521 else
522 IncrementPrefValue(prefs::kStabilityBreakpadRegistrationSuccess);
523}
524
525void MetricsService::RecordBreakpadHasDebugger(bool has_debugger) {
526 if (!has_debugger)
527 IncrementPrefValue(prefs::kStabilityDebuggerNotPresent);
528 else
jar@google.com68475e602008-08-22 03:21:15529 IncrementPrefValue(prefs::kStabilityDebuggerPresent);
cpu@google.come73c01972008-08-13 00:18:24530}
531
initial.commit09911bf2008-07-26 23:55:29532//------------------------------------------------------------------------------
533// private methods
534//------------------------------------------------------------------------------
535
536
537//------------------------------------------------------------------------------
538// Initialization methods
539
540void MetricsService::InitializeMetricsState() {
541 PrefService* pref = g_browser_process->local_state();
542 DCHECK(pref);
543
544 client_id_ = WideToUTF8(pref->GetString(prefs::kMetricsClientID));
545 if (client_id_.empty()) {
546 client_id_ = GenerateClientID();
547 pref->SetString(prefs::kMetricsClientID, UTF8ToWide(client_id_));
548
549 // Might as well make a note of how long this ID has existed
550 pref->SetString(prefs::kMetricsClientIDTimestamp,
551 Int64ToWString(Time::Now().ToTimeT()));
552 }
553
554 // Update session ID
555 session_id_ = pref->GetInteger(prefs::kMetricsSessionID);
556 ++session_id_;
557 pref->SetInteger(prefs::kMetricsSessionID, session_id_);
558
initial.commit09911bf2008-07-26 23:55:29559 // Stability bookkeeping
cpu@google.come73c01972008-08-13 00:18:24560 IncrementPrefValue(prefs::kStabilityLaunchCount);
initial.commit09911bf2008-07-26 23:55:29561
cpu@google.come73c01972008-08-13 00:18:24562 if (!pref->GetBoolean(prefs::kStabilityExitedCleanly)) {
563 IncrementPrefValue(prefs::kStabilityCrashCount);
initial.commit09911bf2008-07-26 23:55:29564 }
cpu@google.come73c01972008-08-13 00:18:24565
566 // This will be set to 'true' if we exit cleanly.
initial.commit09911bf2008-07-26 23:55:29567 pref->SetBoolean(prefs::kStabilityExitedCleanly, false);
568
cpu@google.come73c01972008-08-13 00:18:24569 if (!pref->GetBoolean(prefs::kStabilitySessionEndCompleted)) {
570 IncrementPrefValue(prefs::kStabilityIncompleteSessionEndCount);
initial.commit09911bf2008-07-26 23:55:29571 }
572 // This is marked false when we get a WM_ENDSESSION.
573 pref->SetBoolean(prefs::kStabilitySessionEndCompleted, true);
574
575 int64 last_start_time =
576 StringToInt64(pref->GetString(prefs::kStabilityLaunchTimeSec));
577 int64 last_end_time =
578 StringToInt64(pref->GetString(prefs::kStabilityLastTimestampSec));
579 int64 uptime =
580 StringToInt64(pref->GetString(prefs::kStabilityUptimeSec));
581
582 if (last_start_time && last_end_time) {
583 // TODO(JAR): Exclude sleep time. ... which must be gathered in UI loop.
584 uptime += last_end_time - last_start_time;
585 pref->SetString(prefs::kStabilityUptimeSec, Int64ToWString(uptime));
586 }
587 pref->SetString(prefs::kStabilityLaunchTimeSec,
588 Int64ToWString(Time::Now().ToTimeT()));
589
590 // Save profile metrics.
591 PrefService* prefs = g_browser_process->local_state();
592 if (prefs) {
593 // Remove the current dictionary and store it for use when sending data to
594 // server. By removing the value we prune potentially dead profiles
595 // (and keys). All valid values are added back once services startup.
596 const DictionaryValue* profile_dictionary =
597 prefs->GetDictionary(prefs::kProfileMetrics);
598 if (profile_dictionary) {
599 // Do a deep copy of profile_dictionary since ClearPref will delete it.
600 profile_dictionary_.reset(static_cast<DictionaryValue*>(
601 profile_dictionary->DeepCopy()));
602 prefs->ClearPref(prefs::kProfileMetrics);
603 }
604 }
605
606 // Kick off the process of saving the state (so the uptime numbers keep
607 // getting updated) every n minutes.
608 ScheduleNextStateSave();
609}
610
611void MetricsService::OnGetPluginListTaskComplete() {
612 DCHECK(state_ == PLUGIN_LIST_REQUESTED);
613 if (state_ == PLUGIN_LIST_REQUESTED)
614 state_ = PLUGIN_LIST_ARRIVED;
615}
616
617std::string MetricsService::GenerateClientID() {
618 const int kGUIDSize = 39;
619
620 GUID guid;
621 HRESULT guid_result = CoCreateGuid(&guid);
622 DCHECK(SUCCEEDED(guid_result));
623
624 std::wstring guid_string;
625 int result = StringFromGUID2(guid,
626 WriteInto(&guid_string, kGUIDSize), kGUIDSize);
627 DCHECK(result == kGUIDSize);
628
629 return WideToUTF8(guid_string.substr(1, guid_string.length() - 2));
630}
631
632
633//------------------------------------------------------------------------------
634// State save methods
635
636void MetricsService::ScheduleNextStateSave() {
637 state_saver_factory_.RevokeAll();
638
639 MessageLoop::current()->PostDelayedTask(FROM_HERE,
640 state_saver_factory_.NewRunnableMethod(&MetricsService::SaveLocalState),
641 kSaveStateInterval * 1000);
642}
643
644void MetricsService::SaveLocalState() {
645 PrefService* pref = g_browser_process->local_state();
646 if (!pref) {
647 NOTREACHED();
648 return;
649 }
650
651 RecordCurrentState(pref);
652 pref->ScheduleSavePersistentPrefs(g_browser_process->file_thread());
653
jar@chromium.org281d2882009-01-20 20:32:42654 // TODO(jar): Does this run down the batteries????
initial.commit09911bf2008-07-26 23:55:29655 ScheduleNextStateSave();
656}
657
658
659//------------------------------------------------------------------------------
660// Recording control methods
661
662void MetricsService::StartRecording() {
663 if (current_log_)
664 return;
665
666 current_log_ = new MetricsLog(client_id_, session_id_);
667 if (state_ == INITIALIZED) {
668 // We only need to schedule that run once.
669 state_ = PLUGIN_LIST_REQUESTED;
670
671 // Make sure the plugin list is loaded before the inital log is sent, so
672 // that the main thread isn't blocked generating the list.
673 g_browser_process->file_thread()->message_loop()->PostDelayedTask(FROM_HERE,
674 new GetPluginListTask(MessageLoop::current()),
petersont@google.com252873ef2008-08-04 21:59:45675 kInitialInterlogDuration * 1000 / 2);
initial.commit09911bf2008-07-26 23:55:29676 }
677}
678
679void MetricsService::StopRecording(MetricsLog** log) {
680 if (!current_log_)
681 return;
682
jar@google.com68475e602008-08-22 03:21:15683 // TODO(jar): Integrate bounds on log recording more consistently, so that we
684 // can stop recording logs that are too big much sooner.
petersont@google.comd01b8732008-10-16 02:18:07685 if (current_log_->num_events() > log_event_limit_) {
jar@google.com68475e602008-08-22 03:21:15686 UMA_HISTOGRAM_COUNTS(L"UMA.Discarded Log Events",
687 current_log_->num_events());
688 current_log_->CloseLog();
689 delete current_log_;
jar@google.com294638782008-09-24 00:22:41690 current_log_ = NULL;
jar@google.com68475e602008-08-22 03:21:15691 StartRecording(); // Start trivial log to hold our histograms.
692 }
693
jar@google.com0b33f80b2008-12-17 21:34:36694 // Put incremental data (histogram deltas, and realtime stats deltas) at the
jar@google.com147bbc0b2009-01-06 19:37:40695 // end of all log transmissions (initial log handles this separately).
initial.commit09911bf2008-07-26 23:55:29696 // Don't bother if we're going to discard current_log_.
jar@google.com0b33f80b2008-12-17 21:34:36697 if (log) {
698 current_log_->RecordIncrementalStabilityElements();
initial.commit09911bf2008-07-26 23:55:29699 RecordCurrentHistograms();
jar@google.com0b33f80b2008-12-17 21:34:36700 }
initial.commit09911bf2008-07-26 23:55:29701
702 current_log_->CloseLog();
pkasting@chromium.orgcac78842008-11-27 01:02:20703 if (log)
initial.commit09911bf2008-07-26 23:55:29704 *log = current_log_;
pkasting@chromium.orgcac78842008-11-27 01:02:20705 else
initial.commit09911bf2008-07-26 23:55:29706 delete current_log_;
initial.commit09911bf2008-07-26 23:55:29707 current_log_ = NULL;
708}
709
710void MetricsService::ListenerRegistration(bool start_listening) {
brettw@chromium.orgbfd04a62009-02-01 18:16:56711 AddOrRemoveObserver(this, NotificationType::BROWSER_OPENED, start_listening);
712 AddOrRemoveObserver(this, NotificationType::BROWSER_CLOSED, start_listening);
713 AddOrRemoveObserver(this, NotificationType::USER_ACTION, start_listening);
714 AddOrRemoveObserver(this, NotificationType::TAB_PARENTED, start_listening);
715 AddOrRemoveObserver(this, NotificationType::TAB_CLOSING, start_listening);
716 AddOrRemoveObserver(this, NotificationType::LOAD_START, start_listening);
717 AddOrRemoveObserver(this, NotificationType::LOAD_STOP, start_listening);
718 AddOrRemoveObserver(this, NotificationType::RENDERER_PROCESS_IN_SBOX,
initial.commit09911bf2008-07-26 23:55:29719 start_listening);
brettw@chromium.orgbfd04a62009-02-01 18:16:56720 AddOrRemoveObserver(this, NotificationType::RENDERER_PROCESS_TERMINATED,
initial.commit09911bf2008-07-26 23:55:29721 start_listening);
brettw@chromium.orgbfd04a62009-02-01 18:16:56722 AddOrRemoveObserver(this, NotificationType::RENDERER_PROCESS_HANG,
723 start_listening);
724 AddOrRemoveObserver(this, NotificationType::PLUGIN_PROCESS_HOST_CONNECTED,
725 start_listening);
726 AddOrRemoveObserver(this, NotificationType::PLUGIN_INSTANCE_CREATED,
727 start_listening);
728 AddOrRemoveObserver(this, NotificationType::PLUGIN_PROCESS_CRASHED,
729 start_listening);
730 AddOrRemoveObserver(this, NotificationType::TEMPLATE_URL_MODEL_LOADED,
731 start_listening);
732 AddOrRemoveObserver(this, NotificationType::OMNIBOX_OPENED_URL,
733 start_listening);
734 AddOrRemoveObserver(this, NotificationType::BOOKMARK_MODEL_LOADED,
735 start_listening);
initial.commit09911bf2008-07-26 23:55:29736}
737
738// static
739void MetricsService::AddOrRemoveObserver(NotificationObserver* observer,
pkasting@chromium.orgcac78842008-11-27 01:02:20740 NotificationType type,
741 bool is_add) {
initial.commit09911bf2008-07-26 23:55:29742 NotificationService* service = NotificationService::current();
743
pkasting@chromium.orgcac78842008-11-27 01:02:20744 if (is_add)
initial.commit09911bf2008-07-26 23:55:29745 service->AddObserver(observer, type, NotificationService::AllSources());
pkasting@chromium.orgcac78842008-11-27 01:02:20746 else
initial.commit09911bf2008-07-26 23:55:29747 service->RemoveObserver(observer, type, NotificationService::AllSources());
initial.commit09911bf2008-07-26 23:55:29748}
749
750void MetricsService::PushPendingLogsToUnsentLists() {
751 if (state_ < INITIAL_LOG_READY)
avi@google.com28ab7f92009-01-06 21:39:04752 return; // We didn't and still don't have time to get plugin list etc.
initial.commit09911bf2008-07-26 23:55:29753
754 if (pending_log()) {
755 PreparePendingLogText();
756 if (state_ == INITIAL_LOG_READY) {
757 // We may race here, and send second copy of initial log later.
758 unsent_initial_logs_.push_back(pending_log_text_);
petersont@google.comd01b8732008-10-16 02:18:07759 state_ = SEND_OLD_INITIAL_LOGS;
initial.commit09911bf2008-07-26 23:55:29760 } else {
jar@chromium.org281d2882009-01-20 20:32:42761 // TODO(jar): Verify correctness in other states, including sending unsent
762 // iniitial logs.
jar@google.com68475e602008-08-22 03:21:15763 PushPendingLogTextToUnsentOngoingLogs();
initial.commit09911bf2008-07-26 23:55:29764 }
765 DiscardPendingLog();
766 }
767 DCHECK(!pending_log());
768 StopRecording(&pending_log_);
769 PreparePendingLogText();
jar@google.com68475e602008-08-22 03:21:15770 PushPendingLogTextToUnsentOngoingLogs();
initial.commit09911bf2008-07-26 23:55:29771 DiscardPendingLog();
772 StoreUnsentLogs();
773}
774
jar@google.com68475e602008-08-22 03:21:15775void MetricsService::PushPendingLogTextToUnsentOngoingLogs() {
petersont@google.comd01b8732008-10-16 02:18:07776 // If UMA response told us not to upload, there's no need to save the pending
777 // log. It wasn't supposed to be uploaded anyway.
778 if (!server_permits_upload_)
779 return;
780
jar@google.com68475e602008-08-22 03:21:15781 if (pending_log_text_.length() > kUploadLogAvoidRetransmitSize) {
782 UMA_HISTOGRAM_COUNTS(L"UMA.Large Accumulated Log Not Persisted",
783 static_cast<int>(pending_log_text_.length()));
784 return;
785 }
786 unsent_ongoing_logs_.push_back(pending_log_text_);
787}
788
initial.commit09911bf2008-07-26 23:55:29789//------------------------------------------------------------------------------
790// Transmission of logs methods
791
792void MetricsService::StartLogTransmissionTimer() {
petersont@google.comd01b8732008-10-16 02:18:07793 // If we're not reporting, there's no point in starting a log transmission
794 // timer.
795 if (!reporting_active())
796 return;
797
initial.commit09911bf2008-07-26 23:55:29798 if (!current_log_)
799 return; // Recorder is shutdown.
petersont@google.comd01b8732008-10-16 02:18:07800
801 // If there is already a timer running, we leave it running.
802 // If timer_pending is true because the fetch is waiting for a response,
803 // we return for now and let the response handler start the timer.
804 if (timer_pending_)
initial.commit09911bf2008-07-26 23:55:29805 return;
petersont@google.comd01b8732008-10-16 02:18:07806
petersont@google.comd01b8732008-10-16 02:18:07807 // Before starting the timer, set timer_pending_ to true.
initial.commit09911bf2008-07-26 23:55:29808 timer_pending_ = true;
petersont@google.comd01b8732008-10-16 02:18:07809
810 // Right before the UMA transmission gets started, there's one more thing we'd
811 // like to record: the histogram of memory usage, so we spawn a task to
812 // collect the memory details and when that task is finished, we arrange for
813 // TryToStartTransmission to take over.
initial.commit09911bf2008-07-26 23:55:29814 MessageLoop::current()->PostDelayedTask(FROM_HERE,
815 log_sender_factory_.
816 NewRunnableMethod(&MetricsService::CollectMemoryDetails),
817 static_cast<int>(interlog_duration_.InMilliseconds()));
818}
819
820void MetricsService::TryToStartTransmission() {
821 DCHECK(IsSingleThreaded());
822
petersont@google.comd01b8732008-10-16 02:18:07823 // This function should only be called via timer, so timer_pending_
824 // should be true.
825 DCHECK(timer_pending_);
826 timer_pending_ = false;
initial.commit09911bf2008-07-26 23:55:29827
828 DCHECK(!current_fetch_.get());
initial.commit09911bf2008-07-26 23:55:29829
petersont@google.comd01b8732008-10-16 02:18:07830 // If we're getting no notifications, then the log won't have much in it, and
831 // it's possible the computer is about to go to sleep, so don't upload and
832 // don't restart the transmission timer.
833 if (idle_since_last_transmission_)
834 return;
835
836 // If somehow there is a fetch in progress, we return setting timer_pending_
837 // to true and hope things work out.
838 if (current_fetch_.get()) {
839 timer_pending_ = true;
840 return;
841 }
842
843 // If uploads are forbidden by UMA response, there's no point in keeping
844 // the current_log_, and the more often we delete it, the less likely it is
845 // to expand forever.
846 if (!server_permits_upload_ && current_log_) {
847 StopRecording(NULL);
848 StartRecording();
849 }
initial.commit09911bf2008-07-26 23:55:29850
851 if (!current_log_)
852 return; // Logging was disabled.
petersont@google.comd01b8732008-10-16 02:18:07853 if (!reporting_active())
initial.commit09911bf2008-07-26 23:55:29854 return; // Don't do work if we're not going to send anything now.
855
petersont@google.comd01b8732008-10-16 02:18:07856 MakePendingLog();
initial.commit09911bf2008-07-26 23:55:29857
petersont@google.comd01b8732008-10-16 02:18:07858 // MakePendingLog should have put something in the pending log, if it didn't,
859 // we start the timer again, return and hope things work out.
860 if (!pending_log()) {
861 StartLogTransmissionTimer();
862 return;
863 }
initial.commit09911bf2008-07-26 23:55:29864
petersont@google.comd01b8732008-10-16 02:18:07865 // If we're not supposed to upload any UMA data because the response or the
866 // user said so, cancel the upload at this point, but start the timer.
867 if (!TransmissionPermitted()) {
868 DiscardPendingLog();
869 StartLogTransmissionTimer();
870 return;
871 }
initial.commit09911bf2008-07-26 23:55:29872
petersont@google.comd01b8732008-10-16 02:18:07873 PrepareFetchWithPendingLog();
874
875 if (!current_fetch_.get()) {
876 // Compression failed, and log discarded :-/.
877 DiscardPendingLog();
878 StartLogTransmissionTimer(); // Maybe we'll do better next time
879 // TODO(jar): If compression failed, we should have created a tiny log and
880 // compressed that, so that we can signal that we're losing logs.
881 return;
882 }
883
884 DCHECK(!timer_pending_);
885
886 // The URL fetch is a like timer in that after a while we get called back
887 // so we set timer_pending_ true just as we start the url fetch.
888 timer_pending_ = true;
889 current_fetch_->Start();
890
891 HandleIdleSinceLastTransmission(true);
892}
893
894
895void MetricsService::MakePendingLog() {
896 if (pending_log())
897 return;
898
899 switch (state_) {
900 case INITIALIZED:
901 case PLUGIN_LIST_REQUESTED: // We should be further along by now.
902 DCHECK(false);
903 return;
904
905 case PLUGIN_LIST_ARRIVED:
906 // We need to wait for the initial log to be ready before sending
907 // anything, because the server will tell us whether it wants to hear
908 // from us.
909 PrepareInitialLog();
910 DCHECK(state_ == PLUGIN_LIST_ARRIVED);
911 RecallUnsentLogs();
912 state_ = INITIAL_LOG_READY;
913 break;
914
915 case SEND_OLD_INITIAL_LOGS:
pkasting@chromium.orgcac78842008-11-27 01:02:20916 if (!unsent_initial_logs_.empty()) {
917 pending_log_text_ = unsent_initial_logs_.back();
918 break;
919 }
petersont@google.comd01b8732008-10-16 02:18:07920 state_ = SENDING_OLD_LOGS;
921 // Fall through.
initial.commit09911bf2008-07-26 23:55:29922
petersont@google.comd01b8732008-10-16 02:18:07923 case SENDING_OLD_LOGS:
924 if (!unsent_ongoing_logs_.empty()) {
925 pending_log_text_ = unsent_ongoing_logs_.back();
926 break;
927 }
928 state_ = SENDING_CURRENT_LOGS;
929 // Fall through.
930
931 case SENDING_CURRENT_LOGS:
932 StopRecording(&pending_log_);
933 StartRecording();
934 break;
935
936 default:
937 DCHECK(false);
938 return;
939 }
940
941 DCHECK(pending_log());
942}
943
944bool MetricsService::TransmissionPermitted() const {
945 // If the user forbids uploading that's they're business, and we don't upload
946 // anything. If the server forbids uploading, that's our business, so we take
947 // that to mean it forbids current logs, but we still send up the inital logs
948 // and any old logs.
petersont@google.comd01b8732008-10-16 02:18:07949 if (!user_permits_upload_)
950 return false;
pkasting@chromium.orgcac78842008-11-27 01:02:20951 if (server_permits_upload_)
petersont@google.comd01b8732008-10-16 02:18:07952 return true;
initial.commit09911bf2008-07-26 23:55:29953
pkasting@chromium.orgcac78842008-11-27 01:02:20954 switch (state_) {
955 case INITIAL_LOG_READY:
956 case SEND_OLD_INITIAL_LOGS:
957 case SENDING_OLD_LOGS:
958 return true;
959
960 case SENDING_CURRENT_LOGS:
961 default:
962 return false;
nsylvain@chromium.org8c8824b2008-09-20 01:55:50963 }
initial.commit09911bf2008-07-26 23:55:29964}
965
966void MetricsService::CollectMemoryDetails() {
967 Task* task = log_sender_factory_.
968 NewRunnableMethod(&MetricsService::TryToStartTransmission);
969 MetricsMemoryDetails* details = new MetricsMemoryDetails(task);
970 details->StartFetch();
971
972 // Collect WebCore cache information to put into a histogram.
973 for (RenderProcessHost::iterator it = RenderProcessHost::begin();
974 it != RenderProcessHost::end(); ++it) {
975 it->second->Send(new ViewMsg_GetCacheResourceStats());
976 }
977}
978
979void MetricsService::PrepareInitialLog() {
980 DCHECK(state_ == PLUGIN_LIST_ARRIVED);
981 std::vector<WebPluginInfo> plugins;
982 PluginService::GetInstance()->GetPlugins(false, &plugins);
983
984 MetricsLog* log = new MetricsLog(client_id_, session_id_);
985 log->RecordEnvironment(plugins, profile_dictionary_.get());
986
987 // Histograms only get written to current_log_, so setup for the write.
988 MetricsLog* save_log = current_log_;
989 current_log_ = log;
990 RecordCurrentHistograms(); // Into current_log_... which is really log.
991 current_log_ = save_log;
992
993 log->CloseLog();
994 DCHECK(!pending_log());
995 pending_log_ = log;
996}
997
998void MetricsService::RecallUnsentLogs() {
999 DCHECK(unsent_initial_logs_.empty());
1000 DCHECK(unsent_ongoing_logs_.empty());
1001
1002 PrefService* local_state = g_browser_process->local_state();
1003 DCHECK(local_state);
1004
1005 ListValue* unsent_initial_logs = local_state->GetMutableList(
1006 prefs::kMetricsInitialLogs);
1007 for (ListValue::iterator it = unsent_initial_logs->begin();
1008 it != unsent_initial_logs->end(); ++it) {
scherkus@chromium.org5e324b72008-12-18 00:07:591009 std::string log;
1010 (*it)->GetAsString(&log);
1011 unsent_initial_logs_.push_back(log);
initial.commit09911bf2008-07-26 23:55:291012 }
1013
1014 ListValue* unsent_ongoing_logs = local_state->GetMutableList(
1015 prefs::kMetricsOngoingLogs);
1016 for (ListValue::iterator it = unsent_ongoing_logs->begin();
1017 it != unsent_ongoing_logs->end(); ++it) {
scherkus@chromium.org5e324b72008-12-18 00:07:591018 std::string log;
1019 (*it)->GetAsString(&log);
1020 unsent_ongoing_logs_.push_back(log);
initial.commit09911bf2008-07-26 23:55:291021 }
1022}
1023
1024void MetricsService::StoreUnsentLogs() {
1025 if (state_ < INITIAL_LOG_READY)
1026 return; // We never Recalled the prior unsent logs.
1027
1028 PrefService* local_state = g_browser_process->local_state();
1029 DCHECK(local_state);
1030
1031 ListValue* unsent_initial_logs = local_state->GetMutableList(
1032 prefs::kMetricsInitialLogs);
1033 unsent_initial_logs->Clear();
1034 size_t start = 0;
1035 if (unsent_initial_logs_.size() > kMaxInitialLogsPersisted)
1036 start = unsent_initial_logs_.size() - kMaxInitialLogsPersisted;
1037 for (size_t i = start; i < unsent_initial_logs_.size(); ++i)
1038 unsent_initial_logs->Append(
scherkus@chromium.org5e324b72008-12-18 00:07:591039 Value::CreateStringValue(unsent_initial_logs_[i]));
initial.commit09911bf2008-07-26 23:55:291040
1041 ListValue* unsent_ongoing_logs = local_state->GetMutableList(
1042 prefs::kMetricsOngoingLogs);
1043 unsent_ongoing_logs->Clear();
1044 start = 0;
1045 if (unsent_ongoing_logs_.size() > kMaxOngoingLogsPersisted)
1046 start = unsent_ongoing_logs_.size() - kMaxOngoingLogsPersisted;
1047 for (size_t i = start; i < unsent_ongoing_logs_.size(); ++i)
1048 unsent_ongoing_logs->Append(
scherkus@chromium.org5e324b72008-12-18 00:07:591049 Value::CreateStringValue(unsent_ongoing_logs_[i]));
initial.commit09911bf2008-07-26 23:55:291050}
1051
1052void MetricsService::PreparePendingLogText() {
1053 DCHECK(pending_log());
1054 if (!pending_log_text_.empty())
1055 return;
1056 int original_size = pending_log_->GetEncodedLogSize();
1057 pending_log_->GetEncodedLog(WriteInto(&pending_log_text_, original_size),
1058 original_size);
1059}
1060
petersont@google.comd01b8732008-10-16 02:18:071061void MetricsService::PrepareFetchWithPendingLog() {
initial.commit09911bf2008-07-26 23:55:291062 DCHECK(pending_log());
1063 DCHECK(!current_fetch_.get());
1064 PreparePendingLogText();
1065 DCHECK(!pending_log_text_.empty());
1066
1067 // Allow security conscious users to see all metrics logs that we send.
1068 LOG(INFO) << "METRICS LOG: " << pending_log_text_;
1069
1070 std::string compressed_log;
pkasting@chromium.orgcac78842008-11-27 01:02:201071 if (!Bzip2Compress(pending_log_text_, &compressed_log)) {
initial.commit09911bf2008-07-26 23:55:291072 NOTREACHED() << "Failed to compress log for transmission.";
1073 DiscardPendingLog();
1074 StartLogTransmissionTimer(); // Maybe we'll do better on next log :-/.
1075 return;
1076 }
pkasting@chromium.orgcac78842008-11-27 01:02:201077
initial.commit09911bf2008-07-26 23:55:291078 current_fetch_.reset(new URLFetcher(GURL(kMetricsURL), URLFetcher::POST,
1079 this));
1080 current_fetch_->set_request_context(Profile::GetDefaultRequestContext());
1081 current_fetch_->set_upload_data(kMetricsType, compressed_log);
initial.commit09911bf2008-07-26 23:55:291082}
1083
1084void MetricsService::DiscardPendingLog() {
1085 if (pending_log_) { // Shutdown might have deleted it!
1086 delete pending_log_;
1087 pending_log_ = NULL;
1088 }
1089 pending_log_text_.clear();
1090}
1091
1092// This implementation is based on the Firefox MetricsService implementation.
1093bool MetricsService::Bzip2Compress(const std::string& input,
1094 std::string* output) {
1095 bz_stream stream = {0};
1096 // As long as our input is smaller than the bzip2 block size, we should get
1097 // the best compression. For example, if your input was 250k, using a block
1098 // size of 300k or 500k should result in the same compression ratio. Since
1099 // our data should be under 100k, using the minimum block size of 100k should
1100 // allocate less temporary memory, but result in the same compression ratio.
1101 int result = BZ2_bzCompressInit(&stream,
1102 1, // 100k (min) block size
1103 0, // quiet
1104 0); // default "work factor"
1105 if (result != BZ_OK) { // out of memory?
1106 return false;
1107 }
1108
1109 output->clear();
1110
1111 stream.next_in = const_cast<char*>(input.data());
1112 stream.avail_in = static_cast<int>(input.size());
1113 // NOTE: we don't need a BZ_RUN phase since our input buffer contains
1114 // the entire input
1115 do {
1116 output->resize(output->size() + 1024);
1117 stream.next_out = &((*output)[stream.total_out_lo32]);
1118 stream.avail_out = static_cast<int>(output->size()) - stream.total_out_lo32;
1119 result = BZ2_bzCompress(&stream, BZ_FINISH);
1120 } while (result == BZ_FINISH_OK);
1121 if (result != BZ_STREAM_END) // unknown failure?
1122 return false;
1123 result = BZ2_bzCompressEnd(&stream);
1124 DCHECK(result == BZ_OK);
1125
1126 output->resize(stream.total_out_lo32);
1127
1128 return true;
1129}
1130
1131static const char* StatusToString(const URLRequestStatus& status) {
1132 switch (status.status()) {
1133 case URLRequestStatus::SUCCESS:
1134 return "SUCCESS";
1135
1136 case URLRequestStatus::IO_PENDING:
1137 return "IO_PENDING";
1138
1139 case URLRequestStatus::HANDLED_EXTERNALLY:
1140 return "HANDLED_EXTERNALLY";
1141
1142 case URLRequestStatus::CANCELED:
1143 return "CANCELED";
1144
1145 case URLRequestStatus::FAILED:
1146 return "FAILED";
1147
1148 default:
1149 NOTREACHED();
1150 return "Unknown";
1151 }
1152}
1153
1154void MetricsService::OnURLFetchComplete(const URLFetcher* source,
1155 const GURL& url,
1156 const URLRequestStatus& status,
1157 int response_code,
1158 const ResponseCookies& cookies,
1159 const std::string& data) {
1160 DCHECK(timer_pending_);
1161 timer_pending_ = false;
1162 DCHECK(current_fetch_.get());
1163 current_fetch_.reset(NULL); // We're not allowed to re-use it.
1164
1165 // Confirm send so that we can move on.
jar@chromium.org281d2882009-01-20 20:32:421166 LOG(INFO) << "METRICS RESPONSE CODE: " << response_code << " status=" <<
pkasting@chromium.orgcac78842008-11-27 01:02:201167 StatusToString(status);
petersont@google.com252873ef2008-08-04 21:59:451168
jar@chromium.org0eb34fee2009-01-21 08:04:381169 // Provide boolean for error recovery (allow us to ignore response_code).
1170 boolean discard_log = false;
1171
jar@google.com68475e602008-08-22 03:21:151172 if (response_code != 200 &&
1173 pending_log_text_.length() > kUploadLogAvoidRetransmitSize) {
1174 UMA_HISTOGRAM_COUNTS(L"UMA.Large Rejected Log was Discarded",
1175 static_cast<int>(pending_log_text_.length()));
jar@chromium.org0eb34fee2009-01-21 08:04:381176 discard_log = true;
1177 } else if (response_code == 400) {
1178 // Bad syntax. Retransmission won't work.
1179 UMA_HISTOGRAM_COUNTS(L"UMA.Unacceptable_Log_Discarded", state_);
1180 discard_log = true;
jar@google.com68475e602008-08-22 03:21:151181 }
1182
jar@chromium.org0eb34fee2009-01-21 08:04:381183 if (response_code != 200 && !discard_log) {
jar@chromium.org281d2882009-01-20 20:32:421184 LOG(INFO) << "METRICS: transmission attempt returned a failure code: "
1185 << response_code << ". Verify network connectivity";
petersont@google.com252873ef2008-08-04 21:59:451186 HandleBadResponseCode();
jar@chromium.org0eb34fee2009-01-21 08:04:381187 } else { // Successful receipt (or we are discarding log).
jar@chromium.org281d2882009-01-20 20:32:421188 LOG(INFO) << "METRICS RESPONSE DATA: " << data;
initial.commit09911bf2008-07-26 23:55:291189 switch (state_) {
1190 case INITIAL_LOG_READY:
1191 state_ = SEND_OLD_INITIAL_LOGS;
1192 break;
1193
1194 case SEND_OLD_INITIAL_LOGS:
1195 DCHECK(!unsent_initial_logs_.empty());
1196 unsent_initial_logs_.pop_back();
1197 StoreUnsentLogs();
1198 break;
1199
1200 case SENDING_OLD_LOGS:
1201 DCHECK(!unsent_ongoing_logs_.empty());
1202 unsent_ongoing_logs_.pop_back();
1203 StoreUnsentLogs();
1204 break;
1205
1206 case SENDING_CURRENT_LOGS:
1207 break;
1208
1209 default:
1210 DCHECK(false);
1211 break;
1212 }
petersont@google.comd01b8732008-10-16 02:18:071213
initial.commit09911bf2008-07-26 23:55:291214 DiscardPendingLog();
jar@google.com29be92552008-08-07 22:49:271215 // Since we sent a log, make sure our in-memory state is recorded to disk.
1216 PrefService* local_state = g_browser_process->local_state();
1217 DCHECK(local_state);
1218 if (local_state)
1219 local_state->ScheduleSavePersistentPrefs(
1220 g_browser_process->file_thread());
petersont@google.com252873ef2008-08-04 21:59:451221
jar@google.com147bbc0b2009-01-06 19:37:401222 // Provide a default (free of exponetial backoff, other varances) in case
1223 // the server does not specify a value.
1224 interlog_duration_ = TimeDelta::FromSeconds(kMinSecondsPerLog);
1225
petersont@google.com252873ef2008-08-04 21:59:451226 GetSettingsFromResponseData(data);
petersont@google.com252873ef2008-08-04 21:59:451227 // Override server specified interlog delay if there are unsent logs to
jar@google.com29be92552008-08-07 22:49:271228 // transmit.
initial.commit09911bf2008-07-26 23:55:291229 if (unsent_logs()) {
1230 DCHECK(state_ < SENDING_CURRENT_LOGS);
1231 interlog_duration_ = TimeDelta::FromSeconds(kUnsentLogDelay);
initial.commit09911bf2008-07-26 23:55:291232 }
1233 }
petersont@google.com252873ef2008-08-04 21:59:451234
initial.commit09911bf2008-07-26 23:55:291235 StartLogTransmissionTimer();
1236}
1237
petersont@google.com252873ef2008-08-04 21:59:451238void MetricsService::HandleBadResponseCode() {
jar@chromium.org281d2882009-01-20 20:32:421239 LOG(INFO) << "Verify your metrics logs are formatted correctly. "
pkasting@chromium.orgcac78842008-11-27 01:02:201240 "Verify server is active at " << kMetricsURL;
petersont@google.com252873ef2008-08-04 21:59:451241 if (!pending_log()) {
jar@chromium.org281d2882009-01-20 20:32:421242 LOG(INFO) << "METRICS: Recorder shutdown during log transmission.";
petersont@google.com252873ef2008-08-04 21:59:451243 } else {
1244 // Send progressively less frequently.
1245 DCHECK(kBackoff > 1.0);
1246 interlog_duration_ = TimeDelta::FromMicroseconds(
1247 static_cast<int64>(kBackoff * interlog_duration_.InMicroseconds()));
1248
1249 if (kMaxBackoff * TimeDelta::FromSeconds(kMinSecondsPerLog) <
pkasting@chromium.orgcac78842008-11-27 01:02:201250 interlog_duration_) {
petersont@google.com252873ef2008-08-04 21:59:451251 interlog_duration_ = kMaxBackoff *
1252 TimeDelta::FromSeconds(kMinSecondsPerLog);
pkasting@chromium.orgcac78842008-11-27 01:02:201253 }
petersont@google.com252873ef2008-08-04 21:59:451254
jar@chromium.org281d2882009-01-20 20:32:421255 LOG(INFO) << "METRICS: transmission retry being scheduled in " <<
petersont@google.com252873ef2008-08-04 21:59:451256 interlog_duration_.InSeconds() << " seconds for " <<
1257 pending_log_text_;
initial.commit09911bf2008-07-26 23:55:291258 }
initial.commit09911bf2008-07-26 23:55:291259}
1260
petersont@google.com252873ef2008-08-04 21:59:451261void MetricsService::GetSettingsFromResponseData(const std::string& data) {
1262 // We assume that the file is structured as a block opened by <response>
petersont@google.comd01b8732008-10-16 02:18:071263 // and that inside response, there is a block opened by tag <chrome_config>
1264 // other tags are ignored for now except the content of <chrome_config>.
jar@chromium.org281d2882009-01-20 20:32:421265 LOG(INFO) << "METRICS: getting settings from response data: " << data;
petersont@google.comd01b8732008-10-16 02:18:071266
petersont@google.com252873ef2008-08-04 21:59:451267 int data_size = static_cast<int>(data.size());
1268 if (data_size < 0) {
jar@chromium.org281d2882009-01-20 20:32:421269 LOG(INFO) << "METRICS: server response data bad size: " << data_size <<
pkasting@chromium.orgcac78842008-11-27 01:02:201270 "; aborting extraction of settings";
petersont@google.com252873ef2008-08-04 21:59:451271 return;
1272 }
pkasting@chromium.orgcac78842008-11-27 01:02:201273 xmlDocPtr doc = xmlReadMemory(data.c_str(), data_size, "", NULL, 0);
petersont@google.com252873ef2008-08-04 21:59:451274 DCHECK(doc);
petersont@google.comd01b8732008-10-16 02:18:071275 // If the document is malformed, we just use the settings that were there.
1276 if (!doc) {
jar@chromium.org281d2882009-01-20 20:32:421277 LOG(INFO) << "METRICS: reading xml from server response data failed";
petersont@google.com252873ef2008-08-04 21:59:451278 return;
petersont@google.comd01b8732008-10-16 02:18:071279 }
petersont@google.com252873ef2008-08-04 21:59:451280
petersont@google.comd01b8732008-10-16 02:18:071281 xmlNodePtr top_node = xmlDocGetRootElement(doc), chrome_config_node = NULL;
1282 // Here, we find the chrome_config node by name.
petersont@google.com252873ef2008-08-04 21:59:451283 for (xmlNodePtr p = top_node->children; p; p = p->next) {
petersont@google.comd01b8732008-10-16 02:18:071284 if (xmlStrEqual(p->name, BAD_CAST "chrome_config")) {
1285 chrome_config_node = p;
petersont@google.com252873ef2008-08-04 21:59:451286 break;
1287 }
1288 }
1289 // If the server data is formatted wrong and there is no
1290 // config node where we expect, we just drop out.
petersont@google.comd01b8732008-10-16 02:18:071291 if (chrome_config_node != NULL)
1292 GetSettingsFromChromeConfigNode(chrome_config_node);
petersont@google.com252873ef2008-08-04 21:59:451293 xmlFreeDoc(doc);
1294}
1295
petersont@google.comd01b8732008-10-16 02:18:071296void MetricsService::GetSettingsFromChromeConfigNode(
1297 xmlNodePtr chrome_config_node) {
1298 // Iterate through all children of the config node.
1299 for (xmlNodePtr current_node = chrome_config_node->children;
1300 current_node;
1301 current_node = current_node->next) {
1302 // If we find the upload tag, we appeal to another function
1303 // GetSettingsFromUploadNode to read all the data in it.
petersont@google.com252873ef2008-08-04 21:59:451304 if (xmlStrEqual(current_node->name, BAD_CAST "upload")) {
petersont@google.comd01b8732008-10-16 02:18:071305 GetSettingsFromUploadNode(current_node);
petersont@google.com252873ef2008-08-04 21:59:451306 continue;
1307 }
1308 }
1309}
initial.commit09911bf2008-07-26 23:55:291310
petersont@google.comd01b8732008-10-16 02:18:071311void MetricsService::InheritedProperties::OverwriteWhereNeeded(
1312 xmlNodePtr node) {
1313 xmlChar* salt_value = xmlGetProp(node, BAD_CAST "salt");
1314 if (salt_value) // If the property isn't there, xmlGetProp returns NULL.
1315 salt = atoi(reinterpret_cast<char*>(salt_value));
1316 // If the property isn't there, we keep the value the property had before
1317
1318 xmlChar* denominator_value = xmlGetProp(node, BAD_CAST "denominator");
1319 if (denominator_value)
1320 denominator = atoi(reinterpret_cast<char*>(denominator_value));
1321}
1322
1323void MetricsService::GetSettingsFromUploadNode(xmlNodePtr upload_node) {
1324 InheritedProperties props;
1325 GetSettingsFromUploadNodeRecursive(upload_node, props, "", true);
1326}
1327
pkasting@chromium.orgcac78842008-11-27 01:02:201328void MetricsService::GetSettingsFromUploadNodeRecursive(
1329 xmlNodePtr node,
1330 InheritedProperties props,
1331 std::string path_prefix,
1332 bool uploadOn) {
petersont@google.comd01b8732008-10-16 02:18:071333 props.OverwriteWhereNeeded(node);
1334
1335 // The bool uploadOn is set to true if the data represented by current
1336 // node should be uploaded. This gets inherited in the tree; the children
1337 // of a node that has already been rejected for upload get rejected for
1338 // upload.
1339 uploadOn = uploadOn && NodeProbabilityTest(node, props);
1340
1341 // The path is a / separated list of the node names ancestral to the current
1342 // one. So, if you want to check if the current node has a certain name,
1343 // compare to name. If you want to check if it is a certan tag at a certain
1344 // place in the tree, compare to the whole path.
1345 std::string name = std::string(reinterpret_cast<const char*>(node->name));
1346 std::string path = path_prefix + "/" + name;
1347
1348 if (path == "/upload") {
1349 xmlChar* upload_interval_val = xmlGetProp(node, BAD_CAST "interval");
1350 if (upload_interval_val) {
1351 interlog_duration_ = TimeDelta::FromSeconds(
1352 atoi(reinterpret_cast<char*>(upload_interval_val)));
1353 }
1354
1355 server_permits_upload_ = uploadOn;
1356 }
1357 if (path == "/upload/logs") {
1358 xmlChar* log_event_limit_val = xmlGetProp(node, BAD_CAST "event_limit");
1359 if (log_event_limit_val)
1360 log_event_limit_ = atoi(reinterpret_cast<char*>(log_event_limit_val));
1361 }
1362 if (name == "histogram") {
1363 xmlChar* type_value = xmlGetProp(node, BAD_CAST "type");
1364 if (type_value) {
1365 std::string type = (reinterpret_cast<char*>(type_value));
1366 if (uploadOn)
1367 histograms_to_upload_.insert(type);
1368 else
1369 histograms_to_omit_.insert(type);
1370 }
1371 }
1372 if (name == "log") {
1373 xmlChar* type_value = xmlGetProp(node, BAD_CAST "type");
1374 if (type_value) {
1375 std::string type = (reinterpret_cast<char*>(type_value));
1376 if (uploadOn)
1377 logs_to_upload_.insert(type);
1378 else
1379 logs_to_omit_.insert(type);
1380 }
1381 }
1382
1383 // Recursive call. If the node is a leaf i.e. if it ends in a "/>", then it
1384 // doesn't have children, so node->children is NULL, and this loop doesn't
1385 // call (that's how the recursion ends).
1386 for (xmlNodePtr child_node = node->children;
pkasting@chromium.orgcac78842008-11-27 01:02:201387 child_node;
1388 child_node = child_node->next) {
petersont@google.comd01b8732008-10-16 02:18:071389 GetSettingsFromUploadNodeRecursive(child_node, props, path, uploadOn);
1390 }
1391}
1392
1393bool MetricsService::NodeProbabilityTest(xmlNodePtr node,
pkasting@chromium.orgcac78842008-11-27 01:02:201394 InheritedProperties props) const {
petersont@google.comd01b8732008-10-16 02:18:071395 // Default value of probability on any node is 1, but recall that
1396 // its parents can already have been rejected for upload.
1397 double probability = 1;
1398
1399 // If a probability is specified in the node, we use it instead.
1400 xmlChar* probability_value = xmlGetProp(node, BAD_CAST "probability");
1401 if (probability_value)
jar@google.com0b33f80b2008-12-17 21:34:361402 probability = atoi(reinterpret_cast<char*>(probability_value));
petersont@google.comd01b8732008-10-16 02:18:071403
1404 return ProbabilityTest(probability, props.salt, props.denominator);
1405}
1406
1407bool MetricsService::ProbabilityTest(double probability,
1408 int salt,
1409 int denominator) const {
1410 // Okay, first we figure out how many of the digits of the
1411 // client_id_ we need in order to make a nice pseudorandomish
1412 // number in the range [0,denominator). Too many digits is
1413 // fine.
pkasting@chromium.orgcac78842008-11-27 01:02:201414 int relevant_digits =
1415 static_cast<int>(log10(static_cast<double>(denominator)) + 1.0);
petersont@google.comd01b8732008-10-16 02:18:071416
1417 // n is the length of the client_id_ string
1418 size_t n = client_id_.size();
1419
1420 // idnumber is a positive integer generated from the client_id_.
1421 // It plus salt is going to give us our pseudorandom number.
1422 int idnumber = 0;
1423 const char* client_id_c_str = client_id_.c_str();
1424
1425 // Here we hash the relevant digits of the client_id_
1426 // string somehow to get a big integer idnumber (could be negative
1427 // from wraparound)
1428 int big = 1;
pkasting@chromium.orgcac78842008-11-27 01:02:201429 for (size_t j = n - 1; j >= 0; --j) {
1430 idnumber += static_cast<int>(client_id_c_str[j]) * big;
petersont@google.comd01b8732008-10-16 02:18:071431 big *= 10;
1432 }
1433
1434 // Mod id number by denominator making sure to get a non-negative
1435 // answer.
pkasting@chromium.orgcac78842008-11-27 01:02:201436 idnumber = ((idnumber % denominator) + denominator) % denominator;
petersont@google.comd01b8732008-10-16 02:18:071437
pkasting@chromium.orgcac78842008-11-27 01:02:201438 // ((idnumber + salt) % denominator) / denominator is in the range [0,1]
petersont@google.comd01b8732008-10-16 02:18:071439 // if it's less than probability we call that an affirmative coin
1440 // toss.
pkasting@chromium.orgcac78842008-11-27 01:02:201441 return static_cast<double>((idnumber + salt) % denominator) <
1442 probability * denominator;
petersont@google.comd01b8732008-10-16 02:18:071443}
1444
initial.commit09911bf2008-07-26 23:55:291445void MetricsService::LogWindowChange(NotificationType type,
1446 const NotificationSource& source,
1447 const NotificationDetails& details) {
brettw@google.com534e54b2008-08-13 15:40:091448 int controller_id = -1;
1449 uintptr_t window_or_tab = source.map_key();
initial.commit09911bf2008-07-26 23:55:291450 MetricsLog::WindowEventType window_type;
1451
1452 // Note: since we stop all logging when a single OTR session is active, it is
1453 // possible that we start getting notifications about a window that we don't
1454 // know about.
brettw@google.com534e54b2008-08-13 15:40:091455 if (window_map_.find(window_or_tab) == window_map_.end()) {
1456 controller_id = next_window_id_++;
1457 window_map_[window_or_tab] = controller_id;
initial.commit09911bf2008-07-26 23:55:291458 } else {
brettw@google.com534e54b2008-08-13 15:40:091459 controller_id = window_map_[window_or_tab];
initial.commit09911bf2008-07-26 23:55:291460 }
brettw@google.com534e54b2008-08-13 15:40:091461 DCHECK(controller_id != -1);
initial.commit09911bf2008-07-26 23:55:291462
brettw@chromium.orgbfd04a62009-02-01 18:16:561463 switch (type.value) {
1464 case NotificationType::TAB_PARENTED:
1465 case NotificationType::BROWSER_OPENED:
initial.commit09911bf2008-07-26 23:55:291466 window_type = MetricsLog::WINDOW_CREATE;
1467 break;
1468
brettw@chromium.orgbfd04a62009-02-01 18:16:561469 case NotificationType::TAB_CLOSING:
1470 case NotificationType::BROWSER_CLOSED:
brettw@google.com534e54b2008-08-13 15:40:091471 window_map_.erase(window_map_.find(window_or_tab));
initial.commit09911bf2008-07-26 23:55:291472 window_type = MetricsLog::WINDOW_DESTROY;
1473 break;
1474
1475 default:
1476 NOTREACHED();
1477 break;
1478 }
1479
brettw@google.com534e54b2008-08-13 15:40:091480 // TODO(brettw) we should have some kind of ID for the parent.
1481 current_log_->RecordWindowEvent(window_type, controller_id, 0);
initial.commit09911bf2008-07-26 23:55:291482}
1483
1484void MetricsService::LogLoadComplete(NotificationType type,
1485 const NotificationSource& source,
1486 const NotificationDetails& details) {
1487 if (details == NotificationService::NoDetails())
1488 return;
1489
jar@google.com68475e602008-08-22 03:21:151490 // TODO(jar): There is a bug causing this to be called too many times, and
1491 // the log overflows. For now, we won't record these events.
1492 UMA_HISTOGRAM_COUNTS(L"UMA.LogLoadComplete called", 1);
1493 return;
1494
initial.commit09911bf2008-07-26 23:55:291495 const Details<LoadNotificationDetails> load_details(details);
brettw@google.com534e54b2008-08-13 15:40:091496 int controller_id = window_map_[details.map_key()];
1497 current_log_->RecordLoadEvent(controller_id,
initial.commit09911bf2008-07-26 23:55:291498 load_details->url(),
1499 load_details->origin(),
1500 load_details->session_index(),
1501 load_details->load_time());
1502}
1503
cpu@google.come73c01972008-08-13 00:18:241504void MetricsService::IncrementPrefValue(const wchar_t* path) {
1505 PrefService* pref = g_browser_process->local_state();
1506 DCHECK(pref);
1507 int value = pref->GetInteger(path);
1508 pref->SetInteger(path, value + 1);
1509}
1510
initial.commit09911bf2008-07-26 23:55:291511void MetricsService::LogLoadStarted() {
cpu@google.come73c01972008-08-13 00:18:241512 IncrementPrefValue(prefs::kStabilityPageLoadCount);
jar@google.com0b33f80b2008-12-17 21:34:361513 // We need to save the prefs, as page load count is a critical stat, and it
1514 // might be lost due to a crash :-(.
initial.commit09911bf2008-07-26 23:55:291515}
1516
1517void MetricsService::LogRendererInSandbox(bool on_sandbox_desktop) {
1518 PrefService* prefs = g_browser_process->local_state();
1519 DCHECK(prefs);
cpu@google.come73c01972008-08-13 00:18:241520 if (on_sandbox_desktop)
1521 IncrementPrefValue(prefs::kSecurityRendererOnSboxDesktop);
1522 else
1523 IncrementPrefValue(prefs::kSecurityRendererOnDefaultDesktop);
initial.commit09911bf2008-07-26 23:55:291524}
1525
1526void MetricsService::LogRendererCrash() {
cpu@google.come73c01972008-08-13 00:18:241527 IncrementPrefValue(prefs::kStabilityRendererCrashCount);
initial.commit09911bf2008-07-26 23:55:291528}
1529
1530void MetricsService::LogRendererHang() {
cpu@google.come73c01972008-08-13 00:18:241531 IncrementPrefValue(prefs::kStabilityRendererHangCount);
initial.commit09911bf2008-07-26 23:55:291532}
1533
1534void MetricsService::LogPluginChange(NotificationType type,
1535 const NotificationSource& source,
1536 const NotificationDetails& details) {
avi@google.com690a99c2009-01-06 16:48:451537 FilePath plugin = Details<PluginProcessInfo>(details)->plugin_path();
initial.commit09911bf2008-07-26 23:55:291538
1539 if (plugin_stats_buffer_.find(plugin) == plugin_stats_buffer_.end()) {
1540 plugin_stats_buffer_[plugin] = PluginStats();
1541 }
1542
1543 PluginStats& stats = plugin_stats_buffer_[plugin];
brettw@chromium.orgbfd04a62009-02-01 18:16:561544 switch (type.value) {
1545 case NotificationType::PLUGIN_PROCESS_HOST_CONNECTED:
initial.commit09911bf2008-07-26 23:55:291546 stats.process_launches++;
1547 break;
1548
brettw@chromium.orgbfd04a62009-02-01 18:16:561549 case NotificationType::PLUGIN_INSTANCE_CREATED:
initial.commit09911bf2008-07-26 23:55:291550 stats.instances++;
1551 break;
1552
brettw@chromium.orgbfd04a62009-02-01 18:16:561553 case NotificationType::PLUGIN_PROCESS_CRASHED:
initial.commit09911bf2008-07-26 23:55:291554 stats.process_crashes++;
1555 break;
1556
1557 default:
brettw@chromium.orgbfd04a62009-02-01 18:16:561558 NOTREACHED() << "Unexpected notification type " << type.value;
initial.commit09911bf2008-07-26 23:55:291559 return;
1560 }
1561}
1562
1563// Recursively counts the number of bookmarks and folders in node.
sky@google.comd8e41ed2008-09-11 15:22:321564static void CountBookmarks(BookmarkNode* node, int* bookmarks, int* folders) {
initial.commit09911bf2008-07-26 23:55:291565 if (node->GetType() == history::StarredEntry::URL)
1566 (*bookmarks)++;
1567 else
1568 (*folders)++;
1569 for (int i = 0; i < node->GetChildCount(); ++i)
1570 CountBookmarks(node->GetChild(i), bookmarks, folders);
1571}
1572
sky@google.comd8e41ed2008-09-11 15:22:321573void MetricsService::LogBookmarks(BookmarkNode* node,
initial.commit09911bf2008-07-26 23:55:291574 const wchar_t* num_bookmarks_key,
1575 const wchar_t* num_folders_key) {
1576 DCHECK(node);
1577 int num_bookmarks = 0;
1578 int num_folders = 0;
1579 CountBookmarks(node, &num_bookmarks, &num_folders);
1580 num_folders--; // Don't include the root folder in the count.
1581
1582 PrefService* pref = g_browser_process->local_state();
1583 DCHECK(pref);
1584 pref->SetInteger(num_bookmarks_key, num_bookmarks);
1585 pref->SetInteger(num_folders_key, num_folders);
1586}
1587
sky@google.comd8e41ed2008-09-11 15:22:321588void MetricsService::LogBookmarks(BookmarkModel* model) {
initial.commit09911bf2008-07-26 23:55:291589 DCHECK(model);
1590 LogBookmarks(model->GetBookmarkBarNode(),
1591 prefs::kNumBookmarksOnBookmarkBar,
1592 prefs::kNumFoldersOnBookmarkBar);
1593 LogBookmarks(model->other_node(),
1594 prefs::kNumBookmarksInOtherBookmarkFolder,
1595 prefs::kNumFoldersInOtherBookmarkFolder);
1596 ScheduleNextStateSave();
1597}
1598
1599void MetricsService::LogKeywords(const TemplateURLModel* url_model) {
1600 DCHECK(url_model);
1601
1602 PrefService* pref = g_browser_process->local_state();
1603 DCHECK(pref);
1604 pref->SetInteger(prefs::kNumKeywords,
1605 static_cast<int>(url_model->GetTemplateURLs().size()));
1606 ScheduleNextStateSave();
1607}
1608
1609void MetricsService::RecordPluginChanges(PrefService* pref) {
1610 ListValue* plugins = pref->GetMutableList(prefs::kStabilityPluginStats);
1611 DCHECK(plugins);
1612
1613 for (ListValue::iterator value_iter = plugins->begin();
1614 value_iter != plugins->end(); ++value_iter) {
1615 if (!(*value_iter)->IsType(Value::TYPE_DICTIONARY)) {
1616 NOTREACHED();
1617 continue;
1618 }
1619
1620 DictionaryValue* plugin_dict = static_cast<DictionaryValue*>(*value_iter);
avi@google.com690a99c2009-01-06 16:48:451621 FilePath::StringType plugin_path_str;
1622 plugin_dict->GetString(prefs::kStabilityPluginPath, &plugin_path_str);
1623 if (plugin_path_str.empty()) {
initial.commit09911bf2008-07-26 23:55:291624 NOTREACHED();
1625 continue;
1626 }
1627
avi@google.com690a99c2009-01-06 16:48:451628 FilePath plugin_path(plugin_path_str);
initial.commit09911bf2008-07-26 23:55:291629 if (plugin_stats_buffer_.find(plugin_path) == plugin_stats_buffer_.end())
1630 continue;
1631
1632 PluginStats stats = plugin_stats_buffer_[plugin_path];
1633 if (stats.process_launches) {
1634 int launches = 0;
1635 plugin_dict->GetInteger(prefs::kStabilityPluginLaunches, &launches);
1636 launches += stats.process_launches;
1637 plugin_dict->SetInteger(prefs::kStabilityPluginLaunches, launches);
1638 }
1639 if (stats.process_crashes) {
1640 int crashes = 0;
1641 plugin_dict->GetInteger(prefs::kStabilityPluginCrashes, &crashes);
1642 crashes += stats.process_crashes;
1643 plugin_dict->SetInteger(prefs::kStabilityPluginCrashes, crashes);
1644 }
1645 if (stats.instances) {
1646 int instances = 0;
1647 plugin_dict->GetInteger(prefs::kStabilityPluginInstances, &instances);
1648 instances += stats.instances;
1649 plugin_dict->SetInteger(prefs::kStabilityPluginInstances, instances);
1650 }
1651
1652 plugin_stats_buffer_.erase(plugin_path);
1653 }
1654
1655 // Now go through and add dictionaries for plugins that didn't already have
1656 // reports in Local State.
avi@google.com690a99c2009-01-06 16:48:451657 for (std::map<FilePath, PluginStats>::iterator cache_iter =
initial.commit09911bf2008-07-26 23:55:291658 plugin_stats_buffer_.begin();
1659 cache_iter != plugin_stats_buffer_.end(); ++cache_iter) {
avi@google.com690a99c2009-01-06 16:48:451660 FilePath plugin_path = cache_iter->first;
initial.commit09911bf2008-07-26 23:55:291661 PluginStats stats = cache_iter->second;
1662 DictionaryValue* plugin_dict = new DictionaryValue;
1663
avi@google.com690a99c2009-01-06 16:48:451664 plugin_dict->SetString(prefs::kStabilityPluginPath, plugin_path.value());
initial.commit09911bf2008-07-26 23:55:291665 plugin_dict->SetInteger(prefs::kStabilityPluginLaunches,
1666 stats.process_launches);
1667 plugin_dict->SetInteger(prefs::kStabilityPluginCrashes,
1668 stats.process_crashes);
1669 plugin_dict->SetInteger(prefs::kStabilityPluginInstances,
1670 stats.instances);
1671 plugins->Append(plugin_dict);
1672 }
1673 plugin_stats_buffer_.clear();
1674}
1675
1676bool MetricsService::CanLogNotification(NotificationType type,
1677 const NotificationSource& source,
1678 const NotificationDetails& details) {
1679 // We simply don't log anything to UMA if there is a single off the record
1680 // session visible. The problem is that we always notify using the orginal
1681 // profile in order to simplify notification processing.
1682 return !BrowserList::IsOffTheRecordSessionActive();
1683}
1684
1685void MetricsService::RecordBooleanPrefValue(const wchar_t* path, bool value) {
1686 DCHECK(IsSingleThreaded());
1687
1688 PrefService* pref = g_browser_process->local_state();
1689 DCHECK(pref);
1690
1691 pref->SetBoolean(path, value);
1692 RecordCurrentState(pref);
1693}
1694
1695void MetricsService::RecordCurrentState(PrefService* pref) {
1696 pref->SetString(prefs::kStabilityLastTimestampSec,
1697 Int64ToWString(Time::Now().ToTimeT()));
1698
1699 RecordPluginChanges(pref);
1700}
1701
1702void MetricsService::RecordCurrentHistograms() {
1703 DCHECK(current_log_);
1704
1705 StatisticsRecorder::Histograms histograms;
1706 StatisticsRecorder::GetHistograms(&histograms);
1707 for (StatisticsRecorder::Histograms::iterator it = histograms.begin();
1708 histograms.end() != it;
pkasting@chromium.orgcac78842008-11-27 01:02:201709 ++it) {
initial.commit09911bf2008-07-26 23:55:291710 if ((*it)->flags() & kUmaTargetedHistogramFlag)
jar@google.com0b33f80b2008-12-17 21:34:361711 // TODO(petersont): Only record historgrams if they are not precluded by
1712 // the UMA response data.
petersont@google.comd01b8732008-10-16 02:18:071713 // Bug http://code.google.com/p/chromium/issues/detail?id=2739.
initial.commit09911bf2008-07-26 23:55:291714 RecordHistogram(**it);
1715 }
1716}
1717
1718void MetricsService::RecordHistogram(const Histogram& histogram) {
1719 // Get up-to-date snapshot of sample stats.
1720 Histogram::SampleSet snapshot;
1721 histogram.SnapshotSample(&snapshot);
1722
1723 const std::string& histogram_name = histogram.histogram_name();
1724
1725 // Find the already sent stats, or create an empty set.
1726 LoggedSampleMap::iterator it = logged_samples_.find(histogram_name);
1727 Histogram::SampleSet* already_logged;
1728 if (logged_samples_.end() == it) {
1729 // Add new entry
1730 already_logged = &logged_samples_[histogram.histogram_name()];
1731 already_logged->Resize(histogram); // Complete initialization.
1732 } else {
1733 already_logged = &(it->second);
1734 // Deduct any stats we've already logged from our snapshot.
1735 snapshot.Subtract(*already_logged);
1736 }
1737
1738 // snapshot now contains only a delta to what we've already_logged.
1739
1740 if (snapshot.TotalCount() > 0) {
1741 current_log_->RecordHistogramDelta(histogram, snapshot);
1742 // Add new data into our running total.
1743 already_logged->Add(snapshot);
1744 }
1745}
1746
1747void MetricsService::AddProfileMetric(Profile* profile,
1748 const std::wstring& key,
1749 int value) {
1750 // Restriction of types is needed for writing values. See
1751 // MetricsLog::WriteProfileMetrics.
1752 DCHECK(profile && !key.empty());
1753 PrefService* prefs = g_browser_process->local_state();
1754 DCHECK(prefs);
1755
1756 // Key is stored in prefs, which interpret '.'s as paths. As such, key
1757 // shouldn't have any '.'s in it.
1758 DCHECK(key.find(L'.') == std::wstring::npos);
1759 // The id is most likely an email address. We shouldn't send it to the server.
1760 const std::wstring id_hash =
1761 UTF8ToWide(MetricsLog::CreateBase64Hash(WideToUTF8(profile->GetID())));
1762 DCHECK(id_hash.find('.') == std::string::npos);
1763
1764 DictionaryValue* prof_prefs = prefs->GetMutableDictionary(
1765 prefs::kProfileMetrics);
1766 DCHECK(prof_prefs);
1767 const std::wstring pref_key = std::wstring(prefs::kProfilePrefix) + id_hash +
1768 L"." + key;
1769 prof_prefs->SetInteger(pref_key.c_str(), value);
1770}
1771
1772static bool IsSingleThreaded() {
1773 static int thread_id = 0;
1774 if (!thread_id)
1775 thread_id = GetCurrentThreadId();
1776 return GetCurrentThreadId() == thread_id;
1777}