src/client_cmd.c src/client_cmd.h src/cmd.c src/delta_lease.c src/delta_lease.h src/direct.c src/diskio.c src/diskio.h src/lockspace.c src/main.c src/monotime.c src/monotime.h src/ondisk.c src/paxos_lease.c src/resource.c src/sanlock.8 src/sanlock_internal.h src/sanlock_sock.h

[David Teigland]

 src/client_cmd.c       |   54 +++++++++++++++++++
 src/client_cmd.h       |    1 
 src/cmd.c              |  136 +++++++++++++++++++++++++++++++++++++++++++++++++
 src/delta_lease.c      |   22 ++++++-
 src/delta_lease.h      |    3 -
 src/direct.c           |    4 +
 src/diskio.c           |   32 +++++++----
 src/diskio.h           |    4 -
 src/lockspace.c        |   54 ++++++++++++++++++-
 src/main.c             |   17 ++++++
 src/monotime.c         |   11 +++
 src/monotime.h         |    1 
 src/ondisk.c           |    1 
 src/paxos_lease.c      |   12 ++--
 src/resource.c         |    8 +-
 src/sanlock.8          |    4 +
 src/sanlock_internal.h |   15 +++++
 src/sanlock_sock.h     |    2 
 18 files changed, 349 insertions(+), 32 deletions(-)

New commits:
commit 6313c709722b3ba63234a75d1651a160bf1728ee
Author: David Teigland <teigland(a)redhat.com&gt;
Date:   Wed Mar 9 11:58:21 2016 -0600

    sanlock: renewal history
    
    Keep a history of read and write latencies for a lockspace.
    The times are measured for io in delta lease renewal
    (each delta lease renewal includes one read and one write).
    
    For each successful renewal, a record is saved that includes:
    - the timestamp written in the delta lease by the renewal
    - the time in milliseconds taken by the delta lease read
    - the time in milliseconds taken by the delta lease write
    
    Also counted and recorded are the number io timeouts and
    other io errors that occur between successful renewals.
    
    Two consecutive successful renewals would be recorded as:
    
    timestamp=5332 read_ms=482 write_ms=5525 next_timeouts=0 next_errors=0
    timestamp=5353 read_ms=99 write_ms=3161 next_timeouts=0 next_errors=0
    
    timestamp is the value written into the delta lease during
    that renewal.
    
    read_ms/write_ms are the milliseconds taken for the renewal
    read/write ios.
    
    next_timeouts are the number of io timeouts that occured
    after the renewal recorded on that line and before the next
    successful renewal on the following line.
    
    next_errors are the number of io errors (not timeouts) that
    occured after renewal recorded on that line and before the
    next successful renewal on the following line.
    
    The command 'sanlock client renewal -s lockspace_name' reports
    the full history of renewals saved by sanlock, which by default
    is 180 records, about 1 hour of history when using a 20 second
    renewal interval for a 10 second io timeout.
    
    (A --summary option could be added to calculate and report
    averages over a selected period of the history.)

diff --git a/src/client_cmd.c b/src/client_cmd.c
index 4d457be..fb22435 100644
--- a/src/client_cmd.c
+++ b/src/client_cmd.c
@@ -585,6 +585,60 @@ int sanlock_host_status(int debug, char *lockspace_name)
 	return 0;
 }
 
+int sanlock_renewal(char *lockspace_name)
+{
+	struct sm_header h;
+	struct sanlk_state st;
+	struct sanlk_lockspace lockspace;
+	char str[SANLK_STATE_MAXSTR];
+	int fd, rv;
+
+	if (!lockspace_name || !lockspace_name[0])
+		return -1;
+
+	fd = send_command(SM_CMD_RENEWAL, 0);
+	if (fd < 0)
+		return fd;
+
+	memset(&lockspace, 0, sizeof(lockspace));
+	snprintf(lockspace.name, SANLK_NAME_LEN, "%s", lockspace_name);
+
+	rv = send(fd, &lockspace, sizeof(lockspace), 0);
+	if (rv < 0)
+		goto out;
+
+	rv = recv(fd, &h, sizeof(h), MSG_WAITALL);
+	if (rv < 0) {
+		rv = -errno;
+		goto out;
+	}
+	if (rv != sizeof(h)) {
+		rv = -1;
+		goto out;
+	}
+
+	while (1) {
+		rv = recv(fd, &st, sizeof(st), MSG_WAITALL);
+		if (!rv)
+			break;
+		if (rv != sizeof(st))
+			break;
+
+		if (st.str_len) {
+			rv = recv(fd, str, st.str_len, MSG_WAITALL);
+			if (rv != st.str_len)
+				break;
+		}
+
+		printf("%s\n", str);
+	}
+
+	rv = h.data;
+ out:
+	close(fd);
+	return rv;
+}
+
 int sanlock_log_dump(int max_size)
 {
 	struct sm_header h;
diff --git a/src/client_cmd.h b/src/client_cmd.h
index f7c69c1..4632f5d 100644
--- a/src/client_cmd.h
+++ b/src/client_cmd.h
@@ -11,6 +11,7 @@
 
 int sanlock_status(int debug, char sort_arg);
 int sanlock_host_status(int debug, char *lockspace_name);
+int sanlock_renewal(char *lockspace_name);
 int sanlock_log_dump(int max_size);
 int sanlock_shutdown(uint32_t force, int wait_result);
 
diff --git a/src/cmd.c b/src/cmd.c
index 997ec21..abf0af4 100644
--- a/src/cmd.c
+++ b/src/cmd.c
@@ -2079,6 +2079,7 @@ static int print_state_daemon(char *str)
 		 "mlock_level=%d "
 		 "quiet_fail=%d "
 		 "debug_renew=%d "
+		 "renewal_history_size=%d "
 		 "gid=%d "
 		 "uid=%d "
 		 "sh_retries=%d "
@@ -2099,6 +2100,7 @@ static int print_state_daemon(char *str)
 		 com.mlock_level,
 		 com.quiet_fail,
 		 com.debug_renew,
+		 com.renewal_history_size,
 		 com.gid,
 		 com.uid,
 		 com.sh_retries,
@@ -2240,6 +2242,25 @@ static int print_state_host(struct host_status *hs, char *str)
 	return strlen(str) + 1;
 }
 
