Bug 26240 might have some relevance as it was a similar problem with the same system.

These two issues may be relevant:
http://lists.x.org/archives/xorg-devel/2010-June/009693.html
http://lists.freedesktop.org/archives/dri-devel/2010-June/001110.html

This may be a dupe of bug 28341.

Oddly enough, I can no longer reproduce the flickering. No components have changed in the system, so whatever caused it yesterday must have been some weird state caused by flipping mesa/libdrm versions back and forth.

vsync problem is still present and need investigation though.

Hmm... bad ground work on my part. It seems xbmc did some kind of reset at some point and turned off the vsync setting. Turning it on though results in one frame every five seconds or so. Not really usable...

This was with libdrm and mesa updated to head:

Mesa: 149e709701e0b6ac2c0c820d89db6a3cd32c5f09
DRM: 66375fd6e8d3e95df5d124883a1426460c1b8ed8

Shifting back to the fc13 packages and the flickering is back in place. No frame rate limiting though...

I forgot to mention the kernel versions used.

Before upgrade: 2.6.32.12-115.fc12.x86_64
After upgrade: 2.6.33.5-112.fc13.x86_64

Unfortunately these are Fedora kernels so I'm not sure what DRM stuff is in there.

Been testing different mesa versions to see some kind of pattern:

7.7 branch (mesa_7_6_1_rc1-2602-g0e08054): Low fps
mesa_7_6_1_rc1-3851-g833acea: "just" no sync
7.8 branch (mesa_7_6_1_rc1-5911-gd2f2d0a): Flickering

More pinpointing will follow...

The commit that causes the flickering is:

1ca968363dd55e919bd91c8fc31c34d207af3958 is the first bad commit
commit 1ca968363dd55e919bd91c8fc31c34d207af3958
Author: Jesse Barnes <jbarnes@virtuousgeek.org>
Date:   Fri Mar 5 11:17:19 2010 -0800

    DRI2: expose OML_sync_control if possible
    
    If the server supports the OML related protocol, enable support for the
    extension.

Not too surprising as xbmc uses the OML stuff.

Have you tried the latest 1.8.x X server?  Several fixes landed recently that might affect this...

No, haven't tried replacing the X server as that is the messiest component to swap out. I'll try a compile and just get a custom Xorg binary...

I've now tested with xorg-server-1.8.1.901 and the results are slightly different. Instead of 0.2 fps, I get 2 fps. An increase by a magnitude, but still not useful.

possibly also related to bug 28383.

I wasn't completely correct in my previous comment. Mesa 7.8.1 branch went from flickering to 2 fps. I've now tested master as well and that did however go from 0.2 fps to 2 fps.

Should also note that xbmc is eating 100% CPU now, so I guess it is busy waiting for something.

Has anyone had a look at this? Upgraded to latest mesa today and the problem is still there. Even omlsync in mesa/demos is broken. :/

I did some extra output from omlsync.c:

glXGetSyncValuesOML(disp, winGL, &ust, &msc, &sbc);
fprintf(stderr, "ust: %lld, msc: %lld, sbc: %lld\n", (long long)ust, (long long)msc, (long long)sbc);

Result is this:

ust: 0, msc: 0, sbc: 8912
ust: 0, msc: 0, sbc: 8913
ust: 0, msc: 0, sbc: 8914
ust: 0, msc: 0, sbc: 8915
ust: 0, msc: 0, sbc: 8916
ust: 0, msc: 0, sbc: 8917
ust: 0, msc: 0, sbc: 8918

Doesn't seem correct to me that neither ust nor msc are incrementing.

In regard to comment 2, which resulted in bug 28341, I tried the following in omlsync.c:

        glXSwapBuffersMscOML(disp, winGL, msc, 0, 0);
        glXWaitForSbcOML(disp, winGL, 0, &ust, &msc, &sbc);

Still no syncing.

