From 22515955510f174e130abaea6ca0a6544a71a752 Mon Sep 17 00:00:00 2001 From: Jason Volk Date: Sun, 25 Sep 2016 15:46:54 -0700 Subject: [PATCH] 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 | 24 ++----- include/ircd/ctx_prof.h | 70 +++++++++++++++++++ include/ircd/stdinc.h | 2 + ircd/ctx.cc | 146 +++++++++++++++++++++++++++++++++++++--- 4 files changed, 212 insertions(+), 30 deletions(-) create mode 100644 include/ircd/ctx_prof.h diff --git a/include/ircd/ctx_ctx.h b/include/ircd/ctx_ctx.h index 83bacb1ed..57100983e 100644 --- a/include/ircd/ctx_ctx.h +++ b/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; diff --git a/include/ircd/ctx_prof.h b/include/ircd/ctx_prof.h new file mode 100644 index 000000000..f5f3e0ccc --- /dev/null +++ b/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 + * + * 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 diff --git a/include/ircd/stdinc.h b/include/ircd/stdinc.h index 767e1e0fa..7e18e1693 100644 --- a/include/ircd/stdinc.h +++ b/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" diff --git a/ircd/ctx.cc b/ircd/ctx.cc index 1942ca426..99d1d548d 100644 --- a/ircd/ctx.cc +++ b/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(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(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)); +}