1 Demonstrations of wakeuptime, the Linux eBPF/bcc version. 2 3 4 This program measures when threads block, and shows the stack traces for the 5 threads that performed the wakeup, along with the process names of the waker 6 and target processes, and the total blocked time. This blocked time is measured 7 from when a thread blocks, to when the wakeup signal is sent. Note that this 8 time excludes some run queue latency from the target thread, which may not 9 immediately execute if it needs to wait its turn on-CPU. All the data shown, 10 stack traces, process names, and times, are summarized in-kernel using an eBPF 11 map for efficiency. 12 13 This tool is intended to be used after offcputime, which shows the directly 14 blocked stacks. wakeuptime can then be used to show the stacks that performed 15 the wakeups. 16 17 Here is some example (truncated) output. To explain what we are seeing: the 18 first stack trace shown is for a "vmstat" thread, which was woken up by 19 "swapper/1". The stack trace is for swapper/1, which shows a timer interrupt. 20 The total time is 4.0 seconds: this actually corresponds to a "vmstat 1" 21 printing 4 x 1 second summaries -- we're seeing the interrupt stack that 22 wakes up vmstat: 23 24 # ./wakeuptime 25 Tracing blocked time (us) by kernel stack... Hit Ctrl-C to end. 26 ^C 27 [...truncated...] 28 29 target: vmstat 30 ffffffff810df082 hrtimer_wakeup 31 ffffffff810df494 __hrtimer_run_queues 32 ffffffff810dfba8 hrtimer_interrupt 33 ffffffff8100b9e1 xen_timer_interrupt 34 ffffffff810cb9c8 handle_irq_event_percpu 35 ffffffff810cf1ca handle_percpu_irq 36 ffffffff810cb0c2 generic_handle_irq 37 ffffffff814766f7 evtchn_2l_handle_events 38 ffffffff81473e83 __xen_evtchn_do_upcall 39 ffffffff81475cf0 xen_evtchn_do_upcall 40 ffffffff8178adee xen_do_hypervisor_callback 41 waker: swapper/1 42 4000415 43 44 target: sshd 45 ffffffff812037b6 pollwake 46 ffffffff810b5462 __wake_up_common 47 ffffffff810b54d9 __wake_up 48 ffffffff814939fd n_tty_receive_buf_common 49 ffffffff81494424 n_tty_receive_buf2 50 ffffffff81496df5 flush_to_ldisc 51 ffffffff8108c80a process_one_work 52 ffffffff8108caeb worker_thread 53 ffffffff81092979 kthread 54 ffffffff8178940f ret_from_fork 55 waker: kworker/u16:2 56 4001028 57 58 target: rcuos/0 59 ffffffff810b5b12 autoremove_wake_function 60 ffffffff810b5462 __wake_up_common 61 ffffffff810b54d9 __wake_up 62 ffffffff810d8043 rcu_gp_kthread 63 ffffffff81092979 kthread 64 ffffffff8178940f ret_from_fork 65 ffffffff81ca9420 ddebug_tables 66 waker: rcu_sched 67 4009976 68 69 target: rcuos/7 70 ffffffff810b5b12 autoremove_wake_function 71 ffffffff810b5462 __wake_up_common 72 ffffffff810b54d9 __wake_up 73 ffffffff810d6f28 rcu_nocb_kthread 74 ffffffff81092979 kthread 75 ffffffff8178940f ret_from_fork 76 waker: rcuos/6 77 4095781 78 79 target: rcuos/6 80 ffffffff810b5b12 autoremove_wake_function 81 ffffffff810b5462 __wake_up_common 82 ffffffff810b54d9 __wake_up 83 ffffffff810d8043 rcu_gp_kthread 84 ffffffff81092979 kthread 85 ffffffff8178940f ret_from_fork 86 ffffffff81ca9420 ddebug_tables 87 waker: rcu_sched 88 4101075 89 90 target: rcuos/5 91 ffffffff810b5b12 autoremove_wake_function 92 ffffffff810b5462 __wake_up_common 93 ffffffff810b54d9 __wake_up 94 ffffffff810d6f28 rcu_nocb_kthread 95 ffffffff81092979 kthread 96 ffffffff8178940f ret_from_fork 97 waker: rcuos/4 98 4103492 99 100 target: rcuos/3 101 ffffffff810b5b12 autoremove_wake_function 102 ffffffff810b5462 __wake_up_common 103 ffffffff810b54d9 __wake_up 104 ffffffff810d6f28 rcu_nocb_kthread 105 ffffffff81092979 kthread 106 ffffffff8178940f ret_from_fork 107 waker: rcuos/2 108 4107785 109 110 target: rcuos/2 111 ffffffff810b5b12 autoremove_wake_function 112 ffffffff810b5462 __wake_up_common 113 ffffffff810b54d9 __wake_up 114 ffffffff810d8043 rcu_gp_kthread 115 ffffffff81092979 kthread 116 ffffffff8178940f ret_from_fork 117 ffffffff81ca9420 ddebug_tables 118 waker: rcu_sched 119 4113308 120 121 target: wakeuptime 122 ffffffff8108109e signal_wake_up_state 123 ffffffff810811e6 complete_signal 124 ffffffff8108186b __send_signal 125 ffffffff81081b0e send_signal 126 ffffffff810824e3 do_send_sig_info 127 ffffffff81082955 group_send_sig_info 128 ffffffff810829b4 __kill_pgrp_info 129 ffffffff81082a15 kill_pgrp 130 ffffffff8149081f __isig 131 ffffffff814912b4 isig 132 ffffffff81491f7c n_tty_receive_signal_char 133 ffffffff81493528 n_tty_receive_char_special 134 ffffffff8149419f n_tty_receive_buf_common 135 ffffffff81494424 n_tty_receive_buf2 136 ffffffff81496df5 flush_to_ldisc 137 ffffffff8108c80a process_one_work 138 ffffffff8108caeb worker_thread 139 ffffffff81092979 kthread 140 ffffffff8178940f ret_from_fork 141 waker: kworker/u16:2 142 4125162 143 144 target: sshd 145 ffffffff812037b6 pollwake 146 ffffffff810b5462 __wake_up_common 147 ffffffff810b58d5 __wake_up_sync_key 148 ffffffff816707ba sock_def_readable 149 ffffffff816d9f87 tcp_data_queue 150 ffffffff816dd465 tcp_rcv_established 151 ffffffff816e7ec5 tcp_v4_do_rcv 152 ffffffff816e8ff7 tcp_v4_rcv 153 ffffffff816c3a84 ip_local_deliver_finish 154 ffffffff816c3d80 ip_local_deliver 155 ffffffff816c3762 ip_rcv_finish 156 ffffffff816c4062 ip_rcv 157 ffffffff816885be __netif_receive_skb_core 158 ffffffff81688928 __netif_receive_skb 159 ffffffff81688993 netif_receive_skb_internal 160 ffffffff816894c5 napi_gro_receive 161 ffffffff81593111 xennet_poll 162 ffffffff81688e0e net_rx_action 163 ffffffff8107932b __do_softirq 164 ffffffff810796b2 irq_exit 165 waker: swapper/0 166 4515762 167 168 target: supervise 169 ffffffff810df082 hrtimer_wakeup 170 ffffffff810df494 __hrtimer_run_queues 171 ffffffff810dfba8 hrtimer_interrupt 172 ffffffff8100b9e1 xen_timer_interrupt 173 ffffffff810cb9c8 handle_irq_event_percpu 174 ffffffff810cf1ca handle_percpu_irq 175 ffffffff810cb0c2 generic_handle_irq 176 ffffffff814766f7 evtchn_2l_handle_events 177 ffffffff81473e83 __xen_evtchn_do_upcall 178 ffffffff81475cf0 xen_evtchn_do_upcall 179 ffffffff8178adee xen_do_hypervisor_callback 180 waker: swapper/0 181 25523344 182 183 Detaching... 184 185 The second last stack trace shows sshd being woken up by packets being received. 186 Near the bottom of the stack is driver processing, then IP, TCP, and finally 187 socket processing as we work up the stack. The total time sshd (all sshd's) 188 were blocked and woken up in this way was 4.5 seconds. 189 190 Do be somewhat careful with overhead: this is tracing scheduler functions, which 191 can be called very frequently. While this uses in-kernel summaries for 192 efficiency, the rate of scheduler functions can be very high (> 1,000,000/sec), 193 and this is performing stack walks when threads return to CPU. At some point 194 the overhead will be measurable. 195 196 197 A -p option can be used to filter (in-kernel) on a single process ID. For 198 example, only matching PID 19169, which is a bash shell: 199 200 # ./wakeuptime -p 19169 201 Tracing blocked time (us) by kernel stack... Hit Ctrl-C to end. 202 ^C 203 target: bash 204 ffffffff81075eb8 child_wait_callback 205 ffffffff810b5462 __wake_up_common 206 ffffffff810b58d5 __wake_up_sync_key 207 ffffffff81078046 __wake_up_parent 208 ffffffff810831b3 do_notify_parent 209 ffffffff81077eaf do_exit 210 ffffffff81077f93 do_group_exit 211 ffffffff81078014 sys_exit_group 212 ffffffff81789076 entry_SYSCALL_64_fastpath 213 waker: ls 214 2015 215 216 target: bash 217 ffffffff81075eb8 child_wait_callback 218 ffffffff810b5462 __wake_up_common 219 ffffffff810b58d5 __wake_up_sync_key 220 ffffffff81078046 __wake_up_parent 221 ffffffff810831b3 do_notify_parent 222 ffffffff81077eaf do_exit 223 ffffffff81077f93 do_group_exit 224 ffffffff81078014 sys_exit_group 225 ffffffff81789076 entry_SYSCALL_64_fastpath 226 waker: sleep 227 1001347 228 229 target: bash 230 ffffffff810b5921 woken_wake_function 231 ffffffff810b5462 __wake_up_common 232 ffffffff810b54d9 __wake_up 233 ffffffff814939fd n_tty_receive_buf_common 234 ffffffff81494424 n_tty_receive_buf2 235 ffffffff81496df5 flush_to_ldisc 236 ffffffff8108c80a process_one_work 237 ffffffff8108caeb worker_thread 238 ffffffff81092979 kthread 239 ffffffff8178940f ret_from_fork 240 waker: kworker/u16:0 241 1871024 242 243 target: bash 244 ffffffff810b5921 woken_wake_function 245 ffffffff810b5462 __wake_up_common 246 ffffffff810b54d9 __wake_up 247 ffffffff814939fd n_tty_receive_buf_common 248 ffffffff81494424 n_tty_receive_buf2 249 ffffffff81496df5 flush_to_ldisc 250 ffffffff8108c80a process_one_work 251 ffffffff8108caeb worker_thread 252 ffffffff81092979 kthread 253 ffffffff8178940f ret_from_fork 254 waker: kworker/u16:2 255 3019839 256 257 Detaching... 258 259 These stack traces are fascinating! The first two shows bash waiting on child 260 processes, an "ls" and a "sleep". The sleep stack was responsible for 1.0 261 seconds of blocked time: I'd run a "sleep 1". 262 263 The last two stacks show bash waking up to service tty input (keystrokes). 264 265 266 A duration can be added, for example, tracing PID 19097 (sshd) for 5 seconds 267 only: 268 269 # ./wakeuptime -p 19097 5 270 Tracing blocked time (us) by kernel stack for 5 secs. 271 272 target: sshd 273 ffffffff812037b6 pollwake 274 ffffffff810b5462 __wake_up_common 275 ffffffff810b54d9 __wake_up 276 ffffffff814939fd n_tty_receive_buf_common 277 ffffffff81494424 n_tty_receive_buf2 278 ffffffff81496df5 flush_to_ldisc 279 ffffffff8108c80a process_one_work 280 ffffffff8108caeb worker_thread 281 ffffffff81092979 kthread 282 ffffffff8178940f ret_from_fork 283 waker: kworker/u16:1 284 785 285 286 target: sshd 287 ffffffff812037b6 pollwake 288 ffffffff810b5462 __wake_up_common 289 ffffffff810b54d9 __wake_up 290 ffffffff814939fd n_tty_receive_buf_common 291 ffffffff81494424 n_tty_receive_buf2 292 ffffffff81496df5 flush_to_ldisc 293 ffffffff8108c80a process_one_work 294 ffffffff8108caeb worker_thread 295 ffffffff81092979 kthread 296 ffffffff8178940f ret_from_fork 297 waker: kworker/u16:2 298 2843 299 300 target: sshd 301 ffffffff812037b6 pollwake 302 ffffffff810b5462 __wake_up_common 303 ffffffff810b58d5 __wake_up_sync_key 304 ffffffff816707ba sock_def_readable 305 ffffffff816d9f87 tcp_data_queue 306 ffffffff816dd465 tcp_rcv_established 307 ffffffff816e7ec5 tcp_v4_do_rcv 308 ffffffff816e8ff7 tcp_v4_rcv 309 ffffffff816c3a84 ip_local_deliver_finish 310 ffffffff816c3d80 ip_local_deliver 311 ffffffff816c3762 ip_rcv_finish 312 ffffffff816c4062 ip_rcv 313 ffffffff816884be __netif_receive_skb_core 314 ffffffff81688928 __netif_receive_skb 315 ffffffff81688993 netif_receive_skb_internal 316 ffffffff816894c5 napi_gro_receive 317 ffffffff81593111 xennet_poll 318 ffffffff81688e0e net_rx_action 319 ffffffff8107932b __do_softirq 320 ffffffff810796b2 irq_exit 321 waker: swapper/0 322 276103 323 324 Detaching... 325 326 327 A -f option will emit output using the "folded stacks" format, which can be 328 read directly by flamegraph.pl from the FlameGraph open source software 329 (https://github.com/brendangregg/FlameGraph). Eg: 330 331 # ./wakeuptime -f 5 332 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 333 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 334 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 335 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 336 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 337 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 338 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 339 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 340 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 341 supervise;entry_SYSCALL_64_fastpath;sys_clone;_do_fork;copy_process;call_rwsem_wake;rwsem_wake;__rwsem_do_wake;supervise 5 342 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 343 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 344 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 345 rcuos/6;ret_from_fork;kthread;rcu_nocb_kthread;rcu_gp_kthread_wake;__wake_up;__wake_up_common;autoremove_wake_function;rcu_sched 19 346 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 347 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 348 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 349 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 350 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 351 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 352 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 353 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 354 chown;xen_do_hypervisor_callback;xen_evtchn_do_upcall;irq_exit;__do_softirq;run_timer_softirq;call_timer_fn;process_timeout;rcu_sched 3985 355 supervise;xen_do_hypervisor_callback;xen_evtchn_do_upcall;irq_exit;__do_softirq;run_timer_softirq;call_timer_fn;process_timeout;rcu_sched 3997 356 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 357 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 358 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 359 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 360 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 361 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 362 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 363 run;xen_do_hypervisor_callback;xen_evtchn_do_upcall;irq_exit;__do_softirq;run_timer_softirq;call_timer_fn;process_timeout;rcu_sched 19916 364 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 365 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 366 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 367 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 368 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 369 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 370 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 371 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 372 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 373 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 374 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 375 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 376 bash;return_from_execve;sys_execve;do_execveat_common.isra.33;sched_exec;stop_one_cpu;cpu_stop_queue_work;migration/7 942685 377 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 378 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 379 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 380 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 381 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 382 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 383 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 384 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 385 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 386 run;return_from_execve;sys_execve;do_execveat_common.isra.33;sched_exec;stop_one_cpu;cpu_stop_queue_work;migration/6 1030506 387 run;return_from_execve;sys_execve;do_execveat_common.isra.33;sched_exec;stop_one_cpu;cpu_stop_queue_work;migration/4 1032424 388 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 389 run;return_from_execve;sys_execve;do_execveat_common.isra.33;sched_exec;stop_one_cpu;cpu_stop_queue_work;migration/1 1040207 390 run;return_from_execve;sys_execve;do_execveat_common.isra.33;sched_exec;stop_one_cpu;cpu_stop_queue_work;migration/5 1044756 391 run;return_from_execve;sys_execve;do_execveat_common.isra.33;sched_exec;stop_one_cpu;cpu_stop_queue_work;migration/3 1044986 392 run;return_from_execve;sys_execve;do_execveat_common.isra.33;sched_exec;stop_one_cpu;cpu_stop_queue_work;migration/2 1046347 393 supervise;return_from_execve;sys_execve;do_execveat_common.isra.33;sched_exec;stop_one_cpu;cpu_stop_queue_work;migration/7 1093598 394 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 395 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 396 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 397 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 398 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 399 supervise;return_from_execve;sys_execve;do_execveat_common.isra.33;sched_exec;stop_one_cpu;cpu_stop_queue_work;migration/6 2042698 400 supervise;return_from_execve;sys_execve;do_execveat_common.isra.33;sched_exec;stop_one_cpu;cpu_stop_queue_work;migration/0 2044085 401 run;return_from_execve;sys_execve;do_execveat_common.isra.33;sched_exec;stop_one_cpu;cpu_stop_queue_work;migration/0 2047386 402 run;return_from_execve;sys_execve;do_execveat_common.isra.33;sched_exec;stop_one_cpu;cpu_stop_queue_work;migration/7 2065637 403 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 404 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 405 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 406 supervise;return_from_execve;sys_execve;do_execveat_common.isra.33;sched_exec;stop_one_cpu;cpu_stop_queue_work;migration/5 3050881 407 supervise;return_from_execve;sys_execve;do_execveat_common.isra.33;sched_exec;stop_one_cpu;cpu_stop_queue_work;migration/1 3051454 408 supervise;return_from_execve;sys_execve;do_execveat_common.isra.33;sched_exec;stop_one_cpu;cpu_stop_queue_work;migration/3 3054844 409 supervise;return_from_execve;sys_execve;do_execveat_common.isra.33;sched_exec;stop_one_cpu;cpu_stop_queue_work;migration/2 3059548 410 supervise;return_from_execve;sys_execve;do_execveat_common.isra.33;sched_exec;stop_one_cpu;cpu_stop_queue_work;migration/4 3061480 411 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 412 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 413 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 414 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 415 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 416 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 417 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 418 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 419 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 420 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 421 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 422 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 423 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 424 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 425 rcuos/4;ret_from_fork;kthread;rcu_nocb_kthread;__wake_up;__wake_up_common;autoremove_wake_function;rcuos/5 4973072 426 rcuos/0;ddebug_tables;ret_from_fork;kthread;rcu_nocb_kthread;__wake_up;__wake_up_common;autoremove_wake_function;rcuos/1 4973898 427 rcu_sched;ddebug_tables;ret_from_fork;kthread;rcu_gp_kthread;__wake_up;__wake_up_common;autoremove_wake_function;rcuos/0 4976731 428 rcu_sched;ddebug_tables;ret_from_fork;kthread;rcu_gp_kthread;__wake_up;__wake_up_common;autoremove_wake_function;rcuos/4 4976755 429 rcuos/2;ret_from_fork;kthread;rcu_nocb_kthread;__wake_up;__wake_up_common;autoremove_wake_function;rcuos/3 4980207 430 rcu_sched;ddebug_tables;ret_from_fork;kthread;rcu_gp_kthread;__wake_up;__wake_up_common;autoremove_wake_function;rcuos/2 4980502 431 rcuos/6;ret_from_fork;kthread;rcu_nocb_kthread;__wake_up;__wake_up_common;autoremove_wake_function;rcuos/7 4981025 432 rcu_sched;ddebug_tables;ret_from_fork;kthread;rcu_gp_kthread;__wake_up;__wake_up_common;autoremove_wake_function;rcuos/6 4983110 433 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 434 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 435 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 436 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 437 438 The stack traces are shown as single lines, with functions separated by 439 semicolons. The first entry is the waker task name, followed by the waker stack, 440 and then last entry is the target task name. As a flame graph, this puts the 441 waker name on the bottom, followed by the waker stack, and then the target 442 task name on top. The 2nd column is the total blocked time. 443 444 I'd save this output to a file, then move it to the system where you'll be 445 creating your "wakeup time flame graphs". 446 447 448 USAGE message: 449 450 # ./wakeuptime -h 451 usage: wakeuptime [-h] [-u] [-p PID] [-v] [-f] 452 [--stack-storage-size STACK_STORAGE_SIZE] 453 [-m MIN_BLOCK_TIME] [-M MAX_BLOCK_TIME] 454 [duration] 455 456 Summarize sleep to wakeup time by waker kernel stack 457 458 positional arguments: 459 duration duration of trace, in seconds 460 461 optional arguments: 462 -h, --help show this help message and exit 463 -u, --useronly user threads only (no kernel threads) 464 -p PID, --pid PID trace this PID only 465 -v, --verbose show raw addresses 466 -f, --folded output folded format 467 --stack-storage-size STACK_STORAGE_SIZE 468 the number of unique stack traces that can be stored 469 and displayed (default 1024) 470 -m MIN_BLOCK_TIME, --min-block-time MIN_BLOCK_TIME 471 the amount of time in microseconds over which we store 472 traces (default 1) 473 -M MAX_BLOCK_TIME, --max-block-time MAX_BLOCK_TIME 474 the amount of time in microseconds under which we 475 store traces (default U64_MAX) 476 examples: 477 ./wakeuptime # trace blocked time with waker stacks 478 ./wakeuptime 5 # trace for 5 seconds only 479 ./wakeuptime -f 5 # 5 seconds, and output in folded format 480 ./wakeuptime -u # don't include kernel threads (user only) 481 ./wakeuptime -p 185 # trace for PID 185 only 482
