RE: Exploring EPICS performance/processing limits

[Mark Rivers via Tech-talk <tech-talk at aps.anl.gov>]

Hi Marco,

 

I reproduced the problem and I know why it is happening.

 

This is my database:

 

corvette:CARS/iocBoot/ioc13test>more test_stream.db

record(stringout,"Record1") {

    field(DTYP, "stream")

    field(OUT, "@test_stream.proto writeRead $(PORT) 0 0")

}

record(stringout,"Record2") {

    field(DTYP, "stream")

    field(OUT, "@test_stream.proto writeRead $(PORT) 0 0")

}

record(stringout,"Record3") {

    field(DTYP, "stream")

    field(OUT, "@test_stream.proto writeRead $(PORT) 0 0")

}

record(stringout,"Record4") {

    field(DTYP, "stream")

    field(OUT, "@test_stream.proto writeRead $(PORT) 0 0")

}

 

This is my protocol file:

 

corvette:CARS/iocBoot/ioc13test>more test_stream.proto

writeRead {

   out "%s";

   in "%*s %*d";

}

 

This is my startup script.  I am connecting to port 7 on localhost, which is the Echo Protocol server.  Note that the calls to asynOctetSetOutputEos and asynOctetSetInputEos are commented out.

 

corvette:CARS/iocBoot/ioc13test>more st.cmd.test_stream

< envPaths

# Tell EPICS all about the record types, device-support modules, drivers,

# etc. in this build from CARS

dbLoadDatabase("../../dbd/CARSLinux.dbd")

CARSLinux_registerRecordDeviceDriver(pdbbase)

 

drvAsynIPPortConfigure("loop","localhost:7",0,0,0)

#asynOctetSetOutputEos("loop", 0, "\n")

#asynOctetSetInputEos("loop", 0, "\n")

asynSetTraceIOMask("loop",0,ESCAPE)

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

 

dbLoadRecords("test_stream.db", "PORT=loop")

 

iocInit

 

This is my Python test program.  It is like yours but I can specify a number of loops to repeat.

 

corvette:CARS/iocBoot/ioc13test>more test_stream.py

import epics, time

def test_stream(num_loops=5, sleep_time=0.5):

    for loop in range(num_loops):

        for record in ["Record1", "Record2", "Record3", "Record4"]:

            epics.caput(record, record + ': ' + str(loop))

            time.sleep(sleep_time)

 

If I run the program with num_loops=5 and sleep_time=0.01 I should get 40 asynTrace messages:  5 loops * 4 records * 2 messages (one for write and one for read).  Each message contains the current loop counter and the name of the record.  The loop counter should go from 0 to 4.

 

This is the output when I run the IOC as shown above.  Note that we got all 8 messages with loop counter 0, but only 2 messages with loop counter 1, none with 2, 3 with 3, and 8 with 4.  We are clearly missing many messages.  Note also that the timestamps between the write messages are exactly 0.1 seconds apart, but the sleep time is 0.01 seconds.

 

2022/10/06 18:12:37.511 localhost:7 write 10

Record1: 0

2022/10/06 18:12:37.511 localhost:7 read 10

Record1: 0

2022/10/06 18:12:37.613 localhost:7 write 10

Record2: 0

2022/10/06 18:12:37.613 localhost:7 read 10

Record2: 0

2022/10/06 18:12:37.714 localhost:7 write 10

Record3: 0

2022/10/06 18:12:37.714 localhost:7 read 10

Record3: 0

2022/10/06 18:12:37.816 localhost:7 write 10

Record4: 0

2022/10/06 18:12:37.816 localhost:7 read 10

Record4: 0

2022/10/06 18:12:37.917 localhost:7 write 10

Record1: 1

2022/10/06 18:12:37.917 localhost:7 read 10

Record1: 1

2022/10/06 18:12:38.019 localhost:7 write 10

Record2: 3

2022/10/06 18:12:38.019 localhost:7 read 10

Record2: 3

2022/10/06 18:12:38.120 localhost:7 write 10

Record3: 4

2022/10/06 18:12:38.120 localhost:7 read 10

Record3: 4

2022/10/06 18:12:38.221 localhost:7 write 10

Record4: 4

2022/10/06 18:12:38.222 localhost:7 read 10

Record4: 4

2022/10/06 18:12:38.323 localhost:7 write 10

Record1: 4

2022/10/06 18:12:38.323 localhost:7 read 10

Record1: 4

2022/10/06 18:12:38.424 localhost:7 write 10

