PythonでMySQLのスロークエリログを集計

久々に溜まったブログネタ放出をしようかなと、その前に下書きから掘り起こしてきた、いまさらなスロークエリ関連で準備運動です。

RDSのスロークエリ情報は当然、集計を自動化していつでも見れるようにしてあるのですが、ちょいと必要があったので、今回はあえて単発ログを集計する形に切り出したものを用意してみました。



スロークエリログの必要性

最近はNewRelicとかで、アプリケーションの処理を分別して処理時間などを集計するので、それで課題となるクエリを確認したりもします。

非常に便利な仕組みですが、アプリケーション外のジョブなどが実行したクエリは集計されないことや、負荷試験で課題を炙り出すときだとテスト環境にエージェントやライブラリを仕込む必要がある、といったデメリットとまでは言わないまでも面倒さがあります。

その点、スロークエリはサーバー側で記録するものなので、0.1秒とかでONにしておけば、対象のクエリが確実に記録されます。場合によっては今でもスロークエリのほうが迅速気軽に役立つ場合もあるし、あって困るものでもないので、自動集計を仕込むのはやっておいた方がよいです。


Python集計スクリプト

ぶっちゃけ、mysqldumpslow や pt-query-digest もあるので、ほとんどの場合はそっちを活用したらよいと思います。

私の場合、既存のクエリ解析システムがあったのでそれを流用したことや、Lambda Python で自動化を一通りやってしまいたかったことから、Pythonにした次第です。でも書いてしまえば、必要なものはPython1本になるし、データの扱いもやりたいことが自由自在なので、自分は気に入っています。

で、スクリプト2枚。
  • Gist > GedowFather > counter_slowquery.py

  • メインスクリプトの方でログファイルを直指定して実行すれば、こんな結果が出力されます。一時的な利用はこれですが、定期実行用はJSONをS3に保存するようになっています。


    これはAuroraのログでの結果ですが、少々ログ内容が異なる MariaDB とかでも動きます。

    けっこう大変なのは、複数のRDSログを読み込む場合は途中で切れてたりするし、クエリには改行も含むので、適切に繋いであげる必要があります。他にも入力値を ? に変換してユニーク化したり、とか色々あって、そういうの気にせずログを counterSlowQuery クラスにブチ込んでいけばいいよ。みたいになっています。

    んで結果をだいたい上から順にチェックしていって、主に Target Rows が大きいやつに目をつけて改善していく流れです。


    RDS全インスタンスの集計

    上記スクリプトは負荷試験直後とかに即座に集計したいときに使っていますが、それ程度ならそれこそ pt-query-digest でよくて、実際には全RDSインスタンスのスロークエリを1日に1回集計するのに使っています。そこはフレームワークちっくになってて面倒なので公開しませんが──

    RDSのスロークエリログはホスト毎に1時間単位のログになるので、任意のタグがついたホスト毎に24時間分を取得します。集計した結果を1つにまとめてランキング化し、JSONで保存して、1サービス分として管理画面(参考:AWS API Gatewayで軽量WEBサイトを構築)で結果を見れるようにしています。



    スロークエリだけでは、細かいチューニングまで行き届かないこともありますが、毎日分を気軽に見れるようにしておくと、中級以上の問題クエリを放置して日々品質悪化していくような運用を避けやすくなります。

    今回のは他手段もあるスロークエリだったのでつまらなかったかもですが、

    似た処理の一般クエリ解析におけるクエリ品質の定量化では、INの入力値の最大数を数えたり、一番遅そうなクエリでEXPLAIN実行して結果をまとめたり、インデックスを選択したユニーククエリの数を数えたり(逆に使われていないインデックスがわかる)、色んな仕組みを仕込んでいます。

    なので、そういうクエリのユニーク化処理のコードとか、部分的にでも役立てばいいなくらいの感じですが……なんせ当初PHPで書いてRubyに焼き直してPythonに翻った部品だったりもするので、全体的に雑だし格好良くはないですなw

    数多ある下書きの消化、終わり:-)