Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Visual timing on macOS #2250

Open
hoechenberger opened this issue Feb 1, 2019 · 21 comments

Comments

@hoechenberger
Copy link
Member

commented Feb 1, 2019

@peircej mentioned that he observed a changed timing behavior on Macs since High Sierra, potentially related to triple buffering. I just ran a quick test on my brand-new MacBook Pro 2018 with Touch Bar, running Mojave 10.14.3, and cannot reproduce this issue (at least not when only using the built-in display; cannot hook up an external monitor for now).

from psychopy.visual.window import Window
from psychopy.clock import Clock

clock = Clock()
win = Window(fullscr=True, size=(1440, 900))
n_flips = 10

win.callOnFlip(clock.reset)  # Reset to zero on first flip.

for _ in range(n_flips + 1):
    win.flip()

t = clock.getTime()
win.close()

print(f'Total duration of {n_flips} flips: {round(t*1000, 2)} ms')

Output:

/Users/hoechenberger/miniconda3/envs/psychopy-test/bin/python /Users/hoechenberger/Library/Preferences/PyCharm2018.3/scratches/scratch_1.py
pygame 1.9.4
Hello from the pygame community. https://www.pygame.org/contribute.html
0.9357 	WARNING 	Monitor specification not found. Creating a temporary one...
Total duration of 10 flips: 166.5 ms

Process finished with exit code 0

I consistently get values around 166–168 ms, which is about the expected duration on a 60 Hz screen.

Running PsychoPy master, pyglet 1.3.2.

@peircej

This comment has been minimized.

Copy link
Member

commented Feb 1, 2019

You won't be able to detect it using PsychoPy's reported times:

  • the effect is mostly about a 1-frame lag (so frame durations will be fine and stimulus duration should be fine)
  • as a lag, this is relative to other events, like labjack commands, keyboard polling, sound outputs (although those also carry their own lag!). To measure it you need to output a pulse on flip and compare with physical stimulus appearance (photodiode)

I think @dvbridges and I don't yet know how much impact this is having on variability.

@hoechenberger

This comment has been minimized.

Copy link
Member Author

commented Feb 1, 2019

@hoechenberger

This comment has been minimized.

Copy link
Member Author

commented Feb 2, 2019

I have created a new, simple test case that doesn't require any external measurement devices: I flip, and only proceed to flipping again after the user has pressed a key. This gives us time to view the results of each flip individually.

from psychopy.visual.window import Window
from psychopy.visual.text import TextStim
from psychopy.visual.circle import Circle
from psychopy.event import waitKeys

win = Window(fullscr=True, size=(1440, 900))
text = TextStim(win, pos=(0, 0.25))
disc = Circle(win, radius=0.1, pos=(0, -0.25),
              edges=256, color='red', units='height')
n_flips = 3

for i in range(n_flips):
    # Draw the disc to the back buffer only once: just before we're
    # going to do the very first flip.
    #
    # If we're double-buffered, it should appear on the first flip and
    # disappear on the second.
    #
    # If we're triple-buffered, it should appear on the second flip and
    # disappear on the third.
    if i == 0:
        disc.draw()

    text.text = f'Screen after flip #{i+1}.\nPress key to proceed.'
    text.draw()

    win.flip()
    waitKeys()

win.close()

This works as expected for a double-buffered system on my machine: the red disc appears on the very first flip and disappears with the second flip.

@m-macaskill

This comment has been minimized.

Copy link
Contributor

commented Feb 3, 2019

Does this reflect how triple buffering actually works? i.e. I don't think it necessarily works in serial like a pipeline from 3rd buffer -> 2nd buffer -> front buffer. Rather, the 2nd and 3rd buffer are in parallel, feeding into the front buffer. Whichever one has the latest content is the one which will be fed into the front buffer. So if the drawing code is running faster than the screen refresh rate, often the content in the second buffer will be skipped entirely, in favour of the later-drawn third buffer. Perhaps they could be better labelled "Buffer A" and "Buffer B", to indicate that the pointer to which is the latest alternates between them, potentially at a rate which is faster than the front buffer is flipped to the screen. The point of triple buffering is to avoid lags in getting the latest content to the screen. So I'm not sure that this sort of code could actually show any difference between double and triple buffering.
If we are seeing a one-frame lag, I suspect that might be due to something happening at the OS level (i.e. like the extra processing sometimes done in monitor hardware), i.e. a level of buffering which is laid on top of our user-level drawing code. As per @peircej's suggestion, I don't think we can make much headway here without external hardware timing validation.

@hoechenberger

This comment has been minimized.

Copy link
Member Author

commented Feb 4, 2019

Does this reflect how triple buffering actually works?

A problem is that "triple buffering" seems to be somewhat of an umbrella term with slightly different meanings, but my understanding is that, yes, this is generally how it's supposed to work.

i.e. I don't think it necessarily works in serial like a pipeline from 3rd buffer -> 2nd buffer -> front buffer. Rather, the 2nd and 3rd buffer are in parallel, feeding into the front buffer. Whichever one has the latest content is the one which will be fed into the front buffer.

The question is: How would the driver know which buffer has the "latest" content? When triple-buffering, by issuing the flip command you essentially mark a drawing operation as done and a buffer as "ready to be displayed"; then you may immediately start filling the second buffer, issue flip, immediately start filling the first buffer again, etc.

In that sense, unless there's some kind of interaction on an additional level (OS, hardware) like you mentioned, I believe the test I presented would be valid.

At any rate, I will try to hook up a BBTK some time next week to my computer, to test with both internal and external displays. A colleague of mine has one, and I'll ask if he'd be willing to lend it to me for a couple hours.

@hoechenberger

This comment has been minimized.

Copy link
Member Author

commented Feb 4, 2019

@peircej @dvbridges Could you please share your BBTK test code with me so I can run the exact same tests as you guys? :)

@peircej

This comment has been minimized.

Copy link
Member

commented Feb 4, 2019

Yes, I don't think this test would necessarily show the problem because a) triple buffering might be implemented in multiple ways and b) we don't even know for sure that it's the problem. If we find a software solution that demonstrates the problem it will be great to help us, but if it doesn't show the problem then it only suggests that the test isn't sensitive!
@dvbridges can pass on the code. We bought the "key actuator" (robotic keyboard basher) for the BBTK and that allows us to test the reaction time delay too, but for this test all you need is a labjack or equivalent to send a trigger pulse at (apparent) screen flip.

@hoechenberger

This comment has been minimized.

Copy link
Member Author

commented Feb 4, 2019

@dvbridges can pass on the code. We bought the "key actuator" (robotic keyboard basher) for the BBTK and that allows us to test the reaction time delay too, but for this test all you need is a labjack or equivalent to send a trigger pulse at (apparent) screen flip.

Cool! I have an NI DAQ board, just need to find out if it works with my Mac :)

@dvbridges

This comment has been minimized.

Copy link
Contributor

commented Feb 4, 2019

@hoechenberger , here is the code. I use Digital Stimulus Capture for collecting timing data, and Digital Stimulus Response Echo for response time data. They are run separately because there is a limited number of trials that can be run when combining the two (using Digital Stimulus Capture and Response) with our BBTK, but with these two methods we can run 1000 trials without any problems. The BBTK module is in the PsychoPy code already :)

runBBTK.zip

@hoechenberger

This comment has been minimized.

Copy link
Member Author

commented Feb 4, 2019

Great, thank you!

@cbrnr

This comment has been minimized.

Copy link
Contributor

commented Feb 26, 2019

Not sure if this is related, but I have severe issues with visual timing on my MacBook Pro (Mid-2014) running Mojave 10.14.3 (PsychoPy 3.0.4): win.getActualFrameRate() gives me values around 430 (with pretty high variance). I've tried this with the internal display as well as with an external one (both run at 60Hz), but I get these values for both internal and external displays. I've also tried the pyglet and glfw backends, but the problem seems to be independent of the backend.

@peircej

This comment has been minimized.

Copy link
Member

commented Feb 26, 2019

No, I think that's unrelated. The issue I mention is about an offset of 1 frame but the sync to refresh is stable.
Your machine says the frame rate is 430?! That's something pretty broken, that I've never seen on a mac. On windows this would indicate that you weren't synching to the screen refresh but on a mac I've never had that problem.
Could you upload the graph from timeByFrames (in the demo menu) here?

@cbrnr

This comment has been minimized.

Copy link
Contributor

commented Feb 26, 2019

Here's the graph:
figure_1

@oschmidtmann

This comment has been minimized.

Copy link

commented Feb 26, 2019

@cbrnr Your frame times should variate around 1/60 (16.67) ms. Your frame times are around 50. This is very odd. One important factor for MacBooks for me was to use a single display only. Otherwise the fps deviations got higher. For testing I'd suggest to physically detach the external one.

But there seems to be another issue. Have you tried to build a very simple test with just one shape being drawn one time before win.flip? This is a good point to start. Especially core.wait (including waitkeys!) may cause a high load.

Also: the spike around frame 450 may be related to your programming – which is hard to say. It might also be worthwhile to shut down all possible processes (like timemachine, spotlight indexing, any cloud syncs etc.). If this does not help you might want introduce certain points in your code at which you print the current frame and the time to find the bottleneck.
Good luck!

@cbrnr

This comment has been minimized.

Copy link
Contributor

commented Feb 26, 2019

Yes, with the internal display I do get the expected output graph using the pyglet backend but not the glfw backend. However, in all cases (even in the case with only using the internal display and pyglet) I do get strangely high values around 400 from win.getActualFrameRate().

@peircej should I open a separate issue?

Edit: It seems like I forgot to set fullscr=True. So the (only?) combination that works on my Mac is using pyglet, fullscr=True, and the internal display. All other variants produce weird results.

@peircej

This comment has been minimized.

Copy link
Member

commented Feb 26, 2019

