Compiler deoptimization behaviour

[Andrew Haley]

On 06/12/2018 09:23 PM, David Griffiths wrote:
> I wrote a simple little test to better understand the compiler frame layout
> but it exhibits strange behaviour in that it starts off very fast and then
> slows to a million times slower. From running with -XX:+PrintCompilation I
> _think_ it is something to do with one of the bottom level methods getting
> deoptimized - this message appears just as the performance falls off the
> cliff:

Here's what happens.  If I run with PrintInlining I see:

  @ 21   TestFrames::add3 (31 bytes)   inline (hot)
    @ 21   TestFrames::add4 (31 bytes)   inline (hot)
      @ 21   TestFrames::add5 (32 bytes)   inline (hot)
        @ 22   TestFrames::add6 (32 bytes)   inline (hot)
          @ 22   TestFrames::add7 (32 bytes)   inline (hot)
            @ 22   TestFrames::add8 (32 bytes)   inline (hot)
              @ 22   TestFrames::add9 (32 bytes)   inline (hot)
                @ 22   TestFrames::add10 (32 bytes)   inline (hot)
                  @ 22   TestFrames::add11 (32 bytes)   inline (hot)
                    @ 22   TestFrames::add12 (32 bytes)   inline (hot)
                      @ 22   TestFrames::add13 (12 bytes)   inlining too deep

then


  @ 21   TestFrames::add5 (32 bytes)   inline (hot)
    @ 22   TestFrames::add6 (32 bytes)   inline (hot)
      @ 22   TestFrames::add7 (32 bytes)   inline (hot)
        @ 22   TestFrames::add8 (32 bytes)   inline (hot)
          @ 22   TestFrames::add9 (32 bytes)   inline (hot)
            @ 22   TestFrames::add10 (32 bytes)   inline (hot)
              @ 22   TestFrames::add11 (32 bytes)   inline (hot)
                @ 22   TestFrames::add12 (32 bytes)   inline (hot)
                  @ 22   TestFrames::add13 (12 bytes)   inline (hot)

then

  @ 21   TestFrames::add4 (31 bytes)   inline (hot)
     @ 21   TestFrames::add5 (32 bytes)   inline (hot)
       @ 22   TestFrames::add6 (32 bytes)   inline (hot)
         @ 22   TestFrames::add7 (32 bytes)   inline (hot)
           @ 22   TestFrames::add8 (32 bytes)   inline (hot)
             @ 22   TestFrames::add9 (32 bytes)   inline (hot)
               @ 22   TestFrames::add10 (32 bytes)   inline (hot)
                 @ 22   TestFrames::add11 (32 bytes)   inline (hot)
                   @ 22   TestFrames::add12 (32 bytes)   inline (hot)
                     @ 22   TestFrames::add13 (12 bytes)   inline (hot)

then

  @ 21   TestFrames::add2 (31 bytes)   inline (hot)
    @ 21   TestFrames::add3 (31 bytes)   inline (hot)
      @ 21   TestFrames::add4 (31 bytes)   inline (hot)
        @ 21   TestFrames::add5 (32 bytes)   inline (hot)
          @ 22   TestFrames::add6 (32 bytes)   inline (hot)
            @ 22   TestFrames::add7 (32 bytes)   inline (hot)
              @ 22   TestFrames::add8 (32 bytes)   inline (hot)
                @ 22   TestFrames::add9 (32 bytes)   inline (hot)
                  @ 22   TestFrames::add10 (32 bytes)   inline (hot)
                    @ 22   TestFrames::add11 (32 bytes)   inline (hot)
                      @ 22   TestFrames::add12 (32 bytes)   inlining too deep

... many, many times.  These are just a few.

The recompilation happens each time because counters in the outer
loops are triggered.

We end up with add[2-12] inlined in one method, calling out to add13.
Very unfortunately, this mega-inlined method has a lot of live
variables at the point of the call out to add12: every register is
occupied.  So, it dumps the entire register state onto the stack,
calls add12, which does a tiny bit of work and returns, then the
entire register state has to be restored, tra, la, la la.

It would be much better to ignore the counter overflows in the outer
loops and to inline the inner loops rather than the outer loops but we
aren't smart enough to do that.  Try  -XX:MaxInlineLevel=15.

-- 
Andrew Haley
Java Platform Lead Engineer
Red Hat UK Ltd. <https://www.redhat.com>
EAC8 43EB D3EF DB98 CC77 2FAD A5CD 6035 332F A671