TR: [BUGS] BUG #8842: lo_open/fastpath transaction inconsistency

Hello,

We are facing a bug where our application cannot read a Lob because of concurrent removal. However, we are using the serializable isolation level and a correct transaction scope. We're using the latest JDBC driver snapshot (and hibernate but that does not really matter).

The problematic use case is basically a thread that read the LOB while another thread replace it with a new one and release the old one. In this case, the reader will get a "large object xxx does not exist".

From what I understand, it is due to the opening of the large object that is always done in read/write mode and thus behave as a read commited one (as written in the doc).

This behaviour is at least very surprising especially when working in SERIALIZABLE concurrency level.

The attached patch implements the following changes:
- Opening the lob in read mode until a write function is called. In such a case, the LOB will be reopened in read/write mode. It totally solves my problem since our application does not modify Lob, but creates new ones indeed.
- Deferring the first lo_open until a Blob function is really called (hibernate seems to be creating blob even if it does not even read them...)

What do you think about these behaviors ?

Ludovic

-----Message d'origine-----
De : Ludovic POLLET
Envoyé : vendredi 18 avril 2014 18:15
À : 'Bruce Momjian'
Cc : 'pgsql-bugs(at)postgresql(dot)org'; Fabien BONIC
Objet : RE: [BUGS] BUG #8842: lo_open/fastpath transaction inconsistency

Reading the lo_xxx function documentation again, I found that the behavior could be related to the mode used when opening a lo.
It seems that opening a lo for write is not supposed to be transaction safe (see bellow). However, the jdbc driver we use does it - even for read access.

I will follow the problem to the jdbc guys.

> The server currently does not distinguish between modes INV_WRITE and INV_READ | INV_WRITE: you are allowed to read from the descriptor in either case.
> However there is a significant difference between these modes and INV_READ alone: with INV_READ you cannot write on the descriptor, and the
> data read from it will reflect the contents of the large object at the time of the transaction snapshot that was active when lo_open was executed, regardless
> of later writes by this or other transactions. Reading from a descriptor opened with INV_WRITE returns data that reflects all writes of other
> committed transactions as well as writes of the current transaction. This is similar to the behavior of SERIALIZABLE versus READ COMMITTED transaction modes
> for ordinary SQL SELECT commands.

-----Message d'origine-----
De : Ludovic POLLET
Envoyé : jeudi 17 avril 2014 17:44
À : 'Bruce Momjian'
Cc : pgsql-bugs(at)postgresql(dot)org; Fabien BONIC
Objet : RE: [BUGS] BUG #8842: lo_open/fastpath transaction inconsistency

We just checked on a 9.3.4-3 (win32) and the problem is still present.

Ludovic

-----Message d'origine-----
De : Bruce Momjian [mailto:bruce(at)momjian(dot)us]
Envoyé : mercredi 16 avril 2014 19:55
À : Ludovic POLLET
Cc : pgsql-bugs(at)postgresql(dot)org
Objet : Re: [BUGS] BUG #8842: lo_open/fastpath transaction inconsistency

I see no one replied to you. Can you recreate the problem in a newer
version of Postgres?

---------------------------------------------------------------------------

