acrn-hypervisor/misc/tools/acrntrace/scripts/vmexit_analyze.py
Kaige Fu 366f4be454 acrntrace: Use correct format for total run time
It is better to output it using float instead of int. Otherwise, we will
get '0 sec' for total run time if it is less than one second.

Tracked-On: #4175
Acked-by: Yan, Like <like.yan@intel.com>
Signed-off-by: Kaige Fu <kaige.fu@intel.com>
2019-12-10 15:11:12 +08:00

229 lines
7.1 KiB
Python
Executable File

#!/usr/bin/python3
# -*- coding: UTF-8 -*-
"""
This script defines the function to do the vm_exit analysis
"""
import csv
import struct
TSC_BEGIN = 0
TSC_END = 0
TOTAL_NR_EXITS = 0
VM_EXIT = 0x10
VM_ENTER = 0x11
VMEXIT_ENTRY = 0x10000
LIST_EVENTS = {
'VMEXIT_EXCEPTION_OR_NMI': VMEXIT_ENTRY + 0x00000000,
'VMEXIT_EXTERNAL_INTERRUPT': VMEXIT_ENTRY + 0x00000001,
'VMEXIT_INTERRUPT_WINDOW': VMEXIT_ENTRY + 0x00000002,
'VMEXIT_CPUID': VMEXIT_ENTRY + 0x00000004,
'VMEXIT_RDTSC': VMEXIT_ENTRY + 0x00000010,
'VMEXIT_VMCALL': VMEXIT_ENTRY + 0x00000012,
'VMEXIT_CR_ACCESS': VMEXIT_ENTRY + 0x0000001C,
'VMEXIT_IO_INSTRUCTION': VMEXIT_ENTRY + 0x0000001E,
'VMEXIT_RDMSR': VMEXIT_ENTRY + 0x0000001F,
'VMEXIT_WRMSR': VMEXIT_ENTRY + 0x00000020,
'VMEXIT_EPT_VIOLATION': VMEXIT_ENTRY + 0x00000030,
'VMEXIT_EPT_MISCONFIGURATION': VMEXIT_ENTRY + 0x00000031,
'VMEXIT_RDTSCP': VMEXIT_ENTRY + 0x00000033,
'VMEXIT_APICV_WRITE': VMEXIT_ENTRY + 0x00000038,
'VMEXIT_APICV_ACCESS': VMEXIT_ENTRY + 0x00000039,
'VMEXIT_APICV_VIRT_EOI': VMEXIT_ENTRY + 0x0000003A,
'VMEXIT_UNHANDLED': 0x20000
}
NR_EXITS = {
'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_MISCONFIGURATION': 0,
'VMEXIT_RDTSCP': 0,
'VMEXIT_APICV_WRITE': 0,
'VMEXIT_UNHANDLED': 0
}
TIME_IN_EXIT = {
'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_MISCONFIGURATION': 0,
'VMEXIT_RDTSCP': 0,
'VMEXIT_APICV_WRITE': 0,
'VMEXIT_UNHANDLED': 0
}
# 4 * 64bit per trace entry
TRCREC = "QQQQ"
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
last_ev_id = ''
tsc_exit = 0
fd = open(ifile, 'rb')
# The duration of one vmexit is tsc_enter - tsc_exit
# Here we should find the first vmexit and ignore other entries on top of the first vmexit
while True:
try:
line = fd.read(struct.calcsize(TRCREC))
if not line:
break
(tsc, event, d1, d2) = struct.unpack(TRCREC, line)
event = event & 0xffffffffffff
if event != VM_EXIT:
continue
# We found the first vmexit and should seek back one line as we will read it in the following loop
TSC_BEGIN = tsc
fd.seek(fd.tell() - len(line))
break
except (IOError, struct.error) as e:
sys.exit()
while True:
try:
line = fd.read(struct.calcsize(TRCREC))
if not line:
break
(tsc, event, d1, d2) = struct.unpack(TRCREC, line)
event = event & 0xffffffffffff
if event == VM_ENTER:
TSC_END = tsc
# Found one vmenter in pair with the last vmexit
TIME_IN_EXIT[last_ev_id] += tsc - tsc_exit
elif event == VM_EXIT:
tsc_exit = tsc
TOTAL_NR_EXITS += 1
else:
for key in LIST_EVENTS.keys():
if event == LIST_EVENTS.get(key):
NR_EXITS[key] += 1
last_ev_id = key
break
else:
# Skip the non-VMEXIT trace event
pass
except (IOError, struct.error) as e:
sys.exit()
def generate_report(ofile, freq):
""" generate analysis report
Args:
ofile: output report
freq: TSC 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, 'a') as filep:
f_csv = csv.writer(filep)
total_exit_time = 0
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 ("TSC Freq: %s MHz" % (freq))
print ("Total run time: %.6f sec" % (rt_sec))
f_csv.writerow(['Run time(cycles)', 'Run time(Sec)', 'Freq(MHz)'])
f_csv.writerow(['%d' % (rt_cycle),
'%.3f' % (rt_sec),
'%s' % (freq)])
print ("%-28s\t%-12s\t%-12s\t%-24s\t%-16s" % ("Event", "NR_Exit",
"NR_Exit/Sec", "Time Consumed(cycles)", "Time 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 ("%-28s\t%-12d\t%-12.2f\t%-24d\t%-16.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("%-28s\t%-12d\t%-12.2f\t%-24d\t%-16.2f"
% ("Total", 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)
except IOError as err:
print ("Output File Error: " + str(err))
def analyze_vm_exit(ifile, ofile, freq):
"""do the vm exits analysis
Args:
ifile: input trace data file
ofile: output report file
freq: TSC frequency of the host where we capture the trace data
Return:
None
"""
print("VM exits analysis started... \n\tinput file: %s\n"
"\toutput file: %s.csv" % (ifile, ofile))
parse_trace_data(ifile)
# save report to the output file
generate_report(ofile, freq)