[EXAMPLE] tools: a tool for merging trace data of a guest and a host

[Yoshihiro YUNOMAE]

This tool merges trace data of a guest and a host in chronological
order. Restrictions of this tool is as follows:
- one guest (not for multiple guests)
- stable TSC (not backward TSC)
- synchronized TSC
- unchanged TSC offset (the guest does not execute write_TSC)

- How to use
1. [host] Enable kvm_write_tsc_offset before booting a guest
     # cd /sys/kernel/debug/tracing/instances
     # mkdir tsc_offset
     # cd tsc_offset
     # echo x86-tsc > trace_clock
     # echo 1 > events/kvm/kvm_write_tsc_offset/enable

2. [host] Enable events you want
      Note: I recommend to enable kvm_exit/entry events.
     # cd /sys/kernel/debug/tracing
     # echo kvm_entry >> set_event
     # echo kvm_exit >> set_event
     # [snip]
     # echo x86-tsc > trace_clock

3. [host] Boot the guest

4. [guest] Enable events you want
     # cd /sys/kernel/debug/tracing
     # echo sched_wakeup >> set_event
     # echo sched_switch >> set_event
     # [snip]
     # echo x86-tsc > trace_clock

5. [guest] Run programs

6. [guest/host] Get trace data
     # echo 0 > tracing_on
     # cat trace > /home/yourdir/log/guest_trace.txt (for the guest)
       (cat trace > /home/yourdir/log/host_trace.txt (for the host))
     # scp [host_IP]:/home/yourdir/log/guest_trace.txt (only for the guest)

7. [host] Get next TSC offset
     # cat /sys/kernel/debug/tracing/instances/tsc_offset/trace
    qemu-kvm-22089 [000] d...4300151845072: kvm_write_tsc_offset: 
vcpu=0 prev=0 next=18446739773557710924

8. [host] Run this tool with the next TSC offset for -t option.
$ ./trace-merge.pl -g ~/log/guest_trace.txt -h ~/log/host_trace.txt \
  -t 18446739773557710924

h        qemu-kvm-2687  [003] d...50550079203669: kvm_exit: [detail]
h        qemu-kvm-2687  [003] d...50550079206816: kvm_entry: [detail]
g            comm-3826  [000] d.h.50550079226331: sched_wakeup: [detail]
h        qemu-kvm-2687  [003] d...50550079240656: kvm_exit: [detail]
h        qemu-kvm-2687  [003] d...50550079243467: kvm_entry: [detail]
h        qemu-kvm-2687  [003] d...50550079256103: kvm_exit: [detail]
h        qemu-kvm-2687  [003] d...50550079268391: kvm_entry: [detail]
g            comm-3826  [000] d...50550079279266: sched_switch: [detail]
h        qemu-kvm-2687  [003] d...50550079280829: kvm_exit: [detail]
h        qemu-kvm-2687  [003] d...50550079286028: kvm_entry: [detail]
|
\----guest/host

Thanks,

--
Yoshihiro YUNOMAE
Software Platform Research Dept. Linux Technology Center
Hitachi, Ltd., Yokohama Research Laboratory
E-mail: yoshihiro.yunomae.ez@xxxxxxxxxxx


#!/usr/bin/perl
#
# Tool for merging and sorting trace data of a guest and host
#
# Created by Yoshihiro YUNOMAE <yoshihiro.yunomae.ez@xxxxxxxxxxx>
#
# - How to use
# ./trace-merge.pl <-h host_data -g guest_data -t tsc_offset_value>
#
use strict;
use bigint;
use warnings;
use Getopt::Long qw(:config posix_default no_ignore_case);

my @merged_data = ();
my @sorted_data = ();

my ($opt_host, $opt_guest, $opt_offset);
GetOptions(
	"host_data|h=s"	=> \$opt_host,
	"guest_data|g=s"=> \$opt_guest,
	"tsc_offset|t=i"=> \$opt_offset
);

my $tsc_offset = 0;
my $MASK64 = (1 << 64) - 1;

&get_tsc_offset();
&read_all_data();

sub read_all_data {
	my $h_tsc = 0;
	my $g_comm = "";
	my $g_tsc = 0;
	my $g_event = "";
	my $h_line = "";
	my $g_line = "";

	open HOST_DATA, "<", $opt_host or die "Cannot open host file: $!";
	open GUEST_DATA, "<", $opt_guest or die "Cannot open guest file: $!";

	# skip header information of trace files
	while (!$h_tsc) {
		$h_line = <HOST_DATA>;
		if ($h_line =~ /\[[0-9]+\]\s.{4}\s([0-9]+):/) {
			$h_tsc = $1;
		}
	}

	# skip header information of trace files
	while (!$g_tsc) {
		$g_line = <GUEST_DATA>;
		if ($g_line =~ /^(.+\[[0-9]+\]\s.{4}\s)([0-9]+)(:.+)/) {
			$g_comm = $1;
			$g_tsc = ($2 - $tsc_offset) & $MASK64;
			$g_event = $3;
		}
	}

	# sort trace data by tsc
	while ($h_line) {
		if ($h_tsc < $g_tsc) {
			print "h $h_line";
			$h_line = <HOST_DATA>;
			if (!$h_line) {
				last;
			}
			if ($h_line =~ /\[[0-9]+\]\s.{4}\s([0-9]+):/) {
				$h_tsc = $1;
			}
		} else {
			print "g $g_comm$g_tsc$g_event\n";
			$g_line = <GUEST_DATA>;
			if (!$g_line) {
				last;
			}
			if ($g_line =~ /^(.+\[[0-9]+\]\s.{4}\s)([0-9]+)(:.+)/) {
				$g_comm = $1;
				$g_tsc = ($2 - $tsc_offset) & $MASK64;
				$g_event = $3;
			}
		}
	}

	#flush host data
	while ($h_line) {
		print "h $h_line";
		$h_line = <HOST_DATA>;
		if (!$h_line) {
			last;
		}
	}

	#flush guest data
	while ($g_line) {
		print "g $g_comm$g_tsc$g_event\n";
		$g_line = <GUEST_DATA>;
		if (!$g_line) {
			last;
		}
		if ($g_line =~ /^(.+\[[0-9]+\]\s.{4}\s)([0-9]+)(:.+)/) {
			$g_comm = $1;
			$g_tsc = ($2 - $tsc_offset) & $MASK64;
			$g_event = $3;
		}
	}

	close HOST_DATA;
	close GUEST_DATA;
}

sub get_tsc_offset {
	if (!$opt_offset) {
		$tsc_offset = 0;
	} else {
		$tsc_offset = &convert_tscoffset($opt_offset);
	}
}

sub convert_tscoffset {
	my $offset = shift;

	return $offset - (1 << 64);
}