From afeb256604edef09495f22c6b34bbf4945166581 Mon Sep 17 00:00:00 2001
From: "Wilson W.K. Thong" <wilsonthong@astri.org>
Date: Wed, 21 Dec 2016 16:23:32 +0800
Subject: [PATCH] add more VCD logs to debug thread timing issue
see issue #166
---
openair1/SCHED/phy_procedures_lte_ue.c | 4 ++++
openair2/LAYER2/PDCP_v10.1.0/pdcp_fifo.c | 11 +++++++++++
openair2/UTIL/LOG/vcd_signal_dumper.c | 8 ++++++++
openair2/UTIL/LOG/vcd_signal_dumper.h | 8 ++++++++
targets/RT/USER/lte-ue.c | 6 ++++++
5 files changed, 37 insertions(+)
diff --git a/openair1/SCHED/phy_procedures_lte_ue.c b/openair1/SCHED/phy_procedures_lte_ue.c
index 1c6aa6b20cd..ebc9e3fa318 100644
--- a/openair1/SCHED/phy_procedures_lte_ue.c
+++ b/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) {
diff --git a/openair2/LAYER2/PDCP_v10.1.0/pdcp_fifo.c b/openair2/LAYER2/PDCP_v10.1.0/pdcp_fifo.c
index eb78a4ca7c4..ac64e7352ab 100644
--- a/openair2/LAYER2/PDCP_v10.1.0/pdcp_fifo.c
+++ b/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;
diff --git a/openair2/UTIL/LOG/vcd_signal_dumper.c b/openair2/UTIL/LOG/vcd_signal_dumper.c
index 76806f844fb..3f9128a6645 100644
--- a/openair2/UTIL/LOG/vcd_signal_dumper.c
+++ b/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",
diff --git a/openair2/UTIL/LOG/vcd_signal_dumper.h b/openair2/UTIL/LOG/vcd_signal_dumper.h
index 987da49d705..29358cb51bd 100644
--- a/openair2/UTIL/LOG/vcd_signal_dumper.h
+++ b/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,
diff --git a/targets/RT/USER/lte-ue.c b/targets/RT/USER/lte-ue.c
index 1b981454336..742c0d03d55 100644
--- a/targets/RT/USER/lte-ue.c
+++ b/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++;
--
GitLab