[sql] Stats gathering for sql/ APIs.

Generate stats for how many SQL statements are executed, how many
results they return, and how many changes they make.  Generate timing
values for how long is spent doing all queries, doing updating
operations, doing autocommit updates, and commiting transactions.

The goal of these metrics is to quantify results of decisions like
enabling write-ahead log or memory-mapped I/O.

BUG=489788,489444

Review URL: https://codereview.chromium.org/1145833002

Cr-Commit-Position: refs/heads/master@{#332503}

9 files changed, 841 insertions, 23 deletions

diff --git a/sql/BUILD.gn b/sql/BUILD.gn
index 8b75d80..b3f5e7a 100644
--- a/sql/BUILD.gn
+++ b/sql/BUILD.gn
@@ -13,6 +13,8 @@ component("sql") {
     "init_status.h",
     "meta_table.cc",
     "meta_table.h",
+    "proxy.cc",
+    "proxy.h",
     "recovery.cc",
     "recovery.h",
     "statement.cc",
diff --git a/sql/connection.cc b/sql/connection.cc
index 8720985..c196073 100644
--- a/sql/connection.cc
+++ b/sql/connection.cc
@@ -141,6 +141,16 @@ int GetSqlite3File(sqlite3* db, sqlite3_file** file) {
   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 {
@@ -219,13 +229,74 @@ 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),
+      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_MAX_VALUE);
+  }
+
+  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;
@@ -576,6 +647,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 +690,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 = Now();
+  bool ret = commit.RunWithoutTimers();
+  const base::TimeDelta delta = Now() - before;
+
+  RecordCommitTime(delta);
+  RecordOneEvent(EVENT_COMMIT);
+
+  return ret;
 }
 
 void Connection::RollbackAllTransactions() {
@@ -650,13 +732,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 = 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) {
@@ -886,6 +1020,32 @@ 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_MAX_VALUE, EVENT_MAX_VALUE + 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
@@ -1026,7 +1186,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 = Now();
+  rollback.RunWithoutTimers();
+  const base::TimeDelta delta = Now() - before;
+
+  RecordUpdateTime(delta);
+  RecordOneEvent(EVENT_ROLLBACK);
+
   needs_rollback_ = false;
 }
 
@@ -1043,6 +1212,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())
@@ -1135,4 +1309,8 @@ bool Connection::IntegrityCheckHelper(
   return ret;
 }
 
+base::TimeTicks TimeSource::Now() {
+  return base::TimeTicks::Now();
+}
+
 }  // namespace sql
diff --git a/sql/connection.h b/sql/connection.h
index 17d1191..19592d9 100644
--- a/sql/connection.h
+++ b/sql/connection.h
@@ -25,6 +25,7 @@ struct sqlite3_stmt;
 
 namespace base {
 class FilePath;
+class HistogramBase;
 }
 
 namespace sql {
@@ -32,6 +33,13 @@ namespace sql {
 class Recovery;
 class Statement;
 
+// To allow some test classes to be friended.
+namespace test {
+class ScopedCommitHook;
+class ScopedScalarFunction;
+class ScopedMockTimeSource;
+}
+
 // Uniquely identifies a statement. There are two modes of operation:
 //
 // - In the most common mode, you will use the source file and line number to
@@ -80,6 +88,20 @@ class StatementID {
 
 class Connection;
 
+// Abstract the source of timing information for metrics (RecordCommitTime, etc)
+// to allow testing control.
+class SQL_EXPORT TimeSource {
+ public:
+  TimeSource() {}
+  virtual ~TimeSource() {}
+
+  // Return the current time (by default base::TimeTicks::Now()).
+  virtual base::TimeTicks Now();
+
+ private:
+  DISALLOW_COPY_AND_ASSIGN(TimeSource);
+};
+
 class SQL_EXPORT Connection {
  private:
   class StatementRef;  // Forward declaration, see real one below.
@@ -140,17 +162,52 @@ class SQL_EXPORT Connection {
     error_callback_.Reset();
   }
 
-  // Set this tag to enable additional connection-type histogramming
-  // for SQLite error codes and database version numbers.
-  void set_histogram_tag(const std::string& tag) {
-    histogram_tag_ = tag;
-  }
+  // Set this to enable additional per-connection histogramming.  Must be called
+  // before Open().
+  void set_histogram_tag(const std::string& tag);
 
   // Record a sparse UMA histogram sample under
   // |name|+"."+|histogram_tag_|.  If |histogram_tag_| is empty, no
   // histogram is recorded.
   void AddTaggedHistogram(const std::string& name, size_t sample) const;
 
+  // Track various API calls and results.  Values corrospond to UMA
+  // histograms, do not modify, or add or delete other than directly
+  // before EVENT_MAX_VALUE.
+  enum Events {
+    // Number of statements run, either with sql::Statement or Execute*().
+    EVENT_STATEMENT_RUN = 0,
+
+    // Number of rows returned by statements run.
+    EVENT_STATEMENT_ROWS,
+
+    // Number of statements successfully run (all steps returned SQLITE_DONE or
+    // SQLITE_ROW).
+    EVENT_STATEMENT_SUCCESS,
+
+    // Number of statements run by Execute() or ExecuteAndReturnErrorCode().
+    EVENT_EXECUTE,
+
+    // Number of rows changed by autocommit statements.
+    EVENT_CHANGES_AUTOCOMMIT,
+
+    // Number of rows changed by statements in transactions.
+    EVENT_CHANGES,
+
+    // Count actual SQLite transaction statements (not including nesting).
+    EVENT_BEGIN,
+    EVENT_COMMIT,
+    EVENT_ROLLBACK,
+
+    // Leave this at the end.
+    // TODO(shess): |EVENT_MAX| causes compile fail on Windows.
+    EVENT_MAX_VALUE
+  };
+  void RecordEvent(Events event, size_t count);
+  void RecordOneEvent(Events event) {
+    RecordEvent(event, 1);
+  }
+
   // Run "PRAGMA integrity_check" and post each line of
   // results into |messages|.  Returns the success of running the
   // statement - per the SQLite documentation, if no errors are found the
@@ -415,6 +472,10 @@ class SQL_EXPORT Connection {
   // (they should go through Statement).
   friend class Statement;
 
+  friend class test::ScopedCommitHook;
+  friend class test::ScopedScalarFunction;
+  friend class test::ScopedMockTimeSource;
+
   // Internal initialize function used by both Init and InitInMemory. The file
   // name is always 8 bits since we want to use the 8-bit version of
   // sqlite3_open. The string can also be sqlite's special ":memory:" string.
@@ -548,6 +609,35 @@ class SQL_EXPORT Connection {
       const char* pragma_sql,
       std::vector<std::string>* messages) WARN_UNUSED_RESULT;
 
+  // Record time spent executing explicit COMMIT statements.
+  void RecordCommitTime(const base::TimeDelta& delta);
+
+  // Record time in DML (Data Manipulation Language) statements such as INSERT
+  // or UPDATE outside of an explicit transaction.  Due to implementation
+  // limitations time spent on DDL (Data Definition Language) statements such as
+  // ALTER and CREATE is not included.
+  void RecordAutoCommitTime(const base::TimeDelta& delta);
+
+  // Record all time spent on updating the database.  This includes CommitTime()
+  // and AutoCommitTime(), plus any time spent spilling to the journal if
+  // transactions do not fit in cache.
+  void RecordUpdateTime(const base::TimeDelta& delta);
+
+  // Record all time spent running statements, including time spent doing
+  // updates and time spent on read-only queries.
+  void RecordQueryTime(const base::TimeDelta& delta);
+
+  // Record |delta| as query time if |read_only| (from sqlite3_stmt_readonly) is
+  // true, autocommit time if the database is not in a transaction, or update
+  // time if the database is in a transaction.  Also records change count to
+  // EVENT_CHANGES_AUTOCOMMIT or EVENT_CHANGES_COMMIT.
+  void RecordTimeAndChanges(const base::TimeDelta& delta, bool read_only);
+
+  // Helper to return the current time from the time source.
+  base::TimeTicks Now() {
+    return clock_->Now();
+  }
+
   // The actual sqlite database. Will be NULL before Init has been called or if
   // Init resulted in an error.
   sqlite3* db_;
@@ -594,6 +684,26 @@ class SQL_EXPORT Connection {
   // Tag for auxiliary histograms.
   std::string histogram_tag_;
 
+  // Linear histogram for RecordEvent().
+  base::HistogramBase* stats_histogram_;
+
+  // Histogram for tracking time taken in commit.
+  base::HistogramBase* commit_time_histogram_;
+
+  // Histogram for tracking time taken in autocommit updates.
+  base::HistogramBase* autocommit_time_histogram_;
+
+  // Histogram for tracking time taken in updates (including commit and
+  // autocommit).
+  base::HistogramBase* update_time_histogram_;
+
+  // Histogram for tracking time taken in all queries.
+  base::HistogramBase* query_time_histogram_;
+
+  // Source for timing information, provided to allow tests to inject time
+  // changes.
+  scoped_ptr<TimeSource> clock_;
+
   DISALLOW_COPY_AND_ASSIGN(Connection);
 };
 
diff --git a/sql/connection_unittest.cc b/sql/connection_unittest.cc
index ed86eb0..a09721a 100644
--- a/sql/connection_unittest.cc
+++ b/sql/connection_unittest.cc
@@ -7,8 +7,11 @@
 #include "base/files/scoped_file.h"
 #include "base/files/scoped_temp_dir.h"
 #include "base/logging.h"
+#include "base/metrics/statistics_recorder.h"
+#include "base/test/histogram_tester.h"
 #include "sql/connection.h"
 #include "sql/meta_table.h"
+#include "sql/proxy.h"
 #include "sql/statement.h"
 #include "sql/test/error_callback_support.h"
 #include "sql/test/scoped_error_ignorer.h"
@@ -16,6 +19,122 @@
 #include "testing/gtest/include/gtest/gtest.h"
 #include "third_party/sqlite/sqlite3.h"
 
+namespace sql {
+namespace test {
+
+// Replaces the database time source with an object that steps forward 1ms on
+// each check, and which can be jumped forward an arbitrary amount of time
+// programmatically.
+class ScopedMockTimeSource {
+ public:
+  ScopedMockTimeSource(Connection& db)
+      : db_(db),
+        delta_(base::TimeDelta::FromMilliseconds(1)) {
+    // Save the current source and replace it.
+    save_.swap(db_.clock_);
+    db_.clock_.reset(new MockTimeSource(*this));
+  }
+  ~ScopedMockTimeSource() {
+    // Put original source back.
+    db_.clock_.swap(save_);
+  }
+
+  void adjust(const base::TimeDelta& delta) {
+    current_time_ += delta;
+  }
+
+ private:
+  class MockTimeSource : public TimeSource {
+   public:
+    MockTimeSource(ScopedMockTimeSource& owner)
+        : owner_(owner) {
+    }
+    ~MockTimeSource() override {}
+
+    base::TimeTicks Now() override {
+      base::TimeTicks ret(owner_.current_time_);
+      owner_.current_time_ += owner_.delta_;
+      return ret;
+    }
+
+   private:
+    ScopedMockTimeSource& owner_;
+    DISALLOW_COPY_AND_ASSIGN(MockTimeSource);
+  };
+
+  Connection& db_;
+
+  // Saves original source from |db_|.
+  scoped_ptr<TimeSource> save_;
+
+  // Current time returned by mock.
+  base::TimeTicks current_time_;
+
+  // How far to jump on each Now() call.
+  base::TimeDelta delta_;
+
+  DISALLOW_COPY_AND_ASSIGN(ScopedMockTimeSource);
+};
+
+// Allow a test to add a SQLite function in a scoped context.
+class ScopedScalarFunction {
+ public:
+  ScopedScalarFunction(
+      sql::Connection& db,
+      const char* function_name,
+      int args,
+      base::Callback<void(sqlite3_context*,int,sqlite3_value**)> cb)
+      : db_(db.db_), function_name_(function_name), cb_(cb) {
+    sql::sqlite3_create_function_v2(db_, function_name, args, SQLITE_UTF8,
+                                    this, &Run, NULL, NULL, NULL);
+  }
+  ~ScopedScalarFunction() {
+    sql::sqlite3_create_function_v2(db_, function_name_, 0, SQLITE_UTF8,
+                                    NULL, NULL, NULL, NULL, NULL);
+  }
+
+ private:
+  static void Run(sqlite3_context* context, int argc, sqlite3_value** argv) {
+    ScopedScalarFunction* t = static_cast<ScopedScalarFunction*>(
+        sqlite3_user_data(context));
+    t->cb_.Run(context, argc, argv);
+  }
+
+  sqlite3* db_;
+  const char* function_name_;
+  base::Callback<void(sqlite3_context*,int,sqlite3_value**)> cb_;
+
+  DISALLOW_COPY_AND_ASSIGN(ScopedScalarFunction);
+};
+
+// Allow a test to add a SQLite commit hook in a scoped context.
+class ScopedCommitHook {
+ public:
+  ScopedCommitHook(sql::Connection& db,
+                   base::Callback<int(void)> cb)
+      : db_(db.db_),
+        cb_(cb) {
+    sql::sqlite3_commit_hook(db_, &Run, this);
+  }
+  ~ScopedCommitHook() {
+    sql::sqlite3_commit_hook(db_, NULL, NULL);
+  }
+
+ private:
+  static int Run(void* p) {
+    ScopedCommitHook* t = static_cast<ScopedCommitHook*>(p);
+    return t->cb_.Run();
+  }
+
+  sqlite3* db_;
+  base::Callback<int(void)> cb_;
+
+  DISALLOW_COPY_AND_ASSIGN(ScopedCommitHook);
+};
+
+}  // namespace test
+}  // namespace sql
+
 namespace {
 
 // Helper to return the count of items in sqlite_master.  Return -1 in
@@ -91,6 +210,10 @@ class ScopedUmaskSetter {
 class SQLConnectionTest : public testing::Test {
  public:
   void SetUp() override {
+    // Any macro histograms which fire before the recorder is initialized cannot
+    // be tested.  So this needs to be ahead of Open().
+    base::StatisticsRecorder::Initialize();
+
     ASSERT_TRUE(temp_dir_.CreateUniqueTempDir());
     db_path_ = temp_dir_.path().AppendASCII("SQLConnectionTest.db");
     ASSERT_TRUE(db_.Open(db_path_));
@@ -905,4 +1028,299 @@ TEST_F(SQLConnectionTest, Basic_FullIntegrityCheck) {
   // file that would pass the quick check and fail the full check.
 }
 
+// Test Sqlite.Stats histogram for execute-oriented calls.
+TEST_F(SQLConnectionTest, EventsExecute) {
+  // Re-open with histogram tag.
+  db().Close();
+  db().set_histogram_tag("Test");
+  ASSERT_TRUE(db().Open(db_path()));
+
+  // Open() uses Execute() extensively, don't track those calls.
+  base::HistogramTester tester;
+
+  const char kHistogramName[] = "Sqlite.Stats.Test";
+  const char kGlobalHistogramName[] = "Sqlite.Stats";
+
+  ASSERT_TRUE(db().BeginTransaction());
+  const char* kCreateSql = "CREATE TABLE foo (id INTEGER PRIMARY KEY, value)";
+  EXPECT_TRUE(db().Execute(kCreateSql));
+  EXPECT_TRUE(db().Execute("INSERT INTO foo VALUES (10, 'text')"));
+  EXPECT_TRUE(db().Execute("INSERT INTO foo VALUES (11, 'text')"));
+  EXPECT_TRUE(db().Execute("INSERT INTO foo VALUES (12, 'text')"));
+  EXPECT_TRUE(db().Execute("INSERT INTO foo VALUES (13, 'text')"));
+  EXPECT_TRUE(db().Execute("INSERT INTO foo VALUES (14, 'text')"));
+  EXPECT_TRUE(db().Execute("INSERT INTO foo VALUES (15, 'text');"
+                           "INSERT INTO foo VALUES (16, 'text');"
+                           "INSERT INTO foo VALUES (17, 'text');"
+                           "INSERT INTO foo VALUES (18, 'text');"
+                           "INSERT INTO foo VALUES (19, 'text')"));
+  ASSERT_TRUE(db().CommitTransaction());
+  ASSERT_TRUE(db().BeginTransaction());
+  EXPECT_TRUE(db().Execute("INSERT INTO foo VALUES (20, 'text')"));
+  db().RollbackTransaction();
+  EXPECT_TRUE(db().Execute("INSERT INTO foo VALUES (20, 'text')"));
+  EXPECT_TRUE(db().Execute("INSERT INTO foo VALUES (21, 'text')"));
+
+  // The create, 5 inserts, multi-statement insert, rolled-back insert, 2
+  // inserts outside transaction.
+  tester.ExpectBucketCount(kHistogramName, sql::Connection::EVENT_EXECUTE, 10);
+  tester.ExpectBucketCount(kGlobalHistogramName,
+                           sql::Connection::EVENT_EXECUTE, 10);
+
+  // All of the executes, with the multi-statement inserts broken out, plus one
+  // for each begin, commit, and rollback.
+  tester.ExpectBucketCount(kHistogramName,
+                           sql::Connection::EVENT_STATEMENT_RUN, 18);
+  tester.ExpectBucketCount(kGlobalHistogramName,
+                           sql::Connection::EVENT_STATEMENT_RUN, 18);
+
+  tester.ExpectBucketCount(kHistogramName,
+                           sql::Connection::EVENT_STATEMENT_ROWS, 0);
+  tester.ExpectBucketCount(kGlobalHistogramName,
+                           sql::Connection::EVENT_STATEMENT_ROWS, 0);
+  tester.ExpectBucketCount(kHistogramName,
+                           sql::Connection::EVENT_STATEMENT_SUCCESS, 18);
+  tester.ExpectBucketCount(kGlobalHistogramName,
+                           sql::Connection::EVENT_STATEMENT_SUCCESS, 18);
+
+  // The 2 inserts outside the transaction.
+  tester.ExpectBucketCount(kHistogramName,
+                           sql::Connection::EVENT_CHANGES_AUTOCOMMIT, 2);
+  tester.ExpectBucketCount(kGlobalHistogramName,
+                           sql::Connection::EVENT_CHANGES_AUTOCOMMIT, 2);
+
+  // 11 inserts inside transactions.
+  tester.ExpectBucketCount(kHistogramName, sql::Connection::EVENT_CHANGES, 11);
+  tester.ExpectBucketCount(kGlobalHistogramName,
+                           sql::Connection::EVENT_CHANGES, 11);
+
+  tester.ExpectBucketCount(kHistogramName, sql::Connection::EVENT_BEGIN, 2);
+  tester.ExpectBucketCount(kGlobalHistogramName,
+                           sql::Connection::EVENT_BEGIN, 2);
+  tester.ExpectBucketCount(kHistogramName, sql::Connection::EVENT_COMMIT, 1);
+  tester.ExpectBucketCount(kGlobalHistogramName,
+                           sql::Connection::EVENT_COMMIT, 1);
+  tester.ExpectBucketCount(kHistogramName, sql::Connection::EVENT_ROLLBACK, 1);
+  tester.ExpectBucketCount(kGlobalHistogramName,
+                           sql::Connection::EVENT_ROLLBACK, 1);
+}
+
+// Test Sqlite.Stats histogram for prepared statements.
+TEST_F(SQLConnectionTest, EventsStatement) {
+  // Re-open with histogram tag.
+  db().Close();
+  db().set_histogram_tag("Test");
+  ASSERT_TRUE(db().Open(db_path()));
+
+  const char kHistogramName[] = "Sqlite.Stats.Test";
+  const char kGlobalHistogramName[] = "Sqlite.Stats";
+
+  const char* kCreateSql = "CREATE TABLE foo (id INTEGER PRIMARY KEY, value)";
+  EXPECT_TRUE(db().Execute(kCreateSql));
+  EXPECT_TRUE(db().Execute("INSERT INTO foo VALUES (10, 'text')"));
+  EXPECT_TRUE(db().Execute("INSERT INTO foo VALUES (11, 'text')"));
+  EXPECT_TRUE(db().Execute("INSERT INTO foo VALUES (12, 'text')"));
+
+  {
+    base::HistogramTester tester;
+
+    {
+      sql::Statement s(db().GetUniqueStatement("SELECT value FROM foo"));
+      while (s.Step()) {
+      }
+    }
+
+    tester.ExpectBucketCount(kHistogramName,
+                             sql::Connection::EVENT_STATEMENT_RUN, 1);
+    tester.ExpectBucketCount(kGlobalHistogramName,
+                             sql::Connection::EVENT_STATEMENT_RUN, 1);
+    tester.ExpectBucketCount(kHistogramName,
+                             sql::Connection::EVENT_STATEMENT_ROWS, 3);
+    tester.ExpectBucketCount(kGlobalHistogramName,
+                             sql::Connection::EVENT_STATEMENT_ROWS, 3);
+    tester.ExpectBucketCount(kHistogramName,
+                             sql::Connection::EVENT_STATEMENT_SUCCESS, 1);
+    tester.ExpectBucketCount(kGlobalHistogramName,
+                             sql::Connection::EVENT_STATEMENT_SUCCESS, 1);
+  }
+
+  {
+    base::HistogramTester tester;
+
+    {
+      sql::Statement s(db().GetUniqueStatement(
+          "SELECT value FROM foo WHERE id > 10"));
+      while (s.Step()) {
+      }
+    }
+
+    tester.ExpectBucketCount(kHistogramName,
+                             sql::Connection::EVENT_STATEMENT_RUN, 1);
+    tester.ExpectBucketCount(kGlobalHistogramName,
+                             sql::Connection::EVENT_STATEMENT_RUN, 1);
+    tester.ExpectBucketCount(kHistogramName,
+                             sql::Connection::EVENT_STATEMENT_ROWS, 2);
+    tester.ExpectBucketCount(kGlobalHistogramName,
+                             sql::Connection::EVENT_STATEMENT_ROWS, 2);
+    tester.ExpectBucketCount(kHistogramName,
+                             sql::Connection::EVENT_STATEMENT_SUCCESS, 1);
+    tester.ExpectBucketCount(kGlobalHistogramName,
+                             sql::Connection::EVENT_STATEMENT_SUCCESS, 1);
+  }
+}
+
+// SQLite function to adjust mock time by |argv[0]| milliseconds.
+void sqlite_adjust_millis(sql::test::ScopedMockTimeSource* time_mock,
+                          sqlite3_context* context,
+                          int argc, sqlite3_value** argv) {
+  int64 milliseconds = argc > 0 ? sqlite3_value_int64(argv[0]) : 1000;
+  time_mock->adjust(base::TimeDelta::FromMilliseconds(milliseconds));
+  sqlite3_result_int64(context, milliseconds);
+}
+
+// Adjust mock time by |milliseconds| on commit.
+int adjust_commit_hook(sql::test::ScopedMockTimeSource* time_mock,
+                       int64 milliseconds) {
+  time_mock->adjust(base::TimeDelta::FromMilliseconds(milliseconds));
+  return SQLITE_OK;
+}
+
+const char kCommitTime[] = "Sqlite.CommitTime.Test";
+const char kAutoCommitTime[] = "Sqlite.AutoCommitTime.Test";
+const char kUpdateTime[] = "Sqlite.UpdateTime.Test";
+const char kQueryTime[] = "Sqlite.QueryTime.Test";
+
+// Read-only query allocates time to QueryTime, but not others.
+TEST_F(SQLConnectionTest, TimeQuery) {
+  // Re-open with histogram tag.  Use an in-memory database to minimize variance
+  // due to filesystem.
+  db().Close();
+  db().set_histogram_tag("Test");
+  ASSERT_TRUE(db().OpenInMemory());
+
+  sql::test::ScopedMockTimeSource time_mock(db());
+
+  const char* kCreateSql = "CREATE TABLE foo (id INTEGER PRIMARY KEY, value)";
+  EXPECT_TRUE(db().Execute(kCreateSql));
+
+  // Function to inject pauses into statements.
+  sql::test::ScopedScalarFunction scoper(
+      db(), "milliadjust", 1, base::Bind(&sqlite_adjust_millis, &time_mock));
+
+  base::HistogramTester tester;
+
+  EXPECT_TRUE(db().Execute("SELECT milliadjust(10)"));
+
+  scoped_ptr<base::HistogramSamples> samples(
+      tester.GetHistogramSamplesSinceCreation(kQueryTime));
+  ASSERT_TRUE(samples);
+  // 10 for the adjust, 1 for the measurement.
+  EXPECT_EQ(11, samples->sum());
+
+  samples = tester.GetHistogramSamplesSinceCreation(kUpdateTime);
+  EXPECT_TRUE(!samples || samples->sum() == 0);
+
+  samples = tester.GetHistogramSamplesSinceCreation(kCommitTime);
+  EXPECT_TRUE(!samples || samples->sum() == 0);
+
+  samples = tester.GetHistogramSamplesSinceCreation(kAutoCommitTime);
+  EXPECT_TRUE(!samples || samples->sum() == 0);
+}
+
+// Autocommit update allocates time to QueryTime, UpdateTime, and
+// AutoCommitTime.
+TEST_F(SQLConnectionTest, TimeUpdateAutocommit) {
+  // Re-open with histogram tag.  Use an in-memory database to minimize variance
+  // due to filesystem.
+  db().Close();
+  db().set_histogram_tag("Test");
+  ASSERT_TRUE(db().OpenInMemory());
+
+  sql::test::ScopedMockTimeSource time_mock(db());
+
+  const char* kCreateSql = "CREATE TABLE foo (id INTEGER PRIMARY KEY, value)";
+  EXPECT_TRUE(db().Execute(kCreateSql));
+
+  // Function to inject pauses into statements.
+  sql::test::ScopedScalarFunction scoper(
+      db(), "milliadjust", 1, base::Bind(&sqlite_adjust_millis, &time_mock));
+
+  base::HistogramTester tester;
+
+  EXPECT_TRUE(db().Execute("INSERT INTO foo VALUES (10, milliadjust(10))"));
+
+  scoped_ptr<base::HistogramSamples> samples(
+      tester.GetHistogramSamplesSinceCreation(kQueryTime));
+  ASSERT_TRUE(samples);
+  // 10 for the adjust, 1 for the measurement.
+  EXPECT_EQ(11, samples->sum());
+
+  samples = tester.GetHistogramSamplesSinceCreation(kUpdateTime);
+  ASSERT_TRUE(samples);
+  // 10 for the adjust, 1 for the measurement.
+  EXPECT_EQ(11, samples->sum());
+
+  samples = tester.GetHistogramSamplesSinceCreation(kCommitTime);
+  EXPECT_TRUE(!samples || samples->sum() == 0);
+
+  samples = tester.GetHistogramSamplesSinceCreation(kAutoCommitTime);
+  ASSERT_TRUE(samples);
+  // 10 for the adjust, 1 for the measurement.
+  EXPECT_EQ(11, samples->sum());
+}
+
+// Update with explicit transaction allocates time to QueryTime, UpdateTime, and
+// CommitTime.
+TEST_F(SQLConnectionTest, TimeUpdateTransaction) {
+  // Re-open with histogram tag.  Use an in-memory database to minimize variance
+  // due to filesystem.
+  db().Close();
+  db().set_histogram_tag("Test");
+  ASSERT_TRUE(db().OpenInMemory());
+
+  sql::test::ScopedMockTimeSource time_mock(db());
+
+  const char* kCreateSql = "CREATE TABLE foo (id INTEGER PRIMARY KEY, value)";
+  EXPECT_TRUE(db().Execute(kCreateSql));
+
+  // Function to inject pauses into statements.
+  sql::test::ScopedScalarFunction scoper(
+      db(), "milliadjust", 1, base::Bind(&sqlite_adjust_millis, &time_mock));
+
+  base::HistogramTester tester;
+
+  {
+    // Make the commit slow.
+    sql::test::ScopedCommitHook scoped_hook(
+        db(), base::Bind(adjust_commit_hook, &time_mock, 100));
+    ASSERT_TRUE(db().BeginTransaction());
+    EXPECT_TRUE(db().Execute(
+        "INSERT INTO foo VALUES (11, milliadjust(10))"));
+    EXPECT_TRUE(db().Execute(
+        "UPDATE foo SET value = milliadjust(10) WHERE id = 11"));
+    EXPECT_TRUE(db().CommitTransaction());
+  }
+
+  scoped_ptr<base::HistogramSamples> samples(
+      tester.GetHistogramSamplesSinceCreation(kQueryTime));
+  ASSERT_TRUE(samples);
+  // 10 for insert adjust, 10 for update adjust, 100 for commit adjust, 1 for
+  // measuring each of BEGIN, INSERT, UPDATE, and COMMIT.
+  EXPECT_EQ(124, samples->sum());
+
+  samples = tester.GetHistogramSamplesSinceCreation(kUpdateTime);
+  ASSERT_TRUE(samples);
+  // 10 for insert adjust, 10 for update adjust, 100 for commit adjust, 1 for
+  // measuring each of INSERT, UPDATE, and COMMIT.
+  EXPECT_EQ(123, samples->sum());
+
+  samples = tester.GetHistogramSamplesSinceCreation(kCommitTime);
+  ASSERT_TRUE(samples);
+  // 100 for commit adjust, 1 for measuring COMMIT.
+  EXPECT_EQ(101, samples->sum());
+
+  samples = tester.GetHistogramSamplesSinceCreation(kAutoCommitTime);
+  EXPECT_TRUE(!samples || samples->sum() == 0);
+}
+
 }  // namespace
diff --git a/sql/proxy.cc b/sql/proxy.cc
new file mode 100644
index 0000000..5104812
--- /dev/null
+++ b/sql/proxy.cc
@@ -0,0 +1,28 @@
+// Copyright 2015 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/proxy.h"
+
+namespace sql {
+
+int sqlite3_create_function_v2(
+    sqlite3 *db,
+    const char *zFunctionName,
+    int nArg,
+    int eTextRep,
+    void *pApp,
+    void (*xFunc)(sqlite3_context*,int,sqlite3_value**),
+    void (*xStep)(sqlite3_context*,int,sqlite3_value**),
+    void (*xFinal)(sqlite3_context*),
+    void (*xDestroy)(void*)) {
+  return ::sqlite3_create_function_v2(
+      db, zFunctionName, nArg, eTextRep, pApp,
+      xFunc, xStep, xFinal, xDestroy);
+}
+
+void *sqlite3_commit_hook(sqlite3* db, int(*func)(void*), void* arg) {
+  return ::sqlite3_commit_hook(db, func, arg);
+}
+
+}  // namespace sql
diff --git a/sql/proxy.h b/sql/proxy.h
new file mode 100644
index 0000000..7a2863b
--- /dev/null
+++ b/sql/proxy.h
@@ -0,0 +1,39 @@
+// Copyright 2015 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.
+
+#ifndef SQL_PROXY_H_
+#define SQL_PROXY_H_
+
+#include "sql/sql_export.h"
+#include "third_party/sqlite/sqlite3.h"
+
+// TODO(shess): third_party/sqlite does not track component build correctly, so
+// each shared library gets a private copy of everything, so sqlite3_* calls
+// outside of the main sql/ component don't work right.  Hack around this by
+// adding pass-through functions while I land a separate fix for the component
+// issue.
+
+// This is only required for tests - if these abilities are desired for
+// production code, they should probably do obvious things like live in
+// sql::Connection and use C++ wrappers.
+
+// http://crbug.com/489444
+
+namespace sql {
+
+SQL_EXPORT int sqlite3_create_function_v2(
+    sqlite3 *db,
+    const char *zFunctionName,
+    int nArg,
+    int eTextRep,
+    void *pApp,
+    void (*xFunc)(sqlite3_context*,int,sqlite3_value**),
+    void (*xStep)(sqlite3_context*,int,sqlite3_value**),
+    void (*xFinal)(sqlite3_context*),
+    void (*xDestroy)(void*));
+SQL_EXPORT void *sqlite3_commit_hook(sqlite3*, int(*)(void*), void*);
+
+}  // namespace sql
+
+#endif  // SQL_PROXY_H_
diff --git a/sql/sql.gyp b/sql/sql.gyp
index 825d3d0..fae8ece 100644
--- a/sql/sql.gyp
+++ b/sql/sql.gyp
@@ -27,6 +27,8 @@
         'init_status.h',
         'meta_table.cc',
         'meta_table.h',
+        'proxy.cc',
+        'proxy.h',
         'recovery.cc',
         'recovery.h',
         'statement.cc',
diff --git a/sql/statement.cc b/sql/statement.cc
index 42b4598..038ebde 100644
--- a/sql/statement.cc
+++ b/sql/statement.cc
@@ -51,34 +51,63 @@ bool Statement::CheckValid() const {
   return is_valid();
 }
 
-bool Statement::Run() {
-  DCHECK(!stepped_);
+int Statement::StepInternal(bool timer_flag) {
   ref_->AssertIOAllowed();
   if (!CheckValid())
-    return false;
+    return SQLITE_ERROR;
 
+  const bool was_stepped = stepped_;
   stepped_ = true;
-  return CheckError(sqlite3_step(ref_->stmt())) == SQLITE_DONE;
+  int ret = SQLITE_ERROR;
+  if (!ref_->connection()) {
+    ret = sqlite3_step(ref_->stmt());
+  } else {
+    if (!timer_flag) {
+      ret = sqlite3_step(ref_->stmt());
+    } else {
+      const base::TimeTicks before = ref_->connection()->Now();
+      ret = sqlite3_step(ref_->stmt());
+      const base::TimeTicks after = ref_->connection()->Now();
+      const bool read_only = !!sqlite3_stmt_readonly(ref_->stmt());
+      ref_->connection()->RecordTimeAndChanges(after - before, read_only);
+    }
+
+    if (!was_stepped)
+      ref_->connection()->RecordOneEvent(Connection::EVENT_STATEMENT_RUN);
+
+    if (ret == SQLITE_ROW)
+      ref_->connection()->RecordOneEvent(Connection::EVENT_STATEMENT_ROWS);
+  }
+  return CheckError(ret);
 }
 
-bool Statement::Step() {
-  ref_->AssertIOAllowed();
-  if (!CheckValid())
-    return false;
+bool Statement::Run() {
+  DCHECK(!stepped_);
+  return StepInternal(true) == SQLITE_DONE;
+}
 
-  stepped_ = true;
-  return CheckError(sqlite3_step(ref_->stmt())) == SQLITE_ROW;
+bool Statement::RunWithoutTimers() {
+  DCHECK(!stepped_);
+  return StepInternal(false) == SQLITE_DONE;
+}
+
+bool Statement::Step() {
+  return StepInternal(true) == SQLITE_ROW;
 }
 
 void Statement::Reset(bool clear_bound_vars) {
   ref_->AssertIOAllowed();
   if (is_valid()) {
-    // We don't call CheckError() here because sqlite3_reset() returns
-    // the last error that Step() caused thereby generating a second
-    // spurious error callback.
     if (clear_bound_vars)
       sqlite3_clear_bindings(ref_->stmt());
-    sqlite3_reset(ref_->stmt());
+
+    // StepInternal() cannot track success because statements may be reset
+    // before reaching SQLITE_DONE.  Don't call CheckError() because
+    // sqlite3_reset() returns the last step error, which StepInternal() already
+    // checked.
+    const int rc =sqlite3_reset(ref_->stmt());
+    if (rc == SQLITE_OK && ref_->connection())
+      ref_->connection()->RecordOneEvent(Connection::EVENT_STATEMENT_SUCCESS);
   }
 
   succeeded_ = false;
diff --git a/sql/statement.h b/sql/statement.h
index b411e80..83a5a2d 100644
--- a/sql/statement.h
+++ b/sql/statement.h
@@ -150,6 +150,8 @@ class SQL_EXPORT Statement {
   const char* GetSQLStatement();
 
  private:
+  friend class Connection;
+
   // This is intended to check for serious errors and report them to the
   // connection object. It takes a sqlite error code, and returns the same
   // code. Currently this function just updates the succeeded flag, but will be
@@ -174,6 +176,16 @@ class SQL_EXPORT Statement {
   // ensuring that contracts are honored in error edge cases.
   bool CheckValid() const;
 
+  // Helper for Run() and Step(), calls sqlite3_step() and then generates
+  // sql::Connection histograms based on the results.  Timing and change count
+  // are only recorded if |timer_flag| is true.  The checked value from
+  // sqlite3_step() is returned.
+  int StepInternal(bool timer_flag);
+
+  // sql::Connection uses cached statments for transactions, but tracks their
+  // runtime independently.
+  bool RunWithoutTimers();
+
   // The actual sqlite statement. This may be unique to us, or it may be cached
   // by the connection, which is why it's refcounted. This pointer is
   // guaranteed non-NULL.