—Categories: OpenJDK

Backporting Async Logging to JDK11

Background

Longer than expected pauses were observed during GC in JDK 7 as explained on the Buffered Logging hotspot-dev mailing list:

Some folks noticed much longer than expected
pauses that seemed to coincide with GC logging in the midst of a GC
safepoint. In that setup, the GC logs were going to a disk file (these were
often useful for post-mortem analyses) rather than to a RAM-based tmpfs
which had been the original design center assumption. The vicissitudes of
the dirty page flushing policy in Linux when
IO load on the machine (not necessarily the JVM process doing the logging)
could affect the length and duration of these inline logging stalls.

A buffered logging scheme was then implemented by us (and independently by
others) which we have used successfully to date to avoid these pauses in
high i/o
multi-tenant environments.

[JDK-8229517] Support for optional asynchronous/buffered logging was filed for introducing that implementation to the public upstream OpenJDK. The release notes for the asynchronous logging feature describe it as a way to avoid undesirable delays in a thread using unified logging.

Note that Unified JVM Logging was introduced in JDK 9 whereas asynchronous logging was introduced in JDK17 in PR 3135. As per the Java docs, “logging messages are output synchronously” by default whereas in “asynchronous logging mode, log sites enqueue all logging messages to an intermediate buffer and a standalone thread is responsible for flushing them to the corresponding outputs.” The AWS Developer Tools Blog has an excellent writeup about how and why they implemented this feature as well as an overview of unified logging (e.g. run java -Xlog:'gc*=info:stdout' to see logging output from log_info_p, which in my case includes output from the G1InitLogger).

Starting the Backport

This is a relatively straightforward backport. Clone the jdk11u-dev repo (or your fork as appropriate). The repo was at commit 86d39a69 when I started the backport.

git clone https://github.com/openjdk/jdk11u-dev
cd jdk11u-dev/

To see the exact same outcomes, switch to that commit (if desired).

git checkout 86d39a69

To backport this feature to JDK11, cherry-pick the commit from PR 3135 onto a new branch. We need to add the upstream as a remote to enable cherry-picking PR commits. 

git checkout -b AsyncLogging
git remote add upstream-jdk https://github.com/openjdk/jdk
git fetch upstream-jdk
git cherry-pick 41185d38f21e448370433f7e4f1633777cab6170

Conflict Resolution

I used Visual Studio for conflict resolution with this strategy:

  1. Take Incoming (Source)
  2. Inspect the diff using Compare with Unmodified… to ensure that the changes being pulled are sensible.

The rest of this section can be skipped. I am including the details of the validation of the conflict resolution strategy (i.e. ensuring nothing undesirable is getting pulled in). The advantage of the strategy outlined above is that changes that are required by the code we want to backport are most likely going to be present after conflict resolution.

Conflict Resolution: logTagSet.cpp

As an example, the upstream PR introduced 1 new method and 1 extern size_t to logTagSet.hpp. After conflict resolution, the updated logTagSet.hpp contains improvements to the logging code such as

None of these changes would be present if only the changes from the PR 3135 commit were used. These lists are generated from the blame view are therefore likely omit any delete-only diffs.

Conflict Resolution: logConfiguration.cpp

This is the list of unrelated changes (i.e. changes not in commit from PR 3135) after taking the incoming changes to logConfiguration.cpp includes (potentially partial) changes from:

Conflict Resolution: logDecorators.hpp

Conflict Resolution: logFileOutput.hpp

Only the Copyright year conflicts. Other changes brought in include:

Conflict Resolution: logOutputList.hpp

Conflict Resolution: globals.hpp

Comparing the current and incoming globals.hpp reveals a significant rewriting of this file between the jdk and jdk11u-dev repos. To resolve the conflict, copy only the change from the PR 3135 commit to the target (local) globals.hpp by selecting the checkmark next to the conflict in the Visual Studio merge editor then manually fix up the last line.

Conflict Resolution: init.hpp

jdk and jdk11u-dev also have non-trivial changes to init.hpp so the Merge… command is necessary here.

Conflict Resolution: thread.cpp

The Merge… command is again necessary here due to the significant number of changes between the source and target versions. Take the single line from the source and accept the merge:

Conflict Resolution: hashtable.hpp

Use the Merge… command once more to resolve the changes between the source and target versions. Take the single line from the source and accept the merge:

Addressing Build Errors

Now that all conflicts have been resolved, build the code before committing anything. Here are additional issues that need to be resolved.

Missing ‘runtime/nonJavaThread.hpp’

D:\dev\repos\java\forks\jdk11u-dev\src\hotspot\share\logging/logAsyncWriter.hpp(31): fatal error C1083: Cannot open include file: 'runtime/nonJavaThread.hpp': No such file or directory

