Golang Go语言中各位大佬帮忙分析一个 net.Conn read 延迟的问题

最近使用 golang 写了一个 tls 的测试程序，连接特定服务器接收数据会有 500ms 的延迟，起初以为是网络问题，但是通过 wireshark 抓包查看每次服务端回包都很快，最后发现每次 tls 连接握手成功后，再使用 net.Conn 的 read 接口读取数据时都会有 500ms 延迟。
相同的代码，相同运行环境，连接其他服务器时，不会增加延迟。

大佬帮忙分析下原因，这 500ms 增加的原因

测试环境：win11 22H2

go 版本：go version go1.22.5 windows/amd64

wireshark 抓包：(可以看到发送数据后，到服务端回包只有 100ms 延迟）

打印日志：（可以看到握手成功后，每次读取数据都会有 500ms 延迟，比 100ms 多很多）
2024-07-10 16:13:24.2993355 +0800 CST m=+0.027776101 net.Conn start writing
2024-07-10 16:13:24.3118851 +0800 CST m=+0.040325701 net.Conn last write 12.6118ms
2024-07-10 16:13:24.3119473 +0800 CST m=+0.040387901 net.Conn start reading
2024-07-10 16:13:24.3299688 +0800 CST m=+0.058409401 net.Conn last read 18.0215ms
2024-07-10 16:13:24.3299688 +0800 CST m=+0.058409401 net.Conn start reading
2024-07-10 16:13:24.3305847 +0800 CST m=+0.059025301 net.Conn last read 615.9µs
2024-07-10 16:13:24.3307758 +0800 CST m=+0.059216401 net.Conn start writing
2024-07-10 16:13:24.3307758 +0800 CST m=+0.059216401 net.Conn last write 0s
TLS handshake complete
2024-07-10 16:13:24.3313401 +0800 CST m=+0.059780701 net.Conn start writing
2024-07-10 16:13:24.3313401 +0800 CST m=+0.059780701 net.Conn last write 0s
2024-07-10 16:13:24.3313401 +0800 CST m=+0.059780701 net.Conn start reading
2024-07-10 16:13:24.8493165 +0800 CST m=+0.577757101 net.Conn last read 517.9764ms
2024-07-10 16:13:24.850016 +0800 CST m=+0.578456601 net.Conn start writing
2024-07-10 16:13:24.8505629 +0800 CST m=+0.579003501 net.Conn last write 546.9µs
2024-07-10 16:13:24.8510947 +0800 CST m=+0.579535301 net.Conn start reading
2024-07-10 16:13:25.3798195 +0800 CST m=+1.108260101 net.Conn last read 528.7248ms
2024-07-10 16:13:25.3798195 +0800 CST m=+1.108260101 net.Conn start writing
2024-07-10 16:13:25.3804916 +0800 CST m=+1.108932201 net.Conn last write 672.1µs
2024-07-10 16:13:25.3811492 +0800 CST m=+1.109589801 net.Conn start reading
2024-07-10 16:13:25.9070306 +0800 CST m=+1.635471201 net.Conn last read 525.8814ms
2024-07-10 16:13:25.90721 +0800 CST m=+1.635650601 net.Conn start writing
2024-07-10 16:13:25.9077158 +0800 CST m=+1.636156401 net.Conn last write 505.8µs

代码 demo：
https://gist.github.com/kratos1918/6884f248e20130af93a8adf5d2716851
Golang Go语言中各位大佬帮忙分析一个 net.Conn read 延迟的问题

更多关于Golang Go语言中各位大佬帮忙分析一个 net.Conn read 延迟的问题的实战教程也可以访问 https://www.itying.com/category-94-b0.html

yibo5220 1楼

既然同样代码，连其他服务器没问题，那只能优先怀疑这个网站加密协议的问题了。

针对网站用 https://www.ssllabs.com/ssltest/先测试一下，看看支持那些握手协议。

然后再把具体的握手和加密部分都打印出来，找原因。你 log 文件太简单了，看不出什么东西。

更多关于Golang Go语言中各位大佬帮忙分析一个 net.Conn read 延迟的问题的实战系列教程也可以访问 https://www.itying.com/category-94-b0.html

bupafengyu 2楼

TLSv1.2 Record Layer: Handshake Protocol: Client Hello
Content Type: Handshake (22)
Version: TLS 1.0 (0x0301)
Length: 188
Handshake Protocol: Client Hello
Handshake Type: Client Hello (1)
Length: 184
Version: TLS 1.2 (0x0303)
Random: 02c98e6340c1998429ef68ab84aca85febeda83f31f8c107885898bcc872b1e2
Session ID Length: 32
Session ID: 25b2f6c1e19320ece8ef49afdd86135278b795644c7875df6b177c5bb0c4b7bb
Cipher Suites Length: 32
Cipher Suites (16 suites)
Cipher Suite: TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256 (0xc02b)
Cipher Suite: TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256 (0xc02f)
Cipher Suite: TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384 (0xc02c)
Cipher Suite: TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384 (0xc030)
Cipher Suite: TLS_ECDHE_ECDSA_WITH_CHACHA20_POLY1305_SHA256 (0xcca9)
Cipher Suite: TLS_ECDHE_RSA_WITH_CHACHA20_POLY1305_SHA256 (0xcca8)
Cipher Suite: TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA (0xc009)
Cipher Suite: TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA (0xc013)
Cipher Suite: TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA (0xc00a)
Cipher Suite: TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA (0xc014)
Cipher Suite: TLS_RSA_WITH_AES_128_GCM_SHA256 (0x009c)
Cipher Suite: TLS_RSA_WITH_AES_256_GCM_SHA384 (0x009d)
Cipher Suite: TLS_RSA_WITH_AES_128_CBC_SHA (0x002f)
Cipher Suite: TLS_RSA_WITH_AES_256_CBC_SHA (0x0035)
Cipher Suite: TLS_ECDHE_RSA_WITH_3DES_EDE_CBC_SHA (0xc012)
Cipher Suite: TLS_RSA_WITH_3DES_EDE_CBC_SHA (0x000a)
Compression Methods Length: 1
Compression Methods (1 method)
Extensions Length: 79
Extension: status_request (len=5)
Extension: supported_groups (len=10)
Extension: ec_point_formats (len=2)
Extension: signature_algorithms (len=26)
Extension: renegotiation_info (len=1)
Extension: extended_master_secret (len=0)
Extension: signed_certificate_timestamp (len=0)
Extension: supported_versions (len=3) TLS 1.2
[JA4: t12i160800_8cdfa2d4673b_824bd91ab3e2]
[JA4_r: t12i160800_000a,002f,0035,009c,009d,c009,c00a,c012,c013,c014,c02b,c02c,c02f,c030,cca8,cca9_0005,000a,000b,000d,0012,0017,002b,ff01_0804,0403,0807,0805,0806,0401,0501,0601,0503,0603,0201,0203]
[JA3 Fullstring: 771,49195-49199-49196-49200-52393-52392-49161-49171-49162-49172-156-157-47-53-49170-10,5-10-11-13-65281-23-18-43,29-23-24-25,0]
[JA3: debde53b165c575b8eddf8ed24fd9c97]

TLSv1.2 Record Layer: Handshake Protocol: Server Hello
Content Type: Handshake (22)
Version: TLS 1.2 (0x0303)
Length: 93
Handshake Protocol: Server Hello
Handshake Type: Server Hello (2)
Length: 89
Version: TLS 1.2 (0x0303)
Random: 1575f62a5c52b96571721293311553c226a534045fce72c1444f574e47524401
Session ID Length: 32
Session ID: 0ec01f8dea82283f54f62e7e0ecc70d39c9edba3ae7a80c198eb2ad5cd91a6a7
Cipher Suite: TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256 (0xc02f)
Compression Method: null (0)
Extensions Length: 17
Extension: renegotiation_info (len=1)
Type: renegotiation_info (65281)
Length: 1
Renegotiation Info extension
Renegotiation info extension length: 0
Extension: ec_point_formats (len=4)
Type: ec_point_formats (11)
Length: 4
EC point formats Length: 3
Elliptic curves point formats (3)
EC point format: uncompressed (0)
EC point format: ansiX962_compressed_prime (1)
EC point format: ansiX962_compressed_char2 (2)
Extension: extended_master_secret (len=0)
Type: extended_master_secret (23)
Length: 0
[JA3S Fullstring: 771,49199,65281-11-23]
[JA3S: 76c691f46143bf86e2d1bb73c6187767]

htzhanglong 3楼

"Cipher Suite: TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256 (0xc02f)"

这协议常见的，ECDHE 是椭圆曲线 Diffie-Hellman ，好像是写死的 secp256r1 曲线，256 位计算很快的。

AES 128 GCM 就比普通的 AES 128 多了一个 authTag ，也慢不到哪里去。

最后就算服务器返回 RSA 的是 8192 位或者 16384 位，那也只慢握手一次，也不可能后续每一次 read 都卡。看不出啥问题，汗。

h691938207 4楼作者

wireshark 也打出时间戳吧

yuanlaile 5楼

caililin 6楼

一种可能性是 go scheduler 调度延迟。我看你的 trace 里 P 确实是为 1 （ PS：你的 trace 结果和 demo 代码似乎不是对应的）
但是如果是这种情况的话，不会像你说的 [连接其他服务器时，不会增加延迟]

nodeper 7楼

确实，trace 的时候设置了 GOMAXPROCS=1 ，现象还是一样的

h691938207 8楼作者

网上搜到了相似的问题，但是没找到解决方法 https://stackoverflow.com/questions/15588961/windows-tcp-socket-recv-delay

wuwangju 9楼

GOMAXPROCS>1 情况依旧？能不能来个纯 demo code 的 trace ？

yibo5220 10楼

这次 trace 的 maxprocs 是默认值，https://www.123pan.com/s/WWYTTd-briQA.html 提取码:v2ex

特定服务器执行结果：
2024-07-15 09:10:07.6549564 +0800 CST m=+0.026422301 net.Conn start writing
2024-07-15 09:10:07.668557 +0800 CST m=+0.040022901 net.Conn last write 13.6006ms
2024-07-15 09:10:07.668557 +0800 CST m=+0.040022901 net.Conn start reading
2024-07-15 09:10:07.6874251 +0800 CST m=+0.058891001 net.Conn last read 18.8681ms
2024-07-15 09:10:07.6877773 +0800 CST m=+0.059243201 net.Conn start reading
2024-07-15 09:10:07.6877773 +0800 CST m=+0.059243201 net.Conn last read 0s
2024-07-15 09:10:07.6883967 +0800 CST m=+0.059862601 net.Conn start writing
2024-07-15 09:10:07.6883967 +0800 CST m=+0.059862601 net.Conn last write 0s
2024-07-15 09:10:07.6889185 +0800 CST m=+0.060384401 net.Conn start reading
2024-07-15 09:10:08.2198472 +0800 CST m=+0.591313101 net.Conn last read 530.9287ms
TLS handshake complete
TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256

zlyuanteng 11楼

从 trace 看就是纯粹的过了 500ms 左右, goroutine main.main 被 network 事件唤醒。
也就是 1.调用 Read ，syscall 返回没有可读数据 -> 2.调用 runtime_pollWait 由 runtime 等待 netfd 有可读数据(同时 gouroutine main.main blocked) 3. 500ms 后，runtime 通过 syscall 知道 netfd 有数据可读，唤醒 goroutine
---------------------
所以从 trace 看问题点应该不在 Go 。我自己本机跑也没有出现你的情况。

gougou168 12楼

startTime := time.Now()
fmt.Println(startTime, “net.Conn start writing”)
n, err = t.Conn.Write(b)
t.lastWrite = time.Now()
你这样只是计算的等待 netpoll 可写事件触发的阻塞时间

sinazl 13楼

我也觉得应该不是 go 的问题，我用 wireshar 抓包看回包很快，但是应用读不上来。
我在当前 Read 之前，调用一次 Read(nil)，就不会有 500ms 的问题了，但是换了另一台 pc ，这个方法并不能解决问题。

zlyuanteng 14楼

wireshark(应该)是网卡驱动层捕获 packet ，go 得经过 OS 网络栈，这之间可能有时间差，但也不可能到 500ms…

在你给的信息无误的前提下，是我我可能会用其他语言实现同样功能的代码和 Go 同时去跑一次，看它的延迟

gougou168 15楼

后面试过通过 golang 直接调用 winsock api ，延迟发生的点也是一样的

yibo5220 16楼

在Golang中使用net.Conn进行网络编程时，遇到读取延迟的问题可能由多种因素导致。以下是一些常见的分析方向和解决策略：

网络条件：首先检查网络连接质量。高延迟或不稳定的网络连接会直接影响数据读取速度。
缓冲区设置：net.Conn的读取操作通常依赖于缓冲区。如果缓冲区设置不当（过大或过小），可能会导致不必要的延迟。可以尝试调整读取操作的缓冲区大小，以优化性能。
阻塞与超时：确认是否设置了合理的读取超时。过长的超时时间会导致程序在等待数据到达时阻塞过久。使用SetReadDeadline方法可以设置合理的超时时间。
服务器性能：服务器端的处理能力也是影响读取延迟的重要因素。如果服务器处理请求的速度较慢，或者资源被其他请求占用，也会导致客户端读取延迟。
TCP参数调优：针对TCP连接，可以调整一些TCP参数（如TCP_NODELAY、TCP_QUICKACK等），以优化传输性能。
代码优化：检查读取操作的代码逻辑，确保没有不必要的阻塞或同步操作。使用Go的协程和通道可以更有效地管理并发，减少阻塞。

综上所述，解决net.Conn读取延迟问题需要从多个角度进行排查和优化。建议从网络条件、缓冲区设置、超时设置、服务器性能等方面入手，逐步定位并解决问题。