linux-4.4 bisected: kwin5 stuck on kde5 loading screen with radeon

Mon Jan 18 06:06:59 PST 2016

On 01/18/2016 11:49 AM, Vlastimil Babka wrote:
> On 01/16/2016 05:24 AM, Mario Kleiner wrote:
>> I think a drm.debug=0x21 setting and grep'ping the syslog for "vblank"
>> should probably give useful info around the time of the hang.
> 
> Attached. Captured by having kdm running, switching to console, running
> "dmesg -C ; dmesg -w > /tmp/dmesg", switch to kdm, enter password, see
> frozen splashscreen, switch back, terminate dmesg. So somewhere around
> the middle there should be where ksplashscreen starts...
> 
>> Maybe also check XOrg.0.log for (WW) warnings related to flip.
> 
> No such warnings there.

This is how gdb backtraces look like from the 4 threads of ksplashqml that's stuck.
Thread 3 seems to be waiting on some response to radeon's ioctl?

(gdb) info threads
  Id   Target Id         Frame
  4    Thread 0x7feb296f5700 (LWP 3643) "QXcbEventReader" pthread_cond_wait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
  3    Thread 0x7feb199f8700 (LWP 3644) "ksplashqml" pthread_cond_wait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
  2    Thread 0x7feb18ff2700 (LWP 3645) "QQmlThread" 0x00007feb392bd24d in poll () at ../sysdeps/unix/syscall-template.S:84
* 1    Thread 0x7feb3b79f8c0 (LWP 3642) "ksplashqml" 0x00007feb392bd24d in poll () at ../sysdeps/unix/syscall-template.S:84
(gdb) bt
#0  0x00007feb392bd24d in poll () at ../sysdeps/unix/syscall-template.S:84
#1  0x00007feb32509432 in poll (__timeout=-1, __nfds=1, __fds=0x7ffce30ffb50) at /usr/include/bits/poll2.h:46
#2  _xcb_conn_wait (c=c at entry=0x17e25c0, cond=cond at entry=0x7ffce30ffc70, vector=vector at entry=0x0, count=count at entry=0x0) at xcb_conn.c:459
#3  0x00007feb3250ad57 in wait_for_reply (c=c at entry=0x17e25c0, request=request at entry=883, e=e at entry=0x7ffce30ffd48) at xcb_in.c:516
#4  0x00007feb3250aec1 in xcb_wait_for_reply64 (c=c at entry=0x17e25c0, request=883, e=e at entry=0x7ffce30ffd48) at xcb_in.c:560
#5  0x00007feb32b80300 in _XReply (dpy=dpy at entry=0x17e12c0, rep=rep at entry=0x7ffce30ffdc0, extra=extra at entry=0, discard=discard at entry=0) at xcb_io.c:596
#6  0x00007feb36eda712 in DRI2GetBuffersWithFormat (dpy=0x17e12c0, drawable=12582924, width=width at entry=0x181e528, height=height at entry=0x181e52c,
    attachments=0x7ffce30fff10, count=1, outCount=0x7ffce30ffef0) at dri2.c:491
#7  0x00007feb36edaa17 in dri2GetBuffersWithFormat (driDrawable=<optimized out>, width=0x181e528, height=0x181e52c, attachments=<optimized out>,
    count=<optimized out>, out_count=0x7ffce30ffef0, loaderPrivate=0x1fb1290) at dri2_glx.c:900
#8  0x00007feb20132618 in dri2_drawable_get_buffers (count=<synthetic pointer>, atts=0x1817da0, drawable=0x1816d20) at dri2.c:213
#9  dri2_allocate_textures (ctx=0x1a453d0, drawable=0x1816d20, statts=0x1817da0, statts_count=2) at dri2.c:407
#10 0x00007feb2012f17c in dri_st_framebuffer_validate (stctx=<optimized out>, stfbi=<optimized out>, statts=0x1817da0, count=2, out=0x7ffce3100050)
    at dri_drawable.c:83
#11 0x00007feb2005b5fe in st_framebuffer_validate (stfb=0x1817940, st=st at entry=0x1b11f20) at state_tracker/st_manager.c:200
#12 0x00007feb2005c88e in st_api_make_current (stapi=<optimized out>, stctxi=0x1b11f20, stdrawi=0x1816d20, streadi=0x1816d20) at state_tracker/st_manager.c:831
#13 0x00007feb2012ecd1 in dri_make_current (cPriv=<optimized out>, driDrawPriv=0x181e500, driReadPriv=0x181e500) at dri_context.c:245
#14 0x00007feb2012dcb6 in driBindContext (pcp=<optimized out>, pdp=<optimized out>, prp=<optimized out>) at dri_util.c:531
#15 0x00007feb36edc38b in dri2_bind_context (context=0x1a70960, old=<optimized out>, draw=12582924, read=12582924) at dri2_glx.c:160
#16 0x00007feb36eb99b7 in MakeContextCurrent (dpy=0x17e12c0, draw=draw at entry=12582924, read=read at entry=12582924, gc_user=0x1a70960) at glxcurrent.c:228
#17 0x00007feb36eb9b3b in glXMakeCurrent (dpy=<optimized out>, draw=draw at entry=12582924, gc=<optimized out>) at glxcurrent.c:262
#18 0x00007feb288d9a2d in QGLXContext::makeCurrent (this=0x1a48760, surface=0x1a0ac40) at qglxintegration.cpp:476
#19 0x00007feb3a0f8750 in QOpenGLContext::makeCurrent (this=0x18401e0, surface=0x1842d90) at kernel/qopenglcontext.cpp:936
#20 0x00007feb3af63aef in QSGGuiThreadRenderLoop::renderWindow (this=this at entry=0x1913f50, window=0x1842d80)
    at /usr/src/debug/qtdeclarative-opensource-src-5.5.1/src/quick/scenegraph/qsgrenderloop.cpp:341
#21 0x00007feb3af64d11 in QSGGuiThreadRenderLoop::event (this=0x1913f50, e=<optimized out>)
    at /usr/src/debug/qtdeclarative-opensource-src-5.5.1/src/quick/scenegraph/qsgrenderloop.cpp:474
#22 0x00007feb39b7fbd9 in QCoreApplication::notify (this=<optimized out>, receiver=<optimized out>, event=<optimized out>) at kernel/qcoreapplication.cpp:1038
#23 0x00007feb39b7fcf3 in QCoreApplication::notifyInternal (this=0x7ffce3100740, receiver=0x1913f50, event=event at entry=0x7ffce31004c0)
    at kernel/qcoreapplication.cpp:965
#24 0x00007feb39bd23bd in sendEvent (event=0x7ffce31004c0, receiver=<optimized out>) at ../../src/corelib/kernel/qcoreapplication.h:224
#25 QTimerInfoList::activateTimers (this=0x183e220) at kernel/qtimerinfo_unix.cpp:637
#26 0x00007feb39bd2909 in timerSourceDispatch (source=<optimized out>) at kernel/qeventdispatcher_glib.cpp:177
#27 idleTimerSourceDispatch (source=<optimized out>) at kernel/qeventdispatcher_glib.cpp:224
#28 0x00007feb35f4c097 in g_main_dispatch (context=0x7feb240016f0) at gmain.c:3154
#29 g_main_context_dispatch (context=context at entry=0x7feb240016f0) at gmain.c:3769
#30 0x00007feb35f4c2c8 in g_main_context_iterate (context=context at entry=0x7feb240016f0, block=block at entry=1, dispatch=dispatch at entry=1, self=<optimized out>)
    at gmain.c:3840
#31 0x00007feb35f4c36c in g_main_context_iteration (context=0x7feb240016f0, may_block=may_block at entry=1) at gmain.c:3901
#32 0x00007feb39bd350f in QEventDispatcherGlib::processEvents (this=0x183f080, flags=...) at kernel/qeventdispatcher_glib.cpp:418
#33 0x00007feb39b7d63a in QEventLoop::exec (this=this at entry=0x7ffce31006e0, flags=..., flags at entry=...) at kernel/qeventloop.cpp:204
#34 0x00007feb39b852fd in QCoreApplication::exec () at kernel/qcoreapplication.cpp:1229
#35 0x00007feb3a0bb53c in QGuiApplication::exec () at kernel/qguiapplication.cpp:1527
#36 0x0000000000405ce1 in main (argc=3, argv=0x7ffce3100878) at /usr/src/debug/plasma-workspace-5.5.2/ksplash/ksplashqml/main.cpp:98

(gdb) thread 2
[Switching to thread 2 (Thread 0x7feb18ff2700 (LWP 3645))]
#0  0x00007feb392bd24d in poll () at ../sysdeps/unix/syscall-template.S:84
84      in ../sysdeps/unix/syscall-template.S
(gdb) bt
#0  0x00007feb392bd24d in poll () at ../sysdeps/unix/syscall-template.S:84
#1  0x00007feb35f4c264 in g_main_context_poll (priority=2147483647, n_fds=1, fds=0x7feb14003070, timeout=<optimized out>, context=0x7feb14000990)
    at gmain.c:4135
#2  g_main_context_iterate (context=context at entry=0x7feb14000990, block=block at entry=1, dispatch=dispatch at entry=1, self=<optimized out>) at gmain.c:3835
#3  0x00007feb35f4c36c in g_main_context_iteration (context=0x7feb14000990, may_block=may_block at entry=1) at gmain.c:3901
#4  0x00007feb39bd350f in QEventDispatcherGlib::processEvents (this=0x7feb140008c0, flags=...) at kernel/qeventdispatcher_glib.cpp:418
#5  0x00007feb39b7d63a in QEventLoop::exec (this=this at entry=0x7feb18ff1cf0, flags=..., flags at entry=...) at kernel/qeventloop.cpp:204
#6  0x00007feb399a9b1c in QThread::exec (this=this at entry=0x184dc00) at thread/qthread.cpp:503
#7  0x00007feb38c799a5 in QQmlThreadPrivate::run (this=0x184dc00) at /usr/src/debug/qtdeclarative-opensource-src-5.5.1/src/qml/qml/ftw/qqmlthread.cpp:141
#8  0x00007feb399ae94f in QThreadPrivate::start (arg=0x184dc00) at thread/qthread_unix.cpp:331
#9  0x00007feb37a3d4a4 in start_thread (arg=0x7feb18ff2700) at pthread_create.c:334
#10 0x00007feb392c5bdd in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109

(gdb) thread 3
[Switching to thread 3 (Thread 0x7feb199f8700 (LWP 3644))]
#0  pthread_cond_wait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
185     ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S: No such file or directory.
(gdb) bt
#0  pthread_cond_wait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1  0x00007feb20496e63 in cnd_wait (mtx=0x18abc90, cond=0x18abcb8) at ../../../../../include/c11/threads_posix.h:159
#2  pipe_semaphore_wait (sema=0x18abc90) at ../../../../../src/gallium/auxiliary/os/os_thread.h:259
#3  radeon_drm_cs_emit_ioctl (param=param at entry=0x18ab940) at radeon_drm_winsys.c:653
#4  0x00007feb204966a7 in impl_thrd_routine (p=<optimized out>) at ../../../../../include/c11/threads_posix.h:87
#5  0x00007feb37a3d4a4 in start_thread (arg=0x7feb199f8700) at pthread_create.c:334
#6  0x00007feb392c5bdd in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109

(gdb) thread 4
[Switching to thread 4 (Thread 0x7feb296f5700 (LWP 3643))]
#0  pthread_cond_wait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
185     in ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S
(gdb) bt
#0  pthread_cond_wait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1  0x00007feb32509689 in _xcb_conn_wait (c=c at entry=0x17e25c0, cond=cond at entry=0x17e2600, vector=vector at entry=0x0, count=count at entry=0x0) at xcb_conn.c:427
#2  0x00007feb3250b007 in xcb_wait_for_event (c=0x17e25c0) at xcb_in.c:693
#3  0x00007feb2ba48e29 in QXcbEventReader::run (this=0x17f55d0) at qxcbconnection.cpp:1229
#4  0x00007feb399ae94f in QThreadPrivate::start (arg=0x17f55d0) at thread/qthread_unix.cpp:331
#5  0x00007feb37a3d4a4 in start_thread (arg=0x7feb296f5700) at pthread_create.c:334
#6  0x00007feb392c5bdd in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109