From a5fe2706bd69282fe8a21e3769ef3890a151b1fd Mon Sep 17 00:00:00 2001
From: Christopher Haster <geky@geky.net>
Date: Sat, 11 May 2024 21:39:30 -0500
Subject: [PATCH] Added runtime measurements to test.py -o/--output

Now that we have ~20 minutes of tests, it's good to know _why_ the tests
take ~20 minutes, and if this time is being spent well.

This adds the field test_time to test.py's -o/--output, which reports
the runtime of each test in seconds. This can be organized by suite,
case, etc, with our existing csv scripts.

Note I've limited the precision to only milliseconds (%.6f).
Realistically, this is plenty of precision, and with the number of tests
we have extra digits can really add up!

                             lines                   bytes
  test.csv before:          525593          58432541 56MiB
  test.csv full precision:  525593 (+0.0%)  69817693 67MiB (+19.5%)
  test.csv milli precision: 525593 (+0.0%)  63162935 60MiB (+8.1%)

It still takes a bit of time to process this (50.3s), but now we can see
the biggest culprits of our ~20 minute test time:

  $ ./scripts/summary.py test.csv -bcase -ftest_time -S
  case                                               test_time
  ...
  test_fwrite_hole_compaction                             74.4
  test_fwrite_incr                                       109.7
  test_dirs_mkdir_fuzz                                   115.3
  test_fwrite_overwrite_compaction                       132.4
  test_rbyd_fuzz_append_removes                          134.0
  test_rbyd_fuzz_mixed                                   136.3
  test_rbyd_fuzz_sparse                                  137.4
  test_fwrite_w_seek                                     144.1
  test_rbyd_fuzz_create_deletes                          144.8
  test_dirs_rm_many_backwards                            208.4
  test_dirs_rm_many                                      273.8
  test_fwrite_fuzz_unaligned                             283.2
  test_dread_recursive_rm                                316.7
  test_fwrite_fuzz_aligned                               551.0
  test_dirs_general_fuzz                                 552.8
  test_dirs_rm_fuzz                                      632.7
  test_fwrite_reversed                                   719.0
  test_dirs_mv_fuzz                                     1984.8
  TOTAL                                                 7471.3

Note this machine has 6 cores, 12 hthreads, 7471.3/60/6 => 20.8m, which
is why I don't run these tests single threaded.
---
 scripts/test.py | 8 ++++++--
 1 file changed, 6 insertions(+), 2 deletions(-)

diff --git a/scripts/test.py b/scripts/test.py
index eaa56598..ab62c395 100755
--- a/scripts/test.py
+++ b/scripts/test.py
@@ -972,6 +972,7 @@ def run_stage(name, runner, test_ids, stdout_, trace_, output_, **args):
         last_id = None
         last_stdout = co.deque(maxlen=args.get('context', 5) + 1)
         last_assert = None
+        last_time = time.time()
         try:
             while True:
                 # parse a line for state changes
@@ -999,6 +1000,7 @@ def run_stage(name, runner, test_ids, stdout_, trace_, output_, **args):
                         last_id = m.group('id')
                         last_stdout.clear()
                         last_assert = None
+                        last_time = time.time()
                     elif op == 'powerloss':
                         last_id = m.group('id')
                         powerlosses += 1
@@ -1020,8 +1022,10 @@ def run_stage(name, runner, test_ids, stdout_, trace_, output_, **args):
                             output_.writerow({
                                 'suite': suite,
                                 'case': case,
+                                **defines,
                                 'test_passed': '1/1',
-                                **defines})
+                                'test_time': '%.6f' % (
+                                    time.time() - last_time)})
                     elif op == 'skipped':
                         locals.seen_perms += 1
                     elif op == 'assert':
@@ -1215,7 +1219,7 @@ def run(runner, test_ids=[], **args):
     if args.get('output'):
         output = TestOutput(args['output'],
             ['suite', 'case'],
-            ['test_passed'])
+            ['test_passed', 'test_time'])
 
     # measure runtime
     start = time.time()