Initial zio delay timing

While there is no right maximum timeout for a disk IO we can start
laying the ground work to measure how long they do take in practice.
This change simply measures the IO time and if it exceeds 30s an
event is posted for 'zpool events'.

This value was carefully selected because for sd devices it implies
that at least one timeout (SD_TIMEOUT) has occured.  Unfortunately,
even with FAILFAST set we may retry and request and not get an
error.  This behavior is strongly dependant on the device driver
and how it is hooked in to the scsi error handling stack.  However
by setting the limit at 30s we can log the event even if no error
was returned.

Slightly longer term we can start recording these delays perhaps
as a simple power-of-two histrogram.  This histogram can then be
reported as part of the 'zpool status' command when given an command
line option.

None of this code changes the internal behavior of ZFS.  Currently
it is simply for reporting excessively long delays.

3 files changed, 26 insertions, 3 deletions

diff --git a/module/zfs/vdev_disk.c b/module/zfs/vdev_disk.c
index 863392544..51062ef23 100644
--- a/module/zfs/vdev_disk.c
+++ b/module/zfs/vdev_disk.c
@@ -95,10 +95,10 @@ static void
 vdev_disk_error(zio_t *zio)
 {
 #ifdef ZFS_DEBUG
-	printk("ZFS: zio error=%d type=%d offset=%llu "
-	    "size=%llu flags=%x\n", zio->io_error, zio->io_type,
+	printk("ZFS: zio error=%d type=%d offset=%llu size=%llu "
+	    "flags=%x delay=%llu\n", zio->io_error, zio->io_type,
 	    (u_longlong_t)zio->io_offset, (u_longlong_t)zio->io_size,
-	    zio->io_flags);
+	    zio->io_flags, (u_longlong_t)zio->io_delay);
 #endif
 }
 
@@ -242,6 +242,8 @@ vdev_disk_dio_put(dio_request_t *dr)
 		vdev_disk_dio_free(dr);
 
 		if (zio) {
+			zio->io_delay = jiffies_to_msecs(
+			    jiffies_64 - zio->io_delay);
 			zio->io_error = error;
 			ASSERT3S(zio->io_error, >=, 0);
 			if (zio->io_error)
@@ -403,6 +405,8 @@ retry:
 
 	/* Extra reference to protect dio_request during submit_bio */
 	vdev_disk_dio_get(dr);
+	if (zio)
+		zio->io_delay = jiffies_64;
 
 	/* Submit all bio's associated with this dio */
 	for (i = 0; i < dr->dr_bio_count; i++)
@@ -442,6 +446,7 @@ BIO_END_IO_PROTO(vdev_disk_io_flush_completion, bio, size, rc)
 {
 	zio_t *zio = bio->bi_private;
 
+	zio->io_delay = jiffies_to_msecs(jiffies_64 - zio->io_delay);
 	zio->io_error = -rc;
 	if (rc && (rc == -EOPNOTSUPP))
 		zio->io_vd->vdev_nowritecache = B_TRUE;
@@ -472,6 +477,7 @@ vdev_disk_io_flush(struct block_device *bdev, zio_t *zio)
 	bio->bi_end_io = vdev_disk_io_flush_completion;
 	bio->bi_private = zio;
 	bio->bi_bdev = bdev;
+	zio->io_delay = jiffies_64;
 	submit_bio(WRITE_BARRIER, bio);
 
 	return 0;
diff --git a/module/zfs/zfs_fm.c b/module/zfs/zfs_fm.c
index dd15c5d63..74f2756e3 100644
--- a/module/zfs/zfs_fm.c
+++ b/module/zfs/zfs_fm.c
@@ -290,6 +290,8 @@ zfs_ereport_start(nvlist_t **ereport_out, nvlist_t **detector_out,
 		    DATA_TYPE_INT32, zio->io_error, NULL);
 		fm_payload_set(ereport, FM_EREPORT_PAYLOAD_ZFS_ZIO_FLAGS,
 		    DATA_TYPE_INT32, zio->io_flags, NULL);
+		fm_payload_set(ereport, FM_EREPORT_PAYLOAD_ZFS_ZIO_DELAY,
+		    DATA_TYPE_UINT64, zio->io_delay, NULL);
 
 		/*
 		 * If the 'size' parameter is non-zero, it indicates this is a
diff --git a/module/zfs/zio.c b/module/zfs/zio.c
index 70d3addf5..9f34a2338 100644
--- a/module/zfs/zio.c
+++ b/module/zfs/zio.c
@@ -75,6 +75,7 @@ kmem_cache_t *zio_link_cache;
 kmem_cache_t *zio_buf_cache[SPA_MAXBLOCKSIZE >> SPA_MINBLOCKSHIFT];
 kmem_cache_t *zio_data_buf_cache[SPA_MAXBLOCKSIZE >> SPA_MINBLOCKSHIFT];
 int zio_bulk_flags = 0;
+int zio_delay_max = ZIO_DELAY_MAX;
 
 #ifdef _KERNEL
 extern vmem_t *zio_alloc_arena;
@@ -2754,6 +2755,17 @@ zio_done(zio_t *zio)
 
 	vdev_stat_update(zio, zio->io_size);
 
+	/*
+	 * If this I/O is attached to a particular vdev is slow, exeeding
+	 * 30 seconds to complete, post an error described the I/O delay.
+	 * We ignore these errors if the device is currently unavailable.
+	 */
+	if (zio->io_delay >= zio_delay_max) {
+		if (zio->io_vd != NULL && !vdev_is_dead(zio->io_vd))
+			zfs_ereport_post(FM_EREPORT_ZFS_DELAY, zio->io_spa,
+                                         zio->io_vd, zio, 0, 0);
+	}
+
 	if (zio->io_error) {
 		/*
 		 * If this I/O is attached to a particular vdev,
@@ -2993,4 +3005,7 @@ EXPORT_SYMBOL(zio_type_name);
 
 module_param(zio_bulk_flags, int, 0644);
 MODULE_PARM_DESC(zio_bulk_flags, "Additional flags to pass to bulk buffers");
+
+module_param(zio_delay_max, int, 0644);
+MODULE_PARM_DESC(zio_delay_max, "Max zio delay before posting an event (ms)");
 #endif