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

Question

After our online service has been running for a period of time, there will be a one second long young GC, it only happens a few times a day, detailed GC logs are at the end.

In 28 GC threads,one thread takes one second in the scan ObjectSynchronizer root phase,and the other threads spend 0 in this phase.

My question is:

What may be the cause of this phenomenon?
What are the EXT root scanning and objectsynchronizer roots phases doing? It seems that ext root scanning is scanning GC roots outside the heap?

About the environment,garbage collector is g1 gc, openjdk 1.8.

Thanks!

The original problem is not clear enough and has been revised

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 args:

-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

user_1059372 · Answer

synchronized, in general, is problematic. Though it exists since the very begging in java, the way it works under the hood makes the JVM (and GC) do additional work for it - all the time.

The information about locked/unlocked is usually stored in the header of the Object you are synchronizing against. When BiasedLocking can work (it is not disabled, or identityHashCode does not disable it, etc) and there is no contention - it is simple (and fast). The information about the thread that owns the lock is persisted in the header of the Object, so future lock acquisitions are fast. Unlike your example : where you disable it by default via -UseBiasedLocking.

When that BiasedLocking is not possible (and there is no contention), the information about the lock is stored on the stack, making it still pretty fast.

On the other hand when BiasedLocking is disabled (for whatever reason) and there is contention on a lock, a synchronized will be "inflated" to a System-Monitor (OS specific afaik). The address of this monitor is stored in the monitor of the object still, making this a bi-directional "mapping" (to be put simple). But according to GC this is an external to the heap reference, that points into the heap - thus a GC root, thus it needs scanning. The more locks you have like this and the more time between GC events, the more time it takes to take care of these.

You can make that phase much faster (most probably) by adding a special flag : -XX:+MonitorInUseLists (that is on by default in java-9 and deprecated since java-10) or rewrite the code using ReentrantLock that handles this "inflating" rather differently.

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

1 Answers