Very slow Java full GC wall clock

Question

Sometimes, on a test machine (Windows), Java full GC takes over 20 seconds. The GC logs show that the real time is very high, user is also high, but not as high (around 3 seconds). In one case, it is:

21.2209796 secs [Times: user=3.76 sys=0.45, real=21.22 secs]

What could be the reason? I have a suspicion but don't want to say right now.

What is the easiest way to find out what the root cause is? If you don't know for Windows but know for Linux, that's an option as well: the tests could be re-run on Linux.

The process was started as follows:

"%JAVA_HOME%\bin\java.exe" -verbose:gc -XX:+PrintGCDetails 
    -XX:+PrintGCDateStamps -Xloggc:publish.gc.log 
    -XX:PermSize=256m -XX:MaxPermSize=1024m -Xms1024m 
    -Xmx3072m -XX:NewSize=352m -XX:MaxNewSize=352m 
    -XX:SurvivorRatio=6 

I don't know why NewSize, XX:MaxNewSize and SurvivorRatio are used. MaxPermSize is needed because it's an OSGi environment. Full thread dumps don't show anything special.

The complete log of full GCs is (sorry, long):

2014-05-06T21:38:18.735-0700: 150.261: [Full GC [PSYoungGen: 23614K->0K(309952K)] [PSOldGen: 693188K->311405K(688128K)] 716802K->311405K(998080K) [PSPermGen: 45120K->45120K(262144K)], 1.4533481 secs] [Times: user=1.45 sys=0.01, real=1.45 secs] 
2014-05-06T21:38:58.379-0700: 189.907: [Full GC [PSYoungGen: 1664K->0K(335488K)] [PSOldGen: 668139K->283959K(688128K)] 669803K->283959K(1023616K) [PSPermGen: 46688K->46688K(262144K)], 1.3466773 secs] [Times: user=1.34 sys=0.00, real=1.35 secs] 
2014-05-06T21:39:44.082-0700: 235.613: [Full GC [PSYoungGen: 15200K->0K(309184K)] [PSOldGen: 668643K->292329K(740800K)] 683843K->292329K(1049984K) [PSPermGen: 47733K->47733K(262144K)], 1.3649206 secs] [Times: user=1.36 sys=0.00, real=1.37 secs] 
2014-05-06T21:40:33.090-0700: 284.623: [Full GC [PSYoungGen: 10132K->0K(326528K)] [PSOldGen: 718669K->308144K(858368K)] 728802K->308144K(1184896K) [PSPermGen: 49596K->43403K(262144K)], 1.2978991 secs] [Times: user=1.31 sys=0.02, real=1.30 secs] 
2014-05-06T21:41:39.407-0700: 350.943: [Full GC [PSYoungGen: 37815K->0K(308160K)] [PSOldGen: 842013K->560237K(1236160K)] 879828K->560237K(1544320K) [PSPermGen: 43807K->43807K(262144K)], 1.2742777 secs] [Times: user=1.26 sys=0.00, real=1.27 secs] 
2014-05-06T21:43:36.782-0700: 468.324: [Full GC [PSYoungGen: 640K->0K(329216K)] [PSOldGen: 1233468K->536017K(1242944K)] 1234108K->536017K(1572160K) [PSPermGen: 44438K->44438K(262144K)], 1.4105887 secs] [Times: user=1.42 sys=0.00, real=1.41 secs] 
2014-05-06T21:44:28.404-0700: 519.948: [Full GC [PSYoungGen: 45056K->0K(315392K)] [PSOldGen: 1196082K->481770K(1266240K)] 1241138K->481770K(1581632K) [PSPermGen: 56883K->56883K(262144K)], 1.5773390 secs] [Times: user=1.58 sys=0.00, real=1.58 secs] 
2014-05-06T21:44:51.101-0700: 542.646: [Full GC [PSYoungGen: 30000K->0K(315392K)] [PSOldGen: 1213653K->330467K(1129664K)] 1243653K->330467K(1445056K) [PSPermGen: 106752K->105936K(262144K)], 1.9804992 secs] [Times: user=1.97 sys=0.02, real=1.98 secs] 
2014-05-06T21:45:33.230-0700: 584.777: [Full GC [PSYoungGen: 10301K->0K(319616K)] [PSOldGen: 1105014K->404683K(1248192K)] 1115315K->404683K(1567808K) [PSPermGen: 122771K->122771K(262144K)], 1.9884441 secs] [Times: user=2.00 sys=0.00, real=1.99 secs] 
2014-05-06T21:46:24.169-0700: 635.719: [Full GC [PSYoungGen: 8805K->0K(331136K)] [PSOldGen: 1226188K->506891K(1449856K)] 1234994K->506891K(1780992K) [PSPermGen: 140233K->140233K(262144K)], 2.4515626 secs] [Times: user=2.45 sys=0.01, real=2.45 secs] 
2014-05-06T21:47:34.131-0700: 705.683: [Full GC [PSYoungGen: 45054K->0K(315392K)] [PSOldGen: 1412337K->452967K(1474560K)] 1457392K->452967K(1789952K) [PSPermGen: 141009K->141009K(262144K)], 2.3155816 secs] [Times: user=2.31 sys=0.00, real=2.32 secs] 
2014-05-06T21:48:17.036-0700: 748.590: [Full GC [PSYoungGen: 36896K->0K(315392K)] [PSOldGen: 1392671K->354862K(1476608K)] 1429567K->354862K(1792000K) [PSPermGen: 141037K->140960K(262144K)], 2.2993743 secs] [Times: user=2.28 sys=0.00, real=2.30 secs] 
2014-05-06T21:49:23.816-0700: 815.374: [Full GC [PSYoungGen: 45036K->0K(315392K)] [PSOldGen: 1454959K->348537K(1509824K)] 1499995K->348537K(1825216K) [PSPermGen: 140963K->140963K(262144K)], 2.0907144 secs] [Times: user=2.09 sys=0.00, real=2.09 secs] 
2014-05-06T22:04:38.728-0700: 1729.490: [Full GC [PSYoungGen: 8464K->0K(345344K)] [PSOldGen: 1505186K->422020K(1583296K)] 1513651K->422020K(1928640K) [PSPermGen: 151404K->151404K(262144K)], 3.2901866 secs] [Times: user=2.47 sys=0.00, real=3.31 secs] 
2014-05-06T22:09:33.924-0700: 2023.858: [Full GC [PSYoungGen: 9766K->0K(342784K)] [PSOldGen: 1573919K->443383K(1656064K)] 1583686K->443383K(1998848K) [PSPermGen: 168657K->168657K(262144K)], 2.8910659 secs] [Times: user=2.59 sys=0.02, real=2.90 secs] 
2014-05-06T22:16:32.650-0700: 2442.188: [Full GC [PSYoungGen: 5856K->0K(346944K)] [PSOldGen: 1650623K->398157K(1666944K)] 1656479K->398157K(2013888K) [PSPermGen: 176960K->153660K(262144K)], 5.6906733 secs] [Times: user=2.89 sys=0.11, real=5.69 secs] 
2014-05-06T22:32:40.071-0700: 3409.496: [Full GC [PSYoungGen: 8566K->0K(346304K)] [PSOldGen: 1655315K->460797K(1767360K)] 1663882K->460797K(2113664K) [PSPermGen: 155265K->155265K(262144K)], 3.8090058 secs] [Times: user=2.81 sys=0.03, real=3.81 secs] 
2014-05-06T22:37:53.667-0700: 3723.074: [Full GC [PSYoungGen: 10243K->0K(347456K)] [PSOldGen: 1761438K->458285K(1835712K)] 1771681K->458285K(2183168K) [PSPermGen: 162919K->162919K(262144K)], 4.0235684 secs] [Times: user=2.47 sys=0.06, real=4.02 secs] 
2014-05-06T22:49:53.387-0700: 4442.757: [Full GC [PSYoungGen: 6441K->0K(348224K)] [PSOldGen: 1823902K->451504K(1872448K)] 1830344K->451504K(2220672K) [PSPermGen: 171778K->171778K(262144K)], 2.7130221 secs] [Times: user=2.62 sys=0.02, real=2.71 secs] 
2014-05-06T22:59:59.750-0700: 5049.088: [Full GC [PSYoungGen: 6708K->0K(347904K)] [PSOldGen: 1862823K->365106K(1845248K)] 1869532K->365106K(2193152K) [PSPermGen: 180349K->154273K(262144K)], 9.6984956 secs] [Times: user=2.74 sys=0.16, real=9.70 secs] 
2014-05-06T23:10:35.103-0700: 5684.407: [Full GC [PSYoungGen: 7984K->0K(352192K)] [PSOldGen: 1843448K->585793K(2170304K)] 1851433K->585793K(2522496K) [PSPermGen: 160183K->160183K(262144K)], 2.9633020 secs] [Times: user=2.93 sys=0.00, real=2.96 secs] 
2014-05-06T23:24:38.972-0700: 6528.232: [Full GC [PSYoungGen: 7376K->0K(345344K)] [PSOldGen: 2159450K->684719K(2346304K)] 2166826K->684719K(2691648K) [PSPermGen: 164349K->164349K(262144K)], 8.8952964 secs] [Times: user=3.39 sys=0.05, real=8.90 secs] 
2014-05-06T23:28:10.950-0700: 6740.198: [Full GC [PSYoungGen: 9085K->0K(346368K)] [PSOldGen: 2343205K->724235K(2458176K)] 2352290K->724235K(2804544K) [PSPermGen: 186771K->186771K(262144K)], 3.5238065 secs] [Times: user=3.29 sys=0.00, real=3.52 secs] 
2014-05-06T23:33:58.654-0700: 7087.885: [Full GC [PSYoungGen: 9551K->0K(349184K)] [PSOldGen: 2453964K->597434K(2438976K)] 2463516K->597434K(2788160K) [PSPermGen: 205948K->166988K(262144K)], 12.9225761 secs] [Times: user=3.59 sys=0.12, real=12.92 secs] 
2014-05-06T23:48:13.206-0700: 7942.391: [Full GC [PSYoungGen: 37116K->0K(313728K)] [PSOldGen: 2422753K->610864K(2500736K)] 2459870K->610864K(2814464K) [PSPermGen: 172487K->172487K(262144K)], 4.9881546 secs] [Times: user=3.28 sys=0.03, real=4.99 secs] 
2014-05-07T00:06:19.018-0700: 9028.146: [Full GC [PSYoungGen: 8589K->0K(321920K)] [PSOldGen: 2492066K->620020K(2538304K)] 2500655K->620020K(2860224K) [PSPermGen: 179888K->179888K(262144K)], 3.5624930 secs] [Times: user=3.10 sys=0.06, real=3.56 secs] 
2014-05-07T00:13:51.029-0700: 9480.134: [Full GC [PSYoungGen: 8736K->0K(330688K)] [PSOldGen: 2529168K->564197K(2540800K)] 2537904K->564197K(2871488K) [PSPermGen: 185765K->185765K(262144K)], 3.0340707 secs] [Times: user=2.95 sys=0.00, real=3.03 secs] 
2014-05-07T00:25:39.758-0700: 10188.825: [Full GC [PSYoungGen: 17725K->0K(315392K)] [PSOldGen: 2500502K->543855K(2582528K)] 2518228K->543855K(2897920K) [PSPermGen: 190076K->167636K(262144K)], 12.3609341 secs] [Times: user=3.77 sys=0.16, real=12.36 secs] 
2014-05-07T00:44:01.053-0700: 11290.063: [Full GC [PSYoungGen: 12896K->0K(347264K)] [PSOldGen: 2575016K->547199K(2621184K)] 2587912K->547199K(2968448K) [PSPermGen: 172447K->172447K(262144K)], 6.9150070 secs] [Times: user=3.15 sys=0.03, real=6.92 secs] 
2014-05-07T01:41:59.932-0700: 14768.758: [Full GC [PSYoungGen: 23293K->0K(337152K)] [PSOldGen: 2638852K->580840K(2712704K)] 2662146K->580840K(3049856K) [PSPermGen: 175259K->175259K(262144K)], 11.0725751 secs] [Times: user=3.32 sys=0.13, real=11.07 secs] 
2014-05-07T01:47:58.358-0700: 15127.165: [Full GC [PSYoungGen: 4176K->0K(315392K)] [PSOldGen: 2684820K->577513K(2738176K)] 2688996K->577513K(3053568K) [PSPermGen: 179064K->179064K(262144K)], 6.5166056 secs] [Times: user=3.01 sys=0.02, real=6.52 secs] 
2014-05-07T01:55:50.842-0700: 15599.624: [Full GC [PSYoungGen: 18686K->0K(319616K)] [PSOldGen: 2735388K->490034K(2761664K)] 2754074K->490034K(3081280K) [PSPermGen: 182650K->169843K(262144K)], 21.2209796 secs] [Times: user=3.76 sys=0.45, real=21.22 secs] 
2014-05-07T02:10:06.723-0700: 16455.460: [Full GC [PSYoungGen: 5561K->0K(321600K)] [PSOldGen: 2752252K->569179K(2785280K)] 2757813K->569179K(3106880K) [PSPermGen: 175120K->175120K(262144K)], 3.2125221 secs] [Times: user=3.15 sys=0.02, real=3.21 secs] 
2014-05-07T02:22:36.759-0700: 17205.457: [Full GC [PSYoungGen: 16798K->0K(330304K)] [PSOldGen: 2775106K->580162K(2785280K)] 2791904K->580162K(3115584K) [PSPermGen: 181215K->181215K(262144K)], 3.1422615 secs] [Times: user=3.10 sys=0.02, real=3.14 secs] 
2014-05-07T02:45:44.317-0700: 18592.941: [Full GC [PSYoungGen: 45049K->0K(315392K)] [PSOldGen: 2769893K->624026K(2785280K)] 2814943K->624026K(3100672K) [PSPermGen: 200552K->200552K(262144K)], 3.4347254 secs] [Times: user=3.29 sys=0.00, real=3.44 secs] 
2014-05-07T03:08:18.628-0700: 19947.181: [Full GC [PSYoungGen: 5888K->0K(315392K)] [PSOldGen: 2783516K->419007K(2699456K)] 2789404K->419007K(3014848K) [PSPermGen: 218078K->169930K(262144K)], 11.5310136 secs] [Times: user=3.17 sys=0.20, real=11.53 secs] 
2014-05-07T03:34:53.638-0700: 21542.106: [Full GC [PSYoungGen: 13636K->0K(315392K)] [PSOldGen: 2691667K->554781K(2785280K)] 2705303K->554781K(3100672K) [PSPermGen: 180174K->180174K(262144K)], 2.9612961 secs] [Times: user=2.95 sys=0.02, real=2.96 secs] 
2014-05-07T03:48:06.871-0700: 22335.298: [Full GC [PSYoungGen: 45029K->0K(315392K)] [PSOldGen: 2757384K->645664K(2785280K)] 2802414K->645664K(3100672K) [PSPermGen: 191439K->191439K(262144K)], 4.0145124 secs] [Times: user=3.20 sys=0.05, real=4.01 secs] 
2014-05-07T03:52:48.829-0700: 22617.241: [Full GC [PSYoungGen: 9744K->0K(315392K)] [PSOldGen: 2773296K->575320K(2785280K)] 2783041K->575320K(3100672K) [PSPermGen: 199506K->199506K(262144K)], 3.2600004 secs] [Times: user=3.20 sys=0.00, real=3.26 secs] 
2014-05-07T03:57:47.110-0700: 22915.506: [Full GC [PSYoungGen: 10560K->0K(315392K)] [PSOldGen: 2771785K->436271K(2748608K)] 2782345K->436271K(3064000K) [PSPermGen: 215637K->170286K(262144K)], 6.1593551 secs] [Times: user=3.21 sys=0.05, real=6.16 secs] 
2014-05-07T04:05:46.130-0700: 23394.501: [Full GC [PSYoungGen: 45046K->0K(315392K)] [PSOldGen: 2699071K->624303K(2785280K)] 2744117K->624303K(3100672K) [PSPermGen: 182442K->182442K(262144K)], 3.2887751 secs] [Times: user=3.25 sys=0.00, real=3.29 secs] 
2014-05-07T04:09:00.646-0700: 23589.007: [Full GC [PSYoungGen: 45044K->0K(315392K)] [PSOldGen: 2716819K->709830K(2785280K)] 2761863K->709830K(3100672K) [PSPermGen: 187436K->187436K(262144K)], 3.4306116 secs] [Times: user=3.40 sys=0.00, real=3.43 secs] 

Answer 1

The problem turned out to be allocating more heap memory to the JVM than there is physical memory. In addition to running 3 JVMs, a MongoDB instance was also running on the same machine. The amount of physical memory was clearly lower than the allocated heap memory (java -Xmx...)

So the problem was virtual memory trashing.