[PATCH] mmc: rtsx: fix possible circular locking dependency

[PATCH] mmc: rtsx: fix possible circular locking dependency

[micky_ching]

From: Micky Ching <micky_ching@realsil.com.cn>

To avoid dead lock, we need make sure host->lock is always acquire
before pcr->lock. But in irq handler, we acquired pcr->lock in rtsx mfd
driver, and sd_isr_done_transfer() is called during pcr->lock already
acquired. Since in sd_isr_done_transfer() the only work we do is schdule
tasklet, the cmd_tasklet and data_tasklet never conflict, so it is safe
to remove spin_lock() here.

Signed-off-by: Micky Ching <micky_ching@realsil.com.cn>
---
 drivers/mmc/host/rtsx_pci_sdmmc.c |    4 +---
 1 file changed, 1 insertion(+), 3 deletions(-)

diff --git a/drivers/mmc/host/rtsx_pci_sdmmc.c b/drivers/mmc/host/rtsx_pci_sdmmc.c
index 453e1d4..40695e0 100644
--- a/drivers/mmc/host/rtsx_pci_sdmmc.c
+++ b/drivers/mmc/host/rtsx_pci_sdmmc.c
@@ -108,12 +108,10 @@ static void sd_isr_done_transfer(struct platform_device *pdev)
 {
 	struct realtek_pci_sdmmc *host = platform_get_drvdata(pdev);
 
-	spin_lock(&host->lock);
 	if (host->cmd)
 		tasklet_schedule(&host->cmd_tasklet);
-	if (host->data)
+	else if (host->data)
 		tasklet_schedule(&host->data_tasklet);
-	spin_unlock(&host->lock);
 }
 
 static void sd_request_timeout(unsigned long host_addr)
-- 
1.7.9.5

Re: [PATCH] mmc: rtsx: fix possible circular locking dependency

[Peter Wu]

Hi!

On Wednesday 16 April 2014 09:38:44 micky_ching@realsil.com.cn wrote:
> From: Micky Ching <micky_ching@realsil.com.cn>
> 
> To avoid dead lock, we need make sure host->lock is always acquire
> before pcr->lock. But in irq handler, we acquired pcr->lock in rtsx mfd
> driver, and sd_isr_done_transfer() is called during pcr->lock already
> acquired. Since in sd_isr_done_transfer() the only work we do is schdule
> tasklet, the cmd_tasklet and data_tasklet never conflict, so it is safe
> to remove spin_lock() here.
> 
> Signed-off-by: Micky Ching <micky_ching@realsil.com.cn>
> ---
>  drivers/mmc/host/rtsx_pci_sdmmc.c |    4 +---
>  1 file changed, 1 insertion(+), 3 deletions(-)

This patch came from https://lkml.kernel.org/r/534DE1D7.3000308@realsil.com.cn
("Re: rtsx_pci_sdmmc lockdep splat").

With v3.15-rc1-49-g10ec34f, I have a hung machine when inserting a SD card.
lockdep was not enabled for the kernel, I have not bisected yet.
This patch on top of that kernel version does not help (tested by
rmmod rtsx_pci_sdmmc and insmod the patched one).

Console (as typed over from a picture, sorry for any typos):
WARNING: CPU: 1 PID: 0 at kernel/locking/mutex.c:698
DEBUG_LOCKS_WARN_ON(in_interrupt())
Modules linked in: ...
CPU: 1 PID: 0 Comm: swapper/1 Not tainted 3.15-rc1-custom-000049-g10ec34f #5
Hardware name: Shuttle Inc. XS36V/XS36V, BIOS 1.11 12/18/2012
Call trace:
<IRQ> dump_stack
warn_slowpath_common
warn_slowpath_fmt
__mutex_unlock_slowpath
mutex_unlock
sd_finish_request [rtsx_pci_sdmmc]
tasklet_action
__do_softirq
irq_exit
smp_apic_timer_interrupt
apic_timer_interrupt
<EOI> ? cpuidle_enter_state
cpuidle_enter
cpu_startup_entry
start_secondary
---[end trace ...]---
(60 seconds later:)
INFO: rcu_preempt detected stalls on CPUs/tasks: {} (detected by 1, t=18004 jiffies, g=3264, c=3263, q=2)
INFO: Stall ended before state dump start

