Forum Discussion

oomzay's avatar
oomzay
Visitor
9 years ago

Regression: screen.swapBuffers() held of till after VSYNC

I just re-ran an old test [viewtopic.php?f=34&t=83900]that was designed to illustrate a different problem, and observed that what was once a rock-steady 60 FPS animation now suffers frequent (> 1/sec) judders.

The displayed moving average frame time for fast (< 10mSec) animations used to be rock steady at 16.666 uSecs, now it averages greater than 16.900 uSecs. This is because the call to screen.swapBuffers() is frequently not returning until 20 or 30 mSecs after the previous swapBuffers()/VSYNC instead of 16.666 mSecs later as was the case before.

Is there a bug tracking system?

Test configuration
-----------------------
Model: 2400SK (Roku LT)
Firmware Version: 075.05E00430A - No Jitter
Firmware Version: 077.00E09593A - Jitter

9 Replies

  • Correction: Those units should read mSecs (milliseconds) not uSecs (microseconds).
  • Any chance that "adaptive VSYNC" can something to do with it?
    See this viewtopic.php?f=34&t=54513#p490795
    It's a very obscure topic, there might be only a single person at RokuCo that understands it, rest comes with some external library.
  • > Any chance that "adaptive VSYNC" can something to do with it?

    No. Adaptive VSYNC could explain (*1 & *2) why frames that take longer than 16.66 mSecs to draw then subsequently fail to swap to the screen after an exact multiple of 16.66 mSecs and hence tear. Indeed this was the problem that the test was originally developed to demonstrate. However I am now (firmware version 7.00) observing that even frames that take only 5 mSecs to draw are often (~1 per second) failing to swap on the next VSYNC. This means that even a very simple 60FPS animations gets the judders/jaggies - which is very shoddy.

    Notes
    1: I originally received a quite different explanation from Roku. [viewtopic.php?f=34&t=83540#p479247]
    2. The GL EXT_swap_control_tear feature is anyway a "horrible hack" for people who fail to manage their rendering detail/animation complexity properly. If Roku are enabling this feature by default then they must provide an API to disable it because it totally sucks for accurately scheduled applications. This would also allow it to be eliminated from this enquiry. (I am not even sure this is the case on this platform)
  • On (1), to me the explanation sounds like adaptive_VSYNC explained in "human terms"
    On (2), i doubt giving the per-app option to disable it is feasible. I bet will be major mess, like enabling 24 Hz video output.
    Also, i don't think adaptive_VSYNC is a bad thing because it shouldn't affect "accurately scheduled applications". As long as you stay under 16ms, it won't be kicking in. OTOH it will save sloppier apps from sudden, discrete drops from 60 to 30 to 15fps - at the price of judder possibility.

    This said, indeed adaptive vsync would not explain what you describe, 1/sec tearing with fast draw. Can you post a short&sweet sample code that demonstrates this one problem? Would improve likelihood of response.

    Let's see what Roku* says - give it a week or two and if no response here, email developer at roku.com and keep bugging them
  • > i doubt giving the per-app option to disable [adpative VSYYNC] is feasible. I bet will be major mess, like enabling 24 Hz video output.

    Not sure why you think this is infeasable and messy. The mode is changed by the interval parameter passed to glXSwapIntervalEXT(dpy, drawable, interval); Make the default interval be -1 by all means, and restore the default when apps exits.

    > i don't think adaptive_VSYNC is a bad thing because it shouldn't affect "accurately scheduled applications". As long as you stay under 16ms [my emphasis]

    There are situations where a deliberate and rock steady 30 FPS is more acceptable than trying and failing to deliver 60FPS, plus we really don't want to see tearing when pushing a completely new frame after a few seconds of idle! With adaptive_VSYNC  enabled we have to shadow the screen's buffers and keep re-pushing the last frame every ~16mSecs to avoid tearing on the next frame whenever that is ready - which is a big waste of scarce CPU time and memory.

    > Can you post a short&sweet sample code that demonstrates this one problem?

    Yes. I will do that.
  • Below is a script that demonstrates the ~1 per second glitch I am observing on 2400SK (Firmware: 077.00E09593A) with a simple 60FPS animation:-


    ' ----------------------------------------------------------------------------
    ' Vertical Synchronisation Glitch Demo
    '
    ' On some platforms there is now (7.00 firmware) an intermittent
    ' (~1 per second) failure to SwapBuffers at 60FPS, even for animation times
    ' less than 4mSecs.
    '
    ' This can be observed as tearing and/or juddering of the vertical bars
    ' and is reflected in the displayed frame times. The average should
    ' settle to 16,666 uSecs, the instantaneous value should dither between
    ' 16 and 17 mSecs.
    '
    ' - left/right buttons adjust simulated animation time +/-1 ms
    ' ----------------------------------------------------------------------------

    Library "v30/bslCore.brs"

    ' ----------------------------------------------------------------------------
    ' ----------------------------------------------------------------------------

    sub main ()

        ' Log system info so we know when we are comparing chalk and cheese
        '
        log_system_info()
        
        ' Handy Facts
        '
        VIDEO_FIELD_MS = 1000.0 / 60.0

        ' Initialise various resources
        '
        ecodes = bslUniversalControlEventCodes()
        clk = CreateObject("roTimespan")
        port = CreateObject("roMessagePort")
        screen = CreateObject("roScreen", TRUE)
        screen.SetMessagePort(port)    
            
        ' Prepare font to display statistics on screen
        '
        font = CreateObject("roFontRegistry").GetDefaultFont()
        txt_height = font.getOneLineHeight()
        txt_color = &h60ff60ff
        txt_margin = 100
        
        ' Create some animated stripes to illustrate tearing and judders.
        '
        num_stripes = 10
        stripes = []
        for x = 0 to screen.getWidth()-1 step screen.getWidth()/num_stripes
            stripes.push(VerticalStripe(screen.getWidth(), screen.getHeight(), x))
        end for
            
        ' Simulated frame animation time (target & moving average)
        '
        animation_target_ms = 4
        animation_avg_filter = jcEWMAFilter(0.995, animation_target_ms * 1000)
        last_animation_overrun_ms = animation_target_ms

        ' Frame timing stats.
        '
        last_frame_start = INVALID
        frame_avg_filter = jcEWMAFilter(0.995, VIDEO_FIELD_MS * 1000)
        last_frame_overrun_ms = 17

        ' Do initial buffer swap before we start timing loop
        '
        screen.clear(0)
        screen.SwapBuffers()        
        screen.clear(0)

        ' Spin around SwappingBuffers and monitoring how long field/frame takes.
        '
        while TRUE       

            screen.SwapBuffers()
            this_frame_start = clk.TotalMilliseconds()

            ' Handle any events
            ' - left/right buttons adjust simulated animation time +/-1 ms
            '
            msg = port.GetMessage()
            if type(msg)="roUniversalControlEvent" then
                ecode = msg.GetInt()
                if ecode = ecodes.BUTTON_RIGHT_PRESSED then
                    animation_target_ms = animation_target_ms + 1
                else if ecode = ecodes.BUTTON_LEFT_PRESSED then
                    animation_target_ms = animation_target_ms - 1
                else if ecode = ecodes.BUTTON_UP_PRESSED then
                    stop ' debug
                end if
            end if

            screen.clear(0)

            ' Animate & render the vertical stripes
            '
            for each stripe in stripes
                stripe.animate(screen)
            end for
                        
            ' Calculate & render statistics.
            '
            if last_frame_start <> INVALID then

                ' Calc
                last_frame_ms = this_frame_start - last_frame_start
                frame_avg_us = int(frame_avg_filter.update(last_frame_ms * 1000))
                animation_avg_us = int(animation_avg_filter.update(last_animation_ms * 1000))
                if last_frame_ms > 17 then
                    last_frame_overrun_ms = last_frame_ms
                end if
                if last_animation_ms > animation_target_ms then
                    last_animation_overrun_ms = last_animation_ms
                end if

                ' Render
                x = txt_margin
                y = txt_margin
                screen.drawText("Vertical Synchronisation Glitch Demo", x, y, txt_color, font)            
                y = y + 2 * txt_height
                screen.drawText("Animation target: " + animation_target_ms.toStr() + " ms (L = -1, R = +1)", x, y, txt_color, font)            
                y = y + txt_height
                screen.drawText("Animation actual: " + last_animation_ms.toStr() + " ms (Avg: " + animation_avg_us.toStr() + " us, Last overrun: " + last_animation_overrun_ms.toStr() + " ms)", x, y, txt_color, font)                  
                y = y + txt_height
                screen.drawText("Frame actual: " + last_frame_ms.toStr() + "ms (Avg: " + frame_avg_us.toStr() + " us, Last overrun: " + last_frame_overrun_ms.toStr() + " ms)", x, y, txt_color, font)                  

            endif

            ' Spin until the simulated animation time has elapsed.
            '
            this_animation_ms = clk.TotalMilliseconds() - this_frame_start
            while this_animation_ms < animation_target_ms
                this_animation_ms = clk.TotalMilliseconds() - this_frame_start
            end while

            ' Go round again
            '
            last_frame_start = this_frame_start
            last_animation_ms = this_animation_ms
        end while
    end sub

    ' ----------------------------------------------------------------------------
    ' Animated Vertical White Stripe
    ' ----------------------------------------------------------------------------

    function VerticalStripe (cw as Integer, ch as Integer, x0 as Integer) as Object

        this = {}
        
        this.cw = cw
        this.x = x0
        this.w = 50
        this.h = ch
        this.dx = 4
        this.clr = &h808080ff
        
        ' Animate and render this stripe to canvas.
        '
        this.animate = function (canvas as Object) as Void

            this = m

            this.x = this.x + this.dx
            if this.x > this.cw then
                this.x = this.x - (this.cw + this.w)
            end if        

            canvas.drawRect(this.x, 0, this.w, this.h, this.clr)   
         
        end function
           
        return this

    end function

    ' ----------------------------------------------------------------------------
    ' Exponentially Weighted Moving Average (EWMA) filter
    '
    ' Yt =  Xt  + α ( Yt-1 - Xt)
    ' ----------------------------------------------------------------------------

    function jcEWMAFilter(alpha as Float, avg0 as Float) as Object

        this = {}    
        
        this.alpha = alpha
        this.avg = avg0
                
        ' Insert new sample, returns updated average.
        '
        this.update = function (x as Float) as Float
            this = m
            this.avg = x + (this.alpha * (this.avg - x))
            return this.avg
        end function
            
        return this

    end function

    ' ----------------------------------------------------------------------------
    ' Log basic system info
    ' ----------------------------------------------------------------------------

    sub log_system_info()

        di = CreateObject("roDeviceInfo")    
        print "          Device: "; di.GetDeviceUniqueId()
        print "           Model: "; di.GetModel(); " ("; di.GetModelDisplayName(); ")"
        print "Firmware Version: "; di.GetVersion()

        md = di.GetModelDetails()
        print "     Vendor Name: "; md.VendorName
        print "    Model Number: "; md.ModelNumber

        ai = CreateObject("roAppInfo")    
        print "             App: "; ai.GetTitle(); " ("; ai.GetVersion(); ")"
        print "           DevID: "; ai.GetDevID()

    end sub
  • Could someone at roku comment on this please? This loss of sync once per second or so is really messing up what used to be a rock steady 60 fps animation. Thanks.
  • Below is an almost minimal swap-period logging app that can be used to test for this regression:-
    ' ----------------------------------------------------------------------------
    ' Frame Swap Duration Logger
    '
    ' This app creates a double-buffered roScreen and spins in a loop clearing the
    ' screen to black, swapping the buffers, and logging the inter-swap period to
    ' the debug console.
    '
    ' This is for the purpose of checking that bufferswap() remains locked to vsync.
    '
    ' If all is well the millisecond resolution times should dither between 16 & 17
    ' with a long term average of _exactly_ 16.666 mSecs. Any times outside this range
    ' indicate a loss of vsync and will cause judder and/or tearing in real applications.
    '
    ' You should see absolutely nothing on the screen!
    '
    ' In the log (via telnet) you should see frame timings like this:-
    '
    ' If all is well (e.g. f/w 5.05):-
    '
    ' 17
    ' 16
    ' 17
    ' 17
    ' 16
    ' 17
    '
    ' If vsync is being missed badly (e.g. f/w 7.00):-
    '
    ' 16
    ' 17
    ' 25
    ' 25
    ' 18
    ' 15
    ' 17
    '
    ' This output can be processed by an automated regression testing framework
    ' to detect loss of sync.
    ' ----------------------------------------------------------------------------

    sub main ()

        clk = CreateObject("roTimespan")
        screen = CreateObject("roScreen", TRUE)

        last_frame_start = INVALID
        screen.clear(0)

        while TRUE
            screen.SwapBuffers()
            this_frame_start = clk.TotalMilliseconds()
            screen.clear(0)
            if last_frame_start <> INVALID then
                print (this_frame_start - last_frame_start).toStr()
            end if
            last_frame_start = this_frame_start
        end while

    end sub