RFR: 8229517: Support for optional asynchronous/buffered logging

Fri Mar 26 10:05:32 UTC 2021

On Mon, 22 Mar 2021 22:12:14 GMT, Xin Liu <xliu at openjdk.org> wrote:

> This patch provides a buffer to store asynchrounous messages and flush them to
> underlying files periodically.

Hi Xin,

thanks for finally addressing this issue. In general your change looks good. Please find my detailed comments inline.

Best regards,
Volker

src/hotspot/share/logging/logAsyncFlusher.cpp line 38:

> 36: 
> 37: #ifndef PRODUCT
> 38: template<> void LinkedListDeque<AsyncLogMessage>::log_drop(AsyncLogMessage* e) {

See comment on `pop_front()`. I'd remove this function entirely and handle this functionality right to `LogAsyncFlusher::enqueue()`.

src/hotspot/share/logging/logAsyncFlusher.cpp line 72:

> 70: 
> 71:     if (_buffer.size() >= GCLogBufferSize)  {
> 72:       _buffer.pop_front();

See comment on pop_front(). Instead of relying on `pop-front()` calling `log_drop()` I propose to remove `log_drop()` and implement it's functionality right here where I think it is more appropriate. You can call `buffer.front()` to get a pointer to the `AsyncLogMessage` and easily implement the functionality of `log_drop()` here.

src/hotspot/share/logging/logAsyncFlusher.cpp line 81:

> 79: LogAsyncFlusher* LogAsyncFlusher::_instance = NULL;
> 80: 
> 81: void LogAsyncFlusher::initialize() {

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

src/hotspot/share/logging/logAsyncFlusher.hpp line 34:

> 32: 
> 33: template <typename E>
> 34: class LinkedListDeque : private LinkedListImpl<E, ResourceObj::C_HEAP, mtLogging> {

The name `LinkedListDeque` implies that this is a general purpose Deque implementation which is not true. It's fine to have an implementation for your very specific needs (otherwise it should probably be in its own file under `share/utilities/dequeue.hpp`). But to make this explicitly clear to the reader, can you please rename it to something like `AsyncFlusherDeque` and specify it's semantics in a comment on top of the class. E.g this class doesn't support the usage of the inherited `add()` method because that would break the `size()` functionality.

src/hotspot/share/logging/logAsyncFlusher.hpp line 42:

> 40:   LinkedListDeque() : _tail(NULL), _size(0) {}
> 41:   void push_back(const E& e) {
> 42:     if (!_tail)

I think the convention is to use curly braces even for one-line blocks (as you've done in your other code).

src/hotspot/share/logging/logAsyncFlusher.hpp line 64:

> 62:     if (h != NULL) {
> 63:       --_size;
> 64:       log_drop(h->data());

I'm a little unhappy that some semantics of the Dequeues basic datatype become visible in the implementation of a basic Dequeue method. E.g. "*log dropping*" is not something common for a Dequeue but for the LogAsyncFlusher. I think it would be better to drop the call to `log_drop()` here and implement this functionality right in `LogAsyncFlusher::enqueue()`.

src/hotspot/share/logging/logAsyncFlusher.hpp line 79:

> 77:   }
> 78: 
> 79:   void log_drop(E* e) {}

See comment on `pop_front()`. I'd remove this function entirely and handle it right in `LogAsyncFlusher::enqueue()`.

src/hotspot/share/logging/logAsyncFlusher.hpp line 95:

> 93:     : _output(output), _decorators(decorations.get_decorators()),
> 94:     _level(decorations.get_level()), _tagset(decorations.get_logTagSet()) {
> 95:       // allow to fail here, then _message is NULL

Why do you extract and store the `LogDecorators`, `_level` and `_tagset` set separately and re-create  the `LogDecorations` in `AsyncLogMessage::writeback()`? Is it to save memory (because  `LogDecorators` are much smaller than the `LogDecorations`) at the expense of time for recreating?

src/hotspot/share/logging/logAsyncFlusher.hpp line 96:

> 94:     _level(decorations.get_level()), _tagset(decorations.get_logTagSet()) {
> 95:       // allow to fail here, then _message is NULL
> 96:       _message = os::strdup(msg, mtLogging);

If you think `msg` can't be NULL here please add an assertion, otherwise please handle it.

src/hotspot/share/logging/logAsyncFlusher.hpp line 111:

> 109:     o._message = NULL; // transfer the ownership of _message to this
> 110:   }
> 111: 

Maybe add an explicit copy assignment operator with a `ShouldNotReachHere` to make sure `AsyncLogMessages` are not assigned unintentionally.

src/hotspot/share/logging/logAsyncFlusher.hpp line 116:

> 114:   bool equals(const AsyncLogMessage& o) const {
> 115:     return (&_output == &o._output) && (_message == o._message || !strcmp(_message, o._message));
> 116:   }

[`strcmp()` is not defined for `NULL`](https://en.cppreference.com/w/cpp/string/byte/strcmp) but you can have `_message == NULL` if you've transferred ownership in the copy constructor.

src/hotspot/share/logging/logAsyncFlusher.hpp line 124:

> 122: 
> 123: class LogAsyncFlusher : public PeriodicTask {
> 124:  private:

As far as I know, `PeriodicTask` is designed for short running task. But `LogAsyncFlusher::task()` will now call `AsyncLogMessage::writeback()` which does blocking I/O and can block for quite some time (that's why we have this change in the first place :). How does this affect the other periodic tasks and the `WatcherThread`. What's the worst case scenario if the `WatcherThread` is blocked? Is this any better than before?

src/hotspot/share/logging/logConfiguration.cpp line 544:

> 542:                                     " If set to 0, log rotation is disabled."
> 543:                                     " This will cause existing log files to be overwritten.");
> 544:   out->print_cr("   async=true|false - write asynchronously or not.");

Mention the default here which should be "false".

src/hotspot/share/logging/logDecorations.cpp line 68:

> 66: #undef DECORATOR
> 67: 
> 68:   assert(get_decorators() == decorators, "insanity check");

I think this should read "sanity check".

src/hotspot/share/logging/logDecorators.hpp line 89:

> 87:   }
> 88: 
> 89:   LogDecorators(const LogDecorators& o) : _decorators(o._decorators) {

Why do you need this new copy constructor?

src/hotspot/share/logging/logDecorators.hpp line 92:

> 90:   }
> 91: 
> 92:   LogDecorators& operator=(const LogDecorators& rhs) {

Why do you need this new assignment operator?

src/hotspot/share/logging/logFileOutput.cpp line 50:

> 48:     : LogFileStreamOutput(NULL), _name(os::strdup_check_oom(name, mtLogging)),
> 49:       _file_name(NULL), _archive_name(NULL), _current_file(0),
> 50:       _file_count(DefaultFileCount), _is_default_file_count(true), _async_mode(AsyncLogging), _archive_name_len(0),

See comments on `globals.hpp`. No need for an extra option. Make this `false` by default.

And can you please also add the `_async_mode` to the following log trace in `LogFileOutput::initialize()`:
  log_trace(logging)("Initializing logging to file '%s' (filecount: %u"
                     ", filesize: " SIZE_FORMAT " KiB).",
_file_name, _file_count, _rotate_size / K);

src/hotspot/share/logging/logFileOutput.cpp line 322:

> 320: 
> 321:   LogAsyncFlusher* flusher = LogAsyncFlusher::instance();
> 322:   if (_async_mode && flusher != NULL) {

Why you don't check for `flusher == NULL` in `LogAsyncFlusher::instance()` and call `LogAsyncFlusher::initialize()` in case it is NULL. I think it's no difference where the NULL check is and doing it in `LogAsyncFlusher::instance()` will save you from calling `LogAsyncFlusher::initialize()` in `init_globals()`.

Put `LogAsyncFlusher::instance()` into the `if (_async_mode)` block and add an assertion that `flusher != NULL`.

src/hotspot/share/logging/logFileOutput.cpp line 324:

> 322:   if (_async_mode && flusher != NULL) {
> 323:     flusher->enqueue(*this, decorations, msg);
> 324:     return 0;

I think the contract of `LogFileOutput::write()` is not clear. Should this return the number of characters that have been actually written out or the number of characters that have been consumed. For the time beeing this doesn't seem to be a problem though, because the current callers of `LogFileOutput::write()` don't seem to check the return value anyway.

src/hotspot/share/logging/logFileOutput.cpp line 336:

> 334:   }
> 335: 
> 336:   assert(!_async_mode, "AsyncLogging is not supported yet");

Can you please explain in which circumstances `LogFileOutput::write(LogMessageBuffer::Iterator msg_iterator)` will be called and why it is not necessary to support `_async_mode` here?

src/hotspot/share/runtime/init.cpp line 126:

> 124:     return status;
> 125: 
> 126:   LogAsyncFlusher::initialize();

I don't think this is required here. See my comment on `LogFileOutput::write()`. Just do the initialization  in `LogAsyncFlusher::instance()` when it is called for the first time (i.e. `LogAsyncFlusher::_instance` is still NULL).

test/hotspot/gtest/logging/test_asynclog.cpp line 168:

> 166:   EXPECT_FALSE(file_contains_substring(TestLogFileName, "log_trace-test")); // trace message is masked out
> 167:   EXPECT_TRUE(file_contains_substring(TestLogFileName, "log_debug-test"));
> 168: }

Should have a newline at the end.

-------------

Changes requested by simonis (Reviewer).

PR: https://git.openjdk.java.net/jdk/pull/3135