Issue 7743 - mdb_idl_intersection() seems to expand the search candidates unnecessarily
Summary: mdb_idl_intersection() seems to expand the search candidates unnecessarily
Status: VERIFIED DUPLICATE of issue 8868
Alias: None
Product: OpenLDAP
Classification: Unclassified
Component: backends (show other issues)
Version: 2.4.37
Hardware: All All
: --- normal
Target Milestone: 2.5.0
Assignee: OpenLDAP project
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2013-11-12 03:09 UTC by yos-nishino@ys.jp.nec.com
Modified: 2020-09-03 15:10 UTC (History)
0 users

See Also:


Attachments

Note You need to log in before you can comment on or make changes to this issue.
Description yos-nishino@ys.jp.nec.com 2013-11-12 03:09:05 UTC
Full_Name: Yoshinori Nishino
Version: 2.4.37
OS: RedHatEL 5.5
URL: ftp://ftp.openldap.org/incoming/
Submission from: (NULL) (210.143.35.12)


Dear sir,

 OS:Red Hat Enterprise Linux 5.5(x86) (2.6.18-194.el5)
 Version: 2.4.37 + BDB 4.4.20

In our environment, the issue occurs that the ldapsearch command using the
following filter always took about 15�`30 seconds.

 '(|(mailLocalAddress=XXXXXXX@xxxx.yy.zz)(mailRoutingAddress=XXXXXXX@xxxx.yy.zz)(&(xxxXXXXAlias=XXXXXXX)(xxxXXXYYYYYYList=bb)))'
 # masked the private information for the security reason.

As far as I checked the debug.log("loglevel -1" in slapd.conf) and
servers/slapd/back-bdb/idl.c,
bdb_idl_intersection() seems to expand the search candidates unnecessarily,
which results in this slow response.
#Please see the log below(masked the private information for the security
reason)

The detail that I expect is as follows:

==
 1.
 By seaeching the index datebases, slapd got the candidate sets for each of the
attributes.

  A.The candidate set of mailLocalAddress: (list-type: the number of
elements=296, minID=296,maxID=858689)

  B.The candidate set of mailRoutingAddress:(list-type: the number of
elements=0, minID=0,maxID=0)

  C.The candidate set of xxxXXXXAlias:(list-type: the number of elements=2,
minID=676406, maxID=676407)

  D.The candidate set of xxxXXXYYYYYYList:(range-type: minID=628610,
maxID=868129)
  #become range-type because the number of elements is more than 65536

 2.
 First, slapd ran bdb_idl_intersection(C,D) according to the search filter,
which resulted in the following candidate set.

   E.(range-type: minID=676406, maxID=676407)

 3.
 Next, slapd ran bdb_idl_union(E,A), which resulted in the following.

   F.(range-type: minID=296, maxID=858689)

 4.
 Finally, slapd ran bdb_idl_union(F,B), which resulted in the following search
candidate.

   G.(range-type: minID=296, maxID=858689)

 Therefore, slapd searched many candidates unnecessarily.

==

The issues seems to occur because the following part of idl.c.

  1087          /* If a range completely covers the list, the result is         
                                                             
  1088           * just the list. If idmin to idmax is contiguous, just         
                                                             
  1089           * turn it into a range.                                        
                                                             
  1090           */         
  1091          if ( BDB_IDL_IS_RANGE( b )                                      
                                                             
  1092                  && BDB_IDL_RANGE_FIRST( b ) <= BDB_IDL_RANGE_FIRST( a ) 
                                                             
  1093                  && BDB_IDL_RANGE_LAST( b ) >= BDB_IDL_RANGE_LAST( a ) )
{                                                             
  1094                  if (idmax - idmin + 1 == a[0])                          
                                                             
  1095                  {                                                       
                                                             
  1096                          a[0] = NOID;                                    
                                                             
  1097                          a[1] = idmin;                                   
                                                             
  1098                          a[2] = idmax;                                   
                                                             
  1099                  }                                                       
                                                             
  1100                  goto done;                                              
                                                             
  1101          }            

In the aforementioned "2", the set C matches the "if" condition of line 1094.
Therefore the result of bdb_idl_intersection() becomes the range-type candidate
set.

If the set C didn't matche the condition, slapd would run "goto"(line 1094),
according to which 
the result of bdb_idl_intersection(C,D) would be just "C"(list-type: the number
of elements=2, minID=676406, maxID=676407).
However, because the bdb_idl_intersection() make the result set changed into
"range-type" unnecessarily, 
slapd is finally forced to search about 800,000 entries in vain.

The response of the ldapsearch command becomes faster by modifying idl.c like
that:

  1087          /* If a range completely covers the list, the result is         
                                                             
  1088           * just the list. If idmin to idmax is contiguous, just         
                                                             
  1089           * turn it into a range.                                        
                                                             
  1090           */         
  1091          if ( BDB_IDL_IS_RANGE( b )                                      
                                                             
  1092                  && BDB_IDL_RANGE_FIRST( b ) <= BDB_IDL_RANGE_FIRST( a ) 
                                                             
  1093                  && BDB_IDL_RANGE_LAST( b ) >= BDB_IDL_RANGE_LAST( a ) )
{                                                             
  1094                  /* if (idmax - idmin + 1 == a[0])                       
                                                                
  1095                  {                                                       
                                                             
  1096                          a[0] = NOID;                                    
                                                             
  1097                          a[1] = idmin;                                   
                                                             
  1098                          a[2] = idmax;                                   
                                                             
  1099                  }  */                                                   
                                                               
  1100                  goto done;                                              
                                                             
  1101          }            

By the aforementioned modification, the search candidate set becomes (list-type:
the number of elements=298, minID=296,maxID=858689).

I think the line 1094-1099 part of idl.c seems to be a bug.
The part seems to be implemented in order to just make "ids[]" smaller.
If the reason is so, would you please consider fixing idl.c?


*debug log(masked for security reason)
Nov 12 10:42:58 server2 slapd[714]: daemon: activity on 1 descriptor 
Nov 12 10:42:58 server2 slapd[714]: daemon: activity on:
Nov 12 10:42:58 server2 slapd[714]:  
Nov 12 10:42:58 server2 slapd[714]: slap_listener_activate(8):  
Nov 12 10:42:58 server2 slapd[714]: daemon: epoll: listen=7 active_threads=0
tvp=zero 
Nov 12 10:42:58 server2 slapd[714]: daemon: epoll: listen=8 busy 
Nov 12 10:42:58 server2 slapd[714]: >>> slap_listener(ldap:///) 
Nov 12 10:42:58 server2 slapd[714]: daemon: listen=8, new connection on 10 
Nov 12 10:42:58 server2 slapd[714]: daemon: added 10r (active) listener=(nil) 
Nov 12 10:42:58 server2 slapd[714]: conn=1000 fd=10 ACCEPT from
IP=127.0.0.1:51095 (IP=0.0.0.0:389) 
Nov 12 10:42:58 server2 slapd[714]: daemon: activity on 2 descriptors 
Nov 12 10:42:58 server2 slapd[714]: daemon: activity on:
Nov 12 10:42:58 server2 slapd[714]:  10r
Nov 12 10:42:58 server2 slapd[714]:  
Nov 12 10:42:58 server2 slapd[714]: daemon: read active on 10 
Nov 12 10:42:58 server2 slapd[714]: daemon: epoll: listen=7 active_threads=0
tvp=zero 
Nov 12 10:42:58 server2 slapd[714]: daemon: epoll: listen=8 active_threads=0
tvp=zero 
Nov 12 10:42:58 server2 slapd[714]: connection_get(10) 
Nov 12 10:42:58 server2 slapd[714]: connection_get(10): got connid=1000 
Nov 12 10:42:58 server2 slapd[714]: connection_read(10): checking for input on
id=1000 
Nov 12 10:42:58 server2 slapd[714]: op tag 0x60, time 1384220578 
Nov 12 10:42:58 server2 slapd[714]: daemon: activity on 1 descriptor 
Nov 12 10:42:58 server2 slapd[714]: daemon: activity on:
Nov 12 10:42:58 server2 slapd[714]:  
Nov 12 10:42:58 server2 slapd[714]: daemon: epoll: listen=7 active_threads=0
tvp=zero 
Nov 12 10:42:58 server2 slapd[714]: daemon: epoll: listen=8 active_threads=0
tvp=zero 
Nov 12 10:42:58 server2 slapd[714]: conn=1000 op=0 do_bind 
Nov 12 10:42:58 server2 slapd[714]: >>> dnPrettyNormal: <cn=XXXXXXXX> 
Nov 12 10:42:58 server2 slapd[714]: <<< dnPrettyNormal: <cn=XXXXXXXX>,
<cn=XXXXXXXX> 
Nov 12 10:42:58 server2 slapd[714]: conn=1000 op=0 BIND dn="cn=XXXXXXXX"
method=128 
Nov 12 10:42:58 server2 slapd[714]: do_bind: version=3 dn="cn=XXXXXXXX"
method=128 
Nov 12 10:42:58 server2 slapd[714]: ==> bdb_bind: dn: cn=XXXXXXXX 
Nov 12 10:42:58 server2 slapd[714]: conn=1000 op=0 BIND dn="cn=XXXXXXXX"
mech=SIMPLE ssf=0 
Nov 12 10:42:58 server2 slapd[714]: do_bind: v3 bind: "cn=XXXXXXXX" to
"cn=XXXXXXXX" 
Nov 12 10:42:58 server2 slapd[714]: send_ldap_result: conn=1000 op=0 p=3 
Nov 12 10:42:58 server2 slapd[714]: send_ldap_result: err=0 matched="" text="" 
Nov 12 10:42:58 server2 slapd[714]: send_ldap_response: msgid=1 tag=97 err=0 
Nov 12 10:42:58 server2 slapd[714]: daemon: activity on 1 descriptor 
Nov 12 10:42:58 server2 slapd[714]: daemon: activity on:
Nov 12 10:42:58 server2 slapd[714]:  10r
Nov 12 10:42:58 server2 slapd[714]:  
Nov 12 10:42:58 server2 slapd[714]: daemon: read active on 10 
Nov 12 10:42:58 server2 slapd[714]: daemon: epoll: listen=7 active_threads=0
tvp=zero 
Nov 12 10:42:58 server2 slapd[714]: daemon: epoll: listen=8 active_threads=0
tvp=zero 
Nov 12 10:42:58 server2 slapd[714]: conn=1000 op=0 RESULT tag=97 err=0 text= 
Nov 12 10:42:58 server2 slapd[714]: connection_get(10) 
Nov 12 10:42:58 server2 slapd[714]: connection_get(10): got connid=1000 
Nov 12 10:42:58 server2 slapd[714]: connection_read(10): checking for input on
id=1000 
Nov 12 10:42:58 server2 slapd[714]: op tag 0x63, time 1384220578 
Nov 12 10:42:58 server2 slapd[714]: daemon: activity on 1 descriptor 
Nov 12 10:42:58 server2 slapd[714]: daemon: activity on:
Nov 12 10:42:58 server2 slapd[714]:  
Nov 12 10:42:58 server2 slapd[714]: daemon: epoll: listen=7 active_threads=0
tvp=zero 
Nov 12 10:42:58 server2 slapd[714]: daemon: epoll: listen=8 active_threads=0
tvp=zero 
Nov 12 10:42:58 server2 slapd[714]: conn=1000 op=1 do_search 
Nov 12 10:42:58 server2 slapd[714]: >>> dnPrettyNormal:
<ou=People,dc=yyyy,dc=zz> 
Nov 12 10:42:58 server2 slapd[714]: <<< dnPrettyNormal:
<ou=People,dc=yyyy,dc=zz>, <ou=people,dc=yyyy,dc=zz> 
Nov 12 10:42:58 server2 slapd[714]: SRCH "ou=People,dc=yyyy,dc=zz" 2 0
Nov 12 10:42:58 server2 slapd[714]:     0 0 0 
Nov 12 10:42:58 server2 slapd[714]: begin get_filter 
Nov 12 10:42:58 server2 slapd[714]: OR 
Nov 12 10:42:58 server2 slapd[714]: begin get_filter_list 
Nov 12 10:42:58 server2 slapd[714]: begin get_filter 
Nov 12 10:42:58 server2 slapd[714]: EQUALITY 
Nov 12 10:42:58 server2 slapd[714]: end get_filter 0 
Nov 12 10:42:58 server2 slapd[714]: begin get_filter 
Nov 12 10:42:58 server2 slapd[714]: EQUALITY 
Nov 12 10:42:58 server2 slapd[714]: end get_filter 0 
Nov 12 10:42:58 server2 slapd[714]: begin get_filter 
Nov 12 10:42:58 server2 slapd[714]: AND 
Nov 12 10:42:58 server2 slapd[714]: begin get_filter_list 
Nov 12 10:42:58 server2 slapd[714]: begin get_filter 
Nov 12 10:42:58 server2 slapd[714]: EQUALITY 
Nov 12 10:42:58 server2 slapd[714]: end get_filter 0 
Nov 12 10:42:58 server2 slapd[714]: begin get_filter 
Nov 12 10:42:58 server2 slapd[714]: EQUALITY 
Nov 12 10:42:58 server2 slapd[714]: end get_filter 0 
Nov 12 10:42:58 server2 slapd[714]: end get_filter_list 
Nov 12 10:42:58 server2 slapd[714]: end get_filter 0 
Nov 12 10:42:58 server2 slapd[714]: end get_filter_list 
Nov 12 10:42:58 server2 slapd[714]: end get_filter 0 
Nov 12 10:42:58 server2 slapd[714]:     filter:
(|(mailLocalAddress=XXXXXXX@xxxx.yy.zz)(mailRoutingAddress=XXXXXXX@xxxx.yy.zz)(&(xxxXXXXAlias=XXXXXXX)(xxxXXXYYYYYYList=bb)))

Nov 12 10:42:58 server2 slapd[714]:     attrs:
Nov 12 10:42:58 server2 slapd[714]:  
Nov 12 10:42:58 server2 slapd[714]: conn=1000 op=1 SRCH
base="ou=People,dc=yyyy,dc=zz" scope=2 deref=0
filter="(|(mailLocalAddress=XXXXXXX@xxxx.yy.zz)(mailRoutingAddress=XXXXXXX@xxxx.yy.zz)(&(xxxXXXXAlias=XXXXXXX)(xxxXXXYYYYYYList=bb)))"

Nov 12 10:42:58 server2 slapd[714]: => bdb_search 
Nov 12 10:42:58 server2 slapd[714]: bdb_dn2entry("ou=people,dc=yyyy,dc=zz") 
Nov 12 10:42:58 server2 slapd[714]: => bdb_dn2id("dc=zz") 
Nov 12 10:42:58 server2 slapd[714]: <= bdb_dn2id: got id=0x1 
Nov 12 10:42:58 server2 slapd[714]: => bdb_dn2id("dc=yyyy,dc=zz") 
Nov 12 10:42:58 server2 slapd[714]: <= bdb_dn2id: got id=0x2 
Nov 12 10:42:58 server2 slapd[714]: => bdb_dn2id("ou=people,dc=yyyy,dc=zz") 
Nov 12 10:42:58 server2 slapd[714]: <= bdb_dn2id: got id=0x19 
Nov 12 10:42:58 server2 slapd[714]: entry_decode: "ou=People,dc=yyyy,dc=zz" 
Nov 12 10:42:58 server2 slapd[714]: <= entry_decode(ou=People,dc=yyyy,dc=zz) 
Nov 12 10:42:58 server2 slapd[714]: => access_allowed: search access to
"ou=People,dc=yyyy,dc=zz" "entry" requested 
Nov 12 10:42:58 server2 slapd[714]: <= root access granted 
Nov 12 10:42:58 server2 slapd[714]: => access_allowed: search access granted by
manage(=mwrscxd) 
Nov 12 10:42:58 server2 slapd[714]: search_candidates:
base="ou=people,dc=yyyy,dc=zz" (0x00000019) scope=2 
Nov 12 10:42:58 server2 slapd[714]: => bdb_dn2idl("ou=people,dc=yyyy,dc=zz") 
Nov 12 10:42:58 server2 slapd[714]: bdb_idl_fetch_key: @ou=people,dc=yyyy,dc=zz

Nov 12 10:42:58 server2 slapd[714]: <= bdb_dn2idl: id=-1 first=25 last=868130 
Nov 12 10:42:58 server2 slapd[714]: => bdb_filter_candidates 
Nov 12 10:42:58 server2 slapd[714]: 	AND 
Nov 12 10:42:58 server2 slapd[714]: => bdb_list_candidates 0xa0 
Nov 12 10:42:58 server2 slapd[714]: => bdb_filter_candidates 
Nov 12 10:42:58 server2 slapd[714]: 	OR 
Nov 12 10:42:58 server2 slapd[714]: => bdb_list_candidates 0xa1 
Nov 12 10:42:58 server2 slapd[714]: => bdb_filter_candidates 
Nov 12 10:42:58 server2 slapd[714]: 	EQUALITY 
Nov 12 10:42:58 server2 slapd[714]: => bdb_equality_candidates (objectClass) 
Nov 12 10:42:58 server2 slapd[714]: => key_read 
Nov 12 10:42:58 server2 slapd[714]: bdb_idl_fetch_key: [b49d1940] 
Nov 12 10:42:58 server2 slapd[714]: <= bdb_index_read: failed (-30989) 
Nov 12 10:42:58 server2 slapd[714]: <= bdb_equality_candidates: id=0, first=0,
last=0 
Nov 12 10:42:58 server2 slapd[714]: <= bdb_filter_candidates: id=0 first=0
last=0 
Nov 12 10:42:58 server2 slapd[714]: => bdb_filter_candidates 
Nov 12 10:42:58 server2 slapd[714]: 	OR 
Nov 12 10:42:58 server2 slapd[714]: => bdb_list_candidates 0xa1 
Nov 12 10:42:58 server2 slapd[714]: => bdb_filter_candidates 
Nov 12 10:42:58 server2 slapd[714]: 	EQUALITY 
Nov 12 10:42:58 server2 slapd[714]: => bdb_equality_candidates
(mailLocalAddress) 
Nov 12 10:42:58 server2 slapd[714]: => key_read 
Nov 12 10:42:58 server2 slapd[714]: bdb_idl_fetch_key: [6d316d9b] 
Nov 12 10:42:58 server2 slapd[714]: <= bdb_index_read 296 candidates 
Nov 12 10:42:58 server2 slapd[714]: <= bdb_equality_candidates: id=296,
first=296, last=858689 
Nov 12 10:42:58 server2 slapd[714]: <= bdb_filter_candidates: id=296 first=296
last=858689 
Nov 12 10:42:58 server2 slapd[714]: => bdb_filter_candidates 
Nov 12 10:42:58 server2 slapd[714]: 	EQUALITY 
Nov 12 10:42:58 server2 slapd[714]: => bdb_equality_candidates
(mailRoutingAddress) 
Nov 12 10:42:58 server2 slapd[714]: => key_read 
Nov 12 10:42:58 server2 slapd[714]: bdb_idl_fetch_key: [0afa05dc] 
Nov 12 10:42:58 server2 slapd[714]: <= bdb_index_read: failed (-30989) 
Nov 12 10:42:58 server2 slapd[714]: <= bdb_equality_candidates: id=0, first=0,
last=0 
Nov 12 10:42:58 server2 slapd[714]: <= bdb_filter_candidates: id=0 first=0
last=0 
Nov 12 10:42:58 server2 slapd[714]: => bdb_filter_candidates 
Nov 12 10:42:58 server2 slapd[714]: 	AND 
Nov 12 10:42:58 server2 slapd[714]: => bdb_list_candidates 0xa0 
Nov 12 10:42:58 server2 slapd[714]: => bdb_filter_candidates 
Nov 12 10:42:58 server2 slapd[714]: 	EQUALITY 
Nov 12 10:42:58 server2 slapd[714]: => bdb_equality_candidates (xxxXXXXAlias) 
Nov 12 10:42:58 server2 slapd[714]: => key_read 
Nov 12 10:42:58 server2 slapd[714]: bdb_idl_fetch_key: [a0867a62] 
Nov 12 10:42:58 server2 slapd[714]: <= bdb_index_read 2 candidates 
Nov 12 10:42:58 server2 slapd[714]: <= bdb_equality_candidates: id=2,
first=676406, last=676407 
Nov 12 10:42:58 server2 slapd[714]: <= bdb_filter_candidates: id=2 first=676406
last=676407 
Nov 12 10:42:58 server2 slapd[714]: => bdb_filter_candidates 
Nov 12 10:42:58 server2 slapd[714]: 	EQUALITY 
Nov 12 10:42:58 server2 slapd[714]: => bdb_equality_candidates
(xxxXXXYYYYYYList) 
Nov 12 10:42:58 server2 slapd[714]: => key_read 
Nov 12 10:42:58 server2 slapd[714]: bdb_idl_fetch_key: [d752aaac] 
Nov 12 10:42:58 server2 slapd[714]: <= bdb_index_read 239520 candidates 
Nov 12 10:42:58 server2 slapd[714]: <= bdb_equality_candidates: id=-1,
first=628610, last=868129 
Nov 12 10:42:58 server2 slapd[714]: <= bdb_filter_candidates: id=-1 first=628610
last=868129 
Nov 12 10:42:58 server2 slapd[714]: <= bdb_list_candidates: id=-1 first=676406
last=676407 
Nov 12 10:42:58 server2 slapd[714]: <= bdb_filter_candidates: id=-1 first=676406
last=676407 
Nov 12 10:42:58 server2 slapd[714]: <= bdb_list_candidates: id=-1 first=296
last=858689 
Nov 12 10:42:58 server2 slapd[714]: <= bdb_filter_candidates: id=-1 first=296
last=858689 
Nov 12 10:42:58 server2 slapd[714]: <= bdb_list_candidates: id=-1 first=296
last=858689 
Nov 12 10:42:58 server2 slapd[714]: <= bdb_filter_candidates: id=-1 first=296
last=858689 
Nov 12 10:42:58 server2 slapd[714]: <= bdb_list_candidates: id=-1 first=296
last=858689 
Nov 12 10:42:58 server2 slapd[714]: <= bdb_filter_candidates: id=-1 first=296
last=858689 
Nov 12 10:42:58 server2 slapd[714]: bdb_search_candidates: id=-1 first=296
last=858689 
Nov 12 10:42:58 server2 slapd[714]: entry_decode:
"mailRoutingAddress=000000130@xxxx-xxxxx.yyyy.zz,ou=People,dc=yyyy,dc=zz" 
Nov 12 10:42:58 server2 slapd[714]: <=
entry_decode(mailRoutingAddress=100000130@xxxx-xxxxx.yyyy.zz,ou=People,dc=yyyy,dc=zz)

Nov 12 10:42:58 server2 slapd[714]: =>
bdb_dn2id("mailRoutingAddress=000000130@xxxx-xxxxx.yyyy.zz,ou=people,dc=yyyy,dc=zz")

Nov 12 10:42:58 server2 slapd[714]: <= bdb_dn2id: got id=0x128 
Nov 12 10:42:58 server2 slapd[714]: => test_filter 
Nov 12 10:42:58 server2 slapd[714]:     OR 
Nov 12 10:42:58 server2 slapd[714]: => test_filter_or 
Nov 12 10:42:58 server2 slapd[714]: => test_filter 
Nov 12 10:42:58 server2 slapd[714]:     EQUALITY 
Nov 12 10:42:58 server2 slapd[714]: => access_allowed: search access to
"mailRoutingAddress=100000130@xxxx-xxxxx.yyyy.zz,ou=People,dc=yyyy,dc=zz"
"mailLocalAddress" requested 
Nov 12 10:42:58 server2 slapd[714]: <= root access granted 
Nov 12 10:42:58 server2 slapd[714]: => access_allowed: search access granted by
manage(=mwrscxd) 
Nov 12 10:42:58 server2 slapd[714]: <= test_filter 5 
Nov 12 10:42:58 server2 slapd[714]: => test_filter 
Nov 12 10:42:58 server2 slapd[714]:     EQUALITY 
Nov 12 10:42:58 server2 slapd[714]: => access_allowed: search access to
"mailRoutingAddress=100000130@xxxx-xxxxx.yyyy.zz,ou=People,dc=yyyy,dc=zz"
"mailRoutingAddress" requested 
Nov 12 10:42:58 server2 slapd[714]: <= root access granted 
Nov 12 10:42:58 server2 slapd[714]: => access_allowed: search access granted by
manage(=mwrscxd) 
Nov 12 10:42:58 server2 slapd[714]: <= test_filter 5 
Nov 12 10:42:58 server2 slapd[714]: => test_filter 
Nov 12 10:42:58 server2 slapd[714]:     AND 
Nov 12 10:42:58 server2 slapd[714]: => test_filter_and 
Nov 12 10:42:58 server2 slapd[714]: => test_filter 
Nov 12 10:42:58 server2 slapd[714]:     EQUALITY 
Nov 12 10:42:58 server2 slapd[714]: => access_allowed: search access to
"mailRoutingAddress=100000130@xxxx-xxxxx.yyyy.zz,ou=People,dc=yyyy,dc=zz"
"xxxXXXXAlias" requested 
Nov 12 10:42:58 server2 slapd[714]: <= root access granted 
Nov 12 10:42:58 server2 slapd[714]: => access_allowed: search access granted by
manage(=mwrscxd) 
Nov 12 10:42:58 server2 slapd[714]: <= test_filter 5 
Nov 12 10:42:58 server2 slapd[714]: <= test_filter_and 5 
Nov 12 10:42:58 server2 slapd[714]: <= test_filter 5 
Nov 12 10:42:58 server2 slapd[714]: <= test_filter_or 5 
Nov 12 10:42:58 server2 slapd[714]: <= test_filter 5 
Nov 12 10:42:58 server2 slapd[714]: bdb_search: 296 does not match filter 
Nov 12 10:42:58 server2 slapd[714]: entry_decode:
"gecos=000000130@xxxx-xxxxx.yyyy.zz,ou=Ftp,dc=yyyy,dc=zz" 
Nov 12 10:42:58 server2 slapd[714]: <=
entry_decode(gecos=000000130@xxxx-xxxxx.yyyy.zz,ou=Ftp,dc=yyyy,dc=zz) 
Nov 12 10:42:58 server2 slapd[714]: => bdb_dn2id("ou=ftp,dc=yyyy,dc=zz") 
Nov 12 10:42:58 server2 slapd[714]: <= bdb_dn2id: got id=0x24 
Nov 12 10:42:58 server2 slapd[714]: =>
bdb_dn2id("gecos=000000130@xxxx-xxxxx.yyyy.zz,ou=ftp,dc=yyyy,dc=zz") 
Nov 12 10:42:58 server2 slapd[714]: <= bdb_dn2id: got id=0x129 
Nov 12 10:42:58 server2 slapd[714]: bdb_search: 297 scope not okay 
Nov 12 10:42:58 server2 slapd[714]: entry_decode:
"mailRoutingAddress=000000131@xxxx-xxxxx.yyyy.zz,ou=People,dc=yyyy,dc=zz" 
Nov 12 10:42:58 server2 slapd[714]: <=
entry_decode(mailRoutingAddress=100000131@xxxx-xxxxx.yyyy.zz,ou=People,dc=yyyy,dc=zz)

Nov 12 10:42:58 server2 slapd[714]: =>
bdb_dn2id("mailRoutingAddress=000000131@xxxx-xxxxx.yyyy.zz,ou=people,dc=yyyy,dc=zz")

Nov 12 10:42:58 server2 slapd[714]: <= bdb_dn2id: got id=0x12a 
Nov 12 10:42:58 server2 slapd[714]: => test_filter 
Nov 12 10:42:58 server2 slapd[714]:     OR 
Nov 12 10:42:58 server2 slapd[714]: => test_filter_or 
Nov 12 10:42:58 server2 slapd[714]: => test_filter 
Nov 12 10:42:58 server2 slapd[714]:     EQUALITY 
Nov 12 10:42:58 server2 slapd[714]: => access_allowed: search access to
"mailRoutingAddress=100000131@xxxx-xxxxx.yyyy.zz,ou=People,dc=yyyy,dc=zz"
"mailLocalAddress" requested 
Nov 12 10:42:58 server2 slapd[714]: <= root access granted 
Nov 12 10:42:58 server2 slapd[714]: => access_allowed: search access granted by
manage(=mwrscxd) 
Nov 12 10:42:58 server2 slapd[714]: <= test_filter 5 
Nov 12 10:42:58 server2 slapd[714]: => test_filter 
Nov 12 10:42:58 server2 slapd[714]:     EQUALITY 
Nov 12 10:42:58 server2 slapd[714]: => access_allowed: search access to
"mailRoutingAddress=100000131@xxxx-xxxxx.yyyy.zz,ou=People,dc=yyyy,dc=zz"
"mailRoutingAddress" requested 
Nov 12 10:42:58 server2 slapd[714]: <= root access granted 
Nov 12 10:42:58 server2 slapd[714]: => access_allowed: search access granted by
manage(=mwrscxd) 
Nov 12 10:42:58 server2 slapd[714]: <= test_filter 5 
Nov 12 10:42:58 server2 slapd[714]: => test_filter 
Nov 12 10:42:58 server2 slapd[714]:     AND 
Nov 12 10:42:58 server2 slapd[714]: => test_filter_and 
Nov 12 10:42:58 server2 slapd[714]: => test_filter 
Nov 12 10:42:58 server2 slapd[714]:     EQUALITY 
Nov 12 10:42:58 server2 slapd[714]: => access_allowed: search access to
"mailRoutingAddress=100000131@xxxx-xxxxx.yyyy.zz,ou=People,dc=yyyy,dc=zz"
"xxxXXXXAlias" requested 
Nov 12 10:42:58 server2 slapd[714]: <= root access granted 
Nov 12 10:42:58 server2 slapd[714]: => access_allowed: search access granted by
manage(=mwrscxd) 
Nov 12 10:42:58 server2 slapd[714]: <= test_filter 5 
Nov 12 10:42:58 server2 slapd[714]: <= test_filter_and 5 
Nov 12 10:42:58 server2 slapd[714]: <= test_filter 5 
Nov 12 10:42:58 server2 slapd[714]: <= test_filter_or 5 
Nov 12 10:42:58 server2 slapd[714]: <= test_filter 5 
Nov 12 10:42:58 server2 slapd[714]: bdb_search: 298 does not match filter 
Nov 12 10:42:58 server2 slapd[714]: entry_decode:
"gecos=000000131@xxxx-xxxxx.yyyy.zz,ou=Ftp,dc=yyyy,dc=zz" 
Nov 12 10:42:58 server2 slapd[714]: <=
entry_decode(gecos=000000131@xxxx-xxxxx.yyyy.zz,ou=Ftp,dc=yyyy,dc=zz) 
Nov 12 10:42:58 server2 slapd[714]: =>
bdb_dn2id("gecos=000000131@xxxx-xxxxx.yyyy.zz,ou=ftp,dc=yyyy,dc=zz") 
Nov 12 10:42:58 server2 slapd[714]: <= bdb_dn2id: got id=0x12b 
Nov 12 10:42:58 server2 slapd[714]: bdb_search: 299 scope not okay
(omitted)




Best Regards,
Comment 1 Quanah Gibson-Mount 2013-11-12 03:24:27 UTC
--On Tuesday, November 12, 2013 3:09 AM +0000 
nishino-yoshinori@mxc.nes.nec.co.jp wrote:

> Full_Name: Yoshinori Nishino
> Version: 2.4.37
> OS: RedHatEL 5.5
> URL: ftp://ftp.openldap.org/incoming/
> Submission from: (NULL) (210.143.35.12)

back-bdb is deprecated, I suggest you use back-mdb instead.

--Quanah


--

Quanah Gibson-Mount
Architect - Server
Zimbra, Inc.
--------------------
Zimbra ::  the leader in open source messaging and collaboration

Comment 2 Quanah Gibson-Mount 2013-11-12 04:35:08 UTC
--On Tuesday, November 12, 2013 3:25 AM +0000 quanah@zimbra.com wrote:

> --On Tuesday, November 12, 2013 3:09 AM +0000
> nishino-yoshinori@mxc.nes.nec.co.jp wrote:
>
>> Full_Name: Yoshinori Nishino
>> Version: 2.4.37
>> OS: RedHatEL 5.5
>> URL: ftp://ftp.openldap.org/incoming/
>> Submission from: (NULL) (210.143.35.12)
>
> back-bdb is deprecated, I suggest you use back-mdb instead.

Hm, I see the same bit exists for back-mdb too at line 720ish.  Oh well. :P

--Quanah



--

Quanah Gibson-Mount
Architect - Server
Zimbra, Inc.
--------------------
Zimbra ::  the leader in open source messaging and collaboration

Comment 3 Howard Chu 2013-11-12 04:36:20 UTC
nishino-yoshinori@mxc.nes.nec.co.jp wrote:
> Full_Name: Yoshinori Nishino
> Version: 2.4.37
> OS: RedHatEL 5.5
> URL: ftp://ftp.openldap.org/incoming/
> Submission from: (NULL) (210.143.35.12)
>
>
> Dear sir,
>
>   OS:Red Hat Enterprise Linux 5.5(x86) (2.6.18-194.el5)
>   Version: 2.4.37 + BDB 4.4.20
>
> In our environment, the issue occurs that the ldapsearch command using the
> following filter always took about 15�`30 seconds.

