Add tracepoints for taskq entry lifetime events

This adds some new DTRACE_PROBE* endpoints so that we can observe taskq
latencies on a system. Additionally, a new "taskqlatency.bt" script is
added to do this observation via "bpftrace". Lastly, a "zfs-trace.sh"
script is added to wrap "bpftrace" with the proper options required to
run and use "taskqlatency.bt".

For example, with these changes in place, a user can run the following:

    $ cd ./contrib/bpftrace
    $ sudo ./zfs-trace.sh taskqlatency.bt
    Attaching 6 probes...
    ^C

Here's some example output, showing latency information for time spent
executing the taskq entry's function:

    @exec_lat_us[dp_sync_taskq, userquota_updates_task]:
    [2, 4)                 5 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
    [4, 8)                 0 |                                                    |
    [8, 16)                1 |@@@@@@@@@@                                          |
    [16, 32)               2 |@@@@@@@@@@@@@@@@@@@@                                |

    @exec_lat_us[z_wr_int_h, zio_execute]:
    [8, 16)               16 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
    [16, 32)               2 |@@@@@@                                              |

    @exec_lat_us[z_wr_iss_h, zio_execute]:
    [16, 32)               4 |@@@@@@@@@@@@@@@@                                    |
    [32, 64)              13 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
    [64, 128)              1 |@@@@                                                |

    @exec_lat_us[z_ioctl_int, zio_execute]:
    [2, 4)                 1 |@@@@                                                |
    [4, 8)                11 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
    [8, 16)                8 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@               |

    @exec_lat_us[dp_sync_taskq, sync_dnodes_task]:
    [2, 4)                 1 |@@@@@@                                              |
    [4, 8)                 7 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@       |
    [8, 16)                8 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
    [16, 32)               2 |@@@@@@@@@@@@@                                       |
    [32, 64)               4 |@@@@@@@@@@@@@@@@@@@@@@@@@@                          |
    [64, 128)              1 |@@@@@@                                              |
    [128, 256)             0 |                                                    |
    [256, 512)             1 |@@@@@@

Here's some example output, showing latency information for time spent
waiting on the taskq, prior to starting execution of entry's function:

    @queue_lat_us[dp_sync_taskq]:
    [2, 4)                 1 |@@@@                                                |
    [4, 8)                 7 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@                      |
    [8, 16)                2 |@@@@@@@@                                            |
    [16, 32)               3 |@@@@@@@@@@@@@                                       |
    [32, 64)              12 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
    [64, 128)              6 |@@@@@@@@@@@@@@@@@@@@@@@@@@                          |
    [128, 256)             0 |                                                    |
    [256, 512)             1 |@@@@                                                |

    @queue_lat_us[z_wr_iss]:
    [4, 8)                 4 |@@@@                                                |
    [8, 16)               13 |@@@@@@@@@@@@@@@                                     |
    [16, 32)               6 |@@@@@@@                                             |
    [32, 64)               2 |@@                                                  |
    [64, 128)             12 |@@@@@@@@@@@@@@                                      |
    [128, 256)            15 |@@@@@@@@@@@@@@@@@@                                  |
    [256, 512)            33 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@             |
    [512, 1K)             27 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@                    |
    [1K, 2K)               7 |@@@@@@@@                                            |
    [2K, 4K)              14 |@@@@@@@@@@@@@@@@                                    |
    [4K, 8K)              14 |@@@@@@@@@@@@@@@@                                    |
    [8K, 16K)             23 |@@@@@@@@@@@@@@@@@@@@@@@@@@@                         |
    [16K, 32K)            43 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|

    @queue_lat_us[z_wr_int]:
    [2, 4)                10 |@@@@@                                               |
    [4, 8)                71 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@           |
    [8, 16)               88 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
    [16, 32)              50 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@                       |
    [32, 64)              65 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@              |
    [64, 128)             43 |@@@@@@@@@@@@@@@@@@@@@@@@@                           |
    [128, 256)            19 |@@@@@@@@@@@                                         |
    [256, 512)             3 |@                                                   |
    [512, 1K)              1 |                                                    |

