[tip:perf/core] perf trace beautify ioctl: Beautify KVM ioctl's 'cmd' arg

From: tip-bot for Arnaldo Carvalho de Melo
Date: Thu Aug 10 2017 - 12:35:45 EST

Next message: tip-bot for Ingo Molnar: "[tip:perf/core] perf build: Clarify header version warning message"
Previous message: Tony Lindgren: "Re: [PATCH 00/12] ARM: dts: Add iodelay data for MMC"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]

Commit-ID: 45717b7fb7e59285927170cf7fff233e0bbeeaca
Gitweb: http://git.kernel.org/tip/45717b7fb7e59285927170cf7fff233e0bbeeaca
Author: Arnaldo Carvalho de Melo <acme@xxxxxxxxxx>
AuthorDate: Mon, 31 Jul 2017 17:34:47 -0300
Committer: Arnaldo Carvalho de Melo <acme@xxxxxxxxxx>
CommitDate: Tue, 1 Aug 2017 13:02:52 -0300

perf trace beautify ioctl: Beautify KVM ioctl's 'cmd' arg

Also trying a new approach, using a copy of uapi/linux/kvm.h we auto
generate the string tables, then include it in the ioctl cmd beautifier.

This way either the KVM developers will add the new commands to the
tools/ copy, like is happening with other areas of tools/include/ (bpf.h
comes to mind), or we'll be notified when building perf that our copy
drifted.

E.g., a tracing a process and its threads, but would work for system wide as
well, just drop that '-p 21238', to see ioctls for DRM, tty, sound, etc:

