AnsweredAssumed Answered

db connection loss & huge number of blocked threads

Question asked by mrks.js1 on Jun 30, 2017
Latest reply on Jul 11, 2017 by afaust

We are running Alfresco GA 201702 internally (rhel 6.8, ~25gb of ram, quadcore, mysql, solr4)

 

Since a few weeks we have outages where the alfresco process is running but the application does not respond anymore. Only a restart of alfresco solves this issue.

 

The last error message in the log is this:

2017-01-23 06:44:08,454 ERROR [      Thread-32] [ecutor.AcquireJobsRunnableImpl] exception during job acquisition: Could not open Hibernate Session for transaction; nested exception is org.hibernate.exception.GenericJDBCException: Cannot open connection
org.springframework.transaction.CannotCreateTransactionException: Could not open Hibernate Session for transaction; nested exception is org.hibernate.exception.GenericJDBCException: Cannot open connection
        at org.springframework.orm.hibernate3.HibernateTransactionManager.doBegin(HibernateTransactionManager.java:597)
        at org.springframework.transaction.support.AbstractPlatformTransactionManager.getTransaction(AbstractPlatformTransactionManager.java:372)
        at org.springframework.transaction.support.TransactionTemplate.execute(TransactionTemplate.java:128)
        at org.activiti.spring.SpringTransactionInterceptor.execute(SpringTransactionInterceptor.java:45)
        at org.activiti.engine.impl.interceptor.LogInterceptor.execute(LogInterceptor.java:31)
        at org.activiti.engine.impl.cfg.CommandExecutorImpl.execute(CommandExecutorImpl.java:40)
        at org.activiti.engine.impl.cfg.CommandExecutorImpl.execute(CommandExecutorImpl.java:35)
        at org.activiti.engine.impl.jobexecutor.AcquireJobsRunnableImpl.run(AcquireJobsRunnableImpl.java:54)
        at java.lang.Thread.run(Thread.java:745)
Caused by: org.hibernate.exception.GenericJDBCException: Cannot open connection
        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.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:29)
        at org.hibernate.jdbc.ConnectionManager.openConnection(ConnectionManager.java:426)
        at org.hibernate.jdbc.ConnectionManager.getConnection(ConnectionManager.java:144)
        at org.hibernate.jdbc.JDBCContext.connection(JDBCContext.java:119)
        at org.hibernate.transaction.JDBCTransaction.begin(JDBCTransaction.java:57)
        at org.hibernate.impl.SessionImpl.beginTransaction(SessionImpl.java:1326)
        at org.springframework.orm.hibernate3.HibernateTransactionManager.doBegin(HibernateTransactionManager.java:556)
        ... 8 more
Caused by: org.apache.commons.dbcp.SQLNestedException: Cannot get a connection, pool error Timeout waiting for idle object
        at org.apache.commons.dbcp.PoolingDataSource.getConnection(PoolingDataSource.java:114)
        at org.apache.commons.dbcp.BasicDataSource.getConnection(BasicDataSource.java:1044)
        at org.springframework.orm.hibernate3.LocalDataSourceConnectionProvider.getConnection(LocalDataSourceConnectionProvider.java:83)
        at org.hibernate.jdbc.ConnectionManager.openConnection(ConnectionManager.java:423)
        ... 13 more
Caused by: java.util.NoSuchElementException: Timeout waiting for idle object
        at org.apache.commons.pool.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:1174)
        at org.apache.commons.dbcp.PoolingDataSource.getConnection(PoolingDataSource.java:106)
        ... 16 more

 

When analyzing the jstack / threaddump we notice that there is a huge number (~250 threads) of blocked threads:

Thread 24077: (state = BLOCKED)
- net.sf.jooreports.openoffice.converter.OpenOfficeDocumentConverter.convertInternal(java.io.File, net.sf.jooreports.converter.DocumentFormat, java.io.File, net.sf.jooreports.converter.DocumentFormat) @bci=8, line=105 (Interpreted frame)
- net.sf.jooreports.openoffice.converter.AbstractOpenOfficeDocumentConverter.convert(java.io.File, net.sf.jooreports.converter.DocumentFormat, java.io.File, net.sf.jooreports.converter.DocumentFormat) @bci=156, line=88 (Interpreted frame)
- org.alfresco.repo.content.transform.OpenOfficeContentTransformerWorker.convert(java.io.File, net.sf.jooreports.converter.DocumentFormat, java.io.File, net.sf.jooreports.converter.DocumentFormat) @bci=9, line=125 (Interpreted frame)
- org.alfresco.repo.content.transform.OOoContentTransformerHelper.transform(org.alfresco.service.cmr.repository.ContentReader, org.alfresco.service.cmr.repository.ContentWriter, org.alfresco.service.cmr.repository.TransformationOptions) @bci=550, line=393 (Interpreted frame)
- sun.reflect.GeneratedMethodAccessor1384.invoke(java.lang.Object, java.lang.Object[]) @bci=56 (Interpreted frame)
- sun.reflect.DelegatingMethodAccessorImpl.invoke(java.lang.Object, java.lang.Object[]) @bci=6, line=43 (Compiled frame)
- java.lang.reflect.Method.invoke(java.lang.Object, java.lang.Object[]) @bci=56, line=498 (Compiled frame)
- org.alfresco.repo.management.subsystems.SubsystemProxyFactory$1.invoke(org.aopalliance.intercept.MethodInvocation) @bci=22, line=79 (Compiled frame)
- org.springframework.aop.framework.ReflectiveMethodInvocation.proceed() @bci=101, line=172 (Compiled frame)
- org.springframework.aop.framework.JdkDynamicAopProxy.invoke(java.lang.Object, java.lang.reflect.Method, java.lang.Object[]) @bci=322, line=204 (Compiled frame)
- com.sun.proxy.$Proxy30.transform(org.alfresco.service.cmr.repository.ContentReader, org.alfresco.service.cmr.repository.ContentWriter, org.alfresco.service.cmr.repository.TransformationOptions) @bci=24 (Interpreted frame)
- org.alfresco.repo.content.transform.ProxyContentTransformer.transformInternal(org.alfresco.service.cmr.repository.ContentReader, org.alfresco.service.cmr.repository.ContentWriter, org.alfresco.service.cmr.repository.TransformationOptions) @bci=24, line=107 (Interpreted frame)
- org.alfresco.repo.content.transform.AbstractContentTransformer2.transform(org.alfresco.service.cmr.repository.ContentReader, org.alfresco.service.cmr.repository.ContentWriter, org.alfresco.service.cmr.repository.TransformationOptions) @bci=167, line=272 (Compiled frame)
- org.alfresco.repo.content.transform.ComplexContentTransformer.transformInternal(org.alfresco.service.cmr.repository.ContentReader, org.alfresco.service.cmr.repository.ContentWriter, org.alfresco.service.cmr.repository.TransformationOptions) @bci=257, line=492 (Interpreted frame)
- org.alfresco.repo.content.transform.AbstractContentTransformer2.transform(org.alfresco.service.cmr.repository.ContentReader, org.alfresco.service.cmr.repository.ContentWriter, org.alfresco.service.cmr.repository.TransformationOptions) @bci=167, line=272 (Compiled frame)
- org.alfresco.repo.content.transform.FailoverContentTransformer.transformInternal(org.alfresco.service.cmr.repository.ContentReader, org.alfresco.service.cmr.repository.ContentWriter, org.alfresco.service.cmr.repository.TransformationOptions) @bci=274, line=215 (Interpreted frame)
- org.alfresco.repo.content.transform.AbstractContentTransformer2.transform(org.alfresco.service.cmr.repository.ContentReader, org.alfresco.service.cmr.repository.ContentWriter, org.alfresco.service.cmr.repository.TransformationOptions) @bci=167, line=272 (Compiled frame)
- org.alfresco.repo.content.transform.ComplexContentTransformer.transformInternal(org.alfresco.service.cmr.repository.ContentReader, org.alfresco.service.cmr.repository.ContentWriter, org.alfresco.service.cmr.repository.TransformationOptions) @bci=257, line=492 (Interpreted frame)
- org.alfresco.repo.content.transform.AbstractContentTransformer2.transform(org.alfresco.service.cmr.repository.ContentReader, org.alfresco.service.cmr.repository.ContentWriter, org.alfresco.service.cmr.repository.TransformationOptions) @bci=167, line=272 (Compiled frame)
- org.alfresco.repo.content.ContentServiceImpl.failoverTransformers(org.alfresco.service.cmr.repository.ContentReader, org.alfresco.service.cmr.repository.ContentWriter, org.alfresco.service.cmr.repository.TransformationOptions, java.lang.String, java.util.List) @bci=210, line=668 (Interpreted frame)
- org.alfresco.repo.content.ContentServiceImpl.transform(org.alfresco.service.cmr.repository.ContentReader, org.alfresco.service.cmr.repository.ContentWriter, org.alfresco.service.cmr.repository.TransformationOptions) @bci=232, line=617 (Interpreted frame)
- sun.reflect.GeneratedMethodAccessor1383.invoke(java.lang.Object, java.lang.Object[]) @bci=56 (Interpreted frame)
- sun.reflect.DelegatingMethodAccessorImpl.invoke(java.lang.Object, java.lang.Object[]) @bci=6, line=43 (Compiled frame)
- java.lang.reflect.Method.invoke(java.lang.Object, java.lang.Object[]) @bci=56, line=498 (Compiled frame)
- org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(java.lang.Object, java.lang.reflect.Method, java.lang.Object[]) @bci=7, line=317 (Compiled frame)
- org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint() @bci=12, line=183 (Compiled frame)
- org.springframework.aop.framework.ReflectiveMethodInvocation.proceed() @bci=19, line=150 (Compiled frame)
- net.sf.acegisecurity.intercept.method.aopalliance.MethodSecurityInterceptor.invoke(org.aopalliance.intercept.MethodInvocation) @bci=9, line=80 (Compiled frame)
- org.springframework.aop.framework.ReflectiveMethodInvocation.proceed() @bci=101, line=172 (Compiled frame)
- org.alfresco.repo.model.ml.MLContentInterceptor.invoke(org.aopalliance.intercept.MethodInvocation) @bci=227, line=136 (Compiled frame)
- org.springframework.aop.framework.ReflectiveMethodInvocation.proceed() @bci=101, line=172 (Compiled frame)
- org.alfresco.repo.security.permissions.impl.ExceptionTranslatorMethodInterceptor.invoke(org.aopalliance.intercept.MethodInvocation) @bci=1, line=53 (Compiled frame)
- org.springframework.aop.framework.ReflectiveMethodInvocation.proceed() @bci=101, line=172 (Compiled frame)
- org.alfresco.repo.audit.AuditMethodInterceptor.invoke(org.aopalliance.intercept.MethodInvocation) @bci=15, line=166 (Compiled frame)
- org.springframework.aop.framework.ReflectiveMethodInvocation.proceed() @bci=101, line=172 (Compiled frame)
- org.springframework.transaction.interceptor.TransactionInterceptor$1.proceedWithInvocation() @bci=4, line=96 (Compiled frame)
- org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(java.lang.reflect.Method, java.lang.Class, org.springframework.transaction.interceptor.TransactionAspectSupport$InvocationCallback) @bci=58, line=260 (Compiled frame)
- org.springframework.transaction.interceptor.TransactionInterceptor.invoke(org.aopalliance.intercept.MethodInvocation) @bci=40, line=94 (Compiled frame)
- org.springframework.aop.framework.ReflectiveMethodInvocation.proceed() @bci=101, line=172 (Compiled frame)
- org.springframework.aop.framework.JdkDynamicAopProxy.invoke(java.lang.Object, java.lang.reflect.Method, java.lang.Object[]) @bci=322, line=204 (Compiled frame)
- com.sun.proxy.$Proxy52.transform(org.alfresco.service.cmr.repository.ContentReader, org.alfresco.service.cmr.repository.ContentWriter, org.alfresco.service.cmr.repository.TransformationOptions) @bci=24 (Interpreted frame)
- org.alfresco.repo.rendition.executer.AbstractTransformationRenderingEngine$TransformationCallable$1.doWork() @bci=54, line=447 (Interpreted frame)
- org.alfresco.repo.rendition.executer.AbstractTransformationRenderingEngine$TransformationCallable$1.doWork() @bci=1, line=1 (Interpreted frame)
- org.alfresco.repo.security.authentication.AuthenticationUtil.runAs(org.alfresco.repo.security.authentication.AuthenticationUtil$RunAsWork, java.lang.String) @bci=30, line=555 (Compiled frame)
- org.alfresco.repo.rendition.executer.AbstractTransformationRenderingEngine$TransformationCallable.call() @bci=47, line=437 (Interpreted frame)
- org.alfresco.repo.rendition.executer.AbstractTransformationRenderingEngine$TransformationCallable.call() @bci=1, line=1 (Interpreted frame)
- java.util.concurrent.FutureTask.run() @bci=42, line=266 (Interpreted frame)
- java.util.concurrent.ThreadPoolExecutor.runWorker(java.util.concurrent.ThreadPoolExecutor$Worker) @bci=95, line=1142 (Compiled frame)
- java.util.concurrent.ThreadPoolExecutor$Worker.run() @bci=5, line=617 (Compiled frame)
- java.lang.Thread.run() @bci=11, line=745 (Compiled frame)

 

We have a monitoring system in place and we are able to notice the problem instantly but we want do understand what is happening and if the 2 errors are connected. 

 

Increasing max_connections would probably expand the time to each restart but the question really is if there is a jdbc connection leakage and how it is produced.

 

I was profiling and stressing our test environment for quite some time but I can't reproduce the issue and i can not see jdbc connections not being closed properly.

Outcomes