From db2c03d31d58ef3d5442661e0ae82839b4d4a814 Mon Sep 17 00:00:00 2001 From: Robert Schmidt Date: Wed, 25 May 2022 16:21:25 +0200 Subject: [PATCH 1/9] Do not abort ULSCH decoding in phy-test mode For the RAN-gNB-nrUE-MONO-TDD-Band78-N300 test, in order to measure ULSCH decoding times, we cannot abort ULSCH decoding on DTX. --- openair1/SCHED_NR/phy_procedures_nr_gNB.c | 8 ++++++-- 1 file changed, 6 insertions(+), 2 deletions(-) diff --git a/openair1/SCHED_NR/phy_procedures_nr_gNB.c b/openair1/SCHED_NR/phy_procedures_nr_gNB.c index cdfdfe8e30..c333145b5f 100644 --- a/openair1/SCHED_NR/phy_procedures_nr_gNB.c +++ b/openair1/SCHED_NR/phy_procedures_nr_gNB.c @@ -793,10 +793,14 @@ int phy_procedures_gNB_uespec_RX(PHY_VARS_gNB *gNB, int frame_rx, int slot_rx) { dB_fixed_x10(gNB->pusch_vars[ULSCH_id]->ulsch_power_tot), dB_fixed_x10(gNB->pusch_vars[ULSCH_id]->ulsch_noise_power_tot),gNB->pusch_thres); gNB->pusch_vars[ULSCH_id]->ulsch_power_tot = gNB->pusch_vars[ULSCH_id]->ulsch_noise_power_tot; - nr_fill_indication(gNB,frame_rx, slot_rx, ULSCH_id, harq_pid, 1,1); gNB->pusch_vars[ULSCH_id]->DTX=1; if (stats) stats->DTX++; - return 1; + if (!get_softmodem_params()->phy_test) { + /* in case of phy_test mode, we still want to decode to measure execution time. + Therefore, we don't yet call nr_fill_indication, it will be called later */ + nr_fill_indication(gNB,frame_rx, slot_rx, ULSCH_id, harq_pid, 1,1); + return 1; + } } else { LOG_D(PHY, "PUSCH detected in %d.%d (%d,%d,%d)\n",frame_rx,slot_rx, dB_fixed_x10(gNB->pusch_vars[ULSCH_id]->ulsch_power_tot), From dd801325d471c908c4b5192918bb73332e1c15a8 Mon Sep 17 00:00:00 2001 From: Robert Schmidt Date: Fri, 3 Jun 2022 17:10:03 +0200 Subject: [PATCH 2/9] Terminate LOG with newline --- executables/nr-gnb.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/executables/nr-gnb.c b/executables/nr-gnb.c index 8ea7f16712..66d5c549e7 100644 --- a/executables/nr-gnb.c +++ b/executables/nr-gnb.c @@ -380,7 +380,7 @@ void *tx_reorder_thread(void* param) { if (resL1Reserve) { resL1=resL1Reserve; if (((processingData_L1tx_t *)NotifiedFifoData(resL1))->slot != next_tx_slot) { - LOG_E(PHY,"order mistake"); + LOG_E(PHY,"order mistake\n"); resL1Reserve=NULL; resL1 = pullTpool(gNB->L1_tx_out, gNB->threadPool); } From 43701ddbd6bef4b7f5b3b6a20294807579ac3518 Mon Sep 17 00:00:00 2001 From: Robert Schmidt Date: Fri, 3 Jun 2022 17:11:05 +0200 Subject: [PATCH 3/9] Phy-test scheduler: update MCS so it is shown in logs --- openair2/LAYER2/NR_MAC_gNB/gNB_scheduler_phytest.c | 2 ++ 1 file changed, 2 insertions(+) diff --git a/openair2/LAYER2/NR_MAC_gNB/gNB_scheduler_phytest.c b/openair2/LAYER2/NR_MAC_gNB/gNB_scheduler_phytest.c index aff03a5323..91a34fdfb8 100644 --- a/openair2/LAYER2/NR_MAC_gNB/gNB_scheduler_phytest.c +++ b/openair2/LAYER2/NR_MAC_gNB/gNB_scheduler_phytest.c @@ -309,6 +309,7 @@ void nr_preprocessor_phytest(module_id_t module_id, sched_pdsch->rbSize = rbSize; sched_pdsch->mcs = target_dl_mcs; + sched_ctrl->dl_bler_stats.mcs = target_dl_mcs; /* for logging output */ sched_pdsch->Qm = nr_get_Qm_dl(sched_pdsch->mcs, ps->mcsTableIdx); sched_pdsch->R = nr_get_code_rate_dl(sched_pdsch->mcs, ps->mcsTableIdx); sched_pdsch->tb_size = nr_compute_tbs(sched_pdsch->Qm, @@ -460,6 +461,7 @@ bool nr_ul_preprocessor_phytest(module_id_t module_id, frame_t frame, sub_frame_ const int mcs = target_ul_mcs; NR_sched_pusch_t *sched_pusch = &sched_ctrl->sched_pusch; sched_pusch->mcs = mcs; + sched_ctrl->ul_bler_stats.mcs = mcs; /* for logging output */ sched_pusch->rbStart = rbStart; sched_pusch->rbSize = rbSize; /* get the PID of a HARQ process awaiting retransmission, or -1 for "any new" */ From f2bc364b50d7280883d347abaf18d901837aea39 Mon Sep 17 00:00:00 2001 From: Robert Schmidt Date: Sat, 4 Jun 2022 09:14:22 +0200 Subject: [PATCH 4/9] Drop periodic "Number of bad PUCCH" output --- openair1/SCHED_NR/phy_procedures_nr_gNB.c | 4 ---- 1 file changed, 4 deletions(-) diff --git a/openair1/SCHED_NR/phy_procedures_nr_gNB.c b/openair1/SCHED_NR/phy_procedures_nr_gNB.c index c333145b5f..7f18b1fa1c 100644 --- a/openair1/SCHED_NR/phy_procedures_nr_gNB.c +++ b/openair1/SCHED_NR/phy_procedures_nr_gNB.c @@ -860,10 +860,6 @@ int phy_procedures_gNB_uespec_RX(PHY_VARS_gNB *gNB, int frame_rx, int slot_rx) { } stop_meas(&gNB->phy_proc_rx); - // figure out a better way to choose slot_rx, 19 is ok for a particular TDD configuration with 30kHz SCS - if ((frame_rx&127) == 0 && slot_rx==19) { - LOG_I(NR_PHY, "Number of bad PUCCH received: %lu\n", gNB->bad_pucch); - } if (pucch_decode_done || pusch_decode_done) { T(T_GNB_PHY_PUCCH_PUSCH_IQ, T_INT(frame_rx), T_INT(slot_rx), T_BUFFER(&gNB->common_vars.rxdataF[0][0], gNB->frame_parms.symbols_per_slot * gNB->frame_parms.ofdm_symbol_size * 4)); From 59e10dc8dacb468e144d26f4e6088ec32f91ad1e Mon Sep 17 00:00:00 2001 From: Robert Schmidt Date: Fri, 3 Jun 2022 18:05:18 +0200 Subject: [PATCH 5/9] Clean up MAC stats: don't show timing stats in console log, only file --- openair2/LAYER2/NR_MAC_gNB/gNB_scheduler.c | 9 +++--- openair2/LAYER2/NR_MAC_gNB/mac_proto.h | 2 +- openair2/LAYER2/NR_MAC_gNB/main.c | 34 ++++++++++++---------- 3 files changed, 23 insertions(+), 22 deletions(-) diff --git a/openair2/LAYER2/NR_MAC_gNB/gNB_scheduler.c b/openair2/LAYER2/NR_MAC_gNB/gNB_scheduler.c index d7e2c78c35..d56fc0ae2a 100644 --- a/openair2/LAYER2/NR_MAC_gNB/gNB_scheduler.c +++ b/openair2/LAYER2/NR_MAC_gNB/gNB_scheduler.c @@ -117,8 +117,6 @@ void gNB_dlsch_ulsch_scheduler(module_id_t module_idP, protocol_ctxt_t ctxt={0}; PROTOCOL_CTXT_SET_BY_MODULE_ID(&ctxt, module_idP, ENB_FLAG_YES, NOT_A_RNTI, frame, slot,module_idP); - char stats_output[16384]; - gNB_MAC_INST *gNB = RC.nrmac[module_idP]; NR_COMMON_channels_t *cc = gNB->common_channels; NR_ServingCellConfigCommon_t *scc = cc->ServingCellConfigCommon; @@ -180,9 +178,10 @@ void gNB_dlsch_ulsch_scheduler(module_id_t module_idP, if ((slot == 0) && (frame & 127) == 0) { - stats_output[0]='\0'; - dump_mac_stats(RC.nrmac[module_idP],stats_output,16384,true); - LOG_I(NR_MAC,"Frame.Slot %d.%d\n%s\n",frame,slot,stats_output); + char stats_output[16384]; + stats_output[0] = '\0'; + dump_mac_stats(RC.nrmac[module_idP], stats_output, sizeof(stats_output), true); + LOG_I(NR_MAC, "Frame.Slot %d.%d\n%s\n", frame, slot, stats_output); } nr_mac_update_timers(module_idP, frame, slot); diff --git a/openair2/LAYER2/NR_MAC_gNB/mac_proto.h b/openair2/LAYER2/NR_MAC_gNB/mac_proto.h index f3dd5208d6..5ff9795bbf 100644 --- a/openair2/LAYER2/NR_MAC_gNB/mac_proto.h +++ b/openair2/LAYER2/NR_MAC_gNB/mac_proto.h @@ -534,7 +534,7 @@ int get_mcs_from_bler(const NR_bler_options_t *bler_options, void nr_sr_reporting(gNB_MAC_INST *nrmac, frame_t frameP, sub_frame_t slotP); -void dump_mac_stats(gNB_MAC_INST *gNB, char *output, int strlen, bool reset_rsrp); +size_t dump_mac_stats(gNB_MAC_INST *gNB, char *output, int strlen, bool reset_rsrp); void process_CellGroup(NR_CellGroupConfig_t *CellGroup, NR_UE_sched_ctrl_t *sched_ctrl); diff --git a/openair2/LAYER2/NR_MAC_gNB/main.c b/openair2/LAYER2/NR_MAC_gNB/main.c index 6547544a68..59e307e923 100644 --- a/openair2/LAYER2/NR_MAC_gNB/main.c +++ b/openair2/LAYER2/NR_MAC_gNB/main.c @@ -45,25 +45,30 @@ extern RAN_CONTEXT_t RC; -#define MACSTATSSTRLEN 16384 +#define MACSTATSSTRLEN 65536 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)); + char output[MACSTATSSTRLEN] = {0}; + FILE *file = fopen("nrMAC_stats.log","w"); + AssertFatal(file!=NULL,"Cannot open nrMAC_stats.log, error %s\n",strerror(errno)); while (oai_exit == 0) { - dump_mac_stats(gNB,output,MACSTATSSTRLEN,false); - fprintf(fd,"%s\n",output); - fflush(fd); - usleep(200000); - fseek(fd,0,SEEK_SET); + size_t stroff = 0; + stroff += dump_mac_stats(gNB, output, MACSTATSSTRLEN, false); + stroff += snprintf(output + stroff, MACSTATSSTRLEN - stroff, "\n"); + stroff += print_meas_log(&gNB->eNB_scheduler, "DL & UL scheduling timing stats", NULL, NULL, output + stroff); + stroff += print_meas_log(&gNB->schedule_dlsch, "dlsch scheduler", NULL, NULL, output + stroff); + stroff += print_meas_log(&gNB->rlc_data_req, "rlc_data_req", NULL, NULL, output + stroff); + stroff += print_meas_log(&gNB->rlc_status_ind, "rlc_status_ind", NULL, NULL, output + stroff); + fwrite(output, stroff, 1, file); + fflush(file); + sleep(1); + fseek(file,0,SEEK_SET); } - fclose(fd); + fclose(file); return NULL; } @@ -73,7 +78,7 @@ void clear_mac_stats(gNB_MAC_INST *gNB) { } } -void dump_mac_stats(gNB_MAC_INST *gNB, char *output, int strlen, bool reset_rsrp) +size_t dump_mac_stats(gNB_MAC_INST *gNB, char *output, int strlen, bool reset_rsrp) { int num = 1; @@ -138,10 +143,7 @@ void dump_mac_stats(gNB_MAC_INST *gNB, char *output, int strlen, bool reset_rsrp } } pthread_mutex_unlock(&gNB->UE_info.mutex); - print_meas(&gNB->eNB_scheduler, "DL & UL scheduling timing stats", NULL, NULL); - print_meas(&gNB->schedule_dlsch,"dlsch scheduler",NULL,NULL); - print_meas(&gNB->rlc_data_req, "rlc_data_req",NULL,NULL); - print_meas(&gNB->rlc_status_ind,"rlc_status_ind",NULL,NULL); + return stroff; } From f8f20827e928e04a8f700f1c814778b1c9b95638 Mon Sep 17 00:00:00 2001 From: Robert Schmidt Date: Sat, 4 Jun 2022 09:02:07 +0200 Subject: [PATCH 6/9] Rename DL&UL scheduling timing stats --- ci-scripts/datalog_rt_stats.2x2.yaml | 4 ++-- ci-scripts/datalog_rt_stats.default.yaml | 4 ++-- ci-scripts/stats_monitor_conf.yaml | 4 ++-- openair2/LAYER2/NR_MAC_gNB/main.c | 2 +- 4 files changed, 7 insertions(+), 7 deletions(-) diff --git a/ci-scripts/datalog_rt_stats.2x2.yaml b/ci-scripts/datalog_rt_stats.2x2.yaml index a93ef6aa8c..eccde746cc 100644 --- a/ci-scripts/datalog_rt_stats.2x2.yaml +++ b/ci-scripts/datalog_rt_stats.2x2.yaml @@ -16,7 +16,7 @@ Ref : L1 Rx processing : 175.0 PUSCH inner-receiver : 100.0 PUSCH decoding : 180.0 - DL & UL scheduling timing stats : 37.0 + DL & UL scheduling timing : 37.0 UL Indication : 38.0 Threshold : feprx : 1.25 @@ -28,5 +28,5 @@ Threshold : L1 Rx processing : 1.25 PUSCH inner-receiver : 1.25 PUSCH decoding : 1.25 - DL & UL scheduling timing stats : 1.25 + DL & UL scheduling timing : 1.25 UL Indication : 1.25 diff --git a/ci-scripts/datalog_rt_stats.default.yaml b/ci-scripts/datalog_rt_stats.default.yaml index 0da04dcaed..97591a766d 100644 --- a/ci-scripts/datalog_rt_stats.default.yaml +++ b/ci-scripts/datalog_rt_stats.default.yaml @@ -17,7 +17,7 @@ Ref : PUSCH inner-receiver : 100.0 #PUSCH decoding : 180.0 PUSCH decoding : 240.0 - DL & UL scheduling timing stats : 37.0 + DL & UL scheduling timing : 37.0 UL Indication : 38.0 Threshold : feprx : 1.25 @@ -29,5 +29,5 @@ Threshold : L1 Rx processing : 1.25 PUSCH inner-receiver : 1.25 PUSCH decoding : 1.25 - DL & UL scheduling timing stats : 1.25 + DL & UL scheduling timing : 1.25 UL Indication : 1.25 diff --git a/ci-scripts/stats_monitor_conf.yaml b/ci-scripts/stats_monitor_conf.yaml index 9a2ececd18..4e1f87ed17 100644 --- a/ci-scripts/stats_monitor_conf.yaml +++ b/ci-scripts/stats_monitor_conf.yaml @@ -25,7 +25,7 @@ gnb : L1 Rx processing: PUSCH inner-receiver: PUSCH decoding: - DL & UL scheduling timing stats: + DL & UL scheduling timing: UL Indication: graph : page1: @@ -45,5 +45,5 @@ gnb : page4: rt.PUSCH inner-receiver: rt.PUSCH decoding: - rt.DL & UL scheduling timing stats: + rt.DL & UL scheduling timing: rt.UL Indication: diff --git a/openair2/LAYER2/NR_MAC_gNB/main.c b/openair2/LAYER2/NR_MAC_gNB/main.c index 59e307e923..438be21d59 100644 --- a/openair2/LAYER2/NR_MAC_gNB/main.c +++ b/openair2/LAYER2/NR_MAC_gNB/main.c @@ -59,7 +59,7 @@ void *nrmac_stats_thread(void *arg) { size_t stroff = 0; stroff += dump_mac_stats(gNB, output, MACSTATSSTRLEN, false); stroff += snprintf(output + stroff, MACSTATSSTRLEN - stroff, "\n"); - stroff += print_meas_log(&gNB->eNB_scheduler, "DL & UL scheduling timing stats", NULL, NULL, output + stroff); + stroff += print_meas_log(&gNB->eNB_scheduler, "DL & UL scheduling timing", NULL, NULL, output + stroff); stroff += print_meas_log(&gNB->schedule_dlsch, "dlsch scheduler", NULL, NULL, output + stroff); stroff += print_meas_log(&gNB->rlc_data_req, "rlc_data_req", NULL, NULL, output + stroff); stroff += print_meas_log(&gNB->rlc_status_ind, "rlc_status_ind", NULL, NULL, output + stroff); From bea2ec5c3bdf171bcdf5d4af3d6ea939ac006634 Mon Sep 17 00:00:00 2001 From: Robert Schmidt Date: Sat, 4 Jun 2022 09:12:29 +0200 Subject: [PATCH 7/9] Use snprintf() in dump_mac_stats() --- openair2/LAYER2/NR_MAC_gNB/mac_proto.h | 2 +- openair2/LAYER2/NR_MAC_gNB/main.c | 112 ++++++++++++++----------- 2 files changed, 66 insertions(+), 48 deletions(-) diff --git a/openair2/LAYER2/NR_MAC_gNB/mac_proto.h b/openair2/LAYER2/NR_MAC_gNB/mac_proto.h index 5ff9795bbf..e42acb3061 100644 --- a/openair2/LAYER2/NR_MAC_gNB/mac_proto.h +++ b/openair2/LAYER2/NR_MAC_gNB/mac_proto.h @@ -534,7 +534,7 @@ int get_mcs_from_bler(const NR_bler_options_t *bler_options, void nr_sr_reporting(gNB_MAC_INST *nrmac, frame_t frameP, sub_frame_t slotP); -size_t dump_mac_stats(gNB_MAC_INST *gNB, char *output, int strlen, bool reset_rsrp); +size_t dump_mac_stats(gNB_MAC_INST *gNB, char *output, size_t strlen, bool reset_rsrp); void process_CellGroup(NR_CellGroupConfig_t *CellGroup, NR_UE_sched_ctrl_t *sched_ctrl); diff --git a/openair2/LAYER2/NR_MAC_gNB/main.c b/openair2/LAYER2/NR_MAC_gNB/main.c index 438be21d59..168d0d15ed 100644 --- a/openair2/LAYER2/NR_MAC_gNB/main.c +++ b/openair2/LAYER2/NR_MAC_gNB/main.c @@ -78,11 +78,12 @@ void clear_mac_stats(gNB_MAC_INST *gNB) { } } -size_t dump_mac_stats(gNB_MAC_INST *gNB, char *output, int strlen, bool reset_rsrp) +size_t dump_mac_stats(gNB_MAC_INST *gNB, char *output, size_t strlen, bool reset_rsrp) { int num = 1; + const char *begin = output; + const char *end = output + strlen; - int stroff=0; pthread_mutex_lock(&gNB->UE_info.mutex); UE_iterator(gNB->UE_info.list, UE) { NR_UE_sched_ctrl_t *sched_ctrl = &UE->UE_sched_ctrl; @@ -90,60 +91,77 @@ size_t dump_mac_stats(gNB_MAC_INST *gNB, char *output, int strlen, bool reset_rs const int avg_rsrp = stats->num_rsrp_meas > 0 ? stats->cumul_rsrp / stats->num_rsrp_meas : 0; - stroff+=sprintf(output+stroff,"UE RNTI %04x (%d) PH %d dB PCMAX %d dBm, average RSRP %d (%d meas)\n", - UE->rnti, - num++, - sched_ctrl->ph, - sched_ctrl->pcmax, - avg_rsrp, - stats->num_rsrp_meas); - stroff+=sprintf(output+stroff,"UE %04x: CQI %d, RI %d, PMI (%d,%d)\n", - UE->rnti, - UE->UE_sched_ctrl.CSI_report.cri_ri_li_pmi_cqi_report.wb_cqi_1tb, - UE->UE_sched_ctrl.CSI_report.cri_ri_li_pmi_cqi_report.ri+1, - UE->UE_sched_ctrl.CSI_report.cri_ri_li_pmi_cqi_report.pmi_x1, - UE->UE_sched_ctrl.CSI_report.cri_ri_li_pmi_cqi_report.pmi_x2); - - stroff+=sprintf(output+stroff,"UE %04x: dlsch_rounds %"PRIu64"/%"PRIu64"/%"PRIu64"/%"PRIu64", dlsch_errors %"PRIu64", pucch0_DTX %d, BLER %.5f MCS %d\n", - UE->rnti, + output += snprintf(output, + end - output, + "UE RNTI %04x (%d) PH %d dB PCMAX %d dBm, average RSRP %d (%d meas)\n", + UE->rnti, + num++, + sched_ctrl->ph, + sched_ctrl->pcmax, + avg_rsrp, + stats->num_rsrp_meas); + output += snprintf(output, + end - output, + "UE %04x: CQI %d, RI %d, PMI (%d,%d)\n", + UE->rnti, + UE->UE_sched_ctrl.CSI_report.cri_ri_li_pmi_cqi_report.wb_cqi_1tb, + UE->UE_sched_ctrl.CSI_report.cri_ri_li_pmi_cqi_report.ri+1, + UE->UE_sched_ctrl.CSI_report.cri_ri_li_pmi_cqi_report.pmi_x1, + UE->UE_sched_ctrl.CSI_report.cri_ri_li_pmi_cqi_report.pmi_x2); - stats->dl.rounds[0], stats->dl.rounds[1], - stats->dl.rounds[2], stats->dl.rounds[3], - stats->dl.errors, - stats->pucch0_DTX, - sched_ctrl->dl_bler_stats.bler, - sched_ctrl->dl_bler_stats.mcs); + output += snprintf(output, + end - output, + "UE %04x: dlsch_rounds %"PRIu64"/%"PRIu64"/%"PRIu64"/%"PRIu64", dlsch_errors %"PRIu64", pucch0_DTX %d, BLER %.5f MCS %d\n", + UE->rnti, + stats->dl.rounds[0], stats->dl.rounds[1], + stats->dl.rounds[2], stats->dl.rounds[3], + stats->dl.errors, + stats->pucch0_DTX, + sched_ctrl->dl_bler_stats.bler, + sched_ctrl->dl_bler_stats.mcs); if (reset_rsrp) { stats->num_rsrp_meas = 0; stats->cumul_rsrp = 0; } - stroff+=sprintf(output+stroff,"UE %04x: dlsch_total_bytes %"PRIu64"\n", UE->rnti, stats->dl.total_bytes); - stroff+=sprintf(output+stroff,"UE %04x: ulsch_rounds %"PRIu64"/%"PRIu64"/%"PRIu64"/%"PRIu64", ulsch_DTX %d, ulsch_errors %"PRIu64", BLER %.5f MCS %d\n", - UE->rnti, - stats->ul.rounds[0], stats->ul.rounds[1], - stats->ul.rounds[2], stats->ul.rounds[3], - stats->ulsch_DTX, - stats->ul.errors, - sched_ctrl->ul_bler_stats.bler, - sched_ctrl->ul_bler_stats.mcs); - stroff+=sprintf(output+stroff, - "UE %04x: ulsch_total_bytes_scheduled %"PRIu64", ulsch_total_bytes_received %"PRIu64"\n", - UE->rnti, - stats->ulsch_total_bytes_scheduled, stats->ul.total_bytes); + output += snprintf(output, + end - output, + "UE %04x: dlsch_total_bytes %"PRIu64"\n", + UE->rnti, + stats->dl.total_bytes); + output += snprintf(output, + end - output, + "UE %04x: ulsch_rounds %"PRIu64"/%"PRIu64"/%"PRIu64"/%"PRIu64", ulsch_DTX %d, ulsch_errors %"PRIu64", BLER %.5f MCS %d\n", + UE->rnti, + stats->ul.rounds[0], stats->ul.rounds[1], + stats->ul.rounds[2], stats->ul.rounds[3], + stats->ulsch_DTX, + stats->ul.errors, + sched_ctrl->ul_bler_stats.bler, + sched_ctrl->ul_bler_stats.mcs); + output += snprintf(output, + end - output, + "UE %04x: ulsch_total_bytes_scheduled %"PRIu64", ulsch_total_bytes_received %"PRIu64"\n", + UE->rnti, + stats->ulsch_total_bytes_scheduled, stats->ul.total_bytes); for (int lc_id = 0; lc_id < 63; lc_id++) { - if (stats->dl.lc_bytes[lc_id] > 0) { - stroff+=sprintf(output+stroff, "UE %04x: LCID %d: %"PRIu64" bytes TX\n", UE->rnti, lc_id, stats->dl.lc_bytes[lc_id]); - LOG_D(NR_MAC, "UE %04x: LCID %d: %"PRIu64" bytes TX\n", UE->rnti, lc_id, stats->dl.lc_bytes[lc_id]); - } - if (stats->ul.lc_bytes[lc_id] > 0) { - stroff+=sprintf(output+stroff, "UE %04x: LCID %d: %"PRIu64" bytes RX\n", UE->rnti, lc_id, stats->ul.lc_bytes[lc_id]); - LOG_D(NR_MAC, "UE %04x: LCID %d: %"PRIu64" bytes RX\n", UE->rnti, lc_id, stats->ul.lc_bytes[lc_id]); - - } + if (stats->dl.lc_bytes[lc_id] > 0) + output += snprintf(output, + end - output, + "UE %04x: LCID %d: %"PRIu64" bytes TX\n", + UE->rnti, + lc_id, + stats->dl.lc_bytes[lc_id]); + if (stats->ul.lc_bytes[lc_id] > 0) + output += snprintf(output, + end - output, + "UE %04x: LCID %d: %"PRIu64" bytes RX\n", + UE->rnti, + lc_id, + stats->ul.lc_bytes[lc_id]); } } pthread_mutex_unlock(&gNB->UE_info.mutex); - return stroff; + return output - begin; } From b1d07fb3e0a8dd2e5b4de9ba66c73c7437c8ae89 Mon Sep 17 00:00:00 2001 From: Robert Schmidt Date: Sat, 4 Jun 2022 09:59:03 +0200 Subject: [PATCH 8/9] print_meas_log(): do not write beyond memory end --- common/utils/time_meas.c | 65 ++++++++++++++++++++----------- common/utils/time_meas.h | 7 +++- executables/nr-gnb.c | 42 +++++++++++--------- executables/nr-ue.c | 33 ++++++++-------- openair2/LAYER2/NR_MAC_gNB/main.c | 17 ++++---- 5 files changed, 98 insertions(+), 66 deletions(-) diff --git a/common/utils/time_meas.c b/common/utils/time_meas.c index df2bfd64de..9d1215b5e5 100644 --- a/common/utils/time_meas.c +++ b/common/utils/time_meas.c @@ -111,13 +111,15 @@ 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) +size_t print_meas_log(time_stats_t *ts, + const char *name, + time_stats_t *total_exec_time, + time_stats_t *sf_exec_time, + char *output, + size_t outputlen) { - int stroff = 0; + const char *begin = output; + const char *end = output + outputlen; static int first_time = 0; static double cpu_freq_GHz = 0.0; @@ -128,30 +130,49 @@ int print_meas_log(time_stats_t *ts, 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); + output += snprintf(output, + end - 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); + output += snprintf(output, + end - output, + "%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); + output += snprintf(output, + end - output, + "%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); + output += snprintf(output, + end - output, + "%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; + return output - begin; } double get_time_meas_us(time_stats_t *ts) diff --git a/common/utils/time_meas.h b/common/utils/time_meas.h index 382dd7455a..fded7f1a9c 100644 --- a/common/utils/time_meas.h +++ b/common/utils/time_meas.h @@ -83,7 +83,12 @@ 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); +size_t print_meas_log(time_stats_t *ts, + const char *name, + time_stats_t *total_exec_time, + time_stats_t *sf_exec_time, + char *output, + size_t outputlen); double get_time_meas_us(time_stats_t *ts); double get_cpu_freq_GHz(void); diff --git a/executables/nr-gnb.c b/executables/nr-gnb.c index 66d5c549e7..e6c739dec3 100644 --- a/executables/nr-gnb.c +++ b/executables/nr-gnb.c @@ -304,32 +304,36 @@ void rx_func(void *param) { ); #endif } -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); - stroff += print_meas_log(&gNB->schedule_response_stats, "Schedule Response",NULL,NULL, output+stroff); - if (ru->feprx) stroff += print_meas_log(&ru->ofdm_demod_stats,"feprx",NULL,NULL, output+stroff); +static size_t dump_L1_meas_stats(PHY_VARS_gNB *gNB, RU_t *ru, char *output, size_t outputlen) { + const char *begin = output; + const char *end = output + outputlen; + output += print_meas_log(&gNB->phy_proc_tx, "L1 Tx processing", NULL, NULL, output, end - output); + output += print_meas_log(&gNB->dlsch_encoding_stats, "DLSCH encoding", NULL, NULL, output, end - output); + output += print_meas_log(&gNB->phy_proc_rx, "L1 Rx processing", NULL, NULL, output, end - output); + output += print_meas_log(&gNB->ul_indication_stats, "UL Indication", NULL, NULL, output, end - output); + output += print_meas_log(&gNB->rx_pusch_stats, "PUSCH inner-receiver", NULL, NULL, output, end - output); + output += print_meas_log(&gNB->ulsch_decoding_stats, "PUSCH decoding", NULL, NULL, output, end - output); + output += print_meas_log(&gNB->schedule_response_stats, "Schedule Response", NULL, NULL, output, end - output); + if (ru->feprx) + output += print_meas_log(&ru->ofdm_demod_stats, "feprx", NULL, NULL, output, end - output); 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); + output += print_meas_log(&ru->precoding_stats,"feptx_prec",NULL,NULL, output, end - output); + output += print_meas_log(&ru->txdataF_copy_stats,"txdataF_copy",NULL,NULL, output, end - output); + output += print_meas_log(&ru->ofdm_mod_stats,"feptx_ofdm",NULL,NULL, output, end - output); + output += print_meas_log(&ru->ofdm_total_stats,"feptx_total",NULL,NULL, output, end - output); } - if (ru->fh_north_asynch_in) stroff += print_meas_log(&ru->rx_fhaul,"rx_fhaul",NULL,NULL, output+stroff); + if (ru->fh_north_asynch_in) + output += print_meas_log(&ru->rx_fhaul,"rx_fhaul",NULL,NULL, output, end - output); - stroff += print_meas_log(&ru->tx_fhaul,"tx_fhaul",NULL,NULL, output+stroff); + output += print_meas_log(&ru->tx_fhaul,"tx_fhaul",NULL,NULL, output, end - output); 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); + output += print_meas_log(&ru->compression,"compression",NULL,NULL, output, end - output); + output += print_meas_log(&ru->transport,"transport",NULL,NULL, output, end - output); } + return output - begin; } void *nrL1_stats_thread(void *param) { @@ -355,7 +359,7 @@ void *nrL1_stats_thread(void *param) { dump_nr_I0_stats(fd,gNB); dump_pdsch_stats(fd,gNB); dump_pusch_stats(fd,gNB); - dump_L1_meas_stats(gNB, ru, output); + dump_L1_meas_stats(gNB, ru, output, L1STATSSTRLEN); fprintf(fd,"%s\n",output); fflush(fd); fseek(fd,0,SEEK_SET); diff --git a/executables/nr-ue.c b/executables/nr-ue.c index 6e1864f290..01e6c62138 100644 --- a/executables/nr-ue.c +++ b/executables/nr-ue.c @@ -106,23 +106,24 @@ queue_t nr_rach_ind_queue; static void *NRUE_phy_stub_standalone_pnf_task(void *arg); -static int dump_L1_UE_meas_stats(PHY_VARS_NR_UE *ue, char *output, int max_len) +static size_t dump_L1_UE_meas_stats(PHY_VARS_NR_UE *ue, char *output, size_t max_len) { - int stroff = 0; - stroff += print_meas_log(&ue->phy_proc_tx, "L1 TX processing", NULL, NULL, output); - stroff += print_meas_log(&ue->ulsch_encoding_stats, "ULSCH encoding", NULL, NULL, output + stroff); - stroff += print_meas_log(&ue->phy_proc_rx[0], "L1 RX processing t0", NULL, NULL, output + stroff); - stroff += print_meas_log(&ue->phy_proc_rx[1], "L1 RX processing t1", NULL, NULL, output + stroff); - stroff += print_meas_log(&ue->ue_ul_indication_stats, "UL Indication", NULL, NULL, output + stroff); - stroff += print_meas_log(&ue->rx_pdsch_stats, "PDSCH receiver", NULL, NULL, output + stroff); - stroff += print_meas_log(&ue->dlsch_decoding_stats[0], "PDSCH decoding t0", NULL, NULL, output + stroff); - stroff += print_meas_log(&ue->dlsch_decoding_stats[1], "PDSCH decoding t1", NULL, NULL, output + stroff); - stroff += print_meas_log(&ue->dlsch_deinterleaving_stats, " -> Deinterleive", NULL, NULL, output + stroff); - stroff += print_meas_log(&ue->dlsch_rate_unmatching_stats, " -> Rate Unmatch", NULL, NULL, output + stroff); - stroff += print_meas_log(&ue->dlsch_ldpc_decoding_stats, " -> LDPC Decode", NULL, NULL, output + stroff); - stroff += print_meas_log(&ue->dlsch_unscrambling_stats, "PDSCH unscrambling", NULL, NULL, output + stroff); - stroff += print_meas_log(&ue->dlsch_rx_pdcch_stats, "PDCCH handling", NULL, NULL, output + stroff); - return stroff; + const char *begin = output; + const char *end = output + max_len; + output += print_meas_log(&ue->phy_proc_tx, "L1 TX processing", NULL, NULL, output, end - output); + output += print_meas_log(&ue->ulsch_encoding_stats, "ULSCH encoding", NULL, NULL, output, end - output); + output += print_meas_log(&ue->phy_proc_rx[0], "L1 RX processing t0", NULL, NULL, output, end - output); + output += print_meas_log(&ue->phy_proc_rx[1], "L1 RX processing t1", NULL, NULL, output, end - output); + output += print_meas_log(&ue->ue_ul_indication_stats, "UL Indication", NULL, NULL, output, end - output); + output += print_meas_log(&ue->rx_pdsch_stats, "PDSCH receiver", NULL, NULL, output, end - output); + output += print_meas_log(&ue->dlsch_decoding_stats[0], "PDSCH decoding t0", NULL, NULL, output, end - output); + output += print_meas_log(&ue->dlsch_decoding_stats[1], "PDSCH decoding t1", NULL, NULL, output, end - output); + output += print_meas_log(&ue->dlsch_deinterleaving_stats, " -> Deinterleive", NULL, NULL, output, end - output); + output += print_meas_log(&ue->dlsch_rate_unmatching_stats, " -> Rate Unmatch", NULL, NULL, output, end - output); + output += print_meas_log(&ue->dlsch_ldpc_decoding_stats, " -> LDPC Decode", NULL, NULL, output, end - output); + output += print_meas_log(&ue->dlsch_unscrambling_stats, "PDSCH unscrambling", NULL, NULL, output, end - output); + output += print_meas_log(&ue->dlsch_rx_pdcch_stats, "PDCCH handling", NULL, NULL, output, end - output); + return output - begin; } static void *nrL1_UE_stats_thread(void *param) diff --git a/openair2/LAYER2/NR_MAC_gNB/main.c b/openair2/LAYER2/NR_MAC_gNB/main.c index 168d0d15ed..9b9fd4e76c 100644 --- a/openair2/LAYER2/NR_MAC_gNB/main.c +++ b/openair2/LAYER2/NR_MAC_gNB/main.c @@ -52,18 +52,19 @@ void *nrmac_stats_thread(void *arg) { gNB_MAC_INST *gNB = (gNB_MAC_INST *)arg; char output[MACSTATSSTRLEN] = {0}; + const char *end = output + MACSTATSSTRLEN; FILE *file = fopen("nrMAC_stats.log","w"); AssertFatal(file!=NULL,"Cannot open nrMAC_stats.log, error %s\n",strerror(errno)); while (oai_exit == 0) { - size_t stroff = 0; - stroff += dump_mac_stats(gNB, output, MACSTATSSTRLEN, false); - stroff += snprintf(output + stroff, MACSTATSSTRLEN - stroff, "\n"); - stroff += print_meas_log(&gNB->eNB_scheduler, "DL & UL scheduling timing", NULL, NULL, output + stroff); - stroff += print_meas_log(&gNB->schedule_dlsch, "dlsch scheduler", NULL, NULL, output + stroff); - stroff += print_meas_log(&gNB->rlc_data_req, "rlc_data_req", NULL, NULL, output + stroff); - stroff += print_meas_log(&gNB->rlc_status_ind, "rlc_status_ind", NULL, NULL, output + stroff); - fwrite(output, stroff, 1, file); + char *p = output; + p += dump_mac_stats(gNB, p, end - p, false); + p += snprintf(p, end - p, "\n"); + p += print_meas_log(&gNB->eNB_scheduler, "DL & UL scheduling timing", NULL, NULL, p, end - p); + p += print_meas_log(&gNB->schedule_dlsch, "dlsch scheduler", NULL, NULL, p, end - p); + p += print_meas_log(&gNB->rlc_data_req, "rlc_data_req", NULL, NULL, p, end - p); + p += print_meas_log(&gNB->rlc_status_ind, "rlc_status_ind", NULL, NULL, p, end - p); + fwrite(output, p - output, 1, file); fflush(file); sleep(1); fseek(file,0,SEEK_SET); From 9eccd6c11d668625f2c824a7ded1537989e00049 Mon Sep 17 00:00:00 2001 From: Robert Schmidt Date: Wed, 8 Jun 2022 14:33:21 +0200 Subject: [PATCH 9/9] Correct caracal IP address --- ci-scripts/conf_files/gnb.band78.tm1.106PRB.usrpn300.conf | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/ci-scripts/conf_files/gnb.band78.tm1.106PRB.usrpn300.conf b/ci-scripts/conf_files/gnb.band78.tm1.106PRB.usrpn300.conf index 0c75080398..835e334bbb 100644 --- a/ci-scripts/conf_files/gnb.band78.tm1.106PRB.usrpn300.conf +++ b/ci-scripts/conf_files/gnb.band78.tm1.106PRB.usrpn300.conf @@ -219,7 +219,7 @@ RUs = ( ## beamforming 4x4 matrix: #bf_weights = [0x00007fff, 0x0000, 0x0000, 0x0000, 0x00000000, 0x00007fff, 0x0000, 0x0000, 0x0000, 0x0000, 0x00007fff, 0x0000, 0x0000, 0x0000, 0x0000, 0x00007fff]; - sdr_addrs = "addr=192.168.10.2,second_addr=192.168.20.2,mgmt_addr=192.168.18.85"; + sdr_addrs = "addr=192.168.10.2,second_addr=192.168.20.2"; } );