我们的在线服务运行一段时间后，会有一个1秒长的年轻gc，每天只发生几次，详细的gc日志在末尾。
在28个gc线程中，一个线程在scan objectsynchronizer root阶段花费1秒，其他线程在这个阶段花费0秒。
我的问题是：
造成这种现象的原因可能是什么？
ext root扫描和objectsynchronizer root阶段在做什么？ext root扫描似乎是在扫描堆外的gc根？
关于环境，垃圾收集器是g1gc，openjdk1.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

1条答案

按热度按时间

ipakzgxi1#

synchronized 一般来说，是有问题的。尽管它从 java 乞讨之初就存在，但它在引擎盖下的工作方式使 JVM （和gc）一直为它做额外的工作。
关于 locked/unlocked 通常存储在同步对象的标头中。什么时候 BiasedLocking 可以工作（未禁用，或 identityHashCode 不禁用它，等等），并且没有争用-它很简单（而且很快）。有关拥有锁的线程的信息会持久保存在对象的头中，因此将来的锁获取会很快。与您的示例不同：您通过 -UseBiasedLocking .
什么时候 BiasedLocking 不可能（并且没有争用），有关锁的信息存储在 stack ，使它仍然相当快。
另一方面，当 BiasedLocking 被禁用（无论出于何种原因）并且锁上存在争用，则 synchronized 将“充气”到系统监视器( OS 特定afaik）。这个监视器的地址存储在对象的监视器中，这使得它成为一个双向的“Map”（简单地说）。但是根据 GC 这是堆引用的外部引用，指向堆-因此 GC root ，因此需要扫描。这样的锁越多，gc事件之间的间隔时间越长，处理这些事件所需的时间就越多。
通过添加一个特殊标志，可以使该阶段更快（最有可能）： -XX:+MonitorInUseLists （默认情况下，在 java-9 从那以后就被弃用了 java-10 )或者用 ReentrantLock 处理这种“膨胀”的方式完全不同。

赞(0）回复(0）举报 2021-07-08

java—当发生年轻的gc时，ext根扫描需要很长时间可能的原因是什么？

1条答案

相关问题

热门标签

最新问答