关于故障:数据库故障引发的血案

8次阅读

共计 9676 个字符,预计需要花费 25 分钟才能阅读完成。

题目听起来很骇人听闻,不过的确没有夸张的意思,对于咱们来说的确算得上”血案“了。这个问题最终导致了某个底层的外围利用 15 分钟内不可用,间接导致下层很多利用也呈现了问题,尤其是一些领取相干的业务也呈现了不可用状况。因为故障影响较大,该故障在外部定级很高。故障排查过程也算是一波三折,两头的槽点也比拟多,特地是对网络比拟理解的大佬能一眼看进去问题。这个故障的排查工作我也深度参加了,这里做一下总结,心愿能给大家一些参考。

0. 文章导读

本文约 7000 字,配图 26 张。文章绝对较长,因而这里对文章构造做一些介绍。本篇文章分为 5 个章节,各章节内容概括如下:

  1. 故障景象:本章对故障景象进行了介绍,在浏览后续内容前,需先搞清楚故障景象
  2. 故障排查过程:本章介绍了故障排查过程,并给出了初步论断。
  3. 故障复现:本章基于故障排查论断,针对性的进行了故障复现和验证,并给出了故障的解决措施
  4. 再次摸索:从新对故障排查过程进行扫视,并针对其中疑点再次进行摸索,尝试寻找”假相“
  5. 总结:本章对故障和排查过程中存在的一些问题进行了回顾与总结

须要阐明的是,为了升高图片大小,一些异样栈信息被删除了,但外围调用都在。

1. 故障景象

4 月的某个周日下午 2 点前后,一个外围利用呈现大量的报警,然而一小会后又主动复原了,从监控上看故障持续时间约为 15 分钟。翻看了业务日志,发现外面有很多 druid 相干的报错,看起来像是 druid 出问题了。

图 1:业务线程大量抛出获取连贯超时异样

图 2:druid 连贯生产者线程抛出网络异样

起初从 DBA 那边得悉,阿里云 RDS 因为物理机产生故障,在 13:57 进行了主动主备切换。因为 RDS 主备切换工夫与咱们的利用产生故障的工夫很靠近,因而初步判断该故障和阿里云 RDS 切换无关。从景象上看,阿里云 RDS 执行主备切换后,咱们的利用仿佛没有切换胜利,依然连贯到了故障机上。因为 DBA 之前也做过很屡次主备切换演练,始终都没产生过什么事件,所以这个问题在过后看起来还是挺费解的。

以上就是故障的背景和景象,上面开始剖析故障起因。

2. 故障排查过程

在开展剖析前,先给大家介绍一下 druid 的并发模型,做一些技术铺垫。

2.1 背景常识介绍

druid 数据源应用生产者消费者模型保护连接池,当连接池中没有连贯时,消费者线程会告诉生产者线程创立连贯。生产者创立好连贯后,会将连贯放到池中,并告诉消费者线程取连贯。如果消费者线程在设定工夫没没取到连贯,会抛出一个超时异样。

图 3:druid 并发模型

留神,生产者线程是单线程,如果这个线程在某些状况下阻塞住,会造成大量的消费者线程无奈获取到连贯。

2.2 排查过程

2.2.1 初步排查

这个问题最早是我接手排查的,过后很多信息都还没有,只有异样日志。刚开始排查的时候,我翻看了其中一台机器上的日志,发现日志中只有大量的 GetConnectionTimeoutException 异样,没有 druid 生产者线程抛出的异样。

图 4:消费者线程抛出异样

在消费者线程抛出的异样信息里,蕴含了两个与生产者无关的数据,通过这两个数据能够理解到生产者处于的状态。第一个是 creating,示意生产者以后正在创立连贯。第二个是 createElapseMillis,示意消费者超时返回时,生产者创立连贯所耗费的工夫。上图中,createElapseMillis 值约为 900 秒,这显著是有问题的,阐明生产者线程应该是被阻塞住了。因而依据这个信息,我给出了一个初步论断:

