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
42 extern "C" IMAGE_DOS_HEADER __ImageBase;
43 #endif
44
45 using base::SampleCountIterator;
46 using metrics::HistogramEventProto;
47 using metrics::ProfilerEventProto;
48 using metrics::SystemProfileProto;
49 using metrics::UserActionEventProto;
50 typedef variations::ActiveGroupId ActiveGroupId;
51
52 namespace {
53
54 // Any id less than 16 bytes is considered to be a testing id.
IsTestingID(const std::string & id)55 bool 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.
GetMetricsEnabledDate(PrefService * pref)61 std::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.
ComputeSHA1(const std::string & data)71 std::string ComputeSHA1(const std::string& data) {
72 const std::string sha1 = base::SHA1HashString(data);
73 return base::HexEncode(sha1.data(), sha1.size());
74 }
75
WriteFieldTrials(const std::vector<ActiveGroupId> & field_trial_ids,SystemProfileProto * system_profile)76 void 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.
RoundSecondsToHour(int64 time_in_seconds)90 int64 RoundSecondsToHour(int64 time_in_seconds) {
91 return 3600 * (time_in_seconds / 3600);
92 }
93
94 } // namespace
95
MetricsLog(const std::string & client_id,int session_id,LogType log_type,metrics::MetricsServiceClient * client,PrefService * local_state)96 MetricsLog::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
~MetricsLog()119 MetricsLog::~MetricsLog() {
120 }
121
122 // static
RegisterPrefs(PrefRegistrySimple * registry)123 void 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
Hash(const std::string & value)142 uint64 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
GetBuildTime()157 int64 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
GetCurrentTime()170 int64 MetricsLog::GetCurrentTime() {
171 return (base::TimeTicks::Now() - base::TimeTicks()).InSeconds();
172 }
173
RecordUserAction(const std::string & key)174 void 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
RecordHistogramDelta(const std::string & histogram_name,const base::HistogramSamples & snapshot)182 void 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
RecordStabilityMetrics(const std::vector<metrics::MetricsProvider * > & metrics_providers,base::TimeDelta incremental_uptime,base::TimeDelta uptime)217 void 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
RecordGeneralMetrics(const std::vector<metrics::MetricsProvider * > & metrics_providers)277 void 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
GetFieldTrialIds(std::vector<ActiveGroupId> * field_trial_ids) const283 void MetricsLog::GetFieldTrialIds(
284 std::vector<ActiveGroupId>* field_trial_ids) const {
285 variations::GetFieldTrialActiveGroupIds(field_trial_ids);
286 }
287
HasEnvironment() const288 bool MetricsLog::HasEnvironment() const {
289 return uma_proto()->system_profile().has_uma_enabled_date();
290 }
291
HasStabilityMetrics() const292 bool 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.
WriteRequiredStabilityAttributes(PrefService * pref)300 void 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
WriteRealtimeStabilityAttributes(PrefService * pref,base::TimeDelta incremental_uptime,base::TimeDelta uptime)312 void 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
RecordEnvironment(const std::vector<metrics::MetricsProvider * > & metrics_providers,const std::vector<variations::ActiveGroupId> & synthetic_trials)331 void MetricsLog::RecordEnvironment(
332 const std::vector<metrics::MetricsProvider*>& metrics_providers,
333 const std::vector<variations::ActiveGroupId>& synthetic_trials) {
334 DCHECK(!HasEnvironment());
335
336 SystemProfileProto* system_profile = uma_proto()->mutable_system_profile();
337
338 std::string brand_code;
339 if (client_->GetBrand(&brand_code))
340 system_profile->set_brand_code(brand_code);
341
342 int enabled_date;
343 bool success =
344 base::StringToInt(GetMetricsEnabledDate(local_state_), &enabled_date);
345 DCHECK(success);
346
347 // Reduce granularity of the enabled_date field to nearest hour.
348 system_profile->set_uma_enabled_date(RoundSecondsToHour(enabled_date));
349
350 int64 install_date = client_->GetInstallDate();
351
352 // Reduce granularity of the install_date field to nearest hour.
353 system_profile->set_install_date(RoundSecondsToHour(install_date));
354
355 system_profile->set_application_locale(client_->GetApplicationLocale());
356
357 SystemProfileProto::Hardware* hardware = system_profile->mutable_hardware();
358
359 // By default, the hardware class is empty (i.e., unknown).
360 hardware->set_hardware_class(std::string());
361
362 hardware->set_cpu_architecture(base::SysInfo::OperatingSystemArchitecture());
363 hardware->set_system_ram_mb(base::SysInfo::AmountOfPhysicalMemoryMB());
364 #if defined(OS_WIN)
365 hardware->set_dll_base(reinterpret_cast<uint64>(&__ImageBase));
366 #endif
367
368 SystemProfileProto::OS* os = system_profile->mutable_os();
369 std::string os_name = base::SysInfo::OperatingSystemName();
370 #if defined(OS_WIN)
371 // TODO(mad): This only checks whether the main process is a Metro process at
372 // upload time; not whether the collected metrics were all gathered from
373 // Metro. This is ok as an approximation for now, since users will rarely be
374 // switching from Metro to Desktop mode; but we should re-evaluate whether we
375 // can distinguish metrics more cleanly in the future: http://crbug.com/140568
376 if (base::win::IsMetroProcess())
377 os_name += " (Metro)";
378 #endif
379 os->set_name(os_name);
380 os->set_version(base::SysInfo::OperatingSystemVersion());
381 #if defined(OS_ANDROID)
382 os->set_fingerprint(
383 base::android::BuildInfo::GetInstance()->android_build_fp());
384 #endif
385
386 base::CPU cpu_info;
387 SystemProfileProto::Hardware::CPU* cpu = hardware->mutable_cpu();
388 cpu->set_vendor_name(cpu_info.vendor_name());
389 cpu->set_signature(cpu_info.signature());
390
391 std::vector<ActiveGroupId> field_trial_ids;
392 GetFieldTrialIds(&field_trial_ids);
393 WriteFieldTrials(field_trial_ids, system_profile);
394 WriteFieldTrials(synthetic_trials, system_profile);
395
396 for (size_t i = 0; i < metrics_providers.size(); ++i)
397 metrics_providers[i]->ProvideSystemProfileMetrics(system_profile);
398
399 std::string serialied_system_profile;
400 std::string base64_system_profile;
401 if (system_profile->SerializeToString(&serialied_system_profile)) {
402 base::Base64Encode(serialied_system_profile, &base64_system_profile);
403 PrefService* local_state = local_state_;
404 local_state->SetString(metrics::prefs::kStabilitySavedSystemProfile,
405 base64_system_profile);
406 local_state->SetString(metrics::prefs::kStabilitySavedSystemProfileHash,
407 ComputeSHA1(serialied_system_profile));
408 }
409 }
410
LoadSavedEnvironmentFromPrefs()411 bool MetricsLog::LoadSavedEnvironmentFromPrefs() {
412 PrefService* local_state = local_state_;
413 const std::string base64_system_profile =
414 local_state->GetString(metrics::prefs::kStabilitySavedSystemProfile);
415 if (base64_system_profile.empty())
416 return false;
417
418 const std::string system_profile_hash =
419 local_state->GetString(metrics::prefs::kStabilitySavedSystemProfileHash);
420 local_state->ClearPref(metrics::prefs::kStabilitySavedSystemProfile);
421 local_state->ClearPref(metrics::prefs::kStabilitySavedSystemProfileHash);
422
423 SystemProfileProto* system_profile = uma_proto()->mutable_system_profile();
424 std::string serialied_system_profile;
425 return base::Base64Decode(base64_system_profile, &serialied_system_profile) &&
426 ComputeSHA1(serialied_system_profile) == system_profile_hash &&
427 system_profile->ParseFromString(serialied_system_profile);
428 }
429
CloseLog()430 void MetricsLog::CloseLog() {
431 DCHECK(!closed_);
432 closed_ = true;
433 }
434
GetEncodedLog(std::string * encoded_log)435 void MetricsLog::GetEncodedLog(std::string* encoded_log) {
436 DCHECK(closed_);
437 uma_proto_.SerializeToString(encoded_log);
438 }
439