logmessage 10ms delay with -nodesktop

[jsdpag]

start_arcade.bat opens Matlab with the -nodesktop flag.

This seems to force all printing/logging operations to run in the same thread of execution as the Core process. Consequently, a substantial 10ms delay is imposed any time that something is printed to the Command Window. This delay is mostly eliminated, or at least reduced by an order of magnitude, if the -nodesktop flag is removed. Then, Matlab opens with a standard desktop that runs on a separate thread.

The plot above shows times that were deduced using the TDT RZ2 to record event markers generated before and after a call to logmessage. This was repeated 1000 times for each separate condition (each histogram has N=1000). The blue data shows the distribution of logmessage delays with the -nodesktop flag. The 'full desktop' data in red shows how the delay is reduced by a factor of 10, when the -nodesktop flag is removed. The yellow 'baseline' data shows the sub-millisecond delay between subsequent event markers without any call to logmessage.

Potential solutions include:

• Remove '-nodesktop' from start_arcade.bat.
• Have an existing ARCADE process e.g. daqserver handle message printing and logging.
• Build a new server that receives all log messages, echoes them to a command prompt window, and logs them into a .txt log file in the appropriate session directory. In this scenario, a normal process priorities can be assigned, while others receive a high process priority during trials.

[joschaschmiedt]

Interesting finding that is not entirely surprising to me. logmessage was not intended for real experiments but mostly for debugging and developing trial scripts. It is therefore also mostly used to write startup messages into the (error) logfiles, which are on purpose not saved with the behavioral data. The timing critical event data is saved in binary format using the the EventServer and only written to disk during the inter trial period (https://github.com/esi-neuroscience/ARCADE/blob/master/arcade/Core/SGLSessionArc.m#L183).

What kind of messages in addition to eventmarkers are you looking for? If you're looking for arbitrary text messages, I'd recommend using a buffered system that writes the text log to disk during the ITI, similar to the event markers.

Removing -nodesktop is an option, but will increase the startup times and has not really been tested thoroughly.

[jsdpag]

That's useful background info, thanks!

What ends up happening is that logmessage (or just fprintf) is used in the onEntry/onExit functions in order to give run-time, human readable feedback to the experimenter. This way, the human can see how the trial is progressing. This is something that I and yfcc like to do.

Writes to disk should occur between trials, as you say. But something that echoes messages during a trial without affecting trial latencies is, I think, a very useful tool for monitoring an experiment in progress.

I guess that writes to a Windows pipe is fast, otherwise you wouldn't use them to zap commands to other servers. I imagine that one could follow the same core<>pipe<>server arrangement. Core writes a string of bytes in UTC-16 with a terminating null character. The server reads in new bytes, delimits separate messages by the null char; each message is printed to a command prompt and also buffered for writing after the trial.

ps - I'm glad that you noticed that, Joscha. I am planning to blast little trial headers in UTF-16 from the task script as a string of event markers, for an additional and human-readable layer of redundant information in the TDT files.

[jsdpag]

I just realized that EventServer.writeEvents() is not called at the end of the trial but at the end of the session. This is a bug, but will only be a problem if you have so many eventmarkers during a session that you're running out of memory.

Actually, I think that we're fine. The events are also written after each trial, here.

[joschaschmiedt]

I guess that writes to a Windows pipe is fast, otherwise you wouldn't use them to zap commands to other servers. I imagine that one could follow the same core<>pipe<>server arrangement. Core writes a string of bytes in UTC-16 with a terminating null character. The server reads in new bytes, delimits separate messages by the null char; each message is printed to a command prompt and also buffered for writing after the trial.

I think this should probably work well, if your messages are not terribly long. For monitoring the progress of a session/trial the ControlScreen was the intended tool, which anyway needs a complete rewrite for "modern" MATLAB, or could be re-implemented in a different programming language. Incorporating a pipe for log messages could be a part of that rewrite.

[jsdpag]

Ja, I just show a ms-resolution time stamp and state name. Just one or two dozen bytes at a time. Reworking the Control Screen would be quite a big job. In the meantime, I guess the best solution is to run without -nodesktop and simply avoid printing messages at critical points in the trial ...

[jsdpag]

So, I wrote a very simple program that echoes input to a command prompt and, optionally, also to a text file located in the session's directory. There is a Matlab interface, similar to existing *Server.m interfaces. I haven't properly tested the timing yet, with DAQ event markers and so on. But preliminary tests show that write times, at least, are below 100 microseconds. In use, the EchoServer.exe program consumes a trivial amount of CPU and memory.

yfcc, would this be useful for you?

[jsdpag]

Greetings. I've tested out the latency by recording DAQ event times on the TDT system. There is usually, but not always, sub-millisecond latency in piping messages to the EchoServer:

Note, yfcc pointed out the flaw in my method. The sequence of events is onExit event marker, onEntry send message, onEntry event marker. This should have been done all in the onEntry. So, if you subtract the baseline from the other data then you get the true latencies. I just kept is the same as before so that the data would be directly comparable.

[yfcc]

Hi, this topic is too complex for me, so it took me some time to understand what is actually being discussed 😅 Anyway, here are my thoughts:

1. I agree with @jsdpag that monitoring trial processing through human-readable text strings is important
2. Such information doesn't need to be accurate in time, but should not interfere with the trial progressing
3. Currently (at least in 2.5.x), the delay caused by logmessage or frprintf in onEntry functions doesn't interfere with the trial progressing as long as the state duration is longer than the delay caused. This is because State.startTic = tic is executed before the entry functions (please let me know if this is correct....)
4. This is not true for very short states (example use cases could be gaze-contingent tasks)
5. I agree with @joschaschmiedt that ultimately having such functionality integrated with the control screen seems to be the way to go
6. @jsdpag I am very interested in your EchoServer! I don't want to change the task environment for the current task because I want to have the same environment for both monkeys but I do want to upgrade the set-up in the next experiment.

[jsdpag]

I'd generally agree with your points 3 and 4. The main issue, to me, is that we assume a negligible execution time in the onEntry and onExit functions. Currently, logmessage violates this assumption. Fiddling with GUIs is very time consuming. The EchoServer performs pretty well and it's very simple.

You can have multiple versions of ARCADE that live on the same system, so long as your shortcuts to the different copies of start_arcade.bat are appropriately labelled. So you could park my fork into its own C:\Toolbox folder, assuming you want to try EchoServer out. Then, it's a simple matter of Find/Replace "logmessage" with "EchoServer.Write"; albeit, it is necessary to provide a time stamp yourself, unless you simply re-write the local copy of logmessage to be:

function logmessage(message) EchoServer.Write( sprintf('%s %s\n',datestr(now,'HH:MM:SS'), message) ); end