問題描述

某產(chǎn)品線應(yīng)用【A】接收應(yīng)用【B】發(fā)送到MQ的消息，經(jīng)過業(yè)務(wù)邏輯處理后，將數(shù)據(jù)存儲(chǔ)到數(shù)據(jù)庫中，近期發(fā)現(xiàn)應(yīng)用【A】數(shù)據(jù)庫表中有些記錄的時(shí)間比應(yīng)用【B]數(shù)據(jù)庫表中對應(yīng)記錄的時(shí)間少了8個(gè)小時(shí)。產(chǎn)品線反饋當(dāng)前線上會(huì)斷斷續(xù)續(xù)地產(chǎn)生這種異常數(shù)據(jù)，異常數(shù)據(jù)量不清楚，估計(jì)不算多。

分析過程

相差整整8小時(shí)，最容易想到的就是時(shí)區(qū)問題，但是分析問題還是需要把問題如何發(fā)現(xiàn)、問題發(fā)現(xiàn)的時(shí)間、問題發(fā)生前后系統(tǒng)變更情況、異常數(shù)據(jù)量、影響范圍（應(yīng)用都存在問題還是局部存在問題）、異常數(shù)據(jù)是否存在規(guī)律性、相關(guān)系統(tǒng)如何交互等基本情況了解清楚，這些是基礎(chǔ)也是最重要的判斷依據(jù)。

分析數(shù)據(jù)，尋找規(guī)律

【B】應(yīng)用的數(shù)據(jù)是準(zhǔn)確的，通過對比找出【A】應(yīng)用異常數(shù)據(jù)不同維度的統(tǒng)計(jì)信息。比如：分機(jī)構(gòu)分時(shí)間（分天、分小時(shí)）統(tǒng)計(jì)異常數(shù)據(jù)的數(shù)量，根據(jù)這個(gè)統(tǒng)計(jì)信息可以判斷出系統(tǒng)在什么時(shí)候開始出現(xiàn)問題及逐漸變化的過程（是逐漸變差的還是在某個(gè)時(shí)間突然就變差了），這個(gè)是產(chǎn)品線在問題發(fā)現(xiàn)時(shí)候就應(yīng)該去做的事，很可惜并沒有去做；異常數(shù)據(jù)并不是預(yù)估的不多，而是每天百萬的量級(jí)。

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

系統(tǒng)交互流程圖

為了便于表達(dá)和理解，下面只對涉及時(shí)間的入?yún)⒑筒僮鬟M(jìn)行邏輯抽象。

系統(tǒng)交互關(guān)系

檢查MQ消息

在日志中找到異常數(shù)據(jù)對應(yīng)的MQ消息報(bào)文，時(shí)間戳字段值都是正確的。

確認(rèn)時(shí)區(qū)配置

操作系統(tǒng)時(shí)鐘正常：檢查應(yīng)用180臺(tái)ECS系統(tǒng)時(shí)間是否同步，Linux命令：date操作系統(tǒng)時(shí)區(qū)正常：

• 檢查/etc/localtime正常
• timedatectl，發(fā)現(xiàn)有報(bào)Warning的機(jī)器，經(jīng)過數(shù)據(jù)確認(rèn)，并不是造成時(shí)間不一致的原因

正常

Warning

JVM時(shí)區(qū)配置正常（可以使用下面兩種檢查方式）：

• jinfo <pid> | grep user.timezone

user.timezone：PRC

• arthas：sysprop user.timezone

user.timezone：PRC

DRDS、RDS時(shí)區(qū)配置正常

由數(shù)據(jù)庫負(fù)責(zé)同學(xué)進(jìn)行檢查

應(yīng)用代碼邏輯

數(shù)據(jù)庫兩個(gè)時(shí)間字段對應(yīng)的類型均為：datetime刨除其他無關(guān)邏輯，時(shí)間字段的處理邏輯可以用下面代碼來表達(dá)：

應(yīng)用代碼邏輯

數(shù)據(jù)庫表：

表結(jié)構(gòu)

經(jīng)過代碼Review（沒有特殊的時(shí)間轉(zhuǎn)換邏輯），也沒有發(fā)現(xiàn)問題到底出在哪！

datetime和timestamp

這里有比較關(guān)鍵的知識(shí)點(diǎn)，需要引起關(guān)注：datetime、timestamp如何轉(zhuǎn)換和存儲(chǔ)的，示例解釋如下：

datetime該字段在MySQL Server中存進(jìn)去的是什么取出來的就是什么

【datetime示例一】：

• JVM是UTC + 8，MySQL server session是UTC + 0
• JVM client原始時(shí)間是（UTC + 8）：2022-10-16 10:00:00
• MySQL JDBC Driver發(fā)送給MySQL server的時(shí)間是：2022-10-16 02:00:00（時(shí)間由UTC + 8轉(zhuǎn)換為UTC + 0）
• MySQL server最終存儲(chǔ)的時(shí)間為：2022-10-16 02:00:00
• JVM client從數(shù)據(jù)庫中查出的時(shí)間是：2022-10-16 02:00:00

【datetime示例二】：

• JVM是UTC + 8，MySQL最初的server session是UTC + 0，MySQL JDBC Driver配置的是UTC + 1
• JVM client原始時(shí)間是（UTC + 8）：2022-10-16 10:00:00
• MySQL JDBC Driver發(fā)送給MySQL server的時(shí)間是：2022-10-16 03:00:00（時(shí)間由UTC + 8轉(zhuǎn)換為UTC + 1）
• MySQL server最終存儲(chǔ)的時(shí)間為：2022-10-16 03:00:00
• JVM client從數(shù)據(jù)庫中查出的時(shí)間是：2022-10-16 03:00:00

從上面看出datetime最終存儲(chǔ)的時(shí)間是與MySQL JDBC Driver Session配置的時(shí)區(qū)直接相關(guān)的；

timestamp該字段在MySQL Server中存儲(chǔ)的是UTC時(shí)間

【timestamp示例一】：

• JVM是UTC + 8，MySQL server session是UTC + 0
• JVM client原始時(shí)間是（UTC + 8）：2022-10-16 10:00:00
• MySQL JDBC Driver發(fā)送給MySQL server的時(shí)間是：2022-10-16 02:00:00（時(shí)間由UTC + 8轉(zhuǎn)換為UTC + 0）
• MySQL Server最終存儲(chǔ)的時(shí)間是：2022-10-16 02:00:00（不需要轉(zhuǎn)換）
• 從MySQL Server檢索到server session的時(shí)間是：2022-10-16 02:00:00（不需要轉(zhuǎn)換）
• MySQL JDBC Driver在JVM時(shí)區(qū)內(nèi)解析的時(shí)間是：2022-10-16 10:00:00（時(shí)間由UTC + 0轉(zhuǎn)換為UTC + 8）
• 另外一臺(tái)機(jī)器JVM時(shí)區(qū)是UTC + 9，MySQL JDBC Driver在該JVM內(nèi)解析的時(shí)間是：2022-10-16 11:00:00（時(shí)間由UTC + 0轉(zhuǎn)換為UTC + 9）

【timestamp示例二】：

• JVM是UTC + 8，MySQL最初的server session是UTC + 0，MySQL JDBC Driver配置的是UTC + 1
• JVM client原始時(shí)間是（UTC + 8）：2022-10-16 10:00:00
• MySQL JDBC Driver發(fā)送給MySQL server的時(shí)間是：2022-10-16 03:00:00（時(shí)間由UTC + 8轉(zhuǎn)換為UTC + 1）
• MySQL Server最終存儲(chǔ)的時(shí)間是：2022-10-16 02:00:00（時(shí)間由UTC + 1轉(zhuǎn)換為UTC + 0）
• 從MySQL Server檢索到server session的時(shí)間是：2022-10-16 03:00:00（MySQL內(nèi)部轉(zhuǎn)換，由UTC + 0轉(zhuǎn)換為UTC + 1）
• MySQL JDBC Driver在JVM時(shí)區(qū)內(nèi)解析的時(shí)間是：2022-10-16 10:00:00（時(shí)間由UTC + 1轉(zhuǎn)換為UTC + 8）
• 另外一臺(tái)機(jī)器JVM時(shí)區(qū)是UTC + 9，MySQL JDBC Driver在該JVM內(nèi)解析的時(shí)間是：2022-10-16 11:00:00（時(shí)間由UTC + 1轉(zhuǎn)換為UTC + 9）

JVM運(yùn)行時(shí)時(shí)區(qū)

在上面我們排查了JVM時(shí)區(qū)配置屬性user.timezone:PRC是正常的，同時(shí)我們也排查了幾臺(tái)機(jī)器的TimeZone.getDefault()也是正常的：

user.timezone

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

柳暗花明

在應(yīng)用排查的同時(shí)，我們排查了下游DRDS SQL日志，通過對比異常數(shù)據(jù)，在DRDS SQL日志中發(fā)現(xiàn)了錯(cuò)誤SQL日志：

DRDS sql log

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

user.timezone-GMT

接著查看了這臺(tái)ECS上處理的數(shù)據(jù)都存在時(shí)區(qū)錯(cuò)誤的情況。

之后在應(yīng)用代碼里搜索【TimeZone.setDefault】，發(fā)現(xiàn)了這樣的代碼：

異常代碼

最后通過與產(chǎn)品線溝通，這塊代碼偶爾會(huì)調(diào)用掉（無論如何這兩行代碼都是有問題的）。

異常場景復(fù)盤

異常場景

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

解決辦法

BUG修復(fù)

對于需要單獨(dú)格式化時(shí)間的場景，可以為單獨(dú)的DateFormat設(shè)置時(shí)區(qū)信息，示例：

DateFormat示例

時(shí)區(qū)配置監(jiān)控&報(bào)警

定時(shí)采集時(shí)區(qū)配置（操作系統(tǒng) OR JVM系統(tǒng)配置 OR JVM運(yùn)行時(shí)時(shí)區(qū)）信息。

對于異常數(shù)據(jù)及時(shí)報(bào)警出來?。