[PATCH 00/12] perf trace: Python scripting support
in [Kernel]
|
Prev: [PATCH v3 2/2] cpufreq: ondemand: Independent max speed for nice threads with nice_max_freq
Next: tracing: fixes and documentation updates
From: Tom Zanussi on 27 Jan 2010 03:40 This patchset adds a Python scripting engine to perf trace. In the process, it also creates a scripting-engines directory under perf/util and moves the existing Perl support there, to avoid cluttering the main perf/util directory with scripting support files. It also includes some minor bugfixes and adds Documentation for the Python support, which includes a step-by-step example detailing how to write a new trace stream processing script using Python. Finally, it adds several new scripts, all dealing with aggregation of system call trace data. To make those scripts more user-friendly, it adds a couple patches that export some of the syscall metadata, enough to allow syscall names rather than raw numbers to be printed in the output. NOTE: in order to run the 'record' side of these scripts, you need to first revert commit f5a2c3dce03621b55f84496f58adc2d1a87ca16f "perf record: Intercept all events" - recording the syscall events seems to always trigger the infinite loop in there. Here's the new current listing of available scripts: # 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 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 syscall-counts [comm] system-wide syscall counts And some sample output from the four new ones: The 'syscall-counts' script just gives a high-level overview of all syscalls on the system, listed by syscall: root(a)tropicana:~# perf trace record syscall-counts ^C[ perf record: Woken up 1 times to write data ] [ perf record: Captured and wrote 32.165 MB perf.data (~1405309 samples) ] root(a)tropicana:~# perf trace report syscall-counts syscall events: event count ---------------------------------------- ----------- sys_write 269407 sys_getdents 2782 sys_close 2004 sys_swapoff 1095 sys_read 920 sys_sched_setparam 511 sys_open 331 sys_newfstat 326 sys_mmap 217 sys_munmap 216 sys_select 173 sys_getgid 128 sys_futex 89 sys_poll 76 174 64 sys_setuid 64 sys_setitimer 50 15 25 sys_rt_sigprocmask 24 sys_lseek 7 sys_inotify_add_watch 6 sys_writev 5 sys_ioctl 5 sys_wait4 2 sys_perf_event_open 1 sys_fcntl 1 The 'syscall-counts-by-pid' script dives down into more detail, listing the system calls by comm/pid: root(a)tropicana:~# perf trace report syscall-counts syscall events by comm/pid: comm [pid]/syscalls count ---------------------------------------- ---------- gnome-screensav [6351] sys_read 8 sys_poll 2 firefox [6505] sys_futex 72 sys_write 19 firefox [6502] sys_read 61 sys_select 41 sys_poll 41 sys_futex 17 sys_inotify_add_watch 2 sys_write 1 perf [13629] sys_write 269386 sys_read 790 sys_newfstat 326 sys_open 326 sys_close 324 sys_getdents 222 sys_mmap 217 sys_munmap 216 sys_lseek 7 sys_ioctl 4 sys_perf_event_open 1 sys_fcntl 1 15 1 sys_poll 1 pulseaudio [6275] sys_poll 1 gnome-panel [6329] sys_inotify_add_watch 4 sys_poll 1 sys_read 1 apache2 [6004] sys_wait4 2 sys_select 2 wterm [6659] sys_read 7 sys_select 3 sys_write 1 mysqld [5120] sys_select 2 mysqld [5119] sys_select 2 npviewer.bin [13313] sys_getdents 2560 sys_close 1679 sys_swapoff 1095 sys_sched_setparam 511 sys_getgid 128 174 64 sys_setuid 64 Xorg [5853] sys_select 123 sys_setitimer 50 sys_read 50 15 24 sys_rt_sigprocmask 24 sys_poll 24 sys_writev 5 The 'failed-syscalls' script likewise gives a high-level overview of all failed syscalls on the system, listed both by comm and by syscall: root(a)tropicana:~# perf trace record failed-syscalls ^C[ perf record: Woken up 1 times to write data ] [ perf record: Captured and wrote 32.653 MB perf.data (~1426644 samples) ] root(a)tropicana:~# perf trace report failed-syscalls failed syscalls, by comm: comm # errors -------------------- ---------- npviewer.bin 2468 firefox 91 Xorg 31 gnome-screensav 6 wterm 5 gnome-panel 5 trashapplet 4 hald-addon-stor 4 gvfsd-trash 2 gnome-settings- 2 sh 1 update-notifier 1 failed syscalls, by syscall: syscall # errors ------------------------------ ---------- sys_close 2468 sys_read 81 sys_futex 29 sys_select 15 undefined 15 sys_inotify_add_watch 6 sys_open 4 sys_access 1 sys_wait4 1 And again, diving into more detail, the 'failed-syscalls-by-pid' script lists the failed system calls by comm/pid and error: root(a)tropicana:~# perf trace report failed-syscalls-by-pid perf trace started with Python script /root/libexec/perf-core/scripts/python/failed-syscalls-by-pid.py syscall errors: comm [pid] count ------------------------------ ---------- gnome-screensav [6351] syscall: sys_read err = -11 6 firefox [6505] syscall: sys_futex err = -110 28 firefox [6502] syscall: sys_read err = -11 60 syscall: sys_access err = -2 1 syscall: sys_inotify_add_watch err = -2 2 gnome-panel [6329] syscall: sys_read err = -11 1 syscall: sys_inotify_add_watch err = -2 4 wterm [6659] syscall: sys_read err = -11 5 trashapplet [6364] syscall: sys_read err = -11 4 sh [13717] syscall: sys_wait4 err = -512 1 npviewer.bin [13313] syscall: sys_close err = -11 2468 Xorg [5853] syscall: sys_read err = -11 1 syscall: undefined err = -4 15 syscall: sys_select err = -514 15 gnome-settings- [6297] syscall: sys_read err = -11 2 hald-addon-stor [5721] syscall: sys_open err = -123 1 hald-addon-stor [5715] syscall: sys_open err = -123 1 hald-addon-stor [5724] syscall: sys_open err = -123 1 hald-addon-stor [5718] syscall: sys_open err = -123 1 gvfsd-trash [6370] syscall: sys_read err = -11 1 gvfsd-trash [13719] syscall: sys_futex err = -110 1 update-notifier [6395] syscall: sys_read err = -11 1 These scripts can be used to get a general idea of syscall activity on the system, which can be used to direct further investigation in the form of either more refined scripts and/or looking at the source of apps that seem to be acting strangely. For instance, the output of failed-syscalls-by-pid shows npviewer.bin, a flash plugin wrapper, seems to be making a lot of failed close system calls, while the output of syscalls-by-pid doesn't show a lot of open calls. So it's apparently wasting a lot of time closing nonexistent files (this script was run for only a very short time). It might be useful at this point to record syscalls::sys_enter/exit_close syscalls and write a script that would hash the fds by error code to find out which files it's trying unsuccessfully to close. That might be enough information to go examine and fix the offending code in the wrapper, or put the blame on the wrappee if that's where the problem is... Tom Zanussi (12): perf trace/scripting: Fix supported language listing option perf trace/scripting: fix bug in Util.pm perf trace/scripting: move common code out of Perl-specific files perf trace/scripting: move Perl scripting files to scripting-engines dir perf trace/scripting: remove check-perf-trace from listed scripts perf trace/scripting: add Python scripting engine perf trace/scripting: add syscall tracing scripts perf: export some syscall metadata perf tools: save syscall map perf trace/scripting: make the syscall map available as a Python dict perf trace/scripting: make the syscall map available as a Perl hash perf trace/scripting: add perf-trace-python Documentation kernel/trace/trace_syscalls.c | 87 +++ tools/perf/Documentation/perf-trace-perl.txt | 3 +- tools/perf/Documentation/perf-trace-python.txt | 624 ++++++++++++++++++ tools/perf/Documentation/perf-trace.txt | 15 +- tools/perf/Makefile | 33 +- tools/perf/builtin-trace.c | 5 +- tools/perf/scripts/perl/Perf-Trace-Util/Context.c | 49 ++- tools/perf/scripts/perl/Perf-Trace-Util/Context.xs | 27 +- .../perl/Perf-Trace-Util/lib/Perf/Trace/Context.pm | 2 +- .../perl/Perf-Trace-Util/lib/Perf/Trace/Util.pm | 24 +- .../perf/scripts/perl/bin/check-perf-trace-record | 7 +- .../perf/scripts/perl/bin/check-perf-trace-report | 6 - tools/perf/scripts/perl/bin/failed-syscalls-record | 2 + tools/perf/scripts/perl/bin/failed-syscalls-report | 4 + tools/perf/scripts/perl/failed-syscalls.pl | 51 ++ .../perf/scripts/python/Perf-Trace-Util/Context.c | 110 ++++ .../python/Perf-Trace-Util/lib/Perf/Trace/Core.py | 91 +++ .../python/Perf-Trace-Util/lib/Perf/Trace/Util.py | 37 ++ .../python/bin/failed-syscalls-by-pid-record | 2 + .../python/bin/failed-syscalls-by-pid-report | 4 + .../python/bin/syscall-counts-by-pid-record | 2 + .../python/bin/syscall-counts-by-pid-report | 4 + .../perf/scripts/python/bin/syscall-counts-record | 2 + .../perf/scripts/python/bin/syscall-counts-report | 4 + tools/perf/scripts/python/check-perf-trace.py | 83 +++ .../perf/scripts/python/failed-syscalls-by-pid.py | 69 ++ tools/perf/scripts/python/syscall-counts-by-pid.py | 65 ++ tools/perf/scripts/python/syscall-counts.py | 59 ++ .../perf/util/scripting-engines/trace-event-perl.c | 568 +++++++++++++++++ .../util/scripting-engines/trace-event-python.c | 576 +++++++++++++++++ tools/perf/util/trace-event-info.c | 25 + tools/perf/util/trace-event-parse.c | 78 +++ tools/perf/util/trace-event-perl.c | 661 -------------------- tools/perf/util/trace-event-perl.h | 55 -- tools/perf/util/trace-event-read.c | 18 + tools/perf/util/trace-event-scripting.c | 167 +++++ tools/perf/util/trace-event.h | 20 +- 37 files changed, 2895 insertions(+), 744 deletions(-) create mode 100644 tools/perf/Documentation/perf-trace-python.txt delete mode 100644 tools/perf/scripts/perl/bin/check-perf-trace-report create mode 100644 tools/perf/scripts/perl/bin/failed-syscalls-record create mode 100644 tools/perf/scripts/perl/bin/failed-syscalls-report create mode 100644 tools/perf/scripts/perl/failed-syscalls.pl create mode 100644 tools/perf/scripts/python/Perf-Trace-Util/Context.c create mode 100644 tools/perf/scripts/python/Perf-Trace-Util/lib/Perf/Trace/Core.py create mode 100644 tools/perf/scripts/python/Perf-Trace-Util/lib/Perf/Trace/Util.py create mode 100644 tools/perf/scripts/python/bin/failed-syscalls-by-pid-record create mode 100644 tools/perf/scripts/python/bin/failed-syscalls-by-pid-report create mode 100644 tools/perf/scripts/python/bin/syscall-counts-by-pid-record create mode 100644 tools/perf/scripts/python/bin/syscall-counts-by-pid-report create mode 100644 tools/perf/scripts/python/bin/syscall-counts-record create mode 100644 tools/perf/scripts/python/bin/syscall-counts-report create mode 100644 tools/perf/scripts/python/check-perf-trace.py create mode 100644 tools/perf/scripts/python/failed-syscalls-by-pid.py create mode 100644 tools/perf/scripts/python/syscall-counts-by-pid.py create mode 100644 tools/perf/scripts/python/syscall-counts.py create mode 100644 tools/perf/util/scripting-engines/trace-event-perl.c create mode 100644 tools/perf/util/scripting-engines/trace-event-python.c delete mode 100644 tools/perf/util/trace-event-perl.c delete mode 100644 tools/perf/util/trace-event-perl.h create mode 100644 tools/perf/util/trace-event-scripting.c -- To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to majordomo(a)vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/ |