リクエストごとにSQLの実行ログを書き出すgemを作った

[ピクシブ株式会社 Advent Calendar 2017](https://qiita.com/advent-calendar/2017/pixiv)の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](https://github.com/ksss/mysql2-client-general_log)というgemがありました。ただ、ファイルに書き出す機能をアプリケーション側で書く必要があったり、prepared statementに対応していなかったりしたので、forkしてカスタマイズしました。そして、もっと手軽に設定できるようにRack Middlewareにしてみました。

また、ISUCONではPostgreSQLが使われたこともあったのでPostgreSQL版も作ってみました。mysql2版とpg版の使い方はほぼ同じなので、この記事ではmysql2版の紹介をしようと思います。

* mysql2版: [mysql2-client-general_log](https://github.com/abcang/mysql2-client-general_log)
* pg版: [pg-connection-general_log](https://github.com/abcang/pg-connection-general_log)

## 使い方
今回はSinatraを使った場合の使い方を紹介します。

Gemfileではfork先のgithubのリポジトリを指定します。

```ruby:Gemfile
gem 'mysql2-client-general_log', github: 'abcang/mysql2-client-general_log', branch: 'rack_middleware'
```

config.ruは以下のようになります。

```ruby: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`ディレクトリに保存され、バックトレースも出力されることになります。

アプリケーションには特に手を加える必要はありません。

```ruby:app.rb
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
```

この状態でページにアクセスをすると、その日付のファイル名でログファイルが作成されます。

```text:/tmp/general_log/2017-12-04.txt
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`は次のようになっています。

```ruby
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をログに追加するようにしています。

```ruby
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」から始まる行を抽出して、クエリの実行回数の多い順に並べて見てみます。

```bash
$ 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」から始まる行を抽出して、実行時間の長い順に並べて見てみます。

```bash
$ 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](https://qiita.com/advent-calendar/2017/pixiv)をお楽しみください。