blob: b862bad27c52645d071e12e214577c80f125ba80 [file] [log] [blame]
Brendan Gregg3f3acd82016-12-21 15:34:09 -08001#!/usr/bin/python
2# @lint-avoid-python-3-compatibility-imports
3#
4# cpuunclaimed Sample CPU run queues and calculate unclaimed idle CPU.
5# For Linux, uses BCC, eBPF.
6#
7# This samples the length of the run queues and determine when there are idle
8# CPUs, yet queued threads waiting their turn. Report the amount of idle
9# (yet unclaimed by waiting threads) CPU as a system-wide percentage.
10#
11# This situation can happen for a number of reasons:
12#
13# - An application has been bound to some, but not all, CPUs, and has runnable
14# threads that cannot migrate to other CPUs due to this configuration.
15# - CPU affinity: an optimization that leaves threads on CPUs where the CPU
16# caches are warm, even if this means short periods of waiting while other
17# CPUs are idle. The wait period is tunale (see sysctl, kernel.sched*).
18# - Scheduler bugs.
19#
20# An unclaimed idle of < 1% is likely to be CPU affinity, and not usually a
21# cause for concern. By leaving the CPU idle, overall throughput of the system
22# may be improved. This tool is best for identifying larger issues, > 2%, due
23# to the coarseness of its 99 Hertz samples.
24#
25# This is an experimental tool that currently works by use of sampling to
26# keep overheads low. Tool assumptions:
27#
28# - CPU samples consistently fire around the same offset. There will sometimes
29# be a lag as a sample is delayed by higher-priority interrupts, but it is
30# assumed the subsequent samples will catch up to the expected offsets (as
31# is seen in practice). You can use -J to inspect sample offsets. Some
32# systems can power down CPUs when idle, and when they wake up again they
33# may begin firing at a skewed offset: this tool will detect the skew, print
34# an error, and exit.
35# - All CPUs are online (see ncpu).
36#
37# If this identifies unclaimed CPU, you can double check it by dumping raw
38# samples (-j), as well as using other tracing tools to instrument scheduler
39# events (although this latter approach has much higher overhead).
40#
41# This tool passes all sampled events to user space for post processing.
42# I originally wrote this to do the calculations entirerly in kernel context,
43# and only pass a summary. That involves a number of challenges, and the
44# overhead savings may not outweigh the caveats. You can see my WIP here:
45# https://gist.github.com/brendangregg/731cf2ce54bf1f9a19d4ccd397625ad9
46#
47# USAGE: cpuunclaimed [-h] [-j] [-J] [-T] [interval] [count]
48#
49# If you see "Lost 1881 samples" warnings, try increasing wakeup_hz.
50#
51# REQUIRES: Linux 4.9+ (BPF_PROG_TYPE_PERF_EVENT support). Under tools/old is
52# a version of this tool that may work on Linux 4.6 - 4.8.
53#
54# Copyright 2016 Netflix, Inc.
55# Licensed under the Apache License, Version 2.0 (the "License")
56#
57# 20-Dec-2016 Brendan Gregg Created this.
58
59from __future__ import print_function
60from bcc import BPF, PerfType, PerfSWConfig
61from time import sleep, strftime
62from ctypes import c_int
63import argparse
64import multiprocessing
65from os import getpid, system
66import ctypes as ct
67
68# arguments
69examples = """examples:
70 ./cpuunclaimed # sample and calculate unclaimed idle CPUs,
71 # output every 1 second (default)
72 ./cpuunclaimed 5 10 # print 5 second summaries, 10 times
73 ./cpuunclaimed -T 1 # 1s summaries and timestamps
74 ./cpuunclaimed -j # raw dump of all samples (verbose), CSV
75"""
76parser = argparse.ArgumentParser(
77 description="Sample CPU run queues and calculate unclaimed idle CPU",
78 formatter_class=argparse.RawDescriptionHelpFormatter,
79 epilog=examples)
80parser.add_argument("-j", "--csv", action="store_true",
81 help="print sample summaries (verbose) as comma-separated values")
82parser.add_argument("-J", "--fullcsv", action="store_true",
83 help="print sample summaries with extra fields: CPU sample offsets")
84parser.add_argument("-T", "--timestamp", action="store_true",
85 help="include timestamp on output")
86parser.add_argument("interval", nargs="?", default=-1,
87 help="output interval, in seconds")
88parser.add_argument("count", nargs="?", default=99999999,
89 help="number of outputs")
Nathan Scottcf0792f2018-02-02 16:56:50 +110090parser.add_argument("--ebpf", action="store_true",
91 help=argparse.SUPPRESS)
Brendan Gregg3f3acd82016-12-21 15:34:09 -080092args = parser.parse_args()
93countdown = int(args.count)
94frequency = 99
95dobind = 1
96wakeup_hz = 10 # frequency to read buffers
97wakeup_s = float(1) / wakeup_hz
98ncpu = multiprocessing.cpu_count() # assume all are online
99debug = 0
100
101# process arguments
102if args.fullcsv:
103 args.csv = True
104if args.csv:
105 interval = 0.2
106if args.interval != -1 and (args.fullcsv or args.csv):
107 print("ERROR: cannot use interval with either -j or -J. Exiting.")
108 exit()
109if args.interval == -1:
110 args.interval = "1"
111interval = float(args.interval)
112
113# define BPF program
114bpf_text = """
115#include <uapi/linux/ptrace.h>
116#include <uapi/linux/bpf_perf_event.h>
117#include <linux/sched.h>
118
119struct data_t {
120 u64 ts;
121 u64 cpu;
122 u64 len;
123};
124
125BPF_PERF_OUTPUT(events);
126
127// Declare enough of cfs_rq to find nr_running, since we can't #import the
128// header. This will need maintenance. It is from kernel/sched/sched.h:
129struct cfs_rq_partial {
130 struct load_weight load;
131 unsigned int nr_running, h_nr_running;
132};
133
134int do_perf_event(struct bpf_perf_event_data *ctx)
135{
136 int cpu = bpf_get_smp_processor_id();
137 u64 now = bpf_ktime_get_ns();
138
139 /*
140 * Fetch the run queue length from task->se.cfs_rq->nr_running. This is an
141 * unstable interface and may need maintenance. Perhaps a future version
142 * of BPF will support task_rq(p) or something similar as a more reliable
143 * interface.
144 */
145 unsigned int len = 0;
146 struct task_struct *task = NULL;
147 struct cfs_rq_partial *my_q = NULL;
148 task = (struct task_struct *)bpf_get_current_task();
Paul Chaignon719e1002017-08-06 14:33:20 +0200149 my_q = (struct cfs_rq_partial *)task->se.cfs_rq;
150 len = my_q->nr_running;
Brendan Gregg3f3acd82016-12-21 15:34:09 -0800151
152 struct data_t data = {.ts = now, .cpu = cpu, .len = len};
153 events.perf_submit(ctx, &data, sizeof(data));
154
155 return 0;
156}
157"""
158
159# code substitutions
Nathan Scottcf0792f2018-02-02 16:56:50 +1100160if debug or args.ebpf:
Brendan Gregg3f3acd82016-12-21 15:34:09 -0800161 print(bpf_text)
Nathan Scottcf0792f2018-02-02 16:56:50 +1100162 if args.ebpf:
163 exit()
Brendan Gregg3f3acd82016-12-21 15:34:09 -0800164
165# initialize BPF & perf_events
166b = BPF(text=bpf_text)
167# TODO: check for HW counters first and use if more accurate
168b.attach_perf_event(ev_type=PerfType.SOFTWARE,
169 ev_config=PerfSWConfig.TASK_CLOCK, fn_name="do_perf_event",
170 sample_period=0, sample_freq=frequency)
171
172if args.csv:
173 if args.timestamp:
174 print("TIME", end=",")
175 print("TIMESTAMP_ns", end=",")
Rafael Fd7a5ff02017-03-03 19:57:28 +0100176 print(",".join("CPU" + str(c) for c in range(ncpu)), end="")
Brendan Gregg3f3acd82016-12-21 15:34:09 -0800177 if args.fullcsv:
178 print(",", end="")
Rafael Fd7a5ff02017-03-03 19:57:28 +0100179 print(",".join("OFFSET_ns_CPU" + str(c) for c in range(ncpu)), end="")
Brendan Gregg3f3acd82016-12-21 15:34:09 -0800180 print()
181else:
182 print(("Sampling run queues... Output every %s seconds. " +
183 "Hit Ctrl-C to end.") % args.interval)
184class Data(ct.Structure):
185 _fields_ = [
186 ("ts", ct.c_ulonglong),
187 ("cpu", ct.c_ulonglong),
188 ("len", ct.c_ulonglong)
189 ]
190
191samples = {}
192group = {}
193last = 0
194
195# process event
196def print_event(cpu, data, size):
197 event = ct.cast(data, ct.POINTER(Data)).contents
198 samples[event.ts] = {}
199 samples[event.ts]['cpu'] = event.cpu
200 samples[event.ts]['len'] = event.len
201
202exiting = 0 if args.interval else 1
203slept = float(0)
204
205# Choose the elapsed time from one sample group to the next that identifies a
206# new sample group (a group being a set of samples from all CPUs). The
207# earliest timestamp is compared in each group. This trigger is also used
208# for sanity testing, if a group's samples exceed half this value.
209trigger = int(0.8 * (1000000000 / frequency))
210
211# read events
Mark Drayton5f5687e2017-02-20 18:13:03 +0000212b["events"].open_perf_buffer(print_event, page_cnt=64)
Brendan Gregg3f3acd82016-12-21 15:34:09 -0800213while 1:
214 # allow some buffering by calling sleep(), to reduce the context switch
215 # rate and lower overhead.
216 try:
217 if not exiting:
218 sleep(wakeup_s)
219 except KeyboardInterrupt:
220 exiting = 1
Teng Qindbf00292018-02-28 21:47:50 -0800221 b.perf_buffer_poll()
Brendan Gregg3f3acd82016-12-21 15:34:09 -0800222 slept += wakeup_s
223
224 if slept < 0.999 * interval: # floating point workaround
225 continue
226 slept = 0
227
228 positive = 0 # number of samples where an idle CPU could have run work
229 running = 0
230 idle = 0
231 if debug >= 2:
232 print("DEBUG: begin samples loop, count %d" % len(samples))
233 for e in sorted(samples):
234 if debug >= 2:
235 print("DEBUG: ts %d cpu %d len %d delta %d trig %d" % (e,
236 samples[e]['cpu'], samples[e]['len'], e - last,
237 e - last > trigger))
238
239 # look for time jumps to identify a new sample group
240 if e - last > trigger:
241
242 # first first group timestamp, and sanity test
243 g_time = 0
244 g_max = 0
245 for ge in sorted(group):
246 if g_time == 0:
247 g_time = ge
248 g_max = ge
249
250 # process previous sample group
251 if args.csv:
252 lens = [0] * ncpu
253 offs = [0] * ncpu
254 for ge in sorted(group):
255 lens[samples[ge]['cpu']] = samples[ge]['len']
256 if args.fullcsv:
257 offs[samples[ge]['cpu']] = ge - g_time
258 if g_time > 0: # else first sample
259 if args.timestamp:
260 print("%-8s" % strftime("%H:%M:%S"), end=",")
261 print("%d" % g_time, end=",")
Rafael Fd7a5ff02017-03-03 19:57:28 +0100262 print(",".join(str(lens[c]) for c in range(ncpu)), end="")
Brendan Gregg3f3acd82016-12-21 15:34:09 -0800263 if args.fullcsv:
264 print(",", end="")
Rafael Fd7a5ff02017-03-03 19:57:28 +0100265 print(",".join(str(offs[c]) for c in range(ncpu)))
Brendan Gregg3f3acd82016-12-21 15:34:09 -0800266 else:
267 print()
268 else:
269 # calculate stats
270 g_running = 0
271 g_queued = 0
272 for ge in group:
273 if samples[ge]['len'] > 0:
274 g_running += 1
275 if samples[ge]['len'] > 1:
276 g_queued += samples[ge]['len'] - 1
277 g_idle = ncpu - g_running
278
279 # calculate the number of threads that could have run as the
280 # minimum of idle and queued
281 if g_idle > 0 and g_queued > 0:
282 if g_queued > g_idle:
283 i = g_idle
284 else:
285 i = g_queued
286 positive += i
287 running += g_running
288 idle += g_idle
289
290 # now sanity test, after -J output
291 g_range = g_max - g_time
292 if g_range > trigger / 2:
293 # if a sample group exceeds half the interval, we can no
294 # longer draw conclusions about some CPUs idle while others
295 # have queued work. Error and exit. This can happen when
296 # CPUs power down, then start again on different offsets.
297 # TODO: Since this is a sampling tool, an error margin should
298 # be anticipated, so an improvement may be to bump a counter
299 # instead of exiting, and only exit if this counter shows
300 # a skewed sample rate of over, say, 1%. Such an approach
301 # would allow a small rate of outliers (sampling error),
302 # and, we could tighten the trigger to be, say, trigger / 5.
303 # In the case of a power down, if it's detectable, perhaps
304 # the tool could reinitialize the timers (although exiting
305 # is simple and works).
306 print(("ERROR: CPU samples arrived at skewed offsets " +
307 "(CPUs may have powered down when idle), " +
308 "spanning %d ns (expected < %d ns). Debug with -J, " +
309 "and see the man page. As output may begin to be " +
310 "unreliable, exiting.") % (g_range, trigger / 2))
311 exit()
312
313 # these are done, remove
314 for ge in sorted(group):
315 del samples[ge]
316
317 # begin next group
318 group = {}
319 last = e
320
321 # stash this timestamp in a sample group dict
322 group[e] = 1
323
324 if not args.csv:
325 total = running + idle
326 unclaimed = util = 0
327
328 if debug:
329 print("DEBUG: hit %d running %d idle %d total %d buffered %d" % (
330 positive, running, idle, total, len(samples)))
331
332 if args.timestamp:
333 print("%-8s " % strftime("%H:%M:%S"), end="")
334
335 # output
336 if total:
337 unclaimed = float(positive) / total
338 util = float(running) / total
339 print("%%CPU %6.2f%%, unclaimed idle %0.2f%%" % (100 * util,
340 100 * unclaimed))
341
342 countdown -= 1
343 if exiting or countdown == 0:
344 exit()