MySQL:timestamp 時區轉換導致 CPU %sys 高的問題

文章末尾有他著作的《深入理解 MySQL 主從原理 32 講》,深入透徹理解 MySQL 主從,GTID 相關技術知識。

本文為學習記錄,可能有誤請諒解。

本文建議PC端觀看,效果更佳。

這個問題是一個朋友遇到的@風雲,並且這位朋友已經得出了近乎正確的判斷,下面進行一些描述。

一、問題展示

下面是問題當時的系統負載如下:

技術分享 | MySQL:timestamp 時區轉換導致 CPU %sys 高的問題

我們可以看到 40.4%sy 正是系統調用負載較高的表現,隨即朋友採集了 perf 如下:

技術分享 | MySQL:timestamp 時區轉換導致 CPU %sys 高的問題

接下來朋友採集了 pstack 給我,我發現大量的線程處於如下狀態下:

Thread 38 (Thread 0x7fe57a86f700 (LWP 67268)):#0 0x0000003dee4f82ce in __lll_lock_wait_private () from /lib64/libc.so.6#1 0x0000003dee49df8d in _L_lock_2163 () from /lib64/libc.so.6#2 0x0000003dee49dd47 in __tz_convert () from /lib64/libc.so.6#3 0x00000000007c02e7 in Time_zone_system::gmt_sec_to_TIME(st_mysql_time*, long) const ()#4 0x0000000000811df6 in Field_timestampf::get_date_internal(st_mysql_time*) ()#5 0x0000000000809ea9 in Field_temporal_with_date::val_date_temporal() ()#6 0x00000000005f43cc in get_datetime_value(THD*, Item***, Item**, Item*, bool*) ()#7 0x00000000005e7ba7 in Arg_comparator::compare_datetime() ()#8 0x00000000005eef4e in Item_func_gt::val_int() ()#9 0x00000000006fc6ab in evaluate_join_record(JOIN*, st_join_table*) ()#10 0x0000000000700e7e in sub_select(JOIN*, st_join_table*, bool) ()#11 0x00000000006fecc1 in JOIN::exec() ()

我們可以注意一下 __tz_convert 這正是時區轉換的證據。

二、關於 timestamp 簡要說明

timestamp:佔用 4 字節,內部實現是新紀元時間(1970-01-01 00:00:00)以來的秒,那麼這種格式在展示給用戶的時候就需要做必要的時區轉換才能得到正確數據。下面我們通過訪問 ibd 文件來查看一下內部表示方法,使用到了我的兩個工具 innodb 和 bcview。

詳細參考:https://www.jianshu.com/p/719f1bbb21e8。

timestamp 的內部表示

建立一個測試表

mysql> show variables like '%time_zone%';+------------------+--------+| Variable_name | Value |+------------------+--------+| system_time_zone | CST || time_zone | +08:00 |+------------------+--------+
mysql> create table tmm(dt timestamp);Query OK, 0 rows affected (0.04 sec)
mysql> insert into tmm values('2019-01-01 01:01:01');Query OK, 1 row affected (0.00 sec)

我們來查看一下內部表示如下:

[root@gp1 test]# ./bcview tmm.ibd 16 125 25|grep 00000003current block:00000003--Offset:00125--cnt bytes:25--data is:000001ac3502000000070d52c80000002f01105c2a4b4d0000

整理一下如下:

  • 000001ac3502:rowid
  • 000000070d52:trx id
  • c80000002f0110:roll ptr
  • 5c2a4b4d:timestamp 類型的實際數據十進制為 1546275661

我們使用 Linux 命令如下:

[root@gp1 ~]# date -d @1546275661Tue Jan 1 01:01:01 CST 2019

因為我的 Linux 也是 CST +8 時區這裡數據也和 MySQL 中顯示一樣。下面我們調整一下時區再來看看取值如下:

mysql> set time_zone='+06:00';Query OK, 0 rows affected (0.00 sec)
mysql> select * from tmm;+---------------------+| dt |+---------------------+| 2018-12-31 23:01:01 |+---------------------+1 row in set (0.01 sec)

這裡可以看到減去了 2 個小時,因為我的時區從 +8 變為了 +6。

三、timestamp 轉換

在進行新紀元時間(1970-01-01 00:00:00)以來的秒到實際時間之間轉換的時候 MySQL 根據參數 time_zone 的設置有兩種選擇:

  • time_zone 設置為 SYSTEM 的話:使用 sys_time_zone 獲取的 OS 會話時區,同時使用 OS API 進行轉換。對應轉換函數 Time_zone_system::gmt_sec_to_TIME
  • time_zone 設置為實際的時區的話:比如 ‘+08:00’,那麼使用使用 MySQL 自己的方法進行轉換。對應轉換函數 Time_zone_offset::gmt_sec_to_TIME

實際上 Time_zone_system 和 Time_zone_offset 均繼承於 Time_zone 類,並且實現了 Time_zone 類的虛函數進行了重寫,因此上層調用都是 Time_zone::gmt_sec_to_TIME。

注意這種轉換操作是每行符合條件的數據都需要轉換的。

四、問題修復方案

我們從問題棧幀來看這個故障使用的是 Time_zone_system::gmt_sec_to_TIME 函數進行轉換的,因此可以考慮如下:

  • time_zone:設置為指定的時區,比如 ‘+08:00’。這樣就不會使用 OS API 進行轉換了,而轉為 MySQL 自己的內部實現 調用 Time_zone_offset::gmt_sec_to_TIME 函數。但是需要注意的是,如果使用 MySQL 自己的實現那麼 us% 會加劇。
  • 使用 datetime 代替 timestamp,新版本 datetime 為 5 個字節,只比 timestamp 多一個字節。

五、修復前後

sy% 使用量對比 據朋友說他大概在上午 11 點多完成了修改,做的方式是將 time_zone 修改為 ‘+08:00’,下面展示修改前後 CPU 使用率的對比:

修復前:

技術分享 | MySQL:timestamp 時區轉換導致 CPU %sys 高的問題

修復後:

技術分享 | MySQL:timestamp 時區轉換導致 CPU %sys 高的問題

六、備用棧幀

  • time_zone=‘SYSTEM’轉換棧幀
#0 Time_zone_system::gmt_sec_to_TIME (this=0x2e76948, tmp=0x7fffec0f3ff0, t=1546275661) at /root/mysqlall/percona-server-locks-detail-5.7.22/sql/tztime.cc:1092#1 0x0000000000f6b65c in Time_zone::gmt_sec_to_TIME (this=0x2e76948, tmp=0x7fffec0f3ff0, tv=...) at /root/mysqlall/percona-server-locks-detail-5.7.22/sql/tztime.h:60#2 0x0000000000f51643 in Field_timestampf::get_date_internal (this=0x7ffe7ca66540, ltime=0x7fffec0f3ff0) at /root/mysqlall/percona-server-locks-detail-5.7.22/sql/field.cc:6014#3 0x0000000000f4ff49 in Field_temporal_with_date::val_str (this=0x7ffe7ca66540, val_buffer=0x7fffec0f4370, val_ptr=0x7fffec0f4370) at /root/mysqlall/percona-server-locks-detail-5.7.22/sql/field.cc:5429#4 0x0000000000f11d7b in Field::val_str (this=0x7ffe7ca66540, str=0x7fffec0f4370) at /root/mysqlall/percona-server-locks-detail-5.7.22/sql/field.h:866#5 0x0000000000f4549d in Field::send_text (this=0x7ffe7ca66540, protocol=0x7ffe7c001e88) at /root/mysqlall/percona-server-locks-detail-5.7.22/sql/field.cc:1725#6 0x00000000014dfb82 in Protocol_text::store (this=0x7ffe7c001e88, field=0x7ffe7ca66540) at /root/mysqlall/percona-server-locks-detail-5.7.22/sql/protocol_classic.cc:1415#7 0x0000000000fb06c0 in Item_field::send (this=0x7ffe7c006ec0, protocol=0x7ffe7c001e88, buffer=0x7fffec0f4760) at /root/mysqlall/percona-server-locks-detail-5.7.22/sql/item.cc:7801#8 0x000000000156b15c in THD::send_result_set_row (this=0x7ffe7c000b70, row_items=0x7ffe7c005d58) at /root/mysqlall/percona-server-locks-detail-5.7.22/sql/sql_class.cc:5026#9 0x0000000001565758 in Query_result_send::send_data (this=0x7ffe7c006e98, items=...) at /root/mysqlall/percona-server-locks-detail-5.7.22/sql/sql_class.cc:2932#10 0x0000000001585490 in end_send (join=0x7ffe7c007078, qep_tab=0x7ffe7c0078d0, end_of_records=false) at /root/mysqlall/percona-server-locks-detail-5.7.22/sql/sql_executor.cc:2925#11 0x0000000001582059 in evaluate_join_record (join=0x7ffe7c007078, qep_tab=0x7ffe7c007758)
  • time_zone=‘+08:00’轉換棧幀
#0 Time_zone_offset::gmt_sec_to_TIME (this=0x6723d90, tmp=0x7fffec0f3ff0, t=1546275661) at /root/mysqlall/percona-server-locks-detail-5.7.22/sql/tztime.cc:1418#1 0x0000000000f6b65c in Time_zone::gmt_sec_to_TIME (this=0x6723d90, tmp=0x7fffec0f3ff0, tv=...) at /root/mysqlall/percona-server-locks-detail-5.7.22/sql/tztime.h:60#2 0x0000000000f51643 in Field_timestampf::get_date_internal (this=0x7ffe7ca66540, ltime=0x7fffec0f3ff0) at /root/mysqlall/percona-server-locks-detail-5.7.22/sql/field.cc:6014#3 0x0000000000f4ff49 in Field_temporal_with_date::val_str (this=0x7ffe7ca66540, val_buffer=0x7fffec0f4370, val_ptr=0x7fffec0f4370) at /root/mysqlall/percona-server-locks-detail-5.7.22/sql/field.cc:5429#4 0x0000000000f11d7b in Field::val_str (this=0x7ffe7ca66540, str=0x7fffec0f4370) at /root/mysqlall/percona-server-locks-detail-5.7.22/sql/field.h:866#5 0x0000000000f4549d in Field::send_text (this=0x7ffe7ca66540, protocol=0x7ffe7c001e88) at /root/mysqlall/percona-server-locks-detail-5.7.22/sql/field.cc:1725#6 0x00000000014dfb82 in Protocol_text::store (this=0x7ffe7c001e88, field=0x7ffe7ca66540) at /root/mysqlall/percona-server-locks-detail-5.7.22/sql/protocol_classic.cc:1415#7 0x0000000000fb06c0 in Item_field::send (this=0x7ffe7c006ec0, protocol=0x7ffe7c001e88, buffer=0x7fffec0f4760) at /root/mysqlall/percona-server-locks-detail-5.7.22/sql/item.cc:7801#8 0x000000000156b15c in THD::send_result_set_row (this=0x7ffe7c000b70, row_items=0x7ffe7c005d58) at /root/mysqlall/percona-server-locks-detail-5.7.22/sql/sql_class.cc:5026#9 0x0000000001565758 in Query_result_send::send_data (this=0x7ffe7c006e98, items=...) at /root/mysqlall/percona-server-locks-detail-5.7.22/sql/sql_class.cc:2932#10 0x0000000001585490 in end_send (join=0x7ffe7c007078, qep_tab=0x7ffe7c0078d0, end_of_records=false) at /root/mysqlall/percona-server-locks-detail-5.7.22/sql/sql_executor.cc:2925#11 0x0000000001582059 in evaluate_join_record (join=0x7ffe7c007078, qep_tab=0x7ffe7c007758)


分享到:


相關文章: