topic Re: Consumo excesivo de JAVA al cabo de 10 días in Alfresco Archive

Consumo excesivo de JAVA al cabo de 10 días

rublape — Tue, 05 Sep 2017 14:17:21 GMT

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

Re: Consumo excesivo de JAVA al cabo de 10 días

cristinamr — Tue, 05 Sep 2017 14:49:32 GMT

Buenas.

Tenemos que conocer el entorno del que nos hablas:

¿Qué tipo de arquitectura tenéis?
¿Volumen de content store, base de datos e indices?
¿Qué recursos tiene la máquina?
¿Qué uso le dais a Alfresco?
¿Le metéis mucha carga de subida de documentos os similar?
¿Tienes personalizaciones instaladas?

Cuéntanos un poco y vamos viendo porque de algún lado tiene que venir esa subida y la cuestión no es subir el heap, es ver de dónde viene el problema. Hace tiempo me ocurrió algo parecido y provenía de un desarrollo mal elaborado porque no cerraba los resultSets y terminaban por consumir la máquina. De ahí a todas estas preguntas a ver si vemos algo.

Un saludo,

Cris.

Re: Consumo excesivo de JAVA al cabo de 10 días

rublape — Tue, 05 Sep 2017 15:35:02 GMT

Buenas tardes Cristina,

Te respondo a las preguntas.

¿Qué tipo de arquitectura tenéis? - Es un Centos 6.5 con alfresco 5.1 community y base de datos postgresql. Además para el acceso SSL tenemos un apache montado con el mod_jk
¿Volumen de content store, base de datos e indices? - El content store tenemos un total de 9 GB, indices de Solr4 son 864,4 MB y Postgresql DB - 122 MB
¿Qué recursos tiene la máquina? - 14 GB de memoria, 4 CPU
¿Qué uso le dais a Alfresco? - Le damos un uso sobretodo viendo documentos ya almacenados unas 20 personas como máximo a la vez
¿Le metéis mucha carga de subida de documentos os similar? - No solemos cargar documentos en estos momentos.
¿Tienes personalizaciones instaladas? - Ninguna que yo sepa. ¿Alguna forma de saberlo?

La configuración de la VM de java que tengo es:

more setenv.sh

# Load Tomcat Native Library
LD_LIBRARY_PATH=/alfresco/alfresco-community/common/lib:$LD_LIBRARY_PATH

JAVA_HOME=/alfresco/alfresco-community/java
JRE_HOME=$JAVA_HOME
JAVA_OPTS="-XX:+DisableExplicitGC -XX:+UseConcMarkSweepGC -XX:+UseParNewGC -Djava.awt.headless=true -Dalfresco.home=/alfresco/alfresc
o-community -XX:ReservedCodeCacheSize=128m $JAVA_OPTS "
JAVA_OPTS="-Xms9G -Xmx10G $JAVA_OPTS " # java-memory-settings
# Opciones para gestion JMX
export CATALINA_OPTS="$CATALINA_OPTS -Dcom.sun.management.jmxremote -Dcom.sun.management.jmxremote.port=9999 -Dcom.sun.management.jmx
remote.authenticate=false -Dcom.sun.management.jmxremote.ssl=false -Djava.rmi.server.hostname=172.16.29.171"
export CATALINA_OPTS

# Exports de Java
export JAVA_HOME
export JRE_HOME
export JAVA_OPTS
export LD_LIBRARY_PATH

Esa es la información que así a primera vista te puedo dar. Si necesitaras alguna más en detalle me tendrías que guiar un poco sobre qué comando necesitas o qué fichero necesitas ver

Muchas gracias por la rápida respuesta.

Un saludo

Rubén

Re: Consumo excesivo de JAVA al cabo de 10 días

cristinamr — Wed, 06 Sep 2017 07:09:19 GMT

Buenos días.

En lo que pones no veo nada raro ni en uso ni en asignaciones ¿En el catalina.out o alfresco.log ves algún error o warn cuando el servidor está a tope?

Vamos a tirar por los desarrollos a ver. Comprueba lo siguiente:

Lista los amps de las carpeta alfresco/amps y alfresco/amps_share

Haz lo siguiente:

cd alfresco/bin
java -jar alfresco-mmt.jar list ../tomcat/webapps/alfresco.war
java -jar alfresco-mmt.jar list ../tomcat/webapps/share.war

De estas dos últimas, dime qué te aparece.

Además, mira a ver qué tienes en alfresco/tomcat/shared/classes/alfresco/extension y web-extension De estas dos, quita todos los .sample que solo son ejemplos.

También se pueden desplegar personalizaciones dinamicamente: Con alfresco funcionando, mira en:

Repositorio > Diccionario de Datos > Models
Repositorio > Diccionario de Datos > Web Script Extensions

Y en general haz un repaso por si pudiera haber algo que fuera vuestro dentro de la carpeta Data Dictionary.

Coméntanos ver si damos con la clave.

Un saludo,

Cris.

Re: Consumo excesivo de JAVA al cabo de 10 días

cesarista — Wed, 06 Sep 2017 12:25:40 GMT

Hola:

Además de las consideraciones de Cristina, te recomiendo que instales el módulo de OOTB Support tools, te va a proporcionar mejor información que Jconsole (threads, conexiones de bbdd, heap usada...). Pinta a memory leak. Puede ser relevante además hacer un jstack en el momento que está a tope para ver que threads están activos/esperando.

El repositorio no es especialmente grande y aunque es mas significativo el numero de documentos que el tamaño total de los mismos, no debería tener problemas de rendimiento si tu entorno tiene recursos dedicados, aunque tengas la bbdd en el mismo server. Lo de los 10 días podría estar relacionado con alguna tarea programada. Si eres capaz de detectar o reproducir la hora en el que sube la memoria (o mejor dicho, en la que el diente de sierra no baja) seria de utilidad.

Saludos.

--C.

Re: Consumo excesivo de JAVA al cabo de 10 días

rublape — Wed, 06 Sep 2017 13:58:07 GMT

Buenas tardes Cristina,

En el catalina.out de ayer a la hora que fallaba aparecieron estos errores:

2017-09-05 12:13:30,311 WARN [content.metadata.AbstractMappingMetadataExtracter] [http-apr-8080-exec-60] Metadata extraction failed (turn on DEBUG for full error):
org.alfresco.error.AlfrescoRuntimeException: 080556118 Creation of thumbnail 'doclib' failed
org.alfresco.error.AlfrescoRuntimeException: 080556223 Creation of thumbnail 'doclib' failed
org.alfresco.error.AlfrescoRuntimeException: 080557875 Creation of thumbnail 'doclib' failed
org.alfresco.error.AlfrescoRuntimeException: 080557882 Creation of thumbnail 'doclib' failed
org.alfresco.error.AlfrescoRuntimeException: 080557883 Creation of thumbnail 'doclib' failed
org.alfresco.error.AlfrescoRuntimeException: 080557884 Creation of thumbnail 'doclib' failed
org.alfresco.error.AlfrescoRuntimeException: 080557885 Creation of thumbnail 'doclib' failed
2017-09-05 14:19:51,386 WARN [content.metadata.AbstractMappingMetadataExtracter] [http-apr-8080-exec-53] Metadata extraction failed (turn on DEBUG for full error):
org.alfresco.error.AlfrescoRuntimeException: 080557896 Creation of thumbnail 'doclib' failed
org.alfresco.error.AlfrescoRuntimeException: 08050001 api/solr/aclchangesets return status:503
org.alfresco.error.AlfrescoRuntimeException: 08050000 api/solr/aclchangesets return status:503
org.alfresco.error.AlfrescoRuntimeException: 08050002 GetTransactions return status is 503
org.alfresco.error.AlfrescoRuntimeException: 08050003 api/solr/aclchangesets return status:503
org.alfresco.error.AlfrescoRuntimeException: 08050004 api/solr/aclchangesets return status:503
org.alfresco.error.AlfrescoRuntimeException: 08061175 Creation of thumbnail 'doclib' failed
org.alfresco.error.AlfrescoRuntimeException: 08061196 Creation of thumbnail 'doclib' failed

