Beckhoff: correctly work out if axis is moving

rerpha commented 2 years ago

As a scientist/developer I would like to be correctly told if a motor is moving. Currently there is a delay between the motor position readback changing and the BMOVING flag.

Acceptance Criteria

[x] delay is fixed
[x] DMOV works as expected

Extra Information

MOVN may still flip-flop between 1 and 0 even with a fix applied, if so this can either be done as a separate ticket or as part of #6839

DominicOram commented 2 years ago

Additionally we found that with a simulated PLC on move start the BMOVING takes a while to update, this causes MOVN to flip flop between 0 and 1 for a while.

DominicOram commented 2 years ago

@rerpha and I looked into this a little bit and found that after starting a move the bMoving flag appears to go high in the PLC very quickly (as seen through the XAE) but takes some time (up to a few seconds) to get picked up by the IOC. This time lag didn't seem to be affected much by how many PVs we were reading through tcIOC or whether we had the motor record layer running or not. Next steps are:

Get a scope with accurate time of when the value changes in the PLC (and if it stays high) @Simon-Cooper can help with this
Reduce it down to one axis, maybe even one PV and see if the problem still occurs
Put some print statements in the IOC to see when it's picking up that the flag has changed
From there see if we can find where the slowness is happening
Talk to LIGO and see if they have an idea of why it's slow?

Simon-Cooper commented 2 years ago

For reference, my understanding from discussion with Beckhoff is that the bMoving signal is only ON when the setpoint position of the NC axis is changing (nothing to do with the actual motor position). I guess it's assumed that your actual position will match the setpoint trajectory well enough that this isn't a problem but that might not be the case for us.

rerpha commented 2 years ago

I have successfully managed to set up a scope and i can see that while the fActPosition is changing(or i guess the setpoint) bMoving is set to 1 and never oscillates so I think the problem is definitely something in tcioc. I am going to try with a single axis and see if it consistently takes a few seconds to set the moving flag

for a move which has 100 velocity set to go from 100 -> 600 (5 seconds) the bmoving flag gets set immediately and as you can see stays at 1 for ~5 seconds.

bmoving

rerpha commented 2 years ago

    // Check if it's time to do an EPICS read for the slow (read only) records
    bool readAll = false;
    if (cyclesLeft <= 0) readAll = true;
    // Reset countdown until EPICS read
    if (readAll) cyclesLeft = scanRateMultiple;

JUst spotted this in the code - bmoving would be read only i guess.. cyclesLeft is configurable but defaults to 10

rerpha commented 2 years ago

ok, the above never actually gets called, for whatever reason it thinks that the tc:// calls are read + write only. I guess that's fine and probably one less thing to go wrong as they'll all be called at the faster rate

rerpha commented 2 years ago

Next I am going to have a play with https://github.com/stlehmann/pyads and monitor the bmoving flag when a setpoint is set through EPICS to rule out that it's 100% not an ADS issue and rather a tcioc internal one.

Edit: polling with this script gives a 1/True for bmoving from the start-stop so ADS is 100% not the issue:

import pyads
import time
from datetime import datetime

# connect to plc and open connection
plc = pyads.Connection('192.168.0.25.1.1', 852)
with plc:
    while True:
        # read int value by name
        i = plc.read_by_name("MAIN.afbAxes[1].stAxisStruct.stStatus.bMoving")
        print(f"from PLC, moving is: {i} at {datetime.now()}")
        time.sleep(0.01)

The motor record seems to set MOVN to 1 before BMOVING actually starts which makes me think it's looking at the setpoint vs rbv and determining its moving which is in conflict with bmoving. bmoving PV still seems to lag behind even with no motor record and controlling via ADS - going to delve further into tcioc and then try and figure out why MOVN is being stupid

rerpha commented 2 years ago

From what i've noticed it takes pretty much dead on 5.5 seconds for the moving flag to update...

Another thing to note is that when you send a move the FACTPOSITION field updates as soon as the move is sent. BMOVINGFORWARD and BMOVINGBACKWARD seem to lag like how BMOVING do. The only difference between these two PVs is the address, the name and (most importantly) the record type - FACTPOSITION is an ao but BMOVING is bo - wonder if something in tcioc polls them slowly

