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:	Custom Asyn motor driver hangs on any move after the first?
From:	Eloise de Castelnau via Tech-talk <tech-talk at aps.anl.gov>
To:	"tech-talk at aps.anl.gov" <tech-talk at aps.anl.gov>
Date:	Wed, 5 Oct 2022 22:20:30 +0000

Hi all,

I’m working on writing driver support for an applied motion stepper driver, based on the MCB4B motor v3 software, but running into an extremely strange issue where I am able to write a position to the motor once successfully upon motor startup, but subsequent attempts to write position seem to go unrecognized, or, weirder still, will only register the asyn command about 2 minutes after change to the VAL record (note in the logs below how I am able to set it to 550 within a few seconds of startup, and then I immediately issued a command to 600 with caput, but nothing acknowledged that until about 3 min later when it finally set the value). The implementation is so far very sparse, I overwrote all axis functions except for move and poll to do nothing and autoreturn asynSuccess to try to narrow down where this issue might be occurring and prevent hang points. I understand asyn is throwing some errors about some undefined fields (encoder res, etc) but I can’t imagine how these could be causing this issue. Is there some kind of check I need to validate or write to in the below implementations for motorAsyn to release the thread and allow it to be moved again ( presumably now it is only releasing after some timeout)? Any advice here would be hugely appreciated.

Thanks!

Eloise de Castelnau

Implementations of those functions:

asynStatus AMPAxis::move(double position, int relative, double minVelocity, double maxVelocity, double acceleration)

{

asynStatus status;

//static const char *functionName = "move";

if (relative) {

sprintf(pC_->outString_, "DI%d\rFL", NINT(position));

}

else {

sprintf(pC_->outString_, "SP%d", NINT(position));

}

status = pC_->writeController();

return status;

}

asynStatus AMPAxis::poll(bool *moving)

{

int done;

int driveOn;

int limit;

double position;

asynStatus comStatus;

// Read the current motor position

sprintf(pC_->outString_, "SP", axisNo_);

comStatus = pC_->writeReadController();

if (comStatus) goto skip;

position = atof(&pC_->inString_[3]);

setDoubleParam(pC_->motorPosition_, position);

*moving = false;

skip:

setIntegerParam(pC_->motorStatusProblem_, comStatus ? 1:0);

callParamCallbacks();

return asynSuccess;

}

Asyn debug output:

#!../../bin/linux-x86_64/amp

< envPaths

epicsEnvSet("IOC","iocamp")

epicsEnvSet("TOP","/opt/epics/modules/motor/modules/motorAMP/iocs/ampIOC")

epicsEnvSet("MOTOR","/opt/epics/modules/motor")

epicsEnvSet("ASYN","/opt/epics/base/../modules/asyn")

epicsEnvSet("SNCSEQ","/opt/epics/base/../modules/seq")

epicsEnvSet("BUSY","/opt/epics/base/../modules/busy")

epicsEnvSet("EPICS_BASE","/opt/epics/base")

cd "/opt/epics/modules/motor/modules/motorAMP/iocs/ampIOC"

## Register all support components

dbLoadDatabase "dbd/amp.dbd"

amp_registerRecordDeviceDriver pdbbase

dbLoadRecords("/opt/epics/modules/motor/db/motorUtil.db", "P=amp:")

dbLoadTemplate "iocBoot/iocamp/motor.substitutions.amp"

drvAsynSerialPortConfigure("serial1", "/dev/ttyUSB1", 0, 0, 0)

asynOctetSetInputEos("serial1",0,"\r")

asynOctetSetOutputEos("serial1",0,"\r")

asynSetTraceIOMask("serial1", -1, 0x01)

asynSetTraceMask("serial1", -1, 0x01)

#asynSetTraceMask("serial1", 0, 255)

# asynOctetConnect("s1","serial1",0,100,5000)

# asynOctetWrite("s1", "SP520\r")

### Motors

# dbLoadRecords("db/amp.db")

dbLoadRecords("/opt/epics/base/../modules/asyn/db/asynRecord.db","P=amp:,R=serial1,PORT=serial1,ADDR=0,OMAX=80,IMAX=80")

AMPCreateController("AMP1", "serial1", 1, 100, 5000)

asynSetTraceMask("AMP1", -1, 0x255)

cd "/opt/epics/modules/motor/modules/motorAMP/iocs/ampIOC/iocBoot/iocamp"

