RFR: 8267517: async logging for stdout and stderr

[David Holmes]

On Wed, 27 Oct 2021 08:22:12 GMT, Xin Liu <xliu at openjdk.org> wrote:

> This patch refactors LogFileStreamOutput so stdout/stderr can support support -Xlog:async.
> LogFileStreamOutput::flush() is virtual. 
> 
> With  `-Xlog:all=trace:stdout`, the helloworld in Java outputs 16520 log entries to stdout.  We are see that the wall time reduces from  86.977ms to 72.436ms, or the throughput increases 20% 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):
> 
>             112.59 msec task-clock                #    1.554 CPUs utilized            ( +-  0.15% )
>              1,517      context-switches          #    0.013 M/sec                    ( +-  0.61% )
>                  1      cpu-migrations            #    0.010 K/sec                    ( +-  4.80% )
>              4,014      page-faults               #    0.036 M/sec                    ( +-  0.01% )
> ...
>           0.072436 +- 0.000135 seconds time elapsed  ( +-  0.19% )
> 
>  Performance counter stats for 'java -Xlog:all=trace:stdout  HelloWorld' (300 runs):
> 
>              90.73 msec task-clock                #    1.043 CPUs utilized            ( +-  0.11% )
>                318      context-switches          #    0.004 M/sec                    ( +-  0.32% )
>                  1      cpu-migrations            #    0.009 K/sec                    ( +-  4.80% )
>              4,010      page-faults               #    0.044 M/sec                    ( +-  0.00% )
> ...
>          0.0869777 +- 0.0000979 seconds time elapsed  ( +-  0.11% )
> 
> 
> In this patch, we also fold two locks(RotationLocker and FileLock) of LogFileOutput into one. FileLocker now can protect _stream from multiplexing and log rotation.  The other change is that AsyncLog writing doesn't require any lock protection because it's single-threaded. 
> 
> Add a new jtreg to cover a scenario that the blocked stdout doesn't freeze the JVM application.

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

> 67:   class FileLocker : public StackObj {
> 68:     Semaphore& _sem;
> 69:     debug_only(intx& _locking_thread_id;)

This seems unused even in debug builds- it is set but never inspected. ??

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

> 49: 
> 50:     // process 0 emits unified log to stdout. We must ensure that nobody except for UL emits to stdout.
> 51:     // we expect to demonstrate that process 0 with -Xlog:async can still terminate even though its

Nit: if your comments are sentences then they should start with capital letters. This applies all through this code.

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

> 58:             Thread[] threads = new Thread[ThreadNum];
> 59:             // the size of pipe buffer is hard to tell. just churn many gc-related logs
> 60:             // in ChurnThread.Duration sececonds. it's presumably 64k on Linux.

typo: sececonds

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

> 138:                     while (true) {
> 139:                         Thread.yield();
> 140:                     }

Don't do a busy wait - use a sleep() or a wait().

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

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