2015年3月9日月曜日

MySQL 5.7で絶対に必要になると思うlog_timestampsの設定

気づかなかったけど、これ5.7.2から入ってたのか。

フツーに扱うDATETIME型(やその親戚)は time_zone 変数に支配されるけど、ログに出力される時刻は log_timestamps 変数に支配される。

この変数の取りうる値は UTC または SYSTEM で、暗黙のデフォルトはUTC 。。


mysql57> SELECT @@version;
+---------------+
| @@version     |
+---------------+
| 5.7.5-m15-log |
+---------------+
1 row in set (0.00 sec)

mysql57> SHOW GLOBAL VARIABLES LIKE '%time_zone'; -- タイムゾーンはフツーにJST
+------------------+--------+
| Variable_name    | Value  |
+------------------+--------+
| system_time_zone | JST    |
| time_zone        | SYSTEM |
+------------------+--------+
2 rows in set (0.00 sec)

mysql57> SELECT @@log_timestamps; -- これが5.7.2で導入されたやつ。暗黙のデフォルトUTC(!)
+------------------+
| @@log_timestamps |
+------------------+
| UTC              |
+------------------+
1 row in set (0.00 sec)

mysql57> SELECT NOW();
+---------------------+
| NOW()               |
+---------------------+
| 2015-03-09 13:55:15 |
+---------------------+
1 row in set (0.01 sec)

### ↓なんでもいいからエラーログに何か吐くようなステートメントを叩いてるだけ ###

mysql57> SET SESSION binlog_format= STATEMENT;
Query OK, 0 rows affected (0.00 sec)

mysql57> SELECT NOW(); INSERT INTO t1 SELECT * FROM t1 ORDER BY RAND() LIMIT 1;
+---------------------+
| NOW()               |
+---------------------+
| 2015-03-09 14:01:02 |
+---------------------+
1 row in set (0.00 sec)

Query OK, 0 rows affected, 3 warnings (0.00 sec)
Records: 0  Duplicates: 0  Warnings: 3

mysql57> SHOW WARNINGS;
+-------+------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| Level | Code | Message                                                                                                                                                                                                                                                                                                                                                                          |
+-------+------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| Note  | 1592 | Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. The statement is unsafe because it uses a LIMIT clause. This is unsafe because the set of rows included cannot be predicted.                                                                                                                                                  |
| Note  | 1592 | Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. Statement is unsafe because it uses a system function that may return a different value on the slave.                                                                                                                                                                         |
| Note  | 1592 | Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. Statements writing to a table with an auto-increment column after selecting from another table are unsafe because the order in which rows are retrieved determines what (if any) rows will be written. This order cannot be predicted and may differ on master and the slave. |
+-------+------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
3 rows in set (0.00 sec)


$ tail data/error.log
..2015-03-09T05:01:02.713955Z 14 [Warning] Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. The statement is unsafe because it uses a LIMIT clause. This is unsafe because the set of rows included cannot be predicted. Statement: INSERT INTO t1 SELECT * FROM t1 ORDER BY RAND() LIMIT 1
2015-03-09T05:01:02.713987Z 14 [Warning] Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. Statement is unsafe because it uses a system function that may return a different value on the slave. Statement: INSERT INTO t1 SELECT * FROM t1 ORDER BY RAND() LIMIT 1
2015-03-09T05:01:02.714000Z 14 [Warning] Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. Statements writing to a table with an auto-increment column after selecting from another table are unsafe because the order in which rows are retrieved determines what (if any) rows will be written. This order cannot be predicted and may differ on master and the slave. Statement: INSERT INTO t1 SELECT * FROM t1 ORDER BY RAND() LIMIT 1

$ tail data/slow.log
..
# Time: 2015-03-09T05:01:02.714121Z
# User@Host: root[root] @ localhost []  Id:    14
# Query_time: 0.000633  Lock_time: 0.000215 Rows_sent: 0  Rows_examined: 0
SET timestamp=1425877262;
INSERT INTO t1 SELECT * FROM t1 ORDER BY RAND() LIMIT 1;
# Time: 2015-03-09T05:01:06.197098Z
# User@Host: root[root] @ localhost []  Id:    14
# Query_time: 0.000168  Lock_time: 0.000000 Rows_sent: 0  Rows_examined: 0
SET timestamp=1425877266;
SHOW WARNINGS;

$ tail data/general.log
..
2015-03-09T05:01:02.713098Z   14 Query  SELECT NOW()
2015-03-09T05:01:02.713567Z   14 Query  INSERT INTO t1 SELECT * FROM t1 ORDER BY RAND() LIMIT 1
2015-03-09T05:01:06.196974Z   14 Query  SHOW WARNINGS

:(;゙゚'ω゚'): おいエラーログもスローログもジェネラルログもホントにUTCだぞ。
オンラインで変更も効くので


mysql57> SET GLOBAL log_timestamps= SYSTEM;
Query OK, 0 rows affected (0.00 sec)

mysql57> SELECT NOW(); INSERT INTO t1 SELECT * FROM t1 ORDER BY RAND() LIMIT 1;
+---------------------+
| NOW()               |
+---------------------+
| 2015-03-09 14:03:16 |
+---------------------+
1 row in set (0.00 sec)

Query OK, 0 rows affected, 3 warnings (0.00 sec)
Records: 0  Duplicates: 0  Warnings: 3


$ tail data/error.log
..
2015-03-09T14:03:16.606892+09:00 14 [Warning] Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. The statement is unsafe because it uses a LIMIT clause. This is unsafe because the set of rows included cannot be predicted. Statement: INSERT INTO t1 SELECT * FROM t1 ORDER BY RAND() LIMIT 1
2015-03-09T14:03:16.606932+09:00 14 [Warning] Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. Statement is unsafe because it uses a system function that may return a different value on the slave. Statement: INSERT INTO t1 SELECT * FROM t1 ORDER BY RAND() LIMIT 1
2015-03-09T14:03:16.606948+09:00 14 [Warning] Unsafe statement written to the binary log using statement format since BINLOG_FORMAT = STATEMENT. Statements writing to a table with an auto-increment column after selecting from another table are unsafe because the order in which rows are retrieved determines what (if any) rows will be written. This order cannot be predicted and may differ on master and the slave. Statement: INSERT INTO t1 SELECT * FROM t1 ORDER BY RAND() LIMIT 1

$ tail data/slow.log
..
# Time: 2015-03-09T14:03:16.607072+09:00
# User@Host: root[root] @ localhost []  Id:    14
# Query_time: 0.000671  Lock_time: 0.000226 Rows_sent: 0  Rows_examined: 0
SET timestamp=1425877396;
INSERT INTO t1 SELECT * FROM t1 ORDER BY RAND() LIMIT 1;


$ tail data/general.log
..
2015-03-09T14:03:16.606054+09:00   14 Query     SELECT NOW()
2015-03-09T14:03:16.606477+09:00   14 Query     INSERT INTO t1 SELECT * FROM t1 ORDER BY RAND() LIMIT 1

JSTを示す "+09:00" が付いて、日本時間で表示されるようになった。
これ罠いよー。。


my.cnfに書くなら[mysqld]セクションにlog-timestamps= systemと足しておくと、

$ tail data/error.log
..
2015-03-09T14:07:54.453823+09:00 0 [Note] /usr/mysql/5.7.5/bin/mysqld: ready for connections.

起動時のログもこうなる。

罠い。

0 件のコメント :

コメントを投稿