Service degradation at 99.9 percentiles in latest jetty versions

[kul]

Jetty version(s)
Jetty 11.x-12.x

Jetty Environment

Java version/vendor (use: java -version)
java version "21.0.1" 2023-10-17 LTS
Java(TM) SE Runtime Environment (build 21.0.1+12-LTS-29)
Java HotSpot(TM) 64-Bit Server VM (build 21.0.1+12-LTS-29, mixed mode, sharing)

OS type/version
Linux 5.15.0-1035-azure #42-Ubuntu SMP Tue Feb 28 19:41:23 UTC 2023 x86_64 x86_64 x86_64 GNU/Linux

Description
While upgrading spring version for the application, I moved the application dependency of jetty from 9.x to 12.x. While things seems to be working fine in general, I noticed that proxy servers (nginx) were noticing upstream timeouts only for a very small percentage of requests. When plotting the metrices for eg. you will see degradation only at 99.9 percentiles.

I did move the jetty dependency to 11.x versions and still timeouts remained. In order to unblock I moved the app server to undertow and the timeouts vanished. I would be happy to provide more information here to help this debug as we have observability built around jetty and would like to stick to it.

The service has a decent throughput and single server for above test was serving ~10k requests/sec. You can see the 502 status as reported from nginx for a small percentage (<0.5%). Jetty server itself was however looking fine and the threadpool metrics looked normal.

How to reproduce?

[sbordet]

We run our own load tests and we don't see timeouts.

Can you please report details about the requests that fail?
Are they GET or POST, do they have large content or not, special headers, are they gzipped or not, multipart or not, etc.

Do you have Jetty stack traces for the requests that fail?

Do you have network traces via tcpdump for the request that fail?

Is there a way we can reproduce this issue?

[kul]

Thanks for the response @sbordet.

Jetty is set at default config. All of the requests are POST requests. Less than 1% of requests are responded to with a 200 response otherwise a 204. A 200 status code looks like below in a tcpdump (jetty runs on 8099)

12:10:52.624103 lo In IP 127.0.0.1.8099 > 127.0.0.1.51702: Flags [P.], seq 448:5240, ack 9432, win 512, options [nop,nop,TS val 299574961 ecr 299574938], length 4792
E.....@.@..+............9.U}:.X............
..&...&.HTTP/1.1 200 OK
Content-Encoding: gzip
Connection: keep-alive
Vary: Accept-Encoding, User-Agent
Server: nginx
Transfer-Encoding: chunked
Content-Type: application/json
Date: Mon, 29 Jan 2024 12:10:52 GMT

From what I could observe, there were no failures in the error logs. If you could let me know the loggers (package level) for which logs would be helpful here, I can enable specific logging in logback and provide here.

Note that there are no error codes from jetty itself, the status code graph above are from nginx which assumes a 502 for upstream timeouts. I am not sure on how to give this as a reproducible example.

[joakime]

Jetty is set at default config. All of the requests are POST requests. Less than 1% of requests are responded to with a 200 response otherwise a 204. A 200 status code looks like below in a tcpdump (jetty runs on 8099)

There is no such thing as "default config" with Jetty.

Using jetty-home + jetty-base (also known as standalone), the default is actually nothing.
No configuration, not even a server. (some people even use jetty standalone for things that are not a server!)
Why? Because Jetty is highly modular, and everything is considered an optional feature.

Content-Encoding: gzip

The fact that you see this in your responses means you have a specifically configured instance of Jetty.
Gzip compression, like everything else in Jetty, is an optional feature.

Please run your jetty standalone two ways and report the output of your configuration.

First: the raw configuration of your jetty-base, this will be useful to know what you have configured.

$ cd /path/to/my-jetty-base
$ java -jar /opt/jetty-home/start.jar --list-config

Next, run Jetty with the server dump feature and report that here too.

$ cd /path/to/my-jetty-base
$ java -jar /opt/jetty-home/start.jar jetty.server.dumpAfterStart=true

[gregw]

What version of spring are you using? This could be an issue in the spring jetty 12 integration, which is new code and less tested than jetty 12 itself.

[gregw]

@lorban could we include spring boot integration in our performance testing?

[joakime]

The OP just said "spring".

