Checking timing of routines

Coding
1

In my code for a masked priming experiment, I have 4 routines:

  1. forward mask, 500ms long
  2. prime, 33 ms long
  3. backward mask, 17ms long
  4. target (not timed)

I’m checking if timing of each of the routines above is fine, but I’m facing some weird results.

For one of my routines (the prime), my code says the following:

# ------Prepare to start Routine "prime"-------
    t = 0
    primeClock.reset()  # clock
    frameN = -1
    continueRoutine = True
    routineTimer.add(0.050000)
    # update component parameters for each repeat
    prime_txt.setText(prime)
    # keep track of which components have finished
    primeComponents = [prime_txt]
    for thisComponent in primeComponents:
        if hasattr(thisComponent, 'status'):
            thisComponent.status = NOT_STARTED
    
    # -------Start Routine "prime"-------
    while continueRoutine and routineTimer.getTime() > 0:
        # get current time
        t = primeClock.getTime()
        frameN = frameN + 1  # number of completed frames (so 0 is the first frame)
        # update/draw components on each frame
        
        # *prime_txt* updates
        if t >= 0.0 and prime_txt.status == NOT_STARTED:
            # keep track of start time/frame for later
            prime_txt.tStart = t
            prime_txt.frameNStart = frameN  # exact frame index
            prime_txt.setAutoDraw(True)
        frameRemains = 0.0 + .050- win.monitorFramePeriod * 0.75  # most of one frame period left
        if prime_txt.status == STARTED and t >= frameRemains:
            prime_txt.setAutoDraw(False)
            prime_txt.tEnd = t
        
        # check if all components have finished
        if not continueRoutine:  # a component has requested a forced-end of Routine
            break
        continueRoutine = False  # will revert to True if at least one component still running
        for thisComponent in primeComponents:
            if hasattr(thisComponent, "status") and thisComponent.status != FINISHED:
                continueRoutine = True
                break  # at least one component has not yet finished
        
        # check for quit (the Esc key)
        if endExpNow or event.getKeys(keyList=["escape"]):
            core.quit()
        
        # refresh the screen
        if continueRoutine:  # don't flip if this routine is over or we'll get a blank screen
            win.flip()
    
    # -------Ending Routine "prime"-------
    for thisComponent in primeComponents:
        if hasattr(thisComponent, "setAutoDraw"):
            thisComponent.setAutoDraw(False)
   loop_warmup.addData('on_prime', prime_txt.tStart)
   loop_warmup.addData('off_prime', prime_txt.tEnd)
   loop_warmup.addData('t_prime', prime_txt.tEnd-prime_txt.tStart)

Basically, it’s the usual automated code from the Builder, with two additions (signaled with an arrow):

if prime_txt.status == STARTED and t >= frameRemains:
            prime_txt.setAutoDraw(False)
            prime_txt.tEnd = t <----

[...]

   for thisComponent in primeComponents:
        if hasattr(thisComponent, "setAutoDraw"):
            thisComponent.setAutoDraw(False)

loop_warmup.addData('on_prime', prime_txt.tStart) <---
loop_warmup.addData('off_prime', prime_txt.tEnd) <---
loop_warmup.addData('t_prime', prime_txt.tEnd-prime_txt.tStart) <---

When I run the code, I have a couple of issues:

  1. from time to time, the run would crash with the following error:

loop_warmup.addData(‘off_prime’, prime_txt.tEnd)
AttributeError: ‘TextStim’ object has no attribute ‘tEnd’

  1. In the csv file, the 't_prime' values appears to be lower than expected: about 25 ms, instead of the 33 ms that I would expect given the refresh rate of the monitor (60 Hz). At times, the 't_prime' values drastically drop (even close to 0 ms), with no apparent reason.

Weirdly enough, this happens only with the prime routine, while the timing for the masks are pretty stable.

Can anyone help figure out why this happens, and how to fix it?

2

