| Demonstrations of offcputime, the Linux eBPF/bcc version. |
| |
| |
| This program shows stack traces that were blocked, and the total duration they |
| were blocked. It works by tracing when threads block and when they return to |
| CPU, measuring both the time they were blocked (aka the "off-CPU time") and the |
| blocked kernel stack trace and the task name. This data is summarized in kernel |
| by summing the blocked time by unique stack trace and task name. |
| |
| Here is some example output. To explain what we are seeing: the very first |
| stack trace looks like a page fault (do_page_fault() etc) from the "chmod" |
| command, and in total was off-CPU for 13 microseconds. |
| |
| # ./offcputime |
| Tracing off-CPU time (us) by kernel stack... Hit Ctrl-C to end. |
| ^C |
| schedule |
| schedule_timeout |
| io_schedule_timeout |
| bit_wait_io |
| __wait_on_bit |
| wait_on_page_bit_killable |
| __lock_page_or_retry |
| filemap_fault |
| __do_fault |
| handle_mm_fault |
| __do_page_fault |
| do_page_fault |
| page_fault |
| chmod |
| 13 |
| |
| schedule |
| rcu_nocb_kthread |
| kthread |
| ret_from_fork |
| ddebug_tables |
| rcuos/0 |
| 22 |
| |
| schedule |
| schedule_timeout |
| io_schedule_timeout |
| bit_wait_io |
| __wait_on_bit_lock |
| __lock_page |
| lock_page |
| __do_fault |
| handle_mm_fault |
| __do_page_fault |
| do_page_fault |
| page_fault |
| run |
| 27 |
| |
| schedule |
| schedule_timeout |
| io_schedule_timeout |
| bit_wait_io |
| __wait_on_bit |
| wait_on_page_bit_killable |
| __lock_page_or_retry |
| filemap_fault |
| __do_fault |
| handle_mm_fault |
| __do_page_fault |
| do_page_fault |
| page_fault |
| clear_user |
| padzero |
| load_elf_binary |
| search_binary_handler |
| load_script |
| search_binary_handler |
| do_execveat_common.isra.27 |
| run |
| 28 |
| |
| schedule |
| schedule_timeout |
| io_schedule_timeout |
| bit_wait_io |
| __wait_on_bit |
| wait_on_page_bit_killable |
| __lock_page_or_retry |
| filemap_fault |
| __do_fault |
| handle_mm_fault |
| __do_page_fault |
| do_page_fault |
| page_fault |
| run |
| 82 |
| |
| schedule |
| pipe_wait |
| pipe_read |
| __vfs_read |
| vfs_read |
| sys_read |
| entry_SYSCALL_64_fastpath |
| bash |
| 94 |
| |
| schedule |
| rcu_gp_kthread |
| kthread |
| ret_from_fork |
| ddebug_tables |
| rcu_sched |
| 104 |
| |
| schedule |
| schedule_timeout |
| io_schedule_timeout |
| bit_wait_io |
| __wait_on_bit |
| out_of_line_wait_on_bit |
| __wait_on_buffer |
| jbd2_journal_commit_transaction |
| kjournald2 |
| kthread |
| ret_from_fork |
| mb_cache_list |
| jbd2/xvda1-8 |
| 986 |
| |
| schedule |
| schedule_timeout |
| io_schedule_timeout |
| bit_wait_io |
| __wait_on_bit |
| out_of_line_wait_on_bit |
| __wait_on_buffer |
| jbd2_journal_commit_transaction |
| kjournald2 |
| kthread |
| ret_from_fork |
| mb_cache_list |
| jbd2/xvda1-8 |
| 6630 |
| |
| schedule |
| schedule_timeout |
| io_schedule_timeout |
| bit_wait_io |
| __wait_on_bit |
| out_of_line_wait_on_bit |
| do_get_write_access |
| jbd2_journal_get_write_access |
| __ext4_journal_get_write_access |
| ext4_mb_mark_diskspace_used |
| ext4_mb_new_blocks |
| ext4_ext_map_blocks |
| ext4_map_blocks |
| ext4_writepages |
| do_writepages |
| __filemap_fdatawrite_range |
| filemap_flush |
| ext4_alloc_da_blocks |
| ext4_rename |
| ext4_rename2 |
| supervise |
| 6645 |
| |
| schedule |
| schedule_timeout |
| io_schedule_timeout |
| bit_wait_io |
| __wait_on_bit |
| out_of_line_wait_on_bit |
| do_get_write_access |
| jbd2_journal_get_write_access |
| __ext4_journal_get_write_access |
| __ext4_new_inode |
| ext4_create |
| vfs_create |
| path_openat |
| do_filp_open |
| do_sys_open |
| sys_open |
| entry_SYSCALL_64_fastpath |
| supervise |
| 12702 |
| |
| schedule |
| rcu_nocb_kthread |
| kthread |
| ret_from_fork |
| rcuos/2 |
| 16036 |
| |
| schedule |
| rcu_nocb_kthread |
| kthread |
| ret_from_fork |
| rcuos/4 |
| 24085 |
| |
| schedule |
| do_wait |
| sys_wait4 |
| entry_SYSCALL_64_fastpath |
| run |
| 233055 |
| |
| schedule |
| schedule_timeout |
| io_schedule_timeout |
| bit_wait_io |
| __wait_on_bit |
| wait_on_page_bit |
| truncate_inode_pages_range |
| truncate_inode_pages_final |
| ext4_evict_inode |
| evict |
| iput |
| __dentry_kill |
| dput |
| sys_rename |
| entry_SYSCALL_64_fastpath |
| supervise |
| 297113 |
| |
| schedule |
| schedule_timeout |
| wait_woken |
| n_tty_read |
| tty_read |
| __vfs_read |
| vfs_read |
| sys_read |
| entry_SYSCALL_64_fastpath |
| bash |
| 1789866 |
| |
| schedule |
| schedule_timeout |
| io_schedule_timeout |
| do_blockdev_direct_IO |
| __blockdev_direct_IO |
| blkdev_direct_IO |
| generic_file_read_iter |
| blkdev_read_iter |
| __vfs_read |
| vfs_read |
| sys_read |
| entry_SYSCALL_64_fastpath |
| dd |
| 3310763 |
| |
| schedule |
| smpboot_thread_fn |
| kthread |
| ret_from_fork |
| watchdog/1 |
| 3999989 |
| |
| schedule |
| smpboot_thread_fn |
| kthread |
| ret_from_fork |
| watchdog/5 |
| 3999995 |
| |
| schedule |
| smpboot_thread_fn |
| kthread |
| ret_from_fork |
| watchdog/4 |
| 3999996 |
| |
| schedule |
| smpboot_thread_fn |
| kthread |
| ret_from_fork |
| watchdog/0 |
| 3999996 |
| |
| schedule |
| smpboot_thread_fn |
| kthread |
| ret_from_fork |
| watchdog/3 |
| 3999998 |
| |
| schedule |
| smpboot_thread_fn |
| kthread |
| ret_from_fork |
| watchdog/7 |
| 3999999 |
| |
| schedule |
| smpboot_thread_fn |
| kthread |
| ret_from_fork |
| watchdog/2 |
| 4000001 |
| |
| schedule |
| smpboot_thread_fn |
| kthread |
| ret_from_fork |
| watchdog/6 |
| 4000001 |
| |
| schedule |
| do_wait |
| sys_wait4 |
| entry_SYSCALL_64_fastpath |
| bash |
| 4039675 |
| |
| schedule |
| do_nanosleep |
| hrtimer_nanosleep |
| sys_nanosleep |
| entry_SYSCALL_64_fastpath |
| svscan |
| 5000112 |
| |
| schedule |
| schedule_hrtimeout_range_clock |
| schedule_hrtimeout_range |
| poll_schedule_timeout |
| do_select |
| core_sys_select |
| sys_select |
| entry_SYSCALL_64_fastpath |
| snmpd |
| 5998761 |
| |
| schedule |
| smpboot_thread_fn |
| kthread |
| ret_from_fork |
| migration/3 |
| 6149779 |
| |
| schedule |
| schedule_hrtimeout_range_clock |
| schedule_hrtimeout_range |
| poll_schedule_timeout |
| do_select |
| core_sys_select |
| sys_select |
| entry_SYSCALL_64_fastpath |
| ntpd |
| 6999832 |
| |
| schedule |
| worker_thread |
| kthread |
| ret_from_fork |
| kworker/u16:2 |
| 7131941 |
| |
| schedule |
| worker_thread |
| kthread |
| ret_from_fork |
| kworker/3:0 |
| 7999844 |
| |
| schedule |
| worker_thread |
| kthread |
| ret_from_fork |
| kworker/1:1 |
| 7999872 |
| |
| schedule |
| worker_thread |
| kthread |
| ret_from_fork |
| kworker/2:1 |
| 7999889 |
| |
| schedule |
| worker_thread |
| kthread |
| ret_from_fork |
| kworker/5:1 |
| 7999936 |
| |
| schedule |
| worker_thread |
| kthread |
| ret_from_fork |
| kworker/7:1 |
| 7999938 |
| |
| schedule |
| worker_thread |
| kthread |
| ret_from_fork |
| kworker/6:1 |
| 7999940 |
| |
| schedule |
| do_nanosleep |
| hrtimer_nanosleep |
| sys_nanosleep |
| entry_SYSCALL_64_fastpath |
| tail |
| 8000905 |
| |
| schedule |
| smpboot_thread_fn |
| kthread |
| ret_from_fork |
| migration/7 |
| 8197046 |
| |
| schedule |
| pipe_wait |
| pipe_read |
| __vfs_read |
| vfs_read |
| sys_read |
| entry_SYSCALL_64_fastpath |
| readproctitle |
| 8197835 |
| |
| schedule |
| smpboot_thread_fn |
| kthread |
| ret_from_fork |
| migration/4 |
| 8201851 |
| |
| schedule |
| smpboot_thread_fn |
| kthread |
| ret_from_fork |
| migration/2 |
| 8203375 |
| |
| schedule |
| smpboot_thread_fn |
| kthread |
| ret_from_fork |
| migration/6 |
| 8208664 |
| |
| schedule |
| smpboot_thread_fn |
| kthread |
| ret_from_fork |
| migration/5 |
| 8209819 |
| |
| schedule |
| smpboot_thread_fn |
| kthread |
| ret_from_fork |
| ddebug_tables |
| migration/0 |
| 8211292 |
| |
| schedule |
| smpboot_thread_fn |
| kthread |
| ret_from_fork |
| migration/1 |
| 8212100 |
| |
| schedule |
| worker_thread |
| kthread |
| ret_from_fork |
| kworker/0:2 |
| 8270305 |
| |
| schedule |
| rcu_nocb_kthread |
| kthread |
| ret_from_fork |
| rcuos/3 |
| 8349697 |
| |
| schedule |
| rcu_nocb_kthread |
| kthread |
| ret_from_fork |
| rcuos/2 |
| 8363357 |
| |
| schedule |
| rcu_nocb_kthread |
| kthread |
| ret_from_fork |
| rcuos/1 |
| 8365338 |
| |
| schedule |
| schedule_timeout |
| xfs_buf_terminate |
| kthread |
| ret_from_fork |
| xfsaild/md0 |
| 8371514 |
| |
| schedule |
| rcu_nocb_kthread |
| kthread |
| ret_from_fork |
| rcuos/4 |
| 8384013 |
| |
| schedule |
| rcu_nocb_kthread |
| kthread |
| ret_from_fork |
| rcuos/5 |
| 8390016 |
| |
| schedule |
| rcu_nocb_kthread |
| kthread |
| ret_from_fork |
| ddebug_tables |
| rcuos/0 |
| 8405428 |
| |
| schedule |
| schedule_timeout |
| rcu_gp_kthread |
| kthread |
| ret_from_fork |
| ddebug_tables |
| rcu_sched |
| 8406930 |
| |
| schedule |
| rcu_nocb_kthread |
| kthread |
| ret_from_fork |
| rcuos/7 |
| 8409575 |
| |
| schedule |
| rcu_nocb_kthread |
| kthread |
| ret_from_fork |
| rcuos/6 |
| 8415062 |
| |
| schedule |
| schedule_hrtimeout_range_clock |
| schedule_hrtimeout_range |
| poll_schedule_timeout |
| do_select |
| core_sys_select |
| sys_select |
| entry_SYSCALL_64_fastpath |
| offcputime |
| 8421478 |
| |
| schedule |
| worker_thread |
| kthread |
| ret_from_fork |
| kworker/4:0 |
| 8421492 |
| |
| schedule |
| schedule_hrtimeout_range_clock |
| schedule_hrtimeout_range |
| poll_schedule_timeout |
| do_select |
| core_sys_select |
| sys_select |
| entry_SYSCALL_64_fastpath |
| sshd |
| 14249005 |
| |
| schedule |
| schedule_hrtimeout_range_clock |
| schedule_hrtimeout_range |
| poll_schedule_timeout |
| do_sys_poll |
| sys_poll |
| entry_SYSCALL_64_fastpath |
| supervise |
| 81670888 |
| |
| Detaching... |
| |
| The last few stack traces aren't very interesting, since they are threads that |
| are ofter blocked off-CPU waiting for work. |
| |
| Do be somewhat careful with overhead: this is tracing scheduler functions, which |
| can be called very frequently. While this uses in-kernel summaries for |
| efficiency, the rate of scheduler functions can be very high (> 1,000,000/sec), |
| and this is performing stack walks when threads return to CPU. At some point |
| the overhead will be measurable. |
| |
| |
| A -p option can be used to filter (in-kernel) on a single process ID. For |
| example, only matching PID 26651, which is a running "dd" command: |
| |
| # ./offcputime -p 26651 |
| Tracing off-CPU time (us) by kernel stack... Hit Ctrl-C to end. |
| ^C |
| schedule |
| schedule_timeout |
| io_schedule_timeout |
| do_blockdev_direct_IO |
| __blockdev_direct_IO |
| blkdev_direct_IO |
| generic_file_read_iter |
| blkdev_read_iter |
| __vfs_read |
| vfs_read |
| sys_read |
| entry_SYSCALL_64_fastpath |
| dd |
| 2405710 |
| |
| Detaching... |
| |
| The stack trace shows "dd" is blocked waiting on disk I/O, as expected, for a |
| total of 2.4 seconds during tracing. |
| |
| |
| A duration can be added, for example, tracing for 5 seconds only: |
| |
| # ./offcputime -p 26651 5 |
| Tracing off-CPU time (us) by kernel stack for 5 secs. |
| |
| schedule |
| schedule_timeout |
| io_schedule_timeout |
| do_blockdev_direct_IO |
| __blockdev_direct_IO |
| blkdev_direct_IO |
| generic_file_read_iter |
| blkdev_read_iter |
| __vfs_read |
| vfs_read |
| sys_read |
| entry_SYSCALL_64_fastpath |
| dd |
| 4413909 |
| |
| Detaching... |
| |
| Here, dd was blocked for 4.4 seconds out of 5. Or put differently, likely |
| on-CPU for about 12% of the time. Which matches the ratio seen by time(1): |
| |
| # time dd if=/dev/md0 iflag=direct of=/dev/null bs=1k |
| ^C108115+0 records in |
| 108114+0 records out |
| 110708736 bytes (111 MB) copied, 13.7565 s, 8.0 MB/s |
| |
| real 0m13.760s |
| user 0m0.000s |
| sys 0m1.739s |
| |
| |
| A -f option will emit output using the "folded stacks" format, which can be |
| read directly by flamegraph.pl from the FlameGraph open source software |
| (https://github.com/brendangregg/FlameGraph). Eg: |
| |
| # ./offcputime -f 5 |
| bash;entry_SYSCALL_64_fastpath;sys_read;vfs_read;__vfs_read;tty_read;n_tty_read;call_rwsem_down_read_failed;rwsem_down_read_failed;schedule 8 |
| yes;entry_SYSCALL_64_fastpath;sys_write;vfs_write;__vfs_write;tty_write;n_tty_write;call_rwsem_down_read_failed;rwsem_down_read_failed;schedule 14 |
| run;page_fault;do_page_fault;__do_page_fault;handle_mm_fault;__do_fault;filemap_fault;__lock_page_or_retry;wait_on_page_bit_killable;__wait_on_bit;bit_wait_io;io_schedule_timeout;schedule_timeout;schedule 33 |
| rcuos/4;ret_from_fork;kthread;rcu_nocb_kthread;schedule 45 |
| bash;entry_SYSCALL_64_fastpath;sys_read;vfs_read;__vfs_read;pipe_read;pipe_wait;schedule 88 |
| run;page_fault;do_page_fault;__do_page_fault;handle_mm_fault;__do_fault;filemap_fault;__lock_page_or_retry;wait_on_page_bit_killable;__wait_on_bit;bit_wait_io;io_schedule_timeout;schedule_timeout;schedule 108 |
| jbd2/xvda1-8;mb_cache_list;ret_from_fork;kthread;kjournald2;jbd2_journal_commit_transaction;__wait_on_buffer;out_of_line_wait_on_bit;__wait_on_bit;bit_wait_io;io_schedule_timeout;schedule_timeout;schedule 828 |
| jbd2/xvda1-8;mb_cache_list;ret_from_fork;kthread;kjournald2;jbd2_journal_commit_transaction;__wait_on_buffer;out_of_line_wait_on_bit;__wait_on_bit;bit_wait_io;io_schedule_timeout;schedule_timeout;schedule 6201 |
| supervise;entry_SYSCALL_64_fastpath;sys_rename;dput;__dentry_kill;iput;evict;ext4_evict_inode;truncate_inode_pages_final;truncate_inode_pages_range;wait_on_page_bit;__wait_on_bit;bit_wait_io;io_schedule_timeout;schedule_timeout;schedule 41049 |
| run;entry_SYSCALL_64_fastpath;sys_wait4;do_wait;schedule 120709 |
| bash;entry_SYSCALL_64_fastpath;sys_wait4;do_wait;schedule 699320 |
| ksoftirqd/0;ret_from_fork;kthread;smpboot_thread_fn;schedule 1077529 |
| bash;entry_SYSCALL_64_fastpath;sys_read;vfs_read;__vfs_read;tty_read;n_tty_read;wait_woken;schedule_timeout;schedule 1362045 |
| sshd;entry_SYSCALL_64_fastpath;sys_select;core_sys_select;do_select;poll_schedule_timeout;schedule_hrtimeout_range;schedule_hrtimeout_range_clock;schedule 1377627 |
| migration/0;ddebug_tables;ret_from_fork;kthread;smpboot_thread_fn;schedule 2040753 |
| snmpd;entry_SYSCALL_64_fastpath;sys_select;core_sys_select;do_select;poll_schedule_timeout;schedule_hrtimeout_range;schedule_hrtimeout_range_clock;schedule 2197568 |
| migration/5;ret_from_fork;kthread;smpboot_thread_fn;schedule 3079426 |
| migration/7;ret_from_fork;kthread;smpboot_thread_fn;schedule 3084746 |
| kworker/6:2;ret_from_fork;kthread;worker_thread;schedule 3940583 |
| kworker/5:1;ret_from_fork;kthread;worker_thread;schedule 3944892 |
| kworker/1:2;ret_from_fork;kthread;worker_thread;schedule 3999646 |
| ntpd;entry_SYSCALL_64_fastpath;sys_select;core_sys_select;do_select;poll_schedule_timeout;schedule_hrtimeout_range;schedule_hrtimeout_range_clock;schedule 3999904 |
| kworker/u16:0;ret_from_fork;kthread;worker_thread;schedule 3999967 |
| kworker/7:0;ret_from_fork;kthread;worker_thread;schedule 3999987 |
| tail;entry_SYSCALL_64_fastpath;sys_nanosleep;hrtimer_nanosleep;do_nanosleep;schedule 4000473 |
| migration/1;ret_from_fork;kthread;smpboot_thread_fn;schedule 4091150 |
| migration/4;ret_from_fork;kthread;smpboot_thread_fn;schedule 4095217 |
| readproctitle;entry_SYSCALL_64_fastpath;sys_read;vfs_read;__vfs_read;pipe_read;pipe_wait;schedule 4108470 |
| migration/3;ret_from_fork;kthread;smpboot_thread_fn;schedule 4109264 |
| migration/2;ret_from_fork;kthread;smpboot_thread_fn;schedule 4109280 |
| migration/6;ret_from_fork;kthread;smpboot_thread_fn;schedule 4111143 |
| kworker/4:0;ret_from_fork;kthread;worker_thread;schedule 4402350 |
| kworker/3:0;ret_from_fork;kthread;worker_thread;schedule 4433988 |
| kworker/2:1;ret_from_fork;kthread;worker_thread;schedule 4636142 |
| kworker/0:2;ret_from_fork;kthread;worker_thread;schedule 4832023 |
| rcuos/1;ret_from_fork;kthread;rcu_nocb_kthread;schedule 4974186 |
| rcuos/5;ret_from_fork;kthread;rcu_nocb_kthread;schedule 4977137 |
| rcuos/6;ret_from_fork;kthread;rcu_nocb_kthread;schedule 4987769 |
| rcuos/3;ret_from_fork;kthread;rcu_nocb_kthread;schedule 4992282 |
| rcuos/4;ret_from_fork;kthread;rcu_nocb_kthread;schedule 4992364 |
| rcuos/2;ret_from_fork;kthread;rcu_nocb_kthread;schedule 4992714 |
| rcuos/0;ddebug_tables;ret_from_fork;kthread;rcu_nocb_kthread;schedule 4996504 |
| rcuos/7;ret_from_fork;kthread;rcu_nocb_kthread;schedule 4998497 |
| rcu_sched;ddebug_tables;ret_from_fork;kthread;rcu_gp_kthread;schedule_timeout;schedule 5000686 |
| offcputime;entry_SYSCALL_64_fastpath;sys_select;core_sys_select;do_select;poll_schedule_timeout;schedule_hrtimeout_range;schedule_hrtimeout_range_clock;schedule 5005063 |
| dd;entry_SYSCALL_64_fastpath;sys_read;vfs_read;__vfs_read;blkdev_read_iter;generic_file_read_iter;blkdev_direct_IO;__blockdev_direct_IO;do_blockdev_direct_IO;io_schedule_timeout;schedule_timeout;schedule 8025599 |
| supervise;entry_SYSCALL_64_fastpath;sys_poll;do_sys_poll;poll_schedule_timeout;schedule_hrtimeout_range;schedule_hrtimeout_range_clock;schedule 40835611 |
| |
| The stack traces are shown as single lines, with functions separated by |
| semicolons. The first entry is the task name. The 2nd column is the total |
| off-CPU time. |
| |
| I'd save this output to a file, then move it to the system where you'll be |
| creating your "off-CPU time flame graphs". |
| |
| |
| USAGE message: |
| |
| # ./offcputime -h |
| usage: offcputime [-h] [-u] [-p PID] [-v] [-f] [duration] |
| |
| Summarize off-CPU time by kernel stack trace |
| |
| positional arguments: |
| duration duration of trace, in seconds |
| |
| optional arguments: |
| -h, --help show this help message and exit |
| -u, --useronly user threads only (no kernel threads) |
| -p PID, --pid PID trace this PID only |
| -v, --verbose show raw addresses |
| -f, --folded output folded format |
| |
| examples: |
| ./offcputime # trace off-CPU stack time until Ctrl-C |
| ./offcputime 5 # trace for 5 seconds only |
| ./offcputime -f 5 # 5 seconds, and output in folded format |
| ./offcputime -u # don't include kernel threads (user only) |
| ./offcputime -p 185 # trace for PID 185 only |