changeset 19799:8dfbf0629359

lib-index: Small improvements to logging the reason for long transaction log lock waits
author Timo Sirainen <timo.sirainen@dovecot.fi>
date Mon, 22 Feb 2016 11:15:52 +0200
parents 5bf3271eb63b
children 363311913f82
files src/lib-index/mail-index-fsck.c src/lib-index/mail-index-sync.c src/lib-index/mail-transaction-log-append.c src/lib-index/mail-transaction-log-private.h src/lib-index/mail-transaction-log.c src/lib-index/mail-transaction-log.h src/lib-index/test-mail-transaction-log-append.c
diffstat 7 files changed, 24 insertions(+), 16 deletions(-) [+]
line wrap: on
line diff
--- a/src/lib-index/mail-index-fsck.c	Mon Feb 22 10:25:56 2016 +0200
+++ b/src/lib-index/mail-index-fsck.c	Mon Feb 22 11:15:52 2016 +0200
@@ -441,8 +441,8 @@
 	}
 
 	if (!orig_locked) {
-		if (mail_transaction_log_sync_lock(index->log, &file_seq,
-						   &file_offset) < 0)
+		if (mail_transaction_log_sync_lock(index->log, "fscking",
+						   &file_seq, &file_offset) < 0)
 			return -1;
 	}
 
@@ -457,7 +457,7 @@
 	mail_index_write(index, FALSE);
 
 	if (!orig_locked)
-		mail_transaction_log_sync_unlock(index->log, "fsck");
+		mail_transaction_log_sync_unlock(index->log, "fscking");
 	return 0;
 }
 
