[Date Prev][Date Next]
[Chronological]
[Thread]
[Top]
slow response time (ex. cn=*something*)
Hello
i'm having a hard time finding a reason for the slowness of a substring
search with asterixs on both ends. (i don't know the technical term for
that kind of search).
my goal is to replace a 1.x version of openldap with a 2.x version that
does replication, ssl, sasl and other cool stuff without losing a
lot of response time.
i don't claim to be an expert on openldap or ldap in general, but i've
been playing with it for a while now and i'm not getting anywhere. i'm
hoping someone has an idea about the problem.
i'm pretty sure it has something to do with the indexing and/or schema,
but i'm not able to understand the schema differences and i've tried
pretty much everything with the indexing.
the situation...
i have inherited an old 1.x openldap directory used for email, name, phone
number, office, etc. lookups running in production that is very quick when
i do searches like cn=*something*.
i have a new ldap directory with the same data (different schema
obviously) that is equally fast with searches like cn=something* or
*something, but with *something* its much slower. the difference
is something like 10 times slower after the first request (after its
cached?).
i've gone through some debugs and i've noticed that when i do *something*
searches it steps through pretty much all entries (5000), but when i do
single * it does not.
here are the index lines from my conf.
cachesize 10000
dbcachesize 2000000
sizelimit 500
index objectClass eq,pres
index cn,sn sub,eq,pres
snippets from the debug logs are attached.
any suggestions on how to fix this problem or other things to try would be
much appreciated.
alex
connection_get(8)
connection_get(8): got connid=0
connection_read(8): checking for input on id=0
ber_get_next
ldap_read: want=1, got=1
0000: 30 0
ldap_read: want=1, got=1
0000: 0c .
ldap_read: want=12, got=12
0000: 02 01 01 60 07 02 01 03 04 00 80 00 ...`........
ber_get_next: tag 0x30 len 12 contents:
ber_dump: buf=0x0017bcd8 ptr=0x0017bcd8 end=0x0017bce4 len=12
0000: 02 01 01 60 07 02 01 03 04 00 80 00 ...`........
ber_get_next
ldap_read: want=1 error=Resource temporarily unavailable
ber_get_next on fd 8 failed errno=11 (Resource temporarily unavailable)
do_bind
ber_scanf fmt ({iat) ber:
ber_dump: buf=0x0017bcd8 ptr=0x0017bcdb end=0x0017bce4 len=9
0000: 60 07 02 01 03 04 00 80 00 `........
ber_scanf fmt (o}) ber:
ber_dump: buf=0x0017bcd8 ptr=0x0017bce2 end=0x0017bce4 len=2
0000: 80 00 ..
do_bind: version=3 dn="" method=128
conn=0 op=0 BIND dn="" method=128
send_ldap_result: conn=0 op=0 p=3
send_ldap_result: 0::
send_ldap_response: msgid=1 tag=97 err=0
ber_flush: 14 bytes to sd 8
0000: 30 0c 02 01 01 61 07 0a 01 00 04 00 04 00 0....a........
ldap_write: want=14, written=14
0000: 30 0c 02 01 01 61 07 0a 01 00 04 00 04 00 0....a........
conn=0 op=0 RESULT tag=97 err=0 text=
do_bind: v3 anonymous bind
daemon: select: listen=7 active_threads=1 tvp=NULL
daemon: activity on 1 descriptors
daemon: activity on: 8r
daemon: read activity on 8
connection_get(8)
connection_get(8): got connid=0
connection_read(8): checking for input on id=0
ber_get_next
ldap_read: want=1, got=1
0000: 30 0
ldap_read: want=1, got=1
0000: 33 3
ldap_read: want=51, got=51
0000: 02 01 02 63 2e 04 0e 63 3d 66 72 2c 6f 3d 63 65 ...c...c=fr,o=ce
0010: 74 65 6c 65 6d 0a 01 02 0a 01 00 02 01 00 02 01 telem...........
0020: 00 01 01 00 a4 0b 04 02 63 6e 30 05 81 03 64 65 ........cn0...de
0030: 70 30 00 p0.
ber_get_next: tag 0x30 len 51 contents:
ber_dump: buf=0x00157018 ptr=0x00157018 end=0x0015704b len=51
0000: 02 01 02 63 2e 04 0e 63 3d 66 72 2c 6f 3d 63 65 ...c...c=fr,o=ce
0010: 74 65 6c 65 6d 0a 01 02 0a 01 00 02 01 00 02 01 telem...........
0020: 00 01 01 00 a4 0b 04 02 63 6e 30 05 81 03 64 65 ........cn0...de
0030: 70 30 00 p0.
ber_get_next
ldap_read: want=1 error=Resource temporarily unavailable
ber_get_next on fd 8 failed errno=11 (Resource temporarily unavailable)
do_search
ber_scanf fmt ({aiiiib) ber:
ber_dump: buf=0x00157018 ptr=0x0015701b end=0x0015704b len=48
0000: 63 2e 04 0e 63 3d 66 72 2c 6f 3d 63 65 74 65 6c c...c=fr,o=cetel
0010: 65 6d 0a 01 02 0a 01 00 02 01 00 02 01 00 01 01 em..............
0020: 00 a4 0b 04 02 63 6e 30 05 81 03 64 65 70 30 00 .....cn0...dep0.
SRCH "c=fr,o=cetelem" 2 0 0 0 0
begin get_filter
SUBSTRINGS
begin get_substring_filter
ber_scanf fmt ({o) ber:
ber_dump: buf=0x00157018 ptr=0x0015703c end=0x0015704b len=15
0000: a4 0b 04 02 63 6e 30 05 81 03 64 65 70 30 00 ....cn0...dep0.
ber_scanf fmt (O) ber:
ber_dump: buf=0x00157018 ptr=0x00157044 end=0x0015704b len=7
0000: 81 03 64 65 70 30 00 ..dep0.
ANY
end get_substring_filter
end get_filter 0
filter: (cn=*dep*)
ber_scanf fmt ({v}}) ber:
ber_dump: buf=0x00157018 ptr=0x00157049 end=0x0015704b len=2
0000: 30 00 0.
attrs:
conn=0 op=1 SRCH base="c=fr,o=cetelem" scope=2 filter="(cn=*dep*)"
=> ldbm_back_search
dn2entry_r: dn: "C=FR,O=CETELEM"
=> dn2id( "C=FR,O=CETELEM" )
=> ldbm_cache_open( "dn2id.dbb", 73, 600 )
ldbm_cache_open (blksize 8192) (maxids 2046) (maxindirect 5)
<= ldbm_cache_open (opened 0)
<= dn2id 1
=> id2entry_r( 1 )
=> ldbm_cache_open( "id2entry.dbb", 73, 600 )
ldbm_cache_open (blksize 8192) (maxids 2046) (maxindirect 5)
<= ldbm_cache_open (opened 1)
=> str2entry
<= str2entry(c=fr, o=Cetelem) -> -1 (0x1724b0)
<= id2entry_r( 1 ) 0x1724b0 (disk)
search_candidates: base="C=FR,O=CETELEM" s=2 d=0
=> filter_candidates
AND
=> list_candidates 0xa0
=> filter_candidates
DN SUBTREE
=> dn2idl( "@C=FR,O=CETELEM" )
=> ldbm_cache_open( "dn2id.dbb", 73, 600 )
<= ldbm_cache_open (cache 0)
<= idl_fetch 4773 ids (4773 max)
<= filter_candidates 4773
=> filter_candidates
OR
=> list_candidates 0xa1
=> filter_candidates
EQUALITY
=> equality_candidates
=> ldbm_cache_open( "nextid.dbb", 73, 600 )
ldbm_cache_open (blksize 8192) (maxids 2046) (maxindirect 5)
<= ldbm_cache_open (opened 2)
=> ldbm_cache_open( "objectClass.dbb", 73, 600 )
ldbm_cache_open (blksize 8192) (maxids 2046) (maxindirect 5)
<= ldbm_cache_open (opened 3)
=> key_read
<= index_read 0 candidates
<= equality_candidates NULL
<= equality_candidates 0
<= filter_candidates 0
=> filter_candidates
SUBSTRINGS
=> substrings_candidates
<= substrings_candidates: (0x0716) no keys (cn.dbb)
<= filter_candidates 4774
<= list_candidates 4774
<= filter_candidates 4774
<= list_candidates 4773
<= filter_candidates 4773
====> cache_return_entry_r( 1 ): created (0)
=> id2entry_r( 1 )
====> cache_find_entry_id( 1 ) "c=fr, o=Cetelem" (found) (1 tries)
<= id2entry_r( 1 ) 0x1724b0 (cache)
=> test_filter
SUBSTRINGS
begin test_substrings_filter
=> access_allowed: search access to "c=fr, o=Cetelem" "cn" requested
=> acl_get: [1] check attr cn
=> acl_get: [2] check attr cn
=> acl_get: [3] check attr cn
<= acl_get: [3] acl c=fr, o=Cetelem attr: cn
=> acl_mask: access to entry "c=fr, o=Cetelem", attr "cn" requested
=> acl_mask: to all values by "", (=n)
<= check a_dn_pat: *
<= acl_mask: [1] applying write (=wrscx) (stop)
<= acl_mask: [1] mask: write (=wrscx)
=> access_allowed: search access granted by write (=wrscx)
end test_substrings_filter 1
<= test_filter 5
ldbm_search: candidate 1 does not match filter
====> cache_return_entry_r( 1 ): returned (0)
daemon: select: listen=7 active_threads=1 tvp=NULL
=> id2entry_r( 2 )
=> ldbm_cache_open( "id2entry.dbb", 73, 600 )
<= ldbm_cache_open (cache 1)
=> str2entry
<= str2entry(ou=societes, c=fr, o=Cetelem) -> -1 (0x172530)
<= id2entry_r( 2 ) 0x172530 (disk)
=> test_filter
SUBSTRINGS
begin test_substrings_filter
=> access_allowed: search access to "ou=societes, c=fr, o=Cetelem" "cn" requeste
d
=> acl_get: [1] check attr cn
=> acl_get: [2] check attr cn
=> acl_get: [3] check attr cn
<= acl_get: [3] acl ou=societes, c=fr, o=Cetelem attr: cn
=> acl_mask: access to entry "ou=societes, c=fr, o=Cetelem", attr "cn" requested
=> acl_mask: to all values by "", (=n)
<= check a_dn_pat: *
<= acl_mask: [1] applying write (=wrscx) (stop)
<= acl_mask: [1] mask: write (=wrscx)
=> access_allowed: search access granted by write (=wrscx)
end test_substrings_filter 1
<= test_filter 5
ldbm_search: candidate 2 does not match filter
====> cache_return_entry_r( 2 ): created (0)
=> id2entry_r( 3 )
=> ldbm_cache_open( "id2entry.dbb", 73, 600 )
<= ldbm_cache_open (cache 1)
=> str2entry
<= str2entry(ou=services, c=fr, o=Cetelem) -> -1 (0x172550)
<= id2entry_r( 3 ) 0x172550 (disk)
=> test_filter
SUBSTRINGS
begin test_substrings_filter
=> access_allowed: search access to "ou=services, c=fr, o=Cetelem" "cn" requeste
d
=> acl_get: [1] check attr cn
=> acl_get: [2] check attr cn
=> acl_get: [3] check attr cn
<= acl_get: [3] acl ou=services, c=fr, o=Cetelem attr: cn
=> acl_mask: access to entry "ou=services, c=fr, o=Cetelem", attr "cn" requested
=> acl_mask: to all values by "", (=n)
<= check a_dn_pat: *
<= acl_mask: [1] applying write (=wrscx) (stop)
<= acl_mask: [1] mask: write (=wrscx)
=> access_allowed: search access granted by write (=wrscx)
end test_substrings_filter 1
<= test_filter 5
ldbm_search: candidate 3 does not match filter
====> cache_return_entry_r( 3 ): created (0)
=> id2entry_r( 4 )
=> ldbm_cache_open( "id2entry.dbb", 73, 600 )
<= ldbm_cache_open (cache 1)
=> str2entry
<= str2entry(ou=personnes, c=fr, o=Cetelem) -> -1 (0x172590)
<= id2entry_r( 4 ) 0x172590 (disk)
=> test_filter
SUBSTRINGS
begin test_substrings_filter
=> access_allowed: search access to "ou=personnes, c=fr, o=Cetelem" "cn" request
ed
=> acl_get: [1] check attr cn
=> acl_get: [2] check attr cn
=> acl_get: [3] check attr cn
<= acl_get: [3] acl ou=personnes, c=fr, o=Cetelem attr: cn
=> acl_mask: access to entry "ou=personnes, c=fr, o=Cetelem", attr "cn" requeste
d
=> acl_mask: to all values by "", (=n)
<= check a_dn_pat: *
<= acl_mask: [1] applying write (=wrscx) (stop)
<= acl_mask: [1] mask: write (=wrscx)
=> access_allowed: search access granted by write (=wrscx)
end test_substrings_filter 1
<= test_filter 5
ldbm_search: candidate 4 does not match filter
====> cache_return_entry_r( 4 ): created (0)
=> id2entry_r( 5 )
=> ldbm_cache_open( "id2entry.dbb", 73, 600 )
<= ldbm_cache_open (cache 1)
=> str2entry
<= str2entry(ou=parautilisateurs, c=fr, o=Cetelem) -> -1 (0x1725d0)
<= id2entry_r( 5 ) 0x1725d0 (disk)
=> test_filter
SUBSTRINGS
begin test_substrings_filter
=> access_allowed: search access to "ou=parautilisateurs, c=fr, o=Cetelem" "cn"
requested
=> acl_get: [1] check attr cn
=> acl_get: [2] check attr cn
=> acl_get: [3] check attr cn
<= acl_get: [3] acl ou=parautilisateurs, c=fr, o=Cetelem attr: cn
=> acl_mask: access to entry "ou=parautilisateurs, c=fr, o=Cetelem", attr "cn" r
equested
=> acl_mask:values by "", (=n)
<= check a_dn_pat: *
<= acl_mask: [1] applying write (=wrscx) (stop)
<= acl_mask: [1] mask: write (=wrscx)
=> access_allowed: search access granted by write (=wrscx)
end test_substrings_filter 1
<= test_filter 5
ldbm_search: candidate 6 does not match filter
====> cache_return_entry_r( 6 ): created (0)
=> id2entry_r( 7 )
=> ldbm_cache_open( "id2entry.dbb", 73, 600 )
<= ldbm_cache_open (cache 1)
=> str2entry
<= str2entry(ou=999,ou=999,ou=services,c=fr,o=cetelem) -> -1 (0x1726f0)
<= id2entry_r( 7 ) 0x1726f0 (disk)
=> test_filter
SUBSTRINGS
begin test_substrings_filter
=> access_allowed: search access to "ou=999,ou=999,ou=services,c=fr,o=cetelem" "
cn" requested
=> acl_get: [1] check attr cn
=> acl_get: [2] check attr cn
=> acl_get: [3] check attr cn
<= acl_get: [3] acl ou=999,ou=999,ou=services,c=fr,o=cetelem attr: cn
=> acl_mask: access to entry "ou=999,ou=999,ou=services,c=fr,o=cetelem", attr "c
n" requested
=> acl_mask: to all values by "", (=n)