View Issue Details

Jump to NotesJump to History
IDProjectCategoryView StatusDate SubmittedLast Update
0000561Pgpool-IIGeneralpublic2019-11-30 23:302019-12-10 10:15
Reportersubi Assigned Tot-ishii  
PrioritynormalSeverityminorReproducibilityalways
Status closedResolutionopen 
Product Version4.1.0 
Summary0000561: why transaction with 'set' statement would always be marked as 'writing transaction', even it is began with 'read only'?
Descriptionsuch behavior completely disables the query cache if one needs set some parameters in the transaction.
Tagsquery cache

Activities

t-ishii

2019-12-02 15:25

developer   ~0002986

Last edited: 2019-12-02 16:18

 Because Pgpool-II does not track if current transaction is read-only or not...
Wait, I don't see SET statement prevent SELECT results from being cached:

2019-12-02 16:14:14: pid 25246: LOG: DB node id: 0 backend pid: 25262 statement: begin;
2019-12-02 16:14:45: pid 25246: LOG: DB node id: 0 backend pid: 25262 statement: set application_name to 'foo';
2019-12-02 16:14:50: pid 25246: LOG: DB node id: 0 backend pid: 25262 statement: select 1;
2019-12-02 16:14:54: pid 25246: LOG: DB node id: 0 backend pid: 25262 statement: end;
2019-12-02 16:14:54: pid 25246: LOG: DB node id: 0 backend pid: 25262 statement: SELECT oid FROM pg_database WHERE datname = 'test'
2019-12-02 16:14:56: pid 25246: LOG: fetch from memory cache
2019-12-02 16:14:56: pid 25246: DETAIL: query result fetched from cache. statement: select 1;

Apparently, the result of "SELECT 1" has been cached despite the preceding SET command.

subi

2019-12-02 19:39

reporter   ~0002988

Then I wonder why the following is happening:

----
Here is the clean run:

Dec 02 10:33:37 ip-10-2-32-84 pgpool[5616]: 2019-12-02 10:33:37: pid 5646: LOG: DB node id: 0 backend pid: 5859 statement: SELECT count(*) FROM pg_catalog.pg_proc AS p WHERE p.proname = 'json_build_array' AND p.provolatile = 'i'
Dec 02 10:33:37 ip-10-2-32-84 pgpool[5616]: 2019-12-02 10:33:37: pid 5646: LOG: DB node id: 0 backend pid: 5859 statement: select json_build_array('2');


---
Here is a re-run:

Dec 02 10:33:45 ip-10-2-32-84 pgpool[5616]: 2019-12-02 10:33:45: pid 5646: LOG: fetch from memory cache
Dec 02 10:33:45 ip-10-2-32-84 pgpool[5616]: 2019-12-02 10:33:45: pid 5646: DETAIL: query result fetched from cache. statement: select json_build_array('2');

---
Here is a re-run inside a transaction:

Dec 02 10:35:43 ip-10-2-32-84 pgpool[5616]: 2019-12-02 10:35:43: pid 5646: LOG: DB node id: 0 backend pid: 5859 statement: begin;
Dec 02 10:35:46 ip-10-2-32-84 pgpool[5616]: 2019-12-02 10:35:46: pid 5646: LOG: fetch from memory cache
Dec 02 10:35:46 ip-10-2-32-84 pgpool[5616]: 2019-12-02 10:35:46: pid 5646: DETAIL: query result fetched from cache. statement: select json_build_array('2');

---
Here is a re-run after doing "SET" something in the same transaction:

Dec 02 10:36:04 ip-10-2-32-84 pgpool[5616]: 2019-12-02 10:36:04: pid 5646: LOG: DB node id: 0 backend pid: 5859 statement: set "any.user.settings" TO '1';
Dec 02 10:36:06 ip-10-2-32-84 pgpool[5616]: 2019-12-02 10:36:06: pid 5646: LOG: DB node id: 0 backend pid: 5859 statement: select json_build_array('2');


