Edward Wu | 2188d23 | 2020-05-28 09:36:21 +0800 | [diff] [blame] | 1 | #!/usr/bin/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 | |
| 16 | from __future__ import print_function |
| 17 | from bcc import BPF |
| 18 | from time import sleep, strftime |
| 19 | import argparse |
| 20 | import signal |
| 21 | |
| 22 | # arguments |
| 23 | examples = """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 |
zhaoyao73 | f47b81a | 2021-06-30 13:15:26 -0400 | [diff] [blame] | 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 |
Edward Wu | 2188d23 | 2020-05-28 09:36:21 +0800 | [diff] [blame] | 40 | """ |
| 41 | parser = argparse.ArgumentParser( |
| 42 | description="Time interval and print latency as a histogram", |
| 43 | formatter_class=argparse.RawDescriptionHelpFormatter, |
| 44 | epilog=examples) |
| 45 | parser.add_argument("-p", "--pid", type=int, |
| 46 | help="trace this PID only") |
| 47 | parser.add_argument("-i", "--interval", type=int, |
| 48 | help="summary interval, in seconds") |
| 49 | parser.add_argument("-d", "--duration", type=int, |
| 50 | help="total duration of trace, in seconds") |
| 51 | parser.add_argument("-T", "--timestamp", action="store_true", |
| 52 | help="include timestamp on output") |
| 53 | parser.add_argument("-u", "--microseconds", action="store_true", |
| 54 | help="microsecond histogram") |
| 55 | parser.add_argument("-m", "--milliseconds", action="store_true", |
| 56 | help="millisecond histogram") |
| 57 | parser.add_argument("-v", "--verbose", action="store_true", |
| 58 | help="print the BPF program (for debugging purposes)") |
| 59 | parser.add_argument("pattern", |
| 60 | help="Function/Tracepoint name for tracing") |
| 61 | parser.add_argument("--ebpf", action="store_true", |
| 62 | help=argparse.SUPPRESS) |
| 63 | args = parser.parse_args() |
| 64 | if args.duration and not args.interval: |
| 65 | args.interval = args.duration |
| 66 | if not args.interval: |
| 67 | args.interval = 99999999 |
| 68 | |
| 69 | def bail(error): |
| 70 | print("Error: " + error) |
| 71 | exit(1) |
| 72 | |
| 73 | |
| 74 | parts = args.pattern.split(':') |
| 75 | if len(parts) == 1: |
zhaoyao73 | f47b81a | 2021-06-30 13:15:26 -0400 | [diff] [blame] | 76 | attach_type = "kprobe function" |
Edward Wu | 2188d23 | 2020-05-28 09:36:21 +0800 | [diff] [blame] | 77 | pattern = args.pattern |
zhaoyao73 | f47b81a | 2021-06-30 13:15:26 -0400 | [diff] [blame] | 78 | elif 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] |
Edward Wu | 2188d23 | 2020-05-28 09:36:21 +0800 | [diff] [blame] | 84 | elif len(parts) == 3: |
| 85 | attach_type = "tracepoint" |
| 86 | pattern = ':'.join(parts[1:]) |
| 87 | else: |
| 88 | bail("unrecognized pattern format '%s'" % pattern) |
| 89 | |
| 90 | # define BPF program |
| 91 | bpf_text = """ |
| 92 | #include <uapi/linux/ptrace.h> |
| 93 | |
| 94 | BPF_HASH(start, u32, u64, 1); |
| 95 | BPF_HISTOGRAM(dist); |
| 96 | |
| 97 | int 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 |
zcy | 80242fb | 2021-07-02 00:12:32 +0800 | [diff] [blame] | 112 | dist.atomic_increment(bpf_log2l(delta)); |
Edward Wu | 2188d23 | 2020-05-28 09:36:21 +0800 | [diff] [blame] | 113 | |
| 114 | out: |
| 115 | start.update(&index, &ts); |
| 116 | |
| 117 | return 0; |
| 118 | } |
| 119 | """ |
| 120 | |
| 121 | # code substitutions |
| 122 | if args.pid: |
| 123 | bpf_text = bpf_text.replace('FILTER', |
| 124 | 'if (tgid != %d) { return 0; }' % args.pid) |
| 125 | else: |
| 126 | bpf_text = bpf_text.replace('FILTER', '') |
| 127 | if args.milliseconds: |
| 128 | bpf_text = bpf_text.replace('FACTOR', 'delta /= 1000000;') |
| 129 | label = "msecs" |
| 130 | elif args.microseconds: |
| 131 | bpf_text = bpf_text.replace('FACTOR', 'delta /= 1000;') |
| 132 | label = "usecs" |
| 133 | else: |
| 134 | bpf_text = bpf_text.replace('FACTOR', '') |
| 135 | label = "nsecs" |
| 136 | |
| 137 | if args.verbose or args.ebpf: |
| 138 | print(bpf_text) |
| 139 | if args.ebpf: |
| 140 | exit() |
| 141 | |
| 142 | # signal handler |
| 143 | def signal_ignore(signal, frame): |
| 144 | print() |
| 145 | |
| 146 | |
| 147 | # load BPF program |
| 148 | b = BPF(text=bpf_text) |
| 149 | |
| 150 | if len(parts) == 1: |
| 151 | b.attach_kprobe(event=pattern, fn_name="trace_func_entry") |
| 152 | matched = b.num_open_kprobes() |
zhaoyao73 | f47b81a | 2021-06-30 13:15:26 -0400 | [diff] [blame] | 153 | elif 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() |
Edward Wu | 2188d23 | 2020-05-28 09:36:21 +0800 | [diff] [blame] | 158 | elif len(parts) == 3: |
| 159 | b.attach_tracepoint(tp=pattern, fn_name="trace_func_entry") |
| 160 | matched = b.num_open_tracepoints() |
| 161 | |
| 162 | if matched == 0: |
| 163 | print("0 %s matched by \"%s\". Exiting." % (attach_type, pattern)) |
| 164 | exit() |
| 165 | |
| 166 | # header |
| 167 | print("Tracing %s for \"%s\"... Hit Ctrl-C to end." % |
| 168 | (attach_type, pattern)) |
| 169 | |
| 170 | exiting = 0 if args.interval else 1 |
| 171 | seconds = 0 |
| 172 | dist = b.get_table("dist") |
| 173 | start = b.get_table("start") |
| 174 | while (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() |