Tech Blog

After Rails moved to Rack as server interface, the ability the use Rack middleware was one of the most touted advantages. At first, it wasn’t very clear to me why this was such a big deal. However, I have applied Rack middleware in the last month on several occasions. I thought it might be interesting for other Rails developers to see some practical examples of middleware, to see where they can be applied.

Redirecting

After a complete rewrite, we released the new version of Floorplanner over a year ago. We had to find a way to deal with the thousands of links that were in use by our customers and indexed by Google.

Some of these could simply redirect to their new location, e.g. http://www.floorplanner.com/tryit can now be found on http://www.floorplanner.com/demo. These redirects can of course simply be implemented in either Rails or Apache.

However, we also had a long list of URLs on which floor plans were published using the old version. These plans cannot be migrated to the new version easily, so we had to keep an instance of the old Rails application running. Requests to these URLs should be redirected to this separate instance, now hosted on a different domain name. Moreover, it is important that it only tries to redirect to the old version if the URL cannot be resolved in the new version, because the plan may have been migrated to or recreated on the new version.

We previously implemented this by adding a catch all route to our application, and a custom handler for the ActiveRecord::RecordNotFound exception in our application. This was a rather ugly solution, and we rather not have a dependency on the old version’s database in the new version’s code.

I decided to rewrite this functionality with a piece of Rack middleware. It basically executes every request with our Rails application, and if it returns a 404 response, it checks if the URL exists on the old version. If so, it redirects the user to the old version, otherwise, it will respond with the 404 response that was generated by Rails.

class RedirectToOldVersionMiddleware
  def initialize(app)
    @app = app
  end
 
  def call(env)
    # execute the request using our Rails app
   status, headers, body = @app.call(env)
 
    if status == 404 && url = find_redirect(env['REQUEST_URI'])
 
      # Issue a "Moved permanently" response with the redirect location
      [301, {"Location" => url}, 'Redirecting you to the new location...']
    else
 
      # Not a 404 or no redirect found, just send the response as is
      [status, headers, body]
    end
  end
 
  REDIRECT_HOST = 'http://old.floorplanner.version'
 
  def find_redirect(path)
    # See if we can find a valid URL on the old version.
    Redirect.exists?(path) ? "#{REDIRECT_HOST}#{path}" : nil
  end
end

This way, all the code that is related to redirecting users to the old version is contained in a single file, and doesn’t pollute our application anymore. Moreover, when all the old plans are migrated, or we decide we do not longer support these old plans, we can simply disable the middleware in our environment.rb, without having to alter any code.

Logging complete requests for debugging purposes

Another use for Rack middleware is logging: one of our customers notified us that an API call they were using was failing, but only some of the time. Unfortunately, we did not find any errors in our exception log, which made it very hard to debug this issue. After some time, we discovered that Rails was returning a 422 response, without the request ever “arriving” in our own code. Apparently, the request was stopped from processing somewhere in the Rails framework.

Unfortunately, we were not able to recreate this issue ourselves, and we started suspecting that the request was not well-formed, because Rails sends a 422 response in this case. To discover if this really was the issue, I wrote a piece of middleware that logs the complete request, before it is passed to the Rails framework for further processing.

class RequestLoggerMiddleware
  def initialize(app)
    @app = app
  end
 
  REQUEST_LOG_DIR = Rails.root.join('log', 'api_calls')
 
  def call(env)
    # log the request if it is a troublesome API call.
    if env['REQUEST_URI'] == '/failing_api.xml'
 
      filename = "api_call_#{Time.now.strftime('%Y%m%d%H%M%S')}.log"
      File.open(REQUEST_LOG_DIR.join(filename), 'wb') do |file|
        file.puts(env['rack.input'].read)
      end      
    end
 
    # now, execute the request using our Rails app
    response = @app.call(env)
  end
end

Using these request log files, API calls can be inspected exactly before any of the Rails magic happens. After resolving the issue, removing this logging was as simple as commenting a line in environment.rb.

Remember my last post, where I representing a pixel with a Fixnum, storing the R, G, B and A value in its 4 bytes of memory? Well, I have been working some more on my PNG library and I am now trying loading and saving an image.

Using the PNG specification, building a PNG encoder/decoder isn’t that hard, but the required algorithmic calculations make sure that performance in Ruby is less than stellar. I have rewritten all calculations to only use fast integer math (plus, minus, multiply and bitwise operators), but simply the amount of code that is getting executed is slowing Ruby down. What more can I do to improve the performance?

Encoding RGBA images

Optimizing loading images is very hard, because PNG images can have many variations, and taking shortcuts means that some images are no longer supported. Not so with saving images: as long an image is saved using one of the valid variations, every PNG decoder will be able to read the file. Let’s see if it is possible to optimize one of these encoding variations.

During encoding, the image get splits up into scanlines (rows) of pixels, which in turn get converted into bytes. These bytes can be filtered for optimal compression. For a 3×3 8-bit RGBA image, the result looks like this:

F Rf Gf Bf Af Rf Gf Bf Af Rf Gf Bf Af
F Rf Gf Bf Af Rf Gf Bf Af Rf Gf Bf Af
F Rf Gf Bf Af Rf Gf Bf Af Rf Gf Bf Af

Every line starts with a byte F indicating the filter method, followed by the filtered R, G and B value for every pixel on that line. Now, if we choose filter method 0, which means no filtering, the result looks like this:

0 Ro Go Bo Ao Ro Go Bo Ao Ro Go Bo Ao
0 Ro Go Bo Ao Ro Go Bo Ao Ro Go Bo Ao
0 Ro Go Bo Ao Ro Go Bo Ao Ro Go Bo Ao

Now, the original R, G, B and A byte from the original pixel’s Fixnum, occur in big-endian or network byte order, starting with the top left pixel, moving left to right and then top to bottom. Exactly like the pixels are stored in our image’s pixel array! This means that we can use the Array#pack method to encode into this format. The Array#pack-notation for this is "xN3" in which x get translated into a null byte, and every N as 4-byte integer in network byte order. For optimal performance, it is best to not split the original array in lines, but to pack the complete pixel array at once. So, we can encode all pixels with this command:

pixeldata = pixels.pack("xN#{width}" * height)

This way, the splitting the image into lines, splitting the pixels into bytes, and filtering the bytes can be skipped. In Ruby 1.8.7, this means a speedup of over 1500% (no typo)! Of course, because no filtering applied, the subsequent compression is not optimal, but that is a tradeoff that I am willing to make.

Encoding RGB images

What about RGB images without alpha channel? We can simply choose to encode these using the RGBA method, but that increases the file size with roughly 25%. Can we fix this somehow?

The unfiltered pixel data should look something like this:

0 Ro Go Bo Ro Go Bo Ro Go Bo
0 Ro Go Bo Ro Go Bo Ro Go Bo
0 Ro Go Bo Ro Go Bo Ro Go Bo

This means that for every pixel that is encoded as a 4-byte integer, the last byte should be ditched. Luckily, the Array#pack method offers a modifier that does just that: X. Packing a 3 pixel line can be done with "xNXNXNX". Again we would like to pack the whole pixel array at once:

pixeldata = pixels.pack(("x" + ('NX' * width)) * height)

Because all the encoding steps can get skipped once again, the speed improvement is again 1500%! And the result is 25% smaller than the RGBA method. This method is actually so speedy, that saving an image using Ruby 1.9.1 is only a little bit slower (< 10%) than saving a PNG image using RMagick! See my performance comparison.

Loading images

Given the promising results of the Array#pack method, using its counterpart String#unpack looks promising for speedy image loading, if you know the image’s size and the encoding format beforehand.

An RGBA formatted stream can be loaded quickly with this command:

pixels = rgba_pixeldata.unpack("N#{width * height}")
image = Image.new(width, height, pixels)

For an RGB formatted stream, we can use the X modifier again, but we have to make sure to set the alpha value for every pixel to 255:

pixels = rgb_pixeldata.unpack("NX" * (width * height))
pixels.map! { |pixel| pixel | 0x000000ff }
image = Image.new(width, height, pixels)

You can even use little-endian integers to load streams in ABGR format!

pixels = abgr_pixeldata.unpack("V#{width * height}")
image = Image.new(width, height, pixels)

Loading pixel data for an image like this is again over 1500% faster than decoding the same PNG image. However, this can only be applied if you have control over the input format of the image.

To conclude

Array#pack and String#unpack really have increased the performance for my code. If you can apply them for project, don’t hesitate and spread the love! For all other cases, use as little code as possible, and upgrade to Ruby 1.9 for improved algorithmic performance.

I have been spending some time creating a pure Ruby PNG library. For this library, I need to have some representation of the image, which is composed of RGB pixels, supporting an alpha channel. Because images can be composed of a lot of pixels, I want the implementation to be as memory efficient as possible. I also would like decent performance.

A very naive Ruby implementation for an image represents the red, green, blue and alpha channel using a floating point number between 0.0 and 1.0, and might look something like this:

class Pixel
  attr_reader :r, :g, :b, :a
 
  def initialize(r, g, b, a = 1.0)
    @r, @g, @b, @a = r, g, b, a
  end
end
 
class Image
  attr_reader :width, :height
 
  def initialize(width, height)
    @width, @height = width, height
    @pixels = Array.new(width * height)
  end
 
  def [](x,y)
    @pixels[y * width + x]
  end
 
  def []=(x,y, pixel)
    @pixels[y * width + x] = pixel
  end
end

For a 10×10 image, this representation requires 4 times 100 floating point numbers, which require 8 bytes each. That’s already over 3kB for such a small image just for the floating point numbers! Ouch.

A simple improvement is to decide that 8-bit color depth is enough in the case, in which case each channel can be represented by an integer between 0 and 255. Storing such a number only costs one byte of memory. Ruby’s Fixnum class typically uses 4-byte integers. If only the 4 channels of one byte each could be combined into a single Fixnum instance… Behold!

class Pixel
  attr_reader :value
  alias :to_i :value
 
  def initialize(value)
    @value = value
  end
 
  def self.rgba(r, g, b, a = 255)
    self.new(r << 24 | g << 16 | b << 8 | a)
  end
 
  def r; (@value & 0xff000000) >> 24; end
  def g; (@value & 0x00ff0000) >> 16; end
  def b; (@value & 0x0000ff00) >>  8; end
  def a; (@value & 0x000000ff); end
end

Notice the bit operations, which are extremely fast. This only requires 100 times 4 bytes = 400 bytes for storing the RGBA values for a 10×10 image, an 8 times improvement!

This implementation wraps every pixel inside an object. This is nice, because I want to access the separate channels of every pixel easily using the r, g, b, and a methods, and every other method that is defined for every pixel. However, a Ruby object instance has an overhead of at least 20 bytes. That’s 20 times 100 is about 2kB for our 10×10 image!

To get rid of the object overhead, it is possible to simply store the Fixnum value for every pixel, and only wrapping it inside a Pixel object when it is accessed. This can be done by modifying the Image class:

class Image
  # ...
 
  def [](x,y)
    Pixel.new(@pixels[y * width + x]) # wrap
  end
 
  def []=(x,y, pixel)
    @pixels[y * width + x] = pixel.to_i # unwrap
  end
end

As you can see, some simply changes in the representation can really make a difference in the memory usage. Can this representation be improved further?

Integer math calculations

Because we are now using integers to represent a pixel, this can cause problems when the math requires you to use floating point numbers. For example, the formula for alpha composition of two pixels is as follows:

in which C_a is the color component of the foreground pixel, α_a the alpha channel of the foreground pixel, C_b and α_b the same values for the background pixel, all of which should be values between 0 and 1.

A naive implementation could convert the integer numbers to their floating point equivalents:

def compose(fg, bg)
  return bg if fg.a == 0
  return fg if fg.a == 255
 
  fg_alpha = fg.a / 255.0
  bg_alpha = fg.a / 255.0
  alpha_complement = (1.0 - fg_alpha) * bg_alpha
 
  new_r = (fg_alpha * fg.r + alpha_complement * bg.r).round
  new_g = (fg_alpha * fg.g + alpha_complement * bg.g).round
  new_b = (fg_alpha * fg.b + alpha_complement * bg.b).round
  new_a = ((fg_alpha + alpha_complement) * 255).round
 
  Pixel.rgba(new_r, new_g, new_b, new_a)
end

This implementation is already a little bit optimized: no unnecessary conversions and calculations are being performed. However, this composition can be done a lot quicker after realizing that 255 is almost a power of two, in which computers excel because it can use bitwise operators and shifting for some calculations.

My new approach uses a quicker implementation of multiplication of 8-bit integers that represent floating numbers between 0 and 1:

def compose(fg, bg)
  return bg if fg.a == 0
  return fg if fg.a == 255
 
  alpha_complement = multiply(255 - fg.a, bg.a)
  new_r = multiply(fg.a, fg.r) + multiply(alpha_complement, bg.r)
  new_g = multiply(fg.a, fg.g) + multiply(alpha_complement, bg.g)
  new_b = multiply(fg.a, fg.b) + multiply(alpha_complement, bg.b)
  new_a = fg.a + alpha_complement
 
  Pixel.rgba(new_r, new_g, new_b, new_a)
end
 
# Quicker alternative for (a * b / 255.0).round
def multiply(a, b)
  t = a * b + 0x80
  ((t >> 8) + t) >> 8
end

Not that the new implementation is less precise in theory, but this precision is lost anyway because we have to convert the values back to 8 bit RGBA values. Your thoughts?

Bart & I just released request-log-analyzer 1.6.0. New features since the 1.5.0 release:

• PostgreSQL query log support;
• Delayed::Job log support;
• Small fixes in the Rails file format;
• Various other small fixes and improvements.

As always, run the following command to install or upgrade to the latest version:

sudo gem install request-log-analyzer

The Floorplanner API uses XML-formatted requests and responses, so our servers process a lot of XML. In Rails, most XML parsing is done using the Hash.from_xml method. This method allows for different backends, but the current backends are either slow or buggy. I decided to fix this situation myself.

I fixed bugs in the current libxml and nokogiri backends, and I added some new SAX-based backends for additional performance. My patches are already accepted by the Rails team, so everybody will enjoy fast and bug-free XML parsing in Rails 2.3.6 and eventually in Rails 3!

Performance

I have benchmarked the new backends using an 1.8 MB XML file. The REXML, LibXML and Nokogiri backends currently ship with Rails, but are horribly slow or are buggy. The ++ variants are my improved versions of these backends, and the SAX variants are completely written from scratch using a SAX-based parser.

                  user     system      total        real
REXML        17.170000   0.060000  17.230000 ( 17.297263)
LibXML        2.100000   0.100000   2.200000 (  2.217380)
LibXML++      0.530000   0.000000   0.530000 (  0.531034)
LibXMLSAX     0.630000   0.010000   0.640000 (  0.632472)
Nokogiri      5.280000   0.020000   5.300000 (  5.322575)
Nokogiri++    1.840000   0.020000   1.860000 (  1.872055)
NokogiriSAX   0.770000   0.000000   0.770000 (  0.778777)

As you can see, LibXML++ is the fastest backend, but NokogiriSAX comes close if you want to stick to Nokogiri.

No patience?

Don’t want to wait for the next Rails version for this speed up? You don’t have to: just put the appropriate backend file in the /lib/active_support/xml_mini/ folder of your Rails project, and set your backend accordingly in your environment:

ActiveSupport::XmlMini.backend = 'NokogiriSAX'

Happy coding in 2010!

Bart and I just released request-log-analyzer version 1.5.0. New features include:

• MySQL slow query log format support to analyze what queries are slowing down your database.
• Format autodetection: with all those supported file formats, remembering the right --format parameter gets tricky. With format autodetection, this usually is not needed anymore!

As always, run the following command to install or upgrade to the latest version:

$ gem install request-log-analyzer

Watch out when using validates_uniqueness_of :field, :case_sensitive => false. Rails transforms this in a query that cannot be supported by an index, which will really slow validation down if the underlying table grows larger.

For example, we use validates_uniqueness_of to check for duplicate e-mail addresses. Because email addresses are case-insensitive, adding :case_sensitive => false seems like a natural choice. However, this results in the following queries:

# For a new User instance:
SELECT id FROM users 
 WHERE LOWER(users.email) = BINARY 'user@example.com'
 
# For an existing User instance:
SELECT id FROM users 
 WHERE LOWER(users.email) = BINARY 'user@example.com' 
   AND users.id <> 42

This query cannot be optimized by a (unique) index on the email field and thus has to scan the full table. As our users table grew larger, these queries started to show up in our slow query log.

