tevent: Add tevent_req_profile

This allows detailed reporting where a tevent_req spends its time

Signed-off-by: Volker Lendecke <vl@samba.org>
Reviewed-by: Stefan Metzmacher <metze@samba.org>

4 files changed, 422 insertions, 0 deletions

diff --git a/lib/tevent/ABI/tevent-0.9.36.sigs b/lib/tevent/ABI/tevent-0.9.36.sigs
index ddb2c03b65c..f6227db5c93 100644
--- a/lib/tevent/ABI/tevent-0.9.36.sigs
+++ b/lib/tevent/ABI/tevent-0.9.36.sigs
@@ -75,11 +75,25 @@ tevent_re_initialise: int (struct tevent_context *)
 tevent_register_backend: bool (const char *, const struct tevent_ops *)
 tevent_req_default_print: char *(struct tevent_req *, TALLOC_CTX *)
 tevent_req_defer_callback: void (struct tevent_req *, struct tevent_context *)
+tevent_req_get_profile: const struct tevent_req_profile *(struct tevent_req *)
 tevent_req_is_error: bool (struct tevent_req *, enum tevent_req_state *, uint64_t *)
 tevent_req_is_in_progress: bool (struct tevent_req *)
+tevent_req_move_profile: struct tevent_req_profile *(struct tevent_req *, TALLOC_CTX *)
 tevent_req_poll: bool (struct tevent_req *, struct tevent_context *)
 tevent_req_post: struct tevent_req *(struct tevent_req *, struct tevent_context *)
 tevent_req_print: char *(TALLOC_CTX *, struct tevent_req *)
+tevent_req_profile_append_sub: void (struct tevent_req_profile *, struct tevent_req_profile **)
+tevent_req_profile_create: struct tevent_req_profile *(TALLOC_CTX *)
+tevent_req_profile_get_name: void (const struct tevent_req_profile *, const char **)
+tevent_req_profile_get_start: void (const struct tevent_req_profile *, const char **, struct timeval *)
+tevent_req_profile_get_status: void (const struct tevent_req_profile *, pid_t *, enum tevent_req_state *, uint64_t *)
+tevent_req_profile_get_stop: void (const struct tevent_req_profile *, const char **, struct timeval *)
+tevent_req_profile_get_subprofiles: const struct tevent_req_profile *(const struct tevent_req_profile *)
+tevent_req_profile_next: const struct tevent_req_profile *(const struct tevent_req_profile *)
+tevent_req_profile_set_name: bool (struct tevent_req_profile *, const char *)
+tevent_req_profile_set_start: bool (struct tevent_req_profile *, const char *, struct timeval)
+tevent_req_profile_set_status: void (struct tevent_req_profile *, pid_t, enum tevent_req_state, uint64_t)
+tevent_req_profile_set_stop: bool (struct tevent_req_profile *, const char *, struct timeval)
 tevent_req_received: void (struct tevent_req *)
 tevent_req_reset_endtime: void (struct tevent_req *)
 tevent_req_set_callback: void (struct tevent_req *, tevent_req_fn, void *)
@@ -87,6 +101,7 @@ tevent_req_set_cancel_fn: void (struct tevent_req *, tevent_req_cancel_fn)
 tevent_req_set_cleanup_fn: void (struct tevent_req *, tevent_req_cleanup_fn)
 tevent_req_set_endtime: bool (struct tevent_req *, struct tevent_context *, struct timeval)
 tevent_req_set_print_fn: void (struct tevent_req *, tevent_req_print_fn)
+tevent_req_set_profile: bool (struct tevent_req *)
 tevent_sa_info_queue_count: size_t (void)
 tevent_set_abort_fn: void (void (*)(const char *))
 tevent_set_debug: int (struct tevent_context *, void (*)(void *, enum tevent_debug_level, const char *, va_list), void *)
