RFR: 8319850: PrintInlining should print which methods are late inlines [v27]

[Vladimir Kozlov]

On Mon, 27 Jan 2025 09:21:40 GMT, Theo Weidmann <tweidmann at openjdk.org> wrote:

>> This PR overhauls the print inlining system. It now allows to record multiple inlining messages per potential inline/call site. Since inlines can trigger further inlines, the entire print inlining information is now stored as a tree. This structure enables more detailed logging and prevents the accidental overwriting of useful logs, an issue encountered in the past.
>> 
>> Also, prints will contain detailed information about which methods are late inlines.
>> 
>> This rewrite became necessary due to the hard-to-understand way in which the old print inlining worked, which made it almost impossible to implement printing which methods are late inlines without losing previous print statements (see discussion below).
>> 
>> 
>> Here is a new example print output, showing different messages logged for the same location. In this case, a nice progression, from not being able to inline to late inline can be witnessed.
>> 
>> 
>> @ 18    java.lang.invoke.MethodHandle::invokeBasic()V (0 bytes)   failed to inline: receiver not constant    callee changed to java.lang.invoke.LambdaForm$DMH/0x000000012a403470::invokeStatic (17 bytes)  force inline by annotation   late inline succeeded (method handle)
>> 
>> 
>> Naturally, the output of print inlining changes with this PR, but I tried to keep the changes small.
>> 
>> ----
>> 
>> Original PR description before rewrite:
>> 
>> In https://github.com/openjdk/jdk/pull/16595 @caojoshua previously suggested changes to indicate which calls were inlined late, when printing inlines. This PR re-introduces the changes from the previously closed PR and fixes a minor issue where asserts were triggered.
>> 
>> Concerns were raised by @rwestrel in the previous PR:
>> 
>>> When InlineTree::ok_to_inline() is called, some diagnostic message is recorded for the call site. Do I understand right that with this patch, if the call is inlined late, then that message is dropped and replaced by a new "late inline.." message? If that's the case, isn't it the case that sometimes the InlineTree::ok_to_inline() has some useful information that's lost when late inlining happens?
>> 
>> As already pointed out in the PR by @caojoshua, this does not matter for string/methodhandle/vector/boxing late inlines, as they are [only performed if ok_to_inline() returns true](https://github.com/openjdk/jdk/blob/master/src/hotspot/share/opto/doCall.cpp#L189). This is also the only call to ok_to_inline().  
>> 
>> The only other location, where late inline call generators are created, are ca...
>
> Theo Weidmann has updated the pull request incrementally with one additional commit since the last revision:
> 
>   Address comments

I have few comments.

src/hotspot/share/nmt/nmtTreap.hpp line 70:

> 68:   public:
> 69:     TreapNode(const K& k, uint64_t p) : _priority(p), _key(k), _left(nullptr), _right(nullptr) {}
> 70: 

Why you need these changes in NMT?

src/hotspot/share/opto/bytecodeInfo.cpp line 150:

> 148:       C->inline_printer()
> 149:           ->record(callee_method, caller_jvms, InliningResult::SUCCESS)
> 150:           ->print("Inlined method with many throws (throws=%d):", callee_method->interpreter_throwout_count());

Can you split it into 2 statement: first to get outputStream and then print. With this long line is not clear what it does.

src/hotspot/share/opto/bytecodeInfo.cpp line 175:

> 173:       C->inline_printer()
> 174:           ->record(callee_method, caller_jvms, InliningResult::SUCCESS)
> 175:           ->print("Inlined frequent method (freq=%lf):", freq);

The same: split statement.

src/hotspot/share/opto/parse.hpp line 79:

> 77:                      ciMethod* caller_method,
> 78:                      JVMState* caller_jvms,
> 79:                      bool& should_delay, ciCallProfile& profile);

Indent is wrong.

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

PR Review: https://git.openjdk.org/jdk/pull/21899#pullrequestreview-2578889628
PR Review Comment: https://git.openjdk.org/jdk/pull/21899#discussion_r1932540675
PR Review Comment: https://git.openjdk.org/jdk/pull/21899#discussion_r1932537458
PR Review Comment: https://git.openjdk.org/jdk/pull/21899#discussion_r1932542902
PR Review Comment: https://git.openjdk.org/jdk/pull/21899#discussion_r1932550302