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

@@ -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__event_allocate(isc_mem_t *mctx, void *sender, isc_eventtype_t type,
-		   isc_taskaction_t action, void *arg, size_t size) {
+		    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,
+	ISC_EVENT_INIT_PASS(event, size, 0, NULL, type, action, arg, sender,
-		       mctx);
+			    destroy, mctx);
 
 	return (event);
 }

lib/isc/include/isc/event.h

@@ -15,8 +15,11 @@
 
 /*! \file isc/event.h */
 
+#include <isc/backtrace.h>
 #include <isc/lang.h>
+#include <isc/string.h>
 #include <isc/types.h>
+#include <isc/util.h>
 
 /*****
 ***** 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__event_allocate(isc_mem_t *mctx, void *sender, isc_eventtype_t type,
-		   isc_taskaction_t action, void *arg, size_t size);
+		    isc_taskaction_t action, void *arg,
+		    size_t size ISC__EVENT_FLARG);
 /*%<
  * Allocate an event structure.
  *

lib/isc/include/isc/task.h

@@ -67,6 +67,17 @@
 #include <isc/netmgr.h>
 #include <isc/stdtime.h>
 #include <isc/types.h>
+#include <isc/util.h>
+
+#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_create_bound(isc_taskmgr_t *manager, unsigned int quantum,
-		isc_task_t **taskp);
+		       isc_task_t **taskp, int tid ISC__TASKFLARG);
-isc_result_t
-isc_task_create_bound(isc_taskmgr_t *manager, unsigned int quantum,
-		      isc_task_t **taskp, int tid);
 /*%<
  * Create a task, optionally bound to a particular tid.
  *

lib/isc/task.c

@@ -20,9 +20,11 @@
 
 #include <stdbool.h>
 #include <unistd.h>
+#include <uv.h>
 
 #include <isc/app.h>
 #include <isc/atomic.h>
+#include <isc/backtrace.h>
 #include <isc/condition.h>
 #include <isc/event.h>
 #include <isc/log.h>
@@ -47,6 +49,7 @@
 #include <json_object.h>
 #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_create_bound(isc_taskmgr_t *manager, unsigned int quantum,
-		isc_task_t **taskp) {
+		       isc_task_t **taskp, int tid ISC__TASKFLARG) {
-	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_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
+#if TASKMGR_TRACE
-	while (isc_refcount_current(&(*managerp)->references) > 1) {
+	if (isc_refcount_current(&(*managerp)->references) > 1) {
-		usleep(10 * 1000);
+		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