読者です 読者をやめる 読者になる 読者になる

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>

また,接続するユーザーも専用に用意した.必要なのは参照権限とプロシージャ実行権限なので,以下のように SELECTEXECUTE だけを 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-slowlogv0.0.8 を使おう