diff --git a/lib/tevent/tevent.h b/lib/tevent/tevent.h
index d34a03093f3..aa6fe0de202 100644
--- a/lib/tevent/tevent.h
+++ b/lib/tevent/tevent.h
@@ -1349,6 +1349,191 @@ bool tevent_req_is_error(struct tevent_req *req,
 void tevent_req_received(struct tevent_req *req);
 
 /**
+ * @brief Mark a tevent_req for profiling
+ *
+ * This will turn on profiling for this tevent_req an all subreqs that
+ * are directly started as helper requests off this
+ * tevent_req. subreqs are chained by walking up the talloc_parent
+ * hierarchy at a subreq's tevent_req_create. This means to get the
+ * profiling chain right the subreq that needs to be profiled as part
+ * of this tevent_req's profile must be a talloc child of the requests
+ * state variable.
+ *
+ * @param[in] req The request to do tracing for
+ *
+ * @return        False if the profile could not be activated
+ */
+bool tevent_req_set_profile(struct tevent_req *req);
+
+struct tevent_req_profile;
+
+/**
+ * @brief Get the a request's profile for inspection
+ *
+ * @param[in] req The request to get the profile from
+ *
+ * @return        The request's profile
+ */
+const struct tevent_req_profile *tevent_req_get_profile(
+	struct tevent_req *req);
+
+/**
+ * @brief Move the profile out of a request
+ *
+ * This function detaches the request's profile from the request, so
+ * that the profile can outlive the request in a _recv function.
+ *
+ * @param[in] req     The request to move the profile out of
+ * @param[in] mem_ctx The new talloc context for the profile
+ *
+ * @return            The moved profile
+ */
+
+struct tevent_req_profile *tevent_req_move_profile(struct tevent_req *req,
+						   TALLOC_CTX *mem_ctx);
+
+/**
+ * @brief Get a profile description
+ *
+ * @param[in] profile  The profile to be queried
+ * @param[in] req_name The name of the request (state's name)
+ *
+ * "req_name" after this call is still in talloc-posession of "profile"
+ */
+void tevent_req_profile_get_name(const struct tevent_req_profile *profile,
+				 const char **req_name);
+
+/**
+ * @brief Get a profile's start event data
+ *
+ * @param[in] profile        The profile to be queried
+ * @param[in] start_location The location where this event started
+ * @param[in] start_time     The time this event started
+ *
+ * "start_location" after this call is still in talloc-posession of "profile"
+ */
+void tevent_req_profile_get_start(const struct tevent_req_profile *profile,
+				  const char **start_location,
+				  struct timeval *start_time);
+
+/**
+ * @brief Get a profile's stop event data
+ *
+ * @param[in] profile        The profile to be queried
+ * @param[in] stop_location  The location where this event stopped
+ * @param[in] stop_time      The time this event stopped
+ *
+ * "stop_location" after this call is still in talloc-posession of "profile"
+ */
+void tevent_req_profile_get_stop(const struct tevent_req_profile *profile,
+				 const char **stop_location,
+				 struct timeval *stop_time);
+
+/**
+ * @brief Get a profile's result data
+ *
+ * @param[in] pid        The process where this profile was taken
+ * @param[in] state      The status the profile's tevent_req finished with
+ * @param[in] user_error The user error of the profile's tevent_req
+ */
+void tevent_req_profile_get_status(const struct tevent_req_profile *profile,
+				   pid_t *pid,
+				   enum tevent_req_state *state,
+				   uint64_t *user_error);
+
+/**
+ * @brief Retrieve the first subreq's profile from a profile
+ *
+ * @param[in] profile The profile to query
+ *
+ * @return The first tevent subreq's profile
+ */
+const struct tevent_req_profile *tevent_req_profile_get_subprofiles(
+	const struct tevent_req_profile *profile);
+
+/**
+ * @brief Walk the chain of subreqs
+ *
+ * @param[in] profile The subreq's profile to walk
+ *
+ * @return The next subprofile in the list
+ */
+const struct tevent_req_profile *tevent_req_profile_next(
+	const struct tevent_req_profile *profile);
+
+/**
+ * @brief Create a fresh tevent_req_profile
+ *
+ * @param[in] mem_ctx The talloc context to hang the fresh struct off
+ *
+ * @return The fresh struct
+ */
+struct tevent_req_profile *tevent_req_profile_create(TALLOC_CTX *mem_ctx);
+
+/**
+ * @brief Set a profile's name
+ *
+ * @param[in] profile The profile to set the name for
+ * @param[in] name    The new name for the profile
+ *
+ * @return True if the internal talloc_strdup succeeded
+ */
+bool tevent_req_profile_set_name(struct tevent_req_profile *profile,
+				 const char *name);
+
+/**
+ * @brief Set a profile's start event
+ *
+ * @param[in] profile        The profile to set the start data for
+ * @param[in] start_location The new start location
+ * @param[in] start_time     The new start time
+ *
+ * @return True if the internal talloc_strdup succeeded
+ */
+bool tevent_req_profile_set_start(struct tevent_req_profile *profile,
+				  const char *start_location,
+				  struct timeval start_time);
+
+/**
+ * @brief Set a profile's stop event
+ *
+ * @param[in] profile        The profile to set the stop data for
+ * @param[in] stop_location  The new stop location
+ * @param[in] stop_time      The new stop time
+ *
+ * @return True if the internal talloc_strdup succeeded
+ */
+bool tevent_req_profile_set_stop(struct tevent_req_profile *profile,
+				 const char *stop_location,
+				 struct timeval stop_time);
+
+/**
+ * @brief Set a profile's exit status
+ *
+ * @param[in] profile    The profile to set the exit status for
+ * @param[in] pid        The process where this profile was taken
+ * @param[in] state      The status the profile's tevent_req finished with
+ * @param[in] user_error The user error of the profile's tevent_req
+ */
+void tevent_req_profile_set_status(struct tevent_req_profile *profile,
+				   pid_t pid,
+				   enum tevent_req_state state,
+				   uint64_t user_error);
+
+/**
+ * @brief Add a subprofile to a profile
+ *
+ * @param[in] parent_profile The profile to be modified
+ * @param[in] sub_profile The subreqs profile profile to be added
+ *
+ * "subreq" is talloc_move'ed into "parent_profile", so the talloc
+ * ownership of "sub_profile" changes
+ */
+
+void tevent_req_profile_append_sub(struct tevent_req_profile *parent_profile,
+				   struct tevent_req_profile **sub_profile);
+
+/**
  * @brief Create a tevent subrequest at a given time.
  *
  * The idea is that always the same syntax for tevent requests.
diff --git a/lib/tevent/tevent_internal.h b/lib/tevent/tevent_internal.h
index 17c195816fa..5365fce3533 100644
--- a/lib/tevent/tevent_internal.h
+++ b/lib/tevent/tevent_internal.h
@@ -164,9 +164,28 @@ struct tevent_req {
 		 *
 		 */
 		struct tevent_timer *timer;
+
+		/**
+		 * @brief The place where profiling data is kept
+		 */
+		struct tevent_req_profile *profile;
 	} internal;
 };
 
