memory leak with groovy template 1.5.6

[Chris Lu]

I have put up my site up and running for a while, and found the memory
usage just keep crawling up.

After several heap dump and comparison, I found the culprit is the
included groovy template engine. And there is a recent bug(13/Nov/2008)
fix for it.
http://jira.codehaus.org/browse/GROOVY-3147

So, if any one is using Play! in production, you may need to upgrade the
groovy engine to the latest 1.5.8 if possible.

Chris

[Guillaume Bort]

Hum, which exact version of Play! do you use ?

One of my site (www.shigeta.fr) using the stable3 release is runnning since 3 month and still use 48Mo of memory.
And the stable3 uses the groovy 1.5.6 too.

So perhaps it's a problem with a specific version of Play! ...

[Chris Lu]

I am using the version checked out from bzr.

Maybe not groovy problem. Just updated the groovy to latest release, but still seeing memory creeping up.

I can send you the heap dumps if you want. They are about 30M~70M, so email doesn't work.

Chris

Guillaume Bort wrote:

Hum, which exact version of Play! do you use ?

One of my site (www.shigeta.fr

) using the stable3 release is runnning since
3 month and still use 48Mo of memory.
And the stable3 uses the groovy 1.5.6 too.

So perhaps it's a problem with a specific version of Play! ...

2009/1/17 Chris Lu <chri...@gmail.com>

  

[Guillaume Bort]

I've run some tests using the sample forum application (which use JPA and Groovy templates).
The memory consumption is very stable. After 100 000 request the used heap down to 6Mo (which was
the value before the test). And the surviving generation number is very stable too.

Perhaps this application does not use a specific feature which could make Play! to leak. But
are you sure that the leak doesn't come from your application ?

Do you use the cache ? If yes be aware than the current "in memory" implementation is not ready to be used
in production (you should use memcached).

Guillaume.

[Chris Lu]

Upgrading to JDK 1.6.0u11 helps to lower the memory consumption, but not really solving the leaking problem.
Upgrading groovy to latest version doesn't help either.

Not exactly sure what's the leak. When I am doing "ab -n 100000 url" test, the memory stays the same.
But on production, the memory just keeps slowly creeping up. Maybe need to test all kinds of URL formats.
The leak is slow, but it is a leak.

Attached are the diff of 2 memory dump snapshots shows the increase of long[], and they come from groovy.
One is taken around starting for half an hour (after most initialization is done), the other is taken after one day.

I am sure the leak is not in the application. And I am using memcached.

Chris

Guillaume Bort wrote:

) using the stable3 release is runnning since
3 month and still use 48Mo of memory.
And the stable3 uses the groovy 1.5.6 too.

So perhaps it's a problem with a specific version of Play! ...

2009/1/17 Chris Lu <chri...@gmail.com> <chri...@gmail.com>

   I have put up my site up and running for a while, and found the memory
usage just keep crawling up.

After several heap dump and comparison, I found the culprit is the
included groovy template engine. And there is a recent bug(13/Nov/2008)
fix for it.http://jira.codehaus.org/browse/GROOVY-3147

So, if any one is using Play! in production, you may need to upgrade the
groovy engine to the latest 1.5.8 if possible.

Chris





    

--~--~---------~--~----~------------~-------~--~----~
Vous avez reçu ce message, car vous êtes abonné au groupe Groupe "play-framework" de Google Groupes.
 Pour transmettre des messages à ce groupe, envoyez un e-mail à 
l'adresse play-fr...@googlegroups.com
 Pour résilier votre abonnement à ce groupe, envoyez un e-mail à 
l'adresse play-framewor...@googlegroups.com
 Pour afficher d'autres options, visitez ce groupe à l'adresse http://groups.google.com/group/play-framework?hl=fr
-~----------~----~----~----~------~----~------~--~---


  

---

[Guillaume Bort]

Well,

I've never used YourKit, but from what I understand, the second screenshot shows only 132 instances of Long[] array.
If there is a memory leak, I'm not sure that it comes from these objects ...

---

[Chris Lu]

Right, only 132 total, but 104 of them(shown on the first screenshot) comes after one day's production.

I guess it could be caused by malformed url hits, or some exceptions, etc.

Chris

Here is a composed output of "ps auxf" for the play! java process during different times. You can see it just keep creeping up.

it consumes too much memory and will bomb out with OOM whether call it memory leak or not.

USER       PID %CPU %MEM    VSZ   RSS TTY      STAT START   TIME COMMAND

501      25773  0.0 10.2 256248 107388 pts/0   Sl    2008   0:19                  |   \_ java -javaagent:/home/publisher/app/play/fr

501      25773  0.0 10.3 256248 108148 pts/0   Sl    2008   0:24                  |   \_ java -javaagent:/home/publisher/app/play/fr

501      25773  0.0 10.3 256248 108564 pts/0   Sl    2008   0:26                  |   \_ java -javaagent:/home/publisher/app/play/fr

501      25773  0.0 10.6 258944 111504 pts/0   Sl    2008   0:38                  |   \_ java -javaagent:/home/publisher/app/play/fr

501      25773  0.0 10.8 259048 113516 pts/0   Sl    2008   0:49                  |   \_ java -javaagent:/home/publisher/app/play/fr

501      25773  0.0 11.2 262444 117480 pts/0   Sl    2008   0:57                  |   \_ java -javaagent:/home/publisher/app/play/fr

