From 6d6d05535c63aabe5a5cb95073c0c7f312330def Mon Sep 17 00:00:00 2001 From: Raymond Knopp Date: Tue, 24 Sep 2019 18:53:39 +0200 Subject: [PATCH] nr-ip-over-LTE: Resolved issue with duplicate IP packet at the receiver UE IP interface and packet losses are reduced. Remaining to identify why occasionally IP packets are received at the PDCP stack later than the time slot of their arrival at PHY/MAC. Introduced some debug logs, to be removed later. --- executables/nr-ue.c | 12 +++++----- .../nr_dl_channel_estimation.c | 2 +- .../PHY/NR_UE_TRANSPORT/nr_dlsch_decoding.c | 2 +- openair1/SCHED_NR_UE/fapi_nr_ue_l1.c | 22 +++++++++---------- openair1/SCHED_NR_UE/phy_procedures_nr_ue.c | 2 +- openair2/LAYER2/NR_MAC_UE/nr_ue_procedures.c | 8 +++---- .../LAYER2/NR_MAC_gNB/gNB_scheduler_phytest.c | 20 ++++++++++------- openair2/LAYER2/PDCP_v10.1.0/pdcp.c | 7 ++++++ openair2/LAYER2/PDCP_v10.1.0/pdcp_fifo.c | 4 ++++ openair2/LAYER2/RLC/UM_v9.3.0/rlc_um_dar.c | 17 +++++++++++--- 10 files changed, 62 insertions(+), 34 deletions(-) diff --git a/executables/nr-ue.c b/executables/nr-ue.c index 3c8cd4bcf3..8639b8f690 100644 --- a/executables/nr-ue.c +++ b/executables/nr-ue.c @@ -382,16 +382,18 @@ void processSlotRX( PHY_VARS_NR_UE *UE, UE_nr_rxtx_proc_t *proc) { LOG_D(PHY,"phy_procedures_nrUE_RX: slot:%d, time %lu\n", proc->nr_tti_rx, (rdtsc()-a)/3500); //printf(">>> nr_ue_pdcch_procedures ended\n"); #endif - } - - if(IS_SOFTMODEM_NOS1){ + if(IS_SOFTMODEM_NOS1){ //&& proc->nr_tti_rx==1 //Hardcoded rnti value protocol_ctxt_t ctxt; PROTOCOL_CTXT_SET_BY_MODULE_ID(&ctxt, UE->Mod_id, ENB_FLAG_NO, 0x1234, proc->frame_rx, proc->nr_tti_rx, 0); - pdcp_run(&ctxt); + //pdcp_run(&ctxt); + pdcp_fifo_flush_sdus(&ctxt); } + } + + // no UL for now /* if (UE->mac_enabled==1) { @@ -744,7 +746,7 @@ void *UE_thread(void *arg) { msgToPush->key=slot_nr; pushTpool(Tpool, msgToPush); - if (getenv("RFSIMULATOR")) { + if (getenv("RFSIMULATOR") || IS_SOFTMODEM_NOS1) { //getenv("RFSIMULATOR") // FixMe: Wait previous thread is done, because race conditions seems too bad // in case of actual RF board, the overlap between threads mitigate the issue // We must receive one message, that proves the slot processing is done diff --git a/openair1/PHY/NR_UE_ESTIMATION/nr_dl_channel_estimation.c b/openair1/PHY/NR_UE_ESTIMATION/nr_dl_channel_estimation.c index 6df9e0c20e..fadcb9c660 100644 --- a/openair1/PHY/NR_UE_ESTIMATION/nr_dl_channel_estimation.c +++ b/openair1/PHY/NR_UE_ESTIMATION/nr_dl_channel_estimation.c @@ -645,7 +645,7 @@ int nr_pdcch_channel_estimation(PHY_VARS_NR_UE *ue, for (p=0; pframe_parms.nb_antenna_ports_eNB; p++) { if (ue->pdcch_vars[ue->current_thread_id[Ns]][eNB_offset]->dl_ch_estimates[(p<<1)+aarx]) { - LOG_I(PHY,"Channel Impulse Computation Slot %d ThreadId %d Symbol %d \n", Ns, ue->current_thread_id[Ns], symbol); + LOG_D(PHY,"Channel Impulse Computation Slot %d ThreadId %d Symbol %d \n", Ns, ue->current_thread_id[Ns], symbol); idft((int16_t*) &ue->pdcch_vars[ue->current_thread_id[Ns]][eNB_offset]->dl_ch_estimates[(p<<1)+aarx][0], (int16_t*) ue->pdcch_vars[ue->current_thread_id[Ns]][eNB_offset]->dl_ch_estimates_time[(p<<1)+aarx],1); } diff --git a/openair1/PHY/NR_UE_TRANSPORT/nr_dlsch_decoding.c b/openair1/PHY/NR_UE_TRANSPORT/nr_dlsch_decoding.c index a906215e42..20f3574ee2 100644 --- a/openair1/PHY/NR_UE_TRANSPORT/nr_dlsch_decoding.c +++ b/openair1/PHY/NR_UE_TRANSPORT/nr_dlsch_decoding.c @@ -574,7 +574,7 @@ uint32_t nr_dlsch_decoding(PHY_VARS_NR_UE *phy_vars_ue, if ((err_flag == 0) && (ret>=(1+dlsch->max_ldpc_iterations))) {// a Code segment is in error so break; - LOG_I(PHY,"AbsSubframe %d.%d CRC failed, segment %d/%d \n",frame%1024,nr_tti_rx,r,harq_process->C-1); + LOG_D(PHY,"AbsSubframe %d.%d CRC failed, segment %d/%d \n",frame%1024,nr_tti_rx,r,harq_process->C-1); err_flag = 1; } } diff --git a/openair1/SCHED_NR_UE/fapi_nr_ue_l1.c b/openair1/SCHED_NR_UE/fapi_nr_ue_l1.c index 6802b77d8c..a213aedf18 100644 --- a/openair1/SCHED_NR_UE/fapi_nr_ue_l1.c +++ b/openair1/SCHED_NR_UE/fapi_nr_ue_l1.c @@ -217,17 +217,17 @@ int8_t nr_ue_phy_config_request(nr_phy_config_t *phy_config){ if(phy_config != NULL){ if(phy_config->config_req.config_mask & FAPI_NR_CONFIG_REQUEST_MASK_PBCH){ - LOG_I(MAC,"[L1][IF module][PHY CONFIG]\n"); - LOG_I(MAC,"subcarrier spacing: %d\n", phy_config->config_req.pbch_config.subcarrier_spacing_common); - LOG_I(MAC,"ssb carrier offset: %d\n", phy_config->config_req.pbch_config.ssb_subcarrier_offset); - LOG_I(MAC,"dmrs type A position: %d\n", phy_config->config_req.pbch_config.dmrs_type_a_position); - LOG_I(MAC,"pdcch config sib1: %d\n", phy_config->config_req.pbch_config.pdcch_config_sib1); - LOG_I(MAC,"cell barred: %d\n", phy_config->config_req.pbch_config.cell_barred); - LOG_I(MAC,"intra frequency reselection: %d\n", phy_config->config_req.pbch_config.intra_frequency_reselection); - LOG_I(MAC,"system frame number: %d\n", phy_config->config_req.pbch_config.system_frame_number); - LOG_I(MAC,"ssb index: %d\n", phy_config->config_req.pbch_config.ssb_index); - LOG_I(MAC,"half frame bit: %d\n", phy_config->config_req.pbch_config.half_frame_bit); - LOG_I(MAC,"-------------------------------\n"); + LOG_D(MAC,"[L1][IF module][PHY CONFIG]\n"); + LOG_D(MAC,"subcarrier spacing: %d\n", phy_config->config_req.pbch_config.subcarrier_spacing_common); + LOG_D(MAC,"ssb carrier offset: %d\n", phy_config->config_req.pbch_config.ssb_subcarrier_offset); + LOG_D(MAC,"dmrs type A position: %d\n", phy_config->config_req.pbch_config.dmrs_type_a_position); + LOG_D(MAC,"pdcch config sib1: %d\n", phy_config->config_req.pbch_config.pdcch_config_sib1); + LOG_D(MAC,"cell barred: %d\n", phy_config->config_req.pbch_config.cell_barred); + LOG_D(MAC,"intra frequency reselection: %d\n", phy_config->config_req.pbch_config.intra_frequency_reselection); + LOG_D(MAC,"system frame number: %d\n", phy_config->config_req.pbch_config.system_frame_number); + LOG_D(MAC,"ssb index: %d\n", phy_config->config_req.pbch_config.ssb_index); + LOG_D(MAC,"half frame bit: %d\n", phy_config->config_req.pbch_config.half_frame_bit); + LOG_D(MAC,"-------------------------------\n"); memcpy(&nrUE_config.pbch_config,&phy_config->config_req.pbch_config,sizeof(fapi_nr_pbch_config_t)); diff --git a/openair1/SCHED_NR_UE/phy_procedures_nr_ue.c b/openair1/SCHED_NR_UE/phy_procedures_nr_ue.c index 8873394a18..c6facd5dda 100644 --- a/openair1/SCHED_NR_UE/phy_procedures_nr_ue.c +++ b/openair1/SCHED_NR_UE/phy_procedures_nr_ue.c @@ -4336,7 +4336,7 @@ int phy_procedures_nrUE_RX(PHY_VARS_NR_UE *ue, // looking for pbch only in slot where it is supposed to be if ((ue->decode_MIB == 1) && slot_pbch) { - LOG_I(PHY," ------ PBCH ChannelComp/LLR: frame.slot %d.%d ------ \n", frame_rx%1024, nr_tti_rx); + LOG_D(PHY," ------ PBCH ChannelComp/LLR: frame.slot %d.%d ------ \n", frame_rx%1024, nr_tti_rx); for (int i=1; i<4; i++) { diff --git a/openair2/LAYER2/NR_MAC_UE/nr_ue_procedures.c b/openair2/LAYER2/NR_MAC_UE/nr_ue_procedures.c index 2d0f647a31..92bb451296 100644 --- a/openair2/LAYER2/NR_MAC_UE/nr_ue_procedures.c +++ b/openair2/LAYER2/NR_MAC_UE/nr_ue_procedures.c @@ -228,7 +228,7 @@ int8_t nr_ue_decode_mib( void *pduP, uint16_t cell_id ){ - LOG_I(MAC,"[L2][MAC] decode mib\n"); + LOG_D(MAC,"[L2][MAC] decode mib\n"); NR_UE_MAC_INST_t *mac = get_mac_inst(module_id); @@ -2387,15 +2387,15 @@ nr_ue_send_sdu(module_id_t module_idP, #endif if ((rx_lcids[i] < NB_RB_MAX) && (rx_lcids[i] > DCCH1)) { - LOG_I(MAC, + LOG_D(MAC, "[UE %d] Frame %d : DLSCH -> DL-DTCH%d (eNB %d, %d bytes)\n", module_idP, frameP, rx_lcids[i], eNB_index, rx_lengths[i]); #if defined(ENABLE_MAC_PAYLOAD_DEBUG) - LOG_I(MAC, "Printing MAC PDU contents \n"); + LOG_I(MAC, "Printing MAC PDU contents at slot: %d \n", subframeP); int j; - for (j = 0; j < 10; j++) //rx_lengths[i] + for (j = 0; j < 20; j++) //rx_lengths[i] LOG_I(MAC, "%x.", (unsigned char) payload_ptr[j]); LOG_I(MAC, "\n"); #endif diff --git a/openair2/LAYER2/NR_MAC_gNB/gNB_scheduler_phytest.c b/openair2/LAYER2/NR_MAC_gNB/gNB_scheduler_phytest.c index 0b21c2f6c5..ce57cb9450 100644 --- a/openair2/LAYER2/NR_MAC_gNB/gNB_scheduler_phytest.c +++ b/openair2/LAYER2/NR_MAC_gNB/gNB_scheduler_phytest.c @@ -285,6 +285,11 @@ int configure_fapi_dl_Tx(nfapi_nr_dl_config_request_body_t *dl_req, } + + + + + void nr_schedule_uss_dlsch_phytest(module_id_t module_idP, frame_t frameP, sub_frame_t slotP) @@ -430,7 +435,7 @@ void nr_schedule_uss_dlsch_phytest(module_id_t module_idP, post_padding = 1; } - offset = generate_dlsch_header((unsigned char *) DLSCH_pdu.payload[0], + offset = generate_dlsch_header((unsigned char *)nr_mac->UE_list.DLSCH_pdu[CC_id][0][0].payload[0], //DLSCH_pdu.payload[0], num_sdus, //num_sdus sdu_lengths, // sdu_lcids, 255, // no drx @@ -442,20 +447,17 @@ void nr_schedule_uss_dlsch_phytest(module_id_t module_idP, // Probably there should be other actions done before that // cycle through SDUs and place in dlsch_buffer - // Since we do not have an active UE_list for now we replace with a single DLSCH_pdu //memcpy(&UE_list->DLSCH_pdu[CC_id][0][UE_id].payload[0][offset], dlsch_buffer, sdu_length_total); - memcpy(&DLSCH_pdu.payload[0][offset], dlsch_buffer, sdu_length_total); + memcpy(&nr_mac->UE_list.DLSCH_pdu[CC_id][0][UE_id].payload[0][offset], dlsch_buffer, sdu_length_total); + // fill remainder of DLSCH with 0 for (int j = 0; j < (TBS - sdu_length_total - offset); j++) { - // Since we do not have an active UE_list for now we replace with a single DLSCH_pdu //UE_list->DLSCH_pdu[CC_id][0][UE_id].payload[0][offset + sdu_length_total + j] = 0; - DLSCH_pdu.payload[0][offset + sdu_length_total + j] = 0; + nr_mac->UE_list.DLSCH_pdu[CC_id][0][0].payload[0][offset + sdu_length_total + j] = 0; } - TBS_bytes = configure_fapi_dl_Tx(dl_req, TX_req, cfg, &nr_mac->coreset[CC_id][1], &nr_mac->search_space[CC_id][1], nr_mac->pdu_index[CC_id]); - - memcpy(nr_mac->UE_list.DLSCH_pdu[CC_id][0][0].payload[0],DLSCH_pdu.payload[0],TBS_bytes); + TBS_bytes = configure_fapi_dl_Tx(dl_req, TX_req, cfg, &nr_mac->coreset[CC_id][1], &nr_mac->search_space[CC_id][1], nr_mac->pdu_index[CC_id]); LOG_I(MAC, "Printing first 10 payload bytes at the gNB side, Frame: %d, slot: %d, , TBS size: %d \n \n", frameP, slotP, TBS_bytes); for(int i = 0; i < 10; i++) { // TBS_bytes dlsch_pdu_rel15->transport_block_size/8 6784/8 @@ -504,3 +506,5 @@ void nr_schedule_uss_dlsch_phytest(module_id_t module_idP, } } //for (CC_id=0; CC_iddata,sdu_buffer_sizeP, "[MSG] PDCP UL %s PDU on rb_id %d\n", (srb_flagP)? "CONTROL" : "DATA", rb_idP); + + #if T_TRACER if (ctxt_pP->enb_flag != ENB_FLAG_NO) @@ -1050,6 +1052,11 @@ pdcp_data_ind( memcpy(&new_sdu_p->data[sizeof (pdcp_data_ind_header_t)], &sdu_buffer_pP->data[payload_offset], sdu_buffer_sizeP - payload_offset); + + LOG_I(PDCP, "Printing PDCP SDU before adding it to the list: \n"); + for (int i=0; i<30; i++){ + LOG_I(PDCP, "%x", sdu_buffer_pP->data[i]); + } list_add_tail_eurecom (new_sdu_p, sdu_list_p); } diff --git a/openair2/LAYER2/PDCP_v10.1.0/pdcp_fifo.c b/openair2/LAYER2/PDCP_v10.1.0/pdcp_fifo.c index ba1ef3315d..582b776da7 100644 --- a/openair2/LAYER2/PDCP_v10.1.0/pdcp_fifo.c +++ b/openair2/LAYER2/PDCP_v10.1.0/pdcp_fifo.c @@ -135,6 +135,10 @@ int pdcp_fifo_flush_sdus(const protocol_ctxt_t *const ctxt_pP) { } // PDCP_USE_NETLINK AssertFatal(ret >= 0,"[PDCP_FIFOS] pdcp_fifo_flush_sdus (errno: %d %s)\n", errno, strerror(errno)); + LOG_I(PDCP, "Printing PDCP SDU before removing it from the list: \n"); + for (int i=0; i<30; i++){ + LOG_I(PDCP, "%x", sdu_p->data[i]); + } list_remove_head (&pdcp_sdu_list); free_mem_block (sdu_p, __func__); pdcp_nb_sdu_sent ++; diff --git a/openair2/LAYER2/RLC/UM_v9.3.0/rlc_um_dar.c b/openair2/LAYER2/RLC/UM_v9.3.0/rlc_um_dar.c index f37626ae4c..832770f3ba 100644 --- a/openair2/LAYER2/RLC/UM_v9.3.0/rlc_um_dar.c +++ b/openair2/LAYER2/RLC/UM_v9.3.0/rlc_um_dar.c @@ -723,10 +723,10 @@ void rlc_um_check_timer_dar_time_out( signed int in_window; rlc_usn_t old_vr_ur; - VCD_SIGNAL_DUMPER_DUMP_FUNCTION_BY_NAME(VCD_SIGNAL_DUMPER_FUNCTIONS_RLC_UM_CHECK_TIMER_DAR_TIME_OUT,VCD_FUNCTION_IN); if ((rlc_pP->t_reordering.running)) { + //LOG_I(RLC, "[rlc_um_check_timer_dar_time_out] 2 \n"); if ( // CASE 1: start time out // +-----------+------------------+----------+ @@ -787,6 +787,7 @@ void rlc_um_check_timer_dar_time_out( LOG_D(RLC, " %d", rlc_pP->vr_ur); LOG_D(RLC, "\n"); #endif + LOG_I(RLC, "[rlc_um_check_timer_dar_time_out] 3 \n"); rlc_um_try_reassembly(ctxt_pP, rlc_pP ,old_vr_ur, rlc_pP->vr_ur); in_window = rlc_um_in_window(ctxt_pP, rlc_pP, rlc_pP->vr_ur, rlc_pP->vr_uh, rlc_pP->vr_uh); @@ -1039,6 +1040,7 @@ rlc_um_receive_process_dar ( } else { free_mem_block(pdu_mem_pP, __func__); pdu_mem_pP = NULL; + //LOG_I(RLC, "[rlc_um_receive_process_dar] Problematic case 1 \n"); return; } @@ -1065,6 +1067,7 @@ rlc_um_receive_process_dar ( rlc_pP->stat_rx_data_pdu_out_of_window += 1; rlc_pP->stat_rx_data_bytes_out_of_window += tb_sizeP; free_mem_block(pdu_mem_pP, __func__); + //LOG_I(RLC, "[rlc_um_receive_process_dar] Problematic case 2 \n"); pdu_mem_pP = NULL; RLC_UM_MUTEX_UNLOCK(&rlc_pP->lock_dar_buffer); VCD_SIGNAL_DUMPER_DUMP_FUNCTION_BY_NAME(VCD_SIGNAL_DUMPER_FUNCTIONS_RLC_UM_RECEIVE_PROCESS_DAR, VCD_FUNCTION_OUT); @@ -1083,6 +1086,7 @@ rlc_um_receive_process_dar ( //discard the PDU rlc_pP->stat_rx_data_pdus_duplicate += 1; rlc_pP->stat_rx_data_bytes_duplicate += tb_sizeP; + //LOG_I(RLC, "[rlc_um_receive_process_dar] Problematic case 3 \n"); free_mem_block(pdu_mem_pP, __func__); pdu_mem_pP = NULL; RLC_UM_MUTEX_UNLOCK(&rlc_pP->lock_dar_buffer); @@ -1115,6 +1119,7 @@ rlc_um_receive_process_dar ( // -if VR(UR) falls outside of the reordering window: // -set VR(UR) to (VR(UH) – UM_Window_Size); if (rlc_um_in_reordering_window(ctxt_pP, rlc_pP, sn) < 0) { + LOG_I(RLC, "[rlc_um_receive_process_dar] Before calling rlc_um_try_reassembly() 1 \n"); #if TRACE_RLC_UM_DAR LOG_D(RLC, PROTOCOL_RLC_UM_CTXT_FMT" RX PDU SN %d OUTSIDE REORDERING WINDOW VR(UH)=%d UM_Window_Size=%d\n", PROTOCOL_RLC_UM_CTXT_ARGS(ctxt_pP, rlc_pP), @@ -1130,12 +1135,13 @@ rlc_um_receive_process_dar ( if (in_window < 0) { in_window = in_window + rlc_pP->rx_sn_modulo; } - + LOG_I(RLC, "[rlc_um_receive_process_dar] Before calling rlc_um_try_reassembly() 2 \n"); rlc_um_try_reassembly(ctxt_pP, rlc_pP, rlc_pP->vr_ur, in_window); } if (rlc_um_in_reordering_window(ctxt_pP, rlc_pP, rlc_pP->vr_ur) < 0) { + //LOG_I(RLC, "[rlc_um_receive_process_dar] Problematic case 4 \n"); #if TRACE_RLC_UM_DAR LOG_D(RLC, PROTOCOL_RLC_UM_CTXT_FMT" VR(UR) %d OUTSIDE REORDERING WINDOW SET TO VR(UH) – UM_Window_Size = %d\n", PROTOCOL_RLC_UM_CTXT_ARGS(ctxt_pP, rlc_pP), @@ -1154,13 +1160,18 @@ rlc_um_receive_process_dar ( // SDUs to upper layer in ascending order of the RLC SN if not // delivered before; if ((sn == rlc_pP->vr_ur) && rlc_um_get_pdu_from_dar_buffer(ctxt_pP, rlc_pP, rlc_pP->vr_ur)) { + LOG_I(RLC, "[rlc_um_receive_process_dar] Before calling rlc_um_try_reassembly() 3 \n"); //sn_tmp = rlc_pP->vr_ur; do { rlc_pP->vr_ur = (rlc_pP->vr_ur+1) % rlc_pP->rx_sn_modulo; } while (rlc_um_get_pdu_from_dar_buffer(ctxt_pP, rlc_pP, rlc_pP->vr_ur) && (rlc_pP->vr_ur != rlc_pP->vr_uh)); - + LOG_I(RLC, "[rlc_um_receive_process_dar] Before calling rlc_um_try_reassembly() 4 \n"); rlc_um_try_reassembly(ctxt_pP, rlc_pP, sn, rlc_pP->vr_ur); } + else if (sn != rlc_pP->vr_ur) + LOG_I(RLC, "[rlc_um_receive_process_dar] Problematic case 5, sn: %d, rlc_pP->vr_ur: %d \n",sn, rlc_pP->vr_ur); + else if(!rlc_um_get_pdu_from_dar_buffer(ctxt_pP, rlc_pP, rlc_pP->vr_ur)) + //LOG_I(RLC, "[rlc_um_receive_process_dar] Problematic case 6 \n"); // -if t-Reordering is running: // -if VR(UX) <= VR(UR); or