From 9e5a4a48680c9a18d5142b5af476c1a96aee090a Mon Sep 17 00:00:00 2001 From: Raymond Knopp Date: Wed, 29 Sep 2021 21:32:22 +0200 Subject: [PATCH 1/9] 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/9] 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); } From f64b884ef8cb0171fce5b61bf2b919836b9031d4 Mon Sep 17 00:00:00 2001 From: hardy Date: Thu, 4 Nov 2021 10:48:17 +0100 Subject: [PATCH 3/9] add X2AP-PDU msg cnt to HTML --- ci-scripts/ran.py | 12 +++++++++++- 1 file changed, 11 insertions(+), 1 deletion(-) diff --git a/ci-scripts/ran.py b/ci-scripts/ran.py index 9acb1de34e..7d8fb98b86 100644 --- a/ci-scripts/ran.py +++ b/ci-scripts/ran.py @@ -792,6 +792,8 @@ class RANManagement(): pb_receiving_samples_cnt = 0 #count "removing UE" msg removing_ue = 0 + #count"X2AP-PDU" + x2ap_pdu = 0 #NSA specific log markers nsa_markers ={'SgNBReleaseRequestAcknowledge': [],'FAILURE': [], 'scgFailureInformationNR-r15': [], 'SgNBReleaseRequest': []} @@ -993,7 +995,10 @@ class RANManagement(): result = re.search('\[MAC\]\s+Removing UE', str(line)) if result is not None: removing_ue += 1 - + #count "X2AP-PDU" + result = re.search('X2AP-PDU', str(line)) + if result is not None: + x2ap_pdu += 1 #nsa markers logging for k in nsa_markers: result = re.search(k, line) @@ -1087,6 +1092,11 @@ class RANManagement(): htmlMsg = statMsg+'\n' logging.debug(statMsg) htmleNBFailureMsg += htmlMsg + #X2AP-PDU log + statMsg = 'X2AP-PDU msg count = '+str(x2ap_pdu) + htmlMsg = statMsg+'\n' + logging.debug(statMsg) + htmleNBFailureMsg += htmlMsg #nsa markers statMsg = 'logfile line count = ' + str(line_cnt) htmlMsg = statMsg+'\n' From 5b9de9c1e3d6684841151a205ad2ff156e32a2f3 Mon Sep 17 00:00:00 2001 From: hardy Date: Thu, 4 Nov 2021 16:51:47 +0100 Subject: [PATCH 4/9] moved source for rt stats analysis : from stdout to stat log files --- ci-scripts/ran.py | 73 +++++++++++++++++++++++++++++++---------------- 1 file changed, 49 insertions(+), 24 deletions(-) diff --git a/ci-scripts/ran.py b/ci-scripts/ran.py index 7d8fb98b86..cdc28f0e37 100644 --- a/ci-scripts/ran.py +++ b/ci-scripts/ran.py @@ -797,20 +797,6 @@ class RANManagement(): #NSA specific log markers nsa_markers ={'SgNBReleaseRequestAcknowledge': [],'FAILURE': [], 'scgFailureInformationNR-r15': [], 'SgNBReleaseRequest': []} - #the datalog config file has to be loaded - datalog_rt_stats_file='datalog_rt_stats.yaml' - if (os.path.isfile(datalog_rt_stats_file)): - yaml_file=datalog_rt_stats_file - elif (os.path.isfile('ci-scripts/'+datalog_rt_stats_file)): - yaml_file='ci-scripts/'+datalog_rt_stats_file - else: - logging.error("Datalog RT stats yaml file cannot be found") - sys.exit("Datalog RT stats yaml file cannot be found") - - with open(yaml_file,'r') as f: - datalog_rt_stats = yaml.load(f,Loader=yaml.FullLoader) - rt_keys = datalog_rt_stats['Ref'] #we use the keys from the Ref field - line_cnt=0 #log file line counter for line in enb_log_file.readlines(): line_cnt+=1 @@ -977,15 +963,7 @@ class RANManagement(): if result is not None: #remove 1- all useless char before relevant info (ulsch or dlsch) 2- trailing char dlsch_ulsch_stats[k]=re.sub(r'^.*\]\s+', r'' , line.rstrip()) - #real time statistics for gNB - for k in rt_keys: - result = re.search(k, line) - if result is not None: - #remove 1- all useless char before relevant info 2- trailing char - line=line.replace('[0m','') - tmp=re.match(rf'^.*?(\b{k}\b.*)',line.rstrip()) #from python 3.6 we can use literal string interpolation for the variable k, using rf' in the regex - if tmp!=None: #with ULULULUULULULLLL at the head of the line, we skip it - real_time_stats[k]=tmp.group(1) + #count "problem receiving samples" msg result = re.search('\[PHY\]\s+problem receiving samples', str(line)) @@ -1006,7 +984,54 @@ class RANManagement(): nsa_markers[k].append(line_cnt) enb_log_file.close() - logging.debug(' File analysis completed') + + + #the following part takes the *_stats.log files as source (not the stdout log file) + + #the datalog config file has to be loaded + datalog_rt_stats_file='datalog_rt_stats.yaml' + if (os.path.isfile(datalog_rt_stats_file)): + yaml_file=datalog_rt_stats_file + elif (os.path.isfile('ci-scripts/'+datalog_rt_stats_file)): + yaml_file='ci-scripts/'+datalog_rt_stats_file + else: + logging.error("Datalog RT stats yaml file cannot be found") + sys.exit("Datalog RT stats yaml file cannot be found") + + with open(yaml_file,'r') as f: + datalog_rt_stats = yaml.load(f,Loader=yaml.FullLoader) + rt_keys = datalog_rt_stats['Ref'] #we use the keys from the Ref field + + if (os.path.isfile('./nrL1_stats.log')) and (os.path.isfile('./nrL1_stats.log')): + stat_files_present=True + else: + logging.debug("NR Stats files for RT analysis not found") + if stat_files_present: + nrL1_stat = open('./nrL1_stats.log', 'r') + nrMAC_stat = open('./nrMAC_stats.log', 'r') + for line in nrL1_stat.readlines(): + for k in rt_keys: + result = re.search(k, line) + if result is not None: + #remove 1- all useless char before relevant info 2- trailing char + tmp=re.match(rf'^.*?(\b{k}\b.*)',line.rstrip()) #from python 3.6 we can use literal string interpolation for the variable k, using rf' in the regex + if tmp!=None: + real_time_stats[k]=tmp.group(1) + for line in nrMAC_stat.readlines(): + for k in rt_keys: + result = re.search(k, line) + if result is not None: + #remove 1- all useless char before relevant info 2- trailing char + tmp=re.match(rf'^.*?(\b{k}\b.*)',line.rstrip()) #from python 3.6 we can use literal string interpolation for the variable k, using rf' in the regex + if tmp!=None: + real_time_stats[k]=tmp.group(1) + nrL1_stats.close() + nrMAC_stats.close() + + #stdout log file and stat log files analysis completed + logging.debug(' File analysis (stdout, stats) completed') + + #post processing depending on the node type if (self.air_interface[self.eNB_instance] == 'lte-softmodem') or (self.air_interface[self.eNB_instance] == 'ocp-enb'): nodeB_prefix = 'e' else: From 9374eda06e06e3d907ae2cf9bcc6fbd0fad2e9ba Mon Sep 17 00:00:00 2001 From: hardy Date: Thu, 4 Nov 2021 17:36:07 +0100 Subject: [PATCH 5/9] fix typo in file handlers --- ci-scripts/ran.py | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/ci-scripts/ran.py b/ci-scripts/ran.py index cdc28f0e37..2255273174 100644 --- a/ci-scripts/ran.py +++ b/ci-scripts/ran.py @@ -1007,9 +1007,9 @@ class RANManagement(): else: logging.debug("NR Stats files for RT analysis not found") if stat_files_present: - nrL1_stat = open('./nrL1_stats.log', 'r') - nrMAC_stat = open('./nrMAC_stats.log', 'r') - for line in nrL1_stat.readlines(): + nrL1_stats = open('./nrL1_stats.log', 'r') + nrMAC_stats = open('./nrMAC_stats.log', 'r') + for line in nrL1_stats.readlines(): for k in rt_keys: result = re.search(k, line) if result is not None: @@ -1017,7 +1017,7 @@ class RANManagement(): tmp=re.match(rf'^.*?(\b{k}\b.*)',line.rstrip()) #from python 3.6 we can use literal string interpolation for the variable k, using rf' in the regex if tmp!=None: real_time_stats[k]=tmp.group(1) - for line in nrMAC_stat.readlines(): + for line in nrMAC_stats.readlines(): for k in rt_keys: result = re.search(k, line) if result is not None: From 90e84c01d4d941d7b8e93b24b561c76b1225926a Mon Sep 17 00:00:00 2001 From: hardy Date: Thu, 4 Nov 2021 18:08:03 +0100 Subject: [PATCH 6/9] test : add some rt stats to the monitor (graph) --- ci-scripts/stats_monitor.py | 12 ++++++++++-- ci-scripts/stats_monitor_conf.yaml | 5 ++++- 2 files changed, 14 insertions(+), 3 deletions(-) diff --git a/ci-scripts/stats_monitor.py b/ci-scripts/stats_monitor.py index 877194de59..7098f8f6a2 100755 --- a/ci-scripts/stats_monitor.py +++ b/ci-scripts/stats_monitor.py @@ -35,7 +35,15 @@ class StatMonitor(): self.d[node_type]['ulsch_err'].append(int(result.group(3))) percentage=float(result.group(2))/float(result.group(1)) self.d[node_type]['ulsch_err_perc_round_1'].append(percentage) - + result=re.match(r'^.*\bL1 Tx processing thread 0\b:\s+([0-9\.]+) us;\s+([0-9]+);\s+([0-9\.]+) us;',tmp) + if result is not None: + self.d[node_type]['L1 Tx processing thread 0'].append(float(result.group(3))) + result=re.match(r'^.*\bL1 Tx processing thread 1\b:\s+([0-9\.]+) us;\s+([0-9]+);\s+([0-9\.]+) us;',tmp) + if result is not None: + self.d[node_type]['L1 Tx processing thread 1'].append(float(result.group(3))) + result=re.match(r'^.*\bDLSCH encoding\b:\s+([0-9\.]+) us;\s+([0-9]+);\s+([0-9\.]+) us;',tmp) + if result is not None: + self.d[node_type]['DLSCH encoding'].append(float(result.group(3))) def process_enb (self,node_type,output): for line in output: @@ -88,7 +96,7 @@ if __name__ == "__main__": mon=StatMonitor(cfg_filename) #collecting stats when modem process is stopped - CMD='ps aux | grep mode | grep -v grep' + CMD='ps aux | grep modem | grep -v grep' process=subprocess.Popen(CMD, shell=True, stdout=subprocess.PIPE) output = process.stdout.readlines() while len(output)!=0 : diff --git a/ci-scripts/stats_monitor_conf.yaml b/ci-scripts/stats_monitor_conf.yaml index 6c0a2b0225..b94d74a24c 100644 --- a/ci-scripts/stats_monitor_conf.yaml +++ b/ci-scripts/stats_monitor_conf.yaml @@ -8,4 +8,7 @@ gnb : dlsch_err: dlsch_err_perc_round_1: ulsch_err: - ulsch_err_perc_round_1: \ No newline at end of file + ulsch_err_perc_round_1: + L1 Tx processing thread 0: + L1 Tx processing thread 1: + DLSCH encoding: \ No newline at end of file From 2b36b1f32e7c2008e34ecb238268a54bacb62b3c Mon Sep 17 00:00:00 2001 From: hardy Date: Fri, 5 Nov 2021 09:17:01 +0100 Subject: [PATCH 7/9] redefine monitor conf file + paged graphs --- ci-scripts/ran.py | 4 +- ci-scripts/stats_monitor.py | 73 ++++++++++++++++++------------ ci-scripts/stats_monitor_conf.yaml | 45 ++++++++++++++++-- 3 files changed, 88 insertions(+), 34 deletions(-) diff --git a/ci-scripts/ran.py b/ci-scripts/ran.py index 2255273174..56b063a0b8 100644 --- a/ci-scripts/ran.py +++ b/ci-scripts/ran.py @@ -734,8 +734,8 @@ class RANManagement(): mySSH.command('echo ' + self.eNBPassword + ' | sudo -S mv /tmp/enb_*.pcap .','\$',20) mySSH.command('echo ' + self.eNBPassword + ' | sudo -S mv /tmp/gnb_*.pcap .','\$',20) mySSH.command('echo ' + self.eNBPassword + ' | sudo -S rm -f enb.log.zip', '\$', 5) - mySSH.command('echo ' + self.eNBPassword + ' | sudo -S zip enb.log.zip enb*.log core* enb_*record.raw enb_*.pcap gnb_*.pcap enb_*txt physim_*.log *stats.log *monitor.pickle *monitor.png', '\$', 60) - mySSH.command('echo ' + self.eNBPassword + ' | sudo -S rm enb*.log core* enb_*record.raw enb_*.pcap gnb_*.pcap enb_*txt physim_*.log *stats.log *.pickle *.png', '\$', 5) + mySSH.command('echo ' + self.eNBPassword + ' | sudo -S zip enb.log.zip enb*.log core* enb_*record.raw enb_*.pcap gnb_*.pcap enb_*txt physim_*.log *stats.log *monitor.pickle *monitor*.png', '\$', 60) + mySSH.command('echo ' + self.eNBPassword + ' | sudo -S rm enb*.log core* enb_*record.raw enb_*.pcap gnb_*.pcap enb_*txt physim_*.log *stats.log *monitor.pickle *monitor*.png', '\$', 5) mySSH.close() def AnalyzeLogFile_eNB(self, eNBlogFile, HTML): diff --git a/ci-scripts/stats_monitor.py b/ci-scripts/stats_monitor.py index 7098f8f6a2..933bf13203 100755 --- a/ci-scripts/stats_monitor.py +++ b/ci-scripts/stats_monitor.py @@ -17,9 +17,15 @@ class StatMonitor(): def __init__(self,cfg_file): with open(cfg_file,'r') as file: self.d = yaml.load(file) - for node in self.d: - for metric in self.d[node]: - self.d[node][metric]=[] + for node in self.d:#so far we have enb or gnb as nodes + for metric_l1 in self.d[node]: #first level of metric keys + if metric_l1!="graph": #graph is a reserved word to configure graph paging, so it is disregarded + if self.d[node][metric_l1] is None:#first level is None -> create array + self.d[node][metric_l1]=[] + else: #first level is not None -> there is a second level -> create array + for metric_l2 in self.d[node][metric_l1]: + self.d[node][metric_l1][metric_l2]=[] + def process_gnb (self,node_type,output): @@ -35,15 +41,12 @@ class StatMonitor(): self.d[node_type]['ulsch_err'].append(int(result.group(3))) percentage=float(result.group(2))/float(result.group(1)) self.d[node_type]['ulsch_err_perc_round_1'].append(percentage) - result=re.match(r'^.*\bL1 Tx processing thread 0\b:\s+([0-9\.]+) us;\s+([0-9]+);\s+([0-9\.]+) us;',tmp) - if result is not None: - self.d[node_type]['L1 Tx processing thread 0'].append(float(result.group(3))) - result=re.match(r'^.*\bL1 Tx processing thread 1\b:\s+([0-9\.]+) us;\s+([0-9]+);\s+([0-9\.]+) us;',tmp) - if result is not None: - self.d[node_type]['L1 Tx processing thread 1'].append(float(result.group(3))) - result=re.match(r'^.*\bDLSCH encoding\b:\s+([0-9\.]+) us;\s+([0-9]+);\s+([0-9\.]+) us;',tmp) - if result is not None: - self.d[node_type]['DLSCH encoding'].append(float(result.group(3))) + + for k in self.d[node_type]['rt']: + result=re.match(rf'^.*\b{k}\b:\s+([0-9\.]+) us;\s+([0-9]+);\s+([0-9\.]+) us;',tmp) + if result is not None: + self.d[node_type]['rt'][k].append(float(result.group(3))) + def process_enb (self,node_type,output): for line in output: @@ -70,23 +73,37 @@ class StatMonitor(): def graph(self,node_type): - col = 1 - figure, axis = plt.subplots(len(self.d[node_type]), col ,figsize=(10, 10)) - i=0 - for metric in self.d[node_type]: - major_ticks = np.arange(0, len(self.d[node_type][metric])+1, 1) - axis[i].set_xticks(major_ticks) - axis[i].set_xticklabels([]) - axis[i].plot(self.d[node_type][metric],marker='o') - axis[i].set_xlabel('time') - axis[i].set_ylabel(metric) - axis[i].set_title(metric) - i+=1 + for page in self.d[node_type]['graph']:#work out a set a graphs per page + col = 1 + figure, axis = plt.subplots(len(self.d[node_type]['graph'][page]), col ,figsize=(10, 10)) + i=0 + for m in self.d[node_type]['graph'][page]:#metric may refer to 1 level or 2 levels + metric_path=m.split('.') + if len(metric_path)==1:#1 level + metric_l1=metric_path[0] + major_ticks = np.arange(0, len(self.d[node_type][metric_l1])+1, 1) + axis[i].set_xticks(major_ticks) + axis[i].set_xticklabels([]) + axis[i].plot(self.d[node_type][metric_l1],marker='o') + axis[i].set_xlabel('time') + axis[i].set_ylabel(metric_l1) + axis[i].set_title(metric_l1) + + else:#2 levels + metric_l1=metric_path[0] + metric_l2=metric_path[1] + major_ticks = np.arange(0, len(self.d[node_type][metric_l1][metric_l2])+1, 1) + axis[i].set_xticks(major_ticks) + axis[i].set_xticklabels([]) + axis[i].plot(self.d[node_type][metric_l1][metric_l2],marker='o') + axis[i].set_xlabel('time') + axis[i].set_ylabel(metric_l2) + axis[i].set_title(metric_l2) + i+=1 - plt.tight_layout() - # Combine all the operations and display - plt.savefig(node_type+'_stats_monitor.png') - plt.show() + plt.tight_layout() + #save as png + plt.savefig(node_type+'_stats_monitor_'+page+'.png') if __name__ == "__main__": diff --git a/ci-scripts/stats_monitor_conf.yaml b/ci-scripts/stats_monitor_conf.yaml index b94d74a24c..8760c067fc 100644 --- a/ci-scripts/stats_monitor_conf.yaml +++ b/ci-scripts/stats_monitor_conf.yaml @@ -2,13 +2,50 @@ enb : PHR: bler: mcsoff: - mcs: + mcs: + graph: + page1: + PHR: + bler: + mcsoff: + mcs: gnb : dlsch_err: dlsch_err_perc_round_1: ulsch_err: ulsch_err_perc_round_1: - L1 Tx processing thread 0: - L1 Tx processing thread 1: - DLSCH encoding: \ No newline at end of file + rt : + feprx: + feptx_prec: + feptx_ofdm: + feptx_total: + L1 Tx processing thread 0: + L1 Tx processing thread 1: + DLSCH encoding: + L1 Rx processing: + PUSCH inner-receiver: + PUSCH decoding: + DL & UL scheduling timing stats: + UL Indication: + graph : + page1: + dlsch_err: + dlsch_err_perc_round_1: + ulsch_err: + ulsch_err_perc_round_1: + page2: + rt.feprx: + rt.feptx_prec: + rt.feptx_ofdm: + rt.feptx_total: + page3: + rt.L1 Tx processing thread 0: + rt.L1 Tx processing thread 1: + rt.DLSCH encoding: + rt.L1 Rx processing: + page4: + rt.PUSCH inner-receiver: + rt.PUSCH decoding: + rt.DL & UL scheduling timing stats: + rt.UL Indication: \ No newline at end of file From 0165719a3b76685531d6b5dcc88806a81158ce14 Mon Sep 17 00:00:00 2001 From: hardy Date: Fri, 5 Nov 2021 14:27:14 +0100 Subject: [PATCH 8/9] fix target IP address for pings with CN5G --- ci-scripts/cls_oaicitest.py | 2 +- ci-scripts/epc.py | 1 - 2 files changed, 1 insertion(+), 2 deletions(-) diff --git a/ci-scripts/cls_oaicitest.py b/ci-scripts/cls_oaicitest.py index 92a4e8637e..0423828650 100644 --- a/ci-scripts/cls_oaicitest.py +++ b/ci-scripts/cls_oaicitest.py @@ -1583,7 +1583,7 @@ class OaiCiTest(): if re.match('OAI-Rel14-Docker', EPC.Type, re.IGNORECASE): Target = EPC.MmeIPAddress elif re.match('OAICN5G', EPC.Type, re.IGNORECASE): - Target = '8.8.8.8' + Target = EPC.MmeIPAddress else: Target = EPC.IPAddress #ping from module NIC rather than IP address to make sure round trip is over the air diff --git a/ci-scripts/epc.py b/ci-scripts/epc.py index 8376e07fd5..b8c2050793 100644 --- a/ci-scripts/epc.py +++ b/ci-scripts/epc.py @@ -62,7 +62,6 @@ class EPCManagement(): self.PcapFileName = '' self.testCase_id = '' self.MmeIPAddress = '' - self.AmfIPAddress = '' self.containerPrefix = 'prod' self.mmeConfFile = 'mme.conf' self.yamlPath = '' From 4106a3a09184a2d0db4d394adf47fd7cc804bffe Mon Sep 17 00:00:00 2001 From: hardy Date: Fri, 5 Nov 2021 16:51:54 +0100 Subject: [PATCH 9/9] fix rt stats bug for enb (skip) --- ci-scripts/ran.py | 1 + 1 file changed, 1 insertion(+) diff --git a/ci-scripts/ran.py b/ci-scripts/ran.py index 56b063a0b8..a9e5aa236a 100644 --- a/ci-scripts/ran.py +++ b/ci-scripts/ran.py @@ -1005,6 +1005,7 @@ class RANManagement(): if (os.path.isfile('./nrL1_stats.log')) and (os.path.isfile('./nrL1_stats.log')): stat_files_present=True else: + stat_files_present=False logging.debug("NR Stats files for RT analysis not found") if stat_files_present: nrL1_stats = open('./nrL1_stats.log', 'r')