Experimental Physics and
Industrial Control System

1994 1995 1996 1997 1998 1999 2000 2001 2002 2003 2004 2005 2006 2007 2008 2009 2010 2011 2012 2013 2014 2015 2016 2017 2018 2019 2020 2021 2022 <2023> 2024	Index	1994 1995 1996 1997 1998 1999 2000 2001 2002 2003 2004 2005 2006 2007 2008 2009 2010 2011 2012 2013 2014 2015 2016 2017 2018 2019 2020 2021 2022 <2023> 2024
<== Date ==>		<== Thread ==>

Subject:	RE: Weird behaviour in wait=True when using epics.Motor.get(something,something,wait=True)
From:	Mark Rivers via Tech-talk <tech-talk at aps.anl.gov>
To:	"Marco A. Barra Montevechi Filho" <marco.filho at lnls.br>, Matthew Newville <newville at cars.uchicago.edu>
Cc:	SWC <swc at lnls.br>, "tech-talk at aps.anl.gov" <tech-talk at aps.anl.gov>
Date:	Thu, 19 Jan 2023 17:48:36 +0000

It would be interesting to test whether you observe exactly the same events with camonitor that you observe with Python callbacks. You can run camonitor at the same time you are running the Python tests.

Mark

From: Marco A. Barra Montevechi Filho <marco.filho at lnls.br>
Sent: Thursday, January 19, 2023 9:42 AM
To: Matthew Newville <newville at cars.uchicago.edu>
Cc: Mark Rivers <rivers at cars.uchicago.edu>; SWC <swc at lnls.br>; tech-talk at aps.anl.gov; mooney at anl.gov
Subject: Re: Weird behaviour in wait=True when using epics.Motor.get(something,something,wait=True)

Updates on testing:

So, i did the suggested test alternating CNEN (between 0 and 1), VELO (1 and 2), DHLM (4 and 5) and DLLM (-4 and -5) fields. Not because they have any particular physical meaning, but to understand if the behavior is similar in several motor record fields. I tested at least twice for each field.

I append the code for testing below and attach the logs as files. What i found interesting:

1 - In some tests, the first print from callback function is the first value in which the field was before changing (i.e., before the first caput in the code is called). In some other tests, the first print is the value only after being changed via caput. This suggests to me that the "add_callback" method by itself sometimes triggers a callback and sometimes doesnt. I remember having observed this behavior before with other PVs.

2 - In several parts of the log, callback prints the same value twice. This is more or less predictable: DLLM field for example seems to almost always trigger two callbacks at once, but there are cases like the end of Loop 6 in CNEN_LOG1 where it seems out of the pattern: CNEN almost always triggers only one callback, but in this loop i got two at once.

What i understand:

1 - some fields typically (but not always) trigger callbacks twice and some dont.
2 - the add_callback method may or may not immediately call the callback function, even if no value has been altered in the PV.

What i dont understand:

1 - What are the causes of intermittence in behavior 1, such as observed in end of loop 6?
2 - What are the causes of intermitence in behavior 2?

Generic question: can these things be controlled or is it just something i have to live with?

Thanks so much for your patience. Best regards,

Marco

##########################################
CODE FOR TESTING CNEN:

#!/usr/bin/python3

import epics, time, sys

def check_value(pvname,value,timestamp=0,**kwargs):

print("Callback for", pvname, value, timestamp)

motor = epics.Motor("MGN:B:E873A:DIAG:X:m1")

cnen_val = motor.get("CNEN")

print("Initial CNEN value: ",cnen_val)

motor._pvs["CNEN"].add_callback(check_value)

sleep_time = 0.1

for i in range(0,10):

print("###Loop",i)

time.sleep(sleep_time)

for cnen_val in (0,1,0,1,0,1,0,1):

motor.put("CNEN",cnen_val,wait=False)

time.sleep(sleep_time)

print("Loop {} done.".format(i))

time.sleep(1)

###code for testing DHLM, DLLM and VELO is identical changing CNEN by respective fields and (0,1,0,1,0,1,0,1) by the values seen in logs.

##################################################

