young GC 发生时，ext root 扫描需要很长时间。可能的原因是什么？

Question

我们在线服务运行一段时间后，会出现一秒长的young GC，一天只有几次，详细的GC日志在文末。

在 28 个 GC 线程中，一个线程在 scan ObjectSynchronizer 中花费一秒钟 root阶段，其他线程在这个阶段花费0。

我的问题是：

造成这种现象的原因可能是什么？
EXT 根扫描和对象同步器根阶段在做什么？ ext root scanning好像是扫描堆外的GC roots？

关于环境，垃圾收集器是g1 gc，openjdk 1.8。

谢谢！

原问题不够清楚，已修改

2020-11-03T13:25:28.472+0800: 3006817.162: [GC pause (G1 Evacuation Pause) (young)
Desired survivor size 176160768 bytes, new threshold 3 (max 3)
- age   1:   33875840 bytes,   33875840 total
- age   2:   17965120 bytes,   51840960 total
- age   3:   17908632 bytes,   69749592 total
, 1.5028049 secs]
   [Parallel Time: 1475.9 ms, GC Workers: 28]
      [GC Worker Start (ms):  3006817169.9  3006817170.0  3006817170.0  3006817170.0  3006817170.0  3006817170.0  3006817170.0  3006817170.0  3006817170.0  3006817170.0  3006817170.1  3006817170.1  3006817170.1  3006817170.1  3006817170.1  3006817170.1  3006817170.1  3006817170.1  3006817170.2  3006817170.2  3006817170.2  3006817170.2  3006817170.2  3006817170.2  3006817170.2  3006817170.2  3006817170.2  3006817170.3
       Min: 3006817169.9, Avg: 3006817170.1, Max: 3006817170.3, Diff: 0.3]
      [Ext Root Scanning (ms):  5.5  5.5  5.4  5.4  1475.1  5.3  5.4  5.3  5.4  5.3  5.3  5.3  5.3  5.3  6.0  5.2  5.3  5.3  5.2  5.3  5.2  5.2  5.2  5.2  5.1  5.2  5.1  5.2
       Min: 5.1, Avg: 57.8, Max: 1475.1, Diff: 1470.0, Sum: 1618.6]
         [Thread Roots (ms):  3.9  5.4  5.4  5.3  5.3  5.5  5.4  5.4  5.3  5.3  5.3  5.3  5.3  5.2  5.2  5.2  5.3  5.2  5.2  5.2  5.2  5.2  5.2  5.2  5.3  5.1  5.2  5.1
          Min: 3.9, Avg: 5.2, Max: 5.5, Diff: 1.6, Sum: 146.1]
         [StringTable Roots (ms):  0.1  0.1  0.1  0.2  0.0  0.0  0.1  0.1  0.2  0.2  0.2  0.2  0.2  0.2  0.0  0.2  0.1  0.2  0.1  0.0  0.1  0.1  0.1  0.1  0.0  0.2  0.1  0.1
          Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 3.1]
         [Universe Roots (ms):  0.0  0.0  0.1  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
          Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.1]
         [JNI Handles Roots (ms):  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
          Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [ObjectSynchronizer Roots (ms):  0.0  0.0  0.0  0.0  1469.9  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
          Min: 0.0, Avg: 52.5, Max: 1469.9, Diff: 1469.9, Sum: 1469.9]
         [FlatProfiler Roots (ms):  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.2  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
          Min: 0.0, Avg: 0.0, Max: 0.2, Diff: 0.2, Sum: 0.3]
         [Management Roots (ms):  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
          Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [SystemDictionary Roots (ms):  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.9  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
          Min: 0.0, Avg: 0.0, Max: 0.9, Diff: 0.9, Sum: 0.9]
         [CLDG Roots (ms):  1.5  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
          Min: 0.0, Avg: 0.1, Max: 1.5, Diff: 1.5, Sum: 1.5]
         [JVMTI Roots (ms):  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
          Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [CodeCache Roots (ms):  25.8  25.8  25.9  25.7  0.1  25.7  25.8  25.7  25.7  25.7  25.7  25.7  25.8  25.7  25.0  25.8  25.8  25.8  25.8  25.7  25.8  25.8  25.8  25.7  25.8  25.7  25.8  25.8
          Min: 0.1, Avg: 24.8, Max: 25.9, Diff: 25.8, Sum: 694.6]
         [CM RefProcessor Roots (ms):  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
          Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [Wait For Strong CLD (ms):  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
          Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [Weak CLD Roots (ms):  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
          Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
         [SATB Filtering (ms):  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
          Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Update RS (ms):  10.9  10.9  11.4  11.3  0.0  10.9  11.8  10.9  10.9  10.8  11.8  10.8  10.9  11.3  10.2  11.1  10.9  11.0  10.9  11.5  11.3  11.6  11.0  10.8  11.9  10.8  11.4  11.2
       Min: 0.0, Avg: 10.7, Max: 11.9, Diff: 11.9, Sum: 300.4]
         [Processed Buffers:  154  152  158  118  0  124  145  104  146  129  146  154  129  164  117  108  137  128  160  155  152  164  148  157  126  156  149  155
          Min: 0, Avg: 137.0, Max: 164, Diff: 164, Sum: 3835]
      [Scan RS (ms):  14.8  14.9  14.4  14.4  0.1  14.8  14.0  14.7  14.8  14.9  13.9  14.9  14.8  14.4  14.9  14.7  14.9  14.8  14.9  14.2  14.4  14.2  14.8  14.9  14.0  14.9  14.4  14.5
       Min: 0.1, Avg: 14.1, Max: 14.9, Diff: 14.9, Sum: 394.2]
      [Code Root Scanning (ms):  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0  0.0
       Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms):  28.4  28.4  28.3  28.5  0.4  28.5  28.4  28.6  28.5  28.4  28.5  28.5  28.4  28.4  28.4  28.5  28.4  28.4  28.4  28.4  28.4  28.4  28.5  28.4  28.4  28.4  28.4  28.4
       Min: 0.4, Avg: 27.4, Max: 28.6, Diff: 28.2, Sum: 767.9]
      [Termination (ms):  1416.0  1416.0  1416.1  1416.0  0.0  1416.0  1416.0  1416.1  1416.0  1416.1  1416.0  1416.0  1416.1  1416.1  1416.0  1416.0  1416.0  1416.0  1416.1  1416.0  1416.0  1416.0  1416.1  1416.0  1416.1  1416.0  1416.0  1416.1
       Min: 0.0, Avg: 1365.5, Max: 1416.1, Diff: 1416.1, Sum: 38233.0]
         [Termination Attempts:  6  4  2  1  1  2  2  2  6  1  5  3  4  2  2  3  2  4  3  5  2  2  1  3  3  2  5  3
          Min: 1, Avg: 2.9, Max: 6, Diff: 5, Sum: 81]
      [GC Worker Other (ms):  0.1  0.1  0.0  0.1  0.0  0.1  0.0  0.0  0.0  0.1  0.0  0.0  0.1  0.0  0.0  0.0  0.0  0.1  0.1  0.0  0.1  0.1  0.0  0.1  0.1  0.0  0.1  0.1
       Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 1.6]
      [GC Worker Total (ms):  1475.7  1475.7  1475.7  1475.7  1475.6  1475.7  1475.6  1475.6  1475.6  1475.6  1475.6  1475.6  1475.6  1475.6  1475.5  1475.5  1475.5  1475.5  1475.5  1475.5  1475.5  1475.5  1475.5  1475.5  1475.5  1475.4  1475.4  1475.5
       Min: 1475.4, Avg: 1475.6, Max: 1475.7, Diff: 0.4, Sum: 41315.7]
      [GC Worker End (ms):  3006818645.6  3006818645.7  3006818645.6  3006818645.7  3006818645.6  3006818645.7  3006818645.6  3006818645.7  3006818645.6  3006818645.7  3006818645.6  3006818645.6  3006818645.7  3006818645.7  3006818645.6  3006818645.7  3006818645.6  3006818645.7  3006818645.7  3006818645.6  3006818645.6  3006818645.7  3006818645.7  3006818645.7  3006818645.7  3006818645.6  3006818645.7  3006818645.7
       Min: 3006818645.6, Avg: 3006818645.7, Max: 3006818645.7, Diff: 0.1]
   [Code Root Fixup: 0.1 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 2.4 ms]
   [Other: 24.4 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.4 ms]
      [Ref Enq: 0.0 ms]
      [Redirty Cards: 1.1 ms]
         [Parallel Redirty:  0.7  0.7  0.7  0.7  0.7  0.7  0.7  0.7  0.7  0.7  0.7  0.7  0.7  0.6  0.6  0.6  0.6  0.6  0.6  0.6  0.6  0.6  0.6  0.6  0.5  0.5  0.5  0.5
          Min: 0.5, Avg: 0.6, Max: 0.7, Diff: 0.2, Sum: 17.8]
         [Redirtied Cards:  7601  9123  5417  5715  6705  6400  6061  5120  5108  4864  5474  5888  4352  5956  5623  5888  4096  5088  5224  2816  3744  3328  3457  5120  5572  5685  3328  3072
          Min: 2816, Avg: 5208.0, Max: 9123, Diff: 6307, Sum: 145825]
      [Humongous Register: 0.6 ms]
         [Humongous Total: 528]
         [Humongous Candidate: 76]
      [Humongous Reclaim: 0.2 ms]
         [Humongous Reclaimed: 0]
      [Free CSet: 7.0 ms]
         [Young Free CSet: 7.0 ms]
         [Non-Young Free CSet: 0.0 ms]
   [Eden: 2544.0M(2544.0M)->0.0B(1416.0M) Survivors: 112.0M->120.0M Heap: 14.2G(30.0G)->11.7G(30.0G)]
 [Times: user=40.84 sys=0.00, real=1.50 secs] 
2020-11-03T13:25:29.980+0800: 3006818.669: Total time for which application threads were stopped: 1.5302437 seconds, Stopping threads took: 0.0036071 second

jvm 参数：

-Xmx30720m
-Xms30720m
-XX:MaxGCPauseMillis=90
-XX:MaxTenuringThreshold=3
-XX:SurvivorRatio=8
-XX:MaxDirectMemorySize=10240m
-XX:+UnlockExperimentalVMOptions
-XX:G1LogLevel=finest
-XX:+PrintSafepointStatistics
-XX:PrintSafepointStatisticsCount=1
-XX:+SafepointTimeout
-XX:SafepointTimeoutDelay=1000
-XX:+ExplicitGCInvokesConcurrent
-XX:+HeapDumpOnOutOfMemoryError
-XX:HeapDumpPath=$log_dir
-XX:+PrintGCApplicationStoppedTime
-XX:+MonitorInUseLists
-XX:-UseBiasedLocking
-XX:+UseG1GC
-XX:G1NewSizePercent=5
-XX:InitiatingHeapOccupancyPercent=65 
-XX:+PrintGCDetails 
-XX:+PrintGCDateStamps
-XX:-OmitStackTraceInFastThrow

Answer 1

synchronized，总的来说，是有问题的。虽然它自从 java 开始就存在，但它在幕后的工作方式使 JVM（和 GC）一直为它做额外的工作。

关于locked/unlocked的信息通常存储在您要同步的Object的header中。当 BiasedLocking 可以工作时（它没有被禁用，或者 identityHashCode 没有禁用它，等等）并且没有争用 - 它很简单（而且很快）。关于拥有锁的线程的信息被持久化在Object的header中，因此以后的锁获取速度很快。不像你的例子：默认情况下你通过-UseBiasedLocking禁用它。

当 BiasedLocking 不可能（并且没有争用）时，有关锁的信息存储在 stack 上，使其仍然非常快。

另一方面，当 BiasedLocking 被禁用（无论出于何种原因）并且存在锁争用时，synchronized 将“膨胀”为 System-Monitor（OS 具体的 afaik）。这个监视器的地址仍然存储在 object 的监视器中，使它成为一个 bi-directional “映射”（简单地说）。但是根据 GC 这是堆引用的外部，它指向堆中 - 因此 GC root，因此它需要扫描。像这样的锁越多，GC 事件之间的时间越长，处理这些事件所需的时间就越多。

你可以通过添加一个特殊的标志来使这个阶段更快（最有可能）：-XX:+MonitorInUseLists（在 java-9 中默认打开并在 java-10 后被弃用）或重写使用 ReentrantLock 的代码以不同的方式处理这种“膨胀”。

young GC 发生时，ext root 扫描需要很长时间。可能的原因是什么？

When young GC occurs, ext root scanning takes a long time. What is the possible reason?

java

garbage-collection