[PATCH] Add winbind request profiling

Volker Lendecke Volker.Lendecke at SerNet.DE
Wed Jun 20 14:01:49 UTC 2018


Hi!

Attached find a patchset that allows profiling of tevent_req. The
first application of this is in the winbind parent, see the last
commit for a sample output.

Review appreciated!

Thanks, Volker

-- 
SerNet GmbH, Bahnhofsallee 1b, 37081 Göttingen
phone: +49-551-370000-0, fax: +49-551-370000-9
AG Göttingen, HRB 2816, GF: Dr. Johannes Loxen
http://www.sernet.de, mailto:kontakt at sernet.de
-------------- next part --------------
From e0b74f6fd46668d6f0644b99e92d94775c1317ad Mon Sep 17 00:00:00 2001
From: Volker Lendecke <vl at samba.org>
Date: Wed, 2 May 2018 13:54:42 +0200
Subject: [PATCH 1/7] lib: Multi-line a long line in wscript_build

Why? I'll add another file in a later commit

Signed-off-by: Volker Lendecke <vl at samba.org>
---
 lib/util/wscript_build | 6 +++++-
 1 file changed, 5 insertions(+), 1 deletion(-)

diff --git a/lib/util/wscript_build b/lib/util/wscript_build
index ded91f67d9f..793e24669c9 100644
--- a/lib/util/wscript_build
+++ b/lib/util/wscript_build
@@ -162,7 +162,11 @@ else:
                       )
 
     bld.SAMBA_LIBRARY('tevent-util',
-                      source='tevent_unix.c tevent_ntstatus.c tevent_werror.c',
+                      source='''
+                          tevent_unix.c
+                          tevent_ntstatus.c
+                          tevent_werror.c
+                      ''',
                       local_include=False,
                       public_deps='tevent samba-errors',
                       public_headers='tevent_ntstatus.h tevent_unix.h tevent_werror.h',
-- 
2.11.0


From 792399f15a8a430baa06dc2023c43cac150f282c Mon Sep 17 00:00:00 2001
From: Volker Lendecke <vl at samba.org>
Date: Wed, 2 May 2018 14:01:56 +0200
Subject: [PATCH 2/7] tevent: Add tevent_req_profile

This allows detailed reporting where a tevent_req spends its time

Signed-off-by: Volker Lendecke <vl at samba.org>
---
 lib/tevent/tevent.h          | 185 +++++++++++++++++++++++++++++++++++++++
 lib/tevent/tevent_internal.h |  19 ++++
 lib/tevent/tevent_req.c      | 202 +++++++++++++++++++++++++++++++++++++++++++
 3 files changed, 406 insertions(+)

diff --git a/lib/tevent/tevent.h b/lib/tevent/tevent.h
index 3ccac6a3600..b5b41919397 100644
--- a/lib/tevent/tevent.h
+++ b/lib/tevent/tevent.h
@@ -1327,6 +1327,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 ec3955e70a4..bb816a2518c 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..5b57fea814e 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,176 @@ 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) {
+		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);
+}
-- 
2.11.0


From aefb0b1d5ae5eaa4140d183cef3409caba48ce5d Mon Sep 17 00:00:00 2001
From: Volker Lendecke <vl at samba.org>
Date: Mon, 7 May 2018 13:42:24 +0200
Subject: [PATCH 3/7] tevent 0.9.37

Added profiling

Signed-off-by: Volker Lendecke <vl at samba.org>
---
 lib/tevent/ABI/tevent-0.9.37.sigs | 115 ++++++++++++++++++++++++++++++++++++++
 lib/tevent/wscript                |   2 +-
 2 files changed, 116 insertions(+), 1 deletion(-)
 create mode 100644 lib/tevent/ABI/tevent-0.9.37.sigs

diff --git a/lib/tevent/ABI/tevent-0.9.37.sigs b/lib/tevent/ABI/tevent-0.9.37.sigs
new file mode 100644
index 00000000000..295668f60b6
--- /dev/null
+++ b/lib/tevent/ABI/tevent-0.9.37.sigs
@@ -0,0 +1,115 @@
+_tevent_add_fd: struct tevent_fd *(struct tevent_context *, TALLOC_CTX *, int, uint16_t, tevent_fd_handler_t, void *, const char *, const char *)
+_tevent_add_signal: struct tevent_signal *(struct tevent_context *, TALLOC_CTX *, int, int, tevent_signal_handler_t, void *, const char *, const char *)
+_tevent_add_timer: struct tevent_timer *(struct tevent_context *, TALLOC_CTX *, struct timeval, tevent_timer_handler_t, void *, const char *, const char *)
+_tevent_create_immediate: struct tevent_immediate *(TALLOC_CTX *, const char *)
+_tevent_loop_once: int (struct tevent_context *, const char *)
+_tevent_loop_until: int (struct tevent_context *, bool (*)(void *), void *, const char *)
+_tevent_loop_wait: int (struct tevent_context *, const char *)
+_tevent_queue_create: struct tevent_queue *(TALLOC_CTX *, const char *, const char *)
+_tevent_req_callback_data: void *(struct tevent_req *)
+_tevent_req_cancel: bool (struct tevent_req *, const char *)
+_tevent_req_create: struct tevent_req *(TALLOC_CTX *, void *, size_t, const char *, const char *)
+_tevent_req_data: void *(struct tevent_req *)
+_tevent_req_done: void (struct tevent_req *, const char *)
+_tevent_req_error: bool (struct tevent_req *, uint64_t, const char *)
+_tevent_req_nomem: bool (const void *, struct tevent_req *, const char *)
+_tevent_req_notify_callback: void (struct tevent_req *, const char *)
+_tevent_req_oom: void (struct tevent_req *, const char *)
+_tevent_schedule_immediate: void (struct tevent_immediate *, struct tevent_context *, tevent_immediate_handler_t, void *, const char *, const char *)
+_tevent_threaded_schedule_immediate: void (struct tevent_threaded_context *, struct tevent_immediate *, tevent_immediate_handler_t, void *, const char *, const char *)
+tevent_backend_list: const char **(TALLOC_CTX *)
+tevent_cleanup_pending_signal_handlers: void (struct tevent_signal *)
+tevent_common_add_fd: struct tevent_fd *(struct tevent_context *, TALLOC_CTX *, int, uint16_t, tevent_fd_handler_t, void *, const char *, const char *)
+tevent_common_add_signal: struct tevent_signal *(struct tevent_context *, TALLOC_CTX *, int, int, tevent_signal_handler_t, void *, const char *, const char *)
+tevent_common_add_timer: struct tevent_timer *(struct tevent_context *, TALLOC_CTX *, struct timeval, tevent_timer_handler_t, void *, const char *, const char *)
+tevent_common_add_timer_v2: struct tevent_timer *(struct tevent_context *, TALLOC_CTX *, struct timeval, tevent_timer_handler_t, void *, const char *, const char *)
+tevent_common_check_signal: int (struct tevent_context *)
+tevent_common_context_destructor: int (struct tevent_context *)
+tevent_common_fd_destructor: int (struct tevent_fd *)
+tevent_common_fd_get_flags: uint16_t (struct tevent_fd *)
+tevent_common_fd_set_close_fn: void (struct tevent_fd *, tevent_fd_close_fn_t)
+tevent_common_fd_set_flags: void (struct tevent_fd *, uint16_t)
+tevent_common_have_events: bool (struct tevent_context *)
+tevent_common_loop_immediate: bool (struct tevent_context *)
+tevent_common_loop_timer_delay: struct timeval (struct tevent_context *)
+tevent_common_loop_wait: int (struct tevent_context *, const char *)
+tevent_common_schedule_immediate: void (struct tevent_immediate *, struct tevent_context *, tevent_immediate_handler_t, void *, const char *, const char *)
+tevent_common_threaded_activate_immediate: void (struct tevent_context *)
+tevent_common_wakeup: int (struct tevent_context *)
+tevent_common_wakeup_fd: int (int)
+tevent_common_wakeup_init: int (struct tevent_context *)
+tevent_context_init: struct tevent_context *(TALLOC_CTX *)
+tevent_context_init_byname: struct tevent_context *(TALLOC_CTX *, const char *)
+tevent_context_init_ops: struct tevent_context *(TALLOC_CTX *, const struct tevent_ops *, void *)
+tevent_debug: void (struct tevent_context *, enum tevent_debug_level, const char *, ...)
+tevent_fd_get_flags: uint16_t (struct tevent_fd *)
+tevent_fd_set_auto_close: void (struct tevent_fd *)
+tevent_fd_set_close_fn: void (struct tevent_fd *, tevent_fd_close_fn_t)
+tevent_fd_set_flags: void (struct tevent_fd *, uint16_t)
+tevent_get_trace_callback: void (struct tevent_context *, tevent_trace_callback_t *, void *)
+tevent_loop_allow_nesting: void (struct tevent_context *)
+tevent_loop_set_nesting_hook: void (struct tevent_context *, tevent_nesting_hook, void *)
+tevent_num_signals: size_t (void)
+tevent_queue_add: bool (struct tevent_queue *, struct tevent_context *, struct tevent_req *, tevent_queue_trigger_fn_t, void *)
+tevent_queue_add_entry: struct tevent_queue_entry *(struct tevent_queue *, struct tevent_context *, struct tevent_req *, tevent_queue_trigger_fn_t, void *)
+tevent_queue_add_optimize_empty: struct tevent_queue_entry *(struct tevent_queue *, struct tevent_context *, struct tevent_req *, tevent_queue_trigger_fn_t, void *)
+tevent_queue_entry_untrigger: void (struct tevent_queue_entry *)
+tevent_queue_length: size_t (struct tevent_queue *)
+tevent_queue_running: bool (struct tevent_queue *)
+tevent_queue_start: void (struct tevent_queue *)
+tevent_queue_stop: void (struct tevent_queue *)
+tevent_queue_wait_recv: bool (struct tevent_req *)
+tevent_queue_wait_send: struct tevent_req *(TALLOC_CTX *, struct tevent_context *, struct tevent_queue *)
+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 *)
+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 *)
+tevent_set_debug_stderr: int (struct tevent_context *)
+tevent_set_default_backend: void (const char *)
+tevent_set_trace_callback: void (struct tevent_context *, tevent_trace_callback_t, void *)
+tevent_signal_support: bool (struct tevent_context *)
+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 *)
+tevent_timeval_add: struct timeval (const struct timeval *, uint32_t, uint32_t)
+tevent_timeval_compare: int (const struct timeval *, const struct timeval *)
+tevent_timeval_current: struct timeval (void)
+tevent_timeval_current_ofs: struct timeval (uint32_t, uint32_t)
+tevent_timeval_is_zero: bool (const struct timeval *)
+tevent_timeval_set: struct timeval (uint32_t, uint32_t)
+tevent_timeval_until: struct timeval (const struct timeval *, const struct timeval *)
+tevent_timeval_zero: struct timeval (void)
+tevent_trace_point_callback: void (struct tevent_context *, enum tevent_trace_point)
+tevent_update_timer: void (struct tevent_timer *, struct timeval)
+tevent_wakeup_recv: bool (struct tevent_req *)
+tevent_wakeup_send: struct tevent_req *(TALLOC_CTX *, struct tevent_context *, struct timeval)
diff --git a/lib/tevent/wscript b/lib/tevent/wscript
index 94d190f3b60..ce72557d90a 100644
--- a/lib/tevent/wscript
+++ b/lib/tevent/wscript
@@ -1,7 +1,7 @@
 #!/usr/bin/env python
 
 APPNAME = 'tevent'
