From 28a08786bb30e042761620484be5d6604fc879f2 Mon Sep 17 00:00:00 2001
From: Cedric Roux <cedric.roux@eurecom.fr>
Date: Sun, 19 Jan 2025 13:27:39 +0100
Subject: [PATCH] T hacks: time_meas: add a periodic tracing mode

Useful to debug realtime issues, for example when calling a periodical
routine, if it's not programmed carefully enough, it may be that the first
call takes way longer than the next ones (for example it uses some memory
that is not mapped in the process, leading to many page faults the first
time it's executed).

Having a periodic log for the timing of this routine with min/avg/max/count
will reveal that a call is way longer than average and will help in
finding where exactly in the code the time is spent, thanks to the ease
of use of the T tracer; you put T(T_XX, T_INT(1)) just before the code
you want to measure, you put T(T_XX, T_INT(0)) just after and time_meas
will show the delta time between those events. Then you cut the routine
in smaller pieces, measure with T(1)/T(0), and you finally reach the small
guilty part that takes too long.
---
 common/utils/T/tracer/hacks/time_meas.c | 41 ++++++++++++++++++++++---
 1 file changed, 36 insertions(+), 5 deletions(-)

diff --git a/common/utils/T/tracer/hacks/time_meas.c b/common/utils/T/tracer/hacks/time_meas.c
index 6e8f1f3bbb..5c945db814 100644
--- a/common/utils/T/tracer/hacks/time_meas.c
+++ b/common/utils/T/tracer/hacks/time_meas.c
@@ -1,6 +1,7 @@
 #include <stdio.h>
 #include <stdlib.h>
 #include <string.h>
+#include <stdint.h>
 #include "utils.h"
 #include "event.h"
 #include "database.h"
@@ -14,7 +15,8 @@ void usage(void)
 "    -d <database file>        this option is mandatory\n"
 "    -ip <host>                connect to given IP address (default %s)\n"
 "    -p <port>                 connect to given port (default %d)\n"
-"    -e <event>                event to trace (default VCD_FUNCTION_ENB_DLSCH_ULSCH_SCHEDULER)\n",
+"    -e <event>                event to trace (default VCD_FUNCTION_ENB_DLSCH_ULSCH_SCHEDULER)\n"
+"    -s                        stat mode, print every second min/avg/max + count\n",
   DEFAULT_REMOTE_IP,
   DEFAULT_REMOTE_PORT
   );
@@ -34,6 +36,21 @@ struct timespec time_sub(struct timespec a, struct timespec b)
   return ret;
 }
 
+volatile uint64_t acc, count, acc_min, acc_max;
+
+void *stat_thread(void *_)
+{
+  while (1) {
+    uint64_t v = acc;
+    uint64_t c = count;
+    uint64_t min = acc_min;
+    uint64_t max = acc_max;
+    acc = acc_min = acc_max = count = 0;
+    printf("%ld %ld %ld [%ld]\n", min, c==0 ? 0 : v/c, max, c);
+    sleepms(1000);
+  }
+}
+
 int main(int n, char **v)
 {
   char *database_filename = NULL;
@@ -49,6 +66,7 @@ int main(int n, char **v)
   int start_valid = 0;
   struct timespec start_time, stop_time, delta_time;
   char *name = "VCD_FUNCTION_ENB_DLSCH_ULSCH_SCHEDULER";
+  int stat_mode = 0;
 
   for (i = 1; i < n; i++) {
     if (!strcmp(v[i], "-h") || !strcmp(v[i], "--help")) usage();
@@ -58,9 +76,13 @@ int main(int n, char **v)
     if (!strcmp(v[i], "-p"))
       { if (i > n-2) usage(); port = atoi(v[++i]); continue; }
     if (!strcmp(v[i], "-e")) { if (i > n-2) usage(); name = v[++i]; continue; }
+    if (!strcmp(v[i], "-s")) { stat_mode = 1; continue; }
     usage();
   }
 
+  if (stat_mode)
+    new_thread(stat_thread, NULL);
+
   if (database_filename == NULL) {
     printf("ERROR: provide a database file (-d)\n");
     exit(1);
@@ -96,7 +118,8 @@ int main(int n, char **v)
     if (e.type != ev_fun)
       { printf("unhandled event %d\n", e.type); continue; }
     on_off = e.e[0].i;
-printf("yo %d\n", on_off);
+    if (!stat_mode)
+      printf("yo %d\n", on_off);
     if (on_off == 1) {
       start_time = e.sending_time;
       start_valid = 1;
@@ -107,9 +130,17 @@ printf("yo %d\n", on_off);
     start_valid = 0;
     stop_time = e.sending_time;
     delta_time = time_sub(stop_time, start_time);
-    fprintf(stderr, "%ld\n",
-        delta_time.tv_sec * 1000000000UL + delta_time.tv_nsec);
-    fflush(stderr);
+    if (stat_mode) {
+      uint64_t v = delta_time.tv_sec * 1000000000UL + delta_time.tv_nsec;
+      if (count == 0 || v < acc_min) acc_min = v;
+      if (v > acc_max) acc_max = v;
+      acc += v;
+      count++;
+    } else {
+      fprintf(stderr, "%ld\n",
+              delta_time.tv_sec * 1000000000UL + delta_time.tv_nsec);
+      fflush(stderr);
+    }
   }
 
   return 0;