debuginfod: sqlite3 metrics

Add metrics for tracking sqlite3 error counts and query performance.

The former looks like a new sibling of the "error_count" family, and
is tested by dd-corrupting a live database file then triggering some
debuginfod activity.

    error_count{sqlite3="file is not a database"} 1

The latter looks like _count/_sum pairs for each type of sqlite
prepared-statement used in the code, and is grep smoke-tested.  They
should assist a sysadmin in tuning db storage.  This example shows a
6.4 ms/operation cost:

    sqlite3_milliseconds_count{step-done="rpm-file-intern"} 318
    sqlite3_milliseconds_sum{reset="rpm-file-intern"} 2033

Signed-off-by: Frank Ch. Eigler <fche@redhat.com>

diff --git a/debuginfod/ChangeLog b/debuginfod/ChangeLog
index cd009fd..576b667 100644 (file)
--- a/debuginfod/ChangeLog
+++ b/debuginfod/ChangeLog
@@ -3,6 +3,12 @@
        * debuginfod-client.c (debuginfod_query_server): Initialize
        struct handle_data errbuf to the empty string.
 
+2020-11-23  Frank Ch. Eigler  <fche@redhat.com>
+
+       * debuginfod.cxx (tmp_ms_metric): New class for RAII timing metrics.
+       (sqlite_ps::reset, step*): Call it to track sqlite3 performance.
+       (sqlite_exception ctor): Increment sqlite3 error_count.
+
 2020-11-11  Mark Wielaard  <mark@klomp.org>
 
        * debuginfod-client.c (debuginfod_set_verbose_fd): New function.

diff --git a/debuginfod/debuginfod.cxx b/debuginfod/debuginfod.cxx
index 61c778b..618620b 100644 (file)
--- a/debuginfod/debuginfod.cxx
+++ b/debuginfod/debuginfod.cxx
@@ -435,6 +435,27 @@ public:
   }
 };
 
+class tmp_ms_metric { // a RAII style wrapper for exception-safe scoped timing
+  string m, n, v;
+  struct timeval tv_start;
+public:
+  tmp_ms_metric(const string& mname, const string& lname, const string& lvalue):
+    m(mname), n(lname), v(lvalue)
+  {
+    gettimeofday (& tv_start, NULL);
+  }
+  ~tmp_ms_metric()
+  {
+    struct timeval tv_end;
+    gettimeofday (& tv_end, NULL);
+    double deltas = (tv_end.tv_sec - tv_start.tv_sec)
+      + (tv_end.tv_usec - tv_start.tv_usec)*0.000001;
+
+    add_metric (m + "_milliseconds_sum", n, v, (deltas*1000));
+    inc_metric (m + "_milliseconds_count", n, v);
+  }
+};
+
 
 /* Handle program arguments.  */
 static error_t
@@ -559,7 +580,9 @@ struct reportable_exception
 struct sqlite_exception: public reportable_exception
 {
   sqlite_exception(int rc, const string& msg):
-    reportable_exception(string("sqlite3 error: ") + msg + ": " + string(sqlite3_errstr(rc) ?: "?")) {}
+    reportable_exception(string("sqlite3 error: ") + msg + ": " + string(sqlite3_errstr(rc) ?: "?")) {
+    inc_metric("error_count","sqlite3",sqlite3_errstr(rc));    
+  }
 };
 
 struct libc_exception: public reportable_exception
@@ -755,6 +778,7 @@ private:
 
 public:
   sqlite_ps (sqlite3* d, const string& n, const string& s): db(d), nickname(n), sql(s) {
+    // tmp_ms_metric tick("sqlite3","prep",nickname);
     if (verbose > 4)
       obatched(clog) << nickname << " prep " << sql << endl;
     int rc = sqlite3_prepare_v2 (db, sql.c_str(), -1 /* to \0 */, & this->pp, NULL);
@@ -764,6 +788,7 @@ public:
 
   sqlite_ps& reset()
   {
+    tmp_ms_metric tick("sqlite3","reset",nickname);
     sqlite3_reset(this->pp);
     return *this;
   }
@@ -800,6 +825,7 @@ public:
 
 
   void step_ok_done() {
+    tmp_ms_metric tick("sqlite3","step-done",nickname);
     int rc = sqlite3_step (this->pp);
     if (verbose > 4)
       obatched(clog) << nickname << " step-ok-done(" << sqlite3_errstr(rc) << ") " << sql << endl;
@@ -810,14 +836,13 @@ public:
 
 
   int step() {
+    tmp_ms_metric tick("sqlite3","step",nickname);
     int rc = sqlite3_step (this->pp);
     if (verbose > 4)
       obatched(clog) << nickname << " step(" << sqlite3_errstr(rc) << ") " << sql << endl;
     return rc;
   }
 
-
-
   ~sqlite_ps () { sqlite3_finalize (this->pp); }
   operator sqlite3_stmt* () { return this->pp; }
 };

diff --git a/tests/ChangeLog b/tests/ChangeLog
index c130ce0..f5adc31 100644 (file)
--- a/tests/ChangeLog
+++ b/tests/ChangeLog
@@ -1,3 +1,7 @@
+2020-11-23  Frank Ch. Eigler  <fche@redhat.com>
+
+       * run-debuginfod-find.sh: Add sqlite error injection & stats.
+
 2020-11-02  Mark Wielaard  <mark@klomp.org>
 
        * run-debuginfod-find.sh: Create bogus R/nothing.rpm with cyclic

diff --git a/tests/run-debuginfod-find.sh b/tests/run-debuginfod-find.sh
index 28aa426..7fd3420 100755 (executable)
--- a/tests/run-debuginfod-find.sh
+++ b/tests/run-debuginfod-find.sh
@@ -491,6 +491,22 @@ curl -s http://127.0.0.1:$PORT2/buildid/deadbeef/debuginfo > /dev/null || true
 
 
 ########################################################################
+# Corrupt the sqlite database and get debuginfod to trip across its errors
+curl -s http://127.0.0.1:$PORT1/metrics | grep 'sqlite3.*reset'
+ls -al $DB
+dd if=/dev/zero of=$DB bs=1 count=1
+ls -al $DB
+# trigger some random activity that's Sure to get sqlite3 upset
+kill -USR1 $PID1
+wait_ready $PORT1 'thread_work_total{role="traverse"}' 9
+wait_ready $PORT1 'thread_work_pending{role="scan"}' 0
+wait_ready $PORT1 'thread_busy{role="scan"}' 0
+kill -USR2 $PID1
+wait_ready $PORT1 'thread_work_total{role="groom"}' 4
+curl -s http://127.0.0.1:$PORT1/buildid/beefbeefbeefd00dd00d/debuginfo > /dev/null || true
+curl -s http://127.0.0.1:$PORT1/metrics | grep 'error_count.*sqlite'
+
+########################################################################
 
 # Run the tests again without the servers running. The target file should
 # be found in the cache.