SUMMARY KDE PowerDevil runs into a deadlock which will cause 25 second kwin_wayland freeze if something tries to enable screen inhibitors (e.g. VLC or Firefox duing video playback) STEPS TO REPRODUCE 1. Get PowerDevil to deadlock (I assume this happens when screens are reconnected, maybe due to driver issues?). for testing the kwin_wayland hang you can just suspend the process `pkill -STOP org_kde_powerde` (resume with `pkill -CONT org_kde_powerde`) 2. Start VLC with a video OBSERVED RESULT System hangs for 25 seconds because kwin_wayland waits for the inhibit call to finish, blocking the main thread EXPECTED RESULT PowerDevil does not deadlock, kwin_wayland does freeze WORKAROUNDS Restarting PowerDevil (`systemctl --user restart plasma-powerdevil.service`) fixes the freezing issue (until it deadlocks again). You can also just stop it so it no longer causes issues (`systemctl --user stop plasma-powerdevil.service`). SOFTWARE/OS VERSIONS Linux/KDE Plasma: Arch Linux KDE Plasma Version: 6.3.2 KDE Frameworks Version: 6.11.0 Qt Version: 6.8.2 ADDITIONAL INFORMATION DBus monitor: method call time=1740911305.944531 sender=:1.129 -> destination=org.freedesktop.ScreenSaver serial=3 path=/ScreenSaver; interface=org.freedesktop.ScreenSaver; member=Inhibit string "vlc" string "Playing some media." method call time=1740911305.944673 sender=:1.9 -> destination=org.kde.Solid.PowerManagement.PolicyAgent serial=2091 path=/org/kde/Solid/PowerManagement/PolicyAgent; interface=org.kde.Solid.PowerManagement.PolicyAgent; member=AddInhibition uint32 4 string "vlc" string "Playing some media." # can't find any replies to these method calls GDB Backtrace of PowerDevil ``` #0 __syscall_cancel_arch () at ../sysdeps/unix/sysv/linux/x86_64/syscall_cancel.S:56 #1 0x00007602e7a9fe33 in __internal_syscall_cancel (a1=a1@entry=0, a2=a2@entry=0, a3=a3@entry=140733869441776, a4=a4@entry=0, a5=a5@entry=0, a6=a6@entry=0, nr=230) at cancellation.c:49 #2 0x00007602e7af0a82 in __GI___clock_nanosleep (clock_id=<optimized out>, clock_id@entry=0, flags=flags@entry=0, req=req@entry=0x7fff284bc2f0, rem=rem@entry=0x0) at ../sysdeps/unix/sysv/linux/clock_nanosleep.c:48 #3 0x00007602e7afcc27 in __GI___nanosleep (req=req@entry=0x7fff284bc2f0, rem=rem@entry=0x0) at ../sysdeps/unix/sysv/linux/nanosleep.c:25 #4 0x00007602e7b2761a in usleep (useconds=useconds@entry=100000) at ../sysdeps/posix/usleep.c:31 #5 0x00007602e6d2e7f0 in sleep_millis (milliseconds=100) at base/sleep.c:89 #6 0x00007602e6d282a5 in lock_display (dlr=0x5b97091df140, flags=flags@entry=DDISP_NONE) at base/display_lock.c:239 #7 0x00007602e6d28a14 in lock_display_by_dpath (dpath=..., flags=DDISP_NONE) at base/display_lock.c:393 #8 0x00007602e6d0b86c in i2c_open_bus (busno=4, callopts=callopts@entry=4 '\004', fd_loc=fd_loc@entry=0x7fff284bc4c4) at i2c/i2c_bus_core.c:273 #9 0x00007602e6d12e73 in i2c_check_bus (businfo=businfo@entry=0x5b9709281d90) at i2c/i2c_bus_core.c:1457 #10 0x00007602e6d13b99 in i2c_non_async_scan (i2c_buses=0x5b970919a0a0) at i2c/i2c_bus_core.c:1791 #11 0x00007602e6d14232 in i2c_detect_buses0 () at i2c/i2c_bus_core.c:1949 #12 0x00007602e6d143d5 in i2c_detect_buses () at i2c/i2c_bus_core.c:2014 #13 0x00007602e6cebea1 in dw_redetect_displays () at dw/dw_main.c:383 #14 0x00007602e6d48ed0 in ddca_redetect_displays () at libmain/api_displays.c:445 #15 0x00007602e889af25 in DDCutilPrivateSingleton::redetect (this=0x7602e88d0460 <DDCutilPrivateSingleton::instance()::singleton>) at /usr/src/debug/powerdevil/powerdevil-6.3.2/daemon/controllers/ddcutildetector.cpp:207 #16 0x00007602e75a2f4a in QObject::event (this=0x7602e88d0460 <DDCutilPrivateSingleton::instance()::singleton>, e=0x7602ac000f90) at /usr/src/debug/qt6-base/qtbase/src/corelib/kernel/qobject.cpp:1418 #17 0x00007602e7555b00 in QCoreApplication::notifyInternal2 (receiver=0x7602e88d0460 <DDCutilPrivateSingleton::instance()::singleton>, event=event@entry=0x7602ac000f90) at /usr/src/debug/qt6-base/qtbase/src/corelib/kernel/qcoreapplication.cpp:1172 #18 0x00007602e7555edc in QCoreApplication::sendEvent (receiver=<optimized out>, event=0x7602ac000f90) at /usr/src/debug/qt6-base/qtbase/src/corelib/kernel/qcoreapplication.cpp:1612 #19 QCoreApplicationPrivate::sendPostedEvents (receiver=0x0, event_type=0, data=0x5b9709140e50) at /usr/src/debug/qt6-base/qtbase/src/corelib/kernel/qcoreapplication.cpp:1946 #20 0x00007602e77c859c in QCoreApplication::sendPostedEvents (receiver=0x0, event_type=0) at /usr/src/debug/qt6-base/qtbase/src/corelib/kernel/qcoreapplication.cpp:1800 #21 postEventSourceDispatch (s=0x5b97091456b0) at /usr/src/debug/qt6-base/qtbase/src/corelib/kernel/qeventdispatcher_glib.cpp:246 #22 0x00007602e683c919 in g_main_dispatch (context=0x7602d8000f00) at ../glib/glib/gmain.c:3357 #23 0x00007602e689f5d7 in g_main_context_dispatch_unlocked (context=0x7602d8000f00) at ../glib/glib/gmain.c:4208 #24 g_main_context_iterate_unlocked.isra.0 (context=context@entry=0x7602d8000f00, block=block@entry=1, dispatch=dispatch@entry=1, self=<optimized out>) at ../glib/glib/gmain.c:4273 #25 0x00007602e683be15 in g_main_context_iteration (context=0x7602d8000f00, may_block=1) at ../glib/glib/gmain.c:4338 #26 0x00007602e77c575d in QEventDispatcherGlib::processEvents (this=0x5b9709145610, flags=...) at /usr/src/debug/qt6-base/qtbase/src/corelib/kernel/qeventdispatcher_glib.cpp:399 #27 0x00007602e75606a6 in QEventLoop::processEvents (this=0x7fff284bcc40, flags=...) at /usr/src/debug/qt6-base/qtbase/src/corelib/kernel/qeventloop.cpp:103 #28 QEventLoop::exec (this=0x7fff284bcc40, flags=...) at /usr/src/debug/qt6-base/qtbase/src/corelib/kernel/qeventloop.cpp:185 #29 0x00007602e75591d6 in QCoreApplication::exec () at /usr/src/debug/qt6-base/qtbase/src/corelib/global/qflags.h:74 #30 0x00005b96cbdeb727 in main (argc=<optimized out>, argv=<optimized out>) at /usr/src/debug/powerdevil/powerdevil-6.3.2/daemon/powerdevilapp.cpp:134 ``` PowerDevil logs: ``` Mar 02 10:30:17 r9950 org_kde_powerdevil[1989]: [ 1989] Error queiscing libdducitl API. 1 active API calls outstanding. Mar 02 10:30:17 r9950 org_kde_powerdevil[1989]: org.kde.powerdevil: [DDCutilDisplay]: ddca_close_display -3032 Mar 02 10:30:17 r9950 org_kde_powerdevil[1989]: library quiesced, ddca_close_display temporarily unavailable Mar 02 10:30:17 r9950 org_kde_powerdevil[1989]: org.kde.powerdevil: [DDCutilDisplay]: ddca_open_display2 -3032 Mar 02 10:30:17 r9950 org_kde_powerdevil[1989]: [ 1989] Display redetection starting. Mar 02 10:30:17 r9950 org_kde_powerdevil[1989]: library quiesced, ddca_open_display3 temporarily unavailable Mar 02 10:30:17 r9950 org_kde_powerdevil[1989]: [ 20885] recheck thread terminating because watch thread terminated Mar 02 10:30:17 r9950 org_kde_powerdevil[1989]: [ 1989] Watch thread terminated. Mar 02 10:30:17 r9950 org_kde_powerdevil[1989]: [ 1989] Attempting to unlock display lock owned by different thread Mar 02 10:30:17 r9950 org_kde_powerdevil[1989]: [ 1989] Unexpected error DDCRC_LOCKED from unlock_display_by_dpath(Display_Path[/dev/i2c-4]) ```
More logs: PowerDevil: ``` Mar 02 08:11:05 r9950 systemd[1427]: Started Powerdevil. Mar 02 08:11:05 r9950 org_kde_powerdevil[1989]: org.kde.powerdevil: Handle button events action could not check for screen configuration Mar 02 08:11:05 r9950 org_kde_powerdevil[1989]: org.kde.powerdevil: org.kde.powerdevil.chargethresholdhelper.getthreshold failed "Charge thresholds are not supported by the kernel for this hardware" Mar 02 08:11:05 r9950 org_kde_powerdevil[1989]: [ 2222] (dw_recheck_displays_func) Recheck interval: Slept for 200 millisec Mar 02 10:28:51 r9950 org_kde_powerdevil[1989]: [ 2223] Removing connected display on bus 5 Mar 02 10:28:51 r9950 org_kde_powerdevil[1989]: [ 2223] (dw_remove_display_by_businfo) No Display_Ref found for i2c bus: 5 Mar 02 10:28:53 r9950 org_kde_powerdevil[1989]: [ 2223] (i2c_detect_x37) Extra x37 sleep: Slept for 400 millisec Mar 02 10:28:53 r9950 org_kde_powerdevil[1989]: [ 2223] (i2c_detect_x37) Extra x37 sleep: Slept for 400 millisec Mar 02 10:28:54 r9950 org_kde_powerdevil[1989]: [ 2223] (i2c_detect_x37) Extra x37 sleep: Slept for 400 millisec Mar 02 10:28:54 r9950 org_kde_powerdevil[1989]: [ 2223] Adding connected display with bus 5 Mar 02 10:28:54 r9950 org_kde_powerdevil[1989]: [ 2223] Emitting DDCA_Display_Status_Event[8270.615: DDCA_EVENT_DISPLAY_CONNECTED, card1-HDMI-A-2, dref: DDCA_Display_Ref[3], io_path:/dev/i2c-5, ddc working: false] Mar 02 10:28:54 r9950 org_kde_powerdevil[1989]: [ 2223] libddcutil callback thread 0x7602b4001770 started Mar 02 10:28:54 r9950 org_kde_powerdevil[1989]: [ 2223] Started 1 event callback thread(s) Mar 02 10:28:54 r9950 org_kde_powerdevil[1989]: [ 2222] ddc became enabled for Display_Ref[3:bus /dev/i2c-5 @0x7602b401d540] after 0 milliseconds Mar 02 10:28:54 r9950 org_kde_powerdevil[1989]: [ 2222] Emitting DDCA_Display_Status_Event[8270.615: DDCA_EVENT_DDC_ENABLED, card1-HDMI-A-2, dref: DDCA_Display_Ref[3], io_path:/dev/i2c-5, ddc working: false] Mar 02 10:28:54 r9950 org_kde_powerdevil[1989]: [ 2222] libddcutil callback thread 0x7602bc002ae0 started Mar 02 10:28:54 r9950 org_kde_powerdevil[1989]: [ 2222] Started 1 event callback thread(s) Mar 02 10:28:54 r9950 org_kde_powerdevil[1989]: [ 1989] Quiescing libddcutil API... Mar 02 10:28:54 r9950 org_kde_powerdevil[1989]: [ 1989] Quiesce libddcutil API complete Mar 02 10:28:54 r9950 org_kde_powerdevil[1989]: [ 1989] Display redetection starting. Mar 02 10:28:54 r9950 org_kde_powerdevil[1989]: [ 2222] (dw_recheck_displays_func) Recheck interval: Slept for 200 millisec Mar 02 10:28:54 r9950 org_kde_powerdevil[1989]: [ 2222] recheck thread terminating because watch thread terminated Mar 02 10:28:54 r9950 org_kde_powerdevil[1989]: [ 1989] Watch thread terminated. Mar 02 10:28:55 r9950 org_kde_powerdevil[1989]: [ 1989] (i2c_detect_x37) Extra x37 sleep: Slept for 400 millisec Mar 02 10:28:55 r9950 org_kde_powerdevil[1989]: [ 1989] (i2c_detect_x37) Extra x37 sleep: Slept for 400 millisec Mar 02 10:28:55 r9950 org_kde_powerdevil[1989]: [ 1989] (i2c_detect_x37) Extra x37 sleep: Slept for 400 millisec Mar 02 10:28:57 r9950 org_kde_powerdevil[1989]: [ 1989] busno=4, sleep-multiplier= 2,00, Testing for unsupported feature 0xdd returned Error_Info[DDCRC_RETRIES in ddc_write_read_with_retry, causes: DDCRC_DDC_DATA(10)] Mar 02 10:28:57 r9950 org_kde_powerdevil[1989]: [ 1989] Turning off dynamic sleep and retrying Mar 02 10:28:58 r9950 org_kde_powerdevil[1989]: [ 1989] busno=4, sleep-multiplier = 1,00, Retesting for unsupported feature 0xdd returned Error_Info[DDCRC_REPORTED_UNSUPPORTED in ddc_get_nontable_vcp_value] Mar 02 10:29:00 r9950 org_kde_powerdevil[1989]: [ 1989] Watching for display connection changes, resolved watch mode = Watch_Mode_Xevent, poll loop interval = 100 millisec Mar 02 10:29:00 r9950 org_kde_powerdevil[1989]: [ 1989] extra_stabilization_millisec: 0, stabilization_poll_millisec: 100 Mar 02 10:29:00 r9950 org_kde_powerdevil[1989]: [ 1989] libddcutil recheck thread (nil) started Mar 02 10:29:00 r9950 org_kde_powerdevil[1989]: [ 1989] libddcutil watch thread 0x5b97092e28e0 started Mar 02 10:29:00 r9950 org_kde_powerdevil[1989]: [ 1989] Display redetection finished. Mar 02 10:29:00 r9950 org_kde_powerdevil[1989]: [ 1989] Unquiescing libddcutil API... Mar 02 10:29:00 r9950 org_kde_powerdevil[1989]: [ 20885] (dw_recheck_displays_func) Recheck interval: Slept for 200 millisec Mar 02 10:29:03 r9950 org_kde_powerdevil[1989]: org.kde.powerdevil: [DDCutilDisplay]: ddca_get_non_table_vcp_value -3007 Mar 02 10:30:11 r9950 org_kde_powerdevil[1989]: [ 20886] Removing connected display on bus 5 Mar 02 10:30:11 r9950 org_kde_powerdevil[1989]: [ 20886] (dw_remove_display_by_businfo) No Display_Ref found for i2c bus: 5 Mar 02 10:30:13 r9950 org_kde_powerdevil[1989]: [ 20886] (i2c_detect_x37) Extra x37 sleep: Slept for 400 millisec Mar 02 10:30:13 r9950 org_kde_powerdevil[1989]: [ 20886] (i2c_detect_x37) Extra x37 sleep: Slept for 400 millisec Mar 02 10:30:14 r9950 org_kde_powerdevil[1989]: org.kde.powerdevil: [DDCutilDisplay]: ddca_get_non_table_vcp_value -3007 Mar 02 10:30:14 r9950 org_kde_powerdevil[1989]: [ 20886] (i2c_detect_x37) Extra x37 sleep: Slept for 400 millisec Mar 02 10:30:14 r9950 org_kde_powerdevil[1989]: [ 20886] Adding connected display with bus 5 Mar 02 10:30:14 r9950 org_kde_powerdevil[1989]: [ 20886] Emitting DDCA_Display_Status_Event[8350.483: DDCA_EVENT_DISPLAY_CONNECTED, card1-HDMI-A-2, dref: DDCA_Display_Ref[6], io_path:/dev/i2c-5, ddc working: false] Mar 02 10:30:14 r9950 org_kde_powerdevil[1989]: [ 20886] libddcutil callback thread 0x7602b4019550 started Mar 02 10:30:14 r9950 org_kde_powerdevil[1989]: [ 20886] Started 1 event callback thread(s) Mar 02 10:30:14 r9950 org_kde_powerdevil[1989]: [ 1989] Quiescing libddcutil API... Mar 02 10:30:14 r9950 org_kde_powerdevil[1989]: [ 20885] ddc became enabled for Display_Ref[6:bus /dev/i2c-5 @0x7602b4021a40] after 0 milliseconds Mar 02 10:30:14 r9950 org_kde_powerdevil[1989]: [ 20885] Emitting DDCA_Display_Status_Event[8350.483: DDCA_EVENT_DDC_ENABLED, card1-HDMI-A-2, dref: DDCA_Display_Ref[6], io_path:/dev/i2c-5, ddc working: false] Mar 02 10:30:14 r9950 org_kde_powerdevil[1989]: [ 20885] libddcutil callback thread 0x7602bc002e00 started Mar 02 10:30:14 r9950 org_kde_powerdevil[1989]: [ 20885] Started 1 event callback thread(s) Mar 02 10:30:14 r9950 org_kde_powerdevil[1989]: [ 20885] (dw_recheck_displays_func) Recheck interval: Slept for 200 millisec Mar 02 10:30:17 r9950 org_kde_powerdevil[1989]: Error queiscing libdducitl API. 1 active API calls outstanding. Mar 02 10:30:17 r9950 org_kde_powerdevil[1989]: [ 1989] Error queiscing libdducitl API. 1 active API calls outstanding. Mar 02 10:30:17 r9950 org_kde_powerdevil[1989]: org.kde.powerdevil: [DDCutilDisplay]: ddca_close_display -3032 Mar 02 10:30:17 r9950 org_kde_powerdevil[1989]: library quiesced, ddca_close_display temporarily unavailable Mar 02 10:30:17 r9950 org_kde_powerdevil[1989]: org.kde.powerdevil: [DDCutilDisplay]: ddca_open_display2 -3032 Mar 02 10:30:17 r9950 org_kde_powerdevil[1989]: [ 1989] Display redetection starting. Mar 02 10:30:17 r9950 org_kde_powerdevil[1989]: library quiesced, ddca_open_display3 temporarily unavailable Mar 02 10:30:17 r9950 org_kde_powerdevil[1989]: [ 20885] recheck thread terminating because watch thread terminated Mar 02 10:30:17 r9950 org_kde_powerdevil[1989]: [ 1989] Watch thread terminated. Mar 02 10:30:17 r9950 org_kde_powerdevil[1989]: [ 1989] Attempting to unlock display lock owned by different thread Mar 02 10:30:17 r9950 org_kde_powerdevil[1989]: [ 1989] Unexpected error DDCRC_LOCKED from unlock_display_by_dpath(Display_Path[/dev/i2c-4]) ``` Kernel messages: ``` Mar 02 09:05:11 r9950 kernel: amdgpu 0000:03:00.0: [drm] REG_WAIT timeout 1us * 100 tries - dcn32_program_compbuf_size line:139 Mar 02 10:28:31 r9950 kernel: amdgpu 0000:03:00.0: [drm] REG_WAIT timeout 1us * 100 tries - dcn32_program_compbuf_size line:139 ```
Thank you, this is a terrific bug report. The deadlock is happening within libddcutil, let me add Sanford Rockowitz (ddcutil maintainer) to the CC as he may be interested in this. A possible attempt on the powerdevil side of things could be to abandon ddcutil's display change notifications altogether (with an eye on Bug 500835 as well), and instead trigger manual ddcutil redetection after libkscreen tells us about new or removed displays. Perhaps a shame given how much work has gone into display change notifications for ddcutil 2.2.0, but worth exploring as PowerDevil with KWin/Wayland already limits itself to displays known to libkscreen.
I did some more debugging (coredump available if needed) the Display Lock Record of libddcutil has this data: (gdb) p dlr $1 = (Display_Lock_Record *) 0x5b97091df140 (gdb) p *dlr $2 = {marker = "DDSC", io_path = {io_mode = DDCA_IO_I2C, path = {i2c_busno = 4, hiddev_devno = 4}}, display_mutex = {p = 0x1, i = {1, 0}}, display_mutex_thread = 0x7602b8000de0, linux_thread_id = 20887} The noted linux_thread_id is still active, the backtrace follows: ``` (gdb) thr 2 [Switching to thread 2 (Thread 0x7602c5ffb6c0 (LWP 20887))] #0 __syscall_cancel_arch () at ../sysdeps/unix/sysv/linux/x86_64/syscall_cancel.S:56 56 ret (gdb) bt #0 __syscall_cancel_arch () at ../sysdeps/unix/sysv/linux/x86_64/syscall_cancel.S:56 #1 0x00007602e7a9fe33 in __internal_syscall_cancel (a1=<optimized out>, a2=<optimized out>, a3=<optimized out>, a4=<optimized out>, a5=a5@entry=8, a6=a6@entry=0, nr=271) at cancellation.c:49 #2 0x00007602e7a9fe74 in __syscall_cancel (a1=<optimized out>, a2=<optimized out>, a3=<optimized out>, a4=<optimized out>, a5=a5@entry=8, a6=a6@entry=0, nr=271) at cancellation.c:75 #3 0x00007602e7b1aa06 in __GI_ppoll (fds=fds@entry=0x5b9709222c90, nfds=nfds@entry=1, timeout=<optimized out>, timeout@entry=0x0, sigmask=sigmask@entry=0x0) at ../sysdeps/unix/sysv/linux/ppoll.c:42 #4 0x00007602e689f6a7 in ppoll (__fds=0x5b9709222c90, __nfds=1, __timeout=0x0, __ss=0x0) at /usr/include/bits/poll2.h:101 #5 g_main_context_poll_unlocked (priority=<optimized out>, context=0x7602b8000c40, timeout_usec=<optimized out>, fds=0x5b9709222c90, n_fds=1) at ../glib/glib/gmain.c:4591 #6 g_main_context_iterate_unlocked.isra.0 (context=context@entry=0x7602b8000c40, block=block@entry=1, dispatch=dispatch@entry=1, self=<optimized out>) at ../glib/glib/gmain.c:4268 #7 0x00007602e683be15 in g_main_context_iteration (context=0x7602b8000c40, may_block=1) at ../glib/glib/gmain.c:4338 #8 0x00007602e77c575d in QEventDispatcherGlib::processEvents (this=0x7602b8001010, flags=...) at /usr/src/debug/qt6-base/qtbase/src/corelib/kernel/qeventdispatcher_glib.cpp:399 #9 0x00007602e75606a6 in QEventLoop::processEvents (this=0x7602c5ffaa70, flags=...) at /usr/src/debug/qt6-base/qtbase/src/corelib/kernel/qeventloop.cpp:103 #10 QEventLoop::exec (this=0x7602c5ffaa70, flags=...) at /usr/src/debug/qt6-base/qtbase/src/corelib/kernel/qeventloop.cpp:185 #11 0x00007602e7657999 in QThread::exec (this=<optimized out>) at /usr/src/debug/qt6-base/qtbase/src/corelib/thread/qthread.cpp:590 #12 QThread::run (this=<optimized out>) at /usr/src/debug/qt6-base/qtbase/src/corelib/thread/qthread.cpp:711 #13 0x00007602e76d8a9b in operator() (__closure=<optimized out>) at /usr/src/debug/qt6-base/qtbase/src/corelib/thread/qthread_unix.cpp:375 #14 (anonymous namespace)::terminate_on_exception<QThreadPrivate::start(void*)::<lambda()> > (t=...) at /usr/src/debug/qt6-base/qtbase/src/corelib/thread/qthread_unix.cpp:311 #15 QThreadPrivate::start (arg=0x7602d801f188) at /usr/src/debug/qt6-base/qtbase/src/corelib/thread/qthread_unix.cpp:339 #16 0x00007602e7aa370a in start_thread (arg=<optimized out>) at pthread_create.c:448 #17 0x00007602e7b27aac in __GI___clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:78 ``` I also checked the callback thread Mar 02 10:30:14 r9950 org_kde_powerdevil[1989]: [ 20885] libddcutil callback thread 0x7602bc002e00 started while the thread meta information still resides in memory ``` (gdb) p *(GThreadPosix*)0x7602bc002e00 $11 = {thread = {thread = {func = 0x7602e6ce4980 <dw_execute_callback_func>, data = 0x7602bc002a40, joinable = 1, priority = G_THREAD_PRIORITY_LOW}, ref_count = 1, ours = 1, name = 0x0, retval = 0x0}, system_thread = 129754267096768, joined = 0, lock = {p = 0x0, i = {0, 0}}, proxy = 0x7602e6871f10 <g_thread_proxy>} (gdb) p (pthread_t*) 129754267096768 $13 = (pthread_t *) 0x7602c4ff96c0 ``` the thread is no longer running ``` (gdb) info thr Id Target Id Frame 1 Thread 0x7602df5c4ac0 (LWP 1989) __syscall_cancel_arch () at ../sysdeps/unix/sysv/linux/x86_64/syscall_cancel.S:56 * 2 Thread 0x7602c5ffb6c0 (LWP 20887) __syscall_cancel_arch () at ../sysdeps/unix/sysv/linux/x86_64/syscall_cancel.S:56 3 Thread 0x7602dc9fa6c0 (LWP 2023) __syscall_cancel_arch () at ../sysdeps/unix/sysv/linux/x86_64/syscall_cancel.S:56 4 Thread 0x7602dd1fb6c0 (LWP 2022) __syscall_cancel_arch () at ../sysdeps/unix/sysv/linux/x86_64/syscall_cancel.S:56 5 Thread 0x7602dd9fc6c0 (LWP 2021) syscall () at ../sysdeps/unix/sysv/linux/x86_64/syscall.S:38 6 Thread 0x7602de1fd6c0 (LWP 2020) __syscall_cancel_arch () at ../sysdeps/unix/sysv/linux/x86_64/syscall_cancel.S:56 7 Thread 0x7602de9fe6c0 (LWP 2019) __syscall_cancel_arch () at ../sysdeps/unix/sysv/linux/x86_64/syscall_cancel.S:56 8 Thread 0x7602df1ff6c0 (LWP 2005) __syscall_cancel_arch () at ../sysdeps/unix/sysv/linux/x86_64/syscall_cancel.S:56 ```
From the tracebacks it looks like one of a couple things might be happening: A normal PowerDevil thread has opened a /dev/i2c device and is holding on to the open DDCA_Display_Handle. Meanwhile, a callback function is invoked and blocks waiting for the "normal" thread to close the open display handle. Generally speaking, display handles should be opened only briefly for executing a command, then closed. The cost of opening and closing a display handle is insignificant compared to writing to and reading from a /dev/i2c device. I had looked at clearing, as part of ddca_redetect() processing, all open display locks (internal object) held by display handles. The problem I encountered is that glib function g_mutex_unlock() can only be called from the thread that locked the mutex. If need be, I can look at implementing a more complex data structure to address this restriction. In general, it is safest that the callback function not invoke any API function that entails /dev/i2c IO. For example, ddcui's callback function simply emits a Qt signal that a display change event has occurred. I have made a small change to callback processing in branch 2.2.1-dev. Immediately prior to and after executing the callback function, events (of level NOTICE) are written to the system log. Along with libddcutil option "--trace-api" this should, if my hunch is correct, indicate how the failure occurs.
installed libddcutil branch 2.2.1-dev, set config option `--trace api`, reproduced the issue by running `kscreen-doctor -d off` 4 times. seems like this happens if the screen reconnects (as indicated by the sound effect KDE plays) while the screen is looking for other inputs and shortly before the screen goes to sleep. usually this reconnect just happens after it wakes up. the screen in question is an Acer CB281HK connected via HDMI. here are the logs: ``` Mar 07 23:04:48 r9950 org_kde_powerdevil[1764508]: [1764508] Watching for display connection changes, resolved watch mode = Watch_Mode_Xevent, poll loop interval = 100 millisec Mar 07 23:04:48 r9950 org_kde_powerdevil[1764508]: [1764508] extra_stabilization_millisec: 0, stabilization_poll_millisec: 100 Mar 07 23:04:48 r9950 org_kde_powerdevil[1764508]: [1764508] libddcutil recheck thread (nil) started Mar 07 23:04:48 r9950 org_kde_powerdevil[1764508]: [1764508] libddcutil watch thread 0x5a8509513510 started Mar 07 23:04:48 r9950 org_kde_powerdevil[1764508]: org.kde.powerdevil: org.kde.powerdevil.chargethresholdhelper.getthreshold failed "Charge thresholds are not supported by the kernel for this hardware" Mar 07 23:04:48 r9950 org_kde_powerdevil[1764508]: org.kde.powerdevil: org.kde.powerdevil.backlighthelper.brightness failed Mar 07 23:04:48 r9950 systemd[1421]: Started Powerdevil. Mar 07 23:04:48 r9950 org_kde_powerdevil[1764508]: org.kde.powerdevil: Handle button events action could not check for screen configuration Mar 07 23:04:48 r9950 org_kde_powerdevil[1764508]: org.kde.powerdevil: org.kde.powerdevil.chargethresholdhelper.getthreshold failed "Charge thresholds are not supported by the kernel for this hardware" Mar 07 23:04:48 r9950 org_kde_powerdevil[1764508]: [1764611] (dw_recheck_displays_func) Recheck interval: Slept for 200 millisec Mar 07 23:05:18 r9950 org_kde_powerdevil[1764508]: [1764612] Removing connected display on bus 6 Mar 07 23:05:18 r9950 org_kde_powerdevil[1764508]: [1764612] (dw_remove_display_by_businfo) No Display_Ref found for i2c bus: 6 Mar 07 23:05:20 r9950 org_kde_powerdevil[1764508]: [1764612] (i2c_detect_x37) Extra x37 sleep: Slept for 400 millisec Mar 07 23:05:21 r9950 org_kde_powerdevil[1764508]: [1764612] (i2c_detect_x37) Extra x37 sleep: Slept for 400 millisec Mar 07 23:05:21 r9950 org_kde_powerdevil[1764508]: [1764612] (i2c_detect_x37) Extra x37 sleep: Slept for 400 millisec Mar 07 23:05:21 r9950 org_kde_powerdevil[1764508]: [1764612] Adding connected display with bus 6 Mar 07 23:05:21 r9950 org_kde_powerdevil[1764508]: [1764612] Emitting DDCA_Display_Status_Event[ 36.615: DDCA_EVENT_DISPLAY_CONNECTED, card1-HDMI-A-2, dref: DDCA_Display_Ref[3], io_path:/dev/i2c-6, ddc working: false] Mar 07 23:05:21 r9950 org_kde_powerdevil[1764508]: [1764612] libddcutil callback thread 0x768858011d00 started Mar 07 23:05:21 r9950 org_kde_powerdevil[1764508]: [1764612] Started 1 event callback thread(s) Mar 07 23:05:21 r9950 org_kde_powerdevil[1764508]: [1765730] Invoking callback function 0x7688835c91b0 for event DDCA_Display_Status_Event[ 36.615: DDCA_EVENT_DISPLAY_CONNECTED, card1-HDMI-A-2, dref: DDCA_Display_Ref[3], io_path:/dev/i2c-6, ddc working: false] in this thread [1765730] Mar 07 23:05:21 r9950 org_kde_powerdevil[1764508]: [1765730] Callback function 0x7688835c91b0 for event DDCA_Display_Status_Event[ 36.615: DDCA_EVENT_DISPLAY_CONNECTED, card1-HDMI-A-2, dref: DDCA_Display_Ref[3], io_path:/dev/i2c-6, ddc working: false] complete Mar 07 23:05:21 r9950 org_kde_powerdevil[1764508]: [1764508] Quiescing libddcutil API... Mar 07 23:05:21 r9950 org_kde_powerdevil[1764508]: [1764508] Quiesce libddcutil API complete Mar 07 23:05:21 r9950 org_kde_powerdevil[1764508]: [1764508] Display redetection starting. Mar 07 23:05:21 r9950 org_kde_powerdevil[1764508]: [1764611] ddc became enabled for Display_Ref[3:bus /dev/i2c-6 @0x76885800d630] after 0 milliseconds Mar 07 23:05:21 r9950 org_kde_powerdevil[1764508]: [1764611] Emitting DDCA_Display_Status_Event[ 36.615: DDCA_EVENT_DDC_ENABLED, card1-HDMI-A-2, dref: DDCA_Display_Ref[3], io_path:/dev/i2c-6, ddc working: false] Mar 07 23:05:21 r9950 org_kde_powerdevil[1764508]: [1764611] libddcutil callback thread 0x768854002a30 started Mar 07 23:05:21 r9950 org_kde_powerdevil[1764508]: [1764611] Started 1 event callback thread(s) Mar 07 23:05:21 r9950 org_kde_powerdevil[1764508]: [1764611] recheck thread terminating because watch thread terminated Mar 07 23:05:21 r9950 org_kde_powerdevil[1764508]: [1765731] Invoking callback function 0x7688835c91b0 for event DDCA_Display_Status_Event[ 36.615: DDCA_EVENT_DDC_ENABLED, card1-HDMI-A-2, dref: DDCA_Display_Ref[3], io_path:/dev/i2c-6, ddc working: false] in this thread [1765731] Mar 07 23:05:21 r9950 org_kde_powerdevil[1764508]: [1765731] Callback function 0x7688835c91b0 for event DDCA_Display_Status_Event[ 36.615: DDCA_EVENT_DDC_ENABLED, card1-HDMI-A-2, dref: DDCA_Display_Ref[3], io_path:/dev/i2c-6, ddc working: false] complete Mar 07 23:05:21 r9950 org_kde_powerdevil[1764508]: [1764508] Watch thread terminated. Mar 07 23:05:22 r9950 org_kde_powerdevil[1764508]: [1764508] (i2c_detect_x37) Extra x37 sleep: Slept for 400 millisec Mar 07 23:05:22 r9950 org_kde_powerdevil[1764508]: [1764508] (i2c_detect_x37) Extra x37 sleep: Slept for 400 millisec Mar 07 23:05:22 r9950 org_kde_powerdevil[1764508]: [1764508] (i2c_detect_x37) Extra x37 sleep: Slept for 400 millisec Mar 07 23:05:25 r9950 org_kde_powerdevil[1764508]: [1764508] (check_supported_feature) busno=5, sleep-multiplier = 2,00. Testing for supported feature 0x10 returned Error_Info[DDCRC_RETRIES in ddc_write_read_with_retry, causes: DDCRC_DDC_DATA(10)] Mar 07 23:05:25 r9950 org_kde_powerdevil[1764508]: [1764508] Watching for display connection changes, resolved watch mode = Watch_Mode_Xevent, poll loop interval = 100 millisec Mar 07 23:05:25 r9950 org_kde_powerdevil[1764508]: [1764508] extra_stabilization_millisec: 0, stabilization_poll_millisec: 100 Mar 07 23:05:25 r9950 org_kde_powerdevil[1764508]: [1764508] libddcutil recheck thread (nil) started Mar 07 23:05:25 r9950 org_kde_powerdevil[1764508]: [1764508] libddcutil watch thread 0x5a8509508f20 started Mar 07 23:05:25 r9950 org_kde_powerdevil[1764508]: [1764508] Display redetection finished. Mar 07 23:05:25 r9950 org_kde_powerdevil[1764508]: [1764508] Unquiescing libddcutil API... Mar 07 23:05:25 r9950 org_kde_powerdevil[1764508]: [1765896] (dw_recheck_displays_func) Recheck interval: Slept for 200 millisec Mar 07 23:06:42 r9950 org_kde_powerdevil[1764508]: [1765897] Removing connected display on bus 6 Mar 07 23:06:42 r9950 org_kde_powerdevil[1764508]: [1765897] (dw_remove_display_by_businfo) No Display_Ref found for i2c bus: 6 Mar 07 23:06:44 r9950 org_kde_powerdevil[1764508]: [1765897] (i2c_detect_x37) Extra x37 sleep: Slept for 400 millisec Mar 07 23:06:44 r9950 org_kde_powerdevil[1764508]: [1765897] (i2c_detect_x37) Extra x37 sleep: Slept for 400 millisec Mar 07 23:06:44 r9950 org_kde_powerdevil[1764508]: [1765897] (i2c_detect_x37) Extra x37 sleep: Slept for 400 millisec Mar 07 23:06:44 r9950 org_kde_powerdevil[1764508]: [1765897] Adding connected display with bus 6 Mar 07 23:06:44 r9950 org_kde_powerdevil[1764508]: [1765897] Emitting DDCA_Display_Status_Event[119.939: DDCA_EVENT_DISPLAY_CONNECTED, card1-HDMI-A-2, dref: DDCA_Display_Ref[6], io_path:/dev/i2c-6, ddc working: false] Mar 07 23:06:44 r9950 org_kde_powerdevil[1764508]: [1765897] libddcutil callback thread 0x768854001c70 started Mar 07 23:06:44 r9950 org_kde_powerdevil[1764508]: [1765897] Started 1 event callback thread(s) Mar 07 23:06:44 r9950 org_kde_powerdevil[1764508]: [1768384] Invoking callback function 0x7688835c91b0 for event DDCA_Display_Status_Event[119.939: DDCA_EVENT_DISPLAY_CONNECTED, card1-HDMI-A-2, dref: DDCA_Display_Ref[6], io_path:/dev/i2c-6, ddc working: false] in this thread [1768384] Mar 07 23:06:44 r9950 org_kde_powerdevil[1764508]: [1768384] Callback function 0x7688835c91b0 for event DDCA_Display_Status_Event[119.939: DDCA_EVENT_DISPLAY_CONNECTED, card1-HDMI-A-2, dref: DDCA_Display_Ref[6], io_path:/dev/i2c-6, ddc working: false] complete Mar 07 23:06:44 r9950 org_kde_powerdevil[1764508]: [1764508] Quiescing libddcutil API... Mar 07 23:06:44 r9950 org_kde_powerdevil[1764508]: [1764508] Quiesce libddcutil API complete Mar 07 23:06:44 r9950 org_kde_powerdevil[1764508]: [1764508] Display redetection starting. Mar 07 23:06:44 r9950 org_kde_powerdevil[1764508]: [1765896] ddc became enabled for Display_Ref[6:bus /dev/i2c-6 @0x768854014e60] after 0 milliseconds Mar 07 23:06:44 r9950 org_kde_powerdevil[1764508]: [1765896] Emitting DDCA_Display_Status_Event[119.939: DDCA_EVENT_DDC_ENABLED, card1-HDMI-A-2, dref: DDCA_Display_Ref[6], io_path:/dev/i2c-6, ddc working: false] Mar 07 23:06:44 r9950 org_kde_powerdevil[1764508]: [1765896] libddcutil callback thread 0x7688580024f0 started Mar 07 23:06:44 r9950 org_kde_powerdevil[1764508]: [1765896] Started 1 event callback thread(s) Mar 07 23:06:44 r9950 org_kde_powerdevil[1764508]: [1765896] recheck thread terminating because watch thread terminated Mar 07 23:06:44 r9950 org_kde_powerdevil[1764508]: [1768385] Invoking callback function 0x7688835c91b0 for event DDCA_Display_Status_Event[119.939: DDCA_EVENT_DDC_ENABLED, card1-HDMI-A-2, dref: DDCA_Display_Ref[6], io_path:/dev/i2c-6, ddc working: false] in this thread [1768385] Mar 07 23:06:44 r9950 org_kde_powerdevil[1764508]: [1768385] Callback function 0x7688835c91b0 for event DDCA_Display_Status_Event[119.939: DDCA_EVENT_DDC_ENABLED, card1-HDMI-A-2, dref: DDCA_Display_Ref[6], io_path:/dev/i2c-6, ddc working: false] complete Mar 07 23:06:45 r9950 org_kde_powerdevil[1764508]: [1764508] Watch thread terminated. Mar 07 23:06:45 r9950 org_kde_powerdevil[1764508]: [1764508] (i2c_detect_x37) Extra x37 sleep: Slept for 400 millisec Mar 07 23:06:45 r9950 org_kde_powerdevil[1764508]: [1764508] (i2c_detect_x37) Extra x37 sleep: Slept for 400 millisec Mar 07 23:06:46 r9950 org_kde_powerdevil[1764508]: [1764508] (i2c_detect_x37) Extra x37 sleep: Slept for 400 millisec Mar 07 23:06:48 r9950 org_kde_powerdevil[1764508]: [1764508] Watching for display connection changes, resolved watch mode = Watch_Mode_Xevent, poll loop interval = 100 millisec Mar 07 23:06:48 r9950 org_kde_powerdevil[1764508]: [1764508] extra_stabilization_millisec: 0, stabilization_poll_millisec: 100 Mar 07 23:06:48 r9950 org_kde_powerdevil[1764508]: [1764508] libddcutil recheck thread (nil) started Mar 07 23:06:48 r9950 org_kde_powerdevil[1764508]: [1764508] libddcutil watch thread 0x5a8509570d70 started Mar 07 23:06:48 r9950 org_kde_powerdevil[1764508]: [1764508] Display redetection finished. Mar 07 23:06:48 r9950 org_kde_powerdevil[1764508]: [1764508] Unquiescing libddcutil API... Mar 07 23:06:49 r9950 org_kde_powerdevil[1764508]: [1768468] (dw_recheck_displays_func) Recheck interval: Slept for 200 millisec Mar 07 23:06:51 r9950 org_kde_powerdevil[1764508]: org.kde.powerdevil: [DDCutilDisplay]: ddca_get_non_table_vcp_value -3007 Mar 07 23:06:51 r9950 org_kde_powerdevil[1764508]: org.kde.powerdevil: [DDCutilDetector]: Display "SMBX2231" does not seem to support brightness control - wait before retrying initialization Mar 07 23:06:51 r9950 org_kde_powerdevil[1764508]: org.kde.powerdevil: [DDCutilDisplay]: "SMBX2231" retrying to initialize DDC/CI brightness in 1000 milliseconds - attempt no. 1 Mar 07 23:06:52 r9950 org_kde_powerdevil[1764508]: org.kde.powerdevil: [DDCutilDisplay]: "SMBX2231" succeeded to initialize DDC/CI brightness Mar 07 23:06:55 r9950 org_kde_powerdevil[1764508]: org.kde.powerdevil: [DDCutilDisplay]: ddca_get_non_table_vcp_value -3007 Mar 07 23:08:28 r9950 org_kde_powerdevil[1764508]: [1768469] Removing connected display on bus 6 Mar 07 23:08:28 r9950 org_kde_powerdevil[1764508]: [1768469] (dw_remove_display_by_businfo) No Display_Ref found for i2c bus: 6 Mar 07 23:08:30 r9950 org_kde_powerdevil[1764508]: [1768469] (i2c_detect_x37) Extra x37 sleep: Slept for 400 millisec Mar 07 23:08:31 r9950 org_kde_powerdevil[1764508]: [1768469] (i2c_detect_x37) Extra x37 sleep: Slept for 400 millisec Mar 07 23:08:31 r9950 org_kde_powerdevil[1764508]: org.kde.powerdevil: [DDCutilDisplay]: ddca_get_non_table_vcp_value -3007 Mar 07 23:08:31 r9950 org_kde_powerdevil[1764508]: [1768469] (i2c_detect_x37) Extra x37 sleep: Slept for 400 millisec Mar 07 23:08:31 r9950 org_kde_powerdevil[1764508]: [1768469] Adding connected display with bus 6 Mar 07 23:08:31 r9950 org_kde_powerdevil[1764508]: [1768469] Emitting DDCA_Display_Status_Event[226.576: DDCA_EVENT_DISPLAY_CONNECTED, card1-HDMI-A-2, dref: DDCA_Display_Ref[9], io_path:/dev/i2c-6, ddc working: false] Mar 07 23:08:31 r9950 org_kde_powerdevil[1764508]: [1768469] libddcutil callback thread 0x768858012ac0 started Mar 07 23:08:31 r9950 org_kde_powerdevil[1764508]: [1768469] Started 1 event callback thread(s) Mar 07 23:08:31 r9950 org_kde_powerdevil[1764508]: [1771453] Invoking callback function 0x7688835c91b0 for event DDCA_Display_Status_Event[226.576: DDCA_EVENT_DISPLAY_CONNECTED, card1-HDMI-A-2, dref: DDCA_Display_Ref[9], io_path:/dev/i2c-6, ddc working: false] in this thread [1771453] Mar 07 23:08:31 r9950 org_kde_powerdevil[1764508]: [1771453] Callback function 0x7688835c91b0 for event DDCA_Display_Status_Event[226.576: DDCA_EVENT_DISPLAY_CONNECTED, card1-HDMI-A-2, dref: DDCA_Display_Ref[9], io_path:/dev/i2c-6, ddc working: false] complete Mar 07 23:08:31 r9950 org_kde_powerdevil[1764508]: [1764508] Quiescing libddcutil API... Mar 07 23:08:31 r9950 org_kde_powerdevil[1764508]: [1768468] ddc became enabled for Display_Ref[9:bus /dev/i2c-6 @0x76885801a5f0] after 0 milliseconds Mar 07 23:08:31 r9950 org_kde_powerdevil[1764508]: [1768468] Emitting DDCA_Display_Status_Event[226.576: DDCA_EVENT_DDC_ENABLED, card1-HDMI-A-2, dref: DDCA_Display_Ref[9], io_path:/dev/i2c-6, ddc working: false] Mar 07 23:08:31 r9950 org_kde_powerdevil[1764508]: [1768468] libddcutil callback thread 0x768854014c60 started Mar 07 23:08:31 r9950 org_kde_powerdevil[1764508]: [1768468] Started 1 event callback thread(s) Mar 07 23:08:31 r9950 org_kde_powerdevil[1764508]: [1771454] Invoking callback function 0x7688835c91b0 for event DDCA_Display_Status_Event[226.576: DDCA_EVENT_DDC_ENABLED, card1-HDMI-A-2, dref: DDCA_Display_Ref[9], io_path:/dev/i2c-6, ddc working: false] in this thread [1771454] Mar 07 23:08:31 r9950 org_kde_powerdevil[1764508]: [1771454] Callback function 0x7688835c91b0 for event DDCA_Display_Status_Event[226.576: DDCA_EVENT_DDC_ENABLED, card1-HDMI-A-2, dref: DDCA_Display_Ref[9], io_path:/dev/i2c-6, ddc working: false] complete Mar 07 23:08:31 r9950 org_kde_powerdevil[1764508]: [1768468] (dw_recheck_displays_func) Recheck interval: Slept for 200 millisec Mar 07 23:08:34 r9950 org_kde_powerdevil[1764508]: Error queiscing libdducitl API. 1 active API calls outstanding. Mar 07 23:08:34 r9950 org_kde_powerdevil[1764508]: [1764508] Error queiscing libdducitl API. 1 active API calls outstanding. Mar 07 23:08:34 r9950 org_kde_powerdevil[1764508]: org.kde.powerdevil: [DDCutilDisplay]: ddca_close_display -3032 Mar 07 23:08:34 r9950 org_kde_powerdevil[1764508]: library quiesced, ddca_close_display temporarily unavailable Mar 07 23:08:34 r9950 org_kde_powerdevil[1764508]: org.kde.powerdevil: [DDCutilDisplay]: ddca_open_display2 -3032 Mar 07 23:08:34 r9950 org_kde_powerdevil[1764508]: [1764508] Display redetection starting. Mar 07 23:08:34 r9950 org_kde_powerdevil[1764508]: library quiesced, ddca_open_display3 temporarily unavailable Mar 07 23:08:34 r9950 org_kde_powerdevil[1764508]: [1768468] recheck thread terminating because watch thread terminated Mar 07 23:08:34 r9950 org_kde_powerdevil[1764508]: [1764508] Watch thread terminated. Mar 07 23:08:34 r9950 org_kde_powerdevil[1764508]: [1764508] Attempting to unlock display lock owned by different thread Mar 07 23:08:34 r9950 org_kde_powerdevil[1764508]: [1764508] Unexpected error DDCRC_LOCKED from unlock_display_by_dpath(Display_Path[/dev/i2c-5]) ```
I have made extensive extensive changes to libddcutil in branch 2.2.1-dev to detect API usage errors and diagnose display lock deadlocks. A key problem is that calling ddca_redetect_displays() while display watch is active can produce invalid states. Prior to release 2.2.0, display change detection just informed the client by callback that the display configuration had changed, leaving it to the client to call ddca_redetect_displays() which tells libddcutil to discard everything it knows about connected displays. As of release 2.2.0, display change detection updates libddcuti's internal tables and informs the client by callback what has changed. The client should not need to call ddca_redetect_displays(). A key check is preventing ddca_redetect_displays() from executing with callback threads are active. This can lead to corrupt data structures. Callback functions run in their own thread and libddcutil does not block until the callback completes - otherwise an errant callback function could hang display watch detection. Unfortunately, I don't see a way to distinguish using the glib API between callbacks that are still executing, and which should bock ddca_redetect_displays(), and ones that have actually died. So at best what happens is that an error message is written to the system log warning the ddca_redetect_displays() appears to be called when callback threads are executing. But again, all this convoluted and imperfect logic can be avoided by avoiding use of ddca_redetect_displays() If deadlocks persist, please run with the following settings in configuration file ddcutilrc: options: --ts --tid options: --ts --trace api --trcfile display_lock.c options: --trace-to-syslog-only options: --trcfunc add_open_display_for_current_thread --trcfunc remove_open_display_for_current_thread options: --trcfunc ddc_close_all_displays_for_current_thread options: --trcfunc unlock_all_displays_for_current_thread options: --trcfunc dw_execute_callback_func Output to the system log will be voluminous. Error messages in the system log may immediately indicate the problem. Otherwise leave it to me to examine the output. Unfortunately, I am traveling with only my laptop, so I am unable to test all these changes by attaching and detaching monitors. I also expect to be unavailable for the next several days. But I wanted to give people the opportunity to test with them.
After fixing a few typos (mutex null pointer resulting in crash and comparing a function pointer instead of the function return value resulting in an always true condition) ``` diff --git a/src/dw/dw_common.c b/src/dw/dw_common.c index 8d49cc5b..24a06d13 100644 --- a/src/dw/dw_common.c +++ b/src/dw/dw_common.c @@ -560,7 +560,7 @@ dw_stabilized_buses_bs(Bit_Set_256 bs_prior, bool some_displays_disconnected) { } -GMutex * active_callback_threads_mutex; +GMutex active_callback_threads_mutex; GHashTable * active_callback_threads; @@ -568,11 +568,11 @@ void record_active_callback_thread(GThread* pthread){ bool debug = false; DBGTRC_STARTING(debug,TRACE_GROUP, "pthread=p", pthread); - g_mutex_lock(active_callback_threads_mutex); + g_mutex_lock(&active_callback_threads_mutex); if (!active_callback_threads) active_callback_threads = g_hash_table_new(g_direct_hash, g_direct_equal); g_hash_table_add(active_callback_threads, pthread); - g_mutex_unlock(active_callback_threads_mutex); + g_mutex_unlock(&active_callback_threads_mutex); DBGTRC_DONE(debug, TRACE_GROUP, "pthread=%p"); } diff --git a/src/libmain/api_displays.c b/src/libmain/api_displays.c index 36d8eed9..9a85669a 100644 --- a/src/libmain/api_displays.c +++ b/src/libmain/api_displays.c @@ -451,7 +451,7 @@ ddca_redetect_displays() { API_PROLOGX(debug, NORESPECT_QUIESCE, ""); DDCA_Status ddcrc = 0; #ifdef WATCH_DISPLAYS - if (active_callback_thread_ct > 0) { + if (active_callback_thread_ct() > 0) { SYSLOG2(DDCA_SYSLOG_ERROR, "Attempting to call when callback threads are active"); ddcrc = DDCRC_INVALID_OPERATION; } ``` the deadlock still occurs. should be noted however that before I fixed the `active_callback_thread_ct` typo that it did not deadlock. since the log is too large for KDE bugtracker I uploaded it to pastebin: https://pastebin.com/raw/aa7kbZvN
ddcutil branch 2.2.1-dev contains fixes for the bugs Jonah Wagner identified. Based on the trace output, I've also modified ddca_close_display() to ignore the quiesced state, allowing to to release held locks. This should resolve the immediate deadlock problem, though there may certainly be others.
After fixing this typo to get ddcutil to compile ``` diff --git a/src/libmain/api_displays.c b/src/libmain/api_displays.c index 9e8a6ade..21829a13 100644 --- a/src/libmain/api_displays.c +++ b/src/libmain/api_displays.c @@ -722,7 +722,7 @@ ddca_close_display(DDCA_Display_Handle ddca_dh) { DDCA_Status rc = 0; Error_Info * err = NULL; Display_Handle * dh = (Display_Handle *) ddca_dh; - API_PROLOGX(debug, IGNORE_QUIESCE, "dh = %s", dh_repr(dh)); + API_PROLOGX(debug, NORESPECT_QUIESCE, "dh = %s", dh_repr(dh)); if (dh) { if (memcmp(dh->marker, DISPLAY_HANDLE_MARKER, 4) != 0 ) { err = ERRINFO_NEW(DDCRC_ARG, "Invalid display handle"); @@ -740,7 +740,7 @@ ddca_close_display(DDCA_Display_Handle ddca_dh) { save_thread_error_detail(public_error_detail); } - API_EPILOG_BEFORE_RETURN(debug, RESPECT_QUIESCE, rc, ""); + API_EPILOG_BEFORE_RETURN(debug, NORESPECT_QUIESCE, rc, ""); return rc; } ``` I can confirm that the deadlock in KDE Power Devil is fixed.
Looks like this is exclusively an upstream issue, then. Thanks for working on this, folks!