Skip to content
This repository has been archived by the owner. It is now read-only.

8269865: Async UL needs to handle ERANGE on exceeding SEM_VALUE_MAX #216

Closed
wants to merge 10 commits into from

Conversation

@navyxliu
Copy link
Contributor

@navyxliu navyxliu commented Jul 6, 2021

This patch solved the sempahore overflow issue with errno ERANGE or EOVERFLOW.
Previously, we have asymmetric p/v operations for semaphore _sem. Each iteration
only decrements _sem 1 but dequeues N messages. If logging threads keep preempting
async logging thread, it may cause the value of _sem accumulates until overflow!

We decide to ditch counting semaphore. os::PlatformMonitor can be used as low-level
combination of Mutex/CondVar. It may work if we simply ignore Semaphore::signal failure
due to value overflow, but we have to pollute Semaphore interface. Also it seems that MacOS
semaphore which is non-posix doesn't fail in this case.


Progress

  • Change must not contain extraneous whitespace
  • Commit message must refer to an issue
  • Change must be properly reviewed

Issue

  • JDK-8269865: Async UL needs to handle ERANGE on exceeding SEM_VALUE_MAX

Reviewers

Reviewing

Using git

Checkout this PR locally:
$ git fetch https://git.openjdk.java.net/jdk17 pull/216/head:pull/216
$ git checkout pull/216

Update a local copy of the PR:
$ git checkout pull/216
$ git pull https://git.openjdk.java.net/jdk17 pull/216/head

Using Skara CLI tools

Checkout this PR locally:
$ git pr checkout 216

View PR using the GUI difftool:
$ git pr show -t 216

Using diff file

Download this PR as a diff file:
https://git.openjdk.java.net/jdk17/pull/216.diff

@bridgekeeper
Copy link

@bridgekeeper bridgekeeper bot commented Jul 6, 2021

👋 Welcome back xliu! A progress list of the required criteria for merging this PR into master will be added to the body of your pull request. There are additional pull request commands available for use with this pull request.

Loading

@openjdk openjdk bot added the rfr label Jul 6, 2021
@openjdk
Copy link

@openjdk openjdk bot commented Jul 6, 2021

@navyxliu The following label will be automatically applied to this pull request:

  • hotspot-runtime

When this pull request is ready to be reviewed, an "RFR" email will be sent to the corresponding mailing list. If you would like to change these labels, use the /label pull request command.

Loading

@mlbridge
Copy link

@mlbridge mlbridge bot commented Jul 6, 2021

Loading

Copy link
Member

@dholmes-ora dholmes-ora left a comment

Hi Xin,

I wasn't expecting to see an attempt to balance the semaphore count on each write, but this seems to be okay.

One simplification suggested below.

Thanks,
David

Loading

write();

