Alexey Ivanov | cc01a9c | 2019-01-16 09:50:46 -0800 | [diff] [blame] | 1 | #!/usr/bin/python |
Brendan Gregg | 3a391c2 | 2016-02-08 01:20:31 -0800 | [diff] [blame] | 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> |
Li Chengyuan | c73d7d8 | 2021-10-22 03:23:02 -0700 | [diff] [blame] | 74 | #include <linux/init_task.h> |
Brendan Gregg | 3a391c2 | 2016-02-08 01:20:31 -0800 | [diff] [blame] | 75 | |
| 76 | typedef struct pid_key { |
Brenden Blanco | a687560 | 2016-05-02 23:32:44 -0700 | [diff] [blame] | 77 | u64 id; // work around |
Brendan Gregg | 3a391c2 | 2016-02-08 01:20:31 -0800 | [diff] [blame] | 78 | u64 slot; |
| 79 | } pid_key_t; |
Brendan Gregg | 8276938 | 2017-04-18 14:23:14 -0500 | [diff] [blame] | 80 | |
| 81 | typedef struct pidns_key { |
| 82 | u64 id; // work around |
| 83 | u64 slot; |
| 84 | } pidns_key_t; |
| 85 | |
Brendan Gregg | 3a391c2 | 2016-02-08 01:20:31 -0800 | [diff] [blame] | 86 | BPF_HASH(start, u32); |
| 87 | STORAGE |
| 88 | |
Brenden Blanco | 11a21c8 | 2016-02-10 15:42:16 -0800 | [diff] [blame] | 89 | struct rq; |
| 90 | |
Brendan Gregg | 3a391c2 | 2016-02-08 01:20:31 -0800 | [diff] [blame] | 91 | // record enqueue timestamp |
Cong Wang | e26019f | 2018-04-17 15:56:23 -0700 | [diff] [blame] | 92 | static int trace_enqueue(u32 tgid, u32 pid) |
Brendan Gregg | 3a391c2 | 2016-02-08 01:20:31 -0800 | [diff] [blame] | 93 | { |
Ivan Babrou | 799f46a | 2018-05-08 23:10:27 -0700 | [diff] [blame] | 94 | if (FILTER || pid == 0) |
Brendan Gregg | 3a391c2 | 2016-02-08 01:20:31 -0800 | [diff] [blame] | 95 | return 0; |
| 96 | u64 ts = bpf_ktime_get_ns(); |
| 97 | start.update(&pid, &ts); |
| 98 | return 0; |
| 99 | } |
Li Chengyuan | c73d7d8 | 2021-10-22 03:23:02 -0700 | [diff] [blame] | 100 | |
| 101 | static __always_inline unsigned int pid_namespace(struct task_struct *task) |
| 102 | { |
| 103 | |
| 104 | /* pids[] was removed from task_struct since commit 2c4704756cab7cfa031ada4dab361562f0e357c0 |
| 105 | * Using the macro INIT_PID_LINK as a conditional judgment. |
| 106 | */ |
| 107 | #ifdef INIT_PID_LINK |
| 108 | struct pid_link pids; |
| 109 | unsigned int level; |
| 110 | struct upid upid; |
| 111 | struct ns_common ns; |
| 112 | |
| 113 | /* get the pid namespace by following task_active_pid_ns(), |
| 114 | * pid->numbers[pid->level].ns |
| 115 | */ |
| 116 | bpf_probe_read_kernel(&pids, sizeof(pids), &task->pids[PIDTYPE_PID]); |
| 117 | bpf_probe_read_kernel(&level, sizeof(level), &pids.pid->level); |
| 118 | bpf_probe_read_kernel(&upid, sizeof(upid), &pids.pid->numbers[level]); |
| 119 | bpf_probe_read_kernel(&ns, sizeof(ns), &upid.ns->ns); |
| 120 | |
| 121 | return ns.inum; |
| 122 | #else |
| 123 | struct pid *pid; |
| 124 | unsigned int level; |
| 125 | struct upid upid; |
| 126 | struct ns_common ns; |
| 127 | |
| 128 | /* get the pid namespace by following task_active_pid_ns(), |
| 129 | * pid->numbers[pid->level].ns |
| 130 | */ |
| 131 | bpf_probe_read_kernel(&pid, sizeof(pid), &task->thread_pid); |
| 132 | bpf_probe_read_kernel(&level, sizeof(level), &pid->level); |
| 133 | bpf_probe_read_kernel(&upid, sizeof(upid), &pid->numbers[level]); |
| 134 | bpf_probe_read_kernel(&ns, sizeof(ns), &upid.ns->ns); |
| 135 | |
| 136 | return ns.inum; |
| 137 | #endif |
| 138 | } |
Yonghong Song | 0d72237 | 2018-04-27 04:56:08 -0700 | [diff] [blame] | 139 | """ |
Brendan Gregg | 3a391c2 | 2016-02-08 01:20:31 -0800 | [diff] [blame] | 140 | |
Yonghong Song | 0d72237 | 2018-04-27 04:56:08 -0700 | [diff] [blame] | 141 | bpf_text_kprobe = """ |
Cong Wang | e26019f | 2018-04-17 15:56:23 -0700 | [diff] [blame] | 142 | int trace_wake_up_new_task(struct pt_regs *ctx, struct task_struct *p) |
| 143 | { |
| 144 | return trace_enqueue(p->tgid, p->pid); |
| 145 | } |
| 146 | |
| 147 | int trace_ttwu_do_wakeup(struct pt_regs *ctx, struct rq *rq, struct task_struct *p, |
| 148 | int wake_flags) |
| 149 | { |
| 150 | return trace_enqueue(p->tgid, p->pid); |
| 151 | } |
| 152 | |
Brendan Gregg | 3a391c2 | 2016-02-08 01:20:31 -0800 | [diff] [blame] | 153 | // calculate latency |
| 154 | int trace_run(struct pt_regs *ctx, struct task_struct *prev) |
| 155 | { |
Brenden Blanco | a687560 | 2016-05-02 23:32:44 -0700 | [diff] [blame] | 156 | u32 pid, tgid; |
Brendan Gregg | 3a391c2 | 2016-02-08 01:20:31 -0800 | [diff] [blame] | 157 | |
| 158 | // ivcsw: treat like an enqueue event and store timestamp |
Hengqi Chen | 08765a9 | 2021-10-31 23:20:10 +0800 | [diff] [blame] | 159 | if (prev->STATE_FIELD == TASK_RUNNING) { |
Brenden Blanco | a687560 | 2016-05-02 23:32:44 -0700 | [diff] [blame] | 160 | tgid = prev->tgid; |
Brendan Gregg | 3a391c2 | 2016-02-08 01:20:31 -0800 | [diff] [blame] | 161 | pid = prev->pid; |
Ivan Babrou | 799f46a | 2018-05-08 23:10:27 -0700 | [diff] [blame] | 162 | if (!(FILTER || pid == 0)) { |
Brendan Gregg | 3a391c2 | 2016-02-08 01:20:31 -0800 | [diff] [blame] | 163 | u64 ts = bpf_ktime_get_ns(); |
| 164 | start.update(&pid, &ts); |
| 165 | } |
| 166 | } |
| 167 | |
Brenden Blanco | a687560 | 2016-05-02 23:32:44 -0700 | [diff] [blame] | 168 | tgid = bpf_get_current_pid_tgid() >> 32; |
Brendan Gregg | 3a391c2 | 2016-02-08 01:20:31 -0800 | [diff] [blame] | 169 | pid = bpf_get_current_pid_tgid(); |
Ivan Babrou | 799f46a | 2018-05-08 23:10:27 -0700 | [diff] [blame] | 170 | if (FILTER || pid == 0) |
Brendan Gregg | 3a391c2 | 2016-02-08 01:20:31 -0800 | [diff] [blame] | 171 | return 0; |
| 172 | u64 *tsp, delta; |
| 173 | |
| 174 | // fetch timestamp and calculate delta |
| 175 | tsp = start.lookup(&pid); |
| 176 | if (tsp == 0) { |
| 177 | return 0; // missed enqueue |
| 178 | } |
| 179 | delta = bpf_ktime_get_ns() - *tsp; |
| 180 | FACTOR |
| 181 | |
| 182 | // store as histogram |
| 183 | STORE |
| 184 | |
| 185 | start.delete(&pid); |
| 186 | return 0; |
| 187 | } |
| 188 | """ |
| 189 | |
Yonghong Song | 0d72237 | 2018-04-27 04:56:08 -0700 | [diff] [blame] | 190 | bpf_text_raw_tp = """ |
| 191 | RAW_TRACEPOINT_PROBE(sched_wakeup) |
| 192 | { |
| 193 | // TP_PROTO(struct task_struct *p) |
| 194 | struct task_struct *p = (struct task_struct *)ctx->args[0]; |
Paul Chaignon | a9f96c0 | 2018-06-15 00:27:08 +0200 | [diff] [blame] | 195 | return trace_enqueue(p->tgid, p->pid); |
Yonghong Song | 0d72237 | 2018-04-27 04:56:08 -0700 | [diff] [blame] | 196 | } |
| 197 | |
| 198 | RAW_TRACEPOINT_PROBE(sched_wakeup_new) |
| 199 | { |
| 200 | // TP_PROTO(struct task_struct *p) |
| 201 | struct task_struct *p = (struct task_struct *)ctx->args[0]; |
Paul Chaignon | a9f96c0 | 2018-06-15 00:27:08 +0200 | [diff] [blame] | 202 | return trace_enqueue(p->tgid, p->pid); |
Yonghong Song | 0d72237 | 2018-04-27 04:56:08 -0700 | [diff] [blame] | 203 | } |
| 204 | |
| 205 | RAW_TRACEPOINT_PROBE(sched_switch) |
| 206 | { |
| 207 | // TP_PROTO(bool preempt, struct task_struct *prev, struct task_struct *next) |
| 208 | struct task_struct *prev = (struct task_struct *)ctx->args[1]; |
Paul Chaignon | a9f96c0 | 2018-06-15 00:27:08 +0200 | [diff] [blame] | 209 | struct task_struct *next = (struct task_struct *)ctx->args[2]; |
Yonghong Song | 0d72237 | 2018-04-27 04:56:08 -0700 | [diff] [blame] | 210 | u32 pid, tgid; |
Yonghong Song | 0d72237 | 2018-04-27 04:56:08 -0700 | [diff] [blame] | 211 | |
| 212 | // ivcsw: treat like an enqueue event and store timestamp |
Hengqi Chen | 08765a9 | 2021-10-31 23:20:10 +0800 | [diff] [blame] | 213 | if (prev->STATE_FIELD == TASK_RUNNING) { |
Paul Chaignon | a9f96c0 | 2018-06-15 00:27:08 +0200 | [diff] [blame] | 214 | tgid = prev->tgid; |
| 215 | pid = prev->pid; |
Ivan Babrou | 799f46a | 2018-05-08 23:10:27 -0700 | [diff] [blame] | 216 | if (!(FILTER || pid == 0)) { |
Yonghong Song | 0d72237 | 2018-04-27 04:56:08 -0700 | [diff] [blame] | 217 | u64 ts = bpf_ktime_get_ns(); |
| 218 | start.update(&pid, &ts); |
| 219 | } |
| 220 | } |
| 221 | |
Paul Chaignon | a9f96c0 | 2018-06-15 00:27:08 +0200 | [diff] [blame] | 222 | tgid = next->tgid; |
| 223 | pid = next->pid; |
Ivan Babrou | 799f46a | 2018-05-08 23:10:27 -0700 | [diff] [blame] | 224 | if (FILTER || pid == 0) |
Yonghong Song | 0d72237 | 2018-04-27 04:56:08 -0700 | [diff] [blame] | 225 | return 0; |
| 226 | u64 *tsp, delta; |
| 227 | |
| 228 | // fetch timestamp and calculate delta |
| 229 | tsp = start.lookup(&pid); |
| 230 | if (tsp == 0) { |
| 231 | return 0; // missed enqueue |
| 232 | } |
| 233 | delta = bpf_ktime_get_ns() - *tsp; |
| 234 | FACTOR |
| 235 | |
| 236 | // store as histogram |
| 237 | STORE |
| 238 | |
| 239 | start.delete(&pid); |
| 240 | return 0; |
| 241 | } |
| 242 | """ |
| 243 | |
| 244 | is_support_raw_tp = BPF.support_raw_tracepoint() |
| 245 | if is_support_raw_tp: |
| 246 | bpf_text += bpf_text_raw_tp |
| 247 | else: |
| 248 | bpf_text += bpf_text_kprobe |
| 249 | |
Brendan Gregg | 3a391c2 | 2016-02-08 01:20:31 -0800 | [diff] [blame] | 250 | # code substitutions |
Hengqi Chen | 08765a9 | 2021-10-31 23:20:10 +0800 | [diff] [blame] | 251 | if BPF.kernel_struct_has_field(b'task_struct', b'__state') == 1: |
| 252 | bpf_text = bpf_text.replace('STATE_FIELD', '__state') |
| 253 | else: |
| 254 | bpf_text = bpf_text.replace('STATE_FIELD', 'state') |
Brendan Gregg | 3a391c2 | 2016-02-08 01:20:31 -0800 | [diff] [blame] | 255 | if args.pid: |
Brenden Blanco | a687560 | 2016-05-02 23:32:44 -0700 | [diff] [blame] | 256 | # pid from userspace point of view is thread group from kernel pov |
| 257 | bpf_text = bpf_text.replace('FILTER', 'tgid != %s' % args.pid) |
Brendan Gregg | 3a391c2 | 2016-02-08 01:20:31 -0800 | [diff] [blame] | 258 | else: |
| 259 | bpf_text = bpf_text.replace('FILTER', '0') |
| 260 | if args.milliseconds: |
| 261 | bpf_text = bpf_text.replace('FACTOR', 'delta /= 1000000;') |
| 262 | label = "msecs" |
| 263 | else: |
| 264 | bpf_text = bpf_text.replace('FACTOR', 'delta /= 1000;') |
| 265 | label = "usecs" |
Brenden Blanco | a687560 | 2016-05-02 23:32:44 -0700 | [diff] [blame] | 266 | if args.pids or args.tids: |
| 267 | section = "pid" |
| 268 | pid = "tgid" |
| 269 | if args.tids: |
| 270 | pid = "pid" |
| 271 | section = "tid" |
Brendan Gregg | 3a391c2 | 2016-02-08 01:20:31 -0800 | [diff] [blame] | 272 | bpf_text = bpf_text.replace('STORAGE', |
| 273 | 'BPF_HISTOGRAM(dist, pid_key_t);') |
| 274 | bpf_text = bpf_text.replace('STORE', |
Brenden Blanco | a687560 | 2016-05-02 23:32:44 -0700 | [diff] [blame] | 275 | 'pid_key_t key = {.id = ' + pid + ', .slot = bpf_log2l(delta)}; ' + |
Brendan Gregg | 3a391c2 | 2016-02-08 01:20:31 -0800 | [diff] [blame] | 276 | 'dist.increment(key);') |
Brendan Gregg | 8276938 | 2017-04-18 14:23:14 -0500 | [diff] [blame] | 277 | elif args.pidnss: |
| 278 | section = "pidns" |
| 279 | bpf_text = bpf_text.replace('STORAGE', |
| 280 | 'BPF_HISTOGRAM(dist, pidns_key_t);') |
| 281 | bpf_text = bpf_text.replace('STORE', 'pidns_key_t key = ' + |
Li Chengyuan | c73d7d8 | 2021-10-22 03:23:02 -0700 | [diff] [blame] | 282 | '{.id = pid_namespace(prev), ' + |
zcy | 80242fb | 2021-07-02 00:12:32 +0800 | [diff] [blame] | 283 | '.slot = bpf_log2l(delta)}; dist.atomic_increment(key);') |
Brendan Gregg | 3a391c2 | 2016-02-08 01:20:31 -0800 | [diff] [blame] | 284 | else: |
Brenden Blanco | a687560 | 2016-05-02 23:32:44 -0700 | [diff] [blame] | 285 | section = "" |
Brendan Gregg | 3a391c2 | 2016-02-08 01:20:31 -0800 | [diff] [blame] | 286 | bpf_text = bpf_text.replace('STORAGE', 'BPF_HISTOGRAM(dist);') |
| 287 | bpf_text = bpf_text.replace('STORE', |
zcy | 80242fb | 2021-07-02 00:12:32 +0800 | [diff] [blame] | 288 | 'dist.atomic_increment(bpf_log2l(delta));') |
Nathan Scott | cf0792f | 2018-02-02 16:56:50 +1100 | [diff] [blame] | 289 | if debug or args.ebpf: |
Brendan Gregg | 3a391c2 | 2016-02-08 01:20:31 -0800 | [diff] [blame] | 290 | print(bpf_text) |
Nathan Scott | cf0792f | 2018-02-02 16:56:50 +1100 | [diff] [blame] | 291 | if args.ebpf: |
| 292 | exit() |
Brendan Gregg | 3a391c2 | 2016-02-08 01:20:31 -0800 | [diff] [blame] | 293 | |
| 294 | # load BPF program |
| 295 | b = BPF(text=bpf_text) |
Yonghong Song | 0d72237 | 2018-04-27 04:56:08 -0700 | [diff] [blame] | 296 | if not is_support_raw_tp: |
| 297 | b.attach_kprobe(event="ttwu_do_wakeup", fn_name="trace_ttwu_do_wakeup") |
| 298 | b.attach_kprobe(event="wake_up_new_task", fn_name="trace_wake_up_new_task") |
Guodong Xu | 00b72fd | 2021-03-13 02:23:47 +0000 | [diff] [blame] | 299 | b.attach_kprobe(event_re="^finish_task_switch$|^finish_task_switch\.isra\.\d$", |
| 300 | fn_name="trace_run") |
Brendan Gregg | 3a391c2 | 2016-02-08 01:20:31 -0800 | [diff] [blame] | 301 | |
| 302 | print("Tracing run queue latency... Hit Ctrl-C to end.") |
| 303 | |
| 304 | # output |
| 305 | exiting = 0 if args.interval else 1 |
| 306 | dist = b.get_table("dist") |
| 307 | while (1): |
| 308 | try: |
| 309 | sleep(int(args.interval)) |
| 310 | except KeyboardInterrupt: |
| 311 | exiting = 1 |
| 312 | |
| 313 | print() |
| 314 | if args.timestamp: |
| 315 | print("%-8s\n" % strftime("%H:%M:%S"), end="") |
| 316 | |
Brenden Blanco | a687560 | 2016-05-02 23:32:44 -0700 | [diff] [blame] | 317 | dist.print_log2_hist(label, section, section_print_fn=int) |
Brendan Gregg | 3a391c2 | 2016-02-08 01:20:31 -0800 | [diff] [blame] | 318 | dist.clear() |
| 319 | |
| 320 | countdown -= 1 |
| 321 | if exiting or countdown == 0: |
| 322 | exit() |