From d1d88a28953ae43db430e5b22fcd8d567a306c07 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Ond=C5=99ej=20Sur=C3=BD?= Date: Sat, 26 Mar 2022 14:37:38 +0100 Subject: [PATCH] Add detailed tracing when TASKMGR_TRACE is defined When TASKMGR_TRACE=1 is defined, the task and event objects have detailed tracing information about function, file, line, and backtrace (to the extent tracked by gcc) where it was created. At exit, when there are unfinished tasks, they will be printed along with the detailed information. --- lib/isc/event.c | 9 ++-- lib/isc/include/isc/event.h | 102 +++++++++++++++++++++++++++++------ lib/isc/include/isc/task.h | 23 ++++++-- lib/isc/task.c | 103 ++++++++++++++++++++++++++++++------ 4 files changed, 196 insertions(+), 41 deletions(-) diff --git a/lib/isc/event.c b/lib/isc/event.c index 547c839bb9..294da35254 100644 --- a/lib/isc/event.c +++ b/lib/isc/event.c @@ -31,8 +31,9 @@ destroy(isc_event_t *event) { } isc_event_t * -isc_event_allocate(isc_mem_t *mctx, void *sender, isc_eventtype_t type, - isc_taskaction_t action, void *arg, size_t size) { +isc__event_allocate(isc_mem_t *mctx, void *sender, isc_eventtype_t type, + isc_taskaction_t action, void *arg, + size_t size ISC__EVENT_FLARG) { isc_event_t *event; REQUIRE(size >= sizeof(struct isc_event)); @@ -40,8 +41,8 @@ isc_event_allocate(isc_mem_t *mctx, void *sender, isc_eventtype_t type, event = isc_mem_get(mctx, size); - ISC_EVENT_INIT(event, size, 0, NULL, type, action, arg, sender, destroy, - mctx); + ISC_EVENT_INIT_PASS(event, size, 0, NULL, type, action, arg, sender, + destroy, mctx); return (event); } diff --git a/lib/isc/include/isc/event.h b/lib/isc/include/isc/event.h index 8d7048cd52..c3db540648 100644 --- a/lib/isc/include/isc/event.h +++ b/lib/isc/include/isc/event.h @@ -15,8 +15,11 @@ /*! \file isc/event.h */ +#include #include +#include #include +#include /***** ***** Events. @@ -24,6 +27,62 @@ typedef void (*isc_eventdestructor_t)(isc_event_t *); +#if TASKMGR_TRACE +#define ISC__EVENT_TRACE_SIZE 8 +#define ISC__EVENT_FILELINE , __func__, __FILE__, __LINE__ +#define ISC__EVENT_FLARG , const char *func, const char *file, unsigned int line + +#define ISC_EVENT_COMMON(ltype) \ + size_t ev_size; \ + unsigned int ev_attributes; \ + void *ev_tag; \ + isc_eventtype_t ev_type; \ + isc_taskaction_t ev_action; \ + void *ev_arg; \ + void *ev_sender; \ + isc_eventdestructor_t ev_destroy; \ + void *ev_destroy_arg; \ + void *backtrace[ISC__EVENT_TRACE_SIZE]; \ + int backtrace_size; \ + char func[PATH_MAX]; \ + char file[PATH_MAX]; \ + unsigned int line; \ + ISC_LINK(ltype) ev_link; \ + ISC_LINK(ltype) ev_ratelink + +#define ISC_EVENT_INIT(event, sz, at, ta, ty, ac, ar, sn, df, da) \ + ISC__EVENT_INIT(event, sz, at, ta, ty, ac, ar, sn, df, da, __func__, \ + __FILE__, __LINE__) + +#define ISC_EVENT_INIT_PASS(event, sz, at, ta, ty, ac, ar, sn, df, da) \ + ISC__EVENT_INIT(event, sz, at, ta, ty, ac, ar, sn, df, da, func, file, \ + line) + +#define ISC__EVENT_INIT(event, sz, at, ta, ty, ac, ar, sn, df, da, fn, fl, ln) \ + { \ + (event)->ev_size = (sz); \ + (event)->ev_attributes = (at); \ + (event)->ev_tag = (ta); \ + (event)->ev_type = (ty); \ + (event)->ev_action = (ac); \ + (event)->ev_arg = (ar); \ + (event)->ev_sender = (sn); \ + (event)->ev_destroy = (df); \ + (event)->ev_destroy_arg = (da); \ + ISC_LINK_INIT((event), ev_link); \ + ISC_LINK_INIT((event), ev_ratelink); \ + strlcpy((event)->func, fn, sizeof((event)->func)); \ + strlcpy((event)->file, fl, sizeof((event)->file)); \ + (event)->line = ln; \ + (event)->backtrace_size = isc_backtrace( \ + (event)->backtrace, ISC__EVENT_TRACE_SIZE); \ + } + +#else +#define ISC__EVENT_FILELINE +#define ISC__EVENT_FLARG +#define ISC__EVENT_FLARG_PASS + #define ISC_EVENT_COMMON(ltype) \ size_t ev_size; \ unsigned int ev_attributes; \ @@ -37,6 +96,25 @@ typedef void (*isc_eventdestructor_t)(isc_event_t *); ISC_LINK(ltype) ev_link; \ ISC_LINK(ltype) ev_ratelink +#define ISC_EVENT_INIT(event, sz, at, ta, ty, ac, ar, sn, df, da) \ + { \ + (event)->ev_size = (sz); \ + (event)->ev_attributes = (at); \ + (event)->ev_tag = (ta); \ + (event)->ev_type = (ty); \ + (event)->ev_action = (ac); \ + (event)->ev_arg = (ar); \ + (event)->ev_sender = (sn); \ + (event)->ev_destroy = (df); \ + (event)->ev_destroy_arg = (da); \ + ISC_LINK_INIT((event), ev_link); \ + ISC_LINK_INIT((event), ev_ratelink); \ + } + +#define ISC_EVENT_INIT_PASS ISC_EVENT_INIT + +#endif + /*% * Attributes matching a mask of 0x000000ff are reserved for the task library's * definition. Attributes of 0xffffff00 may be used by the application @@ -52,21 +130,6 @@ typedef void (*isc_eventdestructor_t)(isc_event_t *); */ #define ISC_EVENTATTR_CANCELED 0x00000002 -#define ISC_EVENT_INIT(event, sz, at, ta, ty, ac, ar, sn, df, da) \ - do { \ - (event)->ev_size = (sz); \ - (event)->ev_attributes = (at); \ - (event)->ev_tag = (ta); \ - (event)->ev_type = (ty); \ - (event)->ev_action = (ac); \ - (event)->ev_arg = (ar); \ - (event)->ev_sender = (sn); \ - (event)->ev_destroy = (df); \ - (event)->ev_destroy_arg = (da); \ - ISC_LINK_INIT((event), ev_link); \ - ISC_LINK_INIT((event), ev_ratelink); \ - } while (0) - /*% * This structure is public because "subclassing" it may be useful when * defining new event types. @@ -79,9 +142,14 @@ struct isc_event { ISC_LANG_BEGINDECLS +#define isc_event_allocate(mctx, sender, type, action, arg, size) \ + isc__event_allocate(mctx, sender, type, action, arg, \ + size ISC__EVENT_FILELINE) + isc_event_t * -isc_event_allocate(isc_mem_t *mctx, void *sender, isc_eventtype_t type, - isc_taskaction_t action, void *arg, size_t size); +isc__event_allocate(isc_mem_t *mctx, void *sender, isc_eventtype_t type, + isc_taskaction_t action, void *arg, + size_t size ISC__EVENT_FLARG); /*%< * Allocate an event structure. * diff --git a/lib/isc/include/isc/task.h b/lib/isc/include/isc/task.h index 3a64dad52a..a7ba304413 100644 --- a/lib/isc/include/isc/task.h +++ b/lib/isc/include/isc/task.h @@ -67,6 +67,17 @@ #include #include #include +#include + +#if TASKMGR_TRACE +#define ISC__TASKTRACE_SIZE 8 +#define ISC__TASKFILELINE , __func__, __FILE__, __LINE__ +#define ISC__TASKFLARG , const char *func, const char *file, unsigned int line + +#else +#define ISC__TASKFILELINE +#define ISC__TASKFLARG +#endif #define ISC_TASKEVENT_SHUTDOWN (ISC_EVENTCLASS_TASK + 0) #define ISC_TASKEVENT_TEST (ISC_EVENTCLASS_TASK + 1) @@ -81,12 +92,14 @@ ISC_LANG_BEGINDECLS *** Types ***/ +#define isc_task_create(m, q, t) \ + isc__task_create_bound(m, q, t, -1 ISC__TASKFILELINE) +#define isc_task_create_bound(m, q, t, i) \ + isc__task_create_bound(m, q, t, i ISC__TASKFILELINE) + isc_result_t -isc_task_create(isc_taskmgr_t *manager, unsigned int quantum, - isc_task_t **taskp); -isc_result_t -isc_task_create_bound(isc_taskmgr_t *manager, unsigned int quantum, - isc_task_t **taskp, int tid); +isc__task_create_bound(isc_taskmgr_t *manager, unsigned int quantum, + isc_task_t **taskp, int tid ISC__TASKFLARG); /*%< * Create a task, optionally bound to a particular tid. * diff --git a/lib/isc/task.c b/lib/isc/task.c index fb40c1f7a9..f61b46fd5d 100644 --- a/lib/isc/task.c +++ b/lib/isc/task.c @@ -20,9 +20,11 @@ #include #include +#include #include #include +#include #include #include #include @@ -47,6 +49,7 @@ #include #endif /* HAVE_JSON_C */ +#include "netmgr/uv-compat.h" #include "task_p.h" /* @@ -95,6 +98,11 @@ static const char *statenames[] = { #define TASK_MAGIC ISC_MAGIC('T', 'A', 'S', 'K') #define VALID_TASK(t) ISC_MAGIC_VALID(t, TASK_MAGIC) +#if TASKMGR_TRACE +void +isc__taskmgr_dump_active(isc_taskmgr_t *taskmgr); +#endif + struct isc_task { /* Not locked. */ unsigned int magic; @@ -117,6 +125,13 @@ struct isc_task { /* Protected by atomics */ atomic_bool shuttingdown; /* Locked by task manager lock. */ +#if TASKMGR_TRACE + char func[PATH_MAX]; + char file[PATH_MAX]; + unsigned int line; + void *backtrace[ISC__TASKTRACE_SIZE]; + int backtrace_size; +#endif LINK(isc_task_t) link; }; @@ -190,14 +205,8 @@ task_finished(isc_task_t *task) { } isc_result_t -isc_task_create(isc_taskmgr_t *manager, unsigned int quantum, - isc_task_t **taskp) { - return (isc_task_create_bound(manager, quantum, taskp, -1)); -} - -isc_result_t -isc_task_create_bound(isc_taskmgr_t *manager, unsigned int quantum, - isc_task_t **taskp, int tid) { +isc__task_create_bound(isc_taskmgr_t *manager, unsigned int quantum, + isc_task_t **taskp, int tid ISC__TASKFLARG) { isc_task_t *task = NULL; bool exiting; @@ -209,6 +218,14 @@ isc_task_create_bound(isc_taskmgr_t *manager, unsigned int quantum, task = isc_mem_get(manager->mctx, sizeof(*task)); *task = (isc_task_t){ 0 }; +#if TASKMGR_TRACE + strlcpy(task->func, func, sizeof(task->func)); + strlcpy(task->file, file, sizeof(task->file)); + task->line = line; + task->backtrace_size = isc_backtrace(task->backtrace, + ISC__TASKTRACE_SIZE); +#endif + isc_taskmgr_attach(manager, &task->manager); if (tid == -1) { @@ -909,20 +926,24 @@ void isc__taskmgr_destroy(isc_taskmgr_t **managerp) { REQUIRE(managerp != NULL && VALID_MANAGER(*managerp)); XTHREADTRACE("isc_taskmgr_destroy"); - -#ifdef ISC_TASK_TRACE int counter = 0; + while (isc_refcount_current(&(*managerp)->references) > 1 && counter++ < 1000) { - usleep(10 * 1000); + uv_sleep(10); } - INSIST(counter < 1000); -#else - while (isc_refcount_current(&(*managerp)->references) > 1) { - usleep(10 * 1000); + +#if TASKMGR_TRACE + if (isc_refcount_current(&(*managerp)->references) > 1) { + isc__taskmgr_dump_active(*managerp); } + INSIST(isc_refcount_current(&(*managerp)->references) == 1); #endif + while (isc_refcount_current(&(*managerp)->references) > 1) { + uv_sleep(10); + } + isc_taskmgr_detach(managerp); } @@ -1215,3 +1236,55 @@ error: return (result); } #endif /* ifdef HAVE_JSON_C */ + +#if TASKMGR_TRACE + +static void +event_dump(isc_event_t *event) { + fprintf(stderr, " - event: %p\n", event); + fprintf(stderr, " func: %s\n", event->func); + fprintf(stderr, " file: %s\n", event->file); + fprintf(stderr, " line: %u\n", event->line); + fprintf(stderr, " backtrace: |\n"); + isc_backtrace_symbols_fd(event->backtrace, event->backtrace_size, + STDERR_FILENO); +} + +static void +task_dump(isc_task_t *task) { + LOCK(&task->lock); + fprintf(stderr, "- task: %p\n", task); + fprintf(stderr, " tid: %" PRIu32 "\n", task->tid); + fprintf(stderr, " nevents: %u\n", task->nevents); + fprintf(stderr, " func: %s\n", task->func); + fprintf(stderr, " file: %s\n", task->file); + fprintf(stderr, " line: %u\n", task->line); + fprintf(stderr, " backtrace: |\n"); + isc_backtrace_symbols_fd(task->backtrace, task->backtrace_size, + STDERR_FILENO); + fprintf(stderr, "\n"); + + for (isc_event_t *event = ISC_LIST_HEAD(task->events); event != NULL; + event = ISC_LIST_NEXT(event, ev_link)) + { + event_dump(event); + } + + UNLOCK(&task->lock); +} + +void +isc__taskmgr_dump_active(isc_taskmgr_t *taskmgr) { + LOCK(&taskmgr->lock); + fprintf(stderr, "- taskmgr: %p\n", taskmgr); + + for (isc_task_t *task = ISC_LIST_HEAD(taskmgr->tasks); task != NULL; + task = ISC_LIST_NEXT(task, link)) + { + task_dump(task); + } + + UNLOCK(&taskmgr->lock); +} + +#endif