JDK-8273605 : VM Exit does not abort concurrent mark
  • Type: Bug
  • Component: hotspot
  • Sub-Component: gc
  • Affected Version: 16,17,18
  • Priority: P3
  • Status: Resolved
  • Resolution: Fixed
  • Submitted: 2021-09-10
  • Updated: 2021-09-20
  • Resolved: 2021-09-15
The Version table provides details related to the release that this issue/RFE will be addressed.

Unresolved : Release in which this issue/RFE will be addressed.
Resolved: Release in which this issue/RFE has been resolved.
Fixed : Release in which this issue/RFE has been fixed. The release containing this fix may be available for download as an Early Access Release or a General Availability Release.

To download the current JDK release, click here.
JDK 18
18 b15Fixed
Related Reports
Relates :  
Relates :  
Description
Following log on a 50gb HeapRAMTester, running for 10s (actual runtime):

2021-09-13 09:57:45 - Hit rate = 0.2001949695124563; total hits = 350550; total misses = 1400493; total reads = 1751043; free memory = 3619MB; max time taken = 0.977226ms; uptime = 29 s; tp
2021-09-13 09:57:46 - Hit rate = 0.19992681200864684; total hits = 82497; total misses = 330139; total reads = 412636; free memory = 3643MB; max time taken = 615.887194ms; uptime = 30 s; tp
2021-09-13 09:57:47 - Hit rate = 0.19931418396618797; total hits = 248948; total misses = 1000075; total reads = 1249023; free memory = 2906MB; max time taken = 615.887194ms; uptime = 31 s;
2021-09-13 09:57:48 - Hit rate = 0.19986780274836977; total hits = 251881; total misses = 1008357; total reads = 1260238; free memory = 2162MB; max time taken = 615.887194ms; uptime = 32 s;
2021-09-13 09:57:49 - Hit rate = 0.20071151200371223; total hits = 123274; total misses = 490911; total reads = 614185; free memory = 1988MB; max time taken = 615.887194ms; uptime = 33 s; t
2021-09-13 09:57:50 - Hit rate = 0.19965430015393493; total hits = 229051; total misses = 918187; total reads = 1147238; free memory = 1400MB; max time taken = 615.887194ms; uptime = 34 s;
2021-09-13 09:57:51 - Hit rate = 0.20023346984418983; total hits = 187652; total misses = 749514; total reads = 937166; free memory = 897MB; max time taken = 615.887194ms; uptime = 35 s; tp
1437112360
2021-09-13 09:57:52 - Hit rate = 0.19942183763963975; total hits = 144454; total misses = 579910; total reads = 724364; free memory = 503MB; max time taken = 615.8871

I.e. on 9:57:52 the last log message from the program occurred (and that "1437112360" string is a printout at the end of the application).

Relevant application code here:

    private void go(int seconds) throws InterruptedException {
        int keys = createData();
        accessCache(keys, seconds);
        exit = true;
        System.out.println(totalSum);  <-------- this is that 143...60 printout; after that the application exits.
    }


Looking at the corresponding gc log show that the last message is at

[...]
[2021-09-13T09:58:20.184+0200] GC(23) Finalize Concurrent Mark Cleanup 5.291ms
[2021-09-13T09:58:20.184+0200] GC(23) Pause Cleanup 50694M->50694M(51200M) 6.816ms
[2021-09-13T09:58:20.184+0200] GC(23) Concurrent Cleanup for Next Mark
[2021-09-13T09:58:20.185+0200] GC(23) Running G1 Clear Bitmap with 5 workers for 800 work units.
[2021-09-13T09:58:20.222+0200] GC(23) Concurrent Cleanup for Next Mark 37.406ms
[2021-09-13T09:58:20.222+0200] GC(23) Concurrent Mark Cycle 34499.877ms

right after completion of a mark cycle (also attached, test.log).

I.e. the VM exited only 30s after application exit.
Comments
Changeset: 02af541b Author: Thomas Schatzl <tschatzl@openjdk.org> Date: 2021-09-15 08:27:43 +0000 URL: https://git.openjdk.java.net/jdk/commit/02af541b7427a4b74eecab9513a770026d1a8426
15-09-2021