Track how long it takes to take out the recovery lock from both the main dameon and...

Log this in "ctdb statistics".

Also add a varaible "RecLockLatencyMs" that will log an error everytime it takes longer than this to access the reclock file.

diff --git a/client/ctdb_client.c b/client/ctdb_client.c
index 3bdb4b2617d3ed38c7f06f8722b4501ef13aac4b..fa6a990a4d9cfa647b339f5722595ea36c8bfad1 100644 (file)
--- a/client/ctdb_client.c
+++ b/client/ctdb_client.c
@@ -3615,3 +3615,24 @@ int ctdb_ctrl_getscriptstatus(struct ctdb_context *ctdb,
        return 0;
 }
 
+/*
+  tell the main daemon how long it took to lock the reclock file
+ */
+int ctdb_ctrl_report_recd_lock_latency(struct ctdb_context *ctdb, struct timeval timeout, double latency)
+{
+       int ret;
+       int32_t res;
+       TDB_DATA data;
+
+       data.dptr = (uint8_t *)&latency;
+       data.dsize = sizeof(latency);
+
+       ret = ctdb_control(ctdb, CTDB_CURRENT_NODE, 0, CTDB_CONTROL_RECD_RECLOCK_LATENCY, 0, data, 
+                          ctdb, NULL, &res, NULL, NULL);
+       if (ret != 0 || res != 0) {
+               DEBUG(DEBUG_ERR,("Failed to send recd reclock latency\n"));
+               return -1;
+       }
+
+       return 0;
+}

diff --git a/common/ctdb_util.c b/common/ctdb_util.c
index a3f1731fa1370d188758a63ace1f2bcdb796ac67..3604cc8ed4b7a543f2877bdf46b291967770208c 100644 (file)
--- a/common/ctdb_util.c
+++ b/common/ctdb_util.c
@@ -138,6 +138,22 @@ void ctdb_latency(struct ctdb_db_context *ctdb_db, const char *name, double *lat
        }
 }
 
