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

[David Holmes]

On Wed, 4 Aug 2021 13:08:13 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.

Thanks @chhagedorn . I can see that this message is somewhat expected in this context. Is it really that difficult to ignore in the IR matching? This is XML-ouput and it is formatted as a comment, so shouldn't the matching logic ignore XML comments?

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

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