Logo Questions Linux Laravel Mysql Ubuntu Git Menu
 

Java G1 GC Processing Reference objects works slow

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

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)]

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

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]

This is some problem of JNI Weak Reference.

like image 754
gorbunak Avatar asked Sep 14 '12 17:09

gorbunak


1 Answers

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.

like image 106
gorbunak Avatar answered Nov 07 '22 12:11

gorbunak