501      25773  0.0 11.3 262836 118564 pts/0   Sl    2008   1:26                  |   \_ java -javaagent:/home/publisher/app/play/fr

501      25773  0.0 11.3 262444 119180 pts/0   Sl    2008   1:57  |               |   \_ java -javaagent:/home/publisher/app/play/fr

501      25773  0.0 11.3 262444 119260 pts/0   Sl    2008   2:02  |               |   \_ java -javaagent:/home/publisher/app/play/fr

501      25773  0.0 11.3 262444 119304 pts/0   Sl    2008   2:05  |               |   \_ java -javaagent:/home/publisher/app/play/fr

501      25773  0.0 11.3 262444 119304 pts/0   Sl    2008   2:05  |               |   \_ java -javaagent:/home/publisher/app/play/fr

501      25773  0.0 11.3 262444 119324 pts/0   Sl    2008   2:07  |               |   \_ java -javaagent:/home/publisher/app/play/fr

501      25773  0.0 11.3 262444 119404 pts/0   Sl    2008   2:12  |               |   \_ java -javaagent:/home/publisher/app/play/fr

501      25773  0.0 11.4 262444 119596 ?       Sl    2008   2:25  \_ java -javaagent:/home/publisher/app/play/framework/play.jar -Xm

501      25773  0.0 11.4 262444 120208 ?       Sl    2008   2:32  \_ java -javaagent:/home/publisher/app/play/framework/play.jar -Xm

501      25773  0.0 11.4 262444 120252 ?       Sl    2008   2:35  \_ java -javaagent:/home/publisher/app/play/framework/play.jar -Xm

501      25773  0.0 11.4 262444 120288 ?       Sl    2008   2:37  \_ java -javaagent:/home/publisher/app/play/framework/play.jar -Xm

501      25773  0.0 11.5 262444 120612 ?       Sl    2008   2:54  \_ java -javaagent:/home/publisher/app/play/framework/play.jar -Xm

501      25773  0.0 11.5 262444 121124 ?       Sl    2008   3:17  \_ java -javaagent:/home/publisher/app/play/framework/play.jar -Xm

501      25773  0.0 11.7 262768 123076 ?       Sl    2008   4:22  \_ java -javaagent:/home/publisher/app/play/framework/play.jar -Xm

501      25773  0.0 11.7 262768 123164 ?       Sl    2008   4:29  \_ java -javaagent:/home/publisher/app/play/framework/play.jar -Xm

501      25773  0.0 12.1 266380 127012 ?       Sl    2008   4:38  \_ java -javaagent:/home/publisher/app/play/framework/play.jar -Xm

501      25773  0.0 12.1 266380 127808 ?       Sl    2008   5:29  \_ java -javaagent:/home/publisher/app/play/framework/play.jar -Xm

--
Chris Lu
-------------------------
Instant Scalable Full-Text Search On Any Database/Application
site: http://www.dbsight.net
demo: http://search.dbsight.com
Lucene Database Search in 3 minutes: http://wiki.dbsight.com/index.php?title=Create_Lucene_Database_Search_in_3_minutes
DBSight customer, a shopping comparison site, (anonymous per request) got 2.6 Million Euro funding!

[jf....@gmail.com]

Hi,

From what I understand from your screenshots, having a diff of +132
long after a day running does not looks like the memory problem comes
from here. By "will bomb out with OOM", do you mean at the system
level or at the java level ? Does your operating system kills your
java process, or is the VM complaining about a
java.lang.OutOfMemoryException ? How much memory does your system
have ? Have you set a -Xmx in your conf/application.conf file ?


Regards,
Jean-François

> On Sun, Jan 18, 2009 at 2:51 PM, Guillaume Bort <guillaume.b...@gmail.com>wrote:
>
>
>
> > Well,
>
> > I've never used YourKit, but from what I understand, the second screenshot
> > shows only 132 instances of Long[] array.
> > If there is a memory leak, I'm not sure that it comes from these objects
> > ...
>

> >> On Sat, Jan 17, 2009 at 9:52 PM, Chris Lu <chris...@gmail.com> <chris...@gmail.com> wrote:
>
> >>   I am using the version checked out from bzr.
>
> >> Maybe not groovy problem. Just updated the groovy to latest release, but
> >> still seeing memory creeping up.
>
> >> I can send you the heap dumps if you want. They are about 30M~70M, so email
> >> doesn't work.
>
> >> Chris
>
> >> Guillaume Bort wrote:
>
> >> Hum, which exact version of Play! do you use ?
>
> >> One of my site (www.shigeta.fr
> >> ) using the stable3 release is runnning since
> >> 3 month and still use 48Mo of memory.
> >> And the stable3 uses the groovy 1.5.6 too.
>
> >> So perhaps it's a problem with a specific version of Play! ...
>

> >> 2009/1/17 Chris Lu <chris...@gmail.com> <chris...@gmail.com> <chris...@gmail.com> <chris...@gmail.com>

>
> >>    I have put up my site up and running for a while, and found the memory
> >> usage just keep crawling up.
>
> >> After several heap dump and comparison, I found the culprit is the
> >> included groovy template engine. And there is a recent bug(13/Nov/2008)
> >> fix for it.http://jira.codehaus.org/browse/GROOVY-3147
>
> >> So, if any one is using Play! in production, you may need to upgrade the
> >> groovy engine to the latest 1.5.8 if possible.
>
> >> Chris
>

