blob: 524b4ebbe3ad05c56353121bdbde4130881a2248 [file] [log] [blame]
initial.commit09911bf2008-07-26 23:55:291// Copyright 2008, Google Inc.
2// All rights reserved.
3//
4// Redistribution and use in source and binary forms, with or without
5// modification, are permitted provided that the following conditions are
6// met:
7//
8// * Redistributions of source code must retain the above copyright
9// notice, this list of conditions and the following disclaimer.
10// * Redistributions in binary form must reproduce the above
11// copyright notice, this list of conditions and the following disclaimer
12// in the documentation and/or other materials provided with the
13// distribution.
14// * Neither the name of Google Inc. nor the names of its
15// contributors may be used to endorse or promote products derived from
16// this software without specific prior written permission.
17//
18// THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS
19// "AS IS" AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT
20// LIMITED TO, THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR
21// A PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT
22// OWNER OR CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL,
23// SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT
24// LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF USE,
25// DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON ANY
26// THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT
27// (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE
28// OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
29
30
31
32//------------------------------------------------------------------------------
33// Description of the life cycle of a instance of MetricsService.
34//
35// OVERVIEW
36//
37// A MetricsService instance is typically created at application startup. It
38// is the central controller for the acquisition of log data, and the automatic
39// transmission of that log data to an external server. Its major job is to
40// manage logs, grouping them for transmission, and transmitting them. As part
41// of its grouping, MS finalizes logs by including some just-in-time gathered
42// memory statistics, snapshotting the current stats of numerous histograms,
43// closing the logs, translating to XML text, and compressing the results for
44// transmission. Transmission includes submitting a compressed log as data in a
45// URL-get, and retransmitting (or retaining at process termination) if the
46// attempted transmission failed. Retention across process terminations is done
47// using the the PrefServices facilities. The format for the retained
48// logs (ones that never got transmitted) is always the uncompressed textual
49// representation.
50//
51// Logs fall into one of two categories: "Initial logs," and "ongoing logs."
52// There is at most one initial log sent for each complete run of the chrome
53// product (from startup, to browser shutdown). An initial log is generally
54// transmitted some short time (1 minute?) after startup, and includes stats
55// such as recent crash info, the number and types of plugins, etc. The
56// external server's response to the initial log conceptually tells
57// this MS if it should continue transmitting logs (during this session). The
58// server response can actually be much more detailed, and always includes (at
59// a minimum) how often additional ongoing logs should be sent.
60//
61// After the above initial log, a series of ongoing logs will be transmitted.
62// The first ongoing log actually begins to accumulate information stating when
63// the MS was first constructed. Note that even though the initial log is
64// commonly sent a full minute after startup, the initial log does not include
65// much in the way of user stats. The most common interlog period (delay)
66// is 5 minutes. That time period starts when the first user action causes a
67// logging event. This means that if there is no user action, there may be long
68// periods without any (ongoing) log transmissions. Ongoing log typically
69// contain very detailed records of user activities (ex: opened tab, closed
70// tab, fetched URL, maximized window, etc.) In addition, just before an
71// ongoing log is closed out, a call is made to gather memory statistics. Those
72// memory statistics are deposited into a histogram, and the log finalization
73// code is then called. In the finalization, a call to a Histogram server
74// acquires a list of all local histograms that have been flagged for upload
75// to the UMA server.
76//
77// When the browser shuts down, there will typically be a fragment of an ongoing
78// log that has not yet been transmitted. At shutdown time, that fragment
79// is closed (including snapshotting histograms), and converted to text. Note
80// that memory stats are not gathered during shutdown, as gathering *might* be
81// too time consuming. The textual representation of the fragment of the
82// ongoing log is then stored persistently as a string in the PrefServices, for
83// potential transmission during a future run of the product.
84//
85// There are two slightly abnormal shutdown conditions. There is a
86// "disconnected scenario," and a "really fast startup and shutdown" scenario.
87// In the "never connected" situation, the user has (during the running of the
88// process) never established an internet connection. As a result, attempts to
89// transmit the initial log have failed, and a lot(?) of data has accumulated in
90// the ongoing log (which didn't yet get closed, because there was never even a
91// contemplation of sending it). There is also a kindred "lost connection"
92// situation, where a loss of connection prevented an ongoing log from being
93// transmitted, and a (still open) log was stuck accumulating a lot(?) of data,
94// while the earlier log retried its transmission. In both of these
95// disconnected situations, two logs need to be, and are, persistently stored
96// for future transmission.
97//
98// The other unusual shutdown condition, termed "really fast startup and
99// shutdown," involves the deliberate user termination of the process before
100// the initial log is even formed or transmitted. In that situation, no logging
101// is done, but the historical crash statistics remain (unlogged) for inclusion
102// in a future run's initial log. (i.e., we don't lose crash stats).
103//
104// With the above overview, we can now describe the state machine's various
105// stats, based on the State enum specified in the state_ member. Those states
106// are:
107//
108// INITIALIZED, // Constructor was called.
109// PLUGIN_LIST_REQUESTED, // Waiting for DLL list to be loaded.
110// PLUGIN_LIST_ARRIVED, // Waiting for timer to send initial log.
111// INITIAL_LOG_READY, // Initial log generated, and waiting for reply.
112// SEND_OLD_INITIAL_LOGS, // Sending unsent logs from previous session.
113// SENDING_OLD_LOGS, // Sending unsent logs from previous session.
114// SENDING_CURRENT_LOGS, // Sending standard current logs as they accrue.
115//
116// In more detail, we have:
117//
118// INITIALIZED, // Constructor was called.
119// The MS has been constructed, but has taken no actions to compose the
120// initial log.
121//
122// PLUGIN_LIST_REQUESTED, // Waiting for DLL list to be loaded.
123// Typically about 30 seconds after startup, a task is sent to a second thread
124// to get the list of plugins. That task will (when complete) make an async
125// callback (via a Task) to indicate the completion.
126//
127// PLUGIN_LIST_ARRIVED, // Waiting for timer to send initial log.
128// The callback has arrived, and it is now possible for an initial log to be
129// created. This callback typically arrives back less than one second after
130// the task is dispatched.
131//
132// INITIAL_LOG_READY, // Initial log generated, and waiting for reply.
133// This state is entered only after an initial log has been composed, and
134// prepared for transmission. It is also the case that any previously unsent
135// logs have been loaded into instance variables for possible transmission.
136//
137// SEND_OLD_INITIAL_LOGS, // Sending unsent logs from previous session.
138// This state indicates that the initial log for this session has been
139// successfully sent and it is now time to send any "initial logs" that were
140// saved from previous sessions. Most commonly, there are none, but all old
141// logs that were "initial logs" must be sent before this state is exited.
142//
143// SENDING_OLD_LOGS, // Sending unsent logs from previous session.
144// This state indicates that there are no more unsent initial logs, and now any
145// ongoing logs from previous sessions should be transmitted. All such logs
146// will be transmitted before exiting this state, and proceeding with ongoing
147// logs from the current session (see next state).
148//
149// SENDING_CURRENT_LOGS, // Sending standard current logs as they accrue.
150// Current logs are being accumulated. Typically every 5 minutes a log is
151// closed and finalized for transmission, at the same time as a new log is
152// started.
153//
154// The progression through the above states is simple, and sequential, in the
155// most common use cases. States proceed from INITIAL to SENDING_CURRENT_LOGS,
156// and remain in the latter until shutdown.
157//
158// The one unusual case is when the user asks that we stop logging. When that
159// happens, any pending (transmission in progress) log is pushed into the list
160// of old unsent logs (the appropriate list, depending on whether it is an
161// initial log, or an ongoing log). An addition, any log that is currently
162// accumulating is also finalized, and pushed into the unsent log list. With
163// those pushed performed, we regress back to the SEND_OLD_INITIAL_LOGS state in
164// case the user enables log recording again during this session. This way
165// anything we have "pushed back" will be sent automatically if/when we progress
166// back to SENDING_CURRENT_LOG state.
167//
168// Also note that whenever the member variables containing unsent logs are
169// modified (i.e., when we send an old log), we mirror the list of logs into
170// the PrefServices. This ensures that IF we crash, we won't start up and
171// retransmit our old logs again.
172//
173// Due to race conditions, it is always possible that a log file could be sent
174// twice. For example, if a log file is sent, but not yet acknowledged by
175// the external server, and the user shuts down, then a copy of the log may be
176// saved for re-transmission. These duplicates could be filtered out server
177// side, but are not expected to be a significantly statistical problem.
178//
179//
180//------------------------------------------------------------------------------
181
182#include <windows.h>
183
184#include "chrome/browser/metrics_service.h"
185
186#include "base/histogram.h"
187#include "base/path_service.h"
188#include "base/string_util.h"
189#include "base/task.h"
190#include "chrome/app/google_update_settings.h"
191#include "chrome/browser/bookmark_bar_model.h"
192#include "chrome/browser/browser.h"
193#include "chrome/browser/browser_list.h"
194#include "chrome/browser/browser_process.h"
195#include "chrome/browser/load_notification_details.h"
196#include "chrome/browser/memory_details.h"
197#include "chrome/browser/plugin_process_info.h"
198#include "chrome/browser/plugin_service.h"
199#include "chrome/browser/profile.h"
200#include "chrome/browser/render_process_host.h"
201#include "chrome/browser/template_url.h"
202#include "chrome/browser/template_url_model.h"
203#include "chrome/common/chrome_paths.h"
[email protected]252873ef2008-08-04 21:59:45204#include "chrome/common/libxml_utils.h"
initial.commit09911bf2008-07-26 23:55:29205#include "chrome/common/pref_names.h"
206#include "chrome/common/pref_service.h"
207#include "googleurl/src/gurl.h"
208#include "net/base/load_flags.h"
209#include "third_party/bzip2/bzlib.h"
210
211// Check to see that we're being called on only one thread.
212static bool IsSingleThreaded();
213
214static const char kMetricsURL[] =
215 "https://toolbarqueries.google.com/firefox/metrics/collect";
216
217static const char kMetricsType[] = "application/vnd.mozilla.metrics.bz2";
218
219// The delay, in seconds, after startup before sending the first log message.
[email protected]252873ef2008-08-04 21:59:45220static const int kInitialInterlogDuration = 60; // one minute
221
222// The default maximum number of events in a log uploaded to the UMA server.
223// TODO(petersont): Honor the limit when the log is actually sent.
224static const int kInitialEventLimit = 1000000;
initial.commit09911bf2008-07-26 23:55:29225
226// When we have logs from previous Chrome sessions to send, how long should we
227// delay (in seconds) between each log transmission.
228static const int kUnsentLogDelay = 15; // 15 seconds
229
230// Minimum time a log typically exists before sending, in seconds.
231// This number is supplied by the server, but until we parse it out of a server
232// response, we use this duration to specify how long we should wait before
233// sending the next log. If the channel is busy, such as when there is a
234// failure during an attempt to transmit a previous log, then a log may wait
235// (and continue to accrue now log entries) for a much greater period of time.
236static const int kMinSecondsPerLog = 5 * 60; // five minutes
237
238// We accept suggestions from the log server for how long to wait between
239// submitting logs. We validate that this "suggestion" is at least the
240// following:
241static const int kMinSuggestedSecondsPerLog = 60;
242
243// When we don't succeed at transmitting a log to a server, we progressively
244// wait longer and longer before sending the next log. This backoff process
245// help reduce load on the server, and makes the amount of backoff vary between
246// clients so that a collision (server overload?) on retransmit is less likely.
247// The following is the constant we use to expand that inter-log duration.
248static const double kBackoff = 1.1;
249// We limit the maximum backoff to be no greater than some multiple of the
250// default kMinSecondsPerLog. The following is that maximum ratio.
251static const int kMaxBackoff = 10;
252
253// Interval, in seconds, between state saves.
254static const int kSaveStateInterval = 5 * 60; // five minutes
255
256// The number of "initial" logs we're willing to save, and hope to send during
257// a future Chrome session. Initial logs contain crash stats, and are pretty
258// small.
259static const size_t kMaxInitialLogsPersisted = 20;
260
261// The number of ongoing logs we're willing to save persistently, and hope to
262// send during a this or future sessions. Note that each log will be pretty
263// large, as presumably the related "initial" log wasn't sent (probably nothing
264// was, as the user was probably off-line). As a result, the log probably kept
265// accumulating while the "initial" log was stalled (pending_), and couldn't be
266// sent. As a result, we don't want to save too many of these mega-logs.
267// A "standard shutdown" will create a small log, including just the data that
268// was not yet been transmitted, and that is normal (to have exactly one
269// ongoing_log_ at startup).
270static const size_t kMaxOngoingLogsPersisted = 4;
271
272
273// Handles asynchronous fetching of memory details.
274// Will run the provided task after finished.
275class MetricsMemoryDetails : public MemoryDetails {
276 public:
277 explicit MetricsMemoryDetails(Task* completion) : completion_(completion) {}
278
279 virtual void OnDetailsAvailable() {
280 MessageLoop::current()->PostTask(FROM_HERE, completion_);
281 }
282
283 private:
284 Task* completion_;
285 DISALLOW_EVIL_CONSTRUCTORS(MetricsMemoryDetails);
286};
287
288class MetricsService::GetPluginListTaskComplete : public Task {
289 virtual void Run() {
290 g_browser_process->metrics_service()->OnGetPluginListTaskComplete();
291 }
292};
293
294class MetricsService::GetPluginListTask : public Task {
295 public:
296 explicit GetPluginListTask(MessageLoop* callback_loop)
297 : callback_loop_(callback_loop) {}
298
299 virtual void Run() {
300 std::vector<WebPluginInfo> plugins;
301 PluginService::GetInstance()->GetPlugins(false, &plugins);
302
303 callback_loop_->PostTask(FROM_HERE, new GetPluginListTaskComplete());
304 }
305
306 private:
307 MessageLoop* callback_loop_;
308};
309
310// static
311void MetricsService::RegisterPrefs(PrefService* local_state) {
312 DCHECK(IsSingleThreaded());
313 local_state->RegisterStringPref(prefs::kMetricsClientID, L"");
314 local_state->RegisterStringPref(prefs::kMetricsClientIDTimestamp, L"0");
315 local_state->RegisterStringPref(prefs::kStabilityLaunchTimeSec, L"0");
316 local_state->RegisterStringPref(prefs::kStabilityLastTimestampSec, L"0");
317 local_state->RegisterStringPref(prefs::kStabilityUptimeSec, L"0");
318 local_state->RegisterBooleanPref(prefs::kStabilityExitedCleanly, true);
319 local_state->RegisterBooleanPref(prefs::kStabilitySessionEndCompleted, true);
320 local_state->RegisterIntegerPref(prefs::kMetricsSessionID, -1);
321 local_state->RegisterIntegerPref(prefs::kStabilityLaunchCount, 0);
322 local_state->RegisterIntegerPref(prefs::kStabilityCrashCount, 0);
323 local_state->RegisterIntegerPref(prefs::kStabilityIncompleteSessionEndCount,
324 0);
325 local_state->RegisterIntegerPref(prefs::kStabilityPageLoadCount, 0);
326 local_state->RegisterIntegerPref(prefs::kSecurityRendererOnSboxDesktop, 0);
327 local_state->RegisterIntegerPref(prefs::kSecurityRendererOnDefaultDesktop, 0);
328 local_state->RegisterIntegerPref(prefs::kStabilityRendererCrashCount, 0);
329 local_state->RegisterIntegerPref(prefs::kStabilityRendererHangCount, 0);
[email protected]e73c01972008-08-13 00:18:24330 local_state->RegisterIntegerPref(prefs::kStabilityBreakpadRegistrationFail,
331 0);
332 local_state->RegisterIntegerPref(prefs::kStabilityBreakpadRegistrationSuccess,
333 0);
334 local_state->RegisterIntegerPref(prefs::kStabilityDebuggerPresent, 0);
335 local_state->RegisterIntegerPref(prefs::kStabilityDebuggerNotPresent, 0);
336
initial.commit09911bf2008-07-26 23:55:29337 local_state->RegisterDictionaryPref(prefs::kProfileMetrics);
338 local_state->RegisterIntegerPref(prefs::kNumBookmarksOnBookmarkBar, 0);
339 local_state->RegisterIntegerPref(prefs::kNumFoldersOnBookmarkBar, 0);
340 local_state->RegisterIntegerPref(prefs::kNumBookmarksInOtherBookmarkFolder,
341 0);
342 local_state->RegisterIntegerPref(prefs::kNumFoldersInOtherBookmarkFolder, 0);
343 local_state->RegisterIntegerPref(prefs::kNumKeywords, 0);
344 local_state->RegisterListPref(prefs::kMetricsInitialLogs);
345 local_state->RegisterListPref(prefs::kMetricsOngoingLogs);
346}
347
348MetricsService::MetricsService()
349 : recording_(false),
350 reporting_(true),
351 pending_log_(NULL),
352 pending_log_text_(""),
353 current_fetch_(NULL),
354 current_log_(NULL),
355 state_(INITIALIZED),
356 next_window_id_(0),
357 log_sender_factory_(this),
358 state_saver_factory_(this),
359 logged_samples_(),
[email protected]252873ef2008-08-04 21:59:45360 interlog_duration_(TimeDelta::FromSeconds(kInitialInterlogDuration)),
361 event_limit_(kInitialEventLimit),
initial.commit09911bf2008-07-26 23:55:29362 timer_pending_(false) {
363 DCHECK(IsSingleThreaded());
364 InitializeMetricsState();
365}
366
367MetricsService::~MetricsService() {
368 SetRecording(false);
369}
370
371void MetricsService::SetRecording(bool enabled) {
372 DCHECK(IsSingleThreaded());
373
374 if (enabled == recording_)
375 return;
376
377 if (enabled) {
378 StartRecording();
379 ListenerRegistration(true);
380 } else {
381 // Turn off all observers.
382 ListenerRegistration(false);
383 PushPendingLogsToUnsentLists();
384 DCHECK(!pending_log());
385 if (state_ > INITIAL_LOG_READY && unsent_logs())
386 state_ = SEND_OLD_INITIAL_LOGS;
387 }
388 recording_ = enabled;
389}
390
391bool MetricsService::IsRecording() const {
392 DCHECK(IsSingleThreaded());
393 return recording_;
394}
395
396bool MetricsService::EnableReporting(bool enable) {
397 bool done = GoogleUpdateSettings::SetCollectStatsConsent(enable);
398 if (!done) {
399 bool update_pref = GoogleUpdateSettings::GetCollectStatsConsent();
400 if (enable != update_pref) {
401 DLOG(INFO) << "METRICS: Unable to set crash report status to " << enable;
402 return false;
403 }
404 }
405 if (reporting_ != enable) {
406 reporting_ = enable;
407 if (reporting_)
408 StartLogTransmissionTimer();
409 }
410 return true;
411}
412
413void MetricsService::Observe(NotificationType type,
414 const NotificationSource& source,
415 const NotificationDetails& details) {
416 DCHECK(current_log_);
417 DCHECK(IsSingleThreaded());
418
419 if (!CanLogNotification(type, source, details))
420 return;
421
422 switch (type) {
423 case NOTIFY_USER_ACTION:
424 current_log_->RecordUserAction(*Details<const wchar_t*>(details).ptr());
425 break;
426
427 case NOTIFY_BROWSER_OPENED:
428 case NOTIFY_BROWSER_CLOSED:
429 LogWindowChange(type, source, details);
430 break;
431
[email protected]534e54b2008-08-13 15:40:09432 case NOTIFY_TAB_PARENTED:
initial.commit09911bf2008-07-26 23:55:29433 case NOTIFY_TAB_CLOSING:
434 LogWindowChange(type, source, details);
435 break;
436
437 case NOTIFY_LOAD_STOP:
438 LogLoadComplete(type, source, details);
439 break;
440
441 case NOTIFY_LOAD_START:
442 LogLoadStarted();
443 break;
444
445 case NOTIFY_RENDERER_PROCESS_TERMINATED:
446 if (!*Details<bool>(details).ptr())
447 LogRendererCrash();
448 break;
449
450 case NOTIFY_RENDERER_PROCESS_HANG:
451 LogRendererHang();
452 break;
453
454 case NOTIFY_RENDERER_PROCESS_IN_SBOX:
455 LogRendererInSandbox(*Details<bool>(details).ptr());
456 break;
457
458 case NOTIFY_PLUGIN_PROCESS_HOST_CONNECTED:
459 case NOTIFY_PLUGIN_PROCESS_CRASHED:
460 case NOTIFY_PLUGIN_INSTANCE_CREATED:
461 LogPluginChange(type, source, details);
462 break;
463
464 case TEMPLATE_URL_MODEL_LOADED:
465 LogKeywords(Source<TemplateURLModel>(source).ptr());
466 break;
467
468 case NOTIFY_OMNIBOX_OPENED_URL:
469 current_log_->RecordOmniboxOpenedURL(
470 *Details<AutocompleteLog>(details).ptr());
471 break;
472
473 case NOTIFY_BOOKMARK_MODEL_LOADED:
474 LogBookmarks(Source<Profile>(source)->GetBookmarkBarModel());
475 break;
476
477 default:
478 NOTREACHED();
479 break;
480 }
481 StartLogTransmissionTimer();
482}
483
484void MetricsService::RecordCleanShutdown() {
485 RecordBooleanPrefValue(prefs::kStabilityExitedCleanly, true);
486}
487
488void MetricsService::RecordStartOfSessionEnd() {
489 RecordBooleanPrefValue(prefs::kStabilitySessionEndCompleted, false);
490}
491
492void MetricsService::RecordCompletedSessionEnd() {
493 RecordBooleanPrefValue(prefs::kStabilitySessionEndCompleted, true);
494}
495
[email protected]e73c01972008-08-13 00:18:24496void MetricsService:: RecordBreakpadRegistration(bool success) {
497 if (!success)
498 IncrementPrefValue(prefs::kStabilityBreakpadRegistrationFail);
499 else
500 IncrementPrefValue(prefs::kStabilityBreakpadRegistrationSuccess);
501}
502
503void MetricsService::RecordBreakpadHasDebugger(bool has_debugger) {
504 if (!has_debugger)
505 IncrementPrefValue(prefs::kStabilityDebuggerNotPresent);
506 else
507 IncrementPrefValue(prefs::kStabilityDebuggerPresent);
508}
509
initial.commit09911bf2008-07-26 23:55:29510//------------------------------------------------------------------------------
511// private methods
512//------------------------------------------------------------------------------
513
514
515//------------------------------------------------------------------------------
516// Initialization methods
517
518void MetricsService::InitializeMetricsState() {
519 PrefService* pref = g_browser_process->local_state();
520 DCHECK(pref);
521
522 client_id_ = WideToUTF8(pref->GetString(prefs::kMetricsClientID));
523 if (client_id_.empty()) {
524 client_id_ = GenerateClientID();
525 pref->SetString(prefs::kMetricsClientID, UTF8ToWide(client_id_));
526
527 // Might as well make a note of how long this ID has existed
528 pref->SetString(prefs::kMetricsClientIDTimestamp,
529 Int64ToWString(Time::Now().ToTimeT()));
530 }
531
532 // Update session ID
533 session_id_ = pref->GetInteger(prefs::kMetricsSessionID);
534 ++session_id_;
535 pref->SetInteger(prefs::kMetricsSessionID, session_id_);
536
537 bool done = EnableReporting(GoogleUpdateSettings::GetCollectStatsConsent());
538 DCHECK(done);
539
540 // Stability bookkeeping
[email protected]e73c01972008-08-13 00:18:24541 IncrementPrefValue(prefs::kStabilityLaunchCount);
initial.commit09911bf2008-07-26 23:55:29542
[email protected]e73c01972008-08-13 00:18:24543 if (!pref->GetBoolean(prefs::kStabilityExitedCleanly)) {
544 IncrementPrefValue(prefs::kStabilityCrashCount);
initial.commit09911bf2008-07-26 23:55:29545 }
[email protected]e73c01972008-08-13 00:18:24546
547 // This will be set to 'true' if we exit cleanly.
initial.commit09911bf2008-07-26 23:55:29548 pref->SetBoolean(prefs::kStabilityExitedCleanly, false);
549
[email protected]e73c01972008-08-13 00:18:24550 if (!pref->GetBoolean(prefs::kStabilitySessionEndCompleted)) {
551 IncrementPrefValue(prefs::kStabilityIncompleteSessionEndCount);
initial.commit09911bf2008-07-26 23:55:29552 }
553 // This is marked false when we get a WM_ENDSESSION.
554 pref->SetBoolean(prefs::kStabilitySessionEndCompleted, true);
555
556 int64 last_start_time =
557 StringToInt64(pref->GetString(prefs::kStabilityLaunchTimeSec));
558 int64 last_end_time =
559 StringToInt64(pref->GetString(prefs::kStabilityLastTimestampSec));
560 int64 uptime =
561 StringToInt64(pref->GetString(prefs::kStabilityUptimeSec));
562
563 if (last_start_time && last_end_time) {
564 // TODO(JAR): Exclude sleep time. ... which must be gathered in UI loop.
565 uptime += last_end_time - last_start_time;
566 pref->SetString(prefs::kStabilityUptimeSec, Int64ToWString(uptime));
567 }
568 pref->SetString(prefs::kStabilityLaunchTimeSec,
569 Int64ToWString(Time::Now().ToTimeT()));
570
571 // Save profile metrics.
572 PrefService* prefs = g_browser_process->local_state();
573 if (prefs) {
574 // Remove the current dictionary and store it for use when sending data to
575 // server. By removing the value we prune potentially dead profiles
576 // (and keys). All valid values are added back once services startup.
577 const DictionaryValue* profile_dictionary =
578 prefs->GetDictionary(prefs::kProfileMetrics);
579 if (profile_dictionary) {
580 // Do a deep copy of profile_dictionary since ClearPref will delete it.
581 profile_dictionary_.reset(static_cast<DictionaryValue*>(
582 profile_dictionary->DeepCopy()));
583 prefs->ClearPref(prefs::kProfileMetrics);
584 }
585 }
586
587 // Kick off the process of saving the state (so the uptime numbers keep
588 // getting updated) every n minutes.
589 ScheduleNextStateSave();
590}
591
592void MetricsService::OnGetPluginListTaskComplete() {
593 DCHECK(state_ == PLUGIN_LIST_REQUESTED);
594 if (state_ == PLUGIN_LIST_REQUESTED)
595 state_ = PLUGIN_LIST_ARRIVED;
596}
597
598std::string MetricsService::GenerateClientID() {
599 const int kGUIDSize = 39;
600
601 GUID guid;
602 HRESULT guid_result = CoCreateGuid(&guid);
603 DCHECK(SUCCEEDED(guid_result));
604
605 std::wstring guid_string;
606 int result = StringFromGUID2(guid,
607 WriteInto(&guid_string, kGUIDSize), kGUIDSize);
608 DCHECK(result == kGUIDSize);
609
610 return WideToUTF8(guid_string.substr(1, guid_string.length() - 2));
611}
612
613
614//------------------------------------------------------------------------------
615// State save methods
616
617void MetricsService::ScheduleNextStateSave() {
618 state_saver_factory_.RevokeAll();
619
620 MessageLoop::current()->PostDelayedTask(FROM_HERE,
621 state_saver_factory_.NewRunnableMethod(&MetricsService::SaveLocalState),
622 kSaveStateInterval * 1000);
623}
624
625void MetricsService::SaveLocalState() {
626 PrefService* pref = g_browser_process->local_state();
627 if (!pref) {
628 NOTREACHED();
629 return;
630 }
631
632 RecordCurrentState(pref);
633 pref->ScheduleSavePersistentPrefs(g_browser_process->file_thread());
634
635 ScheduleNextStateSave();
636}
637
638
639//------------------------------------------------------------------------------
640// Recording control methods
641
642void MetricsService::StartRecording() {
643 if (current_log_)
644 return;
645
646 current_log_ = new MetricsLog(client_id_, session_id_);
647 if (state_ == INITIALIZED) {
648 // We only need to schedule that run once.
649 state_ = PLUGIN_LIST_REQUESTED;
650
651 // Make sure the plugin list is loaded before the inital log is sent, so
652 // that the main thread isn't blocked generating the list.
653 g_browser_process->file_thread()->message_loop()->PostDelayedTask(FROM_HERE,
654 new GetPluginListTask(MessageLoop::current()),
[email protected]252873ef2008-08-04 21:59:45655 kInitialInterlogDuration * 1000 / 2);
initial.commit09911bf2008-07-26 23:55:29656 }
657}
658
659void MetricsService::StopRecording(MetricsLog** log) {
660 if (!current_log_)
661 return;
662
663 // Put incremental histogram data at the end of every log transmission.
664 // Don't bother if we're going to discard current_log_.
665 if (log)
666 RecordCurrentHistograms();
667
668 current_log_->CloseLog();
669 if (log) {
670 *log = current_log_;
671 } else {
672 delete current_log_;
673 }
674 current_log_ = NULL;
675}
676
677void MetricsService::ListenerRegistration(bool start_listening) {
678 AddOrRemoveObserver(this, NOTIFY_BROWSER_OPENED, start_listening);
679 AddOrRemoveObserver(this, NOTIFY_BROWSER_CLOSED, start_listening);
680 AddOrRemoveObserver(this, NOTIFY_USER_ACTION, start_listening);
[email protected]534e54b2008-08-13 15:40:09681 AddOrRemoveObserver(this, NOTIFY_TAB_PARENTED, start_listening);
initial.commit09911bf2008-07-26 23:55:29682 AddOrRemoveObserver(this, NOTIFY_TAB_CLOSING, start_listening);
683 AddOrRemoveObserver(this, NOTIFY_LOAD_START, start_listening);
684 AddOrRemoveObserver(this, NOTIFY_LOAD_STOP, start_listening);
685 AddOrRemoveObserver(this, NOTIFY_RENDERER_PROCESS_IN_SBOX, start_listening);
686 AddOrRemoveObserver(this, NOTIFY_RENDERER_PROCESS_TERMINATED,
687 start_listening);
688 AddOrRemoveObserver(this, NOTIFY_RENDERER_PROCESS_HANG, start_listening);
689 AddOrRemoveObserver(this, NOTIFY_PLUGIN_PROCESS_HOST_CONNECTED,
690 start_listening);
691 AddOrRemoveObserver(this, NOTIFY_PLUGIN_INSTANCE_CREATED, start_listening);
692 AddOrRemoveObserver(this, NOTIFY_PLUGIN_PROCESS_CRASHED, start_listening);
693 AddOrRemoveObserver(this, TEMPLATE_URL_MODEL_LOADED, start_listening);
694 AddOrRemoveObserver(this, NOTIFY_OMNIBOX_OPENED_URL, start_listening);
695 AddOrRemoveObserver(this, NOTIFY_BOOKMARK_MODEL_LOADED, start_listening);
696}
697
698// static
699void MetricsService::AddOrRemoveObserver(NotificationObserver* observer,
700 NotificationType type,
701 bool is_add) {
702 NotificationService* service = NotificationService::current();
703
704 if (is_add) {
705 service->AddObserver(observer, type, NotificationService::AllSources());
706 } else {
707 service->RemoveObserver(observer, type, NotificationService::AllSources());
708 }
709}
710
711void MetricsService::PushPendingLogsToUnsentLists() {
712 if (state_ < INITIAL_LOG_READY)
713 return; // We didn't and still don't have time to get DLL list etc.
714
715 if (pending_log()) {
716 PreparePendingLogText();
717 if (state_ == INITIAL_LOG_READY) {
718 // We may race here, and send second copy of initial log later.
719 unsent_initial_logs_.push_back(pending_log_text_);
720 state_ = SENDING_CURRENT_LOGS;
721 } else {
722 unsent_ongoing_logs_.push_back(pending_log_text_);
723 }
724 DiscardPendingLog();
725 }
726 DCHECK(!pending_log());
727 StopRecording(&pending_log_);
728 PreparePendingLogText();
729 unsent_ongoing_logs_.push_back(pending_log_text_);
730 DiscardPendingLog();
731 StoreUnsentLogs();
732}
733
734//------------------------------------------------------------------------------
735// Transmission of logs methods
736
737void MetricsService::StartLogTransmissionTimer() {
738 if (!current_log_)
739 return; // Recorder is shutdown.
740 if (timer_pending_ || !reporting_)
741 return;
742 // If there is no work to do, don't set a timer yet.
743 if (!current_log_->num_events() && !pending_log() && !unsent_logs())
744 return;
745 timer_pending_ = true;
746 MessageLoop::current()->PostDelayedTask(FROM_HERE,
747 log_sender_factory_.
748 NewRunnableMethod(&MetricsService::CollectMemoryDetails),
749 static_cast<int>(interlog_duration_.InMilliseconds()));
750}
751
752void MetricsService::TryToStartTransmission() {
753 DCHECK(IsSingleThreaded());
754
755 DCHECK(timer_pending_); // ONLY call via timer.
756
757 DCHECK(!current_fetch_.get());
758 if (current_fetch_.get())
759 return; // Redundant defensive coding.
760
761 timer_pending_ = false;
762
763 if (!current_log_)
764 return; // Logging was disabled.
765 if (!reporting_ )
766 return; // Don't do work if we're not going to send anything now.
767
768 if (!pending_log())
769 switch (state_) {
770 case INITIALIZED: // We must be further along by now.
771 DCHECK(false);
772 return;
773
774 case PLUGIN_LIST_REQUESTED:
775 StartLogTransmissionTimer();
776 return;
777
778 case PLUGIN_LIST_ARRIVED:
779 // We need to wait for the initial log to be ready before sending
780 // anything, because the server will tell us whether it wants to hear
781 // from us.
782 PrepareInitialLog();
783 DCHECK(state_ == PLUGIN_LIST_ARRIVED);
784 RecallUnsentLogs();
785 state_ = INITIAL_LOG_READY;
786 break;
787
788 case SEND_OLD_INITIAL_LOGS:
789 if (!unsent_initial_logs_.empty()) {
790 pending_log_text_ = unsent_initial_logs_.back();
791 break;
792 }
793 state_ = SENDING_OLD_LOGS;
794 // Fall through.
795
796 case SENDING_OLD_LOGS:
797 if (!unsent_ongoing_logs_.empty()) {
798 pending_log_text_ = unsent_ongoing_logs_.back();
799 break;
800 }
801 state_ = SENDING_CURRENT_LOGS;
802 // Fall through.
803
804 case SENDING_CURRENT_LOGS:
805 if (!current_log_->num_events())
806 return; // Nothing to send.
807 StopRecording(&pending_log_);
808 StartRecording();
809 break;
810
811 default:
812 DCHECK(false);
813 return;
814 }
815 DCHECK(pending_log());
816
817 PreparePendingLogForTransmission();
818 if (!current_fetch_.get())
819 return; // Compression failed, and log discarded :-/.
820
821 DCHECK(!timer_pending_);
822 timer_pending_ = true; // The URL fetch is a pseudo timer.
823 current_fetch_->Start();
824}
825
826void MetricsService::CollectMemoryDetails() {
827 Task* task = log_sender_factory_.
828 NewRunnableMethod(&MetricsService::TryToStartTransmission);
829 MetricsMemoryDetails* details = new MetricsMemoryDetails(task);
830 details->StartFetch();
831
832 // Collect WebCore cache information to put into a histogram.
833 for (RenderProcessHost::iterator it = RenderProcessHost::begin();
834 it != RenderProcessHost::end(); ++it) {
835 it->second->Send(new ViewMsg_GetCacheResourceStats());
836 }
837}
838
839void MetricsService::PrepareInitialLog() {
840 DCHECK(state_ == PLUGIN_LIST_ARRIVED);
841 std::vector<WebPluginInfo> plugins;
842 PluginService::GetInstance()->GetPlugins(false, &plugins);
843
844 MetricsLog* log = new MetricsLog(client_id_, session_id_);
845 log->RecordEnvironment(plugins, profile_dictionary_.get());
846
847 // Histograms only get written to current_log_, so setup for the write.
848 MetricsLog* save_log = current_log_;
849 current_log_ = log;
850 RecordCurrentHistograms(); // Into current_log_... which is really log.
851 current_log_ = save_log;
852
853 log->CloseLog();
854 DCHECK(!pending_log());
855 pending_log_ = log;
856}
857
858void MetricsService::RecallUnsentLogs() {
859 DCHECK(unsent_initial_logs_.empty());
860 DCHECK(unsent_ongoing_logs_.empty());
861
862 PrefService* local_state = g_browser_process->local_state();
863 DCHECK(local_state);
864
865 ListValue* unsent_initial_logs = local_state->GetMutableList(
866 prefs::kMetricsInitialLogs);
867 for (ListValue::iterator it = unsent_initial_logs->begin();
868 it != unsent_initial_logs->end(); ++it) {
869 std::wstring wide_log;
870 (*it)->GetAsString(&wide_log);
871 unsent_initial_logs_.push_back(WideToUTF8(wide_log));
872 }
873
874 ListValue* unsent_ongoing_logs = local_state->GetMutableList(
875 prefs::kMetricsOngoingLogs);
876 for (ListValue::iterator it = unsent_ongoing_logs->begin();
877 it != unsent_ongoing_logs->end(); ++it) {
878 std::wstring wide_log;
879 (*it)->GetAsString(&wide_log);
880 unsent_ongoing_logs_.push_back(WideToUTF8(wide_log));
881 }
882}
883
884void MetricsService::StoreUnsentLogs() {
885 if (state_ < INITIAL_LOG_READY)
886 return; // We never Recalled the prior unsent logs.
887
888 PrefService* local_state = g_browser_process->local_state();
889 DCHECK(local_state);
890
891 ListValue* unsent_initial_logs = local_state->GetMutableList(
892 prefs::kMetricsInitialLogs);
893 unsent_initial_logs->Clear();
894 size_t start = 0;
895 if (unsent_initial_logs_.size() > kMaxInitialLogsPersisted)
896 start = unsent_initial_logs_.size() - kMaxInitialLogsPersisted;
897 for (size_t i = start; i < unsent_initial_logs_.size(); ++i)
898 unsent_initial_logs->Append(
899 Value::CreateStringValue(UTF8ToWide(unsent_initial_logs_[i])));
900
901 ListValue* unsent_ongoing_logs = local_state->GetMutableList(
902 prefs::kMetricsOngoingLogs);
903 unsent_ongoing_logs->Clear();
904 start = 0;
905 if (unsent_ongoing_logs_.size() > kMaxOngoingLogsPersisted)
906 start = unsent_ongoing_logs_.size() - kMaxOngoingLogsPersisted;
907 for (size_t i = start; i < unsent_ongoing_logs_.size(); ++i)
908 unsent_ongoing_logs->Append(
909 Value::CreateStringValue(UTF8ToWide(unsent_ongoing_logs_[i])));
910}
911
912void MetricsService::PreparePendingLogText() {
913 DCHECK(pending_log());
914 if (!pending_log_text_.empty())
915 return;
916 int original_size = pending_log_->GetEncodedLogSize();
917 pending_log_->GetEncodedLog(WriteInto(&pending_log_text_, original_size),
918 original_size);
919}
920
921void MetricsService::PreparePendingLogForTransmission() {
922 DCHECK(pending_log());
923 DCHECK(!current_fetch_.get());
924 PreparePendingLogText();
925 DCHECK(!pending_log_text_.empty());
926
927 // Allow security conscious users to see all metrics logs that we send.
928 LOG(INFO) << "METRICS LOG: " << pending_log_text_;
929
930 std::string compressed_log;
931 bool result = Bzip2Compress(pending_log_text_, &compressed_log);
932
933 if (!result) {
934 NOTREACHED() << "Failed to compress log for transmission.";
935 DiscardPendingLog();
936 StartLogTransmissionTimer(); // Maybe we'll do better on next log :-/.
937 return;
938 }
939 current_fetch_.reset(new URLFetcher(GURL(kMetricsURL), URLFetcher::POST,
940 this));
941 current_fetch_->set_request_context(Profile::GetDefaultRequestContext());
942 current_fetch_->set_upload_data(kMetricsType, compressed_log);
943 // This flag works around the cert mismatch on toolbarqueries.google.com.
944 current_fetch_->set_load_flags(net::LOAD_IGNORE_CERT_COMMON_NAME_INVALID);
945}
946
947void MetricsService::DiscardPendingLog() {
948 if (pending_log_) { // Shutdown might have deleted it!
949 delete pending_log_;
950 pending_log_ = NULL;
951 }
952 pending_log_text_.clear();
953}
954
955// This implementation is based on the Firefox MetricsService implementation.
956bool MetricsService::Bzip2Compress(const std::string& input,
957 std::string* output) {
958 bz_stream stream = {0};
959 // As long as our input is smaller than the bzip2 block size, we should get
960 // the best compression. For example, if your input was 250k, using a block
961 // size of 300k or 500k should result in the same compression ratio. Since
962 // our data should be under 100k, using the minimum block size of 100k should
963 // allocate less temporary memory, but result in the same compression ratio.
964 int result = BZ2_bzCompressInit(&stream,
965 1, // 100k (min) block size
966 0, // quiet
967 0); // default "work factor"
968 if (result != BZ_OK) { // out of memory?
969 return false;
970 }
971
972 output->clear();
973
974 stream.next_in = const_cast<char*>(input.data());
975 stream.avail_in = static_cast<int>(input.size());
976 // NOTE: we don't need a BZ_RUN phase since our input buffer contains
977 // the entire input
978 do {
979 output->resize(output->size() + 1024);
980 stream.next_out = &((*output)[stream.total_out_lo32]);
981 stream.avail_out = static_cast<int>(output->size()) - stream.total_out_lo32;
982 result = BZ2_bzCompress(&stream, BZ_FINISH);
983 } while (result == BZ_FINISH_OK);
984 if (result != BZ_STREAM_END) // unknown failure?
985 return false;
986 result = BZ2_bzCompressEnd(&stream);
987 DCHECK(result == BZ_OK);
988
989 output->resize(stream.total_out_lo32);
990
991 return true;
992}
993
994static const char* StatusToString(const URLRequestStatus& status) {
995 switch (status.status()) {
996 case URLRequestStatus::SUCCESS:
997 return "SUCCESS";
998
999 case URLRequestStatus::IO_PENDING:
1000 return "IO_PENDING";
1001
1002 case URLRequestStatus::HANDLED_EXTERNALLY:
1003 return "HANDLED_EXTERNALLY";
1004
1005 case URLRequestStatus::CANCELED:
1006 return "CANCELED";
1007
1008 case URLRequestStatus::FAILED:
1009 return "FAILED";
1010
1011 default:
1012 NOTREACHED();
1013 return "Unknown";
1014 }
1015}
1016
1017void MetricsService::OnURLFetchComplete(const URLFetcher* source,
1018 const GURL& url,
1019 const URLRequestStatus& status,
1020 int response_code,
1021 const ResponseCookies& cookies,
1022 const std::string& data) {
1023 DCHECK(timer_pending_);
1024 timer_pending_ = false;
1025 DCHECK(current_fetch_.get());
1026 current_fetch_.reset(NULL); // We're not allowed to re-use it.
1027
1028 // Confirm send so that we can move on.
1029 DLOG(INFO) << "METRICS RESPONSE CODE: " << response_code
1030 << " status=" << StatusToString(status);
[email protected]252873ef2008-08-04 21:59:451031
1032 if (response_code != 200) {
1033 HandleBadResponseCode();
1034 } else { // Success.
initial.commit09911bf2008-07-26 23:55:291035 switch (state_) {
1036 case INITIAL_LOG_READY:
1037 state_ = SEND_OLD_INITIAL_LOGS;
1038 break;
1039
1040 case SEND_OLD_INITIAL_LOGS:
1041 DCHECK(!unsent_initial_logs_.empty());
1042 unsent_initial_logs_.pop_back();
1043 StoreUnsentLogs();
1044 break;
1045
1046 case SENDING_OLD_LOGS:
1047 DCHECK(!unsent_ongoing_logs_.empty());
1048 unsent_ongoing_logs_.pop_back();
1049 StoreUnsentLogs();
1050 break;
1051
1052 case SENDING_CURRENT_LOGS:
1053 break;
1054
1055 default:
1056 DCHECK(false);
1057 break;
1058 }
initial.commit09911bf2008-07-26 23:55:291059 DLOG(INFO) << "METRICS RESPONSE DATA: " << data;
1060 DiscardPendingLog();
[email protected]29be92552008-08-07 22:49:271061 // Since we sent a log, make sure our in-memory state is recorded to disk.
1062 PrefService* local_state = g_browser_process->local_state();
1063 DCHECK(local_state);
1064 if (local_state)
1065 local_state->ScheduleSavePersistentPrefs(
1066 g_browser_process->file_thread());
[email protected]252873ef2008-08-04 21:59:451067
1068 GetSettingsFromResponseData(data);
[email protected]252873ef2008-08-04 21:59:451069 // Override server specified interlog delay if there are unsent logs to
[email protected]29be92552008-08-07 22:49:271070 // transmit.
initial.commit09911bf2008-07-26 23:55:291071 if (unsent_logs()) {
1072 DCHECK(state_ < SENDING_CURRENT_LOGS);
1073 interlog_duration_ = TimeDelta::FromSeconds(kUnsentLogDelay);
initial.commit09911bf2008-07-26 23:55:291074 }
1075 }
[email protected]252873ef2008-08-04 21:59:451076
initial.commit09911bf2008-07-26 23:55:291077 StartLogTransmissionTimer();
1078}
1079
[email protected]252873ef2008-08-04 21:59:451080void MetricsService::HandleBadResponseCode() {
1081 DLOG(INFO) << "METRICS: transmission attempt returned a failure code. "
1082 "Verify network connectivity";
1083#ifndef NDEBUG
1084 DLOG(INFO) << "Verify your metrics logs are formatted correctly."
1085 " Verify server is active at " << kMetricsURL;
1086#endif
1087 if (!pending_log()) {
1088 DLOG(INFO) << "METRICS: Recorder shutdown during log transmission.";
1089 } else {
1090 // Send progressively less frequently.
1091 DCHECK(kBackoff > 1.0);
1092 interlog_duration_ = TimeDelta::FromMicroseconds(
1093 static_cast<int64>(kBackoff * interlog_duration_.InMicroseconds()));
1094
1095 if (kMaxBackoff * TimeDelta::FromSeconds(kMinSecondsPerLog) <
1096 interlog_duration_)
1097 interlog_duration_ = kMaxBackoff *
1098 TimeDelta::FromSeconds(kMinSecondsPerLog);
1099
1100 DLOG(INFO) << "METRICS: transmission retry being scheduled in " <<
1101 interlog_duration_.InSeconds() << " seconds for " <<
1102 pending_log_text_;
initial.commit09911bf2008-07-26 23:55:291103 }
initial.commit09911bf2008-07-26 23:55:291104}
1105
[email protected]252873ef2008-08-04 21:59:451106void MetricsService::GetSettingsFromResponseData(const std::string& data) {
1107 // We assume that the file is structured as a block opened by <response>
1108 // and that inside response, there is a block opened by tag <config>
1109 // other tags are ignored for now except the content of <config>.
1110 DLOG(INFO) << data;
1111 int data_size = static_cast<int>(data.size());
1112 if (data_size < 0) {
[email protected]29be92552008-08-07 22:49:271113 DLOG(INFO) << "METRICS: server response data bad size " <<
[email protected]252873ef2008-08-04 21:59:451114 " aborting extraction of settings";
1115 return;
1116 }
1117 xmlDocPtr doc = xmlReadMemory(data.c_str(), data_size,
1118 "", NULL, 0);
1119 DCHECK(doc);
1120 // if the document is malformed, we just use the settings that were there
1121 if (!doc)
1122 return;
1123
1124 xmlNodePtr top_node = xmlDocGetRootElement(doc), config_node = NULL;
1125 // Here, we find the config node by name.
1126 for (xmlNodePtr p = top_node->children; p; p = p->next) {
1127 if (xmlStrEqual(p->name, BAD_CAST "config")) {
1128 config_node = p;
1129 break;
1130 }
1131 }
1132 // If the server data is formatted wrong and there is no
1133 // config node where we expect, we just drop out.
1134 if (config_node != NULL)
1135 GetSettingsFromConfigNode(config_node);
1136 xmlFreeDoc(doc);
1137}
1138
1139void MetricsService::GetSettingsFromConfigNode(xmlNodePtr config_node) {
1140 for (xmlNodePtr current_node = config_node->children;
1141 current_node;
1142 current_node = current_node->next) {
[email protected]252873ef2008-08-04 21:59:451143 // If the node is collectors list, we iterate through the children
1144 // to get the types of collectors.
1145 if (xmlStrEqual(current_node->name, BAD_CAST "collectors")) {
1146 collectors_.clear();
1147 // Iterate through children and get the property "type".
1148 for (xmlNodePtr sub_node = current_node->children;
1149 sub_node;
1150 sub_node = sub_node->next) {
1151 if (xmlStrEqual(sub_node->name, BAD_CAST "collector")) {
1152 xmlChar* type_value = xmlGetProp(sub_node, BAD_CAST "type");
1153 collectors_.insert(reinterpret_cast<char*>(type_value));
1154 }
1155 }
1156 continue;
1157 }
1158 // Search for other tags, limit and upload. Again if the server data
1159 // does not contain those tags, the settings remain unchanged.
1160 if (xmlStrEqual(current_node->name, BAD_CAST "limit")) {
1161 xmlChar* event_limit_value = xmlGetProp(current_node, BAD_CAST "events");
1162 event_limit_ = atoi(reinterpret_cast<char*>(event_limit_value));
1163 continue;
1164 }
1165 if (xmlStrEqual(current_node->name, BAD_CAST "upload")) {
1166 xmlChar* upload_interval_val = xmlGetProp(current_node,
1167 BAD_CAST "interval");
[email protected]29be92552008-08-07 22:49:271168 int upload_interval_sec =
[email protected]252873ef2008-08-04 21:59:451169 atoi(reinterpret_cast<char*>(upload_interval_val));
1170 interlog_duration_ = TimeDelta::FromSeconds(upload_interval_sec);
1171 continue;
1172 }
1173 }
1174}
initial.commit09911bf2008-07-26 23:55:291175
1176void MetricsService::LogWindowChange(NotificationType type,
1177 const NotificationSource& source,
1178 const NotificationDetails& details) {
[email protected]534e54b2008-08-13 15:40:091179 int controller_id = -1;
1180 uintptr_t window_or_tab = source.map_key();
initial.commit09911bf2008-07-26 23:55:291181 MetricsLog::WindowEventType window_type;
1182
1183 // Note: since we stop all logging when a single OTR session is active, it is
1184 // possible that we start getting notifications about a window that we don't
1185 // know about.
[email protected]534e54b2008-08-13 15:40:091186 if (window_map_.find(window_or_tab) == window_map_.end()) {
1187 controller_id = next_window_id_++;
1188 window_map_[window_or_tab] = controller_id;
initial.commit09911bf2008-07-26 23:55:291189 } else {
[email protected]534e54b2008-08-13 15:40:091190 controller_id = window_map_[window_or_tab];
initial.commit09911bf2008-07-26 23:55:291191 }
[email protected]534e54b2008-08-13 15:40:091192 DCHECK(controller_id != -1);
initial.commit09911bf2008-07-26 23:55:291193
1194 switch (type) {
[email protected]534e54b2008-08-13 15:40:091195 case NOTIFY_TAB_PARENTED:
initial.commit09911bf2008-07-26 23:55:291196 case NOTIFY_BROWSER_OPENED:
1197 window_type = MetricsLog::WINDOW_CREATE;
1198 break;
1199
1200 case NOTIFY_TAB_CLOSING:
1201 case NOTIFY_BROWSER_CLOSED:
[email protected]534e54b2008-08-13 15:40:091202 window_map_.erase(window_map_.find(window_or_tab));
initial.commit09911bf2008-07-26 23:55:291203 window_type = MetricsLog::WINDOW_DESTROY;
1204 break;
1205
1206 default:
1207 NOTREACHED();
1208 break;
1209 }
1210
[email protected]534e54b2008-08-13 15:40:091211 // TODO(brettw) we should have some kind of ID for the parent.
1212 current_log_->RecordWindowEvent(window_type, controller_id, 0);
initial.commit09911bf2008-07-26 23:55:291213}
1214
1215void MetricsService::LogLoadComplete(NotificationType type,
1216 const NotificationSource& source,
1217 const NotificationDetails& details) {
1218 if (details == NotificationService::NoDetails())
1219 return;
1220
1221 const Details<LoadNotificationDetails> load_details(details);
[email protected]534e54b2008-08-13 15:40:091222 int controller_id = window_map_[details.map_key()];
1223 current_log_->RecordLoadEvent(controller_id,
initial.commit09911bf2008-07-26 23:55:291224 load_details->url(),
1225 load_details->origin(),
1226 load_details->session_index(),
1227 load_details->load_time());
1228}
1229
[email protected]e73c01972008-08-13 00:18:241230void MetricsService::IncrementPrefValue(const wchar_t* path) {
1231 PrefService* pref = g_browser_process->local_state();
1232 DCHECK(pref);
1233 int value = pref->GetInteger(path);
1234 pref->SetInteger(path, value + 1);
1235}
1236
initial.commit09911bf2008-07-26 23:55:291237void MetricsService::LogLoadStarted() {
[email protected]e73c01972008-08-13 00:18:241238 IncrementPrefValue(prefs::kStabilityPageLoadCount);
initial.commit09911bf2008-07-26 23:55:291239 // We need to save the prefs, as page load count is a critical stat, and
1240 // it might be lost due to a crash :-(.
1241}
1242
1243void MetricsService::LogRendererInSandbox(bool on_sandbox_desktop) {
1244 PrefService* prefs = g_browser_process->local_state();
1245 DCHECK(prefs);
[email protected]e73c01972008-08-13 00:18:241246 if (on_sandbox_desktop)
1247 IncrementPrefValue(prefs::kSecurityRendererOnSboxDesktop);
1248 else
1249 IncrementPrefValue(prefs::kSecurityRendererOnDefaultDesktop);
initial.commit09911bf2008-07-26 23:55:291250}
1251
1252void MetricsService::LogRendererCrash() {
[email protected]e73c01972008-08-13 00:18:241253 IncrementPrefValue(prefs::kStabilityRendererCrashCount);
initial.commit09911bf2008-07-26 23:55:291254}
1255
1256void MetricsService::LogRendererHang() {
[email protected]e73c01972008-08-13 00:18:241257 IncrementPrefValue(prefs::kStabilityRendererHangCount);
initial.commit09911bf2008-07-26 23:55:291258}
1259
1260void MetricsService::LogPluginChange(NotificationType type,
1261 const NotificationSource& source,
1262 const NotificationDetails& details) {
1263 std::wstring plugin = Details<PluginProcessInfo>(details)->dll_path();
1264
1265 if (plugin_stats_buffer_.find(plugin) == plugin_stats_buffer_.end()) {
1266 plugin_stats_buffer_[plugin] = PluginStats();
1267 }
1268
1269 PluginStats& stats = plugin_stats_buffer_[plugin];
1270 switch (type) {
1271 case NOTIFY_PLUGIN_PROCESS_HOST_CONNECTED:
1272 stats.process_launches++;
1273 break;
1274
1275 case NOTIFY_PLUGIN_INSTANCE_CREATED:
1276 stats.instances++;
1277 break;
1278
1279 case NOTIFY_PLUGIN_PROCESS_CRASHED:
1280 stats.process_crashes++;
1281 break;
1282
1283 default:
1284 NOTREACHED() << "Unexpected notification type " << type;
1285 return;
1286 }
1287}
1288
1289// Recursively counts the number of bookmarks and folders in node.
1290static void CountBookmarks(BookmarkBarNode* node,
1291 int* bookmarks,
1292 int* folders) {
1293 if (node->GetType() == history::StarredEntry::URL)
1294 (*bookmarks)++;
1295 else
1296 (*folders)++;
1297 for (int i = 0; i < node->GetChildCount(); ++i)
1298 CountBookmarks(node->GetChild(i), bookmarks, folders);
1299}
1300
1301void MetricsService::LogBookmarks(BookmarkBarNode* node,
1302 const wchar_t* num_bookmarks_key,
1303 const wchar_t* num_folders_key) {
1304 DCHECK(node);
1305 int num_bookmarks = 0;
1306 int num_folders = 0;
1307 CountBookmarks(node, &num_bookmarks, &num_folders);
1308 num_folders--; // Don't include the root folder in the count.
1309
1310 PrefService* pref = g_browser_process->local_state();
1311 DCHECK(pref);
1312 pref->SetInteger(num_bookmarks_key, num_bookmarks);
1313 pref->SetInteger(num_folders_key, num_folders);
1314}
1315
1316void MetricsService::LogBookmarks(BookmarkBarModel* model) {
1317 DCHECK(model);
1318 LogBookmarks(model->GetBookmarkBarNode(),
1319 prefs::kNumBookmarksOnBookmarkBar,
1320 prefs::kNumFoldersOnBookmarkBar);
1321 LogBookmarks(model->other_node(),
1322 prefs::kNumBookmarksInOtherBookmarkFolder,
1323 prefs::kNumFoldersInOtherBookmarkFolder);
1324 ScheduleNextStateSave();
1325}
1326
1327void MetricsService::LogKeywords(const TemplateURLModel* url_model) {
1328 DCHECK(url_model);
1329
1330 PrefService* pref = g_browser_process->local_state();
1331 DCHECK(pref);
1332 pref->SetInteger(prefs::kNumKeywords,
1333 static_cast<int>(url_model->GetTemplateURLs().size()));
1334 ScheduleNextStateSave();
1335}
1336
1337void MetricsService::RecordPluginChanges(PrefService* pref) {
1338 ListValue* plugins = pref->GetMutableList(prefs::kStabilityPluginStats);
1339 DCHECK(plugins);
1340
1341 for (ListValue::iterator value_iter = plugins->begin();
1342 value_iter != plugins->end(); ++value_iter) {
1343 if (!(*value_iter)->IsType(Value::TYPE_DICTIONARY)) {
1344 NOTREACHED();
1345 continue;
1346 }
1347
1348 DictionaryValue* plugin_dict = static_cast<DictionaryValue*>(*value_iter);
1349 std::wstring plugin_path;
1350 plugin_dict->GetString(prefs::kStabilityPluginPath, &plugin_path);
1351 if (plugin_path.empty()) {
1352 NOTREACHED();
1353 continue;
1354 }
1355
1356 if (plugin_stats_buffer_.find(plugin_path) == plugin_stats_buffer_.end())
1357 continue;
1358
1359 PluginStats stats = plugin_stats_buffer_[plugin_path];
1360 if (stats.process_launches) {
1361 int launches = 0;
1362 plugin_dict->GetInteger(prefs::kStabilityPluginLaunches, &launches);
1363 launches += stats.process_launches;
1364 plugin_dict->SetInteger(prefs::kStabilityPluginLaunches, launches);
1365 }
1366 if (stats.process_crashes) {
1367 int crashes = 0;
1368 plugin_dict->GetInteger(prefs::kStabilityPluginCrashes, &crashes);
1369 crashes += stats.process_crashes;
1370 plugin_dict->SetInteger(prefs::kStabilityPluginCrashes, crashes);
1371 }
1372 if (stats.instances) {
1373 int instances = 0;
1374 plugin_dict->GetInteger(prefs::kStabilityPluginInstances, &instances);
1375 instances += stats.instances;
1376 plugin_dict->SetInteger(prefs::kStabilityPluginInstances, instances);
1377 }
1378
1379 plugin_stats_buffer_.erase(plugin_path);
1380 }
1381
1382 // Now go through and add dictionaries for plugins that didn't already have
1383 // reports in Local State.
1384 for (std::map<std::wstring, PluginStats>::iterator cache_iter =
1385 plugin_stats_buffer_.begin();
1386 cache_iter != plugin_stats_buffer_.end(); ++cache_iter) {
1387 std::wstring plugin_path = cache_iter->first;
1388 PluginStats stats = cache_iter->second;
1389 DictionaryValue* plugin_dict = new DictionaryValue;
1390
1391 plugin_dict->SetString(prefs::kStabilityPluginPath, plugin_path);
1392 plugin_dict->SetInteger(prefs::kStabilityPluginLaunches,
1393 stats.process_launches);
1394 plugin_dict->SetInteger(prefs::kStabilityPluginCrashes,
1395 stats.process_crashes);
1396 plugin_dict->SetInteger(prefs::kStabilityPluginInstances,
1397 stats.instances);
1398 plugins->Append(plugin_dict);
1399 }
1400 plugin_stats_buffer_.clear();
1401}
1402
1403bool MetricsService::CanLogNotification(NotificationType type,
1404 const NotificationSource& source,
1405 const NotificationDetails& details) {
1406 // We simply don't log anything to UMA if there is a single off the record
1407 // session visible. The problem is that we always notify using the orginal
1408 // profile in order to simplify notification processing.
1409 return !BrowserList::IsOffTheRecordSessionActive();
1410}
1411
1412void MetricsService::RecordBooleanPrefValue(const wchar_t* path, bool value) {
1413 DCHECK(IsSingleThreaded());
1414
1415 PrefService* pref = g_browser_process->local_state();
1416 DCHECK(pref);
1417
1418 pref->SetBoolean(path, value);
1419 RecordCurrentState(pref);
1420}
1421
1422void MetricsService::RecordCurrentState(PrefService* pref) {
1423 pref->SetString(prefs::kStabilityLastTimestampSec,
1424 Int64ToWString(Time::Now().ToTimeT()));
1425
1426 RecordPluginChanges(pref);
1427}
1428
1429void MetricsService::RecordCurrentHistograms() {
1430 DCHECK(current_log_);
1431
1432 StatisticsRecorder::Histograms histograms;
1433 StatisticsRecorder::GetHistograms(&histograms);
1434 for (StatisticsRecorder::Histograms::iterator it = histograms.begin();
1435 histograms.end() != it;
1436 it++) {
1437 if ((*it)->flags() & kUmaTargetedHistogramFlag)
1438 RecordHistogram(**it);
1439 }
1440}
1441
1442void MetricsService::RecordHistogram(const Histogram& histogram) {
1443 // Get up-to-date snapshot of sample stats.
1444 Histogram::SampleSet snapshot;
1445 histogram.SnapshotSample(&snapshot);
1446
1447 const std::string& histogram_name = histogram.histogram_name();
1448
1449 // Find the already sent stats, or create an empty set.
1450 LoggedSampleMap::iterator it = logged_samples_.find(histogram_name);
1451 Histogram::SampleSet* already_logged;
1452 if (logged_samples_.end() == it) {
1453 // Add new entry
1454 already_logged = &logged_samples_[histogram.histogram_name()];
1455 already_logged->Resize(histogram); // Complete initialization.
1456 } else {
1457 already_logged = &(it->second);
1458 // Deduct any stats we've already logged from our snapshot.
1459 snapshot.Subtract(*already_logged);
1460 }
1461
1462 // snapshot now contains only a delta to what we've already_logged.
1463
1464 if (snapshot.TotalCount() > 0) {
1465 current_log_->RecordHistogramDelta(histogram, snapshot);
1466 // Add new data into our running total.
1467 already_logged->Add(snapshot);
1468 }
1469}
1470
1471void MetricsService::AddProfileMetric(Profile* profile,
1472 const std::wstring& key,
1473 int value) {
1474 // Restriction of types is needed for writing values. See
1475 // MetricsLog::WriteProfileMetrics.
1476 DCHECK(profile && !key.empty());
1477 PrefService* prefs = g_browser_process->local_state();
1478 DCHECK(prefs);
1479
1480 // Key is stored in prefs, which interpret '.'s as paths. As such, key
1481 // shouldn't have any '.'s in it.
1482 DCHECK(key.find(L'.') == std::wstring::npos);
1483 // The id is most likely an email address. We shouldn't send it to the server.
1484 const std::wstring id_hash =
1485 UTF8ToWide(MetricsLog::CreateBase64Hash(WideToUTF8(profile->GetID())));
1486 DCHECK(id_hash.find('.') == std::string::npos);
1487
1488 DictionaryValue* prof_prefs = prefs->GetMutableDictionary(
1489 prefs::kProfileMetrics);
1490 DCHECK(prof_prefs);
1491 const std::wstring pref_key = std::wstring(prefs::kProfilePrefix) + id_hash +
1492 L"." + key;
1493 prof_prefs->SetInteger(pref_key.c_str(), value);
1494}
1495
1496static bool IsSingleThreaded() {
1497 static int thread_id = 0;
1498 if (!thread_id)
1499 thread_id = GetCurrentThreadId();
1500 return GetCurrentThreadId() == thread_id;
1501}