Nouveau - Jul 2018 - [PATCH 1/2] drm/fb_helper: Add drm_fb_helper_output_poll_changed_with_rpm()

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 at redhat.com>
> Reviewed-by: Karol Herbst <karolherbst at gmail.com>
> Cc: Lukas Wunner <lukas at wunner.de>
> Cc: stable at 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 at redhat.com>
> > Reviewed-by: Karol Herbst <karolherbst at gmail.com>
> > Cc: Lukas Wunner <lukas at wunner.de>
> > Cc: stable at 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
> > 
-- 
Cheers,
	Lyude Paul

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 at redhat.com>
> > > Reviewed-by: Karol Herbst <karolherbst at gmail.com>
> > > Cc: Lukas Wunner <lukas at wunner.de>
> > > Cc: stable at 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
> > > 
-- 
Cheers,
	Lyude Paul

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