Response Times in Log Files, Key Press vs. Release, and EXP log messages

[rkempner]

Hello,

I am debugging my log files to ensure that reaction times came in alright, and I have the following three questions that I ask in order to understand the log file information…

(1) In a log file, are the times of the “DATA Keydown” the exact time that the keyboard sends the information, or is that the time we call getKeys once a frame flip?

(2) Further, does the response time , in log as well as in the csv file, record the time of the keypress onset or the time of the key release?

(3) Does the EXP logs contain the approx. time of the next frame flip or the time that the line was called?

[thomas_pronk]

Hey again!

1. It’s the time that the event handler of the key gets called. See this line. I know KeyboardEvents themselves also have a timestamp, but as far as I know, that one isn’t more accurate. See my “Mental Chronometry in the Pocket” paper and its online appendix.
2. It’s the keydown (so when the key is pressed)
3. Not totally sure about this one, but quite sure it’s the moment the requestAnimationFrame callback is called. So that’s somewhere before the actual flip. Again it doesn’t really matter which timestamp you pick, see paper and online appendix again

Best, Thomas

[rkempner]

I do want to follow up about point (3)

Investigating the time stamps in the log file, it seems that the EXP logs are all 16 milliseconds (one frame duration) away from eachother. I took this as evidence that it is the time after the actual flip, but I was not sure how to further verify that. How can I confirm or reject for certain whether this is the time of the actual flip, similar to “win.logOnFlip(level=logging.EXP, msg=‘sent on actual flip’)” in the builder. This value has now become an important predictor in my analysis, so I want to be certain. Of course, I acknowledge that it would only be approx. the time of the flip due to the middle man issue of the browser in online studies.

Thanks for your help as always @thomas_pronk

[thomas_pronk]

Hey again,

As far as I know, you can’t establish this, since there is no way to synchronize timestamps logged in JS with what’s happening on the screen. In my “Mental Chronometry in the Pocket” paper, I tried some stastitical approaches to figure it out, by assuming timestamps logged before flip N are an accurate estimation of the time that flip N-1 occurs, but no love. Basically, whatever timestamps roll out of it just aren’t accurate enough to make such assessments. OSF | MCitP Supplement.pdf

How come you need it with such precision?

Cheers T

[rkempner]

I’m looking for a rough approximation of when the stimulus of the routine first appears. This serves to verify the reaction times are coming in as intended, and also I’m trying to use this as an easy way to get a rough approximation of the RSI.

When I assume that the EXP timestamps are roughly when the frame flips and subtracting that time from the logged timestamp of the keypress in my reaction time experiment, I get values almost identical to the rts recorded in the output csv. Note that I am using sync to screen so I want the keyboard start time to be approx. when the stimulus first appears. I’m having a hard time explaining how this could be the case if the EXP timestamps are much different than the first frame flip after a stimulus is called to be drawn.

[rkempner]

Digging through the scheduler code, which I can not understand well as I’m a beginner in Javascript.

It appears that requestAnimationFrame comes after .render() in the .start() function of the Scheduler. Could this have something to do with the behavior I’m getting? See below for source code:

	/**
	 * Start this scheduler.
	 *
	 * <p>Note: tasks are run after each animation frame.</p>
	 *
	 * @name module:util.Scheduler#start
	 * @public
	 */
	start()
	{
		const self = this;
		let update = () =>
		{
			// stop the animation if need be:
			if (self._stopAtNextUpdate)
			{
				self._status = Scheduler.Status.STOPPED;
				return;
			}

			// self._psychoJS.window._writeLogOnFlip();

			// run the next scheduled tasks until a scene render is requested:
			const state = self._runNextTasks();
			if (state === Scheduler.Event.QUIT)
			{
				self._status = Scheduler.Status.STOPPED;
				return;
			}

			// render the scene in the window:
			self._psychoJS.window.render();

			// request a new frame:
			requestAnimationFrame(update);
		};

		// start the animation:
		requestAnimationFrame(update);
	}

[thomas_pronk]

Having some trouble saying something sensible about your second-last post, but I can about your last post. If I’d rewrite this in an example, that might clear things up. It goes a bit like this:

// Define update function
update = () => {
  // Draw stuff
  requestAnimationFrame(update);
}
requestAnimationFrame(update);

What happens here is the following:

• update isn’t called immediately. It’s scheduled to be called at the next opportune moment via rAF (requestAnimationFrame)
• At the end of the update function, the next call is scheduled, again via rAF

[rkempner]

Thanks, I will make a more clear detailed example.

Now, my goal is to use the log file to obtain the reaction time of a participant on a trial, assuming that we want the reaction time from approximately the onset of the stimuli in the trial, and I marked the “Sync to Screen Timing” to ensure that is what the program does.

We have this in the .csv output and here are the reaction times in milliseconds for the first three trials based on the csv: 587.175, 464.94, 286.35000000000000.

Now, I will go into the log file and find that we can get almost the exact same reaction time values by using the log outputs. Here is an example of a snippet of the log file for the first trial, with some marked code denoting when we call the screen to render:

