[pgpool-general: 9446] Re: Clarification on query results cache visibility

Achilleas Mantzios - cloud a.mantzios at cloud.gatewaynet.com
Tue Apr 29 17:17:47 JST 2025 

On 4/29/25 08:32, Tatsuo Ishii wrote:

> Hello Achilleas,
>
> It turned out that it's a bug of pgpool. When an execute message is
> received, pgpool checks for the parameter of max number of rows to
> return in the execute message. If it's not zero, pgpool sets
> "partial_fetch" flag to receive rows from the portal in the next
> execute message. Problem is, pgpool applied this to even none read
> only SELECTs (INSERT/UPDATE/DELETE) which results in failing to
> invalidate query cache because if the flag is true, subsequent code
> (pool_handle_query_cache) assumes that it's a read only SELECT.
> That's the reason why you see the old value through query cache.
>
> It was an oversight in this commit (my fault):
> https://git.postgresql.org/gitweb/?p=pgpool2.git;a=commit;h=2a99aa5d1910f1fd4855c8eb6751a26cbaa5e48d
>
> Attached is a patch to fix this. In my environment the java test
> program now prints correct results.

Thank you a lot for such a quick response ! I applied, and re-run the 
test, it works correctly.

We will keep testing as in live conditions, with wildfly , etc.

I don't understand two things :

- I also tested a non-prepare statement version of the java test, when 
run against 5432 (pgsql) the pgsql logs showed only Execute(s) as 
expected. When run via 9999 (pgpool),  the pgpool logs showed : 
Parse/Bind/Execute flow as if they were Prepared Statements.

- Why didn't the problem manifest itself during the sql-only tests, why 
we could not replicate it with plain SQL?

