Bug 497556

Summary: LDAPI: activation of LDAPI UNIX socket causes serious performance issues in TCP/IP searches
Product: [Retired] 389 Reporter: Andrey Ivanov <andrey.ivanov>
Component: Directory ServerAssignee: Nathan Kinder <nkinder>
Status: CLOSED CURRENTRELEASE QA Contact: Viktor Ashirov <vashirov>
Severity: medium Docs Contact:
Priority: high    
Version: 1.2.0CC: jgalipea, nhosoi, nkinder, rmeggins
Target Milestone: ---   
Target Release: ---   
Hardware: x86_64   
OS: Linux   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2015-12-07 16:40:49 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:    
Bug Blocks: 434914, 533025    
Attachments:
Description Flags
Patch rmeggins: review+

Description Andrey Ivanov 2009-04-24 17:47:19 UTC 
User-Agent:       Mozilla/5.0 (Windows; U; Windows NT 5.1; fr; rv:1.9.0.8) Gecko/2009032609 Firefox/3.0.8 (.NET CLR 3.5.30729)

I have put the unix socket listening feature to the test in our production environment. But very soon i had to make a step back - there were serious performance problems. When i activate the listening of the unix socket (nsslapd-ldapilisten: on) the TCP/IP requests on multi-operation connections are 40(sic!) times slower. When i put nsslapd-ldapilisten to "off" the server runs again normally without any slowdowns.





Reproducible: Always

Steps to Reproduce:
1. Compile the server with ./confugure --enable-autobind
2. Activate the unix socket in dse.ldif:
nsslapd-ldapifilepath: <path-to-socket>
nsslapd-ldapilisten: on
nsslapd-ldapiautobind: on
nsslapd-ldapimaprootdn: cn=Directory Manager
nsslapd-ldapimaptoentries: off
nsslapd-ldapiuidnumbertype: uidNumber
nsslapd-ldapigidnumbertype: gidNumber
nsslapd-ldapientrysearchbase: dc=example,dc=com
3. Launch a connection wuth a single bind and a lot of operations per bind (in my case, the problem starts after op=20)
Actual Results:  
Here are the typical logs with operation etime (note  that the slowdown starts at operation 20-25, not just after the bind - the time of a search passes from 0-1 milliseconds to 40-42 msec, the binds themselves are not slowed down):

----------------------------
with nsslapd-ldapilisten:on - look at the "etime" for the frst searches and starting from the operation op=20

