add more VCD logs to debug thread timing issue

see issue #166

openair1/SCHED/phy_procedures_lte_ue.c

@@ -1588,6 +1588,7 @@ void ue_pucch_procedures(PHY_VARS_UE *ue,UE_rxtx_proc_t *proc,uint8_t eNB_id,uin
   if(ue->ulsch[eNB_id]->harq_processes[harq_pid]->subframe_scheduling_flag)
   {
       LOG_D(PHY,"PUSCH is programmed on this subframe [pid %d] AbsSuframe %d.%d ==> Skip PUCCH transmission \n",harq_pid,frame_tx,subframe_tx);
+      VCD_SIGNAL_DUMPER_DUMP_FUNCTION_BY_NAME(VCD_SIGNAL_DUMPER_FUNCTIONS_PHY_PROCEDURES_UE_TX_PUCCH,VCD_FUNCTION_OUT);
       return;
   }
 
@@ -1869,6 +1870,9 @@ void ue_pucch_procedures(PHY_VARS_UE *ue,UE_rxtx_proc_t *proc,uint8_t eNB_id,uin
       ue->generate_ul_signal[eNB_id] = 1;
     }
   }
+
+  VCD_SIGNAL_DUMPER_DUMP_FUNCTION_BY_NAME(VCD_SIGNAL_DUMPER_FUNCTIONS_PHY_PROCEDURES_UE_TX_PUCCH,VCD_FUNCTION_OUT);
+
 }
 
 void phy_procedures_UE_TX(PHY_VARS_UE *ue,UE_rxtx_proc_t *proc,uint8_t eNB_id,uint8_t abstraction_flag,runmode_t mode,relaying_type_t r_type) {

openair2/LAYER2/PDCP_v10.1.0/pdcp_fifo.c

@@ -59,6 +59,7 @@ extern int otg_enabled;
 #include "UTIL/LOG/log.h"
 #include "UTIL/OTG/otg_tx.h"
 #include "UTIL/FIFO/pad_list.h"
+#include "UTIL/LOG/vcd_signal_dumper.h"
 #include "platform_constants.h"
 #include "msc.h"
 
@@ -107,6 +108,7 @@ int pdcp_fifo_flush_sdus(const protocol_ctxt_t* const  ctxt_pP)
   int ret = 0;
 #endif
 
+  VCD_SIGNAL_DUMPER_DUMP_FUNCTION_BY_NAME( VCD_SIGNAL_DUMPER_FUNCTIONS_PDCP_FIFO_FLUSH, 1 );
   while (sdu_p && cont) {
 
 #if ! defined(OAI_EMU)
@@ -184,7 +186,11 @@ int pdcp_fifo_flush_sdus(const protocol_ctxt_t* const  ctxt_pP)
 #ifdef LINUX
           memcpy(NLMSG_DATA(nas_nlh_tx)+sizeof(pdcp_data_ind_header_t), &(sdu_p->data[sizeof (pdcp_data_ind_header_t)]), pdcp_output_sdu_bytes_to_write);
           nas_nlh_tx->nlmsg_len += pdcp_output_sdu_bytes_to_write;
+          VCD_SIGNAL_DUMPER_DUMP_VARIABLE_BY_NAME( VCD_SIGNAL_DUMPER_VARIABLES_UE_PDCP_FLUSH_SIZE, pdcp_output_sdu_bytes_to_write);
+          VCD_SIGNAL_DUMPER_DUMP_FUNCTION_BY_NAME( VCD_SIGNAL_DUMPER_FUNCTIONS_PDCP_FIFO_FLUSH_BUFFER, 1 );
           ret = sendmsg(nas_sock_fd,&nas_msg_tx,0);
+          VCD_SIGNAL_DUMPER_DUMP_FUNCTION_BY_NAME( VCD_SIGNAL_DUMPER_FUNCTIONS_PDCP_FIFO_FLUSH_BUFFER, 0 );
+          VCD_SIGNAL_DUMPER_DUMP_VARIABLE_BY_NAME( VCD_SIGNAL_DUMPER_VARIABLES_UE_PDCP_FLUSH_ERR, ret );
 
           if (ret<0) {
             LOG_E(PDCP, "[PDCP_FIFOS] sendmsg returns %d (errno: %d)\n", ret, errno);
@@ -275,6 +281,7 @@ int pdcp_fifo_flush_sdus(const protocol_ctxt_t* const  ctxt_pP)
       }
     }
   }
+  VCD_SIGNAL_DUMPER_DUMP_FUNCTION_BY_NAME( VCD_SIGNAL_DUMPER_FUNCTIONS_PDCP_FIFO_FLUSH, 0 );
 
 #ifdef PDCP_USE_RT_FIFO
 
