Performance issues with message bundles loading and java.lang.IllegalStateException: Timer already cancelled. error

Description

Jean-François Lévêque reported these issues. We've also experienced them.

I first get this failure on the update :
2011-09-15 09:07:27,269 ERROR Timer-3 org.hibernate.util.JDBCExceptionReporter - Lock wait timeout exceeded; try restarting transaction
2011-09-15 09:07:27,270 ERROR Timer-3 org.hibernate.event.def.AbstractFlushingEventListener - Could not synchronize database state with session
org.hibernate.exception.GenericJDBCException: Could not execute JDBC batch update
at org.hibernate.exception.SQLStateConverter.handledNonSpecificException(SQLStateConverter.java:103)
at org.hibernate.exception.SQLStateConverter.convert(SQLStateConverter.java:91)
at org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:43)
at org.hibernate.jdbc.AbstractBatcher.executeBatch(AbstractBatcher.java:254)
at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:266)
at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:168)
at org.hibernate.event.def.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:298)
at org.hibernate.event.def.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:27)
at org.hibernate.impl.SessionImpl.flush(SessionImpl.java:1001)
at org.springframework.orm.hibernate3.HibernateAccessor.flushIfNecessary(HibernateAccessor.java:390)
at org.springframework.orm.hibernate3.HibernateTemplate.doExecute(HibernateTemplate.java:420)
at org.springframework.orm.hibernate3.HibernateTemplate.executeWithNativeSession(HibernateTemplate.java:374)
at org.springframework.orm.hibernate3.HibernateTemplate.saveOrUpdate(HibernateTemplate.java:748)
at org.sakaiproject.messagebundle.impl.MessageBundleServiceImpl.updateMessageBundleProperty(MessageBundleServiceImpl.java:272)
at org.sakaiproject.messagebundle.impl.MessageBundleServiceImpl.saveOrUpdateInternal(MessageBundleServiceImpl.java:193)
at org.sakaiproject.messagebundle.impl.MessageBundleServiceImpl$SaveOrUpdateTask.run(MessageBundleServiceImpl.java:453)
at java.util.TimerThread.mainLoop(Timer.java:512)
at java.util.TimerThread.run(Timer.java:462)
Caused by: java.sql.BatchUpdateException: Lock wait timeout exceeded; try restarting transaction
at com.mysql.jdbc.PreparedStatement.executeBatchSerially(PreparedStatement.java:2024)
at com.mysql.jdbc.PreparedStatement.executeBatch(PreparedStatement.java:1449)
at org.apache.commons.dbcp.DelegatingStatement.executeBatch(DelegatingStatement.java:297)
at org.hibernate.jdbc.BatchingBatcher.doExecuteBatch(BatchingBatcher.java:48)
at org.hibernate.jdbc.AbstractBatcher.executeBatch(AbstractBatcher.java:247)
... 14 more
Caused by: java.sql.SQLException: Lock wait timeout exceeded; try restarting transaction
at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:1073)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3597)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3529)
at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1990)
at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2151)
at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2625)
at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:2119)
at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2415)
at com.mysql.jdbc.PreparedStatement.executeBatchSerially(PreparedStatement.java:1976)
... 18 more
Exception in thread "Timer-3" org.springframework.dao.CannotAcquireLockException: Hibernate operation: Could not execute JDBC batch update; SQL [update SAKAI_MESSAGE_BUNDLE set MODULE_NAME=?, BASENAME=?, PROP_NAME=?, PROP_VALUE=?, LOCALE=?, DEFAULT_VALUE=? where ID=?]; Lock wait timeout exceeded; try restarting transaction; nested exception is java.sql.BatchUpdateException: Lock wait timeout exceeded; try restarting transaction
at org.springframework.jdbc.support.SQLErrorCodeSQLExceptionTranslator.doTranslate(SQLErrorCodeSQLExceptionTranslator.java:244)
at org.springframework.jdbc.support.AbstractFallbackSQLExceptionTranslator.translate(AbstractFallbackSQLExceptionTranslator.java:72)
at org.springframework.orm.hibernate3.HibernateAccessor.convertJdbcAccessException(HibernateAccessor.java:424)
at org.springframework.orm.hibernate3.HibernateAccessor.convertHibernateAccessException(HibernateAccessor.java:410)
at org.springframework.orm.hibernate3.HibernateTemplate.doExecute(HibernateTemplate.java:424)
at org.springframework.orm.hibernate3.HibernateTemplate.executeWithNativeSession(HibernateTemplate.java:374)
at org.springframework.orm.hibernate3.HibernateTemplate.saveOrUpdate(HibernateTemplate.java:748)
at org.sakaiproject.messagebundle.impl.MessageBundleServiceImpl.updateMessageBundleProperty(MessageBundleServiceImpl.java:272)
at org.sakaiproject.messagebundle.impl.MessageBundleServiceImpl.saveOrUpdateInternal(MessageBundleServiceImpl.java:193)
at org.sakaiproject.messagebundle.impl.MessageBundleServiceImpl$SaveOrUpdateTask.run(MessageBundleServiceImpl.java:453)
at java.util.TimerThread.mainLoop(Timer.java:512)
at java.util.TimerThread.run(Timer.java:462)
Caused by: java.sql.BatchUpdateException: Lock wait timeout exceeded; try restarting transaction
at com.mysql.jdbc.PreparedStatement.executeBatchSerially(PreparedStatement.java:2024)
at com.mysql.jdbc.PreparedStatement.executeBatch(PreparedStatement.java:1449)
at org.apache.commons.dbcp.DelegatingStatement.executeBatch(DelegatingStatement.java:297)
at org.hibernate.jdbc.BatchingBatcher.doExecuteBatch(BatchingBatcher.java:48)
at org.hibernate.jdbc.AbstractBatcher.executeBatch(AbstractBatcher.java:247)
at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:266)
at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:168)
at org.hibernate.event.def.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:298)
at org.hibernate.event.def.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:27)
at org.hibernate.impl.SessionImpl.flush(SessionImpl.java:1001)
at org.springframework.orm.hibernate3.HibernateAccessor.flushIfNecessary(HibernateAccessor.java:390)
at org.springframework.orm.hibernate3.HibernateTemplate.doExecute(HibernateTemplate.java:420)
... 7 more
Caused by: java.sql.SQLException: Lock wait timeout exceeded; try restarting transaction
at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:1073)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3597)
at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3529)
at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1990)
at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2151)
at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2625)
at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:2119)
at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2415)
at com.mysql.jdbc.PreparedStatement.executeBatchSerially(PreparedStatement.java:1976)
... 18 more

