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)
--
Sent via pgsql-bugs mailing list (pgsql-bugs@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-bugs
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. +
--
Sent via pgsql-bugs mailing list (pgsql-bugs@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-bugs
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. +
--
Sent via pgsql-bugs mailing list (pgsql-bugs@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-bugs
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@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. +
--
Sent via pgsql-bugs mailing list (pgsql-bugs@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-bugs
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@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 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@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. +
Attachments:
postgresql-jdbc-9.3-1101.lo_open_read.patchapplication/octet-stream; name=postgresql-jdbc-9.3-1101.lo_open_read.patchDownload+55-20
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. +
--
Sent via pgsql-bugs mailing list (pgsql-bugs@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-bugs
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
--
Sent via pgsql-jdbc mailing list (pgsql-jdbc@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-jdbc
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 deleting it."
The problem is that you cannot delete references that have been seen by transaction that started in the past ! So even with this pattern, it is important that older transaction can access LOB that are concurrently deleted/replaced. And this is only possible if they access it in readonly mode. (This is coherent with the fact that they won't be able to perform modification 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
--
Sent via pgsql-jdbc mailing list (pgsql-jdbc@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-jdbc