[erlang-questions] writing a delay loop without now()
James Hague
gives widely varying results, based on the underlying operating
system). Ugly though it may be, I've been using a spin loop based on
now() and timer:now_diff(). While this appears to work, based on the
values returned by now(), it runs much faster than wall clock time.
I'm assuming it's because of this:
"It is also guaranteed that subsequent calls to this BIF returns
continuously increasing values."
Is there another BIF I should be using? I'm hoping I don't have to
write my own linked-in driver for this.
James
_______________________________________________
erlang-questions mailing list
erlang-q...@erlang.org
http://www.erlang.org/mailman/listinfo/erlang-questions
Paul Fisher
> I need more resolution than timer:sleep() will give me. (timer:sleep
> gives widely varying results, based on the underlying operating
> system). Ugly though it may be, I've been using a spin loop based on
> now() and timer:now_diff(). While this appears to work, based on the
> values returned by now(), it runs much faster than wall clock time.
> I'm assuming it's because of this:
>
> "It is also guaranteed that subsequent calls to this BIF returns
> continuously increasing values."
>
> Is there another BIF I should be using? I'm hoping I don't have to
> write my own linked-in driver for this.
sleep( Milliseconds ) ->
receive after Milliseconds -> ok end.
--
paul
Matthew Dempsky
> sleep( Milliseconds ) ->
> receive after Milliseconds -> ok end.
That's exactly how timer:sleep/1 is implemented, which he already mentioned.
Valentin Micic
now()?
NOTE: I've tried it from shell and it didn't make any difference, possibly
because the shell is the only process that is actually doing something,
hence nobody to yield the CPU usage to. Also not sure how this would behave
under the heavy system load, however, according to the manual, the
erlang:yield() is faster than receive after 1 -> ok end.
If you indeed try this approach, could you please give me some feedback on
your observations?
V.
Richard Carlsson
> I need more resolution than timer:sleep() will give me. (timer:sleep
> gives widely varying results, based on the underlying operating
> system). Ugly though it may be, I've been using a spin loop based on
> now() and timer:now_diff(). While this appears to work, based on the
> values returned by now(), it runs much faster than wall clock time.
> I'm assuming it's because of this:
>
> "It is also guaranteed that subsequent calls to this BIF returns
> continuously increasing values."
>
> Is there another BIF I should be using? I'm hoping I don't have to
> write my own linked-in driver for this.
Try erlang:statistics(runtime) or erlang:statistics(wall_clock).
The resolution is still milliseconds, but you could perhaps combine
them with a simple loop that you calibrate at startup, for sub-
millisecond delays.
/Richard
Paul Fisher
> On Tue, Feb 17, 2009 at 5:32 PM, Paul Fisher <pfi...@alertlogic.net> wrote:
>> sleep( Milliseconds ) ->
>> receive after Milliseconds -> ok end.
>
> That's exactly how timer:sleep/1 is implemented, which he already mentioned.
mea culpa! I did not look, and apologize profusely!
--
paul
James Hague
What was the reason for enforcing that now/0 never return the same
value twice? It means you can cause time to run faster by calling
now/0 more frequently. And time accelerates faster on faster
hardware.
Matthew Dempsky
> What was the reason for enforcing that now/0 never return the same
> value twice?
More than that, the runtime enforces that now/0 returns monotonically
increasing values, which makes it useful for timestamping events and
ensuring they have a stable sort order.
James Hague
> increasing values, which makes it useful for timestamping events and
> ensuring they have a stable sort order.
Very useful...but not for now/0. A function that returns the current
time shouldn't itself cause the time to change. now() is make_ref
disguised as a clock.
Matthew Dempsky
> Very useful...but not for now/0. A function that returns the current
> time shouldn't itself cause the time to change. now() is make_ref
> disguised as a clock.
make_ref/0 doesn't return monotonically increasing references.
Per Hedeland
>
>> More than that, the runtime enforces that now/0 returns monotonically
>> increasing values, which makes it useful for timestamping events and
>> ensuring they have a stable sort order.
>
>Very useful...but not for now/0. A function that returns the current
>time shouldn't itself cause the time to change. now() is make_ref
>disguised as a clock.
I don't know if you actually meant it, but of course calling now/0 has
no effect on the VM's idea of time itself, only on subsequent return
values from now/0. Once you stop calling it once per microsecond or
more, the effect will go away.
In the day when this nifty feature was implemented, there existed no
HW/OS combination that could complete the underlying call to
gettimeofday() in less than a microsecond. However implementations that
kept returning the same number of microseconds until a timer interrupt
bumped the value by 10000 or more were common.
Maybe the time (sorry) has come to introduce really_now/0, which would
return the unadjusted result of calling clock_gettime(CLOCK_REALTIME) as
a single bignum (nanoseconds since the epoch). Using this number as the
basis for timeout calculations would be strictly forbidden.
--Per Hedeland
James Hague
decisions behind now/0. Let me rewind a bit.
I have a graphical application that runs at a fixed frame rate (60
frames per second). The processing takes up part of the frame, then I
need to make sure that roughly 16,667 microseconds have passed before
displaying the next frame. os:sleep() is VERY coarse and inconsistent
across platforms. On some platforms os:sleep(1) is the same as
sleep:(32000). Using a timeout value with receive gives the same
results (that's actually how os:sleep is implemented).
erlang:statistics(wall_clock) is just as coarse.
So get around this, I resorted to just spinning in a tight loop using
now/0 and timer:now_diff/2. But now/0 isn't designed to be used like
this, because it always returns increasing values.
This would have been so easy on an 8-bit system from 25 years ago, so
surely there's a way to get raw microsecond time values in Erlang?
Per Hedeland
>
>I have a graphical application that runs at a fixed frame rate (60
>frames per second). The processing takes up part of the frame, then I
>need to make sure that roughly 16,667 microseconds have passed before
milliseconds, right?
>displaying the next frame. os:sleep() is VERY coarse and inconsistent
>across platforms. On some platforms os:sleep(1) is the same as
>sleep:(32000). Using a timeout value with receive gives the same
>results (that's actually how os:sleep is implemented).
Yep, they depend on the OS system timer interrupt interval.
>erlang:statistics(wall_clock) is just as coarse.
That seems very strange though - at least I get the millisecond
resolution that is the best you can possibly get given the definition.
It is basically just rounded numbers from gettimeofday(). Of course
there may be platforms that even to this day provide no better than
multi-millisecond resolution in gettimeofday() or the equivalent - I
tested on FreeBSD and Linux, as usual I have no idea about Windows. But
obviously you can't get microseconds from it.
>So get around this, I resorted to just spinning in a tight loop using
>now/0 and timer:now_diff/2. But now/0 isn't designed to be used like
>this, because it always returns increasing values.
But per my previous message, that should only happen if you manage to
call it more than once per microsecond - unless gettimeofday() returns
bizarre numbers. With a minimal loop
tc1(0) -> ok;
tc1(N) -> now(), tc1(N-1).
I manage to get just above 2 microseconds per call, and perfect
agreement between timer:tc/3 (which uses now/0 of course) and pre/post
statistics(wall_clock) calls (on FreeBSD, 3GHz Intel CPU). I.e. no
opportunity for artificial microsecond-bumping, and none occurring.
If you really manage more than one call per microsecond, consider
yourself lucky, but don't call it so often!:-) Or there is something
else wrong...
>This would have been so easy on an 8-bit system from 25 years ago, so
>surely there's a way to get raw microsecond time values in Erlang?
Linked-in driver...
--Per
Dominic Williams
> I have a graphical application that runs at a fixed frame
> rate (60 frames per second). The processing takes up part
> of the frame, then I need to make sure that roughly 16,667
> microseconds have passed before displaying the next frame.
> os:sleep() is VERY coarse and inconsistent across
> platforms. On some platforms os:sleep(1) is the same as
> sleep:(32000). Using a timeout value with receive gives
> the same results (that's actually how os:sleep is
> implemented). erlang:statistics(wall_clock) is just as
> coarse.
I may not have had quite such stringent realtime
requirements as you, but I've achieved this sort of thing
by:
- calculating time left to the start of next frame
- using timer:send_after/2 to send myself a special message
at start of next frame
- going into a blocking receive of the special message
Two variants of this are:
- using a separate process that produces the "start of
frame" messages, using the same principle
- using timer:send_interval/2, which amounts to using OTP's
built-in separate process that produces regular messages.
Have you tried such approaches?
Best regards,
Dominic Williams
http://dominicwilliams.net
James Hague
>>frames per second). The processing takes up part of the frame, then I
>>need to make sure that roughly 16,667 microseconds have passed before
>
> milliseconds, right?
No, microseconds. It's more or less 16 milliseconds between updates.
I could live with good millisecond accuracy.
I'm still investigating alternatives. My code communicates with an
external graphical client, and I could roll the timing into the client
easily enough (just block if updates are coming closet than 16ms
apart). If that doesn't work I'll look at writing a linked-in driver
(which I've done before, and sure doesn't excite me...).
>But per my previous message, that should only happen if you manage to
>call it more than once per microsecond - unless gettimeofday() returns
>bizarre numbers.
On my MacBook, using a now/0 loop for a delay runs about 25% faster
than it should, so I'm clearly getting more than one call in per
microsecond, at least sometimes.
Per Hedeland
>
>>>I have a graphical application that runs at a fixed frame rate (60
>>>frames per second). The processing takes up part of the frame, then I
>>>need to make sure that roughly 16,667 microseconds have passed before
>>
>> milliseconds, right?
>
>No, microseconds. It's more or less 16 milliseconds between updates.
That's what I meant, just had a temporary misconnect between the weird
custom of sprinkling commas over integers and the equally weird custom
of using a comma for the decimal point.
>I could live with good millisecond accuracy.
That you should definitely be able to get from statistics(wall_clock) -
if you don't, I'll have to say that there is something wrong with your
OS/HW and not with Erlang. See snippet below from a tight-loop that gets
the result of gettimeofday() via os:cmd() every 10 calls to statistics()
(the actual call to statistics() amounts to some 0.2% of the execution
time, the rest is os:cmd() and io:format()).
>>But per my previous message, that should only happen if you manage to
>>call it more than once per microsecond - unless gettimeofday() returns
>>bizarre numbers.
>
>On my MacBook, using a now/0 loop for a delay runs about 25% faster
>than it should, so I'm clearly getting more than one call in per
>microsecond, at least sometimes.
I can't follow that conclusion at all - if you don't know how long a
call takes even on average, I can't see how you can deduce it from an
assumption that the cause of the problems with your loop logic is
microsecond-bumping in now/0 - sounds like circular reasoning to me.
On the other hand laptops frequently do things like varying the CPU
frequency that can confuse applications that try to measure time.
--Per
{13536,0}
{13536,0}
1235162740.330364
{13549,13}
{13549,0}
{13549,0}
{13549,0}
{13550,1}
{13550,0}
{13550,0}
{13550,0}
{13550,0}
{13550,0}
1235162740.344203
{13563,13}
{13563,0}
{13563,0}
{13563,0}
{13563,0}
{13563,0}
{13563,0}
{13564,1}
{13564,0}
{13564,0}
1235162740.357672
{13577,13}
{13577,0}
James Hague
> call takes even on average, I can't see how you can deduce it from an
> assumption that the cause of the problems with your loop logic is
> microsecond-bumping in now/0 - sounds like circular reasoning to me.
I've verified on two very different machines (different CPUs,
different operating systems), that my timing loop based on now() is
running faster than wall clock time, even though it's reporting the
correct internal elapsed time. That's all I know for sure.
James Hague
> finding a solution within Erlang? If so, you could start by posting the
> code to see if others observe the same problem. Maybe also post the code
> that makes you conclude that statistics(wall_clock) jumps about all over
> the place.
Sure, I'd love to work this out. I will put some code together when I
get a chance.
Per Hedeland
>
>> I can't follow that conclusion at all - if you don't know how long a
>> call takes even on average, I can't see how you can deduce it from an
>> assumption that the cause of the problems with your loop logic is
>> microsecond-bumping in now/0 - sounds like circular reasoning to me.
>
>I've verified on two very different machines (different CPUs,
>different operating systems), that my timing loop based on now() is
>running faster than wall clock time, even though it's reporting the
>correct internal elapsed time. That's all I know for sure.
OK - so are you at all interested in figuring out why, and if possible
finding a solution within Erlang? If so, you could start by posting the
code to see if others observe the same problem. Maybe also post the code
that makes you conclude that statistics(wall_clock) jumps about all over
the place.
--Per
James Hague
here. This is only to illustrate one issue; it's not a full analysis
of timing in Erlang.
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.)
Now here's a little function that uses now/0 and timer:now_diff/2 to
wait for a specified number of MICROseconds:
-module(test).
-compile(export_all).
time(N) -> time(N, now()).
time(N, Start) ->
case timer:now_diff(now(), Start) of
M when M >= N -> M;
_ -> time(N, Start)
end.
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.
Fredrik Svahn
Erlang (BEAM) emulator version 5.6.5 [source] [64-bit] [smp:2] [async-threads:0] [hipe] [kernel-poll:false]
Eshell V5.6.5 (abort with ^G)
1> erlang:statistics(wall_clock),test:time(5000000),erlang:statistics(wall_clock).
{18066,5001}
2> erlang:statistics(wall_clock),test:time(1000),erlang:statistics(wall_clock).
{200733,2}
3> erlang:statistics(wall_clock),test:time(1000),erlang:statistics(wall_clock).
{202005,2}
4> erlang:statistics(wall_clock),test:time(1000),erlang:statistics(wall_clock).
{203189,2}
BR /Fredrik
Per Hedeland
>
>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
James Hague
>
> And as we also established, this has nothing to do with Erlang -
Correct. I just provided the numbers for os:sleep(1) and os:sleep(16)
for reference.
> 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).
I get this:
{{4999999,5000000},{460636,1451}}
This is using a 64-bit version of Window Vista, "Erlang (BEAM)
emulator version 5.6.5 [smp:4] [async-threads:0]".
I originally noticed this on a MacBook running OS X 10.4 (which is
Tiger, not 10.5 Leopard), but I don't have timings yet. I also tried
disabling SMP on the Vista box, which gives:
{{4999999,5000000},{153026,1247}}
Jay Nelson
Erlang (BEAM) emulator version 5.6.4 [source] [async-threads:0]
[hipe] [kernel-poll:false]
Eshell V5.6.4 (abort with ^G)
29> erlang:statistics(wall_clock),timer:sleep(1),erlang:statistics
(wall_clock).
{987019,11}
30> erlang:statistics(wall_clock),timer:sleep(16),erlang:statistics
(wall_clock).
{991049,17}
33> erlang:statistics(wall_clock),{test:time2
(5000000),erlang:statistics(wall_clock)}.
{{4824884,5000000},{1008213,3634}}
34> erlang:statistics(wall_clock),{test:time2
(5000000),erlang:statistics(wall_clock)}.
{{4939556,5000000},{1016268,3361}}
jay
Fredrik Svahn
C:\>"C:\Program Files\erl5.6.5\bin\erl"
Eshell V5.6.5 (abort with ^G)
1> erlang:statistics(wall_clock),test:time(5000000),erlang:statistics(wall_clock).
2> erlang:statistics(wall_clock),test:time(1000000),erlang:statistics(wall_clock).
{22184,640}
C:\>"C:\Program Files\erl5.6.5\bin\erl" +c
Eshell V5.6.5 (abort with ^G)
1> erlang:statistics(wall_clock),test:time(5000000),erlang:statistics(wall_clock).
2> erlang:statistics(wall_clock),test:time(1000000),erlang:statistics(wall_clock).
{27253,998}
(With Linux on the same machine I get the expected results no matter if I run with or without the +c flag.)
BR /Fredrik
Per Hedeland
>
>I get this:
> {{4999999,5000000},{460636,1451}}
>
>This is using a 64-bit version of Window Vista, "Erlang (BEAM)
>emulator version 5.6.5 [smp:4] [async-threads:0]".
Eeew, Windows - according the sources, gettimeofday() is there replaced
by GetSystemTime() with SystemTimeToFileTime() applied to the result. I
have no idea what those functions actually do (nor what the quality of
the resulting numbers is), but it would appear that they finish it in a
quarter of a microsecond or so on your box, i.e. now-bumping will kick
in.
You could try what I suggested a few messages back, "don't call it so
often" - i.e. twiddle your thumbs for a while in each loop round, to
make sure the now/0 calls are separated by at least a microsecond. The
below causes some 3 microseconds of twiddling in my tests on a 3GHz CPU,
adjust to taste (weird argument-passing-around to prevent it from being
optimized away, may not be necessary).
time3(N) -> time3(N, now(), 0, [0]).
time3(N, Start, C, X) ->
case timer:now_diff(now(), Start) of
M when M >= N -> {C, M};
_ -> time3(N, Start, C+1, twiddle(X))
end.
twiddle(X) ->
[hd(X)|[Y*Y || Y <- lists:duplicate(5, 12345678901234567890123456789)]].
Fredrik Svahn <fredri...@gmail.com> wrote:
>
>I get the same results as James when running R12B-5 on Windows Vista. It
>seems to be related to the algorithm for adjusting to sudden time changes.
>When disabling it with the "+c" flag it works (almost) as expected.
Hm, this would imply that the numbers that the ersatz gettimeofday() on
Windows returns are more or less garbage, no surprise there I guess - or
possibly that the algorithm has bad assumptions on how to get "really
elapsed time" on Windows [Vista] (great fun was had when it tried to use
times() on FreeBSD back when times() was based on gettimeofday() - the
emulator stopped dead in its tracks). FWIW, it uses GetTickCount() for
that, which sounds reasonable, but who knows...
In either case, the twiddling suggested above may not help then, but
it's worth a try I think. Disabling the algorithm is probably
undesirable.
--Per
tsuraan
> -compile(export_all).
>
> time(N) -> time(N, now()).
> time(N, Start) ->
> case timer:now_diff(now(), Start) of
> M when M >= N -> M;
> _ -> time(N, Start)
> end.
My results, on Linux 2.6.28 (vanilla) and a core2 duo at 3GHz:
Erlang (BEAM) emulator version 5.6.1 [source] [smp:2]
[async-threads:0] [hipe] [kernel-poll:false]
Eshell V5.6.1 (abort with ^G)
1> c(test).
{ok,test}
2> erlang:statistics(wall_clock),test:time(5000000),erlang:statistics(wall_clock).
{24784,3960}
3> erlang:statistics(wall_clock),test:time(5000000),erlang:statistics(wall_clock).
{30248,3964}
4> c(test, native).
{ok,test}
5> erlang:statistics(wall_clock),test:time(5000000),erlang:statistics(wall_clock).
{39371,3773}
6> erlang:statistics(wall_clock),test:time(5000000),erlang:statistics(wall_clock).
{44229,3797}
Native does sleep for 5 seconds a bit faster than without native, but
both ways sleep for 5 seconds in noticeably less than 5 seconds.
tsuraan
> I get the same results as James when running R12B-5 on Windows Vista. It
> seems to be related to the algorithm for adjusting to sudden time changes.
> When disabling it with the "+c" flag it works (almost) as expected.
Interesting: when I try this, I get the opposite effect:
tsuraan@newdev ~/test/erlang $ erl +c
Erlang (BEAM) emulator version 5.6.1 [source] [smp:2]
[async-threads:0] [hipe] [kernel-poll:false]
Eshell V5.6.1 (abort with ^G)
1> c(test).
{ok,test}
2> erlang:statistics(wall_clock),test:time(5000000),erlang:statistics(wall_clock).
{8852,2896}
3> erlang:statistics(wall_clock),test:time(5000000),erlang:statistics(wall_clock).
{14662,2900}
4> c(test, native).
{ok,test}
5> erlang:statistics(wall_clock),test:time(5000000),erlang:statistics(wall_clock).
{25744,2782}
6> erlang:statistics(wall_clock),test:time(5000000),erlang:statistics(wall_clock).
{30166,2802}
Per Hedeland
>
>My results, on Linux 2.6.28 (vanilla) and a core2 duo at 3GHz:
>
>Erlang (BEAM) emulator version 5.6.1 [source] [smp:2]
>[async-threads:0] [hipe] [kernel-poll:false]
>
>Eshell V5.6.1 (abort with ^G)
>1> c(test).
>{ok,test}
>2> erlang:statistics(wall_clock),test:time(5000000),erlang:statistics(wall_clock).
>{24784,3960}
Mighty strange - with Linux, the exact same Erlang runtime, and actually
exact same HW too, I still get perfect results:
2> erlang:statistics(wall_clock),test:time(5000000),erlang:statistics(wall_clock).
{93876,5000}
The kernel is different though ("2.6.20-1.2320.fc5smp"), probably glibc
too, but I have a hard time believing that either of those is the cause.
I don't suppose that you run some primitive time-keeping app that keeps
whacking the system time around? (The above system runs NTP.)
What number do you get with the loop-counting version I posted earlier
(time2/1 reposted below)? I get numbers like 4559687, which is
uncomfortably close to 1 call per microsecond but still just below - I
think it would have to be some 25% faster on your system to produce the
above result. I guess it's possible even if unlikely...
If you do get just about 5000000 (it can never be more), maybe you could
try the "twiddle" version (time3/1 below) too?
--Per
4> erlang:statistics(wall_clock),{test:time2(5000000),erlang:statistics(wall_clock)}.
{{4559687,5000000},{204001,5001}}
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.
time3(N) -> time3(N, now(), 0, [0]).
time3(N, Start, C, X) ->
case timer:now_diff(now(), Start) of
M when M >= N -> {C, M};
_ -> time3(N, Start, C+1, twiddle(X))
end.
twiddle(X) ->
[hd(X)|[Y*Y || Y <- lists:duplicate(5, 12345678901234567890123456789)]].
tsuraan
> too, but I have a hard time believing that either of those is the cause.
> I don't suppose that you run some primitive time-keeping app that keeps
> whacking the system time around? (The above system runs NTP.)
I'm running 2.6.28 (vanilla) and glibc 2.6.1. Ntp is running in the
background, but I don't think it's constantly messing with the system
clock, at least not so much that it would cause these sorts of
results.
It's a gentoo system; everything is compiled with arch=i686 and O2. I
imagine that fedora uses at least O2 for everything, but are they
still supporting pentium1 (arch=i586)? I think that could slow things
down a little, maybe.
> What number do you get with the loop-counting version I posted earlier
> (time2/1 reposted below)? I get numbers like 4559687, which is
> uncomfortably close to 1 call per microsecond but still just below - I
> think it would have to be some 25% faster on your system to produce the
> above result. I guess it's possible even if unlikely...
Just doing time2 (no wall_clock) reliably gives me {4999999,5000000}.
If I do wall_clock, I pretty reliably get 4200 elapsed ms.
>
> If you do get just about 5000000 (it can never be more), maybe you could
> try the "twiddle" version (time3/1 below) too?
That works really well, even with c(test, native):
20> erlang:statistics(wall_clock),test:time3(5000000),erlang:statistics(wall_clock).
{112133,5001}
21> erlang:statistics(wall_clock),test:time3(5000000),erlang:statistics(wall_clock).
{117927,5000}
22> erlang:statistics(wall_clock),test:time3(5000000),erlang:statistics(wall_clock).
{123552,5001}
Also, my raw numbers for time2 (without native compilation) are:
17> erlang:statistics(wall_clock),test:time2(5000000),erlang:statistics(wall_clock).
{93637,4199}
18> erlang:statistics(wall_clock),test:time2(5000000),erlang:statistics(wall_clock).
{98664,4158}
19> erlang:statistics(wall_clock),test:time2(5000000),erlang:statistics(wall_clock).
{103691,4200}
Per Hedeland
>
>I'm running 2.6.28 (vanilla) and glibc 2.6.1. Ntp is running in the
>background, but I don't think it's constantly messing with the system
>clock, at least not so much that it would cause these sorts of
>results.
No, it's very careful to just (effectively) reduce or increase the clock
frequency, won't step the time unless it's way off (i.e. 128 millisec:-).
>It's a gentoo system; everything is compiled with arch=i686 and O2. I
>imagine that fedora uses at least O2 for everything, but are they
>still supporting pentium1 (arch=i586)? I think that could slow things
>down a little, maybe.
Perhaps - most likely is probably some manual optimization in the
relevant kernel code.
>Just doing time2 (no wall_clock) reliably gives me {4999999,5000000}.
>If I do wall_clock, I pretty reliably get 4200 elapsed ms.
OK, that agrees well with a now() that completes in some 0.84
microseconds on average - "bumping" will occur every ~ 7th call to
fulfill the "increasing values" promise.
>> If you do get just about 5000000 (it can never be more), maybe you could
>> try the "twiddle" version (time3/1 below) too?
>
>That works really well, even with c(test, native):
Great, thanks for your perseverance.:-) So, you've confirmed what I said
way back: As long as the underlying OS returns sane results from
gettimeofday() or the equivalent, doing a tight-loop with microsecond-
level accuracy using now/1 works fine. The only problem is if your
system completes the call in less than 1 microsecond on average - in
which case you simply need to make sure that you don't call it so often,
do something else in between the calls to make sure they're at least a
microsecond apart.
Maybe you can even find something more useful to do than multiplying
bignums and throwing away the result.:-) And if you're really ambitious,
you could make this thing auto-adapting to OS/CPU speed - increase the
"twiddle time" until you start getting increments of 2 (or more) from
now/1, then you know that some "real" time has elapsed between calls.
--Per