问题现象
使用 sysbench + haproxy 对 TiDB 进行压测，运行 57 小时后遇到报错。
问题分析步骤
- 根据报错提示 error 2013(Lost connection to MySQL server during query)，判断是客户端连接中断，对应正在执行的语句为 SELECT SUM(k) FROM sbtest3 WHERE ID BETWEEN 10060469 AND 10060568。
- 收集 Clinic，并上传 Clinic Server。
- 首先查看TiDB 监控，判断问题发生在 02:01 分左右，当时发生了 Slow Query，随之业务几乎停止，判断可能跟 Slow Query 有关。
- 查看 Performance 监控，在 02:01~02:02 分之间，确实发生了连接中断，与压测报错一致。
- 在报错之前，集群整体的内存比较平稳，CPU 基本处于满负荷运行状态。
- 查看 Slow Query 监控，发现压测报错的语句显示在慢查询列表中，进一步查看执行计划发现时间主要消耗在 Coprocesor Executor Time 部分。
- 进一步查看 TiDB 日志文件，确认 183 节点 TiDB 日志中存在连接报错的现象，连接报错前存在慢 SQL，与压测一致，从日志看报错语句的执行耗时为 1m0.073155353s，导致 write tcp 192.168.162.183:3306->192.168.26.99:53518 中断，即 TiDB Server -> Haproxy 连接中断。
[2024/07/20 02:01:03.160 +08:00] [WARN] [expensivequery.go:145] [expensive_query] [cost_time=60.066469603s] [stats=sbtest3:451257814232858690] [conn=4129303986] [user=root] [database=titest] [table_ids="[112]"] [txn_start_ts=451257827797762282] [mem_max="1484 Bytes (1.45 KB)"] [sql="SELECT SUM(K) FROM sbtest3 WHERE id BETWEEN 10060469 AND 10060568"] [session_alias=] ["affected rows"=0]
[2024/07/20 02:01:03.168 +08:00] [INFO] [coprocessor.go:1391] ["[TIME_COP_WAIT] resp_time:1m0.073155353s txnStartTS:451257827797762282 region_id:10693 store_addr:192.168.162.184:20160 stats:Cop:{num_rpc:3, total_time:1m0s}, rpc_errors:{context deadline exceeded:1, not_leader:1} kv_process_ms:0 kv_wait_ms:0 kv_read_ms:0 processed_versions:100 total_versions:281 rocksdb_delete_skipped_count:1 rocksdb_key_skipped_count:280 rocksdb_cache_hit_count:12 rocksdb_read_count:0 rocksdb_read_byte:0"] [conn=4129303986] [session_alias=]
[2024/07/20 02:01:03.169 +08:00] [INFO] [conn.go:1146] ["command dispatched failed"] [conn=4129303986] [session_alias=] [connInfo="id:4129303986, addr:192.168.26.99:53518 status:11, collation:utf8mb4_0900_ai_ci, user:root"] [command=Query] [status="inTxn:1, autocommit:1"] [sql="SELECT SUM(K) FROM sbtest3 WHERE id BETWEEN 10060469 AND 10060568"] [txn_mode=PESSIMISTIC] [timestamp=451257827797762282] [err="write tcp 192.168.162.183:3306->192.168.26.99:53518: write: broken pipe\ngithub.com/pingcap/errors.AddStack\n\t/root/go/pkg/mod/github.com/pingcap/errors@v0.11.5-0.20240318064555-6bd07397691f/errors.go:178\ngithub.com/pingcap/errors.Trace\n\t/root/go/pkg/mod/github.com/pingcap/errors@v0.11.5-0.20240318064555-6bd07397691f/juju_adaptor.go:15\ngithub.com/pingcap/tidb/pkg/server/internal.(*PacketIO).Flush\n\t/workspace/source/tidb/pkg/server/internal/packetio.go:307\ngithub.com/pingcap/tidb/pkg/server.(*clientConn).flush\n\t/workspace/source/tidb/pkg/server/conn.go:1458\ngithub.com/pingcap/tidb/pkg/server.(*clientConn).writeResultSet\n\t/workspace/source/tidb/pkg/server/conn.go:2258\ngithub.com/pingcap/tidb/pkg/server.(*clientConn).handleStmt\n\t/workspace/source/tidb/pkg/server/conn.go:2047\ngithub.com/pingcap/tidb/pkg/server.(*clientConn).handleQuery\n\t/workspace/source/tidb/pkg/server/conn.go:1769\ngithub.com/pingcap/tidb/pkg/server.(*clientConn).dispatch\n\t/workspace/source/tidb/pkg/server/conn.go:1343\ngithub.com/pingcap/tidb/pkg/server.(*clientConn).Run\n\t/workspace/source/tidb/pkg/server/conn.go:1113\ngithub.com/pingcap/tidb/pkg/server.(*Server).onConn\n\t/workspace/source/tidb/pkg/server/server.go:739\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_arm64.s:1197"]
[2024/07/20 02:01:03.169 +08:00] [ERROR] [terror.go:324] ["encountered error"] [error="write tcp 192.168.162.183:3306->192.168.26.99:53518: write: broken pipe"] [stack="github.com/pingcap/tidb/pkg/parser/terror.Log\n\t/workspace/source/tidb/pkg/parser/terror/terror.go:324\ngithub.com/pingcap/tidb/pkg/server/internal.(*PacketIO).WritePacket\n\t/workspace/source/tidb/pkg/server/internal/packetio.go:289\ngithub.com/pingcap/tidb/pkg/server.(*clientConn).writePacket\n\t/workspace/source/tidb/pkg/server/conn.go:485\ngithub.com/pingcap/tidb/pkg/server.(*clientConn).writeError\n\t/workspace/source/tidb/pkg/server/conn.go:1533\ngithub.com/pingcap/tidb/pkg/server.(*clientConn).Run\n\t/workspace/source/tidb/pkg/server/conn.go:1156\ngithub.com/pingcap/tidb/pkg/server.(*Server).onConn\n\t/workspace/source/tidb/pkg/server/server.go:739"]
[2024/07/20 02:01:03.169 +08:00] [ERROR] [terror.go:324] ["encountered error"] [error="connection was bad"] [stack="github.com/pingcap/tidb/pkg/parser/terror.Log\n\t/workspace/source/tidb/pkg/parser/terror/terror.go:324\ngithub.com/pingcap/tidb/pkg/server.(*clientConn).Run\n\t/workspace/source/tidb/pkg/server/conn.go:1157\ngithub.com/pingcap/tidb/pkg/server.(*Server).onConn\n\t/workspace/source/tidb/pkg/server/server.go:739"]
- 从上述分析来看，判断可能是 Haproxy 中存在客户端连接配置 timeout，且 timeout 设置为 60 秒，查看 HAProxy 配置，发现确实如此， HAProxy 中均使用默认的客户端配置。建议根据 HAProxy 在 TiDB 中的最佳实践 配置来进行，或者不使用 HAProxy 来进行压测。
- 关于 SQL 语句执行耗时较长的原因，判断可能与集群长时间处于 CPU 满负载工作有关，另外从监控中也能看到网络连接有存在少量波动的情况。
分析结论
Sysbench 报错的原因是遇到慢 SQL 执行超过 60 秒，达到默认的 HAProxy 中的 timeout client 配置，导致 HAProxy 主动中断连接报错。关于此报错的解决方法有：
- 修改 HAProxy 默认配置，参考 HAProxy 在 TiDB 中的最佳实践
- 不使用 HAProxy 进行分发， sysbench 本身可以配置为多 IP 方式均衡到各 TiDB 节点
- sysbench 运行命令添加 --mysql-ignore-errors，确保 sysbench 客户端不退出