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.
Test environment is 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 users creation|100 users deletion|250 users creation|250 users deletion|500
users creation|500 users deletion|
|:---:|:---:|:---:|:---:|:---:|:---:|:---:|
|Vanilla|0m43.464s|0m41.084s|2m46.462s|2m46.462s|9m55.823s|9m15.531s|
|Batching|
```
==============================================================================================================
[VANILLA SSSD]
==============================================================================================================
[30 entries in /etc/passwd]
# Counting users in passwd
[root(a)master.client.vm /var/log/sssd]# cat /etc/passwd | wc -l
30
# Cache cleaning and daemon restart
[root(a)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
[root(a)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
[root(a)master.client.vm /var/log/sssd]# cat /etc/passwd | wc -l
130
# Cache cleaning and daemon restart
[root(a)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
[root(a)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
[root(a)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
[root(a)master.client.vm /var/log/sssd]# cat /etc/passwd | wc -l
280
# Cache cleaning and daemon restart
[root(a)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
[root(a)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
[root(a)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
[root(a)master.client.vm /var/log/sssd]# cat /etc/passwd | wc -l
530
# Cache cleaning and daemon restart
[root(a)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
[root(a)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
[root(a)master.client.vm /var/log/sssd]# cat /etc/passwd | wc -l
30
# Cache cleaning and daemon restart
[root(a)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
[root(a)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
[root(a)master.client.vm /var/log/sssd]# cat /etc/passwd | wc -l
130
# Cache cleaning and daemon restart
[root(a)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
[root(a)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
[root(a)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
[root(a)master.client.vm /var/log/sssd]# cat /etc/passwd | wc -l
280
# Cache cleaning and daemon restart
[root(a)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
[root(a)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
[root(a)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
[root(a)master.client.vm /var/log/sssd]# cat /etc/passwd | wc -l
530
# Cache cleaning and daemon restart
[root(a)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
[root(a)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