java - 为什么我的java young gc时间越来越长？

Question

我有一个代理服务器项目，它每分钟处理大约 60,000 个请求。我发现 gc 时间是有线的。 young gc的时间越来越长。

我的 gc 日志

2015-05-16T07:58:25.660+0800: 359.833: [GC2015-05-16T07:58:25.660+0800: 359.833: [ParNew: 11426343K->459256K(13165760K), 0.1861630 secs] 11426343K->459256K(18285760K), 0.1864010 secs] [Times: user=1.77 sys=0.01, real=0.18 secs] 
2015-05-16T07:59:23.398+0800: 417.571: [GC2015-05-16T07:59:23.398+0800: 417.571: [ParNew: 11430776K->509760K(13165760K), 0.2254760 secs] 11430776K->509760K(18285760K), 0.2257140 secs] [Times: user=2.16 sys=0.01, real=0.22 secs] 
2015-05-16T08:00:14.522+0800: 468.695: [GC2015-05-16T08:00:14.522+0800: 468.695: [ParNew: 11481280K->445475K(13165760K), 0.1242330 secs] 11481280K->445475K(18285760K), 0.1245000 secs] [Times: user=1.14 sys=0.00, real=0.13 secs] 
2015-05-16T08:01:04.571+0800: 518.745: [GC2015-05-16T08:01:04.571+0800: 518.745: [ParNew: 11416995K->503881K(13165760K), 0.1334070 secs] 11416995K->503881K(18285760K), 0.1336370 secs] [Times: user=1.24 sys=0.01, real=0.13 secs] 
2015-05-16T08:01:55.006+0800: 569.179: [GC2015-05-16T08:01:55.006+0800: 569.180: [ParNew: 11475401K->483236K(13165760K), 0.1277270 secs] 11475401K->483236K(18285760K), 0.1279680 secs] [Times: user=1.18 sys=0.01, real=0.13 secs] 
2015-05-16T08:02:53.500+0800: 627.673: [GC2015-05-16T08:02:53.500+0800: 627.673: [ParNew: 11454756K->567960K(13165760K), 0.1926360 secs] 11454756K->567960K(18285760K), 0.1928680 secs] [Times: user=1.84 sys=0.00, real=0.19 secs] 
2015-05-16T08:03:52.168+0800: 686.342: [GC2015-05-16T08:03:52.168+0800: 686.342: [ParNew: 11539480K->508020K(13165760K), 0.2197430 secs] 11539480K->508020K(18285760K), 0.2199800 secs] [Times: user=2.10 sys=0.00, real=0.22 secs] 
2015-05-16T08:04:47.986+0800: 742.159: [GC2015-05-16T08:04:47.986+0800: 742.159: [ParNew: 11479540K->483623K(13165760K), 0.2012450 secs] 11479540K->483623K(18285760K), 0.2014780 secs] [Times: user=1.90 sys=0.01, real=0.20 secs] 
2015-05-16T08:05:43.425+0800: 797.598: [GC2015-05-16T08:05:43.425+0800: 797.598: [ParNew: 11455143K->499526K(13165760K), 0.2690110 secs] 11455143K->539947K(18285760K), 0.2692350 secs] [Times: user=2.42 sys=0.03, real=0.27 secs] 
2015-05-16T08:06:42.983+0800: 857.156: [GC2015-05-16T08:06:42.983+0800: 857.156: [ParNew: 11471046K->478080K(13165760K), 0.3499460 secs] 11511467K->585893K(18285760K), 0.3501800 secs] [Times: user=3.29 sys=0.00, real=0.35 secs] 
2015-05-16T08:07:43.872+0800: 918.045: [GC2015-05-16T08:07:43.872+0800: 918.045: [ParNew: 11449600K->464130K(13165760K), 0.3170180 secs] 11557413K->574042K(18285760K), 0.3172810 secs] [Times: user=3.09 sys=0.00, real=0.32 secs] 
2015-05-16T08:08:39.809+0800: 973.983: [GC2015-05-16T08:08:39.809+0800: 973.983: [ParNew: 11435650K->450610K(13165760K), 0.3563240 secs] 11545562K->562538K(18285760K), 0.3565520 secs] [Times: user=3.45 sys=0.01, real=0.36 secs] 
2015-05-16T08:09:36.247+0800: 1030.420: [GC2015-05-16T08:09:36.247+0800: 1030.420: [ParNew: 11422130K->475736K(13165760K), 0.3948640 secs] 11534058K->594208K(18285760K), 0.3951130 secs] [Times: user=3.86 sys=0.00, real=0.40 secs] 
2015-05-16T08:10:28.126+0800: 1082.299: [GC2015-05-16T08:10:28.126+0800: 1082.299: [ParNew: 11447256K->539808K(13165760K), 0.4354400 secs] 11565728K->662084K(18285760K), 0.4357260 secs] [Times: user=4.24 sys=0.01, real=0.44 secs] 
2015-05-16T08:11:18.431+0800: 1132.604: [GC2015-05-16T08:11:18.431+0800: 1132.605: [ParNew: 11511328K->506115K(13165760K), 0.4649390 secs] 11633604K->632306K(18285760K), 0.4651880 secs] [Times: user=4.55 sys=0.01, real=0.47 secs] 
2015-05-16T08:12:11.087+0800: 1185.261: [GC2015-05-16T08:12:11.087+0800: 1185.261: [ParNew: 11477635K->597355K(13165760K), 0.5022610 secs] 11603826K->727427K(18285760K), 0.5025890 secs] [Times: user=4.92 sys=0.00, real=0.50 secs] 
2015-05-16T08:13:08.187+0800: 1242.360: [GC2015-05-16T08:13:08.187+0800: 1242.360: [ParNew: 11568875K->482715K(13165760K), 0.5356720 secs] 11698947K->617514K(18285760K), 0.5359150 secs] [Times: user=5.26 sys=0.00, real=0.54 secs] 
2015-05-16T08:14:06.023+0800: 1300.196: [GC2015-05-16T08:14:06.023+0800: 1300.196: [ParNew: 11454235K->477157K(13165760K), 0.5269100 secs] 11589034K->632904K(18285760K), 0.5271740 secs] [Times: user=5.13 sys=0.01, real=0.53 secs] 
2015-05-16T08:15:01.303+0800: 1355.477: [GC2015-05-16T08:15:01.303+0800: 1355.477: [ParNew: 11448677K->655192K(13165760K), 0.6135160 secs] 11604424K->822286K(18285760K), 0.6138640 secs] [Times: user=6.02 sys=0.00, real=0.61 secs] 
2015-05-16T08:15:53.316+0800: 1407.489: [GC2015-05-16T08:15:53.316+0800: 1407.489: [ParNew: 11626712K->505502K(13165760K), 0.6275970 secs] 11793806K->683727K(18285760K), 0.6278620 secs] [Times: user=6.18 sys=0.00, real=0.63 secs] 
2015-05-16T08:16:37.701+0800: 1451.874: [GC2015-05-16T08:16:37.701+0800: 1451.874: [ParNew: 11477022K->493920K(13165760K), 0.1365010 secs] 11655247K->676600K(18285760K), 0.1367440 secs] [Times: user=1.28 sys=0.01, real=0.14 secs] 
2015-05-16T08:17:28.338+0800: 1502.511: [GC2015-05-16T08:17:28.338+0800: 1502.511: [ParNew: 11465440K->485473K(13165760K), 0.1307090 secs] 11648120K->672195K(18285760K), 0.1309590 secs] [Times: user=1.20 sys=0.00, real=0.13 secs] 
2015-05-16T08:18:22.343+0800: 1556.516: [GC2015-05-16T08:18:22.343+0800: 1556.516: [ParNew: 11456993K->412544K(13165760K), 0.1325270 secs] 11643715K->603596K(18285760K), 0.1327730 secs] [Times: user=1.23 sys=0.00, real=0.13 secs] 
2015-05-16T08:19:19.744+0800: 1613.917: [GC2015-05-16T08:19:19.744+0800: 1613.917: [ParNew: 11384064K->538411K(13165760K), 0.1575330 secs] 11575116K->733767K(18285760K), 0.1578060 secs] [Times: user=1.47 sys=0.00, real=0.16 secs] 
2015-05-16T08:20:13.689+0800: 1667.863: [GC2015-05-16T08:20:13.689+0800: 1667.863: [ParNew: 11509931K->467140K(13165760K), 0.1500950 secs] 11705287K->666590K(18285760K), 0.1503770 secs] [Times: user=1.38 sys=0.01, real=0.15 secs] 
2015-05-16T08:21:03.746+0800: 1717.919: [GC2015-05-16T08:21:03.746+0800: 1717.919: [ParNew: 11438660K->491515K(13165760K), 0.1573820 secs] 11638110K->695292K(18285760K), 0.1576390 secs] [Times: user=1.47 sys=0.01, real=0.16 secs] 
2015-05-16T08:21:57.057+0800: 1771.231: [GC2015-05-16T08:21:57.057+0800: 1771.231: [ParNew: 11463035K->494812K(13165760K), 0.1683290 secs] 11666812K->703187K(18285760K), 0.1685830 secs] [Times: user=1.58 sys=0.00, real=0.17 secs] 
2015-05-16T08:22:53.009+0800: 1827.183: [GC2015-05-16T08:22:53.009+0800: 1827.183: [ParNew: 11466332K->503009K(13165760K), 0.2752990 secs] 11674707K->715630K(18285760K), 0.2755490 secs] [Times: user=2.65 sys=0.01, real=0.28 secs] 
2015-05-16T08:23:49.248+0800: 1883.421: [GC2015-05-16T08:23:49.248+0800: 1883.421: [ParNew: 11474529K->592507K(13165760K), 0.3214050 secs] 11687150K->810982K(18285760K), 0.3216520 secs] [Times: user=3.10 sys=0.02, real=0.32 secs] 
2015-05-16T08:24:45.261+0800: 1939.434: [GC2015-05-16T08:24:45.261+0800: 1939.434: [ParNew: 11564027K->524559K(13165760K), 0.2616300 secs] 11782502K->747578K(18285760K), 0.2618880 secs] [Times: user=2.49 sys=0.02, real=0.26 secs] 
2015-05-16T08:25:41.077+0800: 1995.250: [GC2015-05-16T08:25:41.077+0800: 1995.250: [ParNew: 11496079K->614392K(13165760K), 0.3724070 secs] 11719098K->842089K(18285760K), 0.3726700 secs] [Times: user=3.61 sys=0.01, real=0.37 secs] 
2015-05-16T08:26:37.097+0800: 2051.271: [GC2015-05-16T08:26:37.097+0800: 2051.271: [ParNew: 11585912K->581647K(13165760K), 0.4181700 secs] 11813609K->813745K(18285760K), 0.4184100 secs] [Times: user=4.08 sys=0.00, real=0.42 secs] 
2015-05-16T08:27:30.132+0800: 2104.305: [GC2015-05-16T08:27:30.132+0800: 2104.305: [ParNew: 11553167K->524464K(13165760K), 0.4743670 secs] 11785265K->761376K(18285760K), 0.4746240 secs] [Times: user=4.66 sys=0.00, real=0.48 secs]

