From: Ondřej Surý Date: Sat, 26 Mar 2022 13:37:38 +0000 (+0100) Subject: Add detailed tracing when TASKMGR_TRACE is defined X-Git-Tag: v9.19.1~66^2 X-Git-Url: http://git.ipfire.org/gitweb.cgi?a=commitdiff_plain;h=d1d88a28953ae43db430e5b22fcd8d567a306c07;p=thirdparty%2Fbind9.git 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. --- diff --git a/lib/isc/event.c b/lib/isc/event.c index 547c839bb95..294da352548 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 8d7048cd52b..c3db5406486 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 3a64dad52a7..a7ba3044130 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 fb40c1f7a9d..f61b46fd5d7 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