ok, just tried to set STCONTROL-BENABLE and then monitored STSTATUS-BENABLED as STSTATUS-BENABLED (read only) is a bo record... but it updates immediately after STCONTROL-BENABLE is set. so the record type cant be the issue

rerpha commented 2 years ago

Another update, it's not just the moving flag that is not updated it's ANYTHING that isn't updated with a different value very quickly - FVELOCITY (LREAL type not BOOL) also does not get updated quickly on one set.

So I wrote a test to see if updating it really quickly does actually process the PV update:

import pyads
import time
from datetime import datetime
SLEEP_TIME = 1
# connect to plc and open connection
plc = pyads.Connection('192.168.0.25.1.1', 852)
with plc:
    while True:
        for i in range(1, 10):
            # read int value by name
            plc.write_by_name("MAIN.afbAxes[1].stAxisStruct.stControl.fVelocity", i)
            print(f"Sent {i} velocity to PLC at {datetime.now()}")
            time.sleep(SLEEP_TIME)

this outputs as follows:

Sent 1 velocity to PLC at 2021-11-26 10:18:10.515402
Sent 2 velocity to PLC at 2021-11-26 10:18:11.518399
Sent 3 velocity to PLC at 2021-11-26 10:18:12.521399
Sent 4 velocity to PLC at 2021-11-26 10:18:13.524410
Sent 5 velocity to PLC at 2021-11-26 10:18:14.528439
Sent 6 velocity to PLC at 2021-11-26 10:18:15.532410
Sent 7 velocity to PLC at 2021-11-26 10:18:16.536412
Sent 8 velocity to PLC at 2021-11-26 10:18:17.540411
Sent 9 velocity to PLC at 2021-11-26 10:18:18.543399
Sent 1 velocity to PLC at 2021-11-26 10:18:19.546415
Sent 2 velocity to PLC at 2021-11-26 10:18:20.550396
Sent 3 velocity to PLC at 2021-11-26 10:18:21.554391

which almost matches a camonitor of the FVELOCITY PV;

TE:NDLT1542:ASTAXES_1:STCONTROL-FVELOCITY.RVAL 2021-11-26 10:17:59.946435 4
TE:NDLT1542:ASTAXES_1:STCONTROL-FVELOCITY.RVAL 2021-11-26 10:18:11.579420 1
TE:NDLT1542:ASTAXES_1:STCONTROL-FVELOCITY.RVAL 2021-11-26 10:18:12.588402 2
TE:NDLT1542:ASTAXES_1:STCONTROL-FVELOCITY.RVAL 2021-11-26 10:18:13.546412 3
TE:NDLT1542:ASTAXES_1:STCONTROL-FVELOCITY.RVAL 2021-11-26 10:18:14.555438 4
TE:NDLT1542:ASTAXES_1:STCONTROL-FVELOCITY.RVAL 2021-11-26 10:18:15.565396 5
TE:NDLT1542:ASTAXES_1:STCONTROL-FVELOCITY.RVAL 2021-11-26 10:18:16.576397 6
TE:NDLT1542:ASTAXES_1:STCONTROL-FVELOCITY.RVAL 2021-11-26 10:18:17.588397 7
TE:NDLT1542:ASTAXES_1:STCONTROL-FVELOCITY.RVAL 2021-11-26 10:18:17.790413 8
TE:NDLT1542:ASTAXES_1:STCONTROL-FVELOCITY.RVAL 2021-11-26 10:18:19.611416 9
TE:NDLT1542:ASTAXES_1:STCONTROL-FVELOCITY.RVAL 2021-11-26 10:18:20.573398 1
TE:NDLT1542:ASTAXES_1:STCONTROL-FVELOCITY.RVAL 2021-11-26 10:18:21.585407 2
TE:NDLT1542:ASTAXES_1:STCONTROL-FVELOCITY.RVAL 2021-11-26 10:18:26.738374 3

as you can see they are pretty much updated every second.

now change SLEEP_TIME to 5 (send velocity every 5 seconds) and you get this:

