libCom's epicsEventTest measures epicsEventWaitWithTimeout() delays from 2.0**0 down to 2.0**-19=0.000001907 and 0.0. However it isn't particularly careful with the starting point of those timings, and it also drops the sign from the calculated delay error. I just added a call to epicsEventWaitWithTimeout(id, 0.000001) before the start of each delay measurement to synchronize each one to the start of an OS tick, and made the error calculation just measured delay - requested delay. The results on VxWorks are interesting. These are with the default 60Hz tick rate:
The results are quite repeatable, only the last digit seems to change by about ±2 between runs.
On Linux I see no negative delay errors at all. On both RTEMS-pc386-qemu and VxWorks I get negative delay errors for requests that are larger than and not an exact multiple of the tick quantum, so those requests are returning earlier than they are supposed to. I am not seeing negative delay errors that are greater than the tick quantum, but as I said above I have synchronized the time measurements to start immediately after a clock tick.
I think I now understand the problem: We pass the time delay to the OS as an integer tick count, but callbackRequestDelay() is now measuring and calculating its delays much more accurately than it used to, using the monotonic clock. Previously those delays would have always been multiples of the tick quantum. In epicsEventWaitWithTimeout() we calculate the delay time in ticks but throw away the remainder, which can now be up to just under a whole tick interval long. We also aren't taking into account that the start of a delay is not aligned to the OS tick event but the end always is, so we're throwing away up to another whole tick there too.
By inserting a busy-wait of just under a tick long after the synchronization to the OS tick that I described above I can produce delay errors of almost 2 ticks. Here the tick rate was 1000Hz and I had inserted a 990µs delay after the previous tick event before starting the measurement:
I wouldn't want to just round up the delay by 2 ticks, that could badly hit performance. The solution to this probably has to involve reading the monotonic clock and calling semTake(id, 1) again if the OS returns before the hi-res delay has expired (we might have to do that twice). However there are a number of other places that also use the tick rate and might need similar adjustments, so there's more work to this fix than just changing osdEvent.c for VxWorks and RTEMS.
libCom's epicsEventTest measures epicsEventWaitW ithTimeout( ) delays from 2.0**0 down to 2.0**-19= 0.000001907 and 0.0. However it isn't particularly careful with the starting point of those timings, and it also drops the sign from the calculated delay error. I just added a call to epicsEventWaitW ithTimeout( id, 0.000001) before the start of each delay measurement to synchronize each one to the start of an OS tick, and made the error calculation just measured delay - requested delay. The results on VxWorks are interesting. These are with the default 60Hz tick rate:
# epicsEventWaitW ithTimeout( 1.000000) delay error 0.000013 sec ithTimeout( 0.500000) delay error 0.000006 sec ithTimeout( 0.250000) delay error 0.000003 sec ithTimeout( 0.125000) delay error -0.008331 sec ithTimeout( 0.062500) delay error -0.012500 sec ithTimeout( 0.031250) delay error -0.014583 sec ithTimeout( 0.015625) delay error 0.001042 sec ithTimeout( 0.007813) delay error 0.008854 sec ithTimeout( 0.003906) delay error 0.012760 sec ithTimeout( 0.001953) delay error 0.014716 sec ithTimeout( 0.000977) delay error 0.015690 sec ithTimeout( 0.000488) delay error 0.016178 sec ithTimeout( 0.000244) delay error 0.016423 sec ithTimeout( 0.000122) delay error 0.016545 sec ithTimeout( 0.000061) delay error 0.016605 sec ithTimeout( 0.000031) delay error 0.016636 sec ithTimeout( 0.000015) delay error 0.016654 sec ithTimeout( 0.000008) delay error 0.016658 sec ithTimeout( 0.000004) delay error 0.016663 sec ithTimeout( 0.000002) delay error 0.016665 sec ithTimeout( 0.000000) delay error 0.000003 sec
# epicsEventWaitW
# epicsEventWaitW
# epicsEventWaitW
# epicsEventWaitW
# epicsEventWaitW
# epicsEventWaitW
# epicsEventWaitW
# epicsEventWaitW
# epicsEventWaitW
# epicsEventWaitW
# epicsEventWaitW
# epicsEventWaitW
# epicsEventWaitW
# epicsEventWaitW
# epicsEventWaitW
# epicsEventWaitW
# epicsEventWaitW
# epicsEventWaitW
# epicsEventWaitW
# epicsEventWaitW
I then set the clock to 1KHz and got these:
# epicsEventWaitW ithTimeout( 1.000000) delay error 0.000025 sec ithTimeout( 0.500000) delay error -0.000005 sec ithTimeout( 0.250000) delay error -0.000003 sec ithTimeout( 0.125000) delay error -0.000001 sec ithTimeout( 0.062500) delay error -0.000501 sec ithTimeout( 0.031250) delay error -0.000250 sec ithTimeout( 0.015625) delay error -0.000625 sec ithTimeout( 0.007813) delay error -0.000813 sec ithTimeout( 0.003906) delay error -0.000907 sec ithTimeout( 0.001953) delay error -0.000953 sec ithTimeout( 0.000977) delay error 0.000023 sec ithTimeout( 0.000488) delay error 0.000512 sec ithTimeout( 0.000244) delay error 0.000756 sec ithTimeout( 0.000122) delay error 0.000878 sec ithTimeout( 0.000061) delay error 0.000938 sec ithTimeout( 0.000031) delay error 0.000969 sec ithTimeout( 0.000015) delay error 0.000984 sec ithTimeout( 0.000008) delay error 0.000992 sec ithTimeout( 0.000004) delay error 0.000996 sec ithTimeout( 0.000002) delay error 0.000998 sec ithTimeout( 0.000000) delay error 0.000002 sec
# epicsEventWaitW
# epicsEventWaitW
# epicsEventWaitW
# epicsEventWaitW
# epicsEventWaitW
# epicsEventWaitW
# epicsEventWaitW
# epicsEventWaitW
# epicsEventWaitW
# epicsEventWaitW
# epicsEventWaitW
# epicsEventWaitW
# epicsEventWaitW
# epicsEventWaitW
# epicsEventWaitW
# epicsEventWaitW
# epicsEventWaitW
# epicsEventWaitW
# epicsEventWaitW
# epicsEventWaitW
The results are quite repeatable, only the last digit seems to change by about ±2 between runs.
On Linux I see no negative delay errors at all. On both RTEMS-pc386-qemu and VxWorks I get negative delay errors for requests that are larger than and not an exact multiple of the tick quantum, so those requests are returning earlier than they are supposed to. I am not seeing negative delay errors that are greater than the tick quantum, but as I said above I have synchronized the time measurements to start immediately after a clock tick.
I think I now understand the problem: We pass the time delay to the OS as an integer tick count, but callbackRequest Delay() is now measuring and calculating its delays much more accurately than it used to, using the monotonic clock. Previously those delays would have always been multiples of the tick quantum. In epicsEventWaitW ithTimeout( ) we calculate the delay time in ticks but throw away the remainder, which can now be up to just under a whole tick interval long. We also aren't taking into account that the start of a delay is not aligned to the OS tick event but the end always is, so we're throwing away up to another whole tick there too.
By inserting a busy-wait of just under a tick long after the synchronization to the OS tick that I described above I can produce delay errors of almost 2 ticks. Here the tick rate was 1000Hz and I had inserted a 990µs delay after the previous tick event before starting the measurement:
# epicsEventWaitW ithTimeout( 1.000000) delay error -0.000976 sec ithTimeout( 0.500000) delay error -0.000962 sec ithTimeout( 0.250000) delay error -0.000956 sec ithTimeout( 0.125000) delay error -0.000953 sec ithTimeout( 0.062500) delay error -0.001451 sec ithTimeout( 0.031250) delay error -0.001200 sec ithTimeout( 0.015625) delay error -0.001574 sec ithTimeout( 0.007813) delay error -0.001762 sec ithTimeout( 0.003906) delay error -0.001855 sec ithTimeout( 0.001953) delay error -0.001903 sec ithTimeout( 0.000977) delay error -0.000926 sec ithTimeout( 0.000488) delay error -0.000437 sec ithTimeout( 0.000244) delay error -0.000194 sec ithTimeout( 0.000122) delay error -0.000072 sec ithTimeout( 0.000061) delay error -0.000011 sec ithTimeout( 0.000031) delay error 0.000020 sec ithTimeout( 0.000015) delay error 0.000035 sec ithTimeout( 0.000008) delay error 0.000043 sec ithTimeout( 0.000004) delay error 0.000047 sec ithTimeout( 0.000002) delay error 0.000048 sec ithTimeout( 0.000000) delay error 0.000002 sec
# epicsEventWaitW
# epicsEventWaitW
# epicsEventWaitW
# epicsEventWaitW
# epicsEventWaitW
# epicsEventWaitW
# epicsEventWaitW
# epicsEventWaitW
# epicsEventWaitW
# epicsEventWaitW
# epicsEventWaitW
# epicsEventWaitW
# epicsEventWaitW
# epicsEventWaitW
# epicsEventWaitW
# epicsEventWaitW
# epicsEventWaitW
# epicsEventWaitW
# epicsEventWaitW
# epicsEventWaitW
I wouldn't want to just round up the delay by 2 ticks, that could badly hit performance. The solution to this probably has to involve reading the monotonic clock and calling semTake(id, 1) again if the OS returns before the hi-res delay has expired (we might have to do that twice). However there are a number of other places that also use the tick rate and might need similar adjustments, so there's more work to this fix than just changing osdEvent.c for VxWorks and RTEMS.