JDK-8061688 : Interleaved verbose logging confuses test
  • Type: Bug
  • Component: hotspot
  • Sub-Component: gc
  • Affected Version: 9
  • Priority: P2
  • Status: Closed
  • Resolution: Duplicate
  • Submitted: 2014-10-21
  • Updated: 2014-10-28
  • Resolved: 2014-10-28
Related Reports
Duplicate :  
JDK-8061805 - BACKOUT - Remove the generations array
Description
For some reason the verbose logging from CMS is interleaved with ParNew logging:
#0: [GC (Allocation Failure) #0: [ParNew: 2693K->320K(3072K), 0.0201404 secs]#1: [CMS: 253K->566K(6848K), 0.0341666 secs] 2693K->566K(9920K), [Metaspace: 77K->77K(4400K)], 0.0562567 secs] [Times: user=0.06 sys=0.01 real=0.05 secs] 

The test expects #1 to be in the beginning of a line, which it isn't here, and the test fails.
Comments
This is easy to reproduce locally. Just run the test with JTreg: $ java -jar jtreg.jar -va -noreport hotspot/test/gc/logging/TestGCId.java The test passes successfully every time based on this changeset: changeset: 7243:76ee2cdb5d88 parent: 7242:5c8dffe3d889 parent: 7211:f1821f27f91c user: jwilhelm date: Mon Oct 20 15:23:33 2014 +0200 summary: Merge And it fails every time when updated to the next changeset: changeset: 7244:d9cb9b61a295 user: jwilhelm date: Fri Aug 22 10:10:08 2014 +0200 summary: 8055702: Remove the generations array The reason is that the log line has changed so that GC #1 is logged on the same line as GC #0: #0: [GC (Allocation Failure) #0: [ParNew: 2679K->318K(3072K), 0.0192166 secs]#1: [CMS: 338K->605K(6848K), 0.0127856 secs] 2679K->605K(9920K), [Metaspace: 3173K->3173K(1056768K)], 0.0324264 secs] [Times: user=0.18 sys=0.01 real=0.03 secs]
21-10-2014