生产者线程被卡住,很可能的起因是在创立连贯时没有配置超时工夫,能够通过在数据库 URL 前面追加一个 connectTimeout 参数解决这个问题。

排查到这里如同也能解释通,然而这里有很多疑难没有解决:到底是在哪个办法上卡住了?配置这个参数是否真的有用,是否复现验证?不答复掉这些问题,这个故障排查论断显然不能压服人。因而后续有更多人参加进来排查,收集到的信息也越来越多。

2.2.2 深刻排查

这个时候,咱们的 DBA 开始找阿里云技术支持沟通,失去的回答 RDS 物理机呈现了故障,触发了主动主备切换机制。另一方面,其余共事具体浏览了更多机器的谬误日志,发现了生产者线程也抛出了异样。

图 5:druid 生产线线程抛出网络异样

奇怪的是,其中有两台机器的日志里找不到生产者的异样。起初询问了利用负责人,才理解到他在 14:10 重启过利用,残余机器还没来得及重启,服务就曾经复原了。不巧的是,我刚开始排查的时候,查看的日志正是被重启过的机器的日志。这里也凸显排查问题时,宽泛收集信息的重要性。除了生产者线程抛出了这个异样,局部消费者线程也抛出了同样的异样:

图 6:消费者线程抛出网络异样

如上,生产者和局部消费者线程都是在卡住 900 多秒后抛出异样,通过查阅 TCP 相干的材料,一起排查的共事认为这个工夫应该是底层网络最大的超时工夫导致的。因而推断 MySQL 物理机产生故障后,不再响应客户端的任何数据包。客户端机器底层网络在通过多次重试后失败后,本人敞开了连贯,下层利用抛出 SocketException。通过材料,咱们理解到 net.ipv4.tcp_retries2 内核参数用于管制 TCP 的重传。Linux 官网文档有相干阐明:

tcp_retries2 – INTEGER

This value influences the timeout of an alive TCP connection,
when RTO retransmissions remain unacknowledged.
Given a value of N, a hypothetical TCP connection following
exponential backoff with an initial RTO of TCP_RTO_MIN would
retransmit N times before killing the connection at the (N+1)th RTO.

The default value of 15 yields a hypothetical timeout of 924.6
seconds and is a lower bound for the effective timeout.
TCP will effectively time out at the first RTO which exceeds the
hypothetical timeout.

图 7:Linux TCP 超时重传状况;图片起源:Marco Pracucci

排查到这里,很多货色都能解释通了,仿佛能够“结案”了。可是状况真的如此吗?因为没有过后的抓包数据,大家还是没法确定是不是这个起因。于是接下来,我依照这个排查论断进行了复现。

3. 故障复现

3.1 筹备工作

为了进行较为精确的复现,咱们在一台与线上配置雷同的 ECS 上部署业务利用。在内网的另一台 ECS 上搭建了一个 MySQL 服务,并把线上数据同步到这个数据库中。因为咱们没法制作 MySQL 物理机故障,因而咱们通过 iptables 配置防火墙策略来模仿因机器故障导致的网络层故障,比方不响应客户端申请。最初咱们通过 arthas 对 druid 生产者线程进行监控,观测连贯创立耗时状况。

3.2 背景常识介绍

在开展后续内容前,先介绍一下 MySQL 驱动与服务端建设连贯的过程。示意图如下:

图 8:MySQL 客户端与服务端通信过程

这里简略解说下,业务利用在建设一个 MySQL 数据库连贯时,首先要实现 TCP 三次握手,待 TCP 连贯建设结束后,再基于 TCP 连贯进行应用层的握手。次要是调换一些信息,以及登录认证。服务端握手信息次要返回的是服务器的版本,服务器承受的登录认证形式,以及其余用于认证的数据。客户端收到数据库的握手信息后,将用户名和明码加密后进行登录认证,随后服务端返回认证后果。上面咱们抓包看一下单方的交互过程。

客户端 ip: 172.***.***.141

服务端 ip: 172.***.***.251

在客户端机器上进行抓包,命令如下:

tcpdump -i eth0 host 172.***.***.251 -w mysql.pcap

抓包后果如下:

图 9:MySQL 连贯建设过程抓包后果 1

图 10:MySQL 连贯建设过程抓包后果 2

咱们后续将应用 Version 作为服务器握手报文段的特色字符串,依据这个特色配置防火墙规定。

3.3 故障复现

本节,咱们除了要验证故障呈现的可能场景,还要验证咱们的解决办法是否无效。在进行复现前,咱们要批改一下 druid 的配置,保障 druid 能够疾速敞开闲暇连贯,不便验证连贯创立过程。

<bean id="dataSource" class="com.alibaba.druid.pool.DruidDataSource" init-method="init" destroy-method="close">
    <!-- 不配置超时工夫,与线上配置保持一致 -->
    <property name="url" value="jdbc:mysql://172.***.***.251:3306/***db" />
    <!-- 最小闲暇连接数 -->
    <property name="minIdle" value="0"/>
    <!-- 初始连接数 -->
    <property name="initialSize" value="0"/>
    <!-- 每隔 1.5 秒检测连贯是否须要被驱赶 -->
    <property name="timeBetweenEvictionRunsMillis" value="1500" />
    <!-- 最小驱赶工夫,连贯闲暇工夫一旦超过这个工夫,就会被敞开 -->
    <property name="minEvictableIdleTimeMillis" value="3000" />
</bean>

3.3.1 故障场景推断

依据生产者线程抛出的异样显示,生产者线程是在与 MySQL 服务端进行应用层握手时卡住的,异样日志如下:

图 11: druid 生产者线程抛出的异样

依据这个报错日志咱们能够判断出问题是出在了 TCP 连贯建设后,MySQL 应用层握手期间时。之所以能够这么必定,是因为代码都到了应用层握手阶段,TCP 层连贯的建设必定是实现了,否则应该会呈现相似无奈连贯的谬误。因而咱们只须要验证 MySQL 客户端与服务端进行应用层握手失败的场景即可,不过咱们能够略微多验证一些其余场景,减少对底层网络行为的理解。上面咱们进行三个场景的模仿:

场景一:服务端不响应客户端 SYN 报文段,TCP 无奈实现三次握手

场景二:TCP 连贯能够失常建设,然而服务端不与客户端进行应用层握手

场景三:连接池中曾经建设好的连贯无奈与服务端通信,导致消费者线程被阻塞

3.3.2 故障复现与验证

3.3.2.1 故障场景一

预期景象:TCP 数据包被抛弃,客户端不停重试。druid 生产者线程被阻塞住,数据库连贯无奈建设

步骤一:场景模仿

登录到 MySQL 服务器,设置防火墙规定,抛弃所有来自客户端的数据包

iptables -I INPUT -s 172.***.***.141 -j DROP

步骤二:触发数据库拜访,察看景象

登录业务机器,应用 arthas 察看 druid 生产者线程执行状况,命令如下:

trace com.alibaba.druid.pool.DruidAbstractDataSource createPhysicalConnection -n 1000 -j

触发一个数据库拜访,因为连接池中没有连贯,druid 会去创立一个连贯。景象如下:

图 12:底层网络故障,druid 新建连贯耗时状况

能够看出,TCP 连贯无奈建设时,druid 的 DruidAbstractDataSource#createPhysicalConnection 办法会消耗掉约 127 秒,且会抛出异样。勾销掉服务端的防火墙规定:察看失常状况下,新建连贯耗时状况:

iptables -D INPUT -s 172.***.***.141 -j DROP

图 13:失常状况下,druid 新建连贯耗时状况

如上,失常状况和异常情况耗时比照还是很显著的,那这 127 秒耗时是如何来的呢?上面剖析一下。

异常情况剖析

TCP 在建设连贯过程中,如果第一个 SYN 报文段失落(没收到另一端的 ACK 报文),Linux 零碎会进行重试,重试肯定次数后终止。初始的 SYN 重试次数受内核参数 tcp_syn_retries,该参数默认值为 6。内核参数阐明如下:

tcp_syn_retries – INTEGER

Number of times initial SYNs for an active TCP connection attempt

