Red Hat Bugzilla – Bug 1593807
Fine grained password policy can impact search performance
Last modified: 2018-10-30 06:15:20 EDT
Description of problem: this is a request to backport https://pagure.io/389-ds-base/issue/49742 to RHEL7. When a search evaluates an shadowAccount entry (to return it or not), it adds the shadow attributes (shadowMax, shadowMin....) to the entry. With fine grained password policy (nsslapd-pwpolicy-local: on), it tries to retrieve the shadow attribute from a pwdpolicysubentry. The problem is that it retrieves pwdpolicysubentry attribute value using an internal base search of the evaluated entry. It is useless as in such case we already have the entry. a stack could look like this #6 0x00007f2ce7aedc27 in ldbm_back_search () at /usr/lib64/dirsrv/plugins/libback-ldbm.so #7 0x00007f2cf3fe59c2 in op_shared_search () at /usr/lib64/dirsrv/libslapd.so.0 #8 0x00007f2cf3ff7527 in search_internal_callback_pb () at /usr/lib64/dirsrv/libslapd.so.0 #9 0x00007f2cf3ff7778 in search_internal_pb () at /usr/lib64/dirsrv/libslapd.so.0 #10 0x00007f2cf3ff7b25 in slapi_search_internal_get_entry () at /usr/lib64/dirsrv/libslapd.so.0 #11 0x00007f2cf40017ff in get_entry () at /usr/lib64/dirsrv/libslapd.so.0 #12 0x00007f2cf3ffd1d6 in new_passwdPolicy () at /usr/lib64/dirsrv/libslapd.so.0 #13 0x00007f2cf40012bd in add_shadow_ext_password_attrs () at /usr/lib64/dirsrv/libslapd.so.0 #14 0x00007f2cf3fe413e in send_results_ext.constprop.4 () at /usr/lib64/dirsrv/libslapd.so.0 #15 0x00007f2cf3fe60f1 in op_shared_search () at /usr/lib64/dirsrv/libslapd.so.0 #16 0x0000564ae8ec844e in do_search () #17 0x0000564ae8eb6535 in connection_threadmain () #18 0x00007f2cf1db0bab in _pt_root () at /lib64/libnspr4.so #19 0x00007f2cf1750dd5 in start_thread () at /lib64/libpthread.so.0 #20 0x00007f2cf0dfdb3d in clone () at /lib64/libc.so.6 Version-Release number of selected component (if applicable): 389-ds-base-1.3.6.1-28.el7_4x86_64.rpm Steps to reproduce 1.Create an instance 2.Create a shadowAccount entry 3.Enable internal search logging (nsslapd-accesslog-leve: 260) 4. Enable nsslapd-pwpolicy-local: 1 5. Do a base search on the entry and check that it exists an additional internal search on the entry Actual results In some rsearch rate it can increase throughput by 3 times
Build tested: 389-ds-base-1.3.8.4-12.el7.x86_64 Before the fix (build 389-ds-base-1.3.7.5-25.el7_5.x86_64): # ldapsearch -xLLL -b dc=example,dc=com '(uid=09999)' dn: uid=09999,ou=People,dc=example,dc=com uid: 09999 uid: testnew09999 objectClass: top objectClass: person objectClass: organizationalPerson objectClass: inetorgperson objectClass: posixAccount objectClass: shadowAccount sn: testnew09999 cn: testnew09999 givenName: testnew09999 description: description09999 mail: testnew09999@example.com uidNumber: 309999 gidNumber: 409999 shadowMin: 0 shadowMax: 99999 shadowInactive: 30 shadowWarning: 7 homeDirectory: /home/uid09999 shadowLastChange: 17773 In the access logs: [30/Aug/2018:14:36:03.572822516 +0000] conn=17 fd=64 slot=64 connection from ::1 to ::1 [30/Aug/2018:14:36:03.573064348 +0000] conn=17 op=0 BIND dn="" method=128 version=3 [30/Aug/2018:14:36:03.573203171 +0000] conn=17 op=0 RESULT err=0 tag=97 nentries=0 etime=0.0000309934 dn="" [30/Aug/2018:14:36:03.573543220 +0000] conn=17 op=1 SRCH base="dc=example,dc=com" scope=2 filter="(uid=09999)" attrs=ALL [30/Aug/2018:14:36:03.573858437 +0000] conn=Internal op=-1 SRCH base="uid=09999,ou=people,dc=example,dc=com" scope=0 filter="(|(objectclass=*)(objectclass=ldapsubentry))" attrs=ALL [30/Aug/2018:14:36:03.573989379 +0000] conn=Internal op=-1 RESULT err=0 tag=48 nentries=1 etime=0.0000158917 [30/Aug/2018:14:36:03.574201475 +0000] conn=17 op=1 RESULT err=0 tag=101 nentries=1 etime=0.0000839187 [30/Aug/2018:14:36:03.574717051 +0000] conn=17 op=2 UNBIND [30/Aug/2018:14:36:03.574743698 +0000] conn=17 op=2 fd=64 closed - U1 # ldclt -b "ou=people,dc=example,dc=com" -f uid=09999 -e esearch -I 32 -N 10 ldclt version 4.23 ldclt[1220]: Starting at Thu Aug 30 14:42:02 2018 ldclt[1220]: Average rate: 20849.60/thr (20849.60/sec), total: 208496 ldclt[1220]: Average rate: 19070.30/thr (19070.30/sec), total: 190703 ldclt[1220]: Average rate: 20754.90/thr (20754.90/sec), total: 207549 ldclt[1220]: Average rate: 20763.00/thr (20763.00/sec), total: 207630 ldclt[1220]: Average rate: 18704.90/thr (18704.90/sec), total: 187049 ldclt[1220]: Average rate: 20681.30/thr (20681.30/sec), total: 206813 ldclt[1220]: Average rate: 20674.30/thr (20674.30/sec), total: 206743 ldclt[1220]: Average rate: 20155.40/thr (20155.40/sec), total: 201554 ldclt[1220]: Average rate: 20670.30/thr (20670.30/sec), total: 206703 ldclt[1220]: Average rate: 20770.40/thr (20770.40/sec), total: 207704 ldclt[1220]: Number of samples achieved. Bye-bye... ldclt[1220]: All threads are dead - exit. ldclt[1220]: T002: thread is dead. ldclt[1220]: Global average rate: 203094.41/thr (20309.44/sec), total: 2030944 ldclt[1220]: Global number times "no activity" reports: never ldclt[1220]: Global number of dead threads: 1 ldclt[1220]: Global no error occurs during this session. ldclt[1220]: Ending at Thu Aug 30 14:43:42 2018 ldclt[1220]: Exit status 0 - No problem during execution. ldclt[1220]: T003: thread is dead. ldclt[1220]: T007: thread is dead. ldclt[1220]: T007: thread is dead. With the fix: [30/Aug/2018:16:20:35.858739252 +0000] conn=2 fd=64 slot=64 connection from ::1 to ::1 [30/Aug/2018:16:20:35.858812922 +0000] conn=2 op=0 BIND dn="" method=128 version=3 [30/Aug/2018:16:20:35.858851101 +0000] conn=2 op=0 RESULT err=0 tag=97 nentries=0 etime=0.0000087840 dn="" [30/Aug/2018:16:20:35.859145550 +0000] conn=2 op=1 SRCH base="dc=example,dc=com" scope=2 filter="(uid=09999)" attrs=ALL [30/Aug/2018:16:20:35.859354708 +0000] conn=2 op=1 RESULT err=0 tag=101 nentries=1 etime=0.0000357791 [30/Aug/2018:16:20:35.859562726 +0000] conn=2 op=2 UNBIND [30/Aug/2018:16:20:35.859576506 +0000] conn=2 op=2 fd=64 closed - U1 # ldclt -b "ou=people,dc=example,dc=com" -f uid=09999 -e esearch -I 32 -N 10 ldclt version 4.23 ldclt[732]: Starting at Thu Aug 30 16:21:50 2018 ldclt[732]: Average rate: 33711.70/thr (33711.70/sec), total: 337117 ldclt[732]: Average rate: 35243.50/thr (35243.50/sec), total: 352435 ldclt[732]: Average rate: 34308.20/thr (34308.20/sec), total: 343082 ldclt[732]: Average rate: 35295.90/thr (35295.90/sec), total: 352959 ldclt[732]: Average rate: 34962.70/thr (34962.70/sec), total: 349627 ldclt[732]: Average rate: 33312.80/thr (33312.80/sec), total: 333128 ldclt[732]: Average rate: 35389.00/thr (35389.00/sec), total: 353890 ldclt[732]: Average rate: 34213.30/thr (34213.30/sec), total: 342133 ldclt[732]: Average rate: 33938.10/thr (33938.10/sec), total: 339381 ldclt[732]: Average rate: 35465.00/thr (35465.00/sec), total: 354650 ldclt[732]: Number of samples achieved. Bye-bye... ldclt[732]: All threads are dead - exit. ldclt[732]: Global average rate: 345840.19/thr (34584.02/sec), total: 3458402 ldclt[732]: Global number times "no activity" reports: never ldclt[732]: Global no error occurs during this session. ldclt[732]: T003: thread is dead. ldclt[732]: Ending at Thu Aug 30 16:23:30 2018 ldclt[732]: Exit status 0 - No problem during execution. ldclt[732]: T009: thread is dead. ldclt[732]: T002: thread is dead. Internal search is no longer present in the access logs and average search rate increased by ~60% (both tests were with nunc-stans on). Marking 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/RHSA-2018:3127