[23/Apr/2009:19:24:17 +0200] conn=7288 fd=129 slot=129 connection from 129.104.69.6 to 129.104.69.6
[23/Apr/2009:19:24:17 +0200] conn=7288 op=0 BIND dn="" method=sasl version=3 mech=GSSAPI
[23/Apr/2009:19:24:17 +0200] conn=7288 op=0 RESULT err=14 tag=97 nentries=0 etime=0.004000, SASL bind in progress
[23/Apr/2009:19:24:17 +0200] conn=7288 op=1 BIND dn="" method=sasl version=3 mech=GSSAPI
[23/Apr/2009:19:24:17 +0200] conn=7288 op=1 RESULT err=14 tag=97 nentries=0 etime=0.000000, SASL bind in progress
[23/Apr/2009:19:24:17 +0200] conn=7288 op=2 BIND dn="" method=sasl version=3 mech=GSSAPI
[23/Apr/2009:19:24:17 +0200] conn=7288 op=2 RESULT err=0 tag=97 nentries=0 etime=0.001000 dn="uid=andrey.ivanov,ou=personnel,ou=utilisateurs,dc=id,dc=polytechnique,dc=edu"
[23/Apr/2009:19:24:17 +0200] conn=7288 op=3 SRCH base="ou=utilisateurs,dc=id,dc=polytechnique,dc=edu" scope=2 filter="(&(objectClass=inetOrgPerson)(X-majaxIndex=*))" attrs="* aci"
[23/Apr/2009:19:24:22 +0200] conn=7288 op=3 RESULT err=0 tag=101 nentries=5423 etime=4.917000 notes=U
[23/Apr/2009:19:24:22 +0200] conn=7288 op=4 SRCH base="uid=andrey.ivanov,ou=Personnel,ou=Utilisateurs,dc=id,dc=polytechnique,dc=edu" scope=0 filter="(&(sn=Ivanov)(givenName=Andrey)(X-Civilite=M.))" attrs="1.1"
[23/Apr/2009:19:24:22 +0200] conn=7288 op=4 RESULT err=0 tag=101 nentries=1 etime=0.000000
[23/Apr/2009:19:24:22 +0200] conn=7288 op=5 SRCH base="ou=dsi,ou=dg,ou=organisation,dc=id,dc=polytechnique,dc=edu" scope=0 filter="(objectClass=*)" attrs="1.1"
[23/Apr/2009:19:24:22 +0200] conn=7288 op=5 RESULT err=0 tag=101 nentries=1 etime=0.000000
[23/Apr/2009:19:24:22 +0200] conn=7288 op=6 SRCH base="uid=boyang.chen,ou=etudiants,ou=utilisateurs,dc=id,dc=polytechnique,dc=edu" scope=0 filter="(&(sn=Chen)(givenName=Boyang)(X-Civilite=M.))" attrs="1.1"
[23/Apr/2009:19:24:22 +0200] conn=7288 op=6 RESULT err=0 tag=101 nentries=1 etime=0.000000
[23/Apr/2009:19:24:22 +0200] conn=7288 op=7 SRCH base="ou=x06,ou=eleve,ou=de,ou=dgae,ou=dg,ou=organisation,dc=id,dc=polytechnique,dc=edu" scope=0 filter="(objectClass=*)" attrs="1.1"
[23/Apr/2009:19:24:22 +0200] conn=7288 op=7 RESULT err=0 tag=101 nentries=1 etime=0.001000
[23/Apr/2009:19:24:22 +0200] conn=7288 op=8 SRCH base="uid=thibaut.bondoux,ou=etudiants,ou=utilisateurs,dc=id,dc=polytechnique,dc=edu" scope=0 filter="(&(sn=Bondoux)(givenName=Thibaut)(X-Civilite=M.))" attrs="1.1"
[23/Apr/2009:19:24:22 +0200] conn=7288 op=8 RESULT err=0 tag=101 nentries=1 etime=0.001000
[23/Apr/2009:19:24:22 +0200] conn=7288 op=9 SRCH base="ou=x05,ou=eleve,ou=de,ou=dgae,ou=dg,ou=organisation,dc=id,dc=polytechnique,dc=edu" scope=0 filter="(objectClass=*)" attrs="1.1"
[23/Apr/2009:19:24:22 +0200] conn=7288 op=9 RESULT err=0 tag=101 nentries=1 etime=0.000000
[23/Apr/2009:19:24:22 +0200] conn=7288 op=10 SRCH base="uid=stephane.thomas,ou=etudiants,ou=utilisateurs,dc=id,dc=polytechnique,dc=edu" scope=0 filter="(&(sn=Thomas)(givenName=St\c3\a9phane)(X-Civilite=M.))" attrs="1.1"
[23/Apr/2009:19:24:22 +0200] conn=7288 op=10 RESULT err=0 tag=101 nentries=1 etime=0.001000
[23/Apr/2009:19:24:22 +0200] conn=7288 op=11 SRCH base="ou=x05,ou=eleve,ou=de,ou=dgae,ou=dg,ou=organisation,dc=id,dc=polytechnique,dc=edu" scope=0 filter="(objectClass=*)" attrs="1.1"
[23/Apr/2009:19:24:22 +0200] conn=7288 op=11 RESULT err=0 tag=101 nentries=1 etime=0.000000
[23/Apr/2009:19:24:22 +0200] conn=7288 op=12 SRCH base="uid=raul.celistrino-teixeira,ou=etudiants,ou=utilisateurs,dc=id,dc=polytechnique,dc=edu" scope=0 filter="(&(sn=Celistrino Teixeira)(givenName=Raul)(X-Civilite=M.))" attrs="1.1"
[23/Apr/2009:19:24:22 +0200] conn=7288 op=12 RESULT err=0 tag=101 nentries=1 etime=0.001000
[23/Apr/2009:19:24:22 +0200] conn=7288 op=13 SRCH base="ou=x06,ou=eleve,ou=de,ou=dgae,ou=dg,ou=organisation,dc=id,dc=polytechnique,dc=edu" scope=0 filter="(objectClass=*)" attrs="1.1"
[23/Apr/2009:19:24:22 +0200] conn=7288 op=13 RESULT err=0 tag=101 nentries=1 etime=0.000000
[23/Apr/2009:19:24:22 +0200] conn=7288 op=14 SRCH base="uid=nicolas.naville,ou=etudiants,ou=utilisateurs,dc=id,dc=polytechnique,dc=edu" scope=0 filter="(&(sn=Naville)(givenName=Nicolas)(X-Civilite=M.))" attrs="1.1"
[23/Apr/2009:19:24:22 +0200] conn=7288 op=14 RESULT err=0 tag=101 nentries=1 etime=0.001000
[23/Apr/2009:19:24:22 +0200] conn=7288 op=15 SRCH base="ou=x05,ou=eleve,ou=de,ou=dgae,ou=dg,ou=organisation,dc=id,dc=polytechnique,dc=edu" scope=0 filter="(objectClass=*)" attrs="1.1"
[23/Apr/2009:19:24:22 +0200] conn=7288 op=15 RESULT err=0 tag=101 nentries=1 etime=0.000000
[23/Apr/2009:19:24:22 +0200] conn=7288 op=16 SRCH base="uid=adel.habre,ou=etudiants,ou=utilisateurs,dc=id,dc=polytechnique,dc=edu" scope=0 filter="(&(sn=Habre)(givenName=Adel)(X-Civilite=M.))" attrs="1.1"
[23/Apr/2009:19:24:22 +0200] conn=7288 op=16 RESULT err=0 tag=101 nentries=1 etime=0.001000
[23/Apr/2009:19:24:22 +0200] conn=7288 op=17 SRCH base="ou=x04,ou=eleve,ou=de,ou=dgae,ou=dg,ou=organisation,dc=id,dc=polytechnique,dc=edu" scope=0 filter="(objectClass=*)" attrs="1.1"
[23/Apr/2009:19:24:22 +0200] conn=7288 op=17 RESULT err=0 tag=101 nentries=1 etime=0.000000
[23/Apr/2009:19:24:22 +0200] conn=7288 op=18 SRCH base="uid=ali.azadi,ou=etudiants,ou=utilisateurs,dc=id,dc=polytechnique,dc=edu" scope=0 filter="(&(sn=Azadi)(givenName=Ali)(X-Civilite=M.))" attrs="1.1"
[23/Apr/2009:19:24:22 +0200] conn=7288 op=18 RESULT err=0 tag=101 nentries=1 etime=0.001000
[23/Apr/2009:19:24:23 +0200] conn=7288 op=19 SRCH base="ou=x05,ou=eleve,ou=de,ou=dgae,ou=dg,ou=organisation,dc=id,dc=polytechnique,dc=edu" scope=0 filter="(objectClass=*)" attrs="1.1"
[23/Apr/2009:19:24:23 +0200] conn=7288 op=19 RESULT err=0 tag=101 nentries=1 etime=0.000000
[23/Apr/2009:19:24:23 +0200] conn=7288 op=20 SRCH base="uid=helene.condat,ou=etudiants,ou=utilisateurs,dc=id,dc=polytechnique,dc=edu" scope=0 filter="(&(sn=Condat)(givenName=H\c3\a9l\c3\a8ne)(X-Civilite=Mlle))" attrs="1.1"
[23/Apr/2009:19:24:23 +0200] conn=7288 op=20 RESULT err=0 tag=101 nentries=1 etime=0.042000
[23/Apr/2009:19:24:23 +0200] conn=7288 op=21 SRCH base="ou=x06,ou=eleve,ou=de,ou=dgae,ou=dg,ou=organisation,dc=id,dc=polytechnique,dc=edu" scope=0 filter="(objectClass=*)" attrs="1.1"
[23/Apr/2009:19:24:23 +0200] conn=7288 op=21 RESULT err=0 tag=101 nentries=1 etime=0.040000
[23/Apr/2009:19:24:23 +0200] conn=7288 op=22 SRCH base="uid=nicolas.roser,ou=etudiants,ou=utilisateurs,dc=id,dc=polytechnique,dc=edu" scope=0 filter="(&(sn=Roser)(givenName=Nicolas)(X-Civilite=M.))" attrs="1.1"
[23/Apr/2009:19:24:23 +0200] conn=7288 op=22 RESULT err=0 tag=101 nentries=1 etime=0.042000
[23/Apr/2009:19:24:23 +0200] conn=7288 op=23 SRCH base="ou=x04,ou=eleve,ou=de,ou=dgae,ou=dg,ou=organisation,dc=id,dc=polytechnique,dc=edu" scope=0 filter="(objectClass=*)" attrs="1.1"
[23/Apr/2009:19:24:23 +0200] conn=7288 op=23 RESULT err=0 tag=101 nentries=1 etime=0.041000
[23/Apr/2009:19:24:23 +0200] conn=7288 op=24 SRCH base="uid=ngoc-duong.dang,ou=etudiants,ou=utilisateurs,dc=id,dc=polytechnique,dc=edu" scope=0 filter="(&(sn=Dang)(givenName=Ngoc Duong)(X-Civilite=M.))" attrs="1.1"
[23/Apr/2009:19:24:23 +0200] conn=7288 op=24 RESULT err=0 tag=101 nentries=1 etime=0.041000
[23/Apr/2009:19:24:23 +0200] conn=7288 op=25 SRCH base="ou=x04,ou=eleve,ou=de,ou=dgae,ou=dg,ou=organisation,dc=id,dc=polytechnique,dc=edu" scope=0 filter="(objectClass=*)" attrs="1.1"
[23/Apr/2009:19:24:23 +0200] conn=7288 op=25 RESULT err=0 tag=101 nentries=1 etime=0.041000
[23/Apr/2009:19:24:23 +0200] conn=7288 op=26 SRCH base="uid=cyrille.ronsin,ou=etudiants,ou=utilisateurs,dc=id,dc=polytechnique,dc=edu" scope=0 filter="(&(sn=Ronsin)(givenName=Cyrille)(X-Civilite=M.))" attrs="1.1"
[23/Apr/2009:19:24:23 +0200] conn=7288 op=26 RESULT err=0 tag=101 nentries=1 etime=0.041000
[23/Apr/2009:19:24:23 +0200] conn=7288 op=27 SRCH base="ou=x04,ou=eleve,ou=de,ou=dgae,ou=dg,ou=organisation,dc=id,dc=polytechnique,dc=edu" scope=0 filter="(objectClass=*)" attrs="1.1"
[23/Apr/2009:19:24:23 +0200] conn=7288 op=27 RESULT err=0 tag=101 nentries=1 etime=0.041000
[23/Apr/2009:19:24:23 +0200] conn=7288 op=28 SRCH base="uid=pablo.de-manuel-triantafilo,ou=etudiants,ou=utilisateurs,dc=id,dc=polytechnique,dc=edu" scope=0 filter="(&(sn=De Manuel Triantafilo)(givenName=Pablo)(X-Civilite=M.))" attrs="1.1"
[23/Apr/2009:19:24:23 +0200] conn=7288 op=28 RESULT err=0 tag=101 nentries=1 etime=0.041000
[23/Apr/2009:19:24:23 +0200] conn=7288 op=29 SRCH base="ou=x04,ou=eleve,ou=de,ou=dgae,ou=dg,ou=organisation,dc=id,dc=polytechnique,dc=edu" scope=0 filter="(objectClass=*)" attrs="1.1"
[23/Apr/2009:19:24:23 +0200] conn=7288 op=29 RESULT err=0 tag=101 nentries=1 etime=0.041000
[23/Apr/2009:19:24:23 +0200] conn=7288 op=30 SRCH base="uid=luciana.batista,ou=etudiants,ou=utilisateurs,dc=id,dc=polytechnique,dc=edu" scope=0 filter="(&(sn=Batista)(givenName=Luciana)(X-Civilite=Mlle))" attrs="1.1"
[23/Apr/2009:19:24:23 +0200] conn=7288 op=30 RESULT err=0 tag=101 nentries=1 etime=0.041000
[23/Apr/2009:19:24:23 +0200] conn=7288 op=31 SRCH base="ou=x05,ou=eleve,ou=de,ou=dgae,ou=dg,ou=organisation,dc=id,dc=polytechnique,dc=edu" scope=0 filter="(objectClass=*)" attrs="1.1"
[23/Apr/2009:19:24:23 +0200] conn=7288 op=31 RESULT err=0 tag=101 nentries=1 etime=0.041000
[23/Apr/2009:19:24:23 +0200] conn=7288 op=32 SRCH base="uid=tiago.gribl-lucas,ou=etudiants,ou=utilisateurs,dc=id,dc=polytechnique,dc=edu" scope=0 filter="(&(sn=Gribl Lucas)(givenName=Tiago)(X-Civilite=M.))" attrs="1.1"
[23/Apr/2009:19:24:23 +0200] conn=7288 op=32 RESULT err=0 tag=101 nentries=1 etime=0.041000
[23/Apr/2009:19:24:23 +0200] conn=7288 op=33 SRCH base="ou=x04,ou=eleve,ou=de,ou=dgae,ou=dg,ou=organisation,dc=id,dc=polytechnique,dc=edu" scope=0 filter="(objectClass=*)" attrs="1.1"
[23/Apr/2009:19:24:23 +0200] conn=7288 op=33 RESULT err=0 tag=101 nentries=1 etime=0.041000
...
[23/Apr/2009:19:24:35 +0200] conn=7288 op=332 SRCH base="uid=timothee.vincent,ou=etudiants,ou=utilisateurs,dc=id,dc=polytechnique,dc=edu" scope=0 filter="(&(sn=Vincent)(givenName=Timoth\c3\a9e)(X-Civilite=M.))" attrs="1.1"
[23/Apr/2009:19:24:35 +0200] conn=7288 op=332 RESULT err=0 tag=101 nentries=1 etime=0.041000
[23/Apr/2009:19:24:35 +0200] conn=7288 op=333 SRCH base="ou=x06,ou=eleve,ou=de,ou=dgae,ou=dg,ou=organisation,dc=id,dc=polytechnique,dc=edu" scope=0 filter="(objectClass=*)" attrs="1.1"
[23/Apr/2009:19:24:35 +0200] conn=7288 op=333 RESULT err=0 tag=101 nentries=1 etime=0.041000
...


