G1 GC shows large time in Other phase

Solution Unverified - Updated 13 Jun 2024

Environment

Java 11
G1 GC

Issue

In our GC logging, we see occassionally see a long time spent in the Other phase. What would contribute to a large spike here?

[2022-10-09T13:16:39.707+0000][3783.195s][debug][gc,heap           ] GC(9) Heap before GC invocations=9 (full 0): garbage-first heap   total 10743808K, used 1819374K [0x0000000570400000, 0x0000000800000000)
[2022-10-09T13:16:49.276+0000][3792.764s][debug][gc,heap           ] GC(9)   region size 4096K, 425 young (1740800K), 7 survivors (28672K)
[2022-10-09T13:16:49.276+0000][3792.764s][debug][gc,heap           ] GC(9)  Metaspace       used 91225K, capacity 98503K, committed 98816K, reserved 339968K
[2022-10-09T13:16:49.276+0000][3792.764s][debug][gc,heap           ] GC(9)   class space    used 10833K, capacity 13361K, committed 13440K, reserved 253952K
[2022-10-09T13:16:49.276+0000][3792.764s][info ][gc,start          ] GC(9) Pause Young (Normal) (G1 Evacuation Pause)
[2022-10-09T13:16:49.276+0000][3792.764s][info ][gc,task           ] GC(9) Using 8 workers of 8 for evacuation
[2022-10-09T13:16:49.276+0000][3792.764s][debug][gc,tlab           ] GC(9) TLAB totals: thrds: 223  refills: 9596 max: 462 slow allocs: 767 max 41 waste:  1.5% gc: 16198888B max: 1568112B slow: 6511096B max: 409312B fast: 0B max: 0B
[2022-10-09T13:16:49.276+0000][3792.764s][debug][gc,alloc,region   ] GC(9) Mutator Allocation stats, regions: 418, wasted size: 4224B ( 0.0%)
[2022-10-09T13:16:49.276+0000][3792.764s][debug][gc,age            ] GC(9) Desired survivor size 113246208 bytes, new threshold 15 (max threshold 15)
[2022-10-09T13:16:49.276+0000][3792.764s][debug][gc,ergo,cset      ] GC(9) Finish choosing CSet. old: 0 regions, predicted old region time: 0.00ms, time remaining: 0.43
[2022-10-09T13:16:49.276+0000][3792.764s][debug][gc,refine         ] Activated worker 0, on threshold: 19, current: 80
[2022-10-09T13:16:49.287+0000][3792.776s][debug][gc,ergo           ] GC(9) Running G1 Clear Card Table Task using 4 workers for 4 units of work for 446 regions.
[2022-10-09T13:16:49.288+0000][3792.776s][debug][gc,ref            ] GC(9) Skipped phase1 of Reference Processing due to unavailable references
[2022-10-09T13:16:49.288+0000][3792.776s][debug][gc,ergo           ] GC(9) Running G1 Free Collection Set using 8 workers for collection set length 425
[2022-10-09T13:16:49.289+0000][3792.777s][debug][gc,ihop           ] GC(9) Basic information (value update), threshold: 7701161574B (70.00), target occupancy: 11001659392B, current occupancy: 115332592B, recent allocation size: 0B, recent allocation duration: 773718.23ms, recent old gen allocation rate: 0.00B/s, recent marking phase length: 0.00ms
[2022-10-09T13:16:49.289+0000][3792.777s][debug][gc,ihop           ] GC(9) Adaptive IHOP information (value update), threshold: 7701161574B (82.35), internal target occupancy: 9351410483B, occupancy: 115332592B, additional buffer size: 2462056448B, predicted old gen allocation rate: 18218.99B/s, predicted marking phase length: 0.00ms, prediction active: false
[2022-10-09T13:16:49.289+0000][3792.777s][debug][gc,ergo,refine    ] GC(9) Updated Refinement Zones: green: 16, yellow: 48, red: 80
[2022-10-09T13:16:49.289+0000][3792.777s][info ][gc,phases         ] GC(9)   Pre Evacuate Collection Set: 0.1ms
[2022-10-09T13:16:49.289+0000][3792.777s][debug][gc,phases         ] GC(9)     Prepare TLABs: 0.1ms
[2022-10-09T13:16:49.289+0000][3792.777s][debug][gc,phases         ] GC(9)     Choose Collection Set: 0.0ms
[2022-10-09T13:16:49.289+0000][3792.777s][debug][gc,phases         ] GC(9)     Humongous Register: 0.1ms
[2022-10-09T13:16:49.289+0000][3792.777s][info ][gc,phases         ] GC(9)   Evacuate Collection Set: 10.7ms
[2022-10-09T13:16:49.289+0000][3792.777s][debug][gc,phases         ] GC(9)     Ext Root Scanning (ms):   Min:  0.9, Avg:  1.0, Max:  1.0, Diff:  0.1, Sum:  7.8, Workers: 8
[2022-10-09T13:16:49.289+0000][3792.777s][debug][gc,phases         ] GC(9)     Update RS (ms):           Min:  0.4, Avg:  0.7, Max:  1.6, Diff:  1.2, Sum:  5.5, Workers: 8
[2022-10-09T13:16:49.289+0000][3792.777s][debug][gc,phases         ] GC(9)       Processed Buffers:        Min: 1, Avg: 26.9, Max: 111, Diff: 110, Sum: 215, Workers: 8
[2022-10-09T13:16:49.289+0000][3792.777s][debug][gc,phases         ] GC(9)       Scanned Cards:            Min: 194, Avg: 509.4, Max: 1890, Diff: 1696, Sum: 4075, Workers: 8
[2022-10-09T13:16:49.289+0000][3792.777s][debug][gc,phases         ] GC(9)       Skipped Cards:            Min: 0, Avg:  1.8, Max: 8, Diff: 8, Sum: 14, Workers: 8
[2022-10-09T13:16:49.289+0000][3792.777s][debug][gc,phases         ] GC(9)     Scan RS (ms):             Min:  0.0, Avg:  0.0, Max:  0.1, Diff:  0.1, Sum:  0.3, Workers: 8
[2022-10-09T13:16:49.289+0000][3792.777s][debug][gc,phases         ] GC(9)       Scanned Cards:            Min: 0, Avg:  2.6, Max: 21, Diff: 21, Sum: 21, Workers: 8
[2022-10-09T13:16:49.289+0000][3792.777s][debug][gc,phases         ] GC(9)       Claimed Cards:            Min: 0, Avg:  4.4, Max: 32, Diff: 32, Sum: 35, Workers: 8
[2022-10-09T13:16:49.289+0000][3792.777s][debug][gc,phases         ] GC(9)       Skipped Cards:            Min: 0, Avg:  2.1, Max: 17, Diff: 17, Sum: 17, Workers: 8
[2022-10-09T13:16:49.289+0000][3792.777s][debug][gc,phases         ] GC(9)     Code Root Scanning (ms):  Min:  0.0, Avg:  0.2, Max:  1.1, Diff:  1.1, Sum:  1.4, Workers: 8
[2022-10-09T13:16:49.289+0000][3792.777s][debug][gc,phases         ] GC(9)     AOT Root Scanning (ms):   skipped
[2022-10-09T13:16:49.289+0000][3792.777s][debug][gc,phases         ] GC(9)     Object Copy (ms):         Min:  7.5, Avg:  8.5, Max:  8.9, Diff:  1.5, Sum: 67.7, Workers: 8
[2022-10-09T13:16:49.289+0000][3792.777s][debug][gc,phases         ] GC(9)     Termination (ms):         Min:  0.0, Avg:  0.0, Max:  0.0, Diff:  0.0, Sum:  0.0, Workers: 8
[2022-10-09T13:16:49.289+0000][3792.777s][debug][gc,phases         ] GC(9)       Termination Attempts:     Min: 1, Avg:  1.0, Max: 1, Diff: 0, Sum: 8, Workers: 8
[2022-10-09T13:16:49.289+0000][3792.777s][debug][gc,phases         ] GC(9)     GC Worker Other (ms):     Min:  0.1, Avg:  0.2, Max:  0.3, Diff:  0.3, Sum:  1.7, Workers: 8
[2022-10-09T13:16:49.289+0000][3792.777s][debug][gc,phases         ] GC(9)     GC Worker Total (ms):     Min: 10.4, Avg: 10.5, Max: 10.7, Diff:  0.3, Sum: 84.3, Workers: 8
[2022-10-09T13:16:49.289+0000][3792.777s][info ][gc,phases         ] GC(9)   Post Evacuate Collection Set: 1.2ms
[2022-10-09T13:16:49.289+0000][3792.777s][debug][gc,phases         ] GC(9)     Code Roots Fixup: 0.0ms
[2022-10-09T13:16:49.289+0000][3792.777s][debug][gc,phases         ] GC(9)     Clear Card Table: 0.3ms
[2022-10-09T13:16:49.289+0000][3792.777s][debug][gc,phases         ] GC(9)     Reference Processing: 0.2ms
[2022-10-09T13:16:49.289+0000][3792.777s][debug][gc,phases,ref     ] GC(9)       Reconsider SoftReferences: 0.0ms
[2022-10-09T13:16:49.289+0000][3792.777s][debug][gc,phases,ref     ] GC(9)         SoftRef (ms):             skipped
[2022-10-09T13:16:49.289+0000][3792.777s][debug][gc,phases,ref     ] GC(9)       Notify Soft/WeakReferences: 0.1ms
[2022-10-09T13:16:49.289+0000][3792.777s][debug][gc,phases,ref     ] GC(9)         SoftRef (ms):             Min:  0.0, Avg:  0.0, Max:  0.0, Diff:  0.0, Sum:  0.0, Workers: 1
[2022-10-09T13:16:49.289+0000][3792.777s][debug][gc,phases,ref     ] GC(9)         WeakRef (ms):             Min:  0.0, Avg:  0.0, Max:  0.0, Diff:  0.0, Sum:  0.0, Workers: 1
[2022-10-09T13:16:49.289+0000][3792.777s][debug][gc,phases,ref     ] GC(9)         FinalRef (ms):            Min:  0.0, Avg:  0.0, Max:  0.0, Diff:  0.0, Sum:  0.0, Workers: 1
[2022-10-09T13:16:49.289+0000][3792.777s][debug][gc,phases,ref     ] GC(9)         Total (ms):               Min:  0.0, Avg:  0.0, Max:  0.0, Diff:  0.0, Sum:  0.0, Workers: 1
[2022-10-09T13:16:49.289+0000][3792.777s][debug][gc,phases,ref     ] GC(9)       Notify and keep alive finalizable: 0.1ms
[2022-10-09T13:16:49.289+0000][3792.777s][debug][gc,phases,ref     ] GC(9)         Balance queues: 0.0ms
[2022-10-09T13:16:49.289+0000][3792.777s][debug][gc,phases,ref     ] GC(9)         FinalRef (ms):            Min:  0.0, Avg:  0.0, Max:  0.1, Diff:  0.0, Sum:  0.3, Workers: 8
[2022-10-09T13:16:49.289+0000][3792.777s][debug][gc,phases,ref     ] GC(9)       Notify PhantomReferences: 0.0ms
[2022-10-09T13:16:49.289+0000][3792.777s][debug][gc,phases,ref     ] GC(9)         PhantomRef (ms):          Min:  0.0, Avg:  0.0, Max:  0.0, Diff:  0.0, Sum:  0.0, Workers: 1
[2022-10-09T13:16:49.289+0000][3792.777s][debug][gc,phases,ref     ] GC(9)       SoftReference:
[2022-10-09T13:16:49.289+0000][3792.777s][debug][gc,phases,ref     ] GC(9)         Discovered: 0
[2022-10-09T13:16:49.289+0000][3792.777s][debug][gc,phases,ref     ] GC(9)         Cleared: 0
[2022-10-09T13:16:49.289+0000][3792.777s][debug][gc,phases,ref     ] GC(9)       WeakReference:
[2022-10-09T13:16:49.289+0000][3792.777s][debug][gc,phases,ref     ] GC(9)         Discovered: 5
[2022-10-09T13:16:49.289+0000][3792.777s][debug][gc,phases,ref     ] GC(9)         Cleared: 5
[2022-10-09T13:16:49.289+0000][3792.777s][debug][gc,phases,ref     ] GC(9)       FinalReference:
[2022-10-09T13:16:49.289+0000][3792.777s][debug][gc,phases,ref     ] GC(9)         Discovered: 38
[2022-10-09T13:16:49.289+0000][3792.777s][debug][gc,phases,ref     ] GC(9)         Cleared: 0
[2022-10-09T13:16:49.289+0000][3792.777s][debug][gc,phases,ref     ] GC(9)       PhantomReference:
[2022-10-09T13:16:49.289+0000][3792.777s][debug][gc,phases,ref     ] GC(9)         Discovered: 2
[2022-10-09T13:16:49.289+0000][3792.777s][debug][gc,phases,ref     ] GC(9)         Cleared: 2
[2022-10-09T13:16:49.289+0000][3792.777s][debug][gc,phases         ] GC(9)     Weak Processing: 0.1ms
[2022-10-09T13:16:49.289+0000][3792.777s][debug][gc,phases         ] GC(9)     Merge Per-Thread State: 0.0ms
[2022-10-09T13:16:49.289+0000][3792.777s][debug][gc,phases         ] GC(9)     Code Roots Purge: 0.0ms
[2022-10-09T13:16:49.289+0000][3792.777s][debug][gc,phases         ] GC(9)     Redirty Cards: 0.0ms
[2022-10-09T13:16:49.289+0000][3792.777s][debug][gc,phases         ] GC(9)     DerivedPointerTable Update: 0.0ms
[2022-10-09T13:16:49.289+0000][3792.777s][debug][gc,phases         ] GC(9)     Free Collection Set: 0.5ms
[2022-10-09T13:16:49.289+0000][3792.777s][debug][gc,phases         ] GC(9)     Humongous Reclaim: 0.0ms
[2022-10-09T13:16:49.289+0000][3792.777s][debug][gc,phases         ] GC(9)     Start New Collection Set: 0.0ms
[2022-10-09T13:16:49.289+0000][3792.777s][debug][gc,phases         ] GC(9)     Resize TLABs: 0.0ms
[2022-10-09T13:16:49.289+0000][3792.777s][debug][gc,phases         ] GC(9)     Expand Heap After Collection: 0.0ms
[2022-10-09T13:16:49.289+0000][3792.777s][info ][gc,phases         ] GC(9)   Other: 9569.7ms
[2022-10-09T13:16:49.289+0000][3792.777s][info ][gc,heap           ] GC(9) Eden regions: 418->0(580)
[2022-10-09T13:16:49.289+0000][3792.777s][info ][gc,heap           ] GC(9) Survivor regions: 7->7(54)
[2022-10-09T13:16:49.289+0000][3792.777s][info ][gc,heap           ] GC(9) Old regions: 22->22
[2022-10-09T13:16:49.289+0000][3792.777s][info ][gc,heap           ] GC(9) Humongous regions: 0->0
[2022-10-09T13:16:49.289+0000][3792.777s][info ][gc,metaspace      ] GC(9) Metaspace: 91225K->91225K(339968K)
[2022-10-09T13:16:49.289+0000][3792.777s][debug][gc,heap           ] GC(9) Heap after GC invocations=10 (full 0): garbage-first heap   total 10743808K, used 112629K [0x0000000570400000, 0x0000000800000000)
[2022-10-09T13:16:49.289+0000][3792.777s][debug][gc,heap           ] GC(9)   region size 4096K, 7 young (28672K), 7 survivors (28672K)
[2022-10-09T13:16:49.289+0000][3792.777s][debug][gc,heap           ] GC(9)  Metaspace       used 91225K, capacity 98503K, committed 98816K, reserved 339968K
[2022-10-09T13:16:49.289+0000][3792.777s][debug][gc,heap           ] GC(9)   class space    used 10833K, capacity 13361K, committed 13440K, reserved 253952K
[2022-10-09T13:16:49.289+0000][3792.777s][info ][gc                ] GC(9) Pause Young (Normal) (G1 Evacuation Pause) 1780M->109M(10492M) 13.288ms
[2022-10-09T13:16:49.289+0000][3792.777s][info ][gc,cpu            ] GC(9) User=0.07s Sys=0.01s Real=0.01s

