Vert.x delayed response during send

[Himanshu Gupta]

We are running a vertx HTTPS server on cloud using ubi8 OpenJDK 17 image. The resources assigned to container are 2 Core CPU and 8 GB RAM. This is the server startup parameter for the vertx 4.2.7 application.

-Xms954m -Xmx3815m -XX:+UnlockExperimentalVMOptions -XX:+UseZGC -XX:MinHeapFreeRatio=10 -XX:MaxHeapFreeRatio=20 -XX:GCTimeRatio=4 -XX:AdaptiveSizePolicyWeight=90 -XX:+ExitOnOutOfmoryError -Dvertx.disableDnsResolver=true

We have enabled epoll and BoringSSL, set the blocked thread checker to check thread blocked for more than 100 msec and starting the server with following flags.

.setSendBufferSize(30 * 1024) // 30 KB

.setReceiveBufferSize(1 * 1024) // 1 KB

.setTcpFastOpen(true)

.setTcpNoDelay(true)

.setTcpQuickAck(true)

.setTcpCork(false)

.setReusePort(true)

.setReuseAddress(true)

.setTcpKeepAlive(true)

.setCompressionSupported(true)

.setUseAlpn(true)

.setHandle100ContinueAutomatically(true)

.setTracingPolicy(TracingPolicy.IGNORE)

.setSsl(true)

.setSslEngineOptions(new OpenSSLEngineOptions().setSessionCacheEnabled(false))

.setKeyStoreOptions(new JksOptions().setPath(config.getJsonObject(ConfigConstants.SSL).getString(ConfigConstants.KEY_STORE)).setPassword(config.getJsonObject(ConfigConstants.SSL).getString(ConfigConstants.CERTIFICATE_PASSWORD)));

We also have the LoggingHandler as the first Handler in the chain.

This is how we are sending the response

routingContext.response()

.setChunked(true)

.putHeader(HttpHeaders.CONTENT_TYPE.toString(), HttpConstants.APPLICATION_HAL_JSON)

.putHeader(HttpConstants.IDENTIFIER, requestObject.getPathParams().get(UrlConstants.IDENTIFIER))

.end(response.encode());

We are seeing that the LoggingHandler reports that the server has taken 1 ms to process the request whereas at client end (for 0.1% of request), we see that the server time and the client reported time do not match. We created a JMH test and used OkHttp at client end and we are seeing this in the logs for the request for which server took 1 ms.

Req # Time Operation

67997 0.000 callStart

67997 0.000 connectionAcquired

67997 0.000 requestHeadersStart

67997 0.000 requestHeadersEnd

67997 0.423 responseHeadersStart

67997 0.423 responseHeadersEnd

67997 0.427 responseBodyStart

67997 0.427 responseBodyEnd

67997 0.427 connectionReleased

67997 0.427 callEnd

Any clues to narrow down the problem to find the root cause ?

Stackoverflow link for same query: https://stackoverflow.com/questions/72821614/vert-x-delayed-response-during-send

[Julien Viet]

can you share your benchmark ? does it reproduce the issue on any machine ?

Julien

> --
> You received this message because you are subscribed to the Google Groups "vert.x" group.
> To unsubscribe from this group and stop receiving emails from it, send an email to vertx+un...@googlegroups.com.
> To view this discussion on the web, visit https://groups.google.com/d/msgid/vertx/4f6371e9-8df1-4bcd-8eb0-5d1c0c95245fn%40googlegroups.com.

[Himanshu Gupta]

Hi,

Let me clean up the test program and vertx code to create a reproducer.

It should be easy to recreate.

Thanks,

Himanshu

[Himanshu Gupta]

Hi Julien,

Please find the archive below.

https://github.com/himanshumps/delayIssue/raw/master/DelayIssue.zip

To run the program, create the fat jar of both applications.

If you are running the test and the server on two separate machine (which I how I was testing), change the path in OkHttpBenchmark.java to point to your server application.

To run the server:

/apps/jdk-17.0.2_8/bin/java -Xms954m -Xmx3815m -XX:+UnlockExperimentalVMOptions -XX:+UseZGC -XX:MinHeapFreeRatio=10 -XX:MaxHeapFreeRatio=20 -XX:GCTimeRatio=4 -XX:AdaptiveSizePolicyWeight=90 -XX:+ExitOnOutOfMemoryError -Dvertx.disableDnsResolver=true --add-exports java.base/sun.security.x509=ALL-UNNAMED -jar delay-issue-starter-1.0.0-SNAPSHOT-fat.jar 

To run the load test application(runs a 120 second test with 20 connection for 1 iteration and 1 fork with no warmup with the threshold being 20 msec for the E2E time):

/apps/jdk-17.0.2_8/bin/java -Dthreshold=20 -jar jmh-test.jar -f 1 -foe true -i 1 -r 120 -t 20 -to 180 -wi 0 

There are two logs file generated:

okHttpLogs.log - Contains the okHttp logs with each log having the identifier being tested.

delayIssueAccessLog.log - Server logs.

The logs of the request taking time are displayed on the screen and you can search for that identifier in the logs.

grep <identifier> okHttpLogs.log delayIssueAccessLog.log 

Please let me know if you are able to recreate the issue or need further information.

Thanks,

Himanshu

[Himanshu Gupta]

Hi Julien,

Were you able to recreate the issue at your end ?

Thanks,

Himanshu

[Julien Viet]

Hi,

I haven't had yet the opportunity to investigate.

Julien

> To view this discussion on the web, visit https://groups.google.com/d/msgid/vertx/659a7c59-96f7-4811-9022-a400cba80ff4n%40googlegroups.com.

[Himanshu Gupta]

Hi Julien,

Can you please let me know if you got some time to investigate .. We are seeing some issues with 99%tile.

https://github.com/himanshumps/delayIssue/raw/master/Screenshot%202022-07-14%20at%203.33.24%20PM.png 

Thanks,

Himanshu

[Himanshu Gupta]

We are seeing the same issue with wrk and wrk2 tools as well