summaryrefslogtreecommitdiffstats
path: root/contrib/bpftrace
diff options
context:
space:
mode:
authorPrakash Surya <[email protected]>2019-10-24 14:13:41 -0700
committerBrian Behlendorf <[email protected]>2019-11-01 13:14:54 -0700
commitae38e00968a1920eb3c1051df888b24301e2f82b (patch)
tree8c365cff0efe7622bbb649b50e3f00539a693fcb /contrib/bpftrace
parente5d1c27e30f1aecfde2a7a16830b2d34c2f5e975 (diff)
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
Diffstat (limited to 'contrib/bpftrace')
-rw-r--r--contrib/bpftrace/Makefile.am3
-rw-r--r--contrib/bpftrace/taskqlatency.bt54
-rwxr-xr-xcontrib/bpftrace/zfs-trace.sh10
3 files changed, 67 insertions, 0 deletions
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" \
+ "$@"