KVM hypercall analysis example (#1082)

* KVM hypercall analysis example

* Update README with KVM analysis example

README.md

@@ -73,6 +73,7 @@ pair of .c and .py files, and some are directories of files.
 - examples/tracing/[trace_fields.py](examples/tracing/trace_fields.py): Simple example of printing fields from traced events.
 - examples/tracing/[urandomread.py](examples/tracing/urandomread.py): A kernel tracepoint example, which traces random:urandom_read. [Examples](examples/tracing/urandomread_example.txt).
 - examples/tracing/[vfsreadlat.py](examples/tracing/vfsreadlat.py) examples/tracing/[vfsreadlat.c](examples/tracing/vfsreadlat.c): VFS read latency distribution. [Examples](examples/tracing/vfsreadlat_example.txt).
+- examples/tracing/[kvm_hypercall.py](examples/tracing/kvm_hypercall.py): Conditional static kernel tracepoints for KVM entry, exit and hypercall [Examples](examples/tracing/kvm_hypercall.txt).
 
 #### Tools:
 <center><a href="images/bcc_tracing_tools_2017.png"><img src="images/bcc_tracing_tools_2017.png" border=0 width=700></a></center>
@@ -223,7 +224,6 @@ what you want to work on.
 
 * _Mailing List:_ http://lists.iovisor.org/mailman/listinfo/iovisor-dev
 * _IRC:_ #iovisor at irc.oftc.net
-* _IRC Logs:_ https://scrollback.io/iovisor/all
 * _BCC Issue Tracker:_ [Github Issues](https://github.com/iovisor/bcc/issues)
 * _A guide for contributing scripts:_ [CONTRIBUTING-SCRIPTS.md](CONTRIBUTING-SCRIPTS.md)
 

examples/tracing/kvm_hypercall.py

+#!/usr/bin/env python
+#
+# kvm_hypercall.py
+#
+# Demonstrates stateful kvm_entry and kvm_exit recording along with the
+# associated hypercall when exit_reason is VMCALL. See kvm_hypercall.txt
+# for usage
+#
+# REQUIRES: Linux 4.7+ (BPF_PROG_TYPE_TRACEPOINT support)
+#
+# Copyright (c) 2017 ShiftLeft Inc.
+#
+# Author(s):
+#   Suchakrapani Sharma <suchakra@shiftleft.io>
+
+
+from __future__ import print_function
+from bcc import BPF
+
+# load BPF program
+b = BPF(text="""
+#define EXIT_REASON 18
+BPF_HASH(start, u8, u8);
+
+TRACEPOINT_PROBE(kvm, kvm_exit) {
+    u8 e = EXIT_REASON;
+    u8 one = 1;
+    if (args->exit_reason == EXIT_REASON) {
+        bpf_trace_printk("KVM_EXIT exit_reason : %d\\n", args->exit_reason);
+        start.update(&e, &one);
+    }
+    return 0;
+}
+
+TRACEPOINT_PROBE(kvm, kvm_entry) {
+    u8 e = EXIT_REASON;
+    u8 zero = 0;
+    u8 *s = start.lookup(&e);
+    if (s != NULL && *s == 1) {
+        bpf_trace_printk("KVM_ENTRY vcpu_id : %u\\n", args->vcpu_id);
+        start.update(&e, &zero);
+    }
+    return 0;
+}
+
+TRACEPOINT_PROBE(kvm, kvm_hypercall) {
+    u8 e = EXIT_REASON;
+    u8 zero = 0;
+    u8 *s = start.lookup(&e);
+    if (s != NULL && *s == 1) {
+        bpf_trace_printk("HYPERCALL nr : %d\\n", args->nr);
+    }
+    return 0;
+};
+""")
+
+# header
+print("%-18s %-16s %-6s %s" % ("TIME(s)", "COMM", "PID", "EVENT"))
+
+# format output
+while 1:
+    try:
+        (task, pid, cpu, flags, ts, msg) = b.trace_fields()
+    except ValueError:
+        continue
+    print("%-18.9f %-16s %-6d %s" % (ts, task, pid, msg))
+

examples/tracing/kvm_hypercall.txt

+Demonstrations of kvm_hypercall.py, showing eBPF/bcc based hypercall analysis
+
+This example demonstrates how we can statefully save static tracepoint
+events based on conditions being met for other events with which they are
+associated. Here, we wish to record kvm_exit and kvm_entry events which are
+linked to the kvm_hypercall event. We are interested in kvm_exit with exit
+reason as VMCALL (18). This may be useful to analyze latency caused by a
+hypercall itself.
+
+To test this, while the python script is run, induce a hypercall from a
+guest based on the following example:
+https://gist.github.com/abenbachir/344822b5ba9fc5ac384cdec3f087e018
+
+# ./kvm_hypercall.py
+TIME(s)            COMM             PID    MESSAGE
+2445.577087000     CPU 0/KVM        8896   KVM_EXIT exit_reason : 18
+2445.577122000     CPU 0/KVM        8896   HYPERCALL nr : 0
+2445.577129000     CPU 0/KVM        8896   KVM_ENTRY vcpu_id : 0
+2445.577136000     CPU 0/KVM        8896   KVM_EXIT exit_reason : 18
+2445.577145000     CPU 0/KVM        8896   HYPERCALL nr : 1
+2445.577149000     CPU 0/KVM        8896   KVM_ENTRY vcpu_id : 0
+2445.577155000     CPU 0/KVM        8896   KVM_EXIT exit_reason : 18
+2445.577160000     CPU 0/KVM        8896   HYPERCALL nr : 2
+2445.577164000     CPU 0/KVM        8896   KVM_ENTRY vcpu_id : 0
+2445.577170000     CPU 0/KVM        8896   KVM_EXIT exit_reason : 18
+2445.577175000     CPU 0/KVM        8896   HYPERCALL nr : 3
+2445.577179000     CPU 0/KVM        8896   KVM_ENTRY vcpu_id : 0
+2445.577185000     CPU 0/KVM        8896   KVM_EXIT exit_reason : 18
+2445.577190000     CPU 0/KVM        8896   HYPERCALL nr : 4
+2445.577194000     CPU 0/KVM        8896   KVM_ENTRY vcpu_id : 0
+
+This output shows a sequence of exit -> hypercall -> entry where the
+exit_reason was VMCALL.