Regarding comment 15, it's hitting this code in Xorg:

    if (!ds->GetMSC) {
        *ust = 0;
        *msc = 0;
        *sbc = pPriv->swap_count;
        return Success;
    }

(from DRI2GetMSC())

Turns out the DDX I was using (6.13.0) didn't have the GetMSC callback. Using master, I got some more proper values. Unfortunately the result now is that omlsync locks up after a bit. Investigating...

Output from omlsync:

ust: 1278446384416354, msc: 37158, sbc: 0
ust: 1278446384416680, msc: 37158, sbc: 0
(hang)

More digging. The client hangs because the X server ignores the request in this code:

    /*
     * Ensures an out of control client can't exhaust our swap queue, and
     * also orders swaps.
     */
    if (DRI2ThrottleClient(client, pDrawable)) 
        return client->noClientException;

(from ProcDRI2SwapBuffers())

From the looks of it, I guess that code means no reply is sent to the client and it will wait forever.

The server does accept the first SwapBuffer request, but the second triggers that throttle thing.

Looks like some kernel issue. Xorg is calling drmWaitVBlank() with proper arguments as far as I can tell:

    fprintf(stderr, "Current counter: %lld\n", (long long)current_msc);
    fprintf(stderr, "Waiting for %lld (0x%08x)\n", (long long)*target_msc, vbl.request.type);

in radeon_dri2_schedule_swap() results in:

Current counter: 132192
Waiting for 132192 (0x14000000)

A vblank event never occurs though so the Xorg stack just sits there forever.

And turning on debug in the kernel shows that vblank interrupts aren't enabled when this is going on. They are running for a while just as the X server is starting, but then they are disabled again.

Some stuff from dmesg:

[drm:r600_irq_process], IH: D2 vblank
[drm:r600_irq_process], r600_irq_process start: rptr 24736, wptr 24752
[drm:r600_irq_process], IH: D2 vblank
[drm:r600_irq_process], r600_irq_process start: rptr 24752, wptr 24768
[drm:r600_irq_process], IH: D2 vblank
[drm:vblank_disable_fn], disabling vblank on crtc 1
[drm:r600_irq_set], r600_irq_set: vblank 0
[drm:r600_irq_set], r600_irq_set: hpd 1
[drm:r600_irq_set], r600_irq_set: hpd 2

Above is once X is running and idle. Then when starting omlsync:

