[PATCH 2/2] tests: Don't sleep in run-debuginfod-find.sh, but wait till ready.

[PATCH 2/2] tests: Don't sleep in run-debuginfod-find.sh, but wait till ready.

[Mark Wielaard]

Wait for the debuginfod server to finish and use the metrics to see
when a server is ready for the next test instead of sleeping. Also
remove DEBUGINFOD_TEST_WEBAPI_SLEEP.

Signed-off-by: Mark Wielaard <mark@klomp.org>
---
 debuginfod/ChangeLog         |  6 +++
 debuginfod/debuginfod.cxx    |  8 ---
 tests/ChangeLog              |  7 +++
 tests/run-debuginfod-find.sh | 94 +++++++++++++++++++++++++++++-------
 4 files changed, 89 insertions(+), 26 deletions(-)

diff --git a/debuginfod/ChangeLog b/debuginfod/ChangeLog
index bd3db9ff..a1d17b5f 100644
--- a/debuginfod/ChangeLog
+++ b/debuginfod/ChangeLog
@@ -1,3 +1,9 @@
+2019-11-24  Mark Wielaard  <mark@klomp.org>
+
+	* debuginfod.cxx (test_webapi_sleep): Removed.
+	(handler_cb): Don't check test_webapi_sleep and sleep.
+	(main): Don't set test_webapi_sleep.
+
 2019-11-24  Mark Wielaard  <mark@klomp.org>
 
 	* debuginfod.cxx (add_metric): New function.
diff --git a/debuginfod/debuginfod.cxx b/debuginfod/debuginfod.cxx
index 3717aa82..cb0e1f3b 100644
--- a/debuginfod/debuginfod.cxx
+++ b/debuginfod/debuginfod.cxx
@@ -375,7 +375,6 @@ static bool scan_rpms = false;
 static vector<string> extra_ddl;
 static regex_t file_include_regex;
 static regex_t file_exclude_regex;
-static int test_webapi_sleep; /* testing only */
 static bool traverse_logical;
 
 static void set_metric(const string& key, int64_t value);
