Re: fast PV transition skipped in EPICS 3.16

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

Hi all,

I had a closer look into this.

To start from scratch I used makeBaseApp.pl to create a fresh IOC. I removed
everything except the sequence.

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.

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.


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
> 
> 

record(mbbo, "cur:S")
{
  field(ZRVL, "0")
  field(ONVL, "1")
  field(TWVL, "2")
  field(THVL, "3")
  field(FRVL, "4")
  field(FVVL, "5")
  field(SXVL, "6")
  field(SVVL, "7")
  field(EIVL, "8")
  field(ELVL, "11")
  field(ZRST, "UNKNOWN")
  field(ONST, "NOTREADY")
  field(TWST, "READY")
  field(THST, "RUNNING")
  field(FRST, "LOADING")
  field(FVST, "UNLOADING")
  field(SXST, "STARTING")
  field(SVST, "STOPPING")
  field(EIST, "ABORTING")
  field(ELST, "ERROR")
  field(VAL,  "0")
  field(PINI, "YES")
}

program sncExample

option +c; /* wait for db connections */
option +r; /* make functions reentrant, multiple instances */
option -d; /* toggle runtime debugging messages */
option +W; /* extra warnings. */

int pv_cur;
assign pv_cur to "cur:S";

%{

enum {
    State_UNKNOWN   =  0,
    State_NOTREADY  =  1,
    State_LOADING   =  4,
    State_UNLOADING =  5,
};

float now() {
    struct timeval tv;
    gettimeofday(&tv, NULL);
    return tv.tv_sec % 60 + (float) (tv.tv_usec) / 1e6;
}
}%

ss ss1 {
    state S_NOTREADY {
        entry {
            pv_cur = State_NOTREADY;
            pvPut(pv_cur, SYNC);
            printf("%02.6f Entered state %s.\n", now(), "NOTREADY");
        }

        when() {
        } state S_LOADING
    }


    state S_LOADING {
        entry {
            pv_cur = State_LOADING;
            pvPut(pv_cur, SYNC);
            printf("%02.6f Entered state %s.\n", now(), "LOADING");
        }

        when() {
        } state S_UNLOADING
    }


    state S_UNLOADING {
        entry {
            pv_cur = State_UNLOADING;
            pvPut(pv_cur, SYNC);
            printf("%02.6f Entered state %s.\n", now(), "UNLOADING");
        }

        when() {
        } state S_NOTREADY
    }
}