wip - debug grind test failures on truffleruby

Shopify · Apr 11, 2023 · 53e4ae2 · 53e4ae2
1 parent 10d895f
commit 53e4ae2
Showing 1 changed file with 47 additions and 18 deletions.
diff --git a/ruby/test/integration/grind_redis_test.rb b/ruby/test/integration/grind_redis_test.rb
@@ -5,6 +5,16 @@ module Integration
   class GrindRedisTest < Minitest::Test
     include OutputTestHelpers
 
+    class StopWatch
+      attr_reader :duration
+      def measure
+        start = Process.clock_gettime(Process::CLOCK_MONOTONIC)
+        yield
+      ensure
+        @duration = Process.clock_gettime(Process::CLOCK_MONOTONIC) - start
+      end
+    end
+
     def setup
       @redis_url = ENV.fetch('REDIS_URL', 'redis://localhost:6379/0')
       @redis = Redis.new(url: @redis_url)
@@ -96,22 +106,35 @@ def test_grind_command_runs_tests
     end
 
     def test_grind_max_time
-      grind_count = 1000000
-      system(
-        { 'BUILDKITE' => '1' },
-        @exe, 'grind',
-        '--queue', @redis_url,
-        '--seed', 'foobar',
-        '--build', '1',
-        '--worker', '1',
-        '--timeout', '1',
-        '--grind-count', grind_count.to_s,
-        '--grind-list', 'grind_list.txt',
-        '--max-duration', '1',
-        '-Itest',
-        'test/dummy_test.rb',
-        chdir: 'test/fixtures/',
-      )
+      grind_count = 10000000
+      stopwatch = StopWatch.new
+      out, err = stopwatch.measure do
+        capture_subprocess_io do
+          system(
+            { 'BUILDKITE' => '1' },
+            @exe, 'grind',
+            '--queue', @redis_url,
+            '--seed', 'foobar',
+            '--build', '1',
+            '--worker', '1',
+            '--timeout', '1',
+            '--grind-count', grind_count.to_s,
+            '--grind-list', 'grind_list.txt',
+            '--max-duration', '1',
+            '-Itest',
+            'test/dummy_test.rb',
+            chdir: 'test/fixtures/',
+          )
+        end
+      end
+
+      # Ensure it respected the timeout (without trying to measure how long the process actually took.
+      assert_match(/reached its timeout of 1 seconds/, err)
+
+      STDERR.puts "took: #{stopwatch.duration}"
+      # assert_operator(duration, :>=, 1, "Should take at least 1s")
+      # Allow some time for startup/teardown.
+      # assert_operator(duration, :<=, 13, "Should abort after 1s")
 
       out, err = capture_subprocess_io do
         system(
@@ -126,8 +149,14 @@ def test_grind_max_time
         )
       end
 
-      output = normalize(out).strip
-      runs_line = output.lines[2]
+      output_lines = normalize(out).strip.lines
+      STDERR.puts output_lines.inspect
+      runs_line = output_lines[2]
+
+      #refute_match(/all tests passed/, output_lines[1].to_s)
+      refute_nil(runs_line, "'Runs:' line not found at index 2 of #{output_lines.inspect}")
+      assert_match(/Runs: \d+/, runs_line)
+
       run_count = runs_line.scan(/\w+/).last.to_i
 
       assert_empty err