y estos que veo que parece que la caché se llena:

2017-09-05 15:52:00,624 WARN [org.alfresco.userToAuthorityTransactionalCache] [LocalFeedGenerator1] Transactional update cache 'org.alfresco.userToAuthorityTransactionalCache' is full (100).
log4j:WARN No appenders could be found for logger (aoservices-trc.AbstractSoapService).
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-05 16:20:30,231 WARN [org.alfresco.userToAuthorityTransactionalCache] [LocalFeedGenerator1] Transactional update cache 'org.alfresco.userToAuthorityTransactionalCache' is full (100).
2017-09-05 16:36:00,325 WARN [org.alfresco.userToAuthorityTransactionalCache] [LocalFeedGenerator1] Transactional update cache 'org.alfresco.userToAuthorityTransactionalCache' is full (100).
2017-09-05 16:37:00,164 WARN [org.alfresco.userToAuthorityTransactionalCache] [LocalFeedGenerator1] Transactional update cache 'org.alfresco.userToAuthorityTransactionalCache' is full (100).
2017-09-05 16:38:00,210 WARN [org.alfresco.userToAuthorityTransactionalCache] [LocalFeedGenerator1] Transactional update cache 'org.alfresco.userToAuthorityTransactionalCache' is full (100).
2017-09-05 16:47:00,645 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-05 16:47:00,645 WARN [solr.component.AsyncBuildSuggestComponent] [Suggestor-alfresco-1] Reported first suggester temp file found, others may exist.
2017-09-05 16:47:44,708 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-05 16:47:44,708 WARN [solr.component.AsyncBuildSuggestComponent] [Suggestor-alfresco-1] Reported first suggester temp file found, others may exist.
2017-09-05 16:48:00,150 WARN [org.alfresco.userToAuthorityTransactionalCache] [LocalFeedGenerator1] Transactional update cache 'org.alfresco.userToAuthorityTransactionalCache' is full (100).
2017-09-05 16:51:00,170 WARN [org.alfresco.userToAuthorityTransactionalCache] [LocalFeedGenerator1] Transactional update cache 'org.alfresco.userToAuthorityTransactionalCache' is full (100).
2017-09-05 17:16:00,201 WARN [org.alfresco.userToAuthorityTransactionalCache] [LocalFeedGenerator1] Transactional update cache 'org.alfresco.userToAuthorityTransactionalCache' is full (100).

Lo mismo para el log de alfresco.log:

2017-09-05 15:52:00,624 WARN [org.alfresco.repo.cache.TransactionalCache.org.alfresco.userToAuthorityTransactionalCache] [LocalFeedGenerator1] Transactional update cache 'org.alfresco.userToAuthorityTransactionalCache' is full (100).
2017-09-05 16:20:30,231 WARN [org.alfresco.repo.cache.TransactionalCache.org.alfresco.userToAuthorityTransactionalCache] [LocalFeedGenerator1] Transactional update cache 'org.alfresco.userToAuthorityTransactionalCache' is full (100).
2017-09-05 16:36:00,325 WARN [org.alfresco.repo.cache.TransactionalCache.org.alfresco.userToAuthorityTransactionalCache] [LocalFeedGenerator1] Transactional update cache 'org.alfresco.userToAuthorityTransactionalCache' is full (100).
2017-09-05 16:37:00,164 WARN [org.alfresco.repo.cache.TransactionalCache.org.alfresco.userToAuthorityTransactionalCache] [LocalFeedGenerator1] Transactional update cache 'org.alfresco.userToAuthorityTransactionalCache' is full (100).
2017-09-05 16:38:00,210 WARN [org.alfresco.repo.cache.TransactionalCache.org.alfresco.userToAuthorityTransactionalCache] [LocalFeedGenerator1] Transactional update cache 'org.alfresco.userToAuthorityTransactionalCache' is full (100).
2017-09-05 16:48:00,150 WARN [org.alfresco.repo.cache.TransactionalCache.org.alfresco.userToAuthorityTransactionalCache] [LocalFeedGenerator1] Transactional update cache 'org.alfresco.userToAuthorityTransactionalCache' is full (100).
2017-09-05 16:51:00,170 WARN [org.alfresco.repo.cache.TransactionalCache.org.alfresco.userToAuthorityTransactionalCache] [LocalFeedGenerator1] Transactional update cache 'org.alfresco.userToAuthorityTransactionalCache' is full (100).
2017-09-05 17:16:00,201 WARN [org.alfresco.repo.cache.TransactionalCache.org.alfresco.userToAuthorityTransactionalCache] [LocalFeedGenerator1] Transactional update cache 'org.alfresco.userToAuthorityTransactionalCache' is full (100).
2017-09-05 18:07:30,203 WARN [org.alfresco.repo.cache.TransactionalCache.org.alfresco.userToAuthorityTransactionalCache] [LocalFeedGenerator1] Transactional update cache 'org.alfresco.userToAuthorityTransactionalCache' is full (100).
2017-09-05 23:35:00,155 WARN [org.alfresco.repo.cache.TransactionalCache.org.alfresco.userToAuthorityTransactionalCache] [LocalFeedGenerator1] Transactional update cache 'org.alfresco.userToAuthorityTransactionalCache' is full (100).

