ircd::ctx: Add preliminary profiling system to mitigate silent degradation.

This system alerts the developer when something blocks a context from yielding
for too long or exceeds stack usage limits. More profiling can be added for
further optimization.

include/ircd/ctx_ctx.h

@@ -55,10 +55,6 @@ struct ctx
 	ctx(const ctx &) = delete;
 };
 
-size_t stack_usage_here(const ctx &) __attribute__((noinline));
-bool stack_warning(const ctx &, const double &pct = 0.80);
-void stack_assertion(const ctx &, const double &pct = 0.80);
-
 struct continuation
 {
 	ctx *self;
@@ -74,9 +70,9 @@ inline
 continuation::continuation(ctx *const &self)
 :self{self}
 {
+	mark(prof::event::CUR_YIELD);
 	assert(self != nullptr);
 	assert(self->notes <= 1);
-	stack_assertion(*self);
 	ircd::ctx::current = nullptr;
 }
 
@@ -85,6 +81,7 @@ continuation::~continuation()
 noexcept
 {
 	ircd::ctx::current = self;
+	mark(prof::event::CUR_CONTINUE);
 	self->notes = 1;
 }
 
@@ -101,20 +98,6 @@ const
 	return *self->yc;
 }
 
-inline void
-stack_assertion(const ctx &ctx,
-                const double &pct)
-{
-	assert(!stack_warning(ctx, pct));
-}
-
-inline bool
-stack_warning(const ctx &ctx,
-              const double &pct)
-{
-	return stack_usage_here(ctx) > double(ctx.stack_max) * pct;
-}
-
 inline bool
 ctx::note()
 {
@@ -151,7 +134,10 @@ ctx::wait()
 	// Interruption shouldn't be used for normal operation,
 	// so please eat this branch misprediction.
 	if(unlikely(flags & INTERRUPTED))
+	{
+		mark(prof::event::CUR_INTERRUPT);
 		throw interrupted("ctx(%p)::wait()", (const void *)this);
+	}
 
 	// notes = 1; set by continuation dtor on wakeup
 	return true;

include/ircd/ctx_prof.h

@@ -0,0 +1,70 @@
+/*
+ * charybdis: oh just a little chat server
+ *
+ * Copyright (C) 2016 Charybdis Development Team
+ * Copyright (C) 2016 Jason Volk <jason@zemos.net>
+ *
+ * Permission to use, copy, modify, and/or distribute this software for any
+ * purpose with or without fee is hereby granted, provided that the above
+ * copyright notice and this permission notice is present in all copies.
+ *
+ * THIS SOFTWARE IS PROVIDED BY THE AUTHOR ``AS IS'' AND ANY EXPRESS OR
+ * IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO, THE IMPLIED
+ * WARRANTIES OF MERCHANTABILITY AND FITNESS FOR A PARTICULAR PURPOSE ARE
+ * DISCLAIMED. IN NO EVENT SHALL THE AUTHOR BE LIABLE FOR ANY DIRECT,
+ * INDIRECT, INCIDENTAL, SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES
+ * (INCLUDING, BUT NOT LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR
+ * SERVICES; LOSS OF USE, DATA, OR PROFITS; OR BUSINESS INTERRUPTION)
+ * HOWEVER CAUSED AND ON ANY THEORY OF LIABILITY, WHETHER IN CONTRACT,
+ * STRICT LIABILITY, OR TORT (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING
+ * IN ANY WAY OUT OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE
+ * POSSIBILITY OF SUCH DAMAGE.
+ */
+
+#pragma once
+#define HAVE_IRCD_CTX_PROF_H
+
+/* Profiling for the context system. These facilities provide tools and statistics.
+ * The primary purpose here is to alert developers of unwanted context behavior, in
+ * addition to optimizing the overall performance of the context system.
+ *
+ * The original use case is for the embedded database backend. Function calls are made which may
+ * conduct blocking I/O before returning. This will hang the current userspace context while it
+ * is running and thus BLOCK EVERY CONTEXT in the entire IRCd. Since this is still an asynchronous
+ * system, it just doesn't have callbacks: we do not do I/O without a cooperative yield.
+ * Fortunately there are mechanisms to mitigate this -- but we have to know for sure. A database
+ * call which has been passed over for mitigation may start doing some blocking flush under load,
+ * etc. The profiler will alert us of this so it doesn't silently degrade performance.
+ */
+namespace ircd {
+namespace ctx  {
+namespace prof {
+
+struct settings
+{
+	double stack_usage_warning;       // percentage
+	double stack_usage_assertion;     // percentage
+
+	microseconds slice_warning;       // Warn when the yield-to-yield time exceeds
+	microseconds slice_interrupt;     // Interrupt exception when exceeded (not a signal)
+	microseconds slice_assertion;     // abort() when exceeded (not a signal, must yield)
+}
+extern settings;
+
+enum class event
+{
+	SPAWN,             // Context spawn requested
+	JOIN,              // Context join requested
+	JOINED,            // Context join completed
+	CUR_ENTER,         // Current context entered
+	CUR_LEAVE,         // Current context leaving
+	CUR_YIELD,         // Current context yielding
+	CUR_CONTINUE,      // Current context continuing
+	CUR_INTERRUPT,     // Current context detects interruption
+};
+
+void mark(const event &);
+
+} // namespace prof	
+} // namespace ctx
+} // namespace ircd

include/ircd/stdinc.h

@@ -47,6 +47,7 @@ namespace ircd
 	using std::chrono::seconds;
 	using std::chrono::milliseconds;
 	using std::chrono::microseconds;
+	using std::chrono::duration_cast;
 	using ostream = std::ostream;
 	namespace ph = std::placeholders;
 	using namespace std::string_literals;
@@ -89,6 +90,7 @@ namespace ircd
 #include "mode_lease.h"
 #include "snomask.h"
 #include "ctx.h"
+#include "ctx_prof.h"
 #include "ctx_dock.h"
 #include "ctx_mutex.h"
 #include "ctx_shared_state.h"

ircd/ctx.cc

@@ -92,6 +92,10 @@ ircd::ctx::context::context(const size_t &stack_sz,
 		ircd::ctx::current = current;
 	});
 