will be retransmitted. Should not be higher than 127. Default value
is 6, which corresponds to 63 seconds till the last retransmission
with the current initial RTO of 1 second. With this the final timeout
for an active TCP connection attempt will happen after 127 seconds.

起源:ip-sysctl.txt

留神最初一句话,与咱们应用 arthas trace 命令失去的后果根本是统一的。上面再抓个包察看一下:

图 14:TCP SYN 重传状况

如上,第一个包是客户端初始的握手包,前面 6 个包都是进行重试。第 8 个包收回时,工夫正好过来了 127 秒,与内核参数阐明是统一的。到这里,对于 TCP 连贯无奈创立胜利的问题就说分明了。因为咱们的利用被卡住了 900 多秒,因而显然能够排除 TCP 握手失败的状况了。不过尽管起因不是这个,但如果 druid 生产者线程被卡住 127 秒,那也是相当危险的。如何预防呢?

预防连贯超时问题

通过配置 connectTimeout 参数,能够升高 TCP SYN 重试工夫,配置如下:

jdbc:mysql://172.***.***.251:3306/***db?connectTimeout=3000

再发动一个数据库申请验证一下配置是否无效。

图 15:配置 connectTimeout 参数后,druid 生产者线程超时状况

如上图,druid 生产者线程调用 DruidAbstractDataSource#createPhysicalConnection 耗费了 3 秒,合乎预期,阐明配置无效。客户端会抛出的异样如下:

图 16:客户端抛出的异样细节

3.3.2.2 故障场景二

这次咱们来模仿底层网络失常,然而应用层不失常的状况,即 MySQL 服务器不与客户端进行握手。

预期景象:druid 生产者线程卡住约 900 秒后报错返回

步骤一:模仿场景

在 MySQL 服务器上配置防火墙规定,禁止 MySQL 握手数据包流出。

# 应用 iptables 的 string 模块进行字符串匹配
iptables -I OUTPUT -m string --algo bm --string "5.7.34-log" -j DROP

查看防火墙规定

图 17:防火墙规定列表

步骤二:察看景象

这次咱们通过消费者线程抛出的异样日志来察看 druid 生产者线程的创立工夫,异样日志如下:

图 18:消费者线程异样日志

如上,消费者线程的异样信息里显示生产者线程以及被阻塞了 1247 秒,且这个值随着工夫的推移越来越长。远远超过了 900 秒,与预期不合乎,起因没有深刻探索。不过,咱们仿佛发现了比原故障更重大的问题,排查到这里如同能够停下脚步了。

预防 MySQL 应用层握手超时

因为 connectTimeout 仅作用在网络层,对应用层的通信有效,所以这次咱们要换个参数了。这次咱们应用的参数是 socketTimeout,配置如下:

jdbc:mysql://172.***.***.251:3306/***db?connectTimeout=3000&socketTimeout=5000

设定 socketTimeout 参数值为 5000 毫秒,验证服务端不与客户端握手状况下,客户端是否在 5 秒后超时返回。arthas 监控如下:

图 19:arthas trace 监控

后果合乎预期,druid 生产者线程的确在 5 秒后报错返回了,错误信息如下:

图 20:druid 生产者线程超时返回状况

如上,通过配置 socketTimeout 能够保障 druid 在服务端不进行握手的状况下超时返回。

3.3.2.3 故障场景三

最初一个场景用于复当初 MySQL 物理机出故障,不响应客户端的 SQL 申请。

预期景象:客户端不停重试,直至 924 秒后超时返回

要模仿这种场景,能够在 MySQL 服务端抛弃掉来自客户端的所有数据包,防火墙配置参考下面的内容。间接看景象吧。

图 21:消费者线程超时返回

如上,消费者线程超时返回工夫与 924 秒十分靠近,根本能够断定多次重试失败后,超时返回了。抓包佐证一下:

图 22:TCP 连贯重试状况

