From 193371ef11e3ed95a095e9d4169c22b18fb94af1 Mon Sep 17 00:00:00 2001 From: Florin Coras Date: Sun, 2 Mar 2025 18:40:11 -0500 Subject: [PATCH] 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 --- src/vppinfra/time.c | 11 +++++++++-- 1 file changed, 9 insertions(+), 2 deletions(-) diff --git a/src/vppinfra/time.c b/src/vppinfra/time.c index f1736499a0a..7c0ea44b481 100644 --- 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); } -- 2.16.6