Add a minimum byte count to metrics log serialization

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"
@@ skipping 12 matching lines @@
 // 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).
 const size_t kMaxOngoingLogsPersisted = 8;
 
+// The number of bytes each of initial and ongoing logs that must be reached
+// before the count-based limits above will be enforced. This ensures that a
+// reasonable amount of history will be stored even if there is a long series
+// of very small logs.
+const size_t kMinStorageBytesPerLogType = 300000;
+
 // We append (2) more elements to persisted lists: the size of the list and a
 // checksum of the elements.
 const size_t kChecksumEntryCount = 2;
 
 // 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.
@@ skipping 44 matching lines @@
       pref_proto = prefs::kMetricsOngoingLogsProto;
       max_store_count = kMaxOngoingLogsPersisted;
       break;
     default:
       NOTREACHED();
       return;
   };
 
   // Write the XML version.
   ListPrefUpdate update_xml(local_state, pref_xml);
-  WriteLogsToPrefList(logs, true, max_store_count, update_xml.Get());
+  WriteLogsToPrefList(logs, true, max_store_count, kMinStorageBytesPerLogType,
+                      update_xml.Get());
 
   // Write the protobuf version.
   ListPrefUpdate update_proto(local_state, pref_proto);
-  WriteLogsToPrefList(logs, false, max_store_count, update_proto.Get());
+  WriteLogsToPrefList(logs, false, max_store_count, kMinStorageBytesPerLogType,
+                      update_proto.Get());
 }
 
 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_xml;
@@ skipping 12 matching lines @@
     // 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<MetricsLogManager::SerializedLog>& local_list,
     bool is_xml,
-    size_t max_list_size,
+    size_t max_list_length,
+    size_t min_bytes,

[jar (doing other things), 2012/05/10 16:49:40]

This should be max_bytes.

[stuartmorgan, 2012/05/11 09:16:40]

Why? In the new model it behaves as a minimum, not a maximum. See the
method-level comment in the header.

Calling them both maximums makes the model much harder to describe and
understand (I tried that first, and it was terrible).

[jar (doing other things), 2012/05/11 21:36:50]

Both lines 142 and 143 represent limits.  When those limits are exceeded, then
some affirmative action is possibly taken.  Hence they should both have the same
sense: both be max, or both be min.

When I thought about it, going back and forth, I decided that the question that
was being asked was:

Have I exceeded the byte count AND have I exceeded the log count?

As a result, I think that both should be max values, with the flexibility to
ignore a violation if we don't have both counts violated.  In any case, they are
the "same sort" of violation.

On 2012/05/11 09:16:40, stuartmorgan wrote:

[stuartmorgan, 2012/05/15 15:57:05]

Good point; I'll change them both to limit (see below)
Agreed.
I reach the opposite conclusion from your clear statement of the goal. There are
two numbers, and we don't stop until we have reached or exceeded both numbers.
Thus the numbers are minimums from my perspective. The limiting factor at the
upper end is that we stop when we've satisfied both minimums.

Since we see the question the same but the terms differently, I've chosen a
neutral word--"limit"--and described the function's behavior without using
"minimum" or "maximum". Hopefully that will make it understandable no matter
which angle someone comes at it from. Let me know if the method comment works
for you this way.

[jar (doing other things), 2012/05/15 18:27:39]

I'm fine with the word "limit."

I think the difference in the read is that I ask:

"Are we going to truncate anything?"

and you ask:

"Are we going to save all?"