int n = write();
for (int i = n - 1; i > 0; --i) {
Copy link
Member

@dholmes-ora dholmes-ora Jul 6, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

while (--n > 0) { // pre-decrement as we already performed the first wait

Loading

@openjdk
Copy link

@openjdk openjdk bot commented Jul 6, 2021

@navyxliu This change now passes all automated pre-integration checks.

ℹ️ This project also has non-automated pre-integration requirements. Please see the file CONTRIBUTING.md for details.

After integration, the commit message for the final commit will be:

8269865: Async UL needs to handle ERANGE on exceeding SEM_VALUE_MAX

Reviewed-by: dholmes, pchilanomate

You can use pull request commands such as /summary, /contributor and /issue to adjust it as needed.

At the time when this comment was updated there had been 45 new commits pushed to the master branch:

  • 0f54707: 8270056: Generated lambda class can not access protected static method of target class
  • 8583aab: 8270025: DynamicCallSiteDesc::withArgs doesn't throw NPE
  • d32e42c: 8270184: [TESTBUG] Add coverage for jvmci ResolvedJavaType.toJavaName() for lambdas
  • b2416b6: 8269281: java/foreign/Test{Down,Up}call.java time out
  • bd95c0c: 8269635: Stress test SEGV while emitting OldObjectSample
  • 00ef65f: 8269525: Deadlock during Volano with JFR
  • e631add: 8259848: Interim javadoc build does not support platform links
  • 040c02b: 8269795: C2: Out of bounds array load floats above its range check in loop peeling resulting in SEGV
  • 0f32982: 8270203: Missing build dependency between jdk.jfr-gendata and buildtools-hotspot
  • 4fc3180: 8266345: (fs) Custom DefaultFileSystemProvider security related loops
  • ... and 35 more: https://git.openjdk.java.net/jdk17/compare/4ad8b04421f3142c396ade26f36334da7a915b5b...master

As there are no conflicts, your changes will automatically be rebased on top of these commits when integrating. If you prefer to avoid this automatic rebasing, please check the documentation for the /integrate command for further details.

➡️ To integrate this PR with the above commit message to the master branch, type /integrate in a new comment.

Loading

@openjdk openjdk bot added the ready label Jul 6, 2021
Copy link
Member

@dholmes-ora dholmes-ora left a comment

Sorry I have to withdraw my initial review approval.

This certainly helps allow the writer thread to catch up sooner, but there is still no guarantee that it will keep up with the loggers sufficient to avoid the overflow.

What we have to ensure in addition is that the number of outstanding log messages permitted by the buffer size is always less than the max value allow by the semaphore. Unfortunately we don't know what that value is.

David

Loading

@openjdk openjdk bot removed the ready label Jul 6, 2021
@navyxliu
Copy link
Contributor Author

@navyxliu navyxliu commented Jul 6, 2021

What we have to ensure in addition is that the number of outstanding log messages permitted by the buffer size is always less than the max value allow by the semaphore. Unfortunately we don't know what that value is.

On Linux, SEM_VALUE_MAX is defined in <semaphore.h>. we can add an assertion that assert(_buffer_max_size < SEM_VALUE_MAX) . Currently, it seems that hotspot needs to support 3 semaphores.

  1. Posix semaphore of glibc. -- SEM_VALUE_MAX
  2. Windows API -- LONG_MAX
  3. MacOS -- I have found document for this.

Yes, you just unveil another issue. I found _buffer_max_size is 91k if I use -XX:AsyncLogBufferSize=50M. That value is bigger than SEM_VALUE_MAX of AIX.

The maximum entries of AsyncLogBuffer: 91022

Loading

@dholmes-ora
Copy link
Member

@dholmes-ora dholmes-ora commented Jul 6, 2021

I don't like the idea of trying to limit the log size based on a platform specific private implementation detail - and you'd have to check that against any user supplied buffer size and reject a too large buffer.

The other option is revert these changes and expose a way to ignore the ERANGE error in Semaphore.

Loading

Copy link
Member

@dholmes-ora dholmes-ora left a comment

I've been thinking about how to handle the ERANGE/EOVERFLOW in the Semaphore API. A default arg is one way. I was also considering a specific signal_xx method that allows overflow; or report to the caller that overflow happened. Not sure what might be best. What you have might be simplest for 17 but there are still some issues that need further investigation. See comments below. I think we need other opinions here too.

I'm surprised macOS has no overflow checks, it looks like its counter will just wrap when it overflows - which would break things, but of course is very unlikely in real use.

Thanks,
David

Loading

@@ -39,7 +39,7 @@ WindowsSemaphore::~WindowsSemaphore() {
::CloseHandle(_semaphore);
}

void WindowsSemaphore::signal(uint count) {
void WindowsSemaphore::signal(uint count, bool ignore_overflow) {
Copy link
Member

@dholmes-ora dholmes-ora Jul 7, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I believe the Windows ReleaseSemaphore can also fail with the equivalent of EOVERFLOW if the count would exceed the maximum allowed. We either need to dig deeper into what value of GetlastError we would see, or else ignore all errors if ignore_overflow is set. I think I can tweak a gtest to see what happens.

Loading

// The only difference between this and Semaphore is that
// it ignores errno ERANGE and EOVERFLOW.
class AsyncLogSemaphore : public CHeapObj<mtSynchronizer> {
SemaphoreImpl _impl;
Copy link
Member

@dholmes-ora dholmes-ora Jul 7, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I don't think this is necessary, just call wait(1, true) where needed.

Loading

@dholmes-ora
Copy link
Member

@dholmes-ora dholmes-ora commented Jul 7, 2021

I ran a test on Linux, Windows and OSX. As expected Linux gives EOVERFLOW. OSX the test just times out without error.

On Windows we get error 298:

ERROR_TOO_MANY_POSTS
298 (0x12A)
Too many posts were made to a semaphore.

so I think we should check for that and ignore it if ignoring overflow.

Thanks,
David

Loading

@navyxliu
Copy link
Contributor Author

@navyxliu navyxliu commented Jul 7, 2021

got it. I will cover Windows.

Loading

@navyxliu
Copy link
Contributor Author

@navyxliu navyxliu commented Jul 7, 2021

I'm surprised macOS has no overflow checks, it looks like its counter will just wrap when it overflows - which would break things, but of course is very unlikely in real use.

Unlike Posix and Win32, it's not easy for me to find any document about Darwin semaphore API.

I guess this is the equivalence of glibc on MacOS. check out semaphore_signal_internal.
https://opensource.apple.com/source/xnu/xnu-344.21.74/osfmk/kern/sync_sema.c.auto.html

if count has overflown, it should return kr from wait_queue_wakeup64_thread_locked.

Loading

This patch handles overflow scenerios for Posix and Windows.
MacOS platform doesn't have any error so we ignore it.
Copy link
Member

@dholmes-ora dholmes-ora left a comment

Figuring out the best way to handle this is proving to be quite tricky - sorry. I need to think some more about it. Unfortunately I'm away for a few days after today.

David

Loading

@@ -50,7 +50,12 @@ class Semaphore : public CHeapObj<mtSynchronizer> {
Semaphore(uint value = 0) : _impl(value) {}
~Semaphore() {}

void signal(uint count = 1) { _impl.signal(count); }
void signal(uint count = 1) { _impl.signal(count, false /* ignore_overflow */); }
Copy link
Member

@dholmes-ora dholmes-ora Jul 8, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Please change comment to:

/* don't ignore overflow */

as that describes what the false argument actually means, rather than just showing what parameter it is providing the value for.

Loading

// Ignore error of overflow
void signal_overflow(uint count = 1) {
Copy link
Member

@dholmes-ora dholmes-ora Jul 8, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'm a bit unsure about how to name and describe this given that the overflow check only relates to debug builds - in a product build both signal and signal_overflow are identical.

I had missed previously that the ignore_overflow parameter was only in the impl API not the main public API.

Loading

Copy link
Contributor Author

@navyxliu navyxliu Jul 8, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks you for reviewing this change.

The reason we only had ignore_overflow in impl API because I defined my own platform-independent Semaphore class, aka. AsyncLogSemaphore in previous revision. I changed type of _sem from Sempahore to AsyncLogSemaphore. I "overloaded" signal(uint count) in that way so I don't pollute "public API".

I don't think this is necessary, just call wait(1, true) where needed.

I think your opinion is that it's not necessary. how about I just add a second parameter ignore_overflow to Semaphore::signal with the default value = false?

Loading

@navyxliu
Copy link
Contributor Author

@navyxliu navyxliu commented Jul 8, 2021

Hi, @tstuefe ,
Do you mind trying this patch? David and I think we should ignore sem_post error when its value has been overflown. It happens rarely and ignoring this error won't affect correctness. I just wonder if this approach can solve the LogConfigurationTest.reconfigure_decorators_MT_vm failure on AIX?

Figuring out the best way to handle this is proving to be quite tricky

If it works out, the one open issue is what we should do on MacOS. My option is that we just leave it alone since semaphore_signal(not posix semaphore) on Darwin doesn't overflow. We can revisit this later if the assumption turns out false in the future.

Loading

@tstuefe
Copy link
Member

@tstuefe tstuefe commented Jul 8, 2021

Sorry for dropping out, I'm snowed in. I put the patch into our AIX CI. Due to the slowness of our AIX hardware, this may take a day or two.

Loading

@navyxliu
Copy link
Contributor Author

@navyxliu navyxliu commented Jul 8, 2021

Thanks! Let's see the result. Meanwhile, allow me refactor this patch and spend more time semaphore of Darwin-XNU

Loading

@mlbridge
Copy link

@mlbridge mlbridge bot commented Jul 8, 2021

Mailing list message from David Holmes on hotspot-runtime-dev:

On 7/07/2021 3:26 pm, Xin Liu wrote:

On Wed, 7 Jul 2021 00:40:10 GMT, David Holmes <dholmes at openjdk.org> wrote:

I'm surprised macOS has no overflow checks, it looks like its counter will just wrap when it overflows - which would break things, but of course is very unlikely in real use.

Unlike Posix and Win32, it's not easy for me to find any document about Darwin semaphore API.

I guess this is the equivalence of glibc on MacOS. check out `semaphore_signal_internal`.
https://opensource.apple.com/source/xnu/xnu-344.21.74/osfmk/kern/sync_sema.c.auto.html

if count has overflown, it should return kr from `wait_queue_wakeup64_thread_locked`.

You mean if count++ wraps around to become negative then the next call
to signal will potentially execute that code? As the count++ happens
after this that doesn't tell us anything about what happens to the
signal that actually causes the overflow.

In any case due diligence has been done here. There is no documented
error for overflow on macOS. A test for overflow failed to trigger any
error within the test timeout period. I'm trying a modified test now to
see if I can get any failure.

David

Loading

@mlbridge
Copy link

@mlbridge mlbridge bot commented Jul 8, 2021

Mailing list message from Liu, Xin on hotspot-runtime-dev:

I had a gtest. I think it can trigger overflow issue on different
platforms. Since we don't know the cap, we have to increment it one by
one. I can't hit any assert on MacOS.

TEST(Semaphore, signal_overflow) {
Semaphore sem(0);
sem.signal((uint)-1);
}

On 7/6/21 11:58 PM, David Holmes wrote:

e due diligence

Loading

@mlbridge
Copy link

@mlbridge mlbridge bot commented Jul 8, 2021

Mailing list message from David Holmes on hotspot-runtime-dev:

On 7/07/2021 3:26 pm, Xin Liu wrote:

On Wed, 7 Jul 2021 00:40:10 GMT, David Holmes <dholmes at openjdk.org> wrote:

I'm surprised macOS has no overflow checks, it looks like its counter will just wrap when it overflows - which would break things, but of course is very unlikely in real use.

Unlike Posix and Win32, it's not easy for me to find any document about Darwin semaphore API.

I guess this is the equivalence of glibc on MacOS. check out `semaphore_signal_internal`.
https://opensource.apple.com/source/xnu/xnu-344.21.74/osfmk/kern/sync_sema.c.auto.html

if count has overflown, it should return kr from `wait_queue_wakeup64_thread_locked`.

You mean if count++ wraps around to become negative then the next call
to signal will potentially execute that code? As the count++ happens
after this that doesn't tell us anything about what happens to the
signal that actually causes the overflow.

In any case due diligence has been done here. There is no documented
error for overflow on macOS. A test for overflow failed to trigger any
error within the test timeout period. I'm trying a modified test now to
see if I can get any failure.

David

Loading

@mlbridge
Copy link

@mlbridge mlbridge bot commented Jul 8, 2021

Mailing list message from Liu, Xin on hotspot-runtime-dev:

I had a gtest. I think it can trigger overflow issue on different
platforms. Since we don't know the cap, we have to increment it one by
one. I can't hit any assert on MacOS.

TEST(Semaphore, signal_overflow) {
Semaphore sem(0);
sem.signal((uint)-1);
}

On 7/6/21 11:58 PM, David Holmes wrote:

e due diligence

Loading

@navyxliu
Copy link
Contributor Author

@navyxliu navyxliu commented Jul 9, 2021

One possibility is to change the code to use a Monitor that acts as the
asynclog lock and the wakeup mechanism, with a suitable guard in the
writing code so that we don't try to use the Monitor until after it has
been initialised (which is after the first log writes may occur).

I am not sure about that. The current code derived from there. HotSpot Monitor needs Thread::current(), but the logging event spans from the very beginning to the very end of JVM. We have to circumvent those cases.

On the other hand, I carefully read the implementation of semaphore_signal on Darwin. I am pretty sure it returns KERN_SUCCESS when overflow happens. I added a line of comment in the last revision. Could you take a look at that?

Loading

@mlbridge
Copy link

@mlbridge mlbridge bot commented Jul 13, 2021

Mailing list message from David Holmes on hotspot-runtime-dev:

On 9/07/2021 11:33 am, Xin Liu wrote:

On Thu, 8 Jul 2021 09:43:11 GMT, David Holmes <david.holmes at oracle.com> wrote:

One possibility is to change the code to use a Monitor that acts as the
asynclog lock and the wakeup mechanism, with a suitable guard in the
writing code so that we don't try to use the Monitor until after it has
been initialised (which is after the first log writes may occur).

I am not sure about that. The current code derived from there. HotSpot Monitor needs Thread::current(), but the logging event spans from the very beginning to the very end of JVM. We have to circumvent those cases.

But we already circumvent that for async logging. We can't use async
logging until after we have called AsyncLogWriter::initialize(). So the
synchronization objects used by AsyncLogWriter can be plain
Mutex/Monitor, they don't need to be Semaphore.

On the other hand, I carefully read the implementation of semaphore_signal on Darwin. I am pretty sure it returns KERN_SUCCESS when overflow happens. I added a line of comment in the last revision. Could you take a look at that?

The issue is not what it returns but how it actually behaves.

David
-----

Loading

1 similar comment
@mlbridge
Copy link

@mlbridge mlbridge bot commented Jul 13, 2021

Mailing list message from David Holmes on hotspot-runtime-dev:

On 9/07/2021 11:33 am, Xin Liu wrote:

On Thu, 8 Jul 2021 09:43:11 GMT, David Holmes <david.holmes at oracle.com> wrote:

One possibility is to change the code to use a Monitor that acts as the
asynclog lock and the wakeup mechanism, with a suitable guard in the
writing code so that we don't try to use the Monitor until after it has
been initialised (which is after the first log writes may occur).

I am not sure about that. The current code derived from there. HotSpot Monitor needs Thread::current(), but the logging event spans from the very beginning to the very end of JVM. We have to circumvent those cases.

But we already circumvent that for async logging. We can't use async
logging until after we have called AsyncLogWriter::initialize(). So the
synchronization objects used by AsyncLogWriter can be plain
Mutex/Monitor, they don't need to be Semaphore.

On the other hand, I carefully read the implementation of semaphore_signal on Darwin. I am pretty sure it returns KERN_SUCCESS when overflow happens. I added a line of comment in the last revision. Could you take a look at that?

The issue is not what it returns but how it actually behaves.

David
-----

Loading

@navyxliu
Copy link
Contributor Author

@navyxliu navyxliu commented Jul 13, 2021

But we already circumvent that for async logging. We can't use async
logging until after we have called AsyncLogWriter::initialize(). So the
synchronization objects used by AsyncLogWriter can be plain
Mutex/Monitor, they don't need to be Semaphore.

That is not true. I deleted finalize() because it was complex and not necessary after we switch from Monitor to Semaphore.
A thread may emit logs even it has deleted itself.

I reviewed this line. https://github.com/apple/darwin-xnu/blob/main/osfmk/kern/sync_sema.c#L400
In my understanding, semaphore_signal will try to wake up one in the wait queue of the semaphore. if kr != KERN_SUCCESS, it will reset counter to 0 because no one is waiting for that. In our case, we should take this route. I think the behavior is defined on MacOS.

thanks,
--lx

Loading

@mlbridge
Copy link

@mlbridge mlbridge bot commented Jul 13, 2021

Mailing list message from David Holmes on hotspot-runtime-dev:

On 13/07/2021 11:41 am, Xin Liu wrote:

On Tue, 13 Jul 2021 01:18:28 GMT, David Holmes <david.holmes at oracle.com> wrote:

But we already circumvent that for async logging. We can't use async
logging until after we have called AsyncLogWriter::initialize(). So the
synchronization objects used by AsyncLogWriter can be plain
Mutex/Monitor, they don't need to be Semaphore.

That is not true. I deleted finalize() because it was complex and not necessary after we switch from Monitor to Semaphore.
A thread may emit logs even it has deletes itself.

Ah - sorry. I was looking at the VM initialization issue not the thread
termination issue. Pity.

I reviewed this line. https://github.com/apple/darwin-xnu/blob/main/osfmk/kern/sync_sema.c#L400
In my understanding, `semaphore_signal` will try to wait up one in the wait queue of the semaphore. if kr != KERN_SUCCESS, it will reset counter to 0 because no one is waiting on that. In our case, we should take this route. I think the behavior is defined.

Sorry but there is no way I'm going to trust any ad-hoc guesses about
what exactly that code will do. I don't know any of the invariants of
the data structure, exactly what the different fields represent, or how
exactly they are maintained. Heck we don't even know that really is the
code involved!

I will continue to think this about this problem, but I'm not seeing any
solution I like so far.

Thanks,
David
-----

Loading

@mlbridge
Copy link

@mlbridge mlbridge bot commented Jul 13, 2021

Mailing list message from David Holmes on hotspot-runtime-dev:

On 13/07/2021 1:03 pm, David Holmes wrote:

On 13/07/2021 11:41 am, Xin Liu wrote:

On Tue, 13 Jul 2021 01:18:28 GMT, David Holmes
<david.holmes at oracle.com> wrote:

But we already circumvent that for async logging. We can't use async
logging until after we have called AsyncLogWriter::initialize(). So the
synchronization objects used by AsyncLogWriter can be plain
Mutex/Monitor, they don't need to be Semaphore.

That is not true. I deleted finalize() because it was complex and not
necessary after we switch from Monitor to Semaphore.
A thread may emit logs even it has deletes itself.

Ah - sorry. I was looking at the VM initialization issue not the thread
termination issue. Pity.

As @pchilano has pointed out to me we can use the lower-level
PlatformMonitor to avoid the problems with Monitor. It is of a similar
low-level as Semaphore.

Instead of having a binary semaphore to control access to the _buffer,
and a counting semaphore to control the wakeup of the async writer
thread, we can just use a PlatformMonitor with a _data_available state
field e.g (rough outline).

void AsyncLogWriter::write() {
AsyncLogBuffer logs;

{ // critical region
AsyncLogLocker locker;

_buffer.pop_all(&logs);
// append meta-messages of dropped counters
AsyncLogMapIterator dropped_counters_iter(logs);
_stats.iterate(&dropped_counters_iter);
_data_available = false;
}
...
}

void AsyncLogWriter::run() {
while (true) {
{
AsyncLogLocker locker;
while (!_data_available) _lock.wait();
}
write();
}
}

void AsyncLogWriter::enqueue_locked(const AsyncLogMessage& msg) {
...
_buffer.push_back(msg);
_data_available = true;
_lock.notify();
}

David
-----

I reviewed this line.
https://github.com/apple/darwin-xnu/blob/main/osfmk/kern/sync_sema.c#L400
In my understanding, `semaphore_signal` will try to wait up one in the
wait queue of the semaphore. if kr != KERN_SUCCESS, it will reset
counter to 0 because no one is waiting on that. In our case, we should
take this route.? I think the behavior is defined.

Sorry but there is no way I'm going to trust any ad-hoc guesses about
what exactly that code will do. I don't know any of the invariants of
the data structure, exactly what the different fields represent, or how
exactly they are maintained. Heck we don't even know that really is the
code involved!

I will continue to think this about this problem, but I'm not seeing any
solution I like so far.

Thanks,
David
-----

Loading

@navyxliu
Copy link
Contributor Author

@navyxliu navyxliu commented Jul 13, 2021

Aha, os::PlatformMonitor is just the cross-platform condition variable, no strings attached!
I think it is a better solution. TBH, I don't like 'ignore_overflow'. it's a hack solution. let's save it as a back-up solution.

We still have 2 week before phase-2 rampdown. Let me also take a look how JFR handle this case. It is said JFR also has an asynchronous buffer too.

Loading

@mlbridge
Copy link

@mlbridge mlbridge bot commented Jul 13, 2021

Mailing list message from David Holmes on hotspot-runtime-dev:

On 13/07/2021 4:10 pm, Xin Liu wrote:

On Thu, 8 Jul 2021 22:12:23 GMT, Xin Liu <xliu at openjdk.org> wrote:

This patch solved the sempahore overflow issue with errno ERANGE or EOVERFLOW.
Previously, we have asymmetric p/v operations for semaphore _sem. Each iteration
only decrements _sem 1 but dequeues N messages. If logging threads keep preempting
async logging thread, it may cause the value of _sem accumulates until overflow!

The patch corrects the value of _sem after write(). n messages are dequeued/processed.
We need to invoke _sem.wait() max(n-1, 1) time. This ensures that each iteration
decrements n instead of 1.

Xin Liu has updated the pull request incrementally with one additional commit since the last revision:

Refactor code with API change.

Semaphore::signal returns a boolean value to indicate it's succeed or not.

Aha, os::PlatformMonitor is just the cross-platform condition variable, no strings attached!
I think it is a better solution. TBH, I don't like 'ignore_overflow'. it's a hack solution. let's save it as a back-up solution.

We still have 2 week before phase-2 rampdown. Let me also take a look how JFR handle this case. It is said JFR also has an asynchronous buffer too.

JDK 17 will enter Rampdown Phase Two this Thursday, 15 July,
at 15:00 UTC. This needs to be handled promptly.

Thanks,
David

Loading

1 similar comment
@mlbridge
Copy link

@mlbridge mlbridge bot commented Jul 13, 2021

Mailing list message from David Holmes on hotspot-runtime-dev:

On 13/07/2021 4:10 pm, Xin Liu wrote:

On Thu, 8 Jul 2021 22:12:23 GMT, Xin Liu <xliu at openjdk.org> wrote:

This patch solved the sempahore overflow issue with errno ERANGE or EOVERFLOW.
Previously, we have asymmetric p/v operations for semaphore _sem. Each iteration
only decrements _sem 1 but dequeues N messages. If logging threads keep preempting
async logging thread, it may cause the value of _sem accumulates until overflow!

The patch corrects the value of _sem after write(). n messages are dequeued/processed.
We need to invoke _sem.wait() max(n-1, 1) time. This ensures that each iteration
decrements n instead of 1.

Xin Liu has updated the pull request incrementally with one additional commit since the last revision:

Refactor code with API change.

Semaphore::signal returns a boolean value to indicate it's succeed or not.

Aha, os::PlatformMonitor is just the cross-platform condition variable, no strings attached!
I think it is a better solution. TBH, I don't like 'ignore_overflow'. it's a hack solution. let's save it as a back-up solution.

We still have 2 week before phase-2 rampdown. Let me also take a look how JFR handle this case. It is said JFR also has an asynchronous buffer too.

JDK 17 will enter Rampdown Phase Two this Thursday, 15 July,
at 15:00 UTC. This needs to be handled promptly.

Thanks,
David

Loading

@navyxliu
Copy link
Contributor Author

@navyxliu navyxliu commented Jul 13, 2021

okay. copy that. I will send out a new revision soon.

Loading

Copy link
Member

@dholmes-ora dholmes-ora left a comment

Sorry this isn't right at all.

David

Loading

// _lock(1) denotes a critional region.
Semaphore _lock;
// _sem is a semaphore whose value denotes how many messages have been enqueued.
// It decreases in AsyncLogWriter::run()
Semaphore _sem;
Semaphore _flush_sem;

os::PlatformMonitor _cv;
Copy link
Member

@dholmes-ora dholmes-ora Jul 13, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

No this isn't what you need. The _lock is the PlatformMonitor. You lock/unlock in AsyncLogLocker for the critical regions, and then use the wait/notify operations for the coordination.

Loading

Copy link
Contributor Author

@navyxliu navyxliu Jul 13, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

you mean I should use os::PlatformMonitor _lock as a combination of mutux and cv, right?

Loading


while (!_data_available) {
_lock.signal();
_cv.wait(0/* no timeout */);
Copy link
Member

@dholmes-ora dholmes-ora Jul 13, 2021

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

You can't call wait() on an unlocked monitor - that's not how monitors are used.

Loading

Second attempt. This patch also removed semaphore-based lock because
PlatformMonitor can also be used as a Mutex lock.
@navyxliu
Copy link
Contributor Author

@navyxliu navyxliu commented Jul 13, 2021

hi, @dholmes-ora @pchilano,

Thank you for letting me know os::PlatformMonitor. I used to think Monitor is a higher-level synchronization construct than Semaphore. it turns out that os::PlatformMonitor is as low-level as semaphore. Lesson learned.

Could you take a look at this change and see if I use it correctly?

thanks,
--lx

Loading

Copy link
Member

@dholmes-ora dholmes-ora left a comment

Hi Xin,

This looks good. I'll run it through our testing.

I'll also try to get @pchilano to review it.

Thanks,
David

Loading

src/hotspot/share/logging/logAsyncWriter.hpp Show resolved Hide resolved
Loading
@openjdk openjdk bot added the ready label Jul 13, 2021
Copy link
Contributor

@pchilano pchilano left a comment

Hi Xin,

Looks good to me too.
The only small suggestion is that you could do the pop_all() and _stats.iterate when coming out of wait() since you are already holding the monitor, and then pass the logs to write(). Either way is fine though.

Thanks,
Patricio

Loading

@navyxliu
Copy link
Contributor Author

@navyxliu navyxliu commented Jul 14, 2021

The only small suggestion is that you could do the pop_all() and _stats.iterate when coming out of wait() since you are already holding the monitor, and then pass the logs to write(). Either way is fine though.

Thanks for reviewing. I see what you mean. I take a note on that. yes, we may gain something if we merge two critical areas.
I will take it as a follow-up.

Loading

@navyxliu
Copy link
Contributor Author

@navyxliu navyxliu commented Jul 14, 2021

Hi, Reviewers,

Thanks a lot. I append a comment to explain why we choose PlatformMonitor over Semaphore. Meanwhile, I defer performance-wise change. Please let me know the results of test. I hope we can make it to jdk17 safely before the window is close.

Loading

@mlbridge
Copy link

@mlbridge mlbridge bot commented Jul 14, 2021

Mailing list message from David Holmes on hotspot-runtime-dev:

On 14/07/2021 11:32 am, Xin Liu wrote:

On Wed, 14 Jul 2021 01:18:17 GMT, Patricio Chilano Mateo <pchilanomate at openjdk.org> wrote:

The only small suggestion is that you could do the pop_all() and _stats.iterate when coming out of wait() since you are already holding the monitor, and then pass the logs to write(). Either way is fine though.

Thanks for reviewing. I see what you mean. I take a note on that. yes, we may gain something if we merge two critical areas.
I will take it as a follow-up.

I think it is cleaner as-is.

Testing tiers 1-3 passed with no problems, so I think this can be
integrated now.

Thanks,
David

Loading

1 similar comment
@mlbridge
Copy link

@mlbridge mlbridge bot commented Jul 14, 2021

Mailing list message from David Holmes on hotspot-runtime-dev:

On 14/07/2021 11:32 am, Xin Liu wrote:

On Wed, 14 Jul 2021 01:18:17 GMT, Patricio Chilano Mateo <pchilanomate at openjdk.org> wrote:

The only small suggestion is that you could do the pop_all() and _stats.iterate when coming out of wait() since you are already holding the monitor, and then pass the logs to write(). Either way is fine though.

Thanks for reviewing. I see what you mean. I take a note on that. yes, we may gain something if we merge two critical areas.
I will take it as a follow-up.

I think it is cleaner as-is.

Testing tiers 1-3 passed with no problems, so I think this can be
integrated now.

Thanks,
David

Loading

@navyxliu
Copy link
Contributor Author

@navyxliu navyxliu commented Jul 14, 2021

/integrate

Loading

@openjdk
Copy link

@openjdk openjdk bot commented Jul 14, 2021

Going to push as commit 67273ae.
Since your change was applied there have been 45 commits pushed to the master branch:

  • 0f54707: 8270056: Generated lambda class can not access protected static method of target class
  • 8583aab: 8270025: DynamicCallSiteDesc::withArgs doesn't throw NPE
  • d32e42c: 8270184: [TESTBUG] Add coverage for jvmci ResolvedJavaType.toJavaName() for lambdas
  • b2416b6: 8269281: java/foreign/Test{Down,Up}call.java time out
  • bd95c0c: 8269635: Stress test SEGV while emitting OldObjectSample
  • 00ef65f: 8269525: Deadlock during Volano with JFR
  • e631add: 8259848: Interim javadoc build does not support platform links
  • 040c02b: 8269795: C2: Out of bounds array load floats above its range check in loop peeling resulting in SEGV
  • 0f32982: 8270203: Missing build dependency between jdk.jfr-gendata and buildtools-hotspot
  • 4fc3180: 8266345: (fs) Custom DefaultFileSystemProvider security related loops
  • ... and 35 more: https://git.openjdk.java.net/jdk17/compare/4ad8b04421f3142c396ade26f36334da7a915b5b...master

Your commit was automatically rebased without conflicts.

Loading

@openjdk openjdk bot closed this Jul 14, 2021
@openjdk openjdk bot added integrated and removed ready rfr labels Jul 14, 2021
@openjdk
Copy link

@openjdk openjdk bot commented Jul 14, 2021

@navyxliu Pushed as commit 67273ae.

💡 You may see a message that your pull request was closed with unmerged commits. This can be safely ignored.

Loading

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
4 participants