I also managed to get this trace about 106 seconds later when switching TTY:
INFO: task kworker/... blocked for more than 120 seconds
Workqueue: kmmcd mm_rescan [mmc_core]
Call trace:
? update_rq_clock.part80
? internal_add_timer
schedule
schedule_preempt
__mutex_lock_slowpath
mutex_lock
sdmmc_request [rtsx_pci_sdmmc]
mmc_start_request [mmc_core]
__mmc_start_req [mmc_core]
mmc_wait_for_cmd [mmc_core]
? mmc_release_host [mmc_core]
mmc_io_rw_direct_host [mmc_core]

I'll try to get a lockdep kernel and text logs later, but perhaps you already
know the issue?

Peter

> diff --git a/drivers/mmc/host/rtsx_pci_sdmmc.c
> b/drivers/mmc/host/rtsx_pci_sdmmc.c index 453e1d4..40695e0 100644
> --- a/drivers/mmc/host/rtsx_pci_sdmmc.c
> +++ b/drivers/mmc/host/rtsx_pci_sdmmc.c
> @@ -108,12 +108,10 @@ static void sd_isr_done_transfer(struct
> platform_device *pdev) {
>  	struct realtek_pci_sdmmc *host = platform_get_drvdata(pdev);
> 
> -	spin_lock(&host->lock);
>  	if (host->cmd)
>  		tasklet_schedule(&host->cmd_tasklet);
> -	if (host->data)
> +	else if (host->data)
>  		tasklet_schedule(&host->data_tasklet);
> -	spin_unlock(&host->lock);
>  }
> 
>  static void sd_request_timeout(unsigned long host_addr)

Locking issues in "mmc: rtsx: add support for pre_req and post_req" (was: Re: [PATCH] mmc: rtsx: fix possible circular locking dependency)

[Peter Wu]

