From: MORITA Kazutaka <morita.kazutaka at lab.ntt.co.jp> We shouldn't spend too much time in the main thread. This checker prints a warning message when sheep uses more than 1 ms in the main thread. Signed-off-by: MORITA Kazutaka <morita.kazutaka at lab.ntt.co.jp> --- sheep/trace/checker.c | 43 +++++++++++++++++++++++++++++++++++++++++++ sheep/trace/graph.c | 8 -------- sheep/trace/trace.c | 1 + sheep/trace/trace.h | 8 ++++++++ 4 files changed, 52 insertions(+), 8 deletions(-) diff --git a/sheep/trace/checker.c b/sheep/trace/checker.c index 1c095ef..90c8948 100644 --- a/sheep/trace/checker.c +++ b/sheep/trace/checker.c @@ -12,6 +12,49 @@ #include "sheep_priv.h" #include "trace/trace.h" +#define MAX_EVENT_DURATION 1000 /* us */ +static int event_handler_depth = -1; +static uint64_t start_time; + +static void event_handler_enter(const struct caller *this_fn, int depth) +{ + if (!is_main_thread()) + return; + + if (event_handler_depth < 0) { + if (strcmp(this_fn->name, "do_event_loop") == 0) + event_handler_depth = depth + 1; + } + + if (depth == event_handler_depth) + start_time = clock_get_time(); +} + +static void event_handler_exit(const struct caller *this_fn, int depth) +{ + if (!is_main_thread()) + return; + + if (depth == event_handler_depth) { + uint64_t duration = clock_get_time() - start_time; + unsigned quot = duration / 1000, rem = duration % 1000; + + if (quot > MAX_EVENT_DURATION) + sd_printf(SDOG_WARNING, + "%s wastes too much time in event loop: " + "%u.%-3u us", this_fn->name, quot, rem); + } +} + +static struct tracer loop_checker = { + .name = "loop_checker", + + .enter = event_handler_enter, + .exit = event_handler_exit, +}; + +tracer_register(loop_checker); + static void thread_check_enter(const struct caller *this_fn, int depth) { if (strcmp(this_fn->section, MAIN_FN_SECTION) == 0) { diff --git a/sheep/trace/graph.c b/sheep/trace/graph.c index f3f0858..33c6365 100644 --- a/sheep/trace/graph.c +++ b/sheep/trace/graph.c @@ -15,14 +15,6 @@ static __thread unsigned long long entry_time[SD_MAX_STACK_DEPTH]; -static uint64_t clock_get_time(void) -{ - struct timespec ts; - - clock_gettime(CLOCK_REALTIME, &ts); - return (uint64_t)ts.tv_sec * 1000000000LL + (uint64_t)ts.tv_nsec; -} - static void graph_tracer_exit(const struct caller *this_fn, int depth) { struct trace_graph_item trace = { diff --git a/sheep/trace/trace.c b/sheep/trace/trace.c index dd7fa69..883c9ee 100644 --- a/sheep/trace/trace.c +++ b/sheep/trace/trace.c @@ -377,6 +377,7 @@ int trace_init(void) #ifdef DEBUG trace_enable("thread_checker"); + trace_enable("loop_checker"); #endif nr_cpu = sysconf(_SC_NPROCESSORS_ONLN); diff --git a/sheep/trace/trace.h b/sheep/trace/trace.h index 7db7053..9912fd2 100644 --- a/sheep/trace/trace.h +++ b/sheep/trace/trace.h @@ -60,5 +60,13 @@ regist_ ##tracer(void) \ regist_tracer(&tracer); \ } +static inline uint64_t clock_get_time(void) +{ + struct timespec ts; + + clock_gettime(CLOCK_REALTIME, &ts); + return (uint64_t)ts.tv_sec * 1000000000LL + (uint64_t)ts.tv_nsec; +} + #endif /* __ASSEMBLY__ */ #endif -- 1.7.9.5 |