@@ -1201,9 +1200,6 @@ handler_cb (void * /*cls*/,
   if (verbose)
     obatched(clog) << conninfo(connection) << " " << method << " " << url << endl;
 
-  if (test_webapi_sleep)
-    sleep (test_webapi_sleep);
-
   try
     {
       if (string(method) != "GET")
@@ -2484,10 +2480,6 @@ main (int argc, char *argv[])
   if (rc != 0)
     error (EXIT_FAILURE, 0, "regcomp failure: %d", rc);
 
-  const char* test_webapi_sleep_str = getenv("DEBUGINFOD_TEST_WEBAPI_SLEEP");
-  if (test_webapi_sleep_str)
-    test_webapi_sleep = atoi (test_webapi_sleep_str);
-
   /* Parse and process arguments.  */
   int remaining;
   argp_program_version_hook = print_version; // this works
diff --git a/tests/ChangeLog b/tests/ChangeLog
index 8142a0f6..27bc4ec2 100644
--- a/tests/ChangeLog
+++ b/tests/ChangeLog
@@ -1,3 +1,10 @@
+2019-11-24  Mark Wielaard  <mark@klomp.org>
+
+	* run-debuginfod-find.sh: Reduce verbosity. Add new cleanup
+	function to use with trap. Add wait_ready function to query
+	metrics instead of sleeping. Calculate rpms and sourcefiles
+	to check.
+
 2019-11-23  Mark Wielaard  <mark@klomp.org>
 
 	* run-debuginfod-find.sh: Replace all localhost with 127.0.0.1.
diff --git a/tests/run-debuginfod-find.sh b/tests/run-debuginfod-find.sh
index ff68c3de..7eb6aa9d 100755
--- a/tests/run-debuginfod-find.sh
+++ b/tests/run-debuginfod-find.sh
@@ -16,15 +16,26 @@
 # You should have received a copy of the GNU General Public License
 # along with this program.  If not, see <http://www.gnu.org/licenses/>.
 
-set -x
 . $srcdir/test-subr.sh  # includes set -e
 
 DB=${PWD}/.debuginfod_tmp.sqlite
 tempfiles $DB
 export DEBUGINFOD_CACHE_PATH=${PWD}/.client_cache
 
+PID1=0
+PID2=0
+
+cleanup()
+{
+  if [ $PID1 -ne 0 ]; then kill $PID1; wait $PID1; fi
+  if [ $PID2 -ne 0 ]; then kill $PID2; wait $PID2; fi
+
+  rm -rf F R L ${PWD}/.client_cache*
+  exit_cleanup
+}
+
 # clean up trash if we were aborted early
-trap 'kill $PID1 $PID2 || true; sleep 5; rm -rf F R L ${PWD}/.client_cache*; exit_cleanup' 0 1 2 3 5 9 15
+trap cleanup 0 1 2 3 5 9 15
 
 # find an unused port number
 while true; do
@@ -45,18 +56,35 @@ mkdir F R L
 # not tempfiles F R L - they are directories which we clean up manually
 ln -s ${abs_builddir}/dwfllines L/foo   # any program not used elsewhere in this test
 
-env DEBUGINFOD_TEST_WEBAPI_SLEEP=3 LD_LIBRARY_PATH=$ldpath DEBUGINFOD_URLS= ${abs_builddir}/../debuginfod/debuginfod -F -R -vvvv -d $DB -p $PORT1 -t0 -g0 R F L &
+wait_ready()
+{
+    port=$1;
+    what=$2;
+    value=$3;
+    timeout=$4;
+
+    echo "Wait $timeout seconds on $port for metric $what to change to $value"
+    while [ $timeout -gt 0 ]; do
+	mvalue="$(curl -s http://127.0.0.1:$port/metrics \
+		 | grep "$what" | awk '{print $NF}')"
+	if [ -z "$mvalue" ]; then mvalue=0; fi
+	echo "metric $what: $mvalue"
+	if [ "$mvalue" -eq "$value" ]; then
+	    break;
+	fi
+	sleep 1;
+	((timeout--));
+    done;
+}
+
+env LD_LIBRARY_PATH=$ldpath DEBUGINFOD_URLS= ${abs_builddir}/../debuginfod/debuginfod -F -R -d $DB -p $PORT1 -t0 -g0 R F L &
 PID1=$!
-sleep 3
+# Server must become ready
+wait_ready $PORT1 "ready" "1" 3
 export DEBUGINFOD_URLS=http://127.0.0.1:$PORT1/   # or without trailing /
 
 # Be patient when run on a busy machine things might take a bit.
-# And under valgrind debuginfod-find is really, really slow.
-if [ "x$VALGRIND_CMD" = "x" ]; then
-  export DEBUGINFOD_TIMEOUT=60
-else
-  export DEBUGINFOD_TIMEOUT=300
-fi
+export DEBUGINFOD_TIMEOUT=10
 
 # We use -t0 and -g0 here to turn off time-based scanning & grooming.
 # For testing purposes, we just sic SIGUSR1 / SIGUSR2 at the process.
@@ -76,7 +104,8 @@ BUILDID=`env LD_LIBRARY_PATH=$ldpath ${abs_builddir}/../src/readelf \
 mv prog F
 mv prog.debug F
 kill -USR1 $PID1
-sleep 3 # give enough time for scanning pass 
+# Wait till both files are in the index.
+wait_ready $PORT1 'thread_work_total{file="F"}' 2 3
 
 ########################################################################
 
@@ -110,7 +139,8 @@ BUILDID2=`env LD_LIBRARY_PATH=$ldpath ${abs_builddir}/../src/readelf \
 
 mv prog2 F
 kill -USR1 $PID1
-sleep 3
+# Now there should be 3 files in the index
+wait_ready $PORT1 'thread_work_total{file="F"}' 3 3
 
 # Rerun same tests for the prog2 binary
 filename=`testrun ${abs_top_builddir}/debuginfod/debuginfod-find -v debuginfo $BUILDID2 2>vlog`
@@ -125,10 +155,34 @@ cmp $filename ${PWD}/prog2.c
 
 cp -rp ${abs_srcdir}/debuginfod-rpms R
 kill -USR1 $PID1
-sleep 10
+# All rpms need to be in the index
+rpms=$(find R -name \*rpm | wc -l)
+wait_ready $PORT1 'scanned_total{source="rpm"}' $rpms 10
+
 kill -USR1 $PID1  # two hits of SIGUSR1 may be needed to resolve .debug->dwz->srefs
-sleep 10
+# Expect all source files found in the rpms (they are all called hello.c :)
+# We will need to extract all rpms (in their own directory) and could all
+# sources referenced in the .debug files.
+mkdir extracted
+cd extracted
+subdir=0;
+newrpms=$(find ../R -name \*\.rpm)
+for i in $newrpms; do
+    subdir=$[$subdir+1];
+    mkdir $subdir;
+    cd $subdir;
+    ls -lah ../$i
+    rpm2cpio ../$i | cpio -id;
+    cd ..;
+done
+sourcefiles=$(find -name \*\\.debug \
+	      | env LD_LIBRARY_PATH=$ldpath xargs \
+		${abs_top_builddir}/src/readelf --debug-dump=decodedline \
+	      | grep mtime: | wc --lines)
+cd ..
+rm -rf extracted
 
+wait_ready $PORT1 'found_sourcerefs_total{source="rpm"}' $sourcefiles 10
 
 # Run a bank of queries against the debuginfod-rpms test cases
 
@@ -175,7 +229,9 @@ RPM_BUILDID=d44d42cbd7d915bc938c81333a21e355a6022fb7 # in rhel6/ subdir, for a l
 
 rm -r R/debuginfod-rpms/rhel6/*
 kill -USR2 $PID1  # groom cycle
-sleep 3
+# Expect 3 rpms to be deleted by the groom
+wait_ready $PORT1 'groom{statistic="file d/e"}' 3 10
+
 rm -rf $DEBUGINFOD_CACHE_PATH # clean it from previous tests
 
 testrun ${abs_top_builddir}/debuginfod/debuginfod-find executable $RPM_BUILDID && false || true
@@ -196,10 +252,10 @@ export DEBUGINFOD_CACHE_PATH=${PWD}/.client_cache2
 mkdir -p $DEBUGINFOD_CACHE_PATH
 # NB: inherits the DEBUGINFOD_URLS to the first server
 # NB: run in -L symlink-following mode for the L subdir
-env LD_LIBRARY_PATH=$ldpath ${abs_builddir}/../debuginfod/debuginfod -F -vvvv -d ${DB}_2 -p $PORT2 -L L &
+env LD_LIBRARY_PATH=$ldpath ${abs_builddir}/../debuginfod/debuginfod -F -d ${DB}_2 -p $PORT2 -L L &
 PID2=$!
 tempfiles ${DB}_2
-sleep 3
+wait_ready $PORT2 "ready" 1 3
 
 # have clients contact the new server
 export DEBUGINFOD_URLS=http://127.0.0.1:$PORT2
@@ -242,7 +298,9 @@ fi
 # be found in the cache.
 
 kill -INT $PID1 $PID2
-sleep 5
+wait $PID1 $PID2
+PID1=0
+PID2=0
 tempfiles .debuginfod_*
 
 testrun ${abs_builddir}/debuginfod_build_id_find -e F/prog2 1
-- 
2.18.1

Add some metrics to debuginfod and use them to make test sleep less

[Mark Wielaard]

Hi,

The following two patches add some metrics to debuginfod that can be
used ito see whether the scanners are still finding new executables,
debuginfo files or find new sources. They can also be used in the
run-debuginfod-find.sh testcase to see whether the server is ready
or not for the next test. This removes most sleeps from the testcase
(and the test_webapi_sleep in the server).

[1/2] debuginfod: Add found_{executable,debuginfo,sourcerefs}_total metrics.
[2/2] tests: Don't sleep in run-debuginfod-find.sh, but wait till ready.

This brings down the run-debuginfod-find.sh run from 2 minutes and 10
seconds to 8 seconds on my machine. And from 3 minutes to 45 seconds
under valgrind

It doesn't actually test that the metrics are correctly set (even
though it calculates what the metrics should be) because the metrics
are not guaranteed to be stable. But maybe the test should?
It could just fail instead of timeing out. Then when we change the
metrics we could just update the test simultaniously?

Cheers,

Mark

[PATCH 1/2] debuginfod: Add found_{executable,debuginfo,sourcerefs}_total metrics.

[Mark Wielaard]

Keeps metrics of how many executables, debuginfo and sourcerefs were
found in total for file and rpm scanners.

Signed-off-by: Mark Wielaard <mark@klomp.org>
---
 debuginfod/ChangeLog      |  8 ++++++++
 debuginfod/debuginfod.cxx | 24 ++++++++++++++++++++++++
 2 files changed, 32 insertions(+)

diff --git a/debuginfod/ChangeLog b/debuginfod/ChangeLog
index 47efb9b4..bd3db9ff 100644
--- a/debuginfod/ChangeLog
+++ b/debuginfod/ChangeLog
@@ -1,3 +1,11 @@
+2019-11-24  Mark Wielaard  <mark@klomp.org>
+
+	* debuginfod.cxx (add_metric): New function.
+	(scan_source_file_path): Record metrics for
+	found_executable_total, found_debuginfo_total and
+	found_sourcerefs_total.
+	(scan_source_rpm_path): Likewise.
+
 2019-11-07  Frank Ch. Eigler  <fche@redhat.com>
 
 	* debuginfod.cxx: Add /metrics endpoint.  Add numerous
diff --git a/debuginfod/debuginfod.cxx b/debuginfod/debuginfod.cxx
index f4bbc7b7..3717aa82 100644
--- a/debuginfod/debuginfod.cxx
+++ b/debuginfod/debuginfod.cxx
@@ -385,6 +385,9 @@ static void set_metric(const string& metric,
                        int64_t value);
 static void inc_metric(const string& metric,
                        const string& lname, const string& lvalue);
+static void add_metric(const string& metric,
+                       const string& lname, const string& lvalue,
+                       int64_t value);
 
 /* Handle program arguments.  */
 static error_t
@@ -1146,6 +1149,15 @@ inc_metric(const string& metric,
   unique_lock<mutex> lock(metrics_lock);
   metrics[key] ++;
 }
+static void
+add_metric(const string& metric,
+           const string& lname, const string& lvalue,
+           int64_t value)
+{
+  string key = (metric + "{" + metric_label(lname, lvalue) + "}");
+  unique_lock<mutex> lock(metrics_lock);
+  metrics[key] += value;
+}
 
 
 // and more for higher arity labels if needed
@@ -1706,6 +1718,10 @@ scan_source_file_path (const string& dir)
                       .bind(5, f->fts_statp->st_mtime)
                       .step_ok_done();
                   }
+                if (executable_p)
+                  inc_metric("found_executable_total","source","files");
+                if (debuginfo_p)
+                  inc_metric("found_debuginfo_total","source","files");
 
                 if (sourcefiles.size() && buildid != "")
                   {
@@ -1748,6 +1764,8 @@ scan_source_file_path (const string& dir)
                           .bind(3, srps)
                           .bind(4, sfs.st_mtime)
                           .step_ok_done();
+
+			inc_metric("found_sourcerefs_total","source","files");
                       }
                   }
 
