8267517: async logging for stdout and stderr #6132

navyxliu · 2021-10-27T08:22:12Z

This patch refactors LogFileStreamOutput so stdout/stderr can support support -Xlog:async.

With -Xlog:all=trace:stdout, the helloworld in Java outputs 16520 log entries to stdout. We are see that the wall time reduces from 84.138ms to 72.914ms, or the throughput increases 15% because of async logging.

$perf stat -r 300 ./build/linux-x86_64-server-release/images/jdk/bin/java -Xlog:all=trace:stdout -Xlog:async -XX:AsyncLogBufferSize=48M HelloWorld > /dev/null

 Performance counter stats for './build/linux-x86_64-server-release/images/jdk/bin/java -Xlog:all=trace:stdout -Xlog:async -XX:AsyncLogBufferSize=48M HelloWorld' (300 runs):

            107.21 msec task-clock                #    1.470 CPUs utilized            ( +-  0.17% )
             2,681      context-switches          #    0.025 M/sec                    ( +-  0.32% )
                 1      cpu-migrations            #    0.011 K/sec                    ( +-  4.56% )
             4,006      page-faults               #    0.037 M/sec                    ( +-  0.01% )
...
          0.072914 +- 0.000126 seconds time elapsed  ( +-  0.17% )

 Performance counter stats for './build/linux-x86_64-server-release/images/jdk/bin/java -Xlog:all=trace:stdout -XX:AsyncLogBufferSize=48M HelloWorld' (300 runs):

             88.04 msec task-clock                #    1.046 CPUs utilized            ( +-  0.10% )
               310      context-switches          #    0.004 M/sec                    ( +-  0.31% )
                 1      cpu-migrations            #    0.008 K/sec                    ( +-  5.07% )
             4,004      page-faults               #    0.045 M/sec                    ( +-  0.01% )
...
          0.084138 +- 0.000111 seconds time elapsed  ( +-  0.13% )

The easiest test of stdout with AsyncLogging is to use tty and XOFF Ctrl^s. Java applications with UL to stdout were blocked by Ctrl-s. The entire java process will be frozen. -Xlog:async now cover both stdout and stderr. It can circumvent this issue.

Add a new jtreg to cover a scenario that unified logging with -Xlog:async will not be frozen even when stdout is blocked.

Progress

Change must not contain extraneous whitespace
Commit message must refer to an issue
Change must be properly reviewed

Issue

JDK-8267517: async logging for stdout and stderr

Reviewers

David Holmes (@dholmes-ora - Reviewer)
Yasumasa Suenaga (@YaSuenag - Reviewer)

Reviewing

Using git

Checkout this PR locally:
$ git fetch https://git.openjdk.java.net/jdk pull/6132/head:pull/6132
$ git checkout pull/6132

Update a local copy of the PR:
$ git checkout pull/6132
$ git pull https://git.openjdk.java.net/jdk pull/6132/head

Using Skara CLI tools

Checkout this PR locally:
$ git pr checkout 6132

View PR using the GUI difftool:
$ git pr show -t 6132

Using diff file

Download this PR as a diff file:
https://git.openjdk.java.net/jdk/pull/6132.diff

This patch refactors logFileStreamOutput and make stdout/stderr support async logging. This patch also removes FileLocker for asynclogging. There's only one thread write logs.

Log rotation only happens in LogFileOutput::flush().This fixes the regression test 'serviceability/logging/TestLogRotation.java'.

we don't need Atomic::add for _current_size because it's synchronized.

This patch fixes two regressions. they have more than 1 active logging outputs. serviceability/logging/TestFullNames.java serviceability/logging/TestQuotedLogOutputs.java Please enter the commit message for your changes. Lines starting

…king

bridgekeeper · 2021-10-27T08:22:55Z

👋 Welcome back xliu! A progress list of the required criteria for merging this PR into master will be added to the body of your pull request. There are additional pull request commands available for use with this pull request.

openjdk · 2021-10-27T08:26:02Z

@navyxliu The following label will be automatically applied to this pull request:

hotspot-runtime