iocInit

Starting iocInit

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

## EPICS R7.0.4.1

## Rev. 2022-08-24T16:46-0700

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

2022/10/05 15:08:22.334 asynPortDriver:drvUserCreate: drvInfo=MOTOR_REC_DIRECTION, index=43

2022/10/05 15:08:22.334 AMP1 asynManager::queueLockPort locking port

2022/10/05 15:08:22.334 AMP1 asynManager::queueLockPort created queueLockPortPvt=0x557b8bae8ab0

2022/10/05 15:08:22.334 AMP1 asynManager::queueLockPort created queueLockPortPvt=0x557b8bae8ab0, event=0x557b8bae8ad0, mutex=0x557b8bae8b80

2022/10/05 15:08:22.334 AMP1 asynManager::queueLockPort taking mutex 0x557b8bae8b80

2022/10/05 15:08:22.334 AMP1 asynManager::queueLockPort queueing request

2022/10/05 15:08:22.334 AMP1 addr 0 queueRequest priority 0 not lockHolder

2022/10/05 15:08:22.334 AMP1 schedule queueRequest timeout in 2.000000 seconds

2022/10/05 15:08:22.334 AMP1 0 autoConnect

2022/10/05 15:08:22.334 asynPortDriver:connect:, pasynUser=0x557b8bad90e8

2022/10/05 15:08:22.334 asynManager::portThread port=AMP1 callback

2022/10/05 15:08:22.334 AMP1 asynManager::queueLockPortCallback signaling begin event

2022/10/05 15:08:22.334 AMP1 asynManager::queueLockPortCallback waiting for mutex from queueUnlockPort

2022/10/05 15:08:22.334 AMP1 asynManager::queueLockPort waiting for event

2022/10/05 15:08:22.334 AMP1 asynManager::queueLockPort got event from callback

2022/10/05 15:08:22.335 asynPortDriver:getIntegerParam: port=AMP1 error getting parameter 43 MOTOR_REC_DIRECTION, in list 0, value undefined

2022/10/05 15:08:22.335 AMP1 queueUnlockPort

2022/10/05 15:08:22.335 AMP1 asynManager::queueUnlockPort waiting for event

2022/10/05 15:08:22.335 AMP1 queueUnlockPort unlock mutex 0x557b8bae8b80 complete.

2022/10/05 15:08:22.335 asynPortDriver:drvUserCreate: drvInfo=MOTOR_MOVE_REL, index=0

2022/10/05 15:08:22.335 asynPortDriver:drvUserCreate: drvInfo=MOTOR_MOVE_ABS, index=1

2022/10/05 15:08:22.335 asynPortDriver:drvUserCreate: drvInfo=MOTOR_MOVE_VEL, index=2

2022/10/05 15:08:22.335 asynPortDriver:drvUserCreate: drvInfo=MOTOR_HOME, index=3

2022/10/05 15:08:22.335 asynPortDriver:drvUserCreate: drvInfo=MOTOR_STOP_AXIS, index=4

2022/10/05 15:08:22.335 asynPortDriver:drvUserCreate: drvInfo=MOTOR_VELOCITY, index=5

2022/10/05 15:08:22.335 asynPortDriver:drvUserCreate: drvInfo=MOTOR_VEL_BASE, index=6

2022/10/05 15:08:22.335 asynPortDriver:drvUserCreate: drvInfo=MOTOR_ACCEL, index=7

2022/10/05 15:08:22.335 asynPortDriver:drvUserCreate: drvInfo=MOTOR_POSITION, index=8

2022/10/05 15:08:22.335 asynPortDriver:drvUserCreate: drvInfo=MOTOR_RESOLUTION, index=12

2022/10/05 15:08:22.335 asynPortDriver:drvUserCreate: drvInfo=MOTOR_ENCODER_RATIO, index=13

2022/10/05 15:08:22.335 asynPortDriver:drvUserCreate: drvInfo=MOTOR_PGAIN, index=14

2022/10/05 15:08:22.335 asynPortDriver:drvUserCreate: drvInfo=MOTOR_IGAIN, index=15

2022/10/05 15:08:22.335 asynPortDriver:drvUserCreate: drvInfo=MOTOR_DGAIN, index=16

2022/10/05 15:08:22.335 asynPortDriver:drvUserCreate: drvInfo=MOTOR_HIGH_LIMIT, index=17

2022/10/05 15:08:22.335 asynPortDriver:drvUserCreate: drvInfo=MOTOR_LOW_LIMIT, index=18

2022/10/05 15:08:22.335 asynPortDriver:drvUserCreate: drvInfo=MOTOR_CLOSED_LOOP, index=19

2022/10/05 15:08:22.335 asynPortDriver:drvUserCreate: drvInfo=MOTOR_STATUS, index=25

2022/10/05 15:08:22.335 asynPortDriver:drvUserCreate: drvInfo=MOTOR_UPDATE_STATUS, index=26

2022/10/05 15:08:22.335 AMP1 0 registerInterruptUser

2022/10/05 15:08:22.335 asynPortDriver:getDoubleParam: port=AMP1 error getting parameter 9 MOTOR_ENCODER_POSITION, in list 0, value undefined

2022/10/05 15:08:22.335 asynPortDriver:getDoubleParam: port=AMP1 error getting parameter 5 MOTOR_VELOCITY, in list 0, value undefined

2022/10/05 15:08:22.335 asynMotorController:readGenericPointer: MotorStatus = status0, position=500.000000, encoder position=0.000000, velocity=0.000000

2022/10/05 15:08:22.335 devMotorAsyn::build_trans: amp:m1 motor_cmnd=9, pact=0, value=1.000000

2022/10/05 15:08:22.335 devAsynMotor::build_trans: calling queueRequest, pmsg=0x557b8bad7b40, sizeof(*pmsg)=24pmsg->command=10, pmsg->interface=1, pmsg->dvalue=inf

2022/10/05 15:08:22.335 AMP1 addr 0 queueRequest priority 0 not lockHolder

2022/10/05 15:08:22.335 asynManager::portThread port=AMP1 callback

2022/10/05 15:08:22.335 devMotorAsyn::asynCallback: amp:m1 pmsg=0x557b8bad7b40, sizeof(*pmsg)=24, pmsg->command=10,pmsg->interface=1, pmsg->ivalue=0, pmsg->dvalue=inf, pasynUser->reason=13

2022/10/05 15:08:22.335 asynMotorController:writeFloat64: Set driver AMP1, axis 0 encoder ratio=inf

2022/10/05 15:08:22.335 devMotorAsyn::init_controller, amp:m1 setting of position not required, position=500.000000, mres=1.000000, dval=0.000000, rdbd=1.0000002022/10/05 15:08:22.335 devMotorAsyn::build_trans: amp:m1 motor_cmnd=19, pact=0, value=10000.000000

2022/10/05 15:08:22.335 devAsynMotor::build_trans: calling queueRequest, pmsg=0x557b8bad7b40, sizeof(*pmsg)=24pmsg->command=14, pmsg->interface=1, pmsg->dvalue=10000.000000

2022/10/05 15:08:22.335 AMP1 addr 0 queueRequest priority 0 not lockHolder

2022/10/05 15:08:22.336 asynManager::portThread port=AMP1 callback

2022/10/05 15:08:22.336 devMotorAsyn::asynCallback: amp:m1 pmsg=0x557b8bad7b40, sizeof(*pmsg)=24, pmsg->command=14,pmsg->interface=1, pmsg->ivalue=0, pmsg->dvalue=10000.000000, pasynUser->reason=17

2022/10/05 15:08:22.336 asynMotorController:writeFloat64: Set driver AMP1, axis 0 high limit=10000.000000

2022/10/05 15:08:22.336 devMotorAsyn::build_trans: amp:m1 motor_cmnd=20, pact=0, value=-10000.000000

2022/10/05 15:08:22.336 devAsynMotor::build_trans: calling queueRequest, pmsg=0x557b8bad7b40, sizeof(*pmsg)=24pmsg->command=15, pmsg->interface=1, pmsg->dvalue=-10000.000000

2022/10/05 15:08:22.336 AMP1 addr 0 queueRequest priority 0 not lockHolder

2022/10/05 15:08:22.336 asynManager::portThread port=AMP1 callback

2022/10/05 15:08:22.336 devMotorAsyn::asynCallback: amp:m1 pmsg=0x557b8bad7b40, sizeof(*pmsg)=24, pmsg->command=15,pmsg->interface=1, pmsg->ivalue=0, pmsg->dvalue=-10000.000000, pasynUser->reason=18

