[PATCHES] More logging for dbwrap_ctdb
Christof Schmitt
cs at samba.org
Mon Jan 13 13:41:22 MST 2014
The attached patches add more logging to ctdb and tdb calls in
dbwrap_ctdb. This allows detecting and debugging the fcntl lock
scalability problems on tdb files.
Christof
-------------- next part --------------
>From 2cd437f9c4114bedd08db9bce3a41635f56aa916 Mon Sep 17 00:00:00 2001
From: Volker Lendecke <vl at samba.org>
Date: Fri, 1 Feb 2013 12:49:52 +0100
Subject: [PATCH 1/4] ctdb_conn: Log long fetch_lock calls
With this patch, the number of fetch_lock attempts before dbwrap_ctdb
logs that it took x attempts to get a record is configurable with
net conf setparm global ctdb:migrate_attempts 10
This patch also adds
net conf setparm global ctdb:migrate_duration 5000
to trigger the same log message if it took longer than x milliseconds
to retrieve a record.
Reviewed-by: Christof Schmitt <cs at samba.org>
---
source3/lib/dbwrap/dbwrap_ctdb.c | 26 ++++++++++++++++++++++----
1 files changed, 22 insertions(+), 4 deletions(-)
diff --git a/source3/lib/dbwrap/dbwrap_ctdb.c b/source3/lib/dbwrap/dbwrap_ctdb.c
index 5a473f9..fa2246b 100644
--- a/source3/lib/dbwrap/dbwrap_ctdb.c
+++ b/source3/lib/dbwrap/dbwrap_ctdb.c
@@ -1017,7 +1017,9 @@ static struct db_record *fetch_locked_internal(struct db_ctdb_ctx *ctx,
struct db_ctdb_rec *crec;
NTSTATUS status;
TDB_DATA ctdb_data;
- int migrate_attempts = 0;
+ int migrate_attempts;
+ struct timeval migrate_start;
+ int duration_msecs;
int lockret;
if (!(result = talloc(mem_ctx, struct db_record))) {
@@ -1044,6 +1046,9 @@ static struct db_record *fetch_locked_internal(struct db_ctdb_ctx *ctx,
return NULL;
}
+ migrate_attempts = 0;
+ GetTimeOfDay(&migrate_start);
+
/*
* Do a blocking lock on the record
*/
@@ -1110,13 +1115,26 @@ again:
goto again;
}
- if (migrate_attempts > 10) {
+ {
+ double duration;
+ duration = timeval_elapsed(&migrate_start);
+
+ /*
+ * Convert the duration to milliseconds to avoid a
+ * floating-point division of
+ * lp_parm_int("migrate_duration") by 1000.
+ */
+ duration_msecs = duration * 1000;
+ }
+
+ if ((migrate_attempts > lp_parm_int(-1, "ctdb", "migrate_attempts", 10)) ||
+ (duration_msecs > lp_parm_int(-1, "ctdb", "migrate_duration", 5000))) {
DEBUG(0, ("db_ctdb_fetch_locked for %s key %s needed %d "
- "attempts\n", tdb_name(ctx->wtdb->tdb),
+ "attempts, %d milliseconds\n", tdb_name(ctx->wtdb->tdb),
hex_encode_talloc(talloc_tos(),
(unsigned char *)key.dptr,
key.dsize),
- migrate_attempts));
+ migrate_attempts, duration_msecs));
}
GetTimeOfDay(&crec->lock_time);
--
1.7.1
>From 8d108f9c55ccf0f3d719fbf0787c0eb22c12b74b Mon Sep 17 00:00:00 2001
From: Volker Lendecke <vl at samba.org>
Date: Mon, 6 May 2013 10:56:12 +0200
Subject: [PATCH 2/4] dbwrap_ctdb: Instrument chainunlock timing
We need an indication whether we run into the fcntl thundering
herd. fcntl unlock should be blindingly fast in the normal case. If it
takes longer than 5 milliseconds, warn. The timeout can be adapted by
setting
ctdb:unlock_warn_threshold = <number-of-milliseconds>
Reviewed-by: Christof Schmitt <cs at samba.org>
---
source3/lib/dbwrap/dbwrap_ctdb.c | 28 ++++++++++++++++++++++++++--
1 files changed, 26 insertions(+), 2 deletions(-)
diff --git a/source3/lib/dbwrap/dbwrap_ctdb.c b/source3/lib/dbwrap/dbwrap_ctdb.c
index fa2246b..5e15e3f 100644
--- a/source3/lib/dbwrap/dbwrap_ctdb.c
+++ b/source3/lib/dbwrap/dbwrap_ctdb.c
@@ -944,6 +944,9 @@ static int db_ctdb_record_destr(struct db_record* data)
struct db_ctdb_rec *crec = talloc_get_type_abort(
data->private_data, struct db_ctdb_rec);
int threshold;
+ int ret;
+ struct timeval before;
+ double timediff;
DEBUG(10, (DEBUGLEVEL > 10
? "Unlocking db %u key %s\n"
@@ -952,11 +955,32 @@ static int db_ctdb_record_destr(struct db_record* data)
hex_encode_talloc(data, (unsigned char *)data->key.dptr,
data->key.dsize)));
- tdb_chainunlock(crec->ctdb_ctx->wtdb->tdb, data->key);
+ before = timeval_current();
+
+ ret = tdb_chainunlock(crec->ctdb_ctx->wtdb->tdb, data->key);
+
+ timediff = timeval_elapsed(&before);
+ timediff *= 1000; /* get us milliseconds */
+
+ if (timediff > lp_parm_int(-1, "ctdb", "unlock_warn_threshold", 5)) {
+ char *key;
+ key = hex_encode_talloc(talloc_tos(),
+ (unsigned char *)data->key.dptr,
+ data->key.dsize);
+ DEBUG(0, ("tdb_chainunlock on db %s, key %s took %f milliseconds\n",
+ tdb_name(crec->ctdb_ctx->wtdb->tdb), key,
+ timediff));
+ TALLOC_FREE(key);
+ }
+
+ if (ret != 0) {
+ DEBUG(0, ("tdb_chainunlock failed\n"));
+ return -1;
+ }
threshold = lp_ctdb_locktime_warn_threshold();
if (threshold != 0) {
- double timediff = timeval_elapsed(&crec->lock_time);
+ timediff = timeval_elapsed(&crec->lock_time);
if ((timediff * 1000) > threshold) {
const char *key;
--
1.7.1
>From 1732348760fec8c99e90ef07511f8f836cc3f776 Mon Sep 17 00:00:00 2001
From: Christian Ambach <ambi at samba.org>
Date: Mon, 13 May 2013 17:02:17 +0200
Subject: [PATCH 3/4] s3:dbwrap report time for chainlock and CTDB migrate
Signed-off-by: Christian Ambach <ambi at samba.org>
Reviewed-by: Christof Schmitt <cs at samba.org>
---
source3/lib/dbwrap/dbwrap_ctdb.c | 17 +++++++++++++++--
1 files changed, 15 insertions(+), 2 deletions(-)
diff --git a/source3/lib/dbwrap/dbwrap_ctdb.c b/source3/lib/dbwrap/dbwrap_ctdb.c
index 5e15e3f..fc95318 100644
--- a/source3/lib/dbwrap/dbwrap_ctdb.c
+++ b/source3/lib/dbwrap/dbwrap_ctdb.c
@@ -1043,6 +1043,10 @@ static struct db_record *fetch_locked_internal(struct db_ctdb_ctx *ctx,
TDB_DATA ctdb_data;
int migrate_attempts;
struct timeval migrate_start;
+ struct timeval chainlock_start;
+ struct timeval ctdb_start;
+ double chainlock_time = 0;
+ double ctdb_time = 0;
int duration_msecs;
int lockret;
@@ -1087,9 +1091,12 @@ again:
TALLOC_FREE(keystr);
}
+ GetTimeOfDay(&chainlock_start);
lockret = tryonly
? tdb_chainlock_nonblock(ctx->wtdb->tdb, key)
: tdb_chainlock(ctx->wtdb->tdb, key);
+ chainlock_time += timeval_elapsed(&chainlock_start);
+
if (lockret != 0) {
DEBUG(3, ("tdb_chainlock failed\n"));
TALLOC_FREE(result);
@@ -1127,8 +1134,11 @@ again:
ctdb_data.dptr ?
((struct ctdb_ltdb_header *)ctdb_data.dptr)->flags : 0));
+ GetTimeOfDay(&ctdb_start);
status = ctdbd_migrate(messaging_ctdbd_connection(), ctx->db_id,
key);
+ ctdb_time += timeval_elapsed(&ctdb_start);
+
if (!NT_STATUS_IS_OK(status)) {
DEBUG(5, ("ctdb_migrate failed: %s\n",
nt_errstr(status)));
@@ -1154,11 +1164,14 @@ again:
if ((migrate_attempts > lp_parm_int(-1, "ctdb", "migrate_attempts", 10)) ||
(duration_msecs > lp_parm_int(-1, "ctdb", "migrate_duration", 5000))) {
DEBUG(0, ("db_ctdb_fetch_locked for %s key %s needed %d "
- "attempts, %d milliseconds\n", tdb_name(ctx->wtdb->tdb),
+ "attempts, %d milliseconds, chainlock: %d ms, "
+ "CTDB %d ms\n", tdb_name(ctx->wtdb->tdb),
hex_encode_talloc(talloc_tos(),
(unsigned char *)key.dptr,
key.dsize),
- migrate_attempts, duration_msecs));
+ migrate_attempts, duration_msecs,
+ (int) chainlock_time * 1000,
+ (int) ctdb_time * 1000));
}
GetTimeOfDay(&crec->lock_time);
--
1.7.1
>From 6c08c6c841ca725a35e1923dc3cbd5874feb2bd9 Mon Sep 17 00:00:00 2001
From: Christian Ambach <ambi at samba.org>
Date: Mon, 13 May 2013 18:20:43 +0200
Subject: [PATCH 4/4] s3:dbwrap include the hashchain in the logs
Signed-off-by: Christian Ambach <ambi at samba.org>
Reviewed-by: Christof Schmitt <cs at samba.org>
---
source3/lib/dbwrap/dbwrap_ctdb.c | 15 ++++++++++++---
1 files changed, 12 insertions(+), 3 deletions(-)
diff --git a/source3/lib/dbwrap/dbwrap_ctdb.c b/source3/lib/dbwrap/dbwrap_ctdb.c
index fc95318..492f3aa 100644
--- a/source3/lib/dbwrap/dbwrap_ctdb.c
+++ b/source3/lib/dbwrap/dbwrap_ctdb.c
@@ -1163,12 +1163,21 @@ again:
if ((migrate_attempts > lp_parm_int(-1, "ctdb", "migrate_attempts", 10)) ||
(duration_msecs > lp_parm_int(-1, "ctdb", "migrate_duration", 5000))) {
- DEBUG(0, ("db_ctdb_fetch_locked for %s key %s needed %d "
- "attempts, %d milliseconds, chainlock: %d ms, "
- "CTDB %d ms\n", tdb_name(ctx->wtdb->tdb),
+ int chain = 0;
+
+ if (tdb_get_flags(ctx->wtdb->tdb) & TDB_INCOMPATIBLE_HASH) {
+ chain = tdb_jenkins_hash(&key) %
+ tdb_hash_size(ctx->wtdb->tdb);
+ }
+
+ DEBUG(0, ("db_ctdb_fetch_locked for %s key %s, chain %d "
+ "needed %d attempts, %d milliseconds, "
+ "chainlock: %d ms, CTDB %d ms\n",
+ tdb_name(ctx->wtdb->tdb),
hex_encode_talloc(talloc_tos(),
(unsigned char *)key.dptr,
key.dsize),
+ chain,
migrate_attempts, duration_msecs,
(int) chainlock_time * 1000,
(int) ctdb_time * 1000));
--
1.7.1
More information about the samba-technical
mailing list