一、问题描述
商城系统今天上线了一个功能,用户在商城中点击商品详情页的去购买按钮时,如果商品是有代金券优惠活动的商品,则会先领券后计算商品金额。 这里面涉及到两步操作:调用领券接口,领券成功后,调用计算接口(计算商品价格接口),计算接口内部会调用代金券查券接口。遇到问题是,发券后,立即调用代金券查询代金券,查询不到刚发的代金券,停几秒中再去查,就可以查到,这种情况大概率会复现。
很奇怪的问题,代金券系统已经很久没有修改过了,线上也未爆出过发了代金券而查询不到的情况。
二、问题排查
一开始以为是数据库主从延迟导致的,把代金券查询接口日志打开,发现dao从库中查询时是可以查到刚发送的券,但是进行规则过滤后,代金券被过滤了,添加详细的日志,发现代金券是被有效期校验给过滤了。
代金券的有效期校验是:当前时间 >= 代金券创建时间 and 当前时间 <= 代金券结束时间
代金券有效期一般都是从发券时间开始,到发券时间+7天,因此当前时间必然<代金券结束时间,那么就是当前时间小于创建时间导致过滤,这就更奇怪了,发券在前,查询在后,查询时,系统时间应该是大于代金券创建时间的,为什么会被过滤呢。
查看数据库记录,发现一个奇怪的问题,代金券createtime居然比updatetime多了1s:
心理隐约感觉找到了方向。继续查看代金系统的日志,发现创建日志打印时间为:2021-07-01 14:18:41.529, 而查询代金券的时间为2021-07-01 14:18:41.611。
这大概就找到问题了,createTime入库时间比系统时间多了1秒,导致2021-07-01 14:18:41.611 < 2021-07-01 14:18:42。那么为什么入库时间会多1秒呢?
查看代金券createTime设值的代码:
setCreateTime(new Date());
取的是当前系统时间,而updateTime其值不是由java代码设置的,而是设置了默认值,也就时入库时,会取mysql current time。
看下createtime和updatetime的sql定义:
`create_time` datetime(0) DEFAULT '0000-00-00 00:00:00' COMMENT '创建时间',
`last_update_time` timestamp(0) DEFAULT CURRENT_TIMESTAMP(0) ON UPDATE CURRENT_TIMESTAMP(0) COMMENT '最后更新时间',
发现两个字段的类型居然不一致,createTime是datetime(0)类型,表示时间会精确到秒,而updateTime是timestamp(0)。
百度一番,发现这居然是mysql的一个bug, 当时间字段类型为datetime时,如果时间毫秒数小于500时,向下舍,如果大于等于500时向上加1秒,也就是:
2021-07-01 14:18:41.400 会存为2021-07-01 14:18:41
2021-07-01 14:18:41.591 会存为2021-07-01 14:18:42
https://wuxiangknow.cn/mysql/%E5%85%B3%E4%BA%8EMysql5.7%E5%AD%98%E5%82%A8%E6%97%B6%E9%97%B4%E5%A4%9A%E4%B8%80%E7%A7%92%E7%9A%84BUG/
线上之所以一直未爆出这个问题,主要是没有这种领券后,在极短时间(500ms内)就去查券的场景,而商城这个场景是自动发券自动查,间隔时间基本上100ms以内,才爆出这个问题。
三、问题解决
解决办法有3个: