Analyzing Rails Log Files for Slow Actions

There are plenty of packages for analyzing rails log files. These are helpful when you want to find bottlenecks in your application. A very easy to use one is rawk.rb discussed in Railscast #97. These tools are great as they help you to spend your efforts on the most costly areas of your code.

However, if you want to do a really quick, but less precise analysis of your code you can resort to some simple Unix tools as shown here:

grep "Completed in" development.log | cut -d' ' -f 3,17 | sort

view raw gistfile1.sh hosted with ❤ by GitHub

This simple command line greps out the "Completed in" lines, cuts out the 3rd and 17th columns as separated by spaces, and then sorts the result. The two fields that have been cut out represent the number of seconds and URL for the action in question looking something like this:

	...
	5.44948 [https://something.org/icons.xml?icon%5Fcategory%5Fid=6045]
	5.45607 [https://something.org/]
	5.46996 [https://something.org/icons.xml?icon%5Fcategory%5Fid=6045]
	6.49698 [https://something.org/icons.xml?icon%5Fcategory%5Fid=6045]
	8.88170 [https://something.org/operations/3/operation_hierarchy/add_subordinate]
	9.01287 [https://something.org/operations/1/operation_hierarchy/add_subordinate]
	9.36590 [https://something.org/operations/6/operation_hierarchy/add_subordinate]

view raw gistfile1.sh hosted with ❤ by GitHub

9 seconds! Ouch!

Of course you can get much more advanced in the command line department with tools like awk but at that point you might as well download rawk.rb and get back to work.