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

[Achilleas Mantzios]

Hello Tatsuo

On 27/4/25 15:01, Tatsuo Ishii wrote:
>>>> I'm confused. So the search_path is literary always constant (not
>>>> something like '$user,public'), or the search_path is changed by
>>>> set_search_path?
>>> the app (wildfly) has this in the conf :
>>>
>>> <new-connection-sql>SET application_name to 'SMA ';select
>>> set_search_path('bdynacom,epaybdynacom,epay');</new-connection-sql>
>>>
>>> This function does some logic and then sets the search path: so by
>>> calling it with the above argument values it yields :
>>> anonym,bdynacom,epaybdynacom,epay,"$user", public
>>>
>>> So the potentially relevant schemata here are  the ones that contain
>>> our tables  useroptions : bdynacom and public.
>>>
>>> The above is called at the start of the connection, only. No search
>>> path setting in the code. We base our multi-tenancy on this technique
>>> to be more precise, so every tenant application sets its own search
>>> path, but only once at the start of the connection. So all insertions
>>> and selects and updates happen on the unqualified table : useroptions,
>>> which is bdynacom.useroptions.
> Ok, the search_path is set by the app and only bdynacom and public
> include useroptions table.
>
>>> *The problem was discovered inside the same app, with same
>>> *search_path,  with the same user, it inserted the new value, but could
>>> *not read it. We were unable to reproduce this with plain SQL.*
> That's unfortunatete.
>
>>> So we may need to try to reproduce it with java and send you the full
>>> working bug. Would you like us to to do this?
> No, I am not familiar with Java applications.

Ok, the JDBC driver handles prepared statements using the low level 
protocol : Parse, Bind, Execute flow (Extended Query protocol):

https://jdbc.postgresql.org/documentation/server-prepare/#server-prepared-statements

https://www.postgresql.org/docs/current/protocol-flow.html#PROTOCOL-FLOW-EXT-QUERY

If the low level protocol is involved somehow in the bug I am unaware 
how it could be reproduced. But at the moment we are unsure about this.

>
>>  From the tests I am doing today, I am very confident that this hasn't
>> got to do with search_path.
>>
>> It is like it created a "hidden" cache entry that is only surfacing
>> under some conditions.
>>
>> Please look :
> How did you set search_path? According to the explanation above, the
> search_path was set by Java app.

Like I wrote before :

<new-connection-sql>SET application_name to 'SMA ';select set_search_path('bdynacom,epaybdynacom,epay');</new-connection-sql>

it runs the above at the start of every connection.

>
>> straight to pgsql :
>>
>> achill at smadevnu:~ % psql -U amantzio
> Maybe you forgot to copy database name here? I am asking because if
> the database name is missing, psql will connect to "amantzio"
> database, which is different database from the pgpool session.
No,  I am using PgSQL since 2000, I'd be a very lousy dba if I made such 
mistakes. |PGDATABASE is set to : dynacom , and there is no db : amantzio.
|
>
>> psql (17.4)
>> Type "help" for help.
>>
>> amantzio@[local]/dynacom=# SELECT tableoid::regclass, app, urlext FROM
>> useroptions WHERE username = 'Achilleas
>> Mantzios' AND app IN ('performreport') AND detail = '';
>>        tableoid       |      app      |        urlext
>> ----------------------+---------------+----------------------
>> bdynacom.useroptions | performreport | *?group=yes&groupno=7 <-- real
>> value*
>> (1 row)
>>
>> marked as bold above is the correct value (real value).
> Ok.
>
>> 1st pgpool session :
>>
>> achill at smadevnu:~ % psql -p 9999 -U amantzio dynacom
>> psql (17.4)
>> Type "help" for help.
>>
>> amantzio@[local]/dynacom=# SELECT app, urlext FROM useroptions WHERE
>> username = 'Achilleas Mantzios' AND app IN ('performreport') AND d
>> etail = '';
>>       app      |        urlext
>> ---------------+----------------------
>> performreport | *?group=yes&groupno=2  <-- old value*
>> (1 row)
> Before starting the query, can you set below?
> pgpool set log_per_node_statement = on;
> pgpool set client_min_messages = log;
>
> (you can also set these in pgpool.conf as:
> log_per_node_statement = on
> set client_min_messages = log)
>
> These will print the query sent to backend and print whether the query
> result was fetched from query cache. This will help to know whether
> pgpool retrieves the data from query cache or not.
>
> At this point I guess the reason you see the old value could be, the
> query cache entry was not removed by previous update for some reasons.
> When a SELECT is executed and a query cache entry is created, pgpool
> creates a file containing the cache information. This is used to
> invalidate cache when the table is updated. If the file is created,
> you can see it as: logdir/oid_of_database/oid_of_table. ("logdir" is
> set in pgpool.conf).  In this case oid_of_database = oid of dynacom,
> and oid_of_table = oid of bdynacom.useroptions. Can you confirm?
Thank you for the useful hints.

Yes I verify the presence of the file, and indeed it bears the oid of 
bdynacom.useroptions :

