RFR: 8229517: Support for optional asynchronous/buffered logging

[Thomas Stuefe]

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

>>> I think this PR is very useful for us!
>>> 
>>> > May we know more about LogMessageBuffer.hpp/cpp? We haven’t found a real use of it. That’s why we are hesitating to support LogFileOutput::write(LogMessageBuffer::Iterator msg_iterator). Further, we haven’t supported async_mode for LogStdoutOutput and LogStderrOutput either. It’s not difficult but needs to big code change.
>>> 
>>> `LogMessageBuffer` is used in `LogMessage`. For example, we can see it as following. Frame # 1 is `LogFileOutput::write(LogMessageBuffer::Iterator msg_iterator)`. IMHO we do not need to change LogStdout/errOutput, but it is better to change LogMessageBuffer.
>>> 
>>> ```
>>> #0  LogFileStreamOutput::write (this=this at entry=0x7ffff0002af0, msg_iterator=...)
>>>     at /home/ysuenaga/github-forked/jdk/src/hotspot/share/logging/logDecorators.hpp:108
>>> #1  0x00007ffff6e80e8e in LogFileOutput::write (this=this at entry=0x7ffff0002af0, msg_iterator=...)
>>>     at /home/ysuenaga/github-forked/jdk/src/hotspot/share/logging/logFileOutput.cpp:314
>>> #2  0x00007ffff6e876eb in LogTagSet::log (
>>>     this=this at entry=0x7ffff7d4a640 <LogTagSetMapping<(LogTag::type)16, (LogTag::type)68, (LogTag::type)0, (LogTag::type)0, (LogTag::type)0, (LogTag::type)0>::_tagset>, msg=...) at /home/ysuenaga/github-forked/jdk/src/hotspot/share/logging/logTagSet.cpp:85
>>> #3  0x00007ffff6a194df in LogImpl<(LogTag::type)16, (LogTag::type)68, (LogTag::type)0, (LogTag::type)0, (LogTag::type)0, (LogTag::type)0>::write (
>>>     msg=...) at /home/ysuenaga/github-forked/jdk/src/hotspot/share/logging/logTagSet.hpp:150
>>> #4  LogMessageImpl<(LogTag::type)16, (LogTag::type)68, (LogTag::type)0, (LogTag::type)0, (LogTag::type)0, (LogTag::type)0>::flush (
>>>     this=0x7ffff58675d0) at /home/ysuenaga/github-forked/jdk/src/hotspot/share/logging/logMessage.hpp:79
>>> #5  LogMessageImpl<(LogTag::type)16, (LogTag::type)68, (LogTag::type)0, (LogTag::type)0, (LogTag::type)0, (LogTag::type)0>::~LogMessageImpl (
>>>     this=0x7ffff58675d0, __in_chrg=<optimized out>) at /home/ysuenaga/github-forked/jdk/src/hotspot/share/logging/logMessage.hpp:74
>>> #6  InstanceKlass::print_class_load_logging (this=this at entry=0x800007430, loader_data=loader_data at entry=0x7ffff00f5200,
>>>     module_entry=module_entry at entry=0x0, cfs=cfs at entry=0x0) at /home/ysuenaga/github-forked/jdk/src/hotspot/share/oops/instanceKlass.cpp:3647
>>> ```
>> 
>> hi, @YaSuenag, 
>> 
>> Thank you for providing the stacktrace! I didn't notice <logMessage.hpp> until you point out. Now I understand the rationale and usecases of logMessageBuffer. Let me figure out how to support it. 
>> 
>> IIUC, the most important attribute of `LogMessage` is to guarantee messages are consecutive, or free from interleaving. I will focus on it.
>
> 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.

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

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