tools: Add funcinterval bcc tool.

Time interval between the same function as a histogram.
Referenced from funclatency.

README.md

@@ -115,6 +115,7 @@ pair of .c and .py files, and some are directories of files.
 - tools/[fileslower](tools/fileslower.py): Trace slow synchronous file reads and writes. [Examples](tools/fileslower_example.txt).
 - tools/[filetop](tools/filetop.py): File reads and writes by filename and process. Top for files. [Examples](tools/filetop_example.txt).
 - tools/[funccount](tools/funccount.py): Count kernel function calls. [Examples](tools/funccount_example.txt).
+- tools/[funcinterval](tools/funcinterval.py): Time interval between the same function as a histogram. [Examples](tools/funcinterval_example.txt).
 - tools/[funclatency](tools/funclatency.py): Time functions and show their latency distribution. [Examples](tools/funclatency_example.txt).
 - tools/[funcslower](tools/funcslower.py): Trace slow kernel or user function calls. [Examples](tools/funcslower_example.txt).
 - tools/[gethostlatency](tools/gethostlatency.py): Show latency for getaddrinfo/gethostbyname[2] calls. [Examples](tools/gethostlatency_example.txt).

man/man8/funcinterval.8

@@ -0,0 +1,115 @@
+.TH funcinterval 8  "2020-05-27" "USER COMMANDS"
+.SH NAME
+funcinterval \- Time interval between the same function, tracepoint as a histogram.
+.SH SYNOPSIS
+.B funcinterval [\-h] [\-p PID] [\-i INTERVAL] [\-d DURATION] [\-T] [\-u] [\-m] [\-v] pattern
+.SH DESCRIPTION
+This tool times interval between the same function as a histogram.
+
+eBPF/bcc is very suitable for platform performance tuning.
+By funclatency, we can profile specific functions to know how latency
+this function costs. However, sometimes performance drop is not about the 
+latency of function but the interval between function calls.
+funcinterval is born for this purpose.
+
+This tool uses in-kernel eBPF maps for storing timestamps and the histogram,
+for efficiency.
+
+WARNING: This uses dynamic tracing of (what can be many) functions, an
+activity that has had issues on some kernel versions (risk of panics or
+freezes). Test, and know what you are doing, before use.
+
+Since this uses BPF, only the root user can use this tool.
+.SH REQUIREMENTS
+CONFIG_BPF and bcc.
+.SH OPTIONS
+pattern
+Function name.
+\-h
+Print usage message.
+.TP
+\-p PID
+Trace this process ID only.
+.TP
+\-i INTERVAL
+Print output every interval seconds.
+.TP
+\-d DURATION
+Total duration of trace, in seconds.
+.TP
+\-T
+Include timestamps on output.
+.TP
+\-u
+Output histogram in microseconds.
+.TP
+\-m
+Output histogram in milliseconds.
+.TP
+\-v
+Print the BPF program (for debugging purposes).
+.SH EXAMPLES
+.TP
+Time the interval of do_sys_open() kernel function as a histogram:
+#
+.B funcinterval do_sys_open
+.TP
+Time the interval of xhci_ring_ep_doorbell(), in microseconds:
+#
+.B funcinterval -u xhci_ring_ep_doorbell
+.TP
+Time the interval of do_nanosleep(), in milliseconds
+#
+.B funcinterval -m do_nanosleep
+.TP
+Output every 5 seconds, with timestamps:
+#
+.B funcinterval -mTi 5 vfs_read
+.TP
+Time process 181 only:
+#
+.B funcinterval -p 181 vfs_read
+.TP
+Time the interval of mm_vmscan_direct_reclaim_begin tracepoint:
+#
+.B funcinterval t:vmscan:mm_vmscan_direct_reclaim_begin
+.SH FIELDS
+.TP
+necs
+Nanosecond range
+.TP
+usecs
+Microsecond range
+.TP
+msecs
+Millisecond range
+.TP
+count
+How many calls fell into this range
+.TP
+distribution
+An ASCII bar chart to visualize the distribution (count column)
+.SH OVERHEAD
+This traces kernel functions and maintains in-kernel timestamps and a histogram,
+which are asynchronously copied to user-space. While this method is very
+efficient, the rate of kernel functions can also be very high (>1M/sec), at
+which point the overhead is expected to be measurable. Measure in a test
+environment and understand overheads before use. You can also use funccount
+to measure the rate of kernel functions over a short duration, to set some
+expectations before use.
+.SH SOURCE
+This is from bcc.
+.IP
+https://github.com/iovisor/bcc
+.PP
+Also look in the bcc distribution for a companion _examples.txt file containing
+example usage, output, and commentary for this tool.
+.SH OS
+Linux
+.SH STABILITY
+Unstable - in development.
+.SH AUTHOR
+Edward Wu
+.SH SEE ALSO
+funclatency(8)
+funccount(8)

tools/funcinterval.py

