记一次产线打印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未必能细致到每个方法，有地方一不小心就踩坑了。