ピクシブ株式会社 Advent Calendar 2017の4日目です。Pawooの開発を担当している17年度新卒のabcangです。
今回はタイトルにもあるように、リクエストごとにSQLの実行ログを書き出すgemを作った話を書こうと思います。
作った動機
Railsのデバッグログではリクエストごとに実行されたSQLを見ることができ、このログを見るとすぐにN+1問題に気づけるのでとても便利です。このロギング機能はActiveRecordが提供しているので、ActiveRecordを使わずに直接mysql2やpgなどのライブラリを使用している場合はこのようなログは出力されません。
ところで、ISUCONでは毎回Rubyで実装されたアプリケーションが提供されており、そのアプリケーションにはN+1問題がある事が多いです。しかし、Sinatraとmysql2を使用して実装されているため、Railsのデバッグログのようにリクエストごとに実行されたSQLを見ることはできません。つまり何が言いたいかというと、ISUCONの問題を解くときに、リクエストごとに実行されたSQLを見たい！！ということです。
そのようなライブラリがないかと調べてみたところ、mysql2-client-general_logというgemがありました。ただ、ファイルに書き出す機能をアプリケーション側で書く必要があったり、prepared statementに対応していなかったりしたので、forkしてカスタマイズしました。そして、もっと手軽に設定できるようにRack Middlewareにしてみました。
また、ISUCONではPostgreSQLが使われたこともあったのでPostgreSQL版も作ってみました。mysql2版とpg版の使い方はほぼ同じなので、この記事ではmysql2版の紹介をしようと思います。
- mysql2版: mysql2-client-general_log
- pg版: pg-connection-general_log
使い方
今回はSinatraを使った場合の使い方を紹介します。
Gemfileではfork先のgithubのリポジトリを指定します。
gem 'mysql2-client-general_log', github: 'abcang/mysql2-client-general_log', branch: 'rack_middleware'
config.ruは以下のようになります。
require_relative './app'
require 'mysql2/client/general_log'
use Mysql2::Client::GeneralLog::Middleware, enabled: true, backtrace: true, path: '/tmp/general_log'
run Sinatra::Application
ミドルウェアに渡すことのできるオプションは「enabled」「backtrace」「path」の3つです。
- enabled: ロギングの有効/無効
- backtrace: バックトレース(直前1件のみ)を出力するかどうか
- path: ログを保存するディレクトリ
この場合ログファイルは/tmp/general_logディレクトリに保存され、バックトレースも出力されることになります。
アプリケーションには特に手を加える必要はありません。
require 'sinatra'
require 'mysql2'
helpers do
def db
Thread.current[:db] ||= Mysql2::Client.new(config)
end
end
get '/' do
db.query("SELECT * FROM users LIMIT 1")
stmt = db.prepare('SELECT * FROM users WHERE name = ?')
stmt.execute('test')
stmt.execute('hoge')
end
この状態でページにアクセスをすると、その日付のファイル名でログファイルが作成されます。
REQUEST GET / 3
SQL (0000.53ms) SELECT * FROM users LIMIT 1 [] /path/to/app.rb:11:in `block in <main>'
SQL (0000.66ms) SELECT * FROM users WHERE name = ? ["test"] /path/to/app.rb:12:in `block in <main>'
SQL (0000.65ms) SELECT * FROM users WHERE name = ? ["hoge"] /path/to/app.rb:13:in `block in <main>'
「REQUEST」から始まっている行はリクエストの情報で、HTTPメソッド、リクエストされたパス、実行されたSQLの数がタブ文字区切りで書かれています。
「SQL」から始まっている行は実行されたSQLの情報で、実行時間、実行されたクエリ、prepared statementの引数、バックトレースがタブ文字区切りで書かれています。
実装
このライブラリでは、実行したSQLや実行にかかった時間を取得するためにmysql2のメソッドにモンキーパッチをしています。
例えば、Mysql2::Client#queryは次のようになっています。
module ClientExt
def query(sql, options = {})
ret = nil
time = Benchmark.realtime do
ret = super
end
Mysql2::Client::GeneralLog.general_log.push(sql, [], caller_locations, time)
ret
end
end
Benchmark.realtimeを使用して実行時間を計測し、実行したSQLや計測した時間などをログに追加しています。
prepared statementの場合はクエリの実行がStatement#executeで行われるので、Client#prepareの返り値のStatementのインスタンスにsqlを代入して、Statement#executeで代入されたsqlをログに追加するようにしています。
module ClientExt
def prepare(sql)
super.tap do |ret|
ret.sql = sql
end
end
end
module StatementExt
attr_accessor :sql
def execute(*args)
ret = nil
time = Benchmark.realtime do
ret = super
end
Mysql2::Client::GeneralLog.general_log.push(sql, args, caller_locations, time)
ret
end
end
実際に使ってみる
ISUCON7の予選で使ってみたときの様子を紹介したいと思います。
出力されたログはそのままでは見づらいので、必要な情報を抽出してソートするのがいいです。まずはSQLの実行回数が多いリクエストを調べてみます。「REQUEST」から始まる行を抽出して、クエリの実行回数の多い順に並べて見てみます。
$ cat /tmp/general_log/2017-12-04.txt | sed '/^REQUEST/!d' | sort -rnk4 | less
REQUEST GET /fetch 202
REQUEST GET /fetch 202
REQUEST GET /fetch 202
REQUEST GET /fetch 202
/fetchでSQLの実行回数が非常に多いことがわかりますね。実際にファイルを開いて該当箇所を見てみるとSELECT * FROM haveread WHERE user_id = ? AND channel_id = ?やSELECT COUNT(*) as cnt FROM message WHERE channel_id = ?が一回のリクエストで何度も呼ばれており、N+1問題が発生していることがすぐにわかりました。
REQUEST GET /fetch 202
SQL (0000.39ms) SET SESSION sql_mode='TRADITIONAL,NO_AUTO_VALUE_ON_ZERO,ONLY_FULL_GROUP_BY' [] /home/isucon/isubata/webapp/ruby/app.rb:364:in `db'
SQL (0000.65ms) SELECT id FROM channel [] /home/isucon/isubata/webapp/ruby/app.rb:164:in `block in <class:App>'
SQL (0000.36ms) SELECT * FROM haveread WHERE user_id = ? AND channel_id = ? [316, 1] /home/isucon/isubata/webapp/ruby/app.rb:170:in `block (2 levels) in <class:App>'
SQL (0014.32ms) SELECT COUNT(*) as cnt FROM message WHERE channel_id = ? [1] /home/isucon/isubata/webapp/ruby/app.rb:176:in `block (2 levels) in <class:App>'
SQL (0000.24ms) SELECT * FROM haveread WHERE user_id = ? AND channel_id = ? [316, 2] /home/isucon/isubata/webapp/ruby/app.rb:170:in `block (2 levels) in <class:App>'
SQL (0005.80ms) SELECT COUNT(*) as cnt FROM message WHERE channel_id = ? [2] /home/isucon/isubata/webapp/ruby/app.rb:176:in `block (2 levels) in <class:App>'
SQL (0003.10ms) SELECT * FROM haveread WHERE user_id = ? AND channel_id = ? [316, 3] /home/isucon/isubata/webapp/ruby/app.rb:170:in `block (2 levels) in <class:App>'
SQL (0005.39ms) SELECT COUNT(*) as cnt FROM message WHERE channel_id = ? [3] /home/isucon/isubata/webapp/ruby/app.rb:176:in `block (2 levels) in <class:App>'
SQL (0000.55ms) SELECT * FROM haveread WHERE user_id = ? AND channel_id = ? [316, 4] /home/isucon/isubata/webapp/ruby/app.rb:170:in `block (2 levels) in <class:App>'
また、このログファイルを使って、単純に実行に時間がかかっているクエリを調べることもできます。今度は「SQL」から始まる行を抽出して、実行時間の長い順に並べて見てみます。
$ cat /tmp/general_log/2017-12-04.txt | sed '/^SQL/!d' | sort -rnk2 | less
SQL (1542.71ms) SELECT * FROM image WHERE name = ? ["f0a6a8334e2b9b3f49c39ce35a19a2d20e648aab.png"] /home/isucon/isubata/webapp/ruby/app.rb:334:in `block in <class:App>'
SQL (1313.45ms) SELECT * FROM image WHERE name = ? ["0614f0cea1b70fb71b4c3b88545a42327157a41e.jpg"] /home/isucon/isubata/webapp/ruby/app.rb:334:in `block in <class:App>'
SQL (1308.25ms) SELECT * FROM image WHERE name = ? ["b4f9effc4d9e86b58b271f5652b51dd997036d43.png"] /home/isucon/isubata/webapp/ruby/app.rb:334:in `block in <class:App>'
SQL (1307.29ms) SELECT * FROM image WHERE name = ? ["bde120814720fb3bee14f415b4001305868df456.png"] /home/isucon/isubata/webapp/ruby/app.rb:334:in `block in <class:App>'
SQL (1302.51ms) SELECT * FROM image WHERE name = ? ["c2d161d74b4e6b6541974a473bf0a9dfb01579dd.png"] /home/isucon/isubata/webapp/ruby/app.rb:334:in `block in <class:App>'
データベースのスロークエリログを有効にすれば遅いクエリを見れますが、このライブラリを使う場合はスタックトレースの情報も出力できるので、どの行で遅いクエリが実行されているかがすぐにわかります。便利ですね。
おわりに
このライブラリではタブ文字区切りのログとして出力していますが、もっと解析しやすいようなフォーマットで出力してみるのもいいかもしれないですね。
ISUCONで使う時に限らず、リクエストごとにSQLの実行ログをSinatraでも見たいと思ったときはぜひ使ってみてください。
引き続きピクシブ株式会社 Advent Calendar 2017をお楽しみください。