When this pull request is ready to be reviewed, an "RFR" email will be sent to the corresponding mailing list. If you would like to change these labels, use the /label pull request command.

bridgekeeper · 2021-11-24T09:59:46Z

@navyxliu This pull request has been inactive for more than 8 weeks and will be automatically closed if another 8 weeks passes without any activity. To avoid this, simply add a new comment to the pull request. Feel free to ask for assistance if you need help with progressing this pull request towards integration!

taskset 0x1 make test TEST='runtime/logging/BlockedLoggingTest.java'

mlbridge · 2021-12-07T02:59:39Z

Webrevs

navyxliu · 2021-12-10T17:19:54Z

Hello,
May I ping this?

dholmes-ora

Hi Xin,

I took a look at this but to be honest I couldn't work out what most of the changes actually had to do with the topic of adding async logging for stdout/stderr. IIUC the change from LogFileOutput to LogFileStreamOutput in the API now enables it to be used for stdout/stderr - right? But most of the changes seemed to relate to log file rotation which doesn't even apply to stdout/stderr! What has force_rotation got to do with things?

David

src/hotspot/share/logging/logFileStreamOutput.hpp

test/hotspot/jtreg/runtime/logging/BlockedLoggingTest.java

navyxliu · 2021-12-15T03:26:06Z

Hi Xin,

I took a look at this but to be honest I couldn't work out what most of the changes actually had to do with the topic of adding async logging for stdout/stderr. IIUC the change from LogFileOutput to LogFileStreamOutput in the API now enables it to be used for stdout/stderr - right? But most of the changes seemed to relate to log file rotation which doesn't even apply to stdout/stderr! What has force_rotation got to do with things?

David

Sorry, this is my fault. This patch incorporates with JDK-8275083. They are so intertwined that I can't split them.
So far, I fail to measure any meaningful performance gain from JDK-8275083, so let me refactor the code and remove JDK-8275083.

navyxliu · 2021-12-21T02:32:07Z

hi, @dholmes-ora ,
I update the the PR, stripping JDK-8275083. As a result, UL throughput to STDOUT increases 15% with -Xlog:async.
It was 20% with JDK-8275083 but I don't think the 5% gain justifies the bigger patch. This patch is now smaller. Could you take a look?

dholmes-ora

Hi Xin,

I think I get the gist of what this is doing now - thanks. A few minor comments below. I'm not sure about the robustness of the test, in particular whether destroyForcibly will be reliable enough on all platform. I will take it for a spin through our CI system.

Thanks,
David

src/hotspot/share/logging/logAsyncWriter.cpp

src/hotspot/share/logging/logAsyncWriter.hpp

test/hotspot/jtreg/runtime/logging/BlockedLoggingTest.java

dholmes-ora

Sorry Xin, the test is timing out on Linux-x64. There's no information to diagnose any problems though.

David

src/hotspot/share/logging/logAsyncWriter.hpp

src/hotspot/share/logging/logAsyncWriter.cpp

test/hotspot/jtreg/ProblemList.txt

navyxliu · 2021-12-22T01:33:20Z

Okay so why does LFO::write_blocking call fflush but LFSO::write_blocking does not? Shouldn't the two methods have the same general semantics?

This is a good question! LFSO::write(LogMessageBuffer::Iterator msg_iterator) only flushes after it writes a chain of messages. LSO::write(LogMessageBuffer::Iterator msg_iterator) drops this semantic because of log rotation for files.

you are right. I shouldn't provide "write_blocking" functions with 2 different semantics. That will confuse everybody including me. This can be done.

…ynclog.cpp. This patch also adds to flushing semantic to LogFileStreamOutput::write_blocking(). It aligns with LogFileOutput::write_blocking().

navyxliu · 2021-12-22T19:59:12Z

hi, @dholmes-ora ,

I come up an idea to prove that -Xlog:async at work. In gtest test_asynclog.cpp, I use testing::internal::GetCapturedStdout/err() to get the contents of stdout/err. Only AsyncLog will drop messages because of the buffer size. freopen is simpler, however I found "freopen(TestLogFileName, stdout)` would mess with other testsuites because all TEST_VM_F run in a same process.

