kakakakakku blog

Weekly Tech Blog: Keep on Learning!

Aurora のスロークエリログを Fluentd 経由で Amazon Elasticsearch Service に転送する

Aurora Fluentd Elasticsearch

Aurora でスロークエリログを出力して，Fluentd 経由で Amazon Elasticsearch Service に転送する構成を作った．MySQL on EC2 のときは，サーバ内で直接スロークエリログを確認していて非常に面倒だったので（単なる運用上の考慮不足），運用面で大きく改善できるし，アプリケーションエンジニアも自由に Kibana で確認できるため，パフォーマンス改善が捗ると思う．非常に良い．

アーキテクチャ図

f:id:kakku22:20170223135353p:plain

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.slow_log` に登録された
--

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.slow_log_backup` に移動された
--

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

スロークエリログを可視化できて便利！

f:id:kakku22:20170223135408p:plain

検証してるときに Fluentd → Amazon Elasticsearch Service の転送でエラーになってて，困ってたら @yoshi_ken さんに Twitter でリプを頂いて，デバッグ方法などを教えてもらった．結果的に aggregator の時刻がズレてて AWS API のコールがエラーになっていることが原因だった．NTP 入って無くて残念な感じだった．アドバイスありがとうございました！

まとめ

  • Aurora のスロークエリを Fluentd 経由で Amazon Elasticsearch Service に転送した
  • Kibana でスロークエリを可視化できると，アプリケーションエンジニアのパフォーマンス改善が捗る
  • fluent-plugin-rds-slowlog は v0.0.8 を使おう