ruby / timeout

Timeout provides a way to auto-terminate a potentially long-running operation if it hasn't finished in a fixed amount of time.
Other
143 stars 21 forks source link

Reimplement Timeout.timeout with a single thread and a Queue #15

Closed eregon closed 2 years ago

eregon commented 2 years ago

Related to discussion in #14.

I wrote all of the changed code myself, so there is no worry about relicensing or so (notably the rubysl-timeout repository which had the Rubinius timeout.rb no longer exists).

This seems to work great. I'd like a review, and I'll self-review in more details later.

eregon commented 2 years ago

For some reason it seems I can't push to eregon/timeout anymore, it sounds like a GitHub bug (I can push to other repos, filed as https://support.github.com/ticket/personal/0/1623804). I have a change locally to use a Mutex around both usages of the ConditionVariable.

eregon commented 2 years ago

I can now push again to this PR. test_skip_rescue currently fails on TruffleRuby, because apparently the semantics of Thread#raise is to call .exception twice, once in the caller with the passed args, once the callee/thread with no args:

[:exception, #<Thread:0x0000000001c2aff0 sleep>, #<Thread:0x000000000245ce30 /home/eregon/code/timeout/lib/timeout.rb:98 run>, ["execution expired"]]
/home/eregon/code/timeout/lib/timeout.rb:41:in `exception'
/home/eregon/code/timeout/lib/timeout.rb:85:in `raise'
/home/eregon/code/timeout/lib/timeout.rb:85:in `interrupt'
/home/eregon/code/timeout/lib/timeout.rb:115:in `block (3 levels) in ensure_timer_thread_created'
/home/eregon/code/timeout/lib/timeout.rb:114:in `each'

[:exception, #<Thread:0x0000000001c2aff0 run>, #<Thread:0x0000000001c2aff0 run>, []]
/home/eregon/code/timeout/lib/timeout.rb:41:in `exception'
/home/eregon/code/timeout/test/test_timeout.rb:44:in `sleep'
/home/eregon/code/timeout/test/test_timeout.rb:44:in `block (2 levels) in test_skip_rescue'
/home/eregon/code/timeout/lib/timeout.rb:168:in `block in timeout'
/home/eregon/code/timeout/lib/timeout.rb:36:in `block in catch'

JRuby already has this behavior, so it passes the test. I'll implement it in TruffleRuby shortly.

headius commented 2 years ago

This implementation appears to be the slowest at this point, but I think there's a bug or leak of some kind. My naive benchmark of repeatedly timing out an empty block gets progressively slower over time:

  3.220000   0.140000   3.360000 (  0.662429)
  1.430000   0.100000   1.530000 (  0.337033)
  0.640000   0.060000   0.700000 (  0.230855)
  0.310000   0.030000   0.340000 (  0.214395)
  0.370000   0.040000   0.410000 (  0.265558)
  0.400000   0.040000   0.440000 (  0.301773)
  0.470000   0.040000   0.510000 (  0.352947)
  0.500000   0.050000   0.550000 (  0.400549)
  0.570000   0.040000   0.610000 (  0.451679)
  0.600000   0.050000   0.650000 (  0.490104)
  0.650000   0.040000   0.690000 (  0.541781)
  0.710000   0.040000   0.750000 (  0.579973)
  0.730000   0.050000   0.780000 (  0.620071)
  0.780000   0.040000   0.820000 (  0.668899)
  0.850000   0.050000   0.900000 (  0.710506)
  0.860000   0.040000   0.900000 (  0.751403)
  0.950000   0.060000   1.010000 (  0.805190)
  0.950000   0.040000   0.990000 (  0.838300)
  1.000000   0.040000   1.040000 (  0.882479)
  1.090000   0.060000   1.150000 (  0.936747)
headius commented 2 years ago

The effect is even more pronounced on TruffleRuby 21.3:

  1.969755   0.272882   2.242637 (  0.510549)
  1.719021   0.110678   1.829699 (  0.550959)
  0.865643   0.073941   0.939584 (  0.705021)
  1.262547   0.056139   1.318686 (  0.889787)
  1.235676   0.050018   1.285694 (  1.115480)
  1.577690   0.050819   1.628509 (  1.355579)
  1.615203   0.050036   1.665239 (  1.585228)
  1.884731   0.055752   1.940483 (  1.828664)
  2.120939   0.056803   2.177742 (  2.066626)
  2.362214   0.060254   2.422468 (  2.303767)
  2.630854   0.069365   2.700219 (  2.586945)
  2.918658   0.111934   3.030592 (  2.947546)
  3.140192   0.085695   3.225887 (  3.095570)
  3.339673   0.076553   3.416226 (  3.281839)
  3.572319   0.079379   3.651698 (  3.508616)
  3.836364   0.081716   3.918080 (  3.763093)
  4.163373   0.111359   4.274732 (  4.142380)
  4.305321   0.084561   4.389882 (  4.250139)
  4.569104   0.088801   4.657905 (  4.518466)
  4.797161   0.089402   4.886563 (  4.766448)
eregon commented 2 years ago

Indeed. The problem is I used Mutex#try_lock like an atomic flag, but because it's not unlocked it stays in a list/array on the Ruby Thread and is never removed (except on process shutdown). Those semantics of a Thread automatically releasing its Mutex when it dies are really ugly and in such a case they cause a leak and a lot of performance. On CRuby the process hangs for a long time just to release those locks. I fixed it now.

eregon commented 2 years ago

Performance:

require 'timeout'
require 'benchmark/ips'

Benchmark.ips do |x|
  x.report("timeout") do
    Timeout.timeout(1, Timeout::Error) {}
  end
end
CRuby 3.0.3
stdlib:
             timeout    106.778k (±20.5%) i/s -    511.511k in   5.041715s
this branch:
             timeout    356.527k (± 6.0%) i/s -      1.799M in   5.062773s

TruffleRuby dev
stdlib:
             timeout      1.282M (±57.1%) i/s -      3.449M in   5.111266s
this branch:
             timeout      1.069M (±17.5%) i/s -      5.328M in   5.099024s

JRuby dev
stdlib:
             timeout    287.614k (±14.4%) i/s -      1.424M in   5.081483s
this branch:
             timeout    411.755k (± 9.4%) i/s -      2.069M in   5.072408s

It seems a clear win for all on this benchmark.

eregon commented 2 years ago

The results above are with an explicit Timeout.timeout(1, Timeout::Error) {} which avoids the catch+throw way. Here are the results for Timeout.timeout(1) {}:

CRuby 3.0.3
stdlib:
             timeout     79.900k (±15.7%) i/s -    396.118k in   5.096547s
this branch:
             timeout    262.823k (± 7.5%) i/s -      1.320M in   5.046642s

TruffleRuby dev
stdlib:
             timeout      1.336M (±57.9%) i/s -      3.450M in   5.008162s
this branch:
             timeout    690.218k (± 9.7%) i/s -      3.438M in   5.033590s

JRuby dev
stdlib:
             timeout    261.070k (±12.5%) i/s -      1.289M in   5.016722s
this branch:
             timeout    350.589k (± 8.8%) i/s -      1.762M in   5.076461s

Still a clear gain for all. That is a bit slower than Timeout.timeout(1, Timeout::Error) {}, due to the extra catch call.

eregon commented 2 years ago

All green now.

headius commented 2 years ago

Perf on JRuby seems to be best with this implementation. I vote to merge and release this change.

headius commented 2 years ago

Anything holding this up? I've got folks at RailsConf interested in trying out JRuby 9.4 but I don't want them to have a poor experience due to the multi-thread timeout.