diff --git a/docs/devel/index.rst b/docs/devel/index.rst index ea0e1e17ae6c..98a7016a9b21 100644 --- a/docs/devel/index.rst +++ b/docs/devel/index.rst @@ -28,6 +28,7 @@ Contents: secure-coding-practices tcg tcg-icount + tracing multi-thread-tcg tcg-plugins bitops diff --git a/docs/devel/tracing.txt b/docs/devel/tracing.rst similarity index 72% rename from docs/devel/tracing.txt rename to docs/devel/tracing.rst index dba43fc7a409..ba83954899d7 100644 --- a/docs/devel/tracing.txt +++ b/docs/devel/tracing.rst @@ -1,71 +1,94 @@ -= Tracing = +======= +Tracing +======= -== Introduction == +Introduction +============ This document describes the tracing infrastructure in QEMU and how to use it for debugging, profiling, and observing execution. -== Quickstart == +Quickstart +========== -1. Build with the 'simple' trace backend: +Enable tracing of ``memory_region_ops_read`` and ``memory_region_ops_write`` +events:: - ./configure --enable-trace-backends=simple - make + $ qemu --trace "memory_region_ops_*" ... + ... + 719585@1608130130.441188:memory_region_ops_read cpu 0 mr 0x562fdfbb3820 addr 0x3cc value 0x67 size 1 + 719585@1608130130.441190:memory_region_ops_write cpu 0 mr 0x562fdfbd2f00 addr 0x3d4 value 0x70e size 2 -2. Create a file with the events you want to trace: +This output comes from the "log" trace backend that is enabled by default when +``./configure --enable-trace-backends=BACKENDS`` was not explicitly specified. - echo memory_region_ops_read >/tmp/events +Multiple patterns can be specified by repeating the ``--trace`` option:: -3. Run the virtual machine to produce a trace file: + $ qemu --trace "kvm_*" --trace "virtio_*" ... - qemu --trace events=/tmp/events ... # your normal QEMU invocation +When patterns are used frequently it is more convenient to store them in a +file to avoid long command-line options:: -4. Pretty-print the binary trace file: + $ echo "memory_region_ops_*" >/tmp/events + $ echo "kvm_*" >>/tmp/events + $ qemu --trace events=/tmp/events ... - ./scripts/simpletrace.py trace-events-all trace-* # Override * with QEMU +Trace events +============ -== Trace events == +Sub-directory setup +------------------- -=== Sub-directory setup === - -Each directory in the source tree can declare a set of static trace events -in a local "trace-events" file. All directories which contain "trace-events" -files must be listed in the "trace-events-subdirs" make variable in the top -level Makefile.objs. During build, the "trace-events" file in each listed -subdirectory will be processed by the "tracetool" script to generate code for -the trace events. +Each directory in the source tree can declare a set of trace events in a local +"trace-events" file. All directories which contain "trace-events" files must be +listed in the "trace_events_subdirs" variable in the top level meson.build +file. During build, the "trace-events" file in each listed subdirectory will be +processed by the "tracetool" script to generate code for the trace events. The individual "trace-events" files are merged into a "trace-events-all" file, which is also installed into "/usr/share/qemu" with the name "trace-events". This merged file is to be used by the "simpletrace.py" script to later analyse traces in the simpletrace data format. -In the sub-directory the following files will be automatically generated +The following files are automatically generated in /trace/ during the +build: + + - trace-.c - the trace event state declarations + - trace-.h - the trace event enums and probe functions + - trace-dtrace-.h - DTrace event probe specification + - trace-dtrace-.dtrace - DTrace event probe helper declaration + - trace-dtrace-.o - binary DTrace provider (generated by dtrace) + - trace-ust-.h - UST event probe helper declarations - - trace.c - the trace event state declarations - - trace.h - the trace event enums and probe functions - - trace-dtrace.h - DTrace event probe specification - - trace-dtrace.dtrace - DTrace event probe helper declaration - - trace-dtrace.o - binary DTrace provider (generated by dtrace) - - trace-ust.h - UST event probe helper declarations +Here is the sub-directory path with '/' replaced by '_'. For example, +"accel/kvm" becomes "accel_kvm" and the final filename for "trace-.c" +becomes "trace-accel_kvm.c". -Source files in the sub-directory should #include the local 'trace.h' file, -without any sub-directory path prefix. eg io/channel-buffer.c would do +Source files in the source tree do not directly include generated files in +"/trace/". Instead they #include the local "trace.h" file, without +any sub-directory path prefix. eg io/channel-buffer.c would do:: #include "trace.h" -To access the 'io/trace.h' file. While it is possible to include a trace.h -file from outside a source file's own sub-directory, this is discouraged in -general. It is strongly preferred that all events be declared directly in -the sub-directory that uses them. The only exception is where there are some -shared trace events defined in the top level directory trace-events file. -The top level directory generates trace files with a filename prefix of -"trace/trace-root" instead of just "trace". This is to avoid ambiguity between -a trace.h in the current directory, vs the top level directory. +The "io/trace.h" file must be created manually with an #include of the +corresponding "trace/trace-.h" file that will be generated in the +builddir:: + + $ echo '#include "trace/trace-io.h"' >io/trace.h + +While it is possible to include a trace.h file from outside a source file's own +sub-directory, this is discouraged in general. It is strongly preferred that +all events be declared directly in the sub-directory that uses them. The only +exception is where there are some shared trace events defined in the top level +directory trace-events file. The top level directory generates trace files +with a filename prefix of "trace/trace-root" instead of just "trace". This is +to avoid ambiguity between a trace.h in the current directory, vs the top level +directory. -=== Using trace events === +Using trace events +------------------ -Trace events are invoked directly from source code like this: +Trace events are invoked directly from source code like this:: #include "trace.h" /* needed for trace event prototype */ @@ -82,7 +105,8 @@ Trace events are invoked directly from source code like this: return ptr; } -=== Declaring trace events === +Declaring trace events +---------------------- The "tracetool" script produces the trace.h header file which is included by every source file that uses trace events. Since many source files include @@ -116,13 +140,14 @@ Format strings must not end with a newline character. It is the responsibility of backends to adapt line ending for proper logging. Each event declaration will start with the event name, then its arguments, -finally a format string for pretty-printing. For example: +finally a format string for pretty-printing. For example:: qemu_vmalloc(size_t size, void *ptr) "size %zu ptr %p" qemu_vfree(void *ptr) "ptr %p" -=== Hints for adding new trace events === +Hints for adding new trace events +--------------------------------- 1. Trace state changes in the code. Interesting points in the code usually involve a state change like starting, stopping, allocating, freeing. State @@ -141,7 +166,8 @@ finally a format string for pretty-printing. For example: 4. Name trace events after their function. If there are multiple trace events in one function, append a unique distinguisher at the end of the name. -== Generic interface and monitor commands == +Generic interface and monitor commands +====================================== You can programmatically query and control the state of trace events through a backend-agnostic interface provided by the header "trace/control.h". @@ -152,11 +178,11 @@ header "trace/control.h" to see which routines are backend-dependent). The state of events can also be queried and modified through monitor commands: -* info trace-events +* ``info trace-events`` View available trace events and their state. State 1 means enabled, state 0 means disabled. -* trace-event NAME on|off +* ``trace-event NAME on|off`` Enable/disable a given trace event or a group of events (using wildcards). The "--trace events=" command line argument can be used to enable the @@ -170,11 +196,12 @@ to enable an entire family of events but one noisy event needs to be disabled. Wildcard matching is supported in both the monitor command "trace-event" and the events list file. That means you can enable/disable the events having a common prefix in a batch. For example, virtio-blk trace events could be enabled using -the following monitor command: +the following monitor command:: trace-event virtio_blk_* on -== Trace backends == +Trace backends +============== The "tracetool" script automates tedious trace event code generation and also keeps the trace event declarations independent of the trace backend. The trace @@ -182,9 +209,9 @@ events are not tightly coupled to a specific trace backend, such as LTTng or SystemTap. Support for trace backends can be added by extending the "tracetool" script. -The trace backends are chosen at configure time: +The trace backends are chosen at configure time:: - ./configure --enable-trace-backends=simple + ./configure --enable-trace-backends=simple,dtrace For a list of supported trace backends, try ./configure --help or see below. If multiple backends are enabled, the trace is sent to them all. @@ -194,7 +221,8 @@ If no backends are explicitly selected, configure will default to the The following subsections describe the supported trace backends. -=== Nop === +Nop +--- The "nop" backend generates empty trace event functions so that the compiler can optimize out trace events completely. This imposes no performance @@ -203,7 +231,8 @@ penalty. Note that regardless of the selected trace backend, events with the "disable" property will be generated with the "nop" backend. -=== Log === +Log +--- The "log" backend sends trace events directly to standard error. This effectively turns trace events into debug printfs. @@ -211,30 +240,56 @@ effectively turns trace events into debug printfs. This is the simplest backend and can be used together with existing code that uses DPRINTF(). -=== Simpletrace === +The -msg timestamp=on|off command-line option controls whether or not to print +the tid/timestamp prefix for each trace event. + +Simpletrace +----------- + +The "simple" backend writes binary trace logs to a file from a thread, making +it lower overhead than the "log" backend. A Python API is available for writing +offline trace file analysis scripts. It may not be as powerful as +platform-specific or third-party trace backends but it is portable and has no +special library dependencies. + +Monitor commands +~~~~~~~~~~~~~~~~ + +* ``trace-file on|off|flush|set `` + Enable/disable/flush the trace file or set the trace file name. + +Analyzing trace files +~~~~~~~~~~~~~~~~~~~~~ + +The "simple" backend produces binary trace files that can be formatted with the +simpletrace.py script. The script takes the "trace-events-all" file and the +binary trace:: + + ./scripts/simpletrace.py trace-events-all trace-12345 -The "simple" backend supports common use cases and comes as part of the QEMU -source tree. It may not be as powerful as platform-specific or third-party -trace backends but it is portable. This is the recommended trace backend -unless you have specific needs for more advanced backends. +You must ensure that the same "trace-events-all" file was used to build QEMU, +otherwise trace event declarations may have changed and output will not be +consistent. -=== Ftrace === +Ftrace +------ The "ftrace" backend writes trace data to ftrace marker. This effectively sends trace events to ftrace ring buffer, and you can compare qemu trace data and kernel(especially kvm.ko when using KVM) trace data. -if you use KVM, enable kvm events in ftrace: +if you use KVM, enable kvm events in ftrace:: # echo 1 > /sys/kernel/debug/tracing/events/kvm/enable -After running qemu by root user, you can get the trace: +After running qemu by root user, you can get the trace:: # cat /sys/kernel/debug/tracing/trace Restriction: "ftrace" backend is restricted to Linux only. -=== Syslog === +Syslog +------ The "syslog" backend sends trace events using the POSIX syslog API. The log is opened specifying the LOG_DAEMON facility and LOG_PID option (so events @@ -246,24 +301,8 @@ NOTE: syslog may squash duplicate consecutive trace events and apply rate Restriction: "syslog" backend is restricted to POSIX compliant OS. -==== Monitor commands ==== - -* trace-file on|off|flush|set - Enable/disable/flush the trace file or set the trace file name. - -==== Analyzing trace files ==== - -The "simple" backend produces binary trace files that can be formatted with the -simpletrace.py script. The script takes the "trace-events-all" file and the -binary trace: - - ./scripts/simpletrace.py trace-events-all trace-12345 - -You must ensure that the same "trace-events-all" file was used to build QEMU, -otherwise trace event declarations may have changed and output will not be -consistent. - -=== LTTng Userspace Tracer === +LTTng Userspace Tracer +---------------------- The "ust" backend uses the LTTng Userspace Tracer library. There are no monitor commands built into QEMU, instead UST utilities should be used to list, @@ -275,43 +314,44 @@ lttng-sessiond daemon for the current user prior to running any instance of QEMU. While running an instrumented QEMU, LTTng should be able to list all available -events: +events:: lttng list -u -Create tracing session: +Create tracing session:: lttng create mysession -Enable events: +Enable events:: lttng enable-event qemu:g_malloc -u Where the events can either be a comma-separated list of events, or "-a" to -enable all tracepoint events. Start and stop tracing as needed: +enable all tracepoint events. Start and stop tracing as needed:: lttng start lttng stop -View the trace: +View the trace:: lttng view -Destroy tracing session: +Destroy tracing session:: lttng destroy -Babeltrace can be used at any later time to view the trace: +Babeltrace can be used at any later time to view the trace:: babeltrace $HOME/lttng-traces/mysession--