> >> ------------------------------

>
> --
> Chris Lu
> -------------------------
> Instant Scalable Full-Text Search On Any Database/Application
> site:http://www.dbsight.net
> demo:http://search.dbsight.com

> Lucene Database Search in 3 minutes:http://wiki.dbsight.com/index.php?title=Create_Lucene_Database_Search...

> DBSight customer, a shopping comparison site, (anonymous per request) got
> 2.6 Million Euro funding!
>

>  image_png_part
> 56KAfficherTélécharger

[Chris Lu]

ok. The long[] may be the wrong scapegoat. Here are some new memory snapshot comparison.

The screenshots showed problem with java.nio.DirectByteBuffer.
Snapshots f611_0,f611_1,f611_2 are taken with around 10 hours interval, with DirectByteBuffer increased by +375, +719.

This bug showed some explanation about it.
https://issues.apache.org/jira/browse/DIRMINA-391
This bug matches my scenario. Even I set the -Xms and -Xmx, the memory keeps creeping up. And looks like it's fixed in some release before 04/Jul/2007 in 2.0-SNAPSHOT

So, when is the Play! default mina-core-2.0.0-M2-SNAPSHOT.jar is created?
I am going to test it with the latest mina jar, but it'll take some time.

BTW: I am using JDK 1.6u11

Chris

[Chris Lu]

Bummer! Just found I can not simply upgrade the mina library. Got an
exception when replacing the default mina-core-2.0.0-M2-SNAPSHOT.jar
with the latest mina-core-2.0.0-M4.jar

Chris

Exception in thread "main" java.lang.NoClassDefFoundError:
org/apache/mina/common/IoFilter
Caused by: java.lang.ClassNotFoundException: org.apache.mina.common.IoFilter
at java.net.URLClassLoader$1.run(URLClassLoader.java:200)
at java.security.AccessController.doPrivileged(Native Method)
at java.net.URLClassLoader.findClass(URLClassLoader.java:188)
at java.lang.ClassLoader.loadClass(ClassLoader.java:306)
at sun.misc.Launcher$AppClassLoader.loadClass(Launcher.java:276)
at java.lang.ClassLoader.loadClass(ClassLoader.java:251)
at java.lang.ClassLoader.loadClassInternal(ClassLoader.java:319)

[Chris Lu]

Requesting to upgrade to latest mina release.

Reason 1: the java.nio.DirectByteBuffer problem.
Reason 2: There is another mina bug also, which is fixed already,
https://issues.apache.org/jira/browse/DIRMINA-633

Chris

