How I sped up our Rails Test Suite by 267%

Development

This is the first post in a series I’ll be doing here at Codeship on speeding up our test suite. I also released a gem that detects the slowdowns in this part for you.

Making test suites run fast has always been an obsession/passion of mine, in fact it all started back in 2010 when I spoke about faster testing in the talk Grease Your Suite. Since then, having a fast test suite is something I maintain on any project I work on. So, when I joined Codeship a few weeks ago their test suite naturally drew my attention. Today I’ll detail techniques I used to discover slow points in the test suite along with their solutions. In the end I got the suite to run over 3x faster!

Something’s not quite right

On my first day at Codeship I got there early. A little too early in fact, as no one was in the office yet. So, I sat down to get the project running on my laptop before everyone got in. I checked out the code, set up the database, and started running the tests. Then, Alex, who is responsible for our Product Experience, came in and said, “Oh, you don’t want to run the tests on your laptop, they’re too slow, we run them all on Codeship.” That makes sense to me, the application is large and my laptop is very small, while Codeship’s servers are big and fast (#shamelessplug).

But something wasn’t quite right. In my taskbar I keep a little triple monitor plugin showing cpu %, memory %, and swap %. And while I was running the Codeship suite, the cpu % barely lifted off the floor! I knew something weird was happening.

Inspecting application status

By a long shot, the Cucumber suite was both the longest and the least CPU intensive. If you’re new to Cucumber, you can check out our other articles on setup, BDD, and continuous integration with cucumber). I picked out one cucumber feature at random: configuring a project. When I ran it, it would hang here for a while:

$ cucumber features/configuring_a_project.feature
Feature: Configuring should be highlighted in the configuration nav setup
  As a user
  I want to configure my project settings

  Background:    # features/configuring_a_project.feature:5

It would sit there for 10 seconds or so, and my cpu meter was flat. The app was waiting for something, but I didn’t know what. Maybe the browser was booting up? Maybe a network request? I didn’t know. I tried ctrl-c but cucumber traps it and exits gracefully, so I couldn’t get a stack trace. I needed to find out what the app was up to when it was hanging.

GDB

Enter GDB, the GNU Debugger. But wait, isn’t that for C and C++? Well, it just so happens that Ruby’s (MRI) interpreter is written in C, and from GDB we can call C functions, including those in the MRI interpreter.

First, we attach to the running ruby process. I ran my cucumber feature and while it was hanging I found the PID and attached GDB:

$ ps ax | grep cucumber
 9105 pts/6    Sl+    0:00 ruby ./bin/cucumber features/configuring_a_project.feature
 9107 ?        Sl     0:00 cucumber features/configuring_a_project.feature
 9126 pts/12   S+     0:00 grep --color=auto cucumber
$ sudo gdb -p 9107
# lots of gdb output
(gdb) call rb_backtrace()

Since that function call is to the ruby interpreter, I have to look over at my ruby process to see the output:

$ cucumber features/configuring_a_project.feature -t @javascript
[Zonebie] Setting timezone: ZONEBIE_TZ="Hobart"
Using the default profile...
Feature: Configuring should be highlighted in the configuration nav setup
  As a user
  I want to configure my project settings

  Background:                                            # features/configuring_a_project.feature:5
        from .gems/gems/puffing-billy-0.2.3/lib/billy/proxy.rb:16:in `block in start'
        from .gems/gems/puffing-billy-0.2.3/lib/billy/proxy.rb:70:in `main_loop'
        from .gems/gems/eventmachine-1.0.3/lib/eventmachine.rb:187:in `run'
        from .gems/gems/eventmachine-1.0.3/lib/eventmachine.rb:187:in `run_machine'

This isn’t helpful, because the first thread was just our http proxy waiting for input. We have to dump the stack trace for all the threads that are running to find the one that’s actually our own code:

(gdb) info threads
  Id   Target Id         Frame 
  6    Thread 0x7ff08de84700 (LWP 9218) "ruby-timer-thr" 0x00007ff08d02f39d in poll ()
    at ../sysdeps/unix/syscall-template.S:81
  5    Thread 0x7ff0793d2700 (LWP 9221) "ruby" 0x00007ff08d0311c3 in select ()
    at ../sysdeps/unix/syscall-template.S:81
  4    Thread 0x7ff0795d4700 (LWP 9222) "ruby" 0x00007ff08d0311c3 in select ()
    at ../sysdeps/unix/syscall-template.S:81
  3    Thread 0x7ff0892fa700 (LWP 9225) "ruby" pthread_cond_timedwait@@GLIBC_2.3.2 ()
    at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:238
  2    Thread 0x7ff0798d7700 (LWP 9228) "ruby" 0x00007ff08da55dbd in read ()
    at ../sysdeps/unix/syscall-template.S:81