Expected Results:  
the time per search should not be increased. Here is the log file of the same server with the same data but with nsslapd-ldapilisten: off.

The etime is always lower that 1msec : 
with nsslapd-ldapilisten:off etime never goes over 1 millisecond

[23/Apr/2009:19:27:46 +0200] conn=1 fd=128 slot=128 connection from 129.104.69.6 to 129.104.69.6
[23/Apr/2009:19:27:46 +0200] conn=1 op=0 BIND dn="" method=sasl version=3 mech=GSSAPI
[23/Apr/2009:19:27:46 +0200] conn=1 op=0 RESULT err=14 tag=97 nentries=0 etime=0.004000, SASL bind in progress
[23/Apr/2009:19:27:46 +0200] conn=1 op=1 BIND dn="" method=sasl version=3 mech=GSSAPI
[23/Apr/2009:19:27:46 +0200] conn=1 op=1 RESULT err=14 tag=97 nentries=0 etime=0.000000, SASL bind in progress
[23/Apr/2009:19:27:46 +0200] conn=1 op=2 BIND dn="" method=sasl version=3 mech=GSSAPI
[23/Apr/2009:19:27:46 +0200] conn=1 op=2 RESULT err=0 tag=97 nentries=0 etime=0.002000 dn="uid=andrey.ivanov,ou=personnel,ou=utilisateurs,dc=id,dc=polytechnique,dc=edu"
[23/Apr/2009:19:27:46 +0200] conn=1 op=3 SRCH base="ou=utilisateurs,dc=id,dc=polytechnique,dc=edu" scope=2 filter="(&(objectClass=inetOrgPerson)(X-majaxIndex=*))" attrs="* aci"
[23/Apr/2009:19:27:50 +0200] conn=1 op=3 RESULT err=0 tag=101 nentries=5423 etime=4.876000 notes=U
[23/Apr/2009:19:27:51 +0200] conn=1 op=4 SRCH base="uid=andrey.ivanov,ou=Personnel,ou=Utilisateurs,dc=id,dc=polytechnique,dc=edu" scope=0 filter="(&(sn=Ivanov)(givenName=Andrey)(X-Civilite=M.))" attrs="1.1"
[23/Apr/2009:19:27:51 +0200] conn=1 op=4 RESULT err=0 tag=101 nentries=1 etime=0.000000
[23/Apr/2009:19:27:51 +0200] conn=1 op=5 SRCH base="ou=dsi,ou=dg,ou=organisation,dc=id,dc=polytechnique,dc=edu" scope=0 filter="(objectClass=*)" attrs="1.1"
[23/Apr/2009:19:27:51 +0200] conn=1 op=5 RESULT err=0 tag=101 nentries=1 etime=0.000000
[23/Apr/2009:19:27:51 +0200] conn=1 op=6 SRCH base="uid=boyang.chen,ou=etudiants,ou=utilisateurs,dc=id,dc=polytechnique,dc=edu" scope=0 filter="(&(sn=Chen)(givenName=Boyang)(X-Civilite=M.))" attrs="1.1"
[23/Apr/2009:19:27:51 +0200] conn=1 op=6 RESULT err=0 tag=101 nentries=1 etime=0.000000
[23/Apr/2009:19:27:51 +0200] conn=1 op=7 SRCH base="ou=x06,ou=eleve,ou=de,ou=dgae,ou=dg,ou=organisation,dc=id,dc=polytechnique,dc=edu" scope=0 filter="(objectClass=*)" attrs="1.1"
[23/Apr/2009:19:27:51 +0200] conn=1 op=7 RESULT err=0 tag=101 nentries=1 etime=0.000000
[23/Apr/2009:19:27:51 +0200] conn=1 op=8 SRCH base="uid=thibaut.bondoux,ou=etudiants,ou=utilisateurs,dc=id,dc=polytechnique,dc=edu" scope=0 filter="(&(sn=Bondoux)(givenName=Thibaut)(X-Civilite=M.))" attrs="1.1"
[23/Apr/2009:19:27:51 +0200] conn=1 op=8 RESULT err=0 tag=101 nentries=1 etime=0.000000
[23/Apr/2009:19:27:51 +0200] conn=1 op=9 SRCH base="ou=x05,ou=eleve,ou=de,ou=dgae,ou=dg,ou=organisation,dc=id,dc=polytechnique,dc=edu" scope=0 filter="(objectClass=*)" attrs="1.1"
[23/Apr/2009:19:27:51 +0200] conn=1 op=9 RESULT err=0 tag=101 nentries=1 etime=0.000000
[23/Apr/2009:19:27:51 +0200] conn=1 op=10 SRCH base="uid=stephane.thomas,ou=etudiants,ou=utilisateurs,dc=id,dc=polytechnique,dc=edu" scope=0 filter="(&(sn=Thomas)(givenName=St\c3\a9phane)(X-Civilite=M.))" attrs="1.1"
[23/Apr/2009:19:27:51 +0200] conn=1 op=10 RESULT err=0 tag=101 nentries=1 etime=0.001000
[23/Apr/2009:19:27:51 +0200] conn=1 op=11 SRCH base="ou=x05,ou=eleve,ou=de,ou=dgae,ou=dg,ou=organisation,dc=id,dc=polytechnique,dc=edu" scope=0 filter="(objectClass=*)" attrs="1.1"
[23/Apr/2009:19:27:51 +0200] conn=1 op=11 RESULT err=0 tag=101 nentries=1 etime=0.000000
[23/Apr/2009:19:27:51 +0200] conn=1 op=12 SRCH base="uid=raul.celistrino-teixeira,ou=etudiants,ou=utilisateurs,dc=id,dc=polytechnique,dc=edu" scope=0 filter="(&(sn=Celistrino Teixeira)(givenName=Raul)(X-Civilite=M.))" attrs="1.1"
[23/Apr/2009:19:27:51 +0200] conn=1 op=12 RESULT err=0 tag=101 nentries=1 etime=0.000000
[23/Apr/2009:19:27:51 +0200] conn=1 op=13 SRCH base="ou=x06,ou=eleve,ou=de,ou=dgae,ou=dg,ou=organisation,dc=id,dc=polytechnique,dc=edu" scope=0 filter="(objectClass=*)" attrs="1.1"
[23/Apr/2009:19:27:51 +0200] conn=1 op=13 RESULT err=0 tag=101 nentries=1 etime=0.000000
[23/Apr/2009:19:27:51 +0200] conn=1 op=14 SRCH base="uid=nicolas.naville,ou=etudiants,ou=utilisateurs,dc=id,dc=polytechnique,dc=edu" scope=0 filter="(&(sn=Naville)(givenName=Nicolas)(X-Civilite=M.))" attrs="1.1"
[23/Apr/2009:19:27:51 +0200] conn=1 op=14 RESULT err=0 tag=101 nentries=1 etime=0.000000
[23/Apr/2009:19:27:51 +0200] conn=1 op=15 SRCH base="ou=x05,ou=eleve,ou=de,ou=dgae,ou=dg,ou=organisation,dc=id,dc=polytechnique,dc=edu" scope=0 filter="(objectClass=*)" attrs="1.1"
[23/Apr/2009:19:27:51 +0200] conn=1 op=15 RESULT err=0 tag=101 nentries=1 etime=0.000000
[23/Apr/2009:19:27:51 +0200] conn=1 op=16 SRCH base="uid=adel.habre,ou=etudiants,ou=utilisateurs,dc=id,dc=polytechnique,dc=edu" scope=0 filter="(&(sn=Habre)(givenName=Adel)(X-Civilite=M.))" attrs="1.1"
[23/Apr/2009:19:27:51 +0200] conn=1 op=16 RESULT err=0 tag=101 nentries=1 etime=0.000000
[23/Apr/2009:19:27:51 +0200] conn=1 op=17 SRCH base="ou=x04,ou=eleve,ou=de,ou=dgae,ou=dg,ou=organisation,dc=id,dc=polytechnique,dc=edu" scope=0 filter="(objectClass=*)" attrs="1.1"
[23/Apr/2009:19:27:51 +0200] conn=1 op=17 RESULT err=0 tag=101 nentries=1 etime=0.001000
[23/Apr/2009:19:27:51 +0200] conn=1 op=18 SRCH base="uid=ali.azadi,ou=etudiants,ou=utilisateurs,dc=id,dc=polytechnique,dc=edu" scope=0 filter="(&(sn=Azadi)(givenName=Ali)(X-Civilite=M.))" attrs="1.1"
[23/Apr/2009:19:27:51 +0200] conn=1 op=18 RESULT err=0 tag=101 nentries=1 etime=0.001000
[23/Apr/2009:19:27:51 +0200] conn=1 op=19 SRCH base="ou=x05,ou=eleve,ou=de,ou=dgae,ou=dg,ou=organisation,dc=id,dc=polytechnique,dc=edu" scope=0 filter="(objectClass=*)" attrs="1.1"
[23/Apr/2009:19:27:51 +0200] conn=1 op=19 RESULT err=0 tag=101 nentries=1 etime=0.000000
[23/Apr/2009:19:27:51 +0200] conn=1 op=20 SRCH base="uid=helene.condat,ou=etudiants,ou=utilisateurs,dc=id,dc=polytechnique,dc=edu" scope=0 filter="(&(sn=Condat)(givenName=H\c3\a9l\c3\a8ne)(X-Civilite=Mlle))" attrs="1.1"
[23/Apr/2009:19:27:51 +0200] conn=1 op=20 RESULT err=0 tag=101 nentries=1 etime=0.000000
[23/Apr/2009:19:27:51 +0200] conn=1 op=21 SRCH base="ou=x06,ou=eleve,ou=de,ou=dgae,ou=dg,ou=organisation,dc=id,dc=polytechnique,dc=edu" scope=0 filter="(objectClass=*)" attrs="1.1"
[23/Apr/2009:19:27:51 +0200] conn=1 op=21 RESULT err=0 tag=101 nentries=1 etime=0.000000
[23/Apr/2009:19:27:51 +0200] conn=1 op=22 SRCH base="uid=nicolas.roser,ou=etudiants,ou=utilisateurs,dc=id,dc=polytechnique,dc=edu" scope=0 filter="(&(sn=Roser)(givenName=Nicolas)(X-Civilite=M.))" attrs="1.1"
[23/Apr/2009:19:27:51 +0200] conn=1 op=22 RESULT err=0 tag=101 nentries=1 etime=0.000000
[23/Apr/2009:19:27:51 +0200] conn=1 op=23 SRCH base="ou=x04,ou=eleve,ou=de,ou=dgae,ou=dg,ou=organisation,dc=id,dc=polytechnique,dc=edu" scope=0 filter="(objectClass=*)" attrs="1.1"
[23/Apr/2009:19:27:51 +0200] conn=1 op=23 RESULT err=0 tag=101 nentries=1 etime=0.000000
[23/Apr/2009:19:27:51 +0200] conn=1 op=24 SRCH base="uid=ngoc-duong.dang,ou=etudiants,ou=utilisateurs,dc=id,dc=polytechnique,dc=edu" scope=0 filter="(&(sn=Dang)(givenName=Ngoc Duong)(X-Civilite=M.))" attrs="1.1"
[23/Apr/2009:19:27:51 +0200] conn=1 op=24 RESULT err=0 tag=101 nentries=1 etime=0.000000
[23/Apr/2009:19:27:51 +0200] conn=1 op=25 SRCH base="ou=x04,ou=eleve,ou=de,ou=dgae,ou=dg,ou=organisation,dc=id,dc=polytechnique,dc=edu" scope=0 filter="(objectClass=*)" attrs="1.1"
[23/Apr/2009:19:27:51 +0200] conn=1 op=25 RESULT err=0 tag=101 nentries=1 etime=0.000000
[23/Apr/2009:19:27:51 +0200] conn=1 op=26 SRCH base="uid=cyrille.ronsin,ou=etudiants,ou=utilisateurs,dc=id,dc=polytechnique,dc=edu" scope=0 filter="(&(sn=Ronsin)(givenName=Cyrille)(X-Civilite=M.))" attrs="1.1"
[23/Apr/2009:19:27:51 +0200] conn=1 op=26 RESULT err=0 tag=101 nentries=1 etime=0.000000
[23/Apr/2009:19:27:51 +0200] conn=1 op=27 SRCH base="ou=x04,ou=eleve,ou=de,ou=dgae,ou=dg,ou=organisation,dc=id,dc=polytechnique,dc=edu" scope=0 filter="(objectClass=*)" attrs="1.1"
[23/Apr/2009:19:27:51 +0200] conn=1 op=27 RESULT err=0 tag=101 nentries=1 etime=0.000000
[23/Apr/2009:19:27:51 +0200] conn=1 op=28 SRCH base="uid=pablo.de-manuel-triantafilo,ou=etudiants,ou=utilisateurs,dc=id,dc=polytechnique,dc=edu" scope=0 filter="(&(sn=De Manuel Triantafilo)(givenName=Pablo)(X-Civilite=M.))" attrs="1.1"
[23/Apr/2009:19:27:51 +0200] conn=1 op=28 RESULT err=0 tag=101 nentries=1 etime=0.000000
[23/Apr/2009:19:27:51 +0200] conn=1 op=29 SRCH base="ou=x04,ou=eleve,ou=de,ou=dgae,ou=dg,ou=organisation,dc=id,dc=polytechnique,dc=edu" scope=0 filter="(objectClass=*)" attrs="1.1"
[23/Apr/2009:19:27:51 +0200] conn=1 op=29 RESULT err=0 tag=101 nentries=1 etime=0.000000
[23/Apr/2009:19:27:51 +0200] conn=1 op=30 SRCH base="uid=luciana.batista,ou=etudiants,ou=utilisateurs,dc=id,dc=polytechnique,dc=edu" scope=0 filter="(&(sn=Batista)(givenName=Luciana)(X-Civilite=Mlle))" attrs="1.1"
[23/Apr/2009:19:27:51 +0200] conn=1 op=30 RESULT err=0 tag=101 nentries=1 etime=0.000000
[23/Apr/2009:19:27:51 +0200] conn=1 op=31 SRCH base="ou=x05,ou=eleve,ou=de,ou=dgae,ou=dg,ou=organisation,dc=id,dc=polytechnique,dc=edu" scope=0 filter="(objectClass=*)" attrs="1.1"
[23/Apr/2009:19:27:51 +0200] conn=1 op=31 RESULT err=0 tag=101 nentries=1 etime=0.001000
[23/Apr/2009:19:27:51 +0200] conn=1 op=32 SRCH base="uid=tiago.gribl-lucas,ou=etudiants,ou=utilisateurs,dc=id,dc=polytechnique,dc=edu" scope=0 filter="(&(sn=Gribl Lucas)(givenName=Tiago)(X-Civilite=M.))" attrs="1.1"
[23/Apr/2009:19:27:51 +0200] conn=1 op=32 RESULT err=0 tag=101 nentries=1 etime=0.001000
[23/Apr/2009:19:27:51 +0200] conn=1 op=33 SRCH base="ou=x04,ou=eleve,ou=de,ou=dgae,ou=dg,ou=organisation,dc=id,dc=polytechnique,dc=edu" scope=0 filter="(objectClass=*)" attrs="1.1"
[23/Apr/2009:19:27:51 +0200] conn=1 op=33 RESULT err=0 tag=101 nentries=1 etime=0.000000
...
[23/Apr/2009:19:27:51 +0200] conn=1 op=332 SRCH base="uid=yannick.vezine,ou=etudiants,ou=utilisateurs,dc=id,dc=polytechnique,dc=edu" scope=0 filter="(&(sn=V\c3\a9zine)(givenName=Yannick)(X-Civilite=M.))" attrs="1.1"
[23/Apr/2009:19:27:51 +0200] conn=1 op=332 RESULT err=0 tag=101 nentries=1 etime=0.000000
[23/Apr/2009:19:27:51 +0200] conn=1 op=333 SRCH base="ou=x06,ou=eleve,ou=de,ou=dgae,ou=dg,ou=organisation,dc=id,dc=polytechnique,dc=edu" scope=0 filter="(objectClass=*)" attrs="1.1"
[23/Apr/2009:19:27:51 +0200] conn=1 op=333 RESULT err=0 tag=101 nentries=1 etime=0.000000
...

Activating or desactivating nsslapd-ldapilisten (on/off) is the only difference. It's tha same server, binary, directiry data - no other changes are made. I have not made the same performance tests through unix socket, only by TCP/IP.

Do you have any idea why it happens? I know that unix socket and autobind are disabled by defalut and it is a sort of a "technology preview" but i think it would be nice to investigate this problem a bit further.
Comment 1 Andrey Ivanov 2009-04-24 20:04:07 UTC 
The system version is CentOS 5.3 x86-64
Comment 2 Nathan Kinder 2009-12-04 18:52:13 UTC 
I am unable to reproduce this issue using the current code.  Here are the steps I performed:

- Turn on microsecond logging by setting nsslapd-accesslog-level to 131328.
- Add 100 inetorgperson entries (user1 through user 100).
- Run the following ldclt command:

  ldclt -V -D "cn=directory manager" -w Secret12 -h localhost.localdomain -n 1 -T 100 -e esearch -e random -r 1 -R 100 -b "dc=example,dc=com" -f "uid=userXX"

- Enable LDAPI (nsslapd-ldapilisten: on) and restart DS
- Run the same ldclt command again.

In both cases (LDAPI on or off), the largest reported e-time I see is 0.001000.  I even tried upping the number of operations to 1000 and the results were the same.