有时会达到 600 毫秒，然后又回到 150 毫秒。然后越长越长。

我的堆信息:

Attaching to process ID 33415, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 24.45-b08

using parallel threads in the new generation.
using thread-local object allocation.
Concurrent Mark-Sweep GC

Heap Configuration:
   MinHeapFreeRatio = 40
   MaxHeapFreeRatio = 70
   MaxHeapSize      = 20971520000 (20000.0MB)
   NewSize          = 15728640000 (15000.0MB)
   MaxNewSize       = 15728640000 (15000.0MB)
   OldSize          = 5242880000 (5000.0MB)
   NewRatio         = 2
   SurvivorRatio    = 5
   PermSize         = 268435456 (256.0MB)
   MaxPermSize      = 268435456 (256.0MB)
   G1HeapRegionSize = 0 (0.0MB)

Heap Usage:
New Generation (Eden + 1 Survivor Space):
   capacity = 13481738240 (12857.1875MB)
   used     = 7330310008 (6990.728385925293MB)
   free     = 6151428232 (5866.459114074707MB)
   54.37214309836652% used
Eden Space:
   capacity = 11234836480 (10714.375MB)
   used     = 6871073864 (6552.766670227051MB)
   free     = 4363762616 (4161.608329772949MB)
   61.15864593340303% used