+struct tevent_req_profile {
+	struct tevent_req_profile *prev, *next;
+	struct tevent_req_profile *parent;
+	const char *req_name;
+	pid_t pid;
+	const char *start_location;
+	struct timeval start_time;
+	const char *stop_location;
+	struct timeval stop_time;
+	enum tevent_req_state state;
+	uint64_t user_error;
+	struct tevent_req_profile *subprofiles;
+};
+
 struct tevent_fd {
 	struct tevent_fd *prev, *next;
 	struct tevent_context *event_ctx;
diff --git a/lib/tevent/tevent_req.c b/lib/tevent/tevent_req.c
index 15754d361ae..76e27b8f7e9 100644
--- a/lib/tevent/tevent_req.c
+++ b/lib/tevent/tevent_req.c
@@ -65,6 +65,7 @@ struct tevent_req *_tevent_req_create(TALLOC_CTX *mem_ctx,
 				    const char *location)
 {
 	struct tevent_req *req;
+	struct tevent_req *parent;
 	void **ppdata = (void **)pdata;
 	void *data;
 	size_t payload;
@@ -103,6 +104,19 @@ struct tevent_req *_tevent_req_create(TALLOC_CTX *mem_ctx,
 
 	talloc_set_destructor(req, tevent_req_destructor);
 
+	parent = talloc_get_type(talloc_parent(mem_ctx), struct tevent_req);
+	if ((parent != NULL) && (parent->internal.profile != NULL)) {
+		bool ok = tevent_req_set_profile(req);
+
+		if (!ok) {
+			TALLOC_FREE(req);
+			return NULL;
+		}
+		req->internal.profile->parent = parent->internal.profile;
+		DLIST_ADD_END(parent->internal.profile->subprofiles,
+			      req->internal.profile);
+	}
+
 	*ppdata = data;
 	return req;
 }
@@ -148,6 +162,7 @@ static void tevent_req_finish(struct tevent_req *req,
 			      enum tevent_req_state state,
 			      const char *location)
 {
+	struct tevent_req_profile *p;
 	/*
 	 * make sure we do not timeout after
 	 * the request was already finished
@@ -159,6 +174,20 @@ static void tevent_req_finish(struct tevent_req *req,
 
 	tevent_req_cleanup(req);
 
+	p = req->internal.profile;
+
+	if (p != NULL) {
+		p->stop_location = location;
+		p->stop_time = tevent_timeval_current();
+		p->state = state;
+		p->user_error = req->internal.error;
+
+		if (p->parent != NULL) {
+			talloc_steal(p->parent, p);
+			req->internal.profile = NULL;
+		}
+	}
+
 	_tevent_req_notify_callback(req, location);
 }
 
@@ -363,3 +392,177 @@ void tevent_req_set_cleanup_fn(struct tevent_req *req, tevent_req_cleanup_fn fn)
 	req->private_cleanup.state = req->internal.state;
 	req->private_cleanup.fn = fn;
 }
+
+static int tevent_req_profile_destructor(struct tevent_req_profile *p);
+
+bool tevent_req_set_profile(struct tevent_req *req)
+{
+	struct tevent_req_profile *p;
+
+	if (req->internal.profile != NULL) {
+		tevent_req_error(req, EINVAL);
+		return false;
+	}
+
+	p = tevent_req_profile_create(req);
+
+	if (tevent_req_nomem(p, req)) {
+		return false;
+	}
+
+	p->req_name = talloc_get_name(req->data);
+	p->start_location = req->internal.create_location;
+	p->start_time = tevent_timeval_current();
+
+	req->internal.profile = p;
+
+	return true;
+}
+
+static int tevent_req_profile_destructor(struct tevent_req_profile *p)
+{
+	if (p->parent != NULL) {
+		DLIST_REMOVE(p->parent->subprofiles, p);
+		p->parent = NULL;
+	}
+
+	while (p->subprofiles != NULL) {
+		p->subprofiles->parent = NULL;
+		DLIST_REMOVE(p->subprofiles, p->subprofiles);
+	}
+
+	return 0;
+}
+
+struct tevent_req_profile *tevent_req_move_profile(struct tevent_req *req,
+						   TALLOC_CTX *mem_ctx)
+{
+	return talloc_move(mem_ctx, &req->internal.profile);
+}
+
+const struct tevent_req_profile *tevent_req_get_profile(
+	struct tevent_req *req)
+{
+	return req->internal.profile;
+}
+
+void tevent_req_profile_get_name(const struct tevent_req_profile *profile,
+				 const char **req_name)
+{
+	if (req_name != NULL) {
+		*req_name = profile->req_name;
+	}
+}
+
+void tevent_req_profile_get_start(const struct tevent_req_profile *profile,
+				  const char **start_location,
+				  struct timeval *start_time)
+{
+	if (start_location != NULL) {
+		*start_location = profile->start_location;
+	}
+	if (start_time != NULL) {
+		*start_time = profile->start_time;
+	}
+}
+
+void tevent_req_profile_get_stop(const struct tevent_req_profile *profile,
+				 const char **stop_location,
+				 struct timeval *stop_time)
+{
+	if (stop_location != NULL) {
+		*stop_location = profile->stop_location;
+	}
+	if (stop_time != NULL) {
+		*stop_time = profile->stop_time;
+	}
+}
+
+void tevent_req_profile_get_status(const struct tevent_req_profile *profile,
+				   pid_t *pid,
+				   enum tevent_req_state *state,
+				   uint64_t *user_error)
+{
+	if (pid != NULL) {
+		*pid = profile->pid;
+	}
+	if (state != NULL) {
+		*state = profile->state;
+	}
+	if (user_error != NULL) {
+		*user_error = profile->user_error;
+	}
+}
+
+const struct tevent_req_profile *tevent_req_profile_get_subprofiles(
+	const struct tevent_req_profile *profile)
+{
+	return profile->subprofiles;
+}
+
+const struct tevent_req_profile *tevent_req_profile_next(
+	const struct tevent_req_profile *profile)
+{
+	return profile->next;
+}
+
+struct tevent_req_profile *tevent_req_profile_create(TALLOC_CTX *mem_ctx)
+{
+	struct tevent_req_profile *result;
+
+	result = talloc_zero(mem_ctx, struct tevent_req_profile);
+	if (result == NULL) {
+		return NULL;
+	}
+	talloc_set_destructor(result, tevent_req_profile_destructor);
+
+	return result;
+}
+
+bool tevent_req_profile_set_name(struct tevent_req_profile *profile,
+				 const char *req_name)
+{
+	profile->req_name = talloc_strdup(profile, req_name);
+	return (profile->req_name != NULL);
+}
+
+bool tevent_req_profile_set_start(struct tevent_req_profile *profile,
+				  const char *start_location,
+				  struct timeval start_time)
+{
+	profile->start_time = start_time;
+
+	profile->start_location = talloc_strdup(profile, start_location);
+	return (profile->start_location != NULL);
+}
+
+bool tevent_req_profile_set_stop(struct tevent_req_profile *profile,
+				 const char *stop_location,
+				 struct timeval stop_time)
+{
+	profile->stop_time = stop_time;
+
+	profile->stop_location = talloc_strdup(profile, stop_location);
+	return (profile->stop_location != NULL);
+}
+
+void tevent_req_profile_set_status(struct tevent_req_profile *profile,
+				   pid_t pid,
+				   enum tevent_req_state state,
+				   uint64_t user_error)
+{
+	profile->pid = pid;
+	profile->state = state;
+	profile->user_error = user_error;
+}
+
+void tevent_req_profile_append_sub(struct tevent_req_profile *parent_profile,
+				   struct tevent_req_profile **sub_profile)
+{
+	struct tevent_req_profile *sub;
+
+	sub = talloc_move(parent_profile, sub_profile);
+
+	sub->parent = parent_profile;
+	DLIST_ADD_END(parent_profile->subprofiles, sub);
+}