-
Bug
-
Resolution: Fixed
-
P4
-
None
-
repo-shenandoah
We recently strengthened this assertion for the generational mode and it failed during a stress test.
It looks like a simulated allocation failure shortly before/after final mark may have caused a barrier call to be out of sync with the heap state (the GC having been recently cancelled).
```
[2024-09-27T03:07:35.725+0000][648.039s][4012][info][gc ] GC(21) Concurrent marking (YOUNG) 6659.600ms
[2024-09-27T03:07:35.725+0000][648.039s][4016][info][gc,start ] GC(21) Pause Final Mark (YOUNG)
[2024-09-27T03:07:35.725+0000][648.039s][4016][info][gc,task ] GC(21) Using 4 of 4 workers for final marking
[2024-09-27T03:07:35.728+0000][648.042s][4016][info][gc,remset ] GC(21) Scan remembered set using bitmap: false
[2024-09-27T03:07:35.730+0000][648.044s][4016][info][gc,age ] GC(21) - age 1: prev 1923733208 bytes, curr 25344 bytes, mortality 1.00
[2024-09-27T03:07:35.730+0000][648.044s][4016][info][gc,age ] GC(21) - age 2: prev 1465392 bytes, curr 1465280 bytes, mortality 0.00
[2024-09-27T03:07:35.730+0000][648.044s][4016][info][gc,age ] GC(21) ----------------------------------------------------------------------------
[2024-09-27T03:07:35.730+0000][648.044s][4016][info][gc,age ] GC(21) - age 4: prev 240 bytes, curr 0 bytes, mortality 1.00
[2024-09-27T03:07:35.730+0000][648.044s][4016][info][gc,age ] GC(21) Skipped: 0 (0.00), R-Aged: 0 (0.00), Clamped: 0 (0.00), R-Young: 0 (0.00)
[2024-09-27T03:07:35.730+0000][648.044s][4016][info][gc,ergo ] GC(21) Planning to promote in place 0 humongous regions and 0 regular regions, spanning a total of 0 used bytes
[2024-09-27T03:07:35.731+0000][648.044s][4016][info][gc,ergo ] GC(21) Adaptive CSet Selection for YOUNG. Max Evacuation: 422M, Actual Free: 4096K.
[2024-09-27T03:07:35.731+0000][648.044s][4016][info][gc,ergo ] GC(21) Chosen CSet evacuates young: 421M (of which at least: 0B are to be promoted), old: 0B
[2024-09-27T03:07:35.731+0000][648.044s][4016][info][gc,ergo ] GC(21) Collectable Garbage: 1410M (98%), Immediate: 4096K (0%), 1 regions, CSet: 1406M (98%), 457 regions
[2024-09-27T03:07:35.731+0000][648.044s][4016][info][gc,ergo ] GC(21) Evacuation Targets: YOUNG: 421M, PROMOTE: 0B, OLD: 0B, TOTAL: 421M
[2024-09-27T03:07:35.731+0000][648.044s][4016][info][gc ] GC(21) Transfer 1 region(s) from OLD to YOUNG, yielding increased size: 10136M
[2024-09-27T03:07:35.731+0000][648.044s][4016][info][gc,ergo ] GC(21) Successfully transferred 1 excess regions to young before start of evacuation
[2024-09-27T03:07:35.731+0000][648.044s][4016][info][gc ] GC(21) Transfer 1 region(s) from YOUNG to OLD, yielding increased size: 108M
[2024-09-27T03:07:35.731+0000][648.045s][4016][info][gc,free ] Free: 6464M, Max: 4096K regular, 4464M humongous, Frag: 31% external, 0% internal; Used: 7794K, Mutator Free: 1617 Collector Reserve: 508M, Max: 4096K; Used: 0B Old Collector Reserve: 9260K, Max: 4096K; Used: 11219K
[2024-09-27T03:07:35.731+0000][648.045s][4016][info][gc,start ] GC(21) Verify Before Evacuation, Level 4
[2024-09-27T03:07:35.822+0000][648.136s][4004][info][gc,remset ] GC(21) Scan remembered set using bitmap: false
[2024-09-27T03:07:35.822+0000][648.136s][4006][info][gc,remset ] GC(21) Scan remembered set using bitmap: false
[2024-09-27T03:07:35.823+0000][648.136s][4005][info][gc,remset ] GC(21) Scan remembered set using bitmap: false
[2024-09-27T03:07:35.823+0000][648.136s][4007][info][gc,remset ] GC(21) Scan remembered set using bitmap: false
[2024-09-27T03:07:39.669+0000][651.983s][4015][info][gc ] Periodic Sample: GCU = 16.036%, MU = 0.432% during most recent 5.0s
[2024-09-27T03:07:42.290+0000][654.604s][4016][info][gc ] GC(21) Verify Before Evacuation, Level 4 (27287693 reachable, 3089176 marked)
[2024-09-27T03:07:42.290+0000][654.604s][4016][info][gc ] GC(21) Pause Final Mark (YOUNG) 6564.997ms
[2024-09-27T03:07:42.291+0000][654.605s][4016][info][safepoint,stats] ShenandoahFinalMarkStartEvac [ 360 0 ][ 49938 6565240657 6565290595 ] 0
[2024-09-27T03:07:42.291+0000][654.605s][4016][info][safepoint ] Safepoint "ShenandoahFinalMarkStartEvac", Time since last: 6715492601 ns, Reaching safepoint: 49938 ns, At safepoint: 6565240657 ns, Total: 6565290595 ns
[2024-09-27T03:07:42.291+0000][654.605s][5076][info][gc ] Failed to allocate 16B for evacuation
[2024-09-27T03:07:42.291+0000][654.605s][5076][info][gc ] Cancelling GC: Allocation Failure During Evacuation
```
It looks like a simulated allocation failure shortly before/after final mark may have caused a barrier call to be out of sync with the heap state (the GC having been recently cancelled).
```
[2024-09-27T03:07:35.725+0000][648.039s][4012][info][gc ] GC(21) Concurrent marking (YOUNG) 6659.600ms
[2024-09-27T03:07:35.725+0000][648.039s][4016][info][gc,start ] GC(21) Pause Final Mark (YOUNG)
[2024-09-27T03:07:35.725+0000][648.039s][4016][info][gc,task ] GC(21) Using 4 of 4 workers for final marking
[2024-09-27T03:07:35.728+0000][648.042s][4016][info][gc,remset ] GC(21) Scan remembered set using bitmap: false
[2024-09-27T03:07:35.730+0000][648.044s][4016][info][gc,age ] GC(21) - age 1: prev 1923733208 bytes, curr 25344 bytes, mortality 1.00
[2024-09-27T03:07:35.730+0000][648.044s][4016][info][gc,age ] GC(21) - age 2: prev 1465392 bytes, curr 1465280 bytes, mortality 0.00
[2024-09-27T03:07:35.730+0000][648.044s][4016][info][gc,age ] GC(21) ----------------------------------------------------------------------------
[2024-09-27T03:07:35.730+0000][648.044s][4016][info][gc,age ] GC(21) - age 4: prev 240 bytes, curr 0 bytes, mortality 1.00
[2024-09-27T03:07:35.730+0000][648.044s][4016][info][gc,age ] GC(21) Skipped: 0 (0.00), R-Aged: 0 (0.00), Clamped: 0 (0.00), R-Young: 0 (0.00)
[2024-09-27T03:07:35.730+0000][648.044s][4016][info][gc,ergo ] GC(21) Planning to promote in place 0 humongous regions and 0 regular regions, spanning a total of 0 used bytes
[2024-09-27T03:07:35.731+0000][648.044s][4016][info][gc,ergo ] GC(21) Adaptive CSet Selection for YOUNG. Max Evacuation: 422M, Actual Free: 4096K.
[2024-09-27T03:07:35.731+0000][648.044s][4016][info][gc,ergo ] GC(21) Chosen CSet evacuates young: 421M (of which at least: 0B are to be promoted), old: 0B
[2024-09-27T03:07:35.731+0000][648.044s][4016][info][gc,ergo ] GC(21) Collectable Garbage: 1410M (98%), Immediate: 4096K (0%), 1 regions, CSet: 1406M (98%), 457 regions
[2024-09-27T03:07:35.731+0000][648.044s][4016][info][gc,ergo ] GC(21) Evacuation Targets: YOUNG: 421M, PROMOTE: 0B, OLD: 0B, TOTAL: 421M
[2024-09-27T03:07:35.731+0000][648.044s][4016][info][gc ] GC(21) Transfer 1 region(s) from OLD to YOUNG, yielding increased size: 10136M
[2024-09-27T03:07:35.731+0000][648.044s][4016][info][gc,ergo ] GC(21) Successfully transferred 1 excess regions to young before start of evacuation
[2024-09-27T03:07:35.731+0000][648.044s][4016][info][gc ] GC(21) Transfer 1 region(s) from YOUNG to OLD, yielding increased size: 108M
[2024-09-27T03:07:35.731+0000][648.045s][4016][info][gc,free ] Free: 6464M, Max: 4096K regular, 4464M humongous, Frag: 31% external, 0% internal; Used: 7794K, Mutator Free: 1617 Collector Reserve: 508M, Max: 4096K; Used: 0B Old Collector Reserve: 9260K, Max: 4096K; Used: 11219K
[2024-09-27T03:07:35.731+0000][648.045s][4016][info][gc,start ] GC(21) Verify Before Evacuation, Level 4
[2024-09-27T03:07:35.822+0000][648.136s][4004][info][gc,remset ] GC(21) Scan remembered set using bitmap: false
[2024-09-27T03:07:35.822+0000][648.136s][4006][info][gc,remset ] GC(21) Scan remembered set using bitmap: false
[2024-09-27T03:07:35.823+0000][648.136s][4005][info][gc,remset ] GC(21) Scan remembered set using bitmap: false
[2024-09-27T03:07:35.823+0000][648.136s][4007][info][gc,remset ] GC(21) Scan remembered set using bitmap: false
[2024-09-27T03:07:39.669+0000][651.983s][4015][info][gc ] Periodic Sample: GCU = 16.036%, MU = 0.432% during most recent 5.0s
[2024-09-27T03:07:42.290+0000][654.604s][4016][info][gc ] GC(21) Verify Before Evacuation, Level 4 (27287693 reachable, 3089176 marked)
[2024-09-27T03:07:42.290+0000][654.604s][4016][info][gc ] GC(21) Pause Final Mark (YOUNG) 6564.997ms
[2024-09-27T03:07:42.291+0000][654.605s][4016][info][safepoint,stats] ShenandoahFinalMarkStartEvac [ 360 0 ][ 49938 6565240657 6565290595 ] 0
[2024-09-27T03:07:42.291+0000][654.605s][4016][info][safepoint ] Safepoint "ShenandoahFinalMarkStartEvac", Time since last: 6715492601 ns, Reaching safepoint: 49938 ns, At safepoint: 6565240657 ns, Total: 6565290595 ns
[2024-09-27T03:07:42.291+0000][654.605s][5076][info][gc ] Failed to allocate 16B for evacuation
[2024-09-27T03:07:42.291+0000][654.605s][5076][info][gc ] Cancelling GC: Allocation Failure During Evacuation
```
- relates to
-
JDK-8339616 GenShen: Introduce new state to distinguish promote-in-place phase as distinct from concurrent evacuation
-
- Resolved
-
- links to
-
Commit(master) openjdk/shenandoah-jdk21u/9f0f4d61
-
Commit(master) openjdk/shenandoah/cbc0fd0a
-
Review(master) openjdk/shenandoah-jdk21u/118
-
Review(master) openjdk/shenandoah/507