vppinfra: make verbose format time more verbose

Dump more cpu and reftime fields in clib time struct. Example:

DBGvpp# sh clock verbose
Time now 6.890267
cpu time 6.890267 now 22333609568369233 last 22333609568350337 since start 19981775480
reftime 6.890268 now 1740958292.416887 last 1740958285.526620 init 1740958285.526620
error 0.000000, clocks/sec 2900000000.000000, Sun, 02 Mar 2025 23:31:32 GMT
Time last barrier release 3.291883104
0: Time now 6.890387
   cpu time 6.890387 now 22333609568706225 last 22333609568696497 since start 19982121640
   reftime 6.890387 now 1740958292.417007 last 1740958285.526620 init 1740958285.526620
   error -.000001, clocks/sec 2900000000.000000
Thread 0 offset 0.000000000 error 0.000000000
1: Time now 5.695180
   cpu time 5.695180 now 22333609568926421 last 22333609568920073 since start 16516023212
   reftime 5.695181 now 1740958292.417084 last 1740958286.721903 init 1740958286.721903
   error -.000001, clocks/sec 2900000000.000000
Thread 1 offset 1.195283275 error -.000000114

Type: improvement

Change-Id: I383b9b1a2ef64a731bbc335cd512d565d47f0cd9
Signed-off-by: Florin Coras <[email protected]>

diff --git a/src/vppinfra/time.c b/src/vppinfra/time.c
index f173649..7c0ea44 100644 (file)
--- a/src/vppinfra/time.c
+++ b/src/vppinfra/time.c
@@ -332,6 +332,7 @@ format_clib_time (u8 * s, va_list * args)
   clib_time_t *c = va_arg (*args, clib_time_t *);
   int verbose = va_arg (*args, int);
   f64 now, reftime, delta_reftime_in_seconds, error;
+  u32 indent = format_get_indent (s);
 
   /* Compute vpp elapsed time from the CPU clock */
   reftime = unix_time_now ();
@@ -346,8 +347,14 @@ format_clib_time (u8 * s, va_list * args)
 
   error = now - delta_reftime_in_seconds;
 
-  s = format (s, ", reftime %.6f, error %.6f, clocks/sec %.6f",
-             delta_reftime_in_seconds, error, c->clocks_per_second);
+  s = format (s, "\n%Ucpu time %.6f now %lu last %lu since start %lu \n",
+             format_white_space, indent, now, clib_cpu_time_now (),
+             c->last_cpu_time, c->total_cpu_time);
+  s = format (s, "%Ureftime %.6f now %.6f last %.6f init %.6f\n",
+             format_white_space, indent, delta_reftime_in_seconds, reftime,
+             c->last_verify_reference_time, c->init_reference_time);
+  s = format (s, "%Uerror %.6f, clocks/sec %.6f", format_white_space, indent,
+             error, c->clocks_per_second);
   return (s);
 }