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

[Xin Liu]

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

>> `LogAsyncFlusher::enqueue` needs Thread::current() to use _lock. 
>> 
>> void Mutex::lock_without_safepoint_check() {
>>   lock_without_safepoint_check(Thread::current());
>> }
>> 
>> 
>> This check is for a very rare corner case.  This can be trigger using the following cmdline.
>> `
>> java -Xlog:'thread+smr=debug:file=/tmp/t.log' -Xlog:async -version
>> `
>> the root cause is the following code in thread
>> 
>> 
>> void ThreadsSMRSupport::smr_delete(JavaThread *thread) {
>>   elapsedTimer timer;
>>   if (EnableThreadSMRStatistics) {
>>     timer.start();
>>   }
>> 
>>   wait_until_not_protected(thread);
>> 
>>   delete thread; // Thread::current() will trigger assert(current != __null) failed: Thread::current() called on detached thread after ~Thread()
>>   if (EnableThreadSMRStatistics) {
>>     timer.stop();
>>     uint millis = (uint)timer.milliseconds();
>>     ThreadsSMRSupport::inc_deleted_thread_cnt();
>>     ThreadsSMRSupport::add_deleted_thread_times(millis);
>>     ThreadsSMRSupport::update_deleted_thread_time_max(millis);
>>   }
>>   // logsite will crash  in async mode because we can't use Thread::current() here. 
>>   log_debug(thread, smr)("tid=" UINTX_FORMAT ": ThreadsSMRSupport::smr_delete: thread=" INTPTR_FORMAT " is deleted.", os::current_thread_id(), p2i(thread));
>> }
>
> Sigh. I get it. Another example that a good logging system should be independent from the infrastructure of the surrounding system. Any chance this patch could use raw locking primitives, pthread_mutex resp. CreateMutex, without having to rewrite everything? 
> 
> Ironically I though async logging would reduce the number of log call sites where the conditions for logging are not met, by moving most of the stack out of the caller into a separate thread. But the Thread::current condition is a new limitation then compared to sync logging.
> 
> If you don't want to change the Mutex:
> 
> So you have some rare log sites which won't allow you to use asynchronous logging since you cannot use locks, and you solve this by returning NULL, which then falls back to synchronous logging? What happens if you mix synchronous and asynchronous logging like this? Does this work?
> 
> From a code point of view your reasoning is very difficult to deduce. Can you please change this: remove the THread::current condition from the singleton getter, and add an explicit check for Thread::current at its caller site. In async mode either just omit printing any output needing Thread::current, or relegate to synchronous printing. And add a good comment there.

Thank you for reviewing. you raise the exact problem which keep me from sleeping...

> From a code point of view your reasoning is very difficult to deduce. Can you please change this: remove the THread::current condition from the singleton getter, and add an explicit check for Thread::current at its caller site. In async mode either just omit printing any output needing Thread::current, or relegate to synchronous printing. And add a good comment there.

That's exactly the current approach. It works but async logging and synchronous logging may overlap in some rare windows such as my example of `smr_delete`. 


LogAsyncFlusher* LogAsyncFlusher::instance() {
  // thread may has been detached, then Thread::current() used by Mutex is inavailable.
  // eg. ThreadsSMRSupport::smr_delete() uses log_debug() after delete thread.
  if (Thread::current_or_null() != nullptr) {
    return _instance;
  } else {
    return nullptr;
  }
}


One drawback is that I have to give up the  FileLocker optimization for the entire interval async logging(99.99% time)
for those "rare" windows :( Once I remove FileLocker for FILE*, it may get stuck when two logging writers overlap!

I am evaluating different approaches.  eg. the 2-synchronization-points design or even replace Mutex with a semaphore-based lock like [ConfigurationLock](https://github.com/openjdk/jdk/blob/master/src/hotspot/share/logging/logConfiguration.cpp#L55)

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

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