-VERSION = '0.9.36'
+VERSION = '0.9.37'
 
 blddir = 'bin'
 
-- 
2.11.0


From c5a04d6e68ed08f2d0777e36233adac3b9eb71e3 Mon Sep 17 00:00:00 2001
From: Volker Lendecke <vl at samba.org>
Date: Wed, 2 May 2018 13:59:57 +0200
Subject: [PATCH 4/7] lib: Add tevent_req_profile helpers

Print and marshall/unmarshall tevent_req_profile structs

Signed-off-by: Volker Lendecke <vl at samba.org>
---
 lib/util/tevent_req_profile.c | 519 ++++++++++++++++++++++++++++++++++++++++++
 lib/util/tevent_req_profile.h |  50 ++++
 lib/util/wscript_build        |   1 +
 3 files changed, 570 insertions(+)
 create mode 100644 lib/util/tevent_req_profile.c
 create mode 100644 lib/util/tevent_req_profile.h

diff --git a/lib/util/tevent_req_profile.c b/lib/util/tevent_req_profile.c
new file mode 100644
index 00000000000..522741c5ede
--- /dev/null
+++ b/lib/util/tevent_req_profile.c
@@ -0,0 +1,519 @@
+/*
+ * Unix SMB/CIFS implementation.
+ *
+ * Helpers around tevent_req_profile
+ *
+ * Copyright (C) Volker Lendecke 2018
+ *
+ *   ** NOTE! The following LGPL license applies to the tevent
+ *   ** library. This does NOT imply that all of Samba is released
+ *   ** under the LGPL
+ *
+ * This library is free software; you can redistribute it and/or
+ * modify it under the terms of the GNU Lesser General Public
+ * License as published by the Free Software Foundation; either
+ * version 3 of the License, or (at your option) any later version.
+ *
+ * This library is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the GNU
+ * Lesser General Public License for more details.
+ *
+ * You should have received a copy of the GNU Lesser General Public
+ * License along with this library; if not, see <http://www.gnu.org/licenses/>.
+ */
+
+#include "replace.h"
+#include <tevent.h>
+#include "lib/util/tevent_req_profile.h"
+#include "lib/util/time_basic.h"
+#include "lib/util/memory.h"
+
+int tevent_req_profile_print(const struct tevent_req_profile *profile,
+			     FILE *fp,
+			     unsigned indent,
+			     unsigned max_indent)
+{
+	struct timeval start, stop, diff;
+	struct timeval_buf start_buf, stop_buf;
+	const char *req_name = NULL;
+	const char *start_location = NULL;
+	const char *stop_location = NULL;
+	pid_t pid;
+	enum tevent_req_state state;
+	const char *state_buf = NULL;
+	uint64_t user_error;
+	const struct tevent_req_profile *sub = NULL;
+	int ret;
+
+	tevent_req_profile_get_name(profile, &req_name);
+
+	tevent_req_profile_get_start(profile, &start_location, &start);
+	timeval_str_buf(&start, false, true, &start_buf);
+
+	tevent_req_profile_get_stop(profile, &stop_location, &stop);
+	timeval_str_buf(&stop, false, true, &stop_buf);
+
+	diff = tevent_timeval_until(&start, &stop);
+
+	tevent_req_profile_get_status(profile, &pid, &state, &user_error);
+
+	switch(state) {
+	case TEVENT_REQ_INIT:
+		state_buf = "TEVENT_REQ_INIT";
+		break;
+	case TEVENT_REQ_IN_PROGRESS:
+		state_buf = "TEVENT_REQ_IN_PROGRESS";
+		break;
+	case TEVENT_REQ_DONE:
+		state_buf = "TEVENT_REQ_DONE";
+		break;
+	case TEVENT_REQ_USER_ERROR:
+		state_buf = "TEVENT_REQ_USER_ERROR";
+		break;
+	case TEVENT_REQ_TIMED_OUT:
+		state_buf = "TEVENT_REQ_TIMED_OUT";
+		break;
+	case TEVENT_REQ_NO_MEMORY:
+		state_buf = "TEVENT_REQ_NO_MEMORY";
+		break;
+	case TEVENT_REQ_RECEIVED:
+		state_buf = "TEVENT_REQ_RECEIVED";
+		break;
+	default:
+		state_buf = "unknown";
+		break;
+	}
+
+	ret = fprintf(
+		fp,
+		"%*s[%s] %s [%s] %s [%s] [%ju.%.6ju] -> %s (%d %"PRIu64"))\n",
+		indent,
+		"",
+		req_name,
+		start_location,
+		start_buf.buf,
+		stop_location,
+		stop_buf.buf,
+		(uintmax_t)diff.tv_sec,
+		(uintmax_t)diff.tv_usec,
+		state_buf,
+		(int)state,
+		user_error);
+
+	if (ret < 0) {
+		return ret;
+	}
+
+	indent += 1;
+
+	if (indent >= max_indent) {
+		return ret;
+	}
+
+	for (sub = tevent_req_profile_get_subprofiles(profile);
+	     sub != NULL;
+	     sub = tevent_req_profile_next(sub)) {
+		int subret;
+
+		subret = tevent_req_profile_print(sub, fp, indent, max_indent);
+		if (subret < 0) {
+			return subret;
+		}
+
+		ret += subret;
+
+		if (ret < subret) {
+			/* overflow */
+			return -1;
+		}
+	}
+
+	return ret;
+}
+
+char *tevent_req_profile_string(const struct tevent_req_profile *profile,
+				TALLOC_CTX *mem_ctx,
+				unsigned indent,
+				unsigned max_indent)
+{
+	FILE *fp = NULL;
+	char *buf = NULL;
+	size_t buflen = 0;
+	char *result = NULL;
+	int ret;
+
+	fp = open_memstream(&buf, &buflen);
+	if (fp == NULL) {
+		return NULL;
+	}
+
+	ret = tevent_req_profile_print(profile, fp, 0, max_indent);
+	if (ret < 0) {
+		goto done;
+	}
+
+	ret = fclose(fp);
+	if (ret != 0) {
+		goto done;
+	}
+
+	/*
+	 * A FILE* from open_memstream maintains the 0-byte at the end
+	 * beyond the reported length.
+	 */
+	result = talloc_memdup(mem_ctx, buf, buflen+1);
+
+done:
+	SAFE_FREE(buf);
+	return result;
+}
+
+static ssize_t tevent_req_profile_pack_one(
+	const struct tevent_req_profile *profile,
+	uint8_t *buf,
+	size_t buflen)
+{
+	const char *req_name = NULL;
+	const char *start_location = NULL;
+	const char *stop_location = NULL;
+	struct timeval start_time, stop_time;
+	pid_t pid;
+	enum tevent_req_state state;
+	uint64_t user_error;
+	size_t pack_len, len;
+	int ret;
+
+	tevent_req_profile_get_name(profile, &req_name);
+	tevent_req_profile_get_start(profile, &start_location, &start_time);
+	tevent_req_profile_get_stop(profile, &stop_location, &stop_time);
+	tevent_req_profile_get_status(profile, &pid, &state, &user_error);
+
+	len = strlen(req_name)+1;
+	if (buflen >= len) {
+		memcpy(buf, req_name, len);
+		buf += len;
+		buflen -= len;
+	}
+
+	pack_len = len;
+
+	len = strlen(start_location)+1;
+	pack_len += len;
+	if (pack_len < len) {
+		return -1;	/* overflow */
+	}
+
+	if (buflen >= len) {
+		memcpy(buf, start_location, len);
+		buf += len;
+		buflen -= len;
+	}
+
+	len = strlen(stop_location)+1;
+	pack_len += len;
+	if (pack_len < len) {
+		return -1;	/* overflow */
+	}
+
+	if (buflen >= len) {
+		memcpy(buf, stop_location, len);
+		buf += len;
+		buflen -= len;
+	}
+
+	ret = snprintf((char *)buf,
+		       buflen,
+		       "%ju %ju %ju %ju %d %d %"PRIu64"",
+		       (uintmax_t)start_time.tv_sec,
+		       (uintmax_t)start_time.tv_usec,
+		       (uintmax_t)stop_time.tv_sec,
+		       (uintmax_t)stop_time.tv_usec,
+		       (int)pid,
+		       (int)state,
+		       user_error);
+	if (ret < 0) {
+		return -1;
+	}
+
+	/*
+	 * Take care of the trailing 0. No overflow check, this would
+	 * be a VERY small number of bits for "int".
+	 */
+	ret += 1;
+
+	pack_len += ret;
+
+	return pack_len;
+}
+
+ssize_t tevent_req_profile_pack(
+	const struct tevent_req_profile *profile,
+	uint8_t *buf,
+	size_t buflen)
+{
+	const struct tevent_req_profile *sub = NULL;
+	size_t num_sub;
+	ssize_t pack_len, profile_len;
+	int ret;
+
+	num_sub = 0;
+	pack_len = 0;
+
+	for (sub = tevent_req_profile_get_subprofiles(profile);
+	     sub != NULL;
+	     sub = tevent_req_profile_next(sub)) {
+		num_sub += 1;
+	}
+
+	ret = snprintf((char *)buf, buflen, "%zu ", num_sub);
+	if (ret < 0) {
+		return -1;
+	}
+
+	if (buflen > (size_t)ret) {
+		buf += ret;
+		buflen -= ret;
+	}
+
+	pack_len = ret;
+
+	profile_len = tevent_req_profile_pack_one(profile, buf, buflen);
+	if (profile_len == -1) {
+		return -1;
+	}
+
+	if (buflen >= (size_t)profile_len) {
+		buf += profile_len;
+		buflen -= profile_len;
+	}
+
+	pack_len += profile_len;
+	if (pack_len < profile_len) {
+		return -1;	/* overflow */
+	}
+
+	for (sub = tevent_req_profile_get_subprofiles(profile);
+	     sub != NULL;
+	     sub = tevent_req_profile_next(sub)) {
+
+		profile_len = tevent_req_profile_pack(sub, buf, buflen);
+		if (profile_len == -1) {
+			return -1;
+		}
+
+		if (buflen >= (size_t)profile_len) {
+			buf += profile_len;
+			buflen -= profile_len;
+		}
+
+		pack_len += profile_len;
+		if (pack_len < profile_len) {
+			return -1;	/* overflow */
+		}
+	}
+
+	return pack_len;
+}
+
+static bool parse_uintmax(const char *buf,
+			  char delimiter,
+			  uintmax_t *presult,
+			  char **p_endptr)
+{
+	uintmax_t result;
+	char *endptr;
+
+	result = strtoumax(buf, &endptr, 10);
+	if ((result == UINTMAX_MAX) && (errno == ERANGE)) {
+		return false;
+	}
+	if (*endptr != delimiter) {
+		return false;
+	}
+
+	*presult = result;
+	*p_endptr = endptr+1;
+
+	return true;
+}
+
+static ssize_t tevent_req_profile_unpack_one(
+	const uint8_t *buf,
+	size_t buflen,
+	struct tevent_req_profile *profile)
+{
+	const char *orig_buf = (const char *)buf;
+	const char *req_name = NULL;
+	const char *start_location = NULL;
+	const char *stop_location = NULL;
+	uintmax_t start_sec, start_usec, stop_sec, stop_usec, pid, state;
+	uintmax_t user_error;
+	char *next = NULL;
+	size_t len;
+	bool ok;
+
+	if (buflen == 0) {
+		return -1;
+	}
+	if (buf[buflen-1] != '\0') {
+		return -1;
+	}
+
+	req_name = (const char *)buf;
+	len = strlen(req_name)+1;
+
+	buf += len;
+	buflen -= len;
+	if (buflen == 0) {
+		return -1;
+	}
+
+	start_location = (const char *)buf;
+	len = strlen(start_location)+1;
+
+	buf += len;
+	buflen -= len;
+	if (buflen == 0) {
+		return -1;
+	}
+
+	stop_location = (const char *)buf;
+	len = strlen(stop_location)+1;
+
+	buf += len;
+	buflen -= len;
+	if (buflen == 0) {
+		return -1;
+	}
+
+	ok = parse_uintmax((const char *)buf, ' ', &start_sec, &next);
+	if (!ok) {
+		return -1;
+	}
+
+	ok = parse_uintmax(next, ' ', &start_usec, &next);
+	if (!ok) {
+		return -1;
+	}
+
+	ok = parse_uintmax(next, ' ', &stop_sec, &next);
+	if (!ok) {
+		return -1;
+	}
+
+	ok = parse_uintmax(next, ' ', &stop_usec, &next);
+	if (!ok) {
+		return -1;
+	}
+
+	ok = parse_uintmax(next, ' ', &pid, &next);
+	if (!ok) {
+		return -1;
+	}
+
+	ok = parse_uintmax(next, ' ', &state, &next);
+	if (!ok) {
+		return -1;
+	}
+
+	ok = parse_uintmax(next, '\0', &user_error, &next);
+	if (!ok) {
+		return -1;
+	}
+
+	ok = tevent_req_profile_set_name(profile, req_name);
+	if (!ok) {
+		return -1;
+	}
+
+	ok = tevent_req_profile_set_start(
+		profile,
+		start_location,
+		(struct timeval){ .tv_sec=start_sec, .tv_usec=start_usec });
+	if (!ok) {
+		return -1;
+	}
+
+	ok = tevent_req_profile_set_stop(
+		profile,
+		stop_location,
+		(struct timeval){ .tv_sec=stop_sec, .tv_usec=stop_usec });
+	if (!ok) {
+		return -1;
+	}
+
+	tevent_req_profile_set_status(
+		profile,
+		pid,
+		(enum tevent_req_state)state,
+		user_error);
+
+	return next - orig_buf;
+}
+
+ssize_t tevent_req_profile_unpack(
+	const uint8_t *buf,
+	size_t buflen,
+	TALLOC_CTX *mem_ctx,
+	struct tevent_req_profile **p_profile)
+{
+	const uint8_t *orig_buf = buf;
+	struct tevent_req_profile *profile = NULL;
+	uintmax_t i, num_subprofiles;
+	char *next = NULL;
+	bool ok;
+	ssize_t len;
+
+	errno = 0;
+
+	if (buf[buflen-1] != '\0') {
+		return -1;
+	}
+
+	ok = parse_uintmax((const char *)buf, ' ', &num_subprofiles, &next);
+	if (!ok) {
+		return -1;
+	}
+
+	len = (next - (const char *)buf);
+
+	buf += len;
+	buflen -= len;
+
+	profile = tevent_req_profile_create(mem_ctx);
+	if (profile == NULL) {
+		return -1;
+	}
+
+	len = tevent_req_profile_unpack_one(buf, buflen, profile);
+	if (len == -1) {
+		TALLOC_FREE(profile);
+		return -1;
+	}
+
+	buf += len;
+	buflen -= len;
+
+	for (i=0; i<num_subprofiles; i++) {
+		struct tevent_req_profile *subprofile;
+
+		len = tevent_req_profile_unpack(
+			buf,
+			buflen,
+			profile,
+			&subprofile);
+		if (len == -1) {
+			TALLOC_FREE(profile);
+			return -1;
+		}
+		buf += len;
+		buflen -= len;
+
+		tevent_req_profile_append_sub(profile, &subprofile);
+	}
+
+	*p_profile = profile;
+
+	return buf - orig_buf;
+}
diff --git a/lib/util/tevent_req_profile.h b/lib/util/tevent_req_profile.h
new file mode 100644
index 00000000000..00dbc5a9cc2
--- /dev/null
+++ b/lib/util/tevent_req_profile.h
@@ -0,0 +1,50 @@
+/*
+ * Unix SMB/CIFS implementation.
+ *
+ * Helpers around tevent_req_profile
+ *
+ * Copyright (C) Volker Lendecke 2018
+ *
+ *   ** NOTE! The following LGPL license applies to the tevent
+ *   ** library. This does NOT imply that all of Samba is released
+ *   ** under the LGPL
+ *
+ * This library is free software; you can redistribute it and/or
+ * modify it under the terms of the GNU Lesser General Public
+ * License as published by the Free Software Foundation; either
+ * version 3 of the License, or (at your option) any later version.
+ *
+ * This library is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the GNU
+ * Lesser General Public License for more details.
+ *
+ * You should have received a copy of the GNU Lesser General Public
+ * License along with this library; if not, see <http://www.gnu.org/licenses/>.
+ */
+
+#ifndef __LIB_UTIL_TEVENT_REQ_PROFILE_UNPACK
+#define __LIB_UTIL_TEVENT_REQ_PROFILE_UNPACK
+
+#include "replace.h"
+#include <tevent.h>
+
+int tevent_req_profile_print(const struct tevent_req_profile *profile,
+			     FILE *fp,
+			     unsigned indent,
+			     unsigned max_indent);
+char *tevent_req_profile_string(const struct tevent_req_profile *profile,
+				TALLOC_CTX *mem_ctx,
+				unsigned indent,
+				unsigned max_indent);
+ssize_t tevent_req_profile_pack(
+	const struct tevent_req_profile *profile,
+	uint8_t *buf,
+	size_t buflen);
+ssize_t tevent_req_profile_unpack(
+	const uint8_t *buf,
+	size_t buflen,
+	TALLOC_CTX *mem_ctx,
+	struct tevent_req_profile **p_profile);
+
+#endif
diff --git a/lib/util/wscript_build b/lib/util/wscript_build
index 793e24669c9..8fc402062fb 100644
--- a/lib/util/wscript_build
+++ b/lib/util/wscript_build
@@ -166,6 +166,7 @@ else:
                           tevent_unix.c
                           tevent_ntstatus.c
                           tevent_werror.c
