openjdk

SIGILL on Startup: How the JDK AOT Cache Crashed Axelix in Docker Author: Artemiy Degtyarev Imagine you are deploying an open source Java application in Docker. You pull the image, run it, and before the first log line appears, the JVM dies with this: # A fatal error has been detected by the Java Runtime Environment: # # SIGILL (0x4) at pc=..., pid=1, tid=... # # Problematic frame: # v ~AdapterBlob That is exactly what happened to some users of Axelix when they started Axelix Master. SIGILL means illegal instruction: the CPU was asked to execute an instruction it does not support. That is not something you expect from a Java application. Java is supposed to be "write once, run anywhere", and bytecode does not contain CPU instructions. We investigated it, fixed it, and wrote this article about it. It is a good story about a new JVM feature, the AOT cache, and a small detail of its design that turned out to matter a lot for anyone who ships a pre-built Docker image. What we saw The bug was reported as #1744. The crash logs users sent us all pointed to the same frame, ~AdapterBlob. Only the illegal instruction differed: - On an ARM64 machine, the JVM crashed on ptrue p7.b. This is an SVE (Scalable Vector Extension) instruction, and SVE was missing from the CPU features listed in the crash log. - We also reproduced it ourselves on x86-64. We started Axelix 1.1.1 on an emulated CPU without AVX, and the JVM crashed on vzeroupper, which is an AVX instruction. So two different architectures crashed in the same place, both on a vector instruction the CPU did not have. As an immediate mitigation, we removed the AOT cache from the Master image. Axelix 1.2.0 shipped without it. Then we went to find out what was actually going on. To understand that, we first need to look at how the AOT cache works. What is the AOT cache? Every time a JVM starts, it does a lot of the same work again. It reads classes from JARs, parses and verifies bytecode, links classes, and runs static initializers. Then it runs the code in the interpreter for a while, collects profiles, and only after that can the JIT compiler produce well-optimized machine code. For a Spring Boot application with thousands of classes, this work is a large part of the startup time. Project Leyden aims to reuse that work between runs. Its first result is the AOT cache: - JEP 483 (JDK 24) — classes are stored in the cache already loaded and linked. - JEP 514 (JDK 25) — simpler command-line ergonomics. - JEP 515 (JDK 25) — method execution profiles are stored too, so the JIT can start optimizing earlier. Training run → collect data → create app.aot ↓ Next runs ← use the data from app.aot The three phases Working with the AOT cache has three phases: 1. Training. You run the application with a representative workload. The JVM records which classes were loaded and linked and how methods were executed. 2. Assembly. A separate JVM takes the recorded configuration and creates the cache file. 3. Production. Later runs start with -XX:AOTCache=... and use the prepared data instead of doing the work again. In a Dockerfile this is a natural multi-stage build. A simplified version of the Axelix Master Dockerfile looks like this: FROM eclipse-temurin:25-jre-alpine AS training WORKDIR /application COPY build/libs/master.jar master.jar # 1. Training: start the application up to the context refresh and record what it does RUN java -XX:AOTMode=record -XX:AOTConfiguration=app.aotconf \ -Dspring.context.exit=onRefresh \ -jar master.jar # 2. Assembly: create the cache from the recorded configuration RUN java -XX:AOTMode=create -XX:AOTConfiguration=app.aotconf -XX:AOTCache=app.aot \ -jar master.jar FROM eclipse-temurin:25-jre-alpine AS final WORKDIR /application COPY --from=training /application/master.jar /application/app.aot ./ # 3. Production ENTRYPOINT exec java -XX:AOTCache=app.aot -cp master.jar org.springframework.boot.loader.launch.JarLauncher -Dspring.context.exit=onRefresh is a Spring Framework feature made for this purpose: the application starts, refreshes the ApplicationContext, and exits. That is enough to warm up everything that matters for startup, and it does not need a database or the network. What is inside the cache? In JDK 25, one AOT cache file contains several kinds of data: - class metadata — classes that are already parsed, verified, and linked; - method profiles — execution statistics collected during training; - heap objects — some pre-built Java objects, for example the module graph; - the AOT code cache — real machine code. The first three are CPU-independent data structures. The last one is the source of our problem. AOTAdapterCaching To see what machine code ends up in the cache, we need to look a little deeper into HotSpot. When a method is called for the first time, the interpreter executes its bytecode. When the method becomes hot, the JIT compiles it into machine code. Interpreted and compiled code use different calling conventions. The interpreter passes arguments on its own stack, while compiled code passes them in registers, as defined by the platform ABI. So the JVM needs small pieces of glue code between them, called adapters: - i2c (interpreted-to-compiled) — used when an interpreted method calls a compiled one; - c2i (compiled-to-interpreted) — used when a compiled method calls a method that is still interpreted. Adapters are generated per method signature, and a large application needs thousands of them. Generating them at startup takes time, so JDK 25 added the AOTAdapterCaching option, which is on by default: the adapters are generated during the assembly phase and stored in the AOT cache as ready-to-run machine code. And here is the catch. Like any code that HotSpot generates, adapters are generated for the CPU the JVM is currently running on. If that CPU supports AVX-512, the adapter may use AVX-512 registers. If it supports SVE, the adapter may use SVE instructions. That code is correct on the build machine. On a machine without those features, the first call through such an adapter executes an instruction the CPU does not know, and the kernel sends SIGILL. Why the JVM didn't protect us The JVM does validate the AOT cache. When the production run starts, it checks the JDK build, the operating system, the CPU architecture (x64 vs aarch64), the classpath, the GC, compressed oops, and some other settings. If something does not match, the JVM, in the default -XX:AOTMode=auto, prints a warning and continues without the cache. The startup is slower, but nothing breaks. In JDK 25, however, the JVM did not check one thing: CPU features within the same architecture. "x64" covers both a modern server CPU with AVX-512 and an old laptop CPU without it. The cache was accepted, and the adapters inside it were used as they were. Now look at how our image was built. The release job runs on a GitHub-hosted runner and builds a multi-platform image: docker build --platform linux/amd64,linux/arm64 --file master-oss/Dockerfile ... - The amd64 variant is trained on whatever CPU the runner happens to have. GitHub runners are cloud VMs, and some of them have AVX-512. - The arm64 variant is trained under QEMU emulation (docker/setup-qemu-action), because the runner itself is x86. QEMU user-mode emulation emulates its max CPU model by default, which includes SVE. However, many real ARM64 CPUs that people run containers on have no SVE: Apple Silicon Macs, AWS Graviton2, and Ampere Altra. A multi-platform build runs the whole Dockerfile once per platform, so each variant of the image gets its own cache, and docker pull picks the variant that matches the host. The architecture always matched. The CPU features within it did not: our build machines had more of them than many of our users' machines. That is exactly the pattern that crashed. The upstream bug During the investigation we found adoptium/adoptium-support#1507, "Launching with AOT cache fatally crashes with SIGILL (0x4) depending on available CPU instructions". It was the same problem: a cache created on a Zen 5 CPU with AVX-512 crashed in ~AdapterBlob on a Zen 2 CPU without AVX-512. The reporter found it the same way we did: GitHub Actions runners sometimes have AVX-512 and sometimes do not. The issue was moved to OpenJDK as JDK-8388703. The response from the HotSpot developers was pragmatic. Adapters are the only AOT code in JDK 25 (stub caching is already off), and they do not improve performance much. So instead of backporting CPU checks, they decided to simply turn adapter caching off by default in JDK 25. That is the fix in JDK 25.0.5: // Disable adapters caching which requires CPU features matching checks // (implemented by JDK-8377507 and JDK-8381975) which we don't // have in this version of code. FLAG_SET_ERGO_IF_DEFAULT(AOTAdapterCaching, false); The proper fix lives in JDK 27: - JDK-8377507 — the CPU features of the assembly machine are stored in the AOT code cache; - JDK-8381975 — at startup the stored features must exactly match the current CPU. If they do not match, the JVM logs AOT Code Cache disabled: cpu features are incompatible, ignores only the machine code, and keeps using everything else in the AOT cache. That is how it should work: the worst case is a little less speed-up, never a crash. Our fix The fix is #1767. We brought the AOT cache back, but we create it without adapters: # Create AOT cache without CPU-specific adapters to avoid SIGILL on other CPUs RUN java \ -XX:+UnlockDiagnosticVMOptions \ -XX:-AOTAdapterCaching \ -XX:AOTMode=create \ -XX:AOTConfiguration=app.aotconf \ -XX:AOTCache=app.aot \ -jar /application/master.jar AOTAdapterCaching is a diagnostic flag, which is why -XX:+UnlockDiagnosticVMOptions is needed. With this flag, the cache contains no machine code at all, and the JVM confirms it on startup: [info][aot] Opened AOT cache app.aot. [info][aot,codecache,init] AOT Code Cache is empty [info][aot] Using AOT-linked classes: true (static archive: has aot-linked classes) What remains is class metadata, profiles, and heap objects, which are the same on any CPU of a given architecture. The adapters are generated at runtime, on the user's machine, for the user's CPU. And removing them does not remove the benefit. In a local check of the image built from the fixed Dockerfile, about 72% of the classes loaded during startup (10,933 of 15,201) came from the AOT cache, and the time to context refresh dropped from about 7.3 s to about 5.4 s on a developer laptop. We discussed the alternatives in the PR. The first idea was to wait for JDK 25.0.5 and keep adapter caching on. But 25.0.5 does not make adapters safe. It simply turns them off, so the result is the same as our flag. The second idea was to move to JDK 27, where the CPU check exists. Most people run Axelix Master in Docker or Kubernetes, so a new Java baseline would not affect them. But Spring Boot 4.1 officially supports Java up to 26, and Java 27 support is expected in Spring Boot 4.2. So we merged the explicit flag. It works on today's JDK 25 builds, and it stays correct after 25.0.5, where it simply matches the new default. What about JDK 27? Once Spring Boot 4.2 is out, we plan to move Axelix to JDK 27. There, turning AOTAdapterCaching back on is safe: on a CPU that does not match, the JVM drops the cached code instead of crashing. But "safe" is not the same as "useful". JDK 27 requires an exact match of CPU features. For an image built on a GitHub runner, or trained under QEMU, the chance that a user's CPU has exactly the same feature set is small. For most users the cached adapters would simply be thrown away. For a pre-built image to really benefit from AOT code, the JVM needs to generate it for a generic, portable CPU baseline. There is an open enhancement for that, JDK-8377630 "Restrict AOT code to a generic set of CPU features". Until it lands, the AOT cache in a distributed image is best seen as a cache of data, not of code. Takeaways - The JDK AOT cache is a real and easy startup win for Spring Boot applications in Docker. A multi-stage Dockerfile with a training stage is enough. - On JDK 25 before 25.0.5, if you build the cache on one machine and run it on another, create it with -XX:+UnlockDiagnosticVMOptions -XX:-AOTAdapterCaching. Otherwise your users' CPUs must have every feature your build machine had. CI runners and QEMU usually have more. - Multi-arch images get a separate cache per architecture automatically, because each platform runs its own training and assembly stages. - The JVM validates the AOT cache and falls back safely when something does not match. Machine code stored in the cache is the one exception before JDK 27. The fix will ship in the next Axelix release. If you are curious about the details, the whole story is in #1744 and #1767.

