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

[Thomas Stuefe]

On Mon, 10 May 2021 23:10:00 GMT, Xin Liu <xliu at openjdk.org> wrote:

>> src/hotspot/share/logging/logAsyncFlusher.cpp line 206:
>> 
>>> 204: 
>>> 205: LogAsyncFlusher* LogAsyncFlusher::instance() {
>>> 206:   if (Thread::current_or_null() != nullptr) {
>> 
>> I don't understand why this depends on the existence of a current thread? Ideally we should be able to log just fine in corner cases, e.g. when thread is detached or if we have an error (during signal handling e..g.)
>
> `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.

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

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