JDBC batch update errors

[edgar]

Hi,

We are getting unpredictable JDBC batch update errors for various actions in the Alfresco Web Client. For instance we sometimes get it when creating a web content item but I have seen it in other actions as well (e.g. regenerate renditions). The errors are unpredictable in that the next time you attempt the same action the problem may be gone.

The log file shows:

INFO   | jvm 1    | 2007/07/23 13:22:02 | java.sql.BatchUpdateException: Lock wait timeout exceeded; try restarting transaction
INFO   | jvm 1    | 2007/07/23 13:22:02 |    at com.mysql.jdbc.PreparedStatement.executeBatchSerially(PreparedStatement.java:1237)
INFO   | jvm 1    | 2007/07/23 13:22:02 |    at com.mysql.jdbc.PreparedStatement.executeBatch(PreparedStatement.java:936)
INFO   | jvm 1    | 2007/07/23 13:22:02 |    at org.apache.commons.dbcp.DelegatingStatement.executeBatch(DelegatingStatement.java:294)
INFO   | jvm 1    | 2007/07/23 13:22:02 |    at org.hibernate.jdbc.BatchingBatcher.doExecuteBatch(BatchingBatcher.java:48)
INFO   | jvm 1    | 2007/07/23 13:22:02 |    at org.hibernate.jdbc.AbstractBatcher.executeBatch(AbstractBatcher.java:242)
INFO   | jvm 1    | 2007/07/23 13:22:02 |    at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:235)
INFO   | jvm 1    | 2007/07/23 13:22:02 |    at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:139)
INFO   | jvm 1    | 2007/07/23 13:22:02 |    at org.hibernate.event.def.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:298)
INFO   | jvm 1    | 2007/07/23 13:22:02 |    at org.hibernate.event.def.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:27)
INFO   | jvm 1    | 2007/07/23 13:22:02 |    at org.hibernate.impl.SessionImpl.flush(SessionImpl.java:1000)
INFO   | jvm 1    | 2007/07/23 13:22:02 |    at org.alfresco.repo.avm.hibernate.AVMNodeDAOHibernate.flush(AVMNodeDAOHibernate.java:175)
INFO   | jvm 1    | 2007/07/23 13:22:02 |    at org.alfresco.repo.avm.PlainDirectoryNodeImpl.removeChild(PlainDirectoryNodeImpl.java:251)
INFO   | jvm 1    | 2007/07/23 13:22:02 |    at sun.reflect.GeneratedMethodAccessor1091.invoke(Unknown Source)
INFO   | jvm 1    | 2007/07/23 13:22:02 |    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
INFO   | jvm 1    | 2007/07/23 13:22:02 |    at java.lang.reflect.Method.invoke(Method.java:585)
INFO   | jvm 1    | 2007/07/23 13:22:02 |    at org.hibernate.proxy.pojo.cglib.CGLIBLazyInitializer.invoke(CGLIBLazyInitializer.java:153)
INFO   | jvm 1    | 2007/07/23 13:22:02 |    at org.alfresco.repo.avm.PlainDirectoryNode$$EnhancerByCGLIB$$67cd87d2.removeChild(<generated>)
INFO   | jvm 1    | 2007/07/23 13:22:02 |    at org.alfresco.repo.avm.AVMStoreImpl.removeNode(AVMStoreImpl.java:641)
INFO   | jvm 1    | 2007/07/23 13:22:02 |    at org.alfresco.repo.avm.AVMRepository.remove(AVMRepository.java:837)
INFO   | jvm 1    | 2007/07/23 13:22:02 |    at org.alfresco.repo.avm.AVMServiceImpl.removeNode(AVMServiceImpl.java:505)
INFO   | jvm 1    | 2007/07/23 13:22:02 |    at sun.reflect.GeneratedMethodAccessor1004.invoke(Unknown Source)
INFO   | jvm 1    | 2007/07/23 13:22:02 |    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
INFO   | jvm 1    | 2007/07/23 13:22:02 |    at java.lang.reflect.Method.invoke(Method.java:585)
INFO   | jvm 1    | 2007/07/23 13:22:02 |    at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:281)
INFO   | jvm 1    | 2007/07/23 13:22:02 |    at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:187)
INFO   | jvm 1    | 2007/07/23 13:22:02 |    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:154)
INFO   | jvm 1    | 2007/07/23 13:22:02 |    at org.alfresco.repo.search.AVMSnapShotTriggeredIndexingMethodInterceptor.invoke(AVMSnapShotTriggeredIndexingMethodInterceptor.java:154)
INFO   | jvm 1    | 2007/07/23 13:22:02 |    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:176)
INFO   | jvm 1    | 2007/07/23 13:22:02 |    at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:210)
INFO   | jvm 1    | 2007/07/23 13:22:02 |    at $Proxy5.removeNode(Unknown Source)
INFO   | jvm 1    | 2007/07/23 13:22:02 |    at org.alfresco.repo.avm.AVMSyncServiceImpl.resetLayer(AVMSyncServiceImpl.java:791)
INFO   | jvm 1    | 2007/07/23 13:22:02 |    at sun.reflect.GeneratedMethodAccessor1008.invoke(Unknown Source)
INFO   | jvm 1    | 2007/07/23 13:22:02 |    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
INFO   | jvm 1    | 2007/07/23 13:22:02 |    at java.lang.reflect.Method.invoke(Method.java:585)
INFO   | jvm 1    | 2007/07/23 13:22:02 |    at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:281)
INFO   | jvm 1    | 2007/07/23 13:22:02 |    at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:187)
INFO   | jvm 1    | 2007/07/23 13:22:02 |    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:154)
INFO   | jvm 1    | 2007/07/23 13:22:02 |    at org.alfresco.repo.transaction.RetryingTransactionAdvice.invoke(RetryingTransactionAdvice.java:92)
INFO   | jvm 1    | 2007/07/23 13:22:02 |    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:176)
INFO   | jvm 1    | 2007/07/23 13:22:02 |    at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:210)
INFO   | jvm 1    | 2007/07/23 13:22:02 |    at $Proxy46.resetLayer(Unknown Source)
INFO   | jvm 1    | 2007/07/23 13:22:02 |    at org.alfresco.web.bean.wcm.CreateWebContentWizard.init(CreateWebContentWizard.java:221)
INFO   | jvm 1    | 2007/07/23 13:22:02 |    at org.alfresco.web.bean.wizard.WizardManager.setCurrentWizard(WizardManager.java:123)
INFO   | jvm 1    | 2007/07/23 13:22:02 |    at org.alfresco.web.app.AlfrescoNavigationHandler.handleWizardOpen(AlfrescoNavigationHandler.java:636)
INFO   | jvm 1    | 2007/07/23 13:22:02 |    at org.alfresco.web.app.AlfrescoNavigationHandler.handleNavigation(AlfrescoNavigationHandler.java:118)
INFO   | jvm 1    | 2007/07/23 13:22:02 |    at org.apache.myfaces.application.ActionListenerImpl.processAction(ActionListenerImpl.java:82)
INFO   | jvm 1    | 2007/07/23 13:22:02 |    at javax.faces.component.UICommand.broadcast(UICommand.java:109)
INFO   | jvm 1    | 2007/07/23 13:22:02 |    at javax.faces.component.UIViewRoot._broadcastForPhase(UIViewRoot.java:97)
INFO   | jvm 1    | 2007/07/23 13:22:02 |    at javax.faces.component.UIViewRoot.processApplication(UIViewRoot.java:171)
INFO   | jvm 1    | 2007/07/23 13:22:02 |    at org.apache.myfaces.lifecycle.InvokeApplicationExecutor.execute(InvokeApplicationExecutor.java:32)
INFO   | jvm 1    | 2007/07/23 13:22:02 |    at org.apache.myfaces.lifecycle.LifecycleImpl.executePhase(LifecycleImpl.java:95)
INFO   | jvm 1    | 2007/07/23 13:22:02 |    at org.apache.myfaces.lifecycle.LifecycleImpl.execute(LifecycleImpl.java:70)
INFO   | jvm 1    | 2007/07/23 13:22:02 |    at javax.faces.webapp.FacesServlet.service(FacesServlet.java:139)
INFO   | jvm 1    | 2007/07/23 13:22:02 |    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:269)
INFO   | jvm 1    | 2007/07/23 13:22:02 |    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:188)
INFO   | jvm 1    | 2007/07/23 13:22:02 |    at org.alfresco.web.app.servlet.AuthenticationFilter.doFilter(AuthenticationFilter.java:81)
INFO   | jvm 1    | 2007/07/23 13:22:02 |    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:215)
INFO   | jvm 1    | 2007/07/23 13:22:02 |    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:188)
INFO   | jvm 1    | 2007/07/23 13:22:02 |    at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:210)
INFO   | jvm 1    | 2007/07/23 13:22:02 |    at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:174)
INFO   | jvm 1    | 2007/07/23 13:22:02 |    at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127)
INFO   | jvm 1    | 2007/07/23 13:22:02 |    at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:117)
INFO   | jvm 1    | 2007/07/23 13:22:02 |    at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:108)
INFO   | jvm 1    | 2007/07/23 13:22:02 |    at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:151)
INFO   | jvm 1    | 2007/07/23 13:22:02 |    at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:870)
INFO   | jvm 1    | 2007/07/23 13:22:02 |    at org.apache.coyote.http11.Http11BaseProtocol$Http11ConnectionHandler.processConnection(Http11BaseProtocol.java:665)
INFO   | jvm 1    | 2007/07/23 13:22:02 |    at org.apache.tomcat.util.net.PoolTcpEndpoint.processSocket(PoolTcpEndpoint.java:528)
INFO   | jvm 1    | 2007/07/23 13:22:02 |    at org.apache.tomcat.util.net.LeaderFollowerWorkerThread.runIt(LeaderFollowerWorkerThread.java:81)
INFO   | jvm 1    | 2007/07/23 13:22:02 |    at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:685)
INFO   | jvm 1    | 2007/07/23 13:22:02 |    at java.lang.Thread.run(Thread.java:595)
‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍

We also notice that the performance of the Alfresco s very slow. The save action when creating a new web content item for example takes a very long time (>1 minute).

Any ideas on how to resolve this? I do not know what the problem is but I have a feeling it has to do with the versioning system maybe? Can we disable versioning on web content items at all, to see if that is the issue?

We are running Alfresco 2.1R1 on Linux on MySQL.

regards,

Edgar

[kvc]

Edgar:


Versioning cannot be disabled in the AVM, but versioning is definitely not the problem here.

This looks like a problem with our new locking feature.  Can you file a bug in JIRA on this?  This should definitely be looked into …  also, if you could not only provide details on your platform in the JIRA issue, but the scale of ops (are you doing one submit or multiple submits simulatenously, how many items are you submitting, etc.) that would be helpful.  We'll look into ASAP.


Kevin