While its likely to be spring boot, that's not the only spring integration point.
Could be standard spring-framework with spring-web, spring-mvc, or even the spring JSF integrations (to name some of the other choices in common use with Jetty)

[gregw]

@joakime most of the jetty spring boot integration is actually in spring-framework and the 12 code is all rather new

[kul]

@gregw The application is using spring boot and the above endpoints are defined by extending HttpServlet class (jakarta in this case because spring 6 dependencies has moved away from javax).

spring-web: 6.1.3
spring-boot-dependencies: 3.2.2

Enabling gzip may be the only customization on top of default spring boot properties. These are the only server.* properties,

server.port=8099
server.compression.enabled=true
server.compression.min-response-size=1
server.error.whitelabel.enabled=false

@joakime I am not able to find a way to pass these options for embedded jetty server in spring.
https://docs.spring.io/spring-boot/docs/current/reference/html/application-properties.html#appendix.application-properties.server

[lorban]

@gregw yes, we could include a spring test app in our perf tests, that should be fairly easy to do.

@kul There are a few oddities in the graphs you posted (like the 502 statuses growing after 15:35, when the load goes slightly up), but nothing substantially abnormal. We need to narrow down the problem and find what's actually causing those timeouts. Any pattern or clue as to why Jetty doesn't respond to some requests would help.

Here are a few questions that popped into my mind that would help start this investigation:

• Are you (or Spring) using the blocking servlet API or the async one?
• What does increasing or shortening the proxy's timeout do? Does that have an impact on the amount of failed requests?
• Does disabling gzip help?
• Do you know what your failing requests were actually doing? Serving static content? Calling a servlet? What is that servlet supposed to do in the latter case?
• Is it always the same kind of request that's causing the issue?

I currently don't see anything in particular that would cause this behavior, so it's probably too early to start looking at debug logs as that would require enabling a large scope, which would tremendously impact performance and generate too much data to be reasonably analyzed. I would concentrate on narrowing the scope for now.

[kul]

@lorban Allow me some time to answer these questions analytically as I would need to corelate a large volume of requests failures across proxy and the app server. However I can answer a couple of them

Are you (or Spring) using the blocking servlet API or the async one?

It is using blocking servlet.

Do you know what your failing requests were actually doing? Serving static content? Calling a servlet? What is that servlet supposed to do in the latter case?

All requests are REST based and responds with with either a no-content(99%) or a json response(1%).

[kul]

@lorban and team,

Does disabling gzip help?

I tried disabling gzip and surprisingly the timeouts went away completely! The modification I did are below

server.port=8099
#server.compression.enabled=true
#server.compression.min-response-size=1
server.error.whitelabel.enabled=false

Given this result, the min-response-size value of 1 looked like a bad choice to me anyways. So i modified the config again to below but the timeouts started happening again.

server.port=8099
server.compression.enabled=true
server.compression.min-response-size=512
server.error.whitelabel.enabled=false

I have not investigated other questions because it seems to have high correlation with enabling gzip.

[gregw]

I'm 99% sure that server.compression.enabled=true in springboot enables the underlying servers compression mechanism. i.e. our GzipHandler and not some spring compression service. So this looks like we may have an issue in our gzip. I think springboot 3.2.2 is using 12.0.5, so that is a recent version.

[joakime]