¿Esto que es la cache de la VM de Java? ¿Hay manera de subir la caché o es recomendable?

Ahora te muestro los desarollos en alfreso/amps:
-rw-r--r-- 1 root root 515446 Jan 27 2016 alfresco-aos-module-1.1.amp
-rw-r--r-- 1 root root 782737 Feb 16 2016 alfresco-googledocs-repo-3.0.3.amp
-rw-r--r-- 1 root root 15503806 Feb 16 2016 alfresco-share-services.amp
-rw-r--r-- 1 root root 21372002 Feb 16 2016 alfresco-wcmqs.amp

y en alfresco/share_amps:

-rw-r--r-- 1 root root 60286 Feb 16 2016 alfresco-googledocs-share-3.0.3.amp
-rw-r--r-- 1 root root 48938 Feb 16 2016 alfresco-wcmqs-share.amp

No tenemos nada en especia 😉

Te sigo mostrando los amps instalados con el comando de java para alfresco:

[root@nocmsralfresco1 bin]# /opt/jdk1.8.0_111/bin/java -jar alfresco-mmt.jar list ../tomcat/webapps/alfresco.war
Module 'create-link-repo' installed in '../tomcat/webapps/alfresco.war'
- Title: create-link-repo AMP project
- Version: 1.0.0.1410011040
- Install Date: Thu May 04 13:46:03 CEST 2017
- Description: Manages the lifecycle of the create-link-repo AMP (Alfresco Module Package)
Module 'alfresco-share-services' installed in '../tomcat/webapps/alfresco.war'
- Title: Alfresco Share Services AMP
- Version: 5.1.0
- Install Date: Thu Jul 28 13:16:04 CEST 2016
- Description: Module to be applied to alfresco.war, containing APIs for Alfresco Share
Module 'org_alfresco_module_wcmquickstart' installed in '../tomcat/webapps/alfresco.war'
- Title: Web Quick Start
- Version: 1.0
- Install Date: Thu Jul 28 13:16:04 CEST 2016
- Description: Web Quick Start
Module 'org.alfresco.integrations.google.docs' installed in '../tomcat/webapps/alfresco.war'
- Title: Alfresco / Google Docs Integration
- Version: 3.0.3
- Install Date: Thu Jul 28 13:16:03 CEST 2016
- Description: The Repository side artifacts of the Alfresco / Google Docs Integration.
Module 'alfresco-aos-module' installed in '../tomcat/webapps/alfresco.war'
- Title: Alfresco Office Services Module
- Version: 1.1
- Install Date: Thu Jul 28 13:16:01 CEST 2016
- Description: Allows applications that can talk to a SharePoint server to talk to your Alfresco installation

Información de los amps instalados en SHARE:

