diff --git a/README.md b/README.md index afbe8a6c1752..0eae60c0b325 100644 --- a/README.md +++ b/README.md @@ -65,23 +65,24 @@ Examples: Tools: -- tools/[biolatency](tools/biolatency): Summarize block device I/O latency as a histogram. [Examples](tools/biolatency_example.txt). -- tools/[biosnoop](tools/biosnoop): Trace block device I/O with PID and latency. [Examples](tools/biosnoop_example.txt). -- tools/[funccount](tools/funccount): Count kernel function calls. [Examples](tools/funccount_example.txt). -- tools/[funclatency](tools/funclatency): Time kernel functions and show their latency distribution. [Examples](tools/funclatency_example.txt). -- tools/[hardirqs](tools/hardirqs): Measure hard IRQ (hard interrupt) event time. [Examples](tools/hardirqs_example.txt). -- tools/[killsnoop](tools/killsnoop): Trace signals issued by the kill() syscall. [Examples](tools/killsnoop_example.txt). -- tools/[offcputime](tools/offcputime): Summarize off-CPU time by kernel stack trace. [Examples](tools/offcputime_example.txt). -- tools/[opensnoop](tools/opensnoop): Trace open() syscalls. [Examples](tools/opensnoop_example.txt). -- tools/[pidpersec](tools/pidpersec): Count new processes (via fork). [Examples](tools/pidpersec_example.txt). -- tools/[softirqs](tools/softirqs): Measure soft IRQ (soft interrupt) event time. [Examples](tools/softirqs_example.txt). -- tools/[stackcount](tools/stackcount): Count kernel function calls and their stack traces. [Examples](tools/stackcount_example.txt). -- tools/[stacksnoop](tools/stacksnoop): Trace a kernel function and print all kernel stack traces. [Examples](tools/stacksnoop_example.txt). -- tools/[syncsnoop](tools/syncsnoop): Trace sync() syscall. [Examples](tools/syncsnoop_example.txt). -- tools/[tcpaccept](tools/tcpaccept): Trace TCP passive connections (accept()). [Examples](tools/tcpaccept_example.txt). -- tools/[tcpconnect](tools/tcpconnect): Trace TCP active connections (connect()). [Examples](tools/tcpconnect_example.txt). -- tools/[vfscount](tools/vfscount) tools/[vfscount.c](tools/vfscount.c): Count VFS calls. [Examples](tools/vfscount_example.txt). -- tools/[vfsstat](tools/vfsstat) tools/[vfsstat.c](tools/vfsstat.c): Count some VFS calls, with column output. [Examples](tools/vfsstat_example.txt). +- tools/[biolatency](tools/biolatency.py): Summarize block device I/O latency as a histogram. [Examples](tools/biolatency_example.txt). +- tools/[biosnoop](tools/biosnoop.py): Trace block device I/O with PID and latency. [Examples](tools/biosnoop_example.txt). +- tools/[funccount](tools/funccount.py): Count kernel function calls. [Examples](tools/funccount_example.txt). +- tools/[funclatency](tools/funclatency.py): Time kernel functions and show their latency distribution. [Examples](tools/funclatency_example.txt). +- tools/[hardirqs](tools/hardirqs.py): Measure hard IRQ (hard interrupt) event time. [Examples](tools/hardirqs_example.txt). +- tools/[killsnoop](tools/killsnoop.py): Trace signals issued by the kill() syscall. [Examples](tools/killsnoop_example.txt). +- tools/[offcputime](tools/offcputime.py): Summarize off-CPU time by kernel stack trace. [Examples](tools/offcputime_example.txt). +- tools/[opensnoop](tools/opensnoop.py): Trace open() syscalls. [Examples](tools/opensnoop_example.txt). +- tools/[pidpersec](tools/pidpersec.py): Count new processes (via fork). [Examples](tools/pidpersec_example.txt). +- tools/[softirqs](tools/softirqs.py): Measure soft IRQ (soft interrupt) event time. [Examples](tools/softirqs_example.txt). +- tools/[stackcount](tools/stackcount.py): Count kernel function calls and their stack traces. [Examples](tools/stackcount_example.txt). +- tools/[stacksnoop](tools/stacksnoop.py): Trace a kernel function and print all kernel stack traces. [Examples](tools/stacksnoop_example.txt). +- tools/[syncsnoop](tools/syncsnoop.py): Trace sync() syscall. [Examples](tools/syncsnoop_example.txt). +- tools/[tcpaccept](tools/tcpaccept.py): Trace TCP passive connections (accept()). [Examples](tools/tcpaccept_example.txt). +- tools/[tcpconnect](tools/tcpconnect.py): Trace TCP active connections (connect()). [Examples](tools/tcpconnect_example.txt). +- tools/[vfscount](tools/vfscount.py) tools/[vfscount.c](tools/vfscount.c): Count VFS calls. [Examples](tools/vfscount_example.txt). +- tools/[vfsstat](tools/vfsstat.py) tools/[vfsstat.c](tools/vfsstat.c): Count some VFS calls, with column output. [Examples](tools/vfsstat_example.txt). +- tools/[wakeuptime](tools/wakeuptime.py): Summarize sleep to wakeup time by waker kernel stack. [Examples](tools/wakeuptime_example.txt). ### Networking diff --git a/man/man8/offcputime.8 b/man/man8/offcputime.8 index 24ba0b8f9840..90863da41e3c 100644 --- a/man/man8/offcputime.8 +++ b/man/man8/offcputime.8 @@ -5,14 +5,14 @@ offcputime \- Summarize off-CPU time by kernel stack trace. Uses Linux eBPF/bcc. .B offcputime [\-h] [\-u] [\-p PID] [\-i INTERVAL] [\-T] [duration] .SH DESCRIPTION This program shows kernel stack traces and task names that were blocked and -"off-CPU", and the total duration they were blocked: their "off-CPU time". +"off-CPU", and the total duration they were not running: their "off-CPU time". It works by tracing when threads block and when they return to CPU, measuring -both the time they were blocked and the blocked kernel stack trace and the +both the time they were off-CPU and the blocked kernel stack trace and the task name. This data is summarized in the kernel using an eBPF map, and by -summing the blocked time by unique stack trace and task name. +summing the off-CPU time by unique stack trace and task name. The output summary will help you identify reasons why threads -were blocking, and quantify the time they were blocked. This spans all types +were blocking, and quantify the time they were off-CPU. This spans all types of blocking activity: disk I/O, network I/O, locks, page faults, involuntary context switches, etc. @@ -46,8 +46,7 @@ duration Duration to trace, in seconds. .SH EXAMPLES .TP -Trace all thread blocking events, and summarize (in-kernel) by kernel stack -trace and total off-CPU time: +Trace all thread blocking events, and summarize (in-kernel) by kernel stack trace and total off-CPU time: # .B offcputime .TP @@ -55,8 +54,7 @@ Trace for 5 seconds only: # .B offcputime 5 .TP -Trace for 5 seconds, and emit output in folded stack format (suitable for -flame graphs): +Trace for 5 seconds, and emit output in folded stack format (suitable for flame graphs): # .B offcputime -f 5 .TP diff --git a/man/man8/wakeuptime.8 b/man/man8/wakeuptime.8 new file mode 100644 index 000000000000..0a2dc2a93711 --- /dev/null +++ b/man/man8/wakeuptime.8 @@ -0,0 +1,94 @@ +.TH wakeuptime 8 "2016-01-27" "USER COMMANDS" +.SH NAME +wakeuptime \- Summarize sleep to wakeup time by waker kernel stack. Uses Linux eBPF/bcc. +.SH SYNOPSIS +.B wakeuptime [\-h] [\-u] [\-p PID] [\-i INTERVAL] [\-T] [duration] +.SH DESCRIPTION +This program shows the kernel stack traces for threads that woke up other +blocked threads, along with the process names of the waker and target, along +with a sum of the time that the target was blocked: the "blocked time". +It works by tracing when threads block and when they were then woken up, and +measuring the time delta. This time measurement will be very similar to off-CPU +time, however, off-CPU time may include a little extra time spent waiting +on a run queue to be scheduled. The stack traces, process names, and time spent +blocked is summarized in the kernel using an eBPF map for efficiency. + +The output summary will help you identify reasons why threads +were blocking by showing who woke them up, along with the time they were +blocked. This spans all types of blocking activity: disk I/O, network I/O, +locks, page faults, involuntary context switches, etc. + +This can be used in conjunction with offcputime, which shows the stack trace +of the blocked thread. wakeuptime shows the stack trace of the waker thread. + +See http://www.brendangregg.com/FlameGraphs/offcpuflamegraphs.html + +The stack depth is currently limited to 20, and the stack traces are kernel +mode only. Check for newer versions where either may be improved. + +This currently only works on x86_64. Check for future versions. +.SH REQUIREMENTS +CONFIG_BPF and bcc. +.SH OPTIONS +.TP +\-h +Print usage message. +.TP +\-u +Only trace user threads (not kernel threads). +.TP +\-v +Show raw addresses. +.TP +\-p PID +Trace this process ID only (filtered in-kernel). +.TP +duration +Duration to trace, in seconds. +.SH EXAMPLES +.TP +Trace all thread blocking events, and summarize (in-kernel) by kernel stack trace and total blocked time: +# +.B wakeuptime +.TP +Trace user-mode target threads only: +# +.B wakeuptime -u +.TP +Trace for 5 seconds only: +# +.B wakeuptime 5 +.TP +Trace for 5 seconds, and emit output in folded stack format (suitable for flame graphs): +# +.B wakeuptime -f 5 +.TP +Trace PID 185 only: +# +.B wakeuptime -p 185 +.SH OVERHEAD +This summarizes unique stack traces in-kernel for efficiency, allowing it to +trace a higher rate of events than methods that post-process in user space. The +stack trace and time data is only copied to user space once, when the output is +printed. While these techniques greatly lower overhead, scheduler events are +still a high frequency event, as they can exceed 1 million events per second, +and so caution should still be used. Test before production use. + +If the overhead is still a problem, take a look at the MINBLOCK_US tunable in +the code. If your aim is to chase down longer blocking events, then this could +be increased to filter shorter blocking events, further lowering overhead. +.SH SOURCE +This is from bcc. +.IP +https://github.com/iovisor/bcc +.PP +Also look in the bcc distribution for a companion _examples.txt file containing +example usage, output, and commentary for this tool. +.SH OS +Linux +.SH STABILITY +Unstable - in development. +.SH AUTHOR +Brendan Gregg +.SH SEE ALSO +offcputime(8), stackcount(8) diff --git a/tools/wakeuptime.py b/tools/wakeuptime.py new file mode 100755 index 000000000000..0ddbae2a1408 --- /dev/null +++ b/tools/wakeuptime.py @@ -0,0 +1,218 @@ +#!/usr/bin/python +# +# wakeuptime Summarize sleep to wakeup time by waker kernel stack +# For Linux, uses BCC, eBPF. +# +# USAGE: wakeuptime [-h] [-u] [-p PID] [-i INTERVAL] [-T] [duration] +# +# The current implementation uses an unrolled loop for x86_64, and was written +# as a proof of concept. This implementation should be replaced in the future +# with an appropriate bpf_ call, when available. +# +# Currently limited to a stack trace depth of 21 (maxdepth + 1). +# +# Copyright 2016 Netflix, Inc. +# Licensed under the Apache License, Version 2.0 (the "License") +# +# 14-Jan-2016 Brendan Gregg Created this. + +from __future__ import print_function +from bcc import BPF +from time import sleep, strftime +import argparse +import signal + +# arguments +examples = """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 fo PID 185 only +""" +parser = argparse.ArgumentParser( + description="Summarize sleep to wakeup time by waker kernel stack", + formatter_class=argparse.RawDescriptionHelpFormatter, + epilog=examples) +parser.add_argument("-u", "--useronly", action="store_true", + help="user threads only (no kernel threads)") +parser.add_argument("-p", "--pid", + help="trace this PID only") +parser.add_argument("-v", "--verbose", action="store_true", + help="show raw addresses") +parser.add_argument("-f", "--folded", action="store_true", + help="output folded format") +parser.add_argument("duration", nargs="?", default=99999999, + help="duration of trace, in seconds") +args = parser.parse_args() +folded = args.folded +duration = int(args.duration) +debug = 0 +maxdepth = 20 # and MAXDEPTH +if args.pid and args.useronly: + print("ERROR: use either -p or -u.") + exit() + +# signal handler +def signal_ignore(signal, frame): + print() + +# define BPF program +bpf_text = """ +#include +#include + +#define MAXDEPTH 20 +#define MINBLOCK_US 1 + +struct key_t { + char waker[TASK_COMM_LEN]; + char target[TASK_COMM_LEN]; + // Skip saving the ip + u64 ret[MAXDEPTH]; +}; +BPF_HASH(counts, struct key_t); +BPF_HASH(start, u32); + +static u64 get_frame(u64 *bp) { + if (*bp) { + // The following stack walker is x86_64 specific + u64 ret = 0; + if (bpf_probe_read(&ret, sizeof(ret), (void *)(*bp+8))) + return 0; + if (bpf_probe_read(bp, sizeof(*bp), (void *)*bp)) + bp = 0; + if (ret < __START_KERNEL_map) + return 0; + return ret; + } + return 0; +} + +int offcpu(struct pt_regs *ctx) { + u32 pid = bpf_get_current_pid_tgid(); + u64 ts = bpf_ktime_get_ns(); + // XXX: should filter here too, but need task_struct + start.update(&pid, &ts); + return 0; +} + +int waker(struct pt_regs *ctx, struct task_struct *p) { + u32 pid = p->pid; + u64 delta, *tsp, ts; + + tsp = start.lookup(&pid); + if (tsp == 0) + return 0; // missed start + start.delete(&pid); + + if (FILTER) + return 0; + + // calculate delta time + delta = bpf_ktime_get_ns() - *tsp; + delta = delta / 1000; + if (delta < MINBLOCK_US) + return 0; + + struct key_t key = {}; + u64 zero = 0, *val, bp = 0; + int depth = 0; + + bpf_probe_read(&key.target, sizeof(key.target), p->comm); + bpf_get_current_comm(&key.waker, sizeof(key.waker)); + bp = ctx->bp; + + // unrolled loop (MAXDEPTH): + if (!(key.ret[depth++] = get_frame(&bp))) goto out; + if (!(key.ret[depth++] = get_frame(&bp))) goto out; + if (!(key.ret[depth++] = get_frame(&bp))) goto out; + if (!(key.ret[depth++] = get_frame(&bp))) goto out; + if (!(key.ret[depth++] = get_frame(&bp))) goto out; + if (!(key.ret[depth++] = get_frame(&bp))) goto out; + if (!(key.ret[depth++] = get_frame(&bp))) goto out; + if (!(key.ret[depth++] = get_frame(&bp))) goto out; + if (!(key.ret[depth++] = get_frame(&bp))) goto out; + if (!(key.ret[depth++] = get_frame(&bp))) goto out; + + if (!(key.ret[depth++] = get_frame(&bp))) goto out; + if (!(key.ret[depth++] = get_frame(&bp))) goto out; + if (!(key.ret[depth++] = get_frame(&bp))) goto out; + if (!(key.ret[depth++] = get_frame(&bp))) goto out; + if (!(key.ret[depth++] = get_frame(&bp))) goto out; + if (!(key.ret[depth++] = get_frame(&bp))) goto out; + if (!(key.ret[depth++] = get_frame(&bp))) goto out; + if (!(key.ret[depth++] = get_frame(&bp))) goto out; + if (!(key.ret[depth++] = get_frame(&bp))) goto out; + if (!(key.ret[depth++] = get_frame(&bp))) goto out; + +out: + val = counts.lookup_or_init(&key, &zero); + (*val) += delta; + return 0; +} +""" +if args.pid: + filter = 'pid != %s' % args.pid +elif args.useronly: + filter = 'p->flags & PF_KTHREAD' +else: + filter = '0' +bpf_text = bpf_text.replace('FILTER', filter) +if debug: + print(bpf_text) + +# initialize BPF +b = BPF(text=bpf_text) +b.attach_kprobe(event="schedule", fn_name="offcpu") +b.attach_kprobe(event="try_to_wake_up", fn_name="waker") +matched = b.num_open_kprobes() +if matched == 0: + print("0 functions traced. Exiting.") + exit() + +# header +if not folded: + print("Tracing blocked time (us) by kernel stack", end="") + if duration < 99999999: + print(" for %d secs." % duration) + else: + print("... Hit Ctrl-C to end.") + +# output +while (1): + try: + sleep(duration) + except KeyboardInterrupt: + # as cleanup can take many seconds, trap Ctrl-C: + signal.signal(signal.SIGINT, signal_ignore) + + if not folded: + print() + counts = b.get_table("counts") + for k, v in sorted(counts.items(), key=lambda counts: counts[1].value): + if folded: + # print folded stack output + line = k.waker + ";" + for i in reversed(range(0, maxdepth)): + if k.ret[i] == 0: + continue + line = line + b.ksym(k.ret[i]) + if i != 0: + line = line + ";" + print("%s;%s %d" % (line, k.target, v.value)) + else: + # print default multi-line stack output + print(" %-16s %s" % ("target:", k.target)) + for i in range(0, maxdepth): + if k.ret[i] == 0: + break + print(" %-16x %s" % (k.ret[i], + b.ksym(k.ret[i]))) + print(" %-16s %s" % ("waker:", k.waker)) + print(" %d\n" % v.value) + counts.clear() + + if not folded: + print("Detaching...") + exit() diff --git a/tools/wakeuptime_example.txt b/tools/wakeuptime_example.txt new file mode 100644 index 000000000000..326e9e6d7958 --- /dev/null +++ b/tools/wakeuptime_example.txt @@ -0,0 +1,470 @@ +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] [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 + +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 fo PID 185 only