Upload UMA data using protocol buffers.

chrome/browser/metrics/metrics_log_serializer.cc

 // Copyright (c) 2011 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/browser/metrics/metrics_log_serializer.h"
 
 #include "base/base64.h"
 #include "base/md5.h"
 #include "base/metrics/histogram.h"
 #include "chrome/browser/browser_process.h"
 #include "chrome/browser/prefs/pref_service.h"
 #include "chrome/browser/prefs/scoped_user_pref_update.h"
 #include "chrome/common/pref_names.h"
 
+namespace {
+
 // The number of "initial" logs we're willing to save, and hope to send during
 // a future Chrome session.  Initial logs contain crash stats, and are pretty
 // small.
-static const size_t kMaxInitialLogsPersisted = 20;
+const size_t kMaxInitialLogsPersisted = 20;
 
 // The number of ongoing logs we're willing to save persistently, and hope to
 // send during a this or future sessions.  Note that each log may be pretty
 // large, as presumably the related "initial" log wasn't sent (probably nothing
 // was, as the user was probably off-line).  As a result, the log probably kept
 // accumulating while the "initial" log was stalled, and couldn't be sent.  As a
 // result, we don't want to save too many of these mega-logs.
 // A "standard shutdown" will create a small log, including just the data that
 // was not yet been transmitted, and that is normal (to have exactly one
 // ongoing_log_ at startup).
-static const size_t kMaxOngoingLogsPersisted = 8;
+const size_t kMaxOngoingLogsPersisted = 8;
 
 // We append (2) more elements to persisted lists: the size of the list and a
 // checksum of the elements.
-static const size_t kChecksumEntryCount = 2;
+const size_t kChecksumEntryCount = 2;
 
-namespace {
-// TODO(ziadh): This is here temporarily for a side experiment. Remove later
-// on.
+// TODO(isherman): Remove this histogram once it's confirmed that there are no
+// encoding failures for protobuf logs.
 enum LogStoreStatus {
   STORE_SUCCESS,    // Successfully presisted log.
   ENCODE_FAIL,      // Failed to encode log.
   COMPRESS_FAIL,    // Failed to compress log.
   END_STORE_STATUS  // Number of bins to use to create the histogram.
 };
 
 MetricsLogSerializer::LogReadStatus MakeRecallStatusHistogram(
-    MetricsLogSerializer::LogReadStatus status) {
-  UMA_HISTOGRAM_ENUMERATION("PrefService.PersistentLogRecall", status,
-                            MetricsLogSerializer::END_RECALL_STATUS);
+    MetricsLogSerializer::LogReadStatus status,
+    bool is_xml) {
+  if (is_xml) {
+    UMA_HISTOGRAM_ENUMERATION("PrefService.PersistentLogRecall",
+                              status, MetricsLogSerializer::END_RECALL_STATUS);
+  } else {
+    UMA_HISTOGRAM_ENUMERATION("PrefService.PersistentLogRecallProtobufs",
+                              status, MetricsLogSerializer::END_RECALL_STATUS);
+  }
   return status;
 }
 
-// TODO(ziadh): Remove this when done with experiment.
 void MakeStoreStatusHistogram(LogStoreStatus status) {
   UMA_HISTOGRAM_ENUMERATION("PrefService.PersistentLogStore2", status,
                             END_STORE_STATUS);
 }
+
 }  // namespace
 
 
 MetricsLogSerializer::MetricsLogSerializer() {}
 
 MetricsLogSerializer::~MetricsLogSerializer() {}
 
-void MetricsLogSerializer::SerializeLogs(const std::vector<std::string>& logs,
-                                         MetricsLogManager::LogType log_type) {
+void MetricsLogSerializer::SerializeLogs(
+    const std::vector<MetricsLogManager::SerializedLog>& logs,
+    MetricsLogManager::LogType log_type) {
   PrefService* local_state = g_browser_process->local_state();
   DCHECK(local_state);
-  const char* pref = NULL;
+  const char* pref_xml = NULL;
+  const char* pref_proto = NULL;
   size_t max_store_count = 0;
   switch (log_type) {
     case MetricsLogManager::INITIAL_LOG:
-      pref = prefs::kMetricsInitialLogs;
+      pref_xml = prefs::kMetricsInitialLogsXml;
+      pref_proto = prefs::kMetricsInitialLogsProto;
       max_store_count = kMaxInitialLogsPersisted;
       break;
     case MetricsLogManager::ONGOING_LOG:
-      pref = prefs::kMetricsOngoingLogs;
+      pref_xml = prefs::kMetricsOngoingLogsXml;
+      pref_proto = prefs::kMetricsOngoingLogsProto;
       max_store_count = kMaxOngoingLogsPersisted;
       break;
     default:
       NOTREACHED();
       return;
   };
-  ListPrefUpdate update(local_state, pref);
-  ListValue* pref_list = update.Get();
-  WriteLogsToPrefList(logs, max_store_count, pref_list);
+
+  // Write the XML version.
+  ListPrefUpdate update_xml(local_state, pref_xml);
+  WriteLogsToPrefList(logs, true, max_store_count, update_xml.Get());
+
+  // Write the protobuf version.
+  ListPrefUpdate update_proto(local_state, pref_proto);
+  WriteLogsToPrefList(logs, false, max_store_count, update_proto.Get());
 }
 
-void MetricsLogSerializer::DeserializeLogs(MetricsLogManager::LogType log_type,
-                                           std::vector<std::string>* logs) {
+void MetricsLogSerializer::DeserializeLogs(
+    MetricsLogManager::LogType log_type,
+    std::vector<MetricsLogManager::SerializedLog>* logs) {
   DCHECK(logs);
   PrefService* local_state = g_browser_process->local_state();
   DCHECK(local_state);
 
-  const char* pref = (log_type == MetricsLogManager::INITIAL_LOG) ?
-      prefs::kMetricsInitialLogs : prefs::kMetricsOngoingLogs;
-  const ListValue* unsent_logs = local_state->GetList(pref);
-  ReadLogsFromPrefList(*unsent_logs, logs);
+  const char* pref_xml;
+  const char* pref_proto;
+  if (log_type == MetricsLogManager::INITIAL_LOG) {
+    pref_xml = prefs::kMetricsInitialLogsXml;
+    pref_proto = prefs::kMetricsInitialLogsProto;
+  } else {
+    pref_xml = prefs::kMetricsOngoingLogsXml;
+    pref_proto = prefs::kMetricsOngoingLogsProto;
+  }
+
+  const ListValue* unsent_logs_xml = local_state->GetList(pref_xml);
+  const ListValue* unsent_logs_proto = local_state->GetList(pref_proto);
+  if (ReadLogsFromPrefList(*unsent_logs_xml, true, logs) == RECALL_SUCCESS) {
+    // In order to try to keep the data sent to both servers roughly in sync,
+    // only read the protobuf data if we read the XML data successfully.
+    ReadLogsFromPrefList(*unsent_logs_proto, false, logs);
+  }
 }
 
 // static
 void MetricsLogSerializer::WriteLogsToPrefList(
-    const std::vector<std::string>& local_list,
-    const size_t kMaxLocalListSize,
-    ListValue* list) {
+    const std::vector<MetricsLogManager::SerializedLog>& local_list,
+    bool is_xml,
+    size_t max_list_size,
+    base::ListValue* list) {
   list->Clear();
   size_t start = 0;
-  if (local_list.size() > kMaxLocalListSize)
-    start = local_list.size() - kMaxLocalListSize;
-  DCHECK(start <= local_list.size());
+  if (local_list.size() > max_list_size)
+    start = local_list.size() - max_list_size;
+  DCHECK_LE(start, local_list.size());
   if (local_list.size() <= start)
     return;
 
   // Store size at the beginning of the list.
   list->Append(Value::CreateIntegerValue(local_list.size() - start));
 
   base::MD5Context ctx;
   base::MD5Init(&ctx);
   std::string encoded_log;
-  for (std::vector<std::string>::const_iterator it = local_list.begin() + start;
+  for (std::vector<MetricsLogManager::SerializedLog>::const_iterator it =
+           local_list.begin() + start;
        it != local_list.end(); ++it) {
+    const std::string& value = is_xml ? it->xml : it->proto;
     // We encode the compressed log as Value::CreateStringValue() expects to
     // take a valid UTF8 string.
-    if (!base::Base64Encode(*it, &encoded_log)) {
+    if (!base::Base64Encode(value, &encoded_log)) {
       MakeStoreStatusHistogram(ENCODE_FAIL);
       list->Clear();
       return;
     }
     base::MD5Update(&ctx, encoded_log);
     list->Append(Value::CreateStringValue(encoded_log));
   }
 
   // Append hash to the end of the list.
   base::MD5Digest digest;
   base::MD5Final(&digest, &ctx);
   list->Append(Value::CreateStringValue(base::MD5DigestToBase16(digest)));
   DCHECK(list->GetSize() >= 3);  // Minimum of 3 elements (size, data, hash).
   MakeStoreStatusHistogram(STORE_SUCCESS);
 }
 
 // static
 MetricsLogSerializer::LogReadStatus MetricsLogSerializer::ReadLogsFromPrefList(
     const ListValue& list,
-    std::vector<std::string>* local_list) {
-  DCHECK(local_list->empty());
+    bool is_xml,
+    std::vector<MetricsLogManager::SerializedLog>* local_list) {
   if (list.GetSize() == 0)
-    return MakeRecallStatusHistogram(LIST_EMPTY);
+    return MakeRecallStatusHistogram(LIST_EMPTY, is_xml);

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

Looking at the data, this LIST_EMPTY case is the vast bulk of all errors. In
fact, it is roughly equally likely to having a success (50% failure on this
case).

Looking at user counts, it appears that roughly every user encounter this error
case.  This suggests (perchance) that the logic does a read of the prefs twice,
and one time it is empty??

Do you have any idea why we had an empty list so often?  The system "should"
have written a partial ongoing log at shutdown, and it should be (I think) very
rare that we had no list at all.
Comments?

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

It looks like the MetricsLogManager code reads in two sets of persisted logs:
unsent initial logs and unsent ongoing logs [1].  I'm guessing it's very rare
that there are any unsent initial logs.  Does that sound about right?
[1]
http://code.google.com/codesearch#OAMlx_jo-ck/src/chrome/common/metrics/metri...

[jar (doing other things), 2012/02/28 01:33:21]

Yup... that explains it perfectly.  Thanks.

On 2012/02/28 00:23:10, Ilya Sherman wrote:

   if (list.GetSize() < 3)
-    return MakeRecallStatusHistogram(LIST_SIZE_TOO_SMALL);
+    return MakeRecallStatusHistogram(LIST_SIZE_TOO_SMALL, is_xml);
 
   // The size is stored at the beginning of the list.
   int size;
   bool valid = (*list.begin())->GetAsInteger(&size);
   if (!valid)
-    return MakeRecallStatusHistogram(LIST_SIZE_MISSING);
-
+    return MakeRecallStatusHistogram(LIST_SIZE_MISSING, is_xml);
   // Account for checksum and size included in the list.
   if (static_cast<unsigned int>(size) !=
       list.GetSize() - kChecksumEntryCount) {
-    return MakeRecallStatusHistogram(LIST_SIZE_CORRUPTION);
+    return MakeRecallStatusHistogram(LIST_SIZE_CORRUPTION, is_xml);
+  }
+
+  // Make room for all of the logs we are going to read in.
+  // Do this ahead of time to avoid making copies of the serialized logs, which
+  // can be fairly large.

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

Although the logs may be large, this only grows the vector, which is typically
small (rarely over 20?  Usually 1 or 2?).

Am I confused, or is this a waste?

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

This is really making sure that we can safely pass in a point to e.g.
(*local_list)[local_index].xml to base::Base64Decode() -- the previous code made
a copy of the string.  Updated the comment to hopefully make this clearer...

+  if (is_xml) {
+    DCHECK(local_list->empty());
+    local_list->resize(size);
+  } else if (local_list->size() != static_cast<size_t>(size)) {
+    return MakeRecallStatusHistogram(XML_PROTO_MISMATCH, false);
   }
 
   base::MD5Context ctx;
   base::MD5Init(&ctx);
   std::string encoded_log;
-  std::string decoded_log;
+  size_t local_index = 0;
   for (ListValue::const_iterator it = list.begin() + 1;
-       it != list.end() - 1; ++it) {  // Last element is the checksum.
-    valid = (*it)->GetAsString(&encoded_log);
+       it != list.end() - 1;  // Last element is the checksum.
+       ++it, ++local_index) {
+    bool valid = (*it)->GetAsString(&encoded_log);
     if (!valid) {
       local_list->clear();
-      return MakeRecallStatusHistogram(LOG_STRING_CORRUPTION);
+      return MakeRecallStatusHistogram(LOG_STRING_CORRUPTION, is_xml);
     }
 
     base::MD5Update(&ctx, encoded_log);
 
+    DCHECK_LT(local_index, local_list->size());
+    std::string& decoded_log = is_xml ?
+        (*local_list)[local_index].xml :
+        (*local_list)[local_index].proto;
     if (!base::Base64Decode(encoded_log, &decoded_log)) {

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

I'm curious: Does the JSON encoding of prefs automatically take care of this
Base64 encode/decode?  Are we doing this redundantly (unnecessarily) and
inducing data expansion by a factor of 1.37?  (Yes... this was in original
code... and perchance should not be addressed in this CL... but might be worth a
TODO and a bug if what I'm saying makes sense).

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

Looks like the base64 encoding/decoding is necessary, per the comment on line
154.

[jar (doing other things), 2012/02/28 01:33:21]

OK. Thanks.

On 2012/02/28 00:23:10, Ilya Sherman wrote:

       local_list->clear();
-      return MakeRecallStatusHistogram(DECODE_FAIL);
+      return MakeRecallStatusHistogram(DECODE_FAIL, is_xml);
     }
-    local_list->push_back(decoded_log);
   }
 
   // Verify checksum.
   base::MD5Digest digest;
   base::MD5Final(&digest, &ctx);
   std::string recovered_md5;
   // We store the hash at the end of the list.
   valid = (*(list.end() - 1))->GetAsString(&recovered_md5);
   if (!valid) {
     local_list->clear();
-    return MakeRecallStatusHistogram(CHECKSUM_STRING_CORRUPTION);
+    return MakeRecallStatusHistogram(CHECKSUM_STRING_CORRUPTION, is_xml);
   }
   if (recovered_md5 != base::MD5DigestToBase16(digest)) {
     local_list->clear();
-    return MakeRecallStatusHistogram(CHECKSUM_CORRUPTION);
+    return MakeRecallStatusHistogram(CHECKSUM_CORRUPTION, is_xml);
   }
-  return MakeRecallStatusHistogram(RECALL_SUCCESS);
+  return MakeRecallStatusHistogram(RECALL_SUCCESS, is_xml);
 }