MySQL 8.0.12 参数log_timestamps 导致日志信息时间错差8小时
发表于:2022-09-16 |
运行环境:MySQL 8.0.12 + CentOS 7.5
背景:
错误日志和慢查询日志中的时间戳信息比正常的时间少了8个小时。
 
知识点:
log_timestamps 自5.7.2版本被引入,此参数控制了general log、error log、slow query log日志中
时间戳的显示,默认使用的UTC。但是此参数不影响mysql.general_log, mysql.slow_log中写入信息的
时间戳。
 
此参数有UTC(默认值)和system的2个可选项,此参数是可以动态修改的。
 
试验验证:
1.创建测试数据:
mysql> select version();
+-----------+
| version() |
+-----------+
| 8.0.12    |
+-----------+
1 row in set (0.00 sec)
 
mysql> select now();
+---------------------+
| now()               |
+---------------------+
| 2018-08-28 22:15:21 |
+---------------------+
1 row in set (0.00 sec)
 
mysql> create table wuhan.city(id int,cityname varchar(20));
Query OK, 0 rows affected (0.03 sec)
 
mysql> insert into wuhan.city(id,cityname)values(1,'wuhan');
Query OK, 1 row affected (0.07 sec)
 
mysql> insert into wuhan.city(id,cityname)values(2,'shenzhen');
Query OK, 1 row affected (0.03 sec)
 
mysql> exit
Bye
 
2.重启mysql实例查看通用日志信息的时间戳:
# date +"%Y/%m/%d %H:%M:%S"
2018/08/28 22:26:28
# cat general.log 
 
2018-08-28T14:25:03.661193Z    9 Connectroot@localhost on  using Socket
2018-08-28T14:25:03.661385Z    9 Queryselect @@version_comment limit 1
2018-08-28T14:25:09.463432Z    9 Queryshutdown
2018-08-28T14:25:09.463500Z    9 Query
/usr/local/mysql80/bin/mysqld, Version: 8.0.12 (MySQL Community Server - GPL). started with:
Tcp port: 3306  Unix socket: /tmp/mysql80.sock
Time                 Id Command    Argument
2018-08-28T14:25:20.249010Z    7 Connect
2018-08-28T14:25:20.249131Z    7 QuerySELECT @@skip_networking, @@skip_name_resolve, @@have_ssl='YES', @@ssl_key, @@ssl_ca, @@ssl_capath, @@ssl_cert, @@ssl_cipher, @@ssl_crl, @@ssl_crlpath, @@tls_version
2018-08-28T14:25:20.250081Z    7 Quit
 
3.查看错误日志信息的时间戳:
# cat error.log 
 
2018-08-28T14:25:09.463480Z 9 [System] [MY-013172] [Server] Received SHUTDOWN from user root. Shutting down mysqld (Version: 8.0.12).
2018-08-28T14:25:11.776175Z 0 [System] [MY-010910] [Server] /usr/local/mysql80/bin/mysqld: Shutdown complete (mysqld 8.0.12)  MySQL Community Server - GPL.
2018-08-28T14:25:19.110965Z 0 [System] [MY-010116] [Server] /usr/local/mysql80/bin/mysqld (mysqld 8.0.12) starting as process 340303
2018-08-28T14:25:20.068100Z 0 [Warning] [MY-010068] [Server] CA certificate ca.pem is self signed.
2018-08-28T14:25:20.068912Z 0 [Warning] [MY-011810] [Server] Insecure configuration for --pid-file: Location '/tmp' in the path is accessible to all OS users. Consider choosing a different directory.
2018-08-28T14:25:20.077651Z 0 [Warning] [MY-010315] [Server] 'user' entry 'mysql.infoschema@localhost' ignored in --skip-name-resolve mode.
2018-08-28T14:25:20.077701Z 0 [Warning] [MY-010315] [Server] 'user' entry 'mysql.session@localhost' ignored in --skip-name-resolve mode.
2018-08-28T14:25:20.077720Z 0 [Warning] [MY-010315] [Server] 'user' entry 'mysql.sys@localhost' ignored in --skip-name-resolve mode.
2018-08-28T14:25:20.077734Z 0 [Warning] [MY-010315] [Server] 'user' entry 'root@localhost' ignored in --skip-name-resolve mode.
2018-08-28T14:25:20.077760Z 0 [Warning] [MY-010323] [Server] 'db' entry 'performance_schema mysql.session@localhost' ignored in --skip-name-resolve mode.
2018-08-28T14:25:20.077771Z 0 [Warning] [MY-010323] [Server] 'db' entry 'sys mysql.sys@localhost' ignored in --skip-name-resolve mode.
2018-08-28T14:25:20.077786Z 0 [Warning] [MY-010311] [Server] 'proxies_priv' entry '@ root@localhost' ignored in --skip-name-resolve mode.
2018-08-28T14:25:20.080054Z 0 [Warning] [MY-010330] [Server] 'tables_priv' entry 'user mysql.session@localhost' ignored in --skip-name-resolve mode.
2018-08-28T14:25:20.080076Z 0 [Warning] [MY-010330] [Server] 'tables_priv' entry 'sys_config mysql.sys@localhost' ignored in --skip-name-resolve mode.
2018-08-28T14:25:20.085037Z 0 [System] [MY-010931] [Server] /usr/local/mysql80/bin/mysqld: ready for connections. Version: '8.0.12'  socket: '/tmp/mysql80.sock'  port: 3306  MySQL Community Server - GPL.
 
