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 を使おう
