Description of problem:

git branch

• 389-ds-base-1.3.2

How reproducible: always.

Steps to Reproduce:
1. Create instance.
2. Create suffix
3. Import an ldif consisting on something like 9000 users and 1000 static
groups containing maximum 1000 uniquemembers each of them. One uniquemember
member of all groups (im my example, uid=user1000)

1. configure server to be sure that dbcache and entry cache are enough to keep
   all data. Use cn=monitor to check after a full scan, caches are good percentage
   free (here using dbmon.sh):

dbcachefree 546604544 free% 91.101 roevicts 0 hit% 99 pagein 12 pageout 0
userroot:ent 10003 505895882 84.3 9407.6
userroot:dn 10003 182770 20.3 71.8

I am using:

nsslapd-dbcachesize: 600000000

UserRoot suffix (o=redhat):

nsslapd-cachememsize: 600000000
nsslapd-dncachememsize: 900717

Just in case:

nsslapd-ndn-cache-enabled: on
nsslapd-ndn-cache-max-size: 200000

Configure access log to log etime in milliseconds:

nsslapd-accesslog-level: 131328

1. Search with scope one a the member present in all the groups:
   (in my example, uid=user1000,ou=people,o=redhat)

ldapsearch -LLL -x -h localhost -p 1389 -D "cn=Directory Manager" -w secret12
-b "ou=groups,o=redhat" -s one "(uniqueMember=uid=user1000,ou=people,o=redhat)"

/dev/nul

Discard first operation and repeat this search to be sure it's in cache:

[11/Aug/2014:15:35:14 +0200] conn=2 op=1 SRCH base="ou=groups,o=redhat" scope=1
filter="(uniqueMember=uid=user1000,ou=people,o=redhat)" attrs=ALL
[11/Aug/2014:15:35:14 +0200] conn=2 op=1 RESULT err=0 tag=101 nentries=1000
etime=0.353000

In my box, etime will be around 0.3/0.4 seconds.

6) do a full search of database:

ldapsearch -LLL -x -h localhost -p 1389 -D "cn=Directory Manager" -w secret12
-b "o=redhat" objectclass=* > /dev/null

7) confirm that database is always in cache:

[root@localhost ~]# DBLIST=userroot HOST=localhost PORT=1389 ./dbmon.sh.fix
Mon Aug 11 15:39:57 CEST 2014
dbcachefree 546604544 free% 91.101 roevicts 0 hit% 100 pagein 0 pageout 0
userroot:ent 10003 505895882 84.3 9407.6
userroot:dn 10003 182770 20.3 71.8

8) Replay step (5)

ldapsearch -LLL -x -h localhost -p 1389 -D "cn=Directory Manager" -w secret12
-b "ou=groups,o=redhat" -s one "(uniqueMember=uid=user1000,ou=people,o=redhat)"

/dev/nul

[11/Aug/2014:15:41:14 +0200] conn=10 op=1 SRCH base="ou=groups,o=redhat"
scope=1 filter="(uniqueMember=uid=user1000,ou=people,o=redhat)" attrs=ALL
[11/Aug/2014:15:41:14 +0200] conn=10 op=1 RESULT err=0 tag=101 nentries=1000
etime=0.693000

now etime will be around 0.6/0.7 seconds. That is to say double than in step 5.

9) Do the full testcase using scope sub and you will see no difference.

[11/Aug/2014:15:44:13 +0200] conn=3 op=1 SRCH base="ou=groups,o=redhat" scope=2
filter="(uniqueMember=uid=user1000,ou=people,o=redhat)" attrs=ALL
[11/Aug/2014:15:44:13 +0200] conn=3 op=1 RESULT err=0 tag=101 nentries=1000
etime=0.332000

[11/Aug/2014:15:44:49 +0200] conn=5 op=1 SRCH base="ou=groups,o=redhat" scope=2
filter="(uniqueMember=uid=user1000,ou=people,o=redhat)" attrs=ALL
[11/Aug/2014:15:44:49 +0200] conn=5 op=1 RESULT err=0 tag=101 nentries=1000
etime=0.335000

Actual results:

etime of the mentioned operation shows a big difference after load (in this
case, just full scan of database).

Expected results:

etime of the operation should be more or less the same after load.

Additional info:

I have tried to debug this issue. I see the time differences are taking place
in result.c function:

send_ldap_search_entry_ext

I am still trying to understand the reason why this difference takes place and
it does not take place with scope sub