SystemTap has extensive libraries called tapsets that allow developers to instrument various aspects of the kernel's operation. SystemTap allows the use of wildcards to instrument multiple locations in particular subsystems. SystemTap has to perform a significant amount of work to create instrumentation for each of the places being probed. This overhead is particularly apparent when using the wildcards for the system call tapset that contains hundreds of entries (syscall.* and syscall.*.return). For some subsets of data collection, replacing the wildcard-matched syscall probes in SystemTap scripts with the kernel.trace("sys_enter") and the kernel.trace("sys_exit") probe will produce smaller instrumentation modules that compile and start up more quickly. In this article, I'll show a few examples of how this works.
All system calls enter the kernel through the kernel.trace("sys_enter") probe, and all system calls exit the kernel through the kernel.trace("sys_exit") probe. Below is the SystemTap command listing those probe points and the arguments available. The kernel.trace("sys_enter") probe provides the $id variable, which can be mapped to the system call name using the syscall_name() function. The kernel.trace("sys_exit") probe provides the return value $ret indicating the success or failure of the system call.
$ stap -L 'kernel.trace("sys_*")'
kernel.trace("raw_syscalls:sys_enter") $regs:struct pt_regs* $id:long int
kernel.trace("raw_syscalls:sys_exit") $regs:struct pt_regs* $ret:long intAs a concrete example, let's look at the syscalls_by_pid.stp example included in systemtap-client-3.3-3.el7.x86_64. It uses the non-dwarf variant of the system call instrumentation: nd_syscall.*.
global syscalls
probe begin {
print ("Collecting data... Type Ctrl-C to exit and display results\n")
}
probe nd_syscall.* {
syscalls[pid()]++
}
probe end {
printf ("%-10s %-s\n", "#SysCalls", "PID")
foreach (pid in syscalls-)
printf("%-10d %-d\n", syscalls[pid], pid)
}Below is a run of the original script. The -v option provides information about the space and time each of the five passes SystemTap uses. The -k option keeps around the intermediate files created by SystemTap, so later we can compare the size of those intermediate files to the results of the revised script if needed. The --disable-cache ensures that SystemTap does not attempt to use a previously built version of a file and corrupt the time measurements. The -m slow names the resulting SystemTap instrumentation module to slow.ko.
At the end of the command is the -c "sleep 0". This command runs the script for a very short time, allowing us to observe the startup and shutdown overhead of pass 5 of the script.
$ stap -v -k --disable-cache -m slow ./syscalls_by_pid.stp -c "sleep 0" Pass 1: parsed user script and 497 library scripts using 264396virt/59208res/3572shr/56344data kb, in 390usr/30sys/423real ms. Pass 2: analyzed script: 531 probes, 27 functions, 103 embeds, 4 globals using 391992virt/187976res/4716shr/183940data kb, in 8170usr/1370sys/9276real ms. Pass 3: translated to C into "/tmp/stapos95gX/slow_src.c" using 391992virt/188212res/4952shr/183940data kb, in 40usr/0sys/45real ms. Pass 4: compiled C into "slow.ko" in 8350usr/1660sys/9794real ms. Pass 5: starting run. Collecting data... Type Ctrl-C to exit and display results #SysCalls PID 42 19096 10 19078 Pass 5: run completed in 10usr/9450sys/9940real ms. Keeping temporary directory "/tmp/stapos95gX"
Below is the new version of the script. Notice that the only difference is the change of nd_syscall.* to kernel.trace("sys_enter"). The script functions in the same manner as before.
global syscalls
probe begin {
print ("Collecting data... Type Ctrl-C to exit and display results\n")
}
probe kernel.trace("sys_enter") {
syscalls[pid()]++
}
probe end {
printf ("%-10s %-s\n", "#SysCalls", "PID")
foreach (pid in syscalls-)
printf("%-10d %-d\n", syscalls[pid], pid)
}
Below is a run of the new script. A noticeable effect of using kernel.trace("sys_enter") in place of nd_syscall.* is that, in pass 2, which is the elaboration phase where SystemTap pulls in information from the tapset libraries, there are only 3 probes, 1 function, and 3 embeds used compared to 531 probes, 27 functions, and 103 embeds for the wildcard syscall version. This change has a follow-on effect for pass 5 where the script is actually run. Because the script is running for a very short duration, most of the time in pass 5 is due to the overhead of starting and stopping the script. For the earlier script using nd_syscall.* to probe the systemcalls 9940 milliseconds, almost 10 seconds, of real time is used in pass 5, but only 363 milliseconds of real time is used for the tracepoint version.
$ stap -v -k --disable-cache -m fast ./syscalls_by_pid.stp -c "sleep 0" Pass 1: parsed user script and 497 library scripts using 264400virt/59208res/3572shr/56348data kb, in 410usr/30sys/456real ms. Pass 2: analyzed script: 3 probes, 1 function, 3 embeds, 1 global using 389600virt/185704res/4856shr/181548data kb, in 45190usr/8990sys/9842real ms. Pass 3: translated to C into "/tmp/stapPcXVCr/fast_src.c" using 389600virt/185948res/5100shr/181548data kb, in 0usr/10sys/1real ms. Pass 4: compiled C into "fast.ko" in 6900usr/1730sys/8231real ms. Pass 5: starting run. Collecting data... Type Ctrl-C to exit and display results #SysCalls PID 42 11076 14 6381 11 2715 10 11071 Pass 5: run completed in 20usr/50sys/363real ms. Keeping temporary directory "/tmp/stapPcXVCr"
The resulting instrumentation for the tracepoint version is also much smaller than the wildcard version, 97KB versus 425KB:
$ ls -l */*.ko -rw-rw-r--. 1 wcohen wcohen 97392 Mar 18 15:32 fast/fast.ko -rw-rw-r--. 1 wcohen wcohen 425408 Mar 18 15:25 slow/slow.ko
The previous example did not track system calls by name. The system call name can be obtained from the $id variable of the kernel.trace("sys_enter"). Below is a one-line script that will tally the times each different system call is used on the system:
stap -e 'global syscalls_count; probe kernel.trace("sys_enter") {syscalls_count[syscall_name($id)]<<<1}'Because of the benefits of using these tracepoints in scripts, SystemTap 4.0 includes the syscall_any tapsets and various SystemTap examples now use the tapset where possible. You should consider similar optimizations using the kernel.trace("sys_enter") and kernel.trace("sys_exit") or the syscall_any tapset for your scripts monitoring all the system calls.
See also:
Last updated: May 1, 2019