Gets late packets during attach

nfapi/nfapi_pnf.c

@@ -242,7 +242,7 @@ extern void nfapi_log(char *file, char *func, int line, int comp, int level, con
 
 void pnf_nfapi_trace(nfapi_trace_level_t nfapi_level, const char* message, ...)
 {
-#if 0
+#if 1
 
   va_list    args;
   int oai_level;
@@ -1087,7 +1087,8 @@ int  pnf_phy_tx_req(nfapi_pnf_p7_config_t* pnf_p7, nfapi_tx_request_t* req)
   uint16_t sfn = NFAPI_SFNSF2SFN(req->sfn_sf);
   uint16_t sf = NFAPI_SFNSF2SF(req->sfn_sf);
 
-  LOG_D(PHY,"%s() SFN/SF:%d%d PDUs:%d\n", __FUNCTION__, sfn, sf, req->tx_request_body.number_of_pdus);
+  if (req->tx_request_body.number_of_pdus==0)
+    LOG_D(PHY,"%s() SFN/SF:%d%d PDUs:%d\n", __FUNCTION__, sfn, sf, req->tx_request_body.number_of_pdus);
 
   if (req->tx_request_body.tl.tag==NFAPI_TX_REQUEST_BODY_TAG)
   {
@@ -1150,7 +1151,7 @@ int pnf_phy_ul_config_req(nfapi_pnf_p7_config_t* pnf_p7, nfapi_ul_config_request
 
   for (int i=0;i<req->ul_config_request_body.number_of_pdus;i++)
   {
-    LOG_D(PHY, "%s() sfn/sf:%d PDU[%d] size:%d\n", __FUNCTION__, NFAPI_SFNSF2DEC(req->sfn_sf), i, ul_config_pdu_list[i].pdu_size);
+    //LOG_D(PHY, "%s() sfn/sf:%d PDU[%d] size:%d\n", __FUNCTION__, NFAPI_SFNSF2DEC(req->sfn_sf), i, ul_config_pdu_list[i].pdu_size);
 
     if (
         ul_config_pdu_list[i].pdu_type == NFAPI_UL_CONFIG_ULSCH_PDU_TYPE ||
@@ -1162,7 +1163,7 @@ int pnf_phy_ul_config_req(nfapi_pnf_p7_config_t* pnf_p7, nfapi_ul_config_request
         ul_config_pdu_list[i].pdu_type == NFAPI_UL_CONFIG_UCI_SR_HARQ_PDU_TYPE
        )
     {
-      LOG_D(PHY, "%s() handle_nfapi_ul_pdu() for PDU:%d\n", __FUNCTION__, i);
+      //LOG_D(PHY, "%s() handle_nfapi_ul_pdu() for PDU:%d\n", __FUNCTION__, i);
 
       handle_nfapi_ul_pdu(eNB,proc,&ul_config_pdu_list[i],curr_sfn,curr_sf,req->ul_config_request_body.srs_present);
     }

nfapi/nfapi_vnf.c

@@ -671,7 +671,7 @@ int phy_harq_indication(struct nfapi_vnf_p7_config* config, nfapi_harq_indicatio
 {
   struct PHY_VARS_eNB_s *eNB = RC.eNB[0][0];
 
-  LOG_E(MAC, "%s() NFAPI SFN/SF:%d number_of_harqs:%u\n", __FUNCTION__, NFAPI_SFNSF2DEC(ind->sfn_sf), ind->harq_indication_body.number_of_harqs);
+  LOG_D(MAC, "%s() NFAPI SFN/SF:%d number_of_harqs:%u\n", __FUNCTION__, NFAPI_SFNSF2DEC(ind->sfn_sf), ind->harq_indication_body.number_of_harqs);
 
   pthread_mutex_lock(&eNB->UL_INFO_mutex);
 
@@ -796,14 +796,14 @@ int phy_sr_indication(struct nfapi_vnf_p7_config* config, nfapi_sr_indication_t*
   *dest_ind = *ind;
   dest_ind->sr_indication_body.sr_pdu_list = dest_pdu_list;
 
-  LOG_D(MAC,"%s() eNB->UL_INFO.sr_ind.sr_indication_body.number_of_srs:%d\n", eNB->UL_INFO.sr_ind.sr_indication_body.number_of_srs);
+  LOG_D(MAC,"%s() eNB->UL_INFO.sr_ind.sr_indication_body.number_of_srs:%d\n", __FUNCTION__, eNB->UL_INFO.sr_ind.sr_indication_body.number_of_srs);
 
   for (int i=0;i<eNB->UL_INFO.sr_ind.sr_indication_body.number_of_srs;i++)
   {
     nfapi_sr_indication_pdu_t *dest_pdu = &dest_ind->sr_indication_body.sr_pdu_list[i];
     nfapi_sr_indication_pdu_t *src_pdu = &ind->sr_indication_body.sr_pdu_list[i];
 
-    LOG_D(MAC, "SR_IND[PDU:%d][rnti:%x cqi:%d channel:%d]\n", i, dest_pdu->rx_ue_information.rnti, dest_pdu->ul_cqi_information.ul_cqi, dest_pdu->ul_cqi_information.channel);
+    LOG_D(MAC, "SR_IND[PDU:%d][rnti:%x cqi:%d channel:%d]\n", i, src_pdu->rx_ue_information.rnti, src_pdu->ul_cqi_information.ul_cqi, src_pdu->ul_cqi_information.channel);
 
     memcpy(dest_pdu, src_pdu, sizeof(*src_pdu));
   }
@@ -863,12 +863,44 @@ void vnf_deallocate(void* ptr)
 	free(ptr);
 }
 
-void vnf_trace(nfapi_trace_level_t level, const char* message, ...)
+extern void nfapi_log(char *file, char *func, int line, int comp, int level, const char* format, va_list args);
+void vnf_trace(nfapi_trace_level_t nfapi_level, const char* message, ...)
 {
-	va_list args;
-	va_start(args, message);
-	vprintf(message, args);
-	va_end(args);
+#if 1
+
+  va_list    args;
+  int oai_level;
+
+  if (nfapi_level==NFAPI_TRACE_ERROR)
+  {
+    oai_level = LOG_ERR;
+  }
+  else if (nfapi_level==NFAPI_TRACE_WARN)
+  {
+    oai_level = LOG_WARNING;
+  }
+  else if (nfapi_level==NFAPI_TRACE_NOTE)
+  {
+    oai_level = LOG_INFO;
+  }
+  else if (nfapi_level==NFAPI_TRACE_INFO)
+  {
+    oai_level = LOG_INFO;
+  }
+  else
+  {
+    oai_level = LOG_INFO;
+  }
+
+  va_start(args, message);
+  nfapi_log("FILE>", "FUNC", 999, PHY, oai_level, message, args);
+  va_end(args);
+#else
+  va_list args;
+  va_start(args, message);
+  vprintf(message, args);
+  va_end(args);
+#endif
 }
 
 int phy_vendor_ext(struct nfapi_vnf_p7_config* config, nfapi_p7_message_header_t* msg)

openair1/PHY/LTE_ESTIMATION/lte_adjust_sync.c

@@ -227,11 +227,8 @@ int lte_est_timing_advance(LTE_DL_FRAME_PARMS *frame_parms,
 
 int lte_est_timing_advance_pusch(PHY_VARS_eNB* eNB,uint8_t UE_id)
 {
-  static int first_run=1;
-  static int max_pos_fil2=0;
   int temp, i, aa, max_pos=0, max_val=0;
-  short Re,Im,coef=24576;
-  short ncoef = 32768 - coef;
+  short Re,Im;
 
   LTE_DL_FRAME_PARMS *frame_parms = &eNB->frame_parms;
   LTE_eNB_PUSCH *eNB_pusch_vars = eNB->pusch_vars[UE_id];
@@ -260,16 +257,9 @@ int lte_est_timing_advance_pusch(PHY_VARS_eNB* eNB,uint8_t UE_id)
   if (max_pos>frame_parms->ofdm_symbol_size/2)
     max_pos = max_pos-frame_parms->ofdm_symbol_size;
 
-  // filter position to reduce jitter
-  if (first_run == 1) {
-    first_run=0;
-    max_pos_fil2 = max_pos;
-  } else
-    max_pos_fil2 = ((max_pos_fil2 * coef) + (max_pos * ncoef)) >> 15;
-
   //#ifdef DEBUG_PHY
-  LOG_D(PHY,"frame %d: max_pos = %d, max_pos_fil = %d, sync_pos=%d\n",eNB->proc.frame_rx,max_pos,max_pos_fil2,sync_pos);
+  LOG_D(PHY,"frame %d: max_pos = %d, sync_pos=%d\n",eNB->proc.frame_rx,max_pos,sync_pos);
   //#endif //DEBUG_PHY
 
-  return(max_pos_fil2-sync_pos);
+  return max_pos - sync_pos;
 }

openair1/PHY/LTE_TRANSPORT/dci_tools.c

@@ -923,6 +923,12 @@ void fill_dci_and_dlsch(PHY_VARS_eNB *eNB,eNB_rxtx_proc_t *proc,DCI_ALLOC_t *dci
   dlsch1_harq                               = dlsch1->harq_processes[rel8->harq_process];
   dlsch1_harq->codeword                     = 1;
   dlsch0->subframe_tx[subframe]             = 1;
+
+  LOG_D(PHY,"NFAPI: dlsch0[rnti:%x] dci_pdu[rnti:%x rnti_type:%d harq_process:%d ndi1:%d] dlsch0_harq[round:%d harq_mask:%x ndi:%d]\n", 
+      dlsch0->rnti, 
+      rel8->rnti, rel8->rnti_type, rel8->harq_process, rel8->new_data_indicator_1,
+      dlsch0_harq->round, dlsch0->harq_mask, dlsch0_harq->ndi);
+
   if (dlsch0->rnti != rel8->rnti) { // if rnti of dlsch is not the same as in the config, this is a new entry
     dlsch0_harq->round=0;
     dlsch0->harq_mask=0;
@@ -939,8 +945,9 @@ void fill_dci_and_dlsch(PHY_VARS_eNB *eNB,eNB_rxtx_proc_t *proc,DCI_ALLOC_t *dci
   dlsch0->active        = 1;
   if (rel8->rnti_type == 2)
       dlsch0_harq->round    = 0;
-LOG_D(PHY,"NFAPI: harq_pid %d harq_mask %x, round %d ndi (%d,%d) rnti type %d\n",rel8->harq_process,dlsch0->harq_mask,dlsch0_harq->round,
-	dlsch0_harq->ndi,rel8->new_data_indicator_1, rel8->rnti_type);
+
+  LOG_D(PHY,"NFAPI: harq_pid %d harq_mask %x, round %d ndi (%d,%d) rnti type %d\n",rel8->harq_process,dlsch0->harq_mask,dlsch0_harq->round,
+      dlsch0_harq->ndi,rel8->new_data_indicator_1, rel8->rnti_type);
 
   switch (rel8->dci_format) {
 
@@ -2500,9 +2507,11 @@ void fill_ulsch(PHY_VARS_eNB *eNB,nfapi_ul_config_ulsch_pdu *ulsch_pdu,int frame
   else if(ulsch->harq_processes[harq_pid]->n_DMRS == 7)
     ulsch->harq_processes[harq_pid]->n_DMRS2 = 9;
   
-  LOG_D(PHY,"[eNB %d][PUSCH %d] Programming PUSCH with n_DMRS2 %d (cshift %d) for Frame %d, Subframe %d\n",
-	eNB->Mod_id,harq_pid,ulsch->harq_processes[harq_pid]->n_DMRS2,ulsch->harq_processes[harq_pid]->n_DMRS,
-	frame,subframe);
+  LOG_D(PHY,"[eNB %d][PUSCH %d] Frame %d, Subframe %d Programming PUSCH with n_DMRS2 %d (cshift %d) ulsch:ndi:%d ulsch_pdu:ndi:%d new_ulsch:%d status:%d\n",
+	eNB->Mod_id,harq_pid,frame,subframe,
+        ulsch->harq_processes[harq_pid]->n_DMRS2,
+        ulsch->harq_processes[harq_pid]->n_DMRS,
+	ulsch->harq_processes[harq_pid]->ndi, ulsch_pdu->ulsch_pdu_rel8.new_data_indication, new_ulsch, ulsch->harq_processes[harq_pid]->status);
   
   ulsch->harq_processes[harq_pid]->rvidx = ulsch_pdu->ulsch_pdu_rel8.redundancy_version;
   ulsch->harq_processes[harq_pid]->Qm    = ulsch_pdu->ulsch_pdu_rel8.modulation_type;

openair1/SCHED/fapi_l1.c

@@ -53,7 +53,7 @@ void handle_nfapi_dci_dl_pdu(PHY_VARS_eNB *eNB,
   LTE_eNB_PDCCH *pdcch_vars       = &eNB->pdcch_vars[idx];
   nfapi_dl_config_dci_dl_pdu *pdu = &dl_config_pdu->dci_dl_pdu;
 
-  LOG_D(PHY,"Frame %d, Subframe %d: DCI processing - populating pdcch_vars->dci_alloc[%d] subframe_tx:%d idx:%d pdcch_vars->num_dci:%d\n",proc->frame_tx,proc->subframe_tx, pdcch_vars->num_dci, proc->subframe_tx, idx, pdcch_vars->num_dci);
+  LOG_D(PHY,"Frame %d, Subframe %d: DCI processing - populating pdcch_vars->dci_alloc[%d] proc:subframe_tx:%d idx:%d pdcch_vars->num_dci:%d\n",proc->frame_tx,proc->subframe_tx, pdcch_vars->num_dci, proc->subframe_tx, idx, pdcch_vars->num_dci);
 
   // copy dci configuration into eNB structure
   fill_dci_and_dlsch(eNB,proc,&pdcch_vars->dci_alloc[pdcch_vars->num_dci],pdu);
@@ -180,9 +180,9 @@ void handle_nfapi_dlsch_pdu(PHY_VARS_eNB *eNB,eNB_rxtx_proc_t *proc,
   dlsch0_harq->pdsch_start = eNB->pdcch_vars[proc->subframe_tx & 1].num_pdcch_symbols;
 
   if (dlsch0_harq->round==0) {  //get pointer to SDU if this a new SDU
-    AssertFatal(sdu!=NULL,"NFAPI: frame %d, subframe %d: programming dlsch for round 0, rnti %x, UE_id %d, harq_pid %d : sdu is null for pdu_index %d\n",
+    AssertFatal(sdu!=NULL,"NFAPI: frame %d, subframe %d: programming dlsch for round 0, rnti %x, UE_id %d, harq_pid %d : sdu is null for pdu_index %d dlsch0_harq[round:%d SFN/SF:%d%d pdu:%p mcs:%d ndi:%d pdschstart:%d]\n",
                 proc->frame_tx,proc->subframe_tx,rel8->rnti,UE_id,harq_pid,
-                dl_config_pdu->dlsch_pdu.dlsch_pdu_rel8.pdu_index);
+                dl_config_pdu->dlsch_pdu.dlsch_pdu_rel8.pdu_index,dlsch0_harq->round,dlsch0_harq->frame,dlsch0_harq->subframe,dlsch0_harq->pdu,dlsch0_harq->mcs,dlsch0_harq->ndi,dlsch0_harq->pdsch_start);
     if (rel8->rnti != 0xFFFF) LOG_D(PHY,"NFAPI: frame %d, subframe %d: programming dlsch for round 0, rnti %x, UE_id %d, harq_pid %d\n",
                                     proc->frame_tx,proc->subframe_tx,rel8->rnti,UE_id,harq_pid);
     if (codeword_index == 0) dlsch0_harq->pdu                    = sdu;
@@ -687,7 +687,7 @@ void schedule_response(Sched_Rsp_t *Sched_INFO)
                   (dlsch_pdu_rel8->transport_blocks>0),
                   "dlsch_pdu_rel8->transport_blocks = %d not in [1,2]\n",
                   dlsch_pdu_rel8->transport_blocks);
-      if (sdu != NULL)
+      if (1)//sdu != NULL)
       {
         handle_nfapi_dlsch_pdu(eNB,proc,dl_config_pdu, dlsch_pdu_rel8->transport_blocks-1, sdu);
       }
@@ -741,6 +741,8 @@ void schedule_response(Sched_Rsp_t *Sched_INFO)
 
   if (nfapi_mode && number_hi_dci0_pdu!=0) {
     oai_nfapi_hi_dci0_req(HI_DCI0_req);
+    eNB->pdcch_vars[subframe&1].num_dci=0;
+    eNB->pdcch_vars[subframe&1].num_pdcch_symbols=0;
   }
 
   for (i=0;i<number_hi_dci0_pdu;i++) {
@@ -765,8 +767,10 @@ void schedule_response(Sched_Rsp_t *Sched_INFO)
     }
   }
 
-  if (nfapi_mode) {
-    for (int future_subframe=0;future_subframe<10;future_subframe++) { 
+  if (0){//nfapi_mode) {
+    int future_subframe=subframe;
+    //for (int future_subframe=0;future_subframe<10;future_subframe++) { 
+    {
       nfapi_ul_config_request_t *ul_req_tmp = &RC.mac[0]->UL_req_tmp[CC_id][future_subframe];
 
       // DJP - indexing directly into the mac - not good - ??????

openair1/SCHED/phy_procedures_lte_eNb.c

@@ -1319,6 +1319,7 @@ void pusch_procedures(PHY_VARS_eNB *eNB,eNB_rxtx_proc_t *proc)
   LTE_DL_FRAME_PARMS *fp=&eNB->frame_parms;
   LTE_eNB_ULSCH_t *ulsch;
   LTE_UL_eNB_HARQ_t *ulsch_harq;
+  struct timespec t_decode, t_crc,t_rx_ind,t_rx_ind_b,t_harq_a,t_harq_b,t_end;
 
   const int subframe = proc->subframe_rx;
   const int frame    = proc->frame_rx;
@@ -1383,6 +1384,8 @@ void pusch_procedures(PHY_VARS_eNB *eNB,eNB_rxtx_proc_t *proc)
 
         stop_meas(&eNB->ulsch_demodulation_stats);
 
+        clock_gettime(CLOCK_MONOTONIC,&t_decode);
+
         start_meas(&eNB->ulsch_decoding_stats);
 
         ret = ulsch_decoding(eNB,proc,
@@ -1393,7 +1396,7 @@ void pusch_procedures(PHY_VARS_eNB *eNB,eNB_rxtx_proc_t *proc)
 
         stop_meas(&eNB->ulsch_decoding_stats);
 
-        LOG_D(PHY,"[eNB %d][PUSCH %d] frame %d subframe %d RNTI %x RX power (%d,%d) N0 (%d,%d) dB ACK (%d,%d), decoding iter %d ulsch_harq->cqi_crc_status:%d ackBits:%d\n",
+        LOG_D(PHY,"[eNB %d][PUSCH %d] frame %d subframe %d RNTI %x RX power (%d,%d) N0 (%d,%d) dB ACK (%d,%d), decoding iter %d ulsch_harq->cqi_crc_status:%d ackBits:%d ulsch_decoding_stats[t:%lld max:%lld]\n",
             eNB->Mod_id,harq_pid,
             frame,subframe,
             ulsch->rnti,
@@ -1405,7 +1408,8 @@ void pusch_procedures(PHY_VARS_eNB *eNB,eNB_rxtx_proc_t *proc)
             ulsch_harq->o_ACK[1],
             ret,
             ulsch_harq->cqi_crc_status,
-            ulsch_harq->O_ACK);
+            ulsch_harq->O_ACK,
+            eNB->ulsch_decoding_stats.diff_now, eNB->ulsch_decoding_stats.max);
 
         //compute the expected ULSCH RX power (for the stats)
         ulsch_harq->delta_TF = get_hundred_times_delta_IF_eNB(eNB,i,harq_pid, 0); // 0 means bw_factor is not considered
@@ -1461,8 +1465,12 @@ void pusch_procedures(PHY_VARS_eNB *eNB,eNB_rxtx_proc_t *proc)
         ulsch_harq->handled = 1;
       }  // ulsch in error
       else {
+        clock_gettime(CLOCK_MONOTONIC,&t_crc);
+
 	fill_crc_indication(eNB,i,frame,subframe,0); // indicate ACK to MAC
+        clock_gettime(CLOCK_MONOTONIC,&t_rx_ind);
 	fill_rx_indication(eNB,i,frame,subframe);  // indicate SDU to MAC
+        clock_gettime(CLOCK_MONOTONIC,&t_rx_ind_b);
 
         ulsch_harq->status = SCH_IDLE;
         ulsch->harq_mask   &= ~(1 << harq_pid);
@@ -1493,7 +1501,9 @@ void pusch_procedures(PHY_VARS_eNB *eNB,eNB_rxtx_proc_t *proc)
 #endif
         }  // ulsch not in error
 
+      clock_gettime(CLOCK_MONOTONIC,&t_harq_a);
       if (ulsch_harq->O_ACK>0) fill_ulsch_harq_indication(eNB,ulsch_harq,ulsch->rnti,frame,subframe,ulsch->bundling);
+      clock_gettime(CLOCK_MONOTONIC,&t_harq_b);
 
       LOG_D(PHY,"[eNB %d] Frame %d subframe %d: received ULSCH harq_pid %d for UE %d, ret = %d, CQI CRC Status %d, ACK %d,%d, ulsch_errors %d/%d\n",
             eNB->Mod_id,frame,subframe,
@@ -1522,6 +1532,15 @@ void pusch_procedures(PHY_VARS_eNB *eNB,eNB_rxtx_proc_t *proc)
             ulsch->rnti, harq_pid, ulsch->harq_mask);
     }
   }   //   for (i=0; i<NUMBER_OF_UE_MAX; i++) {
+  clock_gettime(CLOCK_MONOTONIC,&t_end);
+  LOG_E(PHY,"%s() TIMING:decode:%ld.%09ld crc:%ld.%09ld rx_ind:%ld.%09ld-%ld.%09ld harq:%ld.%09ld-%ld.%09ld end:%ld.%09ld\n", __FUNCTION__, 
+      t_decode.tv_sec, t_decode.tv_nsec, 
+      t_crc.tv_sec, t_crc.tv_nsec, 
+      t_rx_ind.tv_sec, t_rx_ind.tv_nsec, 
+      t_rx_ind_b.tv_sec, t_rx_ind_b.tv_nsec, 
+      t_harq_a.tv_sec, t_harq_a.tv_nsec,
+      t_harq_b.tv_sec, t_harq_b.tv_nsec,
+      t_end.tv_sec, t_end.tv_nsec);
 }
 
 extern int oai_exit;
@@ -1585,7 +1604,7 @@ void fill_rx_indication(PHY_VARS_eNB *eNB,int UE_id,int frame,int subframe)
   pdu->data                              = eNB->ulsch[UE_id]->harq_processes[harq_pid]->b;  
   // estimate timing advance for MAC
   sync_pos                               = lte_est_timing_advance_pusch(eNB,UE_id);
-  timing_advance_update                  = sync_pos - eNB->frame_parms.nb_prefix_samples/4; //to check
+  timing_advance_update                  = sync_pos;
 
   //  if (timing_advance_update > 10) { dump_ulsch(eNB,frame,subframe,UE_id); exit(-1);}
   //  if (timing_advance_update < -10) { dump_ulsch(eNB,frame,subframe,UE_id); exit(-1);}
@@ -1742,7 +1761,7 @@ void fill_ulsch_harq_indication(PHY_VARS_eNB *eNB,LTE_UL_eNB_HARQ_t *ulsch_harq,
   int UE_id = find_dlsch(rnti,eNB,SEARCH_EXIST);
   AssertFatal(UE_id>=0,"UE_id doesn't exist\n");
 
-  LOG_I(PHY,"%s(eNB, ulsch_harq, rnti:%04x, frame:%d, subframe:%d, bundling:%d)\n", __FUNCTION__, rnti, frame, subframe, bundling);
+  LOG_I(PHY,"%s(eNB, ulsch_harq, rnti:%04x, frame:%d, subframe:%d, bundling:%d) harq_pdus:%d\n", __FUNCTION__, rnti, frame, subframe, bundling,eNB->UL_INFO.harq_ind.harq_indication_body.number_of_harqs);
 
   pthread_mutex_lock(&eNB->UL_INFO_mutex);
   nfapi_harq_indication_pdu_t *pdu =   &eNB->UL_INFO.harq_ind.harq_indication_body.harq_pdu_list[eNB->UL_INFO.harq_ind.harq_indication_body.number_of_harqs];

openair2/ENB_APP/enb_config.c

@@ -307,7 +307,7 @@ void RCconfig_L1(void) {
 
         configure_nfapi_pnf(RC.eNB[j][0]->eth_params_n.remote_addr, RC.eNB[j][0]->eth_params_n.remote_portc, RC.eNB[j][0]->eth_params_n.my_addr, RC.eNB[j][0]->eth_params_n.my_portd, RC.eNB[j][0]->eth_params_n     .remote_portd);
 
-        set_comp_log(PHY, LOG_DEBUG, LOG_FULL, 1);
+        set_comp_log(PHY, LOG_DEBUG, LOG_MED, 1);
         printf("DJP - forcing PHY to DEBUG - should see similar line if it works\n");
         LOG_E(PHY,"%s() DJP - forcing PHY to LOG_DEBUG for NFAPI PNF\n", __FUNCTION__);
       }
@@ -395,10 +395,12 @@ void RCconfig_macrlc() {
         configure_nfapi_vnf(RC.mac[j]->eth_params_s.my_addr, RC.mac[j]->eth_params_s.my_portc);
         printf("**************** RETURNED FROM configure_nfapi_vnf() vnf_port:%d\n", RC.mac[j]->eth_params_s.my_portc);
 
-        set_comp_log(MAC, LOG_DEBUG, LOG_FULL, 1);
-        set_comp_log(RRC, LOG_DEBUG, LOG_FULL, 1);
-        set_comp_log(PHY, LOG_DEBUG, LOG_FULL, 1);
-        printf("DJP - forcing MAC/RRC/PHY to DEBUG - should see similar line if it works\n");
+        set_comp_log(RLC, LOG_DEBUG, LOG_MED, 1);
+        set_comp_log(MAC, LOG_DEBUG, LOG_MED, 1);
+        set_comp_log(RRC, LOG_DEBUG, LOG_MED, 1);
+        set_comp_log(PHY, LOG_DEBUG, LOG_MED, 1);
+        printf("DJP - forcing RLC/MAC/RRC/PHY to DEBUG - should see similar line if it works\n");
+        LOG_D(RLC,"%s() DJP - forcing RLC to LOG_DEBUG for VNF\n", __FUNCTION__);
         LOG_D(MAC,"%s() DJP - forcing MAC to LOG_DEBUG for VNF\n", __FUNCTION__);
         LOG_D(RRC,"%s() DJP - forcing RRC to LOG_DEBUG for VNF\n", __FUNCTION__);
         LOG_I(PHY,"%s() DJP - forcing PHY to LOG_DEBUG for VNF\n", __FUNCTION__);

openair2/LAYER2/MAC/eNB_scheduler.c

@@ -455,31 +455,31 @@ void clear_nfapi_information(eNB_MAC_INST *eNB,int CC_idP,frame_t frameP,sub_fra
 void copy_ulreq(module_id_t module_idP,frame_t frameP, sub_frame_t subframeP)
 {
   int CC_id;
-  eNB_MAC_INST *eNB;
-  nfapi_ul_config_request_body_t *ul_req_body_tmp;
-  nfapi_ul_config_request_body_t *ul_req_body;
-
-  eNB = RC.mac[module_idP];
+  eNB_MAC_INST *eNB = RC.mac[module_idP];
 
   for (CC_id=0;CC_id<MAX_NUM_CCs;CC_id++) {
 
-    ul_req_body_tmp       = &eNB->UL_req_tmp[CC_id][subframeP].ul_config_request_body;
-    ul_req_body           = &eNB->UL_req[CC_id].ul_config_request_body;
+    nfapi_ul_config_request_t *ul_req_tmp = &eNB->UL_req_tmp[CC_id][subframeP];
+    nfapi_ul_config_request_t *ul_req     = &eNB->UL_req[CC_id];
+    nfapi_ul_config_request_pdu_t *ul_req_pdu = ul_req->ul_config_request_body.ul_config_pdu_list;
+
+    *ul_req = *ul_req_tmp;
 
-    eNB->UL_req[CC_id].sfn_sf   = (frameP<<4) + subframeP;
-    eNB->UL_req[CC_id].header   = eNB->UL_req_tmp[CC_id][subframeP].header;
-    ul_req_body->number_of_pdus                     = ul_req_body_tmp->number_of_pdus;
-    ul_req_body_tmp->number_of_pdus = 0;
+    // Restore the pointer
+    ul_req->ul_config_request_body.ul_config_pdu_list = ul_req_pdu;
 
-    if (ul_req_body->number_of_pdus>0)
+    ul_req->sfn_sf   = (frameP<<4) + subframeP;
+
+    ul_req_tmp->ul_config_request_body.number_of_pdus = 0;
+
+    if (ul_req->ul_config_request_body.number_of_pdus>0)
     {
-      LOG_E(PHY, "%s() Copying stored UL_req_tmp to UL_req for activation NOW (frameP:%d subframeP:%d) ul_req_body->number_of_pdus:%d\n", __FUNCTION__, frameP, subframeP, ul_req_body->number_of_pdus);
+      LOG_E(PHY, "%s() Copying stored UL_req_tmp to UL_req for activation NOW (frameP:%d subframeP:%d) ul_req_body->number_of_pdus:%d\n", __FUNCTION__, frameP, subframeP, ul_req->ul_config_request_body.number_of_pdus);
     }
 
-    memcpy((void*)ul_req_body->ul_config_pdu_list,
-	   (void*)ul_req_body_tmp->ul_config_pdu_list,
-	   ul_req_body->number_of_pdus*sizeof(nfapi_ul_config_request_pdu_t));
-
+    memcpy((void*)ul_req->ul_config_request_body.ul_config_pdu_list,
+	   (void*)ul_req_tmp->ul_config_request_body.ul_config_pdu_list,
+	   ul_req->ul_config_request_body.number_of_pdus*sizeof(nfapi_ul_config_request_pdu_t));
   }
 }
 
@@ -581,7 +581,7 @@ void eNB_dlsch_ulsch_scheduler(module_id_t module_idP, frame_t frameP, sub_frame
   // This schedules ULSCH in subframeP (dci0)
   schedule_ulsch(module_idP,frameP,subframeP);
   // This schedules UCI_SR in subframeP
-  schedule_SR(module_idP,frameP,subframeP);
+  //schedule_SR(module_idP,frameP,subframeP);
   // This schedules UCI_CSI in subframeP
   schedule_CSI(module_idP, frameP, subframeP);
 

openair2/LAYER2/MAC/eNB_scheduler_RA.c

@@ -469,11 +469,13 @@ void generate_Msg2(module_id_t module_idP,int CC_idP,frame_t frameP,sub_frame_t
     {
 
       if ((RA_template->Msg2_frame == frameP) && (RA_template->Msg2_subframe == subframeP)) {
-	LOG_D(MAC,"[eNB %d] CC_id %d Frame %d, subframeP %d: Generating RAR DCI, RA_active %d format 1A (%d,%d))\n",
+  struct timespec t;
+  clock_gettime(CLOCK_MONOTONIC, &t);
+	LOG_D(MAC,"[eNB %d] CC_id %d Frame %d, subframeP %d: Generating RAR DCI, RA_active %d format 1A (%d,%d)) t:%ld.%09ld\n",
 	      module_idP, CC_idP, frameP, subframeP,
 	      RA_template->RA_active,
 	      RA_template->RA_dci_fmt1,
-	      RA_template->RA_dci_size_bits1);
+	      RA_template->RA_dci_size_bits1, t.tv_sec,t.tv_nsec);
 
 	// Allocate 4 PRBS starting in RB 0
 	first_rb = 0;
@@ -986,7 +988,9 @@ void generate_Msg4(module_id_t module_idP,int CC_idP,frame_t frameP,sub_frame_t
 			     1,                           // ndi
 			     0,                           // rv
 			     0);                          // vrb_flag
-    LOG_D(MAC,"Frame %d, subframe %d: Msg4 SFN/SF:%d%d DCI pdu_num %d (rnti %x,rnti_type %d,harq_pid %d, resource_block_coding (%p) %d\n",
+  struct timespec t;
+  clock_gettime(CLOCK_MONOTONIC, &t);
+    LOG_D(MAC,"Frame %d, subframe %d: Msg4 SFN/SF:%d%d DCI pdu_num %d (rnti %x,rnti_type %d,harq_pid %d, resource_block_coding (%p) %d t:%ld.%09ld\n",
 		  frameP,
 	      subframeP,
               RA_template->Msg4_frame, RA_template->Msg4_subframe,
@@ -995,7 +999,7 @@ void generate_Msg4(module_id_t module_idP,int CC_idP,frame_t frameP,sub_frame_t
           dl_config_pdu->dci_dl_pdu.dci_dl_pdu_rel8.rnti_type,
           dl_config_pdu->dci_dl_pdu.dci_dl_pdu_rel8.harq_process,
           &dl_config_pdu->dci_dl_pdu.dci_dl_pdu_rel8.resource_block_coding,
-          dl_config_pdu->dci_dl_pdu.dci_dl_pdu_rel8.resource_block_coding);
+          dl_config_pdu->dci_dl_pdu.dci_dl_pdu_rel8.resource_block_coding,t.tv_sec,t.tv_nsec);
     AssertFatal(dl_config_pdu->dci_dl_pdu.dci_dl_pdu_rel8.resource_block_coding < 8192,
 				"resource_block_coding %u < 8192\n",
                 dl_config_pdu->dci_dl_pdu.dci_dl_pdu_rel8.resource_block_coding);	

openair2/LAYER2/MAC/eNB_scheduler_dlsch.c

@@ -648,8 +648,7 @@ schedule_ue_spec(
       DevCheck(((eNB_UE_stats->dl_cqi < MIN_CQI_VALUE) || (eNB_UE_stats->dl_cqi > MAX_CQI_VALUE)),
       eNB_UE_stats->dl_cqi, MIN_CQI_VALUE, MAX_CQI_VALUE);
       */
-      eNB_UE_stats->dlsch_mcs1 = cqi_to_mcs[ue_sched_ctl->dl_cqi[CC_id]];
-      eNB_UE_stats->dlsch_mcs1 = eNB_UE_stats->dlsch_mcs1;//cmin(eNB_UE_stats->dlsch_mcs1, openair_daq_vars.target_ue_dl_mcs);
+      eNB_UE_stats->dlsch_mcs1 = 10;//cqi_to_mcs[ue_sched_ctl->dl_cqi[CC_id]];
 
 
       // store stats
@@ -1252,8 +1251,10 @@ schedule_ue_spec(
 		  (UE_list->UE_template[CC_id][UE_id].DAI-1),
 		  mcs);
 	  } else {
-	    LOG_D(MAC,"[eNB %d] Initial transmission CC_id %d : harq_pid %d, mcs %d\n",
-		  module_idP,CC_id,harq_pid,mcs);
+  struct timespec t;
+  clock_gettime(CLOCK_MONOTONIC, &t);
+	    LOG_D(MAC,"[eNB %d] Initial transmission CC_id %d : harq_pid %d, mcs %d t:%ld.%09ld\n",
+		  module_idP,CC_id,harq_pid,mcs,t.tv_sec,t.tv_nsec);
 	    
 	  }
 	  LOG_D(MAC,"Checking feasibility pdu %d (new sdu)\n",dl_req->number_pdu);

openair2/LAYER2/MAC/eNB_scheduler_primitives.c

@@ -2127,9 +2127,10 @@ uint8_t UE_is_to_be_scheduled(module_id_t module_idP,int CC_id,uint8_t UE_id)
   if (UE_sched_ctl->ul_out_of_sync>0)
     return(0);
 
-  LOG_D(MAC,"[eNB %d][PUSCH] Checking UL requirements UE %d/%x\n",module_idP,UE_id,UE_RNTI(module_idP,UE_id));
+  LOG_D(MAC,"[eNB %d][PUSCH] Checking UL requirements UE %d/%x bsr_info:%d:%d:%d:%d ul_SR:%d ul_inactivity_timer:%d ul_scheduled:%d rrc_status:%d\n",module_idP,UE_id,UE_RNTI(module_idP,UE_id),UE_template->bsr_info[LCGID0], UE_template->bsr_info[LCGID1],UE_template->bsr_info[LCGID2],UE_template->bsr_info[LCGID3],UE_template->ul_SR, UE_sched_ctl->ul_inactivity_timer, UE_sched_ctl->ul_scheduled,mac_eNB_get_rrc_status(module_idP,UE_RNTI(module_idP,UE_id)));
 
-  if ((UE_template->bsr_info[LCGID0]>0) ||
+  if (1|| // DJP - no check in
+      (UE_template->bsr_info[LCGID0]>0) ||
       (UE_template->bsr_info[LCGID1]>0) ||
       (UE_template->bsr_info[LCGID2]>0) ||
       (UE_template->bsr_info[LCGID3]>0) ||
@@ -3134,7 +3135,6 @@ void extract_harq(module_id_t mod_idP,int CC_idP,int UE_id,frame_t frameP,sub_fr
           AssertFatal(sched_ctl->round[CC_idP][harq_pid]<8,"Got ACK/NAK for inactive harq_pid %d for UE %d/%x\n",harq_pid,UE_id,rnti);
           AssertFatal(pdu[0] == 1 || pdu[0] == 2 || pdu[0] == 4,
                       "Received ACK/NAK %d which is not 1 or 2 for harq_pid %d from UE %d/%x\n",pdu[0],harq_pid,UE_id,rnti);
-          LOG_D(MAC,"Received %d for harq_pid %d\n",pdu[0],harq_pid);
 
           if (pdu[0] == 1) { // ACK
             sched_ctl->round[CC_idP][harq_pid]=8; // release HARQ process
@@ -3142,10 +3142,13 @@ void extract_harq(module_id_t mod_idP,int CC_idP,int UE_id,frame_t frameP,sub_fr
           }
           else if (pdu[0] == 2 || pdu[0] == 4) // NAK (treat DTX as NAK)
             sched_ctl->round[CC_idP][harq_pid]++; // increment round
+
+          LOG_D(MAC,"Received PDU[0]:%d for harq_pid %d [round:%d tbcnt:%d]\n",pdu[0],harq_pid,sched_ctl->round[CC_idP][harq_pid],sched_ctl->tbcnt[CC_idP][harq_pid]);
         }
         else {
           // one or two ACK/NAK bits
           AssertFatal(num_ack_nak>2,"num_ack_nak %d > 2 for 1 CC and TM3/4/8/9/10\n",num_ack_nak);
+          LOG_D(MAC,"Received PDU[0]:%d:[1]:%d for harq_pid %d [round:%d tbcnt:%d]\n",pdu[0],pdu[1],harq_pid,sched_ctl->round[CC_idP][harq_pid],sched_ctl->tbcnt[CC_idP][harq_pid]);
           if ((num_ack_nak==2) && (sched_ctl->round[CC_idP][harq_pid]<8) && (sched_ctl->tbcnt[CC_idP][harq_pid]==1) && (pdu[0] == 1) && (pdu[1] == 1)) {
             sched_ctl->round[CC_idP][harq_pid]=8;
             sched_ctl->tbcnt[CC_idP][harq_pid]=0;
@@ -3162,6 +3165,7 @@ void extract_harq(module_id_t mod_idP,int CC_idP,int UE_id,frame_t frameP,sub_fr
           else AssertFatal(1==0,"Illegal ACK/NAK/round combination (%d,%d,%d,%d,%d) for harq_pid %d, UE %d/%x\n",
                            num_ack_nak,sched_ctl->round[CC_idP][harq_pid],sched_ctl->round[CC_idP][harq_pid],pdu[0],pdu[1], harq_pid,UE_id,
                            rnti);
+          LOG_D(MAC,"AFTER Received PDU[0]:%d:[1]:%d for harq_pid %d [round:%d tbcnt:%d]\n",pdu[0],pdu[1],harq_pid,sched_ctl->round[CC_idP][harq_pid],sched_ctl->tbcnt[CC_idP][harq_pid]);
         }
         break;
       case 1: // FDD Channel Selection (10.1.2.2.1), must be received for 2 serving cells
@@ -3653,9 +3657,11 @@ void SR_indication(module_id_t mod_idP, int cc_idP, frame_t frameP, sub_frame_t
   int UE_id = find_UE_id(mod_idP, rntiP);
   UE_list_t *UE_list = &RC.mac[mod_idP]->UE_list;
 
+  LOG_D(MAC,"[eNB %d][SR %x] Frame %d subframeP %d Signaling SR for UE %d on CC_id %d\n",mod_idP,rntiP,frameP,subframeP,UE_id,cc_idP);
+
   if (UE_id  != -1) {
-    if (mac_eNB_get_rrc_status(mod_idP,UE_RNTI(mod_idP,UE_id)) < RRC_CONNECTED)
-      LOG_D(MAC,"[eNB %d][SR %x] Frame %d subframeP %d Signaling SR for UE %d on CC_id %d\n",mod_idP,rntiP,frameP,subframeP, UE_id,cc_idP);
+    //if (mac_eNB_get_rrc_status(mod_idP,UE_RNTI(mod_idP,UE_id)) < RRC_CONNECTED)
+      //LOG_D(MAC,"[eNB %d][SR %x] Frame %d subframeP %d Signaling SR for UE %d on CC_id %d\n",mod_idP,rntiP,frameP,subframeP,UE_id,cc_idP);
 
 #if 0
     UE_sched_ctrl *sched_ctl = &UE_list->UE_sched_ctrl[UE_id];

openair2/LAYER2/MAC/eNB_scheduler_ulsch.c

@@ -121,9 +121,14 @@ void rx_sdu(const module_id_t enb_mod_idP,
        UE_list->UE_sched_ctrl[UE_id].ul_inactivity_timer   = 0;
        UE_list->UE_sched_ctrl[UE_id].ul_failure_timer      = 0;
        UE_list->UE_sched_ctrl[UE_id].ul_scheduled         &= (~(1<<harq_pid));
-       /* don't take into account TA if timer is running */
-       if (UE_list->UE_sched_ctrl[UE_id].ta_timer == 0)
-       UE_list->UE_sched_ctrl[UE_id].ta_update             = timing_advance;
+       /* Update with smoothing: 3/4 of old value and 1/4 of new.
+        * This is the logic that was done in the function
+        * lte_est_timing_advance_pusch, maybe it's not necessary?
+        * maybe it's even not correct at all?
+        */
+       UE_list->UE_sched_ctrl[UE_id].ta_update             =
+         (UE_list->UE_sched_ctrl[UE_id].ta_update * 3 + timing_advance)/4;
+
        UE_list->UE_sched_ctrl[UE_id].pusch_snr[CC_idP]       = ul_cqi;
        UE_list->UE_sched_ctrl[UE_id].ul_consecutive_errors = 0;
        first_rb =  UE_list->UE_template[CC_idP][UE_id].first_rb_ul[harq_pid];
@@ -482,7 +487,7 @@ abort();
 	else
 	  UE_list->UE_template[CC_idP][UE_id].ul_buffer_info[UE_list->UE_template[CC_idP][UE_id].lcgidmap[rx_lcids[i]]] = 0;
 
-          LOG_D(MAC,"[eNB %d] CC_id %d Frame %d : ULSCH -> UL-DCCH, received %d bytes form UE %d on LCID %d \n",
+          LOG_D(MAC,"[eNB %d] CC_id %d Frame %d : ULSCH -> UL-DCCH, received %d bytes from UE %d on LCID %d \n",
                 enb_mod_idP,CC_idP,frameP, rx_lengths[i], UE_id, rx_lcids[i]);
 
           mac_rlc_data_ind(
@@ -996,7 +1001,24 @@ abort();
 	  if (status < RRC_CONNECTED)
 	    cqi_req = 0;
 	  else if (UE_sched_ctrl->cqi_req_timer>30) {
-	    cqi_req = 1;
+            //
+            //
+            //
+            //
+            //
+            //
+            //
+            //
+	    cqi_req = 0;
+
+            //
+            //
+            //
+            //
+            //
+            //
+            //
+            //
 	    UE_sched_ctrl->cqi_req_timer=0;
 	  }
 	  else

openair2/RRC/LITE/rrc_eNB.c

@@ -4800,6 +4800,7 @@ rrc_eNB_decode_dcch(
       T(T_ENB_RRC_UL_INFORMATION_TRANSFER, T_INT(ctxt_pP->module_id), T_INT(ctxt_pP->frame),
         T_INT(ctxt_pP->subframe), T_INT(ctxt_pP->rnti));
 
+      LOG_D(RRC,"[MSG] RRC UL Information Transfer \n");
 #ifdef RRC_MSG_PRINT
       LOG_F(RRC,"[MSG] RRC UL Information Transfer \n");
 

openair2/UTIL/LOG/log.c

@@ -618,7 +618,7 @@ void logRecord_thread_safe(const char *file, const char *func,
                             func);
     }
 
-    total_len += snprintf(&log_buffer[total_len], MAX_LOG_TOTAL - total_len, "[%08lx] ", thread_id);
+    //total_len += snprintf(&log_buffer[total_len], MAX_LOG_TOTAL - total_len, "[%08lx] ", thread_id);
 
     if ((g_log->flag & FLAG_FILE_LINE) || (c->flag & FLAG_FILE_LINE) )  {
       total_len += snprintf(&log_buffer[total_len], MAX_LOG_TOTAL - total_len, "[%s:%d]",
@@ -1104,8 +1104,8 @@ void logRecord_mt(const char *file, const char *func, int line,
       if (len > MAX_LOG_TOTAL) len = MAX_LOG_TOTAL;
     }
 
-    len += snprintf(&log_buffer[len], MAX_LOG_TOTAL - len, "[%08lx]", thread_id);
-    if (len > MAX_LOG_TOTAL) len = MAX_LOG_TOTAL;
+    //len += snprintf(&log_buffer[len], MAX_LOG_TOTAL - len, "[%08lx]", thread_id);
+    //if (len > MAX_LOG_TOTAL) len = MAX_LOG_TOTAL;
 
     len += vsnprintf(&log_buffer[len], MAX_LOG_TOTAL - len, format, args);
     if (len > MAX_LOG_TOTAL) len = MAX_LOG_TOTAL;

targets/PROJECTS/GENERIC-LTE-EPC/CONF/oaiL1.nfapi.usrpb210.conf

@@ -6,7 +6,7 @@ log_config = {
   phy_log_level                         ="debug";
   phy_log_verbosity                     ="medium";
   mac_log_level                         ="info";
-  mac_log_verbosity                     ="high";
+  mac_log_verbosity                     ="medium";
   rlc_log_level                         ="info";
   rlc_log_verbosity                     ="medium";
   pdcp_log_level                        ="info";

targets/PROJECTS/GENERIC-LTE-EPC/CONF/rcc.band7.tm1.50PRB.nfapi.conf

@@ -166,19 +166,19 @@ eNBs =
 
 log_config = {
   global_log_level                      ="crit";
-  global_log_verbosity                  ="high";
+  global_log_verbosity                  ="medium";
   hw_log_level                          ="info";
   hw_log_verbosity                      ="medium";
   phy_log_level                         ="debug";
-  phy_log_verbosity                     ="high";
+  phy_log_verbosity                     ="medium";
   mac_log_level                         ="info";
-  mac_log_verbosity                     ="high";
+  mac_log_verbosity                     ="medium";
   rlc_log_level                         ="debug";
-  rlc_log_verbosity                     ="high";
+  rlc_log_verbosity                     ="medium";
   pdcp_log_level                        ="info";
   pdcp_log_verbosity                    ="medium";
   rrc_log_level                         ="debug";
-  rrc_log_verbosity                     ="high";
+  rrc_log_verbosity                     ="medium";
 };
 
 MACRLCs = (

targets/RT/USER/lte-enb.c

@@ -157,8 +157,16 @@ extern uint8_t nfapi_mode;
 extern void oai_subframe_ind(uint16_t sfn, uint16_t sf);
 extern void add_subframe(uint16_t *frameP, uint16_t *subframeP, int offset);
 
+#define TICK_TO_US(ts) (ts.diff/ts.trials/cpu_freq_GHz)
+
 static inline int rxtx(PHY_VARS_eNB *eNB,eNB_rxtx_proc_t *proc, char *thread_name) {
 
+  static double cpu_freq_GHz = 0.0;
+
+  if (cpu_freq_GHz == 0.0)
+    cpu_freq_GHz = get_cpu_freq_GHz();
+
+
   start_meas(&softmodem_stats_rxtx_sf);
 
   // *******************************************************************
@@ -175,7 +183,7 @@ static inline int rxtx(PHY_VARS_eNB *eNB,eNB_rxtx_proc_t *proc, char *thread_nam
     //LOG_D(PHY, "oai_subframe_ind(frame:%u, subframe:%d) - NOT CALLED ********\n", frame, subframe);
     oai_subframe_ind(frame, subframe);
 
-    LOG_D(PHY, "UL_info[rx_ind:%d:%d number_of_harqs:%d:%d number_of_crcs:%d:%d number_of_preambles:%d:%d number_of_cqis:%d] RX:%d%d TX:%d%d num_pdcch_symbols:%d\n", 
+    LOG_D(PHY, "UL_info[rx_ind:%d:%d harqs:%d:%d crcs:%d:%d preambles:%d:%d cqis:%d] RX:%d%d TX:%d%d num_pdcch_symbols:%d\n", 
       NFAPI_SFNSF2DEC(eNB->UL_INFO.rx_ind.sfn_sf),   eNB->UL_INFO.rx_ind.rx_indication_body.number_of_pdus, 
       NFAPI_SFNSF2DEC(eNB->UL_INFO.harq_ind.sfn_sf), eNB->UL_INFO.harq_ind.harq_indication_body.number_of_harqs, 
       NFAPI_SFNSF2DEC(eNB->UL_INFO.crc_ind.sfn_sf),  eNB->UL_INFO.crc_ind.crc_indication_body.number_of_crcs, 
@@ -237,9 +245,43 @@ static inline int rxtx(PHY_VARS_eNB *eNB,eNB_rxtx_proc_t *proc, char *thread_nam
 
   stop_meas( &softmodem_stats_rxtx_sf );
 
-  LOG_D(PHY,"%s() Exit proc[rx:%d%d tx:%d%d] time[in:%lld diff:%lld max:%lld]\n\n", __FUNCTION__, proc->frame_rx, proc->subframe_rx, proc->frame_tx, proc->subframe_tx, 
-      softmodem_stats_rxtx_sf.in, softmodem_stats_rxtx_sf.diff_now, softmodem_stats_rxtx_sf.max);
+  LOG_D(PHY,"%s() Exit proc[rx:%d%d tx:%d%d] rxtx:%lld phy:%15.3f tx:%15.3f rx:%15.3f prach:%15.3f ofdm:%15.3f dlsch[enc:%15.3f mod:%15.3f scr:%15.3f rm:%15.3f t:%15.3f i:%15.3f] rx_dft:%15.3f ",
+      __FUNCTION__, proc->frame_rx, proc->subframe_rx, proc->frame_tx, proc->subframe_tx, 
+      softmodem_stats_rxtx_sf.diff_now,
+      TICK_TO_US(eNB->phy_proc),
+      TICK_TO_US(eNB->phy_proc_tx),
+      TICK_TO_US(eNB->phy_proc_rx),
+      TICK_TO_US(eNB->rx_prach),
+      TICK_TO_US(eNB->ofdm_mod_stats),
+      TICK_TO_US(eNB->dlsch_encoding_stats),
+      TICK_TO_US(eNB->dlsch_modulation_stats),
+      TICK_TO_US(eNB->dlsch_scrambling_stats),
+      TICK_TO_US(eNB->dlsch_rate_matching_stats),
+      TICK_TO_US(eNB->dlsch_turbo_encoding_stats),
+      TICK_TO_US(eNB->dlsch_interleaving_stats),
+      TICK_TO_US(eNB->rx_dft_stats));
+
+  LOG_D(PHY," ulsch[ch:%15.3f freq:%15.3f dec:%15.3f demod:%15.3f ru:%15.3f td:%15.3f dei:%15.3f dem:%15.3f llr:%15.3f tci:%15.3f tca:%15.3f tcb:%15.3f tcg:%15.3f tce:%15.3f l1:%15.3f l2:%15.3f]\n\n", 
+      TICK_TO_US(eNB->ulsch_channel_estimation_stats),
+      TICK_TO_US(eNB->ulsch_freq_offset_estimation_stats),
+      TICK_TO_US(eNB->ulsch_decoding_stats),
+      TICK_TO_US(eNB->ulsch_demodulation_stats),
+      TICK_TO_US(eNB->ulsch_rate_unmatching_stats),
+      TICK_TO_US(eNB->ulsch_turbo_decoding_stats),
+      TICK_TO_US(eNB->ulsch_deinterleaving_stats),
+      TICK_TO_US(eNB->ulsch_demultiplexing_stats),
+      TICK_TO_US(eNB->ulsch_llr_stats),
+      TICK_TO_US(eNB->ulsch_tc_init_stats),
+      TICK_TO_US(eNB->ulsch_tc_alpha_stats),
+      TICK_TO_US(eNB->ulsch_tc_beta_stats),
+      TICK_TO_US(eNB->ulsch_tc_gamma_stats),
+      TICK_TO_US(eNB->ulsch_tc_ext_stats),
+      TICK_TO_US(eNB->ulsch_tc_intl1_stats),
+      TICK_TO_US(eNB->ulsch_tc_intl2_stats)
+      );
   
+      //softmodem_stats_rxtx_sf.in, softmodem_stats_rxtx_sf.diff_now, softmodem_stats_rxtx_sf.max,
+
   return(0);
 }
 

targets/RT/USER/lte-softmodem.c

@@ -1196,29 +1196,6 @@ int main( int argc, char **argv )
     } 
   }
   
-#if 0
-  // Will have parsed the config files by now
-  
-  printf("NFAPI MODE:%d\n", nfapi_mode);
-
-  if (nfapi_mode==1) // PNF
-  {
-    set_comp_log(PHY, LOG_DEBUG, LOG_FULL, 1);
-    printf("DJP - forcing PHY to DEBUG - should see similar line if it works\n");
-    LOG_E(PHY,"%s() DJP - forcing PHY to LOG_DEBUG for PNF\n", __FUNCTION__);
-  }
-  else if (nfapi_mode == 2)  // VNF
-  {
-    set_comp_log(MAC, LOG_DEBUG, LOG_FULL, 1);
-    set_comp_log(RRC, LOG_DEBUG, LOG_FULL, 1);
-    set_comp_log(PHY, LOG_DEBUG, LOG_FULL, 1);
-    printf("DJP - forcing MAC to DEBUG - should see similar line if it works\n");
-    LOG_E(PHY,"%s() DJP - forcing MAC to LOG_DEBUG for VNF\n", __FUNCTION__);
-  }
-#endif
-  
-  
-  printf("mlock\n");
   mlockall(MCL_CURRENT | MCL_FUTURE);
   
   pthread_cond_init(&sync_cond,NULL);
@@ -1353,10 +1330,6 @@ int main( int argc, char **argv )
 
     if (nfapi_mode==1) // PNF
     {
-      //set_comp_log(PHY, LOG_DEBUG, LOG_FULL, 1);
-      //printf("DJP - forcing PHY to DEBUG - should see similar line if it works\n");
-      //LOG_E(PHY,"%s() DJP - forcing PHY to LOG_DEBUG for PNF\n", __FUNCTION__);
-
       wait_nfapi_init("main?");
     }