1378892 – host-find slowness caused by missing host attributes in index

RHEL Engineering is moving the tracking of its product development work on RHEL 6 through RHEL 9 to Red Hat Jira (issues.redhat.com). If you're a Red Hat customer, please continue to file support cases via the Red Hat customer portal. If you're not, please head to the "RHEL project" in Red Hat Jira and file new tickets here. Individual Bugzilla bugs in the statuses "NEW", "ASSIGNED", and "POST" are being migrated throughout September 2023. Bugs of Red Hat partners with an assigned Engineering Partner Manager (EPM) are migrated in late September as per pre-agreed dates. Bugs against components "kernel", "kernel-rt", and "kpatch" are only migrated if still in "NEW" or "ASSIGNED". If you cannot log in to RH Jira, please consult article #7032570. That failing, please send an e-mail to the RH Jira admins at rh-issues@redhat.com to troubleshoot your issue as a user management inquiry. The email creates a ServiceNow ticket with Red Hat. Individual Bugzilla bugs that are migrated will be moved to status "CLOSED", resolution "MIGRATED", and set with "MigratedToJIRA" in "Keywords". The link to the successor Jira issue will be found under "Links", have a little "two-footprint" icon next to it, and direct you to the "RHEL project" in Red Hat Jira (issue links are of type "https://issues.redhat.com/browse/RHEL-XXXX", where "X" is a digit). This same link will be available in a blue banner at the top of the page informing you that that bug has been migrated.

Bug 1378892 - host-find slowness caused by missing host attributes in index

Summary: host-find slowness caused by missing host attributes in index

Keywords:
Status:	CLOSED ERRATA
Alias:	None
Product:	Red Hat Enterprise Linux 7
Classification:	Red Hat
Component:	ipa
Sub Component:
Version:	7.3
Hardware:	Unspecified
OS:	Unspecified
Priority:	unspecified
Severity:	unspecified
Target Milestone:	rc
Target Release:	---
Assignee:	IPA Maintainers
QA Contact:	Kaleem
Docs Contact:
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+	depends on / blocked

Reported:	2016-09-23 13:13 UTC by Nikhil Dehadrai
Modified:	2018-04-10 16:41 UTC (History)
CC List:	8 users (show)
Fixed In Version:	ipa-server-4.5.4-5.el7
Doc Type:	If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed:	2018-04-10 16:40:25 UTC
Target Upstream Version:
Embargoed:

Attachments	(Terms of Use)

Links
System	ID	Private	Priority	Status	Summary	Last Updated
Red Hat Product Errata	RHBA-2018:0918	0	None	None	None	2018-04-10 16:41:35 UTC

Description Nikhil Dehadrai 2016-09-23 13:13:35 UTC

Description of problem:
IPA-host* command in large environment relatively takes more time compared to other commands.

Version-Release number of selected component (if applicable):
IPA-server version: ipa-server-4.4.0-12.el7.x86_64

How reproducible:
NA

ENVIRONMENT:
------------
1. Isolated VM
2. RAM: 4GB RAM
3. Processor: 8
4. Tune the machines.
5. Use the data population script to populate the data.

Steps:
1. Setup IPA on RHEL 7.3.
2. Tune the machine as per the details.
3. Once done, capture the details at regular intervals for respective commands such that the each command is run 10 times and the avg time is taken into account.

Actual results:
After step3, it is observed that ipa-host* command in large environment relatively takes more time compared to other commands.

Expected results:
ipa-host command should reflect similar approximate timings.

Comment 3 Martin Bašti 2016-09-26 07:40:31 UTC

I cannot reproduce such time values on provided reproducer

[root@dhcp213-39 ~]# time ipa host-find > /dev/null
ipa: WARNING: Search result has been truncated: Configured size limit exceeded

real	0m7.261s
user	0m2.323s
sys	0m0.114s
[root@dhcp213-39 ~]# time ipa host-show host999.testrelm.test > /dev/null

real	0m4.188s
user	0m1.942s
sys	0m0.117s


Times above are related to values for users