# perf trace -e ioctl -p 21238 2>&1 | grep -v KVM_RUN
7801.536 ( 0.003 ms): CPU 0/KVM/21276 ioctl(fd: 13<anon_inode:kvm-vm>, cmd: KVM_IRQ_LINE_STATUS, arg: 0x7f484c6c73c0) = 0
<SNIP lots of the last one>
7801.715 ( 0.001 ms): CPU 0/KVM/21276 ioctl(fd: 13<anon_inode:kvm-vm>, cmd: KVM_IRQ_LINE_STATUS, arg: 0x7f484c6c73e0) = 0
11001.051 ( 0.008 ms): qemu-system-x8/21238 ioctl(fd: 13<anon_inode:kvm-vm>, cmd: KVM_SIGNAL_MSI, arg: 0x563c83379d70) = 1
11001.225 ( 0.005 ms): qemu-system-x8/21238 ioctl(fd: 13<anon_inode:kvm-vm>, cmd: KVM_SIGNAL_MSI, arg: 0x563c83379d70) = 1
10750.377 (249.963 ms): CPU 0/KVM/21276 ... [continued]: ioctl()) = 0
11011.780 ( 0.015 ms): qemu-system-x8/21238 ioctl(fd: 13<anon_inode:kvm-vm>, cmd: KVM_SIGNAL_MSI, arg: 0x563c83379d90) = 1
11011.929 ( 0.005 ms): qemu-system-x8/21238 ioctl(fd: 13<anon_inode:kvm-vm>, cmd: KVM_SIGNAL_MSI, arg: 0x7fff053e1000) = 1
11012.090 ( 0.004 ms): qemu-system-x8/21238 ioctl(fd: 13<anon_inode:kvm-vm>, cmd: KVM_SIGNAL_MSI, arg: 0x563c83379d70) = 1
11023.127 ( 0.020 ms): qemu-system-x8/21238 ioctl(fd: 13<anon_inode:kvm-vm>, cmd: KVM_SIGNAL_MSI, arg: 0x563c83379d90) = 1
11000.483 (249.807 ms): CPU 0/KVM/21276 ... [continued]: ioctl()) = 0
25620.877 ( 0.042 ms): qemu-system-x8/21238 ioctl(fd: 13<anon_inode:kvm-vm>, cmd: KVM_IRQ_LINE_STATUS, arg: 0x7fff053e1080) = 0
<SNIP several of the last one>
25621.025 ( 0.002 ms): qemu-system-x8/21238 ioctl(fd: 13<anon_inode:kvm-vm>, cmd: KVM_IRQ_LINE_STATUS, arg: 0x7fff053e10a0) = 0
25500.803 (120.186 ms): CPU 0/KVM/21276 ... [continued]: ioctl()) = 0
25621.078 ( 0.005 ms): CPU 0/KVM/21276 ioctl(fd: 13<anon_inode:kvm-vm>, cmd: KVM_IRQ_LINE_STATUS, arg: 0x7f484c6c73c0) = 0
<SNIP lots of the last one>
25621.346 ( 0.001 ms): CPU 0/KVM/21276 ioctl(fd: 13<anon_inode:kvm-vm>, cmd: KVM_IRQ_LINE_STATUS, arg: 0x7f484c6c73e0) = 0
40456.997 ( 0.100 ms): qemu-system-x8/21238 ioctl(fd: 27</dev/vhost-net>, cmd: (WRITE, 0xaf, 0x30, 0x8), arg: 0x7fff053dffe0) = 0
40457.100 ( 0.019 ms): qemu-system-x8/21238 ioctl(fd: 27</dev/vhost-net>, cmd: (WRITE, 0xaf, 0x30, 0x8), arg: 0x7fff053dffe0) = 0
40457.133 ( 0.002 ms): qemu-system-x8/21238 ioctl(fd: 27</dev/vhost-net>, cmd: (READ|WRITE, 0xaf, 0x12, 0x8), arg: 0x7fff053dff60) = 0
40457.139 ( 0.001 ms): qemu-system-x8/21238 ioctl(fd: 27</dev/vhost-net>, cmd: (READ|WRITE, 0xaf, 0x12, 0x8), arg: 0x7fff053dff60) = 0
40458.503 ( 0.027 ms): qemu-system-x8/21238 ioctl(fd: 13<anon_inode:kvm-vm>, cmd: KVM_IOEVENTFD, arg: 0x7fff053dfc80) = 0
40458.601 ( 0.030 ms): qemu-system-x8/21238 ioctl(fd: 13<anon_inode:kvm-vm>, cmd: KVM_IOEVENTFD, arg: 0x7fff053dfc80) = 0
40458.649 ( 0.003 ms): qemu-system-x8/21238 ioctl(fd: 27</dev/vhost-net>, cmd: (WRITE, 0xaf, 0x21, 0x8), arg: 0x7fff053dff20) = 0
40458.654 ( 0.002 ms): qemu-system-x8/21238 ioctl(fd: 27</dev/vhost-net>, cmd: (WRITE, 0xaf, 0x21, 0x8), arg: 0x7fff053dff20) = 0
40458.657 ( 0.018 ms): qemu-system-x8/21238 ioctl(fd: 13<anon_inode:kvm-vm>, cmd: KVM_IRQFD, arg: 0x7fff053dff00 ) = 0
40459.077 ( 0.017 ms): qemu-system-x8/21238 ioctl(fd: 13<anon_inode:kvm-vm>, cmd: KVM_IRQFD, arg: 0x7fff053dff00 ) = 0
40459.123 ( 0.017 ms): qemu-system-x8/21238 ioctl(fd: 13<anon_inode:kvm-vm>, cmd: KVM_IOEVENTFD, arg: 0x7fff053dfd20) = 0
<SNIP lots of the last one>
40463.477 ( 0.013 ms): qemu-system-x8/21238 ioctl(fd: 13<anon_inode:kvm-vm>, cmd: KVM_IOEVENTFD, arg: 0x7fff053dfd20) = 0
40464.874 ( 0.010 ms): qemu-system-x8/21238 ioctl(fd: 13<anon_inode:kvm-vm>, cmd: KVM_GET_VCPU_EVENTS, arg: 0x7fff053e0000) = 0
40464.892 ( 0.048 ms): qemu-system-x8/21238 ioctl(fd: 12</dev/kvm>, cmd: KVM_CHECK_EXTENSION, arg: 0x4c ) = 1
40464.991 ( 0.002 ms): qemu-system-x8/21238 ioctl(fd: 13<anon_inode:kvm-vm>, cmd: KVM_GET_CLOCK, arg: 0x7fff053e0040) = 0
40464.962 ( 0.013 ms): CPU 0/KVM/21276 ioctl(fd: 20<anon_inode:kvm-vcpu>, cmd: KVM_GET_MSRS, arg: 0x7f484c6c7670) = 1
44540.437 ( 0.103 ms): qemu-system-x8/21238 ioctl(fd: 13<anon_inode:kvm-vm>, cmd: KVM_SET_GSI_ROUTING, arg: 0x563c7c93c000) = 0
44540.544 ( 0.008 ms): qemu-system-x8/21238 ioctl(fd: 13<anon_inode:kvm-vm>, cmd: KVM_IRQFD, arg: 0x7fff053dfea0 ) = 0
44540.555 ( 0.029 ms): qemu-system-x8/21238 ioctl(fd: 13<anon_inode:kvm-vm>, cmd: KVM_SET_GSI_ROUTING, arg: 0x563c7c93c000) = 0
44540.586 ( 0.003 ms): qemu-system-x8/21238 ioctl(fd: 13<anon_inode:kvm-vm>, cmd: KVM_IRQFD, arg: 0x7fff053dfea0 ) = 0
44540.592 ( 0.027 ms): qemu-system-x8/21238 ioctl(fd: 13<anon_inode:kvm-vm>, cmd: KVM_SET_GSI_ROUTING, arg: 0x563c7c93c000) = 0
44540.625 ( 0.005 ms): qemu-system-x8/21238 ioctl(fd: 27</dev/vhost-net>, cmd: (WRITE, 0xaf, 0x21, 0x8), arg: 0x7fff053dfe20) = 0
44540.639 ( 0.018 ms): qemu-system-x8/21238 ioctl(fd: 13<anon_inode:kvm-vm>, cmd: KVM_SET_GSI_ROUTING, arg: 0x563c7c93c000) = 0
44540.658 ( 0.003 ms): qemu-system-x8/21238 ioctl(fd: 27</dev/vhost-net>, cmd: (WRITE, 0xaf, 0x21, 0x8), arg: 0x7fff053dfe20) = 0
44540.686 ( 0.015 ms): qemu-system-x8/21238 ioctl(fd: 13<anon_inode:kvm-vm>, cmd: KVM_IOEVENTFD, arg: 0x7fff053dfbe0) = 0
44540.727 ( 0.014 ms): qemu-system-x8/21238 ioctl(fd: 13<anon_inode:kvm-vm>, cmd: KVM_IOEVENTFD, arg: 0x7fff053dfbe0) = 0
44540.748 ( 0.005 ms): qemu-system-x8/21238 ioctl(fd: 27</dev/vhost-net>, cmd: (WRITE, 0xaf, 0, 0x8), arg: 0x7fff053dfe88) = 0
44540.754 ( 0.026 ms): qemu-system-x8/21238 ioctl(fd: 27</dev/vhost-net>, cmd: (WRITE, 0xaf, 0x3, 0x8), arg: 0x563c7c906870) = 0
44540.783 ( 0.002 ms): qemu-system-x8/21238 ioctl(fd: 27</dev/vhost-net>, cmd: (WRITE, 0xaf, 0x10, 0x8), arg: 0x7fff053dff00) = 0
44540.787 ( 0.002 ms): qemu-system-x8/21238 ioctl(fd: 27</dev/vhost-net>, cmd: (WRITE, 0xaf, 0x12, 0x8), arg: 0x7fff053dff00) = 0
44540.793 ( 0.002 ms): qemu-system-x8/21238 ioctl(fd: 27</dev/vhost-net>, cmd: (WRITE, 0xaf, 0x11, 0x28), arg: 0x7fff053dfe70) = 0
44540.796 ( 0.010 ms): qemu-system-x8/21238 ioctl(fd: 27</dev/vhost-net>, cmd: (WRITE, 0xaf, 0x20, 0x8), arg: 0x7fff053dfef0) = 0
44540.811 ( 0.002 ms): qemu-system-x8/21238 ioctl(fd: 27</dev/vhost-net>, cmd: (WRITE, 0xaf, 0x10, 0x8), arg: 0x7fff053dff00) = 0
44540.814 ( 0.002 ms): qemu-system-x8/21238 ioctl(fd: 27</dev/vhost-net>, cmd: (WRITE, 0xaf, 0x12, 0x8), arg: 0x7fff053dff00) = 0
44540.819 ( 0.002 ms): qemu-system-x8/21238 ioctl(fd: 27</dev/vhost-net>, cmd: (WRITE, 0xaf, 0x11, 0x28), arg: 0x7fff053dfe70) = 0
44540.822 ( 0.005 ms): qemu-system-x8/21238 ioctl(fd: 27</dev/vhost-net>, cmd: (WRITE, 0xaf, 0x20, 0x8), arg: 0x7fff053dfef0) = 0
44540.837 ( 0.006 ms): qemu-system-x8/21238 ioctl(fd: 27</dev/vhost-net>, cmd: (WRITE, 0xaf, 0x30, 0x8), arg: 0x7fff053dff80) = 0
44540.862 ( 0.004 ms): qemu-system-x8/21238 ioctl(fd: 27</dev/vhost-net>, cmd: (WRITE, 0xaf, 0x30, 0x8), arg: 0x7fff053dff80) = 0
44540.887 ( 0.014 ms): qemu-system-x8/21238 ioctl(fd: 13<anon_inode:kvm-vm>, cmd: KVM_IOEVENTFD, arg: 0x7fff053dfd00) = 0
<SNIP lots of the last one>
44542.756 ( 0.020 ms): qemu-system-x8/21238 ioctl(fd: 13<anon_inode:kvm-vm>, cmd: KVM_IOEVENTFD, arg: 0x7fff053dfd00) = 0
44542.809 ( 0.007 ms): qemu-system-x8/21238 ioctl(fd: 13<anon_inode:kvm-vm>, cmd: KVM_SET_VCPU_EVENTS, arg: 0x7fff053dffb0) = 0
44542.819 ( 0.003 ms): qemu-system-x8/21238 ioctl(fd: 12</dev/kvm>, cmd: KVM_CHECK_EXTENSION, arg: 0x4c ) = 1
44543.016 ( 0.004 ms): qemu-system-x8/21238 ioctl(fd: 13<anon_inode:kvm-vm>, cmd: KVM_SET_CLOCK, arg: 0x7fff053dfff0) = 0
44543.022 ( 0.008 ms): qemu-system-x8/21238 ioctl(fd: 20<anon_inode:kvm-vcpu>, cmd: KVM_KVMCLOCK_CTRL ) = 0
46952.502 ( 0.010 ms): qemu-system-x8/21238 ioctl(fd: 13<anon_inode:kvm-vm>, cmd: KVM_SIGNAL_MSI, arg: 0x563c83379d70) = 1
46829.292 (249.860 ms): CPU 0/KVM/21276 ... [continued]: ioctl()) = 0
^C
[root@jouet linux]#