+	// The profiler is told about the spawn request here, not inside the closure
+	// which is probably the same event-slice as event::CUR_ENTER and not as useful.
+	mark(prof::event::SPAWN);
+
 	if(flags & DEFER_POST)
 		ios->post(std::move(spawn));
 	else if(flags & DEFER_DISPATCH)
@@ -134,10 +138,11 @@ ircd::ctx::context::join()
 	if(joined())
 		return;
 
-	// Set the target context to notify this context when it finishes
+	mark(prof::event::JOIN);
 	assert(!c->adjoindre);
-	c->adjoindre = &cur();
+	c->adjoindre = &cur();       // Set the target context to notify this context when it finishes
 	wait();
+	mark(prof::event::JOINED);
 }
 
 ircd::ctx::ctx *
@@ -210,15 +215,17 @@ noexcept
 	notes = 1;
 	stack_base = uintptr_t(__builtin_frame_address(0));
 	ircd::ctx::current = this;
+	mark(prof::event::CUR_ENTER);
 
 	const scope atexit([this]
 	{
-		ircd::ctx::current = nullptr;
-		this->yc = nullptr;
-
 		if(adjoindre)
 			notify(*adjoindre);
 
+		mark(prof::event::CUR_LEAVE);
+		ircd::ctx::current = nullptr;
+		this->yc = nullptr;
+
 		if(flags & SELF_DESTRUCT)
 			delete this;
 	});
@@ -227,12 +234,6 @@ noexcept
 		func();
 }
 
-size_t
-ctx::stack_usage_here(const ctx &ctx)
-{
-	return ctx.stack_base - uintptr_t(__builtin_frame_address(0));
-}
-
 ///////////////////////////////////////////////////////////////////////////////
 //
 // ctx_pool.h
@@ -326,3 +327,126 @@ catch(const std::exception &e)
 	              &cur(),
 	              e.what());
 }
+
+///////////////////////////////////////////////////////////////////////////////
+//
+// ctx_prof.h
+//
+
+namespace ircd {
+namespace ctx  {
+namespace prof {
+
+struct settings settings
+{
+	0.66,        // stack_usage_warning
+	0.87,        // stack_usage_assertion
+
+	5000us,      // slice_warning
+	0us,         // slice_interrupt
+	0us,         // slice_assertion
+};
+
+time_point cur_slice_start;     // Time slice state
+
+size_t stack_usage_here(const ctx &) __attribute__((noinline));
+void check_stack();
+void check_slice();
+void slice_start();
+
+void handle_cur_continue();
+void handle_cur_yield();
+void handle_cur_leave();
+void handle_cur_enter();
+
+} // namespace prof
+} // namespace ctx
+} // namespace ircd
+
+void
+ctx::prof::mark(const event &e)
+{
+	switch(e)
+	{
+		case event::CUR_ENTER:       handle_cur_enter();     break;
+		case event::CUR_LEAVE:       handle_cur_leave();     break;
+		case event::CUR_YIELD:       handle_cur_yield();     break;
+		case event::CUR_CONTINUE:    handle_cur_continue();  break;
+		default:                                             break;
+	}
+}
+
+void
+ctx::prof::handle_cur_enter()
+{
+	slice_start();
+}
+
+void
+ctx::prof::handle_cur_leave()
+{
+	check_slice();
+}
+
+void
+ctx::prof::handle_cur_yield()
+{
+	check_stack();
+	check_slice();
+}
+
+void
+ctx::prof::handle_cur_continue()
+{
+	slice_start();
+}
+
+void
+ctx::prof::slice_start()
+{
+	cur_slice_start = steady_clock::now();
+}
+
+void
+ctx::prof::check_slice()
+{
+	auto &c(cur());
+	const auto time_usage(steady_clock::now() - cur_slice_start);
+	if(unlikely(settings.slice_warning > 0us && time_usage >= settings.slice_warning))
+	{
+		log::warning("CONTEXT TIMESLICE EXCEEDED ctx(%p) last: %06ld microseconds",
+		             (const void *)&c,
+		             duration_cast<microseconds>(time_usage).count());
+
+		assert(settings.slice_assertion == 0us || time_usage < settings.slice_assertion);
+	}
+
+	if(unlikely(settings.slice_interrupt > 0us && time_usage >= settings.slice_interrupt))
+		throw interrupted("ctx(%p): Time slice exceeded (last: %06ld microseconds)",
+		                  (const void *)&c,
+		                  duration_cast<microseconds>(time_usage).count());
+}
+
+void
+ctx::prof::check_stack()
+{
+	auto &c(cur());
+	const double &stack_max(c.stack_max);
+	const auto stack_usage(stack_usage_here(c));
+
+	if(unlikely(stack_usage > stack_max * settings.stack_usage_warning))
+	{
+		log::warning("CONTEXT STACK USAGE ctx(%p) used %zu of %zu bytes",
+		             (const void *)&c,
+		             stack_usage,
+		             c.stack_max);
+
+		assert(stack_usage < c.stack_max * settings.stack_usage_assertion);
+	}
+}
+
+size_t
+ctx::prof::stack_usage_here(const ctx &ctx)
+{
+	return ctx.stack_base - uintptr_t(__builtin_frame_address(0));
+}