hang in drmGetLock (was: Fix xserver build)

[Edgar Toernig]

Michel Dänzer wrote:
>
> On Wed, 2006-10-11 at 01:01 +0200, Edgar Toernig wrote:
> >
> > Anyway, the hangs I mentioned in the original posting (using
> > indirect rendering, i.e. glxinfo -i) are still happening
> > occasionally.  So the timed scheduler wasn't the culprit.
> > Here's a backtrace in case somebody wants to dig into it:
> >
> > [...]
> > #4  0xa7e355a9 in ioctl () from /lib/tls/libc.so.6
> > #5  0xa7fd4183 in drmGetLock (fd=8, context=8, flags=0) at xf86drm.c:1221
> > #6  0x9f82ba43 in r200GetLock (rmesa=0x9d9c188, flags=0) at r200_lock.c:87
> > #7  0x9f828ddd in r200GetBufferSize (buffer=0x9d95c00, width=0x0, height=0x0) at r200_context.c:98
> > #8  0x9f94b034 in _mesa_resizebuffers (ctx=0x9da5a58) at buffers.c:609
> > #9  0x9f85dacd in _mesa_make_current (newCtx=0x9da5a58, drawBuffer=0x9d95c00, readBuffer=0x9d95c00) at context.c:1717
> > #10 0x9f829b5e in r200MakeCurrent (driContextPriv=0x986da80, driDrawPriv=0x9d95b98, driReadPriv=0x0) at r200_context.c:704
> > #11 0x9f825dcc in DoBindContext (dpy=0x0, draw=12582914, read=12582914, ctx=0x0, modes=0x820da08, psp=0x821c790) at dri_util.c:343
> > #12 0x9f825e38 in driBindContext (dpy=0x0, scrn=0, draw=12582914, read=12582914, ctx=0x986da68) at dri_util.c:376
> > #13 0xa7ce5119 in __glXDRIcontextMakeCurrent (baseContext=0xaffff4f0) at glxdri.c:246
> > #14 0xa7cc3f06 in DoMakeCurrent (cl=0x83f1550, drawId=12582914, readId=12582914, contextId=12582915, tag=0) at glxcmds.c:649
> > #15 0xa7cc411f in __glXDisp_MakeCurrent (cl=0x83f1550, pc=0x0) at glxcmds.c:395
> > #16 0xa7cc5e48 in __glXDispatch (client=0x83f1080) at glxext.c:551
> > #17 0x08130a00 in XaceCatchExtProc (client=0x83f1080) at xace.c:299
> > #18 0x08084b29 in Dispatch () at dispatch.c:457
> > #19 0x0806e208 in main (argc=6, argv=0xaffffca4, envp=0xaffffcc0) at main.c:445
> >
> > The ioctl is hanging.  It's interruptible but it doesn't
> > return by its own.  The command which produced this hang was
> > a simple "LIBGL_FORCE_INDIRECT=1 glxinfo".  Doesn't happen
> > always but often.
>
> I can't reproduce this, just tried ten times in a row.

I have a ~50% chance of hitting it.

> Yes, it sounds like some kind of deadlock condition, but it's not clear
> to me from the backtrace how. Setting /sys/module/drm/parameters/debug
> to 1 might give something interesting in the kernel output.

Hmm... 40MB of debugging output within some seconds.  Afaict, this is
the part when starting glxinfo:

[...]
[drm:radeon_cp_dispatch_indirect] indirect: buf=15 s=0x0 e=0xef8
[drm:drm_ioctl] pid=1938, cmd=0xc010644d, nr=0x4d, dev 0xe200, auth=1
[drm:radeon_cp_indirect] indirect: idx=15 s=3832 e=3848 d=1
[drm:radeon_cp_dispatch_indirect] indirect: buf=15 s=0xef8 e=0xf08
[drm:drm_ioctl] pid=1938, cmd=0xc0086420, nr=0x20, dev 0xe200, auth=1
[drm:drm_ctxbitmap_next] drm_ctxbitmap_next bit : 4
[drm:drm_addctx] 4
[drm:drm_ioctl] pid=1938, cmd=0x4008642a, nr=0x2a, dev 0xe200, auth=1
[drm:drm_lock] 4 (pid 1938) requests lock (0x00000001), flags = 0x00000000
[drm:drm_lock] 4 has a
[drm:drm_ioctl] pid=1938, cmd=0x4008642a, nr=0x2a, dev 0xe200, auth=1
[drm:drm_lock] 1 (pid 1938) requests lock (0x00000004), flags = 0x00000000
[drm:drm_lock] 1 has lock
[drm:drm_ioctl] pid=1938, cmd=0x4008642a, nr=0x2a, dev 0xe200, auth=1
[drm:drm_lock] 4 (pid 1938) requests lock (0x00000001), flags = 0x00000000
[drm:drm_lock] 4 has lock
[...]

And then it goes on and on - get lock 1, get lock 4, ...

Btw, this on an a P4-HT SMP kernel in case it matters.

Ciao, ET.