nonJavaThread.hpp is a file now in the upstream JDK repo. Blame shows that PR 2390 moved it out of thread.hpp. Fix:

-#include "runtime/nonJavaThread.hpp"
+#include "runtime/thread.hpp"

Missing ‘;’ before ‘<‘

D:\dev\repos\java\forks\jdk11u-dev\src\hotspot\share\logging/logAsyncWriter.hpp(111): error C2143: syntax error: missing ';' before '<'
D:\dev\repos\java\forks\jdk11u-dev\src\hotspot\share\logging/logAsyncWriter.hpp(111): error C4430: missing type specifier - int assumed. Note: C++ does not support default-int
D:\dev\repos\java\forks\jdk11u-dev\src\hotspot\share\logging/logAsyncWriter.hpp(144): error C3646: '_stats': unknown override specifier
D:\dev\repos\java\forks\jdk11u-dev\src\hotspot\share\logging/logAsyncWriter.hpp(144): error C4430: missing type specifier - int assumed. Note: C++ does not support default-int

Line 111 contains:

typedef KVHashtable<LogFileOutput*, uint32_t, mtLogging> AsyncLogMap;

Line 144 contains:

AsyncLogMap _stats; // statistics for dropped messages

Turns out KVHashtable was removed after async logging support was added so the latest sources aren’t the place to go for details about this class. Instead, see the KVHashtable implementation in the parent commit before it was removed. KVHashtable “is a subclass of BasicHashtable that allows you to do a simple K -> V mapping without using tons of boilerplate code.” The blame view of hashtable.hpp in the async logging support commit reveals that KVHashtable was added in commit 6d269930fdd3. For our purposes, we need to use the KVHashtable implementation that was in use when async logging was added.

Fix: insert lines 223-310 of hashtable.cpp into the local jdk11u-dev hashtable.hpp.

Missing pre_run Method

D:\dev\repos\java\forks\jdk11u-dev\src\hotspot\share\logging/logAsyncWriter.hpp(155): error C3668: 'AsyncLogWriter::pre_run': method with override specifier 'override' did not override any base class methods
D:\dev\repos\java\forks\jdk11u-dev\src\hotspot\share\logging/logAsyncWriter.hpp(156): error C2039: 'pre_run': is not a member of 'NonJavaThread'

Notice that nonJavaThread.hpp in the upstream JDK repo has a pre_run method, unlike the NonJavaThread class in jdk11u-dev. The blame view of PR 2390’s parent commit reveals that these methods were added in commit 526f854c.

Fix: Remove the pre_run method from logAsyncWritter.hpp.

Stream Errors

./src/hotspot/share/logging/logAsyncWriter.cpp(108): error C2660: 'stringStream::as_string': function does not take 1 arguments
D:\dev\repos\java\jdk11u-dev\src\hotspot\share\utilities/ostream.hpp(220): note: see declaration of 'stringStream::as_string'
./src/hotspot/share/logging/logAsyncWriter.cpp(108): error C2661: 'AsyncLogMessage::AsyncLogMessage': no overloaded function takes 2 arguments

The as_string method only has a boolean parameter in the jdk repo (added in JDK15).

Fix: Remove the parameter to as_string.

Conversion loses qualifiers

./src/hotspot/share/logging/logAsyncWriter.cpp(143): error C2440: 'initializing': cannot convert from 'const E *' to 'AsyncLogMessage *'
        with
        [
            E=AsyncLogMessage
        ]
./src/hotspot/share/logging/logAsyncWriter.cpp(143): note: Conversion loses qualifiers

Line 143 contains:

AsyncLogMessage* e = it.next();

This works in the original async logging implementation because jdk/src/hotspot/share/utilities/linkedlist.hpp was updated by 8239066: make LinkedList<T> more generic (a next() method that returns an E* was added).

Fix: git cherry-pick b08595d8443bbfb141685dc5eda7c58a34738048 and resolve the conflict (year on copyright line) using Take Incoming (Source).

Unknown class AutoModifyRestore

./test/hotspot/gtest/logging/test_asynclog.cpp(205): error C2065: 'AutoModifyRestore': undeclared identifier
./test/hotspot/gtest/logging/test_asynclog.cpp(205): error C2275: 'size_t': illegal use of this type as an expression
./build/windows-x86_64-normal-server-release/hotspot/variant-server/libjvm/gtest/objs/BUILD_GTEST_LIBJVM_pch.cpp: note: see declaration of 'size_t'
./test/hotspot/gtest/logging/test_asynclog.cpp(205): error C3861: 'saver': identifier not found

Line 205 contains:

AutoModifyRestore<size_t> saver(AsyncLogBufferSize, sz * 1024 /*in byte*/);

AutoModifyRestore was introduced to fix JDK-8245226.

Fix:

cd src/hotspot/share/utilities/
curl -Lo autoRestore.hpp https://raw.githubusercontent.com/openjdk/jdk/195c45a0e11207e15c277e7671b2a82b8077c5fb/src/hotspot/share/utilities/autoRestore.hpp
# Now include autoRestore.hpp in test_asynclog.cpp

Atomic Errors

./src/hotspot/share/logging/logAsyncWriter.cpp(172): error C2039: 'release_store_fence': is not a member of 'Atomic'
D:\dev\repos\java\jdk11u-dev\src\hotspot\share\runtime/atomic.hpp(51): note: see declaration of 'Atomic'
./src/hotspot/share/logging/logAsyncWriter.cpp(172): error C3861: 'release_store_fence': identifier not found

This method was added to atomic.hpp by OrderAccess. Notice that it appears to have been moved from orderAccess.hpp.

Fix:

-Atomic::release_store_fence(&AsyncLogWriter::_instance, self);
+OrderAccess::release_store_fence(&AsyncLogWriter::_instance, self);

‘disable_outputs’ Identifier not Found

./src/hotspot/share/logging/logConfiguration.cpp(114): error C3861: 'disable_outputs': identifier not found
./src/hotspot/share/logging/logConfiguration.cpp(278): error C2039: 'disable_outputs': is not a member of 'LogConfiguration'
D:\dev\repos\java\forks\jdk11u-dev\src\hotspot\share\logging/logConfiguration.hpp(39): note: see declaration of 'LogConfiguration'
./src/hotspot/share/logging/logConfiguration.cpp(279): error C2065: '_n_outputs': undeclared identifier
./src/hotspot/share/logging/logConfiguration.cpp(293): error C2065: '_outputs': undeclared identifier
./src/hotspot/share/logging/logConfiguration.cpp(296): error C3861: 'delete_output': identifier not found
./src/hotspot/share/logging/logConfiguration.cpp(298): error C2248: 'LogOutput::set_config_string': cannot access protected member declared in class 'LogOutput'
D:\dev\repos\java\forks\jdk11u-dev\src\hotspot\share\logging/logOutput.hpp(63): note: see declaration of 'LogOutput::set_config_string'
D:\dev\repos\java\forks\jdk11u-dev\src\hotspot\share\logging/logConfiguration.hpp(31): note: see declaration of 'LogOutput'

Line 114 is simple the method call disable_outputs(); Since that method body is present in the file, it must be missing in the header file. The correct logConfiguration.hpp shows that 8255756: Disabling logging does unnecessary work is necessary. (This error might have been visible earlier in the process!)

Fix:

git cherry-pick e66fd6f0aa43356ab4b4361d6d332e5e3bcabeb6

# Resolve straightforward conflicts.

git cherry-pick --continue

Undeclared Identifier

./src/hotspot/share/runtime/thread.cpp(4694): error C2065: 'cl': undeclared identifier

Line 4706 contains:

cl.do_thread(AsyncLogWriter::instance());

The declaration of cl is missing. Blame says it was introduced by commit 06e47d05 of [JDK-8246622] Remove CollectedHeap::print_gc_threads_on() – Java Bug System. Simply paste that PrintClosure class definition into thread.cpp (after line 4654) and the cl declaration PrintOnClosure cl(st); on (now) line 4714.

Building on macOS

Once the build succeeds on Windows, validate the changes by building on macOS.

Undeclared identifier ‘primitive_hash’ 

/Users/saint/repos/java/forks/jdk11u-dev/src/hotspot/share/utilities/hashtable.hpp:326:36: error: use of undeclared identifier 'primitive_hash'
    unsigned (*HASH)  (K const&) = primitive_hash<K>,
                                   ^
/Users/saint/repos/java/forks/jdk11u-dev/src/hotspot/share/utilities/hashtable.hpp:327:46: error: use of undeclared identifier 'primitive_equals'
    bool     (*EQUALS)(K const&, K const&) = primitive_equals<K>

Fix:

diff --git a/src/hotspot/share/utilities/hashtable.hpp b/src/hotspot/share/utilities/hashtable.hpp
index 30483b2f36..5e4c414490 100644
--- a/src/hotspot/share/utilities/hashtable.hpp
+++ b/src/hotspot/share/utilities/hashtable.hpp
@@ -30,6 +30,7 @@
 #include "oops/oop.hpp"
 #include "oops/symbol.hpp"
 #include "runtime/handles.hpp"
+#include "utilities/resourceHash.hpp"
 
 // This is a generic hashtable, designed to be used for the symbol
 // and string tables.

Default Member Initializer is a C++11 Extension

