#6100 on large deployment user-add in 4.4 is much slower than in 4.2
Closed: Fixed None Opened 7 years ago by tbordaz.

Comparison of performance between

7.2 ipa-server-4.2.0-15.el7_2.17.x86_64  -  389-ds-base-1.3.4.0-32.el7_2.x86_64
vs
7.3 ipa-server-4.4.0-2.1.el7.x86_64   - 389-ds-base-1.3.5.10-5.el7.x86_64

The test case is : install a server, provision 50K users and 40K hosts, add a user

7.2 time ipa user-add --first=t --last=b tb2 ---> 0m2.734s
vs
7.3 time ipa user-add --first=t --last=b tb6 ---> 1m7.337s

The logs shows that the majority of the time is spent in the ADD of the user

7.3 (4.4)
[20/Jul/2016:18:51:22.912022134 +0200] conn=29 op=8 ADD dn="uid=tb7,cn=users,cn=accounts,<suffix>"
..
[20/Jul/2016:18:52:26.721758995 +0200] conn=29 op=8 RESULT err=0 tag=105 nentries=0 etime=63.810000


vs
7.2 (4.3)
[20/Jul/2016:19:15:49 +0200] conn=35 op=8 ADD dn="uid=tb3,cn=users,cn=accounts,<suffix>"
[20/Jul/2016:19:15:49 +0200] conn=35 op=8 RESULT err=0 tag=105 nentries=0 etime=0.268000

In 4.4 there is NO internal operation during the ADD

Here are additional metrics 7.3 vs 7.2

7.3 (ipa-server-4.4.0-2.1.el7.x86_64   - 389-ds-base-1.3.5.10-5.el7.x86_64): 
    1m16.077s
[21/Jul/2016:16:50:05.969746030 +0200] conn=31 op=8 ADD dn="uid=tb20,cn=users,cn=accounts,<suffix>"
[21/Jul/2016:16:51:15.232939727 +0200] conn=31 op=8 RESULT err=0 tag=105 nentries=0 etime=69.263000

7.3 - no Schema_compat:
    0m36.887s
[21/Jul/2016:15:37:41.568081774 +0200] conn=25 op=9 ADD dn="uid=tb13,cn=users,cn=accounts,<suffix>"
[21/Jul/2016:15:38:14.066583465 +0200] conn=25 op=9 RESULT err=0 tag=105 nentries=0 etime=32.499000

7.3 - no Schema_compat - no Memberof:
    0m22.292s
[21/Jul/2016:16:17:27.587599195 +0200] conn=29 op=8 ADD dn="uid=tb15,cn=users,cn=accounts,<suffix>"
[21/Jul/2016:16:17:46.324726021 +0200] conn=29 op=8 RESULT err=0 tag=105 nentries=0 etime=18.738000

7.3 - no Schema_compat - no Memberof - no uniqueness:
    0m3.790s
[21/Jul/2016:16:20:55.859107187 +0200] conn=29 op=8 ADD dn="uid=tb17,cn=users,cn=accounts,<suffix>"
[21/Jul/2016:16:20:55.985310540 +0200] conn=29 op=8 RESULT err=0 tag=105 nentries=0 etime=0.126000

7.3 - no uniqueness: <<----------- Major impact
    0m2.914s
[21/Jul/2016:19:32:38.347117688 +0200] conn=35 op=8 ADD dn="uid=tb24,cn=users,cn=accounts,<suffix>"
[21/Jul/2016:19:32:38.553857063 +0200] conn=35 op=8 RESULT err=0 tag=105 nentries=0 etime=0.207000


------------------------------------------------

7.2 (7.2 ipa-server-4.2.0-15.el7_2.17.x86_64  -  389-ds-base-1.3.4.0-32.el7_2.x86_64):
    0m2.570s
[21/Jul/2016:18:42:03 +0200] conn=33 op=8 ADD dn="uid=tb7,cn=users,cn=accounts,<suffix>"
[21/Jul/2016:18:42:03 +0200] conn=33 op=8 RESULT err=0 tag=105 nentries=0 etime=0.417000

