crystal-lang / crystal

The Crystal Programming Language
https://crystal-lang.org
Apache License 2.0
19.34k stars 1.61k forks source link

Sleep less than 1ms #6586

Open kochka opened 6 years ago

kochka commented 6 years ago

A sleep under 1ms make a sleep of 1ms.

# 100µs sleep
puts  Time.measure { sleep 100e-6 }

# =>  00:00:00.003399000

Crystal 0.26.0 (2018-08-13)

straight-shoota commented 6 years ago

Timer resolution just isn't that precise. This is not an issue with Crystal but how your operating system works. When your program sleeps, it likely changes execution to a different program and it can take well over 1ms until your program is continued again and has a chance to react to the timeout. Even if there are no OS context switches involved because your program is busy in a different fiber and execution stays within the Crystal program, fiber switches can only happen at specific points in code which again can be well over 1ms apart from each other.

I don't think there is any way to accurately schedule such a short a sleep time out.

Of course, time resolution depends on the operating system, so there can be specific configurations that provide better slutions. But anything below 10ms or so (probably even higher) seems unlikely unless you have a real-time operating system.

asterite commented 6 years ago

Right, initially I thought it was a bug in the math we are doing converting from number to Time::Span to a C timeval struct, but everything looks fine now that I don't look at it at midnight :-P

Right now we are using libevent, and to add an event that wait for some time you need to pass it a C timeval struct, and that has a maximum resolution of one microsecond.

I tried this program:

[0.1, 0.01, 0.001, 0.0001, 0.00001, 0.000001, 0.0000001, 0.00000001, 0.000000001].each do |interval|
  puts Time.measure { sleep interval }
end

Compiled with --release and executed, I get this result:

00:00:00.105064265
00:00:00.011180089
00:00:00.001233431
00:00:00.000137060
00:00:00.000020719
00:00:00.000023988
00:00:00.000002905
00:00:00.000001894
00:00:00.000001780

So at least up to one microsecond it's working more or less fine.

@kochka did you run your program with --release? Also, what's your OS?

kochka commented 6 years ago

I tried on Arch Linux x86_64 Raspberry Pi Raspbian ARM (cross compiled with 0.26 and locally compiled with 0.22) with no success but without --release flag

I just tried on another Arch Linux desktop (because I'm at work) with and without --release and I've the same issue.

00:00:00.100243416
00:00:00.010106960
00:00:00.001092761
00:00:00.003290606
00:00:00.003278467
00:00:00.003269036
00:00:00.000004445
00:00:00.000003276
00:00:00.000001556

@straight-shoota I'm well aware of that but I need microseconds delays, maybe it could also be implemented in a delay method for more clarity ?

RX14 commented 6 years ago

the time going up is suspicious, and hovering around the value 32 is very suspicious

kochka commented 6 years ago

Just to add another example

puts "Libc usleep"
1000.step(to: 0, by: -100) do |t|
  puts Time.measure { C.usleep t }
end

puts "\nCrystal sleep"
1000.step(to: 0, by: -100) do |t|
  puts Time.measure { sleep t / 1e6 }
end

lib C
  fun usleep(useconds_t : Int32) : Int32
end
Libc usleep
00:00:00.001085496
00:00:00.000982670
00:00:00.000895679
00:00:00.000795019
00:00:00.000697595
00:00:00.000577723
00:00:00.000478564
00:00:00.000377908
00:00:00.000277813
00:00:00.000178414
00:00:00.000053182

Crystal sleep
00:00:00.002188195
00:00:00.003180527
00:00:00.003208134
00:00:00.004308357
00:00:00.003232529
00:00:00.003232693
00:00:00.003246281
00:00:00.003253036
00:00:00.003249364
00:00:00.003226399
00:00:00.000003108
asterite commented 6 years ago

It works well in Mac, so it seems like a bug in linux. Someone should investigate this. I'm not sure this linux is 32 or 64 bits. @kochka what's your architecture?

kochka commented 6 years ago

@asterite I've tried on 2 different Arch Linux 64 bits (Core I7) and a RaspberryPi ARMv7 32 bits with same results.

rdp commented 4 years ago

Yep works fine OS X, but ubuntu 19.10, with various numbers, looks like this:

...
00:00:00.004152879
00:00:00.004157976
00:00:00.004164055
00:00:00.004194414
...
00:00:00.003357020
00:00:00.004483488
00:00:00.003307450
00:00:00.002304588 # on occasion I'll get it this low, at best
00:00:00.000008065

usleep works perfect. So it seems to be using multiples of 0.0011 for my machine. Don't know why Linux wouldn't fix select (or epoll) or whatever when they implemented usleep... Modifying /proc/sys/kernel/sched_rr_timeslice_ms doesn't seem to affect it :|

Possibilities as workarounds till it's fixed:

Might be able to write some "busy-ish" loop that calls usleep and Fiber.yield over and over until the desired time has elapsed...though if there are other fibers they might still call to select and, same problem...

Or maybe a new thread that sends a packet to some local special socket you're reading from to wake it up at "right on time"...wonder how golang does it, seems to work OK (its own scheduler thread perhaps?)...

Or using raw threads?

1000.step(to: 0, by: -100) do |t|
  puts Time.measure {
    Thread.new {
      C.usleep t 
    }.join
  }
end
lib C
  fun usleep(useconds_t : Int32) : Int32
end

A little scary? Is that even allowed? :)

ysbaddaden commented 4 years ago

I wouldn't try to outsmart libevent timers, especially since they somewhat fixed it in 2.1.2+ to have microsecond precision on linux/epoll with optional config option (EVENT_BASE_FLAG_PRECISE_TIMER). It's documented as "more precise but less efficient". It can be enabled with the EVENT_PRECISE_TIMER environment variable.

For example Ary's test from above, on Ubuntu 18.04 with libevent 2.1.6 with epoll precision (ms):

$ crystal run --release sleep_precision.cr
00:00:00.100251797
00:00:00.010165819
00:00:00.002224130
00:00:00.004362376
00:00:00.004398384
00:00:00.003250108
00:00:00.000004241
00:00:00.000001098
00:00:00.000001093

Same environment, with precise (µs) but inefficient timer:

$ EVENT_PRECISE_TIMER=1 crystal run --release sleep_precision.cr
00:00:00.100058809
00:00:00.010089082
00:00:00.001027991
00:00:00.000112942
00:00:00.000017708
00:00:00.000007506
00:00:00.000002489
00:00:00.000001840
00:00:00.000001768

See CHANGELOG:

PORTABLE MONOTONIC TIMERS:

Libevent 2.1.2 includes internal support for monotonic timers on (nearly) all supported platforms, including Windows, and OSX. Libevent applications should now be more resilient to jumps forwards or backwards in the system clock. Also, on Linux systems with epoll, we now optionally support microsecond-level timeouts (whereas epoll only supports millisecond-precision timeouts).

And event_base_config_flag documentation.

I'm not sure what they mean with "less efficient", maybe it's because the precision must be handled separately, instead of leveraging epoll timeouts.

RX14 commented 4 years ago

I'm not sure what they mean with "less efficient", maybe it's because the precision must be handled separately, instead of leveraging epoll timeouts.

They just means that they need an additional timerfd_settime call for each event loop iteration. It could be benchmarked, but I suspect for crystal's application it makes little if any difference.

rdp commented 1 year ago

Yeah looks like all it does it create one extra timer/loop, it still uses epoll. Maybe the next version of libevent will have improved this anyway? https://github.com/libevent/libevent/commit/117ee9a03fc74617e378f755c6b25005ac0e954f

erdian718 commented 12 months ago

The semantics of sleep n should be "at least sleep n seconds", and the actual sleep time can be greater than expected.

Time.measure { sleep 100e-6 } # => 00:00:00.003399000

I think this is no problem, as mentioned by @straight-shoota:

Timer resolution just isn't that precise. This is not an issue with Crystal but how your operating system work.

However, I found the opposite on Windows:

Time.measure { sleep 0.001 } # => 00:00:00.000008300

The actual sleep time is less than expected, which should be a bug.

My environment is:

Crystal 1.9.2 [1908c81] (2023-07-19)

LLVM: 16.0.3
Default target: x86_64-pc-windows-msvc
crysbot commented 4 months ago

This issue has been mentioned on Crystal Forum. There might be relevant details there:

https://forum.crystal-lang.org/t/how-to-sleep-for-nanoseconds/6836/4