> The response of the ldapsearch command becomes faster by modifying idl.c like
> that:
>
>    1087          /* If a range completely covers the list, the result is
>
>    1088           * just the list. If idmin to idmax is contiguous, just
>
>    1089           * turn it into a range.
>
>    1090           */
>    1091          if ( BDB_IDL_IS_RANGE( b )
>
>    1092                  && BDB_IDL_RANGE_FIRST( b ) <= BDB_IDL_RANGE_FIRST( a )
>
>    1093                  && BDB_IDL_RANGE_LAST( b ) >= BDB_IDL_RANGE_LAST( a ) )
> {
>    1094                  /* if (idmax - idmin + 1 == a[0])
>
>    1095                  {
>
>    1096                          a[0] = NOID;
>
>    1097                          a[1] = idmin;
>
>    1098                          a[2] = idmax;
>
>    1099                  }  */
>
>    1100                  goto done;
>
>    1101          }
>
> By the aforementioned modification, the search candidate set becomes (list-type:
> the number of elements=298, minID=296,maxID=858689).
>
> I think the line 1094-1099 part of idl.c seems to be a bug.
> The part seems to be implemented in order to just make "ids[]" smaller.
> If the reason is so, would you please consider fixing idl.c?

This is certainly no bug in idl_intersection(), it is an optimization that 
makes subsequent intersection operations faster. As such, your suggested fix 
is wrong.

