From 52758f0e61a00fcf427bd7d6cab67ec077c9abce Mon Sep 17 00:00:00 2001 From: Quentin Dufour Date: Mon, 1 Apr 2019 19:27:40 +0200 Subject: [PATCH] Timing event loop precisely --- src/evt_core.c | 95 ++++++++++++++++++++++++++++++++++++++++++++------ src/evt_core.h | 1 + src/meas_lat.c | 6 ++-- src/utils.c | 12 +++++++ src/utils.h | 2 ++ 5 files changed, 101 insertions(+), 15 deletions(-) diff --git a/src/evt_core.c b/src/evt_core.c index f1b330a..04d7bba 100644 --- a/src/evt_core.c +++ b/src/evt_core.c @@ -172,17 +172,89 @@ void evt_core_free(struct evt_core_ctx* ctx) { g_hash_table_destroy (ctx->urltofd); } +enum timing_config { + TIMING_ACTIVATED = 1 << 0, + TIMING_DISPLAY_START = 1 << 1, + TIMING_DISPLAY_END = 1 << 2, + TIMING_DISPLAY_BOTH = 1 << 3 +}; + +struct timing_fx { + struct timespec start; + enum timing_config config; + uint8_t activated_start; + char start_template[255], end_template[255]; +}; + +void timing_fx_init(struct timing_fx* tfx, enum timing_config conf, char* startt, char* endt) { + tfx->config = conf; + strncpy (tfx->start_template, startt, sizeof(tfx->start_template) - 1); + strncpy (tfx->end_template, endt, sizeof(tfx->end_template) - 1); + tfx->start_template[sizeof(tfx->start_template) - 1] = 0; // Enforce null terminated string + tfx->end_template[sizeof(tfx->end_template) - 1] = 0; +} + +void timing_fx_start(struct timing_fx* tfx, ...) { + va_list args; + if (!(tfx->config & TIMING_ACTIVATED)) return; + if (tfx->config & (TIMING_DISPLAY_START | TIMING_DISPLAY_BOTH)) { + va_start(args, tfx); + vfprintf(stderr, tfx->start_template, args); + va_end(args); + } + + if (clock_gettime(CLOCK_REALTIME, &tfx->start) == -1) { + perror("clock_gettime"); + exit(EXIT_FAILURE); + } +} + +double timing_fx_stop(struct timing_fx* tfx, ...) { + va_list args; + struct timespec stop; + double elapsed_in_cb; + + if (!(tfx->config & TIMING_ACTIVATED)) return 0.; + + if (clock_gettime(CLOCK_REALTIME, &stop) == -1) { + perror("clock_gettime"); + exit(EXIT_FAILURE); + } + + elapsed_in_cb = (double)elapsed_micros (&tfx->start, &stop) / 1000000.; + + if (tfx->config & (TIMING_DISPLAY_END | TIMING_DISPLAY_BOTH)) { + va_start(args, tfx); + vfprintf(stderr, tfx->end_template, args); + fprintf(stderr, ": done in %f sec\n", elapsed_in_cb); + va_end(args); + } + return elapsed_in_cb; +} + void evt_core_loop(struct evt_core_ctx* ctx) { struct epoll_event current_event, events[EVT_CORE_MAX_EVENTS]; struct evt_core_fdinfo* fdinfo; struct evt_core_cat* cat; - clock_t start, end; + int return_code; + clock_t start_timing, end_timing; double elapsed_in_cb; + struct timing_fx tfx_epoll, tfx_err, tfx_cb, tfx_loop; + + enum timing_config base = ctx->verbose ? TIMING_ACTIVATED : 0; + timing_fx_init (&tfx_epoll, base | TIMING_DISPLAY_END, "", "[SLEPT]()"); + timing_fx_init (&tfx_cb, base | TIMING_DISPLAY_BOTH, "[BEGIN CB](name=%s, url=%s, fd=%d)\n", "[END CB]()"); + timing_fx_init (&tfx_err, base | TIMING_DISPLAY_BOTH, "[BEGIN ERR](name=%s, url=%s, fd=%d)\n", "[END ERR]()"); + timing_fx_init (&tfx_loop, base | TIMING_DISPLAY_END, "", "[LOOP]()"); printf("--- Start main loop\n"); int num_fd, n = 0; while(1) { + timing_fx_start(&tfx_epoll); num_fd = epoll_wait(ctx->epollfd, events, EVT_CORE_MAX_EVENTS, -1); + timing_fx_stop(&tfx_epoll); + + timing_fx_start(&tfx_loop); if (num_fd == -1) { perror("Failed to epoll_wait"); exit(EXIT_FAILURE); @@ -213,7 +285,12 @@ void evt_core_loop(struct evt_core_ctx* ctx) { fdinfo = evt_core_get_from_fd(ctx, err_fd); if (fdinfo != NULL) { if (fdinfo->cat->err_cb != NULL) { - if (fdinfo->cat->err_cb(ctx, fdinfo) == 1) { + + timing_fx_start (&tfx_err, fdinfo->cat->name, fdinfo->url, fdinfo->fd); + return_code = fdinfo->cat->err_cb(ctx, fdinfo); + timing_fx_stop(&tfx_err); + + if (return_code == 1) { fprintf(stderr, "Error on fd=%d on cat=%s is handled by app, not clearing it\n", err_fd, fdinfo->cat->name); continue; } @@ -233,17 +310,13 @@ void evt_core_loop(struct evt_core_ctx* ctx) { fprintf(stderr, "Ignoring file descriptor %d as it is not registered. This is a bug.\n", events[n].data.fd); continue; } - if (ctx->verbose) { - fprintf(stderr, "[BEGIN CB](name=%s, url=%s, fd=%d)\n", fdinfo->cat->name, fdinfo->url, fdinfo->fd); - start = clock(); - } + + timing_fx_start(&tfx_cb, fdinfo->cat->name, fdinfo->url, fdinfo->fd); while(fdinfo->cat->cb(ctx, fdinfo) == 0); - if (ctx->verbose) { - end = clock(); - elapsed_in_cb = ((double) (end - start)) / CLOCKS_PER_SEC; - fprintf(stderr, "[END CB](time=%f sec)\n", elapsed_in_cb); - } + timing_fx_stop(&tfx_cb); } + + timing_fx_stop(&tfx_loop); } evt_core_free(ctx); diff --git a/src/evt_core.h b/src/evt_core.h index 4f3c39b..dceae7d 100644 --- a/src/evt_core.h +++ b/src/evt_core.h @@ -8,6 +8,7 @@ #include #include #include "net_tools.h" +#include "utils.h" #define EVT_CORE_MAX_EVENTS 10 diff --git a/src/meas_lat.c b/src/meas_lat.c index 972be87..96e866e 100644 --- a/src/meas_lat.c +++ b/src/meas_lat.c @@ -7,6 +7,7 @@ #include "evt_core.h" #include "net_tools.h" #include "socks5.h" +#include "utils.h" struct measlat_ctx { int count, size, interval, verbose; @@ -55,7 +56,6 @@ int on_udp_err(struct evt_core_ctx* ctx, struct evt_core_fdinfo* fdinfo) { int on_udp(struct evt_core_ctx* ctx, struct evt_core_fdinfo* fdinfo) { ssize_t res; - int secs, nsecs; uint64_t micro_sec; struct timespec curr; struct measure_conf* mc = fdinfo->other; @@ -71,9 +71,7 @@ int on_udp(struct evt_core_ctx* ctx, struct evt_core_fdinfo* fdinfo) { exit(EXIT_FAILURE); } - secs = curr.tv_sec - head->emit_time.tv_sec; - nsecs = curr.tv_nsec - head->emit_time.tv_nsec; - micro_sec = secs * 1000000 + nsecs / 1000; + micro_sec = elapsed_micros (&head->emit_time, &curr); printf("Packet %llu latency %luµs\n", (unsigned long long)head->counter, micro_sec); if (head->counter >= mc->max_measure) { diff --git a/src/utils.c b/src/utils.c index 287d820..e178480 100644 --- a/src/utils.c +++ b/src/utils.c @@ -80,3 +80,15 @@ int ring_le(uint16_t v1, uint16_t v2) { int ring_lt(uint16_t v1, uint16_t v2) { return ring_gt(v2, v1); } + +uint64_t elapsed_micros(struct timespec* t1, struct timespec* t2) { + int secs, nsecs; + uint64_t micro_sec; + + secs = t2->tv_sec - t1->tv_sec; + nsecs = t2->tv_nsec - t1->tv_nsec; + micro_sec = secs * 1000000 + nsecs / 1000; + + return micro_sec; +} + diff --git a/src/utils.h b/src/utils.h index 4aba838..026255f 100644 --- a/src/utils.h +++ b/src/utils.h @@ -23,3 +23,5 @@ int ring_gt(uint16_t v1, uint16_t v2); int ring_ge(uint16_t v1, uint16_t v2); int ring_lt(uint16_t v1, uint16_t v2); int ring_le(uint16_t v1, uint16_t v2); + +uint64_t elapsed_micros(struct timespec* t1, struct timespec* t2);