RFR: 8229517: Support for optional asynchronous/buffered logging

[Robbin Ehn]

On Thu, 25 Mar 2021 20:19:03 GMT, Thomas Stuefe <stuefe at openjdk.org> wrote:

>> Hi Xin,
>> 
>> I skimmed over the patch, but have a number of high level questions - things which have not been clear from your description.
>> 
>> - Who does the writing, and who is affected when the writing stalls?
>> - Do you then block or throw output away? 
>> 	- If the former, how do you mitigate the ripple effect? 
>> 	- If the latter, how does the reader of the log file know that something is missing?
>> - How often do you flush? How do you prevent missing output in the log file in case of crashes?
>> - Can this really the full brunt of logging (-Xlog:*=trace) over many threads?
>> - Does this work with multiple target and multiple IO files?
>> - Does it cost anything if logging is off or not async?
>> 
>> Update: Okay, I see you use PeriodicTask and the WatcherThread. Is this really enough? I would be concerned that it either runs too rarely to be able to swallow all output or that it runs that often that it monopolizes the WatcherThread. 
>> 
>> I actually expected a separate Thread - or multiple, one per output - for this, waking up when there is something to write. That would also be more efficient than constant periodic polling.
>> 
>> - How is the performance impact when we have lots of concurrent writes from many threads? I see that you use a Mutex to synchronize the logging threads with the flush service. Before, these threads would have done concurrent IO and that would be handled by the libc, potentially without locking.
>> 
>> ---
>> 
>> I think this feature could be useful. I am a bit concerned with the increased complexity this brings. UL is already a very (I think unnecessarily) complex codebase. Maybe we should try to reduce its complexity first before adding new features to it. This is just my opinion, lets see what others think.
>> 
>> Cheers, Thomas
>
> p.s. I like the integration into UL via a target modification btw. That feels very organic.

Hi,

This is flushed by the watcher thread (non-JavaThread).
Flushing can thus happen during a safepoint and one or more safepoints may have passed between the actual logging and the flushing.
If the VM thread logs it can be delayed while watcher thread does "pop_all()" it seems like.
I suppose pop_all can take a while if you have a couple of thousands of logs messages? 

We can also change log-configuration during run-time, e.g. turn on/off logs via jcmd.
Wouldn't it be more natural to flush the async logs-lines before we update the log configuration? (e.g. if you turn off a log via jcmd, we flush the async buffer before)

Thanks

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

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