chore(log): adding higher latency log per IO (openzfs#184) (openzfs#189)

When replica gets disconnected with target due to timeout, there might be some IOs that are not responded for long time. There are ZIO delay logs that helps in debugging this issue. This PR is to logs at uZFS layer regarding high latent IOs. Signed-off-by: Vishnu Itta <[email protected]>
prateekpandey14 · Feb 13, 2019 · 14b6742 · 14b6742
1 parent 0787843
commit 14b6742
Showing 1 changed file with 8 additions and 2 deletions.
diff --git a/lib/libzrepl/data_conn.c b/lib/libzrepl/data_conn.c
@@ -41,6 +41,7 @@
 
 #define	MAXEVENTS 64
 
+#define	IO_THRESHOLD_TIME	30
 #define	ZVOL_REBUILD_STEP_SIZE  (10 * 1024ULL * 1024ULL * 1024ULL) // 10GB
 uint64_t zvol_rebuild_step_size = ZVOL_REBUILD_STEP_SIZE;
 
@@ -1812,6 +1813,7 @@ uzfs_zvol_io_ack_sender(void *arg)
 			}
 		}
 
+		latency = 0;
 		if (zio_cmd->hdr.opcode == ZVOL_OPCODE_READ) {
 			if (zio_cmd->hdr.status == ZVOL_OP_STATUS_OK) {
 				/* Send data read from disk */
@@ -1859,10 +1861,14 @@ uzfs_zvol_io_ack_sender(void *arg)
 				}
 			} else if (zio_cmd->hdr.opcode == ZVOL_OPCODE_SYNC) {
 				atomic_inc_64(&zinfo->sync_req_ack_cnt);
-				atomic_add_64(&zinfo->sync_latency,
-				    gethrtime() - zio_cmd->io_start_time);
+				latency = (gethrtime() -
+				    zio_cmd->io_start_time);
+				atomic_add_64(&zinfo->sync_latency, latency);
 			}
 		}
+		if ((latency >> 30) > IO_THRESHOLD_TIME)
+			LOG_INFO("IO %d with seq: %lu took %luns",
+			    zio_cmd->hdr.opcode, zio_cmd->hdr.io_seq, latency);
 		zinfo->zio_cmd_in_ack = NULL;
 		zio_cmd_free(&zio_cmd);
 	}