----

Maybe it could be related to the setting names? ("any.user.settings")

t-ishii

2019-12-02 22:44

developer   ~0002989

In the first place, I wonder why "select json_build_array('2')" was cached because the function is stable. Did you patch Pgpool-II?

subi

2019-12-02 23:05

reporter   ~0002990

I didn't patch pgpool-II but I did update the 'provolatile' of 'json_build_array', but that should be irrelevant. I tested with 'select 1', the result is the same:

Dec 02 13:59:32 ip-10-2-32-84 pgpool[7370]: 2019-12-02 13:59:32: pid 7407: LOG: DB node id: 0 backend pid: 8014 statement: select 1;
Dec 02 13:59:32 ip-10-2-32-84 pgpool[7370]: 2019-12-02 13:59:32: pid 7407: LOG: DB node id: 0 backend pid: 8014 statement: SELECT oid FROM pg_database WHERE datname = 'postgres'
Dec 02 13:59:36 ip-10-2-32-84 pgpool[7370]: 2019-12-02 13:59:36: pid 7407: LOG: fetch from memory cache
Dec 02 13:59:36 ip-10-2-32-84 pgpool[7370]: 2019-12-02 13:59:36: pid 7407: DETAIL: query result fetched from cache. statement: select 1;
Dec 02 13:59:43 ip-10-2-32-84 pgpool[7370]: 2019-12-02 13:59:43: pid 7407: LOG: DB node id: 0 backend pid: 8014 statement: begin;
Dec 02 13:59:54 ip-10-2-32-84 pgpool[7370]: 2019-12-02 13:59:54: pid 7407: LOG: DB node id: 0 backend pid: 8014 statement: set "aou.aoeu" = 'aontuh';
Dec 02 13:59:57 ip-10-2-32-84 pgpool[7370]: 2019-12-02 13:59:57: pid 7407: LOG: DB node id: 0 backend pid: 8014 statement: select 1;

t-ishii

2019-12-03 09:15

developer   ~0002991

Last edited: 2019-12-03 09:16

 Got it. So the facts are:
1) Pgpool-II does cache the query result in a writing transaction (see my example)
2) Pgpool-II does *not* fetch existing cache entry in a writing transaction (see your example)

Let me think how I can do for (2).

subi

2019-12-03 14:52

reporter   ~0002992

If there are workarounds for now, plz let met know. We are quite axious to make the cache works ( for postgrest).

Best Regards.

t-ishii

2019-12-03 15:55

developer   ~0002993

BTW,
> why transaction with 'set' statement would always be marked as 'writing transaction', even it is began with 'read only'?

Really?

BEGIN;
SET transaction_read_only to on;
select * from t1;
From log:
2019-12-03 15:52:19: pid 32115: LOG: fetch from memory cache
2019-12-03 15:52:19: pid 32115: DETAIL: query result fetched from cache. statement: select * from t1;

subi

2019-12-03 16:43

reporter   ~0002994

Here are some detailed logs (debug3):


```BEGIN ISOLATION LEVEL READ COMMITTED READ ONLY; set transaction read only; select 1; commit;```

