Testing PsychoPy event.waitKeys() Event Timing

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!

Share:

Testing round trip USB Serial latency using Python

One important consideration when using a 1000 Hz USB Serial device interface is the delay from when a Serial message is sent to the device to the time when the Serial reply is received by the program. We call this the round trip, or end to end, USB Serial latency of the device.

Here is a simple Python script that tests the round trip USB Serial latency of the first detected MilliKey or USB2TTL8 device.

This example uses a fixed Serial port address that needs to be manually changed to the correct Serial port of the device being tested. For an example of how to programatically detect your LabHackers’ device serial port from within Python checkout this post.

#!/usr/bin/env python
# -*- coding: utf-8 -*-
from __future__ import division, print_function

import serial
import numpy
from timeit import default_timer as getTime

SERIAL_PORT = 'COM138'
ITERATION_COUNT = 10000

try:
    sconn = serial.Serial(SERIAL_PORT, baudrate=128000, timeout=0.1)
except serial.SerialException as e:
    print("Check SERIAL_PORT variable is correct for device being tested.")
    raise e
    
#clear anything in serial rx
while sconn.readline():
    pass

# Test time it takes to send a serial message to the labhackers device
# and receive the serial reply.
results = numpy.zeros(ITERATION_COUNT, dtype=numpy.float64)
for i in range(ITERATION_COUNT):
    tx_time = getTime()
    sconn.write(b"PING\n")
    r = sconn.readline()
    rx_time = getTime()
    if r:
        results[i] = rx_time-tx_time
    else:
        raise RuntimeError("Serial RX Timeout.")

sconn.close()

# Convert times to msec.
results = results * 1000.0

print("LabHackers' USB Serial Rx - Tx Latency 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()))

Here is the output from the script when run on Windows, Linux and macOS, showing that the average round trip USB serial delay of a LabHackers’ device is well under 1 msec on all operating systems.

Windows 10

Run using PsychoPy 3.0.5 Coder IDE

LabHackers' USB Serial Rx - Tx Latency Stats
    Count: (10000,)
    Average: 0.391 msec
    Median: 0.379 msec
    Min: 0.352 msec
    Max: 1.840 msec
    Stdev: 0.055 msec

Linux (Mint 18.3)

LabHackers' USB Serial Rx - Tx Latency Stats
	Count: (10000,)
	Average: 0.320 msec
	Median: 0.313 msec
	Min: 0.253 msec
	Max: 0.583 msec
	Stdev: 0.026 msec
	

macOS 10.13.6

Run using PsychoPy 3.0.5 Coder IDE

LabHackers’ USB Serial Rx – Tx Latency Stats
Count: (10000,)
Average: 0.708 msec
Median: 0.719 msec
Min: 0.559 msec
Max: 1.501 msec
Stdev: 0.059 msec

Happy Hacking!

Share:

Detecting LabHackers’ Serial port addresses using Python

LabHackers’ MilliKey and USB2TTL8 devices have a USB Serial interface that is assigned a unique address by the operating system the first time the device is connected to a computer. The LabHackers’ Device Manager application can be used to view the serial port address assigned to a device.

However, the same LabHackers’ device will likely be assigned a different serial port address when it is connected to a different computer, so it is also useful to be able to identify LabHackers’ device serial port addresses from within your Python script.

Finding available Serial ports

If we want to connect to a LabHackers’ device USB Serial interface, but do not know the device’s serial port address, the first thing we need to do is find it.

Lets start by finding the serial port address for all serial devices connected to the computer.

import serial
import os

def get_serial_ports():
    """
    Return list of serial port addresses that have be openned.
    """
    if os.name == 'nt':  # Windows
        available = []
        for i in range(1, 512):
            try:
                sport = 'COM%d'%(i)
                s = serial.Serial(sport, baudrate=128000)
                available.append(sport)
                s.close()
            except (serial.SerialException, ValueError):
                pass
        return available
    else:  # macOS and Linux
        from serial.tools import list_ports
        return [port[0] for port in list_ports.comports()]

get_serial_ports() returns a list of all serial port addresses on the computer that have a device connected to them. For example:

serial_ports = get_serial_ports()
print(serial_ports)

run on a Windows computer with two connected serial ports, will return something like:

 ['COM2', 'COM9']

Note: get_serial_ports() returns all the serial devices connected to the computer.

Detecting LabHackers’ device Serial ports

Next we need to find which, if any, of the serial addresses are connected to a LabHackers’ MilliKey or USB2TTL8 device. Building on get_serial_ports() , we can get a list of the LabHackers’ ports by checking the responds of each serial port when “PING\n” is sent.

 def get_labhackers_ports():
    """
    Return list of connected LabHackers' device serial port addresses.
    """
    devices = []
    for p in get_serial_ports():
        s = serial.Serial(p, baudrate=128000, timeout=0.1)
        s.write(b"PING\n")
        rx = s.readline()
        if rx:
            rx = str(rx)
            if rx.find('MilliKey')>=0 or rx.find('USB2TTL8')>=0:
                devices.append(p)
        s.close()
    return devices

For example:

labhacker_ports = get_labhackers_ports()
print(labhacker_ports)

run on a Windows computer with one LabHackers’ device connected will return one serial port address:

['COM9']

Putting it together

Here is a complete version of the code.

#!/usr/bin/env python
# -*- coding: utf-8 -*-
from __future__ import print_function

import serial
import os

def get_serial_ports():
    """
    Return list of serial port addresses that have be openned.
    """
    if os.name == 'nt':  # Windows
        available = []
        for i in range(1, 512):
            try:
                sport = 'COM%d'%(i)
                s = serial.Serial(sport, baudrate=128000)
                available.append(sport)
                s.close()
            except (serial.SerialException, ValueError):
                pass
        return available
    else:  # macOS and Linux
        from serial.tools import list_ports
        return [port[0] for port in list_ports.comports()]

def get_labhackers_ports():
    """
    Return list of connected LabHackers' device serial port addresses.
    """
    devices = []
    for p in get_serial_ports():
        s = serial.Serial(p, baudrate=128000, timeout=0.1)
        s.write(b"PING\n")
        rx = s.readline()
        if rx:
            rx = str(rx)
            if rx.find('MilliKey')>=0 or rx.find('USB2TTL8')>=0:
                devices.append(p)
        s.close()
    return devices

if __name__ == '__main__':
    print(get_labhackers_ports())

Happy Hacking!

Share: