[sql] Stats gathering for sql/ APIs.

sql/connection_unittest.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 "base/bind.h"
 #include "base/files/file_util.h"
 #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"
 #include "sql/test/test_helpers.h"
 #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) {
   const char* kMasterCount = "SELECT COUNT(*) FROM sqlite_master";
   sql::Statement s(db->GetUniqueStatement(kMasterCount));
   return s.Step() ? s.ColumnInt(0) : -1;
 }
 
 // Track the number of valid references which share the same pointer.
 // This is used to allow testing an implicitly use-after-free case by
@@ skipping 53 matching lines @@
   ~ScopedUmaskSetter() { umask(old_umask_); }
  private:
   mode_t old_umask_;
   DISALLOW_IMPLICIT_CONSTRUCTORS(ScopedUmaskSetter);
 };
 #endif
 
 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_));
   }
 
   void TearDown() override { db_.Close(); }
 
   sql::Connection& db() { return db_; }
   const base::FilePath& db_path() { return db_path_; }
 
@@ skipping 794 matching lines @@
     EXPECT_TRUE(db().FullIntegrityCheck(&messages));
     EXPECT_LT(1u, messages.size());
     EXPECT_NE(kOk, messages[0]);
     ASSERT_TRUE(ignore_errors.CheckIgnoredErrors());
   }
 
   // TODO(shess): CorruptTableOrIndex could be used to produce a
   // 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.
+  db().Close();
+  db().set_histogram_tag("Test");
+  ASSERT_TRUE(db().Open(db_path()));
+
+  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