If you want to suggest a fix, you should look at idl_union() instead.

-- 
   -- Howard Chu
   CTO, Symas Corp.           http://www.symas.com
   Director, Highland Sun     http://highlandsun.com/hyc/
   Chief Architect, OpenLDAP  http://www.openldap.org/project/

Comment 4 yos-nishino@ys.jp.nec.com 2013-11-12 06:46:18 UTC
Dear Quanah,

Thank you for your prompt reply.

 > back-bdb is deprecated, I suggest you use back-mdb instead.

Would you tell me why you recommend using back-mdb?
It's because the collision of the hash key in the bdb index
occurs more easily than in the mdb index?



Best Regards,
-- 
*********************************************
Yoshinori Nishino
NEC Soft, Ltd.
E-MAIL: nishino-yoshinori@mxc.nes.nec.co.jp
*********************************************

Comment 5 yos-nishino@ys.jp.nec.com 2013-11-12 07:58:15 UTC
Dear Howard,

Thank you for your prompt reply.

 >This is certainly no bug in idl_intersection(), it is an
 >optimizatio that makes subsequent intersection operations faster.
 >As such, your suggested fix is wrong.

I understood the line 1094-1099 part of idl.c was implemented
to optimize subsequent intersection oprations.
On the other hands, in this case,  bdb_idl_intersection(C,D)
(as I described before) returns the range-type candidate set
despite its having only two elements.
Then, by subsequent bdb_idl_union() with A (list-type: the number of 
elements=296, minID=296,maxID=858689), the candidate set becomes
very huge.
#bdb_idl_union() seems to change the candidate set into "range-type"
#if one of the two sets is a "range-type".

