ARTICLE DETAIL

资讯详情

深耕网站视觉设计与运营推广的一线实战洞察。

MySQL连接超时排查:Read timed out与Communications link failure

MySQL连接超时排查:Read timed out与Communications link failure 1. 报错信息拆解Communications link failure 和 Read timed out 分别想告诉你什么1.1 一段真实堆栈里藏着三段关键信息当你在 Java 应用日志里看到这样一串报错com.mysql.cj.jdbc.exceptions.CommunicationsException: Communications link failure The last packet sent successfully to the server was 0 milliseconds ago. The driver has not received any packets from the server. at com.mysql.cj.jdbc.exceptions.SQLError.createCommunicationsException(SQLError.java:174) ... Caused by: java.net.SocketTimeoutException: Read timed out at java.net.SocketInputStream.socketRead0(Native Method) ...大部分人的第一反应是MySQL 是不是挂了我一开始也这么想。实际排查多了会发现这组報错往往意味着服务端还活着但客户端到服务端之间的链路或者连接池里的某个连接已经处于不可用状态。整个堆栈里其实藏着三段独立的信息分别对应三个不同方向的排查线索。第一段是异常头Communications link failure这是 MySQL Connector/J 对所有连接层面异常的统一包装。不管是网络断开、服务端重启、还是 socket 超时驱动最终都会把它包装成这个异常头。所以光看这一行只能确定数据库连接通信失败还不能确定具体失败点。第二段是The last packet sent successfully to the server was 0 milliseconds ago. The driver has not received any packets from the server.这句话是排查的关键锚点它告诉你客户端最后一次成功向服务端发送报文是什么时候。这个时间戳是整个问题定位的切入点。第三段是Caused by: java.net.SocketTimeoutException: Read timed out这才是真正的底层原因。Read timed out表示 TCP 连接已经建立客户端发了请求服务端在规定时间内没有回任何数据于是驱动放弃等待。这个异常和SocketException: Connection reset不一样跟Connection refused也不一样后面我会专门展开。1.2 最后一次成功发送报文这句话应该怎么读Connector/J 在构造 CommunicationsException 的时候会带上两个关键时间点最后一次成功发送报文的时刻、最后一次从服务端收到报文的时刻。不同 MySQL 驱动版本的措辞略有差异但逻辑是一致的。如果这一句显示was 0 milliseconds ago说明连接池刚刚把这连接拿出来、应用正准备执行 SQL就发现这条连接已经死了。这种情况下问题多半出在连接曾经空闲过一段时间空闲期间服务端把它回收了或者中间网络设备把它静默断开了而客户端完全没感知直到再次使用才暴露。如果显示的是一个比较大的毫秒数比如 723000 毫秒约 12 分钟说明连接长时间没有发送过任何请求也就是典型的空闲连接。这时候优先怀疑的仍然是服务端wait_timeout和连接池maxLifetime的配合问题。如果同时给出最后一次成功收到服务端报文的时刻对比一下也能获得不少信息。比如收到报文是 10 秒前发送报文是 0 毫秒前说明连接在最近 10 秒内还是活的那问题更可能出现在这个时间窗口内发生的服务端重启、网络抖动、或者服务端主动断连。1.3 Read timed out 与 connect timed out 的边界要分清楚很多同学把Read timed out和连接超时混为一谈排查时容易走弯路。connectTimeout控制的是TCP 连接建立阶段的超时。JDBC 驱动发起 TCP 三次握手时如果在 connectTimeout 内 SYN 包没有得到回应就会抛出连接超时类异常通常表现为Communications link failure底下跟着Caused by: java.net.ConnectException: Connection timed out: connect。这时候说明服务端 IP 不可达、端口没有监听、或者防火墙直接把包丢了。socketTimeout也就是Read timed out的触发者控制的是TCP 连接建立之后、等待响应数据的超时。客户端已经成功把 SQL 报文发到了服务端但服务端迟迟没有返回任何字节这个迟迟超过了 socketTimeout 的阈值驱动就会放弃等待。用大白话类比connectTimeout 是你给一个门店打电话铃响了几声没人接你就挂了socketTimeout 是你电话已经接通说了需求结果对方沉默不语超过你能忍受的时间你主动挂断了。两种超时的含义完全不同对应的问题场景也完全不同——前者的关键是连不上后者的关键是连上了但等不到响应。2. 三个高频触发场景从偶发到必现对应的故障模型各不相同2.1 场景一连接池里堆满了僵尸连接这是我在实际项目中遇到频率最高的场景。MySQL 服务端有一个wait_timeout参数默认值是 28800 秒也就是 8 小时。任何非交互连接如果在这个时间内没有发送任何请求服务端就会主动关闭它。而连接池HikariCP、Druid、DBCP通常会保留一批空闲连接备用。如果你的连接池里某个连接的存活时间超过了服务端的wait_timeout服务端那边先把它关了。由于 TCP 连接的关闭不是每次都能让客户端立刻感知到很多情况下客户端还认为这条连接是好的。等到应用从连接池拿到这条连接、发出第一条 SQL 时才发现对端已经不存在了。这个问题的典型特征是报错集中在业务低谷后的第一波请求比如早上 9 点上班之后的头几分钟、午休之后、或者测试环境隔了一夜再跑任务。报错信息里The last packet sent successfully to the server was 0 milliseconds ago出现的频率很高。2.2 场景二慢查询耗尽了 socketTimeout另一种常见情况是SQL 本身没问题、连接也没断但查询执行时间超出了客户端设置的socketTimeout。比如有个报表查询正常要跑 50 秒而应用把 socketTimeout 设成了 30 秒那么客户端在第 30 秒就抛Read timed out了。注意此时服务端的查询可能还在执行会在 MySQL 的SHOW PROCESSLIST里看到这条 SQL 仍然处于Sending data或Copying to tmp table状态。这种场景的特征是报错跟特定 SQL 强相关只要某个大查询一跑就超时其他小查询完全正常。而且当你去数据库端看的时候往往能看到连接还在、线程还在跑只是客户端已经不等待了。这种场景下调整 socketTimeout 只能暂时缓解真正要处理的是慢查询本身——加索引、改 SQL、拆批或者把它挪到只读从库去执行。我遇到过一个典型案例一张几千万行的流水表联表统计接口每次都跑一分多钟socketTimeout 调到 120 秒之后报错确实少了但接口的 P99 延迟变得非常难看。后来把统计逻辑改成离线预聚合接口从 60 秒降到 200 毫秒那条 socketTimeout 反而可以调回 30 秒以内。说白了Read timed out只是报警器报警器响了你要去救火而不是把报警器音量调低。2.3 场景三网络设备静默超时与服务端重启第三种情况是最隐蔽的因为链路两端的当事人都觉得自己没做错什么问题出在中间的设备上。云环境里的负载均衡、NAT 网关、防火墙经常会在连接空闲一段时间后静默丢弃会话记录既不发送 RST也不通知任何一端。对数据库服务来说这条连接还挂着对应用来说这条连接也看起来正常。但实际数据包早就被中间设备扔掉了。等下一次应用发请求TCP 数据包出去石沉大海客户端一直等到 socketTimeout 到了才抛出Read timed out。另一种常见诱因是 MySQL 服务端重启。无论是 OOM 导致 mysqld 挂掉后自动拉起还是 DBA 晚上做维护重启实例都会让所有存量连接瞬间失效。客户端不会立即收到通知而是在下一次请求时才感知到连接已断。这时的异常可能是Read timed out也可能是Connection reset取决于重启时 TCP 连接的表现。这种场景的排查需要跳出应用和数据库本身把目光放到网络拓扑和监控上有没有负载均衡防火墙的空闲会话超时设了多久MySQL 是不是有自动重启的策略把这些信息跟报错时间点对齐往往能找到隐藏的故障源。3. 客户端、服务端与连接池三个维度的参数怎么做到位3.1 JDBC URL 里必须明确的两个超时参数如果你的 JDBC 连接串还是jdbc:mysql://10.0.0.10:3306/appdb这种裸配置那我建议尽快把两个超时参数补上。以 MySQL Connector/J 8.x 为例默认情况下connectTimeout为 0不限制socketTimeout也为 0不限制。不限制的后果是当网络真正出问题时应用线程会无限期挂起直到 TCP 层超时或者运维人员介入。我习惯的配置是这样的jdbc:mysql://10.0.0.10:3306/appdb?connectTimeout3000socketTimeout60000useUnicodetruecharacterEncodingutf8connectTimeout3000TCP 握手最多等 3 秒连不上就快速失败避免应用线程长时间阻塞。socketTimeout60000发出 SQL 后等待响应最多 60 秒超过就抛Read timed out。这个值的设定要参考业务里最慢的可接受查询如果确实有报表查询要跑 90 秒就得往上调但要注意socketTimeout 是每条语句的等待时间不是整个事务的时限。如果你的事务里包含多条语句每条语句都有独立的等待上限累计耗时会比你想得更长这点在设定时容易踩坑。3.2 MySQL 服务端参数wait_timeout 和它的兄弟们登录数据库执行这几条 SQL先看清楚现状SHOW VARIABLES LIKE wait_timeout; SHOW VARIABLES LIKE interactive_timeout; SHOW VARIABLES LIKE connect_timeout; SHOW VARIABLES LIKE max_allowed_packet;wait_timeout前面已经说过是服务端回收空闲连接的阈值。interactive_timeout是针对交互式连接比如 mysql 命令行客户端的通常在本地调试时需要关心。connect_timeout是服务端等待客户端完成握手包的超时默认 10 秒一般不需要动。max_allowed_packet如果设置得太小大报文会直接被服务端拒绝也会表现为通讯异常不过那个报错一般会带上 packet 相关提示容易区分。如果发现wait_timeout被改成了很小的值比如 60 秒而连接池没有做相应配合那报错频率就会非常高。我遇到过一个测试环境DBA 为了控制连接数把 wait_timeout 调成了 120 秒结果应用侧的 HikariCP 还把连接闲置在池里于是只要应用空置两分钟以上下一波请求必然报Communications link failure。3.3 连接池的三项设置maxLifetime、空闲检测与探活连接池是第三方配置的重灾区。以 HikariCP 为例几个关键参数和它们的逻辑关系maxLifetime连接池中连接的最大存活时间。官方文档明确要求这个值必须小于数据库或基础设施施加的连接超时时间。如果有 MySQLwait_timeout8 小时把 maxLifetime 设在 30 分钟甚至 15 分钟都合理如果wait_timeout被改成了 300 秒maxLifetime 就必须低于 300 秒否则池里一样会混入僵尸连接。keepaliveTimeHikariCP 在连接空闲时会发送 keepalive 探测包防止中间设备回收。这个参数和idleTimeout配合使用能有效降低静默断连的概率。connectionTimeout连接池获取连接的最大等待时间当池子被占满时应用线程会在此时间内等待连接释放超时则抛出SQLTimeoutException。如果你用的是 Druid那要关注的是testWhileIdle、timeBetweenEvictionRunsMillis、minEvictableIdleTimeMillis和validationQuery。Druid 默认的validationQuery就是SELECT 1开启testWhileIdle后它会在连接空闲时定期做一次轻量探测把已经失效的连接从池里剔除。需要注意的是探活机制只能降低拿到坏连接的概率并不能完全杜绝。在两次探活之间连接仍然可能被服务端或网络设备回收。所以最终极的兜底还是让连接池的连接存活时间小于服务端超时时间。3.4 参数配置总表与设定建议以下是我经过多次事故后沉淀的一张配置表覆盖客户端、服务端、连接池三个层次层次参数默认值常见建议值说明JDBC 驱动connectTimeout0不限制3000–5000 ms控制 TCP 握手等待避免线程无限挂起JDBC 驱动socketTimeout0不限制30000–60000 ms控制请求发出后等待响应的上限与最慢查询对齐MySQL 服务端wait_timeout28800 s保持默认或结合 maxLifetime 调大空闲连接回收阈值MySQL 服务端max_allowed_packet64 MB按实际报文大小调整过小会导致大报文写入失败HikariCPmaxLifetime1800000 ms小于 wait_timeout如 1200000 ms必须小于所有中间层会话超时HikariCPkeepaliveTime030000 ms空闲时发探测包维持会话HikariCPconnectionTimeout30000 ms30000 ms池满时等待连接的最长时间DruidtestWhileIdletruetrue空闲连接定期探活DruidtimeBetweenEvictionRunsMillis60000 ms60000 ms探活周期DruidvalidationQuerySELECT 1SELECT 1探活语句这张表不是死规矩。不同业务、不同网络环境对超时的容忍度不一样但有一条原则是通用的客户端所有超时时间都要有上限连接池所有生命周期参数都要比基础设施的超时时间短一截。有了这个原则大部分谜之断连都能在参数层面被消灭掉。4. Ubuntu 18.04 下 rosdep update 报 The read operation timed out同一种报错完全不同的排查思路4.1 rosdep update 背后发生了什么如果你在 Ubuntu 18.04 上装 ROS Melodic跑sudo rosdep init或者rosdep update时可能会看到ERROR: unable to process source [https://raw.githubusercontent.com/ros/rosdistro/master/rosdep/...]: The read operation timed out同样是 read timed out但这里和 JDBC 的场景完全不同。rosdep update做的事情是通过 Python 的 urllib 去下载 ROS 官方的 rosdistro 索引文件以及各个发行版的依赖描述文件。这些文件默认托管在 GitHub 的 raw 域名下。当你的网络环境到那个域名之间的链路不稳定、响应慢或者客户端在读取响应体时长时间收不到数据urllib 就会抛出The read operation timed out。这个报错经常被误认为是 rosdep 工具本身的问题甚至有人反复重试几十次。但实际上rosdep 只是忠实地把网络层的超时结果抛给了你。直接重试属于碰运气链路质量不改善结果大概率还是超时。4.2 先做两步定位curl 看到的是真话要验证我的判断先别急着重跑 rosdep用 curl 模拟一下它实际要访问的地址curl -v --connect-timeout 5 --max-time 15 https://raw.githubusercontent.com/ros/rosdistro/master/index-v4.yaml -o /dev/null--connect-timeout 5控制 TCP 建连等待--max-time 15控制整个请求的总时限。如果 curl 在 15 秒内完成了请求说明当前时刻链路是通的那 rosdep 的超时可能是偶发如果 curl 直接超时或者在 TLS 握手阶段卡住不动那说明链路问题不是 rosdep 自身能解决的。再顺手检查一下 DNS 解析是否正常nslookup raw.githubusercontent.com如果 DNS 解析返回的地址有问题、或者解析本身就很慢也会导致 urllib 在连接阶段就卡住。另外检查一下当前 shell 是否残留了代理环境变量这些变量会直接影响 urllib 的请求行为env | grep -i proxy如果之前配置过http_proxy、https_proxy用于其他场景但代理服务已经失效rosdep 的所有请求都会超时。这个看起来不起眼的点在排查中很容易被忽略。4.3 换源用镜像源替代默认地址确认是网络链路问题后比较稳妥的做法是换源而不是反复重试。社区里常用的是清华大学开源软件镜像站提供的 ROS distro 镜像。在更新之前把 rosdistro 的索引地址指过去export ROSDISTRO_INDEX_URLhttps://mirrors.tuna.tsinghua.edu.cn/rosdistro/index-v4.yaml rosdep updateROSDISTRO_INDEX_URL这个环境变量是 rosdistro 库读取索引文件地址的入口前面的sudo rosdep init也会受它影响。如果你的rosdep init阶段就卡住同样可以先设置这个环境变量再执行。如果镜像源不可用还有一个更稳的办法把 rosdistro 仓库通过 git 克隆到本地可以从 GitHub也可以从代码托管镜像站拉取然后用本地文件路径作为索引git clone https://github.com/ros/rosdistro.git ~/rosdistro export ROSDISTRO_INDEX_URLfile:///home/user/rosdistro/index-v4.yaml rosdep update本地文件路径没有网络读取环节自然不会超时。唯一的代价是需要维护一份仓库的更新但 ROS 依赖列表更新不频繁隔一段时间手动git pull一次就够了。4.4 换源之后仍然超时的检查方向如果你换了镜像源还是时好时坏那就需要从更基础的环境入手。首先是 Ubuntu 18.04 上 Python 3.6 的系统证书问题有时证书验证环节就会消耗大量时间可以考虑更新ca-certificatessudo apt update sudo apt install --reinstall ca-certificates其次是检查系统里是否有企业级安全代理或者流量审计设备这些设备如果对 HTTPS 长连接做拦截也可能导致响应体读取中断。这种情况下与其跟设备配置较劲不如直接采用本地文件索引的方式从源头上绕开对公网 HTTPS 链路的依赖。5. 网络链路逐段排查从 ping 到 tcpdump 的完整路线5.1 ping 通不代表 TCP 服务可用无论是数据库连接问题还是 rosdep 的超时问题只要怀疑是链路造成的我都会按一条固定的路线排查从最粗的粒度逐步收敛到最细。第一步才是很多人会先做的ping。但要知道ping 走的是 ICMP 协议它只能说明主机在这条链路上是可达的完全不能说明3306 端口或者其他 TCP 服务可用。很多服务端防火墙会放行 ICMP 但限制 TCP 端口或者反过来禁止 ICMP 但开放 TCP。所以 ping 的结果只能作为参考。我见过 ping 完全正常、但 3306 端口被安全组挡死的情况也见过 ping 不通、但业务端口其实正常的情况。5.2 用 telnet 或 nc 验证端口连通性更靠谱的下一个动作是用 TCP 层工具直接验证端口telnet 192.168.1.10 3306如果输出Connected to 192.168.1.10说明 TCP 链路是通的。如果提示Connection refused说明目标端口没有服务在监听。如果是Connection timed out说明数据包出去了但没有回应通常是防火墙丢包或路由问题。nc 是这个动作的脚本化版本nc -vz -w 3 192.168.1.10 3306-w 3表示最多等 3 秒。这个命令适合写进脚本里做批量探测也适合在容器或者跳板机上快速验证。5.3 DNS 解析异常导致的间歇性超时很多间歇性超时的原因其实在 DNS。应用端如果配置了域名连接数据库但 DNS 服务器响应慢、或者返回了多个 IP 其中个别不可用就会出现有时候连得上、有时候连不上的诡异现象。排查时用nslookup db.example.com dig short db.example.com如果每次解析出来的 IP 不一致或者解析时长波动很大那就要怀疑 DNS。处理方式也很直接在应用服务器/etc/hosts里固定数据库的域名映射或者在连接串里直接改成 IP。但要注意数据库 IP 变更时 hosts 文件不会自动更新所以这只能作为应急手段。5.4 tcpdump 抓包观察 SYN 重传和 RST当 ping、telnet、DNS 都排查完还没有结论时就该请出 tcpdump 了。在应用服务器上执行sudo tcpdump -i eth0 -n host 192.168.1.10 and port 3306 -w /tmp/mysql_debug.cap复现一次报错之后CtrlC 停掉抓包然后再分析。重点看三类现象如果看到 SYN 包反复重传但始终没有 SYN-ACK 回应说明数据包在中间某段被丢弃或者服务端没有进程监听。如果看到连接建立成功后隔一段时间直接出现 RST 包说明对端主动重置了连接多半是服务端或中间设备主动回收。如果看到有数据包发出服务端也回了 ACK但后续业务数据迟迟不来直到客户端发出 FIN 或超时重传那就是应用层响应慢的问题方向要转向慢查询排查。tcpdump 输出的信息量很大初学者拿到抓包文件不用怕先用 Wireshark 打开过滤tcp.analysis.retransmission和tcp.analysis.flagsWireshark 会直接标出它认为的问题点比自己盯着十六进制看快得多。6. 实战经验我处理这类报错时的固定顺序与沉淀下来的习惯6.1 第一时间要保存的三样东西遇到Communications link failure或Read timed out我现在的第一反应不是改配置而是先存档。三样东西必须记下来完整堆栈尤其是 Caused by 链、报错发生的精确时间点、以及当时相关的监控指标。完整堆栈决定了排查方向。Caused by 是Read timed out还是Connection reset对应的排查路线完全不同。报错时间点要和业务低谷期、服务端重启时间、网络设备维护窗口去对齐时间对上了方向基本就出来了。监控指标包括 MySQL 的Threads_connected、Aborted_clients、应用线程数和活跃连接数这些数据在事故发生后很难补采所以平时就要让监控系统保留一定时长的历史数据。6.2 从 MySQL 状态变量里找服务端的态度登录 MySQL 执行SHOW GLOBAL STATUS LIKE Aborted_clients; SHOW GLOBAL STATUS LIKE Aborted_connects; SHOW GLOBAL STATUS LIKE Threads_connected;Aborted_clients表示客户端已经建立连接但异常终止的连接数。这个数字如果在你出问题的时段有明显增长说明很多连接是在服务端侧被中断的方向指向wait_timeout或者网络断连。同时记得看一眼 MySQL 错误日志老版本 MySQL 里很常见的一条日志是Aborted connection xxx to db: appdb (Got timeout reading communication packets)这条日志的意思是服务端等待客户端发送数据超时主动断开了连接。看到它几乎可以确定问题就出在空闲连接回收上——客户端把一条连接闲置太久服务端等不到任何报文于是先关掉了。6.3 一点最容易被忽视的对比排查技巧如果你面前有两个环境一个正常、一个报错别急着在出问题的环境上做各种修改先对比两个环境的连接串、连接池配置、MySQL 参数。我处理过很多所谓的疑难杂症最后发现就是某个环境里有人把socketTimeout设成了 10 秒、或者maxLifetime设得比wait_timeout还长。另外在应用侧写一个小的连通性检查脚本很值得。每隔一分钟用 mysql 客户端执行一次SELECT 1记录耗时和结果。这个脚本跑上一天你就能得到一份链路健康曲线比在报错时才去排查高效太多。具体操作很简单while true; do mysql -h 192.168.1.10 -uapp -papp123 -e SELECT 1 21 | grep -v Warning sleep 60 done把输出重定向到日志文件第二天直接看时间轴上的失败点很快就能判断问题是周期性出现、跟业务低谷重合还是随机散布在网络层。6.4 长期稳定性建设比单次救火更值得投入处理完一次事故我会习惯性复盘问题出在参数配合、网络设备还是慢查询对应的长期措施分别是配置基线、网络监控告警和慢查询治理。比如把连接池参数和 MySQL 参数写进一套配置基线环境变更时先检查基线再上线网络方面对数据库端口的连通性做周期探测提前发现链路劣化慢查询方面打开slow_query_log配合mysqldumpslow定期分析主动消灭那些会撞上 socketTimeout 的大查询。回到开头那句话Communications link failure和Read timed out并不是一个数据库挂了的信号而是一个链路状态需要你认真对待的信号。只要你愿意从异常头、Caused by、时间点、参数配合这四个维度去拆绝大多数问题都可以在半小时内定位到根因。这也是为什么我现在看到这类报错时第一反应不再是紧张而是先打开监控面板把堆栈和监控对齐然后按部就班地查下去。
返回列表