SystemTap upcoming feature: boot-time probing

[Jonathan Lebon <jlebon at redhat dot com>]

Hello everyone,

I've been working on making SystemTap use dracut in order to
insert the kernel module at early boot-time. The goal of
this email is to provide some more details and demonstrate
how to use it.

To implement this feature, I've added a dracut module which
simply adds staprun, stapio, and the target SystemTap
module(s) to the initramfs during creation.

Users select which scripts go in the initramfs by using the
new 'onboot' command of SystemTap's initscript. The
initscript then calls dracut to create the image.

Upon boot, staprun inserts the module during the cmdline
hook (the earliest possible using dracut) and detaches from
it. Users can then attach to the module to read in the data.

For testing, see the jlebon/boot-time branch of the
SystemTap git repo:

https://sourceware.org/git/gitweb.cgi?p=systemtap.git

Also take a look at the README.systemtap documentation diff
to see everything that has changed w.r.t. to the initscript:

https://sourceware.org/git/gitweb.cgi?p=systemtap.git;a=commitdiff;h=b0d4bb7

_____
USAGE

To play with the kind of information we can gain during
early-boot, I wrote the following script, which registers
calls to fork(), exec(), do_exit(), init_module(), and
delete_module():

procmod_watcher.stp
===================
function print_time() {
   timer = read_stopwatch_us("timer")
   printf("%4d.%.6d: ", timer/1000000, timer%1000000)
}

probe begin {
   start_stopwatch("timer")
   printf("   0.000000: Started module_watcher on %s\n",
          ctime(gettimeofday_s()))
}

probe kernel.function("do_execve"),
      kernel.function("compat_do_execve")? {

   print_time()
   printf("EXEC: (%4d) %s: file %s",
          pid(), execname(), kernel_string($filename))
   
   # Uncomment below to also print out arguments (can make
   # the output harder to read). You will also need to do
   # the following to enable guru mode:
   #   echo "procmod_watcher_OPT=\"-g\"" > \
   #       /etc/systemtap/conf.d/procmod_watcher.conf
   #arg = $__argv + %{ sizeof(char*) %}
   #ptr = kernel_pointer(arg)
   #if (ptr != 0)
   #   printf(" with args ")
   #while (ptr != 0) {
   #   printf("%s ", user_string2(ptr, "<NA>"))
   #   arg = arg + %{ sizeof(char*) %}
   #   ptr = kernel_pointer(arg)
   #}

   println("")
}

probe kprocess.create {
   print_time()
   printf("FORK: (%4d) %s: pid %d\n",
          pid(), execname(), new_pid)
}

probe kprocess.exit {
   print_time()
   printf("EXIT: (%4d) %s: exit code %d\n",
          pid(), execname(), code)
}

probe kernel.function("do_init_module") {
   print_time()
   printf("LOAD: (%4d) %s: module %s",
          pid(), execname(), kernel_string($mod->name))
   args = kernel_string($mod->args)
   if (args != "")
      printf(" with args \"%s\"", args)
   println("")
}

probe syscall.delete_module {
   print_time()
   printf("UNLD: (%4d) %s: module %s with flags %x\n",
          pid(), execname(), user_string($name_user), flags);
}

probe end {
   print_time()
   printf("Exiting module_watcher on %s\n",
          ctime(gettimeofday_s()))
}
==========

To set up this script for boot-time loading, we first copy
it to the script.d directory:

# cp procmod_watcher.stp /etc/systemtap/script.d/
# 

Then, we use the 'onboot' command:

# service systemtap onboot procmod_watcher
 Compiling procmod_watcher ... done
Creating initramfs: procmod_watcher                        [  OK  ]
# 

We can now restart the computer:

# reboot
# 

And finally, after the system finishes booting up, we can
re-attach to the module (I've only pasted bits of the output):

# staprun -A procmod_watcher
   0.000000: Started module_watcher on Thu Jan  9 19:21:34 2014
   0.004567: FORK: (  90) stapio: pid 90
   0.004598: EXIT: (  90) stapio: exit code 0
   0.004602: EXIT: (  90) stapio: exit code 0
   0.004625: EXIT: (  90) stapio: exit code 0
   0.004923: FORK: (  73) dracut-cmdline: pid 93
   0.005710: EXIT: (  93) dracut-cmdline: exit code 256
   0.005889: FORK: (  73) dracut-cmdline: pid 94
   0.006200: FORK: (  94) dracut-cmdline: pid 95
   0.006659: EXIT: (  95) dracut-cmdline: exit code 256
   0.006829: FORK: (  94) dracut-cmdline: pid 96
   0.007302: EXIT: (  96) dracut-cmdline: exit code 256
   0.007481: FORK: (  94) dracut-cmdline: pid 97
   <...snip...>
   2.843626: FORK: ( 410) firewalld: pid 868
   2.843831: EXEC: ( 868) firewalld: file /sbin/iptables
   2.844514: EXIT: ( 868) iptables: exit code 0
   2.844829: FORK: ( 410) firewalld: pid 869
   2.845034: EXEC: ( 869) firewalld: file /sbin/iptables
   2.845722: EXIT: ( 869) iptables: exit code 0
   2.846036: FORK: ( 410) firewalld: pid 870
   2.846240: EXEC: ( 870) firewalld: file /sbin/iptables
   <...etc...>
# 

If you've enabled argument printing, you will also see
cool things like:

<...snip...>
   1.665215: EXEC: ( 459) netconsole: file /bin/sed with args s|.* src \([^ ]*\).*|\1| 
   1.665678: EXIT: ( 459) sed: exit code 0
   1.665774: EXIT: ( 457) netconsole: exit code 0
   1.665921: FORK: ( 448) netconsole: pid 460
   1.666110: FORK: ( 460) netconsole: pid 461
   1.666177: FORK: ( 460) netconsole: pid 462
   1.666283: EXEC: ( 461) netconsole: file /sbin/arping with args -f -c 1 -I 192.168.122.1
   1.668700: EXEC: ( 462) netconsole: file /bin/awk with args / reply from .*[.*]/ { print gensub(".* reply from .* \\[(.*)\\].*","\\1","G"); exit } 
   1.690545: EXIT: ( 461) arping: exit code 512
   1.690605: EXIT: ( 462) awk: exit code 0
   1.696796: EXIT: ( 460) netconsole: exit code 0
<...snip...>

Hopefully this little exercise gives you an idea as to how
SystemTap can be used in your workflow when trying to find
out more about something that happens during boot-time.

Comments and feedback welcome,

Jonathan