Strange timing issues with pyglet?

This has me completely stumped - I don’t know what I’m doing wrong. What I’m trying to do is:

  1. present an auditory prime (a single word) to the participant while the screen is blank;
  2. wait until the prime has finished playing
  3. present a visual target (a single word presented orthographically) which the participant has to read aloud
  4. measure their RT in the speech signal (which I record using psychopy.microphone)
    (I read somewhere that pyo tends to start recording before the actual microphone.record() call, so I also record the auditory prime and worry about finding the vocal RTs later, off-line. I don’t think this detail matters for my problem, though.)
    (5. While doing all this, I also record EEG activity, but that is tangential to the issue.)

Code is below (pardon any formatting issues). ‘prime’ and ‘ortho’ are strings representing the (auditory) prime and (visual) target, ‘snd’ is a psychopy.Sound object that I created earlier in the code.

    dur = snd.getDuration()
    write('+')
    win.flip()
    core.wait(1)
    win.flip()
    write(ortho)
    parallel.setData(11)
    mic.record(dur+2, filename='rec/'+str(ppn)+'_'+prime+'_'+ortho+'_'+str(rt.getTime())+'.wav', block=False)
    snd.play()
    core.wait(dur)
    win.flip()
    core.wait(2)
    parallel.setData(10)

The problem is in the core.wait(dur) between the snd.play() and the win.flip(). From my understanding, the above code should play the sound, wait until it has exactly finished playing, and then flip the window (revealing the orthographic target).
What I am seeing, however, is that it only waits about half as long as it should, meaning that the window is flipped while the sound is still playing. I am completely stumped by this - what am I missing?

EDIT: after some debugging, it looks like the issue is in pyglet; it looks like the problem is not core.wait() or snd.getDuration() as I originally suspected, but rather that the win.flip() is somehow ‘anticipated’ by pyglet (similarly to how pyo has been known to ‘anticipate’ microphone.record()?). Is that plausible? Strangely enough, it looks like I have found a workaround: sleep for an extra 0.5 seconds right before the call to win.flip() (but after other timing-dependent things).

Hi @LostLinguist, which version of PsychoPy are you using, and on which platform?

1.83.04 (will try on 1.84.1 tomorrow), on Windows 7 x64.

Yes, this is possibly fixed in 1.84. Good luck!

Unfortunately, 1.84.1 doesn’t work for me at all - when I start the experiment, I just get the dreaded ‘pythonw.exe has stopped working’. There is nothing useful in the console output.

Could you share your entire experimental code with us?

What makes you think pyglet is “anticipating” win.flip()? (I’ve no idea how that could happen). I’d have thought the most likely explanation is that the reported time from getDuration() doesn’t match - can you confirm that it is correct given your file?

I’m certainly concerned that 1.84.1 isn’t running your script. I’ve not heard anyone else having trouble. Do demos work for you in 1.84.1?

@richard: certainly; the experiment is here: experiment.py (21.3 KB). This file contains two tasks, but as the problem is only in the second task I’ve commented out the first one. You will need to create an empty folder named ‘rec’ and a folder named ‘res’ which contains all the sound resources used in the experiment; I have no problem sharing them with you, but since this is 600 wave files (and a movie, but that is part of the other task and is hence not necessary), please advise me on how I should provide them to you.

@Jon: yes, getDuration() was my very first suspect as well, so then I tried something like this (I don’t have that debug version of the script any more so I’m doing this from memory):

print "Duration is "+str(dur)
snd.play()
core.wait(dur)
print "Done waiting"
win.flip()

and I noticed that the “Done waiting” print was triggered after the window had been flipped! So PsychoPy appears to be waiting for the correct amount of time, but it looks like the pyglet thread (I’m assuming pyglet is running on a separate thread?) is simply doing its job prematurely. Also, the printed duration matches the duration of the file.

I am as stumped as you are, and it’s very likely that this is just PEBKAC, so let me apologize in advance for having alarmed you while the problem will probably turn out to have been me all along :wink:

W.r.t. 1.84.1 crashing: I’ve done some sleuthing and it looks like it doesn’t crash if I change this code:

ppn = ''
while True:
    write('ID: '+ppn)
    win.flip()
    k = event.waitKeys(keyList=['0','1','2','3','4','5','6','7','8','9','return'])[0]
    if k == 'return': break
    ppn += k

into a simple assignment: ppn = '5'. Additionally, the timing bug (worked around in the current script by the core.wait(0.5) in line 199 seems to have vanished under 1.84.1! And to answer your question: demos appear to work.

As I said, I really don’t understand any of this, so feel free to just file this under ‘weird things deemed specific to that one guy on the internet’. In any case, thank you very, very much for your time :blush:

The line

if k == 'return': break

will never evaluate to be True so break will never occur and you won’t exit this loop. k is a list of keys so you would need to do one of these to get your return value:

if 'return' in k: break

or

for key in k:
    if key == 'return': break

I’d normally call your k variables keys to remind myself that this is a list not a sinlge key

actually, k is a single key: the line

k = event.waitKeys(keyList=['0','1','2','3','4','5','6','7','8','9','return'])[0]

takes the 0'th result of the event.waitKeys() call, so the variable k only contains the very first of the keys pressed.

1 Like

Ah, sorry, the [0] was off the edge of the screen so I didn’t realise you’d extracted the first key. Apols. :wink:

Anyway, glad things are working for you now, even if they remain mysterious (to me as well)!

Well, they’re only working on PsychoPy 1.83.0 with the kludgy workaround of sleeping for .5 seconds after issuing the win.flip() call, so while things are indeed working, I’d like to understand the problem better, because this doesn’t really sit right with me.
Let’s assume that the win.flip() thing is an obscure bug with 1.83 that was fixed in 1.84; the remaining problem is then that my script crashes the 1.84 interpreter. Do you have a build available that has debugging symbols for the interpreter, so that I can try to obtain a backtrace?