zfsonlinux/zfs — pull request #2397 by prakashsurya (2014-06-14 03:01:50+00:00)
Title: Replace DTRACE_PROBE* with Linux tracepoints (WIP)

Replace DTRACE_PROBE* with Linux tracepoints (WIP)

1. This is only a proof of concept. Thus, it is far from complete
and may not even be correct; but, for now, it'll suffice.

2. Linux tracepoints appear to only be available to GPL licensed
modules due to the way certain kernel functions are exported.
I've seen compilation failures due to the following two
functions, but there may be others that I haven't checked:
ring_buffer_discard_commit() and perf_tp_event()

3. Prior to upstream kernel version v3.14-rc6-30-g66cc69e, Linux
tracepoints are not available for unsigned kernel modules if the
kernel config option, CONFIG_MODULE_SIG, is enabled. The kernel
would disabled tracepoints for that module with this message:

"module has bad taint, not creating trace events"

Thus, to test this patch out, signed zfs kernel modules or a
kernel version v3.14-rc6-30-g66cc69e or newer is needed.

OK, now that that's out of the way, lets get into the description of
what this patch actually does.

This patch is a first attempt at leveraging the functionality the Linux
kernel provides via Linux tracepoints. Many Linux performance, debugging,
and analysis tools (e.g. perf, ftrace, systemtap) are capable of using
these tracepoints for a variety of purposes. By integrating the ZFS on
Linux code with Linux tracepoints, developers and users would be able to
use these tools for deep analysis of ZFS and related sub-systems.

This patch replaces all of the DTRACE_PROBE1 call sites found in arc.c
(which were no-ops) with Linux tracepoints. Thus, with a suitably
configured kernel, this patch will provide a number of useful
tracepoints for understanding exactly what the ARC is doing.

The following is a quick example showcasing the inserted tracepoints:

# Show filesystem configuration
$ zfs list
NAME USED AVAIL REFER MOUNTPOINT
tank 106K 7.81G 30K /tank

# List all available zfs events
$ ls /sys/kernel/debug/tracing/events/zfs
enable filter zfs_arc_arc_delete
zfs_arc_arc_evict zfs_arc_arc_hit zfs_arc_l2arc_hit
zfs_arc_l2arc_miss zfs_arc_new_state_mfu zfs_arc_new_state_mru

# Enable a tracepoint and clear the tracepoint buffer
$ echo 1 > /sys/kernel/debug/tracing/events/zfs/zfs_arc_arc_hit/enable
$ echo 0 > /sys/kernel/debug/tracing/trace

