2015-12-21 18:18:04

by Måns Rullgård

[permalink] [raw]
Subject: [PATCH] ata: sata_dwc_460ex: remove incorrect locking

This lock is already taken in ata_scsi_queuecmd() a few levels up the
call stack so attempting to take it here is an error. Moreover, it is
pointless in the first place since it only protects a single, atomic
assignment.

Enabling lock debugging gives the following output:

=============================================
[ INFO: possible recursive locking detected ]
4.4.0-rc5+ #189 Not tainted
---------------------------------------------
kworker/u2:3/37 is trying to acquire lock:
(&(&host->lock)->rlock){-.-...}, at: [<90283294>] sata_dwc_exec_command_by_tag.constprop.14+0x44/0x8c

but task is already holding lock:
(&(&host->lock)->rlock){-.-...}, at: [<902761ac>] ata_scsi_queuecmd+0x2c/0x330

other info that might help us debug this:
Possible unsafe locking scenario:

CPU0
----
lock(&(&host->lock)->rlock);
lock(&(&host->lock)->rlock);

*** DEADLOCK ***
May be due to missing lock nesting notation

4 locks held by kworker/u2:3/37:
#0: ("events_unbound"){.+.+.+}, at: [<9003a0a4>] process_one_work+0x12c/0x430
#1: ((&entry->work)){+.+.+.}, at: [<9003a0a4>] process_one_work+0x12c/0x430
#2: (&bdev->bd_mutex){+.+.+.}, at: [<9011fd54>] __blkdev_get+0x50/0x380
#3: (&(&host->lock)->rlock){-.-...}, at: [<902761ac>] ata_scsi_queuecmd+0x2c/0x330

stack backtrace:
CPU: 0 PID: 37 Comm: kworker/u2:3 Not tainted 4.4.0-rc5+ #189
Workqueue: events_unbound async_run_entry_fn
Stack : 90b38e30 00000021 00000003 9b2a6040 00000000 9005f3f0 904fc8dc 00000025
906b96e4 00000000 90528648 9b3336c4 904fc8dc 9009bf18 00000002 00000004
00000000 00000000 9b3336c4 9b3336e4 904fc8dc 9003d074 00000000 90500000
9005e738 00000000 00000000 00000000 00000000 00000000 00000000 00000000
6e657665 755f7374 756f626e 0000646e 00000000 00000000 9b00ca00 9b025000
...
Call Trace:
[<90009d6c>] show_stack+0x88/0xa4
[<90057744>] __lock_acquire+0x1ce8/0x2154
[<900583e4>] lock_acquire+0x64/0x8c
[<9045ff10>] _raw_spin_lock_irqsave+0x54/0x78
[<90283294>] sata_dwc_exec_command_by_tag.constprop.14+0x44/0x8c
[<90283484>] sata_dwc_qc_issue+0x1a8/0x24c
[<9026b39c>] ata_qc_issue+0x1f0/0x410
[<90273c6c>] ata_scsi_translate+0xb4/0x200
[<90276234>] ata_scsi_queuecmd+0xb4/0x330
[<9025800c>] scsi_dispatch_cmd+0xd0/0x128
[<90259934>] scsi_request_fn+0x58c/0x638
[<901a3e50>] __blk_run_queue+0x40/0x5c
[<901a83d4>] blk_queue_bio+0x27c/0x28c
[<901a5914>] generic_make_request+0xf0/0x188
[<901a5a54>] submit_bio+0xa8/0x194
[<9011adcc>] submit_bh_wbc.isra.23+0x15c/0x17c
[<9011c908>] block_read_full_page+0x3e4/0x428
[<9009e2e0>] do_read_cache_page+0xac/0x210
[<9009fd90>] read_cache_page+0x18/0x24
[<901bbd18>] read_dev_sector+0x38/0xb0
[<901bd174>] msdos_partition+0xb4/0x5c0
[<901bcb8c>] check_partition+0x140/0x274
[<901bba60>] rescan_partitions+0xa0/0x2b0
[<9011ff68>] __blkdev_get+0x264/0x380
[<901201ac>] blkdev_get+0x128/0x36c
[<901b9378>] add_disk+0x3c0/0x4bc
[<90268268>] sd_probe_async+0x100/0x224
[<90043a44>] async_run_entry_fn+0x50/0x124
[<9003a11c>] process_one_work+0x1a4/0x430
[<9003a4f4>] worker_thread+0x14c/0x4fc
[<900408f4>] kthread+0xd0/0xe8
[<90004338>] ret_from_kernel_thread+0x14/0x1c

