Обсуждение: 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
serializableisolation level and a correct transaction scope. We're using the latest JDBC driver snapshot (and hibernate
butthat 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
releasethe 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
behaveas 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/writemode. 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
doesnot 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@postgresql.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
openinga lo. 
It seems that opening a lo for write is not supposed to be transaction safe (see bellow). However, the jdbc driver we
usedoes 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
fromthe descriptor in either case. 
>  However there is a significant difference between these modes and INV_READ alone: with INV_READ you cannot write on
thedescriptor, and the  
> data read from it will reflect the contents of the large object at the time of the transaction snapshot that was
activewhen lo_open was executed, regardless  
> of later writes by this or other transactions. Reading from a descriptor opened with INV_WRITE returns data that
reflectsall writes of other  
> committed transactions as well as writes of the current transaction. This is similar to the behavior of SERIALIZABLE
versusREAD 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@postgresql.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@momjian.us]
Envoyé : mercredi 16 avril 2014 19:55
À : Ludovic POLLET
Cc : pgsql-bugs@postgresql.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.pollet@kurmi-software.com wrote:
> The following bug has been logged on the website:
>
> Bug reference:      8842
> Logged by:          Ludovic P
> Email address:      ludovic.pollet@kurmi-software.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@postgresql.org)
> To make changes to your subscription:
> http://www.postgresql.org/mailpref/pgsql-bugs

--
  Bruce Momjian  <bruce@momjian.us>        http://momjian.us
  EnterpriseDB                             http://enterprisedb.com

  + Everyone has their own god. +

Ludovic POLLET <ludovic.pollet@kurmi-software.com> wrote:

> 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 ?

As one of the developers of the implementation of serializable
transactions used by PostgreSQL, I remember that we needed to
exclude large objects from the transaction serialization because it
basically did not follow transactional semantics in any other
regard.  The only workaround I can think to suggest is to only
insert and delete large objects -- never update them, and rely on
the serialization of modifications to the OID columns which
*reference* the large objects.  Always add the large object before
setting a reference to it, and always eliminate references to a
large object before deleting it.  A crash at the wrong time could
leave a large object which is unreferenced, so you might want to
look at the vacuumlo executable:

http://www.postgresql.org/docs/current/static/vacuumlo.html

Unfortunately, I don't know how that approach interacts with
Hibernate or its use of the JDBC driver.

--
Kevin Grittner
EDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

I encountered this problem while using exactly the pattern you describe!

"Always add the large object before setting a reference to it, and always eliminate references to a large object before
deletingit." 

The problem is that you cannot delete references that have been seen by transaction that started in the past ! So even
withthis pattern, it is important that older transaction can access LOB that are concurrently deleted/replaced. And
thisis only possible if they access it in readonly mode. (This is coherent with the fact that they won't be able to
performmodification on it at that time) 

My patch just make LOB access read only by default until a modification is required.

Ludovic


-----Message d'origine-----
De : Kevin Grittner [mailto:kgrittn@ymail.com]
Envoyé : lundi 5 mai 2014 15:55
À : Ludovic POLLET; pgsql-jdbc@postgresql.org
Objet : Re: [JDBC] TR: [BUGS] BUG #8842: lo_open/fastpath transaction inconsistency

Ludovic POLLET <ludovic.pollet@kurmi-software.com> wrote:

> 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 ?

As one of the developers of the implementation of serializable
transactions used by PostgreSQL, I remember that we needed to
exclude large objects from the transaction serialization because it
basically did not follow transactional semantics in any other
regard.  The only workaround I can think to suggest is to only
insert and delete large objects -- never update them, and rely on
the serialization of modifications to the OID columns which
*reference* the large objects.  Always add the large object before
setting a reference to it, and always eliminate references to a
large object before deleting it.  A crash at the wrong time could
leave a large object which is unreferenced, so you might want to
look at the vacuumlo executable:

http://www.postgresql.org/docs/current/static/vacuumlo.html

Unfortunately, I don't know how that approach interacts with
Hibernate or its use of the JDBC driver.

--
Kevin Grittner
EDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company