FullGC at start-up even before application deployment?

[elshafei.mostafa]

I am performing tuning benchmarks on a web application that is running on JBoss AS4.2.

What I have noticed is that the GC log starts always with a full GC at the server start-up even before the application is deployed.

Can someone explain to me this behavior? There is plenty of free memory in the young, tenured and PermGen. Why is this happening??

FWIW, here is the GC log:

15.464: [Full GC [PSYoungGen: 44456K->0K(458752K)] [ParOldGen: 0K->4385K(1572864K)]
44456K->4385K(2031616K) [PSPermGen: 11565K->11554K(262144K)], 0.9427300 secs]
64.382: [GC [PSYoungGen: 393216K->30720K(458752K)] 397601K->35105K(2031616K), 0.1768945 secs]
105.965: [GC [PSYoungGen: 423936K->38912K(458752K)] 428321K->43297K(2031616K), 0.4344201 secs]

Thanks in advance for any guidance.

[rhusar]

Just shooting this in the wild, but maybe something is calling System.gc()? I am not sure why this is a performance problem for you, because at this point the server is only starting and the application is just getting deployed, so no clients suffer from slow response times, etc. But if its a problem maybe you could try using -XX:-DisableExplicitGC ?

[wdfink]

It depends also to the start parameter of the JVM, e.g. Xms Xmx and whether the complete memory is allocated or virtual (see startup and boot.log to see full JVM params).

Also I recommend to use the latest JVM version of 1.5 (if you use this), but remember the 1.6 will be better and often faster (depend to the application).

[elshafei.mostafa]

Thx Radoslav Husar for answering. However, I tried -XX:-DisableExplicitGC and it still starts with a full GC. Even if its not a performace problem I would like to know the cause.

[elshafei.mostafa]

Here's my full JAVA OPTS configuration:

JAVA_OPTS="-Xms2g -Xmx2g -XX:NewSize=1g -XX:MaxNewSize=1g -XX:PermSize=256m -XX:MaxPermSize=256m -Xss256k -server -XX:+PrintGCDetails -XX:+PrintGCTimeStamps  -Xloggc:/X/X/X.log -XX:+UseParallelGC -XX:+UseParallelOldGC -XX:ParallelGCThreads=4 -XX:+AggressiveHeap -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/X/X/X -XX:+CMSClassUnloadingEnabled -XX:+CMSPermGenSweepingEnabled -Dsun.rmi.dgc.client.gcInterval=3600000 -Dsun.rmi.dgc.server.gcInterval=3600000"

[wdfink]

You use conflicting GC settings and I don't know what the JVM prefere in this case.

See http://www.oracle.com/technetwork/java/javase/tech/vmoptions-jsp-140102.html for detail on options.

I prefere UseParallelGC (only not Old) or 'UseConcMarkSweep AND CMSIncrementalMode' but the performance depends stron on the application memory footprint

So I recommend to not think about optimizing without measure the app, you should drop NewSize option and try to use NewParGC or CMS.

See what happen, you might watch with jstat or VisualVM.

Also I miss the information about the JVM version...

[elshafei.mostafa]

Thank Wolf-Dieter Fink for your reply. However, I can't understand what do you mean by conflicting GC?

What is the difference between ParallelGC and ParallelOldGc?? In the link you proposed it is mentiod that ParallelOldGc automatically enable ParallelGC.

I am always measuring what's happening by viewing GC logs and HeapDumps.

The JVM version is build 1.5.0_12-b04.

[wdfink]

OldParallelGC is an old implementation and the New implementation (from 1.4.1) should be better most times for JBoss and such long running servers. So drop -XX:UseParallelOldGC, also I would drop -XX:+CMS stuff.

Also fixing the eden space (NewSize) might have bad sideeffects because of reducing the OldGen.

I recommed to use the latest 1.5. JVM!

[elshafei.mostafa]

Concerning the JVM 1.5, its an organizational decision.

However, lets get to the main point of this discussion. Why there is always a full GC at the server startup?

[wdfink]

As "Radoslav Husar" mentioned there might be a explicit GC request from a deployed app (avoid with -XX:-DisableExplicitGC).

If not there is no exact point how a FullGC happen, it's a decision of the JVM depend on memory consumption of the different spaces and the frequence of minor GC.

Maybe jstat gives a hint (see oracle jstat documentation).

It might disapear with a new JVM version.

In other words I don't know exactly and if it do not disturb my application, e.g. happen very often, I don't care about

[elshafei.mostafa]

Okay. Thanks anyway.

[peterj]

The call to System.gc() is coded into the app server (or into one of the libraries it uses - I know the the RMI libraries like to make GC calls), I suspect as it transitions from bootstrap to the app server itself. I think it might also perform another GC or two after deployment or other major initialization activity. I think the idea behind this was to have the heap as clean of junk as possible before handling user requests. Of course, that made sense years ago when when servers didn't have that much memory and heaps were smaller. I have seen this behavior in JBoss AS release from 4.0.x up through 5.x (haven't monitored GC behavior on 6). I don't know if AS 7 stil lexhibits this behavior.

[rhusar]

I don't know if AS 7 stil lexhibits this behavior.

Right, AS7 does not do this anymore.

[ask4free]

Hi Mostafa,

mmm... that Full GC only takes 0.9427300 secs !! where's the problem? hehehehe... FullGCs are not a problem if they're not impacting on the user's response time. Just start the server and run some stress testing to check the heap performance of your application ( I remember of having FullGCs of 10 seconds in some stress testing, so it was really a huuuuuuge "little" problem ! however, it was finally solved by "playing" with some jvm parameters  )

take care!

[elshafei.mostafa]

Thanks Peter. That's what I wanted to know.

However, why when I use -XX:-DisableExplicitGC it still starts with a Full GC?