[root@dhcp213-39 ~]# time ipa user-find > /dev/null
ipa: WARNING: Search result has been truncated: Configured size limit exceeded

real	0m11.627s
user	0m2.889s
sys	0m0.167s

[root@dhcp213-39 ~]# time ipa user-show user999 > /dev/null

real	0m4.079s
user	0m1.948s
sys	0m0.104s

Comment 4 Martin Bašti 2016-09-26 08:30:03 UTC

Reproducible when search arg is passed to command host-find, but host show still works as expected

[root@dhcp213-39 ~]# time ipa host-find test101.testrelm.test
--------------
1 host matched
--------------
  Host name: test101.testrelm.test
  Principal name: host/test101.testrelm.test
  Principal alias: host/test101.testrelm.test
----------------------------
Number of entries returned 1
----------------------------

real	0m45.571s
user	0m1.956s
sys	0m0.108s


[root@dhcp213-39 ~]# time ipa host-show test101.testrelm.test
  Host name: test101.testrelm.test
  Principal name: host/test101.testrelm.test
  Principal alias: host/test101.testrelm.test
  Password: False
  Keytab: False
  Managed by: test101.testrelm.test

real	0m3.666s
user	0m1.940s
sys	0m0.140s

Comment 5 Martin Bašti 2016-09-26 08:45:55 UTC

Profiler output

[Mon Sep 26 20:11:38.521895 2016] [:error] [pid 3052] ipa: INFO: [jsonserver_kerb] admin: host_find/1(u'test101.testrelm.test', version=u'2.213'): SUCCESS
[Mon Sep 26 20:11:38.564116 2016] [:error] [pid 3052] ipa: CRITICAL:          152735 function calls (151699 primitive calls) in 33.623 seconds
[Mon Sep 26 20:11:38.564186 2016] [:error] [pid 3052] 
[Mon Sep 26 20:11:38.564190 2016] [:error] [pid 3052]    Ordered by: cumulative time
[Mon Sep 26 20:11:38.564193 2016] [:error] [pid 3052] 
[Mon Sep 26 20:11:38.564197 2016] [:error] [pid 3052]    ncalls  tottime  percall  cumtime  percall filename:lineno(function)
[Mon Sep 26 20:11:38.564226 2016] [:error] [pid 3052]         1    0.000    0.000   33.604   33.604 /usr/lib/python2.7/site-packages/ipalib/frontend.py:439(__call__)
[Mon Sep 26 20:11:38.564230 2016] [:error] [pid 3052]         1    0.000    0.000   33.604   33.604 /usr/lib/python2.7/site-packages/ipalib/frontend.py:451(__do_call)
[Mon Sep 26 20:11:38.564233 2016] [:error] [pid 3052]         1    0.000    0.000   33.595   33.595 /usr/lib/python2.7/site-packages/ipalib/frontend.py:786(run)
[Mon Sep 26 20:11:38.564236 2016] [:error] [pid 3052]         1    0.000    0.000   33.595   33.595 /usr/lib/python2.7/site-packages/ipaserver/plugins/baseldap.py:1951(execute)
[Mon Sep 26 20:11:38.564240 2016] [:error] [pid 3052]         1    0.000    0.000   33.591   33.591 /usr/lib/python2.7/site-packages/ipaserver/plugins/baseldap.py:1092(wrapped)
[Mon Sep 26 20:11:38.564243 2016] [:error] [pid 3052]       2/1    0.000    0.000   33.591   33.591 /usr/lib/python2.7/site-packages/ipapython/ipaldap.py:1314(find_entries)
[Mon Sep 26 20:11:38.564246 2016] [:error] [pid 3052]         8    0.000    0.000   33.231    4.154 /usr/lib64/python2.7/site-packages/ldap/ldapobject.py:80(_ldap_call)
[Mon Sep 26 20:11:38.564250 2016] [:error] [pid 3052]         5    0.000    0.000   33.230    6.646 /usr/lib64/python2.7/site-packages/ldap/ldapobject.py:465(result3)
[Mon Sep 26 20:11:38.564253 2016] [:error] [pid 3052]         5    0.000    0.000   33.230    6.646 /usr/lib64/python2.7/site-packages/ldap/ldapobject.py:473(result4)
[Mon Sep 26 20:11:38.564256 2016] [:error] [pid 3052]         5   33.230    6.646   33.230    6.646 {built-in method result4}
[Mon Sep 26 20:11:38.564259 2016] [:error] [pid 3052]         1    0.000    0.000    0.558    0.558 /usr/lib/python2.7/site-packages/ipaserver/plugins/ldap2.py:81(time_limit)
[Mon Sep 26 20:11:38.564262 2016] [:error] [pid 3052]         2    0.000    0.000    0.558    0.279 /usr/lib/python2.7/site-packages/ipaserver/plugins/ldap2.py:222(get_ipa_config)
[Mon Sep 26 20:11:38.564266 2016] [:error] [pid 3052]         4    0.000    0.000    0.555    0.139 /usr/lib/python2.7/site-packages/ipapython/ipaldap.py:907(_convert_result)
[Mon Sep 26 20:11:38.564269 2016] [:error] [pid 3052]        23    0.000    0.000    0.553    0.024 /usr/lib/python2.7/site-packages/ipapython/ipaldap.py:580(__setitem__)
[Mon Sep 26 20:11:38.564272 2016] [:error] [pid 3052]        23    0.000    0.000    0.553    0.024 /usr/lib/python2.7/site-packages/ipapython/ipaldap.py:400(_set_raw)
[Mon Sep 26 20:11:38.564276 2016] [:error] [pid 3052]        23    0.000    0.000    0.553    0.024 /usr/lib/python2.7/site-packages/ipapython/ipaldap.py:353(_add_attr_name)
[Mon Sep 26 20:11:38.564279 2016] [:error] [pid 3052]        46    0.000    0.000    0.551    0.012 /usr/lib/python2.7/site-packages/ipapython/ipaldap.py:1032(schema)

