>
you're reading...
General

Code Release: PostgreSQL Query Cache


PostgreSQL Query Cache

© pisotskii – Fotolia.com

Source Code

GitHub: https://github.com/colemanc0709/pqc

HTTPS Clone URL: https://github.com/colemanc0709/pqc.git

Background

A while back I was having some major issues with a project regarding the PostgreSQL database queries. The fact was the queries were poorly written and the application was built in such a way that every page view yielded 50+ queries. Performance was an issue and we did not have the time to re-factor the code or clean up the queries. Next step? Cache the results!

That is when I stumbled upon the PostgreSQL Query Cache project by Satoshi Nagayasu on GitHub. It is light-weight, written in C, and was an excellent start. The challenge was that it was nearly two years old and we found it had significant issues with the majority of our queries due to length limitations when caching the queries in memcache.

I modified the source and added md5 hashing to avoid this problem and later converted to sha1. The md5 definitely worked at one point but I have not worked on the project in a while and do not remember if I completed the implementation of sha1. At any rate, I forked the initial repository this morning, committed my changes (and a few unnecessary extras, sorry) so that anyone else who would like to resume or contribute may. Feel free to contribute or “cleanup” the unnecessary files!

Thank you, Satoshi Nagayasu – excellent work! I hope that I’ve added some benefit (my application was able to leverage the hashing and ultimately cache 100% of the queries resulting in a massive performance improvement).

Satoshi provided this presentation about the project on his blog:

And, in case it is any help, here are some notes I jotted down last I was working on my revisions:

I went to re-enable PQCD in order to test some things and I encountered errors trying to start the service due to an invalid version of memcached.so.5. I determined that the 32-bit version was installed instead of the 64-bit version. This is more likely due to a bad conversion of the RPM to DEB (with alien, it doesn’t always work). As such I had to compile PQCD from scratch (source is in /opt/pqcd-source) so I’m adding some notes:

Compilation Notes

  1. This link has a viewable version of the PQCD presentation (was VERY helpful): http://pgsnaga.blogspot.com/2011/03/postgresql-query-cache-pqc.html
  2. “automake” on the source did not work until I did “autoreconf”.
  3. The “configure” command required a prefix so I specified “–prefix=/opt/pqcd”.
  4. “make” still failed because it could not find library, “event”. As such I created a symlink for /usr/lib/libevent.so to point to libevent-2.0.so.5.1.4.
  5. I had to then re-run the “configure” command and follow these steps again.
  6. I copied the pqcd.conf file from the previous installation (and corrected the memcached_bin path) and created pqcd_hba.conf from the sample (with no modifications) in /opt/pqcd/etc.
  7. At any rate, it’s now installed (I left the old version if you care to look at the error, I’ll remove it tomorrow). I started PQCD from command line with:
/opt/pqcd/bin/pqcd

* You can run in debug mode with:

/opt/pqcd/bin/pqcd –d

And, I re-enabled (un-commented) the following line in postgresql.conf (followed by a postgresql restart):

custom_variable_classes = 'pgmemcache' # list of custom variable class names

End Result

I got this working. I ran pqcd in debug mode and noticed that it wasn’t “binding” (indicating a problem with the socket). I created the directory for it, /var/run/pqcd and it started running. I then switched postgresql port to 5433 and set the pgpool to run on 5432. And then, I ran it in debug mode and confirmed that queries were passing through!

Advertisements

About christopherjcoleman

Independent IT Consultant. Cloud Expert. United States Navy Veteran. Dedicated. Focused. Driven. I make companies better by developing applications to meet specific business needs on reliable, cost-efficient cloud infrastructure. If the right solution doesn't exist then create it. I have achieved my greatest accomplishments because someone else told me "it's not possible; there is no way to do it" - and now there is.

Discussion

