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

[Eric Blake]

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*
>  address@hidden 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é <address@hidden>
> ---
>  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*
> +     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
> +

> +++ 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 <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
> +
> +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.

-- 
Eric Blake, Principal Software Engineer
Red Hat, Inc.           +1-919-301-3226
Virtualization:  qemu.org | libvirt.org

signature.asc
Description: OpenPGP digital signature