maki/openairinterface5g
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

Remove timing functions from logging module

Browse Source
This commit is contained in:
Robert Schmidt
2022-02-25 17:22:01 +01:00
parent a0ac75a45b
commit b742717fb8
13 changed files with 67 additions and 164 deletions
Download Patch File Download Diff File Expand all files Collapse all files
common/utils/LOG/log.h
-124
View File
@@ -472,130 +472,6 @@ int32_t write_file_matlab(const char *fname, const char *vname, void *data, int
/* @}*/
static __inline__ uint64_t rdtsc(void) {
uint32_t a, d;
__asm__ volatile ("rdtsc" : "=a" (a), "=d" (d));
return (((uint64_t)d)<<32) | ((uint64_t)a);
}
#define DEBUG_REALTIME 1
#if DEBUG_REALTIME
extern double cpuf;
static inline uint64_t checkTCPU(int timeout,
char *file,
int line)
{
static uint64_t __thread lastCPUTime=0;
static uint64_t __thread last=0;
uint64_t cur=rdtsc();
struct timespec CPUt;
clock_gettime(CLOCK_THREAD_CPUTIME_ID, &CPUt);
uint64_t CPUTime=CPUt.tv_sec*1000*1000+CPUt.tv_nsec/1000;
double microCycles=(double)(cpuf*1000);
int duration=(int)((cur-last)/microCycles);
if ( last!=0 && duration > timeout ) {
//struct timespec ts;
//clock_gettime(CLOCK_MONOTONIC, &ts);
printf("%s:%d lte-ue delay %d (exceed %d), CPU for this period: %lld\n", file, line,
duration, timeout, (long long)CPUTime-lastCPUTime );
}
last=cur;
lastCPUTime=CPUTime;
return cur;
}
static inline unsigned long long checkT(int timeout,
char *file,
int line)
{
static unsigned long long __thread last=0;
unsigned long long cur=rdtsc();
int microCycles=(int)(cpuf*1000);
int duration=(int)((cur-last)/microCycles);
if ( last!=0 && duration > timeout )
printf("%s:%d lte-ue delay %d (exceed %d)\n", file, line,
duration, timeout);
last=cur;
return cur;
}
typedef struct m {
uint64_t iterations;
uint64_t sum;
uint64_t maxArray[11];
} Meas;
static inline void printMeas(char *txt,
Meas *M,
int period)
{
if (M->iterations%period == 0 ) {
char txt2[512];
sprintf(txt2,"%s avg=%" PRIu64 " iterations=%" PRIu64 " max=%"
PRIu64 ":%" PRIu64 ":%" PRIu64 ":%" PRIu64 ":%" PRIu64 ":%" PRIu64 ":%" PRIu64 ":%" PRIu64 ":%" PRIu64 ":%" PRIu64 "\n",
txt,
M->sum/M->iterations,
M->iterations,
M->maxArray[1],M->maxArray[2], M->maxArray[3],M->maxArray[4], M->maxArray[5],
M->maxArray[6],M->maxArray[7], M->maxArray[8],M->maxArray[9],M->maxArray[10]);
#if T_TRACER
LOG_W(PHY,"%s",txt2);
#else
printf("%s",txt2);
#endif
}
}
static inline int cmpint(const void *a,
const void *b)
{
uint64_t *aa=(uint64_t *)a;
uint64_t *bb=(uint64_t *)b;
return (int)(*aa-*bb);
}
static inline void updateTimes(uint64_t start,
Meas *M,
int period,
char *txt)
{
if (start!=0) {
uint64_t end=rdtsc();
long long diff=(end-start)/(cpuf*1000);
M->maxArray[0]=diff;
M->sum+=diff;
M->iterations++;
qsort(M->maxArray, 11, sizeof(uint64_t), cmpint);
printMeas(txt,M,period);
}
}
#define check(a) do { checkT(a,__FILE__,__LINE__); } while (0)
#define checkcpu(a) do { checkTCPU(a,__FILE__,__LINE__); } while (0)
#define initRefTimes(a) static __thread Meas a= {0}
#define pickTime(a) uint64_t a=rdtsc()
#define readTime(a) a
#define initStaticTime(a) static __thread uint64_t a={0}
#define pickStaticTime(a) do { a=rdtsc(); } while (0)
#else
#define check(a) do {} while (0)
#define checkcpu(a) do {} while (0)
#define initRefTimes(a) do {} while (0)
#define initStaticTime(a) do {} while (0)
#define pickTime(a) do {} while (0)
#define readTime(a) 0
#define pickStaticTime(a) do {} while (0)
#define updateTimes(a,b,c,d) do {} while (0)
#define printMeas(a,b,c) do {} while (0)
#endif
#ifdef __cplusplus
}
#endif
common/utils/threadPool/thread-pool.h
+7
View File
@@ -27,12 +27,19 @@
#include <stdbool.h>
#include <stdint.h>
#include <pthread.h>
#include <unistd.h>
#include <sys/syscall.h>
#include <assertions.h>
#include <LOG/log.h>
#include <common/utils/system.h>
//#include <stdatomic.h>
static __inline__ uint64_t rdtsc(void) {
uint32_t a, d;
__asm__ volatile ("rdtsc" : "=a" (a), "=d" (d));
return (((uint64_t)d)<<32) | ((uint64_t)a);
}
#ifdef DEBUG
#define THREADINIT PTHREAD_ERRORCHECK_MUTEX_INITIALIZER_NP
#else
executables/main-fs6.c
+57 -4
View File
@@ -55,6 +55,59 @@ int sum(uint8_t *b, int s) {
return sum;
}
extern double cpuf;
typedef struct m {
uint64_t iterations;
uint64_t sum;
uint64_t maxArray[11];
} Meas;
int cmpint(const void *a, const void *b)
{
uint64_t *aa=(uint64_t *)a;
uint64_t *bb=(uint64_t *)b;
return (int)(*aa-*bb);
}
static inline void printMeas(char *txt,
Meas *M,
int period)
{
if (M->iterations%period == 0 ) {
char txt2[512];
sprintf(txt2,"%s avg=%" PRIu64 " iterations=%" PRIu64 " max=%"
PRIu64 ":%" PRIu64 ":%" PRIu64 ":%" PRIu64 ":%" PRIu64 ":%" PRIu64 ":%" PRIu64 ":%" PRIu64 ":%" PRIu64 ":%" PRIu64 "\n",
txt,
M->sum/M->iterations,
M->iterations,
M->maxArray[1],M->maxArray[2], M->maxArray[3],M->maxArray[4], M->maxArray[5],
M->maxArray[6],M->maxArray[7], M->maxArray[8],M->maxArray[9],M->maxArray[10]);
#if T_TRACER
LOG_W(PHY,"%s",txt2);
#else
printf("%s",txt2);
#endif
}
}
void updateTimes(uint64_t start, Meas *M, int period, char *txt)
{
if (start!=0) {
uint64_t end=rdtsc_oai();
long long diff=(end-start)/(cpuf*1000);
M->maxArray[0]=diff;
M->sum+=diff;
M->iterations++;
qsort(M->maxArray, 11, sizeof(uint64_t), cmpint);
printMeas(txt,M,period);
}
}
#define initStaticTime(a) static __thread uint64_t a={0}
#define pickStaticTime(a) do { a=rdtsc_oai(); } while (0)
#define initRefTimes(a) static __thread Meas a= {0}
static inline int cmpintRev(const void *a, const void *b) {
uint64_t *aa=(uint64_t *)a;
uint64_t *bb=(uint64_t *)b;
@@ -82,7 +135,7 @@ static inline void printMeas2(char *txt, Meas *M, int period, bool MaxMin) {
static inline void updateTimesReset(uint64_t start, Meas *M, int period, bool MaxMin, char *txt) {
if (start!=0) {
uint64_t end=rdtsc();
uint64_t end=rdtsc_oai();
long long diff=(end-start)/(cpuf*1000);
M->maxArray[0]=diff;
M->sum+=diff;
@@ -107,7 +160,7 @@ static inline void updateTimesReset(uint64_t start, Meas *M, int period, bool Ma
static inline void measTransportTime(uint64_t DuSend, uint64_t CuMicroSec, Meas *M, int period, bool MaxMin, char *txt) {
if (DuSend!=0) {
uint64_t end=rdtsc();
uint64_t end=rdtsc_oai();
long long diff=(end-DuSend)/(cpuf*1000)-CuMicroSec;
M->maxArray[0]=diff;
M->sum+=diff;
@@ -1463,7 +1516,7 @@ void DL_cu_fs6(RU_t *ru, L1_rxtx_proc_t *proc, uint64_t DuClock, uint64_t start
}
hDL(bufferZone)->DuClock=DuClock;
hDL(bufferZone)->CuSpentMicroSec=(rdtsc()-startCycle)/(cpuf*1000);
hDL(bufferZone)->CuSpentMicroSec=(rdtsc_oai()-startCycle)/(cpuf*1000);
updateTimesReset(startCycle, &CUprocessing, 1000, true,"CU entire processing from recv to send");
sendSubFrame(&sockFS6, bufferZone, sizeof(fs6_dl_t), CTsentCUv0 );
return;
@@ -1476,7 +1529,7 @@ void UL_cu_fs6(RU_t *ru, L1_rxtx_proc_t *proc, uint64_t *TS, uint64_t *DuClock,
pickStaticTime(begingWait);
int nb_blocks=receiveSubFrame(&sockFS6, bufferZone, sizeof(bufferZone), CTsentDUv0 );
* DuClock=hUDP(bufferZone)->senderClock;
* startProcessing=rdtsc();
* startProcessing=rdtsc_oai();
updateTimesReset(begingWait, &fullLoop, 1000, false, "CU wait DU");
if (nb_blocks ==0) {
executables/nr-ue.c
+2 -2
View File
@@ -766,9 +766,9 @@ void processSlotRX(void *arg) {
#ifdef UE_SLOT_PARALLELISATION
phy_procedures_slot_parallelization_nrUE_RX( UE, proc, 0, 0, 1, no_relay, NULL );
#else
uint64_t a=rdtsc();
uint64_t a=rdtsc_oai();
phy_procedures_nrUE_RX(UE, proc, gNB_id, get_nrUE_params()->nr_dlsch_parallel, &rxtxD->txFifo);
LOG_D(PHY, "In %s: slot %d, time %lu\n", __FUNCTION__, proc->nr_slot_rx, (rdtsc()-a)/3500);
LOG_D(PHY, "In %s: slot %d, time %llu\n", __FUNCTION__, proc->nr_slot_rx, (rdtsc_oai()-a)/3500);
#endif
if(IS_SOFTMODEM_NOS1 || get_softmodem_params()->sa){
executables/transport_split.c
+1 -1
View File
@@ -156,7 +156,7 @@ int receiveSubFrame(UDPsock_t *sock, void *bufferZone, int bufferSize, uint16_t
int sendSubFrame(UDPsock_t *sock, void *bufferZone, ssize_t secondHeaderSize, uint16_t contentType) {
commonUDP_t *UDPheader=(commonUDP_t *)bufferZone ;
UDPheader->contentType=contentType;
UDPheader->senderClock=rdtsc();
UDPheader->senderClock=rdtsc_oai();
int nbBlocks=UDPheader->nbBlocks;
int blockId=0;
openair1/PHY/defs_L1_NB_IoT.h
-3
View File
@@ -452,9 +452,6 @@ typedef struct {
int sub_frame_start;
///
int sub_frame_step;
///
unsigned long long gotIQs;
} UE_rxtx_proc_NB_IoT_t;
/// Context data structure for eNB subframe processing
openair1/PHY/defs_UE.h
-1
View File
@@ -154,7 +154,6 @@ typedef struct {
int sub_frame_start;
int sub_frame_step;
unsigned long long gotIQs;
} UE_rxtx_proc_t;
/// Context data structure for eNB subframe processing
openair1/PHY/thread_NR_UE.h
-1
View File
@@ -62,7 +62,6 @@ typedef struct {
int sub_frame_start;
int sub_frame_step;
unsigned long long gotIQs;
uint8_t decoder_thread_available1;
int dci_err_cnt;
} UE_nr_rxtx_proc_t;
openair1/SIMULATION/LTE_PHY/dlsim.c
-1
View File
@@ -122,7 +122,6 @@ void do_OFDM_mod_l(int32_t **txdataF, int32_t **txdata, uint16_t next_slot, LTE_
slot_offset = (next_slot)*(frame_parms->samples_per_tti>>1);
for (aa=0; aa<frame_parms->nb_antennas_tx; aa++) {
// printf("Thread %d starting ... aa %d (%llu)\n",omp_get_thread_num(),aa,rdtsc());
if (frame_parms->Ncp == 1)
PHY_ofdm_mod(&txdataF[aa][slot_offset_F], // input
&txdata[aa][slot_offset], // output
openair1/SIMULATION/LTE_PHY/dlsim_tm4.c
-1
View File
@@ -112,7 +112,6 @@ void do_OFDM_mod_l(int32_t **txdataF, int32_t **txdata, uint16_t next_slot, LTE_
slot_offset = (next_slot)*(frame_parms->samples_per_tti>>1);
for (aa=0; aa<frame_parms->nb_antennas_tx; aa++) {
// printf("Thread %d starting ... aa %d (%llu)\n",omp_get_thread_num(),aa,rdtsc());
if (frame_parms->Ncp == 1)
PHY_ofdm_mod(&txdataF[aa][slot_offset_F], // input
openair1/SIMULATION/LTE_PHY/framegen.c
-1
View File
@@ -333,7 +333,6 @@ void do_OFDM_mod(mod_sym_t **txdataF, int32_t **txdata, uint16_t next_slot, LTE_
slot_offset = (next_slot)*(frame_parms->samples_per_tti>>1);
for (aa=0; aa<frame_parms->nb_antennas_tx; aa++) {
// printf("Thread %d starting ... aa %d (%llu)\n",omp_get_thread_num(),aa,rdtsc());
if (frame_parms->Ncp == 1)
PHY_ofdm_mod(&txdataF[aa][slot_offset_F], // input
openair1/SIMULATION/LTE_PHY/mbmssim.c
-1
View File
@@ -121,7 +121,6 @@ void do_OFDM_mod_l(int32_t **txdataF, int32_t **txdata, uint16_t next_slot, LTE_
slot_offset = (next_slot)*(frame_parms->samples_per_tti>>1);
for (aa=0; aa<frame_parms->nb_antennas_tx; aa++) {
// printf("Thread %d starting ... aa %d (%llu)\n",omp_get_thread_num(),aa,rdtsc());
if (frame_parms->Ncp == 1)
PHY_ofdm_mod(&txdataF[aa][slot_offset_F], // input
&txdata[aa][slot_offset], // output
targets/RT/USER/lte-ue.c
-24
View File
@@ -815,11 +815,6 @@ static void *UE_thread_rxn_txnp4(void *arg)
pthread_cond_wait( &proc->cond_rxtx, &proc->mutex_rxtx );
}
//printf("Processing sub frqme %d in %s\n", proc->subframe_rx, threadname);
initRefTimes(t2);
initRefTimes(t3);
pickTime(current);
updateTimes(proc->gotIQs, &t2, 10000, "Delay to wake up UE_Thread_Rx (case 2)");
// Process Rx data for one sub-frame
lte_subframe_t sf_type = subframe_select( &UE->frame_parms, proc->subframe_rx);
@@ -886,7 +881,6 @@ static void *UE_thread_rxn_txnp4(void *arg)
if (UE->mode != loop_through_memory)
phy_procedures_UE_S_TX(UE,0,0);
updateTimes(current, &t3, 10000, "Delay to process sub-frame (case 3)");
proc->instance_cnt_rxtx--;
if ( IS_SOFTMODEM_BASICSIM || IS_SOFTMODEM_RFSIM ) {
@@ -1470,12 +1464,6 @@ static void *UE_phy_stub_single_thread_rxn_txnp4(void *arg)
oai_subframe_ind(proc->frame_rx, proc->subframe_rx);
}
//Guessing that the next 4 lines are not needed for the phy_stub mode.
/*initRefTimes(t2);
initRefTimes(t3);
pickTime(current);
updateTimes(proc->gotIQs, &t2, 10000, "Delay to wake up UE_Thread_Rx (case 2)");*/
if (pthread_mutex_lock(&phy_stub_ticking->mutex_single_thread) != 0) {
LOG_E( MAC, "[SCHED][UE] error locking mutex for ue_thread_id %d (mutex_single_thread)\n",ue_thread_id);
exit_fun("nothing to add");
@@ -2225,8 +2213,6 @@ void *UE_thread(void *arg)
LOG_E(PHY,"can't compensate: diff =%d\n", first_symbols);
}
pickTime(gotIQs);
/* no timeout in IS_SOFTMODEM_BASICSIM or IS_SOFTMODEM_RFSIM mode */
if (IS_SOFTMODEM_BASICSIM || IS_SOFTMODEM_RFSIM) {
ret = pthread_mutex_lock(&proc->mutex_rxtx);
@@ -2264,12 +2250,6 @@ void *UE_thread(void *arg)
}
}
//UE->proc.proc_rxtx[0].gotIQs=readTime(gotIQs);
//UE->proc.proc_rxtx[1].gotIQs=readTime(gotIQs);
for (th_id=0; th_id < RX_NB_TH; th_id++) {
UE->proc.proc_rxtx[th_id].gotIQs=readTime(gotIQs);
}
proc->subframe_rx=sub_frame;
proc->subframe_tx=(sub_frame+4)%10;
proc->frame_tx = proc->frame_rx + (proc->subframe_rx>5?1:0);
@@ -2281,10 +2261,6 @@ void *UE_thread(void *arg)
T(T_UE_MASTER_TICK, T_INT(0), T_INT(proc->frame_rx%1024), T_INT(proc->subframe_rx));
AssertFatal (pthread_cond_signal(&proc->cond_rxtx) ==0,"");
AssertFatal(pthread_mutex_unlock(&proc->mutex_rxtx) ==0,"");
initRefTimes(t1);
initStaticTime(lastTime);
updateTimes(lastTime, &t1, 20000, "Delay between two IQ acquisitions (case 1)");
pickStaticTime(lastTime);
} else {
printf("Processing subframe %d",proc->subframe_rx);
getchar();