[Date Prev][Date Next] [Chronological] [Thread] [Top]
Simple paging causes certain searches to not use index?

To: openldap-software@OpenLDAP.org
Subject: Simple paging causes certain searches to not use index?
From: "Armbrust, Daniel C." <Armbrust.Daniel@mayo.edu>
Date: Mon, 12 Apr 2004 10:29:02 -0500
I'm using openldap 2.2.7 with the bdb backend.  

I have a large database where one of the structures looks like this:

dc=codingSchemes,codingScheme=aCodingScheme,dc=relations,association=currentRelation

This particular association contains a large number of entries.. Probably 100,000+.

When I browse to this node in a ldap viewer with simple paging disabled, and a limit of 30, it works properly.  I get 30 results instantly.  If I enable simple paging, it seems to not use (or improperly use) the database indexes, and the slapd starts churning through every entry in the database, and never returns (well, it probably would, but it would take hours) The debug log looks like this when I have simple paging turned off:


connection_get(9): got connid=0
connection_read(9): checking for input on id=0
ber_get_next
ber_get_next: tag 0x30 len 146 contents:
ber_get_next
ber_get_next on fd 9 failed errno=11 (Resource temporarily unavailable)
do_search
ber_scanf fmt ({miiiib) ber:
>>> dnPrettyNormal: <association=hasSubtype,dc=relations,codingScheme=SNOMED-CT,dc=codingSchemes,service=SCT,dc=HL7,dc=org>
=> ldap_bv2dn(association=hasSubtype,dc=relations,codingScheme=SNOMED-CT,dc=codingSchemes,service=SCT,dc=HL7,dc=org,0)
<= ldap_bv2dn(association=hasSubtype,dc=relations,codingScheme=SNOMED-CT,dc=codingSchemes,service=SCT,dc=HL7,dc=org,0)=0
=> ldap_dn2bv(272)
<= ldap_dn2bv(association=hasSubtype,dc=relations,codingScheme=SNOMED-CT,dc=codingSchemes,service=SCT,dc=HL7,dc=org,272)=0
=> ldap_dn2bv(272)
<= ldap_dn2bv(association=hasSubtype,dc=relations,codingScheme=SNOMED-CT,dc=codingschemes,service=sct,dc=hl7,dc=org,272)=0
<<< dnPrettyNormal: <association=hasSubtype,dc=relations,codingScheme=SNOMED-CT,dc=codingSchemes,service=SCT,dc=HL7,dc=org>, <association=hasSubtype,dc=relations,codingScheme=SNOMED-CT,dc=codingschemes,service=sct,dc=hl7,dc=org>
ber_scanf fmt (m) ber:
ber_scanf fmt ({M}}) ber:
=> bdb_search
bdb_dn2entry("association=hasSubtype,dc=relations,codingScheme=SNOMED-CT,dc=codingschemes,service=sct,dc=hl7,dc=org")
=> send_search_entry: dn="association=hasSubtype,dc=relations,codingScheme=SNOMED-CT,dc=codingSchemes,service=SCT,dc=HL7,dc=org"
ber_flush: 305 bytes to sd 9
<= send_search_entry
send_ldap_result: conn=0 op=9 p=3
send_ldap_response: msgid=101 tag=101 err=0
ber_flush: 14 bytes to sd 9
connection_get(9): got connid=0
connection_read(9): checking for input on id=0
ber_get_next
ber_get_next: tag 0x30 len 151 contents:
ber_get_next
ber_get_next on fd 9 failed errno=11 (Resource temporarily unavailable)
do_search
ber_scanf fmt ({miiiib) ber:
>>> dnPrettyNormal: <association=hasSubtype,dc=relations,codingScheme=SNOMED-CT,dc=codingSchemes,service=SCT,dc=HL7,dc=org>
=> ldap_bv2dn(association=hasSubtype,dc=relations,codingScheme=SNOMED-CT,dc=codingSchemes,service=SCT,dc=HL7,dc=org,0)
<= ldap_bv2dn(association=hasSubtype,dc=relations,codingScheme=SNOMED-CT,dc=codingSchemes,service=SCT,dc=HL7,dc=org,0)=0
=> ldap_dn2bv(272)
<= ldap_dn2bv(association=hasSubtype,dc=relations,codingScheme=SNOMED-CT,dc=codingSchemes,service=SCT,dc=HL7,dc=org,272)=0
=> ldap_dn2bv(272)
<= ldap_dn2bv(association=hasSubtype,dc=relations,codingScheme=SNOMED-CT,dc=codingschemes,service=sct,dc=hl7,dc=org,272)=0
<<< dnPrettyNormal: <association=hasSubtype,dc=relations,codingScheme=SNOMED-CT,dc=codingSchemes,service=SCT,dc=HL7,dc=org>, <association=hasSubtype,dc=relations,codingScheme=SNOMED-CT,dc=codingschemes,service=sct,dc=hl7,dc=org>
ber_scanf fmt (m) ber:
ber_scanf fmt ({M}}) ber:
=> bdb_search
bdb_dn2entry("association=hasSubtype,dc=relations,codingScheme=SNOMED-CT,dc=codingschemes,service=sct,dc=hl7,dc=org")
search_candidates: base="association=hasSubtype,dc=relations,codingScheme=SNOMED-CT,dc=codingschemes,service=sct,dc=hl7,dc=org" (0x0018a2c9) scope=1
=> bdb_dn2idl( "association=hasSubtype,dc=relations,codingScheme=SNOMED-CT,dc=codingschemes,service=sct,dc=hl7,dc=org" )
<= bdb_dn2idl: id=-1 first=1843895 last=3599617
=> bdb_presence_candidates (objectClass)
bdb_search_candidates: id=-1 first=1843895 last=3599617
entry_decode: "sourceConcept=31384009,association=hasSubtype,dc=relations,codingScheme=SNOMED-CT,dc=codingSchemes,service=SCT,dc=HL7,dc=org"
<= entry_decode(sourceConcept=31384009,association=hasSubtype,dc=relations,codingScheme=SNOMED-CT,dc=codingSchemes,service=SCT,dc=HL7,dc=org)
=> bdb_dn2id( "sourceConcept=31384009,association=hasSubtype,dc=relations,codingScheme=SNOMED-CT,dc=codingschemes,service=sct,dc=hl7,dc=org" )
<= bdb_dn2id: got id=0x001c22b7
=> send_search_entry: dn="sourceConcept=31384009,association=hasSubtype,dc=relations,codingScheme=SNOMED-CT,dc=codingSchemes,service=SCT,dc=HL7,dc=org" (attrsOnly)
ber_flush: 137 bytes to sd 9
<= send_search_entry
entry_decode: "link=sourceLink,sourceConcept=31384009,association=hasSubtype,dc=relations,codingScheme=SNOMED-CT,dc=codingSchemes,service=SCT,dc=HL7,dc=org"
<= entry_decode(link=sourceLink,sourceConcept=31384009,association=hasSubtype,dc=relations,codingScheme=SNOMED-CT,dc=codingSchemes,service=SCT,dc=HL7,dc=org)
=> bdb_dn2id( "link=sourcelink,sourceConcept=31384009,association=hasSubtype,dc=relations,codingScheme=SNOMED-CT,dc=codingschemes,service=sct,dc=hl7,dc=org" )
<= bdb_dn2id: got id=0x001c22b8
bdb_search: 1843896 scope not okay
entry_decode: "targetConcept=3458000,sourceConcept=31384009,association=hasSubtype,dc=relations,codingScheme=SNOMED-CT,dc=codingSchemes,service=SCT,dc=HL7,dc=org"
<= entry_decode(targetConcept=3458000,sourceConcept=31384009,association=hasSubtype,dc=relations,codingScheme=SNOMED-CT,dc=codingSchemes,service=SCT,dc=HL7,dc=org)
=> bdb_dn2id( "targetConcept=3458000,sourceConcept=31384009,association=hasSubtype,dc=relations,codingScheme=SNOMED-CT,dc=codingschemes,service=sct,dc=hl7,dc=org" )
<= bdb_dn2id: got id=0x001c22b9
.........


