#8134 ipa user-add is inefficient
Closed: fixed a year ago by antorres. Opened 4 years ago by cheimes.

ipa user-add is rather slow because it performs a lot of LDAP operations. user-add should be optimized for batch import of users.

Here is a LDAP access log extract from a single user-add operation:

[02/Dec/2019:10:03:27.571684262 +0100] conn=28 op=0 BIND dn="" method=sasl version=3 mech=GSS-SPNEGO
[02/Dec/2019:10:03:27.574623464 +0100] conn=28 op=0 RESULT err=0 tag=97 nentries=0 etime=0.003072259 dn="uid=admin,cn=users,cn=accounts,dc=ipa,dc=example"
[02/Dec/2019:10:03:27.576425260 +0100] conn=28 op=1 SRCH base="cn=schema" scope=0 filter="(objectClass=*)" attrs="attributeTypes objectClasses"
[02/Dec/2019:10:03:27.649300567 +0100] conn=28 op=1 RESULT err=0 tag=101 nentries=1 etime=0.072958242
[02/Dec/2019:10:03:27.709890380 +0100] conn=28 op=2 SRCH base="cn=ipaconfig,cn=etc,dc=ipa,dc=example" scope=0 filter="(objectClass=*)" attrs=ALL
[02/Dec/2019:10:03:27.710562451 +0100] conn=28 op=2 RESULT err=0 tag=101 nentries=1 etime=0.000817892
[02/Dec/2019:10:03:27.711501227 +0100] conn=28 op=3 SRCH base="uid=testuser,cn=deleted users,cn=accounts,cn=provisioning,dc=ipa,dc=example" scope=0 filter="(objectClass=*)" attrs=""
[02/Dec/2019:10:03:27.711670367 +0100] conn=28 op=3 RESULT err=32 tag=101 nentries=0 etime=0.000283936
[02/Dec/2019:10:03:27.712090418 +0100] conn=28 op=4 SRCH base="cn=UPG Definition,cn=Definitions,cn=Managed Entries,cn=etc,dc=ipa,dc=example" scope=0 filter="(objectClass=*)" attrs="* aci"
[02/Dec/2019:10:03:27.712353531 +0100] conn=28 op=4 RESULT err=0 tag=101 nentries=1 etime=0.000405766
[02/Dec/2019:10:03:27.712878958 +0100] conn=28 op=5 SRCH base="cn=testuser,cn=groups,cn=accounts,dc=ipa,dc=example" scope=0 filter="(objectClass=*)" attrs=""
[02/Dec/2019:10:03:27.713133260 +0100] conn=28 op=5 RESULT err=32 tag=101 nentries=0 etime=0.000355139
[02/Dec/2019:10:03:27.713687413 +0100] conn=28 op=6 SRCH base="cn=UPG Definition,cn=Definitions,cn=Managed Entries,cn=etc,dc=ipa,dc=example" scope=0 filter="(objectClass=*)" attrs="* aci"
[02/Dec/2019:10:03:27.713797730 +0100] conn=28 op=6 RESULT err=0 tag=101 nentries=1 etime=0.000206440
[02/Dec/2019:10:03:27.716926736 +0100] conn=28 op=7 ADD dn="uid=testuser,cn=users,cn=accounts,dc=ipa,dc=example"
[02/Dec/2019:10:03:27.732186988 +0100] conn=28 op=7 RESULT err=0 tag=105 nentries=0 etime=0.015430126
[02/Dec/2019:10:03:27.732803680 +0100] conn=28 op=8 SRCH base="uid=testuser,cn=users,cn=accounts,dc=ipa,dc=example" scope=0 filter="(objectClass=*)" attrs="ipaNTHomeDirectoryDrive ipaUniqueID ipaUserAuthType usercertificate;binary fasLocale mail memberOf fasStatusNote krbCanonicalName objectClass fasIRCNick ipaNTLogonScript ipatokenRadiusUserName fasGPGKeyId memberofindirect loginShell ipaCertMapData telephoneNumber fasCreationTime ipaNTHomeDirectory sn initials gecos displayName givenName homeDirectory ipatokenRadiusConfigLink krbPrincipalName ipaNTProfilePath krbPrincipalExpiration fasTimezone userClass cn uidNumber gidNumber title ou nsAccountLock uid"
[02/Dec/2019:10:03:27.733724356 +0100] conn=28 op=8 RESULT err=0 tag=101 nentries=1 etime=0.001038760
[02/Dec/2019:10:03:27.734474909 +0100] conn=28 op=9 SRCH base="dc=ipa,dc=example" scope=2 filter="(|(member=uid=testuser,cn=users,cn=accounts,dc=ipa,dc=example)(memberUser=uid=testuser,cn=users,cn=accounts,dc=ipa,dc=example)(memberHost=uid=testuser,cn=users,cn=accounts,dc=ipa,dc=example))" attrs=""
[02/Dec/2019:10:03:27.734643777 +0100] conn=28 op=9 RESULT err=0 tag=101 nentries=0 etime=0.000226617 notes=P details="Paged Search" pr_idx=0 pr_cookie=-1
[02/Dec/2019:10:03:27.735171537 +0100] conn=28 op=10 SRCH base="uid=testuser,cn=users,cn=accounts,dc=ipa,dc=example" scope=0 filter="(objectClass=*)" attrs=""
[02/Dec/2019:10:03:27.735311560 +0100] conn=28 op=10 RESULT err=0 tag=101 nentries=1 etime=0.000293177
[02/Dec/2019:10:03:27.735628732 +0100] conn=28 op=11 MOD dn="cn=ipausers,cn=groups,cn=accounts,dc=ipa,dc=example"
[02/Dec/2019:10:03:27.740681547 +0100] conn=28 op=11 RESULT err=0 tag=103 nentries=0 etime=0.005098558
[02/Dec/2019:10:03:27.740969532 +0100] conn=28 op=12 SRCH base="uid=testuser,cn=users,cn=accounts,dc=ipa,dc=example" scope=0 filter="(objectClass=*)" attrs="* aci"
[02/Dec/2019:10:03:27.741897450 +0100] conn=28 op=12 RESULT err=0 tag=101 nentries=1 etime=0.000979098
[02/Dec/2019:10:03:27.742510179 +0100] conn=28 op=13 SRCH base="cn=UPG Definition,cn=Definitions,cn=Managed Entries,cn=etc,dc=ipa,dc=example" scope=0 filter="(objectClass=*)" attrs="* aci"
[02/Dec/2019:10:03:27.742805314 +0100] conn=28 op=13 RESULT err=0 tag=101 nentries=1 etime=0.000398775
[02/Dec/2019:10:03:27.744346722 +0100] conn=28 op=14 SRCH base="uid=testuser,cn=users,cn=accounts,dc=ipa,dc=example" scope=0 filter="(userPassword=*)" attrs="userPassword"
[02/Dec/2019:10:03:27.744515460 +0100] conn=28 op=14 RESULT err=0 tag=101 nentries=0 etime=0.000287000
[02/Dec/2019:10:03:27.744915251 +0100] conn=28 op=15 SRCH base="uid=testuser,cn=users,cn=accounts,dc=ipa,dc=example" scope=0 filter="(krbPrincipalKey=*)" attrs="krbPrincipalKey"
[02/Dec/2019:10:03:27.745132728 +0100] conn=28 op=15 RESULT err=0 tag=101 nentries=0 etime=0.000279579
[02/Dec/2019:10:03:27.746099695 +0100] conn=28 op=16 UNBIND