16:20:03,499 ERROR ~ Caught in Server !
org.apache.mina.filter.codec.ProtocolDecoderException:
java.lang.IllegalArgumentException: Failed to decode the url-encoded
content. (Hexdump: 50 4F 53 54 20 2F 67 75 65 73 74 73 61 76 65 2E 61 73
70 20 48 54 54 50 2F 31 2E 30 0D 0A 48 6F 73 74 3A 20 66 6F 72 75 6D 2E
73 68 75 71 69 61 6E 6A 69 2E 63 6F 6D 0D 0A 58 2D 52 65 61 6C 2D 49 50
3A 20 31 32 32 2E 32 33 30 2E 36 39 2E 32 32 0D 0A 58 2D 46 6F 72 77 61
72 64 65 64 2D 46 6F 72 3A 20 31 32 32 2E 32 33 30 2E 36 39 2E 32 32 0D
0A 43 6F 6E 6E 65 63 74 69 6F 6E 3A 20 63 6C 6F 73 65 0D 0A 41 63 63 65
70 74 3A 20 69 6D 61 67 65 2F 67 69 66 2C 20 69 6D 61 67 65 2F 78 2D 78
62 69 74 6D 61 70 2C 20 69 6D 61 67 65 2F 6A 70 65 67 2C 20 69 6D 61 67
65 2F 70 6A 70 65 67 2C 20 61 70 70 6C 69 63 61 74 69 6F 6E 2F 76 6E 64
2E 6D 73 2D 70 6F 77 65 72 70 6F 69 6E 74 2C 20 61 70 70 6C 69 63 61 74
69 6F 6E 2F 76 6E 64 2E 6D 73 2D 65 78 63 65 6C 2C 20 61 70 70 6C 69 63
61 74 69 6F 6E 2F 6D 73 77 6F 72 64 2C 20 61 70 70 6C 69 63 61 74 69 6F
6E 2F 78 2D 73 68 6F 63 6B 77 61 76 65 2D 66 6C 61 73 68 2C 20 2A 2F 2A
0D 0A 52 65 66 65 72 65 72 3A 20 68 74 74 70 3A 2F 2F 66 6F 72 75 6D 2E
73 68 75 71 69 61 6E 6A 69 2E 63 6F 6D 2F 67 75 65 73 74 73 61 76 65 2E
61 73 70 0D 0A 41 63 63 65 70 74 2D 4C 61 6E 67 75 61 67 65 3A 20 7A 68
2D 63 6E 0D 0A 43 6F 6E 74 65 6E 74 2D 54 79 70 65 3A 20 61 70 70 6C 69
63 61 74 69 6F 6E 2F 78 2D 77 77 77 2D 66 6F 72 6D 2D 75 72 6C 65 6E 63
6F 64 65 64 0D 0A 50 72 6F 78 79 2D 43 6F 6E 6E 65 63 74 69 6F 6E 3A 20
4B 65 65 70 2D 41 6C 69 76 65 0D 0A 55 73 65 72 2D 41 67 65 6E 74 3A 20
4D 6F 7A 69 6C 6C 61 2F 34 2E 30 20 28 63 6F 6D 70 61 74 69 62 6C 65 3B
20 4D 53 49 45 20 36 2E 30 3B 20 57 69 6E 64 6F 77 73 20 4E 54 20 35 2E
31 3B 20 41 6C 65 78 61 20 54 6F 6F 6C 62 61 72 29 0D 0A 43 6F 6E 74 65
6E 74 2D 4C 65 6E 67 74 68 3A 20 33 32 34 0D 0A 50 72 61 67 6D 61 3A 20
6E 6F 2D 63 61 63 68 65 0D 0A 63 4F 4F 6B 49 65 3A 20 0D 0A 0D 0A 67 75
65 73 74 6E 61 6D 65 3D B7 BD BD DC 26 70 61 73 73 77 6F 72 64 3D 26 73
68 65 6E 67 66 65 6E 3D 25 43 44 25 46 38 25 44 33 25 44 31 26 66 72 6F
6D 3D B7 BD BD DC 26 65 6D 61 69 6C 3D 66 61 6E 67 6A 69 65 6A 69 65 40
31 36 33 2E 63 6F 6D 26 68 6F 6D 65 70 61 67 65 3D 68 74 74 70 3A 2F 2F
77 77 77 2E 6E 6F 71 69 61 6E 2E 63 6E 26 6F 69 63 71 3D 36 32 35 34 31
38 35 26 73 65 6C 65 63 74 46 6F 6E 74 3D 25 44 31 25 41 31 25 44 34 25
46 31 25 44 37 25 44 36 25 43 43 25 45 35 26 73 65 6C 65 63 74 43 6F 6C
6F 75 72 3D 30 26 73 65 6C 65 63 74 62 67 43 6F 6C 6F 75 72 3D 30 26 73
65 6C 65 63 74 3D 25 44 37 25 44 36 25 42 41 25 43 35 26 53 75 62 6D 69
74 3D 2B 25 42 37 25 41 32 2B 25 42 31 25 45 44 2B 26 63 6F 6E 74 65 6E
74 3D 5B 55 52 4C 3D 68 74 74 70 3A 2F 2F 77 77 77 2E 6A 74 79 69 6E 67
2E 63 6E 5D BB C6 C9 AB B5 E7 D3 B0 5B 2F 55 52 4C 5D 5B 55 52 4C 3D 68
74 74 70 3A 2F 2F 77 77 77 2E 6E 6F 71 69 61 6E 2E 63 6E 5D C2 D7 C0 ED
B5 E7 D3 B0 5B 2F 55 52 4C 5D)
at
org.apache.mina.filter.codec.ProtocolCodecFilter.messageReceived(ProtocolCodecFilter.java:180)
at
org.apache.mina.common.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:405)
at
org.apache.mina.common.DefaultIoFilterChain.access$1200(DefaultIoFilterChain.java:40)
at
org.apache.mina.common.DefaultIoFilterChain$EntryImpl$1.messageReceived(DefaultIoFilterChain.java:823)
at
org.apache.mina.common.DefaultIoFilterChain$HeadFilter.messageReceived(DefaultIoFilterChain.java:607)
at
org.apache.mina.common.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:405)
at
org.apache.mina.common.DefaultIoFilterChain.fireMessageReceived(DefaultIoFilterChain.java:399)
at
org.apache.mina.common.AbstractPollingIoProcessor.read(AbstractPollingIoProcessor.java:434)
at
org.apache.mina.common.AbstractPollingIoProcessor.process(AbstractPollingIoProcessor.java:396)
at
org.apache.mina.common.AbstractPollingIoProcessor.process(AbstractPollingIoProcessor.java:388)
at
org.apache.mina.common.AbstractPollingIoProcessor.access$400(AbstractPollingIoProcessor.java:43)
at
org.apache.mina.common.AbstractPollingIoProcessor$Worker.run(AbstractPollingIoProcessor.java:706)
at
org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:51)
at
java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
at java.lang.Thread.run(Thread.java:619)
Caused by: java.lang.IllegalArgumentException: Failed to decode the
url-encoded content.
at
org.apache.asyncweb.common.DefaultHttpRequest.setContent(DefaultHttpRequest.java:288)
at
org.apache.asyncweb.common.HttpRequestDecodingStateMachine$3$3.finishDecode(HttpRequestDecodingStateMachine.java:187)
at
org.apache.mina.filter.codec.statemachine.FixedLengthDecodingState.decode(FixedLengthDecodingState.java:58)
at
org.apache.mina.filter.codec.statemachine.DecodingStateMachine.decode(DecodingStateMachine.java:75)
at
org.apache.mina.filter.codec.statemachine.DecodingStateProtocolDecoder.decode(DecodingStateProtocolDecoder.java:65)
at
org.apache.mina.filter.codec.ProtocolCodecFilter.messageReceived(ProtocolCodecFilter.java:170)
... 15 more
Caused by: java.nio.charset.MalformedInputException: Input length = 1
at java.nio.charset.CoderResult.throwException(CoderResult.java:260)
at
org.apache.mina.common.AbstractIoBuffer.getString(AbstractIoBuffer.java:1121)
at
org.apache.asyncweb.common.DefaultHttpRequest.setContent(DefaultHttpRequest.java:286)
... 20 more

