诡异提交失败问题追查

摘要:

自四月份以来，贴吧遇到了发帖失败的问题，现象比较诡异。通过追查发现是操做系统刷磁盘时，阻塞write系统调用致使。本文主要分享问题追查过程，但愿对你们平常工做中定位问题有必定帮助。

TAG:

提交、问题追查、脏页

1 背景

好久前知道上有个问题：“从前天开始，跟帖就是发帖失败，换个ID开始能发，后来又变成发帖失败，很迷惑。谁知道怎么回事么。是系统问题么，仍是网络问题？”最佳答案是：“很大部分是网络出现问题，你能够从新提交下就能够了”。

前段时间，贴吧的提交UI总是报警，晚上的时候手机叮叮咣咣地响，每次看都是apache进程数上千hold不住了，只好逐台重启。后来OP怒了，直接写了个脚本，发现apache进程数上来就自动重启。

好景不长，某天图1被PM截下来发到群上，本身发几个贴测试下竟然复现了！看来真不是网络的问题，必须好好追查下了。

 

2 提交系统综述

先整理下贴吧提交的逻辑和涉及的模块。图2是贴吧提交系统的架构，一个完整的发帖流程须要通过下述模块的处理。

l  提交UI。提交UI是接收用户提交的帖子信息，进行合法性验证后将数据提交给后端的PHP模块，使用apache做为服务器。

l  提交后端。某些提交操做好比发贴和删帖对时序存在要求，全部与发帖有关的操做都经提交后端序列化后，持久化到本地di数据文件。消息队列读取di文件，转发给订阅相关消息的后端模块。

l  提交代理层，简称proxy。贴吧除了发帖外，还有消息推送、消费吧豆等提交操做，所以提交后端以集群的形式存在，而且每一个都是单点。proxy对UI层面屏蔽了各类提交后端的划分，自动根据UI中的命令号转发到相应的提交后端上。

提交UI经过RPC与proxy通讯，短链接。proxy使用rpc_client与提交后端通讯，短链接。proxy和提交后端都是使用rpc框架编写的C模块。

3 问题追查

发表一个帖子通过这么多模块，是在没有头绪，只好辛苦UI的同窗看看什么状况下会出现那个未知错误的哭脸。UI同窗很给力，立刻给出一个case，3000表明提交UI与cm_proxy交互失败，从交互时间看，与cm_proxy交互时间为1秒。刚好UI设置的超时为1秒，去后端看看发生什么回事。

拿着这个logid查cm_proxy和postcm日志，发现两个模块都接收到UI的请求，而且把数据转发到相应的后端模块。继续看warning日志，发现cm_proxy等待postcm回复超时！

3.1  RPCClient问题？

难道是提交后端处理这么慢么？查看本条请求处理时间，只有十几毫秒，理论上不会超时。带着这个问题请教之前负责这个模块的高同窗，得知之前曾经出现相似的问题，猜想是RPCClient在压力上千时，会出现大量读超时。

为了让真凶现形，在OP mm的帮助下搭建好一套线下测试环境，使用压力工具给予proxy 2000/s的压力（线上峰值是1000/s）。一个小时，两个小时……出现时的只是proxy queue full错误（等待链接池满），没有读超时问题。而后wiki一下，也没有找到相似错误的记录，看来RPC库是可依赖的。

3.2  TIME_WAIT问题？

一时找不到头绪，看能不能从日志中挖掘到一些线索。统计cm_proxy日志状况，根据错误号查看代码，主要出现两种类型错误。

读超时：

链接postcm拒绝：

处理时间为0竟然还读超时，太诡异了！统计下5月22日一天proxy与提交后端交互失败的分布。

图4 cm_proxy与提交后端交互失败分布

为啥tc cm00这个机器的链接拒绝这么多，读超时这么少呢？原来提交后端单点部署在这台机器上，提交后端和proxy同机部署可能带来一些问题。查看机器监控，发现这台机器处于TIME_WAIT状态的socket达到十几万。可是查看操做系统参数/proc/sys/net/ipv4/tcp_tw_reuse，值为1。证实目前端口复用已经打开。为了让问题收敛，把tc cm00的proxy下掉，继续跟进。

3.3  Backlog大小问题？

为何会链接拒绝？带着这个问题请教咱们的小强同窗。不愧是大牛，一下就发现tcp listen的时候，Backlog可能设置的过小了。翻阅资料充电：Backlog是listen系统调用的         第二个参数，这个参数所指明的是linux处理tcp链接是所设置的全链接队列的长度。在socket程序设计中，当三次握手完成后，会把刚刚创建好的链接放入这个全链接队列中，当服务器端调用accept系统调用的时候，会从这个全链接队列里取出已经创建好的链接供上层应用使用。这个值在系统中设置了上限，能够经过/proc/sys/net/core/somaxconn查看。当listen系统调用使用的Backlog值小于这个值得时候系统取backlog值为实际值，当Backlog的值大于这个值的时候，系统取SOMAXCONN的值为默认值。