From: Marco A. Barra Montevechi Filho <marco.filho at lnls.br>
Sent: 18 January 2023 08:44
To: Matt Newville <newville at cars.uchicago.edu>
Cc: Mark Rivers <rivers at cars.uchicago.edu>; SWC <swc at lnls.br>; tech-talk at aps.anl.gov <tech-talk at aps.anl.gov>; mooney at anl.gov <mooney at anl.gov>
Subject: Re: Weird behaviour in wait=True when using epics.Motor.get(something,something,wait=True)

>Wouldn't the idea of changing that setting mean that you expect the timing for a "put()" to be changing too?

Yes, i believe that makes sense. In any case, CNEN field was the one i detected the behavior, but it also happens with VELO and i suspect with others too. Anyway, i think Mark's explanation about how wait=True works in python code makes it clear why the return from put can take weird amounts of time to happen. In any case, its clear that wait=True wont solve for what i want. Callbacks might do the work, but i have doubts about it.

> But, I would also suggest not mixing shell and Python for any timing work.

Makes total sense, not very smart of my part now that i think about it.

Im going to test a few things with callbacks and report any useful result. Thanks!

Best regards,

Marco

From: Matt Newville <newville at cars.uchicago.edu>
Sent: 17 January 2023 15:57
To: Marco A. Barra Montevechi Filho <marco.filho at lnls.br>
Cc: Mark Rivers <rivers at cars.uchicago.edu>; SWC <swc at lnls.br>; tech-talk at aps.anl.gov <tech-talk at aps.anl.gov>; mooney at anl.gov <mooney at anl.gov>
Subject: Re: Weird behaviour in wait=True when using epics.Motor.get(something,something,wait=True)

Marco,

I have to admit I do not know for sure when a put to a Motor Record's CNEN field would take a lot of time. It seems odd to be changing a motor from closed- to open-loop control with any frequency at all, especially while also moving the motor and/or expecting positions to be reported well. Wouldn't the idea of changing that setting mean that you expect the timing for a "put()" to be changing too?

That said, I would say that getting callbacks themselves should be fairly predictable. But, I would also suggest not mixing shell and Python for any timing work. That will include the startup of Python and the initial connection of Epics PVs. Those should not be slow, but it will involve network traffic so not completely determined.

I might suggest starting with something like this:

#######

import epics

import time

def check_values(pvname, value, timestamp=0, **kwargs):

print('callback for ', pvname, value, timestamp)

motor = epics.Motor('MGN:B:E873A:DIAG:X:m1')

# get the value of the CNEN field to make sure that PV/Channel is connected

cnen_val = motor.get('CNEN')

# with that connected, add the callback

motor._pvs['CNEN'].add_callback(check_value)

SLEEP_TIME = 0.1

for i in range(10):

print('# Loop ', i)

time.sleep(SLEEP_TIME)

for cnen_val in (0, 1, 0, 1, 0, 1, 0, 1, 0, 1):

motor.put('CNEN', cnen_val, wait=False)

time.sleep(SLEEP_TIME)

print("LOOP DONE")

time.sleep(1)

#############

or some variations from that. Unless the SLEEP_TIME is way too fast for processing, I think you should get all the callbacks run. Or, you could try using `wait=True` for that put.

On Tue, Jan 17, 2023 at 12:26 PM Marco A. Barra Montevechi Filho <marco.filho at lnls.br> wrote:

>However, if the motor record writes multiple values to a field (and does a callback) in rapid succession you are not guaranteed to receive callbacks for all of the values.

Im not sure if i understood this so i made some scripts to test. I made a script called test.py:

import epics, sys, time

desired_value = sys.argv[1]

def check_value(**kwargs):

print("a")

a = epics.Motor("MGN:B:E873A:DIAG:X:m1")

b = epics.PV("MGN:B:E873A:DIAG:X:m1.CNEN")

b.add_callback(check_value)

a.put("CNEN",desired_value)

and in my terminal: for i in {0..50}; do echo "b"; ./test.py $((1-$a)); sleep 0.1; done

What i got was several "a"s and "b"s but with much more "b"s:

b

a

b

a

b

b

b

a

(etc...)

