Merge pull request #202 from brendangregg/master

funccount and BPF_HASH updates

examples/disksnoop.c

@@ -13,36 +13,23 @@
 #include <uapi/linux/ptrace.h>
 #include <linux/blkdev.h>
 
-struct key_t {
-	struct request *req;
-};
-BPF_HASH(start, struct key_t);
-
-int kprobe__blk_start_request(struct pt_regs *ctx, struct request *req) {
-	struct key_t key = {};
-	u64 ts;
+BPF_HASH(start, struct request *);
 
+void kprobe__blk_start_request(struct pt_regs *ctx, struct request *req) {
 	// stash start timestamp by request ptr
-	ts = bpf_ktime_get_ns();
-	key.req = req;
-	start.update(&key, &ts);
+	u64 ts = bpf_ktime_get_ns();
 
-	return 0;
+	start.update(&req, &ts);
 }
 
-int kprobe__blk_update_request(struct pt_regs *ctx, struct request *req) {
-	struct key_t key = {};
+void kprobe__blk_update_request(struct pt_regs *ctx, struct request *req) {
 	u64 *tsp, delta;
 
-	key.req = req;
-	tsp = start.lookup(&key);
-
+	tsp = start.lookup(&req);
 	if (tsp != 0) {
 		delta = bpf_ktime_get_ns() - *tsp;
 		bpf_trace_printk("%d %x %d\n", req->__data_len,
 		    req->cmd_flags, delta / 1000);
-		start.delete(&key);
+		start.delete(&req);
 	}
-
-	return 0;
 }

examples/vfsreadlat.c

@@ -13,11 +13,7 @@
 
 #include <uapi/linux/ptrace.h>
 
-struct key_t {
-	u32 pid;
-};
-
-BPF_HASH(start, struct key_t);
+BPF_HASH(start, u32);
 BPF_TABLE("array", int, u64, dist, 64);
 
 static unsigned int log2(unsigned int v)
@@ -44,29 +40,29 @@ static unsigned int log2l(unsigned long v)
 
 int do_entry(struct pt_regs *ctx)
 {
-	struct key_t key = {};
-	u64 ts, *val, zero = 0;
+	u32 pid;
+	u64 ts, *val;
 
-	key.pid = bpf_get_current_pid_tgid();
+	pid = bpf_get_current_pid_tgid();
 	ts = bpf_ktime_get_ns();
-	start.update(&key, &ts);
+	start.update(&pid, &ts);
 	return 0;
 }
 
 int do_return(struct pt_regs *ctx)
 {
-	struct key_t key = {};
+	u32 pid;
 	u64 *tsp, delta;
 
-	key.pid = bpf_get_current_pid_tgid();
-	tsp = start.lookup(&key);
+	pid = bpf_get_current_pid_tgid();
+	tsp = start.lookup(&pid);
 
 	if (tsp != 0) {
 		delta = bpf_ktime_get_ns() - *tsp;
 		int index = log2l(delta / 1000);
 		u64 *leaf = dist.lookup(&index);
 		if (leaf) (*leaf)++;
-		start.delete(&key);
+		start.delete(&pid);
 	}
 
 	return 0;

man/man8/funccount.8

+.TH funccount 8  "2015-08-18" "USER COMMANDS"
+.SH NAME
+funccount \- Count kernel function calls matching a pattern. Uses Linux eBPF/bcc.
+.SH SYNOPSIS
+.B funccount [\-h] [\-p PID] [\-i INTERVAL] [\-T] [\-r] pattern
+.SH DESCRIPTION
+This tool is a quick way to determine which kernel functions are being called,
+and at what rate. It uses in-kernel eBPF maps to count function calls.
+
+WARNING: This uses dynamic tracing of (what can be many) kernel 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
+Search pattern. Supports "*" wildcards. See EXAMPLES. You can also use \-r for regular expressions.
+\-h
+Print usage message.
+.TP
+\-p PID
+Trace this process ID only.
+.TP
+\-i INTERVAL
+Print output every interval seconds.
+.TP
+\-T
+Include timestamps on output.
+.TP
+\-r
+Use regular expressions for the search pattern.
+.SH EXAMPLES
+.TP
+Count kernel functions beginning with "vfs_", until Ctrl-C is hit:
+#
+.B funccount 'vfs_*'
+.TP
+Count kernel functions beginning with "tcp_send", until Ctrl-C is hit:
+#
+.B funccount 'tcp_send*'
+.TP
+Print kernel functions beginning with "vfs_", every second:
+#
+.B funccount \-i 1 'vfs_*'
+.TP
+Match kernel functions beginning with "vfs_", using regular expressions:
+#
+.B funccount \-r '^vfs_.*'
+.TP
+Count vfs calls for process ID 181 only:
+#
+.B funccount \-p 181 'vfs_*'
+.SH FIELDS
+.TP
+ADDR
+Address of the instruction pointer that was traced (only useful if the FUNC column is suspicious and you would like to double check the translation).
+.TP
+FUNC
+Kernel function name
+.TP
+COUNT
+Number of calls while tracing
+.SH OVERHEAD
+This traces kernel functions and maintains in-kernel counts, which
+are asynchronously copied to user-space. While the rate of VFS operations can
+be very high (>1M/sec), this is a relatively efficient way to trace these
+events, and so the overhead is expected to be small for normal workloads.
+Measure in a test environment, and if overheads are an issue, edit the script
+to reduce the types of vfs functions traced (currently all beginning with
+"vfs_").
+.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
+Brendan Gregg
+.SH SEE ALSO
+vfscount(8)

tools/funccount

+#!/usr/bin/python
+#
+# funccount	Count kernel function calls.
+#		For Linux, uses BCC, eBPF. See .c file.
+#
+# USAGE: funccount [-h] [-p PID] [-i INTERVAL] [-T] [-r] pattern
+#
+# The pattern is a string with optional '*' wildcards, similar to file globbing.
+# If you'd prefer to use regular expressions, use the -r option.
+#
+# Copyright (c) 2015 Brendan Gregg.
+# Licensed under the Apache License, Version 2.0 (the "License")
+#
+# 09-Sep-2015	Brendan Gregg	Created this.
+
+from __future__ import print_function
+from bcc import BPF
+from time import sleep, strftime
+import argparse
+import re
+import signal
+
+# arguments
+examples = """examples:
+    ./funccount 'vfs_*'         # count kernel functions starting with "vfs"
+    ./funccount 'tcp_send*'     # count kernel funcs starting with "tcp_send"
+    ./funccount -r '^vfs.*'     # same as above, using regular expressions
+    ./funccount -Ti 5 'vfs_*'   # output every 5 seconds, with timestamps
+    ./funccount -p 185 'vfs_*'  # count vfs calls for PID 181 only
+"""
+parser = argparse.ArgumentParser(
+	description="Count kernel function calls",
+	formatter_class=argparse.RawDescriptionHelpFormatter,
+	epilog=examples)
+parser.add_argument("-p", "--pid",
+	help="trace this PID only")
+parser.add_argument("-i", "--interval", default=99999999,
+	help="summary interval, seconds")
+parser.add_argument("-T", "--timestamp", action="store_true",
+	help="include timestamp on output")
+parser.add_argument("-r", "--regexp", action="store_true",
+	help="use regular expressions. Default is \"*\" wildcards only.")
+parser.add_argument("pattern",
+	help="search expression for kernel functions")
+args = parser.parse_args()
+pattern = args.pattern
+if not args.regexp:
+	pattern = pattern.replace('*', '.*')
+	pattern = '^' + pattern + '$'
+debug = 0
+
+# signal handler
+def signal_ignore(signal, frame):
+	print()
+
+# load BPF program
+bpf_text = """
+#include <uapi/linux/ptrace.h>
+
+struct key_t {
+	u64 ip;
+};
+BPF_HASH(counts, struct key_t);
+
+int trace_count(struct pt_regs *ctx) {
+	FILTER_START
+	struct key_t key = {};
+	u64 zero = 0, *val;
+	key.ip = ctx->ip;
+	val = counts.lookup_or_init(&key, &zero);
+	(*val)++;
+	FILTER_DONE
+	return 0;
+}
+"""
+if args.pid:
+	bpf_text = bpf_text.replace('FILTER_START',
+	    ('u32 pid; pid = bpf_get_current_pid_tgid(); ' +
+	    'if (pid == %s) {') % (args.pid))
+	bpf_text = bpf_text.replace('FILTER_DONE', '}')
+else:
+	bpf_text = bpf_text.replace('FILTER_START', '')
+	bpf_text = bpf_text.replace('FILTER_DONE', '')
+if debug:
+	print(bpf_text)
+b = BPF(text=bpf_text)
+b.attach_kprobe(event_re=pattern, fn_name="trace_count")
+
+# header
+print("Tracing... Ctrl-C to end.")
+
+# output
+exiting = 0 if args.interval else 1
+while (1):
+	try:
+		sleep(int(args.interval))
+	except KeyboardInterrupt:
+		exiting=1
+		# as cleanup can take many seconds, trap Ctrl-C:
+		signal.signal(signal.SIGINT, signal_ignore)
+
+	print()
+	if args.timestamp:
+		print("%-8s\n" % strftime("%H:%M:%S"), end="")
+
+	print("%-16s %-26s %8s" % ("ADDR", "FUNC", "COUNT"))
+	counts = b.get_table("counts")
+	for k, v in sorted(counts.items(), key=lambda counts: counts[1].value):
+		print("%-16x %-26s %8d" % (k.ip, b.ksym(k.ip), v.value))
+	counts.clear()
+
+	if exiting:
+		print("Detaching...")
+		exit()

tools/syncsnoop

@@ -16,12 +16,10 @@ from bcc import BPF
 
 # load BPF program
 b = BPF(text = """
-int do_sync(void *ctx) {
+void kprobe__sys_sync(void *ctx) {
 	bpf_trace_printk("sync()\\n");
-	return 0;
 };
 """)
-b.attach_kprobe(event="sys_sync", fn_name="do_sync")
 
 # header
 print("%-18s %s" % ("TIME(s)", "CALL"))