On 14-08-30 04:56 PM, Milan Broz wrote:
> Hi,
>
> I am using scsi_debug in cryptsetup testsuite and with recent 3.17-rc kernel
> it deadlocks on rmmod of scsi_debug module.
>
> For me even this simple reproducer causes deadlock:
>    modprobe scsi_debug dev_size_mb=16 sector_size=512 num_tgts=1
>    DEV="/dev/"$(grep -l -e scsi_debug /sys/block/*/device/model | cut -f4 -d /)
>    mkfs -t ext4 $DEV
>    rmmod scsi_debug
>
> (adding small delay before rmmod obviously helps here)

So I used this slight variation for testing:

modprobe scsi_debug dev_size_mb=16 sector_size=512 num_tgts=1 num_parts=1
DEV="/dev/"$(grep -l -e scsi_debug /sys/block/*/device/model | cut -f4 -d /)"1"
echo "mkfs -t ext4 ${DEV}"
mkfs -t ext4 ${DEV}
sleep 0.1
rmmod scsi_debug

> Bisect tracked it to commit
>    commit cbf67842c3d9e7af8ccc031332b79e88d9cca592
>    Author: Douglas Gilbert <dgilbert@interlog.com>
>    Date:   Sat Jul 26 11:55:35 2014 -0400
>    scsi_debug: support scsi-mq, queues and locks
>
> I guess that with introducing mq the del_timer_sync() must not be called
> with acquired queued_arr_lock.
> (to me it looks like situation described in comment before
> del_timer_sync() in kernel/time/timer.c...)

Looks like something a lawyer would write.

> Here is the log (running on vmware VM and i686 arch):
>
> [   67.916472] scsi_debug: host protection
> [   67.916483] scsi host3: scsi_debug, version 1.84 [20140706], dev_size_mb=16, opts=0x0
> [   67.917446] scsi 3:0:0:0: Direct-Access     Linux    scsi_debug       0184 PQ: 0 ANSI: 5
> [   67.920539] sd 3:0:0:0: Attached scsi generic sg8 type 0
> [   67.940542] sd 3:0:0:0: [sdh] 32768 512-byte logical blocks: (16.7 MB/16.0 MiB)
> [   67.940548] sd 3:0:0:0: [sdh] 4096-byte physical blocks
> [   67.950705] sd 3:0:0:0: [sdh] Write Protect is off
> [   67.950715] sd 3:0:0:0: [sdh] Mode Sense: 73 00 10 08
> [   67.970514] sd 3:0:0:0: [sdh] Write cache: enabled, read cache: enabled, supports DPO and FUA
> [   68.040566]  sdh: unknown partition table
> [   68.090618] sd 3:0:0:0: [sdh] Attached SCSI disk
> [   68.799699]  sdh: unknown partition table
> [   69.072314]
> [   69.072387] ======================================================
> [   69.072433] [ INFO: possible circular locking dependency detected ]
> [   69.072487] 3.17.0-rc2+ #80 Not tainted
> [   69.072518] -------------------------------------------------------
> [   69.072560] rmmod/2890 is trying to acquire lock:
> [   69.072595]  ((sqcp->cmnd_timerp)){+.-...}, at: [<c10846c0>] del_timer_sync+0x0/0xb0
> [   69.072704]
> [   69.072704] but task is already holding lock:
> [   69.072743]  (queued_arr_lock){..-...}, at: [<e1271887>] stop_all_queued+0x17/0xc0 [scsi_debug]
> [   69.072852]
> [   69.072852] which lock already depends on the new lock.
> [   69.072852]

<snip>

> [   69.075321]  Possible unsafe locking scenario:
> [   69.075321]
> [   69.075380]        CPU0                    CPU1
> [   69.075424]        ----                    ----
> [   69.075468]   lock(queued_arr_lock);
> [   69.075534]                                lock((sqcp->cmnd_timerp));
> [   69.075613]                                lock(queued_arr_lock);
> [   69.075690]   lock((sqcp->cmnd_timerp));
> [   69.075758]
> [   69.075758]  *** DEADLOCK ***

Interesting analysis, somewhat confusing because cmnd_timerp
is a pointer. Also my guess is the sqcp pointers in the
two threads were different.

Anyway the attached patch removes the lock(queued_arr_lock)
from around the del_timer calls. Could you try it and report
back.

Doug Gilbert