Consumo excesivo de JAVA al cabo de 10 días

[rublape]

Buenas tardes,

Tengo alfresco 5.1 community montado sobre un centos 6.5 y según arranco la máquina va perfectamente. La CPU y memoria de Java va sobre un 15%. Al pasar unos 10 días noto como cada vez se hace más lento y al final incluso ya no se puede usar.

Cuando está en esta fase veo que la memoria HEAP está al 100%, pero con más que subo la memoria termina pasando los mismo... He configurado tweaks de los parámetros de JAVA que he visto en los foros pero sigo sin solucionar el problema... 

Adjunto los datos que he sacado con jconsole cuando la máquina estaba a tope y por lo tanto iba lentísima.

¿Alguien sabe si se puede realizar alguna configuración para que vaya liberando memoria JAVA?

Muchas gracias por adelantado!

Un saludo

[douglascrp]

Quizás la sincronización LDAP tratando de recrear los usuários?

[cesarista]

Hola ‌

Un LDAP grande puede derivar en ese tipo de problemas de cache, sobre todo si se tiene una estrategia de full sync en vez de diferencial sync, pero la frecuencia (diaria) e intervalo temporal no corresponde. Si el WARNING ocurriese todos los días a las 00:00 horas...

Saludos.

--C.

[rublape]

Buenos días,

Ya por probar que no quede...Pero he deshabilitado la sincronización LDAP y el problema persiste...a si que a seguir buscando...

Muchas gracias!

[rublape]

Buenos días,

Por otro lado, estuve mirando con Cristina posibles problemas que tuviera en la config. Lo único que fue más raro ha sido que tenía la auditoria habilitada. La he desactivado, pero sigo viendo el error de caché el cual es continuo ha si que de eso tampoco es 😞

Por otro lado, revisando más en detalle los logs de catalina.out veo algunos errores como estos...voy a mirar si por aquí pudiera venir el problema:

2017-09-07 03:25:15,439 WARN [solr.component.AsyncBuildSuggestComponent] [Suggestor-alfresco-1] Solr suggester temp file found matching file pattern: WFSTInputIterator*.{input,sorted}, path: /alfresco/alfresco-community/tomcat/temp/WFSTInputIterator7353038735798153610.input
2017-09-07 03:25:15,439 WARN [solr.component.AsyncBuildSuggestComponent] [Suggestor-alfresco-1] Reported first suggester temp file found, others may exist.
2017-09-07 03:25:15,439 INFO [solr.component.AsyncBuildSuggestComponent] [Suggestor-alfresco-1] Building suggester index for: shingleBasedSuggestions
2017-09-07 03:26:09,497 INFO [solr.component.AsyncBuildSuggestComponent] [Suggestor-alfresco-1] Built suggester shingleBasedSuggestions, took 54058 ms
2017-09-07 04:28:15,352 WARN [solr.component.AsyncBuildSuggestComponent] [Suggestor-alfresco-1] Solr suggester temp file found matching file pattern: WFSTInputIterator*.{input,sorted}, path: /alfresco/alfresco-community/tomcat/temp/WFSTInputIterator7353038735798153610.input
2017-09-07 04:28:15,352 WARN [solr.component.AsyncBuildSuggestComponent] [Suggestor-alfresco-1] Reported first suggester temp file found, others may exist.
2017-09-07 04:28:15,353 INFO [solr.component.AsyncBuildSuggestComponent] [Suggestor-alfresco-1] Building suggester index for: shingleBasedSuggestions
2017-09-07 04:28:57,887 INFO [solr.component.AsyncBuildSuggestComponent] [Suggestor-alfresco-1] Built suggester shingleBasedSuggestions, took 42534 ms

log4j:WARN No appenders could be found for logger (aoservices-trc.AbstractVermeerService).
log4j:WARN Please initialize the log4j system properly.
log4j:WARN See http://logging.apache.org/log4j/1.2/faq.html#noconfig for more info.

