1#!/usr/bin/env 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#
7# USAGE: runqlat [-h] [-T] [-m] [-P] [-L] [-p PID] [interval] [count]
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
15#    and execution. This traces ttwu_do_wakeup(), wake_up_new_task() ->
16#    finish_task_switch() with either raw tracepoints (if supported) or kprobes
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
27from __future__ import print_function
28from bcc import BPF
29from time import sleep, strftime
30import argparse
31
32# arguments
33examples = """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"""
40parser = argparse.ArgumentParser(
41    description="Summarize run queue (scheduler) latency as a histogram",
42    formatter_class=argparse.RawDescriptionHelpFormatter,
43    epilog=examples)
44parser.add_argument("-T", "--timestamp", action="store_true",
45    help="include timestamp on output")
46parser.add_argument("-m", "--milliseconds", action="store_true",
47    help="millisecond histogram")
48parser.add_argument("-P", "--pids", action="store_true",
49    help="print a histogram per process ID")
50# PID options are --pid and --pids, so namespaces should be --pidns (not done
51# yet) and --pidnss:
52parser.add_argument("--pidnss", action="store_true",
53    help="print a histogram per PID namespace")
54parser.add_argument("-L", "--tids", action="store_true",
55    help="print a histogram per thread ID")
56parser.add_argument("-p", "--pid",
57    help="trace this PID only")
58parser.add_argument("interval", nargs="?", default=99999999,
59    help="output interval, in seconds")
60parser.add_argument("count", nargs="?", default=99999999,
61    help="number of outputs")
62parser.add_argument("--ebpf", action="store_true",
63    help=argparse.SUPPRESS)
64args = parser.parse_args()
65countdown = int(args.count)
66debug = 0
67
68# define BPF program
69bpf_text = """
70#include <uapi/linux/ptrace.h>
71#include <linux/sched.h>
72#include <linux/nsproxy.h>
73#include <linux/pid_namespace.h>
74
75typedef struct pid_key {
76    u64 id;    // work around
77    u64 slot;
78} pid_key_t;
79
80typedef struct pidns_key {
81    u64 id;    // work around
82    u64 slot;
83} pidns_key_t;
84
85BPF_HASH(start, u32);
86STORAGE
87
88struct rq;
89
90// record enqueue timestamp
91static int trace_enqueue(u32 tgid, u32 pid)
92{
93    if (FILTER || pid == 0)
94        return 0;
95    u64 ts = bpf_ktime_get_ns();
96    start.update(&pid, &ts);
97    return 0;
98}
99"""
100
101bpf_text_kprobe = """
102int trace_wake_up_new_task(struct pt_regs *ctx, struct task_struct *p)
103{
104    return trace_enqueue(p->tgid, p->pid);
105}
106
107int 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
113// calculate latency
114int trace_run(struct pt_regs *ctx, struct task_struct *prev)
115{
116    u32 pid, tgid;
117
118    // ivcsw: treat like an enqueue event and store timestamp
119    if (prev->state == TASK_RUNNING) {
120        tgid = prev->tgid;
121        pid = prev->pid;
122        if (!(FILTER || pid == 0)) {
123            u64 ts = bpf_ktime_get_ns();
124            start.update(&pid, &ts);
125        }
126    }
127
128    tgid = bpf_get_current_pid_tgid() >> 32;
129    pid = bpf_get_current_pid_tgid();
130    if (FILTER || pid == 0)
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
150bpf_text_raw_tp = """
151RAW_TRACEPOINT_PROBE(sched_wakeup)
152{
153    // TP_PROTO(struct task_struct *p)
154    struct task_struct *p = (struct task_struct *)ctx->args[0];
155    return trace_enqueue(p->tgid, p->pid);
156}
157
158RAW_TRACEPOINT_PROBE(sched_wakeup_new)
159{
160    // TP_PROTO(struct task_struct *p)
161    struct task_struct *p = (struct task_struct *)ctx->args[0];
162    return trace_enqueue(p->tgid, p->pid);
163}
164
165RAW_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];
169    struct task_struct *next = (struct task_struct *)ctx->args[2];
170    u32 pid, tgid;
171
172    // ivcsw: treat like an enqueue event and store timestamp
173    if (prev->state == TASK_RUNNING) {
174        tgid = prev->tgid;
175        pid = prev->pid;
176        if (!(FILTER || pid == 0)) {
177            u64 ts = bpf_ktime_get_ns();
178            start.update(&pid, &ts);
179        }
180    }
181
182    tgid = next->tgid;
183    pid = next->pid;
184    if (FILTER || pid == 0)
185        return 0;
186    u64 *tsp, delta;
187
188    // fetch timestamp and calculate delta
189    tsp = start.lookup(&pid);
190    if (tsp == 0) {
191        return 0;   // missed enqueue
192    }
193    delta = bpf_ktime_get_ns() - *tsp;
194    FACTOR
195
196    // store as histogram
197    STORE
198
199    start.delete(&pid);
200    return 0;
201}
202"""
203
204is_support_raw_tp = BPF.support_raw_tracepoint()
205if is_support_raw_tp:
206    bpf_text += bpf_text_raw_tp
207else:
208    bpf_text += bpf_text_kprobe
209
210# code substitutions
211if args.pid:
212    # pid from userspace point of view is thread group from kernel pov
213    bpf_text = bpf_text.replace('FILTER', 'tgid != %s' % args.pid)
214else:
215    bpf_text = bpf_text.replace('FILTER', '0')
216if args.milliseconds:
217    bpf_text = bpf_text.replace('FACTOR', 'delta /= 1000000;')
218    label = "msecs"
219else:
220    bpf_text = bpf_text.replace('FACTOR', 'delta /= 1000;')
221    label = "usecs"
222if args.pids or args.tids:
223    section = "pid"
224    pid = "tgid"
225    if args.tids:
226        pid = "pid"
227        section = "tid"
228    bpf_text = bpf_text.replace('STORAGE',
229        'BPF_HISTOGRAM(dist, pid_key_t);')
230    bpf_text = bpf_text.replace('STORE',
231        'pid_key_t key = {.id = ' + pid + ', .slot = bpf_log2l(delta)}; ' +
232        'dist.increment(key);')
233elif args.pidnss:
234    section = "pidns"
235    bpf_text = bpf_text.replace('STORAGE',
236        'BPF_HISTOGRAM(dist, pidns_key_t);')
237    bpf_text = bpf_text.replace('STORE', 'pidns_key_t key = ' +
238        '{.id = prev->nsproxy->pid_ns_for_children->ns.inum, ' +
239        '.slot = bpf_log2l(delta)}; dist.increment(key);')
240else:
241    section = ""
242    bpf_text = bpf_text.replace('STORAGE', 'BPF_HISTOGRAM(dist);')
243    bpf_text = bpf_text.replace('STORE',
244        'dist.increment(bpf_log2l(delta));')
245if debug or args.ebpf:
246    print(bpf_text)
247    if args.ebpf:
248        exit()
249
250# load BPF program
251b = BPF(text=bpf_text)
252if not is_support_raw_tp:
253    b.attach_kprobe(event="ttwu_do_wakeup", fn_name="trace_ttwu_do_wakeup")
254    b.attach_kprobe(event="wake_up_new_task", fn_name="trace_wake_up_new_task")
255    b.attach_kprobe(event="finish_task_switch", fn_name="trace_run")
256
257print("Tracing run queue latency... Hit Ctrl-C to end.")
258
259# output
260exiting = 0 if args.interval else 1
261dist = b.get_table("dist")
262while (1):
263    try:
264        sleep(int(args.interval))
265    except KeyboardInterrupt:
266        exiting = 1
267
268    print()
269    if args.timestamp:
270        print("%-8s\n" % strftime("%H:%M:%S"), end="")
271
272    dist.print_log2_hist(label, section, section_print_fn=int)
273    dist.clear()
274
275    countdown -= 1
276    if exiting or countdown == 0:
277        exit()
278