[drm:drm_stub_open], 
[drm:drm_open_helper], pid = 9962, minor = 0
[drm:drm_ioctl], pid=9962, cmd=0x80046402, nr=0x02, dev 0xe200, auth=1
[drm:drm_add_magic], 37
[drm:drm_getmagic], 37
[drm:drm_ioctl], pid=9952, cmd=0x40046411, nr=0x11, dev 0xe200, auth=1
[drm:drm_authmagic], 37
[drm:drm_remove_magic], 37
[drm:drm_ioctl], pid=9962, cmd=0xc0406400, nr=0x00, dev 0xe200, auth=1
[drm:drm_ioctl], pid=9962, cmd=0xc0406400, nr=0x00, dev 0xe200, auth=1
[drm:drm_ioctl], pid=9962, cmd=0xc0106467, nr=0x67, dev 0xe200, auth=1
[drm:drm_ioctl], pid=9962, cmd=0xc0106467, nr=0x67, dev 0xe200, auth=1
[drm:drm_ioctl], pid=9962, cmd=0xc018645c, nr=0x5c, dev 0xe200, auth=1
[drm:drm_ioctl], pid=9952, cmd=0xc018643a, nr=0x3a, dev 0xe200, auth=1
[drm:drm_wait_vblank], waiting on vblank count 132192, crtc 0
[drm:drm_wait_vblank], returning 132192 to client
[drm:drm_ioctl], pid=9952, cmd=0xc020645d, nr=0x5d, dev 0xe200, auth=1
[drm:drm_ioctl], pid=9952, cmd=0xc008640a, nr=0x0a, dev 0xe200, auth=1
[drm:drm_ioctl], pid=9952, cmd=0xc020645d, nr=0x5d, dev 0xe200, auth=1
[drm:drm_ioctl], pid=9952, cmd=0xc008640a, nr=0x0a, dev 0xe200, auth=1
[drm:drm_ioctl], pid=9952, cmd=0xc008640a, nr=0x0a, dev 0xe200, auth=1
[drm:drm_ioctl], pid=9962, cmd=0xc010640b, nr=0x0b, dev 0xe200, auth=1
[drm:drm_ioctl], pid=9962, cmd=0xc00c6469, nr=0x69, dev 0xe200, auth=1
[drm:radeon_gem_get_tiling_ioctl], 
[drm:drm_ioctl], pid=9962, cmd=0xc010640b, nr=0x0b, dev 0xe200, auth=1
[drm:drm_ioctl], pid=9962, cmd=0xc00c6469, nr=0x69, dev 0xe200, auth=1
[drm:radeon_gem_get_tiling_ioctl], 
[drm:drm_ioctl], pid=9962, cmd=0xc018643a, nr=0x3a, dev 0xe200, auth=1
[drm:drm_wait_vblank], waiting on vblank count 132192, crtc 0
[drm:drm_wait_vblank], returning 132192 to client
[drm:drm_ioctl], pid=9962, cmd=0xc020645d, nr=0x5d, dev 0xe200, auth=1
[drm:drm_ioctl], pid=9962, cmd=0xc020645e, nr=0x5e, dev 0xe200, auth=1
[drm:drm_ioctl], pid=9962, cmd=0xc0086464, nr=0x64, dev 0xe200, auth=1
[drm:drm_ioctl], pid=9962, cmd=0xc020645d, nr=0x5d, dev 0xe200, auth=1
[drm:drm_ioctl], pid=9962, cmd=0xc020645e, nr=0x5e, dev 0xe200, auth=1
[drm:drm_ioctl], pid=9962, cmd=0xc0086464, nr=0x64, dev 0xe200, auth=1
[drm:drm_ioctl], pid=9962, cmd=0xc020645d, nr=0x5d, dev 0xe200, auth=1
[drm:drm_ioctl], pid=9962, cmd=0xc020645e, nr=0x5e, dev 0xe200, auth=1
[drm:drm_ioctl], pid=9962, cmd=0xc0086464, nr=0x64, dev 0xe200, auth=1
[drm:drm_ioctl], pid=9952, cmd=0xc018643a, nr=0x3a, dev 0xe200, auth=1
[drm:drm_wait_vblank], waiting on vblank count 132192, crtc 0
[drm:drm_wait_vblank], returning 132192 to client
[drm:drm_ioctl], pid=9962, cmd=0xc020645d, nr=0x5d, dev 0xe200, auth=1
[drm:drm_ioctl], pid=9962, cmd=0xc020645e, nr=0x5e, dev 0xe200, auth=1
[drm:drm_ioctl], pid=9962, cmd=0xc0086464, nr=0x64, dev 0xe200, auth=1
[drm:drm_ioctl], pid=9952, cmd=0xc018643a, nr=0x3a, dev 0xe200, auth=1
[drm:drm_wait_vblank], waiting on vblank count 132192, crtc 0
[drm:drm_wait_vblank], returning 132192 to client
[drm:drm_ioctl], pid=9952, cmd=0xc018643a, nr=0x3a, dev 0xe200, auth=1
[drm:drm_wait_vblank], waiting on vblank count 132192, crtc 0
[drm:drm_wait_vblank], returning 132192 to client
[drm:drm_ioctl], pid=9952, cmd=0xc018643a, nr=0x3a, dev 0xe200, auth=1
[drm:drm_queue_vblank_event], event on vblank count 132193, current 132192, crtc 0
[drm:drm_ioctl], pid=9962, cmd=0xc020645d, nr=0x5d, dev 0xe200, auth=1
[drm:drm_ioctl], pid=9962, cmd=0xc020645e, nr=0x5e, dev 0xe200, auth=1
[drm:drm_ioctl], pid=9962, cmd=0xc0086464, nr=0x64, dev 0xe200, auth=1
[drm:drm_ioctl], pid=9962, cmd=0xc020645d, nr=0x5d, dev 0xe200, auth=1
[drm:drm_ioctl], pid=9962, cmd=0xc020645e, nr=0x5e, dev 0xe200, auth=1
[drm:drm_ioctl], pid=9962, cmd=0xc0086464, nr=0x64, dev 0xe200, auth=1
[drm:drm_ioctl], pid=9962, cmd=0xc020645d, nr=0x5d, dev 0xe200, auth=1
[drm:drm_ioctl], pid=9962, cmd=0xc020645e, nr=0x5e, dev 0xe200, auth=1
[drm:drm_ioctl], pid=9962, cmd=0xc0086464, nr=0x64, dev 0xe200, auth=1
[drm:drm_ioctl], pid=9962, cmd=0xc020645d, nr=0x5d, dev 0xe200, auth=1
[drm:drm_ioctl], pid=9962, cmd=0xc020645e, nr=0x5e, dev 0xe200, auth=1
[drm:drm_ioctl], pid=9962, cmd=0xc0086464, nr=0x64, dev 0xe200, auth=1
[drm:drm_ioctl], pid=9952, cmd=0xc018643a, nr=0x3a, dev 0xe200, auth=1
[drm:drm_wait_vblank], waiting on vblank count 132192, crtc 0
[drm:drm_wait_vblank], returning 132192 to client

