[sql] Stats gathering for sql/ APIs.

sql/connection_unittest.cc

Index: sql/connection_unittest.cc
diff --git a/sql/connection_unittest.cc b/sql/connection_unittest.cc
index e3b97739ed1cc9ceb7b058ab361c2e67e6084157..2cc0f668f520cd2c0452d34aefd8106dbafe6d8c 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,8 +19,75 @@
 #include "testing/gtest/include/gtest/gtest.h"
 #include "third_party/sqlite/sqlite3.h"
 
+namespace sql {
+namespace test {
+
+// 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,
+                       void (*func)(sqlite3_context*,int,sqlite3_value**))
+      : db_(db.db_), function_name_(function_name) {
+    sql::sqlite3_create_function_v2(db_, function_name, args, SQLITE_UTF8,
+                                    NULL, func, NULL, NULL, NULL);
+  }
+  ~ScopedScalarFunction() {
+    sql::sqlite3_create_function_v2(db_, function_name_, 0, SQLITE_UTF8,
+                                    NULL, NULL, NULL, NULL, NULL);
+  }
+
+ private:
+  sqlite3* db_;
+  const char* function_name_;
+
+  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, int(*func)(void*), void* arg)
+      : db_(db.db_) {
+    sql::sqlite3_commit_hook(db_, func, arg);
+  }
+  ~ScopedCommitHook() {
+    sql::sqlite3_commit_hook(db_, NULL, NULL);
+  }
+
+ private:
+  sqlite3* db_;
+
+  DISALLOW_COPY_AND_ASSIGN(ScopedCommitHook);
+};
+
+}  // namespace test
+}  // namespace sql
+
 namespace {
 
+// Construct an EXPECT_BETWEEN() macro.
+::testing::AssertionResult IntBetweenPredFormat(const char* expr_low,
+                                                const char* expr_target,
+                                                const char* expr_high,
+                                                int low,
+                                                int target,
+                                                int high) {
+  if (low <= target && target < high)
+    return ::testing::AssertionSuccess();
+
+  return ::testing::AssertionFailure()
+      << "Expected: (" << expr_low << ") <= (" << expr_target
+      << ") < (" << expr_high << "), where\n"
+      << expr_low << " evaluates to " << low << ",\n"
+      << expr_target << " evaluates to " << target << ",\n"
+      << expr_high << " evaluates to " << high << ".";
+}
+#define EXPECT_BETWEEN(low, target, high)        \
+  EXPECT_PRED_FORMAT3(IntBetweenPredFormat, low, target, high)
+
+
 // Helper to return the count of items in sqlite_master.  Return -1 in
 // case of error.
 int SqliteMasterCount(sql::Connection* db) {
@@ -91,6 +161,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 +979,266 @@ 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 sleep for the passed number of milliseconds.
+void sqlite_sleep(sqlite3_context* context, int argc, sqlite3_value** argv) {
+  int milliseconds = argc > 0 ? sqlite3_value_int(argv[0]) : 1000;
+  base::PlatformThread::Sleep(base::TimeDelta::FromMilliseconds(milliseconds));
+  sqlite3_result_int(context, milliseconds);
+}
+
+// Sleep for a set period of time at commit.
+int sleep_commit_hook(void* arg) {
+  int64 milliseconds = reinterpret_cast<int64>(arg);
+  base::PlatformThread::Sleep(base::TimeDelta::FromMilliseconds(milliseconds));
+  return SQLITE_OK;
+}
+
+// Test Sqlite.*Time histograms.
+TEST_F(SQLConnectionTest, Times) {
+  // 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());

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

I am having second thoughts about this test.  I wanted something to validate
that the timers were timing things, which is necessarily a bit heuristic, I
think (without some injection, I suppose).  Using a 10% safety net was fine on
all platforms except Android, which was slightly slower than that.  Removing the
filesystem from the equation looks a lot better, but ...

I think the options available would be to increase the sleep times to be enough
greater than the non-sleep overhead that it's more reliable, or to loosen the
upper bound, or perhaps even to only enable the test on a small number of
platforms which have high confidence of not being flaky.

I was aiming for high confidence that it would catch both "The time wasn't
measured at all" and "The time was measured twice", so in the single-sleep cases
100-175ish might work well, maybe the double-sleep case can just reduce to the
commit-time sleep, and assume that the other flows are correct.

[rmcilroy, 2015/05/22 08:48:23]

Yeah I agree, I was a bit worried about these tests being flaky too. One option
would be to make it possible for the sql layer to use an injected time source,
then the tests could set this time source to be a mock time source and your
tests can be deterministic. If you look at how we do this in
renderer_scheduler_impl_unittest.cc and
SchedulerHelper::SetTimeSourceForTesting().
      

[Scott Hess - ex-Googler, 2015/05/22 21:22:14]

OK, most recent patch mocks out the time source.  I like the better precision in
the tests.  It feels a little egregious implementation-wise, but I guess if this
prevents rollback due to flakiness, that's a positive!

+
+  const char kCommitTime[] = "Sqlite.CommitTime.Test";
+  const char kAutoCommitTime[] = "Sqlite.AutoCommitTime.Test";
+  const char kUpdateTime[] = "Sqlite.UpdateTime.Test";
+  const char kQueryTime[] = "Sqlite.QueryTime.Test";
+
+  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(), "millisleep", 1, sqlite_sleep);
+
+  // Test that SQLite isn't just super slow.
+  {
+    base::HistogramTester tester;
+
+    EXPECT_TRUE(db().Execute("SELECT millisleep(1)"));
+
+    scoped_ptr<base::HistogramSamples> samples(
+        tester.GetHistogramSamplesSinceCreation(kQueryTime));
+    ASSERT_TRUE(samples);
+    EXPECT_BETWEEN(0, samples->sum(), 10);
+  }
+
+  // Read-only query allocates time to query, but not others.
+  {
+    base::HistogramTester tester;
+
+    EXPECT_TRUE(db().Execute("SELECT millisleep(100)"));
+
+    scoped_ptr<base::HistogramSamples> samples(
+        tester.GetHistogramSamplesSinceCreation(kQueryTime));
+    ASSERT_TRUE(samples);
+    EXPECT_BETWEEN(100, samples->sum(), 110);
+
+    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 query allocates time to query, update, and autocommit.
+  {
+    base::HistogramTester tester;
+
+    EXPECT_TRUE(db().Execute("INSERT INTO foo VALUES (10, millisleep(100))"));
+
+    scoped_ptr<base::HistogramSamples> samples(
+        tester.GetHistogramSamplesSinceCreation(kQueryTime));
+    ASSERT_TRUE(samples);
+    EXPECT_BETWEEN(100, samples->sum(), 110);
+
+    samples = tester.GetHistogramSamplesSinceCreation(kUpdateTime);
+    ASSERT_TRUE(samples);
+    EXPECT_BETWEEN(100, samples->sum(), 110);
+
+    samples = tester.GetHistogramSamplesSinceCreation(kCommitTime);
+    EXPECT_TRUE(!samples || samples->sum() == 0);
+
+    samples = tester.GetHistogramSamplesSinceCreation(kAutoCommitTime);
+    ASSERT_TRUE(samples);
+    EXPECT_BETWEEN(100, samples->sum(), 110);
+  }
+
+  // Explicit transaction allocates query time to query and update, and commit
+  // time to all three.
+  {
+    base::HistogramTester tester;
+
+    {
+      // Make the commit slow.
+      sql::test::ScopedCommitHook scoped_hook(
+          db(), sleep_commit_hook, reinterpret_cast<void*>(100));
+      ASSERT_TRUE(db().BeginTransaction());
+      EXPECT_TRUE(db().Execute("INSERT INTO foo VALUES (11, millisleep(100))"));
+      EXPECT_TRUE(db().CommitTransaction());
+    }
+
+    scoped_ptr<base::HistogramSamples> samples(
+        tester.GetHistogramSamplesSinceCreation(kQueryTime));
+    ASSERT_TRUE(samples);
+    EXPECT_BETWEEN(200, samples->sum(), 220);
+
+    samples = tester.GetHistogramSamplesSinceCreation(kUpdateTime);
+    ASSERT_TRUE(samples);
+    EXPECT_BETWEEN(200, samples->sum(), 220);
+
+    samples = tester.GetHistogramSamplesSinceCreation(kCommitTime);
+    ASSERT_TRUE(samples);
+    EXPECT_BETWEEN(100, samples->sum(), 110);
+
+    samples = tester.GetHistogramSamplesSinceCreation(kAutoCommitTime);
+    EXPECT_TRUE(!samples || samples->sum() == 0);
+  }
+}
+
 }  // namespace