|132.98521499999333|EXP|monster2_pre: size = [0.4,0.4]|
|---|---|---|
|132.98521499999333|EXP|keyboard_im_pre: autoDraw = true|
|132.98521499999333|EXP|monster3_pre: autoDraw = true|
|132.98521499999333|EXP|monster4_pre: autoDraw = true|
|132.98521499999333|EXP|monster1_pre: autoDraw = true|
|132.98521499999333|EXP|monster2_pre: autoDraw = true|
|132.98521499999333|EXP|monster2_pre: size = [0.42511363636363636,0.42511363636363636]|
|132.98521499999333|EXP|fake_text_to_keep_images_on_screen: autoDraw = true|

return Scheduler.Event.FLIP_REPEAT; is called after the above commands. All of the above commands took place in the RoutineBegin and RoutineEachFrame code before we render the screen. 

|133.00683000002755|EXP|monster2_pre: size = [0.4502272727272727,0.4502272727272727]|
|133.01615500001935|EXP|monster2_pre: size = [0.47534090909090904,0.47534090909090904]|
|133.03105500002857|EXP|monster2_pre: size = [0.5004545454545454,0.5004545454545454]|
|133.04909500002395|EXP|monster2_pre: size = [0.5255681818181818,0.5255681818181818]|
|133.06635000003735|EXP|monster2_pre: size = [0.5506818181818182,0.5506818181818182]|
|133.08125500002643|EXP|monster2_pre: size = [0.5757954545454546,0.5757954545454546]|
|133.44989500002703|DATA|Keydown: f|
In this line right here^, the participant makes a keypress.

Using the above snippet of the log file for the first trial, I can recompute the reaction time by using the timestamp where the key is pressed and the EXP output lines of the function calls that were made right before render. Therefore, I substract the timestamp of this line, |133.44989500002703|DATA|Keydown: f| from this line, |132.98521499999333|EXP|fake_text_to_keep_images_on_screen: autoDraw = true|. The result is 587.015 ms, which is almost exactly what the csv computed.

Now, I will repeat this process for the second and third trial and I get 464.68 and 286.21 milliseconds respectively from the log file. These values are slightly smaller but almost identical to the output csv reaction times, suggesting that the timestamps at the EXP line of the log file are approx. the time right after the frame flip. Further, I used this to aproximate the RSI by taking the response timestamp of the previous trial and the timestamp from the line, |132.98521499999333|EXP|fake_text_to_keep_images_on_screen: autoDraw = true|, of the current trial.

Does that make more sense? I will try another way of explaining if not.

Thanks for your help!

[thomas_pronk]

You’re going deep :). OK, presently, I’m not that deep into these parts of PsychoJS itself, because until now I’ve mainly worked on automated end-to-end testing. I do know there are some plans to work a bit on timestamps, so what I’ll do is this: put your post in a internal list, keep my eyes out for timestamp-developments, and give a shout when I got better info.

[rkempner]

Indeed I am

Are there any developers on your team who worked specifically on this part of PsychoJS who might have some insights? If so, perhaps I can reach out to them.

This is probably a topic that would be important for the documentation about the log files, and will benefit the larger community, so we can understand what exactly the timestamps mean and make sure people are not using them improperly.

[rkempner]

Others are having this same confusion such as Computing RTs according to log file vs. csv file and About reproducing the reaction time from log file

[thomas_pronk]

It’s definitely important and something to sort out properly, with some nice docs etc. Guess it’s easily a day of work, probably more. Need to ensure one of the devs is off the hook (and in a nice focused quiet mood) so this can be produced. I did raise your post internally, but now I’m intentionally backing off so that they (or me) can do it on their own tempo

[rkempner]

Thanks!

Amazing to have yours and the other devs help!

[rkempner]

I have some solid evidence now that the log file EXP timestamps approximately mark the time of the next flip.

For each of 20 participants in a study in 600 trials each, I computed the reaction time using the log file and compared that to the reaction time in the csv file.

In the photo below, I plot (csv reaction time) - (log file computed reaction time) for each participant in all 600 trials. This is in milliseconds scale and the x-axis is limited -0.5 and 1, revealing that these times are extremely close.

Here is my interpretation: This means that the timestamp of the EXP denoting an update in the component before the first flip of the routine is very close to the time that the keyboard component time is reset after the frame flip, and therefore that the EXP timestamp is a close approximation of the frame flip time.

[rkempner]

hi @thomas_pronk, do you agree with my reasoning above?

Summary of reasoning: the fact that the log file allows me to almost exactly acquire the reaction times from the csv, must imply that the log file EXP timestamp at the beginning of a routine record approximately the first flip of routine, because that EXP timestamp is very close to when the keyboard component resets during the sync to screen.

Without digging through the javascript, this seems to be solid proof, but I am curious if we could think of another way in which this behavior could arise that contradicts my understanding.

[Adrian]

Hi @rkempner,

I’ve been having a similar issue to you in some of your posts regarding discrepancies between CSV computed reaction times and LOG computed reaction times. Did you end up finding the source of/solution to your issues?