[sql] Stats gathering for sql/ APIs.

sql/connection.cc

Index: sql/connection.cc
diff --git a/sql/connection.cc b/sql/connection.cc
index b91234bac3d27d5eaa2f73cdaf8e8e96ad77798b..ae0fc48386cddf463b733627fc04167b0082e73b 100644
--- a/sql/connection.cc
+++ b/sql/connection.cc
@@ -219,13 +219,72 @@ Connection::Connection()
       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) {
 }
 
 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::CommitTime(const base::TimeDelta& delta) {
+  UpdateTime(delta);
+  UMA_HISTOGRAM_MEDIUM_TIMES("Sqlite.CommitTime", delta);
+  if (commit_time_histogram_)
+    commit_time_histogram_->AddTime(delta);
+}
+
+void Connection::AutoCommitTime(const base::TimeDelta& delta) {
+  UpdateTime(delta);
+  UMA_HISTOGRAM_MEDIUM_TIMES("Sqlite.AutoCommitTime", delta);
+  if (autocommit_time_histogram_)
+    autocommit_time_histogram_->AddTime(delta);
+}
+
+void Connection::UpdateTime(const base::TimeDelta& delta) {
+  QueryTime(delta);
+  UMA_HISTOGRAM_MEDIUM_TIMES("Sqlite.UpdateTime", delta);
+  if (update_time_histogram_)
+    update_time_histogram_->AddTime(delta);
+}
+
+void Connection::QueryTime(const base::TimeDelta& delta) {
+  UMA_HISTOGRAM_MEDIUM_TIMES("Sqlite.QueryTime", delta);
+  if (query_time_histogram_)
+    query_time_histogram_->AddTime(delta);
+}
+
+void Connection::ChangeHelper(const base::TimeDelta& delta, bool read_only) {
+  if (read_only) {
+    QueryTime(delta);
+  } else {
+    const int changes = sqlite3_changes(db_);
+    if (sqlite3_get_autocommit(db_)) {
+      AutoCommitTime(delta);
+      RecordEvent(EVENT_CHANGES_AUTOCOMMIT, changes);
+    } else {
+      UpdateTime(delta);
+      RecordEvent(EVENT_CHANGES, changes);
+    }
+  }
+}
+
 bool Connection::Open(const base::FilePath& path) {
   if (!histogram_tag_.empty()) {
     int64_t size_64 = 0;
@@ -576,6 +635,7 @@ bool Connection::BeginTransaction() {
     needs_rollback_ = false;
 
     Statement begin(GetCachedStatement(SQL_FROM_HERE, "BEGIN TRANSACTION"));
+    RecordOneEvent(EVENT_BEGIN);
     if (!begin.Run())
       return false;
   }
@@ -618,7 +678,17 @@ bool Connection::CommitTransaction() {
   }
 
   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 = base::TimeTicks::Now();
+  bool ret = commit.RunWithoutTimers();
+  const base::TimeDelta delta = base::TimeTicks::Now() - before;
+
+  CommitTime(delta);
+  RecordOneEvent(EVENT_COMMIT);
+
+  return ret;
 }
 
 void Connection::RollbackAllTransactions() {
@@ -650,13 +720,65 @@ bool Connection::DetachDatabase(const char* 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 = base::TimeTicks::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 int 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 = base::TimeTicks::Now() - before;
+    ChangeHelper(delta, read_only);
+  }
+  return rc;
 }
 
 bool Connection::Execute(const char* sql) {
@@ -886,6 +1008,51 @@ bool Connection::OpenInternal(const std::string& file_name,
   // 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_ =
+        base::Histogram::FactoryTimeGet(
+            "Sqlite.CommitTime." + histogram_tag_,
+            base::TimeDelta::FromMilliseconds(10),
+            base::TimeDelta::FromMinutes(3),
+            50,
+            base::HistogramBase::kUmaTargetedHistogramFlag);

[rmcilroy, 2015/05/21 22:54:48]

Maybe make a helper function which creates a Medium times histogram with a given
name to avoid repeating the same parameters each time here.

[Scott Hess - ex-Googler, 2015/05/21 23:42:36]

Done.

+
+    autocommit_time_histogram_ =
+        base::Histogram::FactoryTimeGet(
+            "Sqlite.AutoCommitTime." + histogram_tag_,
+            base::TimeDelta::FromMilliseconds(10),
+            base::TimeDelta::FromMinutes(3),
+            50,
+            base::HistogramBase::kUmaTargetedHistogramFlag);
+
+    update_time_histogram_ =
+        base::Histogram::FactoryTimeGet(
+            "Sqlite.UpdateTime." + histogram_tag_,
+            base::TimeDelta::FromMilliseconds(10),
+            base::TimeDelta::FromMinutes(3),
+            50,
+            base::HistogramBase::kUmaTargetedHistogramFlag);
+
+    query_time_histogram_ =
+        base::Histogram::FactoryTimeGet(
+            "Sqlite.QueryTime." + histogram_tag_,
+            base::TimeDelta::FromMilliseconds(10),
+            base::TimeDelta::FromMinutes(3),
+            50,
+            base::HistogramBase::kUmaTargetedHistogramFlag);
+  }
+
   // 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
@@ -1028,7 +1195,16 @@ bool Connection::OpenInternal(const std::string& file_name,
 
 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 = base::TimeTicks::Now();
+  rollback.RunWithoutTimers();
+  const base::TimeDelta delta = base::TimeTicks::Now() - before;
+
+  UpdateTime(delta);
+  RecordOneEvent(EVENT_ROLLBACK);
+
   needs_rollback_ = false;
 }
 
@@ -1045,6 +1221,11 @@ void Connection::StatementRefDeleted(StatementRef* ref) {
     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())