[Guillaume Bort]

Well,

Please tell use what is exactly your memory problem ? Do you have some OutOfMemoryException ? If yes then it's clearly a memory leak.
If not I think this is normal.

The screenshot you sent show that some DirectBuffer were allocated since the last snapshot. But it is not necessarily a memory leak. Each request
allocate a lot of DirectBuffer. But if the JVM has enough free heap, they will not be garbaged early ... especially using the -server mode in a 1.6 JVM.
Do you run the garbage collector several times before to take the memory snapshot ?

From my test there is no memory leak in our mina version. But they show that in -server mode the NonHeap memory grows a lot during first requests.
When the JVM is run in -server mode it will do a lot of code analysis, optimizations, and caches during the first run. I think it took almost 50000 requests
to be totally stabilized. And during this time the NonHeap memory grows for about 15Mo in my application. But it's totally normal ...

[jf....@gmail.com]

Hi,

I'm sorry, I still do not know if your java complains about something
like a "OutOfMemory" exception, or if your system kills your java
process. Suspense.... rising.... while you tell us what is
happening :) (output of "free -m" on your server before running play, -
Xmx and -Xms parameters used)

In https://issues.apache.org/jira/browse/DIRMINA-391, Trustin ends
saying" we switched the default buffer type to 'heap' in 2.0-
SNAPSHOT", that was just before 2.0.0-M2 (the one in play). I checked
in the sources, there's a useDirect*** set to false in IoBuffer, so
it's less likely that one, but might be. I'll check it depeer,
depending on how you answer the first question :)

Btw, what are the units of the column size of your screenshots ? b,
kb, mb ?

Regards,
Jean-François

On Jan 19, 7:59 pm, Chris Lu <chris...@gmail.com> wrote:
> ok. The long[] may be the wrong scapegoat. Here are some new memory
> snapshot comparison.
>
> The screenshots showed problem with java.nio.DirectByteBuffer.
> Snapshots f611_0,f611_1,f611_2 are taken with around 10 hours interval,
> with DirectByteBuffer increased by +375, +719.
>

> This bug showed some explanation about it.https://issues.apache.org/jira/browse/DIRMINA-391

>  ScreenHunter_03 Jan. 19 10.48.jpg
> 165KViewDownload
>
>  ScreenHunter_04 Jan. 19 10.48.jpg
> 172KViewDownload

[jf....@gmail.com]

Hi,

That's what they say: do not use M builds, we might change the api and
play the "break your app" game.
Play uses mina + asyncweb (protocol stack). So both play and asyncweb
are tied to that version of mina. We'll upgrade the stack if needed.

Regards,
Jean-Francois

[Chris Lu]

Thanks a lot for trying to help! Well, I thought I am clear enough, but seems not. My system is not throwing OOM yet. It's a production busy system, and I do leave enough system memory left, but I set -Xmx=64m only.

The current output of "free" is:
             total       used       free     shared    buffers     cached
Mem:       1048576     872240     176336          0          0          0
-/+ buffers/cache:     872240     176336

The 176336k free memory used to be around 199000k when Play is started and warmed up.

Here are the memory usages taken during different times with "ps auxf" command.
501      21836  0.0 13.2 270532 138916 ?       Sl    2008   3:37  \_ java -javaagent:/home/publisher/app/play/framework/play.jar -Xm
501      21836  0.0 13.2 270532 139032 ?       Sl    2008   4:32  \_ java -javaagent:/home/publisher/app/play/framework/play.jar -Xm
501      21836  0.0 13.3 271280 140248 ?       Sl    2008   8:47  \_ java -javaagent:/home/publisher/app/play/framework/play.jar -Xm
501      21836  0.0 14.1 272540 148896 ?       Sl    2008  13:37  \_ java -javaagent:/home/publisher/app/play/framework/play.jar -Xm
501      21836  0.0 15.4 281260 161996 ?       Sl    2008  16:29  \_ java -javaagent:/home/publisher/app/play/framework/play.jar -Xm

This is after one day's usage. (16:29 is just cpu minutes) And I am sure it'll get out of memory eventually. I set the -Xms=64m -Xmx=64m, and not expecting memory to grow such.
And I am sure the requests I have on production is way way past 50000. It's way out of the warming up process.

I think no leak in your test is because the tests do not include all different kinds of requests from the wild wide web. And some of them Mina doesn't handle well, leaving memory wasted.
The DirectByteBuffer is not managed well by JVM. Maybe reading this would help: http://www.jroller.com/gkorland/entry/java_s_memory_isn_t

The DirectByteBuffer problem is also in these bugs, but not resolvable because it's JDK problem.
https://issues.apache.org/jira/browse/DIRMINA-576
So I am not sure whether the latest mina resolved this problem, but it'll be better if I can try it.

Please let me know if I am not clear on some details.

Chris

[jf....@gmail.com]

Hi,

We'll run some more tests, this looks interesting. Thanks for your
input, and stay tuned !

Regards,
Jean-Francois

