[RFC v2][PATCH 0/7] perf: 'live mode'

From: Tom Zanussi
Date: Fri Apr 02 2010 - 00:59:42 EST

Next message: Tom Zanussi: "[RFC v2][PATCH 02/11] perf record: introduce special handling for pipe output"
Previous message: Tom Zanussi: "[PATCH] perf/scripts: tuple was set from long in both branches inpython_process_event()"
Next in thread: Tom Zanussi: "[RFC v2][PATCH 02/11] perf record: introduce special handling for pipe output"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]

Currently, a perf session entails two steps: first 'perf record' or
'perf trace record' records the perf data to disk, then 'perf report'
or 'perf trace report' reads the saved data from disk and reports the
results.

This experimental patchset makes some changes to perf that instead
allow the perf data to be piped directly from the record step to the
report step, without ever touching the disk.

This is especially useful for 'perf trace' - adding this capability
means that the trace scripts are no longer relegated to simple
post-processing, but can be run in a continuous 'live mode', forever
processing the event stream and e.g. periodically dumping current
results, essentially becoming special-purpose 'top' applications, or
continuously scanning the event stream for arbitrarily complex
conditions to flag, etc...

Being able to feed the event stream over a pipe also makes it possible
to do things like trace over the network using e.g. netcat.

It turns out that perf is pretty close to being able to do this
already, with the exception of the header data; most of the work of
this patchset deals with changing that. It does so in a mainly
additive way: it doesn't make any changes to the existing disk format
or normal disk-mode processing, just adds special treatment for the
cases when 'perf [trace] record' records to stdout or 'perf [trace]
report reads from stdin.

v2 changes:

- any script in the 'perf trace -l' list can now be run in 'live mode'
automatically by simply specifying the script name [with options] e.g.

$ perf trace syscall-counts

will run both ends of the the syscall-counts script with a pipe in
between, a more usable shorthand for:

$ perf trace record syscall-counts -o - | perf trace report syscall-counts -i -

which itself is shorthand for:

perf record -c 1 -f -a -M -R -e raw_syscalls:sys_enter -o - | perf trace -i - -s ~/libexec/perf-core/scripts/python/syscall-counts.py

- adds and use a term_clear() function for the 'top' scripts (thanks
to Ingo Monlar for the suggestion)

Here are some quick examples. Basically using '-' as the filename to
the -o and -i options send/read the data from stdout/stdin:

Here's a simple 'perf record' | 'perf report' run:

root@tropicana:~# perf record -o - -c 1 -f -a -M -R -e raw_syscalls:sys_enter | perf report -i -

^C# Samples: 376819
#
# Overhead Command Shared Object Symbol
# ........ ............... ................. ......
#
99.94% perf [kernel.kallsyms] [k] syscall_trace_enter
0.04% Xorg [kernel.kallsyms] [k] syscall_trace_enter
0.00% hald-addon-stor [kernel.kallsyms] [k] syscall_trace_enter
0.00% gvfsd-trash [kernel.kallsyms] [k] syscall_trace_enter
0.00% nautilus [kernel.kallsyms] [k] syscall_trace_enter
0.00% firefox [kernel.kallsyms] [k] syscall_trace_enter
0.00% gnome-screensav [kernel.kallsyms] [k] syscall_trace_enter
0.00% wterm [kernel.kallsyms] [k] syscall_trace_enter
0.00% mysqld [kernel.kallsyms] [k] syscall_trace_enter
0.00% gnome-settings- [kernel.kallsyms] [k] syscall_trace_enter
0.00% update-notifier [kernel.kallsyms] [k] syscall_trace_enter
0.00% apache2 [kernel.kallsyms] [k] syscall_trace_enter

#
# (For a higher level overview, try: perf report --sort comm,dso)
#

Included in this patchset are a couple of 'top' scripts, rwtop and
sctop, that are essentially just modifications of existing scripts.
The original scripts were modified to add a 3-second timer and a
screen clear after each print iteration. In the handler for the
timer, the previous screen contents are erased, the current output
summary is printed, and the state is cleared and begun anew, ad
infinitum.

Here are the new scripts as shown in the perf trace list:

root@tropicana:~# perf trace -l
List of available trace scripts:
workqueue-stats workqueue stats (ins/exe/create/destroy)
wakeup-latency system-wide min/max/avg wakeup latency
rw-by-file <comm> r/w activity for a program, by file
rwtop [interval] system-wide r/w top
failed-syscalls [comm] system-wide failed syscalls
rw-by-pid system-wide r/w activity
syscall-counts-by-pid [comm] system-wide syscall counts, by pid
failed-syscalls-by-pid [comm] system-wide failed syscalls, by pid
sctop [comm] [interval] syscall top
syscall-counts [comm] system-wide syscall counts

And here's a sample of the output of the 'sctop' Python script:

root@tropicana:~# perf trace sctop
syscall events:

event count
---------------------------------------- ----------
sys_read 383576
sys_poll 144
sys_futex 97
sys_brk 33
sys_write 20
sys_select 11
sys_open 10
sys_inotify_add_watch 4
sys_setitimer 4
sys_writev 4
sys_wait4 1
sys_exit 1
56 1
sys_alarm 1
sys_ioctl 1
15 1
sys_rt_sigaction 1
sys_close 1
^C
perf trace Python script stopped