Sent 1 velocity to PLC at 2021-11-26 10:20:14.190385
Sent 2 velocity to PLC at 2021-11-26 10:20:19.194383
Sent 3 velocity to PLC at 2021-11-26 10:20:24.197383
Sent 4 velocity to PLC at 2021-11-26 10:20:29.200384
Sent 5 velocity to PLC at 2021-11-26 10:20:34.204367
Sent 6 velocity to PLC at 2021-11-26 10:20:39.207366

and then inconsistent PV updates:

TE:NDLT1542:ASTAXES_1:STCONTROL-FVELOCITY.RVAL 2021-11-26 10:19:55.940227 3
TE:NDLT1542:ASTAXES_1:STCONTROL-FVELOCITY.RVAL 2021-11-26 10:20:19.250384 1
TE:NDLT1542:ASTAXES_1:STCONTROL-FVELOCITY.RVAL 2021-11-26 10:20:22.684370 2
TE:NDLT1542:ASTAXES_1:STCONTROL-FVELOCITY.RVAL 2021-11-26 10:20:29.258369 3
TE:NDLT1542:ASTAXES_1:STCONTROL-FVELOCITY.RVAL 2021-11-26 10:20:31.586381 4
TE:NDLT1542:ASTAXES_1:STCONTROL-FVELOCITY.RVAL 2021-11-26 10:20:39.273381 5
TE:NDLT1542:ASTAXES_1:STCONTROL-FVELOCITY.RVAL 2021-11-26 10:20:40.535381 6

rerpha commented 2 years ago