You heard of "Code doesn't work on Tuesday", get ready for "Code doesn't work the morning after a daylight savings time change" jdk#33760

Java 8 から上げたら G1 がメモリを解放しなくなった Java 8 から Java 11〜25 に上げると、GC を指定しないときに選ばれる GC（既定の GC）が Parallel から G1 に変わる。GC は使われなくなったオブジェクトのメモリを片付ける仕組みで、Parallel と G1 はその種類の名前だ。 この変化で、負荷のピークが過ぎてもコンテナのメモリ（cgroup の memory.current）が下がらなくなる。 同じプログラムに同じ負荷をかけ、ピークのあとにコンテナのメモリがどれだけ変わったかをバージョンごとに比べた1。 バージョン ピークのあとの変化 Java 8 −234.6〜−227.6MB Java 11 0.0〜+2.9MB Java 25 +2.3〜+2.7MB ここでは、JVM が OS から取ってあるヒープの量を確保量、それを減らして OS に返すことを縮めると呼ぶ。下がらない原因はメモリリークではなく、G1 が負荷の続くあいだ確保量を縮めないことにある。 ピークのあとも下がらないメモリがリークか既定の GC の振る舞いかは、すでに集めている JVM のメトリクスと GC ログで、本番に触らずに見分けられる。それでも下げたいときは、G1 に設定を足すか、GC を Parallel に戻す。 GC の仕組み ピークのあとにメモリが下がるかどうかは、GC が動いたかではなく、確保量を縮めたかで決まる。 片付けることと縮めること GC は使われなくなったオブジェクトを片付けて、ヒープの中に空きを作る。片付けで減るのは使用量、つまり確保量の中でオブジェクトが占めている量だ。空いた分を OS に返して確保量を縮めるかどうかは、片付けとは別に決まる。 GC が来るとき JVM はヒープを若い世代と古い世代に分けて使う。作られたオブジェクトの多くは若い世代に置かれ、その多くはそこで使われなくなる。若い世代が埋まると、若い世代だけを片付ける GC（young GC）が動く。オブジェクトを作り続けるあいだは若い世代が繰り返し埋まるので、young GC も繰り返し来る。 young GC を何度か生き延びたオブジェクトは、古い世代に移される。古い世代が埋まると、ヒープ全体を片付ける必要が出る。プログラムを止めてヒープ全体を片付ける GC を full GC と呼ぶ2。 2つの止め方 GC が片付けるあいだはプログラムが止まり、そのあいだに届いたリクエストは待たされる。GC の作りはこの止め方で分かれる。 まとめて止める 小分けに止める 片付け方 プログラムを止めて一度に片付ける 片付けを小分けにし、一部をプログラムと並行して進める 1回の停止 長い 短い プログラムが進められる処理の量（スループット） 大きい GC が CPU を使う分、少し下がる Oracle のガイドが勧める場面 1秒以上の停止を許せる スループットより応答時間が大事 GC Parallel G1 Parallel の名前は止めているあいだの片付けを複数のスレッドで並列に進めることから来ていて、Parallel がプログラムと並行して動くわけではない3。 停止を短く保つため、G1 はプログラムを止めずにヒープ全体の生きているオブジェクトを調べる処理（並行マーキング）を持つ。並行マーキングは最後に短い停止（Remark）を挟んで終わる。始まるのは、young GC の終わりに、古い世代の占有量がしきい値を超えたときだ4。 並行マーキングのあと、G1 は続く young GC で、若い世代と一緒に古い世代の一部も片付ける（mixed GC）。G1 が full GC をするのは、この片付けが追いつかずメモリが足りなくなったときに限られる5。 何が変わったか Java 8 からバージョンを上げたときに変わるのは、既定の GC と、確保量を縮めるきっかけだ。 バージョン 既定の GC 確保量を縮めるきっかけ Java 8 Parallel young GC（若い世代の分） Java 11 G1 full GC Java 12〜25 G1 full GC と、並行マーキングの終わり 既定の GC GC を指定しないとき、Java 8 は Parallel を、Java 9 からは G1 を選ぶ6。OpenJDK は G1 に替えた理由として、「多くの利用者には、スループットを最大にするより、GC の停止時間を抑えるほうが大事だ」を挙げた7。 縮めるきっかけ Java 8 の Parallel は young GC のたびに若い世代の大きさを決め直し、縮める8。負荷が続くあいだも young GC は来るので、縮めるきっかけも来る。 Java 11 の G1 が確保量を縮めるのは、full GC のあとだけだ9。G1 の full GC は片付けが追いつかないときに限られるので、このきっかけはほとんど来ない。 Java 12 からは、並行マーキングの終わりでも確保量を縮める10。ただし並行マーキングが始まるのは古い世代が埋まってきたときなので、作ったオブジェクトがすぐ使われなくなる負荷では、このきっかけも来ない11。 周期 GC Java 12 の変更（JEP 346）によると、G1 は full GC を極力避け、並行マーキングもヒープの占有量と、オブジェクトを作る速さからしか始めないので、外から促されない限りヒープを OS に返さないことが多い。 これは使った分だけ払うコンテナ環境で特に不利なので、Java 12 で、GC がしばらく起きていないときに G1 が自分から並行マーキングを始めて確保量を縮める仕組みが加わった12。これを周期 GC と呼ぶ。 G1 は決めた間隔ごとに直前の GC からの時間を見る。間隔以上たっていれば並行マーキングを始め、その終わりの Remark で縮める。たっていなければ飛ばす13。名前とは違い、間隔ごとに必ず GC するのではない。 たとえば間隔を 10 秒にしても、オブジェクトが作られ続けて young GC が 1 秒もたたずに次々起きていれば、直前の GC から 10 秒たつことがない。そのあいだ、周期 GC は一度も動かない。 間隔は G1PeriodicGCInterval にミリ秒で指定し、0 にすると周期 GC は動かない。既定値は 0 なので、指定しなければ動かない14。 周期 GC を付けたとき 周期 GC を付けると、負荷が続くあいだは飛ばされ、負荷が止んだあとに動いて確保量を縮める。 アクセスが急に増えて引いたあとの2つの状況を模して比べた15。 ピーク（5 秒） ピークのあと 負荷が続く アクセスが急に増える。毎秒 1000MB のオブジェクトを作る 普段のリクエストが来続ける。毎秒 200MB のオブジェクトを作り続ける 負荷が止む 同じ リクエストが来なくなる。何も作らない どちらも Java 25 に -XX:G1PeriodicGCInterval=10000 を付け、間隔を 10 秒にした。 負荷が続くあいだ ピークのあとも負荷が続くと、起動から 10 秒の判定で、GC ログに次の行が出る。この行は -Xlog:gc+periodic=debug を付けたときに出る。 [10.017s][debug][gc,periodic ] Last GC occurred 505ms before which is below threshold 10000ms. Skipping. 直前の GC が 505ms 前で、間隔の 10000ms に届かないので、周期 GC を飛ばしたという行だ13:1。 ピークのあとの 45 秒間に、判定は 5 回あり、5 回とも飛ばされて、周期 GC は一度も動かなかった。確保量もピークの終わりから最後まで変わらなかった。 負荷が止んだあと ピークのあとオブジェクトを作らないと、起動から 20 秒の判定で周期 GC が動いた。10 秒の判定の時点では、ピークの終わりの GC から 10 秒たっていなかった。まず、並行マーキングを始める young GC の行が出る。 [20.016s][info ][gc ] GC(46) Pause Young (Concurrent Start) (G1 Periodic Collection) 195M->37M(377M) 1.104ms (G1 Periodic Collection) が、周期 GC が始めた GC であることを示す。195M->37M は使用量の前と後で、括弧の 377M が確保量だ16。この young GC では、確保量は変わらない。 続く Remark の行では、括弧の確保量が 27M になる10:1。 [20.019s][info ][gc ] GC(47) Pause Remark 37M->7M(27M) 0.478ms JVM のメトリクスで見た確保量（MemoryPoolMXBean で取ったヒープのメモリプールの committed の合計）も、同じだけ下がった17。 計測した時点 確保量 周期 GC の直前 377.0〜432.0MB 周期 GC のあと 27.0〜30.0MB 冒頭で比べたコンテナのメモリ（memory.current、1 秒ごとに計測）も下がった。周期 GC の直前の計測で 393.9〜421.4MB だったのが、最後の計測では 53.8〜59.5MB になった。 自分の環境で見分ける すでに集めている JVM のメトリクスと GC ログを使う。GC ログは -Xlog:gc を付けて出る行で足りる。 選ばれた GC JVM のメトリクスでは、ヒープがいくつかの区画に分かれて見え、区画の名前は GC で決まる。この区画をメモリプールと呼ぶ18。 Micrometer なら jvm.memory.committed の id タグ、Prometheus の Java クライアントなら jvm_memory_pool_committed_bytes の pool ラベルに、プールの名前が入る19。名前を見れば、本番で選ばれた GC が分かる。 GC ヒープのメモリプール Parallel PS Eden Space、PS Survivor Space、PS Old Gen G1 G1 Eden Space、G1 Survivor Space、G1 Old Gen Parallel のプールなら、この記事の現象ではない。どちらでもなければ、「適用範囲」の節を見る。 リークかどうか 下がらないメモリを見ると、まずリークを疑う。リークなら、負荷が一定でも、生きているオブジェクトの量が時間とともに増え続ける20。この記事の現象なら、生きているオブジェクトは少ないまま、確保量だけが高い。 見分けるには、確保量と、GC のあとの使用量を比べる。確保量はヒープのプールの committed の合計で見る。使用量は GC ログの各 GC の行にある GC のあとの値で見る。プールの used は、Eden の分が GC のたびに上下するので、比べるのに向かない。 Java 11 で負荷が続いたとき、ピークのあと最初の young GC の行は次のとおりだった21。 [6.877s][info ][gc ] GC(27) Pause Young (Normal) (G1 Evacuation Pause) 679M->89M(989M) 1.773ms この行では、矢印のあとの 89M が GC のあとの使用量で、括弧の 989M が確保量だ。確保量の大半が空いていて、片付けは進んでいる。空いた分を OS に返していないだけだ。 生きているオブジェクトは GC のあとの使用量を超えないので、GC のあとの使用量が増えていなければ、リークは疑わなくてよい。 ただし young GC は若い世代しか片付けないので、古い世代にたまったゴミは、young GC のあとの使用量に残る。この値は、リークでなくても少しずつ増えることがある。 増えていたら、この記事の現象だけでは説明がつかない。古い世代まで片付ける GC（full GC か、並行マーキングのあとの mixed GC）のあとの値があればそれを見て、そこでも増え続けるか、そうした GC が来ていなければ、リークとして調べる20:1。 縮めるきっかけになる GC 次に、ピークのあとの GC ログで、確保量を縮めるきっかけになる GC の行を探す。行の名前は Java 11 と Java 25 で同じだ22。Java 11 でも Pause Remark は出るが、確保量は縮めない。 バージョン 縮めるきっかけになる GC の行 Java 11 Pause Full Java 12〜25 Pause Full、Pause Remark 並行マーキングが始まると、Pause Remark の前に Pause Young (Concurrent Start) の行も出る。どれも無ければ、縮めるきっかけは来ていない。Java 11 なら、ここで判断がつく。Java 12 以降なら、残るきっかけは周期 GC だ。 周期 GC が動いているか Java 12 以降で Pause Remark が無ければ、周期 GC も動いていない。周期 GC は並行マーキングを始めるので、動けば Pause Remark が出る。 動いていないのは、間隔を指定していないか、指定していても負荷が続いて判定のたびに飛ばされているかだ（「周期 GC を付けたとき」の節）。間隔は起動オプションのほか、動いている JVM にも jcmd で指定できる14:1。 次のすべてに当てはまれば、メモリが下がらないのはリークではなく、G1 が確保量を縮めるきっかけを得ていないためだ。 プールが G1 のもの GC のあとの使用量が増えていない ピークのあとに Pause Full が無く、Java 12 以降なら Pause Remark も無い 対策 リークではないと分かっても、メモリを下げたいときは、G1 のまま負荷が止んだときに縮めるきっかけを足すか、young GC のたびに縮める GC に戻す。 周期 GC を付ける Parallel に戻す オプション -XX:G1PeriodicGCInterval=<ミリ秒> -XX:+UseParallelGC 縮めるきっかけ GC が間隔より長く起きないとき young GC のたび 負荷が絶えないサーバーで 縮めない 縮める23 ピークのすぐあとに負荷が止むとき 縮める 縮めない24 Java 11 で 使えない25 使える 1回の停止 G1 のまま短い 長くなる どちらを取るかは「自分の環境で見分ける」で当てはまったことと、負荷が止む時間帯があるかで決まる。 当てはまったこと 負荷が止む時間帯がある 負荷が止む時間帯がない Java 11 で、Pause Full が出ていない Java 12 以降に上げて周期 GC を付けるか、Parallel に戻す Parallel に戻す Java 12 以降で、周期 GC を指定していない 周期 GC を付ける Parallel に戻す 周期 GC を指定しているが、Pause Remark が出ない 間隔を短くする Parallel に戻す 負荷が止む時間帯は、GC ログの各行の先頭の時刻で見る。GC と GC のあいだが長く空く時間帯があれば、そこで周期 GC が動ける。 周期 GC は間隔ごとの判定で、直前の GC から間隔以上たっていれば動く。判定は間隔ごとにしか来ないので、止んでから動くまでに最大で間隔の2倍かかる。間隔は止む時間帯の長さの半分より短くする13:2。 Parallel に戻すと、1回の停止は長くなる。どれだけ長くなるかはヒープの大きさと生きているオブジェクトの量で変わる。本番の前に、検証環境で -XX:+UseParallelGC を付けて同じ負荷をかけ、GC ログの各行の最後にある停止時間を G1 のときと比べる。 適用範囲 この記事の検証は 2GB・2 CPU のコンテナで、GC を指定せずに動かした。ヒープの確保量は上限を -Xmx で、起動したときの値を -Xms で決める。検証では -Xms を付けていない。負荷は、作ったオブジェクトがすぐ使われなくなるものだった。次の場合は、結論が当てはまらない。 場合 結論との違い 小さいコンテナ（CPU が1つ、またはメモリが 1792MB 未満） Java 8〜26 では Serial が選ばれる26。Parallel と G1 の話は当てはまらない -Xms を付けている -Xms は確保量の下限にもなり、G1 はこれより下に縮めない。-Xmx と同じ値なら、周期 GC を付けても下がらない27 Parallel で、ピークのあと GC が起きない Parallel は GC のときにしか縮めないので、下がらない24:1 オブジェクトが生き残り、古い世代が埋まっていく負荷 並行マーキングが始まり、Java 12 以降の G1 はその Remark で縮める。周期 GC を付けなくても下がる場合がある28 Java 26 G1 も Parallel も young GC のあとに縮める。周期 GC を付けなくても下がる場合がある29 Java 27 小さいコンテナでも G1 が選ばれる30 Serial が選ばれたかは、メモリプールの名前が Eden Space、Survivor Space、Tenured Gen になるか31、起動時の GC ログに次の行が出るかで分かる32。 [0.003s][info][gc ] Using Serial cgroup v2 のコンテナの上限を読めるのは、Java 15 以降と、8u372 以降、11.0.16 以降だ。それより前は、ホストの CPU とメモリで GC を選ぶ33。 脚注 GitHub Actions のランナーの上の Docker で、コンテナは 2GB・2 CPU、-Xmx1500m。5 秒のピーク（アクセスが急に増えたときを模して、毎秒 1000MB のオブジェクトを作った）のあと、45 秒、普段の負荷として毎秒 200MB のオブジェクトを作り続けた。各バージョン 3 回の範囲。スクリプトと結果は show-your-work と GitHub Actions の実行結果 にある。 ↩︎ Oracle の HotSpot Virtual Machine Garbage Collection Tuning Guide の Generations（Java 25）。 ↩︎ Oracle の同じガイド（Java 25）の The Parallel Collector、Garbage-First (G1) Garbage Collector、Available Collectors の Selecting a Collector。 ↩︎ Java 25 で、young GC の終わりに並行マーキングを始めるかを判定する箇所。 ↩︎ Oracle の同じガイド（Java 25）の Garbage-First (G1) Garbage Collector の Space-Reclamation Phase と、その後の Full GC の記述。 ↩︎ Java 8 を -XX:+PrintCommandLineFlags を付けて起動すると、JVM が出すフラグの行に -XX:+UseParallelGC が入る。Java 11 と Java 25 は GC ログの先頭に Using G1 の行（Java 11 では [0.004s][info ][gc ] Using G1）を出す。 ↩︎ JEP 248: Make G1 the Default Garbage Collector の Motivation。 ↩︎ Java 8 の Parallel はyoung GC のたびに若い世代の大きさを決め直す。 ↩︎ Java 11 の G1 は full GC の処理の中で確保量を見直す。 ↩︎ Remark で縮めるようにした変更は JDK-6490394（Java 12）。Java 25 では Remark の処理の中で確保量を見直す。 ↩︎ ↩︎ ピークのあとも毎秒 200MB のオブジェクトを作り続けたとき、Java 11、17、21、25 のどれでも、ピークのあとに並行マーキングは始まらなかった。 ↩︎ JEP 346: Promptly Return Unused Committed Memory from G1 の Motivation。 ↩︎ Java 25 の周期 GC の判定と、既定で並行マーキングを始める設定（G1PeriodicGCInvokesConcurrent）。 ↩︎ ↩︎ ↩︎ G1PeriodicGCInterval の定義。MANAGEABLE のフラグなので、動いている JVM でも変えられる。 ↩︎ ↩︎ 2GB・2 CPU のコンテナ、-Xmx1500m、GC は指定しない。負荷が続く回は、ピークのあと 45 秒、オブジェクトを作り続けた。GC ログは -Xlog:gc*、-Xlog:gc+periodic=debug で採った。確保量の表は周期 GC の直前の計測と、周期 GC のあとの最初の計測。 ↩︎ Oracle の GC チューニングガイド（Java 25）の Generations にある GC ログの読み方（"used before GC" -> "used after GC" ("heap size")）。 ↩︎ 同じ検証を 3 回流した。「〜」で示した値は 3 回の範囲。 ↩︎ プールの名前は G1 と Parallel のソースで決まっている。 ↩︎ どちらも MemoryPoolMXBean から値を取っている。Micrometer 1.13.0 の JvmMemoryMetrics、Prometheus の Java クライアント 1.3.1 の JvmMemoryMetrics。 ↩︎ Oracle の Troubleshooting Guide の Troubleshoot Memory Leaks（Java 25）。 ↩︎ ↩︎ ピークのあとも毎秒 200MB のオブジェクトを作り続けた条件で、ピークのあと最初の young GC の行。 ↩︎ Java 11 の Pause Full、Pause Young (Concurrent Start)、Pause Remark。Java 25 の Pause Full。Java 25 の残りの2つは、「周期 GC を付けたとき」の節のログに出ている。 ↩︎ Java 11 の Parallel もyoung GC のたびに若い世代の大きさを決め直す。Java 11 に -XX:+UseParallelGC を付けてピークのあとも毎秒 200MB のオブジェクトを作り続けると、確保量はピークの終わりの 369.0〜380.0MB から最後の計測で 103.5〜120.5MB に減り、コンテナのメモリ（memory.current）も 141.4〜145.5MB 下がった。 ↩︎ Parallel は Java 8 でも Java 11 でも、young GC の中で大きさを決め直す。 ↩︎ ↩︎ Java 11 で付けると、Unrecognized VM option 'G1PeriodicGCInterval=10000' を出して JVM が起動しない。周期 GC は Java 12 から。 ↩︎ CPU が2つ以上で、メモリが 2GB から 256MB を引いた量以上のときだけ、Java 9 以降は G1 を、Java 8 は Parallel を選ぶ。Java 8 の判定も同じ。 ↩︎ -Xms は、起動したときの確保量と下限（MinHeapSize）の両方を決める。G1 は MinHeapSize より下に縮めない。 ↩︎ G1 はyoung GC の終わりに古い世代の占有量を見て並行マーキングを始め、Remark で縮める。 ↩︎ Java 26 の G1（JDK-8238687）と Parallel（JDK-8338977）。 ↩︎ JEP 523。 ↩︎ Serial のメモリプール。 ↩︎ Java 25 で、コンテナのメモリだけを 1GB にしても、CPU だけを1つにしても、この行が出た。 ↩︎ cgroup v2 の上限を読む変更は Java 15 で入り、11.0.16 と 8u372 に移された。 ↩︎

