From 9e5a4a48680c9a18d5142b5af476c1a96aee090a Mon Sep 17 00:00:00 2001 From: Raymond Knopp Date: Wed, 29 Sep 2021 21:32:22 +0200 Subject: [PATCH 1/2] MAC statistics in separate thread --- openair2/LAYER2/NR_MAC_gNB/gNB_scheduler.c | 82 ++----------------- .../LAYER2/NR_MAC_gNB/gNB_scheduler_uci.c | 1 + openair2/LAYER2/NR_MAC_gNB/mac_proto.h | 1 + openair2/LAYER2/NR_MAC_gNB/main.c | 82 +++++++++++++++++++ openair2/LAYER2/NR_MAC_gNB/nr_mac_gNB.h | 2 + 5 files changed, 92 insertions(+), 76 deletions(-) diff --git a/openair2/LAYER2/NR_MAC_gNB/gNB_scheduler.c b/openair2/LAYER2/NR_MAC_gNB/gNB_scheduler.c index 252144be3b..b5291552f4 100644 --- a/openair2/LAYER2/NR_MAC_gNB/gNB_scheduler.c +++ b/openair2/LAYER2/NR_MAC_gNB/gNB_scheduler.c @@ -62,80 +62,6 @@ uint16_t nr_pdcch_order_table[6] = { 31, 31, 511, 2047, 2047, 8191 }; uint8_t vnf_first_sched_entry = 1; -void clear_mac_stats(gNB_MAC_INST *gNB) { - memset((void*)gNB->UE_info.mac_stats,0,MAX_MOBILES_PER_GNB*sizeof(NR_mac_stats_t)); -} -#define MACSTATSSTRLEN 16384 -void dump_mac_stats(gNB_MAC_INST *gNB) -{ - NR_UE_info_t *UE_info = &gNB->UE_info; - int num = 1; - FILE *fd=fopen("nrMAC_stats.log","w"); - AssertFatal(fd!=NULL,"Cannot open nrMAC_stats.log, error %s\n",strerror(errno)); - char output[MACSTATSSTRLEN]; - memset(output,0,MACSTATSSTRLEN); - int stroff=0; - for (int UE_id = UE_info->list.head; UE_id >= 0; UE_id = UE_info->list.next[UE_id]) { - stroff = sprintf(output,"UE ID %d RNTI %04x (%d/%d)\n", UE_id, UE_info->rnti[UE_id], num++, UE_info->num_UEs); - LOG_I(NR_MAC, "UE ID %d RNTI %04x (%d/%d) PH %d dB PCMAX %d dBm\n", - UE_id, - UE_info->rnti[UE_id], - num++, - UE_info->num_UEs, - UE_info->UE_sched_ctrl[UE_id].ph, - UE_info->UE_sched_ctrl[UE_id].pcmax); - NR_mac_stats_t *stats = &UE_info->mac_stats[UE_id]; - const int avg_rsrp = stats->num_rsrp_meas > 0 ? stats->cumul_rsrp / stats->num_rsrp_meas : 0; - stroff+=sprintf(output+stroff,"UE %d: dlsch_rounds %d/%d/%d/%d, dlsch_errors %d, average RSRP %d (%d meas)\n", - UE_id, - stats->dlsch_rounds[0], stats->dlsch_rounds[1], - stats->dlsch_rounds[2], stats->dlsch_rounds[3], stats->dlsch_errors, - avg_rsrp, stats->num_rsrp_meas); - LOG_I(NR_MAC, "UE %d: dlsch_rounds %d/%d/%d/%d, dlsch_errors %d, average RSRP %d (%d meas)\n", - UE_id, - stats->dlsch_rounds[0], stats->dlsch_rounds[1], - stats->dlsch_rounds[2], stats->dlsch_rounds[3], stats->dlsch_errors, - avg_rsrp, stats->num_rsrp_meas); - stats->num_rsrp_meas = 0; - stats->cumul_rsrp = 0 ; - stroff+=sprintf(output+stroff,"UE %d: dlsch_total_bytes %d\n", UE_id, stats->dlsch_total_bytes); - stroff+=sprintf(output+stroff,"UE %d: ulsch_rounds %d/%d/%d/%d, ulsch_DTX %d, ulsch_errors %d\n", - UE_id, - stats->ulsch_rounds[0], stats->ulsch_rounds[1], - stats->ulsch_rounds[2], stats->ulsch_rounds[3], - stats->ulsch_DTX, - stats->ulsch_errors); - stroff+=sprintf(output+stroff, - "UE %d: ulsch_total_bytes_scheduled %d, ulsch_total_bytes_received %d\n", - UE_id, - stats->ulsch_total_bytes_scheduled, stats->ulsch_total_bytes_rx); - LOG_I(NR_MAC, "UE %d: dlsch_total_bytes %d\n", UE_id, stats->dlsch_total_bytes); - LOG_I(NR_MAC, "UE %d: ulsch_rounds %d/%d/%d/%d, ulsch_DTX %d, ulsch_errors %d\n", - UE_id, - stats->ulsch_rounds[0], stats->ulsch_rounds[1], - stats->ulsch_rounds[2], stats->ulsch_rounds[3], - stats->ulsch_DTX, - stats->ulsch_errors); - LOG_I(NR_MAC, - "UE %d: ulsch_total_bytes_scheduled %d, ulsch_total_bytes_received %d\n", - UE_id, - stats->ulsch_total_bytes_scheduled, stats->ulsch_total_bytes_rx); - for (int lc_id = 0; lc_id < 63; lc_id++) { - if (stats->lc_bytes_tx[lc_id] > 0) { - stroff+=sprintf(output+stroff, "UE %d: LCID %d: %d bytes TX\n", UE_id, lc_id, stats->lc_bytes_tx[lc_id]); - LOG_D(NR_MAC, "UE %d: LCID %d: %d bytes TX\n", UE_id, lc_id, stats->lc_bytes_tx[lc_id]); - } - if (stats->lc_bytes_rx[lc_id] > 0) { - stroff+=sprintf(output+stroff, "UE %d: LCID %d: %d bytes RX\n", UE_id, lc_id, stats->lc_bytes_rx[lc_id]); - LOG_D(NR_MAC, "UE %d: LCID %d: %d bytes RX\n", UE_id, lc_id, stats->lc_bytes_rx[lc_id]); - } - } - } - print_meas(&gNB->eNB_scheduler, "DL & UL scheduling timing stats", NULL, NULL); - if (stroff>0) fprintf(fd,"%s",output); - fclose(fd); -} - void clear_nr_nfapi_information(gNB_MAC_INST * gNB, int CC_idP, frame_t frameP, @@ -354,6 +280,7 @@ void gNB_dlsch_ulsch_scheduler(module_id_t module_idP, PROTOCOL_CTXT_SET_BY_MODULE_ID(&ctxt, module_idP, ENB_FLAG_YES, NOT_A_RNTI, frame, slot,module_idP); const int bwp_id = 1; + char stats_output[16384]; gNB_MAC_INST *gNB = RC.nrmac[module_idP]; NR_COMMON_channels_t *cc = gNB->common_channels; @@ -420,8 +347,11 @@ void gNB_dlsch_ulsch_scheduler(module_id_t module_idP, } - if ((slot == 0) && (frame & 127) == 0) dump_mac_stats(RC.nrmac[module_idP]); - + if ((slot == 0) && (frame & 127) == 0) { + stats_output[0]='\0'; + dump_mac_stats(RC.nrmac[module_idP],stats_output,16384); + LOG_I(NR_MAC,"Frame.Slot %d.%d\n%s\n",frame,slot,stats_output); + } // This schedules MIB schedule_nr_mib(module_idP, frame, slot); diff --git a/openair2/LAYER2/NR_MAC_gNB/gNB_scheduler_uci.c b/openair2/LAYER2/NR_MAC_gNB/gNB_scheduler_uci.c index 6a17cb4879..f3eff1b59e 100644 --- a/openair2/LAYER2/NR_MAC_gNB/gNB_scheduler_uci.c +++ b/openair2/LAYER2/NR_MAC_gNB/gNB_scheduler_uci.c @@ -1084,6 +1084,7 @@ void handle_nr_uci_pucch_0_1(module_id_t mod_id, const int8_t pid = sched_ctrl->feedback_dl_harq.head; remove_front_nr_list(&sched_ctrl->feedback_dl_harq); handle_dl_harq(mod_id, UE_id, pid, harq_value == 1 && harq_confidence == 0); + if (harq_confidence == 1) UE_info->mac_stats[UE_id].pucch0_DTX++; } } diff --git a/openair2/LAYER2/NR_MAC_gNB/mac_proto.h b/openair2/LAYER2/NR_MAC_gNB/mac_proto.h index 391b98af36..a6716918de 100644 --- a/openair2/LAYER2/NR_MAC_gNB/mac_proto.h +++ b/openair2/LAYER2/NR_MAC_gNB/mac_proto.h @@ -435,4 +435,5 @@ bool nr_find_nb_rb(uint16_t Qm, void nr_sr_reporting(int Mod_idP, frame_t frameP, sub_frame_t slotP); +void dump_mac_stats(gNB_MAC_INST *gNB, char *output, int strlen); #endif /*__LAYER2_NR_MAC_PROTO_H__*/ diff --git a/openair2/LAYER2/NR_MAC_gNB/main.c b/openair2/LAYER2/NR_MAC_gNB/main.c index 117c18ae8d..6e13e4bcc6 100644 --- a/openair2/LAYER2/NR_MAC_gNB/main.c +++ b/openair2/LAYER2/NR_MAC_gNB/main.c @@ -45,6 +45,86 @@ extern RAN_CONTEXT_t RC; +#define MACSTATSSTRLEN 16384 + +void *nrmac_stats_thread(void *arg) { + + gNB_MAC_INST *gNB = (gNB_MAC_INST *)arg; + + char output[MACSTATSSTRLEN]; + memset(output,0,MACSTATSSTRLEN); + FILE *fd=fopen("nrMAC_stats.log","w"); + AssertFatal(fd!=NULL,"Cannot open nrMAC_stats.log, error %s\n",strerror(errno)); + + while (oai_exit == 0) { + dump_mac_stats(gNB,output,MACSTATSSTRLEN); + fprintf(fd,"%s\n",output); + fflush(fd); + usleep(200000); + fseek(fd,0,SEEK_SET); + } + fclose(fd); + return (void *)0; +} + +void clear_mac_stats(gNB_MAC_INST *gNB) { + memset((void*)gNB->UE_info.mac_stats,0,MAX_MOBILES_PER_GNB*sizeof(NR_mac_stats_t)); +} + +void dump_mac_stats(gNB_MAC_INST *gNB, char *output, int strlen) +{ + NR_UE_info_t *UE_info = &gNB->UE_info; + int num = 1; + + int stroff=0; + if (UE_info->num_UEs == 0) return; + + for (int UE_id = UE_info->list.head; UE_id >= 0; UE_id = UE_info->list.next[UE_id]) { + + stroff+=sprintf(output+stroff,"UE ID %d RNTI %04x (%d/%d) PH %d dB PCMAX %d dBm\n", + UE_id, + UE_info->rnti[UE_id], + num++, + UE_info->num_UEs, + UE_info->UE_sched_ctrl[UE_id].ph, + UE_info->UE_sched_ctrl[UE_id].pcmax); + + NR_mac_stats_t *stats = &UE_info->mac_stats[UE_id]; + const int avg_rsrp = stats->num_rsrp_meas > 0 ? stats->cumul_rsrp / stats->num_rsrp_meas : 0; + stroff+=sprintf(output+stroff,"UE %d: dlsch_rounds %d/%d/%d/%d, dlsch_errors %d, pucch0_DTX %d average RSRP %d (%d meas)\n", + UE_id, + stats->dlsch_rounds[0], stats->dlsch_rounds[1], + stats->dlsch_rounds[2], stats->dlsch_rounds[3], stats->dlsch_errors, + stats->pucch0_DTX, + avg_rsrp, stats->num_rsrp_meas); + stats->num_rsrp_meas = 0; + stats->cumul_rsrp = 0 ; + stroff+=sprintf(output+stroff,"UE %d: dlsch_total_bytes %d\n", UE_id, stats->dlsch_total_bytes); + stroff+=sprintf(output+stroff,"UE %d: ulsch_rounds %d/%d/%d/%d, ulsch_DTX %d, ulsch_errors %d\n", + UE_id, + stats->ulsch_rounds[0], stats->ulsch_rounds[1], + stats->ulsch_rounds[2], stats->ulsch_rounds[3], + stats->ulsch_DTX, + stats->ulsch_errors); + stroff+=sprintf(output+stroff, + "UE %d: ulsch_total_bytes_scheduled %d, ulsch_total_bytes_received %d\n", + UE_id, + stats->ulsch_total_bytes_scheduled, stats->ulsch_total_bytes_rx); + for (int lc_id = 0; lc_id < 63; lc_id++) { + if (stats->lc_bytes_tx[lc_id] > 0) { + stroff+=sprintf(output+stroff, "UE %d: LCID %d: %d bytes TX\n", UE_id, lc_id, stats->lc_bytes_tx[lc_id]); + LOG_D(NR_MAC, "UE %d: LCID %d: %d bytes TX\n", UE_id, lc_id, stats->lc_bytes_tx[lc_id]); + } + if (stats->lc_bytes_rx[lc_id] > 0) { + stroff+=sprintf(output+stroff, "UE %d: LCID %d: %d bytes RX\n", UE_id, lc_id, stats->lc_bytes_rx[lc_id]); + LOG_D(NR_MAC, "UE %d: LCID %d: %d bytes RX\n", UE_id, lc_id, stats->lc_bytes_rx[lc_id]); + } + } + } + print_meas(&gNB->eNB_scheduler, "DL & UL scheduling timing stats", NULL, NULL); +} + + void mac_top_init_gNB(void) { module_id_t i; @@ -90,6 +170,7 @@ void mac_top_init_gNB(void) RC.nrmac[i]->pre_processor_dl = nr_init_fr1_dlsch_preprocessor(i, 0); RC.nrmac[i]->pre_processor_ul = nr_init_fr1_ulsch_preprocessor(i, 0); } + pthread_create(&RC.nrmac[i]->stats_thread,NULL,nrmac_stats_thread,(void*)RC.nrmac[i]); }//END for (i = 0; i < RC.nb_nr_macrlc_inst; i++) @@ -103,6 +184,7 @@ void mac_top_init_gNB(void) rrc_init_nr_global_param(); + } else { RC.nrmac = NULL; } diff --git a/openair2/LAYER2/NR_MAC_gNB/nr_mac_gNB.h b/openair2/LAYER2/NR_MAC_gNB/nr_mac_gNB.h index 22da5223c0..6251ce2a70 100644 --- a/openair2/LAYER2/NR_MAC_gNB/nr_mac_gNB.h +++ b/openair2/LAYER2/NR_MAC_gNB/nr_mac_gNB.h @@ -616,6 +616,7 @@ typedef struct { int ulsch_total_bytes_scheduled; int ulsch_total_bytes_rx; int ulsch_current_bytes; + int pucch0_DTX; int cumul_rsrp; uint8_t num_rsrp_meas; } NR_mac_stats_t; @@ -662,6 +663,7 @@ typedef struct gNB_MAC_INST_s { NR_TAG_t *tag; /// Pointer to IF module instance for PHY NR_IF_Module_t *if_inst; + pthread_t stats_thread; /// Pusch target SNR int pusch_target_snrx10; /// Pucch target SNR From 35d150771ed8c6f8bc02ee3b8c58eefc2aeb6fce Mon Sep 17 00:00:00 2001 From: Sakthivel Velumani Date: Sat, 2 Oct 2021 14:02:29 +0530 Subject: [PATCH 2/2] L1 perf logging changes Moved the L1 timing stats logs from stdout to nrL1_stats.log --- executables/nr-gnb.c | 68 +++++++++++++++++++------------ 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, 86 insertions(+), 60 deletions(-) diff --git a/executables/nr-gnb.c b/executables/nr-gnb.c index ce09531e78..ca76efc86a 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,9 +322,42 @@ 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); - PHY_VARS_gNB *gNB = (PHY_VARS_gNB *)param; + 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); + } + + if (ru->fh_north_asynch_in) stroff += print_meas_log(&ru->rx_fhaul,"rx_fhaul",NULL,NULL, output+stroff); + + stroff += print_meas_log(&ru->tx_fhaul,"tx_fhaul",NULL,NULL, output+stroff); + + 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); + } +} + +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); @@ -332,34 +366,16 @@ static void *process_stats_thread(void *param) { reset_meas(&gNB->rx_pusch_stats); reset_meas(&gNB->ulsch_decoding_stats); - 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); - } - return(NULL); -} - -void *nrL1_stats_thread(void *param) { - PHY_VARS_gNB *gNB = (PHY_VARS_gNB *)param; - 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"); 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 2de04f4e7f..383c0a691c 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 001770c876..05c09e443c 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 e2ceef8405..fefd43710c 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 6e13e4bcc6..af386163e9 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); }