ipa user-add is rather slow because it performs a lot of LDAP operations. user-add should be optimized for batch import of users.
ipa user-add
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
cn=UPG Definition,cn=Definitions,cn=Managed Entries,cn=etc
uid=testuser,cn=deleted users,cn=accounts,cn=provisioning
cn=staged users,cn=accounts,cn=provisioning
(userPassword=*)
(krbPrincipalKey=*)
user-add
has_password
has_keytab
uid=testuser,cn=users,cn=accounts,dc=ipa,dc=example
has_upg optimization: https://github.com/freeipa/freeipa/pull/3971
@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:
ipa-4-8:
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)
Login to comment on this ticket.