blob: 1f715b79fd271436f466b658691079e3a3a89452 [file] [log] [blame]
Brendan Gregg7bf0e492016-01-27 23:17:40 -08001Demonstrations 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] [duration]
452
453Summarize sleep to wakeup time by waker kernel stack
454
455positional arguments:
456 duration duration of trace, in seconds
457
458optional arguments:
459 -h, --help show this help message and exit
460 -u, --useronly user threads only (no kernel threads)
461 -p PID, --pid PID trace this PID only
462 -v, --verbose show raw addresses
463 -f, --folded output folded format
464
465examples:
466 ./wakeuptime # trace blocked time with waker stacks
467 ./wakeuptime 5 # trace for 5 seconds only
468 ./wakeuptime -f 5 # 5 seconds, and output in folded format
469 ./wakeuptime -u # don't include kernel threads (user only)
Alex Bagehot3b9679a2016-02-06 16:01:02 +0000470 ./wakeuptime -p 185 # trace for PID 185 only