#47874 Performance degradation with scope ONE after some load
Closed: wontfix None Opened 7 years ago by nhosoi.

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


Bug Description: Backend has a bit to indicate "should not bypass
the filter test". It's set if one of the search results is ALLID
in idl_intersection. Once the flag is set, it's never been unset.
It makes the following one level searches slow down.

Fix Description: Introduced slapi_be_unset_flag and unset the bit
at the end of every search.

Reviewed by Rich (Thank you!!)

Pushed to master:
29316b1..8e1345a master -> master
commit 8e1345a

Pushed to 389-ds-base-1.3.2:
39adbdc..3ff6d52 389-ds-base-1.3.2 -> 389-ds-base-1.3.2
commit 3ff6d52

Pushed to 389-ds-1.2.11:
a791bff..caddfa2 389-ds-base-1.2.11 -> 389-ds-base-1.2.11
commit caddfa2

Metadata Update from @nhosoi:
- Issue assigned to nhosoi
- Issue set to the milestone: N/A

4 years ago

389-ds-base is moving from Pagure to Github. This means that new issues and pull requests
will be accepted only in 389-ds-base's github repository.

This issue has been cloned to Github and is available here:
- https://github.com/389ds/389-ds-base/issues/1205

If you want to receive further updates on the issue, please navigate to the github issue
and click on subscribe button.

Thank you for understanding. We apologize for all inconvenience.

Metadata Update from @spichugi:
- Issue close_status updated to: wontfix (was: Fixed)

a year ago

Login to comment on this ticket.

Metadata