Uploaded image for project: 'JDK'
  1. JDK
  2. JDK-8364503

gc/g1/TestCodeCacheUnloadDuringConcCycle.java fails because of race printing to stdout

XMLWordPrintable

    • gc

      Output and diagnostic info for process 1847633 was saved into 'pid-1847633-output.log'
      [0.019s][info][gc] Using G1
      [0.020s][debug][gc] ConcGCThreads: 3 offset 29
      [0.020s][debug][gc] ParallelGCThreads: 13
      [0.020s][trace][gc] MarkStackSize: 4096k MarkStackSizeMax: 524288k
      [0.020s][debug][gc] Initialize mark stack with 4096 chunks, maximum 536870912
      CompileCommand: compileonly gc/g1/SomeClass.* bool compileonly = true
      [0.074s][info ][codecache] Triggering threshold (12.749%) GC due to allocating 15.004% since last unloading (0.000% used -> 15.004% used)
      [0.074s][trace][gc ] main: Try Collect Concurrently (CodeCache GC Threshold): attempt 1
      [0.099s][debug][gc ] GC(0) Allocated 1 survivor 0 old percent total 5.26% (10%)
      [0.100s][info ][gc ] GC(0) Pause Young (Concurrent Start) (CodeCache GC Threshold) 1M->1M(20M) 4.442ms
      [0.100s][info ][gc ] GC(1) Concurrent Mark Cycle
      [0.100s][trace][gc ] main: Try Collect Concurrently (CodeCache GC Threshold): complete true
      [0.112s][info ][codecache] Unknown code cache pressure; don't age code
      [0.113s][info ][gc ] GC(1) Pause Remark 1M->1M(20M) 0.711ms
      [0.117s][info ][gc ] GC(1) Pause Cleanup 1M->1M(20M) 0.053ms
      [0.120s][info ][gc ] GC(1) Concurrent Mark Cycle 20.111ms
      [0.155s][trace][gc ] main: Try Collect Concurrently (WhiteBox Initiated Run to Breakpoint): attempt 1
      [0.159s][debug][gc ] GC(2) Allocated 1 survivor 0 old percent total 5.26% (10%)
      [0.159s][info ][gc ] GC(2) Pause Young (Concurrent Start) (WhiteBox Initiated Run to Breakpoint) 2M->1M(20M) 3.193ms
      [0.159s][info ][gc ] GC(3) Concurrent Mark Cycle
      [0.159s][trace][gc ] main: Try Collect Concurrently (WhiteBox Initiated Run to Breakpoint): complete true
      [0.171s][info ][codecache] Allocation rate: 847.861 KB/s, time to aggressive unloading: 3.286 s, cold timeout: 0.822 s, cold gc count: 14, used: 1.279 MB (15.990%), last used: 1.231 MB (15.382%), gc interval: 0.059 s
      [0.171s][info ][gc ] GC(3) Pause Remark 1M->1M(20M) 0.617ms
      Try to trigger code cache GC
      Compiled 0 classes
      Compiled 20 classes
      Compiled 40 classes
      Compiled 60 classes
      Compiled 80 classes
      Compiled 100 classes
      Compiled 120 classes
      Compiled 140 classes
      Compiled 160 classes
      [2.053s][info ][codecache] Triggering threshold (10.952%) GC due to allocating 10.995% since last unloading (15.990% used -> 26.985% used)
      [2.053s][trace][gc ] C1 CompilerThread0: Try Collect Concurrently (CodeCache GC Threshold): attempt 1
      [2.053s][trace][gc ] C1 CompilerThread0: Try Collect Concurrently (CodeCache GC Threshold): wait
      Compiled 180 classes
      Compilation done, compiled 200 classes
      [2.507s][info ][gc ] GC(3) Pause Cleanup 9M->9M(20M) 0.060ms
      [2.508s][info ][gc ] GC(3) Concurrent Mark Cycle 2348.621ms
      [2.508s][trace][gc ] C1 CompilerThread0: Try Collect Concurrently (CodeCache GC Threshold): retry after in-progress
      [2.508s][trace][gc ] C1 CompilerThread0: Try Collect Concurrently (CodeCache GC Threshold): attempt 2
      [2.508s][trace][gc ] C1 CompilerThread0: Try Collect Concurrently (CodeCache GC Threshold): whitebox control stall
      [2.509s][trace][gc ] C1 CompilerThread0: Try Collect Concurrently (CodeCache GC Threshold): attempt 3
      [2.518s][debug][gc ] GC(4) Allocated 2 survivor 0 old percent total 11.11% (10%)
      [2.518s][info ][gc ] GC(4) Pause Young (Concurrent Start) (CodeCache GC Threshold) 9M->2M(20M) 9.454ms
      [2.518s][info ][gc ] GC(5) Concurrent Mark Cycle
      [2.518s][trace][gc ] C1 CompilerThread0: Try Collect Concurrently (CodeCache GC Threshold): complete true
      Marker for this test
      [2.538s][info ][codecache] Allocation rate: 984.519 KB/s, time to aggressive unloading: 0.134 s, cold timeout: 0.034 s, cold gc count: 2, used: 3.871 MB (48.386%), last used: 1.279 MB (15.990%), gc interval: 1.213 s
      [2.538s][info ][gc ] GC(5) Pause Remark 2M->2M(20M) 4.377ms
      [2.543s][info ][gc ] GC(5) Pause Cleanup 2M->2M(20M) 0.056ms
      [2.543s][info ][gc ] GC(5) Concurrent Mark Cycle 25.200ms
      Compiled 0 classes
      Compiled 20 classes
      Compiled 40 classes
      Compiled 60 classes
      Compiled 80 classes
      Compiled 100 classes
      Compiled 120 classes
      Compiled 140 classes
      Compiled 160 classes
      Compiled 180 classes
      Compilation done, compiled 200 classes

      ----------System.err:(15/1223)----------
      java.lang.RuntimeException: Could not find a CodeCache GC Threshold GC after finishing the concurrent cycle: expected true, was false
      at jdk.test.lib.Asserts.fail(Asserts.java:715)
      at jdk.test.lib.Asserts.assertTrue(Asserts.java:545)
      at gc.g1.TestCodeCacheUnloadDuringConcCycle.runAndCheckTest(TestCodeCacheUnloadDuringConcCycle.java:94)
      at gc.g1.TestCodeCacheUnloadDuringConcCycle.allTests(TestCodeCacheUnloadDuringConcCycle.java:99)
      at gc.g1.TestCodeCacheUnloadDuringConcCycle.main(TestCodeCacheUnloadDuringConcCycle.java:104)
      at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:104)
      at java.base/java.lang.reflect.Method.invoke(Method.java:565)
      at com.sun.javatest.regtest.agent.MainWrapper$MainTask.run(MainWrapper.java:138)
      at java.base/java.lang.Thread.run(Thread.java:1474)

            tschatzl Thomas Schatzl
            dholmes David Holmes
            Votes:
            0 Vote for this issue
            Watchers:
            4 Start watching this issue

              Created:
              Updated: