Upload UMA data using protocol buffers.

chrome/common/metrics/metrics_log_base.cc

 // Copyright (c) 2012 The Chromium Authors. All rights reserved.
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
 #include "chrome/common/metrics/metrics_log_base.h"
 
 #include "base/base64.h"
 #include "base/basictypes.h"
 #include "base/md5.h"
 #include "base/perftimer.h"
 #include "base/string_number_conversions.h"
+#include "base/sys_byteorder.h"
 #include "base/sys_info.h"
 #include "base/third_party/nspr/prtime.h"
 #include "base/utf_string_conversions.h"
 #include "chrome/common/logging_chrome.h"
+#include "chrome/common/metrics/proto/histogram_event.pb.h"
+#include "chrome/common/metrics/proto/user_action_event.pb.h"
 #include "libxml/xmlwriter.h"
 
 #define OPEN_ELEMENT_FOR_SCOPE(name) ScopedElement scoped_element(this, name)
 
 using base::Histogram;
 using base::Time;
 using base::TimeDelta;
-
-// http://blogs.msdn.com/oldnewthing/archive/2004/10/25/247180.aspx
-#if defined(OS_WIN)
-extern "C" IMAGE_DOS_HEADER __ImageBase;
-#endif
+using metrics::HistogramEventProto;
+using metrics::UserActionEventProto;
 
 namespace {
 
 // libxml take xmlChar*, which is unsigned char*
 inline const unsigned char* UnsignedChar(const char* input) {
   return reinterpret_cast<const unsigned char*>(input);
 }
 
+// Any id less than 16 bytes is considered to be a testing id.

[jar (doing other things), 2012/02/23 01:59:18]

Why not just use some fixed ID?  Probability of collision should be
infinitesimal.   As noted below, it wasn't clear why this was needed.

[Ilya Sherman, 2012/02/24 02:10:06]

No idea -- I was just trying to match the existing code (this change used to be
performed server-side...).  If nobody's aware of any need for this, I'm happy to
get rid of it.

+bool IsTestingID(const std::string& id) {
+  return id.size() < 16;
+}
+
+// Converts the 8-byte prefix of an MD5 hash into a uint64 value.
+inline uint64 HashToUInt64(const std::string& hash) {
+  uint64 value;
+  DCHECK_GE(hash.size(), sizeof(value));
+  memcpy(&value, hash.data(), sizeof(value));
+  return base::htonll(value);
+}
+
+// Creates an MD5 hash of the given value, and returns hash as a byte buffer
+// encoded as an std::string.
+std::string CreateHash(const std::string& value) {
+  base::MD5Context context;
+  base::MD5Init(&context);
+  base::MD5Update(&context, value);
+
+  base::MD5Digest digest;
+  base::MD5Final(&digest, &context);
+
+  std::string hash(reinterpret_cast<char*>(digest.a), arraysize(digest.a));
+
+  // The following log is VERY helpful when folks add some named histogram into
+  // the code, but forgot to update the descriptive list of histograms.  When
+  // that happens, all we get to see (server side) is a hash of the histogram
+  // name.  We can then use this logging to find out what histogram name was
+  // being hashed to a given MD5 value by just running the version of Chromium
+  // in question with --enable-logging.
+  DVLOG(1) << "Metrics: Hash numeric [" << value << "]=[" << HashToUInt64(hash)

[jar (doing other things), 2012/02/23 01:59:18]

It is good this is being preserved! ;-) Thanks!

+           << "]";
+
+  return hash;
+}
+
 }  // namespace
 
 class MetricsLogBase::XmlWrapper {
  public:
   XmlWrapper()
       : doc_(NULL),
         buffer_(NULL),
         writer_(NULL) {
     buffer_ = xmlBufferCreate();
     DCHECK(buffer_);
@@ skipping 39 matching lines @@
 };
 
 MetricsLogBase::MetricsLogBase(const std::string& client_id, int session_id,
                                const std::string& version_string)
     : start_time_(Time::Now()),
       client_id_(client_id),
       session_id_(base::IntToString(session_id)),
       locked_(false),
       xml_wrapper_(new XmlWrapper),
       num_events_(0) {
+  int64_t build_time = GetBuildTime();
 
+  // Write the XML version.
   StartElement("log");
   WriteAttribute("clientid", client_id_);
-  WriteInt64Attribute("buildtime", GetBuildTime());
+  WriteInt64Attribute("buildtime", build_time);
   WriteAttribute("appversion", version_string);
+
+  // Write the protobuf version.
+  if (IsTestingID(client_id_)) {

[jar (doing other things), 2012/02/23 01:59:18]

This seems a little strange.  It is nicer to not have special code paths (in
main code) that are for test only.  When you're running the test, you should
know what the client_id is... and hence be ready to compare with the expected
hash.

+    uma_proto_.set_client_id(0);
+  } else {
+    uma_proto_.set_client_id(HashToUInt64(CreateHash(client_id)));
+  }
+  uma_proto_.set_session_id(session_id);
+  uma_proto_.mutable_system_profile()->set_build_timestamp(build_time);
+  uma_proto_.mutable_system_profile()->set_app_version(version_string);
 }
 
 MetricsLogBase::~MetricsLogBase() {
   if (!locked_) {
     locked_ = true;
     int result = xmlTextWriterEndDocument(xml_wrapper_->writer());
     DCHECK_GE(result, 0);
   }
   delete xml_wrapper_;
   xml_wrapper_ = NULL;
 }
 
 void MetricsLogBase::CloseLog() {
   DCHECK(!locked_);
   locked_ = true;
 
   int result = xmlTextWriterEndDocument(xml_wrapper_->writer());
   DCHECK_GE(result, 0);
 
   result = xmlTextWriterFlush(xml_wrapper_->writer());
   DCHECK_GE(result, 0);
 
 #if defined(OS_CHROMEOS)
+  // TODO(isherman): Once the XML pipeline is deprecated, there will be no need
+  // to track the hardware class in a separate member variable and only write it
+  // out when the log is closed.
   xmlNodePtr root = xmlDocGetRootElement(xml_wrapper_->doc());
   if (!hardware_class_.empty()) {
     // The hardware class is determined after the first ongoing log is
     // constructed, so this adds the root element's "hardwareclass"
     // attribute when the log is closed instead.
     xmlNewProp(root, UnsignedChar("hardwareclass"),
                UnsignedChar(hardware_class_.c_str()));
+
+    // Write to the protobuf too.
+    uma_proto_.mutable_system_profile()->set_hardware_class(hardware_class_);
   }
 
+  // TODO(isherman): Why is this done only on ChromeOS?

[jar (doing other things), 2012/02/23 01:59:18]

I have no idea why :-/.

I'd have to read about how the XML module works (it is a pretty funky interface
IMO). Perhaps it is more memory efficient.... or perhaps they are trying to
reduce memory, and maybe they won't save unsent logs etc. on CrOS.

It does look quite strange, and  I can see data in the histograms, so I know
this path is getting exercise.

[Ilya Sherman, 2012/02/24 02:10:06]

Ok.  Well, the good news is that we're (hopefully) getting rid of all the XML
code soon, at which point this will be moot...

   // Flattens the XML tree into a character buffer.
   PerfTimer dump_timer;
   result = xmlNodeDump(xml_wrapper_->buffer(), xml_wrapper_->doc(),
                        root, /* level */ 0, /* format */ 1);
   DCHECK_GE(result, 0);
   UMA_HISTOGRAM_TIMES("UMA.XMLNodeDumpTime", dump_timer.Elapsed());
 
   PerfTimer free_timer;
   xml_wrapper_->FreeDocWriter();
   UMA_HISTOGRAM_TIMES("UMA.XMLWriterDestructionTime", free_timer.Elapsed());
 #endif  // OS_CHROMEOS
 }
 
-int MetricsLogBase::GetEncodedLogSize() {
+int MetricsLogBase::GetEncodedLogSizeXml() {
   DCHECK(locked_);
   CHECK(xml_wrapper_);
   CHECK(xml_wrapper_->buffer());
   return xml_wrapper_->buffer()->use;
 }
 
-bool MetricsLogBase::GetEncodedLog(char* buffer, int buffer_size) {
+bool MetricsLogBase::GetEncodedLogXml(char* buffer, int buffer_size) {
   DCHECK(locked_);
-  if (buffer_size < GetEncodedLogSize())
+  if (buffer_size < GetEncodedLogSizeXml())
     return false;
 
-  memcpy(buffer, xml_wrapper_->buffer()->content, GetEncodedLogSize());
+  memcpy(buffer, xml_wrapper_->buffer()->content, GetEncodedLogSizeXml());
   return true;
 }
 
-std::string MetricsLogBase::GetEncodedLogString() {
+std::string MetricsLogBase::GetEncodedLogProto() {
   DCHECK(locked_);
-  return std::string(reinterpret_cast<char*>(xml_wrapper_->buffer()->content));
+  return uma_proto_.SerializeAsString();

[jar (doing other things), 2012/02/23 01:59:18]

It might be nice to pass in a "std::string*" and have that fleshed out.  I'm a
little wary about the costs of passing around (large) strings in this way....
but maybe it is all super efficient with temps.... but I would expect not :-/.

[Ilya Sherman, 2012/02/24 02:10:06]

I wrote it this way based on the recommendation in [
http://www.chromium.org/developers/coding-style#Method_Signatures ]; but I'll go
ahead and change it to your suggestion, since these are indeed larger strings
than usual.

 }
 
 int MetricsLogBase::GetElapsedSeconds() {
   return static_cast<int>((Time::Now() - start_time_).InSeconds());
 }
 
-std::string MetricsLogBase::CreateHash(const std::string& value) {
-  base::MD5Context ctx;
-  base::MD5Init(&ctx);
-  base::MD5Update(&ctx, value);
+// static
+void MetricsLogBase::CreateHashes(const std::string& string,
+                                  std::string* base64_encoded_hash,
+                                  uint64* numeric_hash) {
+  std::string hash = CreateHash(string);
 
-  base::MD5Digest digest;
-  base::MD5Final(&digest, &ctx);
+  std::string encoded_digest;
+  if (base::Base64Encode(hash, &encoded_digest))
+    DVLOG(1) << "Metrics: Hash [" << encoded_digest << "]=[" << string << "]";
 
-  uint64 reverse_uint64;
-  // UMA only uses first 8 chars of hash. We use the above uint64 instead
-  // of a unsigned char[8] so that we don't run into strict aliasing issues
-  // in the LOG statement below when trying to interpret reverse as a uint64.
-  unsigned char* reverse = reinterpret_cast<unsigned char *>(&reverse_uint64);
-  DCHECK(arraysize(digest.a) >= sizeof(reverse_uint64));
-  for (size_t i = 0; i < sizeof(reverse_uint64); ++i)
-    reverse[i] = digest.a[sizeof(reverse_uint64) - i - 1];
-  // The following log is VERY helpful when folks add some named histogram into
-  // the code, but forgot to update the descriptive list of histograms.  When
-  // that happens, all we get to see (server side) is a hash of the histogram
-  // name.  We can then use this logging to find out what histogram name was
-  // being hashed to a given MD5 value by just running the version of Chromium
-  // in question with --enable-logging.
-  DVLOG(1) << "Metrics: Hash numeric [" << value
-           << "]=[" << reverse_uint64 << "]";
-  return std::string(reinterpret_cast<char*>(digest.a), arraysize(digest.a));
-}
-
-std::string MetricsLogBase::CreateBase64Hash(const std::string& string) {
-  std::string encoded_digest;
-  if (base::Base64Encode(CreateHash(string), &encoded_digest)) {
-    DVLOG(1) << "Metrics: Hash [" << encoded_digest << "]=[" << string << "]";
-    return encoded_digest;
-  }
-  return std::string();
+  *base64_encoded_hash = encoded_digest;
+  *numeric_hash = HashToUInt64(hash);
 }
 
 void MetricsLogBase::RecordUserAction(const char* key) {
   DCHECK(!locked_);
 
-  std::string command_hash = CreateBase64Hash(key);
-  if (command_hash.empty()) {
+  std::string base64_hash;
+  uint64 numeric_hash;
+  CreateHashes(key, &base64_hash, &numeric_hash);
+  if (base64_hash.empty()) {
     NOTREACHED() << "Unable generate encoded hash of command: " << key;
     return;
   }
 
+  // Write the XML version.
   OPEN_ELEMENT_FOR_SCOPE("uielement");
   WriteAttribute("action", "command");
-  WriteAttribute("targetidhash", command_hash);
+  WriteAttribute("targetidhash", base64_hash);
+
+  // Write the protobuf version.
+  UserActionEventProto* user_action = uma_proto_.add_user_action_event();
+  user_action->set_name_hash(numeric_hash);

[jar (doing other things), 2012/02/23 01:59:18]

Have you consistently decided to use a full 64bit hash in our reporting?

[Ilya Sherman, 2012/02/24 02:10:06]

Yes, that was my understanding.

+  user_action->set_time(Time::Now().ToTimeT());

[jar (doing other things), 2012/02/23 01:59:18]

Note that Time::Now() is not monotonic, and will vary when either the clock is
push forward/back for daylight savings, or when the user adjusts the clock.  Is
it really valuable to have (untrustworthy) time-of-day, or would TimeTicks be a
more valuable basis?

[Ilya Sherman, 2012/02/24 02:10:06]

Hmm, that's a really good point.  I think TimeTicks() will be more useful; but I
want to also double-check with Mark Pearson, who is actually thinking about
sessionization of this and omnibox data.  (Updated the omnibox logging to also
use TimeTicks()).

 
   // TODO(jhughes): Properly track windows.
   WriteIntAttribute("window", 0);
   WriteCommonEventAttributes();
 
   ++num_events_;
 }
 
 void MetricsLogBase::RecordLoadEvent(int window_id,
                                      const GURL& url,
@@ skipping 75 matching lines @@
   return base::Uint64ToString(Time::Now().ToTimeT());
 }
 
 // These are the attributes that are common to every event.
 void MetricsLogBase::WriteCommonEventAttributes() {
   WriteAttribute("session", session_id_);
   WriteAttribute("time", GetCurrentTimeString());
 }
 
 void MetricsLogBase::WriteAttribute(const std::string& name,
-                                const std::string& value) {
+                                    const std::string& value) {
   DCHECK(!locked_);
   DCHECK(!name.empty());
 
   int result = xmlTextWriterWriteAttribute(xml_wrapper_->writer(),
                                            UnsignedChar(name.c_str()),
                                            UnsignedChar(value.c_str()));
   DCHECK_GE(result, 0);
 }
 
 void MetricsLogBase::WriteIntAttribute(const std::string& name, int value) {
@@ skipping 56 matching lines @@
     const Histogram& histogram,
     const Histogram::SampleSet& snapshot) {
   DCHECK(!locked_);
   DCHECK_NE(0, snapshot.TotalCount());
   snapshot.CheckSize(histogram);
 
   // We will ignore the MAX_INT/infinite value in the last element of range[].
 
   OPEN_ELEMENT_FOR_SCOPE("histogram");
 
-  WriteAttribute("name", CreateBase64Hash(histogram.histogram_name()));
+  std::string base64_name_hash;
+  uint64 numeric_name_hash;
+  CreateHashes(histogram.histogram_name(),
+               &base64_name_hash,
+               &numeric_name_hash);
+
+  // Write the XML version.
+  WriteAttribute("name", base64_name_hash);
 
   WriteInt64Attribute("sum", snapshot.sum());
   // TODO(jar): Remove sumsquares when protobuffer accepts this as optional.
   WriteInt64Attribute("sumsquares", 0);
 
   for (size_t i = 0; i < histogram.bucket_count(); i++) {
     if (snapshot.counts(i)) {
       OPEN_ELEMENT_FOR_SCOPE("histogrambucket");
       WriteIntAttribute("min", histogram.ranges(i));
       WriteIntAttribute("max", histogram.ranges(i + 1));
       WriteIntAttribute("count", snapshot.counts(i));
     }
   }
+
+  // Write the protobuf version.
+  HistogramEventProto* histogram_proto = uma_proto_.add_histogram_event();
+  histogram_proto->set_name_hash(numeric_name_hash);
+  histogram_proto->set_sum(snapshot.sum());
+
+  for (size_t i = 0; i < histogram.bucket_count(); ++i) {
+    if (snapshot.counts(i)) {
+      HistogramEventProto::Bucket* bucket = histogram_proto->add_bucket();
+      bucket->set_min(histogram.ranges(i));
+      bucket->set_max(histogram.ranges(i + 1));
+      bucket->set_bucket_index(i);
+      bucket->set_count(snapshot.counts(i));
+    }
+  }
 }