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>

diff --git a/source3/winbindd/winbindd.c b/source3/winbindd/winbindd.c
index 56c5b6ed8e2e6c5d152169f914755e53f33c6e7a..254d93b344ddbe76b40372c22de9edc03a527fd5 100644 (file)
--- 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(),