Обсуждение: BUG #11119: JDBC Driver misreports failing query/statement in executeBatch
BUG #11119: JDBC Driver misreports failing query/statement in executeBatch
От
luke.henry@sanmina.com
Дата:
The following bug has been logged on the website: Bug reference: 11119 Logged by: Luke Henry Email address: luke.henry@sanmina.com PostgreSQL version: 9.2.1 Operating system: Windows 7 Description: The various JDBC driver versions, from 9.2X until the latest appear to always report batch record 0 as the offending record when a BatchUpdateException is thrown. Initial analysis of the driver code seems to show that the handlers (BatchResultHandler and CallableBatchResultHandler) only update their internal "result arrays" when handleCommandStatus is invoked. Unfortunately, it appears that method does not get called when one of the batch queries throws an exception. Therefore, the driver always reports the first query as the failing query (as it remains in its default initial state), making it extremely difficult to identify which statement caused the problem. This also means that when an executeBatch fails the updateCounts option on the BatchExecutionException is always empty, even if some number of statements succeeded. The performance benefits of batch calls appear to be substantial, but with such poor diagnostic capabilities it is difficult to use it in production code. Note: the BatchExecutionException does contain the original exception in its getNextException property but it misreports which batch statement caused the exception. Log Details: 14:45:02.999 (3) PostgreSQL 9.3 JDBC4.1 (build 1102) 14:45:02.999 (3) Trying to establish a protocol version 3 connection to localhost:5432 14:45:03.001 (3) Receive Buffer Size is 8192 14:45:03.002 (3) Send Buffer Size is 8192 14:45:03.002 (3) FE=> StartupPacket(user=****, database=batch_mesr, client_encoding=UTF8, DateStyle=ISO, extra_float_digits=2, TimeZone=America/Chicago) 14:45:03.020 (3) <=BE AuthenticationOk 14:45:03.020 (3) <=BE ParameterStatus(application_name = ) 14:45:03.020 (3) <=BE ParameterStatus(client_encoding = UTF8) 14:45:03.021 (3) <=BE ParameterStatus(DateStyle = ISO, MDY) 14:45:03.021 (3) <=BE ParameterStatus(integer_datetimes = on) 14:45:03.021 (3) <=BE ParameterStatus(IntervalStyle = postgres) 14:45:03.021 (3) <=BE ParameterStatus(is_superuser = off) 14:45:03.021 (3) <=BE ParameterStatus(server_encoding = UTF8) 14:45:03.021 (3) <=BE ParameterStatus(server_version = 9.2.1) 14:45:03.021 (3) <=BE ParameterStatus(session_authorization = ****) 14:45:03.021 (3) <=BE ParameterStatus(standard_conforming_strings = on) 14:45:03.021 (3) <=BE ParameterStatus(TimeZone = America/Chicago) 14:45:03.021 (3) <=BE BackendKeyData(pid=3572,ckey=341046590) 14:45:03.021 (3) <=BE ReadyForQuery(I) 14:45:03.021 (3) simple execute, handler=org.postgresql.core.SetupQueryRunner$SimpleResultHandler@89ec211, maxRows=0, fetchSize=0, flags=23 14:45:03.021 (3) FE=> Parse(stmt=null,query="SET extra_float_digits = 3",oids={}) 14:45:03.021 (3) FE=> Bind(stmt=null,portal=null) 14:45:03.021 (3) FE=> Execute(portal=null,limit=1) 14:45:03.021 (3) FE=> Sync 14:45:03.022 (3) <=BE ParseComplete [null] 14:45:03.022 (3) <=BE BindComplete [null] 14:45:03.022 (3) <=BE CommandStatus(SET) 14:45:03.022 (3) <=BE ReadyForQuery(I) 14:45:03.022 (3) compatible = 9.3 14:45:03.022 (3) loglevel = 2 14:45:03.022 (3) prepare threshold = 5 14:45:03.023 (3) types using binary send = INT8_ARRAY,TIMESTAMPTZ,FLOAT4_ARRAY,FLOAT8_ARRAY,UUID,TEXT_ARRAY,VARCHAR_ARRAY,BYTEA,TIME,FLOAT4,FLOAT8,INT2_ARRAY,TIMETZ,INT2,INT8,INT4,INT4_ARRAY,TIMESTAMP,POINT,BOX 14:45:03.023 (3) types using binary receive = INT8_ARRAY,TIMESTAMPTZ,FLOAT4_ARRAY,FLOAT8_ARRAY,UUID,TEXT_ARRAY,VARCHAR_ARRAY,BYTEA,TIME,DATE,FLOAT4,FLOAT8,INT2_ARRAY,TIMETZ,INT2,INT8,INT4,INT4_ARRAY,TIMESTAMP,POINT,BOX 14:45:03.023 (3) integer date/time = true getConnection returning org.postgresql.Driver 14:45:03.028 (3) batch execute 6 queries, handler=org.postgresql.jdbc2.AbstractJdbc2Statement$CallableBatchResultHandler@5ee76547, maxRows=0, fetchSize=0, flags=4 14:45:03.028 (3) FE=> Parse(stmt=S_1,query="BEGIN",oids={}) 14:45:03.029 (3) FE=> Bind(stmt=S_1,portal=null) 14:45:03.029 (3) FE=> Execute(portal=null,limit=0) 14:45:03.030 (3) FE=> Parse(stmt=S_2,query="select * from mesr.test_insert_or_update($1) as result",oids={1043}) 14:45:03.030 (3) FE=> Bind(stmt=S_2,portal=null,$1=<'some_text0'>) 14:45:03.031 (3) FE=> Describe(portal=null) 14:45:03.031 (3) FE=> Execute(portal=null,limit=1) 14:45:03.031 (3) FE=> Bind(stmt=S_2,portal=null,$1=<'some_text1'>) 14:45:03.031 (3) FE=> Describe(portal=null) 14:45:03.031 (3) FE=> Execute(portal=null,limit=1) 14:45:03.031 (3) FE=> Bind(stmt=S_2,portal=null,$1=<'some_text2'>) 14:45:03.031 (3) FE=> Describe(portal=null) 14:45:03.031 (3) FE=> Execute(portal=null,limit=1) 14:45:03.032 (3) FE=> Bind(stmt=S_2,portal=null,$1=<'some_text3'>) 14:45:03.032 (3) FE=> Describe(portal=null) 14:45:03.032 (3) FE=> Execute(portal=null,limit=1) 14:45:03.032 (3) FE=> Bind(stmt=S_2,portal=null,$1=<'some_text4'>) 14:45:03.032 (3) FE=> Describe(portal=null) 14:45:03.032 (3) FE=> Execute(portal=null,limit=1) 14:45:03.032 (3) FE=> Bind(stmt=S_2,portal=null,$1=<'some_text5'>) 14:45:03.032 (3) FE=> Describe(portal=null) 14:45:03.032 (3) FE=> Execute(portal=null,limit=1) 14:45:03.032 (3) FE=> Sync 14:45:03.037 (3) <=BE ParseComplete [S_1] 14:45:03.037 (3) <=BE BindComplete [null] 14:45:03.037 (3) <=BE CommandStatus(BEGIN) 14:45:03.037 (3) <=BE ParseComplete [S_2] 14:45:03.037 (3) <=BE BindComplete [null] 14:45:03.039 (3) <=BE RowDescription(1) 14:45:03.039 (3) Field(,INT4,4,T) 14:45:03.039 (3) <=BE DataRow(len=1) 14:45:03.039 (3) <=BE PortalSuspended 14:45:03.040 (3) <=BE BindComplete [null] 14:45:03.040 (3) <=BE RowDescription(1) 14:45:03.040 (3) Field(,INT4,4,T) 14:45:03.040 (3) <=BE DataRow(len=1) 14:45:03.040 (3) <=BE PortalSuspended 14:45:03.040 (3) <=BE BindComplete [null] 14:45:03.040 (3) <=BE RowDescription(1) 14:45:03.040 (3) Field(,INT4,4,T) 14:45:03.040 (3) <=BE DataRow(len=1) 14:45:03.040 (3) <=BE PortalSuspended 14:45:03.040 (3) <=BE BindComplete [null] 14:45:03.040 (3) <=BE RowDescription(1) 14:45:03.040 (3) Field(,INT4,4,T) 14:45:03.040 (3) <=BE DataRow(len=1) 14:45:03.040 (3) <=BE PortalSuspended 14:45:03.040 (3) <=BE BindComplete [null] 14:45:03.040 (3) <=BE RowDescription(1) 14:45:03.041 (3) Field(,INT4,4,T) 14:45:03.041 (3) <=BE DataRow(len=1) 14:45:03.041 (3) <=BE PortalSuspended 14:45:03.041 (3) <=BE BindComplete [null] 14:45:03.041 (3) <=BE RowDescription(1) 14:45:03.041 (3) Field(,INT4,4,T) 14:45:03.043 (3) <=BE ErrorMessage(ERROR: bad things irl) org.postgresql.util.PSQLException: ERROR: bad things irl at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2198) at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1927) at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:405) at org.postgresql.jdbc2.AbstractJdbc2Statement.executeBatch(AbstractJdbc2Statement.java:2892) at com.sanmina.mds.services.mesreplication.replicator.PersistentBatchReplicatorTest.testBatch(PersistentBatchReplicatorTest.java:85) at com.sanmina.mds.services.mesreplication.replicator.PersistentBatchReplicatorTest.testBatchUpdates(PersistentBatchReplicatorTest.java:59) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:601) at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:47) at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12) at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:44) at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17) at org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26) at org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27) at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:271) at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:70) at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:50) at org.junit.runners.ParentRunner$3.run(ParentRunner.java:238) at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:63) at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:236) at org.junit.runners.ParentRunner.access$000(ParentRunner.java:53) at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:229) at org.junit.runners.ParentRunner.run(ParentRunner.java:309) at org.eclipse.jdt.internal.junit4.runner.JUnit4TestReference.run(JUnit4TestReference.java:50) at org.eclipse.jdt.internal.junit.runner.TestExecution.run(TestExecution.java:38) at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:467) at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:683) at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.run(RemoteTestRunner.java:390) at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.main(RemoteTestRunner.java:197) SQLException: SQLState(P0001) SQLState(P0001) vendor code(0) java.sql.BatchUpdateException: Batch entry 0 select * from mesr.test_insert_or_update('some_text0') as result was aborted. Call getNextException to see the cause. at org.postgresql.jdbc2.AbstractJdbc2Statement$CallableBatchResultHandler.handleError(AbstractJdbc2Statement.java:2813) at org.postgresql.core.v3.QueryExecutorImpl$1.handleError(QueryExecutorImpl.java:461) at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1928) at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:405) at org.postgresql.jdbc2.AbstractJdbc2Statement.executeBatch(AbstractJdbc2Statement.java:2892)
Re: BUG #11119: JDBC Driver misreports failing query/statement in executeBatch
От
Michael Paquier
Дата:
On Mon, Aug 4, 2014 at 4:52 AM, <luke.henry@sanmina.com> wrote: > The following bug has been logged on the website: > > Bug reference: 11119 > Logged by: Luke Henry > Email address: luke.henry@sanmina.com > PostgreSQL version: 9.2.1 > Operating system: Windows 7 > Description: > > The various JDBC driver versions, from 9.2X until the latest appear to > always report batch record 0 as the offending record when a > BatchUpdateException is thrown. You should report that directly to the pgsql-jdbc list as this problem is related to this driver: pgsql-jdbc@postgresql.org Regards, -- Michael