1#!/usr/bin/python 2# 3# offwaketime Summarize blocked time by kernel off-CPU stack + waker stack 4# For Linux, uses BCC, eBPF. 5# 6# USAGE: offwaketime [-h] [-p PID | -u | -k] [-U | -K] [-f] [duration] 7# 8# Copyright 2016 Netflix, Inc. 9# Licensed under the Apache License, Version 2.0 (the "License") 10# 11# 20-Jan-2016 Brendan Gregg Created this. 12 13from __future__ import print_function 14from bcc import BPF 15from time import sleep 16import argparse 17import signal 18import errno 19from sys import stderr 20 21# arg validation 22def positive_int(val): 23 try: 24 ival = int(val) 25 except ValueError: 26 raise argparse.ArgumentTypeError("must be an integer") 27 28 if ival < 0: 29 raise argparse.ArgumentTypeError("must be positive") 30 return ival 31 32def positive_nonzero_int(val): 33 ival = positive_int(val) 34 if ival == 0: 35 raise argparse.ArgumentTypeError("must be nonzero") 36 return ival 37 38def stack_id_err(stack_id): 39 # -EFAULT in get_stackid normally means the stack-trace is not availible, 40 # Such as getting kernel stack trace in userspace code 41 return (stack_id < 0) and (stack_id != -errno.EFAULT) 42 43# arguments 44examples = """examples: 45 ./offwaketime # trace off-CPU + waker stack time until Ctrl-C 46 ./offwaketime 5 # trace for 5 seconds only 47 ./offwaketime -f 5 # 5 seconds, and output in folded format 48 ./offwaketime -m 1000 # trace only events that last more than 1000 usec 49 ./offwaketime -M 9000 # trace only events that last less than 9000 usec 50 ./offwaketime -p 185 # only trace threads for PID 185 51 ./offwaketime -t 188 # only trace thread 188 52 ./offwaketime -u # only trace user threads (no kernel) 53 ./offwaketime -k # only trace kernel threads (no user) 54 ./offwaketime -U # only show user space stacks (no kernel) 55 ./offwaketime -K # only show kernel space stacks (no user) 56""" 57parser = argparse.ArgumentParser( 58 description="Summarize blocked time by kernel stack trace + waker stack", 59 formatter_class=argparse.RawDescriptionHelpFormatter, 60 epilog=examples) 61thread_group = parser.add_mutually_exclusive_group() 62# Note: this script provides --pid and --tid flags but their arguments are 63# referred to internally using kernel nomenclature: TGID and PID. 64thread_group.add_argument("-p", "--pid", metavar="PID", dest="tgid", 65 help="trace this PID only", type=positive_int) 66thread_group.add_argument("-t", "--tid", metavar="TID", dest="pid", 67 help="trace this TID only", type=positive_int) 68thread_group.add_argument("-u", "--user-threads-only", action="store_true", 69 help="user threads only (no kernel threads)") 70thread_group.add_argument("-k", "--kernel-threads-only", action="store_true", 71 help="kernel threads only (no user threads)") 72stack_group = parser.add_mutually_exclusive_group() 73stack_group.add_argument("-U", "--user-stacks-only", action="store_true", 74 help="show stacks from user space only (no kernel space stacks)") 75stack_group.add_argument("-K", "--kernel-stacks-only", action="store_true", 76 help="show stacks from kernel space only (no user space stacks)") 77parser.add_argument("-d", "--delimited", action="store_true", 78 help="insert delimiter between kernel/user stacks") 79parser.add_argument("-f", "--folded", action="store_true", 80 help="output folded format") 81parser.add_argument("--stack-storage-size", default=1024, 82 type=positive_nonzero_int, 83 help="the number of unique stack traces that can be stored and " 84 "displayed (default 1024)") 85parser.add_argument("duration", nargs="?", default=99999999, 86 type=positive_nonzero_int, 87 help="duration of trace, in seconds") 88parser.add_argument("-m", "--min-block-time", default=1, 89 type=positive_nonzero_int, 90 help="the amount of time in microseconds over which we " + 91 "store traces (default 1)") 92parser.add_argument("-M", "--max-block-time", default=(1 << 64) - 1, 93 type=positive_nonzero_int, 94 help="the amount of time in microseconds under which we " + 95 "store traces (default U64_MAX)") 96parser.add_argument("--ebpf", action="store_true", 97 help=argparse.SUPPRESS) 98args = parser.parse_args() 99folded = args.folded 100duration = int(args.duration) 101 102# signal handler 103def signal_ignore(signal, frame): 104 print() 105 106# define BPF program 107bpf_text = """ 108#include <uapi/linux/ptrace.h> 109#include <linux/sched.h> 110 111#define MINBLOCK_US MINBLOCK_US_VALUEULL 112#define MAXBLOCK_US MAXBLOCK_US_VALUEULL 113 114struct key_t { 115 char waker[TASK_COMM_LEN]; 116 char target[TASK_COMM_LEN]; 117 int w_k_stack_id; 118 int w_u_stack_id; 119 int t_k_stack_id; 120 int t_u_stack_id; 121 u32 t_pid; 122 u32 t_tgid; 123 u32 w_pid; 124 u32 w_tgid; 125}; 126BPF_HASH(counts, struct key_t); 127 128// Key of this hash is PID of waiting Process, 129// value is timestamp when it went into waiting 130BPF_HASH(start, u32); 131 132struct wokeby_t { 133 char name[TASK_COMM_LEN]; 134 int k_stack_id; 135 int u_stack_id; 136 int w_pid; 137 int w_tgid; 138}; 139// Key of the hash is PID of the Process to be waken, value is information 140// of the Process who wakes it 141BPF_HASH(wokeby, u32, struct wokeby_t); 142 143BPF_STACK_TRACE(stack_traces, STACK_STORAGE_SIZE); 144 145int waker(struct pt_regs *ctx, struct task_struct *p) { 146 // PID and TGID of the target Process to be waken 147 u32 pid = p->pid; 148 u32 tgid = p->tgid; 149 150 if (!(THREAD_FILTER)) { 151 return 0; 152 } 153 154 // Construct information about current (the waker) Process 155 struct wokeby_t woke = {}; 156 bpf_get_current_comm(&woke.name, sizeof(woke.name)); 157 woke.k_stack_id = KERNEL_STACK_GET; 158 woke.u_stack_id = USER_STACK_GET; 159 woke.w_pid = bpf_get_current_pid_tgid(); 160 woke.w_tgid = bpf_get_current_pid_tgid() >> 32; 161 162 wokeby.update(&pid, &woke); 163 return 0; 164} 165 166int oncpu(struct pt_regs *ctx, struct task_struct *p) { 167 // PID and TGID of the previous Process (Process going into waiting) 168 u32 pid = p->pid; 169 u32 tgid = p->tgid; 170 u64 *tsp; 171 u64 ts = bpf_ktime_get_ns(); 172 173 // Record timestamp for the previous Process (Process going into waiting) 174 if (THREAD_FILTER) { 175 start.update(&pid, &ts); 176 } 177 178 // Calculate current Process's wait time by finding the timestamp of when 179 // it went into waiting. 180 // pid and tgid are now the PID and TGID of the current (waking) Process. 181 pid = bpf_get_current_pid_tgid(); 182 tgid = bpf_get_current_pid_tgid() >> 32; 183 tsp = start.lookup(&pid); 184 if (tsp == 0) { 185 // Missed or filtered when the Process went into waiting 186 return 0; 187 } 188 u64 delta = ts - *tsp; 189 start.delete(&pid); 190 delta = delta / 1000; 191 if ((delta < MINBLOCK_US) || (delta > MAXBLOCK_US)) { 192 return 0; 193 } 194 195 // create map key 196 struct key_t key = {}; 197 struct wokeby_t *woke; 198 199 bpf_get_current_comm(&key.target, sizeof(key.target)); 200 key.t_pid = pid; 201 key.t_tgid = tgid; 202 key.t_k_stack_id = KERNEL_STACK_GET; 203 key.t_u_stack_id = USER_STACK_GET; 204 205 woke = wokeby.lookup(&pid); 206 if (woke) { 207 key.w_k_stack_id = woke->k_stack_id; 208 key.w_u_stack_id = woke->u_stack_id; 209 key.w_pid = woke->w_pid; 210 key.w_tgid = woke->w_tgid; 211 __builtin_memcpy(&key.waker, woke->name, TASK_COMM_LEN); 212 wokeby.delete(&pid); 213 } 214 215 counts.increment(key, delta); 216 return 0; 217} 218""" 219 220# set thread filter 221thread_context = "" 222if args.tgid is not None: 223 thread_context = "PID %d" % args.tgid 224 thread_filter = 'tgid == %d' % args.tgid 225elif args.pid is not None: 226 thread_context = "TID %d" % args.pid 227 thread_filter = 'pid == %d' % args.pid 228elif args.user_threads_only: 229 thread_context = "user threads" 230 thread_filter = '!(p->flags & PF_KTHREAD)' 231elif args.kernel_threads_only: 232 thread_context = "kernel threads" 233 thread_filter = 'p->flags & PF_KTHREAD' 234else: 235 thread_context = "all threads" 236 thread_filter = '1' 237bpf_text = bpf_text.replace('THREAD_FILTER', thread_filter) 238 239# set stack storage size 240bpf_text = bpf_text.replace('STACK_STORAGE_SIZE', str(args.stack_storage_size)) 241bpf_text = bpf_text.replace('MINBLOCK_US_VALUE', str(args.min_block_time)) 242bpf_text = bpf_text.replace('MAXBLOCK_US_VALUE', str(args.max_block_time)) 243 244# handle stack args 245kernel_stack_get = "stack_traces.get_stackid(ctx, 0)" 246user_stack_get = "stack_traces.get_stackid(ctx, BPF_F_USER_STACK)" 247stack_context = "" 248if args.user_stacks_only: 249 stack_context = "user" 250 kernel_stack_get = "-1" 251elif args.kernel_stacks_only: 252 stack_context = "kernel" 253 user_stack_get = "-1" 254else: 255 stack_context = "user + kernel" 256bpf_text = bpf_text.replace('USER_STACK_GET', user_stack_get) 257bpf_text = bpf_text.replace('KERNEL_STACK_GET', kernel_stack_get) 258if args.ebpf: 259 print(bpf_text) 260 exit() 261 262# initialize BPF 263b = BPF(text=bpf_text) 264b.attach_kprobe(event="finish_task_switch", fn_name="oncpu") 265b.attach_kprobe(event="try_to_wake_up", fn_name="waker") 266matched = b.num_open_kprobes() 267if matched == 0: 268 print("0 functions traced. Exiting.") 269 exit() 270 271# header 272if not folded: 273 print("Tracing blocked time (us) by %s off-CPU and waker stack" % 274 stack_context, end="") 275 if duration < 99999999: 276 print(" for %d secs." % duration) 277 else: 278 print("... Hit Ctrl-C to end.") 279 280try: 281 sleep(duration) 282except KeyboardInterrupt: 283 # as cleanup can take many seconds, trap Ctrl-C: 284 # print a newline for folded output on Ctrl-C 285 signal.signal(signal.SIGINT, signal_ignore) 286 287 288if not folded: 289 print() 290 291missing_stacks = 0 292has_enomem = False 293counts = b.get_table("counts") 294stack_traces = b.get_table("stack_traces") 295need_delimiter = args.delimited and not (args.kernel_stacks_only or 296 args.user_stacks_only) 297for k, v in sorted(counts.items(), key=lambda counts: counts[1].value): 298 # handle get_stackid errors 299 if not args.user_stacks_only: 300 missing_stacks += int(stack_id_err(k.w_k_stack_id)) 301 missing_stacks += int(stack_id_err(k.t_k_stack_id)) 302 has_enomem = has_enomem or (k.w_k_stack_id == -errno.ENOMEM) or \ 303 (k.t_k_stack_id == -errno.ENOMEM) 304 if not args.kernel_stacks_only: 305 missing_stacks += int(stack_id_err(k.w_u_stack_id)) 306 missing_stacks += int(stack_id_err(k.t_u_stack_id)) 307 has_enomem = has_enomem or (k.w_u_stack_id == -errno.ENOMEM) or \ 308 (k.t_u_stack_id == -errno.ENOMEM) 309 310 waker_user_stack = [] if k.w_u_stack_id < 1 else \ 311 reversed(list(stack_traces.walk(k.w_u_stack_id))[1:]) 312 waker_kernel_stack = [] if k.w_k_stack_id < 1 else \ 313 reversed(list(stack_traces.walk(k.w_k_stack_id))[1:]) 314 target_user_stack = [] if k.t_u_stack_id < 1 else \ 315 stack_traces.walk(k.t_u_stack_id) 316 target_kernel_stack = [] if k.t_k_stack_id < 1 else \ 317 stack_traces.walk(k.t_k_stack_id) 318 319 if folded: 320 # print folded stack output 321 line = [k.target.decode('utf-8', 'replace')] 322 if not args.kernel_stacks_only: 323 if stack_id_err(k.t_u_stack_id): 324 line.append("[Missed User Stack]") 325 else: 326 line.extend([b.sym(addr, k.t_tgid) 327 for addr in reversed(list(target_user_stack)[1:])]) 328 if not args.user_stacks_only: 329 line.extend(["-"] if (need_delimiter and k.t_k_stack_id > 0 and k.t_u_stack_id > 0) else []) 330 if stack_id_err(k.t_k_stack_id): 331 line.append("[Missed Kernel Stack]") 332 else: 333 line.extend([b.ksym(addr) 334 for addr in reversed(list(target_kernel_stack)[1:])]) 335 line.append("--") 336 if not args.user_stacks_only: 337 if stack_id_err(k.w_k_stack_id): 338 line.append("[Missed Kernel Stack]") 339 else: 340 line.extend([b.ksym(addr) 341 for addr in reversed(list(waker_kernel_stack))]) 342 if not args.kernel_stacks_only: 343 line.extend(["-"] if (need_delimiter and k.w_u_stack_id > 0 and k.w_k_stack_id > 0) else []) 344 if stack_id_err(k.w_u_stack_id): 345 line.extend("[Missed User Stack]") 346 else: 347 line.extend([b.sym(addr, k.w_tgid) 348 for addr in reversed(list(waker_user_stack))]) 349 line.append(k.waker.decode('utf-8', 'replace')) 350 print("%s %d" % (";".join(line), v.value)) 351 else: 352 # print wakeup name then stack in reverse order 353 print(" %-16s %s %s" % ("waker:", k.waker.decode('utf-8', 'replace'), k.t_pid)) 354 if not args.kernel_stacks_only: 355 if stack_id_err(k.w_u_stack_id): 356 print(" [Missed User Stack]") 357 else: 358 for addr in waker_user_stack: 359 print(" %s" % b.sym(addr, k.w_tgid)) 360 if not args.user_stacks_only: 361 if need_delimiter and k.w_u_stack_id > 0 and k.w_k_stack_id > 0: 362 print(" -") 363 if stack_id_err(k.w_k_stack_id): 364 print(" [Missed Kernel Stack]") 365 else: 366 for addr in waker_kernel_stack: 367 print(" %s" % b.ksym(addr)) 368 369 # print waker/wakee delimiter 370 print(" %-16s %s" % ("--", "--")) 371 372 if not args.user_stacks_only: 373 if stack_id_err(k.t_k_stack_id): 374 print(" [Missed Kernel Stack]") 375 else: 376 for addr in target_kernel_stack: 377 print(" %s" % b.ksym(addr)) 378 if not args.kernel_stacks_only: 379 if need_delimiter and k.t_u_stack_id > 0 and k.t_k_stack_id > 0: 380 print(" -") 381 if stack_id_err(k.t_u_stack_id): 382 print(" [Missed User Stack]") 383 else: 384 for addr in target_user_stack: 385 print(" %s" % b.sym(addr, k.t_tgid)) 386 print(" %-16s %s %s" % ("target:", k.target.decode('utf-8', 'replace'), k.w_pid)) 387 print(" %d\n" % v.value) 388 389if missing_stacks > 0: 390 enomem_str = " Consider increasing --stack-storage-size." 391 print("WARNING: %d stack traces lost and could not be displayed.%s" % 392 (missing_stacks, (enomem_str if has_enomem else "")), 393 file=stderr) 394