Re: Remove nested functions from libdwfl V2

[Mark Wielaard]

Hi Timm,

On Mon, 2020-11-23 at 13:27 +0100, Timm Bäder via Elfutils-devel wrote:
> version 2 of this patch set. I removed segmend_read() entirely now,
> which meant modifying a bunch of later patches. Other than that, they
> are the same.
> 
> Hope the --from to git send-email worked out, too.

It did, thanks.

I immediately picked up 9 of these patches that clearly looked like
they improved the code. I added ChangeLog entries and might have
slightly tweaked the large lines to be a little shorter (also fixed up
some tab vs space indents, but the file wasn't really consistent to
begin with).

The last three I skipped for now were:

- segment_report_module: Pull finish_portion() info file scope
- segment_report_module: Pull read_portion() into file scope
- segment_report_module: Pull consider_notes() into file scope

The first two aren't so bad, but maybe we can find a way to not pass so
many arguments around (have a state struct with dwfl,
memory_callback[_arg], data and size maybe?)

consider_notes might be better just inlined because it is used only
once.

Let me know what you think.

Cheers,

Mark

Re: patch: debuginfod sqlite3 metrics

[Mark Wielaard]

Hi Frank,

On Mon, 2020-11-23 at 20:07 -0500, Frank Ch. Eigler via Elfutils-devel
wrote:
> From 0b61f4c758a507fcc2243357363e44140bd13d82 Mon Sep 17 00:00:00
> 2001 ?!??!!
> From: "Frank Ch. Eigler" 
> 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

Looks good. Just one question about the RAII timing metrics.
It is using gettimeofday which I believe might jump around since it
tracks "human time". Might it be better to use clock_gettime
(CLOCK_MONOTONIC) instead? Note that uses nanoseconds instead of
microseconds, so needs adjusting a factor 1000.

Cheers,

Mark

Re: patch: debuginfod sqlite3 metrics

[Frank Ch. Eigler via Elfutils-devel]

Hi -

> Looks good. Just one question about the RAII timing metrics.
> It is using gettimeofday which I believe might jump around since it
> tracks "human time". Might it be better to use clock_gettime
> (CLOCK_MONOTONIC) instead? Note that uses nanoseconds instead of
> microseconds, so needs adjusting a factor 1000.

Sure, can switch the new and old code over to that.

- FChE

patches obv debuginfod

[Frank Ch. Eigler via Elfutils-devel]

Hi -

Committed these as obvious:


commit 841bd252a065d65eee9cff38430bc240cab3d1af (HEAD -> master)
Author: Frank Ch. Eigler 
Date:   Wed Nov 25 21:20:27 2020 -0500

debuginfod: correct prometheus metric typo

The "-" character is not allowed in a metric label_name, whoops,
so use "_" for one of the new sqlite metrics.

Signed-off-by: Frank Ch. Eigler 


