blob: e38e8cbea79a75fb7c91ad1c8f0895adca64912d [file] [log] [blame]
Brendan Greggaf2b46a2016-01-30 11:02:29 -08001Demonstrations 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 offcputime 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
Alex Bagehot7a313512016-02-06 16:09:58 +0000168The stack shown at the bottom is the off-CPU stack belonging to the task name
Brendan Greggaf2b46a2016-01-30 11:02:29 -0800169shown 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 occurances 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] [-u] [-p PID] [-v] [-f] [duration]
309
310Summarize blocked time by kernel off-CPU stack + waker stack
311
312positional arguments:
313 duration duration of trace, in seconds
314
315optional arguments:
316 -h, --help show this help message and exit
317 -u, --useronly user threads only (no kernel threads)
318 -p PID, --pid PID trace this PID only
319 -v, --verbose show raw addresses
320 -f, --folded output folded format
321
322examples:
323 ./offwaketime # trace off-CPU + waker stack time until Ctrl-C
324 ./offwaketime 5 # trace for 5 seconds only
325 ./offwaketime -f 5 # 5 seconds, and output in folded format
326 ./offwaketime -u # don't include kernel threads (user only)
327 ./offwaketime -p 185 # trace fo PID 185 only