-
Notifications
You must be signed in to change notification settings - Fork 6.1k
8359820: Improve handshake/safepoint timeout diagnostic messages #26309
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
base: master
Are you sure you want to change the base?
8359820: Improve handshake/safepoint timeout diagnostic messages #26309
Conversation
👋 Welcome back toxaart! A progress list of the required criteria for merging this PR into |
@toxaart 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:
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 19 new commits pushed to the
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. As you do not have Committer status in this project an existing Committer must agree to sponsor your change. Possible candidates are the reviewers of this PR (@dholmes-ora, @tstuefe) but any other Committer may sponsor as well. ➡️ To flag this PR as ready for integration with the above commit message, type |
Webrevs
|
@toxaart I'm really looking for something in the fatal error handler so that instead of seeing just:
There is something there that indicates it was a handshake timeout. E.g.
We may need the handshake code to set a flag on the target Thread that the error code can query if it sees a SIGILL. |
…in VMError::report()
a8179fc
to
310ef85
Compare
…with-low-handshake-timeout-on-intel-sde
…sde' of https://github.com/toxaart/jdk into JDK-8359820-SIGILL-with-low-handshake-timeout-on-intel-sde
|
…with-low-handshake-timeout-on-intel-sde
BTW, for artificially generated signals we already have a clear indication in hs_err files. We print the sigaction structure associated with the signal. e.g.
SI_USER => sent via kill command or pthread_kill See also: https://pubs.opengroup.org/onlinepubs/007904875/functions/sigaction.html I have nothing against making this clearer, just saying that the info is already kind of there. |
Yes, but there are a few reasons a SIGILL may have been fired at a thread, so it would be useful to get a clear indication of exactly why it happened. Not everyone will realize/know that SIGILL happens because of a timeout in handshake/safepoint. |
I still don't get it.
|
To clarify, I am concerned about misleading printouts. Signal issues are difficult to analyze. Signals can interleave, overlap, get lost, or be blocked. I think it's important to be precise. For example, saving gobal information A, sending signal, and in the handler printing "signal X relates to global information A" can be wrong. The signal can have some other cause. It would be good to save both the sender and recipent's thread id in the global information before sending the signal, the in the signal handler to correlate this with what sigaction_t says who send the signal, and with the receiving thread's thread id. That way we can be sure that, yes, X send a signal A to Y, I am Y, I got signal A from X, so this is safe information I could now print. It would make investigating issues like the one motivating this change a lot easier, especially when multiple signals are involved. |
Yes, the receiving thread is the one to receive the SIGILL. I agree that the changes introduce a degree of redundancy, but it is difficult to see by looking at the thread callstack that it was killed by the timeout mechanism of the handshake. I found it by looking at events log, see the discussion in JBS.
I think I already described a possible situation: if the receiver does not report the crash within 3 seconds, then a fatal error will be reported by the calling thread. However, it may happen that any other thread receives SIGILL for any other reason within that time interval. But the "busy" thread is already in the "communicative" variable, which will not be the signal receiver in this particular case. I do not really know if this situation is just hypothetical or ever occurred in practice.
No, it is intentionally fired by the timeout handler. Quote from mr. Shipilev, see the issue discussion: "The intent for SIGILL is to trigger the crash at the thread that blocks handshake/safepoint sync. E.g. a Java thread that is stuck on miscompiled loop without safepoint checks. Or some VM code that spins without VM transitions. See JDK-8219584. This feature is remarkably useful in the field, used this dozens of times. So whatever we do, we need to keep printing the instructions block and hopefully a backtrace." |
Not sure what is so hard to understand here @tstuefe . A thread is hit with a SIGILL and we report that now, but we don't report why it was hit with the SIGILL. If there were only one reason (like it executed an illegal instruction) then it would be obvious, but we have hijacked SIGILL as a generic "something happened" signal. So the proposal here is to record the identity of the thread being sent a SIGILL due to a handshake or safepoint timeout, so that when that thread responds to the SIGILL it can see that is why it got it and report that fact. If a different thread also got a SIGILL for a different reason we don't want it reporting it was due to the timeout mechanism. |
@toxaart Thank you for laying it out to me. So SDE slowed things down, we did not reach the safepoint, the timeout mechanism fired a SIGILL to the slow thread, the slow thread was not fast enough to end the JVM, and the sending thread then executed the fatal("Handshake timeout")? Which thread won the hs-err pid writing? Was (A) the winner, and it started error handling? And you maybe saw a "Thread XXX also had an error" line from the sending thread? Or (B) did the slow thread not even get the signal, and the hs_err file you got was from the fatal("Handshake timeout") in the sending thread? (B) would be odd; a signal sent with pthread_kill had not been delivered to the target thread for three seconds :-( is signal delivery on SDE broken, or is it just really slow? In any case, I think I understand now that you try to improve the hs_err printout for case (A), right? If so, sure, that makes sense. What confused me was your printout
No problem, its fine to make things clearer.
To help with this case, I suggest a simple addition in handshake.cpp:
which will show a clearer message at the start of the hs-err file, in case we don't have the VM output.
Yes, it could happen. The mechanism could be improved by storing the fact that a SIGILL has been sent to thread X not in a global variable but in the Not saying you have to do this. Can also be done in a later RFE. |
Thank you, @dholmes-ora . I already answered Anton, but I get that now. |
Yes, the slow thread started reporting, and I think I also observed the latter message as well. Note that the fatal error is still processed in the end of the timeout handler, but not reported by VMError, as it can report only one such error. So yes, we want to improve the reporting for case A: when a slow thread receives a SIGILL and dies being able to handle the error, we want to know if SIGILL came from handshake/safepoint timeout and print extra info if that is the case.
Thanks, added to the latest change.
I think this would be a more invasive change, we can do it when there is a real need. |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Ok thanks.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
The structure of this looks good, but I have a few remaining nits. Thanks.
if (os::signal_thread(target, SIGILL, "cannot be handshaked")) { | ||
// Give target a chance to report the error and terminate the VM. | ||
os::naked_sleep(3000); | ||
} | ||
} else { | ||
log_error(handshake)("No thread with an unfinished handshake op(" INTPTR_FORMAT ") found.", p2i(op)); | ||
} | ||
fatal("Handshake timeout"); | ||
if (target != nullptr) { | ||
fatal("Thread " PTR_FORMAT " has not cleared handshake op: " PTR_FORMAT ", then failed to terminate JVM", p2i(target), p2i(op)); |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
fatal("Thread " PTR_FORMAT " has not cleared handshake op: " PTR_FORMAT ", then failed to terminate JVM", p2i(target), p2i(op)); | |
fatal("Thread " PTR_FORMAT " has not cleared handshake op %s, and failed to terminate the JVM", p2i(target), op->name()); |
The earlier logging statement that uses p2i(op)
relies on an even earlier logging statement (line 189/190) that reports the name and the p2i
value. But the fatal error message can't rely on using logging information to map the p2i
value back to a name, so we need the name directly.
volatile intptr_t VMError::handshakeTimedOutThread = p2i(nullptr); | ||
volatile intptr_t VMError::safepointTimedOutThread = p2i(nullptr); |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
volatile intptr_t VMError::handshakeTimedOutThread = p2i(nullptr); | |
volatile intptr_t VMError::safepointTimedOutThread = p2i(nullptr); | |
volatile intptr_t VMError::_handshake_timeout_thread = p2i(nullptr); | |
volatile intptr_t VMError::_safepoint_timeout_thread = p2i(nullptr); |
@@ -1329,6 +1337,14 @@ void VMError::report(outputStream* st, bool _verbose) { | |||
# undef END | |||
} | |||
|
|||
void VMError::set_handshake_timed_out_thread(intptr_t x) { |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
void VMError::set_handshake_timed_out_thread(intptr_t x) { | |
void VMError::set_handshake_timed_out_thread(intptr_t thread_addr) { |
handshakeTimedOutThread = x; | ||
} | ||
|
||
void VMError::set_safepoint_timed_out_thread(intptr_t x) { |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
void VMError::set_safepoint_timed_out_thread(intptr_t x) { | |
void VMError::set_safepoint_timed_out_thread(intptr_t thread_addr) { |
Hi, please consider the following changes:
The problem in the issue description is not a problem by itself, the behavior is not unexpected, but it is somewhat difficult to find out what caused SIGILL to be fired.
We propagate this information from
handshake::handle_timeout()
toVMError::report()
with a help of a global variable. The same mechanism is used to address a similar issue in the safepoint timeout handler.Tested in tiers 1-3.
Progress
Issue
Reviewers
Reviewing
Using
git
Checkout this PR locally:
$ git fetch https://git.openjdk.org/jdk.git pull/26309/head:pull/26309
$ git checkout pull/26309
Update a local copy of the PR:
$ git checkout pull/26309
$ git pull https://git.openjdk.org/jdk.git pull/26309/head
Using Skara CLI tools
Checkout this PR locally:
$ git pr checkout 26309
View PR using the GUI difftool:
$ git pr show -t 26309
Using diff file
Download this PR as a diff file:
https://git.openjdk.org/jdk/pull/26309.diff
Using Webrev
Link to Webrev Comment