From: Ronnie Sahlberg Date: Mon, 11 Oct 2010 04:11:18 +0000 (+1100) Subject: Update latency countes to show min/max and average X-Git-Url: http://git.samba.org/?p=metze%2Fctdb%2Fwip.git;a=commitdiff_plain;h=1919e949af4641ffe919123e44b02fb87c13ab9f Update latency countes to show min/max and average --- diff --git a/include/ctdb_private.h b/include/ctdb_private.h index f018554d..a99b4b03 100644 --- a/include/ctdb_private.h +++ b/include/ctdb_private.h @@ -304,10 +304,21 @@ struct ctdb_daemon_data { #define CTDB_UPDATE_RECLOCK_LATENCY(ctdb, name, counter, value) \ { \ - if (value > ctdb->statistics.counter) \ - ctdb->statistics.counter = value; \ - if (value > ctdb->statistics_current.counter) \ - ctdb->statistics_current.counter = value; \ + if (value > ctdb->statistics.counter.max) \ + ctdb->statistics.counter.max = value; \ + if (value > ctdb->statistics_current.counter.max) \ + ctdb->statistics_current.counter.max = value; \ + \ + if (ctdb->statistics.counter.num == 0 || value < ctdb->statistics.counter.min) \ + ctdb->statistics.counter.min = value; \ + if (ctdb->statistics_current.counter.num == 0 || value < ctdb->statistics_current.counter.min) \ + ctdb->statistics_current.counter.min = value; \ + \ + ctdb->statistics.counter.total += value; \ + ctdb->statistics_current.counter.total += value; \ + \ + ctdb->statistics.counter.num++; \ + ctdb->statistics_current.counter.num++; \ \ if (ctdb->tunable.reclock_latency_ms != 0) { \ if (value*1000 > ctdb->tunable.reclock_latency_ms) { \ @@ -320,10 +331,22 @@ struct ctdb_daemon_data { #define CTDB_UPDATE_LATENCY(ctdb, db, operation, counter, t) \ { \ double l = timeval_elapsed(&t); \ - if (l > ctdb->statistics.counter) \ - ctdb->statistics.counter = l; \ - if (l > ctdb->statistics_current.counter) \ - ctdb->statistics_current.counter = l; \ + \ + if (l > ctdb->statistics.counter.max) \ + ctdb->statistics.counter.max = l; \ + if (l > ctdb->statistics_current.counter.max) \ + ctdb->statistics_current.counter.max = l; \ + \ + if (ctdb->statistics.counter.num == 0 || l < ctdb->statistics.counter.min) \ + ctdb->statistics.counter.min = l; \ + if (ctdb->statistics_current.counter.num == 0 || l < ctdb->statistics_current.counter.min) \ + ctdb->statistics_current.counter.min = l; \ + \ + ctdb->statistics.counter.total += l; \ + ctdb->statistics_current.counter.total += l; \ + \ + ctdb->statistics.counter.num++; \ + ctdb->statistics_current.counter.num++; \ \ if (ctdb->tunable.log_latency_ms !=0) { \ if (l*1000 > ctdb->tunable.log_latency_ms) { \ diff --git a/include/ctdb_protocol.h b/include/ctdb_protocol.h index 750f1f09..1568460a 100644 --- a/include/ctdb_protocol.h +++ b/include/ctdb_protocol.h @@ -536,6 +536,13 @@ struct ctdb_all_public_ips { }; +struct latency_counter { + int num; + double min; + double max; + double total; +}; + /* ctdb statistics information */ @@ -570,8 +577,8 @@ struct ctdb_statistics { uint32_t traverse; } timeouts; struct { - double ctdbd; - double recd; + struct latency_counter ctdbd; + struct latency_counter recd; } reclock; uint32_t total_calls; uint32_t pending_calls; @@ -582,9 +589,9 @@ struct ctdb_statistics { uint32_t memory_used; uint32_t __last_counter; /* hack for control_statistics_all */ uint32_t max_hop_count; - double max_call_latency; - double max_lockwait_latency; - double max_childwrite_latency; + struct latency_counter call_latency; + struct latency_counter lockwait_latency; + struct latency_counter childwrite_latency; uint32_t num_recoveries; struct timeval statistics_start_time; struct timeval statistics_current_time; diff --git a/server/ctdb_daemon.c b/server/ctdb_daemon.c index 16ccaaca..12ad9543 100644 --- a/server/ctdb_daemon.c +++ b/server/ctdb_daemon.c @@ -258,7 +258,7 @@ static void daemon_call_from_client_callback(struct ctdb_call_state *state) DEBUG(DEBUG_ERR, (__location__ " ctdbd_call_recv() returned error\n")); CTDB_DECREMENT_STAT(client->ctdb, pending_calls); - CTDB_UPDATE_LATENCY(client->ctdb, ctdb_db, "call_from_client_cb 1", max_call_latency, dstate->start_time); + CTDB_UPDATE_LATENCY(client->ctdb, ctdb_db, "call_from_client_cb 1", call_latency, dstate->start_time); return; } @@ -268,7 +268,7 @@ static void daemon_call_from_client_callback(struct ctdb_call_state *state) if (r == NULL) { DEBUG(DEBUG_ERR, (__location__ " Failed to allocate reply_call in ctdb daemon\n")); CTDB_DECREMENT_STAT(client->ctdb, pending_calls); - CTDB_UPDATE_LATENCY(client->ctdb, ctdb_db, "call_from_client_cb 2", max_call_latency, dstate->start_time); + CTDB_UPDATE_LATENCY(client->ctdb, ctdb_db, "call_from_client_cb 2", call_latency, dstate->start_time); return; } r->hdr.reqid = dstate->reqid; @@ -283,7 +283,7 @@ static void daemon_call_from_client_callback(struct ctdb_call_state *state) if (res != 0) { DEBUG(DEBUG_ERR, (__location__ " Failed to queue packet from daemon to client\n")); } - CTDB_UPDATE_LATENCY(client->ctdb, ctdb_db, "call_from_client_cb 3", max_call_latency, dstate->start_time); + CTDB_UPDATE_LATENCY(client->ctdb, ctdb_db, "call_from_client_cb 3", call_latency, dstate->start_time); CTDB_DECREMENT_STAT(client->ctdb, pending_calls); talloc_free(dstate); } @@ -409,7 +409,7 @@ static void daemon_request_call_from_client(struct ctdb_client *client, DEBUG(DEBUG_ERR,(__location__ " Unable to allocate call\n")); CTDB_DECREMENT_STAT(ctdb, pending_calls); - CTDB_UPDATE_LATENCY(ctdb, ctdb_db, "call_from_client 1", max_call_latency, dstate->start_time); + CTDB_UPDATE_LATENCY(ctdb, ctdb_db, "call_from_client 1", call_latency, dstate->start_time); return; } @@ -433,7 +433,7 @@ static void daemon_request_call_from_client(struct ctdb_client *client, if (state == NULL) { DEBUG(DEBUG_ERR,(__location__ " Unable to setup call send\n")); CTDB_DECREMENT_STAT(ctdb, pending_calls); - CTDB_UPDATE_LATENCY(ctdb, ctdb_db, "call_from_client 2", max_call_latency, dstate->start_time); + CTDB_UPDATE_LATENCY(ctdb, ctdb_db, "call_from_client 2", call_latency, dstate->start_time); return; } talloc_steal(state, dstate); diff --git a/server/ctdb_lockwait.c b/server/ctdb_lockwait.c index 9bbc25f9..48198fd1 100644 --- a/server/ctdb_lockwait.c +++ b/server/ctdb_lockwait.c @@ -53,7 +53,7 @@ static void lockwait_handler(struct event_context *ev, struct fd_event *fde, key.dptr = talloc_memdup(tmp_ctx, key.dptr, key.dsize); talloc_set_destructor(h, NULL); - CTDB_UPDATE_LATENCY(h->ctdb, h->ctdb_db, "lockwait", max_lockwait_latency, h->start_time); + CTDB_UPDATE_LATENCY(h->ctdb, h->ctdb_db, "lockwait", lockwait_latency, h->start_time); CTDB_DECREMENT_STAT(h->ctdb, pending_lockwait_calls); /* the handle needs to go away when the context is gone - when diff --git a/server/ctdb_persistent.c b/server/ctdb_persistent.c index 8672c5b3..9346f7d0 100644 --- a/server/ctdb_persistent.c +++ b/server/ctdb_persistent.c @@ -475,7 +475,7 @@ static void childwrite_handler(struct event_context *ev, struct fd_event *fde, int ret; char c; - CTDB_UPDATE_LATENCY(h->ctdb, h->ctdb_db, "persistent", max_childwrite_latency, h->start_time); + CTDB_UPDATE_LATENCY(h->ctdb, h->ctdb_db, "persistent", childwrite_latency, h->start_time); CTDB_DECREMENT_STAT(h->ctdb, pending_childwrite_calls); /* the handle needs to go away when the context is gone - when diff --git a/tools/ctdb.c b/tools/ctdb.c index 8d422552..0409a40b 100644 --- a/tools/ctdb.c +++ b/tools/ctdb.c @@ -219,11 +219,29 @@ static void show_statistics(struct ctdb_statistics *s, int show_header) for (i=0;ireclock.ctdbd); - printf("%.6f:", s->reclock.recd); - printf("%.6f:", s->max_call_latency); - printf("%.6f:", s->max_lockwait_latency); - printf("%.6f:", s->max_childwrite_latency); - printf("%.6f:", s->max_childwrite_latency); + printf("%d:", s->reclock.ctdbd.num); + printf("%.6f:", s->reclock.ctdbd.min); + printf("%.6f:", s->reclock.ctdbd.num?s->reclock.ctdbd.total/s->reclock.ctdbd.num:0.0); + printf("%.6f:", s->reclock.ctdbd.max); + + printf("%d:", s->reclock.recd.num); + printf("%.6f:", s->reclock.recd.min); + printf("%.6f:", s->reclock.recd.num?s->reclock.recd.total/s->reclock.recd.num:0.0); + printf("%.6f:", s->reclock.recd.max); + + printf("%d:", s->call_latency.num); + printf("%.6f:", s->call_latency.min); + printf("%.6f:", s->call_latency.num?s->call_latency.total/s->call_latency.num:0.0); + printf("%.6f:", s->call_latency.max); + + printf("%d:", s->lockwait_latency.num); + printf("%.6f:", s->lockwait_latency.min); + printf("%.6f:", s->lockwait_latency.num?s->lockwait_latency.total/s->lockwait_latency.num:0.0); + printf("%.6f:", s->lockwait_latency.max); + + printf("%d:", s->childwrite_latency.num); + printf("%.6f:", s->childwrite_latency.min); + printf("%.6f:", s->childwrite_latency.num?s->childwrite_latency.total/s->childwrite_latency.num:0.0); + printf("%.6f:", s->childwrite_latency.max); printf("\n"); } else { printf("CTDB version %u\n", CTDB_VERSION); @@ -261,13 +297,13 @@ static void show_statistics(struct ctdb_statistics *s, int show_header) 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/%.6f/%.6f sec out of %d\n", "reclock_ctdbd MIN/AVG/MAX", s->reclock.ctdbd.min, s->reclock.ctdbd.num?s->reclock.ctdbd.total/s->reclock.ctdbd.num:0.0, s->reclock.ctdbd.max, s->reclock.ctdbd.num); + + printf(" %-30s %.6f/%.6f/%.6f sec out of %d\n", "reclock_recd MIN/AVG/MAX", s->reclock.recd.min, s->reclock.recd.num?s->reclock.recd.total/s->reclock.recd.num:0.0, s->reclock.recd.max, s->reclock.recd.num); - 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); - printf(" %-30s %.6f sec\n", "max_childwrite_latency", s->max_childwrite_latency); + printf(" %-30s %.6f/%.6f/%.6f sec out of %d\n", "call_latency MIN/AVG/MAX", s->call_latency.min, s->call_latency.num?s->call_latency.total/s->call_latency.num:0.0, s->call_latency.max, s->call_latency.num); + printf(" %-30s %.6f/%.6f/%.6f sec out of %d\n", "lockwait_latency MIN/AVG/MAX", s->lockwait_latency.min, s->lockwait_latency.num?s->lockwait_latency.total/s->lockwait_latency.num:0.0, s->lockwait_latency.max, s->lockwait_latency.num); + printf(" %-30s %.6f/%.6f/%.6f sec out of %d\n", "childwrite_latency MIN/AVG/MAX", s->childwrite_latency.min, s->childwrite_latency.num?s->childwrite_latency.total/s->childwrite_latency.num:0.0, s->childwrite_latency.max, s->childwrite_latency.num); } talloc_free(tmp_ctx); @@ -305,10 +341,10 @@ static int control_statistics_all(struct ctdb_context *ctdb) } statistics.max_hop_count = MAX(statistics.max_hop_count, s1.max_hop_count); - statistics.max_call_latency = - MAX(statistics.max_call_latency, s1.max_call_latency); - statistics.max_lockwait_latency = - MAX(statistics.max_lockwait_latency, s1.max_lockwait_latency); + statistics.call_latency.max = + MAX(statistics.call_latency.max, s1.call_latency.max); + statistics.lockwait_latency.max = + MAX(statistics.lockwait_latency.max, s1.lockwait_latency.max); } talloc_free(nodes); printf("Gathered statistics for %u nodes\n", num_nodes);