@ethauvin Are you interested into testing it with an alternative loom scheduler? See pderop/looma using loom#227

@forked_franz @_karm @victorgao466305 confirmed. a fastdebug build hits this assert: github.com/openjdk/jdk8u/blob/b661ee6ff840d6922aa…

@forked_franz @_karm @victorgao466305 Clankers claim the problem is this narrow-casting and choose to believe it (in this very case): github.com/openjdk/jdk8u/blob/b661ee6ff840d6922aa… but the ~Rulers~ Lawyers of OpenJDK think clankers stink so...

"retired" を "retierd" と書くというしょうもない間違いをそっと直してくれるOpenJDKのSAチームが私は大好きです（そもそもそんなスペルミスすんな！）： jdk#33527

nginx upstream_connect_time comes in 1-second steps An nginx latency alert fires, yet the logs and metrics of the application server behind nginx can show the same requests finishing quickly. This happens when the application server stops entirely for a few seconds, for example during a full GC[^stop], and connections that arrive in the meantime are kept waiting. [^stop]: Ordinary GC pauses are not this long. The JVM's G1 collector has a default pause-time goal of 200 ms (G1Arguments::initialize() in JDK 25). Pauses of several seconds come from things like a full GC under heap pressure, which this article does not verify. sequenceDiagram participant N as nginx participant K as Application server's kernel participant U as Application server Note over U: Stopped by a full GC or similar N->>K: SYN (open a connection) Note over K: The accept queue is full, so the SYN is dropped The dropped SYN is resent every second and connects after the application server resumes. From nginx, these look like 200s that took about 1, 2, or 3 seconds to connect. The three lines below are from the nginx access log, which records $upstream_connect_time (the seconds nginx took to finish connecting to the application server) as uct. The columns are time, request ID, status, uct, $upstream_header_time (uht), $upstream_response_time (urt), and $request_time (rt). uht and urt are the seconds from when nginx starts connecting to the application server until it receives the start of the response, and until it has received the whole response. rt is the seconds from when nginx receives the request until it finishes sending the response. 1792402370.463 487aefe88a1328206a8e93c7c242399a 200 uct=1.002 uht=1.002 urt=1.002 rt=1.002 1792402370.464 cfdd11ceca67677e3601df796850a712 200 uct=2.067 uht=2.067 urt=2.067 rt=2.068 1792402371.040 dd774240d10448d9dc41bfcaaa7d8dfe 200 uct=3.054 uht=3.055 urt=3.055 rt=3.054 The application server receives the request ID that nginx assigned, and its log records time, request ID, and processing time in milliseconds. These are its lines for the same request IDs: 1792402370.463 487aefe88a1328206a8e93c7c242399a 0.092 1792402370.463 cfdd11ceca67677e3601df796850a712 0.104 1792402371.040 dd774240d10448d9dc41bfcaaa7d8dfe 0.084 Nearly all of the time went to connecting, and processing on the application server took about 0.1 ms. The application server starts timing only after it takes the connection off the queue, so the wait to connect does not appear in its logs or metrics. The logs above were taken from an application server that receives 200 requests per second, stopped for 3 seconds[^run]. [^run]: The results are here, and the code is in show-your-work. It ran on GitHub Actions ubuntu-24.04 (x86_64, kernel 6.17) with Docker 28.0.4. What is happening When the application server stops, the accept queue fills up. SYNs that arrive after that are dropped, and connections are made through retransmissions by the nginx-side kernel. The accept queue The kernel carries out the exchange that sets up a TCP connection (the handshake). The connecting side sends a SYN to request a connection, the receiving side replies with a SYN-ACK to accept it, and the handshake completes when the connecting side sends an ACK. A completed connection waits in the kernel's accept queue until the server process takes it with the accept system call. Even while the application server is stopped, the kernel on its side keeps completing handshakes and queuing the connections. Nothing takes connections off the queue during the stop, so the queue fills up. sequenceDiagram participant N as nginx participant NK as nginx-side kernel participant UK as Application server's kernel participant U as Application server Note over U: Stopped N->>NK: Connect to the application server NK->>UK: SYN UK-->>NK: SYN-ACK NK->>UK: ACK NK-->>N: Connected Note over UK: Puts the connection in the accept queue Note over U: On resuming, takes connections off the queue in order The maximum number of connections the queue can hold is the backlog. The application server passes the backlog to the kernel when it starts listening for connections (when it calls listen). The value comes from the runtime's or framework's default, or from configuration. SYNs are dropped when the queue is full When the number of connections in the queue exceeds the backlog, the application server's kernel drops newly arriving SYNs without replying[^drop]. [^drop]: In the Linux 6.17 source, tcp_conn_request() drops the SYN when the queue is full. sk_acceptq_is_full() decides whether it is full, and treats the queue as full when the number of connections in it is greater than (>) the backlog. Retransmissions get through When a SYN gets no reply, the nginx-side kernel waits and sends it again. This is SYN retransmission. If the nginx-side kernel is Linux 6.5 or later, the first few retransmissions go out at 1-second intervals[^linear]. [^linear]: The number of retransmissions sent at 1-second intervals is set by net.ipv4.tcp_syn_linear_timeouts (default 4; see the Linux 6.17 documentation). Retransmitted SYNs are dropped too while the queue is full. Once the application server resumes and the queue has room, the next retransmission gets a SYN-ACK and the connection is made. Depending on which retransmission gets through, $upstream_connect_time is about 1, 2, or 3 seconds. The three log lines at the top are these cases. sequenceDiagram participant N as nginx participant NK as nginx-side kernel participant UK as Application server's kernel participant U as Application server Note over U: Stopped Note over UK: The accept queue is full N->>NK: Connect to the application server NK->>UK: SYN Note over UK: Drops it without replying loop Every second while the queue is full NK->>UK: Resend the SYN Note over UK: Drops it again end Note over U: Resumes and takes connections off the queue NK->>UK: Next retransmission UK-->>NK: SYN-ACK NK->>UK: ACK NK-->>N: Connected ($upstream_connect_time is about 1, 2, or 3 seconds) Verification I stopped the application server for 3 seconds to confirm this sequence. Requests that arrived during the stop split into those that connected immediately and those that connected after waiting about 1, 2, or 3 seconds. Setup nginx and the application server ran as containers on the same Docker network, and nginx was sent 200 requests per second for 15 seconds. Five seconds in, the application server process was stopped from outside with SIGSTOP, then resumed with SIGCONT 3 seconds later. This mimics a full GC stopping the whole process. - nginx is 1.30.6, with a single application server in the upstream block. proxy_connect_timeout (how long nginx waits to finish connecting to the application server) is left at its default of 60 seconds - The application server is an HTTP server that returns 200 immediately for every request, and listens with a backlog of 100 Time to connect In the 3 seconds between the stop and the resume, 600 requests reached nginx, and all of them returned 200. The counts by $upstream_connect_time are: | $upstream_connect_time | Requests | |---|---| | 0 seconds (connected immediately) | 102 | | About 1 second | 204 | | About 2 seconds | 205 | | About 3 seconds | 89 | This holds beyond the three lines at the top: for all 600 requests, the processing time in the application server's log was under 1 ms. Which row a request falls into depends on when it arrived. The queue was full about 0.5 seconds after the stop. Connections that arrived before that went into the queue and connected immediately. Connections that arrived later had their SYNs dropped, the nginx-side kernel resent them every second, and they connected on the first retransmission after the application server resumed. The earlier a connection arrived, the more times its SYN was resent and the longer it waited. Spotting it in your own logs To tell whether the accept queue overflowed, match the nginx access log against the application server's log. The access log shows that SYNs were dropped and the connections were made by retransmission. The application server's log shows that the application server was stopped. Access log In the access log, look at $upstream_connect_time on the 200 lines from when the alert fired. If the values cluster around 1, 2, and 3 seconds, SYNs were dropped and the connections were made by retransmission. $upstream_connect_time is not part of the default combined format, so add it with log_format[^log-format]. The verification used this format: log_format lab '$msec $request_id $status uct=$upstream_connect_time uht=$upstream_header_time urt=$upstream_response_time rt=$request_time'; [^log-format]: Adding variables with log_format is covered in nginx request_time is fast, but users say it's slow. Application server log In the application server's log, find the lines with the same IDs as the requests whose $upstream_connect_time came in 1-second steps, and look at how the lines are spaced around that time. If those requests finished quickly and the lines stop for a while around that time, the application server was stopped. The lines after the gap are bunched at the time it resumed. To match the two logs, pass the ID that nginx assigns to each request ($request_id) to the application server. On the nginx side, this takes one line: proxy_set_header X-Request-Id $request_id; On the application server side, its access log needs to be configured to include the received X-Request-Id header. Fix If the application server's backlog is set larger than the number of requests that arrive during a stop (requests per second × seconds stopped), the queue does not overflow[^somaxconn]. With a backlog of 4096, the 200s of about 1, 2, and 3 seconds no longer appear. The default backlogs of JVM servers, which can stop for a full GC, are: - Tomcat and Spring Boot: 100[^bl-tomcat] - Jetty: 50[^bl-jetty] [^somaxconn]: To go above 4096, also raise net.core.somaxconn in the application server's kernel. The kernel caps the backlog at somaxconn (__sys_listen_socket() in Linux 6.17), and its default is 4096 (preinit_net_sysctl(), documentation). [^bl-tomcat]: The Tomcat 11 documentation on HTTP connector configuration, and TomcatServerProperties in the Spring Boot 4.1.1 source. [^bl-jetty]: Jetty passes 0, and the JDK replaces it with 50. The default is 0 in ServerConnector in the Jetty 12.1.14 source, and ServerSocketChannelImpl in the JDK 25 source turns any value below 1 into 50. Even without an overflow, requests that arrive during a stop wait in the queue until the application server resumes. That wait shows up in $upstream_header_time, so 200s slowed by the length of the stop remain. How this varies by environment With a shortened connect timeout If proxy_connect_timeout is shorter than the stop, nginx gives up on connections whose retransmissions have not gotten through in time and returns 504. When the stop is not 3 seconds A stop of a different length should change the values $upstream_connect_time clusters around. This article tests a 3-second stop. Kernels older than 6.5 If the nginx-side kernel is older than 6.5, $upstream_connect_time clusters around 1 and 3 seconds, and about 2 seconds does not appear. This is because the retransmission interval doubles each time: after 1 second, then 2 seconds after that, then 4 seconds after that. The stock kernel of Ubuntu 24.04 (6.8) is 6.5 or later. Those of Ubuntu 22.04 (5.15), Debian 12 (6.1), and RHEL 9 (5.14) are older. Whether a distribution has backported this change into its own kernel has not been checked. With a proxy in front of the application server If a proxy that accepts connections first sits between nginx and the application server (Docker's userland-proxy, which handles published ports, or a sidecar proxy), that proxy answers the SYNs from nginx. Even if the application server's queue overflows, no retransmissions happen on the nginx side, so the method in this article should not apply. This article does not verify this case.

