DM:tools: add scripts for VM exit analysis

Script usage:
[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

Note: bash and python2 are required.

Example:
Assumed trace data have been copied to /home/xxxx/trace_data/20171115-101605
 # acrnalyze.py -i /home/xxxx/trace_data/20171115-101605/0 -o /home/xxxx/trac
   e_data/20171115-101605/cpu0 --vm_exit

 - "--vm_exit" specify the analysis to do, currently, only vm_exit analysis
   is supported.
 - A preprocess would be taken out to make the trace data start and end with
   an VM_ENTER, and a copy of original data file is saved with suffix ".orig";
 - Analysis report would be given on the std output and in a csv file with
   name specified via "-o outpu_file";

Reviewed-by: Zhao Yakui <yakui.zhao@intel.com>
Signed-off-by: Yan, Like <like.yan@intel.com>
Acked-by: Eddie Dong <eddie.dong@intel.com>

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:])

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

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)