Systemtap generator for simple timings collection

Systemtap generator for simple timings collection

[Fabio Olive Leite]

[-- Attachment #1: Type: text/plain, Size: 4031 bytes --]

Hi all,

While working on a set of systemtaps to help us assess NFS performing
regressions between RHEL releases (quite an obsession), I have abstracted
my set of taps to the point where I actually made an AWK script that
reads a list of kernel functions and generates a systemtap script that
collects timings on those functions, outputing statistics on those timings
when interrupted. I thought I would post it here as it became a generally
interesting tool.

Here's the documentation I just wrote...

-----
kernel_timing_systemtap_generator.awk is, almost obviously, an AWK script that
reads from its input lists of kernel functions and outputs a standardized
systemtap script that collects timings on the durations of the calls to those
functions. So you write in a file a set of kernel functions which you'd like
to "profile" and feed it to the AWK script, and in the output you get a
systemtap script that will time those calls.

The input to the AWK script can be in AWK's standard input, or can come from a
set of files you pass as paremeters to the AWK script's command line. The
output of the AWK script goes to AWK's standard output, so you'll want to
redirect that to a file, named something useful like "nfs_probes.stap".

The format of the input to the AWK script is one kernel function per line, or
one module name and module function per line. For example:

io_schedule
udp_queue_rcv_skb
nfs nfs3_proc_getattr
ext3 ext3_delete_inode

If the first character in a line fed to the script is a '#' it will ignore the
line. This way you can keep a large file containing kernel function names that
interest you and comment out some of them when needed.

The generated systemtap script will collect a microsecond timestamp upon entry
to each of the functions passed in, indexing the timestamps by function name
and process id, and upon function exit will calculate the time spent by the
process inside the function and feed that into a systemtap statistics
collector indexed by function names. When you stop the probe, it will iterate
(ascending asciibetic order) over the function names for which statistics were
collected, and print out each function name, how many calls it received,
minimum time spent on it, average time spent on it, and maximum time spent on
it, in a nicely formatted table.

This generator was made in hopes that it would be useful for quickly comparing
timing differences between kernel releases or different tuning parameters, so
that one can easily focus the debugging of performance regressions or simply
accurately determine the best set of system tunings.

The output from the generated systemtap script should look like this:

$ ./kernel_timing_systemtap_generator.awk nfs_v3_clientops_functions > \
	nfs_v3_clientops_test.stap

$ sudo stap nfs_v3_clientops_test.stap
... do some NFS testing and hit ^C
function                    count   min_us   avg_us   max_us
nfs3_decode_dirent            150        2        2        5
nfs3_forget_cached_acls        69        2        2        7
nfs3_proc_access                4   269623   302668   348510
nfs3_proc_fsinfo                1   274941   274941   274941
nfs3_proc_get_root              1   546148   546148   546148
nfs3_proc_getattr              92   259162   304874   800149
nfs3_proc_read_setup            1        4        4        4
nfs3_proc_readdir               4   292728   550859   790494
nfs3_proc_readlink              1   634002   634002   634002
nfs3_read_done                  1       11       11       11
nfs_open                        3        5        5        5
nfs_release                     3        5        5        6

Yes, that was NFS over a really slow link. :)
-----

You'll find attached the AWK script that generates systemtap scripts,
the "documentation" and example input and output files. I hope this
AWK madness turns out to be useful for some of you!

Cheers!
Fábio Olivé
-- 
ex sed lex awk yacc, e pluribus unix, amem