Since there are clashes in _IOC_NR() for some cases, notably ioctls with
PPC_ and ARM_ in its name and some that depend on some internal state to
be valid, but use the same number as others, those were removed in the
shell script that builds the table, tools/perf/trace/beauty/kvm_ioctl.sh.

Since so far we're supporting only x86 in the 'cmd' ioctl arg beautifier
in perf trace, we can leave fully supporting these ioctls for later.

There are some more to handle here, notably the one for /dev/vhost-net, will
come later.

Cc: Adrian Hunter <adrian.hunter@xxxxxxxxx>
Cc: David Ahern <dsahern@xxxxxxxxx>
Cc: Jiri Olsa <jolsa@xxxxxxxxxx>
Cc: Namhyung Kim <namhyung@xxxxxxxxxx>
Cc: Paolo Bonzini <pbonzini@xxxxxxxxxx>
Cc: Radim KrÄmÃÅ <rkrcmar@xxxxxxxxxx>
Cc: Wang Nan <wangnan0@xxxxxxxxxx>
Link: http://lkml.kernel.org/n/tip-zxhebe579n338d7qrnjoctes@xxxxxxxxxxxxxx
Signed-off-by: Arnaldo Carvalho de Melo <acme@xxxxxxxxxx>
---
tools/perf/Makefile.perf | 15 +++++++++++++--
tools/perf/trace/beauty/ioctl.c | 14 +++++++++++++-
tools/perf/trace/beauty/kvm_ioctl.sh | 11 +++++++++++
3 files changed, 37 insertions(+), 3 deletions(-)