There are a number of issues here:

  • you should probably keep working within the Builder GUI until you absolutely can’t keep doing that: it is difficult to edit the Builder-generated code. You will likely achieve much of what you need if you stay within Builder and use Code components for inserting your custom code: that will handle the placement for you more reliably.
  • for such brief durations, you should probably time your stimuli using frame counting rather than time intervals: again, if you stay in the Builder GUI, this is very easy to switch.
  • you can’t just refer to undefined properties of objects: as the error message indicates, text stimuli don’t come with a .tEnd property. Just store this information in a regular variable.
  • the times you are gathering are not synchronised to the screen refresh. This is why you aren’t measuring intervals that are precise multiples of the refresh interval. e.g. your code might execute immediately after the previous screen refresh, giving a time of close to zero. If you want time stamps linked to the screen refresh, then you need to define a function to pass to the window’s .callOnFlip() function so that it occurs at the precise time of a screen update, rather than at some undetermined time between successive updates.
1 Like
3

Hi Michael,

many thanks for your helpful feedback. A couple of follow-ups:

  1. the times you are gathering are not synchronised to the screen refresh. This is why you aren’t measuring intervals that are precise multiples of the refresh interval. e.g. your code might execute immediately after the previous screen refresh, giving a time of close to zero. If you want time stamps linked to the screen refresh, then you need to define a function to pass to the window’s .callOnFlip() function so that it occurs at the precise time of a screen update, rather than at some undetermined time between successive updates.

Ok, so this is my attempt (for the routine fmask, 500-ms long; my additions have an arrow on the side):

    # ------Prepare to start Routine "fmask"-------
    t = 0
    fmaskClock.reset()  # clock
    frameN = -1
    continueRoutine = True
    routineTimer.add(0.500000)
    # update component parameters for each repeat
    # keep track of which components have finished
    fmaskComponents = [fmask_txt]
    for thisComponent in fmaskComponents:
        if hasattr(thisComponent, 'status'):
            thisComponent.status = NOT_STARTED
    
    # -------Start Routine "fmask"-------
    while continueRoutine: #and routineTimer.getTime() > 0:
        # get current time
        t = fmaskClock.getTime()
        frameN = frameN + 1  # number of completed frames (so 0 is the first frame)
        # update/draw components on each frame
        

if frameN >= 0.0 and fmask_txt.status == NOT_STARTED:
            # keep track of start time/frame for later
            fmask_txt.tStart = t
            fmask_txt.frameNStart = frameN  # exact frame index
            fmask_txt.setAutoDraw(True)
            frameRemains = 0.0 + .500- win.monitorFramePeriod * 0.75  # most of one frame period left
        if fmask_txt.status == STARTED and t >= frameRemains:
            fmask_txt.setAutoDraw(False)
            win.callOnFlip(fmaskClock.reset) # just making sure that the clock resets at the next flip <---
        
        # check if all components have finished
        if not continueRoutine:  # a component has requested a forced-end of Routine
            break
        continueRoutine = False  # will revert to True if at least one component still running
        for thisComponent in fmaskComponents:
            if hasattr(thisComponent, "status") and thisComponent.status != FINISHED:
                continueRoutine = True
                break  # at least one component has not yet finished
        
        # check for quit (the Esc key)
        if endExpNow or event.getKeys(keyList=["escape"]):
            core.quit()
        
        # refresh the screen
        if continueRoutine:  # don't flip if this routine is over or we'll get a blank screen
            win.flip()
    
    # -------Ending Routine "fmask"-------
    for thisComponent in fmaskComponents:
        if hasattr(thisComponent, "setAutoDraw"):
            thisComponent.setAutoDraw(False)
    # store time of presentation to make sure
    loop_warmup.addData('t_fmask', fmaskClock.getTime()) #stamp of routine duration (in s) <---
    loop_warmup.addData('fr_fmask', frameN) #stamp of routine duration (in frames) <---

It seems to work properly, but I wanted to make sure I understood your suggestion.

  1. For such brief durations, you should probably time your stimuli using frame counting rather than time intervals: again, if you stay in the Builder GUI, this is very easy to switch.

You’re right. On this matter, I have a clarification question: what is the difference between “duration (frames)” and “frame N” of the text stimulu pop-up window in the Builder? I don’t seem to understand the difference, nor is it explained anywhere.

As far as I can see, the difference in the code is the following:

  1. duration (frames):
if 'stimulus'.status == STARTED and frameN >= ('stimulus'.frameNStart + 'duration in frames'):
...
  1. frameN:
if 'stimulus'.status == STARTED and frameN >= 'duration in frames':
...