[-- Attachment #2: kernel_timing_systemtap_generator_summary.txt --]
[-- Type: text/plain, Size: 3173 bytes --]

kernel_timing_systemtap_generator.awk is, almost obviously, an AWK script that
reads from its input lists of kernel functions and outputs a standardized
systemtap script that collects timings on the durations of the calls to those
functions. So you write in a file a set of kernel functions which you'd like
to "profile" and feed it to the AWK script, and in the output you get a
systemtap script that will time those calls.

The input to the AWK script can be in AWK's standard input, or can come from a
set of files you pass as paremeters to the AWK script's command line. The
output of the AWK script goes to AWK's standard output, so you'll want to
redirect that to a file, named something useful like "nfs_probes.stap".

The format of the input to the AWK script is one kernel function per line, or
one module name and module function per line. For example:

io_schedule
udp_queue_rcv_skb
nfs nfs3_proc_getattr
ext3 ext3_delete_inode

If the first character in a line fed to the script is a '#' it will ignore the
line. This way you can keep a large file containing kernel function names that
interest you and comment out some of them when needed.

The generated systemtap script will collect a microsecond timestamp upon entry
to each of the functions passed in, indexing the timestamps by function name
and process id, and upon function exit will calculate the time spent by the
process inside the function and feed that into a systemtap statistics
collector indexed by function names. When you stop the probe, it will iterate
(ascending asciibetic order) over the function names for which statistics were
collected, and print out each function name, how many calls it received,
minimum time spent on it, average time spent on it, and maximum time spent on
it, in a nicely formatted table.

This generator was made in hopes that it would be useful for quickly comparing
timing differences between kernel releases or different tuning parameters, so
that one can easily focus the debugging of performance regressions or simply
accurately determine the best set of system tunings.

The output from the generated systemtap script should look like this:

$ ./kernel_timing_systemtap_generator.awk nfs_v3_clientops_functions > \
	nfs_v3_clientops_test.stap

$ sudo stap nfs_v3_clientops_test.stap
... do some NFS testing and hit ^C
function                    count   min_us   avg_us   max_us
nfs3_decode_dirent            150        2        2        5
nfs3_forget_cached_acls        69        2        2        7
nfs3_proc_access                4   269623   302668   348510
nfs3_proc_fsinfo                1   274941   274941   274941
nfs3_proc_get_root              1   546148   546148   546148
nfs3_proc_getattr              92   259162   304874   800149
nfs3_proc_read_setup            1        4        4        4
nfs3_proc_readdir               4   292728   550859   790494
nfs3_proc_readlink              1   634002   634002   634002
nfs3_read_done                  1       11       11       11
nfs_open                        3        5        5        5
nfs_release                     3        5        5        6

Yes, that was NFS over a really slow link. :)

