Add guards to metric values; erase bad events/metrics from db

chrome/browser/performance_monitor/database.cc

Index: chrome/browser/performance_monitor/database.cc
diff --git a/chrome/browser/performance_monitor/database.cc b/chrome/browser/performance_monitor/database.cc
index 27108e319b010b9969c25573ba90bc199a644942..18076e3bb2800054701b49ea31063c11ec7a7b91 100644
--- a/chrome/browser/performance_monitor/database.cc
+++ b/chrome/browser/performance_monitor/database.cc
@@ -18,6 +18,8 @@
 #include "chrome/common/chrome_paths.h"
 #include "content/public/browser/browser_thread.h"
 #include "third_party/leveldatabase/src/include/leveldb/db.h"
+#include "third_party/leveldatabase/src/include/leveldb/iterator.h"
+#include "third_party/leveldatabase/src/include/leveldb/write_batch.h"
 
 namespace performance_monitor {
 namespace {
@@ -145,6 +147,7 @@ Database::EventVector Database::GetEvents(EventType type,
       key_builder_->CreateEventKey(start, EVENT_UNDEFINED);
   std::string end_key =
       key_builder_->CreateEventKey(end, EVENT_NUMBER_OF_EVENTS);
+  leveldb::WriteBatch invalid_entries;
   scoped_ptr<leveldb::Iterator> it(event_db_->NewIterator(read_options_));
   for (it->Seek(start_key);
        it->Valid() && it->key().ToString() <= end_key;
@@ -155,18 +158,21 @@ Database::EventVector Database::GetEvents(EventType type,
       if (key_type != type)
         continue;
     }
+    Value* value = NULL;
     base::DictionaryValue* dict = NULL;
-    if (!base::JSONReader::Read(
-        it->value().ToString())->GetAsDictionary(&dict)) {
-      LOG(ERROR) << "Unable to convert database event to JSON.";
+    scoped_ptr<Event> event;
+    if (!(value = base::JSONReader::Read(it->value().ToString())) ||
+        !value->GetAsDictionary(&dict) ||
+        !(event =
+            Event::FromValue(scoped_ptr<base::DictionaryValue>(dict))).get()) {
+      invalid_entries.Delete(it->key());
+      LOG(ERROR) << "Unable to convert database event to JSON. Erasing the "
+                    "event from the database.";
       continue;
     }
-    scoped_ptr<Event> event =
-        Event::FromValue(scoped_ptr<base::DictionaryValue>(dict));
-    if (!event.get())
-      continue;
     events.push_back(linked_ptr<Event>(event.release()));
   }
+  event_db_->Write(write_options_, &invalid_entries);
   return events;
 }
 
@@ -190,28 +196,33 @@ Database::EventTypeSet Database::GetEventTypes(const base::Time& start,
 }
 
 bool Database::AddMetric(const std::string& activity,
-                         MetricType metric,
-                         const std::string& value) {
+                         const Metric& metric) {
   CHECK(!content::BrowserThread::CurrentlyOn(content::BrowserThread::UI));
+  if (!metric.Validate()) {

[eaugusti, 2012/09/07 23:10:55]

Should this be a DCHECK?
If this method is getting a bad Metric, then a programmer made a mistake.

[Devlin, 2012/09/10 17:49:14]

Not necessarily. If this is a bad Metric, then it is more likely a call returned
a bad value. Perhaps I should have been more verbose in the CL's description,
but blatantly bad values can't always be helped. We've found that we've gotten
CPU usage of negative numbers reported before, page loads in the thousands of
seconds, etc.

A few things on this note. For one, there's not always a guarantee that we can
always fix these. Sometimes, it might be out of our capabilities. I've seen
system calls fail on these things, but clearly we're not going to re-write
those. Another issue is that, even if it is a bug in Chrome's source, the
PerformanceMonitor team can't fix them all (if we have to debug why CPU usage
might return negative on 3 different platforms, heavily diving into
system-specific properties and system calls, it becomes more trouble than it's
worth for the 1% of the time it might return a bad value). Simply ignoring these
bad values is the best solution for the short-term.

+    LOG(ERROR) << "Metric is not valid; ignoring.";
+    return false;
+  }
+
   UpdateActiveInterval();
   base::Time timestamp = clock_->GetTime();

[eaugusti, 2012/09/07 23:10:55]

I don't like how Metric has time, but clock_ is still used here. It could just
be because the uncommited dependency, but it would be best if the clock was not
used for Metrics as soon as Metrics are passed into Add*() methods.

[Devlin, 2012/09/10 17:49:14]

Done.

   std::string recent_key =
-      key_builder_->CreateRecentKey(timestamp, metric, activity);
+      key_builder_->CreateRecentKey(timestamp, metric.type, activity);
   std::string metric_key =
-      key_builder_->CreateMetricKey(timestamp, metric, activity);
+      key_builder_->CreateMetricKey(timestamp, metric.type, activity);
   std::string recent_map_key =
-      key_builder_->CreateRecentMapKey(metric, activity);
+      key_builder_->CreateRecentMapKey(metric.type, activity);
   // Use recent_map_ to quickly find the key that must be removed.
   RecentMap::iterator old_it = recent_map_.find(recent_map_key);
   if (old_it != recent_map_.end())
     recent_db_->Delete(write_options_, old_it->second);
   recent_map_[recent_map_key] = recent_key;
   leveldb::Status recent_status =
-      recent_db_->Put(write_options_, recent_key, value);
+      recent_db_->Put(write_options_, recent_key, metric.ValueAsString());
   leveldb::Status metric_status =
-      metric_db_->Put(write_options_, metric_key, value);
+      metric_db_->Put(write_options_, metric_key, metric.ValueAsString());
 
-  bool max_value_success = UpdateMaxValue(activity, metric, value);
+  bool max_value_success =
+      UpdateMaxValue(activity, metric.type, metric.ValueAsString());
   return recent_status.ok() && metric_status.ok() && max_value_success;
 }
 
@@ -321,7 +332,9 @@ bool Database::GetRecentStatsForActivityAndMetric(const std::string& activity,
   std::string result;
   leveldb::Status status = recent_db_->Get(read_options_, recent_key, &result);
   if (status.ok())
-    *metric = Metric(key_builder_->SplitRecentKey(recent_key).time, result);
+    *metric = Metric(metric_type,
+                     key_builder_->SplitRecentKey(recent_key).time,
+                     result);
   return status.ok();
 }
 
@@ -336,15 +349,27 @@ Database::MetricVector Database::GetStatsForActivityAndMetric(
       key_builder_->CreateMetricKey(start, metric_type, activity);
   std::string end_key =
       key_builder_->CreateMetricKey(end, metric_type, activity);
+  leveldb::WriteBatch invalid_entries;
   scoped_ptr<leveldb::Iterator> it(metric_db_->NewIterator(read_options_));
   for (it->Seek(start_key);
        it->Valid() && it->key().ToString() <= end_key;
        it->Next()) {
     MetricKey split_key =
         key_builder_->SplitMetricKey(it->key().ToString());
-    if (split_key.activity == activity)
-      results.push_back(Metric(split_key.time, it->value().ToString()));
+    if (split_key.activity == activity) {
+      Metric metric(metric_type, split_key.time, it->value().ToString());
+      if (!metric.Validate()) {
+        LOG(ERROR) << "Found bad metric in database. Erasing the metric from "

[eaugusti, 2012/09/07 23:10:55]

We may want to consider moving this to a verbose log. I am imagining the
situation where deprecated or some large chunk of bad data is being accessed.

ps. This comment applies to all the logs of this nature.

[Devlin, 2012/09/10 17:49:14]

I'm a little hesitant to do this, only because the database is still relatively
new and hasn't been strained. I'd be curious how often it fails, and under what
circumstances, so we can fix it. With this more silent option, we only see it if
we look for it (and with how many VLOG(1)'s are in the source, we have to look
*hard*). I'd prefer to keep it as a LOG for now - if we have a lot of prints,
then we can change it (or better, fix it). Since we only run PM right now with
the flag, we can assume anyone running it will consent to a bit more output :)

+                      "the database.";
+        invalid_entries.Delete(it->key());
+        continue;
+      }
+      results.push_back(Metric(metric_type,
+                               split_key.time,
+                               it->value().ToString()));
+    }
   }
+  metric_db_->Write(write_options_, &invalid_entries);
   return results;
 }
 
@@ -358,6 +383,7 @@ Database::MetricVectorMap Database::GetStatsForMetricByActivity(
       key_builder_->CreateMetricKey(start, metric_type, std::string());
   std::string end_key =
       key_builder_->CreateMetricKey(end, metric_type, std::string());
+  leveldb::WriteBatch invalid_entries;
   scoped_ptr<leveldb::Iterator> it(metric_db_->NewIterator(read_options_));
   for (it->Seek(start_key);
        it->Valid() && it->key().ToString() <= end_key;
@@ -367,9 +393,17 @@ Database::MetricVectorMap Database::GetStatsForMetricByActivity(
       results[split_key.activity] =
           linked_ptr<MetricVector >(new MetricVector());
     }
+    Metric metric(metric_type, split_key.time, it->value().ToString());
+    if (!metric.Validate()) {
+      LOG(ERROR) << "Found bad metric in database. Erasing the metric from "
+                    "the database.";
+      invalid_entries.Delete(it->key());
+      continue;
+    }
     results[split_key.activity]->push_back(
-        Metric(split_key.time, it->value().ToString()));
+        Metric(metric_type, split_key.time, it->value().ToString()));
   }
+  metric_db_->Write(write_options_, &invalid_entries);
   return results;
 }