Merge remote-tracking branch 'origin/ci-test-newstats' into integration_2021_wk45_c

ci-scripts/cls_oaicitest.py

@@ -1583,7 +1583,7 @@ class OaiCiTest():
 					if re.match('OAI-Rel14-Docker', EPC.Type, re.IGNORECASE):
 						Target = EPC.MmeIPAddress
 					elif re.match('OAICN5G', EPC.Type, re.IGNORECASE):
-						Target = '8.8.8.8'
+						Target = EPC.MmeIPAddress
 					else:
 						Target = EPC.IPAddress
 					#ping from module NIC rather than IP address to make sure round trip is over the air	

ci-scripts/epc.py

@@ -62,7 +62,6 @@ class EPCManagement():
 		self.PcapFileName = ''
 		self.testCase_id = ''
 		self.MmeIPAddress = ''
-		self.AmfIPAddress = ''
 		self.containerPrefix = 'prod'
 		self.mmeConfFile = 'mme.conf'
 		self.yamlPath = ''

ci-scripts/ran.py

@@ -734,8 +734,8 @@ class RANManagement():
 		mySSH.command('echo ' + self.eNBPassword + ' | sudo -S mv /tmp/enb_*.pcap .','\$',20)
 		mySSH.command('echo ' + self.eNBPassword + ' | sudo -S mv /tmp/gnb_*.pcap .','\$',20)
 		mySSH.command('echo ' + self.eNBPassword + ' | sudo -S rm -f enb.log.zip', '\$', 5)
-		mySSH.command('echo ' + self.eNBPassword + ' | sudo -S zip enb.log.zip enb*.log core* enb_*record.raw enb_*.pcap gnb_*.pcap enb_*txt physim_*.log *stats.log *monitor.pickle *monitor.png', '\$', 60)
-		mySSH.command('echo ' + self.eNBPassword + ' | sudo -S rm enb*.log core* enb_*record.raw enb_*.pcap gnb_*.pcap enb_*txt physim_*.log *stats.log *.pickle *.png', '\$', 5)
+		mySSH.command('echo ' + self.eNBPassword + ' | sudo -S zip enb.log.zip enb*.log core* enb_*record.raw enb_*.pcap gnb_*.pcap enb_*txt physim_*.log *stats.log *monitor.pickle *monitor*.png', '\$', 60)
+		mySSH.command('echo ' + self.eNBPassword + ' | sudo -S rm enb*.log core* enb_*record.raw enb_*.pcap gnb_*.pcap enb_*txt physim_*.log *stats.log *monitor.pickle *monitor*.png', '\$', 5)
 		mySSH.close()
 
 	def AnalyzeLogFile_eNB(self, eNBlogFile, HTML):
@@ -792,23 +792,11 @@ class RANManagement():
 		pb_receiving_samples_cnt = 0
 		#count "removing UE" msg
 		removing_ue = 0
+		#count"X2AP-PDU"
+		x2ap_pdu = 0
 		#NSA specific log markers
 		nsa_markers ={'SgNBReleaseRequestAcknowledge': [],'FAILURE': [], 'scgFailureInformationNR-r15': [], 'SgNBReleaseRequest': []}
 	
-		#the datalog config file has to be loaded
-		datalog_rt_stats_file='datalog_rt_stats.yaml'
-		if (os.path.isfile(datalog_rt_stats_file)):
-			yaml_file=datalog_rt_stats_file
-		elif (os.path.isfile('ci-scripts/'+datalog_rt_stats_file)):
-			yaml_file='ci-scripts/'+datalog_rt_stats_file
-		else:
-			logging.error("Datalog RT stats yaml file cannot be found")
-			sys.exit("Datalog RT stats yaml file cannot be found")
-
-		with open(yaml_file,'r') as f:
-			datalog_rt_stats = yaml.load(f,Loader=yaml.FullLoader)
-		rt_keys = datalog_rt_stats['Ref'] #we use the keys from the Ref field  
-
 		line_cnt=0 #log file line counter
 		for line in enb_log_file.readlines():
 			line_cnt+=1
@@ -975,15 +963,7 @@ class RANManagement():
 				if result is not None:
 					#remove 1- all useless char before relevant info (ulsch or dlsch) 2- trailing char
 					dlsch_ulsch_stats[k]=re.sub(r'^.*\]\s+', r'' , line.rstrip())
-			#real time statistics for gNB
-			for k in rt_keys:
-				result = re.search(k, line)     
-				if result is not None:
-					#remove 1- all useless char before relevant info  2- trailing char
-					line=line.replace('[0m','')
-					tmp=re.match(rf'^.*?(\b{k}\b.*)',line.rstrip()) #from python 3.6 we can use literal string interpolation for the variable k, using rf' in the regex
-					if tmp!=None: #with ULULULUULULULLLL at the head of the line, we skip it
-						real_time_stats[k]=tmp.group(1)
+
 
 			#count "problem receiving samples" msg
 			result = re.search('\[PHY\]\s+problem receiving samples', str(line))
@@ -993,7 +973,10 @@ class RANManagement():
 			result = re.search('\[MAC\]\s+Removing UE', str(line))
 			if result is not None:
 				removing_ue += 1
-
+			#count "X2AP-PDU"
+			result = re.search('X2AP-PDU', str(line))
+			if result is not None:
+				x2ap_pdu += 1
 			#nsa markers logging
 			for k in nsa_markers:
 				result = re.search(k, line)
@@ -1001,7 +984,55 @@ class RANManagement():
 					nsa_markers[k].append(line_cnt)					
 
 		enb_log_file.close()
-		logging.debug('   File analysis completed')
+
+
+		#the following part takes the *_stats.log files as source (not the stdout log file)
+
+		#the datalog config file has to be loaded
+		datalog_rt_stats_file='datalog_rt_stats.yaml'
+		if (os.path.isfile(datalog_rt_stats_file)):
+			yaml_file=datalog_rt_stats_file
+		elif (os.path.isfile('ci-scripts/'+datalog_rt_stats_file)):
+			yaml_file='ci-scripts/'+datalog_rt_stats_file
+		else:
+			logging.error("Datalog RT stats yaml file cannot be found")
+			sys.exit("Datalog RT stats yaml file cannot be found")
+
+		with open(yaml_file,'r') as f:
+			datalog_rt_stats = yaml.load(f,Loader=yaml.FullLoader)
+		rt_keys = datalog_rt_stats['Ref'] #we use the keys from the Ref field  
+
+		if (os.path.isfile('./nrL1_stats.log')) and (os.path.isfile('./nrL1_stats.log')):
+			stat_files_present=True
+		else:
+			stat_files_present=False
+			logging.debug("NR Stats files for RT analysis not found")
+		if stat_files_present:
+			nrL1_stats = open('./nrL1_stats.log', 'r')
+			nrMAC_stats = open('./nrMAC_stats.log', 'r')
+			for line in nrL1_stats.readlines():
+				for k in rt_keys:
+					result = re.search(k, line)     
+					if result is not None:
+						#remove 1- all useless char before relevant info  2- trailing char
+						tmp=re.match(rf'^.*?(\b{k}\b.*)',line.rstrip()) #from python 3.6 we can use literal string interpolation for the variable k, using rf' in the regex
+						if tmp!=None: 
+							real_time_stats[k]=tmp.group(1)
+			for line in nrMAC_stats.readlines():
+				for k in rt_keys:
+					result = re.search(k, line)     
+					if result is not None:
+						#remove 1- all useless char before relevant info  2- trailing char
+						tmp=re.match(rf'^.*?(\b{k}\b.*)',line.rstrip()) #from python 3.6 we can use literal string interpolation for the variable k, using rf' in the regex
+						if tmp!=None: 
+							real_time_stats[k]=tmp.group(1)
+			nrL1_stats.close()
+			nrMAC_stats.close()
+
+		#stdout log file and stat log files analysis completed
+		logging.debug('   File analysis (stdout, stats) completed')
+
+		#post processing depending on the node type
 		if (self.air_interface[self.eNB_instance] == 'lte-softmodem') or (self.air_interface[self.eNB_instance] == 'ocp-enb'):
 			nodeB_prefix = 'e'
 		else:
@@ -1087,6 +1118,11 @@ class RANManagement():
 			htmlMsg = statMsg+'\n'
 			logging.debug(statMsg)
 			htmleNBFailureMsg += htmlMsg
+			#X2AP-PDU log
+			statMsg = 'X2AP-PDU msg count =  '+str(x2ap_pdu)
+			htmlMsg = statMsg+'\n'
+			logging.debug(statMsg)
+			htmleNBFailureMsg += htmlMsg
 			#nsa markers
 			statMsg = 'logfile line count = ' + str(line_cnt)			
 			htmlMsg = statMsg+'\n'

ci-scripts/stats_monitor.py

@@ -17,9 +17,15 @@ class StatMonitor():
     def __init__(self,cfg_file):
         with open(cfg_file,'r') as file:
             self.d = yaml.load(file)
-        for node in self.d:
-            for metric in self.d[node]:
-                self.d[node][metric]=[]
+        for node in self.d:#so far we have enb or gnb as nodes
+            for metric_l1 in self.d[node]: #first level of metric keys
+                if metric_l1!="graph": #graph is a reserved word to configure graph paging, so it is disregarded
+                    if self.d[node][metric_l1] is None:#first level is None -> create array
+                        self.d[node][metric_l1]=[]
+                    else: #first level is not None -> there is a second level -> create array
+                        for metric_l2 in self.d[node][metric_l1]:
+                            self.d[node][metric_l1][metric_l2]=[]                
+
 
 
     def process_gnb (self,node_type,output):
@@ -36,6 +42,11 @@ class StatMonitor():
                 percentage=float(result.group(2))/float(result.group(1))
                 self.d[node_type]['ulsch_err_perc_round_1'].append(percentage)
 
+            for k in self.d[node_type]['rt']:
+                result=re.match(rf'^.*\b{k}\b:\s+([0-9\.]+) us;\s+([0-9]+);\s+([0-9\.]+) us;',tmp)
+                if result is not None:
+                    self.d[node_type]['rt'][k].append(float(result.group(3)))
+
 
     def process_enb (self,node_type,output):
         for line in output:
@@ -62,23 +73,37 @@ class StatMonitor():
 
 
     def graph(self,node_type):
+        for page in self.d[node_type]['graph']:#work out a set a graphs per page
             col = 1
-        figure, axis = plt.subplots(len(self.d[node_type]), col ,figsize=(10, 10))
+            figure, axis = plt.subplots(len(self.d[node_type]['graph'][page]), col ,figsize=(10, 10))
             i=0
-        for metric in self.d[node_type]:
-            major_ticks = np.arange(0, len(self.d[node_type][metric])+1, 1)
+            for m in self.d[node_type]['graph'][page]:#metric may refer to 1 level or 2 levels 
+                metric_path=m.split('.')
+                if len(metric_path)==1:#1 level
+                    metric_l1=metric_path[0]
+                    major_ticks = np.arange(0, len(self.d[node_type][metric_l1])+1, 1)
+                    axis[i].set_xticks(major_ticks)
+                    axis[i].set_xticklabels([])
+                    axis[i].plot(self.d[node_type][metric_l1],marker='o')
+                    axis[i].set_xlabel('time')
+                    axis[i].set_ylabel(metric_l1)
+                    axis[i].set_title(metric_l1)
+                    
+                else:#2 levels
+                    metric_l1=metric_path[0]
+                    metric_l2=metric_path[1]
+                    major_ticks = np.arange(0, len(self.d[node_type][metric_l1][metric_l2])+1, 1)
                     axis[i].set_xticks(major_ticks)
                     axis[i].set_xticklabels([])
-            axis[i].plot(self.d[node_type][metric],marker='o')
+                    axis[i].plot(self.d[node_type][metric_l1][metric_l2],marker='o')
                     axis[i].set_xlabel('time')
-            axis[i].set_ylabel(metric)
-            axis[i].set_title(metric)
+                    axis[i].set_ylabel(metric_l2)
+                    axis[i].set_title(metric_l2)
                 i+=1                
 
             plt.tight_layout()
-        # Combine all the operations and display
-        plt.savefig(node_type+'_stats_monitor.png')
-        plt.show()
+            #save as png
+            plt.savefig(node_type+'_stats_monitor_'+page+'.png')
 
 
 if __name__ == "__main__":
@@ -88,7 +113,7 @@ if __name__ == "__main__":
     mon=StatMonitor(cfg_filename)
 
     #collecting stats when modem process is stopped
-    CMD='ps aux | grep mode | grep -v grep'
+    CMD='ps aux | grep modem | grep -v grep'
     process=subprocess.Popen(CMD, shell=True, stdout=subprocess.PIPE)
     output = process.stdout.readlines()
     while len(output)!=0 :

ci-scripts/stats_monitor_conf.yaml

@@ -3,9 +3,49 @@ enb :
   bler:
   mcsoff:
   mcs:
+  graph:
+    page1:
+      PHR:
+      bler:
+      mcsoff:
+      mcs:      
 
 gnb :
   dlsch_err:
   dlsch_err_perc_round_1:
   ulsch_err:
   ulsch_err_perc_round_1:
+  rt :
+    feprx:
+    feptx_prec:
+    feptx_ofdm:
+    feptx_total:
+    L1 Tx processing thread 0:
+    L1 Tx processing thread 1:
+    DLSCH encoding:
+    L1 Rx processing:
+    PUSCH inner-receiver:
+    PUSCH decoding:
+    DL & UL scheduling timing stats:
+    UL Indication:
+  graph : 
+    page1:
+      dlsch_err:
+      dlsch_err_perc_round_1:
+      ulsch_err:
+      ulsch_err_perc_round_1:
+    page2:    
+      rt.feprx:
+      rt.feptx_prec:
+      rt.feptx_ofdm:
+      rt.feptx_total:
+    page3:
+      rt.L1 Tx processing thread 0:
+      rt.L1 Tx processing thread 1:
+      rt.DLSCH encoding:
+      rt.L1 Rx processing:
+    page4:
+      rt.PUSCH inner-receiver:
+      rt.PUSCH decoding:
+      rt.DL & UL scheduling timing stats:
+      rt.UL Indication:
\ No newline at end of file

executables/nr-gnb.c

@@ -108,6 +108,7 @@ time_stats_t softmodem_stats_rx_sf; // total rx time
 
 //#define TICK_TO_US(ts) (ts.diff)
 #define TICK_TO_US(ts) (ts.trials==0?0:ts.diff/ts.trials)
+#define L1STATSSTRLEN 16384
 
 
 void tx_func(void *param) {
@@ -329,46 +330,63 @@ void rx_func(void *param) {
        );
 #endif
 }
-static void *process_stats_thread(void *param) {
-
-  PHY_VARS_gNB *gNB  = (PHY_VARS_gNB *)param;
+static void dump_L1_meas_stats(PHY_VARS_gNB *gNB, RU_t *ru, char *output) {
+  int stroff = 0;
+  stroff += print_meas_log(gNB->phy_proc_tx_0, "L1 Tx processing thread 0", NULL, NULL, output);
+  stroff += print_meas_log(gNB->phy_proc_tx_1, "L1 Tx processing thread 1", NULL, NULL, output+stroff);
+  stroff += print_meas_log(&gNB->dlsch_encoding_stats, "DLSCH encoding", NULL, NULL, output+stroff);
+  stroff += print_meas_log(&gNB->phy_proc_rx, "L1 Rx processing", NULL, NULL, output+stroff);
+  stroff += print_meas_log(&gNB->ul_indication_stats, "UL Indication", NULL, NULL, output+stroff);
+  stroff += print_meas_log(&gNB->rx_pusch_stats, "PUSCH inner-receiver", NULL, NULL, output+stroff);
+  stroff += print_meas_log(&gNB->ulsch_decoding_stats, "PUSCH decoding", NULL, NULL, output+stroff);
+  if (ru->feprx) stroff += print_meas_log(&ru->ofdm_demod_stats,"feprx",NULL,NULL, output+stroff);
+
+  if (ru->feptx_ofdm) {
+    stroff += print_meas_log(&ru->precoding_stats,"feptx_prec",NULL,NULL, output+stroff);
+    stroff += print_meas_log(&ru->txdataF_copy_stats,"txdataF_copy",NULL,NULL, output+stroff);
+    stroff += print_meas_log(&ru->ofdm_mod_stats,"feptx_ofdm",NULL,NULL, output+stroff);
+    stroff += print_meas_log(&ru->ofdm_total_stats,"feptx_total",NULL,NULL, output+stroff);
+  }
 
-  reset_meas(&gNB->dlsch_encoding_stats);
-  reset_meas(&gNB->phy_proc_rx);
-  reset_meas(&gNB->ul_indication_stats);
-  reset_meas(&gNB->rx_pusch_stats);
-  reset_meas(&gNB->ulsch_decoding_stats);
+  if (ru->fh_north_asynch_in) stroff += print_meas_log(&ru->rx_fhaul,"rx_fhaul",NULL,NULL, output+stroff);
 
-  wait_sync("process_stats_thread");
+  stroff += print_meas_log(&ru->tx_fhaul,"tx_fhaul",NULL,NULL, output+stroff);
 
-  while(!oai_exit)
-  {
-    sleep(1);
-    print_meas(gNB->phy_proc_tx_0, "L1 Tx processing thread 0", NULL, NULL);
-    print_meas(gNB->phy_proc_tx_1, "L1 Tx processing thread 1", NULL, NULL);
-    print_meas(&gNB->dlsch_encoding_stats, "DLSCH encoding", NULL, NULL);
-    print_meas(&gNB->phy_proc_rx, "L1 Rx processing", NULL, NULL);
-    print_meas(&gNB->ul_indication_stats, "UL Indication", NULL, NULL);
-    print_meas(&gNB->rx_pusch_stats, "PUSCH inner-receiver", NULL, NULL);
-    print_meas(&gNB->ulsch_decoding_stats, "PUSCH decoding", NULL, NULL);
+  if (ru->fh_north_out) {
+    stroff += print_meas_log(&ru->compression,"compression",NULL,NULL, output+stroff);
+    stroff += print_meas_log(&ru->transport,"transport",NULL,NULL, output+stroff);
   }
-  return(NULL);
 }
 
 void *nrL1_stats_thread(void *param) {
   PHY_VARS_gNB     *gNB      = (PHY_VARS_gNB *)param;
+  RU_t *ru = RC.ru[0];
+  char output[L1STATSSTRLEN];
+  memset(output,0,L1STATSSTRLEN);
   wait_sync("L1_stats_thread");
   FILE *fd;
-  while (!oai_exit) {
-    sleep(1);
   fd=fopen("nrL1_stats.log","w");
   AssertFatal(fd!=NULL,"Cannot open nrL1_stats.log\n");
+
+  reset_meas(gNB->phy_proc_tx_0);
+  reset_meas(gNB->phy_proc_tx_1);
+  reset_meas(&gNB->dlsch_encoding_stats);
+  reset_meas(&gNB->phy_proc_rx);
+  reset_meas(&gNB->ul_indication_stats);
+  reset_meas(&gNB->rx_pusch_stats);
+  reset_meas(&gNB->ulsch_decoding_stats);
+
+  while (!oai_exit) {
+    sleep(1);
     dump_nr_I0_stats(fd,gNB);
     dump_pdsch_stats(fd,gNB);
     dump_pusch_stats(fd,gNB);
-    //    nr_dump_uci_stats(fd,eNB,eNB->proc.L1_proc_tx.frame_tx);
-    fclose(fd);
+    dump_L1_meas_stats(gNB, ru, output);
+    fprintf(fd,"%s\n",output);
+    fflush(fd);
+    fseek(fd,0,SEEK_SET);
   }
+  fclose(fd);
   return(NULL);
 }
 
@@ -432,8 +450,6 @@ void init_gNB_Tpool(int inst) {
   msgData->next_slot = sf_ahead*gNB->frame_parms.slots_per_subframe; // first Tx slot
   pushNotifiedFIFO(gNB->resp_RU_tx,msgRUTx); // to unblock the process in the beginning
 
-  // Stats measurement thread
-  if(opp_enabled == 1) threadCreate(&proc->process_stats_thread, process_stats_thread,(void *)gNB, "time_meas", -1, OAI_PRIORITY_RT_LOW);
   threadCreate(&proc->L1_stats_thread,nrL1_stats_thread,(void*)gNB,"L1_stats",-1,OAI_PRIORITY_RT_LOW);
 
 }

executables/nr-ru.c

@@ -1508,7 +1508,6 @@ void init_RU_proc(RU_t *ru) {
     if (ru->feptx_ofdm) nr_init_feptx_thread(ru);
   }
 
-  if (opp_enabled == 1) threadCreate(&ru->ru_stats_thread,ru_stats_thread,(void *)ru, "emulateRF", -1, OAI_PRIORITY_RT_LOW);
 }
 
 void kill_NR_RU_proc(int inst) {

openair1/PHY/TOOLS/time_meas.c

@@ -131,6 +131,49 @@ void print_meas(time_stats_t *ts,
   }
 }
 
+int print_meas_log(time_stats_t *ts,
+                const char *name,
+                time_stats_t *total_exec_time,
+                time_stats_t *sf_exec_time,
+                char *output)
+{
+  int stroff = 0;
+  static int first_time = 0;
+  static double cpu_freq_GHz = 0.0;
+
+  if (cpu_freq_GHz == 0.0)
+    cpu_freq_GHz = get_cpu_freq_GHz();
+
+  if (first_time == 0) {
+    first_time=1;
+
+    if ((total_exec_time == NULL) || (sf_exec_time== NULL))
+      stroff += sprintf(output, "%25s  %25s  %25s  %25s %25s %6f\n","Name","Total","Per Trials",   "Num Trials","CPU_F_GHz", cpu_freq_GHz);
+    else
+      stroff += sprintf(output+stroff, "%25s  %25s  %25s  %20s %15s %6f\n","Name","Total","Average/Frame","Trials",    "CPU_F_GHz", cpu_freq_GHz);
+  }
+
+  if (ts->trials>0) {
+    //printf("%20s: total: %10.3f ms, average: %10.3f us (%10d trials)\n", name, ts->diff/cpu_freq_GHz/1000000.0, ts->diff/ts->trials/cpu_freq_GHz/1000.0, ts->trials);
+    if ((total_exec_time == NULL) || (sf_exec_time== NULL)) {
+      stroff += sprintf(output+stroff, "%25s:  %15.3f us; %15d; %15.3f us;\n",
+              name,
+              (ts->diff/ts->trials/cpu_freq_GHz/1000.0),
+              ts->trials,
+              ts->max/cpu_freq_GHz/1000.0);
+    } else {
+      stroff += sprintf(output+stroff, "%25s:  %15.3f ms (%5.2f%%); %15.3f us (%5.2f%%); %15d;\n",
+              name,
+              (ts->diff/cpu_freq_GHz/1000000.0),
+              ((ts->diff/cpu_freq_GHz/1000000.0)/(total_exec_time->diff/cpu_freq_GHz/1000000.0))*100,  // percentage
+              (ts->diff/ts->trials/cpu_freq_GHz/1000.0),
+              ((ts->diff/ts->trials/cpu_freq_GHz/1000.0)/(sf_exec_time->diff/sf_exec_time->trials/cpu_freq_GHz/1000.0))*100,  // percentage
+              ts->trials);
+    }
+  }
+  return stroff;
+}
+
 double get_time_meas_us(time_stats_t *ts)
 {
   static double cpu_freq_GHz = 0.0;

openair1/PHY/TOOLS/time_meas.h

@@ -88,6 +88,7 @@ static inline void stop_meas(time_stats_t *ts) __attribute__((always_inline));
 
 void print_meas_now(time_stats_t *ts, const char *name, FILE *file_name);
 void print_meas(time_stats_t *ts, const char *name, time_stats_t *total_exec_time, time_stats_t *sf_exec_time);
+int print_meas_log(time_stats_t *ts, const char *name, time_stats_t *total_exec_time, time_stats_t *sf_exec_time, char *output);
 double get_time_meas_us(time_stats_t *ts);
 double get_cpu_freq_GHz(void);
 

openair2/LAYER2/NR_MAC_gNB/main.c

@@ -121,7 +121,7 @@ void dump_mac_stats(gNB_MAC_INST *gNB, char *output, int strlen)
       }
     }
   }
-  print_meas(&gNB->eNB_scheduler, "DL & UL scheduling timing stats", NULL, NULL);
+  print_meas_log(&gNB->eNB_scheduler, "DL & UL scheduling timing stats", NULL, NULL, output+stroff);
 }