java - 为什么G1 Remark阶段的Unloading Action 耗时太长

Question

我们有一个带有 JDK8_162 的 Java 应用程序和一些启动参数，如下所示:

-Xms512m
-Xmx512m
-XX:MetaspaceSize=64m
-XX:MaxMetaspaceSize=128m
-XX:+UseG1GC

运行几个小时后，GC并发阶段开始，GC日志如下:

2016-04-18T12:38:56.067+0000: 7352.812: [GC pause (Metadata GC Threshold) (young) (initial-mark)2016-04-18T12:38:56.110+0000: 7352.855: [SoftReference, 0 refs, 0.0000428 secs]2016-04-18T12:38:56.110+0000: 7352.855: [WeakReference, 201 refs, 0.0000261 secs]2016-04-18T12:38:56.110+0000: 7352.855: [FinalReference, 748 refs, 0.0006959 secs]2016-04-18T12:38:56.111+0000: 7352.856: [PhantomReference, 1276 refs, 0 refs, 0.0002082 secs]2016-04-18T12:38:56.111+0000: 7352.856: [JNI Weak Reference, 0.0170219 secs], 0.0748847 secs]
[Parallel Time: 41.4 ms, GC Workers: 8]
  [GC Worker Start (ms): Min: 7352813.6, Avg: 7352813.7, Max: 7352813.7, Diff: 0.1]
  [Ext Root Scanning (ms): Min: 34.8, Avg: 38.7, Max: 41.0, Diff: 6.2, Sum: 310.0]
  [Update RS (ms): Min: 0.0, Avg: 0.8, Max: 2.1, Diff: 2.1, Sum: 6.0]
     [Processed Buffers: Min: 0, Avg: 11.4, Max: 38, Diff: 38, Sum: 91]
  [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.1]
  [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.2]
  [Object Copy (ms): Min: 0.2, Avg: 1.6, Max: 4.2, Diff: 4.0, Sum: 12.9]
  [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
     [Termination Attempts: Min: 1, Avg: 1.2, Max: 2, Diff: 1, Sum: 10]
  [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.2]
  [GC Worker Total (ms): Min: 41.1, Avg: 41.2, Max: 41.2, Diff: 0.1, Sum: 329.4]
  [GC Worker End (ms): Min: 7352854.8, Avg: 7352854.8, Max: 7352854.8, Diff: 0.0]
[Code Root Fixup: 0.0 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.3 ms]
[Other: 33.1 ms]
  [Choose CSet: 0.0 ms]
  [Ref Proc: 18.2 ms]
  [Ref Enq: 0.0 ms]
  [Redirty Cards: 0.4 ms]
  [Humongous Register: 0.0 ms]
  [Humongous Reclaim: 12.3 ms]
  [Free CSet: 0.1 ms]
[Eden: 142.0M(289.0M)->0.0B(297.0M) Survivors: 12.0M->10.0M Heap: 298.2M(512.0M)->108.1M(512.0M)]
[Times: user=0.03 sys=0.00, real=0.08 secs]
2016-04-18T12:38:56.142+0000: 7352.887: [GC concurrent-root-region-scan-start]
2016-04-18T12:38:56.160+0000: 7352.904: [GC concurrent-root-region-scan-end, 0.0178533 secs]
2016-04-18T12:38:56.160+0000: 7352.904: [GC concurrent-mark-start]
2016-04-18T12:38:56.207+0000: 7352.952: [GC concurrent-mark-end, 0.0479237 secs]
2016-04-18T12:38:56.208+0000: 7352.953: [GC remark 2016-04-18T12:38:56.208+0000: 7352.953: [Finalize Marking, 0.0008405 secs] 2016-04-18T12:38:56.209+0000: 7352.954: [GC ref-proc2016-04-18T12:38:56.209+0000: 7352.954: [SoftReference, 280 refs, 0.0000776 secs]2016-04-18T12:38:56.209+0000: 7352.954: [WeakReference, 589 refs, 0.0001071 secs]2016-04-18T12:38:56.209+0000: 7352.954: [FinalReference, 81 refs, 0.0000550 secs]2016-04-18T12:38:56.209+0000: 7352.954: [PhantomReference, 273 refs, 4 refs, 0.0000915 secs]2016-04-18T12:38:56.209+0000: 7352.954: [JNI Weak Reference, 0.0005750 secs], 0.0009585 secs] 2016-04-18T12:38:56.210+0000: 7352.955: [Unloading, 1.3772433 secs], 1.3844168 secs]
[Times: user=0.06 sys=0.01, real=1.39 secs]
2016-04-18T12:38:57.593+0000: 7354.338: [GC cleanup 109M->87M(512M), 0.0056146 secs]
[Times: user=0.00 sys=0.00, real=0.00 secs]
2016-04-18T12:38:57.599+0000: 7354.344: [GC concurrent-cleanup-start]
2016-04-18T12:38:57.599+0000: 7354.344: [GC concurrent-cleanup-end, 0.0000237 secs]

卸载操作需要 1.37 秒，有时甚至超过 2 秒。有人知道 GC 在此操作中做了什么以及为什么需要这么长时间吗？

Answer 1

事实证明，当 GC 执行 Unloading 操作时，CPU 使用率很高。在我的系统上，不只是只有一个 Java 进程，另一个 C++ 进程有时会消耗大量 CPU 资源，如果 Unloading 操作在 CPU 使用率较高的情况下启动，则会导致该操作需要更长的时间才能完成。