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
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
On 22 Jun 2009, at 19:55, Tyler Gates wrote:
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:
I'm afraid I don't have any answers, but a couple of questions regarding the specifics....
Which version of openldap are you running?
Can you include the proxy-cache configuration from your slapd conf file?
Cheers Toby
On 22 Jun 2009, at 19:55, Tyler Gates wrote:
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:
I'm afraid I don't have any answers, but a couple of questions regarding the specifics....
Which version of openldap are you running?
Can you include the proxy-cache configuration from your slapd conf file?
Cheers Toby
-- The University of Edinburgh is a charitable body, registered in Scotland, with registration number SC005336.
Hi Toby,
Version: [root@foo-proxy openldap2.4]# slapd2.4 -VV @(#) $OpenLDAP: slapd 2.4.11 (Jul 18 2008 17:58:12) $ bgmilne@build.telkomsa.net:/home/bgmilne/rpm/BUILD/openldap-2.4.11/servers/slapd
Config: include /usr/share/openldap2.4/schema/core.schema include /usr/share/openldap2.4/schema/cosine.schema include /usr/share/openldap2.4/schema/corba.schema include /usr/share/openldap2.4/schema/inetorgperson.schema include /usr/share/openldap2.4/schema/java.schema include /usr/share/openldap2.4/schema/krb5-kdc.schema include /usr/share/openldap2.4/schema/kerberosobject.schema include /usr/share/openldap2.4/schema/nis.schema include /usr/share/openldap2.4/schema/openldap.schema include /usr/share/openldap2.4/schema/autofs.schema include /usr/share/openldap2.4/schema/samba.schema include /usr/share/openldap2.4/schema/kolab.schema include /usr/share/openldap2.4/schema/evolutionperson.schema include /usr/share/openldap2.4/schema/calendar.schema include /usr/share/openldap2.4/schema/sudo.schema include /usr/share/openldap2.4/schema/dnszone.schema include /usr/share/openldap2.4/schema/dhcp.schema include /usr/share/openldap2.4/schema/ppolicy.schema include /usr/share/openldap2.4/schema/qmail.schema include /etc/openldap2.4/schema/puppet.schema
pidfile /var/run/ldap2.4/slapd.pid argsfile /var/run/ldap2.4/slapd.args
modulepath /usr/lib/openldap2.4
moduleload back_ldap.la moduleload pcache.la moduleload ppolicy.la
TLSCertificateFile /etc/ssl/openldap2.4/foo-proxy.crt TLSCertificateKeyFile /etc/ssl/openldap2.4/foo-proxy.key TLSCACertificateFile /etc/ssl/openldap2.4/foo-proxy.crt
loglevel config stats 4096
allow bind_anon_dn database ldap suffix "dc=foo,dc=com" rootdn "cn=Manager,dc=foo,dc=com"
rootpw {SSHA}ALUc1koiBv2A1rbsFKE/lR2MmJca7fiK uri "ldaps://foo1.domain.com ldaps://foo2.domain.com" overlay pcache proxycache bdb 100000 3 1000 100 proxyAttrset 0 uid userPassword uidNumber gidNumber cn homeDirectory loginShell gecos description memberUid uniqueMember objectClass proxyAttrset 1 cn automountInformation proxyAttrset 2 cn mail proxyTemplate (&(objectClass=)(|(memberUid=)(uniqueMember=))) 0 1800 proxyTemplate (&(objectClass=)(uid=)) 0 1800 proxyTemplate (&(objectClass=)(cn=)) 0 1800 proxyTemplate (&(objectClass=)) 0 1800 proxyTemplate (objectClass=) 0 1800 proxyTemplate (&(objectClass=)(memberUid=)) 0 1800 900 proxyTemplate (&(objectClass=)(uniqueMember=)) 0 1800 900 proxyTemplate (&(objectClass=)(uidNumber=)) 0 1800 proxyTemplate (&(objectClass=)(gidNumber=)) 0 1800 proxyTemplate (&(objectClass=)(|(cn=)(gidNumber=))) 1 3600 600 proxyTemplate (&(objectClass=)(|(cn=)(cn=))) 1 3600 600 proxyTemplate (&(objectClass=)(|(cn=)(cn=)(cn=))) 1 3600 600 proxyTemplate (|(cn=)(mail=)(sn=)) 2 7200
directory /var/lib/ldap2.4
cachesize 1000 idlcachesize 1000 checkpoint 256 5
index objectClass eq index cn,mail,surname,givenname eq,subinitial index uidNumber,gidNumber,memberuid,member,uniqueMember eq index uid eq,subinitial index sambaSID,sambaDomainName,displayName eq index nisMapName,automountInformation eq index userPassword,homeDirectory,loginShell,gecos,description eq index queryId eq
overlay ppolicy ppolicy_default "cn=Password,ou=Policies,dc=foo,dc=com" ppolicy_use_lockout
Hello,
On 23 Jun 2009, at 13:37, Tyler Gates wrote:
Version: [root@foo-proxy openldap2.4]# slapd2.4 -VV @(#) $OpenLDAP: slapd 2.4.11 (Jul 18 2008 17:58:12) $ bgmilne@build.telkomsa.net:/home/bgmilne/rpm/BUILD/openldap-2.4.11/ servers/slapd
This could be ITS #5756 you're seeing - this was fixed in 2.4.14, I think.
I can't tell for sure, based on the segment of log file you've provided, but it seems to be similar behaviour in that queries claim to be cachable, but don't seem to be cached.
Cheers Toby
Hello,
On 23 Jun 2009, at 13:37, Tyler Gates wrote:
Version: [root@foo-proxy openldap2.4]# slapd2.4 -VV @(#) $OpenLDAP: slapd 2.4.11 (Jul 18 2008 17:58:12) $ bgmilne@build.telkomsa.net:/home/bgmilne/rpm/BUILD/openldap-2.4.11/ servers/slapd
This could be ITS #5756 you're seeing - this was fixed in 2.4.14, I think.
I can't tell for sure, based on the segment of log file you've provided, but it seems to be similar behaviour in that queries claim to be cachable, but don't seem to be cached.
Cheers Toby
-- The University of Edinburgh is a charitable body, registered in Scotland, with registration number SC005336.
Awesome Toby, that looks exactly it. Problem is I don't have the fixed version available to me yet. When it does become available I will update this thread on my findings.
Thanks again Toby, Tyler
openldap-technical@openldap.org
-
Toby Blake -
Tyler Gates