Hide Forgot
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.
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
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
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
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")
Attributes that are not in the index: * description * l * nsOsVersion * nsHardwarePlatform * nsHostLocation This causes the slowness of host-find with a search argument
Upstream ticket: https://fedorahosted.org/freeipa/ticket/6371
Fixed upstream master: https://pagure.io/freeipa/c/c99b37737a43a5b101158cff82136a56f9f47af3 https://pagure.io/freeipa/c/5458bb506f70653846e2053fa0234cd63cc3f629
Fixed upstream ipa-4-5: https://pagure.io/freeipa/c/c6e4c8a9663747c55a29318c7cb3c2e444a5e34a https://pagure.io/freeipa/c/43650d45a75271a23712391984013e643ae018cd
Fixed upstream ipa-4-6: https://pagure.io/freeipa/c/47f426a2d31ae3224e355af4de573e4f8c8ccd03 https://pagure.io/freeipa/c/b5735dd3d62f30507cc5d7348edb325cedcf6122
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?
(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.
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.
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"
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