[Cluster-devel] [PATCH dlm-tool 1/8] dlm_tool: add fail functionality if dump failed

[Cluster-devel] [PATCH dlm-tool 1/8] dlm_tool: add fail functionality if dump failed

[Alexander Aring]

Currently dlm_controld sets a embedded data int value of dlm_controld
dump functionality failed for e.g. if lockspace cannot be found. The
dlm_tool does not parse this possible error functionality and will exit
successfully. This patch will add dlm_tool fail functionality if
dlm_controld sets an embedded data error value.
---
 dlm_controld/lib.c           | 25 +++++++++-------
 dlm_controld/libdlmcontrol.h | 10 +++----
 dlm_tool/main.c              | 57 +++++++++++++++++++++++++++---------
 3 files changed, 62 insertions(+), 30 deletions(-)

diff --git a/dlm_controld/lib.c b/dlm_controld/lib.c
index 2888ad05..a21150f2 100644
--- a/dlm_controld/lib.c
+++ b/dlm_controld/lib.c
@@ -109,7 +109,7 @@ static void init_header(struct dlmc_header *h, int cmd, char *name,
 
 static char copy_buf[DLMC_DUMP_SIZE];
 
-static int do_dump(int cmd, char *name, char *buf)
+static int do_dump(int cmd, char *name, char *buf, int *data)
 {
 	struct dlmc_header h;
 	int fd, rv, len;
@@ -118,6 +118,8 @@ static int do_dump(int cmd, char *name, char *buf)
 
 	init_header(&h, cmd, name, 0);
 
+	*data = 0;
+
 	fd = do_connect(DLMC_QUERY_SOCK_PATH);
 	if (fd < 0) {
 		rv = fd;
@@ -134,6 +136,7 @@ static int do_dump(int cmd, char *name, char *buf)
 	if (rv < 0)
 		goto out_close;
 
+	*data = h.data;
 	len = h.len - sizeof(h);
 
 	if (len <= 0 || len > DLMC_DUMP_SIZE)
@@ -150,29 +153,29 @@ static int do_dump(int cmd, char *name, char *buf)
 	return rv;
 }
 
-int dlmc_dump_debug(char *buf)
+int dlmc_dump_debug(char *buf, int *data)
 {
-	return do_dump(DLMC_CMD_DUMP_DEBUG, NULL, buf);
+	return do_dump(DLMC_CMD_DUMP_DEBUG, NULL, buf, data);
 }
 
-int dlmc_dump_config(char *buf)
+int dlmc_dump_config(char *buf, int *data)
 {
-	return do_dump(DLMC_CMD_DUMP_CONFIG, NULL, buf);
+	return do_dump(DLMC_CMD_DUMP_CONFIG, NULL, buf, data);
 }
 
-int dlmc_dump_log_plock(char *buf)
+int dlmc_dump_log_plock(char *buf, int *data)
 {
-	return do_dump(DLMC_CMD_DUMP_LOG_PLOCK, NULL, buf);
+	return do_dump(DLMC_CMD_DUMP_LOG_PLOCK, NULL, buf, data);
 }
 
-int dlmc_dump_plocks(char *name, char *buf)
+int dlmc_dump_plocks(char *name, char *buf, int *data)
 {
-	return do_dump(DLMC_CMD_DUMP_PLOCKS, name, buf);
+	return do_dump(DLMC_CMD_DUMP_PLOCKS, name, buf, data);
 }
 
-int dlmc_dump_run(char *buf)
+int dlmc_dump_run(char *buf, int *data)
 {
-	return do_dump(DLMC_CMD_DUMP_RUN, NULL, buf);
+	return do_dump(DLMC_CMD_DUMP_RUN, NULL, buf, data);
 }
 
 int dlmc_reload_config(void)
diff --git a/dlm_controld/libdlmcontrol.h b/dlm_controld/libdlmcontrol.h
index a8654f3e..08f04c39 100644
--- a/dlm_controld/libdlmcontrol.h
+++ b/dlm_controld/libdlmcontrol.h
@@ -80,11 +80,11 @@ struct dlmc_lockspace {
 
 #define DLMC_STATUS_VERBOSE	0x00000001
 
-int dlmc_dump_debug(char *buf);
-int dlmc_dump_config(char *buf);
-int dlmc_dump_run(char *buf);
-int dlmc_dump_log_plock(char *buf);
-int dlmc_dump_plocks(char *name, char *buf);
+int dlmc_dump_debug(char *buf, int *data);
+int dlmc_dump_config(char *buf, int *data);
+int dlmc_dump_run(char *buf, int *data);
+int dlmc_dump_log_plock(char *buf, int *data);
+int dlmc_dump_plocks(char *name, char *buf, int *data);
 int dlmc_lockspace_info(char *lsname, struct dlmc_lockspace *ls);
 int dlmc_node_info(char *lsname, int nodeid, struct dlmc_node *node);
 /* caller need to free *lss */
diff --git a/dlm_tool/main.c b/dlm_tool/main.c
index 50f0cae9..52fd5b89 100644
--- a/dlm_tool/main.c
+++ b/dlm_tool/main.c
@@ -1466,36 +1466,51 @@ static void do_fence_ack(char *name)
 	dlmc_fence_ack(name);
 }
 
-static void do_plocks(char *name)
+static int do_plocks(char *name)
 {
 	char buf[DLMC_DUMP_SIZE];
+	int rv, data;
 
 	memset(buf, 0, sizeof(buf));
 
-	dlmc_dump_plocks(name, buf);
+	rv = dlmc_dump_plocks(name, buf, &data);
+	if (rv)
+		return rv;
+	else if (data)
+		return data;
 
 	buf[DLMC_DUMP_SIZE-1] = '\0';
 
 	do_write(STDOUT_FILENO, buf, strlen(buf));
+
+	return 0;
 }
 
-static void do_dump(int op)
+static int do_dump(int op)
 {
+	int rv = -EOPNOTSUPP, data;
 	char buf[DLMC_DUMP_SIZE];
 
 	memset(buf, 0, sizeof(buf));
 
 	if (op == OP_DUMP)
-		dlmc_dump_debug(buf);
+		rv = dlmc_dump_debug(buf, &data);
 	else if (op == OP_DUMP_CONFIG)
-		dlmc_dump_config(buf);
+		rv = dlmc_dump_config(buf, &data);
 	else if (op == OP_DUMP_RUN)
-		dlmc_dump_run(buf);
+		rv = dlmc_dump_run(buf, &data);
+
+	if (rv)
+		return rv;
+	else if (data)
+		return data;
 
 	buf[DLMC_DUMP_SIZE-1] = '\0';
 
 	do_write(STDOUT_FILENO, buf, strlen(buf));
 	printf("\n");
+
+	return 0;
 }
 
 static void do_reload_config(void)
@@ -1514,18 +1529,25 @@ static void do_set_config(void)
 		printf("set_config done\n");
 }
 
-static void do_log_plock(void)
+static int do_log_plock(void)
 {
 	char buf[DLMC_DUMP_SIZE];
+	int rv, data;
 
 	memset(buf, 0, sizeof(buf));
 
-	dlmc_dump_log_plock(buf);
+	rv = dlmc_dump_log_plock(buf, &data);
+	if (rv)
+		return rv;
+	else if (data)
+		return data;
 
 	buf[DLMC_DUMP_SIZE-1] = '\0';
 
 	do_write(STDOUT_FILENO, buf, strlen(buf));
 	printf("\n");
+
+	return 0;
 }
 
 static int do_run(int op)
@@ -1576,6 +1598,7 @@ int main(int argc, char **argv)
 {
 	prog_name = argv[0];
 	decode_arguments(argc, argv);
+	int rv = 0;
 
 	switch (operation) {
 
@@ -1605,11 +1628,11 @@ int main(int argc, char **argv)
 		break;
 
 	case OP_DUMP:
-		do_dump(operation);
+		rv = do_dump(operation);
 		break;
 
 	case OP_DUMP_CONFIG:
-		do_dump(operation);
+		rv = do_dump(operation);
 		break;
 
 	case OP_RELOAD_CONFIG:
@@ -1621,11 +1644,11 @@ int main(int argc, char **argv)
 		break;
 
 	case OP_LOG_PLOCK:
-		do_log_plock();
+		rv = do_log_plock();
 		break;
 
 	case OP_PLOCKS:
-		do_plocks(lsname);
+		rv = do_plocks(lsname);
 		break;
 
 	case OP_DEADLOCK_CHECK:
@@ -1654,9 +1677,15 @@ int main(int argc, char **argv)
 		break;
 
 	case OP_DUMP_RUN:
-		do_dump(operation);
+		rv = do_dump(operation);
 		break;
 	}
-	return 0;
+
+	if (rv < 0) {
+		fprintf(stderr, "failed: %s\n", strerror(-rv));
+		return EXIT_FAILURE;
+	}
+
+	return EXIT_SUCCESS;
 }
 
-- 
2.31.1

[Cluster-devel] [PATCH dlm-tool 2/8] dlm_controld: always create logdir

[Alexander Aring]

Currently the logdir will be created only if logfile does contain a
string. To add another logfiles we simple create the logdir always on
startup.
---
 dlm_controld/logging.c | 34 +++++++++++++++++-----------------
 1 file changed, 17 insertions(+), 17 deletions(-)

diff --git a/dlm_controld/logging.c b/dlm_controld/logging.c
index 2c57138c..3298ef99 100644
--- a/dlm_controld/logging.c
+++ b/dlm_controld/logging.c
@@ -38,27 +38,27 @@ void init_logging(void)
 
 	set_logfile_priority();
 
-	if (logfile[0]) {
-		old_umask = umask(0077);
-		rv = mkdir(SYS_VARDIR, 0700);
-		if (rv < 0 && errno != EEXIST) {
-			umask(old_umask);
-			goto skip_logfile;
-		}
+	old_umask = umask(0077);
+	rv = mkdir(SYS_VARDIR, 0700);
+	if (rv < 0 && errno != EEXIST) {
+		umask(old_umask);
+		goto skip_logfile;
+	}
 
-		rv = mkdir(SYS_LOGDIR, 0700);
-		if (rv < 0 && errno != EEXIST) {
-			umask(old_umask);
-			goto skip_logfile;
-		}
+	rv = mkdir(SYS_LOGDIR, 0700);
+	if (rv < 0 && errno != EEXIST) {
+		umask(old_umask);
+		goto skip_logfile;
+	}
 
-		rv = mkdir(LOGDIR, 0700);
-		if (rv < 0 && errno != EEXIST) {
-			umask(old_umask);
-			goto skip_logfile;
-		}
+	rv = mkdir(LOGDIR, 0700);
+	if (rv < 0 && errno != EEXIST) {
 		umask(old_umask);
+		goto skip_logfile;
+	}
+	umask(old_umask);
 
+	if (logfile[0]) {
 		logfile_fp = fopen(logfile, "a+");
 		if (logfile_fp != NULL) {
 			int fd = fileno(logfile_fp);
-- 
2.31.1

[Cluster-devel] [PATCH dlm-tool 3/8] dlm_controld: add plock logfile

[Alexander Aring]

The current plock logging is limited due a in-memory log buffer which
can be dumped via dlm_contol log_plock functionality. To trace plock
performance issues it's necessary to log plock activity in a bigger log
buffer such as a file. This patch will add functionality that plock
logging information will be appended into a log file.

WARNING: depending on plock activity the resulting log file can be
resulting in enormous file size. This option should be used for
debugging purpose only.
---
 dlm_controld/dlm_daemon.h |  4 ++++
 dlm_controld/logging.c    | 39 +++++++++++++++++++++++++++++++--------
 dlm_controld/main.c       |  5 +++++
 3 files changed, 40 insertions(+), 8 deletions(-)

diff --git a/dlm_controld/dlm_daemon.h b/dlm_controld/dlm_daemon.h
index f0bad90f..c74f684a 100644
--- a/dlm_controld/dlm_daemon.h
+++ b/dlm_controld/dlm_daemon.h
@@ -76,10 +76,12 @@
 
 #define RUN_FILE_NAME            "dlm_controld.pid"
 #define LOG_FILE_NAME            "dlm_controld.log"
+#define PLOCK_LOG_FILE_NAME      "plock.log"
 #define CONF_FILE_NAME           "dlm.conf"
 
 #define RUN_FILE_PATH            RUNDIR "/" RUN_FILE_NAME
 #define LOG_FILE_PATH            LOGDIR "/" LOG_FILE_NAME
+#define PLOCK_LOG_FILE_PATH      LOGDIR "/" PLOCK_LOG_FILE_NAME
 #define CONF_FILE_PATH           CONFDIR "/" CONF_FILE_NAME
 
 #define DEFAULT_LOG_MODE         LOG_MODE_OUTPUT_FILE | LOG_MODE_OUTPUT_SYSLOG
@@ -87,6 +89,7 @@
 #define DEFAULT_SYSLOG_PRIORITY  LOG_INFO
 #define DEFAULT_LOGFILE_PRIORITY LOG_INFO
 #define DEFAULT_LOGFILE          LOG_FILE_PATH
+#define DEFAULT_PLOCK_LOGFILE	 PLOCK_LOG_FILE_PATH
 
 #define DEFAULT_NETLINK_RCVBUF	(2 * 1024 * 1024)
 
@@ -110,6 +113,7 @@ enum {
         enable_fscontrol_ind,
         enable_plock_ind,
         plock_debug_ind,
+        plock_debug_logfile_ind,
         plock_rate_limit_ind,
         plock_ownership_ind,
         drop_resources_time_ind,
diff --git a/dlm_controld/logging.c b/dlm_controld/logging.c
index 3298ef99..83de2da4 100644
--- a/dlm_controld/logging.c
+++ b/dlm_controld/logging.c
@@ -12,7 +12,9 @@ static int syslog_facility;
 static int syslog_priority;
 static int logfile_priority;
 static char logfile[PATH_MAX];
+static char plock_logfile[PATH_MAX];
 static FILE *logfile_fp;
+static FILE *plock_logfile_fp;
 
 /* logfile_priority is the only one of these options that
    can be controlled from command line, environment variable
@@ -35,6 +37,7 @@ void init_logging(void)
 	syslog_priority = DEFAULT_SYSLOG_PRIORITY;
 	logfile_priority = DEFAULT_LOGFILE_PRIORITY;
 	strcpy(logfile, DEFAULT_LOGFILE);
+	strcpy(plock_logfile, DEFAULT_PLOCK_LOGFILE);
 
 	set_logfile_priority();
 
@@ -66,6 +69,15 @@ void init_logging(void)
 		}
 	}
 
+	if (dlm_options[plock_debug_logfile_ind].use_int &&
+	    plock_logfile[0]) {
+		plock_logfile_fp = fopen(plock_logfile, "a+");
+		if (plock_logfile_fp != NULL) {
+			int fd = fileno(plock_logfile_fp);
+			fcntl(fd, F_SETFD, fcntl(fd, F_GETFD, 0) | FD_CLOEXEC);
+		}
+	}
+
 skip_logfile:
 	openlog(DAEMON_NAME, LOG_CONS | LOG_PID, syslog_facility);
 }
@@ -75,6 +87,8 @@ void close_logging(void)
 	closelog();
 	if (logfile_fp)
 		fclose(logfile_fp);
+	if (plock_logfile_fp)
+		fclose(plock_logfile_fp);
 }
 
 #define NAME_ID_SIZE 32
@@ -151,6 +165,16 @@ static void log_save_str(int len, char *log_buf, unsigned int *point,
 	*wrap = w;
 }
 
+static void log_str_to_file(FILE *fp)
+{
+	time_t logtime = time(NULL);
+	char tbuf[64];
+
+	strftime(tbuf, sizeof(tbuf), "%b %d %T", localtime(&logtime));
+	fprintf(fp, "%s %s", tbuf, log_str);
+	fflush(fp);
+}
+
 void log_level(char *name_in, uint32_t level_in, const char *fmt, ...)
 {
 	va_list ap;
@@ -191,19 +215,18 @@ void log_level(char *name_in, uint32_t level_in, const char *fmt, ...)
 
 	if (level < LOG_NONE)
 		log_save_str(pos - 1, log_dump, &log_point, &log_wrap);
-	if (plock)
+	if (plock) {
 		log_save_str(pos - 1, log_dump_plock, &log_point_plock, &log_wrap_plock);
 
+		if (plock_logfile_fp)
+			log_str_to_file(plock_logfile_fp);
+	}
+
 	if (level <= syslog_priority)
 		syslog(level, "%s", log_str);
 
-	if (level <= logfile_priority && logfile_fp) {
-		time_t logtime = time(NULL);
-		char tbuf[64];
-		strftime(tbuf, sizeof(tbuf), "%b %d %T", localtime(&logtime));
-		fprintf(logfile_fp, "%s %s", tbuf, log_str);
-		fflush(logfile_fp);
-	}
+	if (level <= logfile_priority && logfile_fp)
+		log_str_to_file(logfile_fp);
 
 	if (!dlm_options[daemon_debug_ind].use_int)
 		return;
diff --git a/dlm_controld/main.c b/dlm_controld/main.c
index c9d1c5f1..8e8d4038 100644
--- a/dlm_controld/main.c
+++ b/dlm_controld/main.c
@@ -1854,6 +1854,11 @@ static void set_opt_defaults(void)
 			0, NULL, 0, 1,
 			"enable plock debugging");
 
+	set_opt_default(plock_debug_logfile_ind,
+			"plock_debug_logfile", 'O', req_arg_bool,
+			0, NULL, 0, 1,
+			"write plock debugging to log file. Note: resulting log file can take enormous space.");
+
 	set_opt_default(plock_rate_limit_ind,
 			"plock_rate_limit", 'l', req_arg_int,
 			0, NULL, 0, 1,
-- 
2.31.1

[Cluster-devel] [PATCH dlm-tool 4/8] dlm_controld: move processing of saved messages to plock level

[Alexander Aring]

Ad the loglevel is for save plock messages during corosync resource
membership upate. This patch will put the processing of saved messages
on the same loglevel.
---
 dlm_controld/plock.c | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

diff --git a/dlm_controld/plock.c b/dlm_controld/plock.c
index 692787e2..c2c80360 100644
--- a/dlm_controld/plock.c
+++ b/dlm_controld/plock.c
@@ -1612,7 +1612,7 @@ void process_saved_plocks(struct lockspace *ls)
 	struct dlm_header *hd;
 	int count = 0;
 
-	log_dlock(ls, "process_saved_plocks begin");
+	log_plock(ls, "process_saved_plocks begin");
 
 	if (list_empty(&ls->saved_messages))
 		goto out;
@@ -1643,7 +1643,7 @@ void process_saved_plocks(struct lockspace *ls)
 		count++;
 	}
  out:
-	log_dlock(ls, "process_saved_plocks %d done", count);
+	log_plock(ls, "process_saved_plocks %d done", count);
 }
 
 /* locks still marked SYNCING should not go into the ckpt; the new node
-- 
2.31.1

[Cluster-devel] [PATCH dlm-tool 5/8] dlm_controld: remove ls parameter

[Alexander Aring]

The ls parameter in write_result() is not used, so we can remove it.
---
 dlm_controld/plock.c | 13 ++++++-------
 1 file changed, 6 insertions(+), 7 deletions(-)

diff --git a/dlm_controld/plock.c b/dlm_controld/plock.c
index c2c80360..462c9212 100644
--- a/dlm_controld/plock.c
+++ b/dlm_controld/plock.c
@@ -684,8 +684,7 @@ static int add_waiter(struct lockspace *ls, struct resource *r,
 	return 0;
 }
 
-static void write_result(struct lockspace *ls, struct dlm_plock_info *in,
-			 int rv)
+static void write_result(struct dlm_plock_info *in, int rv)
 {
 	int write_rv;
 
@@ -719,7 +718,7 @@ static void do_waiters(struct lockspace *ls, struct resource *r)
 		rv = lock_internal(ls, r, in);
 
 		if (in->nodeid == our_nodeid)
-			write_result(ls, in, rv);
+			write_result(in, rv);
 
 		free(w);
 	}
@@ -744,7 +743,7 @@ static void do_lock(struct lockspace *ls, struct dlm_plock_info *in,
 
  out:
 	if (in->nodeid == our_nodeid && rv != -EINPROGRESS)
-		write_result(ls, in, rv);
+		write_result(in, rv);
 
 	do_waiters(ls, r);
 	put_resource(ls, r);
@@ -768,7 +767,7 @@ static void do_unlock(struct lockspace *ls, struct dlm_plock_info *in,
 	}
 
 	if (in->nodeid == our_nodeid)
-		write_result(ls, in, rv);
+		write_result(in, rv);
 
  skip_result:
 	do_waiters(ls, r);
@@ -787,7 +786,7 @@ static void do_get(struct lockspace *ls, struct dlm_plock_info *in,
 	else
 		rv = 0;
 
-	write_result(ls, in, rv);
+	write_result(in, rv);
 	put_resource(ls, r);
 }
 
@@ -830,7 +829,7 @@ static void __receive_plock(struct lockspace *ls, struct dlm_plock_info *in,
 		log_elock(ls, "receive_plock error from %d optype %d",
 			  from, in->optype);
 		if (from == our_nodeid)
-			write_result(ls, in, -EINVAL);
+			write_result(in, -EINVAL);
 	}
 }
 
-- 
2.31.1

[Cluster-devel] [PATCH dlm-tool 6/8] dlm_controld: log lock/pending/waiter state changes

[Alexander Aring]

This patch will trace lock state changes of the used dlm posix locks. In
combination with the plock logfile we can see state changes over time
and follow posix locks and their state.
---
 dlm_controld/dlm_daemon.h |   2 +-
 dlm_controld/logging.c    |   2 +-
 dlm_controld/plock.c      | 124 +++++++++++++++++++++++++++++---------
 3 files changed, 97 insertions(+), 31 deletions(-)

diff --git a/dlm_controld/dlm_daemon.h b/dlm_controld/dlm_daemon.h
index c74f684a..9bf3f621 100644
--- a/dlm_controld/dlm_daemon.h
+++ b/dlm_controld/dlm_daemon.h
@@ -220,7 +220,7 @@ EXTERN struct list_head run_ops;
 #define LOG_PLOCK 0x00010000
 #define LOG_NONE  0x00001111
 
-void log_level(char *name_in, uint32_t level_in, const char *fmt, ...);
+void log_level(const char *name_in, uint32_t level_in, const char *fmt, ...);
 
 #define log_error(fmt, args...) log_level(NULL, LOG_ERR, fmt, ##args)
 #define log_debug(fmt, args...) log_level(NULL, LOG_DEBUG, fmt, ##args)
diff --git a/dlm_controld/logging.c b/dlm_controld/logging.c
index 83de2da4..e71fe52c 100644
--- a/dlm_controld/logging.c
+++ b/dlm_controld/logging.c
@@ -175,7 +175,7 @@ static void log_str_to_file(FILE *fp)
 	fflush(fp);
 }
 
-void log_level(char *name_in, uint32_t level_in, const char *fmt, ...)
+void log_level(const char *name_in, uint32_t level_in, const char *fmt, ...)
 {
 	va_list ap;
 	char name[NAME_ID_SIZE + 2];
diff --git a/dlm_controld/plock.c b/dlm_controld/plock.c
index 462c9212..77c043fd 100644
--- a/dlm_controld/plock.c
+++ b/dlm_controld/plock.c
@@ -208,6 +208,62 @@ static uint64_t dt_usec(struct timeval *start, struct timeval *stop)
 	return dt;
 }
 
+static void plock_print_lock_add_state(const struct lockspace *ls,
+				       const struct lock_waiter *w,
+				       const char *state)
+{
+	log_dlock(ls, "state: add %s %llx %llx-%llx %d/%u/%llx",
+		  state,
+		  (unsigned long long)w->info.number,
+		  (unsigned long long)w->info.start,
+		  (unsigned long long)w->info.end,
+		  w->info.nodeid, w->info.pid,
+		  (unsigned long long)w->info.owner);
+}
+
+static void plock_print_lock_clear_state(const struct lockspace *ls,
+					 const struct lock_waiter *w,
+					 const char *state)
+{
+	log_dlock(ls, "state: clear %s %llx %llx-%llx %d/%u/%llx",
+		  state,
+		  (unsigned long long)w->info.number,
+		  (unsigned long long)w->info.start,
+		  (unsigned long long)w->info.end,
+		  w->info.nodeid, w->info.pid,
+		  (unsigned long long)w->info.owner);
+}
+
+#define plock_print_add_waiter(ls, w) \
+	plock_print_lock_add_state(ls, w, "waiter")
+#define plock_print_clear_waiter(ls, w) \
+	plock_print_lock_clear_state(ls, w, "waiter")
+
+#define plock_print_add_pending(ls, w) \
+	plock_print_lock_add_state(ls, w, "pending")
+#define plock_print_clear_pending(ls, w) \
+	plock_print_lock_clear_state(ls, w, "pending")
+
+static void plock_print_add_plock(const struct lockspace *ls,
+				  const struct posix_lock *plock)
+{
+	log_dlock(ls, "state: add plock NA %llx-%llx %d/%u/%llx",
+		  (unsigned long long)plock->start,
+		  (unsigned long long)plock->end,
+		  plock->nodeid, plock->pid,
+		  (unsigned long long)plock->owner);
+}
+
+static void plock_print_del_plock(const struct lockspace *ls,
+				  const struct posix_lock *plock)
+{
+	log_dlock(ls, "state: del plock NA %llx-%llx %d/%u/%llx",
+		  (unsigned long long)plock->start,
+		  (unsigned long long)plock->end,
+		  plock->nodeid, plock->pid,
+		  (unsigned long long)plock->owner);
+}
+
 static struct resource * rb_search_plock_resource(struct lockspace *ls, uint64_t number)
 {
 	struct rb_node *n = ls->plock_resources_root.rb_node;
@@ -447,8 +503,9 @@ static int is_conflict(struct resource *r, struct dlm_plock_info *in, int get)
 	return 0;
 }
 
-static int add_lock(struct resource *r, uint32_t nodeid, uint64_t owner,
-		    uint32_t pid, int ex, uint64_t start, uint64_t end)
+static int add_lock(const struct lockspace *ls, struct resource *r,
+		    uint32_t nodeid, uint64_t owner, uint32_t pid,
+		    int ex, uint64_t start, uint64_t end)
 {
 	struct posix_lock *po;
 
@@ -464,6 +521,7 @@ static int add_lock(struct resource *r, uint32_t nodeid, uint64_t owner,
 	po->pid = pid;
 	po->ex = ex;
 	list_add_tail(&po->list, &r->locks);
+	plock_print_add_plock(ls, po);
 
 	return 0;
 }
@@ -472,8 +530,8 @@ static int add_lock(struct resource *r, uint32_t nodeid, uint64_t owner,
    1. add new lock for non-overlap area of RE, orig mode
    2. convert RE to RN range and mode */
 
-static int lock_case1(struct posix_lock *po, struct resource *r,
-		      struct dlm_plock_info *in)
+static int lock_case1(const struct lockspace *ls, struct posix_lock *po,
+		      struct resource *r, struct dlm_plock_info *in)
 {
 	uint64_t start2, end2;
 	int rv;
@@ -489,7 +547,7 @@ static int lock_case1(struct posix_lock *po, struct resource *r,
 	po->end = in->end;
 	po->ex = in->ex;
 
-	rv = add_lock(r, in->nodeid, in->owner, in->pid, !in->ex, start2, end2);
+	rv = add_lock(ls, r, in->nodeid, in->owner, in->pid, !in->ex, start2, end2);
  out:
 	return rv;
 }
@@ -499,18 +557,18 @@ static int lock_case1(struct posix_lock *po, struct resource *r,
    2. add new lock for back fragment, orig mode
    3. convert RE to RN range and mode */
 			 
-static int lock_case2(struct posix_lock *po, struct resource *r,
-		      struct dlm_plock_info *in)
+static int lock_case2(const struct lockspace *ls, struct posix_lock *po,
+		      struct resource *r, struct dlm_plock_info *in)
 
 {
 	int rv;
 
-	rv = add_lock(r, in->nodeid, in->owner, in->pid,
+	rv = add_lock(ls, r, in->nodeid, in->owner, in->pid,
 		      !in->ex, po->start, in->start - 1);
 	if (rv)
 		goto out;
 
-	rv = add_lock(r, in->nodeid, in->owner, in->pid,
+	rv = add_lock(ls, r, in->nodeid, in->owner, in->pid,
 		      !in->ex, in->end + 1, po->end);
 	if (rv)
 		goto out;
@@ -522,7 +580,7 @@ static int lock_case2(struct posix_lock *po, struct resource *r,
 	return rv;
 }
 
-static int lock_internal(struct lockspace *ls, struct resource *r,
+static int lock_internal(const struct lockspace *ls, struct resource *r,
 			 struct dlm_plock_info *in)
 {
 	struct posix_lock *po, *safe;
@@ -550,18 +608,19 @@ static int lock_internal(struct lockspace *ls, struct resource *r,
 			if (po->ex == in->ex)
 				goto out;
 
-			rv = lock_case1(po, r, in);
+			rv = lock_case1(ls, po, r, in);
 			goto out;
 
 		case 2:
 			if (po->ex == in->ex)
 				goto out;
 
-			rv = lock_case2(po, r, in);
+			rv = lock_case2(ls, po, r, in);
 			goto out;
 
 		case 3:
 			list_del(&po->list);
+			plock_print_del_plock(ls, po);
 			free(po);
 			break;
 
@@ -578,14 +637,14 @@ static int lock_internal(struct lockspace *ls, struct resource *r,
 		}
 	}
 
-	rv = add_lock(r, in->nodeid, in->owner, in->pid,
+	rv = add_lock(ls, r, in->nodeid, in->owner, in->pid,
 		      in->ex, in->start, in->end);
  out:
 	return rv;
 
 }
 
-static int unlock_internal(struct lockspace *ls, struct resource *r,
+static int unlock_internal(const struct lockspace *ls, struct resource *r,
 			   struct dlm_plock_info *in)
 {
 	struct posix_lock *po, *safe;
@@ -605,6 +664,7 @@ static int unlock_internal(struct lockspace *ls, struct resource *r,
 			/* ranges the same - just remove the existing lock */
 
 			list_del(&po->list);
+			plock_print_del_plock(ls, po);
 			free(po);
 			goto out;
 
@@ -619,7 +679,7 @@ static int unlock_internal(struct lockspace *ls, struct resource *r,
 			/* RN within RE - shrink and update RE to be front
 			 * fragment, and add a new lock for back fragment */
 
-			rv = add_lock(r, in->nodeid, in->owner, in->pid,
+			rv = add_lock(ls, r, in->nodeid, in->owner, in->pid,
 				      po->ex, in->end + 1, po->end);
 			po->end = in->start - 1;
 			goto out;
@@ -629,6 +689,7 @@ static int unlock_internal(struct lockspace *ls, struct resource *r,
 			 * because RN could cover other locks */
 
 			list_del(&po->list);
+			plock_print_del_plock(ls, po);
 			free(po);
 			continue;
 
@@ -649,7 +710,7 @@ static int unlock_internal(struct lockspace *ls, struct resource *r,
 	return rv;
 }
 
-static void clear_waiters(struct lockspace *ls, struct resource *r,
+static void clear_waiters(const struct lockspace *ls, struct resource *r,
 			  struct dlm_plock_info *in)
 {
 	struct lock_waiter *w, *safe;
@@ -659,18 +720,12 @@ static void clear_waiters(struct lockspace *ls, struct resource *r,
 			continue;
 
 		list_del(&w->list);
-
-		log_dlock(ls, "clear waiter %llx %llx-%llx %d/%u/%llx",
-			  (unsigned long long)in->number,
-			  (unsigned long long)in->start,
-			  (unsigned long long)in->end,
-			  in->nodeid, in->pid,
-			  (unsigned long long)in->owner);
+		plock_print_clear_waiter(ls, w);
 		free(w);
 	}
 }
 
-static int add_waiter(struct lockspace *ls, struct resource *r,
+static int add_waiter(const struct lockspace *ls, struct resource *r,
 		      struct dlm_plock_info *in)
 
 {
@@ -681,6 +736,7 @@ static int add_waiter(struct lockspace *ls, struct resource *r,
 		return -ENOMEM;
 	memcpy(&w->info, in, sizeof(struct dlm_plock_info));
 	list_add_tail(&w->list, &r->waiters);
+	plock_print_add_waiter(ls, w);
 	return 0;
 }
 
@@ -695,7 +751,7 @@ static void write_result(struct dlm_plock_info *in, int rv)
 			  errno, plock_device_fd);
 }
 
-static void do_waiters(struct lockspace *ls, struct resource *r)
+static void do_waiters(const struct lockspace *ls, struct resource *r)
 {
 	struct lock_waiter *w, *safe;
 	struct dlm_plock_info *in;
@@ -708,6 +764,7 @@ static void do_waiters(struct lockspace *ls, struct resource *r)
 			continue;
 
 		list_del(&w->list);
+		plock_print_clear_waiter(ls, w);
 
 		/*
 		log_group(ls, "take waiter %llx %llx-%llx %d/%u/%llx",
@@ -1096,6 +1153,7 @@ static void save_pending_plock(struct lockspace *ls, struct resource *r,
 	}
 	memcpy(&w->info, in, sizeof(struct dlm_plock_info));
 	list_add_tail(&w->list, &r->pending);
+	plock_print_add_pending(ls, w);
 }
 
 /* plock ops are on pending list waiting for ownership to be established.
@@ -1108,6 +1166,7 @@ static void add_pending_plocks(struct lockspace *ls, struct resource *r)
 	list_for_each_entry_safe(w, safe, &r->pending, list) {
 		__receive_plock(ls, &w->info, our_nodeid, r);
 		list_del(&w->list);
+		plock_print_clear_pending(ls, w);
 		free(w);
 	}
 }
@@ -1122,6 +1181,7 @@ static void send_pending_plocks(struct lockspace *ls, struct resource *r)
 	list_for_each_entry_safe(w, safe, &r->pending, list) {
 		send_plock(ls, r, &w->info);
 		list_del(&w->list);
+		plock_print_clear_pending(ls, w);
 		free(w);
 	}
 }
@@ -1331,7 +1391,7 @@ static void _receive_sync(struct lockspace *ls, struct dlm_header *hd, int len)
 	}
 
 	if (hd->type == DLM_MSG_PLOCK_SYNC_LOCK)
-		add_lock(r, info.nodeid, info.owner, info.pid, info.ex, 
+		add_lock(ls, r, info.nodeid, info.owner, info.pid, info.ex,
 			 info.start, info.end);
 	else if (hd->type == DLM_MSG_PLOCK_SYNC_WAITER)
 		add_waiter(ls, r, &info);
@@ -1836,18 +1896,20 @@ void send_all_plocks_data(struct lockspace *ls, uint32_t seq, uint32_t *plocks_d
 		  our_nodeid, seq, send_count);
 }
 
-static void free_r_lists(struct resource *r)
+static void free_r_lists(const struct lockspace *ls, struct resource *r)
 {
 	struct posix_lock *po, *po2;
 	struct lock_waiter *w, *w2;
 
 	list_for_each_entry_safe(po, po2, &r->locks, list) {
 		list_del(&po->list);
+		plock_print_del_plock(ls, po);
 		free(po);
 	}
 
 	list_for_each_entry_safe(w, w2, &r->waiters, list) {
 		list_del(&w->list);
+		plock_print_clear_waiter(ls, w);
 		free(w);
 	}
 }
@@ -1957,6 +2019,7 @@ void receive_plocks_data(struct lockspace *ls, struct dlm_header *hd, int len)
 			po->nodeid	= le32_to_cpu(pp->nodeid);
 			po->ex		= pp->ex;
 			list_add_tail(&po->list, &r->locks);
+			plock_print_add_plock(ls, po);
 		} else {
 			w = malloc(sizeof(struct lock_waiter));
 			if (!w)
@@ -1968,6 +2031,7 @@ void receive_plocks_data(struct lockspace *ls, struct dlm_header *hd, int len)
 			w->info.nodeid	= le32_to_cpu(pp->nodeid);
 			w->info.ex	= pp->ex;
 			list_add_tail(&w->list, &r->waiters);
+			plock_print_add_waiter(ls, w);
 		}
 		pp++;
 	}
@@ -1984,7 +2048,7 @@ void receive_plocks_data(struct lockspace *ls, struct dlm_header *hd, int len)
 
  fail_free:
 	if (!(flags & RD_CONTINUE)) {
-		free_r_lists(r);
+		free_r_lists(ls, r);
 		free(r);
 	}
 	return;
@@ -1999,7 +2063,7 @@ void clear_plocks_data(struct lockspace *ls)
 		return;
 
 	list_for_each_entry_safe(r, r2, &ls->plock_resources, list) {
-		free_r_lists(r);
+		free_r_lists(ls, r);
 		rb_del_plock_resource(ls, r);
 		list_del(&r->list);
 		free(r);
@@ -2030,6 +2094,7 @@ void purge_plocks(struct lockspace *ls, int nodeid, int unmount)
 		list_for_each_entry_safe(po, po2, &r->locks, list) {
 			if (po->nodeid == nodeid || unmount) {
 				list_del(&po->list);
+				plock_print_del_plock(ls, po);
 				free(po);
 				purged++;
 			}
@@ -2038,6 +2103,7 @@ void purge_plocks(struct lockspace *ls, int nodeid, int unmount)
 		list_for_each_entry_safe(w, w2, &r->waiters, list) {
 			if (w->info.nodeid == nodeid || unmount) {
 				list_del(&w->list);
+				plock_print_clear_waiter(ls, w);
 				free(w);
 				purged++;
 			}
-- 
2.31.1

[Cluster-devel] [PATCH dlm-tool 7/8] dlm_controld: constify timeval of dt_usec()

[Alexander Aring]

Those parameters are only used read only. We don't change any data where
those pointers point to.
---
 dlm_controld/plock.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/dlm_controld/plock.c b/dlm_controld/plock.c
index 77c043fd..d83a79d2 100644
--- a/dlm_controld/plock.c
+++ b/dlm_controld/plock.c
@@ -198,7 +198,7 @@ static unsigned long time_diff_ms(struct timeval *begin, struct timeval *end)
 	return (result.tv_sec * 1000) + (result.tv_usec / 1000);
 }
 
-static uint64_t dt_usec(struct timeval *start, struct timeval *stop)
+static uint64_t dt_usec(const struct timeval *start, const struct timeval *stop)
 {
 	uint64_t dt;
 
-- 
2.31.1

[Cluster-devel] [PATCH dlm-tool 8/8] dlm_controld: add time diff for state time intervals

[Alexander Aring]

This patch adds functionality to see how long a posix lock is alive or
is in waiting or pending state. It can be used to filter out interesting
locks which are stuck in e.g. waiting state to know that a user space
process probably has contention on it. The logging information will
printout additional lock information to do more search and find to get
more information about it's corosync or kernel communication.
---
 dlm_controld/plock.c | 48 ++++++++++++++++++++++++++++++--------------
 1 file changed, 33 insertions(+), 15 deletions(-)

diff --git a/dlm_controld/plock.c b/dlm_controld/plock.c
index d83a79d2..20c2a1e9 100644
--- a/dlm_controld/plock.c
+++ b/dlm_controld/plock.c
@@ -72,6 +72,7 @@ struct resource {
 
 struct posix_lock {
 	struct list_head	list;	   /* resource locks or waiters list */
+	struct timeval		list_time;
 	uint32_t		pid;
 	uint64_t		owner;
 	uint64_t		start;
@@ -83,6 +84,7 @@ struct posix_lock {
 
 struct lock_waiter {
 	struct list_head	list;
+	struct timeval		list_time;
 	uint32_t		flags;
 	struct dlm_plock_info	info;
 };
@@ -209,9 +211,11 @@ static uint64_t dt_usec(const struct timeval *start, const struct timeval *stop)
 }
 
 static void plock_print_lock_add_state(const struct lockspace *ls,
-				       const struct lock_waiter *w,
+				       struct lock_waiter *w,
 				       const char *state)
 {
+	gettimeofday(&w->list_time, NULL);
+
 	log_dlock(ls, "state: add %s %llx %llx-%llx %d/%u/%llx",
 		  state,
 		  (unsigned long long)w->info.number,
@@ -225,13 +229,20 @@ static void plock_print_lock_clear_state(const struct lockspace *ls,
 					 const struct lock_waiter *w,
 					 const char *state)
 {
-	log_dlock(ls, "state: clear %s %llx %llx-%llx %d/%u/%llx",
+	struct timeval now;
+	uint64_t usec;
+
+	gettimeofday(&now, NULL);
+	usec = dt_usec(&w->list_time, &now);
+
+	log_dlock(ls, "state: clear %s %llx %llx-%llx %d/%u/%llx %.3f",
 		  state,
 		  (unsigned long long)w->info.number,
 		  (unsigned long long)w->info.start,
 		  (unsigned long long)w->info.end,
 		  w->info.nodeid, w->info.pid,
-		  (unsigned long long)w->info.owner);
+		  (unsigned long long)w->info.owner,
+		  usec * 1.e-6);
 }
 
 #define plock_print_add_waiter(ls, w) \
@@ -245,23 +256,30 @@ static void plock_print_lock_clear_state(const struct lockspace *ls,
 	plock_print_lock_clear_state(ls, w, "pending")
 
 static void plock_print_add_plock(const struct lockspace *ls,
-				  const struct posix_lock *plock)
+				  struct posix_lock *po)
 {
-	log_dlock(ls, "state: add plock NA %llx-%llx %d/%u/%llx",
-		  (unsigned long long)plock->start,
-		  (unsigned long long)plock->end,
-		  plock->nodeid, plock->pid,
-		  (unsigned long long)plock->owner);
+	gettimeofday(&po->list_time, NULL);
+	log_dlock(ls, "state: add plock %llx-%llx %d/%u/%llx %.3f",
+		  (unsigned long long)po->start,
+		  (unsigned long long)po->end,
+		  po->nodeid, po->pid,
+		  (unsigned long long)po->owner);
 }
 
 static void plock_print_del_plock(const struct lockspace *ls,
-				  const struct posix_lock *plock)
+				  const struct posix_lock *po)
 {
-	log_dlock(ls, "state: del plock NA %llx-%llx %d/%u/%llx",
-		  (unsigned long long)plock->start,
-		  (unsigned long long)plock->end,
-		  plock->nodeid, plock->pid,
-		  (unsigned long long)plock->owner);
+	struct timeval now;
+	uint64_t usec;
+
+	gettimeofday(&now, NULL);
+	usec = dt_usec(&po->list_time, &now);
+	log_dlock(ls, "state: clear plock %llx-%llx %d/%u/%llx %.3f",
+		  (unsigned long long)po->start,
+		  (unsigned long long)po->end,
+		  po->nodeid, po->pid,
+		  (unsigned long long)po->owner,
+		  usec * 1.e-6);
 }
 
 static struct resource * rb_search_plock_resource(struct lockspace *ls, uint64_t number)
-- 
2.31.1

[Cluster-devel] [PATCH dlm-tool 8/8] dlm_controld: add time diff for state time intervals

[Alexander Aring]

Hi,

On Mon, Jan 30, 2023 at 2:24 PM Alexander Aring <aahringo@redhat.com> wrote:
>
> This patch adds functionality to see how long a posix lock is alive or
> is in waiting or pending state. It can be used to filter out interesting
> locks which are stuck in e.g. waiting state to know that a user space
> process probably has contention on it. The logging information will
> printout additional lock information to do more search and find to get
> more information about it's corosync or kernel communication.
> ---
>  dlm_controld/plock.c | 48 ++++++++++++++++++++++++++++++--------------
>  1 file changed, 33 insertions(+), 15 deletions(-)
>
> diff --git a/dlm_controld/plock.c b/dlm_controld/plock.c
> index d83a79d2..20c2a1e9 100644
> --- a/dlm_controld/plock.c
> +++ b/dlm_controld/plock.c
> @@ -72,6 +72,7 @@ struct resource {
>
>  struct posix_lock {
>         struct list_head        list;      /* resource locks or waiters list */
> +       struct timeval          list_time;
>         uint32_t                pid;
>         uint64_t                owner;
>         uint64_t                start;
> @@ -83,6 +84,7 @@ struct posix_lock {
>
>  struct lock_waiter {
>         struct list_head        list;
> +       struct timeval          list_time;
>         uint32_t                flags;
>         struct dlm_plock_info   info;
>  };
> @@ -209,9 +211,11 @@ static uint64_t dt_usec(const struct timeval *start, const struct timeval *stop)
>  }
>
>  static void plock_print_lock_add_state(const struct lockspace *ls,
> -                                      const struct lock_waiter *w,
> +                                      struct lock_waiter *w,
>                                        const char *state)
>  {
> +       gettimeofday(&w->list_time, NULL);
> +
>         log_dlock(ls, "state: add %s %llx %llx-%llx %d/%u/%llx",
>                   state,
>                   (unsigned long long)w->info.number,
> @@ -225,13 +229,20 @@ static void plock_print_lock_clear_state(const struct lockspace *ls,
>                                          const struct lock_waiter *w,
>                                          const char *state)
>  {
> -       log_dlock(ls, "state: clear %s %llx %llx-%llx %d/%u/%llx",
> +       struct timeval now;
> +       uint64_t usec;
> +
> +       gettimeofday(&now, NULL);
> +       usec = dt_usec(&w->list_time, &now);
> +
> +       log_dlock(ls, "state: clear %s %llx %llx-%llx %d/%u/%llx %.3f",
>                   state,
>                   (unsigned long long)w->info.number,
>                   (unsigned long long)w->info.start,
>                   (unsigned long long)w->info.end,
>                   w->info.nodeid, w->info.pid,
> -                 (unsigned long long)w->info.owner);
> +                 (unsigned long long)w->info.owner,
> +                 usec * 1.e-6);
>  }
>
>  #define plock_print_add_waiter(ls, w) \
> @@ -245,23 +256,30 @@ static void plock_print_lock_clear_state(const struct lockspace *ls,
>         plock_print_lock_clear_state(ls, w, "pending")
>
>  static void plock_print_add_plock(const struct lockspace *ls,
> -                                 const struct posix_lock *plock)
> +                                 struct posix_lock *po)
>  {
> -       log_dlock(ls, "state: add plock NA %llx-%llx %d/%u/%llx",
> -                 (unsigned long long)plock->start,
> -                 (unsigned long long)plock->end,
> -                 plock->nodeid, plock->pid,
> -                 (unsigned long long)plock->owner);
> +       gettimeofday(&po->list_time, NULL);
> +       log_dlock(ls, "state: add plock %llx-%llx %d/%u/%llx %.3f",

removed "%.3f" for plock_print_add_plock(), it's only necessary for
clear. We probably need to add some format(printf, 2, 3) gcc attribute
to see such mistakes...

- Alex

[Cluster-devel] [PATCH dlm-tool 6/8] dlm_controld: log lock/pending/waiter state changes

[Alexander Aring]

Hi,

On Mon, Jan 30, 2023 at 2:24 PM Alexander Aring <aahringo@redhat.com> wrote:
>
> This patch will trace lock state changes of the used dlm posix locks. In
> combination with the plock logfile we can see state changes over time
> and follow posix locks and their state.
> ---
>  dlm_controld/dlm_daemon.h |   2 +-
>  dlm_controld/logging.c    |   2 +-
>  dlm_controld/plock.c      | 124 +++++++++++++++++++++++++++++---------
>  3 files changed, 97 insertions(+), 31 deletions(-)
>
> diff --git a/dlm_controld/dlm_daemon.h b/dlm_controld/dlm_daemon.h
> index c74f684a..9bf3f621 100644
> --- a/dlm_controld/dlm_daemon.h
> +++ b/dlm_controld/dlm_daemon.h
> @@ -220,7 +220,7 @@ EXTERN struct list_head run_ops;
>  #define LOG_PLOCK 0x00010000
>  #define LOG_NONE  0x00001111
>
> -void log_level(char *name_in, uint32_t level_in, const char *fmt, ...);
> +void log_level(const char *name_in, uint32_t level_in, const char *fmt, ...);
>
>  #define log_error(fmt, args...) log_level(NULL, LOG_ERR, fmt, ##args)
>  #define log_debug(fmt, args...) log_level(NULL, LOG_DEBUG, fmt, ##args)
> diff --git a/dlm_controld/logging.c b/dlm_controld/logging.c
> index 83de2da4..e71fe52c 100644
> --- a/dlm_controld/logging.c
> +++ b/dlm_controld/logging.c
> @@ -175,7 +175,7 @@ static void log_str_to_file(FILE *fp)
>         fflush(fp);
>  }
>
> -void log_level(char *name_in, uint32_t level_in, const char *fmt, ...)
> +void log_level(const char *name_in, uint32_t level_in, const char *fmt, ...)
>  {
>         va_list ap;
>         char name[NAME_ID_SIZE + 2];
> diff --git a/dlm_controld/plock.c b/dlm_controld/plock.c
> index 462c9212..77c043fd 100644
> --- a/dlm_controld/plock.c
> +++ b/dlm_controld/plock.c
> @@ -208,6 +208,62 @@ static uint64_t dt_usec(struct timeval *start, struct timeval *stop)
>         return dt;
>  }
>
> +static void plock_print_lock_add_state(const struct lockspace *ls,
> +                                      const struct lock_waiter *w,
> +                                      const char *state)
> +{
> +       log_dlock(ls, "state: add %s %llx %llx-%llx %d/%u/%llx",
> +                 state,
> +                 (unsigned long long)w->info.number,
> +                 (unsigned long long)w->info.start,
> +                 (unsigned long long)w->info.end,
> +                 w->info.nodeid, w->info.pid,
> +                 (unsigned long long)w->info.owner);
> +}
> +
> +static void plock_print_lock_clear_state(const struct lockspace *ls,
> +                                        const struct lock_waiter *w,
> +                                        const char *state)
> +{
> +       log_dlock(ls, "state: clear %s %llx %llx-%llx %d/%u/%llx",
> +                 state,
> +                 (unsigned long long)w->info.number,
> +                 (unsigned long long)w->info.start,
> +                 (unsigned long long)w->info.end,
> +                 w->info.nodeid, w->info.pid,
> +                 (unsigned long long)w->info.owner);
> +}
> +
> +#define plock_print_add_waiter(ls, w) \
> +       plock_print_lock_add_state(ls, w, "waiter")
> +#define plock_print_clear_waiter(ls, w) \
> +       plock_print_lock_clear_state(ls, w, "waiter")
> +
> +#define plock_print_add_pending(ls, w) \
> +       plock_print_lock_add_state(ls, w, "pending")
> +#define plock_print_clear_pending(ls, w) \
> +       plock_print_lock_clear_state(ls, w, "pending")
> +
> +static void plock_print_add_plock(const struct lockspace *ls,
> +                                 const struct posix_lock *plock)

changes *plock to *po, because it's commonly used as *po in other
parts of the code for a struct posix_lock...

> +{
> +       log_dlock(ls, "state: add plock NA %llx-%llx %d/%u/%llx",

removed this NA stuff, there is one attribute which plock doesn't have
but waiter has and I did this as placeholder... it's removed in 8/8 so
I drop to add it.

> +                 (unsigned long long)plock->start,
> +                 (unsigned long long)plock->end,
> +                 plock->nodeid, plock->pid,
> +                 (unsigned long long)plock->owner);
> +}
> +
> +static void plock_print_del_plock(const struct lockspace *ls,
> +                                 const struct posix_lock *plock)
> +{
> +       log_dlock(ls, "state: del plock NA %llx-%llx %d/%u/%llx",
> +                 (unsigned long long)plock->start,
> +                 (unsigned long long)plock->end,
> +                 plock->nodeid, plock->pid,
> +                 (unsigned long long)plock->owner);
> +}

same here.

- Alex