DEV: Add a new way to run specs in parallel with better output (#7778)

DEV: Add a new way to run specs in parallel with better output (#7778)

  • DEV: Add a new way to run specs in parallel with better output

This commit:

  1. adds a new executable, bin/interleaved_rspec which works much like rspec, but runs the tests in parallel.

  2. adds a rake task, rake interleaved:spec which runs the whole test suite.

  3. makes autospec use this new wrapper by default. You can disable this by running PARALLEL_SPEC=0 rake autospec.

It works much like the parallel_tests gem (and relies on it), but makes each subprocess use a machine-readable formatter and parses this output in order to provide a better overall summary.

(It’s called interleaved, because parallel was taken and naming is hard).

  • Make popen3 invocation safer

  • Use FileUtils instead of shelling out

  • DRY up reporter

  • Moved summary logic into Reporter

  • s/interleaved/turbo/g

  • Move Reporter into its own file

  • Moved run into its own class

  • Moved Runner into its own file

  • Move JsonRowsFormatter under TurboTests

  • Join on threads at the end

  • Acted on feedback from eviltrout

diff --git a/bin/turbo_rspec b/bin/turbo_rspec
new file mode 100755
index 0000000..4594db4
--- /dev/null
+++ b/bin/turbo_rspec
@@ -0,0 +1,47 @@
+#!/usr/bin/env ruby
+
+require './lib/turbo_tests'
+require 'optparse'
+
+requires = []
+formatters = []
+
+OptionParser.new do |opts|
+  opts.on("-r", "--require PATH", "Require a file.") do |filename|
+    requires << filename
+  end
+
+  opts.on("-f", "--format FORMATTER", "Choose a formatter.") do |name|
+    formatters << {
+      name: name,
+      outputs: []
+    }
+  end
+
+  opts.on("-o", "--out FILE", "Write output to a file instead of $stdout") do |filename|
+    if formatters.empty?
+      formatters << {
+        name: "progress",
+        outputs: []
+      }
+    end
+    formatters.last[:outputs] << filename
+  end
+end.parse!(ARGV)
+
+requires.each { |f| require(f) }
+
+if formatters.empty?
+  formatters << {
+    name: "progress",
+    outputs: []
+  }
+end
+
+formatters.each do |formatter|
+  if formatter[:outputs].empty?
+    formatter[:outputs] << '-'
+  end
+end
+
+TurboTests::Runner.run(formatters, ARGV)
diff --git a/config/boot.rb b/config/boot.rb
index df26be1..f219708 100644
--- a/config/boot.rb
+++ b/config/boot.rb
@@ -33,16 +33,21 @@ end
 
 # Parallel spec system
 if ENV['RAILS_ENV'] == "test" && ENV['TEST_ENV_NUMBER']
-  n = ENV['TEST_ENV_NUMBER'].to_i
+  if ENV['TEST_ENV_NUMBER'] == ''
+    n = 1
+  else
+    n = ENV['TEST_ENV_NUMBER'].to_i
+  end
+
   port = 10000 + n
 
-  puts "Setting up parallel test mode - starting Redis #{n} on port #{port}"
+  STDERR.puts "Setting up parallel test mode - starting Redis #{n} on port #{port}"
 
   `rm -rf tmp/test_data_#{n} && mkdir -p tmp/test_data_#{n}/redis`
   pid = Process.spawn("redis-server --dir tmp/test_data_#{n}/redis --port #{port}", out: "/dev/null")
 
   ENV["DISCOURSE_REDIS_PORT"] = port.to_s
-  ENV["RAILS_DB"] = "discourse_test_#{ENV['TEST_ENV_NUMBER']}"
+  ENV["RAILS_DB"] = "discourse_test_#{n}"
 
-  at_exit { puts "Terminating redis #{n}"; Process.kill("SIGTERM", pid); Process.wait }
+  at_exit { STDERR.puts "Terminating redis #{n}"; Process.kill("SIGTERM", pid); Process.wait }
 end
diff --git a/lib/autospec/formatter.rb b/lib/autospec/formatter.rb
index c923e55..8b5b3ac 100644
--- a/lib/autospec/formatter.rb
+++ b/lib/autospec/formatter.rb
@@ -14,10 +14,6 @@ class Autospec::Formatter < RSpec::Core::Formatters::BaseTextFormatter
   def initialize(output)
     super
     FileUtils.mkdir_p("tmp") unless Dir.exists?("tmp")
-  end
-
-  def start(example_count)
-    super
     File.delete(RSPEC_RESULT) if File.exists?(RSPEC_RESULT)
     @fail_file = File.open(RSPEC_RESULT, "w")
   end
@@ -32,7 +28,7 @@ class Autospec::Formatter < RSpec::Core::Formatters::BaseTextFormatter
 
   def example_failed(notification)
     output.print RSpec::Core::Formatters::ConsoleCodes.wrap('F', :failure)
-    @fail_file.puts(notification.example.metadata[:location] + " ")
+    @fail_file.puts(notification.example.location + " ")
     @fail_file.flush
   end
 
@@ -46,17 +42,3 @@ class Autospec::Formatter < RSpec::Core::Formatters::BaseTextFormatter
   end
 
 end
-
-class Autospec::ParallelFormatter < ParallelTests::RSpec::LoggerBase
-  RSpec::Core::Formatters.register self, :example_failed
-
-  def message(*args);end
-  def dump_failures(*args);end
-  def dump_summary(*args);end
-  def dump_pending(*args);end
-  def seed(*args);end
-
-  def example_failed(notification)
-    output.puts notification.example.metadata[:location] + " "
-  end
-end
diff --git a/lib/autospec/simple_runner.rb b/lib/autospec/simple_runner.rb
index 3cea530..12c8241 100644
--- a/lib/autospec/simple_runner.rb
+++ b/lib/autospec/simple_runner.rb
@@ -16,18 +16,17 @@ module Autospec
         self.abort
       end
       # we use our custom rspec formatter
-      args = ["-r", "#{File.dirname(__FILE__)}/formatter.rb"]
+      args = [
+        "-r", "#{File.dirname(__FILE__)}/formatter.rb",
+        "-f", "Autospec::Formatter"
+      ]
 
       command = begin
-        if ENV["PARALLEL_SPEC"] &&
+        if ENV["PARALLEL_SPEC"] != '0' &&
               !specs.split.any? { |s| puts s; s =~ /\:/ } # Parallel spec can't run specific groups
 
-          args += ["-f", "progress", "-f", "Autospec::ParallelFormatter", "-o", "./tmp/rspec_result"]
-          args += ["-f", "ParallelTests::RSpec::RuntimeLogger", "-o", "./tmp/parallel_runtime_rspec.log"] if specs == "spec"
-
-          "parallel_rspec -- #{args.join(" ")} -- #{specs.split.join(" ")}"
+          "bin/turbo_rspec #{args.join(" ")} #{specs.split.join(" ")}"
         else
-          args += ["-f", "Autospec::Formatter"]
           "bin/rspec #{args.join(" ")} #{specs.split.join(" ")}"
         end
       end
diff --git a/lib/tasks/turbo.rake b/lib/tasks/turbo.rake
new file mode 100644
index 0000000..b14ec56
--- /dev/null
+++ b/lib/tasks/turbo.rake
@@ -0,0 +1,5 @@
+task 'turbo:spec' => :test do |t|
+  require './lib/turbo_tests'
+
+  TurboTests::Runner.run([{name: 'progress', outputs: ['-']}], ['spec'])
+end
diff --git a/lib/turbo_tests.rb b/lib/turbo_tests.rb
new file mode 100644
index 0000000..5e88601
--- /dev/null
+++ b/lib/turbo_tests.rb
@@ -0,0 +1,62 @@
+require 'open3'
+require 'fileutils'
+require 'json'
+require 'rspec'
+require 'rails'
+
+require 'parallel_tests'
+require 'parallel_tests/rspec/runner'
+
+require './lib/turbo_tests/reporter'
+require './lib/turbo_tests/runner'
+require './lib/turbo_tests/json_rows_formatter'
+
+module TurboTests
+  FakeException = Struct.new(:backtrace, :message, :cause)
+  class FakeException
+    def self.from_obj(obj)
+      if obj
+        obj = obj.symbolize_keys
+        new(
+          obj[:backtrace],
+          obj[:message],
+          obj[:cause]
+        )
+      end
+    end
+  end
+
+  FakeExecutionResult = Struct.new(:example_skipped?, :pending_message, :status, :pending_fixed?, :exception)
+  class FakeExecutionResult
+    def self.from_obj(obj)
+      obj = obj.symbolize_keys
+      new(
+        obj[:example_skipped?],
+        obj[:pending_message],
+        obj[:status].to_sym,
+        obj[:pending_fixed?],
+        FakeException.from_obj(obj[:exception])
+      )
+    end
+  end
+
+  FakeExample = Struct.new(:execution_result, :location, :full_description, :metadata, :location_rerun_argument)
+  class FakeExample
+    def self.from_obj(obj)
+      obj = obj.symbolize_keys
+      new(
+        FakeExecutionResult.from_obj(obj[:execution_result]),
+        obj[:location],
+        obj[:full_description],
+        obj[:metadata].symbolize_keys,
+        obj[:location_rerun_argument],
+      )
+    end
+
+    def notification
+      RSpec::Core::Notifications::ExampleNotification.for(
+        self
+      )
+    end
+  end
+end
diff --git a/lib/turbo_tests/json_rows_formatter.rb b/lib/turbo_tests/json_rows_formatter.rb
new file mode 100644
index 0000000..e9379c5
--- /dev/null
+++ b/lib/turbo_tests/json_rows_formatter.rb
@@ -0,0 +1,93 @@
+module TurboTests
+  # An RSpec formatter used for each subprocess during parallel test execution
+  class JsonRowsFormatter
+    RSpec::Core::Formatters.register(
+      self,
+      :close,
+      :example_failed,
+      :example_passed,
+      :example_pending,
+      :seed
+    )
+
+    attr_reader :output
+
+    def initialize(output)
+      @output = output
+    end
+
+    def exception_to_json(exception)
+      if exception
+        {
+          backtrace: exception.backtrace,
+          message: exception.message,
+          cause: exception.cause
+        }
+      end
+    end
+
+    def execution_result_to_json(result)
+      {
+        example_skipped?: result.example_skipped?,
+        pending_message: result.pending_message,
+        status: result.status,
+        pending_fixed?: result.pending_fixed?,
+        exception: exception_to_json(result.exception)
+      }
+    end
+
+    def example_to_json(example)
+      {
+        execution_result: execution_result_to_json(example.execution_result),
+        location: example.location,
+        full_description: example.full_description,

[... diff too long, it was truncated ...]

GitHub sha: e18ce56f

3 Likes

This is working well in standalone mode!

Can you keep the redises running for a bit longer so it only terminates them at the end and does not interfere with the output?

Upstream discussion is here:

That’s a little tricky, because the redises are run by each subprocess (and I can’t just run them in the main process because they might potentially be required during other parallel tasks).

The log message is printed as each subprocess terminates. Options:

  1. I could keep each process alive longer. I don’t want to do that because there’s currently no ongoing communication from the main process to each subprocess and I’d prefer to keep it that way.
  2. I could delay relaying stderr after we receive a close message (which means that rspec is wrapping up). The problem here is that these are different pipes that aren’t necessarily completely in sync and we could inadvertently delay other messages that were actually printed during a test,
  3. I make an at exit logger. By default it would just go to stderr, but during parallel tests it could go to another pipe which we only read when the main process is wrapping up. This is my preferred option if we definitely want these messages,
  4. I could turn off logging here since it’s not hugely helpful.

This, happy with that as well … that logging is kind of pointless.

A simple … hi I am using 10 workers, at the beginning of the run is handy, but all these termination messages are pointless.

2 Likes