RFR: 8284849: Add deoptimization to unified logging [v3]

[Vladimir Kozlov]

On Wed, 1 Jun 2022 11:59:36 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
>
> Johan Sjölén has updated the pull request incrementally with one additional commit since the last revision:
> 
>   Remove superfluous if stmt

Consider moving this code into separate method.
This part of code is used for processing only uncommon traps when compiled code traps.
A compiled method could be deoptimized for other reasons too. Both paths calls  `fetch_unroll_info_helper()`. May be it is better place to print and log (an other RFE).

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

> 1935:       char* name_sig = tm->name_and_sig_as_C_string();
> 1936:       const char* reason_name = Deoptimization::trap_reason_name(reason);
> 1937:       const char* reason_action = Deoptimization::trap_action_name(action);

What is the reason to specify `Deoptimization::` in these calls?

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

> 1939:       log_debug(deoptimization)("cid: %d osr: %s level: %d %s @ %d %s -> %s",
> 1940:                                 nm->compile_id(),
> 1941:                                 (nm->is_osr_method() ? "true" : "false"),

Since it is one-liner it should follow how we print for `-Xlog:jit+compilation=debug`: 
https://github.com/openjdk/jdk/blob/master/src/hotspot/share/compiler/compileTask.cpp#L482

[0.142s][debug][jit,compilation]    6 %     4       Reproducer::run @ 8 (39 bytes)

Of cause we can use `osr` instead of `%` in output to be clear.

You can simplify `osr: %s` print by `%s` and `(nm->is_osr_method() ? "osr" : "   ")`
You also need to print `osr_bci` - we can have separate compilations of the same method for different `bci`.
Also print `p2i(fr.pc())` and relative PC which very useful:
https://github.com/openjdk/jdk/blob/master/src/hotspot/share/runtime/deoptimization.cpp#L1883

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

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