Skip to content

Add a new --enable-event-tracker configure option #8179

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
masaori335 merged 1 commit into from
Feb 13, 2022
Merged

Add a new --enable-event-tracker configure option #8179

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
12 changes: 12 additions & 0 deletions configure.ac
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -175,6 +175,13 @@ AC_ARG_ENABLE([all-asserts],
)
AC_MSG_RESULT([$enable_all_asserts])

AC_MSG_CHECKING([whether to enable event tracker])
AC_ARG_ENABLE([event-tracker],
[AS_HELP_STRING([--enable-event-tracker],[turn on event tracker])],
[],
[enable_event_tracker=no]
)
AC_MSG_RESULT([$enable_event_tracker])

# Enable code coverage instrumentation only if requested by the user.
AC_MSG_CHECKING([whether to code coverage])
Expand Down Expand Up @@ -973,10 +980,15 @@ fi
if test "x${enable_mime_sanity_check}" = "xyes"; then
TS_ADDTO(AM_CPPFLAGS, [-DENABLE_MIME_SANITY_CHECK])
fi

if test "x${enable_all_asserts}" = "xyes"; then
TS_ADDTO(AM_CPPFLAGS, [-DENABLE_ALL_ASSERTS])
fi

if test "x${enable_event_tracker}" = "xyes"; then
TS_ADDTO(AM_CPPFLAGS, [-DENABLE_EVENT_TRACKER])
fi

# Flags for ASAN
if test "x${enable_asan}" = "xyes"; then
if test "x${enable_tsan}" = "xyes" -o "x${enable_tsan}" = "xstatic"; then
Expand Down
7 changes: 7 additions & 0 deletions include/tscore/ink_stack_trace.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -29,8 +29,15 @@
#ifdef __cplusplus
extern "C" {
#endif

/* dumps the current back trace to stderr */
void ink_stack_trace_dump();

/**
Get symbol of @n-th frame
*/
const void *ink_backtrace(const int n);

#ifdef __cplusplus
}
#endif
13 changes: 13 additions & 0 deletions iocore/eventsystem/I_Event.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -200,6 +200,11 @@ class Event : public Action
// inherited from Action::cancel
// virtual void cancel(Continuation * c = nullptr);

#ifdef ENABLE_EVENT_TRACKER
void set_location();
const void *get_location() const;
#endif

void free();

EThread *ethread = nullptr;
Expand Down Expand Up @@ -239,6 +244,14 @@ class Event : public Action
private:
void *operator new(size_t size); // use the fast allocators

#ifdef ENABLE_EVENT_TRACKER
/**
Address of who scheduled this event
To get symbols, use backtrace_symbols(3) or external tools like `addr2line(1)` (Linux) or `atos(1)`(BSD).
*/
const void *_location = nullptr;
#endif

public:
LINK(Event, link);

Expand Down
57 changes: 49 additions & 8 deletions iocore/eventsystem/P_UnixEThread.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -32,14 +32,20 @@

#include "I_EThread.h"
#include "I_EventProcessor.h"
#include <execinfo.h>

const ink_hrtime DELAY_FOR_RETRY = HRTIME_MSECONDS(10);
extern ink_thread_key ethread_key;

TS_INLINE Event *
EThread::schedule_imm(Continuation *cont, int callback_event, void *cookie)
{
Event *e = ::eventAllocator.alloc();
Event *e = ::eventAllocator.alloc();

#ifdef ENABLE_EVENT_TRACKER
e->set_location();
#endif

e->callback_event = callback_event;
e->cookie = cookie;
return schedule(e->init(cont, 0, 0));
Expand All @@ -48,7 +54,12 @@ EThread::schedule_imm(Continuation *cont, int callback_event, void *cookie)
TS_INLINE Event *
EThread::schedule_at(Continuation *cont, ink_hrtime t, int callback_event, void *cookie)
{
Event *e = ::eventAllocator.alloc();
Event *e = ::eventAllocator.alloc();

#ifdef ENABLE_EVENT_TRACKER
e->set_location();
#endif

e->callback_event = callback_event;
e->cookie = cookie;
return schedule(e->init(cont, t, 0));
Expand All @@ -57,7 +68,12 @@ EThread::schedule_at(Continuation *cont, ink_hrtime t, int callback_event, void
TS_INLINE Event *
EThread::schedule_in(Continuation *cont, ink_hrtime t, int callback_event, void *cookie)
{
Event *e = ::eventAllocator.alloc();
Event *e = ::eventAllocator.alloc();

#ifdef ENABLE_EVENT_TRACKER
e->set_location();
#endif

e->callback_event = callback_event;
e->cookie = cookie;
return schedule(e->init(cont, get_hrtime() + t, 0));
Expand All @@ -66,7 +82,12 @@ EThread::schedule_in(Continuation *cont, ink_hrtime t, int callback_event, void
TS_INLINE Event *
EThread::schedule_every(Continuation *cont, ink_hrtime t, int callback_event, void *cookie)
{
Event *e = ::eventAllocator.alloc();
Event *e = ::eventAllocator.alloc();

#ifdef ENABLE_EVENT_TRACKER
e->set_location();
#endif

e->callback_event = callback_event;
e->cookie = cookie;
if (t < 0) {
Expand Down Expand Up @@ -108,7 +129,12 @@ EThread::schedule(Event *e)
TS_INLINE Event *
EThread::schedule_imm_local(Continuation *cont, int callback_event, void *cookie)
{
Event *e = EVENT_ALLOC(eventAllocator, this);
Event *e = EVENT_ALLOC(eventAllocator, this);

#ifdef ENABLE_EVENT_TRACKER
e->set_location();
#endif

e->callback_event = callback_event;
e->cookie = cookie;
return schedule_local(e->init(cont, 0, 0));
Expand All @@ -117,7 +143,12 @@ EThread::schedule_imm_local(Continuation *cont, int callback_event, void *cookie
TS_INLINE Event *
EThread::schedule_at_local(Continuation *cont, ink_hrtime t, int callback_event, void *cookie)
{
Event *e = EVENT_ALLOC(eventAllocator, this);
Event *e = EVENT_ALLOC(eventAllocator, this);

#ifdef ENABLE_EVENT_TRACKER
e->set_location();
#endif

e->callback_event = callback_event;
e->cookie = cookie;
return schedule_local(e->init(cont, t, 0));
Expand All @@ -126,7 +157,12 @@ EThread::schedule_at_local(Continuation *cont, ink_hrtime t, int callback_event,
TS_INLINE Event *
EThread::schedule_in_local(Continuation *cont, ink_hrtime t, int callback_event, void *cookie)
{
Event *e = EVENT_ALLOC(eventAllocator, this);
Event *e = EVENT_ALLOC(eventAllocator, this);

#ifdef ENABLE_EVENT_TRACKER
e->set_location();
#endif

e->callback_event = callback_event;
e->cookie = cookie;
return schedule_local(e->init(cont, get_hrtime() + t, 0));
Expand All @@ -135,7 +171,12 @@ EThread::schedule_in_local(Continuation *cont, ink_hrtime t, int callback_event,
TS_INLINE Event *
EThread::schedule_every_local(Continuation *cont, ink_hrtime t, int callback_event, void *cookie)
{
Event *e = EVENT_ALLOC(eventAllocator, this);
Event *e = EVENT_ALLOC(eventAllocator, this);

#ifdef ENABLE_EVENT_TRACKER
e->set_location();
#endif

e->callback_event = callback_event;
e->cookie = cookie;
if (t < 0) {
Expand Down
20 changes: 20 additions & 0 deletions iocore/eventsystem/P_UnixEventProcessor.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -135,6 +135,11 @@ EventProcessor::schedule_imm(Continuation *cont, EventType et, int callback_even
#ifdef ENABLE_TIME_TRACE
e->start_time = Thread::get_hrtime();
#endif

#ifdef ENABLE_EVENT_TRACKER
e->set_location();
#endif

e->callback_event = callback_event;
e->cookie = cookie;
return schedule(e->init(cont, 0, 0), et);
Expand All @@ -147,6 +152,11 @@ EventProcessor::schedule_at(Continuation *cont, ink_hrtime t, EventType et, int

ink_assert(t > 0);
ink_assert(et < MAX_EVENT_TYPES);

#ifdef ENABLE_EVENT_TRACKER
e->set_location();
#endif

e->callback_event = callback_event;
e->cookie = cookie;
return schedule(e->init(cont, t, 0), et);
Expand All @@ -158,6 +168,11 @@ EventProcessor::schedule_in(Continuation *cont, ink_hrtime t, EventType et, int
Event *e = eventAllocator.alloc();

ink_assert(et < MAX_EVENT_TYPES);

#ifdef ENABLE_EVENT_TRACKER
e->set_location();
#endif

e->callback_event = callback_event;
e->cookie = cookie;
return schedule(e->init(cont, Thread::get_hrtime() + t, 0), et);
Expand All @@ -170,6 +185,11 @@ EventProcessor::schedule_every(Continuation *cont, ink_hrtime t, EventType et, i

ink_assert(t != 0);
ink_assert(et < MAX_EVENT_TYPES);

#ifdef ENABLE_EVENT_TRACKER
e->set_location();
#endif

e->callback_event = callback_event;
e->cookie = cookie;
if (t < 0) {
Expand Down
18 changes: 18 additions & 0 deletions iocore/eventsystem/UnixEvent.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -29,6 +29,8 @@
*****************************************************************************/
#include "P_EventSystem.h"

#include "tscore/ink_stack_trace.h"

ClassAllocator<Event> eventAllocator("eventAllocator", 256);

void
Expand Down Expand Up @@ -104,3 +106,19 @@ Event::schedule_every(ink_hrtime aperiod, int acallback_event)
ethread->EventQueueExternal.enqueue_local(this);
}
}

#ifdef ENABLE_EVENT_TRACKER

void
Event::set_location()
{
_location = ink_backtrace(3);
Copy link
Contributor Author

@masaori335 masaori335 Aug 3, 2021 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This is doing pretty tricky. Assuming this is called by schedule_* functions to record where they're called (the 3rd frame of the call stack).

Copy link
Member

@rob05c rob05c Feb 10, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Any idea how performant this is? I.e. is it going to significantly impact how much traffic a production cache can take, and/or TTMS? Or is it very small, could we just leave this on in Production?

Copy link
Member

@rob05c rob05c Feb 10, 2022 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

the 3rd frame of the call stack

Yeah, the whole "3" thing is awkward, but that's pretty common when looking back on the stack. It seems fragile, but it's also unlikely to change. Meh.

Copy link
Contributor Author

@masaori335 masaori335 Feb 11, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I though backtrace(3) doesn't have noticeable overhead. Because it just refers address of current call stack. I'll measure on/off at production.
https://man7.org/linux/man-pages/man3/backtrace.3.html

Copy link
Member

@rob05c rob05c Feb 11, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Ah, excellent. I was just curious. It's still very useful in debug mode, but there's so much more we can do if we can just leave it on all the time.

}

const void *
Event::get_location() const
Copy link
Member

@rob05c rob05c Feb 10, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I don't see anything calling get_location. Does anything use the location yet? Or is the plan to do that in a future PR?

Copy link
Contributor Author

@masaori335 masaori335 Feb 11, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Right. It's just the buddy of set_location for now.
A possible use case is printing the location on debug log instead of using add2line command.

{
return _location;
}

#endif
25 changes: 25 additions & 0 deletions src/tscore/ink_stack_trace.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -66,6 +66,25 @@ ink_stack_trace_dump()
}
}

const void *
ink_backtrace(const int n)
{
if (INK_STACK_TRACE_MAX_LEVELS < n + 1) {
return nullptr;
}

const int m = n + 1;
void *callstack[m];
int frames = backtrace(callstack, m);

const void *symbol = nullptr;
if (frames == m && callstack[n] != nullptr) {
symbol = callstack[n];
}

return symbol;
}

#else /* !TS_HAS_BACKTRACE */

void
Expand All @@ -76,4 +95,10 @@ ink_stack_trace_dump()
return;
}

const void *
ink_backtrace(const int /* n */)
{
return nullptr;
}

#endif /* TS_HAS_BACKTRACE */