RFR: 8229517: Support for optional asynchronous/buffered logging [v9]

[Xin Liu]

On Fri, 23 Apr 2021 23:29:48 GMT, Xin Liu <xliu at openjdk.org> wrote:

>> This patch provides a buffer to store asynchrounous messages and flush them to
>> underlying files periodically.
>
> Xin Liu has updated the pull request incrementally with two additional commits since the last revision:
> 
>  - Fix bugs/style/typo based on reviewers' feedbacks.
>  - Accurate Decorations for AsyncLogging.
>    
>    A lightweight LogDecorationRef is created to keep LogDecorations at
>    logging site. It uses refcnt to keep track multiple usage and
>    automatically clean up. If no decorator is in use, no LogDecorationRef
>    is created.

### Integration Test
We understand that a feature is useless or even harmful if it's buggy.  In addition to the gtest in this PR,  we also set up an integration tests to verify it. 

1. The full-brunt logging in an entire jvm lifecycle
The following command dump **all** logs in trace verbosity in async logging mode. 
There are 13k messages and no one is dropped from [0.004s] to [0.087s]

> time ./build/linux-x86_64-server-release/images/jdk/bin/java -Xlog:'all=trace:file=hotspot.log:uptime,tid,l,tg:filecount=0,async=true' --version


$wc -l hotspot.log
13386 hotspot.log
$grep "messages dropped" hotspot.log -n


2. Gclog test
We directly use the testcase in linkedin whitepaper[1]. [Test.java](https://github.com/navyxliu/JavaGCworkload/blob/master/Test.java) launches N threads and each one churns up java heap by allocating String objects.  We use the default gc(G1GC) of jdk17. 

The following command runs infinite time with 10g heap. It launches 4 threads and dump gc logs in trace verbosity. 
>  java -Xmx10g -Xms10g -Xlog:gc=trace:file=gc.log::async=true Test -1 4

We have been running it over a week and no message is drop. 

3. Gclog test with dropping messages 
The following command still uses Test.java introduced in prior test, it dumps all logset as long as it contains `gc`. 
IIUC, it simulates `-XX:+PrintGCDetails`.  It still starts 4 threads and the test ends in 180s. 

> java -Xmx10g -Xms10g -Xlog:'gc*=trace:file=gc-star.log::async=true' Test 180 4

Log rotation works correctly. Give the verbose log and intense gc activities, we do observe some logs dropped. 

In gc-star.log.0, whose timestamp is from [11445.736s] to [11449.168s], it totally drops 4717 messages out of 130224, or 3.6% messages are ditched. 

No message is dropped after we enlarge the buffer to -XX:AsyncLogBufferSize=102400.
In debug build, hotspot will dump dropping messages to tty console with `-XX:+Verbose`.

4. Gclog test with dynamical reconfiguration
While running Test 3, we can dynamically reconfigure logs using jcmd VM.log

We use a [script](https://github.com/navyxliu/JavaGCworkload/blob/master/jcmd_test.sh) to disable all outputs and re-create a file-based output in async mode.  We periodic ran the script in a day and no problem has been identified. 

5. Gclog test with NMT
the following command is same as 3 plus `-XX:NativeMemoryTracking=summary`
>  java -Xmx10g -Xms10g -Xlog:'gc*=trace:file=gc-star.log::async=true' -XX:NativeMemoryTracking=summary Test -1 4

We use a [script](https://github.com/navyxliu/JavaGCworkload/blob/master/monitor_nmt.sh) to monitor NMT summary. All offheap allocation are marked "mtLogging".  We don't observe memory leak on Logging category in long-haul running. 

We also ran asynchorous logging in Minecraft 1.16.5 on both Linux and MacOS. No problem has been captured yet. 

[1] https://engineering.linkedin.com/blog/2016/02/eliminating-large-jvm-gc-pauses-caused-by-background-io-traffic

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

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