psychopy.org | Reference | Downloads | Github

Checking timing of routines

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.

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) <---

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).

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

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).

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?

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.]

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.

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

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.

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.

1 Like

Many thanks, Michael!

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

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.

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)?

You should provide the actual output verbatim.

The lab just closed, so I will do tomorrow - thank you in advance!

Ok, you can find the

Configuration test or settingVersion or valueNotes Benchmark
benchmark version0.1dots & configuration
full-screenTruevisual window for drawing
dots_circle600
dots_square1000
available memory4769.1640625Mphysical RAM available for configuration test (of 8.0G total)
PsychoPy
psychopy1.85.0avoid upgrading during an experiment
localeEnglish_United States.1252can be set in Preferences -> App
python version2.7.11 (32bit)
wx3.0.2.0 msw (classic)
pyglet1.2.4
rushTruefor high-priority threads
Visual
openGL version4.2.12430 Compatibility Profile Context 13.152.1.8000
openGL vendorATI Technologies Inc.
screen size1920 x 1080
have shadersTrue
visual sync (refresh)10.01 ms/frameduring the drifting GratingStim
refresh stability (SD)5.17 msWarning: the refresh rate has high frame-to-frame variability (SD > 0.5 ms)
no dropped frames0 / 180during DotStim with 100 random dots
openGL max vertices2147483647
GL_ARB_multitextureTrue
GL_EXT_framebuffer_objectTrue
GL_ARB_fragment_programTrue
GL_ARB_shader_objectsTrue
GL_ARB_vertex_shaderTrue
GL_ARB_texture_floatTrue
GL_ARB_texture_non_power_of_twoTrue
GL_STEREOFalse
Audio
pyo0.8.0
Numeric
numpy1.11.0vector-based (fast) calculations
scipy0.17.1scientific / numerical
matplotlib1.5.1plotting; fast contains(), overlaps()
System
platformwindowsversion=sys.getwindowsversion(major=6, minor=1, build=7601, platform=2, service_pack=‘Service Pack 1’)
internet accessTruefor online help, usage statistics, software updates, and google-speech
auto proxyTruetry to auto-detect a proxy if needed; see Preferences -> Connections
proxy setting --current manual proxy setting from Preferences -> Connections
CPU speed test0.007 snumpy.std() of 1,000,000 data points
Python packages
PIL1.1.7
openpyxl2.3.5
lxml --could not import package lxml
setuptools22.0.0
pytest2.9.2
sphinx1.4.1
psignifit --could not import package psignifit
pyserial3.2.1
pp --could not import package pp
pynetstationimport ok
labjack --could not import package labjack
pywin32import ok
winioport --could not import package winioport

I’m sorry if that is not super clear…I would have attached a pdf of it, but the software wouldn’t allow me to.

It looks like there is a substantial problem with the refresh rate (bolded above)…

You should check your graphics card settings. Is it set to sync with the vertical refresh? Perhaps provide a screenshot of that control panel for clarity.

It turned out that the refresh rate of the monitor was set at 100 Hz. Taking it back to 60 Hz solved the problem. Thanks for your assistance!