I'm confused what you refer to when you say 450.

  • I thought you meant the frame rate (450 frames per second) which would have meant that you weren't syncing to the flip.
  • In fact your frame times are roughly 50ms, which indicates the opposite problem: frames are being dropped pretty consistently. Were you meaning 450 ms?
  • But in the graph on the left there's a single frame that's taking a very long time at frame number 450 or so. Is that what you were talking about. That indicates some other issue, that the computer is suddenly spending time doing something or other (like synchronising with dropbox, or checking the weather!....)

If everything looks normal without the external monitor connected but does this when you connect a display then I think it's something to do with you laptop trying to synchronise two displays that might not even have the same native frequency). If you consistently get this spike around frame 450 it might be taking that long for the machine to detected the fullscreen mode and then does does something like re-sync with the 2 displays. There are lots of variables here (like the mode of screens, mirroring or not) and how they are set up (optimized for external etc).

You might also try just turning off the window waitblanking setting because that might be interacting badly with your operating system trying to perform this 2-screen sync.

But critically, could you try and always give the unit when you mention a number, because it dramatically changes what the number means! ;-)

@cbrnr

This comment has been minimized.

Copy link
Contributor

commented Feb 27, 2019

OK, sorry for the confusion. There are a lot of parameters here that I didn't explain clearly, so maybe it's best to present them in a table. The last column shows the output of win.getActualFrameRate(), which is the frame rate in Hz. I use PsychoPy 3.0.4 running on Python 3.7.2.

macOS 10.14.3

Here are the results if I run the visualization on my external display:

winType fullscr waitBlanking getActualFrameRate()
pyglet True True None
pyglet True False None
pyglet False True 380.07
pyglet False False 511.33
glfw True True 455.39
glfw True False 539.14
glfw False True 401.31
glfw False False 508.77

And here's how these values look like on my internal display:

winType fullscr waitBlanking getActualFrameRate()
pyglet True True 59.85
pyglet True False None
pyglet False True 440.07
pyglet False False 639.94
glfw True True 90.95
glfw True False None
glfw False True 473.26
glfw False False 623.38

Obviously, I get the expected frame rate of 60Hz only on my internal display using winType="pyglet", fullscr=True, and waitBlanking=True.

Arch Linux

I only have one display on that machine (Xorg, proprietary nvidia driver):

winType fullscr waitBlanking getActualFrameRate()
pyglet True True 29.98
pyglet True False 59.98
pyglet False True 29.97
pyglet False False 59.98
glfw True True 60.31
glfw True False 60.35
glfw False True 60.33
glfw False False 60.34

On Linux, all combinations seem to work except for the (known) issue that I only get half the frame rate if I set waitBlanking=True in combination with winType="pyglet" (it would be super nice if this issue was resolved, because currently the only configuration that works on macOS does not work on Linux). Plus, waitBlanking doesn't have the desired effect since vsync seems to be always enabled no matter what.

Script

Here's the script to produce this table in case anyone wants to try it on their machine:

from psychopy import core, visual


wintypes = ["pyglet", "glfw"]
fullscreen = [True, False]
vsync = [True, False]

table = ("winType | fullscr | waitBlanking | getActualFrameRate()\n"
         "------- | ------- | ------------ | --------------------\n")

for wintype in wintypes:
    for fullscr in fullscreen:
        for waitblank in vsync:
            table += f"{wintype:7} | {str(fullscr):7} | {str(waitblank):12} | "
            win = visual.Window(winType=wintype, fullscr=fullscr,
                                waitBlanking=waitblank)
            framerate = win.getActualFrameRate()
            win.close()
            if framerate is None:
                table += f"{'None':>20}\n"
            else:
                table += f"{framerate:20.2f}\n"
print()
print(table)
core.quit()
@cbrnr

This comment has been minimized.

Copy link
Contributor

commented Feb 28, 2019

I ran the script on our Windows machine with a 120Hz monitor, here's the output:

winType fullscr waitBlanking getActualFrameRate()
pyglet True True 119.99
pyglet True False 119.99
pyglet False True 120.21
pyglet False False 119.87
glfw True True 60.32
glfw True False 60.34
glfw False True 118.14
glfw False False 120.92

On this platform, only glfw doesn't seem to work correctly in fullscreen mode.

@isolver

This comment has been minimized.

Copy link
Contributor

commented Mar 8, 2019

Re the extra 1 frame delay on newer versions of macOS, I've have also seen this on macOS 10.13.6 testing with the MilliKey light sensor. The exact same script on the same computer running in a 10.9.5 partition shows no extra frame delay. I think @peircej also reproduced this in his lab?

From what I gather, macOS < 10.13 is fine, but anything >= 10.13 has a 1 frame delay when tested with a light key.

@mdcutone

This comment has been minimized.

Copy link
Member

commented Mar 13, 2019

@cbrnr

On this platform, only glfw doesn't seem to work correctly in fullscreen mode.

Try using the argument 'swapInterval=1' when using GLFW in fullscreen mode. GLFW has multiple v-sync settings and I think waitBlanking might not be setting it correctly.

@cbrnr

This comment has been minimized.

Copy link
Contributor

commented Mar 14, 2019

@mdcutone unfortunately, this didn't seem to have any effect. It's still showing as 60Hz.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
8 participants
You can’t perform that action at this time.