Can you try this with the current code to see if you still have this issue?
Comment 3 Andrey Ivanov 2009-12-04 21:24:12 UTC 
I don't know whether it is important but in my case it was a kerberos GSSAPI SASL connection. Anyway i'll try the latest code (next week if i have enough time) and tell you if the problem is corrected (there were a lot of changes in sasl code during the last 8 months :)))
Comment 4 Andrey Ivanov 2009-12-05 23:15:55 UTC 
I've tried to reproduce the bug with the old code (april 2009) following your instructions and i didn't succeed. Everything was perfectly normal. I've found out that in order to see the performance slowdown you need to make at least one search with ldapi. So here's how i've proceeded (still with the old code):

- Enable LDAPI (nsslapd-ldapilisten: on) and restart DS

ldclt -D "cn=directory manager" -w Secret12 -h localhost.localdomain -n 1
-T 1000000 -e esearch -e random -r 1 -R 100 -b "dc=example,dc=com" -f "uid=userXX"
...
ldclt[10002]: Average rate: 51706.00/thr  (5170.60/sec), total:  51706
ldclt[10002]: Average rate: 51316.00/thr  (5131.60/sec), total:  51316
ldclt[10002]: Average rate: 51334.00/thr  (5133.40/sec), total:  51334
ldclt[10002]: T000: thread is dead.
ldclt[10002]: Average rate: 25166.00/thr  (2516.60/sec), total:  25166
ldclt[10002]: Average rate:    0.00/thr  (   0.00/sec), total:      0
ldclt[10002]: All threads are dead - exit.
ldclt[10002]: Global average rate: 1000000.00/thr  (4761.90/sec), total: 1000000
ldclt[10002]: Global number times "no activity" reports: never
ldclt[10002]: Global number of dead threads: 1
ldclt[10002]: Global no error occurs during this session.


So far so good (etime is always < 0.001000). Now make AT LEAST ONE successful ldapi search (with autobind mapping activated and bound to directory manager):

ldapsearch -Y EXTERNAL  -H ldapi://%2fLocal%2fdirsrv%2fvar%2frun%2fslapd-dmz.socket -b 'dc=example,dc=com' uid=user01

And now, restart the same ldclt load :

ldclt -V -D "cn=directory manager" -w Secret12 -h localhost.localdomain -n 1
-T 5000 -e esearch -e random -r 1 -R 100 -b "dc=example,dc=com" -f "uid=userXX"

For me, the problem starts at the operation number 144 :

[05/Dec/2009:23:47:41 +0100] conn=10 op=141 RESULT err=0 tag=101 nentries=1 etime=0.000000
[05/Dec/2009:23:47:41 +0100] conn=10 op=142 SRCH base="dc=id,dc=polytechnique,dc=edu" scope=2 filter="(uid=pj)" attrs=ALL
[05/Dec/2009:23:47:41 +0100] conn=10 op=142 RESULT err=0 tag=101 nentries=1 etime=0.000000
[05/Dec/2009:23:47:42 +0100] conn=10 op=143 SRCH base="dc=id,dc=polytechnique,dc=edu" scope=2 filter="(uid=pj)" attrs=ALL
[05/Dec/2009:23:47:42 +0100] conn=10 op=143 RESULT err=0 tag=101 nentries=1 etime=0.000000
[05/Dec/2009:23:47:42 +0100] conn=10 op=144 SRCH base="dc=id,dc=polytechnique,dc=edu" scope=2 filter="(uid=pj)" attrs=ALL
[05/Dec/2009:23:47:42 +0100] conn=10 op=144 RESULT err=0 tag=101 nentries=1 etime=0.041000
[05/Dec/2009:23:47:42 +0100] conn=10 op=145 SRCH base="dc=id,dc=polytechnique,dc=edu" scope=2 filter="(uid=pj)" attrs=ALL
[05/Dec/2009:23:47:42 +0100] conn=10 op=145 RESULT err=0 tag=101 nentries=1 etime=0.031000
[05/Dec/2009:23:47:42 +0100] conn=10 op=146 SRCH base="dc=id,dc=polytechnique,dc=edu" scope=2 filter="(uid=pj)" attrs=ALL
[05/Dec/2009:23:47:42 +0100] conn=10 op=146 RESULT err=0 tag=101 nentries=1 etime=0.040000


