[SCM] Samba Shared Repository - branch master updated

Martin Schwenke martins at samba.org
Mon Jun 19 17:57:02 UTC 2017


The branch, master has been updated
       via  ac4b788 ctdb-locking: If a record could not be locked, log the key
       via  1548ab9 ctdb-locking: Reduce logging in case of contention
       via  5304b70 ctdb-locking: There are no ALLDB locks any more
       via  9005e95 ctdb-client: Add correct control names to log messages
       via  7b558f8 ctdb-tests: Fix function names in protocol test
      from  8e43af0 s3: VFS: Change SMB_VFS_SYMLINK to use const struct smb_filename * instead of const char *.

https://git.samba.org/?p=samba.git;a=shortlog;h=master


- Log -----------------------------------------------------------------
commit ac4b78848db1dac7e0316653d2cafe3a32990e06
Author: Amitay Isaacs <amitay at gmail.com>
Date:   Tue Jun 13 15:32:36 2017 +1000

    ctdb-locking: If a record could not be locked, log the key
    
    Signed-off-by: Amitay Isaacs <amitay at gmail.com>
    Reviewed-by: Martin Schwenke <martin at meltin.net>
    
    Autobuild-User(master): Martin Schwenke <martins at samba.org>
    Autobuild-Date(master): Mon Jun 19 19:56:22 CEST 2017 on sn-devel-144

commit 1548ab99a2ae61315cf38ff982156bb3b9e61ca2
Author: Amitay Isaacs <amitay at gmail.com>
Date:   Wed Jun 7 16:44:24 2017 +1000

    ctdb-locking: Reduce logging in case of contention
    
    Currently, every lock helper will log a message if it cannot get a lock.
    This can spam the logs and overwhelm syslog if there are hundreds of
    lock helpers waiting for contended record.
    
    Instead keep track of the record for which we have already logged once
    with specific timeout interval.  If we get timeout interval larger than
    the previously logged interval, then log again once.  This will reduce
    the amount of logs for contended records to a single log entry per 10
    seconds per record.
    
    Signed-off-by: Amitay Isaacs <amitay at gmail.com>
    Reviewed-by: Martin Schwenke <martin at meltin.net>

commit 5304b7023df755a23a516a10a1c94f28f1446813
Author: Amitay Isaacs <amitay at gmail.com>
Date:   Wed Jun 7 16:45:50 2017 +1000

    ctdb-locking: There are no ALLDB locks any more
    
    Signed-off-by: Amitay Isaacs <amitay at gmail.com>
    Reviewed-by: Martin Schwenke <martin at meltin.net>

commit 9005e95f8c65fe685196a69897a02f8bd72ac67d
Author: Amitay Isaacs <amitay at gmail.com>
Date:   Wed Jun 14 16:35:50 2017 +1000

    ctdb-client: Add correct control names to log messages
    
    Signed-off-by: Amitay Isaacs <amitay at gmail.com>
    Reviewed-by: Martin Schwenke <martin at meltin.net>

commit 7b558f8b6527bd20ddd12c385027cd318316f162
Author: Amitay Isaacs <amitay at gmail.com>
Date:   Thu Apr 6 16:51:57 2017 +1000

    ctdb-tests: Fix function names in protocol test
    
    Signed-off-by: Amitay Isaacs <amitay at gmail.com>
    Reviewed-by: Martin Schwenke <martin at meltin.net>

-----------------------------------------------------------------------

Summary of changes:
 ctdb/client/client_control_sync.c     |   8 +-
 ctdb/include/ctdb_private.h           |   3 +
 ctdb/server/ctdb_lock.c               | 174 +++++++++++++++++++++++++++++-----
 ctdb/server/ctdb_ltdb_server.c        |  10 ++
 ctdb/tests/src/protocol_client_test.c |  56 +++++------
 5 files changed, 193 insertions(+), 58 deletions(-)


Changeset truncated at 500 lines:

diff --git a/ctdb/client/client_control_sync.c b/ctdb/client/client_control_sync.c
index 45d475e..3b44c2f 100644
--- a/ctdb/client/client_control_sync.c
+++ b/ctdb/client/client_control_sync.c
@@ -2658,7 +2658,7 @@ int ctdb_ctrl_db_push_start(TALLOC_CTX *mem_ctx, struct tevent_context *ev,
 				  &request, &reply);
 	if (ret != 0) {
 		DEBUG(DEBUG_ERR,
-		      ("Control DB_PUSH failed to node %u, ret=%d\n",
+		      ("Control DB_PUSH_START failed to node %u, ret=%d\n",
 		       destnode, ret));
 		return ret;
 	}
@@ -2666,7 +2666,7 @@ int ctdb_ctrl_db_push_start(TALLOC_CTX *mem_ctx, struct tevent_context *ev,
 	ret = ctdb_reply_control_db_push_start(reply);
 	if (ret != 0) {
 		DEBUG(DEBUG_ERR,
-		      ("Control DB_PUSH failed, ret=%d\n", ret));
+		      ("Control DB_PUSH_START failed, ret=%d\n", ret));
 		return ret;
 	}
 
@@ -2687,7 +2687,7 @@ int ctdb_ctrl_db_push_confirm(TALLOC_CTX *mem_ctx, struct tevent_context *ev,
 				  &request, &reply);
 	if (ret != 0) {
 		DEBUG(DEBUG_ERR,
-		      ("Control DB_PUSH failed to node %u, ret=%d\n",
+		      ("Control DB_PUSH_CONFIRM failed to node %u, ret=%d\n",
 		       destnode, ret));
 		return ret;
 	}
@@ -2695,7 +2695,7 @@ int ctdb_ctrl_db_push_confirm(TALLOC_CTX *mem_ctx, struct tevent_context *ev,
 	ret = ctdb_reply_control_db_push_confirm(reply, num_records);
 	if (ret != 0) {
 		DEBUG(DEBUG_ERR,
-		      ("Control DB_PUSH failed, ret=%d\n", ret));
+		      ("Control DB_PUSH_CONFIRM failed, ret=%d\n", ret));
 		return ret;
 	}
 
diff --git a/ctdb/include/ctdb_private.h b/ctdb/include/ctdb_private.h
index 6c7dd79..dd54f35 100644
--- a/ctdb/include/ctdb_private.h
+++ b/ctdb/include/ctdb_private.h
@@ -23,6 +23,8 @@
 #include "ctdb_client.h"
 #include <sys/socket.h>
 
+#include "common/db_hash.h"
+
 /*
   array of tcp connections
  */
@@ -376,6 +378,7 @@ struct ctdb_db_context {
 	struct lock_context *lock_current;
 	struct lock_context *lock_pending;
 	int lock_num_current;
+	struct db_hash_context *lock_log;
 
 	struct ctdb_call_state *pending_calls;
 
diff --git a/ctdb/server/ctdb_lock.c b/ctdb/server/ctdb_lock.c
index b2c6d15..2644fcd 100644
--- a/ctdb/server/ctdb_lock.c
+++ b/ctdb/server/ctdb_lock.c
@@ -381,6 +381,129 @@ static void ctdb_lock_handler(struct tevent_context *ev,
 	process_callbacks(lock_ctx, locked);
 }
 
+struct lock_log_entry {
+	struct db_hash_context *lock_log;
+	TDB_DATA key;
+	unsigned long log_sec;
+	struct tevent_timer *timer;
+};
+
+static int lock_log_fetch_parser(uint8_t *keybuf, size_t keylen,
+				 uint8_t *databuf, size_t datalen,
+				 void *private_data)
+{
+	struct lock_log_entry **entry =
+		(struct lock_log_entry **)private_data;
+
+	if (datalen != sizeof(struct lock_log_entry *)) {
+		return EINVAL;
+	}
+
+	*entry = talloc_get_type_abort(*(void **)databuf,
+				       struct lock_log_entry);
+	return 0;
+}
+
+static void lock_log_cleanup(struct tevent_context *ev,
+			     struct tevent_timer *ttimer,
+			     struct timeval current_time,
+			     void *private_data)
+{
+	struct lock_log_entry *entry = talloc_get_type_abort(
+		private_data, struct lock_log_entry);
+	int ret;
+
+	entry->timer = NULL;
+
+	ret = db_hash_delete(entry->lock_log, entry->key.dptr,
+			     entry->key.dsize);
+	if (ret != 0) {
+		return;
+	}
+	talloc_free(entry);
+}
+
+static bool lock_log_skip(struct tevent_context *ev,
+			  struct db_hash_context *lock_log,
+			  TDB_DATA key, unsigned long elapsed_sec)
+{
+	struct lock_log_entry *entry = NULL;
+	int ret;
+
+	ret = db_hash_fetch(lock_log, key.dptr, key.dsize,
+			    lock_log_fetch_parser, &entry);
+	if (ret == ENOENT) {
+
+		entry = talloc_zero(lock_log, struct lock_log_entry);
+		if (entry == NULL) {
+			goto fail;
+		}
+
+		entry->lock_log = lock_log;
+
+		entry->key.dptr = talloc_memdup(entry, key.dptr, key.dsize);
+		if (entry->key.dptr == NULL) {
+			talloc_free(entry);
+			goto fail;
+		}
+		entry->key.dsize = key.dsize;
+
+		entry->log_sec = elapsed_sec;
+		entry->timer = tevent_add_timer(ev, entry,
+						timeval_current_ofs(30, 0),
+						lock_log_cleanup, entry);
+		if (entry->timer == NULL) {
+			talloc_free(entry);
+			goto fail;
+		}
+
+		ret = db_hash_add(lock_log, key.dptr, key.dsize,
+				  (uint8_t *)&entry,
+				  sizeof(struct lock_log_entry *));
+		if (ret != 0) {
+			talloc_free(entry);
+			goto fail;
+		}
+
+		return false;
+
+	} else if (ret == EINVAL) {
+
+		ret = db_hash_delete(lock_log, key.dptr, key.dsize);
+		if (ret != 0) {
+			goto fail;
+		}
+
+		return false;
+
+	} else if (ret == 0) {
+
+		if (elapsed_sec <= entry->log_sec) {
+			return true;
+		}
+
+		entry->log_sec = elapsed_sec;
+
+		TALLOC_FREE(entry->timer);
+		entry->timer = tevent_add_timer(ev, entry,
+						timeval_current_ofs(30, 0),
+						lock_log_cleanup, entry);
+		if (entry->timer == NULL) {
+			ret = db_hash_delete(lock_log, key.dptr, key.dsize);
+			if (ret != 0) {
+				goto fail;
+			}
+			talloc_free(entry);
+		}
+
+		return false;
+	}
+
+
+fail:
+	return false;
+
+}
 
 /*
  * Callback routine when required locks are not obtained within timeout
@@ -392,41 +515,49 @@ static void ctdb_lock_timeout_handler(struct tevent_context *ev,
 				    void *private_data)
 {
 	static char debug_locks[PATH_MAX+1] = "";
-	static struct timeval last_debug_time;
 	struct lock_context *lock_ctx;
 	struct ctdb_context *ctdb;
-	struct timeval now;
 	pid_t pid;
 	double elapsed_time;
-	int new_timer;
+	bool skip;
+	char *keystr;
 
 	lock_ctx = talloc_get_type_abort(private_data, struct lock_context);
 	ctdb = lock_ctx->ctdb;
 
 	elapsed_time = timeval_elapsed(&lock_ctx->start_time);
-	if (lock_ctx->ctdb_db) {
+
+	/* For database locks, always log */
+	if (lock_ctx->type == LOCK_DB) {
 		DEBUG(DEBUG_WARNING,
-		      ("Unable to get %s lock on database %s for %.0lf seconds\n",
-		       (lock_ctx->type == LOCK_RECORD ? "RECORD" : "DB"),
+		      ("Unable to get DB lock on database %s for "
+		       "%.0lf seconds\n",
 		       lock_ctx->ctdb_db->db_name, elapsed_time));
-	} else {
-		DEBUG(DEBUG_WARNING,
-		      ("Unable to get ALLDB locks for %.0lf seconds\n",
-		       elapsed_time));
+		goto lock_debug;
 	}
 
-	/* If a node stopped/banned, don't spam the logs */
-	if (ctdb->nodes[ctdb->pnn]->flags & NODE_FLAGS_INACTIVE) {
+	/* For record locks, check if we have already logged */
+	skip = lock_log_skip(ev, lock_ctx->ctdb_db->lock_log,
+			     lock_ctx->key, (unsigned long)elapsed_time);
+	if (skip) {
 		goto skip_lock_debug;
 	}
 
-	/* Restrict log debugging to once per second */
-	now = timeval_current();
-	if (last_debug_time.tv_sec == now.tv_sec) {
+	keystr = hex_encode_talloc(lock_ctx, lock_ctx->key.dptr,
+				   lock_ctx->key.dsize);
+	DEBUG(DEBUG_WARNING,
+	      ("Unable to get RECORD lock on database %s for %.0lf seconds"
+	       " (key %s)\n",
+	       lock_ctx->ctdb_db->db_name, elapsed_time,
+	       keystr ? keystr : ""));
+	TALLOC_FREE(keystr);
+
+	/* If a node stopped/banned, don't spam the logs */
+	if (ctdb->nodes[ctdb->pnn]->flags & NODE_FLAGS_INACTIVE) {
 		goto skip_lock_debug;
 	}
 
-	last_debug_time.tv_sec = now.tv_sec;
+lock_debug:
 
 	if (ctdb_set_helper("lock debugging helper",
 			    debug_locks, sizeof(debug_locks),
@@ -446,20 +577,11 @@ static void ctdb_lock_timeout_handler(struct tevent_context *ev,
 
 skip_lock_debug:
 
-	/* Back-off logging if lock is not obtained for a long time */
-	if (elapsed_time < 100.0) {
-		new_timer = 10;
-	} else if (elapsed_time < 1000.0) {
-		new_timer = 100;
-	} else {
-		new_timer = 1000;
-	}
-
 	/* reset the timeout timer */
 	// talloc_free(lock_ctx->ttimer);
 	lock_ctx->ttimer = tevent_add_timer(ctdb->ev,
 					    lock_ctx,
-					    timeval_current_ofs(new_timer, 0),
+					    timeval_current_ofs(10, 0),
 					    ctdb_lock_timeout_handler,
 					    (void *)lock_ctx);
 }
diff --git a/ctdb/server/ctdb_ltdb_server.c b/ctdb/server/ctdb_ltdb_server.c
index f5a65f3..66a985e 100644
--- a/ctdb/server/ctdb_ltdb_server.c
+++ b/ctdb/server/ctdb_ltdb_server.c
@@ -1034,6 +1034,16 @@ again:
 		return -1;
 	}
 
+	ret = db_hash_init(ctdb_db, "lock_log", 2048, DB_HASH_COMPLEX,
+			   &ctdb_db->lock_log);
+	if (ret != 0) {
+		DEBUG(DEBUG_ERR,
+		      ("Failed to setup lock logging for db '%s'\n",
+		       ctdb_db->db_name));
+		talloc_free(ctdb_db);
+		return -1;
+	}
+
 	ctdb_db->generation = ctdb->vnn_map->generation;
 
 	DEBUG(DEBUG_NOTICE,("Attached to database '%s' with flags 0x%x\n",
diff --git a/ctdb/tests/src/protocol_client_test.c b/ctdb/tests/src/protocol_client_test.c
index cf068f1..c530dec 100644
--- a/ctdb/tests/src/protocol_client_test.c
+++ b/ctdb/tests/src/protocol_client_test.c
@@ -1979,7 +1979,7 @@ static void test_ctdb_req_header(void)
 	talloc_free(mem_ctx);
 }
 
-static void test_req_call_test(void)
+static void test_ctdb_req_call(void)
 {
 	TALLOC_CTX *mem_ctx;
 	uint8_t *pkt;
@@ -2018,7 +2018,7 @@ static void test_req_call_test(void)
 	talloc_free(mem_ctx);
 }
 
-static void test_reply_call_test(void)
+static void test_ctdb_reply_call(void)
 {
 	TALLOC_CTX *mem_ctx;
 	uint8_t *pkt;
@@ -2057,7 +2057,7 @@ static void test_reply_call_test(void)
 	talloc_free(mem_ctx);
 }
 
-static void test_reply_error_test(void)
+static void test_ctdb_reply_error(void)
 {
 	TALLOC_CTX *mem_ctx;
 	uint8_t *pkt;
@@ -2096,7 +2096,7 @@ static void test_reply_error_test(void)
 	talloc_free(mem_ctx);
 }
 
-static void test_req_dmaster_test(void)
+static void test_ctdb_req_dmaster(void)
 {
 	TALLOC_CTX *mem_ctx;
 	uint8_t *pkt;
@@ -2135,7 +2135,7 @@ static void test_req_dmaster_test(void)
 	talloc_free(mem_ctx);
 }
 
-static void test_reply_dmaster_test(void)
+static void test_ctdb_reply_dmaster(void)
 {
 	TALLOC_CTX *mem_ctx;
 	uint8_t *pkt;
@@ -2176,7 +2176,7 @@ static void test_reply_dmaster_test(void)
 
 #define NUM_CONTROLS	149
 
-static void test_req_control_data_test(void)
+static void test_ctdb_req_control_data(void)
 {
 	TALLOC_CTX *mem_ctx;
 	size_t buflen;
@@ -2206,7 +2206,7 @@ static void test_req_control_data_test(void)
 	fflush(stdout);
 }
 
-static void test_reply_control_data_test(void)
+static void test_ctdb_reply_control_data(void)
 {
 	TALLOC_CTX *mem_ctx;
 	size_t buflen;
@@ -2236,7 +2236,7 @@ static void test_reply_control_data_test(void)
 	fflush(stdout);
 }
 
-static void test_req_control_test(void)
+static void test_ctdb_req_control(void)
 {
 	TALLOC_CTX *mem_ctx;
 	uint8_t *pkt;
@@ -2283,7 +2283,7 @@ static void test_req_control_test(void)
 	fflush(stdout);
 }
 
-static void test_reply_control_test(void)
+static void test_ctdb_reply_control(void)
 {
 	TALLOC_CTX *mem_ctx;
 	uint8_t *pkt;
@@ -2330,7 +2330,7 @@ static void test_reply_control_test(void)
 	fflush(stdout);
 }
 
-static void test_req_message_test(void)
+static void test_ctdb_req_message_data(void)
 {
 	TALLOC_CTX *mem_ctx;
 	uint8_t *pkt;
@@ -2400,7 +2400,7 @@ static void test_ctdb_event_header(void)
 
 #define NUM_COMMANDS	5
 
-static void test_event_request_data(void)
+static void test_ctdb_event_request_data(void)
 {
 	TALLOC_CTX *mem_ctx;
 	size_t buflen;
@@ -2431,7 +2431,7 @@ static void test_event_request_data(void)
 	fflush(stdout);
 }
 
-static void test_event_reply_data(void)
+static void test_ctdb_event_reply_data(void)
 {
 	TALLOC_CTX *mem_ctx;
 	size_t buflen;
@@ -2462,7 +2462,7 @@ static void test_event_reply_data(void)
 	fflush(stdout);
 }
 
-static void test_event_request(void)
+static void test_ctdb_event_request(void)
 {
 	TALLOC_CTX *mem_ctx;
 	uint8_t *buf;
@@ -2502,7 +2502,7 @@ static void test_event_request(void)
 	fflush(stdout);
 }
 
-static void test_event_reply(void)
+static void test_ctdb_event_reply(void)
 {
 	TALLOC_CTX *mem_ctx;
 	uint8_t *buf;
@@ -2551,26 +2551,26 @@ int main(int argc, char *argv[])
 
 	test_ctdb_req_header();
 
-	test_req_call_test();
-	test_reply_call_test();
-	test_reply_error_test();
-	test_req_dmaster_test();
-	test_reply_dmaster_test();
+	test_ctdb_req_call();
+	test_ctdb_reply_call();
+	test_ctdb_reply_error();
+	test_ctdb_req_dmaster();
+	test_ctdb_reply_dmaster();
 
-	test_req_control_data_test();
-	test_reply_control_data_test();
+	test_ctdb_req_control_data();
+	test_ctdb_reply_control_data();
 
-	test_req_control_test();
-	test_reply_control_test();
+	test_ctdb_req_control();
+	test_ctdb_reply_control();
 
-	test_req_message_test();
+	test_ctdb_req_message_data();
 
 	test_ctdb_event_header();
 
-	test_event_request_data();
-	test_event_reply_data();
-	test_event_request();
-	test_event_reply();
+	test_ctdb_event_request_data();
+	test_ctdb_event_reply_data();
+	test_ctdb_event_request();
+	test_ctdb_event_reply();
 
 	return 0;
 }


-- 
Samba Shared Repository



More information about the samba-cvs mailing list