diff --git a/tools/perf/Makefile.perf b/tools/perf/Makefile.perf
index d49354d..6c1be10 100644
--- a/tools/perf/Makefile.perf
+++ b/tools/perf/Makefile.perf
@@ -406,6 +406,13 @@ sndrv_pcm_ioctl_tbl := $(srctree)/tools/perf/trace/beauty/sndrv_pcm_ioctl.sh
$(sndrv_pcm_ioctl_array): $(sndrv_pcm_hdr_dir)/asound.h $(sndrv_pcm_ioctl_tbl)
$(Q)$(SHELL) '$(sndrv_pcm_ioctl_tbl)' $(sndrv_pcm_hdr_dir) > $@

+kvm_ioctl_array := $(beauty_ioctl_outdir)/kvm_ioctl_array.c
+kvm_hdr_dir := $(srctree)/tools/include/uapi/linux
+kvm_ioctl_tbl := $(srctree)/tools/perf/trace/beauty/kvm_ioctl.sh
+
+$(kvm_ioctl_array): $(kvm_hdr_dir)/kvm.h $(kvm_ioctl_tbl)
+ $(Q)$(SHELL) '$(kvm_ioctl_tbl)' $(kvm_hdr_dir) > $@
+
all: shell_compatibility_test $(ALL_PROGRAMS) $(LANG_BINDINGS) $(OTHER_PROGRAMS)

