|
| 1 | +#!/usr/bin/python |
| 2 | +# |
| 3 | +# funclatency Time kernel funcitons and print latency as a histogram. |
| 4 | +# For Linux, uses BCC, eBPF. |
| 5 | +# |
| 6 | +# USAGE: funclatency [-h] [-p PID] [-i INTERVAL] [-T] [-u] [-m] [-r] pattern |
| 7 | +# |
| 8 | +# Run "funclatency -h" for full usage. |
| 9 | +# |
| 10 | +# The pattern is a string with optional '*' wildcards, similar to file globbing. |
| 11 | +# If you'd prefer to use regular expressions, use the -r option. Matching |
| 12 | +# multiple functions is of limited use, since the output has one histogram for |
| 13 | +# everything. Future versions should split the output histogram by the function. |
| 14 | +# |
| 15 | +# Copyright (c) 2015 Brendan Gregg. |
| 16 | +# Licensed under the Apache License, Version 2.0 (the "License") |
| 17 | +# |
| 18 | +# 20-Sep-2015 Brendan Gregg Created this. |
| 19 | + |
| 20 | +from __future__ import print_function |
| 21 | +from bcc import BPF |
| 22 | +from time import sleep, strftime |
| 23 | +import argparse |
| 24 | +import signal |
| 25 | + |
| 26 | +# arguments |
| 27 | +examples = """examples: |
| 28 | + ./funclatency do_sys_open # time the do_sys_open() kenel function |
| 29 | + ./funclatency -u vfs_read # time vfs_read(), in microseconds |
| 30 | + ./funclatency -m do_nanosleep # time do_nanosleep(), in milliseconds |
| 31 | + ./funclatency -mTi 5 vfs_read # output every 5 seconds, with timestamps |
| 32 | + ./funclatency -p 181 vfs_read # time process 181 only |
| 33 | + ./funclatency 'vfs_fstat*' # time both vfs_fstat() and vfs_fstatat() |
| 34 | +""" |
| 35 | +parser = argparse.ArgumentParser( |
| 36 | + description="Time kernel funcitons and print latency as a histogram", |
| 37 | + formatter_class=argparse.RawDescriptionHelpFormatter, |
| 38 | + epilog=examples) |
| 39 | +parser.add_argument("-p", "--pid", |
| 40 | + help="trace this PID only") |
| 41 | +parser.add_argument("-i", "--interval", default=99999999, |
| 42 | + help="summary interval, seconds") |
| 43 | +parser.add_argument("-T", "--timestamp", action="store_true", |
| 44 | + help="include timestamp on output") |
| 45 | +parser.add_argument("-u", "--microseconds", action="store_true", |
| 46 | + help="microsecond histogram") |
| 47 | +parser.add_argument("-m", "--milliseconds", action="store_true", |
| 48 | + help="millisecond histogram") |
| 49 | +parser.add_argument("-r", "--regexp", action="store_true", |
| 50 | + help="use regular expressions. Default is \"*\" wildcards only.") |
| 51 | +parser.add_argument("pattern", |
| 52 | + help="search expression for kernel functions") |
| 53 | +args = parser.parse_args() |
| 54 | +pattern = args.pattern |
| 55 | +if not args.regexp: |
| 56 | + pattern = pattern.replace('*', '.*') |
| 57 | + pattern = '^' + pattern + '$' |
| 58 | +debug = 0 |
| 59 | + |
| 60 | +# define BPF program |
| 61 | +bpf_text = """ |
| 62 | +#include <uapi/linux/ptrace.h> |
| 63 | +#include <linux/blkdev.h> |
| 64 | +
|
| 65 | +BPF_TABLE(\"array\", int, u64, dist, 64); |
| 66 | +BPF_HASH(start, u32); |
| 67 | +
|
| 68 | +int trace_func_entry(struct pt_regs *ctx) |
| 69 | +{ |
| 70 | + u32 pid = bpf_get_current_pid_tgid(); |
| 71 | + u64 ts = bpf_ktime_get_ns(); |
| 72 | +
|
| 73 | + FILTER |
| 74 | + start.update(&pid, &ts); |
| 75 | +
|
| 76 | + return 0; |
| 77 | +} |
| 78 | +
|
| 79 | +int trace_func_return(struct pt_regs *ctx) |
| 80 | +{ |
| 81 | + u64 *tsp, delta; |
| 82 | + u32 pid = bpf_get_current_pid_tgid(); |
| 83 | +
|
| 84 | + // calculate delta time |
| 85 | + tsp = start.lookup(&pid); |
| 86 | + if (tsp == 0) { |
| 87 | + return 0; // missed start |
| 88 | + } |
| 89 | + start.delete(&pid); |
| 90 | + delta = bpf_ktime_get_ns() - *tsp; |
| 91 | + FACTOR |
| 92 | +
|
| 93 | + // store as histogram |
| 94 | + int index = bpf_log2l(delta); |
| 95 | + u64 *leaf = dist.lookup(&index); |
| 96 | + if (leaf) (*leaf)++; |
| 97 | +
|
| 98 | + return 0; |
| 99 | +} |
| 100 | +""" |
| 101 | +if args.pid: |
| 102 | + bpf_text = bpf_text.replace('FILTER', |
| 103 | + 'if (pid != %s) { return 0; }' % args.pid) |
| 104 | +else: |
| 105 | + bpf_text = bpf_text.replace('FILTER', '') |
| 106 | +if args.milliseconds: |
| 107 | + bpf_text = bpf_text.replace('FACTOR', 'delta /= 1000000;') |
| 108 | + label = "msecs" |
| 109 | +elif args.microseconds: |
| 110 | + bpf_text = bpf_text.replace('FACTOR', 'delta /= 1000;') |
| 111 | + label = "usecs" |
| 112 | +else: |
| 113 | + bpf_text = bpf_text.replace('FACTOR', '') |
| 114 | + label = "nsecs" |
| 115 | +if debug: |
| 116 | + print(bpf_text) |
| 117 | + |
| 118 | +# signal handler |
| 119 | +def signal_ignore(signal, frame): |
| 120 | + print() |
| 121 | + |
| 122 | +# load BPF program |
| 123 | +b = BPF(text=bpf_text) |
| 124 | +b.attach_kprobe(event_re=pattern, fn_name="trace_func_entry") |
| 125 | +b.attach_kretprobe(event_re=pattern, fn_name="trace_func_return") |
| 126 | + |
| 127 | +# header |
| 128 | +print("Tracing %s... Hit Ctrl-C to end." % args.pattern) |
| 129 | + |
| 130 | +# output |
| 131 | +exiting = 0 if args.interval else 1 |
| 132 | +dist = b.get_table("dist") |
| 133 | +while (1): |
| 134 | + try: |
| 135 | + sleep(int(args.interval)) |
| 136 | + except KeyboardInterrupt: |
| 137 | + exiting=1 |
| 138 | + # as cleanup can take many seconds, trap Ctrl-C: |
| 139 | + signal.signal(signal.SIGINT, signal_ignore) |
| 140 | + |
| 141 | + print() |
| 142 | + if args.timestamp: |
| 143 | + print("%-8s\n" % strftime("%H:%M:%S"), end="") |
| 144 | + |
| 145 | + dist.print_log2_hist(label) |
| 146 | + dist.clear() |
| 147 | + |
| 148 | + if exiting: |
| 149 | + print("Detaching...") |
| 150 | + exit() |
0 commit comments