Merge remote-tracking branch 'origin/gnb-mac-stats-cleanup' into integration_2025_w27 (!3497)

Update/refine gNB MAC stats, update L1

Only applicable with -q option.

Print a number of statistics, e.g., rx_ulsch_sdu to track UL MAC stats
timing. Remove unused time_meas_t definitions, and fix the name for the
total gNB scheduler time.

Print the RU stats in nrL1_stats.log, as some are already there, and do
not "pollute" the periodic logs when -q is enabled.

I used this to see why there are sometimes late slots with Aerial. I
used the above stats to get a general overview. This additional patch
shows that at least in RFsim, the RLC indication in rx ulsch sdu can
take up to 20us on my machine. Given that we can have multiple PDUs in
UL (10?), this can amount to a sizeable amount of time. While this is
for another MR, I thought the cleanup would be nice to have.
This commit is contained in:
Robert Schmidt
2025-07-01 08:58:39 +02:00
11 changed files with 55 additions and 70 deletions

View File

@@ -19,6 +19,9 @@ Ref :
DL & UL scheduling timing : 17.0
UL Indication : 1.0
Slot Indication : 13.0
feprx : 151.0
feptx_ofdm (per port, half_slot) : 57
feptx_total : 148
DeviationThreshold :
feprx : 0.25
feptx_prec : 0.25
@@ -32,3 +35,6 @@ DeviationThreshold :
DL & UL scheduling timing : 0.25
UL Indication : 1.00
Slot Indication : 0.50
feprx : 0.25
feptx_ofdm (per port, half_slot) : 0.25
feptx_total : 0.25

View File

@@ -19,6 +19,9 @@ Ref :
DL & UL scheduling timing : 5.0
UL Indication : 1.0
Slot Indication : 6.0
feprx : 44.0
feptx_ofdm (per port, half_slot) : 31
feptx_total : 58
DeviationThreshold :
feprx : 0.25
feptx_prec : 0.25
@@ -32,3 +35,6 @@ DeviationThreshold :
DL & UL scheduling timing : 0.50
UL Indication : 1.00
Slot Indication : 0.50
feprx : 0.25
feptx_ofdm (per port, half_slot) : 0.25
feptx_total : 0.25

View File

@@ -19,6 +19,9 @@ Ref :
DL & UL scheduling timing : 8.0
UL Indication : 3.0
Slot Indication : 9.0
feprx : 85.0
feptx_ofdm (per port, half_slot) : 31
feptx_total : 92
DeviationThreshold :
feprx : 0.25
feptx_prec : 0.25
@@ -32,3 +35,6 @@ DeviationThreshold :
DL & UL scheduling timing : 0.35
UL Indication : 1.00
Slot Indication : 0.35
feprx : 0.25
feptx_ofdm (per port, half_slot) : 0.25
feptx_total : 0.25

View File

@@ -19,6 +19,9 @@ Ref :
DL & UL scheduling timing : 4.0
UL Indication : 2.0
Slot Indication : 5.0
feprx : 43.0
feptx_ofdm (per port, half_slot) : 30
feptx_total : 57
DeviationThreshold :
feprx : 0.25
feptx_prec : 0.25
@@ -32,3 +35,6 @@ DeviationThreshold :
DL & UL scheduling timing : 0.50
UL Indication : 1.00
Slot Indication : 0.50
feprx : 0.25
feptx_ofdm (per port, half_slot) : 0.25
feptx_total : 0.25

View File

@@ -239,14 +239,26 @@ static size_t dump_L1_meas_stats(PHY_VARS_gNB *gNB, RU_t *ru, char *output, size
if (ru->feprx)
output += print_meas_log(&ru->ofdm_demod_stats, "feprx", NULL, NULL, output, end - output);
bool full_slot = ru->half_slot_parallelization == 0;
if (ru->feptx_prec) {
output += print_meas_log(&ru->precoding_stats,"feptx_prec",NULL,NULL, output, end - output);
output += print_meas_log(&ru->precoding_stats,
full_slot ? "feptx_prec (per port)" : "feptx_prec (per port, half_slot)",
NULL,
NULL,
output,
end - output);
}
if (ru->feptx_ofdm) {
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_mod_stats,
full_slot ? "feptx_ofdm (per port)" : "feptx_ofdm (per port, half_slot)",
NULL,
NULL,
output,
end - output);
output += print_meas_log(&ru->ofdm_total_stats,"feptx_total",NULL,NULL, output, end - output);
output += print_meas_log(&ru->txdataF_copy_stats, "txdataF_copy", NULL, NULL, output, end - output);
}
if (ru->fh_north_asynch_in)

View File

@@ -992,36 +992,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 (cpu_meas_enabled) {
if (ru->feprx) print_meas(&ru->ofdm_demod_stats,"feprx (all ports)",NULL,NULL);
if (ru->feptx_ofdm) {
print_meas(&ru->precoding_stats,(ru->half_slot_parallelization==0)?"feptx_prec (per port)":"feptx_prec (per port, half_slot)",NULL,NULL);
print_meas(&ru->ofdm_mod_stats,(ru->half_slot_parallelization==0)?"feptx_ofdm (per port)":"feptx_ofdm (per port, half_slot)",NULL,NULL);
print_meas(&ru->txdataF_copy_stats,"txdataF_copy",NULL,NULL);
print_meas(&ru->ofdm_total_stats,"feptx_total",NULL,NULL);
}
print_meas(&ru->rx_fhaul,"rx_fhaul",NULL,NULL);
if (ru->if_south == REMOTE_IF5) print_meas(&ru->ifdevice.tx_fhaul,"tx_fhaul (IF5)",NULL,NULL);
else 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;
@@ -1399,8 +1369,6 @@ void init_RU_proc(RU_t *ru) {
if(emulate_rf)
threadCreate( &proc->pthread_emulateRF, emulatedRF_thread, (void *)proc, "emulateRF", -1, OAI_PRIORITY_RT );
if (cpu_meas_enabled)
threadCreate(&ru->ru_stats_thread, ru_stats_thread, (void *)ru, "ru_stats", -1, OAI_PRIORITY_RT);
LOG_I(PHY, "Initialized RU proc %d (%s,%s),\n", ru->idx, NB_functions[ru->function], NB_timing[ru->if_timing]);
}
@@ -1430,11 +1398,6 @@ void kill_NR_RU_proc(int inst) {
pthread_mutex_unlock( &proc->mutex_fep[0] );
pthread_join(proc->pthread_FH, NULL);
if (cpu_meas_enabled) {
LOG_D(PHY, "Joining ru_stats_thread\n");
pthread_join(ru->ru_stats_thread, NULL);
}
// everything should be stopped now, we can safely stop the RF device
if (ru->stop_rf == NULL) {
LOG_W(PHY, "No stop_rf() for RU %d defined, cannot stop RF!\n", ru->idx);

View File

@@ -174,7 +174,7 @@ void gNB_dlsch_ulsch_scheduler(module_id_t module_idP, frame_t frame, slot_t slo
clear_beam_information(&gNB->beam_info, frame, slot, slots_frame);
gNB->frame = frame;
start_meas(&gNB->eNB_scheduler);
start_meas(&gNB->gNB_scheduler);
VCD_SIGNAL_DUMPER_DUMP_FUNCTION_BY_NAME(VCD_SIGNAL_DUMPER_FUNCTIONS_gNB_DLSCH_ULSCH_SCHEDULER,VCD_FUNCTION_IN);
for (int CC_id = 0; CC_id < MAX_NUM_CCs; CC_id++) {
@@ -244,7 +244,9 @@ void gNB_dlsch_ulsch_scheduler(module_id_t module_idP, frame_t frame, slot_t slo
}
// This schedules the DCI for Uplink and subsequently PUSCH
start_meas(&gNB->schedule_ulsch);
nr_schedule_ulsch(module_idP, frame, slot, &sched_info->UL_dci_req);
stop_meas(&gNB->schedule_ulsch);
// This schedules the DCI for Downlink and PDSCH
start_meas(&gNB->schedule_dlsch);
@@ -262,7 +264,7 @@ void gNB_dlsch_ulsch_scheduler(module_id_t module_idP, frame_t frame, slot_t slo
const int current_index = ul_buffer_index(frame, slot, slots_frame, gNB->UL_tti_req_ahead_size);
copy_ul_tti_req(&sched_info->UL_tti_req, &gNB->UL_tti_req_ahead[0][current_index]);
stop_meas(&gNB->eNB_scheduler);
stop_meas(&gNB->gNB_scheduler);
NR_SCHED_UNLOCK(&gNB->sched_lock);
VCD_SIGNAL_DUMPER_DUMP_FUNCTION_BY_NAME(VCD_SIGNAL_DUMPER_FUNCTIONS_gNB_DLSCH_ULSCH_SCHEDULER,VCD_FUNCTION_OUT);
}

View File

@@ -340,9 +340,7 @@ static void nr_store_dlsch_buffer(module_id_t module_id, frame_t frame, slot_t s
continue;
if (lcid == DL_SCH_LCID_DTCH && nr_timer_is_active(&sched_ctrl->transm_interrupt))
continue;
start_meas(&RC.nrmac[module_id]->rlc_status_ind);
sched_ctrl->rlc_status[lcid] = nr_mac_rlc_status_ind(rnti, frame, lcid);
stop_meas(&RC.nrmac[module_id]->rlc_status_ind);
if (sched_ctrl->rlc_status[lcid].bytes_in_buffer == 0)
continue;

View File

@@ -961,7 +961,9 @@ void nr_rx_sdu(const module_id_t gnb_mod_idP,
{
gNB_MAC_INST *gNB_mac = RC.nrmac[gnb_mod_idP];
NR_SCHED_LOCK(&gNB_mac->sched_lock);
start_meas(&gNB_mac->rx_ulsch_sdu);
_nr_rx_sdu(gnb_mod_idP, CC_idP, frameP, slotP, rntiP, sduP, sdu_lenP, harq_pid, timing_advance, ul_cqi, rssi);
stop_meas(&gNB_mac->rx_ulsch_sdu);
NR_SCHED_UNLOCK(&gNB_mac->sched_lock);
}

View File

@@ -89,10 +89,12 @@ void *nrmac_stats_thread(void *arg) {
p += dump_mac_stats(gNB, p, end - p, false);
NR_SCHED_UNLOCK(&gNB->sched_lock);
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->gNB_scheduler, "gNB_scheduler", NULL, NULL, p, end - p);
p += print_meas_log(&gNB->rx_ulsch_sdu, "rx_ulsch_sdu", NULL, NULL, p, end - p);
p += print_meas_log(&gNB->schedule_dlsch, "dlsch scheduler", NULL, NULL, p, end - p);
p += print_meas_log(&gNB->schedule_ulsch, "ulsch scheduler", NULL, NULL, p, end - p);
p += print_meas_log(&gNB->schedule_ra, "RA 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);
p += print_meas_log(&gNB->nr_srs_ri_computation_timer, "UL-RI computation time", NULL, NULL, p, end - p);
p += print_meas_log(&gNB->nr_srs_tpmi_computation_timer, "UL-TPMI computation time", NULL, NULL, p, end - p);
fwrite(output, p - output, 1, file);
@@ -270,8 +272,6 @@ void mac_top_init_gNB(ngran_node_t node_type,
RC.nrmac[i]->tag = (NR_TAG_t*)malloc(sizeof(NR_TAG_t));
memset((void*)RC.nrmac[i]->tag,0,sizeof(NR_TAG_t));
RC.nrmac[i]->ul_handle = 0;
RC.nrmac[i]->common_channels[0].ServingCellConfigCommon = scc;
RC.nrmac[i]->radio_config = *config;
RC.nrmac[i]->rlc_config = *default_rlc_config;

View File

@@ -856,39 +856,23 @@ typedef struct gNB_MAC_INST_s {
NR_UEs_t UE_info;
/// UL handle
uint32_t ul_handle;
//UE_info_t UE_info;
// MAC function execution peformance profiler
/// processing time of eNB scheduler
time_stats_t eNB_scheduler;
/// processing time of eNB scheduler for SI
time_stats_t schedule_si;
/// processing time of eNB scheduler for Random access
/// processing time of gNB scheduler
time_stats_t gNB_scheduler;
/// processing time of gNB scheduler for Random access
time_stats_t schedule_ra;
/// processing time of eNB ULSCH scheduler
time_stats_t schedule_ulsch;
/// processing time of eNB DCI generation
time_stats_t fill_DLSCH_dci;
/// processing time of eNB MAC preprocessor
time_stats_t schedule_dlsch_preprocessor;
/// processing time of eNB DLSCH scheduler
/// processing time of gNB DLSCH scheduler
time_stats_t schedule_ulsch; // include preprocessor
/// processing time of gNB DLSCH scheduler
time_stats_t schedule_dlsch; // include rlc_data_req + MAC header + preprocessor
/// processing time of rlc_data_req
time_stats_t rlc_data_req;
/// processing time of rlc_status_ind
time_stats_t rlc_status_ind;
/// processing time of nr_srs_ri_computation
time_stats_t nr_srs_ri_computation_timer;
/// processing time of nr_srs_tpmi_estimation
time_stats_t nr_srs_tpmi_computation_timer;
/// processing time of eNB MCH scheduler
time_stats_t schedule_mch;
/// processing time of eNB ULSCH reception
/// processing time of gNB ULSCH reception
time_stats_t rx_ulsch_sdu; // include rlc_data_ind
/// processing time of eNB PCH scheduler
time_stats_t schedule_pch;
NR_beam_info_t beam_info;