Interpret GC logs from jboss instance

Question

We are having a memory leak in production and my GC log is below. Clearly you can see how its an issue. However, i am unable to get a heap dump because by the time we find out its having issues its too late and the heap dump fails (even with the -F force option). So i am trying to find a way to know when its about to go down so i can take a heap dump. Is there anything i can see from these logs that show me its almost about to go down? thanks!

Desired survivor size 134217728 bytes, new threshold 19 (max 31)


2430254K->1903326K(2490368K), 0.1973860 secs]
235738.331: [GC
Desired survivor size 134217728 bytes, new threshold 18 (max 31)
 2427614K->1901667K(2490368K), 0.1901241 secs]
235752.709: [GC
Desired survivor size 134217728 bytes, new threshold 17 (max 31)
 2425955K->1915547K(2490368K), 0.2188464 secs]
235761.054: [GC
Desired survivor size 134217728 bytes, new threshold 16 (max 31)
 2439835K->1908633K(2490368K), 0.2318097 secs]
235772.360: [GC
Desired survivor size 134217728 bytes, new threshold 15 (max 31)
 2432921K->1911872K(2490368K), 0.2773868 secs]
235785.063: [GC-- 2436160K->2479951K(2490368K), 1.1930829 secs]
235786.257: [Full GC 2479951K->1648025K(2490368K), 14.7565160 secs]
235802.763: [GC
Desired survivor size 134217728 bytes, new threshold 14 (max 31)
 2172313K->1732187K(2490368K), 0.1365330 secs]
235813.227: [GC
Desired survivor size 134217728 bytes, new threshold 13 (max 31)
 2256475K->1707125K(2490368K), 0.1693956 secs]
235825.499: [GC
Desired survivor size 134217728 bytes, new threshold 12 (max 31)
 2231413K->1701399K(2490368K), 0.1122006 secs]
235837.714: [GC
Desired survivor size 134217728 bytes, new threshold 11 (max 31)
 2225687K->1719535K(2490368K), 0.1651736 secs]
235852.926: [GC
Desired survivor size 134217728 bytes, new threshold 10 (max 31)
 2243823K->1710722K(2490368K), 0.1077586 secs]
235868.371: [GC
Desired survivor size 134217728 bytes, new threshold 9 (max 31)
 2235010K->1714245K(2490368K), 0.1573498 secs]
235887.277: [GC
Desired survivor size 134217728 bytes, new threshold 8 (max 31)
 2238533K->1707476K(2490368K), 0.1199396 secs]
235900.744: [GC
Desired survivor size 134217728 bytes, new threshold 7 (max 31)
 2231764K->1706693K(2490368K), 0.2301796 secs]
235917.022: [GC
Desired survivor size 134217728 bytes, new threshold 6 (max 31)
 2230981K->1708947K(2490368K), 0.1099928 secs]
235927.712: [GC
Desired survivor size 134217728 bytes, new threshold 5 (max 31)
 2233235K->1729423K(2490368K), 0.1288758 secs]
235944.467: [GC
Desired survivor size 134217728 bytes, new threshold 4 (max 31)
 2253711K->1713068K(2490368K), 0.1224733 secs]
235957.965: [GC
Desired survivor size 134217728 bytes, new threshold 3 (max 31)
 2237356K->1721180K(2490368K), 0.1311912 secs]
235973.956: [GC
Desired survivor size 134217728 bytes, new threshold 2 (max 31)
 2245468K->1735845K(2490368K), 0.1293705 secs]
235988.761: [GC
Desired survivor size 134217728 bytes, new threshold 1 (max 31)
 2260133K->1725458K(2490368K), 0.0830605 secs]
236009.097: [GC
Desired survivor size 134217728 bytes, new threshold 1 (max 31)
 2249746K->1723956K(2490368K), 0.1006387 secs]
236021.587: [GC
Desired survivor size 134217728 bytes, new threshold 1 (max 31)
 2248244K->1732905K(2490368K), 0.1065915 secs]
236039.245: [GC
Desired survivor size 130154496 bytes, new threshold 2 (max 31)
 2257193K->1747624K(2494336K), 0.1222832 secs]
236048.721: [GC
Desired survivor size 124583936 bytes, new threshold 3 (max 31)
 2275880K->1748480K(2490368K), 0.1463785 secs]
236060.974: [GC
Desired survivor size 120127488 bytes, new threshold 4 (max 31)
 2276736K->1743277K(2504128K), 0.3267914 secs]
236067.175: [GC
Desired survivor size 134217728 bytes, new threshold 3 (max 31)
 2290733K->1926829K(2499776K), 0.2225210 secs]
