DEV: Add --profile=[COUNT] option for turbo_rspec

Why is this change required?

By default, `RSpec` comes with a `--profile=[COUNT]` option as well but
enabling that option means that the entire test suite needs to be
executed. This does not work so well for `turbo_rspec` which splits our
test files into various "buckets" for the tests to be executed in
multiple processes. Therefore, this commit adds a similar
`--profile=[COUNT]` option to `turbo_rspec` but will only profile the
tests being executed. Examples:

`LOAD_PLUGINS=1 bin/turbo_rspec --profile plugins/*/spec/system`

or

`LOAD_PLUGINS=1 bin/turbo_rspec --profile=20 plugins/*/spec/system`

bin/turbo_rspec

@@ -11,6 +11,8 @@ formatters = []
 verbose = false
 fail_fast = nil
 seed = rand(2**16)
+profile = false
+profile_print_slowest_examples_count = 10
 
 OptionParser
   .new do |opts|
@@ -27,6 +29,15 @@ OptionParser
 
     opts.on("-v", "--verbose", "More output") { verbose = true }
 
+    opts.on(
+      "-p",
+      "--profile=[COUNT]",
+      "Benchmark the runtime of each example and list the slowest examples (default: 10)",
+    ) do |count|
+      profile = true
+      profile_print_slowest_examples_count = count.to_i if count
+    end
+
     opts.on("--fail-fast=[N]") do |n|
       n =
         begin
@@ -67,6 +78,8 @@ success =
     fail_fast: fail_fast,
     use_runtime_info: use_runtime_info,
     seed: seed.to_s,
+    profile:,
+    profile_print_slowest_examples_count:,
   )
 
 if success

lib/turbo_tests/base_formatter.rb

@@ -0,0 +1,23 @@
+# frozen_string_literal: true
+
+RSpec::Support.require_rspec_core "formatters/base_text_formatter"
+RSpec::Support.require_rspec_core "formatters/console_codes"
+
+module TurboTests
+  class BaseFormatter < RSpec::Core::Formatters::BaseTextFormatter
+    RSpec::Core::Formatters.register(self, :dump_summary)
+
+    def dump_summary(notification, timings)
+      if timings.present?
+        output.puts "\nTop #{timings.size} Slowest examples:"
+
+        timings.each do |(full_description, source_location, duration)|
+          output.puts "  #{full_description}"
+          output.puts "    #{RSpec::Core::Formatters::ConsoleCodes.wrap(duration.to_s + "ms", :bold)} #{source_location}"
+        end
+      end
+
+      super(notification)
+    end
+  end
+end

lib/turbo_tests/documentation_formatter.rb

@@ -1,41 +1,51 @@
 # frozen_string_literal: true
 
-RSpec::Support.require_rspec_core "formatters/base_text_formatter"
-
 module TurboTests
   # An RSpec formatter that prepends the process id to all messages
-  class DocumentationFormatter < RSpec::Core::Formatters::BaseTextFormatter
+  class DocumentationFormatter < ::TurboTests::BaseFormatter
     RSpec::Core::Formatters.register(self, :example_failed, :example_passed, :example_pending)
 
     def example_passed(notification)
       output.puts RSpec::Core::Formatters::ConsoleCodes.wrap(
-                    "[#{notification.example.process_id}] #{notification.example.full_description}",
+                    output_example(notification.example),
                     :success,
                   )
+
       output.flush
     end
 
     def example_pending(notification)
       message = notification.example.execution_result.pending_message
+
       output.puts RSpec::Core::Formatters::ConsoleCodes.wrap(
-                    "[#{notification.example.process_id}] #{notification.example.full_description}" \
+                    "#{output_example(notification.example)} (PENDING: #{message})",
-                      " (PENDING: #{message})",
                     :pending,
                   )
+
       output.flush
     end
 
     def example_failed(notification)
       output.puts RSpec::Core::Formatters::ConsoleCodes.wrap(
-                    "[#{notification.example.process_id}] #{notification.example.full_description}" \
+                    "#{output_example(notification.example)} (FAILED - #{next_failure_index})",
-                      " (FAILED - #{next_failure_index})",
                     :failure,
                   )
+
       output.flush
     end
 
     private
 
+    def output_example(example)
+      output = +"[#{example.process_id}] #{example.full_description}"
+
+      if run_duration_ms = example.metadata[:run_duration_ms]
+        output << " (#{run_duration_ms}ms)"
+      end
+
+      output
+    end
+
     def next_failure_index
       @next_failure_index ||= 0
       @next_failure_index += 1

lib/turbo_tests/json_rows_formatter.rb

@@ -54,6 +54,7 @@ module TurboTests
           shared_group_inclusion_backtrace:
             example.metadata[:shared_group_inclusion_backtrace].map(&method(:stack_frame_to_json)),
           extra_failure_lines: example.metadata[:extra_failure_lines],
+          run_duration_ms: example.metadata[:run_duration_ms],
         },
         location_rerun_argument: example.location_rerun_argument,
       }

lib/turbo_tests/progress_formatter.rb

@@ -1,9 +1,7 @@
 # frozen_string_literal: true
 
