sin/samba-mirror
1
0
Fork 0
mirror of https://github.com/samba-team/samba.git synced 2025-03-01 04:58:35 +03:00
Code

winbindd: Do request profiling

Browse Source 
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>
This commit is contained in:
Volker Lendecke 2018-06-19 11:13:19 +02:00 committed by Ralph Boehme
parent 5af9ecf6f0
commit bb683535f1
1 changed files with 44 additions and 2 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

46
source3/winbindd/winbindd.c
View File

@ -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(),