JDK-8265326 : Strange Characters in G1GC GC Log
  • Type: Bug
  • Component: hotspot
  • Sub-Component: gc
  • Affected Version: 16,17
  • Priority: P3
  • Status: Resolved
  • Resolution: Fixed
  • OS: os_x
  • CPU: x86_64
  • Submitted: 2021-04-14
  • Updated: 2021-04-29
  • Resolved: 2021-04-21
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 17
17 b20Fixed
Related Reports
Duplicate :  
Relates :  
Relates :  
Description
ADDITIONAL SYSTEM INFORMATION :
Mac OS X 10.15.7
Happens in both Java 16 and 17-ea

openjdk version "16" 2021-03-16
OpenJDK Runtime Environment (build 16+36-2231)
OpenJDK 64-Bit Server VM (build 16+36-2231, mixed mode, sharing)

openjdk version "17-ea" 2021-09-14
OpenJDK Runtime Environment (build 17-ea+13-1000)
OpenJDK 64-Bit Server VM (build 17-ea+13-1000, mixed mode, sharing)

A DESCRIPTION OF THE PROBLEM :
When generating a G1 GC log, strange characters appear in the GC log, making parsing difficult.

REGRESSION : Last worked in version 15.0.2

STEPS TO FOLLOW TO REPRODUCE THE PROBLEM :
Generate a GC Log with G1, either with -verbose:gc or -Xlog:gc:log.vgc


EXPECTED VERSUS ACTUAL BEHAVIOR :
EXPECTED -
java -showversion -verbose:gc G1Characters
[0.005s][info][gc] Using G1
openjdk version "15.0.2" 2021-01-19
OpenJDK Runtime Environment Zulu15.29+15-CA (build 15.0.2+7)
OpenJDK 64-Bit Server VM Zulu15.29+15-CA (build 15.0.2+7, mixed mode, sharing)
[0.136s][info][gc] GC(0) Pause Young (Concurrent Start) (G1 Humongous Allocation) 457M->24M(1040M) 2.574ms
[0.136s][info][gc] GC(1) Concurrent Cycle
[0.142s][info][gc] GC(1) Pause Remark 72M->72M(296M) 3.834ms
[0.143s][info][gc] GC(1) Pause Cleanup 88M->88M(296M) 0.120ms
[0.144s][info][gc] GC(1) Concurrent Cycle 7.757ms
[0.145s][info][gc] GC(2) Pause Young (Concurrent Start) (G1 Humongous Allocation) 120M->24M(296M) 1.392ms
[0.145s][info][gc] GC(3) Concurrent Cycle
[0.147s][info][gc] GC(3) Pause Remark 72M->72M(296M) 0.224ms
[0.147s][info][gc] GC(3) Pause Cleanup 88M->88M(296M) 0.035ms
[0.149s][info][gc] GC(3) Concurrent Cycle 3.256ms
[0.150s][info][gc] GC(4) Pause Young (Concurrent Start) (G1 Humongous Allocation) 136M->24M(296M) 0.698ms
[0.150s][info][gc] GC(5) Concurrent Cycle
[0.151s][info][gc] GC(5) Pause Remark 72M->72M(296M) 0.202ms
[0.152s][info][gc] GC(5) Pause Cleanup 88M->88M(296M) 0.027ms
[0.152s][info][gc] GC(5) Concurrent Cycle 2.374ms
etc.
ACTUAL -
java -showversion -verbose:gc G1Characters
[0.004s][info][gc] Using G1
openjdk version "16" 2021-03-16
OpenJDK Runtime Environment (build 16+36-2231)
OpenJDK 64-Bit Server VM (build 16+36-2231, mixed mode, sharing)
[0.134s][info][gc] GC(0) Pause Young (Concurrent Start) (G1 Humongous Allocation) 457M->24M(1040M) 3.213ms
[0.134s][info][gc] GC(1) Concurrent Undo Cycle
[0.140s][info][gc] GC(1) ???t? 5.650ms
[0.151s][info][gc] GC(2) Pause Young (Concurrent Start) (G1 Humongous Allocation) 456M->24M(1040M) 1.674ms
[0.151s][info][gc] GC(3) Concurrent Undo Cycle
[0.153s][info][gc] GC(3) ???t? 2.388ms
[0.164s][info][gc] GC(4) Pause Young (Concurrent Start) (G1 Humongous Allocation) 456M->24M(1040M) 1.139ms
[0.164s][info][gc] GC(5) Concurrent Undo Cycle
[0.166s][info][gc] GC(5) ???t? 1.973ms
etc.

---------- BEGIN SOURCE ----------
public class G1Characters {
  private static Object leak;
  public static void main(String... args) {
    while(true) {
      leak = new byte[10_000_000];
    }
  }
}

---------- END SOURCE ----------

CUSTOMER SUBMITTED WORKAROUND :
Use a different version of Java or a different garbage collector

FREQUENCY : always



Comments
I'm fixing this second issue with a strdup in the mutex name constructor. See JDK-8265682.
23-04-2021

There is a similar issue with HeapRegionRemSet constructor that retains pointer to a temporary, which lives only until the end of the containing full-expression. Can be fixed with something along these lines: https://github.com/mkartashev/jdk/commit/3cb2a08420b9b7548988b5253853689067aea322
22-04-2021

Changeset: da860290 Author: Fairoz Matte <fmatte@openjdk.org> Committer: Thomas Schatzl <tschatzl@openjdk.org> Date: 2021-04-21 11:48:27 +0000 URL: https://git.openjdk.java.net/jdk/commit/da860290
21-04-2021

The regression is caused by JDK-8240556
19-04-2021

Issue is not reproduced on Windows and Linux OS. OS: Windows 10 JDK 15.0.2:Pass JDK16:Pass JDK 17ea16:Pass Output: [0.030s][info][gc] Using G1 [0.136s][info][gc] GC(0) Pause Young (Concurrent Start) (G1 Humongous Allocation) 111M->10M(256M) 2.391ms [0.137s][info][gc] GC(1) Concurrent Cycle [0.141s][info][gc] GC(1) Pause Remark 50M->50M(174M) 1.450ms [0.142s][info][gc] GC(1) Pause Cleanup 60M->60M(174M) 0.126ms [0.144s][info][gc] GC(1) Concurrent Cycle 7.518ms [0.146s][info][gc] GC(2) Pause Young (Concurrent Start) (G1 Humongous Allocation) 80M->10M(174M) 1.283ms [0.147s][info][gc] GC(3) Concurrent Cycle [0.150s][info][gc] GC(3) Pause Remark 40M->40M(140M) 1.025ms [0.151s][info][gc] GC(3) Pause Cleanup 50M->50M(140M) 0.113ms [0.153s][info][gc] GC(3) Concurrent Cycle 6.124ms OS: Linux(Ubuntu20.04) JDK 16:Pass JDK 17ea12:Pass Submitter has reported this issue on MAC OS , moving it to dev team for further analysis.
16-04-2021