Strange behavior of the win.flip() function with 144hz LCD monitor

Hi community,

I am testing a new setup for our lab. In particular, we are using a Benq XL2411 monitor running at 144 Hz. I have already posted the output from timeByframes.py on this forum, everything looks good.
However, I just noticed some weird stuff when running a real experiment. Before my stim presentation, I started a clock and checked time immediately after the flip:

> core.wait(0.25)
> draw stuff...
> test = core.Clock()
> win.flip
> print test.getTime().

I initially performed the testing with fullscreen = False and a 800x800 window:

> win = visual.Window([800,800], fullscr=False, 
>     monitor='LoganLab', color=[128,128,128], colorSpace='rgb255', units='deg')

Below is the output for 8 trials:

> 0.00538480374962
> 0.00486808968708
> 0.00538375321776
> 0.00498230243102
> 0.00484472187236
> 0.00523488316685
> 0.00507997395471
> 0.00471528060734

I then did the same test using fullscreen mode and the native 1920x1080 resolution I was planning to use for my experiment. below is the output:

> 0.000973302870989
> 0.00100087141618
> 0.000977240968496
> 0.00100402208045
> 0.00105495844036
> 0.00103657972068
> 0.00099588278681
> 0.00100927334279

I don’t understand what’s happening, and would appreciate any insight.
I don’t think it is due to the core.wait() function, since adding several win.flip() after it (and before my test clock) doesn’t solve the problem.
I am worried about these results because I plan to start a RT clock immediately after the flip(). The variation introduced across trials is extremely small across trials, so I don’t think it’s a problem (I use static stimuli and just call win.flip() once after polling my response device).

Your clock is measuring the amount of time it takes for the flip function to execute, not the time between flips. So what you’re seeing is that executing “flip” takes about 5ms (± 0.5ms) to execute when running in windowed mode and 1ms (± 0.05ms) to execute when running fullscreen. A 144Hz monitor refreshes every 6.94ms, and the times you’re seeing are all far less than that, so it’s not skipping any frames, and so it probably wouldn’t be detectable in what appears on the screen and when.

Most likely it’s an issue of the computer itself. When it’s in windowed mode, your hardware needs to render everything else on the screen as well as the PsychoPy window, whereas in fullscreen mode PsychoPy is getting the hardware’s undivided attention. Many graphically intensive programs run better in fullscreen mode compared to windowed mode, but in either case I don’t think a sub-refresh-rate rendering difference is going to have any noticeable impact on your experiment.

Thanks Jonathan,

I was wondering about this difference, but you guess makes perfect sense.
Cheers

That’s not strictly the case. win.flip() has its effect almost instantaneously (it’s just flipping two buffers). What the code is actually doing above is measuring the time between creating the clock, and the win.flip() function returning. i.e. when you call win.flip(), you effectively enter a pause period, waiting for the next screen refresh to occur. i.e. this is waiting for a hardware event, its not really anything to do with how long win.flip() takes to execute. i.e. the off-screen and the offscreen buffers will be swapped almost instantly, but then the code waits until that new front buffer is actually drawn to the screen.

So the first set of results show the expected behaviour: it’s effectively random when in the current refresh interval (6.9 ms duration) the timer will be created. win.flip() is called, and so the code pauses until the next screen is displayed. The measured time should therefore be somewhere between a minimum of 0 ms and a maximum of 6.94 ms, with a mean of 3.47. @Servant_Mathieu: this apparent timing variation is of no relevance to how long the stimuli are actually displayed: if you measured from one win.flip() to the next, you’d likely find variability in the microsecond rather than millisecond range.

The stranger thing is the second set of results. That shows that something else is happening entirely. @Servant_Mathieu I wonder if your graphics card and display are capable of the new adaptive frame rate control, such as Nvidia G-Sync? In that case, calling win.flip() might actually initiate a screen refresh, rather than just wait passively for the next one on a scheduled cycle. If so, perhaps it only takes effect when PsychoPy has control of the whole screen rather than just a window?

Check this post and link for more details:

Hi Michael,
Thanks again for your precious help. Very much appreciated.
We have RADEON graphics (AMD RADEON R9 200 Series memory 3791, current display mode 1920x1080 144hz). So it doubt it is capable of the new adaptive frame rate control.
Do you think I have to worry about timing? I already ran two experiments using this setup. For now, I just presented static stimuli, so I drew stim, called win.flip(), and then start my RT clock. I just don’t understand what the win.flip() is doing and I am stuck. I don’t know what else I could check/do… The code is just supposed to work fine on standard hardware…

