Testing PsychoPy event.waitKeys() Event Timing

Originally posted on February 27, 2019.

As discussed in my last post, the LabHackers’ MilliKey button box includes the ability to generate 1000 Hz USB keyboard events after receiving a KGEN serial command. (BTW, the USB2TTL8 also supports the KGEN command.)

One of the main uses of the KGEN command is to test keyboard event timing from within your experiment software without the need to use extra external hardware. In this post we look at how to test the time stamping accuracy of the PsychoPy event.waitKeys() function using KGEN.

Why test?

You might be wondering why, given the MilliKey is a 1000 Hz response box that generates keyboard events with 1 msec average latency, it is important to be able to test keyboard event timing from within your experiment software? Why can’t we just subtract one msec from key press time stamps and assume everything is OK? Two reasons:

  1. 1000 Hz USB HID Keyboard latency can be influenced by the operating system and other USB hardware connected to the computer.
  2. Keyboard events are time stamped by the experiment software being used, not the response box hardware itself.

Therefore it is not safe to rely solely on the device specifications; timing really should be tested and verified within the experiment software being used.

Python Example

#!/usr/bin/env python
# -*- coding: utf-8 -*-
"""
IMPORTANT: Set the mK_serial_port variable below to the correct
           serial port string for the MilliKey to be tested.

Example of testing the latency of MilliKey keyboard events and event time 
stamping accuracy when using core.waitKeys() within a PsychoPy script.

While the demo runs, keyboard events are generated by the
MilliKey device based on serial commands sent from the script.

**DO NOT PRESS ANY KEYS OR MILLIKEY BUTTONS DURING THE TEST.**
"""
from __future__ import absolute_import, division, print_function

from psychopy import visual, event, core
import serial
import string
import numpy

# Serial Port of MilliKey.
mK_serial_port = 'COM138'

# Number of keyboard events to generate.
kgen_count = 100

# min, max msec duration for generated keypresses.
min_dur, max_dur = 175,  300

# Usec MilliKey will wait before issuing the requested key press event.
delay_evt_usec = 5000

possible_kgen_chars = string.ascii_lowercase + string.digits
results = numpy.zeros(kgen_count, dtype=numpy.float64)
mk_sconn = serial.Serial(mK_serial_port, baudrate=128000, timeout=0.1)

win = visual.Window([600, 400])
msg = visual.TextStim(win, text='Creating Key Press: [] (duration of {} msec)')
msg.draw()
win.flip()

evt_delay_sec = delay_evt_usec/1000.0/1000.0
kb_presses = ['']
count = 0
run = True
txt1 = "Generating Key Press: [{}] (duration of {} msec)\n{} of {} events."
while run is True and count < kgen_count:
    kchar = possible_kgen_chars[count % (len(possible_kgen_chars))]
    press_duration = int(numpy.random.randint(min_dur, max_dur))
    msg.setText(txt1.format(kchar, press_duration, count+1, kgen_count))
    msg.draw()
    win.flip()
    kgen_cmd = "KGEN {} {} {}\n".format(kchar,
                                            press_duration,
                                            delay_evt_usec).encode()
    mk_sconn.write(kgen_cmd)
    stime = core.getTime()+evt_delay_sec
    kb_presses = event.waitKeys(maxWait=1.0)
    ktime = core.getTime()
    if not kb_presses:
        raise RuntimeError("KGEN Timeout Error: No Key Press Event Detected.")
    for kbp in kb_presses:
        if kbp in ['escape', 'esc']:
            run = False
            break
    if run is False:
        continue
    kpress = kb_presses[0]
    if kchar == kpress:
        results[count] = ktime-stime
        core.wait((press_duration/1000.0)*1.2)
        count += 1
    else:
        txt = "Keyboard Key != Key Press Issued ({} vs {}). "
        txt += "Was a keyboard key or MilliKey button pressed during the test?"
        raise RuntimeError(txt.format(kchar, kpress))

mk_sconn.close()
win.close()

# Convert times to msec.
results = results[:count] * 1000.0

print("MilliKey Keyboard Press Event Delay (Timestamp Accuracy) Stats")
print("\tCount: {}".format(results.shape))
print("\tAverage: {:.3f} msec".format(results.mean()))
print("\tMedian: {:.3f} msec".format(numpy.median(results)))
print("\tMin: {:.3f} msec".format(results.min()))
print("\tMax: {:.3f} msec".format(results.max()))
print("\tStdev: {:.3f} msec".format(results.std()))

core.quit()

Test Results

Windows 10

Running PsychoPy 3.0.5.

MilliKey Keyboard Press Event Delay (Timestamp Accuracy) Stats
    Count: (100,)
    Average: 1.012 msec
    Median: 0.982 msec
    Min: 0.509 msec
    Max: 1.633 msec
    Stdev: 0.303 msec

Linux (Mint 18.3)

 MilliKey Keyboard Press Event Delay (Timestamp Accuracy) Stats
	Count: (100,)
	Average: 0.899 msec
	Median: 0.898 msec
	Min: 0.350 msec
	Max: 1.499 msec
	Stdev: 0.309 msec

When a PsychoPy experiment script, running on Windows or Linux, can simply wait for MilliKey keyboard events, there is an average difference of ~ 1.0 msec between when the KGEN command is sent by the script and when the keyboard event is received by PsychoPy. If we subtract the time it takes to send a KGEN command, which is 0.3 msec on average, then the average MilliKey key press latency in this test would be about 1.0 – 0.3 = 0.7 msec.

macOS 10.13.6

Running PsychoPy 3.0.5.

MilliKey Keyboard Press Event Delay (Timestamp Accuracy) Stats
Count: (100,)
Average: 4.755 msec
Median: 4.608 msec
Min: 3.679 msec
Max: 18.594 msec
Stdev: 1.445 msec

The average keyboard delay from the same script running on macOS is longer and also more variable than other operating systems tested. It seems, for example, that the first keyboard event received after the python interpreter starts is delayed by an extra 10 or more milliseconds. Results with first event removed:

 MilliKey Keyboard Press Event Delay (Timestamp Accuracy) Stats
    Count: (99,)
    Average: 4.615 msec
    Median: 4.597 msec
    Min: 3.679 msec
    Max: 5.939 msec
    Stdev: 0.394 msec

Remember that the USB serial latency on macOS is under 1 msec, as would be expected, so the additional delay in receiving keyboard events seems to be specific to processing done by the macOS operating system or the underlying keyboard event handling libraries used.

This pattern of results does not seem to be specific to PsychoPy event.waitKeys(). I have also tested using pygame, glfw, pyqt4 and pyqt5 and all show a similar pattern of results across operating systems.

If you have a LabHackers device, please let us know if you your results are consistent with this or not. For that matter, if you have done actual keyboard event delay testing using any method on macOS, it would be great to see the results.

Notes

It is important to recognize that using KGEN to test keyboard event timing has the following caveats:

  1. Timing results can only be generalized to other 1000 Hz USB HID Keyboard hardware that has a 0 millisecond debounce time.
  2. Given the sub millisecond jitter that will occur when sending each serial KGEN command, test results should be considered accurate to within 0.5 msec, even though the resolution of the timing is much greater.

Even with these in mind, we think KGEN is pretty useful and hope you do too.

Happy Hacking!