<html>
<head>
<meta content="text/html; charset=windows-1252"
http-equiv="Content-Type">
</head>
<body bgcolor="#FFFFFF" text="#000000">
<font size="-1"><tt>Keith,<br>
<br>
I am adding hotspot-gc-dev, hoping some one can give a better
explanation.<br>
<br>
Yes, currently the JNI weak reference processing is single
threaded. <br>
You mentioned JNI weak reference pause long for remark and mixed
gc. For young gc, it is long as well. Just for young gc, the
collected set is limited. My guess is you can not make much
difference by tuning.<br>
<br>
There is a possibility for memory leak in the native code. A lot
of Solr applications use native memory for cache. <br>
</tt></font>
<pre class="moz-signature" cols="72">Thanks,
Jenny</pre>
<div class="moz-cite-prefix">On 10/7/2015 11:40 AM, Keith L wrote:<br>
</div>
<blockquote
cite="mid:CAGek2ZNDm8Jx8=qcR0HXvnKRLxZ5mrR5PkbYsLGEErM80XDWwA@mail.gmail.com"
type="cite">
<div dir="ltr">
<div>Java:</div>
<div>- JDK 1.8u40</div>
<div>- UseG1GC, ParallelRefProcEnabled, Xmx12g,Xms12g</div>
<div><br>
</div>
<div>Application:</div>
<div>- Solr 4.10.4</div>
<div><br>
</div>
<div>Application Details:</div>
<div>Using Solr, which does not use JNI directly although it
make heavy use of nio and MMaps. <br>
Possibly relevant is that we run our application with the
yourkit agent with monitoring disabled by default.</div>
<div><br>
</div>
<div>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. (<a moz-do-not-send="true"
href="https://bugs.openjdk.java.net/browse/JDK-8072498">https://bugs.openjdk.java.net/browse/JDK-8072498</a>)<br>
<br>
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.</div>
<div><br>
</div>
<div>Possibly related: after a heap dump of a running
application we noticed anywhere from a couple hundred to
hundreds of thousands of unreferenced DirectByteBuffers.</div>
<div><br>
</div>
<div>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.</div>
<div><br>
</div>
<div>Questions:</div>
<div>1) What is causing the JNI Weak References? </div>
<div> - Is it from nio? Usage of MMaps, DirectBuffers, etc?</div>
<div>2) Why does it become worse during the lifetime of the
application?</div>
<div> - Is there a leak?</div>
<div> - are medium life objects being moved too early</div>
<div> - Tune G1NewSizePercent?</div>
<div> - Tune Survivor settings?</div>
<div>3) Are the JNI Weak References being visited but not
cleaned during GC?</div>
<div> - Why not? tune G1HeapWastePercent?</div>
<div>4) How can more debugging be done to find where the
references are coming from</div>
<div><br>
</div>
<div><br>
</div>
<div>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. </div>
<div><br>
</div>
<div><br>
</div>
<div>We have not tuned any of the options above which disable
the adaptive sizing policy, some options we are actively
testing are:</div>
<div><br>
</div>
<div>- Lowering InitiatingHeapOccupancyPercent</div>
<div> - To force dereferenced objects in tenured to be cleaned
earlier.</div>
<div><br>
</div>
<div>- Increasing MaxGCPauseMillis</div>
<div> - To encourage policy for the young generation size to be
larger (discouraging premature promotion).</div>
<div><br>
</div>
<div><br>
</div>
<div>Example of remark phases below (full gc log can be provided
if required)</div>
<div><br>
</div>
<div>One example log file (however we have seen worse), using
flags in the beginning:</div>
<div><br>
</div>
<div>1348278.630: [GC pause (G1 Evacuation Pause) (young)
(initial-mark)</div>
<div>Desired survivor size 41943040 bytes, new threshold 15 (max
15)</div>
<div>- age 1: 36138128 bytes, 36138128 total</div>
<div>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]</div>
<div> [Parallel Time: 39.7 ms, GC Workers: 23]</div>
<div> [GC Worker Start (ms): Min: 1348278633.2, Avg:
1348278633.7, Max: 1348278634.2, Diff: 1.0]</div>
<div> [Ext Root Scanning (ms): Min: 11.2, Avg: 11.7, Max:
14.9, Diff: 3.7, Sum: 269.2]</div>
<div> [Update RS (ms): Min: 9.9, Avg: 13.3, Max: 14.0,
Diff: 4.1, Sum: 304.8]</div>
<div> [Processed Buffers: Min: 23, Avg: 66.9, Max: 117,
Diff: 94, Sum: 1538]</div>
<div> [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff:
0.1, Sum: 0.6]</div>
<div> [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max:
0.0, Diff: 0.0, Sum: 0.0]</div>
<div> [Object Copy (ms): Min: 11.8, Avg: 12.4, Max: 12.9,
Diff: 1.1, Sum: 286.3]</div>
<div> [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0,
Diff: 0.0, Sum: 0.3]</div>
<div> [GC Worker Other (ms): Min: 0.1, Avg: 0.3, Max: 0.7,
Diff: 0.6, Sum: 6.2]</div>
<div> [GC Worker Total (ms): Min: 37.0, Avg: 37.7, Max:
38.6, Diff: 1.6, Sum: 867.4]</div>
<div> [GC Worker End (ms): Min: 1348278671.2, Avg:
1348278671.4, Max: 1348278671.8, Diff: 0.6]</div>
<div> [Code Root Fixup: 0.4 ms]</div>
<div> [Code Root Purge: 0.0 ms]</div>
<div> [Clear CT: 2.8 ms]</div>
<div> [Other: 152.6 ms]</div>
<div> [Choose CSet: 0.0 ms]</div>
<div> [Ref Proc: 137.2 ms]</div>
<div> [Ref Enq: 2.6 ms]</div>
<div> [Redirty Cards: 3.2 ms]</div>
<div> [Humongous Reclaim: 0.0 ms]</div>
<div> [Free CSet: 0.6 ms]</div>
<div> [Eden: 532.0M(532.0M)->0.0B(532.0M) Survivors:
80.0M->80.0M Heap: 6225.6M(12.0G)->5701.0M(12.0G)]</div>
<div> [Times: user=0.80 sys=0.04, real=0.20 secs]</div>
<div>1348278.827: [GC concurrent-root-region-scan-start]</div>
<div>1348278.828: Total time for which application threads were
stopped: 0.2145574 seconds, Stopping threads took: 0.0012976
seconds</div>
<div>1348278.844: [GC concurrent-root-region-scan-end, 0.0170768
secs]</div>
<div>1348278.844: [GC concurrent-mark-start]</div>
<div>1348279.075: [GC concurrent-mark-end, 0.2306171 secs]</div>
<div>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]</div>
<div> [Times: user=19.59 sys=0.00, real=19.04 secs]</div>
<div>1348298.132: Total time for which application threads were
stopped: 19.0566871 seconds, Stopping threads took: 0.0011100
seconds</div>
<div>1348298.147: [GC cleanup 5836M->4256M(12G), 0.0124121
secs]</div>
<div> [Times: user=0.11 sys=0.00, real=0.01 secs]</div>
<div>...</div>
<div>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]</div>
<div>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]</div>
<div>...</div>
<div>...</div>
<div>...</div>
<div>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]</div>
<div>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]</div>
<div>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]</div>
<div>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]</div>
<div>...</div>
<div>1380251.013: [GC pause (G1 Evacuation Pause) (young)
(initial-mark)</div>
<div>Desired survivor size 41943040 bytes, new threshold 1 (max
15)</div>
<div>- age 1: 46612512 bytes, 46612512 total</div>
<div>[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]</div>
<div> [Parallel Time: 23.5 ms, GC Workers: 23]</div>
<div> [GC Worker Start (ms): Min: 1380251014.8, Avg:
1380251015.3, Max: 1380251015.9, Diff: 1.1]</div>
<div> [Ext Root Scanning (ms): Min: 6.7, Avg: 7.5, Max:
10.9, Diff: 4.2, Sum: 173.4]</div>
<div> [Update RS (ms): Min: 3.7, Avg: 6.5, Max: 7.0, Diff:
3.3, Sum: 150.5]</div>
<div> [Processed Buffers: Min: 27, Avg: 66.7, Max: 112,
Diff: 85, Sum: 1534]</div>
<div> [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff:
0.1, Sum: 0.6]</div>
<div> [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max:
0.0, Diff: 0.0, Sum: 0.0]</div>
<div> [Object Copy (ms): Min: 6.3, Avg: 6.7, Max: 7.3,
Diff: 1.0, Sum: 154.9]</div>
<div> [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0,
Diff: 0.0, Sum: 0.1]</div>
<div> [GC Worker Other (ms): Min: 0.1, Avg: 0.4, Max: 0.8,
Diff: 0.8, Sum: 8.3]</div>
<div> [GC Worker Total (ms): Min: 20.4, Avg: 21.2, Max:
21.8, Diff: 1.4, Sum: 487.7]</div>
<div> [GC Worker End (ms): Min: 1380251036.2, Avg:
1380251036.5, Max: 1380251037.0, Diff: 0.8]</div>
<div> [Code Root Fixup: 0.4 ms]</div>
<div> [Code Root Purge: 0.0 ms]</div>
<div> [Clear CT: 2.9 ms]</div>
<div> [Other: 3041.1 ms]</div>
<div> [Choose CSet: 0.0 ms]</div>
<div> [Ref Proc: 3029.5 ms]</div>
<div> [Ref Enq: 2.7 ms]</div>
<div> [Redirty Cards: 2.7 ms]</div>
<div> [Humongous Reclaim: 0.0 ms]</div>
<div> [Free CSet: 0.3 ms]</div>
<div> [Eden: 532.0M(532.0M)->0.0B(548.0M) Survivors:
80.0M->64.0M Heap: 6142.5M(12.0G)->5620.7M(12.0G)]</div>
<div> [Times: user=3.46 sys=0.00, real=3.07 secs]</div>
<div>1380254.081: [GC concurrent-root-region-scan-start]</div>
<div>1380254.082: Total time for which application threads were
stopped: 3.0847197 seconds, Stopping threads took: 0.0011519
seconds</div>
<div>1380254.092: [GC concurrent-root-region-scan-end, 0.0105392
secs]</div>
<div>1380254.092: [GC concurrent-mark-start]</div>
<div>1380254.275: [GC concurrent-mark-end, 0.1832853 secs]</div>
<div>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]</div>
<div> [Times: user=39.37 sys=0.00, real=38.78 secs]</div>
<div>1380293.067: Total time for which application threads were
stopped: 38.7917823 seconds, Stopping threads took: 0.0011561
seconds</div>
<div>1380293.077: [GC cleanup 5659M->4167M(12G), 0.0120391
secs]</div>
<div> [Times: user=0.11 sys=0.00, real=0.01 secs]</div>
<div><br>
</div>
</div>
<br>
<fieldset class="mimeAttachmentHeader"></fieldset>
<br>
<pre wrap="">_______________________________________________
hotspot-gc-use mailing list
<a class="moz-txt-link-abbreviated" href="mailto:hotspot-gc-use@openjdk.java.net">hotspot-gc-use@openjdk.java.net</a>
<a class="moz-txt-link-freetext" href="http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use">http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use</a>
</pre>
</blockquote>
<br>
</body>
</html>