The impact of removing the optimization of bdb_idl_intersection() is
only that subsequent bdb_idl_intersection() oprations become slower
in certain cases?
If the aforementioned optimization becomes effective when the number of
the element is more than certain threshold number(ex.1024),
I would like to change bdb_idl_intersection() like that:

  ex)
  1091          if ( BDB_IDL_IS_RANGE( b ) 

  1092                  && BDB_IDL_RANGE_FIRST( b ) <= 
BDB_IDL_RANGE_FIRST( a ) 

  1093                  && BDB_IDL_RANGE_LAST( b ) >= 
BDB_IDL_RANGE_LAST( a ) ) { 

  1094                  if (idmax - idmin + 1 == a[0] && a[0] > 1024) 

  1095                  {
  1096                          a[0] = NOID; 

  1097                          a[1] = idmin; 

  1098                          a[2] = idmax; 

  1099                  }
  1100                  goto done; 

  1101          }

The issue occurs in the environment of our user and makes some trouble
because of the slow response of the ldapsearch.
So, I would like to find some fix of the issue.

 >If you want to suggest a fix, you should look at idl_union() instead.

Thank you for your advice.
I'll also try to check bdb_idl_union().

If you have other good idea to fix the issue, could you let me know?


Best Regards,
-- 
*********************************************
Yoshinori Nishino
NEC Soft, Ltd.
E-MAIL: nishino-yoshinori@mxc.nes.nec.co.jp
*********************************************

Comment 6 Quanah Gibson-Mount 2017-04-03 16:56:38 UTC
moved from Incoming to Software Bugs
Comment 7 Quanah Gibson-Mount 2020-03-20 17:45:24 UTC
Needs to be examined in the context of back-mdb, which has identical code in idl.c
Comment 8 Howard Chu 2020-09-03 11:47:18 UTC

*** This issue has been marked as a duplicate of issue 8868 ***