diff --git a/bin/turbo_rspec b/bin/turbo_rspec index 9d6a503721b..75cf12f4cf4 100755 --- a/bin/turbo_rspec +++ b/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 diff --git a/lib/turbo_tests/base_formatter.rb b/lib/turbo_tests/base_formatter.rb new file mode 100644 index 00000000000..ab715a11def --- /dev/null +++ b/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 diff --git a/lib/turbo_tests/documentation_formatter.rb b/lib/turbo_tests/documentation_formatter.rb index 1fefc07c407..4aed5897577 100644 --- a/lib/turbo_tests/documentation_formatter.rb +++ b/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}" \ - " (PENDING: #{message})", + "#{output_example(notification.example)} (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}" \ - " (FAILED - #{next_failure_index})", + "#{output_example(notification.example)} (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 diff --git a/lib/turbo_tests/json_rows_formatter.rb b/lib/turbo_tests/json_rows_formatter.rb index 35118c35027..9ebe04f1603 100644 --- a/lib/turbo_tests/json_rows_formatter.rb +++ b/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, } diff --git a/lib/turbo_tests/progress_formatter.rb b/lib/turbo_tests/progress_formatter.rb index 1d2b746d818..210a8bd08d1 100644 --- a/lib/turbo_tests/progress_formatter.rb +++ b/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( diff --git a/lib/turbo_tests/reporter.rb b/lib/turbo_tests/reporter.rb index be3a6771c5b..068735020c6 100644 --- a/lib/turbo_tests/reporter.rb +++ b/lib/turbo_tests/reporter.rb @@ -2,8 +2,8 @@ module TurboTests class Reporter - def self.from_config(formatter_config, start_time) - reporter = new(start_time) + def self.from_config(formatter_config, start_time, max_timings_count: nil) + 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 diff --git a/lib/turbo_tests/runner.rb b/lib/turbo_tests/runner.rb index f3caebffd53..946217088cb 100644 --- a/lib/turbo_tests/runner.rb +++ b/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 } diff --git a/spec/rails_helper.rb b/spec/rails_helper.rb index 4dd001c1f63..aefe966ad4e 100644 --- a/spec/rails_helper.rb +++ b/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