MySQL：timestamp时区转换导致CPU %sy高的问题
2019-11-04 本文已影响0人
重庆八怪
水平有限，如果有误请谅解。
这个问题是一个朋友遇到的@风云，并且这位朋友已经得出了近乎正确的判断，这位下面进行一些描述。
一、问题展示
下面是问题当时的系统负载如下：
image.png
我们可以看到40.4%sy 正是系统调用负载较高的表现，随即朋友采集了perf如下：
image.png
接下来朋友采集了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 00000003
current 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 @1546275661
Tue 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。
三、timestap转换
在进行新纪元时间（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使用率的对比：
修复前：
image.png
修复后：
image.png
六、备用栈帧
- 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)
