Return-Path: Delivered-To: apmail-openjpa-users-archive@minotaur.apache.org Received: (qmail 66734 invoked from network); 27 Apr 2009 17:49:51 -0000 Received: from hermes.apache.org (HELO mail.apache.org) (140.211.11.3) by minotaur.apache.org with SMTP; 27 Apr 2009 17:49:51 -0000 Received: (qmail 67982 invoked by uid 500); 27 Apr 2009 17:49:51 -0000 Delivered-To: apmail-openjpa-users-archive@openjpa.apache.org Received: (qmail 67894 invoked by uid 500); 27 Apr 2009 17:49:51 -0000 Mailing-List: contact users-help@openjpa.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: users@openjpa.apache.org Delivered-To: mailing list users@openjpa.apache.org Received: (qmail 67883 invoked by uid 99); 27 Apr 2009 17:49:51 -0000 Received: from athena.apache.org (HELO athena.apache.org) (140.211.11.136) by apache.org (qpsmtpd/0.29) with ESMTP; Mon, 27 Apr 2009 17:49:51 +0000 X-ASF-Spam-Status: No, hits=1.4 required=10.0 tests=FORGED_YAHOO_RCVD,SPF_HELO_PASS,SPF_PASS X-Spam-Check-By: apache.org Received-SPF: pass (athena.apache.org: domain of lists+1214986160035-208411@n2.nabble.com designates 216.139.236.158 as permitted sender) Received: from [216.139.236.158] (HELO kuber.nabble.com) (216.139.236.158) by apache.org (qpsmtpd/0.29) with ESMTP; Mon, 27 Apr 2009 17:49:42 +0000 Received: from tervel.nabble.com ([192.168.236.150]) by kuber.nabble.com with esmtp (Exim 4.63) (envelope-from ) id 1LyUxF-0003PI-Qn for users@openjpa.apache.org; Mon, 27 Apr 2009 10:49:21 -0700 Message-ID: <1240854561812-2727497.post@n2.nabble.com> Date: Mon, 27 Apr 2009 10:49:21 -0700 (PDT) From: Chandra Sarath To: users@openjpa.apache.org Subject: Re: OpenJpa, and DB2 shared lock In-Reply-To: <89c0c52c0904270734u62bc7497h7bb3c27399715b3a@mail.gmail.com> MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Transfer-Encoding: 7bit X-Nabble-From: cthella@yahoo.com References: <1240392156466-2675084.post@n2.nabble.com> <1240562065658-2691242.post@n2.nabble.com> <89c0c52c0904240605n3d52714apbb3636f6b8c85f04@mail.gmail.com> <1240624749199-2701139.post@n2.nabble.com> <89c0c52c0904270734u62bc7497h7bb3c27399715b3a@mail.gmail.com> X-Virus-Checked: Checked by ClamAV on apache.org 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... > > > > 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.) > > > > 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 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 >> wrote: >> > >> >> >> >> Hi, >> >> >> >> We have turned on TRACE and we can only see update Sqls for the table >> >> that >> >> is locked. >> >> >> >> >> >> > >> key="openjpa.Log">DefaultLevel=TRACE, Runtime=TRACE, Tool=TRACE, >> >> SQL=TRACE >> >> > key="show_sql">true >> >> >> >> 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.