>
> Best regards,
> --
> Tatsuo Ishii
> SRA OSS K.K.
> English: http://www.sraoss.co.jp/index_en/
> Japanese:http://www.sraoss.co.jp
>
>> Thank you for the self contained test case! I will try to run it and
>> get back to you if I find something.
>>
>>> Dear Tatsuo
>>>
>>> here is a simple java program that exhibits it all . I attach it. Also
>>> I attach the class for you to be able to run it more easily.
>>>
>>> no inheritance, no schema magic needed. It works on the very single
>>> table .
>>>
>>> amantzio@[local]/dynacom=# \d testpgpool
>>>                      Table "public.testpgpool"
>>>   Column  |          Type          | Collation | Nullable | Default
>>> ----------+------------------------+-----------+----------+---------
>>> username | character varying(200) |           | not null |
>>> app      | text                   |           | not null |
>>> detail   | text                   |           | not null |
>>> urlext   | text                   |           | not null |
>>> Indexes:
>>>     "testpgpool_pkey" PRIMARY KEY, btree (username, app, detail)
>>>
>>> place the class inside a dir named : test like :
>>>
>>> achix at achix-xps159550:~/eclipse-workspace/PgPoolTest/bin$ pwd
>>> /home/achix/eclipse-workspace/PgPoolTest/bin
>>> achix at achix-xps159550:~/eclipse-workspace/PgPoolTest/bin$ ls
>>> test
>>> achix at achix-xps159550:~/eclipse-workspace/PgPoolTest/bin$ ls test/
>>> PgPoolTest.class
>>> achix at achix-xps159550:~/eclipse-workspace/PgPoolTest/bin$
>>>
>>> then run it from the current dir  (the one how contains dir test) as :
>>>
>>> java -cp ".:/home/achix/Downloads/postgresql-42.7.5.jar"
>>> test.PgPoolTest <your_pgpool_host> <your_pgpool_port> <your_db_name>
>>> user password
>>>
>>>
>>> as it runs (and you can see clearly that it does not append z1 in
>>> every run as it should), please go to a shell and type :
>>>
>>> /usr/local/pgpool/bin/pcp_invalidate_query_cache
>>>
>>> you will now see the last real data read (with the
>>> perfurlext=?groupno=yesz1)
>>>
>>> and giving pcp_invalidate_query_cache again, will cause the program to
>>> yield : perfurlext=?groupno=yesz1z1 and so forth.
>>>
>>>
>>> On 28/4/25 10:58, Achilleas Mantzios - cloud wrote:
>>>> Good Day Tatsuo
>>>>
>>>> I have not been able to reproduce via sql .
>>>>
>>>> I will provide full log of pgpool as in the app (java) we didn't get
>>>> any useful logs , only entries like :
>>>>
>>>> 2025-04-28 10:07:01,717 WARN
>>>>   [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (default task-35)
>>>> SQL Warning Code: 0, SQLState: XX000
>>>> 2025-04-28 10:07:01,717 WARN
>>>>   [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (default task-35)
>>>> Parse message from frontend.
>>>> 2025-04-28 10:07:01,717 WARN
>>>>   [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (default task-35)
>>>> SQL Warning Code: 0, SQLState: XX000
>>>> 2025-04-28 10:07:01,717 WARN
>>>>   [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (default task-35)
>>>> DB node id: 0 backend pid: 34753 statement: Parse: COMMIT
>>>> 2025-04-28 10:07:01,717 WARN
>>>>   [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (default task-35)
>>>> SQL Warning Code: 0, SQLState: XX000
>>>> 2025-04-28 10:07:01,717 WARN
>>>>   [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (default task-35)
>>>> Bind message from frontend.
>>>> 2025-04-28 10:07:01,717 WARN
>>>>   [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (default task-35)
>>>> SQL Warning Code: 0, SQLState: XX000
>>>> 2025-04-28 10:07:01,717 WARN
>>>>   [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (default task-35)
>>>> DB node id: 0 backend pid: 34753 statement: Bind: COMMIT
>>>> 2025-04-28 10:07:01,717 WARN
>>>>   [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (default task-35)
>>>> SQL Warning Code: 0, SQLState: XX000
>>>> 2025-04-28 10:07:01,717 WARN
>>>>   [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (default task-35)
>>>> Execute message from frontend.
>>>> 2025-04-28 10:07:01,717 WARN
>>>>   [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (default task-35)
>>>> SQL Warning Code: 0, SQLState: XX000
>>>> 2025-04-28 10:07:01,717 WARN
>>>>   [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (default task-35)
>>>> DB node id: 0 backend pid: 34753 statement: Execute: COMMIT
>>>> 2025-04-28 10:07:01,717 WARN
>>>>   [org.hibernate.engine.jdbc.spi.SqlExceptionHelper] (default task-35)
>>>> SQL Warning Code: 0, SQLState: XX000
>>>>
>>>> which do not seem to contain any useful info.
>>>>
>>>> Please disregard any noise in the logs, we are interested on
>>>> useroptions .
>>>>
>>>> The scenario goes like :
>>>>
>>>> 1) Front page queries the db for a specific useroption for a subapp
>>>> (saved from a previous click from within that app, we will look into
>>>> this later in step 2).
>>>>
>>>> The prepared stmt is :
>>>>
>>>> SELECT app, urlext FROM useroptions WHERE username = ? AND app IN
>>>> ('status', 'performreport', 'freshwater', 'comms') AND detail = '';
>>>>
>>>> User name in our tests will be 'Achilleas Mantzios'
>>>>
>>>> The front page uses this result to build the url for the Performance
>>>> Report subapp .
>>>>
>>>> 2) Then the user clicks into the Performance Report subapp , and makes
>>>> some clicks / selections which the app tries to store in
>>>> useroptions. It does so by investigating if there is any option
>>>> already stored or not. By issuing prep stmt:
>>>>
>>>> select 1 from useroptions where username=? and app='performreport' and
>>>> detail=''
>>>>
>>>>  From the result it decides whether to insert or update (back then
>>>> there was no upsert so the app stayed that way), and stores the users
>>>> selections inside the app, depending on the result from the above
>>>> select by either :
>>>>
>>>> insert into useroptions(username,app,detail,urlext)
>>>> values('"+username+"','performreport','',?)
>>>>
>>>> or
>>>>
>>>> update useroptions set urlext=? where username='"+username+"' and
>>>> app='performreport' and detail=''
>>>>
>>>> 3) then by visiting the front page again, (like in1) the front page
>>>> queries
>>>>
>>>> SELECT app, urlext FROM useroptions WHERE username = ? AND app IN
>>>> ('status', 'performreport', 'freshwater', 'comms') AND detail = '';
>>>>
>>>> and presents the new saved options to the Performance Report subapp .
>>>>
>>>> The problem that my colleague found is that while in 2) and making a
>>>> selection, although being stored correctly in the DB, however, by
>>>> clicking on the home page again, the user sees the initially fetched
>>>> result and not the just updated one.
>>>>
>>>> Now I will present the actual test scenario pgpool log and some
>>>> queries from psql :
>>>>
>>>> Initially we have , straight from the db
>>>>
>>>> achill at smadevnu:~ % psql
>>>> psql (17.4)
>>>> Type "help" for help.
>>>>
>>>> amantzio@[local]/dynacom=# SET application_name to 'SMA ';select
>>>> set_search_path('bdynacom,epaybdynacom,epay');
>>>> SET
>>>> set_search_path
>>>> -----------------
>>>>
>>>> (1 row)
>>>>
>>>> amantzio@[local]/dynacom=# select * from useroptions where username =
>>>> 'Achilleas Mantzios';
>>>>       username      |      app      | detail |        urlext
>>>> --------------------+---------------+--------+----------------------
>>>> Achilleas Mantzios | performreport |        | ?group=yes&groupno=7
>>>> (1 row)
>>>>
>>>> amantzio@[local]/dynacom=#
>>>>
>>>> Now I login to the app, via the front page, indeed the url I get for
>>>> this subapp inside the front page is :
>>>>
>>>> https://localhost:8443/sma/pr/perfleet?group=yes&groupno=7
>>>>
>>>> Now I click into the supapp and now choose group 1 :
>>>>
>>>> It correctly stores it in the db :
>>>>
>>>> achill at smadevnu:~ % psql
>>>> psql (17.4)
>>>> Type "help" for help.
>>>>
>>>> amantzio@[local]/dynacom=# SET application_name to 'SMA ';select
>>>> set_search_path('bdynacom,epaybdynacom,epay');
>>>> SET
>>>> set_search_path
>>>> -----------------
>>>>
>>>> (1 row)
>>>>
>>>> amantzio@[local]/dynacom=# select * from useroptions where username =
>>>> 'Achilleas Mantzios';
>>>>       username      |      app      | detail |        urlext
>>>> --------------------+---------------+--------+----------------------
>>>> Achilleas Mantzios | performreport |        | ?group=yes&groupno=1
>>>> (1 row)
>>>>
>>>> amantzio@[local]/dynacom=#
>>>>
>>>> Now I click on the home page , but there I still see the stale initial
>>>> https://localhost:8443/sma/pr/perfleet?group=yes&groupno=7 url !!
>>>>
>>>>  From psql I get the correct  results , cannot reproduce :
>>>>
>>>> achill at smadevnu:~ % psql -p 9999
>>>> psql (17.4)
>>>> Type "help" for help.
>>>>
>>>> amantzio@[local]/dynacom=# SET application_name to 'SMA ';select
>>>> set_search_path('bdynacom,epaybdynacom,epay');
>>>> LOG:  Query message from frontend.
>>>> DETAIL:  query: "SET application_name to 'SMA ';"
>>>> LOG:  DB node id: 0 backend pid: 35636 statement: SELECT
>>>> pg_catalog.version()
>>>> LOG:  DB node id: 0 backend pid: 35636 statement: SET application_name
>>>> to 'SMA ';
>>>> SET
>>>> LOG:  Query message from frontend.
>>>> DETAIL:  query: "select
>>>> set_search_path('bdynacom,epaybdynacom,epay');"
>>>> LOG:  DB node id: 0 backend pid: 35636 statement: SELECT count(*) FROM
>>>> pg_catalog.pg_proc AS p, pg_catalog.pg_namespace AS n WHERE p.proname
>>>> = 'set_search_path' AND n.oid = p.pronamespace
>>>> AND n.nspname ~ '.*' AND p.provolatile = 'i'
>>>> LOG:  DB node id: 0 backend pid: 35636 statement: SELECT count(*) FROM
>>>> pg_catalog.pg_proc AS p, pg_catalog.pg_namespace AS n WHERE p.proname
>>>> = 'set_search_path' AND n.oid = p.pronamespace
>>>> AND n.nspname ~ '.*' AND p.provolatile = 'v'
>>>> LOG:  DB node id: 0 backend pid: 35636 statement: select
>>>> set_search_path('bdynacom,epaybdynacom,epay');
>>>> set_search_path
>>>> -----------------
>>>>
>>>> (1 row)
>>>>
>>>> amantzio@[local]/dynacom=# PREPARE foost(text) AS SELECT app, urlext
>>>> FROM useroptions WHERE username = $1  AND app IN ('status',
>>>> 'performreport', 'freshwater', 'comms') AND detail = '';
>>>> LOG:  Query message from frontend.
>>>> DETAIL:  query: "PREPARE foost(text) AS SELECT app, urlext FROM
>>>> useroptions WHERE username = $1  AND app IN ('status',
>>>> 'performreport', 'freshwater', 'comms') AND detail = '';"
>>>> LOG:  DB node id: 0 backend pid: 35636 statement: PREPARE foost(text)
>>>> AS SELECT app, urlext FROM useroptions WHERE username = $1  AND app IN
>>>> ('status', 'performreport', 'freshwater', 'comm
>>>> s') AND detail = '';
>>>> PREPARE
>>>> amantzio@[local]/dynacom=#
>>>> amantzio@[local]/dynacom=# EXECUTE foost('Achilleas Mantzios');
>>>> LOG:  Query message from frontend.
>>>> DETAIL:  query: "EXECUTE foost('Achilleas Mantzios');"
>>>> LOG:  DB node id: 0 backend pid: 35636 statement: EXECUTE
>>>> foost('Achilleas Mantzios');
>>>>       app      |        urlext
>>>> ---------------+----------------------
>>>> performreport | ?group=yes&groupno=1
>>>> (1 row)
>>>>
>>>> amantzio@[local]/dynacom=# SELECT app, urlext FROM useroptions WHERE
>>>> username = 'Achilleas Mantzios'  AND app IN ('status',
>>>> 'performreport', 'freshwater', 'comms') AND detail = '';
>>>> LOG:  Query message from frontend.
>>>> DETAIL:  query: "SELECT app, urlext FROM useroptions WHERE username =
>>>> 'Achilleas Mantzios'  AND app IN ('status', 'performreport',
>>>> 'freshwater', 'comms') AND detail = '';"
>>>>       app      |        urlext
>>>> ---------------+----------------------
>>>> performreport | ?group=yes&groupno=1
>>>> (1 row)
>>>>
>>>> LOG:  fetch from memory cache
>>>> DETAIL:  query result fetched from cache. statement: SELECT app,
>>>> urlext FROM useroptions WHERE username = 'Achilleas Mantzios'  AND app
>>>> IN ('status', 'performreport', 'freshwater', 'comms'
>>>> ) AND detail = '';
>>>> amantzio@[local]/dynacom=#
>>>>
>>>> More clicks on the front page , still the old reslut :
>>>> ?group=yes&groupno=7
>>>>
>>>> I supply the full pgpool log. Please specify if we can do anything
>>>> more.
>>>>
>>>>
>>>> _______________________________________________
>>>> pgpool-general mailing list
>>>> pgpool-general at pgpool.net
>>>> http://www.pgpool.net/mailman/listinfo/pgpool-general
>> _______________________________________________
>> pgpool-general mailing list
>> pgpool-general at pgpool.net
>> http://www.pgpool.net/mailman/listinfo/pgpool-general

More information about the pgpool-general mailing list