4. 查看慢查询的日志信息:为了演示我所有的查询语句都记录了下来.
mysql> show variables like 'long%';
+-----------------+----------+
| Variable_name   | Value    |
+-----------------+----------+
| long_query_time | 0.000000 |
+-----------------+----------+
1 row in set (0.00 sec)
 
mysql> select now();
+---------------------+
| now()               |
+---------------------+
| 2018-08-28 22:30:31 |
+---------------------+
1 row in set (0.00 sec)
 
mysql> select * from wuhan.city;
+------+----------+
| id   | cityname |
+------+----------+
|    1 | wuhan    |
|    2 | shenzhen |
+------+----------+
2 rows in set (0.00 sec)
 
mysql> system cat slow_query.log
# Time: 2018-08-28T14:30:31.270846Z
# User@Host: root[root] @ localhost []  Id:     8
# Query_time: 0.000205  Lock_time: 0.000000 Rows_sent: 1  Rows_examined: 0
SET timestamp=1535466631;
select now();
# Time: 2018-08-28T14:30:40.409775Z
# User@Host: root[root] @ localhost []  Id:     8
# Query_time: 0.000367  Lock_time: 0.000196 Rows_sent: 2  Rows_examined: 2
SET timestamp=1535466640;
select * from wuhan.city;
可以看到上述的三种日志的时间戳都是和北京时间相差8个小时,这对于日常的日志分析很是不方便。
--查询日志时间戳:
mysql> show variables like 'log_timestamps';
+----------------+-------+
| Variable_name  | Value |
+----------------+-------+
| log_timestamps | UTC   |
+----------------+-------+
1 row in set (0.01 sec)
 
 
5.动态修改参数log_timestamps:
mysql> set global log_timestamps=system;
Query OK, 0 rows affected (0.00 sec)
 
mysql> show variables like 'log_timestamps';
+----------------+--------+
| Variable_name  | Value  |
+----------------+--------+
| log_timestamps | SYSTEM |
+----------------+--------+
1 row in set (0.00 sec)
 
6.验证时间戳在日志中是否立即生效:
mysql> select now();
+---------------------+
| now()               |
+---------------------+
| 2018-08-28 22:34:26 |
+---------------------+
1 row in set (0.00 sec)
 
mysql> system cat slow_query.log
select now();
# Time: 2018-08-28T14:30:40.409775Z
# User@Host: root[root] @ localhost []  Id:     8
# Query_time: 0.000367  Lock_time: 0.000196 Rows_sent: 2  Rows_examined: 2
SET timestamp=1535466640;
select * from wuhan.city;
# Time: 2018-08-28T14:32:34.568500Z
# User@Host: root[root] @ localhost []  Id:     8
# Query_time: 0.004469  Lock_time: 0.001271 Rows_sent: 1  Rows_examined: 1096
SET timestamp=1535466754;
show variables like 'long%';
# Time: 2018-08-28T14:33:23.980805Z
# User@Host: root[root] @ localhost []  Id:     8
# Query_time: 0.002995  Lock_time: 0.000208 Rows_sent: 1  Rows_examined: 1096
SET timestamp=1535466803;
show variables like 'log_timestamps';
# Time: 2018-08-28T22:33:37.351567+08:00
# User@Host: root[root] @ localhost []  Id:     8
# Query_time: 0.000122  Lock_time: 0.000000 Rows_sent: 0  Rows_examined: 0
SET timestamp=1535466817;
set global log_timestamps=system;
# Time: 2018-08-28T22:33:40.647725+08:00
# User@Host: root[root] @ localhost []  Id:     8
# Query_time: 0.003182  Lock_time: 0.000319 Rows_sent: 1  Rows_examined: 1096
SET timestamp=1535466820;
show variables like 'log_timestamps';
# Time: 2018-08-28T22:34:26.605718+08:00
# User@Host: root[root] @ localhost []  Id:     8
# Query_time: 0.000189  Lock_time: 0.000000 Rows_sent: 1  Rows_examined: 0
SET timestamp=1535466866;
select now();
 
可以看到最后执行的 select now() 的时间戳已经显示为正常的时间戳了。时间戳和之前比对如下:
 
# Time: 2018-08-28T14:33:23.980805Z
# Time: 2018-08-28T22:34:26.605718+08:00
之前是UTC时间后加字母Z,修改system后当地时间错+时区。
 
7.设置为持久化参数:
mysql> set persist log_timestamps=system;
Query OK, 0 rows affected (0.00 sec)
或者需要将此参数写入到配置文件中:
[mysqld]
log_timestamps=system
 
结论:
1.为了国内用户便于读取日志信息,建议将参数写入到配置文件my.cnf
2.MySQL 8.0支持参数log_timestamps持久化设置。
上一篇:
Docker Nginx Log 三者的处理详解
下一篇:
UBUNTU 关闭iptables的方法