+                          tevent_req_profile.c
                       ''',
                       local_include=False,
                       public_deps='tevent samba-errors',
-- 
2.11.0


From acd7956f52b9af5ac17890c7d300611dd7897fca Mon Sep 17 00:00:00 2001
From: Volker Lendecke <vl at samba.org>
Date: Wed, 2 May 2018 14:02:18 +0200
Subject: [PATCH 5/7] torture: Test tevent_req_profile

Signed-off-by: Volker Lendecke <vl at samba.org>
---
 lib/tevent/test_req.c               | 276 ++++++++++++++++++++++++++++++++++++
 source4/torture/local/local.c       |   1 +
 source4/torture/local/wscript_build |   1 +
 3 files changed, 278 insertions(+)
 create mode 100644 lib/tevent/test_req.c

diff --git a/lib/tevent/test_req.c b/lib/tevent/test_req.c
new file mode 100644
index 00000000000..888bd40bf2b
--- /dev/null
+++ b/lib/tevent/test_req.c
@@ -0,0 +1,276 @@
+/*
+ * Unix SMB/CIFS implementation.
+ *
+ * testing of some tevent_req aspects
+ *
+ * Copyright (C) Volker Lendecke 2018
+ *
+ *   ** NOTE! The following LGPL license applies to the tevent
+ *   ** library. This does NOT imply that all of Samba is released
+ *   ** under the LGPL
+ *
+ * This library is free software; you can redistribute it and/or
+ * modify it under the terms of the GNU Lesser General Public
+ * License as published by the Free Software Foundation; either
+ * version 3 of the License, or (at your option) any later version.
+ *
+ * This library is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the GNU
+ * Lesser General Public License for more details.
+ *
+ * You should have received a copy of the GNU Lesser General Public
+ * License along with this library; if not, see <http://www.gnu.org/licenses/>.
+ */
+
+#include "includes.h"
+#include "tevent.h"
+#include "torture/torture.h"
+#include "torture/local/proto.h"
+#include "lib/util/tevent_unix.h"
+#include "lib/util/tevent_req_profile.h"
+#include "lib/util/time_basic.h"
+
+struct tevent_req_create_state {
+	uint8_t val;
+};
+
+static bool test_tevent_req_create(struct torture_context *tctx,
+				   const void *test_data)
+{
+	struct tevent_req *req;
+	struct tevent_req_create_state *state;
+
+	req = tevent_req_create(tctx, &state,
+				struct tevent_req_create_state);
+	torture_assert(tctx, req != NULL, "tevent_req_create failed\n");
+	torture_assert(tctx, state->val == 0, "state not initialized\n");
+
+	TALLOC_FREE(req);
+
+	return true;
+}
+
+struct profile1_state {
+	uint8_t dummy;
+};
+
+static bool test_tevent_req_profile1(struct torture_context *tctx,
+				     const void *test_data)
+{
+	struct tevent_req *req;
+	struct profile1_state *state;
+	const struct tevent_req_profile *p1;
+	struct tevent_req_profile *p2;
+	struct timeval start, stop;
+	bool ok;
+	int cmp;
+
+	req = tevent_req_create(tctx, &state, struct profile1_state);
+	torture_assert(tctx, req != NULL, "tevent_req_create failed\n");
+
+	p1 = tevent_req_get_profile(req);
+	torture_assert(tctx, p1 == NULL, "profile not initialized to NULL\n");
+
+	ok = tevent_req_set_profile(req);
+	torture_assert(tctx, ok, "set_profile failed\n");
+
+	tevent_req_done(req);
+
+	p2 = tevent_req_move_profile(req, tctx);
+	torture_assert(tctx, p2 != NULL, "get_profile failed\n");
+
+	/* Demonstrate sure "p" outlives req */
+	TALLOC_FREE(req);
+
+	tevent_req_profile_get_start(p2, NULL, &start);
+	tevent_req_profile_get_stop(p2, NULL, &stop);
+
+	cmp = tevent_timeval_compare(&start, &stop);
+	torture_assert(tctx, cmp <= 0, "stop before start\n");
+
+	TALLOC_FREE(p2);
+
+	return true;
+}
+
+struct profile2_state {
+	uint8_t dummy;
+};
+
+static void profile2_done(struct tevent_req *subreq);
+
+static struct tevent_req *profile2_send(TALLOC_CTX *mem_ctx,
+					struct tevent_context *ev)
+{
+	struct tevent_req *req, *subreq;
+	struct profile2_state *state;
+	bool ok;
+
+	req = tevent_req_create(mem_ctx, &state, struct profile2_state);
+	if (req == NULL) {
+		return NULL;
+	}
+
+	ok = tevent_req_set_profile(req);
+	if (!ok) {
+		return tevent_req_post(req, ev);
+	}
+
+	subreq = tevent_wakeup_send(
+		state,
+		ev,
+		tevent_timeval_current_ofs(0, 1));
+	if (tevent_req_nomem(subreq, req)) {
+		return tevent_req_post(req, ev);
+	}
+	tevent_req_set_callback(subreq, profile2_done, req);
+
+	return req;
+}
+
+static void profile2_done(struct tevent_req *subreq)
+{
+	struct tevent_req *req = tevent_req_callback_data(
+		subreq, struct tevent_req);
+	bool ok;
+
+	ok = tevent_wakeup_recv(subreq);
+	if (!ok) {
+		tevent_req_oom(req);
+		return;
+	}
+	tevent_req_done(req);
+}
+
+static int profile2_recv(struct tevent_req *req,
+			  TALLOC_CTX *mem_ctx,
+			  struct tevent_req_profile **profile)
+{
+	int err;
+
+	if (tevent_req_is_unix_error(req, &err)) {
+		return err;
+	}
+
+	*profile = tevent_req_move_profile(req, mem_ctx);
+
+	return 0;
+}
+
+static bool test_tevent_req_profile2(struct torture_context *tctx,
+				     const void *test_data)
+{
+	struct tevent_context *ev;
+	struct tevent_req *req;
+	struct tevent_req_profile *p1 = NULL;
+	struct tevent_req_profile *p2 = NULL;
+	const char *str1, *str2;
+	struct timeval tv1, tv2;
+	pid_t pid1, pid2;
+	enum tevent_req_state state1, state2;
+	uint64_t err1, err2;
+	ssize_t pack_len;
+	int err;
+	bool ok;
+
+	ev = samba_tevent_context_init(tctx);
+	torture_assert(tctx, ev != NULL, "samba_tevent_context_init failed\n");
+
+	req = profile2_send(tctx, ev);
+	torture_assert(tctx, req != NULL, "profile2_send failed\n");
+
+	ok = tevent_req_poll_unix(req, ev, &err);
+	torture_assert(tctx, ok, "tevent_req_poll_unix failed\n");
+
+	err = profile2_recv(req, tctx, &p1);
+	torture_assert(tctx, err == 0, "profile2_recv failed\n");
+
+	TALLOC_FREE(req);
+	TALLOC_FREE(ev);
+
+	tevent_req_profile_print(p1, stdout, 0, UINT_MAX);
+
+	pack_len = tevent_req_profile_pack(p1, NULL, 0);
+	torture_assert(tctx, pack_len>0, "profile_pack failed\n");
+
+	{
+		uint8_t buf[pack_len];
+		ssize_t unpack_len;
+
+		tevent_req_profile_pack(p1, buf, sizeof(buf));
+		dump_data(10, buf, sizeof(buf));
+
+		unpack_len = tevent_req_profile_unpack(
+			buf,
+			pack_len,
+			tctx,
+			&p2);
+		torture_assert(tctx,
+			       pack_len==unpack_len,
+			       "profile_unpack failed\n");
+	}
+
+	tevent_req_profile_print(p2, stdout, 0, UINT_MAX);
+
+	tevent_req_profile_get_name(p1, &str1);
+	tevent_req_profile_get_name(p2, &str2);
+	torture_assert(tctx, strcmp(str1,str2)==0, "names differ\n");
+
+	tevent_req_profile_get_start(p1, &str1, &tv1);
+	tevent_req_profile_get_start(p2, &str2, &tv2);
+	torture_assert(tctx, strcmp(str1,str2)==0, "start strings differ\n");
+	torture_assert(tctx,
+		       tevent_timeval_compare(&tv1, &tv2) == 0,
+		       "start times differ\n");
+
+	tevent_req_profile_get_stop(p1, &str1, &tv1);
+	tevent_req_profile_get_stop(p2, &str2, &tv2);
+	torture_assert(tctx, strcmp(str1,str2)==0, "stop strings differ\n");
+	torture_assert(tctx,
+		       tevent_timeval_compare(&tv1, &tv2) == 0,
+		       "stop times differ\n");
+
+	tevent_req_profile_get_status(p1, &pid1, &state1, &err1);
+	tevent_req_profile_get_status(p2, &pid2, &state2, &err2);
+	torture_assert(tctx, pid1==pid2, "pids differ\n");
+	torture_assert(tctx, state1==state2, "states differ\n");
+	torture_assert(tctx, err1==err2, "user errors differ\n");
+
+	str1 = tevent_req_profile_string(p1, p1, 0, UINT_MAX);
+	torture_assert(tctx, str1!=NULL, "profile_string failed\n");
+	str2 = tevent_req_profile_string(p2, p2, 0, UINT_MAX);
+	torture_assert(tctx, str2!=NULL, "profile_string failed\n");
+
+	torture_assert(tctx, strcmp(str1,str2)==0, "result strings differ\n");
+
+	TALLOC_FREE(p1);
+	TALLOC_FREE(p2);
+
+	return true;
+}
+
+struct torture_suite *torture_local_tevent_req(TALLOC_CTX *mem_ctx)
+{
+	struct torture_suite *suite;
+
+	suite = torture_suite_create(mem_ctx, "tevent_req");
+
+	torture_suite_add_simple_tcase_const(
+		suite,
+		"create",
+		test_tevent_req_create,
+		NULL);
+	torture_suite_add_simple_tcase_const(
+		suite,
+		"profile1",
+		test_tevent_req_profile1,
+		NULL);
+	torture_suite_add_simple_tcase_const(
+		suite,
+		"profile2",
+		test_tevent_req_profile2,
+		NULL);
+
+	return suite;
+}
diff --git a/source4/torture/local/local.c b/source4/torture/local/local.c
index d1c523bdc1f..69ecc6b6ec8 100644
--- a/source4/torture/local/local.c
+++ b/source4/torture/local/local.c
@@ -64,6 +64,7 @@
 	torture_local_string_case,
 	torture_local_compression,
 	torture_local_event, 
+	torture_local_tevent_req,
 	torture_local_torture,
 	torture_local_dbspeed, 
 	torture_local_credentials,
diff --git a/source4/torture/local/wscript_build b/source4/torture/local/wscript_build
index 6cbb14d86e4..2dd18193c94 100644
--- a/source4/torture/local/wscript_build
+++ b/source4/torture/local/wscript_build
@@ -13,6 +13,7 @@ TORTURE_LOCAL_SOURCE = '''../../../lib/util/charset/tests/iconv.c
         ../../../lib/util/charset/tests/convert_string.c
 	../../libcli/security/tests/sddl.c ../../../lib/tdr/testsuite.c
 	../../../lib/tevent/testsuite.c ../../param/tests/share.c