On 2012/05/15 15:57:05, stuartmorgan wrote:

     base::ListValue* list) {
+  // One of the limit arguments must be non-zero.
+  DCHECK(max_list_length > 0 || min_bytes > 0);

[jar (doing other things), 2012/05/10 16:49:40]

nit: I think you're using a 0 to mean "don't check." I'd suggest using something
more like std::max<size_t>, so that the choice is automatically ignored by the
logic of the code. 

[stuartmorgan, 2012/05/11 09:16:40]

It doesn't mean don't check. Passing both arguments as 0 should mean no logs
would be stored, which isn't what any sane caller would want; thus it indicates
programmer error, and is DCHECK'd

[jar (doing other things), 2012/05/11 21:36:50]

If you don't want to persist unsent logs, I'd expect the values to be zero.  Why
is that outlawed here?

[stuartmorgan, 2012/05/15 15:57:05]

I would expect someone who doesn't want to persist unsent logs not to call a
method named "WriteLogsToPrefList". I think it's extremely implausible that we
would ever deliberately call with 0 and 0, and much more plausible that someone
might accidentally do it.

Making accidents easier just to make what I see as a nonsensical call ("Please
write logs, but don't write any") seems like the wrong tradeoff to me, which is
why I opted for making it an error.

+
   list->Clear();
-  size_t start = 0;
-  if (local_list.size() > max_list_size)
-    start = local_list.size() - max_list_size;

[jar (doing other things), 2012/05/10 16:49:40]

IMO, it would be much easier to read (not to mention more efficient... but that
is not significant here) if you only did the iteration sum when this condition
was true (and you had a chance truncate the save set).

[stuartmorgan, 2012/05/11 09:16:40]

Done.

-  DCHECK_LE(start, local_list.size());
-  if (local_list.size() <= start)
+  if (local_list.size() == 0)
+    return;
+
+  // Keep the most recent logs, up to the size limit.
+  size_t start = local_list.size();
+  size_t bytes_used = 0;
+  for (std::vector<MetricsLogManager::SerializedLog>::const_reverse_iterator
+       it = local_list.rbegin(); it != local_list.rend(); ++it) {
+    // TODO(isherman): Always uses XML length so both formats of a given log
+    // will be saved; switch to proto once that's the primary format.
+    size_t log_size = it->xml.length();
+    bytes_used += log_size;
+    --start;

[jar (doing other things), 2012/05/11 21:36:50]

IT surprised me a bit that you decremented start here, instead of after you've
validated with line 162.

Consider the case where we have max_list_length == 0, and min_bytes == 1.  I
think that in such a case you don't want to persist any logs, but you always
presist at least one.

Is that really desired here?

[stuartmorgan, 2012/05/15 15:57:05]

Since the method is currently designed such that it's always going to write a
log, I thought it was clearer. I've moved it though; it's more future-proof that
way.
Since writing no logs would take 0 bytes, writing no logs when called with a min
of 1 byte would violate the documented behavior of the method in this version.
So yes, it was intentional. That still works with the decrementing and byte
counting moved after the break though.

That is a change from the original CL where I was doing a max number of bytes,
and trying not to go over it. But with the hybrid approach, that became harder
to understand conceptually, so I went to a more straightforward lower bound.

I can go to the "soft-max", but ultimately it doesn't really matter in practice,
since the byte limit only kicks in when there are a bunch of small logs. The
case where soft-max vs. min would be a non-trivial size difference is:
  <a bunch of small logs summing to byte_limit - 1>, enormous log
But we could just as easily have:
  enormous log 1, enormous log 2, ..., enormous log (length_limit - 1)
which would be much more space.

So I went for the easier-to-understand model since the practical effects are
pretty much the same.

+    if ((min_bytes == 0 || bytes_used > min_bytes) &&

[jar (doing other things), 2012/05/10 16:49:40]

The test for ==0 seemed superfluous, and made this a tad more confusing. 
Bytes_used is always positive, and so when min_bytes is 0, then bytes_used >
min_bytes.

[stuartmorgan, 2012/05/11 09:16:40]

Done.

+        (local_list.size() - start) >= max_list_length)
+      break;
+  }
+  DCHECK_LT(start, local_list.size());
+  if (start == local_list.size())

[jar (doing other things), 2012/05/10 16:49:40]

The DCHECK makes it clear that we should never have a start value >
local_list.size(), but safe coding suggests it is better to use >= in such
comparison (as in line 141 of the original file).

[stuartmorgan, 2012/05/11 09:16:40]

Actually, the whole if check goes against Chromium style, which says that we
shouldn't handle DCHECK failures gracefully, so the early return shouldn't have
been there in the first place. I've removed it entirely.

[jar (doing other things), 2012/05/11 21:36:50]

I don't know where you heard such, as it is not in our style guide, nor our
philosophy.  Some folks have argued against DCHECKs, suggesting that there
should "only be CHECKs," but that political faction has not been accepted.

The policy is to identify problems with DCHECKs, and if you can't respond
gracefully to the situtation, only then should you instead CHECK or induce a
crash.  In the case where you can respond gracefully (as in this case), you
should do so.

On 2012/05/11 09:16:40, stuartmorgan wrote:

[stuartmorgan, 2012/05/11 22:04:37]

Not only is it in our style guide, it's one of the only bold things in it:
http://dev.chromium.org/developers/coding-style#TOC-CHECK-vs-DCHECK-and-NOTRE...
should do so.

That's exactly the opposite of what the style guide says.

[jar (doing other things), 2012/05/15 18:27:39]

I went around on this with Darin.  The style guide commentary in this area is
focused on user-visible elements, and error handling.  This area, surrounding
UMA, which is not user-visible, is more questionable with regard to that
proposed pattern. 

Given the ease with which this bug can be stimulated, I'd rather see the error
handling code, than the DCHECK()... so if you insist on only one, I'd like that
one.

This will allow folks to set bounds at very low level, and often (not always)
have zero logs persisted.  For some low-memory users, that may indeed be
preferable.

On 2012/05/11 22:04:37, stuartmorgan wrote:

[stuartmorgan, 2012/05/15 19:02:58]

I can re-add the error-handling. (I'm not clear how it's easy to trigger this
bug though; someone would have to call the function with both values 0, which is
a very strange thing to do, DCHECKs immediately, and is documented as being
disallowed.)
That's not possible as currently written. Does this mean you want me to rewrite
this using what I was calling "soft-max" instead of what it currently does? As I
said before, I think the current version is somewhat easier to understand, and
I'm having a hard time imagining that much memory constraint on a device that
can run Chrome (see below).

     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<MetricsLogManager::SerializedLog>::const_iterator it =
            local_list.begin() + start;
@@ skipping 84 matching lines @@
   if (!valid) {
     local_list->clear();
     return MakeRecallStatusHistogram(CHECKSUM_STRING_CORRUPTION, is_xml);
   }
   if (recovered_md5 != base::MD5DigestToBase16(digest)) {
     local_list->clear();
     return MakeRecallStatusHistogram(CHECKSUM_CORRUPTION, is_xml);
   }
   return MakeRecallStatusHistogram(RECALL_SUCCESS, is_xml);
 }