Aprile 2014 Not responding

Problema

Il server occasionalmente non risponde, dopo time out si ha "Bad Gateway"

requests.jpg
top.jpg

Analisi

Estratto dal log /var/log/tomcat6/catalina.2014-04-07.log

Apr 7, 2014 4:35:50 AM org.apache.catalina.loader.WebappClassLoader clearThreadLocalMap
SEVERE: The web application [/xwiki] created a ThreadLocal with key of type cache.invocation.InvocationContextContainer] .... but failed to remove it when the web application was stopped. This is very likely to create a memory leak.
Apr 7, 2014 4:35:50 AM org.apache.catalina.loader.WebappClassLoader clearThreadLocalMap
SEVERE: The web application [/xwiki] created a ThreadLocal with key of type [org.apache.log4j.helpers.ThreadLocalMap] ... but failed to remove it when the web application was stopped. This is very likely to create a memory leak.


Apr 7, 2014 6:41:58 AM org.apache.catalina.core.StandardService start
INFO: Starting service Catalina
Apr 7, 2014 6:41:59 AM org.apache.catalina.startup.Catalina start
INFO: Server startup in 1482 ms

Apr 7, 2014 8:05:49 AM org.apache.jk.server.JkCoyoteHandler invoke
INFO: Error servicing request R( /xwiki/bin/view/Courses/SdL1213Material)
java.lang.OutOfMemoryError: Java heap space
at org.apache.tomcat.util.buf.CharChunk.allocate(CharChunk.java:119)


Apr 7, 2014 8:09:59 AM org.apache.tomcat.util.threads.ThreadPool$ControlRunnable run
SEVERE: Caught exception (java.lang.OutOfMemoryError: Java heap space) executing org.apache.jk.common.ChannelSocket$SocketAcceptor@807f66, terminating thread
Apr 7, 2014 8:17:35 AM org.apache.jk.common.ChannelSocket processConnection
WARNING: processCallbacks status 2
Apr 7, 2014 8:07:48 AM org.apache.jk.server.JkCoyoteHandler invoke
INFO: Error servicing request R( /xwiki/bin/view/XWiki/NicolaGiancecchi)
java.lang.OutOfMemoryError: Java heap space
at org.apache.tomcat.util.buf.ByteChunk.allocate(ByteChunk.java:173)


RIAVVIO MANUALE
Apr 7, 2014 8:38:02 AM org.apache.catalina.core.StandardService start
INFO: Starting service Catalina
Apr 7, 2014 8:38:05 AM org.apache.catalina.startup.Catalina start
INFO: Server startup in 2747 ms

Dall’analisi si evince che si verificano dei memory leak i quali forse provocano un java.lang.OutOfMemoryError: Java heap space  che dovrebbe essere la causa del problema riscontrato.
Infatti si ritrova lo stesso evento OutOfMemoryError in diverse occasioni nei giorni precedenti. 

localhost Log

Estratto dal log /var/log/tomcat6/localhost.2014-04-05.log

Apr 5, 2014 9:01:46 AM org.apache.catalina.core.StandardWrapperValve invoke
SEVERE: Servlet.service() for servlet action threw exception
java.lang.OutOfMemoryError: Java heap space
Apr 5, 2014 11:08:16 AM org.apache.catalina.core.StandardWrapperValve invoke
SEVERE: Servlet.service() for servlet action threw exception
java.lang.OutOfMemoryError: Java heap space
Apr 5, 2014 11:19:59 AM org.apache.catalina.core.StandardWrapperValve invoke
SEVERE: Servlet.service() for servlet action threw exception
java.lang.OutOfMemoryError: Java heap space
Apr 5, 2014 3:50:08 PM org.apache.catalina.core.StandardWrapperValve invoke
SEVERE: Servlet.service() for servlet action threw exception
java.lang.OutOfMemoryError: Java heap space

Non sembr ci siano problemi particolare dovuti a qualche pagina specifica

Analisi errori runtime

tail -200000 /var/log/tomcat6/catalina.out |grep "ERROR"

014-04-07 07:27:02,188 [http://tucson.alice.unibo.it/xwiki/bin/view/Tuprolog/CorePubs] ERROR store.XWikiHibernateStore       - No data for property bibtex of object id 197833314
2014-04-07 07:27:08,479 [http://tucson.alice.unibo.it/xwiki/bin/view/Tuprolog/CorePubs] ERROR store.XWikiHibernateStore       - No data for property bibtex of object id -1977101402
2014-04-07 07:27:33,035 [http://tucson.alice.unibo.it/xwiki/bin/view/TuCSoN/Publication] ERROR store.XWikiHibernateStore       - No data for property bibtex of object id 197833314
2014-04-07 07:27:34,751 [http://tucson.alice.unibo.it/xwiki/bin/view/TuCSoN/Publication] ERROR store.XWikiHibernateStore       - No data for property author of object id 555405738
2014-04-07 07:27:39,476 [http://tucson.alice.unibo.it/xwiki/bin/view/TuCSoN/Publication] ERROR store.XWikiHibernateStore       - No data for property bibtex of object id -1977101402
2014-04-07 07:27:48,023 [http://simpa.alice.unibo.it/xwiki/bin/view/TheFridge/TracSvnUsers] ERROR internal.DefaultVelocityEngine  - Parser Exception: xwiki:TheFridge.TracSvnUsers
2014-04-07 07:29:07,494 [http://respect.alice.unibo.it/xwiki/bin/view/Publications/MATES09RECOG] ERROR internal.DefaultVelocityEngine  - Exception in macro #pubEditorLink at xwiki:Publications.MATES09RECOG[line 168, column 32]
2014-04-07 07:29:07,494 [http://respect.alice.unibo.it/xwiki/bin/view/Publications/MATES09RECOG] ERROR internal.DefaultVelocityEngine  - Exception in macro #pubEditors at xwiki:Publications.MATES09RECOG[line 47, column 496]
2014-04-07 07:29:16,054 [http://tucson.alice.unibo.it/xwiki/bin/view/TuCSoN/OverviewOld] ERROR internal.DefaultVelocityEngine  - Exception in macro #pubAuthorLink at xwiki:TuCSoN.OverviewOld[line 144, column 32]
2014-04-07 07:29:16,054 [http://tucson.alice.unibo.it/xwiki/bin/view/TuCSoN/OverviewOld] ERROR internal.DefaultVelocityEngine  - Exception in macro #pubAuthors at xwiki:TuCSoN.OverviewOld[line 194, column 84]
2014-04-07 07:29:16,054 [http://tucson.alice.unibo.it/xwiki/bin/view/TuCSoN/OverviewOld] ERROR internal.DefaultVelocityEngine  - Exception in macro #pubATVinline at xwiki:TuCSoN.OverviewOld[line 34, column 70]
2014-04-07 07:29:49,927 [http://www.alice.unibo.it/xwiki/bin/view/Publications/ICSOFT09] ERROR internal.DefaultVelocityEngine  - Exception in macro #pubEditorLink at xwiki:Publications.ICSOFT09[line 168, column 32]
2014-04-07 07:29:49,927 [http://www.alice.unibo.it/xwiki/bin/view/Publications/ICSOFT09] ERROR internal.DefaultVelocityEngine  - Exception in macro #pubEditors at xwiki:Publications.ICSOFT09[line 47, column 496]
2014-04-07 07:30:12,322 [http://respect.alice.unibo.it/xwiki/bin/view/Courses/SmaLs0809Material?xpage=print] ERROR internal.DefaultVelocityEngine  - Exception in macro #pubAuthorLink at xwiki:Courses.SmaLs0809Material[line 144, column 32]
2014-04-07 07:30:12,322 [http://respect.alice.unibo.it/xwiki/bin/view/Courses/SmaLs0809Material?xpage=print] ERROR internal.DefaultVelocityEngine  - Exception in macro #pubAuthors at xwiki:Courses.SmaLs0809Material[line 194, column 84]
2014-04-07 07:30:12,322 [http://respect.alice.unibo.it/xwiki/bin/view/Courses/SmaLs0809Material?xpage=print] ERROR internal.DefaultVelocityEngine  - Exception in macro #pubATVinline at xwiki:Courses.SmaLs0809Material[line 77, column 3]
2014-04-07 07:30:24,174 [http://respect.alice.unibo.it/xwiki/bin/view/ReverseEngineeringGeneNetworks/Theses?language=en] ERROR store.XWikiHibernateStore       - No data for property comment of object id 1599841930
2014-04-07 07:30:24,176 [http://respect.alice.unibo.it/xwiki/bin/view/ReverseEngineeringGeneNetworks/Theses?language=en] ERROR store.XWikiHibernateStore       - No data for property comment of object id 1599841931
2014-04-07 07:30:27,857 [http://tuprolog.apice.unibo.it/xwiki/bin/view/Theses/All?xpage=print] ERROR store.XWikiHibernateStore       - No data for property comment of object id 1599841930
2014-04-07 07:30:27,859 [http://tuprolog.apice.unibo.it/xwiki/bin/view/Theses/All?xpage=print] ERROR store.XWikiHibernateStore       - No data for property comment of object id 1599841931
2014-04-07 07:30:46,132 [http://tucson.alice.unibo.it/xwiki/bin/view/TuCSoN/OngoingTheses] ERROR store.XWikiHibernateStore       - No data for property comment of object id 1599841930
2014-04-07 07:30:46,134 [http://tucson.alice.unibo.it/xwiki/bin/view/TuCSoN/OngoingTheses] ERROR store.XWikiHibernateStore       - No data for property comment of object id 1599841931
2014-04-07 07:31:06,923 [http://tucson.alice.unibo.it/xwiki/bin/view/TuCSoN/Overview-old] ERROR internal.DefaultVelocityEngine  - Exception in macro #pubAuthorLink at xwiki:TuCSoN.Overview-old[line 144, column 32]
2014-04-07 07:31:06,923 [http://tucson.alice.unibo.it/xwiki/bin/view/TuCSoN/Overview-old] ERROR internal.DefaultVelocityEngine  - Exception in macro #pubAuthors at xwiki:TuCSoN.Overview-old[line 194, column 84]
2014-04-07 07:31:06,923 [http://tucson.alice.unibo.it/xwiki/bin/view/TuCSoN/Overview-old] ERROR internal.DefaultVelocityEngine  - Exception in macro #pubATVinline at xwiki:TuCSoN.Overview-old[line 34, column 70]
2014-04-07 07:31:40,794 [http://tuprolog.apice.unibo.it/xwiki/bin/view/BioMABS/Papers] ERROR internal.DefaultVelocityEngine  - Exception in macro #pubAuthorLink at xwiki:BioMABS.Papers[line 144, column 32]
2014-04-07 07:31:40,794 [http://tuprolog.apice.unibo.it/xwiki/bin/view/BioMABS/Papers] ERROR internal.DefaultVelocityEngine  - Exception in macro #pubAuthors at xwiki:BioMABS.Papers[line 176, column 1]
2014-04-07 07:31:40,794 [http://tuprolog.apice.unibo.it/xwiki/bin/view/BioMABS/Papers] ERROR internal.DefaultVelocityEngine  - Exception in macro #pubATVblock at xwiki:BioMABS.Papers[line 7, column 4]
2014-04-07 07:50:55,861 [http://apice.unibo.it/xwiki/bin/view/Main/TagsRss?tag=Open%C3%82%C2%A0issues&xpage=rdf] ERROR util.JDBCExceptionReporter      - Illegal mix of collations (utf8_general_ci,COERCIBLE) and (latin1_swedish_ci,IMPLICIT) for operation=
2014-04-07 08:12:57,203 [https://alice.unibo.it/xwiki/bin/view/Theses/BonettiTuprologeclipse06] ERROR internal.DefaultVelocityEngine  - Exception in macro #template at /templates/startpage.vm[line 3, column 1]
2014-04-07 08:12:48,272 [http://www.alice.unibo.it/xwiki/bin/view/Talks/CoordinationAgentlinkII2001] ERROR internal.DefaultVelocityEngine  - Exception in macro #template at /templates/startpage.vm[line 3, column 1]
2014-04-07 08:12:40,848 [https://alice.unibo.it/xwiki/bin/view/Publications/BioSac2012] ERROR internal.DefaultVelocityEngine  - Exception in macro #template at /templates/xwikivars.vm[line 86, column 1]
2014-04-07 08:08:04,645 [https://alice.unibo.it/xwiki/bin/view/Talks/TalksPerYear?year=2006] ERROR internal.DefaultVelocityEngine  - Exception in macro #userPersonalwikiLink at xwiki:Talks.TalksPerYear[line 67, column 79]
2014-04-07 08:17:35,454 [http://respect.alice.unibo.it/xwiki/bin/view/Courses/SdL1213Material?xpage=print] ERROR internal.DefaultVelocityEngine  - Exception in macro #pubAuthorLink at xwiki:Courses.SdL1213Material[line 144, column 32]

parametri Tomcat

ps -ef|grep tomcat
tomcat6   3049     1  8 08:38 ?        00:12:00 /usr/lib/jvm/default-java/bin/java -Djava.util.logging.config.file=/var/lib/tomcat6/conf/logging.properties -Djava.awt.headless=true -Xmx1024m -XX:+UseConcMarkSweepGC -Xms512m -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager -Djava.endorsed.dirs=/usr/share/tomcat6/endorsed -classpath /usr/share/tomcat6/bin/bootstrap.jar -Dcatalina.base=/var/lib/tomcat6 -Dcatalina.home=/usr/share/tomcat6 -Djava.io.tmpdir=/tmp/tomcat6-tomcat6-tmp org.apache.catalina.startup.Bootstrap start
gestore   4059  2890  0 10:55 pts/0    00:00:00 grep --color=auto tomcat

Diagnosi

Fix

  1. MODIFICA parametri tomcat  heap da "-Xms512m -Xmx1024m" a "-Xms1024m -Xmx1024m"

http://platform.xwiki.org/xwiki/bin/view/AdminGuide/Performances#HMemory||rel="blank"]]

    1. Hard-coded  in /etc/init.d/tomcat6
    2. /usr/share/tomcat6/bin/setenv.sh
  1. Eliminato link preview (?xpage=print) da footer.vm. Rimane anteprima PDF
  2. MODIFICA parametri tomcat secondo nuove linee guida xwiki.org 1. [[Upgrade versione xWiki 2.2 
  3. rebuild del server, su piattaforma a 64 bit con xwiki5

    See also:
    JAVA VM Options
    JAVA Out of memory Article

Sviluppi

Dopo la modifica del parametro xms il problema si è ripresentato

Estratto dal log /var/log/tomcat6/localhost.2014-04-08.log


Apr 8, 2014 2:11:48 AM org.apache.catalina.core.StandardWrapperValve invoke
SEVERE: Servlet.service()  threw exception java.lang.OutOfMemoryError: Java heap space

Apr 8, 2014 2:47:19 AM org.apache.catalina.core.StandardWrapperValve invoke
SEVERE: Servlet.service()  threw exception java.lang.OutOfMemoryError: Java heap space

Apr 8, 2014 4:12:44 AM org.apache.catalina.core.StandardWrapperValve invoke
SEVERE: Servlet.service()  threw exception java.lang.OutOfMemoryError: Java heap space