Gaps in Log data accompanied by screen flash - Priority 2

[taylorlm88]

Summary: Identify and fix cause for spontaneous all-off.

Description: Occasionally there is a flash on the arena screen (flash meaning the LEDs turn off for about ~20 ms). The log of this data then shows an accompanying ~20 ms gap in all data, including timestamps. This happens in any context, whether a trial is being run in a particular mode or whether the screens are just running an all-on command. We have been unable to recreate any particular circumstance in which this happens. Running the same code on different days will result in different frequency, but it does inevitably happen on occasion.

[floesche]

Maybe the delay is a short version of the issue #57, although there the "all on" command is delayed by seconds.

[floesche]

Based on the suggestion received via email, the following code was used for testing:

function gapsInLogXLSX(testCase)
    testCase.panelsController.setRootDirectory("C:\matlabroot\G4");
    testCase.panelsController.setControlMode(1);
    rsps = [];
    runTime = [];
    seqTime = [];            
    for ii=1:400
        testCase.panelsController.startLog()        
        testCase.panelsController.setPatternID(ii);
        testCase.panelsController.setPatternFunctionID(ii);
        testCase.panelsController.setPositionX(ii);
        startTime = tic;
        rsp = testCase.panelsController.startDisplay(23);
        seqComplete = toc(startTime);
        rsps = [rsps; rsp];
        runTime = [runTime; 23];
        seqTime = [seqTime; seqComplete];
        testCase.panelsController.stopLog();
    end
    T = table(rsps, runTime, seqTime);
    writetable(T, "gapsInLog.xlsx", "Sheet", "gaps")
end

With G4 Host version 237 the following metrics were produced:

Threshold	Fails run 1	Fails run 2	Fails run 3
0.02s	1%	1%	1%
0.01s	1.5%	1%	1%
0.008s	2.75%	1.75%	1.25%
0.005s	40.5%	34.75%	26.75%

[floesche]

G4 Host version 239 was suggested as a solution to this issue. Similar metrics for this version looks like this:

Threshold	Fails run 1	Fails run 3	Fails run 5
0.02s	1%	0.25%	0%
0.01s	1.5%	1%	0.25 %
0.008s	2%	1.75%	2%
0.005s	29.5%	40%	41%

After the first iteration of the test the above summary suggests that there are roughly the same amount of issues happening, so version v239 doesn't seem to fix the issue.

[floesche]

Looking into the issue a bit more in depth:

The gapsInLog.xlsx file generated from the script above can be used to identify the trials where the gaps occur. For example, the attached file shows a slowed down response for the 396th trial of around 2,319s (compared to the median of around 2.304).

I then looked into the TDMS-log files of that trial, specifically the *_Frame_Time.tdms. There I calculated the difference between two successive frames and plotted the value. In general, a difference of 2000µs is expected (for 500Hz FPS), but in this specific example the frame takes 18000µs.

In other cases of the same test I have seen gaps as big s 50000µs

...or 42000µs

Since the total number of trials above the threshold hasn't changed between version 237 and 239, the assumption is that v239 doesn't fix the issue.

[floesche]

For the tests before I had used a wrong combination of pattern and arena configuration (4x12 pattern, 3x12 arena).

Configured correctly, the issue seems to become less frequent on my setup. I ran 3 full experiments with v239 and only in one of them I found the error using the same strategy (inside 05-03-2022_15-03-43-46_Frame_Time.tdms and 05-03-2022_15-03-57-29_Frame_Time.tdms of gapsInLog-v239-test9.zip ):

and

[floesche]

After updating the G4 Host to v240, I ran two tests, both produced the same type of errors.

For gapsInLog-v240-test1 one example for an error is inside 05-12-2022_15-03-31-16_Frame_Time.tdms around the timestamp 200332765.

For gapsInLog-v240-test2 there are 9 errors within 28 frames (timestamp 50192333 to 50270332) in 05-12-2022_17-05-28-35_Frame_Time.tdms.

[floesche]

Response via email:

Looking at the first set of v240 data, it showed an error interval of 108-109 runs again and I also didn't see any dequeue error. I ran the test 7 times (2800 total scans) on my PC without an issue so this is difficult to debug. I have to come up with some more debug utilities to help me isolate this issue.

[floesche]

Via email:

Can you run this tester for about an hour or so whenever you have some time and take a screenshot of the front panel at the end?

[floesche]

50 minutes after starting the bandwidth tester:

70 hours after starting the bandwidth tester:

[floesche]

response via email:

It is a bit concerning that you are getting errors with the tester. The tester is allocating a buffer the size of 3 frames worth of data and the host is filling in another frame worth of data whenever there is enough space available. The FPGA is pulling out 1 frame worth of data every 2 ms. So on 3 separate occasions, there was not enough data in the DMA for the FPGA to pull out. I wonder if there is something that is interrupting the DMA transfer occasionally. I could try making the buffer larger to mitigate these interruptions, but the trade off will be longer latency between new patterns (shouldn't result in blank frames).

[floesche]

if this happens only 3 times during a 66 hour interval, then we can live with the problem.

If it happens several times during a 20min experiment (as it does for the test scripts), then this would ruin a lot of valuable experiments.

Blank frames (or even delayed frames) are not an option for our experiments, they ruin data as well. For an increasing number of our experiment we are using electrophysiology and rely on continuous delivery of stimuli -- any small deviation from the 2ms frame length might look like a false signal in our measurements. I just wanted to give you this as an explanation why we are so persistent on getting this issue fixed now -- or at least understand why we are seeing them on some of our setups so we can avoid the same problem on others.