/Users/saint/repos/java/forks/jdk11u-dev/src/hotspot/share/logging/logAsyncWriter.hpp:149:33: error: default member initializer for non-static data member is a C++11 extension [-Werror,-Wc++11-extensions]
  const size_t _buffer_max_size = {AsyncLogBufferSize / (sizeof(AsyncLogMessage) + vwrite_buffer_size)};
                                ^

Fix:

diff --git a/src/hotspot/share/logging/logAsyncWriter.cpp b/src/hotspot/share/logging/logAsyncWriter.cpp
index 0231be78a9..d9f9ddda5b 100644
--- a/src/hotspot/share/logging/logAsyncWriter.cpp
+++ b/src/hotspot/share/logging/logAsyncWriter.cpp
@@ -82,7 +82,8 @@ void AsyncLogWriter::enqueue(LogFileOutput& output, LogMessageBuffer::Iterator m
 
 AsyncLogWriter::AsyncLogWriter()
   : _initialized(false),
-    _stats(17 /*table_size*/) {
+    _stats(17 /*table_size*/),
+    _buffer_max_size(AsyncLogBufferSize / (sizeof(AsyncLogMessage) + vwrite_buffer_size)) {
   if (os::create_thread(this, os::asynclog_thread)) {
     _initialized = true;
   } else {
diff --git a/src/hotspot/share/logging/logAsyncWriter.hpp b/src/hotspot/share/logging/logAsyncWriter.hpp
index 313dd6de06..c4e28e5676 100644
--- a/src/hotspot/share/logging/logAsyncWriter.hpp
+++ b/src/hotspot/share/logging/logAsyncWriter.hpp
@@ -146,7 +146,7 @@ class AsyncLogWriter : public NonJavaThread {
 
   // 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)};
+  const size_t _buffer_max_size;
 
   AsyncLogWriter();
   void enqueue_locked(const AsyncLogMessage& msg);

‘override’ keyword is a C++11 extension

/Users/saint/repos/java/forks/jdk11u-dev/src/hotspot/share/logging/logAsyncWriter.hpp:154:14: error: 'override' keyword is a C++11 extension [-Werror,-Wc++11-extensions]
  void run() override;
             ^
...

Fix: Remove the override keywords

diff --git a/src/hotspot/share/logging/logAsyncWriter.hpp b/src/hotspot/share/logging/logAsyncWriter.hpp
index 313dd6de06..e6ac8aab4a 100644
--- a/src/hotspot/share/logging/logAsyncWriter.hpp
+++ b/src/hotspot/share/logging/logAsyncWriter.hpp
@@ -151,10 +151,10 @@ class AsyncLogWriter : public NonJavaThread {
   AsyncLogWriter();
   void enqueue_locked(const AsyncLogMessage& msg);
   void write();
-  void run() override;
-  char* name() const override { return (char*)"AsyncLog Thread"; }
-  bool is_Named_thread() const override { return true; }
-  void print_on(outputStream* st) const override {
+  void run();
+  char* name() const { return (char*)"AsyncLog Thread"; }
+  bool is_Named_thread() const { return true; }
+  void print_on(outputStream* st) const {
     st->print("\"%s\" ", name());
     Thread::print_on(st);
     st->cr();

Building on Linux

Depending on the GCC version, logAsyncWriter.cpp, logFileOutput.cpp, and test_asynclog.cpp might need to define nullptr to successfully compile:

#ifdef __linux__
#define nullptr 0
#endif

Testing the Build

Windows

To test the async logging code, run this command (HelloWorld doesn’t even need to exist for a really basic test):

./build/windows-x86_64-normal-server-release/jdk/bin/java.exe -Xlog:async -Xlog:all=trace:file=all.log::filecount=0 HelloWorld

Fixing Runtime Bugs

Corrupted Output

After running the simple test above, it becomes evident from the output lgos that something is wrong:

[0.039s][info ][logging          ] The maximum entries of AsyncLogBuffer: 2319, estimated memory use: 2097152 bytes
[@ùŸôÊ ][debug][@ùŸôÊ            ] Async logging thread started.
[      ][info ][ôŸôÊ            ] TemplateTable initialization, 0.0000106 secs

Search for %.*.3.+ to find where the log decorations are done based on this output in the log file. Looks like the big difference is from 8266503: [UL] Make Decorations safely copy-able and reduce their size.

Fix:

git cherry-pick 94c6177f246fc569b416f85f1411f7fe031f7aaf
git cherry-pick 74fecc070a6462e6a2d061525b53a63de15339f9

Wrong Parameter Order

Notice that the order of the parameters passed to Atomic::cmpxchg was also changed so we need to ensure that the arguments are swapped (since they were written when the new Atomic::cmpxchg was already in place). Move the first argument into the last spot.

Resources