37 thoughts on “Code Release: PostgreSQL Query Cache

  1. Specifically reference “pqc.c” in the Github repository. My last commit (aside from a lot of unnecessary make files) included a number of changes for implementing sha1 encoding for the cache keys based on the entire initial query – allowing for 100% coverage of queries rather than limiting them due to length as was initially implemented.

    This was especially important in my case as I was leveraging query cache for a Django application. Django’s ORM can generate extremely long queries and without this only a minor percentage of my queries were even eligible for caching; the bulk were well beyond the maximum length of the query cache key.

    Debugging mode supports verbose logging of cache get / set actions, including the actual SHA1 encoded cache key.

    Posted by christopherjcoleman | 2013-08-29, 23:00
  2. Hi,
    I’ve had a hard time to compile this stuff and finally I could get it up and running on a Centos 6.4 server. My problem is that now I could not connect to pgpool (listening on port 9999, postgres on 5432 – just to test if everything works first) from a postgres client. Here is what I get from the client:

    FATAL: Peer authentication failure for user “postgres_user”

    And here is what I get from pqcd debug mode:

    2014-02-19 17:28:17 LOG: pid 1994: connection received: host=192.168.10.124 port=53405
    2014-02-19 17:28:17 DEBUG: pid 1994: Protocol Major: 3 Minor: 0 database: postgres user: taxisg
    2014-02-19 17:28:17 DEBUG: pid 1994: connecting postmaster Unix domain socket: /tmp/.s.PGSQL.5432
    2014-02-19 17:28:17 DEBUG: pid 1994: connected to postmaster Unix domain socket: /tmp/.s.PGSQL.5432 fd: 7
    2014-02-19 17:28:17 LOG: pid 1994: pool_do_auth: maybe protocol version mismatch (current version 3)

    I’m using Postgres 9.3. Don’t know if this is the cause.

    Posted by Bơ Bay | 2014-02-19, 03:34
  3. Ok, I’ve just made it. It was a problem with permissions in Postgres. Now what I’m facing is more frustrated. pqcd is working, but seems not caching the query results. I executed a query two, or three, or five, or N times, the time to complete the query did not change. Here are some lines from pqcd log (sorry for the long lines):

    2014-02-19 20:20:23 DEBUG: pid 3020: ———————- Ready For Query ———————–
    2014-02-19 20:20:29 DEBUG: pid 3020: read kind from frontend Q(51)
    2014-02-19 20:20:29 LOG: pid 3020: statement: select count(id) from pickups;
    2014-02-19 20:20:29 DEBUG: pid 3020: query cache key =
    2014-02-19 20:20:29 DEBUG: pid 3020: pqc_check_cache_avail: select count(id) from pickups;
    2014-02-19 20:20:29 DEBUG: pid 3020: encode_key: `select count(id) from pickups;’ -> `pqcd_1b2cb2401d76a773ab147b4f84666eed582b5a05′
    2014-02-19 20:20:29 DEBUG: pid 3020: pqc_get_cache: sha_encode_key -> ‘pqcd_1b2cb2401d76a773ab147b4f84666eed582b5a05′
    2014-02-19 20:20:29 ERROR: pid 3020: pqc_get_cache: NOT FOUND
    2014-02-19 20:20:29 DEBUG: pid 3020: Query: IsQueryCacheEnabled = 1, UseQueryCache = 1, FoundInQueryCache = 0
    2014-02-19 20:20:29 DEBUG: pid 3020: Query: A query result _NOT_ found in the query cache, `select count(id) from pickups;’
    2014-02-19 20:20:32 DEBUG: pid 3020: read kind from backend T
    2014-02-19 20:20:32 DEBUG: pid 3020: pool_process_query: kind from backend: T
    2014-02-19 20:20:32 DEBUG: pid 3020: pool_process_query: database name = mydatabase
    2014-02-19 20:20:32 DEBUG: pid 3020: pqc_buf_add: len=1, total=1 bufsize=8192
    2014-02-19 20:20:32 DEBUG: pid 3020: pqc_buf_add: len=4, total=5 bufsize=8192
    2014-02-19 20:20:32 DEBUG: pid 3020: pqc_buf_add: len=26, total=31 bufsize=8192
    2014-02-19 20:20:32 DEBUG: pid 3020: SimpleForwardToFrontend: kind=T, len=30, data=0x1aa8e10
    2014-02-19 20:20:32 DEBUG: pid 3020: pool_process_query: len=31
    2014-02-19 20:20:32 DEBUG: pid 3020: read kind from backend pending data D len: 38 po: 31
    2014-02-19 20:20:32 DEBUG: pid 3020: pool_process_query: kind from backend: D
    2014-02-19 20:20:32 DEBUG: pid 3020: pool_process_query: database name = mydatabase
    2014-02-19 20:20:32 DEBUG: pid 3020: pqc_buf_add: len=1, total=32 bufsize=8192
    2014-02-19 20:20:32 DEBUG: pid 3020: pqc_buf_add: len=4, total=36 bufsize=8192
    2014-02-19 20:20:32 DEBUG: pid 3020: pqc_buf_add: len=14, total=50 bufsize=8192
    2014-02-19 20:20:32 DEBUG: pid 3020: SimpleForwardToFrontend: kind=D, len=18, data=0x1aa8e10
    2014-02-19 20:20:32 DEBUG: pid 3020: pool_process_query: len=50
    2014-02-19 20:20:32 DEBUG: pid 3020: read kind from backend pending data C len: 19 po: 50
    2014-02-19 20:20:32 DEBUG: pid 3020: pool_process_query: kind from backend: C
    2014-02-19 20:20:32 DEBUG: pid 3020: pool_process_query: database name = mydatabase
    2014-02-19 20:20:32 DEBUG: pid 3020: pqc_buf_add: len=1, total=51 bufsize=8192
    2014-02-19 20:20:32 DEBUG: pid 3020: pqc_buf_add: len=4, total=55 bufsize=8192
    2014-02-19 20:20:32 DEBUG: pid 3020: SimpleForwardToFrontend: kind=’C’ string=”SELECT 1″
    2014-02-19 20:20:32 DEBUG: pid 3020: SimpleForwardToFrontend: query=”select count(id) from pickups;”
    2014-02-19 20:20:32 DEBUG: pid 3020: pqc_buf_add: len=9, total=64 bufsize=8192
    2014-02-19 20:20:32 DEBUG: pid 3020: SimpleForwardToFrontend: kind=C, len=13, data=0x1aa8e10
    2014-02-19 20:20:32 DEBUG: pid 3020: pool_process_query: len=64
    2014-02-19 20:20:32 DEBUG: pid 3020: read kind from backend pending data Z len: 5 po: 64
    2014-02-19 20:20:32 DEBUG: pid 3020: pool_process_query: kind from backend: Z
    2014-02-19 20:20:32 DEBUG: pid 3020: pool_process_query: database name = mydatabase
    2014-02-19 20:20:32 DEBUG: pid 3020: pqc_set_cache: Query=select count(id) from pickups;
    2014-02-19 20:20:32 DEBUG: pid 3020: dump_cache_data: len = 64
    2014-02-19 20:20:32 DEBUG: pid 3020: dump_cache_data: 84(T) 0() 0() 0() 30() 0() 1() 99(c) 111(o) 117(u)
    2014-02-19 20:20:32 DEBUG: pid 3020: dump_cache_data: 110(n) 116(t) 0() 0() 0() 0() 0() 0() 0() 0()
    2014-02-19 20:20:32 DEBUG: pid 3020: dump_cache_data: 0() 0() 20() 0() 8) -1(�) -1(�) -1(�) -1(�) 0()
    2014-02-19 20:20:32 DEBUG: pid 3020: dump_cache_data: 0() 68(D) 0() 0() 0() 18() 0() 1() 0() 0()
    2014-02-19 20:20:32 DEBUG: pid 3020: dump_cache_data: 0() 8) 49(1) 53(5) 53(5) 50(2) 57(9) 56(8) 56(8) 53(5)
    ) 83(S) 69(E) 76(L) 69(E) 67(C) 020: dump_cache_data: 67(C) 0() 0() 0() 13(
    2014-02-19 20:20:32 DEBUG: pid 3020: dump_cache_data: 84(T)
    2014-02-19 20:20:32 DEBUG: pid 3020: dump_cache_data: 32( )
    2014-02-19 20:20:32 DEBUG: pid 3020: dump_cache_data: 49(1)
    2014-02-19 20:20:32 DEBUG: pid 3020: dump_cache_data: 0()
    2014-02-19 20:20:32 DEBUG: pid 3020: encode_key: `select count(id) from pickups;’ -> `pqcd_f5f12c9ad9875d2b31aabc3153bc844a925d88c1′
    2014-02-19 20:20:32 DEBUG: pid 3020: pqc_set_cache: sha_encode_key -> ‘pqcd_f5f12c9ad9875d2b31aabc3153bc844a925d88c1’
    2014-02-19 20:20:32 DEBUG: pid 3020: pqc_set_cache: succeeded.
    2014-02-19 20:20:32 DEBUG: pid 3020: pool_read_message_length: lenghth: 5
    2014-02-19 20:20:32 DEBUG: pid 3020: ReadyForQuery: message length: 5
    2014-02-19 20:20:32 DEBUG: pid 3020: ReadyForQuery: transaction state: I
    2014-02-19 20:20:32 DEBUG: pid 3020: Query cache enabled back (by default) after the ReadyForQuery response.
    2014-02-19 20:20:32 DEBUG: pid 3020: ———————- Ready For Query ———————–

    I checked memcached and it is running. But and I terminated pqcd it complained me that it could not find the PID of memcached. Something that lookes like this:

    2014-02-19 20:17:28 ERROR: pid 2945: PID file can’t be opened. – /tmp/memcached.pid
    2014-02-19 20:17:28 DEBUG: pid 2945: pqc_destroy: memcached has been destroyed.

    Spent nearly a day to work on this and have no idea what to do now :-( Is there something still missing?

    Posted by Bơ Bay | 2014-02-19, 06:22
  4. I had a look at memcached stats and it looked like that memcached missed all the gets.
    http://screencloud.net/v/haHP

    Posted by Bơ Bay | 2014-02-19, 07:38
    • Bo – I’m glad you are trying it out. It certainly needs some work but the caching itself should work. According to the debug messages it is indeed succeeding in setting the cache. The SHA encoding is necessary in order to prevent most queries from being ignored due to length. That said, if the query is not identical then it will not be able to retrieve it.

      The logs above indicate that the query was executed, not found in cache, and added to the cache but I do not see a follow-up query that attempts to retrieve it.

      Off-hand I would suggest checking the date/time settings on your machine (particularly if memcache resides on a separate server) and confirm they are in sync. Otherwise, could you send me more of the logs or perhaps email them?

      Posted by christopherjcoleman | 2014-02-19, 11:41
  5. Hi Christopher, thank you for your reply. I checked the system time and found no problem with it. I executed the query again and here are some lines that may be useful:

    2014-02-20 10:09:10 DEBUG: pid 17799: ———————- Ready For Query ———————–
    2014-02-20 10:09:18 DEBUG: pid 17799: read kind from frontend Q(51)
    2014-02-20 10:09:18 LOG: pid 17799: statement: select count(id) from pickups;
    2014-02-20 10:09:18 DEBUG: pid 17799: query cache key =
    2014-02-20 10:09:18 DEBUG: pid 17799: pqc_check_cache_avail: select count(id) from pickups;
    2014-02-20 10:09:18 DEBUG: pid 17799: encode_key: `select count(id) from pickups;’ -> `pqcd_9f2e28220badc830e7fb2cfee90fbcca6a917282′
    2014-02-20 10:09:18 DEBUG: pid 17799: pqc_get_cache: sha_encode_key -> ‘pqcd_9f2e28220badc830e7fb2cfee90fbcca6a917282′
    2014-02-20 10:09:18 ERROR: pid 17799: pqc_get_cache: NOT FOUND
    2014-02-20 10:09:18 DEBUG: pid 17799: Query: IsQueryCacheEnabled = 1, UseQueryCache = 1, FoundInQueryCache = 0
    2014-02-20 10:09:18 DEBUG: pid 17799: Query: A query result _NOT_ found in the query cache, `select count(id) from pickups;’
    2014-02-20 10:09:21 DEBUG: pid 17799: read kind from backend T
    2014-02-20 10:09:21 DEBUG: pid 17799: pool_process_query: kind from backend: T
    2014-02-20 10:09:21 DEBUG: pid 17799: pool_process_query: database name = mydatabase
    2014-02-20 10:09:21 DEBUG: pid 17799: pqc_buf_add: len=1, total=1 bufsize=8192
    2014-02-20 10:09:21 DEBUG: pid 17799: pqc_buf_add: len=4, total=5 bufsize=8192
    2014-02-20 10:09:21 DEBUG: pid 17799: pqc_buf_add: len=26, total=31 bufsize=8192
    2014-02-20 10:09:21 DEBUG: pid 17799: SimpleForwardToFrontend: kind=T, len=30, data=0xc104a0
    2014-02-20 10:09:21 DEBUG: pid 17799: pool_process_query: len=31
    2014-02-20 10:09:21 DEBUG: pid 17799: read kind from backend pending data D len: 38 po: 31
    2014-02-20 10:09:21 DEBUG: pid 17799: pool_process_query: kind from backend: D
    2014-02-20 10:09:21 DEBUG: pid 17799: pool_process_query: database name = mydatabase
    2014-02-20 10:09:21 DEBUG: pid 17799: pqc_buf_add: len=1, total=32 bufsize=8192
    2014-02-20 10:09:21 DEBUG: pid 17799: pqc_buf_add: len=4, total=36 bufsize=8192
    2014-02-20 10:09:21 DEBUG: pid 17799: pqc_buf_add: len=14, total=50 bufsize=8192
    2014-02-20 10:09:21 DEBUG: pid 17799: SimpleForwardToFrontend: kind=D, len=18, data=0xc104a0
    2014-02-20 10:09:21 DEBUG: pid 17799: pool_process_query: len=50
    2014-02-20 10:09:21 DEBUG: pid 17799: read kind from backend pending data C len: 19 po: 50
    2014-02-20 10:09:21 DEBUG: pid 17799: pool_process_query: kind from backend: C
    2014-02-20 10:09:21 DEBUG: pid 17799: pool_process_query: database name = mydatabase
    2014-02-20 10:09:21 DEBUG: pid 17799: pqc_buf_add: len=1, total=51 bufsize=8192
    2014-02-20 10:09:21 DEBUG: pid 17799: pqc_buf_add: len=4, total=55 bufsize=8192
    2014-02-20 10:09:21 DEBUG: pid 17799: SimpleForwardToFrontend: kind=’C’ string=”SELECT 1″
    2014-02-20 10:09:21 DEBUG: pid 17799: SimpleForwardToFrontend: query=”select count(id) from pickups;”
    2014-02-20 10:09:21 DEBUG: pid 17799: pqc_buf_add: len=9, total=64 bufsize=8192
    2014-02-20 10:09:21 DEBUG: pid 17799: SimpleForwardToFrontend: kind=C, len=13, data=0xc104a0
    2014-02-20 10:09:21 DEBUG: pid 17799: pool_process_query: len=64
    2014-02-20 10:09:21 DEBUG: pid 17799: read kind from backend pending data Z len: 5 po: 64
    2014-02-20 10:09:21 DEBUG: pid 17799: pool_process_query: kind from backend: Z
    2014-02-20 10:09:21 DEBUG: pid 17799: pool_process_query: database name = mydatabase
    2014-02-20 10:09:21 DEBUG: pid 17799: pqc_set_cache: Query=select count(id) from pickups;
    2014-02-20 10:09:21 DEBUG: pid 17799: dump_cache_data: len = 64
    2014-02-20 10:09:21 DEBUG: pid 17799: dump_cache_data: 84(T) 0() 0() 0() 30() 0() 1() 99(c) 111(o) 117(u)
    2014-02-20 10:09:21 DEBUG: pid 17799: dump_cache_data: 110(n) 116(t) 0() 0() 0() 0() 0() 0() 0() 0()
    2014-02-20 10:09:21 DEBUG: pid 17799: dump_cache_data: 0() 0() 20() 0() 8) -1(�) -1(�) -1(�) -1(�) 0()
    2014-02-20 10:09:21 DEBUG: pid 17799: dump_cache_data: 0() 68(D) 0() 0() 0() 18() 0() 1() 0() 0()
    2014-02-20 10:09:21 DEBUG: pid 17799: dump_cache_data: 0() 8) 49(1) 53(5) 53(5) 50(2) 57(9) 56(8) 56(8) 53(5)
    ) 83(S) 69(E) 76(L) 69(E) 67(C) 7799: dump_cache_data: 67(C) 0() 0() 0() 13(
    2014-02-20 10:09:21 DEBUG: pid 17799: dump_cache_data: 84(T)
    2014-02-20 10:09:21 DEBUG: pid 17799: dump_cache_data: 32( )
    2014-02-20 10:09:21 DEBUG: pid 17799: dump_cache_data: 49(1)
    2014-02-20 10:09:21 DEBUG: pid 17799: dump_cache_data: 0()
    2014-02-20 10:09:21 DEBUG: pid 17799: encode_key: `select count(id) from pickups;’ -> `pqcd_414e9a5637153e4e31f1ac2c4c88aeb0f712c14f’
    2014-02-20 10:09:21 DEBUG: pid 17799: pqc_set_cache: sha_encode_key -> ‘pqcd_414e9a5637153e4e31f1ac2c4c88aeb0f712c14f’
    2014-02-20 10:09:21 DEBUG: pid 17799: pqc_set_cache: succeeded.
    2014-02-20 10:09:21 DEBUG: pid 17799: pool_read_message_length: lenghth: 5
    2014-02-20 10:09:21 DEBUG: pid 17799: ReadyForQuery: message length: 5
    2014-02-20 10:09:21 DEBUG: pid 17799: ReadyForQuery: transaction state: I
    2014-02-20 10:09:21 DEBUG: pid 17799: Query cache enabled back (by default) after the ReadyForQuery response.
    2014-02-20 10:09:21 DEBUG: pid 17799: ———————- Ready For Query ———————–
    2014-02-20 10:09:52 DEBUG: pid 17799: read kind from frontend Q(51)
    2014-02-20 10:09:52 LOG: pid 17799: statement: select count(id) from pickups;
    2014-02-20 10:09:52 DEBUG: pid 17799: query cache key =
    2014-02-20 10:09:52 DEBUG: pid 17799: pqc_check_cache_avail: select count(id) from pickups;
    2014-02-20 10:09:52 DEBUG: pid 17799: encode_key: `select count(id) from pickups;’ -> `pqcd_4ea672daaca5049e9af933bdf17a8bb610d5be47′
    2014-02-20 10:09:52 DEBUG: pid 17799: pqc_get_cache: sha_encode_key -> ‘pqcd_4ea672daaca5049e9af933bdf17a8bb610d5be47′
    2014-02-20 10:09:52 ERROR: pid 17799: pqc_get_cache: NOT FOUND
    2014-02-20 10:09:52 DEBUG: pid 17799: Query: IsQueryCacheEnabled = 1, UseQueryCache = 1, FoundInQueryCache = 0
    2014-02-20 10:09:52 DEBUG: pid 17799: Query: A query result _NOT_ found in the query cache, `select count(id) from pickups;’
    2014-02-20 10:09:55 DEBUG: pid 17799: read kind from backend T
    2014-02-20 10:09:55 DEBUG: pid 17799: pool_process_query: kind from backend: T
    2014-02-20 10:09:55 DEBUG: pid 17799: pool_process_query: database name = mydatabase
    2014-02-20 10:09:55 DEBUG: pid 17799: pqc_buf_add: len=1, total=1 bufsize=8192
    2014-02-20 10:09:55 DEBUG: pid 17799: pqc_buf_add: len=4, total=5 bufsize=8192
    2014-02-20 10:09:55 DEBUG: pid 17799: pqc_buf_add: len=26, total=31 bufsize=8192
    2014-02-20 10:09:55 DEBUG: pid 17799: SimpleForwardToFrontend: kind=T, len=30, data=0xc104a0
    2014-02-20 10:09:55 DEBUG: pid 17799: pool_process_query: len=31
    2014-02-20 10:09:55 DEBUG: pid 17799: read kind from backend pending data D len: 38 po: 31
    2014-02-20 10:09:55 DEBUG: pid 17799: pool_process_query: kind from backend: D
    2014-02-20 10:09:55 DEBUG: pid 17799: pool_process_query: database name = mydatabase
    2014-02-20 10:09:55 DEBUG: pid 17799: pqc_buf_add: len=1, total=32 bufsize=8192
    2014-02-20 10:09:55 DEBUG: pid 17799: pqc_buf_add: len=4, total=36 bufsize=8192
    2014-02-20 10:09:55 DEBUG: pid 17799: pqc_buf_add: len=14, total=50 bufsize=8192
    2014-02-20 10:09:55 DEBUG: pid 17799: SimpleForwardToFrontend: kind=D, len=18, data=0xc104a0
    2014-02-20 10:09:55 DEBUG: pid 17799: pool_process_query: len=50
    2014-02-20 10:09:55 DEBUG: pid 17799: read kind from backend pending data C len: 19 po: 50
    2014-02-20 10:09:55 DEBUG: pid 17799: pool_process_query: kind from backend: C
    2014-02-20 10:09:55 DEBUG: pid 17799: pool_process_query: database name = mydatabase
    2014-02-20 10:09:55 DEBUG: pid 17799: pqc_buf_add: len=1, total=51 bufsize=8192
    2014-02-20 10:09:55 DEBUG: pid 17799: pqc_buf_add: len=4, total=55 bufsize=8192
    2014-02-20 10:09:55 DEBUG: pid 17799: SimpleForwardToFrontend: kind=’C’ string=”SELECT 1″
    2014-02-20 10:09:55 DEBUG: pid 17799: SimpleForwardToFrontend: query=”select count(id) from pickups;”
    2014-02-20 10:09:55 DEBUG: pid 17799: pqc_buf_add: len=9, total=64 bufsize=8192
    2014-02-20 10:09:55 DEBUG: pid 17799: SimpleForwardToFrontend: kind=C, len=13, data=0xc104a0
    2014-02-20 10:09:55 DEBUG: pid 17799: pool_process_query: len=64
    2014-02-20 10:09:55 DEBUG: pid 17799: read kind from backend pending data Z len: 5 po: 64
    2014-02-20 10:09:55 DEBUG: pid 17799: pool_process_query: kind from backend: Z
    2014-02-20 10:09:55 DEBUG: pid 17799: pool_process_query: database name = mydatabase
    2014-02-20 10:09:55 DEBUG: pid 17799: pqc_set_cache: Query=select count(id) from pickups;
    2014-02-20 10:09:55 DEBUG: pid 17799: dump_cache_data: len = 64
    2014-02-20 10:09:55 DEBUG: pid 17799: dump_cache_data: 84(T) 0() 0() 0() 30() 0() 1() 99(c) 111(o) 117(u)
    2014-02-20 10:09:55 DEBUG: pid 17799: dump_cache_data: 110(n) 116(t) 0() 0() 0() 0() 0() 0() 0() 0()
    2014-02-20 10:09:55 DEBUG: pid 17799: dump_cache_data: 0() 0() 20() 0() 8) -1(�) -1(�) -1(�) -1(�) 0()
    2014-02-20 10:09:55 DEBUG: pid 17799: dump_cache_data: 0() 68(D) 0() 0() 0() 18() 0() 1() 0() 0()
    2014-02-20 10:09:55 DEBUG: pid 17799: dump_cache_data: 0() 8) 49(1) 53(5) 53(5) 50(2) 57(9) 56(8) 56(8) 53(5)
    ) 83(S) 69(E) 76(L) 69(E) 67(C) 7799: dump_cache_data: 67(C) 0() 0() 0() 13(
    2014-02-20 10:09:55 DEBUG: pid 17799: dump_cache_data: 84(T)
    2014-02-20 10:09:55 DEBUG: pid 17799: dump_cache_data: 32( )
    2014-02-20 10:09:55 DEBUG: pid 17799: dump_cache_data: 49(1)
    2014-02-20 10:09:55 DEBUG: pid 17799: dump_cache_data: 0()
    2014-02-20 10:09:55 DEBUG: pid 17799: encode_key: `select count(id) from pickups;’ -> `pqcd_9c288cd4436d808969ff30f4f9794182bc9d629b’
    2014-02-20 10:09:55 DEBUG: pid 17799: pqc_set_cache: sha_encode_key -> ‘pqcd_9c288cd4436d808969ff30f4f9794182bc9d629b’
    2014-02-20 10:09:55 DEBUG: pid 17799: pqc_set_cache: succeeded.
    2014-02-20 10:09:55 DEBUG: pid 17799: pool_read_message_length: lenghth: 5
    2014-02-20 10:09:55 DEBUG: pid 17799: ReadyForQuery: message length: 5
    2014-02-20 10:09:55 DEBUG: pid 17799: ReadyForQuery: transaction state: I
    2014-02-20 10:09:55 DEBUG: pid 17799: Query cache enabled back (by default) after the ReadyForQuery response.
    2014-02-20 10:09:55 DEBUG: pid 17799: ———————- Ready For Query ———————–

    What is strange here is the encode_keys are different for a query. That may be the reason why all gets are missed in memcached, I guess.

    Posted by Bơ Bay | 2014-02-19, 20:20
  6. FYI, memcached was running and I could connect to it using telnet and obtain some statistics.

    Posted by Bơ Bay | 2014-02-19, 21:44
  7. Hello, can you share with me a link to understand the working and architecture of the query cache implementation?
    Thanks.

    Posted by Deepak S | 2014-09-15, 22:46
    • I did not write the core but essentially it creates a cache key from the exact SQL query and remembers the result (you can configure cache expiration, etc.). What I added was encoding of the SQL query to create a cache key. Prior to that 90+% of the queries were not cached because the key length was excessive. By encoding (actually, hashing) using SHA-1 (versus MD5, SHA-1 was chosen because my tests indicated higher performance), I restrict the length of the cache key to a fixed and predictable length so that 100% of the queries are cached. The query cache itself acts as a middle-man between the client and the PostgreSQL server and utilizes pgpool to pool multiple database connections. It has some faults (apparently in the connection pooling under high load) but it is a major development in my opinion toward good PostgreSQL query caching. I have not had the opportunity to work on it in one and a half years but I am hoping it will gain enough traction that someone else can pick-up where I left off! Thank you for your interest!

      Posted by christopherjcoleman | 2014-09-15, 22:53
      • Thanks a ton for the reply :) Its truly a major development toward query caching.
        Sorry to pester you but do you have any idea about the data structures used in it? In MySQL, they use a circular doubly linked list with LRU block replacement algorithm for linking the various blocks(query, table and result blocks) and for hashing they use a dynamic array with chaining. I would like to gain a similar insight into postgres as well. However, I could not find any article that talks about its internals. Thanks for your time.

        Posted by Deepak S | 2014-09-16, 02:32
      • I am not. I have not looked into it in that detail. It is a very basic approach at this point but investigating the data structure might be beneficial in working toward automatic cache expiration to guarantee fresh results – also as MySQL does.

        Posted by christopherjcoleman | 2014-09-16, 07:55
  8. Hi, I have trouble installing QC. ‘make’ gives me error. ‘autoconf’ and ‘configure’ executed fine.

    deepaks@dpaks:~/Project/pqc-master-coleman/src$ make
    make all-am
    make[1]: Entering directory `/home/deepaks/Project/pqc-master-coleman/src’
    gcc -g -O2 -o pqcd main.o child.o pool_auth.o pool_config.o pool_error.o pool_process_query.o pool_stream.o pool_connection_pool.o pool_params.o pool_signal.o ps_status.o strlcpy.o pool_hba.o pool_list.o pool_path.o pqc.o pool_ip.o -lmemcached -levent -lcrypto -lresolv -lnsl -lm
    /usr/bin/ld: cannot find -lmemcached
    /usr/bin/ld: cannot find -levent
    /usr/bin/ld: cannot find -lcrypto
    collect2: error: ld returned 1 exit status
    make[1]: *** [pqcd] Error 1
    make[1]: Leaving directory `/home/deepaks/Project/pqc-master-coleman/src’
    make: *** [all] Error 2

    What should I do? You have talked about creating a symlink. Is that the solution for my problem? However, there is no libevent.so file in /usr/lib. Kindly help. Thanks.

    Posted by Deepak S | 2014-10-14, 00:27
  9. Sorry but I still have ‘cannot find -lcrypto’ error. I resolved the other two errors. Thanks for your link. I installed crypto packages ‘libcryptokit-ocaml’ and ‘libcrypto++-dev’ but still I’m getting the error. Is it that I didn’t install the proper package?

    Posted by Deepak S | 2014-10-14, 02:45
  10. I am stuck in this!

    deepaks@dpaks:~/Project/pqc-master-coleman/src$ make
    make all-am
    make[1]: Entering directory `/home/deepaks/Project/pqc-master-coleman/src’
    gcc -DHAVE_CONFIG_H -DDEFAULT_CONFIGDIR=\”/opt/pqcd/etc\” -I. -Wall -Wmissing-prototypes -Wmissing-declarations -D_GNU_SOURCE -g -O2 -MT main.o -MD -MP -MF .deps/main.Tpo -c -o main.o main.c
    In file included from main.c:53:0:
    pqc.h:9:36: fatal error: libmemcached/memcached.h: No such file or directory
    #include
    ^
    compilation terminated.
    make[1]: *** [main.o] Error 1
    make[1]: Leaving directory `/home/deepaks/Project/pqc-master-coleman/src’
    make: *** [all] Error 2

    I found that these header files are located in ‘/opt/uptime/querycache/include/libmemcached’ direcory. My present working directory is ‘/home/deepaks/Project/pqc-master-coleman/src’. Kindly help. Thanks.

    Posted by Deepak S | 2014-10-14, 03:13
    • libmemcached-dev is the proper library. If you have confirmed that the header files are there then try including in your PATH environment variable. Do a make –clean, and re-run ./configure. Ensure that the configure command finds those libraries before attempting to run make again. If it did not then you must specify it or create a symbolic link in the folder where you are running the configure/make commands to the header file in it’s actual location. Sorry for the delayed response – we are in different timezones.

      Posted by christopherjcoleman | 2014-10-14, 10:34
      • The problem was due to the absence of libmemcached-dev. After installing it, everything went fine. However, when I ran the executable, I got the following messages.

        pool_config: could not open configuration file (pqcd.conf)
        pool_config: using default values…

        1) Is it OK to ignore these warnings? In the etc directory, I made a copy of pqcd_hba.conf.sample to pqcd_hba.conf. Between, I didn’t touch pqcd.conf.sample file.

        2) In pqcd.conf.sample, memcached_bin path is set to ‘/usr/local/bin/memcached’ where nothing exists. . Shouldn’t I change it to ‘/opt/uptime/querycache/bin/memcached’ where memcached executable exists?
        Thanks :)

        Posted by Deepak S | 2014-10-15, 00:31
      • 1. Those warnings should be fine since it automatically reverts to the default settings. I always create my own config file even if it contains the default option. In this case I would setup the PostgreSQL server to listen on an alternate port, and then have pqcd listen on the standard PostgreSQL port (only to be transparent to the applications which will by default try to connect to PostgreSQL on 5432) – but that is just personal preference.

        2. Yes, change the memcached_bin to point to the memcached executable.

        Let me know if you get it working! If you can provide any documentation or setup instructions for others I will gladly add it to the repo and credit you for the work (and any other contributions or modifications you implement). I am glad you stuck with it to get it up and running!

        Posted by christopherjcoleman | 2014-10-15, 08:06
  11. Thanks for the help!
    In the pqcd.conf file, I changed the backend port to 9999 from 5432 and pgpool port to 5432 from 9999. But is pgpool port the listening port of pqcd? In order for the client to connect to pqcd, I started psql using ‘-p 5432’ where 5432 was assigned as the pgpool port in pqcd.conf.

    I started server using ‘-p 9999’ where 9999 was mentioned as the backend port in pqcd.conf.
    However, the warnings that occurred when I stopped pqcd ceased.
    It displays:
    stop request sent to memcached. waiting for termination…done.
    stop request sent to pqcd. waiting for termination…………………………….done.
    (pqcd terminates only when I exit from psql)

    However, caching does not work(inferred from the time for execution). Is it a problem with the port configurations?

    Posted by Deepak S | 2014-10-16, 04:22
    • Deepak, in addition to the suggestions I sent across via email this morning, please also check the settings and debugging procedures above. Note the directory creation for pqcd (/var/run/pqcd) before it would bind, and the port settings I modified in the configuration.

      Posted by christopherjcoleman | 2014-10-20, 10:45
  12. Hurray! Finally I succeeded :) :) :)

    2014-10-21 11:52:17 DEBUG: pid 6189: Query: a cache fetched. len=108
    2014-10-21 11:52:17 DEBUG: pid 6189: pqc_send_message: kind=T, len=56, data=0xbfeb5f6c
    2014-10-21 11:52:17 DEBUG: pid 6189: pqc_send_message: kind=D, len=36, data=0xbfeb5f6c
    2014-10-21 11:52:17 DEBUG: pid 6189: pqc_send_message: kind=C, len=13, data=0xbfeb5f6c
    2014-10-21 11:52:17 DEBUG: pid 6189: pqc_send_message: kind=Z, len=5, data=0xbfeb7fd8
    2014-10-21 11:52:17 DEBUG: pid 6189: Query: sent a query result to the frontend from the query cache, `select * from cities;’
    2014-10-21 11:52:17 DEBUG: pid 6189: ———————- Ready For Query ———————–

    Time taken was reduced from 76.xxx ms to 0.6xx ms.
    You have immensely supported me! Thanks a ton :)

    Posted by Deepak S | 2014-10-20, 23:27
  13. Hi, how to increase the cache size? I did not find any option in memcached.config to manipluate the cache size. Do I need to add an additional config parameter?
    Thanks :)

    Posted by Deepak S | 2014-10-28, 00:39
  14. For both the queries that were cached and not cached, memcached gave similar kind of following message:

    set pqcd_e5e1459907503fdac08f163ebc128a705a04d99a 0 3000 60
    >30 STORED
    30 sending key pqcd_e5e1459907503fdac08f163ebc128a705a04d99a
    >30 END

    Both total cache and item_cache size has been increased to an amount well enough to cache all my queries. I also notice that when the query is NOT cached, I get the following message in my client side:

    ‘The connection to the server was lost. Attempting reset: Succeeded.’ //Server is pqcd

    When I increased the verbosity and ran the non-cached query, I got the following:

    NOT FOUND pqcd_376707391feec239797530b48f08a815e2853eb3
    >30 END
    NOT FOUND pqcd_376707391feec239797530b48f08a815e2853eb3
    >30 STORED

    which means the key is stored. On the second run of the non-cached query I got,

    <30 new auto-negotiating client connection
    30: going from conn_new_cmd to conn_waiting
    30: going from conn_waiting to conn_read
    30: going from conn_read to conn_parse_cmd
    30: Client using the ascii protocol
    FOUND KEY pqcd_376707391feec239797530b48f08a815e2853eb3
    >30 sending key pqcd_376707391feec239797530b48f08a815e2853eb3
    >30 END
    30: going from conn_parse_cmd to conn_mwrite
    30: going from conn_mwrite to conn_new_cmd
    30: going from conn_new_cmd to conn_waiting
    30: going from conn_waiting to conn_read
    30: going from conn_read to conn_closing
    <30 connection closed.

    In the cached-query I got,

    30: going from conn_read to conn_parse_cmd
    FOUND KEY pqcd_e5e1459907503fdac08f163ebc128a705a04d99a
    >30 sending key pqcd_e5e1459907503fdac08f163ebc128a705a04d99a
    >30 END
    30: going from conn_parse_cmd to conn_mwrite
    30: going from conn_mwrite to conn_new_cmd
    30: going from conn_new_cmd to conn_waiting
    30: going from conn_waiting to conn_read
    30: going from conn_read to conn_parse_cmd
    FOUND KEY pqcd_e5e1459907503fdac08f163ebc128a705a04d99a
    >30 sending key pqcd_e5e1459907503fdac08f163ebc128a705a04d99a
    >30 END
    30: going from conn_parse_cmd to conn_mwrite
    30: going from conn_mwrite to conn_new_cmd
    30: going from conn_new_cmd to conn_waiting
    30: going from conn_waiting to conn_read

    In here, what I notice is that in the possible-to-be-cached non-cached-query, it is going from conn_read to conn_closing rather than going from conn_read to conn_parse_cmd.
    While in the cached-query, it went from conn_read to conn_parse_cmd and fetched the key and sent the data to client.

    Something is blocking the journey of that possible-to-be-cached non-cached-query in the function conn_read().

    Any leads on this matter?
    Thanks

    Posted by Deepak S | 2014-10-28, 03:57
    • Non-cached is not the word. Sorry! It is being cached. Memcached stats shows that each time I enter the big query, a hit occurs. But the fetched data is not coming to the client side or is it actually being fetched?

      Posted by Deepak S | 2014-10-28, 09:39
    • There should be another level of debugging that actually shows the full queries submitted, result returned, etc. It appears that the connection is failing but not sure off hand is that is the database connection or the memcache connection. Check your port configurations.

      Posted by christopherjcoleman | 2014-10-28, 09:51
      • Anyhow data is being written by memcached server to psql client. I verified it using memcached “stats”.
        Bytes_written = 963573 //second run
        Bytes_written = 1922473 //third run

        This means that memcached fetches result and sends it to the client right?

        Also, I verified that the queries are being stored(as can be seen from memory usage and hits parameters).

        I don’t suppose its due to port misconfiguration as
        1)select * from stats; //cached but not retrieved
        2)select count(*) from stats; //cached and retrieved

        Stats is a table containing around 9000 records. Its total size is around 932KB.

        Have you encountered such a problem? Is my socket not allowing bigger data?

        Posted by Deepak S | 2014-10-28, 10:27
  15. Well good to rule out the ports – and that does sound like it is caching something but the verbose debugging (even just on the memcache side) would allow you to see exactly what is being cached. If the whole results is not being sent then I would look at the code. If it is being sent and cached but not retrieved, I would look at the memcache configuration. If it is being sent, cached, and retrieved in whole then it would again be a code issue.

    Posted by christopherjcoleman | 2014-10-28, 10:37
    • I have enabled verbose debugging on memcached side as well as pqcd side. My inference is that the results are being fully cached. For the smaller query, each hit is counted as 2 i.e., if I am rerunning the query my hits count will be increased by 2. However, the bigger query results in hits count being incremented just by 1.

      As I mentioned in a previous comment, during the execution of the smaller query, FOUND KEY is being displayed twice while it happens just once for the bigger query. I have posted an excerpt from the verbose log in a previous comment. Please have a look at that.

      Posted by deepaks | 2014-10-28, 10:53
      • In src/pqc.c in pq_set_cache(…) you see a number of pool_debug() commands. These show the entire encryption process – submitted query, conversion (sha1 encryption) to hash key, etc. as well as the fetch result from memcache. This is what I was looking for that I do not see in your logs. It is an additional level of debugging. To enable you need to start pgpool with the –debug flag, and set the “debug_level” in pgpool.conf (probably to 1). If you can get that level of debugging than you can walk through that portion of the code and determine where there might be an issue.

        Posted by christopherjcoleman | 2014-10-28, 11:22
      • I have that debug info too. The one I posted belongs to memcached debug information. I’ll post you pqcd debug cache soon. Anyways, I remember seeing that query submission and sha1 conversion. Thanks

        Posted by deepaks | 2014-10-28, 11:57
  16. On my Debian System and Postgres 9.4 PQCD is very unstable, it disconnects often and don’t always execute queries. :-(

    Posted by Luca Ugo | 2015-03-06, 03:22

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

%d bloggers like this: