On Mon, Nov 28, 2016 at 02:45:59PM +1100, Lachlan Musicman wrote:
I'm on Centos 7.2 and thought I'd try this to see how it
works. Instead of
nice output I got and error. Have I done something wrong?
[root@linux systemtap]# stap id_perf.stp
ERROR: empty aggregate near identifier 'print' at id_perf.stp:68:5
Ah, sorry, this is a silly bug in the script. In your case, id returned
data from the cache (as you can see the time id ran was only 3ms) so
there were no writable transactions done and the script ended up
dereferencing an empty aggregate that normally saves the transaction
times.
I've opened a PR on github to fix the script, but runnning sss_cache
before you run the script next time should give 'better' results.
Total run time of id was: 3 ms
Number of zero-level cache transactions: 0
Time spent in level-0 sysdb transactions: 0 ms
Time spent writing to LDB: 0 ms
Number of LDAP searches: 0
Time spent waiting for LDAP: 0 ms
LDAP searches breakdown:
Number of user requests: 0
Time spent in user requests: 0
Number of group requests: 0
Time spent in group requests: 0
Number of initgroups requests: 0
Time spent in initgroups requests: 0
Unaccounted time: 3 ms
sysdb transaction breakdown:
The most expensive transaction breakdown, per transaction:
WARNING: Number of errors: 1, skipped probes: 0
WARNING: /usr/bin/staprun exited with status: 1
Pass 5: run failed. [man error::pass5]
------
The most dangerous phrase in the language is, "We've always done it this
way."
- Grace Hopper
On 26 November 2016 at 10:05, <zfnoctis(a)gmail.com> wrote:
> Sorry for the delay, the holidays managed to take up more of my spare time
> than anticipated.
>
> This was done on Fedora workstation 25. Overall sssd performance appears
> to be noticeably better than Ubuntu 16.04/16.10 and Fedora 24. Please let
> me know if I made any mistakes running these tests, or if I need to run
> additional tests.
>
> ############################################################
> ########################################
> This was my quick attempt at the USE method in order to rule out other
> causes of performance issues.
> ############################################################
> ########################################
> task: id <domain user>
>
> vmstat, pidstat, and top/htop are showing high amounts of CPU time being
> spent in user-space. Looks to be sssd_be.
>
> e.g. from pidstat
> 02:34:39 PM UID PID %usr %system %guest %CPU CPU
> Command
> 02:34:40 PM 0 12518 100.00 0.00 0.00 100.00 0
> sssd_be
>
>
> iostat is showing minimal I/O occurring, disks are mostly idle. Not
> seeing any errors or queuing.
>
> nicstat shows network interfaces never go above 60% utilization. No
> network errors reported. No queuing.
>
> free is not showing any serious memory pressure, no swapping is occurring.
>
> Unsure how to measure interconnects between subsystems. May use
> perf/systemtap.
>
> ############################################################
> ########################################
>
> These runs were of id <domainuser> and each was of a different user so as
> to hopefully avoid caching.
> Each time there were warnings of missing unwind data, is there a set of
> packages I need to install to resolve this?
>
> ############################################################
> ########################################
>
> [root@fc25-vm systemtap]# stap id_perf.stp
> WARNING: Missing unwind data for a module, rerun with 'stap -d
> /usr/lib64/libtevent.so.0.9.30'
> Total run time of id was: 91098 ms
> Number of zero-level cache transactions: 15
> Time spent in level-0 sysdb transactions: 324 ms
> Time spent writing to LDB: 93 ms
> Number of LDAP searches: 83
> Time spent waiting for LDAP: 1480105770919 ms
> LDAP searches breakdown:
> Number of user requests: 0
> Time spent in user requests: 0
>
> Number of group requests: 14
> Time spent in group requests: 1933
>
> Number of initgroups requests: 0
> Time spent in initgroups requests: 0
>
> Unaccounted time: -1480105680145 ms
> sysdb transaction breakdown:
> 1 hits of transaction sysdb_transaction_commit+0xa0 [libsss_util.so]
> sdap_nested_done+0x2d5 [libsss_ldap_common.so]
> sdap_nested_group_process_done+0x1fe [libsss_ldap_common.so]
> sdap_nested_group_process_done+0x1fe [libsss_ldap_common.so]
> 0x7f78b9781474 [libtevent.so.0.9.30+0x5474]
> avg:36 min: 36 max: 36 sum: 36
>
> 8 hits of transaction sysdb_transaction_commit+0xa0 [libsss_util.so]
> sdap_nested_done+0x2d5 [libsss_ldap_common.so]
> sdap_nested_group_process_done+0x1fe [libsss_ldap_common.so]
> 0x7f78b9781474 [libtevent.so.0.9.30+0x5474]
> avg:21 min: 19 max: 28 sum: 171
>
> 4 hits of transaction sysdb_transaction_commit+0xa0 [libsss_util.so]
> sdap_nested_done+0x2d5 [libsss_ldap_common.so]
> sdap_nested_group_process_done+0x21e [libsss_ldap_common.so]
> 0x7f78b9781474 [libtevent.so.0.9.30+0x5474]
> avg:29 min: 21 max: 52 sum: 117
>
> The most expensive transaction breakdown, per transaction:
> value |-------------------------------------------------- count
> 0 |@@@ 3
> 50 |@ 1
> 100 | 0
> 150 | 0
>
> ############################################################
> ########################################
>
> [root@fc25-vm systemtap]# stap -d /usr/lib64/libtevent.so.0.9.30
> id_perf.stp
> WARNING: Missing unwind data for a module, rerun with 'stap -d
> /usr/libexec/sssd/sssd_be'
> Total run time of id was: 102614 ms
> Number of zero-level cache transactions: 34
> Time spent in level-0 sysdb transactions: 7789 ms
> Time spent writing to LDB: 519 ms
> Number of LDAP searches: 742
> Time spent waiting for LDAP: 51312 ms
> LDAP searches breakdown:
> Number of user requests: 1
> Time spent in user requests: 144
>
> Number of group requests: 30
> Time spent in group requests: 50523
>
> Number of initgroups requests: 1
> Time spent in initgroups requests: 465
>
> Unaccounted time: 43513 ms
> sysdb transaction breakdown:
> 2 hits of transaction sysdb_transaction_commit+0xa0 [libsss_util.so]
> sdap_nested_done+0x2d5 [libsss_ldap_common.so]
> sdap_nested_group_process_done+0x1fe [libsss_ldap_common.so]
> tevent_common_loop_immediate+0xd4 [libtevent.so.0.9.30]
> epoll_event_loop_once+0x5d [libtevent.so.0.9.30]
> std_event_loop_once+0x37 [libtevent.so.0.9.30]
> _tevent_loop_once+0x9d [libtevent.so.0.9.30]
> tevent_common_loop_wait+0x1b [libtevent.so.0.9.30]
> std_event_loop_wait+0x37 [libtevent.so.0.9.30]
> server_loop+0x13 [libsss_util.so]
> 0x55a92ac7c677 [sssd_be+0x8
> avg:22 min: 22 max: 23 sum: 45
>
> 1 hits of transaction sysdb_transaction_commit+0xa0 [libsss_util.so]
> sdap_nested_done+0x2d5 [libsss_ldap_common.so]
> sdap_nested_group_process_done+0x1fe [libsss_ldap_common.so]
> sdap_nested_group_process_done+0x1fe [libsss_ldap_common.so]
> tevent_common_loop_immediate+0xd4 [libtevent.so.0.9.30]
> epoll_event_loop_once+0x5d [libtevent.so.0.9.30]
> std_event_loop_once+0x37 [libtevent.so.0.9.30]
> _tevent_loop_once+0x9d [libtevent.so.0.9.30]
> tevent_common_loop_wait+0x1b [libtevent.so.0.9.30]
> std_event_loop_wait+0x37 [libtevent.so.0.9.30]
>
> avg:53 min: 53 max: 53 sum: 53
>
> 4 hits of transaction sysdb_transaction_commit+0xa0 [libsss_util.so]
> sdap_nested_done+0x2d5 [libsss_ldap_common.so]
> sdap_nested_group_process_done+0x21e [libsss_ldap_common.so]
> tevent_common_loop_immediate+0xd4 [libtevent.so.0.9.30]
> epoll_event_loop_once+0x5d [libtevent.so.0.9.30]
> std_event_loop_once+0x37 [libtevent.so.0.9.30]
> _tevent_loop_once+0x9d [libtevent.so.0.9.30]
> tevent_common_loop_wait+0x1b [libtevent.so.0.9.30]
> std_event_loop_wait+0x37 [libtevent.so.0.9.30]
> server_loop+0x13 [libsss_util.so]
> 0x55fcef0ca677 [sssd_be+0x8
> avg:22 min: 22 max: 23 sum: 90
>
> 2 hits of transaction sysdb_transaction_commit+0xa0 [libsss_util.so]
> sdap_nested_done+0x2d5 [libsss_ldap_common.so]
> sdap_nested_group_process_done+0x21e [libsss_ldap_common.so]
> tevent_common_loop_immediate+0xd4 [libtevent.so.0.9.30]
> epoll_event_loop_once+0x5d [libtevent.so.0.9.30]
> std_event_loop_once+0x37 [libtevent.so.0.9.30]
> _tevent_loop_once+0x9d [libtevent.so.0.9.30]
> tevent_common_loop_wait+0x1b [libtevent.so.0.9.30]
> std_event_loop_wait+0x37 [libtevent.so.0.9.30]
> server_loop+0x13 [libsss_util.so]
> 0x55a92ac7c677 [sssd_be+0x8
> avg:2635 min: 67 max: 5203 sum: 5270
>
> 2 hits of transaction sysdb_transaction_commit+0xa0 [libsss_util.so]
> sdap_nested_done+0x2d5 [libsss_ldap_common.so]
> tevent_common_loop_immediate+0xd4 [libtevent.so.0.9.30]
> epoll_event_loop_once+0x5d [libtevent.so.0.9.30]
> std_event_loop_once+0x37 [libtevent.so.0.9.30]
> _tevent_loop_once+0x9d [libtevent.so.0.9.30]
> tevent_common_loop_wait+0x1b [libtevent.so.0.9.30]
> std_event_loop_wait+0x37 [libtevent.so.0.9.30]
> server_loop+0x13 [libsss_util.so]
> 0x55fcef0ca677 [sssd_be+0x8677]
> avg:25 min: 25 max: 26 sum: 51
>
> 1 hits of transaction sysdb_transaction_commit+0xa0 [libsss_util.so]
> sdap_nested_done+0x2d5 [libsss_ldap_common.so]
> sdap_nested_group_process_done+0x21e [libsss_ldap_common.so]
> sdap_nested_group_process_done+0x1fe [libsss_ldap_common.so]
> sdap_nested_group_process_done+0x1fe [libsss_ldap_common.so]
> tevent_common_loop_immediate+0xd4 [libtevent.so.0.9.30]
> epoll_event_loop_once+0x5d [libtevent.so.0.9.30]
> std_event_loop_once+0x37 [libtevent.so.0.9.30]
> _tevent_loop_once+0x9d [libtevent.so.0.9.30]
> tevent_common_loop_wait+0x1b [libteve
> avg:1539 min: 1539 max: 1539 sum: 1539
>
> 1 hits of transaction sysdb_transaction_commit+0xa0 [libsss_util.so]
> sdap_ad_save_group_membership_with_idmapping+0x532 [libsss_ldap_common.so]
> sdap_ad_tokengroups_initgr_mapping_done+0x13b [libsss_ldap_common.so]
> sdap_get_ad_tokengroups_done+0x22f [libsss_ldap_common.so]
> generic_ext_search_handler.isra.4+0xe0 [libsss_ldap_common.so]
> sdap_get_generic_op_finished+0x5ba [libsss_ldap_common.so]
> sdap_process_result+0x71d [libsss_ldap_common.so]
> tevent_common_loop_timer_delay+0xd0 [libtevent.so.0.9.30]
> epoll_event_loop_once+0x69 [li
> avg:60 min: 60 max: 60 sum: 60
>
> 14 hits of transaction sysdb_transaction_commit+0xa0 [libsss_util.so]
> sdap_nested_done+0x2d5 [libsss_ldap_common.so]
> sdap_nested_group_process_done+0x1fe [libsss_ldap_common.so]
> tevent_common_loop_immediate+0xd4 [libtevent.so.0.9.30]
> epoll_event_loop_once+0x5d [libtevent.so.0.9.30]
> std_event_loop_once+0x37 [libtevent.so.0.9.30]
> _tevent_loop_once+0x9d [libtevent.so.0.9.30]
> tevent_common_loop_wait+0x1b [libtevent.so.0.9.30]
> std_event_loop_wait+0x37 [libtevent.so.0.9.30]
> server_loop+0x13 [libsss_util.so]
> 0x55fcef0ca677 [sssd_be+0x8
> avg:29 min: 20 max: 47 sum: 416
>
> 1 hits of transaction sysdb_transaction_commit+0xa0 [libsss_util.so]
> sdap_save_users+0x28a [libsss_ldap_common.so]
> sdap_get_users_done+0xd2 [libsss_ldap_common.so]
> sdap_search_user_process+0x25f [libsss_ldap_common.so]
> generic_ext_search_handler.isra.4+0xe0 [libsss_ldap_common.so]
> sdap_get_generic_op_finished+0x5ba [libsss_ldap_common.so]
> sdap_process_result+0x71d [libsss_ldap_common.so]
> tevent_common_loop_timer_delay+0xd0 [libtevent.so.0.9.30]
> epoll_event_loop_once+0x69 [libtevent.so.0.9.30]
> std_event_loop_once+0x37 [libtevent
> avg:116 min: 116 max: 116 sum: 116
>
> 1 hits of transaction sysdb_transaction_commit+0xa0 [libsss_util.so]
> sdap_nested_done+0x2d5 [libsss_ldap_common.so]
> sdap_nested_group_process_done+0x1fe [libsss_ldap_common.so]
> sdap_nested_group_process_done+0x21e [libsss_ldap_common.so]
> tevent_common_loop_immediate+0xd4 [libtevent.so.0.9.30]
> epoll_event_loop_once+0x5d [libtevent.so.0.9.30]
> std_event_loop_once+0x37 [libtevent.so.0.9.30]
> _tevent_loop_once+0x9d [libtevent.so.0.9.30]
> tevent_common_loop_wait+0x1b [libtevent.so.0.9.30]
> std_event_loop_wait+0x37 [libtevent.so.0.9.30]
>
> avg:83 min: 83 max: 83 sum: 83
>
> 1 hits of transaction sysdb_transaction_commit+0xa0 [libsss_util.so]
> sdap_get_initgr_user+0x216 [libsss_ldap_common.so]
> generic_ext_search_handler.isra.4+0xe0 [libsss_ldap_common.so]
> sdap_get_generic_op_finished+0x5ba [libsss_ldap_common.so]
> sdap_process_result+0x71d [libsss_ldap_common.so]
> tevent_common_loop_timer_delay+0xd0 [libtevent.so.0.9.30]
> epoll_event_loop_once+0x69 [libtevent.so.0.9.30]
> std_event_loop_once+0x37 [libtevent.so.0.9.30]
> _tevent_loop_once+0x9d [libtevent.so.0.9.30]
> tevent_common_loop_wait+0x1b [libtevent.so
> avg:6 min: 6 max: 6 sum: 6
>
> 2 hits of transaction sysdb_transaction_commit+0xa0 [libsss_util.so]
> sdap_nested_done+0x2d5 [libsss_ldap_common.so]
> sdap_nested_group_process_done+0x21e [libsss_ldap_common.so]
> sdap_nested_group_process_done+0x1fe [libsss_ldap_common.so]
> tevent_common_loop_immediate+0xd4 [libtevent.so.0.9.30]
> epoll_event_loop_once+0x5d [libtevent.so.0.9.30]
> std_event_loop_once+0x37 [libtevent.so.0.9.30]
> _tevent_loop_once+0x9d [libtevent.so.0.9.30]
> tevent_common_loop_wait+0x1b [libtevent.so.0.9.30]
> std_event_loop_wait+0x37 [libtevent.so.0.9.30]
>
> avg:30 min: 26 max: 34 sum: 60
>
> The most expensive transaction breakdown, per transaction:
> value |-------------------------------------------------- count
> 0 | 0
> 50 |@ 1
> 100 | 0
> 150 | 0
> ~
> 450 | 0
> 500 | 0
> >500 |@ 1
>
> ############################################################
> ########################################
>
> [root@fc25-vm systemtap]# stap -d /usr/lib64/libtevent.so.0.9.30 -d
> /usr/libexec/sssd/sssd_be id_perf.stp
> WARNING: Missing unwind data for a module, rerun with 'stap -d /usr/lib64/
> libc-2.24.so'
> Total run time of id was: 162710 ms
> Number of zero-level cache transactions: 32
> Time spent in level-0 sysdb transactions: 944 ms
> Time spent writing to LDB: 301 ms
> Number of LDAP searches: 141
> Time spent waiting for LDAP: 77244 ms
> LDAP searches breakdown:
> Number of user requests: 1
> Time spent in user requests: 136
>
> Number of group requests: 29
> Time spent in group requests: 3561
>
> Number of initgroups requests: 1
> Time spent in initgroups requests: 143
>
> Unaccounted time: 84522 ms
> sysdb transaction breakdown:
> 9 hits of transaction sysdb_transaction_commit+0xa0 [libsss_util.so]
> sdap_nested_done+0x2d5 [libsss_ldap_common.so]
> sdap_nested_group_process_done+0x1fe [libsss_ldap_common.so]
> tevent_common_loop_immediate+0xd4 [libtevent.so.0.9.30]
> epoll_event_loop_once+0x5d [libtevent.so.0.9.30]
> std_event_loop_once+0x37 [libtevent.so.0.9.30]
> _tevent_loop_once+0x9d [libtevent.so.0.9.30]
> tevent_common_loop_wait+0x1b [libtevent.so.0.9.30]
> std_event_loop_wait+0x37 [libtevent.so.0.9.30]
> server_loop+0x13 [libsss_util.so]
> main+0x707 [sssd_be]
> 0x7f76
> avg:28 min: 22 max: 37 sum: 254
>
> 1 hits of transaction sysdb_transaction_commit+0xa0 [libsss_util.so]
> sdap_get_initgr_user+0x216 [libsss_ldap_common.so]
> generic_ext_search_handler.isra.4+0xe0 [libsss_ldap_common.so]
> sdap_get_generic_op_finished+0x5ba [libsss_ldap_common.so]
> sdap_process_result+0x71d [libsss_ldap_common.so]
> tevent_common_loop_timer_delay+0xd0 [libtevent.so.0.9.30]
> epoll_event_loop_once+0x69 [libtevent.so.0.9.30]
> std_event_loop_once+0x37 [libtevent.so.0.9.30]
> _tevent_loop_once+0x9d [libtevent.so.0.9.30]
> tevent_common_loop_wait+0x1b [libtevent.so
> avg:5 min: 5 max: 5 sum: 5
>
> 3 hits of transaction sysdb_transaction_commit+0xa0 [libsss_util.so]
> sdap_nested_done+0x2d5 [libsss_ldap_common.so]
> tevent_common_loop_immediate+0xd4 [libtevent.so.0.9.30]
> epoll_event_loop_once+0x5d [libtevent.so.0.9.30]
> std_event_loop_once+0x37 [libtevent.so.0.9.30]
> _tevent_loop_once+0x9d [libtevent.so.0.9.30]
> tevent_common_loop_wait+0x1b [libtevent.so.0.9.30]
> std_event_loop_wait+0x37 [libtevent.so.0.9.30]
> server_loop+0x13 [libsss_util.so]
> main+0x707 [sssd_be]
> 0x7f7675d86401 [libc-2.24.so+0x20401]
> avg:21 min: 21 max: 22 sum: 64
>
> 1 hits of transaction sysdb_transaction_commit+0xa0 [libsss_util.so]
> sdap_nested_done+0x2d5 [libsss_ldap_common.so]
> sdap_nested_group_process_done+0x21e [libsss_ldap_common.so]
> tevent_common_loop_immediate+0xd4 [libtevent.so.0.9.30]
> epoll_event_loop_once+0x5d [libtevent.so.0.9.30]
> std_event_loop_once+0x37 [libtevent.so.0.9.30]
> _tevent_loop_once+0x9d [libtevent.so.0.9.30]
> tevent_common_loop_wait+0x1b [libtevent.so.0.9.30]
> std_event_loop_wait+0x37 [libtevent.so.0.9.30]
> server_loop+0x13 [libsss_util.so]
> main+0x707 [sssd_be]
> 0x7fc1
> avg:35 min: 35 max: 35 sum: 35
>
> 1 hits of transaction sysdb_transaction_commit+0xa0 [libsss_util.so]
> sdap_nested_done+0x2d5 [libsss_ldap_common.so]
> sdap_nested_group_process_done+0x1fe [libsss_ldap_common.so]
> sdap_nested_group_process_done+0x21e [libsss_ldap_common.so]
> tevent_common_loop_immediate+0xd4 [libtevent.so.0.9.30]
> epoll_event_loop_once+0x5d [libtevent.so.0.9.30]
> std_event_loop_once+0x37 [libtevent.so.0.9.30]
> _tevent_loop_once+0x9d [libtevent.so.0.9.30]
> tevent_common_loop_wait+0x1b [libtevent.so.0.9.30]
> std_event_loop_wait+0x37 [libtevent.so.0.9.30]
>
> avg:42 min: 42 max: 42 sum: 42
>
> 1 hits of transaction sysdb_transaction_commit+0xa0 [libsss_util.so]
> sdap_ad_save_group_membership_with_idmapping+0x532 [libsss_ldap_common.so]
> sdap_ad_tokengroups_initgr_mapping_done+0x13b [libsss_ldap_common.so]
> sdap_get_ad_tokengroups_done+0x22f [libsss_ldap_common.so]
> generic_ext_search_handler.isra.4+0xe0 [libsss_ldap_common.so]
> sdap_get_generic_op_finished+0x5ba [libsss_ldap_common.so]
> sdap_process_result+0x71d [libsss_ldap_common.so]
> tevent_common_loop_timer_delay+0xd0 [libtevent.so.0.9.30]
> epoll_event_loop_once+0x69 [li
> avg:86 min: 86 max: 86 sum: 86
>
> 2 hits of transaction sysdb_transaction_commit+0xa0 [libsss_util.so]
> sdap_nested_done+0x2d5 [libsss_ldap_common.so]
> sdap_nested_group_process_done+0x21e [libsss_ldap_common.so]
> sdap_nested_group_process_done+0x1fe [libsss_ldap_common.so]
> tevent_common_loop_immediate+0xd4 [libtevent.so.0.9.30]
> epoll_event_loop_once+0x5d [libtevent.so.0.9.30]
> std_event_loop_once+0x37 [libtevent.so.0.9.30]
> _tevent_loop_once+0x9d [libtevent.so.0.9.30]
> tevent_common_loop_wait+0x1b [libtevent.so.0.9.30]
> std_event_loop_wait+0x37 [libtevent.so.0.9.30]
>
> avg:31 min: 26 max: 36 sum: 62
>
> 2 hits of transaction sysdb_transaction_commit+0xa0 [libsss_util.so]
> sdap_nested_done+0x2d5 [libsss_ldap_common.so]
> sdap_nested_group_process_done+0x21e [libsss_ldap_common.so]
> sdap_nested_group_process_done+0x21e [libsss_ldap_common.so]
> tevent_common_loop_immediate+0xd4 [libtevent.so.0.9.30]
> epoll_event_loop_once+0x5d [libtevent.so.0.9.30]
> std_event_loop_once+0x37 [libtevent.so.0.9.30]
> _tevent_loop_once+0x9d [libtevent.so.0.9.30]
> tevent_common_loop_wait+0x1b [libtevent.so.0.9.30]
> std_event_loop_wait+0x37 [libtevent.so.0.9.30]
>
> avg:25 min: 24 max: 26 sum: 50
>
> 1 hits of transaction sysdb_transaction_commit+0xa0 [libsss_util.so]
> sdap_nested_done+0x2d5 [libsss_ldap_common.so]
> sdap_nested_group_process_done+0x1fe [libsss_ldap_common.so]
> tevent_common_loop_immediate+0xd4 [libtevent.so.0.9.30]
> epoll_event_loop_once+0x5d [libtevent.so.0.9.30]
> std_event_loop_once+0x37 [libtevent.so.0.9.30]
> _tevent_loop_once+0x9d [libtevent.so.0.9.30]
> tevent_common_loop_wait+0x1b [libtevent.so.0.9.30]
> std_event_loop_wait+0x37 [libtevent.so.0.9.30]
> server_loop+0x13 [libsss_util.so]
> main+0x707 [sssd_be]
> 0x7fc1
> avg:35 min: 35 max: 35 sum: 35
>
> 4 hits of transaction sysdb_transaction_commit+0xa0 [libsss_util.so]
> sdap_nested_done+0x2d5 [libsss_ldap_common.so]
> sdap_nested_group_process_done+0x21e [libsss_ldap_common.so]
> tevent_common_loop_immediate+0xd4 [libtevent.so.0.9.30]
> epoll_event_loop_once+0x5d [libtevent.so.0.9.30]
> std_event_loop_once+0x37 [libtevent.so.0.9.30]
> _tevent_loop_once+0x9d [libtevent.so.0.9.30]
> tevent_common_loop_wait+0x1b [libtevent.so.0.9.30]
> std_event_loop_wait+0x37 [libtevent.so.0.9.30]
> server_loop+0x13 [libsss_util.so]
> main+0x707 [sssd_be]
> 0x7f76
> avg:27 min: 21 max: 36 sum: 111
>
> 1 hits of transaction sysdb_transaction_commit+0xa0 [libsss_util.so]
> sdap_save_users+0x28a [libsss_ldap_common.so]
> sdap_get_users_done+0xd2 [libsss_ldap_common.so]
> sdap_search_user_process+0x25f [libsss_ldap_common.so]
> generic_ext_search_handler.isra.4+0xe0 [libsss_ldap_common.so]
> sdap_get_generic_op_finished+0x5ba [libsss_ldap_common.so]
> sdap_process_result+0x71d [libsss_ldap_common.so]
> tevent_common_loop_timer_delay+0xd0 [libtevent.so.0.9.30]
> epoll_event_loop_once+0x69 [libtevent.so.0.9.30]
> std_event_loop_once+0x37 [libtevent
> avg:114 min: 114 max: 114 sum: 114
>
> 3 hits of transaction sysdb_transaction_commit+0xa0 [libsss_util.so]
> sdap_nested_done+0x2d5 [libsss_ldap_common.so]
> sdap_nested_group_process_done+0x1fe [libsss_ldap_common.so]
> sdap_nested_group_process_done+0x1fe [libsss_ldap_common.so]
> tevent_common_loop_immediate+0xd4 [libtevent.so.0.9.30]
> epoll_event_loop_once+0x5d [libtevent.so.0.9.30]
> std_event_loop_once+0x37 [libtevent.so.0.9.30]
> _tevent_loop_once+0x9d [libtevent.so.0.9.30]
> tevent_common_loop_wait+0x1b [libtevent.so.0.9.30]
> std_event_loop_wait+0x37 [libtevent.so.0.9.30]
>
> avg:28 min: 26 max: 33 sum: 86
>
> The most expensive transaction breakdown, per transaction:
> value |-------------------------------------------------- count
> 0 | 0
> 50 | 0
> 100 |@ 1
> 150 | 0
> 200 | 0
>
> ############################################################
> ########################################
> Caching appears to be taking effect here. Guessing I should clear the user
> cache, is there a best practice for that, rather than just clearing out the
> sss/db/ directory?
> ############################################################
> ########################################
> [root@fc25-vm systemtap]# stap nested_group_perf.stp
> ^CTime spent in group sssd_be searches: 2033
> Time spent in sdap_nested_group_send/recv: 1112 ms (ratio: 54.69%)
> Time spent in zero-level sysdb transactions: 699 ms (ratio: 34.38%)
>
> Breakdown of sdap_nested_group req (total: 1112 ms)
> sdap_nested_group_process req: 1111
> sdap_nested_group_process_split req: 11
> sdap_nested_group_check_cache: 11
> sdap_nested_group_sysdb_search_users: 6
> sdap_nested_group_sysdb_search_groups: 3
> ldap request breakdown of total 2144
> sdap_nested_group_deref req: 54
> sdap_deref_search_send req 54
> processing deref results: 0
> sdap_nested_group_lookup_user req: 979
> sdap_nested_group_lookup_group req: 66
> Time spent refreshing unknown members: 1045
>
> Breakdown of results processing (total 699)
> Time spent populating nested members: 3
> Time spent searching ldb while populating nested members: 3
> Time spent saving nested members: 330
> Time spent writing to the ldb: 226 ms
>
> ############################################################
> ########################################
> This user is from a completely different department, so it likely didn't
> hit the cache much.
> ############################################################
> ########################################
> [root@fc25-vm systemtap]# stap nested_group_perf.stp
> ^CTime spent in group sssd_be searches: 12502
> Time spent in sdap_nested_group_send/recv: 4642 ms (ratio: 37.13%)
> Time spent in zero-level sysdb transactions: 1099 ms (ratio: 8.79%)
>
> Breakdown of sdap_nested_group req (total: 4642 ms)
> sdap_nested_group_process req: 4971
> sdap_nested_group_process_split req: 53
> sdap_nested_group_check_cache: 51
> sdap_nested_group_sysdb_search_users: 17
> sdap_nested_group_sysdb_search_groups: 33
> ldap request breakdown of total 55789
> sdap_nested_group_deref req: 2908
> sdap_deref_search_send req 50266
> processing deref results: 2
> sdap_nested_group_lookup_user req: 2138
> sdap_nested_group_lookup_group req: 623
> Time spent refreshing unknown members: 2762
>
> Breakdown of results processing (total 1099)
> Time spent populating nested members: 29
> Time spent searching ldb while populating nested members:
> 23
> Time spent saving nested members: 635
> Time spent writing to the ldb: 303 ms
> _______________________________________________
> sssd-users mailing list -- sssd-users(a)lists.fedorahosted.org
> To unsubscribe send an email to sssd-users-leave(a)lists.fedorahosted.org
>
_______________________________________________
sssd-users mailing list -- sssd-users(a)lists.fedorahosted.org
To unsubscribe send an email to sssd-users-leave(a)lists.fedorahosted.org