def init_env(self, delete=False):
if delete:
if os.path.exists(self._dir):
shutil.rmtree(self._dir, ignore_errors=True)
os.makedirs(self._dir, exist_ok=True)
if ORIG_QEMU != TMP_QEMU:
shutil.copyfile(ORIG_QEMU, TMP_QEMU)
root_logger = logging.getLogger()
root_logger.addHandler(
logging.FileHandler(os.path.join(self._dir, "log")))
self.trace_parser = Traces(self._dir)
def parse_results2(directory):
traces = Traces(get_dir(directory))
events = traces.get_test_events()
guest_run_time = 0
hist = Counter()
for event1, event2 in zip(events[:-1], events[1:]):
if event1.event == 'kvm_entry':
entry_event = event1
elif event1.event == 'kvm_exit':
exit_event = event1
delta = exit_event.timestamp - entry_event.timestamp
hist.update((int(log2(delta)), ))
guest_run_time += delta
return hist, guest_run_time
def analysie_exit(trace: Traces, dirname):
TYPE = "type"
DURATION = "duration"
ADDR = "addr"
VALUE = "value"
START = "start"
END = "end"
with open(os.path.join(dirname, "exit_info.csv"), "w") as csvfile:
csvwriter = csv.DictWriter(csvfile,
(TYPE, DURATION, START, END, ADDR, VALUE))
csvwriter.writeheader()
current_event_info = defaultdict(lambda: 0)
for event in trace.get_test_events():
if event.event == "kvm_entry":
current_event_info[END] = int(event.timestamp)
current_event_info[DURATION] = current_event_info[
END] - current_event_info[START]
csvwriter.writerow(current_event_info)
current_event_info.clear()
elif event.event == "kvm_exit":
current_event_info[START] = int(event.timestamp)
current_event_info[TYPE] = event.info.split()[1]
elif event.event == "kvm_mmio":
current_event_info[ADDR] = event.info.split()[5]
current_event_info[VALUE] = event.info.split()[7]
def startup():
import sys
d = None
if len(sys.argv) > 1:
d = sys.argv[1]
d = get_dir(d)
os.makedirs(d, exist_ok=True)
root_logger = logging.getLogger()
root_logger.addHandler(logging.FileHandler(os.path.join(d, "log")))
main(d)
trace2csv(d)
t = Traces(d)
t.write_to_file(d, True)
def parse_results(directory):
traces = Traces(get_dir(directory))
events = traces.get_test_events()
guest_run_time = 0
hist = Counter()
for event1, event2 in zip(events[:-1], events[1:]):
# on entry, check the event after
if event1.event == 'kvm_entry':
if event2.event in ('notify_end', 'irq_handler_entry'):
entry_event = event1 # TODO: fix it to event2
else:
entry_event = event1
# on exit, check the event before
elif event2.event == 'kvm_exit':
if event1.event in ('notify_begin', 'cpu_idle'):
exit_event = event1
else:
exit_event = event2
delta = exit_event.timestamp - entry_event.timestamp
hist.update((int(log2(delta)), ))
guest_run_time += delta
return hist, guest_run_time
class TracePerformance:
def __init__(self,
vm: VM,
directory=None,
netperf=None,
msg_size=64,
title="",
auto_dir=False,
name=None):
self._vm = vm
if directory:
self._dir = directory
else:
self._dir = TMP_DIR
if auto_dir:
self._dir = os.path.join(
self._dir, "{name}-{size}".format(name=self._vm.name,
size=msg_size))
if name:
self._dir += "-{name}".format(name=name)
logger.info("Dir: %s", self._dir)
if netperf:
self._netperf = netperf
else:
self._netperf = NetPerfLatency()
self._msg_size = msg_size
self._title = title
# vm.netserver_core = "2"
self.trace_parser = None
self._host_tracer = None
self._guest_tracer = None
self._old_cpumask = ""
def init_env(self, delete=False):
if delete:
if os.path.exists(self._dir):
shutil.rmtree(self._dir, ignore_errors=True)
os.makedirs(self._dir, exist_ok=True)
if ORIG_QEMU != TMP_QEMU:
shutil.copyfile(ORIG_QEMU, TMP_QEMU)
root_logger = logging.getLogger()
root_logger.addHandler(
logging.FileHandler(os.path.join(self._dir, "log")))
self.trace_parser = Traces(self._dir)
def host_traces(self):
assert self._host_tracer is None
self._host_tracer = Trace(localRoot,
os.path.join(self._dir, "trace_host"))
self._host_tracer.setup()
self._host_tracer.set_buffer_size(2000000)
sleep(1)
# if self._vm.cpu_to_pin:
# self._host_tracer.write_value("tracing_cpumask", str(1 << (int(self._vm.cpu_to_pin))))
# clock sync with VM
self._host_tracer.enable_event("kvm/kvm_write_tsc_offset")
# interrupts
# self._host_tracer.enable_event("kvm/kvm_set_irq")
# self._host_tracer.enable_event("kvm/kvm_msi_set_irq")
# self._host_tracer.enable_event("kvm/kvm_inj_virq")
# self._host_tracer.enable_event("kvm/kvm_ioapic_set_irq")
# exit events
self._host_tracer.enable_event("kvm/kvm_exit")
self._host_tracer.enable_event("kvm/kvm_entry")
# self._host_tracer.enable_event("kvm/kvm_userspace_exit")
self._host_tracer.enable_event("kvm/kvm_mmio")
self._host_tracer.enable_event("kvm/kvm_msr")
# sched
self._host_tracer.set_event_filter(
"sched/sched_switch",
r'prev_comm ~ "*qemu*" || next_comm ~ "*qemu*"')
self._host_tracer.enable_event("sched/sched_switch")
# self._host_tracer.set_event_filter("sched/sched_wakeup", r'comm~"*qemu*"')
# self._host_tracer.enable_event("sched/sched_wakeup")
# self._host_tracer.set_event_filter("sched/sched_waking", r'comm~"*qemu*"')
# self._host_tracer.enable_event("sched/sched_waking")
# self._host_tracer.uprobe_add_event("p", "e1000_set_kick", self._vm.exe, "e1000_set_kick")
# self._host_tracer.uprobe_add_event("p", "e1000_kick_cb", self._vm.exe, "e1000_kick_cb")
# self._host_tracer.uprobe_add_event("p", "qemu_mutex_lock_iothread", self._vm.exe, "qemu_mutex_lock_iothread")
# self._host_tracer.uprobe_add_event("r", "qemu_mutex_lock_iothread_end", self._vm.exe, "qemu_mutex_lock_iothread")
# self._host_tracer.uprobe_add_event("p", "qemu_mutex_unlock_iothread", self._vm.exe, "qemu_mutex_unlock_iothread")
# self._host_tracer.uprobe_add_event("r", "qemu_mutex_unlock_iothread_end", self._vm.exe, "qemu_mutex_unlock_iothread")
self._host_tracer.enable_event("irq/irq_handler_entry")
self._host_tracer.enable_event("irq/irq_handler_exit")
self._host_tracer.enable_event("irq_vectors")
self._host_tracer.enable_event("syscalls")
# self._host_tracer.kprobe_add("p:import_iovec import_iovec")
# self._host_tracer.kprobe_add("r:import_iovec_end import_iovec")
# self._host_tracer.kprobe_add("p:tun_get_user tun_get_user")
# self._host_tracer.kprobe_add("r:tun_get_user_end tun_get_user")
#
# self._host_tracer.kprobe_add("p:netif_receive_skb netif_receive_skb")
# self._host_tracer.kprobe_add("r:netif_receive_skb_end netif_receive_skb")
# # self._host_tracer.enable_event("net/netif_receive_skb")
# # self._host_tracer.enable_event("net/netif_receive_skb_entry")
# # self._host_tracer.enable_event("net/netif_rx_ni_entry")
self._host_tracer.kprobe_enable()
self._host_tracer.uprobe_enable()
self._host_tracer.empty_trace()
self._host_tracer.trace_on()
def guest_traces(self):
assert self._guest_tracer is None
self._guest_tracer = Trace(self._vm.root,
os.path.join(self._dir, "trace_guest"))
self._guest_tracer.setup()
self._guest_tracer.set_buffer_size(600000)
self._guest_tracer.enable_event("power/cpu_idle")
self._guest_tracer.enable_event("syscalls/sys_enter_sendto")
# self._guest_tracer.enable_event("syscalls/sys_enter_recvfrom")
self._guest_tracer.enable_event("syscalls/sys_exit_recvfrom")
#sched
self._guest_tracer.set_event_filter(
"sched/sched_switch",
r'prev_comm ~ "*netperf*" || next_comm ~ "*netperf*"')
self._guest_tracer.enable_event("sched/sched_switch")
# net
self._guest_tracer.enable_event("net/net_dev_start_xmit")
self._guest_tracer.enable_event("net/net_dev_xmit")
self._guest_tracer.enable_event("net/net_dev_recv_start")
self._guest_tracer.enable_event("net/net_dev_recv_end")
self._guest_tracer.enable_event("net/net_exit_before")
self._guest_tracer.enable_event("net/net_exit_after")
# irq
self._guest_tracer.enable_event("irq/irq_handler_entry")
self._guest_tracer.enable_event("irq/irq_handler_exit")
self._host_tracer.enable_event("irq_vectors")
self._guest_tracer.enable_event("napi")
# self._guest_tracer.enable_event("tcp/tcp_xmit_break")
self._guest_tracer.kprobe_add("p:recv_start virtnet_receive")
self._guest_tracer.kprobe_add("r:recv_end virtnet_receive")
self._guest_tracer.kprobe_add("p:recv_start e1000_clean_rx_irq")
self._guest_tracer.kprobe_add("r:recv_end e1000_clean_rx_irq")
self._guest_tracer.kprobe_add("p:napi_receive_start napi_gro_receive")
self._guest_tracer.kprobe_add("r:napi_receive_end napi_gro_receive")
self._guest_tracer.kprobe_add(
"p:e1000_update_stats e1000_update_stats")
self._guest_tracer.kprobe_add(
"r:e1000_update_stats_end e1000_update_stats")
# recieve checksum validation
self._guest_tracer.kprobe_add("p:dev_gro_receive dev_gro_receive")
self._guest_tracer.kprobe_add("r:dev_gro_receive_end dev_gro_receive")
# tcp stack boundries
self._guest_tracer.kprobe_add(
"p:netif_receive_skb_internal netif_receive_skb_internal")
self._guest_tracer.kprobe_add(
"r:netif_receive_skb_internal_end netif_receive_skb_internal")
self._guest_tracer.kprobe_add(
"p:dev_hard_start_xmit dev_hard_start_xmit")
self._guest_tracer.kprobe_add(
"r:dev_hard_start_xmit_end dev_hard_start_xmit")
# self._guest_tracer.kprobe_add("p:ip_rcv_finish ip_rcv_finish")
# self._guest_tracer.kprobe_add("r:ip_rcv_finish_end ip_rcv_finish")
# self._guest_tracer.kprobe_add("p:tcp_write_xmit tcp_write_xmit")
# self._guest_tracer.kprobe_add("r:tcp_write_xmit_end tcp_write_xmit")
#
# self._guest_tracer.kprobe_add("p:dev_queue_xmit dev_queue_xmit")
# self._guest_tracer.kprobe_add("r:dev_queue_xmit_end dev_queue_xmit")
#
# self._guest_tracer.kprobe_add("p:tcp_v4_rcv tcp_v4_rcv")
# self._guest_tracer.kprobe_add("r:tcp_v4_rcv_end tcp_v4_rcv")
#
# for n in ("tcp_v4_do_rcv", "tcp_rcv_established", "__tcp_push_pending_frames", "tcp_write_xmit"):
# self._guest_tracer.kprobe_add("p:{name} {name}".format(name=n))
# self._guest_tracer.kprobe_add("r:{name}_end {name}".format(name=n))
# self._guest_tracer.kprobe_add("p:validate_xmit_skb_list validate_xmit_skb_list")
# self._guest_tracer.kprobe_add("r:validate_xmit_skb_list_end validate_xmit_skb_list")
# self._guest_tracer.kprobe_add("p:tcp_ack tcp_ack")
# self._guest_tracer.kprobe_add("r:tcp_ack_end tcp_ack")
# self._guest_tracer.write_value("current_tracer", "function_graph")
# self._guest_tracer.write_value("set_graph_function", "netif_receive_skb_internal")
self._guest_tracer.kprobe_enable()
self._guest_tracer.uprobe_enable()
self._guest_tracer.empty_trace()
self._guest_tracer.trace_on()
def run_netperf(self, runtime=None):
self._host_tracer.trace_marker(TRACE_BEGIN_MSG, cpu=2)
if runtime is not None:
self._netperf.runtime = runtime
netperf_perf = self._netperf.run_netperf(self._vm,
msg_size=self._msg_size)
self._host_tracer.trace_marker(TRACE_END_MSG, cpu=2)
print("Netperf performance: %s" % (netperf_perf, ))
logger.info("Netperf performance: %s", netperf_perf)
def copy_maps(self):
try:
os.unlink(os.path.join(self._dir, "maps"))
except:
pass
shutil.copy("/proc/{}/maps".format(self._vm.get_pid()),
os.path.join(self._dir, "maps"))
def merge_traces(self):
logger.info("Merging traces")
self.trace_parser.parse()
self.trace_parser.write_to_file(self._dir, True)
def run(self):
try:
self._vm.setup()
self.host_traces()
self._vm.run()
self.guest_traces()
self.run_netperf()
self._host_tracer.trace_off()
self._guest_tracer.trace_off()
logger.info("Test again without traces:")
self.run_netperf(10)
self.run_netperf(10)
self.run_netperf(10)
finally:
try:
self._guest_tracer.read_trace_once(to_file=True)
self._host_tracer.read_trace_once(to_file=True, cpu="2")
# self._host_tracer.read_trace_once(to_file=True, filename=os.path.join(self._dir, "full_trace"))
self._host_tracer.set_buffer_size(1000)
except:
import traceback
traceback.print_exc()
self.copy_maps()
self._vm.teardown()
try:
self._host_tracer.disable_all_events()
except:
pass
self.merge_traces()
def stats(self):
new_stats = MainStats(self.trace_parser,
os.path.join(self._dir, "new"),
size=self._msg_size)
os.makedirs(os.path.join(self._dir, "new"), exist_ok=True)
# new_stats.attr = "time_median"
new_stats.attr = "time_avg"
new_stats.run(new_stats.TYP_VIRTIO if "virtio" in
self._vm.name else new_stats.TYP_E1000)
def exit_stats_main(folder):
t = Traces(folder)
exits_stats(t)