embulk チュートリアルを兼ねて RDS のスロークエリをログを Elasticsearch と Kibana で可視化する

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)

参考

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|lnsert_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 にてインデックスを登録しておく。）

20160508101345

ログを簡単に登録することが出来た。後は、適宜、Visualize を作って Dashboard に貼るを繰り返す。

最後に

バッチ化にあたって

バッチ化にあたり、課題としては以下の点。

Elasticsearch のインデックスを日付単位で作成したいので、日毎に YAML を書き換える必要があるので YAML をテンプレート化したいけど、これを embulk だけで完結することが出来るか
ローテーションプロシージャの実行も embulk 出来ると嬉しい（これも embulk だけで完結したい）

以上

embulk を使うことでほぼ数ステップでスロークエリログを可視化することが出来そうなことは解った。

元記事はこちら

「embulk チュートリアルを兼ねて RDS のスロークエリをログを Elasticsearch と Kibana で可視化する」

embulk チュートリアルを兼ねて RDS のスロークエリをログを Elasticsearch と Kibana で可視化する

tl;dr

参考

memo

ログの記録先をどうするか

embulk インストール

embulk プラグインのインストール

YAML ファイルの作成

embulk preview

処理の実行（embulk run）

最後に

バッチ化にあたって

以上

元記事はこちら

AWSの生成AI活用事例集GenUを使い倒す

アイレット新卒シリーズ Vol.65 25卒内定者向けオフィスツアー実施レポート

cron の代わりに systemd timer を使ってみた

【AWS re:Invent 2024】Amazon Linux AL2023 and beyond

【AWS re:Invent 2024】生成AI で MSP を進化せよ！ [PEX201]

embulk チュートリアルを兼ねて RDS のスロークエリをログを Elasticsearch と Kibana で可視化する

tl;dr

参考

memo

ログの記録先をどうするか

embulk インストール

embulk プラグインのインストール

YAML ファイルの作成

embulk preview

処理の実行（embulk run）

最後に

バッチ化にあたって

以上

元記事はこちら

関連記事Related Articles

JMeter の CSV 結果を eEK Stack(embulk + Elasticserach + Kibana) で可視化する考察

（ショロカレ 4 日目）2015 年のうちにやっておきたい Amazon Elasticsearch Service 入門

運用でSSHログインをしないための設計ポイント（ログ取得編）【cloudpack大阪ブログ】

Amazon ES へのアクセスを IAM role と IP アドレスで制御する試行錯誤

CloudTrailのログをKibanaで確認する(CloudWatch → Lambda → Elasticsearch)