Dec 03 07:31:19 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:31:19: pid 5789: DEBUG: invoking the minimal parser
Dec 03 07:31:19 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:31:19: pid 5789: DEBUG: pool_create_temp_query_cache: cache created: 0x55b7074778e8
Dec 03 07:31:19 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:31:19: pid 5789: DEBUG: memcache: extracting table oids: statment is different from INSERT/UPDATE/DELETE/TRUNCATE/DROP TABLE/ALTER T
ABLE
Dec 03 07:31:19 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:31:19: pid 5789: LOG: DB node id: 0 backend pid: 7046 statement: BEGIN ISOLATION LEVEL READ COMMITTED READ ONLY;
Dec 03 07:31:19 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:31:19: pid 5789: DEBUG: waiting for query response
Dec 03 07:31:19 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:31:19: pid 5789: DETAIL: waiting for backend:0 to complete the query
Dec 03 07:31:19 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:31:19: pid 5789: DEBUG: memcache reset buffer
Dec 03 07:31:19 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:31:19: pid 5789: DETAIL: discard: 0x55b707477a38
Dec 03 07:31:19 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:31:19: pid 5789: DEBUG: memcache discarding query cache array
Dec 03 07:31:19 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:31:19: pid 5789: DETAIL: num_caches: 0
Dec 03 07:31:19 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:31:19: pid 5789: DEBUG: memcache reset buffer
Dec 03 07:31:19 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:31:19: pid 5789: DETAIL: create: 0x55b707477a38
Dec 03 07:31:19 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:31:19: pid 5789: DEBUG: memcache reset buffer
Dec 03 07:31:19 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:31:19: pid 5789: DETAIL: discard temp buffer of 0x55b707484b28 (BEGIN ISOLATION LEVEL READ COMMITTED READ ONLY;)
Dec 03 07:31:19 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:31:19: pid 5789: DEBUG: pool_discard_temp_query_cache: cache discarded: 0x55b7074778e8
Dec 03 07:31:30 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:31:30: pid 5789: DEBUG: invoking the minimal parser
Dec 03 07:31:30 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:31:30: pid 5789: DEBUG: pool_create_temp_query_cache: cache created: 0x55b7074778e8
Dec 03 07:31:30 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:31:30: pid 5789: DEBUG: memcache: extracting table oids: statment is different from INSERT/UPDATE/DELETE/TRUNCATE/DROP TABLE/ALTER T
ABLE
Dec 03 07:31:30 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:31:30: pid 5789: LOG: DB node id: 0 backend pid: 7046 statement: set transaction read only;
Dec 03 07:31:30 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:31:30: pid 5789: DEBUG: waiting for query response
Dec 03 07:31:30 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:31:30: pid 5789: DETAIL: waiting for backend:0 to complete the query
Dec 03 07:31:30 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:31:30: pid 5789: DEBUG: memcache reset buffer
Dec 03 07:31:30 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:31:30: pid 5789: DETAIL: discard: 0x55b707477a38
Dec 03 07:31:30 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:31:30: pid 5789: DEBUG: memcache discarding query cache array
Dec 03 07:31:30 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:31:30: pid 5789: DETAIL: num_caches: 0
Dec 03 07:31:30 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:31:30: pid 5789: DEBUG: memcache reset buffer
Dec 03 07:31:30 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:31:30: pid 5789: DETAIL: create: 0x55b707477a38
Dec 03 07:31:30 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:31:30: pid 5789: DEBUG: memcache reset buffer
Dec 03 07:31:30 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:31:30: pid 5789: DETAIL: discard temp buffer of 0x55b707484b28 (set transaction read only;)
Dec 03 07:31:30 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:31:30: pid 5789: DEBUG: pool_discard_temp_query_cache: cache discarded: 0x55b7074778e8
Dec 03 07:31:38 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:31:38: pid 5789: DEBUG: memcache: sending cached messages: 'C' len: 13
Dec 03 07:31:38 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:31:38: pid 5789: DEBUG: memcache: sending messages: kind 'C', len=13, data=0x55b707482b9b
Dec 03 07:31:38 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:31:38: pid 5789: DEBUG: memcache: sending messages: kind 'Z', len=5, data=0x7fff5b019d45
Dec 03 07:31:38 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:31:38: pid 5789: LOG: fetch from memory cache
Dec 03 07:31:38 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:31:38: pid 5789: DETAIL: query result fetched from cache. statement: select 1;
Dec 03 07:31:38 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:31:38: pid 5789: DEBUG: fetch from memory cache
Dec 03 07:31:38 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:31:38: pid 5789: DETAIL: query result found in the query cache, select 1;


```BEGIN ISOLATION LEVEL READ COMMITTED READ ONLY; set transaction read only; set application_name = 'foo'; select 1; select 1; commit;```