On Jan 19, 11:53 pm, Chris Lu <chris...@gmail.com> wrote:
> Thanks a lot for trying to help! Well, I thought I am clear enough, but
> seems not. My system is not throwing OOM yet. It's a production busy
> system, and I do leave enough system memory left, but I set -Xmx=64m only.
>
> The current output of "free" is:
>              total       used       free     shared    buffers     cached

> Mem:       1048576     872240     *176336*          0          0          0

> -/+ buffers/cache:     872240     176336
>
> The 176336k free memory used to be around 199000k when Play is started
> and warmed up.
>
> Here are the memory usages taken during different times with "ps auxf"
> command.
> 501      21836  0.0 13.2 270532 138916 ?       Sl    2008   3:37  \_
> java -javaagent:/home/publisher/app/play/framework/play.jar -Xm
> 501      21836  0.0 13.2 270532 139032 ?       Sl    2008   4:32  \_
> java -javaagent:/home/publisher/app/play/framework/play.jar -Xm
> 501      21836  0.0 13.3 271280 140248 ?       Sl    2008   8:47  \_
> java -javaagent:/home/publisher/app/play/framework/play.jar -Xm
> 501      21836  0.0 14.1 272540 148896 ?       Sl    2008  13:37  \_
> java -javaagent:/home/publisher/app/play/framework/play.jar -Xm

> 501      21836  0.0 15.4 281260 161996 ?       Sl    2008  *16:29*  \_

> java -javaagent:/home/publisher/app/play/framework/play.jar -Xm
>
> This is after one day's usage. (16:29 is just cpu minutes) And I am sure
> it'll get out of memory eventually. I set the -Xms=64m -Xmx=64m, and not
> expecting memory to grow such.
> And I am sure the requests I have on production is way way past 50000.
> It's way out of the warming up process.
>
> I think no leak in your test is because the tests do not include all
> different kinds of requests from the wild wide web. And some of them
> Mina doesn't handle well, leaving memory wasted.
> The DirectByteBuffer is not managed well by JVM. Maybe reading this
> would help:http://www.jroller.com/gkorland/entry/java_s_memory_isn_t
>
> The DirectByteBuffer problem is also in these bugs, but not resolvable

> because it's JDK problem.https://issues.apache.org/jira/browse/DIRMINA-576

> >     j...@taldius.net <mailto:j...@taldius.net> wrote:
> >>     Hi,
>
> >>     From what I understand from your screenshots, having a diff of +132
> >>     long after a day running does not looks like the memory problem comes
> >>     from here. By "will bomb out with OOM", do you mean at the system
> >>     level or at the java level ? Does your operating system kills your
> >>     java process, or is the VM complaining about a
> >>     java.lang.OutOfMemoryException ? How much memory does your system
> >>     have ? Have you set a -Xmx in your conf/application.conf file ?
>
> >>     Regards,
> >>     Jean-François
>

> >>>     On Sun, Jan 18, 2009 at 2:51 PM, Guillaume Bort <guillaume.b...@gmail.com> <mailto:guillaume.b...@gmail.com>wrote:
>
> >>>>     Well,
>
> >>>>     I've never used YourKit, but from what I understand, the second screenshot
> >>>>     shows only 132 instances of Long[] array.
> >>>>     If there is a memory leak, I'm not sure that it comes from these objects
> >>>>     ...
>

> >>>>     On Sun, Jan 18, 2009 at 10:50 PM, Chris Lu <chris...@gmail.com> <mailto:chris...@gmail.com> wrote:
>
> >>>>>      Upgrading to JDK 1.6.0u11 helps to lower the memory consumption, but not
> >>>>>     really solving the leaking problem.
> >>>>>     Upgrading groovy to latest version doesn't help either.
>
> >>>>>     Not exactly sure what's the leak. When I am doing "ab -n 100000 url" test,
> >>>>>     the memory stays the same.
> >>>>>     But on production, the memory just keeps slowly creeping up. Maybe need to
> >>>>>     test all kinds of
>

> ...
>
> read more »

[Chris Lu]

Thanks for helping!

BTW: the system memory keep falling, and some other processes could not be started due to lack of memory. So I have to restart the Play!.
The actual memory used is made bold here.
Before restart:
501      21836  0.0 17.1 292176 180348 ?       Sl    2008  20:53  \_ java -javaagent:/home/publisher/app/play/framework/play.jar -Xm
After restart:
501      32174  0.0  9.5 250108 100016 pts/1   Sl    2008   0:12                  |   \_ java -javaagent:/home/publisher/app/play/fr
After 15 minutes:
501      32174  0.0 10.3 253420 108684 pts/1   Sl    2008   0:22                  |   \_ java -javaagent:/home/publisher/app/play/fr

Maybe too much to ask: Is it possible to switch from of mina+asyncweb to Grizzly?
It has much better performance according to page 19 of this slide http://developers.sun.com/learning/javaoneonline/2007/pdf/TS-2992.pdf
It's from grizzly's authors. But with that much difference, maybe it worth a try.
And since they are from Sun, they should know how to use NIO better.

Thanks!

Chris

[Guillaume Bort]

Before to try to change something, we must know what is the real problem.

The JVM memory can't grow indefinitely. By default the JVM allow only 64Mo of direct memory access (you can adjust this value with
-XX:MaxDirectMemorySize). And mina is not the only piece of Play! making a lot of IO. The memcached client use NIO a lot too.

About your DirectByteBuffer problem. Are you sure that these objects cannot be garbaged ? (please run manually the garbage collector
several time before to take the snapshot). If these objects cannot be garbaged, who maintain them ?

From my test, Play! does not maintain any DirectByteBuffer objects (only the boot classloader use them through the ZipFile objects)

[Guillaume Bort]

I think I can reproduce the problem.
Stay tuned.

[Guillaume Bort]

Well,

I've detected a memory leak (no visible in the Java heap but the process memory was leaking).
The cause was the Java cryptography extensions (JCE). Each time the session is signed
the process lost some memory.

However I'm not sure which JVM are affected by this bug. MacOS X 1.5 sure. But I will test on
Java 1.6 linux tonight.

[Chris Lu]

Thanks. I noticed the problem with SSL also, and I am on linux, jdk1.6u11.

Another thing that can be quickly tested is:
If I hit a non-existing URL, which gives 404 errors, like
ab -n 1000000 -c 10 "http://localhost:9000/asdfasdf"
The memory goes up quickly. Memory growth will eventually stop. I think
it's filling the direct buffer, hitting the limit.
My point is, in this case, is it really necessary to create new objects
every time just to return some constant strings?

Thanks!

Chris

Guillaume Bort wrote:
> Well,
>

>>>> 501 21836 0.0 17.1 292176 *180348* ? Sl 2008 20:53 \_

>>>> java -javaagent:/home/publisher/app/play/framework/play.jar -Xm
>>>> After restart:

>>>> 501 32174 0.0 9.5 250108 *100016* pts/1 Sl 2008

>>>> 0:12 | \_ java -javaagent:/home/publisher/app/play/fr
>>>> After 15 minutes:

>>>> 501 32174 0.0 10.3 253420 *108684* pts/1 Sl 2008

[Guillaume Bort]

Well,
It seems that there is no memory leak in JCE with linux (the bug was only reported on MacOS).

The memory is very stable. Even with bad URL requests there is no problem
at all (excepted mina traces ...).

It's totally normal that the memory grows up quickly in prod mode. The garbage collector is very lazy.

Remember that the memory used by the Java process is not equals to the Java heap.

It should be almost equals to :
   Heap (64Mo for exemple)
+ Non-Heap (PermGen 64Mo and CodeCache 64Mo for exemple ).
+ The JVM process itself !
+ Some direct memory can be allocated (for direct IO operations).

You can limit each of these value with appropriate JVM options ...

What say jmap on your process ?

The Java process memory should not grows indefinitly. Howewer most of our Play! application consume about (120-150Mo)
If your application is big and has a lot of requests the numbers you show in your posts does not appear exessives ...

But if you don't stop the application, what happens ? OutOfMemoryException ? Where ? What is the max amount of memory
ever used by your application ?

[Chris Lu]

Thanks. That helps. The 120-150M range comforts me. The previous 30MB sized example just make mine looks way too huge.
After changing -Xmx to 32M yesterday, the memory usage stabilized around 131M now.

But repeatedly creating a new IOBuffer for the same text when serving 404 errors doesn't seem right.
In HttpHandler.java, line 127:
  response.setContent(IoBuffer.wrap(errorHtml.getBytes("utf-8")));
Same for some other error handling. Reusing it as some constant would save the memory usage.

[jf....@gmail.com]

Hi all,

I've runned some tests, and here are a few observations. First, let's
share some basics about java vm, or at least what I understand of
it.There are several "kind" of memory usage in a vm:
* The executable code of the vm binary (Vm)
* The code loaded by the vm (Cd)
* Java objects are allocated on the heap (Hp)
* Other memory (Ot: directmemory, hotspot's code metrics, cache, and
so on...)

So, the system memory usage I see when I cat /proc/java_pid/status is
more less something like:
m = Vm + Cd + Hp + Ot

Remember: Xmx and Xms set the upper and lower bounds of Hp... So the
rest is up to the "adaptative" abilities of the vm, HotSpot "knows"
what's good for you (most of the time).

So, when creating a play app, setting Xmx to 128m and serving static
data:
100k requests: resident 128m
run gc-gc-gc: the heap usage decreases to 5mb,sys usage 128.

100k requests again: sys memory usage is 155mb: that's bad, it looks
like a memory leak.

Ok, let's run 5 000k request, I'd like to see oom killer in action.
But after 5 000k requests, system memory usage is still at 155mb...
So, leak or not ? I'd tend to say no. Let's experiment a few things:
edit your play script, try to remove the -server option of the
JAVA_ARGS in prod mode (see: http://java.sun.com/docs/hotspot/HotSpotFAQ.html#compiler_types
client mode uses less memory). You could try -
XX:MaxDirectMemorySize=10m, or reducing the Xmx size to 64mb or 32mb
(depends on your app here...). I had similar memory behaviour reports
with Jsmtpd, with people switching from java 5 to java 6, so, when
using a jdk 5.0 + Xmx32m + -XX:MaxDirectMemorySize=10m in client
mode, after a
ab -k -c 100 -n 5000000 http://127.0.0.1:9000/public/afile
the java process won't use more than 70mb on my machine (Linux i686),
instead of the 160mb out of the box. Obviously, you'll kill your raw
performances doing this. The usual trade of memory for cpu usage. Or
not. Leak. Or not, I can't tell, just observations.