So, at least in my case (where one routine has exactly one stimulus), 1) and 2) are basically equivalent. Did I get this right?

Thanks!

4

One setting says “end this stimulus at frame number N”, (i.e. end at a particular point in time) and the other is saying " “end this stimulus at N frames after it started” (i.e. end after a certain duration). These two are equivalent if and only if the stimulus onset is at frame number 0, which means that time == duration.

5

Ok, thanks for clearing that up.

Can you confirm that the code below does what I need it to do? I noticed that there’s still some minimal variation (a couple of ms), and I am not sure if that’s normal.

Many thanks for the help!

6

I’m not exactly sure what that is, so can’t give a definitive answer.

Note that you synchronise the reset of your fmaskClock with the first frame being drawn, but when you actually measure the time elapsed since that definite zero point, that call isn’t synchronised with a window flip, so yes, there might be a bit of slop there.

7

I just need to make sure that my routine lasts as much time as I want.

So to get precise duration of each duration, I should put the clock variable at the end of the routine…?

or thisComponent in fmaskComponents:
        if hasattr(thisComponent, "setAutoDraw"):
            thisComponent.setAutoDraw(False)
            fmaskDuration = fmaskClock.getTime()
    # store time of presentation to make sure
    loop_warmup.addData('t_fmask', fmaskDuration) #stamp of routine duration (in s) <---
    loop_warmup.addData('fr_fmask', frameN) #stamp of routine duration (in frames) <---
8

You could put fmaskDuration = fmaskClock.getTime() directly after the win.flip() (it doesn’t matter that it happens on every frame, as it will only be the last value that gets saved in the data), but realistically it doesn’t matter that much if it is a few lines later. Just bear in mind that the actual duration of the stimulus is one frame duration longer than that: you zeroed the clock at the time the first frame began to be shown, and then get the duration at the beginning of the final frame, but it will continue to be shown on the display for (approximately slightly less than) another 16.666 ms (on a 60 Hz screen).

9

I am afraid I am confused now. Does that mean that the durations fo each of my routines (fmask, prime, bmask; see screenshot below) are 16ms-longer than the csv says?

52%20PM

10

Below is a representation of some frames. They have a start time but also a duration:

|----------------|----------------|----------------
0                1                2

Let’s say you have a stimulus that will be displayed for 3 frames (50 ms duration at 60 Hz). You reset the clock at the start of the zeroth frame (time point 0). You then measure the duration at the beginning of the last frame in that sequence (time point 2). This will give a measured duration of (just over) 33.33 ms, even though the stimulus is appearing on screen for the desired duration (50 ms).

If you want the measured durations to correspond to the actual ones, then you need to put the second time measurement at the beginning of frame 4 (i.e. what would be time point 3, the onset of the next stimulus).

11

I see you’re point. So, the screenshot that I posted above have ~16ms missing?

If so, I just don’t follow why the durations in the screenshot are so precise, especially because I converted all durations into frames:

    # ------Prepare to start Routine "fmask"-------
    t = 0
    fmaskClock.reset()  # clock
    frameN = -1
    continueRoutine = True
    # update component parameters for each repeat
    # keep track of which components have finished
    fmaskComponents = [fmask_txt]
    for thisComponent in fmaskComponents:
        if hasattr(thisComponent, 'status'):
            thisComponent.status = NOT_STARTED
    
    # -------Start Routine "fmask"-------
    while continueRoutine:
        # get current time
        t = fmaskClock.getTime()
        frameN = frameN + 1  # number of completed frames (so 0 is the first frame)
        # update/draw components on each frame
        
        # *fmask_txt* updates
        if frameN >= 0.0 and fmask_txt.status == NOT_STARTED:
            # keep track of start time/frame for later
            fmask_txt.tStart = t
            fmask_txt.frameNStart = frameN  # exact frame index
            fmask_txt.setAutoDraw(True)
        if fmask_txt.status == STARTED and frameN >= 30:
            fmask_txt.setAutoDraw(False)
            win.callOnFlip(fmaskClock.reset) # just making sure that the clock resets at the next flip
        
        # check if all components have finished
        if not continueRoutine:  # a component has requested a forced-end of Routine
            break
        continueRoutine = False  # will revert to True if at least one component still running
        for thisComponent in fmaskComponents:
            if hasattr(thisComponent, "status") and thisComponent.status != FINISHED:
                continueRoutine = True
                break  # at least one component has not yet finished
        
        # check for quit (the Esc key)
        if endExpNow or event.getKeys(keyList=["escape"]):
            core.quit()
        
        # refresh the screen
        if continueRoutine:  # don't flip if this routine is over or we'll get a blank screen
            win.flip()
            fmaskDuration = fmaskClock.getTime()
    
    # -------Ending Routine "fmask"-------
    for thisComponent in fmaskComponents:
        if hasattr(thisComponent, "setAutoDraw"):
            thisComponent.setAutoDraw(False)
    # store time of presentation to make sure
    loop_warmup.addData('t_fmask', fmaskDuration)
    loop_warmup.addData('fr_fmask', frameN)

