ParallelTests::RSpec::RuntimeLogger ignores first process

Problem

Inspired by a recent meeting with the team at Loblaws Digital, I have been looking at tools to improve the execution of my regression suite. To address an ever growing execution time, I turned to the ParallelTests gem. This gem offered the ability to group RSpec examples, which could then be run in parallel on multiple machines.

Using the default grouping by file size, resulted in a huge disparity in processing times. One machine finished in an hour, while another took almost 2 hours. Not particularly surprising given that these are UI tests.

There is an option to group tests by runtime. For this, ParallelTests needs a runtime history for each spec file. This can be generated by using the ParallelTests::RSpec::RuntimeLogger:

parallel_rspec spec -o "--format ParallelTests::RSpec::RuntimeLogger --out tmp/parallel_runtime_rspec.log"

Unfortunately, this produces an empty log when using a single process. With multiple processes, test times were logged, but not for the first process. What is going on? How do we get the run times for the first (or only) process?

Solution

Digging into the ParallelTests::RSpec::RuntimeLogger, you can see that the log file is written by:

def start_dump(*args)
  return unless ENV['TEST_ENV_NUMBER'] #only record when running in parallel
  # TODO: Figure out why sometimes time can be less than 0
  lock_output do
    @example_times.each do |file, time|
      relative_path = file.sub(/^#{Regexp.escape Dir.pwd}\//,'').sub(/^\.\//, "")
      @output.puts "#{relative_path}:#{time > 0 ? time : 0}"
    end
  end
  @output.flush
end

Inspecting the ENV['TEST_ENV_NUMBER'] you will get “nil” for the first process and “2” for the second process. Due to the “nil”, the first line’s return will execute, skipping the logging. I do not understand why you would ever want to use this formatter and skip logging, but fine, let’s ignore that. Where does the ENV['TEST_ENV_NUMBER'] get set?

Looking through the repository, you can see the ParallelTests::Test::Runner.execute_command creates a set of values for later use as environment variables:

def execute_command(cmd, process_number, num_processes, options)
  env = (options[:env] || {}).merge(
    "TEST_ENV_NUMBER" => test_env_number(process_number, options),
    "PARALLEL_TEST_GROUPS" => num_processes
  )
  cmd = "nice #{cmd}" if options[:nice]
  cmd = "#{cmd} 2>&1" if options[:combine_stderr]
  puts cmd if options[:verbose]

  execute_command_and_capture_output(env, cmd, options[:serialize_stdout])
end

More importantly, the TEST_ENV_NUMBER value is defined by:

def test_env_number(process_number, options={})
  if process_number == 0 && !options[:first_is_1]
    ''
  else
    process_number + 1
  end
end

For the first process, an empty String is returned. When it gets used in execute_command_and_capture_output, the setting of the environment variable is done with:

"(SET \"#{k}=#{v}\")"

Note this means the environment variable is set using SET TEST_ENV_NUMBER= not SET TEST_ENV_NUMBER="". This is why ENV['TEST_ENV_NUMBER'] is “nil”.

The next question is what is the options[:first_is_1]? Can we set that value so that test_env_number returns the process_number + 1 instead? This takes us to the ParallelTests::CLI. Here we can see that the option is set to true when using the “–first-is-1” flag.

In the end, this long stroll through the code tells us that we can fix the logging by running:

parallel_rspec spec --first-is-1 -o "--format ParallelTests::RSpec::RuntimeLogger --out tmp/parallel_runtime_rspec.log"
Advertisements
This entry was posted in RSpec and tagged . Bookmark the permalink.

One Response to ParallelTests::RSpec::RuntimeLogger ignores first process

  1. JOE STRAIN says:

    thanks for this article, it was exactly what i was looking for in troubleshooting similar issue

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s