@@ -2145,6 +2163,12 @@ scan_source_rpm_path (const string& dir)
                                   my_fts_executable, my_fts_debuginfo, my_fts_sref, my_fts_sdef,
                                   my_fts_sref_complete_p);
                     inc_metric ("scanned_total","source","rpm");
+                    add_metric("found_debuginfo_total","source","rpm",
+                               my_fts_debuginfo);
+                    add_metric("found_executable_total","source","rpm",
+                               my_fts_executable);
+                    add_metric("found_sourcerefs_total","source","rpm",
+                               my_fts_sref);
                   }
                 catch (const reportable_exception& e)
                   {
-- 
2.18.1

Re: Add some metrics to debuginfod and use them to make test sleep less

[Mark Wielaard]

Hi,

On Sun, Nov 24, 2019 at 08:58:13PM +0100, Mark Wielaard wrote:
> The following two patches add some metrics to debuginfod that can be
> used ito see whether the scanners are still finding new executables,
> debuginfo files or find new sources. They can also be used in the
> run-debuginfod-find.sh testcase to see whether the server is ready
> or not for the next test. This removes most sleeps from the testcase
> (and the test_webapi_sleep in the server).
> 
> [1/2] debuginfod: Add found_{executable,debuginfo,sourcerefs}_total metrics.
> [2/2] tests: Don't sleep in run-debuginfod-find.sh, but wait till ready.
> 
> This brings down the run-debuginfod-find.sh run from 2 minutes and 10
> seconds to 8 seconds on my machine. And from 3 minutes to 45 seconds
> under valgrind

After (a very short) discussion on irc I pushed this to master.  I did
change the sleep 1 to a sleep 0.5 (and doubled the timeout value to
compensate). This makes the test finish a couple of seconds sooner.

> It doesn't actually test that the metrics are correctly set (even
> though it calculates what the metrics should be) because the metrics
> are not guaranteed to be stable. But maybe the test should?
> It could just fail instead of timeing out. Then when we change the
> metrics we could just update the test simultaniously?

I tweaked it so that it fails immediately when at timeout the metric
hasn't changed to the expected value. It seems better to fail fast
because the next test will most likely fail anyway.

Cheers,

Mark