[Qemu-devel] [PATCH] trace: add ability to do simple printf logging via systemtap

[Daniel P . Berrangé]

The dtrace systemtap trace backend for QEMU is very powerful but it is
also somewhat unfriendly to users who aren't familiar with systemtap,
or who don't need its power right now.

  stap -e "....some strange script...."

The 'log' backend for QEMU by comparison is very crude but incredibly
easy to use:

 $ qemu -d trace:qio* ...some args...
 address@hidden:qio_channel_socket_new Socket new ioc=0x563a8a39d400
 address@hidden:qio_task_new Task new task=0x563a891d0570 source=0x563a8a39d400 
func=0x563a86f1e6c0 opaque=0x563a89078000
 address@hidden:qio_task_thread_start Task thread start task=0x563a891d0570 
worker=0x563a86f1ce50 opaque=0x563a891d9d90
 address@hidden:qio_task_thread_run Task thread run task=0x563a891d0570
 address@hidden:qio_channel_socket_connect_sync Socket connect sync 
ioc=0x563a8a39d400 addr=0x563a891d9d90
 address@hidden:qio_channel_socket_connect_fail Socket connect fail 
ioc=0x563a8a39d400

This commit introduces a way to do simple printf style logging of probe
points using systemtap. In particular it creates another set of tapsets,
one per emulator:

  /usr/share/systemtap/tapset/qemu-*-log.stp

These pre-define probe functions which simply call printf() on their
arguments. The printf() format string is taken from the normal
trace-events files, with a little munging to the format specifiers
to cope with systemtap's more restrictive syntax.

With this you can now do

 $ stap -e 'probe qemu.system.x86_64.log.qio*{}'
 address@hidden qio_channel_socket_new Socket new ioc=0x56135d1d7c00
 address@hidden qio_task_new Task new task=0x56135cd66eb0 source=0x56135d1d7c00 
func=0x56135af746c0 opaque=0x56135bf06400
 address@hidden qio_task_thread_start Task thread start task=0x56135cd66eb0 
worker=0x56135af72e50 opaque=0x56135c071d70
 address@hidden qio_task_thread_run Task thread run task=0x56135cd66eb0

We go one step further though and introduce a 'qemu-trace-stap' tool to
make this even easier

 $ qemu-trace-stap run qemu-system-x86_64 qio*
 address@hidden qio_channel_socket_new Socket new ioc=0x56135d1d7c00
 address@hidden qio_task_new Task new task=0x56135cd66eb0 source=0x56135d1d7c00 
func=0x56135af746c0 opaque=0x56135bf06400
 address@hidden qio_task_thread_start Task thread start task=0x56135cd66eb0 
worker=0x56135af72e50 opaque=0x56135c071d70
 address@hidden qio_task_thread_run Task thread run task=0x56135cd66eb0

This tool is clever in that it will automatically change the
SYSTEMTAP_TAPSET env variable to point to the directory containing the
right set of probes for the QEMU binary path you give it. This is useful
if you have QEMU installed in /usr but are trying to test and trace a
binary in /home/berrange/usr/qemu-git. In that case you'd do

 $ qemu-trace-stap run /home/berrange/usr/qemu-git/bin/qemu-system-x86_64 qio*

And it'll make sure /home/berrange/usr/qemu-git/share/systemtap/tapset
is used for the trace session

The 'qemu-trace-stap' script takes a verbose arg so you can understand
what it is running

 $ qemu-trace-stap run /home/berrange/usr/qemu-git/bin/qemu-system-x86_64 qio*
 Using tapset dir '/home/berrange/usr/qemu-git/share/systemtap/tapset' for 
binary '/home/berrange/usr/qemu-git/bin/qemu-system-x86_64'
 Compiling script 'probe qemu.system.x86_64.log.qio* {}'
 Running script, <Ctrl>-c to quit
 ...trace output...

It can enable multiple probes at once

 $ qemu-trace-stap run qemu-system-x86_64 qio* qcrypto* buffer*

Finally if you can't remember what probes are valid it can tell you

 $ qemu-trace-stap list qemu-system-x86_64
 ahci_check_irq
 ahci_cmd_done
 ahci_dma_prepare_buf
 ahci_dma_prepare_buf_fail
 ahci_dma_rw_buf
 ahci_irq_lower
 ...snip...

Or list just those matching a prefix pattern

 $ qemu-trace-stap list -v qemu-system-x86_64 qio*
 Using tapset dir '/home/berrange/usr/qemu-git/share/systemtap/tapset' for 