From Space:
   capacity = 2246901760 (2142.8125MB)
   used     = 459236144 (437.9617156982422MB)
   free     = 1787665616 (1704.8507843017578MB)
   20.438639204234725% used
To Space:
   capacity = 2246901760 (2142.8125MB)
   used     = 0 (0.0MB)
   free     = 2246901760 (2142.8125MB)
   0.0% used
concurrent mark-sweep generation:
   capacity = 5242880000 (5000.0MB)
   used     = 334762784 (319.2546691894531MB)
   free     = 4908117216 (4680.745330810547MB)
   6.385093383789062% used
Perm Generation:
   capacity = 268435456 (256.0MB)
   used     = 60901216 (58.079925537109375MB)
   free     = 207534240 (197.92007446289062MB)
   22.68747091293335% used

30149 interned Strings occupying 3285592 bytes.

我的jvm配置

-XX:+UseConcMarkSweepGC -XX:MaxDirectMemorySize=11000m -Xms20000m -Xmx20000m -XX:NewSize=15000m -XX:SurvivorRatio=5 -XX:PermSize=256m -server -XX:+DisableExplicitGC -Dqunar.logs=$CATALINA_BASE/logs -Dqunar.cache=$CATALINA_BASE/cache -verbose:gc -XX:+PrintGCDateStamps -XX:+PrintGCDetails -Xloggc:$CATALINA_BASE/logs/gc.log

想知道为什么young gc的时间会越来越长

我怎样才能减少它？

Answer 1

I want to know why the time of young gc will grow longer and longer

可能有很多原因，但我认为最有可能的是:

• 您有内存泄漏，新生代 gc 时间的增加是由泄漏对象的累积引起的。

• 您在内存中缓存了很多“东西”，这会影响 GC 时间。 (时间的下降可能与 GC 决定它需要打破缓存数据结构中的薄弱链接以减少内存压力有关。)

在这两种情况下，值得注意的是，GC 时间更多地取决于 Activity 对象的数量，而不是您拥有的垃圾量。任何导致 Activity 对象数量呈上升趋势的因素都会增加 GC 时间。

How can I reduce it?

首先确定时间增加的原因。确保这不是由于您的应用程序正在做的事情。

然后阅读此处的建议:http://java.dzone.com/articles/how-tame-java-gc-pauses .使用大堆(20Gb 很大)来控制暂停时间并不容易。

查看您设置的选项，我怀疑 -XX:NewSize=15000m 可能是问题的一部分。它迫使年轻空间变得非常大——占总堆大小的 3/4。由于 CMS minor collections 是 stop-the-world，这将直接影响暂停时间。如果您删除该选项或将其设置为更小的值，也许效果会更好。

更新

显然，减小年轻空间的大小确实减少了暂停时间。