From karel.gardas@centrum.cz Fri May 30 18:12:33 2014
From: Karel Gardas <karel.gardas@centrum.cz>
To: xwiki-devs@xwiki.org
Subject: Re: [xwiki-devs] Out of memory errors (scalability of xwiki).
Date: Fri, 30 May 2014 20:12:15 +0200
Message-ID: <5388C9FF.30700@centrum.cz>
In-Reply-To: <0BED08A2-3317-48DE-95DE-1FC3733869C6@hoplahup.net>
MIME-Version: 1.0
Content-Type: multipart/mixed; boundary="===============0850549462539345525=="

--===============0850549462539345525==
Content-Type: text/plain; charset="utf-8"
Content-Transfer-Encoding: quoted-printable


Paul,

On 05/28/14 08:11 PM, Paul Libbrecht wrote:
>>> Of course I know the way how to increase Java's memory space/heap
>>> space. The problem is that this will not help here. Simply if I
>>> do so and then create 100 millions of pages on one run I will
>>> still get to the same issue just it'll take a lot longer.
>
> You won't reach 100 time the memory taken by downloading a 100
> million pages after you download a million pages. The caches have
> limits and you should measure how much memory in your setting is
> needed to reach that limit. Tests such as yours, after they reach the
> max, will get slower because of the DB access following the cache
> eviction; they are not very realistic under that point of view.

yes, I'm sure the test is not that realistic so far since majority of=20
xwiki usecases is probably download/rendering of page than upload of=20
page which I'm testing now. The reason of my test is simple, my task is=20
to attempt importing whole Wikipedia content w/o history into the XWiki.=20
For this I need to have it stable for import which is something I do=20
have problem now.

> The best way to follow this is to use JMX and get a graph of the
> cache values, you should see maximum be reached after a while. At
> curriki, we have adjusted the caches to be a bit bigger and we do
> reach the maximum (100'000 if I remember well, for the document
> cache) after about an hour after the restart. Then things get pretty
> stable with our max 8G of memory.

I'm glad that your setup is stable. I do have following cache setup here:

$ grep cache `find . -name 'xwiki.cfg'`
#-# Put a cache in front of the document store. This greatly improves=20
performance at the cost of memory consumption.
xwiki.store.cache=3D1
#-# Maximum number of documents to keep in the cache.
xwiki.store.cache.capacity=3D100
#-# Maximum number of documents to keep in the rendered cache
xwiki.render.cache.capacity=3D100
# xwiki.authentication.ldap.groupcache_expiration=3D21600
xwiki.plugin.image.cache.capacity=3D30

this is XWiki 6.0.1 on top of Tomcat 7.0.53 using PostgreSQL 9.3/64bit.=20
The JVM is 1.7.0_07 everything running on Solaris 11.1. When I give 2GB=20
RAM to catalina by:

$ cat bin/setenv.sh
CATALINA_OPTS=3D"-server -Xms2048m -Xmx2048m -XX:MaxPermSize=3D196m=20
-Dfile.encoding=3Dutf-8 -Djava.awt.headless=3Dtrue -XX:+UseParallelGC=20
-XX:MaxGCPauseMillis=3D100"
export CATALINA_OPTS


and then run my benchmark which is just using REST to import following=20
simple page:

"<?xml version=3D\"1.0\" encoding=3D\"UTF-8\" standalone=3D\"yes\"?>"
      ++ "<page xmlns=3D\"http://www.xwiki.org\">"
      ++ "<title>Semantic XWiki Benchmark page " ++  title ++ "</title>"
      ++ "<syntax>xwiki/2.0</syntax>"
      ++ "<content>This is a benchark page."
      ++ "The list of properties defined for this page is:"
      ++ "</content>"
      ++ "</page>"

where title is BenchPage_<number>

Now, when I pushed that, then after around 400k pages imported I hit OOM=20
error. JConsole is thrown out by closed connection and even benchmark=20
tool complains about few 500 HTTP error codes received. The exception=20
output on Tomcat's console looks:

Exception in thread "DefaultQuartzScheduler_QuartzSchedulerThread"=20
java.lang.OutOfMemoryError: Java heap space
Exception in thread "RMI TCP Connection(idle)" Exception in thread "RMI=20
TCP Connection(idle)" java.lang.OutOfMemoryError: Java heap space
java.lang.OutOfMemoryError: Java heap space
Exception in thread=20
"TxCleanupService,platform.security.authorization.cache,local"=20
java.lang.OutOfMemoryError: Java heap space
Exception in thread=20
"TxCleanupService,localization.bundle.document,local" Exception in=20
thread "TxCleanupService,wiki.descriptor.cache.wikiId,local"=20
java.lang.OutOfMemoryError: Java heap space
java.lang.OutOfMemoryError: Java heap space
Exception in thread "TxCleanupService,xwiki.store.pageexistcache,local"=20
java.lang.OutOfMemoryError: Java heap space
Exception in thread "TxCleanupService,xwiki.store.pagecache,local"=20
java.lang.OutOfMemoryError: Java heap space
May 30, 2014 4:12:18 PM org.restlet.engine.application.StatusFilter doHandle
WARNING: Exception or error caught in status service
java.lang.OutOfMemoryError: Java heap space

