tevent: Call depth tracking

The change to lib/tevent/ABI/tevent-0.13.0.sigs will be reverted
in the commit for the 0.14.0 release...

Signed-off-by: Pavel Filipenský <pfilipen@redhat.com>
Reviewed-by: Stefan Metzmacher <metze@samba.org>
Reviewed-by: Volker Lendecke <vl@samba.org>

lib/tevent/ABI/tevent-0.13.0.sigs

@@ -129,6 +129,10 @@ tevent_set_trace_timer_callback: void (struct tevent_context *, tevent_trace_tim
 tevent_signal_get_tag: uint64_t (const struct tevent_signal *)
 tevent_signal_set_tag: void (struct tevent_signal *, uint64_t)
 tevent_signal_support: bool (struct tevent_context *)
+tevent_thread_call_depth_activate: void (size_t *)
+tevent_thread_call_depth_deactivate: void (void)
+tevent_thread_call_depth_reset_from_req: void (struct tevent_req *)
+tevent_thread_call_depth_start: void (struct tevent_req *)
 tevent_thread_proxy_create: struct tevent_thread_proxy *(struct tevent_context *)
 tevent_thread_proxy_schedule: void (struct tevent_thread_proxy *, struct tevent_immediate **, tevent_immediate_handler_t, void *)
 tevent_threaded_context_create: struct tevent_threaded_context *(TALLOC_CTX *, struct tevent_context *)

lib/tevent/tevent.c

@@ -823,6 +823,9 @@ int _tevent_loop_once(struct tevent_context *ev, const char *location)
 	ret = ev->ops->loop_once(ev, location);
 	tevent_trace_point_callback(ev, TEVENT_TRACE_AFTER_LOOP_ONCE);
 
+	/* New event (and request) will always start with call depth 0. */
+	tevent_thread_call_depth_set(0);
+
 	if (ev->nesting.level > 0) {
 		if (ev->nesting.hook_fn) {
 			int ret2;

lib/tevent/tevent.h

@@ -1928,6 +1928,169 @@ pid_t tevent_cached_getpid(void);
 /* @} */
 
 
+/**
+ * @defgroup tevent_thread_call_depth The tevent call depth tracking functions
+ * @ingroup tevent
+ *
+ *
+ * The call depth tracking consists of two parts.
+ *
+ * Part 1 - storing the depth inside each tevent request.
+ *
+ * Each instance of 'struct tevent_req' internally stores the value of the
+ * current depth. If a new subrequest is created via tevent_req_create(), the
+ * newly created subrequest gets the value from the parent incremented by 1.
+ *
+ * Part 2 - updating external variable with the call depth of the currently
+ * processed tevent request.
+ *
+ * The intended use of call depth is for the trace indentation.  This is done
+ * by registering the address of an external size_t variable via
+ * tevent_thread_call_depth_activate(). And the tracing code just reads it's
+ * value.
+ *
+ * The updates happen during:
+ *
+ * tevent_req_create()
+ * - external variable is set to the value of the newly created request (i.e.
+ *   value of the parent incremented by 1)
+ *
+ * tevent_req_notify_callback()
+ * - external variable is set to the value of the parent tevent request, which
+ *   is just about to be processed
+ *
+ * tevent_queue_immediate_trigger()
+ * - external variable is set to the value of the request coming from the queue
+ *
+ *
+ * While 'Part 1' maintains the call depth value inside each teven request
+ * precisely, the value of the external variable depends on the call flow and
+ * can be changed after return from a function call, so it no longer matches
+ * the value of the request being processed in the current function.
+ *
+ * @code
+ * struct tevent_req *foo_send(TALLOC_CTX *mem_ctx, struct tevent_context *ev)
+ * {
+ *     struct tevent_req *req, *subreq;
+ *     struct foo_state *state;
+ *
+ *     // External variable has value 'X', which is the value in parent code
+ *     // It is ok, since tracing starts often only after tevent_req_create()
+ *     req = tevent_req_create(mem_ctx, &state, struct foo_state);
+ *
+ *     // External variable has now value 'X + 1'
+ *     D_DEBUG("foo_send(): the external variable has the expected value\n");
+ *
+ *     subreq = bar_send(state, ev, ...);
+ *     tevent_req_set_callback(subreq, foo_done, req);
+ *
+ *     // External variable has value 'X + 1 + n', where n > 0 and n is the
+ *     // depth reached in bar_send().
+ *     // We want to reset it via tevent_thread_call_depth_reset_from_req(),
+ *     // since we want the following D_DEBUG() to have the right trace
+ *     //indentation.
+ *
+ *     tevent_thread_call_depth_reset_from_req(req);
+ *     // External variable has again value 'X + 1' taken from req.
+ *     D_DEBUG("foo_send(): the external variable has the expected value\n");
+ *     return req;
+ * }
+ *
+ * static void foo_done(struct tevent_req *subreq)
+ * {
+ *     struct tevent_req *req =
+ *         tevent_req_callback_data(subreq,
+ *         struct tevent_req);
+ *     struct foo_state *state =
+ *         tevent_req_data(req,
+ *         struct foo_state);
+ *
+ *     // external variable has value 'X + 1'
+ *
+ *     D_DEBUG("foo_done(): the external variable has the expected value\n");
+ *     status = bar_recv(subreq, state, ...)
+ *     tevent_req_done(req);
+ * }
+ *
+ * NTSTATUS foo_recv(struct tevent_req *req)
+ * {
+ *     struct foo_state *state = tevent_req_data( req, struct foo_state);
+ *
+ *     // external variable has value 'X' (not 'X + 1')
+ *     // which is ok, if we consider _recv() to be an access function
+ *     // called from the parent context
+ *
+ *     D_DEBUG("foo_recv(): external variable has the value from parent\n");
+ *     return NT_STATUS_OK;
+ * }
+ * @endcode
+ *
+ * Interface has 3 parts:
+ *
+ * Part 1: activation/deactivation
+ *
+ * tevent_thread_call_depth_activate(), tevent_thread_call_depth_deactivate()
+ *
+ * Activating registers external size_t variable that will be maintained with
+ * the current call depth.
+ *
+ * Part 2: Mark the request (and its subrequests) to be tracked
+ *
+ * tevent_thread_call_depth_start(struct tevent_req *req)
+ *
+ * By default, all newly created requests have call depth set to 0.
+ * tevent_thread_call_depth_start() should be called shortly after
+ * tevent_req_create(). It sets the call depth to 1.
+ * Subrequest will have call depth 2 and so on.
+ *
+ * Part 3: reset the external variable using value from tevent request
+ *
+ * tevent_thread_call_depth_reset_from_req(struct tevent_req *req)
+ *
+ * If the call depth is used for trace indentation, it might be usefull to
+ * reset the external variable to the call depth of currently processed tevent
+ * request, since the ext. variable can be changed after return from a function
+ * call that has created subrequests.
+ *
+ * THREADING
+ *
+ * The state is thread specific, i.e. each thread can activate it and register
+ * its own external variable.
+ *
+ * @{
+ */
+
+/**
+ * Activate call depth tracking and register external variable that will
+ * be updated to the call epth of currenty processed tevent request.
+ *
+ * @param[in]  ptr   Address of external variable
+ */
+void tevent_thread_call_depth_activate(size_t *ptr);
+
+/**
+ * Deactivate call depth tracking. Can be used in the child process,
+ * after fork.
+ */
+void tevent_thread_call_depth_deactivate(void);
+
+/**
+ * This request will have call depth set to 1, its subrequest will get 2 and so
+ * on. All other requests will have call depth 0.
+ */
+void tevent_thread_call_depth_start(struct tevent_req *req);
+
+/**
+ * Set the external variable to the call depth of the request req.
+ *
+ * @param[in]  req   Request from which the call depth is assigned to ext.
+ * variable.
+ */
+void tevent_thread_call_depth_reset_from_req(struct tevent_req *req);
+
+/* @} */
+
+
 /**
  * @defgroup tevent_queue The tevent queue functions
  * @ingroup tevent

lib/tevent/tevent_debug.c

@@ -292,3 +292,41 @@ void tevent_trace_queue_callback(struct tevent_context *ev,
 		ev->tracing.qe.callback(qe, tp, ev->tracing.qe.private_data);
 	}
 }
+
+static __thread size_t *tevent_thread_call_depth_ptr = NULL;
+
+void tevent_thread_call_depth_activate(size_t *ptr)
+{
+	tevent_thread_call_depth_ptr = ptr;
+	*tevent_thread_call_depth_ptr = 0;
+}
+
+void tevent_thread_call_depth_deactivate(void)
+{
+	/* Reset the previous storage */
+	if (tevent_thread_call_depth_ptr != NULL) {
+		*tevent_thread_call_depth_ptr = 0;
+	}
+	tevent_thread_call_depth_ptr = NULL;
+}
+
+void tevent_thread_call_depth_start(struct tevent_req *req)
+{
+	if (tevent_thread_call_depth_ptr != NULL) {
+		*tevent_thread_call_depth_ptr = req->internal.call_depth = 1;
+	}
+}
+
+void tevent_thread_call_depth_reset_from_req(struct tevent_req *req)
+{
+	if (tevent_thread_call_depth_ptr != NULL) {
+		*tevent_thread_call_depth_ptr = req->internal.call_depth;
+	}
+}
+
+_PRIVATE_ void tevent_thread_call_depth_set(size_t depth)
+{
+	if (tevent_thread_call_depth_ptr != NULL) {
+		*tevent_thread_call_depth_ptr = depth;
+	}
+}

lib/tevent/tevent_internal.h

@@ -169,6 +169,8 @@ struct tevent_req {
 		 * @brief The place where profiling data is kept
 		 */
 		struct tevent_req_profile *profile;
+
+		size_t call_depth;
 	} internal;
 };
 
@@ -497,6 +499,7 @@ void tevent_epoll_set_panic_fallback(struct tevent_context *ev,
 					       bool replay));
 #endif
 