Dec 03 07:38:46 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:38:46: pid 5789: DEBUG: invoking the minimal parser
Dec 03 07:38:46 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:38:46: pid 5789: DEBUG: pool_create_temp_query_cache: cache created: 0x55b7074778e8
Dec 03 07:38:46 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:38:46: pid 5789: DEBUG: memcache: extracting table oids: statment is different from INSERT/UPDATE/DELETE/TRUNCATE/DROP TABLE/ALTER TABLE
Dec 03 07:38:46 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:38:46: pid 5789: LOG: DB node id: 0 backend pid: 7046 statement: BEGIN ISOLATION LEVEL READ COMMITTED READ ONLY;
Dec 03 07:38:46 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:38:46: pid 5789: DEBUG: waiting for query response
Dec 03 07:38:46 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:38:46: pid 5789: DETAIL: waiting for backend:0 to complete the query
Dec 03 07:38:46 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:38:46: pid 5789: DEBUG: memcache reset buffer
Dec 03 07:38:46 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:38:46: pid 5789: DETAIL: discard: 0x55b707477a38
Dec 03 07:38:46 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:38:46: pid 5789: DEBUG: memcache discarding query cache array
Dec 03 07:38:46 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:38:46: pid 5789: DETAIL: num_caches: 0
Dec 03 07:38:46 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:38:46: pid 5789: DEBUG: memcache reset buffer
Dec 03 07:38:46 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:38:46: pid 5789: DETAIL: create: 0x55b707477a38
Dec 03 07:38:46 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:38:46: pid 5789: DEBUG: memcache reset buffer
Dec 03 07:38:46 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:38:46: pid 5789: DETAIL: discard temp buffer of 0x55b707484b28 (BEGIN ISOLATION LEVEL READ COMMITTED READ ONLY;)
Dec 03 07:38:46 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:38:46: pid 5789: DEBUG: pool_discard_temp_query_cache: cache discarded: 0x55b7074778e8
Dec 03 07:39:14 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:39:14: pid 5789: DEBUG: invoking the minimal parser
Dec 03 07:39:14 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:39:14: pid 5789: DEBUG: pool_create_temp_query_cache: cache created: 0x55b7074778e8
Dec 03 07:39:14 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:39:14: pid 5789: DEBUG: memcache: extracting table oids: statment is different from INSERT/UPDATE/DELETE/TRUNCATE/DROP TABLE/ALTER TABLE
Dec 03 07:39:14 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:39:14: pid 5789: LOG: DB node id: 0 backend pid: 7046 statement: set transaction read only;
Dec 03 07:39:14 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:39:14: pid 5789: DEBUG: waiting for query response
Dec 03 07:39:14 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:39:14: pid 5789: DETAIL: waiting for backend:0 to complete the query
Dec 03 07:39:14 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:39:14: pid 5789: DEBUG: memcache reset buffer
Dec 03 07:39:14 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:39:14: pid 5789: DETAIL: discard: 0x55b707477a38
Dec 03 07:39:14 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:39:14: pid 5789: DEBUG: memcache discarding query cache array
Dec 03 07:39:14 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:39:14: pid 5789: DETAIL: num_caches: 0
Dec 03 07:39:14 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:39:14: pid 5789: DEBUG: memcache reset buffer
Dec 03 07:39:14 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:39:14: pid 5789: DETAIL: create: 0x55b707477a38
Dec 03 07:39:14 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:39:14: pid 5789: DEBUG: memcache reset buffer
Dec 03 07:39:14 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:39:14: pid 5789: DETAIL: discard temp buffer of 0x55b707484b28 (set transaction read only;)
Dec 03 07:39:14 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:39:14: pid 5789: DEBUG: pool_discard_temp_query_cache: cache discarded: 0x55b7074778e8
Dec 03 07:40:39 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:40:39: pid 5789: DEBUG: invoking the minimal parser
Dec 03 07:40:39 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:40:39: pid 5789: DEBUG: pool_create_temp_query_cache: cache created: 0x55b7074778e8
Dec 03 07:40:39 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:40:39: pid 5789: DEBUG: memcache: extracting table oids: statment is different from INSERT/UPDATE/DELETE/TRUNCATE/DROP TABLE/ALTER TABLE
Dec 03 07:40:39 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:40:39: pid 5789: LOG: DB node id: 0 backend pid: 7046 statement: set application_name = 'foo';
Dec 03 07:40:39 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:40:39: pid 5789: DEBUG: waiting for query response
Dec 03 07:40:39 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:40:39: pid 5789: DETAIL: waiting for backend:0 to complete the query
Dec 03 07:40:39 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:40:39: pid 5789: DEBUG: not SET TRANSACTION READ ONLY
Dec 03 07:40:39 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:40:39: pid 5789: DEBUG: memcache reset buffer
Dec 03 07:40:39 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:40:39: pid 5789: DETAIL: discard: 0x55b707477a38
Dec 03 07:40:39 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:40:39: pid 5789: DEBUG: memcache discarding query cache array
Dec 03 07:40:39 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:40:39: pid 5789: DETAIL: num_caches: 0
Dec 03 07:40:39 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:40:39: pid 5789: DEBUG: memcache reset buffer
Dec 03 07:40:39 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:40:39: pid 5789: DETAIL: create: 0x55b707477a38
Dec 03 07:40:39 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:40:39: pid 5789: DEBUG: memcache reset buffer
Dec 03 07:40:39 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:40:39: pid 5789: DETAIL: discard temp buffer of 0x55b707484b28 (set application_name = 'foo';)
Dec 03 07:40:39 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:40:39: pid 5789: DEBUG: pool_discard_temp_query_cache: cache discarded: 0x55b7074778e8