diff --git a/debuginfod/debuginfod.cxx b/debuginfod/debuginfod.cxx
index 9da4c44a9554..41698787c005 100644
--- a/debuginfod/debuginfod.cxx
+++ b/debuginfod/debuginfod.cxx
@@ -825,7 +825,7 @@ struct sqlite_ps
 
 
   void step_ok_done() {
-tmp_ms_metric tick("sqlite3","step-done",nickname);
+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;




commit ea5788a5bae5ac88148e4cddbe5fe7ea7628eadc (origin/master, origin/HEAD, 
eu1/master)
Author: Frank Ch. Eigler 
Date:   Wed Nov 25 19:41:03 2020 -0500

debuginfod: use clock_gettime(CLOCK_MONOTONIC) for intervals

On Mark's request, use a monotonic clock for metrics/reports related
to time interval measurement.  gettimeofday can jump a bit, which
could distort metrics.  Tests unaffected.

Signed-off-by: Frank Ch. Eigler 

diff --git a/debuginfod/debuginfod.cxx b/debuginfod/debuginfod.cxx
index 618620b4c478..9da4c44a9554 100644
--- a/debuginfod/debuginfod.cxx
+++ b/debuginfod/debuginfod.cxx
@@ -437,19 +437,19 @@ 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;
+  struct timespec ts_start;
 public:
   tmp_ms_metric(const string& mname, const string& lname, const string& 
lvalue):
 m(mname), n(lname), v(lvalue)
   {
-gettimeofday (& tv_start, NULL);
+clock_gettime (CLOCK_MONOTONIC, & ts_start);
   }
   ~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.01;
+struct timespec ts_end;
+clock_gettime (CLOCK_MONOTONIC, & ts_end);
+double deltas = (ts_end.tv_sec - ts_start.tv_sec)
+  + (ts_end.tv_nsec - ts_start.tv_nsec)/1.e9;
 
 add_metric (m + "_milliseconds_sum", n, v, (deltas*1000));
 inc_metric (m + "_milliseconds_count", n, v);
@@ -1862,8 +1862,8 @@ handler_cb (void * /*cls*/,
 #endif
   int http_code = 500;
   off_t http_size = -1;
-  struct timeval tv_start, tv_end;
-  gettimeofday (&tv_start, NULL);
+  struct timespec ts_start, ts_end;
+  clock_gettime (CLOCK_MONOTONIC, &ts_start);
 
   try
 {
@@ -1938,8 +1938,8 @@ handler_cb (void * /*cls*/,
   rc = e.mhd_send_response (connection);
 }
 
-  gettimeofday (&tv_end, NULL);
-  double deltas = (tv_end.tv_sec - tv_start.tv_sec) + (tv_end.tv_usec - 
tv_start.tv_usec)*0.01;
+  clock_gettime (CLOCK_MONOTONIC, &ts_end);
+  double deltas = (ts_end.tv_sec - ts_start.tv_sec) + (ts_end.tv_nsec - 
ts_start.tv_nsec)/1.e9;
   obatched(clog) << conninfo(connection)
  << ' ' << method << ' ' << url
  << ' ' << http_code << ' ' << http_size
@@ -2856,8 +2856,8 @@ scan_source_paths()
 throw libc_exception(errno, "cannot fts_open");
   defer_dtor fts_cleanup (fts, fts_close);
 
-  struct timeval tv_start, tv_end;
-  gettimeofday (&tv_start, NULL);
+  struct timespec ts_start, ts_end;
+  clock_gettime (CLOCK_MONOTONIC, &ts_start);
   unsigned fts_scanned = 0, fts_regex = 0;
 
   FTSENT *f;
@@ -2934,8 +2934,8 @@ scan_source_paths()
 break;
   }
   }
-  gettimeofday (&tv_end, NULL);
-  double deltas = (tv_end.tv_sec - tv_start.tv_sec) + (tv_end.tv_usec - 
tv_start.tv_usec)*0.01;
+  clock_gettime (CLOCK_MONOTONIC, &ts_end);
+  double deltas = (ts_end.tv_sec - ts_start.tv_sec) + (ts_end.tv_nsec - 
ts_start.tv_nsec)/1.e9;
 
   obatched(clog) << "fts traversed source paths in " << deltas << "s, 
scanned=" << fts_scanned
  << ", regex-skipped=" << fts_regex << endl;
@@ -3025,8 +3025,8 @@ void groom()
 {
   obatched(clog) << "grooming database" << endl;
 
-  struct timeval tv_start, tv_end;
-  gettimeofday (&tv_start, NULL);
+  struct timespec ts_start, ts_end;
+  clock_gettime (CLOCK_MONOTONIC, &ts_start);
 
   database_stats_report();
   
@@ -3090,8 +3090,8 @@ void groom()
   fdcache.limit(0,0); // release the fdcache contents
   fdcache.limit(fdcache_fds,fdcache_mbs); // restore status quo parameters
 
-  gettimeofday (&tv_end, NULL);
-  double deltas = (tv_end.tv_sec - tv_start.tv_sec) + (tv_end.tv_usec - 
tv_start.tv_usec)*0.01;
+  clock_gettime (CLOCK_MONOTONIC, &ts_end);
+  double deltas = (ts_end.tv_sec - ts_start.tv_sec) + (ts_end.tv_nsec - 
ts_start.tv_nsec)/1.e9;
 
   obatched(clog) << "groomed database in " << deltas << "s" << endl;
 }