Delayed sending request

[shaxiaozz]

My Env：
okhttp version is 4.9.1
java version is Java(TM) SE Runtime Environment (build 1.8.0_333-b02)

Problems encountered：
I'm using okhttp to make requests to the website, GET&POST methods.

I am using okhttp to access a domain name website (https://test-rights-platform.e-buy.com). My program will record the request time. I found that in some cases, the delay in requesting this website is It will be extremely large (nearly 1 second), but I can ensure that my network outgoing network is normal.

In response to the above situation, I deliberately captured the data packets when this happened. I found that after obtaining the IP address returned by DNS, the program waited nearly 800ms before initiating the TCP three-way handshake. I understand that when dns returns the IP address, it should immediately initiate the TCP three-way handshake instead of waiting for a while before handshaking.

I'm not sure about the entire process of okhttp requesting a domain name. Is this normal? I have repeatedly checked my network environment, there is no packet loss, and the network outgoing delay is normal. But this problem still occurs occasionally, or there is something wrong with my okhttp usage or configuration.

Hope to get your reply~

Datagram

After completing the DNS query, it waited nearly 800ms before sending out the tcp syn packet. I don't know if this is controlled by okhttp. .

[Endeavour233]

My Env： okhttp version is 4.9.1 java version is Java(TM) SE Runtime Environment (build 1.8.0_333-b02)

Problems encountered： I'm using okhttp to make requests to the website, GET&POST methods.

I am using okhttp to access a domain name website (https://test-rights-platform.e-buy.com). My program will record the request time. I found that in some cases, the delay in requesting this website is It will be extremely large (nearly 1 second), but I can ensure that my network outgoing network is normal.

In response to the above situation, I deliberately captured the data packets when this happened. I found that after obtaining the IP address returned by DNS, the program waited nearly 800ms before initiating the TCP three-way handshake. I understand that when dns returns the IP address, it should immediately initiate the TCP three-way handshake instead of waiting for a while before handshaking.

I'm not sure about the entire process of okhttp requesting a domain name. Is this normal? I have repeatedly checked my network environment, there is no packet loss, and the network outgoing delay is normal. But this problem still occurs occasionally, or there is something wrong with my okhttp usage or configuration.

Hope to get your reply~

Datagram After completing the DNS query, it waited nearly 800ms before sending out the tcp syn packet. I don't know if this is controlled by okhttp. .

Have no idea why there was a delay. But noticed that the [SYN] packet from source to destination, which initiates handshake, was missing in your wireshark log. By the way, how did you record the request time? This information might help with pinpointing the issue. Thanks.

[yschimke]

I suspect the delay is waiting for an IPv4 dns response. You can confirm that by decorating DNS and printing out when it returns.

[shaxiaozz]

@Endeavour233 Thank you for your reply.

Before requesting, my program will output the log to logger.info, so I can clearly see the time when this logic is entered. To find the corresponding request from the message.

Regarding the [SYN] request, I'm sorry, it should be that my NPM mirroring traffic is not mirrored. But this should not affect it.

Are there any other ways to look at this issue?

[shaxiaozz]

@yschimke Hello, like the message I mentioned above, the entire process of dns query should only take about 10ms.

[yschimke]

If you record the events with an event listener, it should confirm that.

That's usually easier to tie back to OkHttp stages than wireshark.

[shaxiaozz]

@yschimke
How should I enable the DNS event listener to log events?

Can you provide guidance or send relevant documents?

[shaxiaozz]

This is the time spent on dns query calculated by Wireshark based on existing packets~

[yschimke]

https://square.github.io/okhttp/features/events/

[shaxiaozz]

@yschimke Thank you, I will add debugging

[shaxiaozz]

@yschimke At the same time, what if the delay in the secureConnectEnd stage is high?

[Endeavour233]

@Endeavour233 Thank you for your reply.

Before requesting, my program will output the log to logger.info, so I can clearly see the time when this logic is entered. To find the corresponding request from the message.

Regarding the [SYN] request, I'm sorry, it should be that my NPM mirroring traffic is not mirrored. But this should not affect it.

Are there any other ways to look at this issue?

I was thinking that [SYN] marks the initialization of handshake, and since it was missing in the log, we could not assume that there was a delay as large as 800ms between DNS return and handshake initialization. Anyway, after using eventlistener to track the request, hopefully we'll find out where the delay happens~

[shaxiaozz]

I'll update the progress~

I have added EventListener, below the output of EventListener：

2024-05-16T03:22:36.923379130Z 0046 https://test-rights-platform.e-buy.com/channel/watsons/codeStatusUpdate
2024-05-16T03:22:36.923517673Z 0046 0.000 callStart
2024-05-16T03:22:36.923665310Z 0046 0.000 proxySelectStart
2024-05-16T03:22:36.923701670Z 0046 0.000 proxySelectEnd
2024-05-16T03:22:36.923715849Z 0046 0.000 dnsStart
2024-05-16T03:22:36.923736751Z 0046 0.000 dnsEnd
2024-05-16T03:22:36.923807354Z 0046 0.000 connectStart
2024-05-16T03:22:36.952235332Z 0046 0.029 secureConnectStart
2024-05-16T03:22:37.792585640Z 0046 0.869 secureConnectEnd
2024-05-16T03:22:37.792607859Z 0046 0.869 connectEnd
2024-05-16T03:22:37.792711948Z 0046 0.869 connectionAcquired
2024-05-16T03:22:37.796580122Z 0046 0.873 requestHeadersStart
2024-05-16T03:22:37.796636533Z 0046 0.873 requestHeadersEnd
2024-05-16T03:22:37.796654404Z 0046 0.873 requestBodyStart
2024-05-16T03:22:37.796714463Z 0046 0.873 requestBodyEnd
2024-05-16T03:22:37.834815218Z 0046 0.911 responseHeadersStart
2024-05-16T03:22:37.834854752Z 0046 0.911 responseHeadersEnd
2024-05-16T03:22:37.835051185Z 0046 0.912 responseBodyStart
2024-05-16T03:22:37.863026980Z 0046 0.940 responseBodyEnd
2024-05-16T03:22:37.863047238Z 0046 0.940 connectionReleased
2024-05-16T03:22:37.863049606Z 0046 0.940 callEnd

I see that the time spent is all in the secureConnectEnd phase. I see that the time is spent in the secureConnectEnd phase.

[shaxiaozz]

The following request processing time is: 678ms

[Endeavour233]

The following request processing time is: 678ms

From my view, your last 2 logs both indicated that most time was spent on TLS handshake(as per my understanding of okhttp, when secureConnectStart, TCP handshake has completed. connectEnd is the mark of the establishment of the whole secure connection). However, it seems different from your initial issue, where I guess the bottleneck is TCP handshake.

[yschimke]

Is this happening on every request? or just the first one with each OkHttpClient instance?

If it's only on the first, then TLS initialisation is probably a factor.

[yschimke]

Test on Android emulator with two requests, forced to reconnect.

05-19 18:05:57.323  7595  7616 I System.out: 18:05:55.523743 [0 ms] callStart: Request{method=GET, url=https://test-rights-platform.e-buy.com/robots.txt}
05-19 18:05:57.325  7595  7616 I System.out: 18:05:55.583774 [68 ms] proxySelectStart: https://test-rights-platform.e-buy.com/
05-19 18:05:57.325  7595  7616 I System.out: 18:05:55.584795 [69 ms] proxySelectEnd: [DIRECT]
05-19 18:05:57.325  7595  7616 I System.out: 18:05:55.585059 [69 ms] dnsStart: test-rights-platform.e-buy.com
05-19 18:05:57.326  7595  7616 I System.out: 18:05:55.592838 [76 ms] dnsEnd: [test-rights-platform.e-buy.com/47.101.44.29]
05-19 18:05:57.326  7595  7616 I System.out: 18:05:55.608193 [92 ms] connectStart: test-rights-platform.e-buy.com/47.101.44.29:443 DIRECT
05-19 18:05:57.327  7595  7616 I System.out: 18:05:55.839102 [323 ms] secureConnectStart
05-19 18:05:57.328  7595  7616 I System.out: 18:05:56.322772 [807 ms] secureConnectEnd: Handshake{tlsVersion=TLS_1_2 cipherSuite=TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256 peerCertificates=[CN=*.e-buy.com, O=易百信息技术（上海）股份有限公司, ST=上海市, C=CN, CN=GeoTrust CN RSA CA G1, OU=www.digicert.com, O=DigiCert Inc, C=US, CN=DigiCert Global Root CA, OU=www.digicert.com, O=DigiCert Inc, C=US] localCertificates=[]}
05-19 18:05:57.329  7595  7616 I System.out: 18:05:56.331113 [815 ms] connectEnd: http/1.1
05-19 18:05:57.329  7595  7616 I System.out: 18:05:56.334553 [818 ms] connectionAcquired: Connection{test-rights-platform.e-buy.com:443, proxy=DIRECT hostAddress=test-rights-platform.e-buy.com/47.101.44.29:443 cipherSuite=TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256 protocol=http/1.1}
05-19 18:05:57.330  7595  7616 I System.out: 18:05:56.349031 [833 ms] requestHeadersStart
05-19 18:05:57.330  7595  7616 I System.out: 18:05:56.350322 [834 ms] requestHeadersEnd
05-19 18:05:57.330  7595  7616 I System.out: 18:05:56.572177 [1056 ms] responseHeadersStart
05-19 18:05:57.332  7595  7616 I System.out: 18:05:56.577485 [1061 ms] responseHeadersEnd: Response{protocol=http/1.1, code=404, message=Not Found, url=https://test-rights-platform.e-buy.com/robots.txt}
05-19 18:05:57.332  7595  7616 I System.out: 18:05:56.594852 [1078 ms] responseBodyStart
05-19 18:05:57.333  7595  7616 I System.out: 18:05:56.595127 [1079 ms] responseBodyEnd: byteCount=0
05-19 18:05:57.334  7595  7616 I System.out: 18:05:56.595778 [1080 ms] connectionReleased
05-19 18:05:57.334  7595  7616 I System.out: 18:05:56.597847 [1081 ms] callEnd
05-19 18:05:57.335  7595  7616 I System.out: 18:05:56.600711 [0 ms] callStart: Request{method=GET, url=https://test-rights-platform.e-buy.com/robots.txt}
05-19 18:05:57.335  7595  7616 I System.out: 18:05:56.601934 [1 ms] proxySelectStart: https://test-rights-platform.e-buy.com/
05-19 18:05:57.336  7595  7616 I System.out: 18:05:56.603537 [2 ms] proxySelectEnd: [DIRECT]
05-19 18:05:57.336  7595  7616 I System.out: 18:05:56.603759 [3 ms] dnsStart: test-rights-platform.e-buy.com
05-19 18:05:57.336  7595  7616 I System.out: 18:05:56.604168 [3 ms] dnsEnd: [test-rights-platform.e-buy.com/47.101.44.29]
05-19 18:05:57.337  7595  7616 I System.out: 18:05:56.606141 [5 ms] connectStart: test-rights-platform.e-buy.com/47.101.44.29:443 DIRECT
05-19 18:05:57.337  7595  7616 I System.out: 18:05:56.853399 [252 ms] secureConnectStart
05-19 18:05:57.339  7595  7616 I System.out: 18:05:57.078881 [478 ms] secureConnectEnd: Handshake{tlsVersion=TLS_1_2 cipherSuite=TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256 peerCertificates=[CN=*.e-buy.com, O=易百信息技术（上海）股份有限公司, ST=上海市, C=CN, CN=GeoTrust CN RSA CA G1, OU=www.digicert.com, O=DigiCert Inc, C=US, CN=DigiCert Global Root CA, OU=www.digicert.com, O=DigiCert Inc, C=US] localCertificates=[]}
05-19 18:05:57.339  7595  7616 I System.out: 18:05:57.079178 [478 ms] connectEnd: http/1.1
05-19 18:05:57.341  7595  7616 I System.out: 18:05:57.080581 [479 ms] connectionAcquired: Connection{test-rights-platform.e-buy.com:443, proxy=DIRECT hostAddress=test-rights-platform.e-buy.com/47.101.44.29:443 cipherSuite=TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256 protocol=http/1.1}
05-19 18:05:57.341  7595  7616 I System.out: 18:05:57.081082 [480 ms] requestHeadersStart
05-19 18:05:57.341  7595  7616 I System.out: 18:05:57.081888 [481 ms] requestHeadersEnd
05-19 18:05:57.342  7595  7616 I System.out: 18:05:57.293637 [692 ms] responseHeadersStart
05-19 18:05:57.342  7595  7616 I System.out: 18:05:57.294013 [693 ms] responseHeadersEnd: Response{protocol=http/1.1, code=404, message=Not Found, url=https://test-rights-platform.e-buy.com/robots.txt}
05-19 18:05:57.343  7595  7616 I System.out: 18:05:57.294677 [693 ms] responseBodyStart
05-19 18:05:57.343  7595  7616 I System.out: 18:05:57.294907 [694 ms] responseBodyEnd: byteCount=0
05-19 18:05:57.343  7595  7616 I System.out: 18:05:57.295584 [694 ms] connectionReleased
05-19 18:05:57.344  7595  7616 I System.out: 18:05:57.296040 [695 ms] callEnd

Similar time, so maybe it's just the handshake.

Going to close this out, as expected.

[shaxiaozz]

@yschimke @Endeavour233 receive. Thank you, it looks like a server-side problem