In Progress
Unit 1, Lesson 1
In Progress

Sleep

Video transcript & code

When we want to make a Ruby program, or the current thread of a program, stop and do nothing for a period of time, we use the #sleep method. This is probably not news to you. #sleep takes one argument, a number of seconds to sleep. This argument can be a floating point number, which enables us to specify sleep intervals of less than a second.

sleep 5 # sleep 5 seconds
sleep 0.1 # sleep 1 tenth of a second

Sleep isn't the only place we might tell the program to wait for a while. In recent episodes we've also seen how we can wait for a given period of time for a condition variable to be signaled.

cv = ConditionVariable.new
lock = Mutex.new
lock.synchronize do
  cv.wait(lock, 1)
  # ...
end

#sleep doesn't seem like a very interesting method. But there's something I've always wondered about: just how accurate is it? In other words, if I tell the program to sleep for, say, 10 milliseconds, how sure can I be that it will wait exactly that long? If it isn't exact, will the interval be longer or shorter than the one I specified? And by how much? With a floating point argument I can specify arbitrarily small intervals, but at what point do they become too small for Ruby to obey my instruction?

OK, maybe these aren't questions that keep you awake at night, but I hope you'll indulge me for a few minutes as we write some code to satisfy my curiosity.

Our benchmark script will take two arguments, one for the length of sleep it should test, and a second specifying how many seconds to spend repeating the test and collecting data. It determines the number of repetitions from these two numbers.

Next we declare a couple of variables, an array to collect data samples, and another to measure the total real time it took to perform the full test.

For each repetition, we measure the actual duration of a call to #sleep. We do the measurement using a gem called "Hitimes". This handy gem provides tools for very accurate measurements of time intervals. It does this by using the most accurate low-level system calls for time measurement that are available from whatever operating system it is used on.

Inside the measurement block, we do the actual sleeping. Then we add the measured duration to our list of samples, increment the total duration by the measured time, and repeat. We are careful to keep all of this bookeeping outside the measurement block.

require "thread"
require "hitimes"

duration = ARGV[0].to_f
seconds  = ARGV[1].to_f

repeat = (seconds / duration).to_i
samples = []
total_duration = 0.0
repeat.times do
  actual_duration = Hitimes::Interval.measure do
    sleep duration
  end
  samples << actual_duration
  total_duration += actual_duration
end

Next we use the code we came up with in episode 150 to calculate min, max, average, median, and standard deviation from the collected samples.

min = samples.min
max = samples.max
sum = samples.reduce(:+)
avg = sum / samples.size
sorted = samples.sort
half_size = sorted.size / 2
q, r = sorted.size.divmod(2)
middle = sorted[q - 1 + r, 2 - r]
med = middle.reduce(:+) / middle.size
std = Math.sqrt(samples.map{|n| (n - avg) ** 2}.reduce(:+) / samples.size)

Finally, we output lots of information about what we have discovered.

puts "Sleep duration: #{duration}"
puts "Repeat: #{repeat}"
puts "Ideal length: #{duration * repeat} seconds"
puts "Actual length: #{total_duration} seconds"
puts "Samples: #{samples.size}"
puts "Min: #{samples.min}"
puts "Max: #{samples.max}"
puts "Avg: #{avg}"
puts "Median: #{med}"
puts "Std dev: #{std}"

Let's give this script a whirl. We'll start by trying a sleep of a tenth of a second, repeated for a period of 5 seconds.

The results tell us that the minimum actual sleep duration was a few hundred microseconds over a tenth of a second, the maximum was about a millisecond over the target time, and overall the average wait time was very very close to a tenth of a second.

$ ruby test-sleep.rb 0.1 5
Sleep duration: 0.1
Repeat: 50
Ideal length: 5.0 seconds
Actual length: 5.0044805000000006 seconds
Samples: 50
Min: 0.10006694
Max: 0.100131835
Avg: 0.10008961000000001
Median: 0.1000871425
Std dev: 2.015484080413578e-05

Next we'll try waiting for a one hundredth of a second, or 10 milliseconds. We'll do this for one second's worth of samples.

$ ruby test-sleep.rb 0.01 1
Sleep duration: 0.01
Repeat: 100
Ideal length: 1.0 seconds
Actual length: 1.0084955079999998 seconds
Samples: 100
Min: 0.010057735
Max: 0.010149375
Avg: 0.010084955079999998
Median: 0.010075866999999999
Std dev: 2.513492319848217e-05

Once again, the numbers all look very close to the target duration. The average wait exceeds the target time by only about 85 microseconds.

Next, we'll try waiting for a milliscond.

$ ruby test-sleep.rb 0.001 1            
Sleep duration: 0.001
Repeat: 1000
Ideal length: 1.0 seconds
Actual length: 1.0832039779999998 seconds
Samples: 1000
Min: 0.001014563
Max: 0.002941898
Avg: 0.0010832039779999998
Median: 0.0010679965
Std dev: 7.196325944716177e-05

This time our margin of error is starting to be a bit more meaningful. The maximum sleep time is almost three milliseconds, three times the number we specified. But the average sleep time is still less than 100 microseconds off from the time we specified.

Now let's try a wait of 100 microseconds. Again, we'll perform 1 second's worth of sleeps.

