[sheepdog] [PATCH 10/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/thread_check.c |   42 ++++++++++++++++++++++++++++++++++++++++++
 sheep/trace/graph.c  |    8 --------
 sheep/trace/trace.h  |    8 ++++++++
 3 files changed, 50 insertions(+), 8 deletions(-)

diff --git a/sheep/thread_check.c b/sheep/thread_check.c
index 8a63b0d..39ad25b 100644
--- a/sheep/thread_check.c
+++ b/sheep/thread_check.c
@@ -12,6 +12,47 @@
 #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 event_handler_tracer = {
+	.name = "event handler",
+
+	.enter = event_handler_enter,
+	.exit = event_handler_exit,
+};
+
 static void thread_check_enter(const struct caller *this_fn, int depth)
 {
 	if (strcmp(this_fn->section, MAIN_FN_SECTION) == 0) {
@@ -33,5 +74,6 @@ static struct tracer thread_check_tracer = {
 
 void register_thread_checker(void)
 {
+	trace_register(&event_handler_tracer);
 	trace_register(&thread_check_tracer);
 }
diff --git a/sheep/trace/graph.c b/sheep/trace/graph.c
index 0ab34d6..becea09 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.h b/sheep/trace/trace.h
index dc85298..f097984 100644
--- a/sheep/trace/trace.h
+++ b/sheep/trace/trace.h
@@ -63,5 +63,13 @@ unsigned long trace_return_call(void);
 int trace_register(struct tracer *tracer);
 int trace_unregister(struct 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