From 35d150771ed8c6f8bc02ee3b8c58eefc2aeb6fce Mon Sep 17 00:00:00 2001
From: Sakthivel Velumani <velumani@eurecom.fr>
Date: Sat, 2 Oct 2021 14:02:29 +0530
Subject: [PATCH] L1 perf logging changes Moved the L1 timing stats logs from
stdout to nrL1_stats.log
---
executables/nr-gnb.c | 66 +++++++++++++++++++------------
executables/nr-ru.c | 32 ---------------
openair1/PHY/TOOLS/time_meas.c | 43 ++++++++++++++++++++
openair1/PHY/TOOLS/time_meas.h | 1 +
openair2/LAYER2/NR_MAC_gNB/main.c | 2 +-
5 files changed, 85 insertions(+), 59 deletions(-)
diff --git a/executables/nr-gnb.c b/executables/nr-gnb.c
index ce09531e78d..ca76efc86ae 100644
--- a/executables/nr-gnb.c
+++ b/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);
+ stroff += print_meas_log(&ru->tx_fhaul,"tx_fhaul",NULL,NULL, output+stroff);
- wait_sync("process_stats_thread");
-
- 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;
+ 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);
- fd=fopen("nrL1_stats.log","w");
- AssertFatal(fd!=NULL,"Cannot open nrL1_stats.log\n");
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);
}
diff --git a/executables/nr-ru.c b/executables/nr-ru.c
index 2de04f4e7fc..383c0a691ca 100644
--- a/executables/nr-ru.c
+++ b/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) {
diff --git a/openair1/PHY/TOOLS/time_meas.c b/openair1/PHY/TOOLS/time_meas.c
index 001770c876f..05c09e443c6 100644
--- a/openair1/PHY/TOOLS/time_meas.c
+++ b/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;
diff --git a/openair1/PHY/TOOLS/time_meas.h b/openair1/PHY/TOOLS/time_meas.h
index e2ceef84050..fefd43710ca 100644
--- a/openair1/PHY/TOOLS/time_meas.h
+++ b/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);
diff --git a/openair2/LAYER2/NR_MAC_gNB/main.c b/openair2/LAYER2/NR_MAC_gNB/main.c
index 6e13e4bcc62..af386163e98 100644
--- a/openair2/LAYER2/NR_MAC_gNB/main.c
+++ b/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);
}
--
GitLab