8349755: Fix corner case issues in async UL

Reviewed-by: dholmes, aboldtch
This commit is contained in:
Johan Sjölen 2025-02-17 09:22:57 +00:00
parent b1b48286a6
commit f1258f9e16
7 changed files with 147 additions and 26 deletions

View File

@ -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<LogTag::__NO_TAG>::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.

View File

@ -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();

View File

@ -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;
}

View File

@ -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;
}

View File

@ -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) \

View File

@ -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);
}

View File

@ -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");
}
}