Spring leyden numbers are suspiciously bad

[franz1981]

Latest results shows:

which report Spring 3/4 w Layden to deliver impressively bad results compared to Layden w Loom.

After collecting JFR profiling data in the lab

spring-layden-loom.zip

and using async-profiler jfrconv with --classify option it is clear that:

Leyden (slow):

  ┌──────────────────┬──────────────┬───────┐
  │       Tier       │ Leaf samples │   %   │
  ├──────────────────┼──────────────┼───────┤
  │ _[0] interpreted │ 854          │ 36.0% │
  ├──────────────────┼──────────────┼───────┤
  │ _[1] C1          │ 846          │ 35.7% │
  ├──────────────────┼──────────────┼───────┤
  │ _[i] inlined     │ 278          │ 11.7% │
  ├──────────────────┼──────────────┼───────┤
  │ _[j] C2          │ 267          │ 11.3% │
  ├──────────────────┼──────────────┼───────┤
  │ _[k] kernel      │ 127          │ 5.4%  │
  └──────────────────┴──────────────┴───────┘

Virtual-Leyden (fast):

  ┌──────────────────┬──────────────┬───────┐
  │       Tier       │ Leaf samples │   %   │
  ├──────────────────┼──────────────┼───────┤
  │ _[0] interpreted │ 15           │ 0.9%  │
  ├──────────────────┼──────────────┼───────┤
  │ _[1] C1          │ 498          │ 29.4% │
  ├──────────────────┼──────────────┼───────┤
  │ _[i] inlined     │ 608          │ 35.9% │
  ├──────────────────┼──────────────┼───────┤
  │ _[j] C2          │ 343          │ 20.2% │
  ├──────────────────┼──────────────┼───────┤
  │ _[k] kernel      │ 230          │ 13.6% │
  └──────────────────┴──────────────┴───────┘

Both are running fully consuming the 4 cores (accordly to pidstat and mpstat).

36% of CPU time in leyden is spent executing interpreted code vs under 1% for virtual-leyden.
The Leyden AOT cache for the non-virtual Spring 4 variant is loading code but leaving it stuck in the interpreter — the JIT isn't recompiling it to C1/C2.

As a separate confirmation, mpstat extract of the load test last few seconds:

Leyden mpstat:

04:48:42 PM  CPU    %usr   %nice    %sys %iowait    %irq   %soft  %steal  %guest  %gnice   %idle
04:48:43 PM    2   89.00    0.00    9.00    0.00    0.00    2.00    0.00    0.00    0.00    0.00
04:48:43 PM    4   87.88    0.00    9.09    0.00    0.00    3.03    0.00    0.00    0.00    0.00
04:48:43 PM    6   87.88    0.00    9.09    0.00    0.00    3.03    0.00    0.00    0.00    0.00
04:48:43 PM    8   87.00    0.00   10.00    0.00    1.00    2.00    0.00    0.00    0.00    0.00

Virtual-Leyden mpstat:

05:08:17 PM  CPU    %usr   %nice    %sys %iowait    %irq   %soft  %steal  %guest  %gnice   %idle
05:08:18 PM    2   77.23    0.00   16.83    0.00    0.99    4.95    0.00    0.00    0.00    0.00
05:08:18 PM    4   78.00    0.00   16.00    0.00    1.00    5.00    0.00    0.00    0.00    0.00
05:08:18 PM    6   77.45    0.00   15.69    0.00    0.98    4.90    0.00    0.00    0.00    0.98
05:08:18 PM    8   80.00    0.00   14.00    0.00    1.00    4.00    0.00    0.00    0.00    1.00

which shows that layden (no Virtual Thread) is spending more urs space cpu time (likely because of slower code, being interpreted).

[franz1981]

