RFR: 8267926: AsyncLogGtest.java fails on assert with: decorator was not part of the decorator set specified at creation. [v3]

[Liu, Xin]

Hi, David,

No, logoutput won't show all decorators. It just materialize
logDecorations for All. This only happens when lost logs happen.

It's very tricky here, but it's essential to reason how the lockless
synchronization works for LogDecorations in
LogConfiguration::configure_output.

A LogDecorators a SET of decorators in bitmask. A LogDecorations
instance represents a materialized LogDecorators.

There are 2 different LogDecorations instances coexist. 
Set 1: LogOutput::_decorators, which is used to select which decorations
are output. LogFileStreamOutput::write_decorations()
Set 2: LogTagSet::_decorators, which is used to materialize LogDecorations.


In any give time, set 1 is a 'subset' of set 2. This guarantees that
write_decorations() always outputs defined decorations.

Why configure_output() is MT-safe if users allow to change decorations
dynamically? Let's say the new decorations user provided is set N.

There are 4 steps in configure_output().
1) ts->update_decorators(decorators);   // set 2 = union(set 2, set N)
2) ts->set_output_level(output, level); // wait_until_no_readers()
After it, ts->log() must see the new set 2 in synchronous logging.
Some async log message with old decorations may be in the buffer. This
is the Hazard #1.
3) output->set_decorators(decorators);  // set 1 = set N in atomic.
4) ts->update_decorators(LogDecorators::None); // set 2 = intersect(set
2, set N), essentially shrink the set 2 to set N.

This mechanism is intrigue. That's why I try to comment it out. I also
discover a race condition which only happens in preemptive context
switch. Please help me to review the change in LogTagSet::log().

To make current mechanism support async logging, I insert a
AsyncLogWriter::flush() before step 3).  Yes, after flush() returns,
logsites can still enqueues messages in parallel, but they must seen new
set 2! It's not hazard.


thanks,
--lx



On 5/31/21 6:27 PM, David Holmes wrote:
> CAUTION: This email originated from outside of the organization. Do not click links or open attachments unless you can confirm the sender and know the content is safe.
> 
> 
> 
> On 1/06/2021 10:26 am, Xin Liu wrote:
>> On Mon, 31 May 2021 22:14:46 GMT, David Holmes <dholmes at openjdk.org> wrote:
>>
>>>> Xin Liu has updated the pull request incrementally with one additional commit since the last revision:
>>>>
>>>>    Increase reader's counter before creating LogDecoration.
>>>
>>> src/hotspot/share/logging/logAsyncWriter.cpp line 105:
>>>
>>>> 103:
>>>> 104:     if (*counter > 0) {
>>>> 105:       LogDecorations decorations(LogLevel::Warning, none::tagset(), LogDecorators::All);
>>>
>>> This looks odd to use LogDecorators::All - what exactly will that produce?
>>
>> This is the out-of-band message, it just shows that "xyz messages dropped due to async logging."
>>
>> Unlike normal log messages, this ad-hoc message is enqueued when buffer is flushing. The synchronization I described in `LogConfiguration::configure_output` only protects enqueuing log messages.  This message is not under protection.Without LogDecorators::All, it will fail 'gtest:LogConfigurationTest.reconfigure_decorators_MT*' in async log mode.
> 
> I understand the need to not use the true decorators, but using All
> sounds like it will produce a log line with an excessive number of
> decorators applied:
> 
> Available log decorators:
>   time (t), utctime (utc), uptime (u), timemillis (tm), uptimemillis
> (um), timenanos (tn), uptimenanos (un), hostname (hn), pid (p), tid
> (ti), level (l), tags (tg)
> 
> will all of those appear on this log line?
> 
> Thanks,
> David
> 
>> -------------
>>
>> PR: https://git.openjdk.java.net/jdk/pull/4257
>>