However, MySQL uses case-insensitive comparison by default. (To be exact, case-sensitiveness depends on the current collation, which can vary. Rails generates the weird query to make sure the check works, regardless of the current collation.) The conversion to lowercase therefore is not necessary for a uniqueness check (as long as the field has a case-insensitive collation like utf8_general_ci). I decided to write my own validation method that issues a query that can be optimized by a query.

  # Alternative for validates_uniqueness_of :email, :case_sensitive => false
  validate do |user|
    conditions = "users.email = :email"
    conditions << " AND users.id != :id" unless user.new_record?
    conditions = [conditions, { :email => user.email, :id => user.id }]
    if User.find(:first, :select => :id, :conditions => conditions)
      user.errors.add(:email, 'Already in use')
    end
  end

There is a ticket for this issue in Rails’s Lighthouse, but as of yet this issue is unresolved. For now, this solution works to keep our slow query log nice and quiet!

ParseTree is a very useful to gem that can translate Ruby code into a syntax tree. I recently needed to evaluate a static part of this tree to return the original hash it represented. I wrote a simple method called ParseTree.eval_static_tree for this purpose.

The method can only evaluate trees that have a static value composed of hashes, arrays, strings, symbols and numerics. You can however pass a block to the function that will be called for every dynamic part the method encounters (function calls, etc.)

A quick sample on how to use it:

code = '{ :static_array => ["str", 123, 4.5], :dynamic => method_call }'
tree = ParseTree.translate(code)
# => [:hash, [:lit, :static_array], [:array, [:str, "str"], 
#       [:lit, 123], [:lit, 4.5]], [:lit, :dynamic], [:vcall, :method_call]]
 
ParseTree.eval_static_tree(tree)
# => RuntimeError: tree is not static: :vcall ...
 
# Pass a block to simply return nil for every dynamic item in the tree.
ParseTree.eval_static_tree(tree) { |dynamic_subtree| nil }
# => {:dynamic=>nil, :static_array=>["str", 123, 4.5]}

Bart and I have been working a lot on request-log-analyzer lately, our tool to produce performance reports for web applications based on their log files. Today, we released version 1.4.0, which boasts many new features since I last blogged about a release. The changelog contains all changes we have implemented recently with some additional information, but these are the highlights:

• New and improved log formats: r-l-a can now handle Apache access logs, Rack CommonLogger logs and Amazon S3 access logs. Moreover, the Rails format has been restructured to offer more flexibility.
• Improved database support: the database supports other databases than SQLite3 as well, and r-l-a can append information to an existing database instead of overwriting it. Moreover, a console tool similar to Rails’s script/console is bundled to inspect the database and run queries on it easily.
• Added standard deviation to reports: the standard deviation measure has been added to duration and traffic reports to get some feel of the variation in values besides the mean.
• E-mailing reports: r-l-a can email the performance report to a given e-mail address. This can be useful when running r-l-a in a cron job.
• Compressed log support: r-l-a will decompress compressed logs automatically.
• Speed improvements: we have profiled request-log-analyzer itself and significantly improved its performance.
• API: we created a basic API so it is possible to use the r-l-a engine as a library as well.
• Monitoring integration: integrate performance information into your Munin dashboard or your Scout account.

As always, use sudo gem install request-log-analyzer to install or upgrade.

Ruby en Rails 2009 conference

Bart and I will be presenting request-log-analyzer and performance tuning of Rails applications in general at the Ruby en Rails conference in Amsterdam, October 30-31 2009. We hope to see you there!

Michel and I have been playing around with integrating Adyen payment services in Rails applications. We have assembled some of the pieces of code we have written, combined them, written specs for them and released the result as a gem. The package is also included on the Adyen support site.

Currently, the gem provides the following:

• Simple configuration and setup.
• Uses Adyen’s test or production environment based on your Rails environment.
• Generating hidden form fields for redirecting to Adyen for a payment.
• Calculating the signature to sign these redirects.
• Checking Adyen’s signature when the user gets redirected back.
• Matchers to easily test your payment forms using RSpec.
• Receiving and storing notifications from Adyen.
• Calling the Adyen SOAP services (requires the Handsoap gem).

Currently, not all SOAP services are implemented (because we didn’t need them all). It should be quite easy to implement them as well based on the other services that are implemented already. Don’t hesitate to submit patches!