You can not select more than 25 topics
Topics must start with a letter or number, can include dashes ('-') and can be up to 35 characters long.
481 lines
33 KiB
481 lines
33 KiB
Demonstrations of wakeuptime, the Linux eBPF/bcc version. |
|
|
|
|
|
This program measures when threads block, and shows the stack traces for the |
|
threads that performed the wakeup, along with the process names of the waker |
|
and target processes, and the total blocked time. This blocked time is measured |
|
from when a thread blocks, to when the wakeup signal is sent. Note that this |
|
time excludes some run queue latency from the target thread, which may not |
|
immediately execute if it needs to wait its turn on-CPU. All the data shown, |
|
stack traces, process names, and times, are summarized in-kernel using an eBPF |
|
map for efficiency. |
|
|
|
This tool is intended to be used after offcputime, which shows the directly |
|
blocked stacks. wakeuptime can then be used to show the stacks that performed |
|
the wakeups. |
|
|
|
Here is some example (truncated) output. To explain what we are seeing: the |
|
first stack trace shown is for a "vmstat" thread, which was woken up by |
|
"swapper/1". The stack trace is for swapper/1, which shows a timer interrupt. |
|
The total time is 4.0 seconds: this actually corresponds to a "vmstat 1" |
|
printing 4 x 1 second summaries -- we're seeing the interrupt stack that |
|
wakes up vmstat: |
|
|
|
# ./wakeuptime |
|
Tracing blocked time (us) by kernel stack... Hit Ctrl-C to end. |
|
^C |
|
[...truncated...] |
|
|
|
target: vmstat |
|
ffffffff810df082 hrtimer_wakeup |
|
ffffffff810df494 __hrtimer_run_queues |
|
ffffffff810dfba8 hrtimer_interrupt |
|
ffffffff8100b9e1 xen_timer_interrupt |
|
ffffffff810cb9c8 handle_irq_event_percpu |
|
ffffffff810cf1ca handle_percpu_irq |
|
ffffffff810cb0c2 generic_handle_irq |
|
ffffffff814766f7 evtchn_2l_handle_events |
|
ffffffff81473e83 __xen_evtchn_do_upcall |
|
ffffffff81475cf0 xen_evtchn_do_upcall |
|
ffffffff8178adee xen_do_hypervisor_callback |
|
waker: swapper/1 |
|
4000415 |
|
|
|
target: sshd |
|
ffffffff812037b6 pollwake |
|
ffffffff810b5462 __wake_up_common |
|
ffffffff810b54d9 __wake_up |
|
ffffffff814939fd n_tty_receive_buf_common |
|
ffffffff81494424 n_tty_receive_buf2 |
|
ffffffff81496df5 flush_to_ldisc |
|
ffffffff8108c80a process_one_work |
|
ffffffff8108caeb worker_thread |
|
ffffffff81092979 kthread |
|
ffffffff8178940f ret_from_fork |
|
waker: kworker/u16:2 |
|
4001028 |
|
|
|
target: rcuos/0 |
|
ffffffff810b5b12 autoremove_wake_function |
|
ffffffff810b5462 __wake_up_common |
|
ffffffff810b54d9 __wake_up |
|
ffffffff810d8043 rcu_gp_kthread |
|
ffffffff81092979 kthread |
|
ffffffff8178940f ret_from_fork |
|
ffffffff81ca9420 ddebug_tables |
|
waker: rcu_sched |
|
4009976 |
|
|
|
target: rcuos/7 |
|
ffffffff810b5b12 autoremove_wake_function |
|
ffffffff810b5462 __wake_up_common |
|
ffffffff810b54d9 __wake_up |
|
ffffffff810d6f28 rcu_nocb_kthread |
|
ffffffff81092979 kthread |
|
ffffffff8178940f ret_from_fork |
|
waker: rcuos/6 |
|
4095781 |
|
|
|
target: rcuos/6 |
|
ffffffff810b5b12 autoremove_wake_function |
|
ffffffff810b5462 __wake_up_common |
|
ffffffff810b54d9 __wake_up |
|
ffffffff810d8043 rcu_gp_kthread |
|
ffffffff81092979 kthread |
|
ffffffff8178940f ret_from_fork |
|
ffffffff81ca9420 ddebug_tables |
|
waker: rcu_sched |
|
4101075 |
|
|
|
target: rcuos/5 |
|
ffffffff810b5b12 autoremove_wake_function |
|
ffffffff810b5462 __wake_up_common |
|
ffffffff810b54d9 __wake_up |
|
ffffffff810d6f28 rcu_nocb_kthread |
|
ffffffff81092979 kthread |
|
ffffffff8178940f ret_from_fork |
|
waker: rcuos/4 |
|
4103492 |
|
|
|
target: rcuos/3 |
|
ffffffff810b5b12 autoremove_wake_function |
|
ffffffff810b5462 __wake_up_common |
|
ffffffff810b54d9 __wake_up |
|
ffffffff810d6f28 rcu_nocb_kthread |
|
ffffffff81092979 kthread |
|
ffffffff8178940f ret_from_fork |
|
waker: rcuos/2 |
|
4107785 |
|
|
|
target: rcuos/2 |
|
ffffffff810b5b12 autoremove_wake_function |
|
ffffffff810b5462 __wake_up_common |
|
ffffffff810b54d9 __wake_up |
|
ffffffff810d8043 rcu_gp_kthread |
|
ffffffff81092979 kthread |
|
ffffffff8178940f ret_from_fork |
|
ffffffff81ca9420 ddebug_tables |
|
waker: rcu_sched |
|
4113308 |
|
|
|
target: wakeuptime |
|
ffffffff8108109e signal_wake_up_state |
|
ffffffff810811e6 complete_signal |
|
ffffffff8108186b __send_signal |
|
ffffffff81081b0e send_signal |
|
ffffffff810824e3 do_send_sig_info |
|
ffffffff81082955 group_send_sig_info |
|
ffffffff810829b4 __kill_pgrp_info |
|
ffffffff81082a15 kill_pgrp |
|
ffffffff8149081f __isig |
|
ffffffff814912b4 isig |
|
ffffffff81491f7c n_tty_receive_signal_char |
|
ffffffff81493528 n_tty_receive_char_special |
|
ffffffff8149419f n_tty_receive_buf_common |
|
ffffffff81494424 n_tty_receive_buf2 |
|
ffffffff81496df5 flush_to_ldisc |
|
ffffffff8108c80a process_one_work |
|
ffffffff8108caeb worker_thread |
|
ffffffff81092979 kthread |
|
ffffffff8178940f ret_from_fork |
|
waker: kworker/u16:2 |
|
4125162 |
|
|
|
target: sshd |
|
ffffffff812037b6 pollwake |
|
ffffffff810b5462 __wake_up_common |
|
ffffffff810b58d5 __wake_up_sync_key |
|
ffffffff816707ba sock_def_readable |
|
ffffffff816d9f87 tcp_data_queue |
|
ffffffff816dd465 tcp_rcv_established |
|
ffffffff816e7ec5 tcp_v4_do_rcv |
|
ffffffff816e8ff7 tcp_v4_rcv |
|
ffffffff816c3a84 ip_local_deliver_finish |
|
ffffffff816c3d80 ip_local_deliver |
|
ffffffff816c3762 ip_rcv_finish |
|
ffffffff816c4062 ip_rcv |
|
ffffffff816885be __netif_receive_skb_core |
|
ffffffff81688928 __netif_receive_skb |
|
ffffffff81688993 netif_receive_skb_internal |
|
ffffffff816894c5 napi_gro_receive |
|
ffffffff81593111 xennet_poll |
|
ffffffff81688e0e net_rx_action |
|
ffffffff8107932b __do_softirq |
|
ffffffff810796b2 irq_exit |
|
waker: swapper/0 |
|
4515762 |
|
|
|
target: supervise |
|
ffffffff810df082 hrtimer_wakeup |
|
ffffffff810df494 __hrtimer_run_queues |
|
ffffffff810dfba8 hrtimer_interrupt |
|
ffffffff8100b9e1 xen_timer_interrupt |
|
ffffffff810cb9c8 handle_irq_event_percpu |
|
ffffffff810cf1ca handle_percpu_irq |
|
ffffffff810cb0c2 generic_handle_irq |
|
ffffffff814766f7 evtchn_2l_handle_events |
|
ffffffff81473e83 __xen_evtchn_do_upcall |
|
ffffffff81475cf0 xen_evtchn_do_upcall |
|
ffffffff8178adee xen_do_hypervisor_callback |
|
waker: swapper/0 |
|
25523344 |
|
|
|
Detaching... |
|
|
|
The second last stack trace shows sshd being woken up by packets being received. |
|
Near the bottom of the stack is driver processing, then IP, TCP, and finally |
|
socket processing as we work up the stack. The total time sshd (all sshd's) |
|
were blocked and woken up in this way was 4.5 seconds. |
|
|
|
Do be somewhat careful with overhead: this is tracing scheduler functions, which |
|
can be called very frequently. While this uses in-kernel summaries for |
|
efficiency, the rate of scheduler functions can be very high (> 1,000,000/sec), |
|
and this is performing stack walks when threads return to CPU. At some point |
|
the overhead will be measurable. |
|
|
|
|
|
A -p option can be used to filter (in-kernel) on a single process ID. For |
|
example, only matching PID 19169, which is a bash shell: |
|
|
|
# ./wakeuptime -p 19169 |
|
Tracing blocked time (us) by kernel stack... Hit Ctrl-C to end. |
|
^C |
|
target: bash |
|
ffffffff81075eb8 child_wait_callback |
|
ffffffff810b5462 __wake_up_common |
|
ffffffff810b58d5 __wake_up_sync_key |
|
ffffffff81078046 __wake_up_parent |
|
ffffffff810831b3 do_notify_parent |
|
ffffffff81077eaf do_exit |
|
ffffffff81077f93 do_group_exit |
|
ffffffff81078014 sys_exit_group |
|
ffffffff81789076 entry_SYSCALL_64_fastpath |
|
waker: ls |
|
2015 |
|
|
|
target: bash |
|
ffffffff81075eb8 child_wait_callback |
|
ffffffff810b5462 __wake_up_common |
|
ffffffff810b58d5 __wake_up_sync_key |
|
ffffffff81078046 __wake_up_parent |
|
ffffffff810831b3 do_notify_parent |
|
ffffffff81077eaf do_exit |
|
ffffffff81077f93 do_group_exit |
|
ffffffff81078014 sys_exit_group |
|
ffffffff81789076 entry_SYSCALL_64_fastpath |
|
waker: sleep |
|
1001347 |
|
|
|
target: bash |
|
ffffffff810b5921 woken_wake_function |
|
ffffffff810b5462 __wake_up_common |
|
ffffffff810b54d9 __wake_up |
|
ffffffff814939fd n_tty_receive_buf_common |
|
ffffffff81494424 n_tty_receive_buf2 |
|
ffffffff81496df5 flush_to_ldisc |
|
ffffffff8108c80a process_one_work |
|
ffffffff8108caeb worker_thread |
|
ffffffff81092979 kthread |
|
ffffffff8178940f ret_from_fork |
|
waker: kworker/u16:0 |
|
1871024 |
|
|
|
target: bash |
|
ffffffff810b5921 woken_wake_function |
|
ffffffff810b5462 __wake_up_common |
|
ffffffff810b54d9 __wake_up |
|
ffffffff814939fd n_tty_receive_buf_common |
|
ffffffff81494424 n_tty_receive_buf2 |
|
ffffffff81496df5 flush_to_ldisc |
|
ffffffff8108c80a process_one_work |
|
ffffffff8108caeb worker_thread |
|
ffffffff81092979 kthread |
|
ffffffff8178940f ret_from_fork |
|
waker: kworker/u16:2 |
|
3019839 |
|
|
|
Detaching... |
|
|
|
These stack traces are fascinating! The first two shows bash waiting on child |
|
processes, an "ls" and a "sleep". The sleep stack was responsible for 1.0 |
|
seconds of blocked time: I'd run a "sleep 1". |
|
|
|
The last two stacks show bash waking up to service tty input (keystrokes). |
|
|
|
|
|
A duration can be added, for example, tracing PID 19097 (sshd) for 5 seconds |
|
only: |
|
|
|
# ./wakeuptime -p 19097 5 |
|
Tracing blocked time (us) by kernel stack for 5 secs. |
|
|
|
target: sshd |
|
ffffffff812037b6 pollwake |
|
ffffffff810b5462 __wake_up_common |
|
ffffffff810b54d9 __wake_up |
|
ffffffff814939fd n_tty_receive_buf_common |
|
ffffffff81494424 n_tty_receive_buf2 |
|
ffffffff81496df5 flush_to_ldisc |
|
ffffffff8108c80a process_one_work |
|
ffffffff8108caeb worker_thread |
|
ffffffff81092979 kthread |
|
ffffffff8178940f ret_from_fork |
|
waker: kworker/u16:1 |
|
785 |
|
|
|
target: sshd |
|
ffffffff812037b6 pollwake |
|
ffffffff810b5462 __wake_up_common |
|
ffffffff810b54d9 __wake_up |
|
ffffffff814939fd n_tty_receive_buf_common |
|
ffffffff81494424 n_tty_receive_buf2 |
|
ffffffff81496df5 flush_to_ldisc |
|
ffffffff8108c80a process_one_work |
|
ffffffff8108caeb worker_thread |
|
ffffffff81092979 kthread |
|
ffffffff8178940f ret_from_fork |
|
waker: kworker/u16:2 |
|
2843 |
|
|
|
target: sshd |
|
ffffffff812037b6 pollwake |
|
ffffffff810b5462 __wake_up_common |
|
ffffffff810b58d5 __wake_up_sync_key |
|
ffffffff816707ba sock_def_readable |
|
ffffffff816d9f87 tcp_data_queue |
|
ffffffff816dd465 tcp_rcv_established |
|
ffffffff816e7ec5 tcp_v4_do_rcv |
|
ffffffff816e8ff7 tcp_v4_rcv |
|
ffffffff816c3a84 ip_local_deliver_finish |
|
ffffffff816c3d80 ip_local_deliver |
|
ffffffff816c3762 ip_rcv_finish |
|
ffffffff816c4062 ip_rcv |
|
ffffffff816884be __netif_receive_skb_core |
|
ffffffff81688928 __netif_receive_skb |
|
ffffffff81688993 netif_receive_skb_internal |
|
ffffffff816894c5 napi_gro_receive |
|
ffffffff81593111 xennet_poll |
|
ffffffff81688e0e net_rx_action |
|
ffffffff8107932b __do_softirq |
|
ffffffff810796b2 irq_exit |
|
waker: swapper/0 |
|
276103 |
|
|
|
Detaching... |
|
|
|
|
|
A -f option will emit output using the "folded stacks" format, which can be |
|
read directly by flamegraph.pl from the FlameGraph open source software |
|
(https://github.com/brendangregg/FlameGraph). Eg: |
|
|
|
# ./wakeuptime -f 5 |
|
run;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 |
|
run;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 |
|
chmod;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 |
|
supervise;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 |
|
run;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 |
|
run;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 |
|
mkdir;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 |
|
mkdir;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 |
|
run;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 |
|
supervise;entry_SYSCALL_64_fastpath;sys_clone;_do_fork;copy_process;call_rwsem_wake;rwsem_wake;__rwsem_do_wake;supervise 5 |
|
rcuos/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 |
|
swapper/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 |
|
swapper/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 |
|
rcuos/6;ret_from_fork;kthread;rcu_nocb_kthread;rcu_gp_kthread_wake;__wake_up;__wake_up_common;autoremove_wake_function;rcu_sched 19 |
|
run;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 |
|
bash;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 |
|
swapper/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 |
|
pickup;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 |
|
swapper/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 |
|
chown;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 |
|
supervise;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 |
|
supervise;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 |
|
chown;xen_do_hypervisor_callback;xen_evtchn_do_upcall;irq_exit;__do_softirq;run_timer_softirq;call_timer_fn;process_timeout;rcu_sched 3985 |
|
supervise;xen_do_hypervisor_callback;xen_evtchn_do_upcall;irq_exit;__do_softirq;run_timer_softirq;call_timer_fn;process_timeout;rcu_sched 3997 |
|
supervise;__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 |
|
chmod;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 |
|
swapper/4;xen_do_hypervisor_callback;xen_evtchn_do_upcall;irq_exit;__do_softirq;run_timer_softirq;call_timer_fn;process_timeout;rcu_sched 7971 |
|
readproctitle;__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 |
|
swapper/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 |
|
run;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 |
|
swapper/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 |
|
run;xen_do_hypervisor_callback;xen_evtchn_do_upcall;irq_exit;__do_softirq;run_timer_softirq;call_timer_fn;process_timeout;rcu_sched 19916 |
|
swapper/1;xen_do_hypervisor_callback;xen_evtchn_do_upcall;irq_exit;__do_softirq;run_timer_softirq;call_timer_fn;process_timeout;rcu_sched 31877 |
|
mkdir;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 |
|
swapper/5;xen_do_hypervisor_callback;xen_evtchn_do_upcall;irq_exit;__do_softirq;run_timer_softirq;call_timer_fn;process_timeout;rcu_sched 39837 |
|
chown;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 |
|
chmod;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 |
|
swapper/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 |
|
bash;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 |
|
vmstat;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 |
|
swapper/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 |
|
kworker/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 |
|
swapper/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 |
|
sshd;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 |
|
bash;return_from_execve;sys_execve;do_execveat_common.isra.33;sched_exec;stop_one_cpu;cpu_stop_queue_work;migration/7 942685 |
|
swapper/0;xen_do_hypervisor_callback;xen_evtchn_do_upcall;irq_exit;__do_softirq;run_timer_softirq;call_timer_fn;process_timeout;rcu_sched 969059 |
|
swapper/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 |
|
swapper/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 |
|
sleep;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 |
|
swapper/3;xen_do_hypervisor_callback;xen_evtchn_do_upcall;irq_exit;__do_softirq;run_timer_softirq;call_timer_fn;process_timeout;rcu_sched 1016980 |
|
mkdir;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 |
|
chown;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 |
|
swapper/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 |
|
swapper/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 |
|
run;return_from_execve;sys_execve;do_execveat_common.isra.33;sched_exec;stop_one_cpu;cpu_stop_queue_work;migration/6 1030506 |
|
run;return_from_execve;sys_execve;do_execveat_common.isra.33;sched_exec;stop_one_cpu;cpu_stop_queue_work;migration/4 1032424 |
|
swapper/6;xen_do_hypervisor_callback;xen_evtchn_do_upcall;irq_exit;__do_softirq;run_timer_softirq;call_timer_fn;process_timeout;rcu_sched 1036908 |
|
run;return_from_execve;sys_execve;do_execveat_common.isra.33;sched_exec;stop_one_cpu;cpu_stop_queue_work;migration/1 1040207 |
|
run;return_from_execve;sys_execve;do_execveat_common.isra.33;sched_exec;stop_one_cpu;cpu_stop_queue_work;migration/5 1044756 |
|
run;return_from_execve;sys_execve;do_execveat_common.isra.33;sched_exec;stop_one_cpu;cpu_stop_queue_work;migration/3 1044986 |
|
run;return_from_execve;sys_execve;do_execveat_common.isra.33;sched_exec;stop_one_cpu;cpu_stop_queue_work;migration/2 1046347 |
|
supervise;return_from_execve;sys_execve;do_execveat_common.isra.33;sched_exec;stop_one_cpu;cpu_stop_queue_work;migration/7 1093598 |
|
swapper/7;xen_do_hypervisor_callback;xen_evtchn_do_upcall;irq_exit;__do_softirq;run_timer_softirq;call_timer_fn;process_timeout;rcu_sched 1858510 |
|
supervise;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 |
|
swapper/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 |
|
swapper/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 |
|
swapper/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 |
|
supervise;return_from_execve;sys_execve;do_execveat_common.isra.33;sched_exec;stop_one_cpu;cpu_stop_queue_work;migration/6 2042698 |
|
supervise;return_from_execve;sys_execve;do_execveat_common.isra.33;sched_exec;stop_one_cpu;cpu_stop_queue_work;migration/0 2044085 |
|
run;return_from_execve;sys_execve;do_execveat_common.isra.33;sched_exec;stop_one_cpu;cpu_stop_queue_work;migration/0 2047386 |
|
run;return_from_execve;sys_execve;do_execveat_common.isra.33;sched_exec;stop_one_cpu;cpu_stop_queue_work;migration/7 2065637 |
|
swapper/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 |
|
swapper/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 |
|
swapper/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 |
|
supervise;return_from_execve;sys_execve;do_execveat_common.isra.33;sched_exec;stop_one_cpu;cpu_stop_queue_work;migration/5 3050881 |
|
supervise;return_from_execve;sys_execve;do_execveat_common.isra.33;sched_exec;stop_one_cpu;cpu_stop_queue_work;migration/1 3051454 |
|
supervise;return_from_execve;sys_execve;do_execveat_common.isra.33;sched_exec;stop_one_cpu;cpu_stop_queue_work;migration/3 3054844 |
|
supervise;return_from_execve;sys_execve;do_execveat_common.isra.33;sched_exec;stop_one_cpu;cpu_stop_queue_work;migration/2 3059548 |
|
supervise;return_from_execve;sys_execve;do_execveat_common.isra.33;sched_exec;stop_one_cpu;cpu_stop_queue_work;migration/4 3061480 |
|
swapper/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 |
|
swapper/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 |
|
swapper/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 |
|
swapper/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 |
|
swapper/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 |
|
swapper/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 |
|
swapper/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 |
|
swapper/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 |
|
swapper/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 |
|
swapper/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 |
|
swapper/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 |
|
swapper/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 |
|
chmod;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 |
|
run;entry_SYSCALL_64_fastpath;sys_write;vfs_write;__vfs_write;pipe_write;__wake_up_sync_key;__wake_up_common;autoremove_wake_function;readproctitle 4096457 |
|
rcuos/4;ret_from_fork;kthread;rcu_nocb_kthread;__wake_up;__wake_up_common;autoremove_wake_function;rcuos/5 4973072 |
|
rcuos/0;ddebug_tables;ret_from_fork;kthread;rcu_nocb_kthread;__wake_up;__wake_up_common;autoremove_wake_function;rcuos/1 4973898 |
|
rcu_sched;ddebug_tables;ret_from_fork;kthread;rcu_gp_kthread;__wake_up;__wake_up_common;autoremove_wake_function;rcuos/0 4976731 |
|
rcu_sched;ddebug_tables;ret_from_fork;kthread;rcu_gp_kthread;__wake_up;__wake_up_common;autoremove_wake_function;rcuos/4 4976755 |
|
rcuos/2;ret_from_fork;kthread;rcu_nocb_kthread;__wake_up;__wake_up_common;autoremove_wake_function;rcuos/3 4980207 |
|
rcu_sched;ddebug_tables;ret_from_fork;kthread;rcu_gp_kthread;__wake_up;__wake_up_common;autoremove_wake_function;rcuos/2 4980502 |
|
rcuos/6;ret_from_fork;kthread;rcu_nocb_kthread;__wake_up;__wake_up_common;autoremove_wake_function;rcuos/7 4981025 |
|
rcu_sched;ddebug_tables;ret_from_fork;kthread;rcu_gp_kthread;__wake_up;__wake_up_common;autoremove_wake_function;rcuos/6 4983110 |
|
kworker/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 |
|
swapper/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 |
|
run;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 |
|
swapper/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 |
|
|
|
The stack traces are shown as single lines, with functions separated by |
|
semicolons. The first entry is the waker task name, followed by the waker stack, |
|
and then last entry is the target task name. As a flame graph, this puts the |
|
waker name on the bottom, followed by the waker stack, and then the target |
|
task name on top. The 2nd column is the total blocked time. |
|
|
|
I'd save this output to a file, then move it to the system where you'll be |
|
creating your "wakeup time flame graphs". |
|
|
|
|
|
USAGE message: |
|
|
|
# ./wakeuptime -h |
|
usage: wakeuptime [-h] [-u] [-p PID] [-v] [-f] |
|
[--stack-storage-size STACK_STORAGE_SIZE] |
|
[-m MIN_BLOCK_TIME] [-M MAX_BLOCK_TIME] |
|
[duration] |
|
|
|
Summarize sleep to wakeup time by waker kernel stack |
|
|
|
positional arguments: |
|
duration duration of trace, in seconds |
|
|
|
optional arguments: |
|
-h, --help show this help message and exit |
|
-u, --useronly user threads only (no kernel threads) |
|
-p PID, --pid PID trace this PID only |
|
-v, --verbose show raw addresses |
|
-f, --folded output folded format |
|
--stack-storage-size STACK_STORAGE_SIZE |
|
the number of unique stack traces that can be stored |
|
and displayed (default 1024) |
|
-m MIN_BLOCK_TIME, --min-block-time MIN_BLOCK_TIME |
|
the amount of time in microseconds over which we store |
|
traces (default 1) |
|
-M MAX_BLOCK_TIME, --max-block-time MAX_BLOCK_TIME |
|
the amount of time in microseconds under which we |
|
store traces (default U64_MAX) |
|
examples: |
|
./wakeuptime # trace blocked time with waker stacks |
|
./wakeuptime 5 # trace for 5 seconds only |
|
./wakeuptime -f 5 # 5 seconds, and output in folded format |
|
./wakeuptime -u # don't include kernel threads (user only) |
|
./wakeuptime -p 185 # trace for PID 185 only
|
|
|