诡异提交失败问题追查
摘要:
自四月份以来,贴吧遇到了发帖失败的问题,现象比较诡异。通过层层分析,几经波折,终于找到“凶手”。
1 背景
很久前知道上有个问题:“从前天开始,跟帖就是发帖失败,换个ID开始能发,后来又变成发帖失败,很迷惑。谁知道怎么回事么。是系统问题么,还是网络问题?”最佳答案是:“很大部分是网络出现问题,你可以重新提交下就可以了”。
前段时间,贴吧的提交UI老是报警,晚上的时候手机叮叮咣咣地响,每次看都是apache进程数上千hold不住了,只好逐台重启。后来OP怒了,直接写了个脚本,发现apache进程数上来就自动重启。
好景不长,某天图1被PM截下来发到群上,自己发几个贴测试下居然复现了!看来真不是网络的问题,必须好好追查下了。
2 提交系统综述
先整理下贴吧提交的逻辑和涉及的模块。图2是贴吧提交系统的架构,一个完整的发帖流程需要经过下述模块的处理。
提交UI。提交UI是接收用户提交的帖子信息,进行内容过滤,spam识别等一系列策略后将数据提交给后端的PHP模块,使用apache作为服务器。
postcm。postcm是post commit manager的简称,顾名思义就是发帖管理员,一个单点。所有与发帖有关的操作都经其序列化后,持久化到本地di数据文件。
cm_proxy。贴吧除了发帖外,还有消息推送、消费吧豆等提交操作,因此除了postcm外,还有clubcm、ecm等存在。cm_proxy对UI层面屏蔽了各种cm的划分,自动根据UI中的命令号转发到相应的cm上。
transfer。transfer读取cm生成的di数据文件,将其转发到需要的后端模块,比如frs(贴吧主题页),pb(帖子内容页)。
提交UI通过camel(现在是RAL了)与cm_proxy通信,短连接。cm_proxy使用UB_client与postcm通信,短连接。cm_proxy和postcm都是使用UB框架编写的C模块,尤其postcm,版本号都是4.X.X.X,可谓历史悠久。
3 问题追查
发表一个帖子经过这么多模块,是在没有头绪,只好辛苦UI的同学看看什么情况下会出现那个未知错误的哭脸。UI同学很给力,马上给出一个case,3000代表提交UI与cm_proxy交互失败,从交互时间看,与cm_proxy交互时间为1秒。恰好UI设置的超时为1秒,去后端看看发生什么回事。
拿着这个logid查cm_proxy和postcm日志,发现两个模块都接收到UI的请求,并且把数据转发到相应的后端模块。继续看warning日志,发现cm_proxy等待postcm回复超时!
3.1 UBClient问题?
难道是postcm处理这么慢么?查看本条请求处理时间,只有十几毫秒,理论上不会超时。带着这个问题请教以前负责这个模块的高同学,得知以前曾经出现类似的问题,猜测是UBClient在压力上千时,会出现大量读超时。
为了让真凶现形,在OP mm的帮助下搭建好一套线下测试环境,使用gmt工具给予cm_proxy 2000/s的压力(线上峰值是1000/s)。一个小时,两个小时……出现时的只是cm_proxy queue full错误,没有读超时问题。然后wiki一下,也没有找到类似错误的记录,看来UB库是可依赖的。
3.2 TIME_WAIT问题?
一时找不到头绪,看能不能从日志中挖掘到一些线索。统计cm_proxy日志情况,根据错误号查看代码,主要出现两种类型错误。
读超时:
连接postcm拒绝:
处理时间为0居然还读超时,太诡异了!统计下5月22日一天cm_proxy与postcm交互失败的分布。
图4 cm_proxy与postcm交互失败分布
为啥tc cm00这个机器的连接拒绝这么多,读超时这么少呢?原来postcm单点部署在这台机器上,postcm和cm_proxy同机部署可能带来一些问题。查看机器监控,发现这台机器处于TIME_WAIT状态的socket达到十几万。但是查看操作系统参数/proc/sys/net/ipv4/tcp_tw_reuse,值为1。证明目前端口复用已经打开。为了让问题收敛,把tc cm00的cm_proxy下掉,继续跟进。
3.3 Backlog大小问题?
为什么会连接拒绝?带着这个问题请教我们的小强同学。不愧是大牛,一下就发现tcp listen的时候,Backlog可能设置的太小了。翻阅资料充电:Backlog是listen系统调用的 第二个参数,这个参数所指明的是linux处理tcp连接是所设置的全连接队列的长度。在socket程序设计中,当三次握手完成后,会把刚刚建立好的连接放入这个全连接队列中,当服务器端调用accept系统调用的时候,会从这个全连接队列里取出已经建立好的连接供上层应用使用。这个值在系统中设置了上限,可以通过/proc/sys/net/core/somaxconn查看。当listen系统调用使用的Backlog值小于这个值得时候系统取backlog值为实际值,当Backlog的值大于这个值的时候,系统取SOMAXCONN的值为默认值。
查看postcm上系统SOMAXCONN的值为2048,而listen时Backlog大小只有100,貌似有点小。5月28日,OP操作把这个值调到1024,观察效果。
图5 22日和28日cm_proxy与postcm交互失败分布
调整后,交互失败下降到原来的三分一,有点进度。但是如果仅仅是Backolg大小问题,为什么依然存在这么多的交互失败呢,看来幕后凶手还没有找到。
3.4 现场缉凶!
目前掌握的证据还不充分,实时观察日志或许能发现些东西。tail一台cm_proxy的错误日志,发现每隔一段时间刷出一批错误日志。统计每秒错误日志数,发现一个规律,很多时候每隔15秒左右会一下子刷子40条交互失败的日志。这个40有点眼熟,就是cm_proxy的线程数!这意味这个时间点所有的交互都失败了。
火速赶往postcm机器,iostat一下,发现一个很有意思的现象。IO的情况随着时间上下波动,然后每隔一段时间会有一次大的IO操作(>80M/s,持续1~3秒),此时cm_proxy会有较大几率出现交互失败。
为了确认案情,统计6.2一天postcm日志,共有477个请求处理时间大于等于1000ms。这477个请求处理时间几乎平均分布在[1000,3995]ms中。目前cm_proxy与postcm连接超时为1000ms,意味着477个请求持续时间内,cm_proxy与postcm有可能出现读超时(根据IO被阻塞时间和请求达到postcm时间确定)
真正的原因是在流量高峰期,postcm提交量上升, 当脏页占系统内存的比例超/proc/sys/vm/dirty_ratio的时候, write系统调用会被被阻塞,主动回写dirty page,直到脏页比例低于/proc/sys/vm/dirty_ratio。由于postcm工作模型(单线程),会导致postcm短时间内不能响应请求,造成上级模块陆续超时或连接失败
4 解决办法
整理一下思路,目前造成提交不稳定主要以下三个。
4.1 cm_proxy读超时
根据com wiki经验,修改操作系统参数,观察效果并不断调整。
修改刷脏页频率,从5s调整到3s
echo 300 > /proc/sys/vm/dirty_writeback_centisecs
修改脏页存在的时间限制,从30s调整到10s
echo 1000 > /proc/sys/vm/dirty_expire_centisecs
效果描述:
从iostat信息来看,刷脏页的频率变高,每次刷的脏页数量变少。从上层应用程序来看,性能变得平稳。修改后每天超过1000ms的请求在200个左右。存在继续优化的空间。
增大提交UI与cm_proxy和cm_proxy与postcm的读超时,从1000ms修改为3000ms。那么每天在postcm两百多个超过1秒刷脏页的时间范围内,用户的提交会延迟而不会失败。
4.2 cm_proxy连接拒绝
当IO被阻塞期间,到达postcm请求数超过连接队列长度,则拒绝连接。通过实验观察postcm Backlog的最佳大小,目前操作系统参数上限为2048。根据实验结果,将postcm Backlog大小调整为2048。
4.3 cm_proxy queue full
当cm_proxy与postcm交互失败期间,若前端请求过多,若cm_proxy工作线程数不足或cm_proxy连接postcm连接池连接数不足时出现。根据实验结果和目前cm_proxy压力状态(最大1000/s),将cm_proxy线程数和postcm连接池连接数修改为100。
总结
本次追查过程走了许多弯路,很多问题别人也遇到过,需要不断总结追查问题的方法。通过这次追查得出的经验是一个问题的出现可能有很多现象,有些可能是表面原因,修改了对问题有不少的改善,但只有真正找到引发问题的原因后,才能找到最恰当的解决办法。由于经验不足,写的不对的地方,恳请大家指正。
by chenyuzhe
建议继续学习:
- 再叙TIME_WAIT (阅读:3201)
- TIME_WAIT状态消除方法-快速回收 (阅读:2785)
- 关于流量升高导致TIME_WAIT增加,MySQL连接大量失败的问题 (阅读:2706)
- linux上大量tcp端口处于TIME_WAIT的问题 (阅读:2247)
- 记一次TIME_WAIT网络故障 (阅读:2308)
- PHP-FPM中backlog参数变更的一些思考 (阅读:2184)
扫一扫订阅我的微信号:IT技术博客大学习
- 作者:editor 来源: 搜索研发部官方博客
- 标签: Backlog cm_proxy TIME_WAIT
- 发布时间:2012-07-19 14:08:42
- [67] Oracle MTS模式下 进程地址与会话信
- [65] 如何拿下简短的域名
- [65] Go Reflect 性能
- [61] android 开发入门
- [60] 【社会化设计】自我(self)部分――欢迎区
- [59] 图书馆的世界纪录
- [59] IOS安全–浅谈关于IOS加固的几种方法
- [54] 视觉调整-设计师 vs. 逻辑
- [48] 读书笔记-壹百度:百度十年千倍的29条法则
- [47] 界面设计速成