-RSpec::Support.require_rspec_core "formatters/base_text_formatter"
-
 module TurboTests
-  class ProgressFormatter < RSpec::Core::Formatters::BaseTextFormatter
+  class ProgressFormatter < ::TurboTests::BaseFormatter
     LINE_LENGTH = 80
 
     RSpec::Core::Formatters.register(

lib/turbo_tests/reporter.rb

@@ -2,8 +2,8 @@
 
 module TurboTests
   class Reporter
-    def self.from_config(formatter_config, start_time)
+    def self.from_config(formatter_config, start_time, max_timings_count: nil)
-      reporter = new(start_time)
+      reporter = new(start_time:, max_timings_count:)
 
       formatter_config.each do |config|
         name, outputs = config.values_at(:name, :outputs)
@@ -20,7 +20,7 @@ module TurboTests
     attr_reader :failed_examples
     attr_reader :formatters
 
-    def initialize(start_time)
+    def initialize(start_time:, max_timings_count:)
       @formatters = []
       @pending_examples = []
       @failed_examples = []
@@ -28,6 +28,8 @@ module TurboTests
       @start_time = start_time
       @messages = []
       @errors_outside_of_examples_count = 0
+      @timings = []
+      @max_timings_count = max_timings_count
     end
 
     def add(name, outputs)
@@ -50,6 +52,7 @@ module TurboTests
       delegate_to_formatters(:example_passed, example.notification)
 
       @all_examples << example
+      log_timing(example)
     end
 
     def example_pending(example)
@@ -57,6 +60,7 @@ module TurboTests
 
       @all_examples << example
       @pending_examples << example
+      log_timing(example)
     end
 
     def example_failed(example)
@@ -64,6 +68,7 @@ module TurboTests
 
       @all_examples << example
       @failed_examples << example
+      log_timing(example)
     end
 
     def message(message)
@@ -79,14 +84,17 @@ module TurboTests
       end_time = Time.now
 
       delegate_to_formatters(:start_dump, RSpec::Core::Notifications::NullNotification)
+
       delegate_to_formatters(
         :dump_pending,
         RSpec::Core::Notifications::ExamplesNotification.new(self),
       )
+
       delegate_to_formatters(
         :dump_failures,
         RSpec::Core::Notifications::ExamplesNotification.new(self),
       )
+
       delegate_to_formatters(
         :dump_summary,
         RSpec::Core::Notifications::SummaryNotification.new(
@@ -97,7 +105,9 @@ module TurboTests
           0,
           @errors_outside_of_examples_count,
         ),
+        @timings,
       )
+
       delegate_to_formatters(:close, RSpec::Core::Notifications::NullNotification)
     end
 
@@ -108,5 +118,15 @@ module TurboTests
         formatter.send(method, *args) if formatter.respond_to?(method)
       end
     end
+
+    private
+
+    def log_timing(example)
+      if run_duration_ms = example.metadata[:run_duration_ms]
+        @timings << [example.full_description, example.location, run_duration_ms]
+        @timings.sort_by! { |timing| -timing.last }
+        @timings.pop if @timings.size > @max_timings_count
+      end
+    end
   end
 end

lib/turbo_tests/runner.rb

@@ -13,7 +13,12 @@ module TurboTests
 
       STDOUT.puts "VERBOSE" if verbose
 
-      reporter = Reporter.from_config(formatters, start_time)
+      reporter =
+        Reporter.from_config(
+          formatters,
+          start_time,
+          max_timings_count: opts[:profile_print_slowest_examples_count],
+        )
 
       if ENV["GITHUB_ACTIONS"]
         RSpec.configure do |config|
@@ -31,6 +36,7 @@ module TurboTests
         fail_fast: fail_fast,
         use_runtime_info: use_runtime_info,
         seed: seed,
+        profile: opts[:profile],
       ).run
     end
 
@@ -49,6 +55,7 @@ module TurboTests
       @fail_fast = opts[:fail_fast]
       @use_runtime_info = opts[:use_runtime_info]
       @seed = opts[:seed]
+      @profile = opts[:profile]
       @failure_count = 0
 
       @messages = Queue.new
@@ -168,6 +175,8 @@ module TurboTests
           *tests,
         ]
 
+        env["DISCOURSE_RSPEC_PROFILE_EACH_EXAMPLE"] = "1" if @profile
+
         if @verbose
           command_str =
             [env.map { |k, v| "#{k}=#{v}" }.join(" "), command.join(" ")].select { |x| x.size > 0 }

spec/rails_helper.rb

@@ -369,6 +369,13 @@ RSpec.configure do |config|
     end
   end
 
+  if ENV["DISCOURSE_RSPEC_PROFILE_EACH_EXAMPLE"]
+    config.around :each do |example|
+      measurement = Benchmark.measure { example.run }
+      RSpec.current_example.metadata[:run_duration_ms] = (measurement.real * 1000).round(2)
+    end
+  end
+
   config.before :each do
     # This allows DB.transaction_open? to work in tests. See lib/mini_sql_multisite_connection.rb
     DB.test_transaction = ActiveRecord::Base.connection.current_transaction