The operation performs 12 LDAP searches (not counting the schema lookup), one ADD and one MOD.

  • cn=ipaconfig,cn=etc is already optimized and looked up one time for a connection / batch.
  • cn=UPG Definition,cn=Definitions,cn=Managed Entries,cn=etc is looked up three times for each user added. It is trivial to optimize and cache the value like cn=ipaconfig,cn=etc.
  • Deleted user entry uid=testuser,cn=deleted users,cn=accounts,cn=provisioning is looked up because the whole provisioning area is not checked by unique uid plugin. This could be addressed by only excluding cn=staged users,cn=accounts,cn=provisioning from uniqueness. It's a pointless to exclude the whole provisioning tree and then perform manual uniqueness checks.
  • (userPassword=*) and (krbPrincipalKey=*) are performed to check if a user has a password or keytab. For user-add IPA can calculate has_password and has_keytab based on the arguments. Perhaps we can archive the same goal much faster with a 389-DS plugin that adds has_password and has_keytab without revealing the content?
  • There are three searches for uid=testuser,cn=users,cn=accounts,dc=ipa,dc=example. I haven't investigated why the user is retrieved three times.

@cheimes, just a comment regarding MOD dn="cn=ipausers,cn=groups,cn=accounts,dc=ipa,dc=example"

This group can become large and its update was IIRC a major contributor to the bad response time of user-add. I do not know if this group is used internally in IPA. An option could be to rebuild it on demand.

master:

  • dcb33e4 Optimize user-add by caching ldap2.has_upg()

ipa-4-8:

  • 0785a03 Optimize user-add by caching ldap2.has_upg()

Closing as we already analyzed operations in user-add during the performance testing effort in 2021.

Metadata Update from @antorres:
- Issue close_status updated to: fixed
- Issue status updated to: Closed (was: Open)

a year ago

Login to comment on this ticket.

Metadata