diff --git a/server/include/config.h b/server/include/config.h index 0eac018c1..d12069d83 100644 --- a/server/include/config.h +++ b/server/include/config.h @@ -27,7 +27,7 @@ #define DEFAULT_POOLSIZE 32 /** Width of log output in characters */ -#define LOG_WIDTH 74 +#define LOG_WIDTH 132 /** Socket priority */ #define SOCKET_PRIO 7 diff --git a/server/include/hooks.h b/server/include/hooks.h index 17e3c503e..977f551d6 100644 --- a/server/include/hooks.h +++ b/server/include/hooks.h @@ -132,4 +132,7 @@ int hook_stats(struct path *p, struct hook *h, int when); /** Core hook: send path statistics to another node */ int hook_stats_send(struct path *p, struct hook *h, int when); +/** Not a hook: just prints header for periodic statistics */ +void hook_stats_header(); + #endif /** _HOOKS_H_ @} @} */ diff --git a/server/include/log.h b/server/include/log.h index a16a95d92..375c3d394 100644 --- a/server/include/log.h +++ b/server/include/log.h @@ -24,6 +24,7 @@ #define INFO "" #define WARN YEL("Warn ") #define ERROR RED("Error") +#define STATS MAG("Stats") /** Change log indention for current thread. * diff --git a/server/src/hooks.c b/server/src/hooks.c index 959f17740..b656eef25 100644 --- a/server/src/hooks.c +++ b/server/src/hooks.c @@ -347,9 +347,9 @@ int hook_stats(struct path *p, struct hook *h, int when) } 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:"); hist_print(&p->hist_gap); } - if (p->hist_sequence.total) { info("Sequence number gaps:"); hist_print(&p->hist_sequence); } + 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); } break; case HOOK_PATH_RESTART: @@ -360,7 +360,17 @@ int hook_stats(struct path *p, struct hook *h, int when) case HOOK_PERIODIC: { char *buf = path_print(p); - info("%-32s : %-8u %-8u %-8u %-8u %-8u %-8u", buf, p->sent, p->received, p->dropped, p->skipped, p->invalid, p->overrun); + + 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->sent, p->received, p->dropped, p->skipped, p->invalid, p->overrun, p->current->length + ); + else + log_print(STATS, "%-40s|%10s|%10s|%10u|%10u|%10u|%10u|%10u|%10u|%10s|", buf, "", "", + p->sent, p->received, p->dropped, p->skipped, p->invalid, p->overrun, "" + ); + free(buf); break; } @@ -369,6 +379,24 @@ int hook_stats(struct path *p, struct hook *h, int when) return 0; } +void hook_stats_header() +{ +#define UNIT(u) "(" YEL(u) ")" + + log_print(STATS, "%-40s|%19s|%19s|%19s|%19s|%19s|%19s|%19s|%10s|%10s|", "Source " MAG("=>") " Destination", + "OWD" UNIT("S") " ", + "Rate" UNIT("p/S") " ", + "Sent" UNIT("p") " ", + "Recv" UNIT("p") " ", + "Drop" UNIT("p") " ", + "Skip" UNIT("p") " ", + "Inval" UNIT("p") " ", + "Overuns ", + "Values " + ); + line(); +} + REGISTER_HOOK("stats_send", 99, hook_stats_send, HOOK_PRIVATE | HOOK_MSG) int hook_stats_send(struct path *p, struct hook *h, int when) { diff --git a/server/src/ngsi.c b/server/src/ngsi.c index 4dd7b9e23..9474d0736 100644 --- a/server/src/ngsi.c +++ b/server/src/ngsi.c @@ -107,8 +107,8 @@ static int ngsi_request(CURL *handle, const char *endpoint, const char *operatio curl_easy_getinfo(handle, CURLINFO_TOTAL_TIME, &time); curl_easy_getinfo(handle, CURLINFO_RESPONSE_CODE, &code); - debug(10, "Request to context broker completed in %.4f seconds", time); - debug(20, "Response from context broker (code=%ld):\n%s", code, chunk.data); + debug(16, "Request to context broker completed in %.4f seconds", time); + debug(17, "Response from context broker (code=%ld):\n%s", code, chunk.data); json_error_t err; json_t *resp = json_loads(chunk.data, 0, &err); diff --git a/server/src/path.c b/server/src/path.c index 38872fecf..534d325c1 100644 --- a/server/src/path.c +++ b/server/src/path.c @@ -32,7 +32,7 @@ static void path_write(struct path *p) n->combine /* Number of messages which should be sent */ ); - debug(1, "Sent %u messages to node '%s'", sent, n->name); + debug(15, "Sent %u messages to node '%s'", sent, n->name); p->sent += sent; clock_gettime(CLOCK_REALTIME, &p->ts_sent); @@ -95,7 +95,7 @@ static void * path_run(void *arg) /** @todo Replace this timestamp by hardware timestamping */ clock_gettime(CLOCK_REALTIME, &p->ts_recv); - debug(10, "Received %u messages from node '%s'", recv, p->in->name); + debug(15, "Received %u messages from node '%s'", recv, p->in->name); /* Run preprocessing hooks */ if (path_run_hook(p, HOOK_PRE)) { @@ -134,7 +134,8 @@ static void * path_run(void *arg) int path_start(struct path *p) { INDENT char *buf = path_print(p); - info("Starting path: %s (poolsize = %u, msgsize = %u, #hooks = %zu)", buf, p->poolsize, p->msgsize, list_length(&p->hooks)); + info("Starting path: %s (poolsize = %u, msgsize = %u, #hooks = %zu, rate = %.1f)", + buf, p->poolsize, p->msgsize, list_length(&p->hooks), p->rate); free(buf); /* We sort the hooks according to their priority before starting the path */ diff --git a/server/src/server.c b/server/src/server.c index a13a25e50..2e2d6f0af 100644 --- a/server/src/server.c +++ b/server/src/server.c @@ -189,9 +189,7 @@ int main(int argc, char *argv[]) /* Run! */ if (settings.stats > 0) { - info("%-32s : %-8s %-8s %-8s %-8s %-8s %-8s", - "Source " MAG("=>") " Destination", "#Sent", "#Recv", "#Drop", "#Skip", "#Invalid", "#Overuns"); - line(); + hook_stats_header(); do list_foreach(struct path *p, &paths) { usleep(settings.stats * 1e6);