[sheepdog] [PATCH v2 09/10] sheep: add event_loop checker

[MORITA Kazutaka]

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 d7531c5..7cebf4b 100644
--- a/sheep/trace/trace.c
+++ b/sheep/trace/trace.c
@@ -375,6 +375,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 534c3a7..f043b2b 100644
--- a/sheep/trace/trace.h
+++ b/sheep/trace/trace.h
@@ -67,5 +67,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