Record2: 4

2022/10/06 18:12:38.425 localhost:7 read 10

Record2: 4

 

I then uncommented the calls to asynOctetSetOutputEos and asynOctetSetInputEos, rebooted the IOC and ran the Python program again.  This is the output of asynTrace.  Now we got all 40 messages and the total elapsed time to write and read 20 times was 0.242 seconds.

 

2022/10/06 18:16:42.457 localhost:7 write 11

Record1: 0\n

2022/10/06 18:16:42.457 localhost:7 read 11

Record1: 0\n

2022/10/06 18:16:42.482 localhost:7 write 11

Record2: 0\n

2022/10/06 18:16:42.483 localhost:7 read 11

Record2: 0\n

2022/10/06 18:16:42.509 localhost:7 write 11

Record3: 0\n

2022/10/06 18:16:42.509 localhost:7 read 11

Record3: 0\n

2022/10/06 18:16:42.536 localhost:7 write 11

Record4: 0\n

2022/10/06 18:16:42.537 localhost:7 read 11

Record4: 0\n

2022/10/06 18:16:42.547 localhost:7 write 11

Record1: 1\n

2022/10/06 18:16:42.547 localhost:7 read 11

Record1: 1\n

2022/10/06 18:16:42.557 localhost:7 write 11

Record2: 1\n

2022/10/06 18:16:42.557 localhost:7 read 11

Record2: 1\n

2022/10/06 18:16:42.567 localhost:7 write 11

Record3: 1\n

2022/10/06 18:16:42.567 localhost:7 read 11

Record3: 1\n

2022/10/06 18:16:42.577 localhost:7 write 11

Record4: 1\n

2022/10/06 18:16:42.577 localhost:7 read 11

Record4: 1\n

2022/10/06 18:16:42.588 localhost:7 write 11

Record1: 2\n

2022/10/06 18:16:42.588 localhost:7 read 11

Record1: 2\n

2022/10/06 18:16:42.598 localhost:7 write 11

Record2: 2\n

2022/10/06 18:16:42.598 localhost:7 read 11

Record2: 2\n

2022/10/06 18:16:42.608 localhost:7 write 11

Record3: 2\n

2022/10/06 18:16:42.608 localhost:7 read 11

Record3: 2\n

2022/10/06 18:16:42.618 localhost:7 write 11

Record4: 2\n

2022/10/06 18:16:42.619 localhost:7 read 11

Record4: 2\n

2022/10/06 18:16:42.629 localhost:7 write 11

Record1: 3\n

2022/10/06 18:16:42.629 localhost:7 read 11

Record1: 3\n

2022/10/06 18:16:42.639 localhost:7 write 11

Record2: 3\n

2022/10/06 18:16:42.639 localhost:7 read 11

Record2: 3\n

2022/10/06 18:16:42.649 localhost:7 write 11

Record3: 3\n

2022/10/06 18:16:42.649 localhost:7 read 11

Record3: 3\n

2022/10/06 18:16:42.659 localhost:7 write 11

Record4: 3\n

2022/10/06 18:16:42.659 localhost:7 read 11

Record4: 3\n

2022/10/06 18:16:42.670 localhost:7 write 11

Record1: 4\n

2022/10/06 18:16:42.670 localhost:7 read 11

Record1: 4\n

2022/10/06 18:16:42.680 localhost:7 write 11

Record2: 4\n

2022/10/06 18:16:42.680 localhost:7 read 11

Record2: 4\n

2022/10/06 18:16:42.690 localhost:7 write 11

Record3: 4\n

2022/10/06 18:16:42.690 localhost:7 read 11

Record3: 4\n

2022/10/06 18:16:42.700 localhost:7 write 11

Record4: 4\n

2022/10/06 18:16:42.700 localhost:7 read 11

Record4: 4\n

 

The explanation is simple.  Since the port was created with noProcessEos=0 the EOS interpose interface is in use.  That means a read operation will only return when one of the following occurs:

-          The specified terminator has been received.

-          The specified number of characters has been received.  The stream protocol does not specify a number of characters.

-          An end-of-message has been received.  This does not apply to TCP, only GPIB.

-          The specified timeout has elapsed.

 

It seems clear that there is a default 0.1 second timeout either in asyn or stream, since we did not specify that.  Once we specified the terminator then asyn/stream knew when the response from the echo server was complete, and it no longer times out and runs at the expected speed.

 

Mark

 

 

 

 

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

 

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.