From 3a63e6592f701209eee271df3a6d2f7d5d3321cb Mon Sep 17 00:00:00 2001 From: Vishnu Itta Date: Mon, 7 Jan 2019 18:46:56 +0530 Subject: [PATCH] chore(log): adding higher latency log per IO (#184) 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 --- lib/libzrepl/data_conn.c | 10 ++++++++-- 1 file changed, 8 insertions(+), 2 deletions(-) diff --git a/lib/libzrepl/data_conn.c b/lib/libzrepl/data_conn.c index e2881155e5b7..e65ffcdf49f1 100644 --- 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; @@ -1787,6 +1788,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 */ @@ -1834,10 +1836,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); }