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

[Volker Simonis]

On Tue, 30 Mar 2021 13:33:27 GMT, Thomas Stuefe <stuefe at openjdk.org> wrote:

>> Hi Xin, regrading the VM thread blocking on logs.
>> 
>> If you instead use two arrays, one active and one for flushing, you can swap them with atomic stores from the flushing thread.
>> And use GlobalCounter::write_synchronize(); to make sure no writer is still using the swapped out array for logging.
>> 
>> The logging thread would use GlobalCounter::critical_section_begin(), atomic inc position to get the spot in the array for the log, store the log and then GlobalCounter::critical_section_end().
>> 
>> That way you will never block a logging thread with the flushing and run enqueues in parallel.
>> 
>> If you want really want smooth logging you could also remove the strdup, since it may cause a syscall to "break in" more memory.
>> To solve that you could use the arrays as memory instead, and do bump the pointer allocation with an atomic increment to size needed instead of position.
>> 
>> I tested a bit locally generally I don't think there is an issue with blocking the VM thread on flushing.
>> So I'm not really that concern about this, but it's always nice to have an algorithm which is constant time instead. (Neither CS begin()/end() or atomic inc can fail or loop on x86)
>
>> Hi Xin, regrading the VM thread blocking on logs.
>> 
>> If you instead use two arrays, one active and one for flushing, you can swap them with atomic stores from the flushing thread.
>> And use GlobalCounter::write_synchronize(); to make sure no writer is still using the swapped out array for logging.
>> 
>> The logging thread would use GlobalCounter::critical_section_begin(), atomic inc position to get the spot in the array for the log, store the log and then GlobalCounter::critical_section_end().
>> 
>> That way you will never block a logging thread with the flushing and run enqueues in parallel.
>> 
>> If you want really want smooth logging you could also remove the strdup, since it may cause a syscall to "break in" more memory.
>> To solve that you could use the arrays as memory instead, and do bump the pointer allocation with an atomic increment to size needed instead of position.
> 
> +1. This is what I meant with my strdup() critique. Does the Deque does not also allocate memory for its entries dynamically? If yes, we'd have at least two allocations per log, which I would avoid. I'd really prefer a simple stupid fixed-sized array here (or two, the double buffering Robbin proposed is a nice touch).
> 
> As I wrote before, this would make UL also more robust in case we ever want to log low level VM stuff without running into circularities. Ideally, UL should never have relied on VM infrastructure to begin with. That is a design flaw IMHO. UL calling - while logging - into os::malloc makes me deeply uneasy.
> 
>> 
>> I tested a bit locally generally I don't think there is an issue with blocking the VM thread on flushing.
>> So I'm not really that concern about this, but it's always nice to have an algorithm which is constant time instead. (Neither CS begin()/end() or atomic inc can fail or loop on x86)

Thanks everybody for your valuable comments. As requested in the PR, I've just started a [new discussion thread on hotspot-dev](https://mail.openjdk.java.net/pipermail/hotspot-dev/2021-March/050491.html) (with all current reviewers on CC).

Before diving into more discussions about implementation details, I'd first like to:

1. Reach general consensus that asynchronous logging is a useful feature that's worth while adding to HotSpot.
2. Agree on the desired properties of asynchronous logging. I've tried to collect a basic set of desired properties in the "Proposed solution" section of that mail.
3. Discuss various implementation details and finally prepare new pull requests based on the that discussions.

Your comments, suggestions and contributions are highly appreciated.
Thank you and best regards,
Volker

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

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