SmallPayroll.ca was my first big Rails project, and looking back at some of the code, it shows. One of the first things I did was the timesheet. The form has 21 input fields per employee, then it has to go through the database and figure out if days have changed or deleted. So it’s doing a lot, and at the time I was trying to figure out how both Ruby and Rails worked, and the code ended up being a mess.

But I was OK with that. If I was to get anywhere with SmallPayroll, people had to submit a timesheet. They didn’t care if the server side code was efficient as long as it worked. And, as I was to find out, they didn’t seem to care if it was slow. In order to build the rest of the app I had to have a timesheet. So I left my ugly inefficient code in, along with the tests that exercised it, and got to building the rest of the application.

Between Rails Analyzer and New Relic I kept an eye on things. The timesheet did get worse as time passed. Now that SmallPayroll has become more successful and I can spend more time on it, I’ve come back to look at fixing this. But before I know if I’m doing a better job, I have to know how I’m doing now.

I found Advanced Performance Optimization of Rails Applications that had a neat trick to capture the queries generated by a test.

Put this in test_helper.rb:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26

module ActiveSupport
  class BufferedLogger
    attr_reader :tracked_queries
    def tracking=(val)
      @tracked_queries = []
      @tracking = val
    end
    def debug_with_tracking(message)
      @tracked_queries
      debug_without_tracking(message)
    end
    alias_method_chain :debug, :tracking
  end
end
class ActiveSupport::TestCase
  def track_queries(&block)
    RAILS_DEFAULT_LOGGER.tracking = true
    # Had to add this to get queries to be logged
    Rails.logger.level = ActiveSupport::BufferedLogger::DEBUG
    yield
    result = RAILS_DEFAULT_LOGGER.tracked_queries
    RAILS_DEFAULT_LOGGER.tracking = false
    Rails.logger.level = ActiveSupport::BufferedLogger::INFO
    result
  end
end

Then wrap your test inside a test_queries block:

1
2
3
4
5
6
7
8
9
10

def test_submit_timesheet
    visit "/timesheet?date=2011-07-10"
    10.upto(16) do |day|
      fill_in /.*_shift_REG_2011-07-#{day}_hours/, :with => 8
    end
    queries = track_queries do
      click_button "Update"
    end
    puts queries.inspect
  end

After that it was a matter of making a performance test, copying over some of my functional tests that represented a case I was trying to optimize, then doing some before/after.

Before
------
TimesheetTest#test_submit_timesheet (283 ms warmup)
        process_time: 707 ms
        memory: 18915.89 KB
        objects: 232124
Queries: ["User Load", "User Update", "Employer Load", "Employee Load", "Shift Load", "Shift Create", "Shift Load", "Shift Create",
 "Shift Load", "Shift Create", "Shift Load", "Shift Create", "Shift Load", "Shift Create", "Shift Load", "Shift Create", "Shift Load",
 "Shift Create", "Shift Load", "Shift Create", "Shift Load", "Shift Create", "Shift Load", "Shift Create", "Shift Load", "Shift Create",
 "Shift Load", "Shift Create", "Shift Load", "Shift Create", "Shift Load", "Shift Create", "Shift Load", "Shift Create", "Shift Load",
 "Shift Create", "Shift Load", "Shift Create", "Shift Load", "Shift Create", "Shift Load", "Shift Create", "Shift Load", "Shift Create",
 "Shift Load", "Shift Create", "Employee Load", "Shift Load", "Property Load"]
After
-----
TimesheetTest#test_submit_timesheet (243 ms warmup)
        process_time: 578 ms
              memory: 14788.10 KB
             objects: 204551
Queries: ["User Load", "User Update", "Employer Load", "Employee Load", "Shift Load", "Shift Create", "Shift Create", "Shift Create",
"Shift Create", "Shift Create", "Shift Create", "Shift Create", "Employee Load", "Shift Load", "Property Load"]

So it would seem I’ve been able to knock off some time and memory consumption, along with lots of queries, by optimizing my code. Since I had already written test cases I was able to show that it worked the same as before.

But I think the better point to make here is that I could have spent a lot of time trying to build these optimizations in from day 1 and detracted from building a good product. Instead, I deferred the hard work until the time that it mattered. And now that I have more Ruby and Rails experience, doing the optimization was much easier. Something that might have taken several evenings over the course of a couple of weeks was done in less than a day. And while I don’t follow TDD, having existing tests to start from made a huge difference.