Chapter 40. Profiling kernel activity with SystemTap
Chapter 40. Profiling kernel activity with SystemTap You can profile the kernel activity by monitoring function calls with the following scripts. 40.1. Counting function calls with SystemTap You can use the functioncallcount.stp SystemTap script to count specific kernel function calls. You can also use this script to target multiple kernel functions. Prerequisites You have installed SystemTap as described in Installing Systemtap . Procedure Run the functioncallcount.stp script: This script takes the targeted kernel function as an argument. You can use the argument wildcards to target multiple kernel functions up to a certain extent. The output of the script, in alphabetical order, contains the names of the functions called and how many times it was called during the sample time. Consider the following example: where: -w : Suppresses warnings. -v : Makes the output of starting kernel visible. -c command : Tells SystemTap to count function calls during the execution of a command, in this example being /bin/true . The output should look similar to the following: 40.2. Tracing function calls with SystemTap You can use the para-callgraph.stp SystemTap script to trace function calls and function returns. Prerequisites You have installed SystemTap as described in Installing Systemtap . Procedure Run the para-callgraph.stp script. The script para-callgraph.stp takes two command-line arguments: The name of the function(s) whose entry/exit you'd like to trace. An optional trigger function, which enables or disables tracing on a per-thread basis. Tracing in each thread will continue as long as the trigger function has not exited yet. Consider the following example: where: -w : Suppresses warnings. -v : Makes the output of starting kernel visible. -c command : Tells SystemTap to count function calls during the execution of a command, in this example being /bin/true . The output should look similar to the following: 40.3. Determining time spent in kernel and user space with SystemTap You can use the thread-times.stp SystemTap script to determine the amount of time any given thread is spending in either the kernel or user-space. Prerequisites You have installed SystemTap as described in Installing Systemtap . Procedure Run the thread-times.stp script: This script will display the top 20 processes taking up CPU time during a 5-second period, along with the total number of CPU ticks made during the sample. The output of this script also notes the percentage of CPU time each process used, as well as whether that time was spent in kernel space or user space. 40.4. Monitoring polling applications with SystemTap You can use timeout.stp SystemTap script to identify and monitor which applications are polling. Doing so allows you to track unnecessary or excessive polling, which helps you pinpoint areas for improvement in terms of CPU usage and power savings. Prerequisites You have installed SystemTap as described in Installing Systemtap . Procedure Run the timeout.stp script: This script will track how many times each application uses the following system calls over time: poll select epoll itimer futex nanosleep signal In this example output you can see which process used which system call and how many times. 40.5. Tracking most frequently used system calls with SystemTap You can use the topsys.stp SystemTap script to list the top 20 system calls used by the system per 5-second interval. It also lists how many times each system call was used during that period. Prerequisites You have installed SystemTap as described in Installing Systemtap . Procedure Run the topsys.stp script: Consider the following example: where -v makes the output of starting kernel visible. The output should look similar to the following: 40.6. Tracking system call volume per process with SystemTap You can use the syscalls_by_proc.stp SystemTap script to see which processes are performing the highest volume of system calls. It displays 20 processes performing the most of system calls. Prerequisites You have installed SystemTap as described in Installing Systemtap . Procedure Run the syscalls_by_proc.stp script: Output of the syscalls_by_proc.stp script looks similar to the following:
stap --example functioncallcount.stp 'argument' stap -w -v --example functioncallcount.stp "*@mm*.c" -c /bin/true [...] __vma_link 97 __vma_link_file 66 __vma_link_list 97 __vma_link_rb 97 __xchg 103 add_page_to_active_list 102 add_page_to_inactive_list 19 add_to_page_cache 19 add_to_page_cache_lru 7 all_vm_events 6 alloc_pages_node 4630 alloc_slabmgmt 67 anon_vma_alloc 62 anon_vma_free 62 anon_vma_lock 66 anon_vma_prepare 98 anon_vma_unlink 97 anon_vma_unlock 66 arch_get_unmapped_area_topdown 94 arch_get_unmapped_exec_area 3 arch_unmap_area_topdown 97 atomic_add 2 atomic_add_negative 97 atomic_dec_and_test 5153 atomic_inc 470 atomic_inc_and_test 1 [...] stap --example para-callgraph.stp 'argument1' 'argument2' stap -wv --example para-callgraph.stp 'kernel.function("*@fs/proc.c*")' 'kernel.function("vfs_read")' -c "cat /proc/sys/vm/* || true" [...] 267 gnome-terminal(2921): <-do_sync_read return=0xfffffffffffffff5 269 gnome-terminal(2921):<-vfs_read return=0xfffffffffffffff5 0 gnome-terminal(2921):->fput file=0xffff880111eebbc0 2 gnome-terminal(2921):<-fput 0 gnome-terminal(2921):->fget_light fd=0x3 fput_needed=0xffff88010544df54 3 gnome-terminal(2921):<-fget_light return=0xffff8801116ce980 0 gnome-terminal(2921):->vfs_read file=0xffff8801116ce980 buf=0xc86504 count=0x1000 pos=0xffff88010544df48 4 gnome-terminal(2921): ->rw_verify_area read_write=0x0 file=0xffff8801116ce980 ppos=0xffff88010544df48 count=0x1000 7 gnome-terminal(2921): <-rw_verify_area return=0x1000 12 gnome-terminal(2921): ->do_sync_read filp=0xffff8801116ce980 buf=0xc86504 len=0x1000 ppos=0xffff88010544df48 15 gnome-terminal(2921): <-do_sync_read return=0xfffffffffffffff5 18 gnome-terminal(2921):<-vfs_read return=0xfffffffffffffff5 0 gnome-terminal(2921):->fput file=0xffff8801116ce980 stap --example thread-times.stp tid %user %kernel (of 20002 ticks) 0 0.00% 87.88% 32169 5.24% 0.03% 9815 3.33% 0.36% 9859 0.95% 0.00% 3611 0.56% 0.12% 9861 0.62% 0.01% 11106 0.37% 0.02% 32167 0.08% 0.08% 3897 0.01% 0.08% 3800 0.03% 0.00% 2886 0.02% 0.00% 3243 0.00% 0.01% 3862 0.01% 0.00% 3782 0.00% 0.00% 21767 0.00% 0.00% 2522 0.00% 0.00% 3883 0.00% 0.00% 3775 0.00% 0.00% 3943 0.00% 0.00% 3873 0.00% 0.00% stap --example timeout.stp uid | poll select epoll itimer futex nanosle signal| process 28937 | 148793 0 0 4727 37288 0 0| firefox 22945 | 0 56949 0 1 0 0 0| scim-bridge 0 | 0 0 0 36414 0 0 0| swapper 4275 | 23140 0 0 1 0 0 0| mixer_applet2 4191 | 0 14405 0 0 0 0 0| scim-launcher 22941 | 7908 1 0 62 0 0 0| gnome-terminal 4261 | 0 0 0 2 0 7622 0| escd 3695 | 0 0 0 0 0 7622 0| gdm-binary 3483 | 0 7206 0 0 0 0 0| dhcdbd 4189 | 6916 0 0 2 0 0 0| scim-panel-gtk 1863 | 5767 0 0 0 0 0 0| iscsid stap --example topsys.stp stap -v --example topsys.stp -------------------------------------------------------------- SYSCALL COUNT gettimeofday 1857 read 1821 ioctl 1568 poll 1033 close 638 open 503 select 455 write 391 writev 335 futex 303 recvmsg 251 socket 137 clock_gettime 124 rt_sigprocmask 121 sendto 120 setitimer 106 stat 90 time 81 sigreturn 72 fstat 66 -------------------------------------------------------------- stap --example syscalls_by_proc.stp Collecting data... Type Ctrl-C to exit and display results #SysCalls Process Name 1577 multiload-apple 692 synergyc 408 pcscd 376 mixer_applet2 299 gnome-terminal 293 Xorg 206 scim-panel-gtk 95 gnome-power-man 90 artsd 85 dhcdbd 84 scim-bridge 78 gnome-screensav 66 scim-launcher [...]