Brendan Gregg | 38cef48 | 2016-01-15 17:26:30 -0800 | [diff] [blame] | 1 | #!/usr/bin/python |
| 2 | # |
| 3 | # offcputime Summarize off-CPU time by kernel stack trace |
| 4 | # For Linux, uses BCC, eBPF. |
| 5 | # |
Brendan Gregg | 62f4c28 | 2016-01-30 11:05:40 -0800 | [diff] [blame] | 6 | # USAGE: offcputime [-h] [-u] [-p PID] [-v] [-f] [duration] |
Brendan Gregg | 38cef48 | 2016-01-15 17:26:30 -0800 | [diff] [blame] | 7 | # |
| 8 | # The current implementation uses an unrolled loop for x86_64, and was written |
| 9 | # as a proof of concept. This implementation should be replaced in the future |
| 10 | # with an appropriate bpf_ call, when available. |
| 11 | # |
Brendan Gregg | 38cef48 | 2016-01-15 17:26:30 -0800 | [diff] [blame] | 12 | # Copyright 2016 Netflix, Inc. |
| 13 | # Licensed under the Apache License, Version 2.0 (the "License") |
| 14 | # |
| 15 | # 13-Jan-2016 Brendan Gregg Created this. |
| 16 | |
| 17 | from __future__ import print_function |
| 18 | from bcc import BPF |
| 19 | from time import sleep, strftime |
| 20 | import argparse |
| 21 | import signal |
| 22 | |
| 23 | # arguments |
| 24 | examples = """examples: |
| 25 | ./offcputime # trace off-CPU stack time until Ctrl-C |
| 26 | ./offcputime 5 # trace for 5 seconds only |
| 27 | ./offcputime -f 5 # 5 seconds, and output in folded format |
Brendan Gregg | d364d04 | 2016-01-19 17:12:52 -0800 | [diff] [blame] | 28 | ./offcputime -u # don't include kernel threads (user only) |
Brendan Gregg | 38cef48 | 2016-01-15 17:26:30 -0800 | [diff] [blame] | 29 | ./offcputime -p 185 # trace fo PID 185 only |
| 30 | """ |
| 31 | parser = argparse.ArgumentParser( |
| 32 | description="Summarize off-CPU time by kernel stack trace", |
| 33 | formatter_class=argparse.RawDescriptionHelpFormatter, |
| 34 | epilog=examples) |
Brendan Gregg | d364d04 | 2016-01-19 17:12:52 -0800 | [diff] [blame] | 35 | parser.add_argument("-u", "--useronly", action="store_true", |
| 36 | help="user threads only (no kernel threads)") |
Brendan Gregg | 38cef48 | 2016-01-15 17:26:30 -0800 | [diff] [blame] | 37 | parser.add_argument("-p", "--pid", |
| 38 | help="trace this PID only") |
| 39 | parser.add_argument("-v", "--verbose", action="store_true", |
| 40 | help="show raw addresses") |
| 41 | parser.add_argument("-f", "--folded", action="store_true", |
| 42 | help="output folded format") |
| 43 | parser.add_argument("duration", nargs="?", default=99999999, |
| 44 | help="duration of trace, in seconds") |
| 45 | args = parser.parse_args() |
| 46 | folded = args.folded |
| 47 | duration = int(args.duration) |
| 48 | debug = 0 |
Brendan Gregg | d364d04 | 2016-01-19 17:12:52 -0800 | [diff] [blame] | 49 | if args.pid and args.useronly: |
| 50 | print("ERROR: use either -p or -u.") |
| 51 | exit() |
Brendan Gregg | 38cef48 | 2016-01-15 17:26:30 -0800 | [diff] [blame] | 52 | |
| 53 | # signal handler |
| 54 | def signal_ignore(signal, frame): |
| 55 | print() |
| 56 | |
Brendan Gregg | d364d04 | 2016-01-19 17:12:52 -0800 | [diff] [blame] | 57 | # define BPF program |
Brendan Gregg | 38cef48 | 2016-01-15 17:26:30 -0800 | [diff] [blame] | 58 | bpf_text = """ |
| 59 | #include <uapi/linux/ptrace.h> |
| 60 | #include <linux/sched.h> |
| 61 | |
Brendan Gregg | 38cef48 | 2016-01-15 17:26:30 -0800 | [diff] [blame] | 62 | #define MINBLOCK_US 1 |
| 63 | |
| 64 | struct key_t { |
| 65 | char name[TASK_COMM_LEN]; |
Vicent Marti | e82fb1b | 2016-03-25 17:21:44 +0100 | [diff] [blame] | 66 | int stack_id; |
Brendan Gregg | 38cef48 | 2016-01-15 17:26:30 -0800 | [diff] [blame] | 67 | }; |
| 68 | BPF_HASH(counts, struct key_t); |
| 69 | BPF_HASH(start, u32); |
Vicent Marti | e82fb1b | 2016-03-25 17:21:44 +0100 | [diff] [blame] | 70 | BPF_STACK_TRACE(stack_traces, 1024) |
Brendan Gregg | 38cef48 | 2016-01-15 17:26:30 -0800 | [diff] [blame] | 71 | |
Brendan Gregg | d364d04 | 2016-01-19 17:12:52 -0800 | [diff] [blame] | 72 | int oncpu(struct pt_regs *ctx, struct task_struct *prev) { |
| 73 | u32 pid; |
| 74 | u64 ts, *tsp; |
Brendan Gregg | 38cef48 | 2016-01-15 17:26:30 -0800 | [diff] [blame] | 75 | |
Brendan Gregg | d364d04 | 2016-01-19 17:12:52 -0800 | [diff] [blame] | 76 | // record previous thread sleep time |
| 77 | if (FILTER) { |
| 78 | pid = prev->pid; |
| 79 | ts = bpf_ktime_get_ns(); |
| 80 | start.update(&pid, &ts); |
| 81 | } |
Brendan Gregg | 38cef48 | 2016-01-15 17:26:30 -0800 | [diff] [blame] | 82 | |
Brendan Gregg | d364d04 | 2016-01-19 17:12:52 -0800 | [diff] [blame] | 83 | // calculate current thread's delta time |
| 84 | pid = bpf_get_current_pid_tgid(); |
Brendan Gregg | 38cef48 | 2016-01-15 17:26:30 -0800 | [diff] [blame] | 85 | tsp = start.lookup(&pid); |
| 86 | if (tsp == 0) |
Brendan Gregg | f747114 | 2016-01-19 14:40:41 -0800 | [diff] [blame] | 87 | return 0; // missed start or filtered |
| 88 | u64 delta = bpf_ktime_get_ns() - *tsp; |
Brendan Gregg | 38cef48 | 2016-01-15 17:26:30 -0800 | [diff] [blame] | 89 | start.delete(&pid); |
| 90 | delta = delta / 1000; |
| 91 | if (delta < MINBLOCK_US) |
| 92 | return 0; |
| 93 | |
Brendan Gregg | f747114 | 2016-01-19 14:40:41 -0800 | [diff] [blame] | 94 | // create map key |
Vicent Marti | e82fb1b | 2016-03-25 17:21:44 +0100 | [diff] [blame] | 95 | u64 zero = 0, *val; |
Brendan Gregg | f747114 | 2016-01-19 14:40:41 -0800 | [diff] [blame] | 96 | struct key_t key = {}; |
Vicent Marti | e82fb1b | 2016-03-25 17:21:44 +0100 | [diff] [blame] | 97 | |
Brendan Gregg | 38cef48 | 2016-01-15 17:26:30 -0800 | [diff] [blame] | 98 | bpf_get_current_comm(&key.name, sizeof(key.name)); |
Vicent Marti | e82fb1b | 2016-03-25 17:21:44 +0100 | [diff] [blame] | 99 | key.stack_id = stack_traces.get_stackid(ctx, BPF_F_REUSE_STACKID); |
Brendan Gregg | 38cef48 | 2016-01-15 17:26:30 -0800 | [diff] [blame] | 100 | |
Brendan Gregg | 38cef48 | 2016-01-15 17:26:30 -0800 | [diff] [blame] | 101 | val = counts.lookup_or_init(&key, &zero); |
| 102 | (*val) += delta; |
| 103 | return 0; |
| 104 | } |
| 105 | """ |
| 106 | if args.pid: |
Brendan Gregg | d364d04 | 2016-01-19 17:12:52 -0800 | [diff] [blame] | 107 | filter = 'pid == %s' % args.pid |
| 108 | elif args.useronly: |
| 109 | filter = '!(prev->flags & PF_KTHREAD)' |
Brendan Gregg | 38cef48 | 2016-01-15 17:26:30 -0800 | [diff] [blame] | 110 | else: |
Brendan Gregg | d364d04 | 2016-01-19 17:12:52 -0800 | [diff] [blame] | 111 | filter = '1' |
| 112 | bpf_text = bpf_text.replace('FILTER', filter) |
Brendan Gregg | 38cef48 | 2016-01-15 17:26:30 -0800 | [diff] [blame] | 113 | if debug: |
| 114 | print(bpf_text) |
Brendan Gregg | d364d04 | 2016-01-19 17:12:52 -0800 | [diff] [blame] | 115 | |
| 116 | # initialize BPF |
Brendan Gregg | 38cef48 | 2016-01-15 17:26:30 -0800 | [diff] [blame] | 117 | b = BPF(text=bpf_text) |
Brendan Gregg | 38cef48 | 2016-01-15 17:26:30 -0800 | [diff] [blame] | 118 | b.attach_kprobe(event="finish_task_switch", fn_name="oncpu") |
| 119 | matched = b.num_open_kprobes() |
| 120 | if matched == 0: |
| 121 | print("0 functions traced. Exiting.") |
| 122 | exit() |
| 123 | |
| 124 | # header |
| 125 | if not folded: |
| 126 | print("Tracing off-CPU time (us) by kernel stack", end="") |
| 127 | if duration < 99999999: |
| 128 | print(" for %d secs." % duration) |
| 129 | else: |
| 130 | print("... Hit Ctrl-C to end.") |
| 131 | |
| 132 | # output |
| 133 | while (1): |
| 134 | try: |
| 135 | sleep(duration) |
| 136 | except KeyboardInterrupt: |
| 137 | # as cleanup can take many seconds, trap Ctrl-C: |
| 138 | signal.signal(signal.SIGINT, signal_ignore) |
| 139 | |
| 140 | if not folded: |
| 141 | print() |
| 142 | counts = b.get_table("counts") |
Vicent Marti | e82fb1b | 2016-03-25 17:21:44 +0100 | [diff] [blame] | 143 | stack_traces = b.get_table("stack_traces") |
Brendan Gregg | 38cef48 | 2016-01-15 17:26:30 -0800 | [diff] [blame] | 144 | for k, v in sorted(counts.items(), key=lambda counts: counts[1].value): |
| 145 | if folded: |
| 146 | # print folded stack output |
Vicent Marti | e82fb1b | 2016-03-25 17:21:44 +0100 | [diff] [blame] | 147 | stack = list(stack_traces.walk(k.stack_id))[1:] |
| 148 | line = [k.name.decode()] + [b.ksym(addr) for addr in reversed(stack)] |
| 149 | print("%s %d" % (";".join(line), v.value)) |
Brendan Gregg | 38cef48 | 2016-01-15 17:26:30 -0800 | [diff] [blame] | 150 | else: |
| 151 | # print default multi-line stack output |
Vicent Marti | e82fb1b | 2016-03-25 17:21:44 +0100 | [diff] [blame] | 152 | for addr in stack_traces.walk(k.stack_id): |
| 153 | print(" %-16x %s" % (addr, b.ksym(addr))) |
Brendan Gregg | 38cef48 | 2016-01-15 17:26:30 -0800 | [diff] [blame] | 154 | print(" %-16s %s" % ("-", k.name)) |
| 155 | print(" %d\n" % v.value) |
| 156 | counts.clear() |
| 157 | |
| 158 | if not folded: |
| 159 | print("Detaching...") |
| 160 | exit() |