Dec 03 07:41:00 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:41:00: pid 5789: DEBUG: invoking the minimal parser
Dec 03 07:41:00 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:41:00: pid 5789: DEBUG: pool_create_temp_query_cache: cache created: 0x55b7074778e8
Dec 03 07:41:00 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:41:00: pid 5789: DEBUG: checking if query has INSERT INTO, FOR SHARE or FOR UPDATE
Dec 03 07:41:00 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:41:00: pid 5789: DETAIL: result = 0
Dec 03 07:41:00 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:41:00: pid 5789: DEBUG: checking if SELECT statement contains the IMMUTABLE function call
Dec 03 07:41:00 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:41:00: pid 5789: DETAIL: result = 0
Dec 03 07:41:00 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:41:00: pid 5789: LOG: DB node id: 0 backend pid: 7046 statement: select 1;
Dec 03 07:41:00 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:41:00: pid 5789: DEBUG: waiting for query response
Dec 03 07:41:00 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:41:00: pid 5789: DETAIL: waiting for backend:0 to complete the query
Dec 03 07:41:00 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:41:00: pid 5789: DEBUG: memcache adding data to internal buffer
Dec 03 07:41:00 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:41:00: pid 5789: DETAIL: realloc old size:0 new size:8192
Dec 03 07:41:00 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:41:00: pid 5789: DEBUG: memcache adding data to internal buffer
Dec 03 07:41:00 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:41:00: pid 5789: DETAIL: len:1, total:1 bufsize:8192
Dec 03 07:41:00 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:41:00: pid 5789: DEBUG: memcache adding data to internal buffer
Dec 03 07:41:00 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:41:00: pid 5789: DETAIL: len:4, total:5 bufsize:8192
Dec 03 07:41:00 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:41:00: pid 5789: DEBUG: memcache adding data to internal buffer
Dec 03 07:41:00 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:41:00: pid 5789: DETAIL: len:29, total:34 bufsize:8192
Dec 03 07:41:00 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:41:00: pid 5789: DEBUG: memcache adding data to internal buffer
Dec 03 07:41:00 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:41:00: pid 5789: DETAIL: len:1, total:35 bufsize:8192
Dec 03 07:41:00 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:41:00: pid 5789: DEBUG: memcache adding data to internal buffer
Dec 03 07:41:00 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:41:00: pid 5789: DETAIL: len:4, total:39 bufsize:8192
Dec 03 07:41:00 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:41:00: pid 5789: DEBUG: memcache adding data to internal buffer
Dec 03 07:41:00 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:41:00: pid 5789: DETAIL: len:7, total:46 bufsize:8192
Dec 03 07:41:00 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:41:00: pid 5789: DEBUG: memcache adding data to internal buffer
Dec 03 07:41:00 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:41:00: pid 5789: DETAIL: len:1, total:47 bufsize:8192
Dec 03 07:41:00 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:41:00: pid 5789: DEBUG: memcache adding data to internal buffer
Dec 03 07:41:00 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:41:00: pid 5789: DETAIL: len:4, total:51 bufsize:8192
Dec 03 07:41:00 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:41:00: pid 5789: DEBUG: memcache adding data to internal buffer
Dec 03 07:41:00 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:41:00: pid 5789: DETAIL: len:9, total:60 bufsize:8192
Dec 03 07:41:00 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:41:00: pid 5789: DEBUG: query cache handler for ReadyForQuery
Dec 03 07:41:00 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:41:00: pid 5789: DETAIL: num_oids: 0 oid: 0
Dec 03 07:41:00 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:41:00: pid 5789: DEBUG: memcache adding query cache array
Dec 03 07:41:00 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:41:00: pid 5789: DETAIL: num_caches: 0 cache: 0x55b7074778e8
Dec 03 07:41:14 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:41:14: pid 5789: DEBUG: invoking the minimal parser
Dec 03 07:41:14 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:41:14: pid 5789: DEBUG: pool_create_temp_query_cache: cache created: 0x55b7074776c8
Dec 03 07:41:14 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:41:14: pid 5789: DEBUG: checking if query has INSERT INTO, FOR SHARE or FOR UPDATE
Dec 03 07:41:14 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:41:14: pid 5789: DETAIL: result = 0
Dec 03 07:41:14 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:41:14: pid 5789: DEBUG: checking if SELECT statement contains the IMMUTABLE function call
Dec 03 07:41:14 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:41:14: pid 5789: DETAIL: result = 0
Dec 03 07:41:14 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:41:14: pid 5789: LOG: DB node id: 0 backend pid: 7046 statement: select 1;
Dec 03 07:41:14 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:41:14: pid 5789: DEBUG: waiting for query response
Dec 03 07:41:14 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:41:14: pid 5789: DETAIL: waiting for backend:0 to complete the query
Dec 03 07:41:14 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:41:14: pid 5789: DEBUG: memcache adding data to internal buffer
Dec 03 07:41:14 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:41:14: pid 5789: DETAIL: realloc old size:0 new size:8192
Dec 03 07:41:14 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:41:14: pid 5789: DEBUG: memcache adding data to internal buffer
Dec 03 07:41:14 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:41:14: pid 5789: DETAIL: len:1, total:1 bufsize:8192
Dec 03 07:41:14 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:41:14: pid 5789: DEBUG: memcache adding data to internal buffer
Dec 03 07:41:14 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:41:14: pid 5789: DETAIL: len:4, total:5 bufsize:8192
Dec 03 07:41:14 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:41:14: pid 5789: DEBUG: memcache adding data to internal buffer
Dec 03 07:41:14 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:41:14: pid 5789: DETAIL: len:29, total:34 bufsize:8192
Dec 03 07:41:14 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:41:14: pid 5789: DEBUG: memcache adding data to internal buffer
Dec 03 07:41:14 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:41:14: pid 5789: DETAIL: len:1, total:35 bufsize:8192
Dec 03 07:41:14 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:41:14: pid 5789: DEBUG: memcache adding data to internal buffer
Dec 03 07:41:14 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:41:14: pid 5789: DETAIL: len:4, total:39 bufsize:8192
Dec 03 07:41:14 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:41:14: pid 5789: DEBUG: memcache adding data to internal buffer
Dec 03 07:41:14 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:41:14: pid 5789: DETAIL: len:7, total:46 bufsize:8192
Dec 03 07:41:14 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:41:14: pid 5789: DEBUG: memcache adding data to internal buffer
Dec 03 07:41:14 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:41:14: pid 5789: DETAIL: len:1, total:47 bufsize:8192
Dec 03 07:41:14 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:41:14: pid 5789: DEBUG: memcache adding data to internal buffer
Dec 03 07:41:14 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:41:14: pid 5789: DETAIL: len:4, total:51 bufsize:8192
Dec 03 07:41:14 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:41:14: pid 5789: DEBUG: memcache adding data to internal buffer
Dec 03 07:41:14 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:41:14: pid 5789: DETAIL: len:9, total:60 bufsize:8192
Dec 03 07:41:14 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:41:14: pid 5789: DEBUG: query cache handler for ReadyForQuery
Dec 03 07:41:14 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:41:14: pid 5789: DETAIL: num_oids: 0 oid: 0
Dec 03 07:41:14 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:41:14: pid 5789: DEBUG: memcache adding query cache array
Dec 03 07:41:14 ip-10-2-32-84 pgpool[5726]: 2019-12-03 07:41:14: pid 5789: DETAIL: num_caches: 1 cache: 0x55b7074776c8