nginxのupstream_connect_timeが1秒刻みになる nginx 側のレイテンシのアラートが鳴ったのに、nginx の後ろのアプリケーションサーバーのログやメトリクスでは、同じリクエストが速く終わっていることがある。アプリケーションサーバーが full GC などでプロセスごと数秒止まり1、その間に届いた接続が待たされると、こうなる。 捨てられた SYN は 1 秒ごとに送り直され、アプリケーションサーバーが動き出したあとにつながる。nginx からは、接続を張るのに約 1 秒、約 2 秒、約 3 秒かかった 200 に見える。下の3行は nginx のアクセスログで、$upstream_connect_time（nginx がアプリケーションサーバーへの接続を張り終えるまでにかかった秒数）を uct として出している。列は時刻、リクエスト ID、ステータス、uct、$upstream_header_time（uht）、$upstream_response_time（urt）、$request_time（rt）の順に並ぶ。uht と urt は、nginx がアプリケーションサーバーにつなぎ始めてから、応答の先頭を受け取るまでと、応答を受け取り終えるまでの秒数だ。rt は、nginx がリクエストを受けてから応答を返し終えるまでの秒数だ。 1792402370.463 487aefe88a1328206a8e93c7c242399a 200 uct=1.002 uht=1.002 urt=1.002 rt=1.002 1792402370.464 cfdd11ceca67677e3601df796850a712 200 uct=2.067 uht=2.067 urt=2.067 rt=2.068 1792402371.040 dd774240d10448d9dc41bfcaaa7d8dfe 200 uct=3.054 uht=3.055 urt=3.055 rt=3.054 アプリケーションサーバーには、nginx が付けたリクエスト ID を渡し、ログに時刻、リクエスト ID、処理時間（ミリ秒）の順に出している。上の3行と同じリクエスト ID の行は次のとおりだ。 1792402370.463 487aefe88a1328206a8e93c7c242399a 0.092 1792402370.463 cfdd11ceca67677e3601df796850a712 0.104 1792402371.040 dd774240d10448d9dc41bfcaaa7d8dfe 0.084 かかった時間のほとんどが接続を張るまでの時間で、アプリケーションサーバーでの処理は 0.1 ミリ秒ほどだ。アプリケーションサーバーが時間を測り始めるのは接続を取り出したあとなので、接続を張るまでの待ちは、そのログやメトリクスに出ない。 上のログは毎秒 200 件を受けるアプリケーションサーバーを 3 秒止めて取ったものだ2。 何が起きているか アプリケーションサーバーが止まると accept キューが埋まり、そのあと届いた SYN は捨てられ、nginx 側のカーネルの再送でつながる。 accept キュー TCP の接続を張るやりとり（ハンドシェイク）は、カーネルが行う。接続を張る側が接続を求める SYN を送り、受ける側が受け入れの返事の SYN-ACK を返し、張る側が ACK を返すと、ハンドシェイクが終わる。終わった接続は、サーバーのプロセスが accept というシステムコールで取り出すまで、カーネルの accept キューに並んで待つ。 アプリケーションサーバーが止まっていても、アプリケーションサーバー側のカーネルはハンドシェイクを進め、終わった接続をキューに積む。止まっている間は接続が取り出されないので、キューは埋まっていく。 キューに並べられる接続の数の上限が backlog で、アプリケーションサーバーが接続を待ち受けるとき（listen するとき）に backlog をカーネルに渡す。値はランタイムやフレームワークの既定値か設定で決まる。 満杯なら SYN を捨てる キューにある接続の数が backlog を超えると、アプリケーションサーバー側のカーネルは、新しく届いた SYN を返事をせずに捨てる3。 再送でつながる SYN に返事がないと、nginx 側のカーネルは時間をおいて SYN を送り直す。これを SYN の再送と呼ぶ。nginx 側のカーネルが Linux 6.5 以降なら、最初の数回を 1 秒間隔で送り直す4。 送り直した SYN も、キューが満杯のうちは捨てられる。アプリケーションサーバーが動き出してキューが空くと、その次の再送で SYN-ACK が返り、つながる。何回目の再送でつながったかで、$upstream_connect_time は約 1 秒、約 2 秒、約 3 秒になる。冒頭の3行がこれにあたる。 検証 アプリケーションサーバーを 3 秒止めて、この流れを確かめた。止まっている間に届いたリクエストは、すぐつながったものと、約 1 秒、約 2 秒、約 3 秒待ってつながったものに分かれた。 構成 nginx とアプリケーションサーバーを同じ Docker ネットワークのコンテナで動かし、nginx に毎秒 200 件のリクエストを 15 秒送った。送り始めて 5 秒後に、アプリケーションサーバーのプロセスに外から SIGSTOP を送って止め、3 秒後に SIGCONT で再開させた。full GC でプロセス全体が止まる状態を模している。 nginx は 1.30.6 で、upstream ブロックにアプリケーションサーバーを 1 台置いた。proxy_connect_timeout（nginx がアプリケーションサーバーへの接続を張り終えるのを待つ上限）は既定の 60 秒のまま アプリケーションサーバーは受けたリクエストにすぐ 200 を返す HTTP サーバーで、backlog 100 で listen する 接続にかかった時間 止めてから再開させるまでの 3 秒に nginx に届いたリクエストは 600 件で、すべて 200 だった。$upstream_connect_time ごとの件数は次のとおりだ。 $upstream_connect_time 件数 0 秒（すぐつながった） 102 件 約 1 秒 204 件 約 2 秒 205 件 約 3 秒 89 件 冒頭の3行に限らず、600 件とも、アプリケーションサーバーのログの処理時間は 1 ミリ秒未満だった。 表のどの値に入るかは、届いた時刻で決まる。止めてから 0.5 秒ほどでキューが満杯になり、それより前に届いた接続はキューに入って、すぐつながった。それより後に届いた接続は SYN を捨てられ、nginx 側のカーネルが 1 秒ごとに送り直して、アプリケーションサーバーが動き出したあとの次の再送でつながった。早く届いた接続ほど、送り直した回数が多く、待ちが長い。 自分のログで見分ける accept キューが溢れたかどうかは、nginx のアクセスログとアプリケーションサーバーのログを突き合わせて見分ける。アクセスログで SYN が捨てられて再送でつながったと分かり、アプリケーションサーバーのログで、アプリケーションサーバーが止まっていたと分かる。 アクセスログ アクセスログでは、アラートが鳴った時間帯の 200 の行の $upstream_connect_time を見る。値が約 1 秒、約 2 秒、約 3 秒に固まっていれば、SYN が捨てられ、再送でつながっている。 $upstream_connect_time は既定の combined 形式に入らないので、log_format に足す5。検証では次の形式を使った。 log_format lab '$msec $request_id $status uct=$upstream_connect_time uht=$upstream_header_time urt=$upstream_response_time rt=$request_time'; アプリケーションサーバーのログ アプリケーションサーバーのログでは、アクセスログで $upstream_connect_time が 1 秒刻みの値になったリクエストと同じ ID の行と、その時間帯の行の並びを見る。同じ ID のリクエストが速く終わり、その時間帯に行が途切れていれば、アプリケーションサーバーは止まっていた。途切れたあとの行は、動き出した時刻にまとまって並ぶ。 突き合わせるには、nginx がリクエストごとに付ける ID（$request_id）をアプリケーションサーバーに渡す。nginx の側は次の1行で渡せる。 proxy_set_header X-Request-Id $request_id; アプリケーションサーバーの側では受け取った X-Request-Id ヘッダをアクセスログに出す設定が要る。 対策 アプリケーションサーバーの backlog の設定を、止まっている間に届く件数（毎秒の件数 × 止まる秒数）より大きくすれば、溢れは起きない6。backlog を 4096 にすると、約 1 秒、約 2 秒、約 3 秒の 200 は出なくなる。 full GC で止まることのある JVM のサーバーの既定の backlog は、次のとおりだ。 Tomcat と Spring Boot：1007 Jetty：508 止まっている間に届いたリクエストは、溢れなくても、アプリケーションサーバーが動き出すまでキューで待たされる。この待ちは $upstream_header_time に出て、止まった時間の分だけ遅い 200 は残る。 環境による違い 接続のタイムアウトを縮めているとき proxy_connect_timeout を止まる時間より短くしていると、再送を待ちきれなかった接続は、nginx が打ち切って 504 を返す。 止まる時間が 3 秒でないとき 止まる時間が違えば、$upstream_connect_time が固まる値も変わるはずだ。この記事では 3 秒止めた場合を確かめている。 6.5 より前のカーネル nginx 側のカーネルが 6.5 より前だと、$upstream_connect_time は約 1 秒と約 3 秒に固まり、約 2 秒は出ない。再送の間隔が 1 秒後、その 2 秒後、その 4 秒後と倍々に伸びるからだ。 Ubuntu 24.04 の標準のカーネル（6.8）は 6.5 以降、Ubuntu 22.04（5.15）、Debian 12（6.1）、RHEL 9（5.14）は 6.5 より前だ。ディストリビューションがこの変更を自分のカーネルに取り込んでいるかは確かめていない。 アプリケーションサーバーの前にプロキシがあるとき nginx とアプリケーションサーバーの間に、先に接続を受けるプロキシ（Docker の公開ポートを受ける userland-proxy、サイドカーのプロキシ）があると、nginx からの SYN にはそのプロキシが返事をする。アプリケーションサーバーのキューが溢れても nginx 側では再送が起きないので、この記事の見分け方は使えないはずだ。この記事では確かめていない。 脚注 普段の GC ではここまで止まらない。JVM の G1 は停止時間の目標が既定で 200ms だ（JDK 25 の G1Arguments::initialize()）。秒単位で止まるのは、ヒープが逼迫したときの full GC などで、この記事では確かめていない。 ↩︎ 検証結果はこちら、コードは show-your-work にある。GitHub Actions の ubuntu-24.04（x86_64、カーネル 6.17）で、Docker 28.0.4 を使った。 ↩︎ Linux 6.17 のソースの tcp_conn_request() で、キューが満杯なら SYN を捨てている。満杯かどうかは sk_acceptq_is_full() が決め、キューにある接続の数が backlog より大きい（>）ときに満杯とする。 ↩︎ 1 秒間隔で送り直す回数は net.ipv4.tcp_syn_linear_timeouts（既定 4）で決まる（Linux 6.17 の文書）。 ↩︎ log_format の足し方は nginxのrequest_timeは速いのにユーザーは遅いと言うで扱った。 ↩︎ 4096 より大きくするときは、アプリケーションサーバー側のカーネルの net.core.somaxconn も上げる。カーネルは backlog を somaxconn までに切り詰め（Linux 6.17 の __sys_listen_socket()）、その既定は 4096 だ（preinit_net_sysctl()、文書）。 ↩︎ Tomcat 11 の文書の HTTP コネクタの設定と、Spring Boot 4.1.1 のソースの TomcatServerProperties。 ↩︎ Jetty は 0 を渡し、JDK が 50 に置き換える。Jetty 12.1.14 のソースの ServerConnector で既定が 0、JDK 25 のソースの ServerSocketChannelImpl で 1 未満を 50 にしている。 ↩︎