[root@nocmsralfresco1 bin]# /opt/jdk1.8.0_111/bin/java -jar alfresco-mmt.jar list ../tomcat/webapps/share.war
Module 'create-link-share' installed in '../tomcat/webapps/share.war'
- Title: create-link-share AMP project
- Version: 1.0.0.1410011042
- Install Date: Thu May 04 13:46:19 CEST 2017
- Description: Manages the lifecycle of the create-link-share AMP (Alfresco Module Package)
Module 'org.alfresco.integrations.share.google.docs' installed in '../tomcat/webapps/share.war'
- Title: Alfresco / Google Docs Share Module
- Version: 3.0.3
- Install Date: Thu Jul 28 13:16:09 CEST 2016
- Description: The Share side artifacts of the Alfresco / Google Docs Integration.
Module 'org_alfresco_module_wcmquickstartshare' installed in '../tomcat/webapps/share.war'
- Title: Web Quick Start Share
- Version: 1.1
- Install Date: Thu Jul 28 13:16:07 CEST 2016
- Description: Web Quick Start Share Module

Archivos en /alfresco/extensions:

drwxr-xr-x 2 root root 4096 Jul 28 2016 audit
drwxr-xr-x 2 root root 4096 Jul 28 2016 bootstrap
-rw-r--r-- 1 root root 11675 May 4 10:57 custom-log4j.properties
drwxr-xr-x 2 root root 4096 Jul 28 2016 mimetype
-rw-r--r-- 1 root root 102 Jul 28 2016 wqsapi-custom.properties

¿se pueden eliminar los .sample o pueden servir para algo?

Archivos en /alfresco/web-extensions

drwxr-xr-x 2 root root 4096 Jul 14 11:22 .
drwxr-xr-x 5 root root 4096 Aug 4 2016 ..
-rw-r--r-- 1 root root 11412 Feb 16 2016 awe-config-custom.xml
-rw-r--r-- 1 root root 2156 Feb 16 2016 custom-slingshot-application-context.xml.sample
-rw-r--r-- 1 root root 20354 Jul 28 2016 share-config-custom.xml
-rw-r--r-- 1 root root 20354 Sep 13 2016 share-config-custom.xml.ori
-rw-r--r-- 1 root root 2188 Feb 16 2016 smartfolders-amp-actions-config.xml

Dentro de Alfresco / Repository:

Repositorio > Diccionario de Datos > Models: Aquí no tengo nada, ni scripts ni documentos.
Repositorio > Diccionario de Datos > Web Script Extensions: Aquí solo tengo un archivo que se llama readme.html que te indica cómo customizar un Web Script.

He repasado todo el Repository y no tengo nada...

Espero que con los logs obtenidos puedas ayudarme a sacar algo en claro.

Muchas gracias por tu ayuda!

Un saludo

Rubén

Re: Consumo excesivo de JAVA al cabo de 10 días

rublape — Wed, 06 Sep 2017 14:08:16 GMT

Buenas Cesar,

Muchas gracias por el aporte de la herramienta ya que me viene muy bien para tener monitorizado todo el sistema. Ya he descargado el amp, pero tengo la duda de si se instala en el alfresco.war o en el share.war o en ¿ambos?

He mirado varios links de github y de zylk.net referidos en este post pero no encuentro cómo instalarlo. Por lo menos en que war está situado.

Por otro lado digo 10 días por aproximar, a veces tarda un poco más o un poco menos, como máximo cada dos semanas tengo que reiniciar. Yo creo que hay parte de memoria que JAVA ni libera y sube y sube hasta que se llena...pero no soy capaz de identificarlo...

Esperemos que con el programa pueda sacar más luz sobre tanta oscuridad...

Muchas gracias!

Un saludo

Re: Consumo excesivo de JAVA al cabo de 10 días

cesarista — Wed, 06 Sep 2017 14:15:45 GMT

Buenas:

El proyecto debería compilar un AMP para el repo y otro para Share, pero el relevante para tu caso es el del repositorio. La monitorización está en la consola del repositorio (/alfresco/)

Saludos.

--C.

Re: Consumo excesivo de JAVA al cabo de 10 días

