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.
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.
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"/>
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"/>
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.
Let us know what you find out. Thanks for your patience while we attempt to
figure out the source of the problem.
Kevin
On Fri, Apr 24, 2009 at 8:59 PM, Chandra Sarath <[email protected]> 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 <[email protected]>
> 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.
>
>
