filter strace logs for an epoll em reactor to find latency

em-strace-filter.rb

#!/usr/bin/env ruby
#
# Use to filter strace output associated with ruby/EM processes running with EM.epoll
#   sudo strace -ttTp <ruby process pid> -o ruby.strace
#   cat ruby.strace | ./em-strace-filter.rb > filtered.strace
#
require 'time'

begin_time = nil
end_time = nil

prev_timestamp = nil
last_time = nil
last_lines = []
last_times = []

latent_num = 0
latent_time = 0
latent_sys = 0

long_num = 0
long_time = 0

gaps_num = 0
gaps_time = 0
cur_gaps = 0

while line = gets
  line.strip!
  if line =~ /<([.0-9]+?)>$/
    timestamp = Time.parse(line.split(' ').first)
    time = $1.to_f

    begin_time ||= timestamp
    end_time = timestamp

    if line !~ /epoll_wait/ and time > 0.1
      line += " <<<<<<=========== LONG"
      long_num += 1
      long_time += time
    end

    if prev_timestamp and timestamp-prev_timestamp > 0.1
      gap = timestamp-prev_timestamp
      last_lines << "=============>>>>>> GAP: #{gap} seconds"
      gaps_num += 1
      gaps_time += gap
      cur_gaps += gap
    end
    prev_timestamp = timestamp+time

    if line =~ /epoll_wait/
      if last_time and timestamp-last_time > 0.24
        syscall = last_times.inject(0){|sum,n| sum+n}

        puts last_lines.join("\n")
        puts
        puts "[#{timestamp - last_time} second reactor latency, #{syscall} in syscalls, #{cur_gaps} in gaps]"
        puts "--------------------"
        puts

        latent_num += 1
        latent_time += timestamp-last_time
        latent_sys += syscall
      end

      cur_gaps = 0
      last_time = timestamp+time
      last_lines = []
      last_times = []
    end

    last_times << time unless line =~ /epoll_wait/
  end

  last_lines << line
end

while end_time < begin_time
  end_time += 3600*24
end

puts
puts "#{end_time - begin_time} seconds of data collected"
puts "#{latent_num} latent for a total of #{latent_time} seconds (#{latent_sys} in syscalls)"
puts "#{long_num} long for a total of #{long_time} seconds"
puts "#{gaps_num} gaps for a total of #{gaps_time} seconds"