Overhead time on image acquisition

[kematusik]

The detector model I'm using is DW936A_BV, driver version 2.8.0, firmware ver. 14.136, SDK version 2.102.30034.0 and ADCore version 3.11.0. I am running the detector in full frame with 5MHz ADC speed. For a 1 s exposure, my "accumulate period" read back is 2.069s; from the Andor detector datasheet I'm expecting a frame rate of 0.953 fps or 1.049 s readout per frame which is not too far off the accumulate period overhead of 1.069s. When I do a callback on the acquire button and run the detector in single image mode, I see that my image acquisition time is more like 2.6s on a 1 s exposure, i.e. a 1.6 s overhead, and about 500 ms more than expected. Any insight as to why I have this overhead is appreciated, thanks.

[kematusik]

With the master branch, I am now getting 1.4 s overhead, as opposed to 1.6 s with R2-8, i.e. 200 ms improvement. Is this the best that I can hope for, or should I really be getting 1.069s overhead per image, which is the time that my "accumulate period" states?

[MarkRivers]

I hope others who are actively using this driver can comment. I don't really have a detector to test with.

What do you see if you use ImageMode=Multiple (=Andor Kinetic Series mode), i.e. what is the total time to collect 10 images with 1 second exposure?

[MarkRivers]

The driver will provide lots of information on what it is doing if you enable ASYN_TRACE_FLOW. If you enable that in your startup script we can probably figure out what is causing the delay.

[kematusik]

@MarkRivers - I un-commented the following lines in the st.cmd file:

asynSetTraceMask("$(PORT)",0,3)
asynSetTraceIOMask("$(PORT)",0,4)

and I'm attaching the output that looked to correspond to taking a 1s exposure in single image mode. When I take 10 x 1s images in multiple mode (full frame, 5 MHz), the cumulative time is 21.77 s, i.e. 2.177s per image, 1.177s overhead per image, as compared to 1.4s overhead per image when running in single mode.

Andor_AsynOutput.txt

[MarkRivers]

You did not enable ASYN_TRACE_FLOW, you enabled ASYN_TRACE_DEVICE which is not very useful. Please change those lines to:

asynSetTraceMask("$(PORT)",0,ERROR|FLOW)
asynSetTraceIOMask("$(PORT)",0,ESCAPE|HEX)

That will print ASYN_TRACE_ERROR and ASYN_TRACE_FLOW messages. It will print data in both ASCII with escape, and hex.

[kematusik]

@MarkRivers, thank you for the clarification. Attached is the output from taking a single 1s exposure.

Andor_AsynOutput.txt

[MarkRivers]

@kematusik I think this is pretty clear. Here are the important messages with timestamps

2022/02/15 10:24:41.286 andorCCD:writeInt32:, StartAcquisition()
2022/02/15 10:24:41.725 andorCCD:writeInt32:, Sending dataEvent to dataTask ...
2022/02/15 10:24:41.725 andorCCD:dataTask:, got data event
2022/02/15 10:24:41.725 andorCCD:statusTask: Got status event
2022/02/15 10:24:41.726 andorCCD:dataTask:, GetStatus returned 20072
2022/02/15 10:24:41.726 andorCCD:dataTask:, WaitForAcquisition().
2022/02/15 10:24:44.098 andorCCD:dataTask:, WaitForAcquisition has returned.

The driver called the SDK function StartAcquisition() at 41.286. That is this line in the driver.

ADAndor/andorApp/src/andorCCD.cpp

Line 679 in f4f28bd

checkStatus(StartAcquisition());

The next message is "Sending dataEvent" at 41.725. That is this line in the driver:

ADAndor/andorApp/src/andorCCD.cpp

Line 778 in f4f28bd

"%s:%s:, Sending dataEvent to dataTask ...\n",

There is no code being executed between those 2 lines that can take any significant time, which means that the call to StartAcquisition() actually took 0.439 seconds.

1 ms after the "Sending dataEvent" message is the WaitForAcquisition() message at 41.726. That is when the driver is waiting for the camera to be done. It is this line in the driver.

ADAndor/andorApp/src/andorCCD.cpp

Line 1596 in f4f28bd

checkStatus(WaitForAcquisition());

Note that the driver is not polling in a loop, it is just a single blocking call to WaitForAcquisition() in the SDK.

It gets done when the "WaitForAcquisition has returned" message is printed at 44.098. That means it was waiting for acquisition for 2.372 seconds. Since the acquisition time was 1.0 seconds, the readout overhead is 1.372 seconds.

So the total overhead is .439 second waiting for StartAcquisition() to return and 1.372 waiting for WaitForAcquisition() to return. That is a total of 1.811 seconds of overhead.

Your original message said you were seeing about 1.6 seconds of overhead, but these messages seem to show it is actually about 1.8 seconds. I think it is pretty clear that all of this overhead is in their SDK and not in the EPICS driver.

[kematusik]

@MarkRivers I reran the test a few times and verified that, on average, the time between StartAcquisition() and WaitForAcquisition has returned is about 1.6s, e.g.

2022/02/16 11:54:35.423 andorCCD:writeInt32:, StartAcquisition()
2022/02/16 11:54:35.630 andorCCD:writeInt32:, Sending dataEvent to dataTask ...
2022/02/16 11:54:35.630 andorCCD:dataTask:, got data event
2022/02/16 11:54:35.630 andorCCD:statusTask: Got status event
2022/02/16 11:54:35.630 andorCCD:dataTask:, GetStatus returned 20072
2022/02/16 11:54:35.630 andorCCD:dataTask:, WaitForAcquisition().
2022/02/16 11:54:38.011 andorCCD:dataTask:, WaitForAcquisition has returned.

I think that 1.811s of overhead was a byproduct of restarting the IOC and grabbing the first image; I've since found that sometimes the first acquired image after the IOC has been restarted can take ~200 ms longer to acquire. Interestingly, I still measure 1.4s when I do a callback on the Acquire PV; screenshot attached that shows a few elapsed times for a 1s exposure in single mode. Maybe the Acquire PV is toggled to 1 at the WaitForAcquisition() call? I'm closing this issue since you are right, it seems that the overhead is on the SDK's end. Thanks again for your help.

[MarkRivers]

Interestingly, I still measure 1.4s when I do a callback on the Acquire PV; screenshot attached that shows a few elapsed times for a 1s exposure in single mode. Maybe the Acquire PV is toggled to 1 at the WaitForAcquisition() call?

I think the 1.4s you are seeing is expected. Acquire has asynchronous device support, and so does its callback on changing to 1 only after the writeInt32() method returns, i.e. after the call to StartAcquisition() completes. That is 0.2 seconds after the Acquire PV was written to 1. So then it takes 2.4 seconds before it goes back to 0.