我的java应用程序在整个gc过程中停止了几乎190 ms，包括等待线程在“2022-10-26 16：08：37.285”到达安全点的时间。gc日志显示STW的时间只有30+ ms，所以我下载了vm日志，以检查长时间停止是否是由等待线程到达安全点和阻塞线程的阶段引起的。vm日志显示在“同步”阶段花费了183 ms。我想知道在"同步“阶段停止这么长时间的原因是什么。
gc日志：
2022-10-26T16:08:36.239+0800: 7081.719: [GC concurrent-root-region-scan-start]
2022-10-26T16:08:36.239+0800: 7081.719: Total time for which application threads were stopped: 0.0424589 seconds, Stopping threads took: 0.0001501 seconds
2022-10-26T16:08:36.279+0800: 7081.759: [GC concurrent-root-region-scan-end, 0.0402316 secs]
2022-10-26T16:08:36.279+0800: 7081.759: [GC concurrent-mark-start]
2022-10-26T16:08:37.246+0800: 7082.726: Application time: 1.0071790 seconds
2022-10-26T16:08:37.248+0800: 7082.727: [GC pause (G1 Evacuation Pause) (young) 7082.727: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 8541, predicted base time: 7.41 ms, remaining time: 27.59 ms, target pause time: 35.00 ms]
7082.727: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 85 regions, survivors: 17 regions, predicted young region time: 24.66 ms]
7082.727: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 85 regions, survivors: 17 regions, old: 0 regions, predicted pause time: 32.08 ms, target pause time: 35.00 ms]
, 0.0355926 secs]
[Parallel Time: 32.8 ms, GC Workers: 10]
[GC Worker Start (ms): Min: 7082727.6, Avg: 7082727.6, Max: 7082727.6, Diff: 0.1]
[Ext Root Scanning (ms): Min: 0.3, Avg: 0.9, Max: 2.2, Diff: 1.9, Sum: 9.0]
[Update RS (ms): Min: 1.9, Avg: 3.1, Max: 3.4, Diff: 1.5, Sum: 30.8]
[Processed Buffers: Min: 9, Avg: 15.4, Max: 23, Diff: 14, Sum: 154]
[Scan RS (ms): Min: 3.2, Avg: 3.9, Max: 4.1, Diff: 0.8, Sum: 39.2]
[Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Object Copy (ms): Min: 24.6, Avg: 24.7, Max: 25.2, Diff: 0.6, Sum: 247.2]
[Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
[Termination Attempts: Min: 1, Avg: 25.9, Max: 40, Diff: 39, Sum: 259]
[GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.2]
[GC Worker Total (ms): Min: 32.7, Avg: 32.7, Max: 32.7, Diff: 0.1, Sum: 327.1]
[GC Worker End (ms): Min: 7082760.3, Avg: 7082760.3, Max: 7082760.3, Diff: 0.0]
[Code Root Fixup: 0.0 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.8 ms]
[Other: 1.9 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 0.3 ms]
[Ref Enq: 0.0 ms]
[Redirty Cards: 0.2 ms]
[Humongous Register: 0.2 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 0.3 ms]
[Eden: 680.0M(680.0M)->0.0B(3192.0M) Survivors: 136.0M->80.0M Heap: 9831.7M(16.0G)->9154.2M(16.0G)]
[Times: user=0.32 sys=0.01, real=0.04 secs]
2022-10-26T16:08:37.283+0800: 7082.763: Total time for which application threads were stopped: 0.0368899 seconds, Stopping threads took: 0.0001211 seconds
2022-10-26T16:08:39.807+0800: 7085.287: [GC concurrent-mark-end, 3.5278637 secs]
2022-10-26T16:08:39.807+0800: 7085.287: Application time: 2.5240566 seconds
2022-10-26T16:08:39.808+0800: 7085.288: [GC remark 2022-10-26T16:08:39.808+0800: 7085.288: [Finalize Marking, 0.0004663 secs] 2022-10-26T16:08:39.809+0800: 7085.289: [GC ref-proc, 0.0004983 secs] 2022-10-26T16:08:39.809+0800: 7085.289: [Unloading, 0.0123397 secs], 0.0222890 secs]
[Times: user=0.17 sys=0.04, real=0.03 secs]
2022-10-26T16:08:39.831+0800: 7085.310: Total time for which application threads were stopped: 0.0233879 seconds, Stopping threads took: 0.0001474 seconds
2022-10-26T16:08:39.831+0800: 7085.310: Application time: 0.0000378 seconds
2022-10-26T16:08:39.832+0800: 7085.311: [GC cleanup 10G->10G(16G), 0.0194897 secs]
[Times: user=0.16 sys=0.03, real=0.02 secs]
2022-10-26T16:08:39.851+0800: 7085.331: Total time for which application threads were stopped: 0.0204211 seconds, Stopping threads took: 0.0001703 seconds
2022-10-26T16:08:41.088+0800: 7086.568: Application time: 1.2366444 seconds
2022-10-26T16:08:41.089+0800: 7086.569: Total time for which application threads were stopped: 0.0011031 seconds, Stopping threads took: 0.0002013 seconds
2022-10-26T16:08:41.089+0800: 7086.569: Application time: 0.0000264 seconds
2022-10-26T16:08:41.090+0800: 7086.569: Total time for which application threads were stopped: 0.0006572 seconds, Stopping threads took: 0.0000450 seconds
2022-10-26T16:08:42.038+0800: 7087.518: Application time: 0.9482548 secondsvm日志：
7069.947: G1IncCollectionPause [ 290 0 0 ] [ 0 0 0 0 33 ] 0
vmop [threads: total initially_running wait_to_block] [time: spin block sync cleanup vmop] page_trap_count
7074.822: G1IncCollectionPause [ 290 1 1 ] [ 0 0 0 0 33 ] 0
vmop [threads: total initially_running wait_to_block] [time: spin block sync cleanup vmop] page_trap_count
7076.947: G1IncCollectionPause [ 290 1 3 ] [ 0 0 0 0 33 ] 0
vmop [threads: total initially_running wait_to_block] [time: spin block sync cleanup vmop] page_trap_count
7081.676: G1IncCollectionPause [ 290 1 4 ] [ 0 0 0 0 41 ] 0
vmop [threads: total initially_running wait_to_block] [time: spin block sync cleanup vmop] page_trap_count
7082.543: G1IncCollectionPause [ 290 0 0 ] [ 0 0 183 0 35 ] 0
vmop [threads: total initially_running wait_to_block] [time: spin block sync cleanup vmop] page_trap_count
7085.287: CGC_Operation [ 290 0 2 ] [ 0 0 0 0 22 ] 0
vmop [threads: total initially_running wait_to_block] [time: spin block sync cleanup vmop] page_trap_count
7085.311: CGC_Operation [ 290 2 2 ] [ 0 0 0 0 19 ] 2
vmop [threads: total initially_running wait_to_block] [time: spin block sync cleanup vmop] page_trap_count
7086.567: FindDeadlocks [ 290 2 6 ] [ 0 0 0 0 0 ] 0我想知道是什么原因导致在“同步”阶段停止这么长时间，以及如何解决这个问题
1条答案
按热度按时间imzjd6km1#
您日志不足以找到解决方案，但它显示了问题来源VM希望到达安全点，所有线程都应在已知点停止要到达安全点 *.，所有线程都必须停止有些线程可以到达安全点并停止，但有些线程由于尚未观察到它而继续工作操作停止线程正在等待运行线程这次，表示为sync**关键字这意味着，同步是发送安全点请求和阻塞所有java线程之间的总时间。所以你的应用程序正在等待停止所有java线程。这可能有很多原因，但我知道的主要原因是：
1.长循环
1.运行状态上的线程太多
1.大型数据副本，例如
System.arraycopy()This pdf（第199页）很好地解释了TTSP（安全点时间）。（这是用shenandoah GC解释的，但足以理解）