Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

8229517: Support for optional asynchronous/buffered logging #3135

Open
wants to merge 24 commits into
base: master
from
Open
Changes from all commits
Commits
Show all changes
24 commits
Select commit Hold shift + click to select a range
0697587
8229517: Support for optional asynchronous/buffered logging
Mar 22, 2021
a3945d0
8229517: Support for optional asynchronous/buffered logging
Mar 22, 2021
e23657f
8229517: Support for optional asynchronous/buffered logging
Mar 22, 2021
2871894
8229517: Support for optional asynchronous/buffered logging
Mar 22, 2021
760ec76
8229517: Support for optional asynchronous/buffered logging
Mar 28, 2021
bcefbec
8229517: Support for optional asynchronous/buffered logging
Mar 28, 2021
09c058d
8229517: Support for optional asynchronous/buffered logging
Apr 1, 2021
9211121
8229517: Support for optional asynchronous/buffered logging
Apr 9, 2021
81b2a0c
fix runtime/logging/RedefineClasses.java crashed with -XX:+AsyncLogging
Apr 9, 2021
54aadfa
Revert "fix runtime/logging/RedefineClasses.java crashed with -XX:+As…
Apr 12, 2021
f453d03
Inject the number of dropped messages since last dumpping.
Apr 15, 2021
3d74a32
Fix build issue with `--disable-precompiled-headers`
Apr 15, 2021
2bd104f
Support Jcmd pid VM.log disable
Apr 16, 2021
edb15c6
Remove LogAsyncInterval completely
Apr 20, 2021
11c2b7a
Resolve rank conflict between tty_lock and LogAsyncFlusher's _lock.
Apr 21, 2021
b2ad511
Fix a race condition bug on LogAsyncFlusher termination.
Apr 22, 2021
13c1c2b
Merge branch 'master' into JDK-8229517
Apr 22, 2021
4cf4a57
Refactor LogAsyncFlusher::abort()
Apr 23, 2021
1f06be3
Accurate Decorations for AsyncLogging.
Apr 23, 2021
e2d6f9e
Fix bugs/style/typo based on reviewers' feedbacks.
Apr 23, 2021
78d8f2c
Revert "Accurate Decorations for AsyncLogging."
Apr 29, 2021
e035ee3
Reimplement Accurate Decorations for AsyncLogging.
Apr 29, 2021
98ae33f
Implement the global option -Xlog:async per CSR.
May 3, 2021
1d5e540
Use LogTagSetMapping<LogTag::__NO_TAG>::tagset() instead of NULL poin…
May 5, 2021
File filter
Filter file types
Jump to
Jump to file
Failed to load files.

Always

Just for now