+        ../../../lib/tevent/test_req.c
 	../../param/tests/loadparm.c ../../../auth/credentials/tests/simple.c local.c
 	dbspeed.c torture.c ../ldb/ldb.c ../../dsdb/common/tests/dsdb_dn.c
 	../../dsdb/schema/tests/schema_syntax.c
-- 
2.11.0


From d3bd4d2865ebc44609bcda0fccffd3d6ca9cd5df Mon Sep 17 00:00:00 2001
From: Volker Lendecke <vl at samba.org>
Date: Thu, 3 May 2018 15:12:55 +0200
Subject: [PATCH 6/7] winbind: Convert process_request() to tevent_req

Having a central tevent_req per winbind child request is prerequisite
for request profiling

Signed-off-by: Volker Lendecke <vl at samba.org>
---
 source3/winbindd/winbindd.c | 328 ++++++++++++++++++++++++--------------------
 1 file changed, 181 insertions(+), 147 deletions(-)

diff --git a/source3/winbindd/winbindd.c b/source3/winbindd/winbindd.c
index f0f0eef7bfc..56c5b6ed8e2 100644
--- a/source3/winbindd/winbindd.c
+++ b/source3/winbindd/winbindd.c
@@ -54,8 +54,6 @@
 static bool client_is_idle(struct winbindd_cli_state *state);
 static void remove_client(struct winbindd_cli_state *state);
 static void winbindd_setup_max_fds(void);
