From f1258f9e16b063c0fdbdd614ae2dc76c67607654 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Johan=20Sj=C3=B6len?= Date: Mon, 17 Feb 2025 09:22:57 +0000 Subject: [PATCH] 8349755: Fix corner case issues in async UL Reviewed-by: dholmes, aboldtch --- src/hotspot/share/logging/logAsyncWriter.cpp | 82 +++++++++++++++++-- src/hotspot/share/logging/logAsyncWriter.hpp | 9 +- src/hotspot/share/logging/logFileOutput.cpp | 9 +- .../share/logging/logFileStreamOutput.cpp | 8 +- src/hotspot/share/logging/logTag.hpp | 2 + src/hotspot/share/logging/logTagSet.cpp | 9 +- .../jtreg/runtime/logging/AsyncDeathTest.java | 54 ++++++++++++ 7 files changed, 147 insertions(+), 26 deletions(-) create mode 100644 test/hotspot/jtreg/runtime/logging/AsyncDeathTest.java diff --git a/src/hotspot/share/logging/logAsyncWriter.cpp b/src/hotspot/share/logging/logAsyncWriter.cpp index 8360a4af91d..44758958dd3 100644 --- a/src/hotspot/share/logging/logAsyncWriter.cpp +++ b/src/hotspot/share/logging/logAsyncWriter.cpp @@ -31,18 +31,34 @@ #include "runtime/atomic.hpp" #include "runtime/os.inline.hpp" +DEBUG_ONLY(bool AsyncLogWriter::ignore_recursive_logging = false;) + class AsyncLogWriter::AsyncLogLocker : public StackObj { - public: + static Thread* _holder; +public: + static Thread* current_holder() { return _holder; } AsyncLogLocker() { assert(_instance != nullptr, "AsyncLogWriter::_lock is unavailable"); _instance->_lock.lock(); + _holder = Thread::current_or_null(); } ~AsyncLogLocker() { + assert(_holder == Thread::current_or_null(), "must be"); + _holder = nullptr; _instance->_lock.unlock(); } + + void wait() { + Thread* saved_holder = _holder; + _holder = nullptr; + _instance->_lock.wait(0/* no timeout */); + _holder = saved_holder; + } }; +Thread* AsyncLogWriter::AsyncLogLocker::_holder = nullptr; + // LogDecorator::None applies to 'constant initialization' because of its constexpr constructor. const LogDecorations& AsyncLogWriter::None = LogDecorations(LogLevel::Warning, LogTagSetMapping::tagset(), LogDecorators::None); @@ -84,19 +100,67 @@ void AsyncLogWriter::enqueue_locked(LogFileStreamOutput* output, const LogDecora _lock.notify(); } -void AsyncLogWriter::enqueue(LogFileStreamOutput& output, const LogDecorations& decorations, const char* msg) { +// This function checks for cases where continuing with asynchronous logging may lead to stability issues, such as a deadlock. +// If this returns false then we give up on logging asynchronously and do so synchronously instead. +bool AsyncLogWriter::is_enqueue_allowed() { + AsyncLogWriter* alw = AsyncLogWriter::instance(); + Thread* holding_thread = AsyncLogWriter::AsyncLogLocker::current_holder(); + Thread* this_thread = Thread::current_or_null(); + if (this_thread == nullptr) { + // The current thread is unattached. + return false; + } + + if (holding_thread == this_thread) { + // A thread, while enqueuing a message, has attempted to log something. + // Do not log while holding the Async log lock. + // Try to catch possible occurrences in debug builds. +#ifdef ASSERT + if (!AsyncLogWriter::ignore_recursive_logging) { + ShouldNotReachHere(); + } +#endif // ASSERT + return false; + } + + if (alw == nullptr) { + // There is no AsyncLogWriter instance yet. + return false; + } + + if (this_thread == alw) { + // The async log producer is attempting to log, leading to recursive logging. + return false; + } + + return true; +} + +bool AsyncLogWriter::enqueue(LogFileStreamOutput& output, const LogDecorations& decorations, const char* msg) { + if (!is_enqueue_allowed()) { + return false; + } + AsyncLogLocker locker; - enqueue_locked(&output, decorations, msg); + DEBUG_ONLY(log_debug(deathtest)("Induce a recursive log for testing (for crashing)");) + DEBUG_ONLY(log_debug(deathtest2)("Induce a recursive log for testing");) + AsyncLogWriter::instance()->enqueue_locked(&output, decorations, msg); + return true; } // LogMessageBuffer consists of a multiple-part/multiple-line message. // The lock here guarantees its integrity. -void AsyncLogWriter::enqueue(LogFileStreamOutput& output, LogMessageBuffer::Iterator msg_iterator) { - AsyncLogLocker locker; - - for (; !msg_iterator.is_at_end(); msg_iterator++) { - enqueue_locked(&output, msg_iterator.decorations(), msg_iterator.message()); +bool AsyncLogWriter::enqueue(LogFileStreamOutput& output, LogMessageBuffer::Iterator msg_iterator) { + if (!is_enqueue_allowed()) { + return false; } + + // If we get here we know the AsyncLogWriter is initialized. + AsyncLogLocker locker; + for (; !msg_iterator.is_at_end(); msg_iterator++) { + AsyncLogWriter::instance()->enqueue_locked(&output, msg_iterator.decorations(), msg_iterator.message()); + } + return true; } AsyncLogWriter::AsyncLogWriter() @@ -155,7 +219,7 @@ void AsyncLogWriter::run() { AsyncLogLocker locker; while (!_data_available) { - _lock.wait(0/* no timeout */); + locker.wait(); } // Only doing a swap and statistics under the lock to // guarantee that I/O jobs don't block logsites. diff --git a/src/hotspot/share/logging/logAsyncWriter.hpp b/src/hotspot/share/logging/logAsyncWriter.hpp index 4d18e612110..e2c8cb36e07 100644 --- a/src/hotspot/share/logging/logAsyncWriter.hpp +++ b/src/hotspot/share/logging/logAsyncWriter.hpp @@ -195,9 +195,12 @@ class AsyncLogWriter : public NonJavaThread { ~BufferUpdater(); }; - public: - void enqueue(LogFileStreamOutput& output, const LogDecorations& decorations, const char* msg); - void enqueue(LogFileStreamOutput& output, LogMessageBuffer::Iterator msg_iterator); + static bool is_enqueue_allowed(); + +public: + DEBUG_ONLY(static bool ignore_recursive_logging;) + static bool enqueue(LogFileStreamOutput& output, const LogDecorations& decorations, const char* msg); + static bool enqueue(LogFileStreamOutput& output, LogMessageBuffer::Iterator msg_iterator); static AsyncLogWriter* instance(); static void initialize(); diff --git a/src/hotspot/share/logging/logFileOutput.cpp b/src/hotspot/share/logging/logFileOutput.cpp index 568708a5961..9d6d19d739e 100644 --- a/src/hotspot/share/logging/logFileOutput.cpp +++ b/src/hotspot/share/logging/logFileOutput.cpp @@ -292,9 +292,7 @@ int LogFileOutput::write(const LogDecorations& decorations, const char* msg) { return 0; } - AsyncLogWriter* aio_writer = AsyncLogWriter::instance(); - if (aio_writer != nullptr) { - aio_writer->enqueue(*this, decorations, msg); + if (AsyncLogWriter::enqueue(*this, decorations, msg)) { return 0; } @@ -306,10 +304,7 @@ int LogFileOutput::write(LogMessageBuffer::Iterator msg_iterator) { // An error has occurred with this output, avoid writing to it. return 0; } - - AsyncLogWriter* aio_writer = AsyncLogWriter::instance(); - if (aio_writer != nullptr) { - aio_writer->enqueue(*this, msg_iterator); + if (AsyncLogWriter::enqueue(*this, msg_iterator)) { return 0; } diff --git a/src/hotspot/share/logging/logFileStreamOutput.cpp b/src/hotspot/share/logging/logFileStreamOutput.cpp index f8bbb28472c..2464bc806c2 100644 --- a/src/hotspot/share/logging/logFileStreamOutput.cpp +++ b/src/hotspot/share/logging/logFileStreamOutput.cpp @@ -173,9 +173,7 @@ int LogFileStreamOutput::write_blocking(const LogDecorations& decorations, const } int LogFileStreamOutput::write(const LogDecorations& decorations, const char* msg) { - AsyncLogWriter* aio_writer = AsyncLogWriter::instance(); - if (aio_writer != nullptr) { - aio_writer->enqueue(*this, decorations, msg); + if (AsyncLogWriter::enqueue(*this, decorations, msg)) { return 0; } @@ -186,9 +184,7 @@ int LogFileStreamOutput::write(const LogDecorations& decorations, const char* ms } int LogFileStreamOutput::write(LogMessageBuffer::Iterator msg_iterator) { - AsyncLogWriter* aio_writer = AsyncLogWriter::instance(); - if (aio_writer != nullptr) { - aio_writer->enqueue(*this, msg_iterator); + if (AsyncLogWriter::enqueue(*this, msg_iterator)) { return 0; } diff --git a/src/hotspot/share/logging/logTag.hpp b/src/hotspot/share/logging/logTag.hpp index 15ac30d09ab..c3db84930ad 100644 --- a/src/hotspot/share/logging/logTag.hpp +++ b/src/hotspot/share/logging/logTag.hpp @@ -68,6 +68,8 @@ class outputStream; LOG_TAG(data) \ LOG_TAG(datacreation) \ LOG_TAG(dcmd) \ + DEBUG_ONLY(LOG_TAG(deathtest)) /* Log Internal death test tag */ \ + DEBUG_ONLY(LOG_TAG(deathtest2)) /* Log Internal death test tag */ \ LOG_TAG(decoder) \ LOG_TAG(defaultmethods) \ LOG_TAG(deoptimization) \ diff --git a/src/hotspot/share/logging/logTagSet.cpp b/src/hotspot/share/logging/logTagSet.cpp index 3cb04a033c6..718627be3a5 100644 --- a/src/hotspot/share/logging/logTagSet.cpp +++ b/src/hotspot/share/logging/logTagSet.cpp @@ -22,6 +22,7 @@ * */ #include "jvm.h" +#include "logging/logAsyncWriter.hpp" #include "logging/logDecorations.hpp" #include "logging/logFileStreamOutput.hpp" #include "logging/logLevel.hpp" @@ -77,7 +78,13 @@ void LogTagSet::log(LogLevelType level, const char* msg) { // the implied memory order of Atomic::add(). LogOutputList::Iterator it = _output_list.iterator(level); LogDecorations decorations(level, *this, _decorators); - +#ifdef ASSERT + // If we log for tag deathtest2 then we're testing that recursive logging works. + // In this case, do not crash when detecting recursive logging. + if (this->contains(LogTagType::_deathtest2)) { + AsyncLogWriter::ignore_recursive_logging = true; + } +#endif for (; it != _output_list.end(); it++) { (*it)->write(decorations, msg); } diff --git a/test/hotspot/jtreg/runtime/logging/AsyncDeathTest.java b/test/hotspot/jtreg/runtime/logging/AsyncDeathTest.java new file mode 100644 index 00000000000..2dff887f108 --- /dev/null +++ b/test/hotspot/jtreg/runtime/logging/AsyncDeathTest.java @@ -0,0 +1,54 @@ +/* + * Copyright (c) 2025, 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 + * @bug 8349755 + * @summary Perform recursive logging in async UL on purpose + * @requires vm.flagless + * @requires vm.debug + * @library /test/lib + * @modules java.base/jdk.internal.misc + * java.management + * @run driver AsyncDeathTest + */ + +import jdk.test.lib.process.ProcessTools; +import jdk.test.lib.process.OutputAnalyzer; + +public class AsyncDeathTest { + public static void main(String[] args) throws Exception { + // For deathtest we expect the VM to reach ShouldNotReachHere() and die + ProcessBuilder pb = + ProcessTools.createLimitedTestJavaProcessBuilder("-Xlog:async", "-Xlog:os,deathtest=debug", "-XX:-CreateCoredumpOnCrash", "--version"); + OutputAnalyzer output = new OutputAnalyzer(pb.start()); + output.shouldNotHaveExitValue(0); + output.shouldNotContain("Induce a recursive log for testing"); + // For deathtest2 we expect the VM to ignore that recursive logging has been detected and is handled by printing synchronously. + ProcessBuilder pb2 = + ProcessTools.createLimitedTestJavaProcessBuilder("-Xlog:async", "-Xlog:os,deathtest2=debug", "--version"); + OutputAnalyzer output2 = new OutputAnalyzer(pb2.start()); + output2.shouldHaveExitValue(0); + output2.shouldContain("Induce a recursive log for testing"); + } +}