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