Horloge murale Java pleine GC très lente

Parfois, sur une machine de test (Windows), Java full GC prend plus de 20 secondes. Les journaux GC montrent que le temps real est très élevé, user est également élevé, mais pas aussi élevé (environ 3 secondes). Dans un cas, c'est:

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

Quelle pourrait être la raison? J'ai des soupçons mais je ne veux pas le dire maintenant.

Quel est le moyen le plus simple de découvrir quelle est la cause profonde? Si vous ne connaissez pas Windows mais que vous connaissez Linux, c'est également une option: les tests peuvent être réexécutés sur Linux.

Le processus a été lancé comme suit:

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

Je ne sais pas pourquoi NewSize, XX:MaxNewSize et SurvivorRatio sont utilisés. MaxPermSize est nécessaire car c'est un environnement OSGi. Les vidages de threads complets ne montrent rien de spécial.

Le journal complet de GCs complet est (désolé, 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]