Ruby and Rails

Ruby と Ruby on Rails のこと

Rails のログから遅い処理を見つけるワンライナー

ruby shell rails

ログから 200ms 以上かかっている処理を見つけるワンライナー。

$ ruby -ne 'if /(\d+\.?\d+)ms/ then puts "#{$.} #{$1} #{$_}" if $1.to_f > 200; end' log/production.log

行番号と時間とログが表示される。

283026 232.7 I, [2014-12-04T10:55:27.899449 #10715]  INFO -- :   Rendered foo/_form.html.erb (232.7ms)
283027 251.2 I, [2014-12-04T10:55:27.899779 #10715]  INFO -- :   Rendered foo/index.html.erb within laybars/slate (251.2ms)
283028 14459 I, [2014-12-04T10:55:27.901620 #10715]  INFO -- : Completed 200 OK in 14459ms (Views: 292.9ms | ActiveRecord: 12773.3ms)
283120 235.6 I, [2014-12-04T10:56:10.649837 #10715]  INFO -- :   Rendered foo/confirm.html.erb within laybars/slate (235.6ms)
283121 274 I, [2014-12-04T10:56:10.651312 #10715]  INFO -- : Completed 200 OK in 274ms (Views: 234.0ms | ActiveRecord: 20.7ms)
283364 6274 I, [2014-12-04T10:57:48.125014 #10715]  INFO -- : Completed 200 OK in 6274ms (Views: 8.6ms | ActiveRecord: 0.4ms)
283503 6309 I, [2014-12-04T10:59:24.549037 #10715]  INFO -- : Completed 200 OK in 6309ms (Views: 112.3ms | ActiveRecord: 6.4ms)
283686 333.6 I, [2014-12-04T11:02:31.107191 #28121]  INFO -- :   Rendered bar/_form.html.erb (333.6ms)
283687 335.7 I, [2014-12-04T11:02:31.107378 #28121]  INFO -- :   Rendered bar/index.html.erb within layouts/slate (335.7ms)
283688 596 I, [2014-12-04T11:02:31.324355 #28121]  INFO -- : Completed 200 OK in 596ms (Views: 547.1ms | ActiveRecord: 8.7ms)
283888 2456 I, [2014-12-04T11:03:41.131938 #28121]  INFO -- : Completed 200 OK in 2456ms (Views: 6.8ms | ActiveRecord: 2222.7ms)

該当行の前後を見たい場合。

# 100 行目を表示
$ sed -n 100p log/production.log

# 100 〜 200 行目を表示
$ sed -n 100,200p log/production.log