In this revision, write_blocking() has flushing semantic for both LFO and LFSO. Could you take a look?

dholmes-ora

Latest version looks good to me. I'm running it through our CI testing.

Thanks,
David

openjdk · 2021-12-23T02:48:08Z

@navyxliu This change now passes all automated pre-integration checks.

ℹ️ This project also has non-automated pre-integration requirements. Please see the file CONTRIBUTING.md for details.

After integration, the commit message for the final commit will be:

8267517: async logging for stdout and stderr

Reviewed-by: dholmes, ysuenaga

You can use pull request commands such as /summary, /contributor and /issue to adjust it as needed.

At the time when this comment was updated there had been 104 new commits pushed to the master branch:

ad1dc9c: 8278125: Some preallocated OOMEs are missing stack trace
eaefb1a: 8244669: convert clhsdb "mem" command from javascript to java
d64820d: 8209398: sun/security/pkcs11/KeyStore/SecretKeysBasic.sh failed with "PKCS11Exception: CKR_ATTRIBUTE_SENSITIVE"
f1fbba2: Merge
dfb15c3: 8274315: JFR: One closed state per file or stream
e49d4a9: 8271447: java.nio.file.InvalidPathException: Malformed input or input contains unmappable characters
713fbeb: 8278987: RunThese24H.java failed with EXCEPTION_ACCESS_VIOLATION in write_sample_info
7341439: 8279007: jstatd fails to start because SecurityManager is disabled
97c5cd7: 8278508: Enable X86 maskAll instruction pattern for 32 bit JVM.
9ee3ccf: 8279045: Intrinsics missing vzeroupper instruction
... and 94 more: https://git.openjdk.java.net/jdk/compare/46f99aca94ed878a94878eacb113fe2813050ad7...master

As there are no conflicts, your changes will automatically be rebased on top of these commits when integrating. If you prefer to avoid this automatic rebasing, please check the documentation for the /integrate command for further details.

➡️ To integrate this PR with the above commit message to the master branch, type /integrate in a new comment.

dholmes-ora · 2021-12-23T05:18:09Z

Testing results were fine.

navyxliu · 2021-12-23T20:20:57Z

@dholmes-ora @YaSuenag
Thanks for reviewing!

navyxliu · 2021-12-23T20:23:54Z

/integrate

openjdk · 2021-12-23T20:25:16Z

Going to push as commit 7aff03a.
Since your change was applied there have been 109 commits pushed to the master branch:

ff2ca4f: 8205187: javac/javadoc should not crash if no java.lang; crash message obsolete
bc0466c: 8279182: MakeZipReproducible ZipEntry timestamps not localized to UTC
558a682: 8279115: Fix internal doc comment errors.
87cc4e5: 8276302: Locale.filterTags methods ignore actual weight when matching "*" (as if it is 1)
214f98f: 8278766: Enable OpenJDK build support for reproducible jars and jmods using --date
ad1dc9c: 8278125: Some preallocated OOMEs are missing stack trace
eaefb1a: 8244669: convert clhsdb "mem" command from javascript to java
d64820d: 8209398: sun/security/pkcs11/KeyStore/SecretKeysBasic.sh failed with "PKCS11Exception: CKR_ATTRIBUTE_SENSITIVE"
f1fbba2: Merge
dfb15c3: 8274315: JFR: One closed state per file or stream
... and 99 more: https://git.openjdk.java.net/jdk/compare/46f99aca94ed878a94878eacb113fe2813050ad7...master

Your commit was automatically rebased without conflicts.

openjdk · 2021-12-23T20:25:35Z

@navyxliu Pushed as commit 7aff03a.

💡 You may see a message that your pull request was closed with unmerged commits. This can be safely ignored.

Xin Liu added 5 commits October 11, 2021 08:53

8267517: async logging for stdout and stderr

dff4701

This patch refactors logFileStreamOutput and make stdout/stderr support async logging. This patch also removes FileLocker for asynclogging. There's only one thread write logs.

make LogFileStreamOutput::flush() virtual.

f0c7edf

Log rotation only happens in LogFileOutput::flush().This fixes the regression test 'serviceability/logging/TestLogRotation.java'.

