Here are some more runs of nested_group_perf.stp.
Running fc25 workstation, kernel 4.8.8-300.fc25.x86_64, gnome desktop.
############################################################################################
Noticed a small issue with the system tap script
############################################################################################
nested_group_perf.stp
When missing a package it suggests using yum rather than dnf.
e.g.
“use: yum install kernel-devel-4.8.8-300.fc25.x86_64”
############################################################################################
Modifications to /etc/sssd/sssd.conf: dyndns_update = True
############################################################################################
real 1m23.424s
user 0m0.006s
sys 0m0.013s
[root@fc25-vm systemtap]# stap nested_group_perf.stp
^CTime spent in group sssd_be searches: 18543
Time spent in sdap_nested_group_send/recv: 12793 ms (ratio: 68.99%)
Time spent in zero-level sysdb transactions: 4894 ms (ratio: 26.39%)
Breakdown of sdap_nested_group req (total: 12793 ms)
sdap_nested_group_process req: 10973
sdap_nested_group_process_split req: 502
sdap_nested_group_check_cache: 459
sdap_nested_group_sysdb_search_users: 226
sdap_nested_group_sysdb_search_groups: 213
ldap request breakdown of total 22629
sdap_nested_group_deref req: 7462
sdap_deref_search_send req 12399
processing deref results: 534
sdap_nested_group_lookup_user req: 4611
sdap_nested_group_lookup_group req: 791
Time spent refreshing unknown members: 4828
Breakdown of results processing (total 4894)
Time spent populating nested members: 1581
Time spent searching ldb while populating nested members: 1372
Time spent saving nested members: 2829
Time spent writing to the ldb: 470 ms
############################################################################################
Same user, ran sss_cache -UG, but perhaps some organizational information is still
cached?
Not sure what else accounts for the time difference.
############################################################################################
real 0m49.898s
user 0m0.004s
sys 0m0.007s
[root@fc25-vm systemtap]# stap nested_group_perf.stp
^CTime spent in group sssd_be searches: 16000
Time spent in sdap_nested_group_send/recv: 7629 ms (ratio: 47.68%)
Time spent in zero-level sysdb transactions: 1770 ms (ratio: 11.06%)
Breakdown of sdap_nested_group req (total: 7629 ms)
sdap_nested_group_process req: 5971
sdap_nested_group_process_split req: 302
sdap_nested_group_check_cache: 281
sdap_nested_group_sysdb_search_users: 150
sdap_nested_group_sysdb_search_groups: 120
ldap request breakdown of total 21757
sdap_nested_group_deref req: 3708
sdap_deref_search_send req 14555
processing deref results: 36
sdap_nested_group_lookup_user req: 3243
sdap_nested_group_lookup_group req: 583
Time spent refreshing unknown members: 3376
Breakdown of results processing (total 1770)
Time spent populating nested members: 302
Time spent searching ldb while populating nested members: 268
Time spent saving nested members: 1236
Time spent writing to the ldb: 212 ms
############################################################################################
Different user than before.
############################################################################################
real 0m41.878s
user 0m0.004s
sys 0m0.003s
[root@fc25-vm systemtap]# stap nested_group_perf.stp
^CTime spent in group sssd_be searches: 16000
Time spent in sdap_nested_group_send/recv: 7629 ms (ratio: 47.68%)
Time spent in zero-level sysdb transactions: 1770 ms (ratio: 11.06%)
Breakdown of sdap_nested_group req (total: 7629 ms)
sdap_nested_group_process req: 5971
sdap_nested_group_process_split req: 302
sdap_nested_group_check_cache: 281
sdap_nested_group_sysdb_search_users: 150
sdap_nested_group_sysdb_search_groups: 120
ldap request breakdown of total 21757
sdap_nested_group_deref req: 3708
sdap_deref_search_send req 14555
processing deref results: 36
sdap_nested_group_lookup_user req: 3243
sdap_nested_group_lookup_group req: 583
Time spent refreshing unknown members: 3376
Breakdown of results processing (total 1770)
Time spent populating nested members: 302
Time spent searching ldb while populating nested members: 268
Time spent saving nested members: 1236
Time spent writing to the ldb: 212 ms
[root@fc25-vm systemtap]# stap nested_group_perf.stp
^CTime spent in group sssd_be searches: 6862
Time spent in sdap_nested_group_send/recv: 5495 ms (ratio: 80.07%)
Time spent in zero-level sysdb transactions: 1133 ms (ratio: 16.51%)
Breakdown of sdap_nested_group req (total: 5495 ms)
sdap_nested_group_process req: 4024
sdap_nested_group_process_split req: 182
sdap_nested_group_check_cache: 158
sdap_nested_group_sysdb_search_users: 49
sdap_nested_group_sysdb_search_groups: 90
ldap request breakdown of total 18417
sdap_nested_group_deref req: 2900
sdap_deref_search_send req 14437
processing deref results: 46
sdap_nested_group_lookup_user req: 1687
sdap_nested_group_lookup_group req: 482
Time spent refreshing unknown members: 1811
Breakdown of results processing (total 1133)
Time spent populating nested members: 88
Time spent searching ldb while populating nested members: 63
Time spent saving nested members: 910
Time spent writing to the ldb: 77 ms
############################################################################################
^C[root@fc25-vm systemtap]# stap nested_group_perf.stp
^CTime spent in group sssd_be searches: 5021
Time spent in sdap_nested_group_send/recv: 10726 ms (ratio: 213.62%)
Time spent in zero-level sysdb transactions: 368 ms (ratio: 7.32%)
Breakdown of sdap_nested_group req (total: 10726 ms)
sdap_nested_group_process req: 1480525834936
sdap_nested_group_process_split req: 124
sdap_nested_group_check_cache: 51
sdap_nested_group_sysdb_search_users: 31
sdap_nested_group_sysdb_search_groups: 19
ldap request breakdown of total 22264
sdap_nested_group_deref req: 1480525833504
sdap_deref_search_send req 16770
processing deref results: 1480525825718
sdap_nested_group_lookup_user req: 2637
sdap_nested_group_lookup_group req: 110
Time spent refreshing unknown members: 2747
Breakdown of results processing (total 368)
Time spent populating nested members: 4729
Time spent searching ldb while populating nested members: 3947
Time spent saving nested members: 221
Time spent writing to the ldb: 95 ms
############################################################################################
real 2m4.412s
user 0m0.004s
sys 0m0.005s
[root@fc25-vm systemtap]# stap nested_group_perf.stp
^C
^CTime spent in group sssd_be searches: 8083
Time spent in sdap_nested_group_send/recv: 36901 ms (ratio: 456.52%)
Time spent in zero-level sysdb transactions: 2329 ms (ratio: 28.81%)
Breakdown of sdap_nested_group req (total: 36901 ms)
sdap_nested_group_process req: 35943
sdap_nested_group_process_split req: 177
sdap_nested_group_check_cache: 146
sdap_nested_group_sysdb_search_users: 50
sdap_nested_group_sysdb_search_groups: 87
ldap request breakdown of total 29401
sdap_nested_group_deref req: 34914
sdap_deref_search_send req 26218
processing deref results: 25004
sdap_nested_group_lookup_user req: 1385
sdap_nested_group_lookup_group req: 340
Time spent refreshing unknown members: 1458
Breakdown of results processing (total 2329)
Time spent populating nested members: 826
Time spent searching ldb while populating nested members: 590
Time spent saving nested members: 1786
Time spent writing to the ldb: 256 ms
############################################################################################
su - <domain user>
############################################################################################
[root@fc25-vm systemtap]# stap nested_group_perf.stp
^CTime spent in group sssd_be searches: 545
Time spent in sdap_nested_group_send/recv: 1480527569532 ms (ratio: 271656434776.51%)
Time spent in zero-level sysdb transactions: 112 ms (ratio: 20.55%)
Breakdown of sdap_nested_group req (total: 1480527569532 ms)
sdap_nested_group_process req: 1480527569440
sdap_nested_group_process_split req: 11
sdap_nested_group_check_cache: 11
sdap_nested_group_sysdb_search_users: 5
sdap_nested_group_sysdb_search_groups: 6
ldap request breakdown of total 451
sdap_nested_group_deref req: 1480527569424
sdap_deref_search_send req 192
processing deref results: 1480527569190
sdap_nested_group_lookup_user req: 114
sdap_nested_group_lookup_group req: 15
Time spent refreshing unknown members: 130
Breakdown of results processing (total 112)
Time spent populating nested members: 649
Time spent searching ldb while populating nested members: 438
Time spent saving nested members: 58
Time spent writing to the ldb: 38 ms