Adding ~16ms to each of them would mean that the routines are longer than expected. Does it make sense?

12

Above, you fmaskClock.reset() before anything has been drawn. This could be up to 16 ms before the screen actually gets updated. This initial resetting needs to happen at the time of the first win.flip()

When you later do this: fmaskDuration = fmaskClock.getTime(), it is when frameN 29 has just been drawn. At this stage, that image will still be on screen for a further 16 ms. Can you see that everything is timed early by about a frame duration, but the interval between them is approximately correct, so it looks OK, but with a bit of noise?

Remember, you are counting from zero and the code is running in the period before the corresponding frame number will be drawn to screen. The next win.flip() will occur at the actual time of onset of the frame corresponding to the code currently running. It is easy to lose sight of the fact that the code is running while the previous frame is on display. Perhaps the diagram above should look like this:

----------------|----------------|----------------|---------------|
                0                1                2               3

Your code is running in the dashed portions of the time line, some time before the corresponding frame number will actually be drawn to screen (at the instant indicated by the vertical line).

So if you want a stimulus to appear for a duration of three frames (50 ms), set the timer to reset when frame 0 is drawn and measure the duration by checking the timer when frame 3 is drawn. Frame number 3 is actually the fourth frame overall, and the first frame of the next stimulus, but its time of onset marks the actual end of the previous interval.

i.e. the actual duration of your stimulus is the interval between the points labelled 0 and 3. It doesn’t include any of the time prior to time point 0, which is when the code runs that prepares the onset of the stimulus. But currently you reset the clock at some time between time point -1 and time point 0, and measure the time elapsed at time point 2. The duration will be approximately correct (roughly three frame intervals) but the absolute times are out. Also, the duration on the very first trial is likely to be worse than any subsequently measured one, as we don’t really know when in time with respect to the frame updates that the code will be running on the first iteration (it will hopefully be synchronised after that). [That only applies if this is the very first frame of the experiment.]

13

Many thanks for this, Michael! I really appreciated your explanation.