It looks that LDAP module somehow stuck on getting results

Comment 6 Martin Bašti 2016-09-26 09:56:29 UTC

Output from LDAP access log

[26/Sep/2016:20:11:05.486327379 +051800] conn=37 op=5 SRCH base="cn=computers,cn=accounts,dc=testrelm,dc=test" scope=1 filter="(&(|(description=*test101.testrelm.test*)(krbCanonicalName=*test101.testrelm.test*)(l=*test101.testrelm.test*)(nsOsVersion=*test101.testrelm.test*)(fqdn=*test101.testrelm.test*)(managedBy=*test101.testrelm.test*)(nsHardwarePlatform=*test101.testrelm.test*)(krbPrincipalName=*test101.testrelm.test*)(nsHostLocation=*test101.testrelm.test*))(&(objectClass=ipaobject)(objectClass=nshost)(objectClass=ipahost)(objectClass=pkiuser)(objectClass=ipaservice)))" attrs="macAddress ipaSshPubKey description krbCanonicalName ipaAllowedToPerform l nsOsVersion fqdn ipaAssignedIDView userCertificate nsHardwarePlatform krbPrincipalName krbPrincipalAuthInd nsHostLocation userClass"
[26/Sep/2016:20:11:38.516424829 +051800] conn=37 op=5 RESULT err=0 tag=101 nentries=1 etime=33 notes=U


There is an unindexed search (Please see "notes=U")

Comment 7 Martin Bašti 2016-09-26 10:14:49 UTC

Attributes that are not in the index:
* description
* l
* nsOsVersion
* nsHardwarePlatform
* nsHostLocation

This causes the slowness of host-find with a search argument

Comment 8 Petr Vobornik 2016-09-30 13:30:14 UTC

Upstream ticket:
https://fedorahosted.org/freeipa/ticket/6371

Comment 13 Standa Laznicka 2017-11-07 15:51:53 UTC

Fixed upstream
master:
https://pagure.io/freeipa/c/c99b37737a43a5b101158cff82136a56f9f47af3
https://pagure.io/freeipa/c/5458bb506f70653846e2053fa0234cd63cc3f629

Comment 14 Standa Laznicka 2017-11-08 07:19:46 UTC

Fixed upstream
ipa-4-5:
https://pagure.io/freeipa/c/c6e4c8a9663747c55a29318c7cb3c2e444a5e34a
https://pagure.io/freeipa/c/43650d45a75271a23712391984013e643ae018cd

Comment 15 Standa Laznicka 2017-11-08 07:28:03 UTC

Fixed upstream
ipa-4-6:
https://pagure.io/freeipa/c/47f426a2d31ae3224e355af4de573e4f8c8ccd03
https://pagure.io/freeipa/c/b5735dd3d62f30507cc5d7348edb325cedcf6122

Comment 20 Standa Laznicka 2018-01-23 08:42:11 UTC

Nikhil, in the results you provided, I am seeing a major performance bump from 7.3 to 7.4 that basically shows that the fix was not that necessary.

My question is, then - did you try the build with this patch on 7.4 first or did you use the official 7.4 bits? Was the data the same as previously, where `host-{add,find,show}` operations took >50sec or did you use a smaller data-set?

Comment 21 Nikhil Dehadrai 2018-01-23 08:59:09 UTC

(In reply to Stanislav Laznicka from comment #20)
> Nikhil, in the results you provided, I am seeing a major performance bump
> from 7.3 to 7.4 that basically shows that the fix was not that necessary.
> 
> My question is, then - did you try the build with this patch on 7.4 first or
> did you use the official 7.4 bits? Was the data the same as previously,
> where `host-{add,find,show}` operations took >50sec or did you use a smaller
> data-set?

I had used similar data-set, by using the script available at https://github.com/freeipa/freeipa-tools/blob/master/create-test-data.py on both RHEL 7.4.z and RHEL 7.5 replicating similar setup and following the steps mentioned at description.

Comment 22 Standa Laznicka 2018-01-23 09:43:03 UTC

I see that previously you tested this scenario only on one machine, without replication. While I doubt that the entries in the "cn=index,cn=userroot,cn=ldbm database,cn=plugins,cn=config" subtree get replicated, can you please re-run the tests on both the machines separated (meaning separate 7.4, 7.5 masters)?

I do not know what to account for the performance boost in 7.3 -> 7.4 and it's easier to blame different environments first than search the git tree.

I also checked the patches in distgit rhel-7.4 branch for ipa and it does not seem like we added any performance updates for host-related operations there.

Comment 23 Nikhil Dehadrai 2018-01-24 13:32:30 UTC

ipa-server-version: ipa-4.5.4-8.el7

Tested the bug on the basis of following steps:
1. Isolated VM
2. RAM: 4GB RAM
3. HDD: 40GB
4. Processor: 8
5. Tuned the systems using following script:

Tunning.sh
----------------------------------------------------------
#!/bin/bash
 
ldapsearch -D "cn=directory manager" -w Secret123 -b "cn=config,cn=ldbm database,cn=plugins,cn=config" nsslapd-dbcachesize nsslapd-db-locks | grep nsslapd-dbcachesize
ldapsearch -D "cn=directory manager" -w Secret123 -b "cn=config,cn=ldbm database,cn=plugins,cn=config" nsslapd-dbcachesize nsslapd-db-locks | grep nsslapd-db-locks
 
ldapsearch -D "cn=directory manager" -w Secret123 -b "cn=userRoot,cn=ldbm database,cn=plugins,cn=config" nsslapd-cachememsize nsslapd-dncachememsize | grep nsslapd-cachememsize
ldapsearch -D "cn=directory manager" -w Secret123 -b "cn=userRoot,cn=ldbm database,cn=plugins,cn=config" nsslapd-cachememsize nsslapd-dncachememsize | grep nsslapd-dncachememsize
 
cat << EOF > nsslapd-dbcachesize.ldif
dn: cn=config,cn=ldbm database,cn=plugins,cn=config
changetype: modify
replace: nsslapd-dbcachesize
nsslapd-dbcachesize: 200000000
EOF
 
ldapmodify -D "cn=directory manager" -w Secret123 -x -f nsslapd-dbcachesize.ldif
ldapsearch -D "cn=directory manager" -w Secret123 -b "cn=config,cn=ldbm database,cn=plugins,cn=config" nsslapd-dbcachesize nsslapd-db-locks | grep nsslapd-dbcachesize
 
cat << EOF > nsslapd-cachememsize.ldif
dn: cn=userRoot,cn=ldbm database,cn=plugins,cn=config
changetype: modify
replace: nsslapd-cachememsize
nsslapd-cachememsize: 400000000
EOF
 
ldapmodify -D "cn=directory manager" -w Secret123 -x -f nsslapd-cachememsize.ldif
ldapsearch -D "cn=directory manager" -w Secret123 -b "cn=userRoot,cn=ldbm database,cn=plugins,cn=config" nsslapd-cachememsize nsslapd-dncachememsize | grep nsslapd-cachememsize
 
cat << EOF > nsslapd-dncachememsize.ldif
dn: cn=userRoot,cn=ldbm database,cn=plugins,cn=config
changetype: modify
Replace: nsslapd-dncachememsize
Nsslapd-dncachememsize: 22496800
EOF
 
ldapmodify -D "cn=directory manager" -w Secret123 -x -f nsslapd-dncachememsize.ldif
ldapsearch -D "cn=directory manager" -w Secret123 -b "cn=userRoot,cn=ldbm database,cn=plugins,cn=config" nsslapd-cachememsize nsslapd-dncachememsize | grep nsslapd-dncachememsize

ipactl stop
 
cat /etc/dirsrv/slapd-TESTRELM-TEST/dse.ldif | grep nsslapd-db-locks:
 
# vi /etc/dirsrv/slapd-TESTRELM-TEST/dse.ldif and update nsslapd-db-locks: db_lock_number (example : 22496800)..update this on the basis of DN entries
cat /etc/dirsrv/slapd-TESTRELM-TEST/dse.ldif | grep nsslapd-db-locks:
 
sed -i -e 's/^nsslapd-db-locks:.*/nsslapd-db-locks: 22496800/' /etc/dirsrv/slapd-TESTRELM-TEST/dse.ldif
 
cat /etc/dirsrv/slapd-TESTRELM-TEST/dse.ldif | grep nsslapd-db-locks:

#once above step done execute systemctl start dirsrv.target
#systemctl start dirsrv.target

ipactl restart 


----------------------------end of tunning script------------------------------

STEPS to Reproduce and Verify:
1. Setup IPA MASTERR on RHEL 7.4.z and RHEL 7.5 IPA server, Prepare my.ldif for data population on both the IPA server to replicate large environment.
2. Get the large-environment script from https://github.com/freeipa/freeipa-tools/blob/master/create-test-data.py and rename it to "create_data.py"
3. Create ldif file for import "python create_data.py > my.ldif"
4. Now import data to repective IPA servers "ldapadd -D "cn=directory manager" -w Secret123 -x -c -f my.ldif"
5. Once completed, Tune the systems by running "Tunning.sh" shared above.
6. Run the commands:
# ipa config-mod --searchrecordslimit=0
# ipa config-mod --searchtimelimit=0
7. Capture the data
 

Following Data is captured for host command performance:

RHEL 7.5:(sec)
-------------
Host-add: 1.823
Host-find: 1.818
Host-show: 2.67

RHEL 7.4.z:(sec)
--------------
Host-add: 1.86
Host-find: 47.116
Host-show: 2.774

Improvement (Difference RHEL 7.5 - RHEL 7.4.z) (sec):
-----------------
Host-add: -0.037
Host-find: -45.298
Host-show: -0.104

Thus based on above observations, marking the status of the bug as "VERIFIED"

Comment 27 errata-xmlrpc 2018-04-10 16:40:25 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://access.redhat.com/errata/RHBA-2018:0918

Note You need to log in before you can comment on or make changes to this bug.