问题描述

某产品线应用【A】接收应用【B】发送到MQ的消息，经过业务逻辑处理后，将数据存储到数据库中，近期发现应用【A】数据库表中有些记录的时间比应用【B]数据库表中对应记录的时间少了8个小时。
产品线反馈当前线上会断断续续地产生这种异常数据，异常数据量不清楚，估计不算多。

分析过程

相差整整8小时，最容易想到的就是时区问题，但是分析问题还是需要把问题如何发现、问题发现的时间、问题发生前后系统变更情况、异常数据量、影响范围（应用都存在问题还是局部存在问题）、异常数据是否存在规律性、相关系统如何交互等基本情况了解清楚，这些是基础也是最重要的判断依据。

分析数据，寻找规律

【B】应用的数据是准确的，通过对比找出【A】应用异常数据不同维度的统计信息。比如：分机构分时间（分天、分小时）统计异常数据的数量，根据这个统计信息可以判断出系统在什么时候开始出现问题及逐渐变化的过程（是逐渐变差的还是在某个时间突然就变差了），这个是产品线在问题发现时候就应该去做的事，很可惜并没有去做；异常数据并不是预估的不多，而是每天百万的量级。

通过异常数据中订单ID可以去系统中捞出这个订单从最开始处理到结束之间所有的日志（入参、处理过程中的参数等等），通过日志可以分析出发生问题的机器有哪些，确定了机器就比较有针对性了（该应用在线上有180台ECS），通过日志也可以在线下环境通过模拟回放的方式去尝试复现问题。由于缺少类似SLS的产品，当前日志分析比较辛苦和低效，这个做的结果不够清晰，也是这次分析问题比较遗憾的一个地方。

系统交互流程图

为了便于表达和理解，下面只对涉及时间的入参和操作进行逻辑抽象。

检查MQ消息

在日志中找到异常数据对应的MQ消息报文，时间戳字段值都是正确的。

确认时区配置

操作系统时钟正常：
检查应用180台ECS系统时间是否同步，Linux命令：date
操作系统时区正常：

• 检查/etc/localtime正常
• timedatectl，发现有报Warning的机器，经过数据确认，并不是造成时间不一致的原因

JVM时区配置正常（可以使用下面两种检查方式）：

• jinfo <pid> | grep user.timezone

user.timezone：PRC

• arthas：sysprop user.timezone

user.timezone：PRC

DRDS、RDS时区配置正常

由数据库负责同学进行检查

应用代码逻辑

数据库两个时间字段对应的类型均为：datetime
刨除其他无关逻辑，时间字段的处理逻辑可以用下面代码来表达：

数据库表：

经过代码Review（没有特殊的时间转换逻辑），也没有发现问题到底出在哪！

datetime和timestamp

这里有比较关键的知识点，需要引起关注：datetime、timestamp如何转换和存储的，示例解释如下：
datetime
该字段在MySQL Server中存进去的是什么取出来的就是什么
【datetime示例一】：

• JVM是UTC + 8，MySQL server session是UTC + 0
• JVM client原始时间是（UTC + 8）：2022-10-16 10:00:00
• MySQL JDBC Driver发送给MySQL server的时间是：2022-10-16 02:00:00（时间由UTC + 8转换为UTC + 0）
• MySQL server最终存储的时间为：2022-10-16 02:00:00
• JVM client从数据库中查出的时间是：2022-10-16 02:00:00

【datetime示例二】：

• JVM是UTC + 8，MySQL最初的server session是UTC + 0，MySQL JDBC Driver配置的是UTC + 1
• JVM client原始时间是（UTC + 8）：2022-10-16 10:00:00
• MySQL JDBC Driver发送给MySQL server的时间是：2022-10-16 03:00:00（时间由UTC + 8转换为UTC + 1）
• MySQL server最终存储的时间为：2022-10-16 03:00:00
• JVM client从数据库中查出的时间是：2022-10-16 03:00:00

从上面看出datetime最终存储的时间是与MySQL JDBC Driver Session配置的时区直接相关的；
timestamp
该字段在MySQL Server中存储的是UTC时间
【timestamp示例一】：

• JVM是UTC + 8，MySQL server session是UTC + 0
• JVM client原始时间是（UTC + 8）：2022-10-16 10:00:00
• MySQL JDBC Driver发送给MySQL server的时间是：2022-10-16 02:00:00（时间由UTC + 8转换为UTC + 0）
• MySQL Server最终存储的时间是：2022-10-16 02:00:00（不需要转换）
• 从MySQL Server检索到server session的时间是：2022-10-16 02:00:00（不需要转换）
• MySQL JDBC Driver在JVM时区内解析的时间是：2022-10-16 10:00:00（时间由UTC + 0转换为UTC + 8）
• 另外一台机器JVM时区是UTC + 9，MySQL JDBC Driver在该JVM内解析的时间是：2022-10-16 11:00:00（时间由UTC + 0转换为UTC + 9）

【timestamp示例二】：

• JVM是UTC + 8，MySQL最初的server session是UTC + 0，MySQL JDBC Driver配置的是UTC + 1
• JVM client原始时间是（UTC + 8）：2022-10-16 10:00:00
• MySQL JDBC Driver发送给MySQL server的时间是：2022-10-16 03:00:00（时间由UTC + 8转换为UTC + 1）
• MySQL Server最终存储的时间是：2022-10-16 02:00:00（时间由UTC + 1转换为UTC + 0）
• 从MySQL Server检索到server session的时间是：2022-10-16 03:00:00（MySQL内部转换，由UTC + 0转换为UTC + 1）
• MySQL JDBC Driver在JVM时区内解析的时间是：2022-10-16 10:00:00（时间由UTC + 1转换为UTC + 8）
• 另外一台机器JVM时区是UTC + 9，MySQL JDBC Driver在该JVM内解析的时间是：2022-10-16 11:00:00（时间由UTC + 1转换为UTC + 9）

JVM运行时时区

在上面我们排查了JVM时区配置属性user.timezone:PRC是正常的，同时我们也排查了几台机器的TimeZone.getDefault()也是正常的：

由于线上180台机器，检查TimeZone.getDefault()比较繁琐，所以没有对每台机器进行检查（这也是导致我们走了弯路的一步）。

柳暗花明

在应用排查的同时，我们排查了下游DRDS SQL日志，通过对比异常数据，在DRDS SQL日志中发现了错误SQL日志：

通过上面日志，找到了问题ECS的IP和端口号，登录到ECS，使用arthas查看TimeZone信息，居然是0时区：

接着查看了这台ECS上处理的数据都存在时区错误的情况。

之后在应用代码里搜索【TimeZone.setDefault】，发现了这样的代码：

最后通过与产品线沟通，这块代码偶尔会调用掉（无论如何这两行代码都是有问题的）。

异常场景复盘

从上图的【5.业务操作】之后，我们的数据开始出现异常。由于【5.业务操作】是即将下线的功能，后端服务器数量比较多，所以没有造成更大范围的异常数据。

解决办法

BUG修复

对于需要单独格式化时间的场景，可以为单独的DateFormat设置时区信息，示例：

时区配置监控&报警

• 定时采集时区配置（操作系统 OR JVM系统配置 OR JVM运行时时区）信息
• 对于异常数据及时报警出来