diff --git a/devicemodel/tools/acrntrace/scripts/acrnalyze.py b/devicemodel/tools/acrntrace/scripts/acrnalyze.py new file mode 100755 index 000000000..1678da7a4 --- /dev/null +++ b/devicemodel/tools/acrntrace/scripts/acrnalyze.py @@ -0,0 +1,107 @@ +#!/usr/bin/python2 +# -*- coding: UTF-8 -*- + +""" +This is the main script of arnalyzer, which: +- parse the options +- pre-process the trace data file +- call a specific script to do analysis +""" + +import sys +import getopt +import os +from vmexit_analyze import analyze_vm_exit + +def usage(): + """print the usage of the script + Args: NA + Returns: None + Raises: NA + """ + print ''' + [Usage] acrnalyze.py [options] [value] ... + + [options] + -h: print this message + -i, --ifile=[string]: input file + -o, --ofile=[string]: output file + --vm_exit: to generate vm_exit report + ''' + +def do_analysis(ifile, ofile, analyzer): + """do the specific analysis + + Args: + ifile: input trace data file + ofile: output analysis report file + analyzer: a function do the specific analysis + Returns: + None + Raises: + NA + """ + analyzer(ifile, ofile) + +# pre process to make sure the trace data start and end with VMENTER +def pre_process(ifile, evstr): + """invoke sh script to preprocess the data file + + Args: + ifile: input trace data file + evstr: event string, after the processing, the data file should + start and end with the string + Returns: + status of sh script execution + Raises: + NA + """ + status = os.system('bash pre_process.sh %s %s' % (ifile, evstr)) + return status + +def main(argv): + """Main enterance function + + Args: + argv: arguments string + Returns: + None + Raises: + GetoptError + """ + inputfile = '' + outputfile = '' + opts_short = "hi:o:" + opts_long = ["ifile=", "ofile=", "vm_exit"] + + try: + opts, args = getopt.getopt(argv, opts_short, opts_long) + except getopt.GetoptError: + usage() + sys.exit(1) + + for opt, arg in opts: + if opt == '-h': + usage() + sys.exit() + elif opt in ("-i", "--ifile"): + inputfile = arg + elif opt in ("-o", "--ofile"): + outputfile = arg + elif opt == "--vm_exit": + analyzer = analyze_vm_exit + else: + assert False, "unhandled option" + + assert inputfile != '', "input file is required" + assert outputfile != '', "output file is required" + assert analyzer != '', 'MUST contain one of analyzer: ''vm_exit' + + status = pre_process(inputfile, 'VM_ENTER') + if status == 0: + do_analysis(inputfile, outputfile, analyzer) + else: + print "Invalid trace data file %s" % (inputfile) + +if __name__ == "__main__": + main(sys.argv[1:]) diff --git a/devicemodel/tools/acrntrace/scripts/pre_process.sh b/devicemodel/tools/acrntrace/scripts/pre_process.sh new file mode 100755 index 000000000..80245c288 --- /dev/null +++ b/devicemodel/tools/acrntrace/scripts/pre_process.sh @@ -0,0 +1,33 @@ +#!/bin/bash + +IFILE=$1 +STR=$2 +BAK_FILE=${IFILE}.orig + +if [ ! -f $BAK_FILE ]; then + cp $IFILE $BAK_FILE +fi + +echo $IFILE, $BAK_FILE, $STR + +FIRST_LINE=$(grep -n $STR -m 1 $IFILE | awk -F: '{print $1}') +LAST_LINE=$(grep -n $STR $IFILE | tail -1 | awk -F: '{print $1}') +TOTAL_LINE=$(wc -l $IFILE | awk '{print $1}') + +echo $FIRST_LINE, $LAST_LINE, $TOTAL_LINE + +if [[ $FIRST_LINE -ge $LAST_LINE || $LAST_LINE -gt $TOTAL_LINE ]]; then + exit 1 +fi + +if [[ $LAST_LINE -lt $TOTAL_LINE ]]; then + let LAST_LINE=$((LAST_LINE))+1 + echo "sed -i ${LAST_LINE},${TOTAL_LINE}d $IFILE" + sed -i ${LAST_LINE}','${TOTAL_LINE}'d' $IFILE +fi + +if [[ $FIRST_LINE -gt 2 ]]; then + let FIRST_LINE=$((FIRST_LINE))-1 + echo "sed -i 2,${FIRST_LINE}d $IFILE" + sed -i '2,'${FIRST_LINE}'d' $IFILE +fi diff --git a/devicemodel/tools/acrntrace/scripts/vmexit_analyze.py b/devicemodel/tools/acrntrace/scripts/vmexit_analyze.py new file mode 100755 index 000000000..b8aa0e57b --- /dev/null +++ b/devicemodel/tools/acrntrace/scripts/vmexit_analyze.py @@ -0,0 +1,274 @@ +#!/usr/bin/python2 +# -*- coding: UTF-8 -*- + +""" +This script defines the function to do the vm_exit analysis +""" + +import csv + +TSC_BEGIN = 0L +TSC_END = 0L +TOTAL_NR_EXITS = 0L + +LIST_EVENTS = [ + 'VMEXIT_EXCEPTION_OR_NMI', + 'VMEXIT_EXTERNAL_INTERRUPT', + 'VMEXIT_INTERRUPT_WINDOW', + 'VMEXIT_CPUID', + 'VMEXIT_RDTSC', + 'VMEXIT_VMCALL', + 'VMEXIT_CR_ACCESS', + 'VMEXIT_IO_INSTRUCTION', + 'VMEXIT_RDMSR', + 'VMEXIT_WRMSR', + 'VMEXIT_APICV_ACCESS', + 'VMEXIT_APICV_VIRT_EOI', + 'VMEXIT_EPT_VIOLATION', + 'VMEXIT_EPT_VIOLATION_GVT', + 'VMEXIT_EPT_MISCONFIGURATION', + 'VMEXIT_RDTSCP', + 'VMEXIT_APICV_WRITE', + 'VMEXIT_UNHANDLED' +] + +NR_EXITS = { + 'VM_EXIT': 0, + 'VM_ENTER': 0, + 'VMEXIT_EXCEPTION_OR_NMI': 0, + 'VMEXIT_EXTERNAL_INTERRUPT': 0, + 'VMEXIT_INTERRUPT_WINDOW': 0, + 'VMEXIT_CPUID': 0, + 'VMEXIT_RDTSC': 0, + 'VMEXIT_VMCALL': 0, + 'VMEXIT_CR_ACCESS': 0, + 'VMEXIT_IO_INSTRUCTION': 0, + 'VMEXIT_RDMSR': 0, + 'VMEXIT_WRMSR': 0, + 'VMEXIT_APICV_ACCESS': 0, + 'VMEXIT_APICV_VIRT_EOI': 0, + 'VMEXIT_EPT_VIOLATION': 0, + 'VMEXIT_EPT_VIOLATION_GVT': 0, + 'VMEXIT_EPT_MISCONFIGURATION': 0, + 'VMEXIT_RDTSCP': 0, + 'VMEXIT_APICV_WRITE': 0, + 'VMEXIT_UNHANDLED': 0 +} + +TIME_IN_EXIT = { + 'VM_EXIT': 0, + 'VM_ENTER': 0, + 'VMEXIT_EXCEPTION_OR_NMI': 0, + 'VMEXIT_EXTERNAL_INTERRUPT': 0, + 'VMEXIT_INTERRUPT_WINDOW': 0, + 'VMEXIT_CPUID': 0, + 'VMEXIT_RDTSC': 0, + 'VMEXIT_VMCALL': 0, + 'VMEXIT_CR_ACCESS': 0, + 'VMEXIT_IO_INSTRUCTION': 0, + 'VMEXIT_RDMSR': 0, + 'VMEXIT_WRMSR': 0, + 'VMEXIT_APICV_ACCESS': 0, + 'VMEXIT_APICV_VIRT_EOI': 0, + 'VMEXIT_EPT_VIOLATION': 0, + 'VMEXIT_EPT_VIOLATION_GVT': 0, + 'VMEXIT_EPT_MISCONFIGURATION': 0, + 'VMEXIT_RDTSCP': 0, + 'VMEXIT_APICV_WRITE': 0, + 'VMEXIT_UNHANDLED': 0 +} + +IRQ_EXITS = {} + +def count_irq(info): + vec = info[5:15] + if IRQ_EXITS.has_key(vec): + IRQ_EXITS[vec] += 1 + else: + IRQ_EXITS[vec] = 1 + +def parse_trace_data(ifile): + """parse the trace data file + Args: + ifile: input trace data file + Return: + None + """ + global TSC_BEGIN, TSC_END, TOTAL_NR_EXITS + tsc_enter = 0L + tsc_exit = 0L + tsc_last_exit_period = 0L + + ev_id = '' + last_ev_id = '' + + try: + ifp = open(ifile) + + line = ifp.readline() + + # should preprocess to make sure first event is VM_ENTER + while 1: + line = ifp.readline() + if line == '': + ifp.close() + break + + try: + (cpuid, tsc, payload) = line.split(" | ") + + (ev_id, info) = payload.split(":") + + except ValueError, execp: + print execp + print line + continue + + if ev_id == 'VM_ENTER': + if TSC_BEGIN == 0: + TSC_BEGIN = long(tsc) + tsc_exit = long(tsc) + TOTAL_NR_EXITS = 0 + + tsc_enter = long(tsc) + TSC_END = tsc_enter + tsc_last_exit_period = tsc_enter - tsc_exit + if tsc_last_exit_period != 0: + TIME_IN_EXIT[last_ev_id] += tsc_last_exit_period + elif ev_id == 'VM_EXIT': + tsc_exit = long(tsc) + TSC_END = tsc_exit + TOTAL_NR_EXITS += 1 + elif ev_id.startswith('VMEXIT_'): + if (ev_id == 'VMEXIT_EPT_VIOLATION' + and (eval(info[6:24]) & 0x38) == 0x28): + ev_id = 'VMEXIT_EPT_VIOLATION_GVT' + + if ev_id.startswith('VMEXIT_EX'): + count_irq(info) + + NR_EXITS[ev_id] += 1 + last_ev_id = ev_id + else: + # skip the non-VMEXIT trace event + pass + + except IOError as err: + print "Input File Error: " + str(err) + + finally: + if 'ifp' in locals(): + ifp.close() + +def generate_report(ofile, freq): + """ generate analysis report + Args: + ofile: output report + freq: CPU frequency of the device trace data from + Return: + None + """ + global TSC_BEGIN, TSC_END, TOTAL_NR_EXITS + + csv_name = ofile + '.csv' + try: + with open(csv_name, 'w') as filep: + f_csv = csv.writer(filep) + + total_exit_time = 0L + rt_cycle = TSC_END - TSC_BEGIN + assert rt_cycle != 0, "total_run_time in cycle is 0,\ + tsc_end %d, tsc_begin %d"\ + % (TSC_END, TSC_BEGIN) + + rt_sec = float(rt_cycle) / (float(freq) * 1000 * 1000) + + for event in LIST_EVENTS: + total_exit_time += TIME_IN_EXIT[event] + + print "Total run time: %d (cycles)" % (rt_cycle) + print "CPU Freq: %f MHz)" % (freq) + print "Total run time %d (Sec)" % (rt_sec) + + f_csv.writerow(['Run time(cycles)', 'Run time(Sec)', 'Freq(MHz)']) + f_csv.writerow(['%d' % (rt_cycle), + '%.3f' % (rt_sec), + '%d' % (freq)]) + + print "Event \tNR_Exit \tNR_Exit/Sec \tTime Consumed \tTime Percentage" + f_csv.writerow(['Exit_Reason', + 'NR_Exit', + 'NR_Exit/Sec', + 'Time Consumed(cycles)', + 'Time Percentage']) + + for event in LIST_EVENTS: + ev_freq = float(NR_EXITS[event]) / rt_sec + pct = float(TIME_IN_EXIT[event]) * 100 / float(rt_cycle) + + print ("%s \t%d \t%.2f \t%d \t%2.2f" % + (event, NR_EXITS[event], ev_freq, TIME_IN_EXIT[event], pct)) + row = [event, NR_EXITS[event], '%.2f' % ev_freq, TIME_IN_EXIT[event], + '%2.2f' % (pct)] + f_csv.writerow(row) + + ev_freq = float(TOTAL_NR_EXITS) / rt_sec + pct = float(total_exit_time) * 100 / float(rt_cycle) + print("Total \t%d \t%.2f \t%d \t%2.2f" + % (TOTAL_NR_EXITS, ev_freq, total_exit_time, pct)) + row = ["Total", TOTAL_NR_EXITS, '%.2f' % ev_freq, total_exit_time, + '%2.2f' % (pct)] + f_csv.writerow(row) + + # insert a empty row to separate two tables + f_csv.writerow(['']) + + print "\nVector \t\tCount \tNR_Exit/Sec" + f_csv.writerow(['Vector', 'NR_Exit', 'NR_Exit/Sec']) + for e in IRQ_EXITS.keys(): + pct = float(IRQ_EXITS[e]) / rt_sec + print "%s \t %d \t%.2f" % (e,IRQ_EXITS[e], pct) + f_csv.writerow([e, IRQ_EXITS[e], '%.2f' % pct]) + + except IOError as err: + print "Output File Error: " + str(err) + +def get_freq(ifile): + """ get cpu freq from the first line of trace file + Args: + ifile: input trace data file + Return: + cpu frequency + """ + try: + ifp = open(ifile) + line = ifp.readline() + freq = float(line[10:]) + + except IOError as err: + print "Failed to get cpu freq" + freq = 1920.00 + + finally: + if 'ifp' in locals(): + ifp.close() + + return freq + +def analyze_vm_exit(ifile, ofile): + """do the vm exits analysis + Args: + ifile: input trace data file + ofile: output report file + Return: + None + """ + + print("VM exits analysis started... \n\tinput file: %s\n" + "\toutput file: %s.csv" % (ifile, ofile)) + + freq = get_freq(ifile) + + parse_trace_data(ifile) + # save report to the output file + generate_report(ofile, freq)