2022/10/05 15:08:22.336 asynMotorController:writeFloat64: Set driver AMP1, axis 0 low limit=-10000.000000

2022/10/05 15:08:22.336 asynPortDriver:drvUserCreate: drvInfo=MOTOR_REC_OFFSET, index=44

2022/10/05 15:08:22.336 AMP1 asynManager::queueLockPort locking port

2022/10/05 15:08:22.336 AMP1 asynManager::queueLockPort taking mutex 0x557b8bae8b80

2022/10/05 15:08:22.336 AMP1 asynManager::queueLockPort queueing request

2022/10/05 15:08:22.336 AMP1 addr 0 queueRequest priority 0 not lockHolder

2022/10/05 15:08:22.336 AMP1 schedule queueRequest timeout in 2.000000 seconds

2022/10/05 15:08:22.336 asynManager::portThread port=AMP1 callback

2022/10/05 15:08:22.336 AMP1 asynManager::queueLockPortCallback signaling begin event

2022/10/05 15:08:22.336 AMP1 asynManager::queueLockPortCallback waiting for mutex from queueUnlockPort

2022/10/05 15:08:22.336 AMP1 asynManager::queueLockPort waiting for event

2022/10/05 15:08:22.336 AMP1 asynManager::queueLockPort got event from callback

2022/10/05 15:08:22.336 asynPortDriver:getDoubleParam: port=AMP1 error getting parameter 44 MOTOR_REC_OFFSET, in list 0, value undefined

2022/10/05 15:08:22.337 AMP1 queueUnlockPort

2022/10/05 15:08:22.337 AMP1 asynManager::queueUnlockPort waiting for event

2022/10/05 15:08:22.337 AMP1 queueUnlockPort unlock mutex 0x557b8bae8b80 complete.

2022/10/05 15:08:22.337 asynPortDriver:drvUserDestroy: this=0x557b8bad6c80, pasynUser=0x557b8baea328

2022/10/05 15:08:22.337 asynPortDriver:drvUserCreate: drvInfo=MOTOR_REC_RESOLUTION, index=42

2022/10/05 15:08:22.337 AMP1 asynManager::queueLockPort locking port

2022/10/05 15:08:22.337 AMP1 asynManager::queueLockPort taking mutex 0x557b8bae8b80

2022/10/05 15:08:22.337 AMP1 asynManager::queueLockPort queueing request

2022/10/05 15:08:22.337 AMP1 addr 0 queueRequest priority 0 not lockHolder

2022/10/05 15:08:22.337 AMP1 schedule queueRequest timeout in 2.000000 seconds

2022/10/05 15:08:22.337 asynManager::portThread port=AMP1 callback

2022/10/05 15:08:22.337 AMP1 asynManager::queueLockPortCallback signaling begin event

2022/10/05 15:08:22.337 AMP1 asynManager::queueLockPortCallback waiting for mutex from queueUnlockPort

2022/10/05 15:08:22.337 AMP1 asynManager::queueLockPort waiting for event

2022/10/05 15:08:22.337 AMP1 asynManager::queueLockPort got event from callback

2022/10/05 15:08:22.337 asynPortDriver:getDoubleParam: port=AMP1 error getting parameter 42 MOTOR_REC_RESOLUTION, in list 0, value undefined

2022/10/05 15:08:22.337 AMP1 queueUnlockPort

2022/10/05 15:08:22.337 AMP1 asynManager::queueUnlockPort waiting for event

2022/10/05 15:08:22.337 AMP1 queueUnlockPort unlock mutex 0x557b8bae8b80 complete.

2022/10/05 15:08:22.337 asynPortDriver:drvUserDestroy: this=0x557b8bad6c80, pasynUser=0x557b8bae9408

cas warning: Configured TCP port was unavailable.

cas warning: Using dynamically assigned TCP port 37045,

cas warning: but now two or more servers share the same UDP port.

cas warning: Depending on your IP kernel this server may not be

