add xfsdist tool

README.md

@@ -152,6 +152,7 @@ bpftrace contains various tools, which also serve as examples of programming in
 - tools/[pidpersec.bt](tools/pidpersec.bt): Count new procesess (via fork). [Examples](tools/pidpersec_example.txt).
 - tools/[vfscount.bt](tools/vfscount.bt): Count VFS calls. [Examples](tools/vfscount_example.txt).
 - tools/[vfsstat.bt](tools/vfsstat.bt): Count some VFS calls, with per-second summaries. [Examples](tools/vfsstat_example.txt).
+- tools/[xfsdist.bt](tools/xfsdist.bt): Summarize XFS operation latency distribution as a histogram. [Examples](tools/xfsdist_example.txt).
 
 For more eBPF observability tools, see [bcc tools](https://github.com/iovisor/bcc#tools).
 

man/man8/xfsdist.8

+.TH xfsdist 8  "2018-09-08" "USER COMMANDS"
+.SH NAME
+xfsdist.bt \- Summarize XFS operation latency. Uses bpftrace/eBPF.
+.SH SYNOPSIS
+.B xfsdist.bt
+.SH DESCRIPTION
+This tool summarizes time (latency) spent in common XFS file operations: reads,
+writes, opens, and syncs, and presents it as a power-of-2 histogram. It uses an
+in-kernel eBPF map to store the histogram for efficiency.
+
+Since this works by tracing the xfs_file_operations interface functions, it
+will need updating to match any changes to these functions.
+
+Since this uses BPF, only the root user can use this tool.
+.SH REQUIREMENTS
+CONFIG_BPF and bpftrace.
+.SH EXAMPLES
+.TP
+Trace XFS operation time, and print a summary on Ctrl-C:
+#
+.B xfsdist
+.SH FIELDS
+.TP
+0th
+The operation name (shown in "@[...]") is printed before each I/O histogram.
+.TP
+1st, 2nd
+This is a range of latency, in microseconds (shown in "[...)" set notation).
+.TP
+3rd
+A column showing the count of operations in this range.
+.TP
+4th
+This is an ASCII histogram representing the count colimn.
+.SH OVERHEAD
+This adds low-overhead instrumentation to these XFS operations,
+including reads and writes from the file system cache. Such reads and writes
+can be very frequent (depending on the workload; eg, 1M/sec), at which
+point the overhead of this tool may become noticeable.
+Measure and quantify before use.
+.SH SOURCE
+This is from bpftrace.
+.IP
+https://github.com/iovisor/bpftrace
+.PP
+Also look in the bpftrace distribution for a companion _examples.txt file containing
+example usage, output, and commentary for this tool.
+
+This is a bpftrace version of the bcc tool of the same name. The bcc tool
+may provide more options and customizations.
+.IP
+https://github.com/iovisor/bcc
+.SH OS
+Linux
+.SH STABILITY
+Unstable - in development.
+.SH AUTHOR
+Brendan Gregg
+.SH SEE ALSO
+iosnoop(1)

tools/xfsdist.bt

+/*
+ * xfsdist	Summarize XFS operation latency.
+ *		For Linux, uses bpftrace and eBPF.
+ *
+ * This traces four common file system calls: read, write, open, and fsync.
+ * It can be customized to trace more if desired.
+ *
+ * USAGE: xfsdist.bt
+ *
+ * This is a bpftrace version of the bcc tool of the same name.
+ *
+ * Copyright 2018 Netflix, Inc.
+ * Licensed under the Apache License, Version 2.0 (the "License")
+ *
+ * 08-Sep-2018	Brendan Gregg	Created this.
+ */
+
+BEGIN
+{
+	printf("Tracing XFS operation latency... Hit Ctrl-C to end.\n");
+}
+
+kprobe:xfs_file_read_iter,
+kprobe:xfs_file_write_iter,
+kprobe:xfs_file_open,
+kprobe:xfs_file_fsync
+{
+	@start[tid] = nsecs;
+	@name[tid] = func;
+}
+
+kretprobe:xfs_file_read_iter,
+kretprobe:xfs_file_write_iter,
+kretprobe:xfs_file_open,
+kretprobe:xfs_file_fsync
+/@start[tid]/
+{
+	@us[@name[tid]] = hist((nsecs - @start[tid]) / 1000);
+	delete(@start[tid]);
+	delete(@name[tid]);
+}

tools/xfsdist_example.txt

+Demonstrations of xfsdist, the Linux bpftrace/eBPF version.
+
+
+xfsdist traces XFS reads, writes, opens, and fsyncs, and summarizes their
+latency as a power-of-2 histogram. For example:
+
+# xfsdist.bt
+Attaching 9 probes...
+Tracing XFS operation latency... Hit Ctrl-C to end.
+^C
+
+@us[xfs_file_write_iter]:
+[0, 1]                 0 |                                                    |
+[2, 4)                 0 |                                                    |
+[4, 8)                 0 |                                                    |
+[8, 16)                1 |@@@@@@@@@@@@@@@@@@@@@@@@@@                          |
+[16, 32)               2 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
+
+@us[xfs_file_read_iter]:
+[0, 1]               724 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
+[2, 4)               137 |@@@@@@@@@                                           |
+[4, 8)               143 |@@@@@@@@@@                                          |
+[8, 16)               37 |@@                                                  |
+[16, 32)              11 |                                                    |
+[32, 64)              22 |@                                                   |
+[64, 128)              7 |                                                    |
+[128, 256)             0 |                                                    |
+[256, 512)           485 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@                  |
+[512, 1K)            149 |@@@@@@@@@@                                          |
+[1K, 2K)              98 |@@@@@@@                                             |
+[2K, 4K)              85 |@@@@@@                                              |
+[4K, 8K)              27 |@                                                   |
+[8K, 16K)             29 |@@                                                  |
+[16K, 32K)            25 |@                                                   |
+[32K, 64K)             1 |                                                    |
+[64K, 128K)            0 |                                                    |
+[128K, 256K)           6 |                                                    |
+
+@us[xfs_file_open]:
+[0, 1]              1819 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
+[2, 4)               272 |@@@@@@@                                             |
+[4, 8)                 0 |                                                    |
+[8, 16)                9 |                                                    |
+[16, 32)               7 |                                                    |
+
+This output shows a bi-modal distribution for read latency, with a faster
+mode of 724 reads that took between 0 and 1 microseconds, and a slower
+mode of over 485 reads that took between 256 and 512 microseconds. It's
+likely that the faster mode was a hit from the in-memory file system cache,
+and the slower mode is a read from a storage device (disk).
+
+This "latency" is measured from when the operation was issued from the VFS
+interface to the file system, to when it completed. This spans everything:
+block device I/O (disk I/O), file system CPU cycles, file system locks, run
+queue latency, etc. This is a better measure of the latency suffered by
+applications reading from the file system than measuring this down at the
+block device interface.
+
+Note that this only traces the common file system operations previously
+listed: other file system operations (eg, inode operations including
+getattr()) are not traced.
+
+
+There is another version of this tool in bcc: https://github.com/iovisor/bcc
+The bcc version provides command line options to customize the output.