Vert.x delayed response during send

29 views
Skip to first unread message

Himanshu Gupta

unread,
Jun 30, 2022, 4:37:33 PMJun 30
to vert.x
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 ?

Julien Viet

unread,
Jul 1, 2022, 5:03:49 AMJul 1
to vert.x
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

unread,
Jul 1, 2022, 5:33:17 AMJul 1
to vert.x
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

unread,
Jul 1, 2022, 9:20:29 AMJul 1
to vert.x
Hi Julien,

Please find the archive below.


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

unread,
Jul 5, 2022, 1:49:35 AMJul 5
to vert.x
Hi Julien,

Were you able to recreate the issue at your end ?

Thanks,
Himanshu

Julien Viet

unread,
Jul 6, 2022, 4:39:39 AMJul 6
to vert.x
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

unread,
Jul 14, 2022, 6:06:17 AMJul 14
to vert.x
Hi Julien,

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


Thanks,
Himanshu

Himanshu Gupta

unread,
Jul 14, 2022, 6:07:38 AMJul 14
to vert.x
We are seeing the same issue with wrk and wrk2 tools as well
Reply all
Reply to author
Forward
0 new messages