-static void request_ok(struct winbindd_cli_state *state);
-static void request_error(struct winbindd_cli_state *state);
 
 static bool opt_nocache = False;
 static bool interactive = False;
@@ -660,219 +658,222 @@ static struct winbindd_async_dispatch_table async_priv_table[] = {
 	{ 0, NULL, NULL, NULL }
 };
 
-static void wb_request_done(struct tevent_req *req);
+struct process_request_state {
+	struct winbindd_cli_state *cli_state;
+	struct tevent_context *ev;
+};
 
-static void process_request(struct winbindd_cli_state *state)
+static void process_request_done(struct tevent_req *subreq);
+static void process_request_written(struct tevent_req *subreq);
+
+static struct tevent_req *process_request_send(
+	TALLOC_CTX *mem_ctx,
+	struct tevent_context *ev,
+	struct winbindd_cli_state *cli_state)
 {
+	struct tevent_req *req, *subreq;
+	struct process_request_state *state;
 	struct winbindd_async_dispatch_table *atable;
+	enum winbindd_cmd cmd = cli_state->request->cmd;
 	size_t i;
 	bool ok;
 
-	state->mem_ctx = talloc_named(state, 0, "winbind request");
-	if (state->mem_ctx == NULL)
-		return;
+	req = tevent_req_create(mem_ctx, &state,
+				struct process_request_state);
+	if (req == NULL) {
+		return NULL;
+	}
+	state->cli_state = cli_state;
+	state->ev = ev;
+
+	SMB_ASSERT(cli_state->mem_ctx == NULL);
+	cli_state->mem_ctx = talloc_named(cli_state, 0, "winbind request");
+	if (tevent_req_nomem(cli_state->mem_ctx, req)) {
+		return tevent_req_post(req, ev);
+	}
+
+	cli_state->response = talloc_zero(
+		cli_state->mem_ctx,
+		struct winbindd_response);
+	if (tevent_req_nomem(cli_state->response, req)) {
+		return tevent_req_post(req, ev);
+	}
+	cli_state->response->result = WINBINDD_PENDING;
+	cli_state->response->length = sizeof(struct winbindd_response);
 
 	/* Remember who asked us. */
-	state->pid = state->request->pid;
+	cli_state->pid = cli_state->request->pid;
 
-	state->cmd_name = "unknown request";
-	state->recv_fn = NULL;
-	/* client is newest */
-	winbindd_promote_client(state);
+	cli_state->cmd_name = "unknown request";
+	cli_state->recv_fn = NULL;
 
-	/* Process command */
+	/* client is newest */
+	winbindd_promote_client(cli_state);
 
 	for (atable = async_nonpriv_table; atable->send_req; atable += 1) {
-		if (state->request->cmd == atable->cmd) {
+		if (cmd == atable->cmd) {
 			break;
 		}
 	}
 
-	if ((atable->send_req == NULL) && state->privileged) {
+	if ((atable->send_req == NULL) && cli_state->privileged) {
 		for (atable = async_priv_table; atable->send_req;
 		     atable += 1) {
-			if (state->request->cmd == atable->cmd) {
+			if (cmd == atable->cmd) {
 				break;
 			}
 		}
 	}
 
 	if (atable->send_req != NULL) {
-		struct tevent_req *req;
-
-		state->cmd_name = atable->cmd_name;
-		state->recv_fn = atable->recv_req;
+		cli_state->cmd_name = atable->cmd_name;
+		cli_state->recv_fn = atable->recv_req;
 
 		DEBUG(10, ("process_request: Handling async request %d:%s\n",
-			   (int)state->pid, state->cmd_name));
-
-		req = atable->send_req(state->mem_ctx, server_event_context(),
-				       state, state->request);
-		if (req == NULL) {
-			DEBUG(0, ("process_request: atable->send failed for "
-				  "%s\n", atable->cmd_name));
-			request_error(state);
-			return;
+			   (int)cli_state->pid, cli_state->cmd_name));
+
+		subreq = atable->send_req(
+			state,
+			state->ev,
+			cli_state,
+			cli_state->request);
+		if (tevent_req_nomem(subreq, req)) {
+			return tevent_req_post(req, ev);
 		}
-		tevent_req_set_callback(req, wb_request_done, state);
-		return;
+		tevent_req_set_callback(subreq, process_request_done, req);
+		return req;
 	}
 
-	state->response = talloc_zero(state->mem_ctx,
-				      struct winbindd_response);
-	if (state->response == NULL) {
-		DEBUG(10, ("talloc failed\n"));
-		remove_client(state);
-		return;
-	}
-	state->response->result = WINBINDD_PENDING;
-	state->response->length = sizeof(struct winbindd_response);
-
 	for (i=0; i<ARRAY_SIZE(bool_dispatch_table); i++) {
-		if (bool_dispatch_table[i].cmd == state->request->cmd) {
+		if (cmd == bool_dispatch_table[i].cmd) {
 			break;
 		}
 	}
 
-	if (i == ARRAY_SIZE(bool_dispatch_table)) {
-		DEBUG(10,("process_request: unknown request fn number %d\n",
-			  (int)state->request->cmd ));
-		request_error(state);
-		return;
-	}
-
-	DBG_DEBUG("process_request: request fn %s\n",
-		  bool_dispatch_table[i].cmd_name);
-
-	ok = bool_dispatch_table[i].fn(state);
+	ok = false;
 
-	if (ok) {
-		request_ok(state);
-	} else {
-		request_error(state);
+	if (i < ARRAY_SIZE(bool_dispatch_table)) {
+		DBG_DEBUG("process_request: request fn %s\n",
+			  bool_dispatch_table[i].cmd_name);
+		ok = bool_dispatch_table[i].fn(cli_state);
 	}
-}
 
-static void wb_request_done(struct tevent_req *req)
-{
-	struct winbindd_cli_state *state = tevent_req_callback_data(
-		req, struct winbindd_cli_state);
-	NTSTATUS status;
+	cli_state->response->result = ok ? WINBINDD_OK : WINBINDD_ERROR;
 
-	state->response = talloc_zero(state->mem_ctx,
-				      struct winbindd_response);
-	if (state->response == NULL) {
-		DEBUG(0, ("wb_request_done[%d:%s]: talloc_zero failed - removing client\n",
-			  (int)state->pid, state->cmd_name));
-		remove_client(state);
-		return;
-	}
-	state->response->result = WINBINDD_PENDING;
-	state->response->length = sizeof(struct winbindd_response);
+	TALLOC_FREE(cli_state->io_req);
+	TALLOC_FREE(cli_state->request);
 
-	status = state->recv_fn(req, state->response);
-	TALLOC_FREE(req);
+	subreq = wb_resp_write_send(
+		state,
+		state->ev,
+		cli_state->out_queue,
+		cli_state->sock,
+		cli_state->response);
+	if (tevent_req_nomem(subreq, req)) {
+		return tevent_req_post(req, ev);
+	}
+	tevent_req_set_callback(subreq, process_request_written, req);
 
-	DEBUG(10,("wb_request_done[%d:%s]: %s\n",
-		  (int)state->pid, state->cmd_name, nt_errstr(status)));
+	cli_state->io_req = subreq;
 
-	if (!NT_STATUS_IS_OK(status)) {
-		request_error(state);
-		return;
-	}
-	request_ok(state);
+	return req;
 }
 
-/*
- * This is the main event loop of winbind requests. It goes through a
- * state-machine of 3 read/write requests, 4 if you have extra data to send.
- *
- * An idle winbind client has a read request of 4 bytes outstanding,
- * finalizing function is request_len_recv, checking the length. request_recv
- * then processes the packet. The processing function then at some point has
- * to call request_finished which schedules sending the response.
- */
-
-static void request_finished(struct winbindd_cli_state *state);
+static void process_request_done(struct tevent_req *subreq)
+{
+	struct tevent_req *req = tevent_req_callback_data(
+		subreq, struct tevent_req);
+	struct process_request_state *state = tevent_req_data(
+		req, struct process_request_state);
+	struct winbindd_cli_state *cli_state = state->cli_state;
+	NTSTATUS status;
+	bool ok;
 
-static void winbind_client_request_read(struct tevent_req *req);
-static void winbind_client_response_written(struct tevent_req *req);
-static void winbind_client_activity(struct tevent_req *req);
+	status = cli_state->recv_fn(subreq, cli_state->response);
+	TALLOC_FREE(subreq);
 
-static void request_finished(struct winbindd_cli_state *state)
-{
-	struct tevent_req *req;
+	DBG_DEBUG("[%d:%s]: %s\n",
+		  (int)cli_state->pid,
+		  cli_state->cmd_name,
+		  nt_errstr(status));
 
-	/* free client socket monitoring request */
-	TALLOC_FREE(state->io_req);
+	ok = NT_STATUS_IS_OK(status);
+	cli_state->response->result = ok ? WINBINDD_OK : WINBINDD_ERROR;
 
-	TALLOC_FREE(state->request);
+	TALLOC_FREE(cli_state->io_req);
+	TALLOC_FREE(cli_state->request);
 
-	req = wb_resp_write_send(state, server_event_context(),
-				 state->out_queue, state->sock,
-				 state->response);
-	if (req == NULL) {
-		DEBUG(10,("request_finished[%d:%s]: wb_resp_write_send() failed\n",
-			  (int)state->pid, state->cmd_name));
-		remove_client(state);
+	subreq = wb_resp_write_send(
+		state,
+		state->ev,
+		cli_state->out_queue,
+		cli_state->sock,
+		cli_state->response);
+	if (tevent_req_nomem(subreq, req)) {
 		return;
 	}
-	tevent_req_set_callback(req, winbind_client_response_written, state);
-	state->io_req = req;
+	tevent_req_set_callback(subreq, process_request_written, req);
+
+	cli_state->io_req = subreq;
 }
 
-static void winbind_client_response_written(struct tevent_req *req)
+static void process_request_written(struct tevent_req *subreq)
 {
-	struct winbindd_cli_state *state = tevent_req_callback_data(
-		req, struct winbindd_cli_state);
+	struct tevent_req *req = tevent_req_callback_data(
+		subreq, struct tevent_req);
+	struct process_request_state *state = tevent_req_data(
+		req, struct process_request_state);
+	struct winbindd_cli_state *cli_state = state->cli_state;
 	ssize_t ret;
 	int err;
 
-	state->io_req = NULL;
+	cli_state->io_req = NULL;
 
-	ret = wb_resp_write_recv(req, &err);
-	TALLOC_FREE(req);
+	ret = wb_resp_write_recv(subreq, &err);
+	TALLOC_FREE(subreq);
 	if (ret == -1) {
-		close(state->sock);
-		state->sock = -1;
-		DEBUG(2, ("Could not write response[%d:%s] to client: %s\n",
-			  (int)state->pid, state->cmd_name, strerror(err)));
-		remove_client(state);
+		tevent_req_nterror(req, map_nt_error_from_unix(err));
 		return;
 	}
 
-	DEBUG(10,("winbind_client_response_written[%d:%s]: delivered response "
-		  "to client\n", (int)state->pid, state->cmd_name));
+	DBG_DEBUG("[%d:%s]: delivered response to client\n",
+		  (int)cli_state->pid, cli_state->cmd_name);
 
-	TALLOC_FREE(state->mem_ctx);
-	state->response = NULL;
-	state->cmd_name = "no request";
-	state->recv_fn = NULL;
+	TALLOC_FREE(cli_state->mem_ctx);
+	cli_state->response = NULL;
+	cli_state->cmd_name = "no request";
+	cli_state->recv_fn = NULL;
 
-	req = wb_req_read_send(state, server_event_context(), state->sock,
-			       WINBINDD_MAX_EXTRA_DATA);
-	if (req == NULL) {
-		remove_client(state);
-		return;
-	}
-	tevent_req_set_callback(req, winbind_client_request_read, state);
-	state->io_req = req;
+	tevent_req_done(req);
 }
 
-static void request_error(struct winbindd_cli_state *state)
+static NTSTATUS process_request_recv(struct tevent_req *req)
 {
-	SMB_ASSERT(state->response->result == WINBINDD_PENDING);
-	state->response->result = WINBINDD_ERROR;
-	request_finished(state);
-}
+	NTSTATUS status;
 
-static void request_ok(struct winbindd_cli_state *state)
-{
-	SMB_ASSERT(state->response->result == WINBINDD_PENDING);
-	state->response->result = WINBINDD_OK;
-	request_finished(state);
+	if (tevent_req_is_nterror(req, &status)) {
+		tevent_req_received(req);
+		return status;
+	}
+
+	tevent_req_received(req);
+	return NT_STATUS_OK;
 }
 
+/*
+ * This is the main event loop of winbind requests. It goes through a
+ * state-machine of 3 read/write requests, 4 if you have extra data to send.
+ *
+ * An idle winbind client has a read request of 4 bytes outstanding,
+ * finalizing function is request_len_recv, checking the length. request_recv
+ * then processes the packet. The processing function then at some point has
+ * to call request_finished which schedules sending the response.
+ */
+
+static void winbind_client_request_read(struct tevent_req *req);
+static void winbind_client_activity(struct tevent_req *req);
+static void winbind_client_processed(struct tevent_req *req);
+
 /* Process a new connection by adding it to the client connection list */
 
 static void new_connection(int listen_sock, bool privileged)
@@ -970,7 +971,13 @@ static void winbind_client_request_read(struct tevent_req *req)
 	tevent_req_set_callback(req, winbind_client_activity, state);
 	state->io_req = req;
 
-	process_request(state);
+	req = process_request_send(state, server_event_context(), state);
+	if (req == NULL) {
+		DBG_ERR("process_request_send failed\n");
+		remove_client(state);
+		return;
+	}
+	tevent_req_set_callback(req, winbind_client_processed, state);
 }
 
 static void winbind_client_activity(struct tevent_req *req)
@@ -1004,6 +1011,33 @@ static void winbind_client_activity(struct tevent_req *req)
 	remove_client(state);
 }
 
+static void winbind_client_processed(struct tevent_req *req)
+{
+	struct winbindd_cli_state *cli_state = tevent_req_callback_data(
+		req, struct winbindd_cli_state);
+	NTSTATUS status;
+
+	status = process_request_recv(req);
+	TALLOC_FREE(req);
+	if (!NT_STATUS_IS_OK(status)) {
+		DBG_DEBUG("process_request failed: %s\n", nt_errstr(status));
+		remove_client(cli_state);
+		return;
+	}
+
+	req = wb_req_read_send(
+		cli_state,
+		server_event_context(),
+		cli_state->sock,
+		WINBINDD_MAX_EXTRA_DATA);
+	if (req == NULL) {
+		remove_client(cli_state);
+		return;
+	}
+	tevent_req_set_callback(req, winbind_client_request_read, cli_state);
+	cli_state->io_req = req;
+}
+
 /* Remove a client connection from client connection list */
 
 static void remove_client(struct winbindd_cli_state *state)
-- 
2.11.0


From 76992bddc69c90112228b1f36a90d65d146e68f1 Mon Sep 17 00:00:00 2001
From: Volker Lendecke <vl at samba.org>
Date: Tue, 19 Jun 2018 11:13:19 +0200
Subject: [PATCH 7/7] winbindd: Do request profiling

By default we log a request that takes more than 60 seconds. This can be
changed by setting

winbind:request profile threshold = <seconds>

Another parameter controls the depth of the request hierarchy printed:

winbind:request profile depth = <n>

The default request logged to syslog via DEBUG(0) looks like the
following for a wbinfo -P:

[struct process_request_state] ../source3/winbindd/winbindd.c:683 [2018/06/19 13:33:14.190365] ../source3/winbindd/winbindd.c:853 [2018/06/19 13:33:14.192737] [0.002372] -> TEVENT_REQ_DONE (2 0))
 [struct winbindd_ping_dc_state] ../source3/winbindd/winbindd_ping_dc.c:41 [2018/06/19 13:33:14.190369] ../source3/winbindd/winbindd_ping_dc.c:112 [2018/06/19 13:33:14.192681] [0.002312] -> TEVENT_REQ_DONE (2 0))
  [struct dcerpc_wbint_PingDc_state] default/librpc/gen_ndr/ndr_winbind_c.c:4335 [2018/06/19 13:33:14.190383] default/librpc/gen_ndr/ndr_winbind_c.c:4396 [2018/06/19 13:33:14.192680] [0.002297] -> TEVENT_REQ_DONE (2 0))
   [struct dcerpc_wbint_PingDc_r_state] default/librpc/gen_ndr/ndr_winbind_c.c:4251 [2018/06/19 13:33:14.190385] default/librpc/gen_ndr/ndr_winbind_c.c:4285 [2018/06/19 13:33:14.192678] [0.002293] -> TEVENT_REQ_DONE (2 0))
    [struct dcerpc_binding_handle_call_state] ../librpc/rpc/binding_handle.c:371 [2018/06/19 13:33:14.190387] ../librpc/rpc/binding_handle.c:520 [2018/06/19 13:33:14.192675] [0.002288] -> TEVENT_REQ_DONE (2 0))
     [struct dcerpc_binding_handle_raw_call_state] ../librpc/rpc/binding_handle.c:149 [2018/06/19 13:33:14.190400] ../librpc/rpc/binding_handle.c:203 [2018/06/19 13:33:14.192646] [0.002246] -> TEVENT_REQ_DONE (2 0))
      [struct wbint_bh_raw_call_state] ../source3/winbindd/winbindd_dual_ndr.c:89 [2018/06/19 13:33:14.190402] ../source3/winbindd/winbindd_dual_ndr.c:204 [2018/06/19 13:33:14.192644] [0.002242] -> TEVENT_REQ_DONE (2 0))
       [struct wb_domain_request_state] ../source3/winbindd/winbindd_dual.c:473 [2018/06/19 13:33:14.190404] ../source3/winbindd/winbindd_dual.c:708 [2018/06/19 13:33:14.192640] [0.002236] -> TEVENT_REQ_DONE (2 0))
        [struct wb_child_request_state] ../source3/winbindd/winbindd_dual.c:198 [2018/06/19 13:33:14.190411] ../source3/winbindd/winbindd_dual.c:273 [2018/06/19 13:33:14.192638] [0.002227] -> TEVENT_REQ_DONE (2 0))
         [struct tevent_queue_wait_state] ../lib/tevent/tevent_queue.c:336 [2018/06/19 13:33:14.190412] ../lib/tevent/tevent_queue.c:355 [2018/06/19 13:33:14.190415] [0.000003] -> TEVENT_REQ_DONE (2 0))
         [struct wb_simple_trans_state] ../nsswitch/wb_reqtrans.c:375 [2018/06/19 13:33:14.190424] ../nsswitch/wb_reqtrans.c:432 [2018/06/19 13:33:14.192630] [0.002206] -> TEVENT_REQ_DONE (2 0))
          [struct req_write_state] ../nsswitch/wb_reqtrans.c:158 [2018/06/19 13:33:14.190425] ../nsswitch/wb_reqtrans.c:194 [2018/06/19 13:33:14.190472] [0.000047] -> TEVENT_REQ_DONE (2 0))
           [struct writev_state] ../lib/async_req/async_sock.c:263 [2018/06/19 13:33:14.190432] ../lib/async_req/async_sock.c:412 [2018/06/19 13:33:14.190470] [0.000038] -> TEVENT_REQ_DONE (2 0))
          [struct resp_read_state] ../nsswitch/wb_reqtrans.c:222 [2018/06/19 13:33:14.190475] ../nsswitch/wb_reqtrans.c:275 [2018/06/19 13:33:14.192629] [0.002154] -> TEVENT_REQ_DONE (2 0))
           [struct read_packet_state] ../lib/async_req/async_sock.c:458 [2018/06/19 13:33:14.190476] ../lib/async_req/async_sock.c:546 [2018/06/19 13:33:14.192626] [0.002150] -> TEVENT_REQ_DONE (2 0))
 [struct resp_write_state] ../nsswitch/wb_reqtrans.c:307 [2018/06/19 13:33:14.192693] ../nsswitch/wb_reqtrans.c:344 [2018/06/19 13:33:14.192734] [0.000041] -> TEVENT_REQ_DONE (2 0))
  [struct writev_state] ../lib/async_req/async_sock.c:263 [2018/06/19 13:33:14.192694] ../lib/async_req/async_sock.c:412 [2018/06/19 13:33:14.192732] [0.000038] -> TEVENT_REQ_DONE (2 0))

Signed-off-by: Volker Lendecke <vl at samba.org>
---
 source3/winbindd/winbindd.c | 46 +++++++++++++++++++++++++++++++++++++++++++--
 1 file changed, 44 insertions(+), 2 deletions(-)

diff --git a/source3/winbindd/winbindd.c b/source3/winbindd/winbindd.c
index 56c5b6ed8e2..254d93b344d 100644
--- a/source3/winbindd/winbindd.c
+++ b/source3/winbindd/winbindd.c
@@ -45,6 +45,7 @@
 #include "libsmb/samlogon_cache.h"
 #include "libcli/auth/netlogon_creds_cli.h"
 #include "passdb.h"
+#include "lib/util/tevent_req_profile.h"
 
 #undef DBGC_CLASS
 #define DBGC_CLASS DBGC_WINBIND
@@ -686,6 +687,11 @@ static struct tevent_req *process_request_send(
 	state->cli_state = cli_state;
 	state->ev = ev;
 
+	ok = tevent_req_set_profile(req);
+	if (!ok) {
+		return tevent_req_post(req, ev);
+	}
+
 	SMB_ASSERT(cli_state->mem_ctx == NULL);
 	cli_state->mem_ctx = talloc_named(cli_state, 0, "winbind request");
 	if (tevent_req_nomem(cli_state->mem_ctx, req)) {
@@ -847,7 +853,10 @@ static void process_request_written(struct tevent_req *subreq)
 	tevent_req_done(req);
 }
 
-static NTSTATUS process_request_recv(struct tevent_req *req)
+static NTSTATUS process_request_recv(
+	struct tevent_req *req,
+	TALLOC_CTX *mem_ctx,
+	struct tevent_req_profile **profile)
 {
 	NTSTATUS status;
 
@@ -856,6 +865,7 @@ static NTSTATUS process_request_recv(struct tevent_req *req)
 		return status;
 	}
 
+	*profile = tevent_req_move_profile(req, mem_ctx);
 	tevent_req_received(req);
 	return NT_STATUS_OK;
 }