binary '/home/berrange/usr/qemu-git/bin/qemu-system-x86_64'
 Listing probes with name 'qemu.system.x86_64.log.qio*'
 qio_channel_command_abort
 qio_channel_command_new_pid
 qio_channel_command_new_spawn
 qio_channel_command_wait
 qio_channel_file_new_fd
 ...snip...

Signed-off-by: Daniel P. Berrangé <address@hidden>
---
 Makefile                             |   3 +
 Makefile.target                      |  11 +-
 scripts/qemu-trace-stap              | 159 +++++++++++++++++++++++++++
 scripts/tracetool/format/log_stap.py |  75 +++++++++++++
 4 files changed, 247 insertions(+), 1 deletion(-)
 create mode 100755 scripts/qemu-trace-stap
 create mode 100644 scripts/tracetool/format/log_stap.py

diff --git a/Makefile b/Makefile
index a9ac16d94e..f29c1fbe43 100644
--- a/Makefile
+++ b/Makefile
@@ -735,6 +735,9 @@ endif
 ifneq ($(HELPERS-y),)
        $(call install-prog,$(HELPERS-y),$(DESTDIR)$(libexecdir))
 endif
+ifdef CONFIG_TRACE_SYSTEMTAP
+       $(INSTALL_PROG) "scripts/qemu-trace-stap" $(DESTDIR)$(bindir)
+endif
 ifneq ($(BLOBS),)
        set -e; for x in $(BLOBS); do \
                $(INSTALL_DATA) $(SRC_PATH)/pc-bios/$$x 
"$(DESTDIR)$(qemu_datadir)"; \
diff --git a/Makefile.target b/Makefile.target
index 44ec4b630c..cb85eb450c 100644
--- a/Makefile.target
+++ b/Makefile.target
@@ -45,7 +45,7 @@ config-target.h: config-target.h-timestamp
 config-target.h-timestamp: config-target.mak
 
 ifdef CONFIG_TRACE_SYSTEMTAP
-stap: $(QEMU_PROG).stp-installed $(QEMU_PROG).stp $(QEMU_PROG)-simpletrace.stp
+stap: $(QEMU_PROG).stp-installed $(QEMU_PROG).stp $(QEMU_PROG)-simpletrace.stp 
$(QEMU_PROG)-log.stp
 
 ifdef CONFIG_USER_ONLY
 TARGET_TYPE=user
@@ -84,6 +84,14 @@ $(QEMU_PROG)-simpletrace.stp: $(BUILD_DIR)/trace-events-all 
$(tracetool-y)
                --probe-prefix=qemu.$(TARGET_TYPE).$(TARGET_NAME) \
                $< > $@,"GEN","$(TARGET_DIR)$(QEMU_PROG)-simpletrace.stp")
 
+$(QEMU_PROG)-log.stp: $(BUILD_DIR)/trace-events-all $(tracetool-y)
+       $(call quiet-command,$(TRACETOOL) \
+               --group=all \
+               --format=log-stap \
+               --backends=$(TRACE_BACKENDS) \
+               --probe-prefix=qemu.$(TARGET_TYPE).$(TARGET_NAME) \
+               $< > $@,"GEN","$(TARGET_DIR)$(QEMU_PROG)-log.stp")
+
 else
 stap:
 endif
@@ -224,6 +232,7 @@ ifdef CONFIG_TRACE_SYSTEMTAP
        $(INSTALL_DIR) "$(DESTDIR)$(qemu_datadir)/../systemtap/tapset"
        $(INSTALL_DATA) $(QEMU_PROG).stp-installed 
"$(DESTDIR)$(qemu_datadir)/../systemtap/tapset/$(QEMU_PROG).stp"
        $(INSTALL_DATA) $(QEMU_PROG)-simpletrace.stp 
"$(DESTDIR)$(qemu_datadir)/../systemtap/tapset/$(QEMU_PROG)-simpletrace.stp"
+       $(INSTALL_DATA) $(QEMU_PROG)-log.stp 
"$(DESTDIR)$(qemu_datadir)/../systemtap/tapset/$(QEMU_PROG)-log.stp"
 endif
 
 GENERATED_FILES += config-target.h
