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

Xin Liu xliu at openjdk.java.net
Thu Dec 16 06:50:41 UTC 2021


> 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.

Xin Liu has updated the pull request with a new target base due to a merge or a rebase. The incremental webrev excludes the unrelated changes brought in by the merge/rebase. The pull request contains 13 additional commits since the last revision:

 - Refactor code. Remove JDK-8275083.
 - Merge branch 'master' into JDK-8267517
 - Remove the unused semaphore in LogFileOutput.
 - Merge branch 'master' into JDK-8267517
 - Fixed the regression test.
 - Fix the deadlock issue on single core.
   
   taskset 0x1 make test TEST='runtime/logging/BlockedLoggingTest.java'
 - Update the jtreg test.
 - Merge branch 'master' into JDK-8267517
 - Add a jtreg test to demonstrate -Xlog:async can prevent JVM from blocking
 - _locking_thread_id should be a member data of LogFileStreamOutput.
   
   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
 - ... and 3 more: https://git.openjdk.java.net/jdk/compare/d1013795...119a51dc

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

Changes:
  - all: https://git.openjdk.java.net/jdk/pull/6132/files
  - new: https://git.openjdk.java.net/jdk/pull/6132/files/45e15916..119a51dc

Webrevs:
 - full: https://webrevs.openjdk.java.net/?repo=jdk&pr=6132&range=01
 - incr: https://webrevs.openjdk.java.net/?repo=jdk&pr=6132&range=00-01

  Stats: 23344 lines in 667 files changed: 17674 ins; 2610 del; 3060 mod
  Patch: https://git.openjdk.java.net/jdk/pull/6132.diff
  Fetch: git fetch https://git.openjdk.java.net/jdk pull/6132/head:pull/6132

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


More information about the hotspot-runtime-dev mailing list