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 all 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
@@ -714,6 +714,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;
@@ -0,0 +1,194 @@
/*
* 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 guarantees its integrity.
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()
: _initialized(false),
_stats(17 /*table_size*/) {
if (os::create_thread(this, os::asynclog_thread)) {
_initialized = true;
} 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;
bool own_io = false;

{ // 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.

own_io = _io_sem.trywait();
}

LinkedListIterator<AsyncLogMessage> it(logs.head());
if (!own_io) {
_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->_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();
}
}
@@ -0,0 +1,176 @@
/*
* 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.
*
*/
#ifndef SHARE_LOGGING_LOGASYNCWRITER_HPP
#define SHARE_LOGGING_LOGASYNCWRITER_HPP
#include "logging/log.hpp"
This conversation was marked as resolved by navyxliu

This comment has been minimized.

@phohensee

phohensee May 20, 2021
Member

Use SHARE_LOGGING_LOGASYNCHWRITER_HPP to conform with existing naming standard.

This comment has been minimized.

@navyxliu

navyxliu May 22, 2021
Author Member

Oh, there's a hidden naming convention here.
thanks for the head-up!

#include "logging/logDecorations.hpp"
#include "logging/logFileOutput.hpp"
#include "logging/logMessageBuffer.hpp"
#include "memory/resourceArea.hpp"
#include "runtime/nonJavaThread.hpp"
#include "utilities/hashtable.hpp"
#include "utilities/linkedlist.hpp"

This conversation was marked as resolved by navyxliu

This comment has been minimized.

@dholmes-ora

dholmes-ora May 21, 2021
Member

Could you write a summary of operation comment explaining how async mode works e.g. details on initialization and teardown, how the thread interacts with writers etc. Thanks.

This comment has been minimized.

@navyxliu

navyxliu May 21, 2021
Author Member

How about this?

initialize() is called once when JVM is initialized. It creates and initialize the singleton instance of AsyncLogWriter. Once async logging is established, there's no way to turn it off.

instance() is MT-safe and returns the pointer of the singleton instance if and only if async mode is on and has well initialized. Clients can use its return value to determine async logging is established or not.

The basic operation of AsyncLogWriter is enqueue. Two overloading versions of it are provided to match LogOutput::write. To support async logging, derived classes of LogOutput can invoke the corresponding AsyncLogWriter::enqueue in write() and return -1. AsyncLogWriter is responsible of copying both decorations and cstr messages and managing their lifecycle.

The static member function flushis designated to flush out all pending messages when JVM is terminating or aborting. In normal JVM termination, flush() is invoked in LogConfiguration::finalize(). In abortion situation, flush() is invoked in os::shutdown(). flush is MT-safe and can be invoked arbitrary times. It is no-op if asynclogging is not established.

template <typename E, MEMFLAGS F>
class LinkedListDeque : private LinkedListImpl<E, ResourceObj::C_HEAP, F> {
private:
LinkedListNode<E>* _tail;
size_t _size;

public:
LinkedListDeque() : _tail(NULL), _size(0) {}
void push_back(const E& e) {
if (!_tail) {
_tail = this->add(e);
} else {
_tail = this->insert_after(e, _tail);
}

++_size;
}

// pop all elements to logs.
void pop_all(LinkedList<E>* logs) {
logs->move(static_cast<LinkedList<E>* >(this));
_tail = NULL;
_size = 0;
}

void pop_all(LinkedListDeque<E, F>* logs) {
logs->_size = _size;
logs->_tail = _tail;
pop_all(static_cast<LinkedList<E>* >(logs));
}

void pop_front() {
LinkedListNode<E>* h = this->unlink_head();
if (h == _tail) {
_tail = NULL;
}

if (h != NULL) {
--_size;
this->delete_node(h);
}
}

size_t size() const { return _size; }

const E* front() const {
return this->_head == NULL ? NULL : this->_head->peek();
}

const E* back() const {
return _tail == NULL ? NULL : _tail->peek();
}

LinkedListNode<E>* head() const {
return this->_head;
}
};

class AsyncLogMessage {
LogFileOutput& _output;
const LogDecorations _decorations;
char* _message;

public:
AsyncLogMessage(LogFileOutput& output, const LogDecorations& decorations, char* msg)
: _output(output), _decorations(decorations), _message(msg) {}

// placeholder for LinkedListImpl.
bool equals(const AsyncLogMessage& o) const { return false; }

LogFileOutput* output() const { return &_output; }
const LogDecorations& decorations() const { return _decorations; }
char* message() const { return _message; }
};

typedef LinkedListDeque<AsyncLogMessage, mtLogging> AsyncLogBuffer;
typedef KVHashtable<LogFileOutput*, uint32_t, mtLogging> AsyncLogMap;

