fix measurement

openair2/UTIL/LOG/log.h

@@ -52,7 +52,27 @@
 #ifdef __cplusplus
 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
  * @{*/
 /* @}*/

targets/ARCH/USRP/USERSPACE/LIB/usrp_lib.cpp

@@ -96,26 +96,7 @@ typedef struct {
     openair0_timestamp rx_timestamp;
 
 } usrp_state_t;
-extern double cpuf;
-#if defined(__x86_64)
-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;
-    unsigned long long cur=rdtsc();
-    int microCycles=(int)(cpuf*1000);
-    if ( (cur-last) > timeout*microCycles)
-        printf("%s:%d lte-ue delay %d\n", file, line,(int)((cur-last)/microCycles));
-    last=cur;
-    return cur;
-}
-#define check(a) checkT(a,__FILE__,__LINE__)
-#else
-static inline unsigned long long check(int a) {};
-#endif
+
 
 
 /*! \brief Called to start the USRP transceiver. Return 0 if OK, < 0 if error
@@ -603,6 +584,9 @@ extern "C" {
             }
         }
 
+        //s->usrp->set_clock_source("external");
+        //s->usrp->set_time_source("external");
+
         // display USRP settings
         LOG_I(PHY,"Actual master clock: %fMHz...\n",s->usrp->get_master_clock_rate()/1e6);
 
@@ -637,7 +621,7 @@ extern "C" {
             LOG_I(PHY,"  Actual RX frequency: %fGHz...\n", s->usrp->get_rx_freq(i)/1e9);
             LOG_I(PHY,"  Actual RX gain: %f...\n", s->usrp->get_rx_gain(i));
             LOG_I(PHY,"  Actual RX bandwidth: %fM...\n", s->usrp->get_rx_bandwidth(i)/1e6);
-            LOG_I(PHY,"  Actual RX antenna: %s...\n", s->usrp->get_rx_antenna(i));
+            LOG_I(PHY,"  Actual RX antenna: %s...\n", s->usrp->get_rx_antenna(i).c_str());
         }
 
         for (int i=0; i<openair0_cfg[0].tx_num_channels; i++) {
@@ -646,7 +630,7 @@ extern "C" {
             LOG_I(PHY,"  Actual TX frequency: %fGHz...\n", s->usrp->get_tx_freq(i)/1e9);
             LOG_I(PHY,"  Actual TX gain: %f...\n", s->usrp->get_tx_gain(i));
             LOG_I(PHY,"  Actual TX bandwidth: %fM...\n", s->usrp->get_tx_bandwidth(i)/1e6);
-            LOG_I(PHY,"  Actual TX antenna: %u...\n", s->usrp->get_tx_antenna(i));
+            LOG_I(PHY,"  Actual TX antenna: %s...\n", s->usrp->get_tx_antenna(i).c_str());
         }
 
         LOG_I(PHY,"Device timestamp: %f...\n", s->usrp->get_time_now().get_real_secs());

targets/RT/USER/lte-ue.c

@@ -76,24 +76,9 @@
 #include "UTIL/OPT/opt.h"
 
 /* start SYRTEM */
-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;
-    unsigned long long cur=rdtsc();
-    int microCycles=(int)(cpuf*1000);
-    if ( (cur-last) > timeout*microCycles)
-        printf("%s:%d lte-ue delay %d\n", file, line,(int)((cur-last)/microCycles));
-    last=cur;
-    return cur;
-}
+
 #define DEBUG_REALTIME 1
 #if DEBUG_REALTIME
