Bug 1235387

Summary: Slow replication when deleting large quantities of multi-valued attributes
Product: Red Hat Enterprise Linux 7 Reporter: Noriko Hosoi <nhosoi>
Component: 389-ds-baseAssignee: Noriko Hosoi <nhosoi>
Status: CLOSED ERRATA QA Contact: Viktor Ashirov <vashirov>
Severity: unspecified Docs Contact:
Priority: unspecified    
Version: 7.0CC: nkinder, rmeggins, sramling
Target Milestone: rc   
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: 389-ds-base-1.3.4.0-2.el7 Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2015-11-19 11:42:45 UTC Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:

Description Noriko Hosoi 2015-06-24 16:48:02 UTC
This bug is created as a clone of upstream ticket:
https://fedorahosted.org/389/ticket/48195

We write to our directory via Java API. When changing our groups the ModificationItems are lists of distinguished names of users. 

There is no problem when we add new uniqueMembers to our groups, but deleting them takes much too long on the second (replicated) master. (example deleting 850 members from 86000 takes 159 seconds on dldap02).

dldap01
[01/Jun/2015:13:44:47 +0200] conn=141407 op=3 MOD dn="cn=TSNMAIL-VerteilerZugriff,cn=TSNMAIL,cn=Applications,ou=Groups,ou=TSN-AD,dc=tirol+gvOuId=AT:L7:LVN:000001,dc=gv,dc=at"
[01/Jun/2015:13:44:48 +0200] conn=141407 op=3 RESULT err=0 tag=103 nentries=0 etime=0.858000 csn=556c45b0000000010000

dldap02
[01/Jun/2015:13:44:48 +0200] conn=141354 op=4 MOD dn="cn=TSNMAIL-VerteilerZugriff,cn=TSNMAIL,cn=Applications,ou=Groups,ou=TSN-AD,dc=tirol+gvOuId=AT:L7:LVN:000001,dc=gv,dc=at"
[01/Jun/2015:13:47:28 +0200] conn=141354 op=4 RESULT err=0 tag=103 nentries=0 etime=159.670000 csn=556c45b0000000010000

