[G1GC] Slow processing JNI Weak References
Keith L
kelaban17 at gmail.com
Wed Oct 7 18:40:57 UTC 2015
Java:
- JDK 1.8u40
- UseG1GC, ParallelRefProcEnabled, Xmx12g,Xms12g
Application:
- Solr 4.10.4
Application Details:
Using Solr, which does not use JNI directly although it make heavy use of
nio and MMaps.
Possibly relevant is that we run our application with the yourkit agent
with monitoring disabled by default.
When using G1GC we are seeing very high processing times for JNI Weak
Reference processing, in both GC Remak phase and during Mixed collections.
Originally we saw high times during WeakReference processing but
adding"-XX:+ParallelRefProcEnabled" flag did away with this. JNI Weak
Reference processing we've seen take as much as 300+ seconds!, although
more commonly we see it taking 20-60 seconds when it start becoming a
problem. Currently JNI Weak Reference are not processed in parallel in
HotSpot so adding the parallel flag has no affect. (
https://bugs.openjdk.java.net/browse/JDK-8072498)
Generally we don't see the time for processing be a problem until a few
days of uptime. At some point the JNI processing gets more expensive and
time taken climbs up and is expensive nearly every there is a Remark phase.
Possibly related: after a heap dump of a running application we noticed
anywhere from a couple hundred to hundreds of thousands of unreferenced
DirectByteBuffers.
Doing a jstack I've seen as many 16 Million JNI Global References being
reported. Although I haven't been able to find a way to get the JNI Weak
Reference information to be displayed.
Questions:
1) What is causing the JNI Weak References?
- Is it from nio? Usage of MMaps, DirectBuffers, etc?
2) Why does it become worse during the lifetime of the application?
- Is there a leak?
- are medium life objects being moved too early
- Tune G1NewSizePercent?
- Tune Survivor settings?
3) Are the JNI Weak References being visited but not cleaned during GC?
- Why not? tune G1HeapWastePercent?
4) How can more debugging be done to find where the references are coming
from
As of right now we are experimenting with different G1GC flags, however
without understanding the root cause it sometimes requires days between
experiments for the problem to present itself.
We have not tuned any of the options above which disable the adaptive
sizing policy, some options we are actively testing are:
- Lowering InitiatingHeapOccupancyPercent
- To force dereferenced objects in tenured to be cleaned earlier.
- Increasing MaxGCPauseMillis
- To encourage policy for the young generation size to be larger
(discouraging premature promotion).
Example of remark phases below (full gc log can be provided if required)
One example log file (however we have seen worse), using flags in the
beginning:
1348278.630: [GC pause (G1 Evacuation Pause) (young) (initial-mark)
Desired survivor size 41943040 bytes, new threshold 15 (max 15)
- age 1: 36138128 bytes, 36138128 total
1348278.676: [SoftReference, 0 refs, 0.0086523 secs]1348278.684:
[WeakReference, 7128 refs, 0.0047846 secs]1348278.689: [FinalReference, 414
refs, 0.0063207 secs]1348278.695: [PhantomReference, 0 refs, 376 refs,
0.0129979 secs]1348278.709: [JNI Weak Reference, 0.1018689 secs], 0.1955299
secs]
[Parallel Time: 39.7 ms, GC Workers: 23]
[GC Worker Start (ms): Min: 1348278633.2, Avg: 1348278633.7, Max:
1348278634.2, Diff: 1.0]
[Ext Root Scanning (ms): Min: 11.2, Avg: 11.7, Max: 14.9, Diff: 3.7,
Sum: 269.2]
[Update RS (ms): Min: 9.9, Avg: 13.3, Max: 14.0, Diff: 4.1, Sum:
304.8]
[Processed Buffers: Min: 23, Avg: 66.9, Max: 117, Diff: 94, Sum:
1538]
[Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.6]
[Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0,
Sum: 0.0]
[Object Copy (ms): Min: 11.8, Avg: 12.4, Max: 12.9, Diff: 1.1, Sum:
286.3]
[Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.3]
[GC Worker Other (ms): Min: 0.1, Avg: 0.3, Max: 0.7, Diff: 0.6, Sum:
6.2]
[GC Worker Total (ms): Min: 37.0, Avg: 37.7, Max: 38.6, Diff: 1.6,
Sum: 867.4]
[GC Worker End (ms): Min: 1348278671.2, Avg: 1348278671.4, Max:
1348278671.8, Diff: 0.6]
[Code Root Fixup: 0.4 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 2.8 ms]
[Other: 152.6 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 137.2 ms]
[Ref Enq: 2.6 ms]
[Redirty Cards: 3.2 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 0.6 ms]
[Eden: 532.0M(532.0M)->0.0B(532.0M) Survivors: 80.0M->80.0M Heap:
6225.6M(12.0G)->5701.0M(12.0G)]
[Times: user=0.80 sys=0.04, real=0.20 secs]
1348278.827: [GC concurrent-root-region-scan-start]
1348278.828: Total time for which application threads were stopped:
0.2145574 seconds, Stopping threads took: 0.0012976 seconds
1348278.844: [GC concurrent-root-region-scan-end, 0.0170768 secs]
1348278.844: [GC concurrent-mark-start]
1348279.075: [GC concurrent-mark-end, 0.2306171 secs]
1348279.088: [GC remark 1348279.088: [Finalize Marking, 0.0051946 secs]
1348279.093: [GC ref-proc1348279.093: [SoftReference, 186 refs, 0.0089505
secs]1348279.102: [WeakReference, 2668 refs, 0.0051839 secs]1348279.107:
[FinalReference, 848 refs, 0.0088167 secs]1348279.116: [PhantomReference, 0
refs, 3836 refs, 0.0130326 secs]1348279.129: [JNI Weak Reference,
18.9741270 secs], 19.0130579 secs] 1348298.106: [Unloading, 0.0177559
secs], 19.0412558 secs]
[Times: user=19.59 sys=0.00, real=19.04 secs]
1348298.132: Total time for which application threads were stopped:
19.0566871 seconds, Stopping threads took: 0.0011100 seconds
1348298.147: [GC cleanup 5836M->4256M(12G), 0.0124121 secs]
[Times: user=0.11 sys=0.00, real=0.01 secs]
...
1348358.227: [GC remark 1348358.227: [Finalize Marking, 0.0042513 secs]
1348358.231: [GC ref-proc1348358.231: [SoftReference, 197 refs, 0.0085051
secs]1348358.240: [WeakReference, 5962 refs, 0.0082517 secs]1348358.248:
[FinalReference, 1881 refs, 0.0074058 secs]1348358.255: [PhantomReference,
0 refs, 3802 refs, 0.0116230 secs]1348358.267: [JNI Weak Reference,
29.3914835 secs], 29.4310975 secs] 1348387.662: [Unloading, 0.0179274
secs], 29.4583167 secs]
1350907.355: [GC remark 1350907.355: [Finalize Marking, 0.0066394 secs]
1350907.362: [GC ref-proc1350907.362: [SoftReference, 189 refs, 0.0084702
secs]1350907.370: [WeakReference, 2379 refs, 0.0046033 secs]1350907.375:
[FinalReference, 779 refs, 0.0086055 secs]1350907.383: [PhantomReference, 0
refs, 4349 refs, 0.0124574 secs]1350907.396: [JNI Weak Reference,
29.9550822 secs], 29.9923290 secs] 1350937.354: [Unloading, 0.0171185
secs], 30.0213910 secs]
...
...
...
1377495.992: [GC remark 1377495.992: [Finalize Marking, 0.0039972 secs]
1377495.996: [GC ref-proc1377495.996: [SoftReference, 192 refs, 0.0084780
secs]1377496.005: [WeakReference, 1171 refs, 0.0040591 secs]1377496.009:
[FinalReference, 619 refs, 0.0068656 secs]1377496.016: [PhantomReference, 0
refs, 4886 refs, 0.0094143 secs]1377496.025: [JNI Weak Reference,
48.3669099 secs], 48.3980356 secs] 1377544.394: [Unloading, 0.0159881
secs], 48.4228951 secs]
1378034.868: [GC remark 1378034.868: [Finalize Marking, 0.0033629 secs]
1378034.871: [GC ref-proc1378034.871: [SoftReference, 193 refs, 0.0059063
secs]1378034.877: [WeakReference, 1332 refs, 0.0036461 secs]1378034.881:
[FinalReference, 611 refs, 0.0046526 secs]1378034.885: [PhantomReference, 0
refs, 4254 refs, 0.0059437 secs]1378034.891: [JNI Weak Reference,
46.6392836 secs], 46.6624796 secs] 1378081.534: [Unloading, 0.0180802
secs], 46.6893835 secs]
1378677.326: [GC remark 1378677.326: [Finalize Marking, 0.0039769 secs]
1378677.330: [GC ref-proc1378677.330: [SoftReference, 193 refs, 0.0080377
secs]1378677.338: [WeakReference, 1719 refs, 0.0035972 secs]1378677.341:
[FinalReference, 351 refs, 0.0063767 secs]1378677.348: [PhantomReference, 0
refs, 4753 refs, 0.0103290 secs]1378677.358: [JNI Weak Reference,
43.9230851 secs], 43.9537699 secs] 1378721.284: [Unloading, 0.0150821
secs], 43.9780128 secs]
1379626.009: [GC remark 1379626.009: [Finalize Marking, 0.0040175 secs]
1379626.013: [GC ref-proc1379626.013: [SoftReference, 186 refs, 0.0080680
secs]1379626.021: [WeakReference, 955 refs, 0.0064521 secs]1379626.028:
[FinalReference, 567 refs, 0.0098877 secs]1379626.038: [PhantomReference, 0
refs, 4701 refs, 0.0104484 secs]1379626.048: [JNI Weak Reference,
51.3181908 secs], 51.3558998 secs] 1379677.369: [Unloading, 0.0207052
secs], 51.3856987 secs]
...
1380251.013: [GC pause (G1 Evacuation Pause) (young) (initial-mark)
Desired survivor size 41943040 bytes, new threshold 1 (max 15)
- age 1: 46612512 bytes, 46612512 total
[SoftReference, 0 refs, 0.0074261 secs]1380251.048: [WeakReference, 5189
refs, 0.0041909 secs]1380251.052: [FinalReference, 393 refs, 0.0042160
secs]1380251.056: [PhantomReference, 0 refs, 83 refs, 0.0074198
secs]1380251.064: [JNI Weak Reference, 3.0041020 secs], 3.0678505 secs]
[Parallel Time: 23.5 ms, GC Workers: 23]
[GC Worker Start (ms): Min: 1380251014.8, Avg: 1380251015.3, Max:
1380251015.9, Diff: 1.1]
[Ext Root Scanning (ms): Min: 6.7, Avg: 7.5, Max: 10.9, Diff: 4.2,
Sum: 173.4]
[Update RS (ms): Min: 3.7, Avg: 6.5, Max: 7.0, Diff: 3.3, Sum: 150.5]
[Processed Buffers: Min: 27, Avg: 66.7, Max: 112, Diff: 85, Sum:
1534]
[Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.6]
[Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0,
Sum: 0.0]
[Object Copy (ms): Min: 6.3, Avg: 6.7, Max: 7.3, Diff: 1.0, Sum:
154.9]
[Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
[GC Worker Other (ms): Min: 0.1, Avg: 0.4, Max: 0.8, Diff: 0.8, Sum:
8.3]
[GC Worker Total (ms): Min: 20.4, Avg: 21.2, Max: 21.8, Diff: 1.4,
Sum: 487.7]
[GC Worker End (ms): Min: 1380251036.2, Avg: 1380251036.5, Max:
1380251037.0, Diff: 0.8]
[Code Root Fixup: 0.4 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 2.9 ms]
[Other: 3041.1 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 3029.5 ms]
[Ref Enq: 2.7 ms]
[Redirty Cards: 2.7 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 0.3 ms]
[Eden: 532.0M(532.0M)->0.0B(548.0M) Survivors: 80.0M->64.0M Heap:
6142.5M(12.0G)->5620.7M(12.0G)]
[Times: user=3.46 sys=0.00, real=3.07 secs]
1380254.081: [GC concurrent-root-region-scan-start]
1380254.082: Total time for which application threads were stopped:
3.0847197 seconds, Stopping threads took: 0.0011519 seconds
1380254.092: [GC concurrent-root-region-scan-end, 0.0105392 secs]
1380254.092: [GC concurrent-mark-start]
1380254.275: [GC concurrent-mark-end, 0.1832853 secs]
1380254.289: [GC remark 1380254.290: [Finalize Marking, 0.0039580 secs]
1380254.294: [GC ref-proc1380254.294: [SoftReference, 183 refs, 0.0068857
secs]1380254.300: [WeakReference, 1384 refs, 0.0043966 secs]1380254.305:
[FinalReference, 579 refs, 0.0073469 secs]1380254.312: [PhantomReference, 0
refs, 4327 refs, 0.0077366 secs]1380254.320: [JNI Weak Reference,
38.7211438 secs], 38.7506058 secs] 1380293.044: [Unloading, 0.0174879
secs], 38.7765019 secs]
[Times: user=39.37 sys=0.00, real=38.78 secs]
1380293.067: Total time for which application threads were stopped:
38.7917823 seconds, Stopping threads took: 0.0011561 seconds
1380293.077: [GC cleanup 5659M->4167M(12G), 0.0120391 secs]
[Times: user=0.11 sys=0.00, real=0.01 secs]
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mail.openjdk.java.net/pipermail/hotspot-gc-use/attachments/20151007/13f63eee/attachment.html>
More information about the hotspot-gc-use
mailing list