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