I’ve been trying to do this, but I can’t seem to get the expected durations. As far as my coding skills go, I believe that In the code below time of fmask is reset at frame 0 and then measured at the next stimulus’ first frame (see arrows and comments).

    # ------Prepare to start Routine "fmask"-------
    frameN = -1
    continueRoutine = True
    # update component parameters for each repeat
    # keep track of which components have finished
    fmaskComponents = [fmask_txt]
    for thisComponent in fmaskComponents:
        if hasattr(thisComponent, 'status'):
            thisComponent.status = NOT_STARTED
    
    # -------Start Routine "fmask"-------
    while continueRoutine:# and routineTimer.getTime() > 0:
        frameN = frameN + 1  # number of completed frames (so 0 is the first frame)
        # update/draw components on each frame
        
        # *fmask_txt* updates
        if frameN >= 0.0 and fmask_txt.status == NOT_STARTED:
            # keep track of start time/frame for later
            #fmask_txt.tStart = t
            fmask_txt.frameNStart = frameN  # exact frame index
            fmask_txt.setAutoDraw(True)
            fmaskClock.reset() <-------- 'reset time when frame 0 is drawn'
        if fmask_txt.status == STARTED and frameN >= fwdFrame:
            fmask_txt.setAutoDraw(False)
            win.callOnFlip(fmaskClock.reset) #not sure it this is of any help
            
        # check if all components have finished
        if not continueRoutine:  # a component has requested a forced-end of Routine
            break
        continueRoutine = False  # will revert to True if at least one component still running
        for thisComponent in fmaskComponents:
            if hasattr(thisComponent, "status") and thisComponent.status != FINISHED:
                continueRoutine = True
                break  # at least one component has not yet finished
        
        # check for quit (the Esc key)
        if endExpNow or event.getKeys(keyList=["escape"]):
            core.quit()
        
        # refresh the screen
        if continueRoutine:  # don't flip if this routine is over or we'll get a blank screen
            win.flip()
            
    # -------Ending Routine "fmask"-------
    for thisComponent in fmaskComponents:
        if hasattr(thisComponent, "setAutoDraw"):
            thisComponent.setAutoDraw(False)
    # store time of presentation to make sure
    loop_warmup.addData('fr_fmask', frameN)
    
    # ------Prepare to start Routine "prime"-------
    
    primeClock.reset()  # clock
    frameN = -1
    continueRoutine = True
    # update component parameters for each repeat
    prime_txt.setText(prime)
    # keep track of which components have finished
    primeComponents = [prime_txt]
    for thisComponent in primeComponents:
        if hasattr(thisComponent, 'status'):
            thisComponent.status = NOT_STARTED
    
    # -------Start Routine "prime"-------
    while continueRoutine:# and routineTimer.getTime() > 0:
        frameN = frameN + 1  # number of completed frames (so 0 is the first frame)
        # update/draw components on each frame
       
        # *prime_txt* updates
        if frameN >= 0.0 and prime_txt.status == NOT_STARTED:
            # keep track of start time/frame for later
            prime_txt.frameNStart = frameN  # exact frame index
            prime_txt.setAutoDraw(True)
            fmaskDuration = fmaskClock.getTime() <--- 'duration when "frame 3" is drawn'
        if prime_txt.status == STARTED and frameN >= primeFrame:
            prime_txt.setAutoDraw(False)
            win.callOnFlip(primeClock.reset) # not sure if this is of any help in the end
        
        # check if all components have finished
        if not continueRoutine:  # a component has requested a forced-end of Routine
            break
        continueRoutine = False  # will revert to True if at least one component still running
        for thisComponent in primeComponents:
            if hasattr(thisComponent, "status") and thisComponent.status != FINISHED:
                continueRoutine = True
                break  # at least one component has not yet finished
        
        # check for quit (the Esc key)
        if endExpNow or event.getKeys(keyList=["escape"]):
            core.quit()
        
        # refresh the screen
        if continueRoutine:  # don't flip if this routine is over or we'll get a blank screen
            win.flip()
            primeDuration = primeClock.getTime()
            
    # -------Ending Routine "prime"-------
    for thisComponent in primeComponents:
        if hasattr(thisComponent, "setAutoDraw"):
            thisComponent.setAutoDraw(False)
    loop_warmup.addData('t_fmask', fmaskDuration)
    loop_warmup.addData('fr_prime', frameN)

However, the durations are a bit above the threshold, as they vary between 498 and 510 ms. I feel like there’s something I am missing and can’t quite grasp.

14

To establish your first time point, you need to reset the clock at the moment the first frame is drawn. At the moment, you are still doing it some indeterminate time before that. So you need to coordinate the reset with the flip when frameN == 0.

e.g. instead of fmaskClock.reset(), which happens immediately, do win.callOnFlip(fmaskClock.reset) which won’t happen immediately, but when the image actually appears on screen.

Then you measure the duration by doing fmaskClock.getTime() immediately after the first win.flip() of the next stimulus.

win.flip() # drawing the prime stimulus
if frameN == 0: # the very first frame of the prime stimulus
    fmaskDuration = fmaskClock.getTime() # marks the offset of the previous mask stimulus

Remove the other reference to resetting fmaskClock, but set up a parallel structure for the prime clock. i.e. it will be reset on frameN == 0 during the prime-drawing portion of the code, with a getTime() when frame == 0 of the following stimulus.

1 Like
15

I hadn’t thought about this at all. I am learning a lot - Many many thanks for the suggestion!!

Now everything seems almost perfect: duration values seem to be multiples of the refresh rate (with a +/- 2 ms variance, which I am okay with), but I notice that the duration of a couple of random trials of the routines are reported to last ~16ms (e.g., 1 frame) longer than they are supposed to :

