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