2017-09-07 05:31:15,526 WARN [solr.component.AsyncBuildSuggestComponent] [Suggestor-alfresco-1] Solr suggester temp file found matching file pattern: WFSTInputIterator*.{input,sorted}, path: /alfresco/alfresco-community/tomcat/temp/WFSTInputIterator7353038735798153610.input
2017-09-07 05:31:15,526 WARN [solr.component.AsyncBuildSuggestComponent] [Suggestor-alfresco-1] Reported first suggester temp file found, others may exist.
2017-09-07 05:31:15,527 INFO [solr.component.AsyncBuildSuggestComponent] [Suggestor-alfresco-1] Building suggester index for: shingleBasedSuggestions
2017-09-07 05:31:59,965 INFO [solr.component.AsyncBuildSuggestComponent] [Suggestor-alfresco-1] Built suggester shingleBasedSuggestions, took 44438 ms
2017-09-07 05:58:30,227 WARN [org.alfresco.userToAuthorityTransactionalCache] [LocalFeedGenerator1] Transactional update cache 'org.alfresco.userToAuthorityTransactionalCache' is full (100).
2017-09-07 05:59:30,220 WARN [org.alfresco.userToAuthorityTransactionalCache] [LocalFeedGenerator1] Transactional update cache 'org.alfresco.userToAuthorityTransactionalCache' is full (100).
2017-09-07 06:00:00,232 WARN [org.alfresco.userToAuthorityTransactionalCache] [LocalFeedGenerator1] Transactional update cache 'org.alfresco.userToAuthorityTransactionalCache' is full (100).
2017-09-07 06:34:15,294 WARN [solr.component.AsyncBuildSuggestComponent] [Suggestor-alfresco-1] Solr suggester temp file found matching file pattern: WFSTInputIterator*.{input,sorted}, path: /alfresco/alfresco-community/tomcat/temp/WFSTInputIterator7353038735798153610.input
2017-09-07 06:34:15,295 WARN [solr.component.AsyncBuildSuggestComponent] [Suggestor-alfresco-1] Reported first suggester temp file found, others may exist.
2017-09-07 06:34:15,295 INFO [solr.component.AsyncBuildSuggestComponent] [Suggestor-alfresco-1] Building suggester index for: shingleBasedSuggestions
2017-09-07 06:35:02,618 INFO [solr.component.AsyncBuildSuggestComponent] [Suggestor-alfresco-1] Built suggester shingleBasedSuggestions, took 47323 ms
2017-09-07 07:25:30,179 WARN [org.alfresco.userToAuthorityTransactionalCache] [LocalFeedGenerator1] Transactional update cache 'org.alfresco.userToAuthorityTransactionalCache' is full (100).
2017-09-07 07:37:15,255 WARN [solr.component.AsyncBuildSuggestComponent] [Suggestor-alfresco-1] Solr suggester temp file found matching file pattern: WFSTInputIterator*.{input,sorted}, path: /alfresco/alfresco-community/tomcat/temp/WFSTInputIterator7353038735798153610.input
2017-09-07 07:37:15,255 WARN [solr.component.AsyncBuildSuggestComponent] [Suggestor-alfresco-1] Reported first suggester temp file found, others may exist.
2017-09-07 07:37:15,255 INFO [solr.component.AsyncBuildSuggestComponent] [Suggestor-alfresco-1] Building suggester index for: shingleBasedSuggestions
2017-09-07 07:37:58,134 INFO [solr.component.AsyncBuildSuggestComponent] [Suggestor-alfresco-1] Built suggester shingleBasedSuggestions, took 42879 ms

Muchas gracias por el apoyo!

Un saludo

Rubén

[cesarista]

Hola:

La auditoría es mejor desactivarla si tienes problemas de rendimiento. 

