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

[David Holmes]

On 24/05/2021 2:29 pm, Xin Liu wrote:
> Hi, Thomas
> 
> Thanks for the advice. I agree.  OpenJDK have invested so much on those unified logging tests. It's wasteful if I skip them in async mode. I manage to resolve the race conditions.
> 
> To support it, I strengthen "AsyncLogWriter::flush()".  Now it not only flushes pending messages out of buffer, it guarantees all logs messages are seen by external.  one lock  _io_sem is introduced to consolidate that.

Sorry I didn't see this before sending my other mail about the role of 
the io_sem.

I don't think this semaphore does what you want/need and it's use during 
a VM abort is likely to be very problematic as we may cause the aborting 
thread to wait for the log writing thread, which may not be above to run 
due to the fact that we are aborting.

IIUC what you are trying to deal with is a case where the log writing 
thread has emptied the buffer and as is busy writing that out, and other 
log messages then get enqueued, but then we abort/terminate and we call 
flush() in the aborting/terminating thread. So now we would have two 
threads trying to write to the log outputs and these different logging 
messages could get interleaved in a confusing way; plus as the aborting 
thread is likely to finish first then it will complete the abort and the 
log writer won't get to finish. But I see two problems here:

First, as noted, making the aborting thread wait() could be very 
problematic for the process of aborting. Perhaps we can do this for a 
normal termination, but not I think for the abort case.

Second, there is still a race as to which thread will get the io_sem 
first and so the output could still be presented in the wrong order. I 
think to solve that you would need to acquire the _io_sem first and hold 
it for the duration of the write() operation. I think this could also be 
a regular Mutex rather than a Semaphore.

> By inserting AsyncLogWriter::flush() in some places of unified logging tests, I can pass all gtests in async mode. I verified it in different builds.  flush() is no-op if async log is not established.
> 
> Amazingly, I discovered a very subtle bug also. The following call can also turn off all log outputs but it will bypass `LogConfiguration::disable_outputs()`. Fixed.
> 
> 
> LogConfiguration::parse_log_arguments(filename, "all=off", "", "", &stream);
> 
> 
> 
> @dholmes-ora ,
> Could you verify that with TEST_OPTS='VM_OPTIONS=-Xlog:async'?

I'm submitting it to our test system as I did before for tier 1-3 
testing. I'll see if I can also explicitly enable async logging. Though 
I think I'll hold off until the io_sem situation is resolved.

Thanks,
David

> I also verified on Windows 10(WSL1). It works as expected.
> 
> -------------
> 
> PR: https://git.openjdk.java.net/jdk/pull/3135
>