1Demonstrations of offwaketime, the Linux eBPF/bcc version. 2 3 4This program shows kernel stack traces and task names that were blocked and 5"off-CPU", along with the stack traces and task names for the threads that woke 6them, and the total elapsed time from when they blocked to when they were woken 7up. This combines the summaries from both the offwaketime and wakeuptime tools. 8The time measurement will be very similar to off-CPU time, however, off-CPU time 9may include a little extra time spent waiting on a run queue to be scheduled. 10The combined stacks, task names, and total time is summarized in kernel context 11for efficiency, using an eBPF map. 12 13The output summary will further help you identify reasons why threads 14were blocking, and quantify the time from when they were blocked to woken up. 15This spans all types of blocking activity: disk I/O, network I/O, locks, page 16faults, swapping, sleeping, involuntary context switches, etc. 17 18Here is some sample output from a 5 second trace, truncated to highlight several 19stack pairs: 20 21# ./offwaketime 5 22Tracing blocked time (us) by kernel off-CPU and waker stack for 5 secs. 23 24[...] 25 26 waker: swapper/0 27 ffffffff8137897c blk_mq_complete_request 28 ffffffff81378930 __blk_mq_complete_request 29 ffffffff81378793 blk_mq_end_request 30 ffffffff813778b9 blk_mq_free_request 31 ffffffff8137782d __blk_mq_free_request 32 ffffffff8137bc57 blk_mq_put_tag 33 ffffffff8137b2c7 bt_clear_tag 34 ffffffff810b54d9 __wake_up 35 ffffffff810b5462 __wake_up_common 36 ffffffff810b5b12 autoremove_wake_function 37 - - 38 ffffffff81785085 schedule 39 ffffffff81787e16 schedule_timeout 40 ffffffff81784634 __sched_text_start 41 ffffffff8137b839 bt_get 42 ffffffff8137bbf7 blk_mq_get_tag 43 ffffffff8137761b __blk_mq_alloc_request 44 ffffffff81379442 blk_mq_map_request 45 ffffffff8137a445 blk_sq_make_request 46 ffffffff8136ebc3 generic_make_request 47 ffffffff8136ed07 submit_bio 48 ffffffff81225adf submit_bh_wbc 49 ffffffff81225b42 submit_bh 50 ffffffff812721e0 __ext4_get_inode_loc 51 ffffffff812751dd ext4_iget 52 ffffffff81275c90 ext4_iget_normal 53 ffffffff8127f45b ext4_lookup 54 ffffffff811f94ed lookup_real 55 ffffffff811fad43 __lookup_hash 56 ffffffff811fc3fb walk_component 57 ffffffff811fd050 link_path_walk 58 target: cksum 59 56529 60 61[...] 62 63 waker: swapper/1 64 ffffffff81475cf0 xen_evtchn_do_upcall 65 ffffffff81473e83 __xen_evtchn_do_upcall 66 ffffffff814766f7 evtchn_2l_handle_events 67 ffffffff810cb0c2 generic_handle_irq 68 ffffffff810cf1ca handle_percpu_irq 69 ffffffff810cb9c8 handle_irq_event_percpu 70 ffffffff8100b9e1 xen_timer_interrupt 71 ffffffff810dfba8 hrtimer_interrupt 72 ffffffff810df494 __hrtimer_run_queues 73 ffffffff810df082 hrtimer_wakeup 74 - - 75 ffffffff81785085 schedule 76 ffffffff817880bf do_nanosleep 77 ffffffff810e003d hrtimer_nanosleep 78 ffffffff810e018c sys_nanosleep 79 ffffffff81789076 entry_SYSCALL_64_fastpath 80 target: vmstat 81 3000331 82 83[...] 84 85 waker: swapper/0 86 ffffffff81378930 __blk_mq_complete_request 87 ffffffff8137875a blk_mq_end_request 88 ffffffff8136f157 blk_update_request 89 ffffffff8136836f bio_endio 90 ffffffff812ba709 mpage_end_io 91 ffffffff81176af9 unlock_page 92 ffffffff810b5781 __wake_up_bit 93 ffffffff810b54d9 __wake_up 94 ffffffff810b5462 __wake_up_common 95 ffffffff810b5b7e wake_bit_function 96 - - 97 ffffffff81785085 schedule 98 ffffffff81787e16 schedule_timeout 99 ffffffff81784634 __sched_text_start 100 ffffffff8178586b bit_wait_io 101 ffffffff8178563e __wait_on_bit_lock 102 ffffffff8117616e __lock_page_killable 103 ffffffff81177fce generic_file_read_iter 104 ffffffff811ef9c7 __vfs_read 105 ffffffff811f0206 vfs_read 106 ffffffff811f0eb6 sys_read 107 ffffffff81789076 entry_SYSCALL_64_fastpath 108 target: cksum 109 4334521 110 111[...] 112 113 waker: kworker/u16:2 114 ffffffff8178940f ret_from_fork 115 ffffffff81092979 kthread 116 ffffffff8108caeb worker_thread 117 ffffffff8108c80a process_one_work 118 ffffffff81496df5 flush_to_ldisc 119 ffffffff81494424 n_tty_receive_buf2 120 ffffffff814939fd n_tty_receive_buf_common 121 ffffffff810b54d9 __wake_up 122 ffffffff810b5462 __wake_up_common 123 ffffffff812037b6 pollwake 124 - - 125 ffffffff81785085 schedule 126 ffffffff81788234 schedule_hrtimeout_range_clock 127 ffffffff81788253 schedule_hrtimeout_range 128 ffffffff812035d4 poll_schedule_timeout 129 ffffffff8120402a do_select 130 ffffffff812042f0 core_sys_select 131 ffffffff8120449b sys_select 132 ffffffff81789076 entry_SYSCALL_64_fastpath 133 target: sshd 134 6530897 135 136[...] 137 138 waker: swapper/0 139 ffffffff81475cf0 xen_evtchn_do_upcall 140 ffffffff81473e83 __xen_evtchn_do_upcall 141 ffffffff814766f7 evtchn_2l_handle_events 142 ffffffff810cb0c2 generic_handle_irq 143 ffffffff810cf1ca handle_percpu_irq 144 ffffffff810cb9c8 handle_irq_event_percpu 145 ffffffff8100b9e1 xen_timer_interrupt 146 ffffffff810dfba8 hrtimer_interrupt 147 ffffffff810df494 __hrtimer_run_queues 148 ffffffff810df082 hrtimer_wakeup 149 - - 150 ffffffff81785085 schedule 151 ffffffff81787fc3 schedule_hrtimeout_range_clock.part.23 152 ffffffff81788219 schedule_hrtimeout_range_clock 153 ffffffff81788253 schedule_hrtimeout_range 154 ffffffff812035d4 poll_schedule_timeout 155 ffffffff81204b6d do_sys_poll 156 ffffffff81204cf2 sys_poll 157 ffffffff81789076 entry_SYSCALL_64_fastpath 158 target: supervise 159 16332240 160 161Detaching... 162 163The output includes two paths from the cksum(1) command, one for reading files 164via vfs_read() and the other doing a link_path_walk(). There is also a vmstat(8) 165stack showing it sleeping between intervals, and an sshd(8) stack showing it 166waiting on a file descriptor for input. 167 168The stack shown at the bottom is the off-CPU stack belonging to the task name 169shown after "target:". Then there is a separator, "-", and above it the waker 170stack and the waker task name after "waker:". The wakeup stack is printed 171in reverse order. 172 173The number beneath the stacks is the total time spent from the blocking event 174to the wakeup event. This is summed for all occurrences with the same stack 175pairs. 176 177 178The -u option will print user-mode target threads only, and the -f option will 179show the stacks in "folded stacks" format. Eg: 180 181# ./offwaketime -fu 5 182supervise;entry_SYSCALL_64_fastpath;sys_rename;dput;__dentry_kill;iput;evict;ext4_evict_inode;ext4_truncate;ext4_ext_truncate;ext4_ext_remove_space;ext4_free_blocks;__ext4_handle_dirty_metadata;_cond_resched;preempt_schedule_common;-; 2 183sshd;entry_SYSCALL_64_fastpath;sys_read;vfs_read;__vfs_read;tty_read;n_tty_read;down_read;_cond_resched;preempt_schedule_common;-; 2 184cksum;entry_SYSCALL_64_fastpath;sys_open;do_sys_open;do_filp_open;path_openat;lookup_real;ext4_lookup;ext4_iget_normal;ext4_iget;iget_locked;alloc_inode;ext4_alloc_inode;kmem_cache_alloc;_cond_resched;preempt_schedule_common;-; 3 185mkdir;page_fault;do_page_fault;__do_page_fault;handle_mm_fault;anon_vma_prepare;_cond_resched;preempt_schedule_common;-; 3 186cksum;entry_SYSCALL_64_fastpath;sys_open;do_sys_open;do_filp_open;path_openat;link_path_walk;walk_component;__lookup_hash;lookup_real;ext4_lookup;ext4_iget_normal;ext4_iget;__ext4_get_inode_loc;__breadahead;ll_rw_block;submit_bh_wbc;bio_alloc_bioset;mempool_alloc;_cond_resched;preempt_schedule_common;-; 3 187cksum;entry_SYSCALL_64_fastpath;sys_read;vfs_read;__vfs_read;generic_file_read_iter;page_cache_sync_readahead;ondemand_readahead;__do_page_cache_readahead;ext4_readpages;ext4_mpage_readpages;ext4_map_blocks;down_read;_cond_resched;preempt_schedule_common;-; 3 188cksum;entry_SYSCALL_64_fastpath;sys_open;do_sys_open;fd_install;__fd_install;_cond_resched;preempt_schedule_common;-; 3 189run;return_from_execve;sys_execve;do_execveat_common.isra.33;search_binary_handler;load_script;search_binary_handler;load_elf_binary;elf_map;vm_munmap;down_write;_cond_resched;preempt_schedule_common;-; 3 190svscan;entry_SYSCALL_64_fastpath;sys_getdents;iterate_dir;ext4_readdir;ext4_htree_fill_tree;htree_dirblock_to_tree;ext4_htree_store_dirent;__kmalloc;_cond_resched;preempt_schedule_common;-; 4 191cksum;entry_SYSCALL_64_fastpath;sys_open;do_sys_open;do_filp_open;path_openat;mutex_lock;_cond_resched;preempt_schedule_common;-; 4 192run;entry_SYSCALL_64_fastpath;sys_mprotect;down_write;_cond_resched;preempt_schedule_common;-; 5 193sshd;entry_SYSCALL_64_fastpath;sys_select;core_sys_select;do_select;_cond_resched;preempt_schedule_common;-; 5 194run;return_from_execve;sys_execve;do_execveat_common.isra.33;search_binary_handler;load_script;search_binary_handler;load_elf_binary;set_brk;vm_brk;down_write;_cond_resched;preempt_schedule_common;-; 5 195supervise;entry_SYSCALL_64_fastpath;sys_clone;_do_fork;copy_process;anon_vma_fork;anon_vma_clone;down_write;_cond_resched;preempt_schedule_common;-; 6 196svscan;retint_user;prepare_exit_to_usermode;exit_to_usermode_loop;schedule;-;hrtimer_wakeup;__hrtimer_run_queues;hrtimer_interrupt;xen_timer_interrupt;handle_irq_event_percpu;handle_percpu_irq;generic_handle_irq;evtchn_2l_handle_events;__xen_evtchn_do_upcall;xen_evtchn_do_upcall;swapper/0 11 197supervise;return_from_execve;sys_execve;do_execveat_common.isra.33;search_binary_handler;load_script;search_binary_handler;load_elf_binary;flush_old_exec;mmput;exit_mmap;free_pgtables;unlink_anon_vmas;down_write;_cond_resched;preempt_schedule_common;-; 12 198run;return_from_execve;sys_execve;do_execveat_common.isra.33;search_binary_handler;load_elf_binary;flush_old_exec;mmput;_cond_resched;preempt_schedule_common;-; 13 199sshd;entry_SYSCALL_64_fastpath;sys_write;vfs_write;__vfs_write;sock_write_iter;sock_sendmsg;inet_sendmsg;tcp_sendmsg;lock_sock_nested;_cond_resched;preempt_schedule_common;-; 14 200cksum;entry_SYSCALL_64_fastpath;sys_write;vfs_write;__vfs_write;tty_write;n_tty_write;mutex_lock;_cond_resched;preempt_schedule_common;-; 19 201sshd;retint_user;prepare_exit_to_usermode;exit_to_usermode_loop;schedule;-; 24 202run;return_from_execve;sys_execve;do_execveat_common.isra.33;search_binary_handler;load_script;search_binary_handler;load_elf_binary;vm_brk;down_write;_cond_resched;preempt_schedule_common;-; 31 203sshd;entry_SYSCALL_64_fastpath;sys_write;vfs_write;__vfs_write;sock_write_iter;sock_sendmsg;inet_sendmsg;tcp_sendmsg;sk_stream_alloc_skb;__alloc_skb;kmem_cache_alloc_node;_cond_resched;preempt_schedule_common;-; 32 204run;page_fault;do_page_fault;__do_page_fault;_cond_resched;preempt_schedule_common;-; 33 205run;page_fault;do_page_fault;__do_page_fault;handle_mm_fault;anon_vma_prepare;_cond_resched;preempt_schedule_common;-; 33 206run;entry_SYSCALL_64_fastpath;sys_clone;_do_fork;copy_process;down_write;_cond_resched;preempt_schedule_common;-; 35 207run;page_fault;do_page_fault;__do_page_fault;handle_mm_fault;__do_fault;filemap_fault;_cond_resched;preempt_schedule_common;-; 36 208run;return_from_execve;sys_execve;do_execveat_common.isra.33;search_binary_handler;load_script;search_binary_handler;load_elf_binary;elf_map;vm_mmap;vm_mmap_pgoff;down_write;_cond_resched;preempt_schedule_common;-; 38 209cksum;entry_SYSCALL_64_fastpath;sys_open;do_sys_open;do_filp_open;path_openat;lookup_real;ext4_lookup;ext4_iget_normal;ext4_iget;__ext4_get_inode_loc;__getblk_gfp;_cond_resched;preempt_schedule_common;-; 38 210chmod;int_ret_from_sys_call;syscall_return_slowpath;exit_to_usermode_loop;schedule;-; 39 211run;entry_SYSCALL_64_fastpath;sys_munmap;vm_munmap;do_munmap;unmap_region;unmap_vmas;unmap_single_vma;_cond_resched;preempt_schedule_common;-; 41 212readproctitle;entry_SYSCALL_64_fastpath;sys_read;vfs_read;__vfs_read;pipe_read;mutex_lock;_cond_resched;preempt_schedule_common;-; 44 213run;entry_SYSCALL_64_fastpath;sys_clone;_do_fork;copy_process;kmem_cache_alloc;_cond_resched;preempt_schedule_common;-; 48 214run;return_from_execve;sys_execve;do_execveat_common.isra.33;search_binary_handler;load_elf_binary;flush_old_exec;mmput;exit_mmap;unmap_vmas;unmap_single_vma;_cond_resched;preempt_schedule_common;-; 49 215sshd;entry_SYSCALL_64_fastpath;sys_select;core_sys_select;do_select;tty_poll;tty_ldisc_ref_wait;ldsem_down_read;_cond_resched;preempt_schedule_common;-; 50 216supervise;return_from_execve;sys_execve;do_execveat_common.isra.33;search_binary_handler;load_script;remove_arg_zero;get_user_pages;__get_user_pages;_cond_resched;preempt_schedule_common;-; 50 217readproctitle;int_ret_from_sys_call;syscall_return_slowpath;exit_to_usermode_loop;schedule;-; 51 218mkdir;int_ret_from_sys_call;syscall_return_slowpath;exit_to_usermode_loop;schedule;-; 53 219supervise;entry_SYSCALL_64_fastpath;sys_clone;_do_fork;copy_process;copy_creds;prepare_creds;kmem_cache_alloc;_cond_resched;preempt_schedule_common;-; 66 220cksum;entry_SYSCALL_64_fastpath;sys_open;do_sys_open;do_filp_open;path_openat;lookup_real;ext4_lookup;ext4_find_entry;__ext4_read_dirblock;ext4_bread;ext4_getblk;__getblk_gfp;_cond_resched;preempt_schedule_common;-; 76 221run;return_from_execve;sys_execve;do_execveat_common.isra.33;search_binary_handler;load_elf_binary;kernel_read;vfs_read;__vfs_read;generic_file_read_iter;_cond_resched;preempt_schedule_common;-; 96 222chmod;entry_SYSCALL_64_fastpath;sys_exit_group;do_group_exit;do_exit;mmput;exit_mmap;unmap_vmas;unmap_single_vma;_cond_resched;preempt_schedule_common;-; 100 223run;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;__sched_text_start;schedule_timeout;schedule;-;wake_bit_function;__wake_up_common;__wake_up;__wake_up_bit;unlock_page;handle_mm_fault;__do_page_fault;do_page_fault;page_fault;;run 117 224run;entry_SYSCALL_64_fastpath;sys_clone;_do_fork;copy_process;copy_page_range;_cond_resched;preempt_schedule_common;-; 117 225cksum;entry_SYSCALL_64_fastpath;sys_read;vfs_read;__vfs_read;generic_file_read_iter;_cond_resched;preempt_schedule_common;-; 121 226chown;entry_SYSCALL_64_fastpath;sys_mmap;sys_mmap_pgoff;vm_mmap_pgoff;down_write;_cond_resched;preempt_schedule_common;-; 137 227chown;entry_SYSCALL_64_fastpath;sys_mmap;sys_mmap_pgoff;vm_mmap_pgoff;do_mmap;mmap_region;kmem_cache_alloc;_cond_resched;preempt_schedule_common;-; 138 228run;return_from_execve;sys_execve;do_execveat_common.isra.33;count.isra.21.constprop.38;_cond_resched;preempt_schedule_common;-; 145 229supervise;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;__sched_text_start;schedule_timeout;schedule;-;wake_bit_function;__wake_up_common;__wake_up;__wake_up_bit;end_page_writeback;ext4_finish_bio;ext4_end_bio;bio_endio;blk_update_request;blk_mq_end_request;mkdir 147 230chmod;return_from_execve;sys_execve;do_execveat_common.isra.33;search_binary_handler;load_elf_binary;clear_user;page_fault;do_page_fault;__do_page_fault;_cond_resched;preempt_schedule_common;-; 159 231chown;return_from_execve;sys_execve;do_execveat_common.isra.33;search_binary_handler;load_elf_binary;setup_arg_pages;shift_arg_pages;vma_adjust;down_write;_cond_resched;preempt_schedule_common;-; 173 232chown;retint_user;prepare_exit_to_usermode;exit_to_usermode_loop;schedule;-; 176 233chmod;retint_user;prepare_exit_to_usermode;exit_to_usermode_loop;schedule;-; 191 234chmod;entry_SYSCALL_64_fastpath;sys_fchmodat;chmod_common;notify_change;ext4_setattr;__mark_inode_dirty;ext4_dirty_inode;ext4_mark_inode_dirty;ext4_reserve_inode_write;__ext4_get_inode_loc;__getblk_gfp;_cond_resched;preempt_schedule_common;-; 221 235cksum;entry_SYSCALL_64_fastpath;sys_open;do_sys_open;do_filp_open;path_openat;trailing_symlink;page_follow_link_light;page_getlink.isra.34.constprop.38;read_cache_page;do_read_cache_page;wait_on_page_read;wait_on_page_bit;__wait_on_bit;bit_wait_io;__sched_text_start;schedule_timeout;schedule;-;wake_bit_function;__wake_up_common;__wake_up;__wake_up_bit;unlock_page;mpage_end_io;bio_endio;blk_update_request;blk_mq_end_request;__blk_mq_complete_request;swapper/0 230 236cksum;entry_SYSCALL_64_fastpath;sys_open;do_sys_open;do_filp_open;path_openat;lookup_real;ext4_lookup;ext4_find_entry;__ext4_read_dirblock;ext4_bread;__wait_on_buffer;out_of_line_wait_on_bit;__wait_on_bit;bit_wait_io;__sched_text_start;schedule_timeout;schedule;-;wake_bit_function;__wake_up_common;__wake_up;__wake_up_bit;wake_up_bit;unlock_buffer;__end_buffer_read_notouch;end_buffer_read_sync;end_bio_bh_io_sync;bio_endio;rcu_sched 231 237supervise;return_from_execve;sys_execve;do_execveat_common.isra.33;search_binary_handler;load_script;search_binary_handler;load_elf_binary;flush_old_exec;mmput;_cond_resched;preempt_schedule_common;-; 234 238chown;int_ret_from_sys_call;syscall_return_slowpath;exit_to_usermode_loop;schedule;-; 249 239cksum;entry_SYSCALL_64_fastpath;sys_read;vfs_read;__vfs_read;generic_file_read_iter;__lock_page_killable;__wait_on_bit_lock;bit_wait_io;__sched_text_start;schedule_timeout;schedule;-;wake_bit_function;__wake_up_common;__wake_up;__wake_up_bit;unlock_page;mpage_end_io;bio_endio;blk_update_request;blk_mq_end_request;__blk_mq_complete_request;svscan 273 240mkdir;entry_SYSCALL_64_fastpath;sys_exit_group;do_group_exit;do_exit;mmput;exit_mmap;unmap_vmas;unmap_single_vma;_cond_resched;preempt_schedule_common;-; 382 241supervise;return_from_execve;sys_execve;do_execveat_common.isra.33;search_binary_handler;load_script;search_binary_handler;load_elf_binary;flush_old_exec;mmput;exit_mmap;unmap_vmas;unmap_single_vma;_cond_resched;preempt_schedule_common;-; 389 242run;page_fault;do_page_fault;__do_page_fault;handle_mm_fault;do_wp_page;wp_page_copy.isra.57;anon_vma_prepare;_cond_resched;preempt_schedule_common;-; 390 243supervise;return_from_execve;sys_execve;do_execveat_common.isra.33;sched_exec;stop_one_cpu;wait_for_completion;_cond_resched;preempt_schedule_common;-; 409 244run;return_from_execve;sys_execve;do_execveat_common.isra.33;sched_exec;stop_one_cpu;wait_for_completion;_cond_resched;preempt_schedule_common;-; 419 245mkdir;retint_user;prepare_exit_to_usermode;exit_to_usermode_loop;schedule;-; 457 246cksum;entry_SYSCALL_64_fastpath;sys_read;vfs_read;__vfs_read;generic_file_read_iter;__lock_page_killable;__wait_on_bit_lock;bit_wait_io;__sched_text_start;schedule_timeout;schedule;-;wake_bit_function;__wake_up_common;__wake_up;__wake_up_bit;unlock_page;mpage_end_io;bio_endio;blk_update_request;blk_mq_end_request;__blk_mq_complete_request;rcuos/0 460 247run;entry_SYSCALL_64_fastpath;sys_exit_group;do_group_exit;do_exit;mmput;exit_mmap;unmap_vmas;unmap_single_vma;_cond_resched;preempt_schedule_common;-; 481 248sshd;int_ret_from_sys_call;syscall_return_slowpath;exit_to_usermode_loop;schedule;-; 495 249cksum;do_filp_open;path_openat;lookup_real;ext4_lookup;ext4_find_entry;dx_probe;__ext4_read_dirblock;ext4_bread;ext4_getblk;ext4_map_blocks;ext4_ext_map_blocks;ext4_find_extent;__read_extent_tree_block;bh_submit_read;out_of_line_wait_on_bit;__wait_on_bit;bit_wait_io;__sched_text_start;schedule_timeout;schedule;-;wake_bit_function;__wake_up_common;__wake_up;__wake_up_bit;wake_up_bit;unlock_buffer;__end_buffer_read_notouch;end_buffer_read_sync;end_bio_bh_io_sync;bio_endio;swapper/0 495 250cksum;entry_SYSCALL_64_fastpath;sys_open;do_sys_open;do_filp_open;path_openat;lookup_real;ext4_lookup;ext4_find_entry;dx_probe;__ext4_read_dirblock;ext4_bread;__wait_on_buffer;out_of_line_wait_on_bit;__wait_on_bit;bit_wait_io;__sched_text_start;schedule_timeout;schedule;-;wake_bit_function;__wake_up_common;__wake_up;__wake_up_bit;wake_up_bit;unlock_buffer;__end_buffer_read_notouch;end_buffer_read_sync;end_bio_bh_io_sync;bio_endio;swapper/0 514 251run;entry_SYSCALL_64_fastpath;sys_clone;_do_fork;copy_process;alloc_pid;kmem_cache_alloc;_cond_resched;preempt_schedule_common;-; 572 252run;return_from_execve;sys_execve;do_execveat_common.isra.33;search_binary_handler;load_script;search_binary_handler;load_elf_binary;clear_user;page_fault;do_page_fault;__do_page_fault;handle_mm_fault;__pte_alloc;pte_alloc_one;alloc_pages_current;__alloc_pages_nodemask;_cond_resched;preempt_schedule_common;-; 579 253supervise;entry_SYSCALL_64_fastpath;sys_clone;_do_fork;copy_process;copy_page_range;_cond_resched;preempt_schedule_common;-; 590 254cksum;int_ret_from_sys_call;syscall_return_slowpath;exit_to_usermode_loop;schedule;-; 592 255chmod;return_from_execve;sys_execve;do_execveat_common.isra.33;search_binary_handler;load_elf_binary;setup_arg_pages;shift_arg_pages;vma_adjust;down_write;_cond_resched;preempt_schedule_common;-; 697 256cksum;entry_SYSCALL_64_fastpath;sys_open;do_sys_open;do_filp_open;path_openat;lookup_real;ext4_lookup;ext4_find_entry;__ext4_read_dirblock;ext4_bread;__wait_on_buffer;out_of_line_wait_on_bit;__wait_on_bit;bit_wait_io;__sched_text_start;schedule_timeout;schedule;-;wake_bit_function;__wake_up_common;__wake_up;__wake_up_bit;wake_up_bit;unlock_buffer;__end_buffer_read_notouch;end_buffer_read_sync;end_bio_bh_io_sync;bio_endio;swapper/0 706 257cksum;entry_SYSCALL_64_fastpath;sys_write;vfs_write;__vfs_write;tty_write;n_tty_write;mutex_lock;_cond_resched;preempt_schedule_common;-;woken_wake_function;__wake_up_common;__wake_up;n_tty_read;tty_read;__vfs_read;vfs_read;sys_read;entry_SYSCALL_64_fastpath;;sshd 804 258supervise;retint_user;prepare_exit_to_usermode;exit_to_usermode_loop;schedule;-; 1101 259run;return_from_execve;sys_execve;do_execveat_common.isra.33;search_binary_handler;load_elf_binary;flush_old_exec;mmput;exit_mmap;free_pgtables;unlink_anon_vmas;__put_anon_vma;_cond_resched;preempt_schedule_common;-; 1122 260cksum;entry_SYSCALL_64_fastpath;sys_read;vfs_read;__vfs_read;generic_file_read_iter;__lock_page_killable;__wait_on_bit_lock;bit_wait_io;__sched_text_start;schedule_timeout;schedule;-;wake_bit_function;__wake_up_common;__wake_up;__wake_up_bit;unlock_page;mpage_end_io;bio_endio;blk_update_request;blk_mq_end_request;__blk_mq_complete_request;readproctitle 1319 261run;int_ret_from_sys_call;syscall_return_slowpath;exit_to_usermode_loop;schedule;-; 1902 262cksum;entry_SYSCALL_64_fastpath;sys_read;vfs_read;__vfs_read;generic_file_read_iter;__lock_page_killable;__wait_on_bit_lock;bit_wait_io;__sched_text_start;schedule_timeout;schedule;-;wake_bit_function;__wake_up_common;__wake_up;__wake_up_bit;unlock_page;mpage_end_io;bio_endio;blk_update_request;blk_mq_end_request;__blk_mq_complete_request;chown 1925 263supervise;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;__sched_text_start;schedule_timeout;schedule;-;wake_bit_function;__wake_up_common;__wake_up;__wake_up_bit;end_page_writeback;ext4_finish_bio;ext4_end_bio;bio_endio;blk_update_request;blk_mq_end_request;cksum 2181 264cksum;entry_SYSCALL_64_fastpath;sys_open;do_sys_open;do_filp_open;path_openat;link_path_walk;walk_component;__lookup_hash;lookup_real;ext4_lookup;ext4_find_entry;__wait_on_buffer;out_of_line_wait_on_bit;__wait_on_bit;bit_wait_io;__sched_text_start;schedule_timeout;schedule;-;wake_bit_function;__wake_up_common;__wake_up;__wake_up_bit;wake_up_bit;unlock_buffer;__end_buffer_read_notouch;end_buffer_read_sync;end_bio_bh_io_sync;bio_endio;swapper/0 2599 265cksum;retint_user;prepare_exit_to_usermode;exit_to_usermode_loop;schedule;-; 2816 266supervise;ext4_rename2;ext4_rename;ext4_alloc_da_blocks;filemap_flush;__filemap_fdatawrite_range;do_writepages;ext4_writepages;ext4_map_blocks;ext4_ext_map_blocks;ext4_mb_new_blocks;ext4_mb_mark_diskspace_used;__ext4_journal_get_write_access;jbd2_journal_get_write_access;do_get_write_access;out_of_line_wait_on_bit;__wait_on_bit;bit_wait_io;__sched_text_start;schedule_timeout;schedule;-;wake_bit_function;__wake_up_common;__wake_up;__wake_up_bit;wake_up_bit;journal_end_buffer_io_sync;end_bio_bh_io_sync;bio_endio;blk_update_request;blk_mq_end_request;swapper/0 3393 267supervise;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;__sched_text_start;schedule_timeout;schedule;-;wake_bit_function;__wake_up_common;__wake_up;__wake_up_bit;end_page_writeback;ext4_finish_bio;ext4_end_bio;bio_endio;blk_update_request;blk_mq_end_request;supervise 5398 268sshd;entry_SYSCALL_64_fastpath;sys_select;core_sys_select;do_select;poll_schedule_timeout;schedule_hrtimeout_range;schedule_hrtimeout_range_clock;schedule;-;pollwake;__wake_up_common;__wake_up_sync_key;sock_def_readable;tcp_data_queue;tcp_rcv_established;tcp_v4_do_rcv;tcp_v4_rcv;ip_local_deliver_finish;ip_local_deliver;mkdir 6582 269cksum;entry_SYSCALL_64_fastpath;sys_read;vfs_read;__vfs_read;generic_file_read_iter;__lock_page_killable;__wait_on_bit_lock;bit_wait_io;__sched_text_start;schedule_timeout;schedule;-;wake_bit_function;__wake_up_common;__wake_up;__wake_up_bit;unlock_page;mpage_end_io;bio_endio;blk_update_request;blk_mq_end_request;__blk_mq_complete_request;chmod 8310 270run;retint_user;prepare_exit_to_usermode;exit_to_usermode_loop;schedule;-; 8444 271supervise;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;__sched_text_start;schedule_timeout;schedule;-;wake_bit_function;__wake_up_common;__wake_up;__wake_up_bit;end_page_writeback;ext4_finish_bio;ext4_end_bio;bio_endio;blk_update_request;blk_mq_end_request;readproctitle 9768 272supervise;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;__sched_text_start;schedule_timeout;schedule;-;wake_bit_function;__wake_up_common;__wake_up;__wake_up_bit;end_page_writeback;ext4_finish_bio;ext4_end_bio;bio_endio;blk_update_request;blk_mq_end_request;run 9945 273cksum;entry_SYSCALL_64_fastpath;sys_read;vfs_read;__vfs_read;generic_file_read_iter;__lock_page_killable;__wait_on_bit_lock;bit_wait_io;__sched_text_start;schedule_timeout;schedule;-;wake_bit_function;__wake_up_common;__wake_up;__wake_up_bit;unlock_page;mpage_end_io;bio_endio;blk_update_request;blk_mq_end_request;__blk_mq_complete_request;mkdir 11978 274cksum;entry_SYSCALL_64_fastpath;sys_open;do_sys_open;do_filp_open;path_openat;link_path_walk;walk_component;__lookup_hash;lookup_real;ext4_lookup;ext4_iget_normal;ext4_iget;__ext4_get_inode_loc;__wait_on_buffer;out_of_line_wait_on_bit;__wait_on_bit;bit_wait_io;__sched_text_start;schedule_timeout;schedule;-;wake_bit_function;__wake_up_common;__wake_up;__wake_up_bit;wake_up_bit;unlock_buffer;__end_buffer_read_notouch;end_buffer_read_sync;end_bio_bh_io_sync;bio_endio;swapper/0 12120 275cksum;link_path_walk;walk_component;__lookup_hash;lookup_real;ext4_lookup;ext4_iget_normal;ext4_iget;__ext4_get_inode_loc;submit_bh;submit_bh_wbc;submit_bio;generic_make_request;blk_sq_make_request;blk_mq_map_request;__blk_mq_alloc_request;blk_mq_get_tag;bt_get;__sched_text_start;schedule_timeout;schedule;-;autoremove_wake_function;__wake_up_common;__wake_up;bt_clear_tag;blk_mq_put_tag;__blk_mq_free_request;blk_mq_free_request;blk_mq_end_request;__blk_mq_complete_request;blk_mq_complete_request;swapper/0 23243 276cksum;entry_SYSCALL_64_fastpath;sys_open;do_sys_open;do_filp_open;path_openat;lookup_real;ext4_lookup;ext4_find_entry;__wait_on_buffer;out_of_line_wait_on_bit;__wait_on_bit;bit_wait_io;__sched_text_start;schedule_timeout;schedule;-;wake_bit_function;__wake_up_common;__wake_up;__wake_up_bit;wake_up_bit;unlock_buffer;__end_buffer_read_notouch;end_buffer_read_sync;end_bio_bh_io_sync;bio_endio;swapper/0 24767 277run;entry_SYSCALL_64_fastpath;sys_wait4;do_wait;schedule;-;child_wait_callback;__wake_up_common;__wake_up_sync_key;__wake_up_parent;do_notify_parent;do_exit;do_group_exit;sys_exit_group;entry_SYSCALL_64_fastpath;;chmod 33289 278run;entry_SYSCALL_64_fastpath;sys_wait4;do_wait;schedule;-;child_wait_callback;__wake_up_common;__wake_up_sync_key;__wake_up_parent;do_notify_parent;do_exit;do_group_exit;sys_exit_group;entry_SYSCALL_64_fastpath;;mkdir 34991 279cksum;entry_SYSCALL_64_fastpath;sys_read;vfs_read;__vfs_read;generic_file_read_iter;__lock_page_killable;__wait_on_bit_lock;bit_wait_io;__sched_text_start;schedule_timeout;schedule;-;wake_bit_function;__wake_up_common;__wake_up;__wake_up_bit;unlock_page;mpage_end_io;bio_endio;blk_update_request;blk_mq_end_request;__blk_mq_complete_request;supervise 35746 280run;entry_SYSCALL_64_fastpath;sys_wait4;do_wait;schedule;-;child_wait_callback;__wake_up_common;__wake_up_sync_key;__wake_up_parent;do_notify_parent;do_exit;do_group_exit;sys_exit_group;entry_SYSCALL_64_fastpath;;chown 36942 281supervise;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;__sched_text_start;schedule_timeout;schedule;-;wake_bit_function;__wake_up_common;__wake_up;__wake_up_bit;end_page_writeback;ext4_finish_bio;ext4_end_bio;bio_endio;blk_update_request;blk_mq_end_request;swapper/0 42993 282cksum;entry_SYSCALL_64_fastpath;sys_open;do_sys_open;do_filp_open;path_openat;lookup_real;ext4_lookup;ext4_iget_normal;ext4_iget;__ext4_get_inode_loc;__wait_on_buffer;out_of_line_wait_on_bit;__wait_on_bit;bit_wait_io;__sched_text_start;schedule_timeout;schedule;-;wake_bit_function;__wake_up_common;__wake_up;__wake_up_bit;wake_up_bit;unlock_buffer;__end_buffer_read_notouch;end_buffer_read_sync;end_bio_bh_io_sync;bio_endio;swapper/0 53348 283sshd;entry_SYSCALL_64_fastpath;sys_select;core_sys_select;do_select;poll_schedule_timeout;schedule_hrtimeout_range;schedule_hrtimeout_range_clock;schedule;-;pollwake;__wake_up_common;__wake_up;n_tty_receive_buf_common;n_tty_receive_buf2;flush_to_ldisc;process_one_work;worker_thread;kthread;ret_from_fork;kworker/u16:2 86256 284cksum;entry_SYSCALL_64_fastpath;sys_read;vfs_read;__vfs_read;generic_file_read_iter;__lock_page_killable;__wait_on_bit_lock;bit_wait_io;__sched_text_start;schedule_timeout;schedule;-;wake_bit_function;__wake_up_common;__wake_up;__wake_up_bit;unlock_page;mpage_end_io;bio_endio;blk_update_request;blk_mq_end_request;__blk_mq_complete_request;run 109480 285ntpd;entry_SYSCALL_64_fastpath;sys_select;core_sys_select;do_select;poll_schedule_timeout;schedule_hrtimeout_range;schedule_hrtimeout_range_clock;schedule;-;signal_wake_up_state;complete_signal;__send_signal;send_signal;do_send_sig_info;group_send_sig_info;kill_pid_info;it_real_fn;__hrtimer_run_queues;hrtimer_interrupt;cksum 999975 286ntpd;entry_SYSCALL_64_fastpath;sys_select;core_sys_select;do_select;poll_schedule_timeout;schedule_hrtimeout_range;schedule_hrtimeout_range_clock;schedule;-;signal_wake_up_state;complete_signal;__send_signal;send_signal;do_send_sig_info;group_send_sig_info;kill_pid_info;it_real_fn;__hrtimer_run_queues;hrtimer_interrupt;swapper/0 999976 287supervise;entry_SYSCALL_64_fastpath;sys_poll;do_sys_poll;poll_schedule_timeout;schedule_hrtimeout_range;schedule_hrtimeout_range_clock;schedule_hrtimeout_range_clock.part.23;schedule;-;hrtimer_wakeup;__hrtimer_run_queues;hrtimer_interrupt;xen_timer_interrupt;handle_irq_event_percpu;handle_percpu_irq;generic_handle_irq;evtchn_2l_handle_events;__xen_evtchn_do_upcall;xen_evtchn_do_upcall;chmod 1021082 288snmpd;entry_SYSCALL_64_fastpath;sys_select;core_sys_select;do_select;poll_schedule_timeout;schedule_hrtimeout_range;schedule_hrtimeout_range_clock;schedule_hrtimeout_range_clock.part.23;schedule;-;hrtimer_wakeup;__hrtimer_run_queues;hrtimer_interrupt;xen_timer_interrupt;handle_irq_event_percpu;handle_percpu_irq;generic_handle_irq;evtchn_2l_handle_events;__xen_evtchn_do_upcall;xen_evtchn_do_upcall;swapper/0 1726275 289ntpd;entry_SYSCALL_64_fastpath;sys_select;core_sys_select;do_select;poll_schedule_timeout;schedule_hrtimeout_range;schedule_hrtimeout_range_clock;schedule;-;signal_wake_up_state;complete_signal;__send_signal;send_signal;do_send_sig_info;group_send_sig_info;kill_pid_info;it_real_fn;__hrtimer_run_queues;hrtimer_interrupt;swapper/1 1999944 290supervise;entry_SYSCALL_64_fastpath;sys_poll;do_sys_poll;poll_schedule_timeout;schedule_hrtimeout_range;schedule_hrtimeout_range_clock;schedule_hrtimeout_range_clock.part.23;schedule;-;hrtimer_wakeup;__hrtimer_run_queues;hrtimer_interrupt;xen_timer_interrupt;handle_irq_event_percpu;handle_percpu_irq;generic_handle_irq;evtchn_2l_handle_events;__xen_evtchn_do_upcall;xen_evtchn_do_upcall;cksum 2041945 291cksum;entry_SYSCALL_64_fastpath;sys_read;vfs_read;__vfs_read;generic_file_read_iter;__lock_page_killable;__wait_on_bit_lock;bit_wait_io;__sched_text_start;schedule_timeout;schedule;-;wake_bit_function;__wake_up_common;__wake_up;__wake_up_bit;unlock_page;mpage_end_io;bio_endio;blk_update_request;blk_mq_end_request;__blk_mq_complete_request;swapper/0 3720413 292vmstat;entry_SYSCALL_64_fastpath;sys_nanosleep;hrtimer_nanosleep;do_nanosleep;schedule;-;hrtimer_wakeup;__hrtimer_run_queues;hrtimer_interrupt;xen_timer_interrupt;handle_irq_event_percpu;handle_percpu_irq;generic_handle_irq;evtchn_2l_handle_events;__xen_evtchn_do_upcall;xen_evtchn_do_upcall;swapper/0 4000402 293tail;entry_SYSCALL_64_fastpath;sys_nanosleep;hrtimer_nanosleep;do_nanosleep;schedule;-;hrtimer_wakeup;__hrtimer_run_queues;hrtimer_interrupt;xen_timer_interrupt;handle_irq_event_percpu;handle_percpu_irq;generic_handle_irq;evtchn_2l_handle_events;__xen_evtchn_do_upcall;xen_evtchn_do_upcall;swapper/0 4000447 294readproctitle;entry_SYSCALL_64_fastpath;sys_read;vfs_read;__vfs_read;pipe_read;pipe_wait;schedule;-;autoremove_wake_function;__wake_up_common;__wake_up_sync_key;pipe_write;__vfs_write;vfs_write;sys_write;entry_SYSCALL_64_fastpath;;run 4149862 295offwaketime.py;entry_SYSCALL_64_fastpath;sys_select;core_sys_select;do_select;poll_schedule_timeout;schedule_hrtimeout_range;schedule_hrtimeout_range_clock;schedule_hrtimeout_range_clock.part.23;schedule;-;hrtimer_wakeup;__hrtimer_run_queues;hrtimer_interrupt;xen_timer_interrupt;handle_irq_event_percpu;handle_percpu_irq;generic_handle_irq;evtchn_2l_handle_events;__xen_evtchn_do_upcall;xen_evtchn_do_upcall;swapper/1 5005058 296supervise;entry_SYSCALL_64_fastpath;sys_poll;do_sys_poll;poll_schedule_timeout;schedule_hrtimeout_range;schedule_hrtimeout_range_clock;schedule_hrtimeout_range_clock.part.23;schedule;-;hrtimer_wakeup;__hrtimer_run_queues;hrtimer_interrupt;xen_timer_interrupt;handle_irq_event_percpu;handle_percpu_irq;generic_handle_irq;evtchn_2l_handle_events;__xen_evtchn_do_upcall;xen_evtchn_do_upcall;swapper/1 8168600 297sshd;entry_SYSCALL_64_fastpath;sys_select;core_sys_select;do_select;poll_schedule_timeout;schedule_hrtimeout_range;schedule_hrtimeout_range_clock;schedule;-;pollwake;__wake_up_common;__wake_up;n_tty_receive_buf_common;n_tty_receive_buf2;flush_to_ldisc;process_one_work;worker_thread;kthread;ret_from_fork;kworker/u16:1 8821767 298supervise;entry_SYSCALL_64_fastpath;sys_poll;do_sys_poll;poll_schedule_timeout;schedule_hrtimeout_range;schedule_hrtimeout_range_clock;schedule_hrtimeout_range_clock.part.23;schedule;-;hrtimer_wakeup;__hrtimer_run_queues;hrtimer_interrupt;xen_timer_interrupt;handle_irq_event_percpu;handle_percpu_irq;generic_handle_irq;evtchn_2l_handle_events;__xen_evtchn_do_upcall;xen_evtchn_do_upcall;run 9186846 299supervise;entry_SYSCALL_64_fastpath;sys_poll;do_sys_poll;poll_schedule_timeout;schedule_hrtimeout_range;schedule_hrtimeout_range_clock;schedule_hrtimeout_range_clock.part.23;schedule;-;hrtimer_wakeup;__hrtimer_run_queues;hrtimer_interrupt;xen_timer_interrupt;handle_irq_event_percpu;handle_percpu_irq;generic_handle_irq;evtchn_2l_handle_events;__xen_evtchn_do_upcall;xen_evtchn_do_upcall;swapper/0 20415299 300 301This output format is suitable for feeding into the open source FlameGraph 302software, which visualizes these. 303 304 305USAGE message: 306 307# ./offwaketime -h 308usage: offwaketime [-h] [-p PID | -t TID | -u | -k] [-U | -K] [-d] [-f] 309 [--stack-storage-size STACK_STORAGE_SIZE] 310 [-m MIN_BLOCK_TIME] [-M MAX_BLOCK_TIME] 311 [duration] 312 313Summarize blocked time by kernel stack trace + waker stack 314 315positional arguments: 316 duration duration of trace, in seconds 317 318optional arguments: 319 -h, --help show this help message and exit 320 -p PID, --pid PID trace this PID only 321 -t TID, --tid TID trace this TID only 322 -u, --user-threads-only 323 user threads only (no kernel threads) 324 -k, --kernel-threads-only 325 kernel threads only (no user threads) 326 -U, --user-stacks-only 327 show stacks from user space only (no kernel space 328 stacks) 329 -K, --kernel-stacks-only 330 show stacks from kernel space only (no user space 331 stacks) 332 -d, --delimited insert delimiter between kernel/user stacks 333 -f, --folded output folded format 334 --stack-storage-size STACK_STORAGE_SIZE 335 the number of unique stack traces that can be stored 336 and displayed (default 1024) 337 -m MIN_BLOCK_TIME, --min-block-time MIN_BLOCK_TIME 338 the amount of time in microseconds over which we store 339 traces (default 1) 340 -M MAX_BLOCK_TIME, --max-block-time MAX_BLOCK_TIME 341 the amount of time in microseconds under which we 342 store traces (default U64_MAX) 343 344examples: 345 ./offwaketime # trace off-CPU + waker stack time until Ctrl-C 346 ./offwaketime 5 # trace for 5 seconds only 347 ./offwaketime -f 5 # 5 seconds, and output in folded format 348 ./offwaketime -m 1000 # trace only events that last more than 1000 usec 349 ./offwaketime -M 10000 # trace only events that last less than 10000 usec 350 ./offwaketime -p 185 # only trace threads for PID 185 351 ./offwaketime -t 188 # only trace thread 188 352 ./offwaketime -u # only trace user threads (no kernel) 353 ./offwaketime -k # only trace kernel threads (no user) 354 ./offwaketime -U # only show user space stacks (no kernel) 355 ./offwaketime -K # only show kernel space stacks (no user) 356