39%20PM

In the screenshot above, the upper right arrow indicates that the very first bmask trial is reported to be ~33ms long (i.e., exactly ~16ms/1 frame longer than expected); the bottom left arrow highlights that the penultimate fmask trail is reported to be ~517ms long (i.e., exactly ~16ms/1 frame longer than expected). Any idea of why this happens?

I am sorry for being so picky on this. I’m just trying to understand how the code works, so that I could do better in the future (and possibly be comfortable with working with the coder, and thus refrain from using the Builder at all). And I am okay with this occasional delay in the time report, as long as it is some sort of “glitch” that is independent of the actual time/frame duration of trials.

1 Like
16

You are “dropping frames”. This happens when code takes too long to execute within one refresh period. The screen will update regardless of what our code does, so it will just continue to show what it was last given until the next win.flip() command gives it new content. So if you want to show a stimulus for one frame (16.66 ms duration) but a frame drop occurs, what happens looks like this:

----------------|----------------|----------------|---------------|
                0                                 1               2

If you are using frame-counting code, you don’t know that anything has gone wrong. You draw frame 0, and draw frame 1. It’s just that frame 1 actually occurs one period later than intended because the win.flip() happened too late to influence the scheduled screen update. So your 16.7 ms stimulus was actually shown for 33 ms.

With a one-frame duration stimulus, there isn’t much you can do about this except make the measurements you are currently doing, so you know the extent of any problem. With the 500 ms stimulus, however, you have the option of going back to time-based code. That way, you can correct for any dropped frames by ensuring that the stimulus is displayed for a total of 500 ms regardless of how many win.flip’s were issued (assuming the dropped frame doesn’t occur on the very last frame).

Why do dropped frames occur? In your case, the PsychoPy code seems fine, because normally you get things done in time (it is certainly possible for your own code to drop frames, for example if you are updating a stimulus by reading in a large image file from disk, which can easily take more than one refresh interval). But in your case, it is likely some other process that is intruding on your time. You need to have as “clean” a computer and operating system as possible. Disconnect from the net, strip out virus checkers and disable automatic updates during experiments, don’t install any software (e.g. Microsoft Office) that you don’t need to run the experiment. Many pieces of software create processes that run in the background and compete for CPU resources with PsychoPy.

This issue isn’t unique to PsychoPy: think of how many times when you’ve been using a computer that it seemed briefly to be unresponsive or to stutter when moving the mouse pointer. When running an experiment and doing careful testing like you are, you see the evidence of this at the millisecond level. From a software point of view, remove as many possible competing programs as possible and from a hardware point of view, use a computer with a fast CPU, decent amount of RAM, ideally solid state drives, and a good graphics card. That means that you can get more done within a single screen refresh period: your own code is currently quick enough, but this would help reduce the impact of other programs running at the same time.

3 Likes
17

Many thanks, Michael!

18

Hello again!

I am re-using the same for another experiment with the same design, but this time I’ll be using two different computers. I don’t know why, but the code is working differently in the two computers with respect to the timing of routines. The same code gives different results with the two computers: in the former (macOS Sierra, Psychopy 1.85.6), it works as expected (e.g., 30 frames of the given routine = ~500 ms), in the latter (Windows, PsychoPy 1.85) the timed duration is substantially slower (e.g., 30 frames = 300 ms). This is particularly weird since (a) the two monitors have the same refresh rate (60 Hz), even though they do have a different resolution and (b) in the Windows computer the frame-seconds conversion is not consistent (e.g., 2 frames = 30 ms).

Does anybody have any idea what is going on? The code is the same for the two computers, and the version of Psychopy is also (more or less) the same, so I have no idea what might be causing this.

Thanks,
-Roberto

19

This may be due to limitations with the graphics card and/or its driver on the Windows PC. Try running the benchmark wizard from the Tools menu in PsychoPy to see what sort of performance you are getting.

20

Yeah, I tried that too. It says that there is a slight problem with the refresh rate of less than 0.5 seconds. What does this mean exactly? That the stimuli may not be presented for as many frames as I want? If so, is there anyway I could fix this (other than buying a different graphic card)?