mita2 database life

主にMySQLに関するメモです

MySQLのスロークエリログにはエラーになったクエリが含まれる? (ver 8.0.29, ver 5.7.38 以前)

お題

  • エラーになったクエリはスロークエリログに記録されるのか?
  • されるとしたら、エラーになったクエリであることは判別可能なのか?

試してみます

1. 文法エラー

まずは、文法エラー。

mysql> UPDATE t.tx1 SET c1  100;
ERROR 1064 (42000): You have an error in your SQL syntax; check the manual that corresponds 
to your MySQL server version for the right syntax to use near '100' at line 1

文法エラーでも、ログに落ちました。文法エラーでログが落ちるということは、どんなエラーでも、スロークエリログにクエリが書かれる予感がします(早速、答えが出てしまった)。

# Time: 2020-02-25T21:13:22.700729+09:00
# User@Host: root[root] @ localhost []  Id:    15
# Query_time: 0.000100  Lock_time: 0.000000 Rows_sent: 0  Rows_examined: 0 Thread_id: 15 Errno: 0 Killed: 0 Bytes_received: 0 Bytes_sent: 162 Read_first: 0 Read_last: 0 Read_key: 0 Read_next: 0 Read_prev: 0 Read_rnd: 0 Read_rnd_next: 0 Sort_merge_passes: 0 Sort_range_count: 0 Sort_rows: 0 Sort_scan_count: 0 Created_tmp_disk_tables: 0 Created_tmp_tables: 0 Start: 2020-02-25T21:13:22.700629+09:00 End: 2020-02-25T21:13:22.700729+09:00
SET timestamp=1582632802;
UPDATE t.tx1 SET c1  100;

2. 制約違反

Duplicate Entry の場合。

mysql> INSERT INTO t.tx1 VALUES(1, 100);
ERROR 1062 (23000): Duplicate entry '1' for key 'tx1.PRIMARY'

制約違反でもログに落ちました。MySQL 8.0 で登場した log_slow_extra を 有効にして、スロークエリログに記録される項目を増やしています。 Errno0(エラーなし扱い) のままみたいです。

# Time: 2020-02-25T22:05:24.647928+09:00
# User@Host: root[root] @ localhost []  Id:    84
# Query_time: 0.000537  Lock_time: 0.000235 Rows_sent: 0  Rows_examined: 0 Thread_id: 84 Errno: 0 Killed: 0 Bytes_received: 0 Bytes_sent: 54 Read_first: 0 Read_last: 0 Read_key: 0 Read_next: 0 Read_prev: 0 Read_rnd: 0 Read_rnd_next: 0 Sort_merge_passes: 0 Sort_range_count: 0 Sort_rows: 0 Sort_scan_count: 0 Created_tmp_disk_tables: 0 Created_tmp_tables: 0 Start: 2020-02-25T22:05:24.647391+09:00 End: 2020-02-25T22:05:24.647928+09:00
SET timestamp=1582635924;
INSERT INTO t.tx1 VALUES(1, 100);

3. ロックタイムアウト

mysql> UPDATE t.tx1 SET c1 = 100;
ERROR 1205 (HY000): Lock wait timeout exceeded; try restarting transaction

ハイ、こちらもログに落ちます。しかし、相変わらず、Errno0 です。

# Time: 2020-02-25T21:11:55.309032+09:00
# User@Host: root[root] @ localhost []  Id:    14
# Query_time: 4.001521  Lock_time: 4.001169 Rows_sent: 0  Rows_examined: 1 Thread_id: 14 Errno: 0 Killed: 0 Bytes_received: 0 Bytes_sent: 67 Read_first: 1 Read_last: 0 Read_key: 1 Read_next: 0 Read_prev: 0 Read_rnd: 0 Read_rnd_next: 2 Sort_merge_passes: 0 Sort_range_count: 0 Sort_rows: 0 Sort_scan_count: 0 Created_tmp_disk_tables: 0 Created_tmp_tables: 0 Start: 2020-02-25T21:11:51.307511+09:00 End: 2020-02-25T21:11:55.309032+09:00
SET timestamp=1582632711;
UPDATE t.tx1 SET c1 = 100;

4. 中断

エラーではありませんが、Ctrl-C で中断したパターンも試してみます。

mysql> SELECT SLEEP(10);
^C^C -- query aborted
+-----------+
| SLEEP(10) |
+-----------+
+-----------+
1 row in set (2.61 sec)

相変わらず、Errno0 です。 Errno はいつ 0 以外の値になるんですかねぇ・・・

# Time: 2020-02-25T21:02:38.084781+09:00
# User@Host: root[root] @ localhost []  Id:     9
# Query_time: 2.612076  Lock_time: 0.000000 Rows_sent: 1  Rows_examined: 1 Thread_id: 9 Errno: 0 Killed: 0 Bytes_received: 0 Bytes_sent: 57 Read_first: 0 Read_last: 0 Read_key: 0 Read_next: 0 Read_prev: 0 Read_rnd: 0 Read_rnd_next: 0 Sort_merge_passes: 0 Sort_range_count: 0 Sort_rows: 0 Sort_scan_count: 0 Created_tmp_disk_tables: 0 Created_tmp_tables: 0 Start: 2020-02-25T21:02:35.472705+09:00 End: 2020-02-25T21:02:38.084781+09:00
SET timestamp=1582632155;
SELECT SLEEP(10);

まとめ

  • エラーになったクエリはスロークエリログに記録されるのか?→YES
  • されるとしたら、エラーになったクエリであることは判別可能なのか?→NO
    • Errno にエラー番号が書かれないケースがありそう(というか、Errno書かれるケースが不明)

参考

tom__bo さんが、先日、スロークエリログに関するエントリーを書いてました。 こちらもあわせてどうぞ。

tombo2.hatenablog.com