metrics_log.cc revision 116680a4aac90f2aa7413d9095a592090648e557 
1// Copyright 2014 The Chromium Authors. All rights reserved.
2// Use of this source code is governed by a BSD-style license that can be
3// found in the LICENSE file.
4
5#include "components/metrics/metrics_log.h"
6
7#include <algorithm>
8#include <string>
9#include <vector>
10
11#include "base/base64.h"
12#include "base/basictypes.h"
13#include "base/cpu.h"
14#include "base/memory/scoped_ptr.h"
15#include "base/metrics/histogram.h"
16#include "base/metrics/histogram_samples.h"
17#include "base/prefs/pref_registry_simple.h"
18#include "base/prefs/pref_service.h"
19#include "base/sha1.h"
20#include "base/strings/string_number_conversions.h"
21#include "base/strings/string_util.h"
22#include "base/strings/utf_string_conversions.h"
23#include "base/sys_info.h"
24#include "base/time/time.h"
25#include "components/metrics/metrics_hashes.h"
26#include "components/metrics/metrics_pref_names.h"
27#include "components/metrics/metrics_provider.h"
28#include "components/metrics/metrics_service_client.h"
29#include "components/metrics/proto/histogram_event.pb.h"
30#include "components/metrics/proto/system_profile.pb.h"
31#include "components/metrics/proto/user_action_event.pb.h"
32#include "components/variations/active_field_trials.h"
33
34#if defined(OS_ANDROID)
35#include "base/android/build_info.h"
36#endif
37
38#if defined(OS_WIN)
39#include "base/win/metro.h"
40
41// http://blogs.msdn.com/oldnewthing/archive/2004/10/25/247180.aspx
42extern "C" IMAGE_DOS_HEADER __ImageBase;
43#endif
44
45using base::SampleCountIterator;
46using metrics::HistogramEventProto;
47using metrics::ProfilerEventProto;
48using metrics::SystemProfileProto;
49using metrics::UserActionEventProto;
50typedef variations::ActiveGroupId ActiveGroupId;
51
52namespace {
53
54// Any id less than 16 bytes is considered to be a testing id.
55bool IsTestingID(const std::string& id) {
56  return id.size() < 16;
57}
58
59// Returns the date at which the current metrics client ID was created as
60// a string containing seconds since the epoch, or "0" if none was found.
61std::string GetMetricsEnabledDate(PrefService* pref) {
62  if (!pref) {
63    NOTREACHED();
64    return "0";
65  }
66
67  return pref->GetString(metrics::prefs::kMetricsReportingEnabledTimestamp);
68}
69
70// Computes a SHA-1 hash of |data| and returns it as a hex string.
71std::string ComputeSHA1(const std::string& data) {
72  const std::string sha1 = base::SHA1HashString(data);
73  return base::HexEncode(sha1.data(), sha1.size());
74}
75
76void WriteFieldTrials(const std::vector<ActiveGroupId>& field_trial_ids,
77                      SystemProfileProto* system_profile) {
78  for (std::vector<ActiveGroupId>::const_iterator it =
79       field_trial_ids.begin(); it != field_trial_ids.end(); ++it) {
80    SystemProfileProto::FieldTrial* field_trial =
81        system_profile->add_field_trial();
82    field_trial->set_name_id(it->name);
83    field_trial->set_group_id(it->group);
84  }
85}
86
87// Round a timestamp measured in seconds since epoch to one with a granularity
88// of an hour. This can be used before uploaded potentially sensitive
89// timestamps.
90int64 RoundSecondsToHour(int64 time_in_seconds) {
91  return 3600 * (time_in_seconds / 3600);
92}
93
94}  // namespace
95
96MetricsLog::MetricsLog(const std::string& client_id,
97                       int session_id,
98                       LogType log_type,
99                       metrics::MetricsServiceClient* client,
100                       PrefService* local_state)
101    : closed_(false),
102      log_type_(log_type),
103      client_(client),
104      creation_time_(base::TimeTicks::Now()),
105      local_state_(local_state) {
106  if (IsTestingID(client_id))
107    uma_proto_.set_client_id(0);
108  else
109    uma_proto_.set_client_id(Hash(client_id));
110
111  uma_proto_.set_session_id(session_id);
112
113  SystemProfileProto* system_profile = uma_proto_.mutable_system_profile();
114  system_profile->set_build_timestamp(GetBuildTime());
115  system_profile->set_app_version(client_->GetVersionString());
116  system_profile->set_channel(client_->GetChannel());
117}
118
119MetricsLog::~MetricsLog() {
120}
121
122// static
123void MetricsLog::RegisterPrefs(PrefRegistrySimple* registry) {
124  registry->RegisterIntegerPref(metrics::prefs::kStabilityLaunchCount, 0);
125  registry->RegisterIntegerPref(metrics::prefs::kStabilityCrashCount, 0);
126  registry->RegisterIntegerPref(
127      metrics::prefs::kStabilityIncompleteSessionEndCount, 0);
128  registry->RegisterIntegerPref(
129      metrics::prefs::kStabilityBreakpadRegistrationFail, 0);
130  registry->RegisterIntegerPref(
131      metrics::prefs::kStabilityBreakpadRegistrationSuccess, 0);
132  registry->RegisterIntegerPref(metrics::prefs::kStabilityDebuggerPresent, 0);
133  registry->RegisterIntegerPref(metrics::prefs::kStabilityDebuggerNotPresent,
134                                0);
135  registry->RegisterStringPref(metrics::prefs::kStabilitySavedSystemProfile,
136                               std::string());
137  registry->RegisterStringPref(metrics::prefs::kStabilitySavedSystemProfileHash,
138                               std::string());
139}
140
141// static
142uint64 MetricsLog::Hash(const std::string& value) {
143  uint64 hash = metrics::HashMetricName(value);
144
145  // The following log is VERY helpful when folks add some named histogram into
146  // the code, but forgot to update the descriptive list of histograms.  When
147  // that happens, all we get to see (server side) is a hash of the histogram
148  // name.  We can then use this logging to find out what histogram name was
149  // being hashed to a given MD5 value by just running the version of Chromium
150  // in question with --enable-logging.
151  DVLOG(1) << "Metrics: Hash numeric [" << value << "]=[" << hash << "]";
152
153  return hash;
154}
155
156// static
157int64 MetricsLog::GetBuildTime() {
158  static int64 integral_build_time = 0;
159  if (!integral_build_time) {
160    base::Time time;
161    static const char kDateTime[] = __DATE__ " " __TIME__ " GMT";
162    bool result = base::Time::FromString(kDateTime, &time);
163    DCHECK(result);
164    integral_build_time = static_cast<int64>(time.ToTimeT());
165  }
166  return integral_build_time;
167}
168
169// static
170int64 MetricsLog::GetCurrentTime() {
171  return (base::TimeTicks::Now() - base::TimeTicks()).InSeconds();
172}
173
174void MetricsLog::RecordUserAction(const std::string& key) {
175  DCHECK(!closed_);
176
177  UserActionEventProto* user_action = uma_proto_.add_user_action_event();
178  user_action->set_name_hash(Hash(key));
179  user_action->set_time(GetCurrentTime());
180}
181
182void MetricsLog::RecordHistogramDelta(const std::string& histogram_name,
183                                      const base::HistogramSamples& snapshot) {
184  DCHECK(!closed_);
185  DCHECK_NE(0, snapshot.TotalCount());
186
187  // We will ignore the MAX_INT/infinite value in the last element of range[].
188
189  HistogramEventProto* histogram_proto = uma_proto_.add_histogram_event();
190  histogram_proto->set_name_hash(Hash(histogram_name));
191  histogram_proto->set_sum(snapshot.sum());
192
193  for (scoped_ptr<SampleCountIterator> it = snapshot.Iterator(); !it->Done();
194       it->Next()) {
195    base::Histogram::Sample min;
196    base::Histogram::Sample max;
197    base::Histogram::Count count;
198    it->Get(&min, &max, &count);
199    HistogramEventProto::Bucket* bucket = histogram_proto->add_bucket();
200    bucket->set_min(min);
201    bucket->set_max(max);
202    bucket->set_count(count);
203  }
204
205  // Omit fields to save space (see rules in histogram_event.proto comments).
206  for (int i = 0; i < histogram_proto->bucket_size(); ++i) {
207    HistogramEventProto::Bucket* bucket = histogram_proto->mutable_bucket(i);
208    if (i + 1 < histogram_proto->bucket_size() &&
209        bucket->max() == histogram_proto->bucket(i + 1).min()) {
210      bucket->clear_max();
211    } else if (bucket->max() == bucket->min() + 1) {
212      bucket->clear_min();
213    }
214  }
215}
216
217void MetricsLog::RecordStabilityMetrics(
218    const std::vector<metrics::MetricsProvider*>& metrics_providers,
219    base::TimeDelta incremental_uptime,
220    base::TimeDelta uptime) {
221  DCHECK(!closed_);
222  DCHECK(HasEnvironment());
223  DCHECK(!HasStabilityMetrics());
224
225  PrefService* pref = local_state_;
226  DCHECK(pref);
227
228  // Get stability attributes out of Local State, zeroing out stored values.
229  // NOTE: This could lead to some data loss if this report isn't successfully
230  //       sent, but that's true for all the metrics.
231
232  WriteRequiredStabilityAttributes(pref);
233
234  // Record recent delta for critical stability metrics.  We can't wait for a
235  // restart to gather these, as that delay biases our observation away from
236  // users that run happily for a looooong time.  We send increments with each
237  // uma log upload, just as we send histogram data.
238  WriteRealtimeStabilityAttributes(pref, incremental_uptime, uptime);
239
240  SystemProfileProto* system_profile = uma_proto()->mutable_system_profile();
241  for (size_t i = 0; i < metrics_providers.size(); ++i)
242    metrics_providers[i]->ProvideStabilityMetrics(system_profile);
243
244  // Omit some stats unless this is the initial stability log.
245  if (log_type() != INITIAL_STABILITY_LOG)
246    return;
247
248  int incomplete_shutdown_count =
249      pref->GetInteger(metrics::prefs::kStabilityIncompleteSessionEndCount);
250  pref->SetInteger(metrics::prefs::kStabilityIncompleteSessionEndCount, 0);
251  int breakpad_registration_success_count =
252      pref->GetInteger(metrics::prefs::kStabilityBreakpadRegistrationSuccess);
253  pref->SetInteger(metrics::prefs::kStabilityBreakpadRegistrationSuccess, 0);
254  int breakpad_registration_failure_count =
255      pref->GetInteger(metrics::prefs::kStabilityBreakpadRegistrationFail);
256  pref->SetInteger(metrics::prefs::kStabilityBreakpadRegistrationFail, 0);
257  int debugger_present_count =
258      pref->GetInteger(metrics::prefs::kStabilityDebuggerPresent);
259  pref->SetInteger(metrics::prefs::kStabilityDebuggerPresent, 0);
260  int debugger_not_present_count =
261      pref->GetInteger(metrics::prefs::kStabilityDebuggerNotPresent);
262  pref->SetInteger(metrics::prefs::kStabilityDebuggerNotPresent, 0);
263
264  // TODO(jar): The following are all optional, so we *could* optimize them for
265  // values of zero (and not include them).
266  SystemProfileProto::Stability* stability =
267      system_profile->mutable_stability();
268  stability->set_incomplete_shutdown_count(incomplete_shutdown_count);
269  stability->set_breakpad_registration_success_count(
270      breakpad_registration_success_count);
271  stability->set_breakpad_registration_failure_count(
272      breakpad_registration_failure_count);
273  stability->set_debugger_present_count(debugger_present_count);
274  stability->set_debugger_not_present_count(debugger_not_present_count);
275}
276
277void MetricsLog::RecordGeneralMetrics(
278    const std::vector<metrics::MetricsProvider*>& metrics_providers) {
279  for (size_t i = 0; i < metrics_providers.size(); ++i)
280    metrics_providers[i]->ProvideGeneralMetrics(uma_proto());
281}
282
283void MetricsLog::GetFieldTrialIds(
284    std::vector<ActiveGroupId>* field_trial_ids) const {
285  variations::GetFieldTrialActiveGroupIds(field_trial_ids);
286}
287
288bool MetricsLog::HasEnvironment() const {
289  return uma_proto()->system_profile().has_uma_enabled_date();
290}
291
292bool MetricsLog::HasStabilityMetrics() const {
293  return uma_proto()->system_profile().stability().has_launch_count();
294}
295
296// The server refuses data that doesn't have certain values.  crashcount and
297// launchcount are currently "required" in the "stability" group.
298// TODO(isherman): Stop writing these attributes specially once the migration to
299// protobufs is complete.
300void MetricsLog::WriteRequiredStabilityAttributes(PrefService* pref) {
301  int launch_count = pref->GetInteger(metrics::prefs::kStabilityLaunchCount);
302  pref->SetInteger(metrics::prefs::kStabilityLaunchCount, 0);
303  int crash_count = pref->GetInteger(metrics::prefs::kStabilityCrashCount);
304  pref->SetInteger(metrics::prefs::kStabilityCrashCount, 0);
305
306  SystemProfileProto::Stability* stability =
307      uma_proto()->mutable_system_profile()->mutable_stability();
308  stability->set_launch_count(launch_count);
309  stability->set_crash_count(crash_count);
310}
311
312void MetricsLog::WriteRealtimeStabilityAttributes(
313    PrefService* pref,
314    base::TimeDelta incremental_uptime,
315    base::TimeDelta uptime) {
316  // Update the stats which are critical for real-time stability monitoring.
317  // Since these are "optional," only list ones that are non-zero, as the counts
318  // are aggregated (summed) server side.
319
320  SystemProfileProto::Stability* stability =
321      uma_proto()->mutable_system_profile()->mutable_stability();
322
323  const uint64 incremental_uptime_sec = incremental_uptime.InSeconds();
324  if (incremental_uptime_sec)
325    stability->set_incremental_uptime_sec(incremental_uptime_sec);
326  const uint64 uptime_sec = uptime.InSeconds();
327  if (uptime_sec)
328    stability->set_uptime_sec(uptime_sec);
329}
330
331void MetricsLog::RecordEnvironment(
332    const std::vector<metrics::MetricsProvider*>& metrics_providers,
333    const std::vector<variations::ActiveGroupId>& synthetic_trials,
334    int64 install_date) {
335  DCHECK(!HasEnvironment());
336
337  SystemProfileProto* system_profile = uma_proto()->mutable_system_profile();
338
339  std::string brand_code;
340  if (client_->GetBrand(&brand_code))
341    system_profile->set_brand_code(brand_code);
342
343  int enabled_date;
344  bool success =
345      base::StringToInt(GetMetricsEnabledDate(local_state_), &enabled_date);
346  DCHECK(success);
347
348  // Reduce granularity of the enabled_date field to nearest hour.
349  system_profile->set_uma_enabled_date(RoundSecondsToHour(enabled_date));
350
351  // Reduce granularity of the install_date field to nearest hour.
352  system_profile->set_install_date(RoundSecondsToHour(install_date));
353
354  system_profile->set_application_locale(client_->GetApplicationLocale());
355
356  SystemProfileProto::Hardware* hardware = system_profile->mutable_hardware();
357
358  // By default, the hardware class is empty (i.e., unknown).
359  hardware->set_hardware_class(std::string());
360
361  hardware->set_cpu_architecture(base::SysInfo::OperatingSystemArchitecture());
362  hardware->set_system_ram_mb(base::SysInfo::AmountOfPhysicalMemoryMB());
363#if defined(OS_WIN)
364  hardware->set_dll_base(reinterpret_cast<uint64>(&__ImageBase));
365#endif
366
367  SystemProfileProto::OS* os = system_profile->mutable_os();
368  std::string os_name = base::SysInfo::OperatingSystemName();
369#if defined(OS_WIN)
370  // TODO(mad): This only checks whether the main process is a Metro process at
371  // upload time; not whether the collected metrics were all gathered from
372  // Metro.  This is ok as an approximation for now, since users will rarely be
373  // switching from Metro to Desktop mode; but we should re-evaluate whether we
374  // can distinguish metrics more cleanly in the future: http://crbug.com/140568
375  if (base::win::IsMetroProcess())
376    os_name += " (Metro)";
377#endif
378  os->set_name(os_name);
379  os->set_version(base::SysInfo::OperatingSystemVersion());
380#if defined(OS_ANDROID)
381  os->set_fingerprint(
382      base::android::BuildInfo::GetInstance()->android_build_fp());
383#endif
384
385  base::CPU cpu_info;
386  SystemProfileProto::Hardware::CPU* cpu = hardware->mutable_cpu();
387  cpu->set_vendor_name(cpu_info.vendor_name());
388  cpu->set_signature(cpu_info.signature());
389
390  std::vector<ActiveGroupId> field_trial_ids;
391  GetFieldTrialIds(&field_trial_ids);
392  WriteFieldTrials(field_trial_ids, system_profile);
393  WriteFieldTrials(synthetic_trials, system_profile);
394
395  for (size_t i = 0; i < metrics_providers.size(); ++i)
396    metrics_providers[i]->ProvideSystemProfileMetrics(system_profile);
397
398  std::string serialied_system_profile;
399  std::string base64_system_profile;
400  if (system_profile->SerializeToString(&serialied_system_profile)) {
401    base::Base64Encode(serialied_system_profile, &base64_system_profile);
402    PrefService* local_state = local_state_;
403    local_state->SetString(metrics::prefs::kStabilitySavedSystemProfile,
404                           base64_system_profile);
405    local_state->SetString(metrics::prefs::kStabilitySavedSystemProfileHash,
406                           ComputeSHA1(serialied_system_profile));
407  }
408}
409
410bool MetricsLog::LoadSavedEnvironmentFromPrefs() {
411  PrefService* local_state = local_state_;
412  const std::string base64_system_profile =
413      local_state->GetString(metrics::prefs::kStabilitySavedSystemProfile);
414  if (base64_system_profile.empty())
415    return false;
416
417  const std::string system_profile_hash =
418      local_state->GetString(metrics::prefs::kStabilitySavedSystemProfileHash);
419  local_state->ClearPref(metrics::prefs::kStabilitySavedSystemProfile);
420  local_state->ClearPref(metrics::prefs::kStabilitySavedSystemProfileHash);
421
422  SystemProfileProto* system_profile = uma_proto()->mutable_system_profile();
423  std::string serialied_system_profile;
424  return base::Base64Decode(base64_system_profile, &serialied_system_profile) &&
425         ComputeSHA1(serialied_system_profile) == system_profile_hash &&
426         system_profile->ParseFromString(serialied_system_profile);
427}
428
429void MetricsLog::CloseLog() {
430  DCHECK(!closed_);
431  closed_ = true;
432}
433
434void MetricsLog::GetEncodedLog(std::string* encoded_log) {
435  DCHECK(closed_);
436  uma_proto_.SerializeToString(encoded_log);
437}
438