[Date Prev][Date Next] [Chronological] [Thread] [Top]
Simple paging causes certain searches to not use index? (ITS#3076)

To: openldap-its@OpenLDAP.org
Subject: Simple paging causes certain searches to not use index? (ITS#3076)
From: daniel.armbrust@mayo.edu
Date: Mon, 12 Apr 2004 16:51:12 GMT
Full_Name: Daniel Armbrust
Version: 2.2.7
OS: Redhat 9
URL: 
Submission from: (NULL) (129.176.151.21)


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 as I try to expand the hasSubtype node:


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..

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 on the mailing list the other day - I'm going to examine
the logs for that error, I don't know if it related to this or not yet.  I'll
probably file another report on it.)

I'll attempt to get this problem to recreate itself with a reasonably sized
database, but I don't have one yet.... it only seems to happen on particular
nodes of very large databases.  I can post all of our custom schema information
if that would be helpful, and I'll see if I can come up with a small database
that has this problem to submit.

Dan
Prev by Date: Re: syncrepl root suffix issue when updatedn != rootdn (ITS#3056)
Next by Date: RE: Simple paging causes certain searches to not use index? (ITS#3076)
Index(es):
- Chronological
- Thread