OLD | NEW |
---|---|
1 // Copyright (c) 2010 The Chromium Authors. All rights reserved. | 1 // Copyright (c) 2010 The Chromium Authors. All rights reserved. |
2 // Use of this source code is governed by a BSD-style license that can be | 2 // Use of this source code is governed by a BSD-style license that can be |
3 // found in the LICENSE file. | 3 // found in the LICENSE file. |
4 | 4 |
5 #include "chrome/browser/metrics/metrics_log.h" | 5 #include "chrome/browser/metrics/metrics_log.h" |
6 | 6 |
7 #include "base/base64.h" | 7 #include "base/base64.h" |
8 #include "base/time.h" | 8 #include "base/time.h" |
9 #include "base/basictypes.h" | 9 #include "base/basictypes.h" |
10 #include "base/file_util.h" | 10 #include "base/file_util.h" |
11 #include "base/file_version_info.h" | 11 #include "base/file_version_info.h" |
12 #include "base/md5.h" | 12 #include "base/md5.h" |
13 #include "base/perftimer.h" | 13 #include "base/perftimer.h" |
14 #include "base/scoped_ptr.h" | 14 #include "base/scoped_ptr.h" |
15 #include "base/string_util.h" | 15 #include "base/string_util.h" |
16 #include "base/sys_info.h" | 16 #include "base/sys_info.h" |
17 #include "base/utf_string_conversions.h" | 17 #include "base/utf_string_conversions.h" |
18 #include "base/third_party/nspr/prtime.h" | 18 #include "base/third_party/nspr/prtime.h" |
19 #include "chrome/app/chrome_version_info.h" | 19 #include "chrome/app/chrome_version_info.h" |
20 #include "chrome/browser/autocomplete/autocomplete.h" | 20 #include "chrome/browser/autocomplete/autocomplete.h" |
21 #include "chrome/browser/browser_process.h" | 21 #include "chrome/browser/browser_process.h" |
22 #include "chrome/browser/pref_service.h" | 22 #include "chrome/browser/pref_service.h" |
23 #include "chrome/common/logging_chrome.h" | 23 #include "chrome/common/logging_chrome.h" |
24 #include "chrome/common/pref_names.h" | 24 #include "chrome/common/pref_names.h" |
25 #include "googleurl/src/gurl.h" | 25 #include "googleurl/src/gurl.h" |
26 | 26 |
27 #define OPEN_ELEMENT_FOR_SCOPE(name) ScopedElement scoped_element(this, name) | 27 #define OPEN_ELEMENT_FOR_SCOPE(name) ScopedElement scoped_element(this, name) |
28 | 28 |
29 using base::Time; | |
30 using base::TimeDelta; | |
31 | |
32 // http://blogs.msdn.com/oldnewthing/archive/2004/10/25/247180.aspx | 29 // http://blogs.msdn.com/oldnewthing/archive/2004/10/25/247180.aspx |
33 #if defined(OS_WIN) | 30 #if defined(OS_WIN) |
34 extern "C" IMAGE_DOS_HEADER __ImageBase; | 31 extern "C" IMAGE_DOS_HEADER __ImageBase; |
35 #endif | 32 #endif |
36 | 33 |
37 // static | 34 MetricsLog::MetricsLog(const std::string& client_id, int session_id) |
38 std::string MetricsLog::version_extension_; | 35 : MetricsLogBase(client_id, session_id, MetricsLog::GetVersionString()) {} |
39 | 36 |
40 // libxml take xmlChar*, which is unsigned char* | 37 MetricsLog::~MetricsLog() {} |
41 inline const unsigned char* UnsignedChar(const char* input) { | |
42 return reinterpret_cast<const unsigned char*>(input); | |
43 } | |
44 | 38 |
45 // static | 39 // static |
46 void MetricsLog::RegisterPrefs(PrefService* local_state) { | 40 void MetricsLog::RegisterPrefs(PrefService* local_state) { |
47 local_state->RegisterListPref(prefs::kStabilityPluginStats); | 41 local_state->RegisterListPref(prefs::kStabilityPluginStats); |
48 } | 42 } |
49 | 43 |
50 MetricsLog::MetricsLog(const std::string& client_id, int session_id) | 44 int64 MetricsLog::GetIncrementalUptime(PrefService* pref) { |
51 : start_time_(Time::Now()), | 45 base::TimeTicks now = base::TimeTicks::Now(); |
52 client_id_(client_id), | 46 static base::TimeTicks last_updated_time(now); |
53 session_id_(IntToString(session_id)), | 47 int64 incremental_time = (now - last_updated_time).InSeconds(); |
54 locked_(false), | 48 last_updated_time = now; |
55 doc_(NULL), | |
56 buffer_(NULL), | |
57 writer_(NULL), | |
58 num_events_(0) { | |
59 | 49 |
60 buffer_ = xmlBufferCreate(); | 50 if (incremental_time > 0) { |
61 DCHECK(buffer_); | 51 int64 metrics_uptime = pref->GetInt64(prefs::kUninstallMetricsUptimeSec); |
52 metrics_uptime += incremental_time; | |
53 pref->SetInt64(prefs::kUninstallMetricsUptimeSec, metrics_uptime); | |
54 } | |
62 | 55 |
63 #if defined(OS_CHROMEOS) | 56 return incremental_time; |
64 writer_ = xmlNewTextWriterDoc(&doc_, /* compression */ 0); | |
65 #else | |
66 writer_ = xmlNewTextWriterMemory(buffer_, /* compression */ 0); | |
67 #endif // OS_CHROMEOS | |
68 DCHECK(writer_); | |
69 | |
70 int result = xmlTextWriterSetIndent(writer_, 2); | |
71 DCHECK_EQ(0, result); | |
72 | |
73 StartElement("log"); | |
74 WriteAttribute("clientid", client_id_); | |
75 WriteInt64Attribute("buildtime", GetBuildTime()); | |
76 WriteAttribute("appversion", GetVersionString()); | |
77 } | 57 } |
78 | 58 |
79 MetricsLog::~MetricsLog() { | 59 std::string MetricsLog::GetInstallDate() const { |
80 FreeDocWriter(); | 60 PrefService* pref = g_browser_process->local_state(); |
81 | 61 if (pref) { |
82 if (buffer_) { | 62 return WideToUTF8(pref->GetString(prefs::kMetricsClientIDTimestamp)); |
83 xmlBufferFree(buffer_); | 63 } else { |
84 buffer_ = NULL; | 64 NOTREACHED(); |
65 return "0"; | |
85 } | 66 } |
86 } | 67 } |
87 | 68 |
88 void MetricsLog::CloseLog() { | |
89 DCHECK(!locked_); | |
90 locked_ = true; | |
91 | |
92 int result = xmlTextWriterEndDocument(writer_); | |
93 DCHECK_GE(result, 0); | |
94 | |
95 result = xmlTextWriterFlush(writer_); | |
96 DCHECK_GE(result, 0); | |
97 | |
98 #if defined(OS_CHROMEOS) | |
99 xmlNodePtr root = xmlDocGetRootElement(doc_); | |
100 if (!hardware_class_.empty()) { | |
101 // The hardware class is determined after the first ongoing log is | |
102 // constructed, so this adds the root element's "hardwareclass" | |
103 // attribute when the log is closed instead. | |
104 xmlNewProp(root, UnsignedChar("hardwareclass"), | |
105 UnsignedChar(hardware_class_.c_str())); | |
joth
2010/06/10 10:52:37
I think your change has reverted this code (added
| |
106 } | |
107 | |
108 // Flattens the XML tree into a character buffer. | |
109 PerfTimer dump_timer; | |
110 result = xmlNodeDump(buffer_, doc_, root, /* level */ 0, /* format */ 1); | |
111 DCHECK_GE(result, 0); | |
112 UMA_HISTOGRAM_TIMES("UMA.XMLNodeDumpTime", dump_timer.Elapsed()); | |
113 | |
114 PerfTimer free_timer; | |
115 FreeDocWriter(); | |
116 UMA_HISTOGRAM_TIMES("UMA.XMLWriterDestructionTime", free_timer.Elapsed()); | |
117 #endif // OS_CHROMEOS | |
118 } | |
119 | |
120 int MetricsLog::GetEncodedLogSize() { | |
121 DCHECK(locked_); | |
122 return buffer_->use; | |
123 } | |
124 | |
125 bool MetricsLog::GetEncodedLog(char* buffer, int buffer_size) { | |
126 DCHECK(locked_); | |
127 if (buffer_size < GetEncodedLogSize()) | |
128 return false; | |
129 | |
130 memcpy(buffer, buffer_->content, GetEncodedLogSize()); | |
131 return true; | |
132 } | |
133 | |
134 int MetricsLog::GetElapsedSeconds() { | |
135 return static_cast<int>((Time::Now() - start_time_).InSeconds()); | |
136 } | |
137 | |
138 std::string MetricsLog::CreateHash(const std::string& value) { | |
139 MD5Context ctx; | |
140 MD5Init(&ctx); | |
141 MD5Update(&ctx, value.data(), value.length()); | |
142 | |
143 MD5Digest digest; | |
144 MD5Final(&digest, &ctx); | |
145 | |
146 uint64 reverse_uint64; | |
147 // UMA only uses first 8 chars of hash. We use the above uint64 instead | |
148 // of a unsigned char[8] so that we don't run into strict aliasing issues | |
149 // in the LOG statement below when trying to interpret reverse as a uint64. | |
150 unsigned char* reverse = reinterpret_cast<unsigned char *>(&reverse_uint64); | |
151 DCHECK(arraysize(digest.a) >= sizeof(reverse_uint64)); | |
152 for (size_t i = 0; i < sizeof(reverse_uint64); ++i) | |
153 reverse[i] = digest.a[sizeof(reverse_uint64) - i - 1]; | |
154 // The following log is VERY helpful when folks add some named histogram into | |
155 // the code, but forgot to update the descriptive list of histograms. When | |
156 // that happens, all we get to see (server side) is a hash of the histogram | |
157 // name. We can then use this logging to find out what histogram name was | |
158 // being hashed to a given MD5 value by just running the version of Chromium | |
159 // in question with --enable-logging. | |
160 LOG(INFO) << "Metrics: Hash numeric [" << value << "]=[" | |
161 << reverse_uint64 << "]"; | |
162 return std::string(reinterpret_cast<char*>(digest.a), arraysize(digest.a)); | |
163 } | |
164 | |
165 std::string MetricsLog::CreateBase64Hash(const std::string& string) { | |
166 std::string encoded_digest; | |
167 if (base::Base64Encode(CreateHash(string), &encoded_digest)) { | |
168 DLOG(INFO) << "Metrics: Hash [" << encoded_digest << "]=[" << string << "]"; | |
169 return encoded_digest; | |
170 } | |
171 return std::string(); | |
172 } | |
173 | |
174 void MetricsLog::RecordUserAction(const char* key) { | |
175 DCHECK(!locked_); | |
176 | |
177 std::string command_hash = CreateBase64Hash(key); | |
178 if (command_hash.empty()) { | |
179 NOTREACHED() << "Unable generate encoded hash of command: " << key; | |
180 return; | |
181 } | |
182 | |
183 OPEN_ELEMENT_FOR_SCOPE("uielement"); | |
184 WriteAttribute("action", "command"); | |
185 WriteAttribute("targetidhash", command_hash); | |
186 | |
187 // TODO(jhughes): Properly track windows. | |
188 WriteIntAttribute("window", 0); | |
189 WriteCommonEventAttributes(); | |
190 | |
191 ++num_events_; | |
192 } | |
193 | |
194 void MetricsLog::RecordLoadEvent(int window_id, | |
195 const GURL& url, | |
196 PageTransition::Type origin, | |
197 int session_index, | |
198 TimeDelta load_time) { | |
199 DCHECK(!locked_); | |
200 | |
201 OPEN_ELEMENT_FOR_SCOPE("document"); | |
202 WriteAttribute("action", "load"); | |
203 WriteIntAttribute("docid", session_index); | |
204 WriteIntAttribute("window", window_id); | |
205 WriteAttribute("loadtime", Int64ToString(load_time.InMilliseconds())); | |
206 | |
207 std::string origin_string; | |
208 | |
209 switch (PageTransition::StripQualifier(origin)) { | |
210 // TODO(jhughes): Some of these mappings aren't right... we need to add | |
211 // some values to the server's enum. | |
212 case PageTransition::LINK: | |
213 case PageTransition::MANUAL_SUBFRAME: | |
214 origin_string = "link"; | |
215 break; | |
216 | |
217 case PageTransition::TYPED: | |
218 origin_string = "typed"; | |
219 break; | |
220 | |
221 case PageTransition::AUTO_BOOKMARK: | |
222 origin_string = "bookmark"; | |
223 break; | |
224 | |
225 case PageTransition::AUTO_SUBFRAME: | |
226 case PageTransition::RELOAD: | |
227 origin_string = "refresh"; | |
228 break; | |
229 | |
230 case PageTransition::GENERATED: | |
231 case PageTransition::KEYWORD: | |
232 origin_string = "global-history"; | |
233 break; | |
234 | |
235 case PageTransition::START_PAGE: | |
236 origin_string = "start-page"; | |
237 break; | |
238 | |
239 case PageTransition::FORM_SUBMIT: | |
240 origin_string = "form-submit"; | |
241 break; | |
242 | |
243 default: | |
244 NOTREACHED() << "Received an unknown page transition type: " << | |
245 PageTransition::StripQualifier(origin); | |
246 } | |
247 if (!origin_string.empty()) | |
248 WriteAttribute("origin", origin_string); | |
249 | |
250 WriteCommonEventAttributes(); | |
251 | |
252 ++num_events_; | |
253 } | |
254 | |
255 void MetricsLog::RecordWindowEvent(WindowEventType type, | |
256 int window_id, | |
257 int parent_id) { | |
258 DCHECK(!locked_); | |
259 | |
260 OPEN_ELEMENT_FOR_SCOPE("window"); | |
261 WriteAttribute("action", WindowEventTypeToString(type)); | |
262 WriteAttribute("windowid", IntToString(window_id)); | |
263 if (parent_id >= 0) | |
264 WriteAttribute("parent", IntToString(parent_id)); | |
265 WriteCommonEventAttributes(); | |
266 | |
267 ++num_events_; | |
268 } | |
269 | |
270 std::string MetricsLog::GetCurrentTimeString() { | |
271 return Uint64ToString(Time::Now().ToTimeT()); | |
272 } | |
273 | |
274 // These are the attributes that are common to every event. | |
275 void MetricsLog::WriteCommonEventAttributes() { | |
276 WriteAttribute("session", session_id_); | |
277 WriteAttribute("time", GetCurrentTimeString()); | |
278 } | |
279 | |
280 void MetricsLog::WriteAttribute(const std::string& name, | |
281 const std::string& value) { | |
282 DCHECK(!locked_); | |
283 DCHECK(!name.empty()); | |
284 | |
285 int result = xmlTextWriterWriteAttribute(writer_, | |
286 UnsignedChar(name.c_str()), | |
287 UnsignedChar(value.c_str())); | |
288 DCHECK_GE(result, 0); | |
289 } | |
290 | |
291 void MetricsLog::WriteIntAttribute(const std::string& name, int value) { | |
292 WriteAttribute(name, IntToString(value)); | |
293 } | |
294 | |
295 void MetricsLog::WriteInt64Attribute(const std::string& name, int64 value) { | |
296 WriteAttribute(name, Int64ToString(value)); | |
297 } | |
298 | |
299 // static | |
300 const char* MetricsLog::WindowEventTypeToString(WindowEventType type) { | |
301 switch (type) { | |
302 case WINDOW_CREATE: return "create"; | |
303 case WINDOW_OPEN: return "open"; | |
304 case WINDOW_CLOSE: return "close"; | |
305 case WINDOW_DESTROY: return "destroy"; | |
306 | |
307 default: | |
308 NOTREACHED(); | |
309 return "unknown"; // Can't return NULL as this is used in a required | |
310 // attribute. | |
311 } | |
312 } | |
313 | |
314 void MetricsLog::FreeDocWriter() { | |
315 if (writer_) { | |
316 xmlFreeTextWriter(writer_); | |
317 writer_ = NULL; | |
318 } | |
319 | |
320 if (doc_) { | |
321 xmlFreeDoc(doc_); | |
322 doc_ = NULL; | |
323 } | |
324 } | |
325 | |
326 void MetricsLog::StartElement(const char* name) { | |
327 DCHECK(!locked_); | |
328 DCHECK(name); | |
329 | |
330 int result = xmlTextWriterStartElement(writer_, UnsignedChar(name)); | |
331 DCHECK_GE(result, 0); | |
332 } | |
333 | |
334 void MetricsLog::EndElement() { | |
335 DCHECK(!locked_); | |
336 | |
337 int result = xmlTextWriterEndElement(writer_); | |
338 DCHECK_GE(result, 0); | |
339 } | |
340 | |
341 // static | 69 // static |
342 std::string MetricsLog::GetVersionString() { | 70 std::string MetricsLog::GetVersionString() { |
343 scoped_ptr<FileVersionInfo> version_info( | 71 scoped_ptr<FileVersionInfo> version_info( |
344 chrome_app::GetChromeVersionInfo()); | 72 chrome_app::GetChromeVersionInfo()); |
345 if (version_info.get()) { | 73 if (version_info.get()) { |
346 std::string version = WideToUTF8(version_info->product_version()); | 74 std::string version = WideToUTF8(version_info->product_version()); |
347 if (!version_extension_.empty()) | 75 if (!version_extension_.empty()) |
348 version += version_extension_; | 76 version += version_extension_; |
349 if (!version_info->is_official_build()) | 77 if (!version_info->is_official_build()) |
350 version.append("-devel"); | 78 version.append("-devel"); |
351 return version; | 79 return version; |
352 } else { | 80 } else { |
353 NOTREACHED() << "Unable to retrieve version string."; | 81 NOTREACHED() << "Unable to retrieve version string."; |
354 } | 82 } |
355 | 83 |
356 return std::string(); | 84 return std::string(); |
357 } | 85 } |
358 | 86 |
359 // static | |
360 int64 MetricsLog::GetBuildTime() { | |
361 static int64 integral_build_time = 0; | |
362 if (!integral_build_time) { | |
363 Time time; | |
364 const char* kDateTime = __DATE__ " " __TIME__ " GMT"; | |
365 bool result = Time::FromString(ASCIIToWide(kDateTime).c_str(), &time); | |
366 DCHECK(result); | |
367 integral_build_time = static_cast<int64>(time.ToTimeT()); | |
368 } | |
369 return integral_build_time; | |
370 } | |
371 | |
372 // static | |
373 int64 MetricsLog::GetIncrementalUptime(PrefService* pref) { | |
374 base::TimeTicks now = base::TimeTicks::Now(); | |
375 static base::TimeTicks last_updated_time(now); | |
376 int64 incremental_time = (now - last_updated_time).InSeconds(); | |
377 last_updated_time = now; | |
378 | |
379 if (incremental_time > 0) { | |
380 int64 metrics_uptime = pref->GetInt64(prefs::kUninstallMetricsUptimeSec); | |
381 metrics_uptime += incremental_time; | |
382 pref->SetInt64(prefs::kUninstallMetricsUptimeSec, metrics_uptime); | |
383 } | |
384 | |
385 return incremental_time; | |
386 } | |
387 | |
388 std::string MetricsLog::GetInstallDate() const { | |
389 PrefService* pref = g_browser_process->local_state(); | |
390 if (pref) { | |
391 return WideToUTF8(pref->GetString(prefs::kMetricsClientIDTimestamp)); | |
392 } else { | |
393 NOTREACHED(); | |
394 return "0"; | |
395 } | |
396 } | |
397 | |
398 void MetricsLog::RecordIncrementalStabilityElements() { | 87 void MetricsLog::RecordIncrementalStabilityElements() { |
399 DCHECK(!locked_); | 88 DCHECK(!locked_); |
400 | 89 |
401 PrefService* pref = g_browser_process->local_state(); | 90 PrefService* pref = g_browser_process->local_state(); |
402 DCHECK(pref); | 91 DCHECK(pref); |
403 | 92 |
404 OPEN_ELEMENT_FOR_SCOPE("profile"); | 93 OPEN_ELEMENT_FOR_SCOPE("profile"); |
405 WriteCommonEventAttributes(); | 94 WriteCommonEventAttributes(); |
406 | 95 |
407 WriteInstallElement(); // Supply appversion. | 96 WriteInstallElement(); // Supply appversion. |
(...skipping 336 matching lines...) Expand 10 before | Expand all | Expand 10 after Loading... | |
744 const std::string result_type(AutocompleteMatch::TypeToString(i->type)); | 433 const std::string result_type(AutocompleteMatch::TypeToString(i->type)); |
745 if (!result_type.empty()) | 434 if (!result_type.empty()) |
746 WriteAttribute("resulttype", result_type); | 435 WriteAttribute("resulttype", result_type); |
747 WriteIntAttribute("relevance", i->relevance); | 436 WriteIntAttribute("relevance", i->relevance); |
748 WriteIntAttribute("isstarred", i->starred ? 1 : 0); | 437 WriteIntAttribute("isstarred", i->starred ? 1 : 0); |
749 } | 438 } |
750 } | 439 } |
751 | 440 |
752 ++num_events_; | 441 ++num_events_; |
753 } | 442 } |
754 | |
755 // TODO(JAR): A The following should really be part of the histogram class. | |
756 // Internal state is being needlessly exposed, and it would be hard to reuse | |
757 // this code. If we moved this into the Histogram class, then we could use | |
758 // the same infrastructure for logging StatsCounters, RatesCounters, etc. | |
759 void MetricsLog::RecordHistogramDelta(const Histogram& histogram, | |
760 const Histogram::SampleSet& snapshot) { | |
761 DCHECK(!locked_); | |
762 DCHECK_NE(0, snapshot.TotalCount()); | |
763 snapshot.CheckSize(histogram); | |
764 | |
765 // We will ignore the MAX_INT/infinite value in the last element of range[]. | |
766 | |
767 OPEN_ELEMENT_FOR_SCOPE("histogram"); | |
768 | |
769 WriteAttribute("name", CreateBase64Hash(histogram.histogram_name())); | |
770 | |
771 WriteInt64Attribute("sum", snapshot.sum()); | |
772 WriteInt64Attribute("sumsquares", snapshot.square_sum()); | |
773 | |
774 for (size_t i = 0; i < histogram.bucket_count(); i++) { | |
775 if (snapshot.counts(i)) { | |
776 OPEN_ELEMENT_FOR_SCOPE("histogrambucket"); | |
777 WriteIntAttribute("min", histogram.ranges(i)); | |
778 WriteIntAttribute("max", histogram.ranges(i + 1)); | |
779 WriteIntAttribute("count", snapshot.counts(i)); | |
780 } | |
781 } | |
782 } | |
OLD | NEW |