RE: Exploring EPICS performance/processing limits

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

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.