Merge pull request iovisor#150 from brendangregg/master

some bcc examples and tools
egggHang · Aug 19, 2015 · 307ac0b · 307ac0b
2 parents 5484bad + ebdb242
commit 307ac0b
Show file tree

Hide file tree

Showing 24 changed files with 1,254 additions and 0 deletions.
diff --git a/examples/bitehist.c b/examples/bitehist.c
@@ -0,0 +1,48 @@
+/*
+ * bitehist.c	Block I/O size histogram.
+ *		For Linux, uses BCC, eBPF. See .py file.
+ *
+ * Based on eBPF sample tracex2 by Alexi Starovoitov.
+ * Copyright (c) 2013-2015 PLUMgrid, http://plumgrid.com
+ * This program is free software; you can redistribute it and/or
+ * modify it under the terms of version 2 of the GNU General Public
+ * License as published by the Free Software Foundation.
+ *
+ * 15-Aug-2015	Brendan Gregg	Created this.
+ */
+
+#include <uapi/linux/ptrace.h>
+#include <linux/blkdev.h>
+
+BPF_TABLE("array", int, u64, dist, 64);
+
+static unsigned int log2(unsigned int v)
+{
+	unsigned int r;
+	unsigned int shift;
+
+	r = (v > 0xFFFF) << 4; v >>= r;
+	shift = (v > 0xFF) << 3; v >>= shift; r |= shift;
+	shift = (v > 0xF) << 2; v >>= shift; r |= shift;
+	shift = (v > 0x3) << 1; v >>= shift; r |= shift;
+	r |= (v >> 1);
+	return r;
+}
+
+static unsigned int log2l(unsigned long v)
+{
+	unsigned int hi = v >> 32;
+	if (hi)
+		return log2(hi) + 32 + 1;
+	else
+		return log2(v) + 1;
+}
+
+int do_request(struct pt_regs *ctx, struct request *req)
+{
+	int index = log2l(req->__data_len / 1024);
+	u64 *leaf = dist.lookup(&index);
+	if (leaf) (*leaf)++;
+
+	return 0;
+}
diff --git a/examples/bitehist.py b/examples/bitehist.py
@@ -0,0 +1,109 @@
+#!/usr/bin/python
+#
+# bitehist.py	Block I/O size histogram.
+#		For Linux, uses BCC, eBPF. See .c file.
+#
+# Written as a basic example of using a histogram to show a distribution.
+#
+# USAGE: bitehist.py [interval [count]]
+#
+# The default interval is 5 seconds. A Ctrl-C will print the partially
+# gathered histogram then exit.
+#
+# Copyright (c) 2015 Brendan Gregg.
+# Licensed under the Apache License, Version 2.0 (the "License")
+#
+# 15-Aug-2015	Brendan Gregg	Created this.
+
+from bpf import BPF
+from ctypes import c_ushort, c_int, c_ulonglong
+from time import sleep
+from sys import argv
+
+def usage():
+	print("USAGE: %s [interval [count]]" % argv[0])
+	exit()
+
+# arguments
+interval = 5
+count = -1
+if len(argv) > 1:
+	try:
+		interval = int(argv[1])
+		if interval == 0:
+			raise
+		if len(argv) > 2:
+			count = int(argv[2])
+	except:	# also catches -h, --help
+		usage()
+
+# load BPF program
+b = BPF(src_file = "bitehist.c")
+BPF.attach_kprobe(b.load_func("do_request", BPF.KPROBE), "blk_start_request")
+dist = b.get_table("dist")
+dist_max = 64
+
+# header
+print("Tracing... Hit Ctrl-C to end.")
+last = {}
+for i in range(1, dist_max + 1):
+	last[i] = 0
+
+# functions
+stars_max = 38
+def stars(val, val_max, width):
+	i = 0
+	text = ""
+	while (1):
+		if (i > (width * val / val_max) - 1) or (i > width - 1):
+			break
+		text += "*"
+		i += 1
+	if val > val_max:
+		text = text[:-1] + "+"
+	return text
+
+def print_log2_hist(d, val_type):
+	idx_max = -1
+	val_max = 0
+	for i in range(1, dist_max + 1):
+		try:
+			val = dist[c_int(i)].value - last[i]
+			if (val > 0):
+				idx_max = i
+			if (val > val_max):
+				val_max = val
+		except:
+			break
+	if idx_max > 0:
+		print("     %-15s : count     distribution" % val_type);
+	for i in range(1, idx_max + 1):
+		low = (1 << i) >> 1
+		high = (1 << i) - 1
+		if (low == high):
+			low -= 1
+		try:
+			val = dist[c_int(i)].value - last[i]
+			print("%8d -> %-8d : %-8d |%-*s|" % (low, high, val,
+			    stars_max, stars(val, val_max, stars_max)))
+			last[i] = dist[c_int(i)].value
+		except:
+			break
+
+# output
+loop = 0
+do_exit = 0
+while (1):
+	if count > 0:
+		loop += 1
+		if loop > count:
+			exit()
+	try:
+		sleep(interval)
+	except KeyboardInterrupt:
+		pass; do_exit = 1
+
+	print
+	print_log2_hist(dist, "kbytes")
+	if do_exit:
+		exit()
diff --git a/examples/bitehist_example.txt b/examples/bitehist_example.txt
@@ -0,0 +1,70 @@
+Demonstrations of bitehist.py, the Linux eBPF/bcc version.
+
+This prints a power-of-2 histogram to show the block I/O size distribution.
+By default, a summary is printed every five seconds:
+
+# ./bitehist.py
+Tracing... Hit Ctrl-C to end.
+
+     kbytes          : count     distribution
+       0 -> 1        : 0        |                                      |
+       2 -> 3        : 0        |                                      |
+       4 -> 7        : 26       |*************                         |
+       8 -> 15       : 3        |*                                     |
+      16 -> 31       : 5        |**                                    |
+      32 -> 63       : 6        |***                                   |
+      64 -> 127      : 7        |***                                   |
+     128 -> 255      : 75       |**************************************|
+
+     kbytes          : count     distribution
+       0 -> 1        : 0        |                                      |
+       2 -> 3        : 0        |                                      |
+       4 -> 7        : 83       |**************************************|
+       8 -> 15       : 2        |                                      |
+      16 -> 31       : 6        |**                                    |
+      32 -> 63       : 6        |**                                    |
+      64 -> 127      : 5        |**                                    |
+     128 -> 255      : 21       |*********                             |
+^C
+     kbytes          : count     distribution
+       0 -> 1        : 0        |                                      |
+       2 -> 3        : 0        |                                      |
+       4 -> 7        : 8        |**************************************|
+
+The first output shows a bimodal distribution. The largest mode of 75 I/O were
+between 128 and 255 Kbytes in size, and another mode of 26 I/O were between 4
+and 7 Kbytes in size. 
+
+The next output summary shows the workload is doing more 4 - 7 Kbyte I/O.
+
+The final output is partial, showing what was measured until Ctrl-C was hit.
+
+
+For an output interval of one second, and three summaries:
+
+# ./bitehist.py 1 3
+Tracing... Hit Ctrl-C to end.
+
+     kbytes          : count     distribution
+       0 -> 1        : 0        |                                      |
+       2 -> 3        : 0        |                                      |
+       4 -> 7        : 4        |**************************************|
+
+     kbytes          : count     distribution
+       0 -> 1        : 0        |                                      |
+       2 -> 3        : 0        |                                      |
+       4 -> 7        : 5        |**************************************|
+       8 -> 15       : 0        |                                      |
+      16 -> 31       : 0        |                                      |
+      32 -> 63       : 1        |*******                               |
+
+     kbytes          : count     distribution
+       0 -> 1        : 0        |                                      |
+       2 -> 3        : 0        |                                      |
+       4 -> 7        : 4        |**************************************|
+
+
+Full usage:
+
+# ./bitehist.py -h
+USAGE: ./bitehist.py [interval [count]]
diff --git a/examples/disksnoop.c b/examples/disksnoop.c
@@ -0,0 +1,48 @@
+/*
+ * disksnoop.c	Trace block device I/O: basic version of iosnoop.
+ *		For Linux, uses BCC, eBPF. See .py file.
+ *
+ * Copyright (c) 2015 Brendan Gregg.
+ * This program is free software; you can redistribute it and/or
+ * modify it under the terms of version 2 of the GNU General Public
+ * License as published by the Free Software Foundation.
+ *
+ * 11-Aug-2015	Brendan Gregg	Created this.
+ */
+
+#include <uapi/linux/ptrace.h>
+#include <linux/blkdev.h>
+
+struct key_t {
+	struct request *req;
+};
+BPF_TABLE("hash", struct key_t, u64, start, 10240);
+
+int do_request(struct pt_regs *ctx, struct request *req) {
+	struct key_t key = {};
+	u64 ts;
+
+	// stash start timestamp by request ptr
+	ts = bpf_ktime_get_ns();
+	key.req = req;
+	start.update(&key, &ts);
+
+	return 0;
+}
+
+int do_completion(struct pt_regs *ctx, struct request *req) {
+	struct key_t key = {};
+	u64 *tsp, delta;
+
+	key.req = req;
+	tsp = start.lookup(&key);
+
+	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);
+	}
+
+	return 0;
+}
diff --git a/examples/disksnoop.py b/examples/disksnoop.py
@@ -0,0 +1,53 @@
+#!/usr/bin/python
+#
+# disksnoop.py	Trace block device I/O: basic version of iosnoop.
+#		For Linux, uses BCC, eBPF. See .c file.
+#
+# Written as a basic example of tracing latency.
+#
+# Copyright (c) 2015 Brendan Gregg.
+# Licensed under the Apache License, Version 2.0 (the "License")
+#
+# 11-Aug-2015	Brendan Gregg	Created this.
+
+from __future__ import print_function
+from bpf import BPF
+import sys
+
+REQ_WRITE = 1		# from include/linux/blk_types.h
+
+# load BPF program
+b = BPF(src_file="disksnoop.c")
+BPF.attach_kprobe(b.load_func("do_request", BPF.KPROBE), "blk_start_request")
+BPF.attach_kprobe(b.load_func("do_completion", BPF.KPROBE), "blk_update_request")
+
+# header
+print("%-18s %-2s %-7s %8s" % ("TIME(s)", "T", "BYTES", "LAT(ms)"))
+
+# open trace pipe
+try:
+	trace = open("/sys/kernel/debug/tracing/trace_pipe", "r")
+except:
+	print("ERROR: opening trace_pipe", file=sys.stderr)
+	exit(1)
+
+# format output
+while 1:
+	try:
+		line = trace.readline().rstrip()
+	except KeyboardInterrupt:
+		pass; exit()
+	prolog, time_s, colon, bytes_s, flags_s, us_s = \
+		line.rsplit(" ", 5)
+
+	time_s = time_s[:-1]	# strip trailing ":"
+	flags = int(flags_s, 16)
+	if flags & REQ_WRITE:
+		type_s = "W"
+	elif bytes_s == "0":	# see blk_fill_rwbs() for logic
+		type_s = "M"
+	else:
+		type_s = "R"
+	ms = float(int(us_s, 10)) / 1000
+
+	print("%-18s %-2s %-7s %8.2f" % (time_s, type_s, bytes_s, ms))
diff --git a/examples/disksnoop_example.txt b/examples/disksnoop_example.txt
@@ -0,0 +1,40 @@
+Demonstrations of disksnoop.py, the Linux eBPF/bcc version.
+
+
+This traces block I/O, a prints a line to summarize each I/O completed:
+
+# ./disksnoop.py 
+TIME(s)            T  BYTES    LAT(ms)
+16458043.435457    W  4096        2.73
+16458043.435981    W  4096        3.24
+16458043.436012    W  4096        3.13
+16458043.437326    W  4096        4.44
+16458044.126545    R  4096       42.82
+16458044.129872    R  4096        3.24
+16458044.130705    R  4096        0.73
+16458044.142813    R  4096       12.01
+16458044.147302    R  4096        4.33
+16458044.148117    R  4096        0.71
+16458044.148950    R  4096        0.70
+16458044.164332    R  4096       15.29
+16458044.168003    R  4096        3.58
+16458044.171676    R  4096        3.59
+16458044.172453    R  4096        0.72
+16458044.173213    R  4096        0.71
+16458044.173989    R  4096        0.72
+16458044.174739    R  4096        0.70
+16458044.190334    R  4096       15.52
+16458044.196608    R  4096        6.17
+16458044.203091    R  4096        6.35
+
+The output includes a basic timestamp (in seconds), the type of I/O (W == write,
+R == read, M == metadata), the size of the I/O in bytes, and the latency (or
+duration) of the I/O in milliseconds.
+
+The latency is measured from I/O request to the device, to the device
+completion. This excludes latency spent queued in the OS.
+
+Most of the I/O in this example were 0.7 and 4 milliseconds in duration. There
+was an outlier of 42.82 milliseconds, a read which followed many writes (the
+high latency may have been caused by the writes still being serviced on the
+storage device).