Two Applications Compared At The JVM Level - Startling Stuff
Posted by Mike Brunt at 11:37 AM
16 comments - Categories:
This posting has two important messages, in my opinion. Load test all applications and code to least 150% of the expect before deploying to production and before deploying anything to production make sure that the JVM has been tuned, the "out of the box" settings after a ColdFusion install are not good enough.
What I am showing here are Garbage Collection logging results from two different clients, because I want to illustrate the immense differences we encounter with different clients and environments. The first example is from a client using two of the prominent CFC based frameworks...
{Heap before GC invocations=40639 (full 193):
PSYoungGen total 125120K, used 102464K [0x5bbf0000, 0x64c60000, 0x64c60000)
eden space 102464K, 100% used [0x5bbf0000,0x62000000,0x62000000)
from space 22656K, 0% used [0x63640000,0x63640000,0x64c60000)
to space 22720K, 0% used [0x62000000,0x62000000,0x63630000)
PSOldGen total 1183296K, used 1183291K [0x13860000, 0x5bbf0000, 0x5bbf0000)
object space 1183296K, 99% used [0x13860000,0x5bbeefb8,0x5bbf0000)
PSPermGen total 196608K, used 97179K [0x03860000, 0x0f860000, 0x13860000)
object space 196608K, 49% used [0x03860000,0x09746d20,0x0f860000)
15339.053: [Full GC [PSYoungGen: 102464K->26228K(125120K)] [PSOldGen: 1183291K->1183291K(1183296K)] 1285755K->1209520K(1308416K) [PSPermGen: 97179K->97179K(196608K)], 3.1595979 secs] [Times: user=3.16 sys=0.00, real=3.16 secs]
In this case the server has been running for 15,339 seconds and in that time there have been 40,639 garbage collections and 193 Full GC's. Full GC's are challenging because all other processes stop during a Full GC, so we do not want too many. This snapshot is taken when the server is dying, mainly because we are out of Old Generation space because that is where all objects end up. Despite, 193 Full GC's some lasting for seconds the objects in the Old Generation cannot be collected because they still have references to them from the application I could even say Application Scope. In this dying phase of the server, Full GC's are also occurring every few seconds, In essence, the garbage collector is frantically trying to do a good job.
Here is example two, from a different client and this time using no well known CFC based frameworks.
{Heap before GC invocations=3989 (full 62):
PSYoungGen total 702528K, used 649818K [0x000000011c9f0000, 0x000000014b4e0000, 0x000000014b7f0000)
eden space 646464K, 100% used [0x000000011c9f0000,0x0000000144140000,0x0000000144140000)
from space 56064K, 5% used [0x0000000147e20000,0x0000000148166860,0x000000014b4e0000)
to space 59200K, 0% used [0x0000000144140000,0x0000000144140000,0x0000000147b10000)
PSOldGen total 1152000K, used 699717K [0x000000008fff0000, 0x00000000d64f0000, 0x000000011c9f0000)
object space 1152000K, 60% used [0x000000008fff0000,0x00000000bab41478,0x00000000d64f0000)
PSPermGen total 196608K, used 121178K [0x000000007fff0000, 0x000000008bff0000, 0x000000008fff0000)
object space 196608K, 61% used [0x000000007fff0000,0x0000000087646b98,0x000000008bff0000)
198572.058: [GC [PSYoungGen: 649818K->11108K(705664K)] 1349535K->711718K(1857664K), 0.0431385 secs]
The difference is quite marked. In 198,572 seconds there have been 3,989 garbage collections of which 62 were Full GC's.
Back to my original point, had our first client here been able to fully test the framework and applications they would not have ended up with the issues they have and what makes it worse is their ColdFusion application is totally enmeshed in the framework and cannot easily be gotten out of there.
Joshua Cyr wrote on 07/12/10 11:57 AM
Can you clarify a bit more about what in the frameworks (if really related to the framework) was causing the additional full GC? Was it due to so much being loaded in the app scope from the framework, or the client code? What did they do to resolve?