RE: Channel Access client sees only partial update.

[Mark Rivers <rivers@cars.uchicago.edu>]

Hi Michael,

For images 86, 87, 88, and 89 this is what the IOC log shows.

2017/06/07 16:38:01.230 INSTR:cam1:RawEventData devAsynInt8Array::interruptCallbackInput ringSize=20, len=262144, callback data:V\000\000\000\276\272\376\312\340\377\003\000\000\000\000\000\340xC\001\000\000\000\000\000\000\000\000\000\000\000\000\001\003X\325\220\200\212\001\001\003X\325\220\200\212\001^.b\227\323\200\222\001^.b\227\323\200\222\001[\346\343v`\000\232\001[\346\343v`\000\232\001
2017/06/07 16:38:01.231 Block: 86 DataSize: 262112
2017/06/07 16:38:01.231 INSTR:cam1:RawEventData devAsynInt8Array::interruptCallbackInput ringSize=20, len=262144, callback data:W\000\000\000\276\272\376\312\340\377\003\000\000\000\000\000\300xG\001\000\000\000\000\000\000\000\000\000\000\000\000%\316\233\335\265\000o=%\316\233\335\265\000o=-\356\227j\262\000o=-\356\227j\262\000o=\aEo\265\217\000o=\aEo\265\217\000o=
2017/06/07 16:38:01.232 INSTR:cam1:RawEventData devAsynInt8Array::processCommon nord=262144, pwf->bptr data:V\000\000\000\276\272\376\312\340\377\003\000\000\000\000\000\340xC\001\000\000\000\000\000\000\000\000\000\000\000\000\001\003X\325\220\200\212\001\001\003X\325\220\200\212\001^.b\227\323\200\222\001^.b\227\323\200\222\001[\346\343v`\000\232\001[\346\343v`\000\232\001
2017/06/07 16:38:01.232 Block: 87 DataSize: 262112
2017/06/07 16:38:01.232 INSTR:cam1:RawEventData devAsynInt8Array::interruptCallbackInput ringSize=20, len=262144, callback data:X\000\000\000\276\272\376\312\340\377\003\000\000\000\000\000\240xK\001\000\000\000\000\000\000\000\000\000\000\000\000\372\341\230\300\232\000\004:\372\341\230\300\232\000\004:\203U\321m\205\000\t:\203U\321m\205\000\t:$5\2474@\000\n:$5\2474@\000\n:
2017/06/07 16:38:01.233 Block: 88 DataSize: 262112
2017/06/07 16:38:01.233 INSTR:cam1:RawEventData devAsynInt8Array::interruptCallbackInput ringSize=20, len=199984, callback data:Y\000\000\000\276\272\376\312\020\r\003\000\000\000\000\000\260\205N\001\000\000\000\000\000\000\000\000\000\000\000\000\272\356\336\301\"\000\2547h\313\320\271\\\000\2627h\313\320\271\\\000\2627\240\325\257\257N\200\2647\240\325\257\257N\200\2647\270\215bP\266\200\2647
2017/06/07 16:38:01.233 INSTR:cam1:RawEventData devAsynInt8Array::processCommon nord=262144, pwf->bptr data:W\000\000\000\276\272\376\312\340\377\003\000\000\000\000\000\300xG\001\000\000\000\000\000\000\000\000\000\000\000\000%\316\233\335\265\000o=%\316\233\335\265\000o=-\356\227j\262\000o=-\356\227j\262\000o=\aEo\265\217\000o=\aEo\265\217\000o=
2017/06/07 16:38:01.234 Block: 89 DataSize: 199952
2017/06/07 16:38:01.234 INSTR:cam1:RawEventData devAsynInt8Array::processCommon nord=262144, pwf->bptr data:X\000\000\000\276\272\376\312\340\377\003\000\000\000\000\000\240xK\001\000\000\000\000\000\000\000\000\000\000\000\000\372\341\230\300\232\000\004:\372\341\230\300\232\000\004:\203U\321m\205\000\t:\203U\321m\205\000\t:$5\2474@\000\n:$5\2474@\000\n:
2017/06/07 16:38:01.235 INSTR:cam1:RawEventData devAsynInt8Array::processCommon nord=199984, pwf->bptr data:Y\000\000\000\276\272\376\312\020\r\003\000\000\000\000\000\260\205N\001\000\000\000\000\000\000\000\000\000\000\000\000\272\356\336\301\"\000\2547h\313\320\271\\\000\2627h\313\320\271\\\000\2627\240\325\257\257N\200\2647\240\325\257\257N\200\2647\270\215bP\266\200\2647

You will see that everything above seems correct.  

All 4 blocks were received in interruptCallbackInput with the correct sizes (262144, 262144, 262144, 199984). The first byte of the array is the blockID and these are V, W, X, Y which are 86, 87, 88, 89 in decimal.

All 4 blocks also resulted in the waveform record processing (::processCommon).  Again the blockID and sizes are correct in processCommon.

This means that the waveform record processed correctly for each callback.

The problem you are having is thus not due to your driver, or to asyn.  The problem is Channel Access.  At the end of the waveform record processing it calls db_post_events which tells Channel Access to post monitors on the array. However Channel Access does not provide any buffering or queuing for arrays.  This means that if the record processes twice before it has a chance to send the first monitor that some arrays will be skipped.  It also means that by the time Channel Access runs for array N array the record might have processed again with N+1.  So you can get duplicates.  You are seeing both of these problems as shown by camonitor and your CA client:

This is what camonitor shows:

INSTR:cam1:RawEventData 2017-06-07 16:38:01.231555 4 86 0 0 0  
INSTR:cam1:RawEventData 2017-06-07 16:38:01.234717 4 89 0 0 0  
INSTR:cam1:RawEventData 2017-06-07 16:38:01.234717 4 89 0 0 0  

This is what your CA client log shows:

CB: INSTR:cam1:RawEventData Wed Jun 07 2017 16:38:01.****** Block 86 Datasize 262112
CB: INSTR:cam1:RawEventData Wed Jun 07 2017 16:38:01.****** Block 89 Datasize 199952
CB: INSTR:cam1:RawEventData Wed Jun 07 2017 16:38:01.****** Block 89 Datasize 199952

It is probably a bad idea to rely on Channel Access if you need to have reliable data transfer between your IOC and the software saving your data with no missing data.

This might be a case for using pvAccess from V4.  I believe that it provides for queueing which Channel Access does not. areaDetector already provides NDPluginPva which will convert your NDArrays to EPICS V4 NTNDArrays and serve them using pvAccess.  You would then just need to convert your client program to use pvAccess rather than Channe Access.

Mark



-----Original Message-----
From: Michael Huth [mailto:michael.huth@byte-physics.de] 
Sent: Thursday, June 08, 2017 11:09 AM
To: Mark Rivers; tech-talk@aps.anl.gov
Subject: Re: Channel Access client sees only partial update.

Hello Mark,

attached you will find the logs with Trace enabled.

There is the complete ioc output, the camonitor and from my own CA client.

When testing I noticed the following: If I subscribe in my own client
only to the INSTR:cam1:RawEventData PV then the callbacks follow the
same pattern as the camonitor output.
The camonitor log shows two acquisition runs, one with 17 blocks and
another with 221 blocks. My own CA client shows the second acquisition
with the 221 blocks.
The blocks are with header that contains an id number. For some like 84
and 89 there are doubles, whereas e.g. 82, 83 and 87, 88 is missing.
Here camonitor and my own client is in sync.
Still, no valid block stream and not the correct number of callbacks either.

However if I subscribe to a second PV that is updated only once the main
loop in the IOC runs, then I get only callbacks for the last block i.e.
for both PVs only one callback per main loop run in the IOC. Nothing in
the code is changed. That is the situation I described before where I
only see callbacks for the last block.
I tried camonitor with the same two PVs as argument, but it doesn't
reduce the callbacks for INSTR:cam1:RawEventData.
Then I reduced my own CA client to be basically a C++ copy of camonitor
but it didn't changed the behavior - as soon as I subscribe to both the
callbacks for
INSTR:cam1:RawEventData get reduced to the same rate as
INSTR:LiveImageXY:ArrayData.

Best regards,
Michael Huth

On 06.06.2017 22:59, Mark Rivers wrote:
> Hi Michael,
>
> Is the output you just sent with the info tag present or absent?  I see that you are only getting the last block of each burst of 4 data blocks.  
>
> I had assumed from your first message that you were getting the correct number of Channel Access callbacks, but that the data was all the same, i.e. from the last block.  That is why I suggested the ring buffer.  However, it looks like what you are seeing is that you are only getting CA callbacks at all for the last block.  I don't understand that.
>
> Your previous message said that using the info tag you got duplicate arrays like:
>> Block 1037
>> Block 1038
>> Block 1041
>> Block 1041
> But I don't see that in your most recent message.
>
> Can you send the client output when the server has the info tag, and also when it does not.
>
> It would also help to have timestamps on both the server and client messages.  For the server you can change your printf to asynPrint(pasynUserSelf, ASYN_TRACE_ERROR, ...) to get timestamps.
>
> Where in your data block is the block number?  You could use
>
> camonitor -# NNN PV
>
> to display the first NNN bytes of the waveform record, where NNN is selected to include the block number.  That will show if camonitor agrees with your client on when callbacks are coming.
>
> You can also enable asynTrace for your driver in the startup script.
>
> asynSetTraceIOMask(myPort, 0, 2)
> asynSetTraceMask(myPort, 0, 255)
>
> Then we will see useful messages from device support.
>
> Mark
>
>
> -----Original Message-----
> From: Michael Huth [mailto:michael.huth@byte-physics.de] 
> Sent: Tuesday, June 06, 2017 3:14 PM
> To: Mark Rivers; tech-talk@aps.anl.gov
> Subject: Re: Channel Access client sees only partial update.
>
> Hello Mark,
>
> I'am using asyn 4.26. / Epics 3.15.5.
>
> There is only the main IOC thread copying source data to the block
> buffer in a simple loop:
>
>   size_t dataSize = BlockSize - headerSize;
>   auto source = SourceData.data();
>   auto dest = DataBlock.data();
>  
>   do {
>       // prepare block header
>       Blockheader.dataSizeInBlock = (sourceBytes > dataSize) ? dataSize
> : sourceBytes ;
>       // join header with data
>       memcpy(dest, &Blockheader, sizeof(Blockheader));
>       memcpy(dest + headerSize, source, Blockheader.dataSizeInBlock);
>       // send away
>       doCallbacksInt8Array(dest , headerSize +
> Blockheader.dataSizeInBlock, Data, 0);
>      
>       printf("Block: %d DataSize: %d\n", Blockheader.blockNr,
> Blockheader.dataSizeInBlock);
>       source += Blockheader.dataSizeInBlock;
>       sourceBytes -= Blockheader.dataSizeInBlock;
>       Blockheader.blockNr++;
>   } while(sourceBytes);
>
> This loop is between lock() and unlock().
>
> Following is first the output from the subscribed channel access client
> and after that the output of the IOC. There is a second process variable
> subscribed that is updated once per main loop in the IOC called 'Image'
> here. For this run the average data size is rather small so that it
> splits in ~4 small blocks.
>
> A longer output from the channel access client:
> Block 493 Datasize 200272
> Block 494 Datasize 204160
> got Image
> got Image
> Block 498 Datasize 200272
> got Image
> Block 502 Datasize 198224
> got Image
> Block 506 Datasize 200272
> got Image
> Block 510 Datasize 198224
> got Image
> Block 511 Datasize 204160
> got Image
> Block 515 Datasize 200272
> got Image
> Block 519 Datasize 198224
> got Image
> Block 523 Datasize 198224
> got Image
> Block 527 Datasize 202320
> got Image
> Block 528 Datasize 202112
> got Image
> Block 532 Datasize 202320
> got Image
> Block 536 Datasize 194128
> got Image
> Block 540 Datasize 200272
> got Image
> Block 544 Datasize 200272
> got Image
> Block 545 Datasize 204160
> got Image
> Block 549 Datasize 200272
> Block 550 Datasize 262112
> got Image
> Block 553 Datasize 196176
> got Image
> Block 557 Datasize 200272
> got Image
> Block 561 Datasize 200272
> got Image
> Block 562 Datasize 204160
> got Image
> Block 566 Datasize 200272
> got Image
> Block 570 Datasize 196176
> got Image
> Block 574 Datasize 200272
> got Image
> Block 578 Datasize 200272
> got Image
> Block 579 Datasize 204160
> got Image
> Block 583 Datasize 200272
> got Image
> Block 587 Datasize 196176
> got Image
> Block 591 Datasize 200272
> got Image
> Block 595 Datasize 202320
> Block 596 Datasize 204160
>
> IOC driver output at the same run:
> Block: 498 DataSize: 200272
> Reason to call CBF: measurement complete.
> Block: 499 DataSize: 262112
> Block: 500 DataSize: 262112
> Block: 501 DataSize: 262112
> Block: 502 DataSize: 198224
> Reason to call CBF: measurement complete.
> Block: 503 DataSize: 262112
> Block: 504 DataSize: 262112
> Block: 505 DataSize: 262112
> Block: 506 DataSize: 200272
> Reason to call CBF: measurement complete.
> Block: 507 DataSize: 262112
> Block: 508 DataSize: 262112
> Block: 509 DataSize: 262112
> Block: 510 DataSize: 198224
> Reason to call CBF: measurement complete.
> Block: 511 DataSize: 204160
> Reason to call CBF: measurement complete.
> Block: 512 DataSize: 262112
> Block: 513 DataSize: 262112
> Block: 514 DataSize: 262112
> Block: 515 DataSize: 200272
> Reason to call CBF: measurement complete.
> Block: 516 DataSize: 262112
> Block: 517 DataSize: 262112
> Block: 518 DataSize: 262112
> Block: 519 DataSize: 198224
> Reason to call CBF: measurement complete.
> Block: 520 DataSize: 262112
> Block: 521 DataSize: 262112
> Block: 522 DataSize: 262112
> Block: 523 DataSize: 198224
> Reason to call CBF: measurement complete.
> Block: 524 DataSize: 262112
> Block: 525 DataSize: 262112
> Block: 526 DataSize: 262112
> Block: 527 DataSize: 202320
> Reason to call CBF: measurement complete.
> Block: 528 DataSize: 202112
> Reason to call CBF: measurement complete.
> Block: 529 DataSize: 262112
> Block: 530 DataSize: 262112
> Block: 531 DataSize: 262112
> Block: 532 DataSize: 202320
> Reason to call CBF: measurement complete.
> Block: 533 DataSize: 262112
> Block: 534 DataSize: 262112
> Block: 535 DataSize: 262112
> Block: 536 DataSize: 194128
> Reason to call CBF: measurement complete.
> Block: 537 DataSize: 262112
> Block: 538 DataSize: 262112
> Block: 539 DataSize: 262112
> Block: 540 DataSize: 200272
> Reason to call CBF: measurement complete.
> Block: 541 DataSize: 262112
> Block: 542 DataSize: 262112
> Block: 543 DataSize: 262112
> Block: 544 DataSize: 200272
> Reason to call CBF: measurement complete.
> Block: 545 DataSize: 204160
> Reason to call CBF: measurement complete.
> Block: 546 DataSize: 262112
> Block: 547 DataSize: 262112
> Block: 548 DataSize: 262112
> Block: 549 DataSize: 200272
> Reason to call CBF: measurement complete.
> Block: 550 DataSize: 262112
> Block: 551 DataSize: 262112
> Block: 552 DataSize: 262112
> Block: 553 DataSize: 196176
> Reason to call CBF: measurement complete.
> Block: 554 DataSize: 262112
> Block: 555 DataSize: 262112
> Block: 556 DataSize: 262112
> Block: 557 DataSize: 200272
> Reason to call CBF: measurement complete.
> Block: 558 DataSize: 262112
> Block: 559 DataSize: 262112
> Block: 560 DataSize: 262112
> Block: 561 DataSize: 200272
> Reason to call CBF: measurement complete.
> Block: 562 DataSize: 204160
> Reason to call CBF: measurement complete.
> Block: 563 DataSize: 262112
> Block: 564 DataSize: 262112
> Block: 565 DataSize: 262112
> Block: 566 DataSize: 200272
> Reason to call CBF: measurement complete.
> Block: 567 DataSize: 262112
> Block: 568 DataSize: 262112
> Block: 569 DataSize: 262112
> Block: 570 DataSize: 196176
> Reason to call CBF: measurement complete.
> Block: 571 DataSize: 262112
> Block: 572 DataSize: 262112
> Block: 573 DataSize: 262112
> Block: 574 DataSize: 200272
> Reason to call CBF: measurement complete.
> Block: 575 DataSize: 262112
> Block: 576 DataSize: 262112
> Block: 577 DataSize: 262112
> Block: 578 DataSize: 200272
> Reason to call CBF: measurement complete.
> Block: 579 DataSize: 204160
> Reason to call CBF: measurement complete.
> Block: 580 DataSize: 262112
> Block: 581 DataSize: 262112
> Block: 582 DataSize: 262112
> Block: 583 DataSize: 200272
> Reason to call CBF: measurement complete.
> Block: 584 DataSize: 262112
> Block: 585 DataSize: 262112
> Block: 586 DataSize: 262112
> Block: 587 DataSize: 196176
> Reason to call CBF: measurement complete.
> Block: 588 DataSize: 262112
> Block: 589 DataSize: 262112
> Block: 590 DataSize: 262112
> Block: 591 DataSize: 200272
> Reason to call CBF: measurement complete.
> Block: 592 DataSize: 262112
> Block: 593 DataSize: 262112
> Block: 594 DataSize: 262112
> Block: 595 DataSize: 202320
> Reason to call CBF: measurement complete.
> Block: 596 DataSize: 204160
>
> I hope that helps.
>
> Best regards,
> Michael
>
> On 06.06.2017 21:38, Mark Rivers wrote:
>> Hi Michael,
>>
>> What version of asyn are you using?
>>
>> Can you send a longer sequence of blocks received with and without the info tag?
>>
>>> A rough guess of me is that the copy to the ring buffer is late and the
>>> source was already updated with the next block?
>> The copy to the ring buffer in done in your driver's thread that is calling doCallbacksInt8Array(blockPtr , block_size, Data, 0).  There is no way it can be "late".
>>
>> The only way I can see for the data to be overwritten is if your driver has another thread which is modifying the data in blockPtr while doCallbacksInt8Array() is executing.  If so you need to use a mutex to make sure you don't change the data in blockPtr before doCallbacksInt8Array has returned.
>>
>> In areaDetector normally the data is copied into an NDArray object that is allocated from the NDArrayPool.  The driver calls doCallbacksGenericPointer() to pass the NDArray to the plugins.  The NDPluginStdArrays plugin is what would actually call doCallbacksInt8Array.  It then decrements the reference count on the NDArray, returning it to the NDArrayPool if this was the last reference.  This prevents overwriting buffers if you have another thread getting the data from the device because it would always allocate a new NDArray.
>>
>>> Is there a way to block execution in the IOC to be sure that the data is in the Channel Access output buffer?
>> You don't need to wait for it to be in the Channel Access buffer, that is the point of the ring buffers.  The waveform record device support can buffer multiple arrays in the ring buffer.  You just need to make sure that your driver does not modify the data pointed to by blockPtr until doCallbacksInt8Array() has returned.
>>
>> Mark
>>
>>
>>
>> -----Original Message-----
>> From: Michael Huth [mailto:michael.huth@byte-physics.de] 
>> Sent: Tuesday, June 06, 2017 2:14 PM
>> To: Mark Rivers; tech-talk@aps.anl.gov
>> Subject: Re: Channel Access client sees only partial update.
>>
>> Hello Mark,
>>
>> with the line added to the database file the behavior is not much different,
>> just that I get now sometimes really multiple blocks per IOC task loop,
>> however with block IDs like this:
>>
>> Block 1037
>> Block 1038
>> Block 1041
>> Block 1041
>>
>> where e.g. a block with the 1041 data is sent twice. The ID number is
>> part of the blocks data.
>> A rough guess of me is that the copy to the ring buffer is late and the
>> source was already updated with the next block?
>> Is there a way to block execution in the IOC to be sure that the data is
>> in the Channel Access output buffer?
>>
>> The HDF5 swmr is actually already implemented in the CA client. It is
>> not planned to use HDF5 writing as part of the IOC driver.
>>
>> Best regards,
>> Michael
>>
>> On 06.06.2017 20:28, Mark Rivers wrote:
>>> Hi Michael,
>>>
>>> By default the devAsynInt8Array callback does not buffer the array it receives, it copies it directly into the waveform record.  If your driver callbacks are happening faster than the record processing and Channel Access transfer to the client then what you are seeing is expected.
>>>
>>> devAsynInt8Array can optionally use a ring-buffer to buffer the arrays passed to the callback function.  This should eliminate the problem you are seeing.  The ring buffer is disabled by default, but you can enable it by adding this line to your waveform record database file:
>>>
>>> info(asyn:FIFO, "20")
>>>
>>> where 20 is the maximum number of blocks you want to be able to buffer.
>>>
>>> This is documented here (search for "Buffering of Driver Callbacks"):
>>> http://www.aps.anl.gov/epics/modules/soft/asyn/R4-31/asynDriver.html
>>>
>>> How large is the data set you are trying to transfer?  Are you breaking it into blocks because of its size, or is your source actually delivering it in sub-blocks?
>>>
>>> Mark
>>>
>>>
>>> -----Original Message-----
>>> From: tech-talk-bounces@aps.anl.gov [mailto:tech-talk-bounces@aps.anl.gov] On Behalf Of Michael Huth
>>> Sent: Tuesday, June 06, 2017 1:15 PM
>>> To: tech-talk@aps.anl.gov
>>> Subject: Channel Access client sees only partial update.
>>>
>>> Hello,
>>>
>>> I'am quite new to Epics and ran into an issue where I could use a hint
>>> how to solve it:
>>>
>>> I have an IOC driver based on the area detector driver that should be
>>> extended for the transfer of a large data set from another source.
>>>
>>> So I setup a Record for it like this:
>>> record(waveform, "$(P)$(R)Data")
>>> {
>>>     field(PINI, "0")
>>>     field(DTYP, "asynInt8ArrayIn")
>>>     field(INP,  "@asyn($(PORT),$(ADDR),$(TIMEOUT))DATA")
>>>     field(FTVL, "CHAR")
>>>     field(NELM, "$(SIZE_DATA_BLOCK)")
>>>     field(SCAN, "I/O Intr")
>>> }
>>>
>>> In the main thread of the IOC I split the large data set into smaller
>>> blocks and have a loop that calls
>>>
>>> doCallbacksInt8Array(blockPtr , block_size, Data, 0);
>>>
>>> for each block to transfer the blocks to the data base.
>>>
>>> In a second process a channel access client is subscribed with
>>> ca_create_subscription to 'DATA'.
>>>
>>> The issue is that the client receives only the last block from each loop
>>> of the IOC driver thread.
>>>
>>> I guess I have to wait somehow until the database processing has
>>> finished after each block?!?
>>>
>>> Best regards,
>>> Michael Huth
>>>

-- 
() byte physics
    Dr. Michael Huth
    Software-Developer    

Company CEO: Thomas Braun
Address:     Schwarzastraße 9, 12055 Berlin, Germany
Web:         www.byte-physics.de
Telephone:   +49 (0)30/52 68 23 22
Fax:         +49 (0)30/52 68 43 26
USt-IdNr:    DE276717536