FM / doc

/usr/share/doc/bpfcc-tools/examples/doc/

/usr/share/doc/bpfcc-tools/examples/doc

Name	Size	Mode	Actions
lib/	-	0755	rm
argdist_example.txt	23029	0644	edit dl rm
bashreadline_example.txt	882	0644	edit dl rm
bindsnoop_example.txt	4530	0644	edit dl rm
biolatency_example.txt	24021	0644	edit dl rm
biolatpcts_example.txt	3040	0644	edit dl rm
biopattern_example.txt	1406	0644	edit dl rm
biosnoop_example.txt	3549	0644	edit dl rm
biotop_example.txt	9326	0644	edit dl rm
bitesize_example.txt	5100	0644	edit dl rm
bpflist_example.txt	2179	0644	edit dl rm
btrfsdist_example.txt	9545	0644	edit dl rm
btrfsslower_example.txt	6812	0644	edit dl rm
cachestat_example.txt	4012	0644	edit dl rm
cachetop_example.txt	3918	0644	edit dl rm
capable_example.txt	6655	0644	edit dl rm
cobjnew_example.txt	3044	0644	edit dl rm
compactsnoop_example.txt	10160	0644	edit dl rm
cpudist_example.txt	16876	0644	edit dl rm
cpuunclaimed_example.txt	15568	0644	edit dl rm
criticalstat_example.txt	4926	0644	edit dl rm
cthreads_example.txt	2132	0644	edit dl rm
dbslower_example.txt	3981	0644	edit dl rm
dbstat_example.txt	6656	0644	edit dl rm
dcsnoop_example.txt	4371	0644	edit dl rm
dcstat_example.txt	3343	0644	edit dl rm
deadlock_example.txt	16643	0644	edit dl rm
dirtop_example.txt	5097	0644	edit dl rm
drsnoop_example.txt	5120	0644	edit dl rm
execsnoop_example.txt	6795	0644	edit dl rm
exitsnoop_example.txt	6373	0644	edit dl rm
ext4dist_example.txt	8991	0644	edit dl rm
ext4slower_example.txt	11335	0644	edit dl rm
filegone_example.txt	743	0644	edit dl rm
filelife_example.txt	2092	0644	edit dl rm
fileslower_example.txt	5711	0644	edit dl rm
filetop_example.txt	6968	0644	edit dl rm
funccount_example.txt	13605	0644	edit dl rm
funcinterval_example.txt	15646	0644	edit dl rm
funclatency_example.txt	21485	0644	edit dl rm
funcslower_example.txt	6786	0644	edit dl rm
gethostlatency_example.txt	1317	0644	edit dl rm
hardirqs_example.txt	37936	0644	edit dl rm
inject_example.txt	6832	0644	edit dl rm
javacalls_example.txt	4000	0644	edit dl rm
javaflow_example.txt	6017	0644	edit dl rm
javagc_example.txt	3867	0644	edit dl rm
javaobjnew_example.txt	3044	0644	edit dl rm
javastat_example.txt	3052	0644	edit dl rm
javathreads_example.txt	2132	0644	edit dl rm
killsnoop_example.txt	1339	0644	edit dl rm
klockstat_example.txt	8536	0644	edit dl rm
kvmexit_example.txt	11909	0644	edit dl rm
llcstat_example.txt	3315	0644	edit dl rm
mdflush_example.txt	1780	0644	edit dl rm
memleak_example.txt	10263	0644	edit dl rm
mountsnoop_example.txt	1481	0644	edit dl rm
mysqld_qslower_example.txt	2351	0644	edit dl rm
netqtop_example.txt	12497	0644	edit dl rm
nfsdist_example.txt	8508	0644	edit dl rm
nfsslower_example.txt	7867	0644	edit dl rm
nodegc_example.txt	3867	0644	edit dl rm
nodestat_example.txt	3052	0644	edit dl rm
offcputime_example.txt	19662	0644	edit dl rm
offwaketime_example.txt	38258	0644	edit dl rm
oomkill_example.txt	1925	0644	edit dl rm
opensnoop_example.txt	10573	0644	edit dl rm
perlcalls_example.txt	4000	0644	edit dl rm
perlflow_example.txt	6017	0644	edit dl rm
perlstat_example.txt	3052	0644	edit dl rm
phpcalls_example.txt	4000	0644	edit dl rm
phpflow_example.txt	6017	0644	edit dl rm
phpstat_example.txt	3052	0644	edit dl rm
pidpersec_example.txt	677	0644	edit dl rm
ppchcalls_example.txt	7097	0644	edit dl rm
profile_example.txt	31826	0644	edit dl rm
pythoncalls_example.txt	4000	0644	edit dl rm
pythonflow_example.txt	6017	0644	edit dl rm
pythongc_example.txt	3867	0644	edit dl rm
pythonstat_example.txt	3052	0644	edit dl rm
rdmaucma_example.txt	1983	0644	edit dl rm
readahead_example.txt	3248	0644	edit dl rm
reset-trace_example.txt	9365	0644	edit dl rm
rubycalls_example.txt	4000	0644	edit dl rm
rubyflow_example.txt	6017	0644	edit dl rm
rubygc_example.txt	3867	0644	edit dl rm
rubyobjnew_example.txt	3044	0644	edit dl rm
rubystat_example.txt	3052	0644	edit dl rm
runqlat_example.txt	32051	0644	edit dl rm
runqlen_example.txt	12136	0644	edit dl rm
runqslower_example.txt	2184	0644	edit dl rm
shmsnoop_example.txt	2798	0644	edit dl rm
slabratetop_example.txt	5347	0644	edit dl rm
sofdsnoop_example.txt	3211	0644	edit dl rm
softirqs_example.txt	11286	0644	edit dl rm
solisten_example.txt	2355	0644	edit dl rm
sslsniff_example.txt	6902	0644	edit dl rm
stackcount_example.txt	21965	0644	edit dl rm
statsnoop_example.txt	3091	0644	edit dl rm
swapin.txt	2632	0644	edit dl rm
swapin_example.txt	1421	0644	edit dl rm
syncsnoop_example.txt	387	0644	edit dl rm
syscount_example.txt	6419	0644	edit dl rm
tclcalls_example.txt	4000	0644	edit dl rm
tclflow_example.txt	6017	0644	edit dl rm
tclobjnew_example.txt	3044	0644	edit dl rm
tclstat_example.txt	3052	0644	edit dl rm
tcpaccept_example.txt	2822	0644	edit dl rm
tcpcong_example.txt	34106	0644	edit dl rm
tcpconnect_example.txt	6420	0644	edit dl rm
tcpconnlat_example.txt	2616	0644	edit dl rm
tcpdrop_example.txt	2001	0644	edit dl rm
tcplife_example.txt	6995	0644	edit dl rm
tcpretrans_example.txt	3938	0644	edit dl rm
tcprtt_example.txt	10070	0644	edit dl rm
tcpstates_example.txt	2908	0644	edit dl rm
tcpsubnet_example.txt	5503	0644	edit dl rm
tcpsynbl_example.txt	1179	0644	edit dl rm
tcptop_example.txt	5890	0644	edit dl rm
tcptracer_example.txt	2029	0644	edit dl rm
threadsnoop_example.txt	1094	0644	edit dl rm
tplist_example.txt	4507	0644	edit dl rm
trace_example.txt	22136	0644	edit dl rm
ttysnoop_example.txt	3315	0644	edit dl rm
vfscount_example.txt	2221	0644	edit dl rm
vfsstat_example.txt	1696	0644	edit dl rm
virtiostat_example.txt	2678	0644	edit dl rm
wakeuptime_example.txt	34048	0644	edit dl rm
xfsdist_example.txt	6928	0644	edit dl rm
xfsslower_example.txt	7080	0644	edit dl rm
zfsdist_example.txt	9753	0644	edit dl rm
zfsslower_example.txt	7551	0644	edit dl rm

Edit: /usr/share/doc/bpfcc-tools/examples/doc/wakeuptime_example.txt (34048B)

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

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
    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 16384)
  -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

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 16384) -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