winbindd: Do request profiling
authorVolker Lendecke <vl@samba.org>
Tue, 19 Jun 2018 09:13:19 +0000 (11:13 +0200)
committerRalph Boehme <slow@samba.org>
Wed, 11 Jul 2018 21:04:23 +0000 (23:04 +0200)
commitbb683535f1e97b2f5a401575e38c78ad917a286c
tree763ab26485c8e2465976dd3e3791bf769e46e758
parent5af9ecf6f021552f38021b138850bc4020693270
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>
source3/winbindd/winbindd.c