# Create a new empty file in ZFS and dump the tracepoint buffer
$ touch /tank/file
$ cat /sys/kernel/debug/tracing/trace
# tracer: nop
#
# entries-in-buffer/entries-written: 11/11 #P:8
#
# _-----=> irqs-off
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / delay
# TASK-PID CPU# |||| TIMESTAMP FUNCTION
# | | | |||| | |
touch-26325 [000] .... 16648.644307: zfs_arc_arc_hit: dva 1:3 birth 4 cksum0 0x10c78b174 flags 0x260 datacnt 1 type 1 size 512 spa 14926363338598041761 state_type 3 mru_hits 0 mru_ghost_hits 1 mfu_hits 0 mfu_ghost_hits 0 l2_hits 0 refcount 1
touch-26325 [000] .... 16648.644323: zfs_arc_arc_hit: dva 1:3 birth 4 cksum0 0x10c78b174 flags 0x260 datacnt 1 type 1 size 512 spa 14926363338598041761 state_type 3 mru_hits 0 mru_ghost_hits 1 mfu_hits 1 mfu_ghost_hits 0 l2_hits 0 refcount 1
touch-26325 [000] .... 16648.644442: zfs_arc_arc_hit: dva 1:3 birth 4 cksum0 0x10c78b174 flags 0x260 datacnt 1 type 1 size 512 spa 14926363338598041761 state_type 3 mru_hits 0 mru_ghost_hits 1 mfu_hits 2 mfu_ghost_hits 0 l2_hits 0 refcount 1
txg_sync-26240 [000] .... 16650.835535: zfs_arc_arc_hit: dva 1:28 birth 4 cksum0 0x191bc63d9 flags 0x260 datacnt 1 type 1 size 512 spa 14926363338598041761 state_type 3 mru_hits 0 mru_ghost_hits 1 mfu_hits 0 mfu_ghost_hits 0 l2_hits 0 refcount 1
txg_sync-26240 [000] .... 16650.836168: zfs_arc_arc_hit: dva 1:29 birth 4 cksum0 0x191bc641f flags 0x260 datacnt 1 type 1 size 512 spa 14926363338598041761 state_type 3 mru_hits 0 mru_ghost_hits 1 mfu_hits 0 mfu_ghost_hits 0 l2_hits 0 refcount 1
txg_sync-26240 [006] .... 16650.843426: zfs_arc_arc_hit: dva 1:119 birth 63 cksum0 0x17da9785f2 flags 0x260 datacnt 1 type 1 size 4096 spa 14926363338598041761 state_type 1 mru_hits 0 mru_ghost_hits 0 mfu_hits 0 mfu_ghost_hits 0 l2_hits 0 refcount 1
txg_sync-26240 [006] .... 16650.843449: zfs_arc_arc_hit: dva 1:121 birth 63 cksum0 0x1920d7be93 flags 0x260 datacnt 1 type 1 size 4096 spa 14926363338598041761 state_type 1 mru_hits 0 mru_ghost_hits 0 mfu_hits 0 mfu_ghost_hits 0 l2_hits 0 refcount 1
txg_sync-26240 [006] .... 16650.843469: zfs_arc_arc_hit: dva 1:120 birth 63 cksum0 0x1920d7be93 flags 0x260 datacnt 1 type 1 size 4096 spa 14926363338598041761 state_type 1 mru_hits 0 mru_ghost_hits 0 mfu_hits 0 mfu_ghost_hits 0 l2_hits 0 refcount 1
txg_sync-26240 [006] .... 16650.845858: zfs_arc_arc_hit: dva 1:119 birth 63 cksum0 0x183eb122ea flags 0x260 datacnt 1 type 1 size 4096 spa 14926363338598041761 state_type 1 mru_hits 0 mru_ghost_hits 0 mfu_hits 0 mfu_ghost_hits 0 l2_hits 0 refcount 1
txg_sync-26240 [006] .... 16650.845884: zfs_arc_arc_hit: dva 1:121 birth 63 cksum0 0x1aad65da27 flags 0x260 datacnt 1 type 1 size 4096 spa 14926363338598041761 state_type 1 mru_hits 0 mru_ghost_hits 0 mfu_hits 0 mfu_ghost_hits 0 l2_hits 0 refcount 1
txg_sync-26240 [006] .... 16650.845905: zfs_arc_arc_hit: dva 1:120 birth 63 cksum0 0x1aad65da27 flags 0x260 datacnt 1 type 1 size 4096 spa 14926363338598041761 state_type 1 mru_hits 0 mru_ghost_hits 0 mfu_hits 0 mfu_ghost_hits 0 l2_hits 0 refcount 1

As one can see, the tracepoint provides a significant amount of
information regarding each ARC buffer that received a hit, along with
the process that caused it. This type of in depth information can prove
invaluable when trying to understand a system that's under any
non-trivial workload.

My hope is that this quick and dirty proof of concept sparks a more
thorough and in-depth look into how we can leverage Linux tracepoints
for our various needs (e.g. debugging, performance profiling, etc).

For anybody looking to pick up this work and extend it, these following
three links along with the XFS source code proved to be an excellent
reference and extremely helpful:

* http://lwn.net/Articles/379903/
* http://lwn.net/Articles/381064/
* http://lwn.net/Articles/383362/

Signed-off-by: Prakash Surya