| Message ID | 20180718205645.25924-2-lyude@redhat.com (mailing list archive) |
|---|---|
| State | New, archived |
| Headers | show |
On Wed, Jul 18, 2018 at 04:56:39PM -0400, Lyude Paul wrote: > When DP MST hubs get confused, they can occasionally stop responding for > a good bit of time up until the point where the DRM driver manages to > do the right DPCD accesses to get it to start responding again. In a > worst case scenario however, this process can take upwards of 10+ > seconds. > > Currently we use the default output_poll_changed handler > drm_fb_helper_output_poll_changed() to handle output polling, which > doesn't happen to grab any power references on the device when polling. > If we're unlucky enough to have a hub (such as Lenovo's infamous laptop > docks for the P5x/P7x series) that's easily startled and confused, this > can lead to a pretty nasty deadlock situation that looks like this: > > - Hotplug event from hub happens, we enter > drm_fb_helper_output_poll_changed() and start communicating with the > hub > - While we're in drm_fb_helper_output_poll_changed() and attempting to > communicate with the hub, we end up confusing it and cause it to stop > responding for at least 10 seconds > - After 5 seconds of being in drm_fb_helper_output_poll_changed(), the > pm core attempts to put the GPU into autosuspend, which ends up > calling drm_kms_helper_poll_disable() > - While the runtime PM core is waiting in drm_kms_helper_poll_disable() > for the output poll to finish, we end up finally detecting an MST > display > - We notice the new display and tries to enable it, which triggers > an atomic commit which triggers a call to pm_runtime_get_sync() > - the output poll thread deadlocks the pm core waiting for the pm core > to finish the autosuspend request while the pm core waits for the > output poll thread to finish This will still deadlock if ->runtime_suspend commences before the hotplug event and the hotplug event occurs before polling has been disabled by ->runtime_suspend. The correct fix is to call pm_runtime_get_sync() *conditionally* in the atomic commit which enables the display, using the same conditional as d61a5c106351, i.e. if (!drm_kms_helper_is_poll_worker()). Now I realize I sent you down the wrong path when I suggested to introduce a DRM helper here. My apologies, I didn't fully appreciate what is going awry here! Anything that happens in nouveau's poll worker never needs to acquire a runtime PM ref because polling is only enabled while runtime active, and ->runtime_suspend waits for an ongoing poll to finish. Thinking a bit more about this, our mistake is to acquire runtime PM refs too far down in the call stack. As a fix that can be backported to stable, adding if (!drm_kms_helper_is_poll_worker()) conditionals seems fine to me, but the long term fix is to push acquisition of refs further up in the call stack. E.g., if the user forces connector probing via sysfs, a runtime PM ref should be acquired in status_store() in drm_sysfs.c before invoking connector->funcs->fill_modes(). That way, if the user forces connector probing while the GPU is powering down, rpm_resume() will correctly wait for rpm_suspend() to finish before resuming the card. So if we architect it like this, we're actually using the functionality provided by the PM core in the way that it's supposed to be used. The problem is that adding pm_runtime_get_sync() to status_store() conflicts with the desire to have a library of generic DRM functions: Some GPUs may be able to probe connectors without resuming to runtime active state, others don't use runtime PM at all. One solution that comes to mind is a driver_features flag which tells the DRM core whether to acquire a runtime PM ref in various places. In your original patches 4 and 5, what exactly was the call stack which led to i2c being accessed while runtime suspended? Was it sysfs access via /sys/class/i2c-adapter/* ? If so, acquisition of the runtime PM ref needs to likewise happen in that sysfs entry point, rather than deep down in the call stack upon accessing the i2c bus. Thanks, Lukas > > Sample: > [ 246.669625] INFO: task kworker/4:0:37 blocked for more than 120 seconds. > [ 246.673398] Not tainted 4.18.0-rc5Lyude-Test+ #2 > [ 246.675271] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. > [ 246.676527] kworker/4:0 D 0 37 2 0x80000000 > [ 246.677580] Workqueue: events output_poll_execute [drm_kms_helper] > [ 246.678704] Call Trace: > [ 246.679753] __schedule+0x322/0xaf0 > [ 246.680916] schedule+0x33/0x90 > [ 246.681924] schedule_preempt_disabled+0x15/0x20 > [ 246.683023] __mutex_lock+0x569/0x9a0 > [ 246.684035] ? kobject_uevent_env+0x117/0x7b0 > [ 246.685132] ? drm_fb_helper_hotplug_event.part.28+0x20/0xb0 [drm_kms_helper] > [ 246.686179] mutex_lock_nested+0x1b/0x20 > [ 246.687278] ? mutex_lock_nested+0x1b/0x20 > [ 246.688307] drm_fb_helper_hotplug_event.part.28+0x20/0xb0 [drm_kms_helper] > [ 246.689420] drm_fb_helper_output_poll_changed+0x23/0x30 [drm_kms_helper] > [ 246.690462] drm_kms_helper_hotplug_event+0x2a/0x30 [drm_kms_helper] > [ 246.691570] output_poll_execute+0x198/0x1c0 [drm_kms_helper] > [ 246.692611] process_one_work+0x231/0x620 > [ 246.693725] worker_thread+0x214/0x3a0 > [ 246.694756] kthread+0x12b/0x150 > [ 246.695856] ? wq_pool_ids_show+0x140/0x140 > [ 246.696888] ? kthread_create_worker_on_cpu+0x70/0x70 > [ 246.697998] ret_from_fork+0x3a/0x50 > [ 246.699034] INFO: task kworker/0:1:60 blocked for more than 120 seconds. > [ 246.700153] Not tainted 4.18.0-rc5Lyude-Test+ #2 > [ 246.701182] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. > [ 246.702278] kworker/0:1 D 0 60 2 0x80000000 > [ 246.703293] Workqueue: pm pm_runtime_work > [ 246.704393] Call Trace: > [ 246.705403] __schedule+0x322/0xaf0 > [ 246.706439] ? wait_for_completion+0x104/0x190 > [ 246.707393] schedule+0x33/0x90 > [ 246.708375] schedule_timeout+0x3a5/0x590 > [ 246.709289] ? mark_held_locks+0x58/0x80 > [ 246.710208] ? _raw_spin_unlock_irq+0x2c/0x40 > [ 246.711222] ? wait_for_completion+0x104/0x190 > [ 246.712134] ? trace_hardirqs_on_caller+0xf4/0x190 > [ 246.713094] ? wait_for_completion+0x104/0x190 > [ 246.713964] wait_for_completion+0x12c/0x190 > [ 246.714895] ? wake_up_q+0x80/0x80 > [ 246.715727] ? get_work_pool+0x90/0x90 > [ 246.716649] flush_work+0x1c9/0x280 > [ 246.717483] ? flush_workqueue_prep_pwqs+0x1b0/0x1b0 > [ 246.718442] __cancel_work_timer+0x146/0x1d0 > [ 246.719247] cancel_delayed_work_sync+0x13/0x20 > [ 246.720043] drm_kms_helper_poll_disable+0x1f/0x30 [drm_kms_helper] > [ 246.721123] nouveau_pmops_runtime_suspend+0x3d/0xb0 [nouveau] > [ 246.721897] pci_pm_runtime_suspend+0x6b/0x190 > [ 246.722825] ? pci_has_legacy_pm_support+0x70/0x70 > [ 246.723737] __rpm_callback+0x7a/0x1d0 > [ 246.724721] ? pci_has_legacy_pm_support+0x70/0x70 > [ 246.725607] rpm_callback+0x24/0x80 > [ 246.726553] ? pci_has_legacy_pm_support+0x70/0x70 > [ 246.727376] rpm_suspend+0x142/0x6b0 > [ 246.728185] pm_runtime_work+0x97/0xc0 > [ 246.728938] process_one_work+0x231/0x620 > [ 246.729796] worker_thread+0x44/0x3a0 > [ 246.730614] kthread+0x12b/0x150 > [ 246.731395] ? wq_pool_ids_show+0x140/0x140 > [ 246.732202] ? kthread_create_worker_on_cpu+0x70/0x70 > [ 246.732878] ret_from_fork+0x3a/0x50 > [ 246.733768] INFO: task kworker/4:2:422 blocked for more than 120 seconds. > [ 246.734587] Not tainted 4.18.0-rc5Lyude-Test+ #2 > [ 246.735393] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. > [ 246.736113] kworker/4:2 D 0 422 2 0x80000080 > [ 246.736789] Workqueue: events_long drm_dp_mst_link_probe_work [drm_kms_helper] > [ 246.737665] Call Trace: > [ 246.738490] __schedule+0x322/0xaf0 > [ 246.739250] schedule+0x33/0x90 > [ 246.739908] rpm_resume+0x19c/0x850 > [ 246.740750] ? finish_wait+0x90/0x90 > [ 246.741541] __pm_runtime_resume+0x4e/0x90 > [ 246.742370] nv50_disp_atomic_commit+0x31/0x210 [nouveau] > [ 246.743124] drm_atomic_commit+0x4a/0x50 [drm] > [ 246.743775] restore_fbdev_mode_atomic+0x1c8/0x240 [drm_kms_helper] > [ 246.744603] restore_fbdev_mode+0x31/0x140 [drm_kms_helper] > [ 246.745373] drm_fb_helper_restore_fbdev_mode_unlocked+0x54/0xb0 [drm_kms_helper] > [ 246.746220] drm_fb_helper_set_par+0x2d/0x50 [drm_kms_helper] > [ 246.746884] drm_fb_helper_hotplug_event.part.28+0x96/0xb0 [drm_kms_helper] > [ 246.747675] drm_fb_helper_output_poll_changed+0x23/0x30 [drm_kms_helper] > [ 246.748544] drm_kms_helper_hotplug_event+0x2a/0x30 [drm_kms_helper] > [ 246.749439] nv50_mstm_hotplug+0x15/0x20 [nouveau] > [ 246.750111] drm_dp_send_link_address+0x177/0x1c0 [drm_kms_helper] > [ 246.750764] drm_dp_check_and_send_link_address+0xa8/0xd0 [drm_kms_helper] > [ 246.751602] drm_dp_mst_link_probe_work+0x51/0x90 [drm_kms_helper] > [ 246.752314] process_one_work+0x231/0x620 > [ 246.752979] worker_thread+0x44/0x3a0 > [ 246.753838] kthread+0x12b/0x150 > [ 246.754619] ? wq_pool_ids_show+0x140/0x140 > [ 246.755386] ? kthread_create_worker_on_cpu+0x70/0x70 > [ 246.756162] ret_from_fork+0x3a/0x50 > [ 246.756847] > Showing all locks held in the system: > [ 246.758261] 3 locks held by kworker/4:0/37: > [ 246.759016] #0: 00000000f8df4d2d ((wq_completion)"events"){+.+.}, at: process_one_work+0x1b3/0x620 > [ 246.759856] #1: 00000000e6065461 ((work_completion)(&(&dev->mode_config.output_poll_work)->work)){+.+.}, at: process_one_work+0x1b3/0x620 > [ 246.760670] #2: 00000000cb66735f (&helper->lock){+.+.}, at: drm_fb_helper_hotplug_event.part.28+0x20/0xb0 [drm_kms_helper] > [ 246.761516] 2 locks held by kworker/0:1/60: > [ 246.762274] #0: 00000000fff6be0f ((wq_completion)"pm"){+.+.}, at: process_one_work+0x1b3/0x620 > [ 246.762982] #1: 000000005ab44fb4 ((work_completion)(&dev->power.work)){+.+.}, at: process_one_work+0x1b3/0x620 > [ 246.763890] 1 lock held by khungtaskd/64: > [ 246.764664] #0: 000000008cb8b5c3 (rcu_read_lock){....}, at: debug_show_all_locks+0x23/0x185 > [ 246.765588] 5 locks held by kworker/4:2/422: > [ 246.766440] #0: 00000000232f0959 ((wq_completion)"events_long"){+.+.}, at: process_one_work+0x1b3/0x620 > [ 246.767390] #1: 00000000bb59b134 ((work_completion)(&mgr->work)){+.+.}, at: process_one_work+0x1b3/0x620 > [ 246.768154] #2: 00000000cb66735f (&helper->lock){+.+.}, at: drm_fb_helper_restore_fbdev_mode_unlocked+0x4c/0xb0 [drm_kms_helper] > [ 246.768966] #3: 000000004c8f0b6b (crtc_ww_class_acquire){+.+.}, at: restore_fbdev_mode_atomic+0x4b/0x240 [drm_kms_helper] > [ 246.769921] #4: 000000004c34a296 (crtc_ww_class_mutex){+.+.}, at: drm_modeset_backoff+0x8a/0x1b0 [drm] > [ 246.770839] 1 lock held by dmesg/1038: > [ 246.771739] 2 locks held by zsh/1172: > [ 246.772650] #0: 00000000836d0438 (&tty->ldisc_sem){++++}, at: ldsem_down_read+0x37/0x40 > [ 246.773680] #1: 000000001f4f4d48 (&ldata->atomic_read_lock){+.+.}, at: n_tty_read+0xc1/0x870 > > [ 246.775522] ============================================= > > So, to fix this (and any other possible deadlock issues like this that > could occur in the output_poll_changed patch) we make sure that > nouveau's output_poll_changed functions grab a runtime power ref before > sending any hotplug events, and hold it until we're finished. We > introduce this through adding a generic DRM helper which other drivers > may reuse. > > This fixes deadlock issues when in fbcon with nouveau on my P50, and > should fix it for everyone else's as well! > > Signed-off-by: Lyude Paul <lyude@redhat.com> > Reviewed-by: Karol Herbst <karolherbst@gmail.com> > Cc: Lukas Wunner <lukas@wunner.de> > Cc: stable@vger.kernel.org > --- > Changes since v1: > - Add a generic helper for DRM to handle this > > drivers/gpu/drm/drm_fb_helper.c | 23 +++++++++++++++++++++++ > drivers/gpu/drm/nouveau/dispnv50/disp.c | 2 +- > include/drm/drm_fb_helper.h | 5 +++++ > 3 files changed, 29 insertions(+), 1 deletion(-) > > diff --git a/drivers/gpu/drm/drm_fb_helper.c b/drivers/gpu/drm/drm_fb_helper.c > index 2ee1eaa66188..1ab2f3646526 100644 > --- a/drivers/gpu/drm/drm_fb_helper.c > +++ b/drivers/gpu/drm/drm_fb_helper.c > @@ -34,6 +34,7 @@ > #include <linux/sysrq.h> > #include <linux/slab.h> > #include <linux/module.h> > +#include <linux/pm_runtime.h> > #include <drm/drmP.h> > #include <drm/drm_crtc.h> > #include <drm/drm_fb_helper.h> > @@ -2928,6 +2929,28 @@ void drm_fb_helper_output_poll_changed(struct drm_device *dev) > } > EXPORT_SYMBOL(drm_fb_helper_output_poll_changed); > > +/** > + * drm_fb_helper_output_poll_changed_with_rpm - DRM mode > + * config \.output_poll_changed > + * helper for fbdev emulation > + * @dev: DRM device > + * > + * Same as drm_fb_helper_output_poll_changed, except that it makes sure that > + * the device is active by synchronously grabbing a runtime power reference > + * while probing. > + */ > +void drm_fb_helper_output_poll_changed_with_rpm(struct drm_device *dev) > +{ > + int ret; > + > + ret = pm_runtime_get_sync(dev->dev); > + if (WARN_ON(ret < 0 && ret != -EACCES)) > + return; > + drm_fb_helper_hotplug_event(dev->fb_helper); > + pm_runtime_put(dev->dev); > +} > +EXPORT_SYMBOL(drm_fb_helper_output_poll_changed_with_rpm); > + > /* The Kconfig DRM_KMS_HELPER selects FRAMEBUFFER_CONSOLE (if !EXPERT) > * but the module doesn't depend on any fb console symbols. At least > * attempt to load fbcon to avoid leaving the system without a usable console. > diff --git a/drivers/gpu/drm/nouveau/dispnv50/disp.c b/drivers/gpu/drm/nouveau/dispnv50/disp.c > index eb3e41a78806..fa3ab618a0f9 100644 > --- a/drivers/gpu/drm/nouveau/dispnv50/disp.c > +++ b/drivers/gpu/drm/nouveau/dispnv50/disp.c > @@ -2015,7 +2015,7 @@ nv50_disp_atomic_state_alloc(struct drm_device *dev) > static const struct drm_mode_config_funcs > nv50_disp_func = { > .fb_create = nouveau_user_framebuffer_create, > - .output_poll_changed = drm_fb_helper_output_poll_changed, > + .output_poll_changed = drm_fb_helper_output_poll_changed_with_rpm, > .atomic_check = nv50_disp_atomic_check, > .atomic_commit = nv50_disp_atomic_commit, > .atomic_state_alloc = nv50_disp_atomic_state_alloc, > diff --git a/include/drm/drm_fb_helper.h b/include/drm/drm_fb_helper.h > index b069433e7fc1..ca809bfbaebb 100644 > --- a/include/drm/drm_fb_helper.h > +++ b/include/drm/drm_fb_helper.h > @@ -330,6 +330,7 @@ void drm_fb_helper_fbdev_teardown(struct drm_device *dev); > > void drm_fb_helper_lastclose(struct drm_device *dev); > void drm_fb_helper_output_poll_changed(struct drm_device *dev); > +void drm_fb_helper_output_poll_changed_with_rpm(struct drm_device *dev); > #else > static inline void drm_fb_helper_prepare(struct drm_device *dev, > struct drm_fb_helper *helper, > @@ -564,6 +565,10 @@ static inline void drm_fb_helper_output_poll_changed(struct drm_device *dev) > { > } > > +static inline void drm_fb_helper_output_poll_changed_with_rpm(struct drm_device *dev) > +{ > +} > + > #endif > > static inline int > -- > 2.17.1 >
On Thu, 2018-07-19 at 09:49 +0200, Lukas Wunner wrote: > On Wed, Jul 18, 2018 at 04:56:39PM -0400, Lyude Paul wrote: > > When DP MST hubs get confused, they can occasionally stop responding for > > a good bit of time up until the point where the DRM driver manages to > > do the right DPCD accesses to get it to start responding again. In a > > worst case scenario however, this process can take upwards of 10+ > > seconds. > > > > Currently we use the default output_poll_changed handler > > drm_fb_helper_output_poll_changed() to handle output polling, which > > doesn't happen to grab any power references on the device when polling. > > If we're unlucky enough to have a hub (such as Lenovo's infamous laptop > > docks for the P5x/P7x series) that's easily startled and confused, this > > can lead to a pretty nasty deadlock situation that looks like this: > > > > - Hotplug event from hub happens, we enter > > drm_fb_helper_output_poll_changed() and start communicating with the > > hub > > - While we're in drm_fb_helper_output_poll_changed() and attempting to > > communicate with the hub, we end up confusing it and cause it to stop > > responding for at least 10 seconds > > - After 5 seconds of being in drm_fb_helper_output_poll_changed(), the > > pm core attempts to put the GPU into autosuspend, which ends up > > calling drm_kms_helper_poll_disable() > > - While the runtime PM core is waiting in drm_kms_helper_poll_disable() > > for the output poll to finish, we end up finally detecting an MST > > display > > - We notice the new display and tries to enable it, which triggers > > an atomic commit which triggers a call to pm_runtime_get_sync() > > - the output poll thread deadlocks the pm core waiting for the pm core > > to finish the autosuspend request while the pm core waits for the > > output poll thread to finish > > This will still deadlock if ->runtime_suspend commences before the > hotplug event and the hotplug event occurs before polling has been > disabled by ->runtime_suspend. > > The correct fix is to call pm_runtime_get_sync() *conditionally* in > the atomic commit which enables the display, using the same conditional > as d61a5c106351, i.e. if (!drm_kms_helper_is_poll_worker()). > > Now I realize I sent you down the wrong path when I suggested to > introduce a DRM helper here. My apologies, I didn't fully appreciate > what is going awry here! > > Anything that happens in nouveau's poll worker never needs to acquire > a runtime PM ref because polling is only enabled while runtime active, > and ->runtime_suspend waits for an ongoing poll to finish. Hopefully I'm not missing anything here, but this doesn't really make any sense. I'm not sure I explained myself as well as I thought I did. To be honest, I had to double check this about literally 20 times to make sure I was actually understanding this issue correctly. Turns out I was missing a couple of parts, so I'm going to try again at explaining this using a diagram that shows the various threads running concurrently START: Driver load | | | Thread 1 ----- output_poll_execute() | drm_helper_hpd_irq_event() | | Schedules → Thread 2 ----------------- nouveau_display_hpd_work() Finish | pm_runtime_get_sync() <--- keeps GPU alive | ... | ------------------------------ <still Thread 2> drm_helper_hpd_irq_event() | | Schedules → ------------------------------ | Thread 3 Drop last RPM ref -v | output_poll_execute() pm_runtime_put_sync() | | drm_dp_mst_topology_mgr_set_mst() Finish | | ← Schedules | -----------------------------| | | Thread 4 | | | drm_dp_mst_link_probe_work() drm_dp_mst_wait_tx_reply() <-- these wait on eachother | | this is normal | Sideband transactions | | happen here, this is | | where timeouts happen | | | | 5 seconds later... | autosuspend delay kicks in | ... | | | | Thread 5 | Communication + timeouts | pm_runtime_work | are still happening here | | | | nouveau_pmops_runtime_suspend() | | | | Success! We can enable | | | displays now! | drm_kms_helper_poll_disable() | | | | *Atomic commit begins* | | | <------------- | | More sideband transactions | Waiting on | | ...... | output_poll_execute() | | | <------------- | | pm_runtime_get_sync() | | | | | --------------------> | -------------> | | Waiting on | Waiting on | | output_poll_exec() | suspend requests | | --------------------> | -------------> | | | | ----------------------------------------------------->| DEADLOCK phew. that took a LONG time to come up with. Anyway-that's why your explanation doesn't make sense: the deadlock is happening because we're calling pm_runtime_get_sync(). If we were to make that call conditional (e.g. drm_kms_helper_is_poll_worker()), all that would mean is that we wouldn't grab any runtime power reference and the GPU would immediately suspend once the atomic commit finished, as the suspend request in Thread 5 would finally get unblocked and thus----suspend. Hopefully I explained that better this time, I'll definitely make sure to actually include that diagram in the patch. As for whether or not this patch is even the right solution, I will need to confirm that tommorrow (if you don't think it is still, please feel free to say so!) because it's getting late here. Cheers! Lyude > > Thinking a bit more about this, our mistake is to acquire runtime PM > refs too far down in the call stack. As a fix that can be backported > to stable, adding if (!drm_kms_helper_is_poll_worker()) conditionals > seems fine to me, but the long term fix is to push acquisition of refs > further up in the call stack. > > E.g., if the user forces connector probing via sysfs, a runtime PM ref > should be acquired in status_store() in drm_sysfs.c before invoking > connector->funcs->fill_modes(). That way, if the user forces connector > probing while the GPU is powering down, rpm_resume() will correctly wait > for rpm_suspend() to finish before resuming the card. So if we architect > it like this, we're actually using the functionality provided by the > PM core in the way that it's supposed to be used. > > The problem is that adding pm_runtime_get_sync() to status_store() > conflicts with the desire to have a library of generic DRM functions: > Some GPUs may be able to probe connectors without resuming to runtime > active state, others don't use runtime PM at all. One solution that > comes to mind is a driver_features flag which tells the DRM core whether > to acquire a runtime PM ref in various places. > > In your original patches 4 and 5, what exactly was the call stack which > led to i2c being accessed while runtime suspended? Was it sysfs access > via /sys/class/i2c-adapter/* ? If so, acquisition of the runtime PM ref > needs to likewise happen in that sysfs entry point, rather than deep down > in the call stack upon accessing the i2c bus. > > Thanks, > > Lukas > > > > > Sample: > > [ 246.669625] INFO: task kworker/4:0:37 blocked for more than 120 > > seconds. > > [ 246.673398] Not tainted 4.18.0-rc5Lyude-Test+ #2 > > [ 246.675271] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables > > this message. > > [ 246.676527] kworker/4:0 D 0 37 2 0x80000000 > > [ 246.677580] Workqueue: events output_poll_execute [drm_kms_helper] > > [ 246.678704] Call Trace: > > [ 246.679753] __schedule+0x322/0xaf0 > > [ 246.680916] schedule+0x33/0x90 > > [ 246.681924] schedule_preempt_disabled+0x15/0x20 > > [ 246.683023] __mutex_lock+0x569/0x9a0 > > [ 246.684035] ? kobject_uevent_env+0x117/0x7b0 > > [ 246.685132] ? drm_fb_helper_hotplug_event.part.28+0x20/0xb0 > > [drm_kms_helper] > > [ 246.686179] mutex_lock_nested+0x1b/0x20 > > [ 246.687278] ? mutex_lock_nested+0x1b/0x20 > > [ 246.688307] drm_fb_helper_hotplug_event.part.28+0x20/0xb0 > > [drm_kms_helper] > > [ 246.689420] drm_fb_helper_output_poll_changed+0x23/0x30 > > [drm_kms_helper] > > [ 246.690462] drm_kms_helper_hotplug_event+0x2a/0x30 [drm_kms_helper] > > [ 246.691570] output_poll_execute+0x198/0x1c0 [drm_kms_helper] > > [ 246.692611] process_one_work+0x231/0x620 > > [ 246.693725] worker_thread+0x214/0x3a0 > > [ 246.694756] kthread+0x12b/0x150 > > [ 246.695856] ? wq_pool_ids_show+0x140/0x140 > > [ 246.696888] ? kthread_create_worker_on_cpu+0x70/0x70 > > [ 246.697998] ret_from_fork+0x3a/0x50 > > [ 246.699034] INFO: task kworker/0:1:60 blocked for more than 120 > > seconds. > > [ 246.700153] Not tainted 4.18.0-rc5Lyude-Test+ #2 > > [ 246.701182] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables > > this message. > > [ 246.702278] kworker/0:1 D 0 60 2 0x80000000 > > [ 246.703293] Workqueue: pm pm_runtime_work > > [ 246.704393] Call Trace: > > [ 246.705403] __schedule+0x322/0xaf0 > > [ 246.706439] ? wait_for_completion+0x104/0x190 > > [ 246.707393] schedule+0x33/0x90 > > [ 246.708375] schedule_timeout+0x3a5/0x590 > > [ 246.709289] ? mark_held_locks+0x58/0x80 > > [ 246.710208] ? _raw_spin_unlock_irq+0x2c/0x40 > > [ 246.711222] ? wait_for_completion+0x104/0x190 > > [ 246.712134] ? trace_hardirqs_on_caller+0xf4/0x190 > > [ 246.713094] ? wait_for_completion+0x104/0x190 > > [ 246.713964] wait_for_completion+0x12c/0x190 > > [ 246.714895] ? wake_up_q+0x80/0x80 > > [ 246.715727] ? get_work_pool+0x90/0x90 > > [ 246.716649] flush_work+0x1c9/0x280 > > [ 246.717483] ? flush_workqueue_prep_pwqs+0x1b0/0x1b0 > > [ 246.718442] __cancel_work_timer+0x146/0x1d0 > > [ 246.719247] cancel_delayed_work_sync+0x13/0x20 > > [ 246.720043] drm_kms_helper_poll_disable+0x1f/0x30 [drm_kms_helper] > > [ 246.721123] nouveau_pmops_runtime_suspend+0x3d/0xb0 [nouveau] > > [ 246.721897] pci_pm_runtime_suspend+0x6b/0x190 > > [ 246.722825] ? pci_has_legacy_pm_support+0x70/0x70 > > [ 246.723737] __rpm_callback+0x7a/0x1d0 > > [ 246.724721] ? pci_has_legacy_pm_support+0x70/0x70 > > [ 246.725607] rpm_callback+0x24/0x80 > > [ 246.726553] ? pci_has_legacy_pm_support+0x70/0x70 > > [ 246.727376] rpm_suspend+0x142/0x6b0 > > [ 246.728185] pm_runtime_work+0x97/0xc0 > > [ 246.728938] process_one_work+0x231/0x620 > > [ 246.729796] worker_thread+0x44/0x3a0 > > [ 246.730614] kthread+0x12b/0x150 > > [ 246.731395] ? wq_pool_ids_show+0x140/0x140 > > [ 246.732202] ? kthread_create_worker_on_cpu+0x70/0x70 > > [ 246.732878] ret_from_fork+0x3a/0x50 > > [ 246.733768] INFO: task kworker/4:2:422 blocked for more than 120 > > seconds. > > [ 246.734587] Not tainted 4.18.0-rc5Lyude-Test+ #2 > > [ 246.735393] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables > > this message. > > [ 246.736113] kworker/4:2 D 0 422 2 0x80000080 > > [ 246.736789] Workqueue: events_long drm_dp_mst_link_probe_work > > [drm_kms_helper] > > [ 246.737665] Call Trace: > > [ 246.738490] __schedule+0x322/0xaf0 > > [ 246.739250] schedule+0x33/0x90 > > [ 246.739908] rpm_resume+0x19c/0x850 > > [ 246.740750] ? finish_wait+0x90/0x90 > > [ 246.741541] __pm_runtime_resume+0x4e/0x90 > > [ 246.742370] nv50_disp_atomic_commit+0x31/0x210 [nouveau] > > [ 246.743124] drm_atomic_commit+0x4a/0x50 [drm] > > [ 246.743775] restore_fbdev_mode_atomic+0x1c8/0x240 [drm_kms_helper] > > [ 246.744603] restore_fbdev_mode+0x31/0x140 [drm_kms_helper] > > [ 246.745373] drm_fb_helper_restore_fbdev_mode_unlocked+0x54/0xb0 > > [drm_kms_helper] > > [ 246.746220] drm_fb_helper_set_par+0x2d/0x50 [drm_kms_helper] > > [ 246.746884] drm_fb_helper_hotplug_event.part.28+0x96/0xb0 > > [drm_kms_helper] > > [ 246.747675] drm_fb_helper_output_poll_changed+0x23/0x30 > > [drm_kms_helper] > > [ 246.748544] drm_kms_helper_hotplug_event+0x2a/0x30 [drm_kms_helper] > > [ 246.749439] nv50_mstm_hotplug+0x15/0x20 [nouveau] > > [ 246.750111] drm_dp_send_link_address+0x177/0x1c0 [drm_kms_helper] > > [ 246.750764] drm_dp_check_and_send_link_address+0xa8/0xd0 > > [drm_kms_helper] > > [ 246.751602] drm_dp_mst_link_probe_work+0x51/0x90 [drm_kms_helper] > > [ 246.752314] process_one_work+0x231/0x620 > > [ 246.752979] worker_thread+0x44/0x3a0 > > [ 246.753838] kthread+0x12b/0x150 > > [ 246.754619] ? wq_pool_ids_show+0x140/0x140 > > [ 246.755386] ? kthread_create_worker_on_cpu+0x70/0x70 > > [ 246.756162] ret_from_fork+0x3a/0x50 > > [ 246.756847] > > Showing all locks held in the system: > > [ 246.758261] 3 locks held by kworker/4:0/37: > > [ 246.759016] #0: 00000000f8df4d2d ((wq_completion)"events"){+.+.}, at: > > process_one_work+0x1b3/0x620 > > [ 246.759856] #1: 00000000e6065461 ((work_completion)(&(&dev- > > >mode_config.output_poll_work)->work)){+.+.}, at: > > process_one_work+0x1b3/0x620 > > [ 246.760670] #2: 00000000cb66735f (&helper->lock){+.+.}, at: > > drm_fb_helper_hotplug_event.part.28+0x20/0xb0 [drm_kms_helper] > > [ 246.761516] 2 locks held by kworker/0:1/60: > > [ 246.762274] #0: 00000000fff6be0f ((wq_completion)"pm"){+.+.}, at: > > process_one_work+0x1b3/0x620 > > [ 246.762982] #1: 000000005ab44fb4 ((work_completion)(&dev- > > >power.work)){+.+.}, at: process_one_work+0x1b3/0x620 > > [ 246.763890] 1 lock held by khungtaskd/64: > > [ 246.764664] #0: 000000008cb8b5c3 (rcu_read_lock){....}, at: > > debug_show_all_locks+0x23/0x185 > > [ 246.765588] 5 locks held by kworker/4:2/422: > > [ 246.766440] #0: 00000000232f0959 ((wq_completion)"events_long"){+.+.}, > > at: process_one_work+0x1b3/0x620 > > [ 246.767390] #1: 00000000bb59b134 ((work_completion)(&mgr- > > >work)){+.+.}, at: process_one_work+0x1b3/0x620 > > [ 246.768154] #2: 00000000cb66735f (&helper->lock){+.+.}, at: > > drm_fb_helper_restore_fbdev_mode_unlocked+0x4c/0xb0 [drm_kms_helper] > > [ 246.768966] #3: 000000004c8f0b6b (crtc_ww_class_acquire){+.+.}, at: > > restore_fbdev_mode_atomic+0x4b/0x240 [drm_kms_helper] > > [ 246.769921] #4: 000000004c34a296 (crtc_ww_class_mutex){+.+.}, at: > > drm_modeset_backoff+0x8a/0x1b0 [drm] > > [ 246.770839] 1 lock held by dmesg/1038: > > [ 246.771739] 2 locks held by zsh/1172: > > [ 246.772650] #0: 00000000836d0438 (&tty->ldisc_sem){++++}, at: > > ldsem_down_read+0x37/0x40 > > [ 246.773680] #1: 000000001f4f4d48 (&ldata->atomic_read_lock){+.+.}, at: > > n_tty_read+0xc1/0x870 > > > > [ 246.775522] ============================================= > > > > So, to fix this (and any other possible deadlock issues like this that > > could occur in the output_poll_changed patch) we make sure that > > nouveau's output_poll_changed functions grab a runtime power ref before > > sending any hotplug events, and hold it until we're finished. We > > introduce this through adding a generic DRM helper which other drivers > > may reuse. > > > > This fixes deadlock issues when in fbcon with nouveau on my P50, and > > should fix it for everyone else's as well! > > > > Signed-off-by: Lyude Paul <lyude@redhat.com> > > Reviewed-by: Karol Herbst <karolherbst@gmail.com> > > Cc: Lukas Wunner <lukas@wunner.de> > > Cc: stable@vger.kernel.org > > --- > > Changes since v1: > > - Add a generic helper for DRM to handle this > > > > drivers/gpu/drm/drm_fb_helper.c | 23 +++++++++++++++++++++++ > > drivers/gpu/drm/nouveau/dispnv50/disp.c | 2 +- > > include/drm/drm_fb_helper.h | 5 +++++ > > 3 files changed, 29 insertions(+), 1 deletion(-) > > > > diff --git a/drivers/gpu/drm/drm_fb_helper.c > > b/drivers/gpu/drm/drm_fb_helper.c > > index 2ee1eaa66188..1ab2f3646526 100644 > > --- a/drivers/gpu/drm/drm_fb_helper.c > > +++ b/drivers/gpu/drm/drm_fb_helper.c > > @@ -34,6 +34,7 @@ > > #include <linux/sysrq.h> > > #include <linux/slab.h> > > #include <linux/module.h> > > +#include <linux/pm_runtime.h> > > #include <drm/drmP.h> > > #include <drm/drm_crtc.h> > > #include <drm/drm_fb_helper.h> > > @@ -2928,6 +2929,28 @@ void drm_fb_helper_output_poll_changed(struct > > drm_device *dev) > > } > > EXPORT_SYMBOL(drm_fb_helper_output_poll_changed); > > > > +/** > > + * drm_fb_helper_output_poll_changed_with_rpm - DRM mode > > + * config > > \.output_poll_changed > > + * helper for fbdev > > emulation > > + * @dev: DRM device > > + * > > + * Same as drm_fb_helper_output_poll_changed, except that it makes sure > > that > > + * the device is active by synchronously grabbing a runtime power > > reference > > + * while probing. > > + */ > > +void drm_fb_helper_output_poll_changed_with_rpm(struct drm_device *dev) > > +{ > > + int ret; > > + > > + ret = pm_runtime_get_sync(dev->dev); > > + if (WARN_ON(ret < 0 && ret != -EACCES)) > > + return; > > + drm_fb_helper_hotplug_event(dev->fb_helper); > > + pm_runtime_put(dev->dev); > > +} > > +EXPORT_SYMBOL(drm_fb_helper_output_poll_changed_with_rpm); > > + > > /* The Kconfig DRM_KMS_HELPER selects FRAMEBUFFER_CONSOLE (if !EXPERT) > > * but the module doesn't depend on any fb console symbols. At least > > * attempt to load fbcon to avoid leaving the system without a usable > > console. > > diff --git a/drivers/gpu/drm/nouveau/dispnv50/disp.c > > b/drivers/gpu/drm/nouveau/dispnv50/disp.c > > index eb3e41a78806..fa3ab618a0f9 100644 > > --- a/drivers/gpu/drm/nouveau/dispnv50/disp.c > > +++ b/drivers/gpu/drm/nouveau/dispnv50/disp.c > > @@ -2015,7 +2015,7 @@ nv50_disp_atomic_state_alloc(struct drm_device *dev) > > static const struct drm_mode_config_funcs > > nv50_disp_func = { > > .fb_create = nouveau_user_framebuffer_create, > > - .output_poll_changed = drm_fb_helper_output_poll_changed, > > + .output_poll_changed = > > drm_fb_helper_output_poll_changed_with_rpm, > > .atomic_check = nv50_disp_atomic_check, > > .atomic_commit = nv50_disp_atomic_commit, > > .atomic_state_alloc = nv50_disp_atomic_state_alloc, > > diff --git a/include/drm/drm_fb_helper.h b/include/drm/drm_fb_helper.h > > index b069433e7fc1..ca809bfbaebb 100644 > > --- a/include/drm/drm_fb_helper.h > > +++ b/include/drm/drm_fb_helper.h > > @@ -330,6 +330,7 @@ void drm_fb_helper_fbdev_teardown(struct drm_device > > *dev); > > > > void drm_fb_helper_lastclose(struct drm_device *dev); > > void drm_fb_helper_output_poll_changed(struct drm_device *dev); > > +void drm_fb_helper_output_poll_changed_with_rpm(struct drm_device *dev); > > #else > > static inline void drm_fb_helper_prepare(struct drm_device *dev, > > struct drm_fb_helper *helper, > > @@ -564,6 +565,10 @@ static inline void > > drm_fb_helper_output_poll_changed(struct drm_device *dev) > > { > > } > > > > +static inline void drm_fb_helper_output_poll_changed_with_rpm(struct > > drm_device *dev) > > +{ > > +} > > + > > #endif > > > > static inline int > > -- > > 2.17.1 > >
On Thu, 2018-07-19 at 20:08 -0400, Lyude Paul wrote: > [snip] > > > > Anything that happens in nouveau's poll worker never needs to acquire > > a runtime PM ref because polling is only enabled while runtime active, > > and ->runtime_suspend waits for an ongoing poll to finish. > > Hopefully I'm not missing anything here, but this doesn't really make any > sense. I'm not sure I explained myself as well as I thought I did. To be > honest, I had to double check this about literally 20 times to make sure I > was > actually understanding this issue correctly. Turns out I was missing a > couple > of parts, so I'm going to try again at explaining this using a diagram that > shows the various threads running concurrently > > START: Driver load > | > | > | Thread 1 > ----- output_poll_execute() > | > drm_helper_hpd_irq_event() > | > | Schedules → Thread 2 > ----------------- nouveau_display_hpd_work() > Finish | > pm_runtime_get_sync() <--- keeps > GPU alive > | > ... > | > ------------------------------ > <still Thread 2> > drm_helper_hpd_irq_event() > | > | Schedules → > ------------------------------ > | Thread 3 > Drop last RPM ref -v | output_poll_execute() > pm_runtime_put_sync() | ^^^^^^ As an additional note, I realized this might seem wrong but it isn't pm_runtime_put_sync() calls down to nouveau's runtime idle callback, which does this: static int nouveau_pmops_runtime_idle(struct device *dev) { if (!nouveau_pmops_runtime()) { pm_runtime_forbid(dev); return -EBUSY; } pm_runtime_mark_last_busy(dev); pm_runtime_autosuspend(dev); /* we don't want the main rpm_idle to call suspend - we want to autosuspend */ return 1; } So, it doesn't actually synchronously suspend the GPU, it just starts up the autosuspend thread Just wanted to make sure there wasn't any confusion :) > | drm_dp_mst_topology_mgr_set_mst() > Finish | > | > ← Schedules | > -----------------------------| > | | > Thread 4 | > | | > drm_dp_mst_link_probe_work() drm_dp_mst_wait_tx_reply() <-- these > wait on eachother > | | th > is is normal > | Sideband transactions | > | happen here, this is | > | where timeouts happen | > | | > | 5 seconds later... | autosuspend delay > kicks in > | ... | > | > | | Th > read 5 > | Communication + > timeouts | pm_runtime_work > | are still happening > here | | > | | nouveau_pmop > s_runtime_suspend() > | | > | > | Success! We can > enable | | > | displays > now! | drm_kms_helper_poll_disable() > | | > | > | *Atomic commit > begins* | > | | <---------- > --- | > | More sideband transactions | Waiting > on | > | ...... | output_poll_execute() > | > | | <---------- > --- | > | pm_runtime_get_sync() > | > | | > | > | --------------------> | ------------- > > | > | Waiting on | Waiting > on | > | output_poll_exec() | suspend > requests | > | --------------------> | ------------- > > | > | | > | > ----------------------------------------------------- > >| > DEA > DLOCK > > phew. that took a LONG time to come up with. > > Anyway-that's why your explanation doesn't make sense: the deadlock is > happening because we're calling pm_runtime_get_sync(). If we were to make > that > call conditional (e.g. drm_kms_helper_is_poll_worker()), all that would mean > is that we wouldn't grab any runtime power reference and the GPU would > immediately suspend once the atomic commit finished, as the suspend request > in > Thread 5 would finally get unblocked and thus----suspend. > > Hopefully I explained that better this time, I'll definitely make sure to > actually include that diagram in the patch. As for whether or not this patch > is even the right solution, I will need to confirm that tommorrow (if you > don't think it is still, please feel free to say so!) because it's getting > late here. > > Cheers! > Lyude > > > > > Thinking a bit more about this, our mistake is to acquire runtime PM > > refs too far down in the call stack. As a fix that can be backported > > to stable, adding if (!drm_kms_helper_is_poll_worker()) conditionals > > seems fine to me, but the long term fix is to push acquisition of refs > > further up in the call stack. > > > > E.g., if the user forces connector probing via sysfs, a runtime PM ref > > should be acquired in status_store() in drm_sysfs.c before invoking > > connector->funcs->fill_modes(). That way, if the user forces connector > > probing while the GPU is powering down, rpm_resume() will correctly wait > > for rpm_suspend() to finish before resuming the card. So if we architect > > it like this, we're actually using the functionality provided by the > > PM core in the way that it's supposed to be used. > > > > The problem is that adding pm_runtime_get_sync() to status_store() > > conflicts with the desire to have a library of generic DRM functions: > > Some GPUs may be able to probe connectors without resuming to runtime > > active state, others don't use runtime PM at all. One solution that > > comes to mind is a driver_features flag which tells the DRM core whether > > to acquire a runtime PM ref in various places. > > > > In your original patches 4 and 5, what exactly was the call stack which > > led to i2c being accessed while runtime suspended? Was it sysfs access > > via /sys/class/i2c-adapter/* ? If so, acquisition of the runtime PM ref > > needs to likewise happen in that sysfs entry point, rather than deep down > > in the call stack upon accessing the i2c bus. > > > > Thanks, > > > > Lukas > > > > > > > > Sample: > > > [ 246.669625] INFO: task kworker/4:0:37 blocked for more than 120 > > > seconds. > > > [ 246.673398] Not tainted 4.18.0-rc5Lyude-Test+ #2 > > > [ 246.675271] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" > > > disables > > > this message. > > > [ 246.676527] kworker/4:0 D 0 37 2 0x80000000 > > > [ 246.677580] Workqueue: events output_poll_execute [drm_kms_helper] > > > [ 246.678704] Call Trace: > > > [ 246.679753] __schedule+0x322/0xaf0 > > > [ 246.680916] schedule+0x33/0x90 > > > [ 246.681924] schedule_preempt_disabled+0x15/0x20 > > > [ 246.683023] __mutex_lock+0x569/0x9a0 > > > [ 246.684035] ? kobject_uevent_env+0x117/0x7b0 > > > [ 246.685132] ? drm_fb_helper_hotplug_event.part.28+0x20/0xb0 > > > [drm_kms_helper] > > > [ 246.686179] mutex_lock_nested+0x1b/0x20 > > > [ 246.687278] ? mutex_lock_nested+0x1b/0x20 > > > [ 246.688307] drm_fb_helper_hotplug_event.part.28+0x20/0xb0 > > > [drm_kms_helper] > > > [ 246.689420] drm_fb_helper_output_poll_changed+0x23/0x30 > > > [drm_kms_helper] > > > [ 246.690462] drm_kms_helper_hotplug_event+0x2a/0x30 [drm_kms_helper] > > > [ 246.691570] output_poll_execute+0x198/0x1c0 [drm_kms_helper] > > > [ 246.692611] process_one_work+0x231/0x620 > > > [ 246.693725] worker_thread+0x214/0x3a0 > > > [ 246.694756] kthread+0x12b/0x150 > > > [ 246.695856] ? wq_pool_ids_show+0x140/0x140 > > > [ 246.696888] ? kthread_create_worker_on_cpu+0x70/0x70 > > > [ 246.697998] ret_from_fork+0x3a/0x50 > > > [ 246.699034] INFO: task kworker/0:1:60 blocked for more than 120 > > > seconds. > > > [ 246.700153] Not tainted 4.18.0-rc5Lyude-Test+ #2 > > > [ 246.701182] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" > > > disables > > > this message. > > > [ 246.702278] kworker/0:1 D 0 60 2 0x80000000 > > > [ 246.703293] Workqueue: pm pm_runtime_work > > > [ 246.704393] Call Trace: > > > [ 246.705403] __schedule+0x322/0xaf0 > > > [ 246.706439] ? wait_for_completion+0x104/0x190 > > > [ 246.707393] schedule+0x33/0x90 > > > [ 246.708375] schedule_timeout+0x3a5/0x590 > > > [ 246.709289] ? mark_held_locks+0x58/0x80 > > > [ 246.710208] ? _raw_spin_unlock_irq+0x2c/0x40 > > > [ 246.711222] ? wait_for_completion+0x104/0x190 > > > [ 246.712134] ? trace_hardirqs_on_caller+0xf4/0x190 > > > [ 246.713094] ? wait_for_completion+0x104/0x190 > > > [ 246.713964] wait_for_completion+0x12c/0x190 > > > [ 246.714895] ? wake_up_q+0x80/0x80 > > > [ 246.715727] ? get_work_pool+0x90/0x90 > > > [ 246.716649] flush_work+0x1c9/0x280 > > > [ 246.717483] ? flush_workqueue_prep_pwqs+0x1b0/0x1b0 > > > [ 246.718442] __cancel_work_timer+0x146/0x1d0 > > > [ 246.719247] cancel_delayed_work_sync+0x13/0x20 > > > [ 246.720043] drm_kms_helper_poll_disable+0x1f/0x30 [drm_kms_helper] > > > [ 246.721123] nouveau_pmops_runtime_suspend+0x3d/0xb0 [nouveau] > > > [ 246.721897] pci_pm_runtime_suspend+0x6b/0x190 > > > [ 246.722825] ? pci_has_legacy_pm_support+0x70/0x70 > > > [ 246.723737] __rpm_callback+0x7a/0x1d0 > > > [ 246.724721] ? pci_has_legacy_pm_support+0x70/0x70 > > > [ 246.725607] rpm_callback+0x24/0x80 > > > [ 246.726553] ? pci_has_legacy_pm_support+0x70/0x70 > > > [ 246.727376] rpm_suspend+0x142/0x6b0 > > > [ 246.728185] pm_runtime_work+0x97/0xc0 > > > [ 246.728938] process_one_work+0x231/0x620 > > > [ 246.729796] worker_thread+0x44/0x3a0 > > > [ 246.730614] kthread+0x12b/0x150 > > > [ 246.731395] ? wq_pool_ids_show+0x140/0x140 > > > [ 246.732202] ? kthread_create_worker_on_cpu+0x70/0x70 > > > [ 246.732878] ret_from_fork+0x3a/0x50 > > > [ 246.733768] INFO: task kworker/4:2:422 blocked for more than 120 > > > seconds. > > > [ 246.734587] Not tainted 4.18.0-rc5Lyude-Test+ #2 > > > [ 246.735393] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" > > > disables > > > this message. > > > [ 246.736113] kworker/4:2 D 0 422 2 0x80000080 > > > [ 246.736789] Workqueue: events_long drm_dp_mst_link_probe_work > > > [drm_kms_helper] > > > [ 246.737665] Call Trace: > > > [ 246.738490] __schedule+0x322/0xaf0 > > > [ 246.739250] schedule+0x33/0x90 > > > [ 246.739908] rpm_resume+0x19c/0x850 > > > [ 246.740750] ? finish_wait+0x90/0x90 > > > [ 246.741541] __pm_runtime_resume+0x4e/0x90 > > > [ 246.742370] nv50_disp_atomic_commit+0x31/0x210 [nouveau] > > > [ 246.743124] drm_atomic_commit+0x4a/0x50 [drm] > > > [ 246.743775] restore_fbdev_mode_atomic+0x1c8/0x240 [drm_kms_helper] > > > [ 246.744603] restore_fbdev_mode+0x31/0x140 [drm_kms_helper] > > > [ 246.745373] drm_fb_helper_restore_fbdev_mode_unlocked+0x54/0xb0 > > > [drm_kms_helper] > > > [ 246.746220] drm_fb_helper_set_par+0x2d/0x50 [drm_kms_helper] > > > [ 246.746884] drm_fb_helper_hotplug_event.part.28+0x96/0xb0 > > > [drm_kms_helper] > > > [ 246.747675] drm_fb_helper_output_poll_changed+0x23/0x30 > > > [drm_kms_helper] > > > [ 246.748544] drm_kms_helper_hotplug_event+0x2a/0x30 [drm_kms_helper] > > > [ 246.749439] nv50_mstm_hotplug+0x15/0x20 [nouveau] > > > [ 246.750111] drm_dp_send_link_address+0x177/0x1c0 [drm_kms_helper] > > > [ 246.750764] drm_dp_check_and_send_link_address+0xa8/0xd0 > > > [drm_kms_helper] > > > [ 246.751602] drm_dp_mst_link_probe_work+0x51/0x90 [drm_kms_helper] > > > [ 246.752314] process_one_work+0x231/0x620 > > > [ 246.752979] worker_thread+0x44/0x3a0 > > > [ 246.753838] kthread+0x12b/0x150 > > > [ 246.754619] ? wq_pool_ids_show+0x140/0x140 > > > [ 246.755386] ? kthread_create_worker_on_cpu+0x70/0x70 > > > [ 246.756162] ret_from_fork+0x3a/0x50 > > > [ 246.756847] > > > Showing all locks held in the system: > > > [ 246.758261] 3 locks held by kworker/4:0/37: > > > [ 246.759016] #0: 00000000f8df4d2d ((wq_completion)"events"){+.+.}, > > > at: > > > process_one_work+0x1b3/0x620 > > > [ 246.759856] #1: 00000000e6065461 ((work_completion)(&(&dev- > > > > mode_config.output_poll_work)->work)){+.+.}, at: > > > > > > process_one_work+0x1b3/0x620 > > > [ 246.760670] #2: 00000000cb66735f (&helper->lock){+.+.}, at: > > > drm_fb_helper_hotplug_event.part.28+0x20/0xb0 [drm_kms_helper] > > > [ 246.761516] 2 locks held by kworker/0:1/60: > > > [ 246.762274] #0: 00000000fff6be0f ((wq_completion)"pm"){+.+.}, at: > > > process_one_work+0x1b3/0x620 > > > [ 246.762982] #1: 000000005ab44fb4 ((work_completion)(&dev- > > > > power.work)){+.+.}, at: process_one_work+0x1b3/0x620 > > > > > > [ 246.763890] 1 lock held by khungtaskd/64: > > > [ 246.764664] #0: 000000008cb8b5c3 (rcu_read_lock){....}, at: > > > debug_show_all_locks+0x23/0x185 > > > [ 246.765588] 5 locks held by kworker/4:2/422: > > > [ 246.766440] #0: 00000000232f0959 > > > ((wq_completion)"events_long"){+.+.}, > > > at: process_one_work+0x1b3/0x620 > > > [ 246.767390] #1: 00000000bb59b134 ((work_completion)(&mgr- > > > > work)){+.+.}, at: process_one_work+0x1b3/0x620 > > > > > > [ 246.768154] #2: 00000000cb66735f (&helper->lock){+.+.}, at: > > > drm_fb_helper_restore_fbdev_mode_unlocked+0x4c/0xb0 [drm_kms_helper] > > > [ 246.768966] #3: 000000004c8f0b6b (crtc_ww_class_acquire){+.+.}, at: > > > restore_fbdev_mode_atomic+0x4b/0x240 [drm_kms_helper] > > > [ 246.769921] #4: 000000004c34a296 (crtc_ww_class_mutex){+.+.}, at: > > > drm_modeset_backoff+0x8a/0x1b0 [drm] > > > [ 246.770839] 1 lock held by dmesg/1038: > > > [ 246.771739] 2 locks held by zsh/1172: > > > [ 246.772650] #0: 00000000836d0438 (&tty->ldisc_sem){++++}, at: > > > ldsem_down_read+0x37/0x40 > > > [ 246.773680] #1: 000000001f4f4d48 (&ldata->atomic_read_lock){+.+.}, > > > at: > > > n_tty_read+0xc1/0x870 > > > > > > [ 246.775522] ============================================= > > > > > > So, to fix this (and any other possible deadlock issues like this that > > > could occur in the output_poll_changed patch) we make sure that > > > nouveau's output_poll_changed functions grab a runtime power ref before > > > sending any hotplug events, and hold it until we're finished. We > > > introduce this through adding a generic DRM helper which other drivers > > > may reuse. > > > > > > This fixes deadlock issues when in fbcon with nouveau on my P50, and > > > should fix it for everyone else's as well! > > > > > > Signed-off-by: Lyude Paul <lyude@redhat.com> > > > Reviewed-by: Karol Herbst <karolherbst@gmail.com> > > > Cc: Lukas Wunner <lukas@wunner.de> > > > Cc: stable@vger.kernel.org > > > --- > > > Changes since v1: > > > - Add a generic helper for DRM to handle this > > > > > > drivers/gpu/drm/drm_fb_helper.c | 23 +++++++++++++++++++++++ > > > drivers/gpu/drm/nouveau/dispnv50/disp.c | 2 +- > > > include/drm/drm_fb_helper.h | 5 +++++ > > > 3 files changed, 29 insertions(+), 1 deletion(-) > > > > > > diff --git a/drivers/gpu/drm/drm_fb_helper.c > > > b/drivers/gpu/drm/drm_fb_helper.c > > > index 2ee1eaa66188..1ab2f3646526 100644 > > > --- a/drivers/gpu/drm/drm_fb_helper.c > > > +++ b/drivers/gpu/drm/drm_fb_helper.c > > > @@ -34,6 +34,7 @@ > > > #include <linux/sysrq.h> > > > #include <linux/slab.h> > > > #include <linux/module.h> > > > +#include <linux/pm_runtime.h> > > > #include <drm/drmP.h> > > > #include <drm/drm_crtc.h> > > > #include <drm/drm_fb_helper.h> > > > @@ -2928,6 +2929,28 @@ void drm_fb_helper_output_poll_changed(struct > > > drm_device *dev) > > > } > > > EXPORT_SYMBOL(drm_fb_helper_output_poll_changed); > > > > > > +/** > > > + * drm_fb_helper_output_poll_changed_with_rpm - DRM mode > > > + * config > > > \.output_poll_changed > > > + * helper for fbdev > > > emulation > > > + * @dev: DRM device > > > + * > > > + * Same as drm_fb_helper_output_poll_changed, except that it makes sure > > > that > > > + * the device is active by synchronously grabbing a runtime power > > > reference > > > + * while probing. > > > + */ > > > +void drm_fb_helper_output_poll_changed_with_rpm(struct drm_device *dev) > > > +{ > > > + int ret; > > > + > > > + ret = pm_runtime_get_sync(dev->dev); > > > + if (WARN_ON(ret < 0 && ret != -EACCES)) > > > + return; > > > + drm_fb_helper_hotplug_event(dev->fb_helper); > > > + pm_runtime_put(dev->dev); > > > +} > > > +EXPORT_SYMBOL(drm_fb_helper_output_poll_changed_with_rpm); > > > + > > > /* The Kconfig DRM_KMS_HELPER selects FRAMEBUFFER_CONSOLE (if !EXPERT) > > > * but the module doesn't depend on any fb console symbols. At least > > > * attempt to load fbcon to avoid leaving the system without a usable > > > console. > > > diff --git a/drivers/gpu/drm/nouveau/dispnv50/disp.c > > > b/drivers/gpu/drm/nouveau/dispnv50/disp.c > > > index eb3e41a78806..fa3ab618a0f9 100644 > > > --- a/drivers/gpu/drm/nouveau/dispnv50/disp.c > > > +++ b/drivers/gpu/drm/nouveau/dispnv50/disp.c > > > @@ -2015,7 +2015,7 @@ nv50_disp_atomic_state_alloc(struct drm_device > > > *dev) > > > static const struct drm_mode_config_funcs > > > nv50_disp_func = { > > > .fb_create = nouveau_user_framebuffer_create, > > > - .output_poll_changed = drm_fb_helper_output_poll_changed, > > > + .output_poll_changed = > > > drm_fb_helper_output_poll_changed_with_rpm, > > > .atomic_check = nv50_disp_atomic_check, > > > .atomic_commit = nv50_disp_atomic_commit, > > > .atomic_state_alloc = nv50_disp_atomic_state_alloc, > > > diff --git a/include/drm/drm_fb_helper.h b/include/drm/drm_fb_helper.h > > > index b069433e7fc1..ca809bfbaebb 100644 > > > --- a/include/drm/drm_fb_helper.h > > > +++ b/include/drm/drm_fb_helper.h > > > @@ -330,6 +330,7 @@ void drm_fb_helper_fbdev_teardown(struct drm_device > > > *dev); > > > > > > void drm_fb_helper_lastclose(struct drm_device *dev); > > > void drm_fb_helper_output_poll_changed(struct drm_device *dev); > > > +void drm_fb_helper_output_poll_changed_with_rpm(struct drm_device > > > *dev); > > > #else > > > static inline void drm_fb_helper_prepare(struct drm_device *dev, > > > struct drm_fb_helper *helper, > > > @@ -564,6 +565,10 @@ static inline void > > > drm_fb_helper_output_poll_changed(struct drm_device *dev) > > > { > > > } > > > > > > +static inline void drm_fb_helper_output_poll_changed_with_rpm(struct > > > drm_device *dev) > > > +{ > > > +} > > > + > > > #endif > > > > > > static inline int > > > -- > > > 2.17.1 > > >
On Thu, Jul 19, 2018 at 08:08:15PM -0400, Lyude Paul wrote: > On Thu, 2018-07-19 at 09:49 +0200, Lukas Wunner wrote: > > On Wed, Jul 18, 2018 at 04:56:39PM -0400, Lyude Paul wrote: > > > When DP MST hubs get confused, they can occasionally stop responding for > > > a good bit of time up until the point where the DRM driver manages to > > > do the right DPCD accesses to get it to start responding again. In a > > > worst case scenario however, this process can take upwards of 10+ > > > seconds. > > > > > > Currently we use the default output_poll_changed handler > > > drm_fb_helper_output_poll_changed() to handle output polling, which > > > doesn't happen to grab any power references on the device when polling. > > > If we're unlucky enough to have a hub (such as Lenovo's infamous laptop > > > docks for the P5x/P7x series) that's easily startled and confused, this > > > can lead to a pretty nasty deadlock situation that looks like this: > > > > > > - Hotplug event from hub happens, we enter > > > drm_fb_helper_output_poll_changed() and start communicating with the > > > hub > > > - While we're in drm_fb_helper_output_poll_changed() and attempting to > > > communicate with the hub, we end up confusing it and cause it to stop > > > responding for at least 10 seconds > > > - After 5 seconds of being in drm_fb_helper_output_poll_changed(), the > > > pm core attempts to put the GPU into autosuspend, which ends up > > > calling drm_kms_helper_poll_disable() > > > - While the runtime PM core is waiting in drm_kms_helper_poll_disable() > > > for the output poll to finish, we end up finally detecting an MST > > > display > > > - We notice the new display and tries to enable it, which triggers > > > an atomic commit which triggers a call to pm_runtime_get_sync() > > > - the output poll thread deadlocks the pm core waiting for the pm core > > > to finish the autosuspend request while the pm core waits for the > > > output poll thread to finish > > > > The correct fix is to call pm_runtime_get_sync() *conditionally* in > > the atomic commit which enables the display, using the same conditional > > as d61a5c106351, i.e. if (!drm_kms_helper_is_poll_worker()). First of all, I was mistaken when I wrote above that a check for !drm_kms_helper_is_poll_worker() would solve the problem. Sorry! It doesn't because the call to pm_runtime_get_sync() is not happening in output_poll_execute() but in drm_dp_mst_link_probe_work(). Looking once more at the three stack traces you've provided, we've got: - output_poll_execute() stuck waiting for fb_helper->lock which is held by drm_dp_mst_link_probe_work() - rpm_suspend() stuck waiting for output_poll_execute() to finish - drm_dp_mst_link_probe_work() stuck waiting in rpm_resume() For the moment we can ignore the first task, i.e. output_poll_execute(), and focus on the latter two. As said I'm unfamiliar with MST but browsing through drm_dp_mst_topology.c I notice that drm_dp_mst_link_probe_work() is the ->work element in drm_dp_mst_topology_mgr() and is queued on HPD. I further notice that the work item is flushed on ->runtime_suspend: nouveau_pmops_runtime_suspend() nouveau_do_suspend() nouveau_display_suspend() nouveau_display_fini() disp->fini() == nv50_display_fini() nv50_mstm_fini() drm_dp_mst_topology_mgr_suspend() flush_work(&mgr->work); And before the work item is flushed, the HPD source is quiesced. So it looks like drm_dp_mst_link_probe_work() can only ever run while the GPU is runtime resumed, it never runs while the GPU is runtime suspended. This means that you don't have to acquire any runtime PM references in or below drm_dp_mst_link_probe_work(). Au contraire, you must not acquire any because it will deadlock while the GPU is runtime suspending. If there are functions which are called from drm_dp_mst_link_probe_work() as well as from other contexts, and those other contexts need a runtime PM ref to be acquired, you need to acquire the runtime PM ref conditionally on not being drm_dp_mst_link_probe_work() (using the current_work() technique). Alternatively, move acquisition of the runtime PM ref further up in the call chain to those other contexts. > Anyway-that's why your explanation doesn't make sense: the deadlock is > happening because we're calling pm_runtime_get_sync(). If we were to > make that call conditional (e.g. drm_kms_helper_is_poll_worker()), > all that would mean is that we wouldn't grab any runtime power reference > and the GPU would immediately suspend once the atomic commit finished, > as the suspend request in Thread 5 would finally get unblocked and thus > ----suspend. Right, that seems to be a bug nouveau_pmops_runtime_suspend(): If a display is plugged in while the GPU is about to runtime suspend, the display may be lit up by output_poll_execute() but the GPU will then nevertheless be powered off. I guess after calling drm_kms_helper_poll_disable() we should re-check if a crtc has been activated. This should have bumped the runtime PM refcount and have_disp_power_ref should be true. In that case, the nouveau_pmops_runtime_suspend() should return -EBUSY to abort the runtime_suspend. The same check seems necessary after flushing drm_dp_mst_link_probe_work(): If the work item lit up a new display, all previous suspend steps need to be unwound and -EBUSY needs to be returned to the PM core. Communication with an MST hub exceeding the autosuspend timeout is just one scenario where this bug manifests itself. BTW, drm_kms_helper_poll_disable() seems to be called twice in the runtime_suspend code path, once in nouveau_pmops_runtime_suspend() and a second time in nouveau_display_fini(). A stupid question, I notice that nv50_display_fini() calls nv50_mstm_fini() only if encoder_type != DRM_MODE_ENCODER_DPMST. Why isn't that == ? Thanks, Lukas
On Sat, 2018-07-21 at 11:39 +0200, Lukas Wunner wrote: > On Thu, Jul 19, 2018 at 08:08:15PM -0400, Lyude Paul wrote: > > On Thu, 2018-07-19 at 09:49 +0200, Lukas Wunner wrote: > > > On Wed, Jul 18, 2018 at 04:56:39PM -0400, Lyude Paul wrote: > > > > When DP MST hubs get confused, they can occasionally stop responding > > > > for > > > > a good bit of time up until the point where the DRM driver manages to > > > > do the right DPCD accesses to get it to start responding again. In a > > > > worst case scenario however, this process can take upwards of 10+ > > > > seconds. > > > > > > > > Currently we use the default output_poll_changed handler > > > > drm_fb_helper_output_poll_changed() to handle output polling, which > > > > doesn't happen to grab any power references on the device when > > > > polling. > > > > If we're unlucky enough to have a hub (such as Lenovo's infamous > > > > laptop > > > > docks for the P5x/P7x series) that's easily startled and confused, > > > > this > > > > can lead to a pretty nasty deadlock situation that looks like this: > > > > > > > > - Hotplug event from hub happens, we enter > > > > drm_fb_helper_output_poll_changed() and start communicating with the > > > > hub > > > > - While we're in drm_fb_helper_output_poll_changed() and attempting to > > > > communicate with the hub, we end up confusing it and cause it to > > > > stop > > > > responding for at least 10 seconds > > > > - After 5 seconds of being in drm_fb_helper_output_poll_changed(), the > > > > pm core attempts to put the GPU into autosuspend, which ends up > > > > calling drm_kms_helper_poll_disable() > > > > - While the runtime PM core is waiting in > > > > drm_kms_helper_poll_disable() > > > > for the output poll to finish, we end up finally detecting an MST > > > > display > > > > - We notice the new display and tries to enable it, which triggers > > > > an atomic commit which triggers a call to pm_runtime_get_sync() > > > > - the output poll thread deadlocks the pm core waiting for the pm core > > > > to finish the autosuspend request while the pm core waits for the > > > > output poll thread to finish > > > > > > The correct fix is to call pm_runtime_get_sync() *conditionally* in > > > the atomic commit which enables the display, using the same conditional > > > as d61a5c106351, i.e. if (!drm_kms_helper_is_poll_worker()). > > First of all, I was mistaken when I wrote above that a check for > !drm_kms_helper_is_poll_worker() would solve the problem. Sorry! > It doesn't because the call to pm_runtime_get_sync() is not happening > in output_poll_execute() but in drm_dp_mst_link_probe_work(). > > Looking once more at the three stack traces you've provided, we've got: > - output_poll_execute() stuck waiting for fb_helper->lock > which is held by drm_dp_mst_link_probe_work() > - rpm_suspend() stuck waiting for output_poll_execute() to finish > - drm_dp_mst_link_probe_work() stuck waiting in rpm_resume() > > For the moment we can ignore the first task, i.e. output_poll_execute(), > and focus on the latter two. > > As said I'm unfamiliar with MST but browsing through drm_dp_mst_topology.c > I notice that drm_dp_mst_link_probe_work() is the ->work element in > drm_dp_mst_topology_mgr() and is queued on HPD. I further notice that > the work item is flushed on ->runtime_suspend: > > nouveau_pmops_runtime_suspend() > nouveau_do_suspend() > nouveau_display_suspend() > nouveau_display_fini() > disp->fini() == nv50_display_fini() > nv50_mstm_fini() > drm_dp_mst_topology_mgr_suspend() > flush_work(&mgr->work); > > And before the work item is flushed, the HPD source is quiesced. > > So it looks like drm_dp_mst_link_probe_work() can only ever run > while the GPU is runtime resumed, it never runs while the GPU is > runtime suspended. This means that you don't have to acquire any > runtime PM references in or below drm_dp_mst_link_probe_work(). > Au contraire, you must not acquire any because it will deadlock while > the GPU is runtime suspending. If there are functions which are > called from drm_dp_mst_link_probe_work() as well as from other contexts, > and those other contexts need a runtime PM ref to be acquired, > you need to acquire the runtime PM ref conditionally on not being > drm_dp_mst_link_probe_work() (using the current_work() technique). > > Alternatively, move acquisition of the runtime PM ref further up in > the call chain to those other contexts. > > > > Anyway-that's why your explanation doesn't make sense: the deadlock is > > happening because we're calling pm_runtime_get_sync(). If we were to > > make that call conditional (e.g. drm_kms_helper_is_poll_worker()), > > all that would mean is that we wouldn't grab any runtime power reference > > and the GPU would immediately suspend once the atomic commit finished, > > as the suspend request in Thread 5 would finally get unblocked and thus > > ----suspend. > > Right, that seems to be a bug nouveau_pmops_runtime_suspend(): > > If a display is plugged in while the GPU is about to runtime suspend, > the display may be lit up by output_poll_execute() but the GPU will > then nevertheless be powered off. > > I guess after calling drm_kms_helper_poll_disable() we should re-check > if a crtc has been activated. This should have bumped the runtime PM > refcount and have_disp_power_ref should be true. In that case, the > nouveau_pmops_runtime_suspend() should return -EBUSY to abort the > runtime_suspend. > > The same check seems necessary after flushing drm_dp_mst_link_probe_work(): > If the work item lit up a new display, all previous suspend steps need > to be unwound and -EBUSY needs to be returned to the PM core. > > Communication with an MST hub exceeding the autosuspend timeout is > just one scenario where this bug manifests itself. > > BTW, drm_kms_helper_poll_disable() seems to be called twice in the > runtime_suspend code path, once in nouveau_pmops_runtime_suspend() > and a second time in nouveau_display_fini(). > > A stupid question, I notice that nv50_display_fini() calls nv50_mstm_fini() > only if encoder_type != DRM_MODE_ENCODER_DPMST. Why isn't that == ? Because there's a difference between DPMST connectors and encoders vs. the rest of the device's encoders. Every DP MST topology will take up a single "physical" DP connector on the device that will be marked as disconnected. This connector also owns the "mstm" (MST manager, referred to as the drm_dp_mst_topology_mgr in DRM), which through the callbacks nouveau provides is responsible for creating the fake DP MST ports and encoders. All of these fake ports will have DPMST encoders as opposed to the physical DP ports, which will have TMDS encoders. Hence-mstms are only on physical connectors with TMDS, not fake connectors with DPMST. > > Thanks, > > Lukas
diff --git a/drivers/gpu/drm/drm_fb_helper.c b/drivers/gpu/drm/drm_fb_helper.c index 2ee1eaa66188..1ab2f3646526 100644 --- a/drivers/gpu/drm/drm_fb_helper.c +++ b/drivers/gpu/drm/drm_fb_helper.c @@ -34,6 +34,7 @@ #include <linux/sysrq.h> #include <linux/slab.h> #include <linux/module.h> +#include <linux/pm_runtime.h> #include <drm/drmP.h> #include <drm/drm_crtc.h> #include <drm/drm_fb_helper.h> @@ -2928,6 +2929,28 @@ void drm_fb_helper_output_poll_changed(struct drm_device *dev) } EXPORT_SYMBOL(drm_fb_helper_output_poll_changed); +/** + * drm_fb_helper_output_poll_changed_with_rpm - DRM mode + * config \.output_poll_changed + * helper for fbdev emulation + * @dev: DRM device + * + * Same as drm_fb_helper_output_poll_changed, except that it makes sure that + * the device is active by synchronously grabbing a runtime power reference + * while probing. + */ +void drm_fb_helper_output_poll_changed_with_rpm(struct drm_device *dev) +{ + int ret; + + ret = pm_runtime_get_sync(dev->dev); + if (WARN_ON(ret < 0 && ret != -EACCES)) + return; + drm_fb_helper_hotplug_event(dev->fb_helper); + pm_runtime_put(dev->dev); +} +EXPORT_SYMBOL(drm_fb_helper_output_poll_changed_with_rpm); + /* The Kconfig DRM_KMS_HELPER selects FRAMEBUFFER_CONSOLE (if !EXPERT) * but the module doesn't depend on any fb console symbols. At least * attempt to load fbcon to avoid leaving the system without a usable console. diff --git a/drivers/gpu/drm/nouveau/dispnv50/disp.c b/drivers/gpu/drm/nouveau/dispnv50/disp.c index eb3e41a78806..fa3ab618a0f9 100644 --- a/drivers/gpu/drm/nouveau/dispnv50/disp.c +++ b/drivers/gpu/drm/nouveau/dispnv50/disp.c @@ -2015,7 +2015,7 @@ nv50_disp_atomic_state_alloc(struct drm_device *dev) static const struct drm_mode_config_funcs nv50_disp_func = { .fb_create = nouveau_user_framebuffer_create, - .output_poll_changed = drm_fb_helper_output_poll_changed, + .output_poll_changed = drm_fb_helper_output_poll_changed_with_rpm, .atomic_check = nv50_disp_atomic_check, .atomic_commit = nv50_disp_atomic_commit, .atomic_state_alloc = nv50_disp_atomic_state_alloc, diff --git a/include/drm/drm_fb_helper.h b/include/drm/drm_fb_helper.h index b069433e7fc1..ca809bfbaebb 100644 --- a/include/drm/drm_fb_helper.h +++ b/include/drm/drm_fb_helper.h @@ -330,6 +330,7 @@ void drm_fb_helper_fbdev_teardown(struct drm_device *dev); void drm_fb_helper_lastclose(struct drm_device *dev); void drm_fb_helper_output_poll_changed(struct drm_device *dev); +void drm_fb_helper_output_poll_changed_with_rpm(struct drm_device *dev); #else static inline void drm_fb_helper_prepare(struct drm_device *dev, struct drm_fb_helper *helper, @@ -564,6 +565,10 @@ static inline void drm_fb_helper_output_poll_changed(struct drm_device *dev) { } +static inline void drm_fb_helper_output_poll_changed_with_rpm(struct drm_device *dev) +{ +} + #endif static inline int
When DP MST hubs get confused, they can occasionally stop responding for a good bit of time up until the point where the DRM driver manages to do the right DPCD accesses to get it to start responding again. In a worst case scenario however, this process can take upwards of 10+ seconds. Currently we use the default output_poll_changed handler drm_fb_helper_output_poll_changed() to handle output polling, which doesn't happen to grab any power references on the device when polling. If we're unlucky enough to have a hub (such as Lenovo's infamous laptop docks for the P5x/P7x series) that's easily startled and confused, this can lead to a pretty nasty deadlock situation that looks like this: - Hotplug event from hub happens, we enter drm_fb_helper_output_poll_changed() and start communicating with the hub - While we're in drm_fb_helper_output_poll_changed() and attempting to communicate with the hub, we end up confusing it and cause it to stop responding for at least 10 seconds - After 5 seconds of being in drm_fb_helper_output_poll_changed(), the pm core attempts to put the GPU into autosuspend, which ends up calling drm_kms_helper_poll_disable() - While the runtime PM core is waiting in drm_kms_helper_poll_disable() for the output poll to finish, we end up finally detecting an MST display - We notice the new display and tries to enable it, which triggers an atomic commit which triggers a call to pm_runtime_get_sync() - the output poll thread deadlocks the pm core waiting for the pm core to finish the autosuspend request while the pm core waits for the output poll thread to finish Sample: [ 246.669625] INFO: task kworker/4:0:37 blocked for more than 120 seconds. [ 246.673398] Not tainted 4.18.0-rc5Lyude-Test+ #2 [ 246.675271] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 246.676527] kworker/4:0 D 0 37 2 0x80000000 [ 246.677580] Workqueue: events output_poll_execute [drm_kms_helper] [ 246.678704] Call Trace: [ 246.679753] __schedule+0x322/0xaf0 [ 246.680916] schedule+0x33/0x90 [ 246.681924] schedule_preempt_disabled+0x15/0x20 [ 246.683023] __mutex_lock+0x569/0x9a0 [ 246.684035] ? kobject_uevent_env+0x117/0x7b0 [ 246.685132] ? drm_fb_helper_hotplug_event.part.28+0x20/0xb0 [drm_kms_helper] [ 246.686179] mutex_lock_nested+0x1b/0x20 [ 246.687278] ? mutex_lock_nested+0x1b/0x20 [ 246.688307] drm_fb_helper_hotplug_event.part.28+0x20/0xb0 [drm_kms_helper] [ 246.689420] drm_fb_helper_output_poll_changed+0x23/0x30 [drm_kms_helper] [ 246.690462] drm_kms_helper_hotplug_event+0x2a/0x30 [drm_kms_helper] [ 246.691570] output_poll_execute+0x198/0x1c0 [drm_kms_helper] [ 246.692611] process_one_work+0x231/0x620 [ 246.693725] worker_thread+0x214/0x3a0 [ 246.694756] kthread+0x12b/0x150 [ 246.695856] ? wq_pool_ids_show+0x140/0x140 [ 246.696888] ? kthread_create_worker_on_cpu+0x70/0x70 [ 246.697998] ret_from_fork+0x3a/0x50 [ 246.699034] INFO: task kworker/0:1:60 blocked for more than 120 seconds. [ 246.700153] Not tainted 4.18.0-rc5Lyude-Test+ #2 [ 246.701182] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 246.702278] kworker/0:1 D 0 60 2 0x80000000 [ 246.703293] Workqueue: pm pm_runtime_work [ 246.704393] Call Trace: [ 246.705403] __schedule+0x322/0xaf0 [ 246.706439] ? wait_for_completion+0x104/0x190 [ 246.707393] schedule+0x33/0x90 [ 246.708375] schedule_timeout+0x3a5/0x590 [ 246.709289] ? mark_held_locks+0x58/0x80 [ 246.710208] ? _raw_spin_unlock_irq+0x2c/0x40 [ 246.711222] ? wait_for_completion+0x104/0x190 [ 246.712134] ? trace_hardirqs_on_caller+0xf4/0x190 [ 246.713094] ? wait_for_completion+0x104/0x190 [ 246.713964] wait_for_completion+0x12c/0x190 [ 246.714895] ? wake_up_q+0x80/0x80 [ 246.715727] ? get_work_pool+0x90/0x90 [ 246.716649] flush_work+0x1c9/0x280 [ 246.717483] ? flush_workqueue_prep_pwqs+0x1b0/0x1b0 [ 246.718442] __cancel_work_timer+0x146/0x1d0 [ 246.719247] cancel_delayed_work_sync+0x13/0x20 [ 246.720043] drm_kms_helper_poll_disable+0x1f/0x30 [drm_kms_helper] [ 246.721123] nouveau_pmops_runtime_suspend+0x3d/0xb0 [nouveau] [ 246.721897] pci_pm_runtime_suspend+0x6b/0x190 [ 246.722825] ? pci_has_legacy_pm_support+0x70/0x70 [ 246.723737] __rpm_callback+0x7a/0x1d0 [ 246.724721] ? pci_has_legacy_pm_support+0x70/0x70 [ 246.725607] rpm_callback+0x24/0x80 [ 246.726553] ? pci_has_legacy_pm_support+0x70/0x70 [ 246.727376] rpm_suspend+0x142/0x6b0 [ 246.728185] pm_runtime_work+0x97/0xc0 [ 246.728938] process_one_work+0x231/0x620 [ 246.729796] worker_thread+0x44/0x3a0 [ 246.730614] kthread+0x12b/0x150 [ 246.731395] ? wq_pool_ids_show+0x140/0x140 [ 246.732202] ? kthread_create_worker_on_cpu+0x70/0x70 [ 246.732878] ret_from_fork+0x3a/0x50 [ 246.733768] INFO: task kworker/4:2:422 blocked for more than 120 seconds. [ 246.734587] Not tainted 4.18.0-rc5Lyude-Test+ #2 [ 246.735393] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 246.736113] kworker/4:2 D 0 422 2 0x80000080 [ 246.736789] Workqueue: events_long drm_dp_mst_link_probe_work [drm_kms_helper] [ 246.737665] Call Trace: [ 246.738490] __schedule+0x322/0xaf0 [ 246.739250] schedule+0x33/0x90 [ 246.739908] rpm_resume+0x19c/0x850 [ 246.740750] ? finish_wait+0x90/0x90 [ 246.741541] __pm_runtime_resume+0x4e/0x90 [ 246.742370] nv50_disp_atomic_commit+0x31/0x210 [nouveau] [ 246.743124] drm_atomic_commit+0x4a/0x50 [drm] [ 246.743775] restore_fbdev_mode_atomic+0x1c8/0x240 [drm_kms_helper] [ 246.744603] restore_fbdev_mode+0x31/0x140 [drm_kms_helper] [ 246.745373] drm_fb_helper_restore_fbdev_mode_unlocked+0x54/0xb0 [drm_kms_helper] [ 246.746220] drm_fb_helper_set_par+0x2d/0x50 [drm_kms_helper] [ 246.746884] drm_fb_helper_hotplug_event.part.28+0x96/0xb0 [drm_kms_helper] [ 246.747675] drm_fb_helper_output_poll_changed+0x23/0x30 [drm_kms_helper] [ 246.748544] drm_kms_helper_hotplug_event+0x2a/0x30 [drm_kms_helper] [ 246.749439] nv50_mstm_hotplug+0x15/0x20 [nouveau] [ 246.750111] drm_dp_send_link_address+0x177/0x1c0 [drm_kms_helper] [ 246.750764] drm_dp_check_and_send_link_address+0xa8/0xd0 [drm_kms_helper] [ 246.751602] drm_dp_mst_link_probe_work+0x51/0x90 [drm_kms_helper] [ 246.752314] process_one_work+0x231/0x620 [ 246.752979] worker_thread+0x44/0x3a0 [ 246.753838] kthread+0x12b/0x150 [ 246.754619] ? wq_pool_ids_show+0x140/0x140 [ 246.755386] ? kthread_create_worker_on_cpu+0x70/0x70 [ 246.756162] ret_from_fork+0x3a/0x50 [ 246.756847] Showing all locks held in the system: [ 246.758261] 3 locks held by kworker/4:0/37: [ 246.759016] #0: 00000000f8df4d2d ((wq_completion)"events"){+.+.}, at: process_one_work+0x1b3/0x620 [ 246.759856] #1: 00000000e6065461 ((work_completion)(&(&dev->mode_config.output_poll_work)->work)){+.+.}, at: process_one_work+0x1b3/0x620 [ 246.760670] #2: 00000000cb66735f (&helper->lock){+.+.}, at: drm_fb_helper_hotplug_event.part.28+0x20/0xb0 [drm_kms_helper] [ 246.761516] 2 locks held by kworker/0:1/60: [ 246.762274] #0: 00000000fff6be0f ((wq_completion)"pm"){+.+.}, at: process_one_work+0x1b3/0x620 [ 246.762982] #1: 000000005ab44fb4 ((work_completion)(&dev->power.work)){+.+.}, at: process_one_work+0x1b3/0x620 [ 246.763890] 1 lock held by khungtaskd/64: [ 246.764664] #0: 000000008cb8b5c3 (rcu_read_lock){....}, at: debug_show_all_locks+0x23/0x185 [ 246.765588] 5 locks held by kworker/4:2/422: [ 246.766440] #0: 00000000232f0959 ((wq_completion)"events_long"){+.+.}, at: process_one_work+0x1b3/0x620 [ 246.767390] #1: 00000000bb59b134 ((work_completion)(&mgr->work)){+.+.}, at: process_one_work+0x1b3/0x620 [ 246.768154] #2: 00000000cb66735f (&helper->lock){+.+.}, at: drm_fb_helper_restore_fbdev_mode_unlocked+0x4c/0xb0 [drm_kms_helper] [ 246.768966] #3: 000000004c8f0b6b (crtc_ww_class_acquire){+.+.}, at: restore_fbdev_mode_atomic+0x4b/0x240 [drm_kms_helper] [ 246.769921] #4: 000000004c34a296 (crtc_ww_class_mutex){+.+.}, at: drm_modeset_backoff+0x8a/0x1b0 [drm] [ 246.770839] 1 lock held by dmesg/1038: [ 246.771739] 2 locks held by zsh/1172: [ 246.772650] #0: 00000000836d0438 (&tty->ldisc_sem){++++}, at: ldsem_down_read+0x37/0x40 [ 246.773680] #1: 000000001f4f4d48 (&ldata->atomic_read_lock){+.+.}, at: n_tty_read+0xc1/0x870 [ 246.775522] ============================================= So, to fix this (and any other possible deadlock issues like this that could occur in the output_poll_changed patch) we make sure that nouveau's output_poll_changed functions grab a runtime power ref before sending any hotplug events, and hold it until we're finished. We introduce this through adding a generic DRM helper which other drivers may reuse. This fixes deadlock issues when in fbcon with nouveau on my P50, and should fix it for everyone else's as well! Signed-off-by: Lyude Paul <lyude@redhat.com> Reviewed-by: Karol Herbst <karolherbst@gmail.com> Cc: Lukas Wunner <lukas@wunner.de> Cc: stable@vger.kernel.org --- Changes since v1: - Add a generic helper for DRM to handle this drivers/gpu/drm/drm_fb_helper.c | 23 +++++++++++++++++++++++ drivers/gpu/drm/nouveau/dispnv50/disp.c | 2 +- include/drm/drm_fb_helper.h | 5 +++++ 3 files changed, 29 insertions(+), 1 deletion(-)