+static int print_state_renewal(struct renewal_history *hi, char *str)
+{
+	memset(str, 0, SANLK_STATE_MAXSTR);
+
+	snprintf(str, SANLK_STATE_MAXSTR-1,
+		 "timestamp=%llu "
+		 "read_ms=%d "
+		 "write_ms=%d "
+		 "next_timeouts=%d "
+		 "next_errors=%d",
+		 (unsigned long long)hi->timestamp,
+		 hi->read_ms,
+		 hi->write_ms,
+		 hi->next_timeouts,
+		 hi->next_errors);
+
+	return strlen(str) + 1;
+}
+
 static void send_state_daemon(int fd)
 {
 	struct sanlk_state st;
@@ -2364,6 +2385,26 @@ static void send_state_host(int fd, struct host_status *hs, int
host_id)
 		send(fd, str, str_len, MSG_NOSIGNAL);
 }
 
+static void send_state_renewal(int fd, struct renewal_history *hi)
+{
+	struct sanlk_state st;
+	char str[SANLK_STATE_MAXSTR];
+	int str_len;
+
+	memset(&st, 0, sizeof(st));
+
+	st.type = SANLK_STATE_RENEWAL;
+	st.data64 = hi->timestamp;
+
+	str_len = print_state_renewal(hi, str);
+
+	st.str_len = str_len;
+
+	send(fd, &st, sizeof(st), MSG_NOSIGNAL);
+	if (str_len)
+		send(fd, str, str_len, MSG_NOSIGNAL);
+}
+
 static void cmd_status(int fd, struct sm_header *h_recv, int client_maxi)
 {
 	struct sm_header h;
@@ -2475,6 +2516,97 @@ static void cmd_host_status(int fd, struct sm_header *h_recv)
 		free(status);
 }
 
+static void cmd_renewal(int fd, struct sm_header *h_recv)
+{
+	struct sm_header h;
+	struct sanlk_lockspace lockspace;
+	struct space *sp;
+	uint32_t io_timeout = 0;
+	struct renewal_history *history = NULL;
+	struct renewal_history *hi;
+	int history_size, history_prev, history_next;
+	int i, rv, len;
+
+	memset(&h, 0, sizeof(h));
+	memcpy(&h, h_recv, sizeof(struct sm_header));
+	h.version = SM_PROTO;
+	h.length = sizeof(h);
+	h.data = 0;
+
+	if (!com.renewal_history_size)
+		goto fail;
+
+	len = sizeof(struct renewal_history) * com.renewal_history_size;
+
+	history = malloc(len);
+	if (!history) {
+		h.data = -ENOMEM;
+		goto fail;
+	}
+
+	rv = recv(fd, &lockspace, sizeof(struct sanlk_lockspace), MSG_WAITALL);
+	if (rv != sizeof(struct sanlk_lockspace)) {
+		h.data = -ENOTCONN;
+		goto fail;
+	}
+
+	pthread_mutex_lock(&spaces_mutex);
+	sp = find_lockspace(lockspace.name);
+	if (sp) {
+		history_size = sp->renewal_history_size;
+		history_prev = sp->renewal_history_prev;
+		history_next = sp->renewal_history_next;
+		io_timeout = sp->io_timeout;
+
+		if (history_size != com.renewal_history_size) {
+			log_error("mismatch history size");
+			history_size = 0;
+			history_prev = 0;
+			history_next = 0;
+		} else {
+			memcpy(history, sp->renewal_history, len);
+		}
+	}
+	pthread_mutex_unlock(&spaces_mutex);
+
+	if (!sp) {
+		h.data = -ENOSPC;
+		goto fail;
+	}
+
+	if (!history_size || (!history_prev && !history_next))
+		goto fail;
+
+	h.data2 = io_timeout;
+
+	send(fd, &h, sizeof(h), MSG_NOSIGNAL);
+
+	/* If next slot is non-zero, then we've wrapped and
+	   should begin sending history from next to end
+	   before sending from 0 to prev. */
+
+	if (history[history_next].timestamp) {
+		for (i = history_next; i < history_size; i++) {
+			hi = &history[i];
+			send_state_renewal(fd, hi);
+		}
+	
+	}
+	for (i = 0; i < history_next; i++) {
+		hi = &history[i];
+		send_state_renewal(fd, hi);
+	}
+
+	if (history)
+		free(history);
+	return;
+ fail:
+	send(fd, &h, sizeof(h), MSG_NOSIGNAL);
+
+	if (history)
+		free(history);
+}
+
 static char send_data_buf[LOG_DUMP_SIZE];
 
 static void cmd_log_dump(int fd, struct sm_header *h_recv)
