Full_Name: Pavel Lisy Version: 2.4.19 or 2.4.20 OS: linux - CentOS4/5 URL: ftp://ftp.openldap.org/incoming/ Submission from: (NULL) (85.132.159.239)
I have my rpm built on source from Fedora 12.
ldapsearch have delay on start, slapd is heavy loaded (up to 90% proc) on the same machine over TLS/SSL only (numbers below)
[root@ldap1 ~]# time ldapsearch24 -ZZ -h ldap1.ldapnet.tmapy.cz -x -s sub -D "cn=Manager,dc=tmapy,dc=cz" -b 'dc=tmapy,dc=cz' -w heslo -d 1 > search-zz.log 2>&1
real 0m2.610s user 0m0.029s sys 0m0.014s
[root@ldap1 ~]# time ldapsearch24 -Z -h ldap1.ldapnet.tmapy.cz -x -s sub -D "cn=Manager,dc=tmapy,dc=cz" -b 'dc=tmapy,dc=cz' -w heslo -d 1 > search-z.log 2>&1
real 0m2.700s user 0m0.026s sys 0m0.013s
[root@ldap1 ~]# time ldapsearch24 -h ldap1.ldapnet.tmapy.cz -x -s sub -D "cn=Manager,dc=tmapy,dc=cz" -b 'dc=tmapy,dc=cz' -w heslo -d 1 > search.log 2>&1
real 0m0.021s user 0m0.010s sys 0m0.008s
[root@ldap1 ~]# time ldapsearch24 -h ldap2.ldapnet.tmapy.cz -x -s sub -D "cn=Manager,dc=tmapy,dc=cz" -b 'dc=tmapy,dc=cz' -w heslo -d 1 > search-l2.log 2>&1
real 0m0.027s user 0m0.009s sys 0m0.014s
[root@ldap1 ~]# time ldapsearch24 -Z -h ldap2.ldapnet.tmapy.cz -x -s sub -D "cn=Manager,dc=tmapy,dc=cz" -b 'dc=tmapy,dc=cz' -w heslo -d 1 > search-l2-z.log 2>&1
real 0m0.070s user 0m0.028s sys 0m0.020s
[root@ldap1 ~]# time ldapsearch24 -ZZ -h ldap2.ldapnet.tmapy.cz -x -s sub -D "cn=Manager,dc=tmapy,dc=cz" -b 'dc=tmapy,dc=cz' -w heslo -d 1 > search-l2-zz.log 2>&1
real 0m0.048s user 0m0.026s sys 0m0.017s
This means: delay is there when I query from the same machine over TLS/SSL, not across machines. I suppose it is bug but I cannot find where it is.
When I've changed in slapd.conf "loglevel 0" to "loglevel 1" delay is gone
[root@ldap1 ~]# time ldapsearch24 -ZZ -h ldap1.ldapnet.tmapy.cz -x -s sub -D "cn=Manager,dc=tmapy,dc=cz" -b 'dc=tmapy,dc=cz' -w heslo -d 1 > search-zz.log 2>&1
real 0m0.315s user 0m0.030s sys 0m0.025s
When I start ldapsearch24 through strace delay was in part with stars: ------------ cut --------------- munmap(0x2b2edf8b1000, 4096) = 0 brk(0x15747000) = 0x15747000 write(2, "TLS trace: SSL_connect:before/co"..., 53TLS trace: SSL_connect:before/connect initialization ) = 53 open("/dev/urandom", O_RDONLY|O_NOCTTY|O_NONBLOCK) = 4 fstat(4, {st_mode=S_IFCHR|0444, st_rdev=makedev(1, 9), ...}) = 0 poll([{fd=4, events=POLLIN}], 1, 10) = 1 ([{fd=4, revents=POLLIN}]) read(4, "D~j?,\274k\310mx\336\t\17k\207Q\322\0369SDB\260\241bd6[R}6\201"..., 48) = 48 close(4) = 0 getuid() = 0 write(3, "\200t\1\3\1\0K\0\0\0 \0\0009\0\0008\0\0005\0\0\26\0\0\23\0\0\n\7\0\300"..., 118 *********************************************** DELAY 2s HERE *********************************************** ) = 118 write(2, "TLS trace: SSL_connect:SSLv2/v3 "..., 53TLS trace: SSL_connect:SSLv2/v3 write client hello A ) = 53 read(3, "\26\3\1\0J\2\0", 7) = 7 read(3, "\0F\3\1K \10\5\232\0\3\2\354\235\351\233\276\31\242\302\217\214\35\32\370cGH\342\277\7;"..., 72) = 7 write(2, "TLS trace: SSL_connect:SSLv3 rea"..., 49TLS trace: SSL_connect:SSLv3 read server hello A ) = 49 read(3, "\26\3\1\6\303", 5) = 5 read(3, "\v\0\6\277\0\6\274\0\2\2500\202\2\2440\202\2\r\2\3\20\0\0010\r\6\t*\206H\206\367"..., 1731) = 1731 write(2, "TLS certificate verification: de"..., 191TLS certificate verification: depth: 1, err: 0, subject: / write(2, " issuer: /O=T-MAPY spol. s r.o./"..., 143 issuer: /O=T-MAPY spol. s r.o./OU=ldapnet/emailAddress=pa ) = 143 write(2, "TLS certificate verification: de"..., 146TLS certificate verification: depth: 0, err: 0, subject: / write(2, " issuer: /O=T-MAPY spol. s r.o./"..., 143 issuer: /O=T-MAPY spol. s r.o./OU=ldapnet/emailAddress=pa ) = 143 write(2, "TLS trace: SSL_connect:SSLv3 rea"..., 55TLS trace: SSL_connect:SSLv3 read server certificate A ) = 55 read(3, "\26\3\1\0\4", 5) = 5 read(3, "\16\0\0\0", 4) = 4 write(2, "TLS trace: SSL_connect:SSLv3 rea"..., 48TLS trace: SSL_connect:SSLv3 read server done A ) = 48 write(2, "TLS trace: SSL_connect:SSLv3 wri"..., 57TLS trace: SSL_connect:SSLv3 write client key exchange A ) = 57 write(2, "TLS trace: SSL_connect:SSLv3 wri"..., 56TLS trace: SSL_connect:SSLv3 write change cipher spec A ) = 56 write(2, "TLS trace: SSL_connect:SSLv3 wri"..., 46TLS trace: SSL_connect:SSLv3 write finished A ) = 46 write(3, "\26\3\1\0\206\20\0\0\202\0\200\202\365\233\356\r\26\27\330\251\17\330\331\3362\23\231\211`\\262\32 write(2, "TLS trace: SSL_connect:SSLv3 flu"..., 40TLS trace: SSL_connect:SSLv3 flush data ) = 40 read(3, "\24\3\1\0\1", 5) = 5 read(3, "\1", 1) = 1 read(3, "\26\3\1\0000", 5) = 5 read(3, "\353;\20\337y\307&\331\207@#\265\314\267\240\244\177P\223\216\221\216!"G \27\265R\3078l"..., 48) = write(2, "TLS trace: SSL_connect:SSLv3 rea"..., 45TLS trace: SSL_connect:SSLv3 read finished A ) = 45 write(2, "ldap_sasl_bind\n", 15ldap_sasl_bind ) = 15 write(2, "ldap_send_initial_request\n", 26ldap_send_initial_request ) = 26 write(2, "ldap_send_server_request\n", 25ldap_send_server_request ) = 25 write(2, "ber_scanf fmt ({it) ber:\n", 25ber_scanf fmt ({it) ber: ) = 25 write(2, "ber_scanf fmt ({i) ber:\n", 24ber_scanf fmt ({i) ber: ) = 24 write(2, "ber_flush2: 44 bytes to sd 3\n", 29ber_flush2: 44 bytes to sd 3 ) = 29 write(3, "\27\3\1\0 \217\244v\31\275A\232=\300\357\330\312*\316)\311\23\242\260\350n\353\373\221\204B\v"..., write(2, "ldap_result ld 0x156816c0 msgid "..., 34ldap_result ld 0x156816c0 msgid 2 ) = 34 write(2, "wait4msg ld 0x156816c0 msgid 2 ("..., 50wait4msg ld 0x156816c0 msgid 2 (infinite timeout) ) = 50 write(2, "wait4msg continue ld 0x156816c0 "..., 46wait4msg continue ld 0x156816c0 msgid 2 all 1 ) = 46 write(2, "** ld 0x156816c0 Connections:\n", 30** ld 0x156816c0 Connections: ) = 30 write(2, "* host: ldap1.ldapnet.tmapy.cz "..., 53* host: ldap1.ldapnet.tmapy.cz port: 389 (default) ) = 53 write(2, " refcnt: 2 status: Connected\n", 31 refcnt: 2 status: Connected ) = 31 write(2, " last used: Wed Dec 9 21:26:51"..., 39 last used: Wed Dec 9 21:26:51 2009 ------------ cut ---------------
How can I debug it more? I will send more details if you want.