dynacom=# select oid from pg_database where datname = 'dynacom';
  oid
-------
17748
(1 row)
dynacom=# select oid from pg_namespace where nspname = 'bdynacom';
  oid
-------
16902
(1 row)
dynacom=# select oid, oid::regclass, relnamespace from pg_class where 
relname='useroptions' and relnamespace=16902;
  oid  |         oid          | relnamespace
-------+----------------------+--------------
19097 | bdynacom.useroptions |        16902
(1 row)

jboss at smadevnu:~ % sudo ls -l /var/log/pgpool/oiddir/17748/
Password:
total 1
-rw-------  1 pgpool pgpool 8 Apr 27 19:00 19097


I will provide the rest of answers tomorrow. Hopefully.

>
>> amantzio@[local]/dynacom=# SELECT tableoid::regclass, app, urlext FROM
>> useroptions WHERE username = 'Achilleas Mantzios' AND app IN ('p
>> erformreport') AND detail = '';
>>        tableoid       |      app      |  urlext
>> ----------------------+---------------+-----------
>> bdynacom.useroptions | performreport | *?group=no  <-- also old value*
>> (1 row)
>>
>> bow besides the false stale value ( *?group=yes&groupno=2 ) *if we add
>> tableoid in the select we also get another also false and stale value
>> : "group=no"
>>
>> 2nd pgpool session
>>
>> pgpool at smadevnu:~ % psql -p 9999 -U amantzio dynacom
>> psql (15.7, server 17.4)
>> WARNING: psql major version 15, server major version 17.
>>          Some psql features might not work.
>> Type "help" for help.
>>
>> dynacom=# SELECT app, urlext FROM useroptions WHERE username =
>> 'Achilleas Mantzios' AND app IN ('performreport
>> ') AND detail = '';
>>       app      |        urlext
>> ---------------+----------------------
>> performreport | *?group=yes&groupno=2*
>> (1 row)
>>
>> dynacom=# /*NO QUERY CACHE*/ SELECT app, urlext FROM useroptions WHERE
>> username = 'Achilleas Mantzios' AND app
>> IN ('performreport') AND detail = '';
>>       app      |        urlext
>> ---------------+----------------------
>> performreport | *?group=yes&groupno=7    <---- real value*
>> (1 row)
>>
>> dynacom=# /*FORCE QUERY CACHE*/ SELECT app, urlext FROM useroptions
>> WHERE username = 'Achilleas Mantzios' AND
>> app IN ('performreport') AND detail = '';
>>       app      |  urlext
>> ---------------+-----------
>> performreport | *?group=no  <-- also old value*
>> (1 row)
>>
>> In the first select we get the same old version  as in the 1st
>> session, in the second select (no query cache) we get the real correct
>> value , while in the last select by forcing query cache, we get the
>> same value as if putting the tableoid in the select.
>>
>>
>> now comes the ultra crazy part :
>>
>> same session :
>>
>> dynacom=# SELECT tableoid::regclass,app, urlext FROM useroptions WHERE
>> username = 'Achilleas Mantzios' AND app
>> IN ('performreport') AND detail = '';
>>        tableoid       |      app      |        urlext
>> ----------------------+---------------+----------------------
>> bdynacom.useroptions | performreport | ?group=yes&groupno=7
>> (1 row)
>>
>> dynacom=# SELECT tableoid::regclass, app, urlext FROM useroptions
>> WHERE username = 'Achilleas Mantzios' AND ap
>> p IN ('performreport') AND detail = '';
>>        tableoid       |      app      |  urlext
>> ----------------------+---------------+-----------
>> bdynacom.useroptions | performreport | ?group=no
>> (1 row)
>>
>> can you spot the difference ? it is the space after "regclass," here :
>> tableoid::regclass, app
>>
>> here without the tableoid :
>>
>> dynacom=# SELECT app, urlext FROM useroptions WHERE username =
>> 'Achilleas Mantzios' AND app IN ('performreport
>> ') AND detail = '';
>>       app      |        urlext
>> ---------------+----------------------
>> performreport | ?group=yes&groupno=2
>> (1 row)
>>
>> dynacom=# SELECT app,urlext FROM useroptions WHERE username =
>> 'Achilleas Mantzios' AND app IN ('performreport'
>> ) AND detail = '';
>>       app      |        urlext
>> ---------------+----------------------
>> performreport | ?group=yes&groupno=7
>> (1 row)
>>
>> only different thing is the space in the select ,
> That's an expected behavior. When pgpool fetches a cache entry, it is
> based on the exact string match of the query strings. So even a white
> space matters.

Ok but seeing stale and irrelevant results for the same query is not right.

Maybe you could thing of using postgresql's queryid ? just saying

>
> Best regards,
> --
> Tatsuo Ishii
> SRA OSS K.K.
> English:http://www.sraoss.co.jp/index_en/
> Japanese:http://www.sraoss.co.jp
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://www.pgpool.net/pipermail/pgpool-general/attachments/20250427/4fe28209/attachment-0001.htm>