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. 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; Estimated time needed to mark domain as inconsistent: |Version|30 users|30 + 100 users|30 + 250 users|30 + 500 users| |:---:|:---:|:---:|:---:|:---:| |Vanilla|91ms|190ms|444ms|891ms| |Batching|34ms|63ms|105ms|188ms| Time consumed by calling operations on `X` users: `time for N in `seq X`; do useradd test-user-$N; done` `time for N in `seq X`; do userdel -rf test-user-$N; done` |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` - Introduce 1st semi step which will send DBUS commands 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 to read file part by part ``` ============================================================================================================== [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