Re: Streamdevice - record only completes processing every other activation

[Zimoch Dirk via Tech-talk <tech-talk at aps.anl.gov>]

I just see you found out that much yourself :-)

On Thu, 2024-03-21 at 16:23 +0100, Zimoch Dirk wrote:
> Hi Evan,
> 
> Here is what happens:
> 
> Initially
> epics> dbgf _SRAM_TEST:SWEEP_CMD_EXSC
> DBF_DOUBLE:         0
> epics> dbpf SRAM_TEST:SWEEP_CMD_EXSC 1
> DBF_STRING:         "Sweep"  
> 
> Now the record outputs.
> 
> epics> dbgf _SRAM_TEST:SWEEP_CMD_EXSC
> DBF_DOUBLE:         1
> epics> dbpf SRAM_TEST:SWEEP_CMD_EXSC 1
> DBF_STRING:         "Sweep"   
> 
> Nothing happens.
> 
> epics> dbgf _SRAM_TEST:SWEEP_CMD_EXSC
> DBF_DOUBLE:         0
> 
> Because "Transition To Non-zero" does not apply now.
> 
> You have 
> field(INPA, "$(D):SWEEP_CMD_EXSC")
> and probably you think SWEEP_CMD_EXSC falls back to 0 after HIGH=0.5 seconds, so
> it should work the next time the user writes a 1.
> But the output record is still busy waiting for a reply from the hardware.
> StreamDevice is asynchronous, thus the trigger record can actually fall back to
> 0 while the output record is busy waiting. But the output record cannot be
> processed again by the fanout while it is busy. Thus it misses the trigger
> record going to 0. 
> 
> Only next time the user writes, A goes to 0. (I actually wonder why.) But now
> "Transition To Non-zero" prevents the record from writing.
> 
> If I make HIGH much longer, say 5 seconds, it works (if the user waits for 5
> seconds between writes) because now the output record is no longer busy when the
> trigger falls back to 0.
> 
> It may take me a bit longer to give you a working solution. The idea is to do
> the "Transition To Non-zero" in an earlier stage, not in the record that does
> the asynchronous I/O.
> 
> Some other remark:
> Record _$(D):SWEEP_CMD_EXSC references field B in a complicated way:
> out "fullsweep4 c %(_\$1:SWEEP_CMD_EXSC.B)#x";
> 
> You can simply use %(B)#x in this case.
> And if the record had
>     field(DOPT, "Use OCAL")
>     field(OCAL, "B")
> you could even simply use %#x.
> 
> Of course this does not affect the behavior you see.
> 
> Dirk
> 
> On Thu, 2024-03-21 at 14:13 +0000, Zimoch Dirk via Tech-talk wrote:
> > Hi Evan,
> > 
> > This is a hard to debug without your device.
> > I am a bit surprised about the "\r\0\n" line terminators in your code but if
> > that is what the device sends, so may it be.
> > 
> > BTW: I usually break such long lines for readability:
> >     in "\r\0\n\r\0\n"
> >        "Chip: 0\r\0\n"
> >        "# of Events: %(\$1:EVT_RD_CHIP0)d\r\0\n"
> >        "Chip: 1\r\0\n"
> >        "# of Events: %(\$1:EVT_RD_CHIP1)d\r\0\n"
> >        "Chip: 2\r\0\n"
> >        "# of Events: %(\$1:EVT_RD_CHIP2)d\r\0\n"
> >        "Chip: 3\r\0\n"
> >        "# of Events: %(\$1:EVT_RD_CHIP3)d";
> > 
> > As far as I know, RPRO goes to 1 when something writes to a record while it is
> > still processing (and thus locked). I thought that should make the record
> > process again once the current processing has finished.
> > 
> > To me this looks like the record is waiting for something and thus has not
> > finished processing. Probably for 2 seconds (ReadTimeout=2000).
> > 
> > Have you tried with 'var streamDebug 1'?
> > 
> > Dirk
> > 
> > On Wed, 2024-03-20 at 18:11 +0000, Daykin, Evan via Tech-talk wrote:
> > > Hi,
> > >  
> > > I have an unusual issue I haven’t seen before. I have a mode selector, activation bo, directed through a fanout (single output with SELL), which finally sends out a read command, like this:
> > >  
> > >  
> > > record(mbbo, "$(D):MODE_CMD_SWEEP"){
> > >     field(ZRST, "Fullsweep")
> > >     field(ZRVL, "0")
> > >     field(ONST, "Fullsweep4") <- SELECTED
> > >     field(ONVL, "1")
> > >     field(TWST, "Simulsweep4")
> > >     field(TWVL, "2")
> > > }
> > >  
> > > #User presses this to execute a scan, stays high for 0.5s
> > > record(bo, "$(D):SWEEP_CMD_EXSC"){
> > >     field(ZNAM, "Idle")
> > >     field(ONAM, "Sweep")
> > >     field(HIGH, "0.5")
> > >     field(VAL, "0")
> > >     field(FLNK, "_$(D):SWEEP_EXSC")
> > > }
> > >  
> > > record(fanout, "_$(D):SWEEP_EXSC"){
> > >     field(SELM, "Specified")
> > >     field(SELL, "$(D):MODE_CMD_SWEEP")
> > >     field(LNK0, "_$(D):SWEEP_CMD_DBG")
> > >     field(LNK1, "_$(D):SWEEP_CMD_EXSC") <- SELECTED
> > >     field(LNK2, "_$(D):SWEEP_CMD_SIM")
> > > }
> > >  
> > > record(calcout, "_$(D):SWEEP_CMD_EXSC"){
> > >     field(DTYP, "stream")
> > >     field(INPA, "$(D):SWEEP_CMD_EXSC")
> > >     field(INPB, "$(D):PAT_CSET_SWEEP")
> > >     field(CALC, "A")
> > >     field(OOPT, "Transition To Non-zero")
> > >     field(OUT, "@sram.proto fullsweep4($(D)) $(HOST)")
> > > }
> > >  
> > > The protocol file entry looks like this:
> > >  
> > > fullsweep4{
> > >     ReadTimeout=2000;
> > >     InTerminator="\r\0\n\r\0\n>";
> > >     out "fullsweep4 c %(_\$1:SWEEP_CMD_EXSC.B)#x";
> > >     in "\r\0\n\r\0\nChip: 0\r\0\n# of Events: %(\$1:EVT_RD_CHIP0)d\r\0\nChip: 1\r\0\n# of Events: %(\$1:EVT_RD_CHIP1)d\r\0\nChip: 2\r\0\n# of Events: %(\$1:EVT_RD_CHIP2)d\r\0\nChip: 3\r\0\n# of Events: %(\$1:EVT_RD_CHIP3)d";
> > > }
> > > it wants a message of the form:
> > >  
> > > Chip: 0
> > > # of Events: 131072
> > > Chip: 1
> > > # of Events: 131072
> > > Chip: 2
> > > # of Events: 131072
> > > Chip: 3
> > > # of Events: 131072
> > >  
> > >  
> > > But, the last record (calcout) _SWEEP_CMD_EXSC only fires every other time I activate the bo SWEEP_CMD_EXSC, and wireshark confirms it’s only sending out the inquiry every other click as well. Setting TPRO shows:
> > >  
> > > epics> ca:daykin@diag-cam: dbProcess of '_SRAM_TEST:SWEEP_CMD_EXSC'
> > > cbLow: dbProcess of '_SRAM_TEST:SWEEP_CMD_EXSC' <- Nothing actually happened, nothing in wireshark, readback records don’t update
> > >  
> > > ca:daykin@diag-cam: dbProcess of '_SRAM_TEST:SWEEP_CMD_EXSC'
> > > cbLow: dbProcess of Active '_SRAM_TEST:SWEEP_CMD_EXSC' with RPRO=0 <- Record fired correctly, readback records update
> > >  
> > > What does this indicate? What is RPRO doing?
> > >  
> > > Thank you,
> > > Evan
> > >  
> > >  
> > >