1# -*- tab-width: 4 -*- ;; Emacs 2# vi: set filetype=sh tabstop=8 shiftwidth=8 noexpandtab :: Vi/ViM 3############################################################ IDENT(1) 4# 5# $Title: dwatch(8) module for dtrace_io(4) $ 6# $Copyright: 2014-2026 Devin Teske. All rights reserved. $ 7# 8############################################################ DESCRIPTION 9# 10# Display activity related to disk I/O. The io-slow profile instead 11# measures per-request latency -- the time between io:::start and 12# io:::done for the same struct bio -- printing any request that meets 13# a threshold (default 100 ms; tunable via DWATCH_IO_MS in the 14# environment, 0 to show everything). Answers "is the application slow 15# because the disk is slow?" and, watched per-device, hunts I/O 16# starvation; on ZFS, watched against zvols and the pool's leaf vdevs, 17# it brackets where in the stack the time is going. 18# 19############################################################ PROBE 20 21case "$PROFILE" in 22io) : ${PROBE:=io:::start, io:::done} ;; 23io-slow) : ${PROBE:=io:::done} ;; 24 *) : ${PROBE:=io:::${PROFILE#io-}} 25esac 26 27############################################################ EVENT ACTION 28 29if [ "$PROFILE" = "io-slow" ]; then 30 : ${DWATCH_IO_MS:=100} 31 32 case "$DWATCH_IO_MS" in 33 ""|*[!0-9]*) die "DWATCH_IO_MS must be a number" ;; # NOTREACHED 34 esac 35 36 [ "$CUSTOM_TEST" ] || 37 EVENT_TEST="this->devinfo.dev_name != \"\" && 38 this->io_ns >= (int64_t)$DWATCH_IO_MS * 1000000" 39else 40 [ "$CUSTOM_TEST" ] || EVENT_TEST='this->devinfo.dev_name != ""' 41fi 42 43############################################################ ACTIONS 44 45exec 9<<EOF 46this bufinfo_t bufinfo; 47this devinfo_t devinfo; 48this int b_flags; 49this long bio_length; 50this string bio_cmd; 51this string bio_flags; 52this string device_entry; 53this string device_if; 54this string device_type; 55this string flow; 56 57inline string append_bio_flag[int flags, int flag] = this->bio_flags = 58 strjoin(this->bio_flags, 59 strjoin(this->bio_flags == "" ? "" : (flags & flag) == flag ? "|" : "", 60 bio_flag_string[flags & flag])); 61 62$PROBE /(struct bio *)args[0] != NULL/ /* probe ID $ID */ 63{${TRACE:+ 64 printf("<$ID>"); 65} 66 /* 67 * dtrace_io(4) 68 */ 69 this->flow = probefunc == "done" ? "<-" : "->"; 70 71 /* 72 * struct bio * 73 */ 74 this->bufinfo = xlate <bufinfo_t> ((struct bio *)args[0]); 75 this->bio_cmd = bio_cmd_string[(int)this->bufinfo.b_cmd]; 76 this->b_flags = (int)this->bufinfo.b_flags; 77 this->bio_flags = bio_flag_string[this->b_flags & BIO_ERROR]; 78 this->bio_flags = strjoin(this->bio_flags, this->bufinfo.b_error ? 79 strjoin(this->bio_flags == "" ? 80 bio_flag_string[BIO_ERROR] : "", 81 strjoin("#", lltostr(this->bufinfo.b_error))) : 82 ""); 83 append_bio_flag[this->b_flags, BIO_DONE]; 84 append_bio_flag[this->b_flags, BIO_ONQUEUE]; 85 append_bio_flag[this->b_flags, BIO_ORDERED]; 86 append_bio_flag[this->b_flags, BIO_UNMAPPED]; 87 append_bio_flag[this->b_flags, BIO_TRANSIENT_MAPPING]; 88 append_bio_flag[this->b_flags, BIO_VLIST]; 89 this->bio_flags = this->bio_flags == "" ? "-" : this->bio_flags; 90 this->bio_length = (long)this->bufinfo.b_bcount; 91 92 /* 93 * struct devstat * 94 */ 95 this->devinfo = xlate <devinfo_t> ((struct devstat *)args[1]); 96 this->device_type = device_type[(int)this->devinfo.dev_type]; 97 this->device_if = device_if[(int)this->devinfo.dev_type]; 98 this->device_entry = strjoin(this->devinfo.dev_name, 99 lltostr(this->devinfo.dev_minor)); 100} 101EOF 102ACTIONS=$( cat <&9 ) 103ID=$(( $ID + 1 )) 104 105if [ "$PROFILE" = "io-slow" ]; then 106exec 9<<EOF 107$ACTIONS 108 109this int64_t io_ns; 110int64_t io_ts[uintptr_t]; 111 112io:::start /(struct bio *)args[0] != NULL/ /* probe ID $ID */ 113{${TRACE:+ 114 printf("<$ID>"); 115} 116 io_ts[(uintptr_t)args[0]] = timestamp; 117} 118 119$PROBE /(struct bio *)args[0] != NULL/ /* probe ID $(( $ID + 1 )) */ 120{${TRACE:+ 121 printf("<$(( $ID + 1 ))>"); 122} 123 /* NB: -1 if we did not see the start (enabled mid-request) */ 124 this->io_ns = io_ts[(uintptr_t)args[0]] ? 125 timestamp - io_ts[(uintptr_t)args[0]] : -1; 126 io_ts[(uintptr_t)args[0]] = 0; 127} 128EOF 129ACTIONS=$( cat <&9 ) 130ID=$(( $ID + 2 )) 131fi 132 133############################################################ EVENT DETAILS 134 135if [ "$PROFILE" = "io-slow" ] && [ ! "$CUSTOM_DETAILS" ]; then 136exec 9<<EOF 137 /* 138 * Print disk I/O latency details 139 */ 140 printf("%s %s %s %s %d byte%s %d.%03d ms", 141 this->device_type, 142 this->device_entry, 143 this->bio_cmd, 144 this->bio_flags, 145 this->bio_length, 146 this->bio_length == 1 ? "" : "s", 147 this->io_ns / 1000000, 148 (this->io_ns % 1000000) / 1000); 149EOF 150EVENT_DETAILS=$( cat <&9 ) 151elif [ ! "$CUSTOM_DETAILS" ]; then 152exec 9<<EOF 153 /* 154 * Print disk I/O details 155 */ 156 printf("%s %s %s %s %s %s %d byte%s", 157 this->flow, 158 this->device_type, 159 this->device_if, 160 this->device_entry, 161 this->bio_cmd, 162 this->bio_flags, 163 this->bio_length, 164 this->bio_length == 1 ? "" : "s"); 165EOF 166EVENT_DETAILS=$( cat <&9 ) 167fi 168 169################################################################################ 170# END 171################################################################################ 172