Re: Exploring EPICS performance/processing limits

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

Hi!

The problem is getting much clearer thanks to your help.

The service running in port 60000 is a custom protocol made in-house. I dont have immediate access to the documents of the protocol, but its not hard to get them.
Im going to look for it, i think we are close to a solution. I dont know why the previous developer defined these terminators in the .proto file but if this is the problem we are close to fixing it.

Will be back soon with updates. Much thanks for the help ��

Marco

---

From: Mark Rivers <rivers at cars.uchicago.edu>
Sent: 07 October 2022 12:09
To: Marco A. Barra Montevechi Filho <marco.filho at lnls.br>; Matthew Newville <newville at cars.uchicago.edu>
Cc: tech-talk at aps.anl.gov <tech-talk at aps.anl.gov>
Subject: RE: Exploring EPICS performance/processing limits

 

Hi Marco,

 

Your example is pretty complex, it is best to simplify as much as possible for tests like this.

 

I have some questions.

-          Your drvAsynIPPort driver is connecting to 127.0.0.1:60000.  What server are you running on port 60000?  I was using the standard Echo Protocol service on port 7.

-          Your protocol file has Terminator = LF;  However, the asynTrace output shows that there is actually no LF terminator being sent or received. Do you understand this?

 

2022/10/07 11:15:41.810 127.0.0.1:60000 write 92

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

2022/10/07 11:15:41.815 127.0.0.1:60000 read 57

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

2022/10/07 11:15:41.917 127.0.0.1:60000 write 87

 

-          The asynTrace shows that it is almost exactly 0.1 seconds between the 2 write commands.  This is the same thing I was seeing, and I believe it is due to a read timeout because you are not using a terminator.

 

Mark

 

 

From: Marco A. Barra Montevechi Filho <marco.filho at lnls.br>
Sent: Friday, October 7, 2022 9:17 AM
To: Mark Rivers <rivers at cars.uchicago.edu>; Matthew Newville <newville at cars.uchicago.edu>
Cc: tech-talk at aps.anl.gov
Subject: Re: Exploring EPICS performance/processing limits

 

Hi, Mark!

I just saw your most recent e-mail and im going to read it carefully. Just sending the previous required files in here as i said i would do: i send them as attached files.

The record ImgChipNumberID is defined as an alias in line 119 of mobibackend.template file. One of my attempts of changing it sequentially with transform record is in mobipix_sensors_initialization.template file.
The write_2param function is defined in line 55 of the protocol file.
The output of asynTrace function was made when running my python script with large (bigger than 0.5) delays.

Thanks for the help, im going to see the email about how you reproducted the behavior now.

Best regards,

Marco

---

From: Mark Rivers <rivers at cars.uchicago.edu>
Sent: 06 October 2022 15:19
To: Marco A. Barra Montevechi Filho <marco.filho at lnls.br>; Matthew Newville <newville at cars.uchicago.edu>
Cc: tech-talk at aps.anl.gov <tech-talk at aps.anl.gov>
Subject: RE: Exploring EPICS performance/processing limits

 

Hi Marco,

 

Please post:

 

-          The complete output when your IOC starts

-          The database containing MOBICDTE:Backend:ImgChipNumberID

-          The protocol file you are using

-          The output of asynTrace as I suggested my message this morning

 

Mark

 

 

 

From: Tech-talk <tech-talk-bounces at aps.anl.gov> On Behalf Of Marco A. Barra Montevechi Filho via Tech-talk
Sent: Thursday, October 6, 2022 1:12 PM
To: Matthew Newville <newville at cars.uchicago.edu>
Cc: tech-talk at aps.anl.gov
Subject: Re: Exploring EPICS performance/processing limits

 

Hi, Matt!

Sorry, I tried to make my question succint but ended up hiding several details of the problem.

So, first of all: the whole problem showed itself when i tried to create a transform record that had several OUT fields, some of them pointing to the same record and changing its value. Here is part of the transform record:

record(transform, "$(P)$(R)SensorsInitChip"){

    field(A,"0")

    field(B,"154")

    field(C,"198")

    field(D,"208")

    field(E,"57")

    field(F, "1")

    field(G, "1")

    field(H,"182")

    field(OUTA,"${P}${BE}:ImgChipNumberID PP")

    field(OUTB,"${P}${BE}:DAC_GND PP")

    field(OUTC,"${P}${BE}:DAC_CAS PP")

    field(OUTD,"${P}${BE}:DAC_FBK PP")

    field(OUTE,"${P}${BE}:DAC_DiscL PP")

    field(OUTF,"$(P)$(R)Tmr1 PP")

    field(OUTG,"${P}${BE}:ImgChipNumberID PP")

    field(OUTH,"${P}${BE}:DAC_GND PP")

}

So it changes ImgChipNumberID's value, do several things and then changes it again.
To test if the problem was with the transform record (spoilers: it seems it is not), i then made the following script:

import epics, time, sys

 

def changer(x):

    for i in range(0,4):

        epics.caput("MOBICDTE:Backend:ImgChipNumberID", i)

        time.sleep(x)

 

changer(float(sys.argv[1]))

and ran .my_test.py while monitoring the IOC with 'tcpflow -c -i lo port 60000 | grep "HS_ImgChipNumberID"' (HS_ImgChipNumberID is the JSON command being sent by the record) and monitoring the record with camonitor, as you suggested.
Here are the results:

FOR 5 SECONDS OF SLEEP TIME:
TCPFLOW:

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

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

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

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

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

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

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

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

(The "params": [["1", "N"]] is the command causing trouble later, but it is working nice here)

CAMONITOR:

camonitor MOBICDTE:Backend:ImgChipNumberID

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 14:56:42.275342454

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

MOBICDTE:Backend:ImgChipNumberID 2022-10-06 14:31:09.112389 3 READ INVALID

MOBICDTE:Backend:ImgChipNumberID 2022-10-06 14:57:59.690554 0 READ INVALID

MOBICDTE:Backend:ImgChipNumberID 2022-10-06 14:58:04.690451 1 READ INVALID

MOBICDTE:Backend:ImgChipNumberID 2022-10-06 14:58:09.692468 2 READ INVALID

MOBICDTE:Backend:ImgChipNumberID 2022-10-06 14:58:14.696379 3 READ INVALID

FOR 0.1 SECONDS OF SLEEP TIME:

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

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

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

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

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

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

(so we can see that the command "params": [["1", "2"]] was skipped)

CAMONITOR:
MOBICDTE:Backend:ImgChipNumberID 2022-10-06 15:05:22.936035 1 READ INVALID
MOBICDTE:Backend:ImgChipNumberID 2022-10-06 15:05:23.141153 3 READ INVALID

So we can see that even though the command "params": [["1","0"]] was sent, the PV was not published with value=0.

So to answer your questions: the weird behavior is also when monitoring with camonitor and VALUE is indeed different for each iteration.

Thanks for the help,

Marco

---

From: Matt Newville <newville at cars.uchicago.edu>
Sent: 05 October 2022 21:52
To: 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

 

Hi Marco,

 

I don't understand that behavior and would ask whether that observation is only when using tcpflow or also appears from using a camonitor.  

To be clear, you should not need `sleep()` there, and certainly not as long as 0.5 seconds.  Yes, the IOC and Channel Access should be capable of dealing with time intervals much smaller than that.  

 

Since "VALUE" is left to the imagination of the reader, is it obvious that this should be a new value (ie, different from the current value) for all PVs?

 

--Matt

 

 

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.