Strange batch update exceptions

Jesper_D · **Joined:** Tue Jul 17, 2007 6:01 am **Posts:** 3

We are encountering a rather odd exception from hibernate BatchingBatcher. It seems the row count returned from the JDBC call
executeBatch() is -1 which according to the JDBC specs should not happen.

We are using Weblogic 9.2 ,
Oracle 9i,
Oracle Thin JDBC Driver 10.2.0.2.0,
Spring 1.2.8,
Hibernate 3.1.3 and Hibernate 3.2.3.

The problem is that it isn't any specific code that throws the exception but rather something fails with this exception on a server and
then all application using Hibernate and the same Connection Pool throws this exception during batch inserts or updates. After an
application restart it works fine for a couple of days.

We are currently trying to find a way to recreate the problem in our test enviroments but without success so far.

Another strange thing is that it is always "update: 2 " in the error messages that returns row count -1.

[ERROR] org.hibernate.jdbc.AbstractBatcher - Exception executing batch:
org.hibernate.StaleStateException: Batch update returned unexpected row count from update: 2 actual row count: -1 expected: 1
at org.hibernate.jdbc.BatchingBatcher.checkRowCount(BatchingBatcher.java:93)
at org.hibernate.jdbc.BatchingBatcher.checkRowCounts(BatchingBatcher.java:79)
at org.hibernate.jdbc.BatchingBatcher.doExecuteBatch(BatchingBatcher.java:58)
at org.hibernate.jdbc.AbstractBatcher.executeBatch(AbstractBatcher.java:195)
at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:235)
at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:144)

Do anyone know of a situation when the actual row count could possible be -1.

cbredesen · **Posted:** Wed Jul 18, 2007 8:30 am

This isn't exactly a solution, but it might help you work around the issue till you get it sorted. There's a configuration property that controls the batching (or not) of versioned data "hibernate.jdbc.batch_versioned_data":

http://www.hibernate.org/hib_docs/v3/re ... n-optional

It's in table 3.4. Have you enabled that?

-Chris

Jesper_D · **Joined:** Tue Jul 17, 2007 6:01 am **Posts:** 3

The hibernate.jdbc.batch_versioned_data is set to false (default) since our driver only returns -2 as row count ( Statement.SUCCESS_NO_INFO ).

And we actually dont use versioning on the Entities involved. I will try and post the mappings and sessionfactory configuration tomorrow.

Thx

Jesper_D · **Joined:** Tue Jul 17, 2007 6:01 am **Posts:** 3

I have now managed to reproduce the problem with some hibernate logging turned on. First the sessionfactory config:

Code:

2007-08-09 14:12:46,820 [DEBUG] org.hibernate.cfg.Configuration - Preparing to build session factory with filters : {}
2007-08-09 14:12:46,837 [DEBUG] org.hibernate.cfg.Configuration - processing extends queue
2007-08-09 14:12:46,844 [DEBUG] org.hibernate.cfg.Configuration - processing collection mappings
2007-08-09 14:12:46,844 [DEBUG] org.hibernate.cfg.Configuration - processing native query and ResultSetMapping mappings
2007-08-09 14:12:46,845 [DEBUG] org.hibernate.cfg.Configuration - processing association property references
2007-08-09 14:12:46,845 [DEBUG] org.hibernate.cfg.Configuration - processing foreign key constraints
2007-08-09 14:12:47,449 [INFO ] org.hibernate.connection.ConnectionProviderFactory - Initializing connection provider: org.springframework.orm.hibernate3.Loc
alDataSourceConnectionProvider
2007-08-09 14:12:47,494 [INFO ] org.hibernate.cfg.SettingsFactory - RDBMS: Oracle, version: Oracle9i Enterprise Edition Release 9.2.0.8.0 - 64bit Production
With the Partitioning, OLAP and Oracle Data Mining options
JServer Release 9.2.0.8.0 - Production
2007-08-09 14:12:47,495 [INFO ] org.hibernate.cfg.SettingsFactory - JDBC driver: Oracle JDBC driver, version: 10.2.0.2.0
2007-08-09 14:12:47,707 [INFO ] org.hibernate.dialect.Dialect - Using dialect: org.hibernate.dialect.OracleDialect
2007-08-09 14:12:47,747 [INFO ] org.hibernate.transaction.TransactionFactoryFactory - Transaction strategy: org.hibernate.transaction.CMTTransactionFactory
2007-08-09 14:12:47,768 [INFO ] org.hibernate.transaction.TransactionManagerLookupFactory - instantiating TransactionManagerLookup: org.hibernate.transaction
.WeblogicTransactionManagerLookup
2007-08-09 14:12:47,776 [INFO ] org.hibernate.transaction.TransactionManagerLookupFactory - instantiated TransactionManagerLookup
2007-08-09 14:12:47,778 [INFO ] org.hibernate.cfg.SettingsFactory - Automatic flush during beforeCompletion(): disabled
2007-08-09 14:12:47,778 [INFO ] org.hibernate.cfg.SettingsFactory - Automatic session close at end of transaction: disabled
2007-08-09 14:12:47,779 [INFO ] org.hibernate.cfg.SettingsFactory - JDBC batch size: 15
2007-08-09 14:12:47,781 [INFO ] org.hibernate.cfg.SettingsFactory - JDBC batch updates for versioned data: disabled
2007-08-09 14:12:47,789 [INFO ] org.hibernate.cfg.SettingsFactory - Scrollable result sets: enabled
2007-08-09 14:12:47,789 [DEBUG] org.hibernate.cfg.SettingsFactory - Wrap result sets: disabled
2007-08-09 14:12:47,790 [INFO ] org.hibernate.cfg.SettingsFactory - JDBC3 getGeneratedKeys(): enabled
2007-08-09 14:12:47,792 [INFO ] org.hibernate.cfg.SettingsFactory - Connection release mode: on_close
2007-08-09 14:12:47,795 [INFO ] org.hibernate.cfg.SettingsFactory - Default batch fetch size: 1
2007-08-09 14:12:47,796 [INFO ] org.hibernate.cfg.SettingsFactory - Generate SQL with comments: disabled
2007-08-09 14:12:47,796 [INFO ] org.hibernate.cfg.SettingsFactory - Order SQL updates by primary key: disabled
2007-08-09 14:12:47,803 [INFO ] org.hibernate.cfg.SettingsFactory - Query translator: org.hibernate.hql.ast.ASTQueryTranslatorFactory
2007-08-09 14:12:47,816 [INFO ] org.hibernate.hql.ast.ASTQueryTranslatorFactory - Using ASTQueryTranslatorFactory
2007-08-09 14:12:47,819 [INFO ] org.hibernate.cfg.SettingsFactory - Query language substitutions: {}
2007-08-09 14:12:47,820 [INFO ] org.hibernate.cfg.SettingsFactory - Second-level cache: disabled
2007-08-09 14:12:47,820 [INFO ] org.hibernate.cfg.SettingsFactory - Query cache: disabled
2007-08-09 14:12:47,828 [INFO ] org.hibernate.cfg.SettingsFactory - Optimize cache for minimal puts: disabled
2007-08-09 14:12:47,829 [INFO ] org.hibernate.cfg.SettingsFactory - Structured second-level cache entries: disabled
2007-08-09 14:12:47,838 [DEBUG] org.hibernate.exception.SQLExceptionConverterFactory - Using dialect defined converter
2007-08-09 14:12:47,869 [INFO ] org.hibernate.cfg.SettingsFactory - Statistics: disabled
2007-08-09 14:12:47,869 [INFO ] org.hibernate.cfg.SettingsFactory - Deleted entity synthetic identifier rollback: disabled
2007-08-09 14:12:47,871 [INFO ] org.hibernate.cfg.SettingsFactory - Default entity-mode: pojo
2007-08-09 14:12:48,131 [INFO ] org.hibernate.impl.SessionFactoryImpl - building session factory
2007-08-09 14:12:48,133 [DEBUG] org.hibernate.impl.SessionFactoryImpl - Session factory constructed with filter configurations : {}

This is what is logged when the error occurs the first time:

Code:

2007-08-09 15:48:49,629 [DEBUG] org.hibernate.persister.entity.AbstractEntityPersister - Deleting entity: [com.unibet.replication.database.persistence.SqlSta
tementEntity#79356373]
2007-08-09 15:48:49,629 [DEBUG] org.hibernate.jdbc.AbstractBatcher - reusing prepared statement
2007-08-09 15:48:49,629 [DEBUG] org.hibernate.SQL - delete from replication_temp where id=?
2007-08-09 15:48:49,629 [DEBUG] org.hibernate.type.LongType - binding '79356373' to parameter: 1
2007-08-09 15:48:49,629 [DEBUG] org.hibernate.jdbc.AbstractBatcher - Adding to batch
2007-08-09 15:48:49,629 [DEBUG] org.hibernate.persister.entity.AbstractEntityPersister - Deleting entity: [com.unibet.replication.database.persistence.SqlSta
tementEntity#79356374]
2007-08-09 15:48:49,629 [DEBUG] org.hibernate.jdbc.AbstractBatcher - reusing prepared statement
2007-08-09 15:48:49,629 [DEBUG] org.hibernate.SQL - delete from replication_temp where id=?
2007-08-09 15:48:49,629 [DEBUG] org.hibernate.type.LongType - binding '79356374' to parameter: 1
2007-08-09 15:48:49,629 [DEBUG] org.hibernate.jdbc.AbstractBatcher - Adding to batch
2007-08-09 15:48:49,630 [DEBUG] org.hibernate.persister.entity.AbstractEntityPersister - Deleting entity: [com.unibet.replication.database.persistence.SqlSta
tementEntity#79356375]
2007-08-09 15:48:49,630 [DEBUG] org.hibernate.jdbc.AbstractBatcher - reusing prepared statement
2007-08-09 15:48:49,630 [DEBUG] org.hibernate.SQL - delete from replication_temp where id=?
2007-08-09 15:48:49,630 [DEBUG] org.hibernate.type.LongType - binding '79356375' to parameter: 1
2007-08-09 15:48:49,630 [DEBUG] org.hibernate.jdbc.AbstractBatcher - Adding to batch
2007-08-09 15:48:49,630 [DEBUG] org.hibernate.jdbc.AbstractBatcher - Executing batch size: 15
2007-08-09 15:48:49,633 [DEBUG] org.hibernate.jdbc.AbstractBatcher - success of batch update unknown: 0
2007-08-09 15:48:49,633 [DEBUG] org.hibernate.jdbc.AbstractBatcher - success of batch update unknown: 1
2007-08-09 15:48:49,768 [ERROR] org.hibernate.jdbc.AbstractBatcher - Exception executing batch:
org.hibernate.StaleStateException: Batch update returned unexpected row count from update: 2 actual row count: -1 expected: 1
        at org.hibernate.jdbc.BatchingBatcher.checkRowCount(BatchingBatcher.java:93)
        at org.hibernate.jdbc.BatchingBatcher.checkRowCounts(BatchingBatcher.java:79)
        at org.hibernate.jdbc.BatchingBatcher.doExecuteBatch(BatchingBatcher.java:58)
        at org.hibernate.jdbc.BatchingBatcher.addToBatch(BatchingBatcher.java:34)
        at org.hibernate.persister.entity.AbstractEntityPersister.delete(AbstractEntityPersister.java:2291)
        at org.hibernate.persister.entity.AbstractEntityPersister.delete(AbstractEntityPersister.java:2440)
        at org.hibernate.action.EntityDeleteAction.execute(EntityDeleteAction.java:73)
        at org.hibernate.engine.ActionQueue.execute(ActionQueue.java:248)
        at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:232)
        at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:144)
        at org.hibernate.event.def.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:297)
        at org.hibernate.event.def.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:27)
        at org.hibernate.impl.SessionImpl.flush(SessionImpl.java:985)

What happens after this is that all subsequent batch statements of this type fails. After a little while the globally opened PreparedStatements increases:

Code:

2007-08-09 16:44:43,568 [DEBUG] org.hibernate.jdbc.AbstractBatcher - about to close PreparedStatement (open PreparedStatements: 1, globally: 642)

Most likely this indicates that the problem is JDBC Driver related since the Oracle drivers is rather infamous (at least the early ones). We are currently trying Oracle OCI thick driver to see if that could solve the problem.