Обсуждение: BUG #8842: lo_open/fastpath transaction inconsistency
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)
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. +
We just checked on a 9.3.4-3 (win32) and the problem is still present. Ludovic -----Message d'origine----- De=A0: Bruce Momjian [mailto:bruce@momjian.us]=20 Envoy=E9=A0: mercredi 16 avril 2014 19:55 =C0=A0: Ludovic POLLET Cc=A0: pgsql-bugs@postgresql.org Objet=A0: 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: >=20 > Bug reference: 8842 > Logged by: Ludovic P > Email address: ludovic.pollet@kurmi-software.com > PostgreSQL version: 9.0.3 > Operating system: Windows > Description: =20 >=20 > Summary: >=20 > 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".=20 > However, the same access pattern implemented using plain sql select > loread(lo_open(...)) just works reliably. >=20 > I suspect that the "fastpath" way of calling lo_open is broken regarding > transaction consistency (ie it sees data that are otherwise not visible t= o > the transaction). >=20 > Details: >=20 > I have a table (async_operations) that holds an oid row (result) that is > really a reference to a lob. >=20 > create table async_operations ( > idASYNC_OPERATION int4 not null,=20 > result oid,=20 > ... (removed for clarity) > primary key (idASYNC_OPERATION)) >=20 > This table has a trigger that manage the lob (ie lo_delete on update/ > delete) >=20 > create trigger t_async_operations_result before update or delete on > async_operations for each row execute procedure lo_manage(result) > / >=20 > Two kinds of transaction may happen :=20 > '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 t= he > lob. >=20 > 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'. >=20 > Here is an extract of the service side query trace of my application (9.0= .3, > default_transaction_isolation =3D 'repeatable read'. latest 9.3 and highe= r > isolation level behave the same). The log pattern is '%m %c %x %v'. >=20 >=20 > 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) >=20 > 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 t= he > client (in that case the jdbc driver), but to the server. >=20 > 2014-01-15 11:44:40.429 CET 52d6668a.8fc 0 5/37LOG: statement: BEGIN;sel= ect > asyncopera0_.idASYNC_OPERATION as idASYNC1_570_0_, asyncopera0_.result as > result570_0_ from async_operations asyncopera0_ where > asyncopera0_.idASYNC_OPERATION=3D304837 > 2014-01-15 11:44:40.430 CET 52d6668a.8fc 0 5/37LOG: fastpath function ca= ll: > "lo_open" (OID 952) > 2014-01-15 11:44:40.430 CET 52d6668a.8fc 0 5/37LOG: fastpath function ca= ll: > "lo_creat" (OID 957) > 2014-01-15 11:44:40.430 CET 52d6668a.8fc 493216 5/37LOG: fastpath functi= on > call: "lo_open" (OID 952) > 2014-01-15 11:44:40.430 CET 52d6668a.8fc 493216 5/37LOG: fastpath functi= on > call: "lowrite" (OID 955) > 2014-01-15 11:44:40.430 CET 52d6668a.8fc 493216 5/37LOG: fastpath functi= on > call: "lo_close" (OID 953) > 2014-01-15 11:44:40.431 CET 52d6668a.8fc 493216 5/37LOG: statement: upda= te > async_operations set result=3D581532 where idASYNC_OPERATION=3D304837 > ... > 2014-01-15 11:44:40.908 CET 52d66616.d28 0 4/414LOG: statement: > BEGIN;select result from async_operations where idASYNC_OPERATION=3D30483= 7 > 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=3D30483= 7 > 2014-01-15 11:44:40.931 CET 52d6668a.8fc 493216 5/37LOG: statement: COMM= IT > 2014-01-15 11:44:40.931 CET 52d66616.d28 0 4/414LOG: statement: select > result from async_operations where idASYNC_OPERATION=3D304837 > 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 a= s > 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_.additionalHeaderFie= ld > 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=3D304837 > 2014-01-15 11:44:40.932 CET 52d66616.d28 0 4/414LOG: statement: select > result from async_operations where idASYNC_OPERATION=3D304837 > 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) > =3D> This should work since the access using statement in the same transa= ction > was ok (I triple checked in the code that the OID passed to lo_open was t= he > 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=3D304837 > 2014-01-15 11:44:40.932 CET 52d66616.d28 0 4/414LOG: statement: select > loread(lo_open(581531, 262144), 1000000) >=20 >=20 >=20 >=20 >=20 >=20 > --=20 > Sent via pgsql-bugs mailing list (pgsql-bugs@postgresql.org) > To make changes to your subscription: > http://www.postgresql.org/mailpref/pgsql-bugs --=20 Bruce Momjian <bruce@momjian.us> http://momjian.us EnterpriseDB http://enterprisedb.com + Everyone has their own god. +
On Fri, Apr 18, 2014 at 04:14:50PM +0000, Ludovic POLLET wrote: > 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. Thanks. -- Bruce Momjian <bruce@momjian.us> http://momjian.us EnterpriseDB http://enterprisedb.com + Everyone has their own god. +
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 acce= ss. 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 ca= se. > However there is a significant difference between these modes and INV_RE= AD alone: with INV_READ you cannot write on the descriptor, and the=20 > data read from it will reflect the contents of the large object at the ti= me of the transaction snapshot that was active when lo_open was executed, r= egardless=20 > of later writes by this or other transactions. Reading from a descriptor = opened with INV_WRITE returns data that reflects all writes of other=20 > committed transactions as well as writes of the current transaction. This= is similar to the behavior of SERIALIZABLE versus READ COMMITTED transacti= on modes=20 > for ordinary SQL SELECT commands. -----Message d'origine----- De=A0: Ludovic POLLET=20 Envoy=E9=A0: jeudi 17 avril 2014 17:44 =C0=A0: 'Bruce Momjian' Cc=A0: pgsql-bugs@postgresql.org; Fabien BONIC Objet=A0: 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=A0: Bruce Momjian [mailto:bruce@momjian.us]=20 Envoy=E9=A0: mercredi 16 avril 2014 19:55 =C0=A0: Ludovic POLLET Cc=A0: pgsql-bugs@postgresql.org Objet=A0: 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: >=20 > Bug reference: 8842 > Logged by: Ludovic P > Email address: ludovic.pollet@kurmi-software.com > PostgreSQL version: 9.0.3 > Operating system: Windows > Description: =20 >=20 > Summary: >=20 > 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".=20 > However, the same access pattern implemented using plain sql select > loread(lo_open(...)) just works reliably. >=20 > I suspect that the "fastpath" way of calling lo_open is broken regarding > transaction consistency (ie it sees data that are otherwise not visible t= o > the transaction). >=20 > Details: >=20 > I have a table (async_operations) that holds an oid row (result) that is > really a reference to a lob. >=20 > create table async_operations ( > idASYNC_OPERATION int4 not null,=20 > result oid,=20 > ... (removed for clarity) > primary key (idASYNC_OPERATION)) >=20 > This table has a trigger that manage the lob (ie lo_delete on update/ > delete) >=20 > create trigger t_async_operations_result before update or delete on > async_operations for each row execute procedure lo_manage(result) > / >=20 > Two kinds of transaction may happen :=20 > '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 t= he > lob. >=20 > 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'. >=20 > Here is an extract of the service side query trace of my application (9.0= .3, > default_transaction_isolation =3D 'repeatable read'. latest 9.3 and highe= r > isolation level behave the same). The log pattern is '%m %c %x %v'. >=20 >=20 > 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) >=20 > 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 t= he > client (in that case the jdbc driver), but to the server. >=20 > 2014-01-15 11:44:40.429 CET 52d6668a.8fc 0 5/37LOG: statement: BEGIN;sel= ect > asyncopera0_.idASYNC_OPERATION as idASYNC1_570_0_, asyncopera0_.result as > result570_0_ from async_operations asyncopera0_ where > asyncopera0_.idASYNC_OPERATION=3D304837 > 2014-01-15 11:44:40.430 CET 52d6668a.8fc 0 5/37LOG: fastpath function ca= ll: > "lo_open" (OID 952) > 2014-01-15 11:44:40.430 CET 52d6668a.8fc 0 5/37LOG: fastpath function ca= ll: > "lo_creat" (OID 957) > 2014-01-15 11:44:40.430 CET 52d6668a.8fc 493216 5/37LOG: fastpath functi= on > call: "lo_open" (OID 952) > 2014-01-15 11:44:40.430 CET 52d6668a.8fc 493216 5/37LOG: fastpath functi= on > call: "lowrite" (OID 955) > 2014-01-15 11:44:40.430 CET 52d6668a.8fc 493216 5/37LOG: fastpath functi= on > call: "lo_close" (OID 953) > 2014-01-15 11:44:40.431 CET 52d6668a.8fc 493216 5/37LOG: statement: upda= te > async_operations set result=3D581532 where idASYNC_OPERATION=3D304837 > ... > 2014-01-15 11:44:40.908 CET 52d66616.d28 0 4/414LOG: statement: > BEGIN;select result from async_operations where idASYNC_OPERATION=3D30483= 7 > 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=3D30483= 7 > 2014-01-15 11:44:40.931 CET 52d6668a.8fc 493216 5/37LOG: statement: COMM= IT > 2014-01-15 11:44:40.931 CET 52d66616.d28 0 4/414LOG: statement: select > result from async_operations where idASYNC_OPERATION=3D304837 > 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 a= s > 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_.additionalHeaderFie= ld > 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=3D304837 > 2014-01-15 11:44:40.932 CET 52d66616.d28 0 4/414LOG: statement: select > result from async_operations where idASYNC_OPERATION=3D304837 > 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) > =3D> This should work since the access using statement in the same transa= ction > was ok (I triple checked in the code that the OID passed to lo_open was t= he > 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=3D304837 > 2014-01-15 11:44:40.932 CET 52d66616.d28 0 4/414LOG: statement: select > loread(lo_open(581531, 262144), 1000000) >=20 >=20 >=20 >=20 >=20 >=20 > --=20 > Sent via pgsql-bugs mailing list (pgsql-bugs@postgresql.org) > To make changes to your subscription: > http://www.postgresql.org/mailpref/pgsql-bugs --=20 Bruce Momjian <bruce@momjian.us> http://momjian.us EnterpriseDB http://enterprisedb.com + Everyone has their own god. +