RDS(MySQL)のSlowQueryログをFluentdで収集したり

件名のとおりなんですが、同じような挙動をするプラグインが公式のリスト中にいくつもあって、どれを使えばいいの、ってなります。(なりました)

SlowQueryが取れそうなのは、

の3つが見つかりました。

どれでも良かったのですが、rds-log を使うことにしました。

github.com

rds-log自体rds-slowlogからforkされているのですが、選んだ理由は、一番ダウンロード数が多かったのと、hostも取得できたのと、genlogも取得できそうだったからです。(お寿司食べたかったから)

使い方とか

githubにある README.md 見ればわかる気がしますが一応。

gem install fluent-plugin-rds-log

<source>
  @type rds_log
  @id in_slow_query_log_sample_rds
  @label @slowquery
  log_type slow_log
  host sample-rds.xxxxxxxxxxxx.ap-northeast-1.rds.amazonaws.com
  username sample_user
  password sample_password
  refresh_interval 60
  auto_reconnect true
  tag rds-slowquery-log
  add_host true
</source>

<label @slowquery>
  <match rds-slowquery-log>
    @type stdout
  </match>
</label>

集めたログはKibanaに送ってあげれば良いのですが、そのまま送るとちょっと扱いづらいので加工してあげます。

ログの加工など

MySQLのスロークエリーログの何が扱いづらいかといいますと、 query_timelock_timeです。
このフィールドのフォーマットがMySQL5.6だと HH:mm:SS
MySQL5.7だと、 HH:mm:SS.ssssss にパワーアップします。 知りたいのは秒数だし、ElasticSearchには date型はあるけど、 time型はないっぽいので、これを加工します。あとついでにIPやUserも user_host から抜き出します。

ログの加工は record_transformer で行います。enable_rubytrue にして強引にパースすることにしました。

<label @slowquery>
    <filter>
        @type record_transformer
        enable_ruby true
        <record>
            source_ip ${user_host[/@.*?\[([0-9\.]+)\]/,1]}
            user      ${user_host[/^.+?\[(.+?)\].*?@/,1]}
            query_second ${m = query_time.match(/(?<hour>\d+):(?<minute>\d+):(?<second>\d+)(?:\.(?<milli>\d+))?/); m[:milli].to_i.to_f / 1000000 + m[:hour].to_i * 3600 + m[:minute].to_i * 60 + m[:second].to_i}
            lock_second  ${m = lock_time.match(/(?<hour>\d+):(?<minute>\d+):(?<second>\d+)(?:\.(?<milli>\d+))?/);  m[:milli].to_i.to_f / 1000000 + m[:hour].to_i * 3600 + m[:minute].to_i * 60 + m[:second].to_i}
        </record>
    </filter>
    <match>
      ....
    </match>
</label>

あとから見てもだいぶ強引ですが、これで晴れてquery_secondフィールドに浮動小数点でかかった時間が入るようになりました。

f:id:hajimeni:20170725193125p:plain

色々見せれない箇所にはモザイク入れていますが、 query_time からパースしたものが query_second に入っています。

おまけとか

fluent-plugin-rds-log 、前のバージョンである 0.1.9 まではMySQL5.7に接続したあとCloseする際の処理がうまくいっておらず、Closeすると必ず error-log

2017-07-04T09:58:45.968034Z 703463 [Note] Aborted connection 703463 to db: 'mysql' user: 'user_name' host: '10.x.x.x' (Got an error reading communication packets)

みたいなログが吐かれていました。

害はなさそうだったのですが、気になったので PullRequest を送ったところ、無事マージされました。ありがとうございました。

mysql2 のバージョンが 0.4.1 以上じゃないと発生するようなので、他のプラグインでも同じエラーが出るかもしれません。

今見たら、fluentd-plugin-rds-slowloggem.add_dependency "mysql2", "~> 0.3.11" とあるので発生しそうですね・・・ 時間があるときに動作確認してPRおくろうかな・・・