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

[Xin Liu]

On Fri, 7 May 2021 10:02:45 GMT, Thomas Stuefe <stuefe at openjdk.org> wrote:

> About synchronization: I don't understand the reasoning behind having a periodic flush. Would an implementation which just flushes if output is available not be less complex and actually better? Why make the flusher thread wake up twice a second if there is nothing to do? OTOH why wait 500ms if there is actually output to be printed?

>From my observation, the character of logging events is high-frequent but low cost. Using HotSpot Monitor(the combination of pthead_mutex_t and pthread_cond_t) for an individual logging event is expensive.  The cost of waking up AsyncLog thread and lock/unlock data structure would easily shadow IO jobs(fprintf), which usually are cached in libc.

My strategy is to do IO jobs in batch and amortize the cost of synchronizations.  In my design, m.wait() in the following code snippet wakes up mainly due to the load of buffer is over 3/4.   

  while (_state == ThreadState::Running) {
    {
      MonitorLocker m(&_lock, Mutex::_no_safepoint_check_flag);
      m.wait(500 /* ms, timeout*/);
    }
    flush();
  }


500ms here,  which was the global option `LogAsyncInterval` , serves as a **stall protector**.  If Hotspot stalls for whatever reasons, AsyncLog thread still can flush messages after timeout.  I think it's useful for develops who may rely on the log files to figure out what happened inside of the hanging hotspot.  Without timeout parameter, AsyncLog Thread may leave messages in the buffer and never get a change to flush them if all threads stall. 

>  IIUC this wait introduces an artificial 500ms delay on VM shutdown, since you have this handshake with the flusher thread which does an unconditional wait.
That's not true. In `LogAsyncFlusher::terminate`, I notify AsyncLog thread.  `m.wait(500 /* ms, timeout*/);` should return immediately once kernel wakes it up. 


    {
      MonitorLocker ml(&self->_lock, Mutex::_no_safepoint_check_flag);
      self->_state = ThreadState::Terminating;
      ml.notify();
    }


Actually, I admit that the termination protocol is overkill. I learned from WatchThreads. 
The bottom line is to make sure no message left behind.  This has been enforced by LogConfiguration::disable_outputs(). 
I added code change in disable_outputs() after terminate() to support jcmd's "VM.log disable". I will see if it's safe to remove `LogAsyncFlusher::terminate() `.

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

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