今年是第三个618，进公司也25个月了。前两年的618基本上是平稳度过，没什么波澜。但是今年的618有些不寻常，业务范围有了些调整。一个是原先的店铺业务被交接出去，另一个是接手了领券中心业务。
对于店铺业务，由接手的BJ团队负责618的准备工作。
对于领券中心业务，由原先的团队负责，我们这边做了618前的一个需求，新增了几个接口，这几个接口需要我们这边自己压测，并负责接口的所有问题。
所以，看上去这次618压力应该不大，但是问题却出了不少。很不幸，其中有两个是我埋坑。一个是店铺，一个是领券中心。
1、店铺
在2018年1月，开发上线了店铺的拼购商品打标功能。也就是给店铺中的拼购商品打上拼购的标，让用户一眼能看出是拼购商品，促成用户下单。很简单的功能，也很顺利的上线了。但是到了6月8号（618活动已经开始），产品经理突然说有些店铺的拼购商品没有打标。
～～晴天霹雳～～
拨上VPN，仔细查看日志。发现拼购信息在缓存中设置的有效时间不对，导致了拼购活动还没结束，缓存中的拼购信息也就没有了。店铺中的拼购商品没有打标。
【直接原因分析】
缓存中没有拼购信息 >> 拼购信息的缓存时间小于活动时间 >> 拼购信息的缓存时间计算错误。
缓存时间的计算方法如下：
拿到拼购活动的结束时间（结束时间实际就是Long型，单位是秒）。在Java中，这个时间是一个long值。为了计算距离现在的失效时间，只需要拿活动失效时间乘以1000，再减去现在的时间long值即可。此时得到的有效时间是毫秒级别的，再除以1000即得到实际的秒数。这个时间就是这个拼购信息的过期时间了。
计算思路很简单，问题出在了最后一步。在拿到缓存有效时间（毫秒级）后，直接使用了Long.intVal()，此时是强制转换，把long型的64位值，截取了低位的32位。这种转换是很危险的。如果long型的值超过了Integer.Max的值，强制转换后，可能是负数，也可能是正数。对于负数，写缓存的时候，代码会认为没有设置缓存有效时间，这个还好，不会对业务有影响。但是对于转换成正数的，实际产生的效果是缓存时间变小了（比如，本来10年的有效期，由于存在强制的截断，现在变成了24天以内的有效期）。
【解决问题】
1）优先解决线上问题。使用预发布环境把线上错误的缓存时间给刷回来。也就是批量查询数据库，从数据库中获取正确的结束时间，重新刷新缓存。
说干就干，写了代码立刻上预发布，并开始了刷新任务。跑了一夜，发现还没结束，查看线上原来没有拼购的几个店铺，恢复了拼购打标，更加证实了是这个原因。只是，无法确认所有的店铺都好了。为了不影响线上白天的业务，停止了任务。
为什么这么慢，慢在了哪里成了问题。查询了数据库，发现有2000w+条记录。数据量大是刷新慢的一部分原因。
只有一台预发布容器也是一部分原因。
同时查看代码，发现之前遍历数据库的方法有些问题。使用的是设置limit的方式去做，这么做降低了查询的效率。而且是越往后，查询效率越低，因为越往后查询，limit查询需要查询的内容在不断增加，查询效率急剧下降，从一开始的10ms，变成了后开的数秒。这是整个刷新任务慢的主要原因。
更换了刷新思路，改用有索引的id来查询。首先查出max(id)，然后分出5个区间来，让5台机器分担着去刷。这么一来，不到30分钟，2000w+的数据刷新就完毕了。火是灭了，得治里了。
2）代码修复
long到int的转换，做了判断。对于超过Integer.Max的long值，直接使用Integer.Max（实际的拼购时间不可能超过10年），小于等于的long值直接转换成int（截断也是安全的）。
至此，问题算是全部解决。后续跟踪日志，也没有发现有问题。线上也没有再爆有问题的拼购打标。小小的数值转换，埋下了祸根。
万幸的是，这个问题是产品经理发现的，而不是业务方投诉，未造成大的影响。另外，只是打标有问题，点击商品后，商详中显示的还是拼购商品，可能有些人还不知道店铺商品列表中应该需要打标。所以没有被发现和投诉吧。
本bug的影响范围也有限，因为在拼购时间超过24天的拼购信息中，有一部分设置成了永久缓存（强制转换成负数的情况）；剩余的设置成了短于结束时间的过期时间，而且只有等到时间过期后才会发现有问题的拼购打标。
【根本原因分析】
1、代码开发不够严谨。当时没有想到会有这么长时间的拼购时间，没有跟产品确认实际的时间需求，考虑不足。虽然写代码的时候隐约感觉到了问题，但是没有仔细地换算缓存时间是否够用，想当然的觉得1个月肯定没啥问题。
2、代码Review不足，只有在合并master代码的时候才有一次Review，而且只是一位同事Review，也不是会议的方式展开，比较随意，效果不好。
3、产品经理的PRD中没有明确的写出拼购有效时间的范围，也是导致开发时考虑遗漏的一个重要原因。产品经理的PRD过于粗糙，需要开发进一步细化，并加以提醒。
2、领券中心
6月1号左右，领券中心的监控中，有个接口的可用率始终在99%左右徘徊。线上没有投诉领券中心有什么问题。但是618大促期间，不敢怠慢。赶紧张罗调查原因。
【直接原因分析】
查看日志，发现时不时会出现NullPointerException，显然是代码逻辑问题。定位到代码，发现有个对象是可能为Null的。在我新增需求代码的时候，没有完全考虑全版本控制代码，忽视了低版本中某个对象为null的可能性（客户端版本小于6.5.0时会出现）。
这个问题之所以之前没有被发现，是因为在我修改前的老代码中，监控代码存在问题，对于异常情况并没有上报监控，导致监控中看到的接口调用始终是100%。原来的开发者发现了监控的问题，加上了完整的监控并上线（6月1日上线），6月1日该问题得以暴露。
虽然线上没什么投诉，但是从分析来看，这个确实是个BUG。
【根本原因分析】
1、客观上第一次在领券中心代码中开发新需求，在没有完全理解代码的情况下做了新功能扩展，导致了异常的发生。
2、开发周期缩短近一半，由于618前会封网，时间卡的比较死，急于上线的心态也是一个原因。
3、原作者review了代码，但是也没有发现问题。还是Review的方式存在问题，不够严谨。
4、对于异常情况，没有在最外层进行捕捉和处理，特别是异常的上报，导致上线后没有能够发现这个问题。
3、总结
以上是我在今年618期间所处理的两个线上问题。处理的过程中，心情复杂的。焦急、紧张、自责、歉疚、煎熬......五味杂陈。教训是深刻的，我想以后一看到long和int，一想到接口设计，这次的教训就会浮现出来。也许这就是这次经历的价值所在吧。
网友评论