GC accidentally cleans valid megamorphic vtable inline caches

We got a report on the zgc-dev list about a large performance issue affecting ZGC:
https://mail.openjdk.java.net/pipermail/zgc-dev/2021-November/001086.html

One of the issues that the reporter identified was that we could get extremely long class unloading / unlinking times:

[17606.140s][info][gc,phases ] GC(719) Concurrent Process Non-Strong References 25781.928ms
[17610.181s][info][gc,stats ] Subphase: Concurrent Classes Unlink 14280.772 / 25769.511 1126.563 / 25769.511 217.882 / 68385.750 217.882 / 68385.750 ms

and while this were happening we got a huge number of ICBufferFull safepoints.

It turns out that we have a 10-year-old bug in the inline cache cleaning code. This code came in with the permgen removal. See how the original code only calls set_to_clean when ic_oop is non-null:

https://github.com/openjdk/jdk/commit/5c58d27aac7b291b879a7a3ff6f39fca25619103
---
        CompiledIC *ic = CompiledIC_at(iter.reloc());
        oop ic_oop = ic->cached_oop();
        if (ic_oop != NULL && !is_alive->do_object_b(ic_oop)) {
          // The only exception is compiledICHolder oops which may
          // yet be marked below. (We check this further below).
          if (ic_oop->is_compiledICHolder()) {
            compiledICHolderOop cichk_oop = compiledICHolderOop(ic_oop);
            if (is_alive->do_object_b(
                  cichk_oop->holder_method()->method_holder()) &&
                is_alive->do_object_b(cichk_oop->holder_klass())) {
              continue;
            }
          }
          ic->set_to_clean();
          assert(ic->cached_oop() == NULL,
                 "cached oop in IC should be cleared");
        }
      }
---

The rewritten code put the set_to_clean call in a different scope, causing the CompiledIC to also be cleaned when ic_oop is NULL:
---
        CompiledIC *ic = CompiledIC_at(iter.reloc());
        if (ic->is_icholder_call()) {
          // The only exception is compiledICHolder oops which may
          // yet be marked below. (We check this further below).
          CompiledICHolder* cichk_oop = ic->cached_icholder();
          if (cichk_oop->holder_method()->method_holder()->is_loader_alive(is_alive) &&
              cichk_oop->holder_klass()->is_loader_alive(is_alive)) {
              continue;
            }
        } else {
          Metadata* ic_oop = ic->cached_metadata();
          if (ic_oop != NULL) {
            if (ic_oop->is_klass()) {
              if (((Klass*)ic_oop)->is_loader_alive(is_alive)) {
                continue;
              }
            } else if (ic_oop->is_method()) {
              if (((Method*)ic_oop)->method_holder()->is_loader_alive(is_alive)) {
                continue;
              }
            } else {
              ShouldNotReachHere();
            }
          }
          }
          ic->set_to_clean();
      }
---

Note the weird indentation, which could be seen as a hint that this might be a dubious / accidental change.

To understand why this is causing the problems we are seeing it's good to start by reading:
https://wiki.openjdk.java.net/display/HotSpot/Overview+of+CompiledIC+and+CompiledStaticCall

