So I upgraded one of my test systems to 2.5, from 2.4. Doing a quick basic functionality check after the upgrade, I noticed that the performance on the upgraded system was significantly slower.
When the system was running 2.4, searching for my entry after a cold start took a little more than a second:
# time ldapsearch -x -b dc=cpp,dc=edu -H ldap://localhost/ uid=henson [...] dn: uid=henson,ou=user,dc=cpp,dc=edu [...] real 0m1.274s
and then subsequent searches generally less than 1/10th of a second:
real 0m0.010s real 0m0.009s real 0m0.007s real 0m0.006s real 0m0.010s real 0m0.008s
After upgrading to 2.5, searches, both cold start and subsequent, all took between 1.5-2 seconds:
real 0m1.513s real 0m1.523s real 0m1.308s real 0m1.874s real 0m2.150s real 0m1.406s
These are test systems, so really have no load. I noticed on the upgraded box that the CPU kept spiking to 100% every few seconds, and tracked it down to the load balancer health checks, which basically run:
# time /opt/symas/bin/ldapsearch -x -b dc=cpp,dc=edu '(objectClass=dcObject)'
On the upgraded system, this again takes about 1.5 seconds on every search:
real 0m1.483s
whereas on the 2.4 system, less than 1/10th of a second:
real 0m0.006s
It feels like something weird is going on with indexing. I turned on debugging, and this is what the index activity looked like on the 2.4 system:
Oct 21 15:27:06 ldap-dev-02 slapd[73033]: <= mdb_index_read: failed (-30798) Oct 21 15:27:06 ldap-dev-02 slapd[73033]: <= mdb_index_read: failed (-30798) Oct 21 15:27:12 ldap-dev-02 slapd[73033]: <= mdb_index_read: failed (-30798) Oct 21 15:27:12 ldap-dev-02 slapd[73033]: <= mdb_index_read 1 candidates
Which makes sense, there's only one of me :). On the other hand, on the upgraded system:
Oct 21 15:25:55 ldap-dev-03 slapd[42259]: <= mdb_index_read: failed (-30798) Oct 21 15:25:55 ldap-dev-03 slapd[42259]: <= mdb_index_read: failed (-30798) Oct 21 15:26:19 ldap-dev-03 slapd[42259]: <= mdb_index_read 132354 candidates
It looks like it's doing a full directory search for my entry? My configuration on the two systems is exactly the same, other than the changed paths for the 2.5 directory layout, removing the password policy schema include, and removing a pres index on automountInformation for the upgrade advice.
I have tested this both with using the existing binary mdb database files from the 2.4 system as well as dumping them out via slapcat, deleting the old ones, and creating new ones with the 2.5 version of slapadd, with the exact same behavior
Any thoughts on what might be going on or how I can debug it to track down exactly what is causing it? There was obviously a lot more debug info in the logs that I didn't include, but none of it jumped out to me as "smoking gun".
Thanks much…
Paul B. Henson wrote:
Any thoughts on what might be going on or how I can debug it to track down exactly what is causing it? There was obviously a lot more debug info in the logs that I didn't include, but none of it jumped out to me as "smoking gun".
Try the search again with -d5. Also include the lines showing which attribute it's checking in the index. e.g.:
6171fcb7.1be5a183 0x7f28b65fd640 search_candidates: base="dc=example,dc=com" (0x00000001) scope=2 6171fcb7.1be5b227 0x7f28b65fd640 => mdb_equality_candidates (objectClass) 6171fcb7.1be5cfe4 0x7f28b65fd640 => key_read 6171fcb7.1be5e088 0x7f28b65fd640 mdb_idl_fetch_key: [b49d1940] 6171fcb7.1be5faff 0x7f28b65fd640 <= mdb_index_read: failed (-30798) 6171fcb7.1be60a00 0x7f28b65fd640 <= mdb_equality_candidates: id=0, first=0, last=0 6171fcb7.1be61901 0x7f28b65fd640 => mdb_equality_candidates (sn) 6171fcb7.1be62f1a 0x7f28b65fd640 => key_read 6171fcb7.1be63fbf 0x7f28b65fd640 mdb_idl_fetch_key: [03915b69] 6171fcb7.1be659a9 0x7f28b65fd640 <= mdb_index_read 2 candidates 6171fcb7.1be66a94 0x7f28b65fd640 <= mdb_equality_candidates: id=2, first=8, last=9 6171fcb7.1be68cae 0x7f28b65fd640 mdb_search_candidates: id=2 first=8 last=9
Okay, here is the start of the search:
Oct 21 17:14:35 ldap-dev-03 slapd[4335]: conn=1001 op=1 do_search Oct 21 17:14:35 ldap-dev-03 slapd[4335]: >>> dnPrettyNormal: <dc=cpp,dc=edu> Oct 21 17:14:35 ldap-dev-03 slapd[4335]: <<< dnPrettyNormal: <dc=cpp,dc=edu>, <dc=cpp,dc=edu> Oct 21 17:14:35 ldap-dev-03 slapd[4335]: SRCH "dc=cpp,dc=edu" 2 0 0 0 0 Oct 21 17:14:35 ldap-dev-03 slapd[4335]: filter: (uid=henson) Oct 21 17:14:35 ldap-dev-03 slapd[4335]: attrs: Oct 21 17:14:35 ldap-dev-03 slapd[4335]: ==> limits_get: conn=1001 op=1 self="[anonymous]" this="dc=cpp,dc=edu" Oct 21 17:14:35 ldap-dev-03 slapd[4335]: <== limits_get: type=DN match=ANONYMOUS Oct 21 17:14:35 ldap-dev-03 slapd[4335]: => mdb_search Oct 21 17:14:35 ldap-dev-03 slapd[4335]: mdb_dn2entry("dc=cpp,dc=edu") Oct 21 17:14:35 ldap-dev-03 slapd[4335]: => mdb_dn2id("dc=cpp,dc=edu") Oct 21 17:14:35 ldap-dev-03 slapd[4335]: <= mdb_dn2id: got id=0x1 Oct 21 17:14:35 ldap-dev-03 slapd[4335]: => mdb_entry_decode: Oct 21 17:14:35 ldap-dev-03 slapd[4335]: <= mdb_entry_decode Oct 21 17:14:35 ldap-dev-03 slapd[4335]: search_candidates: base="dc=cpp,dc=edu" (0x00000001) scope=2 Oct 21 17:14:35 ldap-dev-03 slapd[4335]: => mdb_equality_candidates (objectClass) Oct 21 17:14:35 ldap-dev-03 slapd[4335]: => key_read Oct 21 17:14:35 ldap-dev-03 slapd[4335]: mdb_idl_fetch_key: [d913076f] Oct 21 17:14:35 ldap-dev-03 slapd[4335]: <= mdb_index_read 132354 candidates Oct 21 17:14:35 ldap-dev-03 slapd[4335]: <= mdb_equality_candidates: id=-1, first=3, last=132356 Oct 21 17:14:35 ldap-dev-03 slapd[4335]: mdb_search_candidates: id=-1 first=3 last=132356
It looks like is is looking for an objectClass match and then doing a full scan of my entire directory? These lines are followed by thousands and thousands of entries like:
Oct 21 17:14:35 ldap-dev-03 slapd[4335]: => mdb_entry_decode: Oct 21 17:14:35 ldap-dev-03 slapd[4335]: <= mdb_entry_decode Oct 21 17:14:35 ldap-dev-03 slapd[4335]: >>> dnNormalize: <dc=cpp,dc=edu> Oct 21 17:14:35 ldap-dev-03 slapd[4335]: <<< dnNormalize: <dc=cpp,dc=edu> Oct 21 17:14:35 ldap-dev-03 slapd[4335]: => mdb_entry_decode: Oct 21 17:14:35 ldap-dev-03 slapd[4335]: <= mdb_entry_decode Oct 21 17:14:35 ldap-dev-03 slapd[4335]: >>> dnNormalize: <dc=cpp,dc=edu> Oct 21 17:14:35 ldap-dev-03 slapd[4335]: <<< dnNormalize: <dc=cpp,dc=edu>
Then some "does not match filter" log lines start being interspersed, again for thousands and thousands of lines:
Oct 21 17:14:35 ldap-dev-03 slapd[4335]: mdb_search: 1063 does not match filter Oct 21 17:14:35 ldap-dev-03 slapd[4335]: => mdb_entry_decode: Oct 21 17:14:35 ldap-dev-03 slapd[4335]: <= mdb_entry_decode Oct 21 17:14:35 ldap-dev-03 slapd[4335]: mdb_search: 1064 does not match filter Oct 21 17:14:35 ldap-dev-03 slapd[4335]: => mdb_entry_decode: Oct 21 17:14:35 ldap-dev-03 slapd[4335]: <= mdb_entry_decode Oct 21 17:14:35 ldap-dev-03 slapd[4335]: mdb_search: 1065 does not match filter Oct 21 17:14:35 ldap-dev-03 slapd[4335]: => mdb_entry_decode: Oct 21 17:14:35 ldap-dev-03 slapd[4335]: <= mdb_entry_decode Oct 21 17:14:35 ldap-dev-03 slapd[4335]: mdb_search: 1066 does not match filter
Until eventually it seems to be done looking at the object class attribute?
Oct 21 17:14:51 ldap-dev-03 slapd[4335]: => mdb_search Oct 21 17:14:51 ldap-dev-03 slapd[4335]: mdb_dn2entry("dc=cpp,dc=edu") Oct 21 17:14:51 ldap-dev-03 slapd[4335]: => mdb_dn2id("dc=cpp,dc=edu") Oct 21 17:14:51 ldap-dev-03 slapd[4335]: <= mdb_dn2id: got id=0x1 Oct 21 17:14:51 ldap-dev-03 slapd[4335]: => mdb_entry_decode: Oct 21 17:14:51 ldap-dev-03 slapd[4335]: <= mdb_entry_decode Oct 21 17:14:51 ldap-dev-03 slapd[4335]: search_candidates: base="dc=cpp,dc=edu" (0x00000001) scope= 2 Oct 21 17:14:51 ldap-dev-03 slapd[4335]: => mdb_equality_candidates (objectClass) Oct 21 17:14:51 ldap-dev-03 slapd[4335]: => key_read Oct 21 17:14:51 ldap-dev-03 slapd[4335]: mdb_idl_fetch_key: [b49d1940] Oct 21 17:14:51 ldap-dev-03 slapd[4335]: <= mdb_index_read: failed (-30798) Oct 21 17:14:51 ldap-dev-03 slapd[4335]: <= mdb_equality_candidates: id=0, first=0, last=0
It then looks for uid, for which I guess the index seems to be functioning correctly, as only one record is returned:
Oct 21 17:14:51 ldap-dev-03 slapd[4335]: => mdb_equality_candidates (uid) Oct 21 17:14:51 ldap-dev-03 slapd[4335]: => key_read Oct 21 17:14:51 ldap-dev-03 slapd[4335]: mdb_idl_fetch_key: [6e61da89] Oct 21 17:14:51 ldap-dev-03 slapd[4335]: <= mdb_index_read 1 candidates Oct 21 17:14:51 ldap-dev-03 slapd[4335]: <= mdb_equality_candidates: id=1, first=3, last=3 Oct 21 17:14:51 ldap-dev-03 slapd[4335]: mdb_search_candidates: id=1 first=3 last=3 Oct 21 17:14:51 ldap-dev-03 slapd[4335]: => mdb_entry_decode: Oct 21 17:14:51 ldap-dev-03 slapd[4335]: <= mdb_entry_decode Oct 21 17:14:51 ldap-dev-03 slapd[4335]: >>> dnPrettyNormal: <dc=cpp,dc=edu> Oct 21 17:14:51 ldap-dev-03 slapd[4335]: <<< dnPrettyNormal: <dc=cpp,dc=edu>, <dc=cpp,dc=edu> Oct 21 17:14:51 ldap-dev-03 slapd[4335]: => mdb_search Oct 21 17:14:51 ldap-dev-03 slapd[4335]: mdb_dn2entry("dc=cpp,dc=edu") Oct 21 17:14:51 ldap-dev-03 slapd[4335]: => mdb_dn2id("dc=cpp,dc=edu") Oct 21 17:14:51 ldap-dev-03 slapd[4335]: <= mdb_dn2id: got id=0x1 Oct 21 17:14:51 ldap-dev-03 slapd[4335]: => mdb_entry_decode: Oct 21 17:14:51 ldap-dev-03 slapd[4335]: <= mdb_entry_decode
Then it does a lookup on memberUid, presumably because I am using the dynlist module to maintain memberOf:
dynlist-attrset cppEduPerson memberURL memberOf
and my entry has this attribute:
memberURL: ldap:///dc=cpp,dc=edu??sub?(memberUid=henson)
Oct 21 17:14:51 ldap-dev-03 slapd[4335]: search_candidates: base="dc=cpp,dc=edu" (0x00000001) scope=2 Oct 21 17:14:51 ldap-dev-03 slapd[4335]: => mdb_equality_candidates (memberUid) Oct 21 17:14:51 ldap-dev-03 slapd[4335]: => key_read Oct 21 17:14:51 ldap-dev-03 slapd[4335]: mdb_idl_fetch_key: [41e77321] Oct 21 17:14:51 ldap-dev-03 slapd[4335]: <= mdb_index_read 31 candidates Oct 21 17:14:51 ldap-dev-03 slapd[4335]: <= mdb_equality_candidates: id=31, first=1323, last=119410 Oct 21 17:14:51 ldap-dev-03 slapd[4335]: mdb_search_candidates: id=31 first=1323 last=119410
that index also seems to be right, returning only 31 entries, and then my entry seems to be returned to the client:
Oct 21 17:14:51 ldap-dev-03 slapd[4335]: send_ldap_result: conn=1001 op=1 p=3 Oct 21 17:14:51 ldap-dev-03 slapd[4335]: send_ldap_result: err=0 matched="" text="" Oct 21 17:14:51 ldap-dev-03 slapd[4335]: => send_search_entry: conn 1001 dn="uid=henson,ou=user,dc=c pp,dc=edu" Oct 21 17:14:51 ldap-dev-03 slapd[4335]: <= send_search_entry: conn 1001 exit. Oct 21 17:14:51 ldap-dev-03 slapd[4335]: send_ldap_result: conn=1001 op=1 p=3 Oct 21 17:14:51 ldap-dev-03 slapd[4335]: send_ldap_result: err=0 matched="" text=""
After that, however, it looks like all of the other entries in my directory get traversed:
Oct 21 17:14:51 ldap-dev-03 slapd[4335]: => mdb_entry_get: ndn: "uid=he,ou=user,dc=cpp,dc=edu" Oct 21 17:14:51 ldap-dev-03 slapd[4335]: => mdb_entry_get: oc: "(null)", at: "(null)" Oct 21 17:14:51 ldap-dev-03 slapd[4335]: mdb_dn2entry("uid=he,ou=user,dc=cpp,dc=edu") Oct 21 17:14:51 ldap-dev-03 slapd[4335]: => mdb_dn2id("uid=he,ou=user,dc=cpp,dc=edu") Oct 21 17:14:51 ldap-dev-03 slapd[4335]: <= mdb_dn2id: got id=0xb8c Oct 21 17:14:51 ldap-dev-03 slapd[4335]: => mdb_entry_decode: Oct 21 17:14:51 ldap-dev-03 slapd[4335]: <= mdb_entry_decode Oct 21 17:14:51 ldap-dev-03 slapd[4335]: mdb_entry_get: rc=0 Oct 21 17:14:51 ldap-dev-03 slapd[4335]: => mdb_entry_get: ndn: "uid=hu,ou=user,dc=cpp,dc=edu" Oct 21 17:14:51 ldap-dev-03 slapd[4335]: => mdb_entry_get: oc: "(null)", at: "(null)" Oct 21 17:14:51 ldap-dev-03 slapd[4335]: mdb_dn2entry("uid=hu,ou=user,dc=cpp,dc=edu") Oct 21 17:14:51 ldap-dev-03 slapd[4335]: => mdb_dn2id("uid=hu,ou=user,dc=cpp,dc=edu") Oct 21 17:14:51 ldap-dev-03 slapd[4335]: <= mdb_dn2id: got id=0xe17 Oct 21 17:14:51 ldap-dev-03 slapd[4335]: => mdb_entry_decode: Oct 21 17:14:51 ldap-dev-03 slapd[4335]: <= mdb_entry_decode Oct 21 17:14:51 ldap-dev-03 slapd[4335]: mdb_entry_get: rc=0 Oct 21 17:14:51 ldap-dev-03 slapd[4335]: => mdb_entry_get: ndn: "uid=li,ou=user,dc=cpp,dc=edu" [...] Oct 21 17:15:08 ldap-dev-03 slapd[4335]: => mdb_entry_get: ndn: "uid=ysabdelwahab,ou=user,dc=cpp,dc= edu" Oct 21 17:15:08 ldap-dev-03 slapd[4335]: => mdb_entry_get: oc: "(null)", at: "(null)" Oct 21 17:15:08 ldap-dev-03 slapd[4335]: mdb_dn2entry("uid=ysabdelwahab,ou=user,dc=cpp,dc=edu") Oct 21 17:15:08 ldap-dev-03 slapd[4335]: => mdb_dn2id("uid=ysabdelwahab,ou=user,dc=cpp,dc=edu") Oct 21 17:15:08 ldap-dev-03 slapd[4335]: <= mdb_dn2id: got id=0x1f4c8 Oct 21 17:15:08 ldap-dev-03 slapd[4335]: => mdb_entry_decode: Oct 21 17:15:08 ldap-dev-03 slapd[4335]: <= mdb_entry_decode Oct 21 17:15:08 ldap-dev-03 slapd[4335]: connection_get(20) Oct 21 17:15:08 ldap-dev-03 slapd[4335]: connection_get(20): got connid=1001 Oct 21 17:15:08 ldap-dev-03 slapd[4335]: connection_read(20): checking for input on id=1001 Oct 21 17:15:08 ldap-dev-03 slapd[4335]: op tag 0x42, time 1634861708 Oct 21 17:15:08 ldap-dev-03 slapd[4335]: ber_get_next on fd 20 failed errno=0 (Success) Oct 21 17:15:08 ldap-dev-03 slapd[4335]: conn=1001 op=2 do_unbind
And then the connection is closed. Comparing that to the same search on my 2.4 server:
Oct 21 17:33:16 ldap-dev-02 slapd[2389]: conn=1000 op=1 do_search Oct 21 17:33:16 ldap-dev-02 slapd[2389]: >>> dnPrettyNormal: <dc=cpp,dc=edu> Oct 21 17:33:16 ldap-dev-02 slapd[2389]: <<< dnPrettyNormal: <dc=cpp,dc=edu>, <dc=cpp,dc=edu> Oct 21 17:33:16 ldap-dev-02 slapd[2389]: SRCH "dc=cpp,dc=edu" 2 0 Oct 21 17:33:16 ldap-dev-02 slapd[2389]: 0 0 0 Oct 21 17:33:16 ldap-dev-02 slapd[2389]: filter: (uid=henson) Oct 21 17:33:16 ldap-dev-02 slapd[2389]: attrs: Oct 21 17:33:16 ldap-dev-02 slapd[2389]: Oct 21 17:33:16 ldap-dev-02 slapd[2389]: ==> limits_get: conn=1000 op=1 self="[anonymous]" this="dc=cpp,dc=edu" Oct 21 17:33:16 ldap-dev-02 slapd[2389]: <== limits_get: type=DN match=ANONYMOUS Oct 21 17:33:16 ldap-dev-02 slapd[2389]: => mdb_search Oct 21 17:33:16 ldap-dev-02 slapd[2389]: mdb_dn2entry("dc=cpp,dc=edu") Oct 21 17:33:16 ldap-dev-02 slapd[2389]: => mdb_dn2id("dc=cpp,dc=edu") Oct 21 17:33:16 ldap-dev-02 slapd[2389]: <= mdb_dn2id: got id=0x1 Oct 21 17:33:16 ldap-dev-02 slapd[2389]: => mdb_entry_decode: Oct 21 17:33:16 ldap-dev-02 slapd[2389]: <= mdb_entry_decode Oct 21 17:33:16 ldap-dev-02 slapd[2389]: search_candidates: base="dc=cpp,dc=edu" (0x00000001) scope=2 Oct 21 17:33:16 ldap-dev-02 slapd[2389]: => mdb_equality_candidates (objectClass) Oct 21 17:33:16 ldap-dev-02 slapd[2389]: => key_read Oct 21 17:33:16 ldap-dev-02 slapd[2389]: mdb_idl_fetch_key: [b49d1940] Oct 21 17:33:16 ldap-dev-02 slapd[2389]: <= mdb_index_read: failed (-30798) Oct 21 17:33:16 ldap-dev-02 slapd[2389]: <= mdb_equality_candidates: id=0, first=0, last=0
The search on objectClass doesn't seem to return any records? It just immediately jumps to the uid search:
Oct 21 17:33:16 ldap-dev-02 slapd[2389]: => mdb_equality_candidates (uid) Oct 21 17:33:16 ldap-dev-02 slapd[2389]: => key_read Oct 21 17:33:16 ldap-dev-02 slapd[2389]: mdb_idl_fetch_key: [b49d1940] Oct 21 17:33:16 ldap-dev-02 slapd[2389]: <= mdb_index_read: failed (-30798) Oct 21 17:33:16 ldap-dev-02 slapd[2389]: <= mdb_equality_candidates: id=0, first=0, last=0 Oct 21 17:33:16 ldap-dev-02 slapd[2389]: => mdb_equality_candidates (uid) Oct 21 17:33:16 ldap-dev-02 slapd[2389]: => key_read Oct 21 17:33:16 ldap-dev-02 slapd[2389]: mdb_idl_fetch_key: [6e61da89] Oct 21 17:33:16 ldap-dev-02 slapd[2389]: <= mdb_index_read 1 candidates
It finds my record, does the memberUid look up, and immediately returns it:
Oct 21 17:33:16 ldap-dev-02 slapd[2389]: send_ldap_result: conn=1000 op=1 p=3 Oct 21 17:33:16 ldap-dev-02 slapd[2389]: send_ldap_result: err=0 matched="" text="" Oct 21 17:33:16 ldap-dev-02 slapd[2389]: => send_search_entry: conn 1000 dn="uid=henson,ou=user,dc=cpp,dc=edu" Oct 21 17:33:16 ldap-dev-02 slapd[2389]: <= send_search_entry: conn 1000 exit. Oct 21 17:33:16 ldap-dev-02 slapd[2389]: send_ldap_result: conn=1000 op=1 p=3 Oct 21 17:33:16 ldap-dev-02 slapd[2389]: send_ldap_result: err=0 matched="" text="" Oct 21 17:33:16 ldap-dev-02 slapd[2389]: send_ldap_response: msgid=2 tag=101 err=0
After the record is returned, the connection is immediately closed without looking at anything else:
Oct 21 17:33:16 ldap-dev-02 slapd[2389]: connection_get(15) Oct 21 17:33:16 ldap-dev-02 slapd[2389]: connection_get(15): got connid=1000 Oct 21 17:33:16 ldap-dev-02 slapd[2389]: connection_read(15): checking for input on id=1000 Oct 21 17:33:16 ldap-dev-02 slapd[2389]: op tag 0x42, time 1634862796 Oct 21 17:33:16 ldap-dev-02 slapd[2389]: ber_get_next on fd 15 failed errno=0 (Success) Oct 21 17:33:16 ldap-dev-02 slapd[2389]: conn=1000 op=2 do_unbind Oct 21 17:33:16 ldap-dev-02 slapd[2389]: connection_close: conn=1000 sd=15
So it looks like there is something weird going on with objectClass? I do have an index on that:
index default eq index entryCSN,objectClass,reqEnd,reqResult,reqStart
My configuration between 2.4 and 2.5 is pretty much identical. Any idea why it might be fully traversing the directory looking for object class matches?
On 10/21/2021 4:55 PM, Howard Chu wrote:
Paul B. Henson wrote:
Any thoughts on what might be going on or how I can debug it to track down exactly what is causing it? There was obviously a lot more debug info in the logs that I didn't include, but none of it jumped out to me as "smoking gun".
Try the search again with -d5. Also include the lines showing which attribute it's checking in the index. e.g.:
6171fcb7.1be5a183 0x7f28b65fd640 search_candidates: base="dc=example,dc=com" (0x00000001) scope=2 6171fcb7.1be5b227 0x7f28b65fd640 => mdb_equality_candidates (objectClass) 6171fcb7.1be5cfe4 0x7f28b65fd640 => key_read 6171fcb7.1be5e088 0x7f28b65fd640 mdb_idl_fetch_key: [b49d1940] 6171fcb7.1be5faff 0x7f28b65fd640 <= mdb_index_read: failed (-30798) 6171fcb7.1be60a00 0x7f28b65fd640 <= mdb_equality_candidates: id=0, first=0, last=0 6171fcb7.1be61901 0x7f28b65fd640 => mdb_equality_candidates (sn) 6171fcb7.1be62f1a 0x7f28b65fd640 => key_read 6171fcb7.1be63fbf 0x7f28b65fd640 mdb_idl_fetch_key: [03915b69] 6171fcb7.1be659a9 0x7f28b65fd640 <= mdb_index_read 2 candidates 6171fcb7.1be66a94 0x7f28b65fd640 <= mdb_equality_candidates: id=2, first=8, last=9 6171fcb7.1be68cae 0x7f28b65fd640 mdb_search_candidates: id=2 first=8 last=9
Paul B. Henson wrote:
Okay, here is the start of the search:
Oct 21 17:14:35 ldap-dev-03 slapd[4335]: conn=1001 op=1 do_search Oct 21 17:14:35 ldap-dev-03 slapd[4335]: >>> dnPrettyNormal: <dc=cpp,dc=edu> Oct 21 17:14:35 ldap-dev-03 slapd[4335]: <<< dnPrettyNormal: <dc=cpp,dc=edu>, <dc=cpp,dc=edu> Oct 21 17:14:35 ldap-dev-03 slapd[4335]: SRCH "dc=cpp,dc=edu" 2 0 0 0 0 Oct 21 17:14:35 ldap-dev-03 slapd[4335]: filter: (uid=henson) Oct 21 17:14:35 ldap-dev-03 slapd[4335]: attrs: Oct 21 17:14:35 ldap-dev-03 slapd[4335]: ==> limits_get: conn=1001 op=1 self="[anonymous]" this="dc=cpp,dc=edu" Oct 21 17:14:35 ldap-dev-03 slapd[4335]: <== limits_get: type=DN match=ANONYMOUS Oct 21 17:14:35 ldap-dev-03 slapd[4335]: => mdb_search Oct 21 17:14:35 ldap-dev-03 slapd[4335]: mdb_dn2entry("dc=cpp,dc=edu") Oct 21 17:14:35 ldap-dev-03 slapd[4335]: => mdb_dn2id("dc=cpp,dc=edu") Oct 21 17:14:35 ldap-dev-03 slapd[4335]: <= mdb_dn2id: got id=0x1 Oct 21 17:14:35 ldap-dev-03 slapd[4335]: => mdb_entry_decode: Oct 21 17:14:35 ldap-dev-03 slapd[4335]: <= mdb_entry_decode Oct 21 17:14:35 ldap-dev-03 slapd[4335]: search_candidates: base="dc=cpp,dc=edu" (0x00000001) scope=2 Oct 21 17:14:35 ldap-dev-03 slapd[4335]: => mdb_equality_candidates (objectClass) Oct 21 17:14:35 ldap-dev-03 slapd[4335]: => key_read Oct 21 17:14:35 ldap-dev-03 slapd[4335]: mdb_idl_fetch_key: [d913076f] Oct 21 17:14:35 ldap-dev-03 slapd[4335]: <= mdb_index_read 132354 candidates Oct 21 17:14:35 ldap-dev-03 slapd[4335]: <= mdb_equality_candidates: id=-1, first=3, last=132356 Oct 21 17:14:35 ldap-dev-03 slapd[4335]: mdb_search_candidates: id=-1 first=3 last=132356
It looks like is is looking for an objectClass match and then doing a full scan of my entire directory? These lines are followed by thousands and thousands of entries like:
Then it does a lookup on memberUid, presumably because I am using the dynlist module to maintain memberOf:
dynlist-attrset cppEduPerson memberURL memberOf
and my entry has this attribute:
memberURL: ldap:///dc=cpp,dc=edu??sub?(memberUid=henson)
Then this is probably dynlist searching for objectclass=cppEduPerson.
You should change this configuration to use 2.5 dynlist's memberOf support.
Indexing is not broken.
My configuration between 2.4 and 2.5 is pretty much identical. Any idea why it might be fully traversing the directory looking for object class matches?
On 10/21/2021 4:55 PM, Howard Chu wrote:
Paul B. Henson wrote:
Any thoughts on what might be going on or how I can debug it to track down exactly what is causing it? There was obviously a lot more debug info in the logs that I didn't include, but none of it jumped out to me as "smoking gun".
Try the search again with -d5. Also include the lines showing which attribute it's checking in the index. e.g.:
6171fcb7.1be5a183 0x7f28b65fd640 search_candidates: base="dc=example,dc=com" (0x00000001) scope=2 6171fcb7.1be5b227 0x7f28b65fd640 => mdb_equality_candidates (objectClass) 6171fcb7.1be5cfe4 0x7f28b65fd640 => key_read 6171fcb7.1be5e088 0x7f28b65fd640 mdb_idl_fetch_key: [b49d1940] 6171fcb7.1be5faff 0x7f28b65fd640 <= mdb_index_read: failed (-30798) 6171fcb7.1be60a00 0x7f28b65fd640 <= mdb_equality_candidates: id=0, first=0, last=0 6171fcb7.1be61901 0x7f28b65fd640 => mdb_equality_candidates (sn) 6171fcb7.1be62f1a 0x7f28b65fd640 => key_read 6171fcb7.1be63fbf 0x7f28b65fd640 mdb_idl_fetch_key: [03915b69] 6171fcb7.1be659a9 0x7f28b65fd640 <= mdb_index_read 2 candidates 6171fcb7.1be66a94 0x7f28b65fd640 <= mdb_equality_candidates: id=2, first=8, last=9 6171fcb7.1be68cae 0x7f28b65fd640 mdb_search_candidates: id=2 first=8 last=9
On 10/21/2021 6:06 PM, Howard Chu wrote:
Then this is probably dynlist searching for objectclass=cppEduPerson.
You should change this configuration to use 2.5 dynlist's memberOf support.
I must have missed that, I wasn't aware of any new specific memberOf support in dynlist? I don't see anything mentioning that in the administration guide:
https://www.openldap.org/doc/admin25/guide.html#Dynamic%20Lists
I did find a reference to it in a release announcement:
https://www.openldap.org/software/release/announce.html
"dynlist can now generate (is)memberOf dynamically"
but it had no specifics as to how that was configured or what it did?
Ah, I see there is a mention of it in the man page, but sadly I don't quite understand it.
dynlist-attrset <group-oc> [<URI>] <URL-ad> [[<mapped-ad>:]<member-ad>[+<memberOf-ad[@<static-oc>[*]] ...]
The value group-oc is the name of the objectClass that triggers the dynamic expansion of the data.
The optional URI restricts expansion only to entries matching the DN, the scope and the filter portions of the URI.
The value URL-ad is the name of the attributeDescription that contains the URI that is expanded by the overlay; if none is present, no expansion occurs. If the intersection of the attributes requested by the search operation (or the asserted attribute for compares) and the attributes listed in the URI is empty, no expansion occurs for that specific URI. It must be a subtype of labeledURI.
The value member-ad is optional; if present, the overlay behaves as a dynamic group: this attribute will list the DN of the entries resulting from the internal search. In this case, the attrs portion of the URIs in the URL-ad attribute must be absent, and the DNs of all the entries resulting from the expansion of the URIs are listed as values of this attribute. Compares that assert the value of the member-ad attribute of entries with group-oc objectClass apply as if the DN of the entries resulting from the expansion of the URI were present in the group-oc entry as values of the member-ad attribute. If the optional memberOf-ad attribute is also specified, then it will be populated with the DNs of the dynamic groups that an entry is a member of. If the optional static-oc objectClass is also specified, then the memberOf attribute will also be populated with the DNs of the static groups that an entry is a member of.
It appears it still needs an object class to trigger it? And in my case, that object class would still be cppEduPerson? (IE, only trigger this dynamic expansion on objects that have that object class?) Right now my configuration again is:
dynlist-attrset cppEduPerson memberURL memberOf
My understanding of which says that for any search which returns an object of the object class "cppEduPerson", perform the search as indicated in the attribute "memberURL", which for me is:
memberURL: ldap:///dc=cpp,dc=edu??sub?(memberUid=henson)
and shove all the DN's that result from that search in the memberOf attribute. What exactly am I supposed to do differently to avail of this new support? And how would it remove the need for the reference to the cppEduPerson object class?
Indexing is not broken.
There was a question mark in my subject line, I was just guessing :). It is still though definitely a difference in behavior between 2.4 and 2.5, and I'm not understanding why? I don't see any mention of dynlist or memberOf in the upgrade guide:
https://www.openldap.org/doc/admin25/guide.html#Upgrading%20from%202.4.x
Is my current configuration under 2.4 "broken but happens to work"?
Thanks…
On 10/21/2021 6:06 PM, Howard Chu wrote:
You should change this configuration to use 2.5 dynlist's memberOf support.
Ah, it seems I stupidly didn't look at the examples at the bottom of the man page 8-/.
I'm not using any dynamic groups, so I guess the example relevant to me is:
dynlist-attrset groupOfURLs memberURL member+memberOf@groupOfNames
which is described as "This example extends the dynamic memberOf feature to add the memberOf attribute to all the members of both static and dynamic groups".
I don't have any dynamic groups, so no objects with the class groupOfURLs will contain a memberURL attribute. So what exactly would this do? Hmm. I tried it and it seems to work. Wow, you can even search by memberOf now, you couldn't do that before, nice.
How does this get triggered? Previously, if I searched for a user, it would match on the object class for the user and expand the memberURL dynamically, filling in the memberOf attribute. What makes the overlay add in the attributes when I search for a user, as the group isn't referenced? Perhaps some source code spelunking is in order :).
This appears to solve my problem, but I am still curious why the config that worked fine under 2.4 blew up under 2.5.
Thanks much...
openldap-technical@openldap.org
-
Howard Chu -
Paul B. Henson