From 9e0a8a0eeecc6fa58fca98692f39950a1ea40a6b Mon Sep 17 00:00:00 2001 From: Mark Riddoch Date: Thu, 23 Oct 2014 13:38:46 +0100 Subject: [PATCH] Addition of show eventstats --- server/core/housekeeper.c | 2 +- server/core/poll.c | 87 +++++++++++++++++++++++++------ server/include/dcb.h | 2 + server/include/poll.h | 1 + server/modules/routing/debugcmd.c | 4 ++ 5 files changed, 80 insertions(+), 16 deletions(-) diff --git a/server/core/housekeeper.c b/server/core/housekeeper.c index 7cc3d5f4b..520fe97f4 100644 --- a/server/core/housekeeper.c +++ b/server/core/housekeeper.c @@ -296,7 +296,7 @@ struct tm tm; char buf[40]; dcb_printf(pdcb, "%-25s | Type | Frequency | Next Due\n", "Name"); - dcb_printf(pdcb, "--------------------------+----------+-----------+-----------------------\n"); + dcb_printf(pdcb, "--------------------------+----------+-----------+-------------------------\n"); spinlock_acquire(&tasklock); ptr = tasks; while (ptr) diff --git a/server/core/poll.c b/server/core/poll.c index e614c7ba6..d5f5830ca 100644 --- a/server/core/poll.c +++ b/server/core/poll.c @@ -159,6 +159,17 @@ static struct { int blockingpolls; /*< Number of epoll_waits with a timeout specified */ } pollStats; +#define N_QUEUE_TIMES 30 +/** + * The event queue statistics + */ +static struct { + unsigned int qtimes[N_QUEUE_TIMES+1]; + unsigned int exectimes[N_QUEUE_TIMES+1]; + unsigned long maxqtime; + unsigned long maxexectime; +} queueStats; + /** * How frequently to call the poll_loadav function used to monitor the load * average of the poll subsystem. @@ -187,6 +198,7 @@ int i; exit(-1); } memset(&pollStats, 0, sizeof(pollStats)); + memset(&queueStats, 0, sizeof(queueStats)); bitmask_init(&poll_mask); n_threads = config_threadcount(); if ((thread_data = @@ -543,9 +555,7 @@ int poll_spins = 0; if (dcb->evq.pending_events == 0) { pollStats.evq_pending++; -#if PROFILE_POLL dcb->evq.inserted = hkheartbeat; -#endif } dcb->evq.pending_events |= ev; } @@ -567,9 +577,7 @@ int poll_spins = 0; } pollStats.evq_length++; pollStats.evq_pending++; -#if PROFILE_POLL dcb->evq.inserted = hkheartbeat; -#endif if (pollStats.evq_length > pollStats.evq_max) { pollStats.evq_max = pollStats.evq_length; @@ -664,6 +672,7 @@ process_pollq(int thread_id) DCB *dcb; int found = 0; uint32_t ev; +unsigned long qtime; spinlock_acquire(&pollqlock); if (eventq == NULL) @@ -712,6 +721,15 @@ uint32_t ev; #if PROFILE_POLL memlog_log(plog, hkheartbeat - dcb->evq.inserted); #endif + qtime = hkheartbeat - dcb->evq.inserted; + dcb->evq.started = hkheartbeat; + + if (qtime > N_QUEUE_TIMES) + queueStats.qtimes[N_QUEUE_TIMES]++; + else + queueStats.qtimes[qtime]++; + if (qtime > queueStats.maxqtime) + queueStats.maxqtime = qtime; CHK_DCB(dcb); @@ -914,6 +932,14 @@ uint32_t ev; spinlock_release(&dcb->dcb_initlock); } #endif + qtime = hkheartbeat - dcb->evq.started; + + if (qtime > N_QUEUE_TIMES) + queueStats.exectimes[N_QUEUE_TIMES]++; + else + queueStats.exectimes[qtime % N_QUEUE_TIMES]++; + if (qtime > queueStats.maxexectime) + queueStats.maxexectime = qtime; spinlock_acquire(&pollqlock); dcb->evq.processing_events = 0; @@ -1010,6 +1036,7 @@ dprintPollStats(DCB *dcb) { int i; + dcb_printf(dcb, "\nPoll Statistics.\n\n"); dcb_printf(dcb, "No. of epoll cycles: %d\n", pollStats.n_polls); dcb_printf(dcb, "No. of epoll cycles with wait: %d\n", @@ -1164,8 +1191,8 @@ double qavg1 = 0.0, qavg5 = 0.0, qavg15 = 0.0; if (thread_data == NULL) return; - dcb_printf(dcb, " ID | State | # fds | Descriptor | Event\n"); - dcb_printf(dcb, "----+------------+--------+------------------+---------------\n"); + dcb_printf(dcb, " ID | State | # fds | Descriptor | Running | Event\n"); + dcb_printf(dcb, "----+------------+--------+------------------+----------+---------------\n"); for (i = 0; i < n_threads; i++) { switch (thread_data[i].state) @@ -1188,11 +1215,11 @@ double qavg1 = 0.0, qavg5 = 0.0, qavg15 = 0.0; } if (thread_data[i].state != THREAD_PROCESSING) dcb_printf(dcb, - " %2d | %-10s | | |\n", + " %2d | %-10s | | | |\n", i, state); else if (thread_data[i].cur_dcb == NULL) dcb_printf(dcb, - " %2d | %-10s | %6d | |\n", + " %2d | %-10s | %6d | | |\n", i, state, thread_data[i].n_fds); else { @@ -1201,9 +1228,10 @@ double qavg1 = 0.0, qavg5 = 0.0, qavg15 = 0.0; if (event_string == NULL) event_string = "??"; dcb_printf(dcb, - " %2d | %-10s | %6d | %-16p | %s\n", + " %2d | %-10s | %6d | %-16p | <%3d00ms | %s\n", i, state, thread_data[i].n_fds, - thread_data[i].cur_dcb, event_string); + thread_data[i].cur_dcb, 1 + hkheartbeat - dcb->evq.started, + event_string); free(event_string); } } @@ -1282,6 +1310,7 @@ uint32_t ev = EPOLLOUT; else { dcb->evq.pending_events = ev; + dcb->evq.inserted = hkheartbeat; if (eventq) { dcb->evq.prev = eventq->evq.prev; @@ -1297,9 +1326,7 @@ uint32_t ev = EPOLLOUT; } pollStats.evq_length++; pollStats.evq_pending++; -#if PROFILE_POLL dcb->evq.inserted = hkheartbeat; -#endif if (pollStats.evq_length > pollStats.evq_max) { pollStats.evq_max = pollStats.evq_length; @@ -1317,17 +1344,16 @@ void dShowEventQ(DCB *pdcb) { DCB *dcb; -int found = 0; -uint32_t ev; spinlock_acquire(&pollqlock); if (eventq == NULL) { /* Nothing to process */ spinlock_release(&pollqlock); - return 0; + return; } dcb = eventq; + dcb_printf(pdcb, "\nEvent Queue.\n"); dcb_printf(pdcb, "%-16s | %-10s | %-18s | %s\n", "DCB", "Status", "Processing Events", "Pending Events"); dcb_printf(pdcb, "-----------------+------------+--------------------+-------------------\n"); @@ -1340,3 +1366,34 @@ uint32_t ev; } while (dcb != eventq); spinlock_release(&pollqlock); } + + +/** + * Print the event queue statistics + * + * @param pdcb The DCB to print the event queue to + */ +void +dShowEventStats(DCB *pdcb) +{ +int i; + + dcb_printf(pdcb, "\nEvent statistics.\n"); + dcb_printf(pdcb, "Maximum queue time: %3d00ms\n", queueStats.maxqtime); + dcb_printf(pdcb, "Maximum execution time: %3d00ms\n", queueStats.maxexectime); + dcb_printf(pdcb, "Maximum event queue length: %3d\n", pollStats.evq_max); + dcb_printf(pdcb, "Current event queue length: %3d\n", pollStats.evq_length); + dcb_printf(pdcb, "\n"); + dcb_printf(pdcb, " | Number of events\n"); + dcb_printf(pdcb, "Duration | Queued | Executed\n"); + dcb_printf(pdcb, "---------------+------------+-----------\n"); + dcb_printf(pdcb, " < 100ms | %-10d | %-10d\n", + queueStats.qtimes[0], queueStats.exectimes[0]); + for (i = 1; i < N_QUEUE_TIMES; i++) + { + dcb_printf(pdcb, " %2d00 - %2d00ms | %-10d | %-10d\n", i, i + 1, + queueStats.qtimes[i], queueStats.exectimes[i]); + } + dcb_printf(pdcb, " > %2d00ms | %-10d | %-10d\n", N_QUEUE_TIMES, + queueStats.qtimes[N_QUEUE_TIMES], queueStats.exectimes[N_QUEUE_TIMES]); +} diff --git a/server/include/dcb.h b/server/include/dcb.h index 723838151..8c29ec265 100644 --- a/server/include/dcb.h +++ b/server/include/dcb.h @@ -109,6 +109,7 @@ typedef struct gw_protocol { * processing Flag to indicate the processing status of the DCB * eventqlock Spinlock to protect this structure * inserted Insertion time for logging purposes + * started Time that the processign started */ typedef struct { struct dcb *next; @@ -118,6 +119,7 @@ typedef struct { int processing; SPINLOCK eventqlock; unsigned long inserted; + unsigned long started; } DCBEVENTQ; /** diff --git a/server/include/poll.h b/server/include/poll.h index f4d9f4aa8..eae895a1b 100644 --- a/server/include/poll.h +++ b/server/include/poll.h @@ -44,4 +44,5 @@ extern void poll_set_nonblocking_polls(unsigned int); extern void dprintPollStats(DCB *); extern void dShowThreads(DCB *dcb); extern void dShowEventQ(DCB *dcb); +extern void dShowEventStats(DCB *dcb); #endif diff --git a/server/modules/routing/debugcmd.c b/server/modules/routing/debugcmd.c index db309c671..c89ba048e 100644 --- a/server/modules/routing/debugcmd.c +++ b/server/modules/routing/debugcmd.c @@ -124,6 +124,10 @@ struct subcommand showoptions[] = { "Show the queue of events waiting to be processed", "Show the queue of events waiting to be processed", {0, 0, 0} }, + { "eventstats", 0, dShowEventStats, + "Show the event statistics", + "Show the event statistics", + {0, 0, 0} }, { "filter", 1, dprintFilter, "Show details of a filter, called with a filter name", "Show details of a filter, called with the address of a filter",