src/cmd.c | 2 +
src/delta_lease.c | 43 +++++++++++++++++++++++------
src/delta_lease.h | 1
src/direct.c | 1
src/diskio.c | 72 +++++++++++++++++++++++++++++++++++--------------
src/diskio.h | 2 -
src/lockspace.c | 19 ++++++++++--
src/main.c | 8 +++++
src/sanlock.8 | 4 ++
src/sanlock.conf | 3 ++
src/sanlock_internal.h | 3 ++
src/task.c | 29 ++++++++++++++-----
12 files changed, 146 insertions(+), 41 deletions(-)
New commits:
commit adbeb34efaf1fefb40ef5b88444282572891ef7a
Author: David Teigland <teigland(a)redhat.com>
Date: Mon Jan 25 14:40:40 2016 -0600
sanlock: man page reference to sanlock.conf
diff --git a/src/sanlock.8 b/src/sanlock.8
index c605b64..6078a5f 100644
--- a/src/sanlock.8
+++ b/src/sanlock.8
@@ -1038,6 +1038,10 @@ renewed its delta_lease for a specific length of time, then the owner
value in the paxos_lease becomes expired, and other hosts will use the
paxos algorithm to acquire the paxos_lease, and set a new owner.
+.SH FILES
+
+/etc/sanlock/sanlock.conf
+
.SH SEE ALSO
.BR wdmd (8)
commit 0257ef138eff2c9dde4e5f90261e4a916e53b880
Author: David Teigland <teigland(a)redhat.com>
Date: Fri Jan 22 16:59:49 2016 -0600
sanlock: tolerate longer read delays in renewal
Previously, a renewal read that timed out was abandoned and
then retried. If the first read actually completed during
the second (retried) read, the first would be ignored, despite
the fact that it could be used.
Now, a timed out read is given an extra io timeout interval to
complete as part of the subsequent renewal retry. If the first
read completes during the first phase of the second retry read,
it will be used.
This effectively doubles the length of time that renewal reads
can persistently take without having any negative effect on
the operation of the lockspace.
If read io was persistently taking just longer than the io
timeout, lease renewal would never get beyond the read phase,
and the lockspace would enter recovery mode. Now, the read
io can be persistently delayed by up to twice the io timeout
before this happens. Furthermore, the extended timeout for
the read can be configured to be even longer, to compensate
for reads that are persistently delayed even longer. The
effect of extending the read timeout is that the time allowed
for the renewal write to complete is reduced. The read and
the write for a renewal must still both complete within
the same time limit before the renewal is considered to
have failed and the lockspace enters recovery mode.
diff --git a/src/cmd.c b/src/cmd.c
index c2f05ba..997ec21 100644
--- a/src/cmd.c
+++ b/src/cmd.c
@@ -2167,6 +2167,7 @@ static int print_state_lockspace(struct space *sp, char *str, const char *list_n
"used_retries=%u "
"external_used=%d "
"used_by_orphans=%d "
+ "renewal_read_extend_sec=%u "
"corrupt_result=%d "
"acquire_last_result=%d "
"renewal_last_result=%d "
@@ -2184,6 +2185,7 @@ static int print_state_lockspace(struct space *sp, char *str, const char *list_n
sp->used_retries,
(sp->flags & SP_EXTERNAL_USED) ? 1 : 0,
(sp->flags & SP_USED_BY_ORPHANS) ? 1 : 0,
+ sp->renewal_read_extend_sec,
sp->lease_status.corrupt_result,
sp->lease_status.acquire_last_result,
sp->lease_status.renewal_last_result,
diff --git a/src/delta_lease.c b/src/delta_lease.c
index 3d5189c..3cf98fb 100644
--- a/src/delta_lease.c
+++ b/src/delta_lease.c
@@ -474,6 +474,7 @@ int delta_lease_renew(struct task *task,
char **p_wbuf;
char *wbuf;
uint32_t checksum;
+ uint32_t reap_timeout_msec;
uint64_t host_id, id_offset, new_ts, now;
int rv, iobuf_len, sector_size;
@@ -516,9 +517,18 @@ int delta_lease_renew(struct task *task,
goto skip_reap;
}
- /* only wait .5 sec when trying to reap a prev io */
+ log_space(sp, "delta_renew begin reap");
+
+ if (!sp->renewal_read_extend_sec) {
+ /* only wait .5 sec when trying to reap a prev io to clear it */
+ reap_timeout_msec = 500;
+ } else {
+ /* effectively continue/extend the read phase from the previous renewal */
+ reap_timeout_msec = sp->renewal_read_extend_sec * 1000;
+ }
+
rv = read_iobuf_reap(disk->fd, disk->offset,
- task->iobuf, iobuf_len, task, 500000000);
+ task->iobuf, iobuf_len, task, reap_timeout_msec);
log_space(sp, "delta_renew reap %d", rv);
diff --git a/src/diskio.c b/src/diskio.c
index 218fab1..d5f06f2 100644
--- a/src/diskio.c
+++ b/src/diskio.c
@@ -780,7 +780,7 @@ int read_sectors(const struct sync_disk *disk, uint64_t sector_nr,
task->read_iobuf_timeout_aicb . */
int read_iobuf_reap(int fd, uint64_t offset, char *iobuf, int iobuf_len,
- struct task *task, int ioto)
+ struct task *task, uint32_t ioto_msec)
{
struct timespec ts;
struct aicb *aicb;
@@ -805,7 +805,8 @@ int read_iobuf_reap(int fd, uint64_t offset, char *iobuf, int iobuf_len,
return -EINVAL;
memset(&ts, 0, sizeof(struct timespec));
- ts.tv_nsec = ioto;
+ ts.tv_sec = ioto_msec / 1000;
+ ts.tv_nsec = (ioto_msec % 1000) * 1000000;
retry:
memset(&event, 0, sizeof(event));
diff --git a/src/diskio.h b/src/diskio.h
index db00cfe..d2c5be1 100644
--- a/src/diskio.h
+++ b/src/diskio.h
@@ -27,7 +27,7 @@ int read_iobuf(int fd, uint64_t offset, char *iobuf, int iobuf_len,
struct task *task, int ioto);
int read_iobuf_reap(int fd, uint64_t offset, char *iobuf, int iobuf_len,
- struct task *task, int ioto);
+ struct task *task, uint32_t ioto_msec);
/*
* sector functions allocate an iobuf themselves, copy into it for read, use it
diff --git a/src/lockspace.c b/src/lockspace.c
index bc8849f..b7f2e9c 100644
--- a/src/lockspace.c
+++ b/src/lockspace.c
@@ -811,6 +811,11 @@ int add_lockspace_start(struct sanlk_lockspace *ls, uint32_t io_timeout, struct
sp->set_bitmap_seconds = calc_set_bitmap_seconds(io_timeout);
pthread_mutex_init(&sp->mutex, NULL);
+ if (com.renewal_read_extend_sec_set)
+ sp->renewal_read_extend_sec = com.renewal_read_extend_sec;
+ else
+ sp->renewal_read_extend_sec = io_timeout;
+
for (i = 0; i < MAX_EVENT_FDS; i++)
sp->event_fds[i] = -1;
diff --git a/src/main.c b/src/main.c
index 25d0819..af7c57c 100644
--- a/src/main.c
+++ b/src/main.c
@@ -2325,6 +2325,12 @@ static void read_config_file(void)
memset(str, 0, sizeof(str));
get_val_str(line, str);
strncpy(com.our_host_name, str, NAME_ID_SIZE);
+
+ } else if (!strcmp(str, "renewal_read_extend_sec")) {
+ /* zero is a valid setting so we need the _set field to say it's set */
+ get_val_int(line, &val);
+ com.renewal_read_extend_sec_set = 1;
+ com.renewal_read_extend_sec = val;
}
}
@@ -3181,6 +3187,8 @@ int main(int argc, char *argv[])
com.pid = -1;
com.sh_retries = DEFAULT_SH_RETRIES;
com.quiet_fail = DEFAULT_QUIET_FAIL;
+ com.renewal_read_extend_sec_set = 0;
+ com.renewal_read_extend_sec = 0;
if (getgrnam("sanlock") && getpwnam("sanlock")) {
com.uname = (char *)"sanlock";
diff --git a/src/sanlock.conf b/src/sanlock.conf
index 06b8647..062692f 100644
--- a/src/sanlock.conf
+++ b/src/sanlock.conf
@@ -37,4 +37,7 @@
#
# our_host_name = <str>
# command line: -e <str>
+#
+# renewal_read_extend_sec = <seconds>
+# command line: n/a
diff --git a/src/sanlock_internal.h b/src/sanlock_internal.h
index 9a276d1..511b448 100644
--- a/src/sanlock_internal.h
+++ b/src/sanlock_internal.h
@@ -178,6 +178,7 @@ struct space {
uint32_t set_bitmap_seconds;
uint32_t flags; /* SP_ */
uint32_t used_retries;
+ uint32_t renewal_read_extend_sec; /* defaults to io_timeout */
int align_size;
int renew_fail;
int space_dead;
@@ -319,6 +320,8 @@ struct command_line {
int res_count;
int sh_retries;
uint32_t force_mode;
+ 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];
char *file_path;
char *dump_path;
commit 6dc88282bb83994ab2c25d73681d84b73a66cc77
Author: David Teigland <teigland(a)redhat.com>
Date: Fri Jan 22 14:41:20 2016 -0600
sanlock: improve logging for renewals
diff --git a/src/delta_lease.c b/src/delta_lease.c
index ef1cb3c..3d5189c 100644
--- a/src/delta_lease.c
+++ b/src/delta_lease.c
@@ -464,6 +464,7 @@ int delta_lease_renew(struct task *task,
struct delta_extra *extra,
int prev_result,
int *read_result,
+ int log_renewal_level,
struct leader_record *leader_last,
struct leader_record *leader_ret)
{
@@ -473,7 +474,7 @@ int delta_lease_renew(struct task *task,
char **p_wbuf;
char *wbuf;
uint32_t checksum;
- uint64_t host_id, id_offset, new_ts;
+ uint64_t host_id, id_offset, new_ts, now;
int rv, iobuf_len, sector_size;
if (!leader_last) {
@@ -569,14 +570,21 @@ 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);
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
try to reap the event */
- log_erros(sp, "delta_renew read rv %d offset %llu %s",
- rv, (unsigned long long)disk->offset, disk->path);
+ if (rv == SANLK_AIO_TIMEOUT)
+ log_erros(sp, "delta_renew read timeout %u sec offset %llu %s",
+ sp->io_timeout, (unsigned long long)disk->offset, disk->path);
+ else
+ log_erros(sp, "delta_renew read rv %d offset %llu %s",
+ rv, (unsigned long long)disk->offset, disk->path);
return rv;
}
@@ -625,9 +633,11 @@ int delta_lease_renew(struct task *task,
new_ts = monotime();
- if (leader.timestamp >= new_ts) {
+ if (log_renewal_level != -1)
+ log_level(sp->space_id, 0, NULL, log_renewal_level, "delta_renew begin write for new ts %llu", (unsigned long long)new_ts);
+
+ if (leader.timestamp >= new_ts)
log_erros(sp, "delta_renew timestamp too small");
- }
leader.timestamp = new_ts;
leader.checksum = 0; /* set below */
@@ -670,11 +680,18 @@ int delta_lease_renew(struct task *task,
if (rv != SANLK_AIO_TIMEOUT)
free(wbuf);
+ now = monotime();
+
if (rv < 0) {
- log_erros(sp, "delta_renew write error %d", rv);
+ log_erros(sp, "delta_renew write time %llu error %d",
+ (unsigned long long)(now - new_ts), rv);
return rv;
}
+ if (now - new_ts >= sp->io_timeout)
+ log_erros(sp, "delta_renew long write time %llu sec",
+ (unsigned long long)(now - new_ts));
+
/* the paper shows doing a delay and another read here, but it seems
unnecessary since we do the same at the beginning of the next renewal */
diff --git a/src/delta_lease.h b/src/delta_lease.h
index 968c7c7..38c469a 100644
--- a/src/delta_lease.h
+++ b/src/delta_lease.h
@@ -33,6 +33,7 @@ int delta_lease_renew(struct task *task,
struct delta_extra *extra,
int prev_result,
int *read_result,
+ int log_renewal_level,
struct leader_record *leader_last,
struct leader_record *leader_ret);
diff --git a/src/direct.c b/src/direct.c
index 2dbb098..c39988c 100644
--- a/src/direct.c
+++ b/src/direct.c
@@ -251,6 +251,7 @@ static int do_delta_action(int action,
NULL,
-1,
&read_result,
+ 0,
&leader,
&leader);
break;
diff --git a/src/diskio.c b/src/diskio.c
index 7647094..218fab1 100644
--- a/src/diskio.c
+++ b/src/diskio.c
@@ -347,9 +347,17 @@ static struct aicb *find_callback_slot(struct task *task, int ioto)
struct iocb *ev_iocb = event.obj;
struct aicb *ev_aicb = container_of(ev_iocb, struct aicb, iocb);
int op = ev_iocb ? ev_iocb->aio_lio_opcode : -1;
+ const char *op_str;
- log_taskw(task, "aio collect %d %p:%p:%p result %ld:%ld old free",
- op, ev_aicb, ev_iocb, ev_aicb->buf, event.res, event.res2);
+ if (op == IO_CMD_PREAD)
+ op_str = "RD";
+ else if (op == IO_CMD_PWRITE)
+ op_str = "WR";
+ else
+ op_str = "UK";
+
+ log_taskw(task, "aio collect %s %p:%p:%p result %ld:%ld old free",
+ op_str, ev_aicb, ev_iocb, ev_aicb->buf, event.res, event.res2);
ev_aicb->used = 0;
free(ev_aicb->buf);
ev_aicb->buf = NULL;
@@ -373,6 +381,7 @@ static int do_linux_aio(int fd, uint64_t offset, char *buf, int len,
struct aicb *aicb;
struct iocb *iocb;
struct io_event event;
+ const char *op_str;
int rv;
if (!ioto) {
@@ -426,24 +435,31 @@ 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 (op == IO_CMD_PREAD)
+ op_str = "RD";
+ else if (op == IO_CMD_PWRITE)
+ op_str = "WR";
+ else
+ op_str = "UK";
+
ev_aicb->used = 0;
if (ev_iocb != iocb) {
- log_taskw(task, "aio collect %d %p:%p:%p result %ld:%ld other free",
- op, ev_aicb, ev_iocb, ev_aicb->buf, event.res, event.res2);
+ log_taskw(task, "aio collect %s %p:%p:%p result %ld:%ld other free",
+ op_str, ev_aicb, ev_iocb, ev_aicb->buf, event.res, event.res2);
free(ev_aicb->buf);
ev_aicb->buf = NULL;
goto retry;
}
if ((int)event.res < 0) {
- log_taskw(task, "aio collect %d %p:%p:%p result %ld:%ld match res",
- op, ev_aicb, ev_iocb, ev_aicb->buf, event.res, event.res2);
+ log_taskw(task, "aio collect %s %p:%p:%p result %ld:%ld match res",
+ op_str, ev_aicb, ev_iocb, ev_aicb->buf, event.res, event.res2);
rv = event.res;
goto out;
}
if (event.res != len) {
- log_taskw(task, "aio collect %d %p:%p:%p result %ld:%ld match len %d",
- op, ev_aicb, ev_iocb, ev_aicb->buf, event.res, event.res2, len);
+ log_taskw(task, "aio collect %s %p:%p:%p result %ld:%ld match len %d",
+ op_str, ev_aicb, ev_iocb, ev_aicb->buf, event.res, event.res2, len);
rv = -EMSGSIZE;
goto out;
}
@@ -466,8 +482,15 @@ static int do_linux_aio(int fd, uint64_t offset, char *buf, int len,
task->to_count++;
- log_taskw(task, "aio timeout %d %p:%p:%p ioto %d to_count %d",
- cmd, aicb, iocb, buf, ioto, task->to_count);
+ if (cmd == IO_CMD_PREAD)
+ op_str = "RD";
+ else if (cmd == IO_CMD_PWRITE)
+ op_str = "WR";
+ else
+ op_str = "UK";
+
+ log_taskw(task, "aio timeout %s %p:%p:%p ioto %d to_count %d",
+ op_str, aicb, iocb, buf, ioto, task->to_count);
rv = io_cancel(task->aio_ctx, iocb, &event);
if (!rv) {
@@ -798,31 +821,39 @@ int read_iobuf_reap(int fd, uint64_t offset, char *iobuf, int iobuf_len,
struct iocb *ev_iocb = event.obj;
struct aicb *ev_aicb = container_of(ev_iocb, struct aicb, iocb);
int op = ev_iocb ? ev_iocb->aio_lio_opcode : -1;
+ const char *op_str;
+
+ if (op == IO_CMD_PREAD)
+ op_str = "RD";
+ else if (op == IO_CMD_PWRITE)
+ op_str = "WR";
+ else
+ op_str = "UK";
ev_aicb->used = 0;
if (ev_iocb != iocb) {
- log_taskw(task, "aio collect %d %p:%p:%p result %ld:%ld other free r",
- op, ev_aicb, ev_iocb, ev_aicb->buf, event.res, event.res2);
+ log_taskw(task, "aio collect %s %p:%p:%p result %ld:%ld other free r",
+ op_str, ev_aicb, ev_iocb, ev_aicb->buf, event.res, event.res2);
free(ev_aicb->buf);
ev_aicb->buf = NULL;
goto retry;
}
if ((int)event.res < 0) {
- log_taskw(task, "aio collect %d %p:%p:%p result %ld:%ld match res r",
- op, ev_aicb, ev_iocb, ev_aicb->buf, event.res, event.res2);
+ log_taskw(task, "aio collect %s %p:%p:%p result %ld:%ld match res r",
+ op_str, ev_aicb, ev_iocb, ev_aicb->buf, event.res, event.res2);
rv = event.res;
goto out;
}
if (event.res != iobuf_len) {
- log_taskw(task, "aio collect %d %p:%p:%p result %ld:%ld match len %d r",
- op, ev_aicb, ev_iocb, ev_aicb->buf, event.res, event.res2, iobuf_len);
+ log_taskw(task, "aio collect %s %p:%p:%p result %ld:%ld match len %d r",
+ op_str, ev_aicb, ev_iocb, ev_aicb->buf, event.res, event.res2, iobuf_len);
rv = -EMSGSIZE;
goto out;
}
- log_taskw(task, "aio collect %d %p:%p:%p result %ld:%ld match reap",
- op, ev_aicb, ev_iocb, ev_aicb->buf, event.res, event.res2);
+ log_taskw(task, "aio collect %s %p:%p:%p result %ld:%ld match reap",
+ op_str, ev_aicb, ev_iocb, ev_aicb->buf, event.res, event.res2);
rv = 0;
goto out;
diff --git a/src/lockspace.c b/src/lockspace.c
index 24f75d6..bc8849f 100644
--- a/src/lockspace.c
+++ b/src/lockspace.c
@@ -547,6 +547,7 @@ static void *lockspace_thread(void *arg_in)
struct space *sp;
struct leader_record leader;
uint64_t delta_begin, last_success = 0;
+ int log_renewal_level = -1;
int rv, delta_length, renewal_interval = 0;
int id_renewal_seconds, id_renewal_fail_seconds;
int acquire_result, delta_result, read_result;
@@ -554,6 +555,9 @@ static void *lockspace_thread(void *arg_in)
int stop = 0;
int wd_con;
+ if (com.debug_renew)
+ log_renewal_level = LOG_DEBUG;
+
sp = (struct space *)arg_in;
memset(&task, 0, sizeof(struct task));
@@ -652,7 +656,6 @@ static void *lockspace_thread(void *arg_in)
if (stop)
break;
-
/*
* wait between each renewal
*/
@@ -681,6 +684,7 @@ static void *lockspace_thread(void *arg_in)
delta_result = delta_lease_renew(&task, sp, &sp->host_id_disk,
sp->space_name, bitmap, &extra,
delta_result, &read_result,
+ log_renewal_level,
&leader, &leader);
delta_length = monotime() - delta_begin;
@@ -732,9 +736,11 @@ static void *lockspace_thread(void *arg_in)
} else if (delta_length > id_renewal_seconds) {
log_erros(sp, "renewed %llu delta_length %d too long",
(unsigned long long)last_success, delta_length);
- } else if (com.debug_renew) {
- log_space(sp, "renewed %llu delta_length %d interval %d",
- (unsigned long long)last_success, delta_length, renewal_interval);
+ } else {
+ if (com.debug_renew) {
+ log_space(sp, "renewed %llu delta_length %d interval %d",
+ (unsigned long long)last_success, delta_length, renewal_interval);
+ }
}
}
commit 64fc348a616ce622ae3611835144699a2a84ed6d
Author: David Teigland <teigland(a)redhat.com>
Date: Fri Jan 22 12:00:02 2016 -0600
sanlock: use io_destroy to clear outstanding aio
When a lockspace thread attempts to clear outstanding
aio ops, it was using io_getevents indefinitely to wait
for completions. Now, it uses io_getevents to clear the
ops for up to 2 minutes, after which it uses io_destroy
to clear them. io_destroy may have the ability clear
certain ops that will never have a completion.
diff --git a/src/task.c b/src/task.c
index 144f5f8..f3c10f8 100644
--- a/src/task.c
+++ b/src/task.c
@@ -68,7 +68,9 @@ void close_task_aio(struct task *task)
struct timespec ts;
struct io_event event;
uint64_t last_warn;
- int rv, i, used, warn;
+ uint64_t begin;
+ uint64_t now;
+ int rv, i, used, lvl;
if (!task->use_aio)
goto skip_aio;
@@ -77,16 +79,19 @@ void close_task_aio(struct task *task)
ts.tv_sec = DEFAULT_IO_TIMEOUT;
last_warn = time(NULL);
+ begin = last_warn;
/* wait for all outstanding aio to complete before
destroying aio context, freeing iocb and buffers */
while (1) {
- warn = 0;
+ now = time(NULL);
- if (time(NULL) - last_warn >= DEFAULT_IO_TIMEOUT) {
- last_warn = time(NULL);
- warn = 1;
+ if (now - last_warn >= (DEFAULT_IO_TIMEOUT * 6)) {
+ last_warn = now;
+ lvl = LOG_ERR;
+ } else {
+ lvl = LOG_DEBUG;
}
used = 0;
@@ -96,15 +101,16 @@ void close_task_aio(struct task *task)
continue;
used++;
- if (!warn)
- continue;
- log_taske(task, "close_task_aio %d %p busy",
+ log_level(0, 0, task->name, lvl, "close_task_aio %d %p busy",
i, &task->callbacks[i]);
}
if (!used)
break;
+ if (now - begin >= 120)
+ break;
+
memset(&event, 0, sizeof(event));
rv = io_getevents(task->aio_ctx, 1, 1, &event, &ts);
@@ -127,8 +133,15 @@ void close_task_aio(struct task *task)
ev_aicb->buf = NULL;
}
}
+
+ if (used)
+ log_taskd(task, "close_task_aio destroy %d incomplete ops", used);
+
io_destroy(task->aio_ctx);
+ if (used)
+ log_taske(task, "close_task_aio destroyed %d incomplete ops", used);
+
if (task->iobuf)
free(task->iobuf);
