sanlock-devel May 2020

sanlock-devel@lists.fedorahosted.org

7 participants
14 discussions

[lvmlockd] sanlock stuck while getting VGLK
by Damon Wang 20 May '20

20 May '20

Hi, I got a wired case recently with a 24-nodes sanlock cluster recently. One sanlock process stuck with getting VGLK since it thinks there are two live host using VGLK shared lock, here is sanlock log from this host(host_id 19): https://pastebin.com/zJubYLRv I find important messages: "2020-05-14 21:28:51 2018540 [14765]: r857 clear_dead_shared host_id 61 gen 1 alive" "2020-05-14 21:28:51 2018540 [14765]: r857 clear_dead_shared host_id 94 gen 1 alive" "2020-05-14 21:28:52 2018541 [14764]: r858 clear_dead_shared host_id 61 gen 1 alive" "2020-05-14 21:28:52 2018541 [14764]: r858 clear_dead_shared host_id 94 gen 1 alive" "2020-05-14 21:28:53 2018542 [14765]: r859 clear_dead_shared host_id 61 gen 1 alive" "2020-05-14 21:28:53 2018542 [14765]: r859 clear_dead_shared host_id 94 gen 1 alive" "2020-05-14 21:28:54 2018543 [14764]: r860 clear_dead_shared host_id 61 gen 1 alive" "2020-05-14 21:28:54 2018543 [14764]: r860 clear_dead_shared host_id 94 gen 1 alive" "2020-05-14 21:28:55 2018544 [14765]: r861 clear_dead_shared host_id 61 gen 1 alive" "2020-05-14 21:28:55 2018544 [14765]: r861 clear_dead_shared host_id 94 gen 1 alive" and this last hours till I init VGLK manually: sanlock direct init -r xxx So I try to find out what happend to host_id 61 and host_id 94, it seems both two hosts tried to acquire VGLK and then released, though with long time. full log of host_id 61: https://pastebin.com/zDWQAtHE useful log: 2020-05-14 20:23:03 2545197 [33739]: cmd_acquire 6,16,33743 ci_in 6 fd 16 count 1 flags 9 2020-05-14 20:23:03 2545197 [33739]: s5:r1044 resource lvm_fc261665e94c4d0f8341e254398e7ed5:VGLK:/dev/mapper/fc261665e94c4d0f8341e254398e7ed5-lvmlock:69206016:SH for 6,16,33743 2020-05-14 20:23:03 2545197 [33739]: r1044 paxos_acquire begin e 0 0 2020-05-14 20:23:03 2545197 [33739]: r1044 leader 6067 owner 36 2 0 dblocks 35:12132036:12132036:36:2:2099201:6067:1, 2020-05-14 20:23:03 2545197 [33739]: r1044 paxos_acquire leader 6067 owner 36 2 0 max mbal[35] 12132036 our_dblock 12096061 12096061 61 1 2537794 6049 2020-05-14 20:23:03 2545197 [33739]: r1044 paxos_acquire leader 6067 free 2020-05-14 20:23:03 2545197 [33739]: r1044 ballot 6068 phase1 write mbal 12134061 2020-05-14 20:23:03 2545198 [33739]: r1044 ballot 6068 mode[93] shared 1 gen 1 2020-05-14 20:23:03 2545198 [33739]: r1044 ballot 6068 phase1 read 60:12134061:0:0:0:0:6068:0, 2020-05-14 20:23:03 2545198 [33739]: r1044 ballot 6068 phase2 write bal 12134061 inp 61 1 2545198 q_max -1 2020-05-14 20:23:03 2545198 [33739]: r1044 ballot 6068 phase2 read 60:12134061:12134061:61:1:2545198:6068:0, 2020-05-14 20:23:03 2545198 [33739]: r1044 ballot 6068 commit self owner 61 1 2545198 2020-05-14 20:23:03 2545198 [33739]: r1044 acquire_disk rv 1 lver 6068 at 2545198 2020-05-14 20:23:03 2545198 [33739]: r1044 write_host_block host_id 61 flags 1 gen 1 dblock 12134061:12134061:61:1:2545198:6068:RELEASED. 2020-05-14 20:23:03 2545198 [33739]: r1044 paxos_release leader 6068 owner 61 1 2545198 2020-05-14 20:23:03 2545198 [33739]: cmd_acquire 6,16,33743 result 0 pid_dead 0 2020-05-14 20:23:03 2545198 [33740]: cmd_get_lvb ci 8 fd 20 result 0 res lvm_fc261665e94c4d0f8341e254398e7ed5:VGLK 2020-05-14 20:23:03 2545198 [33739]: cmd_acquire 6,16,33743 ci_in 6 fd 16 count 1 flags 8 2020-05-14 20:23:03 2545198 [33739]: s5:r1045 resource lvm_fc261665e94c4d0f8341e254398e7ed5:lL0kHh-CZ1i-jtMi-1qHO-ykfR-6nmu-Gk0rES:/dev/mapper/fc261665e94c4d0f8341e254398e7ed5-lvmlock:104857600 for 6,16,33743 2020-05-14 20:23:03 2545198 [33739]: r1045 paxos_acquire begin a 0 0 2020-05-14 20:23:03 2545198 [33739]: r1045 leader 9 owner 94 1 0 dblocks 93:16094:16094:94:1:8414771:9:1, 2020-05-14 20:23:03 2545198 [33739]: r1045 paxos_acquire leader 9 owner 94 1 0 max mbal[93] 16094 our_dblock 0 0 0 0 0 0 2020-05-14 20:23:03 2545198 [33739]: r1045 paxos_acquire leader 9 free 2020-05-14 20:23:03 2545198 [33739]: r1045 ballot 10 phase1 write mbal 18061 2020-05-14 20:23:03 2545198 [33739]: r1045 ballot 10 phase1 read 60:18061:0:0:0:0:10:0, 2020-05-14 20:23:03 2545198 [33739]: r1045 ballot 10 phase2 write bal 18061 inp 61 1 2545198 q_max -1 2020-05-14 20:23:03 2545198 [33739]: r1045 ballot 10 phase2 read 60:18061:18061:61:1:2545198:10:0, 2020-05-14 20:23:03 2545198 [33739]: r1045 ballot 10 commit self owner 61 1 2545198 2020-05-14 20:23:03 2545198 [33739]: r1045 acquire_disk rv 1 lver 10 at 2545198 2020-05-14 20:23:03 2545198 [33739]: cmd_acquire 6,16,33743 result 0 pid_dead 0 ... 2020-05-14 20:55:05 2547119 [33740]: cmd_release 6,16,33743 ci_in 6 fd 16 count 1 flags 0 2020-05-14 20:55:05 2547119 [33740]: r1045 release_token r_flags 8 lver 10 2020-05-14 20:55:05 2547119 [33740]: r1045 write_host_block host_id 61 flags 0 gen 0 dblock 18061:18061:61:1:2545198:10:RELEASED. 2020-05-14 20:55:05 2547119 [33740]: r1045 paxos_release leader 10 owner 61 1 2545198 2020-05-14 20:55:05 2547119 [33740]: r1045 release_token done r_flags 8 2020-05-14 20:55:05 2547119 [33740]: cmd_release 6,16,33743 result 0 pid_dead 0 count 1 full log of host_id 94: https://pastebin.com/H18vAHZq useful log, it's similar to host_id 60, but shorter time to release: 2020-05-14 20:01:20 8414771 [11203]: cmd_acquire 6,16,11206 ci_in 6 fd 16 count 1 flags 9 2020-05-14 20:01:20 8414771 [11203]: s5:r3021 resource lvm_fc261665e94c4d0f8341e254398e7ed5:VGLK:/dev/mapper/fc261665e94c4d0f8341e254398e7ed5-lvmlock:69206016:SH for 6,16,11206 2020-05-14 20:01:20 8414771 [11203]: r3021 paxos_acquire begin e 0 0 2020-05-14 20:01:20 8414771 [11203]: r3021 leader 6063 owner 36 2 0 dblocks 35:12124036:12124036:36:2:2097966:6063:1, 2020-05-14 20:01:20 8414771 [11203]: r3021 paxos_acquire leader 6063 owner 36 2 0 max mbal[35] 12124036 our_dblock 11840094 11840094 94 1 8325309 5921 2020-05-14 20:01:20 8414771 [11203]: r3021 paxos_acquire leader 6063 free 2020-05-14 20:01:20 8414771 [11203]: r3021 ballot 6064 phase1 write mbal 12126094 2020-05-14 20:01:20 8414771 [11203]: r3021 ballot 6064 phase1 read 93:12126094:0:0:0:0:6064:0, 2020-05-14 20:01:20 8414771 [11203]: r3021 ballot 6064 phase2 write bal 12126094 inp 94 1 8414771 q_max -1 2020-05-14 20:01:20 8414771 [11203]: r3021 ballot 6064 phase2 read 93:12126094:12126094:94:1:8414771:6064:0, 2020-05-14 20:01:20 8414771 [11203]: r3021 ballot 6064 commit self owner 94 1 8414771 2020-05-14 20:01:20 8414771 [11203]: r3021 acquire_disk rv 1 lver 6064 at 8414771 2020-05-14 20:01:20 8414771 [11203]: r3021 write_host_block host_id 94 flags 1 gen 1 dblock 12126094:12126094:94:1:8414771:6064:RELEASED. 2020-05-14 20:01:20 8414771 [11203]: r3021 paxos_release leader 6064 owner 94 1 8414771 2020-05-14 20:01:20 8414771 [11203]: cmd_acquire 6,16,11206 result 0 pid_dead 0 2020-05-14 20:01:20 8414771 [11202]: cmd_get_lvb ci 8 fd 20 result 0 res lvm_fc261665e94c4d0f8341e254398e7ed5:VGLK 2020-05-14 20:01:20 8414771 [11203]: cmd_acquire 6,16,11206 ci_in 6 fd 16 count 1 flags 8 2020-05-14 20:01:20 8414771 [11203]: s5:r3022 resource lvm_fc261665e94c4d0f8341e254398e7ed5:lL0kHh-CZ1i-jtMi-1qHO-ykfR-6nmu-Gk0rES:/dev/mapper/fc261665e94c4d0f8341e254398e7ed5-lvmlock:104857600:SH for 6,16,11206 2020-05-14 20:01:20 8414771 [11203]: r3022 paxos_acquire begin e 0 0 2020-05-14 20:01:20 8414771 [11203]: r3022 leader 8 owner 36 2 0 dblocks 35:14036:14036:36:2:1566014:8:1, 2020-05-14 20:01:20 8414771 [11203]: r3022 paxos_acquire leader 8 owner 36 2 0 max mbal[35] 14036 our_dblock 0 0 0 0 0 0 2020-05-14 20:01:20 8414771 [11203]: r3022 paxos_acquire leader 8 free 2020-05-14 20:01:20 8414771 [11203]: r3022 ballot 9 phase1 write mbal 16094 2020-05-14 20:01:20 8414771 [11203]: r3022 ballot 9 mode[35] shared 1 gen 2 2020-05-14 20:01:20 8414771 [11203]: r3022 ballot 9 phase1 read 93:16094:0:0:0:0:9:0, 2020-05-14 20:01:20 8414771 [11203]: r3022 ballot 9 phase2 write bal 16094 inp 94 1 8414771 q_max -1 2020-05-14 20:01:20 8414771 [11203]: r3022 ballot 9 phase2 read 93:16094:16094:94:1:8414771:9:0, 2020-05-14 20:01:20 8414771 [11203]: r3022 ballot 9 commit self owner 94 1 8414771 2020-05-14 20:01:20 8414771 [11203]: r3022 acquire_disk rv 1 lver 9 at 8414771 2020-05-14 20:01:20 8414771 [11203]: r3022 write_host_block host_id 94 flags 1 gen 1 dblock 16094:16094:94:1:8414771:9:RELEASED. 2020-05-14 20:01:20 8414771 [11203]: r3022 paxos_release leader 9 owner 94 1 8414771 2020-05-14 20:01:20 8414771 [11203]: cmd_acquire 6,16,11206 result 0 pid_dead 0 ... ... 2020-05-14 20:11:20 8415371 [11202]: cmd_release 6,16,11206 ci_in 6 fd 16 count 1 flags 0 2020-05-14 20:11:20 8415371 [11202]: r3022 release_token r_flags 1 lver 9 2020-05-14 20:11:20 8415371 [11202]: r3022 write_host_block host_id 94 flags 0 gen 0 dblock 16094:16094:94:1:8414771:9:RELEASED. 2020-05-14 20:11:20 8415371 [11202]: r3022 release_token done r_flags 1 2020-05-14 20:11:20 8415371 [11202]: cmd_release 6,16,11206 result 0 pid_dead 0 count 1 So, I got several questions: 1. Why it takes so long to release lock, does it should blame to storage I/O ? 2. Why other host(host_id 19) can read pervious shared lock(host_id 60 & 94) after hour? 3. What's the "right" way to solve this problem? Thanks a lot ! Damon Wang

