Brendan Gregg | 3a391c2 | 2016-02-08 01:20:31 -0800 | [diff] [blame] | 1 | #!/usr/bin/python |
| 2 | # @lint-avoid-python-3-compatibility-imports |
| 3 | # |
| 4 | # runqlat Run queue (scheduler) latency as a histogram. |
| 5 | # For Linux, uses BCC, eBPF. |
| 6 | # |
Brenden Blanco | a687560 | 2016-05-02 23:32:44 -0700 | [diff] [blame] | 7 | # USAGE: runqlat [-h] [-T] [-m] [-P] [-L] [-p PID] [interval] [count] |
Brendan Gregg | 3a391c2 | 2016-02-08 01:20:31 -0800 | [diff] [blame] | 8 | # |
| 9 | # This measures the time a task spends waiting on a run queue for a turn |
| 10 | # on-CPU, and shows this time as a histogram. This time should be small, but a |
| 11 | # task may need to wait its turn due to CPU load. |
| 12 | # |
| 13 | # This measures two types of run queue latency: |
| 14 | # 1. The time from a task being enqueued on a run queue to its context switch |
Ivan Babrou | 5c48a3f | 2018-05-08 17:24:19 -0700 | [diff] [blame] | 15 | # and execution. This traces ttwu_do_wakeup(), wake_up_new_task() -> |
| 16 | # finish_task_switch() with either raw tracepoints (if supported) or kprobes |
Brendan Gregg | 3a391c2 | 2016-02-08 01:20:31 -0800 | [diff] [blame] | 17 | # and instruments the run queue latency after a voluntary context switch. |
| 18 | # 2. The time from when a task was involuntary context switched and still |
| 19 | # in the runnable state, to when it next executed. This is instrumented |
| 20 | # from finish_task_switch() alone. |
| 21 | # |
| 22 | # Copyright 2016 Netflix, Inc. |
| 23 | # Licensed under the Apache License, Version 2.0 (the "License") |
| 24 | # |
| 25 | # 07-Feb-2016 Brendan Gregg Created this. |
| 26 | |
| 27 | from __future__ import print_function |
| 28 | from bcc import BPF |
| 29 | from time import sleep, strftime |
| 30 | import argparse |
| 31 | |
| 32 | # arguments |
| 33 | examples = """examples: |
| 34 | ./runqlat # summarize run queue latency as a histogram |
| 35 | ./runqlat 1 10 # print 1 second summaries, 10 times |
| 36 | ./runqlat -mT 1 # 1s summaries, milliseconds, and timestamps |
| 37 | ./runqlat -P # show each PID separately |
| 38 | ./runqlat -p 185 # trace PID 185 only |
| 39 | """ |
| 40 | parser = argparse.ArgumentParser( |
Brendan Gregg | 8276938 | 2017-04-18 14:23:14 -0500 | [diff] [blame] | 41 | description="Summarize run queue (scheduler) latency as a histogram", |
Brendan Gregg | 3a391c2 | 2016-02-08 01:20:31 -0800 | [diff] [blame] | 42 | formatter_class=argparse.RawDescriptionHelpFormatter, |
| 43 | epilog=examples) |
| 44 | parser.add_argument("-T", "--timestamp", action="store_true", |
| 45 | help="include timestamp on output") |
| 46 | parser.add_argument("-m", "--milliseconds", action="store_true", |
| 47 | help="millisecond histogram") |
| 48 | parser.add_argument("-P", "--pids", action="store_true", |
| 49 | help="print a histogram per process ID") |
Brendan Gregg | 8276938 | 2017-04-18 14:23:14 -0500 | [diff] [blame] | 50 | # PID options are --pid and --pids, so namespaces should be --pidns (not done |
| 51 | # yet) and --pidnss: |
| 52 | parser.add_argument("--pidnss", action="store_true", |
| 53 | help="print a histogram per PID namespace") |
Brenden Blanco | a687560 | 2016-05-02 23:32:44 -0700 | [diff] [blame] | 54 | parser.add_argument("-L", "--tids", action="store_true", |
| 55 | help="print a histogram per thread ID") |
Brendan Gregg | 3a391c2 | 2016-02-08 01:20:31 -0800 | [diff] [blame] | 56 | parser.add_argument("-p", "--pid", |
| 57 | help="trace this PID only") |
| 58 | parser.add_argument("interval", nargs="?", default=99999999, |
| 59 | help="output interval, in seconds") |
| 60 | parser.add_argument("count", nargs="?", default=99999999, |
| 61 | help="number of outputs") |
Nathan Scott | cf0792f | 2018-02-02 16:56:50 +1100 | [diff] [blame] | 62 | parser.add_argument("--ebpf", action="store_true", |
| 63 | help=argparse.SUPPRESS) |
Brendan Gregg | 3a391c2 | 2016-02-08 01:20:31 -0800 | [diff] [blame] | 64 | args = parser.parse_args() |
| 65 | countdown = int(args.count) |
| 66 | debug = 0 |
| 67 | |
| 68 | # define BPF program |
| 69 | bpf_text = """ |
| 70 | #include <uapi/linux/ptrace.h> |
Brenden Blanco | 11a21c8 | 2016-02-10 15:42:16 -0800 | [diff] [blame] | 71 | #include <linux/sched.h> |
Brendan Gregg | 8276938 | 2017-04-18 14:23:14 -0500 | [diff] [blame] | 72 | #include <linux/nsproxy.h> |
| 73 | #include <linux/pid_namespace.h> |
Brendan Gregg | 3a391c2 | 2016-02-08 01:20:31 -0800 | [diff] [blame] | 74 | |
| 75 | typedef struct pid_key { |
Brenden Blanco | a687560 | 2016-05-02 23:32:44 -0700 | [diff] [blame] | 76 | u64 id; // work around |
Brendan Gregg | 3a391c2 | 2016-02-08 01:20:31 -0800 | [diff] [blame] | 77 | u64 slot; |
| 78 | } pid_key_t; |
Brendan Gregg | 8276938 | 2017-04-18 14:23:14 -0500 | [diff] [blame] | 79 | |
| 80 | typedef struct pidns_key { |
| 81 | u64 id; // work around |
| 82 | u64 slot; |
| 83 | } pidns_key_t; |
| 84 | |
Brendan Gregg | 3a391c2 | 2016-02-08 01:20:31 -0800 | [diff] [blame] | 85 | BPF_HASH(start, u32); |
| 86 | STORAGE |
| 87 | |
Brenden Blanco | 11a21c8 | 2016-02-10 15:42:16 -0800 | [diff] [blame] | 88 | struct rq; |
| 89 | |
Brendan Gregg | 3a391c2 | 2016-02-08 01:20:31 -0800 | [diff] [blame] | 90 | // record enqueue timestamp |
Cong Wang | e26019f | 2018-04-17 15:56:23 -0700 | [diff] [blame] | 91 | static int trace_enqueue(u32 tgid, u32 pid) |
Brendan Gregg | 3a391c2 | 2016-02-08 01:20:31 -0800 | [diff] [blame] | 92 | { |
Ivan Babrou | 799f46a | 2018-05-08 23:10:27 -0700 | [diff] [blame] | 93 | if (FILTER || pid == 0) |
Brendan Gregg | 3a391c2 | 2016-02-08 01:20:31 -0800 | [diff] [blame] | 94 | return 0; |
| 95 | u64 ts = bpf_ktime_get_ns(); |
| 96 | start.update(&pid, &ts); |
| 97 | return 0; |
| 98 | } |
Yonghong Song | 0d72237 | 2018-04-27 04:56:08 -0700 | [diff] [blame] | 99 | """ |
Brendan Gregg | 3a391c2 | 2016-02-08 01:20:31 -0800 | [diff] [blame] | 100 | |
Yonghong Song | 0d72237 | 2018-04-27 04:56:08 -0700 | [diff] [blame] | 101 | bpf_text_kprobe = """ |
Cong Wang | e26019f | 2018-04-17 15:56:23 -0700 | [diff] [blame] | 102 | int trace_wake_up_new_task(struct pt_regs *ctx, struct task_struct *p) |
| 103 | { |
| 104 | return trace_enqueue(p->tgid, p->pid); |
| 105 | } |
| 106 | |
| 107 | int trace_ttwu_do_wakeup(struct pt_regs *ctx, struct rq *rq, struct task_struct *p, |
| 108 | int wake_flags) |
| 109 | { |
| 110 | return trace_enqueue(p->tgid, p->pid); |
| 111 | } |
| 112 | |
Brendan Gregg | 3a391c2 | 2016-02-08 01:20:31 -0800 | [diff] [blame] | 113 | // calculate latency |
| 114 | int trace_run(struct pt_regs *ctx, struct task_struct *prev) |
| 115 | { |
Brenden Blanco | a687560 | 2016-05-02 23:32:44 -0700 | [diff] [blame] | 116 | u32 pid, tgid; |
Brendan Gregg | 3a391c2 | 2016-02-08 01:20:31 -0800 | [diff] [blame] | 117 | |
| 118 | // ivcsw: treat like an enqueue event and store timestamp |
| 119 | if (prev->state == TASK_RUNNING) { |
Brenden Blanco | a687560 | 2016-05-02 23:32:44 -0700 | [diff] [blame] | 120 | tgid = prev->tgid; |
Brendan Gregg | 3a391c2 | 2016-02-08 01:20:31 -0800 | [diff] [blame] | 121 | pid = prev->pid; |
Ivan Babrou | 799f46a | 2018-05-08 23:10:27 -0700 | [diff] [blame] | 122 | if (!(FILTER || pid == 0)) { |
Brendan Gregg | 3a391c2 | 2016-02-08 01:20:31 -0800 | [diff] [blame] | 123 | u64 ts = bpf_ktime_get_ns(); |
| 124 | start.update(&pid, &ts); |
| 125 | } |
| 126 | } |
| 127 | |
Brenden Blanco | a687560 | 2016-05-02 23:32:44 -0700 | [diff] [blame] | 128 | tgid = bpf_get_current_pid_tgid() >> 32; |
Brendan Gregg | 3a391c2 | 2016-02-08 01:20:31 -0800 | [diff] [blame] | 129 | pid = bpf_get_current_pid_tgid(); |
Ivan Babrou | 799f46a | 2018-05-08 23:10:27 -0700 | [diff] [blame] | 130 | if (FILTER || pid == 0) |
Brendan Gregg | 3a391c2 | 2016-02-08 01:20:31 -0800 | [diff] [blame] | 131 | return 0; |
| 132 | u64 *tsp, delta; |
| 133 | |
| 134 | // fetch timestamp and calculate delta |
| 135 | tsp = start.lookup(&pid); |
| 136 | if (tsp == 0) { |
| 137 | return 0; // missed enqueue |
| 138 | } |
| 139 | delta = bpf_ktime_get_ns() - *tsp; |
| 140 | FACTOR |
| 141 | |
| 142 | // store as histogram |
| 143 | STORE |
| 144 | |
| 145 | start.delete(&pid); |
| 146 | return 0; |
| 147 | } |
| 148 | """ |
| 149 | |
Yonghong Song | 0d72237 | 2018-04-27 04:56:08 -0700 | [diff] [blame] | 150 | bpf_text_raw_tp = """ |
| 151 | RAW_TRACEPOINT_PROBE(sched_wakeup) |
| 152 | { |
| 153 | // TP_PROTO(struct task_struct *p) |
| 154 | struct task_struct *p = (struct task_struct *)ctx->args[0]; |
Paul Chaignon | a9f96c0 | 2018-06-15 00:27:08 +0200 | [diff] [blame] | 155 | return trace_enqueue(p->tgid, p->pid); |
Yonghong Song | 0d72237 | 2018-04-27 04:56:08 -0700 | [diff] [blame] | 156 | } |
| 157 | |
| 158 | RAW_TRACEPOINT_PROBE(sched_wakeup_new) |
| 159 | { |
| 160 | // TP_PROTO(struct task_struct *p) |
| 161 | struct task_struct *p = (struct task_struct *)ctx->args[0]; |
Paul Chaignon | a9f96c0 | 2018-06-15 00:27:08 +0200 | [diff] [blame] | 162 | return trace_enqueue(p->tgid, p->pid); |
Yonghong Song | 0d72237 | 2018-04-27 04:56:08 -0700 | [diff] [blame] | 163 | } |
| 164 | |
| 165 | RAW_TRACEPOINT_PROBE(sched_switch) |
| 166 | { |
| 167 | // TP_PROTO(bool preempt, struct task_struct *prev, struct task_struct *next) |
| 168 | struct task_struct *prev = (struct task_struct *)ctx->args[1]; |
Paul Chaignon | a9f96c0 | 2018-06-15 00:27:08 +0200 | [diff] [blame] | 169 | struct task_struct *next = (struct task_struct *)ctx->args[2]; |
Yonghong Song | 0d72237 | 2018-04-27 04:56:08 -0700 | [diff] [blame] | 170 | u32 pid, tgid; |
| 171 | long state; |
| 172 | |
| 173 | // ivcsw: treat like an enqueue event and store timestamp |
| 174 | bpf_probe_read(&state, sizeof(long), &prev->state); |
| 175 | if (state == TASK_RUNNING) { |
Paul Chaignon | a9f96c0 | 2018-06-15 00:27:08 +0200 | [diff] [blame] | 176 | tgid = prev->tgid; |
| 177 | pid = prev->pid; |
Ivan Babrou | 799f46a | 2018-05-08 23:10:27 -0700 | [diff] [blame] | 178 | if (!(FILTER || pid == 0)) { |
Yonghong Song | 0d72237 | 2018-04-27 04:56:08 -0700 | [diff] [blame] | 179 | u64 ts = bpf_ktime_get_ns(); |
| 180 | start.update(&pid, &ts); |
| 181 | } |
| 182 | } |
| 183 | |
Paul Chaignon | a9f96c0 | 2018-06-15 00:27:08 +0200 | [diff] [blame] | 184 | tgid = next->tgid; |
| 185 | pid = next->pid; |
Ivan Babrou | 799f46a | 2018-05-08 23:10:27 -0700 | [diff] [blame] | 186 | if (FILTER || pid == 0) |
Yonghong Song | 0d72237 | 2018-04-27 04:56:08 -0700 | [diff] [blame] | 187 | return 0; |
| 188 | u64 *tsp, delta; |
| 189 | |
| 190 | // fetch timestamp and calculate delta |
| 191 | tsp = start.lookup(&pid); |
| 192 | if (tsp == 0) { |
| 193 | return 0; // missed enqueue |
| 194 | } |
| 195 | delta = bpf_ktime_get_ns() - *tsp; |
| 196 | FACTOR |
| 197 | |
| 198 | // store as histogram |
| 199 | STORE |
| 200 | |
| 201 | start.delete(&pid); |
| 202 | return 0; |
| 203 | } |
| 204 | """ |
| 205 | |
| 206 | is_support_raw_tp = BPF.support_raw_tracepoint() |
| 207 | if is_support_raw_tp: |
| 208 | bpf_text += bpf_text_raw_tp |
| 209 | else: |
| 210 | bpf_text += bpf_text_kprobe |
| 211 | |
Brendan Gregg | 3a391c2 | 2016-02-08 01:20:31 -0800 | [diff] [blame] | 212 | # code substitutions |
| 213 | if args.pid: |
Brenden Blanco | a687560 | 2016-05-02 23:32:44 -0700 | [diff] [blame] | 214 | # pid from userspace point of view is thread group from kernel pov |
| 215 | bpf_text = bpf_text.replace('FILTER', 'tgid != %s' % args.pid) |
Brendan Gregg | 3a391c2 | 2016-02-08 01:20:31 -0800 | [diff] [blame] | 216 | else: |
| 217 | bpf_text = bpf_text.replace('FILTER', '0') |
| 218 | if args.milliseconds: |
| 219 | bpf_text = bpf_text.replace('FACTOR', 'delta /= 1000000;') |
| 220 | label = "msecs" |
| 221 | else: |
| 222 | bpf_text = bpf_text.replace('FACTOR', 'delta /= 1000;') |
| 223 | label = "usecs" |
Brenden Blanco | a687560 | 2016-05-02 23:32:44 -0700 | [diff] [blame] | 224 | if args.pids or args.tids: |
| 225 | section = "pid" |
| 226 | pid = "tgid" |
| 227 | if args.tids: |
| 228 | pid = "pid" |
| 229 | section = "tid" |
Brendan Gregg | 3a391c2 | 2016-02-08 01:20:31 -0800 | [diff] [blame] | 230 | bpf_text = bpf_text.replace('STORAGE', |
| 231 | 'BPF_HISTOGRAM(dist, pid_key_t);') |
| 232 | bpf_text = bpf_text.replace('STORE', |
Brenden Blanco | a687560 | 2016-05-02 23:32:44 -0700 | [diff] [blame] | 233 | 'pid_key_t key = {.id = ' + pid + ', .slot = bpf_log2l(delta)}; ' + |
Brendan Gregg | 3a391c2 | 2016-02-08 01:20:31 -0800 | [diff] [blame] | 234 | 'dist.increment(key);') |
Brendan Gregg | 8276938 | 2017-04-18 14:23:14 -0500 | [diff] [blame] | 235 | elif args.pidnss: |
| 236 | section = "pidns" |
| 237 | bpf_text = bpf_text.replace('STORAGE', |
| 238 | 'BPF_HISTOGRAM(dist, pidns_key_t);') |
| 239 | bpf_text = bpf_text.replace('STORE', 'pidns_key_t key = ' + |
| 240 | '{.id = prev->nsproxy->pid_ns_for_children->ns.inum, ' + |
| 241 | '.slot = bpf_log2l(delta)}; dist.increment(key);') |
Brendan Gregg | 3a391c2 | 2016-02-08 01:20:31 -0800 | [diff] [blame] | 242 | else: |
Brenden Blanco | a687560 | 2016-05-02 23:32:44 -0700 | [diff] [blame] | 243 | section = "" |
Brendan Gregg | 3a391c2 | 2016-02-08 01:20:31 -0800 | [diff] [blame] | 244 | bpf_text = bpf_text.replace('STORAGE', 'BPF_HISTOGRAM(dist);') |
| 245 | bpf_text = bpf_text.replace('STORE', |
| 246 | 'dist.increment(bpf_log2l(delta));') |
Nathan Scott | cf0792f | 2018-02-02 16:56:50 +1100 | [diff] [blame] | 247 | if debug or args.ebpf: |
Brendan Gregg | 3a391c2 | 2016-02-08 01:20:31 -0800 | [diff] [blame] | 248 | print(bpf_text) |
Nathan Scott | cf0792f | 2018-02-02 16:56:50 +1100 | [diff] [blame] | 249 | if args.ebpf: |
| 250 | exit() |
Brendan Gregg | 3a391c2 | 2016-02-08 01:20:31 -0800 | [diff] [blame] | 251 | |
| 252 | # load BPF program |
| 253 | b = BPF(text=bpf_text) |
Yonghong Song | 0d72237 | 2018-04-27 04:56:08 -0700 | [diff] [blame] | 254 | if not is_support_raw_tp: |
| 255 | b.attach_kprobe(event="ttwu_do_wakeup", fn_name="trace_ttwu_do_wakeup") |
| 256 | b.attach_kprobe(event="wake_up_new_task", fn_name="trace_wake_up_new_task") |
| 257 | b.attach_kprobe(event="finish_task_switch", fn_name="trace_run") |
Brendan Gregg | 3a391c2 | 2016-02-08 01:20:31 -0800 | [diff] [blame] | 258 | |
| 259 | print("Tracing run queue latency... Hit Ctrl-C to end.") |
| 260 | |
| 261 | # output |
| 262 | exiting = 0 if args.interval else 1 |
| 263 | dist = b.get_table("dist") |
| 264 | while (1): |
| 265 | try: |
| 266 | sleep(int(args.interval)) |
| 267 | except KeyboardInterrupt: |
| 268 | exiting = 1 |
| 269 | |
| 270 | print() |
| 271 | if args.timestamp: |
| 272 | print("%-8s\n" % strftime("%H:%M:%S"), end="") |
| 273 | |
Brenden Blanco | a687560 | 2016-05-02 23:32:44 -0700 | [diff] [blame] | 274 | dist.print_log2_hist(label, section, section_print_fn=int) |
Brendan Gregg | 3a391c2 | 2016-02-08 01:20:31 -0800 | [diff] [blame] | 275 | dist.clear() |
| 276 | |
| 277 | countdown -= 1 |
| 278 | if exiting or countdown == 0: |
| 279 | exit() |