最初一个数据包收回的工夫证实了咱们的判断是对的。从下面的抓包后果能够看出,总共进行了 16 次重试。后面说过,TCP 非 SYN 重试受内核参数 ipv4.tcp_retries2 影响,该参数值默认为 15,为什么这里进行了 16 次重试呢?这里简略阐明一下吧,这里的 15 是用来计算超时总时长的,并不代表重传次数,更具体的解释大家 STFW。

场景三的预防形式与场景二雷同,都是通过配置 socketTimeout,就不赘述了。

3.4 小结

到此,整个的复现过程就完结了。通过对故障进行复现,仿佛证实了咱们之前的排查后果是正确的。与此同时,咱们也对 connectTimeout 和 socketTimeout 两个配置的有效性进行了验证,后果也是合乎预期的。然而复现过程中,生产者被卡住的工夫远远长于 900 秒,不合乎预期,还是很让人纳闷的。因为过后大家认为这个看起来比原问题还要重大,且通过 socketTimeout 能够躲避掉,所以就没在细究起因。到此,排查工作就完结了,后续由 DBA 推动各利用配置两个超时参数,这个事件告一段落。

4. 再次摸索

在我筹备写这篇文章前的一周,我花了一些工夫从新看了一下之前的排查文档和谬误日志,有个问题始终围绕在我的脑海里,不得其解。业务日志里生产者和局部消费者线程抛出的异样信息里均蕴含 “Connection reset”,而非后面复现过程中呈现的 “Read timed out”。很显然连贯被重置和连贯超时不是同一种状况,那么问题出在了哪里呢?是不是咱们所复现的环境与阿里云 RDS 有什么一样的中央,导致复现后果与理论不合乎。于是我查阅了一些和阿里云 RDS 相干的材料,有一张架构图吸引了我。

图 23:阿里云 RDS 高可用架构;起源:阿里云 RDS 技术白皮书

从这张图里能够看出,咱们搭建的复现环境短少了 SLB,但 SLB 只是一个负载平衡,难道它会中断连贯?答案是,我不晓得。于是又去找了一些材料理解在什么状况下会产生 RST 包。状况比拟多,局部如下:

  1. 指标端口未监听
  2. 通信单方中的一方机器掉电重启,实质上也是指标端口未监听
  3. 通信门路中存在防火墙,连贯被防火墙策略中断
  4. 服务端监听队列满了,无奈再承受新的连贯。当然服务端也能够间接抛弃掉 SYN 包,让客户端重试
  5. TCP 缓冲区溢出

理解了 RST 产生的几种状况,咱们再尝试推理一下阿里云 RDS 在产生相似故障后,会执行什么策略。思考到他们的技术人员也要排查问题,因而最可能的策略是仅将故障机从 SLB 上摘除,故障机器不重启,保留现场。如果是这样,那么故障机器并不会发送 RST 数据包。其余策略,比方杀掉 MySQL 过程或者让故障机关机,都会发送 FIN 数据包失常敞开连贯,这个我抓包验证过。排查到到这里,思路又断了,切实想不通哪里会在 900 多秒时收回一个 RST 包进去。目前惟一能狐疑的可能就是 SLB,然而 SLB 毕竟只是个负载平衡,应该会像防火墙那样依据策略阻断连贯。因为没有其余思路了,当初只能关注一下 SLB。因为对 SLB 不相熟,又是一通找材料,这次如同有点头绪了。

一开始通过 Google 搜寻 SLB RST,没找到有用的信息。思考到 SLB 是基于 LVS 实现的,把 SLB 换成 LVS 持续搜寻,这次找到了一些有用的信息。通过这篇文章 负载平衡超时工夫 理解到阿里云 SLB 在连贯闲暇超过设定值后,会中断连贯。于是又找到 SLB 的官网文档,在一个 FAQ 里找到了冀望的信息。

图 24:阿里云官网文档对于负载平衡 FAQ

当初思考这种状况,故障机器底层网络并没问题,但处于应用层的 MySQL 处于僵死状态,不响应客户端申请。当 TCP 连贯闲暇工夫超过 900 秒后,SLB 客户端发送了一个 RST 断开连接。看到这句话时十分开心,于是我在阿里云买了两台 ECS 和一个 SLB 验证了一下,SLB 的超时工夫放弃默认值 900 秒。应用 nc 工具在一台 ECS 上启动一个 TCP 服务器,在另一台机器上,同样能够应用 nc 命令连贯这个服务器。只不过咱们不能直连,而是同通过 SLB 连贯。示意图如下:

图 25:SLB 验证环境

环境搭建好后,抓包验证了一下。

图 26:SLB 超时机制验证

到这里我曾经拿到了想要的后果,目前仿佛能够下结论说咱们的利用在卡住 900 多秒后,被 SLB 发送 RST 断开连接了。但在后续的验证中发现,连贯闲暇时,RDS 的 TCP 层开启了 keepalive 机制,每隔一分钟发一个数据包做连贯保活,此时 SLB 不会被动断开连接。除非故障机器被隔离了,无奈与 SLB 通信。排查到这里,根本放弃医治了。如果 RST 包是 SLB 收回的,连贯应该处于真正闲暇状态,不存在保活的数据包。因为没有过后的抓包数据,加上对阿里云外部故障机器解决机制不理解,目前没法给出更正当的论断了。权且先用这个论断”搪塞“一下,也欢大家集思广益,一起交流学习。

5. 总结与思考

本次故障排查耗时十分长,也破费了我很多精力。尽管如此,还是没有找到最终起因,感觉比拟遗憾。不过不论后果怎么样,总的来说,这次故障的排查过程让我受害良多。一方面学到了很多常识,另一方面也发现了一些有余。上面简略对这次故障进行总结。

首先,这次的故障偶发性十分大,是公司应用阿里云服务几年来第一次呈现这样的状况。其次,MySQL 服务端故障起因也比较复杂,依据阿里云技术的回复,触发主备切换是因为 RDS 所在的物理机文件系统查看有异样。因而对咱们来说,复现的老本也十分高。同时,本次故障和网络的关系很亲密,然而很遗憾,咱们没有过后的抓包数据。加上故障复现老本太高,且未必能 100% 复现,导致这份要害的信息缺失。进而导致咱们不分明底层的通信状况是怎么的,比方有没有产生重传,服务端有没有发送 TCP 保活数据包等。最初,在后面几个因素的作用下,咱们只能通过收集各种信息,并联合故障景象进行猜测,而后逐个验证猜测的合理性。当然限于咱们的常识边界,可能还有很多状况咱们没有思考到,或者已有的猜测存在显著不合理之处,也欢送大家斧正。

在这次的排查问题过程中,因为集体经验不足,也裸露了很多问题。文章的最初同样做下总结,心愿能给大家提供一些参考。

  1. 排查初期没有宽泛收集信息,此时无论是做的猜测还是下的论断都是不牢靠的
  2. 过于关注某些故障景象,导致陷入了细节,没能从整体进行扫视。岂但做了很多无用功,也没失去后果
  3. 计算机网络常识深度有余,对一些显著景象熟视无睹,同时也做了一些谬误猜测。后续须要重点补充这方面的常识
  4. 疏忽了一些重要的差别,复现过程中呈现的景象是超时,而理论状况是连贯被重置,这个差别过后没有深究
  5. 假相只有一个,如果有些景象无奈失去正当解释,就阐明问题的本源仍未找到,此时不要强行解释

本篇文章到此结束,感激浏览。

参考内容

  1. Linux TCP_RTO_MIN, TCP_RTO_MAX and the tcp_retries2
  2. ip-sysctl.txt
  3. 聊一聊重传次数
  4. 你所须要把握的问题排查常识
  5. 阿里云云数据库 RDS 版技术白皮书
  6. 负载平衡超时问题
  7. 阿里云负载平衡服务 FAQ
  8. TCP RESET/RST Reasons

本文在常识共享许可协定 4.0 下公布,转载请注明出处
作者:田小波
原创文章优先公布到集体网站,欢送拜访:https://www.tianxiaobo.com


本作品采纳常识共享署名 - 非商业性应用 - 禁止演绎 4.0 国内许可协定进行许可。

正文完
 0