Hibernate version: 3.1.2
Name and version of the database : MS SQL Server 2000
Datasource implmentation class being used : com.sap.nwmss.jdbcx.sqlserver.SQLServerDataSource
We are using SAP NetWeaver Application Server 6.0 and Hibernate 3.1.2 in our application. We have StalessSessionBeans which use Hibernate to interact with the database. We are running into a situation where the application goes into a hang state when the following flow is bein executed:
Code:
//transaction attribute = "Required"
beanMethod() {
myObj = new MyObj();
myObj.setSomeValue();
session = SessionFactory.openSession();
//id is auto generated by database
id = session.insert(myObj);
//retrieve the recently inserted obj
myUpdatedObj = session.load(id);
//modify the myUpdatedObj
myUpdatedObj.modifySomeValue();
//update using hibernate session
session.update(myUpdatedObj);
//return from method
}
Here's the flow:
1) In a CMT stateless session bean, there's a method which has transaction atrribute as "Required"
2) This method creates a new object and inserts it
3) Then loads this saved object and modifies some values in it
4) Then invokes the update method on the session to update this modified object in the database.
Note: We have enabled auto flush on transaction in the hibernate configuration file.
And here's what we are observing:
- The insert obtains a lock on the row as part of the transaction
- When the update is called on the same row as part of the auto flush, the update never completes. The update statement is unable to obtain a lock on the same row.
Here is some additional info:
- We have set :
Code:
session.connection().setTransactionIsolation(Connection.TRANSACTION_READ_UNCOMMITTED);
hibernate.cfg.xml:
Code:
<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE hibernate-configuration PUBLIC
"-//Hibernate/Hibernate Configuration DTD 3.0//EN"
"http://hibernate.sourceforge.net/hibernate-configuration-3.0.dtd">
<hibernate-configuration>
<session-factory>
<property name="hibernate.jndi.class">
com.sap.engine.services.jndi.InitialContextFactoryImpl
</property>
<property name="hibernate.session_factory_name">
HibernateSessionFactory
</property>
<property name="hibernate.transaction.factory_class">
org.hibernate.transaction.JTATransactionFactory
</property>
<property name="hibernate.connection.datasource">jdbc/SQLPool1</property>
<property name="hibernate.connection.pool_size">25</property>
<property name="show_sql">true</property>
<property name="hibernate.connection.isolation">1</property>
<property name="hibernate.prepare_sql">true</property>
<property name="hibernate.statement_cache.size">10000</property>
<!--property name="hibernate.jdbc.use_scrollable_resultset">true</property-->
<property name="transaction.manager_lookup_class">
com.tdemand.server.util.hibernate.SAPWebASTransactionManagerLookup
</property>
<property name="hibernate.jdbc.use_get_generated_keys">
false
</property>
<property name="hibernate.transaction.flush_before_completion">true</property>
<property name="hibernate.jdbc.batch_size">1000</property>
<property name="hibernate.cache.use_second_level_cache">false</property>
......
</session-factory>
</hibernate-configuration>
Any clue why the update query is having problem in completing, even though update and insert are being called from the same bean method as part of a transaction?
Here's the log:
Quote:
2006-11-01 22:10:00,310 INFO [com.tdemand.server.planning.ejbs.ForecastPlanningSessionBean] - Starting save
2006-11-01 22:10:00,310 DEBUG [org.hibernate.event.def.DefaultSaveOrUpdateEventListener] - saving transient instance
2006-11-01 22:10:00,310 DEBUG [org.hibernate.event.def.DefaultSaveOrUpdateEventListener] - saving transient instance
2006-11-01 22:10:00,310 DEBUG [org.hibernate.event.def.AbstractSaveEventListener] - saving [com.tdemand.generated.pojo.TdForecastPlan#<null>]
2006-11-01 22:10:00,310 DEBUG [org.hibernate.event.def.AbstractSaveEventListener] - saving [com.tdemand.generated.pojo.TdForecastPlan#<null>]
2006-11-01 22:10:00,310 DEBUG [org.hibernate.event.def.AbstractSaveEventListener] - executing insertions
2006-11-01 22:10:00,310 DEBUG [org.hibernate.event.def.AbstractSaveEventListener] - executing insertions
2006-11-01 22:10:00,310 DEBUG [org.hibernate.persister.entity.BasicEntityPersister] - Inserting entity: com.tdemand.generated.pojo.TdForecastPlan (native id)
2006-11-01 22:10:00,310 DEBUG [org.hibernate.persister.entity.BasicEntityPersister] - Inserting entity: com.tdemand.generated.pojo.TdForecastPlan (native id)
2006-11-01 22:10:00,310 DEBUG [org.hibernate.jdbc.AbstractBatcher] - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2006-11-01 22:10:00,310 DEBUG [org.hibernate.jdbc.AbstractBatcher] - about to open PreparedStatement (open PreparedStatements: 0, globally: 0)
2006-11-01 22:10:00,325 DEBUG [org.hibernate.SQL] - insert into trd0nedbo.TD_FORECAST_PLAN (ORGANIZATION_TBL_ID, USER_TBL_ID, PLAN_NAME, IS_ACTIVE, PLAN_TYPE, TIMECREATED, TIMEUPDATED, START_TIME, END_TIME, HORIZON, HORIZON_UOM, REVIEW_FREQ, ACCU_THRESHOLD, REVIEW_FREQ_UOM, FORECAST_METRIC, BASE_FORECAST, PRECISION_FORECAST, ADJUSTED_FORECAST, ORG_ID, CRON_TRIG_NAME) values (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?) select scope_identity()
2006-11-01 22:10:00,325 DEBUG [org.hibernate.SQL] - insert into trd0nedbo.TD_FORECAST_PLAN (ORGANIZATION_TBL_ID, USER_TBL_ID, PLAN_NAME, IS_ACTIVE, PLAN_TYPE, TIMECREATED, TIMEUPDATED, START_TIME, END_TIME, HORIZON, HORIZON_UOM, REVIEW_FREQ, ACCU_THRESHOLD, REVIEW_FREQ_UOM, FORECAST_METRIC, BASE_FORECAST, PRECISION_FORECAST, ADJUSTED_FORECAST, ORG_ID, CRON_TRIG_NAME) values (?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?) select scope_identity()
2006-11-01 22:10:00,325 DEBUG [org.hibernate.jdbc.AbstractBatcher] - preparing statement
2006-11-01 22:10:00,325 DEBUG [org.hibernate.jdbc.AbstractBatcher] - preparing statement
2006-11-01 22:10:00,325 DEBUG [org.hibernate.persister.entity.BasicEntityPersister] - Dehydrating entity: [com.tdemand.generated.pojo.TdForecastPlan#<null>]
2006-11-01 22:10:00,325 DEBUG [org.hibernate.persister.entity.BasicEntityPersister] - Dehydrating entity: [com.tdemand.generated.pojo.TdForecastPlan#<null>]
2006-11-01 22:10:00,341 DEBUG [org.hibernate.type.LongType] - binding '6' to parameter: 1
2006-11-01 22:10:00,341 DEBUG [org.hibernate.type.LongType] - binding '6' to parameter: 1
2006-11-01 22:10:00,341 DEBUG [org.hibernate.type.LongType] - binding '1' to parameter: 2
2006-11-01 22:10:00,341 DEBUG [org.hibernate.type.LongType] - binding '1' to parameter: 2
2006-11-01 22:10:00,341 DEBUG [org.hibernate.type.StringType] - binding 'jaikiranpai' to parameter: 3
2006-11-01 22:10:00,341 DEBUG [org.hibernate.type.StringType] - binding 'jaikiranpai' to parameter: 3
2006-11-01 22:10:00,341 DEBUG [org.hibernate.type.StringType] - binding 'Y' to parameter: 4
2006-11-01 22:10:00,341 DEBUG [org.hibernate.type.StringType] - binding 'Y' to parameter: 4
2006-11-01 22:10:00,341 DEBUG [org.hibernate.type.StringType] - binding 'RetailDCOrderForecast' to parameter: 5
2006-11-01 22:10:00,341 DEBUG [org.hibernate.type.StringType] - binding 'RetailDCOrderForecast' to parameter: 5
2006-11-01 22:10:00,341 DEBUG [org.hibernate.type.TimestampType] - binding '2006-11-01 22:10:00' to parameter: 6
2006-11-01 22:10:00,341 DEBUG [org.hibernate.type.TimestampType] - binding '2006-11-01 22:10:00' to parameter: 6
2006-11-01 22:10:00,341 DEBUG [org.hibernate.type.TimestampType] - binding null to parameter: 7
2006-11-01 22:10:00,341 DEBUG [org.hibernate.type.TimestampType] - binding null to parameter: 7
2006-11-01 22:10:00,341 DEBUG [org.hibernate.type.TimestampType] - binding '2006-11-01 22:10:00' to parameter: 8
2006-11-01 22:10:00,341 DEBUG [org.hibernate.type.TimestampType] - binding '2006-11-01 22:10:00' to parameter: 8
2006-11-01 22:10:00,341 DEBUG [org.hibernate.type.TimestampType] - binding null to parameter: 9
2006-11-01 22:10:00,341 DEBUG [org.hibernate.type.TimestampType] - binding null to parameter: 9
2006-11-01 22:10:00,341 DEBUG [org.hibernate.type.BigDecimalType] - binding '14' to parameter: 10
2006-11-01 22:10:00,341 DEBUG [org.hibernate.type.BigDecimalType] - binding '14' to parameter: 10
2006-11-01 22:10:00,341 DEBUG [org.hibernate.type.StringType] - binding 'DAY' to parameter: 11
2006-11-01 22:10:00,341 DEBUG [org.hibernate.type.StringType] - binding 'DAY' to parameter: 11
2006-11-01 22:10:00,341 DEBUG [org.hibernate.type.BigDecimalType] - binding '7' to parameter: 12
2006-11-01 22:10:00,341 DEBUG [org.hibernate.type.BigDecimalType] - binding '7' to parameter: 12
2006-11-01 22:10:00,341 DEBUG [org.hibernate.type.BigDecimalType] - binding '0' to parameter: 13
2006-11-01 22:10:00,341 DEBUG [org.hibernate.type.BigDecimalType] - binding '0' to parameter: 13
2006-11-01 22:10:00,341 DEBUG [org.hibernate.type.StringType] - binding 'DAY' to parameter: 14
2006-11-01 22:10:00,341 DEBUG [org.hibernate.type.StringType] - binding 'DAY' to parameter: 14
2006-11-01 22:10:00,341 DEBUG [org.hibernate.type.StringType] - binding 'MAPE' to parameter: 15
2006-11-01 22:10:00,341 DEBUG [org.hibernate.type.StringType] - binding 'MAPE' to parameter: 15
2006-11-01 22:10:00,341 DEBUG [org.hibernate.type.StringType] - binding null to parameter: 16
2006-11-01 22:10:00,341 DEBUG [org.hibernate.type.StringType] - binding null to parameter: 16
2006-11-01 22:10:00,341 DEBUG [org.hibernate.type.StringType] - binding null to parameter: 17
2006-11-01 22:10:00,341 DEBUG [org.hibernate.type.StringType] - binding null to parameter: 17
2006-11-01 22:10:00,341 DEBUG [org.hibernate.type.StringType] - binding null to parameter: 18
2006-11-01 22:10:00,341 DEBUG [org.hibernate.type.StringType] - binding null to parameter: 18
2006-11-01 22:10:00,341 DEBUG [org.hibernate.type.BigDecimalType] - binding null to parameter: 19
2006-11-01 22:10:00,341 DEBUG [org.hibernate.type.BigDecimalType] - binding null to parameter: 19
2006-11-01 22:10:00,341 DEBUG [org.hibernate.type.StringType] - binding null to parameter: 20
2006-11-01 22:10:00,341 DEBUG [org.hibernate.type.StringType] - binding null to parameter: 20
2006-11-01 22:10:00,341 DEBUG [org.hibernate.id.IdentifierGeneratorFactory] - Natively generated identity: 103
2006-11-01 22:10:00,341 DEBUG [org.hibernate.id.IdentifierGeneratorFactory] - Natively generated identity: 103
2006-11-01 22:10:00,341 DEBUG [org.hibernate.jdbc.AbstractBatcher] - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2006-11-01 22:10:00,341 DEBUG [org.hibernate.jdbc.AbstractBatcher] - about to close PreparedStatement (open PreparedStatements: 1, globally: 1)
2006-11-01 22:10:00,341 DEBUG [org.hibernate.jdbc.AbstractBatcher] - closing statement
2006-11-01 22:10:00,341 DEBUG [org.hibernate.jdbc.AbstractBatcher] - closing statement