Aurora でスロークエリログを出力して,Fluentd 経由で Amazon Elasticsearch Service に転送する構成を作った.MySQL on EC2 のときは,サーバ内で直接スロークエリログを確認していて非常に面倒だったので(単なる運用上の考慮不足),運用面で大きく改善できるし,アプリケーションエンジニアも自由に Kibana で確認できるため,パフォーマンス改善が捗ると思う.非常に良い.
アーキテクチャ図
Aurora インスタンスパラメータ
デフォルトのインスタンスパラメータではスロークエリログは有効になっていないため,パラメータを変更する必要がある.今回はスロークエリログを有効にするだけではなく,デフォルトで10秒になっている閾値を5秒に変更した.
パラメータ名 |
Before |
After |
slow_query_log |
<engine-default> |
1 |
long_query_time |
<engine-default> |
5 |
どちらも「適用タイプ」は「dynamic」なので,Aurora の再起動は必要なく,自動的に反映される.反映されたかどうかは,実際に SQL で確認することができる.
mysql> SHOW VARIABLES LIKE 'slow_query_log';
+
| Variable_name | Value |
+
| slow_query_log | ON |
+
1 row in set (0.00 sec)
mysql> SHOW VARIABLES LIKE 'long_query_time';
+
| Variable_name | Value |
+
| long_query_time | 5.000000 |
+
1 row in set (0.00 sec)
Aurora のスロークエリはデフォルトでテーブルに書き込まれる
MySQL on EC2 と違って,Aurora ではスロークエリログがデフォルトでテーブルに書き込まれる.もしファイルに書き込む場合は,log_output
パラメータを変更する必要がある.今回はテーブルのまま運用することにした.
mysql> SHOW VARIABLES LIKE 'log_output';
+
| Variable_name | Value |
+
| log_output | TABLE |
+
1 row in set (0.00 sec)
スロークエリログは mysql.slow_log
というテーブルに書き込まれるが,Aurora 側で用意されているストアドプロシージャ mysql.rds_rotate_slow_log
を実行すると mysql.slow_log_backup
にローテートされる.よって,例えば mysql.slow_log_backup
を2回連続で実行すると,スロークエリログは完全に消すことができる.後述する Fluentd Plugin でも mysql.rds_rotate_slow_log
を実行して,mysql.slow_log_backup
からスロークエリログを取得する実装になっている.簡単に動作確認をすると,以下のようになる.
mysql> SELECT * FROM mysql.slow_log\G
Empty set (0.00 sec)
mysql> SELECT * FROM mysql.slow_log_backup\G
Empty set (0.00 sec)
mysql> SELECT SLEEP(10);
+
| SLEEP(10) |
+
| 0 |
+
1 row in set (10.01 sec)
mysql> SELECT * FROM mysql.slow_log\G
*************************** 1. row ***************************
start_time: 2017-02-23 13:06:28
user_host: xxx[xxx] @ [1.2.3.4]
query_time: 00:00:10
lock_time: 00:00:00
rows_sent: 1
rows_examined: 0
db:
last_insert_id: 0
insert_id: 0
server_id: 0
sql_text: SELECT SLEEP(10)
thread_id: 42
1 row in set (0.00 sec)
mysql> SELECT * FROM mysql.slow_log_backup\G
Empty set (0.01 sec)
mysql> CALL mysql.rds_rotate_slow_log;
Query OK, 0 rows affected (0.02 sec)
mysql> SELECT * FROM mysql.slow_log\G
Empty set (0.00 sec)
mysql> SELECT * FROM mysql.slow_log_backup\G
*************************** 1. row ***************************
start_time: 2017-02-23 13:06:28
user_host: xxx[xxx] @ [1.2.3.4]
query_time: 00:00:10
lock_time: 00:00:00
rows_sent: 1
rows_examined: 0
db:
last_insert_id: 0
insert_id: 0
server_id: 0
sql_text: SELECT SLEEP(10)
thread_id: 42
1 row in set (0.00 sec)
Aurora のログ関連の仕様とストアドプロシージャの仕様はドキュメントに書いてある.
docs.aws.amazon.com
docs.aws.amazon.com
SELECT SLEEP(10)
MySQL には標準で SLEEP
関数が付属していて,意図的にスロークエリを再現することができる.案外知らない人も多そうだし,僕も今回検証をしていて知ったので,一応載せておく.
fluent-plugin-rds-slowlog
今回スロークエリログを Fluentd 経由で転送するために,以下のプラグインを使った.
github.com
td-agent.conf
は以下のように書いた.ポイントを箇条書きにしておく.
- Aurora Writer と Aurora Reader のスロークエリログを転送するため
source
を2個用意した
interval
はデフォルトの10秒だと短すぎるため,300秒に変更した
<source>
@type rds_slowlog
tag rds_slowlog.writer
host example1.ap-northeast-1.rds.amazonaws.com
username xxx
password yyy
interval 300
</source>
<source>
@type rds_slowlog
tag rds_slowlog.reader
host example2.ap-northeast-1.rds.amazonaws.com
username xxx
password yyy
interval 300
</source>
<match rds_slowlog.*>
...
</match>
また,接続するユーザーも専用に用意した.必要なのは参照権限とプロシージャ実行権限なので,以下のように SELECT
と EXECUTE
だけを GRANT した.
mysql> GRANT SELECT, EXECUTE ON *.* TO 'fluentd'@'1.2.3.4' IDENTIFIED BY 'xxx';
今日 2/23 にリリースされた fluent-plugin-rds-slowlog v0.0.8
を使おう!
今までずっと公開されていた最新バージョンは v0.0.7
で,実はこれだと MySQL の再接続でエラーになる問題があり,既に master では修正が取り込まれていた.しかし,Gem がリリースされていなかったため,v0.0.7
だと source
を2個用意したことによって,コネクションがバッティングする場合があり,そのときに以下のエラーが出てしまっていた.
2017-02-22 15:35:12 +0900 [error]: Lost connection to MySQL server during query
2017-02-22 15:35:12 +0900 [error]: /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/mysql2-0.3.21/lib/mysql2/client.rb:80:in `_query'
2017-02-22 15:35:12 +0900 [error]: /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/mysql2-0.3.21/lib/mysql2/client.rb:80:in `block in query'
2017-02-22 15:35:12 +0900 [error]: /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/mysql2-0.3.21/lib/mysql2/client.rb:79:in `handle_interrupt'
2017-02-22 15:35:12 +0900 [error]: /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/mysql2-0.3.21/lib/mysql2/client.rb:79:in `query'
2017-02-22 15:35:12 +0900 [error]: /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluent-plugin-rds-slowlog-0.0.7/lib/fluent/plugin/in_rds_slowlog.rb:69:in `output'
2017-02-22 15:35:12 +0900 [error]: /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluent-plugin-rds-slowlog-0.0.7/lib/fluent/plugin/in_rds_slowlog.rb:92:in `call'
2017-02-22 15:35:12 +0900 [error]: /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluent-plugin-rds-slowlog-0.0.7/lib/fluent/plugin/in_rds_slowlog.rb:92:in `on_timer'
2017-02-22 15:35:12 +0900 [error]: /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/cool.io-1.4.2/lib/cool.io/loop.rb:88:in `run_once'
2017-02-22 15:35:12 +0900 [error]: /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/cool.io-1.4.2/lib/cool.io/loop.rb:88:in `run'
2017-02-22 15:35:12 +0900 [error]: /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluent-plugin-rds-slowlog-0.0.7/lib/fluent/plugin/in_rds_slowlog.rb:62:in `watch'
2017-02-22 15:45:22 +0900 [error]: MySQL server has gone away
2017-02-22 15:45:22 +0900 [error]: suppressed same stacktrace
2017-02-22 15:55:32 +0900 [error]: closed MySQL connection
2017-02-22 15:55:32 +0900 [error]: suppressed same stacktrace
エラーの詳細は Issue にも書いた.
github.com
Issue を書いた後に,直接コードを書き換えて master の状態にして検証をしてみたら,自動的に再接続が行われることによって問題は解決した.よって,メンテナ側に頼んで v0.0.8
を今日 2/23 にリリースしてもらった.
@winebarrel さん,助かりました!!!
github.com
ちなみに v0.0.8
だと,上記エラーが出た後に,以下のログが追加で出るようになっている.引き続きスタックトレース自体は出てしまうため,捨てる方法があるなら捨てたいなぁ…という感じ.どうしたら良いんだろう.
2017-02-23 12:03:28 +0900 [info]: fluent-plugin-rds-slowlog: try to reconnect to RDS
Amazon Elasticsearch Service + Kibana で可視化する
Elasticsearch 側は特に難しいことはなく,テンプレートを用意して,Kibana で可視化した.
{
"template": "rds_slowlog-*",
"mappings": {
"rds_slowlog": {
"properties": {
"user_host": {
"type": "string",
"index": "not_analyzed"
},
"sql_text": {
"type": "string",
"index": "not_analyzed"
}
}
}
}
}
Elasticsearch のインデックスは統一しているけど,@log_name
で Writer と Reader の識別ができるため,以下のようなクエリを書くとデータを分割できる.
@log_name: rds_slowlog.reader
@log_name: rds_slowlog.writer
スロークエリログを可視化できて便利!
検証してるときに Fluentd → Amazon Elasticsearch Service の転送でエラーになってて,困ってたら @yoshi_ken さんに Twitter でリプを頂いて,デバッグ方法などを教えてもらった.結果的に aggregator の時刻がズレてて AWS API のコールがエラーになっていることが原因だった.NTP 入って無くて残念な感じだった.アドバイスありがとうございました!
まとめ
- Aurora のスロークエリを Fluentd 経由で Amazon Elasticsearch Service に転送した
- Kibana でスロークエリを可視化できると,アプリケーションエンジニアのパフォーマンス改善が捗る
fluent-plugin-rds-slowlog
は v0.0.8
を使おう