Skip to content

O
OpenXG UE
Commit 4427d92a authored by laurent's avatar laurent
Browse files
Options

better performance measurements

parent cab265a4
Show whitespace changes
Inline Side-by-side
Showing with 258 additions and 356 deletions
openair2/UTIL/LOG/log.h
View file @ 4427d92a
......@@ -53,26 +53,6 @@
extern "C" {
#endif
extern double cpuf;
static inline unsigned long long rdtsc(void) {
unsigned long long a, d;
__asm__ volatile ("rdtsc" : "=a" (a), "=d" (d));
return (d<<32) | a;
}
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;
}
#define check(a) checkT(a,__FILE__,__LINE__)
/** @defgroup _LOG LOG Generator
* @{*/
/* @}*/
......@@ -96,117 +76,20 @@ extern "C" {
* @ingroup _macro
* @brief LOG defines 9 levels of messages for users. Importance of these levels decrease gradually from 0 to 8
* @{*/
#ifndef LOG_EMERG
# define LOG_EMERG 0 /*!< \brief system is unusable */
#endif
#ifndef LOG_ALERT
# define LOG_ALERT 1 /*!< \brief action must be taken immediately */
#endif
#ifndef LOG_CRIT
# define LOG_CRIT 2 /*!< \brief critical conditions */
#endif
#ifndef LOG_ERR
# define LOG_ERR 3 /*!< \brief error conditions */
#endif
#ifndef LOG_WARNING
# define LOG_WARNING 4 /*!< \brief warning conditions */
#endif
#ifndef LOG_NOTICE
# define LOG_NOTICE 5 /*!< \brief normal but significant condition */
#endif
#ifndef LOG_INFO
# define LOG_INFO 6 /*!< \brief informational */
#endif
#ifndef LOG_DEBUG
# define LOG_DEBUG 7 /*!< \brief debug-level messages */
#endif
#ifndef LOG_FILE
# define LOG_FILE 8 /*!< \brief message sequence chart -level */
#endif
#ifndef LOG_TRACE
# define LOG_TRACE 9 /*!< \brief trace-level messages */
#endif
#define NUM_LOG_LEVEL 10 /*!< \brief the number of message levels users have with LOG */
/* @}*/
/** @defgroup _logIt logIt function
* @ingroup _macro
* @brief Macro used to call tr_log_full_ex with file, function and line information
* @{*/
#ifdef USER_MODE
//#define logIt(component, level, format, args...) do {logRecord(__FILE__, __FUNCTION__, __LINE__, component, level, format, ##args);} while(0);
#ifdef LOG_NO_THREAD
#define logIt(component, level, format, args...) logRecord_mt(__FILE__, __FUNCTION__, __LINE__, component, level, format, ##args)
#else //default
#define logIt(component, level, format, args...) logRecord(__FILE__, __FUNCTION__, __LINE__, component, level, format, ##args)
#endif
#else
#ifdef LOG_NO_THREAD
#define logIt(component, level, format, args...) logRecord_mt(NULL, __FUNCTION__, __LINE__, component, level, format, ##args)
#else // default
#define logIt(component, level, format, args...) logRecord(NULL, __FUNCTION__, __LINE__, component, level, format, ##args)
#endif
#endif
/* @}*/
/** @defgroup _debugging debugging macros
* @ingroup _macro
* @brief Macro used to call logIt function with different message levels
* @{*/
// debugging macros
#ifdef USER_MODE
# if T_TRACER
# include "T.h"
# define LOG_I(c, x...) T(T_LEGACY_ ## c ## _INFO, T_PRINTF(x))
# define LOG_W(c, x...) T(T_LEGACY_ ## c ## _WARNING, T_PRINTF(x))
# define LOG_E(c, x...) T(T_LEGACY_ ## c ## _ERROR, T_PRINTF(x))
# define LOG_D(c, x...) T(T_LEGACY_ ## c ## _DEBUG, T_PRINTF(x))
# define LOG_T(c, x...) T(T_LEGACY_ ## c ## _TRACE, T_PRINTF(x))
# define LOG_G(c, x...) /* */
# define LOG_A(c, x...) /* */
# define LOG_C(c, x...) /* */
# define LOG_N(c, x...) /* */
# define LOG_F(c, x...) /* */
# else /* T_TRACER */
# define LOG_G(c, x...) logIt(c, LOG_EMERG, x)
# define LOG_A(c, x...) logIt(c, LOG_ALERT, x)
# define LOG_C(c, x...) logIt(c, LOG_CRIT, x)
# define LOG_E(c, x...) logIt(c, LOG_ERR, x)
# define LOG_W(c, x...) logIt(c, LOG_WARNING, x)
# define LOG_N(c, x...) logIt(c, LOG_NOTICE, x)
# define LOG_I(c, x...) logIt(c, LOG_INFO, x)
# define LOG_D(c, x...) logIt(c, LOG_DEBUG, x)
# define LOG_F(c, x...) logIt(c, LOG_FILE, x) // log to a file, useful for the MSC chart generation
# define LOG_T(c, x...) logIt(c, LOG_TRACE, x)
# endif /* T_TRACER */
#else /* USER_MODE */
# define LOG_G(c, x...) printk(x)
# define LOG_A(c, x...) printk(x)
# define LOG_C(c, x...) printk(x)
# define LOG_E(c, x...) printk(x)
# define LOG_W(c, x...) printk(x)
# define LOG_N(c, x...) printk(x)
# define LOG_I(c, x...) printk(x)
# define LOG_D(c, x...) printk(x)
# define LOG_T(c, x...) printk(x)
#endif
/* @}*/
/** @defgroup _useful_functions useful functions in LOG
* @ingroup _macro
* @brief Macro of some useful functions defined by LOG
* @{*/
#define LOG_ENTER(c) do {LOG_T(c, "Entering\n");}while(0) /*!< \brief Macro to log a message with severity DEBUG when entering a function */
#define LOG_EXIT(c) do {LOG_T(c,"Exiting\n"); return;}while(0) /*!< \brief Macro to log a message with severity TRACE when exiting a function */
#define LOG_RETURN(c,x) do {uint32_t __rv;__rv=(unsigned int)(x);LOG_T(c,"Returning %08x\n", __rv);return((typeof(x))__rv);}while(0) /*!< \brief Macro to log a function exit, including integer value, then to return a value to the calling function */
/* @}*/
/** @defgroup _log_format Defined log format
* @ingroup _macro
* @brief Macro of log formats defined by LOG
......@@ -354,7 +237,6 @@ typedef struct LOG_params {
int len;
} LOG_params;
#if defined(ENABLE_ITTI)
typedef enum log_instance_type_e {
LOG_INSTANCE_UNKNOWN,
......@@ -364,11 +246,178 @@ typedef enum log_instance_type_e {
void log_set_instance_type (log_instance_type_t instance);
#endif
int logInit (void);
/*--- INCLUDES ---------------------------------------------------------------*/
# include "log_if.h"
/*----------------------------------------------------------------------------*/
int logInit (void);
void logRecord_mt(const char *file, const char *func, int line,int comp, int level, const char *format, ...);
void logRecord(const char *file, const char *func, int line,int comp, int level, const char *format, ...);
int set_comp_log(int component, int level, int verbosity, int interval);
int set_log(int component, int level, int interval);
void set_glog(int level, int verbosity);
void set_log_syslog(int enable);
void set_log_onlinelog(int enable);
void set_log_filelog(int enable);
void set_component_filelog(int comp);
int map_str_to_int(mapping *map, const char *str);
char *map_int_to_str(mapping *map, int val);
void logClean (void);
int is_newline( char *str, int size);
void *log_thread_function(void * list);
/** @defgroup _logIt logIt function
* @ingroup _macro
* @brief Macro used to call tr_log_full_ex with file, function and line information
* @{*/
#ifdef USER_MODE
//#define logIt(component, level, format, args...) do {logRecord(__FILE__, __FUNCTION__, __LINE__, component, level, format, ##args);} while(0);
#ifdef LOG_NO_THREAD
#define logIt(component, level, format, args...) logRecord_mt(__FILE__, __FUNCTION__, __LINE__, component, level, format, ##args)
#else //default
#define logIt(component, level, format, args...) logRecord(__FILE__, __FUNCTION__, __LINE__, component, level, format, ##args)
#endif
#else
#ifdef LOG_NO_THREAD
#define logIt(component, level, format, args...) logRecord_mt(NULL, __FUNCTION__, __LINE__, component, level, format, ##args)
#else // default
#define logIt(component, level, format, args...) logRecord(NULL, __FUNCTION__, __LINE__, component, level, format, ##args)
#endif
#endif
/* @}*/
/** @defgroup _debugging debugging macros
* @ingroup _macro
* @brief Macro used to call logIt function with different message levels
* @{*/
// debugging macros
#ifdef USER_MODE
# if T_TRACER
# include "T.h"
# define LOG_I(c, x...) T(T_LEGACY_ ## c ## _INFO, T_PRINTF(x))
# define LOG_W(c, x...) T(T_LEGACY_ ## c ## _WARNING, T_PRINTF(x))
# define LOG_E(c, x...) T(T_LEGACY_ ## c ## _ERROR, T_PRINTF(x))
# define LOG_D(c, x...) T(T_LEGACY_ ## c ## _DEBUG, T_PRINTF(x))
# define LOG_T(c, x...) T(T_LEGACY_ ## c ## _TRACE, T_PRINTF(x))
# define LOG_G(c, x...) /* */
# define LOG_A(c, x...) /* */
# define LOG_C(c, x...) /* */
# define LOG_N(c, x...) /* */
# define LOG_F(c, x...) /* */
# else /* T_TRACER */
# define LOG_G(c, x...) logIt(c, LOG_EMERG, x)
# define LOG_A(c, x...) logIt(c, LOG_ALERT, x)
# define LOG_C(c, x...) logIt(c, LOG_CRIT, x)
# define LOG_E(c, x...) logIt(c, LOG_ERR, x)
# define LOG_W(c, x...) logIt(c, LOG_WARNING, x)
# define LOG_N(c, x...) logIt(c, LOG_NOTICE, x)
# define LOG_I(c, x...) logIt(c, LOG_INFO, x)
# define LOG_D(c, x...) logIt(c, LOG_DEBUG, x)
# define LOG_F(c, x...) logIt(c, LOG_FILE, x) // log to a file, useful for the MSC chart generation
# define LOG_T(c, x...) logIt(c, LOG_TRACE, x)
# endif /* T_TRACER */
#else /* USER_MODE */
# define LOG_G(c, x...) printk(x)
# define LOG_A(c, x...) printk(x)
# define LOG_C(c, x...) printk(x)
# define LOG_E(c, x...) printk(x)
# define LOG_W(c, x...) printk(x)
# define LOG_N(c, x...) printk(x)
# define LOG_I(c, x...) printk(x)
# define LOG_D(c, x...) printk(x)
# define LOG_T(c, x...) printk(x)
#endif
/* @}*/
/** @defgroup _useful_functions useful functions in LOG
* @ingroup _macro
* @brief Macro of some useful functions defined by LOG
* @{*/
#define LOG_ENTER(c) do {LOG_T(c, "Entering\n");}while(0) /*!< \brief Macro to log a message with severity DEBUG when entering a function */
#define LOG_EXIT(c) do {LOG_T(c,"Exiting\n"); return;}while(0) /*!< \brief Macro to log a message with severity TRACE when exiting a function */
#define LOG_RETURN(c,x) do {uint32_t __rv;__rv=(unsigned int)(x);LOG_T(c,"Returning %08x\n", __rv);return((typeof(x))__rv);}while(0) /*!< \brief Macro to log a function exit, including integer value, then to return a value to the calling function */
/* @}*/
static inline unsigned long long rdtsc(void) {
unsigned long long a, d;
__asm__ volatile ("rdtsc" : "=a" (a), "=d" (d));
return (d<<32) | a;
}
#define DEBUG_REALTIME 1
#if DEBUG_REALTIME
extern double cpuf;
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 {
unsigned long long iterations;
unsigned long long sum;
unsigned long long 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=%llu, iterations=%llu, max=%llu/%llu/%llu/%llu/%llu/%llu/%llu/%llu/%llu/%llu\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]);
LOG_W(PHY,txt2);
}
}
static inline int cmpint(const void* a, const void* b) {
unsigned long long* aa=(unsigned long long*)a;
unsigned long long* bb=(unsigned long long*)b;
return (int)(*aa-*bb);
}
static inline void updateTimes(unsigned long long start, Meas *M, int period, char * txt) {
if (start!=0) {
unsigned long long end=rdtsc();
long long diff=(end-start)/(cpuf*1000);
M->maxArray[0]=diff;
M->sum+=diff;
M->iterations++;
qsort(M->maxArray, 11, sizeof(unsigned long long), cmpint);
printMeas(txt,M,period);
}
}
#define check(a) checkT(a,__FILE__,__LINE__)
#define initRefTimes(a) static __thread Meas a= {0}
#define pickTime(a) unsigned long long a=rdtsc()
#define readTime(a) a
#define initStaticTime(a) static __thread unsigned long long a={0}
#define pickStaticTime(a) a=rdtsc()
#else
#define check(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
......
openair2/UTIL/LOG/log_if.h
View file @ 4427d92a
......@@ -27,59 +27,8 @@
* \warning This component can be runned only in user-space
* @ingroup routing
*/
#ifndef __LOG_IF_H__
# define __LOG_IF_H__
/*--- INCLUDES ---------------------------------------------------------------*/
# include "log.h"
/*----------------------------------------------------------------------------*/
#ifdef __cplusplus
extern "C" {
#endif
# ifdef COMPONENT_LOG
# ifdef COMPONENT_LOG_IF
# define private_log_if(x) x
# define friend_log_if(x) x
# define public_log_if(x) x
# else
# define private_log_if(x)
# define friend_log_if(x) extern x
# define public_log_if(x) extern x
# endif
# else
# define private_log_if(x)
# define friend_log_if(x)
# define public_log_if(x) extern x
# endif
/** @defgroup _log_if Interfaces of LOG
* @{*/
//public_log_if( log_t *g_log;)
public_log_if( int logInit (void);)
public_log_if( void logRecord_mt(const char *file, const char *func, int line,int comp, int level, const char *format, ...);)
public_log_if( void logRecord(const char *file, const char *func, int line,int comp, int level, const char *format, ...);)
public_log_if( int set_comp_log(int component, int level, int verbosity, int interval);)
public_log_if( int set_log(int component, int level, int interval);)
public_log_if( void set_glog(int level, int verbosity);)
public_log_if( void set_log_syslog(int enable);)
public_log_if( void set_log_onlinelog(int enable);)
public_log_if( void set_log_filelog(int enable);)
public_log_if( void set_component_filelog(int comp);)
public_log_if( int map_str_to_int(mapping *map, const char *str);)
public_log_if( char *map_int_to_str(mapping *map, int val);)
public_log_if( void logClean (void); )
public_log_if( int is_newline( char *str, int size);)
public_log_if( void *log_thread_function(void * list);)
/* @}*/
#ifdef __cplusplus
}
#endif
#endif
// LTS: kept this file for compatibility
// this file was probably a trial to separate internal functions and external ones
// but it has never been finished, most source code include directly log.h (not log_if.h)
#include "log.h"
targets/RT/USER/lte-ue.c
View file @ 4427d92a
......@@ -75,101 +75,6 @@
#include "UTIL/LOG/vcd_signal_dumper.h"
#include "UTIL/OPT/opt.h"
#define DEBUG_REALTIME 1
#if DEBUG_REALTIME
typedef struct latency_stat {
uint64_t counter;
uint64_t stat1100;
uint64_t stat1200;
uint64_t stat1500;
uint64_t stat2000;
uint64_t stat3000;
} latency_stat_t;
static inline void saif_meas(int frame_rx) {
static latency_stat_t __thread latency_stat;
static struct timespec __thread last= {0};
struct timespec now;
clock_gettime(CLOCK_MONOTONIC_RAW, &now);
if ( last.tv_sec ) {
uint64_t diffTime = ((uint64_t)now.tv_sec *1000 *1000 *1000 + now.tv_nsec) -
((uint64_t)last.tv_sec *1000 *1000 *1000 + last.tv_nsec);
diffTime/=1000;
latency_stat.counter++;
if ( diffTime >= 1100 ) {
if (diffTime < 1200 )
latency_stat.stat1100++;
else if ( diffTime < 1500 )
latency_stat.stat1200++;
else if ( diffTime < 2000 )
latency_stat.stat1500++;
else if ( diffTime < 3000 )
latency_stat.stat2000++;
else
latency_stat.stat3000++;
}
if ( diffTime>=1100 || latency_stat.counter%20000==0 ) {
time_t current=time(NULL);
LOG_W(HW,
"%.2f delay=%llu Period stats %2.6f%% below 100µs\ncumul of events: 1100=%ld 1200=%ld 1500=%ld 2000=%ld >3000=%ld - (frame_rx=%d) - %s",
now.tv_sec+(double)now.tv_nsec/1e9,
diffTime,
(latency_stat.counter-latency_stat.stat1100-latency_stat.stat1200-
latency_stat.stat1500-latency_stat.stat2000-latency_stat.stat3000)/
(float)latency_stat.counter *100,
latency_stat.stat1100, latency_stat.stat1200,
latency_stat.stat1500, latency_stat.stat2000,
latency_stat.stat3000,
frame_rx, ctime(&current));
fflush(stdout);
}
}
last=now;
}
typedef struct m {
unsigned long long iterations;
unsigned long long sum;
unsigned long long maxArray[11];
} Meas;
void printMeas(char * txt, Meas *M, int period) {
if (M->iterations%period == 0 ) {
char txt2[512];
sprintf(txt2,"%s avg=%llu, iterations=%llu, max=%llu/%llu/%llu/%llu/%llu/%llu/%llu/%llu/%llu/%llu\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]);
LOG_W(PHY,txt2);
}
}
int cmpint(const void* a, const void* b) {
unsigned long long* aa=(unsigned long long*)a;
unsigned long long* bb=(unsigned long long*)b;
return (int)(*aa-*bb);
}
void updateTimes(unsigned long long start, Meas *M, int period, char * txt) {
unsigned long long end=rdtsc();
long long diff=(end-start)/(cpuf*1000);
M->maxArray[0]=diff;
M->sum+=diff;
M->iterations++;
qsort(M->maxArray, 11, sizeof(unsigned long long), cmpint);
printMeas(txt,M,period);
}
#else
#define check(a) do {} while (0)
#define saif_meas(a) do {} while (0)
#define update_max_times(a,b) do {} while (0)
#define print_meas(a,b) do {} while (0)
#endif
/* End of Changed by SYRTEM */
#define FRAME_PERIOD 100000000ULL
......@@ -742,9 +647,10 @@ static void *UE_thread_rxn_txnp4(void *arg) {
instance_cnt_rxtx=proc->subframe_rx;
AssertFatal(pthread_mutex_unlock(&proc->mutex_rxtx) ==0,"");
static __thread Meas t2= {0}, t3= {0};
unsigned long long current=rdtsc();
updateTimes(proc->gotIQs, &t2, 10000, "saif: Delay to wake up UE_Thread_Rx (case 2)");
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);
......@@ -812,7 +718,7 @@ static void *UE_thread_rxn_txnp4(void *arg) {
(UE->frame_parms.frame_type == TDD))
if (UE->mode != loop_through_memory)
phy_procedures_UE_S_TX(UE,0,0,no_relay);
updateTimes(current, &t3, 10000, "saif: Delay to process sub-frame (case 3)");
updateTimes(current, &t3, 10000, "Delay to process sub-frame (case 3)");
}
......@@ -1002,15 +908,15 @@ void *UE_thread(void *arg) {
if ( first_symbols <0 )
LOG_E(PHY,"can't compensate: diff =%d\n", first_symbols);
}
unsigned long long gotIQs=rdtsc();
pickTime(gotIQs);
// operate on thread sf mod 2
AssertFatal(pthread_mutex_lock(&proc->mutex_rxtx) ==0,"");
if(sub_frame == 0) {
UE->proc.proc_rxtx[0].frame_rx++;
UE->proc.proc_rxtx[1].frame_rx++;
}
UE->proc.proc_rxtx[0].gotIQs=gotIQs;
UE->proc.proc_rxtx[1].gotIQs=gotIQs;
UE->proc.proc_rxtx[0].gotIQs=readTime(gotIQs);
UE->proc.proc_rxtx[1].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);
......@@ -1020,12 +926,10 @@ void *UE_thread(void *arg) {
AssertFatal (pthread_cond_signal(&proc->cond_rxtx) ==0 ,"");
AssertFatal(pthread_mutex_unlock(&proc->mutex_rxtx) ==0,"");
static __thread Meas t1= {0};
static unsigned long long lastTime=0;
if ( lastTime != 0 )
updateTimes(lastTime, &t1, 20000, "saif: Delay between two IQ acquisitions (case 1)");
lastTime=rdtsc();
saif_meas(proc->frame_rx);
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);
......
Markdown is supported
0% or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment