diff --git a/spec/support/rspec_run_time.rb b/spec/support/rspec_run_time.rb index 875bdc0852e792166072816ee1feb8952133f578..841f714e3692c6da7c035fe932ee325bf03d29f8 100644 --- a/spec/support/rspec_run_time.rb +++ b/spec/support/rspec_run_time.rb @@ -14,25 +14,72 @@ class RSpecFormatter < RSpec::Core::Formatters::BaseFormatter def start(_notification) @group_level = 0 @rspec_test_suite_start_time = Process.clock_gettime(Process::CLOCK_MONOTONIC) - output.puts "\n# Starting RSpec timer..." + output.puts "\n# [RSpecRunTime] Starting RSpec timer..." + + init_expected_duration_report end - def example_group_started(_notification) - @start_time = Process.clock_gettime(Process::CLOCK_MONOTONIC) if @group_level == 0 + def example_group_started(notification) + if @group_level == 0 + @current_group_start_time = Process.clock_gettime(Process::CLOCK_MONOTONIC) + file_path = spec_file_path(notification) + output.puts "# [RSpecRunTime] Starting example group #{file_path}. #{expected_run_time(file_path)}" + end + @group_level += 1 end def example_group_finished(notification) @group_level -= 1 if @group_level > 0 - return unless @group_level == 0 + if @group_level == 0 + file_path = spec_file_path(notification) + time_now = Process.clock_gettime(Process::CLOCK_MONOTONIC) + actual_duration = time_now - @current_group_start_time + + output.puts "\n# [RSpecRunTime] #{file_path} took #{readable_duration(actual_duration)}. " \ + "#{expected_run_time(file_path)}" + end + + output_elapsed_time + end + + private + + def expected_duration_report + report_path = ENV['KNAPSACK_RSPEC_SUITE_REPORT_PATH'] + + return unless report_path && File.exist?(report_path) + + # rubocop:disable Gitlab/Json -- regular JSON is sufficient + @expected_duration_report ||= JSON.parse(File.read(report_path)) + # rubocop:enable Gitlab/Json + end + alias_method :init_expected_duration_report, :expected_duration_report + + def spec_file_path(notification) + notification.group.metadata[:file_path].sub('./', '') + end + + def expected_run_time(spec_file_path) + return '' unless expected_duration_report + + expected_duration = expected_duration_report[spec_file_path] + return "Missing expected duration from Knapsack report for #{spec_file_path}." unless expected_duration + + "Expected to take #{readable_duration(expected_duration)}." + end + + def output_elapsed_time time_now = Process.clock_gettime(Process::CLOCK_MONOTONIC) - duration = time_now - @start_time - elapsed_time = time_now - @rspec_test_suite_start_time + elapsed_seconds = time_now - @rspec_test_suite_start_time + + # skip the output unless the duration increased by at least 1 second + unless @last_elapsed_seconds.nil? || elapsed_seconds - @last_elapsed_seconds < 1 + output.puts "# [RSpecRunTime] RSpec elapsed time: #{readable_duration(elapsed_seconds)}.\n\n" + end - output.puts "\n# Example group #{notification.group.description} " \ - "(#{notification.group.metadata[:file_path]}) took #{readable_duration(duration)}." - output.puts "# RSpec elapsed time: #{readable_duration(elapsed_time)}.\n\n" + @last_elapsed_seconds = elapsed_seconds end end end