Bug 1593807 - Fine grained password policy can impact search performance
Summary: Fine grained password policy can impact search performance
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Red Hat Enterprise Linux 7
Classification: Red Hat
Component: 389-ds-base
Version: 7.7-Alt
Hardware: All
OS: Linux
high
high
Target Milestone: rc
: ---
Assignee: thierry bordaz
QA Contact: RHDS QE
Marc Muehlfeld
URL:
Whiteboard:
Depends On:
Blocks: 1615924
TreeView+ depends on / blocked
 
Reported: 2018-06-21 15:37 UTC by German Parente
Modified: 2018-10-30 10:15 UTC (History)
7 users (show)

Fixed In Version: 389-ds-base-1.3.8.4-1.el7
Doc Type: Bug Fix
Doc Text:
Improved performance when the fine-grained password policy is enabled in Directory Server When a search evaluates the "shadowAccount" entry, Directory Server adds the shadow attributes to the entry. If the fine-grained password policy is enabled, the "shadowAccount" entry can contain its own "pwdpolicysubentry" policy attribute. Previously, to retrieve this attribute, the server started an internal search for each "shadowAccount" entry, which was unnecessary because the entry was already known to the server. With this update, Directory Server only starts internal searches if if the entry is not known. As a result, the performance of searches, such as response time and throughput, is improved.
Clone Of:
: 1615924 (view as bug list)
Environment:
Last Closed: 2018-10-30 10:14:34 UTC


Attachments (Terms of Use)


Links
System ID Priority Status Summary Last Updated
Red Hat Product Errata RHSA-2018:3127 None None None 2018-10-30 10:15:20 UTC

Description German Parente 2018-06-21 15:37:52 UTC
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

Comment 8 Viktor Ashirov 2018-08-30 16:25:40 UTC
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.

Comment 10 errata-xmlrpc 2018-10-30 10:14:34 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/RHSA-2018:3127


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