[pgpool-general: 9444] Re: Clarification on query results cache visibility
Tatsuo Ishii
ishii at postgresql.org
Tue Apr 29 09:01:17 JST 2025
Hellow Achilleas,
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
More information about the pgpool-general
mailing list