Fixes: 62936009f35a ("[libata] Add 460EX on-chip SATA driver, sata_dwc_460ex")
Signed-off-by: Mans Rullgard <[email protected]>
---
drivers/ata/sata_dwc_460ex.c | 4 +---
1 file changed, 1 insertion(+), 3 deletions(-)

diff --git a/drivers/ata/sata_dwc_460ex.c b/drivers/ata/sata_dwc_460ex.c
index 902034991517..7a7faca0ddcd 100644
--- a/drivers/ata/sata_dwc_460ex.c
+++ b/drivers/ata/sata_dwc_460ex.c
@@ -924,15 +924,13 @@ static void sata_dwc_exec_command_by_tag(struct ata_port *ap,
struct ata_taskfile *tf,
u8 tag, u32 cmd_issued)
{
- unsigned long flags;
struct sata_dwc_device_port *hsdevp = HSDEVP_FROM_AP(ap);

dev_dbg(ap->dev, "%s cmd(0x%02x): %s tag=%d\n", __func__, tf->command,
ata_get_cmd_descript(tf->command), tag);

- spin_lock_irqsave(&ap->host->lock, flags);
hsdevp->cmd_issued[tag] = cmd_issued;
- spin_unlock_irqrestore(&ap->host->lock, flags);
+
/*
* Clear SError before executing a new command.
* sata_dwc_scr_write and read can not be used here. Clearing the PM
--
2.6.3


2015-12-21 20:41:04

by Andy Shevchenko

[permalink] [raw]
Subject: Re: [PATCH] ata: sata_dwc_460ex: remove incorrect locking

On Mon, 2015-12-21 at 18:17 +0000, Mans Rullgard wrote:
> This lock is already taken in ata_scsi_queuecmd() a few levels up the
> call stack so attempting to take it here is an error.  Moreover, it
> is
> pointless in the first place since it only protects a single, atomic
> assignment.
>
> Enabling lock debugging gives the following output:
>

+Julian.

I think Julian may give his Tested-by: tag.

> =============================================
> [ INFO: possible recursive locking detected ]
> 4.4.0-rc5+ #189 Not tainted
> ---------------------------------------------
> kworker/u2:3/37 is trying to acquire lock:
>  (&(&host->lock)->rlock){-.-...}, at: [<90283294>]
> sata_dwc_exec_command_by_tag.constprop.14+0x44/0x8c
>
> but task is already holding lock:
>  (&(&host->lock)->rlock){-.-...}, at: [<902761ac>]
> ata_scsi_queuecmd+0x2c/0x330
>
> other info that might help us debug this:
>  Possible unsafe locking scenario:
>
>        CPU0
>        ----
>   lock(&(&host->lock)->rlock);
>   lock(&(&host->lock)->rlock);
>
>  *** DEADLOCK ***
>  May be due to missing lock nesting notation
>
> 4 locks held by kworker/u2:3/37:
>  #0:  ("events_unbound"){.+.+.+}, at: [<9003a0a4>]
> process_one_work+0x12c/0x430
>  #1:  ((&entry->work)){+.+.+.}, at: [<9003a0a4>]
> process_one_work+0x12c/0x430
>  #2:  (&bdev->bd_mutex){+.+.+.}, at: [<9011fd54>]
> __blkdev_get+0x50/0x380
>  #3:  (&(&host->lock)->rlock){-.-...}, at: [<902761ac>]
> ata_scsi_queuecmd+0x2c/0x330
>
> stack backtrace:
> CPU: 0 PID: 37 Comm: kworker/u2:3 Not tainted 4.4.0-rc5+ #189
> Workqueue: events_unbound async_run_entry_fn
> Stack : 90b38e30 00000021 00000003 9b2a6040 00000000 9005f3f0
> 904fc8dc 00000025
>         906b96e4 00000000 90528648 9b3336c4 904fc8dc 9009bf18
> 00000002 00000004
>         00000000 00000000 9b3336c4 9b3336e4 904fc8dc 9003d074
> 00000000 90500000
>         9005e738 00000000 00000000 00000000 00000000 00000000
> 00000000 00000000
>         6e657665 755f7374 756f626e 0000646e 00000000 00000000
> 9b00ca00 9b025000
>           ...
> Call Trace:
> [<90009d6c>] show_stack+0x88/0xa4
> [<90057744>] __lock_acquire+0x1ce8/0x2154
> [<900583e4>] lock_acquire+0x64/0x8c
> [<9045ff10>] _raw_spin_lock_irqsave+0x54/0x78
> [<90283294>] sata_dwc_exec_command_by_tag.constprop.14+0x44/0x8c
> [<90283484>] sata_dwc_qc_issue+0x1a8/0x24c
> [<9026b39c>] ata_qc_issue+0x1f0/0x410
> [<90273c6c>] ata_scsi_translate+0xb4/0x200
> [<90276234>] ata_scsi_queuecmd+0xb4/0x330
> [<9025800c>] scsi_dispatch_cmd+0xd0/0x128
> [<90259934>] scsi_request_fn+0x58c/0x638
> [<901a3e50>] __blk_run_queue+0x40/0x5c
> [<901a83d4>] blk_queue_bio+0x27c/0x28c
> [<901a5914>] generic_make_request+0xf0/0x188
> [<901a5a54>] submit_bio+0xa8/0x194
> [<9011adcc>] submit_bh_wbc.isra.23+0x15c/0x17c
> [<9011c908>] block_read_full_page+0x3e4/0x428
> [<9009e2e0>] do_read_cache_page+0xac/0x210
> [<9009fd90>] read_cache_page+0x18/0x24
> [<901bbd18>] read_dev_sector+0x38/0xb0
> [<901bd174>] msdos_partition+0xb4/0x5c0
> [<901bcb8c>] check_partition+0x140/0x274
> [<901bba60>] rescan_partitions+0xa0/0x2b0
> [<9011ff68>] __blkdev_get+0x264/0x380
> [<901201ac>] blkdev_get+0x128/0x36c
> [<901b9378>] add_disk+0x3c0/0x4bc
> [<90268268>] sd_probe_async+0x100/0x224
> [<90043a44>] async_run_entry_fn+0x50/0x124
> [<9003a11c>] process_one_work+0x1a4/0x430
> [<9003a4f4>] worker_thread+0x14c/0x4fc
> [<900408f4>] kthread+0xd0/0xe8
> [<90004338>] ret_from_kernel_thread+0x14/0x1c
>
> Fixes: 62936009f35a ("[libata] Add 460EX on-chip SATA driver,
> sata_dwc_460ex")
> Signed-off-by: Mans Rullgard <[email protected]>
> ---
>  drivers/ata/sata_dwc_460ex.c | 4 +---
>  1 file changed, 1 insertion(+), 3 deletions(-)
>
> diff --git a/drivers/ata/sata_dwc_460ex.c
> b/drivers/ata/sata_dwc_460ex.c
> index 902034991517..7a7faca0ddcd 100644
> --- a/drivers/ata/sata_dwc_460ex.c
> +++ b/drivers/ata/sata_dwc_460ex.c
> @@ -924,15 +924,13 @@ static void sata_dwc_exec_command_by_tag(struct
> ata_port *ap,
>    struct ata_taskfile *tf,
>    u8 tag, u32 cmd_issued)
>  {
> - unsigned long flags;
>   struct sata_dwc_device_port *hsdevp = HSDEVP_FROM_AP(ap);
>  
>   dev_dbg(ap->dev, "%s cmd(0x%02x): %s tag=%d\n", __func__,
> tf->command,
>   ata_get_cmd_descript(tf->command), tag);
>  
> - spin_lock_irqsave(&ap->host->lock, flags);
>   hsdevp->cmd_issued[tag] = cmd_issued;
> - spin_unlock_irqrestore(&ap->host->lock, flags);
> +
>   /*
>    * Clear SError before executing a new command.
>    * sata_dwc_scr_write and read can not be used here.
> Clearing the PM

--
Andy Shevchenko <[email protected]>
Intel Finland Oy

2015-12-21 21:42:28

by Julian Margetson

[permalink] [raw]
Subject: Re: [PATCH] ata: sata_dwc_460ex: remove incorrect locking

On 12/21/2015 4:41 PM, Andy Shevchenko wrote:
> On Mon, 2015-12-21 at 18:17 +0000, Mans Rullgard wrote:
>> This lock is already taken in ata_scsi_queuecmd() a few levels up the
>> call stack so attempting to take it here is an error. Moreover, it
>> is
>> pointless in the first place since it only protects a single, atomic
>> assignment.
>>
>> Enabling lock debugging gives the following output:
>>
> +Julian.
>
> I think Julian may give his Tested-by: tag.
>
>> =============================================
>> [ INFO: possible recursive locking detected ]
>> 4.4.0-rc5+ #189 Not tainted
>> ---------------------------------------------
>> kworker/u2:3/37 is trying to acquire lock:
>> (&(&host->lock)->rlock){-.-...}, at: [<90283294>]
>> sata_dwc_exec_command_by_tag.constprop.14+0x44/0x8c
>>
>> but task is already holding lock:
>> (&(&host->lock)->rlock){-.-...}, at: [<902761ac>]
>> ata_scsi_queuecmd+0x2c/0x330
>>
>> other info that might help us debug this:
>> Possible unsafe locking scenario:
>>
>> CPU0
>> ----
>> lock(&(&host->lock)->rlock);
>> lock(&(&host->lock)->rlock);
>>
>> *** DEADLOCK ***
>> May be due to missing lock nesting notation
>>
>> 4 locks held by kworker/u2:3/37:
>> #0: ("events_unbound"){.+.+.+}, at: [<9003a0a4>]
>> process_one_work+0x12c/0x430
>> #1: ((&entry->work)){+.+.+.}, at: [<9003a0a4>]
>> process_one_work+0x12c/0x430
>> #2: (&bdev->bd_mutex){+.+.+.}, at: [<9011fd54>]
>> __blkdev_get+0x50/0x380
>> #3: (&(&host->lock)->rlock){-.-...}, at: [<902761ac>]
>> ata_scsi_queuecmd+0x2c/0x330
>>
>> stack backtrace:
>> CPU: 0 PID: 37 Comm: kworker/u2:3 Not tainted 4.4.0-rc5+ #189
>> Workqueue: events_unbound async_run_entry_fn
>> Stack : 90b38e30 00000021 00000003 9b2a6040 00000000 9005f3f0
>> 904fc8dc 00000025
>> 906b96e4 00000000 90528648 9b3336c4 904fc8dc 9009bf18
>> 00000002 00000004
>> 00000000 00000000 9b3336c4 9b3336e4 904fc8dc 9003d074
>> 00000000 90500000
>> 9005e738 00000000 00000000 00000000 00000000 00000000
>> 00000000 00000000
>> 6e657665 755f7374 756f626e 0000646e 00000000 00000000
>> 9b00ca00 9b025000
>> ...
>> Call Trace:
>> [<90009d6c>] show_stack+0x88/0xa4
>> [<90057744>] __lock_acquire+0x1ce8/0x2154
>> [<900583e4>] lock_acquire+0x64/0x8c
>> [<9045ff10>] _raw_spin_lock_irqsave+0x54/0x78
>> [<90283294>] sata_dwc_exec_command_by_tag.constprop.14+0x44/0x8c
>> [<90283484>] sata_dwc_qc_issue+0x1a8/0x24c
>> [<9026b39c>] ata_qc_issue+0x1f0/0x410
>> [<90273c6c>] ata_scsi_translate+0xb4/0x200
>> [<90276234>] ata_scsi_queuecmd+0xb4/0x330
>> [<9025800c>] scsi_dispatch_cmd+0xd0/0x128
>> [<90259934>] scsi_request_fn+0x58c/0x638
>> [<901a3e50>] __blk_run_queue+0x40/0x5c
>> [<901a83d4>] blk_queue_bio+0x27c/0x28c
>> [<901a5914>] generic_make_request+0xf0/0x188
>> [<901a5a54>] submit_bio+0xa8/0x194
>> [<9011adcc>] submit_bh_wbc.isra.23+0x15c/0x17c
>> [<9011c908>] block_read_full_page+0x3e4/0x428
>> [<9009e2e0>] do_read_cache_page+0xac/0x210
>> [<9009fd90>] read_cache_page+0x18/0x24
>> [<901bbd18>] read_dev_sector+0x38/0xb0
>> [<901bd174>] msdos_partition+0xb4/0x5c0
>> [<901bcb8c>] check_partition+0x140/0x274
>> [<901bba60>] rescan_partitions+0xa0/0x2b0
>> [<9011ff68>] __blkdev_get+0x264/0x380
>> [<901201ac>] blkdev_get+0x128/0x36c
>> [<901b9378>] add_disk+0x3c0/0x4bc
>> [<90268268>] sd_probe_async+0x100/0x224
>> [<90043a44>] async_run_entry_fn+0x50/0x124
>> [<9003a11c>] process_one_work+0x1a4/0x430
>> [<9003a4f4>] worker_thread+0x14c/0x4fc
>> [<900408f4>] kthread+0xd0/0xe8
>> [<90004338>] ret_from_kernel_thread+0x14/0x1c
>>
>> Fixes: 62936009f35a ("[libata] Add 460EX on-chip SATA driver,
>> sata_dwc_460ex")
>> Signed-off-by: Mans Rullgard <[email protected]>
>> ---
>> drivers/ata/sata_dwc_460ex.c | 4 +---
>> 1 file changed, 1 insertion(+), 3 deletions(-)
>>
>> diff --git a/drivers/ata/sata_dwc_460ex.c
>> b/drivers/ata/sata_dwc_460ex.c
>> index 902034991517..7a7faca0ddcd 100644
>> --- a/drivers/ata/sata_dwc_460ex.c
>> +++ b/drivers/ata/sata_dwc_460ex.c
>> @@ -924,15 +924,13 @@ static void sata_dwc_exec_command_by_tag(struct
>> ata_port *ap,
>> struct ata_taskfile *tf,
>> u8 tag, u32 cmd_issued)
>> {
>> - unsigned long flags;
>> struct sata_dwc_device_port *hsdevp = HSDEVP_FROM_AP(ap);
>>
>> dev_dbg(ap->dev, "%s cmd(0x%02x): %s tag=%d\n", __func__,
>> tf->command,
>> ata_get_cmd_descript(tf->command), tag);
>>
>> - spin_lock_irqsave(&ap->host->lock, flags);
>> hsdevp->cmd_issued[tag] = cmd_issued;
>> - spin_unlock_irqrestore(&ap->host->lock, flags);
>> +
>> /*
>> * Clear SError before executing a new command.
>> * sata_dwc_scr_write and read can not be used here.
>> Clearing the PM

Tested-by: Julian Margetson <[email protected]>