//
// ASYNC LOGGING SUPPORT
//
// Summary:
// Async Logging is working on the basis of singleton AsyncLogWriter, which manages an intermediate buffer and a flushing thread.
//
// Interface:
//
// initialize() is called once when JVM is initialized. It creates and initializes the singleton instance of AsyncLogWriter.
// Once async logging is established, there's no way to turn it off.
//
// instance() is MT-safe and returns the pointer of the singleton instance if and only if async logging is enabled and has well
// initialized. Clients can use its return value to determine async logging is established or not.
//
// The basic operation of AsyncLogWriter is enqueue(). 2 overloading versions of it are provided to match LogOutput::write().
// They are both MT-safe and non-blocking. Derived classes of LogOutput can invoke the corresponding enqueue() in write() and
// return 0. AsyncLogWriter is responsible of copying neccessary data.
//
// The static member function flush() is designated to flush out all pending messages when JVM is terminating.
// In normal JVM termination, flush() is invoked in LogConfiguration::finalize(). flush() is MT-safe and can be invoked arbitrary
// times. It is no-op if async logging is not established.
//
class AsyncLogWriter : public NonJavaThread {
static AsyncLogWriter* _instance;
// _sem is a semaphore whose value denotes how many messages have been enqueued.

This comment has been minimized.

@albertnetymk

albertnetymk May 22, 2021
Member

"how many messages have been enqueued" seems to suggest it's a monotonically growing number as new message are enqueued. In fact, this number will decrease as _buffer is flushed. Maybe "_sem denotes the number of messages in _buffer` and moving the two together?

This comment has been minimized.

@navyxliu

navyxliu May 24, 2021
Author Member

The value of _sem denotes the number of messages have been enqueued. It's actually different from "the number of messages in _buffer". When _sem.wait() returns, it just decreases one. however, _buffer.pop_all() pops all messages in queue at once. The two numbers are not consistent all the time.

Maybe "_sem denotes the number of messages in _buffer` and moving the two together?

Could you elaborate this? thanks?

This comment has been minimized.

@albertnetymk

albertnetymk May 24, 2021
Member

When _sem.wait() returns, it just decreases one. however, _buffer.pop_all() pops all messages in queue at once. The two numbers are not consistent all the time.

Thank you for the explanation. I overlooked the fact that the "consumer" clears out the buffer in bulk.

Could you elaborate this? thanks?

I mean that "_sem is a semaphore whose value denotes how many messages have been enqueued" is a bit inaccurate, because write() will decrement the semaphore value. For example, a producer has enqueued 2 msgs, but _sem could be 0, as flush has been called.

However, I don't see a easy way to "fix" this; I am OK with the current comment.

This comment has been minimized.

@navyxliu

navyxliu May 27, 2021
Author Member

Technically, we can make _sem denotes "the number of messages in buffer".
Semaphore.signal() can pass in an integer argument. It should increase the semaphore value count instead of just 1.
I don't think it would help for performance but can avoid wasteful spin. Let's do that later.

// It decreases in AsyncLogWriter::run()
static Semaphore _sem;
This conversation was marked as resolved by navyxliu

This comment has been minimized.

@dholmes-ora

dholmes-ora May 21, 2021
Member

What is this semaphore for? A comment and/or a more meaningful name would be good.

This comment has been minimized.

@navyxliu

navyxliu May 22, 2021
Author Member

I added some comments here and _sem.wait().

// A lock of IO
static Semaphore _io_sem;

volatile bool _initialized;
AsyncLogMap _stats; // statistics for dropped messages
AsyncLogBuffer _buffer;

// The memory use of each AsyncLogMessage (payload) consists of itself and a variable-length c-str message.
// A regular logging message is smaller than vwrite_buffer_size, which is defined in logtagset.cpp
const size_t _buffer_max_size = {AsyncLogBufferSize / (sizeof(AsyncLogMessage) + vwrite_buffer_size)};

AsyncLogWriter();
void enqueue_locked(const AsyncLogMessage& msg);
void write();
void run() override;
void pre_run() override {
NonJavaThread::pre_run();
log_debug(logging, thread)("starting AsyncLog Thread tid = " INTX_FORMAT, os::current_thread_id());
}
char* name() const override { return (char*)"AsyncLog Thread"; }
bool is_Named_thread() const override { return true; }
void print_on(outputStream* st) const override {
st->print("\"%s\" ", name());
Thread::print_on(st);
st->cr();
}

public:
void enqueue(LogFileOutput& output, const LogDecorations& decorations, const char* msg);
void enqueue(LogFileOutput& output, LogMessageBuffer::Iterator msg_iterator);

static AsyncLogWriter* instance();
static void initialize();
static void flush();
};

#endif // SHARE_LOGGING_LOGASYNCWRITER_HPP