背景
休假期间收到公司同事的信息说系统日志有大量的报错,且收到邮件告警。
同事排查不到原因,迫不得已联系到正在休假的我。幸亏我带着电脑呢!(打工人的觉悟真高,休假都带着电脑)于是我打开电脑,连上V**,连接远程桌面,登录日志系统,查看一番,又翻了翻代码,发现是因为从Redis中查询的数据为字符串null(这种情况是Redis中不存在且数据库也不存在时,避免缓存穿透而临时缓存的字符串null),导致抛出业务异常,打印错误日志,从而触发邮件告警。接口调用量一上来,报错就多了,于是就收到了千余封告警邮件。
由于我在休假,所以告诉同事几个排查思路,去看看Redis为啥为空(正常情况下,这种配置数据应该是在数据库中的)。
解决
于是同事最后找到了原因,是因为数据库未初始化相应数据(上线了新接口,需要增加配置,新人忘记加了),然后紧急修复了一下。
但是修复后,接下来的国庆假期,每天还是会收到上千封告警邮件(缓存的接口开关数据,且实际为关,不影响实际业务),于是同事在值班邮件中写道:xx月xx日已修复,但缓存中为空,缓存设置了过期时间,到期会自动清除,同步数据库中数据后即不再报错。于是大家都不再关注这个问题了。
再现
细心的我发现到了过期时间之后,还是会报相应的错,还是会每天收到告警邮件,为什么呢?不是设置了过期时间吗?空值咋还在缓存中呢?
首先我们排除了数据库查不到数据的嫌疑,我们确保按线上SQL的查询条件能够查到数据。其次,我们查询了key的过期时间,换算一下还有4天过期,经过推算,从缓存null值开始计算,三天前就该过期了,为啥现在查还是4天呢?
继续排查
我们排查了代码,发现该缓存key使用的是Redis哈希结构,field是不同的用户id,value是对应的数据库记录,并设置了过期时间5天。乍一看没什么问题,但是仔细再看看,发现了猫腻。
当从Redis执行hget无法获取到数据时,会查数据库然后执行hset将用户id和对应的数据缓存,并设置过期时间为5天。原因就在这,每次执行hset时都设置过期时间,这样就导致缓存可能很久才会过期,因为过期时间可能会一直被重置。
举个例子,最初哈希无数据,用户1查询后缓存了用户1,设置5天过期,当快过期时,用户2又来查询然后缓存用户2的数据,设置5天过期,那么此时用户1的数据过期时间相当于又被重置为了5天。以此类推,最坏的情况就是,用户1的数据在哈希key每次快过期时都被重置过期时间,那么用户1的数据将会缓存(N+1)*5天才过期。即,直至所有用户数据都在哈希中且再过5天后整个hash数据才被清除。
为了验证这个观点,我们又执行了一次ttl命令,发现这次过期时间换算后为4.9天,再结合日志,发现确实有新的field被缓存!于是证实了上述猜想!
最终解决
到此,问题原因已经排查到。剩下的就是解决,思路就是:
首先删除缓存为null的field,让业务先正常走下去。为了仅提交一次工单一次性全部删除,我们排查了有多少这样的field(缓存为null但数据库有值),一次性处理完。
其次优化代码。目前存在的问题是可能导致缓存为字符串null的数据很久很久都不过期。优化方案:执行hset后判断key没有设置过期时间,再执行expire,防止过期时间被覆盖。
总结一下
问题原因:
1.数据库未初始化数据,导致缓存了null字符串,抛出业务异常导致告警
2.缓存过期时间一直被重置,导致缓存一直不刷新
3.修复问题时仅为数据库初始化数据,未主动清缓存
解决办法:
感悟:
至此,本次问题排查并解决完毕,这个坑你遇到过吗?希望对你有帮助!