记录一次线上问题处理总结

1,141 阅读14分钟

项目背景

单位计划做个内容风控的项目,对文本、图片、音频、视频进行风险审核。项目分为商户端、总台、脚本服务、API服务,API服务接收业务方的风险数据,转发给第三方的风控服务。功能不复杂,而且老板也不重视,说反正赚不了钱。

本人作为该项目的技术负责人,技术选型由CTO决定(CTO是做PHP出身的,和老板是朋友),项目服务端使用PHP的Yii2框架,项目过程中的各种阻力, 产品的各种坑爹需求就不说了。经过2周的开发,1周联调,1周测试,项目上线了。上线前申请服务器,8核16G服务器都不敢奢望了,申请4核8G的吧,规划是API服务3台机器、商户端和总台共用1台机器、脚本服务1台机器,共5台机器,加上Redis和RDS。

结果直接被拒绝,被CTO砍了一半,最终只给2台2核4G的机器,加上一台Redis服务器,一台RDS服务器,当然都是最低配置的。所有服务都部署在一台机器上,然后克隆部署。(PS:运维在上线时,偷偷给选了4核8G的服务器,给运维点赞!O(∩_∩)O~)

然后项目就这样上线了,服务器上任何监控都没有,没有日志收集,没有报警机制。我一直要求加日志服务,加服务器监控和报警机制,一直被驳回。o(╥﹏╥)o

而且项目中很多逻辑都是可以拆分成异步执行的,如果还是用PHP的话,做异步会很麻烦,会提高系统的复杂度,还会被喷过度设计。所以项目上线后,我就提议用Java或者Golang重构,这样的话接口响应时间最少可以提高2个量级,可惜还是被驳回。

灾难的开始

项目上线运行2周后,只有单位一个正在开发阶段的项目接了内容风控,一切正常。

直到某一天,老板突然说,有个大客户要接我们的风控。然后再某一个,突然被拉进一个对接群里,说客户已经完成对接并上线了。让他们有问题直接找我。结果俩天后的晚上快10点时,客户在群里反馈一个问题,统计页面报错。

统计页面报错

客户一说统计页面报错,我就知道怎么回事了。产品的需求是选定时间范围内的数据要实时计算,也就是说如果选定时间范围内有1000万条数据,就要对这1000万条数据做实时计算。我当初极力反对,可CTO是那种产品的需求必须实现,不管是否合理的那种人,老板不懂技术,老板技术这块全听CTO的,然后老板、CTO一起把我怼着。最后还是要求按照产品的需求来,实时计算。说什么数据量大了,再优化。

因为那时已经是晚上快10点了,都下班回家了,只能在家里解决,临时限制只计算前1000条数据,可单位全是内网环境,代码提交不了,单位也没架设Virtual Private Network(大家懂得!),赶紧找运维,运维只有一个自己用的Virtual Private Network,还是Windows环境下的,Mac下没法用,最后运维临时开了一个外网服务器,让我把代码提交了,服务上线了,线上服务恢复了。

第二天上班时,紧急开会,这回CTO和老板都没参加,单位新来了个技术总监,我把技术总监拉到会议室。而且产品经理换人了(✿✿ヽ(°▽°)ノ✿)(原来的产品经理高升了)。

一开始新的产品经理还是要求统计这里实时计算,我把实时计算的各种问题说了一遍,改成离线技术,按天合并,显示选定时间内每一天的统计数据,而不是之前的选定时间内的所有数据,技术总监同意了我的观点,然后产品才同意。这就好办了,我之前就预料这里会有问题,已经在脚本服务里写好了,数据都按天统计好了,直接查询就行了,分分钟搞定。

API服务超时和500错误

安逸的日子没过俩天,有天晚上又是快10点时,客户在群里说凌晨4点多时,API服务有一波超时和一次500的错误。老板又diss我,让我赶紧解决,我当时就有句MMP不知该不该说,线上环境没有任何监控和日志,叫我怎么定位问题,当初说要做这些时,一个个不同意,现在出问题了,就怼我了。

第一天

第二天周五,去单位直接找运维,运维先看了一下阿里云的服务器各项指标都正常,然后看一眼带宽,说带宽爆了,50M带宽不够,要加带宽,得要200M带宽,给了个预算,一年大概要20万RMB。客户每天的数据才10万条,不应该把带宽打爆,先临时加到200M带宽,然后再排查问题。因为加带宽,需要花钱的,得要老板批准。我就火急火燎的跑去找老板,把运维的方案一说,老板又把我一顿骂,说我不要什么临时的方案,我要最终解决方案,巴拉巴拉的。我弱弱的说了一句“线上服务出问题了,先保证线上服务可用啊。”结果老板骂得更狠了,最后灰头土脸的出来了,线上服务继续时不时的超时。

出来后,开始找原因,为什么“带宽爆了”,技术总监优先怀疑代码的问题,让我排查自己的代码,看是否有什么逻辑的问题。我又没有大量的调用其他服务,怎么可能把带宽弄爆。顶着技术总监质疑的目光,直接找运维开了个阿里云的子账号,自己上阿里云看服务器的各项监控,最后仔细一看,服务搭建了SLB,SLB高峰时才十几K的数据流量,而那个时段,应用服务器的带宽占用率并不高,而且,运维所谓的带宽,是内网带宽,阿里云的内网带宽几个Gbps,你打爆给我看看!!!而且阿里云中带宽曲线图中黄色那条线表示入网bps,不是触发临界值才用黄色显示!!!

为什么那段时间,入网带宽激增呢?因为阿里云的安全机制,每晚4点多会向服务器丢包,扫码肉鸡和安全漏洞,那时API服务刚好有超时发生,凑巧,赶上了!!!

就这样,一天时间过去了。问题处理进度0。

第二天

第二天,周六,加班。拉着运维接日志服务,加报警,报警直接以短信形式发送到我的手机上(单位没有报警机制与应急处理人员和方案),这回上面直接同意了。因为之前开发时,日志已经埋好点了,接一下日志服务就行。日志分为业务运行中关键节点的日志和错误日志,等了半天,又出现500错误了,有日志就好定位问题了。在请求第三方风控服务后,第三方返回的数据是json格式,用Yii框架的Json::decode()解析,报错了,因为客户提交的数据中,有个emoji表情,PHP识别不了,原因是emoji表情一直在新增,PHP只能识别部分的emoji表情,又因为Json::decode()在解析时,如果失败了,直接抛出异常,所以会报500错误,问题找到了就好解决了,返回给客户的数据,只需要告诉他们风险结果和有风险的那段文本就行,有没有emoji表情都无所谓,在Json::decode()之前,过滤掉emoji表情。

修改完后,测试没问题,上线。并一边查看是否继续有错误日志产生,一边定位超时的问题。

因为之前日志埋点时,只记录关键的参数,没记录耗时(o(╥﹏╥)o),赶紧加上,发布上线。可是整个白天都没发生超时,坐在电脑前等啊等,一直到下午6点多还没发生超时,下班回家。

问题处理进度50%。

结果快到家时,报警短信来了,发生超时了。内网环境,还没Virtual Private Network,在家没法办公,而且大家都回去了,硬着头皮顶呗。晚上快10点时,客户又在群里报告问题了(你就不能在工作日时反馈问题嘛!(•́へ•́╬)),说还超时。又被老板一顿骂。

第三天

周日,继续加班。因为已经加上了耗时的记录了,立马定位到耗时的地方。时间耗在调用save()方法保存用户提交过来的数据这里。技术总监有怀疑我的代码问题了,问是否数据的插入有问题,数据库中的数据量是否太大了......,一顿有理有据的解释后,又问用了MySQL的连接池了吗,我就没回答他了。

(内心活动:PHP是多进程的,一个HTTP请求过来了,你辛辛苦苦实现了个创建了连接池,HTTP请求结束了,资源回收了, 你的连接池也被回收了。如果借用第三方,比如swoole实现连接池,你还得维护连接池,连接MySQL时间过长的话,MySQL自己会断开链接,你得自己保证连接池中所有连接的keepalive,连接释放时,你得考虑gc,之前用的一个基于swoole集成的框架,它的连接池就是这里有问题。而且当项目需要使用到连接池时,Java它不香吗!Java社区那些开箱即用的工具满足不了你吗!何必折腾自己呢!)

技术总监找了个Java开发过来,和他说PHP这里连接MySQL有问题,对数据库的操作,让他用Java重写,我这边调用Java那边的接口。Java开发开始吭哧吭哧的干活了。

到运维那边,看rds的情况,一切正常,也没出现慢查询。猜测问题可能出在和rds服务器的TCP通信这里有问题。找运维要来服务器的ssh连接权限,登录服务器,tcpdump抓取到数据库的包:

tcpdump port 3306 -w /opt/tcpdump/3306.cap

然后等超时发生。还好不到一个小时又有超时发生了,将数据包下载到本地,用wireshark查看。找到超时时的那条TCP流,发现TCP等了好几秒才把那条SQL语句发送给RDS,看到RDS服务器这时的window size为74,考虑到服务器都是最低配置,就没细看了。而发送那条insert语句的数据包,TCP报文长度为300多字节,可能触发了TCP的流量控制协议。单位有个群,里面很多阿里云的技术支持,赶紧到群里找阿里云的技术支持反馈,并把TCP包发给他们。过会阿里云给答复了,他们用的是TCP窗口扩大选项,实际窗口应该看calculated window size这个值。丢脸了!o(╥﹏╥)o

技术总监认为这更进一步验证了他的想法,PHP连接MySQL有问题,Java的兄弟继续吭哧吭哧干活。

