diff --git a/ci-scripts/cls_oaicitest.py b/ci-scripts/cls_oaicitest.py index 92a4e8637e..0423828650 100644 --- a/ci-scripts/cls_oaicitest.py +++ b/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 diff --git a/ci-scripts/epc.py b/ci-scripts/epc.py index 8376e07fd5..b8c2050793 100644 --- a/ci-scripts/epc.py +++ b/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 = '' diff --git a/ci-scripts/ran.py b/ci-scripts/ran.py index 9acb1de34e..a9e5aa236a 100644 --- a/ci-scripts/ran.py +++ b/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' diff --git a/ci-scripts/stats_monitor.py b/ci-scripts/stats_monitor.py index 877194de59..933bf13203 100755 --- a/ci-scripts/stats_monitor.py +++ b/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): - col = 1 - figure, axis = plt.subplots(len(self.d[node_type]), 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) - axis[i].set_xticks(major_ticks) - axis[i].set_xticklabels([]) - axis[i].plot(self.d[node_type][metric],marker='o') - axis[i].set_xlabel('time') - axis[i].set_ylabel(metric) - axis[i].set_title(metric) - i+=1 + 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]['graph'][page]), col ,figsize=(10, 10)) + i=0 + 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_l1][metric_l2],marker='o') + axis[i].set_xlabel('time') + 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() + plt.tight_layout() + #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 : diff --git a/ci-scripts/stats_monitor_conf.yaml b/ci-scripts/stats_monitor_conf.yaml index 6c0a2b0225..8760c067fc 100644 --- a/ci-scripts/stats_monitor_conf.yaml +++ b/ci-scripts/stats_monitor_conf.yaml @@ -2,10 +2,50 @@ enb : PHR: bler: mcsoff: - mcs: + mcs: + graph: + page1: + PHR: + bler: + mcsoff: + mcs: gnb : dlsch_err: dlsch_err_perc_round_1: ulsch_err: - ulsch_err_perc_round_1: \ No newline at end of file + 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 diff --git a/executables/nr-gnb.c b/executables/nr-gnb.c index d659739ffa..d87bf91561 100644 --- a/executables/nr-gnb.c +++ b/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) { +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); - PHY_VARS_gNB *gNB = (PHY_VARS_gNB *)param; + 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); + } + if (ru->fh_north_asynch_in) stroff += print_meas_log(&ru->rx_fhaul,"rx_fhaul",NULL,NULL, output+stroff); + + stroff += print_meas_log(&ru->tx_fhaul,"tx_fhaul",NULL,NULL, output+stroff); + + 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); + } +} + +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; + 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); - wait_sync("process_stats_thread"); - - 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); - } - return(NULL); -} - -void *nrL1_stats_thread(void *param) { - PHY_VARS_gNB *gNB = (PHY_VARS_gNB *)param; - 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"); 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); } diff --git a/executables/nr-ru.c b/executables/nr-ru.c index c90750d39a..3a2589632b 100644 --- a/executables/nr-ru.c +++ b/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) { diff --git a/openair1/PHY/TOOLS/time_meas.c b/openair1/PHY/TOOLS/time_meas.c index c62fbed106..996f7fb277 100644 --- a/openair1/PHY/TOOLS/time_meas.c +++ b/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; diff --git a/openair1/PHY/TOOLS/time_meas.h b/openair1/PHY/TOOLS/time_meas.h index f78ea55530..1ef2935917 100644 --- a/openair1/PHY/TOOLS/time_meas.h +++ b/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); diff --git a/openair2/LAYER2/NR_MAC_gNB/main.c b/openair2/LAYER2/NR_MAC_gNB/main.c index 6e13e4bcc6..af386163e9 100644 --- a/openair2/LAYER2/NR_MAC_gNB/main.c +++ b/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); }