Orologio da parete GC completo Java molto lento

Question

A volte, su un computer di prova (Windows), il GC completo di Java richiede più di 20 secondi. I log del GC mostrano che il tempo dello real è molto alto, user è anche alto, ma non alto (circa 3 secondi). In un caso, è:

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

Quale potrebbe essere il motivo? Ho un sospetto ma non voglio dirlo adesso.

Qual è il modo più semplice per scoprire quale sia la causa principale? Se non conosci Windows ma conosci Linux, anche questa è un'opzione: i test potrebbero essere eseguiti su Linux.

Il processo è stato avviato come segue:

"%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 

Non so il motivo per cui vengono utilizzati NewSize, XX:MaxNewSize e SurvivorRatio. MaxPermSize è necessario perché è un ambiente OSGi. I dump di thread completi non mostrano nulla di speciale.

il log completo della piena GC è (mi dispiace, lunga):

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

Il problema si è verificato assegnando più memoria heap alla JVM rispetto alla memoria fisica. Oltre a eseguire 3 JVM, anche un'istanza MongoDB era in esecuzione sulla stessa macchina. La quantità di memoria fisica era chiaramente inferiore alla memoria heap allocata (java -Xmx...)

Quindi il problema era la memoria virtuale.

Answer 2

Purtroppo, questo può accadere abbastanza facilmente con il collettore G1 spazzatura.

I dump di thread e heap sono sempre un ottimo modo per capire cosa sta realmente accadendo in un sistema.

+1 al suggerimento da verificare per finalizzare.

Informazioni sulla guida verso una correzione: Qui ci sono alcuni VM options per cambiare strategia gc o ottimizzare la strategia esistente. Livello superiore Java 7 gc information.