$(OUTPUT)python/perf.so: $(PYTHON_EXT_SRCS) $(PYTHON_EXT_DEPS) $(LIBTRACEEVENT_DYNAMIC_LIST)
@@ -500,7 +507,10 @@ endif
__build-dir = $(subst $(OUTPUT),,$(dir $@))
build-dir = $(if $(__build-dir),$(__build-dir),.)

-prepare: $(OUTPUT)PERF-VERSION-FILE $(OUTPUT)common-cmds.h archheaders $(drm_ioctl_array) $(sndrv_pcm_ioctl_array) $(sndrv_ctl_ioctl_array)
+prepare: $(OUTPUT)PERF-VERSION-FILE $(OUTPUT)common-cmds.h archheaders $(drm_ioctl_array) \
+ $(sndrv_pcm_ioctl_array) \
+ $(sndrv_ctl_ioctl_array) \
+ $(kvm_ioctl_array)

$(OUTPUT)%.o: %.c prepare FORCE
$(Q)$(MAKE) -f $(srctree)/tools/build/Makefile.build dir=$(build-dir) $@
@@ -768,7 +778,8 @@ clean:: $(LIBTRACEEVENT)-clean $(LIBAPI)-clean $(LIBBPF)-clean $(LIBSUBCMD)-clea
$(OUTPUT)pmu-events/pmu-events.c \
$(OUTPUT)$(drm_ioctl_array) \
$(OUTPUT)$(sndrv_ctl_ioctl_array) \
- $(OUTPUT)$(sndrv_pcm_ioctl_array)
+ $(OUTPUT)$(sndrv_pcm_ioctl_array) \
+ $(OUTPUT)$(kvm_ioctl_array)
$(QUIET_SUBDIR0)Documentation $(QUIET_SUBDIR1) clean
$(python-clean)

