Real time memory profiling Ruby on Rails application using: Rails.logger, tail, awk and asciigraph

memory_profiling_ruby_on_rails.md

1. Search a place in the code to put a logger line. It can be:

# home_controller
# ...
def index
  # ...
  Rails.logger.info "BEFORE_PRIMARY_LOCATION_RSS PID |#{$$}| is: " + `ps -o rss -p #{$$}`.chomp.split("\n").last
  # ...
end
# ...

BEFORE_PRIMARY_LOCATION_RSS: is a tag you can use to grep later on. PID |#{$$}|: It is meant to print the PID of the process, just in case you want to compare the PID later on, maybe your Rails app is running sub process?. In Ruby, $$ is a special variable that contains the PID of the current ruby process

The final string inside the backticks is the interesting part. It calls a system program that will return its output. This: ps -o rss -p #{$$} will call ps and ask the RSS (Resident Set Size) of the current process (it interpolates $$ ruby variable). Unit of measure is kilobytes. I borrowed this command from this excelent article

2. Tail follow log/development.log, pipe the output to awk, use awk to grep the log line with the RSS value and filter the RSS value and pipe it to asciigraph

In another terminal, run this chain of commands:

tail log/development.log -f -n 1000 | mawk -W interactive '/RSS/ {print $5}' | asciigraph -r -h 10 -w 40 -c "RSS"

• tail log/development.log -f -n 1000: It will use tail to output the last 1000 lines of the rails development log (with -n 1000 argument), but the process will not finish with the -f flag. That flag will output more lines when more lines are added to the development log.
• mawk -W interactive '/RSS/ {print $5}':

  • mawk is an awk implementation that lets you use -W interactive argument. If you change the line above and replace mawk by awk AND remove the -W interactive argument ('cos awk will crash with that argument), it won't work properly. Because on the middle of the chain of piped arguments awk will use a buffer and will wait until it gets X lines to send the output to the next piped command. It won't work in real time :(

  • /RSS/ is the regular expression, so mawk will take the input coming from tail and will filter only the lines that match RSS. You can tweak this regex to match the complete tag /BEFORE_PRIMARY_LOCATION_RSS/ or another tag you may have written on your rails app.

  • {print $5}: it will print the fifth element of the matched line. On the example written on this gist, the fifth element (counted by space separation) is the RSS value.

• asciigraph is a program written in GO language, -r is a flag to toggle real time. This way the program will stay running receiving input. -h 10 sets the height of the graph to 10 rows. -w 40 sets the width of the graph to 40 columns. -c "RSS" sets the caption of the graph to RSS.