2 2

[sanlock] branch master updated: sanlock: remove LOG_CONS from direct command
by pagure＠pagure.io 19 May '20

19 May '20

This is an automated email from the git hooks/post-receive script. teigland pushed a commit to branch master in repository sanlock. The following commit(s) were added to refs/heads/master by this push: new 315a0b9 sanlock: remove LOG_CONS from direct command 315a0b9 is described below commit 315a0b90612a2b6c3b11d33b48385aa1352fa671 Author: Nir Soffer <nsoffer(a)redhat.com> AuthorDate: Tue May 19 09:24:43 2020 -0500 sanlock: remove LOG_CONS from direct command --- src/main.c | 8 ++++++-- 1 file changed, 6 insertions(+), 2 deletions(-) diff --git a/src/main.c b/src/main.c index 8c6eef8..998ee58 100644 --- a/src/main.c +++ b/src/main.c @@ -3672,8 +3672,12 @@ static int do_direct(void) uint32_t cmd_flags = 0; int rv; - /* we want a record of any out-of-band changes to disk */ - openlog("sanlock-direct", LOG_CONS | LOG_PID, LOG_DAEMON); + /* + * We want a record of any out-of-band changes to disk in the system + * log. If /dev/log is missing, drop the message so it would not be + * logged to stderr. + */ + openlog("sanlock-direct", LOG_PID, LOG_DAEMON); setup_task_aio(&main_task, com.aio_arg, DIRECT_AIO_CB_SIZE); sprintf(main_task.name, "%s", "main_direct"); -- To stop receiving notification emails like this one, please contact the administrator of this repository.

