From 9a8880fd39bd642f32110bce009087a15aa61f08 Mon Sep 17 00:00:00 2001 From: Andrew Burger Date: Fri, 10 Jul 2020 10:39:55 -0700 Subject: [PATCH] Added timestamps and logging --- common/utils/LOG/log.c | 35 +++++++++++++++++----------- openair2/PHY_INTERFACE/phy_stub_UE.c | 9 ++++--- targets/RT/USER/lte-enb.c | 2 +- targets/RT/USER/lte-ue.c | 21 +++++++---------- 4 files changed, 36 insertions(+), 31 deletions(-) diff --git a/common/utils/LOG/log.c b/common/utils/LOG/log.c index f6d57bd791..e1d75620fc 100644 --- a/common/utils/LOG/log.c +++ b/common/utils/LOG/log.c @@ -43,7 +43,7 @@ #include #include #include "common/config/config_userapi.h" - +#include // main log variables log_mem_cnt_t log_mem_d[2]; @@ -476,20 +476,29 @@ char *log_getthreadname(char *threadname, } static int log_header(char *log_buffer, - int buffsize, - int comp, - int level, - const char *format) + int buffsize, + int comp, + int level, + const char *format) { char threadname[PR_SET_NAME]; - return snprintf(log_buffer, buffsize, "%s%s[%s]%c %s %s%s", - log_level_highlight_end[level], - ( (g_log->flag & FLAG_NOCOLOR)?"":log_level_highlight_start[level]), - g_log->log_component[comp].name, - ( (g_log->flag & FLAG_LEVEL)?g_log->level2string[level]:' '), - ( (g_log->flag & FLAG_THREAD)?log_getthreadname(threadname,PR_SET_NAME+1):""), - format, - log_level_highlight_end[level]); + struct timeval tv; + gettimeofday(&tv, NULL); + struct tm tm; + localtime_r(&tv.tv_sec, &tm); + + return snprintf(log_buffer, buffsize, "%02d:%02d:%02d.%06ld %s%s[%s]%c %s %s%s", + tm.tm_hour, + tm.tm_min, + tm.tm_sec, + tv.tv_usec, + log_level_highlight_end[level], + ((g_log->flag & FLAG_NOCOLOR) ? "" : log_level_highlight_start[level]), + g_log->log_component[comp].name, + ((g_log->flag & FLAG_LEVEL) ? g_log->level2string[level] : ' '), + ((g_log->flag & FLAG_THREAD) ? log_getthreadname(threadname, PR_SET_NAME + 1) : ""), + format, + log_level_highlight_end[level]); } void logRecord_mt(const char *file, diff --git a/openair2/PHY_INTERFACE/phy_stub_UE.c b/openair2/PHY_INTERFACE/phy_stub_UE.c index 960104f0d3..aafc151077 100644 --- a/openair2/PHY_INTERFACE/phy_stub_UE.c +++ b/openair2/PHY_INTERFACE/phy_stub_UE.c @@ -74,8 +74,6 @@ void fill_rx_indication_UE_MAC(module_id_t Mod_id, nfapi_rx_indication_pdu_t *pdu; int timing_advance_update; - LOG_I(MAC, "Entered fill_rx_indication_UE_MAC\n"); - pthread_mutex_lock(&fill_ul_mutex.rx_mutex); UL_INFO->rx_ind.header.message_id = NFAPI_RX_ULSCH_INDICATION; @@ -1186,7 +1184,7 @@ void ue_init_standalone_socket(const char *addr, int tx_port, int rx_port) void *ue_standalone_pnf_task(void *context) { struct sockaddr_in server_address; - int addr_len = sizeof(server_address); + socklen_t addr_len = sizeof(server_address); char buffer[1024]; int sd = ue_rx_sock_descriptor; @@ -1313,7 +1311,7 @@ const char *hexdump(const void *data, size_t data_len, char *out, size_t out_len return out; } - void send_standalone_msg(UL_IND_t * UL, nfapi_message_id_e msg_type) + void send_standalone_msg(UL_IND_t *UL, nfapi_message_id_e msg_type) { int encoded_size = -1; char buffer[1024]; @@ -1321,7 +1319,8 @@ const char *hexdump(const void *data, size_t data_len, char *out, size_t out_len { case NFAPI_RACH_INDICATION: encoded_size = nfapi_p7_message_pack(&UL->rach_ind, buffer, sizeof(buffer), NULL); - LOG_E(MAC, "RACH_IND sent to Proxy, Size: %d\n", encoded_size); + LOG_E(MAC, "RACH_IND sent to Proxy, Size: %d Frame %d Subframe %d\n", encoded_size, + NFAPI_SFNSF2SFN(UL->rach_ind.sfn_sf), NFAPI_SFNSF2SF(UL->rach_ind.sfn_sf)); break; case NFAPI_CRC_INDICATION: encoded_size = nfapi_p7_message_pack(&UL->crc_ind, buffer, sizeof(buffer), NULL); diff --git a/targets/RT/USER/lte-enb.c b/targets/RT/USER/lte-enb.c index 147bc955ae..0d2457c6a8 100644 --- a/targets/RT/USER/lte-enb.c +++ b/targets/RT/USER/lte-enb.c @@ -261,7 +261,7 @@ static inline int rxtx(PHY_VARS_eNB *eNB, eNB->UL_INFO.subframe = proc->subframe_rx; eNB->UL_INFO.module_id = eNB->Mod_id; eNB->UL_INFO.CC_id = eNB->CC_id; - eNB->if_inst->UL_indication(&eNB->UL_INFO, proc); + eNB->if_inst->UL_indication(&eNB->UL_INFO, proc); // Andrew calling eNB maclayer check the UL_INFO structure AssertFatal((ret= pthread_mutex_unlock(&eNB->UL_INFO_mutex))==0,"error unlocking UL_INFO_mutex, return %d\n",ret); /* this conflict resolution may be totally wrong, to be tested */ /* CONFLICT RESOLUTION: BEGIN */ diff --git a/targets/RT/USER/lte-ue.c b/targets/RT/USER/lte-ue.c index d719b5d4e5..516823474b 100644 --- a/targets/RT/USER/lte-ue.c +++ b/targets/RT/USER/lte-ue.c @@ -1039,7 +1039,6 @@ static void *UE_phy_stub_standalone_pnf_task(void *arg) int num_lone = 0; int last_sfn_sf = -1; - uint64_t last_subframe_start = clock_usec(); while (!oai_exit) { bool sent_any = false; int sfn_sf = current_sfn_sf; @@ -1048,24 +1047,19 @@ static void *UE_phy_stub_standalone_pnf_task(void *arg) continue; } - uint64_t subframe_start = clock_usec(); - // LOG_I(MAC, "subframe elapsed %" PRIu64 "usec\n", - // subframe_start - last_subframe_start); - last_subframe_start = subframe_start; - last_sfn_sf = sfn_sf; // FDD and TDD tx timing settings. // XXX:It is the result of timing adjustment in debug. proc->subframe_tx = NFAPI_SFNSF2SF(sfn_sf); proc->frame_tx = NFAPI_SFNSF2SFN(sfn_sf); - + LOG_E(MAC, "received from proxy frame %d subframe %d\n", proc->frame_tx, + proc->subframe_tx); nfapi_dl_config_request_t *dl_config_req = get_queue(&dl_config_req_queue); nfapi_tx_request_pdu_t *tx_request_pdu_list = get_queue(&tx_req_pdu_queue); nfapi_ul_config_request_t *ul_config_req = get_queue(&ul_config_req_queue); nfapi_hi_dci0_request_t *hi_dci0_req = get_queue(&hi_dci0_req_queue); - if ((dl_config_req != NULL) != (tx_request_pdu_list != NULL)) { uint64_t start = clock_usec(); uint64_t deadline = start + 10000; @@ -1136,7 +1130,6 @@ static void *UE_phy_stub_standalone_pnf_task(void *arg) } } } - if (hi_dci0_req) { nfapi_hi_dci0_request_body_t *hi_dci0_body = &hi_dci0_req->hi_dci0_request_body; for (int i = 0; i < hi_dci0_body->number_of_dci + hi_dci0_body->number_of_hi; i++) { @@ -1149,15 +1142,19 @@ static void *UE_phy_stub_standalone_pnf_task(void *arg) } for (ue_index = 0; ue_index < ue_num; ue_index++) { + ue_Mod_id = ue_thread_id + NB_THREAD_INST * ue_index; + UE = PHY_vars_UE_g[ue_Mod_id][0]; #if UE_TIMING_TRACE start_meas(&UE->generic_stat); #endif - + int rx_frame = proc->subframe_tx < 4 ? (proc->frame_tx + 1023) % 1024 : proc->frame_tx; // subtracting 4 from subframe_tx + int rx_subframe = proc->subframe_tx < 4 ? proc->subframe_tx + 6 : proc->subframe_tx - 4; + LOG_E(MAC, "rx_frame %d rx_subframe %d\n", rx_frame, rx_subframe); if (UE->mac_enabled == 1) { ret = ue_scheduler(ue_Mod_id, - proc->subframe_tx < 4 ? (proc->frame_tx + 1023) % 1024 : proc->frame_tx, // subtracting 4 from subframe_tx - proc->subframe_tx < 4 ? proc->subframe_tx + 6 : proc->subframe_tx - 4, + rx_frame, + rx_subframe, proc->frame_tx, proc->subframe_tx, subframe_select(&UE->frame_parms, proc->subframe_tx),