Provide command to add information to log file. - Priority 3

[taylorlm88]

Summary: Provide command to add information to log file.

Description: Provide an additional command that writes the provided information to the tdms log file. The information that needs logging has two parts and is 8bit + 64bit long. A suggested format for ‘log_data’ could be [0x09 0x47 CLASS NANO_SINCE_EPOCH]. CLASS would be a 1 byte, NANO_SINCE_EPOCH a int64_t data type.
The information can either be logged in the base TDMS file in a new group ‘timesync’ (in addition to ‘Treadmill’ and ‘Commands Received’) or in an additional file _SYNC.tdms. The information needs to be logged together with the usual ‘Time’ that is used in the other log structures.

[achiusciotex]

Just to clarify, the command would be 0x0A,0x47,CLASS,NANO_SINCE_EPOCH

[floesche]

That sounds good.

Inside the TDMS file, CLASS should be logged as a char (eg 0x00…0xFF or 0…255), NANO_SINCE_EPOCH as int64_t.

[floesche]

Currently, both CLASS and NANO_SINCE_EPOCH get logged inside Sync in a Data column but not in Command Received.

I see two solutions: either log the current format inside Commands Received or change the format inside Sync to having class and data in separate columns.

Secondly I noticed that the timing is unexpected: I try to log 4 consecutive numbers as quickly as possible, avoiding loops or anything else that might be slow. The next 4 consecutive numbers are from a new iteration of a loop.

Pseudocode (in reality I used pre-computed random numbers...):

for i = 1:20
    panelsController.sendSyncLog(1, i);
    panelsController.sendSyncLog(1, i+1);
    panelsController.sendSyncLog(1, i+2);
    panelsController.sendSyncLog(1, i+3);
end

When doing that, I see delays between the individual sync Log commands between 0 and 8.506 ms (screenshot of the first 20 or so logs):

How come this number fluctuates that much?

We want to synchronize external data to frames, but at this point the sync command might up to 5 frames off. Can this be reduced?

Would it ever be possible to get this command to have within-frame precision?

[achiusciotex]

I modified the querying of the FPGA variables to try to optimize the communication between the host and the FPGA, but this causes some delay on the timestamp updates. I can try doing the timestamp queries like I did previously to get a more accurate timestamp and then give you a new release.

[achiusciotex]

https://www.dropbox.com/s/o5um3q92rgor60c/G4%20Host%28Ver1-0-0-244%29.zip?dl=0

Build with update FPGA tick query and separation of Class and Data in its own columns.

[floesche]

The separation into class and data does not work well, the second class should be FF not F, the data should be 9223372036854775807. For single digit classes the separation seems to work well.

For the timing, I think this has gotten better. Nevertheless I still see some jitter. The following data shows the timing of a few commands that I send via this code inside a loop, with i and j being random integers.

testCase.panelsController.setPatternFunctionID(i);
testCase.panelsController.sendSyncLog(i, j);
testCase.panelsController.sendSyncLog(i, j+1);
testCase.panelsController.sendSyncLog(i, j+2);
testCase.panelsController.sendSyncLog(i, j+3);

The TDMS time column is the time of the individual command with reference to the Set Control Mode command. A value of 5904 means that this specific command was logged 5904ns after the Set Control Mode.

I also captured the network packets on the loopback device. The Network time column is the time after the set Control Mode packet was sent by MATLAB. A value of 9119 means, that the TCP/IP packet for this specific command was sent 9119ns after the packet for Set Control Mode was sent.

The Offset column is the difference between the TDMS time column and the Network time column. A value of 1064 means, that the network packet was 1064ns faster than the logging.

Most of the sync log commands seem to be logged 1ms (between 900ns and 1300ns) after the network package was sent, while some of the other commands are faster. In this example the Set pattern function ID command gets logged around 500ns (76ns ..580ns) after the network packet.

This seems to be a systematic difference between some of the commands -- this is unexpected to me. Can you explain where this difference comes from? What exactly is the time that is getting logged in the TDMS files?

[achiusciotex]

Release with the fix for class issue.
https://www.dropbox.com/s/8c09cdfddn3nq73/G4%20Host%28Ver1-0-0-245%29.zip?dl=0

So here is a simplified diagram of how the TCP loop works.
The loop is always going between reading data on the port to checking if any application messages have been received. Application messages are typically messages that are queued up to be sent back over to the TCP port (responses, treadmill data, etc.). I can see where there could be a little jitter when querying the FPGA for the timestamp from the Host application and bouncing back and forth between sending and receiving data. I also made a change to this build with the loop priority to see if it helps at all with the arena gap issue.

[floesche]

It seems, v244 introduces a new issue: The Stop Log command (0x01 0x40) introduces extremely long wait times. There seems to be a correlation with the length of the experiment that is being logged. In some of our observations it takes the stop log command 3 seconds to send the TCP response, for a 23 second trial it took roughly 23 seconds to finish stop log.

@achiusciotex : Can you see this on your side or do you need an explicit test case?