236067.398: [Full GC 1926829K->1896112K(2499776K), 12.3642659 secs]
236081.066: [Full GC 2382464K->1961344K(2499776K), 13.0067024 secs]
236095.026: [Full GC 2382463K->1972662K(2499776K), 12.6296210 secs]
236108.585: [Full GC 2382463K->1891859K(2499776K), 14.3240448 secs]
236123.974: [Full GC 2382463K->1958937K(2499776K), 13.2175196 secs]
236138.415: [Full GC 2382463K->2004901K(2499776K), 13.5869753 secs]
236153.869: [Full GC 2382463K->2034151K(2499776K), 14.5268706 secs]
236169.379: [Full GC 2382463K->1981368K(2499776K), 17.8114037 secs]
236188.164: [Full GC 2382463K->2019591K(2499776K), 17.3729262 secs]
236206.151: [Full GC 2382464K->2054701K(2499776K), 17.2837183 secs]
236224.275: [Full GC 2382464K->2086992K(2499776K), 18.0917252 secs]
236242.927: [Full GC 2382464K->2007157K(2499776K), 18.8760425 secs]
236262.701: [Full GC 2382463K->2088662K(2499776K), 18.0601789 secs]
236281.380: [Full GC 2382463K->2120933K(2499776K), 19.5213884 secs]
236301.719: [Full GC 2382463K->2142691K(2499776K), 19.8563379 secs]
236322.349: [Full GC 2382463K->2093867K(2499776K), 23.5206669 secs]
236346.683: [Full GC 2382464K->2141437K(2499776K), 21.5340729 secs]
236368.895: [Full GC 2382464K->2165122K(2499776K), 20.9653757 secs]
236390.663: [Full GC 2373194K->2187083K(2499776K), 21.7935591 secs]
236413.582: [Full GC 2382464K->2162963K(2499776K), 22.9974370 secs]
236437.187: [Full GC 2382463K->2209939K(2499776K), 21.7474342 secs]
236459.506: [Full GC 2382463K->2208399K(2499776K), 21.1459454 secs]
236481.136: [Full GC 2382463K->2211743K(2499776K), 20.7020540 secs]
236502.553: [Full GC 2382463K->2174831K(2499776K), 23.5576392 secs]
236527.434: [Full GC 2382464K->2210273K(2499776K), 21.3455734 secs]
236549.321: [Full GC 2382464K->2220642K(2499776K), 20.4743578 secs]
236570.593: [Full GC 2382464K->2226068K(2499776K), 19.7456885 secs]
236590.796: [Full GC 2382464K->2170462K(2499776K), 22.6452983 secs]
236614.818: [Full GC 2382463K->2198514K(2499776K), 18.0114350 secs]
236633.619: [Full GC 2382463K->2224056K(2499776K), 20.3950715 secs]
236654.872: [Full GC

Here are my JVM options and we are using java 1.6. This is for a high traffic ecommerce site that gets about 15 million visitors a month. Thoughts?

 Xmx2560m -Xms2560m -Xss512k -XX:NewSize=768m -XX:MaxNewSize=768m -XX:MaxPermSize=512m -    XX:ParallelGCThreads=20 -XX:+UseParallelGC -XX:SurvivorRatio=4 -XX:TargetSurvivorRatio=90 -XX:MaxTenuringThreshold=31 -Dsun.rmi.dgc.c
lient.gcInterval=3600000 -Dsun.rmi.dgc.server.gcInterval=3600000 - Dsun.lang.ClassLoader.allowArraySyntax=true

Could you add your JVM options? And your VM version? – Aleš Dec 11 '12 at 21:27 — Aleš, Dec 11 '12 at 21:27

score 5 · Answer 1 · answered Dec 11 '12 at 18:24

You can use -XX:+HeapDumpOnOutOfMemoryError as a Java option to the JBoss startup. This will dump the heap when the out of memory error occurs. In addition, you may also want to specify -XX:HeapDumpPath to specify where the dump file goes (e.g -XX:HeapDumpPath=/disk2/dumps)

Lastly, consider using a tool like HPjmeter to visualize the loggc data you pasted in your question.

Aleš · Answer 2 · 2012-12-18T05:43:27.427

You can also try to print Class Histograms to see what classes occupy the Heap. Printing histograms is lighter than dumping the whole heap.

Compare the number of instances before/after a Full GC. This could tell you if there are any instances that are not being collected by Full GCs. Enable :

-XX:+PrintClassHistogramBeforeFullGC -XX:+PrintClassHistogramAfterFullGC
And then you can take histogram snapshots before the Full GCs hit you to see if any suspected class instances continue growing during the runtime of the application:

jmap -histo $pid

UPDATE: You can also use jstat to collect stats about each Heap Memory area, perhaps you will be able to detect some allocation patterns:

jstat -gcutil -t <pid> <interval> <number_of_samples>

Interpret GC logs from jboss instance

2 Answers2