I have been working on request-log-analyzer quite a lot recently. One of the things I focused on was improving the parsing performance: because it parses log files that often are very big, processing times tend to be long. So all savings are very welcome.
Improving the performance of a command line application that does a lot of processing is very different from optimizing the performance of a web application. Request-log-analyzer basically reads a file line by line and processes it, so small performance improvements in the line processing algorithm can really add up when the file has a lot of lines. I used ruby-prof to get information about the performance of our algorithms split out by method to focus my tweaking efforts. I have written down some of my findings below; hopefully they can be helpful.
Parallelization
My first thought for improving performance was parallelization: parse multiple lines at the same time. Unfortunately, this did not yield the results I was hoping for: it instead become slower. Probably, this is because Ruby implements its own in-process threading and thus only uses one core of my processor.
Block overhead
The overhead of using a block should not be underestimated. Consider the following simple change, which improved the performance of request-log-analyzer by 1.5-2% on large log files:
# with block io.each_line { |line| process_line(line) } # without block process_line(line) while line = io.gets
Regular expressions
If you’re using complex regular expressions, and you do not expect that every string will match it successfully, it can be beneficial to test the string with a simpler regexp first. For example, request-log-analyzer uses a complex regexp to see if a line in a log file is a “Completed in…” line with the request duration in it:
# Check every line to see if it is a "completed" line and capture the values if line =~ /Completed in (\d+)ms \((?:View: (\d+), )?DB: (\d+)\) \| (\d\d\d).+\[(http.+)\]/ # do something with the captured values end
I improved this by first checking for a superficial regexp that tells me with 99% certainty that the complex regexp will match the line successfully as well:
if line =~ /Completed in/ if line =~ /Completed in (\d+)ms \((?:View: (\d+), )?DB: (\d+)\) \| (\d\d\d).+\[(http.+)\]/ # do something with the captured values else $stderr.puts "#{line.inspect} expected to match 'Completed' regexp!" end end
Depending on the log file, this can increase performance by ~3%. Another benefit of this approach is that it will give feedback on lines that matched the simple regexp, but not the complex one. This information can be used to correct the regular expressions.
Calculate things that do not change only once
Calculate things that do not change only once is easier said than done. For instance, request-log analyzer can aggregate durations in a category. A category can be based on a request field that is parsed from the log, or a Proc that calculates it:
# during parsing: if categorizer.respond_to?(:call) category = categorizer.call(request) else category = request[categorizer] end categories[category].aggregate_request(request)
With this implementation, categorizer will be checked to be a Proc for every request, but as the value of categorizer will not change, the result of the check will be constant as well. I solved this my making sure that it is always a Proc beforehand, so the check is no longer necessary during parsing:
# before parsing: if categorizer.respond_to?(:call) categorizer_proc = categorizer else categorizer_proc = lambda { |request| request[categorizer] } end # during parsing: category = categorizer_proc.call(request) categories[category].aggregate_request(request)
Performance gain: ~1%! And because on several instances a similar technique could be applied, the performance got improved by about 4% in total.
Check the most common case first
Consider the following example, which converts a number in any traffic unit (kilobytes, MB, etc) to bytes:
def convert_traffic(value, unit) case unit when :GB, :G, :gigabyte then (value.to_f * 1000_000_000).round when :MB, :M, :megabyte then (value.to_f * 1000_000).round when :KB, :K, :kilobyte, :kB then (value.to_f * 1000).round # ... even more units here else value.to_i end end
In most cases, the value will simply given in bytes, which will be returned by the final else after all possibilities have been checked. This can be improved by checking for this possibility first:
# Converts traffic in any unit to bytes. def convert_traffic(value, unit) case unit when nil, :B, :byte then value.to_i when :GB, :G, :gigabyte then (value.to_f * 1000_000_000).round when :MB, :M, :megabyte then (value.to_f * 1000_000).round when :KB, :K, :kilobyte, :kB then (value.to_f * 1000).round # ... even more units here else raise "Unknown unit: #{unit.inspect}!" end end
Again this change adds up to a ~1% performance increase if this method is called very often.
These kinds of changes really improved the performance of request-log-analyzer by quite a bit, so upgrade to the latest version to get some of your valuable time back! 
Tags: algorithms, analysis, blocks, parallelization, performance, profiling, regular expressions, request-log-analyzer, ruby, ruby-prof
Tim Knip's profile
September 27th, 2009 at 9:25 pm
Nice article
Most of these apply to other programming languages as well, especially the “Check the most common case is first”, “Calculate things that do not change only once” and regex tips.
What you say about Ruby not using multiple cores in a multiprocessor system is true for versions of Ruby prior to 1.9, when it still used so called “Green Threads”. If you want multicore performance with Ruby 1.8, you can use processes instead (or upgrade to 1.9 and benefit from native threading support).
September 28th, 2009 at 11:14 am
I have tried the multithreaded variant of r-l-a with both Ruby 1.9.1 (source install) and JRuby (OSX package from website).
Ruby 1.9.1 does not make much difference, because all threads still block on IO operations. Of course, r-l-a does a lot of file-reading, so it needs to be rewritten using non-blocking IO to make a difference.
JRuby is actually a lot faster using the threaded approach, but is so much slower to begin with, that it is still slower than Ruby 1.8 in the end.
With the different approaches taken by the different interpreters, the different concurrency APIs that are available and the small speed gains to be made at this moment, I decided to not use threading for now.
Fortunately, the other tweaks did improve performance significantly, and they work with every Ruby version and interpreter.
September 30th, 2009 at 11:40 am
[...] improvements: we have profiled request-log-analyzer itself and significantly improved its [...]
October 5th, 2009 at 9:20 pm
Parallelization–one of my projects involves data normalization and aggregation where parsing and transforming fields in GBs of data is one of the primary tasks. We developed delineations in the data and in the work flow where forking proved to be a huge aid to processing speed.
Looking at a log file (for Rails anyway), it’s pretty easy to identify requests. They start with “Processing…” and have some empty lines between them. It would be pretty easy to fork processing on a per request basis. Assuming the organization of the rest of your processing wouldn’t result in huge RAM duplication (our processes are organized to minimize this).
I can see a workflow like: load log file, split into requests, iterate requests forking for each one, parse request, when all requests are parsed, main thread starts analysis (probably forking for each one), save results of each analysis to file, when all forks completed, read the file, stitch the results together for group analysis / presentation.
I have a cheesy test file to show you how to do the forking if you’re interested. I would expect it to speed up your processing quite a bit.
October 6th, 2009 at 8:11 am
Hey Greg,
What you suggest seems like an approach with potential as it uses processes instead of threads. I definitely going to try this out at some point when I have some more time available. Can you send me your test file (willem AT floorplanner DOR com)? And, if you have time to spare, please fork the project and try it out yourself
I do expect some problems though, all of which can probably be worked around. First of all: Rails log files are not always ordered correctly. R-l-a uses some heuristics to detect this, but this may not work when parsing is split out in different processes. Moreover, in production mode every request, every requests consists of about 6 lines. Is the overhead of forking not bigger than the gains that can be made? Interesting stuff to try out.
October 9th, 2009 at 7:04 pm
quick thoughts —
log file ordering: assuming each request is stored into a single array of hashes, my first reaction would be to build an index based on request time. I’d use a two-dimensional array [[time, position], [time, position]], then sort based on the time to give me an index into request data array. Even though there’s forked processes, the original process is the one storing the results and creating the index.
gains from forking: depending on how much work you’re doing for those 6 lines, the tradeoff does indeed need to be verified. But, you could also split the file by regex into requests, then send batches of requests to each fork. Send each fork 10, 50, 1000 requests or whatever.
code file is “in the mail”