También puedes probar a desactivar el suggester de SOLR que está relacionado con los WARNING de WFSTInputIterator* y que te habrá creado unos archivos temporales importantes en $ALF_HOME/tomcat/temp/*....

Para ello suggester.enabled=false en /opt/alfresco52g/solr4/workspace-SpacesStore/conf/solrcore.properties (y reiniciar alfresco)

Saludos.

--C.

[cristinamr]

Una pena que no vengan por ahí los tiros Bueno vamos a intentarlo por otro lado:

¿Y si probados a poner el log a debug? Podrías poner en alfresco/tomcat/shared/classes/alfresco/extension/custo-log4j.properties (o similar) esto:

log4j.logger.org.alfresco.repo.cache.TransactionalCache=debug

Reinicias y a ver si nos dan mas detalles los logs /alfresco.log y catalina.out)

Por cierto ¿conseguiste replicar el problema en otro entorno?

Por cierto lo que comenta César deberías hacerlo para no cargar más el sistema.

Cris.

[rublape]

Buenas tardes,

En el otro entorno de pruebas (es exactamente el mismo entorno pero sin usuarios utilizándolo) con la auditoria activada pasa exactamente lo mismo:

2017-02-09 11:15:33,324 WARN [org.alfresco.userToAuthorityTransactionalCache] [http-apr-8080-exec-2] Transactional update cache 'org.alfresco.userToAuthorityTransactionalCache' is full (100).
2017-02-09 15:32:05,190 WARN [org.alfresco.userToAuthorityTransactionalCache] [http-apr-8080-exec-5] Transactional update cache 'org.alfresco.userToAuthorityTransactionalCache' is full (100).
2017-02-09 16:03:09,468 WARN [org.alfresco.userToAuthorityTransactionalCache] [http-apr-8080-exec-3] Transactional update cache 'org.alfresco.userToAuthorityTransactionalCache' is full (100).

A si que esto es preocupante porque no hay usuarios haciendo nada...

Por el lado de debug, lo probaré y os iré diciendo lo que va apareciendo.

Muchas gracias!

Un saludo!

[rublape]

Buenos días a todos!

Ya he puesto el debug en el log y he obtenido el siguiente mensaje :

2017-09-11 09:48:33,231 INFO [org.alfresco.repo.cache.TransactionalCache.org.alfresco.userToAuthorityTransactionalCache] [LocalFeedGenerator1] Transactional update cache 'org.alfresco.userToAuthorityTransactionalCache' is full (100).
java.lang.Exception: Stack:
at org.alfresco.repo.cache.TransactionalCache.put(TransactionalCache.java:738)
at org.alfresco.repo.security.authority.AuthorityDAOImpl.getContainingAuthorities(AuthorityDAOImpl.java:866)
at org.alfresco.repo.security.authority.AuthorityDAOImpl.isAuthorityContained(AuthorityDAOImpl.java:1163)
at org.alfresco.repo.security.authority.AuthorityServiceImpl.hasAuthority(AuthorityServiceImpl.java:218)
at org.alfresco.repo.security.authority.AuthorityServiceImpl.getRoleAuthorities(AuthorityServiceImpl.java:278)
at org.alfresco.repo.security.authority.AuthorityServiceImpl.access$0(AuthorityServiceImpl.java:255)
at org.alfresco.repo.security.authority.AuthorityServiceImpl$UserAuthoritySet.<init>(AuthorityServiceImpl.java:746)
at org.alfresco.repo.security.authority.AuthorityServiceImpl.getAuthoritiesForUser(AuthorityServiceImpl.java:251)
at org.alfresco.repo.security.permissions.impl.PermissionServiceImpl.getCoreAuthorisations(PermissionServiceImpl.java:825)
at org.alfresco.repo.security.permissions.impl.PermissionServiceImpl.getAuthorisations(PermissionServiceImpl.java:883)
at org.alfresco.repo.security.permissions.impl.PermissionServiceImpl.hasPermission(PermissionServiceImpl.java:701)
at org.alfresco.repo.security.permissions.impl.PermissionServiceImpl.hasPermission_aroundBody20(PermissionServiceImpl.java:566)
at org.alfresco.repo.security.permissions.impl.PermissionServiceImpl$AjcClosure21.run(PermissionServiceImpl.java:1)
at org.aspectj.runtime.reflect.JoinPointImpl.proceed(JoinPointImpl.java:221)
at org.alfresco.traitextender.AJExtender.localProceed(AJExtender.java:722)
at org.alfresco.traitextender.AJProxyTrait.invoke(AJProxyTrait.java:79)
at com.sun.proxy.$Proxy23.hasPermission(Unknown Source)
at org.alfresco.repo.virtual.bundle.VirtualPermissionServiceExtension.hasPermission(VirtualPermissionServiceExtension.java:103)
at sun.reflect.GeneratedMethodAccessor455.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:497)
at org.alfresco.traitextender.SingletonExtensionFactory$TraiSingletontHandler.invoke(SingletonExtensionFactory.java:67)
at com.sun.proxy.$Proxy195.hasPermission(Unknown Source)
at sun.reflect.GeneratedMethodAccessor454.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:497)
at org.alfresco.traitextender.AJExtender.extendAroundAdvice(AJExtender.java:648)
at org.alfresco.traitextender.RouteExtensions.ajc$inlineAccessMethod$org_alfresco_traitextender_RouteExtensions$org_alfresco_traitextender_AJExtender$extendAroundAdvice(RouteExtensions.java:1)
at org.alfresco.traitextender.RouteExtensions.intercept(RouteExtensions.java:78)
at org.alfresco.repo.security.permissions.impl.PermissionServiceImpl.hasPermission(PermissionServiceImpl.java:498)
at org.alfresco.repo.security.permissions.impl.PermissionServiceImpl.hasPermission_aroundBody64(PermissionServiceImpl.java:1108)
at org.alfresco.repo.security.permissions.impl.PermissionServiceImpl$AjcClosure65.run(PermissionServiceImpl.java:1)
at org.aspectj.runtime.reflect.JoinPointImpl.proceed(JoinPointImpl.java:221)
at org.alfresco.traitextender.AJExtender.localProceed(AJExtender.java:722)
at org.alfresco.traitextender.AJProxyTrait.invoke(AJProxyTrait.java:79)
at com.sun.proxy.$Proxy23.hasPermission(Unknown Source)
at org.alfresco.repo.virtual.bundle.VirtualPermissionServiceExtension.hasPermission(VirtualPermissionServiceExtension.java:70)
at sun.reflect.GeneratedMethodAccessor435.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:497)
at org.alfresco.traitextender.SingletonExtensionFactory$TraiSingletontHandler.invoke(SingletonExtensionFactory.java:67)
at com.sun.proxy.$Proxy195.hasPermission(Unknown Source)
at sun.reflect.GeneratedMethodAccessor453.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:497)
at org.alfresco.traitextender.AJExtender.extendAroundAdvice(AJExtender.java:648)
at org.alfresco.traitextender.RouteExtensions.ajc$inlineAccessMethod$org_alfresco_traitextender_RouteExtensions$org_alfresco_traitextender_AJExtender$extendAroundAdvice(RouteExtensions.java:1)
at org.alfresco.traitextender.RouteExtensions.intercept(RouteExtensions.java:78)
at org.alfresco.repo.security.permissions.impl.PermissionServiceImpl.hasPermission(PermissionServiceImpl.java:1106)
at sun.reflect.GeneratedMethodAccessor435.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:497)
at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:317)
at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
at org.springframework.transaction.interceptor.TransactionInterceptor$1.proceedWithInvocation(TransactionInterceptor.java:96)
at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:260)
at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:94)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204)
at com.sun.proxy.$Proxy45.hasPermission(Unknown Source)
at sun.reflect.GeneratedMethodAccessor435.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:497)
at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:317)
at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
at net.sf.acegisecurity.intercept.method.aopalliance.MethodSecurityInterceptor.invoke(MethodSecurityInterceptor.java:80)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
at org.alfresco.repo.security.permissions.impl.ExceptionTranslatorMethodInterceptor.invoke(ExceptionTranslatorMethodInterceptor.java:46)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
at org.alfresco.repo.audit.AuditMethodInterceptor.invoke(AuditMethodInterceptor.java:159)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
at org.springframework.transaction.interceptor.TransactionInterceptor$1.proceedWithInvocation(TransactionInterceptor.java:96)
at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:260)
at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:94)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204)
at com.sun.proxy.$Proxy72.hasPermission(Unknown Source)
at org.alfresco.repo.activities.feed.local.LocalFeedTaskProcessor$4.doWork(LocalFeedTaskProcessor.java:459)
at org.alfresco.repo.activities.feed.local.LocalFeedTaskProcessor$4.doWork(LocalFeedTaskProcessor.java:1)
at org.alfresco.repo.security.authentication.AuthenticationUtil.runAs(AuthenticationUtil.java:548)
at org.alfresco.repo.activities.feed.local.LocalFeedTaskProcessor.canReadImpl(LocalFeedTaskProcessor.java:455)
at org.alfresco.repo.activities.feed.local.LocalFeedTaskProcessor.access$1(LocalFeedTaskProcessor.java:395)
at org.alfresco.repo.activities.feed.local.LocalFeedTaskProcessor$3.doWork(LocalFeedTaskProcessor.java:384)
at org.alfresco.repo.activities.feed.local.LocalFeedTaskProcessor$3.doWork(LocalFeedTaskProcessor.java:1)
at org.alfresco.repo.tenant.TenantUtil.runAsWork(TenantUtil.java:119)
at org.alfresco.repo.tenant.TenantUtil.runAsTenant(TenantUtil.java:88)
at org.alfresco.repo.tenant.TenantUtil$1.doWork(TenantUtil.java:62)
at org.alfresco.repo.security.authentication.AuthenticationUtil.runAs(AuthenticationUtil.java:548)
at org.alfresco.repo.tenant.TenantUtil.runAsUserTenant(TenantUtil.java:58)
at org.alfresco.repo.tenant.TenantUtil.runAsSystemTenant(TenantUtil.java:112)
at org.alfresco.repo.activities.feed.local.LocalFeedTaskProcessor.canRead(LocalFeedTaskProcessor.java:380)
at org.alfresco.repo.activities.feed.FeedTaskProcessor.process(FeedTaskProcessor.java:245)
at org.alfresco.repo.activities.feed.FeedTaskProcessor$$FastClassBySpringCGLIB$$e69767f7.invoke(<generated>)
at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:204)
at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:700)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
at org.alfresco.repo.transaction.CheckTransactionAdvice.invoke(CheckTransactionAdvice.java:47)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:633)
at org.alfresco.repo.activities.feed.local.LocalFeedTaskProcessor$$EnhancerBySpringCGLIB$$44aa786d.process(<generated>)
at org.alfresco.repo.activities.feed.local.LocalFeedGenerator$2$1.execute(LocalFeedGenerator.java:136)
at org.alfresco.repo.activities.feed.local.LocalFeedGenerator$2$1.execute(LocalFeedGenerator.java:1)
at org.alfresco.repo.transaction.RetryingTransactionHelper.doInTransaction(RetryingTransactionHelper.java:457)
at org.alfresco.repo.activities.feed.local.LocalFeedGenerator$2.process(LocalFeedGenerator.java:126)
at org.alfresco.repo.activities.feed.local.LocalFeedGenerator$2.process(LocalFeedGenerator.java:1)
at org.alfresco.repo.batch.BatchProcessor$TxnCallback.execute(BatchProcessor.java:713)
at org.alfresco.repo.transaction.RetryingTransactionHelper.doInTransaction(RetryingTransactionHelper.java:457)
at org.alfresco.repo.batch.BatchProcessor$TxnCallback.run(BatchProcessor.java:757)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)

¿Os dice algo a alguno de vosotros o solo es un log informativo?

Muchas gracias!

Un saludo

[cesarista]

Hola Ruben:

IMO, que una caché se llene puede degenerar en un problema de rendimiento pero no tiene por qué ser así. Si esto fuese así, los momentos en los que se pierde el servicio serían relativamente claros. ¿ Cuanto tiempo pasa desde el WARNING hasta que se pierde el servicio ? Por otro lado, desde la última versión del módulo de OOTB Support Tools se pueden borrar/vaciar las caches en caliente.

Es más significativo un jstack en el momento que notas una pérdida de rendimiento, porque permite ver los hilos de ejecución. Entre los hilos que estén esperando desde hace un tiempo, estarán los "procesos" que están dando guerra en tu sistema.

Saludos.

--C.

[angelborroy]

En tu caso, parece un problema relacionado con el generador de feeds:

https://github.com/Alfresco/community-edition-old/blob/master/projects/repository/config/alfresco/su...

Igual puedes ajustar las propiedades por defecto para disminuir la carga transaccional en este proceso:

https://github.com/Alfresco/community-edition-old/blob/master/projects/repository/config/alfresco/su...