8146009: "pure virtual method called" with using new GC logging mechanism

Co-authored-by: Michail Chernov <michail.chernov@oracle.com>
Reviewed-by: dsamersoff, dholmes, mchernov

hotspot/src/share/vm/logging/logConfiguration.cpp

@@ -98,14 +98,14 @@ void LogConfiguration::initialize(jlong vm_start_time) {
   LogDecorations::initialize(vm_start_time);
   assert(_outputs == NULL, "Should not initialize _outputs before this function, initialize called twice?");
   _outputs = NEW_C_HEAP_ARRAY(LogOutput*, 2, mtLogging);
-  _outputs[0] = LogOutput::Stdout;
-  _outputs[1] = LogOutput::Stderr;
+  _outputs[0] = &StdoutLog;
+  _outputs[1] = &StderrLog;
   _n_outputs = 2;
 }
 
 void LogConfiguration::finalize() {
-  for (size_t i = 2; i < _n_outputs; i++) {
-    delete _outputs[i];
+  for (size_t i = _n_outputs; i > 0; i--) {
+    disable_output(i - 1);
   }
   FREE_C_HEAP_ARRAY(LogOutput*, _outputs);
 }
@@ -279,8 +279,8 @@ void LogConfiguration::disable_output(size_t idx) {
     ts->update_decorators();
   }
 
-  // Delete the output unless stdout/stderr
-  if (out != LogOutput::Stderr && out != LogOutput::Stdout) {
+  // Delete the output unless stdout or stderr (idx 0 or 1)
+  if (idx > 1) {
     delete_output(idx);
   } else {
     out->set_config_string("all=off");
@@ -322,7 +322,7 @@ void LogConfiguration::configure_stdout(LogLevelType level, bool exact_match, ..
 
   // Apply configuration to stdout (output #0), with the same decorators as before.
   ConfigurationLock cl;
-  configure_output(0, expr, LogOutput::Stdout->decorators());
+  configure_output(0, expr, _outputs[0]->decorators());
   notify_update_listeners();
 }
 

hotspot/src/share/vm/logging/logDecorations.hpp

@@ -36,7 +36,7 @@ class LogDecorations VALUE_OBJ_CLASS_SPEC {
   char _decorations_buffer[DecorationsBufferSize];
   char* _decoration_offset[LogDecorators::Count];
   LogLevelType _level;
-  LogTagSet _tagset;
+  const LogTagSet& _tagset;
   jlong _millis;
   static jlong _vm_start_time_millis;
   static const char* _host_name;

hotspot/src/share/vm/logging/logFileStreamOutput.cpp

@@ -28,8 +28,20 @@
 #include "logging/logMessageBuffer.hpp"
 #include "memory/allocation.inline.hpp"
 
-LogStdoutOutput LogStdoutOutput::_instance;
-LogStderrOutput LogStderrOutput::_instance;
+static bool initialized;
+static char stdoutmem[sizeof(LogStdoutOutput)];
+static char stderrmem[sizeof(LogStderrOutput)];
+
+LogStdoutOutput &StdoutLog = reinterpret_cast<LogStdoutOutput&>(stdoutmem);
+LogStderrOutput &StderrLog = reinterpret_cast<LogStderrOutput&>(stderrmem);
+
+LogFileStreamInitializer::LogFileStreamInitializer() {
+  if (!initialized) {
+    ::new (&StdoutLog) LogStdoutOutput();
+    ::new (&StderrLog) LogStderrOutput();
+    initialized = true;
+  }
+}
 
 int LogFileStreamOutput::write_decorations(const LogDecorations& decorations) {
   int total_written = 0;

hotspot/src/share/vm/logging/logFileStreamOutput.hpp

@@ -30,6 +30,14 @@
 
 class LogDecorations;
 
+class LogFileStreamInitializer {
+ public:
+  LogFileStreamInitializer();
+};
+
+// Ensure the default log streams have been initialized (stdout, stderr) using the static initializer below
+static LogFileStreamInitializer log_stream_initializer;
+
 // Base class for all FileStream-based log outputs.
 class LogFileStreamOutput : public LogOutput {
  protected:
@@ -50,9 +58,8 @@ class LogFileStreamOutput : public LogOutput {
 };
 
 class LogStdoutOutput : public LogFileStreamOutput {
-  friend class LogOutput;
+  friend class LogFileStreamInitializer;
  private:
-  static LogStdoutOutput _instance;
   LogStdoutOutput() : LogFileStreamOutput(stdout) {
     set_config_string("all=warning");
   }
@@ -66,9 +73,8 @@ class LogStdoutOutput : public LogFileStreamOutput {
 };
 
 class LogStderrOutput : public LogFileStreamOutput {
-  friend class LogOutput;
+  friend class LogFileStreamInitializer;
  private:
-  static LogStderrOutput _instance;
   LogStderrOutput() : LogFileStreamOutput(stderr) {
     set_config_string("all=off");
   }
@@ -81,4 +87,7 @@ class LogStderrOutput : public LogFileStreamOutput {
   }
 };
 
+extern LogStderrOutput &StderrLog;
+extern LogStdoutOutput &StdoutLog;
+
 #endif // SHARE_VM_LOGGING_LOGFILESTREAMOUTPUT_HPP

hotspot/src/share/vm/logging/logOutput.cpp

@@ -29,9 +29,6 @@
 #include "runtime/mutexLocker.hpp"
 #include "runtime/os.inline.hpp"
 
-LogOutput* const LogOutput::Stdout = &LogStdoutOutput::_instance;
-LogOutput* const LogOutput::Stderr = &LogStderrOutput::_instance;
-
 LogOutput::~LogOutput() {
   os::free(_config_string);
 }

hotspot/src/share/vm/logging/logOutput.hpp

@@ -57,9 +57,6 @@ class LogOutput : public CHeapObj<mtLogging> {
   void set_config_string(const char* string);
 
  public:
-  static LogOutput* const Stdout;
-  static LogOutput* const Stderr;
-
   void set_decorators(const LogDecorators &decorators) {
     _decorators = decorators;
   }

hotspot/src/share/vm/logging/logTagSet.cpp

@@ -23,6 +23,7 @@
  */
 #include "precompiled.hpp"
 #include "logging/logDecorations.hpp"
+#include "logging/logFileStreamOutput.hpp"
 #include "logging/logLevel.hpp"
 #include "logging/logMessageBuffer.hpp"
 #include "logging/logOutput.hpp"
@@ -50,7 +51,7 @@ LogTagSet::LogTagSet(PrefixWriter prefix_writer, LogTagType t0, LogTagType t1, L
   _ntagsets++;
 
   // Set the default output to warning and error level for all new tagsets.
-  _output_list.set_output_level(LogOutput::Stdout, LogLevel::Default);
+  _output_list.set_output_level(&StdoutLog, LogLevel::Default);
 }
 
 void LogTagSet::update_decorators(const LogDecorators& decorator) {

hotspot/test/gc/g1/logging/TestG1LoggingFailure.java

@@ -0,0 +1,95 @@
+/*
+ * Copyright (c) 2016, Oracle and/or its affiliates. All rights reserved.
+ * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
+ *
+ * This code is free software; you can redistribute it and/or modify it
+ * under the terms of the GNU General Public License version 2 only, as
+ * published by the Free Software Foundation.
+ *
+ * This code is distributed in the hope that it will be useful, but WITHOUT
+ * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
+ * FITNESS FOR A PARTICULAR PURPOSE.  See the GNU General Public License
+ * version 2 for more details (a copy is included in the LICENSE file that
+ * accompanied this code).
+ *
+ * You should have received a copy of the GNU General Public License version
+ * 2 along with this work; if not, write to the Free Software Foundation,
+ * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA.
+ *
+ * Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA
+ * or visit www.oracle.com if you need additional information or have any
+ * questions.
+ */
+
+ /*
+ * @test TestG1LoggingFailure
+ * @bug 8151034
+ * @summary Regression test for G1 logging at OOME
+ * @requires vm.gc.G1
+ * @library /test/lib
+ * @modules java.management
+ * @build gc.g1.logging.TestG1LoggingFailure
+ * @run main/timeout=300 gc.g1.logging.TestG1LoggingFailure
+ */
+package gc.g1.logging;
+
+import java.util.ArrayList;
+import java.util.Collections;
+import java.util.List;
+import jdk.test.lib.process.OutputAnalyzer;
+import jdk.test.lib.process.ProcessTools;
+import jdk.test.lib.Utils;
+
+public class TestG1LoggingFailure {
+
+    public static void main(String[] args) throws Throwable {
+        List<String> options = new ArrayList<>();
+        Collections.addAll(options, Utils.getTestJavaOpts());
+        Collections.addAll(options,
+                "-XX:+UseG1GC",
+                "-Xmx20m",
+                "-Xmn10m",
+                "-Xlog:gc=info",
+                "-XX:G1HeapRegionSize=1m"
+        );
+
+        options.add(Alloc.class.getName());
+
+        // According to https://bugs.openjdk.java.net/browse/JDK-8146009 failure happens not every time.
+        // Will try to reproduce this failure.
+        for (int iteration = 0; iteration < 40; ++iteration) {
+            startVM(options);
+        }
+    }
+
+    private static void startVM(List<String> options) throws Throwable, RuntimeException {
+        OutputAnalyzer out = ProcessTools.executeTestJvm(options.toArray(new String[options.size()]));
+
+        out.shouldNotContain("pure virtual method called");
+        out.shouldContain("Exception: java.lang.OutOfMemoryError thrown from the UncaughtExceptionHandler in thread \"main\"");
+
+        if (out.getExitValue() == 0) {
+            System.out.println(out.getOutput());
+            throw new RuntimeException("Expects Alloc failure.");
+        }
+    }
+
+    // Simple class to be executed in separate VM.
+    static class Alloc {
+
+        public static final int CHUNK = 1024;
+        public static ArrayList<Object> arr = new ArrayList<>();
+
+        public static void main(String[] args) {
+            try {
+                while (true) {
+                    arr.add(new byte[CHUNK]);
+                }
+            } catch (OutOfMemoryError oome) {
+            }
+            while (true) {
+                arr.add(new byte[CHUNK]);
+            }
+        }
+    }
+}

hotspot/test/native/logging/test_logConfiguration.cpp

@@ -25,6 +25,7 @@
 #include "logTestFixture.hpp"
 #include "logTestUtils.inline.hpp"
 #include "logging/logConfiguration.hpp"
+#include "logging/logFileStreamOutput.hpp"
 #include "logging/logLevel.hpp"
 #include "logging/logOutput.hpp"
 #include "logging/logTag.hpp"
@@ -68,8 +69,8 @@ TEST_VM_F(LogConfigurationTest, describe) {
   const char* description = ss.as_string();
 
   // Verify that stdout and stderr are listed by default
-  EXPECT_PRED2(string_contains_substring, description, LogOutput::Stdout->name());
-  EXPECT_PRED2(string_contains_substring, description, LogOutput::Stderr->name());
+  EXPECT_PRED2(string_contains_substring, description, StdoutLog.name());
+  EXPECT_PRED2(string_contains_substring, description, StderrLog.name());
 
   // Verify that each tag, level and decorator is listed
   for (size_t i = 0; i < LogTag::Count; i++) {
@@ -126,7 +127,7 @@ TEST_VM_F(LogConfigurationTest, update_output) {
     EXPECT_TRUE(is_described("logging=info"));
 
     // Verify by iterating over tagsets
-    LogOutput* o = LogOutput::Stdout;
+    LogOutput* o = &StdoutLog;
     for (LogTagSet* ts = LogTagSet::first(); ts != NULL; ts = ts->next()) {
       EXPECT_TRUE(ts->has_output(o));
       EXPECT_TRUE(ts->is_level(LogLevel::Info));
@@ -178,8 +179,8 @@ TEST_VM_F(LogConfigurationTest, disable_logging) {
 
   // Verify that no tagset has logging enabled
   for (LogTagSet* ts = LogTagSet::first(); ts != NULL; ts = ts->next()) {
-    EXPECT_FALSE(ts->has_output(LogOutput::Stdout));
-    EXPECT_FALSE(ts->has_output(LogOutput::Stderr));
+    EXPECT_FALSE(ts->has_output(&StdoutLog));
+    EXPECT_FALSE(ts->has_output(&StderrLog));
     EXPECT_FALSE(ts->is_level(LogLevel::Error));
   }
 }
@@ -193,7 +194,7 @@ TEST_VM_F(LogConfigurationTest, disable_output) {
   EXPECT_TRUE(is_described("#0: stdout all=off"));
 
   // Verify by iterating over tagsets
-  LogOutput* o = LogOutput::Stdout;
+  LogOutput* o = &StdoutLog;
   for (LogTagSet* ts = LogTagSet::first(); ts != NULL; ts = ts->next()) {
     EXPECT_FALSE(ts->has_output(o));
     EXPECT_FALSE(ts->is_level(LogLevel::Error));
@@ -247,7 +248,7 @@ TEST_VM_F(LogConfigurationTest, parse_empty_command_line_arguments) {
     bool ret = LogConfiguration::parse_command_line_arguments(cmdline);
     EXPECT_TRUE(ret) << "Error parsing command line arguments '" << cmdline << "'";
     for (LogTagSet* ts = LogTagSet::first(); ts != NULL; ts = ts->next()) {
-      EXPECT_EQ(LogLevel::Unspecified, ts->level_for(LogOutput::Stdout));
+      EXPECT_EQ(LogLevel::Unspecified, ts->level_for(&StdoutLog));
     }
   }
 }
@@ -306,7 +307,7 @@ TEST_F(LogConfigurationTest, configure_stdout) {
   EXPECT_FALSE(log_is_enabled(Debug, logging));
   EXPECT_FALSE(log_is_enabled(Info, gc));
   LogTagSet* logging_ts = &LogTagSetMapping<LOG_TAGS(logging)>::tagset();
-  EXPECT_EQ(LogLevel::Info, logging_ts->level_for(LogOutput::Stdout));
+  EXPECT_EQ(LogLevel::Info, logging_ts->level_for(&StdoutLog));
 
   // Enable 'gc=debug' (no wildcard), verifying no other tags are enabled
   LogConfiguration::configure_stdout(LogLevel::Debug, true, LOG_TAGS(gc));
@@ -316,9 +317,9 @@ TEST_F(LogConfigurationTest, configure_stdout) {
   for (LogTagSet* ts = LogTagSet::first(); ts != NULL; ts = ts->next()) {
     if (ts->contains(PREFIX_LOG_TAG(gc))) {
       if (ts->ntags() == 1) {
-        EXPECT_EQ(LogLevel::Debug, ts->level_for(LogOutput::Stdout));
+        EXPECT_EQ(LogLevel::Debug, ts->level_for(&StdoutLog));
       } else {
-        EXPECT_EQ(LogLevel::Off, ts->level_for(LogOutput::Stdout));
+        EXPECT_EQ(LogLevel::Off, ts->level_for(&StdoutLog));
       }
     }
   }
@@ -329,12 +330,12 @@ TEST_F(LogConfigurationTest, configure_stdout) {
   EXPECT_TRUE(log_is_enabled(Trace, gc, heap));
   for (LogTagSet* ts = LogTagSet::first(); ts != NULL; ts = ts->next()) {
     if (ts->contains(PREFIX_LOG_TAG(gc))) {
-      EXPECT_EQ(LogLevel::Trace, ts->level_for(LogOutput::Stdout));
+      EXPECT_EQ(LogLevel::Trace, ts->level_for(&StdoutLog));
     } else if (ts == logging_ts) {
       // Previous setting for 'logging' should remain
-      EXPECT_EQ(LogLevel::Info, ts->level_for(LogOutput::Stdout));
+      EXPECT_EQ(LogLevel::Info, ts->level_for(&StdoutLog));
     } else {
-      EXPECT_EQ(LogLevel::Off, ts->level_for(LogOutput::Stdout));
+      EXPECT_EQ(LogLevel::Off, ts->level_for(&StdoutLog));
     }
   }
 
@@ -345,7 +346,7 @@ TEST_F(LogConfigurationTest, configure_stdout) {
   EXPECT_FALSE(log_is_enabled(Error, gc));
   EXPECT_FALSE(log_is_enabled(Error, gc, heap));
   for (LogTagSet* ts = LogTagSet::first(); ts != NULL; ts = ts->next()) {
-    EXPECT_EQ(LogLevel::Off, ts->level_for(LogOutput::Stdout));
+    EXPECT_EQ(LogLevel::Off, ts->level_for(&StdoutLog));
   }
 }
 

hotspot/test/native/logging/test_logOutputList.cpp

@@ -22,6 +22,7 @@
  */
 
 #include "precompiled.hpp"
+#include "logging/logFileStreamOutput.hpp"
 #include "logging/logLevel.hpp"
 #include "logging/logOutput.hpp"
 #include "logging/logOutputList.hpp"
@@ -173,7 +174,7 @@ TEST(LogOutputList, is_level_single_output) {
   for (size_t i = LogLevel::First; i < LogLevel::Count; i++) {
     LogLevelType level = static_cast<LogLevelType>(i);
     LogOutputList list;
-    list.set_output_level(LogOutput::Stdout, level);
+    list.set_output_level(&StdoutLog, level);
     for (size_t j = LogLevel::First; j < LogLevel::Count; j++) {
       LogLevelType other = static_cast<LogLevelType>(j);
       // Verify that levels finer than the current level for stdout are reported as disabled,
@@ -201,8 +202,8 @@ TEST(LogOutputList, is_level_empty) {
 // Test is_level() on lists with two outputs on different levels
 TEST(LogOutputList, is_level_multiple_outputs) {
   for (size_t i = LogLevel::First; i < LogLevel::Count - 1; i++) {
-      LogOutput* dummy1 = LogOutput::Stdout;
-      LogOutput* dummy2 = LogOutput::Stderr;
+      LogOutput* dummy1 = &StdoutLog;
+      LogOutput* dummy2 = &StderrLog;
       LogLevelType first = static_cast<LogLevelType>(i);
       LogLevelType second = static_cast<LogLevelType>(i + 1);
       LogOutputList list;
@@ -226,19 +227,19 @@ TEST(LogOutputList, level_for) {
   LogOutputList list;
 
   // Ask the empty list about stdout, stderr
-  EXPECT_EQ(LogLevel::Off, list.level_for(LogOutput::Stdout));
-  EXPECT_EQ(LogLevel::Off, list.level_for(LogOutput::Stderr));
+  EXPECT_EQ(LogLevel::Off, list.level_for(&StdoutLog));
+  EXPECT_EQ(LogLevel::Off, list.level_for(&StderrLog));
 
   // Ask for level in a list with two outputs on different levels
-  list.set_output_level(LogOutput::Stdout, LogLevel::Info);
-  list.set_output_level(LogOutput::Stderr, LogLevel::Trace);
-  EXPECT_EQ(LogLevel::Info, list.level_for(LogOutput::Stdout));
-  EXPECT_EQ(LogLevel::Trace, list.level_for(LogOutput::Stderr));
+  list.set_output_level(&StdoutLog, LogLevel::Info);
+  list.set_output_level(&StderrLog, LogLevel::Trace);
+  EXPECT_EQ(LogLevel::Info, list.level_for(&StdoutLog));
+  EXPECT_EQ(LogLevel::Trace, list.level_for(&StderrLog));
 
   // Remove and ask again
-  list.set_output_level(LogOutput::Stdout, LogLevel::Off);
-  EXPECT_EQ(LogLevel::Off, list.level_for(LogOutput::Stdout));
-  EXPECT_EQ(LogLevel::Trace, list.level_for(LogOutput::Stderr));
+  list.set_output_level(&StdoutLog, LogLevel::Off);
+  EXPECT_EQ(LogLevel::Off, list.level_for(&StdoutLog));
+  EXPECT_EQ(LogLevel::Trace, list.level_for(&StderrLog));
 
   // Ask about an unknown output
   LogOutput* dummy = dummy_output(4711);
@@ -251,5 +252,5 @@ TEST(LogOutputList, level_for) {
   }
 
   // Make sure the stderr level is still the same
-  EXPECT_EQ(LogLevel::Trace, list.level_for(LogOutput::Stderr));
+  EXPECT_EQ(LogLevel::Trace, list.level_for(&StderrLog));
 }

hotspot/test/native/logging/test_logTagSet.cpp

@@ -22,6 +22,7 @@
  */
 
 #include "precompiled.hpp"
+#include "logging/logFileStreamOutput.hpp"
 #include "logging/logLevel.hpp"
 #include "logging/logOutput.hpp"
 #include "logging/logTag.hpp"
@@ -37,18 +38,18 @@ TEST(LogTagSet, defaults) {
     EXPECT_TRUE(ts->is_level(LogLevel::Error));
     EXPECT_TRUE(ts->is_level(LogLevel::Warning));
     EXPECT_FALSE(ts->is_level(LogLevel::Info));
-    EXPECT_TRUE(ts->has_output(LogOutput::Stdout));
-    EXPECT_FALSE(ts->has_output(LogOutput::Stderr));
+    EXPECT_TRUE(ts->has_output(&StdoutLog));
+    EXPECT_FALSE(ts->has_output(&StderrLog));
   }
 }
 
 TEST(LogTagSet, has_output) {
   LogTagSet& ts = LogTagSetMapping<LOG_TAGS(logging)>::tagset();
-  ts.set_output_level(LogOutput::Stderr, LogLevel::Trace);
-  EXPECT_TRUE(ts.has_output(LogOutput::Stderr));
+  ts.set_output_level(&StderrLog, LogLevel::Trace);
+  EXPECT_TRUE(ts.has_output(&StderrLog));
   EXPECT_FALSE(ts.has_output(NULL));
-  ts.set_output_level(LogOutput::Stderr, LogLevel::Off);
-  EXPECT_FALSE(ts.has_output(LogOutput::Stderr));
+  ts.set_output_level(&StderrLog, LogLevel::Off);
+  EXPECT_FALSE(ts.has_output(&StderrLog));
 }
 
 TEST(LogTagSet, ntags) {
@@ -61,18 +62,18 @@ TEST(LogTagSet, ntags) {
 TEST(LogTagSet, is_level) {
   LogTagSet& ts = LogTagSetMapping<LOG_TAGS(logging)>::tagset();
   // Set info level on stdout and verify that is_level() reports correctly
-  ts.set_output_level(LogOutput::Stdout, LogLevel::Info);
+  ts.set_output_level(&StdoutLog, LogLevel::Info);
   EXPECT_TRUE(ts.is_level(LogLevel::Error));
   EXPECT_TRUE(ts.is_level(LogLevel::Warning));
   EXPECT_TRUE(ts.is_level(LogLevel::Info));
   EXPECT_FALSE(ts.is_level(LogLevel::Debug));
   EXPECT_FALSE(ts.is_level(LogLevel::Trace));
-  ts.set_output_level(LogOutput::Stdout, LogLevel::Default);
+  ts.set_output_level(&StdoutLog, LogLevel::Default);
   EXPECT_TRUE(ts.is_level(LogLevel::Default));
 }
 
 TEST(LogTagSet, level_for) {
-  LogOutput* output = LogOutput::Stdout;
+  LogOutput* output = &StdoutLog;
   LogTagSet& ts = LogTagSetMapping<LOG_TAGS(logging)>::tagset();
   for (uint i = 0; i < LogLevel::Count; i++) {
     LogLevelType level = static_cast<LogLevelType>(i);