Permalink
Browse files

Initial commit

  • Loading branch information...
0 parents commit e8f23668760aa43f185e4a06972bb83d6e94efec @andyjeffries committed Aug 28, 2009
Showing with 686 additions and 0 deletions.
  1. +62 −0 README.textile
  2. +79 −0 access_log_grapher
  3. +67 −0 access_log_request_sizer
  4. +114 −0 caching_visualiser
  5. +126 −0 passenger_mon_grapher
  6. +150 −0 rails_log_analyser
  7. +44 −0 rb_linetime.d
  8. +44 −0 response_time_grapher
62 README.textile
@@ -0,0 +1,62 @@
+h1. Rails Log Analysis
+
+During some performance analysis for a client of a client ("LVS":http://www.lvs.co.uk/) I needed some tools to analyse Rails and Apache log files. The utilities in this repository are simply the current state of those tools, shared in case anyone finds them of interest.
+
+h2. Rails Log Analyser
+
+This is one of the best utilities! A Rails log often gets lines from different requests interleaved within each other, making it difficult to see what a particular request logged. This utility sorts this out. There are two ways of using this:
+
+ ./rails_log_analyser production.log -l
+
+Which will output for each request: an id, the Controller/Action, the time taken and the status code. You can then view the log output for one or more of these requests with:
+
+ ./rails_log_analyser production.log -s 243 1012
+
+Where the numbers are the ids are the ids given in the -l output.
+
+h2. Passenger DTrace script
+
+This dtrace script prints out a summary of times spent in each method, sorted by total time with a file and count. The way I use it is to do the following (from a Rails application):
+
+touch tmp/restart.txt
+curl http://my-local-domain/controller/action
+sudo passenger-status
+(find out passenger pid)
+sudo dtrace -s rb_linetime.d -p $pid > log
+
+Then in another window do:
+
+curl http://my-local-domain/controller/action
+
+Then Ctrl-C the dtrace window when it finishes. Up until now I've been "grep -v"ing Ruby.framework, vendor/rails, (eval), gems to just try to get to the main code. I know there will be bits where we call a standard Ruby method far too many times, or likely the same in the Rails framework, but for now I'm concentrating on the big hitters so this serves me well.
+
+h2. Access Log Request Sizer
+
+This utility is simply run with the name of an Apache log file (in common format) after it and it will print out the top 20 URLs based on the size of the request:
+
+ ./access_log_request_sizer access.log_20090825
+
+h2. Access Log Grapher
+
+Using a log format like the following:
+
+ LogFormat "%v:%p %h %{X-Forward-For}i %l %u %t \"%r\" %>s %b \"%{Referer}i\" \"%{User-Agent}i\" %T/%D \"%{X-Runtime}o\"" passenger_combined
+
+This utility will produce a graph of Response times, using the "Gruff":http://nubyonrails.com/pages/gruff library, and open it using the 'open' command on your (Mac OS X) system.
+
+ ./access_log_grapher access.log_20090825
+
+h2. Caching Visualiser
+
+At LVS we have some Rails Middleware (not sure if I'm allowed to release that code or not as it's kinda core, so I won't) that does full page caching in memcached. I tweaked it while doing the performance analysis to log output using a prefix of CACHING_MIDDLEWARE. This utility analyses a Rails log and prints a constantly updating page of Passenger process IDs and what they are doing with the cache, reading, getting a lock to generate a cached page, generating the page and saving it to the cache. It goes lightning fast unless you alter the case statement within the display method to slow down certain line ranges.
+
+It works best if you fly through it and note where things start going crazy, then edit the script and slow down that region.
+
+ ./caching_visualiser production.log
+
+h2. Passenger Sampler Analyser
+
+This is really only an internal use tool (for the LVSers that visit this page). We have a script called sample.rb that we run in a sleeping while loop to sample things like Passenger children usage, load average, etc. This tool takes those stats and graphs them nicely, opening the result as per Access Log Grapher.
+
+ ./passenger_mon_grapher data.csv
+
79 access_log_grapher
@@ -0,0 +1,79 @@
+#!/usr/bin/env ruby
+
+require 'rubygems'
+require 'progressbar'
+require 'gruff'
+
+module Apache
+ module Log
+ class Entry
+ attr_accessor :method
+ attr_accessor :url
+ attr_accessor :status
+ attr_accessor :size
+ attr_accessor :time_sec
+ attr_accessor :time_usec
+ attr_accessor :time_passenger
+
+ def initialize(params)
+ params.each do |k,v|
+ self.send("#{k}=", v)
+ end
+ end
+ end
+
+ class List
+ attr_reader :items
+
+ def initialize
+ @items = []
+ end
+
+ def read(filename)
+ lines = `wc -l #{filename}`.to_i
+ pbar = ProgressBar.new("Analysing", lines)
+
+ File.open(filename, 'r').each do |line|
+ if line =~ /"(GET|POST) ([^ ]+).*?" (\d+) (\d+) .*? (\d+)\/(\d+) "(\d+)"/
+ entry = Entry.new(:method => $1, :url => $2, :status => $3, :size => $4, :time_sec => $5, :time_usec => $6, :time_passenger => $7)
+ @items << entry
+ end
+ pbar.inc
+ end
+ pbar.finish
+ end
+
+ def to_url_size_hash
+ hash = {}
+ @items.each do |item|
+ if hash[item.url].nil? || hash[item.url].to_i < item.size.to_i
+ hash[item.url] = item.size.to_i
+ end
+ end
+ hash
+ end
+
+ def top_size(number)
+ items = to_url_size_hash
+ items.sort {|a,b| a[1] <=> b[1]}.reverse[0..number]
+ end
+
+ end
+ end
+end
+
+#--------------------------------------------------------------------------------
+
+filename = ARGV[0]
+list = Apache::Log::List.new
+list.read(filename)
+
+g = Gruff::Line.new(800)
+g.title = "Response times"
+g.data("Time/ms", list.items.collect {|e| (e.time_usec.to_i/1000).to_i } )
+#g.labels = {0 => '2003', 2 => '2004', 4 => '2005'}
+g.write('response_times.png')
+g.hide_lines = true
+g.write('response_times_no_lines.png')
+
+`open *.png`
67 access_log_request_sizer
@@ -0,0 +1,67 @@
+#!/usr/bin/env ruby
+
+require 'pp'
+
+module Apache
+ module Log
+ class Entry
+ attr_accessor :method
+ attr_accessor :url
+ attr_accessor :status
+ attr_accessor :size
+
+ def initialize(params)
+ params.each do |k,v|
+ self.send("#{k}=", v)
+ end
+ end
+ end
+
+ class List
+ def initialize
+ @items = []
+ end
+
+ def read(filename)
+ File.open(filename, 'r').each do |line|
+ if line =~ /"(GET|POST) ([^ ]+).*?" (\d+) (\d+)/
+ entry = Entry.new(:method => $1, :url => $2, :status => $3, :size => $4)
+ @items << entry
+ end
+ end
+ end
+
+ def to_url_size_hash
+ hash = {}
+ @items.each do |item|
+ if hash[item.url].nil? || hash[item.url].to_i < item.size.to_i
+ hash[item.url] = item.size.to_i
+ end
+ end
+ hash
+ end
+
+ def top_size(number)
+ items = to_url_size_hash
+ items.sort {|a,b| a[1] <=> b[1]}.reverse[0..number]
+ end
+
+ end
+ end
+end
+
+#--------------------------------------------------------------------------------
+
+filename = ARGV[0]
+list = Apache::Log::List.new
+list.read(filename)
+
+top_10 = list.top_size(100)
+puts "Top 10 URLs by size".upcase
+puts
+puts "%-40s %19s" % ["URL", "Size/B"]
+puts "-" * 60
+top_10.each do |url,size|
+ puts "%-40s %19s" % [url, size.to_s]
+end
+
114 caching_visualiser
@@ -0,0 +1,114 @@
+#!/usr/bin/env ruby
+
+class ANSI
+ def self.set_cursor(x=1, y=1)
+ puts "\033[1;#{x};#{y}H"
+ end
+
+ def self.clear_screen
+ puts "\033[1;2J"
+ end
+
+ def self.red(text)
+ "\033[31m#{text}\033[0m"
+ end
+
+ def self.blue(text)
+ "\033[34m#{text}\033[0m"
+ end
+
+ def self.green(text)
+ "\033[32m#{text}\033[0m"
+ end
+
+ def self.yellow(text)
+ "\033[33m#{text}\033[0m"
+ end
+end
+
+class ProcessStatus
+ attr_accessor :message
+ attr_accessor :url
+ attr_accessor :last_accessed
+
+ def initialize(message, url, position)
+ @message = message
+ @url = url
+ @last_accessed = position
+ end
+end
+
+class Visualiser
+ def initialize
+ @processes = {}
+ @time = ""
+ @position = 0
+ ANSI.clear_screen
+ end
+
+ def process_file(filename)
+ File.open(ARGV[0], "r").each do |line|
+ next unless line =~ /CACHING_MIDDLEWARE/
+ next if line =~ /Not cacheable/
+ parse_line(line)
+ @position += 1
+ display
+ end
+ end
+
+ def parse_line(line)
+ # [hpbl20050] [2009-08-21 14:06:03] [24040] [WARN] CACHING_MIDDLEWARE Using cached version [/sports/highlight_block]
+ if line =~ /\[.*?\] \[(.*?)\] \[(\d+)\] .*CACHING_MIDDLEWARE.*? (.*?) \[(.*?)\]/
+ @time = $1
+ status = @processes[$2]
+ if status
+ status.message = $3
+ status.url = $4
+ status.last_accessed = @position
+ else
+ status = ProcessStatus.new($3, $4, @position)
+ end
+ @processes[$2] = status
+ end
+ end
+
+ def display
+ ANSI.set_cursor
+ puts "#{@time} (#{@position})"
+
+ @processes.sort.each do |pid, status|
+ puts "%6s: %-60s %-20s %40s" % [pid, nice_status(status.message), status.url, " "*40]
+ end
+
+ @sleep = 0
+ case @position
+ when 34000..36500
+ @sleep = 0.4
+ when 36500..50000
+ @sleep = 0.4
+ end
+
+ sleep @sleep
+ reap_old_processes
+ end
+
+ def nice_status(status)
+ if status =~ /lock/
+ ANSI.red(status)
+ elsif status =~ /generating/
+ ANSI.yellow(status)
+ elsif status =~ /seconds/
+ ANSI.green(status)
+ else
+ status
+ end
+ end
+
+ def reap_old_processes
+ @processes.delete_if do |pid, status|
+ status.last_accessed < @position - 500
+ end
+ end
+end
+
+Visualiser.new.process_file(ARGV[0])
126 passenger_mon_grapher
@@ -0,0 +1,126 @@
+#!/usr/bin/env ruby
+
+require 'rubygems'
+require 'progressbar'
+require 'gruff'
+
+module FDJ
+ module Monitor
+ class Entry
+ attr_accessor :date
+ attr_accessor :passenger_children
+ attr_accessor :passenger_max
+ attr_accessor :passenger_active
+ attr_accessor :passenger_inactive
+ attr_accessor :passenger_queue
+ attr_accessor :mem_used
+ attr_accessor :load_average
+ attr_accessor :io
+ attr_accessor :memcached_current
+ attr_accessor :memcached_max
+
+ def initialize(params)
+ self.date = params.shift
+ self.passenger_children = params.shift
+ self.passenger_max = params.shift
+ self.passenger_active = params.shift
+ self.passenger_inactive = params.shift
+ self.passenger_queue = params.shift
+ self.mem_used = params.shift
+ self.load_average = params.shift
+ self.io = params.shift
+ self.memcached_current = params.shift
+ self.memcached_max = params.shift
+ end
+ end
+
+ class List
+ attr_reader :items
+
+ def initialize
+ @items = []
+ end
+
+ def read(filename)
+ lines = `wc -l #{filename}`.to_i
+ pbar = ProgressBar.new("Analysing", lines)
+
+ first = true
+ File.open(filename, 'r').each do |line|
+ if first
+ first = false
+ next
+ end
+
+ @items << Entry.new(line.split(','))
+ pbar.inc
+ end
+ pbar.finish
+ end
+
+ def to_url_size_hash
+ hash = {}
+ @items.each do |item|
+ if hash[item.url].nil? || hash[item.url].to_i < item.size.to_i
+ hash[item.url] = item.size.to_i
+ end
+ end
+ hash
+ end
+
+ def top_size(number)
+ items = to_url_size_hash
+ items.sort {|a,b| a[1] <=> b[1]}.reverse[0..number]
+ end
+
+ end
+ end
+end
+
+#--------------------------------------------------------------------------------
+
+filename = ARGV[0]
+list = FDJ::Monitor::List.new
+list.read(filename)
+
+g = Gruff::Line.new(800)
+g.title = "Passenger Children"
+g.data("Max", list.items.collect {|e| e.passenger_max.to_i } )
+g.data("Current", list.items.collect {|e| e.passenger_children.to_i } )
+g.data("Active", list.items.collect {|e| e.passenger_active.to_i } )
+g.data("Inactive", list.items.collect {|e| e.passenger_inactive.to_i } )
+g.write('passenger_children.png')
+
+g = Gruff::Line.new(800)
+g.title = "Load Average"
+g.data("Load", list.items.collect {|e| (e.load_average).to_f } )
+g.write('load_average.png')
+
+g = Gruff::Line.new(800)
+g.title = "Active Children and Load"
+g.data("Active Children", list.items.collect {|e| (e.passenger_active).to_f } )
+g.data("Load", list.items.collect {|e| (e.load_average).to_f } )
+g.write('active_and_load.png')
+
+g = Gruff::Line.new(800)
+g.title = "Passenger Queue Size"
+g.data("Queu", list.items.collect {|e| e.passenger_queue.to_i } )
+g.write('passenger_queue.png')
+
+g = Gruff::Line.new(800)
+g.title = "Memory Usage"
+g.data("Mb", list.items.collect {|e| (e.mem_used.to_i/1024).to_i } )
+g.write('memory_usage.png')
+
+g = Gruff::Line.new(800)
+g.title = "Memcached Memory"
+g.data("Current", list.items.collect {|e| e.memcached_current.to_i } )
+g.data("Max", list.items.collect {|e| e.memcached_max.to_i } )
+g.write('memcached_memory.png')
+
+g = Gruff::Line.new(800)
+g.title = "IO Throughput"
+g.data("IO MB/s", list.items.collect {|e| (e.io).to_f } )
+g.write('io_throughput.png')
+
+`open *.png`
150 rails_log_analyser
@@ -0,0 +1,150 @@
+#!/usr/bin/env ruby
+
+require 'pp'
+require 'rubygems'
+require 'progressbar'
+
+module Rails
+ module LogAnalyser
+ class Entry
+ attr_accessor :process_id
+ attr_accessor :action
+ attr_accessor :status
+ attr_accessor :messages
+ attr_accessor :time
+ attr_accessor :time_spent
+
+ def initialize(process_id, action, time)
+ self.process_id = process_id
+ self.action = action
+ self.time = time
+ self.messages = []
+ end
+
+ def <<(message)
+ self.messages << message
+ end
+ end
+
+ class List
+ attr_accessor :transactions
+
+ def initialize
+ @current_transactions = {}
+ @transactions = []
+ end
+
+ def start_transaction(process_id, action, time, message)
+ complete_transaction(process_id)
+ @current_transactions[process_id] = Rails::LogAnalyser::Entry.new(process_id, action, time)
+ continue_transaction(process_id, message, message)
+ end
+
+ def continue_transaction(process_id, message, line)
+ if !process_id
+ process_id = @last_process_id
+ else
+ @last_process_id = process_id
+ end
+ if message =~ /Completed in (\d+)ms/ && @current_transactions[process_id]
+ @current_transactions[process_id].time_spent = $1.to_i
+ message =~ /.*?\|\s+(\d+)/
+ @current_transactions[process_id].status = $1
+ elsif message =~ /Rendering .* \((\d+)\)/
+ @current_transactions[process_id].status = $1
+ elsif message.nil?
+ @current_transactions[process_id] << line if @current_transactions[process_id]
+ else
+ @current_transactions[process_id] << message if @current_transactions[process_id]
+ end
+ end
+
+ def complete_transaction(process_id)
+ @transactions << @current_transactions[process_id] if @current_transactions[process_id]
+ @current_transactions[process_id] = nil
+ end
+
+ def complete_all_transactions
+ @current_transactions.keys.each do |process_id|
+ complete_transaction(process_id)
+ end
+ end
+
+ def read(filename)
+ lines = `wc -l #{filename}`.to_i
+ pbar = ProgressBar.new("Analysing", lines)
+
+ next_line_is_process_marker = false
+ action = ""
+ time = ""
+
+ File.open(filename, 'r').each do |line|
+ pbar.inc
+ process_id = nil
+ message = nil
+ if line =~ /\[(\d+)\] (.*)/
+ process_id = $1
+ message = $2
+ end
+
+ if next_line_is_process_marker
+ start_transaction(process_id, action, time, message)
+ next_line_is_process_marker = false
+ elsif line =~ /Processing ([^ ]+).*\(.*at ([0-9 :-]+)\)/
+ action = $1
+ time = $2
+ next_line_is_process_marker = true
+ else
+ continue_transaction(process_id, message, line)
+ end
+ end
+ complete_all_transactions
+ pbar.finish
+ end
+
+ end
+ end
+end
+
+#--------------------------------------------------------------------------------
+
+filename = ARGV[0]
+log = Rails::LogAnalyser::List.new
+log.read(filename)
+
+# List transactions
+# -l
+#
+# Show transaction
+# -s
+
+if ARGV[1] == '-l'
+ log.transactions.each_with_index do |tran, index|
+ puts "%4d : %-40s %14s (%dms %d)" % [index, tran.action, tran.time, tran.time_spent, tran.status]
+ end
+elsif ARGV[1] == '-ls'
+ log.transactions.sort {|a,b| a.time.gsub('ms', '').to_i <=> b.time.gsub('ms', '').to_i}.each do |tran, index|
+ puts "%4d : %-40s %14s (%dms)" % [index, tran.action, tran.time, tran.time_spent]
+ end
+elsif ARGV[1] == '-s'
+ ids = ARGV[2..10000].map {|x| x.to_i}
+ ids.each do |transaction_id|
+ tran = log.transactions[transaction_id]
+ puts "%4d : %-40s %14s" % [transaction_id, tran.action, tran.time]
+ puts "-" * 62
+ puts tran.messages
+ puts
+ end
+end
+
+
+#
+# top_10 = list.top_size(100)
+# puts "Top 10 URLs by size".upcase
+# puts
+# puts "%-40s %19s" % ["URL", "Size/B"]
+# puts "-" * 60
+# top_10.each do |url,size|
+# puts "%-40s %19s" % [url, size.to_s]
+# end
+#
44 rb_linetime.d
@@ -0,0 +1,44 @@
+#pragma D option quiet
+
+this string str;
+
+dtrace:::BEGIN
+{
+ printf("Tracing... Hit Ctrl-C to end.\n");
+ depth = 0;
+}
+
+ruby$target:::function-entry
+{
+ self->depth++;
+ self->start[copyinstr(arg0), copyinstr(arg1), self->depth] = timestamp;
+}
+
+ruby$target:::function-return
+/(this->class = copyinstr(arg0)) != NULL && \
+ (this->func = copyinstr(arg1)) != NULL && \
+ self->start[this->class, this->func, self->depth]/
+{
+ this->elapsed = timestamp - self->start[this->class, this->func, self->depth];
+
+ this->file = copyinstr(arg2);
+ this->line = arg3;
+ @num[this->file, this->line] = count();
+ @eavg[this->file, this->line] = avg(this->elapsed);
+ @esum[this->file, this->line] = sum(this->elapsed);
+
+ self->start[this->class, this->func, self->depth] = 0;
+ self->depth--;
+}
+
+dtrace:::END
+{
+ normalize(@eavg, 1000);
+ normalize(@esum, 1000);
+ setopt("aggsortpos", "2");
+ printf("%-33s %123s\n", "___ OVERLAP TIMES: ___",
+ "______ ELAPSED _____");
+ printf("%-120s %5s %6s %10s %12s\n", "FILE", "LINE",
+ "COUNT", "AVG(us)", "SUM(us)");
+ printa("%-120.120s %5d %@6d %@10d %@12d\n", @num, @eavg, @esum);
+}
44 response_time_grapher
@@ -0,0 +1,44 @@
+#!/usr/bin/env ruby
+
+require 'rubygems'
+require 'progressbar'
+require 'gruff'
+
+module Apache
+ module Log
+ class List
+ attr_reader :items
+
+ def initialize
+ @items = []
+ end
+
+ def read(filename)
+ lines = `wc -l #{filename}`.to_i
+ pbar = ProgressBar.new("Analysing", lines)
+
+ `cat #{filename} | cut -d' ' -f 23|cut -d'/' -f 2`.each do |line|
+ @items << line.chomp.to_i
+ pbar.inc
+ end
+ pbar.finish
+ end
+ end
+ end
+end
+
+#--------------------------------------------------------------------------------
+
+filename = ARGV[0]
+list = Apache::Log::List.new
+list.read(filename)
+
+g = Gruff::Line.new(800)
+g.title = "Response times"
+g.data("Time/ms", list.items)
+#g.labels = {0 => '2003', 2 => '2004', 4 => '2005'}
+g.write('response_times.png')
+g.hide_lines = true
+g.write('response_times_no_lines.png')
+
+`open *.png`

0 comments on commit e8f2366

Please sign in to comment.