Manageiq: Benchmark.realtime_block's ensure can be interrupted by a MiqQueue TimeoutError

[jrafanie]

It looks like it's possible for the ensure block in Benchmark.realtime_block to be interrupted by a TimeoutError from the queue, causing the timing results to never get reset:

grep -E "#31387" log/evm.log | grep -o "total_time=>[0-9]*\.[0-9]*"
total_time=>3.7621521949768066
total_time=>4.0121684074401855
total_time=>4.326230525970459
total_time=>4.696136236190796
total_time=>9.155161142349243
total_time=>9.155161142349243
total_time=>9.165400743484497
total_time=>9.184295654296875
total_time=>9.196443557739258
total_time=>9.208587408065796
total_time=>9.2324378490448
total_time=>9.241880178451538
total_time=>9.256477355957031
total_time=>9.270721673965454
total_time=>9.284515619277954
total_time=>9.29817533493042
total_time=>9.32113242149353
total_time=>9.343579292297363
total_time=>9.35648775100708
total_time=>10.613795042037964
total_time=>14.181613206863403
total_time=>14.181613206863403
total_time=>14.884168148040771
total_time=>18.260033130645752
...
total_time=>1974.3429281711578
total_time=>1974.3602719306946
total_time=>1974.374357700348
total_time=>1974.3870587348938
total_time=>1974.399513244629
total_time=>1975.1172680854797
total_time=>1979.7663094997406
total_time=>1979.7663094997406
total_time=>1979.7774863243103

This test will sometimes fail:

diff --git a/gems/pending/spec/util/extensions/miq-benchmark_spec.rb b/gems/pending/spec/util/extensions/miq-benchmark_spec.rb
index 63f874a..8db2f82 100644
--- a/gems/pending/spec/util/extensions/miq-benchmark_spec.rb
+++ b/gems/pending/spec/util/extensions/miq-benchmark_spec.rb
@@ -51,6 +51,23 @@ describe Benchmark do
     expect(timings[:test3]).to be_within(0.5).of(500)
   end

+  10_000.times do |i|
+    it "Timeout raising within .realtime_block #{i}" do
+      begin
+        result, timings = Timeout.timeout(0.000000000001) do
+          Benchmark.realtime_block(:test1) do
+            Benchmark.realtime_block(:test2) do
+            end
+            "test"
+          end
+        end
+      rescue TimeoutError
+      end
+
+      expect(Benchmark.in_realtime_block?).to be_falsey
+    end
+  end
+

It's horrible but we can make MiqQueue's rescue of TimeoutError be responsible for clearing the Benchmark thread local variable in case it "may have been" interrupted the ensure block.

I'd rather we not use Timeout.timeout. 😢

[jrafanie]

cc @Fryguy

[Fryguy]

:( It is what it is

[miq-bot]

This issue has been automatically marked as stale because it has not been updated for at least 6 months.

If you can still reproduce this issue on the current release or on master, please reply with all of the information you have about it in order to keep the issue open.

Thank you for all your contributions!

[cben]

Saw this again in production, it's annoying. It's also causing pressure towards dumb unstructured logging.
Wanted to find mitigation and I think I found (ugly) solution: https://github.com/ManageIQ/manageiq-gems-pending/pull/263

There is no global fix, there are other cleanups Timeout can mess...
This might be fixable in Ruby itself, if injecting exception into a thread could wait until it's not handling/propogating another exception.