From 021788c7a76c1b64888ce623f246d5ef02d42f7a Mon Sep 17 00:00:00 2001 From: cig Date: Thu, 29 Jul 2021 14:25:14 +0200 Subject: [PATCH] Improved logging in the MAC PDU processing function at gNB - improved debug logging - minor fixes and cleanup --- .../LAYER2/NR_MAC_gNB/gNB_scheduler_ulsch.c | 163 ++++++++++-------- 1 file changed, 89 insertions(+), 74 deletions(-) diff --git a/openair2/LAYER2/NR_MAC_gNB/gNB_scheduler_ulsch.c b/openair2/LAYER2/NR_MAC_gNB/gNB_scheduler_ulsch.c index fbd8a4b5ca..11d2090094 100644 --- a/openair2/LAYER2/NR_MAC_gNB/gNB_scheduler_ulsch.c +++ b/openair2/LAYER2/NR_MAC_gNB/gNB_scheduler_ulsch.c @@ -174,60 +174,63 @@ void calculate_preferred_ul_tda(module_id_t module_id, const NR_BWP_Uplink_t *ub tdd->nrofUplinkSlots); } +// For both UL-SCH except: +// - UL-SCH: fixed-size MAC CE(known by LCID) +// - UL-SCH: padding +// - UL-SCH: MSG3 48-bits +// |0|1|2|3|4|5|6|7| bit-wise +// |R|F| LCID | +// | L | +// |0|1|2|3|4|5|6|7| bit-wise +// |R|F| LCID | +// | L | +// | L | +// +// For: +// - UL-SCH: fixed-size MAC CE(known by LCID) +// - UL-SCH: padding, for single/multiple 1-oct padding CE(s) +// - UL-SCH: MSG3 48-bits +// |0|1|2|3|4|5|6|7| bit-wise +// |R|R| LCID | +// +// LCID: The Logical Channel ID field identifies the logical channel instance of the corresponding MAC SDU or the type of the corresponding MAC CE or padding as described in Tables 6.2.1-1 and 6.2.1-2 for the DL-SCH and UL-SCH respectively. There is one LCID field per MAC subheader. The LCID field size is 6 bits; +// L: The Length field indicates the length of the corresponding MAC SDU or variable-sized MAC CE in bytes. There is one L field per MAC subheader except for subheaders corresponding to fixed-sized MAC CEs and padding. The size of the L field is indicated by the F field; +// F: length of L is 0:8 or 1:16 bits wide +// R: Reserved bit, set to zero. + void nr_process_mac_pdu(module_id_t module_idP, int UE_id, uint8_t CC_id, frame_t frameP, sub_frame_t slot, uint8_t *pduP, - uint16_t mac_pdu_len) + int pdu_len) { - // This function is adapting code from the old - // parse_header(...) and ue_send_sdu(...) functions of OAI LTE - - uint8_t *pdu_ptr = pduP, rx_lcid, done = 0; - int pdu_len = mac_pdu_len; - uint16_t mac_ce_len, mac_subheader_len, mac_sdu_len; + uint8_t rx_lcid; + uint8_t done = 0; + uint16_t mac_ce_len; + uint16_t mac_subheader_len; + uint16_t mac_sdu_len; NR_UE_info_t *UE_info = &RC.nrmac[module_idP]->UE_info; NR_UE_sched_ctrl_t *sched_ctrl = &UE_info->UE_sched_ctrl[UE_id]; if ( pduP[0] != UL_SCH_LCID_PADDING ) - trace_NRpdu(DIRECTION_UPLINK, pduP, mac_pdu_len ,UE_id, WS_C_RNTI, UE_info->rnti[UE_id], frameP, 0, 0, 0); + trace_NRpdu(DIRECTION_UPLINK, pduP, pdu_len, UE_id, WS_C_RNTI, UE_info->rnti[UE_id], frameP, 0, 0, 0); - // For both DL/UL-SCH - // Except: - // - UL/DL-SCH: fixed-size MAC CE(known by LCID) - // - UL/DL-SCH: padding - // - UL-SCH: MSG3 48-bits - // |0|1|2|3|4|5|6|7| bit-wise - // |R|F| LCID | - // | L | - // |0|1|2|3|4|5|6|7| bit-wise - // |R|F| LCID | - // | L | - // | L | - - // For both DL/UL-SCH - // For: - // - UL/DL-SCH: fixed-size MAC CE(known by LCID) - // - UL/DL-SCH: padding, for single/multiple 1-oct padding CE(s) - // - UL-SCH: MSG3 48-bits - // |0|1|2|3|4|5|6|7| bit-wise - // |R|R| LCID | - // LCID: The Logical Channel ID field identifies the logical channel instance of the corresponding MAC SDU or the type of the corresponding MAC CE or padding as described in Tables 6.2.1-1 and 6.2.1-2 for the DL-SCH and UL-SCH respectively. There is one LCID field per MAC subheader. The LCID field size is 6 bits; - // L: The Length field indicates the length of the corresponding MAC SDU or variable-sized MAC CE in bytes. There is one L field per MAC subheader except for subheaders corresponding to fixed-sized MAC CEs and padding. The size of the L field is indicated by the F field; - // F: lenght of L is 0:8 or 1:16 bits wide - // R: Reserved bit, set to zero. + #ifdef ENABLE_MAC_PAYLOAD_DEBUG + LOG_I(NR_MAC, "In %s: dumping MAC PDU in %d.%d:\n", __func__, frameP, slot); + log_dump(NR_MAC, pduP, pdu_len, LOG_DUMP_CHAR, "\n"); + #endif while (!done && pdu_len > 0){ mac_ce_len = 0; - mac_subheader_len = 1; // default to fixed-length subheader = 1-oct + mac_subheader_len = sizeof(NR_MAC_SUBHEADER_FIXED); mac_sdu_len = 0; - rx_lcid = ((NR_MAC_SUBHEADER_FIXED *)pdu_ptr)->LCID; + rx_lcid = ((NR_MAC_SUBHEADER_FIXED *)pduP)->LCID; - LOG_D(NR_MAC, "LCID received at gNB side: %d \n", rx_lcid); + LOG_D(NR_MAC, "In %s: received UL-SCH sub-PDU with LCID 0x%x in %d.%d (remaining PDU length %d)\n", __func__, rx_lcid, frameP, slot, pdu_len); unsigned char *ce_ptr; int n_Lcg = 0; @@ -236,7 +239,7 @@ void nr_process_mac_pdu(module_id_t module_idP, // MAC CE /*#ifdef DEBUG_HEADER_PARSING - LOG_D(NR_MAC, "[UE] LCID %d, PDU length %d\n", ((NR_MAC_SUBHEADER_FIXED *)pdu_ptr)->LCID, pdu_len); + LOG_D(NR_MAC, "[UE] LCID %d, PDU length %d\n", ((NR_MAC_SUBHEADER_FIXED *)pduP)->LCID, pdu_len); #endif*/ case UL_SCH_LCID_RECOMMENDED_BITRATE_QUERY: // 38.321 Ch6.1.3.20 @@ -252,7 +255,7 @@ void nr_process_mac_pdu(module_id_t module_idP, //fixed length mac_ce_len =1; /* Extract short BSR value */ - ce_ptr = &pdu_ptr[mac_subheader_len]; + ce_ptr = &pduP[mac_subheader_len]; NR_BSR_SHORT *bsr_s = (NR_BSR_SHORT *) ce_ptr; sched_ctrl->estimated_ul_buffer = 0; sched_ctrl->estimated_ul_buffer = NR_SHORT_BSR_TABLE[bsr_s->Buffer_size]; @@ -270,14 +273,14 @@ void nr_process_mac_pdu(module_id_t module_idP, case UL_SCH_LCID_L_TRUNCATED_BSR: //38.321 section 6.1.3.1 //variable length - mac_ce_len |= (uint16_t)((NR_MAC_SUBHEADER_SHORT *)pdu_ptr)->L; + mac_ce_len |= (uint16_t)((NR_MAC_SUBHEADER_SHORT *)pduP)->L; mac_subheader_len = 2; - if(((NR_MAC_SUBHEADER_SHORT *)pdu_ptr)->F){ - mac_ce_len |= (uint16_t)(((NR_MAC_SUBHEADER_LONG *)pdu_ptr)->L2)<<8; + if(((NR_MAC_SUBHEADER_SHORT *)pduP)->F){ + mac_ce_len |= (uint16_t)(((NR_MAC_SUBHEADER_LONG *)pduP)->L2)<<8; mac_subheader_len = 3; } /* Extract long BSR value */ - ce_ptr = &pdu_ptr[mac_subheader_len]; + ce_ptr = &pduP[mac_subheader_len]; NR_BSR_LONG *bsr_l = (NR_BSR_LONG *) ce_ptr; sched_ctrl->estimated_ul_buffer = 0; @@ -290,18 +293,18 @@ void nr_process_mac_pdu(module_id_t module_idP, for (int n = 0; n < n_Lcg; n++){ LOG_D(NR_MAC, "LONG BSR, %d/%d (n/n_Lcg), BS Index %d, BS value < %d", - n, n_Lcg, pdu_ptr[mac_subheader_len + 1 + n], - NR_LONG_BSR_TABLE[pdu_ptr[mac_subheader_len + 1 + n]]); + n, n_Lcg, pduP[mac_subheader_len + 1 + n], + NR_LONG_BSR_TABLE[pduP[mac_subheader_len + 1 + n]]); sched_ctrl->estimated_ul_buffer += - NR_LONG_BSR_TABLE[pdu_ptr[mac_subheader_len + 1 + n]]; + NR_LONG_BSR_TABLE[pduP[mac_subheader_len + 1 + n]]; LOG_D(NR_MAC, "LONG BSR at %4d.%2d, %d/%d (n/n_Lcg), BS Index %d, BS value < %d, total %d\n", frameP, slot, n, n_Lcg, - pdu_ptr[mac_subheader_len + 1 + n], - NR_LONG_BSR_TABLE[pdu_ptr[mac_subheader_len + 1 + n]], + pduP[mac_subheader_len + 1 + n], + NR_LONG_BSR_TABLE[pduP[mac_subheader_len + 1 + n]], sched_ctrl->estimated_ul_buffer); } @@ -319,7 +322,7 @@ void nr_process_mac_pdu(module_id_t module_idP, //fixed length mac_ce_len = 2; /* Extract SINGLE ENTRY PHR elements for PHR calculation */ - ce_ptr = &pdu_ptr[mac_subheader_len]; + ce_ptr = &pduP[mac_subheader_len]; NR_SINGLE_ENTRY_PHR_MAC_CE *phr = (NR_SINGLE_ENTRY_PHR_MAC_CE *) ce_ptr; /* Save the phr info */ const int PH = phr->PH; @@ -338,10 +341,10 @@ void nr_process_mac_pdu(module_id_t module_idP, case UL_SCH_LCID_MULTI_ENTRY_PHR_1_OCT: //38.321 section 6.1.3.9 // varialbe length - mac_ce_len |= (uint16_t)((NR_MAC_SUBHEADER_SHORT *)pdu_ptr)->L; + mac_ce_len |= (uint16_t)((NR_MAC_SUBHEADER_SHORT *)pduP)->L; mac_subheader_len = 2; - if(((NR_MAC_SUBHEADER_SHORT *)pdu_ptr)->F){ - mac_ce_len |= (uint16_t)(((NR_MAC_SUBHEADER_LONG *)pdu_ptr)->L2)<<8; + if(((NR_MAC_SUBHEADER_SHORT *)pduP)->F){ + mac_ce_len |= (uint16_t)(((NR_MAC_SUBHEADER_LONG *)pduP)->L2)<<8; mac_subheader_len = 3; } /* Extract MULTI ENTRY PHR elements from single octet bitmap for PHR calculation */ @@ -350,10 +353,10 @@ void nr_process_mac_pdu(module_id_t module_idP, case UL_SCH_LCID_MULTI_ENTRY_PHR_4_OCT: //38.321 section 6.1.3.9 // varialbe length - mac_ce_len |= (uint16_t)((NR_MAC_SUBHEADER_SHORT *)pdu_ptr)->L; + mac_ce_len |= (uint16_t)((NR_MAC_SUBHEADER_SHORT *)pduP)->L; mac_subheader_len = 2; - if(((NR_MAC_SUBHEADER_SHORT *)pdu_ptr)->F){ - mac_ce_len |= (uint16_t)(((NR_MAC_SUBHEADER_LONG *)pdu_ptr)->L2)<<8; + if(((NR_MAC_SUBHEADER_SHORT *)pduP)->F){ + mac_ce_len |= (uint16_t)(((NR_MAC_SUBHEADER_LONG *)pduP)->L2)<<8; mac_subheader_len = 3; } /* Extract MULTI ENTRY PHR elements from four octets bitmap for PHR calculation */ @@ -366,13 +369,13 @@ void nr_process_mac_pdu(module_id_t module_idP, case UL_SCH_LCID_SRB1: case UL_SCH_LCID_SRB2: - if(((NR_MAC_SUBHEADER_SHORT *)pdu_ptr)->F){ - //mac_sdu_len |= (uint16_t)(((NR_MAC_SUBHEADER_LONG *)pdu_ptr)->L2)<<8; + if(((NR_MAC_SUBHEADER_SHORT *)pduP)->F){ + //mac_sdu_len |= (uint16_t)(((NR_MAC_SUBHEADER_LONG *)pduP)->L2)<<8; mac_subheader_len = 3; - mac_sdu_len = ((uint16_t)(((NR_MAC_SUBHEADER_LONG *) pdu_ptr)->L1 & 0x7f) << 8) - | ((uint16_t)((NR_MAC_SUBHEADER_LONG *) pdu_ptr)->L2 & 0xff); + mac_sdu_len = ((uint16_t)(((NR_MAC_SUBHEADER_LONG *) pduP)->L1 & 0x7f) << 8) + | ((uint16_t)((NR_MAC_SUBHEADER_LONG *) pduP)->L2 & 0xff); } else { - mac_sdu_len = (uint16_t)((NR_MAC_SUBHEADER_SHORT *)pdu_ptr)->L; + mac_sdu_len = (uint16_t)((NR_MAC_SUBHEADER_SHORT *)pduP)->L; mac_subheader_len = 2; } LOG_D(NR_MAC, "[UE %d] Frame %d : ULSCH -> UL-DCCH %d (gNB %d, %d bytes), rnti: %d \n", module_idP, frameP, rx_lcid, module_idP, mac_sdu_len, UE_info->rnti[UE_id]); @@ -383,7 +386,7 @@ void nr_process_mac_pdu(module_id_t module_idP, ENB_FLAG_YES, MBMS_FLAG_NO, rx_lcid, - (char *) (pdu_ptr + mac_subheader_len), + (char *) (pduP + mac_subheader_len), mac_sdu_len, 1, NULL); @@ -404,7 +407,7 @@ void nr_process_mac_pdu(module_id_t module_idP, // Check if it is a valid CCCH1 message, we get all 00's messages very often int i = 0; for(i=0; i<(mac_subheader_len+mac_sdu_len); i++) { - if(pdu_ptr[i] != 0) { + if(pduP[i] != 0) { break; } } @@ -425,35 +428,34 @@ void nr_process_mac_pdu(module_id_t module_idP, 0, UE_info->rnti[UE_id], CCCH, - pdu_ptr+mac_subheader_len, + pduP + mac_subheader_len, mac_sdu_len, 0); break; case UL_SCH_LCID_DTCH: // check if LCID is valid at current time. - if (((NR_MAC_SUBHEADER_SHORT *)pdu_ptr)->F) { - // mac_sdu_len |= (uint16_t)(((NR_MAC_SUBHEADER_LONG *)pdu_ptr)->L2)<<8; + if (((NR_MAC_SUBHEADER_SHORT *)pduP)->F) { + // mac_sdu_len |= (uint16_t)(((NR_MAC_SUBHEADER_LONG *)pduP)->L2)<<8; mac_subheader_len = 3; - mac_sdu_len = ((uint16_t)(((NR_MAC_SUBHEADER_LONG *)pdu_ptr)->L1 & 0x7f) << 8) - | ((uint16_t)((NR_MAC_SUBHEADER_LONG *)pdu_ptr)->L2 & 0xff); + mac_sdu_len = ((uint16_t)(((NR_MAC_SUBHEADER_LONG *)pduP)->L1 & 0x7f) << 8) + | ((uint16_t)((NR_MAC_SUBHEADER_LONG *)pduP)->L2 & 0xff); } else { - mac_sdu_len = (uint16_t)((NR_MAC_SUBHEADER_SHORT *)pdu_ptr)->L; + mac_sdu_len = (uint16_t)((NR_MAC_SUBHEADER_SHORT *)pduP)->L; mac_subheader_len = 2; } - LOG_D(NR_MAC, "[UE %d] Frame %d : ULSCH -> UL-%s %d (gNB %d, %d bytes)\n", + LOG_D(NR_MAC, "In %s: [UE %d] %d.%d : ULSCH -> UL-%s %d (gNB %d, %d bytes)\n", + __func__, module_idP, frameP, + slot, rx_lcid<4?"DCCH":"DTCH", rx_lcid, module_idP, mac_sdu_len); UE_info->mac_stats[UE_id].lc_bytes_rx[rx_lcid] += mac_sdu_len; -#if defined(ENABLE_MAC_PAYLOAD_DEBUG) - log_dump(NR_MAC, pdu_ptr + mac_subheader_len, 32, LOG_DUMP_CHAR, "\n"); -#endif mac_rlc_data_ind(module_idP, UE_info->rnti[UE_id], @@ -462,7 +464,7 @@ void nr_process_mac_pdu(module_id_t module_idP, ENB_FLAG_YES, MBMS_FLAG_NO, rx_lcid, - (char *)(pdu_ptr + mac_subheader_len), + (char *)(pduP + mac_subheader_len), mac_sdu_len, 1, NULL); @@ -479,14 +481,27 @@ void nr_process_mac_pdu(module_id_t module_idP, return; break; } - pdu_ptr += ( mac_subheader_len + mac_ce_len + mac_sdu_len ); + + #ifdef ENABLE_MAC_PAYLOAD_DEBUG + if (rx_lcid < 45 || rx_lcid == 52 || rx_lcid == 63) { + LOG_I(NR_MAC, "In %s: dumping UL MAC SDU sub-header with length %d (LCID = 0x%02x):\n", __func__, mac_subheader_len, rx_lcid); + log_dump(NR_MAC, pduP, mac_subheader_len, LOG_DUMP_CHAR, "\n"); + LOG_I(NR_MAC, "In %s: dumping UL MAC SDU with length %d (LCID = 0x%02x):\n", __func__, mac_sdu_len, rx_lcid); + log_dump(NR_MAC, pduP + mac_subheader_len, mac_sdu_len, LOG_DUMP_CHAR, "\n"); + } else { + LOG_I(NR_MAC, "In %s: dumping UL MAC CE with length %d (LCID = 0x%02x):\n", __func__, mac_ce_len, rx_lcid); + log_dump(NR_MAC, pduP + mac_subheader_len + mac_sdu_len, mac_ce_len, LOG_DUMP_CHAR, "\n"); + } + #endif + + pduP += ( mac_subheader_len + mac_ce_len + mac_sdu_len ); pdu_len -= ( mac_subheader_len + mac_ce_len + mac_sdu_len ); if (pdu_len < 0) { - LOG_E(NR_MAC, "%s() residual mac pdu length < 0!, pdu_len: %d\n", __func__, pdu_len); + LOG_E(NR_MAC, "In %s: residual UL MAC PDU in %d.%d with length < 0!, pdu_len %d \n", __func__, frameP, slot, pdu_len); LOG_E(NR_MAC, "MAC PDU "); for (int i = 0; i < 20; i++) // Only printf 1st - 20nd bytes - printf("%02x ", pdu_ptr[i]); + printf("%02x ", pduP[i]); printf("\n"); return; }