Experimental Physics and
Industrial Control System

Michael Davidsaver via Core-talk <[email protected]> · Sun, 30 Dec 2018 10:08:15 -0800

>>caput -c -w2 testBusyAsyn:Busy 1
...
> When I run this test application I do NOT get the warning messages from base 7.0.2.

I think the warning you see has served its purpose and can be removed,
or made conditional on dbAccessDebugPUTF.  This condition is inevitable
if record support process() is allowed to return PACT=0 without
calling recGblFwdLink()

The real issue is that you should be seeing this warning both with and
without '-c'.  That you do not is a symptom of dbNotify never setting PUTF.
While it wasn't immediately clear to me, dbPutField() is only used for link fields.
In other cases, the logic of dbPutField() is partially replicated in dbNotify.c
with calls to dbPut() and dbProcess().

On 12/21/18 3:29 PM, Mark Rivers wrote:
> Hi Michael,
> 
>  
> 
> I have now reproduced the problem with a simple 6 record database (attached).  This database can be run on any IOC that is built with the busy record.  A simple one is busy/busyApp/src/testBusyAsyn.cpp.  That IOC also requires asyn, but this database does not.
> 
>  
> 
> The database works as follows:
> 
>  
> 
> bo record Acquire.  Writing 1 to this record is what will trigger the problem.
> 
>  
> 
> bi record Acquire_RBV.  This record is written to by Acquire.  It is set to 0 by Reset.  It is monitored by ClearBusy.
> 
>  
> 
> calcout record SetBusy.  This record is FLNKd by Acquire and gets its value from Acquire.  On transition to 1 it sets Busy to 1.  It FNLKs to Reset.
> 
>  
> 
> busy record Busy.  The value 1 is written to this record by SetBusy and the value 0 is written to it by ClearBusy.  The busy record is basically a clone of the bo record except that it only calls RecGblFwdLink when its value is 0.
> 
>  
> 
> seq record Reset.  This record processed when 1 is written to Busy.  It has a delay of 1 second, and after that time it writes 0 to Acquire_RBV.  It is disabled if Busy is 0 to avoid infinite loop.
> 
>  
> 
> calcout record ClearBusy.  This record monitors Acquire_RBV.  On that PV transitioning from 1 to 0 it writes 0 to the Busy record.  I believe it is this write operation that is causing the error in EPICS base.
> 
>  
> 
> This is the error from EPICS base 7.0.2 after I also added a call to epicsStaceTrace() in addition to the errlogPrintf.
> 
>  
> 
> epics> Dumping a stack trace of thread 'scanOnce':
> 
> [    0x7f49751f113b]: /usr/local/epics-devel/base-7.0.2/lib/linux-x86_64/libCom.so.3.17.2(epicsStackTrace+0x4b)
> 
> [    0x7f49756b7057]: /usr/local/epics-devel/base-7.0.2/lib/linux-x86_64/libdbCore.so.3.17.2(dbDbPutValue+0x107)
> 
> [    0x7f49756bac19]: /usr/local/epics-devel/base-7.0.2/lib/linux-x86_64/libdbCore.so.3.17.2(dbPutLink+0x29)
> 
> [    0x7f497592f8a8]: /usr/local/epics-devel/base-7.0.2/lib/linux-x86_64/libdbRecStd.so.3.17.2(execOutput+0x88)
> 
> [    0x7f497592ff29]: /usr/local/epics-devel/base-7.0.2/lib/linux-x86_64/libdbRecStd.so.3.17.2(process+0x589)
> 
> [    0x7f49756a91c8]: /usr/local/epics-devel/base-7.0.2/lib/linux-x86_64/libdbCore.so.3.17.2(dbProcess+0x1d8)
> 
> [    0x7f49756bcb37]: /usr/local/epics-devel/base-7.0.2/lib/linux-x86_64/libdbCore.so.3.17.2(onceTask+0x87)
> 
> [    0x7f49751eb7bc]: /usr/local/epics-devel/base-7.0.2/lib/linux-x86_64/libCom.so.3.17.2(start_routine+0xdc)
> 
> [    0x7f49743aae25]: /lib64/libpthread.so.0(start_thread+0xc5)
> 
> [    0x7f49746bdbad]: /lib64/libc.so.6(clone+0x6d)
> 
> Warning: 'testBusyAsyn:Busy.PUTF' found true with PACT false
> 
>  
> 
>  
> 
> Mark
> 
>  
> 
>  
> 
>  
> 
>  
> 
>  
> 
> *From:* Mark Rivers
> *Sent:* Thursday, December 20, 2018 12:53 PM
> *To:* 'Michael Davidsaver' <[email protected]>
> *Cc:* '[email protected]' <[email protected]>; 'Johnson, Andrew N.' <[email protected]>
> *Subject:* RE: Issues with latest version of base-7.0
> 
>  
> 
> Hi Michael,
> 
>  
> 
> I would like to pursue this issue a bit.
> 
>  
> 
> I have a test application in the synApps busy module.  It simulates the way a typical asynchronous asyn port driver works.
> 
>  
> 
> - Busy record is set to 1 to initiate an operation. Busy record sets PACT=1
> 
> - Driver get a write of the value 1 and starts a time-consuming operation in another thread.
> 
> - Busy record completes asynchronous record processing and sets PACT=0 as soon as this write operation is complete.  However, it does NOT call recGblFwdLink.
> 
> - Driver does a callback with a value 0 when the time consuming operation is done.
> 
> - Busy record processes again.  Because the value is now 0 it calls RecGblFwdLink.
> 
>  
> 
> If clients do ca_put_callback when writing 1 to the busy record, the callback will not occur until the busy record goes back to 0.
> 
>  
> 
>  
> 
> This is the medm screen for the test application.  The sleep time is the time that the driver is “busy” before it does the callback.
> 
>  
> 
> Since the sleep time is 1 second I set the timeout for a ca_put_callback to 2 seconds.  caput –c does not return until 1 second has elapsed, while caput without –c returns immediately.
> 
>  
> 
>>caput -c -w2 testBusyAsyn:Busy 1
> 
>  
> 
> camonitor shows that it is exactly 1 second after the busy record set to 1 that it goes back to 0.
> 
>  
> 
> corvette:simDetectorIOC/iocBoot/iocSimDetector>camonitor testBusyAsyn:Busy
> 
> testBusyAsyn:Busy              2018-12-20 12:26:03.111412 Zero
> 
> testBusyAsyn:Busy              2018-12-20 12:28:10.403137 One
> 
> testBusyAsyn:Busy              2018-12-20 12:28:11.403340 Zero
> 
>  
> 
> When I run this test application I do NOT get the warning messages from base 7.0.2.
> 
>  
> 
> However, when I run the real areaDetector drivers I do.  I would like to understand why that is the case, and make sure I am not doing something wrong in areaDetector.
> 
>  
> 
> These are the database records involved:
> 
>  
> 
> *****************************************
> 
> record(bo, "$(P)$(R)Acquire") {
> 
>    field(DTYP, "asynInt32")
> 
>    field(OUT, "@asyn($(PORT),$(ADDR=0),$(TIMEOUT=1))ACQUIRE")
> 
>    field(ZNAM, "Done")
> 
>    field(ONAM, "Acquire")
> 
>    field(VAL,  "0")
> 
>    field(FLNK, "$(P)$(R)SetAcquireBusy")
> 
>    info(asyn:READBACK, "1")
> 
> }
> 
>  
> 
> record(bi, "$(P)$(R)Acquire_RBV") {
> 
>    field(DTYP, "asynInt32")
> 
>    field(INP, "@asyn($(PORT),$(ADDR=0),$(TIMEOUT=1))ACQUIRE")
> 
>    field(ZNAM, "Done")
> 
>    field(ZSV,  "NO_ALARM")
> 
>    field(ONAM, "Acquiring")
> 
>    field(OSV,  "MINOR")
> 
>    field(SCAN, "I/O Intr")
> 
> }
> 
>  
> 
> record(calcout, "$(P)$(R)SetAcquireBusy")
> 
> {
> 
>     field(INPA, "$(P)$(R)Acquire NPP")
> 
>     field(CALC, "A")
> 
>     field(OOPT, "Transition To Non-zero")
> 
>     field(OUT,  "$(P)$(R)AcquireBusy PP")
> 
> }
> 
>  
> 
> record(busy, "$(P)$(R)AcquireBusy") {
> 
>    field(ZNAM, "Done")
> 
>    field(ZSV,  "NO_ALARM")
> 
>    field(ONAM, "Acquiring")
> 
>    field(OSV,  "MINOR")
> 
>    field(VAL,  "0")
> 
> }
> 
>  
> 
> record(calcout, "$(P)$(R)ClearAcquireBusy")
> 
> {
> 
>     field(INPA, "$(P)$(R)WaitForPlugins CP")
> 
>     field(INPB, "$(P)$(R)Acquire_RBV CP")
> 
>     field(INPC, "$(P)$(R)NumQueuedArrays CP")
> 
>     field(CALC, "A ? B || (C > 0) : B")
> 
>     field(OOPT, "Transition To Zero")
> 
>     field(OUT,  "$(P)$(R)AcquireBusy PP")
> 
> }
> 
> *****************************************
> 
>  
> 
> The way this database works is as follows:
> 
> -          Client writes 1 to Acquire to start acquisition
> 
> -          That forward links to SetAcquireBusy.   On transition from 0 to 1 that record writes 1 to AcquireBusy (the busy record)
> 
> -          When the driver is done it does a callback with value 0 on the Acquire_RBV record.
> 
> -          The ClearAcquireBusy record monitors Acquire_RBV with CP.  When it transitions to 0 it writes 0 to AcquireBusy, the busy record.  If WaitForPlugins is non-zero then this record also waits until NumQueuedArrays is 0 before setting AcquireBusy to 0.
> 
>  
> 
> I have modified dbDbLink.c to call epicsStackTrace just before printing the warning message.  I have also set the TPRO field of 13SIM1:cam1:AcquireBusy to 1.  This is what I see:
> 
>  
> 
> ca:epics@corvette: dbProcess of '13SIM1:cam1:AcquireBusy'
> 
> Dumping a stack trace of thread 'scanOnce':
> 
> [         0x11ae86b]: ../../bin/linux-x86_64/simDetectorApp(epicsStackTrace+0x4b)
> 
> [         0x115ed37]: ../../bin/linux-x86_64/simDetectorApp(dbDbPutValue+0x107)
> 
> [         0x112eeb9]: ../../bin/linux-x86_64/simDetectorApp(dbPutLink+0x29)
> 
> [         0x10f22b8]: ../../bin/linux-x86_64/simDetectorApp(execOutput+0x88)
> 
> [         0x10f2939]: ../../bin/linux-x86_64/simDetectorApp(process+0x589)
> 
> [         0x111e6c8]: ../../bin/linux-x86_64/simDetectorApp(dbProcess+0x1d8)
> 
> [         0x1130dd7]: ../../bin/linux-x86_64/simDetectorApp(onceTask+0x87)
> 
> [         0x11aa50c]: ../../bin/linux-x86_64/simDetectorApp(start_routine+0xdc)
> 
> [    0x7fa272973e25]: /lib64/libpthread.so.0(start_thread+0xc5)
> 
> [    0x7fa27182cbad]: /lib64/libc.so.6(clone+0x6d)
> 
> scanOnce: dbProcess of '13SIM1:cam1:AcquireBusy'
> 
> Warning: '13SIM1:cam1:AcquireBusy.PUTF' found true with PACT false
> 
>  
> 
> So I want to understand why the above database is causing the warning message to appear, when it does not appear for the simpler test in the busy module.
> 
>  
> 
> Any ideas?
> 
>  
> 
> Thanks,
> 
> Mark
> 
>  
> 
>  
> 
>  
> 
> -----Original Message-----
> From: Mark Rivers
> Sent: Wednesday, December 19, 2018 8:21 AM
> To: 'Johnson, Andrew N.' <[email protected] <mailto:[email protected]>>; Michael Davidsaver <[email protected] <mailto:[email protected]>>
> Cc: [email protected] <mailto:[email protected]>
> 
> 
> Subject: RE: Issues with latest version of base-7.0
> 
>  
> 
> Unfortunately it does not look like this issue is fixed in 7.0.2.  Whenever a busy record makes a transition from 1 to 0 this message is printed on the IOC:
> 
>  
> 
> Warning: '13SIM1:cam1:AcquireBusy.PUTF' found true with PACT false
> 
>  
> 
> It is coming from this file:
> 
> ./dbDbLink.c:            errlogPrintf("Warning: '%s.PUTF' found true with PACT false\n",
> 
>  
> 
> This will be annoying for everyone using the busy record, which is areaDetector and lots of synApps modules.
> 
>  
> 
> Thanks,
> 
> Mark
> 
>  
> 
>  
> 
> -----Original Message-----
> 
> From: Johnson, Andrew N. <[email protected] <mailto:[email protected]>>
> 
> Sent: Wednesday, November 14, 2018 9:18 PM
> 
> To: Michael Davidsaver <[email protected] <mailto:[email protected]>>
> 
> Cc: Mark Rivers <[email protected] <mailto:[email protected]>>; [email protected] <mailto:[email protected]>
> 
> Subject: Re: Issues with latest version of base-7.0
> 
>  
> 
> @Michael: call it experience of too many encounters with Murphy’s law...
> 
>  
> 
> I don’t think it’s worth using a debugger, this is probably because of the slightly unusual behavior of the busy record, which I didn’t really think about or test with this change. The synapps busy record explicitly allows the database to determine when processing is complete and hence when to fire put-completion; you should probably take a look at the busy::process() routine to understand it.
> 
>  
> 
> It has been suggested that we should add the busy record or something like it to base. Marty has a simple kind of busy record in the exampleCpp module.
> 
>  
> 
> I will look at Mark’s build issue when I get a chance, someone else here has also reported this, which is purely a warning message that I added but will probably disable for the final release.
> 
>  
> 
> - Andrew
> 
>  
> 
> --
> 
> Sent from my iPad
> 
>  
> 
>> On Nov 15, 2018, at 11:08 AM, Michael Davidsaver <[email protected] <mailto:[email protected]>> wrote:
> 
>> 
> 
>>> On 11/14/18 12:59 PM, Mark Rivers wrote:
> 
>>> I am having 2 issues with the version of base-7.0 that I updated today.
> 
>>> 
> 
>>> 
> 
>>> 
> 
>>> 1)      Whenever I set a “busy” record to 0 in my drivers (e.g. areaDetector) I see this warning from modules/database/src/ioc/db/dbDbLink.c
> 
>>> 
> 
>>> 
> 
>>> 
> 
>>> Warning: '13SIM1:cam1:AcquireBusy.PUTF' found true with PACT false
> 
>> 
> 
>> Ha, now Andrew can feel smug.  I originally made this an assert().
> 
>> 
> 
>> FYI. 7.0.2 has a change to the way the PUTF, PACT, and RPRO fields interact.
> 
>> The new protocol fixes an queuing issue when chaining multiple asynchronous records (via FLNK or OUT).
> 
>> This warning is flagging a state which I didn't think should ever happen.
> 
>> Though there is not any real harm if it does.
> 
>> 
> 
>> Can you run in a debugger and set a break point on the errlogPrintf() in question?
> 
>> I'd like to know the exact stack trace (and thus DB link chain) involved.
> 
>> 
> 
>> https://code.launchpad.net/~epics-core/epics-base/+git/prop-putf/+merge/336468
> 
>> 
> 
>> 
> 
>>> 2)      When I run “make” in any App/op/ that automatically converts adl files to opi, ui, etc. I get these warnings:
> 
>>> 
> 
>>> corvette:modbus/modbusApp/op>make
> 
>>> 
> 
>>> /corvette/usr/local/epics-devel/base-7.0.1/configure/RULES_COMMON:18: warning: overriding recipe for target `show-makefile.../../configure/CONFIG'
> 
>> 
> 
>> I'll leave this one to Andrew.
> 

Experimental Physics and Industrial Control System

Experimental Physics and
Industrial Control System