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

[Thomas Stuefe]

On Mon, 26 Apr 2021 20:45:23 GMT, Xin Liu <xliu at openjdk.org> wrote:

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

Hi @navyxliu ,

sorry for the quiet time, but good work on the testing!

Had a read through your patch. One thing I dislike is the optimization you did for LogDecorations. I see what you did there, but this makes the coding a lot more unreadable while being not a perfect solution.

The fact that LogDecorations are implemented with a fixed sized 256 char buffer is not perfect today even outside the context of async logging. It may still be too small (interestingly, one thing I noticed is that UL does not have standard decorators like "file" and "line" which may exhaust that buffer). While still taking much too much memory on average, especially in a context like yours where you want to store resolved decorations.

I propose to tackle that problem separately though, independently from your patch. One possible solution we have done in the past with similar problems is to delay the string resolution and store the raw data for printing in some kind of vector (similar to a va_arg pointer). But I'd leave this for another day, your patch is complex as it is.

For now I propose one of two things:

- Either live with the full Decorations and pay the 256char-per-message price
- Or, just resolve the decorations in the async logger thread, for now clearly document it as "works as designed, decorators (e.g. tid) may be off if async logging is engaged")

and in both cases wait for the follow-up RFE to introduce a better way to persist decorations.

What do you think?

Cheers, Thomas

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

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