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

chrome/browser/performance_monitor/database.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/browser/performance_monitor/database.h"
 
 #include "base/file_path.h"
 #include "base/file_util.h"
 #include "base/json/json_reader.h"
 #include "base/json/json_writer.h"
 #include "base/logging.h"
 #include "base/path_service.h"
 #include "base/stl_util.h"
 #include "base/string_number_conversions.h"
 #include "base/time.h"
 #include "base/utf_string_conversions.h"
 #include "chrome/browser/performance_monitor/key_builder.h"
 #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 {
 const char kDbDir[] = "Performance Monitor Databases";
 const char kRecentDb[] = "Recent Metrics";
 const char kMaxValueDb[] = "Max Value Metrics";
 const char kEventDb[] = "Events";
 const char kStateDb[] = "Configuration";
 const char kActiveIntervalDb[] = "Active Interval";
 const char kMetricDb[] = "Metrics";
@@ skipping 107 matching lines @@
 
 Database::EventVector Database::GetEvents(EventType type,
                                           const base::Time& start,
                                           const base::Time& end) {
   CHECK(!content::BrowserThread::CurrentlyOn(content::BrowserThread::UI));
   EventVector events;
   std::string start_key =
       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;
        it->Next()) {
     if (type != EVENT_UNDEFINED) {
       EventType key_type =
           key_builder_->EventKeyToEventType(it->key().ToString());
       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;
 }
 
 Database::EventTypeSet Database::GetEventTypes(const base::Time& start,
                                                const base::Time& end) {
   CHECK(!content::BrowserThread::CurrentlyOn(content::BrowserThread::UI));
   EventTypeSet results;
   std::string start_key =
       key_builder_->CreateEventKey(start, EVENT_UNDEFINED);
   std::string end_key =
       key_builder_->CreateEventKey(end, EVENT_NUMBER_OF_EVENTS);
   scoped_ptr<leveldb::Iterator> it(event_db_->NewIterator(read_options_));
   for (it->Seek(start_key);
        it->Valid() && it->key().ToString() <= end_key;
        it->Next()) {
     EventType key_type =
         key_builder_->EventKeyToEventType(it->key().ToString());
     results.insert(key_type);
   }
   return results;
 }
 
 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;
 }
 
 bool Database::UpdateMaxValue(const std::string& activity,
                               MetricType metric,
                               const std::string& value) {
   std::string max_value_key(
       key_builder_->CreateMaxValueKey(metric, activity));
   bool has_key = ContainsKey(max_value_map_, max_value_key);
   if ((has_key && StringToDouble(value) > max_value_map_[max_value_key]) ||
@@ skipping 89 matching lines @@
   CHECK(!content::BrowserThread::CurrentlyOn(content::BrowserThread::UI));
   std::string recent_map_key =
       key_builder_->CreateRecentMapKey(metric_type, activity);
   if (!ContainsKey(recent_map_, recent_map_key))
     return false;
   std::string recent_key = recent_map_[recent_map_key];
 
   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();
 }
 
 Database::MetricVector Database::GetStatsForActivityAndMetric(
     const std::string& activity,
     MetricType metric_type,
     const base::Time& start,
     const base::Time& end) {
   CHECK(!content::BrowserThread::CurrentlyOn(content::BrowserThread::UI));
   MetricVector results;
   std::string start_key =
       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;
 }
 
 Database::MetricVectorMap Database::GetStatsForMetricByActivity(
     MetricType metric_type,
     const base::Time& start,
     const base::Time& end) {
   CHECK(!content::BrowserThread::CurrentlyOn(content::BrowserThread::UI));
   MetricVectorMap results;
   std::string start_key =
       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;
        it->Next()) {
     MetricKey split_key = key_builder_->SplitMetricKey(it->key().ToString());
     if (!results[split_key.activity].get()) {
       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;
 }
 
 Database::Database(const FilePath& path)
     : key_builder_(new KeyBuilder()),
       path_(path),
       read_options_(leveldb::ReadOptions()),
       write_options_(leveldb::WriteOptions()) {
   InitDBs();
   LoadRecents();
@@ skipping 99 matching lines @@
     start_time_key_ = key_builder_->CreateActiveIntervalKey(current_time);
     end_time = start_time_key_;
   } else {
     end_time = key_builder_->CreateActiveIntervalKey(clock_->GetTime());
   }
   last_update_time_ = current_time;
   active_interval_db_->Put(write_options_, start_time_key_, end_time);
 }
 
 }  // namespace performance_monitor