Re: Problem with huge waveforms in EPICS 7

[Mark Rivers via Core-talk <core-talk at aps.anl.gov>]

The database I posted uses only support from base. I don’t know the Python PVA code but perhaps you can convert my PyEpics code to PVA and test.

Mark


Sent from my iPhone

> On Jun 25, 2022, at 10:58 PM, Michael Davidsaver <mdavidsaver at gmail.com> wrote:
> 
> On 6/25/22 16:51, Mark Rivers via Core-talk wrote:
>> I also did this simDetector test with base 3.15.5 and there are no monitor callbacks after acquisition is complete.  So the issue was introduced after that release.
> 
> I would be interested to know if PVA (QSRV) shows the same behavour.
> I wonder whether this is really CA (RSRV) specific, or something
> with the database.  Like dbEvent or record support code.
> 
> 
>> Mark
>> *From:*Mark Rivers
>> *Sent:* Saturday, June 25, 2022 6:34 PM
>> *To:* Zimoch Dirk (PSI) <dirk.zimoch at psi.ch>; Andrew Johnson <anj at anl.gov>
>> *Cc:* core-talk at aps.anl.gov
>> *Subject:* RE: Problem with huge waveforms in EPICS 7
>> I did another test with the simDetector.  This is the setup screen:
>> The AcquireTime is 0.1 second, which means it will do 10 callbacks per second.
>> The simulation mode is linear ramp, and the Gain is 1, which means each pixel value will increase by 1 in successive images.  This makes it possible to see if the image is changing, and which image is being received.
>> The ImageMode is Multiple and NumImages=100 which means that when Acquire is set to 1 it will collect 100 images and then stop.
>> The waveform record for the NDStdArrays plugin has 20000000 elements and FTVL=SHORT.  The DataType of the simDetector is UInt16.
>> I made a new Python test program.
>> -It prints the a counter value in the callback function,  which it increments.
>> -It also prints the first value in the waveform record, so we can see how much it is changing.
>> -The program starts the acquisition, and then waits for it to complete by reading the value of the Acquire PV, which will go to 0 after 100 images have been collected.
>> -It then waits another 60 seconds for any additional monitor callbacks.
>> (base) corvette:asyn/iocBoot/ioctestAsynPortDriver>more monitor_test_ad.py
>> from epics import PV
>> import numpy as np
>> import time
>> from datetime import datetime
>> def current_time():
>>     return datetime.now().strftime('%Y-%m-%d %H:%M:%S.%f')
>> def pv_callback(pvname=None, value=None, timestamp=None, **kw):
>>     global counter
>>     counter += 1
>>     print('%s: pv_callback counter=%d, pvName=%s, size=%d, value=[0]=%d' % (current_time(), counter, pvname, len(value), value[0]))
>> counter = 0
>> big_array = PV('13SIM1:image1:ArrayData', auto_monitor=True)
>> print('%s: Adding BIGARRAY callback function' % (current_time()))
>> big_array.add_callback(pv_callback)
>> acquire = PV('13SIM1:cam1:Acquire', auto_monitor=False)
>> print('%s: Starting acquisition' % (current_time()))
>> acquire.put(1)
>> print('%s: Waiting for acquisition to complete' % (current_time()))
>> while (acquire.get() == 1):
>>     time.sleep(0.1)
>> print('%s: Acquisition complete' % (current_time()))
>> print('%s: Sleeping for 60 seconds' % (current_time()))
>> time.sleep(60)
>> print('%s: Exiting' % (current_time()))
>> This is the output of the Python program when it is run on a remote Windows machine over a 1 Gbit link from the Linux IOC.
>> (base) J:\epics\devel\asyn\iocBoot\ioctestAsynPortDriver>python monitor_test_ad.py
>> 2022-06-25 17:45:08.977807: Adding BIGARRAY callback function
>> 2022-06-25 17:45:08.977807: Starting acquisition
>> 2022-06-25 17:45:09.008815: Waiting for acquisition to complete
>> 2022-06-25 17:45:09.501366: pv_callback counter=1, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=199
>> 2022-06-25 17:45:09.912184: pv_callback counter=2, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=203
>> 2022-06-25 17:45:10.326705: pv_callback counter=3, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=207
>> 2022-06-25 17:45:10.734307: pv_callback counter=4, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=211
>> 2022-06-25 17:45:11.144670: pv_callback counter=5, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=215
>> 2022-06-25 17:45:11.571989: pv_callback counter=6, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=219
>> 2022-06-25 17:45:11.987259: pv_callback counter=7, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=223
>> 2022-06-25 17:45:12.405577: pv_callback counter=8, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=227
>> 2022-06-25 17:45:12.823582: pv_callback counter=9, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=232
>> 2022-06-25 17:45:13.252142: pv_callback counter=10, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=236
>> 2022-06-25 17:45:13.668979: pv_callback counter=11, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=240
>> 2022-06-25 17:45:14.081098: pv_callback counter=12, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=244
>> 2022-06-25 17:45:14.497104: pv_callback counter=13, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=248
>> 2022-06-25 17:45:14.922151: pv_callback counter=14, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=252
>> 2022-06-25 17:45:15.341294: pv_callback counter=15, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=257
>> 2022-06-25 17:45:15.763571: pv_callback counter=16, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=261
>> 2022-06-25 17:45:16.187630: pv_callback counter=17, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=265
>> 2022-06-25 17:45:16.601769: pv_callback counter=18, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=269
>> 2022-06-25 17:45:17.018671: pv_callback counter=19, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=274
>> 2022-06-25 17:45:17.434503: pv_callback counter=20, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=278
>> 2022-06-25 17:45:17.856621: pv_callback counter=21, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=282
>> 2022-06-25 17:45:18.273360: pv_callback counter=22, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=286
>> 2022-06-25 17:45:18.687654: pv_callback counter=23, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=290
>> 2022-06-25 17:45:19.112557: pv_callback counter=24, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=294
>> 2022-06-25 17:45:19.527148: pv_callback counter=25, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=299
>> 2022-06-25 17:45:19.950669: pv_callback counter=26, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=299
>> 2022-06-25 17:45:19.952671: Acquisition complete
>> 2022-06-25 17:45:19.952671: Sleeping for 60 seconds
>> 2022-06-25 17:45:20.367371: pv_callback counter=27, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=299
>> 2022-06-25 17:45:20.782781: pv_callback counter=28, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=299
>> 2022-06-25 17:45:21.208172: pv_callback counter=29, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=299
>> 2022-06-25 17:45:21.626443: pv_callback counter=30, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=299
>> 2022-06-25 17:45:22.042891: pv_callback counter=31, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=299
>> 2022-06-25 17:45:22.457375: pv_callback counter=32, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=299
>> 2022-06-25 17:45:22.874498: pv_callback counter=33, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=299
>> 2022-06-25 17:45:23.294542: pv_callback counter=34, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=299
>> 2022-06-25 17:45:23.710515: pv_callback counter=35, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=299
>> 2022-06-25 17:45:24.129236: pv_callback counter=36, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=299
>> 2022-06-25 17:45:24.554132: pv_callback counter=37, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=299
>> 2022-06-25 17:45:24.969318: pv_callback counter=38, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=299
>> 2022-06-25 17:45:25.383840: pv_callback counter=39, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=299
>> 2022-06-25 17:45:25.815720: pv_callback counter=40, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=299
>> 2022-06-25 17:45:26.234223: pv_callback counter=41, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=299
>> 2022-06-25 17:45:26.658804: pv_callback counter=42, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=299
>> 2022-06-25 17:45:27.075088: pv_callback counter=43, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=299
>> 2022-06-25 17:45:27.701913: pv_callback counter=44, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=299
>> 2022-06-25 17:45:28.116487: pv_callback counter=45, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=299
>> 2022-06-25 17:45:28.766605: pv_callback counter=46, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=299
>> 2022-06-25 17:45:29.180284: pv_callback counter=47, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=299
>> 2022-06-25 17:45:30.773591: pv_callback counter=48, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=299
>> 2022-06-25 17:45:31.971378: pv_callback counter=49, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=299
>> 2022-06-25 17:45:32.970545: pv_callback counter=50, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=299
>> 2022-06-25 17:45:33.967158: pv_callback counter=51, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=299
>> 2022-06-25 17:45:34.783298: pv_callback counter=52, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=299
>> 2022-06-25 17:45:35.204079: pv_callback counter=53, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=299
>> 2022-06-25 17:45:35.626276: pv_callback counter=54, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=299
>> 2022-06-25 17:45:36.041266: pv_callback counter=55, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=299
>> 2022-06-25 17:45:36.453080: pv_callback counter=56, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=299
>> 2022-06-25 17:45:36.871318: pv_callback counter=57, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=299
>> 2022-06-25 17:45:37.285079: pv_callback counter=58, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=299
>> 2022-06-25 17:45:37.720734: pv_callback counter=59, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=299
>> 2022-06-25 17:45:38.366094: pv_callback counter=60, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=299
>> 2022-06-25 17:45:39.229229: pv_callback counter=61, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=299
>> 2022-06-25 17:45:39.914253: pv_callback counter=62, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=299
>> 2022-06-25 17:45:40.734391: pv_callback counter=63, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=299
>> 2022-06-25 17:45:41.148555: pv_callback counter=64, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=299
>> 2022-06-25 17:45:41.591978: pv_callback counter=65, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=299
>> 2022-06-25 17:45:42.028103: pv_callback counter=66, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=299
>> 2022-06-25 17:45:42.508956: pv_callback counter=67, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=299
>> 2022-06-25 17:45:43.030108: pv_callback counter=68, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=299
>> 2022-06-25 17:45:43.449413: pv_callback counter=69, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=299
>> 2022-06-25 17:45:43.862464: pv_callback counter=70, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=299
>> 2022-06-25 17:45:44.279789: pv_callback counter=71, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=299
>> 2022-06-25 17:45:44.703770: pv_callback counter=72, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=299
>> 2022-06-25 17:45:45.137917: pv_callback counter=73, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=299
>> 2022-06-25 17:45:45.552173: pv_callback counter=74, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=299
>> 2022-06-25 17:45:45.971023: pv_callback counter=75, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=299
>> 2022-06-25 17:45:46.388227: pv_callback counter=76, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=299
>> 2022-06-25 17:45:46.809020: pv_callback counter=77, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=299
>> 2022-06-25 17:45:47.426263: pv_callback counter=78, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=299
>> 2022-06-25 17:45:47.849754: pv_callback counter=79, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=299
>> 2022-06-25 17:45:48.463381: pv_callback counter=80, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=299
>> 2022-06-25 17:45:48.888499: pv_callback counter=81, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=299
>> 2022-06-25 17:45:49.300091: pv_callback counter=82, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=299
>> 2022-06-25 17:45:49.718147: pv_callback counter=83, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=299
>> 2022-06-25 17:45:50.141606: pv_callback counter=84, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=299
>> 2022-06-25 17:45:50.557192: pv_callback counter=85, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=299
>> 2022-06-25 17:45:50.976428: pv_callback counter=86, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=299
>> 2022-06-25 17:45:51.387190: pv_callback counter=87, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=299
>> 2022-06-25 17:45:51.802159: pv_callback counter=88, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=299
>> 2022-06-25 17:45:52.217662: pv_callback counter=89, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=299
>> 2022-06-25 17:45:52.632185: pv_callback counter=90, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=299
>> 2022-06-25 17:45:53.051046: pv_callback counter=91, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=299
>> 2022-06-25 17:45:53.668667: pv_callback counter=92, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=299
>> 2022-06-25 17:45:54.091076: pv_callback counter=93, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=299
>> 2022-06-25 17:45:54.508703: pv_callback counter=94, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=299
>> 2022-06-25 17:45:54.926338: pv_callback counter=95, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=299
>> 2022-06-25 17:45:55.335884: pv_callback counter=96, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=299
>> 2022-06-25 17:45:55.756442: pv_callback counter=97, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=299
>> 2022-06-25 17:45:56.174092: pv_callback counter=98, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=299
>> 2022-06-25 17:45:56.987064: pv_callback counter=99, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=299
>> 2022-06-25 17:45:57.603519: pv_callback counter=100, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=299
>> 2022-06-25 17:45:58.017257: pv_callback counter=101, pvName=13SIM1:image1:ArrayData, size=20000000, value=[0]=299
>> 2022-06-25 17:46:19.955976: Exiting
>> Important things to note:
>> -The first waveform element is usually incrementing by 4, not by 1, which means we are only getting every 4’th monitor.  This is because of the speed of the link.
>> -The time between starting acquisition and detecting that it is complete is just over 10 seconds.  The acquisition should have taken 10 seconds (100 frames, 0.1 second acquisition time).
>> -When acquisition was complete 26 callbacks had been received.
>> -After acquisition was complete an additional 75 monitor callbacks were received.  These all have the same first pixel value, which is that of the last image collected.
>> -The total number of callbacks was 101, which is 1 more than the total number of images collected.  The +1 is presumably because there is a monitor on the initial connection, before acquisition starts.
>> -This behavior is exactly what Dirk observed, although I don’t know if he realized that the total number of monitors eventually received is the total number of times db_post_events was called.
>> When I increased NumImages to 150 there were 34 callbacks before acquisition completed, and a total of 141 callbacks (not 150).
>> When I increased NumImages to 200 there were 40 callbacks before acquisition completed, and a total of 148 callbacks (not 200).
>> So it does seem like something is limiting the total number of “stale” callbacks, it does not increase without bound as the number of dropped callbacks increases.
>> I made an interesting observation.  During the period when the client is receiving the stale arrays if I change conditions and start acquisition again (outside the Python program) Python immediately receives the new arrays, it does not continue to receive the stale arrays.  But then when that acquisition stops it will now receive even more stale arrays (those missing in the first acquisition and those missed in the second acquisition.
>> Mark
>