DAOS-16585 tests: Improve NLT checking of ioil metrics.

Use the ioil statistics to verify read/write counts rather
than just checking for function name.

Signed-off-by: Ashley Pittman <ashley.m.pittman@intel.com>

src/client/dfuse/il/int_posix.c

@@ -359,8 +359,10 @@ ioil_init(void)
 static void
 ioil_show_summary()
 {
-	D_INFO("Performed %"PRIu64" reads and %"PRIu64" writes from %"PRIu64" files\n",
-	       ioil_iog.iog_read_count, ioil_iog.iog_write_count, ioil_iog.iog_file_count);
+	D_INFO("Performed %" PRIu64 " reads, %" PRIu64 " writes and %" PRIu64
+	       " fstats from %" PRIu64 " files\n",
+	       ioil_iog.iog_read_count, ioil_iog.iog_write_count, ioil_iog.iog_fstat_count,
+	       ioil_iog.iog_file_count);
 
 	if (ioil_iog.iog_file_count == 0 || !ioil_iog.iog_show_summary)
 		return;

utils/node_local_test.py

@@ -46,17 +46,27 @@
 class NLTestFail(Exception):
     """Used to indicate test failure"""
 
+    def __repr__(self):
+        return "Test failure object for NLT"
+
 
 class NLTestNoFi(NLTestFail):
     """Used to indicate Fault injection didn't work"""
 
 
-class NLTestNoFunction(NLTestFail):
+class NLTestIlZeroCall(NLTestFail):
     """Used to indicate a function did not log anything"""
 
     def __init__(self, function):
         super().__init__(self)
         self.function = function
+        self.command = []
+
+    def __str__(self):
+        if self.command:
+            cmd = ' '.join(self.command)
+            return f'Command "{cmd}" has zero stat count for {self.function}'
+        return f"Called program did not call {self.function}"
 
 
 class NLTestTimeout(NLTestFail):
@@ -1507,8 +1517,11 @@ def il_cmd(self, cmd, check_read=True, check_write=True, check_fstat=True):
         would be freed in the _fini() function, and a lot of
         commands do not free all memory anyway.
         """
+        if self.caching:
+            check_fstat = False
+
         my_env = get_base_env()
-        prefix = f'dnt_dfuse_il_{get_inc_id()}_'
+        prefix = f'dnt_ioil_{cmd[0]}_{get_inc_id()}_'
         with tempfile.NamedTemporaryFile(prefix=prefix, suffix='.log', delete=False) as log_file:
             log_name = log_file.name
         my_env['D_LOG_FILE'] = log_name
@@ -1517,21 +1530,27 @@ def il_cmd(self, cmd, check_read=True, check_write=True, check_fstat=True):
         my_env['D_IL_REPORT'] = '2'
         if self.conf.args.client_debug:
             my_env['D_LOG_MASK'] = self.conf.args.client_debug
+
+        if check_fstat:
+            fsu = self.check_usage()['statistics']
+
         ret = subprocess.run(cmd, env=my_env, check=False)
         print(f'Logged il to {log_name}')
         print(ret)
 
-        if self.caching:
-            check_fstat = False
+        if check_fstat:
+            fsu2 = self.check_usage()['statistics']
+            print(fsu)
+            print(fsu2)
+            delta = fsu2.get('getattr', 0) - fsu.get('getattr', 0)
+            print(f"Command caused {delta} stat calls")
 
         try:
             log_test(self.conf, log_name, check_read=check_read, check_write=check_write,
                      check_fstat=check_fstat)
-            assert ret.returncode == 0
-        except NLTestNoFunction as error:
-            command = ' '.join(cmd)
-            print(f"ERROR: command '{command}' did not log via {error.function}")
-            ret.returncode = 1
+        except NLTestIlZeroCall as error:
+            error.command = cmd
+            raise
 
         assert ret.returncode == 0, ret
         return ret
@@ -2712,11 +2731,7 @@ def test_il_cat(self):
         with open(fname, 'w'):
             pass
 
-        check_fstat = True
-        if self.dfuse.caching:
-            check_fstat = False
-
-        self.dfuse.il_cmd(['cat', fname], check_write=False, check_fstat=check_fstat)
+        self.dfuse.il_cmd(['cat', fname], check_write=False)
 
     @needs_dfuse_with_opt(caching=False)
     def test_il(self):
@@ -4654,7 +4669,6 @@ def run_tests(dfuse):
     assert_file_size(ofd, 21)
     print(os.fstat(ofd.fileno()))
     ofd.close()
-    dfuse.il_cmd(['cat', fname], check_write=False)
     ofd = os.open(fname, os.O_TRUNC)
     assert_file_size_fd(ofd, 0)
     os.close(ofd)
@@ -4831,20 +4845,21 @@ def sizeof_fmt(num, suffix='B'):
         if not lto.fi_triggered:
             raise NLTestNoFi
 
-    functions = set()
-
     if check_read or check_write or check_fstat:
         for line in log_iter.new_iter():
-            functions.add(line.function)
+            if line.function != "ioil_show_summary":
+                continue
+            print(line.get_msg())
 
-    if check_read and 'dfuse_read' not in functions:
-        raise NLTestNoFunction('dfuse_read')
+            # These numbers match the D_INFO log line in the ioil_show_summary function.
+            if check_read and int(line.get_field(3)) == 0:
+                raise NLTestIlZeroCall('read')
 
-    if check_write and 'dfuse_write' not in functions:
-        raise NLTestNoFunction('dfuse_write')
+            if check_write and int(line.get_field(5)) == 0:
+                raise NLTestIlZeroCall('write')
 
-    if check_fstat and 'dfuse___fxstat' not in functions:
-        raise NLTestNoFunction('dfuse___fxstat')
+            if check_fstat and int(line.get_field(8)) == 0:
+                raise NLTestIlZeroCall('fstat')
 
     if conf.max_log_size and fstat.st_size > conf.max_log_size:
         message = (f'Max log size exceeded, {sizeof_fmt(fstat.st_size)} > '