Full_Name: Bill MacAllister Version: 2.4.19+ OS: Debian 5 URL: ftp://ftp.openldap.org/incoming/ Submission from: (NULL) (171.64.19.165) On a system where slapd is the top CPU process and is consuming 4% of the CPU simple queries are taking ten of seconds to complete. Here is an example query: % time ldapsearch -x -h ldap1.stanford.edu -b dc=stanford,dc=edu uid=whm # extended LDIF # # LDAPv3 # base <dc=stanford,dc=edu> with scope subtree # filter: uid=whm # requesting: ALL # ...data... # search result search: 2 result: 0 Success # numResponses: 2 # numEntries: 1 0.001u 0.000s 0:18.13 0.0% 0+0k 0+0io 0pf+0w Here is a backtrace: ldap1:/var/log# gdb slapd 24029 GNU gdb 6.8-debian Copyright (C) 2008 Free Software Foundation, Inc. License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html> This is free software: you are free to change and redistribute it. There is NO WARRANTY, to the extent permitted by law. Type "show copying" and "show warranty" for details. This GDB was configured as "x86_64-linux-gnu"... Attaching to program: /usr/sbin/slapd, process 24029 Reading symbols from /usr/lib/libtcmalloc_minimal.so.0...done. Loaded symbols for /usr/lib/libtcmalloc_minimal.so.0 Reading symbols from /usr/lib/libldap_r-2.4.so.2...Reading symbols from /usr/lib/debug/usr/lib/libldap_r-2.4.so.2.5.2...done. done. Loaded symbols for /usr/lib/libldap_r-2.4.so.2 Reading symbols from /usr/lib/liblber-2.4.so.2...Reading symbols from /usr/lib/debug/usr/lib/liblber-2.4.so.2.5.2...done. done. Loaded symbols for /usr/lib/liblber-2.4.so.2 Reading symbols from /usr/lib/libdb-4.8.so...Reading symbols from /usr/lib/debug/usr/lib/libdb-4.8.so.debug...done. done. Loaded symbols for /usr/lib/libdb-4.8.so Reading symbols from /usr/lib/libodbc.so.1...done. Loaded symbols for /usr/lib/libodbc.so.1 Reading symbols from /usr/lib/libslp.so.1...done. Loaded symbols for /usr/lib/libslp.so.1 Reading symbols from /usr/lib/libsasl2.so.2...done. Loaded symbols for /usr/lib/libsasl2.so.2 Reading symbols from /usr/lib/libssl.so.0.9.8...done. Loaded symbols for /usr/lib/libssl.so.0.9.8 Reading symbols from /usr/lib/libcrypto.so.0.9.8...done. Loaded symbols for /usr/lib/libcrypto.so.0.9.8 Reading symbols from /lib/libcrypt.so.1...done. Loaded symbols for /lib/libcrypt.so.1 Reading symbols from /lib/libresolv.so.2...done. Loaded symbols for /lib/libresolv.so.2 Reading symbols from /usr/lib/libltdl.so.3...done. Loaded symbols for /usr/lib/libltdl.so.3 Reading symbols from /lib/libpthread.so.0...done. [Thread debugging using libthread_db enabled] [New Thread 0x7f89261b86f0 (LWP 24029)] [New Thread 0x44bef950 (LWP 24047)] [New Thread 0x443ee950 (LWP 24046)] [New Thread 0x40a74950 (LWP 24045)] [New Thread 0x43bed950 (LWP 24044)] [New Thread 0x433ec950 (LWP 24043)] [New Thread 0x42beb950 (LWP 24042)] [New Thread 0x423ea950 (LWP 24041)] [New Thread 0x41be9950 (LWP 24040)] [New Thread 0x413e8950 (LWP 24039)] Loaded symbols for /lib/libpthread.so.0 Reading symbols from /lib/libc.so.6...done. Loaded symbols for /lib/libc.so.6 Reading symbols from /usr/lib/libstdc++.so.6...done. Loaded symbols for /usr/lib/libstdc++.so.6 Reading symbols from /lib/libm.so.6...done. Loaded symbols for /lib/libm.so.6 Reading symbols from /lib/libgcc_s.so.1...done. Loaded symbols for /lib/libgcc_s.so.1 Reading symbols from /lib/libnsl.so.1...done. Loaded symbols for /lib/libnsl.so.1 Reading symbols from /lib/libdl.so.2...done. Loaded symbols for /lib/libdl.so.2 Reading symbols from /usr/lib/libz.so.1...done. Loaded symbols for /usr/lib/libz.so.1 Reading symbols from /lib/ld-linux-x86-64.so.2...done. Loaded symbols for /lib64/ld-linux-x86-64.so.2 Reading symbols from /lib/libnss_files.so.2...done. Loaded symbols for /lib/libnss_files.so.2 Reading symbols from /usr/lib/sasl2/libntlm.so.2...done. Loaded symbols for /usr/lib/sasl2/libntlm.so.2 Reading symbols from /usr/lib/sasl2/libcrammd5.so.2...done. Loaded symbols for /usr/lib/sasl2/libcrammd5.so.2 Reading symbols from /usr/lib/sasl2/liblogin.so.2...done. Loaded symbols for /usr/lib/sasl2/liblogin.so.2 Reading symbols from /usr/lib/sasl2/libsasldb.so.2...done. Loaded symbols for /usr/lib/sasl2/libsasldb.so.2 Reading symbols from /usr/lib/libdb-4.6.so...done. Loaded symbols for /usr/lib/libdb-4.6.so Reading symbols from /usr/lib/sasl2/libdigestmd5.so.2...done. Loaded symbols for /usr/lib/sasl2/libdigestmd5.so.2 Reading symbols from /usr/lib/sasl2/libgssapiv2.so.2...done. Loaded symbols for /usr/lib/sasl2/libgssapiv2.so.2 Reading symbols from /usr/lib/libgssapi.so.2...done. Loaded symbols for /usr/lib/libgssapi.so.2 Reading symbols from /usr/lib/libkrb5.so.25...done. Loaded symbols for /usr/lib/libkrb5.so.25 Reading symbols from /usr/lib/libasn1.so.8...done. Loaded symbols for /usr/lib/libasn1.so.8 Reading symbols from /usr/lib/libroken.so.18...done. Loaded symbols for /usr/lib/libroken.so.18 Reading symbols from /lib/libcom_err.so.2...done. Loaded symbols for /lib/libcom_err.so.2 Reading symbols from /usr/lib/libheimntlm.so.0...done. Loaded symbols for /usr/lib/libheimntlm.so.0 Reading symbols from /usr/lib/libhx509.so.3...done. Loaded symbols for /usr/lib/libhx509.so.3 Reading symbols from /usr/lib/libwind.so.0...done. Loaded symbols for /usr/lib/libwind.so.0 Reading symbols from /usr/lib/sasl2/libanonymous.so.2...done. Loaded symbols for /usr/lib/sasl2/libanonymous.so.2 Reading symbols from /usr/lib/sasl2/libplain.so.2...done. Loaded symbols for /usr/lib/sasl2/libplain.so.2 Reading symbols from /usr/lib/ldap/back_hdb-2.4.so.2...Reading symbols from /usr/lib/debug/usr/lib/ldap/back_hdb-2.4.so.2.5.2...done. done. Loaded symbols for /usr/lib/ldap/back_hdb-2.4.so.2 Reading symbols from /usr/lib/ldap/back_monitor-2.4.so.2...Reading symbols from /usr/lib/debug/usr/lib/ldap/back_monitor-2.4.so.2.5.2...done. done. Loaded symbols for /usr/lib/ldap/back_monitor-2.4.so.2 Reading symbols from /usr/lib/ldap/valsort-2.4.so.2...Reading symbols from /usr/lib/debug/usr/lib/ldap/valsort-2.4.so.2.5.2...done. done. Loaded symbols for /usr/lib/ldap/valsort-2.4.so.2 Reading symbols from /usr/lib/ldap/dynlist-2.4.so.2...Reading symbols from /usr/lib/debug/usr/lib/ldap/dynlist-2.4.so.2.5.2...done. done. Loaded symbols for /usr/lib/ldap/dynlist-2.4.so.2 Reading symbols from /lib/libnss_dns.so.2...done. Loaded symbols for /lib/libnss_dns.so.2 0x00007f89240a0715 in pthread_join () from /lib/libpthread.so.0 (gdb) thr apply all bt Thread 10 (Thread 0x413e8950 (LWP 24039)): #0 0x00007f8923e15b78 in epoll_wait () from /lib/libc.so.6 #1 0x0000000000438fdf in slapd_daemon_task (ptr=0x0) at /tmp/buildd/openldap-2.4.19/servers/slapd/daemon.c:2460 #2 0x00007f892409ffc7 in start_thread () from /lib/libpthread.so.0 #3 0x00007f8923e155ad in clone () from /lib/libc.so.6 #4 0x0000000000000000 in ?? () Thread 9 (Thread 0x41be9950 (LWP 24040)): #0 0x00007f89240a6384 in __lll_lock_wait () from /lib/libpthread.so.0 #1 0x00007f89240a1bf0 in _L_lock_102 () from /lib/libpthread.so.0 #2 0x00007f89240a14fe in pthread_mutex_lock () from /lib/libpthread.so.0 #3 0x00007f8925b1c6e5 in ldap_pvt_thread_mutex_lock (mutex=0x2aad8d0) at /tmp/buildd/openldap-2.4.19/libraries/libldap_r/thr_posix.c:296 #4 0x00007f8925b264e9 in ldap_pvt_sasl_mutex_lock (mutex=0x2aad8d0) at cyrus.c:1160 #5 0x00007f8921df100d in ?? () from /usr/lib/sasl2/libgssapiv2.so.2 #6 0x00007f8924f00500 in ?? () from /usr/lib/libsasl2.so.2 #7 0x00007f8924f00aca in sasl_encodev () from /usr/lib/libsasl2.so.2 #8 0x00007f8924f00b72 in sasl_encode () from /usr/lib/libsasl2.so.2 #9 0x00007f8925b24585 in sb_sasl_cyrus_encode (p=0x3c2e2be0, buf=0x39a3740 "0\202\001���002\001\004d\202\001���\004*uid=carimer,cn=accounts,dc=stanford,dc=edu0\202\001\2170>\004\tsuService11\004\006dialin\004\003afs\004\006leland\004\005email\004\003pts\004\004seas\004\bkerberos0\020\004\003uid1\t\004\acarimer0\034\004\020suKerberosStatus1\b\004\006active0\031\004\rsuEmailStatus1\b\004\006active0\201"..., len=458, dst=0x3c2e2c50) at cyrus.c:165 #10 0x00007f8925b298a1 in sb_sasl_generic_write (sbiod=0x37a3f420, buf=0x39a3740, len=458) at sasl.c:716 #11 0x00007f8925905b70 in sb_debug_write (sbiod=0x3c2feb10, buf=0x39a3740, len=458) at /tmp/buildd/openldap-2.4.19/libraries/liblber/sockbuf.c:852 #12 0x00007f8925904f61 in ber_int_sb_write (sb=0x3ca3d300, buf=0x39a3740, len=458) at /tmp/buildd/openldap-2.4.19/libraries/liblber/sockbuf.c:445 #13 0x00007f892590112e in ber_flush2 (sb=0x3ca3d300, ber=0x41a674e0, freeit=0) at /tmp/buildd/openldap-2.4.19/libraries/liblber/io.c:246 #14 0x0000000000451c56 in send_ldap_ber (op=0x3a875800, ber=0x41a674e0) at /tmp/buildd/openldap-2.4.19/servers/slapd/result.c:191 #15 0x0000000000455857 in slap_send_search_entry (op=0x3a875800, rs=0x41be8c90) at /tmp/buildd/openldap-2.4.19/servers/slapd/result.c:1260 #16 0x00007f8920597320 in hdb_search (op=0x3a875800, rs=0x41be8c90) at search.c:961 #17 0x00000000004c70be in overlay_op_walk (op=0x3a875800, rs=0x41be8c90, which=op_search, oi=0x2e0fa00, on=0x0) at /tmp/buildd/openldap-2.4.19/servers/slapd/backover.c:669 #18 0x00000000004c72e5 in over_op_func (op=0x3a875800, rs=0x41be8c90, which=op_search) at /tmp/buildd/openldap-2.4.19/servers/slapd/backover.c:721 #19 0x00000000004c73b3 in over_op_search (op=0x3a875800, rs=0x41be8c90) at /tmp/buildd/openldap-2.4.19/servers/slapd/backover.c:748 #20 0x0000000000440844 in fe_op_search (op=0x3a875800, rs=0x41be8c90) at /tmp/buildd/openldap-2.4.19/servers/slapd/search.c:366 #21 0x00000000004401af in do_search (op=0x3a875800, rs=0x41be8c90) at /tmp/buildd/openldap-2.4.19/servers/slapd/search.c:217 #22 0x000000000043cbd6 in connection_operation (ctx=0x41be8de0, arg_v=0x3a875800) at /tmp/buildd/openldap-2.4.19/servers/slapd/connection.c:1123 #23 0x000000000043d162 in connection_read_thread (ctx=0x41be8de0, argv=0x91) at /tmp/buildd/openldap-2.4.19/servers/slapd/connection.c:1259 #24 0x00007f8925b1b19d in ldap_int_thread_pool_wrapper (xpool=0x2d48000) at /tmp/buildd/openldap-2.4.19/libraries/libldap_r/tpool.c:685 #25 0x00007f892409ffc7 in start_thread () from /lib/libpthread.so.0 #26 0x00007f8923e155ad in clone () from /lib/libc.so.6 #27 0x0000000000000000 in ?? () Thread 8 (Thread 0x423ea950 (LWP 24041)): #0 0x00007f89240a6384 in __lll_lock_wait () from /lib/libpthread.so.0 #1 0x00007f89240a1bf0 in _L_lock_102 () from /lib/libpthread.so.0 #2 0x00007f89240a14fe in pthread_mutex_lock () from /lib/libpthread.so.0 #3 0x00007f8925b1c6e5 in ldap_pvt_thread_mutex_lock (mutex=0x2aad8d0) at /tmp/buildd/openldap-2.4.19/libraries/libldap_r/thr_posix.c:296 #4 0x00007f8925b264e9 in ldap_pvt_sasl_mutex_lock (mutex=0x2aad8d0) at cyrus.c:1160 #5 0x00007f8921df18a4 in ?? () from /usr/lib/sasl2/libgssapiv2.so.2 #6 0x00007f8924f03dbf in sasl_server_step () from /usr/lib/libsasl2.so.2 #7 0x00000000004a85d0 in slap_sasl_bind (op=0x3bb9b800, rs=0x423e9c90) at /tmp/buildd/openldap-2.4.19/servers/slapd/sasl.c:1528 #8 0x0000000000464126 in fe_op_bind (op=0x3bb9b800, rs=0x423e9c90) at /tmp/buildd/openldap-2.4.19/servers/slapd/bind.c:280 #9 0x0000000000463d2b in do_bind (op=0x3bb9b800, rs=0x423e9c90) at /tmp/buildd/openldap-2.4.19/servers/slapd/bind.c:205 #10 0x000000000043cbd6 in connection_operation (ctx=0x423e9de0, arg_v=0x3bb9b800) at /tmp/buildd/openldap-2.4.19/servers/slapd/connection.c:1123 #11 0x000000000043d162 in connection_read_thread (ctx=0x423e9de0, argv=0x94) at /tmp/buildd/openldap-2.4.19/servers/slapd/connection.c:1259 #12 0x00007f8925b1b19d in ldap_int_thread_pool_wrapper (xpool=0x2d48000) at /tmp/buildd/openldap-2.4.19/libraries/libldap_r/tpool.c:685 #13 0x00007f892409ffc7 in start_thread () from /lib/libpthread.so.0 #14 0x00007f8923e155ad in clone () from /lib/libc.so.6 #15 0x0000000000000000 in ?? () Thread 7 (Thread 0x42beb950 (LWP 24042)): #0 0x00007f89240a6384 in __lll_lock_wait () from /lib/libpthread.so.0 #1 0x00007f89240a1bf0 in _L_lock_102 () from /lib/libpthread.so.0 #2 0x00007f89240a14fe in pthread_mutex_lock () from /lib/libpthread.so.0 #3 0x00007f8925b1c6e5 in ldap_pvt_thread_mutex_lock (mutex=0x2aad8d0) at /tmp/buildd/openldap-2.4.19/libraries/libldap_r/thr_posix.c:296 #4 0x00007f8925b264e9 in ldap_pvt_sasl_mutex_lock (mutex=0x2aad8d0) at cyrus.c:1160 #5 0x00007f8921df16f0 in ?? () from /usr/lib/sasl2/libgssapiv2.so.2 #6 0x00007f8924f03dbf in sasl_server_step () from /usr/lib/libsasl2.so.2 #7 0x00007f8924f0510e in sasl_server_start () from /usr/lib/libsasl2.so.2 #8 0x00000000004a8599 in slap_sasl_bind (op=0x340cd800, rs=0x42beac90) at /tmp/buildd/openldap-2.4.19/servers/slapd/sasl.c:1522 #9 0x0000000000464126 in fe_op_bind (op=0x340cd800, rs=0x42beac90) at /tmp/buildd/openldap-2.4.19/servers/slapd/bind.c:280 #10 0x0000000000463d2b in do_bind (op=0x340cd800, rs=0x42beac90) at /tmp/buildd/openldap-2.4.19/servers/slapd/bind.c:205 #11 0x000000000043cbd6 in connection_operation (ctx=0x42beade0, arg_v=0x340cd800) at /tmp/buildd/openldap-2.4.19/servers/slapd/connection.c:1123 #12 0x000000000043d162 in connection_read_thread (ctx=0x42beade0, argv=0x29) at /tmp/buildd/openldap-2.4.19/servers/slapd/connection.c:1259 #13 0x00007f8925b1b19d in ldap_int_thread_pool_wrapper (xpool=0x2d48000) at /tmp/buildd/openldap-2.4.19/libraries/libldap_r/tpool.c:685 #14 0x00007f892409ffc7 in start_thread () from /lib/libpthread.so.0 #15 0x00007f8923e155ad in clone () from /lib/libc.so.6 #16 0x0000000000000000 in ?? () Thread 6 (Thread 0x433ec950 (LWP 24043)): #0 0x00007f89240a6384 in __lll_lock_wait () from /lib/libpthread.so.0 #1 0x00007f89240a1bf0 in _L_lock_102 () from /lib/libpthread.so.0 #2 0x00007f89240a14fe in pthread_mutex_lock () from /lib/libpthread.so.0 #3 0x00007f8925b1c6e5 in ldap_pvt_thread_mutex_lock (mutex=0x2aad8d0) at /tmp/buildd/openldap-2.4.19/libraries/libldap_r/thr_posix.c:296 #4 0x00007f8925b264e9 in ldap_pvt_sasl_mutex_lock (mutex=0x2aad8d0) at cyrus.c:1160 #5 0x00007f8921df100d in ?? () from /usr/lib/sasl2/libgssapiv2.so.2 #6 0x00007f8924f00500 in ?? () from /usr/lib/libsasl2.so.2 #7 0x00007f8924f00aca in sasl_encodev () from /usr/lib/libsasl2.so.2 #8 0x00007f8924f00b72 in sasl_encode () from /usr/lib/libsasl2.so.2 #9 0x00007f8925b24585 in sb_sasl_cyrus_encode (p=0x2e29e000, buf=0xe58cc10 "0\r\002\002\004He\a\n\001", len=15, dst=0x2e29e070) at cyrus.c:165 #10 0x00007f8925b298a1 in sb_sasl_generic_write (sbiod=0x2e3f50f0, buf=0xe58cc10, len=15) at sasl.c:716 #11 0x00007f8925905b70 in sb_debug_write (sbiod=0x2e389b70, buf=0xe58cc10, len=15) at /tmp/buildd/openldap-2.4.19/libraries/liblber/sockbuf.c:852 #12 0x00007f8925904f61 in ber_int_sb_write (sb=0x2e3b88d0, buf=0xe58cc10, len=15) at /tmp/buildd/openldap-2.4.19/libraries/liblber/sockbuf.c:445 #13 0x00007f892590112e in ber_flush2 (sb=0x2e3b88d0, ber=0x4326a480, freeit=0) at /tmp/buildd/openldap-2.4.19/libraries/liblber/io.c:246 #14 0x0000000000451c56 in send_ldap_ber (op=0x33ce9400, ber=0x4326a480) at /tmp/buildd/openldap-2.4.19/servers/slapd/result.c:191 #15 0x00000000004528a1 in send_ldap_response (op=0x33ce9400, rs=0x433ebc90) at /tmp/buildd/openldap-2.4.19/servers/slapd/result.c:548 #16 0x00000000004531ee in slap_send_ldap_result (op=0x33ce9400, rs=0x433ebc90) at /tmp/buildd/openldap-2.4.19/servers/slapd/result.c:706 #17 0x00007f892059765d in hdb_search (op=0x33ce9400, rs=0x433ebc90) at search.c:1028 #18 0x00000000004c70be in overlay_op_walk (op=0x33ce9400, rs=0x433ebc90, which=op_search, oi=0x2e0fa00, on=0x0) at /tmp/buildd/openldap-2.4.19/servers/slapd/backover.c:669 #19 0x00000000004c72e5 in over_op_func (op=0x33ce9400, rs=0x433ebc90, which=op_search) at /tmp/buildd/openldap-2.4.19/servers/slapd/backover.c:721 #20 0x00000000004c73b3 in over_op_search (op=0x33ce9400, rs=0x433ebc90) at /tmp/buildd/openldap-2.4.19/servers/slapd/backover.c:748 #21 0x0000000000440844 in fe_op_search (op=0x33ce9400, rs=0x433ebc90) at /tmp/buildd/openldap-2.4.19/servers/slapd/search.c:366 #22 0x00000000004401af in do_search (op=0x33ce9400, rs=0x433ebc90) at /tmp/buildd/openldap-2.4.19/servers/slapd/search.c:217 #23 0x000000000043cbd6 in connection_operation (ctx=0x433ebde0, arg_v=0x33ce9400) at /tmp/buildd/openldap-2.4.19/servers/slapd/connection.c:1123 #24 0x000000000043d162 in connection_read_thread (ctx=0x433ebde0, argv=0x17) at /tmp/buildd/openldap-2.4.19/servers/slapd/connection.c:1259 #25 0x00007f8925b1b19d in ldap_int_thread_pool_wrapper (xpool=0x2d48000) at /tmp/buildd/openldap-2.4.19/libraries/libldap_r/tpool.c:685 #26 0x00007f892409ffc7 in start_thread () from /lib/libpthread.so.0 #27 0x00007f8923e155ad in clone () from /lib/libc.so.6 #28 0x0000000000000000 in ?? () Thread 5 (Thread 0x43bed950 (LWP 24044)): #0 0x00007f89240a6384 in __lll_lock_wait () from /lib/libpthread.so.0 #1 0x00007f89240a1bf0 in _L_lock_102 () from /lib/libpthread.so.0 #2 0x00007f89240a14fe in pthread_mutex_lock () from /lib/libpthread.so.0 #3 0x00007f8925b1c6e5 in ldap_pvt_thread_mutex_lock (mutex=0x2ebbed8) at /tmp/buildd/openldap-2.4.19/libraries/libldap_r/thr_posix.c:296 #4 0x000000000043c414 in connection_next (c=0x2ebbec0, index=0x43beb96c) at /tmp/buildd/openldap-2.4.19/servers/slapd/connection.c:893 #5 0x00007f892036adfa in monitor_subsys_conn_create (op=0x32d96c00, rs=0x43becc90, ndn=0x0, e_parent=0x3b680f8, ep=0x43beba48) at /tmp/buildd/openldap-2.4.19/servers/slapd/back-monitor/conn.c:500 #6 0x00007f8920365077 in monitor_entry_create (op=0x32d96c00, rs=0x43becc90, ndn=0x0, e_parent=0x3b680f8, ep=0x43beba48) at /tmp/buildd/openldap-2.4.19/servers/slapd/back-monitor/entry.c:90 #7 0x00007f8920363420 in monitor_send_children (op=0x32d96c00, rs=0x43becc90, e_parent=0x3b680f8, sub=1) at /tmp/buildd/openldap-2.4.19/servers/slapd/back-monitor/search.c:53 #8 0x00007f89203635c7 in monitor_send_children (op=0x32d96c00, rs=0x43becc90, e_parent=0x3b68058, sub=1) at /tmp/buildd/openldap-2.4.19/servers/slapd/back-monitor/search.c:123 #9 0x00007f8920363a13 in monitor_back_search (op=0x32d96c00, rs=0x43becc90) at /tmp/buildd/openldap-2.4.19/servers/slapd/back-monitor/search.c:245 #10 0x0000000000440844 in fe_op_search (op=0x32d96c00, rs=0x43becc90) at /tmp/buildd/openldap-2.4.19/servers/slapd/search.c:366 #11 0x00000000004401af in do_search (op=0x32d96c00, rs=0x43becc90) at /tmp/buildd/openldap-2.4.19/servers/slapd/search.c:217 #12 0x000000000043cbd6 in connection_operation (ctx=0x43becde0, arg_v=0x32d96c00) at /tmp/buildd/openldap-2.4.19/servers/slapd/connection.c:1123 #13 0x000000000043d162 in connection_read_thread (ctx=0x43becde0, argv=0x69) at /tmp/buildd/openldap-2.4.19/servers/slapd/connection.c:1259 #14 0x00007f8925b1b19d in ldap_int_thread_pool_wrapper (xpool=0x2d48000) at /tmp/buildd/openldap-2.4.19/libraries/libldap_r/tpool.c:685 #15 0x00007f892409ffc7 in start_thread () from /lib/libpthread.so.0 #16 0x00007f8923e155ad in clone () from /lib/libc.so.6 #17 0x0000000000000000 in ?? () Thread 4 (Thread 0x40a74950 (LWP 24045)): #0 0x00007f8923e0ece2 in select () from /lib/libc.so.6 #1 0x00007f892193e729 in ?? () from /usr/lib/libkrb5.so.25 #2 0x00007f892193edce in krb5_sendto () from /usr/lib/libkrb5.so.25 #3 0x00007f892193f06f in krb5_sendto_context () from /usr/lib/libkrb5.so.25 #4 0x00007f892191eb34 in ?? () from /usr/lib/libkrb5.so.25 #5 0x00007f892191efbf in ?? () from /usr/lib/libkrb5.so.25 #6 0x00007f892191f89b in ?? () from /usr/lib/libkrb5.so.25 #7 0x00007f892191f94e in ?? () from /usr/lib/libkrb5.so.25 #8 0x00007f8921920054 in krb5_get_credentials_with_flags () from /usr/lib/libkrb5.so.25 #9 0x00007f89219300c2 in krb5_mk_req_exact () from /usr/lib/libkrb5.so.25 #10 0x00007f8921919a9c in ?? () from /usr/lib/libkrb5.so.25 #11 0x00007f8921919eb8 in krb5_digest_probe () from /usr/lib/libkrb5.so.25 #12 0x00007f8921bddf1b in ?? () from /usr/lib/libgssapi.so.2 #13 0x00007f8921bdbcd9 in ?? () from /usr/lib/libgssapi.so.2 #14 0x00007f8921bd60cc in gss_acquire_cred () from /usr/lib/libgssapi.so.2 #15 0x00007f8921be13f1 in ?? () from /usr/lib/libgssapi.so.2 #16 0x00007f8921bd60cc in gss_acquire_cred () from /usr/lib/libgssapi.so.2 #17 0x00007f8921df17ef in ?? () from /usr/lib/sasl2/libgssapiv2.so.2 #18 0x00007f8924f03dbf in sasl_server_step () from /usr/lib/libsasl2.so.2 #19 0x00007f8924f0510e in sasl_server_start () from /usr/lib/libsasl2.so.2 #20 0x00000000004a8599 in slap_sasl_bind (op=0x3c185800, rs=0x40a73c90) at /tmp/buildd/openldap-2.4.19/servers/slapd/sasl.c:1522 #21 0x0000000000464126 in fe_op_bind (op=0x3c185800, rs=0x40a73c90) at /tmp/buildd/openldap-2.4.19/servers/slapd/bind.c:280 #22 0x0000000000463d2b in do_bind (op=0x3c185800, rs=0x40a73c90) at /tmp/buildd/openldap-2.4.19/servers/slapd/bind.c:205 #23 0x000000000043cbd6 in connection_operation (ctx=0x40a73de0, arg_v=0x3c185800) at /tmp/buildd/openldap-2.4.19/servers/slapd/connection.c:1123 #24 0x000000000043d162 in connection_read_thread (ctx=0x40a73de0, argv=0x93) at /tmp/buildd/openldap-2.4.19/servers/slapd/connection.c:1259 #25 0x00007f8925b1b19d in ldap_int_thread_pool_wrapper (xpool=0x2d48000) at /tmp/buildd/openldap-2.4.19/libraries/libldap_r/tpool.c:685 #26 0x00007f892409ffc7 in start_thread () from /lib/libpthread.so.0 #27 0x00007f8923e155ad in clone () from /lib/libc.so.6 #28 0x0000000000000000 in ?? () Thread 3 (Thread 0x443ee950 (LWP 24046)): #0 0x00007f89240a6384 in __lll_lock_wait () from /lib/libpthread.so.0 #1 0x00007f89240a1bf0 in _L_lock_102 () from /lib/libpthread.so.0 #2 0x00007f89240a14fe in pthread_mutex_lock () from /lib/libpthread.so.0 #3 0x00007f8925b1c6e5 in ldap_pvt_thread_mutex_lock (mutex=0x2aad8d0) at /tmp/buildd/openldap-2.4.19/libraries/libldap_r/thr_posix.c:296 #4 0x00007f8925b264e9 in ldap_pvt_sasl_mutex_lock (mutex=0x2aad8d0) at cyrus.c:1160 #5 0x00007f8921df1c8e in ?? () from /usr/lib/sasl2/libgssapiv2.so.2 #6 0x00007f8924f03dbf in sasl_server_step () from /usr/lib/libsasl2.so.2 #7 0x00000000004a85d0 in slap_sasl_bind (op=0x354b8c00, rs=0x443edc90) at /tmp/buildd/openldap-2.4.19/servers/slapd/sasl.c:1528 #8 0x0000000000464126 in fe_op_bind (op=0x354b8c00, rs=0x443edc90) at /tmp/buildd/openldap-2.4.19/servers/slapd/bind.c:280 #9 0x0000000000463d2b in do_bind (op=0x354b8c00, rs=0x443edc90) at /tmp/buildd/openldap-2.4.19/servers/slapd/bind.c:205 #10 0x000000000043cbd6 in connection_operation (ctx=0x443edde0, arg_v=0x354b8c00) at /tmp/buildd/openldap-2.4.19/servers/slapd/connection.c:1123 #11 0x000000000043d162 in connection_read_thread (ctx=0x443edde0, argv=0x96) at /tmp/buildd/openldap-2.4.19/servers/slapd/connection.c:1259 #12 0x00007f8925b1b19d in ldap_int_thread_pool_wrapper (xpool=0x2d48000) at /tmp/buildd/openldap-2.4.19/libraries/libldap_r/tpool.c:685 #13 0x00007f892409ffc7 in start_thread () from /lib/libpthread.so.0 #14 0x00007f8923e155ad in clone () from /lib/libc.so.6 #15 0x0000000000000000 in ?? () Thread 2 (Thread 0x44bef950 (LWP 24047)): #0 0x00007f89240a6384 in __lll_lock_wait () from /lib/libpthread.so.0 #1 0x00007f89240a1bf0 in _L_lock_102 () from /lib/libpthread.so.0 #2 0x00007f89240a14fe in pthread_mutex_lock () from /lib/libpthread.so.0 #3 0x00007f8925b1c6e5 in ldap_pvt_thread_mutex_lock (mutex=0x2aad8d0) at /tmp/buildd/openldap-2.4.19/libraries/libldap_r/thr_posix.c:296 #4 0x00007f8925b264e9 in ldap_pvt_sasl_mutex_lock (mutex=0x2aad8d0) at cyrus.c:1160 #5 0x00007f8921df100d in ?? () from /usr/lib/sasl2/libgssapiv2.so.2 #6 0x00007f8924f00500 in ?? () from /usr/lib/libsasl2.so.2 #7 0x00007f8924f00aca in sasl_encodev () from /usr/lib/libsasl2.so.2 #8 0x00007f8924f00b72 in sasl_encode () from /usr/lib/libsasl2.so.2 #9 0x00007f8925b24585 in sb_sasl_cyrus_encode (p=0x3c934960, buf=0xfdea740 "0\202\001���002\001\004d\202\001���\004(uid=tayah,cn=accounts,dc=stanford,dc=edu0\202\001\2150>\004\tsuService11\004\006dialin\004\003afs\004\006leland\004\005email\004\004seas\004\003pts\004\bkerberos0\016\004\003uid1\a\004\005tayah0\034\004\020suKerberosStatus1\b\004\006active0\031\004\rsuEmailStatus1\b\004\006active0\201���\004\vo"..., len=454, dst=0x3c9349d0) at cyrus.c:165 #10 0x00007f8925b298a1 in sb_sasl_generic_write (sbiod=0x3cb61690, buf=0xfdea740, len=454) at sasl.c:716 #11 0x00007f8925905b70 in sb_debug_write (sbiod=0x3ca07cc0, buf=0xfdea740, len=454) at /tmp/buildd/openldap-2.4.19/libraries/liblber/sockbuf.c:852 #12 0x00007f8925904f61 in ber_int_sb_write (sb=0x3caca750, buf=0xfdea740, len=454) at /tmp/buildd/openldap-2.4.19/libraries/liblber/sockbuf.c:445 #13 0x00007f892590112e in ber_flush2 (sb=0x3caca750, ber=0x44a6d4e0, freeit=0) at /tmp/buildd/openldap-2.4.19/libraries/liblber/io.c:246 #14 0x0000000000451c56 in send_ldap_ber (op=0x3c185000, ber=0x44a6d4e0) at /tmp/buildd/openldap-2.4.19/servers/slapd/result.c:191 #15 0x0000000000455857 in slap_send_search_entry (op=0x3c185000, rs=0x44beec90) at /tmp/buildd/openldap-2.4.19/servers/slapd/result.c:1260 #16 0x00007f8920597320 in hdb_search (op=0x3c185000, rs=0x44beec90) at search.c:961 #17 0x00000000004c70be in overlay_op_walk (op=0x3c185000, rs=0x44beec90, which=op_search, oi=0x2e0fa00, on=0x0) at /tmp/buildd/openldap-2.4.19/servers/slapd/backover.c:669 #18 0x00000000004c72e5 in over_op_func (op=0x3c185000, rs=0x44beec90, which=op_search) at /tmp/buildd/openldap-2.4.19/servers/slapd/backover.c:721 #19 0x00000000004c73b3 in over_op_search (op=0x3c185000, rs=0x44beec90) at /tmp/buildd/openldap-2.4.19/servers/slapd/backover.c:748 #20 0x0000000000440844 in fe_op_search (op=0x3c185000, rs=0x44beec90) at /tmp/buildd/openldap-2.4.19/servers/slapd/search.c:366 #21 0x00000000004401af in do_search (op=0x3c185000, rs=0x44beec90) at /tmp/buildd/openldap-2.4.19/servers/slapd/search.c:217 #22 0x000000000043cbd6 in connection_operation (ctx=0x44beede0, arg_v=0x3c185000) at /tmp/buildd/openldap-2.4.19/servers/slapd/connection.c:1123 #23 0x000000000043d162 in connection_read_thread (ctx=0x44beede0, argv=0x82) at /tmp/buildd/openldap-2.4.19/servers/slapd/connection.c:1259 #24 0x00007f8925b1b19d in ldap_int_thread_pool_wrapper (xpool=0x2d48000) at /tmp/buildd/openldap-2.4.19/libraries/libldap_r/tpool.c:685 #25 0x00007f892409ffc7 in start_thread () from /lib/libpthread.so.0 #26 0x00007f8923e155ad in clone () from /lib/libc.so.6 #27 0x0000000000000000 in ?? () Thread 1 (Thread 0x7f89261b86f0 (LWP 24029)): #0 0x00007f89240a0715 in pthread_join () from /lib/libpthread.so.0 #1 0x00007f8925b1c5f3 in ldap_pvt_thread_join (thread=1094617424, thread_return=0x0) at /tmp/buildd/openldap-2.4.19/libraries/libldap_r/thr_posix.c:197 #2 0x0000000000439d2e in slapd_daemon () at /tmp/buildd/openldap-2.4.19/servers/slapd/daemon.c:2835 #3 0x000000000041afdd in main (argc=3, argv=0x7fff0941e0b8) at /tmp/buildd/openldap-2.4.19/servers/slapd/main.c:950 #0 0x00007f89240a0715 in pthread_join () from /lib/libpthread.so.0 (gdb)
--On November 16, 2009 8:27:21 PM +0000 whm@stanford.edu wrote: > Full_Name: Bill MacAllister > Version: 2.4.19+ > OS: Debian 5 > URL: ftp://ftp.openldap.org/incoming/ > Submission from: (NULL) (171.64.19.165) > > > On a system where slapd is the top CPU process and is consuming 4% of the > CPU simple queries are taking ten of seconds to complete. Here is an > example query: Last time we saw this it appeared that it might be related to DNS. How long does a netstat -a take on the affected systems when the LDAP queries are slow? --Quanah -- Quanah Gibson-Mount Principal Software Engineer Zimbra, Inc -------------------- Zimbra :: the leader in open source messaging and collaboration
--On Monday, November 16, 2009 07:37:49 PM -0800 Quanah Gibson-Mount <quanah@zimbra.com> wrote: > > > --On November 16, 2009 8:27:21 PM +0000 whm@stanford.edu wrote: > >> Full_Name: Bill MacAllister >> Version: 2.4.19+ >> OS: Debian 5 >> URL: ftp://ftp.openldap.org/incoming/ >> Submission from: (NULL) (171.64.19.165) >> >> >> On a system where slapd is the top CPU process and is consuming 4% of the >> CPU simple queries are taking ten of seconds to complete. Here is an >> example query: > > Last time we saw this it appeared that it might be related to DNS. > How long does a netstat -a take on the affected systems when the > LDAP queries are slow? I don't have that number. I have only see it once in the test environment I am not sure how long it will take me to get it. Since this plastered the production service today, I will have to reproduce it though before we attempt another production upgrade. Not clear to me why a DNS issue would appear only under load and not at other times. And it seems strange that it appears in lenny/openldap-2.4 and not in etch/openldap-2.3. Bill -- Bill MacAllister, System Software Programmer Unix Systems Group, Stanford University
changed notes changed state Open to Feedback
On Nov 16, 2009, at 9:03 PM, Bill MacAllister <whm@stanford.edu> wrote: > > > --On Monday, November 16, 2009 07:37:49 PM -0800 Quanah Gibson-Mount > <quanah@zimbra.com> wrote: > >> >> >> --On November 16, 2009 8:27:21 PM +0000 whm@stanford.edu wrote: >> >>> Full_Name: Bill MacAllister >>> Version: 2.4.19+ >>> OS: Debian 5 >>> URL: ftp://ftp.openldap.org/incoming/ >>> Submission from: (NULL) (171.64.19.165) >>> >>> >>> On a system where slapd is the top CPU process and is consuming 4% >>> of the >>> CPU simple queries are taking ten of seconds to complete. Here is >>> an >>> example query: >> >> Last time we saw this it appeared that it might be related to DNS. >> How long does a netstat -a take on the affected systems when the >> LDAP queries are slow? > > I don't have that number. I have only see it once in the test > environment I am not sure how long it will take me to get it. Since > this plastered the production service today, I will have to reproduce > it though before we attempt another production upgrade. > > Not clear to me why a DNS issue would appear only under load and not > at other times. And it seems strange that it appears in > lenny/openldap-2.4 and not in etch/openldap-2.3. > > Bill > > -- > Bill MacAllister, System Software Programmer > Unix Systems Group, Stanford University For historical note this was caused by Cyrus-sasl being built incorrectly by the debian packagers when heimdal is used. --Quanah
quanah@zimbra.com writes: > For historical note this was caused by Cyrus-sasl being built > incorrectly by the debian packagers when heimdal is used. Well, rather, that's a theory which currently looks good. It definitely hasn't been proven yet. -- Russ Allbery (rra@stanford.edu) <http://www.eyrie.org/~eagle/>
--On Tuesday, November 17, 2009 09:11:23 PM -0800 Quanah Gibson-Mount <quanah@zimbra.com> wrote: > > > On Nov 16, 2009, at 9:03 PM, Bill MacAllister <whm@stanford.edu> wrote: > >> >> >> --On Monday, November 16, 2009 07:37:49 PM -0800 Quanah Gibson-Mount >> <quanah@zimbra.com> wrote: >> >>> >>> >>> --On November 16, 2009 8:27:21 PM +0000 whm@stanford.edu wrote: >>> >>>> Full_Name: Bill MacAllister >>>> Version: 2.4.19+ >>>> OS: Debian 5 >>>> URL: ftp://ftp.openldap.org/incoming/ >>>> Submission from: (NULL) (171.64.19.165) >>>> >>>> >>>> On a system where slapd is the top CPU process and is consuming 4% >>>> of the >>>> CPU simple queries are taking ten of seconds to complete. Here is >>>> an >>>> example query: >>> >>> Last time we saw this it appeared that it might be related to DNS. >>> How long does a netstat -a take on the affected systems when the >>> LDAP queries are slow? >> >> I don't have that number. I have only see it once in the test >> environment I am not sure how long it will take me to get it. Since >> this plastered the production service today, I will have to reproduce >> it though before we attempt another production upgrade. >> >> Not clear to me why a DNS issue would appear only under load and not >> at other times. And it seems strange that it appears in >> lenny/openldap-2.4 and not in etch/openldap-2.3. >> >> Bill >> >> -- >> Bill MacAllister, System Software Programmer >> Unix Systems Group, Stanford University > > For historical note this was caused by Cyrus-sasl being built > incorrectly by the debian packagers when heimdal is used. > > --Quanah I don't understand why you refer to this finding as historical. If I am reading this correctly you and Howard have found the underlying cause. Now that the problem is understood can you suggest a way for us to cause the problem in our test environments? At this point we will really need to convince ourselves that the problem is indeed fixed before we try to deploy 2.4 in our production environment again. Bill -- Bill MacAllister, System Software Programmer Unix Systems Group, Stanford University
--On November 18, 2009 9:39:02 AM +0000 Bill MacAllister <whm@stanford.edu> wrote: >> For historical note this was caused by Cyrus-sasl being built >> incorrectly by the debian packagers when heimdal is used. >> > > I don't understand why you refer to this finding as historical. Not a historical finding. As a record for anyone who comes across this ITS and wants to know what was found. > If I > am reading this correctly you and Howard have found the underlying > cause. Now that the problem is understood can you suggest a way for > us to cause the problem in our test environments? At this point we > will really need to convince ourselves that the problem is indeed fixed > before we try to deploy 2.4 in our production environment again. To note, first off, this issue was not a bug in OpenLDAP, and the project went beyond its scope in tracking down why cyrus-sasl was behaving the way it was. Finding out test cases for you to explore is also beyond the scope of the OpenLDAP project when dealing with non-OpenLDAP issues. However, given what is known, i.e., that the NTLM code path was being called during SASL/GSSAPI binds, I would suggest you either set up a number of windows boxes that try and do SASL/GSSAPI auth with NTLM to a test server, or write a script that does that and run it from multiple systems. Some reference points: <http://www.netid.washington.edu/documentation/ldapAuth.aspx> It also seems it may be possible to use python-ldap to do this. I don't know if it is possible with Net::LDAP or Net::LDAPapi --Quanah -- Quanah Gibson-Mount Principal Software Engineer Zimbra, Inc -------------------- Zimbra :: the leader in open source messaging and collaboration
most likely not ours
changed state Feedback to Closed