Bug 1615924

Summary: Fine grained password policy can impact search performance [rhel-7.5.z]
Product: Red Hat Enterprise Linux 7 Reporter: Oneata Mircea Teodor <toneata>
Component: 389-ds-baseAssignee: mreynolds
Status: CLOSED ERRATA QA Contact: Viktor Ashirov <vashirov>
Severity: high Docs Contact: Marc Muehlfeld <mmuehlfe>
Priority: high    
Version: 7.7-AltCC: cbuissar, gparente, mhonek, mreynolds, msauton, nkinder, rmeggins, spichugi, tbordaz, tmihinto, vashirov
Target Milestone: rcKeywords: ZStream
Target Release: ---   
Hardware: All   
OS: Linux   
Whiteboard:
Fixed In Version: 389-ds-base-1.3.7.5-26.el7_5 Doc Type: Bug Fix
Doc Text:
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 the entry is not known. As a result, the performance of searches, such as response time and throughput, is improved.
 Story Points: ---
Clone Of: 1593807 Environment:
Last Closed: 2018-09-25 19:06:11 UTC Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Bug Depends On: 1593807    
Bug Blocks:    

Description Oneata Mircea Teodor 2018-08-14 14:23:15 UTC 
This bug has been copied from bug #1593807 and has been proposed to be backported to 7.5 z-stream (EUS).
Comment 3 Viktor Ashirov 2018-08-30 14:51:28 UTC 
Build tested: 389-ds-base-1.3.7.5-27.el7_5.x86_64

Before the fix (build -25):
# 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
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:14:37:47.959443571 +0000] conn=2 fd=64 slot=64 connection from ::1 to ::1
[30/Aug/2018:14:37:47.959705138 +0000] conn=2 op=0 BIND dn="" method=128 version=3
[30/Aug/2018:14:37:47.959822415 +0000] conn=2 op=0 RESULT err=0 tag=97 nentries=0 etime=0.0000324388 dn=""
[30/Aug/2018:14:37:47.960266428 +0000] conn=2 op=1 SRCH base="dc=example,dc=com" scope=2 filter="(uid=09999)" attrs=ALL
[30/Aug/2018:14:37:47.960801248 +0000] conn=2 op=1 RESULT err=0 tag=101 nentries=1 etime=0.0000833225
[30/Aug/2018:14:37:47.961340496 +0000] conn=2 op=2 UNBIND
[30/Aug/2018:14:37:47.961377484 +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[1877]: Starting at Thu Aug 30 14:45:57 2018

ldclt[1877]: Average rate: 34292.00/thr  (34292.00/sec), total: 342920
ldclt[1877]: Average rate: 33961.00/thr  (33961.00/sec), total: 339610
ldclt[1877]: Average rate: 33089.50/thr  (33089.50/sec), total: 330895
ldclt[1877]: Average rate: 34167.60/thr  (34167.60/sec), total: 341676
ldclt[1877]: Average rate: 34308.20/thr  (34308.20/sec), total: 343082
ldclt[1877]: Average rate: 32118.20/thr  (32118.20/sec), total: 321182
ldclt[1877]: Average rate: 34664.60/thr  (34664.60/sec), total: 346646
ldclt[1877]: Average rate: 34318.10/thr  (34318.10/sec), total: 343181
ldclt[1877]: Average rate: 33888.50/thr  (33888.50/sec), total: 338885
ldclt[1877]: Average rate: 34459.90/thr  (34459.90/sec), total: 344599
ldclt[1877]: Number of samples achieved. Bye-bye...
ldclt[1877]: All threads are dead - exit.
ldclt[1877]: Global average rate: 339267.59/thr  (33926.76/sec), total: 3392676
ldclt[1877]: Global number times "no activity" reports: never
ldclt[1877]: Global no error occurs during this session.
ldclt[1877]: T006: thread is dead.
ldclt[1877]: Ending at Thu Aug 30 14:47:37 2018
ldclt[1877]: Exit status 0 - No problem during execution.
ldclt[1877]: 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 5 errata-xmlrpc 2018-09-25 19:06:11 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:2757