And the ldclt performance results speak for themselves (the performance goes down by the factor of ~200) :
ldclt[10036]: Average rate:  249.00/thr  (  24.90/sec), total:    249
ldclt[10036]: Average rate:  250.00/thr  (  25.00/sec), total:    250
ldclt[10036]: Average rate:  248.00/thr  (  24.80/sec), total:    248
ldclt[10036]: T000: thread is dead.
ldclt[10036]: Average rate:   23.00/thr  (   2.30/sec), total:     23
ldclt[10036]: Average rate:    0.00/thr  (   0.00/sec), total:      0
ldclt[10036]: All threads are dead - exit.
ldclt[10036]: Global average rate: 5000.00/thr  ( 22.73/sec), total:   5000
ldclt[10036]: Global number times "no activity" reports: never
ldclt[10036]: Global number of dead threads: 1
ldclt[10036]: Global no error occurs during this session.



I think you can reproduce the same behavior with the latest code, but as i said i'll try to test the latest code next week anyway.
Comment 5 Andrey Ivanov 2009-12-06 16:01:27 UTC 
I have downloaded and tested the latest rc1 (CentOS 5.4, x86_64) :
[root@ldap-model tmp]# rpm -qa |grep 389
389-admin-1.1.9-1.el5
389-ds-base-1.2.5-0.2.rc1.el5
389-adminutil-1.1.8-3.el5