t-ishii

2019-12-03 16:53

developer   ~0002995

So what's the point of this log? What I said in the former message was, "set transaction read only" does not set writing transaction flag. But you seems to demonstrate that "set application_name = 'foo'" sets writing transaction flag, which I already agreed.

t-ishii

2019-12-03 16:57

developer   ~0002996

> If there are workarounds for now, plz let met know.
There's no workaround for this. The only way to solve the issue is patching Pgpool-II. Attached patch disables to set writing transaction flag for *all* set commands. For now all of regression tests passed and I cannot think of any bad side effect of the patch. So please test the patch if you like.
enable_query_cache_even_with_set.diff (649 bytes)    


 enable_query_cache_even_with_set.diff (649 bytes)   
			




	




		
		
		

		

		

			 subi		

		

						2019-12-03 17:13					

		

			reporter			 
									
				~0002997			
					

				

		

		

				

		

			
	
	> why transaction with 'set' statement would always be marked as 'writing transaction', even it is began with 'read only'?



I admit that the title may be misleading. To make it clear, I mean, if any transaction starts with 'begin read only', and uses any 'set' statements (excluding 'set transaction read only', of course), the transaction would be marked as writing transaction.			




	




		
		
		

		

		

			 subi		

		

						2019-12-03 17:14					

		

			reporter			 
									
				~0002998			
					

				

		

		

				

		

			
	
	> There's no workaround for this. The only way to solve the issue is patching Pgpool-II. Attached patch disables to set writing transaction flag for *all* set commands. For now all of regression tests passed and I cannot think of any bad side effect of the patch. So please test the patch if you like.



