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.
+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)
+           << "]";
+
+  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_)) {
+    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_);
   }
 
   // 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() {
+void MetricsLogBase::GetEncodedLogProto(std::string* encoded_log) {
   DCHECK(locked_);
-  return std::string(reinterpret_cast<char*>(xml_wrapper_->buffer()->content));
+  *encoded_log = uma_proto_.SerializeAsString();

[jar (doing other things), 2012/02/27 20:35:34]

Use std::swap to avoid a string copy.  There is a *chance* that the compiler
does this for you, but I'd expect not.

Alternatively, you could pass in the std::string* to SerializeAsString() to do
the placement.

[Ilya Sherman, 2012/02/28 00:23:10]

Done.

 }
 
 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);
+  user_action->set_time(base::TimeTicks::Now().ToInternalValue());

[jar (doing other things), 2012/02/27 20:35:34]

ToInternalValue returns microseconds... better would be seconds (more like what
we had with ToTimeT().)

[Ilya Sherman, 2012/02/28 00:23:10]

Done.

 
   // 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));
+    }
+  }
 }