Railsのproductionログから処理に時間がかかっている部分を探す

先日、運用環境のRailsで動いているアプリのログからレスポンスタイムを確認する機会があって、production.logをもとに、時間がかかっている重い処理を抽出しました。ちなみにRailsのバージョンは2.1系です。

このエントリは、そのメモ書きです。どの処理が遅いのかを探し出すための最初の一歩ということで参考になれば。

Railsのログ

Railsアプリをproductionモードで動かしていると、以下のようなログが各処理の最後で記録され、処理全体にかかった時間や、そのうちのレンダリング処理、DB処理の内訳なども確認できるようになっています。

Completed in 0.52340 (1 reqs/sec) | Rendering: 0.41524 (79%) | DB: 0.07341 (14%) | 200 OK [https://example.jp/hoge]

時間がかかっている処理を遅い順で並べる

logの配置してあるディレクトリにcdして以下を実行。
※もしくはgrepの実行時にパス(下記production.logの部分)を指定する。

$ grep Completed production.log | sort -nr -k 3 | head -10

結果は以下のような感じ。

Completed in 2.69093 (0 reqs/sec) | Rendering: 0.44624 (16%) | DB: 2.13887 (79%) | 200 OK [https://example.jp/hoge]
Completed in 0.98980 (1 reqs/sec) | Rendering: 0.47597 (48%) | DB: 0.02830 (2%) | 200 OK [https://example.jp/fuga]
Completed in 0.97201 (1 reqs/sec) | Rendering: 0.39922 (41%) | DB: 0.03789 (3%) | 200 OK [https://example.jp/xxx]
Completed in 0.80405 (1 reqs/sec) | Rendering: 0.65980 (82%) | DB: 0.09888 (12%) | 200 OK [https://example.jp/fuga]
Completed in 0.78754 (1 reqs/sec) | Rendering: 0.35290 (44%) | DB: 0.34467 (43%) | 200 OK [https://example.jp/xxx]
Completed in 0.78178 (1 reqs/sec) | Rendering: 0.56329 (72%) | DB: 0.03432 (4%) | 200 OK [https://example.jp/yyy]
Completed in 0.70684 (1 reqs/sec) | Rendering: 0.13841 (19%) | DB: 0.44586 (63%) | 200 OK [https://example.jp/xxx]
Completed in 0.64225 (1 reqs/sec) | Rendering: 0.00122 (0%) | DB: 0.00183 (0%) | 200 OK [https://example.jp/zzz]
Completed in 0.63974 (1 reqs/sec) | Rendering: 0.42505 (66%) | DB: 0.04362 (6%) | 200 OK [https://example.jp/zzz]
Completed in 0.61231 (1 reqs/sec) | Rendering: 0.38080 (62%) | DB: 0.14062 (22%) | 200 OK [https://example.jp/yyy]

今回の例では、上位10個を出しましたが、headコマンドの引数を変えることで、出力する数は制御可能です。

以下でも同様ですが、headコマンドを実行しなければ、全ての処理が遅い順にソートされた状態で出力されます。

レンダリングに時間がかかっているリクエストを調べる

同様に、、、

$ grep "Rendering:" production.log | sort -nr -k 8 | head -5

上記のコマンドを発行すると、、、

Completed in 0.80405 (1 reqs/sec) | Rendering: 0.65980 (82%) | DB: 0.09888 (12%) | 200 OK [https://example.jp/fuga]
Completed in 0.78178 (1 reqs/sec) | Rendering: 0.56329 (72%) | DB: 0.03432 (4%) | 200 OK [https://example.jp/xxx]
Completed in 0.98980 (1 reqs/sec) | Rendering: 0.47597 (48%) | DB: 0.02830 (2%) | 200 OK [https://example.jp/fuga]
Completed in 0.51523 (1 reqs/sec) | Rendering: 0.46443 (90%) | DB: 0.01914 (3%) | 200 OK [https://example.jp/zzz]
Completed in 0.52032 (1 reqs/sec) | Rendering: 0.45536 (87%) | DB: 0.00715 (1%) | 200 OK [https://example.jp/yyy]

こんな感じで"Rendering"の部分で時間がかかっている処理の順となります。

DB処理に時間がかかっているリクエストを調べる

同様に、、、

$ grep "DB:" production.log | sort -nr -k 12 | head -5

上記のコマンドを発行すると、、、

Completed in 2.69093 (0 reqs/sec) | Rendering: 0.44624 (16%) | DB: 2.13887 (79%) | 200 OK [https://example.jp/hoge]
Completed in 0.70684 (1 reqs/sec) | Rendering: 0.13841 (19%) | DB: 0.44586 (63%) | 200 OK [https://example.jp/xxx]
Completed in 0.78754 (1 reqs/sec) | Rendering: 0.35290 (44%) | DB: 0.34467 (43%) | 200 OK [https://example.jp/xxx]
Completed in 0.59749 (1 reqs/sec) | Rendering: 0.16830 (28%) | DB: 0.32549 (54%) | 200 OK [https://example.jp/yyy]
Completed in 0.32658 (3 reqs/sec) | Rendering: 0.00251 (0%) | DB: 0.31102 (95%) | 200 OK [https://example.jp/fuga]

こんな感じで"DB"の部分で時間がかかっている処理の順となります。

その他

ログ内全ての処理を対象に遅い順でソートし、profile.logに出力する

$ grep Completed production.log | sort -k 3 > profile.log

処理に1秒以上かかっているリクエストのみを抽出し、profile.logに出力する

$ grep "(0 reqs/sec)" production.log | sort -k 3 > profile.log

エンタープライズ Rails ―企業ユーザのためのWebアプリケーション設計術