tl;dr When using Timecop, always remember to turn it off at the end of the test.

I post this in the hopes that I’m not the only one to make this mistake and someone else might actually benefit from my stupidity.

It’s a sad truth, but in my experience, when googling, googling again and googling some more for a solution to a problem turns up nary a post from someone having the same problem, it’s usually because PEBKAC (I’m an idiot). For several days I’ve been noticing in frustration that the RSpec suite on one of my applications was periodically reporting negative runtimes, e.g.,

Finished in -537150.87202 seconds
329 examples, 0 failures

This consistently happened when running the entire test suite, but seemed sporadic when running a subset of the test suite. Adding to my confusion, at just about the same time that this problem appeared I had upgraded to RSpec 2.8 which fixed an issue that popped up when using Spork. I grudgingly pushed the matter to the back of my mind since, with the test suite running sufficiently fast, there were higher priority tasks. But today I found myself specfically wanting to benchmark the test suite, and these negative runtimes just wouldn’t do. So I poked around deeper.

I generated a fresh Rails application using the same template I’d used to generate the offending application. Running the new application’s nigh empty test suite reported accurate (positive) runtimes, so I started looking for additions/modifications made to spec/spec_helper.rb to see where things diverged. Nothing seemed significant. I then checked Gemfile to see what gems had been added to the offending application. Timecop! Of course, if something was going to interfere with runtime calculations, freezing Time would probably do it. I grepped for Timecop in my spec files and found it in use in only one, but damningly, it was mentioned only once. I was calling Timecop.freeze from a before block, but I was not restoring Time by calling Timecop.return from a corresponding after block.

face.send(:palm)

I added the missing after block. Runtime reports were accurate once again. Unicorns! Rainbows! Chocolate milk!

As an aside, if you use RSpec and Spork, and had found yourself adding the following to your spec_helper.rb:

Spork.each_run do
  $rspec_start_time = Time.now
end

You can remove that kludge after you upgrade to RSpec 2.8. Yay!