| Summary: | KDE PowerDevil deadlock causes kwin_wayland to hang | ||
|---|---|---|---|
| Product: | [Plasma] plasmashell | Reporter: | Jona Wagner <jona> |
| Component: | Power management & brightness | Assignee: | Plasma Bugs List <plasma-bugs> |
| Status: | RESOLVED UPSTREAM | ||
| Severity: | major | CC: | jpetso, julien.dlq, lee295012, m66q4blzl, nate, rockowitz, vlad.zahorodnii, xaver.hugl |
| Priority: | NOR | ||
| Version First Reported In: | 6.3.2 | ||
| Target Milestone: | 1.0 | ||
| Platform: | Arch Linux | ||
| OS: | Linux | ||
| Latest Commit: | Version Fixed In: | ddcutil 2.2.1 | |
| Sentry Crash Report: | |||
|
Description
Jona Wagner
2025-03-02 11:17:44 UTC
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! *** Bug 505094 has been marked as a duplicate of this bug. *** |