setup-ds-admin.pl with "typical" settings and the suffix "dc=example,dc=com". I wanted to generate a sample database with dbgen.pl but the server crashes when i try to import it by ldif2db (i've sent a detailed description of this crash to 389-users mailing list). So finally i just installed the 389 with the default config and DIT (groups like cn=Accounting Managers etc).

1. Activate "nsslapd-ldapilisten: on" and /etc/init.d/dirsrv restart
2. Start ldclt

[root@ldap-model tmp]# ldclt -D "cn=Directory Manager" -w secret12 -h localhost.localdomain -n 1 -T 500000 -e esearch -e random -r 1 -R 100 -b "dc=example,dc=com" -f "cn=PD Managers"

ldclt version 4.23
ldclt[5831]: Starting at Sun Dec  6 16:51:45 2009

ldclt[5831]: Average rate: 62207.00/thr  (6220.70/sec), total:  62207
ldclt[5831]: Average rate: 67382.00/thr  (6738.20/sec), total:  67382
ldclt[5831]: Average rate: 66988.00/thr  (6698.80/sec), total:  66988
ldclt[5831]: Average rate: 67514.00/thr  (6751.40/sec), total:  67514
ldclt[5831]: Average rate: 67304.00/thr  (6730.40/sec), total:  67304
ldclt[5831]: Average rate: 67031.00/thr  (6703.10/sec), total:  67031
ldclt[5831]: Average rate: 67854.00/thr  (6785.40/sec), total:  67854
ldclt[5831]: T000: thread is dead.
ldclt[5831]: Average rate: 33720.00/thr  (3372.00/sec), total:  33720
ldclt[5831]: Average rate:    0.00/thr  (   0.00/sec), total:      0
ldclt[5831]: All threads are dead - exit.
ldclt[5831]: Global average rate: 500000.00/thr  (5555.56/sec), total: 500000
ldclt[5831]: Global number times "no activity" reports: never
ldclt[5831]: Global number of dead threads: 1
ldclt[5831]: Global no error occurs during this session.
ldclt[5831]: Ending at Sun Dec  6 16:53:15 2009
ldclt[5831]: Exit status 0 - No problem during execution.



3. A single search over ldapi :
 ldapsearch -Y EXTERNAL  -H ldapi://%2fvar%2frun%2fslapd-dmz.socket -b 'dc=example,dc=com' cn=PD*

4. Start ldclt and compare the performance :
[root@ldap-model tmp]# ldclt -D "cn=Directory Manager" -w secret12 -h localhost.localdomain -n 1 -T 5000 -e esearch -e random -r 1 -R 100 -b "dc=example,dc=com" -f "cn=PD Managers"  
ldclt version 4.23
ldclt[5852]: Starting at Sun Dec  6 16:55:59 2009

ldclt[5852]: Average rate:  249.00/thr  (  24.90/sec), total:    249
ldclt[5852]: Average rate:  250.00/thr  (  25.00/sec), total:    250
ldclt[5852]: Average rate:  247.00/thr  (  24.70/sec), total:    247
ldclt[5852]: Average rate:  250.00/thr  (  25.00/sec), total:    250
...
ldclt[5852]: Average rate:  249.00/thr  (  24.90/sec), total:    249
ldclt[5852]: Average rate:  249.00/thr  (  24.90/sec), total:    249
ldclt[5852]: Average rate:  249.00/thr  (  24.90/sec), total:    249
ldclt[5852]: Average rate:  249.00/thr  (  24.90/sec), total:    249
ldclt[5852]: T000: thread is dead.
ldclt[5852]: Average rate:   21.00/thr  (   2.10/sec), total:     21
ldclt[5852]: Average rate:    0.00/thr  (   0.00/sec), total:      0
ldclt[5852]: All threads are dead - exit.
ldclt[5852]: Global average rate: 5000.00/thr  ( 22.73/sec), total:   5000
ldclt[5852]: Global number times "no activity" reports: never
ldclt[5852]: Global number of dead threads: 1
ldclt[5852]: Global no error occurs during this session.
ldclt[5852]: Ending at Sun Dec  6 16:59:39 2009
ldclt[5852]: Exit status 0 - No problem during execution.
Comment 6 Nathan Kinder 2009-12-09 22:35:05 UTC 
Thanks for the detail Andrey.  I am able to reproduce this issue now.

It turns out that the cause for this performance degradation is pretty simple.  If a slot from the connection table had previously been used for an LDAPI connection, it would cause serious performance degradation (20 times worse on my system) to a TCP connection that reused the same slot.  The problem was that we were not clearing the flag that indicates that a connection is a UNIX local socket in the connection cleanup function.  Clearing this flag makes the reused slots perform as expected.
Comment 7 Nathan Kinder 2009-12-09 22:36:01 UTC 
Created attachment 377332 [details]
Patch
Comment 8 Nathan Kinder 2009-12-09 23:22:12 UTC 
Patch from comment #7 pushed to master.  Thanks to Rich for his review!

Counting objects: 11, done.
Delta compression using 2 threads.
Compressing objects: 100% (6/6), done.
Writing objects: 100% (6/6), 805 bytes, done.
Total 6 (delta 4), reused 0 (delta 0)
To ssh://git.fedorahosted.org/git/389/ds.git
   c3120fc..99ac483  master -> master
Comment 9 Jenny Severance 2010-05-21 13:09:27 UTC 
verified - RHEL 4

version:
redhat-ds-base-8.2.0-2010052104.el4dsrv

Before LDAPI search:

ldclt[30193]: Average rate: 5000.00/thr  ( 500.00/sec), total:   5000
ldclt[30193]: T000: nbOpers = 0
ldclt[30193]: Average rate:    0.00/thr  (   0.00/sec), total:      0
ldclt[30193]: All threads are dead - exit.
ldclt[30193]: Global average rate: 5000.00/thr  (250.00/sec), total:   5000
ldclt[30193]: Global number times "no activity" reports: never
ldclt[30193]: Global number of dead threads: 1
ldclt[30193]: Global no error occurs during this session.
ldclt[30193]: Ending at Fri May 21 09:02:21 2010
ldclt[30193]: Exit status 0 - No problem during execution.

LDAPI search:
ldapsearch -x -H ldapi://%2fvar%2frun%2fslapd-jgalipea-rhel4.socket -b "dc=example,dc=com"


After LDAPI search:

ldclt[30199]: Average rate: 5000.00/thr  ( 500.00/sec), total:   5000
ldclt[30199]: T000: nbOpers = 0
ldclt[30199]: Average rate:    0.00/thr  (   0.00/sec), total:      0
ldclt[30199]: All threads are dead - exit.
ldclt[30199]: Global average rate: 5000.00/thr  (250.00/sec), total:   5000
ldclt[30199]: Global number times "no activity" reports: never
ldclt[30199]: Global number of dead threads: 1
ldclt[30199]: Global no error occurs during this session.
ldclt[30199]: Ending at Fri May 21 09:05:22 2010
ldclt[30199]: Exit status 0 - No problem during execution.