[erlang-questions] writing a delay loop without now()

[Per Hedeland]

James Hague <james.hague@REDACTED> wrote:
>
>First, try this from the shell:
>
>     erlang:statistics(wall_clock),timer:sleep(5000),erlang:statistics(wall_clock).
>
>I get {57018,5007} which is just about five seconds (the second number
>is the elapsed time between calls.  The parameter to sleep is in
>MILLIseconds.  (Note that if I change 5000 to 1, I get a result of 16
>milliseconds elapsed on the machine I'm using at the moment.  If I
>change it to 16, I get a result of 31 milliseconds.)

Right, this demonstrates the dependency of timer:sleep/1 on the OS timer
interrupt frequency that we already established - it doesn't demonstrate
that there is a problem with statistics(wall_clock), on the contrary it
probably reports the exact numbers that demonstrate the timer:sleep/1
dependency.

And as we also established, this has nothing to do with Erlang - any way
you try to implement "wait for some period of time without busy-looping"
will have this issue, including C library functions with fancy names and
arguments such as nanosleep(2) (actually the Linux man page says that it
busy-waited in certain cases in pre-2.6 kernels - not anymore though).

The only way you can improve on this is to increase the OS timer
interrupt frequency. FWIW, on stock FreeBSD 7.0 x86 with "Erlang (BEAM)
emulator version 5.6.3 [source] [async-threads:0] [hipe]
[kernel-poll:false]" I get:

 erlang:statistics(wall_clock),timer:sleep(1),erlang:statistics(wall_clock).
{1218509,3}
 erlang:statistics(wall_clock),timer:sleep(16),erlang:statistics(wall_clock).
{1228419,17}

- and basically the same (perhaps slightly better) on stock Fedora Core
5 Linux x86 with the venerable "Erlang (BEAM) emulator version 5.4.13
[source] [hipe]". Both of these systems nominally have a 1000 Hz system
clock - interestingly though, on the FreeBSD I get

 erlang:statistics(wall_clock),timer:sleep(5000),erlang:statistics(wall_clock).
{1873951,5048}

- i.e. it seems it is playing some tricks to avoid a constant 1000 Hz
interrupt rate, and not doing its absolutely best of it.

>Now here's a little function that uses now/0 and timer:now_diff/2 to
>wait for a specified number of MICROseconds:

[snip]

>Now try it from the shell:
>
>     erlang:statistics(wall_clock),test:time(5000000),erlang:statistics(wall_clock).
>
>I get {836723,1310} on the same machine.  1.3 seconds.

OK, now it gets interesting - this works exactly as expected for me, on
both the abovementioned systems:

 erlang:statistics(wall_clock),test:time(5000000),erlang:statistics(wall_clock).
{3998801,5000}

- occasionally the number is 5001, very rarely 5002. Could you try
adding a counter to the loop, to see how many now/0 calls you are
actually doing:

time2(N) -> time2(N, now(), 0).
time2(N, Start, C) ->
    case timer:now_diff(now(), Start) of
        M when M >= N -> {C, M};
        _ -> time2(N, Start, C+1)
    end.

With this I get:

 erlang:statistics(wall_clock),{test:time2(5000000),erlang:statistics(wall_clock)}.
{{1295305,5000001},{241916,5000}}

I.e. on the order of one call every 3.9 microseconds => no now/0 bumping
occurs (you need to have more than one call per microsecond *on average*
for that to have an effect on the total).

Also, what version of the Erlang runtime are you using - there could of
course be a BUG...

--Per