「前任的50种死法」开发踩坑案例--慢就是错
背景
《50 ways to say goodbye》中文名《前任的50种死法》是我之前报的英语班里外教老师放给我们听的歌。老外说很困惑为什么我们还在听《Take me home,Country Road》这种老掉牙的歌。
《前任的50种死法》里因为生女友的气幻想她的各种死法：飞机坠机、晒日光浴被晒死、被狮子吃掉、泡澡被淹死……
等等，听着咋就这么像做项目：看起来根本就不可能的原因，结果服务被整死了。本系列文章汇总了50个项目中“下水被鲨鱼吃掉”这样的离奇的服务出错分析。
案例分析-超时导致接口报500错误
引发问题
我做的heimdal和carter这两个产品一期上线，heimdal是k8s的事件监听服务。在设计为了验证是否有事件丢失、对事件的处理是否正确等正确性验证，carter作为heimdal的事件处理，并对外直接暴露接口提供服务。一期使用了mysql做存储。因为mysql非常成熟，不会干扰对结果的验证。
但实际上因为涉及各种过滤式的查询。用sql来查询的时候，这么来说吧，如果直接写sql语句要嵌套几十个in的子查询。在代码编写的时候为了适应各种情况，分查询语句的，就是说要建立多次连接。
来看上面的数据，resource这个接口TP90已经超过2秒了。上游调用在服务治理框架OCTO中显示上游因为设置了超时时间为2秒，结果有0.4%的请求都调用失败了。因为在核心链路里有10次重试，而且如果10次重试还是获取不到结果，会在请求层失败。调用方看到这个错误会再次发起请求，实际上是可以得到正确结果的。但是上游会有监控报警，触发了报警，上游同学就来找我了。
我记得第一次处理这个问题是晚上11点多在地铁上。用手机连V**处理的。怎么应急处理这种事情呢？就是将堵塞的mysql慢查询kill掉。
问题解决初版
综合考虑已有问题的影响：实际上对业务没有影响。所以决定先按照原有的计划先完成标签管理系统hydra。用hydra的标签过滤来代替几十个in的子查询。这个方法可以彻底解决对mysql的压力。
hydra采用ElasticSearch做底层存储，将原有的sql查询转化为ES查询。并且因为标签的修改频率低，延时不敏感。我在编写客户端引用包的时候做了客户端本地缓存处理。缓存最近30条查询条件，每100ms取拉取最新条件对应的结果。所以条件命中的情况下，10ms完全可以返回结果。下面是端到端(最上游调用方的耗时，中间有很多网络传输)的响应耗时数据：
因为2s超时，而时间上TP99可以在200ms内返回。所以理论上是完全可以解决问题的。
看起来很完美，线下环境运行非常正常。但是线上环境运行了1天之后，超时现象却又复发了！在cat日志上还发现了大量由于mysql引起的错误。
mysql优化
下面是cat监控得到的结果，主要问题是数据库获取物理连接超时和内存溢出！
我们刚上线的服务qps每秒都没有几个请求，由于占用数据库连接池太多而引起内存溢出很蹊跷。并且查看数据库日志，并没有特别严重的慢查询。了解到这不是背后的根因，但是同时也暴露出另外一个问题：数据库参数设置是不合理的。
由于目前的报错实际上对业务没有影响。所以决定先不解决真正问题，而先借这个契机对数据库进行一版优化。主要做了两个优化：
第一，由于之前有部分的服务是主从延时敏感的，后面的同学新建服务的时候都一直采用“只读主库”的路由方式。考虑carter实际上对主从延时不敏感，同时从库需要一定的流量来保证万一主库出现问题进行主从切换的时候，从库是真正的热备，不需要额外的激活操作。所以将carter改成主从分离。
第二，对物理连接不是很苛刻的情况下，可以适当调大checkoutTimeout这个参数，以免不断的重连造成性能的反而下降。
通过这一版优化，cat上的错误日志确实是消失了。但是仍然超时！
解决根因
解决问题先看现象。下面是出现问题的那段时间的内存和cpu。能够看到有明显的攀升和尖刺。
从cat日志上找到耗时最长的那个记录，点进入看到有个方法调用是不该出现的。就是本来我做了客户端本地缓存，那就不应该在实际请求的时候走远程调用。除非超过了30个的存储限制，本地缓存失效！
果然，因为线上环境比线下复杂，30个不够用了。通过配置管理改成150个缓存，问题解决。上面内存和cpu是显示了1个月的数据。可以看到调整之后内存和cpu使用情况恢复了正常。
总结
慢就是错。响应速度不符合预期要当做错误进行彻底的排查。