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@samba.org>
Reviewed-by: Ralph Boehme <slow@samba.org>

1 files 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(),