So i supposed this is not because im not getting the callback, but because my script is terminating before i have time to receive the callback and execute the check_value function. So i added sleep(0.1) after a.put("CNEN", desired_value) and now what i get when doing
for i in {0..50}; do echo "b"; ./test.py $((1-$a)); sleep 0.1; done
is several "a"s and "b"s but now with more "a"s than "b"s:

b

a

a

b

a

a
(etc...)

So im guessing i not only have time to receive the callback but im also receiving two sometimes. Is this line way of reasoning correct?

Thanks in advance,

Marco

From: Mark Rivers <rivers at cars.uchicago.edu>
Sent: 17 January 2023 14:27
To: Marco A. Barra Montevechi Filho <marco.filho at lnls.br>; Matthew Newville <newville at cars.uchicago.edu>
Cc: SWC <swc at lnls.br>; tech-talk at aps.anl.gov <tech-talk at aps.anl.gov>; mooney at anl.gov <mooney at anl.gov>
Subject: Re: Weird behaviour in wait=True when using epics.Motor.get(something,something,wait=True)

> Is this behavior the same with the callbacks (i mean at python level like the add_callback in the PV objects)? Is this why i sometimes get two, one or no callback from record in identical situations in a kinda unpredictable manner?

No, I don't think that should affect callbacks. The motor record does callbacks even while it is moving.

However, if the motor record writes multiple values to a field (and does a callback) in rapid succession you are not guaranteed to receive callbacks for all of the values. There is no queuing in the Channel Access server, so you are only guaranteed to get the last value of the field. That can explain behavior where you sometimes get a callback on an intermediate value, and sometimes you don't.

Mark

From: Marco A. Barra Montevechi Filho <marco.filho at lnls.br>
Sent: Tuesday, January 17, 2023 11:20 AM
To: Mark Rivers <rivers at cars.uchicago.edu>; Matthew Newville <newville at cars.uchicago.edu>
Cc: SWC <swc at lnls.br>; tech-talk at aps.anl.gov <tech-talk at aps.anl.gov>; mooney at anl.gov <mooney at anl.gov>
Subject: Re: Weird behaviour in wait=True when using epics.Motor.get(something,something,wait=True)

That explains a lot!

Is this behavior the same with the callbacks (i mean at python level like the add_callback in the PV objects)? Is this why i sometimes get two, one or no callback from record in identical situations in a kinda unpredictable manner?

If yes, what is the best way of checking the field (not the record) for updates?

The best i cant think is something like:

start_time=time.time()
while VALUE!=desired_value:
VALUE=epics.caget(BLAH)
time.sleep(0.1)
if time.time()-start_time>timeout:
raise SomeException

But this could considerably slow my scan. Is there a better way?

Thanks,

Marco

From: Mark Rivers <rivers at cars.uchicago.edu>
Sent: 17 January 2023 14:11
To: Matthew Newville <newville at cars.uchicago.edu>; Marco A. Barra Montevechi Filho <marco.filho at lnls.br>
Cc: SWC <swc at lnls.br>; tech-talk at aps.anl.gov <tech-talk at aps.anl.gov>; mooney at anl.gov <mooney at anl.gov>
Subject: Re: Weird behaviour in wait=True when using epics.Motor.get(something,something,wait=True)

Hi Marco,

I think there may be a complication with the motor record, and other complex records like mca, scaler, etc. Using Python put(wait=True) means you are using ca_put_callback() in the underlying Channel Access C code. ca_put_callback() completes when the record calls recGblFwdLink(). For those complex records recGblFwdLink() is called when the record is "done". For the motor record that means that a move is complete, for the mca and scaler record it means acquisition is complete. I think this means that if a move is in progress when writing to CNEN then that write will only complete when the move is complete, so it could take a long time.

Tim Mooney may correct me if my understanding is wrong.

Mark

From: Tech-talk <tech-talk-bounces at aps.anl.gov> on behalf of Marco A. Barra Montevechi Filho via Tech-talk <tech-talk at aps.anl.gov>
Sent: Tuesday, January 17, 2023 10:53 AM
To: Matthew Newville <newville at cars.uchicago.edu>

