非同期レプリケーション接続フェイルオーバについて に続いて、先月リリースされた MySQL 8.0.22 のリリース情報から執筆しようと思います。
MySQL8.0.22 からエラーログの内容を従来のログファイルだけでなく performance_schema.error_log テーブルで確認できるようになりました。
また、当ブログでもご紹介しました Oracle Cloud の MySQL Database Service では、リリース当初はログ内容を確認する事ができなかったのが、このリリースにより、ログの内容を確認できるようになっています。
(現在の MySQL Database Service では、MySQL8.0.22 が稼働できるようになっています。)
今回は performance_schema.error_log テーブルについて、確認したいと思います。
詳細は、以下のリファレンスに記載されていますので、一読される事をお勧めします。
テーブルの構成・出力内容
テーブルの構成は以下のようになっています。
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 |
mysql> SHOW CREATE TABLE performance_schema.error_log\G *************************** 1. row *************************** Table: error_log Create Table: CREATE TABLE `error_log` ( `LOGGED` timestamp(6) NOT NULL, `THREAD_ID` bigint unsigned DEFAULT NULL, `PRIO` enum('System','Error','Warning','Note') NOT NULL, `ERROR_CODE` varchar(10) DEFAULT NULL, `SUBSYSTEM` varchar(7) DEFAULT NULL, `DATA` text NOT NULL, PRIMARY KEY (`LOGGED`), KEY `THREAD_ID` (`THREAD_ID`), KEY `PRIO` (`PRIO`), KEY `ERROR_CODE` (`ERROR_CODE`), KEY `SUBSYSTEM` (`SUBSYSTEM`) ) ENGINE=PERFORMANCE_SCHEMA DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_0900_ai_ci 1 row in set (0.00 sec) |
各カラムに格納する値は以下のようになります。
“DATA” カラムには、インデックスが存在しないので、イベントメッセージで検索する際は(そのようなケースはないかと思いますが)、注意が必要です。
| カラム | 説明 |
|---|---|
| LOGGED | イベント出力日時。 |
| THREAD_ID | イベント対象のスレッドID。バックグラウンドスレッドの場合は 0 が表示される。 |
| PRIO | イベントの優先度。System Error Warning Noteのいずれかが出力される。 |
| ERROR_CODE | イベントのエラーコード。 |
| SUBSYSTEM | イベントが発生したサブシステム。 |
| DATA | イベントメッセージ。 |
格納されているデータを参照すると、以下のようになっています。
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 |
*************************** 1. row *************************** LOGGED: 2020-11-10 15:24:06.495869 THREAD_ID: 0 PRIO: System ERROR_CODE: MY-013169 SUBSYSTEM: Server DATA: /usr/sbin/mysqld (mysqld 8.0.22) initializing of server in progress as process 26098 *************************** 2. row *************************** LOGGED: 2020-11-10 15:24:06.508323 THREAD_ID: 1 PRIO: System ERROR_CODE: MY-013576 SUBSYSTEM: InnoDB DATA: InnoDB initialization has started. *************************** 3. row *************************** LOGGED: 2020-11-10 15:24:07.534942 THREAD_ID: 1 PRIO: System ERROR_CODE: MY-013577 SUBSYSTEM: InnoDB DATA: InnoDB initialization has ended. 3 rows in set (0.00 sec) |
実際のログファイルを見てみると、ログファイルと同じ情報が出力されている事が分かります。
|
1 2 3 4 |
# head -n 3 /var/log/mysqld.log 2020-11-10T06:24:06.495869Z 0 [System] [MY-013169] [Server] /usr/sbin/mysqld (mysqld 8.0.22) initializing of server in progress as process 26098 2020-11-10T06:24:06.508323Z 1 [System] [MY-013576] [InnoDB] InnoDB initialization has started. 2020-11-10T06:24:07.534942Z 1 [System] [MY-013577] [InnoDB] InnoDB initialization has ended. |
performance_schema.error_log と ログファイルで、イベント出力日時が異なっていますが、これは検証した環境の以下のパラメータの違いによるものです。
- performance_schema.error_log
以下の設定に従いJSTの日時で出力。
|
1 2 3 4 5 6 7 |
mysql> SHOW GLOBAL VARIABLES LIKE '%zone%'; +------------------+--------+ | Variable_name | Value | +------------------+--------+ | system_time_zone | JST | | time_zone | SYSTEM | +------------------+--------+ |
- ログファイル
以下の設定に従いUTCの日時で出力。
|
1 2 3 4 5 6 |
mysql> SHOW GLOBAL VARIABLES LIKE 'log_timestamps'; +----------------+-------+ | Variable_name | Value | +----------------+-------+ | log_timestamps | UTC | +----------------+-------+ |
performance_schema.error_log を参照する際は、time_zone の設定を変更する事で、イベント出力日時を任意のタイムゾーンに変更して出力する事が可能です。
例えば、現状の設定から、UTCの日時で出力したい場合には、以下のように実行します。
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 |
mysql> SET SESSION time_zone = '+00:00'; Query OK, 0 rows affected (0.00 sec) mysql> SELECT * FROM performance_schema.error_log ORDER BY LOGGED LIMIT 3\G *************************** 1. row *************************** LOGGED: 2020-11-10 06:24:06.495869 THREAD_ID: 0 PRIO: System ERROR_CODE: MY-013169 SUBSYSTEM: Server DATA: /usr/sbin/mysqld (mysqld 8.0.22) initializing of server in progress as process 26098 *************************** 2. row *************************** LOGGED: 2020-11-10 06:24:06.508323 THREAD_ID: 1 PRIO: System ERROR_CODE: MY-013576 SUBSYSTEM: InnoDB DATA: InnoDB initialization has started. *************************** 3. row *************************** LOGGED: 2020-11-10 06:24:07.534942 THREAD_ID: 1 PRIO: System ERROR_CODE: MY-013577 SUBSYSTEM: InnoDB DATA: InnoDB initialization has ended. 3 rows in set (0.00 sec) |
※Oracle Cloud の MySQL Database Service では、デフォルトで system_time_zone=UTC に設定されている為、time_zone を以下のように設定してから抽出することで、イベント出力日時を日本時間で表示できます。
|
1 |
mysql> SET SESSION time_zone = '+09:00'; |
また、このエラーログテーブルのみを参照するユーザを作成したい場合には、以下のようにユーザに権限を割り当てます。
|
1 |
GRANT SELECT ON performance_schema.error_log to '<ユーザ名>'@'<接続元ホスト>'; |
テーブルに関するステータス変数
リファレンスに記載がありますが、performance_schema.error_log のデータは、新しいイベントを格納する為に、必要に応じて古いイベントが自動的に削除されるようです。
そういった情報に関するステータス変数も追加されています。
|
1 2 3 4 5 6 7 8 9 10 |
mysql> SHOW GLOBAL STATUS LIKE 'Error_log%'; +---------------------------+------------------+ | Variable_name | Value | +---------------------------+------------------+ | Error_log_buffered_bytes | 1392 | | Error_log_buffered_events | 11 | | Error_log_expired_events | 0 | | Error_log_latest_write | 1604989454195492 | +---------------------------+------------------+ 4 rows in set (0.00 sec) |
| 変数名 | 説明 |
|---|---|
| Error_log_buffered_bytes | テーブルで使用される容量。（バイト数） |
| Error_log_buffered_events | テーブルに存在するイベント数。 |
| Error_log_expired_events | テーブルから破棄されたイベント数。 |
| Error_log_latest_write | テーブルへの最後の書き込み日時。 |
古いイベントの自動削除検証
前述しましたが、performance_schema.error_log のデータは必要に応じて古いイベントが削除されるという事なので、どの位のデータが格納されれば削除されるのか、簡単に検証しました。
検証方法は、log_error_verbosity=3 を設定して、ログイン認証エラーをエラーログに出力するようにし、以下のように、認証エラーを繰り返します。
|
1 2 3 4 5 6 |
# while :; do mysql -u root -pxxxxx ; done mysql: [Warning] Using a password on the command line interface can be insecure. ERROR 1045 (28000): Access denied for user 'root'@'localhost' (using password: YES) mysql: [Warning] Using a password on the command line interface can be insecure. ERROR 1045 (28000): Access denied for user 'root'@'localhost' (using password: YES) ・・・ |
また、上記の実行中に、エラーログに関するステータス変数を1秒ごとに取得しておきます。
|
1 |
# while :; do mysql --login-path=local -e "SHOW GLOBAL STATUS LIKE 'Error_log%';" >> /tmp/error_status.log; sleep 1; done |
実行結果は以下のようになりました。
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 |
# tail -f /tmp/error_status.log ・・・ Variable_name Value Error_log_buffered_bytes 5230040 Error_log_buffered_events 43586 Error_log_expired_events 0 Error_log_latest_write 1604992379035956 Variable_name Value Error_log_buffered_bytes 5235200 Error_log_buffered_events 43629 Error_log_expired_events 0 Error_log_latest_write 1604992380083151 Variable_name Value Error_log_buffered_bytes 5241560 Error_log_buffered_events 43682 Error_log_expired_events 0 Error_log_latest_write 1604992381129506 Variable_name Value Error_log_buffered_bytes 5242824 Error_log_buffered_events 43688 Error_log_expired_events 52 ★イベント削除が発生しだす Error_log_latest_write 1604992382176299 Variable_name Value Error_log_buffered_bytes 5242800 Error_log_buffered_events 43690 Error_log_expired_events 106 Error_log_latest_write 1604992383219076 Variable_name Value Error_log_buffered_bytes 5242800 Error_log_buffered_events 43690 Error_log_expired_events 163 Error_log_latest_write 1604992384244379 Variable_name Value Error_log_buffered_bytes 5242800 Error_log_buffered_events 43690 Error_log_expired_events 220 Error_log_latest_write 1604992385311401 Variable_name Value Error_log_buffered_bytes 5242800 Error_log_buffered_events 43690 Error_log_expired_events 275 Error_log_latest_write 1604992386351178 ・・・ |
イベント数が、43,682 ～ 43,688 の間で、イベントの削除が発生しています。
その後は、イベント数が 43,690 となった以降は、イベント数の増加がありませんでした。
(出力されるイベントメッセージ等によって変動する事が考えられますので、参考程度の情報となります。)
また、Error_log_buffered_bytes についても 5MB 付近から上昇が見られなくなりました。
検証後の最も古いデータは認証エラーのデータになっており、古いデータが削除された事が分かります。
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 |
mysql> SELECT * FROM performance_schema.error_log ORDER BY LOGGED LIMIT 3\G *************************** 1. row *************************** LOGGED: 2020-11-10 15:57:05.123084 THREAD_ID: 473 PRIO: Note ERROR_CODE: MY-010926 SUBSYSTEM: Server DATA: Access denied for user 'root'@'localhost' (using password: YES) *************************** 2. row *************************** LOGGED: 2020-11-10 15:57:05.141731 THREAD_ID: 474 PRIO: Note ERROR_CODE: MY-010926 SUBSYSTEM: Server DATA: Access denied for user 'root'@'localhost' (using password: YES) *************************** 3. row *************************** LOGGED: 2020-11-10 15:57:05.163393 THREAD_ID: 475 PRIO: Note ERROR_CODE: MY-010926 SUBSYSTEM: Server DATA: Access denied for user 'root'@'localhost' (using password: YES) 3 rows in set (0.07 sec) |
イベントの削除について
テーブルに格納されているイベントの削除方法については、リファレンスに明記されておらず、削除できないようです。
rootユーザで試しに実行してみましたが、エラーとなり削除できませんでした。
|
1 2 3 4 |
mysql> DELETE FROM performance_schema.error_log; ERROR 1142 (42000): DELETE command denied to user 'root'@'localhost' for table 'error_log' mysql> TRUNCATE TABLE performance_schema.error_log; ERROR 1142 (42000): DROP command denied to user 'root'@'localhost' for table 'error_log' |
また、テーブルには PERFORMANCE_SCHEMA ストレージエンジンを使用しておりますが、MySQLインスタンスの再起動に伴ってデータがクリアされる事はありません。
まとめ
OSログインせずともエラー内容が確認できるようになった事で、恩恵をうける方も多いのではないでしょうか。
最初に記載した通り、この機能リリースに伴い、Oracle Cloud の MySQL Database Service でエラーログの内容が確認できるようになったのですが、個人的な所感となりますが、MySQL Database Service を意識した機能であるように思います。
（今回は検証を簡単に行う為に、ローカル環境での確認となりましたが、、）
今後も、MySQL Database Service に関連するような更新情報もあるかと思いますので、そういった観点からもリリース内容を確認していきたいと思います。
