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