james_lohr's picture

VSync issue

I'm currently getting unexpected results with VSync.

This literally takes 1 minute to recreate:

Take the QuickStart example and add logging code to the OnRenderFrame method using System.Diagnostics.StopWatch to measure the time between calls to the method.

The results are posted below.

My machine is a beast and runs the QuickStart demo at ~15000 fps if I turn off VSync, so it can't be anything to do with my system struggling.

The results:

ticks: 33.13464
ticks: 0.07139169
ticks: 15.77021
ticks: 16.48787
ticks: 16.49044
ticks: 16.4806
ticks: 16.49385
ticks: 16.49797
ticks: 16.97414
ticks: 16.00023
ticks: 33.15481
ticks: 0.06767362
ticks: 32.91978
ticks: 0.07110124
ticks: 32.91439
ticks: 0.06753439
ticks: 32.92782
ticks: 0.06756329
ticks: 32.92101
ticks: 0.07141045
ticks: 33.40022
ticks: 0.06771039
ticks: 32.4365
ticks: 0.06974392
ticks: 16.26222
ticks: 33.14958
ticks: 0.06716101
ticks: 32.91126
ticks: 0.06760682
ticks: 32.9221
ticks: 0.06766123
ticks: 32.9231
ticks: 0.06751788
ticks: 33.40296
ticks: 0.06757905
ticks: 32.43908
ticks: 0.06756329
ticks: 32.87897
ticks: 0.06782597
ticks: 32.92503
ticks: 0.06785599
ticks: 33.41447
ticks: 0.06761695
ticks: 32.44505
ticks: 0.06745221
ticks: 32.92596
ticks: 0.06744546
ticks: 32.92983
ticks: 0.06739442
ticks: 16.2604
ticks: 16.49591
ticks: 33.15328
ticks: 0.06753589
ticks: 32.92304
ticks: 0.06764472
ticks: 32.90973
ticks: 0.06780908
ticks: 32.92807
ticks: 0.06745671
ticks: 33.41536
ticks: 0.06747773
ticks: 32.44619
ticks: 16.49636
ticks: 0.06765485
ticks: 32.93631
ticks: 0.06749912
ticks: 33.40794
ticks: 0.07091586
ticks: 32.44439
ticks: 0.06734977
ticks: 32.91516
ticks: 0.06705519
ticks: 33.4212
ticks: 0.07098904
ticks: 32.44051
ticks: 0.0673978
ticks: 32.93655
ticks: 0.06799709
ticks: 16.25328
ticks: 16.50334
ticks: 17.01293
ticks: 15.98207
ticks: 16.49375
ticks: 16.53736
ticks: 16.47475
ticks: 16.50614
ticks: 16.98101
ticks: 16.5024
ticks: 15.96761
ticks: 16.50377
ticks: 16.49611
ticks: 16.49944
ticks: 16.49305
ticks: 17.0114
ticks: 15.98469
ticks: 16.49686
ticks: 16.49333
ticks: 16.50515
ticks: 16.48506
ticks: 17.01918
ticks: 15.97376
ticks: 16.48689
ticks: 16.51487
ticks: 16.48943
ticks: 16.49404
ticks: 16.50012
ticks: 17.01402
ticks: 15.98233
ticks: 33.1557
ticks: 0.07159846
ticks: 32.9217
ticks: 0.06736328
ticks: 32.93121
ticks: 0.06739217
ticks: 30.84721
ticks: 0.07189529
ticks: 32.6997
ticks: 0.06777381
ticks: 33.42576
ticks: 0.06752576
ticks: 32.47266
ticks: 0.07102581
ticks: 32.9429
ticks: 0.06719891
ticks: 32.95671
ticks: 0.07053872
ticks: 32.9426
ticks: 0.07076913
ticks: 32.94884
ticks: 0.06737228
ticks: 32.94203
ticks: 0.06739555
ticks: 32.95658
ticks: 0.07091474
ticks: 32.94383
ticks: 0.06745784
ticks: 16.3084
ticks: 16.48786
ticks: 33.65186
ticks: 0.07128924
ticks: 15.80729
ticks: 16.49699
ticks: 16.50968
ticks: 16.50558

Something else I tried was timing the "SwapBuffers()" call. The results I got were: sometimes it would take ~16 ms, and sometimes it would take ~0ms. Also, if I measure the time between frames after the call to SwapBuffers(), then I see a consistent 16ms.

So, either I'm misunderstanding VSync, or there is a bug somewhere.

This is what I expect to see:

SwapBuffers() taking ~16ms every frame since this is where the application waits for the VSync (isn't it?).

Instead what appears to be happening is that sometimes the 16ms wait for the Vsync is happening outside of the call to SwapBuffers() (and even before the rendering code has run!).

Any idea what's going on here?