At least some time intervals are wrong on the Erlang level

[peerst]

When I call:

timer:sleep(10000).

It takes 20s instead of 10s to wake up.

> T1 = erlang:now().

... wait for 10s

> T2 = erlang:now().
> timer:now_diff(T2,T1)/1000000.
5.206791

The same goes for:

> T1 = os:timestamp().

... wait for 10s

> T2 = os:timestamp().
> timer:now_diff(T2,T1)/1000000.
5.177451

Looking at some of the new time functions:

> erlang:system_info(os_system_time_source).
[{function,clock_gettime},
 {clock_id,'CLOCK_REALTIME'},
 {resolution,1000000000},
 {parallel,yes},
 {time,568460484965710933}]

... wait 10s

> erlang:system_info(os_system_time_source).
[{function,clock_gettime},
 {clock_id,'CLOCK_REALTIME'},
 {resolution,1000000000},
 {parallel,yes},
 {time,568460490123233905}]
> 568460484965710933-568460490123233905.
-5157522972
> (568460484965710933-568460490123233905)/1000000000.
-5.157522972000001

It looks very much that all the times are consistently off by a factor of two. @c-mauderer reported quite a while ago that they checked the RTEMS POSIX time functions and they work correctly so there is something weird going on here which we need to look into.

[peerst]

Just a addendum as is expected by the timer:sleep() test also

receive after 10000 -> timeout end

Takes 20s instead of 10

[peerst]

Added the folwing code snippet during system startup in the Init task before Erlang is started:

printf("before sleep");
sleep(10);
printf("after sleep");

This sleep takes almost 30s so even more. I get the impression this has nothing to do with our Erlang port but the RTEMS BSP needs to fix the time.

BTW we found out that Erlang uses https://www.freebsd.org/cgi/man.cgi?query=clock_gettime to ask the OS for time mostly. Also the timeouts in the select() call should work precisely since that is used by the Erlang VM whenever it needs to wait for I/O or time passed. Thats just additional info on what to maybe test with didn't check how much these times are off after sleep() already failed.

The configuration we start the system with can be at the end of:

https://github.com/grisp/grisp/blob/master/grisp/grisp_base/sys/erl_main.c

[c-mauderer]

Hello @peerst,

I had a similar problem on another atsamv based board and I'm currently trying to fix it: A sleep(1) needs a lot longer than 1 second but only if no debugger is connected.

The reason behind it seems to be that the wall clock on the atsamv is implemented based on a counter in the ARM DWT block. This should be a free running counter but it seems that it stops on a WFI (wait for interrupt) instruction. The WFI is used in the idle loop.

Could you try to add the following workaround to your applications configuration:

/* Workarround for problem that the wait instruction in the default idle body
 * has an influence on the cycle counter that is used for the wall clock. */
void *_My_Idle_body(uintptr_t ignored)
{
  for( ; ; ) ;
  return 0;   /* to avoid warning */
}

#define CONFIGURE_IDLE_TASK_BODY _My_Idle_body

If that works, that is the same problem.

Regards

Christian

[peerst]

Hi @c-mauderer added this snippet and it definitely changed something.

But now a sleep(10) only sleeps 8 Seconds

[peerst]

Well while sleep() on the C level seems to still behave weirdly the workaround definitely fixes Erlangs notion of time:

(grisp@base0006)5> T1 = erlang:now().     
{567,996917,409432}

wait 100s ...

(grisp@base0006)6> T2 = erlang:now().     
{567,997017,588033}
(grisp@base0006)7> 
(grisp@base0006)9> timer:now_diff(T2, T1)/1000000.
100.178601

[c-mauderer]

Hello @peerst,

the problem is now fixed in the upstream RTEMS. To keep the impact small for you, I cherry-picked the patch onto the current GRiSP branch of RTEMS. As soon as you update the grisp-software repo to the current master and rebuild RTEMS, you shouldn't need the workarround any more.

Regards

Christian