diff --git a/server/include/hooks.h b/server/include/hooks.h index 977f551d6..13b366f8a 100644 --- a/server/include/hooks.h +++ b/server/include/hooks.h @@ -72,7 +72,7 @@ enum hook_type { /** All path related actions */ HOOK_PATH = HOOK_PATH_START | HOOK_PATH_STOP | HOOK_PATH_RESTART, /** Hooks which are used to collect statistics. */ - HOOK_STATS = HOOK_INTERNAL | HOOK_PRIVATE | HOOK_PATH | HOOK_MSG | HOOK_PERIODIC, + HOOK_STATS = HOOK_INTERNAL | HOOK_PRIVATE | HOOK_PATH | HOOK_MSG | HOOK_PRE | HOOK_PERIODIC, /** All hooks */ HOOK_ALL = HOOK_INTERNAL - 1 /** @} */ diff --git a/server/include/path.h b/server/include/path.h index c381c3069..cf78a2e06 100644 --- a/server/include/path.h +++ b/server/include/path.h @@ -68,17 +68,21 @@ struct path /* The following fields are mostly managed by hook_ functions */ + /** Histogram for one-way-delay (OWD) of received messages */ + struct hist hist_owd; + /** Histogram for inter message timestamps (as sent by remote) */ + struct hist hist_gap_msg; + /** Histogram for inter message arrival time (as seen by this instance) */ + struct hist hist_gap_recv; /** Histogram of sequence number displacement of received messages */ - struct hist hist_sequence; - /** Histogram for delay of received messages */ - struct hist hist_delay; - /** Histogram for inter message delay (time between received messages) */ - struct hist hist_gap; - + struct hist hist_gap_seq; + /** Last message received */ struct timespec ts_recv; /** Last message sent */ struct timespec ts_sent; + /** Previous message received (old value of path::ts_recv) */ + struct timespec ts_last; /** Counter for sent messages to all outgoing nodes */ unsigned int sent; diff --git a/server/src/hooks.c b/server/src/hooks.c index 4e7d9075b..8d35e3ef9 100644 --- a/server/src/hooks.c +++ b/server/src/hooks.c @@ -322,40 +322,55 @@ int hook_stats(struct path *p, struct hook *h, int when) switch (when) { case HOOK_INIT: /** @todo Allow configurable bounds for histograms */ - hist_create(&p->hist_sequence, -HIST_SEQ, +HIST_SEQ, 1); - hist_create(&p->hist_delay, 0, 2, 100e-3); - hist_create(&p->hist_gap, 0, 40e-3, 1e-3); + hist_create(&p->hist_gap_seq, -HIST_SEQ, +HIST_SEQ, 1); + hist_create(&p->hist_owd, 0, 1, 100e-3); + hist_create(&p->hist_gap_msg, 90e-3, 110e-3, 1e-3); + hist_create(&p->hist_gap_recv, 90e-3, 110e-3, 1e-3); break; case HOOK_DEINIT: - hist_destroy(&p->hist_sequence); - hist_destroy(&p->hist_delay); - hist_destroy(&p->hist_gap); + hist_destroy(&p->hist_gap_seq); + hist_destroy(&p->hist_owd); + hist_destroy(&p->hist_gap_msg); + hist_destroy(&p->hist_gap_recv); break; + + case HOOK_PRE: + /* Exclude first message from statistics */ + if (p->received > 0) { + double gap = time_delta(&p->ts_last, &p->ts_recv); + + hist_put(&p->hist_gap_recv, gap); + } case HOOK_MSG: { struct msg *prev = p->previous, *cur = p->current; - - int dist = cur->sequence - (int32_t) prev->sequence; - double delay = time_delta(&p->ts_recv, &MSG_TS(cur)); - double gap = time_delta(&MSG_TS(prev), &MSG_TS(cur)); - hist_put(&p->hist_sequence, dist); - hist_put(&p->hist_delay, delay); - hist_put(&p->hist_gap, gap); + /* Exclude first message from statistics */ + if (p->received > 0) { + int dist = cur->sequence - (int32_t) prev->sequence; + double delay = time_delta(&MSG_TS(cur), &p->ts_recv); + double gap = time_delta(&MSG_TS(prev), &MSG_TS(cur)); + + hist_put(&p->hist_gap_msg, gap); + hist_put(&p->hist_gap_seq, dist); + hist_put(&p->hist_owd, delay); + } break; } case HOOK_PATH_STOP: - if (p->hist_delay.total) { info("One-way delay (received):"); hist_print(&p->hist_delay); } - if (p->hist_gap.total) { info("Message gap time (received):"); hist_print(&p->hist_gap); } - if (p->hist_sequence.total) { info("Sequence number gaps (received):"); hist_print(&p->hist_sequence); } + if (p->hist_owd.total) { info("One-way delay:"); hist_print(&p->hist_owd); } + if (p->hist_gap_recv.total){ info("Inter-message arrival time:"); hist_print(&p->hist_gap_recv); } + if (p->hist_gap_msg.total) { info("Inter-message ts gap:"); hist_print(&p->hist_gap_msg); } + if (p->hist_gap_seq.total) { info("Inter-message sequence number gaps:"); hist_print(&p->hist_gap_seq); } break; case HOOK_PATH_RESTART: - hist_reset(&p->hist_sequence); - hist_reset(&p->hist_delay); - hist_reset(&p->hist_gap); + hist_reset(&p->hist_owd); + hist_reset(&p->hist_gap_seq); + hist_reset(&p->hist_gap_msg); + hist_reset(&p->hist_gap_recv); break; case HOOK_PERIODIC: { @@ -363,7 +378,7 @@ int hook_stats(struct path *p, struct hook *h, int when) if (p->received > 0) log_print(STATS, "%-40s|%10.2g|%10.2f|%10u|%10u|%10u|%10u|%10u|%10u|%10u|", buf, - hist_mean(&p->hist_delay), 1 / hist_mean(&p->hist_gap), + p->hist_owd.last, 1 / p->hist_gap_msg.last, p->sent, p->received, p->dropped, p->skipped, p->invalid, p->overrun, p->current->length ); else @@ -429,8 +444,9 @@ int hook_stats_send(struct path *p, struct hook *h, int when) m.data[m.length++].f = p->invalid; m.data[m.length++].f = p->skipped; m.data[m.length++].f = p->dropped; - m.data[m.length++].f = p->hist_delay.last, - m.data[m.length++].f = p->hist_gap.last; + m.data[m.length++].f = p->hist_owd.last, + m.data[m.length++].f = p->hist_gap_msg.last; + m.data[m.length++].f = p->hist_gap_recv.last; /* Send single message with statistics to destination node */ node_write_single(private->dest, &m); diff --git a/server/src/path.c b/server/src/path.c index f68c5d9dc..e5de77570 100644 --- a/server/src/path.c +++ b/server/src/path.c @@ -93,6 +93,7 @@ static void * path_run(void *arg) continue; /** @todo Replace this timestamp by hardware timestamping */ + p->ts_last = p->ts_recv; p->ts_recv = time_now(); debug(15, "Received %u messages from node '%s'", recv, p->in->name);