On Mar 11, 2014, at 2:01 PM, Brian Geffon <[email protected]> wrote:
> Hi all,
> There has been discussion on IRC about techniques for following requests
> across events. I've slapped together a simple patch that attaches
> backtraces to Continuations every time an event is scheduled. Since some
> people may find this useful I wanted to "archive" it via the mailing list.
> If it's very useful we can consider cleaning it up and adding it to master
> via autoconf.
This sounds like a potential candidate for inclusion with debug builds ?
— Leif
>
> Brian
>
>
> Example via gdb:
> (gdb) p *((Continuation*)(contp)).bt@
> ((Continuation*)(contp))->current_bt_size
> $10 = {0x4cc0f3 <EventProcessor::schedule(Event*, int, bool)+231>, 0x4cc279
> <EventProcessor::schedule_imm(Continuation*, int, int, void*)+153>,
> 0x4f2209 <INKVConnInternal::reenable(VIO*)+97>, 0x50a893
> <VIO::reenable()+63>, 0x5b6061 <HttpTunnel::producer_handler(int,
> HttpTunnelProducer*)+1213>, 0x5b568e
> <HttpTunnel::producer_run(HttpTunnelProducer*)+2732>, 0x5b4b1b
> <HttpTunnel::tunnel_run(HttpTunnelProducer*)+155>, 0x57c46c
> <HttpSM::set_next_state()+3450>, 0x57b6eb
> <HttpSM::call_transact_and_set_next_state(void
> (*)(HttpTransact::State*))+439>, 0x56883f
> <HttpSM::handle_api_return()+313>, 0x568613 <HttpSM::state_api_callout(int,
> void*)+2185>, 0x567d0f <HttpSM::state_api_callback(int, void*)+419>,
> 0x4fd83c <TSHttpTxnReenable(TSHttpTxn, TSEvent)+386>, 0x7ffff302814c
> <(anonymous namespace)::handleGlobalPluginEvents(TSCont, TSEvent,
> void*)+92>, 0x4f1a94 <INKContInternal::handle_event(int, void*)+176>,
> 0x4e8d82 <Continuation::handleEvent(int, void*)+108>, ...}
>
>
>
> diff --git a/iocore/eventsystem/I_Continuation.h
> b/iocore/eventsystem/I_Continuation.h
> index 1de095b..cd8c297 100644
> --- a/iocore/eventsystem/I_Continuation.h
> +++ b/iocore/eventsystem/I_Continuation.h
> @@ -56,6 +56,20 @@ class EThread;
> #define CONTINUATION_DONE 0
> #define CONTINUATION_CONT 1
>
> +#ifndef CROSS_EVENT_STACK_TRACES
> +#define CROSS_EVENT_STACK_TRACES
> +#endif
> +
> +#ifdef CROSS_EVENT_STACK_TRACES
> +#ifdef __GNUG__
> +#define CROSS_EVENT_STACK_TRACES_ALWAYS_INLINE inline
> __attribute__((always_inline))
> +#else
> +#define CROSS_EVENT_STACK_TRACES_ALWAYS_INLINE inline
> +#endif
> +#include <execinfo.h>
> +#define BT_LIMIT_PER_EVENT 128
> +#endif
> +
> typedef int (Continuation::*ContinuationHandler) (int event, void *data);
>
> class force_VFPT_to_top
> @@ -93,6 +107,27 @@ public:
>
> class Continuation: private force_VFPT_to_top
> {
> +#ifdef CROSS_EVENT_STACK_TRACES
> +public:
> + size_t current_bt_size;
> + size_t max_bt_size;
> + void **bt;
> +
> + void CROSS_EVENT_STACK_TRACES_ALWAYS_INLINE attach_current_stack_trace()
> {
> + if (max_bt_size < (current_bt_size + BT_LIMIT_PER_EVENT)) {
> + // we need more space so we can attach at least BT_LIMIT_PER_EVENT
> pointers
> + if (max_bt_size == 0) {
> + max_bt_size = BT_LIMIT_PER_EVENT;
> + bt = static_cast<void**>(ats_malloc(sizeof(void *) * max_bt_size));
> + } else {
> + max_bt_size <<= 1;
> + bt = static_cast<void **>(ats_realloc(bt, sizeof(void *) *
> max_bt_size));
> + }
> + }
> + current_bt_size += backtrace (bt + current_bt_size,
> BT_LIMIT_PER_EVENT);
> + }
> +private:
> +#endif
> public:
>
> /**
> @@ -167,9 +202,14 @@ public:
> #define SET_HANDLER(_h) \
> (handler = ((ContinuationHandler)_h),handler_name = #_h)
> #else
> +#ifdef CROSS_EVENT_STACK_TRACES
> +#define SET_HANDLER(_h) \
> + (handler = ((ContinuationHandler)_h), current_bt_size = 0)
> +#else
> #define SET_HANDLER(_h) \
> (handler = ((ContinuationHandler)_h))
> #endif
> +#endif
>
> /**
> Sets a Continuation's handler.
> @@ -184,13 +224,22 @@ public:
> #define SET_CONTINUATION_HANDLER(_c,_h) \
> (_c->handler = ((ContinuationHandler) _h),_c->handler_name = #_h)
> #else
> +#ifdef CROSS_EVENT_STACK_TRACES
> #define SET_CONTINUATION_HANDLER(_c,_h) \
> - (_c->handler = ((ContinuationHandler) _h))
> + (_c->handler = ((ContinuationHandler) _h), _c->current_bt_size = 0);
> +#else
> +#define SET_CONTINUATION_HANDLER(_c,_h) \
> + (_c->handler = ((ContinuationHandler) _h));
> +#endif
> #endif
>
> inline
> Continuation::Continuation(ProxyMutex * amutex)
> - : handler(NULL),
> + :
> +#ifdef CROSS_EVENT_STACK_TRACES
> + current_bt_size(0), max_bt_size(0), bt(NULL),
> +#endif
> +handler(NULL),
> #ifdef DEBUG
> handler_name(NULL),
> #endif
> diff --git a/iocore/eventsystem/P_UnixEThread.h
> b/iocore/eventsystem/P_UnixEThread.h
> index 462de69..1f2c4e7 100644
> --- a/iocore/eventsystem/P_UnixEThread.h
> +++ b/iocore/eventsystem/P_UnixEThread.h
> @@ -91,6 +91,9 @@ EThread::schedule_every(Continuation * cont, ink_hrtime
> t, int callback_event, v
> TS_INLINE Event *
> EThread::schedule(Event * e, bool fast_signal)
> {
> +#ifdef CROSS_EVENT_STACK_TRACES
> + e->continuation->attach_current_stack_trace();
> +#endif
> e->ethread = this;
> ink_assert(tt == REGULAR);
> if (e->continuation->mutex)
> @@ -141,6 +144,9 @@ EThread::schedule_every_local(Continuation * cont,
> ink_hrtime t, int callback_ev
> TS_INLINE Event *
> EThread::schedule_local(Event * e)
> {
> +#ifdef CROSS_EVENT_STACK_TRACES
> + e->continuation->attach_current_stack_trace();
> +#endif
> if (tt != REGULAR) {
> ink_assert(tt == DEDICATED);
> return eventProcessor.schedule(e, ET_CALL);
> diff --git a/iocore/eventsystem/P_UnixEventProcessor.h
> b/iocore/eventsystem/P_UnixEventProcessor.h
> index d9a1e73..bae525e 100644
> --- a/iocore/eventsystem/P_UnixEventProcessor.h
> +++ b/iocore/eventsystem/P_UnixEventProcessor.h
> @@ -74,6 +74,9 @@ EventProcessor::assign_thread(EventType etype)
> TS_INLINE Event *
> EventProcessor::schedule(Event * e, EventType etype, bool fast_signal)
> {
> +#ifdef CROSS_EVENT_STACK_TRACES
> + e->continuation->attach_current_stack_trace();
> +#endif
> ink_assert(etype < MAX_EVENT_TYPES);
> e->ethread = assign_thread(etype);
> if (e->continuation->mutex)
> diff --git a/iocore/eventsystem/UnixEvent.cc
> b/iocore/eventsystem/UnixEvent.cc
> index 634cee9..17ecfbf 100644
> --- a/iocore/eventsystem/UnixEvent.cc
> +++ b/iocore/eventsystem/UnixEvent.cc
> @@ -34,6 +34,9 @@ ClassAllocator<Event> eventAllocator("eventAllocator",
> 256);
> void
> Event::schedule_imm(int acallback_event)
> {
> +#ifdef CROSS_EVENT_STACK_TRACES
> + continuation->attach_current_stack_trace();
> +#endif
> callback_event = acallback_event;
> ink_assert(ethread == this_ethread());
> if (in_the_priority_queue)
> @@ -49,6 +52,9 @@ Event::schedule_imm(int acallback_event)
> void
> Event::schedule_at(ink_hrtime atimeout_at, int acallback_event)
> {
> +#ifdef CROSS_EVENT_STACK_TRACES
> + continuation->attach_current_stack_trace();
> +#endif
> callback_event = acallback_event;
> ink_assert(ethread == this_ethread());
> ink_assert(atimeout_at > 0);
> @@ -65,6 +71,9 @@ Event::schedule_at(ink_hrtime atimeout_at, int
> acallback_event)
> void
> Event::schedule_in(ink_hrtime atimeout_in, int acallback_event)
> {
> +#ifdef CROSS_EVENT_STACK_TRACES
> + continuation->attach_current_stack_trace();
> +#endif
> callback_event = acallback_event;
> ink_assert(ethread == this_ethread());
> if (in_the_priority_queue)
> @@ -80,6 +89,9 @@ Event::schedule_in(ink_hrtime atimeout_in, int
> acallback_event)
> void
> Event::schedule_every(ink_hrtime aperiod, int acallback_event)
> {
> +#ifdef CROSS_EVENT_STACK_TRACES
> + continuation->attach_current_stack_trace();
> +#endif
> callback_event = acallback_event;
> ink_assert(ethread == this_ethread());
> ink_assert(aperiod != 0);