I’m not familiar with it, but a quick google shows that this card is capable of the AMD equivalent, which is called Free Sync. Can you find a setting to disable that in your graphics card driver?

We generally assume a fixed refresh rate. PsychoPy can certainly work with adaptive frame rates, but the code has to alter accordingly. Having said that, I’m just guessing that this is coming into play here. You should run your tests before and after disabling Free Sync to see.

But regardless, you need to understand when to start your timing. You are correct if you start your RT clock immediately after the first win.flip() of your stimulus.

In my Radeon settings menu, it is written "Free Sync not supported; wait for vertical refresh = Always True. Below are results from the TimesByFrames demo I posted some time ago. The first frame is ~2.5ms, while the others are nicely gathered around the expected 6.9ms.

I just ran the same demo on my personal computer, running on windows 10. My graphic card is not great (Intel HD Graphics 4600), and I have a LCD samsung 60Hz. Here again, the duration of the first frame is considerably lower than the others.

Am I missing something? Is it normal?

No, that all looks very good.Your original question was about the inconsistency between those two sets of measured time intervals, and I don’t think that the timing stability of your display is really relevant to that.

But regardless, the fact you were seeing that level of variability in the first set of numbers was simply due to the structure of your code. If you time your RT correctly from after the first win.flip() of your stimulus, you should be good.

Why that variability was markedly reduced when running full-screen remains to be explained.

@Michael So I’ve done additional investigations and I think I have identified the issue, which seems serious.

I ran two basic codes:
code n°1:

> from __future__ import division
> from psychopy import core, data, event, visual, gui
> import numpy as np
> import os
> from psychopy import logging
> 
> 
> 
> logging.console.setLevel(logging.CRITICAL)
> 
> win = visual.Window([1920,1080], fullscr=True, 
>     monitor='testMonitor', color=[128,128,128], colorSpace='rgb255', units='deg')
> #win.recordFrameIntervals = True
> police = 'Lucida Console'                    
> 
> #
> #target_H = visual.TextStim(win=win, ori=0,
> #    text=u'H',
> #    font=police,
> #    pos=[0, 0],
> #    color=[0,0,0], colorSpace=u'rgb255', height = 0.5)
> #    
> #    
> #target_H.draw()
> 
> timer = core.Clock()
> win.flip()
> timer.reset()
> win.flip()
> print timer.getTime()
> 
> #Shutting down:
> win.close()
> core.quit()

Code n° 2 is identical, except that I now draw target_H:

> logging.console.setLevel(logging.CRITICAL)
> 
> win = visual.Window([1920,1080], fullscr=True, 
>     monitor='testMonitor', color=[128,128,128], colorSpace='rgb255', units='deg')
> #win.recordFrameIntervals = True
> police = 'Lucida Console'                    
> 
> 
> target_H = visual.TextStim(win=win, ori=0,
>     text=u'H',
>     font=police,
>     pos=[0, 0],
>     color=[0,0,0], colorSpace=u'rgb255', height = 0.5)
>     
>     
> target_H.draw()
> 
> timer = core.Clock()
> win.flip()
> timer.reset()
> win.flip()
> print timer.getTime()
> 
> #Shutting down:
> win.close()
> core.quit()

Below are results from computer A (AMD RADEON R9 200 Series, monitor LCD BENQ at 144Hz):
code n° 1:

> ###### Running: C:\Users\LoganLab\Desktop\Mathieu\Eriksen_Dot\untitled.py ######
> 0.00699874805287
> ()
> ###### Running: C:\Users\LoganLab\Desktop\Mathieu\Eriksen_Dot\untitled.py ######
> 0.00693914759904
> ()
> ###### Running: C:\Users\LoganLab\Desktop\Mathieu\Eriksen_Dot\untitled.py ######
> 0.00689635053277
> ()
> ###### Running: C:\Users\LoganLab\Desktop\Mathieu\Eriksen_Dot\untitled.py ######
> 0.00692260637879
> ()
> ###### Running: C:\Users\LoganLab\Desktop\Mathieu\Eriksen_Dot\untitled.py ######
> 0.00690238969401

code n° 2:

> ###### Running: C:\Users\LoganLab\Desktop\Mathieu\Eriksen_Dot\untitled.py ######
> 0.00422009639442
> ()
> ###### Running: C:\Users\LoganLab\Desktop\Mathieu\Eriksen_Dot\untitled.py ######
> 0.00302887009457
> ()
> ###### Running: C:\Users\LoganLab\Desktop\Mathieu\Eriksen_Dot\untitled.py ######
> 0.00113608874381
> ()
> ###### Running: C:\Users\LoganLab\Desktop\Mathieu\Eriksen_Dot\untitled.py ######
> 0.00679526571184
> ()
> ###### Running: C:\Users\LoganLab\Desktop\Mathieu\Eriksen_Dot\untitled.py ######
> 0.000847537536174
> ()
> ###### Running: C:\Users\LoganLab\Desktop\Mathieu\Eriksen_Dot\untitled.py ######
> 0.00471764383838

Computer B (Intel HD graphics 4600 monitor LCD SAMSUNG 60Hz):
code n°1:

> ##### Running: C:\Users\mat\Desktop\Flanker_Dot_Probe\Experiment_3\experimental_code\untitled.py #####
> 0.0166847715154
> ()
> ##### Running: C:\Users\mat\Desktop\Flanker_Dot_Probe\Experiment_3\experimental_code\untitled.py #####
> 0.016642392613
> ()
> ##### Running: C:\Users\mat\Desktop\Flanker_Dot_Probe\Experiment_3\experimental_code\untitled.py #####
> 0.0167691987008
> ()
> ##### Running: C:\Users\mat\Desktop\Flanker_Dot_Probe\Experiment_3\experimental_code\untitled.py #####
> 0.0166675550863
> ()
> ##### Running: C:\Users\mat\Desktop\Flanker_Dot_Probe\Experiment_3\experimental_code\untitled.py #####
> 0.0166225272696
> ()

code n ° 2:

> ##### Running: C:\Users\mat\Desktop\Flanker_Dot_Probe\Experiment_3\experimental_code\untitled.py #####
> 0.0184203267563
> ()
> ##### Running: C:\Users\mat\Desktop\Flanker_Dot_Probe\Experiment_3\experimental_code\untitled.py #####
> 0.0198810801376
> ()
> ##### Running: C:\Users\mat\Desktop\Flanker_Dot_Probe\Experiment_3\experimental_code\untitled.py #####
> 0.00938696344383
> ()
> ##### Running: C:\Users\mat\Desktop\Flanker_Dot_Probe\Experiment_3\experimental_code\untitled.py #####
> 0.0133394738659
> ()
> ##### Running: C:\Users\mat\Desktop\Flanker_Dot_Probe\Experiment_3\experimental_code\untitled.py #####
> 0.020676018903
> ()
> ##### Running: C:\Users\mat\Desktop\Flanker_Dot_Probe\Experiment_3\experimental_code\untitled.py #####
> 0.0207819666248

Again, I may be missing something. But this behavior seems clearly abnormal, and does not depend on hardware. I am using psychopy V.1.85.4

Just to elaborate on the mechanism behind the pause, the call to swap buffers returns immediately, however your video card will ‘hold’ drawing to the back buffer until vertical retrace if v-sync is enabled. So any drawing commands will be queued until it’s released, but this alone doesn’t block your program’s execution so it will run asynchronously with your display. PsychoPy gets around this by issuing dummy draw calls and a glFinish() after flipping the buffers, pausing the thread until the back buffer is free, forcing GPU/CPU synchronization.

@mdc So if GPU/CPU are supposed to be synchronized, how do you explain the apparent desynchronization that I observed when drawing stuff ? Guys I 'm lost here. I would just like to know if there is a problem with our system/timing. I precise that v-sync is enabled in my GPU options.

PsychoPy has some provisional code for handling buggy ATI/AMD drivers in the post-flip ‘pause’ routine I mentioned which may be rendering it ineffective on Windows machines, but your data suggests something else is going on here. Based on your data I suspect something related to text rendering might be throwing off your timings. I can’t replicate this issue on my machines (nvidia all over here), but I’ll mull over what you provided for a solution.

@Michael I figured out the cause of the second set of results: triple buffering was enabled. Disabling it fixed the issue. Should triple buffering be always disabled when running an experiment, or is there some advantage of using it in particular circumstances?

In most PsychoPy code, we work with just two buffers: the “front” one currently being displayed, and the “back” one, containing the content currently being prepared for display. When drawing is complete, we issue the call to flip the two (which will happen at the next screen refresh). So yes, to keep things running simply, disable triple buffering.