Could you let your app run more requests (let's say 40x actual) and
tell us about your system memory usage ?

Regards,
Jean-Francois

On Jan 20, 8:06 pm, Chris Lu <chris...@gmail.com> wrote:
> Thanks. I noticed the problem with SSL also, and I am on linux, jdk1.6u11.
>
> Another thing that can be quickly tested is:
> If I hit a non-existing URL, which gives 404 errors, like
>   ab -n 1000000 -c 10 "http://localhost:9000/asdfasdf"
> The memory goes up quickly. Memory growth will eventually stop. I think
> it's filling the direct buffer, hitting the limit.
> My point is, in this case, is it really necessary to create new objects
> every time just to return some constant strings?
>
> Thanks!
>
> Chris
>
> Guillaume Bort wrote:
> > Well,
>
> > I've detected a memory leak (no visible in the Java heap but the process
> > memory was leaking).
> > The cause was the Java cryptography extensions (JCE). Each time the session
> > is signed
> > the process lost some memory.
>
> > However I'm not sure which JVM are affected by this bug. MacOS X 1.5 sure.
> > But I will test on
> > Java 1.6 linux tonight.
>

> > On Tue, Jan 20, 2009 at 6:10 PM, Guillaume Bort <guillaume.b...@gmail.com>wrote:
>
> >> I think I can reproduce the problem.
> >> Stay tuned.
>

> >> On Tue, Jan 20, 2009 at 11:34 AM, Guillaume Bort <guillaume.b...@gmail.com

>
> >>> wrote:
>
> >>> Before to try to change something, we must know what is the real problem.
>
> >>> The JVM memory can't grow indefinitely. By default the JVM allow only 64Mo
> >>> of direct memory access (you can adjust this value with
> >>> -XX:MaxDirectMemorySize). And mina is not the only piece of Play! making a
> >>> lot of IO. The memcached client use NIO a lot too.
>
> >>> About your DirectByteBuffer problem. Are you sure that these objects
> >>> cannot be garbaged ? (please run manually the garbage collector
> >>> several time before to take the snapshot). If these objects cannot be
> >>> garbaged, who maintain them ?
>
> >>> From my test, Play! does not maintain any DirectByteBuffer objects (only
> >>> the boot classloader use them through the ZipFile objects)
>

> ...
>
> read more »

[Guillaume Bort]

Yes,

It's sure that if you want to save memory, running the -client Hotspot will consume less memory (but performance will be less too).

You can try to limit Java Heap size (Xms,Xmx), DirectMemorySize (-XX:MaxDirectMemorySize), PermGen size(-XX:MaxPermSize),
CodeCache size (-XX:ReservedCodeCacheSize), ...

Moreover I'm not sure of how exact is the memory usage displayed by utilities like ps and top. It seems that they include the Shared memory
into the process memory ...

I think like Jef, that out of the box, Hotspot try to do the best. But you can tune it a lot. And Hotspot is very complicated...

[Guillaume Bort]

About the error pages. It's right that if the page content is really static you can consider that it's a waste of time and memory to
compute them again and again.

But :

- Sometime the error pages are no so static. Think about of a 404 page trying to determine how it could help you by analysing the request URL ...
- 404 and 500 should be exceptions. So optimize them should not improve a lot your application performance ... !
- For each request you except to generate a response. A 404 response should not be different than a normal response ...

But yes we could provide some application.conf which could enable a "static 404 and 500" cache ...
Not sure however it will help you a lot to consume less memory.

[Chris Lu]

Thanks for all the helps.

One more nitpicking: I can only use REMAINING_ARGS to pass those extra jvm memory options to play for now. The "play" script doesn't take it correctly.

The jvm.memory variable in conf/application.conf doesn't take the other parameters except Xms Xmx.
If I append "-XX:MaxDirectMemorySize=32m" directly, and start play via "play run"
Exception in thread "main" java.lang.NoClassDefFoundError: 32m
Caused by: java.lang.ClassNotFoundException: 32m

    at java.net.URLClassLoader$1.run(URLClassLoader.java:200)
    at java.security.AccessController.doPrivileged(Native Method)
    at java.net.URLClassLoader.findClass(URLClassLoader.java:188)
    at java.lang.ClassLoader.loadClass(ClassLoader.java:306)
    at sun.misc.Launcher$AppClassLoader.loadClass(Launcher.java:276)
    at java.lang.ClassLoader.loadClass(ClassLoader.java:251)
    at java.lang.ClassLoader.loadClassInternal(ClassLoader.java:319)

Chris

[Chris Lu]

Thanks a lot. Removing "-server" helps a lot!
Now, without "-server" and with "-Xmx32m", starting memory usages now drops to 62M, after some warm up, it's 84M(although creeping up), but almost half of 144M that using "-server" and "-Xmx64m". This makes big difference since I am on a vps with 512M memory.

And removing "-server" is not really "kill the performance" for a web app. My test shows non-noticeable difference regarding the "Requests per second" or "Time per request". In reality, the framework, or the java process takes a little percentage of the time for the whole request. The SQL queries takes most part of the time.

Chris

[Jean-Francois Poux]

Hi,

You could try with a jdk 5.0, it should also help lowering your memory usage. Try to observe the behaviour with more requests if you can (like 500k - 1M).


Regards,
Jean-Francois