--- a/src/lib-index/mail-index-sync.c	Mon Feb 22 10:25:56 2016 +0200
+++ b/src/lib-index/mail-index-sync.c	Mon Feb 22 11:15:52 2016 +0200
@@ -328,7 +328,7 @@
 	/* if we require changes, don't lock transaction log yet. first check
 	   if there's anything to sync. */
 	if ((flags & MAIL_INDEX_SYNC_FLAG_REQUIRE_CHANGES) == 0) {
-		if (mail_transaction_log_sync_lock(index->log,
+		if (mail_transaction_log_sync_lock(index->log, "syncing",
 						   &seq, &offset) < 0)
 			return -1;
 		locked = TRUE;
--- a/src/lib-index/mail-transaction-log-append.c	Mon Feb 22 10:25:56 2016 +0200
+++ b/src/lib-index/mail-transaction-log-append.c	Mon Feb 22 11:15:52 2016 +0200
@@ -221,7 +221,7 @@
 	struct mail_transaction_boundary boundary;
 
 	if (!index->log_sync_locked) {
-		if (mail_transaction_log_lock_head(index->log) < 0)
+		if (mail_transaction_log_lock_head(index->log, "appending") < 0)
 			return -1;
 	}
 	ctx = i_new(struct mail_transaction_log_append_ctx, 1);
--- a/src/lib-index/mail-transaction-log-private.h	Mon Feb 22 10:25:56 2016 +0200
+++ b/src/lib-index/mail-transaction-log-private.h	Mon Feb 22 11:15:52 2016 +0200
@@ -136,7 +136,8 @@
 
 bool mail_transaction_log_want_rotate(struct mail_transaction_log *log);
 int mail_transaction_log_rotate(struct mail_transaction_log *log, bool reset);
-int mail_transaction_log_lock_head(struct mail_transaction_log *log);
+int mail_transaction_log_lock_head(struct mail_transaction_log *log,
+				   const char *lock_reason);
 void mail_transaction_log_file_unlock(struct mail_transaction_log_file *file,
 				      const char *lock_reason);
 
--- a/src/lib-index/mail-transaction-log.c	Mon Feb 22 10:25:56 2016 +0200
+++ b/src/lib-index/mail-transaction-log.c	Mon Feb 22 11:15:52 2016 +0200
@@ -421,7 +421,8 @@
 	return 1;
 }
 
-int mail_transaction_log_lock_head(struct mail_transaction_log *log)
+int mail_transaction_log_lock_head(struct mail_transaction_log *log,
+				   const char *lock_reason)
 {
 	struct mail_transaction_log_file *file;
 	time_t lock_wait_started, lock_secs = 0;
@@ -455,7 +456,8 @@
 		file->refcount++;
 		ret = mail_transaction_log_refresh(log, TRUE);
 		if (--file->refcount == 0) {
-			mail_transaction_log_file_unlock(file, "trying to lock head");
+			mail_transaction_log_file_unlock(file, t_strdup_printf(
+				"trying to lock head for %s", lock_reason));
 			mail_transaction_logs_clean(log);
 			file = NULL;
 		}
@@ -467,9 +469,10 @@
 			break;
 		}
 
-		if (file != NULL)
-			mail_transaction_log_file_unlock(file, "trying to lock head");
-
+		if (file != NULL) {
+			mail_transaction_log_file_unlock(file, t_strdup_printf(
+				"trying to lock head for %s", lock_reason));
+		}
 		if (ret < 0)
 			break;
 
@@ -485,17 +488,19 @@
 }
 
 int mail_transaction_log_sync_lock(struct mail_transaction_log *log,
+				   const char *lock_reason,
 				   uint32_t *file_seq_r, uoff_t *file_offset_r)
 {
 	i_assert(!log->index->log_sync_locked);
 
-	if (mail_transaction_log_lock_head(log) < 0)
+	if (mail_transaction_log_lock_head(log, lock_reason) < 0)
 		return -1;
 
 	/* update sync_offset */
 	if (mail_transaction_log_file_map(log->head, log->head->sync_offset,
 					  (uoff_t)-1) <= 0) {
-		mail_transaction_log_file_unlock(log->head, "trying to lock syncing");
+		mail_transaction_log_file_unlock(log->head, t_strdup_printf(
+			"%s - map failed", lock_reason));
 		return -1;
 	}
 
@@ -506,12 +511,12 @@
 }
 
 void mail_transaction_log_sync_unlock(struct mail_transaction_log *log,
-				      const char *log_reason)
+				      const char *lock_reason)
 {
 	i_assert(log->index->log_sync_locked);
 
 	log->index->log_sync_locked = FALSE;
-	mail_transaction_log_file_unlock(log->head, log_reason);
+	mail_transaction_log_file_unlock(log->head, lock_reason);
 }
 
 void mail_transaction_log_get_head(struct mail_transaction_log *log,
--- a/src/lib-index/mail-transaction-log.h	Mon Feb 22 10:25:56 2016 +0200
+++ b/src/lib-index/mail-transaction-log.h	Mon Feb 22 11:15:52 2016 +0200
@@ -278,6 +278,7 @@
 /* Lock transaction log for index synchronization. Log cannot be read or
    written to while it's locked. Returns end offset. */
 int mail_transaction_log_sync_lock(struct mail_transaction_log *log,
+				   const char *lock_reason,
 				   uint32_t *file_seq_r, uoff_t *file_offset_r);
 void mail_transaction_log_sync_unlock(struct mail_transaction_log *log,
 				      const char *lock_reason);
--- a/src/lib-index/test-mail-transaction-log-append.c	Mon Feb 22 10:25:56 2016 +0200
+++ b/src/lib-index/test-mail-transaction-log-append.c	Mon Feb 22 11:15:52 2016 +0200
@@ -16,7 +16,8 @@
 {
 }
 
-int mail_transaction_log_lock_head(struct mail_transaction_log *log ATTR_UNUSED)
+int mail_transaction_log_lock_head(struct mail_transaction_log *log ATTR_UNUSED,
+				   const char *lock_reason ATTR_UNUSED)
 {
 	return log_lock_failure ? -1 : 0;
 }