[-- Attachment #3: nfs_v3_clientops_functions --]
[-- Type: text/plain, Size: 736 bytes --]

nfs nfs3_proc_get_root
nfs nfs3_proc_getattr
nfs nfs3_proc_setattr
nfs nfs3_proc_lookup
nfs nfs3_proc_access
nfs nfs3_proc_readlink
#nfs nfs3_proc_read
#nfs nfs3_proc_write
#nfs nfs3_proc_commit
nfs nfs3_proc_create
nfs nfs3_proc_remove
nfs nfs3_proc_unlink_setup
nfs nfs3_proc_unlink_done
nfs nfs3_proc_rename
nfs nfs3_proc_link
nfs nfs3_proc_symlink
nfs nfs3_proc_mkdir
nfs nfs3_proc_rmdir
nfs nfs3_proc_readdir
nfs nfs3_proc_mknod
nfs nfs3_proc_statfs
nfs nfs3_proc_fsinfo
nfs nfs3_proc_pathconf
nfs nfs3_decode_dirent
nfs nfs3_proc_read_setup
nfs nfs3_read_done
nfs nfs3_proc_write_setup
nfs nfs3_write_done
nfs nfs3_proc_commit_setup
nfs nfs3_commit_done
nfs nfs_open
nfs nfs_release
nfs nfs3_proc_lock
nfs nfs3_forget_cached_acls

[-- Attachment #4: kernel_timing_systemtap_generator.awk --]
[-- Type: application/x-awk, Size: 2002 bytes --]

[-- Attachment #5: nfs_v3_clientops_test.stap --]
[-- Type: text/plain, Size: 6515 bytes --]

global entry, timings

function collect_entry() { entry[probefunc(),pid()] = gettimeofday_us() }
function collect_exit() { timings[probefunc()] <<< (gettimeofday_us() - entry[probefunc(),pid()]) }

# Filename: nfs_v3_clientops_functions Line: 1
probe module("nfs").function("nfs3_proc_get_root") { collect_entry(); }
probe module("nfs").function("nfs3_proc_get_root").return { collect_exit(); }

# Filename: nfs_v3_clientops_functions Line: 2
probe module("nfs").function("nfs3_proc_getattr") { collect_entry(); }
probe module("nfs").function("nfs3_proc_getattr").return { collect_exit(); }

# Filename: nfs_v3_clientops_functions Line: 3
probe module("nfs").function("nfs3_proc_setattr") { collect_entry(); }
probe module("nfs").function("nfs3_proc_setattr").return { collect_exit(); }

# Filename: nfs_v3_clientops_functions Line: 4
probe module("nfs").function("nfs3_proc_lookup") { collect_entry(); }
probe module("nfs").function("nfs3_proc_lookup").return { collect_exit(); }

# Filename: nfs_v3_clientops_functions Line: 5
probe module("nfs").function("nfs3_proc_access") { collect_entry(); }
probe module("nfs").function("nfs3_proc_access").return { collect_exit(); }

# Filename: nfs_v3_clientops_functions Line: 6
probe module("nfs").function("nfs3_proc_readlink") { collect_entry(); }
probe module("nfs").function("nfs3_proc_readlink").return { collect_exit(); }

# Filename: nfs_v3_clientops_functions Line: 10
probe module("nfs").function("nfs3_proc_create") { collect_entry(); }
probe module("nfs").function("nfs3_proc_create").return { collect_exit(); }

# Filename: nfs_v3_clientops_functions Line: 11
probe module("nfs").function("nfs3_proc_remove") { collect_entry(); }
probe module("nfs").function("nfs3_proc_remove").return { collect_exit(); }

# Filename: nfs_v3_clientops_functions Line: 12
probe module("nfs").function("nfs3_proc_unlink_setup") { collect_entry(); }
probe module("nfs").function("nfs3_proc_unlink_setup").return { collect_exit(); }

# Filename: nfs_v3_clientops_functions Line: 13
probe module("nfs").function("nfs3_proc_unlink_done") { collect_entry(); }
probe module("nfs").function("nfs3_proc_unlink_done").return { collect_exit(); }

# Filename: nfs_v3_clientops_functions Line: 14
probe module("nfs").function("nfs3_proc_rename") { collect_entry(); }
probe module("nfs").function("nfs3_proc_rename").return { collect_exit(); }

# Filename: nfs_v3_clientops_functions Line: 15
probe module("nfs").function("nfs3_proc_link") { collect_entry(); }
probe module("nfs").function("nfs3_proc_link").return { collect_exit(); }

# Filename: nfs_v3_clientops_functions Line: 16
probe module("nfs").function("nfs3_proc_symlink") { collect_entry(); }
probe module("nfs").function("nfs3_proc_symlink").return { collect_exit(); }

# Filename: nfs_v3_clientops_functions Line: 17
probe module("nfs").function("nfs3_proc_mkdir") { collect_entry(); }
probe module("nfs").function("nfs3_proc_mkdir").return { collect_exit(); }

# Filename: nfs_v3_clientops_functions Line: 18
probe module("nfs").function("nfs3_proc_rmdir") { collect_entry(); }
probe module("nfs").function("nfs3_proc_rmdir").return { collect_exit(); }

# Filename: nfs_v3_clientops_functions Line: 19
probe module("nfs").function("nfs3_proc_readdir") { collect_entry(); }
probe module("nfs").function("nfs3_proc_readdir").return { collect_exit(); }

# Filename: nfs_v3_clientops_functions Line: 20
probe module("nfs").function("nfs3_proc_mknod") { collect_entry(); }
probe module("nfs").function("nfs3_proc_mknod").return { collect_exit(); }

# Filename: nfs_v3_clientops_functions Line: 21
probe module("nfs").function("nfs3_proc_statfs") { collect_entry(); }
probe module("nfs").function("nfs3_proc_statfs").return { collect_exit(); }

# Filename: nfs_v3_clientops_functions Line: 22
probe module("nfs").function("nfs3_proc_fsinfo") { collect_entry(); }
probe module("nfs").function("nfs3_proc_fsinfo").return { collect_exit(); }

# Filename: nfs_v3_clientops_functions Line: 23
probe module("nfs").function("nfs3_proc_pathconf") { collect_entry(); }
probe module("nfs").function("nfs3_proc_pathconf").return { collect_exit(); }

# Filename: nfs_v3_clientops_functions Line: 24
probe module("nfs").function("nfs3_decode_dirent") { collect_entry(); }
probe module("nfs").function("nfs3_decode_dirent").return { collect_exit(); }

# Filename: nfs_v3_clientops_functions Line: 25
probe module("nfs").function("nfs3_proc_read_setup") { collect_entry(); }
probe module("nfs").function("nfs3_proc_read_setup").return { collect_exit(); }

# Filename: nfs_v3_clientops_functions Line: 26
probe module("nfs").function("nfs3_read_done") { collect_entry(); }
probe module("nfs").function("nfs3_read_done").return { collect_exit(); }

# Filename: nfs_v3_clientops_functions Line: 27
probe module("nfs").function("nfs3_proc_write_setup") { collect_entry(); }
probe module("nfs").function("nfs3_proc_write_setup").return { collect_exit(); }

# Filename: nfs_v3_clientops_functions Line: 28
probe module("nfs").function("nfs3_write_done") { collect_entry(); }
probe module("nfs").function("nfs3_write_done").return { collect_exit(); }

# Filename: nfs_v3_clientops_functions Line: 29
probe module("nfs").function("nfs3_proc_commit_setup") { collect_entry(); }
probe module("nfs").function("nfs3_proc_commit_setup").return { collect_exit(); }

# Filename: nfs_v3_clientops_functions Line: 30
probe module("nfs").function("nfs3_commit_done") { collect_entry(); }
probe module("nfs").function("nfs3_commit_done").return { collect_exit(); }

# Filename: nfs_v3_clientops_functions Line: 31
probe module("nfs").function("nfs_open") { collect_entry(); }
probe module("nfs").function("nfs_open").return { collect_exit(); }

# Filename: nfs_v3_clientops_functions Line: 32
probe module("nfs").function("nfs_release") { collect_entry(); }
probe module("nfs").function("nfs_release").return { collect_exit(); }

# Filename: nfs_v3_clientops_functions Line: 33
probe module("nfs").function("nfs3_proc_lock") { collect_entry(); }
probe module("nfs").function("nfs3_proc_lock").return { collect_exit(); }

# Filename: nfs_v3_clientops_functions Line: 34
probe module("nfs").function("nfs3_forget_cached_acls") { collect_entry(); }
probe module("nfs").function("nfs3_forget_cached_acls").return { collect_exit(); }

probe end {
	printf("function                    count   min_us   avg_us   max_us\n")
	foreach (i+ in timings) {
		printf("%-25s %7d %8d %8d %8d\n", i, @count(timings[i]),
			@min(timings[i]), @avg(timings[i]), @max(timings[i]))
	}
}

Re: Systemtap generator for simple timings collection

[Mark Wielaard]

Hi Fabio,

On Fri, 2008-10-24 at 15:51 -0200, Fabio Olive Leite wrote:
> While working on a set of systemtaps to help us assess NFS performing
> regressions between RHEL releases (quite an obsession), I have abstracted
> my set of taps to the point where I actually made an AWK script that
> reads a list of kernel functions and generates a systemtap script that
> collects timings on those functions, outputing statistics on those timings
> when interrupted. I thought I would post it here as it became a generally
> interesting tool.

Nice! I added a reference to this on the systemtap wiki under "Systemtap
Applications": http://sourceware.org/systemtap/wiki/HomePage

Thanks,

Mark