-#define check(a) checkT(a,__FILE__,__LINE__)
 
 typedef struct latency_stat {
     uint64_t		counter;
@@ -126,7 +111,7 @@ static inline void saif_meas(int frame_rx) {
             else
                 latency_stat.stat3000++;
         }
-        if ( diffTime>=1100 ) {
+        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",
@@ -141,12 +126,50 @@ static inline void saif_meas(int frame_rx) {
                   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 */
 
@@ -392,9 +415,6 @@ static void *UE_thread_synch(void *arg) {
 
 #endif
 
-
-
-
     printf("starting UE synch thread (IC %d)\n",UE->proc.instance_cnt_synch);
     ind = 0;
     found = 0;
@@ -694,7 +714,7 @@ static void *UE_thread_rxn_txnp4(void *arg) {
     int ret;
     PHY_VARS_UE *UE=PHY_vars_UE_g[0][proc->CC_id];
 
-    proc->instance_cnt_rxtx=-1;
+    static long long __thread instance_cnt_rxtx=-1;
     proc->subframe_rx=proc->sub_frame_start;
 
     char threadName[256]= {0};
@@ -709,22 +729,22 @@ static void *UE_thread_rxn_txnp4(void *arg) {
         // Wait Rx data to process are available
         AssertFatal(pthread_mutex_lock(&proc->mutex_rxtx) ==0,"");
         pthread_cond_wait( &proc->cond_rxtx, &proc->mutex_rxtx );
-        if ( (proc->instance_cnt_rxtx+proc->sub_frame_step)%10 != proc->subframe_rx &&  proc->instance_cnt_rxtx!=-1 )
+        if ( (instance_cnt_rxtx+proc->sub_frame_step)%10 != proc->subframe_rx &&  instance_cnt_rxtx!=-1 )
             LOG_W(PHY,"REAL TIME NOT MATCHED: missed a sub-frame: expecting %d, got %d\n",
-                  (proc->instance_cnt_rxtx+proc->sub_frame_step)%10, proc->subframe_rx);
-        proc->instance_cnt_rxtx=proc->subframe_rx;
+                  (instance_cnt_rxtx+proc->sub_frame_step)%10, proc->subframe_rx);
+        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();
-        if ( (current - proc->gotIQs)/(int)(cpuf*1000*100) > 100 )
-            LOG_W(PHY,"Delay to wake up UE_Thread_Rx > 100µs, actual value= %d µs\n", (current - proc->gotIQs)/(int)(cpuf*1000*100));
-        check(2000);
+	updateTimes(proc->gotIQs, &t2, 10000, "saif: Delay to wake up UE_Thread_Rx (case 2)");
+	
         // Process Rx data for one sub-frame
         if ((subframe_select( &UE->frame_parms, proc->subframe_rx) == SF_DL) ||
                 (UE->frame_parms.frame_type == FDD) ||
                 (subframe_select( &UE->frame_parms, proc->subframe_rx ) == SF_S)) {
             phy_procedures_UE_RX( UE, proc, 0, 0, UE->mode, no_relay, NULL );
         }
-        check(600);
         if (UE->mac_enabled==1) {
             ret = mac_xface->ue_scheduler(UE->Mod_id,
                                           proc->frame_tx,
@@ -749,14 +769,13 @@ static void *UE_thread_rxn_txnp4(void *arg) {
             LOG_E( PHY, "[UE %"PRIu8"] Frame %"PRIu32", subframe %u %s\n",
                    UE->Mod_id, proc->frame_rx, proc->subframe_tx,txt );
         }
-        check(100);
         // Prepare the future Tx data
         if ((subframe_select( &UE->frame_parms, proc->subframe_tx) == SF_UL) ||
                 (UE->frame_parms.frame_type == FDD) ||
                 (subframe_select( &UE->frame_parms, proc->subframe_tx ) == SF_S))
             if (UE->mode != loop_through_memory)
                 phy_procedures_UE_TX(UE,proc,0,0,UE->mode,no_relay);
-        check(200);
+	updateTimes(current, &t3, 10000, "saif: Delay to process sub-frame (case 3)");
     }
     // thread finished
     return &UE_thread_rxtx_retval;
@@ -921,7 +940,6 @@ void *UE_thread(void *arg) {
                                                            rxp,
                                                            readBlockSize,
                                                            UE->frame_parms.nb_antennas_rx),"");
-                    check(1020);
                     AssertFatal( writeBlockSize ==
                                  UE->rfdevice.trx_write_func(&UE->rfdevice,
                                          timestamp+
@@ -932,7 +950,6 @@ void *UE_thread(void *arg) {
                                          writeBlockSize,
                                          UE->frame_parms.nb_antennas_tx,
                                          1),"");
-                    check(100);
                     if( sub_frame==9) {
                         // read in first symbol of next frame and adjust for timing drift
                         int first_symbols=writeBlockSize-readBlockSize;
@@ -947,15 +964,14 @@ void *UE_thread(void *arg) {
                             LOG_E(PHY,"can't compensate: diff =%d\n", first_symbols);
                     }
                     unsigned long long gotIQs=rdtsc();
-                    check(250);
                     // 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=gotIQs;
+		    UE->proc.proc_rxtx[1].gotIQs=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);
@@ -965,9 +981,12 @@ void *UE_thread(void *arg) {
 
                     AssertFatal (pthread_cond_signal(&proc->cond_rxtx) ==0 ,"");
                     AssertFatal(pthread_mutex_unlock(&proc->mutex_rxtx) ==0,"");
-                    check(50);
+		    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);
-                    check(50);
 
                 } else {
                     printf("Processing subframe %d",proc->subframe_rx);