Re: fast PV transition skipped in EPICS 3.16

["Reiter, Simon Patrik via Tech-talk" <tech-talk@aps.anl.gov>]

Hi Andrew,

thank you very much for your detailed description!

Concerning my 1st observations, which are related to my real problem, I will simply watch the req:S instead of the cur:S.

Cheers,
Simon

> On Oct 14, 2019, at 20:56, Johnson, Andrew N. via Tech-talk <tech-talk@aps.anl.gov> wrote:
> 
> Hi Simon,
> 
> Sorry that nobody responded to this issue sooner, many of our developers were busy preparing for and attending the ICALEPCS conference that took place in New York last week.
> 
> I think I understand what is happening in your case, and if I'm right this is not due to a bug but is explicitly designed behaviour in the IOC server.
> 
> On 10/14/19 10:50 AM, Simon Reiter via Tech-talk wrote:
>> The sequence has 3 states, which are just following each other w/o any
>> condition. In every state, the only PV used and provided by the IOC itself is
>> set to a new value with SYNC and a log message with time in sec and usec is
>> printed.
>> 
> Your sequence program does a series of ca_put_callback() operations to an mbbo record by cycling continually through 3 different states, with the synchronization points being that the program calls pvPut(pv_cur, SYNC); and printf() in each state. The SYNC tells the sequencer    to wait for the acknowledgement that the put is complete before it moves on to the next state, but nothing else slows down the sequence program which seems to be generating synchronous pvPut() calls at about 43KHz.
> 
>> I am monitoring the PV with camonitor and the following is a comparison of
>> camonitor and the log of the ioc:
>> 
>> cur:S  17:02:37.313890 NOTREADY     | 37.313911 Entered state NOTREADY.
>> cur:S  17:02:37.313913 LOADING      | 37.313934 Entered state LOADING.
>> cur:S  17:02:37.313939 UNLOADING    | 37.313961 Entered state UNLOADING.
>> cur:S  17:02:37.313968 NOTREADY     | 37.314003 Entered state NOTREADY.
>>                                     | 37.314026 Entered state LOADING.
>>                                     | 37.314049 Entered state UNLOADING.
>>                                     | 37.314068 Entered state NOTREADY.
>>                                     | 37.314095 Entered state LOADING.
>> cur:S  17:02:37.314098 UNLOADING    | 37.314121 Entered state UNLOADING.
>> cur:S  17:02:37.314124 NOTREADY     | 37.314140 Entered state NOTREADY.
>> cur:S  17:02:37.314146 LOADING      | 37.314163 Entered state LOADING.
>> cur:S  17:02:37.314169 UNLOADING    | 37.314186 Entered state UNLOADING.
>> cur:S  17:02:37.314192 NOTREADY     | 37.314213 Entered state NOTREADY.
>> 
>> 
>> For the first roughly 2000 cycles it is synchron and then updates of the PV are
>> missing. This time in the example above 4 transitions are missing. The next one
>> in my example was again 4 transitions, after that 6 transitions.
>> 
> The left column above is your camonitor output, the right column comes from the printf() calls in the sequence program. The above output actually matches what I would expect to happen, since the IOC's Channel Access server can and does throw away monitor update events when a CA client doesn't keep up with the data stream being sent to it.
> 
> Your sequence program is (presumably) running in the same process as the IOC, so CA is able to use a short-cut connection which can send and receive messages faster than when the connection goes over a TCP socket to a different process. The camonitor program is a separate process, so messages to and from the IOC must be serialized, pass through the OS kernel, then deserialized again at the other end. Monitor events are queued inside the IOC, and if the client doesn't handle them as quickly as they get queued eventually the event queue fills up and the IOC will throw away previously queued events to avoid filling up memory. It never discards the latest event though, so a client will always receive the last value queued if the slow-up was temporary or the data stream stops.
> 
> Channel Access was explicitly designed to not be a data acquisition protocol, its aim was that a badly-behaved client should not be able to affect the operation of the real-time control system. In your case your event stream seems to be generated faster that your client can accept it, so you either need to slow down the event stream, or accept that the client will not see every event.
> 
> HTH,
> 
> - Andrew
> 
>> I tested the behavior with seq v2.2.7 and EPICS 3.16 and EPICS 3.14 on a
>> CentOS7.
>> Let me know, in case you need more information to debug the problem.
>> 
>> Best regards,
>> Simon
>> 
>> 
>> 
>> On Wed, 2019-10-02 at 14:57 +0200, Simon Reiter via Tech-talk wrote:
>> 
>>> -------- Forwarded Message --------
>>> From: Simon Reiter 
>>> <simon.reiter@exp2.physik.uni-giessen.de>
>>> 
>>> To: 
>>> tech-talk-request@aps.anl.gov
>>> 
>>> Subject: fast PV transition skipped?
>>> Date: Tue, 1 Oct 2019 11:55:29 +0200
>>> 
>>> Hi,
>>> 
>>> I am observing a strange behavior with EPICS 3.16 and the sequencer v2.2.7.
>>> But
>>> I fear
>>> it origins in base. So this is, what is used:
>>> 
>>> 1. I set a mbbo PV "main:req" from 1 to 3(e.g. by caput)
>>> 2. A calcout PV pushed to a dfanout (input as CPP)
>>> 3. dfanouts pushes to second mbbo "sub:req"
>>> 4. sequencer reacts onto second mbbo and changes its state correctly rom 1 ->
>>> 2
>>> (visible via logging)
>>> 5. a thrid mbbo "sub:cur" is set by the sequencer (using SYNC and usleep(100)
>>> )
>>> 
>>> 6. I set the first mbbo PV "main:req" back to 1
>>> 7. repeat of step 2 and 3
>>> 8. sequencer needs to go from state 2 to state 4 before going back to state 1
>>> (also visible via logging)
>>> 
>>> But in case I do step 1 and 6 too close to each other, step 8 seems to not
>>> push
>>> the state correctly. The logging inside the IOC shows me that the state was
>>> included in the transistions.
>>> 
>>> 
>>> This is my logging via camonitor:
>>> 
>>> caput main:req 3 && caput main:req 1
>>> 
>>> --- works ---
>>> sub:req       2019-10-01 09:37:20.373428 3
>>> sub:req       2019-10-01 09:37:20.410165 1
>>> 
>>> sub:cur       2019-10-01 09:37:20.374262 2
>>> sub:cur       2019-10-01 09:37:20.410946 4
>>> sub:cur       2019-10-01 09:37:20.411308 1
>>> 
>>> --- fails ---
>>> sub:req       2019-10-01 09:37:50.956651 3
>>> sub:req       2019-10-01 09:37:50.993201 1
>>> 
>>> sub:cur       2019-10-01 09:37:50.957223 2
>>> sub:cur       2019-10-01 09:37:50.994039 1
>>> 
>>> 
>>> Currently I have not yet stripped my project to a very small version and
>>> there
>>> is more than just 1 sub in total.
>>> 
>>> 
>>> 
>>> In addition to this I have a copy (simple calcout with CPP as input) of
>>> sub:cur
>>> in a separate IOC on a different host (actually ppc). I observed that this PV
>>> is not updated properly as well sometimes:
>>> 
>>> sub:cur       2019-09-30 17:45:23.270295 2
>>> copy:sub:cur  2019-09-30 17:45:23.270986 2
>>> sub:cur       2019-09-30 17:45:25.280127 3
>>> sub:cur       2019-09-30 17:45:25.280533 1
>>> copy:sub:cur  2019-09-30 17:45:25.281447 1
>>> 
>>> 
>>> 
>>> With EPICS 3.14 this does not occur.
>>> 
>>> Any idea, what might have changed and where this problem is connected to?
>>> 
>>> Best regards,
>>> Simon
>>> 
>>> 
>>> 
> 
> -- 
> Complexity comes for free, Simplicity you have to work for.
> 

—

Simon Reiter
II. Physikalisches Institut
Justus-Liebig-Universität
Heinrich-Buff-Ring 14
D-35392 Giessen
Tel: +49 641 99 33250
simon.reiter@physik.jlug.de