[pgpool-general: 9445] Re: Clarification on query results cache visibility
Tatsuo Ishii
ishii at postgresql.org
Tue Apr 29 16:32:45 JST 2025
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.
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
-------------- next part --------------
A non-text attachment was scrubbed...
Name: query_cache.patch
Type: text/x-patch
Size: 1280 bytes
Desc: not available
URL: <http://www.pgpool.net/pipermail/pgpool-general/attachments/20250429/b26d5718/attachment.bin>
More information about the pgpool-general
mailing list