/* * Licensed to the OpenAirInterface (OAI) Software Alliance under one or more * contributor license agreements. See the NOTICE file distributed with * this work for additional information regarding copyright ownership. * The OpenAirInterface Software Alliance licenses this file to You under * the OAI Public License, Version 1.1 (the "License"); you may not use this file * except in compliance with the License. * You may obtain a copy of the License at * * http://www.openairinterface.org/?page_id=698 * * Unless required by applicable law or agreed to in writing, software * distributed under the License is distributed on an "AS IS" BASIS, * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. * See the License for the specific language governing permissions and * limitations under the License. *------------------------------------------------------------------------------- * For more information about the OpenAirInterface (OAI) Software Alliance: * contact@openairinterface.org */ /* ************************************************************************************************* USER GUIDE 1 - CONFIGURE TEST SESSION see TESTS PARAMETERS section below 2 - COMPILATION CMD LINE (same as openair compilation) - NO AVX SUPPORT /usr/bin/cc -msse4.1 -mssse3 -std=gnu99 -Wall -Wstrict-prototypes -fno-strict-aliasing -rdynamic -funroll-loops -Wno-packed-bitfield-compat -fPIC -DSTDC_HEADERS=1 -DHAVE_SYS_TYPES_H=1 -DHAVE_SYS_STAT_H=1 -DHAVE_STDLIB_H=1 -DHAVE_STRING_H=1 -DHAVE_MEMORY_H=1 -DHAVE_STRINGS_H=1 -DHAVE_INTTYPES_H=1 -DHAVE_STDINT_H=1 -DHAVE_UNISTD_H=1 -DHAVE_FCNTL_H=1 -DHAVE_ARPA_INET_H=1 -DHAVE_SYS_TIME_H=1 -DHAVE_SYS_SOCKET_H=1 -DHAVE_STRERROR=1 -DHAVE_SOCKET=1 -DHAVE_MEMSET=1 -DHAVE_GETTIMEOFDAY=1 -DHAVE_STDLIB_H=1 -DHAVE_MALLOC=1 -DHAVE_LIBSCTP -g -DMALLOC_CHECK_=3 -O2 -o lte-hwlat-test lte-hwlat2.c -lrt -lpthread -lm -ldl - AVX2 Support /usr/bin/cc -mavx2 -msse4.1 -mssse3 -std=gnu99 -Wall -Wstrict-prototypes -fno-strict-aliasing -rdynamic -funroll-loops -Wno-packed-bitfield-compat -fPIC -DSTDC_HEADERS=1 -DHAVE_SYS_TYPES_H=1 -DHAVE_SYS_STAT_H=1 -DHAVE_STDLIB_H=1 -DHAVE_STRING_H=1 -DHAVE_MEMORY_H=1 -DHAVE_STRINGS_H=1 -DHAVE_INTTYPES_H=1 -DHAVE_STDINT_H=1 -DHAVE_UNISTD_H=1 -DHAVE_FCNTL_H=1 -DHAVE_ARPA_INET_H=1 -DHAVE_SYS_TIME_H=1 -DHAVE_SYS_SOCKET_H=1 -DHAVE_STRERROR=1 -DHAVE_SOCKET=1 -DHAVE_MEMSET=1 -DHAVE_GETTIMEOFDAY=1 -DHAVE_STDLIB_H=1 -DHAVE_MALLOC=1 -DHAVE_LIBSCTP -g -DMALLOC_CHECK_=3 -O2 -o lte-hwlat-test lte-hwlat2.c -lrt -lpthread -lm -ldl 3 - RUN sudo cset shield --force --kthread on -c 1-3 // for 4 cores sudo cset shield --force --kthread on -c 1-7 // for 8 cores sudo cset shield ./lte-hwlat-test 4 - remove cset shield sudo cset shield --reset ***************************************************************************************************/ /* ************************************************************************************************* * TESTS PARAMETERS */ #define HWLAT_LOOP_CNT 1000000 /* measurment loop count for each thread*/ #define HWLAT_TTI_SLEEP_US 250 /* usleep duration -> IQ capture simulation (in µ seconds) */ #define RX_NB_TH 6 #define CALIB_RT_INTRUMENTATION 0 /* Laurent Thpmas instrumentation -> see openair2/UTIL/LOG/log.h for full implementation -> This is a copy and paste implementation in this file for a self contained source */ #define INSTRUMENTATION_LT_RDTSC 1 /* SYRTEM rdtsc instrumentation implementation (see below for more infaormation) */ #define INSTRUMENTATION_SYR_RDTSC 2 /* SYRTEM instrumentation using clock_gettime MONOTONIC */ #define INSTRUMENTATION_SYR_CLOCK_MONO 3 /* SYRTEM instrumentation using clock_gettime REALTIME */ #define INSTRUMENTATION_SYR_CLOCK_REALTIME 4 #define HWLAT_INSTRUMENTATION INSTRUMENTATION_LT_RDTSC /* Statistics histogram output */ #define HISTOGRAM_MIN_VALUE 0 #define HISTOGRAM_MAX_VALUE 2000 #define HISTOGRAM_STEP 1 #define HISTOGRAM_SIZE ( ( ( HISTOGRAM_MAX_VALUE - HISTOGRAM_MIN_VALUE ) / HISTOGRAM_STEP ) + 1 ) /* *************************************************************************************************/ /* * INCLUDES */ #define _GNU_SOURCE #include #include #include #include #include #include #include #include #include #include #include #include #include #include #include #include #include #include #include #include #include #include #include #include #include /* For SYS_xxx definitions */ #ifndef __STDC_FORMAT_MACROS #define __STDC_FORMAT_MACROS #endif #include /* From rt_wrapper.h ****************************************************************************************/ #define gettid() syscall(__NR_gettid) // for gettid /* From common/utils/itti/assertions.h ****************************************************************************************/ # define display_backtrace() #define _Assert_Exit_ \ { \ fprintf(stderr, "\nExiting execution\n"); \ display_backtrace(); \ fflush(stdout); \ fflush(stderr); \ exit(EXIT_FAILURE); \ } #define _Assert_(cOND, aCTION, fORMAT, aRGS...) \ do { \ if (!(cOND)) { \ fprintf(stderr, "\nAssertion ("#cOND") failed!\n" \ "In %s() %s:%d\n" fORMAT, \ __FUNCTION__, __FILE__, __LINE__, ##aRGS); \ aCTION; \ } \ } while(0) #define AssertFatal(cOND, fORMAT, aRGS...) _Assert_(cOND, _Assert_Exit_, fORMAT, ##aRGS) /* From "openair1/PHY/TOOLS/time_meas.h" ****************************************************************************************/ double cpu_freq_GHz; typedef struct { long long in; long long diff; long long diff_now; long long p_time; /*!< \brief absolute process duration */ long long diff_square; /*!< \brief process duration square */ long long max; int trials; int meas_flag; } time_stats_t; static inline unsigned long long rdtsc_oai(void) __attribute__((always_inline)); static inline unsigned long long rdtsc_oai(void) { unsigned long long a, d; __asm__ volatile ("rdtsc" : "=a" (a), "=d" (d)); return (d<<32) | a; } double get_cpu_freq_GHz(void); static inline void reset_meas(time_stats_t *ts) { ts->trials=0; ts->diff=0; ts->diff_now=0; ts->p_time=0; ts->diff_square=0; ts->max=0; ts->meas_flag=0; } double estimate_MHz_syr(void); static __inline__ uint64_t pickCyclesStart(void); static __inline__ uint64_t pickCyclesStop(void); /* From "openair2/UTIL/LOG/log.h" ****************************************************************************************/ extern double cpuf; extern double cpu_mhz_syr; static __inline__ uint64_t rdtsc(void) { uint64_t a, d; __asm__ volatile ("rdtsc" : "=a" (a), "=d" (d)); return (d<<32) | a; } 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]); // SYRTEM : just use printf do not include all LOG_X for this test //#if DISABLE_LOG_X printf("%s",txt2); //#else // LOG_W(PHY, "%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 uint64_t 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); // SYRTEM : Printed only a the end of the measurment loop return diff; } return 0; } static inline uint64_t updateTimes_syr(uint64_t start, Meas *M, int period, char * txt) { if (start!=0) { // uint64_t end=rdtsc(); uint64_t end=pickCyclesStop(); long long diff=(long long)((double)(end-start)/(cpu_mhz_syr)); // 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); // SYRTEM : Printed only a the end of the measurment loop return diff; } return 0; } #define initRefTimes(a) static __thread Meas a= {0} #define pickTime(a) uint64_t a=rdtsc() #define pickTime_syr(a) uint64_t a=pickCyclesStart() #define readTime(a) a /* * DEFINES */ #define TIMESPEC_TO_DOUBLE_US( t ) ( ( (double)t.tv_sec * 1000000 ) + ( (double)t.tv_nsec / 1000 ) ) typedef struct histo_time { double max; unsigned int count; } histo_time_t; static void measure_time ( struct timespec *start, struct timespec *stop, uint8_t START, uint16_t PRINT_INTERVAL ); static struct timespec get_timespec_diff( struct timespec *start, struct timespec *stop ); void histogram_save_in_csv( histo_time_t *histo , char *file_prefix); histo_time_t *histogram_init( histo_time_t *histo ); void histogram_store_value( histo_time_t *histo, double value ); #define FIFO_PRIORITY 40 #define true 1 #define false 0 /* * STRUCTURES */ /* stub of UE_rxtx_proc full structure in openair1/PHY/defs.h */ typedef struct UE_rxtx_proc { int instance_cnt_rxtx; pthread_t pthread_rxtx; pthread_cond_t cond_rxtx; pthread_mutex_t mutex_rxtx; int sub_frame_start; int sub_frame_step; unsigned long long gotIQs; unsigned long syr_rdtsc_rxtx_th_unlock_iteration; uint64_t syr_rdtsc_ue_th_got_iq; double syr_rdtsc_rxtx_th_unlock; double syr_rdtsc_rxtx_th_unlock_max; double syr_rdtsc_rxtx_th_unlock_mean; double syr_rdtsc_rxtx_th_unlock_min; histo_time_t *syr_rdtsc_rxtx_th_unlock_histogram; } UE_rxtx_proc_t; /* this structure is used to pass both UE phy vars and * proc to the function UE_thread_rxn_txnp4 */ struct rx_tx_thread_data { /* PHY_VARS_UE *UE; */ // UE phy vars not used for this test UE_rxtx_proc_t *proc; // We use a stub of rxtx_proc see definition above }; // ODD / EVEN Scheduling #if 0 typedef struct threads_s { int iq; int odd; int even; } threads_t; threads_t threads = { -1, -1, -1 }; // Core number for each thread (iq=3, even=2, odd=1) #endif // SLOT 0 / SLOT 1 parallelization typedef struct threads_s { int iq; int one; int two; int three; int four; int five; int six; int slot1_proc_one; int slot1_proc_two; int slot1_proc_three; } threads_t; threads_t threads= {7,6,5,4,3,2,1,-1,-1,-1}; /* * FUNCTIONS DEFINITION */ void *UE_thread(void *arg); void init_UE(int nb_inst); /* * GLOBALS VARIABLES */ volatile int oai_exit = 0; int th_count = 0; double cpuf; double cpu_mhz_syr; pthread_t pthread_ue; pthread_attr_t attr_ue; UE_rxtx_proc_t **rxtx_proc; struct timespec even_start, even_stop; struct timespec odd_start, odd_stop; histo_time_t *th_wake_histogram; /* * FUNCTIONS */ void exit_fun(const char* s) { if ( s != NULL ) { printf("%s %s() Exiting OAI softmodem: %s\n",__FILE__, __FUNCTION__, s); } oai_exit = 1; } void init_thread(int sched_runtime, int sched_deadline, int sched_fifo, cpu_set_t *cpuset, char * name) { #ifdef DEADLINE_SCHEDULER if (sched_runtime!=0) { struct sched_attr attr= {0}; attr.size = sizeof(attr); attr.sched_policy = SCHED_DEADLINE; attr.sched_runtime = sched_runtime; attr.sched_deadline = sched_deadline; attr.sched_period = 0; AssertFatal(sched_setattr(0, &attr, 0) == 0, "[SCHED] %s thread: sched_setattr failed %s \n", name, strerror(errno)); LOG_I(HW,"[SCHED][eNB] %s deadline thread %lu started on CPU %d\n", name, (unsigned long)gettid(), sched_getcpu()); } #else if (CPU_COUNT(cpuset) > 0) AssertFatal( 0 == pthread_setaffinity_np(pthread_self(), sizeof(cpu_set_t), cpuset), ""); struct sched_param sp; sp.sched_priority = sched_fifo; AssertFatal(pthread_setschedparam(pthread_self(),SCHED_FIFO,&sp)==0, "Can't set thread priority, Are you root?\n"); /* Check the actual affinity mask assigned to the thread */ cpu_set_t *cset=CPU_ALLOC(CPU_SETSIZE); if (0 == pthread_getaffinity_np(pthread_self(), CPU_ALLOC_SIZE(CPU_SETSIZE), cset)) { char txt[512]={0}; for (int j = 0; j < CPU_SETSIZE; j++) if (CPU_ISSET(j, cset)) sprintf(txt+strlen(txt), " %d ", j); printf("CPU Affinity of thread %s is %s\n", name, txt); } CPU_FREE(cset); #endif // Lock memory from swapping. This is a process wide call (not constraint to this thread). mlockall(MCL_CURRENT | MCL_FUTURE); pthread_setname_np( pthread_self(), name ); // SYRTEM : Synchronization thread is not simulated -> just ignore this part of code // // LTS: this sync stuff should be wrong // printf("waiting for sync (%s)\n",name); // pthread_mutex_lock(&sync_mutex); // printf("Locked sync_mutex, waiting (%s)\n",name); // while (sync_var<0) // pthread_cond_wait(&sync_cond, &sync_mutex); // pthread_mutex_unlock(&sync_mutex); printf("started %s as PID: %ld\n",name, gettid()); } void init_UE(int nb_inst) { int inst; for (inst=0; inst < nb_inst; inst++) { // UE->rfdevice.type = NONE_DEV; // SYRTEM : we use a stub of phy_var_ue // PHY_VARS_UE *UE = PHY_vars_UE_g[inst][0]; // AssertFatal(0 == pthread_create(&UE->proc.pthread_ue, &UE->proc.attr_ue, UE_thread, (void*)UE), ""); AssertFatal( 0 == pthread_create( &pthread_ue, &attr_ue, UE_thread, NULL ), "" ); } printf("UE threads created by %ld\n", gettid()); } // SYRTEM - UE synchronization thread is not used in this latency test program //static void *UE_thread_synch(void *arg) { // ... //} // SYRTEM - Stub of UE_thread_rxn_txnp4 // -> No DSP scheduled // -> Only thread initialization and thread wake up are kept static void *UE_thread_rxn_txnp4(void *arg){ static __thread int UE_thread_rxtx_retval; struct rx_tx_thread_data *rtd = arg; UE_rxtx_proc_t *proc = rtd->proc; proc->instance_cnt_rxtx=-1; char threadname[256]; sprintf(threadname,"UE_%d_proc_%d", 0, proc->sub_frame_start); cpu_set_t cpuset; CPU_ZERO(&cpuset); if ( (proc->sub_frame_start)%RX_NB_TH == 0 && threads.one != -1 ) CPU_SET(threads.one, &cpuset); if ( (proc->sub_frame_start)%RX_NB_TH == 1 && threads.two != -1 ) CPU_SET(threads.two, &cpuset); if ( (proc->sub_frame_start)%RX_NB_TH == 2 && threads.three != -1 ) CPU_SET(threads.three, &cpuset); if ( (proc->sub_frame_start)%RX_NB_TH == 3 && threads.four != -1 ) CPU_SET(threads.four, &cpuset); if ( (proc->sub_frame_start)%RX_NB_TH == 4 && threads.five != -1 ) CPU_SET(threads.five, &cpuset); if ( (proc->sub_frame_start)%RX_NB_TH == 5 && threads.six != -1 ) CPU_SET(threads.six, &cpuset); //CPU_SET(threads.three, &cpuset); init_thread(900000,1000000 , FIFO_PRIORITY-1, &cpuset, threadname); proc->syr_rdtsc_rxtx_th_unlock_iteration=0; proc->syr_rdtsc_rxtx_th_unlock_max=0; proc->syr_rdtsc_rxtx_th_unlock_mean=0; proc->syr_rdtsc_rxtx_th_unlock_min=1000; proc->syr_rdtsc_rxtx_th_unlock_histogram = NULL; proc->syr_rdtsc_rxtx_th_unlock_histogram = histogram_init (proc->syr_rdtsc_rxtx_th_unlock_histogram); while (!oai_exit) { if (pthread_mutex_lock(&proc->mutex_rxtx) != 0) { printf("[SCHED][UE] error locking mutex for UE RXTX\n" ); exit_fun("nothing to add"); } while (proc->instance_cnt_rxtx < 0) { // most of the time, the thread is waiting here pthread_cond_wait( &proc->cond_rxtx, &proc->mutex_rxtx ); } if (pthread_mutex_unlock(&proc->mutex_rxtx) != 0) { printf("[SCHED][UE] error unlocking mutex for UE RXn_TXnp4\n" ); exit_fun("nothing to add"); } proc->syr_rdtsc_rxtx_th_unlock = (double)(pickCyclesStop()-proc->syr_rdtsc_ue_th_got_iq )/cpu_mhz_syr; proc->syr_rdtsc_rxtx_th_unlock_iteration++; proc->syr_rdtsc_rxtx_th_unlock_mean += proc->syr_rdtsc_rxtx_th_unlock; if ( proc->syr_rdtsc_rxtx_th_unlock_max < proc->syr_rdtsc_rxtx_th_unlock ) proc->syr_rdtsc_rxtx_th_unlock_max = proc->syr_rdtsc_rxtx_th_unlock; if ( proc->syr_rdtsc_rxtx_th_unlock_min > proc->syr_rdtsc_rxtx_th_unlock ) proc->syr_rdtsc_rxtx_th_unlock_min = proc->syr_rdtsc_rxtx_th_unlock; histogram_store_value( proc->syr_rdtsc_rxtx_th_unlock_histogram, proc->syr_rdtsc_rxtx_th_unlock ); if (pthread_mutex_lock(&proc->mutex_rxtx) != 0) { printf("[SCHED][UE] error locking mutex for UE RXTX\n" ); exit_fun("noting to add"); } proc->instance_cnt_rxtx--; if (pthread_mutex_unlock(&proc->mutex_rxtx) != 0) { printf("[SCHED][UE] error unlocking mutex for UE RXTX\n" ); exit_fun("noting to add"); } } // thread finished free(arg); return &UE_thread_rxtx_retval; } void *UE_thread(void *arg) { int i = 0; int hw_loop_cnt = 0; int nb_threads = RX_NB_TH; char threadname[128]; cpu_set_t cpuset; struct rx_tx_thread_data *rtd; UE_rxtx_proc_t *proc; CPU_ZERO( &cpuset ); if ( threads.iq != -1 ) CPU_SET( threads.iq, &cpuset ); init_thread( 100000, 500000, FIFO_PRIORITY, &cpuset, "HDW Threads" ); sprintf( threadname, "Main UE %d", 0 ); pthread_setname_np( pthread_self(), threadname ); // init_UE_threads(UE) pthread_attr_init( &attr_ue ); pthread_attr_setstacksize( &attr_ue, 8192 );//5*PTHREAD_STACK_MIN); for ( i = 0; i < nb_threads; i++ ) { printf("\n"); rtd = calloc( 1, sizeof( struct rx_tx_thread_data ) ); if ( rtd == NULL ) abort(); rtd->proc = rxtx_proc[i]; // &UE->proc.proc_rxtx[i]; pthread_mutex_init( &rxtx_proc[i]->mutex_rxtx ,NULL ); // pthread_mutex_init( &UE->proc.proc_rxtx[i].mutex_rxtx,NULL ); pthread_cond_init( &rxtx_proc[i]->cond_rxtx, NULL ); // pthread_cond_init(&UE->proc.proc_rxtx[i].cond_rxtx,NULL); rtd->proc->sub_frame_start=i; rtd->proc->sub_frame_step=nb_threads; printf("Init_UE_threads rtd %d proc %d nb_threads %d i %d\n",rtd->proc->sub_frame_start, rxtx_proc[i]->sub_frame_start,nb_threads, i); pthread_create( &rxtx_proc[i]->pthread_rxtx, NULL, UE_thread_rxn_txnp4, rtd ); // pthread_create( &UE->proc.proc_rxtx[i].pthread_rxtx, NULL, UE_thread_rxn_txnp4, rtd); usleep(1000); } // init_UE_threads(UE) int sub_frame=-1; while ( !oai_exit ) { sub_frame++; sub_frame %= 10; proc = rxtx_proc[hw_loop_cnt%RX_NB_TH]; // Simulate IQ reception usleep( HWLAT_TTI_SLEEP_US ); proc->syr_rdtsc_ue_th_got_iq = pickCyclesStart(); AssertFatal(pthread_mutex_lock(&proc->mutex_rxtx) ==0,""); proc->instance_cnt_rxtx++; if ( proc->instance_cnt_rxtx == 0 ) { if ( pthread_cond_signal( &proc->cond_rxtx) != 0 ) { exit_fun( "nothing to add" ); } } else { if ( proc->instance_cnt_rxtx > 2 ) exit_fun( "instance_cnt_rxtx > 2" ); } AssertFatal( pthread_cond_signal( &proc->cond_rxtx ) == 0 ,"" ); AssertFatal(pthread_mutex_unlock(&proc->mutex_rxtx) ==0,""); /* Do not go indefinitely */ hw_loop_cnt++; if ( hw_loop_cnt%1000 == 0 ) { printf("\r%d/%d",hw_loop_cnt,HWLAT_LOOP_CNT*RX_NB_TH); fflush(stdout); } if (hw_loop_cnt >= HWLAT_LOOP_CNT*RX_NB_TH) { printf("\n\n"); for (i=0 ; ipthread_rxtx,threadname,128 ); printf("RxTX Thread unlock latency on thread %s (it. %lu) (us) : max=%8.3f - mean=%8.3f - min=%8.3f\n", threadname, proc->syr_rdtsc_rxtx_th_unlock_iteration, proc->syr_rdtsc_rxtx_th_unlock_max, proc->syr_rdtsc_rxtx_th_unlock_mean/proc->syr_rdtsc_rxtx_th_unlock_iteration, proc->syr_rdtsc_rxtx_th_unlock_min); histogram_save_in_csv(proc->syr_rdtsc_rxtx_th_unlock_histogram, threadname ); } printf("\n\n"); oai_exit = 1; } } // while !oai_exit oai_exit = 1; return NULL; } #define CALIB_LOOP_CNT 1000000 //2000000000 #define CALIB_LOOP_REPORT_PERIOD 1000 #define CALIB_LOOP_UP_THRESHOLD 20 // 20 -> for NG Intel flat model #define CALIB_USLEEP 250 int main( void ) { int i; #if CALIB_RT_INTRUMENTATION uint32_t calib_loop_count; uint64_t lt_overhead_cur; uint64_t lt_overhead_min; uint64_t lt_overhead_max; uint64_t lt_overhead_mean; histo_time_t *lt_overhead_histogram = NULL; uint64_t lt_syr_overhead_cur; uint64_t lt_syr_overhead_min; uint64_t lt_syr_overhead_max; uint64_t lt_syr_overhead_mean; histo_time_t *lt_syr_overhead_histogram = NULL; double syr_rdtsc_overhead_cur; double syr_rdtsc_overhead_min; double syr_rdtsc_overhead_max; double syr_rdtsc_overhead_mean; histo_time_t *syr_rdtsc_overhead_histogram = NULL; double syr_clock_gettime_overhead_cur; double syr_clock_gettime_overhead_min; double syr_clock_gettime_overhead_max; double syr_clock_gettime_overhead_mean; histo_time_t *syr_clock_gettime_overhead_histogram = NULL; uint64_t cycles_start; uint64_t cycles_stop; uint64_t cycles_diff; uint64_t cycles_diff_max = 0; struct timespec start; struct timespec stop; #endif cpuf = get_cpu_freq_GHz(); cpu_mhz_syr = estimate_MHz_syr(); printf("\n\ncpuf %f - cpu_mhz_syr %f\n\n", cpuf, cpu_mhz_syr); #if CALIB_RT_INTRUMENTATION /* ********************************************************************************************** */ /* CALIBRATION */ /* ********************************************************************************************** */ /* ************************************************************* Laurent Thomas instrumentation overhead */ printf("\nCalibrating OAI Realtime Instrumentation (Laurent Thomas imp.)\n"); calib_loop_count = CALIB_LOOP_CNT; initRefTimes(lt_instru_calib); // Laurent Thomas realtime instrumentation calibration measurments lt_overhead_min = 1000; lt_overhead_max = 0; lt_overhead_mean = 0; lt_overhead_histogram = histogram_init( lt_overhead_histogram ); while(calib_loop_count) { pickTime(lt_start); // asm volatile(""); // Nop instruction usleep(CALIB_USLEEP); lt_overhead_cur = updateTimes( readTime(lt_start), <_instru_calib, CALIB_LOOP_CNT, "Laurent Thomas realtime instrumentation calibration measurments"); lt_overhead_mean += lt_overhead_cur; if ( lt_overhead_max < lt_overhead_cur ) lt_overhead_max = lt_overhead_cur; if ( lt_overhead_min > lt_overhead_cur ) lt_overhead_min = lt_overhead_cur; histogram_store_value( lt_overhead_histogram, (double)lt_overhead_cur ); if ( calib_loop_count%CALIB_LOOP_REPORT_PERIOD == 0 ) { printf("\r%d/%d",calib_loop_count,CALIB_LOOP_CNT); fflush(stdout); } calib_loop_count--; } lt_overhead_mean = lt_overhead_mean/CALIB_LOOP_CNT; // printMeas("\nLaurent Thomas realtime instrumentation calibration measurments",<_instru_calib,CALIB_LOOP_CNT); /* ************************************************************* Laurent Thomas instrumentation overhead */ printf("\nCalibrating OAI Realtime Instrumentation - SYRTEM revisited\n"); calib_loop_count = CALIB_LOOP_CNT; initRefTimes(lt_instru_calib_syr); // Laurent Thomas realtime instrumentation calibration measurments lt_syr_overhead_min = 1000; lt_syr_overhead_max = 0; lt_syr_overhead_mean = 0; lt_syr_overhead_histogram = histogram_init( lt_syr_overhead_histogram ); while(calib_loop_count) { pickTime_syr(lt_start_syr); // asm volatile(""); // Nop instruction usleep(CALIB_USLEEP); lt_syr_overhead_cur = updateTimes_syr(readTime(lt_start_syr), <_instru_calib_syr, CALIB_LOOP_CNT, "Laurent Thomas realtime instrumentation calibration measurments (SYRTEM Update)"); lt_syr_overhead_mean += lt_syr_overhead_cur; if ( lt_syr_overhead_max < lt_syr_overhead_cur ) lt_syr_overhead_max = lt_syr_overhead_cur; if ( lt_syr_overhead_min > lt_syr_overhead_cur ) lt_syr_overhead_min = lt_syr_overhead_cur; histogram_store_value( lt_syr_overhead_histogram, (double)lt_syr_overhead_cur ); if ( calib_loop_count%CALIB_LOOP_REPORT_PERIOD == 0 ) { printf("\r%d/%d",calib_loop_count,CALIB_LOOP_CNT); fflush(stdout); } calib_loop_count--; } lt_syr_overhead_mean = lt_syr_overhead_mean / CALIB_LOOP_CNT; // printMeas("\nLaurent Thomas realtime instrumentation calibration measurments (SYRTEM Update)",<_instru_calib_syr,CALIB_LOOP_CNT); /* ************************************************************* SYRTEM RDTSC instrumentation overhead */ printf("\nCalibrating SYRTEM RDTSC Realtime Instrumentation\n"); calib_loop_count = CALIB_LOOP_CNT; syr_rdtsc_overhead_min = 1000; syr_rdtsc_overhead_max = 0; syr_rdtsc_overhead_mean = 0; syr_rdtsc_overhead_histogram = histogram_init( syr_rdtsc_overhead_histogram ); while(calib_loop_count) { cycles_start = pickCyclesStart(); // asm volatile(""); // Nop instruction usleep(CALIB_USLEEP); cycles_stop = pickCyclesStop(); cycles_diff = cycles_stop - cycles_start; if(cycles_diff_max < cycles_diff) cycles_diff_max = cycles_diff; syr_rdtsc_overhead_cur = (double)cycles_diff/cpu_mhz_syr; syr_rdtsc_overhead_mean += syr_rdtsc_overhead_cur; if ( syr_rdtsc_overhead_max < syr_rdtsc_overhead_cur ) syr_rdtsc_overhead_max = syr_rdtsc_overhead_cur; if ( syr_rdtsc_overhead_min > syr_rdtsc_overhead_cur ) syr_rdtsc_overhead_min = syr_rdtsc_overhead_cur; histogram_store_value( syr_rdtsc_overhead_histogram, (double)syr_rdtsc_overhead_cur ); if ( calib_loop_count%CALIB_LOOP_REPORT_PERIOD == 0 ) { printf("\r%d/%d",calib_loop_count,CALIB_LOOP_CNT); fflush(stdout); } calib_loop_count--; } syr_rdtsc_overhead_mean = syr_rdtsc_overhead_mean / CALIB_LOOP_CNT; // printf("\nSYRTEM RDTSV realtime instrumentation calibration : cycles_diff_max %ld - tsc_duration_max %f us\n ", cycles_diff_max, tsc_duration_max); /* ************************************************************* SYRTEM Clock_gettime MONOTONIC instrumentation overhead */ printf("\nCalibrating SYRTEM clock_gettime Realtime Instrumentation\n"); calib_loop_count = CALIB_LOOP_CNT; syr_clock_gettime_overhead_min = 1000; syr_clock_gettime_overhead_max = 0; syr_clock_gettime_overhead_mean = 0; syr_clock_gettime_overhead_histogram = histogram_init( syr_clock_gettime_overhead_histogram ); while(calib_loop_count) { clock_gettime( CLOCK_MONOTONIC, &start ); // asm volatile(""); // Nop instruction usleep(CALIB_USLEEP); clock_gettime( CLOCK_MONOTONIC, &stop ); syr_clock_gettime_overhead_cur = TIMESPEC_TO_DOUBLE_US( get_timespec_diff( &start, &stop ) ); syr_clock_gettime_overhead_mean += syr_clock_gettime_overhead_cur; if ( syr_clock_gettime_overhead_max < syr_clock_gettime_overhead_cur ) syr_clock_gettime_overhead_max = syr_clock_gettime_overhead_cur; if ( syr_clock_gettime_overhead_min > syr_clock_gettime_overhead_cur ) syr_clock_gettime_overhead_min = syr_clock_gettime_overhead_cur; histogram_store_value( syr_clock_gettime_overhead_histogram, (double)syr_clock_gettime_overhead_cur ); if ( calib_loop_count%CALIB_LOOP_REPORT_PERIOD == 0 ) { printf("\r%d/%d",calib_loop_count,CALIB_LOOP_CNT); fflush(stdout); } calib_loop_count--; } syr_clock_gettime_overhead_mean = syr_clock_gettime_overhead_mean / CALIB_LOOP_CNT; // printf("\nSYRTEM clock_gettime MONOTONIC calibration : clock_gettime duration_max %f us\n ", max); printf("\n"); printf("OAI LT RT profiling overhead (it. %d) (us) : max=%8ld - mean=%8ld - min=%8ld\n", CALIB_LOOP_CNT, lt_overhead_max, lt_overhead_mean, lt_overhead_min); printf("OAI SYR RT profiling overhead (it. %d) (us) : max=%8ld - mean=%8ld - min=%8ld\n", CALIB_LOOP_CNT, lt_syr_overhead_max, lt_syr_overhead_mean, lt_syr_overhead_min); printf("SYR RDTSC profiling overhead (it. %d) (us) : max=%8.3f - mean=%8.3f - min=%8.3f\n", CALIB_LOOP_CNT, syr_rdtsc_overhead_max, syr_rdtsc_overhead_mean, syr_rdtsc_overhead_min); printf("SYR clock_gettime profiling overhead (it. %d) (us): max=%8.3f - mean=%8.3f - min=%8.3f\n", CALIB_LOOP_CNT, syr_clock_gettime_overhead_max, syr_clock_gettime_overhead_mean, syr_clock_gettime_overhead_min); return 0; #endif rxtx_proc = calloc( RX_NB_TH, sizeof( UE_rxtx_proc_t* ) ); for (i=0 ; i * Small changes by David Sterba * */ struct timespec start; struct timespec stop; unsigned long long int cycles[2]; /* must be 64 bit */ double microseconds; /* total time taken */ /* get this function in cached memory */ cycles[0] = rdtsc (); clock_gettime( CLOCK_REALTIME, &start ); /* we don't trust that this is any specific length of time */ usleep (100000); cycles[1] = rdtsc (); clock_gettime( CLOCK_REALTIME, &stop ); microseconds = TIMESPEC_TO_DOUBLE_US( get_timespec_diff( &start, &stop ) ); unsigned long long int elapsed = 0; if (cycles[1] < cycles[0]) { //printf("c0 = %llu c1 = %llu",cycles[0],cycles[1]); elapsed = UINT32_MAX - cycles[0]; elapsed = elapsed + cycles[1]; //printf("c0 = %llu c1 = %llu max = %llu elapsed=%llu\n",cycles[0], cycles[1], UINT32_MAX,elapsed); } else { elapsed = cycles[1] - cycles[0]; // printf("\nc0 = %llu c1 = %llu elapsed=%llu\n",cycles[0], cycles[1],elapsed); } double mhz = elapsed / microseconds; //printf("%llg MHz processor (estimate). diff cycles=%llu microseconds=%llu \n", mhz, elapsed, microseconds); //printf("%g elapsed %llu microseconds %llu\n",mhz, elapsed, microseconds); return (mhz); } /** TSC Timestamp references - http://oliveryang.net/2015/09/pitfalls-of-TSC-usage/#312-tsc-sync-behaviors-on-smp-system - https://www.intel.com/content/www/us/en/embedded/training/ia-32-ia-64-benchmark-code-execution-paper.html - https://www.intel.com/content/dam/www/public/us/en/documents/manuals/64-ia-32-architectures-software-developer-vol-3b-part-2-manual.pdf - http://blog.tinola.com/?e=54 - https://stackoverflow.com/questions/24392392/getting-tsc-frequency-from-proc-cpuinfo !! warning on turbo - https://gist.github.com/nfarring/1624742 - https://www.lmax.com/blog/staff-blogs/2015/10/25/time-stamp-counters/ - https://github.com/cyring/CoreFreq - https://patchwork.kernel.org/patch/9438133/ --> TSC_ADJUST - to be checked -> https://software.intel.com/en-us/forums/software-tuning-performance-optimization-platform-monitoring/topic/388964 - https://www.google.fr/url?sa=t&rct=j&q=&esrc=s&source=web&cd=11&ved=0ahUKEwjwpJbem5DVAhWBDpoKHXv0Dt04ChAWCCIwAA&url=https%3A%2F%2Fsigarra.up.pt%2Ffeup%2Fpt%2Fpub_geral.show_file%3Fpi_gdoc_id%3D809041&usg=AFQjCNFHTMjmjWMG6QSVnLDflEoU0RavKw&cad=rja - https://unix4lyfe.org/benchmarking/ - https://stackoverflow.com/questions/27693145/rdtscp-versus-rdtsc-cpuid - https://github.com/dterei/tsc/blob/master/tsc.h - https://software.intel.com/en-us/forums/intel-isa-extensions/topic/280440 - https://stackoverflow.com/questions/19941588/wrong-clock-cycle-measurements-with-rdtsc */ static __inline__ uint64_t pickCyclesStart(void) { unsigned cycles_low, cycles_high; asm volatile( "CPUID\n\t" // serialize "RDTSC\n\t" // read clock "MOV %%edx, %0\n\t" "MOV %%eax, %1\n\t" : "=r" (cycles_high), "=r" (cycles_low) :: "%rax", "%rbx", "%rcx", "%rdx" ); return ((uint64_t) cycles_high << 32) | cycles_low; } static __inline__ uint64_t pickCyclesStop(void) { uint32_t eax, edx; __asm__ __volatile__("rdtscp" : "=a" (eax), "=d" (edx) : : "%ecx", "memory"); return (((uint64_t)edx << 32) | eax); } /************************************************************************************** EXTRACT from openair1/PHY/TOOLS/time_meas.c ***************************************************************************************/ double get_cpu_freq_GHz(void) { time_stats_t ts = {0}; reset_meas(&ts); ts.trials++; ts.in = rdtsc_oai(); sleep(1); ts.diff = (rdtsc_oai()-ts.in); cpu_freq_GHz = (double)ts.diff/1000000000; printf("CPU Freq is %f \n", cpu_freq_GHz); return cpu_freq_GHz; } /************************************************************************************** SYRTEM STATISTICS HELPER ***************************************************************************************/ histo_time_t *histogram_init(histo_time_t *histo ) { int i = 0; double max_val = HISTOGRAM_MIN_VALUE + HISTOGRAM_STEP; histo = calloc( HISTOGRAM_SIZE, sizeof( histo_time_t ) ); if ( histo == NULL ) { printf( "ERROR allocating histogram structure !\n" ); return NULL; } for ( i = 0; i < HISTOGRAM_SIZE; i++ ) { histo[i].max = max_val; max_val += HISTOGRAM_STEP; } return histo; } void histogram_store_value( histo_time_t *histo, double value ) { int i = 0; for ( i = 0; i < HISTOGRAM_SIZE; i++ ) { if ( histo[i].max >= value || ( i + 1 ) == HISTOGRAM_SIZE ) { histo[i].count++; break; } } } void histogram_save_in_csv( histo_time_t *histo , char *file_sufix) { char *csv_filename; char month[3], day[3], hour[3], min[3], sec[3]; time_t curr_time; struct tm *datetime; curr_time = time( NULL ); datetime = localtime( &curr_time ); csv_filename = calloc( sizeof( char ), 64 ); if ( csv_filename == NULL ) { return; } memset( csv_filename, 0x00, 64 ); memset( month, 0x00, 3 ); memset( day, 0x00, 3 ); memset( hour, 0x00, 3 ); memset( min, 0x00, 3 ); memset( sec, 0x00, 3 ); /* Month. */ if ( datetime->tm_mon < 9 ) snprintf( month, 3, "0%d", datetime->tm_mon + 1 ); else snprintf( month, 3, "%d", datetime->tm_mon + 1 ); /* Day. */ if ( datetime->tm_mday < 10 ) snprintf( day, 3, "0%d", datetime->tm_mday ); else snprintf( day, 3, "%d", datetime->tm_mday ); /* Hour. */ if ( datetime->tm_hour < 10 ) snprintf( hour, 3, "0%d", datetime->tm_hour ); else snprintf( hour, 3, "%d", datetime->tm_hour ); /* Minute. */ if ( datetime->tm_min < 10 ) snprintf( min, 3, "0%d", datetime->tm_min ); else snprintf( min, 3, "%d", datetime->tm_min ); /* Second. */ if ( datetime->tm_sec < 10 ) snprintf( sec, 3, "0%d", datetime->tm_sec ); else snprintf( sec, 3, "%d", datetime->tm_sec ); snprintf( csv_filename, 63, "ADRV9371_ZC706_HISTO_UEtoRXTX_%d%s%s%s%s%s_%s.csv", datetime->tm_year + 1900, month, day, hour, min, sec, file_sufix ); FILE *fp; int i = 0; int min_val = 0; fp = fopen( csv_filename, "w+" ); fprintf( fp, "range;count\n" ); for ( i = 0; i < HISTOGRAM_SIZE; i++ ) { if ( i + 1 == HISTOGRAM_SIZE ) fprintf( fp, "%d+;%u\n", min_val, histo[i].count ); else fprintf( fp, "%d-%.0f;%u\n", min_val, histo[i].max, histo[i].count ); min_val = histo[i].max; } free(csv_filename); fclose( fp ); } static struct timespec get_timespec_diff( struct timespec *start, struct timespec *stop ) { struct timespec result; if ( ( stop->tv_nsec - start->tv_nsec ) < 0 ) { result.tv_sec = stop->tv_sec - start->tv_sec - 1; result.tv_nsec = stop->tv_nsec - start->tv_nsec + 1000000000; } else { result.tv_sec = stop->tv_sec - start->tv_sec; result.tv_nsec = stop->tv_nsec - start->tv_nsec; } return result; } static void measure_time ( struct timespec *start, struct timespec *stop, uint8_t START, uint16_t PRINT_INTERVAL ) { static double max = 0; static double min = 0; static double total = 0; static int count = 0; if ( START ) { clock_gettime( CLOCK_REALTIME, start ); } else { clock_gettime( CLOCK_REALTIME, stop ); struct timespec diff; double current = 0; diff = get_timespec_diff( start, stop ); // current = ( (double)diff.tv_sec * 1000000 ) + ( (double)diff.tv_nsec / 1000 ); current = TIMESPEC_TO_DOUBLE_US( diff ); if ( current > max ) { max = current; } if ( min == 0 || current < min ) { min = current; } total += current; histogram_store_value( th_wake_histogram, current ); if ( count % PRINT_INTERVAL == 0 && count != 0 ) { double avg = total / ( count + 1 ); printf( "[%d] Current : %.2lf µs, Min : %.2lf µs, Max : %.2lf µs, Moy : %.2lf µs\n", count, current, min, max, avg ); } count++; } }