Cc: SWC <swc at lnls.br>; tech-talk at aps.anl.gov <tech-talk at aps.anl.gov>

Subject: Re: Weird behaviour in wait=True when using epics.Motor.get(something,something,wait=True)

Thanks, Matt.

In my tests, put("CNEN",value,wait=True) returns in much less than 10 seconds, so i dont think this is the case.

Something interesting: i had the same problem with VELO field so im guessing problem is with my understanding about how the IOC works in general, not an actual communication with hardware problem.

Best regards,

Marco

From: Matt Newville <newville at cars.uchicago.edu>
Sent: 17 January 2023 13:30
To: Marco A. Barra Montevechi Filho <marco.filho at lnls.br>
Cc: tech-talk at aps.anl.gov <tech-talk at aps.anl.gov>; SWC <swc at lnls.br>
Subject: Re: Weird behaviour in wait=True when using epics.Motor.get(something,something,wait=True)

To follow up on Torsten's comment, the default timeout for a `epics.Motor.put()` is 10 seconds. The behavior you are seeing could be because the processing of setting CNEN takes more than that 10 seconds.

Giving a longer timeout to the `put()` might clarify what is happening.

On Mon, Jan 16, 2023 at 3:27 PM Marco A. Barra Montevechi Filho via Tech-talk <tech-talk at aps.anl.gov> wrote:

Good evening all.

Im working with the same IOC i was using here: https://epics.anl.gov/tech-talk/2023/msg00020.php. Now i loaded some motor records in it and am trying to control the IOC via pyepics. Something weird is happening.

i made the following python script:

import epics

a = epics.Motor("MGN:B:E873A:DIAG:X:m1")

a.put("CNEN", 1,wait=True)

assert a.get("CNEN")==1

And i frequently get assertion errors. What is happening? Shouldn't wait=True prevent this? How do i debug this?
Even more weird: i tried debugging this with callbacks:

import epics, time

a = epics.Motor(

"MGN:B:E873A:DIAG:X:m1")

def printvalue(**kwargs):

print(kwargs["value"])

b = epics.PV("MGN:B:E873A:DIAG:X:m1.CNEN")

b.add_callback(printvalue)

c = 1

while True:

c=1-c

print("#####")

a.put("CNEN",c)

time.sleep(0.1)

And i get prints like:

#####

1

#####

0

#####

1

0

#####

Why do i sometimes get two callbacks and sometimes get only one? Thanks in advance for any help.

I append the IOC initialization log and the substitutions file it loads:

INIT LOG:

#!/usr/local/epics/apps/pigcs2IOC/bin/linux-x86_64/pigcs2

< /usr/local/epics/apps/pigcs2IOC/iocBoot/iocPIGCS2/envPaths

epicsEnvSet("IOC","iocPIGCS2")

epicsEnvSet("TOP","/usr/local/epics-nfs/modules/R3.15.6/synApps/R6.1/support/motor-R7-1/modules/motorPIGCS2-R1-1/iocs/pigcs2IOC")

epicsEnvSet("SUPPORT","/usr/local/epics-nfs/modules/R3.15.6/synApps/R6.1/support")

epicsEnvSet("ASYN","/usr/local/epics-nfs/modules/R3.15.6/synApps/R6.1/support/asyn-R4-36")

epicsEnvSet("STREAM","/usr/local/epics-nfs/modules/R3.15.6/synApps/R6.1/support/StreamDevice-2-8-9")

epicsEnvSet("CALC","/usr/local/epics-nfs/modules/R3.15.6/synApps/R6.1/support/calc-R3-7-3")

epicsEnvSet("RECCASTER","/usr/local/epics-nfs/apps/recsync/1.4_epics_3.15/client")

epicsEnvSet("SNCSEQ","/usr/local/epics-nfs/modules/R3.15.6/synApps/R6.1/support/seq-2-2-6")

epicsEnvSet("BUSY","/usr/local/epics-nfs/modules/R3.15.6/synApps/R6.1/support/busy-R1-7-2")

epicsEnvSet("IPAC","/usr/local/epics-nfs/modules/R3.15.6/synApps/R6.1/support/ipac-2-15")

epicsEnvSet("MOTOR","/usr/local/epics-nfs/modules/R3.15.6/synApps/R6.1/support/motor-R7-1")

epicsEnvSet("EPICS_BASE","/usr/local/epics-nfs/base/R3.15.6")

cd "/usr/local/epics-nfs/modules/R3.15.6/synApps/R6.1/support/motor-R7-1/modules/motorPIGCS2-R1-1/iocs/pigcs2IOC"

## Set up environment

epicsEnvSet("DEV","MGN:B:E873A:DIAG:X:")

epicsEnvSet("BL", "MGN:B:E873A:DIAG:X")

epicsEnvSet("IOCNAME", "MGN-B-E873A-DIAG-X")

epicsEnvSet("EPICS_CA_MAX_ARRAY_BYTES",15728645)

# protocol file paths

epicsEnvSet ("STREAM_PROTOCOL_PATH", ".:/usr/local/epics-nfs/modules/R3.15.6/synApps/R6.1/support/motor-R7-1/db")

## Register all support components

dbLoadDatabase "dbd/pigcs2.dbd"

pigcs2_registerRecordDeviceDriver pdbbase

cd "/usr/local/epics-nfs/modules/R3.15.6/synApps/R6.1/support/motor-R7-1/modules/motorPIGCS2-R1-1/iocs/pigcs2IOC/iocBoot/iocPIGCS2"

## motorUtil (allstop & alldone)

dbLoadRecords("/usr/local/epics-nfs/modules/R3.15.6/synApps/R6.1/support/motor-R7-1/db/motorUtil.db", "P=MGN:B:E873A:DIAG:X:")

##

# < PI_GCS2.cmd

# PI GCS2 support

dbLoadTemplate("/usr/local/epics/apps/config/PIGCS2/e873aX.substitutions")

drvAsynIPPortConfigure("E873_ETH","CDE5B3D.abtlus.org.br:50000",0,0,0)

# Turn on asyn trace

# asynSetTraceMask("E873_ETH",0,3)

# asynSetTraceIOMask("E873_ETH",0,1)

# PI_GCS2_CreateController(portName, asynPort, numAxes, priority, stackSize, movingPollingRate, idlePollingRate)

# # this is the final setup

# PI_GCS2_CreateController("E873", "E873_ETH", 1, 0, 0, 100, 1000)

# speedup debug

PI_GCS2_CreateController("E873", "E873_ETH", 1, 0, 0, 50, 1000)

2023/01/16 18:23:03.949 read from E873_ETH: (c)2016-2020 Physik Instrumente (PI) GmbH & Co. KG, E-873.1AT, 120040762, 03.033

PIasynAxis::PIasynAxis() 0: 1

----------------- axis num: 0 createCLParams() m_szAxisName: 1-------------------

# Turn off asyn trace

# asynSetTraceMask("E873_ETH",0,1)

# asynSetTraceIOMask("E873_ETH",0,0)

# Set end-of-string terminators (port, addr, terminator)

asynOctetSetInputEos("E873_ETH", 0, "\n")

asynOctetSetOutputEos("E873_ETH", 0, "\n")

dbLoadRecords("/usr/local/epics-nfs/modules/R3.15.6/synApps/R6.1/support/motor-R7-1/modules/motorPIGCS2-R1-1/iocs/pigcs2IOC/db/PI_Support.db","P=MGN:B:E873A:DIAG:X:,R=m1:,PORT=E873,ADDR=0,TIMEOUT=1")

# asyn record for troubleshooting

dbLoadRecords("/usr/local/epics-nfs/modules/R3.15.6/synApps/R6.1/support/asyn-R4-36/db/asynRecord.db","P=MGN:B:E873A:DIAG:X:,R=asynEth,PORT=E873_ETH,ADDR=0,OMAX=256,IMAX=524288")

# RECSYNC

dbLoadRecords("/usr/local/epics-nfs/apps/recsync/1.4_epics_3.15/client/db/reccaster.db", "P=MGN:B:E873A:DIAG:X:REC:")

# protocol

#dbLoadRecords("$(MOTOR)/db/e873.db", "P=$(DEV),PORT=E873_ETH")

iocInit

