Determine what tasks are periodically taking processor time

​

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 minutes60seconds1,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 periodic script will collect data until Ctrl+c is pressed. Below is an example run of ​

​periodic.stp​

​:

​​Raw​​

$ /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 run 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 is 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 processrs 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.