RFR: 8267517: async logging for stdout and stderr [v3]

[David Holmes]

On Thu, 16 Dec 2021 09:01:28 GMT, Xin Liu <xliu at openjdk.org> wrote:

>> 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.
>
> Xin Liu has updated the pull request incrementally with one additional commit since the last revision:
> 
>   Fix typo and the building eror on MacOS.

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 line 154:

> 152:     assert(req == 1, "AsyncLogWriter::flush() is NOT MT-safe!");
> 153:     // LogFileOutput::write_block() has called fflush().
> 154:     // stderr does not cache.

cache? Do you mean "buffer"?

src/hotspot/share/logging/logAsyncWriter.cpp line 155:

> 153:     // LogFileOutput::write_block() has called fflush().
> 154:     // stderr does not cache.
> 155:     fflush(stdout);

if `LogFileOutput::write_block() has called fflush()` why are we calling it here?

src/hotspot/share/logging/logAsyncWriter.hpp line 31:

> 29: #include "memory/resourceArea.hpp"
> 30: #include "runtime/nonJavaThread.hpp"
> 31: #include "runtime/semaphore.hpp"

Seems unneeded by the other changes in this file.

test/hotspot/jtreg/runtime/logging/BlockedLoggingTest.java line 58:

> 56:             // The size of pipe buffer is indeterminate. It is presumably 64k on many Linux distros.
> 57:             // We just churn many gc-related logs in ChurnThread.Duration seconds.
> 58:             for(int i = 0; i < ThreadNum; ++i) {

Style nit: need space after 'for'

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

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