Starting iocInit

############################################################################

## EPICS R3.15.6

## EPICS Base built Sep 27 2021

############################################################################

e873aX.substitutions FILE:

file "$(MOTOR)/motorApp/Db/asyn_motor.db"

{

pattern

{P, M, DTYP, PORT, ADDR, DESC, EGU, DIR, VELO, VBAS, ACCL, BDST, BVEL, BACC, MRES, PREC, DHLM, DLLM, INIT}

{MGN:B:E873A:DIAG:X:, "m1", "asynMotor", "E873", 0, "Motor 1", mm, Pos, 1, 0, .1, 0, 0, 0, 0.000001, 7, 5.0, -5.0, ""}

}

Aviso Legal: Esta mensagem e seus anexos podem conter informações confidenciais e/ou de uso restrito. Observe atentamente seu conteúdo e considere eventual consulta ao remetente antes de copiá-la, divulgá-la ou distribuí-la. Se você recebeu esta mensagem por engano, por favor avise o remetente e apague-a imediatamente.

Disclaimer: This email and its attachments may contain confidential and/or privileged information. Observe its content carefully and consider possible querying to the sender before copying, disclosing or distributing it. If you have received this email by mistake, please notify the sender and delete it immediately.

--Matt Newville <newville at cars.uchicago.edu> 630-327-7411

References:: Weird behaviour in wait=True when using epics.Motor.get(something,something,wait=True) Marco A. Barra Montevechi Filho via Tech-talk; Re: Weird behaviour in wait=True when using epics.Motor.get(something, something, wait=True) Matt Newville via Tech-talk; Re: Weird behaviour in wait=True when using epics.Motor.get(something,something,wait=True) Marco A. Barra Montevechi Filho via Tech-talk; Re: Weird behaviour in wait=True when using epics.Motor.get(something,something,wait=True) Mark Rivers via Tech-talk; Re: Weird behaviour in wait=True when using epics.Motor.get(something,something,wait=True) Marco A. Barra Montevechi Filho via Tech-talk; Re: Weird behaviour in wait=True when using epics.Motor.get(something,something,wait=True) Mark Rivers via Tech-talk; Re: Weird behaviour in wait=True when using epics.Motor.get(something,something,wait=True) Marco A. Barra Montevechi Filho via Tech-talk; Re: Weird behaviour in wait=True when using epics.Motor.get(something, something, wait=True) Matt Newville via Tech-talk; Re: Weird behaviour in wait=True when using epics.Motor.get(something,something,wait=True) Marco A. Barra Montevechi Filho via Tech-talk; Re: Weird behaviour in wait=True when using epics.Motor.get(something,something,wait=True) Marco A. Barra Montevechi Filho via Tech-talk

Navigate by Date:: Prev: Re: Weird behaviour in wait=True when using epics.Motor.get(something,something,wait=True) Marco A. Barra Montevechi Filho via Tech-talk; Next: Re: Weird behaviour in wait=True when using epics.Motor.get(something, something, wait=True) Matt Newville via Tech-talk; Index: 1994 1995 1996 1997 1998 1999 2000 2001 2002 2003 2004 2005 2006 2007 2008 2009 2010 2011 2012 2013 2014 2015 2016 2017 2018 2019 2020 2021 2022 <2023> 2024
Navigate by Thread:: Prev: Re: Weird behaviour in wait=True when using epics.Motor.get(something,something,wait=True) Marco A. Barra Montevechi Filho via Tech-talk; Next: Re: Weird behaviour in wait=True when using epics.Motor.get(something, something, wait=True) Matt Newville via Tech-talk; Index: 1994 1995 1996 1997 1998 1999 2000 2001 2002 2003 2004 2005 2006 2007 2008 2009 2010 2011 2012 2013 2014 2015 2016 2017 2018 2019 2020 2021 2022 <2023> 2024

ANJ, 19 Jan 2023

· Home · News · About · Base · Modules · Extensions · Distributions · Download ·
· Search · EPICS V4 · IRMIS · Talk · Bugs · Documents · Links · Licensing ·

Experimental Physics and Industrial Control System

Experimental Physics and
Industrial Control System