[Date Prev][Date Next] [Chronological] [Thread] [Top]

Re: proxy cache not really caching?

> 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

Anyone? I'm still clueless as to why this is happening.
Maybe I'm wrong and the logs are not a good indicator of
pcache performance? Which begs another question: Is there a command or
tool to monitor pcache's performance on proxy directory servers?

  Tyler