Re: OpenJpa, and DB2 shared lock

Donald Woods Mon, 27 Apr 2009 08:40:24 -0700

Hi Chandra, can you provide more details on the Spring side of your app,like what version of Spring you're using and what if any annotations arebeing used, like the @Transactional for Spring or JPA annotations?

Are you solely using annotations or do you have a persistence.xml and/ororm.xml you can post?



-Donald


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.

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...

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.)

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.

Re: OpenJpa, and DB2 shared lock

Reply via email to