EPICS Base

Bug #1861612
Comment #5

Comment 5 for bug 1861612

Revision history for this message

rivers (rivers) wrote on 2020-02-02:

Perhaps my hypothesis about callbackRequestDelay behavior change is wrong.

I looked for where callbackRequestDelay is used in base, and it seems to be used in the HIGH delay for bo records. I thus thought that HIGH delays of 1/60. second or less would result in effectively 0 delay. However, I tested this with camonitor in a vxWorks IOC running 7.0.3.1. This is what I see with HIGH=0.01, which is less than 1 tick time=0.016666666. This is as I repeatedly write 1 to the record with caput.

corvette:~/devel/nable 13LAB:userTranEnable 13LAB:userTranEnable 13LAB:userTranEnable 13LAB:userTranEnable 13LAB:userTranEnable 13LAB:userTranEnable 13LAB:userTranEnable 13LAB:userTranEnable 13LAB:userTranEnable 13LAB:userTranEnable 13LAB:userTranEnable 13LAB:userTranEnable 13LAB:userTranEnable 13LAB:userTranEnable 13LAB:userTranEnable 13LAB:userTranEnable 13LAB:userTranEnable 13LAB:userTranEnable 13LAB:userTranEnable 13LAB:userTranEnable 13LAB:userTranEnable 13LAB:userTranEnable 13LAB:userTranEnable 13LAB:userTranEnable 13LAB:userTranEnable 13LAB:userTranEnable 13LAB:userTranEnable 13LAB:userTranEnable />PY_NTNDA_Viewer>camonitor -tic 13LAB:userTranEnable
(2020-02-02 10:41:57.387524) Disable
( +4.306785) Enable
( +0.007119) Disable
( +0.346203) Enable
( +0.003968) Disable
( +0.313715) Enable
( +0.002799) Disable
( +0.236848) Enable
( +0.013807) Disable
( +0.290088) Enable
( +0.009729) Disable
( +0.249017) Enable
( +0.017225) Disable
( +0.290018) Enable
( +0.010037) Disable
( +0.192072) Enable
( +0.008027) Disable
( +0.200641) Enable
( +0.015982) Disable
( +0.208282) Enable
( +0.008714) Disable
( +0.230697) Enable
( +0.002203) Disable
( +0.206095) Enable
( +0.010524) Disable
( +0.197474) Enable
( +0.002590) Disable
( +0.174295) Enable
( +0.009070) Disable

So the transition from 1 (Enable) to 0 (Disable) seems to take a random amount of time between 0 and 0.01666 seconds. This is exactly what I expect if the delay does wait for the next clock tick, just like epicsThreadSleep. The tick rate in my IOC is 60.

However, if I change HIGH from .01 to .005 the behavior changes, and it is only high for 20-40 microseconds (measuring time on a Linux client).

corvette:~/devel/PY_NTNDA_Viewer>camonitor -tic 13LAB:userTranEnable
13LAB:userTranEnable (2020-02-02 10:52:10.095757) Disable

Why is there a change in behavior between HIGH = 0.01 and 0.005?

I have not done the same experiment on 7.0.3.

Perhaps my hypothesis about callbackRequestDelay behavior change is wrong.

I looked for where callbackRequestDelay is used in base, and it seems to be used in the HIGH delay for bo records. I thus thought that HIGH delays of 1/60. second or less would result in effectively 0 delay.  However, I tested this with camonitor in a vxWorks IOC running 7.0.3.1.  This is what I see with HIGH=0.01, which is less than 1 tick time=0.016666666.  This is as I repeatedly write 1 to the record with caput.

corvette:~/devel/PY_NTNDA_Viewer>camonitor -tic 13LAB:userTranEnable
13LAB:userTranEnable           (2020-02-02 10:41:57.387524) Disable
13LAB:userTranEnable                         (   +4.306785) Enable
13LAB:userTranEnable                         (   +0.007119) Disable
13LAB:userTranEnable                         (   +0.346203) Enable
13LAB:userTranEnable                         (   +0.003968) Disable
13LAB:userTranEnable                         (   +0.313715) Enable
13LAB:userTranEnable                         (   +0.002799) Disable
13LAB:userTranEnable                         (   +0.236848) Enable
13LAB:userTranEnable                         (   +0.013807) Disable
13LAB:userTranEnable                         (   +0.290088) Enable
13LAB:userTranEnable                         (   +0.009729) Disable
13LAB:userTranEnable                         (   +0.249017) Enable
13LAB:userTranEnable                         (   +0.017225) Disable
13LAB:userTranEnable                         (   +0.290018) Enable
13LAB:userTranEnable                         (   +0.010037) Disable
13LAB:userTranEnable                         (   +0.192072) Enable
13LAB:userTranEnable                         (   +0.008027) Disable
13LAB:userTranEnable                         (   +0.200641) Enable
13LAB:userTranEnable                         (   +0.015982) Disable
13LAB:userTranEnable                         (   +0.208282) Enable
13LAB:userTranEnable                         (   +0.008714) Disable
13LAB:userTranEnable                         (   +0.230697) Enable
13LAB:userTranEnable                         (   +0.002203) Disable
13LAB:userTranEnable                         (   +0.206095) Enable
13LAB:userTranEnable                         (   +0.010524) Disable
13LAB:userTranEnable                         (   +0.197474) Enable
13LAB:userTranEnable                         (   +0.002590) Disable
13LAB:userTranEnable                         (   +0.174295) Enable
13LAB:userTranEnable                         (   +0.009070) Disable

So the transition from 1 (Enable) to 0 (Disable) seems to take a random amount of time between 0 and 0.01666 seconds.  This is exactly what I expect if the delay does wait for the next clock tick, just like epicsThreadSleep. The tick rate in my IOC is 60.

However, if I change HIGH from .01 to .005 the behavior changes, and it is only high for 20-40 microseconds (measuring time on a Linux client).

corvette:~/devel/PY_NTNDA_Viewer>camonitor -tic 13LAB:userTranEnable
13LAB:userTranEnable           (2020-02-02 10:52:10.095757) Disable

13LAB:userTranEnable                         (  +11.698305) Enable
13LAB:userTranEnable                         (   +0.000056) Disable
13LAB:userTranEnable                         (   +0.752278) Enable
13LAB:userTranEnable                         (   +0.000034) Disable
13LAB:userTranEnable                         (   +0.239082) Enable
13LAB:userTranEnable                         (   +0.000037) Disable
13LAB:userTranEnable                         (   +0.223219) Enable
13LAB:userTranEnable                         (   +0.000038) Disable
13LAB:userTranEnable                         (   +0.178778) Enable
13LAB:userTranEnable                         (   +0.000028) Disable
13LAB:userTranEnable                         (   +0.314707) Enable
13LAB:userTranEnable                         (   +0.000036) Disable
13LAB:userTranEnable                         (   +0.096827) Enable
13LAB:userTranEnable                         (   +0.000030) Disable
13LAB:userTranEnable                         (   +0.176998) Enable
13LAB:userTranEnable                         (   +0.000030) Disable
13LAB:userTranEnable                         (   +0.193591) Enable
13LAB:userTranEnable                         (   +0.000022) Disable
13LAB:userTranEnable                         (   +0.191531) Enable
13LAB:userTranEnable                         (   +0.000031) Disable
13LAB:userTranEnable                         (   +0.207274) Enable
13LAB:userTranEnable                         (   +0.000024) Disable

Why is there a change in behavior between HIGH = 0.01 and 0.005?

I have not done the same experiment on 7.0.3.