Reviewed by: Brad Lewis <[email protected]>
Reviewed-by: Brian Behlendorf <[email protected]>
Signed-off-by: Prakash Surya <[email protected]>
Closes #9525

4 files changed, 69 insertions, 2 deletions

diff --git a/contrib/Makefile.am b/contrib/Makefile.am
index 9a82f82ee..9f34fd835 100644
--- a/contrib/Makefile.am
+++ b/contrib/Makefile.am
@@ -1,2 +1,2 @@
-SUBDIRS = bash_completion.d dracut initramfs pyzfs zcp
-DIST_SUBDIRS = bash_completion.d dracut initramfs pyzfs zcp
+SUBDIRS = bash_completion.d bpftrace dracut initramfs pyzfs zcp
+DIST_SUBDIRS = bash_completion.d bpftrace dracut initramfs pyzfs zcp
diff --git a/contrib/bpftrace/Makefile.am b/contrib/bpftrace/Makefile.am
new file mode 100644
index 000000000..c4359e6c8
--- /dev/null
+++ b/contrib/bpftrace/Makefile.am
@@ -0,0 +1,3 @@
+EXTRA_DIST = \
+	$(top_srcdir)/contrib/bpftrace/taskqlatency.bt \
+	$(top_srcdir)/contrib/bpftrace/zfs-trace.sh
diff --git a/contrib/bpftrace/taskqlatency.bt b/contrib/bpftrace/taskqlatency.bt
new file mode 100644
index 000000000..598f9882b
--- /dev/null
+++ b/contrib/bpftrace/taskqlatency.bt
@@ -0,0 +1,54 @@
+#include <sys/taskq.h>
+
+kprobe:trace_zfs_taskq_ent__birth
+{
+        $tqent = (struct taskq_ent *)arg0;
+
+        $tqent_id = $tqent->tqent_id;
+        $tq_name = str($tqent->tqent_taskq->tq_name);
+
+        @birth[$tq_name, $tqent_id] = nsecs;
+}
+
+kprobe:trace_zfs_taskq_ent__start
+{
+        $tqent = (struct taskq_ent *)arg0;
+
+        @tqent_id[tid] = $tqent->tqent_id;
+        @tq_name[tid] = str($tqent->tqent_taskq->tq_name);
+
+        @start[@tq_name[tid], @tqent_id[tid]] = nsecs;
+}
+
+kprobe:trace_zfs_taskq_ent__start
+/ @birth[@tq_name[tid], @tqent_id[tid]] /
+{
+        @queue_lat_us[@tq_name[tid]] =
+                hist((nsecs - @birth[@tq_name[tid], @tqent_id[tid]])/1000);
+        delete(@birth[@tq_name[tid], @tqent_id[tid]]);
+}
+
+kprobe:trace_zfs_taskq_ent__finish
+/ @start[@tq_name[tid], @tqent_id[tid]] /
+{
+        $tqent = (struct taskq_ent *)arg0;
+
+        @exec_lat_us[@tq_name[tid], ksym($tqent->tqent_func)] =
+                hist((nsecs - @start[@tq_name[tid], @tqent_id[tid]])/1000);
+        delete(@start[@tq_name[tid], @tqent_id[tid]]);
+}
+
+kprobe:trace_zfs_taskq_ent__finish
+{
+        delete(@tq_name[tid]);
+        delete(@tqent_id[tid]);
+}
+
+END
+{
+        clear(@birth);
+        clear(@start);
+
+        clear(@tq_name);
+        clear(@tqent_id);
+}
diff --git a/contrib/bpftrace/zfs-trace.sh b/contrib/bpftrace/zfs-trace.sh
new file mode 100755
index 000000000..13230b78c
--- /dev/null
+++ b/contrib/bpftrace/zfs-trace.sh
@@ -0,0 +1,10 @@
+#!/bin/sh
+
+ZVER=$(cat /sys/module/zfs/version | cut -f 1 -d '-')
+KVER=$(uname -r)
+
+bpftrace \
+	--include "/usr/src/zfs-$ZVER/$KVER/zfs_config.h" \
+	-I "/usr/src/zfs-$ZVER/include" \
+	-I "/usr/src/zfs-$ZVER/include/spl" \
+	"$@"