1#!/usr/bin/env python 2# @lint-avoid-python-3-compatibility-imports 3# 4# funcinterval Time interval between the same function, tracepoint 5# as a histogram. 6# 7# USAGE: funcinterval [-h] [-p PID] [-i INTERVAL] [-T] [-u] [-m] [-v] pattern 8# 9# Run "funcinterval -h" for full usage. 10# 11# Copyright (c) 2020 Realtek, Inc. 12# Licensed under the Apache License, Version 2.0 (the "License") 13# 14# 03-Jun-2020 Edward Wu Referenced funclatency and created this. 15 16from __future__ import print_function 17from bcc import BPF 18from time import sleep, strftime 19import argparse 20import signal 21 22# arguments 23examples = """examples: 24 # time the interval of do_sys_open() 25 ./funcinterval do_sys_open 26 # time the interval of xhci_ring_ep_doorbell(), in microseconds 27 ./funcinterval -u xhci_ring_ep_doorbell 28 # time the interval of do_nanosleep(), in milliseconds 29 ./funcinterval -m do_nanosleep 30 # output every 5 seconds, with timestamps 31 ./funcinterval -mTi 5 vfs_read 32 # time process 181 only 33 ./funcinterval -p 181 vfs_read 34 # time the interval of mm_vmscan_direct_reclaim_begin tracepoint 35 ./funcinterval t:vmscan:mm_vmscan_direct_reclaim_begin 36 # time the interval of c:malloc used by top every 3 seconds 37 ./funcinterval -p `pidof -s top` -i 3 c:malloc 38 # time /usr/local/bin/python main function 39 ./funcinterval /usr/local/bin/python:main 40""" 41parser = argparse.ArgumentParser( 42 description="Time interval and print latency as a histogram", 43 formatter_class=argparse.RawDescriptionHelpFormatter, 44 epilog=examples) 45parser.add_argument("-p", "--pid", type=int, 46 help="trace this PID only") 47parser.add_argument("-i", "--interval", type=int, 48 help="summary interval, in seconds") 49parser.add_argument("-d", "--duration", type=int, 50 help="total duration of trace, in seconds") 51parser.add_argument("-T", "--timestamp", action="store_true", 52 help="include timestamp on output") 53parser.add_argument("-u", "--microseconds", action="store_true", 54 help="microsecond histogram") 55parser.add_argument("-m", "--milliseconds", action="store_true", 56 help="millisecond histogram") 57parser.add_argument("-v", "--verbose", action="store_true", 58 help="print the BPF program (for debugging purposes)") 59parser.add_argument("pattern", 60 help="Function/Tracepoint name for tracing") 61parser.add_argument("--ebpf", action="store_true", 62 help=argparse.SUPPRESS) 63args = parser.parse_args() 64if args.duration and not args.interval: 65 args.interval = args.duration 66if not args.interval: 67 args.interval = 99999999 68 69def bail(error): 70 print("Error: " + error) 71 exit(1) 72 73 74parts = args.pattern.split(':') 75if len(parts) == 1: 76 attach_type = "kprobe function" 77 pattern = args.pattern 78elif len(parts) == 2: 79 attach_type = "uprobe function" 80 elf = BPF.find_library(parts[0]) or BPF.find_exe(parts[0]) 81 if not elf: 82 bail("Can't find elf binary %s" % elf) 83 pattern = parts[1] 84elif len(parts) == 3: 85 attach_type = "tracepoint" 86 pattern = ':'.join(parts[1:]) 87else: 88 bail("unrecognized pattern format '%s'" % pattern) 89 90# define BPF program 91bpf_text = """ 92#include <uapi/linux/ptrace.h> 93 94BPF_HASH(start, u32, u64, 1); 95BPF_HISTOGRAM(dist); 96 97int trace_func_entry(struct pt_regs *ctx) 98{ 99 u64 pid_tgid = bpf_get_current_pid_tgid(); 100 u32 index = 0, tgid = pid_tgid >> 32; 101 u64 *tsp, ts = bpf_ktime_get_ns(), delta; 102 103 FILTER 104 tsp = start.lookup(&index); 105 if (tsp == 0) 106 goto out; 107 108 delta = ts - *tsp; 109 FACTOR 110 111 // store as histogram 112 dist.atomic_increment(bpf_log2l(delta)); 113 114out: 115 start.update(&index, &ts); 116 117 return 0; 118} 119""" 120 121# code substitutions 122if args.pid: 123 bpf_text = bpf_text.replace('FILTER', 124 'if (tgid != %d) { return 0; }' % args.pid) 125else: 126 bpf_text = bpf_text.replace('FILTER', '') 127if args.milliseconds: 128 bpf_text = bpf_text.replace('FACTOR', 'delta /= 1000000;') 129 label = "msecs" 130elif args.microseconds: 131 bpf_text = bpf_text.replace('FACTOR', 'delta /= 1000;') 132 label = "usecs" 133else: 134 bpf_text = bpf_text.replace('FACTOR', '') 135 label = "nsecs" 136 137if args.verbose or args.ebpf: 138 print(bpf_text) 139 if args.ebpf: 140 exit() 141 142# signal handler 143def signal_ignore(signal, frame): 144 print() 145 146 147# load BPF program 148b = BPF(text=bpf_text) 149 150if len(parts) == 1: 151 b.attach_kprobe(event=pattern, fn_name="trace_func_entry") 152 matched = b.num_open_kprobes() 153elif len(parts) == 2: 154 # sym_re is regular expression for symbols 155 b.attach_uprobe(name = elf, sym_re = pattern, fn_name = "trace_func_entry", 156 pid = args.pid or -1) 157 matched = b.num_open_uprobes() 158elif len(parts) == 3: 159 b.attach_tracepoint(tp=pattern, fn_name="trace_func_entry") 160 matched = b.num_open_tracepoints() 161 162if matched == 0: 163 print("0 %s matched by \"%s\". Exiting." % (attach_type, pattern)) 164 exit() 165 166# header 167print("Tracing %s for \"%s\"... Hit Ctrl-C to end." % 168 (attach_type, pattern)) 169 170exiting = 0 if args.interval else 1 171seconds = 0 172dist = b.get_table("dist") 173start = b.get_table("start") 174while (1): 175 try: 176 sleep(args.interval) 177 seconds += args.interval 178 except KeyboardInterrupt: 179 exiting = 1 180 # as cleanup can take many seconds, trap Ctrl-C: 181 signal.signal(signal.SIGINT, signal_ignore) 182 if args.duration and seconds >= args.duration: 183 exiting = 1 184 185 print() 186 if args.timestamp: 187 print("%-8s\n" % strftime("%H:%M:%S"), end="") 188 189 dist.print_log2_hist(label) 190 dist.clear() 191 start.clear() 192 193 if exiting: 194 print("Detaching...") 195 exit() 196