@@ -1015,9 +1025,12 @@ static void winbind_client_processed(struct tevent_req *req)
 {
 	struct winbindd_cli_state *cli_state = tevent_req_callback_data(
 		req, struct winbindd_cli_state);
+	struct tevent_req_profile *profile = NULL;
+	struct timeval start, stop, diff;
+	int threshold;
 	NTSTATUS status;
 
-	status = process_request_recv(req);
+	status = process_request_recv(req, cli_state, &profile);
 	TALLOC_FREE(req);
 	if (!NT_STATUS_IS_OK(status)) {
 		DBG_DEBUG("process_request failed: %s\n", nt_errstr(status));
@@ -1025,6 +1038,35 @@ static void winbind_client_processed(struct tevent_req *req)
 		return;
 	}
 
+	tevent_req_profile_get_start(profile, NULL, &start);
+	tevent_req_profile_get_stop(profile, NULL, &stop);
+	diff = tevent_timeval_until(&start, &stop);
+
+	threshold = lp_parm_int(-1, "winbind", "request profile threshold", 60);
+
+	if (diff.tv_sec >= threshold) {
+		int depth;
+		char *str;
+
+		depth = lp_parm_int(
+			-1,
+			"winbind",
+			"request profile depth",
+			INT_MAX);
+
+		DBG_ERR("request took %u.%.6u seconds\n",
+			(unsigned)diff.tv_sec, (unsigned)diff.tv_usec);
+
+		str = tevent_req_profile_string(profile, talloc_tos(), 0, depth);
+		if (str != NULL) {
+			/* No "\n", already contained in "str" */
+			DEBUGADD(0, ("%s", str));
+		}
+		TALLOC_FREE(str);
+	}
+
+	TALLOC_FREE(profile);
+
 	req = wb_req_read_send(
 		cli_state,
 		server_event_context(),
-- 
2.11.0



More information about the samba-technical mailing list