Add time details about test runs

Store timestamps related to when a test begun running and when it finished.

We currently have access to the overall time the test took, but not at what point in time the test was run.

ruby/lib/ci/queue/version.rb

@@ -2,7 +2,7 @@
 
 module CI
   module Queue
-    VERSION = '0.20.9'
+    VERSION = '0.21.0'
     DEV_SCRIPTS_ROOT = ::File.expand_path('../../../../../redis', __FILE__)
     RELEASE_SCRIPTS_ROOT = ::File.expand_path('../redis', __FILE__)
   end

ruby/lib/minitest/queue.rb

@@ -102,6 +102,10 @@ def mark_as_flaked!
     end
   end
 
+  module WithTimestamps
+    attr_accessor :start_timestamp, :finish_timestamp
+  end
+
   module Queue
     attr_writer :run_command_formatter, :project_root
 
@@ -159,13 +163,30 @@ def <=>(other)
         id <=> other.id
       end
 
+      def with_timestamps
+        start_timestamp = current_timestamp
+        result = yield
+        result
+      ensure
+        result.start_timestamp = start_timestamp
+        result.finish_timestamp = current_timestamp
+      end
+
       def run
-        Minitest.run_one_method(@runnable, @method_name)
+        with_timestamps do
+          Minitest.run_one_method(@runnable, @method_name)
+        end
       end
 
       def flaky?
         Minitest.queue.flaky?(self)
       end
+
+      private
+
+      def current_timestamp
+        Time.now.to_i
+      end
     end
 
     attr_reader :queue
@@ -244,9 +265,11 @@ def run_from_queue(reporter, *)
 if defined? MiniTest::Result
   MiniTest::Result.prepend(MiniTest::Requeueing)
   MiniTest::Result.prepend(MiniTest::Flakiness)
+  MiniTest::Result.prepend(MiniTest::WithTimestamps)
 else
   MiniTest::Test.prepend(MiniTest::Requeueing)
   MiniTest::Test.prepend(MiniTest::Flakiness)
+  MiniTest::Test.prepend(MiniTest::WithTimestamps)
 
   module MinitestBackwardCompatibility
     def source_location

ruby/lib/minitest/queue/test_data.rb

@@ -52,6 +52,14 @@ def test_duration
         @test.time
       end
 
+      def test_start_timestamp
+        @test.start_timestamp
+      end
+
+      def test_finish_timestamp
+        @test.finish_timestamp
+      end
+
       def test_file_path
         path = @test.source_location.first
         begin
@@ -107,6 +115,8 @@ def to_h
           test_retried: test_retried,
           test_assertions: test_assertions,
           test_duration: test_duration,
+          test_start_timestamp: test_start_timestamp,
+          test_finish_timestamp: test_finish_timestamp,
           test_file_path: test_file_path,
           test_file_line_number: test_file_line_number,
           error_class: error_class,

ruby/test/fixtures/test/time_test.rb

@@ -0,0 +1,9 @@
+# frozen_string_literal: true
+require 'test_helper'
+
+class TimeTest < Minitest::Test
+  def test_foo
+    sleep(1)
+    assert true
+  end
+end

ruby/test/integration/minitest_redis_test.rb

@@ -1,10 +1,12 @@
 # frozen_string_literal: true
 require 'test_helper'
 require 'tmpdir'
+require 'active_support/testing/time_helpers'
 
 module Integration
   class MinitestRedisTest < Minitest::Test
     include OutputTestHelpers
+    include ActiveSupport::Testing::TimeHelpers
 
     def setup
       @junit_path = File.expand_path('../../fixtures/log/junit.xml', __FILE__)
@@ -347,54 +349,84 @@ def test_test_data_reporter
       output = normalize(out.lines.last.strip)
       assert_equal 'Ran 9 tests, 6 assertions, 1 failures, 1 errors, 1 skips, 2 requeues in X.XXs', output
 
+      content = File.read(@test_data_path)
+      failures = JSON.parse(content, symbolize_names: true)
+                     .sort_by { |h| "#{h[:test_id]}##{h[:test_index]}" }
+
+      assert_equal 'foo', failures[0][:namespace]
+      assert_equal 'ATest#test_bar', failures[0][:test_id]
+      assert_equal 'test_bar', failures[0][:test_name]
+      assert_equal 'ATest', failures[0][:test_suite]
+      assert_equal 'failure', failures[0][:test_result]
+      assert_equal true, failures[0][:test_retried]
+      assert_equal false, failures[0][:test_result_ignored]
+      assert_equal 1, failures[0][:test_assertions]
+      assert_equal 'test/dummy_test.rb', failures[0][:test_file_path]
+      assert_equal 9, failures[0][:test_file_line_number]
+      assert_equal 'Minitest::Assertion', failures[0][:error_class]
+      assert_equal 'Expected false to be truthy.', failures[0][:error_message]
+      assert_equal 'test/dummy_test.rb', failures[0][:error_file_path]
+      assert_equal 10, failures[0][:error_file_number]
+
+      assert_equal 'foo', failures[1][:namespace]
+      assert_equal 'ATest#test_bar', failures[1][:test_id]
+      assert_equal 'test_bar', failures[1][:test_name]
+      assert_equal 'ATest', failures[1][:test_suite]
+      assert_equal 'failure', failures[1][:test_result]
+      assert_equal false, failures[1][:test_result_ignored]
+      assert_equal false, failures[1][:test_retried]
+      assert_equal 1, failures[1][:test_assertions]
+      assert_equal 'test/dummy_test.rb', failures[1][:test_file_path]
+      assert_equal 9, failures[1][:test_file_line_number]
+      assert_equal 'Minitest::Assertion', failures[1][:error_class]
+      assert_equal 'Expected false to be truthy.', failures[1][:error_message]
+      assert_equal 'test/dummy_test.rb', failures[1][:error_file_path]
+      assert_equal 10, failures[1][:error_file_number]
+
+      assert failures[0][:test_index] < failures[1][:test_index]
+
+      assert_equal 'ATest#test_flaky', failures[2][:test_id]
+      assert_equal 'skipped', failures[2][:test_result]
+      assert_equal false, failures[2][:test_retried]
+      assert_equal true, failures[2][:test_result_ignored]
+      assert_equal 1, failures[2][:test_assertions]
+      assert_equal 'test/dummy_test.rb', failures[2][:test_file_path]
+      assert_equal 13, failures[2][:test_file_line_number]
+      assert_equal 'Minitest::Assertion', failures[2][:error_class]
+      assert_equal 18, failures[2][:error_file_number]
+
+      assert_equal 'ATest#test_flaky_passes', failures[4][:test_id]
+      assert_equal 'success', failures[4][:test_result]
+    end
+
+    def test_test_data_time_reporter
+      start_time = Time.now
+      travel_to(start_time) do
+        capture_subprocess_io do
+          system(
+            @exe, 'run',
+            '--queue', @redis_url,
+            '--seed', 'foobar',
+            '--namespace', 'foo',
+            '--build', '1',
+            '--worker', '1',
+            '--timeout', '10',
+            '-Itest',
+            'test/time_test.rb',
+            chdir: 'test/fixtures/',
+          )
+        end
+      end
+      end_time = Time.now
+
       content = File.read(@test_data_path)
       failure = JSON.parse(content, symbolize_names: true)
                     .sort_by { |h| "#{h[:test_id]}##{h[:test_index]}" }
+                    .first
 
-      assert_equal 'foo', failure[0][:namespace]
-      assert_equal 'ATest#test_bar', failure[0][:test_id]
-      assert_equal 'test_bar', failure[0][:test_name]
-      assert_equal 'ATest', failure[0][:test_suite]
-      assert_equal 'failure', failure[0][:test_result]
-      assert_equal true, failure[0][:test_retried]
-      assert_equal false, failure[0][:test_result_ignored]
-      assert_equal 1, failure[0][:test_assertions]
-      assert_equal 'test/dummy_test.rb', failure[0][:test_file_path]
-      assert_equal 9, failure[0][:test_file_line_number]
-      assert_equal 'Minitest::Assertion', failure[0][:error_class]
-      assert_equal 'Expected false to be truthy.', failure[0][:error_message]
-      assert_equal 'test/dummy_test.rb', failure[0][:error_file_path]
-      assert_equal 10, failure[0][:error_file_number]
-
-      assert_equal 'foo', failure[1][:namespace]
-      assert_equal 'ATest#test_bar', failure[1][:test_id]
-      assert_equal 'test_bar', failure[1][:test_name]
-      assert_equal 'ATest', failure[1][:test_suite]
-      assert_equal 'failure', failure[1][:test_result]
-      assert_equal false, failure[1][:test_result_ignored]
-      assert_equal false, failure[1][:test_retried]
-      assert_equal 1, failure[1][:test_assertions]
-      assert_equal 'test/dummy_test.rb', failure[1][:test_file_path]
-      assert_equal 9, failure[1][:test_file_line_number]
-      assert_equal 'Minitest::Assertion', failure[1][:error_class]
-      assert_equal 'Expected false to be truthy.', failure[1][:error_message]
-      assert_equal 'test/dummy_test.rb', failure[1][:error_file_path]
-      assert_equal 10, failure[1][:error_file_number]
-
-      assert failure[0][:test_index] < failure[1][:test_index]
-
-      assert_equal 'ATest#test_flaky', failure[2][:test_id]
-      assert_equal 'skipped', failure[2][:test_result]
-      assert_equal false, failure[2][:test_retried]
-      assert_equal true, failure[2][:test_result_ignored]
-      assert_equal 1, failure[2][:test_assertions]
-      assert_equal 'test/dummy_test.rb', failure[2][:test_file_path]
-      assert_equal 13, failure[2][:test_file_line_number]
-      assert_equal 'Minitest::Assertion', failure[2][:error_class]
-      assert_equal 18, failure[2][:error_file_number]
-
-      assert_equal 'ATest#test_flaky_passes', failure[4][:test_id]
-      assert_equal 'success', failure[4][:test_result]
+      assert_in_delta start_time.to_i, failure[:test_start_timestamp], 5
+      assert_in_delta end_time.to_i, failure[:test_finish_timestamp], 5
+      assert failure[:test_finish_timestamp] > failure[:test_start_timestamp]
     end
 
     def test_junit_reporter