$ ruby test-sleep.rb 0.0001 1           
Sleep duration: 0.0001
Repeat: 10000
Ideal length: 1.0 seconds
Actual length: 1.5849713390000042 seconds
Samples: 10000
Min: 0.000112675
Max: 0.001965845
Avg: 0.00015849713390000042
Median: 0.000157477
Std dev: 2.491877949551643e-05

At this level of granularity, things start to go off the rails. The maximum sleep is almost twenty times our intended duration of 100us. The minimum sleep was still pretty close to what we asked for, but the average is around 150 microseconds. As a result, 10000 100us sleeps actually took over one and a half seconds worth of wall-clock time.

Let's take it one step further, to 10 microseconds.

$ ruby test-sleep.rb 0.00001 1          
Sleep duration: 1.0e-05
Repeat: 99999
Ideal length: 0.99999 seconds
Actual length: 6.690315132999939 seconds
Samples: 99999
Min: 1.7454e-05
Max: 0.004489594
Avg: 6.690382036820308e-05
Median: 6.732e-05
Std dev: 3.4818066154251705e-05

We are now well beyond the capabilities of the system. Our sleeps exceeded the specified durations by so much that what should have been 1 second's worth turned into close to 7 seconds. We have reached the point where specifying shorter sleeps is pointless, because the VM isn't capable of satisfying the request.

From what we've seen so far, we can make two observations: MRI, running on my linux machine with no significant CPU load, has a sleep accuracy of about a millisecond. There's little point in specifying sleeps or timeouts of less than that amount. And second, that when sleep is inaccurate, it always errs on the side of sleeping too long, never to short. As we saw in the last couple of tests, this means that when we have a program with many very short sleeps, we can experience "drift" as the cumulative error of all those wait times adds up.

Let's now try this test on JRuby and Rubinius, starting at 1 millisecond.

$ rvm jruby,rbx --verbose do ruby test-sleep.rb 0.001 1                                                              
jruby-1.7.4: jruby 1.7.4 (1.9.3p392) 2013-05-16 2390d3b on Java HotSpot(TM) 64-B
it Server VM 1.7.0_21-b11 [linux-amd64]                                        
Sleep duration: 0.001
Repeat: 1000
Ideal length: 1.0 seconds
Actual length: 1.1180506600000006 seconds
Samples: 1000
Min: 0.001026813
Max: 0.00272422
Avg: 0.0011180506600000006
Median: 0.0010890685
Std dev: 0.00011295048325847208
rbx-head: rubinius 2.0.0rc1 (1.9.3 release 2012-11-02 JI) [x86_64-unknown-linux-
gnu]                                                                           
Sleep duration: 0.001
Repeat: 1000
Ideal length: 1.0 seconds
Actual length: 1.083565672999999 seconds
Samples: 1000
Min: 0.001015623
Max: 0.004236704
Avg: 0.001083565672999999
Median: 0.0010594085000000001
Std dev: 0.00016947418052338264

Rubinius' performance is similar to that of MRI, although the maximum actual wait is a bit longer. JRuby tends to err a bit more on the side of longer waits, with an average real wait time of 1.1 milliseconds.

When we run this again for a specified wait of 100 microseconds, we see something interesting. For JRuby, the total wallclock time of a second's worth of sleeps is substantially less than a second this time. Remember, in all our previous tests this number was always higher than the ideal. It seems that at this level of granularity, JRuby's implementation may actually sleep for a shorter period than specified.

$ rvm jruby,rbx --verbose do ruby test-sleep.rb 0.0001 1                                                                
jruby-1.7.4: jruby 1.7.4 (1.9.3p392) 2013-05-16 2390d3b on Java HotSpot(TM) 64-Bit Server VM 1.7.0_21-b11 [linux-amd64]                                        
Sleep duration: 0.0001
Repeat: 10000
Ideal length: 1.0 seconds
Actual length: 0.05607388499999989 seconds
Samples: 10000
Min: 2.002e-06
Max: 0.000120069
Avg: 5.607388499999989e-06
Median: 5.64e-06
Std dev: 2.665470801334675e-06
rbx-head: rubinius 2.0.0rc1 (1.9.3 release 2012-11-02 JI) [x86_64-unknown-linux-gnu]                                                                           
Sleep duration: 0.0001
Repeat: 10000
Ideal length: 1.0 seconds
Actual length: 1.6065821489999945 seconds
Samples: 10000
Min: 0.000108257
Max: 0.00405398
Avg: 0.00016065821489999945
Median: 0.0001575355
Std dev: 7.936508640242704e-05

Bear in mind, when looking at all these numbers, that these are specific to my system, a dual-core I7 running linux, with relatively low load. Your results may differ, and I encourage you to run these benchmarks for yourself.

What I take away from these benchmarks is that down to a millisecond, #sleep is fairly reliable on all Ruby implementations. Anything shorter than that has quickly diminishing accuracy.

More broadly, these benchmarks are a reminder that as much as we think of our programs as perfect, logical machines, we still wind up dealing with the messy, unpredictable world of OS process schedulers, hardware limitations, and VM implementation differences. When it comes to time-sensitive operations, sometimes the only answer to the question "does this code behave the way I think it does" is to measure it for ourselves. Happy hacking!

Responses