Slow performance

[fschnell]

We have Alfresco 2.2E installed and uploaded 120,000 documents residing in a hierarchy of a handfull (maybe 100) spaces. Access via CIFS or the webinterface is fast on the first level showing about 15 spaces. From there opening a space with 200 documents takes about 10 seconds, with 500 documents >30 seconds and every space with more than that is inaccessible. There are 150 LDAP users defined and the backend database on a separate server is Oracle 9. I got the recommendation not to store more than 200 documents in a space/folder as performance after that would massively decrease.

As I do not know where to start analysing and what values would be normal or common, can others please post access times for folders with various amounts of documents, e.g. 100 files, 200 files, 500 files and a 1000 files; what database is used and whether it is on a separate server.

Thanks for your help
Frank

[varsenault]

One of our client's installation has been really hit hard by performance issues since a couple of months, and now it's practically unuseable.

Here is our Alfresco version :

08:26:17,984 WARN  [org.alfresco.util.OpenOfficeConnectionTester] An initial OpenOffice connection could not be established.
08:26:17,998 INFO  [org.alfresco.service.descriptor.DescriptorService] Alfresco JVM - v1.5.0_12-b04; maximum heap size 1877.375MB
08:26:17,999 INFO  [org.alfresco.service.descriptor.DescriptorService] Alfresco started (Labs): Current version 3.0.0 (Stable 1526) schema 1002 - Installed version 2.1.0 (484) schema 64‍‍‍

It is running on an Dell FC7 Quad-core Xeon machine with 10gb of RAM, Mysql Distrib 5.0.37, for redhat-linux-gnu (x86_64). It has 2 JBPM workflow definitions running about 1000 open workflow instances (and about 3000 closed instances). It has about 80gb's worth of documents, 20 concurrent users, etc. Here's the startup script JAVA_OPTS config :

export JAVA_OPTS='-server -Xms1g -Xmx2g -XX:MaxPermSize=128m -XX:NewSize=512m'‍

And here's the java -version output :

java version "1.5.0_12"
Java(TM) 2 Runtime Environment, Standard Edition (build 1.5.0_12-b04)
Java HotSpot(TM) Server VM (build 1.5.0_12-b04, mixed mode)‍‍‍

After not even 15 minutes, the logs are filled with entries like :

09:25:45,217 ERROR [org.alfresco.web.ui.common.Utils] Failed to get completed tasks: java.lang.OutOfMemoryError: Java heap space
java.lang.OutOfMemoryError: Java heap space
09:25:53,241 ERROR [org.alfresco.web.ui.common.Utils] Failed to get pooled tasks: java.lang.OutOfMemoryError: Java heap space
java.lang.OutOfMemoryError: Java heap space
09:25:56,820 ERROR [org.alfresco.web.ui.common.Utils] Failed to get completed tasks: java.lang.OutOfMemoryError: Java heap space
java.lang.OutOfMemoryError: Java heap space‍‍‍‍‍‍

At this point, any help would be appreciated. Thanks.

[fselendic]

One of our client's installation has been really hit hard by performance issues since a couple of months, and now it's practically unuseable.

Here is our Alfresco version :

08:26:17,984 WARN  [org.alfresco.util.OpenOfficeConnectionTester] An initial OpenOffice connection could not be established.
08:26:17,998 INFO  [org.alfresco.service.descriptor.DescriptorService] Alfresco JVM - v1.5.0_12-b04; maximum heap size 1877.375MB
08:26:17,999 INFO  [org.alfresco.service.descriptor.DescriptorService] Alfresco started (Labs): Current version 3.0.0 (Stable 1526) schema 1002 - Installed version 2.1.0 (484) schema 64‍‍‍

It is running on an Dell FC7 Quad-core Xeon machine with 10gb of RAM, Mysql Distrib 5.0.37, for redhat-linux-gnu (x86_64). It has 2 JBPM workflow definitions running about 1000 open workflow instances (and about 3000 closed instances). It has about 80gb's worth of documents, 20 concurrent users, etc. Here's the startup script JAVA_OPTS config :

