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