I then start to get ERRORs like :
2011-09-15 09:09:25,326 ERROR TP-Processor24 org.sakaiproject.portal.util.ErrorReporter - Failed to generate request display
java.lang.IllegalStateException: Timer already cancelled.
at java.util.Timer.sched(Timer.java:354)
at java.util.Timer.schedule(Timer.java:170)
at org.sakaiproject.messagebundle.impl.MessageBundleServiceImpl.saveOrUpdate(MessageBundleServiceImpl.java:145)
at sun.reflect.GeneratedMethodAccessor427.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:307)
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 $Proxy135.saveOrUpdate(Unknown Source)
at org.sakaiproject.util.DbResourceBundle.indexResourceBundle(DbResourceBundle.java:140)
at org.sakaiproject.util.ResourceLoader.loadBundleFromDb(ResourceLoader.java:635)
at org.sakaiproject.util.ResourceLoader.loadBundle(ResourceLoader.java:588)
at org.sakaiproject.util.ResourceLoader.getBundleFromDb(ResourceLoader.java:556)
at org.sakaiproject.util.ResourceLoader.getBundle(ResourceLoader.java:529)
at org.sakaiproject.util.ResourceLoader.getString(ResourceLoader.java:370)
at org.sakaiproject.portal.util.ErrorReporter.requestDisplay(ErrorReporter.java:596)
at org.sakaiproject.portal.util.ErrorReporter.report(ErrorReporter.java:417)
at org.sakaiproject.portal.util.ErrorReporter.report(ErrorReporter.java:399)
at org.sakaiproject.portal.charon.SkinnableCharonPortal.doThrowableError(SkinnableCharonPortal.java:379)
at org.sakaiproject.portal.charon.SkinnableCharonPortal.doGet(SkinnableCharonPortal.java:903)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:627)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:729)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:269)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:188)
at org.sakaiproject.util.RequestFilter.doFilter(RequestFilter.java:659)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:215)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:188)
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:213)
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:172)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:117)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:108)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:174)
at org.apache.jk.server.JkCoyoteHandler.invoke(JkCoyoteHandler.java:200)
at org.apache.jk.common.HandlerRequest.invoke(HandlerRequest.java:291)
at org.apache.jk.common.ChannelSocket.invoke(ChannelSocket.java:775)
at org.apache.jk.common.ChannelSocket.processConnection(ChannelSocket.java:704)
at org.apache.jk.common.ChannelSocket$SocketConnection.runIt(ChannelSocket.java:897)
at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:689)
at java.lang.Thread.run(Thread.java:662)
2011-09-15 09:09:25,337 ERROR TP-Processor24 org.apache.catalina.core.ContainerBase.[Catalina].[localhost]./portal.[sakai.portal.charon] - "Servlet.service()" pour la servlet sakai.portal.charon a généré une exception

And they keep coming until Tomcat is restarted.

Cheers,

Activity

Show:

Steve Swinsburg January 28, 2013 at 3:12 PM

Presuming this needs a merge to 1.3.x as well?

Matthew Buckett January 14, 2013 at 10:10 AM

This commit also fixes issues with Tomcat shutting down on 2.8.x as the Timer was not marked as a daemon so was keeping the JVM running when everything else had shutdown.

Beth Kirschner September 12, 2012 at 7:04 AM

This change only affects the MessageBundle contrib tool (https://source.sakaiproject.org/contrib/rsmart/messagebundle) which is not running on any nightly server, so this is difficult to test. A code review found no problems or concerns, so I think we should merge to kernel trunk.

We should verify this on https://qa13-uk.sakaiproject.org/portal once this server has been updated to a kernel build that includes this fix.

Hudson CI Server January 27, 2012 at 2:25 PM

Integrated in kernel-trunk #423 (See http://builds.sakaiproject.org:8080/job/kernel-trunk/423/)
address weird jdbc issues and timer already cancelled problems.

John Bush January 27, 2012 at 2:01 PM

Followed the same pattern the BaseDigestService is using. I think possibly not using a Timer as a daemon was part of the problem. In addition, this should solve any sort of locking issues as the queue will be processed by one thread now, this should limit any contention that was the root of the weird jdbc errors.

Fixed

Details

Priority

Affects versions

Fix versions

Components

Assignee

Reporter

Created January 27, 2012 at 8:05 AM
Updated April 25, 2018 at 3:18 PM
Resolved January 27, 2012 at 1:59 PM