作者： 数据源的TiDB学习之路



问题现象

使用 sysbench + haproxy 对 TiDB 进行压测，运行 57 小时后遇到报错。

一次 sysbench 长稳测试过程中连接中断的问题分析排查_slowquery



问题分析步骤

  1. 根据报错提示 error 2013(Lost connection to MySQL server during query)，判断是客户端连接中断，对应正在执行的语句为 SELECT SUM(k) FROM sbtest3 WHERE ID BETWEEN 10060469 AND 10060568。
  2. 收集 Clinic，并上传 Clinic Server。
  3. 首先查看TiDB 监控，判断问题发生在 02:01 分左右，当时发生了 Slow Query，随之业务几乎停止，判断可能跟 Slow Query 有关。

一次 sysbench 长稳测试过程中连接中断的问题分析排查_slowquery_02

  1. 查看 Performance 监控，在 02:01~02:02 分之间，确实发生了连接中断，与压测报错一致。

一次 sysbench 长稳测试过程中连接中断的问题分析排查_haproxy_03

  1. 在报错之前，集群整体的内存比较平稳，CPU 基本处于满负荷运行状态。

一次 sysbench 长稳测试过程中连接中断的问题分析排查_slowquery_04

  1. 查看 Slow Query 监控，发现压测报错的语句显示在慢查询列表中，进一步查看执行计划发现时间主要消耗在 Coprocesor Executor Time 部分。

一次 sysbench 长稳测试过程中连接中断的问题分析排查_tidb_05

一次 sysbench 长稳测试过程中连接中断的问题分析排查_timeout_06

  1. 进一步查看 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"]
  1. 从上述分析来看，判断可能是 Haproxy 中存在客户端连接配置 timeout，且 timeout 设置为 60 秒，查看 HAProxy 配置，发现确实如此， HAProxy 中均使用默认的客户端配置。建议根据 HAProxy 在 TiDB 中的最佳实践 配置来进行，或者不使用 HAProxy 来进行压测。

一次 sysbench 长稳测试过程中连接中断的问题分析排查_slowquery_07

  1. 关于 SQL 语句执行耗时较长的原因，判断可能与集群长时间处于 CPU 满负载工作有关，另外从监控中也能看到网络连接有存在少量波动的情况。

一次 sysbench 长稳测试过程中连接中断的问题分析排查_slowquery_08

一次 sysbench 长稳测试过程中连接中断的问题分析排查_tidb_09



分析结论

Sysbench 报错的原因是遇到慢 SQL 执行超过 60 秒，达到默认的 HAProxy 中的 timeout client 配置，导致 HAProxy 主动中断连接报错。关于此报错的解决方法有：

  1. 修改 HAProxy 默认配置，参考 HAProxy 在 TiDB 中的最佳实践
  2. 不使用 HAProxy 进行分发， sysbench 本身可以配置为多 IP 方式均衡到各 TiDB 节点
  3. sysbench 运行命令添加 --mysql-ignore-errors，确保 sysbench 客户端不退出