3
N.times { Thread.new { puts Benchmark.measure { /* code */ } } }

Does the benchmark show the time actually spent executing the code in the thread?

Or does it show the total time the ruby interpreter has been running on any thread while the thread we are considering is alive (even if it is paused because another one is running)?

For example suppose that a thread A has been in execution for 1ms, then MRI switches to the thread B and stays there for 3ms. Finally thread A is executed again and after another 1ms it terminates.

For thread A does the benchmark shows 2ms or 5ms as the total time? (not real time)

UPDATE: I think that a single Sidekiq process spawns multiple Ruby threads. So it's equivalent to talk about Sidekiq jobs instead of threads. I have some Sidekiq jobs that take much more cpu time when Sidekiq is executing some other heavy jobs. This leads me to think that the benchmarking is including the time spent on other jobs. However maybe @mudasobwa is right and cpu time doesn't include the time spent on other threads/jobs. In that case the only explanation I can give is that the system connectivity/bandwidth is a bottleneck (and my lightweight jobs performance are affected by the other heavy jobs that consume a lot of bandwidth).

collimarco
  • 34,231
  • 36
  • 108
  • 142

1 Answers1

1

I wonder whether is it so hard to check?

▶ Benchmark.measure { 3.times { |i| 
    Thread.new { puts Benchmark.measure { sleep i }.inspect } 
  } }
#⇒ #<Benchmark::Tms:0x000000018c2818 @label="", @real=8.5858e-05, @cstime=0.0, @cutime=0.0, @stime=0.0, @utime=0.0, @total=0.0>
#⇒ #<Benchmark::Tms:0x000000018c3ab0 @cstime=0.0, @cutime=0.0, @label="", @real=0.000118425, @stime=0.0, @total=0.0, @utime=0.0>
#⇒ #<Benchmark::Tms:0x0000000183cc40 @label="", @real=1.000119122, @cstime=0.0, @cutime=0.0, @stime=0.0, @utime=0.0, @total=0.0>
#⇒ #<Benchmark::Tms:0x0000000183c7e0 @label="", @real=2.000088775, @cstime=0.0, @cutime=0.0, @stime=0.0, @utime=0.0, @total=0.0>

The second line is obviously the surrounding total.

OK, here is an example with awakened threads (last is the total):

▶ Benchmark.measure { 3.times { |i| Thread.new { puts Benchmark.measure { (i * 100_000_000).times { 2000 << 2 } }.inspect } } }
#⇒ #<Benchmark::Tms:0x000000016c6438 @label="", @real=2.377e-06, @cstime=0.0, @cutime=0.0, @stime=0.0, @utime=0.0, @total=0.0>
#⇒ #<Benchmark::Tms:0x000000016c5420 @label="", @real=9.034328202, @cstime=0.0, @cutime=0.0, @stime=0.0, @utime=9.040000000000001, @total=9.040000000000001>
#⇒ #<Benchmark::Tms:0x000000016c4a98 @label="", @real=13.769757073, @cstime=0.0, @cutime=0.0, @stime=0.010000000000000009, @utime=13.77, @total=13.78>
#⇒ #<Benchmark::Tms:0x000000016c6bb8 @cstime=0.0, @cutime=0.0, @label="", @real=5.1321e-05, @stime=0.0, @total=0.0, @utime=0.0>
Aleksei Matiushkin
  • 119,336
  • 10
  • 100
  • 160
  • It's not so clear. Since total time in your snippet is always zero I guess that only the time actually spent on the thread is counted. However I am not fully convinced: in your case all threads are sleeping so maybe also the interpreter is doing the same. – collimarco Jun 23 '16 at 13:52