[sql] Stats gathering for sql/ APIs.

sql/connection.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 "sql/connection.h"
 
 #include <string.h>
 
 #include "base/files/file_path.h"
 #include "base/files/file_util.h"
@@ skipping 123 matching lines @@
 
   // TODO(shess): NULL in file->pMethods has been observed on android_dbg
   // content_unittests, even though it should not be possible.
   // http://crbug.com/329982
   if (!*file || !(*file)->pMethods)
     return SQLITE_ERROR;
 
   return rc;
 }
 
+// This should match UMA_HISTOGRAM_MEDIUM_TIMES().
+base::HistogramBase* GetMediumTimeHistogram(const std::string& name) {
+  return base::Histogram::FactoryTimeGet(
+      name,
+      base::TimeDelta::FromMilliseconds(10),
+      base::TimeDelta::FromMinutes(3),
+      50,
+      base::HistogramBase::kUmaTargetedHistogramFlag);
+}
+
 }  // namespace
 
 namespace sql {
 
 // static
 Connection::ErrorIgnorerCallback* Connection::current_ignorer_cb_ = NULL;
 
 // static
 bool Connection::ShouldIgnoreSqliteError(int error) {
   if (!current_ignorer_cb_)
@@ skipping 58 matching lines @@
 
 Connection::Connection()
     : db_(NULL),
       page_size_(0),
       cache_size_(0),
       exclusive_locking_(false),
       restrict_to_user_(false),
       transaction_nesting_(0),
       needs_rollback_(false),
       in_memory_(false),
-      poisoned_(false) {
+      poisoned_(false),
+      stats_histogram_(NULL),
+      commit_time_histogram_(NULL),
+      autocommit_time_histogram_(NULL),
+      update_time_histogram_(NULL),
+      query_time_histogram_(NULL),
+      clock_(new TimeSource()) {
 }
 
 Connection::~Connection() {
   Close();
 }
 
+void Connection::RecordEvent(Events event, size_t count) {
+  for (size_t i = 0; i < count; ++i) {
+    UMA_HISTOGRAM_ENUMERATION("Sqlite.Stats", event, EVENT_MX);
+  }
+
+  if (stats_histogram_) {
+    for (size_t i = 0; i < count; ++i) {
+      stats_histogram_->Add(event);
+    }
+  }
+}
+
+void Connection::RecordCommitTime(const base::TimeDelta& delta) {
+  RecordUpdateTime(delta);
+  UMA_HISTOGRAM_MEDIUM_TIMES("Sqlite.CommitTime", delta);
+  if (commit_time_histogram_)
+    commit_time_histogram_->AddTime(delta);
+}
+
+void Connection::RecordAutoCommitTime(const base::TimeDelta& delta) {
+  RecordUpdateTime(delta);
+  UMA_HISTOGRAM_MEDIUM_TIMES("Sqlite.AutoCommitTime", delta);
+  if (autocommit_time_histogram_)
+    autocommit_time_histogram_->AddTime(delta);
+}
+
+void Connection::RecordUpdateTime(const base::TimeDelta& delta) {
+  RecordQueryTime(delta);
+  UMA_HISTOGRAM_MEDIUM_TIMES("Sqlite.UpdateTime", delta);
+  if (update_time_histogram_)
+    update_time_histogram_->AddTime(delta);
+}
+
+void Connection::RecordQueryTime(const base::TimeDelta& delta) {
+  UMA_HISTOGRAM_MEDIUM_TIMES("Sqlite.QueryTime", delta);
+  if (query_time_histogram_)
+    query_time_histogram_->AddTime(delta);
+}
+
+void Connection::RecordTimeAndChanges(
+    const base::TimeDelta& delta, bool read_only) {
+  if (read_only) {
+    RecordQueryTime(delta);
+  } else {
+    const int changes = sqlite3_changes(db_);
+    if (sqlite3_get_autocommit(db_)) {
+      RecordAutoCommitTime(delta);
+      RecordEvent(EVENT_CHANGES_AUTOCOMMIT, changes);
+    } else {
+      RecordUpdateTime(delta);
+      RecordEvent(EVENT_CHANGES, changes);
+    }
+  }
+}
+
 bool Connection::Open(const base::FilePath& path) {
   if (!histogram_tag_.empty()) {
     int64_t size_64 = 0;
     if (base::GetFileSize(path, &size_64)) {
       size_t sample = static_cast<size_t>(size_64 / 1024);
       std::string full_histogram_name = "Sqlite.SizeKB." + histogram_tag_;
       base::HistogramBase* histogram =
           base::Histogram::FactoryGet(
               full_histogram_name, 1, 1000000, 50,
               base::HistogramBase::kUmaTargetedHistogramFlag);
@@ skipping 330 matching lines @@
     // When we're going to rollback, fail on this begin and don't actually
     // mark us as entering the nested transaction.
     return false;
   }
 
   bool success = true;
   if (!transaction_nesting_) {
     needs_rollback_ = false;
 
     Statement begin(GetCachedStatement(SQL_FROM_HERE, "BEGIN TRANSACTION"));
+    RecordOneEvent(EVENT_BEGIN);
     if (!begin.Run())
       return false;
   }
   transaction_nesting_++;
   return success;
 }
 
 void Connection::RollbackTransaction() {
   if (!transaction_nesting_) {
     DLOG_IF(FATAL, !poisoned_) << "Rolling back a nonexistent transaction";
@@ skipping 22 matching lines @@
     // Mark any nested transactions as failing after we've already got one.
     return !needs_rollback_;
   }
 
   if (needs_rollback_) {
     DoRollback();
     return false;
   }
 
   Statement commit(GetCachedStatement(SQL_FROM_HERE, "COMMIT"));
-  return commit.Run();
+
+  // Collect the commit time manually, sql::Statement would register it as query
+  // time only.
+  const base::TimeTicks before = Now();
+  bool ret = commit.RunWithoutTimers();
+  const base::TimeDelta delta = Now() - before;
+
+  RecordCommitTime(delta);
+  RecordOneEvent(EVENT_COMMIT);
+
+  return ret;
 }
 
 void Connection::RollbackAllTransactions() {
   if (transaction_nesting_ > 0) {
     transaction_nesting_ = 0;
     DoRollback();
   }
 }
 
 bool Connection::AttachDatabase(const base::FilePath& other_db_path,
@@ skipping 11 matching lines @@
 }
 
 bool Connection::DetachDatabase(const char* attachment_point) {
   DCHECK(ValidAttachmentPoint(attachment_point));
 
   Statement s(GetUniqueStatement("DETACH DATABASE ?"));
   s.BindString(0, attachment_point);
   return s.Run();
 }
 
+// TODO(shess): Consider changing this to execute exactly one statement.  If a
+// caller wishes to execute multiple statements, that should be explicit, and
+// perhaps tucked into an explicit transaction with rollback in case of error.
 int Connection::ExecuteAndReturnErrorCode(const char* sql) {
   AssertIOAllowed();
   if (!db_) {
     DLOG_IF(FATAL, !poisoned_) << "Illegal use of connection without a db";
     return SQLITE_ERROR;
   }
-  return sqlite3_exec(db_, sql, NULL, NULL, NULL);
+  DCHECK(sql);
+
+  RecordOneEvent(EVENT_EXECUTE);
+  int rc = SQLITE_OK;
+  while ((rc == SQLITE_OK) && *sql) {
+    sqlite3_stmt *stmt = NULL;
+    const char *leftover_sql;
+
+    const base::TimeTicks before = Now();
+    rc = sqlite3_prepare_v2(db_, sql, -1, &stmt, &leftover_sql);
+    sql = leftover_sql;
+
+    // Stop if an error is encountered.
+    if (rc != SQLITE_OK)
+      break;
+
+    // This happens if |sql| originally only contained comments or whitespace.
+    // TODO(shess): Audit to see if this can become a DCHECK().  Having
+    // extraneous comments and whitespace in the SQL statements increases
+    // runtime cost and can easily be shifted out to the C++ layer.
+    if (!stmt)
+      continue;
+
+    // Save for use after statement is finalized.
+    const bool read_only = !!sqlite3_stmt_readonly(stmt);
+
+    RecordOneEvent(Connection::EVENT_STATEMENT_RUN);
+    while ((rc = sqlite3_step(stmt)) == SQLITE_ROW) {
+      // TODO(shess): Audit to see if this can become a DCHECK.  I think PRAGMA
+      // is the only legitimate case for this.
+      RecordOneEvent(Connection::EVENT_STATEMENT_ROWS);
+    }
+
+    // sqlite3_finalize() returns SQLITE_OK if the most recent sqlite3_step()
+    // returned SQLITE_DONE or SQLITE_ROW, otherwise the error code.
+    rc = sqlite3_finalize(stmt);
+    if (rc == SQLITE_OK)
+      RecordOneEvent(Connection::EVENT_STATEMENT_SUCCESS);
+
+    // sqlite3_exec() does this, presumably to avoid spinning the parser for
+    // trailing whitespace.
+    // TODO(shess): Audit to see if this can become a DCHECK.
+    while (IsAsciiWhitespace(*sql)) {
+      sql++;
+    }
+
+    const base::TimeDelta delta = Now() - before;
+    RecordTimeAndChanges(delta, read_only);
+  }
+  return rc;
 }
 
 bool Connection::Execute(const char* sql) {
   if (!db_) {
     DLOG_IF(FATAL, !poisoned_) << "Illegal use of connection without a db";
     return false;
   }
 
   int error = ExecuteAndReturnErrorCode(sql);
   if (error != SQLITE_OK)
@@ skipping 209 matching lines @@
   AssertIOAllowed();
 
   if (db_) {
     DLOG(FATAL) << "sql::Connection is already open.";
     return false;
   }
 
   // Make sure sqlite3_initialize() is called before anything else.
   InitializeSqlite();
 
+  // Setup the stats histograms immediately rather than allocating lazily.
+  // Connections which won't exercise all of these probably shouldn't exist.
+  if (!histogram_tag_.empty()) {
+    stats_histogram_ =
+        base::LinearHistogram::FactoryGet(
+            "Sqlite.Stats." + histogram_tag_, 1, EVENT_MX, EVENT_MX + 1,
+            base::HistogramBase::kUmaTargetedHistogramFlag);
+
+    // The timer setup matches UMA_HISTOGRAM_MEDIUM_TIMES().  3 minutes is an
+    // unreasonable time for any single operation, so there is not much value to
+    // knowing if it was 3 minutes or 5 minutes.  In reality at that point
+    // things are entirely busted.
+    commit_time_histogram_ =
+        GetMediumTimeHistogram("Sqlite.CommitTime." + histogram_tag_);
+
+    autocommit_time_histogram_ =
+        GetMediumTimeHistogram("Sqlite.AutoCommitTime." + histogram_tag_);
+
+    update_time_histogram_ =
+        GetMediumTimeHistogram("Sqlite.UpdateTime." + histogram_tag_);
+
+    query_time_histogram_ =
+        GetMediumTimeHistogram("Sqlite.QueryTime." + histogram_tag_);
+  }
+
   // If |poisoned_| is set, it means an error handler called
   // RazeAndClose().  Until regular Close() is called, the caller
   // should be treating the database as open, but is_open() currently
   // only considers the sqlite3 handle's state.
   // TODO(shess): Revise is_open() to consider poisoned_, and review
   // to see if any non-testing code even depends on it.
   DLOG_IF(FATAL, poisoned_) << "sql::Connection is already open.";
   poisoned_ = false;
 
   int err = sqlite3_open(file_name.c_str(), &db_);
@@ skipping 122 matching lines @@
     if (was_poisoned && retry_flag == RETRY_ON_POISON)
       return OpenInternal(file_name, NO_RETRY);
     return false;
   }
 
   return true;
 }
 
 void Connection::DoRollback() {
   Statement rollback(GetCachedStatement(SQL_FROM_HERE, "ROLLBACK"));
-  rollback.Run();
+
+  // Collect the rollback time manually, sql::Statement would register it as
+  // query time only.
+  const base::TimeTicks before = Now();
+  rollback.RunWithoutTimers();
+  const base::TimeDelta delta = Now() - before;
+
+  RecordUpdateTime(delta);
+  RecordOneEvent(EVENT_ROLLBACK);
+
   needs_rollback_ = false;
 }
 
 void Connection::StatementRefCreated(StatementRef* ref) {
   DCHECK(open_statements_.find(ref) == open_statements_.end());
   open_statements_.insert(ref);
 }
 
 void Connection::StatementRefDeleted(StatementRef* ref) {
   StatementRefSet::iterator i = open_statements_.find(ref);
   if (i == open_statements_.end())
     DLOG(FATAL) << "Could not find statement";
   else
     open_statements_.erase(i);
 }
 
+void Connection::set_histogram_tag(const std::string& tag) {
+  DCHECK(!is_open());
+  histogram_tag_ = tag;
+}
+
 void Connection::AddTaggedHistogram(const std::string& name,
                                     size_t sample) const {
   if (histogram_tag_.empty())
     return;
 
   // TODO(shess): The histogram macros create a bit of static storage
   // for caching the histogram object.  This code shouldn't execute
   // often enough for such caching to be crucial.  If it becomes an
   // issue, the object could be cached alongside histogram_prefix_.
   std::string full_histogram_name = name + "." + histogram_tag_;
@@ skipping 72 matching lines @@
     ret = stmt.Succeeded();
   }
 
   // Best effort to put things back as they were before.
   const char kNoWritableSchema[] = "PRAGMA writable_schema = OFF";
   ignore_result(Execute(kNoWritableSchema));
 
   return ret;
 }
 
+base::TimeTicks TimeSource::Now() {
+  return base::TimeTicks::Now();
+}
+
 }  // namespace sql