export JAVA_OPTS='-server -Xms1g -Xmx2g -XX:MaxPermSize=128m -XX:NewSize=512m'‍

And here's the java -version output :

java version "1.5.0_12"
Java(TM) 2 Runtime Environment, Standard Edition (build 1.5.0_12-b04)
Java HotSpot(TM) Server VM (build 1.5.0_12-b04, mixed mode)‍‍‍

After not even 15 minutes, the logs are filled with entries like :

09:25:45,217 ERROR [org.alfresco.web.ui.common.Utils] Failed to get completed tasks: java.lang.OutOfMemoryError: Java heap space
java.lang.OutOfMemoryError: Java heap space
09:25:53,241 ERROR [org.alfresco.web.ui.common.Utils] Failed to get pooled tasks: java.lang.OutOfMemoryError: Java heap space
java.lang.OutOfMemoryError: Java heap space
09:25:56,820 ERROR [org.alfresco.web.ui.common.Utils] Failed to get completed tasks: java.lang.OutOfMemoryError: Java heap space
java.lang.OutOfMemoryError: Java heap space‍‍‍‍‍‍

At this point, any help would be appreciated. Thanks.

Well, what would be really helpful for you, if you are supporting biggish Alfresco (on any other Java based) installations, is to read a page or two about Java memory management (heap, NewGeneration, OldGeneration, various Garbage Collectors, default values, tuning etc.).

I'll try to explain just this specific case, which is actually rather simple to solve.

So, Java has garbage collectors. For them to work as fast and efficient as possible, heap (thats memory that Java uses for objects) has to be defined during startup of java virtual machine. There are some default values (which are different depending on Java version and compiler used), and there are switches that you can start Java with to modify those default values. The most known and used switches are -Xms (sets a heap value that Java will start with) and, most important in your case, -Xmx (sets a maximum heap value that Java session can have and use).

