| Message ID | 20190118173103.4903-5-berrange@redhat.com (mailing list archive) |
|---|---|
| State | New, archived |
| Headers | show |
| Series | trace: make systemtap easier to use for simple logging | expand |
On 1/18/19 11:31 AM, Daniel P. Berrangé wrote: > 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...." > > 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* > 22806@1547735341399856820 qio_channel_socket_new Socket new ioc=0x56135d1d7c00 One thing I did not immediately get on the first read, and therefore which may be worth mentioning in the docs portion of the patch: Am I correct that stap is always run as a separate process from the process(es) being traced, and that you can start the two in either order (qemu first, then stap; or stap first, then qemu), where the tracing is effectively output as long as both processes are running and trace points being hit in the qemu process? > Signed-off-by: Daniel P. Berrangé <berrange@redhat.com> > --- > Makefile | 3 + > Makefile.target | 11 +- > docs/devel/tracing.txt | 32 +++++ > scripts/qemu-trace-stap | 167 +++++++++++++++++++++++++++ > scripts/tracetool/format/log_stap.py | 127 ++++++++++++++++++++ Overall, I'm impressed with the concept, but my familiarity with stap and python is weak enough that I'm not leaving a formal R-b. Still, I'll give it a shot at looking for anything that stands out as I read through. > 5 files changed, 339 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 dccba1dca2..22e481e7ba 100644 > --- a/Makefile > +++ b/Makefile > @@ -736,6 +736,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 No man page being installed? If we're planning on this binary being available on a similar par with qemu-io, it deserves some installed documentation. > +++ b/docs/devel/tracing.txt > @@ -317,6 +317,38 @@ probes: > --target-name x86_64 \ > <trace-events-all >qemu.stp > > +To facilitate simple usage of systemtap where there merely needs to be printf > +logging of certain probes, a helper script "qemu-trace-stap" is provided > + Trailing '.' would look better > +This can list all probes available for a given QEMU emulator binary: > + > + $ 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... > + > +Optionally restricted to a pattern prefix: > + > + $ qemu-trace-stap list qemu-system-x86_64 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... > + > +It can then run a simple systemtap script which prints each requested probe Trailing ':' would look better > + > + $ qemu-trace-stap run qemu-system-x86_64 qio* > + 22806@1547735341399856820 qio_channel_socket_new Socket new ioc=0x56135d1d7c00 > + 22806@1547735341399862570 qio_task_new Task new task=0x56135cd66eb0 source=0x56135d1d7c00 func=0x56135af746c0 opaque=0x56135bf06400 > + 22806@1547735341399865943 qio_task_thread_start Task thread start task=0x56135cd66eb0 worker=0x56135af72e50 opaque=0x56135c071d70 > + 22806@1547735341399976816 qio_task_thread_run Task thread run task=0x56135cd66eb0 > + > +++ b/scripts/qemu-trace-stap > + > +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* This output is not copy-pastable - it includes shell globs which might inadvertantly expand based on the contents of $PWD. Should you amend the output to be properly quoted for reuse in shell commands? > +""" % {"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* and again > +""" % {"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..3ccbc09d61 > --- /dev/null > +++ b/scripts/tracetool/format/log_stap.py > @@ -0,0 +1,127 @@ > +#!/usr/bin/env python > +# -*- coding: utf-8 -*- > + > +""" > +Generate .stp file that printfs log messages (DTrace with SystemTAP only). > +""" > + > +__author__ = "Daniel P. Berrange <berrange@redhat.com>" > +__copyright__ = "Copyright (C) 2014-2019, Red Hat, Inc." > +__license__ = "GPL version 2 or (at your option) any later version" > + > +__maintainer__ = "Daniel Berrange" > +__email__ = "berrange@redhat.com" > + > +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 > + > +STATE_SKIP = 0 > +STATE_LITERAL = 1 > +STATE_MACRO = 2 > + > +def c_macro_to_format(macro): > + if macro.startswith("PRI"): > + return macro[3] > + > + if macro == "TARGET_FMT_plx": > + return "%016x" Do we really want to permit TARGET_FMT in our trace-events files, or should that be fixed in hw/tpm/trace-events? See commit 73ff0610.
On Fri, Jan 18, 2019 at 12:14:14PM -0600, Eric Blake wrote: > On 1/18/19 11:31 AM, Daniel P. Berrangé wrote: > > +def c_macro_to_format(macro): > > + if macro.startswith("PRI"): > > + return macro[3] > > + > > + if macro == "TARGET_FMT_plx": > > + return "%016x" > > Do we really want to permit TARGET_FMT in our trace-events files, or > should that be fixed in hw/tpm/trace-events? See commit 73ff0610. TARGET_FMT_plx is constant across all QEMU targets. I think supporting it is nice since it makes writing trace events more natural/convenient. Stefan
On Mon, Jan 21, 2019 at 10:53:14AM +0000, Stefan Hajnoczi wrote: > On Fri, Jan 18, 2019 at 12:14:14PM -0600, Eric Blake wrote: > > On 1/18/19 11:31 AM, Daniel P. Berrangé wrote: > > > +def c_macro_to_format(macro): > > > + if macro.startswith("PRI"): > > > + return macro[3] > > > + > > > + if macro == "TARGET_FMT_plx": > > > + return "%016x" > > > > Do we really want to permit TARGET_FMT in our trace-events files, or > > should that be fixed in hw/tpm/trace-events? See commit 73ff0610. > > TARGET_FMT_plx is constant across all QEMU targets. I think supporting > it is nice since it makes writing trace events more natural/convenient. Yep, I'm fine with supporting custom macros beyond PRI* in trace-events, provided that they can be subsituted out with a simple formats code for stap. Regards, Daniel
On Fri, Jan 18, 2019 at 12:14:14PM -0600, Eric Blake wrote: > On 1/18/19 11:31 AM, Daniel P. Berrangé wrote: > > 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...." > > > > > 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* > > 22806@1547735341399856820 qio_channel_socket_new Socket new ioc=0x56135d1d7c00 > > One thing I did not immediately get on the first read, and therefore > which may be worth mentioning in the docs portion of the patch: > > Am I correct that stap is always run as a separate process from the > process(es) being traced, and that you can start the two in either order > (qemu first, then stap; or stap first, then qemu), where the tracing is > effectively output as long as both processes are running and trace > points being hit in the qemu process? If you're using the stap binary directly you have a choice of it working against any existing process on the system, or you can have it launch the process on your behalf and target just that one process. For our wrapper script I'm only targetting the former, since I think the common case is that someone/something else has already run the QEMU process. I could however easily add a "-p PID" option too which would allow the trace to be tailored to a specific QEMU process, instead of all running QEMU processes. And yes, there's no ordering dependancy - unless it is critical that you see traces from QEMU's early initialization of course, in which case you'd launch the tracing first. > > 5 files changed, 339 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 dccba1dca2..22e481e7ba 100644 > > --- a/Makefile > > +++ b/Makefile > > @@ -736,6 +736,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 > > No man page being installed? If we're planning on this binary being > available on a similar par with qemu-io, it deserves some installed > documentation. Heh, no good deed / quick enhancement goes unpunished :-P Yes, I'll do a proper job of this and write a man page too :-) > > +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* > > This output is not copy-pastable - it includes shell globs which might > inadvertantly expand based on the contents of $PWD. Should you amend the > output to be properly quoted for reuse in shell commands? Yes, that is true Regards, Daniel
diff --git a/Makefile b/Makefile index dccba1dca2..22e481e7ba 100644 --- a/Makefile +++ b/Makefile @@ -736,6 +736,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 39f72e81be..401dc1ea6f 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 @@ -227,6 +235,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/docs/devel/tracing.txt b/docs/devel/tracing.txt index bc52f12485..53327cd35b 100644 --- a/docs/devel/tracing.txt +++ b/docs/devel/tracing.txt @@ -317,6 +317,38 @@ probes: --target-name x86_64 \ <trace-events-all >qemu.stp +To facilitate simple usage of systemtap where there merely needs to be printf +logging of certain probes, a helper script "qemu-trace-stap" is provided + +This can list all probes available for a given QEMU emulator binary: + + $ 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... + +Optionally restricted to a pattern prefix: + + $ qemu-trace-stap list qemu-system-x86_64 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... + +It can then run a simple systemtap script which prints each requested probe + + $ qemu-trace-stap run qemu-system-x86_64 qio* + 22806@1547735341399856820 qio_channel_socket_new Socket new ioc=0x56135d1d7c00 + 22806@1547735341399862570 qio_task_new Task new task=0x56135cd66eb0 source=0x56135d1d7c00 func=0x56135af746c0 opaque=0x56135bf06400 + 22806@1547735341399865943 qio_task_thread_start Task thread start task=0x56135cd66eb0 worker=0x56135af72e50 opaque=0x56135c071d70 + 22806@1547735341399976816 qio_task_thread_run Task thread run task=0x56135cd66eb0 + == Trace event properties == Each event in the "trace-events-all" file can be prefixed with a space-separated diff --git a/scripts/qemu-trace-stap b/scripts/qemu-trace-stap new file mode 100755 index 0000000000..2db7b1470c --- /dev/null +++ b/scripts/qemu-trace-stap @@ -0,0 +1,167 @@ +#!/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(binary): + for path in os.environ["PATH"].split(os.pathsep): + if os.path.exists(os.path.join(path, binary)): + return os.path.join(path, binary) + + print("Unable to find '%s' in $PATH" % binary) + sys.exit(1) + + +def tapset_dir(binary): + dirname, filename = os.path.split(binary) + if dirname == '': + thisfile = which(binary) + else: + thisfile = os.path.realpath(binary) + if not os.path.exists(thisfile): + print("Unable to find '%s'" % thisfile) + sys.exit(1) + + 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..3ccbc09d61 --- /dev/null +++ b/scripts/tracetool/format/log_stap.py @@ -0,0 +1,127 @@ +#!/usr/bin/env python +# -*- coding: utf-8 -*- + +""" +Generate .stp file that printfs log messages (DTrace with SystemTAP only). +""" + +__author__ = "Daniel P. Berrange <berrange@redhat.com>" +__copyright__ = "Copyright (C) 2014-2019, Red Hat, Inc." +__license__ = "GPL version 2 or (at your option) any later version" + +__maintainer__ = "Daniel Berrange" +__email__ = "berrange@redhat.com" + +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 + +STATE_SKIP = 0 +STATE_LITERAL = 1 +STATE_MACRO = 2 + +def c_macro_to_format(macro): + if macro.startswith("PRI"): + return macro[3] + + if macro == "TARGET_FMT_plx": + return "%016x" + + raise Exception("Unhandled macro '%s'" % macro) + +def c_fmt_to_stap(fmt): + state = 0 + bits = [] + literal = "" + macro = "" + escape = 0; + for i in range(len(fmt)): + if fmt[i] == '\\': + if escape: + escape = 0 + else: + escape = 1 + if state != STATE_LITERAL: + raise Exception("Unexpected escape outside string literal") + literal = literal + fmt[i] + elif fmt[i] == '"' and not escape: + if state == STATE_LITERAL: + state = STATE_SKIP + bits.append(literal) + literal = "" + else: + if state == STATE_MACRO: + bits.append(c_macro_to_format(macro)) + state = STATE_LITERAL + elif fmt[i] == ' ' or fmt[i] == '\t': + if state == STATE_MACRO: + bits.append(c_macro_to_format(macro)) + macro = "" + state = STATE_SKIP + elif state == STATE_LITERAL: + literal = literal + fmt[i] + else: + escape = 0 + if state == STATE_SKIP: + state = STATE_MACRO + + if state == STATE_LITERAL: + literal = literal + fmt[i] + else: + macro = macro + fmt[i] + + if state == STATE_MACRO: + bits.append(c_macro_to_format(macro)) + elif state == STATE_LITERAL: + bits.append(literal) + + fmt = re.sub("%(\d*)z(x|u|d)", "%\\1\\2", "".join(bits)) + 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 = "%d@%d " + 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()
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... 23266@1547735759.137292:qio_channel_socket_new Socket new ioc=0x563a8a39d400 23266@1547735759.137305:qio_task_new Task new task=0x563a891d0570 source=0x563a8a39d400 func=0x563a86f1e6c0 opaque=0x563a89078000 23266@1547735759.137326:qio_task_thread_start Task thread start task=0x563a891d0570 worker=0x563a86f1ce50 opaque=0x563a891d9d90 23273@1547735759.137491:qio_task_thread_run Task thread run task=0x563a891d0570 23273@1547735759.137503:qio_channel_socket_connect_sync Socket connect sync ioc=0x563a8a39d400 addr=0x563a891d9d90 23273@1547735759.138108: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*{}' 22806@1547735341399856820 qio_channel_socket_new Socket new ioc=0x56135d1d7c00 22806@1547735341399862570 qio_task_new Task new task=0x56135cd66eb0 source=0x56135d1d7c00 func=0x56135af746c0 opaque=0x56135bf06400 22806@1547735341399865943 qio_task_thread_start Task thread start task=0x56135cd66eb0 worker=0x56135af72e50 opaque=0x56135c071d70 22806@1547735341399976816 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* 22806@1547735341399856820 qio_channel_socket_new Socket new ioc=0x56135d1d7c00 22806@1547735341399862570 qio_task_new Task new task=0x56135cd66eb0 source=0x56135d1d7c00 func=0x56135af746c0 opaque=0x56135bf06400 22806@1547735341399865943 qio_task_thread_start Task thread start task=0x56135cd66eb0 worker=0x56135af72e50 opaque=0x56135c071d70 22806@1547735341399976816 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é <berrange@redhat.com> --- Makefile | 3 + Makefile.target | 11 +- docs/devel/tracing.txt | 32 +++++ scripts/qemu-trace-stap | 167 +++++++++++++++++++++++++++ scripts/tracetool/format/log_stap.py | 127 ++++++++++++++++++++ 5 files changed, 339 insertions(+), 1 deletion(-) create mode 100755 scripts/qemu-trace-stap create mode 100644 scripts/tracetool/format/log_stap.py