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

Closed
wants to merge 39 commits into from
Closed
Changes from 36 commits
Commits
Show all changes
39 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
c67d74e
Change option AsyncLogBufferEntries to AsyncLogBufferSize.
May 7, 2021
e3ee430
Merge branch 'master' into JDK-8229517
May 8, 2021
908d2a3
Update based on the feedbacks from reviwers.
May 11, 2021
7df8b1e
Fix build on Windows.
May 12, 2021
8f7b3b1
Refactor Initialize() and Termiante().
May 13, 2021
cade304
Replace Mutex with Semaphore.
May 14, 2021
e19e90a
refactor code and update per reviewers' feedback.
May 16, 2021
be83aaf
Implement the new discard policy: drop the incoming message.
May 17, 2021
348edfc
Update according to reviewer's feedback.
May 20, 2021
2381ba1
Add threadump support for AsyncLog Thread.
May 22, 2021
cad42d7
Update according to reviewers' feedback (Part-2).
May 22, 2021
9800a8c
flush() waits until all pending logging IO operations are done.
May 24, 2021
a25b8d6
Biased to the thread which is taking buffer lock.
May 24, 2021
2ffc33f
Remove AsyncLogWriter::flush() from os::shutdown().
May 25, 2021
b3d36cf
Correct typos and add a comment for a corner case.
May 27, 2021
File filter
Filter by extension
Conversations
Failed to load comments.
Jump to
Jump to file
Failed to load files.
Diff view
Diff view
@@ -29,6 +29,7 @@
#endif
#include "jvmtifiles/jvmti.h"
#include "logging/log.hpp"
#include "logging/logAsyncWriter.hpp"
#include "memory/allocation.inline.hpp"
#include "os_posix.inline.hpp"
#include "runtime/globals_extension.hpp"
@@ -1946,6 +1947,9 @@ void os::shutdown() {
// needs to remove object in file system
AttachListener::abort();

// flush buffered messages
AsyncLogWriter::flush();

// 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/logAsyncWriter.hpp"
#include "memory/allocation.inline.hpp"
#include "oops/oop.inline.hpp"
#include "os_share_windows.hpp"
@@ -714,6 +715,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;
@@ -1094,6 +1096,9 @@ void os::shutdown() {
// allow PerfMemory to attempt cleanup of any persistent resources
perfMemory_exit();

// flush buffered messages
AsyncLogWriter::flush();

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

@@ -0,0 +1,188 @@
/*
* 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 "logging/logAsyncWriter.hpp"
#include "logging/logConfiguration.hpp"
#include "logging/logFileOutput.hpp"
#include "logging/logHandle.hpp"
#include "runtime/atomic.hpp"

Semaphore AsyncLogWriter::_sem(0);
Semaphore AsyncLogWriter::_io_sem(1);

class AsyncLogLocker : public StackObj {
private:
static Semaphore _lock;
public:
AsyncLogLocker() {
_lock.wait();
}

~AsyncLogLocker() {
_lock.signal();
}
};

Semaphore AsyncLogLocker::_lock(1);

void AsyncLogWriter::enqueue_locked(const AsyncLogMessage& msg) {
if (_buffer.size() >= _buffer_max_size) {
bool p_created;
uint32_t* counter = _stats.add_if_absent(msg.output(), 0, &p_created);
*counter = *counter + 1;
// drop the enqueueing message.
return;
This conversation was marked as resolved by navyxliu

This comment has been minimized.

@simonis

simonis May 19, 2021
Member

I don't understand this? If we drop the incoming message msg, why do we increment the drop counter for the LogFileOutput of the first (i.e. front()) enqueued message?
Shouldn't this simply be:

if (_buffer.size() >= _buffer_max_size)  {
  bool p_created;
  uint32_t* counter = _stats.add_if_absent(msg->output(), 0, &p_created);
  *counter = *counter + 1;
  return;

This comment has been minimized.

@navyxliu

navyxliu May 19, 2021
Author Member

you are right. I will change this.
in previous implementation, I pop_front() and enqueue msg.
I didn't clean up everything.

}

assert(_buffer.size() < _buffer_max_size, "_buffer is over-sized.");
_buffer.push_back(msg);
_sem.signal();
}

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

{ // critical area
AsyncLogLocker lock;
enqueue_locked(m);
}
}

// LogMessageBuffer consists of a multiple-part/multiple-line messsage.
// The lock here gurantees its integrity.
This conversation was marked as resolved by navyxliu

This comment has been minimized.

@dholmes-ora

dholmes-ora May 27, 2021
Member Outdated

Typo: gurantees

void AsyncLogWriter::enqueue(LogFileOutput& output, LogMessageBuffer::Iterator msg_iterator) {
AsyncLogLocker lock;

for (; !msg_iterator.is_at_end(); msg_iterator++) {
AsyncLogMessage m(output, msg_iterator.decorations(), os::strdup(msg_iterator.message()));
enqueue_locked(m);
}
}

AsyncLogWriter::AsyncLogWriter()
: _state(ThreadState::NotReady),
_stats(17 /*table_size*/) {
if (os::create_thread(this, os::asynclog_thread)) {
_state = ThreadState::Initialized;
} else {
log_warning(logging, thread)("AsyncLogging failed to create thread. Falling back to synchronous logging.");
}

log_info(logging)("The maximum entries of AsyncLogBuffer: " SIZE_FORMAT ", estimated memory use: " SIZE_FORMAT " bytes",
_buffer_max_size, AsyncLogBufferSize);
}

class AsyncLogMapIterator {
AsyncLogBuffer& _logs;

public:
AsyncLogMapIterator(AsyncLogBuffer& logs) :_logs(logs) {}
bool do_entry(LogFileOutput* output, uint32_t* counter) {
using none = LogTagSetMapping<LogTag::__NO_TAG>;

if (*counter > 0) {
LogDecorations decorations(LogLevel::Warning, none::tagset(), output->decorators());
stringStream ss;
ss.print(UINT32_FORMAT_W(6) " messages dropped due to async logging", *counter);
AsyncLogMessage msg(*output, decorations, ss.as_string(true /*c_heap*/));
_logs.push_back(msg);
*counter = 0;
}

return true;
}
};

void AsyncLogWriter::write() {
// Use kind of copy-and-swap idiom here.
// Empty 'logs' swaps the content with _buffer.
// Along with logs destruction, all processed messages are deleted.
//
// The operation 'pop_all()' is done in O(1). All I/O jobs are then performed without
// lock protection. This guarantees I/O jobs don't block logsites.
AsyncLogBuffer logs;
{ // critical region
AsyncLogLocker lock;

_buffer.pop_all(&logs);
// append meta-messages of dropped counters
AsyncLogMapIterator dropped_counters_iter(logs);
_stats.iterate(&dropped_counters_iter);
This conversation was marked as resolved by navyxliu

This comment has been minimized.

@albertnetymk

albertnetymk May 22, 2021
Member

Any particular reason why the iterator is not declared right above its usage? IOW, why not

_buffer.pop_all(&logs);
AsyncLogMapIterator dropped_counters_iter(logs);
_stats.iterate(&dropped_counters_iter);

This comment has been minimized.

@navyxliu

navyxliu May 24, 2021
Author Member

yes, it works. I will update it.
I unconsciously wrote code in C style. ie. declarations come first, code snippet follows.

}

LinkedListIterator<AsyncLogMessage> it(logs.head());
_io_sem.wait();
while (!it.is_empty()) {
AsyncLogMessage* e = it.next();
char* msg = e->message();

if (msg != nullptr) {
e->output()->write_blocking(e->decorations(), msg);
os::free(msg);
}
}
_io_sem.signal();
}

void AsyncLogWriter::run() {
while (true) {
// The value of a semphore cannot be negative. Therefore, the current thread falls asleep
// when its value is zero. It will be waken up when new messages are enqueued.
_sem.wait();
write();
}
}

AsyncLogWriter* AsyncLogWriter::_instance = nullptr;

void AsyncLogWriter::initialize() {
if (!LogConfiguration::is_async_mode()) return;

assert(_instance == nullptr, "initialize() should only be invoked once.");

AsyncLogWriter* self = new AsyncLogWriter();
if (self->_state == ThreadState::Initialized) {
Atomic::release_store_fence(&AsyncLogWriter::_instance, self);
// All readers of _instance after the fence see non-NULL.
// We use LogOutputList's RCU counters to ensure all synchronous logsites have completed.
// After that, we start AsyncLog Thread and it exclusively takes over all logging I/O.
for (LogTagSet* ts = LogTagSet::first(); ts != NULL; ts = ts->next()) {
ts->wait_until_no_readers();
}
os::start_thread(self);
log_debug(logging, thread)("Async logging thread started.");
}
}

AsyncLogWriter* AsyncLogWriter::instance() {
return _instance;
}

// write() acquires and releases _io_sem even _buffer is empty.
// This guarantees all logging I/O of dequeued messages are done when it returns.
void AsyncLogWriter::flush() {
if (_instance != nullptr) {
_instance->write();
}
}