openjpa-users mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Chandra Sarath <cthe...@yahoo.com>
Subject Re: OpenJpa, and DB2 shared lock
Date Mon, 27 Apr 2009 17:49:21 GMT

Kevin, 

My answers below in Bold.. I'm attaching the SystemErr.log file here that
may have the same info as the trace.
  http://n2.nabble.com/file/n2727497/SystemErr_Update_lock_testing.log
SystemErr_Update_lock_testing.log 

Thanks,
Chandra



Kevin Sutter wrote:
> 
> Hi Chandra,
> Interesting data.  First thing I noticed is that all of that exception
> trace
> data happens for the same deadlock/timeout exception.  There is no retry
> logic that I can see.  The exception is first reported at 12:27:54:977 and
> the last log messages for this exception (before you break out) is logged
> at
> 12:27:55:400.  Then, it looks like the messages kick in again after you
> force the exit at 12:32:56:103.  So, there's about 5 minutes of nothing
> from
> an OpenJPA trace viewpoint.
> 
> Please ignore 12:32:56:103 database transactions as these are not related
> to our testing. I'm sorry I should have deleted these. :( 
> 
> During those 5 minutes, are you seeing activity with the database itself?
> Do you continue to see the SQL Updates being fired to the database?  From
> an
> OpenJPA perspective, we should either see "success" statements being
> logged
> or the SQL exception data.
> 
> A few things come to mind to narrow down the code path...
> 
> o  First off, have you tried the latest 1.2.x version of OpenJPA?  We
> recently released version 1.2.1.  There have been some updates related to
> the next items in my list that may come into play here.
> 
> We haven't used this version yet. As we are close to start the User
> acceptance testing I'm not sure if we my team lead wants to change the
> version. But i can talk to him.
> 
> 
> 
> o  One area that be affecting you is the Statement Batching support.  As a
> test, could you try turning off Statement Batching to see if that changes
> your scenario at all?  You can do this by setting the following
> property...
> 
> <property name="openjpa.jdbc.DBDictionary" value="batchLimit=0"/>
> 
> Sure I'll include this..
> 
> o  This next item is a longer shot, but a couple of "unexplained exception
> paths" were traced back to our Query SQL Cache.  You can try turning off
> this support via this property.  (I am not seeing anything in the trace
> that
> would indicate that this is related, but if you can remove this thread of
> doubt, that would be great.)
> 
> <property name="openjpa.jdbc.QuerySQLCache" value="false"/>
> 
> Sure I'll include this..
> 
> Based on your provided data, I again re-visited our code and can't find
> where we are doing the retry logic.  But, maybe the experimentation
> suggested above will highlight the spot.  Looking through your trace,
> there
> is also some interesting interaction between your app and Spring.  In area
> of "savepointing"...
> 
> 	at
> org.apache.openjpa.persistence.EntityManagerImpl.flush(EntityManagerImpl.java:592)
> 	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> 	at
> sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:64)
> 	at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> 	at java.lang.reflect.Method.invoke(Method.java:615)
> 	at
> org.springframework.orm.jpa.SharedEntityManagerCreator$SharedEntityManagerInvocationHandler.invoke(SharedEntityManagerCreator.java:194)
> 	at $Proxy2.flush(Unknown Source)
> 	at
> us.or.state.dhs.framework.dao.jpa.application.JpaApplicationHelper.saveApplicationData(JpaApplicationHelper.java:103)
> 	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
> 	at
> sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:64)
> 	at
> sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> 	at java.lang.reflect.Method.invoke(Method.java:615)
> 	at
> org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:310)
> 	at
> org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:182)
> 	at
> org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:149)
> 	at
> org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:106)
> 	at
> org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:171)
> 	at
> org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204)
> 	at $Proxy53.saveApplicationData(Unknown Source)
> 	at
> us.or.state.dhs.framework.dao.jpa.application.JpaApplicationDataDao.saveApplicationData(JpaApplicationDataDao.java:25)
> 
> A combination of your app and Spring seem to be deciding that a flush is
> necessary.  But, because I don't see the retry logic happening in this
> trace, I can't tell if this is the source of the retry or not.  Or, maybe
> since there's no trace data for 5 minutes, maybe it's just deadlocked and
> there is no retry logic.
> 
> Those 5 minutes i think we haven't used the server. So please ignore that.
> 
> Let us know what you find out.  Thanks for your patience while we attempt
> to
> figure out the source of the problem.
> 
> Sure. I'm planning to send trace (end of the day) file again after the
> suggested changes made. 
> 
> 
> Kevin
> 
> On Fri, Apr 24, 2009 at 8:59 PM, Chandra Sarath <cthella@yahoo.com> wrote:
> 
>>
>> Hi Kevin,
>>
>> We have saved trace in a file and attached here. Please take a look at
>> them
>> and let me know if you find any information about why updates are not
>> timed
>> out. Please note that we we have forced it exit, the updates did not time
>> out on their own.
>>
>> We are using DB2  LUW 9.1 fixpack 4  as our database with Websphere 6.1
>> with
>> EJB3 Fep and OpenJpa 1.2.0. We use a non xa driver
>> (db.driverClassName=com.ibm.db2.jcc.DB2Driver) used by a Datasource
>> created
>> in Websphere.
>> http://n2.nabble.com/file/n2701139/trace_Update_lock_testing.log
>> trace_Update_lock_testing.log .
>>
>> Thanks,
>> Chandra
>>
>>
>>
>> Kevin Sutter wrote:
>> >
>> > Hi Chandra,
>> > Do you have the complete trace in a file that you could attach to this
>> > exchange?  Or, post on filebin or something?  Thanks!
>> >
>> > Kevin
>> >
>> > On Fri, Apr 24, 2009 at 3:34 AM, Chandra Sarath <cthella@yahoo.com>
>> wrote:
>> >
>> >>
>> >> Hi,
>> >>
>> >> We have turned on TRACE and we can only see update Sqls for the table
>> >> that
>> >> is locked.
>> >>
>> >>
>> >>                                        <prop
>> >> key="openjpa.Log">DefaultLevel=TRACE, Runtime=TRACE, Tool=TRACE,
>> >> SQL=TRACE</prop>
>> >>                                         <prop
>> key="show_sql">true</prop>
>> >>
>> >> Here is how we tested.
>> >>
>> >>      1. We have locked a child table with shared lock (Read only
>> table)
>> >> and
>> >> ran an update from parent table class.
>> >>         entityManger.merge(parentClass).
>> >>
>> >>       We saw an update sql in TRACE that is trying to update the
>> Locked
>> >> table (say table emp). Since this table is locked, database timed out
>> at
>> >> 30
>> >> sec (timeout property in datasource), but Jpa tried to execute update
>> sql
>> >> again. It tried to update 2 times and timed out and showed the 40001
>> (Db2
>> >> -911) error. for stacktracesee below.
>> >>
>> >>    2. We tried to merge again one more time and it tried to update the
>> >> locked table for 4 times and timeout with the above error.
>> >>
>> >>    3. We tried to merge one more time, and this time it tried to
>> update
>> >> the
>> >> locked table for more than 15 times and continued trying the same
>> until
>> >> we
>> >> disconnected the database manually.
>> >>
>> >> So this is a inconsistent behavior of OpenJPA and is it a bug? We
>> wonder
>> >> why
>> >> it is trying unlimited times to update a locked (read only) table. But
>> >> for
>> >> inserts it times out properly and shows the proper error. I do not
>> knwo
>> >> why
>> >> it is behaving differently for updates.
>> >>
>> >> Please advice any Jpa timeout parameters that I can use for the
>> readonly
>> >> locks.
>> >>
>> >> It is a top priority issue now. Any help on this is greatly
>> appreciated.
>> >> Please find the stacktrace below..
>> >>
>> >> [4/23/09 13:35:27:501 PDT] 00000040 SystemErr     Caused by:
>> >> org.apache.openjpa.lib.jdbc.ReportingSQLException: The
>> >>  current transaction has been rolled back because of a deadlock or
>> >> timeout.
>> >> Reason code "68". {prepstmnt 1684038752
>> >> UPDATE SCHEMA.TABLE SET REC_UPD_TS = ?, AVERAGE_MONTH_INCOME = ?,
>> >> TEST_CODE
>> >> = ?,TEST_PERIOD_CODE = ? WHERE ID = ?
>> >> [params=(Timestamp) 2009-04-23 13:25:25.365, (long) 888, (String) H,
>> >> (String) W, (long) 71383]} [co
>> >> de=-911, state=40001]
>> >>        at
>> >>
>> >>
>> org.apache.openjpa.lib.jdbc.LoggingConnectionDecorator.wrap(LoggingConnectionDecorator.java:192)
>> >>        at
>> >>
>> >>
>> org.apache.openjpa.lib.jdbc.LoggingConnectionDecorator.access$700(LoggingConnectionDecorator.java:57)
>> >>        at
>> >>
>> >>
>> org.apache.openjpa.lib.jdbc.LoggingConnectionDecorator$LoggingConnection$LoggingPreparedStatement.executeU
>> >> pdate(LoggingConnectionDecorator.java:866)
>> >>        at
>> >>
>> >>
>> org.apache.openjpa.lib.jdbc.DelegatingPreparedStatement.executeUpdate(DelegatingPreparedStatement.java:269
>> >> )
>> >>      at
>> >>
>> >>
>> org.apache.openjpa.jdbc.kernel.JDBCStoreManager$CancelPreparedStatement.executeUpdate(JDBCStoreManager.jav
>> >> a:1504)
>> >>        at
>> >>
>> >>
>> org.apache.openjpa.jdbc.kernel.PreparedStatementManagerImpl.executeUpdate(PreparedStatementManagerImpl.jav
>> >> a:151)
>> >>        at
>> >>
>> >>
>> org.apache.openjpa.jdbc.kernel.PreparedStatementManagerImpl.flushAndUpdate(PreparedStatementManagerImpl.ja
>> >> va:120)
>> >>        at
>> >>
>> >>
>> org.apache.openjpa.jdbc.kernel.BatchingPreparedStatementManagerImpl.batchOrExecuteRow(BatchingPreparedStat
>> >> ementManagerImpl.java:102)
>> >>        at
>> >>
>> >>
>> org.apache.openjpa.jdbc.kernel.BatchingPreparedStatementManagerImpl.flushAndUpdate(BatchingPreparedStateme
>> >> ntManagerImpl.java:86)
>> >>        at
>> >>
>> >>
>> org.apache.openjpa.jdbc.kernel.PreparedStatementManagerImpl.flushInternal(PreparedStatementManagerImpl.jav
>> >>
>> >>
>> >>
>> >> Thanks,
>> >> Chandra
>> >>
>> >>
>> >>
>> >>
>> >> Chandra Sarath wrote:
>> >> >
>> >> > Hi,
>> >> >
>> >> > We use OpenJpa, DB2 and Websphere 6.1. We have created a Datasource
>> in
>> >> > Websphere console that connects DB2 using a non-xa driver.
>> >> >
>> >> > We were testing our application about how it rolls back the data
>> when
>> >> > there is a shared lock in a table. we have following scenarios. We
>> have
>> >> > also set a Timeout of 30 seconds in Datasource/connection
>> properties.
>> >> >
>> >> >   1. Insert a record in a read only (Shared lock).
>> >> >   2. Update a record in read only table (Shared lock).
>> >> >
>> >> >   For Scenario 1, after 30 seconds application times out and gives
>> us
>> >> > proper error. But for scenario 2, it goes in infinite
>> >> >   loop and tries to update Database for every 30 secs, and it never
>> >> stops
>> >> > trying to.
>> >> >
>> >> >   Is there any extra property that we need to set in Jpa level or
>> >> > Datasource level so application can timeout after 30 seconds?
>> >> >
>> >> >   we use entityManager.persist() for inserts and
>> entityManager.merge()
>> >> for
>> >> > updates. Can someone help us on this?
>> >> >
>> >> > Thank you!
>> >> > Chandra
>> >> >
>> >>
>> >> --
>> >> View this message in context:
>> >>
>> http://n2.nabble.com/OpenJpa%2C-and-DB2-shared-lock-tp2675084p2691242.html
>> >> Sent from the OpenJPA Users mailing list archive at Nabble.com.
>> >>
>> >>
>> >
>> >
>> http://n2.nabble.com/file/n2701139/trace_Update_lock_testing.log
>> trace_Update_lock_testing.log
>> --
>> View this message in context:
>> http://n2.nabble.com/OpenJpa%2C-and-DB2-shared-lock-tp2675084p2701139.html
>> Sent from the OpenJPA Users mailing list archive at Nabble.com.
>>
>>
> 
> 

-- 
View this message in context: http://n2.nabble.com/OpenJpa%2C-and-DB2-shared-lock-tp2675084p2727497.html
Sent from the OpenJPA Users mailing list archive at Nabble.com.


Mime
View raw message