When running a latency-sensitive application one might notice that on a regular basis (for example every 5 minutes) there is a delay. The SystemTap periodic.stp script can provide some possible causes of that regular delay. The SystemTap periodic.stp script generates a list of the number of times that various scheduled functions run and the time between each scheduled execution. In the case of delay every five minutes one would run the periodic script for tens of minutes and then look through the output list for a function that has a period of approximately 300,000,00 microseconds (5 minutes*60 seconds*1,000,000 microseconds/second).

Follow the instructions in the SystemTap Beginners Guide to install SystemTap. The SystemTap --all-modules option should be included on the command line when using periodic.stp script so the script can map the kernel module instruction addresses back to function names and make it easier to interpret what is periodically running. The script will collect data until cntrl-c is pressed. Below is an example run of periodic.stp:

$ /usr/share/doc/systemtap-*/examples/profiling/periodic.stp --all-modules
#monitoring timer periods (press control-c for output)
^C#type   function                                            period(us)     count
kernel  0xffffffffa0c59200 [stap_eb782113d30627ea6aa3ef949        1000     13552
kernel  0xffffffffa0c59200 [stap_eb782113d30627ea6aa3ef949        1000     13552
kernel  0xffffffffa0c59200 [stap_eb782113d30627ea6aa3ef949        1000     13551
kernel  0xffffffffa0c59200 [stap_eb782113d30627ea6aa3ef949        1000     13550
work_q  do_dbs_timer                                              9999      1354
work_q  do_dbs_timer                                              9999      1354
kernel  0xffffffffa0c590e0 [stap_eb782113d30627ea6aa3ef949        9999      1354
work_q  do_dbs_timer                                             10000      1354
work_q  do_dbs_timer                                             10022      1351
kernel  0xffffffffa0c59020 [stap_eb782113d30627ea6aa3ef949       19999       676
kernel  monitor_timeout+0x0/0x10 [intel_ips]                    200003        67
kernel  clocksource_watchdog+0x0/0x230 [kernel]                 500033        26
kernel  tcp_delack_timer+0x0/0x270 [kernel]                     981240        13
work_q  i915_gem_retire_work_handler                           1007250        12
work_q  vmstat_update                                          1000000        12
kernel  ipmi_timeout+0x0/0x470 [kernel]                        1000002        12
work_q  vmstat_update                                          1000000        12
kernel  br_fdb_cleanup+0x0/0x120 [bridge]                       999999        12
work_q  vmstat_update                                           999999        12
work_q  vmstat_update                                          1000000        12
process kslowd000(157)                                            4983         8
work_q  cache_reap                                             2000001         6
kernel  e1000_watchdog+0x0/0x20 [e1000e]                       2000001         6
work_q  cache_reap                                             1999999         6
work_q  cache_reap                                             1999998         6
kernel  br_hello_timer_expired+0x0/0x90 [bridge]               1999998         6
work_q  cache_reap                                             2000000         6
kernel  tcp_write_timer+0x0/0x200 [kernel]                     2933662         3
kernel  cfq_idle_slice_timer+0x0/0x100 [kernel]                2037998         3
work_q  flush_to_ldisc                                         3017627         3
kernel  dev_watchdog+0x0/0x280 [kernel]                        5000425         2
process bdi-default(29)                                        5000211         2
process ips-adjust(892)                                        5000047         2
kernel  sync_supers_timer_fn+0x0/0x20 [kernel]                 6000000         2
kernel  inet_twdr_hangman+0x0/0xd0 [kernel]                    7499776         1
process kslowd000(157)                                            1126         1
process flush-253:0(1336)                                      4999981         1
work_q  do_cache_clean                                            4875         1
process flush-253:4(11335)                                     5000013         1

The first column is the type of queue that the task periodically runs and can be a process, a kernel, or a work_q. A process entry is a user-space process with the second column listing the process name and the associated PID. A kernel entry is a kernel function scheduled to run with the second column listing the function and module name. A work_q entry is also a function in kernel-space, but it runs in a process context and is able to sleep. The "period(us)" column lists the measured period in microseconds between starts of the task. Variation in the time measurements may cause a timer interval of 10000 (1 millisecond) to be off, for example 9999 microseconds. The data are collated by the kernel timer data structure. A timer data structure may be initialized for each processor. Thus, for a periodic task running on all processors of a four-processor machine there would be four entries in the periodic.stp output (as seen for do_dbs_timer above). The last column is the count which indicates the number of times that the function or process ran.

The SystemTap runtime needs to do some regular runtime adjustment to keep the time measurements accurate because the processor can change the clock speed. Every microsecond there the SystemTap task is running on each of the four processors of the machine. Those are the first four entries associated with the stap_eb782113d30627ea6aa3ef949 kernel module.

The periodic.stp script makes clear the tasks the kernel is regularly performing. The do_dbs_timer is part of the kernel code that adjusts the processor clock frequency. It is running every 10 milliseconds (9999 microseconds) to determine whether the processor clock speed needs to be adjusted. The vmstat_update function is running once a second keep track of the virtual memory of system. The cache_reap runs every two seconds to reclaim memory being used to cache files.

If you're new to SystemTap, see my previous article Starting with SystemTap.

Last updated: January 10, 2023