L1 perf logging changes

Moved the L1 timing stats logs from stdout to nrL1_stats.log

executables/nr-gnb.c

@@ -110,6 +110,7 @@ time_stats_t softmodem_stats_rx_sf; // total rx time
 
 //#define TICK_TO_US(ts) (ts.diff)
 #define TICK_TO_US(ts) (ts.trials==0?0:ts.diff/ts.trials)
+#define L1STATSSTRLEN 16384
 
 
 void tx_func(void *param) {
@@ -321,45 +322,60 @@ void rx_func(void *param) {
        );
 #endif
 }
-static void *process_stats_thread(void *param) {
+static void dump_L1_meas_stats(PHY_VARS_gNB *gNB, RU_t *ru, char *output) {
+  int stroff = 0;
+  stroff += print_meas_log(&gNB->phy_proc_tx, "L1 Tx processing", NULL, NULL, output);
+  stroff += print_meas_log(&gNB->dlsch_encoding_stats, "DLSCH encoding", NULL, NULL, output+stroff);
+  stroff += print_meas_log(&gNB->phy_proc_rx, "L1 Rx processing", NULL, NULL, output+stroff);
+  stroff += print_meas_log(&gNB->ul_indication_stats, "UL Indication", NULL, NULL, output+stroff);
+  stroff += print_meas_log(&gNB->rx_pusch_stats, "PUSCH inner-receiver", NULL, NULL, output+stroff);
+  stroff += print_meas_log(&gNB->ulsch_decoding_stats, "PUSCH decoding", NULL, NULL, output+stroff);
+  if (ru->feprx) stroff += print_meas_log(&ru->ofdm_demod_stats,"feprx",NULL,NULL, output+stroff);
+
+  if (ru->feptx_ofdm) {
+    stroff += print_meas_log(&ru->precoding_stats,"feptx_prec",NULL,NULL, output+stroff);
+    stroff += print_meas_log(&ru->txdataF_copy_stats,"txdataF_copy",NULL,NULL, output+stroff);
+    stroff += print_meas_log(&ru->ofdm_mod_stats,"feptx_ofdm",NULL,NULL, output+stroff);
+    stroff += print_meas_log(&ru->ofdm_total_stats,"feptx_total",NULL,NULL, output+stroff);
+  }
 
-  PHY_VARS_gNB *gNB  = (PHY_VARS_gNB *)param;
+  if (ru->fh_north_asynch_in) stroff += print_meas_log(&ru->rx_fhaul,"rx_fhaul",NULL,NULL, output+stroff);
 
-  reset_meas(&gNB->phy_proc_tx);
-  reset_meas(&gNB->dlsch_encoding_stats);
-  reset_meas(&gNB->phy_proc_rx);
-  reset_meas(&gNB->ul_indication_stats);
-  reset_meas(&gNB->rx_pusch_stats);
-  reset_meas(&gNB->ulsch_decoding_stats);
-
-  wait_sync("process_stats_thread");
+  stroff += print_meas_log(&ru->tx_fhaul,"tx_fhaul",NULL,NULL, output+stroff);
 
-  while(!oai_exit)
-  {
-    sleep(1);
-    print_meas(&gNB->phy_proc_tx, "L1 Tx processing", NULL, NULL);
-    print_meas(&gNB->dlsch_encoding_stats, "DLSCH encoding", NULL, NULL);
-    print_meas(&gNB->phy_proc_rx, "L1 Rx processing", NULL, NULL);
-    print_meas(&gNB->ul_indication_stats, "UL Indication", NULL, NULL);
-    print_meas(&gNB->rx_pusch_stats, "PUSCH inner-receiver", NULL, NULL);
-    print_meas(&gNB->ulsch_decoding_stats, "PUSCH decoding", NULL, NULL);
+  if (ru->fh_north_out) {
+    stroff += print_meas_log(&ru->compression,"compression",NULL,NULL, output+stroff);
+    stroff += print_meas_log(&ru->transport,"transport",NULL,NULL, output+stroff);
   }
-  return(NULL);
 }
 
 void *nrL1_stats_thread(void *param) {
   PHY_VARS_gNB     *gNB      = (PHY_VARS_gNB *)param;
+  RU_t *ru = RC.ru[0];
+  char output[L1STATSSTRLEN];
+  memset(output,0,L1STATSSTRLEN);
   wait_sync("L1_stats_thread");
   FILE *fd;
-  while (!oai_exit) {
-    sleep(1);
   fd=fopen("nrL1_stats.log","w");
   AssertFatal(fd!=NULL,"Cannot open nrL1_stats.log\n");
+
+  reset_meas(&gNB->phy_proc_tx);
+  reset_meas(&gNB->dlsch_encoding_stats);
+  reset_meas(&gNB->phy_proc_rx);
+  reset_meas(&gNB->ul_indication_stats);
+  reset_meas(&gNB->rx_pusch_stats);
+  reset_meas(&gNB->ulsch_decoding_stats);
+
+  while (!oai_exit) {
+    sleep(1);
     dump_nr_I0_stats(fd,gNB);
     dump_pusch_stats(fd,gNB);
-    //    nr_dump_uci_stats(fd,eNB,eNB->proc.L1_proc_tx.frame_tx);
-    fclose(fd);
+    dump_L1_meas_stats(gNB, ru, output);
+    fprintf(fd,"%s\n",output);
+    fflush(fd);
+    fseek(fd,0,SEEK_SET);
   }
+  fclose(fd);
   return(NULL);
 }
 
@@ -399,8 +415,6 @@ void init_gNB_Tpool(int inst) {
   gNB->resp_RU_tx = (notifiedFIFO_t*) malloc(sizeof(notifiedFIFO_t));
   initNotifiedFIFO(gNB->resp_RU_tx);
 
-  // Stats measurement thread
-  if(opp_enabled == 1) threadCreate(&proc->process_stats_thread, process_stats_thread,(void *)gNB, "time_meas", -1, OAI_PRIORITY_RT_LOW);
   threadCreate(&proc->L1_stats_thread,nrL1_stats_thread,(void*)gNB,"L1_stats",-1,OAI_PRIORITY_RT_LOW);
 
 }

executables/nr-ru.c

@@ -1122,37 +1122,6 @@ int setup_RU_buffers(RU_t *ru) {
   return(0);
 }
 
-void *ru_stats_thread(void *param) {
-  RU_t               *ru      = (RU_t *)param;
-  wait_sync("ru_stats_thread");
-
-  while (!oai_exit) {
-    sleep(1);
-
-    if (opp_enabled == 1) {
-      if (ru->feprx) print_meas(&ru->ofdm_demod_stats,"feprx",NULL,NULL);
-
-      if (ru->feptx_ofdm) {
-        print_meas(&ru->precoding_stats,"feptx_prec",NULL,NULL);
-        print_meas(&ru->txdataF_copy_stats,"txdataF_copy",NULL,NULL);
-        print_meas(&ru->ofdm_mod_stats,"feptx_ofdm",NULL,NULL);
-        print_meas(&ru->ofdm_total_stats,"feptx_total",NULL,NULL);
-      }
-
-      if (ru->fh_north_asynch_in) print_meas(&ru->rx_fhaul,"rx_fhaul",NULL,NULL);
-
-      print_meas(&ru->tx_fhaul,"tx_fhaul",NULL,NULL);
-
-      if (ru->fh_north_out) {
-        print_meas(&ru->compression,"compression",NULL,NULL);
-        print_meas(&ru->transport,"transport",NULL,NULL);
-      }
-    }
-  }
-
-  return(NULL);
-}
-
 void ru_tx_func(void *param) {
   processingData_RU_t *info = (processingData_RU_t *) param;
   RU_t *ru = info->ru;
@@ -1459,7 +1428,6 @@ void init_RU_proc(RU_t *ru) {
     if (ru->feptx_ofdm) nr_init_feptx_thread(ru);
   }
 
-  if (opp_enabled == 1) threadCreate(&ru->ru_stats_thread,ru_stats_thread,(void *)ru, "emulateRF", -1, OAI_PRIORITY_RT_LOW);
 }
 
 void kill_NR_RU_proc(int inst) {

openair1/PHY/TOOLS/time_meas.c

@@ -121,6 +121,49 @@ void print_meas(time_stats_t *ts,
   }
 }
 
+int print_meas_log(time_stats_t *ts,
+                const char *name,
+                time_stats_t *total_exec_time,
+                time_stats_t *sf_exec_time,
+                char *output)
+{
+  int stroff = 0;
+  static int first_time = 0;
+  static double cpu_freq_GHz = 0.0;
+
+  if (cpu_freq_GHz == 0.0)
+    cpu_freq_GHz = get_cpu_freq_GHz();
+
+  if (first_time == 0) {
+    first_time=1;
+
+    if ((total_exec_time == NULL) || (sf_exec_time== NULL))
+      stroff += sprintf(output, "%25s  %25s  %25s  %25s %25s %6f\n","Name","Total","Per Trials",   "Num Trials","CPU_F_GHz", cpu_freq_GHz);
+    else
+      stroff += sprintf(output+stroff, "%25s  %25s  %25s  %20s %15s %6f\n","Name","Total","Average/Frame","Trials",    "CPU_F_GHz", cpu_freq_GHz);
+  }
+
+  if (ts->trials>0) {
+    //printf("%20s: total: %10.3f ms, average: %10.3f us (%10d trials)\n", name, ts->diff/cpu_freq_GHz/1000000.0, ts->diff/ts->trials/cpu_freq_GHz/1000.0, ts->trials);
+    if ((total_exec_time == NULL) || (sf_exec_time== NULL)) {
+      stroff += sprintf(output+stroff, "%25s:  %15.3f us; %15d; %15.3f us;\n",
+              name,
+              (ts->diff/ts->trials/cpu_freq_GHz/1000.0),
+              ts->trials,
+              ts->max/cpu_freq_GHz/1000.0);
+    } else {
+      stroff += sprintf(output+stroff, "%25s:  %15.3f ms (%5.2f%%); %15.3f us (%5.2f%%); %15d;\n",
+              name,
+              (ts->diff/cpu_freq_GHz/1000000.0),
+              ((ts->diff/cpu_freq_GHz/1000000.0)/(total_exec_time->diff/cpu_freq_GHz/1000000.0))*100,  // percentage
+              (ts->diff/ts->trials/cpu_freq_GHz/1000.0),
+              ((ts->diff/ts->trials/cpu_freq_GHz/1000.0)/(sf_exec_time->diff/sf_exec_time->trials/cpu_freq_GHz/1000.0))*100,  // percentage
+              ts->trials);
+    }
+  }
+  return stroff;
+}
+
 double get_time_meas_us(time_stats_t *ts)
 {
   static double cpu_freq_GHz = 0.0;

openair1/PHY/TOOLS/time_meas.h

@@ -62,6 +62,7 @@ static inline void stop_meas(time_stats_t *ts) __attribute__((always_inline));
 
 void print_meas_now(time_stats_t *ts, const char *name, FILE *file_name);
 void print_meas(time_stats_t *ts, const char *name, time_stats_t *total_exec_time, time_stats_t *sf_exec_time);
+int print_meas_log(time_stats_t *ts, const char *name, time_stats_t *total_exec_time, time_stats_t *sf_exec_time, char *output);
 double get_time_meas_us(time_stats_t *ts);
 double get_cpu_freq_GHz(void);
 

openair2/LAYER2/NR_MAC_gNB/main.c

@@ -121,7 +121,7 @@ void dump_mac_stats(gNB_MAC_INST *gNB, char *output, int strlen)
       }
     }
   }
-  print_meas(&gNB->eNB_scheduler, "DL & UL scheduling timing stats", NULL, NULL);
+  print_meas_log(&gNB->eNB_scheduler, "DL & UL scheduling timing stats", NULL, NULL, output+stroff);
 }