7.2 - no Schema_compat:
    0m2.073s
[21/Jul/2016:18:51:14 +0200] conn=28 op=8 ADD dn="uid=tb8,cn=users,cn=accounts,<suffix>"
[21/Jul/2016:18:51:15 +0200] conn=28 op=8 RESULT err=0 tag=105 nentries=0 etime=0.124000

7.2 - no Schema_compat - no Memberof:
    0m1.449s
[21/Jul/2016:18:54:30 +0200] conn=27 op=9 ADD dn="uid=tb10,cn=users,cn=accounts,<suffix>"
[21/Jul/2016:18:54:30 +0200] conn=27 op=9 RESULT err=0 tag=105 nentries=0 etime=0.275000

7.2 - no Schema_compat - no Memberof - no uniqueness:
    0m2.082s
[21/Jul/2016:18:57:19 +0200] conn=27 op=9 ADD dn="uid=tb12,cn=users,cn=accounts,<suffix>"
[21/Jul/2016:18:57:19 +0200] conn=27 op=9 RESULT err=0 tag=105 nentries=0 etime=0.169000

uniqueness:
- certificate store issuer/serial uniqueness
- certificate store subject uniqueness
- ipaUniqueID
- krbCanonicalName
- krbPrincipalName
- netgroup
- sudorule name
- uid

In conclusion:

  • In 7.2
    • CLI response time is almost identical disabling or not some plugins
    • ADD response time is two times faster disabling or not some plugins
  • In 7.3

    • CLI response time is 20 times faster disable some plugins
    • ADD response time is 600 times faster disabling some plugins
      *ADD response time is almost identical to 7.2 response time when some plugins are disabled.

    One of the most impacting plugin is uid uniqueness.
    Next steps is to confirm the impact of this plugin and check
    what changed in that plugin 1.3.4.0-32 vs 1.3.5.10-5

  • there is no significant change in 389-ds uid uniqueness plugin 1.3.4.0-32 vs 1.3.5.10-5
  • The problem is likely a configuration issue. The performance hit occurs because krbCanonicalName uniqueness checking. It triggers an internal search that is not indexed:

    [22/Jul/2016:11:43:37.912161012 +0200] conn=Internal op=-1 SRCH base="<suffix>" scope=2 filter="(|(krbCanonicalName=tb41@<realm>))" attrs="1.1"
    [22/Jul/2016:11:43:57.785950316 +0200] conn=Internal op=-1 RESULT err=0 tag=48 nentries=0 etime=19.874000 notes=A

  • Note that the performance issue does not occurs when checking uniqueness of the others attributes

    • certificate store issuer/serial uniqueness
    • certificate store subject uniqueness
    • ipaUniqueID
    • krbPrincipalName
    • netgroup
    • sudorule name
    • uid

Adding the index krbCanonicalName, restore the good performance:

dn: cn=krbCanonicalName,cn=index,cn=userRoot,cn=ldbm database,cn=plugins,cn=co
 nfig
cn: krbCanonicalName
nsIndexType: eq
nsIndexType: sub 
nsSystemIndex: false
objectClass: top 
objectClass: nsIndex





ADD : 0m2.317s                                                                                                                      
[22/Jul/2016:12:06:56.423116589 +0200] conn=30 op=8 ADD dn="uid=tb43,cn=users,cn=accounts,<suffix>"
[22/Jul/2016:12:06:56.576491358 +0200] conn=30 op=8 RESULT err=0 tag=105 nentries=0 etime=0.153000

Additional note:

in 7.2 uniqueness krbCanonicalName was enforced.
It worked fast in 7.2 because there was no krbCanonicalName attribute in the added entry.
So DS was not checking the duplicate values.

master:

  • 807702c Create indexes for krbCanonicalName attribute

Metadata Update from @tbordaz:
- Issue assigned to mbabinsk
- Issue set to the milestone: FreeIPA 4.4.1

7 years ago

Login to comment on this ticket.

Metadata