Thanks. I will test it.			




	




		
		
		

		

		

			 t-ishii		

		

						2019-12-03 17:26					

		

			developer			 
									
				~0002999			
					

				

		

		

				

		

			
	
	Oops. Please disregard previous patch.


 enable_query_cache_even_with_set_v2.diff (1,177 bytes)   



 enable_query_cache_even_with_set_v2.diff (1,177 bytes)   
			




	




		
		
		

		

		

			 subi		

		

						2019-12-05 22:08					

		

			reporter			 
									
				~0003004			
					

				

		

		

				

		

			
	
	The patch works. Thanks a lot.	




	




		
		
		

		

		

			 t-ishii		

		

						2019-12-06 11:24					

		

			developer			 
									
				~0003006			
					

				

		

		

				

		

			
	
	May I close this issue?	




	




		
		
		

		

		

			 subi		

		

						2019-12-06 11:55					

		

			reporter			 
									
				~0003009			
					

				

		

		

				

		

			
	
	Yes please.



Regards.			




	














	

		
		

	
		

	

		

						Issue History		

		

			
							
		

	

	

	

	

	

		
			

				
					Date Modified				
				
					Username				
				
					Field				
				
					Change				
			

		
	
		
				

				
					2019-11-30 23:30				
				
					subi				
				
					New Issue				
				
									
			

				

				
					2019-11-30 23:30				
				
					subi				
				
					Tag Attached: query cache				
				
									
			

				

				
					2019-12-02 15:25				
				
					t-ishii				
				
					Note Added: 0002986				
				
									
			

				

				
					2019-12-02 15:25				
				
					t-ishii				
				
					Assigned To				
				
					 => t-ishii				
			

				

				
					2019-12-02 15:25				
				
					t-ishii				
				
					Status				
				
					new => feedback				
			

				

				
					2019-12-02 16:18				
				
					t-ishii				
				
					Note Edited: 0002986				
				
									
			

				

				
					2019-12-02 19:39				
				
					subi				
				
					Note Added: 0002988				
				
									
			

				

				
					2019-12-02 19:39				
				
					subi				
				
					Status				
				
					feedback => assigned				
			

				

				
					2019-12-02 22:44				
				
					t-ishii				
				
					Note Added: 0002989				
				
									
			

				

				
					2019-12-02 23:05				
				
					subi				
				
					Note Added: 0002990				
				
									
			

				

				
					2019-12-03 09:15				
				
					t-ishii				
				
					Note Added: 0002991				
				
									
			

				

				
					2019-12-03 09:15				
				
					t-ishii				
				
					Note Edited: 0002991				
				
									
			

				

				
					2019-12-03 09:16				
				
					t-ishii				
				
					Note Edited: 0002991				
				
									
			

				

				
					2019-12-03 14:52				
				
					subi				
				
					Note Added: 0002992				
				
									
			

				

				
					2019-12-03 15:55				
				
					t-ishii				
				
					Note Added: 0002993				
				
									
			

				

				
					2019-12-03 16:43				
				
					subi				
				
					Note Added: 0002994				
				
									
			

				

				
					2019-12-03 16:53				
				
					t-ishii				
				
					Note Added: 0002995				
				
									
			

				

				
					2019-12-03 16:57				
				
					t-ishii				
				
					File Added: enable_query_cache_even_with_set.diff				
				
									
			

				

				
					2019-12-03 16:57				
				
					t-ishii				
				
					Note Added: 0002996				
				
									
			

				

				
					2019-12-03 17:13				
				
					subi				
				
					Note Added: 0002997				
				
									
			

				

				
					2019-12-03 17:14				
				
					subi				
				
					Note Added: 0002998				
				
									
			

				

				
					2019-12-03 17:26				
				
					t-ishii				
				
					File Added: enable_query_cache_even_with_set_v2.diff				
				
									
			

				

				
					2019-12-03 17:26				
				
					t-ishii				
				
					Note Added: 0002999				
				
									
			

				

				
					2019-12-04 09:05				
				
					t-ishii				
				
					Status				
				
					assigned => feedback				
			

				

				
					2019-12-05 22:08				
				
					subi				
				
					Note Added: 0003004				
				
									
			

				

				
					2019-12-05 22:08				
				
					subi				
				
					Status				
				
					feedback => assigned				
			

				

				
					2019-12-06 11:24				
				
					t-ishii				
				
					Note Added: 0003006				
				
									
			

				

				
					2019-12-06 11:55				
				
					subi				
				
					Note Added: 0003009				
				
									
			

				

				
					2019-12-10 10:15				
				
					t-ishii				
				
					Status				
				
					assigned => closed