Re: Exploring EPICS performance/processing limits

["Marco A. Barra Montevechi Filho via Tech-talk" <tech-talk at aps.anl.gov>]

Hi, Mark! As always, thanks for the help.

Where i before only had drvAsynIPPortConfigure("IPPORT1", "127.0.0.1:60000", 0, 0, 0), now i have:

drvAsynIPPortConfigure("IPPORT1", "127.0.0.1:60000", 0, 0, 0)

asynSetTraceIOMask("IPPORT1", 0, ESCAPE)

asynSetTraceMask("IPPORT1", 0, ERROR|DRIVER)

and running the script again with the monitors both via camonitor and via tcpflow generate the following results:

FOR 5 SECONDS OF DELAY:

TCPFLOW RESULTS:

127.000.000.001.55866-127.000.000.001.60000: {"id":"1", "method":"HS_ImgChipNumberID_Command", "params": [["1", "0"]], "jsonrpc": "2.0"}

127.000.000.001.55866-127.000.000.001.60000: {"id":"1", "method":"HS_ImgChipNumberID_Command", "params": [["0"]], "jsonrpc": "2.0"}

127.000.000.001.55866-127.000.000.001.60000: {"id":"1", "method":"HS_ImgChipNumberID_Command", "params": [["1", "1"]], "jsonrpc": "2.0"}

127.000.000.001.55866-127.000.000.001.60000: {"id":"1", "method":"HS_ImgChipNumberID_Command", "params": [["0"]], "jsonrpc": "2.0"}

127.000.000.001.55866-127.000.000.001.60000: {"id":"1", "method":"HS_ImgChipNumberID_Command", "params": [["1", "2"]], "jsonrpc": "2.0"}

127.000.000.001.55866-127.000.000.001.60000: {"id":"1", "method":"HS_ImgChipNumberID_Command", "params": [["0"]], "jsonrpc": "2.0"}

127.000.000.001.55866-127.000.000.001.60000: {"id":"1", "method":"HS_ImgChipNumberID_Command", "params": [["1", "3"]], "jsonrpc": "2.0"}

127.000.000.001.55866-127.000.000.001.60000: {"id":"1", "method":"HS_ImgChipNumberID_Command", "params": [["0"]], "jsonrpc": "2.0"}

CAMONITOR:

camonitor MOBICDTE:Backend:ImgChipNumberID

MOBICDTE:Backend:ImgChipNumberID <undefined> 0 UDF INVALID

CA.Client.Exception...............................................

    Warning: "Identical process variable names on multiple servers"

    Context: "Channel: "MOBICDTE:Backend:ImgChipNumberID", Connecting to: 192.168.55.1:5064, Ignored: s-mgn-mob01-l.abtlus.org.br:5064"

    Source File: ../cac.cpp line 1320

    Current Time: Thu Oct 06 2022 15:36:31.762020681

..................................................................

MOBICDTE:Backend:ImgChipNumberID 2022-10-06 15:36:55.282127 0 READ INVALID

MOBICDTE:Backend:ImgChipNumberID 2022-10-06 15:37:00.287686 1 READ INVALID

MOBICDTE:Backend:ImgChipNumberID 2022-10-06 15:37:05.291961 2 READ INVALID

MOBICDTE:Backend:ImgChipNumberID 2022-10-06 15:37:10.296531 3 READ INVALID

IN THE IOC SHELL:

2022/10/06 15:36:55.180 127.0.0.1:60000 write 92