setting the dirty flag on all PLC records in tcComms.cpp rather than a small subset of them like this:

    for (int i = 0; i < records.size(); ++i) {

rather than

    for (int i = 0; i < update_workload; ++i) {

fixes the delay from ADS, which I think means we could just modify that or add a flag to make it configurable - however the motor record still tends to do something weird when receiving setpoints so i'm going to look into that next. I think this is because when it receives a setpoint it sets MOVN to 1 then bmoving hasn't updated yet which forces it back to 0, then 1 again. This only happens sometimes, as it's a bit of a race condition between tcioc and the motor record. We could either: A) live with this, which means that waitfor_move etc won't work reliably B) change the implementation of the motor record to look at bmoving entirely if possible for deciding when to set MOVN.

I think the latter is the better approach so i'm going to see if that's possible.

rerpha commented 2 years ago

message to myself - this is the fix/workaround for the delay: https://github.com/ISISComputingGroup/EPICS-tcIoc/pull/12

to do: sort out the weird flip flopping now for DMOV and MOVN - there is now no (or a very short) delay for moving, just need to work out how to remedy the flip flopping between 0-1-0-1 on initial move.

rerpha commented 2 years ago

repointing to 8 for next sprint, think it'll take a couple of days to sort out the MOVN flipflopping as there's something weird going on with timestamping. probably another day for review

FreddieAkeroyd commented 2 years ago

The above mentions both MOVN and DMOV. Can you confirm that MOVN is a nicety and not a problem, and it is just DMOV that needs to be fixed? I believe waitfor_move etc just use DMOV

rerpha commented 2 years ago

The above mentions both MOVN and DMOV. Can you confirm that MOVN is a nicety and not a problem, and it is just DMOV that needs to be fixed? I believe waitfor_move etc just use DMOV

fairly sure DMOV was affected but will have to double check, will get it set up now

FreddieAkeroyd commented 2 years ago

I think it is up to the motor driver, some may write the same value to both DMOV and MOVN, but we shouldn't be relying on MOVN anywhere.

rerpha commented 2 years ago

Have just tried it, there is a slight ordering issue (DMOV updating before BMOVING, but only ~60ms), but dmov seems to not be affected. weird, thought it was, but maybe I was looking at MOVN mistakenly. In which case I think this ticket may be done..

I will continue debugging for a bit with the maintainer but for now we at least have a workaround and i'd like to get it in for this release so going to tidy this up and move it into review

camonitor output from a relative move:

TE:NDLT1542:MOT:MTR0101.RBV    2022-01-04 14:02:55.242727 120
TE:NDLT1542:ASTAXES_1:STSTATUS-BMOVING.RVAL 2022-01-04 14:14:20.683162 1
TE:NDLT1542:MOT:MTR0101.RBV    2022-01-04 14:14:20.731152 121.293
TE:NDLT1542:MOT:MTR0101.DMOV   2022-01-04 14:14:20.731152 0
TE:NDLT1542:MOT:MTR0101.RBV    2022-01-04 14:14:20.931412 122.793
TE:NDLT1542:MOT:MTR0101.RBV    2022-01-04 14:14:21.132542 124.293
TE:NDLT1542:MOT:MTR0101.RBV    2022-01-04 14:14:21.332803 127.293
TE:NDLT1542:MOT:MTR0101.RBV    2022-01-04 14:14:21.533004 128.793
TE:NDLT1542:MOT:MTR0101.RBV    2022-01-04 14:14:21.734223 130.293
TE:NDLT1542:MOT:MTR0101.RBV    2022-01-04 14:14:21.935382 133.293
TE:NDLT1542:MOT:MTR0101.RBV    2022-01-04 14:14:22.136537 134.793
TE:NDLT1542:MOT:MTR0101.RBV    2022-01-04 14:14:22.337738 136.293
TE:NDLT1542:MOT:MTR0101.RBV    2022-01-04 14:14:22.538211 139.293
TE:NDLT1542:MOT:MTR0101.RBV    2022-01-04 14:14:22.739445 140.793
TE:NDLT1542:MOT:MTR0101.RBV    2022-01-04 14:14:22.939389 142.393
TE:NDLT1542:MOT:MTR0101.RBV    2022-01-04 14:14:23.139636 145.393
TE:NDLT1542:MOT:MTR0101.RBV    2022-01-04 14:14:23.340727 146.893
TE:NDLT1542:MOT:MTR0101.RBV    2022-01-04 14:14:23.540941 148.393
TE:NDLT1542:MOT:MTR0101.RBV    2022-01-04 14:14:23.741140 150
TE:NDLT1542:MOT:MTR0101        2022-01-04 14:14:23.741140 150
TE:NDLT1542:MOT:MTR0101.DMOV   2022-01-04 14:14:23.741140 1
TE:NDLT1542:ASTAXES_1:STSTATUS-BMOVING.RVAL 2022-01-04 14:14:23.842184 0

rerpha commented 2 years ago

PRs:

tcioc: https://github.com/ISISComputingGroup/EPICS-tcIoc/pull/12 ioc: https://github.com/ISISComputingGroup/EPICS-ioc/pull/663 release notes: https://github.com/ISISComputingGroup/IBEX/pull/6952/files

To test:

set up a simulated Beckhoff PLC using everything on master, start TWINCAT IOC and monitor these PVs:

camonitor %MYPVPREFIX%MOT:MTR0101.DMOV %MYPVPREFIX%MOT:MTR0101 %MYPVPREFIX%ASTAXES_1:STSTATUS-BMOVING.RVAL %MYPVPREFIX%MOT:MTR0101.RBV

perform a move either through the table of motors or through the Beckhoff main VISU in visual studio ( PLC -> tc_project_app -> tc_project_app Project -> tc_mca_std_lib -> VISUs -> MainVisu )

you should see that there is a huge delay on the BMOVING flag compared to an actual move

now check out tcioc branch and make from the top level

do the same again and you should see the moving updates almost immediately. DMOV should also flip to 0 when moving then 1 when done.

FreddieAkeroyd commented 2 years ago

Does the motor record poll loop use the same axis status read as the twincat update of the BMOVING PV? If so, it may be just the motor record poll that updates DMOV is running more often.

rerpha commented 2 years ago

yes, I think so, its done in pollAll could also be to do with hardware timestamps vs epics motor record timestamps? either way im not sure its that important

FreddieAkeroyd commented 2 years ago

you could run camonitor -t cs PV_OF_INTEREST - this prints the client as well as server side timestamps. It may be both pvs update at the same time, but the BMOVING gets a hardware timestamp and DMOV get the server software timestamp. If you add -cs to camonitor you'll get the local timestamp when the update happened, which might give more of a clue as if the updates get posted at the same time

rerpha commented 2 years ago

here is the output of using -t cs

TE:NDLT1542:MOT:MTR0101.DMOV   2022-01-04 14:42:00.705298(2022-01-04 14:42:00.706364) 0
TE:NDLT1542:ASTAXES_1:STSTATUS-BMOVING.RVAL 2022-01-04 14:42:00.783923(2022-01-04 14:42:00.783106) 1
TE:NDLT1542:MOT:MTR0101.RBV    2022-01-04 14:42:00.905118(2022-01-04 14:42:00.905152) 151.193
TE:NDLT1542:MOT:MTR0101.RBV    2022-01-04 14:42:01.106074(2022-01-04 14:42:01.106166) 154.293
TE:NDLT1542:MOT:MTR0101.RBV    2022-01-04 14:42:01.306290(2022-01-04 14:42:01.306115) 155.793
TE:NDLT1542:MOT:MTR0101.RBV    2022-01-04 14:42:01.507423(2022-01-04 14:42:01.507111) 157.293
TE:NDLT1542:MOT:MTR0101.RBV    2022-01-04 14:42:01.707637(2022-01-04 14:42:01.707088) 160.293
TE:NDLT1542:MOT:MTR0101.RBV    2022-01-04 14:42:01.907912(2022-01-04 14:42:01.907148) 161.793
TE:NDLT1542:MOT:MTR0101.RBV    2022-01-04 14:42:02.108106(2022-01-04 14:42:02.107281) 163.293
TE:NDLT1542:MOT:MTR0101.RBV    2022-01-04 14:42:02.309237(2022-01-04 14:42:02.308426) 166.293
TE:NDLT1542:MOT:MTR0101.RBV    2022-01-04 14:42:02.509420(2022-01-04 14:42:02.508543) 167.793
TE:NDLT1542:MOT:MTR0101.RBV    2022-01-04 14:42:02.710678(2022-01-04 14:42:02.709826) 169.293
TE:NDLT1542:MOT:MTR0101.RBV    2022-01-04 14:42:02.910838(2022-01-04 14:42:02.909959) 172.293
TE:NDLT1542:MOT:MTR0101.RBV    2022-01-04 14:42:03.111087(2022-01-04 14:42:03.110234) 173.793
TE:NDLT1542:MOT:MTR0101.RBV    2022-01-04 14:42:03.311272(2022-01-04 14:42:03.310334) 175.293
TE:NDLT1542:MOT:MTR0101.RBV    2022-01-04 14:42:03.512417(2022-01-04 14:42:03.511484) 178.293
TE:NDLT1542:MOT:MTR0101.RBV    2022-01-04 14:42:03.713621(2022-01-04 14:42:03.712676) 179.757
TE:NDLT1542:MOT:MTR0101.RBV    2022-01-04 14:42:03.913854(2022-01-04 14:42:03.912849) 180
TE:NDLT1542:MOT:MTR0101        2022-01-04 14:42:03.913854(2022-01-04 14:42:03.913919) 180
TE:NDLT1542:MOT:MTR0101.DMOV   2022-01-04 14:42:03.913854(2022-01-04 14:42:03.914872) 1
TE:NDLT1542:ASTAXES_1:STSTATUS-BMOVING.RVAL 2022-01-04 14:42:03.944912(2022-01-04 14:42:03.945870) 0

looks like the DMOV is more closely related to MTR0101 value change, which looks like it only gets updated when the SP is reached, so could be the difference between that and bmoving changing + updating from the PLC. I think there's a minor difference in the poll rates of tcioc and the motor record scan loop (300ms and 200ms respectively) so that could be it. I can try with a faster tcioc rate like 150ms to see if that solves it. EDIT: it does solve it, setting to 10ms scan for ADS and 50ms for epics does this:

TE:NDLT1542:MOT:MTR0101.RBV    2022-01-04 14:49:30.022670(2022-01-04 14:49:33.063392) 240
TE:NDLT1542:ASTAXES_1:STSTATUS-BMOVING.RVAL 2022-01-04 14:49:41.583423(2022-01-04 14:49:41.585022) 1
TE:NDLT1542:MOT:MTR0101.RBV    2022-01-04 14:49:41.655212(2022-01-04 14:49:41.657006) 240.233
TE:NDLT1542:MOT:MTR0101.DMOV   2022-01-04 14:49:41.655212(2022-01-04 14:49:41.658455) 0
TE:NDLT1542:MOT:MTR0101.RBV    2022-01-04 14:49:41.855939(2022-01-04 14:49:41.858044) 242.193
TE:NDLT1542:MOT:MTR0101.RBV    2022-01-04 14:49:42.055775(2022-01-04 14:49:42.058129) 244.193
TE:NDLT1542:MOT:MTR0101.RBV    2022-01-04 14:49:42.256553(2022-01-04 14:49:42.259166) 246.193
TE:NDLT1542:MOT:MTR0101.RBV    2022-01-04 14:49:42.456311(2022-01-04 14:49:42.459250) 248.193
TE:NDLT1542:MOT:MTR0101.RBV    2022-01-04 14:49:42.656195(2022-01-04 14:49:42.659469) 250.193
TE:NDLT1542:MOT:MTR0101.RBV    2022-01-04 14:49:42.856993(2022-01-04 14:49:42.860556) 252.393
TE:NDLT1542:MOT:MTR0101.RBV    2022-01-04 14:49:43.057822(2022-01-04 14:49:43.061656) 254.193
TE:NDLT1542:MOT:MTR0101.RBV    2022-01-04 14:49:43.257917(2022-01-04 14:49:43.261331) 256.193
TE:NDLT1542:MOT:MTR0101.RBV    2022-01-04 14:49:43.459095(2022-01-04 14:49:43.462236) 258.393
TE:NDLT1542:MOT:MTR0101.RBV    2022-01-04 14:49:43.660350(2022-01-04 14:49:43.662996) 260.393
TE:NDLT1542:MOT:MTR0101.RBV    2022-01-04 14:49:43.861522(2022-01-04 14:49:43.863779) 262.393
TE:NDLT1542:MOT:MTR0101.RBV    2022-01-04 14:49:44.061683(2022-01-04 14:49:44.063549) 264.293
TE:NDLT1542:MOT:MTR0101.RBV    2022-01-04 14:49:44.262926(2022-01-04 14:49:44.264412) 266.393
TE:NDLT1542:MOT:MTR0101.RBV    2022-01-04 14:49:44.464049(2022-01-04 14:49:44.465116) 268.393
TE:NDLT1542:MOT:MTR0101.RBV    2022-01-04 14:49:44.664257(2022-01-04 14:49:44.664923) 269.992
TE:NDLT1542:ASTAXES_1:STSTATUS-BMOVING.RVAL 2022-01-04 14:49:44.713446(2022-01-04 14:49:44.713995) 0
TE:NDLT1542:MOT:MTR0101.RBV    2022-01-04 14:49:44.864483(2022-01-04 14:49:44.864773) 270
TE:NDLT1542:MOT:MTR0101        2022-01-04 14:49:44.864483(2022-01-04 14:49:44.865831) 270
TE:NDLT1542:MOT:MTR0101.DMOV   2022-01-04 14:49:44.864483(2022-01-04 14:49:44.866806) 1

will push that change too.

FreddieAkeroyd commented 2 years ago

BTW the TE:NDLT1542:ASTAXES_1:STSTATUS-BMOVING.RVAL name doesn't look correctly prefixed, you would get a clash if you ran more than one IOC. Should it have a TWINCAT_01 added?

rerpha commented 2 years ago

yes it should, https://github.com/ISISComputingGroup/IBEX/issues/4669 is to sort that out for now not much of a problem as nowhere is using two of them, but will quickly become an issue if they do.

rerpha commented 2 years ago

Upping the scan rate for tcioc seems to have inadvertently fixed the MOVN problem as well, weird. Think that means #6839 may work once this is in?

FreddieAkeroyd commented 2 years ago

We should look to do #4669 ASAP as otherwise we'll get incorrect names in blocks and other places that we'll need to sort out later

rerpha commented 2 years ago

definitely. I am a bit stuck for ideas for it besides modding tcioc to shorten the names and just use the last part of the pv after the hyphen, like BENABLE, BENABLED etc.

FreddieAkeroyd commented 2 years ago

I guess we couldn't ask for shorter names in the axis structure :-D Will add some ideas to #4669

JackEAllen commented 2 years ago

EPICS-tcIoc, ioc, and release notes have been merged in resolving the issue of delay from ADS and DMOV updating before BMOVING

ISISComputingGroup / IBEX

Beckhoff: correctly work out if axis is moving #6874

Acceptance Criteria

Extra Information