Sounds like a potential problem with the radeon drm driver...

the vbltest program from libdrm tests just the events by themselves, that can help verify if events are working at all.

It could be that X is waiting on a disabled pipe or something, you wouldn't generally see events from that.

vbltest does indeed indicate some problem:

[root@hugin vbltest]# ./vbltest
trying to load module i915...failed.
trying to load module radeon...success.
starting count: 13013
select timed out or error (ret 0)
select timed out or error (ret 0)
select timed out or error (ret 0)
select timed out or error (ret 0)

But if I turn off X (still KMS though):

[root@hugin vbltest]# ./vbltest
trying to load module i915...failed.
trying to load module radeon...success.
starting count: 13289
freq: 60.27Hz
freq: 60.02Hz
freq: 60.02Hz
freq: 60.02Hz
freq: 60.02Hz

However! This works with X running:

[root@hugin vbltest]# ./vbltest -s
trying to load module i915...failed.
trying to load module radeon...success.
starting count: 9081
freq: 60.85Hz
freq: 60.02Hz
freq: 60.02Hz
freq: 60.02Hz



Could there be some confusion about pipes here?

On Wed,  7 Jul 2010 12:04:55 -0700 (PDT)
bugzilla-daemon@freedesktop.org wrote:

> https://bugs.freedesktop.org/show_bug.cgi?id=28410
> 
> --- Comment #25 from Pierre Ossman <pierre-bugzilla@ossman.eu> 2010-07-07 12:04:55 PDT ---
> However! This works with X running:
> 
> [root@hugin vbltest]# ./vbltest -s
> trying to load module i915...failed.
> trying to load module radeon...success.
> starting count: 9081
> freq: 60.85Hz
> freq: 60.02Hz
> freq: 60.02Hz
> freq: 60.02Hz
> 
> 
> 
> Could there be some confusion about pipes here?

Yeah, looks like X uses a different pipe config than fbcon.  That would
explain the above at least.

Now you just need to check the X code to be sure it's getting things
right...

Noteworthy is also that drm-next is need to get any working condition. Backward compatibility with older kernels seem to be a little lacking here guys. ;)

On Wed,  7 Jul 2010 12:17:52 -0700 (PDT)
bugzilla-daemon@freedesktop.org wrote:

> https://bugs.freedesktop.org/show_bug.cgi?id=28410
> 
> --- Comment #27 from Pierre Ossman <pierre-bugzilla@ossman.eu> 2010-07-07 12:17:52 PDT ---
> Noteworthy is also that drm-next is need to get any working condition. Backward
> compatibility with older kernels seem to be a little lacking here guys. ;)

DRI2 didn't support any of the vsync related extensions until both the
kernel vblank event support landed and support for the new DRI2
protocol bits landed in the X server and DDX drivers.  So compat with
older kernels (i.e. kernels w/o vblank event support) isn't really
possible.

Bingo! Xorg thinks it is using the primary pipe, but is actually using the secondary pipe. Doing some ugly hacks makes omlsync work. Haven't tested xbmc yet.

So where should the problem be? Where does Xorg associate pipes with CRTCs?

(In reply to comment #28)
> 
> DRI2 didn't support any of the vsync related extensions until both the
> kernel vblank event support landed and support for the new DRI2
> protocol bits landed in the X server and DDX drivers.  So compat with
> older kernels (i.e. kernels w/o vblank event support) isn't really
> possible.

But couldn't there be a fallback to whatever mechanism was in place with the initial interrupt support? OpenGL vsync was fine with Xorg 1.7.x and Fedora's 2.6.32 kernel.

Although I appreciate the lack of manpower, this whole business of having very narrow compatibility windows between the different graphics components makes testing very difficult. :/

On Wed,  7 Jul 2010 12:38:09 -0700 (PDT)
bugzilla-daemon@freedesktop.org wrote:

> https://bugs.freedesktop.org/show_bug.cgi?id=28410
> 
> --- Comment #30 from Pierre Ossman <pierre-bugzilla@ossman.eu> 2010-07-07 12:38:09 PDT ---
> (In reply to comment #28)
> > 
> > DRI2 didn't support any of the vsync related extensions until both the
> > kernel vblank event support landed and support for the new DRI2
> > protocol bits landed in the X server and DDX drivers.  So compat with
> > older kernels (i.e. kernels w/o vblank event support) isn't really
> > possible.
> 
> But couldn't there be a fallback to whatever mechanism was in place with the
> initial interrupt support? OpenGL vsync was fine with Xorg 1.7.x and Fedora's
> 2.6.32 kernel.

Ah yeah there were some bits that worked sometimes, but they didn't
have any knowledge of pipe configuration, so they'd only work in
certain configs.  There's no easy way to fall back to that...

> Although I appreciate the lack of manpower, this whole business of having very
> narrow compatibility windows between the different graphics components makes
> testing very difficult. :/

Yes, it is a pain.  Things have slowed down a lot recently though; it's
much better than when we were first developing TTM, GEM and KMS at
least. :)

As for the pipe config error you found, I think that's probably a DDX
driver bug.  If the DDX doesn't pass the right flags to drm_wait_vblank
you'll see timeouts, so maybe the DDX isn't detecting which pipe to
wait on properly?

Seems like I had an old xorg.conf still around. Removing it seems to clear things up.

This is the conf:

# Xorg configuration created by pyxf86config

Section "ServerLayout"
        Identifier     "Default Layout"
        Screen      0  "Screen0" 0 0
EndSection

Section "ServerFlags"
        Option      "AutoAddDevices" "false"
EndSection

Section "Extensions"
#       Option      "Composite" "Disable"
EndSection

Section "Device"
        Identifier  "ATI"
        Driver      "radeon"
#       BusID       "PCI:1:5:0"
        Option      "AccelMethod" "EXA"
        Option      "DRI" "on"
#       Option      "EXAVSync" "off"
#       Option      "DMAForXv" "on"
#       Option      "noint10" "true"
EndSection

Section "Monitor"
        Identifier  "DVI-0"
        Option      "Enable" "yes"
        ModeLine    "HDTV" 71.2 1360 1424 1536 1792 768 771 777 795
        Option      "PreferredMode" "HDTV"
EndSection

Section "Screen"
        Identifier "Screen0"
        Device     "ATI"
        DefaultDepth     24
        SubSection "Display"
                Viewport   0 0
                Depth     24
#               Virtual   2720 768
        EndSubSection
EndSection


DVI-0 was unused, and therefore probably forced on here. Not really something I wanted or needed, but it still shouldn't cause problems like this.

Created attachment 36844 [details] [review]
return the proper crtc_id

Return the crtc_id, not the counter value.  They are not
necessarily the same.

Patch did not fix the issue, I'm afraid.

Removed xorg.conf and tested xbmc. It is now frame rate limited to 60 Hz, but there is some bad buffer handling that causes quite a bit of flickering. Might be bug 28341.

> --- Comment #28 from Jesse Barnes <jbarnes@virtuousgeek.org> 2010-07-07 12:22:31 PDT ---
> DRI2 didn't support any of the vsync related extensions until both the
> kernel vblank event support landed and support for the new DRI2
> protocol bits landed in the X server and DDX drivers.  So compat with
> older kernels (i.e. kernels w/o vblank event support) isn't really
> possible.
> 
it's not possible to only advertise support for those vsync related
extensions if the support is actually there?

On Wed,  7 Jul 2010 13:34:59 -0700 (PDT)
bugzilla-daemon@freedesktop.org wrote:

> https://bugs.freedesktop.org/show_bug.cgi?id=28410
> 
> --- Comment #36 from Julien Cristau <jcristau@debian.org> 2010-07-07 13:34:59 PDT ---
> > --- Comment #28 from Jesse Barnes <jbarnes@virtuousgeek.org> 2010-07-07 12:22:31 PDT ---
> > DRI2 didn't support any of the vsync related extensions until both the
> > kernel vblank event support landed and support for the new DRI2
> > protocol bits landed in the X server and DDX drivers.  So compat with
> > older kernels (i.e. kernels w/o vblank event support) isn't really
> > possible.
> > 
> it's not possible to only advertise support for those vsync related
> extensions if the support is actually there?

Yeah, we try to.  If the DDX doesn't support the interfaces, the X
server won't list them in the GLX server extensions string.

Tried the ugly hack from Dänzer, but it didn't fix the flickering with xbmc unfortunately.

Also tried adding a call to glXWaitForSbcOML() as suggested in bug 28341, but no luck with that either. :/

Hacking xbmc to use plain ol' glXSwapBuffers() makes everything work properly though, so it would seem like it's only the OML_sync_control extension that's broken.

Does reverting xf86-video-ati Git commit 30591320ec46e491ba20904cc64f3405b51c6505 ('kms: add support for the MSC swap & sync API') fix this problem?

Created attachment 37036 [details] [review]
 Revert xf86-video-ati commit 30591320ec46e491ba20904cc64f3405b51c6505

Here's a patch against current xf86-video-ati Git master with the conflicts resolved.

No noticeable effect. Flickering is still there. Didn't brake the frame rate limiting though, so it's not worse either...

Installed the final patch from bug 28341 and it solved the flickering issue. So now OpenGL vsync seems to be back to a fully working state.

What do you want to do with this bug? There is still a remaining issue of vsync breaking if you have a disconnected output that's forced on. It doesn't affect me anymore, but it's still a bug.

Can you elaborate on the bug when one output is forced on ? What exactly is the bug ?

Hmm... I guess we had that discussion on irc. Anyway, the problem seemed to boil down to:

CRTC 0 is forced on (via xorg.conf) and disconnected
CRTC 1 is on and connected

Somehow this caused confusion between userspace and the kernel as to which CRTC is which. This caused vblank events to not be delivered as userspace asked for CRTC 1 but the kernel only considered CRTC 0 to be running.

Alex Deucher guessed that some parts of the kernel might be looking at connect state instead of on/off. Didn't really investigate further as I had no need to force an output on so my immediate problem was solved.

Mass closure: This bug has been untouched for more than six years, and is not
obviously still valid. Please reopen this bug or file a new report if you continue to experience issues with current releases.