@@ -0,0 +1,180 @@
+#!/usr/bin/python
+# @lint-avoid-python-3-compatibility-imports
+#
+# funcinterval   Time interval between the same function, tracepoint
+#                as a histogram.
+#
+# USAGE: funcinterval [-h] [-p PID] [-i INTERVAL] [-T] [-u] [-m] [-v] pattern
+#
+# Run "funcinterval -h" for full usage.
+#
+# Copyright (c) 2020 Realtek, Inc.
+# Licensed under the Apache License, Version 2.0 (the "License")
+#
+# 03-Jun-2020   Edward Wu   Referenced funclatency and created this.
+
+from __future__ import print_function
+from bcc import BPF
+from time import sleep, strftime
+import argparse
+import signal
+
+# arguments
+examples = """examples:
+    # time the interval of do_sys_open()
+    ./funcinterval do_sys_open
+    # time the interval of xhci_ring_ep_doorbell(), in microseconds
+    ./funcinterval -u xhci_ring_ep_doorbell
+    # time the interval of do_nanosleep(), in milliseconds
+    ./funcinterval -m do_nanosleep
+    # output every 5 seconds, with timestamps
+    ./funcinterval -mTi 5 vfs_read
+    # time process 181 only
+    ./funcinterval -p 181 vfs_read
+    # time the interval of mm_vmscan_direct_reclaim_begin tracepoint
+    ./funcinterval t:vmscan:mm_vmscan_direct_reclaim_begin
+"""
+parser = argparse.ArgumentParser(
+    description="Time interval and print latency as a histogram",
+    formatter_class=argparse.RawDescriptionHelpFormatter,
+    epilog=examples)
+parser.add_argument("-p", "--pid", type=int,
+    help="trace this PID only")
+parser.add_argument("-i", "--interval", type=int,
+    help="summary interval, in seconds")
+parser.add_argument("-d", "--duration", type=int,
+    help="total duration of trace, in seconds")
+parser.add_argument("-T", "--timestamp", action="store_true",
+    help="include timestamp on output")
+parser.add_argument("-u", "--microseconds", action="store_true",
+    help="microsecond histogram")
+parser.add_argument("-m", "--milliseconds", action="store_true",
+    help="millisecond histogram")
+parser.add_argument("-v", "--verbose", action="store_true",
+    help="print the BPF program (for debugging purposes)")
+parser.add_argument("pattern",
+    help="Function/Tracepoint name for tracing")
+parser.add_argument("--ebpf", action="store_true",
+    help=argparse.SUPPRESS)
+args = parser.parse_args()
+if args.duration and not args.interval:
+    args.interval = args.duration
+if not args.interval:
+    args.interval = 99999999
+
+def bail(error):
+    print("Error: " + error)
+    exit(1)
+
+
+parts = args.pattern.split(':')
+if len(parts) == 1:
+    attach_type = "function"
+    pattern = args.pattern
+elif len(parts) == 3:
+    attach_type = "tracepoint"
+    pattern = ':'.join(parts[1:])
+else:
+    bail("unrecognized pattern format '%s'" % pattern)
+
+# define BPF program
+bpf_text = """
+#include <uapi/linux/ptrace.h>
+
+BPF_HASH(start, u32, u64, 1);
+BPF_HISTOGRAM(dist);
+
+int trace_func_entry(struct pt_regs *ctx)
+{
+    u64 pid_tgid = bpf_get_current_pid_tgid();
+    u32 index = 0, tgid = pid_tgid >> 32;
+    u64 *tsp, ts = bpf_ktime_get_ns(), delta;
+
+    FILTER
+    tsp = start.lookup(&index);
+    if (tsp == 0)
+        goto out;
+
+    delta = ts - *tsp;
+    FACTOR
+
+    // store as histogram
+    dist.increment(bpf_log2l(delta));
+
+out:
+    start.update(&index, &ts);
+
+    return 0;
+}
+"""
+
+# code substitutions
+if args.pid:
+    bpf_text = bpf_text.replace('FILTER',
+        'if (tgid != %d) { return 0; }' % args.pid)
+else:
+    bpf_text = bpf_text.replace('FILTER', '')
+if args.milliseconds:
+    bpf_text = bpf_text.replace('FACTOR', 'delta /= 1000000;')
+    label = "msecs"
+elif args.microseconds:
+    bpf_text = bpf_text.replace('FACTOR', 'delta /= 1000;')
+    label = "usecs"
+else:
+    bpf_text = bpf_text.replace('FACTOR', '')
+    label = "nsecs"
+
+if args.verbose or args.ebpf:
+    print(bpf_text)
+    if args.ebpf:
+        exit()
+
+# signal handler
+def signal_ignore(signal, frame):
+    print()
+
+
+# load BPF program
+b = BPF(text=bpf_text)
+
+if len(parts) == 1:
+    b.attach_kprobe(event=pattern, fn_name="trace_func_entry")
+    matched = b.num_open_kprobes()
+elif len(parts) == 3:
+    b.attach_tracepoint(tp=pattern, fn_name="trace_func_entry")
+    matched = b.num_open_tracepoints()
+
+if matched == 0:
+    print("0 %s matched by \"%s\". Exiting." % (attach_type, pattern))
+    exit()
+
+# header
+print("Tracing %s for \"%s\"... Hit Ctrl-C to end." %
+    (attach_type, pattern))
+
+exiting = 0 if args.interval else 1
+seconds = 0
+dist = b.get_table("dist")
+start = b.get_table("start")
+while (1):
+    try:
+        sleep(args.interval)
+        seconds += args.interval
+    except KeyboardInterrupt:
+        exiting = 1
+        # as cleanup can take many seconds, trap Ctrl-C:
+        signal.signal(signal.SIGINT, signal_ignore)
+    if args.duration and seconds >= args.duration:
+        exiting = 1
+
+    print()
+    if args.timestamp:
+        print("%-8s\n" % strftime("%H:%M:%S"), end="")
+
+    dist.print_log2_hist(label)
+    dist.clear()
+    start.clear()
+
+    if exiting:
+        print("Detaching...")
+        exit()