數(shù)據(jù)庫時(shí)間慢了14個(gè)小時(shí)，Mybatis說，這個(gè)鍋我不背！
本文轉(zhuǎn)載自微信公眾號(hào)「程序新視界」，作者二師兄。轉(zhuǎn)載本文請(qǐng)聯(lián)系程序新視界公眾號(hào)。
同事反饋一個(gè)問題：Mybatis插入數(shù)據(jù)庫的時(shí)間是昨天的，是不是因?yàn)樯蒑ybatis逆向工程生成的代碼有問題?
大家都知道，對(duì)于這類Bug本人是很感興趣的。直覺告訴我，應(yīng)該不是Mybatis的Bug，很可能是時(shí)區(qū)的問題。
很好，今天又可以帶大家一起來排查Bug了，看看從這次的Bug排查中你能Get什么技能。
這次研究的問題有點(diǎn)深?yuàn)W，但結(jié)論很重要。Let's go!
問題猜想
同事反饋問題的時(shí)候，帶了自己的猜想：是不是數(shù)據(jù)庫字段設(shè)置為datetime導(dǎo)致?是不是Mybatis逆向工程生成的代碼中類型不一致導(dǎo)致的?
同事還要把datetime改為varchar……馬上被我制止了，說：先排查問題，再說解決方案，下午我也抽時(shí)間看看。
問題核查
第一步，檢查數(shù)據(jù)庫字段類型，是datetime的，沒問題。
第二步，檢查實(shí)體類中類型，是java.util.Date類型，沒問題。
第三步，Bug復(fù)現(xiàn)。
在Bug復(fù)現(xiàn)這一步，用到了單元測(cè)試。話說之前還跟朋友討論過單元測(cè)試的魅力，現(xiàn)在本人是越來越喜歡單元測(cè)試了。
項(xiàng)目基于Spring Boot的，單元測(cè)試如下(代碼已脫敏)：
- @SpringBootTest
- class DateTimeTests {
- @Resource
- private UserMapper userMapper;
- @Test
- public void testDate(){
- User user = new User();
- // 省略其他字段
- user.setCreateDate(new Date());
- userMapper.insertSelective(user);
- }
- }
執(zhí)行單元測(cè)試，查看數(shù)據(jù)庫中插入的數(shù)據(jù)。Bug復(fù)現(xiàn)，時(shí)間的確是前一天的，與當(dāng)前時(shí)間相差14個(gè)小時(shí)。
經(jīng)過上面三步的排查，核實(shí)了數(shù)據(jù)庫字段和代碼中類型沒問題。單元測(cè)試也復(fù)現(xiàn)了問題，同事沒有欺騙我，總要眼見為實(shí)，哈哈。
于是基本確定是時(shí)區(qū)問題。
時(shí)區(qū)排查
檢查服務(wù)器時(shí)間
登錄測(cè)試服務(wù)器，執(zhí)行date命令，檢查服務(wù)器時(shí)間和時(shí)區(qū)：
- [root@xxx ~]# date
- 2021年 11月 25日 星期四 09:26:25 CST
- [root@xxx ~]# date -R
- Thu, 25 Nov 2021 09:33:34 +0800
顯示時(shí)間是當(dāng)前時(shí)間，采用CST時(shí)間，最后的+0800，即東8區(qū)，沒問題。
檢查數(shù)據(jù)庫時(shí)區(qū)
連接數(shù)據(jù)庫，執(zhí)行show命令：
- show variables like '%time_zone%';
- +----------------------------+
- |Variable | Value |
- +----------------------------+
- |system_time_zone |CST |
- |time_zone |SYSTEM |
- system_time_zone：全局參數(shù)，系統(tǒng)時(shí)區(qū)，在MySQL啟動(dòng)時(shí)會(huì)檢查當(dāng)前系統(tǒng)的時(shí)區(qū)并根據(jù)系統(tǒng)時(shí)區(qū)設(shè)置全局參數(shù)system_time_zone的值。值為CST，與系統(tǒng)時(shí)間的時(shí)區(qū)一致。
- time_zone：全局參數(shù)，設(shè)置每個(gè)連接會(huì)話的時(shí)區(qū)，默認(rèn)為SYSTEM，使用全局參數(shù)system_time_zone的值。
檢查代碼中時(shí)區(qū)
在單元測(cè)試的方法內(nèi)再添加打印時(shí)區(qū)的代碼：
- @Test
- public void testDate(){
- System.out.println(System.getProperty("user.timezone"));
- User user = new User();
- // 省略其他字段
- user.setCreateDate(new Date());
- userMapper.insertSelective(user);
- }
打印的時(shí)區(qū)為：
- Asia/Shanghai
也就是說Java中使用的是UTC時(shí)區(qū)進(jìn)行業(yè)務(wù)邏輯處理的，也是東八區(qū)的時(shí)間。
那么問題到底出在哪里呢?
問題基本呈現(xiàn)
經(jīng)過上述排查，基本上確定是時(shí)區(qū)的問題。這里，再補(bǔ)充一下上述相關(guān)的時(shí)區(qū)知識(shí)點(diǎn)。
UTC時(shí)間
UTC時(shí)間：世界協(xié)調(diào)時(shí)間(UTC)是世界上不同國家用來調(diào)節(jié)時(shí)鐘和時(shí)間的主要時(shí)間標(biāo)準(zhǔn)，也就是零時(shí)區(qū)的時(shí)間。
UTC, Coordinated Universal Time是一個(gè)標(biāo)準(zhǔn)，而不是一個(gè)時(shí)區(qū)。UTC 是一個(gè)全球通用的時(shí)間標(biāo)準(zhǔn)。全球各地都同意將各自的時(shí)間進(jìn)行同步協(xié)調(diào) (coordinated)，這也是UTC名字的來源：Universal Coordinated Time。
CST時(shí)間
CST時(shí)間：中央標(biāo)準(zhǔn)時(shí)間。
CST可以代表如下4個(gè)不同的時(shí)區(qū)：
- Central Standard Time (USA) UT-6:00，美國
- Central Standard Time (Australia) UT+9:30，澳大利亞
- China Standard Time UT+8:00，中國
- Cuba Standard Time UT-4:00，古巴
再次分析
很顯然，這里與UTC時(shí)間無關(guān)，它只是時(shí)間標(biāo)準(zhǔn)。目前Mysql中的system_time_zone是CST，而CST可以代表4個(gè)不同的時(shí)區(qū)，那么，Mysql把它當(dāng)做哪個(gè)時(shí)區(qū)進(jìn)行處理了呢?
簡單推算一下，中國時(shí)間是UT+8:00，美國是 UT-6:00，當(dāng)傳入中國時(shí)間，直接轉(zhuǎn)換為美國時(shí)間(未考慮時(shí)區(qū)問題)，時(shí)間便慢了14個(gè)小時(shí)。
既然知道了問題，那么解決方案也就有了。
解決方案
針對(duì)上述問題可通過數(shù)據(jù)庫層面和代碼層面進(jìn)行解決。
方案一：修改數(shù)據(jù)庫時(shí)區(qū)
既然是MySQL理解錯(cuò)了CST指定的時(shí)區(qū)，那么就將其設(shè)置為正確的。
連接Mysql數(shù)據(jù)庫，設(shè)置正確的時(shí)區(qū)：
- [root@xxxxx ~]# mysql -uroot -p
- mysql> set global time_zone = '+8:00';
- mysql> set time_zone = '+8:00'
- mysql> flush privileges;
再次執(zhí)行show命令：
- show variables like '%time_zone%';
- +----------------------------+
- |Variable | Value |
- +----------------------------+
- |system_time_zone |CST |
- |time_zone |+08:00 |
可以看到時(shí)區(qū)已經(jīng)成為東八區(qū)的時(shí)間了。再次執(zhí)行單元測(cè)試，問題得到解決。
此種方案也可以直接修改MySQL的my.cnf文件進(jìn)行指定時(shí)區(qū)。
方案二：修改數(shù)據(jù)庫連接參數(shù)
在代碼連接數(shù)據(jù)庫時(shí)，通過參數(shù)指定所使用的時(shí)區(qū)。
在配置數(shù)據(jù)庫連接的URL后面添加上指定的時(shí)區(qū)serverTimezone=Asia/Shanghai：
- url: jdbc:mysql://xx.xx.xx.xx:3306/db_name?useUnicode=true&characterEncoding=utf8&autoReconnect=true&serverTimezone=Asia/Shanghai
再次執(zhí)行單元測(cè)試，問題同樣可以得到解決。
問題完了?
經(jīng)過上述分析與操作，時(shí)區(qū)的問題已經(jīng)解決了。問題就這么完事了嗎?為什么是這樣呢?
為了驗(yàn)證時(shí)區(qū)問題，在時(shí)區(qū)錯(cuò)誤的數(shù)據(jù)庫中，創(chuàng)建了一個(gè)字段，該字段類型為datetime，默認(rèn)值為CURRENT_TIMESTAMP。
那么，此時(shí)插入一條記錄，讓Mysql自動(dòng)生成該字段的時(shí)間，你猜該字段的時(shí)間是什么?中國時(shí)間。
神奇不?為什么同樣是CST時(shí)區(qū)，系統(tǒng)自動(dòng)生成的時(shí)間是正確的，而代碼插入的時(shí)間就有時(shí)差問題呢?
到底是Mysql將CST時(shí)區(qū)理解為美國時(shí)間了，還是Mybatis、連接池或驅(qū)動(dòng)程序?qū)⑵淅斫鉃槊绹鴷r(shí)間了?
重頭戲開始
為了追查到底是代碼中哪里出了問題，先開啟Mybatis的debug日志，看看insert時(shí)是什么值：
- 2021-11-25 11:05:28.367 [|1637809527983|] DEBUG 20178 --- [ scheduling-1] c.h.s.m.H.listByCondition : ==> Parameters: 2021-11-25 11:05:27(String), 0(Integer), 1(Integer), 2(Integer), 3(Integer), 4(Integer)
上面是insert時(shí)的參數(shù)，也就是說在Mybatis層面時(shí)間是沒問題的。排除一個(gè)。
那是不是連接池或驅(qū)動(dòng)程序的問題?連接池本身來講跟數(shù)據(jù)庫連接的具體操作關(guān)系不大，就直接來排查驅(qū)動(dòng)程序。
Mybatis是xml中定義日期字段類型為TIMESTAMP，扒了一下mysql-connector-Java-8.0.x的源碼，發(fā)現(xiàn)SqlTimestampValueFactory是用來處理TIMESTAMP類型的。
在SqlTimestampValueFactory的構(gòu)造方法上打上斷點(diǎn)，執(zhí)行單元測(cè)試：
timezone
可以明確的看到，Calendar將時(shí)區(qū)設(shè)置為Locale.US，也就是美國時(shí)間，時(shí)區(qū)為CST，offset為-21600000。-21600000單位為毫秒，轉(zhuǎn)化為小時(shí)，恰好是“-6:00”，這與北京時(shí)間“GMT+08:00”恰好相差14個(gè)小時(shí)。
于是一路往上最終追溯調(diào)用鏈路，該TimeZone來自NativeServerSession的serverTimeZone，而serverTimeZone的值是由NativeProtocol類的configureTimezone方法設(shè)置的。
- public void configureTimezone() {
- String configuredTimeZoneOnServer = this.serverSession.getServerVariable("time_zone");
- if ("SYSTEM".equalsIgnoreCase(configuredTimeZoneOnServer)) {
- configuredTimeZoneOnServer = this.serverSession.getServerVariable("system_time_zone");
- }
- String canonicalTimezone = getPropertySet().getStringProperty(PropertyKey.serverTimezone).getValue();
- if (configuredTimeZoneOnServer != null) {
- // user can override this with driver properties, so don't detect if that's the case
- if (canonicalTimezone == null || StringUtils.isEmptyOrWhitespaceOnly(canonicalTimezone)) {
- try {
- canonicalTimezone = TimeUtil.getCanonicalTimezone(configuredTimeZoneOnServer, getExceptionInterceptor());
- } catch (IllegalArgumentException iae) {
- throw ExceptionFactory.createException(WrongArgumentException.class, iae.getMessage(), getExceptionInterceptor());
- }
- }
- }
- if (canonicalTimezone != null && canonicalTimezone.length() > 0) {
- // 此處設(shè)置TimeZone
- this.serverSession.setServerTimeZone(TimeZone.getTimeZone(canonicalTimezone));
- if (!canonicalTimezone.equalsIgnoreCase("GMT") && this.serverSession.getServerTimeZone().getID().equals("GMT")) {
- throw ExceptionFactory.createException(WrongArgumentException.class, Messages.getString("Connection.9", new Object[] { canonicalTimezone }),
- getExceptionInterceptor());
- }
- }
- }
debug跟蹤一下上述代碼，顯示信息如下：
CST獲得
至此，通過canonicalTimezone值的獲取，可以看出URL后面配置serverTimezone=Asia/Shanghai的作用了。其中，上面第一個(gè)代碼塊獲取time_zone的值，第二個(gè)代碼塊中獲取system_time_zone的值。這與查詢數(shù)據(jù)庫獲得的值一致。
因?yàn)槌鰡栴}時(shí)并未在url中添加參數(shù)serverTimezone=Asia/Shanghai，所以走canonicalTimezone為null的情況。隨后邏輯中調(diào)用了TimeUtil.getCanonicalTimezone方法：
- public static String getCanonicalTimezone(String timezoneStr, ExceptionInterceptor exceptionInterceptor) {
- if (timezoneStr == null) {
- return null;
- }
- timezoneStr = timezoneStr.trim();
- // handle '+/-hh:mm' form ...
- if (timezoneStr.length() > 2) {
- if ((timezoneStr.charAt(0) == '+' || timezoneStr.charAt(0) == '-') && Character.isDigit(timezoneStr.charAt(1))) {
- return "GMT" + timezoneStr;
- }
- }
- synchronized (TimeUtil.class) {
- if (timeZoneMappings == null) {
- loadTimeZoneMappings(exceptionInterceptor);
- }
- }
- String canonicalTz;
- if ((canonicalTz = timeZoneMappings.getProperty(timezoneStr)) != null) {
- return canonicalTz;
- }
- throw ExceptionFactory.createException(InvalidConnectionAttributeException.class,
- Messages.getString("TimeUtil.UnrecognizedTimezoneId", new Object[] { timezoneStr }), exceptionInterceptor);
- }
上述代碼中最終走到了loadTimeZoneMappings(exceptionInterceptor);方法：
- private static void loadTimeZoneMappings(ExceptionInterceptor exceptionInterceptor) {
- timeZoneMappings = new Properties();
- try {
- timeZoneMappings.load(TimeUtil.class.getResourceAsStream(TIME_ZONE_MAPPINGS_RESOURCE));
- } catch (IOException e) {
- throw ExceptionFactory.createException(Messages.getString("TimeUtil.LoadTimeZoneMappingError"), exceptionInterceptor);
- }
- // bridge all Time Zone ids known by Java
- for (String tz : TimeZone.getAvailableIDs()) {
- if (!timeZoneMappings.containsKey(tz)) {
- timeZoneMappings.put(tz, tz);
- }
- }
- }
該方法加載了配置文件"/com/mysql/cj/util/TimeZoneMapping.properties"里面的值，經(jīng)過轉(zhuǎn)換，timeZoneMappings中，對(duì)應(yīng)CST的為"CST"。
最終得到canonicalTimezone為“CST”，而TimeZone獲得是通過TimeZone.getTimeZone(canonicalTimezone)方法獲得的。
也就是說TimeZone.getTimeZone("CST")的值為美國時(shí)間。寫個(gè)單元測(cè)試驗(yàn)證一下：
- public class TimeZoneTest {
- @Test
- public void testTimeZone(){
- System.out.println(TimeZone.getTimeZone("CST"));
- }
- }
打印結(jié)果：
- sun.util.calendar.ZoneInfo[id="CST",offset=-21600000,dstSavings=3600000,useDaylight=true,transitions=235,lastRule=java.util.SimpleTimeZone[id=CST,offset=-21600000,dstSavings=3600000,useDaylight=true,startYear=0,startMode=3,startMonth=2,startDay=8,startDayOfWeek=1,startTime=7200000,startTimeMode=0,endMode=3,endMonth=10,endDay=1,endDayOfWeek=1,endTime=7200000,endTimeMode=0]]
很顯然，該方法傳入CST之后，默認(rèn)是美國時(shí)間。
至此，問題原因基本明朗：
- Mysql中設(shè)置的server_time_zone為CST，time_zone為SYSTEM。
- Mysql驅(qū)動(dòng)查詢到time_zone為SYSTEM，于是使用server_time_zone的值，為”CST“。
- JDK中TimeZone.getTimeZone("CST")獲得的值為美國時(shí)區(qū);
- 以美國時(shí)區(qū)構(gòu)造的Calendar類;
- SqlTimestampValueFactory使用上述Calendar來格式化系統(tǒng)獲取的中國時(shí)間，時(shí)差問題便出現(xiàn)了;
- 最終反映在數(shù)據(jù)庫數(shù)據(jù)上就是錯(cuò)誤的時(shí)間。
serverVariables變量
再延伸一下，其中server_time_zone和time_zone都來自于NativeServerSession的serverVariables變量，該變量在NativeSession的loadServerVariables方法中進(jìn)行初始化，關(guān)鍵代碼：
- if (versionMeetsMinimum(5, 1, 0)) {
- StringBuilder queryBuf = new StringBuilder(versionComment).append("SELECT");
- queryBuf.append(" @@session.auto_increment_increment AS auto_increment_increment");
- queryBuf.append(", @@character_set_client AS character_set_client");
- queryBuf.append(", @@character_set_connection AS character_set_connection");
- queryBuf.append(", @@character_set_results AS character_set_results");
- queryBuf.append(", @@character_set_server AS character_set_server");
- queryBuf.append(", @@collation_server AS collation_server");
- queryBuf.append(", @@collation_connection AS collation_connection");
- queryBuf.append(", @@init_connect AS init_connect");
- queryBuf.append(", @@interactive_timeout AS interactive_timeout");
- if (!versionMeetsMinimum(5, 5, 0)) {
- queryBuf.append(", @@language AS language");
- }
- queryBuf.append(", @@license AS license");
- queryBuf.append(", @@lower_case_table_names AS lower_case_table_names");
- queryBuf.append(", @@max_allowed_packet AS max_allowed_packet");
- queryBuf.append(", @@net_write_timeout AS net_write_timeout");
- queryBuf.append(", @@performance_schema AS performance_schema");
- if (!versionMeetsMinimum(8, 0, 3)) {
- queryBuf.append(", @@query_cache_size AS query_cache_size");
- queryBuf.append(", @@query_cache_type AS query_cache_type");
- }
- queryBuf.append(", @@sql_mode AS sql_mode");
- queryBuf.append(", @@system_time_zone AS system_time_zone");
- queryBuf.append(", @@time_zone AS time_zone");
- if (versionMeetsMinimum(8, 0, 3) || (versionMeetsMinimum(5, 7, 20) && !versionMeetsMinimum(8, 0, 0))) {
- queryBuf.append(", @@transaction_isolation AS transaction_isolation");
- } else {
- queryBuf.append(", @@tx_isolation AS transaction_isolation");
- }
- queryBuf.append(", @@wait_timeout AS wait_timeout");
- NativePacketPayload resultPacket = sendCommand(this.commandBuilder.buildComQuery(null, queryBuf.toString()), false, 0);
- Resultset rs = ((NativeProtocol) this.protocol).readAllResults(-1, false, resultPacket, false, null,
- new ResultsetFactory(Type.FORWARD_ONLY, null));
- Field[] f = rs.getColumnDefinition().getFields();
- if (f.length > 0) {
- ValueFactory<String> vf = new StringValueFactory(this.propertySet);
- Row r;
- if ((r = rs.getRows().next()) != null) {
- for (int i = 0; i < f.length; i++) {
- this.protocol.getServerSession().getServerVariables().put(f[i].getColumnLabel(), r.getValue(i, vf));
- }
- }
- }
在上述StringBuilder的append操作中，有"@@time_zone AS time_zone"和"@@system_time_zone AS system_time_zone"兩個(gè)值，然后查詢數(shù)據(jù)庫，從數(shù)據(jù)庫獲得值之后，put到serverVariables中。
再來debug一下：
system_time_zone
可以看出system_time_zone的值為CST。
time_zone
同樣time_zone的值為“SYSTEM”。
根據(jù)代碼中的提示，拼接與代碼一樣的SQL查詢一下數(shù)據(jù)庫：
- select @@time_zone;
- SYSTEM
值的確是“SYSTEM”。此時(shí)，我們又得出另外一個(gè)查詢Mysql當(dāng)前時(shí)區(qū)的方法。
至此，該問題的排查完美收官。大出一口氣。
小結(jié)
在上述問題排查的過程中，多次用到單元測(cè)試，這也是單元測(cè)試的魅力所在，用最簡單的代碼，最輕量的邏輯，最節(jié)省時(shí)間的方式來驗(yàn)證和追蹤錯(cuò)誤。
再回顧一下上述Bug排查中用到和學(xué)到的知識(shí)點(diǎn)：
- Linux日期查看，時(shí)區(qū)查看及衍生如何配置時(shí)區(qū);
- Mysql時(shí)區(qū)查看;
- Spring Boot單元測(cè)試;
- Java時(shí)區(qū)獲取;
- UTC時(shí)間和CST時(shí)間;
- 兩種解決時(shí)區(qū)問題的方案;
- 閱讀、debug Mysql驅(qū)動(dòng)源代碼;
- TimeZone.getTimeZone("CST")默認(rèn)時(shí)區(qū)為美國時(shí)區(qū);
- Mysql驅(qū)動(dòng)中處理時(shí)區(qū)問題基本流程邏輯;
- Mybatis debug日志相關(guān)打印;
- 其他相關(guān)知識(shí)。
通過本篇Bug查找的文章，你學(xué)到了什么?如果有那么一點(diǎn)啟發(fā)，不要吝嗇，給點(diǎn)個(gè)贊吧!
