记一次产线打印json导致的redis连接超时

服务在中午十一点上线后，服务每分钟发出三到四次redis连接超时告警。错误信息为：

Dial err:dial tcp: lookup xxxxx: i/o timeout

排查过程

先是检查redis机器的情况，redis写入并发数较大，缓存中保留了一小时大概400w条数据。redis服务器cpu和内存跟出问题前都差不多，非常接近，看不出什么问题。接下来看看服务的情况。

> LLEN xxxServ:price:change
(integer) 4100314
> ZCARD xxxServ:price:change:zSet
(integer) 963090

业务简单图

服务关键监控指标

• cpu 从 12%飙升到150%
  

• 内存平稳，在 150M 上下
  

• goroutines翻倍，从300到600
  

• gc时间暴涨，从110us涨到7.5ms
  

• redis 连接数达到了配置的上限20
  

• 文件描述符翻倍了，从100到250
  

消息监控

• 消息消费的qps
  

• 消息平均耗时
  

核心接口监控

• 核心接口qps减半，从200减少到100
  

• 接口耗时涨到6倍，从250ms涨到1.5s
  

火焰图

定位原因

异常的指标有cpu使用率飙升，goroutines翻倍，gc时间暴涨，文件描述符翻倍，核心接口qps减半且耗时暴涨。再看看火焰图，LogToJson函数占用了83%的cpu。

出问题前上线了打印debug日志的代码，产线debug日志默认不会输出，但是debug日志入参是LogToJson的输出，输出的数据为全局的缓存数据，缓存数据比较大，且每次请求都打印一次。

并发数较高，大量打印json导致cpu过高，每次请求后这些大对象要被回收，从而导致gc时间过长，进而导致时不时出现redis io timeout 的错误。取消打印json的debug日志，问题就解决了。

经验教训

大对象不要在并发高场合打印。看到的问题可能只是现象，未必是根本原因，就像这次看起来是redis问题，但实际是打印json的问题。Code Review未必能细致到每个方法，有地方一不小心就踩坑了。