查看提交后端上系统SOMAXCONN的值为2048，而listen时Backlog大小只有100，貌似有点小。5月28日，OP操做把这个值调到1024，观察效果。

图5  22日和28日cm_proxy与提交后端交交互失败分布

调整后，交互失败降低到原来的三分一，有点进度。可是若是仅仅是Backolg大小问题，为何依然存在这么多的交互失败呢，看来幕后凶手尚未找到。

3.4  现场缉凶！

目前掌握的证据还不充分，实时观察日志或许能发现些东西。tail一台proxy的错误日志，发现每隔一段时间刷出一批错误日志。统计每秒错误日志数，发现一个规律，不少时候每隔15秒左右会一会儿刷子40条交互失败的日志。这个40有点眼熟，就是proxy的线程数！这意味这个时间点全部的交互都失败了。

火速赶往提交后端机器，iostat一下，发现一个颇有意思的现象。IO的状况随着时间上下波动，而后每隔一段时间会有一次大的IO操做（>80M/s,持续1~3秒），此时proxy会有较大概率出现交互失败。

为了确认案情，统计6.2一天提交后端日志，共有477个请求处理时间大于等于1000ms。这477个请求处理时间几乎平均分布在[1000,3995]ms中。目前proxy与提交后端链接超时为1000ms，意味着477个请求持续时间内，proxy与提交后端有可能出现读超时（根据IO被阻塞时间和请求达到提交后端时间肯定）

真正的缘由是在流量高峰期，postcm提交量上升， 当脏页占系统内存的比例超/proc/sys/vm/dirty_ratio的时候, write系统调用会被被阻塞,主动回写dirty page,直到脏页比例低于/proc/sys/vm/dirty_ratio。因为提交后端单线程的工做模型，会致使提交后端短期内不能响应请求，形成上级模块陆续超时或链接失败。

4 解决办法

整理一下思路，目前形成提交不稳定主要如下三个。

4.1  cm_proxy读超时

l  修改操做系统参数，观察效果并不断调整。

由基础架构的同窗总结，操做系统会在下面三种状况下回写脏页：

1） 定时方式。定时回写是基于这样的原则:/proc/sys/vm/dirty_writeback_centisecs的值表示多长时间会启动回写pdflush线程,由这个定时器启动的回写线程只回写在内存中为dirty时间超过(/proc/sys/vm/didirty_expire_centisecs / 100)秒的页(这个值默认是3000,也就是30秒),通常状况下dirty_writeback_centisecs的值是500,也就是5秒,因此默认状况下系统会5秒钟启动一次回写线程,把dirty时间超过30秒的页回写,要注意的是,这种方式启动的回写线程只回写超时的dirty页，不会回写没超时的dirty页。

2） 内存不足的时候。这时并不将全部的dirty页写到磁盘,而是每次写大概1024个页面,直到空闲页面知足需求为止。

3） 写操做时发现脏页超过必定比例: 当脏页占系统内存的比例超过/proc/sys/vm/dirty_background_ratio 的时候,write系统调用会唤醒pdflush回写dirty page,直到脏页比例低于/proc/sys/vm/dirty_background_ratio,但write系统调用不会被阻塞,当即返回.当脏页占系统内存的比例超/proc/sys/vm/dirty_ratio的时候, write系统调用会被被阻塞,主动回写dirty page,直到脏页比例低于/proc/sys/vm/dirty_ratio。

 

修改刷脏页频率，从5s调整到3s

echo 300 > /proc/sys/vm/dirty_writeback_centisecs

修改脏页存在的时间限制，从30s调整到10s

echo 1000 > /proc/sys/vm/dirty_expire_centisecs

 

效果描述：

从iostat信息来看，刷脏页的频率变高，每次刷的脏页数量变少。从上层应用程序来看，性能变得平稳。修改后天天超过1000ms的请求在200个左右。存在继续优化的空间。

l  增大提交UI与proxy和proxy与提交后端的读超时，从1000ms修改成3000ms。那么天天在提交后端两百多个超过1秒刷脏页的时间范围内，用户的提交会延迟而不会失败。

4.2  cm_proxy链接拒绝

当IO被阻塞期间，到达提交后端请求数超过链接队列长度，则拒绝链接。经过实验观察提交后端Backlog的最佳大小，目前操做系统参数上限为2048。根据实验结果，将提交后端Backlog大小调整为2048。

4.3  cm_proxy queue full

当proxy与提交后端交互失败期间，若前端请求过多，若proxy工做线程数不足或proxy链接提交后端链接池链接数不足时出现。根据实验结果和目前proxy压力状态（最大1000/s），将proxy线程数和提交后端链接池链接数修改成100。

总结

经过此次追查得出的经验是一个问题的出现可能有不少现象，有些多是表面缘由，修改对问题会有很多的改善，但只有真正找到引起问题的缘由后，才能找到最恰当的解决办法。本文小结了网络交互失败追查的一些方向和方法，但愿对你们有所帮助。

by  chenyuzhe