Log actual time the pattern is displayed, as well as when the TCP commands are received - Priority 7

[taylorlm88]

Summary: Log display time as well as communication time.

Description: If possible, we would like to Log the exact time that a pattern appears on the screen. Right now we get the exact time of each TCP command, so we know when the 'start-display' was received. But the frame position data seems to indicate there is some lag time between the start-display command being received and the frame position indicating the new pattern is being displayed. It's hard to get a handle on how long this lag is exactly due to the way frame position is logged described in number 1. If we could, in addition, get information on when the start-display command actually takes effect and the pattern appears on the screen, it would be very helpful to us.

[floesche]

Issue #57 seems to be an extreme case for this -- commands are only executed many seconds after they are sent.

[achiusciotex]

This should already be in the latest builds. You can get the time received for a message in the base tdms file and the time the pattern is played out in the Frame_Time tdms file

[floesche]

The data is now in the TDMS files.

For my understanding, could you clarify the timing of events please?

Let me use one example of the gapsInLogXLSX function that we shared previously.

Within each loop, there are 6 commands sent to the G4 Host (here the full code within each loop, minor change compared to previously shared code):

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);
testCase.panelsController.stopLog();
rsps = [rsps; rsp];
runTime = [runTime; 23];
seqTime = [seqTime; seqComplete];

For the Command Received I get the following timings (last column added by me, difference of current Time to previous line):

Time	Command	Data	time diff
1419599480	Set Pattern ID	3A/1	NA
1419599480	Set Pattern Function ID	3A/1	0
1419601942	Set-Position X	3A/1	2462
1419601942	Start-Display	17/0	0
1421907925	Stop Log		2305983

For the same trial, the Pattern Position contains the following values (second column added by me):

Time	time diff
1419629800	NA
1419631801	2001
1419633800	1999
...	...
1421923801	2001
1421925800	1999
1421927800	2000

The difference between the timing of the first item in Pattern Position and the last item is 2298000, which is exactly what I'd expect for an experiment that is supposed to last 2300ms.

I don't fully understand the timing within Command Received, specifically why two commands are received at exactly the same ns, but the command that is on the next line in MATLAB take 2462ns. This might be addressed in issue #52, though.

In this current issue I would like to understand the difference between Command Received and Pattern Position. So the time difference between the Start-Display command and the first pattern is 27858ns (for other experiments this value is similar between 24000ns and 29000ns). Is my interpretation correct, it takes almost 28ms between sending a Start-Display and actually starting the display? (Which seems long but acceptable, especially in open-loop conditions. If it is a one-time initialization cost, then it is probably also OK for closed loop conditions.)

Secondly, the difference between the last pattern from the Pattern Position and the Stop-Display command in the _Command Received is -19875ns (for other experiments this values is similar between 18000ns and 20000ns), that means the Stop-Display command is sent 20ms before the last frame starts showing (22ms before it is finished). We know that the startDisplay command in the MATLAB code above receives the confirmation precisely at the right time (that was fixed in #59). It then does the toc line in MATLAB before sending a stopDisplay command.

Related to this I have three more related questions:

1. Do I understand it correctly that the start-display command sends the confirmation of being finished while the display itself is still displaying patterns for some more time?
2. At what time exactly does the Host send the confirmation for start-display? In this example 2300ms after start-display was received or 2300ms after having executed the start-display, which might take about 8000ns according to the delay of stop-display.
3. I am assuming all all other commands have similar delays between receiving the command and actually doing it. Is there a way to find out the actual timings of these delays?

[achiusciotex]

1. The "setPositionX" is only applicable to the "Stream Pattern Position".
2. The timing of the command timestamps may be off because of my attempt to optimize communication between the FPGA and Host. I tried to limit the querying of the FPGA, but that caused some inaccuracies in the command timestamps so I changed the querying of the FPGA back to the way it was originally done. I posted that build in Issue Provide command to add information to log file. - Priority 3 #52.
3. So the timing between the "Start-Display" and the first frame being displayed can vary depending on the buffer size. The larger the buffer, the longer it will take before the new frames appear on the display.
4. You are correct in your understanding that the "start-display" send a confirmation of being finished while the display itself is displaying for a little bit more time. The confirmation is sent when the last frame for a sequence is sent to the DMA. There could be a few frames still in the DMA depending on the buffer size. Making the buffer size smaller would allow for the display to update with less latency.