+/*
+  update a reclock latency number
+ */
+void ctdb_reclock_latency(struct ctdb_context *ctdb, const char *name, double *latency, double l)
+{
+       if (l > *latency) {
+               *latency = l;
+       }
+
+       if (ctdb->tunable.reclock_latency_ms !=0) {
+               if (l*1000 > ctdb->tunable.reclock_latency_ms) {
+                       DEBUG(DEBUG_ERR, ("High RECLOCK latency %fs for operation %s\n", l, name));
+               }
+       }
+}
+
 uint32_t ctdb_reqid_new(struct ctdb_context *ctdb, void *state)
 {
        uint32_t id;

diff --git a/include/ctdb_private.h b/include/ctdb_private.h
index f37560abe065c68d83a89b597b29a96f9a6d8b94..5ecf8a6494f3d4ce930102a88c0fe7d06d103ba2 100644 (file)
--- a/include/ctdb_private.h
+++ b/include/ctdb_private.h
@@ -105,6 +105,7 @@ struct ctdb_tunable {
        uint32_t recd_ping_timeout;
        uint32_t recd_ping_failcount;
        uint32_t log_latency_ms;
+       uint32_t reclock_latency_ms;
        uint32_t recovery_drop_all_ips;
        uint32_t verify_recovery_lock;
 };
@@ -299,6 +300,10 @@ struct ctdb_statistics {
                uint32_t control;
                uint32_t traverse;
        } timeouts;
+       struct {
+               double ctdbd;
+               double recd;
+       } reclock;
        uint32_t total_calls;
        uint32_t pending_calls;
        uint32_t lockwait_calls;
@@ -562,6 +567,7 @@ enum ctdb_controls {CTDB_CONTROL_PROCESS_EXISTS          = 0,
                    CTDB_CONTROL_EVENT_SCRIPT_FINISHED   = 95,
                    CTDB_CONTROL_GET_EVENT_SCRIPT_STATUS = 96,
                    CTDB_CONTROL_TRAVERSE_KILL           = 97,
+                   CTDB_CONTROL_RECD_RECLOCK_LATENCY    = 98,
 };     
 
 /*
@@ -954,6 +960,7 @@ void ctdb_recv_raw_pkt(void *p, uint8_t *data, uint32_t length);
 int ctdb_socket_connect(struct ctdb_context *ctdb);
 
 void ctdb_latency(struct ctdb_db_context *ctdb_db, const char *name, double *latency, struct timeval t);
+void ctdb_reclock_latency(struct ctdb_context *ctdb, const char *name, double *latency, double l);
 
 uint32_t ctdb_reqid_new(struct ctdb_context *ctdb, void *state);
 void *_ctdb_reqid_find(struct ctdb_context *ctdb, uint32_t reqid, const char *type, const char *location);
@@ -1431,5 +1438,6 @@ int32_t ctdb_control_event_script_finished(struct ctdb_context *ctdb);
 int32_t ctdb_control_get_event_script_status(struct ctdb_context *ctdb, TDB_DATA *outdata);
 
 int ctdb_log_event_script_output(struct ctdb_context *ctdb, char *str, uint16_t len);
+int ctdb_ctrl_report_recd_lock_latency(struct ctdb_context *ctdb, struct timeval timeout, double latency);
 
 #endif

diff --git a/server/ctdb_control.c b/server/ctdb_control.c
index d5d4766490d68fdc6a8a2916db8529a882795d5d..72e60c526b9b662e298f0b233c9a6b95aa2b487a 100644 (file)
--- a/server/ctdb_control.c
+++ b/server/ctdb_control.c
@@ -441,6 +441,10 @@ static int32_t ctdb_control_dispatch(struct ctdb_context *ctdb,
                CHECK_CONTROL_DATA_SIZE(0);
                return ctdb_control_get_event_script_status(ctdb, outdata);
 
+       case CTDB_CONTROL_RECD_RECLOCK_LATENCY:
+               CHECK_CONTROL_DATA_SIZE(sizeof(double));
+               ctdb_reclock_latency(ctdb, "recd reclock", &ctdb->statistics.reclock.recd, *((double *)indata.dptr));
+               return 0;
        default:
                DEBUG(DEBUG_CRIT,(__location__ " Unknown CTDB control opcode %u\n", opcode));
                return -1;

diff --git a/server/ctdb_recover.c b/server/ctdb_recover.c
index c979398f30a4bed335fde61c5aa7111d0c172dbc..b4428fa4946e9edaf6974a3081fe5ef973742fdb 100644 (file)
--- a/server/ctdb_recover.c
+++ b/server/ctdb_recover.c
@@ -492,6 +492,7 @@ struct ctdb_set_recmode_state {
        struct timed_event *te;
        struct fd_event *fde;
        pid_t child;
+       struct timeval start_time;
 };
 
 /*
@@ -520,6 +521,10 @@ static void ctdb_set_recmode_timeout(struct event_context *ev, struct timed_even
 */
 static int set_recmode_destructor(struct ctdb_set_recmode_state *state)
 {
+       double l = timeval_elapsed(&state->start_time);
+
+       ctdb_reclock_latency(state->ctdb, "daemon reclock", &state->ctdb->statistics.reclock.ctdbd, l);
+               
        kill(state->child, SIGKILL);
        return 0;
 }
@@ -632,6 +637,7 @@ int32_t ctdb_control_set_recmode(struct ctdb_context *ctdb,
        state = talloc(ctdb, struct ctdb_set_recmode_state);
        CTDB_NO_MEMORY(ctdb, state);
 
+       state->start_time = timeval_current();
 
        if (ctdb->tunable.verify_recovery_lock == 0) {
                /* dont need to verify the reclock file */

diff --git a/server/ctdb_recoverd.c b/server/ctdb_recoverd.c
index c6d0a7a5f4a22725c875c0475f7bf95db755d739..995284fbb22bdb753ad5e6dba80350be75041937 100644 (file)
--- a/server/ctdb_recoverd.c
+++ b/server/ctdb_recoverd.c
@@ -1328,6 +1328,7 @@ static int do_recovery(struct ctdb_recoverd *rec,
        struct ctdb_dbid_map *dbmap;
        TDB_DATA data;
        uint32_t *nodes;
+       struct timeval start_time;
 
        DEBUG(DEBUG_NOTICE, (__location__ " Starting do_recovery\n"));
 
@@ -1351,11 +1352,15 @@ static int do_recovery(struct ctdb_recoverd *rec,
                ctdb_ban_node(rec, rec->last_culprit, ctdb->tunable.recovery_ban_period);
        }
 
+       DEBUG(DEBUG_ERR,("Taking out recovery lock from recovery daemon\n"));
+       start_time = timeval_current();
        if (!ctdb_recovery_lock(ctdb, true)) {
                ctdb_set_culprit(rec, pnn);
                DEBUG(DEBUG_ERR,("Unable to get recovery lock - aborting recovery\n"));
                return -1;
        }
+       ctdb_ctrl_report_recd_lock_latency(ctdb, CONTROL_TIMEOUT(), timeval_elapsed(&start_time));
+       DEBUG(DEBUG_ERR,("Recovery lock taken successfully by recovery daemon\n"));
 
        DEBUG(DEBUG_NOTICE, (__location__ " Recovery initiated due to problem with node %u\n", culprit));
 

diff --git a/server/ctdb_tunables.c b/server/ctdb_tunables.c
index bab9aef25a8f450da4f9afdc1ba510ae7371982a..6a8876fc2b7ee0eede30d3e7bbcb5410acad91c4 100644 (file)
--- a/server/ctdb_tunables.c
+++ b/server/ctdb_tunables.c
@@ -53,6 +53,7 @@ static const struct {
        { "RecdPingTimeout",     20,  offsetof(struct ctdb_tunable, recd_ping_timeout) },
        { "RecdFailCount",        3,  offsetof(struct ctdb_tunable, recd_ping_failcount) },
        { "LogLatencyMs",         0,  offsetof(struct ctdb_tunable, log_latency_ms) },
+       { "RecLockLatencyMs",  1000,  offsetof(struct ctdb_tunable, reclock_latency_ms) },
        { "RecoveryDropAllIPs",  60,  offsetof(struct ctdb_tunable, recovery_drop_all_ips) },
        { "VerifyRecoveryLock",   1,  offsetof(struct ctdb_tunable, verify_recovery_lock) },
 };

diff --git a/tools/ctdb.c b/tools/ctdb.c
index 35a4190eb738d2d64cf5d7718a251b202e4c3865..b85354c001930dca9d29fe7ff07b7d24186e466c 100644 (file)
--- a/tools/ctdb.c
+++ b/tools/ctdb.c
@@ -209,6 +209,9 @@ static void show_statistics(struct ctdb_statistics *s)
                       preflen?0:4, "",
                       *(uint32_t *)(fields[i].offset+(uint8_t *)s));
        }
+       printf(" %-30s     %.6f sec\n", "max_reclock_ctdbd", s->reclock.ctdbd);
+       printf(" %-30s     %.6f sec\n", "max_reclock_recd", s->reclock.recd);
+
        printf(" %-30s     %.6f sec\n", "max_call_latency", s->max_call_latency);
        printf(" %-30s     %.6f sec\n", "max_lockwait_latency", s->max_lockwait_latency);
        printf(" %-30s     %.6f sec\n", "max_childwrite_latency", s->max_childwrite_latency);