diff options
author | Volker Lendecke <vl@samba.org> | 2018-06-19 11:13:19 +0200 |
---|---|---|
committer | Ralph Boehme <slow@samba.org> | 2018-07-11 23:04:23 +0200 |
commit | bb683535f1e97b2f5a401575e38c78ad917a286c (patch) | |
tree | 763ab26485c8e2465976dd3e3791bf769e46e758 /source3 | |
parent | 5af9ecf6f021552f38021b138850bc4020693270 (diff) | |
download | samba-bb683535f1e97b2f5a401575e38c78ad917a286c.tar.gz |
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>
Diffstat (limited to 'source3')
-rw-r--r-- | source3/winbindd/winbindd.c | 46 |
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(), |