Resolution

Address any file I/O concerns
Java 17+ offers a -Xlog:async mode so the GC log file writes are done outside of a safe point pause to avoid such a pause inflation from a slow file write
- Content from bugs.openjdk.org is not included.JDK-8229517
- Content from bugs.openjdk.org is not included.JDK-8267077

Root Cause

Other simply reports the total time spent in a pause minus any amount tracked in another known phase. So much time in Other is rare and would account for any time spent outside reported GC phases. But a large Other time can be produced as follows
- "Total time" counter starts for the pause
- GC timer starts
- GC workers start and complete GC accounting for their phase time
- GC timer stops; logs report short GC time;
- "Total time" counter stops; includes STALL
- Reporting code computes (total - sum[phases]) for Other, and that includes the stall
A likely source of a stall at the point to just produce a high Other time is file I/O and a long blocking write to the GC log. Consider the example logging in this issue. The delay in that GC operation is specifically between these two log lines:

[2022-10-09T13:16:39.707+0000][3783.195s][debug][gc,heap           ] GC(9) Heap before GC invocations=9 (full 0): garbage-first heap   total 10743808K, used 1819374K [0x0000000570400000, 0x0000000800000000)
[2022-10-09T13:16:49.276+0000][3792.764s][debug][gc,heap           ] GC(9)   region size 4096K, 425 young (1740800K), 7 survivors (28672K)

Note that these log lines basically come from Content from github.com is not included.the adjacent code lines in the same method without much of note occurring to inflate time here aside from the GC log file write:

Diagnostic Steps

Investigate any slow file I/O concerns negatively impacting the GC log write

SBR

JVM & Diagnostics

Product(s)

Red Hat JBoss Enterprise Application Platform

Components

java-11-openjdk

Category

Troubleshoot

Tags

This solution is part of Red Hat’s fast-track publication program, providing a huge library of solutions that Red Hat engineers have created while supporting our customers. To give you the knowledge you need the instant it becomes available, these articles may be presented in a raw and unedited form.