Viewing Rails log file on a production server

December 6, 2006 Link to post  Permalink

The Rails log file is a great way to see what your app is doing, but what do you do when the incoming request rate goes up, like on your production server?

Typically, you’ll be using tail to view the latest requests, and you’ll see something like this:

 1rocessing MyController#index (for 127.0.0.1 at 2006-12-06 18:55:42) [GET]
 2  Session ID: 88a032a331d5eca72e75e6880ec55016
 3  Parameters: {"action"=>"index", "controller"=>"my"}
 4...
 5...
 6Rendering ...
 7Rendering my/index
 8Completed in 0.10900 (9 reqs/sec) | Rendering: 0.06200 (56%) | DB: 0.03200 (29%) | 200 OK [http://localhost/]
 9
10
11Processing MyController#index (for 127.0.0.1 at 2006-12-06 18:55:42) [GET]
12  Session ID: 88a032a331d5eca72e75e6880ec55016
13  Parameters: {"action"=>"index", "controller"=>"my"}
14...
15...
16Rendering ...
17Rendering my/index
18Completed in 0.10900 (9 reqs/sec) | Rendering: 0.06200 (56%) | DB: 0.03200 (29%) | 200 OK [http://localhost/]
19

When you start getting a few of these a second, this method becomes unusable.

Here’s how I get around that, but can still watch in real time.

1ail -f production.log | grep "Processing "

This gives me an output that looks like this:

 1rocessing MyController#index (for 127.0.0.1 at 2006-12-06 18:55:42) [GET]
 2Processing MyController#index (for 127.0.0.1 at 2006-12-06 18:55:43) [GET]
 3Processing MyController#index (for 127.0.0.1 at 2006-12-06 18:55:44) [GET]
 4Processing MyController#index (for 127.0.0.1 at 2006-12-06 18:55:45) [GET]
 5Processing MyController#index (for 127.0.0.1 at 2006-12-06 18:55:46) [GET]
 6Processing MyController#index (for 127.0.0.1 at 2006-12-06 18:55:47) [GET]
 7Processing MyController#index (for 127.0.0.1 at 2006-12-06 18:55:48) [GET]
 8Processing MyController#index (for 127.0.0.1 at 2006-12-06 18:55:49) [GET]
 9Processing MyController#index (for 127.0.0.1 at 2006-12-06 18:55:50) [GET]
10Processing MyController#index (for 127.0.0.1 at 2006-12-06 18:55:51) [GET]

This is less informative, but allows me to keep up with what my server is doing in real time.

The next question is: What happens when I get so many requests that this technique becomes useless?