This "could" be related to #420 as well: virtual layden has just 4 Loom carriers which run user code, which could leave more cpu time to C2 compilations - whilst without Loom, the large thread pool of Spring could "starve" C2 to death, leaving the code in interpreted state (or C1 tier 3).
In addition to it, tier 3 code has the additional hit of contention among method data counters (see https://redhatperf.github.io/post/method-data-scalability/) - and having less OS threads running code w them, is welcome.

[edeandrea]

For this run we also changed the garbage collector to ParallelGC - could that be the cause?

[franz1981]

For this run we also changed the garbage collector to ParallelGC - could that be the cause?

If it is...it should have similarly hit with or without Loom.
I have pinged our OpenJDK IBM team to see if they can take a look/reproduce it.
In case we need to provide them the exact command we used to run it in the lab and how to adapt it if they need to reproduce it locally

[franz1981]

Running the load test with syncjfr add more colors to the investigation.

Compilation tiers during recording:

  ┌───────────────────────────────────────────────┬───────────────┬───────────────────────┐
  │                                               │ Leyden (slow) │ Virtual-Leyden (fast) │
  ├───────────────────────────────────────────────┼───────────────┼───────────────────────┤
  │ Level 4 (C2) compilations                     │ 363           │ 107                   │
  ├───────────────────────────────────────────────┼───────────────┼───────────────────────┤
  │ Level 2 (C1-limited) compilations             │ 134           │ 0                     │
  ├───────────────────────────────────────────────┼───────────────┼───────────────────────┤
  │ Avg compilation duration                      │ 661ms         │ 236ms                 │
  ├───────────────────────────────────────────────┼───────────────┼───────────────────────┤
  │ Max compilation duration                      │ 20.5 seconds  │ 812ms                 │
  ├───────────────────────────────────────────────┼───────────────┼───────────────────────┤
  │ C2 failures ("retry without subsuming loads") │ 4             │ 15                    │
  └───────────────────────────────────────────────┴───────────────┴───────────────────────┘

C2 compiler queue (end of recording):

  ┌──────────────────┬─────────────┬────────────────┐
  │                  │   Leyden    │ Virtual-Leyden │
  ├──────────────────┼─────────────┼────────────────┤
  │ C2 queue size    │ 168 pending │ 0              │
  ├──────────────────┼─────────────┼────────────────┤
  │ C2 peak queue    │ 459         │ 66             │
  ├──────────────────┼─────────────┼────────────────┤
  │ C2 total added   │ 2,606       │ 4,322          │
  ├──────────────────┼─────────────┼────────────────┤
  │ C2 total removed │ 2,438       │ 4,322          │
  ├──────────────────┼─────────────┼────────────────┤
  │ C2 threads       │ 2           │ 1              │
  └──────────────────┴─────────────┴────────────────┘

Thread count:

• Leyden: 100+ active threads (the http handlers)
• Virtual-Leyden: ~4 active threads (the loom carriers)

Context switch rate (at steady state):

• Leyden: 190,000–215,000 switches/sec
• Virtual-Leyden: 96,000–100,000 switches/sec

Leyden has 4x more threads and 2x the context switch rate despite it deliver 1/3 of TPS.

C2 compiler is choking in non-virtual leyden

[franz1981]

Now, If the issue is due to the inherent more intensive compilation activity of Spring, there is not much we can do if not to be more gentle and perform a much slower and longer ramp up during warmup to give Spring time to catch-up and compile everything, but I am against it as it seems distant from what could happen in prod too - and is an inherent limit of Spring due to its heavier nature.

If instead it is a bug in Layden on JDK 25 we have to check if we can do anything about it.
Afaik more recent Layden versions can use compiled nmethods without compiling them, so, it will naturally solved as these will be available in newer JDK versions.

[franz1981]

This is fun - similarly to a customer case I was involved last year and #420 it seems that -Xbatch "fix" it:
i.e.

PHASE     METRIC        THROUGHPUT     REQUESTS  MEAN      STD_DEV    MAX        p50       p90       p99       p99.9      p99.99     TIMEOUTS  ERRORS  BLOCKED  2xx     3xx  4xx  5xx  CACHE
warmup    getAllFruits  5706.03 req/s    684900  17.52 ms  128.49 ms   13.96 s   11.60 ms  20.84 ms  94.37 ms  973.08 ms    6.88 s          0       0     0 ns  684900    0    0    0      0
loadTest  getAllFruits  7528.28 req/s    225999  13.27 ms   10.75 ms  341.84 ms  11.86 ms  18.22 ms  51.90 ms  163.58 ms  270.53 ms         0       0     0 ns  225999    0    0    0      0

but...similarly to the customer case I was involved into, in production this is not really an option as disabling background compilation stall Java "mutators" threads waiting the compilation to complete (IIRC) for a non-deterministic amount of time - and AFAIK none in prod really want that.

The flight recording data agree...
Compilation tiers during recording:

    ┌───────────────────────────────────────────────┬────────────────────┬────────────────┐
    │                                               │ Leyden (no -Xbatch)│ Leyden -Xbatch │
    ├───────────────────────────────────────────────┼────────────────────┼────────────────┤
    │ Level 4 (C2) compilations                     │ 363                │ 241            │
    ├───────────────────────────────────────────────┼────────────────────┼────────────────┤
    │ Level 3 (C1 profiling) compilations           │ 0                  │ 5              │
    ├───────────────────────────────────────────────┼────────────────────┼────────────────┤
    │ Level 2 (C1-limited) compilations             │ 134                │ 1              │
    ├───────────────────────────────────────────────┼────────────────────┼────────────────┤
    │ Avg compilation duration                      │ 661ms              │ 380ms          │
    ├───────────────────────────────────────────────┼────────────────────┼────────────────┤
    │ Max compilation duration                      │ 20.5 seconds       │ 6.2 seconds    │
    ├───────────────────────────────────────────────┼────────────────────┼────────────────┤
    │ C2 failures ("retry without subsuming loads") │ 4                  │ 13             │
    └───────────────────────────────────────────────┴────────────────────┴────────────────┘

C2 compiler queue (end of recording):

    ┌──────────────────┬────────────────────┬────────────────┐
    │                  │ Leyden (no -Xbatch)│ Leyden -Xbatch │
    ├──────────────────┼────────────────────┼────────────────┤
    │ C2 queue size    │ 168 pending        │ 0              │
    ├──────────────────┼────────────────────┼────────────────┤
    │ C2 peak queue    │ 459                │ 99             │
    ├──────────────────┼────────────────────┼────────────────┤
    │ C2 total added   │ 2,606              │ 4,428          │
    ├──────────────────┼────────────────────┼────────────────┤
    │ C2 total removed │ 2,438              │ 4,428          │
    ├──────────────────┼────────────────────┼────────────────┤
    │ C2 threads       │ 2                  │ 1              │
    └──────────────────┴────────────────────┴────────────────┘

Compilation trajectory (warmup → measurement):

    │                      │ Leyden (no -Xbatch, ~3K req/s)  │ Leyden -Xbatch (~7.5K req/s)   │
    ├──────────────────────┼─────────────────────────────────┼────────────────────────────────┤
    │ Start compileCount   │ 2,548                           │ 1,903                          │
    ├──────────────────────┼─────────────────────────────────┼────────────────────────────────┤
    │ Start nmethodCodeSize│ 3.3MB                           │ 2.5MB                          │
    ├──────────────────────┼─────────────────────────────────┼────────────────────────────────┤
    │ End compileCount     │ 17,072                          │ 19,815                         │
    ├──────────────────────┼─────────────────────────────────┼────────────────────────────────┤
    │ End nmethodCodeSize  │ 21.7MB                          │ 34.1MB                         │
    ├──────────────────────┼─────────────────────────────────┼────────────────────────────────┤
    │ End totalTimeSpent   │ 362s                            │ 139.9s                         │
    ├──────────────────────┼─────────────────────────────────┼────────────────────────────────┤
    │ At measurement start │ 16,799 compiles / 20.8MB        │ ~19,700 compiles / 33.8MB      │
    │                      │ C2 queue: 168 pending           │ C2 queue: 0                    │
    │                      │ still compiling during meas.    │ compilation effectively done    │
    ├──────────────────────┼─────────────────────────────────┼────────────────────────────────┤
    │ During measurement   │ +273 compiles / +0.9MB / +59s   │ +115 compiles / +0.3MB / +1.8s │
    └──────────────────────┴─────────────────────────────────┴────────────────────────────────┘

Thread count and context switch rate (steady state):

    ┌──────────────────────────┬─────────────────────┬─────────────────────┐
    │                          │ Leyden (no -Xbatch) │ Leyden -Xbatch      │
    ├──────────────────────────┼─────────────────────┼─────────────────────┤
    │ OS threads               │ 131                 │ 131                 │
    ├──────────────────────────┼─────────────────────┼─────────────────────┤
    │ Context switch rate      │ 190K–215K/sec       │ 112K–316K/sec       │
    └──────────────────────────┴─────────────────────┴─────────────────────

[edeandrea]

@franz1981 this is all good work!

Maybe I don't 100% understand, but my takeaway is that Spring with leyden has some issues, and those issues seem to be related to Spring and not the benchmarking infrastructure, JDK, or somewhere else?

[franz1981]

is that Spring with leyden has some issues

As explained at #420 Spring is affected regardless Layden, but since Layden appear to be even more C2 (the optimizing compiler in Hotspot) intensive - for unknown yet reasons - it struggles even more than usual.

Now, the core issue is:

• hotspot compilation need LOT of CPU time
• Spring is very unfriendly at warmup with it, because not as much "lean" as Quarkus
• the runtime fail to compile "fast" enough good optimized code, because the injection rate/load is too high, and fully consuming the CPU time
• the peak TPS suffer because of this

The "hidden" dimensions are:

1. our perf lab RHEL 9.6 is using CFS scheduler vs more modern ones, which are able to give C2 enough "quality" time with a CPU core and make progress quickly, without been interleaved by 100 "noisy" http Spring workers: TLDR a modern OS would improve this
2. our benchmark is not ramping up more gently during "warmup" but is "full" load a time 0: this is what "could" happen in prod, and been more gentle here dismiss the "realism" part of the benchmarking story, but at the same time it's fair to assume that people have rate limiting in front of their "lil container microservices" instances no?
3. our injection pattern is not that realistic: real traffic can be point poisson/bursty - which can likely leave more "room" to C2 compiler to finish its job, but similarly to the previous point: what realistic case are we trying to capture here?
4. modern JVM with Layden are capable to "save" C2 compiled method without causing excessive C2 activity if the compilations are "good" (are really used!): modern JDKs mitigate this issue regardless the CFS Linux OS scheduler

[franz1981]

I have just measured that disabling background compilation almost fixed it but is not a production level fix tbh, as it led to 6 seconds (!!) pauses to Java threads.
In short, as explained before, the type of workload (warmup + load) is a bad fit for Spring being so JIT intensive, and so far doesn't see there is much we can do to help here.
I'm making sure there is not obviously wrong on how we perform the training runs, but if I am right is better we publish some blog post to explain why Spring is hit so badly while Quarkus isn't, to make sure in the community people understand why the numbers are what they are

[iklam]

Could you try adding -XX:+UnlockDiagnosticVMOptions -XX:-AOTRecordTraining -XX:-AOTReplayTraining to the training, assembly, and production runs and see if this dials back the compilation?

[franz1981]

Hi @iklam !
Sorry if I missed your comment 🙏

We have found that there's a JDK 25 bug which @ashu-mehra is working on (a one liner!) which cause JIT to be less aggressive to promote to C2 compilations, if there're training data - but probably you're already aware if you both had some sync these days

The difference is....very relevant!!

I'm waiting Ashu to fill the JDK issue so I can finish my article on this!

[DanHeidinga]

I think this was Ashu's bug: https://bugs.openjdk.org/browse/JDK-8386852

[ashu-mehra]

@DanHeidinga yes, thanks for posting the link here.

[franz1981]

@DanHeidinga Yep - we have published https://quarkus.io/blog/when-the-jit-cant-keep-up/ and https://redhatperf.github.io/post/when-the-jit-cant-keep-up/ which go deeper into the analysis and the root causes 🙏

I think this could be closed, as there's not THAT much to do here, if not waiting till backported to JDK 25 (it will @DanHeidinga @ashu-mehra ?)