On Wed, Jan 15, 2014 at 12:49:35PM +0000, ludovic(dot)pollet(at)kurmi-software(dot)com wrote:
> The following bug has been logged on the website:
>
> Bug reference: 8842
> Logged by: Ludovic P
> Email address: ludovic(dot)pollet(at)kurmi-software(dot)com
> PostgreSQL version: 9.0.3
> Operating system: Windows
> Description:
>
> Summary:
>
> Accessing LOB using the lo_open function via fastpath call sometime fails
> for blob that have been concurrently deleted after the start of the
> transaction, with a message "large object xxx does not exist".
> However, the same access pattern implemented using plain sql select
> loread(lo_open(...)) just works reliably.
>
> I suspect that the "fastpath" way of calling lo_open is broken regarding
> transaction consistency (ie it sees data that are otherwise not visible to
> the transaction).
>
> Details:
>
> I have a table (async_operations) that holds an oid row (result) that is
> really a reference to a lob.
>
> create table async_operations (
> idASYNC_OPERATION int4 not null,
> result oid,
> ... (removed for clarity)
> primary key (idASYNC_OPERATION))
>
> This table has a trigger that manage the lob (ie lo_delete on update/
> delete)
>
> create trigger t_async_operations_result before update or delete on
> async_operations for each row execute procedure lo_manage(result)
> /
>
> Two kinds of transaction may happen :
> 'update transaction' create a new lob and update the result oid (and the
> trigger delete the old one
> 'consult transaction' select an entry, and perform a lo_open/loread on the
> lob.
>
> When load transaction is implemented using the jdbc api, random failures
> happen in fastpath function call to to_open, just after the commit of an
> 'update transaction'.
>
> Here is an extract of the service side query trace of my application (9.0.3,
> default_transaction_isolation = 'repeatable read'. latest 9.3 and higher
> isolation level behave the same). The log pattern is '%m %c %x %v'.
>
>
> Transaction 5/37 is 'update transaction'
> Transaction 3/2510 is a 'consult transaction', but it first does a plain sql
> way (to show that the sql way works), then a fastpath way (returning the
> error)
> Transaction 4/414 is 'consult transaction' that loops the plain sql way. It
> correctly reads the initial lob oid and content before and after commit, and
> keep reading during the whole transaction. (this was intended to double
> check that the transaction could not see value commited concurrently)
>
> It shows that within the Transaction 3/2510, the call to lo_open using
> select statement success while the call to lo_open using fastpath fails
> (still in the SAME transaction). So I the problem seemns not related to the
> client (in that case the jdbc driver), but to the server.
>
> 2014-01-15 11:44:40.429 CET 52d6668a.8fc 0 5/37LOG: statement: BEGIN;select
> asyncopera0_.idASYNC_OPERATION as idASYNC1_570_0_, asyncopera0_.result as
> result570_0_ from async_operations asyncopera0_ where
> asyncopera0_.idASYNC_OPERATION=304837
> 2014-01-15 11:44:40.430 CET 52d6668a.8fc 0 5/37LOG: fastpath function call:
> "lo_open" (OID 952)
> 2014-01-15 11:44:40.430 CET 52d6668a.8fc 0 5/37LOG: fastpath function call:
> "lo_creat" (OID 957)
> 2014-01-15 11:44:40.430 CET 52d6668a.8fc 493216 5/37LOG: fastpath function
> call: "lo_open" (OID 952)
> 2014-01-15 11:44:40.430 CET 52d6668a.8fc 493216 5/37LOG: fastpath function
> call: "lowrite" (OID 955)
> 2014-01-15 11:44:40.430 CET 52d6668a.8fc 493216 5/37LOG: fastpath function
> call: "lo_close" (OID 953)
> 2014-01-15 11:44:40.431 CET 52d6668a.8fc 493216 5/37LOG: statement: update
> async_operations set result=581532 where idASYNC_OPERATION=304837
> ...
> 2014-01-15 11:44:40.908 CET 52d66616.d28 0 4/414LOG: statement:
> BEGIN;select result from async_operations where idASYNC_OPERATION=304837
> 2014-01-15 11:44:40.908 CET 52d66616.d28 0 4/414LOG: statement: select
> loread(lo_open(581531, 262144), 1000000)
> ...
> 2014-01-15 11:44:40.931 CET 52d66611.26f0 0 3/2510LOG: statement:
> BEGIN;select result from async_operations where idASYNC_OPERATION=304837
> 2014-01-15 11:44:40.931 CET 52d6668a.8fc 493216 5/37LOG: statement: COMMIT
> 2014-01-15 11:44:40.931 CET 52d66616.d28 0 4/414LOG: statement: select
> result from async_operations where idASYNC_OPERATION=304837
> 2014-01-15 11:44:40.931 CET 52d66611.26f0 0 3/2510LOG: statement: select
> loread(lo_open(581531, 262144), 1000000)
> 2014-01-15 11:44:40.931 CET 52d66616.d28 0 4/414LOG: statement: select
> loread(lo_open(581531, 262144), 1000000)
> 2014-01-15 11:44:40.932 CET 52d66611.26f0 0 3/2510LOG: statement: select
> asyncopera0_.idASYNC_OPERATION as idASYNC1_570_0_, asyncopera0_.userId as
> userId570_0_, asyncopera0_.originalUserId as original3_570_0_,
> asyncopera0_.executerTitle as executer4_570_0_, asyncopera0_.flag as
> flag570_0_, asyncopera0_.status as status570_0_, asyncopera0_.startTime as
> startTime570_0_, asyncopera0_.endTime as endTime570_0_,
> asyncopera0_.description as descript9_570_0_, asyncopera0_.encodedForm as
> encoded10_570_0_, asyncopera0_.result as result570_0_,
> asyncopera0_.fileContent as fileCon12_570_0_,
> asyncopera0_.fileContentEncoding as fileCon13_570_0_,
> asyncopera0_.fileProc_class as fileProc14_570_0_, asyncopera0_.pojoName1 as
> pojoName15_570_0_, asyncopera0_.pojoName2 as pojoName16_570_0_,
> asyncopera0_.language as language570_0_, asyncopera0_.additionalHeaderField
> as additio18_570_0_, asyncopera0_.massOperation as massOpe19_570_0_,
> asyncopera0_.node as node570_0_, asyncopera0_.execNode as execNode570_0_
> from async_operations asyncopera0_ where
> asyncopera0_.idASYNC_OPERATION=304837
> 2014-01-15 11:44:40.932 CET 52d66616.d28 0 4/414LOG: statement: select
> result from async_operations where idASYNC_OPERATION=304837
> 2014-01-15 11:44:40.932 CET 52d66616.d28 0 4/414LOG: statement: select
> loread(lo_open(581531, 262144), 1000000)
> 2014-01-15 11:44:40.932 CET 52d66611.26f0 0 3/2510LOG: fastpath function
> call: "lo_open" (OID 952)
> => This should work since the access using statement in the same transaction
> was ok (I triple checked in the code that the OID passed to lo_open was the
> same as the previous select, in this case 581531)
> 2014-01-15 11:44:40.932 CET 52d66611.26f0 0 3/2510ERROR: large object
> 581531 does not exist
> 2014-01-15 11:44:40.932 CET 52d66616.d28 0 4/414LOG: statement: select
> result from async_operations where idASYNC_OPERATION=304837
> 2014-01-15 11:44:40.932 CET 52d66616.d28 0 4/414LOG: statement: select
> loread(lo_open(581531, 262144), 1000000)
>
>
>
>
>
>
> --
> Sent via pgsql-bugs mailing list (pgsql-bugs(at)postgresql(dot)org)
> To make changes to your subscription:
> http://www.postgresql.org/mailpref/pgsql-bugs

--
Bruce Momjian <bruce(at)momjian(dot)us> http://momjian.us
EnterpriseDB http://enterprisedb.com

+ Everyone has their own god. +