cristinamr — Wed, 06 Sep 2017 14:26:53 GMT

Te cuento lo que veo:

A modo informativo: Tienes un addon instalado que no es nativo pero no lo tienes desplegado en amps/ y amps_share/:

create-link-repo AMP project y create-link-share AMP project

Pertenecen a este desarrollo: GitHub - skomarica/alfresco-share-create-link: "Create Link" is a custom Alfresco Share Document Library action, similar…

Para que lo tengas en cuenta en un futuro: Esta funcionalidad ya existe en Alfresco 5.2.

Por otra parte, dado esto:

2017-09-05 15:52:00,624 WARN [org.alfresco.repo.cache.TransactionalCache.org.alfresco.userToAuthorityTransactionalCache] [LocalFeedGenerator1] Transactional update cache 'org.alfresco.userToAuthorityTransactionalCache' is full (100).

Creo que aquí tenemos la pista sobre qué está ocurriendo. Si echamos un vistazo a qué hace esta caché:

Normally you shouldn't see this particular warning though, unless you are creating / manipulating more than 100 Alfresco users per transaction

Sacado de aquí.

En tu Alfresco debes tener "algo" que manipula usuarios más de 100 por transacción (de ahí a que está completa la caché) y relentice el sistema porque siga manipulando usuarios en transacciones. Deberías analizar en profundidad qué tienes desplegado en webapps/alfresco y webapps/share por si tienes algún paquete o personalizaciones (mira en esta ruta a ver si ves algo: alfresco-5.1/tomcat/webapps/alfresco/WEB-INF/classes/), me da que no va a ser en Share, pero echa un vistazo igualmente.

Aquí te dejo sobre cómo debes aumentar la variable de la TransactionalCache : Individual cache settings | Alfresco Documentation ¡Ojo!: Esto no es una solución, solo es paliativo hasta que demos con el proceso que la consume.

Ve comentándonos.

Cris.

Re: Consumo excesivo de JAVA al cabo de 10 días

douglascrp — Wed, 06 Sep 2017 17:38:24 GMT

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

Re: Consumo excesivo de JAVA al cabo de 10 días

douglascrp — Wed, 06 Sep 2017 17:40:53 GMT

Yo tengo utilizado con éxito el Recolector de basura G1GC

G1: One Garbage Collector To Rule Them All

Re: Consumo excesivo de JAVA al cabo de 10 días

cesarista — Wed, 06 Sep 2017 18:16:21 GMT

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.

Re: Consumo excesivo de JAVA al cabo de 10 días

rublape — Thu, 07 Sep 2017 05:47:21 GMT

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!

Re: Consumo excesivo de JAVA al cabo de 10 días

rublape — Thu, 07 Sep 2017 05:53:56 GMT

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

Re: Consumo excesivo de JAVA al cabo de 10 días

cesarista — Thu, 07 Sep 2017 08:17:42 GMT

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.

Re: Consumo excesivo de JAVA al cabo de 10 días

cristinamr — Thu, 07 Sep 2017 14:35:57 GMT

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.

Re: Consumo excesivo de JAVA al cabo de 10 días

rublape — Fri, 08 Sep 2017 14:12:55 GMT

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!

Re: Consumo excesivo de JAVA al cabo de 10 días

rublape — Mon, 11 Sep 2017 09:23:09 GMT

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

Re: Consumo excesivo de JAVA al cabo de 10 días

cesarista — Mon, 11 Sep 2017 10:00:40 GMT

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.

Re: Consumo excesivo de JAVA al cabo de 10 días

rublape — Mon, 11 Sep 2017 10:23:50 GMT

Hola César,

Ese mensaje está apareciendo continuamente, pero el problema rendimiento suele ocurrir cuando lleva unas dos semanas (aprox) el servicio Alfresco sin reiniciarse... Al ver estas alarmas en el log estabamos intentando ver si el fallo de rendimiento es producido por la caché.

Por otro lado, en cuanto falle de nuevo Alfresco adjuntaré los resultados de jstack a ver si arroja algo más de información.

Un saludo!

Rubén