cas warning: reachable with UDP unicast (a host's IP in EPICS_CA_ADDR_LIST)

iocRun: All initialization complete

2022/10/05 15:08:22.851 AMP1 addr 0 queueRequest priority 0 not lockHolder

2022/10/05 15:08:22.852 AMP1 addr 0 queueRequest priority 0 not lockHolder

2022/10/05 15:08:22.852 asynManager::portThread port=AMP1 callback

2022/10/05 15:08:22.854 asynManager::portThread port=AMP1 callback

epics> 2022/10/05 15:08:42.919 devMotorAsyn::build_trans: amp:m1 motor_cmnd=6, pact=1, value=100.000000

2022/10/05 15:08:42.919 devAsynMotor::build_trans: calling queueRequest, pmsg=0x557b8bad7b40, sizeof(*pmsg)=24pmsg->command=5, pmsg->interface=1, pmsg->dvalue=100.000000

2022/10/05 15:08:42.919 AMP1 addr 0 queueRequest priority 0 not lockHolder

2022/10/05 15:08:42.919 devMotorAsyn::build_trans: amp:m1 motor_cmnd=5, pact=1, value=100.000000

2022/10/05 15:08:42.919 devAsynMotor::build_trans: calling queueRequest, pmsg=0x7feb08017c90, sizeof(*pmsg)=24pmsg->command=6, pmsg->interface=1, pmsg->dvalue=100.000000

2022/10/05 15:08:42.919 AMP1 addr 0 queueRequest priority 0 not lockHolder

2022/10/05 15:08:42.919 devMotorAsyn::build_trans: amp:m1 motor_cmnd=7, pact=1, value=1.000000

2022/10/05 15:08:42.919 devAsynMotor::build_trans: calling queueRequest, pmsg=0x7feb08017ce0, sizeof(*pmsg)=24pmsg->command=7, pmsg->interface=1, pmsg->dvalue=1.000000

2022/10/05 15:08:42.919 AMP1 addr 0 queueRequest priority 0 not lockHolder

2022/10/05 15:08:42.919 devMotorAsyn::build_trans: amp:m1 motor_cmnd=0, pact=1, value=550.000000

2022/10/05 15:08:42.919 devMotorAsyn::build_trans: amp:m1 motor_cmnd=8, pact=1, value=0.000000

2022/10/05 15:08:42.919 devAsynMotor::build_trans: calling queueRequest, pmsg=0x7feb08017f00, sizeof(*pmsg)=24pmsg->command=0, pmsg->interface=1, pmsg->dvalue=550.000000

2022/10/05 15:08:42.919 AMP1 addr 0 queueRequest priority 0 not lockHolder

2022/10/05 15:08:42.921 asynManager::portThread port=AMP1 callback

2022/10/05 15:08:42.921 devMotorAsyn::asynCallback: amp:m1 pmsg=0x557b8bad7b40, sizeof(*pmsg)=24, pmsg->command=5,pmsg->interface=1, pmsg->ivalue=0, pmsg->dvalue=100.000000, pasynUser->reason=5

2022/10/05 15:08:42.921 asynManager::portThread port=AMP1 callback

2022/10/05 15:08:42.921 devMotorAsyn::asynCallback: amp:m1 pmsg=0x7feb08017c90, sizeof(*pmsg)=24, pmsg->command=6,pmsg->interface=1, pmsg->ivalue=0, pmsg->dvalue=100.000000, pasynUser->reason=6

2022/10/05 15:08:42.921 asynManager::portThread port=AMP1 callback

2022/10/05 15:08:42.921 devMotorAsyn::asynCallback: amp:m1 pmsg=0x7feb08017ce0, sizeof(*pmsg)=24, pmsg->command=7,pmsg->interface=1, pmsg->ivalue=0, pmsg->dvalue=1.000000, pasynUser->reason=7

2022/10/05 15:08:42.921 asynManager::portThread port=AMP1 callback

2022/10/05 15:08:42.921 devMotorAsyn::asynCallback: amp:m1 pmsg=0x7feb08017f00, sizeof(*pmsg)=24, pmsg->command=0,pmsg->interface=1, pmsg->ivalue=0, pmsg->dvalue=550.000000, pasynUser->reason=1

2022/10/05 15:08:42.927 asynMotorController:writeFloat64: Set driver AMP1, axis 0 move absolute to 550.000000, base velocity=100.000000, velocity=100.000000, acceleration=1.000000

2022/10/05 15:11:35.157 devMotorAsyn::build_trans: amp:m1 motor_cmnd=6, pact=1, value=100.000000

2022/10/05 15:11:35.157 devAsynMotor::build_trans: calling queueRequest, pmsg=0x557b8bad7b40, sizeof(*pmsg)=24pmsg->command=5, pmsg->interface=1, pmsg->dvalue=100.000000