Now, if I enable simple paging the log looks like this:


connection_get(9): got connid=0
connection_read(9): checking for input on id=0
ber_get_next
ber_get_next: tag 0x30 len 146 contents:
ber_get_next
ber_get_next on fd 9 failed errno=11 (Resource temporarily unavailable)
do_search
ber_scanf fmt ({miiiib) ber:
>>> dnPrettyNormal: <association=hasSubtype,dc=relations,codingScheme=SNOMED-CT,dc=codingSchemes,service=SCT,dc=HL7,dc=org>
=> ldap_bv2dn(association=hasSubtype,dc=relations,codingScheme=SNOMED-CT,dc=codingSchemes,service=SCT,dc=HL7,dc=org,0)
<= ldap_bv2dn(association=hasSubtype,dc=relations,codingScheme=SNOMED-CT,dc=codingSchemes,service=SCT,dc=HL7,dc=org,0)=0
=> ldap_dn2bv(272)
<= ldap_dn2bv(association=hasSubtype,dc=relations,codingScheme=SNOMED-CT,dc=codingSchemes,service=SCT,dc=HL7,dc=org,272)=0
=> ldap_dn2bv(272)
<= ldap_dn2bv(association=hasSubtype,dc=relations,codingScheme=SNOMED-CT,dc=codingschemes,service=sct,dc=hl7,dc=org,272)=0
<<< dnPrettyNormal: <association=hasSubtype,dc=relations,codingScheme=SNOMED-CT,dc=codingSchemes,service=SCT,dc=HL7,dc=org>, <association=hasSubtype,dc=relations,codingScheme=SNOMED-CT,dc=codingschemes,service=sct,dc=hl7,dc=org>
ber_scanf fmt (m) ber:
ber_scanf fmt ({M}}) ber:
=> bdb_search
bdb_dn2entry("association=hasSubtype,dc=relations,codingScheme=SNOMED-CT,dc=codingschemes,service=sct,dc=hl7,dc=org")
=> send_search_entry: dn="association=hasSubtype,dc=relations,codingScheme=SNOMED-CT,dc=codingSchemes,service=SCT,dc=HL7,dc=org"
ber_flush: 305 bytes to sd 9
<= send_search_entry
send_ldap_result: conn=0 op=9 p=3
send_ldap_response: msgid=60 tag=101 err=0
ber_flush: 14 bytes to sd 9
connection_get(9): got connid=0
connection_read(9): checking for input on id=0
ber_get_next
ber_get_next: tag 0x30 len 254 contents:
ber_get_next
ber_get_next on fd 9 failed errno=11 (Resource temporarily unavailable)
do_search
ber_scanf fmt ({miiiib) ber:
>>> dnPrettyNormal: <association=hasSubtype,dc=relations,codingScheme=SNOMED-CT,dc=codingSchemes,service=SCT,dc=HL7,dc=org>
=> ldap_bv2dn(association=hasSubtype,dc=relations,codingScheme=SNOMED-CT,dc=codingSchemes,service=SCT,dc=HL7,dc=org,0)
<= ldap_bv2dn(association=hasSubtype,dc=relations,codingScheme=SNOMED-CT,dc=codingSchemes,service=SCT,dc=HL7,dc=org,0)=0
=> ldap_dn2bv(272)
<= ldap_dn2bv(association=hasSubtype,dc=relations,codingScheme=SNOMED-CT,dc=codingSchemes,service=SCT,dc=HL7,dc=org,272)=0
=> ldap_dn2bv(272)
<= ldap_dn2bv(association=hasSubtype,dc=relations,codingScheme=SNOMED-CT,dc=codingschemes,service=sct,dc=hl7,dc=org,272)=0
<<< dnPrettyNormal: <association=hasSubtype,dc=relations,codingScheme=SNOMED-CT,dc=codingSchemes,service=SCT,dc=HL7,dc=org>, <association=hasSubtype,dc=relations,codingScheme=SNOMED-CT,dc=codingschemes,service=sct,dc=hl7,dc=org>
ber_scanf fmt (m) ber:
ber_scanf fmt ({M}}) ber:
=> get_ctrls
ber_scanf fmt ({m) ber:
ber_scanf fmt (b) ber:
ber_scanf fmt (m) ber:
=> get_ctrls: oid="1.2.840.113556.1.4.473" (noncritical)
ber_scanf fmt ({m) ber:
ber_scanf fmt (b) ber:
ber_scanf fmt (m) ber:
=> get_ctrls: oid="1.2.840.113556.1.4.319" (critical)
ber_scanf fmt ({im}) ber:
<= get_ctrls: n=2 rc=0 err=""
=> bdb_search
bdb_dn2entry("association=hasSubtype,dc=relations,codingScheme=SNOMED-CT,dc=codingschemes,service=sct,dc=hl7,dc=org")
search_candidates: base="association=hasSubtype,dc=relations,codingScheme=SNOMED-CT,dc=codingschemes,service=sct,dc=hl7,dc=org" (0x0018a2c9) scope=1
=> bdb_dn2idl( "association=hasSubtype,dc=relations,codingScheme=SNOMED-CT,dc=codingschemes,service=sct,dc=hl7,dc=org" )
<= bdb_dn2idl: id=-1 first=1843895 last=3599617
=> bdb_presence_candidates (objectClass)
bdb_search_candidates: id=-1 first=1843895 last=3599617
bdb_search: 1 scope not okay
bdb_search: 2 scope not okay
bdb_search: 3 scope not okay
bdb_search: 4 scope not okay
bdb_search: 5 scope not okay
entry_decode: "conceptCode=101009,dc=concepts,codingScheme=SNOMED-CT,dc=codingSchemes,service=SCT,dc=HL7,dc=org"
<= entry_decode(conceptCode=101009,dc=concepts,codingScheme=SNOMED-CT,dc=codingSchemes,service=SCT,dc=HL7,dc=org)
=> bdb_dn2id( "conceptCode=101009,dc=concepts,codingScheme=SNOMED-CT,dc=codingschemes,service=sct,dc=hl7,dc=org" )
<= bdb_dn2id: got id=0x00000006
bdb_search: 6 scope not okay
entry_decode: "conceptCode=102002,dc=concepts,codingScheme=SNOMED-CT,dc=codingSchemes,service=SCT,dc=HL7,dc=org"
<= entry_decode(conceptCode=102002,dc=concepts,codingScheme=SNOMED-CT,dc=codingSchemes,service=SCT,dc=HL7,dc=org)
=> bdb_dn2id( "conceptCode=102002,dc=concepts,codingScheme=SNOMED-CT,dc=codingschemes,service=sct,dc=hl7,dc=org" )
<= bdb_dn2id: got id=0x00000007
bdb_search: 7 scope not okay
entry_decode: "conceptCode=103007,dc=concepts,codingScheme=SNOMED-CT,dc=codingSchemes,service=SCT,dc=HL7,dc=org"
<= entry_decode(conceptCode=103007,dc=concepts,codingScheme=SNOMED-CT,dc=codingSchemes,service=SCT,dc=HL7,dc=org)
=> bdb_dn2id( "conceptCode=103007,dc=concepts,codingScheme=SNOMED-CT,dc=codingschemes,service=sct,dc=hl7,dc=org" )
<= bdb_dn2id: got id=0x00000008
bdb_search: 8 scope not okay
....


The only difference between these two logs is the part where the controls were put in - and then at the end, the first log shows the server doing the right thing, getting results to return.  The second log shows the server churning through entries that have nothing to do with the search I made (notice the path) and returning scope not okay, over and over again..

Can anyone give me an idea what is going on here?  To add fun to the debug process, this doesn't happen on all of my databases - and it doesn't happen on all of the nodes in the database - other nodes that also have a large amount of entries work fine with paging (ignoring the random breakages I reported the other day)

I'll attempt to get this problem to recreate itself with a reasonably sized database, but I don't have one yet....

Dan
Follow-Ups:
- RE: Simple paging causes certain searches to not use index?
  - From: "Howard Chu" <hyc@highlandsun.com>
Prev by Date: Road Map : improved scalability - how to proceed ?
Next by Date: RE: Road Map : improved scalability - how to proceed ?
Index(es):
- Chronological
- Thread