Hello, I've been running my openldap 2.4 proxy directory server using back_ldap and pcache in front of two masters for a few days and have been a little confused about why I'm not getting more "QUERY ANSWERED" messages in the logs considering all the "QUERY CACHED" messages. According to the script I wrote to parse the log file for certain key words, I'm seeing data like this:
******************************* QUERIES ANSWERED: 26901 QUERIES NOT ANSWERED: 142386 QUERIES CACHEABLE: 114491 QUERIES NOT CACHEABLE: 27895 ------------------------------- TOTAL QUERIES: 169287 QUERIES ADDED: 114080 QUERIES STORED: 7 QUERY HIT: %15.8907653866 *******************************
As you can see my templates are catching a good majority of the queries and they appear to be added to cache. For example I see messages like this: 'Added query expires at 1244899436 (NEGATIVE)' But even though I've tried bumping the ttl up, I'm still seeing a lot of QUERY NOT ANSWERABLE messages fly by about queries that should have been in cache before. For example, this snippet below appears to cache querystr '(&(objectClass=posixGroup)(memberUid=xfs))' but then one query later the exact same query comes up and it says its not answerable and adds it to cache again.
Jun 13 09:08:56 directory-proxy slapd2.4[20842]: conn=99 op=1658 SRCH base="dc=castlebranch,dc=com" scope=2 deref=0 filter="(&(objectClass=posixGroup)(memberUid=xfs))" Jun 13 09:08:56 directory-proxy slapd2.4[20842]: conn=99 op=1658 SRCH attr=gidNumber Jun 13 09:08:56 directory-proxy slapd2.4[20842]: query template of incoming query = (&(objectClass=)(memberUid=)) Jun 13 09:08:56 directory-proxy slapd2.4[20842]: Entering QC, querystr = (&(objectClass=posixGroup)(memberUid=xfs)) Jun 13 09:08:56 directory-proxy slapd2.4[20842]: Lock QC index = 0x8354560 Jun 13 09:08:56 directory-proxy slapd2.4[20842]: Not answerable: Unlock QC index=0x8354560 Jun 13 09:08:56 directory-proxy slapd2.4[20842]: QUERY NOT ANSWERABLE Jun 13 09:08:56 directory-proxy slapd2.4[20842]: QUERY CACHEABLE Jun 13 09:08:56 directory-proxy slapd2.4[20842]: Added query expires at 1244899436 (NEGATIVE) Jun 13 09:08:56 directory-proxy slapd2.4[20842]: Lock AQ index = 0x8354560 Jun 13 09:08:56 directory-proxy slapd2.4[20842]: TEMPLATE 0x8354560 QUERIES++ 1 Jun 13 09:08:56 directory-proxy slapd2.4[20842]: Unlock AQ index = 0x8354560 Jun 13 09:08:56 directory-proxy slapd2.4[20842]: conn=99 op=1658 SEARCH RESULT tag=101 err=0 nentries=0 text= Jun 13 09:08:56 directory-proxy slapd2.4[20842]: conn=86 op=1661 SRCH base="dc=castlebranch,dc=com" scope=2 deref=0 filter="(&(objectClass=posixAccount)(uid=xfs))" Jun 13 09:08:56 directory-proxy slapd2.4[20842]: query template of incoming query = (&(objectClass=)(uid=)) Jun 13 09:08:56 directory-proxy slapd2.4[20842]: QUERY NOT ANSWERABLE Jun 13 09:08:56 directory-proxy slapd2.4[20842]: QUERY NOT CACHEABLE Jun 13 09:08:56 directory-proxy slapd2.4[20842]: conn=86 op=1661 SEARCH RESULT tag=101 err=0 nentries=0 text= Jun 13 09:08:56 directory-proxy slapd2.4[20842]: conn=86 op=1662 SRCH base="dc=castlebranch,dc=com" scope=2 deref=0 filter="(&(objectClass=posixGroup)(memberUid=xfs))" Jun 13 09:08:56 directory-proxy slapd2.4[20842]: conn=86 op=1662 SRCH attr=gidNumber Jun 13 09:08:56 directory-proxy slapd2.4[20842]: query template of incoming query = (&(objectClass=)(memberUid=)) Jun 13 09:08:56 directory-proxy slapd2.4[20842]: Entering QC, querystr = (&(objectClass=posixGroup)(memberUid=xfs)) Jun 13 09:08:56 directory-proxy slapd2.4[20842]: Lock QC index = 0x8354560 Jun 13 09:08:56 directory-proxy slapd2.4[20842]: Not answerable: Unlock QC index=0x8354560 Jun 13 09:08:56 directory-proxy slapd2.4[20842]: QUERY NOT ANSWERABLE Jun 13 09:08:56 directory-proxy slapd2.4[20842]: QUERY CACHEABLE Jun 13 09:08:56 directory-proxy slapd2.4[20842]: Added query expires at 1244899436 (NEGATIVE) Jun 13 09:08:56 directory-proxy slapd2.4[20842]: Lock AQ index = 0x8354560 Jun 13 09:08:56 directory-proxy slapd2.4[20842]: TEMPLATE 0x8354560 QUERIES++ 1 Jun 13 09:08:56 directory-proxy slapd2.4[20842]: Unlock AQ index = 0x8354560
According to the logs I currently have 7 cached queries and about a %15.8 hit rate which seems ridiculous given all the 'added query' messages I'm getting. Is there something wrong with my caching engine on the directory server or am I missing something with how the caching mechanism works?
Thanks, Tyler