PHP这段时间不知道在干嘛,一直没提交这条insert语句。我就在想,执行save()方法时,是否执行了其他操作。因为这个save()方法,是我们CTO封装的,现在用的框架虽然说是用的Yii框架,CTO说Yii框架怎么怎么好,开发起来多么方便,但是,巴拉巴拉的说Yii框架有哪些缺陷,哪些不合理的,于是对Yii框架做了再封装(PS:每次都是这样,所有东西他都要再封装一次,对Redis操作这样,对rabbitMQ操作也是这样)。在save之前,调用了一次雪花算法,生成id。然后看Yii自己做了些什么,发现也就获取一下schema信息,要说这块的优化,把缓存schema的配置开启,不要每次都获取schema信息。先这样上线看看,果然没用,还是会时不时的发生超时。

一天时间过去了,问题处理进度依然50%。

第四天

周一,上午和技术总监开会,讨论分析这块问题,巴拉巴拉的,开了一上午的会。

下午,想了下,基本已经排除RDS那块的问题了,在请求RDS之前,就只剩雪花算法请求Redis了,感觉这里不可能有问题,不管了,先抓包看看。

tcpdump port 6379 -w /opt/tcpdump/6379.cap

没几个小时,超时发生了,看看Redis的TCP数据包,对Redis的请求倒是挺多了,密密麻麻,可没那个请求耗时好几秒的情况啊。排除了Redis的问题。

这时我已经开始绝望了。绞尽脑汁,又想到一个办法,用strace分析进程的堆栈信息。一边用strace记录进程的堆栈,等待超时再次发生,一边协助Java的兄弟干活。

可到晚上10点,还是没发生超时。不管了,回去了。头疼死了。

问题处理进度50%。

第五天

周二,上午,因为昨晚躺床上时,头脑里一直考虑这块的问题,想来想去,感觉要出问题的话,可能还是Redis这块的问题,因为看Redis的TCP包时,time since first frame in this tcp stream有12秒多。只是这条TCP流里发送的请求数量太多了,没法找到是哪次请求耗时怎么多的。所以上午一边协助Java兄弟干活,一边继续分析Redis的TCP包。

可这条TCP流,有10来万次的请求啊,等等,10来万次的请求?!!一个HTTP请求,需要对Redis发送这么多请求吗?!!看了一下其他正常的请求,发现才100多次请求。10来万次的请求,一共耗时12秒,这就对上了啊。查看发送了哪些请求,一看吓一跳,全是向Redis发送incr请求。问题找到了(strace可以停掉了)。

雪花算法那里,是我们CTO弄的,他找的第三方的一个叫godruoyi/php-snowflake的composer包,第三方的包可以直接用的,还是那样,他还要再封装一下。封装就算了,但是,包里有个接口:

interface SequenceResolver
{
    /**
     * The snowflake.
     *
     * @param int|string $currentTime current request ms
     *
     * @return int
     */
    public function sequence(int $currentTime);
}

包里自己已经实现了这个接口了,而且还是4种实现方式,LaravelSequenceResolverRandomSequenceResolverSwooleSequenceResolverRedisSequenceResolver,结果我们那个CTO非要自己用Redis再实现一次。

public function sequence(int $currentTime)
{
    $sequence = $this->redis->incr($this->key);
    if ($sequence > 100000) {
        $this->redis->del($this->key);
        $sequence = $this->redis->incr($this->key);
        $this->redis->expire($this->key, 3600);
    }
    return $sequence;
}

问题就在这!!!包里有个方法Snowflake::callResolver()会调用这个接口,然后Snowflake::id()方法调用上面的方法:

public function id()
{
    ...
    while (($sequence = $this->callResolver($currentTime)) > (-1 ^ (-1 << self::MAX_SEQUENCE_LENGTH))) {
        usleep(1);
        $currentTime = $this->getCurrentMicrotime();
    }
...
}

问题已经很明了了,抽象理解就是这样:

while ($sequence > 4095) {
    $sequence = $redis->incr($key);
    if ($sequence > 100000) {
        $redis->del($key);
        $sequence = $redis->incr($key);
        $redis->expire($key, 3600);
    }
}

所以当$sequence大于4095时,就会一直向Redis发送incr请求,直到$key的值大于100000才会重置$key的值。所以才会向Redis发送了大概10万次的incr请求。

问题终于解决了!!!

总结

这几天都神经过敏了,手机短信一响,立马心里一颤。从昨天到现在一直没有超时报警了,心里终于松了一口气。

......

说一下收获吧!以前学习TCP/IP、tcpdump、Wireshark这些,都只是停留在理论阶段,或简单操作一下,很多概念都知道,但没理解,这次终于有了实操的机会了。

因为有客户用我们的产品了,老板开始重视了,之前提到的用Java或Golang重构也批准了,现在开始用Java重构API服务,后续再慢慢把其他服务也替换成Java。好了,不说了,继续写bug了。