* 1    Thread 0x7ff08de6a740 (LWP 9216) "ruby" pthread_cond_timedwait@@GLIBC_2.3.2 ()
    at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:238

I have no idea which one is the one we want, so let’s dump them all!

(gdb) thread 2
[Switching to thread 2 (Thread 0x7ff0798d7700 (LWP 9228))]
#0  0x00007ff08da55dbd in read () at ../sysdeps/unix/syscall-template.S:81
81  ../sysdeps/unix/syscall-template.S: No such file or directory.
(gdb) call rb_backtrace()
# stack trace
  from /usr/local/lib/ruby/2.1.0/webrick/utils.rb:176:in `block in initialize'
  from /usr/local/lib/ruby/2.1.0/webrick/utils.rb:176:in `sleep'

Nope, that’s our web server, not very helpful.

(gdb) thread 3
[Switching to thread 3 (Thread 0x7ff0892fa700 (LWP 9225))]
#0  pthread_cond_timedwait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:238
238 ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S: No such file or directory.
(gdb) call rb_backtrace()
# stack trace is huge, and contains a bunch of cucumber stuff, jackpot!
  from -e:1:in `<main>'
  <redacted>
  from .gems/gems/cucumber-1.3.17/bin/cucumber:13:in `<top (required)>'
  from .gems/gems/cucumber-1.3.17/lib/cucumber/cli/main.rb:47:in `execute!'
  from .gems/gems/cucumber-1.3.17/lib/cucumber/runtime.rb:49:in `run!'
  from .gems/gems/cucumber-1.3.17/lib/cucumber/ast/tree_walker.rb:20:in `visit_features'
  from .gems/gems/cucumber-1.3.17/lib/cucumber/ast/tree_walker.rb:170:in `broadcast'
  from .gems/gems/cucumber-1.3.17/lib/cucumber/ast/tree_walker.rb:21:in `block in visit_features'
  <redacted>
  from .gems/gems/cucumber-1.3.17/lib/cucumber/core_ext/instance_exec.rb:48:in `block in cucumber_instance_exec'
  from .gems/gems/cucumber-1.3.17/lib/cucumber/core_ext/instance_exec.rb:48:in `instance_exec'
  from .gems/gems/cucumber-1.3.17/lib/cucumber/rb_support/rb_step_definition.rb:49:in `block in create_proc'
  from workspace/mothership/features/support/user_helper.rb:59:in `sign_in_as'
  from workspace/mothership/features/support/signed_in_user.rb:31:in `signed_in?'
  from .gems/gems/capybara-2.4.4/lib/capybara/session.rb:676:in `block (2 levels) in <class:Session>'
  from .gems/gems/capybara-2.4.4/lib/capybara/node/matchers.rb:39:in `has_selector?'
  <redacted>
  from .gems/gems/capybara-2.4.4/lib/capybara/node/base.rb:102:in `find_css'
  from .gems/gems/poltergeist-1.5.1/lib/capybara/poltergeist/driver.rb:122:in `find_css'

Boom! features/support/user_helper.rb:59‘s sign_in_as is hanging. So, what’s going on here? Let’s check out the code:

current_user.sign_out if current_user.signed_in?

OK, that’s reasonable, let’s sign out if someone signs in when we need to log in as a user. Let’s see what signed_in? looks like:

def signed_in?
  page.has_selector? signed_in_selector
end

And this, right here, is the most common and subtle performance bug in the behavior of the Capybara gem: auto-waiting finders.

Capybara finders

Let’s do a little background on Capybara. Capybara is an awesome Ruby gem that drives a browser over your code so you can exercise your entire application. It has a variety of methods like visit(url) to visit a page, or click_link("Sign in") to click a link. It also has an amazing feature which is to retry a command when it’s driving a real browser like Selenium or PhantomJS to handle asynchronous issues. So, if you say click_link("Sign in") but there’s no link with the text “Sign in” then Capybara will try to find it over and over until it finds it or it reaches Capybara’s default_wait_time.

This is great when we’re working on a test and it’s not passing yet because our code isn’t done. We want it to try and fail if the link isn’t there. And if that link pops up via a jQuery plugin, we want Capybara to wait for it to show up, not fail fast.