+void tevent_thread_call_depth_set(size_t depth);
 
 void tevent_trace_point_callback(struct tevent_context *ev,
 				 enum tevent_trace_point);

lib/tevent/tevent_queue.c

@@ -149,6 +149,8 @@ static void tevent_queue_immediate_trigger(struct tevent_context *ev,
 
 	tevent_trace_queue_callback(ev, q->list,
 				    TEVENT_EVENT_TRACE_BEFORE_HANDLER);
+	/* Set the call depth of the request coming from the queue. */
+	tevent_thread_call_depth_set(q->list->req->internal.call_depth);
 	q->list->triggered = true;
 	q->list->trigger(q->list->req, q->list->private_data);
 }

lib/tevent/tevent_req.c

@@ -120,6 +120,13 @@ struct tevent_req *_tevent_req_create(TALLOC_CTX *mem_ctx,
 	}
 
 	*ppdata = data;
+
+	/* Initially, talloc_zero_size() sets internal.call_depth to 0 */
+	if (parent != NULL && parent->internal.call_depth > 0) {
+		req->internal.call_depth = parent->internal.call_depth + 1;
+		tevent_thread_call_depth_set(req->internal.call_depth);
+	}
+
 	return req;
 }
 
@@ -138,6 +145,9 @@ void _tevent_req_notify_callback(struct tevent_req *req, const char *location)
 		return;
 	}
 	if (req->async.fn != NULL) {
+		/* Calling back the parent code, decrement the call depth. */
+		tevent_thread_call_depth_set(req->internal.call_depth > 0 ?
+					     req->internal.call_depth - 1 : 0);
 		req->async.fn(req);
 	}
 }