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

[Xin Liu]

On Thu, 13 May 2021 06:55:59 GMT, Thomas Stuefe <stuefe at openjdk.org> wrote:

>> Xin Liu has updated the pull request incrementally with one additional commit since the last revision:
>> 
>>   Fix build on Windows.
>>   
>>   It seems that headers on Windows define WAIT_TIMEOUT somewhere. rename it.
>
>> > About synchronization: I don't understand the reasoning behind having a periodic flush. Would an implementation which just flushes if output is available not be less complex and actually better? Why make the flusher thread wake up twice a second if there is nothing to do? OTOH why wait 500ms if there is actually output to be printed?
>> 
>> From my observation, the character of logging events is high-frequent but low cost. Using HotSpot Monitor(the combination of pthead_mutex_t and pthread_cond_t) for an individual logging event is expensive. The cost of waking up AsyncLog thread and lock/unlock data structure would easily shadow IO jobs(fprintf), which usually are cached in libc.
>> 
>> My strategy is to do IO jobs in batch and amortize the cost of synchronizations. In my design, m.wait() in the following code snippet wakes up mainly due to the load of buffer is over 3/4.
>> 
>> ```c++
>>   while (_state == ThreadState::Running) {
>>     {
>>       MonitorLocker m(&_lock, Mutex::_no_safepoint_check_flag);
>>       m.wait(500 /* ms, timeout*/);
>>     }
>>     flush();
>>   }
>> ```
>> 
>> 500ms here, which was the global option `LogAsyncInterval` , serves as a **stall protector**. If Hotspot stalls for whatever reasons, AsyncLog thread still can flush messages after timeout. I think it's useful for develops who may rely on the log files to figure out what happened inside of the hanging hotspot. Without timeout parameter, AsyncLog Thread may leave messages in the buffer and never get a change to flush them if all threads stall.
> 
> Okay, I understand.

hi, @tstuefe & @dholmes-ora , 

I replace Monitor with Semaphore.  Previously, the monitor _lock served in twofold meaning. 
1. mutex to protect key data structure. 
2. condition_variable to signal AsyncLog Thread to wake up. 

In this revision, I replace '_lock' with two separated semaphores.  Semaphore is primitive and don't reply on Hotspot Runtime, so I can remove some workarounds of Hotspot mutex. 

Not only it can simplify implementation, it is also faster than Monitor.  I guess it's still because it's more primitive than pthread.  eg. _sem->notify() just increases an integer in atomic and signal. Monitor needs unlock, signal, lock. 

Baseline is all=trace by default. 
`perf stat -r 300  ./build/linux-x86_64-server-release/images/jdk/bin/java  -Xlog:'all=trace:file=hotspot-gold.log:uptime,tid,l,tg:filecount=0' --version > /dev/null`

Monitor and Semaphore  are both synchronous logging with different implementation. 
`perf stat -r 300  ./build/linux-x86_64-server-release/images/jdk/bin/java -Xlog:async -Xlog:'all=trace:file=hotspot-async.log:uptime,tid,l,tg:filecount=0' --version > /dev/null`



Baseline:           0.102001 +- 0.000162 seconds time elapsed  ( +-  0.16% )
Monitor:            0.078309 +- 0.000161 seconds time elapsed  ( +-  0.21% )
Sempahore:          0.068590 +- 0.000137 seconds time elapsed  ( +-  0.20% )

 
I compared the outputs files. The semaphore-based revision also output all logs like synchronous one.

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

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