4:44 p.m.
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.