@@ -29,6 +29,7 @@
#endif
#include "jvmtifiles/jvmti.h"
#include "logging/log.hpp"
#include "logging/logAsyncFlusher.hpp"
#include "memory/allocation.inline.hpp"
#include "os_posix.inline.hpp"
#include "runtime/globals_extension.hpp"
@@ -1945,6 +1946,7 @@ void os::shutdown() {
// needs to remove object in file system
AttachListener::abort();

LogAsyncFlusher::abort();
// flush buffered output, finish log files
ostream_abort();

@@ -38,6 +38,7 @@
#include "jvmtifiles/jvmti.h"
#include "logging/log.hpp"
#include "logging/logStream.hpp"
#include "logging/logAsyncFlusher.hpp"
#include "memory/allocation.inline.hpp"
#include "memory/filemap.hpp"
#include "oops/oop.inline.hpp"
@@ -717,6 +718,7 @@ bool os::create_thread(Thread* thread, ThreadType thr_type,
case os::vm_thread:
case os::pgc_thread:
case os::cgc_thread:
case os::asynclog_thread:
case os::watcher_thread:
if (VMThreadStackSize > 0) stack_size = (size_t)(VMThreadStackSize * K);
break;
@@ -1097,6 +1099,7 @@ void os::shutdown() {
// allow PerfMemory to attempt cleanup of any persistent resources
perfMemory_exit();

LogAsyncFlusher::abort();
// flush buffered output, finish log files
ostream_abort();

@@ -0,0 +1,230 @@
/*
* Copyright Amazon.com Inc. 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.
*
*/
#include "precompiled.hpp"
#include "jvm.h"
#include "logging/logAsyncFlusher.hpp"
#include "logging/logConfiguration.hpp"
#include "logging/logFileOutput.hpp"
#include "logging/logHandle.hpp"
#include "runtime/atomic.hpp"

void AsyncLogMessage::writeback() {
if (_message != NULL) {
assert(_decorations != NULL, "sanity check");
_output.write_blocking(*_decorations, _message);
}
}

void LogAsyncFlusher::enqueue_impl(const AsyncLogMessage& msg) {
assert_lock_strong(&_lock);

if (_buffer.size() >= AsyncLogBufferEntries) {
const AsyncLogMessage* h = _buffer.front();
assert(h != NULL, "sanity check");

if (h->message() != nullptr) {
bool p_created;
uintx* counter = _stats.add_if_absent(h->output(), 0, &p_created);
*counter = *counter + 1;

if (Verbose) {
// Temporarily turn off SerializeVMOutput so defaultStream will not
// invoke set_owner(self) for tty_lock.
FlagSetting t(SerializeVMOutput, false);
// The writing below can not guarantee non-blocking because tty may be piped by the filesystems
// or throttled by XOFF, so only dump the dropping message in Verbose mode.
tty->print_cr("asynclog dropping message: %s", h->message());
}
}

_buffer.pop_front();
}
assert(_buffer.size() < AsyncLogBufferEntries, "_buffer is over-sized.");
_buffer.push_back(msg);

// notify asynclog thread if occupancy is over 3/4
size_t sz = _buffer.size();
if (sz > (AsyncLogBufferEntries >> 2) * 3 ) {
_lock.notify();
}
}

void LogAsyncFlusher::enqueue(LogFileOutput& output, const LogDecorations& decorations, const char* msg) {
AsyncLogMessage m(output, decorations, msg);

{ // critical area
// The rank of _lock is same as _tty_lock on purpuse.
// if logging thread is holding _tty_lock now, temporarily yield to _lock.
ttyUnlocker ttyul;
MutexLocker ml(&_lock, Mutex::_no_safepoint_check_flag);
enqueue_impl(m);
}
}

// LogMessageBuffer consists of a multiple-part/multiple-line messsages.
// the mutex here gurantees its integrity.
void LogAsyncFlusher::enqueue(LogFileOutput& output, LogMessageBuffer::Iterator msg_iterator) {
ttyUnlocker ttyul;
MutexLocker ml(&_lock, Mutex::_no_safepoint_check_flag);

for (; !msg_iterator.is_at_end(); msg_iterator++) {
AsyncLogMessage m(output, msg_iterator.decorations(), msg_iterator.message());
enqueue_impl(m);
}
}

LogAsyncFlusher::LogAsyncFlusher()
: _state(ThreadState::Running),
_lock(Mutex::tty, "async-log-monitor", true /* allow_vm_block */, Mutex::_safepoint_check_never),
_stats(17 /*table_size*/) {
if (os::create_thread(this, os::asynclog_thread)) {
os::start_thread(this);
}
}

bool AsyncLogMapIterator::do_entry(LogFileOutput* output, uintx* counter) {
using dummy = LogTagSetMapping<LogTag::__NO_TAG>;
LogDecorations decorations(LogLevel::Warning, dummy::tagset(), output->decorators());
const int sz = 128;
char out_of_band[sz];

if (*counter > 0) {
jio_snprintf(out_of_band, sz, UINTX_FORMAT_W(6) " messages dropped...", *counter);
output->write_blocking(decorations, out_of_band);
*counter = 0;
}

return true;
}

void LogAsyncFlusher::writeback(const LinkedList<AsyncLogMessage>& logs) {
LinkedListIterator<AsyncLogMessage> it(logs.head());
while (!it.is_empty()) {
AsyncLogMessage* e = it.next();
e->writeback();
e->destroy();
}
}

void LogAsyncFlusher::flush(bool with_lock) {
LinkedListImpl<AsyncLogMessage, ResourceObj::C_HEAP, mtLogging> logs;

if (with_lock) { // critical area
// Caveat: current thread must not hold _tty_lock or other lower rank lockers.
// Cannot install ttyUnlocker here because flush() may be invoked before defaultStream
// initialization.
MutexLocker ml(&_lock, Mutex::_no_safepoint_check_flag);
_buffer.pop_all(&logs);
AsyncLogMapIterator iter;
_stats.iterate(&iter);
} else {
// C++ lambda can simplify the code snippet.
_buffer.pop_all(&logs);
AsyncLogMapIterator iter;
_stats.iterate(&iter);
}

writeback(logs);
}

void LogAsyncFlusher::run() {
while (_state == ThreadState::Running) {
{
MonitorLocker m(&_lock, Mutex::_no_safepoint_check_flag);
m.wait(500 /* ms, timeout*/);
}
flush();
}

// Signal thread has terminated
MonitorLocker ml(Terminator_lock);
_state = ThreadState::Terminated;
ml.notify_all();
}

LogAsyncFlusher* LogAsyncFlusher::_instance = nullptr;

void LogAsyncFlusher::initialize() {
This conversation was marked as resolved by navyxliu

This comment has been minimized.

@simonis

simonis Mar 26, 2021
Member

I don't think you need this. Please merge the initialization into LogAsyncFlusher::instance() (see my comments on your changes in init.cpp).

if (!LogConfiguration::is_async_mode()) return;

if (_instance == NULL) {
Atomic::release_store(&LogAsyncFlusher::_instance, new LogAsyncFlusher());
}
}

// Termination
// 1. issue an atomic release_store to close the logging window.
// 2. flush itself in-place.
// 3. signal asynclog thread to exit.
// 4. wait until asynclog thread exits.
// 5. (optional) delete this in post_run().
void LogAsyncFlusher::terminate() {
if (_instance != NULL) {
LogAsyncFlusher* self = _instance;

Atomic::release_store<LogAsyncFlusher*, LogAsyncFlusher*>(&_instance, nullptr);
self->flush();
{
MonitorLocker ml(&self->_lock, Mutex::_no_safepoint_check_flag);
self->_state = ThreadState::Terminating;
ml.notify();
}
{
MonitorLocker ml(Terminator_lock, Mutex::_no_safepoint_check_flag);
while (self->_state != ThreadState::Terminated) {
ml.wait();
}
}
}
}

LogAsyncFlusher* LogAsyncFlusher::instance() {
if (Thread::current_or_null() != nullptr) {
return _instance;
} else {
// current thread may has been detached.
return nullptr;
}
}

// Different from terminate(), abort is invoked by os::abort().
// There are 2 constraints:
// 1. must be async-safe because os::abort() may be invoked by a signal handler while other
// threads are executing.
// 2. must not obtain _lock. eg. gtest.MutexRank.mutex_lock_access_leaf(test_mutex_rank.cpp)
// holds a 'assess' lock and then traps SIGSEGV on purpose.
//
// Unlike terminate, abort() just ensures all pending log messages are flushed. It doesnot
// exit asynclog thread.
void LogAsyncFlusher::abort() {
if (_instance != nullptr) {
// To meet prior constraints, I borrow the idea in LogConfiguration::disable_outputs(),
// the following code shut down all outputs for all tagsets with a RCU synchroniziation.
// After then, I can flush pending queue without a lock.
for (LogTagSet* ts = LogTagSet::first(); ts != NULL; ts = ts->next()) {
ts->disable_outputs();
}
_instance->flush(false /*with_lock*/);
}
}
ProTip! Use n and p to navigate between commits in a pull request.