Hi -
>From 0b61f4c758a507fcc2243357363e44140bd13d82 Mon Sep 17 00:00:00 2001 ?!??!!
From: "Frank Ch. Eigler" <f...@redhat.com>
Date: Mon, 23 Nov 2020 19:58:10 -0500
Subject: [PATCH] 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 <f...@redhat.com>
---
debuginfod/ChangeLog | 6 ++++++
debuginfod/debuginfod.cxx | 31 ++++++++++++++++++++++++++++---
tests/ChangeLog | 4 ++++
tests/run-debuginfod-find.sh | 16 ++++++++++++++++
4 files changed, 54 insertions(+), 3 deletions(-)
diff --git a/debuginfod/ChangeLog b/debuginfod/ChangeLog
index bd4dbf403f30..a81e3781986d 100644
--- a/debuginfod/ChangeLog
+++ b/debuginfod/ChangeLog
@@ -1,3 +1,9 @@
+2020-11-23 Frank Ch. Eigler <f...@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 <m...@klomp.org>
* debuginfod-client.c (debuginfod_set_verbose_fd): New function.
diff --git a/debuginfod/debuginfod.cxx b/debuginfod/debuginfod.cxx
index 61c778b10893..618620b4c478 100644
--- a/debuginfod/debuginfod.cxx
+++ b/debuginfod/debuginfod.cxx
@@ -435,6 +435,27 @@ class tmp_inc_metric { // a RAII style wrapper for
exception-safe scoped increme
}
};
+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 @@ struct sqlite_ps
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 @@ struct sqlite_ps
sqlite_ps& reset()
{
+ tmp_ms_metric tick("sqlite3","reset",nickname);
sqlite3_reset(this->pp);
return *this;
}
@@ -800,6 +825,7 @@ struct sqlite_ps
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 @@ struct sqlite_ps
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 c130ce049caa..f5adc315ae38 100644
--- a/tests/ChangeLog
+++ b/tests/ChangeLog
@@ -1,3 +1,7 @@
+2020-11-23 Frank Ch. Eigler <f...@redhat.com>
+
+ * run-debuginfod-find.sh: Add sqlite error injection & stats.
+
2020-11-02 Mark Wielaard <m...@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 28aa4263c500..7fd3420ab20a 100755
--- a/tests/run-debuginfod-find.sh
+++ b/tests/run-debuginfod-find.sh
@@ -490,6 +490,22 @@ curl -s http://127.0.0.1:$PORT2/badapi > /dev/null || true
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
--
2.28.0
