Java G1 GC处理参考对象工作缓慢 [英] Java G1 GC Processing Reference objects works slow

问题描述

我有用Java运行的计数器。它的工作时间是24小时，每秒约100次。
白天GC处理时间从20-60毫秒缓慢上升至10000-60000毫秒，然后下降至20-60毫秒。这种模式不时重复。从GC日志中我发现大部分时间GC都花费在处理引用对象（Ref Proc）上。那么，这么长的GC时间的原因可能是什么？

I have hit counter running on Java. It works 24 hours and hits pass at about 100 times per second. During the day GC processing time slowly rises from 20-60 ms till 10000-60000 ms and then drops to 20-60 ms. Such pattern is repeated from time to time. From GC logs I found that mostly all time GC spend for processing Reference objects (Ref Proc). So what's the causes of such long GC time could be?

Server: Amazon EC2 m1.small
OS: Ubuntu 10.04.3 LTS
Java: Oracle 1.7.0_07

GC日志示例： p>

Example of GC logs:

2012-09-13T16:51:20.091+0400: 167239.936: [GC pause (young), 62.58395400 secs]
...
[Other: 62489.7 ms]
    [Choose CSet:   0.0 ms]
    [Ref Proc: 62433.9 ms]
    [Ref Enq:   0.0 ms]
    [Free CSet:   0.7 ms]
[Eden: 200M(200M)->0B(199M) Survivors: 4096K->5120K Heap: 578M(1024M)->380M(1024M)]

时间 - Ref Proc图：

Time - "Ref Proc" graph:

09:37:59 - 242.4 ms
09:38:50 - 226.0 ms
09:39:00 - 83.6 ms
...
11:45:22 - 451.8 ms
11:46:04 - 489.3 ms
11:46:46 - 505.6 ms
...
14:05:40 - 1027.3 ms
14:06:01 - 796.6 ms
14:06:35 - 1064.0 ms
...
15:44:32 - 1920.4 ms
15:45:04 - 2116.7 ms
15:45:39 - 2196.8 ms
...
16:19:07 - 3983.3 ms
16:19:43 - 4494.9 ms
16:20:16 - 4065.2 ms
...
16:33:11 - 7690.1 ms
16:33:50 - 8501.4 ms
16:34:28 - 8059.3 ms
...
16:47:14 - 51378.6 ms
16:49:11 - 57529.2 ms
16:51:20 - 62433.9 ms
16:53:00 - 46.1 ms
16:53:30 - 45.5 ms
16:54:03 - 45.0 ms
...
16:54:38 - 57.0 ms
16:55:09 - 20.9 ms
16:55:43 - 21.3 ms
...
16:09:45 - 134.3 ms
16:10:21 - 142.1 ms
16:10:58 - 147.5 ms
...
17:18:51 - 177.3 ms
17:19:27 - 135.8 ms
17:20:03 - 179.6 ms

我在java源代码中找到PrintReferenceGC。 GC日志显示下一个

I found in java sources parameter PrintReferenceGC. GC log showed next

[SoftReference, 0 refs, 0.0000050 secs]
[WeakReference, 6 refs, 0.0000030 secs]
[FinalReference, 113 refs, 0.0011180 secs]
[PhantomReference, 0 refs, 0.0000020 secs]
[JNI Weak Reference, 3.9010450 secs]

这是JNI Weak Reference的一些问题。

This is some problem of JNI Weak Reference.

推荐答案

重要的是，我所有的运行都是使用Yourkit分析器。我安装了OpenJDK7的fastdebug版本。在这个版本中有一个参数-XX：+ TraceReferenceGC。运行该参数后，gc log显示约5000个终结器。关闭Yourkit的套接字探测器即可解决该问题。

Its important that all my runs were with Yourkit profiler. I installed fastdebug build of OpenJDK7. At this version there is a parameter -XX:+TraceReferenceGC. After running with this parameter gc log shown about 5000 some finalizers. This problem was resolved by turning off socket probes of Yourkit.

这篇关于Java G1 GC处理参考对象工作缓慢的文章就介绍到这了，希望我们推荐的答案对大家有所帮助，也希望大家多多支持IT屋！