RFR: 8323807: Async UL: Add a stalling mode to async UL [v19]

[David Holmes]

On Mon, 24 Feb 2025 13:27:10 GMT, Johan Sjölen <jsjolen at openjdk.org> wrote:

>> Hi,
>> 
>> In January of this year I took a stab at implementing a stalling mode for UL, see link: https://github.com/openjdk/jdk/pull/17757 . I also talked about this feature in the mailing lists and seemed to receive positive feedback. With that PR, I also implemented a circular buffer. This PR didn't go through because 1. The stalling mode was broken 2. The complexity was a bit too large imho.
>> 
>> This PR does a much smaller change by only focusing on implementing the actual stalling.
>> 
>> The addition in terms of command line changes are the same as before, you can now specify the mode of your async logging:
>> 
>> 
>> $ java -Xlog:async:drop # Dropping mode, same as today
>> $ java -Xlog:async:stall # Stalling mode!
>> $ java -Xlog:async # Dropping mode by default still
>> 
>> 
>> The change in protocol is quite simple. If a producer thread `P` cannot fit a message into the buffer, it `malloc`s a message and exposes it via a shared pointer. It blocks all other producer threads from writing into the buffer. At the same time, the consumer thread (`AsyncLogWriter`) will perform all writing. When the consumer thread has emptied the write buffer, it writes the stalled message, notifies `P` and releases all locks. `P` then let's all other producer threads continue.
>> 
>> We do this by having two locks: `Outer` and `Inner`. In our example above, `P` prevents any other producers from progressing by holding the outer lock, but allows the consumer thread to progress by releasing the inner lock.
>> 
>> In pseudo-code we have something like this in the stalling case.
>> 
>> 
>> void produce() {
>>   OuterLock olock;
>>   InnerLock ilock;
>>   bool out_of_memory = attempt_produce(shared_buffer);
>>   if (out_of_memory) {
>>     pmsg = new Message();
>>     shared_message = pmsg;
>>     while (shared_message != nullptr) ilock.wait();
>>     free(pmsg);
>>   }
>> }
>> 
>> void consume() {
>>   InnerLock ilock;
>>   consume(shared_buffer);
>>   if (shared_message != nullptr) {
>>     consume(shared_message);
>>     ilock.notify();
>>   }
>> }
>> 
>> 
>> *Note!* It is very important that the consumer prints all output found in the buffer before printing the stalled message. This is because logging is output in Program Order. In other words: `print(m0); print(m1);` means that `m0` must appear before `m1` in the log file.
>> 
>> *Note!* Yes, we do force *all* threads to stall before the original stalled message has been printed. This isn't optimal, but I still have hope that we can switch to a faster circu...
>
> Johan Sjölen has updated the pull request incrementally with one additional commit since the last revision:
> 
>   Self-review

Looks good. I think it makes sense. Only a couple of minor comments, plus we need the manpage updated.

src/hotspot/share/logging/logAsyncWriter.cpp line 133:

> 131:       while (_stalled_message != nullptr) {
> 132:         clocker.wait();
> 133:       }

I was worried about lost wakeups here until I again remembered that we still hold the producer lock while we wait so the only thread that can interact with the clocker is the async logging thread. Perhaps a comment before the while loop:

// Note we still hold the producer lock so cannot race against other threads trying to log a message

src/hotspot/share/logging/logAsyncWriter.cpp line 205:

> 203: 
> 204:   // If we get here we know the AsyncLogWriter is initialized.
> 205:   ProducerLocker locker;

Suggestion:

  ProducerLocker plocker;

src/hotspot/share/logging/logConfiguration.cpp line 639:

> 637: 
> 638:   out->print_cr("Asynchronous logging (off by default):");
> 639:   out->print_cr(" -Xlog:async[:[mode]]");

This reminded me we need an update to the Java manpage/command-reference as well.

src/hotspot/share/runtime/globals.hpp line 1874:

> 1872:           "Memory budget (in bytes) for the buffer of Asynchronous "        \
> 1873:           "Logging (-Xlog:async).")                                         \
> 1874:           range(DEBUG_ONLY(96) NOT_DEBUG(100*K), 50*M)                      \

Why 96 when the test uses 192? I guess it could be anything.

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

PR Review: https://git.openjdk.org/jdk/pull/22770#pullrequestreview-2640175394
PR Review Comment: https://git.openjdk.org/jdk/pull/22770#discussion_r1969304525
PR Review Comment: https://git.openjdk.org/jdk/pull/22770#discussion_r1969306651
PR Review Comment: https://git.openjdk.org/jdk/pull/22770#discussion_r1969313824
PR Review Comment: https://git.openjdk.org/jdk/pull/22770#discussion_r1969322750