When the GC hits this path and finds an ic_oop that is NULL, it means that it is dealing with an inline cache that is a megamorphic vtable call (or clean). Those should not be cleaned (at least that wasn't the intention of the old code).

But now we do clean them, and to do so we use an ICStub (to make a safe transition to the clean state), which uses up slots in the ICBuffer. When the ICBuffer is full, concurrent GCs have to stop and schedule an ICBufferFull safepoint stop-the-world operation, which removes the ICStub from the inline cache and completely frees up the ICBuffer. If the GC cleans a lot of these megamorphic vtable inline caches, then we'll create a large number of ICBufferFull safepoints.

But it is even worse than that. After the class unloading GCs have destroyed all megamorphic vtable inline caches, the Java threads will see these cleaned inline caches and correct them. Correcting the cleaned inline caches from the Java threads will also use ICStubs, and eventually the inline caches will transition back to be a megamorphic vtable calls. Because of this we can end up in a situation where the GC and Java threads change the inline cache back and forth between clean and megamorphic vtable calls. When this happen both GC and Java threads will continuously schedule ICBufferFull safepoints, and this can go on for many seconds, even minutes, if we are unlucky. For ZGC this has the effect that it blocks any further GC work, and eventually the Java threads will run out of memory and hit allocation stalls. The Java threads will then wait for the GC "clean" all inline caches and exit the class unloading phase and proceed to the phase where memory is reclaimed. You can see in the GC logs that even though the problematic unlinking phase goes on for many seconds, the allocation stalls are "only" a few hundred milliseconds. This shows that when the Java threads stop fighting over the inline caches, the GC can finish the work relatively quickly.

G1 performs the inline cache cleaning while the Java threads are stopped, and therefore don't have to use ICStubs when the megamorphic vtables are accidentally cleaned. So, G1 (and other stop-the-world class unloading GCs) won't enter the situation where the GC and Java thread concurrently fight over the inline caches. It still causes the Java threads to have to take a slow path and fix the inline caches, which can result in unnecessary ICBufferFull safepoints.

I been able to reproduce the issue where ZGC and the Java threads fight over the ICStubs, causing minute long unloading times, by running one of the microbenchmarks from the Blackbird library used by the reporter of this issue. See description in:
https://mail.openjdk.java.net/pipermail/zgc-dev/2021-November/001096.html

I think this could be reproduced in other workloads as well. I've also been able to reproduce the excessive ICBufferFull safepoints with Kitchensink (an oracle-internal stress test).

I've verified that restoring the set_to_clean code to the right scope fixes the issue that I can reproduce with both Blackbird and Kitchensink. After the fix, the class unloading times go back to normal levels.

To identify this issue, it's good to run with -Xlog:gc*,safepoint and take note of the "Concurrent Process Non-Strong References" times and ICBufferFull safepoint lines.

Example logs from ZGC where concurrent cleaning causes ICBufferFull safepoints:
---
[38.557s][1637062062666ms][info ][gc,phases ] GC(222) Concurrent Mark Free 0.001ms
[38.565s][1637062062673ms][info ][safepoint ] Safepoint "ICBufferFull", Time since last: 7389821 ns, Reaching safepoint: 167546 ns, At safepoint: 6840 ns, Total: 174386 ns
[38.565s][1637062062673ms][info ][safepoint ] Safepoint "ICBufferFull", Time since last: 27749 ns, Reaching safepoint: 89368 ns, At safepoint: 5710 ns, Total: 95078 ns
[38.566s][1637062062674ms][info ][safepoint ] Safepoint "ICBufferFull", Time since last: 678872 ns, Reaching safepoint: 145967 ns, At safepoint: 6969 ns, Total: 152936 ns
[38.567s][1637062062675ms][info ][safepoint ] Safepoint "ICBufferFull", Time since last: 934596 ns, Reaching safepoint: 165826 ns, At safepoint: 5460 ns, Total: 171286 ns
[38.567s][1637062062675ms][info ][safepoint ] Safepoint "ICBufferFull", Time since last: 16500 ns, Reaching safepoint: 91147 ns, At safepoint: 5770 ns, Total: 96917 ns
[38.568s][1637062062677ms][info ][safepoint ] Safepoint "ICBufferFull", Time since last: 1124041 ns, Reaching safepoint: 154426 ns, At safepoint: 6280 ns, Total: 160706 ns
[38.570s][1637062062678ms][info ][safepoint ] Safepoint "ICBufferFull", Time since last: 1222819 ns, Reaching safepoint: 152646 ns, At safepoint: 6920 ns, Total: 159566 ns
[38.571s][1637062062679ms][info ][safepoint ] Safepoint "ICBufferFull", Time since last: 1070303 ns, Reaching safepoint: 152686 ns, At safepoint: 6029 ns, Total: 158715 ns
[38.571s][1637062062679ms][info ][safepoint ] Safepoint "ICBufferFull", Time since last: 23650 ns, Reaching safepoint: 83208 ns, At safepoint: 6170 ns, Total: 89378 ns
[38.572s][1637062062681ms][info ][safepoint ] Safepoint "ICBufferFull", Time since last: 1005014 ns, Reaching safepoint: 148206 ns, At safepoint: 5660 ns, Total: 153866 ns
[38.572s][1637062062681ms][info ][safepoint ] Safepoint "ICBufferFull", Time since last: 15110 ns, Reaching safepoint: 84047 ns, At safepoint: 5690 ns, Total: 89737 ns
[38.574s][1637062062682ms][info ][safepoint ] Safepoint "ICBufferFull", Time since last: 1370755 ns, Reaching safepoint: 171876 ns, At safepoint: 5030 ns, Total: 176906 ns
[38.574s][1637062062682ms][info ][safepoint ] Safepoint "ICBufferFull", Time since last: 19749 ns, Reaching safepoint: 82478 ns, At safepoint: 4740 ns, Total: 87218 ns
[38.574s][1637062062682ms][info ][safepoint ] Safepoint "ICBufferFull", Time since last: 12480 ns, Reaching safepoint: 86707 ns, At safepoint: 5040 ns, Total: 91747 ns
[38.575s][1637062062684ms][info ][safepoint ] Safepoint "ICBufferFull", Time since last: 904007 ns, Reaching safepoint: 162666 ns, At safepoint: 5160 ns, Total: 167826 ns
[38.575s][1637062062684ms][info ][safepoint ] Safepoint "ICBufferFull", Time since last: 14269 ns, Reaching safepoint: 80878 ns, At safepoint: 5420 ns, Total: 86298 ns
[38.577s][1637062062685ms][info ][safepoint ] Safepoint "ICBufferFull", Time since last: 1240908 ns, Reaching safepoint: 144267 ns, At safepoint: 7030 ns, Total: 151297 ns
[38.578s][1637062062686ms][info ][safepoint ] Safepoint "ICBufferFull", Time since last: 971325 ns, Reaching safepoint: 175725 ns, At safepoint: 4710 ns, Total: 180435 ns
[38.578s][1637062062686ms][info ][safepoint ] Safepoint "ICBufferFull", Time since last: 16140 ns, Reaching safepoint: 80258 ns, At safepoint: 5389 ns, Total: 85647 ns
[38.578s][1637062062686ms][info ][safepoint ] Safepoint "ICBufferFull", Time since last: 10290 ns, Reaching safepoint: 80858 ns, At safepoint: 5530 ns, Total: 86388 ns
[38.579s][1637062062687ms][info ][safepoint ] Safepoint "ICBufferFull", Time since last: 430509 ns, Reaching safepoint: 159906 ns, At safepoint: 4610 ns, Total: 164516 ns
[38.579s][1637062062687ms][info ][safepoint ] Safepoint "ICBufferFull", Time since last: 18269 ns, Reaching safepoint: 83838 ns, At safepoint: 4520 ns, Total: 88358 ns
[38.579s][1637062062687ms][info ][safepoint ] Safepoint "ICBufferFull", Time since last: 13270 ns, Reaching safepoint: 77928 ns, At safepoint: 4790 ns, Total: 82718 ns
[38.579s][1637062062688ms][info ][safepoint ] Safepoint "ICBufferFull", Time since last: 384230 ns, Reaching safepoint: 193705 ns, At safepoint: 4080 ns, Total: 197785 ns
[38.579s][1637062062688ms][info ][safepoint ] Safepoint "ICBufferFull", Time since last: 14099 ns, Reaching safepoint: 80908 ns, At safepoint: 4840 ns, Total: 85748 ns
[38.580s][1637062062688ms][info ][safepoint ] Safepoint "ICBufferFull", Time since last: 9150 ns, Reaching safepoint: 79268 ns, At safepoint: 4890 ns, Total: 84158 ns
[38.580s][1637062062689ms][info ][safepoint ] Safepoint "ICBufferFull", Time since last: 549396 ns, Reaching safepoint: 143086 ns, At safepoint: 6430 ns, Total: 149516 ns
[38.580s][1637062062689ms][info ][safepoint ] Safepoint "ICBufferFull", Time since last: 12540 ns, Reaching safepoint: 94717 ns, At safepoint: 5800 ns, Total: 100517 ns
[38.581s][1637062062690ms][info ][safepoint ] Safepoint "ICBufferFull", Time since last: 847758 ns, Reaching safepoint: 146687 ns, At safepoint: 5969 ns, Total: 152656 ns
[38.582s][1637062062691ms][info ][safepoint ] Safepoint "ICBufferFull", Time since last: 972285 ns, Reaching safepoint: 128177 ns, At safepoint: 6350 ns, Total: 134527 ns
[38.584s][1637062062692ms][info ][safepoint ] Safepoint "ICBufferFull", Time since last: 986975 ns, Reaching safepoint: 136396 ns, At safepoint: 5770 ns, Total: 142166 ns
[38.584s][1637062062692ms][info ][safepoint ] Safepoint "ICBufferFull", Time since last: 17280 ns, Reaching safepoint: 87097 ns, At safepoint: 5270 ns, Total: 92367 ns
[38.585s][1637062062693ms][info ][safepoint ] Safepoint "ICBufferFull", Time since last: 1143131 ns, Reaching safepoint: 188315 ns, At safepoint: 5250 ns, Total: 193565 ns
[38.585s][1637062062694ms][info ][safepoint ] Safepoint "ICBufferFull", Time since last: 12200 ns, Reaching safepoint: 80168 ns, At safepoint: 7480 ns, Total: 87648 ns
[38.586s][1637062062695ms][info ][safepoint ] Safepoint "ICBufferFull", Time since last: 1153410 ns, Reaching safepoint: 166846 ns, At safepoint: 7060 ns, Total: 173906 ns
[38.587s][1637062062695ms][info ][safepoint ] Safepoint "ICBufferFull", Time since last: 21549 ns, Reaching safepoint: 89898 ns, At safepoint: 5360 ns, Total: 95258 ns
[38.588s][1637062062696ms][info ][safepoint ] Safepoint "ICBufferFull", Time since last: 1129411 ns, Reaching safepoint: 156726 ns, At safepoint: 4810 ns, Total: 161536 ns
[38.588s][1637062062696ms][info ][safepoint ] Safepoint "ICBufferFull", Time since last: 14089 ns, Reaching safepoint: 80588 ns, At safepoint: 5170 ns, Total: 85758 ns
[38.589s][1637062062697ms][info ][safepoint ] Safepoint "ICBufferFull", Time since last: 644824 ns, Reaching safepoint: 140666 ns, At safepoint: 5990 ns, Total: 146656 ns
[38.590s][1637062062699ms][info ][safepoint ] Safepoint "ICBufferFull", Time since last: 1085312 ns, Reaching safepoint: 254264 ns, At safepoint: 5440 ns, Total: 259704 ns
[38.590s][1637062062699ms][info ][safepoint ] Safepoint "ICBufferFull", Time since last: 14609 ns, Reaching safepoint: 83748 ns, At safepoint: 5610 ns, Total: 89358 ns
[38.591s][1637062062699ms][info ][safepoint ] Safepoint "ICBufferFull", Time since last: 387680 ns, Reaching safepoint: 201215 ns, At safepoint: 5340 ns, Total: 206555 ns
[38.591s][1637062062699ms][info ][safepoint ] Safepoint "ICBufferFull", Time since last: 18929 ns, Reaching safepoint: 85098 ns, At safepoint: 5910 ns, Total: 91008 ns
[38.591s][1637062062700ms][info ][safepoint ] Safepoint "ICBufferFull", Time since last: 380750 ns, Reaching safepoint: 175066 ns, At safepoint: 4730 ns, Total: 179796 ns
[38.592s][1637062062700ms][info ][safepoint ] Safepoint "ICBufferFull", Time since last: 14500 ns, Reaching safepoint: 80577 ns, At safepoint: 6790 ns, Total: 87367 ns
[38.592s][1637062062700ms][info ][safepoint ] Safepoint "ICBufferFull", Time since last: 14660 ns, Reaching safepoint: 78498 ns, At safepoint: 7180 ns, Total: 85678 ns
[38.592s][1637062062701ms][info ][safepoint ] Safepoint "ICBufferFull", Time since last: 655783 ns, Reaching safepoint: 141717 ns, At safepoint: 6089 ns, Total: 147806 ns
[38.594s][1637062062702ms][info ][safepoint ] Safepoint "ICBufferFull", Time since last: 916657 ns, Reaching safepoint: 144226 ns, At safepoint: 5360 ns, Total: 149586 ns
[38.595s][1637062062703ms][info ][safepoint ] Safepoint "ICBufferFull", Time since last: 1012334 ns, Reaching safepoint: 133037 ns, At safepoint: 10439 ns, Total: 143476 ns
[38.597s][1637062062705ms][info ][gc,phases ] GC(222) Concurrent Process Non-Strong References 39.443ms
---

Example logs from G1 where the Java threads fixes the cleaned inline caches and run out of ICStubs:
[125.998s][1637065197322ms][info ][gc ] GC(1040) Pause Remark 586M->414M(2048M) 6.609ms
[125.998s][1637065197322ms][info ][gc,cpu ] GC(1040) User=0.08s Sys=0.00s Real=0.01s
[125.998s][1637065197322ms][info ][safepoint ] Safepoint "G1Concurrent", Time since last: 33150646 ns, Reaching safepoint: 103457 ns, At safepoint: 6666988 ns, Total: 6770445 ns
[125.998s][1637065197322ms][info ][gc,marking ] GC(1040) Concurrent Mark 38.296ms
[125.998s][1637065197322ms][info ][gc,marking ] GC(1040) Concurrent Rebuild Remembered Sets
[126.001s][1637065197326ms][info ][safepoint ] Safepoint "ICBufferFull", Time since last: 2621782 ns, Reaching safepoint: 626684 ns, At safepoint: 9340 ns, Total: 636024 ns
[126.002s][1637065197326ms][info ][safepoint ] Safepoint "ICBufferFull", Time since last: 19949 ns, Reaching safepoint: 714022 ns, At safepoint: 12160 ns, Total: 726182 ns
[126.007s][1637065197331ms][info ][safepoint ] Safepoint "ICBufferFull", Time since last: 4665009 ns, Reaching safepoint: 339751 ns, At safepoint: 9640 ns, Total: 349391 ns
[126.009s][1637065197334ms][info ][safepoint ] Safepoint "ICBufferFull", Time since last: 2274802 ns, Reaching safepoint: 365760 ns, At safepoint: 9250 ns, Total: 375010 ns
[126.027s][1637065197352ms][info ][gc,marking ] GC(1040) Concurrent Rebuild Remembered Sets 29.618ms

I've tested the performance of the change with SPECjbb2015, SPECjvm2008, DaCapo, Renaissance.

I've tested run the patch through tier1-7.