@@ -2715,6 +2847,10 @@ void call_cmd_daemon(int ci, struct sm_header *h_recv, int
client_maxi)
 		strcpy(client[ci].owner_name, "host_status");
 		cmd_host_status(fd, h_recv);
 		break;
+	case SM_CMD_RENEWAL:
+		strcpy(client[ci].owner_name, "renewal");
+		cmd_renewal(fd, h_recv);
+		break;
 	case SM_CMD_LOG_DUMP:
 		strcpy(client[ci].owner_name, "log_dump");
 		cmd_log_dump(fd, h_recv);
diff --git a/src/delta_lease.c b/src/delta_lease.c
index 3cf98fb..93aa418 100644
--- a/src/delta_lease.c
+++ b/src/delta_lease.c
@@ -466,13 +466,15 @@ int delta_lease_renew(struct task *task,
 		      int *read_result,
 		      int log_renewal_level,
 		      struct leader_record *leader_last,
-		      struct leader_record *leader_ret)
+		      struct leader_record *leader_ret,
+		      int *rd_ms, int *wr_ms)
 {
 	struct leader_record leader;
 	struct leader_record leader_end;
 	char **p_iobuf;
 	char **p_wbuf;
 	char *wbuf;
+	struct timespec begin, end, diff;
 	uint32_t checksum;
 	uint32_t reap_timeout_msec;
 	uint64_t host_id, id_offset, new_ts, now;
@@ -483,6 +485,9 @@ int delta_lease_renew(struct task *task,
 		return -EINVAL;
 	}
 
+	*rd_ms = -1;
+	*wr_ms = -1;
+
 	*read_result = SANLK_ERROR;
 
 	host_id = leader_last->owner_id;
@@ -527,12 +532,19 @@ int delta_lease_renew(struct task *task,
 			reap_timeout_msec = sp->renewal_read_extend_sec * 1000;
 		}
 
+		clock_gettime(CLOCK_MONOTONIC_RAW, &begin);
+
 		rv = read_iobuf_reap(disk->fd, disk->offset,
 				     task->iobuf, iobuf_len, task, reap_timeout_msec);
 
 		log_space(sp, "delta_renew reap %d", rv);
 
 		if (!rv) {
+			/* read time for this renewal is the io_timeout length
+			   for the previous read plus the time spent in reap. */
+			clock_gettime(CLOCK_MONOTONIC_RAW, &end);
+			ts_diff(&begin, &end, &diff);
+			*rd_ms = (diff.tv_sec * 1000) + (diff.tv_nsec / 1000000) + (sp->io_timeout *
1000);
 			task->read_iobuf_timeout_aicb = NULL;
 			goto read_done;
 		}
@@ -583,7 +595,7 @@ int delta_lease_renew(struct task *task,
 	if (log_renewal_level != -1)
 		log_level(sp->space_id, 0, NULL, log_renewal_level, "delta_renew begin
read");
 
-	rv = read_iobuf(disk->fd, disk->offset, task->iobuf, iobuf_len, task,
sp->io_timeout);
+	rv = read_iobuf(disk->fd, disk->offset, task->iobuf, iobuf_len, task,
sp->io_timeout, rd_ms);
 	if (rv) {
 		/* the next time delta_lease_renew() is called, prev_result
 		   will be this rv.  If this rv is SANLK_AIO_TIMEOUT, we'll
@@ -685,7 +697,7 @@ int delta_lease_renew(struct task *task,
 	   retrying unnecessarily would probably be counter productive. */
 
 	rv = write_iobuf(disk->fd, disk->offset+id_offset, wbuf, sector_size, task,
-			 calc_host_dead_seconds(sp->io_timeout));
+			 calc_host_dead_seconds(sp->io_timeout), wr_ms);
 
 	if (rv != SANLK_AIO_TIMEOUT)
 		free(wbuf);
@@ -835,7 +847,7 @@ int delta_lease_init(struct task *task,
 		memcpy(iobuf + (i * disk->sector_size), &leader_end, sizeof(struct
leader_record));
 	}
 
-	rv = write_iobuf(disk->fd, disk->offset, iobuf, iobuf_len, task, io_timeout);
+	rv = write_iobuf(disk->fd, disk->offset, iobuf, iobuf_len, task, io_timeout,
NULL);
 	if (rv < 0)
 		goto out;
 
@@ -855,7 +867,7 @@ int delta_lease_init(struct task *task,
 
 	memcpy(iobuf, &leader_end, sizeof(struct leader_record));
 
-	rv = write_iobuf(disk->fd, disk->offset, iobuf, disk->sector_size, task,
io_timeout);
+	rv = write_iobuf(disk->fd, disk->offset, iobuf, disk->sector_size, task,
io_timeout, NULL);
  out:
 	if (rv != SANLK_AIO_TIMEOUT)
 		free(iobuf);
diff --git a/src/delta_lease.h b/src/delta_lease.h
index 38c469a..0cfca29 100644
--- a/src/delta_lease.h
+++ b/src/delta_lease.h
@@ -35,7 +35,8 @@ int delta_lease_renew(struct task *task,
 		      int *read_result,
 		      int log_renewal_level,
                       struct leader_record *leader_last,
-                      struct leader_record *leader_ret);
+                      struct leader_record *leader_ret,
+		      int *rd_ms, int *wr_ms);
 
 int delta_lease_release(struct task *task,
                         struct space *sp,
diff --git a/src/direct.c b/src/direct.c
index c39988c..8fd6e10 100644
--- a/src/direct.c
+++ b/src/direct.c
@@ -201,6 +201,7 @@ static int do_delta_action(int action,
 	struct space space;
 	char bitmap[HOSTID_BITMAP_SIZE];
 	int read_result, rv;
+	int rd_ms, wr_ms;
 
 	memset(bitmap, 0, sizeof(bitmap));
 
@@ -253,7 +254,8 @@ static int do_delta_action(int action,
 				       &read_result,
 				       0,
 				       &leader,
-				       &leader);
+				       &leader,
+				       &rd_ms, &wr_ms);
 		break;
 	case ACT_RELEASE_ID:
 		rv = delta_lease_leader_read(task, io_timeout, &sd,
diff --git a/src/diskio.c b/src/diskio.c
index d5f06f2..4025f94 100644
--- a/src/diskio.c
+++ b/src/diskio.c
@@ -375,12 +375,13 @@ static struct aicb *find_callback_slot(struct task *task, int ioto)
  */
 
 static int do_linux_aio(int fd, uint64_t offset, char *buf, int len,
-			struct task *task, int ioto, int cmd)
+			struct task *task, int ioto, int cmd, int *ms)
 {
 	struct timespec ts;
 	struct aicb *aicb;
 	struct iocb *iocb;
 	struct io_event event;
+	struct timespec begin, end, diff;
 	const char *op_str;
 	int rv;
 
@@ -404,6 +405,9 @@ static int do_linux_aio(int fd, uint64_t offset, char *buf, int len,
 	iocb->u.c.nbytes = len;
 	iocb->u.c.offset = offset;
 
+	if (ms)
+		clock_gettime(CLOCK_MONOTONIC_RAW, &begin);
+
 	rv = io_submit(task->aio_ctx, 1, &iocb);
 	if (rv < 0) {
 		log_taske(task, "aio submit %d %p:%p:%p rv %d fd %d",
@@ -435,6 +439,12 @@ static int do_linux_aio(int fd, uint64_t offset, char *buf, int len,
 		struct aicb *ev_aicb = container_of(ev_iocb, struct aicb, iocb);
 		int op = ev_iocb ? ev_iocb->aio_lio_opcode : -1;
 
+		if (ms) {
+			clock_gettime(CLOCK_MONOTONIC_RAW, &end);
+			ts_diff(&begin, &end, &diff);
+			*ms = (diff.tv_sec * 1000) + (diff.tv_nsec / 1000000);
+		}
+
 		if (op == IO_CMD_PREAD)
 			op_str = "RD";
 		else if (op == IO_CMD_PWRITE)
@@ -508,15 +518,15 @@ static int do_linux_aio(int fd, uint64_t offset, char *buf, int
len,
 }
 
 static int do_write_aio_linux(int fd, uint64_t offset, char *buf, int len,
-			      struct task *task, int ioto)
+			      struct task *task, int ioto, int *wr_ms)
 {
-	return do_linux_aio(fd, offset, buf, len, task, ioto, IO_CMD_PWRITE);
+	return do_linux_aio(fd, offset, buf, len, task, ioto, IO_CMD_PWRITE, wr_ms);
 }
 
 static int do_read_aio_linux(int fd, uint64_t offset, char *buf, int len,
-			     struct task *task, int ioto)
+			     struct task *task, int ioto, int *rd_ms)
 {
-	return do_linux_aio(fd, offset, buf, len, task, ioto, IO_CMD_PREAD);
+	return do_linux_aio(fd, offset, buf, len, task, ioto, IO_CMD_PREAD, rd_ms);
 }
 
 static int do_write_aio_posix(int fd, uint64_t offset, char *buf, int len,
@@ -621,10 +631,10 @@ static int do_read_aio_posix(int fd, uint64_t offset, char *buf, int
len,
 /* write aligned io buffer */
 
 int write_iobuf(int fd, uint64_t offset, char *iobuf, int iobuf_len,
-		struct task *task, int ioto)
+		struct task *task, int ioto, int *wr_ms)
 {
 	if (task && task->use_aio == 1)
-		return do_write_aio_linux(fd, offset, iobuf, iobuf_len, task, ioto);
+		return do_write_aio_linux(fd, offset, iobuf, iobuf_len, task, ioto, wr_ms);
 	else if (task && task->use_aio == 2)
 		return do_write_aio_posix(fd, offset, iobuf, iobuf_len, task, ioto);
 	else
@@ -659,7 +669,7 @@ static int _write_sectors(const struct sync_disk *disk, uint64_t
sector_nr,
 	memset(iobuf, 0, iobuf_len);
 	memcpy(iobuf, data, data_len);
 
-	rv = write_iobuf(disk->fd, offset, iobuf, iobuf_len, task, ioto);
+	rv = write_iobuf(disk->fd, offset, iobuf, iobuf_len, task, ioto, NULL);
 	if (rv < 0) {
 		log_error("write_sectors %s offset %llu rv %d %s",
 			  blktype, (unsigned long long)offset, rv, disk->path);
@@ -715,10 +725,10 @@ int write_sectors(const struct sync_disk *disk, uint64_t sector_nr,
 /* read aligned io buffer */
 
 int read_iobuf(int fd, uint64_t offset, char *iobuf, int iobuf_len,
-	       struct task *task, int ioto)
+	       struct task *task, int ioto, int *rd_ms)
 {
 	if (task && task->use_aio == 1)
-		return do_read_aio_linux(fd, offset, iobuf, iobuf_len, task, ioto);
+		return do_read_aio_linux(fd, offset, iobuf, iobuf_len, task, ioto, rd_ms);
 	else if (task && task->use_aio == 2)
 		return do_read_aio_posix(fd, offset, iobuf, iobuf_len, task, ioto);
 	else
@@ -761,7 +771,7 @@ int read_sectors(const struct sync_disk *disk, uint64_t sector_nr,
 
 	memset(iobuf, 0, iobuf_len);
 
-	rv = read_iobuf(disk->fd, offset, iobuf, iobuf_len, task, ioto);
+	rv = read_iobuf(disk->fd, offset, iobuf, iobuf_len, task, ioto, NULL);
 	if (!rv) {
 		memcpy(data, iobuf, data_len);
 	} else {
diff --git a/src/diskio.h b/src/diskio.h
index d2c5be1..6cb1b4f 100644
--- a/src/diskio.h
+++ b/src/diskio.h
@@ -21,10 +21,10 @@ int majority_disks(int num_disks, int num);
  */
 
 int write_iobuf(int fd, uint64_t offset, char *iobuf, int iobuf_len,
-		struct task *task, int ioto);
+		struct task *task, int ioto, int *wr_ms);
 
 int read_iobuf(int fd, uint64_t offset, char *iobuf, int iobuf_len,
-	       struct task *task, int ioto);
+	       struct task *task, int ioto, int *rd_ms);
 
 int read_iobuf_reap(int fd, uint64_t offset, char *iobuf, int iobuf_len,
 		    struct task *task, uint32_t ioto_msec);
diff --git a/src/lockspace.c b/src/lockspace.c
index b7f2e9c..e9bba20 100644
--- a/src/lockspace.c
+++ b/src/lockspace.c
@@ -532,6 +532,44 @@ static void close_event_fds(struct space *sp)
 }
 
 /*
+ * if delta_result is success:
+ * new record saving last_success (timestamp in renewal), rd_ms, wr_ms
+ * if delta_result is timeout:
+ * increment next_timeouts in prev record
+ * if delta_result is failure:
+ * increment next_errors in prev record
+ */
+
+static void save_renewal_history(struct space *sp, int delta_result,
+				 uint64_t last_success, int rd_ms, int wr_ms)
+{
+	struct renewal_history *hi;
+
+	if (!sp->renewal_history_size || !sp->renewal_history)
+		return;
+
+	if (delta_result == SANLK_OK) {
+		hi = &sp->renewal_history[sp->renewal_history_next];
+
+		hi->timestamp = last_success;
+		hi->read_ms = rd_ms;
+		hi->write_ms = wr_ms;
+
+		sp->renewal_history_prev = sp->renewal_history_next;
+		sp->renewal_history_next++;
+		if (sp->renewal_history_next >= sp->renewal_history_size)
+			sp->renewal_history_next = 0;
+	} else {
+		hi = &sp->renewal_history[sp->renewal_history_prev];
+
+		if (delta_result == SANLK_AIO_TIMEOUT)
+			hi->next_timeouts++;
+		else
+			hi->next_errors++;
+	}
+}
+
+/*
  * This thread must not be stopped unless all pids that may be using any
  * resources in it are dead/gone.  (The USED flag in the lockspace represents
  * pids using resources in the lockspace, when those pids are not using actual
@@ -551,6 +589,7 @@ static void *lockspace_thread(void *arg_in)
 	int rv, delta_length, renewal_interval = 0;
 	int id_renewal_seconds, id_renewal_fail_seconds;
 	int acquire_result, delta_result, read_result;
+	int rd_ms, wr_ms;
 	int opened = 0;
 	int stop = 0;
 	int wd_con;
@@ -642,6 +681,8 @@ static void *lockspace_thread(void *arg_in)
 	sp->lease_status.renewal_last_attempt = delta_begin;
 	if (delta_result == SANLK_OK)
 		sp->lease_status.renewal_last_success = last_success;
+	/* First renewal entry shows the acquire time with 0 latencies. */
+	save_renewal_history(sp, delta_result, last_success, 0, 0);
 	pthread_mutex_unlock(&sp->mutex);
 
 	if (acquire_result < 0)
@@ -685,7 +726,8 @@ static void *lockspace_thread(void *arg_in)
 						 sp->space_name, bitmap, &extra,
 						 delta_result, &read_result,
 						 log_renewal_level,
-						 &leader, &leader);
+						 &leader, &leader,
+						 &rd_ms, &wr_ms);
 		delta_length = monotime() - delta_begin;
 
 		if (delta_result == SANLK_OK) {
@@ -714,7 +756,6 @@ static void *lockspace_thread(void *arg_in)
 			sp->lease_status.renewal_read_count++;
 		}
 
-
 		/*
 		 * pet the watchdog
 		 * (don't update on thread_stop because it's probably unlinked)
@@ -723,6 +764,7 @@ static void *lockspace_thread(void *arg_in)
 		if (delta_result == SANLK_OK && !sp->thread_stop)
 			update_watchdog(sp, last_success, id_renewal_fail_seconds);
 
+		save_renewal_history(sp, delta_result, last_success, rd_ms, wr_ms);
 		pthread_mutex_unlock(&sp->mutex);
 
 
@@ -819,6 +861,14 @@ int add_lockspace_start(struct sanlk_lockspace *ls, uint32_t
io_timeout, struct
 	for (i = 0; i < MAX_EVENT_FDS; i++)
 		sp->event_fds[i] = -1;
 
+	if (com.renewal_history_size) {
+		sp->renewal_history = malloc(sizeof(struct renewal_history) *
com.renewal_history_size);
+		if (sp->renewal_history) {
+			sp->renewal_history_size = com.renewal_history_size;
+			memset(sp->renewal_history, 0, sizeof(struct renewal_history) *
com.renewal_history_size);
+		}
+	}
+
 	pthread_mutex_lock(&spaces_mutex);
 
 	/* search all lists for an identical lockspace */
diff --git a/src/main.c b/src/main.c
index af7c57c..ebc1e06 100644
--- a/src/main.c
+++ b/src/main.c
@@ -1218,6 +1218,7 @@ static void process_connection(int ci)
 	case SM_CMD_SHUTDOWN:
 	case SM_CMD_STATUS:
 	case SM_CMD_HOST_STATUS:
+	case SM_CMD_RENEWAL:
 	case SM_CMD_LOG_DUMP:
 	case SM_CMD_GET_LOCKSPACES:
 	case SM_CMD_GET_HOSTS:
@@ -1807,6 +1808,7 @@ static void print_usage(void)
 	printf("  -D            no fork and print all logging to stderr\n");
 	printf("  -Q 0|1        quiet error messages for common lock contention
(%d)\n", DEFAULT_QUIET_FAIL);
 	printf("  -R 0|1        renewal debugging, log debug info about renewals
(0)\n");
+	printf("  -H <num>      renewal history size (%d)\n",
DEFAULT_RENEWAL_HISTORY_SIZE);
 	printf("  -L <pri>      write logging at priority level and up to logfile (3
LOG_ERR)\n");
 	printf("                (use -1 for none)\n");
 	printf("  -S <pri>      write logging at priority level and up to syslog (3
LOG_ERR)\n");
@@ -1827,6 +1829,7 @@ static void print_usage(void)
 	printf("sanlock client status [-D] [-o p|s]\n");
 	printf("sanlock client gets [-h 0|1]\n");
 	printf("sanlock client host_status -s LOCKSPACE [-D]\n");
+	printf("sanlock client renewal -s LOCKSPACE\n");
 	printf("sanlock client set_event -s LOCKSPACE -i <host_id> [-g gen] -e
<event> -d <data>\n");
 	printf("sanlock client set_config -s LOCKSPACE [-u 0|1] [-O 0|1]\n");
 	printf("sanlock client log_dump\n");
@@ -1935,6 +1938,8 @@ static int read_command_line(int argc, char *argv[])
 			com.action = ACT_STATUS;
 		else if (!strcmp(act, "host_status"))
 			com.action = ACT_HOST_STATUS;
+		else if (!strcmp(act, "renewal"))
+			com.action = ACT_RENEWAL;
 		else if (!strcmp(act, "gets"))
 			com.action = ACT_GETS;
 		else if (!strcmp(act, "log_dump"))
@@ -2051,6 +2056,9 @@ static int read_command_line(int argc, char *argv[])
 		case 'R':
 			com.debug_renew = atoi(optionarg);
 			break;
+		case 'H':
+			com.renewal_history_size = atoi(optionarg);
+			break;
 		case 'L':
 			log_logfile_priority = atoi(optionarg);
 			break;
@@ -2331,6 +2339,10 @@ static void read_config_file(void)
 			get_val_int(line, &val);
 			com.renewal_read_extend_sec_set = 1;
 			com.renewal_read_extend_sec = val;
+
+		} else if (!strcmp(str, "renewal_history_size")) {
+			get_val_int(line, &val);
+			com.renewal_history_size = val;
 		}
 	}
 
@@ -2571,6 +2583,10 @@ static int do_client(void)
 		rv = sanlock_host_status(com.debug, com.lockspace.name);
 		break;
 
+	case ACT_RENEWAL:
+		rv = sanlock_renewal(com.lockspace.name);
+		break;
+
 	case ACT_GETS:
 		rv = do_client_gets();
 		break;
@@ -3189,6 +3205,7 @@ int main(int argc, char *argv[])
 	com.quiet_fail = DEFAULT_QUIET_FAIL;
 	com.renewal_read_extend_sec_set = 0;
 	com.renewal_read_extend_sec = 0;
+	com.renewal_history_size = DEFAULT_RENEWAL_HISTORY_SIZE;
 
 	if (getgrnam("sanlock") && getpwnam("sanlock")) {
 		com.uname = (char *)"sanlock";
diff --git a/src/monotime.c b/src/monotime.c
index e4ce85a..5691766 100644
--- a/src/monotime.c
+++ b/src/monotime.c
@@ -19,3 +19,14 @@ uint64_t monotime(void)
 
 	return ts.tv_sec;
 }
+
+void ts_diff(struct timespec *begin, struct timespec *end, struct timespec *diff)
+{
+	if ((end->tv_nsec - begin->tv_nsec) < 0) {
+		diff->tv_sec = end->tv_sec - begin->tv_sec - 1;
+		diff->tv_nsec = end->tv_nsec - begin->tv_nsec + 1000000000;
+	} else {
+		diff->tv_sec = end->tv_sec - begin->tv_sec;
+		diff->tv_nsec = end->tv_nsec - begin->tv_nsec;
+	}
+}
diff --git a/src/monotime.h b/src/monotime.h
index 4e8c12d..788edd3 100644
--- a/src/monotime.h
+++ b/src/monotime.h
@@ -10,5 +10,6 @@
 #define	__MONOTIME_H__
 
 uint64_t monotime(void);
+void ts_diff(struct timespec *begin, struct timespec *end, struct timespec *diff);
 
 #endif
diff --git a/src/ondisk.c b/src/ondisk.c
index c161f8b..83b6832 100644
--- a/src/ondisk.c
+++ b/src/ondisk.c
@@ -11,6 +11,7 @@
 #include <byteswap.h>
 #include <inttypes.h>
 #include <unistd.h>
+#include <time.h>
 
 #include "sanlock_internal.h"
 #include "ondisk.h"
diff --git a/src/paxos_lease.c b/src/paxos_lease.c
index 2206c95..ecd4597 100644
--- a/src/paxos_lease.c
+++ b/src/paxos_lease.c
@@ -181,7 +181,7 @@ static int write_dblock_mblock_sh(struct task *task,
 	memcpy(iobuf, (char *)&pd_end, sizeof(struct paxos_dblock));
 	memcpy(iobuf + MBLOCK_OFFSET, (char *)&mb_end, sizeof(struct mode_block));
 
-	rv = write_iobuf(disk->fd, offset, iobuf, iobuf_len, task, token->io_timeout);
+	rv = write_iobuf(disk->fd, offset, iobuf, iobuf_len, task, token->io_timeout,
NULL);
 
 	if (rv < 0) {
 		log_errot(token, "write_dblock_mblock_sh host_id %llu gen %llu rv %d",
@@ -513,7 +513,7 @@ static int run_ballot(struct task *task, struct token *token, int
num_hosts,
 			continue;
 		memset(iobuf[d], 0, iobuf_len);
 
-		rv = read_iobuf(disk->fd, disk->offset, iobuf[d], iobuf_len, task,
token->io_timeout);
+		rv = read_iobuf(disk->fd, disk->offset, iobuf[d], iobuf_len, task,
token->io_timeout, NULL);
 		if (rv == SANLK_AIO_TIMEOUT)
 			iobuf[d] = NULL;
 		if (rv < 0)
@@ -667,7 +667,7 @@ static int run_ballot(struct task *task, struct token *token, int
num_hosts,
 			continue;
 		memset(iobuf[d], 0, iobuf_len);
 
-		rv = read_iobuf(disk->fd, disk->offset, iobuf[d], iobuf_len, task,
token->io_timeout);
+		rv = read_iobuf(disk->fd, disk->offset, iobuf[d], iobuf_len, task,
token->io_timeout, NULL);
 		if (rv == SANLK_AIO_TIMEOUT)
 			iobuf[d] = NULL;
 		if (rv < 0)
@@ -954,7 +954,7 @@ int paxos_read_buf(struct task *task,
 
 	memset(iobuf, 0, iobuf_len);
 
-	rv = read_iobuf(disk->fd, disk->offset, iobuf, iobuf_len, task,
token->io_timeout);
+	rv = read_iobuf(disk->fd, disk->offset, iobuf, iobuf_len, task,
token->io_timeout, NULL);
 
 	*buf_out = iobuf;
 
@@ -1141,7 +1141,7 @@ static int _lease_read_one(struct task *task,
 
 	memset(iobuf, 0, iobuf_len);
 
-	rv = read_iobuf(disk->fd, disk->offset, iobuf, iobuf_len, task,
token->io_timeout);
+	rv = read_iobuf(disk->fd, disk->offset, iobuf, iobuf_len, task,
token->io_timeout, NULL);
 	if (rv < 0)
 		goto out;
 
@@ -2101,7 +2101,7 @@ int paxos_lease_init(struct task *task,
 
 	for (d = 0; d < token->r.num_disks; d++) {
 		rv = write_iobuf(token->disks[d].fd, token->disks[d].offset,
-				 iobuf, iobuf_len, task, token->io_timeout);
+				 iobuf, iobuf_len, task, token->io_timeout, NULL);
 
 		if (rv == SANLK_AIO_TIMEOUT)
 			aio_timeout = 1;
diff --git a/src/resource.c b/src/resource.c
index 4d80528..584b66f 100644
--- a/src/resource.c
+++ b/src/resource.c
@@ -334,7 +334,7 @@ static int write_host_block(struct task *task, struct token *token,
 
 		offset = disk->offset + ((2 + host_id - 1) * disk->sector_size);
 
-		rv = write_iobuf(disk->fd, offset, iobuf, iobuf_len, task, token->io_timeout);
+		rv = write_iobuf(disk->fd, offset, iobuf, iobuf_len, task, token->io_timeout,
NULL);
 		if (rv < 0)
 			break;
 	}
@@ -382,7 +382,7 @@ static int read_mode_block(struct task *task, struct token *token,
 
 		offset = disk->offset + ((2 + host_id - 1) * disk->sector_size);
 
-		rv = read_iobuf(disk->fd, offset, iobuf, iobuf_len, task, token->io_timeout);
+		rv = read_iobuf(disk->fd, offset, iobuf, iobuf_len, task, token->io_timeout,
NULL);
 		if (rv < 0)
 			break;
 
@@ -469,7 +469,7 @@ static int read_lvb_block(struct task *task, struct token *token)
 	if (!r->lvb)
 		return 0;
 
-	rv = read_iobuf(disk->fd, offset, iobuf, iobuf_len, task, token->io_timeout);
+	rv = read_iobuf(disk->fd, offset, iobuf, iobuf_len, task, token->io_timeout,
NULL);
 
 	return rv;
 }
@@ -489,7 +489,7 @@ static int write_lvb_block(struct task *task, struct resource *r,
struct token *
 	if (!r->lvb)
 		return 0;
 
-	rv = write_iobuf(disk->fd, offset, iobuf, iobuf_len, task, token->io_timeout);
+	rv = write_iobuf(disk->fd, offset, iobuf, iobuf_len, task, token->io_timeout,
NULL);
 
 	return rv;
 }
diff --git a/src/sanlock.8 b/src/sanlock.8
index 6078a5f..73e48ff 100644
--- a/src/sanlock.8
+++ b/src/sanlock.8
@@ -560,6 +560,10 @@ Print lockspaces being managed by the sanlock daemon.  The LOCKSPACE
 string will be followed by ADD or REM if the lockspace is currently being
 added or removed.  Add -h 1 to also show hosts in each lockspace.
 
+.BR "sanlock client renewal -s" " LOCKSPACE"
+
+Print a history of renewals with timing details.
+
 .B sanlock client log_dump
 
 Print the sanlock daemon internal debug log.
diff --git a/src/sanlock_internal.h b/src/sanlock_internal.h
index 511b448..1e4e7e1 100644
--- a/src/sanlock_internal.h
+++ b/src/sanlock_internal.h
@@ -161,6 +161,14 @@ struct host_status {
 	char owner_name[NAME_ID_SIZE];
 };
 
+struct renewal_history {
+	uint64_t timestamp;
+	int read_ms;
+	int write_ms;
+	int next_timeouts;
+	int next_errors;
+};
+
 /* The max number of connections that can get events for a lockspace. */
 #define MAX_EVENT_FDS 32
 
@@ -193,6 +201,10 @@ struct space {
 	pthread_mutex_t mutex; /* protects lease_status, thread_stop  */
 	struct lease_status lease_status;
 	struct host_status host_status[DEFAULT_MAX_HOSTS];
+	struct renewal_history *renewal_history;
+	int renewal_history_size;
+	int renewal_history_next;
+	int renewal_history_prev;
 };
 
 /* Update lockspace_info() to copy any fields from struct space
@@ -283,6 +295,7 @@ EXTERN struct client *client;
 #define DEFAULT_MAX_WORKER_THREADS 8
 #define DEFAULT_SH_RETRIES 8
 #define DEFAULT_QUIET_FAIL 1
+#define DEFAULT_RENEWAL_HISTORY_SIZE 180 /* about 1 hour with 20 sec renewal interval */
 
 struct command_line {
 	int type;				/* COM_ */
@@ -320,6 +333,7 @@ struct command_line {
 	int res_count;
 	int sh_retries;
 	uint32_t force_mode;
+	int renewal_history_size;
 	int renewal_read_extend_sec_set; /* 1 if renewal_read_extend_sec is configured */
 	uint32_t renewal_read_extend_sec;
 	char our_host_name[SANLK_NAME_LEN+1];
@@ -367,6 +381,7 @@ enum {
 	ACT_SET_EVENT,
 	ACT_SET_CONFIG,
 	ACT_WRITE_LEADER,
+	ACT_RENEWAL,
 };
 
 EXTERN int external_shutdown;
diff --git a/src/sanlock_sock.h b/src/sanlock_sock.h
index d9fb076..78821c2 100644
--- a/src/sanlock_sock.h
+++ b/src/sanlock_sock.h
@@ -54,6 +54,7 @@ enum {
 	SM_CMD_END_EVENT         = 31,
 	SM_CMD_SET_EVENT         = 32,
 	SM_CMD_SET_CONFIG        = 33,
+	SM_CMD_RENEWAL           = 34,
 };
 
 #define SM_CB_GET_EVENT 1
@@ -76,6 +77,7 @@ struct sm_header {
 #define SANLK_STATE_LOCKSPACE   3
 #define SANLK_STATE_RESOURCE    4
 #define SANLK_STATE_HOST	5
+#define SANLK_STATE_RENEWAL	6
 
 struct sanlk_state {
 	uint32_t type; /* SANLK_STATE_ */