URL: https://github.com/SSSD/sssd/pull/5552
Title: #5552: files: split update into batches
elkoniu commented:
"""
I did some testing comparing this PR with vanilla SSSD. I added extra log in
`sf_passwd_cb()` which is `/etc/passwd` file modification callback and in
`sss_resp_domain_inconsistent()` which is receiver of DBUS command
`SetInconsisten` marking domain as inconsistent. With microseconds enabled in
SSSD logs I was trying to estimate time needed to mark domain as inconsistent.
Another test was creation and deletion of 100, 250 and 500 users in bash `for`
loop.
I have not run dedicated test for `/etc/groups` based routines as I thought
result of `/etc/passwd` modifications
will be already meaningful.
Test environment was sssd-test-suite VM (1 core CPU, 2G RAM) running Fedora 31.
As a base I used upstream commit: 66960c76952baf6b636d4f1949822710a3dc7da8
On top of it I added my commit with extra logs and then this PR.
Full log from test is on the bottom.
TL; DR;
|Version|30 users|30 + 100 users|30 + 250 users|30 + 500 users|
|:---:|:---:|:---:|:---:|:---:|
|Vanilla|91ms|190ms|444ms|891ms|
|Batching|34ms|63ms|105ms|188ms|
|Version|100 useradd|100 userdel|250 useradd|250 userdel|500 useradd|500
userdel|
|:---:|:---:|:---:|:---:|:---:|:---:|:---:|
|Vanilla|0m43.464s|0m41.084s|2m46.462s|2m46.462s|9m55.823s|9m15.531s|
|Batching|0m53.304s|0m48.572s|3m42.061s|4m16.405s|20m15.965s|18m1.768s|
Conclusion: While this PR shortens the time needed to mark a domain as
inconsistent it is still affected by the size of `/etc/passwd` file. The issues
reported for files provider with 1k+ users may be solved now but they will be
still valid for 10k+ etc. Another observation is that total time of adding /
deleting N users via bash script has been increased by this PR. I guess playing
with `state->initial_delay` and `state->delay` could help fix this.
Positive observation is drop in CPU usage. Load on CPU for 500 users adding /
deleting was still heavy but not that heavy as in vanilla version and better
balanced.
To speed up domain marking as inconsistent there are three options:
- As @pbrezina suggested use monitor DBUS connector to send `SetInconsistent`
to cache
- Introduce 1st semi step which will send DBUS commands only even before
`/etc/passwd` / `/etc/groups` processing to release backend tevent loop faster
and push DBUS commands
- Split 1st step which is file read into even smaller substeps
```
==============================================================================================================
[VANILLA SSSD]
==============================================================================================================
[30 entries in /etc/passwd]
# Counting users in passwd
[r...@master.client.vm /var/log/sssd]# cat /etc/passwd | wc -l
30
# Cache cleaning and daemon restart
[r...@master.client.vm /var/log/sssd]# sss_cache -E; systemctl stop sssd; rm
-rf /var/lib/sss/db/*; rm -rf /var/log/sssd/*; systemctl start sssd
# Triggering actions
3 x manual call "touch /etc/passwd" with few seconds in between calls
# Logs timestamp calculation
./sssd_files.log:1715:(2021-04-03 14:15:23:911881): [be[files]] [sf_passwd_cb]
(0x0200): >>>PASSWD_MODIFIED_CB
./sssd_nss.log:215:(2021-04-03 14:15:24:007537): [nss]
[sss_resp_domain_inconsistent] (0x0200): >>>DOMAIN_INCONSISTENT_RECEIVED
1000000 - 911881 + 007537 = 95656
./sssd_files.log:2430:(2021-04-03 14:16:42:521671): [be[files]] [sf_passwd_cb]
(0x0200): >>>PASSWD_MODIFIED_CB
./sssd_nss.log:243:(2021-04-03 14:16:42:610820): [nss]
[sss_resp_domain_inconsistent] (0x0200): >>>DOMAIN_INCONSISTENT_RECEIVED
610820 - 521671 = 89149
./sssd_files.log:3145:(2021-04-03 14:17:00:105384): [be[files]] [sf_passwd_cb]
(0x0200): >>>PASSWD_MODIFIED_CB
./sssd_nss.log:271:(2021-04-03 14:17:00:193427): [nss]
[sss_resp_domain_inconsistent] (0x0200): >>>DOMAIN_INCONSISTENT_RECEIVED
193427 - 105384 = 88043
Average = (95656 + 89149 + 88043) / 3 = 90949us = 90,949ms
--------------------------------------------------------------------------------------------------------------
[30 + 100 entries in /etc/passwd]
# Adding users
[r...@master.client.vm /var/log/sssd]# time for N in `seq 100`; do useradd
test-user-$N; done
real 0m43.464s
user 0m7.187s
sys 0m3.635s
# Counting users in passwd
[r...@master.client.vm /var/log/sssd]# cat /etc/passwd | wc -l
130
# Cache cleaning and daemon restart
[r...@master.client.vm /var/log/sssd]# sss_cache -E; systemctl stop sssd; rm
-rf /var/lib/sss/db/*; rm -rf /var/log/sssd/*; systemctl start sssd
# Triggering actions
3 x manual call "touch /etc/passwd" with few seconds in between calls
# Logs timestamp calculation
./sssd_files.log:5125:(2021-04-03 14:27:10:556898): [be[files]] [sf_passwd_cb]
(0x0200): >>>PASSWD_MODIFIED_CB
./sssd_nss.log:260:(2021-04-03 14:27:10:750840): [nss]
[sss_resp_domain_inconsistent] (0x0200): >>>DOMAIN_INCONSISTENT_RECEIVED
750840 - 556898 = 193942
./sssd_files.log:7540:(2021-04-03 14:27:41:406064): [be[files]] [sf_passwd_cb]
(0x0200): >>>PASSWD_MODIFIED_CB
./sssd_nss.log:288:(2021-04-03 14:27:41:600166): [nss]
[sss_resp_domain_inconsistent] (0x0200): >>>DOMAIN_INCONSISTENT_RECEIVED
600166 - 406064 = 194102
./sssd_files.log:9955:(2021-04-03 14:27:58:037802): [be[files]] [sf_passwd_cb]
(0x0200): >>>PASSWD_MODIFIED_CB
./sssd_nss.log:316:(2021-04-03 14:27:58:221111): [nss]
[sss_resp_domain_inconsistent] (0x0200): >>>DOMAIN_INCONSISTENT_RECEIVED
221111 - 037802 = 183309
Average = (193942 + 194102 + 183309) / 3 = 190451us = 190,451ms
# Deleting users
[r...@master.client.vm /var/log/sssd]# time for N in `seq 100`; do userdel -rf
test-user-$N; done
real 0m41.084s
user 0m6.838s
sys 0m3.729s
--------------------------------------------------------------------------------------------------------------
[30 + 250 entries in /etc/passwd]
# Adding users
[r...@master.client.vm /var/log/sssd]# time for N in `seq 250`; do useradd
test-user-$N; done
real 2m46.462s
user 0m34.869s
sys 0m18.381s
# Counting users in passwd
[r...@master.client.vm /var/log/sssd]# cat /etc/passwd | wc -l
280
# Cache cleaning and daemon restart
[r...@master.client.vm /var/log/sssd]# sss_cache -E; systemctl stop sssd; rm
-rf /var/lib/sss/db/*; rm -rf /var/log/sssd/*; systemctl start sssd
# Triggering actions
3 x manual call "touch /etc/passwd" with few seconds in between calls
# Logs timestamp calculation
./sssd_files.log:10205:(2021-04-03 18:04:14:997171): [be[files]] [sf_passwd_cb]
(0x0200): >>>PASSWD_MODIFIED_CB
./sssd_nss.log:161:(2021-04-03 18:04:15:422140): [nss]
[sss_resp_domain_inconsistent] (0x0200): >>>DOMAIN_INCONSISTENT_RECEIVED
1000000 - 997171 + 422140 = 424969
./sssd_files.log:15170:(2021-04-03 18:04:38:941796): [be[files]] [sf_passwd_cb]
(0x0200): >>>PASSWD_MODIFIED_CB
./sssd_nss.log:189:(2021-04-03 18:04:39:387461): [nss]
[sss_resp_domain_inconsistent] (0x0200): >>>DOMAIN_INCONSISTENT_RECEIVED
1000000 - 941796 + 387461 = 445665
./sssd_files.log:20135:(2021-04-03 18:04:56:860883): [be[files]] [sf_passwd_cb]
(0x0200): >>>PASSWD_MODIFIED_CB
./sssd_nss.log:217:(2021-04-03 18:04:57:322166): [nss]
[sss_resp_domain_inconsistent] (0x0200): >>>DOMAIN_INCONSISTENT_RECEIVED
1000000 - 860883 + 322166 = 461283
Average = (424969 + 445665 + 461283) / 3 = 443972us = 443,972ms
# Deleting users
[r...@master.client.vm /var/log/sssd]# time for N in `seq 250`; do userdel -rf
test-user-$N; done
real 2m42.784s
user 0m34.563s
sys 0m17.203s
--------------------------------------------------------------------------------------------------------------
[30 + 500 entries in /etc/passwd]
# Adding users
[r...@master.client.vm /var/log/sssd]# time for N in `seq 500`; do useradd
test-user-$N; done
real 9m55.823s
user 2m15.133s
sys 1m7.711s
# Counting users in passwd
[r...@master.client.vm /var/log/sssd]# cat /etc/passwd | wc -l
530
# Cache cleaning and daemon restart
[r...@master.client.vm /var/log/sssd]# sss_cache -E; systemctl stop sssd; rm
-rf /var/lib/sss/db/*; rm -rf /var/log/sssd/*; systemctl start sssd
# Triggering actions
3 x manual call "touch /etc/passw" with few seconds in between calls
# Logs timestamp calculation
./sssd_files.log:18705:(2021-04-03 19:08:04:485795): [be[files]] [sf_passwd_cb]
(0x0200): >>>PASSWD_MODIFIED_CB
./sssd_nss.log:157:(2021-04-03 19:08:05:358181): [nss]
[sss_resp_domain_inconsistent] (0x0200): >>>DOMAIN_INCONSISTENT_RECEIVED
1000000 - 485795 + 358181 = 872386
./sssd_files.log:27920:(2021-04-03 19:08:23:710157): [be[files]] [sf_passwd_cb]
(0x0200): >>>PASSWD_MODIFIED_CB
./sssd_nss.log:185:(2021-04-03 19:08:24:608777): [nss]
[sss_resp_domain_inconsistent] (0x0200): >>>DOMAIN_INCONSISTENT_RECEIVED
1000000 - 710157 + 608777 = 898620
./sssd_files.log:37135:(2021-04-03 19:08:50:350387): [be[files]] [sf_passwd_cb]
(0x0200): >>>PASSWD_MODIFIED_CB
./sssd_nss.log:213:(2021-04-03 19:08:51:253827): [nss]
[sss_resp_domain_inconsistent] (0x0200): >>>DOMAIN_INCONSISTENT_RECEIVED
1000000 - 350387 + 253827 = 903440
Average = (872386 + 898620 + 903440) / 3 = 891482us = 891,482ms
# Deleting users
[r...@master.client.vm /var/log/sssd]# time for N in `seq 500`; do userdel -rf
test-user-$N; done
real 9m15.531s
user 2m9.902s
sys 1m2.880s
==============================================================================================================
[SSSD FILES BATCHING]
==============================================================================================================
[30 entries in /etc/passwd]
# Counting users in passwd
[r...@master.client.vm /var/log/sssd]# cat /etc/passwd | wc -l
30
# Cache cleaning and daemon restart
[r...@master.client.vm /var/log/sssd]# sss_cache -E; systemctl stop sssd; rm
-rf /var/lib/sss/db/*; rm -rf /var/log/sssd/*; systemctl start sssd
# Triggering actions
3 x manual call "touch /etc/passwd" with few seconds in between calls
# Logs timestamp calculation
./sssd_files.log:1755:(2021-04-03 20:38:17:173733): [be[files]] [sf_passwd_cb]
(0x0200): >>>PASSWD_MODIFIED_CB
./sssd_nss.log:263:(2021-04-03 20:38:17:208845): [nss]
[sss_resp_domain_inconsistent] (0x0200): >>>DOMAIN_INCONSISTENT_RECEIVED
208845 - 173733 = 35112
./sssd_files.log:2485:(2021-04-03 20:38:39:735251): [be[files]] [sf_passwd_cb]
(0x0200): >>>PASSWD_MODIFIED_CB
./sssd_nss.log:291:(2021-04-03 20:38:39:765298): [nss]
[sss_resp_domain_inconsistent] (0x0200): >>>DOMAIN_INCONSISTENT_RECEIVED
765298 - 735251 = 30047
./sssd_files.log:3215:(2021-04-03 20:38:58:006912): [be[files]] [sf_passwd_cb]
(0x0200): >>>PASSWD_MODIFIED_CB
./sssd_nss.log:319:(2021-04-03 20:38:58:042773): [nss]
[sss_resp_domain_inconsistent] (0x0200): >>>DOMAIN_INCONSISTENT_RECEIVED
042773 - 006912 = 35861
Average = (35112 + 30047 + 35861) / 3 = 33673us = 33,673ms
--------------------------------------------------------------------------------------------------------------
[30 + 100 entries in /etc/passwd]
# Adding users
[r...@master.client.vm /var/log/sssd]# time for N in `seq 100`; do useradd
test-user-$N; done
real 0m53.304s
user 0m6.711s
sys 0m3.675s
# Counting users in passwd
[r...@master.client.vm /var/log/sssd]# cat /etc/passwd | wc -l
130
# Cache cleaning and daemon restart
[r...@master.client.vm /var/log/sssd]# sss_cache -E; systemctl stop sssd; rm
-rf /var/lib/sss/db/*; rm -rf /var/log/sssd/*; systemctl start sssd
# Triggering actions
3 x manual call "touch /etc/passwd" with few seconds in between calls
# Logs timestamp calculation
./sssd_files.log:5215:(2021-04-03 20:46:34:054796): [be[files]] [sf_passwd_cb]
(0x0200): >>>PASSWD_MODIFIED_CB
./sssd_nss.log:265:(2021-04-03 20:46:34:113920): [nss]
[sss_resp_domain_inconsistent] (0x0200): >>>DOMAIN_INCONSISTENT_RECEIVED
113920 - 054796 = 59124
./sssd_files.log:7675:(2021-04-03 20:47:06:303398): [be[files]] [sf_passwd_cb]
(0x0200): >>>PASSWD_MODIFIED_CB
./sssd_nss.log:293:(2021-04-03 20:47:06:369933): [nss]
[sss_resp_domain_inconsistent] (0x0200): >>>DOMAIN_INCONSISTENT_RECEIVED
369933 - 303398 = 66535
./sssd_files.log:10135:(2021-04-03 20:47:21:847043): [be[files]] [sf_passwd_cb]
(0x0200): >>>PASSWD_MODIFIED_CB
./sssd_nss.log:321:(2021-04-03 20:47:21:910637): [nss]
[sss_resp_domain_inconsistent] (0x0200): >>>DOMAIN_INCONSISTENT_RECEIVED
910637 - 847043 = 63594
Average = (59124 + 66535 + 63594) / 3 = 63084us = 63,084ms
# Deleting users
[r...@master.client.vm /var/log/sssd]# time for N in `seq 100`; do userdel -rf
test-user-$N; done
real 0m48.572s
user 0m6.181s
sys 0m3.636s
--------------------------------------------------------------------------------------------------------------
[30 + 250 entries in /etc/passwd]
# Adding users
[r...@master.client.vm /var/log/sssd]# time for N in `seq 250`; do useradd
test-user-$N; done
real 3m42.061s
user 0m29.853s
sys 0m15.093s
# Counting users in passwd
[r...@master.client.vm /var/log/sssd]# cat /etc/passwd | wc -l
280
# Cache cleaning and daemon restart
[r...@master.client.vm /var/log/sssd]# sss_cache -E; systemctl stop sssd; rm
-rf /var/lib/sss/db/*; rm -rf /var/log/sssd/*; systemctl start sssd
# Triggering actions
3 x manual call "touch /etc/passwd" with few seconds in between calls
# Logs timestamp calculation
./sssd_files.log:10385:(2021-04-03 20:57:13:771709): [be[files]] [sf_passwd_cb]
(0x0200): >>>PASSWD_MODIFIED_CB
./sssd_nss.log:168:(2021-04-03 20:57:13:886122): [nss]
[sss_resp_domain_inconsistent] (0x0200): >>>DOMAIN_INCONSISTENT_RECEIVED
886122 - 771709 = 114413
./sssd_files.log:15440:(2021-04-03 20:57:32:787196): [be[files]] [sf_passwd_cb]
(0x0200): >>>PASSWD_MODIFIED_CB
./sssd_nss.log:196:(2021-04-03 20:57:32:888939): [nss]
[sss_resp_domain_inconsistent] (0x0200): >>>DOMAIN_INCONSISTENT_RECEIVED
888939 - 787196 = 101743
./sssd_files.log:20495:(2021-04-03 20:57:49:476424): [be[files]] [sf_passwd_cb]
(0x0200): >>>PASSWD_MODIFIED_CB
./sssd_nss.log:224:(2021-04-03 20:57:49:576838): [nss]
[sss_resp_domain_inconsistent] (0x0200): >>>DOMAIN_INCONSISTENT_RECEIVED
576838 - 476424 = 100414
Average = (114413 + 101743 + 100414) / 3 = 105523us = 105,523ms
# Deleting users
[r...@master.client.vm /var/log/sssd]# time for N in `seq 250`; do userdel -rf
test-user-$N; done
real 4m16.405s
user 0m28.943s
sys 0m14.883s
--------------------------------------------------------------------------------------------------------------
[30 + 500 entries in /etc/passwd]
# Adding users
[r...@master.client.vm /var/log/sssd]# time for N in `seq 500`; do useradd
test-user-$N; done
real 20m15.965s
user 2m20.204s
sys 1m9.866s
# Counting users in passwd
[r...@master.client.vm /var/log/sssd]# cat /etc/passwd | wc -l
530
# Cache cleaning and daemon restart
[r...@master.client.vm /var/log/sssd]# sss_cache -E; systemctl stop sssd; rm
-rf /var/lib/sss/db/*; rm -rf /var/log/sssd/*; systemctl start sssd
# Triggering actions
3 x manual call "touch /etc/passwd" with few seconds in between calls
# Logs timestamp calculation
./sssd_files.log:19035:(2021-04-03 21:43:11:230076): [be[files]] [sf_passwd_cb]
(0x0200): >>>PASSWD_MODIFIED_CB
./sssd_nss.log:156:(2021-04-03 21:43:11:438640): [nss]
[sss_resp_domain_inconsistent] (0x0200): >>>DOMAIN_INCONSISTENT_RECEIVED
438640 - 230076 = 208564
./sssd_files.log:28415:(2021-04-03 21:43:25:944105): [be[files]] [sf_passwd_cb]
(0x0200): >>>PASSWD_MODIFIED_CB
./sssd_nss.log:184:(2021-04-03 21:43:26:106063): [nss]
[sss_resp_domain_inconsistent] (0x0200): >>>DOMAIN_INCONSISTENT_RECEIVED
1000000 - 944105 + 106063 = 161958
./sssd_files.log:37795:(2021-04-03 21:44:08:229897): [be[files]] [sf_passwd_cb]
(0x0200): >>>PASSWD_MODIFIED_CB
./sssd_nss.log:212:(2021-04-03 21:44:08:424929): [nss]
[sss_resp_domain_inconsistent] (0x0200): >>>DOMAIN_INCONSISTENT_RECEIVED
424929 - 229897 = 195032
Average = (208564 + 161958 + 195032) / 3 = 188518us = 188,518ms
# Deleting users
[r...@master.client.vm /var/log/sssd]# time for N in `seq 500`; do userdel -rf
test-user-$N; done
real 18m1.768s
user 1m53.758s
sys 0m59.567s
```
"""
See the full comment at
https://github.com/SSSD/sssd/pull/5552#issuecomment-812930403
_______________________________________________
sssd-devel mailing list -- sssd-devel@lists.fedorahosted.org
To unsubscribe send an email to sssd-devel-le...@lists.fedorahosted.org
Fedora Code of Conduct:
https://docs.fedoraproject.org/en-US/project/code-of-conduct/
List Guidelines: https://fedoraproject.org/wiki/Mailing_list_guidelines
List Archives:
https://lists.fedorahosted.org/archives/list/sssd-devel@lists.fedorahosted.org
Do not reply to spam on the list, report it:
https://pagure.io/fedora-infrastructure
