• Home
  • Line#
  • Scopes#
  • Navigate#
  • Raw
  • Download
1Demonstrations of wakeuptime, the Linux eBPF/bcc version.
2
3
4This program measures when threads block, and shows the stack traces for the
5threads that performed the wakeup, along with the process names of the waker
6and target processes, and the total blocked time. This blocked time is measured
7from when a thread blocks, to when the wakeup signal is sent. Note that this
8time excludes some run queue latency from the target thread, which may not
9immediately execute if it needs to wait its turn on-CPU. All the data shown,
10stack traces, process names, and times, are summarized in-kernel using an eBPF
11map for efficiency.
12
13This tool is intended to be used after offcputime, which shows the directly
14blocked stacks. wakeuptime can then be used to show the stacks that performed
15the wakeups.
16
17Here is some example (truncated) output. To explain what we are seeing: the
18first stack trace shown is for a "vmstat" thread, which was woken up by
19"swapper/1". The stack trace is for swapper/1, which shows a timer interrupt.
20The total time is 4.0 seconds: this actually corresponds to a "vmstat 1"
21printing 4 x 1 second summaries -- we're seeing the interrupt stack that
22wakes up vmstat:
23
24# ./wakeuptime
25Tracing blocked time (us) by kernel stack... Hit Ctrl-C to end.
26^C
27[...truncated...]
28
29    target:          vmstat
30    ffffffff810df082 hrtimer_wakeup
31    ffffffff810df494 __hrtimer_run_queues
32    ffffffff810dfba8 hrtimer_interrupt
33    ffffffff8100b9e1 xen_timer_interrupt
34    ffffffff810cb9c8 handle_irq_event_percpu
35    ffffffff810cf1ca handle_percpu_irq
36    ffffffff810cb0c2 generic_handle_irq
37    ffffffff814766f7 evtchn_2l_handle_events
38    ffffffff81473e83 __xen_evtchn_do_upcall
39    ffffffff81475cf0 xen_evtchn_do_upcall
40    ffffffff8178adee xen_do_hypervisor_callback
41    waker:           swapper/1
42        4000415
43
44    target:          sshd
45    ffffffff812037b6 pollwake
46    ffffffff810b5462 __wake_up_common
47    ffffffff810b54d9 __wake_up
48    ffffffff814939fd n_tty_receive_buf_common
49    ffffffff81494424 n_tty_receive_buf2
50    ffffffff81496df5 flush_to_ldisc
51    ffffffff8108c80a process_one_work
52    ffffffff8108caeb worker_thread
53    ffffffff81092979 kthread
54    ffffffff8178940f ret_from_fork
55    waker:           kworker/u16:2
56        4001028
57
58    target:          rcuos/0
59    ffffffff810b5b12 autoremove_wake_function
60    ffffffff810b5462 __wake_up_common
61    ffffffff810b54d9 __wake_up
62    ffffffff810d8043 rcu_gp_kthread
63    ffffffff81092979 kthread
64    ffffffff8178940f ret_from_fork
65    ffffffff81ca9420 ddebug_tables
66    waker:           rcu_sched
67        4009976
68
69    target:          rcuos/7
70    ffffffff810b5b12 autoremove_wake_function
71    ffffffff810b5462 __wake_up_common
72    ffffffff810b54d9 __wake_up
73    ffffffff810d6f28 rcu_nocb_kthread
74    ffffffff81092979 kthread
75    ffffffff8178940f ret_from_fork
76    waker:           rcuos/6
77        4095781
78
79    target:          rcuos/6
80    ffffffff810b5b12 autoremove_wake_function
81    ffffffff810b5462 __wake_up_common
82    ffffffff810b54d9 __wake_up
83    ffffffff810d8043 rcu_gp_kthread
84    ffffffff81092979 kthread
85    ffffffff8178940f ret_from_fork
86    ffffffff81ca9420 ddebug_tables
87    waker:           rcu_sched
88        4101075
89
90    target:          rcuos/5
91    ffffffff810b5b12 autoremove_wake_function
92    ffffffff810b5462 __wake_up_common
93    ffffffff810b54d9 __wake_up
94    ffffffff810d6f28 rcu_nocb_kthread
95    ffffffff81092979 kthread
96    ffffffff8178940f ret_from_fork
97    waker:           rcuos/4
98        4103492
99
100    target:          rcuos/3
101    ffffffff810b5b12 autoremove_wake_function
102    ffffffff810b5462 __wake_up_common
103    ffffffff810b54d9 __wake_up
104    ffffffff810d6f28 rcu_nocb_kthread
105    ffffffff81092979 kthread
106    ffffffff8178940f ret_from_fork
107    waker:           rcuos/2
108        4107785
109
110    target:          rcuos/2
111    ffffffff810b5b12 autoremove_wake_function
112    ffffffff810b5462 __wake_up_common
113    ffffffff810b54d9 __wake_up
114    ffffffff810d8043 rcu_gp_kthread
115    ffffffff81092979 kthread
116    ffffffff8178940f ret_from_fork
117    ffffffff81ca9420 ddebug_tables
118    waker:           rcu_sched
119        4113308
120
121    target:          wakeuptime
122    ffffffff8108109e signal_wake_up_state
123    ffffffff810811e6 complete_signal
124    ffffffff8108186b __send_signal
125    ffffffff81081b0e send_signal
126    ffffffff810824e3 do_send_sig_info
127    ffffffff81082955 group_send_sig_info
128    ffffffff810829b4 __kill_pgrp_info
129    ffffffff81082a15 kill_pgrp
130    ffffffff8149081f __isig
131    ffffffff814912b4 isig
132    ffffffff81491f7c n_tty_receive_signal_char
133    ffffffff81493528 n_tty_receive_char_special
134    ffffffff8149419f n_tty_receive_buf_common
135    ffffffff81494424 n_tty_receive_buf2
136    ffffffff81496df5 flush_to_ldisc
137    ffffffff8108c80a process_one_work
138    ffffffff8108caeb worker_thread
139    ffffffff81092979 kthread
140    ffffffff8178940f ret_from_fork
141    waker:           kworker/u16:2
142        4125162
143
144    target:          sshd
145    ffffffff812037b6 pollwake
146    ffffffff810b5462 __wake_up_common
147    ffffffff810b58d5 __wake_up_sync_key
148    ffffffff816707ba sock_def_readable
149    ffffffff816d9f87 tcp_data_queue
150    ffffffff816dd465 tcp_rcv_established
151    ffffffff816e7ec5 tcp_v4_do_rcv
152    ffffffff816e8ff7 tcp_v4_rcv
153    ffffffff816c3a84 ip_local_deliver_finish
154    ffffffff816c3d80 ip_local_deliver
155    ffffffff816c3762 ip_rcv_finish
156    ffffffff816c4062 ip_rcv
157    ffffffff816885be __netif_receive_skb_core
158    ffffffff81688928 __netif_receive_skb
159    ffffffff81688993 netif_receive_skb_internal
160    ffffffff816894c5 napi_gro_receive
161    ffffffff81593111 xennet_poll
162    ffffffff81688e0e net_rx_action
163    ffffffff8107932b __do_softirq
164    ffffffff810796b2 irq_exit
165    waker:           swapper/0
166        4515762
167
168    target:          supervise
169    ffffffff810df082 hrtimer_wakeup
170    ffffffff810df494 __hrtimer_run_queues
171    ffffffff810dfba8 hrtimer_interrupt
172    ffffffff8100b9e1 xen_timer_interrupt
173    ffffffff810cb9c8 handle_irq_event_percpu
174    ffffffff810cf1ca handle_percpu_irq
175    ffffffff810cb0c2 generic_handle_irq
176    ffffffff814766f7 evtchn_2l_handle_events
177    ffffffff81473e83 __xen_evtchn_do_upcall
178    ffffffff81475cf0 xen_evtchn_do_upcall
179    ffffffff8178adee xen_do_hypervisor_callback
180    waker:           swapper/0
181        25523344
182
183Detaching...
184
185The second last stack trace shows sshd being woken up by packets being received.
186Near the bottom of the stack is driver processing, then IP, TCP, and finally
187socket processing as we work up the stack. The total time sshd (all sshd's)
188were blocked and woken up in this way was 4.5 seconds.
189
190Do be somewhat careful with overhead: this is tracing scheduler functions, which
191can be called very frequently. While this uses in-kernel summaries for
192efficiency, the rate of scheduler functions can be very high (> 1,000,000/sec),
193and this is performing stack walks when threads return to CPU. At some point
194the overhead will be measurable.
195
196
197A -p option can be used to filter (in-kernel) on a single process ID. For
198example, only matching PID 19169, which is a bash shell:
199
200# ./wakeuptime -p 19169
201Tracing blocked time (us) by kernel stack... Hit Ctrl-C to end.
202^C
203    target:          bash
204    ffffffff81075eb8 child_wait_callback
205    ffffffff810b5462 __wake_up_common
206    ffffffff810b58d5 __wake_up_sync_key
207    ffffffff81078046 __wake_up_parent
208    ffffffff810831b3 do_notify_parent
209    ffffffff81077eaf do_exit
210    ffffffff81077f93 do_group_exit
211    ffffffff81078014 sys_exit_group
212    ffffffff81789076 entry_SYSCALL_64_fastpath
213    waker:           ls
214        2015
215
216    target:          bash
217    ffffffff81075eb8 child_wait_callback
218    ffffffff810b5462 __wake_up_common
219    ffffffff810b58d5 __wake_up_sync_key
220    ffffffff81078046 __wake_up_parent
221    ffffffff810831b3 do_notify_parent
222    ffffffff81077eaf do_exit
223    ffffffff81077f93 do_group_exit
224    ffffffff81078014 sys_exit_group
225    ffffffff81789076 entry_SYSCALL_64_fastpath
226    waker:           sleep
227        1001347
228
229    target:          bash
230    ffffffff810b5921 woken_wake_function
231    ffffffff810b5462 __wake_up_common
232    ffffffff810b54d9 __wake_up
233    ffffffff814939fd n_tty_receive_buf_common
234    ffffffff81494424 n_tty_receive_buf2
235    ffffffff81496df5 flush_to_ldisc
236    ffffffff8108c80a process_one_work
237    ffffffff8108caeb worker_thread
238    ffffffff81092979 kthread
239    ffffffff8178940f ret_from_fork
240    waker:           kworker/u16:0
241        1871024
242
243    target:          bash
244    ffffffff810b5921 woken_wake_function
245    ffffffff810b5462 __wake_up_common
246    ffffffff810b54d9 __wake_up
247    ffffffff814939fd n_tty_receive_buf_common
248    ffffffff81494424 n_tty_receive_buf2
249    ffffffff81496df5 flush_to_ldisc
250    ffffffff8108c80a process_one_work
251    ffffffff8108caeb worker_thread
252    ffffffff81092979 kthread
253    ffffffff8178940f ret_from_fork
254    waker:           kworker/u16:2
255        3019839
256
257Detaching...
258
259These stack traces are fascinating! The first two shows bash waiting on child
260processes, an "ls" and a "sleep". The sleep stack was responsible for 1.0
261seconds of blocked time: I'd run a "sleep 1".
262
263The last two stacks show bash waking up to service tty input (keystrokes).
264
265
266A duration can be added, for example, tracing PID 19097 (sshd) for 5 seconds
267only:
268
269# ./wakeuptime -p 19097 5
270Tracing blocked time (us) by kernel stack for 5 secs.
271
272    target:          sshd
273    ffffffff812037b6 pollwake
274    ffffffff810b5462 __wake_up_common
275    ffffffff810b54d9 __wake_up
276    ffffffff814939fd n_tty_receive_buf_common
277    ffffffff81494424 n_tty_receive_buf2
278    ffffffff81496df5 flush_to_ldisc
279    ffffffff8108c80a process_one_work
280    ffffffff8108caeb worker_thread
281    ffffffff81092979 kthread
282    ffffffff8178940f ret_from_fork
283    waker:           kworker/u16:1
284        785
285
286    target:          sshd
287    ffffffff812037b6 pollwake
288    ffffffff810b5462 __wake_up_common
289    ffffffff810b54d9 __wake_up
290    ffffffff814939fd n_tty_receive_buf_common
291    ffffffff81494424 n_tty_receive_buf2
292    ffffffff81496df5 flush_to_ldisc
293    ffffffff8108c80a process_one_work
294    ffffffff8108caeb worker_thread
295    ffffffff81092979 kthread
296    ffffffff8178940f ret_from_fork
297    waker:           kworker/u16:2
298        2843
299
300    target:          sshd
301    ffffffff812037b6 pollwake
302    ffffffff810b5462 __wake_up_common
303    ffffffff810b58d5 __wake_up_sync_key
304    ffffffff816707ba sock_def_readable
305    ffffffff816d9f87 tcp_data_queue
306    ffffffff816dd465 tcp_rcv_established
307    ffffffff816e7ec5 tcp_v4_do_rcv
308    ffffffff816e8ff7 tcp_v4_rcv
309    ffffffff816c3a84 ip_local_deliver_finish
310    ffffffff816c3d80 ip_local_deliver
311    ffffffff816c3762 ip_rcv_finish
312    ffffffff816c4062 ip_rcv
313    ffffffff816884be __netif_receive_skb_core
314    ffffffff81688928 __netif_receive_skb
315    ffffffff81688993 netif_receive_skb_internal
316    ffffffff816894c5 napi_gro_receive
317    ffffffff81593111 xennet_poll
318    ffffffff81688e0e net_rx_action
319    ffffffff8107932b __do_softirq
320    ffffffff810796b2 irq_exit
321    waker:           swapper/0
322        276103
323
324Detaching...
325
326
327A -f option will emit output using the "folded stacks" format, which can be
328read directly by flamegraph.pl from the FlameGraph open source software
329(https://github.com/brendangregg/FlameGraph). Eg:
330
331# ./wakeuptime -f 5
332run;entry_SYSCALL_64_fastpath;sys_mmap;sys_mmap_pgoff;vm_mmap_pgoff;do_mmap;mmap_region;do_munmap;__split_vma.isra.35;vma_adjust;call_rwsem_wake;rwsem_wake;__rwsem_do_wake;run 1
333run;page_fault;do_page_fault;__do_page_fault;handle_mm_fault;unlock_page;__wake_up_bit;__wake_up;__wake_up_common;wake_bit_function;run 1
334chmod;page_fault;do_page_fault;__do_page_fault;handle_mm_fault;unlock_page;__wake_up_bit;__wake_up;__wake_up_common;wake_bit_function;mkdir 2
335supervise;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_file_vma;call_rwsem_wake;rwsem_wake;__rwsem_do_wake;supervise 2
336run;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;unlock_page;__wake_up_bit;__wake_up;__wake_up_common;wake_bit_function;run 2
337run;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_file_vma;call_rwsem_wake;rwsem_wake;__rwsem_do_wake;run 3
338mkdir;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;handle_mm_fault;unlock_page;__wake_up_bit;__wake_up;__wake_up_common;wake_bit_function;mkdir 3
339mkdir;page_fault;do_page_fault;__do_page_fault;handle_mm_fault;unlock_page;__wake_up_bit;__wake_up;__wake_up_common;wake_bit_function;mkdir 4
340run;page_fault;do_page_fault;__do_page_fault;handle_mm_fault;unlock_page;__wake_up_bit;__wake_up;__wake_up_common;wake_bit_function;mkdir 4
341supervise;entry_SYSCALL_64_fastpath;sys_clone;_do_fork;copy_process;call_rwsem_wake;rwsem_wake;__rwsem_do_wake;supervise 5
342rcuos/0;ddebug_tables;ret_from_fork;kthread;rcu_nocb_kthread;rcu_gp_kthread_wake;__wake_up;__wake_up_common;autoremove_wake_function;rcu_sched 10
343swapper/7;cpu_bringup_and_idle;cpu_startup_entry;rcu_idle_enter;rcu_eqs_enter;rcu_eqs_enter_common;wake_nocb_leader;__wake_up;__wake_up_common;autoremove_wake_function;rcuos/6 12
344swapper/0;xen_start_kernel;x86_64_start_reservations;start_kernel;rest_init;cpu_startup_entry;rcu_idle_enter;rcu_eqs_enter;rcu_eqs_enter_common;wake_nocb_leader;__wake_up;__wake_up_common;autoremove_wake_function;rcuos/0 16
345rcuos/6;ret_from_fork;kthread;rcu_nocb_kthread;rcu_gp_kthread_wake;__wake_up;__wake_up_common;autoremove_wake_function;rcu_sched 19
346run;page_fault;do_page_fault;__do_page_fault;handle_mm_fault;unlock_page;__wake_up_bit;__wake_up;__wake_up_common;wake_bit_function;run 25
347bash;entry_SYSCALL_64_fastpath;sys_write;vfs_write;__vfs_write;tty_write;n_tty_write;do_output_char;pty_write;tty_flip_buffer_push;queue_work_on;__queue_work;insert_work;kworker/u16:2 26
348swapper/4;cpu_bringup_and_idle;cpu_startup_entry;rcu_idle_enter;rcu_eqs_enter;rcu_eqs_enter_common;wake_nocb_leader;__wake_up;__wake_up_common;autoremove_wake_function;rcuos/4 30
349pickup;entry_SYSCALL_64_fastpath;sys_write;vfs_write;__vfs_write;sock_write_iter;sock_sendmsg;unix_stream_sendmsg;sock_def_readable;__wake_up_sync_key;__wake_up_common;ep_poll_callback;__wake_up_locked;__wake_up_common;master 36
350swapper/1;cpu_bringup_and_idle;cpu_startup_entry;rcu_idle_enter;rcu_eqs_enter;rcu_eqs_enter_common;wake_nocb_leader;__wake_up;__wake_up_common;autoremove_wake_function;rcuos/0 52
351chown;xen_evtchn_do_upcall;__xen_evtchn_do_upcall;evtchn_2l_handle_events;generic_handle_irq;handle_edge_irq;handle_irq_event;handle_irq_event_percpu;blkif_interrupt;blk_mq_complete_request;__blk_mq_complete_request;blk_mq_end_request;blk_update_request;bio_endio;ext4_end_bio;ext4_finish_bio;end_page_writeback;__wake_up_bit;__wake_up;__wake_up_common;wake_bit_function;supervise 189
352supervise;xen_evtchn_do_upcall;__xen_evtchn_do_upcall;evtchn_2l_handle_events;generic_handle_irq;handle_edge_irq;handle_irq_event;handle_irq_event_percpu;blkif_interrupt;blk_mq_complete_request;__blk_mq_complete_request;blk_mq_end_request;blk_update_request;bio_endio;end_bio_bh_io_sync;journal_end_buffer_io_sync;wake_up_bit;__wake_up_bit;__wake_up;__wake_up_common;wake_bit_function;supervise 371
353supervise;xen_evtchn_do_upcall;__xen_evtchn_do_upcall;evtchn_2l_handle_events;generic_handle_irq;handle_edge_irq;handle_irq_event;handle_irq_event_percpu;blkif_interrupt;blk_mq_complete_request;__blk_mq_complete_request;blk_mq_end_request;blk_update_request;bio_endio;ext4_end_bio;ext4_finish_bio;end_page_writeback;__wake_up_bit;__wake_up;__wake_up_common;wake_bit_function;supervise 3093
354chown;xen_do_hypervisor_callback;xen_evtchn_do_upcall;irq_exit;__do_softirq;run_timer_softirq;call_timer_fn;process_timeout;rcu_sched 3985
355supervise;xen_do_hypervisor_callback;xen_evtchn_do_upcall;irq_exit;__do_softirq;run_timer_softirq;call_timer_fn;process_timeout;rcu_sched 3997
356supervise;__xen_evtchn_do_upcall;evtchn_2l_handle_events;generic_handle_irq;handle_edge_irq;handle_irq_event;handle_irq_event_percpu;blkif_interrupt;blk_mq_complete_request;__blk_mq_complete_request;blk_mq_end_request;blk_update_request;bio_endio;end_bio_bh_io_sync;journal_end_buffer_io_sync;unlock_buffer;wake_up_bit;__wake_up_bit;__wake_up;__wake_up_common;wake_bit_function;jbd2/xvda1-8 4511
357chmod;xen_evtchn_do_upcall;__xen_evtchn_do_upcall;evtchn_2l_handle_events;generic_handle_irq;handle_edge_irq;handle_irq_event;handle_irq_event_percpu;blkif_interrupt;blk_mq_complete_request;__blk_mq_complete_request;blk_mq_end_request;blk_update_request;bio_endio;ext4_end_bio;ext4_finish_bio;end_page_writeback;__wake_up_bit;__wake_up;__wake_up_common;wake_bit_function;supervise 4646
358swapper/4;xen_do_hypervisor_callback;xen_evtchn_do_upcall;irq_exit;__do_softirq;run_timer_softirq;call_timer_fn;process_timeout;rcu_sched 7971
359readproctitle;__xen_evtchn_do_upcall;evtchn_2l_handle_events;generic_handle_irq;handle_edge_irq;handle_irq_event;handle_irq_event_percpu;blkif_interrupt;blk_mq_complete_request;__blk_mq_complete_request;blk_mq_end_request;blk_update_request;bio_endio;end_bio_bh_io_sync;journal_end_buffer_io_sync;unlock_buffer;wake_up_bit;__wake_up_bit;__wake_up;__wake_up_common;wake_bit_function;jbd2/xvda1-8 8249
360swapper/2;cpu_bringup_and_idle;cpu_startup_entry;rcu_idle_enter;rcu_eqs_enter;rcu_eqs_enter_common;wake_nocb_leader;__wake_up;__wake_up_common;autoremove_wake_function;rcuos/2 12016
361run;xen_evtchn_do_upcall;__xen_evtchn_do_upcall;evtchn_2l_handle_events;generic_handle_irq;handle_edge_irq;handle_irq_event;handle_irq_event_percpu;blkif_interrupt;blk_mq_complete_request;__blk_mq_complete_request;blk_mq_end_request;blk_update_request;bio_endio;ext4_end_bio;ext4_finish_bio;end_page_writeback;__wake_up_bit;__wake_up;__wake_up_common;wake_bit_function;supervise 13973
362swapper/0;xen_evtchn_do_upcall;__xen_evtchn_do_upcall;evtchn_2l_handle_events;generic_handle_irq;handle_edge_irq;handle_irq_event;handle_irq_event_percpu;blkif_interrupt;blk_mq_complete_request;__blk_mq_complete_request;blk_mq_end_request;blk_update_request;bio_endio;end_bio_bh_io_sync;journal_end_buffer_io_sync;wake_up_bit;__wake_up_bit;__wake_up;__wake_up_common;wake_bit_function;supervise 15736
363run;xen_do_hypervisor_callback;xen_evtchn_do_upcall;irq_exit;__do_softirq;run_timer_softirq;call_timer_fn;process_timeout;rcu_sched 19916
364swapper/1;xen_do_hypervisor_callback;xen_evtchn_do_upcall;irq_exit;__do_softirq;run_timer_softirq;call_timer_fn;process_timeout;rcu_sched 31877
365mkdir;entry_SYSCALL_64_fastpath;sys_exit_group;do_group_exit;do_exit;do_notify_parent;__wake_up_parent;__wake_up_sync_key;__wake_up_common;child_wait_callback;run 39619
366swapper/5;xen_do_hypervisor_callback;xen_evtchn_do_upcall;irq_exit;__do_softirq;run_timer_softirq;call_timer_fn;process_timeout;rcu_sched 39837
367chown;entry_SYSCALL_64_fastpath;sys_exit_group;do_group_exit;do_exit;do_notify_parent;__wake_up_parent;__wake_up_sync_key;__wake_up_common;child_wait_callback;run 42190
368chmod;entry_SYSCALL_64_fastpath;sys_exit_group;do_group_exit;do_exit;do_notify_parent;__wake_up_parent;__wake_up_sync_key;__wake_up_common;child_wait_callback;run 43486
369swapper/0;xen_evtchn_do_upcall;__xen_evtchn_do_upcall;evtchn_2l_handle_events;generic_handle_irq;handle_edge_irq;handle_irq_event;handle_irq_event_percpu;blkif_interrupt;blk_mq_complete_request;__blk_mq_complete_request;blk_mq_end_request;blk_update_request;bio_endio;ext4_end_bio;ext4_finish_bio;end_page_writeback;__wake_up_bit;__wake_up;__wake_up_common;wake_bit_function;supervise 47810
370bash;entry_SYSCALL_64_fastpath;sys_write;vfs_write;__vfs_write;tty_write;n_tty_write;pty_write;tty_flip_buffer_push;queue_work_on;__queue_work;insert_work;kworker/u16:2 86794
371vmstat;entry_SYSCALL_64_fastpath;sys_write;vfs_write;__vfs_write;tty_write;n_tty_write;pty_write;tty_flip_buffer_push;queue_work_on;__queue_work;insert_work;kworker/u16:2 210848
372swapper/0;irq_exit;__do_softirq;net_rx_action;xennet_poll;napi_gro_receive;netif_receive_skb_internal;__netif_receive_skb;__netif_receive_skb_core;ip_rcv;ip_rcv_finish;ip_local_deliver;ip_local_deliver_finish;tcp_v4_rcv;tcp_v4_do_rcv;tcp_rcv_established;tcp_data_queue;sock_def_readable;__wake_up_sync_key;__wake_up_common;pollwake;sshd 543295
373kworker/u16:2;ret_from_fork;kthread;worker_thread;process_one_work;flush_to_ldisc;n_tty_receive_buf2;n_tty_receive_buf_common;__wake_up;__wake_up_common;woken_wake_function;bash 543570
374swapper/7;xen_do_hypervisor_callback;xen_evtchn_do_upcall;irq_exit;__do_softirq;run_timer_softirq;call_timer_fn;delayed_work_timer_fn;__queue_work;insert_work;kworker/u16:2 741234
375sshd;entry_SYSCALL_64_fastpath;sys_write;vfs_write;__vfs_write;tty_write;n_tty_write;pty_write;tty_flip_buffer_push;queue_work_on;__queue_work;insert_work;kworker/u16:2 855436
376bash;return_from_execve;sys_execve;do_execveat_common.isra.33;sched_exec;stop_one_cpu;cpu_stop_queue_work;migration/7 942685
377swapper/0;xen_do_hypervisor_callback;xen_evtchn_do_upcall;irq_exit;__do_softirq;run_timer_softirq;call_timer_fn;process_timeout;rcu_sched 969059
378swapper/4;xen_do_hypervisor_callback;xen_evtchn_do_upcall;__xen_evtchn_do_upcall;evtchn_2l_handle_events;generic_handle_irq;handle_percpu_irq;handle_irq_event_percpu;add_interrupt_randomness;credit_entropy_bits;queue_work_on;__queue_work;insert_work;kworker/4:0 999981
379swapper/0;xen_do_hypervisor_callback;xen_evtchn_do_upcall;__xen_evtchn_do_upcall;evtchn_2l_handle_events;generic_handle_irq;handle_percpu_irq;handle_irq_event_percpu;xen_timer_interrupt;hrtimer_interrupt;__hrtimer_run_queues;hrtimer_wakeup;sleep 1000103
380sleep;entry_SYSCALL_64_fastpath;sys_exit_group;do_group_exit;do_exit;do_notify_parent;__wake_up_parent;__wake_up_sync_key;__wake_up_common;child_wait_callback;bash 1001564
381swapper/3;xen_do_hypervisor_callback;xen_evtchn_do_upcall;irq_exit;__do_softirq;run_timer_softirq;call_timer_fn;process_timeout;rcu_sched 1016980
382mkdir;xen_do_hypervisor_callback;xen_evtchn_do_upcall;__xen_evtchn_do_upcall;evtchn_2l_handle_events;generic_handle_irq;handle_percpu_irq;handle_irq_event_percpu;xen_timer_interrupt;hrtimer_interrupt;__hrtimer_run_queues;hrtimer_wakeup;supervise 1019302
383chown;xen_do_hypervisor_callback;xen_evtchn_do_upcall;__xen_evtchn_do_upcall;evtchn_2l_handle_events;generic_handle_irq;handle_percpu_irq;handle_irq_event_percpu;xen_timer_interrupt;hrtimer_interrupt;__hrtimer_run_queues;hrtimer_wakeup;supervise 1019908
384swapper/7;xen_do_hypervisor_callback;xen_evtchn_do_upcall;__xen_evtchn_do_upcall;evtchn_2l_handle_events;generic_handle_irq;handle_percpu_irq;handle_irq_event_percpu;xen_timer_interrupt;hrtimer_interrupt;__hrtimer_run_queues;hrtimer_wakeup;supervise 1021074
385swapper/4;xen_do_hypervisor_callback;xen_evtchn_do_upcall;__xen_evtchn_do_upcall;evtchn_2l_handle_events;generic_handle_irq;handle_percpu_irq;handle_irq_event_percpu;xen_timer_interrupt;hrtimer_interrupt;__hrtimer_run_queues;hrtimer_wakeup;supervise 1021075
386run;return_from_execve;sys_execve;do_execveat_common.isra.33;sched_exec;stop_one_cpu;cpu_stop_queue_work;migration/6 1030506
387run;return_from_execve;sys_execve;do_execveat_common.isra.33;sched_exec;stop_one_cpu;cpu_stop_queue_work;migration/4 1032424
388swapper/6;xen_do_hypervisor_callback;xen_evtchn_do_upcall;irq_exit;__do_softirq;run_timer_softirq;call_timer_fn;process_timeout;rcu_sched 1036908
389run;return_from_execve;sys_execve;do_execveat_common.isra.33;sched_exec;stop_one_cpu;cpu_stop_queue_work;migration/1 1040207
390run;return_from_execve;sys_execve;do_execveat_common.isra.33;sched_exec;stop_one_cpu;cpu_stop_queue_work;migration/5 1044756
391run;return_from_execve;sys_execve;do_execveat_common.isra.33;sched_exec;stop_one_cpu;cpu_stop_queue_work;migration/3 1044986
392run;return_from_execve;sys_execve;do_execveat_common.isra.33;sched_exec;stop_one_cpu;cpu_stop_queue_work;migration/2 1046347
393supervise;return_from_execve;sys_execve;do_execveat_common.isra.33;sched_exec;stop_one_cpu;cpu_stop_queue_work;migration/7 1093598
394swapper/7;xen_do_hypervisor_callback;xen_evtchn_do_upcall;irq_exit;__do_softirq;run_timer_softirq;call_timer_fn;process_timeout;rcu_sched 1858510
395supervise;xen_do_hypervisor_callback;xen_evtchn_do_upcall;__xen_evtchn_do_upcall;evtchn_2l_handle_events;generic_handle_irq;handle_percpu_irq;handle_irq_event_percpu;xen_timer_interrupt;hrtimer_interrupt;__hrtimer_run_queues;hrtimer_wakeup;supervise 2041736
396swapper/6;xen_do_hypervisor_callback;xen_evtchn_do_upcall;__xen_evtchn_do_upcall;evtchn_2l_handle_events;generic_handle_irq;handle_percpu_irq;handle_irq_event_percpu;xen_timer_interrupt;hrtimer_interrupt;__hrtimer_run_queues;hrtimer_wakeup;supervise 2042028
397swapper/1;xen_do_hypervisor_callback;xen_evtchn_do_upcall;__xen_evtchn_do_upcall;evtchn_2l_handle_events;generic_handle_irq;handle_percpu_irq;handle_irq_event_percpu;xen_timer_interrupt;hrtimer_interrupt;__hrtimer_run_queues;hrtimer_wakeup;supervise 2042149
398swapper/2;xen_do_hypervisor_callback;xen_evtchn_do_upcall;__xen_evtchn_do_upcall;evtchn_2l_handle_events;generic_handle_irq;handle_percpu_irq;handle_irq_event_percpu;xen_timer_interrupt;hrtimer_interrupt;__hrtimer_run_queues;hrtimer_wakeup;supervise 2042152
399supervise;return_from_execve;sys_execve;do_execveat_common.isra.33;sched_exec;stop_one_cpu;cpu_stop_queue_work;migration/6 2042698
400supervise;return_from_execve;sys_execve;do_execveat_common.isra.33;sched_exec;stop_one_cpu;cpu_stop_queue_work;migration/0 2044085
401run;return_from_execve;sys_execve;do_execveat_common.isra.33;sched_exec;stop_one_cpu;cpu_stop_queue_work;migration/0 2047386
402run;return_from_execve;sys_execve;do_execveat_common.isra.33;sched_exec;stop_one_cpu;cpu_stop_queue_work;migration/7 2065637
403swapper/4;xen_do_hypervisor_callback;xen_evtchn_do_upcall;irq_exit;__do_softirq;run_timer_softirq;call_timer_fn;delayed_work_timer_fn;__queue_work;insert_work;kworker/4:0 2999930
404swapper/6;xen_do_hypervisor_callback;xen_evtchn_do_upcall;__xen_evtchn_do_upcall;evtchn_2l_handle_events;generic_handle_irq;handle_percpu_irq;handle_irq_event_percpu;xen_timer_interrupt;hrtimer_interrupt;__hrtimer_run_queues;hrtimer_wakeup;snmpd 2999999
405swapper/1;xen_do_hypervisor_callback;xen_evtchn_do_upcall;irq_exit;__do_softirq;run_timer_softirq;call_timer_fn;delayed_work_timer_fn;__queue_work;insert_work;kworker/u16:2 3010848
406supervise;return_from_execve;sys_execve;do_execveat_common.isra.33;sched_exec;stop_one_cpu;cpu_stop_queue_work;migration/5 3050881
407supervise;return_from_execve;sys_execve;do_execveat_common.isra.33;sched_exec;stop_one_cpu;cpu_stop_queue_work;migration/1 3051454
408supervise;return_from_execve;sys_execve;do_execveat_common.isra.33;sched_exec;stop_one_cpu;cpu_stop_queue_work;migration/3 3054844
409supervise;return_from_execve;sys_execve;do_execveat_common.isra.33;sched_exec;stop_one_cpu;cpu_stop_queue_work;migration/2 3059548
410supervise;return_from_execve;sys_execve;do_execveat_common.isra.33;sched_exec;stop_one_cpu;cpu_stop_queue_work;migration/4 3061480
411swapper/3;xen_do_hypervisor_callback;xen_evtchn_do_upcall;__xen_evtchn_do_upcall;evtchn_2l_handle_events;generic_handle_irq;handle_percpu_irq;handle_irq_event_percpu;xen_timer_interrupt;hrtimer_interrupt;__hrtimer_run_queues;hrtimer_wakeup;supervise 3062666
412swapper/5;xen_do_hypervisor_callback;xen_evtchn_do_upcall;__xen_evtchn_do_upcall;evtchn_2l_handle_events;generic_handle_irq;handle_percpu_irq;handle_irq_event_percpu;xen_timer_interrupt;hrtimer_interrupt;__hrtimer_run_queues;hrtimer_wakeup;supervise 3063222
413swapper/7;xen_do_hypervisor_callback;xen_evtchn_do_upcall;__xen_evtchn_do_upcall;evtchn_2l_handle_events;generic_handle_irq;handle_percpu_irq;handle_irq_event_percpu;xen_timer_interrupt;hrtimer_interrupt;__hrtimer_run_queues;it_real_fn;kill_pid_info;group_send_sig_info;do_send_sig_info;send_signal;__send_signal;complete_signal;signal_wake_up_state;ntpd 3999835
414swapper/1;xen_do_hypervisor_callback;xen_evtchn_do_upcall;irq_exit;__do_softirq;run_timer_softirq;call_timer_fn;delayed_work_timer_fn;__queue_work;insert_work;kworker/1:0 3999933
415swapper/6;xen_do_hypervisor_callback;xen_evtchn_do_upcall;irq_exit;__do_softirq;run_timer_softirq;call_timer_fn;delayed_work_timer_fn;__queue_work;insert_work;kworker/6:0 3999938
416swapper/3;xen_do_hypervisor_callback;xen_evtchn_do_upcall;irq_exit;__do_softirq;run_timer_softirq;call_timer_fn;delayed_work_timer_fn;__queue_work;insert_work;kworker/3:0 3999938
417swapper/7;xen_do_hypervisor_callback;xen_evtchn_do_upcall;irq_exit;__do_softirq;run_timer_softirq;call_timer_fn;delayed_work_timer_fn;__queue_work;insert_work;kworker/7:2 3999939
418swapper/5;xen_do_hypervisor_callback;xen_evtchn_do_upcall;irq_exit;__do_softirq;run_timer_softirq;call_timer_fn;delayed_work_timer_fn;__queue_work;insert_work;kworker/5:3 3999942
419swapper/2;xen_do_hypervisor_callback;xen_evtchn_do_upcall;irq_exit;__do_softirq;run_timer_softirq;call_timer_fn;delayed_work_timer_fn;__queue_work;insert_work;kworker/2:1 3999946
420swapper/0;xen_do_hypervisor_callback;xen_evtchn_do_upcall;irq_exit;__do_softirq;run_timer_softirq;call_timer_fn;delayed_work_timer_fn;__queue_work;insert_work;kworker/0:1 3999953
421swapper/0;xen_do_hypervisor_callback;xen_evtchn_do_upcall;__xen_evtchn_do_upcall;evtchn_2l_handle_events;generic_handle_irq;handle_percpu_irq;handle_irq_event_percpu;xen_timer_interrupt;hrtimer_interrupt;__hrtimer_run_queues;hrtimer_wakeup;tail 4000414
422swapper/4;xen_do_hypervisor_callback;xen_evtchn_do_upcall;__xen_evtchn_do_upcall;evtchn_2l_handle_events;generic_handle_irq;handle_percpu_irq;handle_irq_event_percpu;xen_timer_interrupt;hrtimer_interrupt;__hrtimer_run_queues;hrtimer_wakeup;vmstat 4000417
423chmod;xen_do_hypervisor_callback;xen_evtchn_do_upcall;__xen_evtchn_do_upcall;evtchn_2l_handle_events;generic_handle_irq;handle_percpu_irq;handle_irq_event_percpu;xen_timer_interrupt;hrtimer_interrupt;__hrtimer_run_queues;hrtimer_wakeup;supervise 4083231
424run;entry_SYSCALL_64_fastpath;sys_write;vfs_write;__vfs_write;pipe_write;__wake_up_sync_key;__wake_up_common;autoremove_wake_function;readproctitle 4096457
425rcuos/4;ret_from_fork;kthread;rcu_nocb_kthread;__wake_up;__wake_up_common;autoremove_wake_function;rcuos/5 4973072
426rcuos/0;ddebug_tables;ret_from_fork;kthread;rcu_nocb_kthread;__wake_up;__wake_up_common;autoremove_wake_function;rcuos/1 4973898
427rcu_sched;ddebug_tables;ret_from_fork;kthread;rcu_gp_kthread;__wake_up;__wake_up_common;autoremove_wake_function;rcuos/0 4976731
428rcu_sched;ddebug_tables;ret_from_fork;kthread;rcu_gp_kthread;__wake_up;__wake_up_common;autoremove_wake_function;rcuos/4 4976755
429rcuos/2;ret_from_fork;kthread;rcu_nocb_kthread;__wake_up;__wake_up_common;autoremove_wake_function;rcuos/3 4980207
430rcu_sched;ddebug_tables;ret_from_fork;kthread;rcu_gp_kthread;__wake_up;__wake_up_common;autoremove_wake_function;rcuos/2 4980502
431rcuos/6;ret_from_fork;kthread;rcu_nocb_kthread;__wake_up;__wake_up_common;autoremove_wake_function;rcuos/7 4981025
432rcu_sched;ddebug_tables;ret_from_fork;kthread;rcu_gp_kthread;__wake_up;__wake_up_common;autoremove_wake_function;rcuos/6 4983110
433kworker/u16:2;ret_from_fork;kthread;worker_thread;process_one_work;flush_to_ldisc;n_tty_receive_buf2;n_tty_receive_buf_common;__wake_up;__wake_up_common;pollwake;sshd 5004430
434swapper/6;xen_do_hypervisor_callback;xen_evtchn_do_upcall;__xen_evtchn_do_upcall;evtchn_2l_handle_events;generic_handle_irq;handle_percpu_irq;handle_irq_event_percpu;xen_timer_interrupt;hrtimer_interrupt;__hrtimer_run_queues;hrtimer_wakeup;wakeuptime 5005051
435run;xen_do_hypervisor_callback;xen_evtchn_do_upcall;__xen_evtchn_do_upcall;evtchn_2l_handle_events;generic_handle_irq;handle_percpu_irq;handle_irq_event_percpu;xen_timer_interrupt;hrtimer_interrupt;__hrtimer_run_queues;hrtimer_wakeup;supervise 7144088
436swapper/0;xen_do_hypervisor_callback;xen_evtchn_do_upcall;__xen_evtchn_do_upcall;evtchn_2l_handle_events;generic_handle_irq;handle_percpu_irq;handle_irq_event_percpu;xen_timer_interrupt;hrtimer_interrupt;__hrtimer_run_queues;hrtimer_wakeup;supervise 11229310
437
438The stack traces are shown as single lines, with functions separated by
439semicolons. The first entry is the waker task name, followed by the waker stack,
440and then last entry is the target task name. As a flame graph, this puts the
441waker name on the bottom, followed by the waker stack, and then the target
442task name on top. The 2nd column is the total blocked time.
443
444I'd save this output to a file, then move it to the system where you'll be
445creating your "wakeup time flame graphs".
446
447
448USAGE message:
449
450# ./wakeuptime -h
451usage: wakeuptime [-h] [-u] [-p PID] [-v] [-f]
452                  [--stack-storage-size STACK_STORAGE_SIZE]
453                  [-m MIN_BLOCK_TIME] [-M MAX_BLOCK_TIME]
454                  [duration]
455
456Summarize sleep to wakeup time by waker kernel stack
457
458positional arguments:
459  duration              duration of trace, in seconds
460
461optional arguments:
462  -h, --help            show this help message and exit
463  -u, --useronly        user threads only (no kernel threads)
464  -p PID, --pid PID     trace this PID only
465  -v, --verbose         show raw addresses
466  -f, --folded          output folded format
467  --stack-storage-size STACK_STORAGE_SIZE
468                        the number of unique stack traces that can be stored
469                        and displayed (default 1024)
470  -m MIN_BLOCK_TIME, --min-block-time MIN_BLOCK_TIME
471                        the amount of time in microseconds over which we store
472                        traces (default 1)
473  -M MAX_BLOCK_TIME, --max-block-time MAX_BLOCK_TIME
474                        the amount of time in microseconds under which we
475                        store traces (default U64_MAX)
476examples:
477    ./wakeuptime             # trace blocked time with waker stacks
478    ./wakeuptime 5           # trace for 5 seconds only
479    ./wakeuptime -f 5        # 5 seconds, and output in folded format
480    ./wakeuptime -u          # don't include kernel threads (user only)
481    ./wakeuptime -p 185      # trace for PID 185 only
482