So, Java cannot dynamically change the maximum heap size (that's the nature of all garbage collectors that are present in Suns Java). Lets assume that, in your case, Java starts with 512Mb of heap. Inside that space, objects will be created, and destroyed/garbage collected when they are not needed anymore. Objects aren't garbage collected all the time (this is a gross simplification, that actually depends on objects lifecycle and type of garbage collector used), there is a trigger that puts GC to work; usually it is when 70% of heap is taken when GC kicks in. It then "stops the world", forbids JVM to do anything while it cleans unused objects (which can pause running of your program from few milliseconds to several seconds or even minutes). It collects all unreferenced objects, frees the heap, and "sleeps" until it is triggered again (when heap is 70+% full again).

So, what happens when GC cannot free more than 30% of memory? Poor thing tries, it gets triggered all the time, "stopping the world", your performance goes to hell because now only GC is running (and not Alfresco), and, in most extreme cases (yours), there's just not enough memory to be freed, new objects can't be created, and JVM throws:

java.lang.OutOfMemoryError: Java heap space java.lang.OutOfMemoryError: Java heap space

That has nothing to do with actual physical memory that you have on machine. It is consequence of how much of that memory you dedicated to Java, and how much of that dedicated memory Java has to use in your particular Alfresco installation case.

How to fix it?
Find out how your Java/Alfresco is starting. If on Linux, there is startup.sh script in "/pathtoyourtomcat/bin" directory. In it, there is something resembling this:

export JAVA_OPTS="-Xmx512m -Xms128m -XX:MaxPermSize=256m‍

Just change -Xmx512m to, lets say -Xmx1024m, and start Alfresco again. It should help a lot.

For a far more deeper insight in tuning Java systems, try to read stuff about Java garbage collectors and compilers, and how Java actually handles memory.


Regards,
Filip

[varsenault]

Thanks Filip, But our settings are already setup that way (Xmx=2g, Xms=1g). That's a maximum for a non-64bit installation… So there must be something else….

[fselendic]

Thanks Filip, But our settings are already setup that way (Xmx=2g, Xms=1g). That's a maximum for a non-64bit installation… So there must be something else….

Java outofmemory is, well, Java outofmemory 

Put -verbosegc in JVM startup. That way you'll be able to see what GC is doing, and how much heap it actually takes.

[varsenault]

Thanks again Filip.

The out of memory happen in Alfresco JBPM Dashlet code, for sure. There is 2GB assigned to Alfresco, and the exceptions are fired by Alfresco code and not custom extension code. First, all I get is "Failed to get pooled tasks", "Failed to get completed tasks", "Failed to get all active tasks". And the lines that keep coming up are :

org.alfresco.repo.workflow.jbpm.JBPMEngine.getPooledTasks(JBPMEngine.java:1228)
org.alfresco.repo.workflow.WorkflowServiceImpl.getPooledTasks(WorkflowServiceImpl.java:482)
org.alfresco.repo.workflow.jbpm.JBPMEngine.createWorkflowInstance(JBPMEngine.java:2762)
org.alfresco.repo.workflow.jbpm.JBPMEngine.createWorkflowPath(JBPMEngine.java:2673)
org.alfresco.repo.workflow.jbpm.JBPMEngine.createWorkflowTask(JBPMEngine.java:2830)‍‍‍‍‍

I understand that a memory problem is a memory problem, but it is definetly not coming from a JVM memory configuration problem or a usage overload. So, it must be something else… I'm wondering if anybody else has seen anything like it before….

[fselendic]

Thanks again Filip.

The out of memory happen in Alfresco JBPM Dashlet code, for sure. There is 2GB assigned to Alfresco, and the exceptions are fired by Alfresco code and not custom extension code. First, all I get is "Failed to get pooled tasks", "Failed to get completed tasks", "Failed to get all active tasks". And the lines that keep coming up are :

org.alfresco.repo.workflow.jbpm.JBPMEngine.getPooledTasks(JBPMEngine.java:1228)
org.alfresco.repo.workflow.WorkflowServiceImpl.getPooledTasks(WorkflowServiceImpl.java:482)
org.alfresco.repo.workflow.jbpm.JBPMEngine.createWorkflowInstance(JBPMEngine.java:2762)
org.alfresco.repo.workflow.jbpm.JBPMEngine.createWorkflowPath(JBPMEngine.java:2673)
org.alfresco.repo.workflow.jbpm.JBPMEngine.createWorkflowTask(JBPMEngine.java:2830)‍‍‍‍‍

I understand that a memory problem is a memory problem, but it is definetly not coming from a JVM memory configuration problem or a usage overload. So, it must be something else… I'm wondering if anybody else has seen anything like it before….

Huh, sorry, now I see that you do have -Xmx2g 

OK, lets go and debug this beast.

1. Are you sure that JVM is actually using 2GB heap (I know it sounds stupid, but better safe than sorry)
2. Are you sure that JVM is really not supposed to use 2GB of memory (this too sounds stupid, but how should I know what are you running there  )

If answers to both questions are "Yes", well, then you have a memory leak.

I doubt this kind of leak (filling 2Gb in 15 minutes) is coming from Alfresco, so I suppose that you do have some custom Java code running.
Either way, you will have to profile application. There are some objects that you don't need, but are still referenced by other objects, and cannot be freed. That fills memory, degrades performance, and in the end, throws Java OEM error.

There are several profilers out there, like JProbe, JProfiler, and there are also tools coming with JDK like JConsole.

http://developers.sun.com/learning/javaoneonline/sessions/hol2007/1420/jmxjconsole/index.html

You'll need Sun developer network account for reading this article, but you'll find lots of nice examples for profiling your app with free Sun tools like JConsole and jhat.

Also, most of the third party profiles have free evaluation versions.

If you don't have any custom Java code, if you are using plain old Alfresco, then try to Google for "Alfresco OutOfMemory" or "Alfresco memory leak", also try issues.alfresco.com to see if it is a known problem.

[zomurn]

I have the same problem.
To analyse this, I monitored Alfresco Tomcat server with JConsole.
I did a request from WebClient and saw all stacks traces from the http request thread (through JConsole topthread plugin)
By far the longest one was (with a refresh of stacks traces every second) :

java.net.SocketInputStream.socketRead0(Native Method)
java.net.SocketInputStream.read(SocketInputStream.java:129)
java.io.DataInputStream.readFully(DataInputStream.java:178)
java.io.DataInputStream.readFully(DataInputStream.java:152)
net.sourceforge.jtds.jdbc.SharedSocket.readPacket(SharedSocket.java:841)
net.sourceforge.jtds.jdbc.SharedSocket.getNetPacket(SharedSocket.java:722)
net.sourceforge.jtds.jdbc.ResponseStream.getPacket(ResponseStream.java:466)
net.sourceforge.jtds.jdbc.ResponseStream.read(ResponseStream.java:103)
net.sourceforge.jtds.jdbc.ResponseStream.peek(ResponseStream.java:88)
net.sourceforge.jtds.jdbc.TdsCore.wait(TdsCore.java:3928)
net.sourceforge.jtds.jdbc.TdsCore.executeSQL(TdsCore.java:1045)
net.sourceforge.jtds.jdbc.JtdsStatement.executeSQLQuery(JtdsStatement.java:465)
net.sourceforge.jtds.jdbc.JtdsPreparedStatement.executeQuery(JtdsPreparedStatement.java:777)
org.apache.commons.dbcp.DelegatingPreparedStatement.executeQuery(DelegatingPreparedStatement.java:92)
org.hibernate.jdbc.AbstractBatcher.getResultSet(AbstractBatcher.java:186)
org.hibernate.loader.Loader.getResultSet(Loader.java:1787)
org.hibernate.loader.Loader.scroll(Loader.java:2286)
org.hibernate.loader.hql.QueryLoader.scroll(QueryLoader.java:441)
org.hibernate.hql.ast.QueryTranslatorImpl.scroll(QueryTranslatorImpl.java:390)
org.hibernate.engine.query.HQLQueryPlan.performScroll(HQLQueryPlan.java:245)
org.hibernate.impl.SessionImpl.scroll(SessionImpl.java:1206)
org.hibernate.impl.QueryImpl.scroll(QueryImpl.java:67)
org.alfresco.repo.node.db.hibernate.HibernateNodeDaoServiceImpl$16.doInHibernate(HibernateNodeDaoServiceImpl.java:2191)
org.springframework.orm.hibernate3.HibernateTemplate.execute(HibernateTemplate.java:372)
org.springframework.orm.hibernate3.HibernateTemplate.execute(HibernateTemplate.java:338)
org.alfresco.repo.node.db.hibernate.HibernateNodeDaoServiceImpl.getChildAssocs(HibernateNodeDaoServiceImpl.java:2197)
sun.reflect.GeneratedMethodAccessor547.invoke(Unknown Source)
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
java.lang.reflect.Method.invoke(Method.java:597)
org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:304)
org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:182)
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:149)
org.alfresco.repo.transaction.TransactionalDaoInterceptor.invoke(TransactionalDaoInterceptor.java:68)
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:171)
org.alfresco.repo.domain.hibernate.DirtySessionMethodInterceptor.invoke(DirtySessionMethodInterceptor.java:381)
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:171)
org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204)
$Proxy2.getChildAssocs(Unknown Source)
org.alfresco.repo.node.db.DbNodeServiceImpl.getChildAssocs(DbNodeServiceImpl.java:1417)
org.alfresco.repo.node.AbstractNodeServiceImpl.getChildAssocs(AbstractNodeServiceImpl.java:591)
sun.reflect.GeneratedMethodAccessor479.invoke(Unknown Source)
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
java.lang.reflect.Method.invoke(Method.java:597)
org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:304)
org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:182)
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:149)
org.alfresco.repo.transaction.SingleEntryTransactionResourceInterceptor.invokeInternal(SingleEntryTransactionResourceInterceptor.java:169)
org.alfresco.repo.transaction.SingleEntryTransactionResourceInterceptor.invoke(SingleEntryTransactionResourceInterceptor.java:138)
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:171)
org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204)
$Proxy7.getChildAssocs(Unknown Source)
sun.reflect.GeneratedMethodAccessor479.invoke(Unknown Source)
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
java.lang.reflect.Method.invoke(Method.java:597)
org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:304)
org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:182)
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:149)
org.alfresco.repo.tenant.MultiTNodeServiceInterceptor.invoke(MultiTNodeServiceInterceptor.java:110)
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:171)
org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204)
$Proxy7.getChildAssocs(Unknown Source)
sun.reflect.GeneratedMethodAccessor479.invoke(Unknown Source)
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
java.lang.reflect.Method.invoke(Method.java:597)
org.alfresco.repo.service.StoreRedirectorProxyFactory$RedirectorInvocationHandler.invoke(StoreRedirectorProxyFactory.java:221)
$Proxy8.getChildAssocs(Unknown Source)
sun.reflect.GeneratedMethodAccessor479.invoke(Unknown Source)
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
java.lang.reflect.Method.invoke(Method.java:597)
org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:304)
org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:182)
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:149)
org.alfresco.repo.node.MLPropertyInterceptor.invoke(MLPropertyInterceptor.java:306)
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:171)
org.alfresco.repo.node.MLPropertyInterceptor.invoke(MLPropertyInterceptor.java:306)
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:171)
org.alfresco.repo.node.NodeRefPropertyMethodInterceptor.invoke(NodeRefPropertyMethodInterceptor.java:274)
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:171)
org.alfresco.repo.node.NodeRefPropertyMethodInterceptor.invoke(NodeRefPropertyMethodInterceptor.java:274)
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:171)
org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204)
$Proxy7.getChildAssocs(Unknown Source)
sun.reflect.GeneratedMethodAccessor479.invoke(Unknown Source)
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
java.lang.reflect.Method.invoke(Method.java:597)
org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:304)
org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:182)
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:149)
net.sf.acegisecurity.intercept.method.aopalliance.MethodSecurityInterceptor.invoke(MethodSecurityInterceptor.java:80)
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:171)
org.alfresco.repo.security.permissions.impl.ExceptionTranslatorMethodInterceptor.invoke(ExceptionTranslatorMethodInterceptor.java:49)
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:171)
org.alfresco.repo.audit.AuditComponentImpl.audit(AuditComponentImpl.java:275)
org.alfresco.repo.audit.AuditMethodInterceptor.invoke(AuditMethodInterceptor.java:69)
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:171)
org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:106)
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:171)
org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204)
$Proxy7.getChildAssocs(Unknown Source)
org.alfresco.repo.template.BaseContentNode.getChildren(BaseContentNode.java:280)


How can I optimize alfresco to respond faster to this "stack trace" ?

Thanks

My DB server is MS SQL Server 2005 with 3GB RAM, Xeon 2.5GHz quad core….and more for the app server.
That's NOT a problem of machine. DB fragmentation ? : there are about 70 000 document in repository.
EDIT : I realize that CPU was a long time at 100% on the DB server….are the query inefficient ? or does I need to do DB optimization ?

[sselvan]

@Munwar - Your explanation was great! In other hand, your book is a good read on Alfresco too. I recommend to many folks!

All -
In my setup, I uploaded only 1400 images via webdav and for almost 2 hours - no user was able to upload any file via the Web UI.
I use Alfresco 3.2 and MySQL in Linux machine. Is there any recommendation on CPU requirements, Database server size etc.,?
Any kind of best practices for performance!!

Any information around this will be very helpful. Anybody has it handy?

[leonk]

Any updates on this issue?
It's a shame that Alfresco that pretends to be a major Sharepoint competitor is not investing time to create good optimization manuals like Atlassian have.

[zaizi]

It's a shame that Alfresco that pretends to be a major Sharepoint competitor is not investing time to create good optimization manuals like Atlassian have.

There are number of resources on Alfresco Network. However, these are unfortunately for Enterprise customers. Kind of like JBoss in the early days. Software is free, but not the documentation.

Ainga