RFR: 8271471: [IR Framework] Rare occurrence of "<!-- safepoint while printing -->" in PrintIdeal/PrintOptoAssembly can let tests fail

[Christian Hagedorn]

On Thu, 29 Jul 2021 12:25:27 GMT, Christian Hagedorn <chagedorn at openjdk.org> wrote:

> A test VM used by the IR framework sometimes prints `` in the middle of emitting a `PrintIdeal` or `PrintOptoAssembly` output which could lead to IR matching failures:
> https://github.com/openjdk/jdk/blob/489e5fd12a37a45f4f5ea64b05f85c6f99f70811/src/hotspot/share/utilities/ostream.cpp#L918-L927
> 
> I thought about just bailing out of IR matching if this string is found after a failure but this issue also affects internal framework tests (I observed one case locally where this happened in the test `TestIRMatching`, letting it fail).
> 
> Handling `` makes things more complicated for the IR framework tests. I'm not sure about the value of printing this message in the first place. But if nobody objects, I suggest to either remove it or at least guard it with `Verbose`, for example. I went with the latter solution in this PR.
> 
> Thanks,
> Christian

I played around with it and interestingly this code path is hit quite often when just running `java -Xbatch -XX:+PrintIdeal -XX:+PrintOptoAssembly --version`.

I had a closer look at one of these occurrences. In this case, the reason we are executing `break_tty_lock_for_safepoint()` with a tty lock (i.e. at a safepoint while printing) was the following:
At some point, `SharedRuntime::handle_wrong_method_ic_miss` is called in thread X due to having cached the wrong method. This code then creates a new inline cache stub. In the meantime, the VM thread Y is waiting for a next VM operation in the loop. When the VM thread is calling `VMThread::setup_periodic_safepoint_if_needed()` it notices that a cleanup is needed (`SafepointSynchronize::is_cleanup_needed()` is true) due to the new IC stub. The cleanup operation is chosen as next VM operation. To execute this operation, it requires a safepoint. It sets the polling word of all threads, including the C2 compiler thread and `SafepointMechanism::local_poll_armed()` is now true. Unfortunately, the C2 compiler thread is currently printing with a tty lock acquired either at:
https://github.com/openjdk/jdk/blob/eec64f55870cf51746755d8fa59098a82109e826/src/hotspot/share/opto/output.cpp#L1870-L1871
or at
https://github.com/openjdk/jdk/blob/eec64f55870cf51746755d8fa59098a82109e826/src/hotspot/share/opto/compile.cpp#L789-L790
Therefore, we break the lock inside `ThreadInVMfromNative()` at the next print call in the C2 compiler thread because `SafepointMechanism::local_poll_armed()` is true.

To me this seems okay and not a problem but just bad luck due to timing.

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

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