May 30, 2014 4:12:18 PM org.restlet.engine.application.StatusFilter doHandle
WARNING: Exception or error caught in status service
java.lang.OutOfMemoryError: Java heap space
         at java.lang.Class.getDeclaredMethods0(Native Method)
         at java.lang.Class.privateGetDeclaredMethods(Class.java:2442)
         at java.lang.Class.getMethod0(Class.java:2685)
         at java.lang.Class.getMethod(Class.java:1620)
         at=20
org.xwiki.legacy.internal.oldcore.notification.LegacyNotificationDispatcher.g=
etNotificationManager(LegacyNotificationDispatcher.java:94)
         at=20
org.xwiki.legacy.internal.oldcore.notification.LegacyNotificationDispatcher.o=
nEvent(LegacyNotificationDispatcher.java:109)
         at=20
org.xwiki.observation.internal.DefaultObservationManager.notify(DefaultObserv=
ationManager.java:299)
         at=20
org.xwiki.observation.internal.DefaultObservationManager.notify(DefaultObserv=
ationManager.java:264)
         at com.xpn.xwiki.XWiki.saveDocument(XWiki.java:1323)
         at com.xpn.xwiki.api.Document.saveDocument(Document.java:2299)
         at com.xpn.xwiki.api.Document.save(Document.java:2202)
         at com.xpn.xwiki.api.Document.save(Document.java:2196)
         at=20
org.xwiki.rest.internal.resources.pages.ModifiablePageResource.putPage(Modifi=
ablePageResource.java:67)
         at=20
org.xwiki.rest.internal.resources.pages.PageResourceImpl.putPage(PageResource=
Impl.java:62)
         at sun.reflect.GeneratedMethodAccessor296.invoke(Unknown Source)
         at=20
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.=
java:43)
         at java.lang.reflect.Method.invoke(Method.java:601)
         at=20
org.restlet.ext.jaxrs.internal.wrappers.AbstractMethodWrapper.internalInvoke(=
AbstractMethodWrapper.java:171)
         at=20
org.restlet.ext.jaxrs.internal.wrappers.ResourceMethod.invoke(ResourceMethod.=
java:291)
         at=20
org.restlet.ext.jaxrs.JaxRsRestlet.invokeMethod(JaxRsRestlet.java:1043)
         at org.restlet.ext.jaxrs.JaxRsRestlet.handle(JaxRsRestlet.java:792)
         at org.restlet.routing.Filter.doHandle(Filter.java:159)
         at org.restlet.routing.Filter.handle(Filter.java:206)
         at org.restlet.routing.Router.doHandle(Router.java:500)
         at org.restlet.routing.Router.handle(Router.java:740)
         at org.restlet.routing.Filter.doHandle(Filter.java:159)
         at org.restlet.routing.Filter.handle(Filter.java:206)
         at org.restlet.routing.Filter.doHandle(Filter.java:159)
         at org.restlet.routing.Filter.handle(Filter.java:206)
         at org.restlet.routing.Filter.doHandle(Filter.java:159)
         at org.restlet.routing.Filter.handle(Filter.java:206)
         at org.restlet.routing.Filter.doHandle(Filter.java:159)

May 30, 2014 4:12:18 PM org.restlet.engine.application.StatusFilter doHandle
WARNING: Exception or error caught in status service
java.lang.OutOfMemoryError: Java heap space
         at java.lang.Class.getDeclaredMethods0(Native Method)
         at java.lang.Class.privateGetDeclaredMethods(Class.java:2442)
         at java.lang.Class.getMethod0(Class.java:2685)
         at java.lang.Class.getMethod(Class.java:1620)
         at=20
org.xwiki.legacy.internal.oldcore.notification.LegacyNotificationDispatcher.g=
etNotificationManager(LegacyNotificationDispatcher.java:94)
         at=20
org.xwiki.legacy.internal.oldcore.notification.LegacyNotificationDispatcher.o=
nEvent(LegacyNotificationDispatcher.java:109)
         at=20
org.xwiki.observation.internal.DefaultObservationManager.notify(DefaultObserv=
ationManager.java:299)
         at=20
org.xwiki.observation.internal.DefaultObservationManager.notify(DefaultObserv=
ationManager.java:264)
         at com.xpn.xwiki.XWiki.saveDocument(XWiki.java:1323)
         at com.xpn.xwiki.api.Document.saveDocument(Document.java:2299)
         at com.xpn.xwiki.api.Document.save(Document.java:2202)
         at com.xpn.xwiki.api.Document.save(Document.java:2196)
         at=20
org.xwiki.rest.internal.resources.pages.ModifiablePageResource.putPage(Modifi=
ablePageResource.java:67)
         at=20
org.xwiki.rest.internal.resources.pages.PageResourceImpl.putPage(PageResource=
Impl.java:62)
         at sun.reflect.GeneratedMethodAccessor296.invoke(Unknown Source)
         at=20
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.=
java:43)
         at java.lang.reflect.Method.invoke(Method.java:601)
         at=20
org.restlet.ext.jaxrs.internal.wrappers.AbstractMethodWrapper.internalInvoke(=
AbstractMethodWrapper.java:171)
         at=20
org.restlet.ext.jaxrs.internal.wrappers.ResourceMethod.invoke(ResourceMethod.=
java:291)
         at=20
org.restlet.ext.jaxrs.JaxRsRestlet.invokeMethod(JaxRsRestlet.java:1043)
         at org.restlet.ext.jaxrs.JaxRsRestlet.handle(JaxRsRestlet.java:792)
         at org.restlet.routing.Filter.doHandle(Filter.java:159)
         at org.restlet.routing.Filter.handle(Filter.java:206)
         at org.restlet.routing.Router.doHandle(Router.java:500)
         at org.restlet.routing.Router.handle(Router.java:740)
         at org.restlet.routing.Filter.doHandle(Filter.java:159)
         at org.restlet.routing.Filter.handle(Filter.java:206)
         at org.restlet.routing.Filter.doHandle(Filter.java:159)
         at org.restlet.routing.Filter.handle(Filter.java:206)
         at org.restlet.routing.Filter.doHandle(Filter.java:159)
         at org.restlet.routing.Filter.handle(Filter.java:206)
         at org.restlet.routing.Filter.doHandle(Filter.java:159)

May 30, 2014 4:12:18 PM org.restlet.engine.application.StatusFilter doHandle
WARNING: Exception or error caught in status service
java.lang.OutOfMemoryError: Java heap space

2014-05-30 16:12:18,851 [DefaultQuartzScheduler_Worker-7] ERROR=20
o.q.c.JobRunShell              - Job=20
DEFAULT.xwiki:Scheduler.WatchListHourlyNotifier_0 threw an unhandled=20
Exception:
java.lang.OutOfMemoryError: Java heap space
2014-05-30 16:12:18,856 [XWiki Solr index thread] WARN=20
o.h.u.JDBCExceptionReporter    - SQL Error: 0, SQLState: 08001
2014-05-30 16:12:18,856 [XWiki Solr index thread] ERROR=20
o.h.u.JDBCExceptionReporter    - The connection attempt failed.
2014-05-30 16:12:18,858 [DefaultQuartzScheduler_Worker-7] ERROR=20
o.q.c.ErrorLogger              - Job=20
(DEFAULT.xwiki:Scheduler.WatchListHourlyNotifier_0 threw an exception.
org.quartz.SchedulerException: Job threw an unhandled exception.
         at org.quartz.core.JobRunShell.run(JobRunShell.java:213)=20
~[quartz-1.6.5.jar:1.6.5]
         at=20
org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:525)=
=20
[quartz-1.6.5.jar:1.6.5]
Caused by: java.lang.OutOfMemoryError: Java heap space
2014-05-30 16:12:18,859 [DefaultQuartzScheduler_Worker-7] ERROR=20
c.x.x.p.s.StatusListener       - Job=20
(DEFAULT.xwiki:Scheduler.WatchListHourlyNotifier_0 threw an exception.
org.quartz.SchedulerException: Job threw an unhandled exception.
         at org.quartz.core.JobRunShell.run(JobRunShell.java:213)=20
~[quartz-1.6.5.jar:1.6.5]
         at=20
org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:525)=
=20
[quartz-1.6.5.jar:1.6.5]
Caused by: java.lang.OutOfMemoryError: Java heap space


Funny thing is that before the error JConsole does not show any signs=20
that the server was allocating a lot of memory. Probably this should be=20
quick spike in mem consumption or otherwise I don't understand at all=20
why this happen.


Now, the question is: I do have or I think I do have very limited cache=20
setup here. I've increase RAM side to 2GB which is over the recommended=20
size by xwiki.org itself -- they warn about size bigger than 1GB due to=20
slowness of GC then. Anyway, 2GB, limited size of cache and yet I hit=20
OOM. Do you think I shall increase RAM limit even further?

Thanks!
Karel

--===============0850549462539345525==--