diff --git a/scripts/qemu-trace-stap b/scripts/qemu-trace-stap
new file mode 100755
index 0000000000..b2eb41fbb0
--- /dev/null
+++ b/scripts/qemu-trace-stap
@@ -0,0 +1,159 @@
+#!/usr/bin/python
+# -*- python -*-
+#
+#  Copyright (C) 2019 Red Hat, Inc
+#
+#  QEMU SystemTap Trace Tool
+#
+#  This program is free software; you can redistribute it and/or modify
+#  it under the terms of the GNU General Public License as published by
+#  the Free Software Foundation; under version 2 of the License.
+#
+#  This program is distributed in the hope that it will be useful,
+#  but WITHOUT ANY WARRANTY; without even the implied warranty of
+#  MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+#  GNU General Public License for more details.
+#
+#  You should have received a copy of the GNU General Public License
+#  along with this program; if not, see <http://www.gnu.org/licenses/>.
+
+from __future__ import print_function
+
+import argparse
+import copy
+import os.path
+import re
+import subprocess
+import sys
+
+
+def probe_prefix(binary):
+    dirname, filename = os.path.split(binary)
+    return re.sub("-", ".", filename) + ".log"
+
+
+def which(file):
+    for path in os.environ["PATH"].split(os.pathsep):
+        if os.path.exists(os.path.join(path, file)):
+                return os.path.join(path, file)
+
+    print("Unable to find '%s' in $PATH" % binary)
+    sys.exit(1)
+
+
+def tapset_dir(binary):
+    thisfile = which(binary)
+    basedir = os.path.split(thisfile)[0]
+    tapset = os.path.join(basedir, "..", "share", "systemtap", "tapset")
+    return os.path.realpath(tapset)
+
+
+def tapset_env(tapset_dir):
+    tenv = copy.copy(os.environ)
+    tenv["SYSTEMTAP_TAPSET"] = tapset_dir
+    return tenv
+
+def cmd_run(args):
+    prefix = probe_prefix(args.binary)
+    tapsets = tapset_dir(args.binary)
+
+    if args.verbose:
+        print("Using tapset dir '%s' for binary '%s'" % (tapsets, args.binary))
+
+    probes = []
+    for probe in args.probes:
+        probes.append("probe %s.%s {}" % (prefix, probe))
+    if len(probes) == 0:
+        probes.append("probe %s.* {}" % prefix)
+
+    script = " ".join(probes)
+    if args.verbose:
+        print("Compiling script '%s'" % script)
+        script = """probe begin { print("Running script, <Ctrl>-c to quit\\n") 
} """ + script
+    subprocess.call(["stap", "-e", script],
+                    env=tapset_env(tapsets))
+
+
+def cmd_list(args):
+    tapsets = tapset_dir(args.binary)
+
+    if args.verbose:
+        print("Using tapset dir '%s' for binary '%s'" % (tapsets, args.binary))
+
+    def print_probes(verbose, name):
+        prefix = probe_prefix(args.binary)
+        offset = len(prefix) + 1
+        script = prefix + "." + name
+
+        if verbose:
+            print("Listing probes with name '%s'" % script)
+        proc = subprocess.Popen(["stap", "-l", script],
+                                stdout=subprocess.PIPE, 
env=tapset_env(tapsets))
+        out, err = proc.communicate()
+        if proc.returncode != 0:
+            print("No probes found, are the tapsets installed in %s" % 
tapset_dir(args.binary))
+            sys.exit(1)
+
+        for line in out.splitlines():
+            if line.startswith(prefix):
+                print("%s" % line[offset:])
+
+    if len(args.probes) == 0:
+        print_probes(args.verbose, "*")
+    else:
+        for probe in args.probes:
+            print_probes(args.verbose, probe)
+
+
+def main():
+    parser = argparse.ArgumentParser(description="QEMU SystemTap trace tool")
+
+    subparser = parser.add_subparsers(help="commands")
+    subparser.required = True
+    subparser.dest = "command"
+
+    runparser = subparser.add_parser("run", help="Run a trace session",
+                                     
formatter_class=argparse.RawDescriptionHelpFormatter,
+                                     epilog="""
+
+To watch all trace points on the qemu-system-x86_64 binary:
+
+   %(argv0)s run qemu-system-x86_64
+
+To only watch the trace points matching the qio* and qcrypto* patterns
+
+   %(argv0)s run qemu-system-x86_64 qio* qcrypto*
+""" % {"argv0": sys.argv[0]})
+    runparser.set_defaults(func=cmd_run)
+    runparser.add_argument("-v", "--verbose", help="Print verbose progress 
info",
+                           action='store_true')
+    runparser.add_argument("binary", help="QEMU system or user emulator 
binary")
+    runparser.add_argument("probes", help="Probe names or wildcards",
+                           nargs=argparse.REMAINDER)
+
+    listparser = subparser.add_parser("list", help="List probe points",
+                                      
formatter_class=argparse.RawDescriptionHelpFormatter,
+                                      epilog="""
+
+To list all trace points on the qemu-system-x86_64 binary:
+
+   %(argv0)s list qemu-system-x86_64
+
+To only list the trace points matching the qio* and qcrypto* patterns
+
+   %(argv0)s list qemu-system-x86_64 qio* qcrypto*
+""" % {"argv0": sys.argv[0]})
+    listparser.set_defaults(func=cmd_list)
+    listparser.add_argument("-v", "--verbose", help="Print verbose progress 
info",
+                            action='store_true')
+    listparser.add_argument("binary", help="QEMU system or user emulator 
binary")
+    listparser.add_argument("probes", help="Probe names or wildcards",
+                            nargs=argparse.REMAINDER)
+
+    args = parser.parse_args()
+
+    args.func(args)
+    sys.exit(0)
+
+if __name__ == '__main__':
+    main()
diff --git a/scripts/tracetool/format/log_stap.py 
b/scripts/tracetool/format/log_stap.py
new file mode 100644
index 0000000000..c8d5e21fe9
--- /dev/null
+++ b/scripts/tracetool/format/log_stap.py
@@ -0,0 +1,75 @@
+#!/usr/bin/env python
+# -*- coding: utf-8 -*-
+
+"""
+Generate .stp file that printfs log messages (DTrace with SystemTAP only).
+"""
+
+__author__     = "Daniel P. Berrange <address@hidden>"
+__copyright__  = "Copyright (C) 2014-2019, Red Hat, Inc."
+__license__    = "GPL version 2 or (at your option) any later version"
+
+__maintainer__ = "Daniel Berrange"
+__email__      = "address@hidden"
+
+import re
+
+from tracetool import out
+from tracetool.backend.dtrace import binary, probeprefix
+from tracetool.backend.simple import is_string
+from tracetool.format.stap import stap_escape
+
+def global_var_name(name):
+    return probeprefix().replace(".", "_") + "_" + name
+
+def c_fmt_to_stap(fmt):
+    fmt = re.sub("\\\\\"", "'", fmt)
+    fmt = re.sub("\s*PRI(d|i)(64|32|16|8)\s*", "d", fmt)
+    fmt = re.sub("\s*PRIu(64|32|16|8)\s*", "u", fmt)
+    fmt = re.sub("\s*PRI(x|X)(64|32|16|8)\s*", "x", fmt)
+    fmt = re.sub("\s*PRIxPTR\s*", "p", fmt)
+    fmt = re.sub("%(\d*)z(x|u|d)", "%\\1\\2", fmt)
+    fmt = re.sub("\"", "", fmt)
+    return fmt
+
+def generate(events, backend, group):
+    out('/* This file is autogenerated by tracetool, do not edit. */',
+        '')
+
+    for event_id, e in enumerate(events):
+        if 'disable' in e.properties:
+            continue
+
+        out('probe %(probeprefix)s.log.%(name)s = %(probeprefix)s.%(name)s ?',
+            '{',
+            probeprefix=probeprefix(),
+            name=e.name)
+
+        # Get references to userspace strings
+        for type_, name in e.args:
+            name = stap_escape(name)
+            if is_string(type_):
+                out('    try {',
+                    '        arg%(name)s_str = %(name)s ? ' +
+                    'user_string_n(%(name)s, 512) : "<null>"',
+                    '    } catch {}',
+                    name=name)
+
+        # Determine systemtap's view of variable names
+        fields = ["pid()", "gettimeofday_ns()"]
+        for type_, name in e.args:
+            name = stap_escape(name)
+            if is_string(type_):
+                fields.append("arg" + name + "_str")
+            else:
+                fields.append(name)
+
+        # Emit the entire record in a single SystemTap printf()
+        arg_str = ', '.join(arg for arg in fields)
+        fmt_str = "address@hidden " + e.name + " " + c_fmt_to_stap(e.fmt) + 
"\\n"
+        out('    printf("%(fmt_str)s", %(arg_str)s)',
+            fmt_str=fmt_str, arg_str=arg_str)
+
+        out('}')
+
+    out()
-- 
2.20.1