This shows just the last iteration - the script in real life
continuously erases and displays the previous interval's results.

Note that the scripts in this patchset will only show the syscall
numbers in the output, not the names as shown here - I just happened
to have the 'export some syscall metadata' patches previously posted
applied as well when I ran this script.

Lastly, here's an example that uses netcat to run the 'rwtop' Perl
script over the network:

On the system collecting the data and printing the output every 3
seconds:

root@tropicana:~# nc -l -p 7777 | perf trace report rwtop -i -

On the system being traced:

root@tropicana:~# perf trace record rwtop -o - | nc localhost 7777

read counts by pid:

pid comm # reads bytes_req bytes_read
------ -------------------- ---------- ---------- ----------
9580 nc 606 4964352 5382144
9578 perf 72256 3178656 3178448
9575 nc 379 3104768 3104768
5856 Xorg 148 386320 3980
6265 metacity 105 430080 1440
6325 gnome-screensav 110 450560 1024
6261 gnome-settings- 3 12288 32
6678 wterm 5 20480 32

write counts by pid:

pid comm # writes bytes_written
------ -------------------- ---------- -------------
9580 nc 657 5382144
9575 nc 379 3104768

perf trace Perl script stopped

I just noticed a hashtable error in this script when running it over
netcat just now, which is part of the reason it's an RFC patchset - it
still needs more testing, though other than that I haven't seen many
problems with it.

Tom

Tom Zanussi (11):
perf: add pipe-specific header read/write and event processing code
perf record: introduce special handling for pipe output
perf report: introduce special handling for pipe input
perf trace: introduce special handling for pipe input
perf: convert perf header attrs into attr events
perf: convert perf event types into event type events
perf: convert perf tracing data into a tracing_data event
perf: convert perf header build_ids into build_id events
perf trace/scripting: rwtop and sctop scripts
perf trace/scripting: enable scripting shell scripts for live mode
perf trace: invoke live mode automatically if record/report not
specified

tools/perf/builtin-record.c | 68 ++++-
tools/perf/builtin-report.c | 16 +-
tools/perf/builtin-trace.c | 75 ++++-
.../perl/Perf-Trace-Util/lib/Perf/Trace/Util.pm | 6 +
tools/perf/scripts/perl/bin/failed-syscalls-record | 2 +-
tools/perf/scripts/perl/bin/failed-syscalls-report | 8 +-
tools/perf/scripts/perl/bin/rw-by-file-record | 3 +-
tools/perf/scripts/perl/bin/rw-by-file-report | 8 +-
tools/perf/scripts/perl/bin/rw-by-pid-record | 2 +-
tools/perf/scripts/perl/bin/rw-by-pid-report | 2 +-
tools/perf/scripts/perl/bin/rwtop-record | 2 +
tools/perf/scripts/perl/bin/rwtop-report | 23 ++
tools/perf/scripts/perl/bin/wakeup-latency-record | 2 +-
tools/perf/scripts/perl/bin/wakeup-latency-report | 2 +-
tools/perf/scripts/perl/bin/workqueue-stats-record | 2 +-
tools/perf/scripts/perl/bin/workqueue-stats-report | 2 +-
tools/perf/scripts/perl/rwtop.pl | 177 ++++++++++
.../python/Perf-Trace-Util/lib/Perf/Trace/Util.py | 3 +
.../python/bin/failed-syscalls-by-pid-record | 2 +-
.../python/bin/failed-syscalls-by-pid-report | 8 +-
tools/perf/scripts/python/bin/sctop-record | 2 +
tools/perf/scripts/python/bin/sctop-report | 24 ++
.../python/bin/syscall-counts-by-pid-record | 2 +-
.../python/bin/syscall-counts-by-pid-report | 8 +-
.../perf/scripts/python/bin/syscall-counts-record | 2 +-
.../perf/scripts/python/bin/syscall-counts-report | 8 +-
tools/perf/scripts/python/sctop.py | 78 +++++
tools/perf/util/event.h | 35 ++
tools/perf/util/header.c | 361 ++++++++++++++++++--
tools/perf/util/header.h | 38 ++-
tools/perf/util/session.c | 192 ++++++++++-
tools/perf/util/session.h | 10 +-
tools/perf/util/trace-event-info.c | 24 ++
tools/perf/util/trace-event-read.c | 89 +++---
tools/perf/util/trace-event.h | 4 +-
35 files changed, 1184 insertions(+), 106 deletions(-)
create mode 100644 tools/perf/scripts/perl/bin/rwtop-record
create mode 100644 tools/perf/scripts/perl/bin/rwtop-report
create mode 100644 tools/perf/scripts/perl/rwtop.pl
create mode 100644 tools/perf/scripts/python/bin/sctop-record
create mode 100644 tools/perf/scripts/python/bin/sctop-report
create mode 100644 tools/perf/scripts/python/sctop.py

--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/

Next message: Tom Zanussi: "[RFC v2][PATCH 02/11] perf record: introduce special handling for pipe output"
Previous message: Tom Zanussi: "[PATCH] perf/scripts: tuple was set from long in both branches inpython_process_event()"
Next in thread: Tom Zanussi: "[RFC v2][PATCH 02/11] perf record: introduce special handling for pipe output"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]