{\"id\":\"1\", \"method\":\"HS_ImgChipNumberID_Command\", \"params\": [[\"1\", \"0\"]], \"jsonr

2022/10/06 15:36:55.182 127.0.0.1:60000 read 57

{\"id\":\"1\", \"result\":\"Selected sensor 0\", \"jsonrpc\":\"2.0\"}

2022/10/06 15:36:55.283 127.0.0.1:60000 write 87

{\"id\":\"1\", \"method\":\"HS_ImgChipNumberID_Command\", \"params\": [[\"0\"]], \"jsonrpc\":

2022/10/06 15:36:55.284 127.0.0.1:60000 read 41

{\"id\":\"1\", \"result\":\"0\", \"jsonrpc\":\"2.0\"}

2022/10/06 15:37:00.185 127.0.0.1:60000 write 92

{\"id\":\"1\", \"method\":\"HS_ImgChipNumberID_Command\", \"params\": [[\"1\", \"1\"]], \"jsonr

2022/10/06 15:37:00.187 127.0.0.1:60000 read 57

{\"id\":\"1\", \"result\":\"Selected sensor 1\", \"jsonrpc\":\"2.0\"}

2022/10/06 15:37:00.289 127.0.0.1:60000 write 87

{\"id\":\"1\", \"method\":\"HS_ImgChipNumberID_Command\", \"params\": [[\"0\"]], \"jsonrpc\":

2022/10/06 15:37:00.289 127.0.0.1:60000 read 41

{\"id\":\"1\", \"result\":\"1\", \"jsonrpc\":\"2.0\"}

2022/10/06 15:37:05.190 127.0.0.1:60000 write 92

{\"id\":\"1\", \"method\":\"HS_ImgChipNumberID_Command\", \"params\": [[\"1\", \"2\"]], \"jsonr

2022/10/06 15:37:05.191 127.0.0.1:60000 read 57

{\"id\":\"1\", \"result\":\"Selected sensor 2\", \"jsonrpc\":\"2.0\"}

2022/10/06 15:37:05.293 127.0.0.1:60000 write 87

{\"id\":\"1\", \"method\":\"HS_ImgChipNumberID_Command\", \"params\": [[\"0\"]], \"jsonrpc\":

2022/10/06 15:37:05.294 127.0.0.1:60000 read 41

{\"id\":\"1\", \"result\":\"2\", \"jsonrpc\":\"2.0\"}

2022/10/06 15:37:10.194 127.0.0.1:60000 write 92

{\"id\":\"1\", \"method\":\"HS_ImgChipNumberID_Command\", \"params\": [[\"1\", \"3\"]], \"jsonr

2022/10/06 15:37:10.196 127.0.0.1:60000 read 57

{\"id\":\"1\", \"result\":\"Selected sensor 3\", \"jsonrpc\":\"2.0\"}

2022/10/06 15:37:10.298 127.0.0.1:60000 write 87

{\"id\":\"1\", \"method\":\"HS_ImgChipNumberID_Command\", \"params\": [[\"0\"]], \"jsonrpc\":

2022/10/06 15:37:10.298 127.0.0.1:60000 read 41

{\"id\":\"1\", \"result\":\"3\", \"jsonrpc\":\"2.0\"}

WITH 0.1 SECOND OF DELAY:

TCPFLOW:

127.000.000.001.55866-127.000.000.001.60000: {"id":"1", "method":"HS_ImgChipNumberID_Command", "params": [["1", "0"]], "jsonrpc": "2.0"}

127.000.000.001.55866-127.000.000.001.60000: {"id":"1", "method":"HS_ImgChipNumberID_Command", "params": [["0"]], "jsonrpc": "2.0"}

127.000.000.001.55866-127.000.000.001.60000: {"id":"1", "method":"HS_ImgChipNumberID_Command", "params": [["1", "1"]], "jsonrpc": "2.0"}

127.000.000.001.55866-127.000.000.001.60000: {"id":"1", "method":"HS_ImgChipNumberID_Command", "params": [["0"]], "jsonrpc": "2.0"}

127.000.000.001.55866-127.000.000.001.60000: {"id":"1", "method":"HS_ImgChipNumberID_Command", "params": [["1", "3"]], "jsonrpc": "2.0"}

127.000.000.001.55866-127.000.000.001.60000: {"id":"1", "method":"HS_ImgChipNumberID_Command", "params": [["0"]], "jsonrpc": "2.0"}

CAMONITOR:

MOBICDTE:Backend:ImgChipNumberID 2022-10-06 15:40:05.170536 1 READ INVALID
MOBICDTE:Backend:ImgChipNumberID 2022-10-06 15:40:05.376049 3 READ INVALID

IOCSHELL:

{\"id\":\"1\", \"method\":\"HS_ImgChipNumberID_Command\", \"params\": [[\"1\", \"0\"]], \"jsonr

2022/10/06 15:40:05.070 127.0.0.1:60000 read 57

{\"id\":\"1\", \"result\":\"Selected sensor 0\", \"jsonrpc\":\"2.0\"}

2022/10/06 15:40:05.172 127.0.0.1:60000 write 87

{\"id\":\"1\", \"method\":\"HS_ImgChipNumberID_Command\", \"params\": [[\"0\"]], \"jsonrpc\":

2022/10/06 15:40:05.172 127.0.0.1:60000 read 41

{\"id\":\"1\", \"result\":\"0\", \"jsonrpc\":\"2.0\"}

2022/10/06 15:40:05.274 127.0.0.1:60000 write 92

{\"id\":\"1\", \"method\":\"HS_ImgChipNumberID_Command\", \"params\": [[\"1\", \"1\"]], \"jsonr

2022/10/06 15:40:05.275 127.0.0.1:60000 read 57

{\"id\":\"1\", \"result\":\"Selected sensor 1\", \"jsonrpc\":\"2.0\"}

2022/10/06 15:40:05.377 127.0.0.1:60000 write 87

{\"id\":\"1\", \"method\":\"HS_ImgChipNumberID_Command\", \"params\": [[\"0\"]], \"jsonrpc\":

2022/10/06 15:40:05.378 127.0.0.1:60000 read 41

{\"id\":\"1\", \"result\":\"1\", \"jsonrpc\":\"2.0\"}

2022/10/06 15:40:05.480 127.0.0.1:60000 write 92

{\"id\":\"1\", \"method\":\"HS_ImgChipNumberID_Command\", \"params\": [[\"1\", \"3\"]], \"jsonr

2022/10/06 15:40:05.481 127.0.0.1:60000 read 57

{\"id\":\"1\", \"result\":\"Selected sensor 3\", \"jsonrpc\":\"2.0\"}

2022/10/06 15:40:05.583 127.0.0.1:60000 write 87

{\"id\":\"1\", \"method\":\"HS_ImgChipNumberID_Command\", \"params\": [[\"0\"]], \"jsonrpc\":

2022/10/06 15:40:05.583 127.0.0.1:60000 read 41

{\"id\":\"1\", \"result\":\"3\", \"jsonrpc\":\"2.0\"}

So i think the IOC is actually having trouble with sending the commands? This is bizarre to me, i have used streamdevice before with higher speeds and never have any trouble of this kind at all.

---

From: Mark Rivers <rivers at cars.uchicago.edu>
Sent: 06 October 2022 11:16
To: Hu, Yong <yhu at bnl.gov>; Marco A. Barra Montevechi Filho <marco.filho at lnls.br>
Cc: tech-talk at aps.anl.gov <tech-talk at aps.anl.gov>
Subject: RE: Exploring EPICS performance/processing limits

 

Ø  To me, looping with “caput_one_pv_at_a_time” seems inefficient, especially in the Python world where “list” is a daily-usable data structure.

 

That may be true, but it does not really address the issue Marco is reporting, which is unexpectedly poor behavior with single caput operations.

 

Marco, since you are using streamDevice in your IOC and the loopback IP address that means you must have created an drvAsynIPPort port for the communication.  The first line of debugging you should use is to enable asynTraceIODriver on that port.  That will show you exactly what is being sent on the network without needing to run tcpinfo.  In your IOC st.cmd add these lines:

 

asynSetTraceIOMask(portName, 0, ESCAPE)

asynSetTraceMask(portName, 0, ERROR|DRIVER)

 

where portName is the name you gave to the drvAsynIPPort.

 

This will show the communication over that socket.  See if it agrees with what tcpinfo shows.

 

Mark

 

 

 

 

From: Tech-talk <tech-talk-bounces at aps.anl.gov> On Behalf Of Hu, Yong via Tech-talk
Sent: Thursday, October 6, 2022 8:33 AM
To: Marco A. Barra Montevechi Filho <marco.filho at lnls.br>; tech-talk at aps.anl.gov
Subject: Re: Exploring EPICS performance/processing limits

 

Hello Marco,

To me, looping with “caput_one_pv_at_a_time” seems inefficient, especially in the Python world where “list” is a daily-usable data structure.

I have been using another Python-based Channel Access tool named “cothread” where you simply caput a list of pvs associated with a list of values: cothread.catools.caput(pvs, values). In your case, cothread.catools.caput(a_list_of_records, VALUE, repeat_value=True).

I have used “cothread” in one application where I get ~200 BPM waveform data (100K doubles per BPM) in a few seconds by caget(bpm_wavform_pv_list). Basically the processing time is dominated by the limited network bandwidth. “cothread” is very efficient by using cooperative threading.

Take a look at these links:
https://github.com/dls-controls/cothread
https://cothread.readthedocs.io/en/latest/catools.html#cothread.catools.caput

Cheers,
Yong

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>
Date: Wednesday, October 5, 2022 at 7:26 PM
To: tech-talk at aps.anl.gov <tech-talk at aps.anl.gov>
Subject: Exploring EPICS performance/processing limits

Hello all.

I bumped into something that may or may not be caused by EPICS default processing time limits and would like tips on how to explore it, if possible.
I have a set of records that send messages to a loopback ethernet address via a .proto file and stream device.
Lets say RECORD1 sends a string "message1 VAL1", RECORD2 sends "message2 VAL2", etc.

I was monitoring the traffic with ´tcpflow -c -i <my_IP> port <my_PORT> | grep "message"´ and made a python script in the form:

import epics, time
def do_thing(x):

    for record in ["RECORD1", "RECORD2", "RECORD3", "RECORD4"]:

        epics.caput(record, VALUE)

        time.sleep(x)

The messages i got from tcpflow when executing the python script with do_thing(1.5) were nicely formatted:
message1 VALUE
message2 VALUE
message3 VALUE
message4 VALUE

But when i do the same thing with x=0.5, messages 2 and 3 were sometimes missing or sometimes badly formatted. Sometimes i got things like:
message1 VALUE

message2

message3

message4 VALUE

And sometimes like:

message1 VALUE

message4 VALUE

 

Is this a PV processing time issue? Shouldnt the IOC be capable of dealing with time intervals smaller than this? Is there a way i can improve this behaviour without setting sleep times between my caputs?

Thanks in advance,

Marco

 

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.