Try Codeship – The simplest Continuous Integration service out there.

Additional finders

In addition to these commands, Capybara also has finders like has_content?("Dashboard") which would check if “Dashboard” was on the page. But there’s a trick: this command assumes “Dashboard” should be on the page, and waits for it to appear. This is supposed to be used with an assertion, like assert page.has_content?("Dashboard").

If you want the opposite you need to flip the finder, not the assertion. So, assert page.has_no_content?("Dashboard") will look to see that the page doesn’t have “Dashboard”. But if the page does have “Dashboard” it will wait until “Dashboard” leaves the page via ajax.

That brings us to a common mistake: flipping the assertion instead of the finder, like this: refute page.has_content?("Dashboard"). This will wait until the page has the content “Dashboard”, which it won’t, then return false, which passes the refute. So while this test passes, it always waits the full Capybara default wait time. Which means that this is 15 seconds (the default) slower than assert page.has_no_content?("Dashboard").

In summary, it’s really important to use the capybara finder that lines up with what you expect on the page.

Back to our test

So, let’s take a fresh look at our code:

def signed_in?
  page.has_selector? signed_in_selector
end

This code assumes that the signed_in_selector is present on the page. So if someone is signed in, this code returns true very quickly. If someone is not signed in, this code returns false in 15 seconds after waiting to see the selector show up. The huge problem with our code is that we use signed_in? in branches, so it could be either true or false in different test cases. Whenever it’s false (no one is signed in) we lose 15 seconds.

Unfortunately for Codeship, this is almost always used in the first step of a feature: sign a user in (and sign anyone out if they are signed in). So thats 15 seconds times every time this is improperly used.

There are two ways to solve this:

  1. Pass the intent to the helper
  2. Use a non-waiting finder

Passing the intent to the helper means that we would pass our expectation in and then switch the finder we’re using, like this:

def signed_in?(expected: false)
  if expected
    page.has_selector? signed_in_selector
  else
    !page.has_no_selector? signed_in_selector
  end
end

signed_in?(expected: false) # I don't think they're signed in, are they?
signed_in?(expected: true)  # I think they're signed in, right?

But that requires us to change every usage, and change the cucumber steps, etc. A big pain. Let’s look at #2: the non waiting finder:

def signed_in?
  page.all(signed_in_selector).any?
end

This time, we’re asking for all the signed in selectors on the page, then using any? which returns true for arrays that aren’t empty. This Capybara finder doesn’t have an assumed result, it’s just a query. So whether true or false, it will be fast.

Find them all

At this point, I realize that while this is a big improvement, there may be many more occurrences of slow finders in our test. So I defined what I was looking for: any time a waiting Capybara method reaches the timeout. In my opinion, if a Capybara finder hits the timeout, it should be replaced with either its double negative (like turning has_content to !has_no_content) for assertions or with a non-waiting finder for branches.

To do this, I made a little monkeypatch, which I later turned into a gem called capybara-slow_finder_errors:

module Capybara
  class SlowFinderError < CapybaraError; end
  module Node
    class Base
      def synchronize_with_timeout_error(seconds=Capybara.default_wait_time, options = {}, &block)
        start_time = Time.now
        synchronize_without_timeout_error(seconds, options, &block)
      rescue Capybara::ElementNotFound => e
        if Time.now-start_time > seconds
          raise SlowFinderError
        end
      end
      alias_method :synchronize_without_timeout_error, :synchronize
      alias_method :synchronize, :synchronize_with_timeout_error
    end
  end
end

We’re extending Capybara’s synchronize such that if it exceeds the timeout, it raises a Capybara::SlowFinderError which Capybara won’t catch and turn into a boolean (that’s what it does with ElementNotFound for many finders). Now, we just run our suite and follow every stack trace back to the offending code. Which is exactly what I did.

Results

When I started, the Cucumber suite ran in 9:30 (9 minutes, 30 seconds). After fixing all the slow finders, we got it down to 5:45, almost twice as fast!

One more thing

Previously, I had tried switching to Poltergeist (we were on Selenium) but didn’t see a speed improvement and also saw a few errors. Now that I had removed slow finders I had a hunch that Poltergeist would be worth it. At the very least, we could stop Firefox from popping up when we ran our tests (I know, I know, I can use a virtual framebuffer, but it’s still annoying).

I switched us over to Poltergeist (based on PhantomJS), and got a free speed boost! Now that the suite was actually running hard on the CPU, Poltergeist made a big difference. We went from 5:45 to 2:35! All in all, we went from 9:30 to 2:35, which is a speedup factor of x3.67!