@@ -429,7 +436,10 @@ int pdcp_fifo_read_input_sdus (const protocol_ctxt_t* const  ctxt_pP)
   int rlc_data_req_flag = 3;
  
   while ((len > 0) && (rlc_data_req_flag !=0))  {
+    VCD_SIGNAL_DUMPER_DUMP_FUNCTION_BY_NAME( VCD_SIGNAL_DUMPER_FUNCTIONS_PDCP_FIFO_READ, 1 );
+    VCD_SIGNAL_DUMPER_DUMP_FUNCTION_BY_NAME( VCD_SIGNAL_DUMPER_FUNCTIONS_PDCP_FIFO_READ_BUFFER, 1 );
     len = recvmsg(nas_sock_fd, &nas_msg_rx, 0);
+    VCD_SIGNAL_DUMPER_DUMP_FUNCTION_BY_NAME( VCD_SIGNAL_DUMPER_FUNCTIONS_PDCP_FIFO_READ_BUFFER, 0 );
 
     if (len<=0) {
       // nothing in pdcp NAS socket
@@ -707,6 +717,7 @@ int pdcp_fifo_read_input_sdus (const protocol_ctxt_t* const  ctxt_pP)
         }
       }
     }
+    VCD_SIGNAL_DUMPER_DUMP_FUNCTION_BY_NAME( VCD_SIGNAL_DUMPER_FUNCTIONS_PDCP_FIFO_READ, 0 );
   }
 
   return len;

openair2/UTIL/LOG/vcd_signal_dumper.c

@@ -174,8 +174,12 @@ const char* eurecomVariablesNames[] = {
   "ue0_SFN5",
   "ue0_SFN6",
   "ue0_SFN7",
+  "ue_pdcp_flush_size",
+  "ue_pdcp_flush_err",
   "ue0_trx_read_ns",
   "ue0_trx_write_ns",
+  "ue0_trx_read_ns_missing",
+  "ue0_trx_write_ns_missing"
 };
 
 const char* eurecomFunctionsNames[] = {
@@ -339,6 +343,10 @@ const char* eurecomFunctionsNames[] = {
   "pdcp_data_ind",
   "pdcp_apply_security",
   "pdcp_validate_security",
+  "pdcp_fifo_read",
+  "pdcp_fifo_read_buffer",
+  "pdcp_fifo_flush",
+  "pdcp_fifo_flush_buffer",
   /* RRC signals  */
   "rrc_rx_tx",
   "rrc_mac_config_req",

openair2/UTIL/LOG/vcd_signal_dumper.h

@@ -146,8 +146,12 @@ typedef enum {
   VCD_SIGNAL_DUMPER_VARIABLES_UE0_SFN5,
   VCD_SIGNAL_DUMPER_VARIABLES_UE0_SFN6,
   VCD_SIGNAL_DUMPER_VARIABLES_UE0_SFN7,
+  VCD_SIGNAL_DUMPER_VARIABLES_UE_PDCP_FLUSH_SIZE,
+  VCD_SIGNAL_DUMPER_VARIABLES_UE_PDCP_FLUSH_ERR,
   VCD_SIGNAL_DUMPER_VARIABLES_UE0_TRX_READ_NS,
   VCD_SIGNAL_DUMPER_VARIABLES_UE0_TRX_WRITE_NS,
+  VCD_SIGNAL_DUMPER_VARIABLES_UE0_TRX_READ_NS_MISSING,
+  VCD_SIGNAL_DUMPER_VARIABLES_UE0_TRX_WRITE_NS_MISSING,
   VCD_SIGNAL_DUMPER_VARIABLES_LAST,
   VCD_SIGNAL_DUMPER_VARIABLES_END = VCD_SIGNAL_DUMPER_VARIABLES_LAST,
 } vcd_signal_dump_variables;
@@ -312,6 +316,10 @@ typedef enum {
   VCD_SIGNAL_DUMPER_FUNCTIONS_PDCP_DATA_IND,
   VCD_SIGNAL_DUMPER_FUNCTIONS_PDCP_APPLY_SECURITY,
   VCD_SIGNAL_DUMPER_FUNCTIONS_PDCP_VALIDATE_SECURITY,
+  VCD_SIGNAL_DUMPER_FUNCTIONS_PDCP_FIFO_READ,
+  VCD_SIGNAL_DUMPER_FUNCTIONS_PDCP_FIFO_READ_BUFFER,
+  VCD_SIGNAL_DUMPER_FUNCTIONS_PDCP_FIFO_FLUSH,
+  VCD_SIGNAL_DUMPER_FUNCTIONS_PDCP_FIFO_FLUSH_BUFFER,
 
   /* RRC signals  */
   VCD_SIGNAL_DUMPER_FUNCTIONS_RRC_RX_TX,

targets/RT/USER/lte-ue.c

@@ -1079,6 +1079,7 @@ void *UE_thread(void *arg) {
 					       UE->frame_parms.nb_antennas_rx);
 	      VCD_SIGNAL_DUMPER_DUMP_FUNCTION_BY_NAME( VCD_SIGNAL_DUMPER_FUNCTIONS_TRX_READ, 0 );
 	      VCD_SIGNAL_DUMPER_DUMP_VARIABLE_BY_NAME( VCD_SIGNAL_DUMPER_VARIABLES_UE0_TRX_READ_NS, rxs );
+	      VCD_SIGNAL_DUMPER_DUMP_VARIABLE_BY_NAME( VCD_SIGNAL_DUMPER_VARIABLES_UE0_TRX_READ_NS_MISSING, UE->frame_parms.samples_per_tti - rxs);
 	      if (rxs != UE->frame_parms.samples_per_tti) {
 	        LOG_E(PHY, "problem in rx 5! expect #samples=%d but got only %d!\n", UE->frame_parms.samples_per_tti, rxs);
 	        exit_fun("problem in rx 5!");
@@ -1101,10 +1102,12 @@ void *UE_thread(void *arg) {
 						1);
 	      VCD_SIGNAL_DUMPER_DUMP_FUNCTION_BY_NAME( VCD_SIGNAL_DUMPER_FUNCTIONS_TRX_WRITE, 0 );
 	      VCD_SIGNAL_DUMPER_DUMP_VARIABLE_BY_NAME( VCD_SIGNAL_DUMPER_VARIABLES_UE0_TRX_WRITE_NS, txs );
+	      VCD_SIGNAL_DUMPER_DUMP_VARIABLE_BY_NAME( VCD_SIGNAL_DUMPER_VARIABLES_UE0_TRX_WRITE_NS_MISSING, UE->frame_parms.samples_per_tti - txs);
         if (txs !=  UE->frame_parms.samples_per_tti) {
            LOG_E(PHY,"TX : Timeout (sent %d/%d)\n",txs, UE->frame_parms.samples_per_tti);
            exit_fun( "problem transmitting samples" );
         }
+	      VCD_SIGNAL_DUMPER_DUMP_VARIABLE_BY_NAME( VCD_SIGNAL_DUMPER_VARIABLES_UE0_TRX_WRITE_NS_MISSING, UE->frame_parms.samples_per_tti - txs);
 	    }
 	    
 	    else {
@@ -1116,6 +1119,7 @@ void *UE_thread(void *arg) {
 					       UE->frame_parms.nb_antennas_rx);
 	      VCD_SIGNAL_DUMPER_DUMP_FUNCTION_BY_NAME( VCD_SIGNAL_DUMPER_FUNCTIONS_TRX_READ_SF9, 0 );
 	      VCD_SIGNAL_DUMPER_DUMP_VARIABLE_BY_NAME( VCD_SIGNAL_DUMPER_VARIABLES_UE0_TRX_READ_NS, rxs );
+	      VCD_SIGNAL_DUMPER_DUMP_VARIABLE_BY_NAME( VCD_SIGNAL_DUMPER_VARIABLES_UE0_TRX_READ_NS_MISSING, (UE->frame_parms.samples_per_tti-UE->frame_parms.ofdm_symbol_size-UE->frame_parms.nb_prefix_samples0) - rxs);
         if (rxs != (UE->frame_parms.samples_per_tti-UE->frame_parms.ofdm_symbol_size-UE->frame_parms.nb_prefix_samples0)) {
           LOG_E(PHY, "problem in rx 6! expect #samples=%d but got only %d!\n", UE->frame_parms.samples_per_tti-UE->frame_parms.ofdm_symbol_size-UE->frame_parms.nb_prefix_samples0, rxs);
           exit_fun("problem in rx 6!");
@@ -1138,6 +1142,7 @@ void *UE_thread(void *arg) {
 						1);
 	      VCD_SIGNAL_DUMPER_DUMP_FUNCTION_BY_NAME( VCD_SIGNAL_DUMPER_FUNCTIONS_TRX_WRITE_SF9, 0 );
 	      VCD_SIGNAL_DUMPER_DUMP_VARIABLE_BY_NAME( VCD_SIGNAL_DUMPER_VARIABLES_UE0_TRX_WRITE_NS, txs );
+	      VCD_SIGNAL_DUMPER_DUMP_VARIABLE_BY_NAME( VCD_SIGNAL_DUMPER_VARIABLES_UE0_TRX_WRITE_NS_MISSING, (UE->frame_parms.samples_per_tti - rx_off_diff) - txs);
               if (txs !=  UE->frame_parms.samples_per_tti - rx_off_diff) {
                  LOG_E(PHY,"TX : Timeout (sent %d/%d)\n",txs, UE->frame_parms.samples_per_tti-rx_off_diff);
                  exit_fun( "problem transmitting samples" );
@@ -1172,6 +1177,7 @@ void *UE_thread(void *arg) {
 	  }
 	  // increment instance count and change proc subframe/frame variables
 	  int instance_cnt_rxtx = ++proc->instance_cnt_rxtx;
+	  VCD_SIGNAL_DUMPER_DUMP_VARIABLE_BY_NAME(VCD_SIGNAL_DUMPER_VARIABLES_UE_INST_CNT_RX, proc->instance_cnt_rxtx);
 	  if(sf == 0)
 	  {
 	     UE->proc.proc_rxtx[0].frame_rx++;