File APIs for Java Developers
Manipulate DOC, XLS, PPT, PDF and many others from your application.
http://aspose.com/file-tools
The moose likes Performance and the fly likes Any pointers why my app does so much minor GC? Big Moose Saloon
  Search | Java FAQ | Recent Topics | Flagged Topics | Hot Topics | Zero Replies
Register / Login


Win a copy of Android Security Essentials Live Lessons this week in the Android forum!
JavaRanch » Java Forums » Java » Performance
Bookmark "Any pointers why my app does so much minor GC?" Watch "Any pointers why my app does so much minor GC?" New topic
Author

Any pointers why my app does so much minor GC?

Nathan Russell
Ranch Hand

Joined: Aug 18, 2004
Posts: 75
Hi.
I wonder if anyone can give me a few pointers about something. I am supporting a servlet based application. I did not write it myself but do have access to the development team who did.
When the application is under reasonable load the JVM does an awful lot of minor GC - so much so that after a period of time the CPU can spend more time GC'ing than servicing requests. The following is a snippet from the app server's (JBoss AS 4.2.2 GA) stdout:


286.003: [GC [PSYoungGen: 112112K->2256K(113088K)] 553228K->445058K(1045184K), 0.0173570 secs]
286.359: [GC [PSYoungGen: 112208K->2376K(113152K)] 555010K->446947K(1045248K), 0.0175590 secs]
286.713: [GC [PSYoungGen: 112328K->2344K(113152K)] 556899K->448603K(1045248K), 0.0166680 secs]
287.050: [GC [PSYoungGen: 112488K->2192K(113216K)] 558747K->450168K(1045312K), 0.0179490 secs]
287.394: [GC [PSYoungGen: 112336K->2144K(113408K)] 560312K->451767K(1045504K), 0.0147850 secs]
287.738: [GC [PSYoungGen: 112544K->2336K(113408K)] 562167K->453580K(1045504K), 0.0176960 secs]
288.069: [GC [PSYoungGen: 112736K->2208K(113408K)] 563980K->455106K(1045504K), 0.0154590 secs]
288.431: [GC [PSYoungGen: 112736K->2296K(113408K)] 565634K->456927K(1045504K), 0.0161960 secs]
288.772: [GC [PSYoungGen: 112824K->2456K(113600K)] 567455K->458709K(1045696K), 0.0176930 secs]
289.290: [GC [PSYoungGen: 113176K->1904K(113600K)] 569429K->459875K(1045696K), 0.0165690 secs]
289.656: [GC [PSYoungGen: 112624K->2584K(113472K)] 570595K->462013K(1045568K), 0.0176020 secs]
289.986: [GC [PSYoungGen: 113176K->2152K(113536K)] 572605K->463419K(1045632K), 0.0175200 secs]


The way I'm reading this is that the system is doing a minor GC 3 times a second! and each minor GC is freeing up about 110MB. To come to this conslusion I've intepreted each line as:
[PSYoungGen: 112112K->2256K(113088K)] which means the young generation heap started at 112112K and ended at 2256K which means it released 109856K; and that the 113088K in brackets is the total heap size of the young generation. Hopefully thats the right way to interpret these logs.

Anyway, clearly its doing a lot of minor GC! I know I can tune the JVM and the way GC operates - heap sizes, ratios etc etc - but before I get into that I want to try to understand why all this memory becomes available for GC so frequently!

To produce the above I've artifically applied load with jmeter. My jmeter test is a 10 thread test running for 5 minutes. Each thread submits a single HTTP request to the servlet. The HTTP session timeout is 15 seconds. The above GC stats were produced with this jmeter test. The jmeter test ran for 5 minutes and in that time issued 5684 requests at an average throughput of 18.5 requests per second (I'm going to round that up to 20). I have taken a heap dump of the system under load and the development team can see each of the sessions and tell me that each session is using about 250K. So ...
In 1 second we make 20 requests. Each request results in a session of 250K. Each session lives for 15 seconds. Therefore session memory usage is 20 X 250K X 15 = 75000K
So, in any 15 second period, I can account for 75MB of memory.
I cant account for 110MB every second!!!

Where / how should I look to account for this massive amount of memory usage?
Any pointers would be very much appreciated;

Cheers

Nathan
Nathan Russell
Ranch Hand

Joined: Aug 18, 2004
Posts: 75
In support of my posting, I've run the gc logs through GCViewer (http://www.tagtraum.com/gcviewer.html); and have attached the screenshot - might mean something to someone, but to my untrained eye 5.792GB/sec of garbage collection is going some!!!



[Thumbnail for gcScreenshot.jpg]

R van Vliet
Ranch Hand

Joined: Nov 10, 2007
Posts: 144
Nathan Russell wrote:In support of my posting, I've run the gc logs through GCViewer (http://www.tagtraum.com/gcviewer.html); and have attached the screenshot - might mean something to someone, but to my untrained eye 5.792GB/sec of garbage collection is going some!!!


At the risk of stating the obvious, is the servlet creating a lot of short lived object instances while processing a request? Simple memory profiling will probably give you the answers you need.
 
 
subject: Any pointers why my app does so much minor GC?
 
Similar Threads
tomcat 3.3.1 takes a high time for Minor GC using JDK 1.4.2 build 28
GC - Young generation promotion can't be guaranteed
Any advice how to tune GC?
help me to analyz GC log
Interupt Gc log