Experimental Physics and
Industrial Control System

rivers via Core-talk <core-talk at aps.anl.gov> · Sun, 02 Feb 2020 16:58:45 -0000

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.

-- 
You received this bug notification because you are a member of EPICS
Core Developers, which is subscribed to EPICS Base.
Matching subscriptions: epics-core-list-subscription
https://bugs.launchpad.net/bugs/1861612

Title:
  callbackRequestDelay not waiting for 1/60 sec on vxWorks

Status in EPICS Base:
  New

Bug description:
  The problem is documented in this tech-talk thread:
  https://epics.anl.gov/tech-talk/2020/msg00308.php

  In 7.0.3.1, but not in 7.0.3, callbackRequestDelay(1/60) results in
  100% CPU time, most of the time in cbHigh.

  This happens on vxWorks 6.9.4.1 and was first seen with the scaler
  record with multiple types of scaler hardware and device support.

To manage notifications about this bug go to:
https://bugs.launchpad.net/epics-base/+bug/1861612/+subscriptions

Experimental Physics and Industrial Control System

Experimental Physics and
Industrial Control System