1 0

sanlock 3.8.1 is available for testing
by Nir Soffer 14 May '20

14 May '20

I pushed sanlock 3.8.1 to Fedora updates-testing. If you have a Fedora 30 setup please upgrade sanlock: sudo dnf upgrade --enablerepo=updates-testing --advisory=FEDORA-2020-87665d32ca and provide feedback here: https://bodhi.fedoraproject.org/updates/FEDORA-2020-87665d32ca The update is also available for other versions: f31: https://bodhi.fedoraproject.org/updates/FEDORA-2020-455253f67d f32: https://bodhi.fedoraproject.org/updates/FEDORA-2020-99d4242726 f33: already in stable Cheers, Nir

1 2

[sanlock] 02/02: sanlock: write_init_io_timeout
by pagure＠pagure.io 11 May '20

11 May '20

This is an automated email from the git hooks/post-receive script. teigland pushed a commit to branch test-sched2 in repository sanlock. commit 3268693b861d1886af19f3fc75b67b28c3cbd572 Author: David Teigland <teigland(a)redhat.com> AuthorDate: Fri May 8 16:22:04 2020 -0500 sanlock: write_init_io_timeout Add a new io timeout used when initializing ondisk structures for a lockspace or resource. This is independent of the standard io timeout used as part of the lockspace or resource algorithm. This write_init_io_timeout will generally be larger, can be set in sanlock.conf, and if zero the code will fall back to using the standard io_timeout as has been used before. --- src/cmd.c | 2 ++ src/delta_lease.c | 16 ++++++++++++++-- src/main.c | 6 ++++++ src/paxos_lease.c | 13 ++++++++++++- src/sanlock.8 | 7 +++++++ src/sanlock.conf | 3 +++ src/sanlock_internal.h | 2 ++ 7 files changed, 46 insertions(+), 3 deletions(-) diff --git a/src/cmd.c b/src/cmd.c index 5c91181..cdeac7a 100644 --- a/src/cmd.c +++ b/src/cmd.c @@ -2267,6 +2267,7 @@ static int print_state_daemon(char *str) "max_sectors_kb_ignore=%d " "max_sectors_kb_align=%d " "max_sectors_kb_num=%d " + "write_init_io_timeout=%u " "use_aio=%d " "kill_grace_seconds=%d " "helper_pid=%d " @@ -2295,6 +2296,7 @@ static int print_state_daemon(char *str) com.max_sectors_kb_ignore, com.max_sectors_kb_align, com.max_sectors_kb_num, + com.write_init_io_timeout, main_task.use_aio, kill_grace_seconds, helper_pid, diff --git a/src/delta_lease.c b/src/delta_lease.c index 5616432..9a8fc22 100644 --- a/src/delta_lease.c +++ b/src/delta_lease.c @@ -844,6 +844,7 @@ int delta_lease_init(struct task *task, int sector_size = 0; int align_size = 0; int max_hosts = 0; + int write_io_timeout; int i, rv; uint32_t checksum; @@ -903,8 +904,19 @@ int delta_lease_init(struct task *task, memcpy(iobuf + (i * sector_size), &leader_end, sizeof(struct leader_record)); } + + /* + * The io_timeout arg is a part of the lockspace logic, and + * determines how the lockspace times out. The process of + * initializing the lease on disk can to use a longer timeout + * than the algorithm uses. + */ + if (com.write_init_io_timeout) + write_io_timeout = com.write_init_io_timeout; + else + write_io_timeout = io_timeout; - rv = write_iobuf(disk->fd, disk->offset, iobuf, iobuf_len, task, io_timeout, NULL); + rv = write_iobuf(disk->fd, disk->offset, iobuf, iobuf_len, task, write_io_timeout, NULL); if (rv < 0) goto out; @@ -924,7 +936,7 @@ int delta_lease_init(struct task *task, memcpy(iobuf, &leader_end, sizeof(struct leader_record)); - rv = write_iobuf(disk->fd, disk->offset, iobuf, sector_size, task, io_timeout, NULL); + rv = write_iobuf(disk->fd, disk->offset, iobuf, sector_size, task, write_io_timeout, NULL); out: if (rv != SANLK_AIO_TIMEOUT) free(iobuf); diff --git a/src/main.c b/src/main.c index 7336df2..67b70c5 100644 --- a/src/main.c +++ b/src/main.c @@ -2820,6 +2820,11 @@ static void read_config_file(void) com.renewal_read_extend_sec_set = 1; com.renewal_read_extend_sec = val; + } else if (!strcmp(str, "write_init_io_timeout")) { + get_val_int(line, &val); + if (val > 0) + com.write_init_io_timeout = val; + } else if (!strcmp(str, "renewal_history_size")) { get_val_int(line, &val); com.renewal_history_size = val; @@ -3866,6 +3871,7 @@ int main(int argc, char *argv[]) com.names_log_priority = LOG_WARNING; com.max_worker_threads = DEFAULT_MAX_WORKER_THREADS; com.io_timeout_arg = DEFAULT_IO_TIMEOUT; + com.write_init_io_timeout = DEFAULT_WRITE_INIT_IO_TIMEOUT; com.aio_arg = DEFAULT_USE_AIO; com.pid = -1; com.sh_retries = DEFAULT_SH_RETRIES; diff --git a/src/paxos_lease.c b/src/paxos_lease.c index 259cd15..4850347 100644 --- a/src/paxos_lease.c +++ b/src/paxos_lease.c @@ -2422,6 +2422,7 @@ int paxos_lease_init(struct task *task, int align_size = 0; int max_hosts = 0; int aio_timeout = 0; + int write_io_timeout = 0; int rv, d; rv = sizes_from_flags(token->r.flags, &sector_size, &align_size, &max_hosts, "RES"); @@ -2488,9 +2489,19 @@ int paxos_lease_init(struct task *task, memcpy(iobuf, &leader_end, sizeof(struct leader_record)); memcpy(iobuf + sector_size, &rr_end, sizeof(struct request_record)); + /* + * The process of initializing the lease on disk can use a + * longer timeout than the algorithm uses. + */ + if (com.write_init_io_timeout) + write_io_timeout = com.write_init_io_timeout; + for (d = 0; d < token->r.num_disks; d++) { + if (!write_io_timeout) + write_io_timeout = token->io_timeout; + rv = write_iobuf(token->disks[d].fd, token->disks[d].offset, - iobuf, iobuf_len, task, token->io_timeout, NULL); + iobuf, iobuf_len, task, write_io_timeout, NULL); if (rv == SANLK_AIO_TIMEOUT) aio_timeout = 1; diff --git a/src/sanlock.8 b/src/sanlock.8 index 4704122..63a017c 100644 --- a/src/sanlock.8 +++ b/src/sanlock.8 @@ -1378,6 +1378,13 @@ sched_warn_renew_sec = <seconds> Log a warning if the wait between lockspace renewals is this many seconds longer than intended. Set to 0 to disable. +.IP \[bu] 2 +write_init_io_timeout = <seconds> +.br +The io timeout to use when initializing ondisk lease structures +for a lockspace or resource. This timeout is not used as a part +of either lease algorithm (as the standard io_timeout is.) + .SH SEE ALSO .BR wdmd (8) diff --git a/src/sanlock.conf b/src/sanlock.conf index 5d47ad1..71eee41 100644 --- a/src/sanlock.conf +++ b/src/sanlock.conf @@ -69,3 +69,6 @@ # # sched_warn_renew_sec = <seconds> # command line: n/a +# +# write_init_io_timeout = <seconds> +# command line: n/a diff --git a/src/sanlock_internal.h b/src/sanlock_internal.h index b103209..22507c3 100644 --- a/src/sanlock_internal.h +++ b/src/sanlock_internal.h @@ -329,6 +329,7 @@ EXTERN struct client *client; #define DEFAULT_SH_RETRIES 8 #define DEFAULT_QUIET_FAIL 1 #define DEFAULT_RENEWAL_HISTORY_SIZE 180 /* about 1 hour with 20 sec renewal interval */ +#define DEFAULT_WRITE_INIT_IO_TIMEOUT 60 #define DEFAULT_MAX_SECTORS_KB_IGNORE 0 /* don't change it */ #define DEFAULT_MAX_SECTORS_KB_ALIGN 0 /* set it to align size */ @@ -357,6 +358,7 @@ struct command_line { int max_worker_threads; int aio_arg; int io_timeout_arg; + int write_init_io_timeout; int set_bitmap_seconds; int persistent; int orphan_set; -- To stop receiving notification emails like this one, please contact the administrator of this repository.

1 0

[sanlock] 01/02: sanlock: warn about scheduling delay
by pagure＠pagure.io 11 May '20

11 May '20

This is an automated email from the git hooks/post-receive script. teigland pushed a commit to branch test-sched2 in repository sanlock. commit d41ec4a2871942d82a6d7664dcc17330064685c9 Author: David Teigland <teigland(a)redhat.com> AuthorDate: Fri May 8 14:36:07 2020 -0500 sanlock: warn about scheduling delay Two new config file settings: sched_warn_main_ms = <ms> sched_warn_renew_sec = <sec> If the main loop check interval is delayed more than <ms> milliseconds longer than intended, log a warning. If the lockspace thread sleep between renewals is <sec> seconds longer than intended, log a warning. --- src/cmd.c | 4 ++++ src/lockspace.c | 27 ++++++++++++++++++++++++++- src/main.c | 15 +++++++++++++++ src/sanlock.8 | 13 +++++++++++++ src/sanlock.conf | 6 ++++++ src/sanlock_internal.h | 2 ++ 6 files changed, 66 insertions(+), 1 deletion(-) diff --git a/src/cmd.c b/src/cmd.c index 23522ba..5c91181 100644 --- a/src/cmd.c +++ b/src/cmd.c @@ -2259,6 +2259,8 @@ static int print_state_daemon(char *str) "debug_clients=%d " "debug_cmds=0x%llx " "renewal_history_size=%d " + "sched_warn_main_ms=%u " + "sched_warn_renew_sec=%u " "gid=%d " "uid=%d " "sh_retries=%d " @@ -2285,6 +2287,8 @@ static int print_state_daemon(char *str) com.debug_clients, (unsigned long long)com.debug_cmds, com.renewal_history_size, + com.sched_warn_main_ms, + com.sched_warn_renew_sec, com.gid, com.uid, com.sh_retries, diff --git a/src/lockspace.c b/src/lockspace.c index 41f96cb..dd4875f 100644 --- a/src/lockspace.c +++ b/src/lockspace.c @@ -670,6 +670,8 @@ static void *lockspace_thread(void *arg_in) struct space *sp; struct leader_record leader; uint64_t delta_begin, last_success = 0; + uint64_t wait_interval_begin = 0, wait_interval_want = 0; + uint64_t now; int sector_size = 0; int align_size = 0; int max_hosts = 0; @@ -815,9 +817,24 @@ static void *lockspace_thread(void *arg_in) /* * wait between each renewal + * + * T=10 delta renew begins and ends, wrote leader.timesamp=10, last_success=10 + * T=30 delta renew begins, write leader.timestamp=30 + * T=35 delta renew ends after write being delayed + * renewal_interval = leader.timestamp - last_success (30-10) = 20 + * last_success = leader.timestamp = 30 + * + * now - last_success (35 - 30) = 5 < id_renewal_seconds (20) + * so delay for 15 sec before starting next renewal + * delay = id_renewal_seconds - (now - last_success) */ + now = monotime(); - if (monotime() - last_success < id_renewal_seconds) { + if (now - last_success < id_renewal_seconds) { + if (!wait_interval_begin) { + wait_interval_begin = now; + wait_interval_want = id_renewal_seconds - (now - last_success); + } sleep(1); continue; } else { @@ -826,6 +843,14 @@ static void *lockspace_thread(void *arg_in) usleep(500000); } + /* Warn about scheduling delays */ + if (com.sched_warn_renew_sec && wait_interval_begin && wait_interval_want && + (now - wait_interval_begin > wait_interval_want + com.sched_warn_renew_sec)) { + log_warns(sp, "renew interval is %u sec want %u warn %u", + (uint32_t)(now - wait_interval_begin), (uint32_t)wait_interval_want, com.sched_warn_renew_sec); + } + wait_interval_begin = 0; + wait_interval_want = 0; /* * do a renewal, measuring length of time spent in renewal, diff --git a/src/main.c b/src/main.c index 8c6eef8..7336df2 100644 --- a/src/main.c +++ b/src/main.c @@ -823,6 +823,11 @@ static int main_loop(void) poll_timeout = check_interval - ms; continue; } + if (com.sched_warn_main_ms && + (ms >= (check_interval + com.sched_warn_main_ms))) { + log_warn("main check interval is %u ms want %u warn %u", + ms, check_interval, com.sched_warn_main_ms); + } last_check = now; check_interval = STANDARD_CHECK_INTERVAL; @@ -2872,6 +2877,14 @@ static void read_config_file(void) } else { log_error("ignore unknown max_sectors_kb %s", str); } + + } else if (!strcmp(str, "sched_warn_main_ms")) { + get_val_int(line, &val); + com.sched_warn_main_ms = val; + + } else if (!strcmp(str, "sched_warn_renew_sec")) { + get_val_int(line, &val); + com.sched_warn_renew_sec = val; } } @@ -3860,6 +3873,8 @@ int main(int argc, char *argv[]) com.renewal_read_extend_sec_set = 0; com.renewal_read_extend_sec = 0; com.renewal_history_size = DEFAULT_RENEWAL_HISTORY_SIZE; + com.sched_warn_main_ms = 2000; + com.sched_warn_renew_sec = 2; com.paxos_debug_all = 0; com.max_sectors_kb_ignore = DEFAULT_MAX_SECTORS_KB_IGNORE; com.max_sectors_kb_align = DEFAULT_MAX_SECTORS_KB_ALIGN; diff --git a/src/sanlock.8 b/src/sanlock.8 index d75211d..4704122 100644 --- a/src/sanlock.8 +++ b/src/sanlock.8 @@ -1365,6 +1365,19 @@ for that command. Special values +all and -all can be used to enable or disable all commands, and can be used before or after other debug_cmd lines. +.IP \[bu] 2 +sched_warn_main_ms = <msec> +.br +Log a warning if the interval between checks by main processing +loop is this many milliseconds longer than intended. Set to 0 +to disable. + +.IP \[bu] 2 +sched_warn_renew_sec = <seconds> +.br +Log a warning if the wait between lockspace renewals is this +many seconds longer than intended. Set to 0 to disable. + .SH SEE ALSO .BR wdmd (8) diff --git a/src/sanlock.conf b/src/sanlock.conf index e52da2b..5d47ad1 100644 --- a/src/sanlock.conf +++ b/src/sanlock.conf @@ -63,3 +63,9 @@ # debug_cmd = -<name> # ... # command line: n/a +# +# sched_warn_main_ms = <msec> +# command line: n/a +# +# sched_warn_renew_sec = <seconds> +# command line: n/a diff --git a/src/sanlock_internal.h b/src/sanlock_internal.h index cd4d23a..b103209 100644 --- a/src/sanlock_internal.h +++ b/src/sanlock_internal.h @@ -385,6 +385,8 @@ struct command_line { int renewal_history_size; int renewal_read_extend_sec_set; /* 1 if renewal_read_extend_sec is configured */ uint32_t renewal_read_extend_sec; + uint32_t sched_warn_main_ms; + uint32_t sched_warn_renew_sec; char our_host_name[SANLK_NAME_LEN+1]; char *file_path; char *dump_path; -- To stop receiving notification emails like this one, please contact the administrator of this repository.

1 0

[sanlock] 03/03: sanlock: write_init_io_timeout
by pagure＠pagure.io 08 May '20

08 May '20

This is an automated email from the git hooks/post-receive script. teigland pushed a commit to branch test-sched in repository sanlock. commit 5142d99184a301dbc37870e93e8ffa07b41c3495 Author: David Teigland <teigland(a)redhat.com> AuthorDate: Fri May 8 16:22:04 2020 -0500 sanlock: write_init_io_timeout Add a new io timeout used when initializing ondisk structures for a lockspace or resource. This is independent of the standard io timeout used as part of the lockspace or resource algorithm. This write_init_io_timeout will generally be larger, can be set in sanlock.conf, and if zero the code will fall back to using the standard io_timeout as has been used before. --- src/cmd.c | 2 ++ src/delta_lease.c | 16 ++++++++++++++-- src/main.c | 6 ++++++ src/paxos_lease.c | 13 ++++++++++++- src/sanlock.8 | 7 +++++++ src/sanlock.conf | 3 +++ src/sanlock_internal.h | 2 ++ 7 files changed, 46 insertions(+), 3 deletions(-) diff --git a/src/cmd.c b/src/cmd.c index 5c91181..cdeac7a 100644 --- a/src/cmd.c +++ b/src/cmd.c @@ -2267,6 +2267,7 @@ static int print_state_daemon(char *str) "max_sectors_kb_ignore=%d " "max_sectors_kb_align=%d " "max_sectors_kb_num=%d " + "write_init_io_timeout=%u " "use_aio=%d " "kill_grace_seconds=%d " "helper_pid=%d " @@ -2295,6 +2296,7 @@ static int print_state_daemon(char *str) com.max_sectors_kb_ignore, com.max_sectors_kb_align, com.max_sectors_kb_num, + com.write_init_io_timeout, main_task.use_aio, kill_grace_seconds, helper_pid, diff --git a/src/delta_lease.c b/src/delta_lease.c index 5616432..9a8fc22 100644 --- a/src/delta_lease.c +++ b/src/delta_lease.c @@ -844,6 +844,7 @@ int delta_lease_init(struct task *task, int sector_size = 0; int align_size = 0; int max_hosts = 0; + int write_io_timeout; int i, rv; uint32_t checksum; @@ -903,8 +904,19 @@ int delta_lease_init(struct task *task, memcpy(iobuf + (i * sector_size), &leader_end, sizeof(struct leader_record)); } + + /* + * The io_timeout arg is a part of the lockspace logic, and + * determines how the lockspace times out. The process of + * initializing the lease on disk can to use a longer timeout + * than the algorithm uses. + */ + if (com.write_init_io_timeout) + write_io_timeout = com.write_init_io_timeout; + else + write_io_timeout = io_timeout; - rv = write_iobuf(disk->fd, disk->offset, iobuf, iobuf_len, task, io_timeout, NULL); + rv = write_iobuf(disk->fd, disk->offset, iobuf, iobuf_len, task, write_io_timeout, NULL); if (rv < 0) goto out; @@ -924,7 +936,7 @@ int delta_lease_init(struct task *task, memcpy(iobuf, &leader_end, sizeof(struct leader_record)); - rv = write_iobuf(disk->fd, disk->offset, iobuf, sector_size, task, io_timeout, NULL); + rv = write_iobuf(disk->fd, disk->offset, iobuf, sector_size, task, write_io_timeout, NULL); out: if (rv != SANLK_AIO_TIMEOUT) free(iobuf); diff --git a/src/main.c b/src/main.c index 4afd4db..75c792d 100644 --- a/src/main.c +++ b/src/main.c @@ -2819,6 +2819,11 @@ static void read_config_file(void) com.renewal_read_extend_sec_set = 1; com.renewal_read_extend_sec = val; + } else if (!strcmp(str, "write_init_io_timeout")) { + get_val_int(line, &val); + if (val > 0) + com.write_init_io_timeout = val; + } else if (!strcmp(str, "renewal_history_size")) { get_val_int(line, &val); com.renewal_history_size = val; @@ -3865,6 +3870,7 @@ int main(int argc, char *argv[]) com.names_log_priority = LOG_WARNING; com.max_worker_threads = DEFAULT_MAX_WORKER_THREADS; com.io_timeout_arg = DEFAULT_IO_TIMEOUT; + com.write_init_io_timeout = DEFAULT_WRITE_INIT_IO_TIMEOUT; com.aio_arg = DEFAULT_USE_AIO; com.pid = -1; com.sh_retries = DEFAULT_SH_RETRIES; diff --git a/src/paxos_lease.c b/src/paxos_lease.c index 259cd15..4850347 100644 --- a/src/paxos_lease.c +++ b/src/paxos_lease.c @@ -2422,6 +2422,7 @@ int paxos_lease_init(struct task *task, int align_size = 0; int max_hosts = 0; int aio_timeout = 0; + int write_io_timeout = 0; int rv, d; rv = sizes_from_flags(token->r.flags, &sector_size, &align_size, &max_hosts, "RES"); @@ -2488,9 +2489,19 @@ int paxos_lease_init(struct task *task, memcpy(iobuf, &leader_end, sizeof(struct leader_record)); memcpy(iobuf + sector_size, &rr_end, sizeof(struct request_record)); + /* + * The process of initializing the lease on disk can use a + * longer timeout than the algorithm uses. + */ + if (com.write_init_io_timeout) + write_io_timeout = com.write_init_io_timeout; + for (d = 0; d < token->r.num_disks; d++) { + if (!write_io_timeout) + write_io_timeout = token->io_timeout; + rv = write_iobuf(token->disks[d].fd, token->disks[d].offset, - iobuf, iobuf_len, task, token->io_timeout, NULL); + iobuf, iobuf_len, task, write_io_timeout, NULL); if (rv == SANLK_AIO_TIMEOUT) aio_timeout = 1; diff --git a/src/sanlock.8 b/src/sanlock.8 index 0ee8d95..0328b17 100644 --- a/src/sanlock.8 +++ b/src/sanlock.8 @@ -1378,6 +1378,13 @@ sched_warn_renew_sec = <seconds> Log a warning if the intended delay between lockspace renewals is this many seconds later than intended. Set to 0 to disable. +.IP \[bu] 2 +write_init_io_timeout = <seconds> +.br +The io timeout to use when initializing ondisk lease structures +for a lockspace or resource. This timeout is not used as a part +of either lease algorithm (as the standard io_timeout is.) + .SH SEE ALSO .BR wdmd (8) diff --git a/src/sanlock.conf b/src/sanlock.conf index 5d47ad1..71eee41 100644 --- a/src/sanlock.conf +++ b/src/sanlock.conf @@ -69,3 +69,6 @@ # # sched_warn_renew_sec = <seconds> # command line: n/a +# +# write_init_io_timeout = <seconds> +# command line: n/a diff --git a/src/sanlock_internal.h b/src/sanlock_internal.h index b103209..22507c3 100644 --- a/src/sanlock_internal.h +++ b/src/sanlock_internal.h @@ -329,6 +329,7 @@ EXTERN struct client *client; #define DEFAULT_SH_RETRIES 8 #define DEFAULT_QUIET_FAIL 1 #define DEFAULT_RENEWAL_HISTORY_SIZE 180 /* about 1 hour with 20 sec renewal interval */ +#define DEFAULT_WRITE_INIT_IO_TIMEOUT 60 #define DEFAULT_MAX_SECTORS_KB_IGNORE 0 /* don't change it */ #define DEFAULT_MAX_SECTORS_KB_ALIGN 0 /* set it to align size */ @@ -357,6 +358,7 @@ struct command_line { int max_worker_threads; int aio_arg; int io_timeout_arg; + int write_init_io_timeout; int set_bitmap_seconds; int persistent; int orphan_set; -- To stop receiving notification emails like this one, please contact the administrator of this repository.

1 0

[sanlock] 02/03: sanlock: warn about scheduling delay
by pagure＠pagure.io 08 May '20

08 May '20

This is an automated email from the git hooks/post-receive script. teigland pushed a commit to branch test-sched in repository sanlock. commit f49110b426222c931e604e63ee38552d549d0eac Author: David Teigland <teigland(a)redhat.com> AuthorDate: Fri May 8 14:36:07 2020 -0500 sanlock: warn about scheduling delay Two new config file settings: sched_warn_main_ms = <ms> sched_warn_renew_sec = <sec> If the main loop check interval is delayed more than <ms> milliseconds longer than intended, log a warning. If the lockspace thread sleep between renewals is <sec> seconds longer than intended, log a warning. --- src/cmd.c | 4 ++++ src/lockspace.c | 27 ++++++++++++++++++++++++++- src/main.c | 14 ++++++++++++++ src/sanlock.8 | 13 +++++++++++++ src/sanlock.conf | 6 ++++++ src/sanlock_internal.h | 2 ++ 6 files changed, 65 insertions(+), 1 deletion(-) diff --git a/src/cmd.c b/src/cmd.c index 23522ba..5c91181 100644 --- a/src/cmd.c +++ b/src/cmd.c @@ -2259,6 +2259,8 @@ static int print_state_daemon(char *str) "debug_clients=%d " "debug_cmds=0x%llx " "renewal_history_size=%d " + "sched_warn_main_ms=%u " + "sched_warn_renew_sec=%u " "gid=%d " "uid=%d " "sh_retries=%d " @@ -2285,6 +2287,8 @@ static int print_state_daemon(char *str) com.debug_clients, (unsigned long long)com.debug_cmds, com.renewal_history_size, + com.sched_warn_main_ms, + com.sched_warn_renew_sec, com.gid, com.uid, com.sh_retries, diff --git a/src/lockspace.c b/src/lockspace.c index 41f96cb..dd4875f 100644 --- a/src/lockspace.c +++ b/src/lockspace.c @@ -670,6 +670,8 @@ static void *lockspace_thread(void *arg_in) struct space *sp; struct leader_record leader; uint64_t delta_begin, last_success = 0; + uint64_t wait_interval_begin = 0, wait_interval_want = 0; + uint64_t now; int sector_size = 0; int align_size = 0; int max_hosts = 0; @@ -815,9 +817,24 @@ static void *lockspace_thread(void *arg_in) /* * wait between each renewal + * + * T=10 delta renew begins and ends, wrote leader.timesamp=10, last_success=10 + * T=30 delta renew begins, write leader.timestamp=30 + * T=35 delta renew ends after write being delayed + * renewal_interval = leader.timestamp - last_success (30-10) = 20 + * last_success = leader.timestamp = 30 + * + * now - last_success (35 - 30) = 5 < id_renewal_seconds (20) + * so delay for 15 sec before starting next renewal + * delay = id_renewal_seconds - (now - last_success) */ + now = monotime(); - if (monotime() - last_success < id_renewal_seconds) { + if (now - last_success < id_renewal_seconds) { + if (!wait_interval_begin) { + wait_interval_begin = now; + wait_interval_want = id_renewal_seconds - (now - last_success); + } sleep(1); continue; } else { @@ -826,6 +843,14 @@ static void *lockspace_thread(void *arg_in) usleep(500000); } + /* Warn about scheduling delays */ + if (com.sched_warn_renew_sec && wait_interval_begin && wait_interval_want && + (now - wait_interval_begin > wait_interval_want + com.sched_warn_renew_sec)) { + log_warns(sp, "renew interval is %u sec want %u warn %u", + (uint32_t)(now - wait_interval_begin), (uint32_t)wait_interval_want, com.sched_warn_renew_sec); + } + wait_interval_begin = 0; + wait_interval_want = 0; /* * do a renewal, measuring length of time spent in renewal, diff --git a/src/main.c b/src/main.c index 8c6eef8..4afd4db 100644 --- a/src/main.c +++ b/src/main.c @@ -823,6 +823,10 @@ static int main_loop(void) poll_timeout = check_interval - ms; continue; } + if (ms >= (check_interval + com.sched_warn_main_ms)) { + log_warn("main check interval is %u ms want %u warn %u", + ms, check_interval, com.sched_warn_main_ms); + } last_check = now; check_interval = STANDARD_CHECK_INTERVAL; @@ -2872,6 +2876,14 @@ static void read_config_file(void) } else { log_error("ignore unknown max_sectors_kb %s", str); } + + } else if (!strcmp(str, "sched_warn_main_ms")) { + get_val_int(line, &val); + com.sched_warn_main_ms = val; + + } else if (!strcmp(str, "sched_warn_renew_sec")) { + get_val_int(line, &val); + com.sched_warn_renew_sec = val; } } @@ -3860,6 +3872,8 @@ int main(int argc, char *argv[]) com.renewal_read_extend_sec_set = 0; com.renewal_read_extend_sec = 0; com.renewal_history_size = DEFAULT_RENEWAL_HISTORY_SIZE; + com.sched_warn_main_ms = 2000; + com.sched_warn_renew_sec = 2; com.paxos_debug_all = 0; com.max_sectors_kb_ignore = DEFAULT_MAX_SECTORS_KB_IGNORE; com.max_sectors_kb_align = DEFAULT_MAX_SECTORS_KB_ALIGN; diff --git a/src/sanlock.8 b/src/sanlock.8 index d75211d..0ee8d95 100644 --- a/src/sanlock.8 +++ b/src/sanlock.8 @@ -1365,6 +1365,19 @@ for that command. Special values +all and -all can be used to enable or disable all commands, and can be used before or after other debug_cmd lines. +.IP \[bu] 2 +sched_warn_main_ms = <msec> +.br +Log a warning if the intended check interval of the main processing +loop is run this many milliseconds later than intended. Set to 0 +to disable. + +.IP \[bu] 2 +sched_warn_renew_sec = <seconds> +.br +Log a warning if the intended delay between lockspace renewals +is this many seconds later than intended. Set to 0 to disable. + .SH SEE ALSO .BR wdmd (8) diff --git a/src/sanlock.conf b/src/sanlock.conf index e52da2b..5d47ad1 100644 --- a/src/sanlock.conf +++ b/src/sanlock.conf @@ -63,3 +63,9 @@ # debug_cmd = -<name> # ... # command line: n/a +# +# sched_warn_main_ms = <msec> +# command line: n/a +# +# sched_warn_renew_sec = <seconds> +# command line: n/a diff --git a/src/sanlock_internal.h b/src/sanlock_internal.h index cd4d23a..b103209 100644 --- a/src/sanlock_internal.h +++ b/src/sanlock_internal.h @@ -385,6 +385,8 @@ struct command_line { int renewal_history_size; int renewal_read_extend_sec_set; /* 1 if renewal_read_extend_sec is configured */ uint32_t renewal_read_extend_sec; + uint32_t sched_warn_main_ms; + uint32_t sched_warn_renew_sec; char our_host_name[SANLK_NAME_LEN+1]; char *file_path; char *dump_path; -- To stop receiving notification emails like this one, please contact the administrator of this repository.

1 0

[sanlock] 01/03: disable high_priority SCHED_RR by default
by pagure＠pagure.io 08 May '20

08 May '20

This is an automated email from the git hooks/post-receive script. teigland pushed a commit to branch test-sched in repository sanlock. commit fdf599535f93181d89fabcade2d3c8a625231775 Author: David Teigland <teigland(a)redhat.com> AuthorDate: Fri May 8 15:22:17 2020 -0500 disable high_priority SCHED_RR by default in both sanlock and wdmd Setting the scheduler does not work with the default system setup. --- src/sanlock_internal.h | 2 +- wdmd/main.c | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/src/sanlock_internal.h b/src/sanlock_internal.h index 381b0e6..cd4d23a 100644 --- a/src/sanlock_internal.h +++ b/src/sanlock_internal.h @@ -319,7 +319,7 @@ EXTERN struct client *client; #define DEFAULT_IO_TIMEOUT 10 #define DEFAULT_GRACE_SEC 40 #define DEFAULT_USE_WATCHDOG 1 -#define DEFAULT_HIGH_PRIORITY 1 +#define DEFAULT_HIGH_PRIORITY 0 #define DEFAULT_MLOCK_LEVEL 1 /* 1=CURRENT, 2=CURRENT|FUTURE */ #define DEFAULT_SOCKET_UID 0 #define DEFAULT_SOCKET_GID 0 diff --git a/wdmd/main.c b/wdmd/main.c index edd15e8..aebacbe 100644 --- a/wdmd/main.c +++ b/wdmd/main.c @@ -44,7 +44,7 @@ #define DEFAULT_TEST_INTERVAL 10 #define RECOVER_TEST_INTERVAL 1 #define DEFAULT_FIRE_TIMEOUT 60 -#define DEFAULT_HIGH_PRIORITY 1 +#define DEFAULT_HIGH_PRIORITY 0 /* * If the group name specified here, or specified on the -- To stop receiving notification emails like this one, please contact the administrator of this repository.

1 0

[sanlock] 02/02: Makefile: %systemd_postun requires arguments now
by pagure＠pagure.io 07 May '20

07 May '20

This is an automated email from the git hooks/post-receive script. nsoffer pushed a commit to branch master in repository sanlock. commit 820b52a95cb1939bfe9d2fadf9a1137f33f47926 Author: Nir Soffer <nsoffer(a)redhat.com> AuthorDate: Sun May 3 01:54:12 2020 +0300 Makefile: %systemd_postun requires arguments now Since Fedora 31, %system_postun requires arguments, and fail with this "helpful" message without arguments: error: This macro requires some arguments Signed-off-by: Nir Soffer <nsoffer(a)redhat.com> --- sanlock.spec.in | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/sanlock.spec.in b/sanlock.spec.in index 9ae4d8f..b14da9b 100644 --- a/sanlock.spec.in +++ b/sanlock.spec.in @@ -99,7 +99,7 @@ getent passwd sanlock > /dev/null || /usr/sbin/useradd \ %systemd_preun wdmd.service sanlock.service %postun -%systemd_postun +%systemd_postun wdmd.service sanlock.service %files /usr/lib/systemd/systemd-wdmd -- To stop receiving notification emails like this one, please contact the administrator of this repository.

1 0

[sanlock] 01/02: Makfile: Use PY_VERSION=3
by pagure＠pagure.io 07 May '20

07 May '20

This is an automated email from the git hooks/post-receive script. nsoffer pushed a commit to branch master in repository sanlock. commit 6c4f557afa2276f9ea11bdf5217e5d34b209d14f Author: Nir Soffer <nsoffer(a)redhat.com> AuthorDate: Sun May 3 01:39:04 2020 +0300 Makfile: Use PY_VERSION=3 The makefile was using 3.6 which is leftover from Fedora 29. Using python3 works with any python 3 version. Signed-off-by: Nir Soffer <nsoffer(a)redhat.com> --- sanlock.spec.in | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/sanlock.spec.in b/sanlock.spec.in index 087076c..9ae4d8f 100644 --- a/sanlock.spec.in +++ b/sanlock.spec.in @@ -46,7 +46,7 @@ The sanlock daemon manages leases for applications on hosts using shared storage # upstream does not support _smp_mflags CFLAGS=$RPM_OPT_FLAGS make -C wdmd CFLAGS=$RPM_OPT_FLAGS make -C src -CFLAGS=$RPM_OPT_FLAGS make -C python PY_VERSION=3.6 +CFLAGS=$RPM_OPT_FLAGS make -C python PY_VERSION=3 CFLAGS=$RPM_OPT_FLAGS make -C reset %install @@ -60,7 +60,7 @@ make -C wdmd \ make -C python \ install LIBDIR=%{_libdir} \ DESTDIR=$RPM_BUILD_ROOT \ - PY_VERSION=3.6 + PY_VERSION=3 make -C reset \ install LIBDIR=%{_libdir} \ DESTDIR=$RPM_BUILD_ROOT -- To stop receiving notification emails like this one, please contact the administrator of this repository.

1 0

2024

2023

2022

2021

2020

2019

2018

2017

2016

2015

2014

2013

2012

2011

sanlock-devel May 2020