前言每日BUG排查系列是一些简单的BUG排查，笔者将在这里介绍一些简单的BUG排查技巧，同时积累素材^_^。一天下午在Bug现场，笔者在研究某个问题的时候，人气很高。开发者突然找到笔者，上线某系统突然无法消费队列。队列不消耗可以看作是一个日常问题。先冷静的把流量切换到别的机房，让问题先恢复。消息累积之后，就是看没消费的队列到哪里去了，打开mq（消息中间件）控制台，全部都累积到mq上了。同时开发向笔者反馈只有这个队列已经积累，其他队列依然可以正常消费。在问题发生的时候，笔者也得到了一个关键信息。这个问题是DBA操作关联数据库后出现的。当时由于操作注入的数据库很大，导致数据库主从切换，导致VIP丢失。从时间点来看，应该是这个问题的原因。既然jstack卡住了，那就老办法，看看jstack，看看我们的mq消费线程在干什么：ActiveMQSessionTask-1234atjava.net.SocketInputStream.socketRead0……atcom.mysql.jdbc.MysqlIO.readFully。....atorg.apache.activemq.ActiveMQMessageConsumer.dispatch...很明显，都卡在了MysqlIO.readFully上，也就是数据库读取，再也不会下去了。如果没有超时，那一定是没有超时。查看了他们的配置，确实是没有配置。之前系统已经整理过很多次了，没想到这种鱼漏网了。问题分析本身很简单。但是这里我想多说说为什么数据主从切换会造成这样的现象。mha切换如图所示。mha的切换逻辑是从DB的oldmaster上去掉vip，然后把vip挂在DB的新master上。为了观察这种行为，作者编写了一个python程序进行测试。据观察，在移除VIP的那一刻，双方的通讯已经不正常了。但是tcp连接状态仍然是ESTABLISHED。为什么tcp状态还是ESTABLISHED，因为去掉ip不会让已有的socket马上感知到，那么socket什么时候才能感知到我们的连接已经被gg了呢？当前场景下，如果应用没有设置sockettimeout，有几种可能：如果此时App正在向这个五元组发送请求；如果数据库正在写回一个请求到这个五元组。从以上两种情况，我们可以知道是哪一方做出了发送动作，哪一方可以通过reset或者尝试次数过多的方式感知到连接已经gg了。很明显，因为我们的应用卡在了socketread，说明我们的App应用不是在发送数据，而是在等待MySQL的返回，那么App是如何感知到连接实际上死掉的，而不设置超时呢？好的。由于tcpkeep-alive定时器不是应用程序发送的，所以轮到我们使用tcpkeep-alive定时器tcp_keepalive。linux下默认内核参数为：/proc/sys/net/ipv4/tcp_keepalive_time7200两小时/proc/sys/net/ipv4/tcp_keepalive_probes9探测9次/proc/sys/net/ipv4/tcp_keepalive_intvl75s每次探测间隔75stcp保活定时器默认7200s开始，即2小时后，检测9次，每次间隔75s。如果9次后有明显失败或没有返回，则确定连接gg。在我们的场景中，应用程序会在两个小时后开始保持活动状态，对端会在第一次检测时发送重置，以便应用程序感知到连接gg。这时，应用程序返回。也就是说，如果不设置超时时间，在这种情况下，应用线程会卡住2个小时！如果DB进程宕机或者重启，如果不是MHA开关，而是DB进程重启或者宕机，因为Linux内核没有down保持。内核会自动关闭DB进程所属的socket，即发回FIN报文。然后应用程序可以立即从套接字读取系统调用返回。物理机宕机时，物理机宕机不丢失VIP，应用不设置超时时间。如果是数据发送阶段，tcp_reties会在2次重试后从socketread系统调用返回。如果没有发送数据，则与上面的描述基本相同，2小时后启动保活定时器。唯一不同的是，这次需要检测9次，所以需要多花11分钟左右的时间来感知。为什么线下预演没有问题？VIP漂流的操作已经在线下演练过了。当时应用切换的很快。怎么卡在网上了？这是因为在没有离线添加IO挂起的情况下，SQL处理时间过长。SQL返回很快，所以我们的离线线程只有很小的概率会卡在socketread上。而且有几十个线程在消耗，一两张卡是无关大局的。在我们的例子中，因为SQL处理时间太长，基本上所有线程都在VIP漂移的瞬间执行socketread，也就是等待数据库返回，导致所有线程挂起等待。这个时候只能等待tcp_keepalive或者重启。本文转载自微信公众号《Bug解决之路》，可通过以下二维码关注。转载本文请联系BUG解决公众号。
