IndexedDB: Added timing histograms.

content/browser/indexed_db/leveldb/leveldb_database.cc

 // Copyright (c) 2013 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 "content/browser/indexed_db/leveldb/leveldb_database.h"
 
 #include <cerrno>
 
 #include "base/basictypes.h"
 #include "base/files/file.h"
@@ skipping 246 matching lines @@
   if (s.IsIOError())
     ParseAndHistogramIOErrorDetails(histogram_name, s);
   else
     ParseAndHistogramCorruptionDetails(histogram_name, s);
 }
 
 leveldb::Status LevelDBDatabase::Open(const base::FilePath& file_name,
                                       const LevelDBComparator* comparator,
                                       scoped_ptr<LevelDBDatabase>* result,
                                       bool* is_disk_full) {
+  base::TimeTicks begin_time = base::TimeTicks::Now();
+
   scoped_ptr<ComparatorAdapter> comparator_adapter(
       new ComparatorAdapter(comparator));
 
   leveldb::DB* db;
   const leveldb::Status s =
       OpenDB(comparator_adapter.get(), leveldb::IDBEnv(), file_name, &db);
 
   if (!s.ok()) {
     HistogramLevelDBError("WebCore.IndexedDB.LevelDBOpenErrors", s);
     int free_space_k_bytes = CheckFreeSpace("Failure", file_name);
     // Disks with <100k of free space almost never succeed in opening a
     // leveldb database.
     if (is_disk_full)
       *is_disk_full = free_space_k_bytes >= 0 && free_space_k_bytes < 100;
 
     LOG(ERROR) << "Failed to open LevelDB database from "
                << file_name.AsUTF8Unsafe() << "," << s.ToString();
     return s;
   }
 
+  UMA_HISTOGRAM_MEDIUM_TIMES("WebCore.IndexedDB.LevelDB.OpenTime.Disk",

[jsbell, 2014/08/13 22:49:11]

Assumes anything < 10 seconds is "fast enough" and we don't need to break it
down further? Sounds okay.

[cmumford, 2014/08/13 23:53:02]

If I'm reading the code correctly then UMA_HISTOGRAM_MEDIUM_TIMES is 10msec < h
< 3min. I'm not sure if times < 10msec are ignored, or rounded up to to 10msec.

[dgrogan, 2014/08/13 23:55:18]

They'll show up in the 0 bucket.

+                             base::TimeTicks::Now() - begin_time);
+
   CheckFreeSpace("Success", file_name);
 
   (*result).reset(new LevelDBDatabase);
   (*result)->db_ = make_scoped_ptr(db);
   (*result)->comparator_adapter_ = comparator_adapter.Pass();
   (*result)->comparator_ = comparator;
 
   return s;
 }
 
@@ skipping 16 matching lines @@
   result->env_ = in_memory_env.Pass();
   result->db_ = make_scoped_ptr(db);
   result->comparator_adapter_ = comparator_adapter.Pass();
   result->comparator_ = comparator;
 
   return result.Pass();
 }
 
 leveldb::Status LevelDBDatabase::Put(const StringPiece& key,
                                      std::string* value) {
+  base::TimeTicks begin_time = base::TimeTicks::Now();
+
   leveldb::WriteOptions write_options;
   write_options.sync = kSyncWrites;
 
   const leveldb::Status s =
       db_->Put(write_options, MakeSlice(key), MakeSlice(*value));
   if (!s.ok())
     LOG(ERROR) << "LevelDB put failed: " << s.ToString();
+  else
+    UMA_HISTOGRAM_TIMES("WebCore.IndexedDB.LevelDB.PutTime",
+                        base::TimeTicks::Now() - begin_time);
   return s;
 }
 
 leveldb::Status LevelDBDatabase::Remove(const StringPiece& key) {

[jsbell, 2014/08/13 22:49:11]

Why no histogram here?

[cmumford, 2014/08/13 23:53:02]

No reason. Your bug only mentioned open & commit so I figured I'd post this and
you'd mention any other functions you'd like measured in this review.

I'll go ahead and measure Remove().

   leveldb::WriteOptions write_options;
   write_options.sync = kSyncWrites;
 
   const leveldb::Status s = db_->Delete(write_options, MakeSlice(key));
   if (!s.IsNotFound())
     LOG(ERROR) << "LevelDB remove failed: " << s.ToString();
   return s;
 }
 
 leveldb::Status LevelDBDatabase::Get(const StringPiece& key,
@@ skipping 12 matching lines @@
     return s;
   }
   if (s.IsNotFound())
     return leveldb::Status::OK();
   HistogramLevelDBError("WebCore.IndexedDB.LevelDBReadErrors", s);
   LOG(ERROR) << "LevelDB get failed: " << s.ToString();
   return s;
 }
 
 leveldb::Status LevelDBDatabase::Write(const LevelDBWriteBatch& write_batch) {
+  base::TimeTicks begin_time = base::TimeTicks::Now();
   leveldb::WriteOptions write_options;
   write_options.sync = kSyncWrites;
 
   const leveldb::Status s =
       db_->Write(write_options, write_batch.write_batch_.get());
   if (!s.ok()) {
     HistogramLevelDBError("WebCore.IndexedDB.LevelDBWriteErrors", s);
     LOG(ERROR) << "LevelDB write failed: " << s.ToString();
+  } else {
+    UMA_HISTOGRAM_TIMES("WebCore.IndexedDB.LevelDB.WriteTime",
+                        base::TimeTicks::Now() - begin_time);
   }
   return s;
 }
 
 scoped_ptr<LevelDBIterator> LevelDBDatabase::CreateIterator(
     const LevelDBSnapshot* snapshot) {
   leveldb::ReadOptions read_options;
   read_options.verify_checksums = true;  // TODO(jsbell): Disable this if the
                                          // performance impact is too great.
   read_options.snapshot = snapshot ? snapshot->snapshot_ : 0;
@@ skipping 12 matching lines @@
   const leveldb::Slice start_slice = MakeSlice(start);
   const leveldb::Slice stop_slice = MakeSlice(stop);
   // NULL batch means just wait for earlier writes to be done
   db_->Write(leveldb::WriteOptions(), NULL);
   db_->CompactRange(&start_slice, &stop_slice);
 }
 
 void LevelDBDatabase::CompactAll() { db_->CompactRange(NULL, NULL); }
 
 }  // namespace content