I found a closed ticket (#346) with some simmilarities, maybe the problem still exists in a multimaster replication environment when deleting attributes. Logging shows millions of calls to plugin_call_syntax_filter_ava uniqueMember=gvGid=AT:L7:TSN:i.weitlaner,ou=People,ou=TSN-AD,dc=tirol+gvOuId=AT:L7:LVN:000001,dc=gv,dc=at ?

Comment 2 Sankar Ramalingam 2015-09-19 08:55:41 UTC
Enabled memberOf plugin and added a group with 90000 members in group. Then, added/deleted about 100 users as member/uniquemember to the group.

[root@dhcp35-196 ~]# PORT=1289; ldapsearch -LLL -x -p $PORT -h localhost -D "cn=Directory Manager" -w Secret123 -b "cn=MemberOf Plugin,cn=plugins,cn=config" "memberofgroupattr"
dn: cn=MemberOf Plugin,cn=plugins,cn=config
memberofgroupattr: member
memberofgroupattr: uniquemember

[root@dhcp35-196 export]# ldapsearch -x -p $PORT -h localhost -D "cn=Directory Manager" -w Secret123 -b "cn=grpC,ou=groups,dc=nestgrpsuff,dc=com" |grep -i member: |wc -l
90000

[root@dhcp35-196 export]# PORT=1189; time ldapmodify -x -p $PORT -h localhost -D "cn=Directory Manager" -w Secret123 -f 100addmember.ldif
modifying entry "cn=grpC,ou=groups,dc=nestgrpsuff,dc=com"

real	1m24.197s
user	0m0.009s
sys	0m0.007s

[root@dhcp35-196 export]# PORT=1189; time ldapmodify -x -p $PORT -h localhost -D "cn=Directory Manager" -w Secret123 -f 100delmember.ldif
modifying entry "cn=grpC,ou=groups,dc=nestgrpsuff,dc=com"

real	0m5.059s
user	0m0.003s
sys	0m0.008s

[root@dhcp35-196 export]# PORT=1189; time ldapmodify -x -p $PORT -h localhost -D "cn=Directory Manager" -w Secret123 -f 100uinqmemadd.ldif modifying entry "cn=grpC,ou=groups,dc=nestgrpsuff,dc=com"

real	1m23.539s
user	0m0.005s
sys	0m0.014s

[root@dhcp35-196 export]# PORT=1189; time ldapmodify -x -p $PORT -h localhost -D "cn=Directory Manager" -w Secret123 -f 100uinqmemdel.ldif 
modifying entry "cn=grpC,ou=groups,dc=nestgrpsuff,dc=com"

real	1m24.492s
user	0m0.006s
sys	0m0.017s


Another set of delete/add member/uniquemember attribute to groups.

[root@dhcp35-196 export]# PORT=1189; time ldapmodify -x -p $PORT -h localhost -D "cn=Directory Manager" -w Secret123 -f New100addmember.ldif 
modifying entry "cn=grpC,ou=groups,dc=nestgrpsuff,dc=com"

real	1m21.672s
user	0m0.007s
sys	0m0.023s

[root@dhcp35-196 export]# PORT=1189; time ldapmodify -x -p $PORT -h localhost -D "cn=Directory Manager" -w Secret123 -f New100delmember.ldif 
modifying entry "cn=grpC,ou=groups,dc=nestgrpsuff,dc=com"

real	0m4.045s
user	0m0.004s
sys	0m0.005s

[root@dhcp35-196 export]# PORT=1189; time ldapmodify -x -p $PORT -h localhost -D "cn=Directory Manager" -w Secret123 -f New100uinqmemadd.ldif 
modifying entry "cn=grpC,ou=groups,dc=nestgrpsuff,dc=com"

real	1m45.207s
user	0m0.010s
sys	0m0.019s

[root@dhcp35-196 export]# PORT=1189; time ldapmodify -x -p $PORT -h localhost -D "cn=Directory Manager" -w Secret123 -f New100uinqmemdel.ldif 
modifying entry "cn=grpC,ou=groups,dc=nestgrpsuff,dc=com"

real	0m49.638s
user	0m0.005s
sys	0m0.017s

-----
It takes about 90secs on an average to add or delete about 120 member/uniquemember attributes. I checked this only on Master.
-----

[root@dhcp35-196 export]# cat New100delmember.ldif |head -5
dn: cn=grpC,ou=groups,dc=nestgrpsuff,dc=com
delete: member
member: uid=usrC59879,ou=people,dc=nestgrpsuff,dc=com
member: uid=usrC59880,ou=people,dc=nestgrpsuff,dc=com
member: uid=usrC59881,ou=people,dc=nestgrpsuff,dc=com

[root@dhcp35-196 export]# cat New100addmember.ldif |head -5
dn: cn=grpC,ou=groups,dc=nestgrpsuff,dc=com
add: member
member: uid=usrB59879,ou=people,dc=nestgrpsuff,dc=com
member: uid=usrB59880,ou=people,dc=nestgrpsuff,dc=com
member: uid=usrB59881,ou=people,dc=nestgrpsuff,dc=com

[root@dhcp35-196 export]# cat New100uinqmemadd.ldif |head -5
dn: cn=grpC,ou=groups,dc=nestgrpsuff,dc=com
add: uniquemember
uniquemember: uid=usrB49879,ou=people,dc=nestgrpsuff,dc=com
uniquemember: uid=usrB49880,ou=people,dc=nestgrpsuff,dc=com
uniquemember: uid=usrB49881,ou=people,dc=nestgrpsuff,dc=com

[root@dhcp35-196 export]# cat New100uinqmemdel.ldif |head -5
dn: cn=grpC,ou=groups,dc=nestgrpsuff,dc=com
delete: uniquemember
uniquemember: uid=usrB49879,ou=people,dc=nestgrpsuff,dc=com
uniquemember: uid=usrB49880,ou=people,dc=nestgrpsuff,dc=com
uniquemember: uid=usrB49881,ou=people,dc=nestgrpsuff,dc=com

Comment 3 Viktor Ashirov 2015-09-21 17:07:30 UTC
Updating on behalf of Sankar (bz was down).

For adding 122 users with uniquemember attribute:

[root@dhcp35-196 export]# PORT="1189";ldapsearch -x -p $PORT -h localhost -D "cn=Directory Manager" -w Secret123 -b "cn=GrpC,ou=groups,dc=grpmembers,dc=com" "uniquemember" |wc -l ; time ldapmodify -x -p $PORT -h localhost -D "cn=Directory Manager" -w Secret123 -f New100uinqmemadd.ldif
90017
modifying entry "cn=grpC,ou=groups,dc=grpmembers,dc=com"

real	0m35.561s
user	0m0.005s
sys	0m0.003s

[root@dhcp35-196 ~]# ncount=0; PORT="1289";Count=`ldapsearch -x -p $PORT -h localhost -D "cn=Directory Manager" -w Secret123 -b "cn=GrpC,ou=groups,dc=grpmembers,dc=com" "uniquemember" |wc -l`; while [ $Count -ne 90139 ]; do Count=`ldapsearch -x -p $PORT -h localhost -D "cn=Directory Manager" -w Secret123 -b "cn=GrpC,ou=groups,dc=grpmembers,dc=com" "uniquemember" |wc -l` ; sleep 1; ncount=`expr $ncount + 1`; echo "Total wait time is $ncount" ; done
--
--
Total wait time is 36
[root@dhcp35-196 ~]#

For deleting 122 users with uniquemember attribute:

[root@dhcp35-196 export]# PORT="1189";ldapsearch -x -p $PORT -h localhost -D "cn=Directory Manager" -w Secret123 -b "cn=GrpC,ou=groups,dc=grpmembers,dc=com" "uniquemember" |wc -l ; time ldapmodify -x -p $PORT -h localhost -D "cn=Directory Manager" -w Secret123 -f New100uinqmemdel.ldif 
90139
modifying entry "cn=grpC,ou=groups,dc=grpmembers,dc=com"

real	0m5.225s
user	0m0.002s
sys	0m0.003s

[root@dhcp35-196 ~]# ncount=0; PORT="1289";Count=`ldapsearch -x -p $PORT -h localhost -D "cn=Directory Manager" -w Secret123 -b "cn=GrpC,ou=groups,dc=grpmembers,dc=com" "uniquemember" |wc -l`; while [ $Count -ne 90017 ]; do Count=`ldapsearch -x -p $PORT -h localhost -D "cn=Directory Manager" -w Secret123 -b "cn=GrpC,ou=groups,dc=grpmembers,dc=com" "uniquemember" |wc -l` ; sleep 1; ncount=`expr $ncount + 1`; echo "Total wait time is $ncount" ; done
--
--
Total wait time is 5
[root@dhcp35-196 ~]# 

For adding 122 users with member attribute:

[root@dhcp35-196 export]# PORT="1189";ldapsearch -x -p $PORT -h localhost -D "cn=Directory Manager" -w Secret123 -b "cn=GrpB,ou=groups,dc=grpmembers,dc=com" "member" |wc -l ; time ldapmodify -x -p $PORT -h localhost -D "cn=Directory Manager" -w Secret123 -f New100addmember.ldif 
90017
modifying entry "cn=grpB,ou=groups,dc=grpmembers,dc=com"

real	0m37.067s
user	0m0.005s
sys	0m0.004s

[root@dhcp35-196 ~]# ncount=0; PORT="1289";Count=`ldapsearch -x -p $PORT -h localhost -D "cn=Directory Manager" -w Secret123 -b "cn=GrpC,ou=groups,dc=grpmembers,dc=com" "uniquemember" |wc -l`; while [ $Count -ne 90139 ]; do Count=`ldapsearch -x -p $PORT -h localhost -D "cn=Directory Manager" -w Secret123 -b "cn=GrpC,ou=groups,dc=grpmembers,dc=com" "uniquemember" |wc -l` ; sleep 1; ncount=`expr $ncount + 1`; echo "Total wait time is $ncount" ; done
--
--
Total wait time is 39
[root@dhcp35-196 ~]# 


For deleting 244 users with member attribute:

[root@dhcp35-196 export]# PORT="1189";ldapsearch -x -p $PORT -h localhost -D "cn=Directory Manager" -w Secret123 -b "cn=GrpB,ou=groups,dc=grpmembers,dc=com" "member" |wc -l ; time ldapmodify -x -p $PORT -h localhost -D "cn=Directory Manager" -w Secret123 -f New100delmember.ldif 
89895
modifying entry "cn=grpB,ou=groups,dc=grpmembers,dc=com"

real	0m41.023s
user	0m0.008s
sys	0m0.004s


[root@dhcp35-196 ~]# ncount=0; PORT="1289";Count=`ldapsearch -x -p $PORT -h localhost -D "cn=Directory Manager" -w Secret123 -b "cn=GrpB,ou=groups,dc=grpmembers,dc=com" "member" |wc -l`; while [ $Count -ne 89651 ]; do Count=`ldapsearch -x -p $PORT -h localhost -D "cn=Directory Manager" -w Secret123 -b "cn=GrpB,ou=groups,dc=grpmembers,dc=com" "member" |wc -l` ; sleep 1; ncount=`expr $ncount + 1`; echo "Total wait time is $ncount" ; done
--
--
Total wait time is 43


The data above shows that... to synchronize the member/uniquemember attribute add/delete operations to replica is taking almost the same time as the master. Hence, marking the bug as Verified.

Build  tested:

[root@dhcp35-196 ~]# rpm -qa |grep -i 389-ds
389-ds-base-libs-1.3.4.0-15.el7.x86_64
389-ds-base-1.3.4.0-15.el7.x86_64

Comment 4 errata-xmlrpc 2015-11-19 11:42:45 UTC
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://rhn.redhat.com/errata/RHBA-2015-2351.html