Re: possible circular locking dependency detected [was: linux-next: Tree for Aug 22]

Bart Van Assche
2017-08-22T21:43:56Z

On Tue, 2017-08-22 at 19:47 +0900, Sergey Senozhatsky wrote:
> ======================================================
> WARNING: possible circular locking dependency detected
> 4.13.0-rc6-next-20170822-dbg-00020-g39758ed8aae0-dirty #1746 Not tainted
> ------------------------------------------------------
> fsck.ext4/148 is trying to acquire lock:
> (&bdev->bd_mutex){+.+.}, at: [<ffffffff8116e73e>] __blkdev_put+0x33/0x190
>
> but now in release context of a crosslock acquired at the following:
> ((complete)&wait#2){+.+.}, at: [<ffffffff812159e0>] blk_execute_rq+0xbb/0xda
>
> which lock already depends on the new lock.
>
> the existing dependency chain (in reverse order) is:
>
> -> #1 ((complete)&wait#2){+.+.}:
> lock_acquire+0x176/0x19e
> __wait_for_common+0x50/0x1e3
> blk_execute_rq+0xbb/0xda
> scsi_execute+0xc3/0x17d [scsi_mod]
> sd_revalidate_disk+0x112/0x1549 [sd_mod]
> rescan_partitions+0x48/0x2c4
> __blkdev_get+0x14b/0x37c
> blkdev_get+0x191/0x2c0
> device_add_disk+0x2b4/0x3e5
> sd_probe_async+0xf8/0x17e [sd_mod]
> async_run_entry_fn+0x34/0xe0
> process_one_work+0x2af/0x4d1
> worker_thread+0x19a/0x24f
> kthread+0x133/0x13b
> ret_from_fork+0x27/0x40
>
> -> #0 (&bdev->bd_mutex){+.+.}:
> __blkdev_put+0x33/0x190
> blkdev_close+0x24/0x27
> __fput+0xee/0x18a
> task_work_run+0x79/0xa0
> prepare_exit_to_usermode+0x9b/0xb5
>
> other info that might help us debug this:
> Possible unsafe locking scenario by crosslock:
> CPU0 CPU1
> ---- ----
> lock(&bdev->bd_mutex);
> lock((complete)&wait#2);
> lock(&bdev->bd_mutex);
> unlock((complete)&wait#2);
>
> *** DEADLOCK ***
> 4 locks held by fsck.ext4/148:
> #0: (&bdev->bd_mutex){+.+.}, at: [<ffffffff8116e73e>] __blkdev_put+0x33/0x190
> #1: (rcu_read_lock){....}, at: [<ffffffff81217f16>] rcu_lock_acquire+0x0/0x20
> #2: (&(&host->lock)->rlock){-.-.}, at: [<ffffffffa00e7550>] ata_scsi_queuecmd+0x23/0x74 [libata]
> #3: (&x->wait#14){-...}, at: [<ffffffff8106b593>] complete+0x18/0x50
>
> stack backtrace:
> CPU: 1 PID: 148 Comm: fsck.ext4 Not tainted 4.13.0-rc6-next-20170822-dbg-00020-g39758ed8aae0-dirty #1746
> Call Trace:
> dump_stack+0x67/0x8e
> print_circular_bug+0x2a1/0x2af
> ? zap_class+0xc5/0xc5
> check_prev_add+0x76/0x20d
> ? __lock_acquire+0xc27/0xcc8
> lock_commit_crosslock+0x327/0x35e
> complete+0x24/0x50
> scsi_end_request+0x8d/0x176 [scsi_mod]
> scsi_io_completion+0x1be/0x423 [scsi_mod]
> __blk_mq_complete_request+0x112/0x131
> ata_scsi_simulate+0x212/0x218 [libata]
> __ata_scsi_queuecmd+0x1be/0x1de [libata]
> ata_scsi_queuecmd+0x41/0x74 [libata]
> scsi_dispatch_cmd+0x194/0x2af [scsi_mod]
> scsi_queue_rq+0x1e0/0x26f [scsi_mod]
> blk_mq_dispatch_rq_list+0x193/0x2a7
> ? _raw_spin_unlock+0x2e/0x40
> blk_mq_sched_dispatch_requests+0x132/0x176
> __blk_mq_run_hw_queue+0x59/0xc5
> __blk_mq_delay_run_hw_queue+0x5f/0xc1
> blk_mq_flush_plug_list+0xfc/0x10b
> blk_flush_plug_list+0xc6/0x1eb
> blk_finish_plug+0x25/0x32
> generic_writepages+0x56/0x63
> do_writepages+0x36/0x70
> __filemap_fdatawrite_range+0x59/0x5f
> filemap_write_and_wait+0x19/0x4f
> __blkdev_put+0x5f/0x190
> blkdev_close+0x24/0x27
> __fput+0xee/0x18a
> task_work_run+0x79/0xa0
> prepare_exit_to_usermode+0x9b/0xb5
> entry_SYSCALL_64_fastpath+0xab/0xad

Byungchul, did you add the crosslock checks to lockdep? Can you have a look at
the above report? That report namely doesn't make sense to me.

Bart.