Rails Log Parsing with Timber

Posted by Lance Ivy Fri, 23 Jul 2010 23:21:00 GMT

I’m needing to do more analysis of my production logs, and at every turn I see “requires Hodel 3000 Complaint blah blah”. But that’s not what I have—I have standard logs! And thanks to buffered logging, they are quite parseable as they are.

http://github.com/cainlevy/timber

This fresh plugin provides simple objects to parse a production log into requests and extract whatever data you need. By default it extracts controller, method, and request time. But if you have special data in your log files that you want to analyze, it’s quite easy to add.

For example, I want to use Oink to analyze which requests most frequently bloat my worker thread sizes. Here’s a snip that adds Oink parsing to the Request class:

module Timber
  module Plugins

    module Oink
      # create simple :pid attribute
      attr_reader :pid

      # create memory attribute, but return as integer
      def memory
        @_memory ||= @memory ? @memory.to_i : nil
      end
    end
  end

  # add to Request
  Request.class_eval {include Plugins::Oink}

  # add the regexp => vars pattern for the Oink log format
  Request::PATTERNS[/Memory usage: (\d+) \| PID: (\d+)/] = [:memory, :pid]
end

With that, I can rewrite the Oink log parser to offload the log parsing to Timber and simplify it down to its own reporting logic:

module Oink
  class MemoryUsageReporter < Base
    def print(output)
      output.puts "---- MEMORY THRESHOLD ----"
      output.puts "THRESHOLD: #{@threshold/1024} MB\n"
      output.puts "\n-- REQUESTS --\n" if @format == :verbose

      @inputs.each do |input|
        logfile = Timber::Log.new(input)
        while request = logfile.shift
          if pid = @pids[request.pid] and request.memory
            delta = request.memory - pid[:last_memory_reading]

            if delta > @threshold
              @bad_actions[request.action] ||= 0
              @bad_actions[request.action] += 1
              @bad_requests.push(OinkedMemoryRequest.new(request.action, request.time, request.lines, delta))

              if @format == :verbose
                request.lines.each { |b| output.puts b }
                output.puts "---------------------------------------------------------------------"
              end
            end

          else
            @pids[request.pid] = {:last_memory_reading => request.memory}
          end
        end
      end

      print_summary(output)
    end
  end
end

Comments

  1. Avatar
    Stanley 10 days later:

    Lance, you should open up comments for your older posts.

    RE: your unicorn post, thanks for the write up.. any chance you could share your Capistrano recipe for unicorn?

  2. Avatar
    Lance 10 days later:

    Hi Stanley—I actually haven’t used Capistrano with Unicorn. By the time I switched to Unicorn, I had also switched to chef-deploy on EY Cloud.