Amy R. Johnson

Troubleshooting Performance in Ruby, Part 1

During my fellowship at Stack Exchange I’ve been working on a photo mosaic application using Rails and RMagick, a wrapper on ImageMagick for Ruby. The application takes an uploaded image and a search term from the user and returns a mosaic of that image created from google image search results for the given term.

The main issue I ran into when working on this application was how slow it ran. From start to finish the process of creating the mosaic took several minutes, even for a small number of photo tiles. My mentor at Stack Exchange helped me come up with several strategies to tackle this issue and speed up the application.

The first step to improving the performance of the application was discovering exactly which processes were causing it to be slow. This would also provide a baseline performance metric to compare against once we implemented optimizations. In order to do this we added in some simple benchmarks. Before and after each process that was run, I printed out a system timestamp.

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
def make_mosaic(photo_length, photo_width, tile_length, tile_width)
    time1 = Time.now
    self.get_pixels(photo_length, photo_width)
    time2 = Time.now
    puts "getting pixels took #{time2 - time1}"
    s = Search.new(self.search)
    s.complete_search(tile_length, tile_width)
    time3 = Time.now
    puts "completing search took #{time3 - time2}"
    self.match_pixels(s.photo_tile_colors)
    time4 = Time.now
    puts "matching pixels with image tiles took #{time4 - time3}"
    self.order_tiles(s.resized_photo_tiles)
    time5 = Time.now
    puts "putting tiles in order took #{time5 - time4}"
    m = Mosaic.new
    puts "ordering photos for mosaic"
    photos = m.order_photos(self.ordered_tiles, self.rows, self.cols, tile_length, tile_width)
    puts "making mosaic"
    m.create_mosaic(photos)
    puts "making mosaic took #{Time.now - time5}"
    puts "total time: #{Time.now - time}""
end 

Although writing out the puts statements was time consuming, it gave me great readable output:

1
2
3
4
5
6
7
=> getting pixels took 0.983399
search took 71.075624
matching pixels with image tiles took 0.134034
putting tiles in order took 0.16947
ordering photos took 0.046765
making mosaic took 0.202503
total time 72.611871

Initially I’d thought that assembling the photos into a mosaic has been taking the longest amount of time, but from this initial output, I was able to pinpoint the source of the delay to the photo search function. From there I put further benchmarks into the search function to get more information.

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
def complete_search(tile_length, tile_width)
  time = Time.now
  self.get_pictures
  time2 = Time.now
  puts "Getting pictures took #{time2 - time}"
  self.resize_pictures(tile_length, tile_width)
  time3 = Time.now
  puts  "resizing pictures took #{time3 - time2}"
  self.average_color_list
  time4 = Time.now 
  puts "getting picture colors took #{time4 - time3}"

end

=> Getting pictures took 59.405176
resizing pictures took 9.876595
getting picture colors took 0.031038
search took 69.316089

By far the slowest operation was downloading the photos and reading them into memory. This was taking 59 seconds out of a total 72 seconds! Now that I had a clear idea of how long the process was taking and which part was the bottleneck, I could begin to optimize. In part two of this post, I’ll show you my next steps.