From 9037b91365c88f4d0447b09a4d6e54b27f2ed51c Mon Sep 17 00:00:00 2001 From: Fabian Keil Date: Wed, 23 Aug 2017 08:50:43 +0200 Subject: [PATCH 187/325] share/dtrace: Import bio-request-latency Obtained from: ElectroBSD --- share/dtrace/Makefile | 1 + share/dtrace/bio-request-latency | 116 +++++++++++++++++++++++++++++++ 2 files changed, 117 insertions(+) create mode 100755 share/dtrace/bio-request-latency diff --git a/share/dtrace/Makefile b/share/dtrace/Makefile index 4386cba69afe..66d0639ba365 100644 --- a/share/dtrace/Makefile +++ b/share/dtrace/Makefile @@ -6,6 +6,7 @@ .include SCRIPTS= blocking \ + bio-request-latency \ disklatency \ disklatencycmd \ fbt-time \ diff --git a/share/dtrace/bio-request-latency b/share/dtrace/bio-request-latency new file mode 100755 index 000000000000..be107a88edf2 --- /dev/null +++ b/share/dtrace/bio-request-latency @@ -0,0 +1,116 @@ +#!/usr/sbin/dtrace -s +/*************************************************************************** + * bio-request-latency.d + * + * Shows the latency for each disk and BIO type. + * + * io probes without BIO are ignored as they don't provide + * enough information. For details see: + * https://bugs.freebsd.org/bugzilla/show_bug.cgi?id=220965 + * + * Inspired by: + * http://dtrace.org/blogs/ahl/2014/08/31/openzfs-tuning/ + * + * Copyright (c) 2017 Fabian Keil + * + * Permission to use, copy, modify, and distribute this software for any + * purpose with or without fee is hereby granted, provided that the above + * copyright notice and this permission notice appear in all copies. + * + * THE SOFTWARE IS PROVIDED "AS IS" AND THE AUTHOR DISCLAIMS ALL WARRANTIES + * WITH REGARD TO THIS SOFTWARE INCLUDING ALL IMPLIED WARRANTIES OF + * MERCHANTABILITY AND FITNESS. IN NO EVENT SHALL THE AUTHOR BE LIABLE FOR + * ANY SPECIAL, DIRECT, INDIRECT, OR CONSEQUENTIAL DAMAGES OR ANY DAMAGES + * WHATSOEVER RESULTING FROM LOSS OF USE, DATA OR PROFITS, WHETHER IN AN + * ACTION OF CONTRACT, NEGLIGENCE OR OTHER TORTIOUS ACTION, ARISING OUT OF + * OR IN CONNECTION WITH THE USE OR PERFORMANCE OF THIS SOFTWARE. + ***************************************************************************/ + +#pragma D option quiet +#pragma D option dynvarsize=10m + +BEGIN +{ + start = timestamp; + bogus_timestamps = 0; + + bio_command[0x01] = "BIO_READ"; + bio_command[0x02] = "BIO_WRITE"; + bio_command[0x03] = "BIO_DELETE"; + bio_command[0x04] = "BIO_GETATTR"; + bio_command[0x05] = "BIO_FLUSH"; + bio_command[0x06] = "BIO_CMD0"; + bio_command[0x07] = "BIO_CMD1"; + bio_command[0x08] = "BIO_CMD2"; + bio_command[0x09] = "BIO_ZONE"; +} + +io:::start +/arg0 != NULL/ +{ + io_start[arg0] = timestamp; +} + +/* Cache timestamp so we can sanity check it */ +io:::done +{ + this->timestamp = timestamp; +} + +io:::done +/arg0 != NULL && io_start[arg0] && io_start[arg0] > this->timestamp/ +{ + /* + * At least in theory the timestamps goes up, in practice + * timestamps can jump back due to bugs like: + * https://bugs.freebsd.org/bugzilla/show_bug.cgi?id=218452 + * + * If this happens the timestamp delta is obviously useless + * for our purposes so lets not include it in the stats. + */ + bogus_timestamps++; + io_start[arg0] = 0; +} + +/* If this section gets entered this->timestamp isn't obviouly bogus */ +io:::done +/arg0 != NULL && io_start[arg0]/ +{ + this->delta = (this->timestamp - io_start[arg0]) / 1000; + this->bio_command = (bio_command[args[0]->bio_cmd] != NULL) ? + bio_command[args[0]->bio_cmd] : "Unregistered command"; + this->disk_name = stringof(args[0]->bio_disk->d_geom->name); + + @quantize[this->disk_name, this->bio_command] = quantize(this->delta); + @average[this->disk_name, this->bio_command] = avg(this->delta); + @stddev[this->disk_name, this->bio_command] = stddev(this->delta); + @max[this->disk_name, this->bio_command] = max(this->delta); + @min[this->disk_name, this->bio_command] = min(this->delta); + @requests[this->disk_name, this->bio_command] = count(); + @ios[this->disk_name, this->bio_command] = count(); + @throughput[this->disk_name, this->bio_command] = sum(args[0]->bio_length); + + io_start[arg0] = 0; +} + +END +{ + printa(@quantize); + + normalize(@ios, (timestamp - start) / 1000000000); + normalize(@throughput, (timestamp - start) / 1000000000 * 1024); + + printf("%-8s %-12s %10s | %-15s %-23s | %6s %12s\n", + "Disk", "Bio Type", "Requests", "", "Latency in us", "iops", "Throughput"); + printf("%-32s | %9s %9s %9s %9s |\n", "", "avg", "stddev", "max", "min"); + printa("%-8s %-12s %@10u | %@9u %@9u %@9u %@9u | %@6u %@8u k/s\n", + @requests, @average, @stddev, @max, @min, @ios, @throughput); +} + +END +/bogus_timestamps != 0/ +{ + printf("\nLatency for %d requests not measured due to obviously bogus timestamps.\n", + bogus_timestamps); + printf("Note that some of the other measurements may be based on less-obviously bogus timestamps.\n"); +} -- 2.32.0