各位大佬帮忙分析一个 net.Conn read 延迟的问题

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

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

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

@tool2dx
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]

"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 都卡。看不出啥问题，汗。

wireshark 也打出时间戳吧

@1423

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

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

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

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

@wisej 这次 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

@zhangsanfeng2012 从 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 。我自己本机跑也没有出现你的情况。

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

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

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

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

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