RDS のスロークエリをログを Elasticsearch と Kibana で可視化するシリーズ。
tl;dr
RDS のスロークエリをログを Elasticsearch と Kibana で可視化する方法を色々と模索。リアルタイムに可視化したければ、ログの出力先をテーブル、ファイルの場合でも fluentd と絡めると良さそう。リアルタイムまでは求められていないけど、一定期間のログを後から可視化して分析したいというシチュエーションがあったとしたら、Embulk を絡めると良いのではと思ったので Embulk のチュートリアルを兼ねて検討してみた。
検討に利用した環境は以下の通り。
% sw_vers ProductName: Mac OS X ProductVersion: 10.11.5 BuildVersion: 15F24b % java -version java version "1.7.0_79" Java(TM) SE Runtime Environment (build 1.7.0_79-b15) Java HotSpot(TM) 64-Bit Server VM (build 24.79-b02, mixed mode)
参考
- http://www.embulk.org/docs/recipe/scheduled-csv-load-to-elasticsearch-kibana4.html
- http://qiita.com/sonots/items/979c8b0810ccffc47317
memo
ログの記録先をどうするか
ログファイルから読み込んでみたいと思ったが、スロークエリログを読み込むプラグインを探すことが出来なかったのと、プラグインをこさえる力量も無いので、既に配布されている embulk-input-mysql プラグインを利用してログをテーブルから読み込むようにしたい。
embulk インストール
ドキュメントに従って embulk をインストールする。
% curl --create-dirs -o ~/.embulk/bin/embulk -L "http://dl.embulk.org/embulk-latest.jar" % chmod +x ~/.embulk/bin/embulk % echo 'export PATH="$HOME/.embulk/bin:$PATH"' >> ~/.zshrc % source ~/.zshrc % embulk --version embulk 0.8.8
embulk プラグインのインストール
今回はテーブルからログを読み込む為の embulk-input-mysql と読み込んだログを Elasticsearch に放り込む embulk-output-elasticsearch を以下のようにインストール。
% mkdir batch % cd batch # # プラグインを Gemfile で管理したいと思ったので以下のように対応 # 参考：http://qiita.com/sonots/items/979c8b0810ccffc47317 # % embulk mkbundle bundle % vim bundle/Gemfile (snip) # # 以下を追加 # gem 'embulk-input-mysql' gem 'embulk-output-elasticsearch' (snip) # # プラグインのインストール # % embulk bundle
プラグインがインストールされたことを確認する。
% embulk bundle list -b bundle 2016-05-08 09:58:47.619 +0900: Embulk v0.8.8 Gems included by the bundle: * bundler (1.10.6) * embulk (0.7.11) * embulk-input-mysql (0.7.1) * embulk-output-elasticsearch (0.3.0) * liquid (3.0.6) * rjack-icu (4.54.1.1)
YAML ファイルの作成
guess サブコマンドを利用して雛形から生成するステップをよく見かけるものの、以下のように YAML ファイルを作成。
in: type: mysql host: demo-db.xxxxxxxxxxxx.ap-northeast-1.rds.amazonaws.com user: ${user} password: ${password} database: mysql query: | SELECT CONVERT_TZ(start_time, '+00:00','+09:00') AS converted_start_time, user_host, SECOND(query_time) AS converted_query_time, SECOND(lock_time) AS converted_lock_time, rows_sent, rows_examined, db, sql_text FROM mysql.slow_log_backup out: type: elasticsearch index: embulk-2016.05.08 index_type: embulk nodes: - host: ${elasticsearc-host}
テーブルにログを記録する場合、ログ自体は mysql.slow_log に書き込まれるが、以下のようなローテーションプロシージャを実行することで mysql.slow_log_backup というテーブルにログがコピーされる。
ALL mysql.rds_rotate_slow_log;
このテーブルに対して、クエリを投げるように設定する。
また、テーブルに記録されているログはデフォルトでは以下のような結果となる。
mysql> SELECT * FROM mysql.slow_log_backup; +---------------------+----------------------------------------------------------------------------------+------------+-----------+-----------+---------------+----+----------------+-----------+-----------+-----------------+-----------+ | start_time | user_host | query_time | lock_time | rows_sent | rows_examined | db | last_insert_id | insert_id | server_id | sql_text | thread_id | +---------------------+----------------------------------------------------------------------------------+------------+-----------+-----------+---------------+----+----------------+-----------+-----------+-----------------+-----------+ | 2016-05-07 23:25:09 | user[user] @ xxxxxxx | 00:00:03 | 00:00:00 | 1 | 0 | | 0 | 0 | 700921024 | select sleep(3) | 29 | | 2016-05-07 23:25:16 | user[user] @ xxxxxxx | 00:00:02 | 00:00:00 | 1 | 0 | | 0 | 0 | 700921024 | select sleep(2) | 30 | +---------------------+----------------------------------------------------------------------------------+------------+-----------+-----------+---------------+----+----------------+-----------+-----------+-----------------+-----------+ 2 rows in set (0.03 sec)
このままでも Elasticsearch に放り込むことが出来ることは確認したが、start_time が UTC になってしまっている点、query_time と lock_time がそのままだと embulk 側で timestamp で解釈されてしまったので、以下のように SQL のクエリで調整してみた。
SELECT CONVERT_TZ(start_time, '+00:00','+09:00'), user_host, SECOND(query_time), SECOND(lock_time), rows_sent, rows_examined, db, sql_text FROM mysql.slow_log_backup
このあたりは embulk 側で調整出来るなら調整した方がいいのかな...。もしかしたら、アンチパターンかもしれないので、ちゃんと調べたい。
embulk preview
実際の処理を前に preview サブコマンドで処理の事前確認を行う。
% embulk preview rds-slowlog.yml -b bundle
以下のように出力される。
2016-05-08 19:30:40.383 +0900: Embulk v0.8.8 2016-05-08 19:30:41.518 +0900 [INFO] (0001:preview): Loaded plugin embulk-input-mysql (0.7.1) 2016-05-08 19:30:41.604 +0900 [INFO] (0001:preview): Fetch size is 10000. Using server-side prepared statement. 2016-05-08 19:30:42.188 +0900 [INFO] (0001:preview): SQL: SELECT CONVERT_TZ(start_time, '+00:00','+09:00') AS converted_start_time, user_host, SECOND(query_time) AS converted_query_time, SECOND(lock_time) AS converted_lock_time, rows_sent, rows_examined, db, sql_text FROM mysql.slow_log_backup 2016-05-08 19:30:42.380 +0900 [INFO] (0001:preview): Fetch size is 10000. Using server-side prepared statement. 2016-05-08 19:30:42.634 +0900 [INFO] (0001:preview): SQL: SELECT CONVERT_TZ(start_time, '+00:00','+09:00') AS converted_start_time, user_host, SECOND(query_time) AS converted_query_time, SECOND(lock_time) AS converted_lock_time, rows_sent, rows_examined, db, sql_text FROM mysql.slow_log_backup 2016-05-08 19:30:42.690 +0900 [INFO] (0001:preview): > 0.03 seconds +--------------------------------+----------------------------------------------------------------------------------+---------------------------+--------------------------+----------------+--------------------+-----------+-----------------+ | converted_start_time:timestamp | user_host:string | converted_query_time:long | converted_lock_time:long | rows_sent:long | rows_examined:long | db:string | sql_text:string | +--------------------------------+----------------------------------------------------------------------------------+---------------------------+--------------------------+----------------+--------------------+-----------+-----------------+ | 2016-05-08 10:30:06 UTC | user[user] @ xxxxxxx | 1 | 0 | 1 | 0 | | select sleep(1) | +--------------------------------+----------------------------------------------------------------------------------+---------------------------+--------------------------+----------------+--------------------+-----------+-----------------+
処理の実行（embulk run）
preview サブコマンドでエラーが無ければ、以下のように処理を実行する。
% mysql -h demo-db.xxxxxxxxxxxxx.ap-northeast-1.rds.amazonaws.com -u${user} -p${password} --execute 'CALL mysql.rds_rotate_slow_log;' % embulk run rds-slowlog.yml -b bundle
以下のように出力される。
2016-05-08 10:08:01.872 +0900: Embulk v0.8.8 2016-05-08 10:08:04.457 +0900 [INFO] (0001:transaction): Loaded plugin embulk-input-mysql (0.7.1) 2016-05-08 10:08:04.557 +0900 [INFO] (0001:transaction): Loaded plugin embulk-output-elasticsearch (0.3.0) 2016-05-08 10:08:04.654 +0900 [INFO] (0001:transaction): Fetch size is 10000. Using server-side prepared statement. 2016-05-08 10:08:05.313 +0900 [INFO] (0001:transaction): SQL: SELECT CONVERT_TZ(start_time, '+00:00','+09:00'), user_host, SECOND(query_time), SECOND(lock_time), rows_sent, rows_examined, db, sql_text FROM mysql.slow_log_backup 2016-05-08 10:08:05.490 +0900 [INFO] (0001:transaction): Using local thread executor with max_threads=8 / output tasks 4 = input tasks 1 * 4 2016-05-08 10:08:05.604 +0900 [INFO] (0001:transaction): [Artie] loaded [], sites [] 2016-05-08 10:08:06.651 +0900 [INFO] (0001:transaction): Executing plugin with 'insert' mode. 2016-05-08 10:08:06.652 +0900 [INFO] (0001:transaction): Inserting data into index[embulk-2016.05.08] 2016-05-08 10:08:06.660 +0900 [INFO] (0001:transaction): {done: 0 / 1, running: 0} 2016-05-08 10:08:06.690 +0900 [INFO] (0029:task-0000): [Scaleface] loaded [], sites [] 2016-05-08 10:08:06.814 +0900 [INFO] (0029:task-0000): [Coach] loaded [], sites [] 2016-05-08 10:08:06.922 +0900 [INFO] (0029:task-0000): [Looter] loaded [], sites [] 2016-05-08 10:08:07.015 +0900 [INFO] (0029:task-0000): [Blindspot] loaded [], sites [] 2016-05-08 10:08:07.342 +0900 [INFO] (0029:task-0000): Fetch size is 10000. Using server-side prepared statement. 2016-05-08 10:08:07.597 +0900 [INFO] (0029:task-0000): SQL: SELECT CONVERT_TZ(start_time, '+00:00','+09:00'), user_host, SECOND(query_time), SECOND(lock_time), rows_sent, rows_examined, db, sql_text FROM mysql.slow_log_backup 2016-05-08 10:08:05.490 +0900 [INFO] (0001:transaction): Using local thread executor with max_threads=8 / output tasks 4 = input tasks 1 * 4 2016-05-08 10:08:05.604 +0900 [INFO] (0001:transaction): [Artie] loaded [], sites [] 2016-05-08 10:08:06.651 +0900 [INFO] (0001:transaction): Executing plugin with 'insert' mode. 2016-05-08 10:08:06.652 +0900 [INFO] (0001:transaction): Inserting data into index[embulk-2016.05.08] 2016-05-08 10:08:06.660 +0900 [INFO] (0001:transaction): {done: 0 / 1, running: 0} 2016-05-08 10:08:06.690 +0900 [INFO] (0029:task-0000): [Scaleface] loaded [], sites [] 2016-05-08 10:08:06.814 +0900 [INFO] (0029:task-0000): [Coach] loaded [], sites [] 2016-05-08 10:08:06.922 +0900 [INFO] (0029:task-0000): [Looter] loaded [], sites [] 2016-05-08 10:08:07.015 +0900 [INFO] (0029:task-0000): [Blindspot] loaded [], sites [] 2016-05-08 10:08:07.342 +0900 [INFO] (0029:task-0000): Fetch size is 10000. Using server-side prepared statement. 2016-05-08 10:08:07.597 +0900 [INFO] (0029:task-0000): SQL: SELECT CONVERT_TZ(start_time, '+00:00','+09:00'), user_host, SECOND(query_time), SECOND(lock_time), rows_sent, rows_examined, db, sql_text FROM mysql.slow_log_backup 2016-05-08 10:08:07.664 +0900 [INFO] (0029:task-0000): > 0.03 seconds 2016-05-08 10:08:07.791 +0900 [INFO] (0029:task-0000): Execute 270 bulk actions 2016-05-08 10:08:09.591 +0900 [INFO] (elasticsearch[Scaleface][listener][T#1]): 270 bulk actions succeeded 2016-05-08 10:08:09.752 +0900 [INFO] (0001:transaction): {done: 1 / 1, running: 0} 2016-05-08 10:08:09.775 +0900 [INFO] (main): Committed. 2016-05-08 10:08:09.776 +0900 [INFO] (main): Next config diff: {"in":{},"out":{}}
Kibana の Discover で確認してみる。（事前に Index Patterns にてインデックスを登録しておく。）
ログを簡単に登録することが出来た。後は、適宜、Visualize を作って Dashboard に貼るを繰り返す。
最後に
バッチ化にあたって
バッチ化にあたり、課題としては以下の点。
- Elasticsearch のインデックスを日付単位で作成したいので、日毎に YAML を書き換える必要があるので YAML をテンプレート化したいけど、これを embulk だけで完結することが出来るか
- ローテーションプロシージャの実行も embulk 出来ると嬉しい（これも embulk だけで完結したい）
以上
embulk を使うことでほぼ数ステップでスロークエリログを可視化することが出来そうなことは解った。
