T: some traces for gNB MAC scheduler debugging

common/utils/T/T.h

@@ -1,6 +1,8 @@
 #ifndef _T_T_T_
 #define _T_T_T_
 
+#define CHECK_T_TYPE
+
 #if T_TRACER
 
 #include <stdint.h>

common/utils/T/T_messages.txt

@@ -328,6 +328,96 @@ ID = ENB_RRC_UNKNOW_MESSAGE
     GROUP = ALL:RRC:ENB
     FORMAT = int,eNB_ID : int,frame : int,subframe : int,rnti
 
+#jitter measurement
+ID = JITTER_GTP_IN
+    DESC = log when a GTP packet comes in
+    GROUP = ALL:JITTER
+    FORMAT = int,socket : buffer,data : int,data_len
+ID = JITTER_PDCP_IN
+    DESC = log when a PDCP packet comes in
+    GROUP = ALL:JITTER
+    #type: 0: DRB AM, 1: DRB UM, 2: SRB
+    #entity_id is actually lower 4 bytes of the rlc entity address in memory
+    FORMAT = int,entity_id : int,type : int,rb_id : int,pdu_session_id : buffer,data : int,data_len
+ID = JITTER_RLC_IN
+    DESC = log when a RLC packet comes in
+    GROUP = ALL:JITTER
+    #entity_id is actually lower 4 bytes of the rlc entity address in memory
+    #mode: 0: AM, 1: UM, 2:TM
+    FORMAT = int,entity_id : int,mode : int,sdu_id : buffer,data : int,data_len
+
+#gNB mac scheduler decision making
+
+ID = GNB_MAC_SCHED_RETRANSMIT
+    DESC = retransmission of a transport block
+    GROUP = ALL:MAC_SCHED
+    FORMAT = int,rnti : int,frame : int,slot : int,harq_pid : int,harq_round : int,tbs
+
+ID = GNB_MAC_SCHED_NUM_TOTAL_BYTES
+    DESC = value of sched_ctrl->num_total_bytes
+    GROUP = ALL:MAC_SCHED
+    FORMAT = int,rnti : int,frame : int,slot : int,harq_pid : int,num_total_bytes
+
+ID = GNB_MAC_SCHED_RLC_BUFFER_SIZE
+    DESC = available data from an RLC entity
+    GROUP = ALL:MAC_SCHED
+    FORMAT = int,rnti : int,frame : int,slot : int,lcid : int,pdus_in_buffer : int,bytes_in_buffer
+
+ID = GNB_MAC_SCHED_RLC_FILL_BUFFER
+    DESC = fill RLC buffer by RLC module (limited to 'max_size_requested')
+    GROUP = ALL:MAC_SCHED
+    FORMAT = int,rnti : int,frame : int,slot : int,lcid : int,max_size_allowed : int,size_filled
+
+ID = GNB_MAC_SCHED_PF_DL_RETRANSMIT
+    DESC = pf dl algo decision to schedule a retransmission
+    GROUP = ALL:MAC_SCHED
+    FORMAT = int,rnti : int,frame : int,slot : int,harq_pid : int,do_retransmit
+
+ID = GNB_MAC_SCHED_PF_DL_HAS_FREE_HARQ
+    DESC = pf dl algo check on free harq available for initial transmission
+    GROUP = ALL:MAC_SCHED
+    FORMAT = int,rnti : int,frame : int,slot : int,harq_pid : int,has_free_harq
+
+ID = GNB_MAC_SCHED_PF_DL_SKIP_UE
+    DESC = pf dl algo decision to skip the UE for initial transmission
+    GROUP = ALL:MAC_SCHED
+    FORMAT = int,rnti : int,frame : int,slot : int,num_total_bytes : int,do_skip
+
+ID = GNB_MAC_SCHED_PF_DL_COEFF
+    DESC = pf dl algo coeff computation
+    GROUP = ALL:MAC_SCHED
+    FORMAT = int,rnti : int,frame : int,slot : int,mcs : int,number_of_layers : int,pm_index : int,Qm : int,code_rate : int,tbs : float,dl_thr_ue : float,coeff_ue
+
+ID = GNB_MAC_SCHED_PF_DL_SKIP_UE_NO_HARQ
+    DESC = pf dl algo decision to skip the UE for initial transmission if no available harq
+    GROUP = ALL:MAC_SCHED
+    FORMAT = int,rnti : int,frame : int,slot : int,harq_pid : int,do_skip
+
+ID = GNB_MAC_SCHED_PF_DL_SLBITMAP
+    DESC = pf dl algo slbitmap
+    GROUP = ALL:MAC_SCHED
+    FORMAT = int,rnti : int,frame : int,slot : int,slbitmap
+
+ID = GNB_MAC_SCHED_PF_DL_SKIP_RBSIZE
+    DESC = pf dl algo rbsize (and do we skip if not enough rb)
+    GROUP = ALL:MAC_SCHED
+    FORMAT = int,rnti : int,frame : int,slot : int,rbStart : int,min_rbSize : int,max_rbSize : int,do_skip
+
+ID = GNB_MAC_SCHED_PF_DL_SKIP_CCEINDEX
+    DESC = pf dl algo cce index (and do we skip if no free cce index)
+    GROUP = ALL:MAC_SCHED
+    FORMAT = int,rnti : int,frame : int,slot : int,cce_index : int,do_skip
+
+ID = GNB_MAC_SCHED_PF_DL_SKIP_PUCCH_ALLOC
+    DESC = pf dl algo pucch allocation (and do we skip if no pucch allocation)
+    GROUP = ALL:MAC_SCHED
+    FORMAT = int,rnti : int,frame : int,slot : int,r_pucch : int,alloc : int,do_skip
+
+ID = GNB_MAC_SCHED_PF_DL_SCHEDULE
+    DESC = pf dl algo schedule decision
+    GROUP = ALL:MAC_SCHED
+    FORMAT = int,rnti : int,frame : int,slot : int,mcs : int,Qm : int,R : int,nrOfLayers : int,nrOfSymbols : int,num_total_bytes : int,header_bytes : int,rb_start : int,rb_size : int,tbs
+
 #legacy logs
 ID = LEGACY_MAC_INFO
     DESC = MAC legacy logs - info level

openair2/LAYER2/NR_MAC_gNB/gNB_scheduler_dlsch.c

@@ -349,6 +349,8 @@ static void nr_store_dlsch_buffer(module_id_t module_id, frame_t frame, sub_fram
                                                         0);
       stop_meas(&RC.nrmac[module_id]->rlc_status_ind);
 
+      T(T_GNB_MAC_SCHED_RLC_BUFFER_SIZE, T_INT(rnti), T_INT(frame), T_INT(slot), T_INT(lcid), T_INT(sched_ctrl->rlc_status[lcid].pdus_in_buffer), T_INT(sched_ctrl->rlc_status[lcid].bytes_in_buffer));
+
       if (sched_ctrl->rlc_status[lcid].bytes_in_buffer == 0)
         continue;
 
@@ -646,6 +648,8 @@ static void pf_dl(module_id_t module_id,
       /* Allocate retransmission */
       bool r = allocate_dl_retransmission(module_id, frame, slot, &n_rb_sched, UE, sched_pdsch->dl_harq_pid);
 
+      T(T_GNB_MAC_SCHED_PF_DL_RETRANSMIT, T_INT(UE->rnti), T_INT(frame), T_INT(slot), T_INT(sched_pdsch->dl_harq_pid), T_INT(b));
+
       if (!r) {
         LOG_D(NR_MAC, "[UE %04x][%4d.%2d] DL retransmission could not be allocated\n",
               UE->rnti,
@@ -660,6 +664,7 @@ static void pf_dl(module_id_t module_id,
       /* skip this UE if there are no free HARQ processes. This can happen e.g.
        * if the UE disconnected in L2sim, in which case the gNB is not notified
        * (this can be considered a design flaw) */
+      T(T_GNB_MAC_SCHED_PF_DL_HAS_FREE_HARQ, T_INT(UE->rnti), T_INT(frame), T_INT(slot), T_INT(sched_ctrl->available_dl_harq.head), T_INT(sched_ctrl->available_dl_harq.head >= 0));
       if (sched_ctrl->available_dl_harq.head < 0) {
         LOG_D(NR_MAC, "[UE %04x][%4d.%2d] UE has no free DL HARQ process, skipping\n",
               UE->rnti,
@@ -669,6 +674,7 @@ static void pf_dl(module_id_t module_id,
       }
 
       /* Check DL buffer and skip this UE if no bytes and no TA necessary */
+      T(T_GNB_MAC_SCHED_PF_DL_SKIP_UE, T_INT(UE->rnti), T_INT(frame), T_INT(slot), T_INT(sched_ctrl->num_total_bytes), T_INT(sched_ctrl->num_total_bytes == 0 && frame != (sched_ctrl->ta_frame + 100) % 1024));
       if (sched_ctrl->num_total_bytes == 0 && frame != (sched_ctrl->ta_frame + 100) % 1024)
         continue;
 
@@ -706,6 +712,7 @@ static void pf_dl(module_id_t module_id,
       /* Create UE_sched list for UEs eligible for new transmission*/
       UE_sched[curUE].coef=coeff_ue;
       UE_sched[curUE].UE=UE;
+      T(T_GNB_MAC_SCHED_PF_DL_COEFF, T_INT(UE->rnti), T_INT(frame), T_INT(slot), T_INT(sched_pdsch->mcs), T_INT(sched_pdsch->nrOfLayers), T_INT(sched_pdsch->pm_index), T_INT(Qm), T_INT(R), T_INT(tbs), T_FLOAT(UE->dl_thr_ue), T_FLOAT(coeff_ue));
       curUE++;
     }
   }
@@ -724,6 +731,7 @@ static void pf_dl(module_id_t module_id,
     NR_UE_DL_BWP_t *dl_bwp = &iterator->UE->current_DL_BWP;
     NR_UE_UL_BWP_t *ul_bwp = &iterator->UE->current_UL_BWP;
 
+    T(T_GNB_MAC_SCHED_PF_DL_SKIP_UE_NO_HARQ, T_INT(rnti), T_INT(frame), T_INT(slot), T_INT(sched_ctrl->available_dl_harq.head), T_INT(sched_ctrl->available_dl_harq.head < 0));
     if (sched_ctrl->available_dl_harq.head < 0) {
       LOG_D(NR_MAC, "[UE %04x][%4d.%2d] UE has no free DL HARQ process, skipping\n",
             iterator->UE->rnti,
@@ -753,6 +761,7 @@ static void pf_dl(module_id_t module_id,
     NR_tda_info_t *tda_info = &sched_pdsch->tda_info;
 
     const uint16_t slbitmap = SL_to_bitmap(tda_info->startSymbolIndex, tda_info->nrOfSymbols);
+    T(T_GNB_MAC_SCHED_PF_DL_SLBITMAP, T_INT(rnti), T_INT(frame), T_INT(slot), T_INT(slbitmap));
 
     // TODO assuming beam 0 for now
     uint16_t *rballoc_mask = mac->common_channels[CC_id].vrb_map[0];
@@ -769,6 +778,7 @@ static void pf_dl(module_id_t module_id,
     while (rbStart + max_rbSize <= rbStop && !(rballoc_mask[rbStart + max_rbSize + bwp_start] & slbitmap))
       max_rbSize++;
 
+    T(T_GNB_MAC_SCHED_PF_DL_SKIP_RBSIZE, T_INT(rnti), T_INT(frame), T_INT(slot), T_INT(rbStart), T_INT(min_rbSize), T_INT(max_rbSize), T_INT(max_rbSize < min_rbSize));
     if (max_rbSize < min_rbSize) {
       LOG_D(NR_MAC,
             "(%d.%d) Cannot schedule RNTI %04x, rbStart %d, rbSize %d, rbStop %d\n",
@@ -795,6 +805,7 @@ static void pf_dl(module_id_t module_id,
                                  sched_ctrl->coreset,
                                  &sched_ctrl->sched_pdcch,
                                  false);
+    T(T_GNB_MAC_SCHED_PF_DL_SKIP_CCEINDEX, T_INT(rnti), T_INT(frame), T_INT(slot), T_INT(CCEIndex), T_INT(CCEIndex < 0));
     if (CCEIndex<0) {
       LOG_D(NR_MAC, "[UE %04x][%4d.%2d] could not find free CCE for DL DCI\n",
             rnti,
@@ -811,6 +822,7 @@ static void pf_dl(module_id_t module_id,
     if (!get_FeedbackDisabled(iterator->UE->sc_info.downlinkHARQ_FeedbackDisabled_r17, sched_pdsch->dl_harq_pid)) {
       int r_pucch = nr_get_pucch_resource(sched_ctrl->coreset, ul_bwp->pucch_Config, CCEIndex);
       alloc = nr_acknack_scheduling(mac, iterator->UE, frame, slot, beam, r_pucch, 0);
+      T(T_GNB_MAC_SCHED_PF_DL_SKIP_PUCCH_ALLOC, T_INT(rnti), T_INT(frame), T_INT(slot), T_INT(r_pucch), T_INT(alloc), T_INT(alloc < 0));
       if (alloc < 0) {
         LOG_D(NR_MAC, "[UE %04x][%4d.%2d] could not find PUCCH for DL DCI\n",
               rnti,
@@ -852,6 +864,7 @@ static void pf_dl(module_id_t module_id,
     sched_pdsch->tb_size = TBS;
     /* transmissions: directly allocate */
     n_rb_sched -= sched_pdsch->rbSize;
+    T(T_GNB_MAC_SCHED_PF_DL_SCHEDULE, T_INT(rnti), T_INT(frame), T_INT(slot), T_INT(sched_pdsch->mcs), T_INT(sched_pdsch->Qm), T_INT(sched_pdsch->R), T_INT(sched_pdsch->nrOfLayers), T_INT(tda_info->nrOfSymbols), T_INT(sched_ctrl->num_total_bytes), T_INT(oh), T_INT(rbStart), T_INT(rbSize), T_INT(TBS));
 
     for (int rb = bwp_start; rb < sched_pdsch->rbSize; rb++)
       rballoc_mask[rb + sched_pdsch->rbStart] |= slbitmap;
@@ -1251,6 +1264,7 @@ void nr_schedule_ue_spec(module_id_t module_id,
                   current_harq_pid);
       T(T_GNB_MAC_RETRANSMISSION_DL_PDU_WITH_DATA, T_INT(module_id), T_INT(CC_id), T_INT(rnti),
         T_INT(frame), T_INT(slot), T_INT(current_harq_pid), T_INT(harq->round), T_BUFFER(harq->transportBlock, TBS));
+      T(T_GNB_MAC_SCHED_RETRANSMIT, T_INT(rnti), T_INT(frame), T_INT(slot), T_INT(current_harq_pid), T_INT(harq->round), T_INT(TBS));
       UE->mac_stats.dl.total_rbs_retx += sched_pdsch->rbSize;
     } else { /* initial transmission */
       LOG_D(NR_MAC, "Initial HARQ transmission in %d.%d\n", frame, slot);
@@ -1269,6 +1283,8 @@ void nr_schedule_ue_spec(module_id_t module_id,
       start_meas(&gNB_mac->rlc_data_req);
       int sdus = 0;
 
+      T(T_GNB_MAC_SCHED_NUM_TOTAL_BYTES, T_INT(rnti), T_INT(frame), T_INT(slot), T_INT(current_harq_pid), T_INT(sched_ctrl->num_total_bytes));
+
       if (sched_ctrl->num_total_bytes > 0) {
         /* loop over all activated logical channels */
         for (int i = 0; i < seq_arr_size(&sched_ctrl->lc_config); ++i) {
@@ -1310,6 +1326,8 @@ void nr_schedule_ue_spec(module_id_t module_id,
                   ndata,
                   bufEnd-buf-sizeof(NR_MAC_SUBHEADER_LONG));
 
+            T(T_GNB_MAC_SCHED_RLC_FILL_BUFFER, T_INT(rnti), T_INT(frame), T_INT(slot), T_INT(lcid), T_INT(ndata), T_INT(len));
+
             if (len == 0)
               break;
 

openair2/LAYER2/nr_pdcp/nr_pdcp_entity.c

@@ -230,6 +230,8 @@ static int nr_pdcp_entity_process_sdu(nr_pdcp_entity_t *entity,
   DevAssert(nr_max_pdcp_pdu_size(size) <= pdu_max_size);
   int      dc_bit;
 
+  T(T_JITTER_PDCP_IN, T_INT((int)(intptr_t)entity), T_INT(entity->type), T_INT(entity->rb_id), T_INT(entity->pdusession_id), T_BUFFER(buffer, size > 128 ? 128 : size), T_INT(size));
+
   if (entity->entity_suspended) {
     LOG_W(PDCP,
           "PDCP entity (%s) %d is suspended. Quit SDU processing.\n",

openair2/LAYER2/nr_rlc/nr_rlc_entity_am.c

@@ -1814,6 +1814,8 @@ void nr_rlc_entity_am_recv_sdu(nr_rlc_entity_t *_entity,
     return;
   }
 
+  T(T_JITTER_RLC_IN, T_INT((int)(intptr_t)entity), T_INT(NR_RLC_AM), T_INT(sdu_id), T_BUFFER(buffer, size > 128 ? 128 : size), T_INT(size));
+
   entity->tx_size += size;
   // SDU received: Count as arrival bytes
   entity->common.stats.rxsdu_bytes += size;

openair2/LAYER2/nr_rlc/nr_rlc_entity_tm.c

@@ -153,6 +153,8 @@ void nr_rlc_entity_tm_recv_sdu(nr_rlc_entity_t *_entity,
     return;
   }
 
+  T(T_JITTER_RLC_IN, T_INT((int)(intptr_t)entity), T_INT(NR_RLC_TM), T_INT(sdu_id), T_BUFFER(buffer, size > 128 ? 128 : size), T_INT(size));
+
   entity->tx_size += size;
 
   sdu = nr_rlc_new_sdu(buffer, size, sdu_id);

openair2/LAYER2/nr_rlc/nr_rlc_entity_um.c

@@ -592,6 +592,8 @@ void nr_rlc_entity_um_recv_sdu(nr_rlc_entity_t *_entity,
     return;
   }
 
+  T(T_JITTER_RLC_IN, T_INT((int)(intptr_t)entity), T_INT(NR_RLC_UM), T_INT(sdu_id), T_BUFFER(buffer, size > 128 ? 128 : size), T_INT(size));
+
   entity->tx_size += size;
 
   sdu = nr_rlc_new_sdu(buffer, size, sdu_id);

openair3/ocp-gtpu/gtp_itf.cpp

@@ -1237,6 +1237,7 @@ void gtpv1uReceiver(int h) {
       return;
     }
     LOG_D(GTPU, "[%d] Received GTP data, msg type: %x\n", h, msg->msgType);
+    T(T_JITTER_GTP_IN, T_INT(h), T_BUFFER(udpData, udpDataLen > 128 ? 128 : udpDataLen), T_INT(udpDataLen));
     switch(msg->msgType) {
       case GTP_ECHO_RSP:
         break;