問題描述

某產品線應用【A】接收應用【B】發送到MQ的消息，經過業務邏輯處理后，將數據存儲到數據庫中，近期發現應用【A】數據庫表中有些記錄的時間比應用【B]數據庫表中對應記錄的時間少了8個小時。產品線反饋當前線上會斷斷續續地產生這種異常數據，異常數據量不清楚，估計不算多。

分析過程

相差整整8小時，最容易想到的就是時區問題，但是分析問題還是需要把問題如何發現、問題發現的時間、問題發生前后系統變更情況、異常數據量、影響范圍（應用都存在問題還是局部存在問題）、異常數據是否存在規律性、相關系統如何交互等基本情況了解清楚，這些是基礎也是最重要的判斷依據。

分析數據，尋找規律

【B】應用的數據是準確的，通過對比找出【A】應用異常數據不同維度的統計信息。比如：分機構分時間（分天、分小時）統計異常數據的數量，根據這個統計信息可以判斷出系統在什么時候開始出現問題及逐漸變化的過程（是逐漸變差的還是在某個時間突然就變差了），這個是產品線在問題發現時候就應該去做的事，很可惜并沒有去做；異常數據并不是預估的不多，而是每天百萬的量級。

通過異常數據中訂單ID可以去系統中撈出這個訂單從最開始處理到結束之間所有的日志（入參、處理過程中的參數等等），通過日志可以分析出發生問題的機器有哪些，確定了機器就比較有針對性了（該應用在線上有180臺ECS），通過日志也可以在線下環境通過模擬回放的方式去嘗試復現問題。由于缺少類似SLS的產品，當前日志分析比較辛苦和低效，這個做的結果不夠清晰，也是這次分析問題比較遺憾的一個地方。

系統交互流程圖

為了便于表達和理解，下面只對涉及時間的入參和操作進行邏輯抽象。

系統交互關系

檢查MQ消息

在日志中找到異常數據對應的MQ消息報文，時間戳字段值都是正確的。

確認時區配置

操作系統時鐘正常：檢查應用180臺ECS系統時間是否同步，Linux命令：date操作系統時區正常：

• 檢查/etc/localtime正常
• timedatectl，發現有報Warning的機器，經過數據確認，并不是造成時間不一致的原因

正常

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()也是正常的：

user.timezone

由于線上180臺機器，檢查TimeZone.getDefault()比較繁瑣，所以沒有對每臺機器進行檢查（這也是導致我們走了彎路的一步）。

柳暗花明

在應用排查的同時，我們排查了下游DRDS SQL日志，通過對比異常數據，在DRDS SQL日志中發現了錯誤SQL日志：

DRDS sql log

通過上面日志，找到了問題ECS的IP和端口號，登錄到ECS，使用arthas查看TimeZone信息，居然是0時區：

user.timezone-GMT

接著查看了這臺ECS上處理的數據都存在時區錯誤的情況。

之后在應用代碼里搜索【TimeZone.setDefault】，發現了這樣的代碼：

異常代碼

最后通過與產品線溝通，這塊代碼偶爾會調用掉（無論如何這兩行代碼都是有問題的）。

異常場景復盤

異常場景

從上圖的【5.業務操作】之后，我們的數據開始出現異常。由于【5.業務操作】是即將下線的功能，后端服務器數量比較多，所以沒有造成更大范圍的異常數據。

解決辦法

BUG修復

對于需要單獨格式化時間的場景，可以為單獨的DateFormat設置時區信息，示例：

DateFormat示例

時區配置監控&報警

定時采集時區配置（操作系統 OR JVM系統配置 OR JVM運行時時區）信息。

對于異常數據及時報警出來?。