So, I reverted c42deffd5b53c9e583d83c7964854ede2f12410d ("mmc: rtsx: add 
support for pre_req and post_req") on top of v3.15-rc1-49-g10ec34f and the 
hang issue went away.

There is something that is possibly problematic. All three tasklets (cmd, 
data, finish) try to spinlock on host->lock. According to the tasklets 
documentation[1], they always run at interrupts (i.e., at any time, possibly 
right after tasklet_schedule if I got this right?).

These tasklets however do get scheduled *under* the host->lock which will 
cause a deadlock. This proposed patch ("mmc: rtsx: fix possible circular 
locking dependency") fixes the issue for sd_isr_done_transfer, but there are 
others:

1. sd_request_timeout:
 125         spin_lock_irqsave(&host->lock, flags);
 ...
 139 out:
 140         tasklet_schedule(&host->finish_tasklet); // <--
 141         spin_unlock_irqrestore(&host->lock, flags);

2. sd_get_rsp (cmd_tasklet!):
 429         spin_lock_irqsave(&host->lock, flags);
 ...
 506         tasklet_schedule(&host->finish_tasklet); // <--
 507         spin_unlock_irqrestore(&host->lock, flags);

3. sd_finish_multi_rw (data_tasklet!):
 657         spin_lock_irqsave(&host->lock, flags);
 ...
 684         tasklet_schedule(&host->finish_tasklet); // <--
 685         spin_unlock_irqrestore(&host->lock, flags);

4. sdmmc_request:
 921         mutex_lock(&pcr->pcr_mutex);
 922         spin_lock_irqsave(&host->lock, flags);
 ...
 967         tasklet_schedule(&host->finish_tasklet); // <--
 968         spin_unlock_irqrestore(&host->lock, flags);

5. rtsx_pci_sdmmc_drv_remove:
  1526         spin_lock_irqsave(&host->lock, flags);
  1527         if (host->mrq) {
  ...
  1541                 tasklet_schedule(&host->finish_tasklet); // <--
  1542         }
  1543         spin_unlock_irqrestore(&host->lock, flags);
  1544 
  1545         del_timer_sync(&host->timer);
  1546         tasklet_kill(&host->cmd_tasklet);
  1547         tasklet_kill(&host->data_tasklet);
  1548         tasklet_kill(&host->finish_tasklet); // <--

pcr_mutex (un)locking:
 - gets locked in sdmmc_request
 - gets unlocked in sd_finish_request (finish_tasklet).
 - gets locked/unlocked in sdmmc_set_ios
 - gets locked/unlocked in sdmmc_get_ro
 - gets locked/unlocked in sdmmc_get_cd
 - gets locked/unlocked in sdmmc_switch_voltage
 - gets locked/unlocked in sdmmc_execute_tuning

finish_tasklet (sd_finish_request()) gets scheduled in:
 - sd_request_timeout (under host->lock; called on timer expiration)
 - error path of sd_send_cmd
 - get_rsp (cmd_tasklet; under host->lock)
 - error path of sd_start_multi_rw (after mod timer)
 - sd_finish_multi_rw (under host->lock)
 - sdmmc_request (under host->lock in error path; without host->lock
   elsewhere)
 - rtsx_pci_sdmmc_drv_remove (under host->lock)

sd_request_timeout (timer) related:
 - deleted in sd_finish_request under host->lock (also assumes pcr_mutex)
 - sd_send_cmd (timer set with 100ms timeout, not called in error path)
 - sd_start_multi_rw (timeout set to 10 HZ, called before error path is
   checked in which finish_tasklet gets scheduled)
Note: sd_request_timeout claims+releases host->lock.

If I understand it correctly, host->lock is responsible for protecting the 
realtek_pci_sdmmc structure. Why is tasklet_schedule() on the same lock?

Shouldn't the above five tasklet_schedule calls be moved outside the lock? 
Will it be problematic if the same tasklet gets executed multiple times (if 
that is possible?).

Does it really need that much locking? dw_mmc.c also implements pre_req, but 
uses tasklets without needing to lock anything.

Kind regards,
Peter

 [1]: http://www.makelinux.net/ldd3/chp-7-sect-5

On Friday 18 April 2014 16:00:53 Peter Wu wrote:
> On Wednesday 16 April 2014 09:38:44 micky_ching@realsil.com.cn wrote:
> > From: Micky Ching <micky_ching@realsil.com.cn>
> > 
> > To avoid dead lock, we need make sure host->lock is always acquire
> > before pcr->lock. But in irq handler, we acquired pcr->lock in rtsx mfd
> > driver, and sd_isr_done_transfer() is called during pcr->lock already
> > acquired. Since in sd_isr_done_transfer() the only work we do is schdule
> > tasklet, the cmd_tasklet and data_tasklet never conflict, so it is safe
> > to remove spin_lock() here.
> > 
> > Signed-off-by: Micky Ching <micky_ching@realsil.com.cn>
> > ---
> > 
> >  drivers/mmc/host/rtsx_pci_sdmmc.c |    4 +---
> >  1 file changed, 1 insertion(+), 3 deletions(-)
> 
> This patch came from
> https://lkml.kernel.org/r/534DE1D7.3000308@realsil.com.cn ("Re:
> rtsx_pci_sdmmc lockdep splat").
> 
> With v3.15-rc1-49-g10ec34f, I have a hung machine when inserting a SD card.
> lockdep was not enabled for the kernel, I have not bisected yet.
> This patch on top of that kernel version does not help (tested by
> rmmod rtsx_pci_sdmmc and insmod the patched one).
> 
> Console (as typed over from a picture, sorry for any typos):
> WARNING: CPU: 1 PID: 0 at kernel/locking/mutex.c:698
> DEBUG_LOCKS_WARN_ON(in_interrupt())
> Modules linked in: ...
> CPU: 1 PID: 0 Comm: swapper/1 Not tainted 3.15-rc1-custom-000049-g10ec34f #5
> Hardware name: Shuttle Inc. XS36V/XS36V, BIOS 1.11 12/18/2012
> Call trace:
> <IRQ> dump_stack
> warn_slowpath_common
> warn_slowpath_fmt
> __mutex_unlock_slowpath
> mutex_unlock
> sd_finish_request [rtsx_pci_sdmmc]
> tasklet_action
> __do_softirq
> irq_exit
> smp_apic_timer_interrupt
> apic_timer_interrupt
> <EOI> ? cpuidle_enter_state
> cpuidle_enter
> cpu_startup_entry
> start_secondary
> ---[end trace ...]---
> (60 seconds later:)
> INFO: rcu_preempt detected stalls on CPUs/tasks: {} (detected by 1, t=18004
> jiffies, g=3264, c=3263, q=2) INFO: Stall ended before state dump start
> 
> I also managed to get this trace about 106 seconds later when switching TTY:
> INFO: task kworker/... blocked for more than 120 seconds
> Workqueue: kmmcd mm_rescan [mmc_core]
> Call trace:
> ? update_rq_clock.part80
> ? internal_add_timer
> schedule
> schedule_preempt
> __mutex_lock_slowpath
> mutex_lock
> sdmmc_request [rtsx_pci_sdmmc]
> mmc_start_request [mmc_core]
> __mmc_start_req [mmc_core]
> mmc_wait_for_cmd [mmc_core]
> ? mmc_release_host [mmc_core]
> mmc_io_rw_direct_host [mmc_core]
> 
> I'll try to get a lockdep kernel and text logs later, but perhaps you
> already know the issue?
> 
> Peter
> 
> > diff --git a/drivers/mmc/host/rtsx_pci_sdmmc.c
> > b/drivers/mmc/host/rtsx_pci_sdmmc.c index 453e1d4..40695e0 100644
> > --- a/drivers/mmc/host/rtsx_pci_sdmmc.c
> > +++ b/drivers/mmc/host/rtsx_pci_sdmmc.c
> > @@ -108,12 +108,10 @@ static void sd_isr_done_transfer(struct
> > platform_device *pdev) {
> > 
> >  	struct realtek_pci_sdmmc *host = platform_get_drvdata(pdev);
> > 
> > -	spin_lock(&host->lock);
> > 
> >  	if (host->cmd)
> >  	
> >  		tasklet_schedule(&host->cmd_tasklet);
> > 
> > -	if (host->data)
> > +	else if (host->data)
> > 
> >  		tasklet_schedule(&host->data_tasklet);
> > 
> > -	spin_unlock(&host->lock);
> > 
> >  }
> >  
> >  static void sd_request_timeout(unsigned long host_addr)

Re: Locking issues in "mmc: rtsx: add support for pre_req and post_req"

[micky]

Hi Peter,

I'm considering not using spinlock to get it work and will resend the 
patch later.
Thank you.

Best Regards.
micky
On 04/19/2014 07:13 AM, Peter Wu wrote:
> So, I reverted c42deffd5b53c9e583d83c7964854ede2f12410d ("mmc: rtsx: add
> support for pre_req and post_req") on top of v3.15-rc1-49-g10ec34f and the
> hang issue went away.
>
> There is something that is possibly problematic. All three tasklets (cmd,
> data, finish) try to spinlock on host->lock. According to the tasklets
> documentation[1], they always run at interrupts (i.e., at any time, possibly
> right after tasklet_schedule if I got this right?).
>
> These tasklets however do get scheduled *under* the host->lock which will
> cause a deadlock. This proposed patch ("mmc: rtsx: fix possible circular
> locking dependency") fixes the issue for sd_isr_done_transfer, but there are
> others:
>
> 1. sd_request_timeout:
>   125         spin_lock_irqsave(&host->lock, flags);
>   ...
>   139 out:
>   140         tasklet_schedule(&host->finish_tasklet); // <--
>   141         spin_unlock_irqrestore(&host->lock, flags);
>
> 2. sd_get_rsp (cmd_tasklet!):
>   429         spin_lock_irqsave(&host->lock, flags);
>   ...
>   506         tasklet_schedule(&host->finish_tasklet); // <--
>   507         spin_unlock_irqrestore(&host->lock, flags);
>
> 3. sd_finish_multi_rw (data_tasklet!):
>   657         spin_lock_irqsave(&host->lock, flags);
>   ...
>   684         tasklet_schedule(&host->finish_tasklet); // <--
>   685         spin_unlock_irqrestore(&host->lock, flags);
>
> 4. sdmmc_request:
>   921         mutex_lock(&pcr->pcr_mutex);
>   922         spin_lock_irqsave(&host->lock, flags);
>   ...
>   967         tasklet_schedule(&host->finish_tasklet); // <--
>   968         spin_unlock_irqrestore(&host->lock, flags);
>
> 5. rtsx_pci_sdmmc_drv_remove:
>    1526         spin_lock_irqsave(&host->lock, flags);
>    1527         if (host->mrq) {
>    ...
>    1541                 tasklet_schedule(&host->finish_tasklet); // <--
>    1542         }
>    1543         spin_unlock_irqrestore(&host->lock, flags);
>    1544
>    1545         del_timer_sync(&host->timer);
>    1546         tasklet_kill(&host->cmd_tasklet);
>    1547         tasklet_kill(&host->data_tasklet);
>    1548         tasklet_kill(&host->finish_tasklet); // <--
>
> pcr_mutex (un)locking:
>   - gets locked in sdmmc_request
>   - gets unlocked in sd_finish_request (finish_tasklet).
>   - gets locked/unlocked in sdmmc_set_ios
>   - gets locked/unlocked in sdmmc_get_ro
>   - gets locked/unlocked in sdmmc_get_cd
>   - gets locked/unlocked in sdmmc_switch_voltage
>   - gets locked/unlocked in sdmmc_execute_tuning
>
> finish_tasklet (sd_finish_request()) gets scheduled in:
>   - sd_request_timeout (under host->lock; called on timer expiration)
>   - error path of sd_send_cmd
>   - get_rsp (cmd_tasklet; under host->lock)
>   - error path of sd_start_multi_rw (after mod timer)
>   - sd_finish_multi_rw (under host->lock)
>   - sdmmc_request (under host->lock in error path; without host->lock
>     elsewhere)
>   - rtsx_pci_sdmmc_drv_remove (under host->lock)
>
> sd_request_timeout (timer) related:
>   - deleted in sd_finish_request under host->lock (also assumes pcr_mutex)
>   - sd_send_cmd (timer set with 100ms timeout, not called in error path)
>   - sd_start_multi_rw (timeout set to 10 HZ, called before error path is
>     checked in which finish_tasklet gets scheduled)
> Note: sd_request_timeout claims+releases host->lock.
>
> If I understand it correctly, host->lock is responsible for protecting the
> realtek_pci_sdmmc structure. Why is tasklet_schedule() on the same lock?
>
> Shouldn't the above five tasklet_schedule calls be moved outside the lock?
> Will it be problematic if the same tasklet gets executed multiple times (if
> that is possible?).
>
> Does it really need that much locking? dw_mmc.c also implements pre_req, but
> uses tasklets without needing to lock anything.
>
> Kind regards,
> Peter
>
>   [1]: http://www.makelinux.net/ldd3/chp-7-sect-5
>
> On Friday 18 April 2014 16:00:53 Peter Wu wrote:
>> On Wednesday 16 April 2014 09:38:44 micky_ching@realsil.com.cn wrote:
>>> From: Micky Ching <micky_ching@realsil.com.cn>
>>>
>>> To avoid dead lock, we need make sure host->lock is always acquire
>>> before pcr->lock. But in irq handler, we acquired pcr->lock in rtsx mfd
>>> driver, and sd_isr_done_transfer() is called during pcr->lock already
>>> acquired. Since in sd_isr_done_transfer() the only work we do is schdule
>>> tasklet, the cmd_tasklet and data_tasklet never conflict, so it is safe
>>> to remove spin_lock() here.
>>>
>>> Signed-off-by: Micky Ching <micky_ching@realsil.com.cn>
>>> ---
>>>
>>>   drivers/mmc/host/rtsx_pci_sdmmc.c |    4 +---
>>>   1 file changed, 1 insertion(+), 3 deletions(-)
>> This patch came from
>> https://lkml.kernel.org/r/534DE1D7.3000308@realsil.com.cn ("Re:
>> rtsx_pci_sdmmc lockdep splat").
>>
>> With v3.15-rc1-49-g10ec34f, I have a hung machine when inserting a SD card.
>> lockdep was not enabled for the kernel, I have not bisected yet.
>> This patch on top of that kernel version does not help (tested by
>> rmmod rtsx_pci_sdmmc and insmod the patched one).
>>
>> Console (as typed over from a picture, sorry for any typos):
>> WARNING: CPU: 1 PID: 0 at kernel/locking/mutex.c:698
>> DEBUG_LOCKS_WARN_ON(in_interrupt())
>> Modules linked in: ...
>> CPU: 1 PID: 0 Comm: swapper/1 Not tainted 3.15-rc1-custom-000049-g10ec34f #5
>> Hardware name: Shuttle Inc. XS36V/XS36V, BIOS 1.11 12/18/2012
>> Call trace:
>> <IRQ> dump_stack
>> warn_slowpath_common
>> warn_slowpath_fmt
>> __mutex_unlock_slowpath
>> mutex_unlock
>> sd_finish_request [rtsx_pci_sdmmc]
>> tasklet_action
>> __do_softirq
>> irq_exit
>> smp_apic_timer_interrupt
>> apic_timer_interrupt
>> <EOI> ? cpuidle_enter_state
>> cpuidle_enter
>> cpu_startup_entry
>> start_secondary
>> ---[end trace ...]---
>> (60 seconds later:)
>> INFO: rcu_preempt detected stalls on CPUs/tasks: {} (detected by 1, t=18004
>> jiffies, g=3264, c=3263, q=2) INFO: Stall ended before state dump start
>>
>> I also managed to get this trace about 106 seconds later when switching TTY:
>> INFO: task kworker/... blocked for more than 120 seconds
>> Workqueue: kmmcd mm_rescan [mmc_core]
>> Call trace:
>> ? update_rq_clock.part80
>> ? internal_add_timer
>> schedule
>> schedule_preempt
>> __mutex_lock_slowpath
>> mutex_lock
>> sdmmc_request [rtsx_pci_sdmmc]
>> mmc_start_request [mmc_core]
>> __mmc_start_req [mmc_core]
>> mmc_wait_for_cmd [mmc_core]
>> ? mmc_release_host [mmc_core]
>> mmc_io_rw_direct_host [mmc_core]
>>
>> I'll try to get a lockdep kernel and text logs later, but perhaps you
>> already know the issue?
>>
>> Peter
>>
>>> diff --git a/drivers/mmc/host/rtsx_pci_sdmmc.c
>>> b/drivers/mmc/host/rtsx_pci_sdmmc.c index 453e1d4..40695e0 100644
>>> --- a/drivers/mmc/host/rtsx_pci_sdmmc.c
>>> +++ b/drivers/mmc/host/rtsx_pci_sdmmc.c
>>> @@ -108,12 +108,10 @@ static void sd_isr_done_transfer(struct
>>> platform_device *pdev) {
>>>
>>>   	struct realtek_pci_sdmmc *host = platform_get_drvdata(pdev);
>>>
>>> -	spin_lock(&host->lock);
>>>
>>>   	if (host->cmd)
>>>   	
>>>   		tasklet_schedule(&host->cmd_tasklet);
>>>
>>> -	if (host->data)
>>> +	else if (host->data)
>>>
>>>   		tasklet_schedule(&host->data_tasklet);
>>>
>>> -	spin_unlock(&host->lock);
>>>
>>>   }
>>>   
>>>   static void sd_request_timeout(unsigned long host_addr)
> .
>