Our latest release Jetty 12.0.6 has a fix for a sporadic IllegalStateException in GzipHandler (#11095)
Perhaps retest but with Jetty 12.0.6?

[kul]

I tried selectively excluding 12.0.5 and including 12.0.6 in spring but still cannot get it to package 12.0.6 correctly. I will test this once spring-boot-starter-jetty bumps up jetty to 12.0.6. Going ahead, I plan to move gzipping off of jetty to nginx for the service.

[lorban]

(sorry for the confusing previous comment I deleted; it was intended for another issue.)

[lorban]

Sorry for the delay getting back to you. I spent some time trying to reproduce your problem with Spring Boot and I noticed that there are problems in Jetty 12.0.5 that Spring Boot triggers, but Jetty 12.0.6 has the necessary fixes, like #11098. It was fairly easy to make Jetty 12.0.5 with Spring Boot, but Jetty 12.0.6 seems to work just fine in all the tests I made.

Other people have complained about problems with Jetty 12.0.5 and Spring Boot in #11326 but it seems everything eventually points to #11098.

There's a good chance that simply upgrading Jetty will solve your problem, so we would be glad if you could try that and keep us posted about the outcome.

Thanks!

[kul]

Hi @lorban , I was waiting for new release on https://mvnrepository.com/artifact/org.springframework.boot/spring-boot-starter-jetty to test this out. However not sure what timelines spring has, so asking for help here directly.
I tried to manually exclude dependencies but still was not able to get mvn to package jetty correctly. I tried this but mvn still seems to package 12.05 because of the way jetty-ee10 BOM is imported.

        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-jetty</artifactId>
            <exclusions>
                <exclusion>
                    <groupId>org.eclipse.jetty.ee10</groupId>
                    <artifactId>*</artifactId>
                </exclusion>
                <exclusion>
                    <groupId>org.eclipse.jetty.ee10.websocket</groupId>
                    <artifactId>*</artifactId>
                </exclusion>
            </exclusions>
        </dependency>
        <dependency>
            <groupId>org.eclipse.jetty.ee10</groupId>
            <artifactId>jetty-ee10-servlets</artifactId>
            <version>12.0.6</version>
        </dependency>
        <dependency>
            <groupId>org.eclipse.jetty.ee10</groupId>
            <artifactId>jetty-ee10-servlets</artifactId>
            <version>12.0.6</version>
        </dependency>

jar -tvf target/myservice.jar| grep jetty
 50363 Mon Jun 05 23:12:48 IST 2023 BOOT-INF/lib/jetty-ee10-servlets-12.0.6.jar
387879 Mon Jun 05 23:12:48 IST 2023 BOOT-INF/lib/jetty-http-12.0.5.jar
632286 Mon Jun 05 23:12:48 IST 2023 BOOT-INF/lib/jetty-util-12.0.5.jar
177131 Thu Nov 11 08:38:00 IST 2010 BOOT-INF/lib/jetty-util-6.1.26.jar
279732 Mon Jun 05 23:12:48 IST 2023 BOOT-INF/lib/jetty-io-12.0.5.jar
  4786 Fri Jan 19 06:37:42 IST 2024 BOOT-INF/lib/spring-boot-starter-jetty-3.2.2.jar

[olamy]

@kul you should add the jetty core/ee10 bom in your dptMngt section

<dependencyManagement>
  <dependencies>
     ......
      <dependency>
        <groupId>org.eclipse.jetty</groupId>
        <artifactId>jetty-bom</artifactId>
        <version>12.0.6</version>
        <type>pom</type>
        <scope>import</scope>
      </dependency>
      <dependency>
        <groupId>org.eclipse.jetty.ee10</groupId>
        <artifactId>jetty-ee10-bom</artifactId>
        <version>12.0.6</version>
        <type>pom</type>
        <scope>import</scope>
      </dependency>
      ....
  </dependencies>
</dependencyManagement>

if after this you still have this strange jetty-util-6.1.26.
You should try to see where it's coming from using mvn dependency:tree

[kul]

@olamy , thanks a lot, this seems to fix everything without even the excludes ! Only dep I see which is not 12.0.6 is from an older version of jetty under org.mortbay package which I hope can be ignored. This unblocks me and I will try out the test again some time today.

➜ shell ✗ jar -tvf target/myservice.jar| grep jetty                 
 50363 Mon Jun 05 23:12:48 IST 2023 BOOT-INF/lib/jetty-ee10-servlets-12.0.6.jar
 28899 Mon Jun 05 23:12:48 IST 2023 BOOT-INF/lib/jetty-websocket-jetty-api-12.0.6.jar
 38792 Mon Jun 05 23:12:48 IST 2023 BOOT-INF/lib/jetty-ee10-websocket-jetty-server-12.0.6.jar
 46333 Mon Jun 05 23:12:48 IST 2023 BOOT-INF/lib/jetty-websocket-core-server-12.0.6.jar
 80705 Mon Jun 05 23:12:48 IST 2023 BOOT-INF/lib/jetty-xml-12.0.6.jar
 30791 Mon Jun 05 23:12:48 IST 2023 BOOT-INF/lib/jetty-jndi-12.0.6.jar
 41142 Mon Jun 05 23:12:48 IST 2023 BOOT-INF/lib/jetty-ee10-websocket-jakarta-server-12.0.6.jar
 20184 Mon Jun 05 23:12:48 IST 2023 BOOT-INF/lib/jetty-ee10-websocket-jakarta-client-12.0.6.jar
400962 Mon Jun 05 23:12:48 IST 2023 BOOT-INF/lib/jetty-http-12.0.6.jar
187250 Mon Jun 05 23:12:48 IST 2023 BOOT-INF/lib/jetty-websocket-core-common-12.0.6.jar
145170 Mon Jun 05 23:12:48 IST 2023 BOOT-INF/lib/jetty-security-12.0.6.jar
584102 Mon Jun 05 23:12:48 IST 2023 BOOT-INF/lib/jetty-server-12.0.6.jar
 81865 Mon Jun 05 23:12:48 IST 2023 BOOT-INF/lib/jetty-ee10-annotations-12.0.6.jar
 34589 Mon Jun 05 23:12:48 IST 2023 BOOT-INF/lib/jetty-plus-12.0.6.jar
632618 Mon Jun 05 23:12:48 IST 2023 BOOT-INF/lib/jetty-util-12.0.6.jar
402295 Mon Jun 05 23:12:48 IST 2023 BOOT-INF/lib/jetty-ee10-servlet-12.0.6.jar
177131 Thu Nov 11 08:38:00 IST 2010 BOOT-INF/lib/jetty-util-6.1.26.jar
117051 Mon Jun 05 23:12:48 IST 2023 BOOT-INF/lib/jetty-session-12.0.6.jar
  8655 Mon Jun 05 23:12:48 IST 2023 BOOT-INF/lib/jetty-ee10-websocket-servlet-12.0.6.jar
341970 Mon Jun 05 23:12:48 IST 2023 BOOT-INF/lib/jetty-client-12.0.6.jar
280833 Mon Jun 05 23:12:48 IST 2023 BOOT-INF/lib/jetty-io-12.0.6.jar
  4786 Fri Jan 19 06:37:42 IST 2024 BOOT-INF/lib/spring-boot-starter-jetty-3.2.2.jar
 31471 Mon Jun 05 23:12:48 IST 2023 BOOT-INF/lib/jetty-websocket-jetty-common-12.0.6.jar
113610 Mon Jun 05 23:12:48 IST 2023 BOOT-INF/lib/jetty-ee10-websocket-jakarta-common-12.0.6.jar
 22178 Mon Jun 05 23:12:48 IST 2023 BOOT-INF/lib/jetty-ee10-plus-12.0.6.jar
 24613 Mon Jun 05 23:12:48 IST 2023 BOOT-INF/lib/jetty-websocket-core-client-12.0.6.jar
  7136 Mon Jun 05 23:12:48 IST 2023 BOOT-INF/lib/jetty-alpn-client-12.0.6.jar
149214 Mon Jun 05 23:12:48 IST 2023 BOOT-INF/lib/jetty-ee10-webapp-12.0.6.jar
➜ shell ✗ jar -tvf target/myservice.jar| grep jetty | grep -v 12.0.6
177131 Thu Nov 11 08:38:00 IST 2010 BOOT-INF/lib/jetty-util-6.1.26.jar
  4786 Fri Jan 19 06:37:42 IST 2024 BOOT-INF/lib/spring-boot-starter-jetty-3.2.2.jar

[olamy]

@kul good to hear.
But if you could get rid of jetty-util-6.1.26.jar this would be great as well.
mvn dependency:tree should help to find the "guilty" :)

[kul]

@olamy I had started my tests before I saw this comment. Only reservations I have with this is that the dependency is being pulled from third party libraries and I might end up breaking their behaviour on runtime. I will take this up as a separate exercise.

@gregw @joakime @sbordet @lorban After testing again by completely migrating jetty to 12.0.6 I no longer see any timeouts. I plan on running the tests for longer duration to check any other regressions. So far it looks good in terms of throughput, latency and error rates and seems on par with jetty 9.x.

Thank you for the support on this issue. 🙏

[olamy]

@kul thanks for your report. Please reopen if you still have some issues.