diff --git a/tools/perf/trace/beauty/ioctl.c b/tools/perf/trace/beauty/ioctl.c
index ec5a5a4..89fa4eb 100644
--- a/tools/perf/trace/beauty/ioctl.c
+++ b/tools/perf/trace/beauty/ioctl.c
@@ -77,6 +77,17 @@ static size_t ioctl__scnprintf_sndrv_ctl_cmd(int nr, char *bf, size_t size)
return scnprintf(bf, size, "(%#x, %#x)", 'U', nr);
}

+static size_t ioctl__scnprintf_kvm_cmd(int nr, char *bf, size_t size)
+{
+#include "trace/beauty/generated/ioctl/kvm_ioctl_array.c"
+ static DEFINE_STRARRAY(kvm_ioctl_cmds);
+
+ if (nr < strarray__kvm_ioctl_cmds.nr_entries && strarray__kvm_ioctl_cmds.entries[nr] != NULL)
+ return scnprintf(bf, size, "KVM_%s", strarray__kvm_ioctl_cmds.entries[nr]);
+
+ return scnprintf(bf, size, "(%#x, %#x)", 0xAE, nr);
+}
+
static size_t ioctl__scnprintf_cmd(unsigned long cmd, char *bf, size_t size)
{
int dir = _IOC_DIR(cmd),
@@ -91,7 +102,8 @@ static size_t ioctl__scnprintf_cmd(unsigned long cmd, char *bf, size_t size)
{ .type = 'A', .scnprintf = ioctl__scnprintf_sndrv_pcm_cmd, },
['T' - 'A']= { .type = 'T', .scnprintf = ioctl__scnprintf_tty_cmd, },
['U' - 'A']= { .type = 'U', .scnprintf = ioctl__scnprintf_sndrv_ctl_cmd, },
- ['d' - 'A'] = { .type = 'd', .scnprintf = ioctl__scnprintf_drm_cmd, }
+ ['d' - 'A'] = { .type = 'd', .scnprintf = ioctl__scnprintf_drm_cmd, },
+ [0xAE - 'A'] = { .type = 0xAE, .scnprintf = ioctl__scnprintf_kvm_cmd, },
};
const int nr_types = ARRAY_SIZE(ioctl_types);

diff --git a/tools/perf/trace/beauty/kvm_ioctl.sh b/tools/perf/trace/beauty/kvm_ioctl.sh
new file mode 100755
index 0000000..bd28817
--- /dev/null
+++ b/tools/perf/trace/beauty/kvm_ioctl.sh
@@ -0,0 +1,11 @@
+#!/bin/sh
+
+kvm_header_dir=$1
+
+printf "static const char *kvm_ioctl_cmds[] = {\n"
+regex='^#[[:space:]]*define[[:space:]]+KVM_(\w+)[[:space:]]+_IO[RW]*\([[:space:]]*KVMIO[[:space:]]*,[[:space:]]*(0x[[:xdigit:]]+).*'
+egrep $regex ${kvm_header_dir}/kvm.h | \
+ sed -r "s/$regex/\2 \1/g" | \
+ egrep -v " ((ARM|PPC|S390)_|[GS]ET_(DEBUGREGS|PIT2|XSAVE|TSC_KHZ)|CREATE_SPAPR_TCE_64)" | \
+ sort | xargs printf "\t[%s] = \"%s\",\n"
+printf "};\n"

Next message: tip-bot for Ingo Molnar: "[tip:perf/core] perf build: Clarify header version warning message"
Previous message: Tony Lindgren: "Re: [PATCH 00/12] ARM: dts: Add iodelay data for MMC"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]