This is one of the tricky parts of performance improvements: sometimes certain bottlenecks are blocking other improvements from being worthwhile. That’s why you always have to fix the current bottleneck before a new performance tweak will have any effect.

So, with my caveat that it may not be your bottleneck, try out capybara-slow_finder_errors and see if you get any errors. At the very least, they’re worth investigating.

I’m continuing my quest to discover more ways to speed up Codeship‘s test suite, and I will have more tips soon! Capybara is supported out of the box on Codeship. If you’re interested you can learn more about it in our Codeship Ruby Documentation.

PS: If you liked this article you might also be interested in one of our free eBooks from our Codeship Resources Library. Download it here: Why Continuous Integration Is Important

Subscribe via Email

Over 60,000 people from companies like Netflix, Apple, Spotify and O'Reilly are reading our articles.
Subscribe to receive a weekly newsletter with articles around Continuous Integration, Docker, and software development best practices.



We promise that we won't spam you. You can unsubscribe any time.

Join the Discussion

Leave us some comments on what you think about this topic or if you like to add something.

  • Wow, great write up on some easy low-hanging-fruit to improve test speeds. I’m upgrading several apps from older versions of Rails, and this will come in handy considering how often I’m running the test suites.

    • Nick Gauthier

      Thanks Chris!

  • Beautiful, cant wait to try this out at work tomorrow cos I know it will help speed my test suite up, I’ve been making the same mistake for years.

    • Nick Gauthier

      So have I. It’s really common! Let me know how it goes.

  • Micah Geisel

    Yowza, just got a ~100% speedup in our largest Capybara suite, just by eliminating slow finders with the gem! That’s so valuable that I think the gem should be considered for integration into Capybara proper, somehow, in an always-on fashion. Maybe it could raise a warning instead of an error?

  • Jeb Baxley

    Awesome, good job sir.

    • Nick Gauthier

      Indeed, thank you!

  • We drop from ~20min to ~13min just by updating cucumber from 1.2.1 to 1.3.17. After that switching to phantomjs drops 7-8min off, so now test rans in 5min.

    I’ll give your gem a try if it’s speeding tests more. Thanks!

    • Nick Gauthier

      Awesome! Every little bit helps. It’s all about finding the bottlenecks!

  • Matt Metzger

    This is awesome – I had previously been manually watching my test suite execute (~1 hour) and looking for any places where the expectation / finder needed to be negated. This is going to make that process a lot easier going forward.

    • Nick Gauthier

      Thanks Matt! Let me know how it goes!

  • mrcasals

    So, from the gem README file, if you are using RSpec then you don’t have this problem, right?

    • Nick Gauthier

      Rspec will flip finders when they are on expectations, but, if like us, you had this in your own helper method *not* in an expectation, then you may have this problem. So, in Rspec:

      expect(page).not_to have_content?(“foo”) # OK!
      click_link “foo” if page.has_content?(“bar”) # Bad if the page sometimes doesn’t have bar

      So, RSpec will invert the finders using “not_to”, but only when you are making an assertion.

      In our case, it was a helper method that accessed capybara directly that caused the problem. We are using RSpec and Cucumber.

  • This only found one issue in my test suite. I want my money back!

    • Nick Gauthier

      Please post your paypal and I will money you 0$ :P

  • But seriously, great write-up Nick, and great job building a safety-net gem.

    • Nick Gauthier

      Thanks

  • ledestin

    Brilliant, though monotonic time should be used to measure time, as real time has dst changes and leap seconds. Hitimes gem allows to do it, or my monotonic_time gem.

  • tgxworld

    Great post! Capybara has always been one of the bottlenecks in my test suites! I’ll give the gem a try!

    • Nick Gauthier

      Thanks!

  • Ari Pollak

    Thanks for this gem! For the final example, could you use “page.has_selector? signed_in_selector, wait: false” instead of “all…any?”? https://github.com/jnicklas/capybara/blob/e5800777b43f318c23e173b1e9c30bd2bc8305aa/lib/capybara/node/finders.rb#L23

  • Pingback: Ruby Links (I) | luismayoral.com()

  • T.L.

    Sorry to be a nitpicker, but if the test suite execution time was reduced from 9:30 to 2:35 — i.e., from 570 to 155 seconds — that’s a reduction of 73%, not 267%. The latter would have meant that your test suit would have finished running almost 16 minutes before you started it. :)

    • Nick Gauthier

      If you have something that is 5 seconds and now it runs in 1 second, it is 5 times faster, which is 500% faster, which is a 500% speedup. It is now running in 20% of the time, which is a reduction of 80%. It’s all in the phrasing.

      So, 267% faster is 2.67x faster. 1/2.67 = 0.37. 1-0.37 = .73 = reduction of 73%.

      • bb

        No, ‘5 times faster’ is not the same as ‘500% faster’. Though 5 500%, the sentences don’t say the same. You would have to write ‘500% times faster’ to get the same meaning but it would read weird.
        T.L is right with his calculation.
        It’s the same when you read a sign ‘50% off’ at a sale. This means the article is half the price. They don’t call it ‘100% off’.
        That’s basic math.

        • Nick Gauthier

          Here’s another discussion on the subject:

          http://stackoverflow.com/questions/8127862/how-do-you-calculate-how-much-faster-time-x-is-from-time-y-in-terms-of

          500% is 500 per cent which means 500 per 100 (cent is 100). So 20 per 100 means for everyone 100 of a thing you have, this number refers to 20 things.

          So if something is 500 per 100 faster. Then if the previous thing was 5 minutes, then 5 minutes is your “100”. So, since I said “faster” this thing can execute 500 things for every 100 things you could execute before. So, I could execute 500 test suites in the time I used to be able to execute 100 test suites. Or, divide it down to 5 suites in the time it took to run 1 suite. Or, one run is now 1/5 the time it was before. So my new suite is 1 minute.

          I’m sticking to my guns on this, but I understand you have a different interpretation of “speedup” and “faster”. What you absolutely cannot contest is the fact that our tests went from 9:30 to 2:35, which is pretty awesome and is the point of the article. Further discussion down this road is a waste of time because we’re just being subjective on the semantics of the English language.

          Nick

          • Thanks for a very nice article about tweaking the finders, but you can remove the “speedup factor of x3.67” because swapping to headless alternative is something that should have been done long before starting the fine tuning.

          • Nick Gauthier

            No. It’s helpful.

  • Paulo Fabiano Langer

    Awesome article! Congrats.

    • Nick Gauthier

      Thanks Paulo!

      • Paulo Fabiano Langer

        You’re welcome, Nick! I really need to improve my testing skills in Rails. You should be a teacher :)
        I read all the discussion in capybara’s github and I got very frustrated about it. I believe your suggestions are very good the could use it. Well, life goes on and your gem is nice too.

        • Nick Gauthier

          it’s really ok it’s not in capybara. The gem does its job. And I did used to teach with JumpstartLab :D

  • John Naegle

    Isn’t the default wait time in capybara 2 seconds (https://github.com/jnicklas/capybara/blob/master/lib/capybara.rb#L361), not 15 seconds? It seems like you could have had a significant speedup by using the default wait time instead of overriding it.

    • Nick Gauthier

      Yes, but that all depends on the needs of your application. In our case, we run our builds across all the cores on the system so each individual test is a little slower but on the whole the suite is faster. So, upping the wait time was useful for us.

      Also, one *really* easy way to find slow finders is just set the default wait time to 5 mins and wait for the suite to hang :-D

      But yeah, if you have a short wait time (and no random failures because of it) the slow finder problem is less of an issue. But many many teams increase this value for stability.

      Really, it should be long because you’d rather it waited and passed then failed by waiting. And, you should not have any waiting finders.

  • Pingback: 3 – How I sped up our Rails Test Suite by 267% – Official Offeryour.com Blog()

  • It’s worth noting that the `all` query now also waits: https://github.com/jnicklas/capybara/commit/828bc2e812df1635e5ac11b45f89f89218f73630, which means the `page.all(…).any?` trick will no longer work unless you explicitly tell it not to wait by passing in the :wait option.

  • Alejandra Cernas

    I learn something good today, I can’t wait to check my test suite, great post!

  • Pingback: 10 ways how to speed your unit tests [Rails, RSpec, Capybara] – My Programming Blog()

  • Thanks for the post. I don’t understand how moving intentions to the helper speeds anything up, though. Could you clarify that please?

    • Because while `page.has_selector? signed_in_selector` and `!page.has_no_selector? signed_in_selector` look the same, they exhibit different behavior.

      The first one returns true if it finds the selector. Otherwise, it waits until timeout for the selector to show up before returning false.
      The 2nd one returns true if it does not find the selector, Otherwise, it waits until timeout for the selector to disappear before returning true.

      By moving telling the helper our intention, it can use the appropriate test.