SIGILL при старте: как AOT-кэш JDK уронил Axelix в Docker Введение Представьте, что вы разворачиваете open source Java-приложение в Docker. Вы скачиваете образ, запускаете его, и ещё до первой строчки лога JVM падает вот с таким сообщением: A fatal error has been detected by the Java Runtime Environment: # SIGILL (0x4) at pc=..., pid=1, tid=... # Problematic frame: v ~AdapterBlob sourcecraft.dev Именно это произошло у некоторых пользователей Axelix при запуске Axelix Master. SIGILL означает illegal instruction (недопустимая инструкция): процессор получил команду выполнить инструкцию, которую он не поддерживает. От Java-приложения такого не ждёшь. Java должна следовать принципу «write once, run anywhere», а байткод не содержит процессорных инструкций. Мы разобрались в проблеме, исправили её и написали об этом статью. Это хорошая история о новой возможности JVM, AOT-кэше, и о небольшой детали его устройства, которая оказалась очень важной для всех, кто распространяет заранее собранный Docker-образ. Что мы увидели Баг был заведён как #1744. Все крэш-логи, которые нам прислали пользователи, указывали на один и тот же фрейм, ~AdapterBlob. Отличалась только недопустимая инструкция: На машине с ARM64 JVM падала на ptrue p7.b. Это инструкция SVE (Scalable Vector Extension), а SVE отсутствовал в списке возможностей процессора в крэш-логе. Мы также воспроизвели проблему сами на x86-64. Мы запустили Axelix 1.1.1 на эмулируемом процессоре без AVX, и JVM упала на vzeroupper, это инструкция AVX. Итак, две разные архитектуры падали в одном и том же месте, и оба раза на векторной инструкции, которой у процессора не было. В качестве срочной меры мы убрали AOT-кэш из образа Master. Axelix 1.2.0 вышел без него. А затем мы пошли выяснять, что на самом деле происходит. Чтобы в этом разобраться, сначала нужно посмотреть, как работает AOT-кэш. Что такое AOT-кэш? При каждом запуске JVM заново выполняет много одной и той же работы. Она читает классы из JAR-файлов, разбирает и верифицирует байткод, линкует классы и выполняет статические инициализаторы. Затем какое-то время исполняет код в интерпретаторе, собирает профили, и только после этого JIT-компилятор может выдать хорошо оптимизированный машинный код. Для Spring Boot-приложения с тысячами классов эта работа составляет значительную часть времени старта. Project Leyden ставит целью переиспользовать эту работу между запусками. Его первый результат: AOT-кэш: JEP 483 (JDK 24) — классы хранятся в кэше уже загруженными и слинкованными. JEP 514 (JDK 25) — упрощённые параметры командной строки. JEP 515 (JDK 25) — в кэше также хранятся профили исполнения методов, поэтому JIT может начать оптимизацию раньше. Тренировочный запуск → сбор данных → создание app.aot ↓ Следующие запуски ← используют данные из app.aot sourcecraft.dev Три фазы Работа с AOT-кэшем состоит из трёх фаз: Тренировка (training). Вы запускаете приложение с репрезентативной нагрузкой. JVM записывает, какие классы были загружены и слинкованы и как исполнялись методы. Сборка (assembly). Отдельная JVM берёт записанную конфигурацию и создаёт файл кэша. Продакшн (production). Последующие запуски стартуют с -XX:AOTCache=... и используют подготовленные данные вместо того, чтобы снова проделывать всю работу. В Dockerfile это естественным образом ложится на multi-stage сборку. Упрощённая версия Dockerfile для Axelix Master выглядит так: FROM eclipse-temurin:25-jre-alpine AS training WORKDIR /application COPY build/libs/master.jar master.jar 1. Тренировка: запускаем приложение до обновления контекста и записываем, что оно делает RUN java -XX:AOTMode=record -XX:AOTConfiguration=app.aotconf \ -Dspring.context.exit=onRefresh \ -jar master.jar 2. Сборка: создаём кэш из записанной конфигурации RUN java -XX:AOTMode=create -XX:AOTConfiguration=app.aotconf -XX:AOTCache=app.aot \ -jar master.jar FROM eclipse-temurin:25-jre-alpine AS final WORKDIR /application COPY --from=training /application/master.jar /application/app.aot ./ 3. Продакшн ENTRYPOINT exec java -XX:AOTCache=app.aot -cp master.jar org.springframework.boot.loader.launch.JarLauncher sourcecraft.dev -Dspring.context.exit=onRefresh это возможность Spring Framework, созданная как раз для этой цели: приложение стартует, обновляет ApplicationContext и завершается. Этого достаточно, чтобы «прогреть» всё, что важно для старта, и при этом не нужны ни база данных, ни сеть. Что лежит внутри кэша? В JDK 25 один файл AOT-кэша содержит несколько видов данных: метаданные классов — классы, которые уже разобраны, верифицированы и слинкованы; профили методов — статистика исполнения, собранная во время тренировки; объекты кучи — некоторые заранее построенные Java-объекты, например граф модулей; кэш AOT-кода — настоящий машинный код. Первые три являются структурами данных, не зависящими от процессора. Последний является источником нашей проблемы. AOTAdapterCaching Чтобы понять, какой машинный код попадает в кэш, нужно заглянуть в HotSpot чуть глубже. Когда метод вызывается впервые, интерпретатор исполняет его байткод. Когда метод становится «горячим», JIT компилирует его в машинный код. Интерпретируемый и скомпилированный код используют разные соглашения о вызовах. Интерпретатор передаёт аргументы через собственный стек, а скомпилированный код передаёт их через регистры, как того требует ABI платформы. Поэтому JVM нужны небольшие фрагменты связующего кода между ними, которые называются адаптерами: i2c (interpreted-to-compiled) — используется, когда интерпретируемый метод вызывает скомпилированный; c2i (compiled-to-interpreted) — используется, когда скомпилированный метод вызывает метод, который всё ещё интерпретируется. Адаптеры генерируются для каждой сигнатуры метода, и большому приложению их нужны тысячи. Их генерация при старте занимает время, поэтому в JDK 25 добавили опцию AOTAdapterCaching, которая включена по умолчанию: адаптеры генерируются на фазе сборки и сохраняются в AOT-кэше в виде готового к исполнению машинного кода. И вот в чём подвох. Как и любой код, который генерирует HotSpot, адаптеры генерируются под процессор, на котором JVM работает в данный момент. Если этот процессор поддерживает AVX-512, адаптер может использовать регистры AVX-512. Если он поддерживает SVE, адаптер может использовать инструкции SVE. На машине, где шла сборка, такой код корректен. На машине без этих возможностей первый же вызов через такой адаптер выполняет инструкцию, которую процессор не знает, и ядро посылает SIGILL. Почему JVM нас не защитила JVM действительно валидирует AOT-кэш. При продакшн-запуске она проверяет сборку JDK, операционную систему, архитектуру процессора (x64 или aarch64), classpath, GC, compressed oops и ещё ряд настроек. Если что-то не совпадает, JVM в режиме по умолчанию -XX:AOTMode=auto выводит предупреждение и продолжает работу без кэша. Старт получается медленнее, но ничего не ломается. Однако одну вещь JVM в JDK 25 не проверяла: возможности процессора в пределах одной архитектуры. «x64» означает и современный серверный процессор с AVX-512, и старый процессор ноутбука без него. Кэш принимался, а адаптеры внутри него использовались как есть. Теперь посмотрим, как собирался наш образ. Релизный job запускается на раннере, который предоставляет GitHub, и собирает multi-platform образ: docker build --platform linux/amd64,linux/arm64 --file master-oss/Dockerfile ... sourcecraft.dev Вариант amd64 тренируется на том процессоре, который случайно окажется у раннера. Раннеры GitHub являются облачными виртуальные машины, и у некоторых из них есть AVX-512. Вариант arm64 тренируется под эмуляцией QEMU (docker/setup-qemu-action), потому что сам раннер работает на x86. Эмуляция QEMU в user-mode по умолчанию эмулирует модель процессора max, в которой есть SVE. Однако у многих реальных ARM64-процессоров, на которых люди запускают контейнеры, SVE нет: у Mac на Apple Silicon, AWS Graviton2 и Ampere Altra. Multi-platform сборка прогоняет весь Dockerfile отдельно для каждой платформы, поэтому каждый вариант образа получает собственный кэш, а docker pull выбирает вариант, соответствующий хосту. Архитектура всегда совпадала. А вот возможности процессора в её пределах не совпадали: у наших сборочных машин их было больше, чем у многих машин наших пользователей. Ровно такая комбинация и приводила к падению. Баг в апстриме В ходе расследования мы нашли adoptium/adoptium-support#1507, «Launching with AOT cache fatally crashes with SIGILL (0x4) depending on available CPU instructions». Проблема была та же самая: кэш, созданный на процессоре Zen 5 с AVX-512, падал в ~AdapterBlob на процессоре Zen 2 без AVX-512. Автор обнаружил её так же, как и мы: у раннеров GitHub Actions AVX-512 то есть, то нет. Issue перенесли в OpenJDK как JDK-8388703. Реакция разработчиков HotSpot была прагматичной. Адаптеры являются единственным AOT-кодом в JDK 25 (кэширование стабов уже выключено), и производительность они улучшают не сильно. Поэтому вместо того, чтобы бэкпортировать проверки процессора, они решили просто выключить кэширование адаптеров по умолчанию в JDK 25. Именно это исправление вошло в JDK 25.0.5: // Disable adapters caching which requires CPU features matching checks // (implemented by JDK-8377507 and JDK-8381975) which we don't // have in this version of code. FLAG_SET_ERGO_IF_DEFAULT(AOTAdapterCaching, false); sourcecraft.dev Полноценное исправление находится в JDK 27: JDK-8377507 — возможности процессора машины, на которой шла сборка, сохраняются в кэше AOT-кода; JDK-8381975 — при старте сохранённые возможности должны точно совпадать с возможностями текущего процессора. Если они не совпадают, JVM пишет в лог AOT Code Cache disabled: cpu features are incompatible, игнорирует только машинный код и продолжает использовать всё остальное из AOT-кэша. Так и должно быть: в худшем случае ускорение будет чуть меньше, но падения не будет никогда. Наше исправление Исправление: #1767. Мы вернули AOT-кэш, но создаём его без адаптеров: Create AOT cache without CPU-specific adapters to avoid SIGILL on other CPUs RUN java \ -XX:+UnlockDiagnosticVMOptions \ -XX:-AOTAdapterCaching \ -XX:AOTMode=create \ -XX:AOTConfiguration=app.aotconf \ -XX:AOTCache=app.aot \ -jar /application/master.jar sourcecraft.dev AOTAdapterCaching является диагностическим флагом, поэтому нужен -XX:+UnlockDiagnosticVMOptions. С этим флагом в кэше вообще нет машинного кода, и JVM подтверждает это при старте: [info][aot] Opened AOT cache app.aot. [info][aot,codecache,init] AOT Code Cache is empty [info][aot] Using AOT-linked classes: true (static archive: has aot-linked classes) sourcecraft.dev Остаются метаданные классов, профили и объекты кучи, которые одинаковы на любом процессоре данной архитектуры. Адаптеры генерируются во время работы, на машине пользователя и под его процессор. И их удаление не лишает нас выигрыша. При локальной проверке образа, собранного из исправленного Dockerfile, около 72% классов, загруженных при старте (10 933 из 15 201), были взяты из AOT-кэша, а время до обновления контекста сократилось примерно с 7,3 с до 5,4 с на ноутбуке разработчика. Альтернативы мы обсуждали в PR. Первая идея была дождаться JDK 25.0.5 и оставить кэширование адаптеров включённым. Но 25.0.5 не делает адаптеры безопасными. Он просто выключает их, так что результат тот же, что и с нашим флагом. Вторая идея была перейти на JDK 27, где проверка процессора есть. Большинство запускает Axelix Master в Docker или Kubernetes, так что новая базовая версия Java их бы не затронула. Но Spring Boot 4.1 официально поддерживает Java до 26-й версии, а поддержка Java 27 ожидается в Spring Boot 4.2. Поэтому мы смёржили явный флаг. Он работает на сегодняшних сборках JDK 25 и остаётся корректным после 25.0.5, где просто совпадает с новым значением по умолчанию. А что с JDK 27? Как только выйдет Spring Boot 4.2, мы планируем перевести Axelix на JDK 27. Там снова включать AOTAdapterCaching безопасно: на несовпадающем процессоре JVM отбросит закэшированный код, а не упадёт. Но «безопасно» не значит «полезно». JDK 27 требует точного совпадения возможностей процессора. Для образа, собранного на раннере GitHub или натренированного под QEMU, шанс, что у процессора пользователя окажется ровно тот же набор возможностей, невелик. У большинства пользователей закэшированные адаптеры просто будут выброшены. Чтобы заранее собранный образ действительно выигрывал от AOT-кода, JVM должна генерировать его под общий, переносимый базовый набор возможностей процессора. Для этого есть открытое улучшение, JDK-8377630 «Restrict AOT code to a generic set of CPU features». Пока оно не появилось, AOT-кэш в распространяемом образе лучше воспринимать как кэш данных, а не кода. Выводы AOT-кэш JDK является реальным и простым способом ускорить старт Spring Boot-приложений в Docker. Достаточно multi-stage Dockerfile с этапом тренировки. На JDK 25 до версии 25.0.5, если вы собираете кэш на одной машине, а запускаете на другой, создавайте его с -XX:+UnlockDiagnosticVMOptions -XX:-AOTAdapterCaching. Иначе процессоры ваших пользователей должны поддерживать все возможности, которые были у вашей сборочной машины. А у CI-раннеров и QEMU их обычно больше. Multi-arch образы автоматически получают отдельный кэш для каждой архитектуры, потому что каждая платформа проходит собственные этапы тренировки и сборки. JVM валидирует AOT-кэш и безопасно откатывается, если что-то не совпадает. Единственное исключение до JDK 27: машинный код, хранящийся в кэше. Исправление войдёт в следующий релиз Axelix. Если вам интересны подробности, вся история описана в #1744 и #1767.