RFR: 8284849: Add deoptimization to unified logging

[Jorn Vernee]

On Fri, 20 May 2022 14:12:30 GMT, Johan Sjölén <duke at openjdk.java.net> wrote:

> This PR adds a new "deoptimization" tag and a new log message on the info level mimicking JFR's deoptimization event. In the future this tag will be used to add trace level information, hopefully replacing TraceDeoptimization. JFR's event also captures the stacktrace, which this does not (happy to add this if considered important).
> 
> An example output looks like this: 
> 
> 
> [1.346s][info][deoptimization] Deoptimization start {
> [1.346s][info][deoptimization]   compileId = 407
> [1.346s][info][deoptimization]   compiler = c2
> [1.346s][info][deoptimization]   method:lineno:bci = java.util.concurrent.locks.ReentrantLock$Sync.tryRelease(I)Z:176:26
> [1.346s][info][deoptimization]   instruction = ifne
> [1.346s][info][deoptimization]   reason = unstable_if
> [1.346s][info][deoptimization]   action = reinterpret
> [1.346s][info][deoptimization] } Deoptimization end

Thanks for looking at this!

I suggest trying to match the style of the `-Xlog:jit+compilation=debug` messages, since deoptimization is like the dual of compilation. And trying to keep the output on a single line,

Rather than printing the compiler name, I think printing the compilation level is more useful, as well as including some info about whether it was an osr compilation maybe. The `jit+compilation` log messages do the latter by printing an extra `%`.

Maybe something like:


<compile id> <is osr> <compile level> <method signature> @ <bci> <reason> -> <action>


The instruction and line number could also be incorporated somewhere, but the compilation messages don't have them either. They seem fine to leave out I think.

Also, I noticed that `jit+compilation` has the `debug` level, so maybe this log message should be under the `debug` level as well, instead of `info`. I don't know if there is any guidance on that somewhere.

src/hotspot/share/runtime/deoptimization.cpp line 1935:

> 1933:     JFR_ONLY(post_deoptimization_event(nm, trap_method(), trap_bci, trap_bc, reason, action);)
> 1934: 
> 1935:     if(Log(deoptimization)::is_info()) {

I don't see this pattern used for checking whether a log tag is enabled used elsewhere. Won't this only print when the log level is exactly `info`?

The pattern I see used elsewhere is:


LogTarget(Info, <tag>) lt;
if (lt.is_enabled()) {
    ...
}

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

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