Make FileLocker an inner class of LogFileStreamOutput.

62df386

we don't need Atomic::add for _current_size because it's synchronized.

Add a jtreg test to demonstrate -Xlog:async can prevent JVM from bloc…

10f2704

…king

openjdk bot added the hotspot-runtime hotspot-runtime-dev@openjdk.org label Oct 27, 2021

Xin Liu added 6 commits December 2, 2021 18:33

Merge branch 'master' into JDK-8267517

23a6287

Update the jtreg test.

f1c7aa9

Fix the deadlock issue on single core.

d49d6fc

taskset 0x1 make test TEST='runtime/logging/BlockedLoggingTest.java'

Fixed the regression test.

b3f4f87

Merge branch 'master' into JDK-8267517

014988f

Remove the unused semaphore in LogFileOutput.

45e1591

navyxliu marked this pull request as ready for review December 7, 2021 02:54

openjdk bot added the rfr Pull request is ready for review label Dec 7, 2021

dholmes-ora reviewed Dec 14, 2021

View reviewed changes

Xin Liu added 3 commits December 15, 2021 06:52

Merge branch 'master' into JDK-8267517

70ca54e

Refactor code. Remove JDK-8275083.

119a51d

Fix typo and the building eror on MacOS.

396f7cd

dholmes-ora reviewed Dec 21, 2021

View reviewed changes

dholmes-ora suggested changes Dec 21, 2021

View reviewed changes

Sideline BlockedLoggingTest.java

769110a

openjdk bot removed the rfr Pull request is ready for review label Dec 21, 2021

dholmes-ora reviewed Dec 21, 2021

View reviewed changes

Remove BlockedLoggingTest.java and add test for stdout/err in test_as…

eed6f8a

…ynclog.cpp. This patch also adds to flushing semantic to LogFileStreamOutput::write_blocking(). It aligns with LogFileOutput::write_blocking().

openjdk bot added the rfr Pull request is ready for review label Dec 22, 2021

dholmes-ora approved these changes Dec 23, 2021

View reviewed changes

openjdk bot added the ready Pull request is ready to be integrated label Dec 23, 2021

YaSuenag approved these changes Dec 23, 2021

View reviewed changes

openjdk bot added the integrated Pull request has been integrated label Dec 23, 2021

openjdk bot closed this Dec 23, 2021

openjdk bot removed ready Pull request is ready to be integrated rfr Pull request is ready for review labels Dec 23, 2021

8267517: async logging for stdout and stderr #6132

8267517: async logging for stdout and stderr #6132

Uh oh!

Conversation

navyxliu commented Oct 27, 2021 • edited by openjdk bot Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Progress

Issue

Reviewers

Reviewing

Uh oh!

bridgekeeper bot commented Oct 27, 2021

Uh oh!

openjdk bot commented Oct 27, 2021

Uh oh!

bridgekeeper bot commented Nov 24, 2021

Uh oh!

mlbridge bot commented Dec 7, 2021 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Webrevs

Uh oh!

navyxliu commented Dec 10, 2021

Uh oh!

dholmes-ora left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

navyxliu commented Dec 15, 2021

Uh oh!

navyxliu commented Dec 21, 2021

Uh oh!

dholmes-ora left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

dholmes-ora left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

navyxliu commented Dec 22, 2021

Uh oh!

navyxliu commented Dec 22, 2021

Uh oh!

dholmes-ora left a comment

Choose a reason for hiding this comment

Uh oh!

openjdk bot commented Dec 23, 2021 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

dholmes-ora commented Dec 23, 2021

Uh oh!

navyxliu commented Dec 23, 2021

Uh oh!

navyxliu commented Dec 23, 2021

Uh oh!

openjdk bot commented Dec 23, 2021

Uh oh!

openjdk bot commented Dec 23, 2021

Uh oh!

Uh oh!

navyxliu commented Oct 27, 2021 •

edited by openjdk bot

Loading

mlbridge bot commented Dec 7, 2021 •

edited

Loading

openjdk bot commented Dec 23, 2021 •

edited

Loading