Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]

Groups > linux.kernel > #1593449 > unrolled thread

Re: [bdi_unregister] 165a5e22fa INFO: task swapper:1 blocked for more than 120 seconds.

Back to article view | Back to linux.kernel

This discussion starts older than the indexed window; earlier articles aren't shown. The article labeled Started by below is the oldest one visible, not the original post.

Contents

  Re: [bdi_unregister] 165a5e22fa INFO: task swapper:1 blocked for  more than 120 seconds. James Bottomley <jejb@linux.vnet.ibm.com> - 2017-03-06 15:50 +0100
    Re: [bdi_unregister] 165a5e22fa INFO: task swapper:1 blocked for  more than 120 seconds. Jan Kara <jack@suse.cz> - 2017-03-06 16:30 +0100
      Re: [bdi_unregister] 165a5e22fa INFO: task swapper:1 blocked for  more than 120 seconds. Jan Kara <jack@suse.cz> - 2017-03-06 17:20 +0100
        Re: [bdi_unregister] 165a5e22fa INFO: task swapper:1 blocked for  more than 120 seconds. James Bottomley <jejb@linux.vnet.ibm.com> - 2017-03-06 20:50 +0100
          Re: [bdi_unregister] 165a5e22fa INFO: task swapper:1 blocked for  more than 120 seconds. Jan Kara <jack@suse.cz> - 2017-03-07 15:50 +0100
            Re: [bdi_unregister] 165a5e22fa INFO: task swapper:1 blocked for  more than 120 seconds. James Bottomley <jejb@linux.vnet.ibm.com> - 2017-03-07 19:20 +0100
              Re: [bdi_unregister] 165a5e22fa INFO: task swapper:1 blocked for  more than 120 seconds. Jan Kara <jack@suse.cz> - 2017-03-07 21:30 +0100
                Re: [bdi_unregister] 165a5e22fa INFO: task swapper:1 blocked for  more than 120 seconds. Jan Kara <jack@suse.cz> - 2017-03-08 11:00 +0100
      Re: [bdi_unregister] 165a5e22fa INFO: task swapper:1 blocked for  more than 120 seconds. James Bottomley <jejb@linux.vnet.ibm.com> - 2017-03-06 20:30 +0100

#1593449 — Re: [bdi_unregister] 165a5e22fa INFO: task swapper:1 blocked for more than 120 seconds.

On Mon, 2017-03-06 at 13:01 +0100, Jan Kara wrote:
> On Mon 06-03-17 11:27:33, Jan Kara wrote:
> > Hi,
> > 
> > On Sun 05-03-17 10:21:11, Wu Fengguang wrote:
> > > FYI next-20170303 is good while mainline is bad with this error.
> > > The attached reproduce-* may help reproduce the issue.
> > 
> > Thanks for report! So from the stacktrace we are in the path 
> > testing removal of a device immediately after it has been probed 
> > and for some reason bdi_unregister() hangs - likely waiting for 
> > cgroup-writeback references to drop. Given how early this happens 
> > my guess is we fail to initialize something but for now I don't see 
> > how my patch could make a difference. I'm trying to reproduce this 
> > to be able to debug more...
> 
> OK, so after some debugging I think this is yet another problem in 
> SCSI initialization / destruction code which my patch only makes 
> visible (added relevant maintainers).
> 
> I can reproduce the problem reliably with enabling:
> 
> CONFIG_DEBUG_TEST_DRIVER_REMOVE=y
> CONFIG_SCSI_DEBUG=m
> CONFIG_BLK_CGROUP=y
> CONFIG_MEMCG=y
> (and thus CONFIG_CGROUP_WRITEBACK=y)
> 
> then 'modprobe scsi_debug' is all it takes to reproduce hang. 
> Relevant kernel messages with some of my debugging added (attached is 
> a patch that adds those debug messages):

This looks to be precisely the same problem Dan Williams was debugging
for us.

> [   58.721765] scsi host0: scsi_debug: version 1.86 [20160430]
> [   58.721765]   dev_size_mb=8, opts=0x0, submit_queues=1,
> statistics=0
> [   58.728946] CGWB init ffff88007fbb2000
> [   58.730095] Created sdev ffff880078e1a000
> [   58.731611] scsi 0:0:0:0: Direct-Access     Linux    scsi_debug
> 0186 PQ : 0 ANSI: 7
> [   58.782246] sd 0:0:0:0: [sda] 16384 512-byte logical blocks: (8.39
> MB/8.00 MiB)
> [   58.789687] sd 0:0:0:0: [sda] Write Protect is off
> [   58.791140] sd 0:0:0:0: [sda] Mode Sense: 73 00 10 08
> [   58.800879] sd 0:0:0:0: [sda] Write cache: enabled, read cache:
> enabled, supports DPO and FUA
> [   58.893738] sd 0:0:0:0: [sda] Attached SCSI disk
> [   58.896808] Unreg1
> [   58.897960] Unreg2
> [   58.898637] Unreg3
> [   58.899100] CGWB ffff88007fbb2000 usage_cnt: 0
> [   58.900004] Unreg4
> [   58.904976] sd 0:0:0:0: [sda] Synchronizing SCSI cache

OK, can you put a WARN_ON trace in sd_shutdown and tell us where this
is coming from.  For the device to be reused after this we have to be
calling sd_shutdown() without going into SDEV_DEL.

Thanks,

James

[toc] | [next] | [standalone]

#1593476

On Mon 06-03-17 06:35:21, James Bottomley wrote:
> On Mon, 2017-03-06 at 13:01 +0100, Jan Kara wrote:
> > On Mon 06-03-17 11:27:33, Jan Kara wrote:
> > > Hi,
> > > 
> > > On Sun 05-03-17 10:21:11, Wu Fengguang wrote:
> > > > FYI next-20170303 is good while mainline is bad with this error.
> > > > The attached reproduce-* may help reproduce the issue.
> > > 
> > > Thanks for report! So from the stacktrace we are in the path 
> > > testing removal of a device immediately after it has been probed 
> > > and for some reason bdi_unregister() hangs - likely waiting for 
> > > cgroup-writeback references to drop. Given how early this happens 
> > > my guess is we fail to initialize something but for now I don't see 
> > > how my patch could make a difference. I'm trying to reproduce this 
> > > to be able to debug more...
> > 
> > OK, so after some debugging I think this is yet another problem in 
> > SCSI initialization / destruction code which my patch only makes 
> > visible (added relevant maintainers).
> > 
> > I can reproduce the problem reliably with enabling:
> > 
> > CONFIG_DEBUG_TEST_DRIVER_REMOVE=y
> > CONFIG_SCSI_DEBUG=m
> > CONFIG_BLK_CGROUP=y
> > CONFIG_MEMCG=y
> > (and thus CONFIG_CGROUP_WRITEBACK=y)
> > 
> > then 'modprobe scsi_debug' is all it takes to reproduce hang. 
> > Relevant kernel messages with some of my debugging added (attached is 
> > a patch that adds those debug messages):
> 
> This looks to be precisely the same problem Dan Williams was debugging
> for us.
> 
> > [   58.721765] scsi host0: scsi_debug: version 1.86 [20160430]
> > [   58.721765]   dev_size_mb=8, opts=0x0, submit_queues=1,
> > statistics=0
> > [   58.728946] CGWB init ffff88007fbb2000
> > [   58.730095] Created sdev ffff880078e1a000
> > [   58.731611] scsi 0:0:0:0: Direct-Access     Linux    scsi_debug
> > 0186 PQ : 0 ANSI: 7
> > [   58.782246] sd 0:0:0:0: [sda] 16384 512-byte logical blocks: (8.39
> > MB/8.00 MiB)
> > [   58.789687] sd 0:0:0:0: [sda] Write Protect is off
> > [   58.791140] sd 0:0:0:0: [sda] Mode Sense: 73 00 10 08
> > [   58.800879] sd 0:0:0:0: [sda] Write cache: enabled, read cache:
> > enabled, supports DPO and FUA
> > [   58.893738] sd 0:0:0:0: [sda] Attached SCSI disk
> > [   58.896808] Unreg1
> > [   58.897960] Unreg2
> > [   58.898637] Unreg3
> > [   58.899100] CGWB ffff88007fbb2000 usage_cnt: 0
> > [   58.900004] Unreg4
> > [   58.904976] sd 0:0:0:0: [sda] Synchronizing SCSI cache
> 
> OK, can you put a WARN_ON trace in sd_shutdown and tell us where this
> is coming from.  For the device to be reused after this we have to be
> calling sd_shutdown() without going into SDEV_DEL.

Sure. The call trace is:

[   41.919244] ------------[ cut here ]------------
[   41.919263] WARNING: CPU: 4 PID: 2335 at drivers/scsi/sd.c:3332 sd_shutdown+0x2f/0x100
[   41.919268] Modules linked in: scsi_debug(+) netconsole loop btrfs raid6_pq zlib_deflate lzo_compress xor
[   41.919319] CPU: 4 PID: 2335 Comm: modprobe Not tainted 4.11.0-rc1-xen+ #49
[   41.919325] Hardware name: Bochs Bochs, BIOS Bochs 01/01/2011
[   41.919331] Call Trace:
[   41.919343]  dump_stack+0x8e/0xf0
[   41.919354]  __warn+0x116/0x120
[   41.919361]  warn_slowpath_null+0x1d/0x20
[   41.919368]  sd_shutdown+0x2f/0x100
[   41.919374]  sd_remove+0x70/0xd0

*** Here is the unexpected step I guess...

[   41.919383]  driver_probe_device+0xe0/0x4c0
[   41.919395]  ? kobject_uevent_env+0x1bc/0x660
[   41.919403]  __device_attach_driver+0xfa/0x120
[   41.919410]  ? __driver_attach+0x110/0x110
[   41.919417]  bus_for_each_drv+0x68/0x90
[   41.919424]  __device_attach+0xb2/0x110
[   41.919432]  device_initial_probe+0x13/0x20
[   41.919439]  bus_probe_device+0xa8/0xc0
[   41.919446]  device_add+0x297/0x600
[   41.919453]  ? call_rcu_bh+0x20/0x20
[   41.919463]  ? mutex_unlock+0x12/0x20
[   41.919473]  scsi_sysfs_add_sdev+0x69/0x210
[   41.919480]  scsi_probe_and_add_lun+0xcfd/0xd10
[   41.919489]  ? find_next_zero_bit+0x10/0x20
[   41.919496]  __scsi_scan_target+0xd2/0x4c0
[   41.919506]  ? proc_register+0x41/0x130
[   41.919512]  ? proc_register+0x11c/0x130
[   41.919520]  ? trace_hardirqs_on+0xd/0x10
[   41.919527]  ? _raw_spin_unlock_irq+0x30/0x50
[   41.919534]  scsi_scan_channel+0x5f/0xa0
[   41.919541]  scsi_scan_host_selected+0xb9/0x120
[   41.919549]  do_scsi_scan_host+0x81/0x90
[   41.919555]  scsi_scan_host+0x17a/0x1b0
[   41.919568]  ? scsi_add_host_with_dma+0x302/0x310
[   41.919593]  sdebug_driver_probe+0x204/0x320 [scsi_debug]
[   41.919601]  ? driver_sysfs_add+0x90/0xb0
[   41.919608]  driver_probe_device+0xb3/0x4c0
[   41.919615]  ? kobject_uevent_env+0x1bc/0x660
[   41.919623]  __device_attach_driver+0xfa/0x120
[   41.919630]  ? __driver_attach+0x110/0x110
[   41.919636]  bus_for_each_drv+0x68/0x90
[   41.919643]  __device_attach+0xb2/0x110
[   41.919651]  device_initial_probe+0x13/0x20
[   41.919658]  bus_probe_device+0xa8/0xc0
[   41.919664]  device_add+0x297/0x600
[   41.919671]  ? dev_set_name+0x41/0x50
[   41.919681]  device_register+0x1e/0x30
[   41.919696]  sdebug_add_adapter+0xff/0x1d0 [scsi_debug]
[   41.919703]  ? kobject_uevent+0xb/0x10
[   41.919709]  ? 0xffffffffa0172000
[   41.919723]  scsi_debug_init+0x40e/0x1000 [scsi_debug]
[   41.919730]  ? 0xffffffffa0172000
[   41.919739]  do_one_initcall+0xbe/0x200

								Honza

-- 
Jan Kara <jack@suse.com>
SUSE Labs, CR

[toc] | [prev] | [next] | [standalone]

#1593507

On Mon 06-03-17 07:44:55, James Bottomley wrote:
> On Mon, 2017-03-06 at 16:14 +0100, Jan Kara wrote:
> > On Mon 06-03-17 06:35:21, James Bottomley wrote:
> > > On Mon, 2017-03-06 at 13:01 +0100, Jan Kara wrote:
> > > > On Mon 06-03-17 11:27:33, Jan Kara wrote:
> > > > > Hi,
> > > > > 
> > > > > On Sun 05-03-17 10:21:11, Wu Fengguang wrote:
> > > > > > FYI next-20170303 is good while mainline is bad with this
> > > > > > error.
> > > > > > The attached reproduce-* may help reproduce the issue.
> > > > > 
> > > > > Thanks for report! So from the stacktrace we are in the path 
> > > > > testing removal of a device immediately after it has been
> > > > > probed 
> > > > > and for some reason bdi_unregister() hangs - likely waiting for
> > > > > cgroup-writeback references to drop. Given how early this
> > > > > happens 
> > > > > my guess is we fail to initialize something but for now I don't
> > > > > see 
> > > > > how my patch could make a difference. I'm trying to reproduce
> > > > > this 
> > > > > to be able to debug more...
> > > > 
> > > > OK, so after some debugging I think this is yet another problem
> > > > in 
> > > > SCSI initialization / destruction code which my patch only makes 
> > > > visible (added relevant maintainers).
> > > > 
> > > > I can reproduce the problem reliably with enabling:
> > > > 
> > > > CONFIG_DEBUG_TEST_DRIVER_REMOVE=y
> > > > CONFIG_SCSI_DEBUG=m
> > > > CONFIG_BLK_CGROUP=y
> > > > CONFIG_MEMCG=y
> > > > (and thus CONFIG_CGROUP_WRITEBACK=y)
> > > > 
> > > > then 'modprobe scsi_debug' is all it takes to reproduce hang. 
> > > > Relevant kernel messages with some of my debugging added
> > > > (attached is 
> > > > a patch that adds those debug messages):
> > > 
> > > This looks to be precisely the same problem Dan Williams was
> > > debugging
> > > for us.
> > > 
> > > > [   58.721765] scsi host0: scsi_debug: version 1.86 [20160430]
> > > > [   58.721765]   dev_size_mb=8, opts=0x0, submit_queues=1,
> > > > statistics=0
> > > > [   58.728946] CGWB init ffff88007fbb2000
> > > > [   58.730095] Created sdev ffff880078e1a000
> > > > [   58.731611] scsi 0:0:0:0: Direct-Access     Linux   
> > > >  scsi_debug
> > > > 0186 PQ : 0 ANSI: 7
> > > > [   58.782246] sd 0:0:0:0: [sda] 16384 512-byte logical blocks:
> > > > (8.39
> > > > MB/8.00 MiB)
> > > > [   58.789687] sd 0:0:0:0: [sda] Write Protect is off
> > > > [   58.791140] sd 0:0:0:0: [sda] Mode Sense: 73 00 10 08
> > > > [   58.800879] sd 0:0:0:0: [sda] Write cache: enabled, read
> > > > cache:
> > > > enabled, supports DPO and FUA
> > > > [   58.893738] sd 0:0:0:0: [sda] Attached SCSI disk
> > > > [   58.896808] Unreg1
> > > > [   58.897960] Unreg2
> > > > [   58.898637] Unreg3
> > > > [   58.899100] CGWB ffff88007fbb2000 usage_cnt: 0
> > > > [   58.900004] Unreg4
> > > > [   58.904976] sd 0:0:0:0: [sda] Synchronizing SCSI cache
> > > 
> > > OK, can you put a WARN_ON trace in sd_shutdown and tell us where
> > > this
> > > is coming from.  For the device to be reused after this we have to
> > > be
> > > calling sd_shutdown() without going into SDEV_DEL.
> > 
> > Sure. The call trace is:
> > 
> > [   41.919244] ------------[ cut here ]------------
> > [   41.919263] WARNING: CPU: 4 PID: 2335 at drivers/scsi/sd.c:3332
> > sd_shutdown+0x2f/0x100
> > [   41.919268] Modules linked in: scsi_debug(+) netconsole loop btrfs
> > raid6_pq zlib_deflate lzo_compress xor
> > [   41.919319] CPU: 4 PID: 2335 Comm: modprobe Not tainted 4.11.0-rc1
> > -xen+ #49
> > [   41.919325] Hardware name: Bochs Bochs, BIOS Bochs 01/01/2011
> > [   41.919331] Call Trace:
> > [   41.919343]  dump_stack+0x8e/0xf0
> > [   41.919354]  __warn+0x116/0x120
> > [   41.919361]  warn_slowpath_null+0x1d/0x20
> > [   41.919368]  sd_shutdown+0x2f/0x100
> > [   41.919374]  sd_remove+0x70/0xd0
> > 
> > *** Here is the unexpected step I guess...
> > 
> > [   41.919383]  driver_probe_device+0xe0/0x4c0
> 
> Exactly.  It's this, I think
> 
> 	bool test_remove = IS_ENABLED(CONFIG_DEBUG_TEST_DRIVER_REMOVE) &&
> 			   !drv->suppress_bind_attrs;
> 
> You have that config option set.

Yes - or better said 0-day testing has it set. Maybe that is not a sane
default for 0-day tests? The option is explicitely marked as "unstable"...
Fengguang?

> So the drivers base layer is calling ->remove after probe and
> triggering the destruction of the queue.
> 
> What to do about this (apart from nuke such a stupid option) is
> somewhat more problematic.

I guess this is between you and Greg :).

								Honza
-- 
Jan Kara <jack@suse.com>
SUSE Labs, CR

[toc] | [prev] | [next] | [standalone]

#1593666

On Mon, 2017-03-06 at 17:13 +0100, Jan Kara wrote:
> On Mon 06-03-17 07:44:55, James Bottomley wrote:
> > On Mon, 2017-03-06 at 16:14 +0100, Jan Kara wrote:
> > > On Mon 06-03-17 06:35:21, James Bottomley wrote:
> > > > On Mon, 2017-03-06 at 13:01 +0100, Jan Kara wrote:
> > > > > On Mon 06-03-17 11:27:33, Jan Kara wrote:
> > > > > > Hi,
> > > > > > 
> > > > > > On Sun 05-03-17 10:21:11, Wu Fengguang wrote:
> > > > > > > FYI next-20170303 is good while mainline is bad with this
> > > > > > > error.
> > > > > > > The attached reproduce-* may help reproduce the issue.
> > > > > > 
> > > > > > Thanks for report! So from the stacktrace we are in the
> > > > > > path 
> > > > > > testing removal of a device immediately after it has been
> > > > > > probed 
> > > > > > and for some reason bdi_unregister() hangs - likely waiting
> > > > > > for
> > > > > > cgroup-writeback references to drop. Given how early this
> > > > > > happens 
> > > > > > my guess is we fail to initialize something but for now I
> > > > > > don't
> > > > > > see 
> > > > > > how my patch could make a difference. I'm trying to
> > > > > > reproduce
> > > > > > this 
> > > > > > to be able to debug more...
> > > > > 
> > > > > OK, so after some debugging I think this is yet another
> > > > > problem
> > > > > in 
> > > > > SCSI initialization / destruction code which my patch only
> > > > > makes 
> > > > > visible (added relevant maintainers).
> > > > > 
> > > > > I can reproduce the problem reliably with enabling:
> > > > > 
> > > > > CONFIG_DEBUG_TEST_DRIVER_REMOVE=y
> > > > > CONFIG_SCSI_DEBUG=m
> > > > > CONFIG_BLK_CGROUP=y
> > > > > CONFIG_MEMCG=y
> > > > > (and thus CONFIG_CGROUP_WRITEBACK=y)
> > > > > 
> > > > > then 'modprobe scsi_debug' is all it takes to reproduce hang.
> > > > > Relevant kernel messages with some of my debugging added
> > > > > (attached is 
> > > > > a patch that adds those debug messages):
> > > > 
> > > > This looks to be precisely the same problem Dan Williams was
> > > > debugging
> > > > for us.
> > > > 
> > > > > [   58.721765] scsi host0: scsi_debug: version 1.86
> > > > > [20160430]
> > > > > [   58.721765]   dev_size_mb=8, opts=0x0, submit_queues=1,
> > > > > statistics=0
> > > > > [   58.728946] CGWB init ffff88007fbb2000
> > > > > [   58.730095] Created sdev ffff880078e1a000
> > > > > [   58.731611] scsi 0:0:0:0: Direct-Access     Linux   
> > > > >  scsi_debug
> > > > > 0186 PQ : 0 ANSI: 7
> > > > > [   58.782246] sd 0:0:0:0: [sda] 16384 512-byte logical
> > > > > blocks:
> > > > > (8.39
> > > > > MB/8.00 MiB)
> > > > > [   58.789687] sd 0:0:0:0: [sda] Write Protect is off
> > > > > [   58.791140] sd 0:0:0:0: [sda] Mode Sense: 73 00 10 08
> > > > > [   58.800879] sd 0:0:0:0: [sda] Write cache: enabled, read
> > > > > cache:
> > > > > enabled, supports DPO and FUA
> > > > > [   58.893738] sd 0:0:0:0: [sda] Attached SCSI disk
> > > > > [   58.896808] Unreg1
> > > > > [   58.897960] Unreg2
> > > > > [   58.898637] Unreg3
> > > > > [   58.899100] CGWB ffff88007fbb2000 usage_cnt: 0
> > > > > [   58.900004] Unreg4
> > > > > [   58.904976] sd 0:0:0:0: [sda] Synchronizing SCSI cache
> > > > 
> > > > OK, can you put a WARN_ON trace in sd_shutdown and tell us
> > > > where
> > > > this
> > > > is coming from.  For the device to be reused after this we have
> > > > to
> > > > be
> > > > calling sd_shutdown() without going into SDEV_DEL.
> > > 
> > > Sure. The call trace is:
> > > 
> > > [   41.919244] ------------[ cut here ]------------
> > > [   41.919263] WARNING: CPU: 4 PID: 2335 at
> > > drivers/scsi/sd.c:3332
> > > sd_shutdown+0x2f/0x100
> > > [   41.919268] Modules linked in: scsi_debug(+) netconsole loop
> > > btrfs
> > > raid6_pq zlib_deflate lzo_compress xor
> > > [   41.919319] CPU: 4 PID: 2335 Comm: modprobe Not tainted 4.11.0
> > > -rc1
> > > -xen+ #49
> > > [   41.919325] Hardware name: Bochs Bochs, BIOS Bochs 01/01/2011
> > > [   41.919331] Call Trace:
> > > [   41.919343]  dump_stack+0x8e/0xf0
> > > [   41.919354]  __warn+0x116/0x120
> > > [   41.919361]  warn_slowpath_null+0x1d/0x20
> > > [   41.919368]  sd_shutdown+0x2f/0x100
> > > [   41.919374]  sd_remove+0x70/0xd0
> > > 
> > > *** Here is the unexpected step I guess...
> > > 
> > > [   41.919383]  driver_probe_device+0xe0/0x4c0
> > 
> > Exactly.  It's this, I think
> > 
> > 	bool test_remove = IS_ENABLED(CONFIG_DEBUG_TEST_DRIVER_REMOVE)
> > &&
> > 			   !drv->suppress_bind_attrs;
> > 
> > You have that config option set.
> 
> Yes - or better said 0-day testing has it set. Maybe that is not a 
> sane default for 0-day tests? The option is explicitely marked as
> "unstable"... Fengguang?
> 
> > So the drivers base layer is calling ->remove after probe and
> > triggering the destruction of the queue.
> > 
> > What to do about this (apart from nuke such a stupid option) is
> > somewhat more problematic.
> 
> I guess this is between you and Greg :).

Nice try, sport ... you qualify just behind Dan in the "not my problem"
olympic hurdles event.  I'm annoyed because there's no indication in
the log that the driver add behaviour is radically altered, so I've
been staring at the wrong code for weeks.  However, the unbind/rebind
should work, so the real issue is that your bdi changes (or perhaps
something else in block) have induced a regression in the unbinding of
upper layer drivers.  If you're going to release the bdi in
del_gendisk, you have to have some mechanism for re-acquiring it on re
-probe (likely with the same name) otherwise rebind is broken for every
block driver.

The fact that the second rebind tried with a different name indicates
that sd_devt_release wasn't called, so some vestige of the devt remains
on the subsequent rebind.  Here's the problem: the queue belongs to
SCSI (the lower layer), so it's not going to change because it doesn't
see the release.  The gendisk and its allied stuff belongs to sd so it
gets freed and re-created for the same queue.  Something in block is
very confused when this happens.

James

[toc] | [prev] | [next] | [standalone]

#1594306

On Mon 06-03-17 09:25:42, James Bottomley wrote:
> On Mon, 2017-03-06 at 17:13 +0100, Jan Kara wrote:
> > On Mon 06-03-17 07:44:55, James Bottomley wrote:
...
> > > > Sure. The call trace is:
> > > > 
> > > > [   41.919244] ------------[ cut here ]------------
> > > > [   41.919263] WARNING: CPU: 4 PID: 2335 at
> > > > drivers/scsi/sd.c:3332
> > > > sd_shutdown+0x2f/0x100
> > > > [   41.919268] Modules linked in: scsi_debug(+) netconsole loop
> > > > btrfs
> > > > raid6_pq zlib_deflate lzo_compress xor
> > > > [   41.919319] CPU: 4 PID: 2335 Comm: modprobe Not tainted 4.11.0
> > > > -rc1
> > > > -xen+ #49
> > > > [   41.919325] Hardware name: Bochs Bochs, BIOS Bochs 01/01/2011
> > > > [   41.919331] Call Trace:
> > > > [   41.919343]  dump_stack+0x8e/0xf0
> > > > [   41.919354]  __warn+0x116/0x120
> > > > [   41.919361]  warn_slowpath_null+0x1d/0x20
> > > > [   41.919368]  sd_shutdown+0x2f/0x100
> > > > [   41.919374]  sd_remove+0x70/0xd0
> > > > 
> > > > *** Here is the unexpected step I guess...
> > > > 
> > > > [   41.919383]  driver_probe_device+0xe0/0x4c0
> > > 
> > > Exactly.  It's this, I think
> > > 
> > > 	bool test_remove = IS_ENABLED(CONFIG_DEBUG_TEST_DRIVER_REMOVE)
> > > &&
> > > 			   !drv->suppress_bind_attrs;
> > > 
> > > You have that config option set.
> > 
> > Yes - or better said 0-day testing has it set. Maybe that is not a 
> > sane default for 0-day tests? The option is explicitely marked as
> > "unstable"... Fengguang?
> > 
> > > So the drivers base layer is calling ->remove after probe and
> > > triggering the destruction of the queue.
> > > 
> > > What to do about this (apart from nuke such a stupid option) is
> > > somewhat more problematic.
> > 
> > I guess this is between you and Greg :).
> 
> Nice try, sport ... you qualify just behind Dan in the "not my problem"
> olympic hurdles event.  I'm annoyed because there's no indication in
> the log that the driver add behaviour is radically altered, so I've
> been staring at the wrong code for weeks.  However, the unbind/rebind
> should work, so the real issue is that your bdi changes (or perhaps
> something else in block) have induced a regression in the unbinding of
> upper layer drivers.  If you're going to release the bdi in
> del_gendisk, you have to have some mechanism for re-acquiring it on re
> -probe (likely with the same name) otherwise rebind is broken for every
> block driver.

So my patch does not release bdi in del_gendisk(). Bdi has two
initialization / destruction phases (similarly to request queue). You
allocate and initialize bdi through bdi_init(), then you call
bdi_register() to register it (which happens in device_add_disk()). On
shutdown you have to first call bdi_unregister() (used to be called from
blk_cleanup_queue(), my patch moved it to del_gendisk()). After that the
last reference to bdi may be dropped which does final bdi destruction.

So do I understand correctly that SCSI may call device_add_disk(),
del_gendisk() repeatedly for the same request queue? If yes, then indeed I
have a bug to fix... But gendisk seems to get allocated from scratch on
each probe so we don't call device_add_disk(), del_gendisk() more times on
the same disk, right?

> The fact that the second rebind tried with a different name indicates
> that sd_devt_release wasn't called, so some vestige of the devt remains
> on the subsequent rebind.

Yep, I guess that's caused by Dan's patch (commit 0dba1314d4f8 now) which
calls put_disk_devt() only in blk_cleanup_queue() which, if I understood
you correctly, does not get called during unbind-bind cycle? In fact Dan's
patch would end up leaking devt's because of repeated device_add_disk()
calls for the same request queue...

> Here's the problem: the queue belongs to SCSI (the lower layer), so it's
> not going to change because it doesn't see the release.  The gendisk and
> its allied stuff belongs to sd so it gets freed and re-created for the
> same queue.  Something in block is very confused when this happens.

Yep, I think the binding of request queue to different gendisks is
something I or Dan did not expect.

								Honza
-- 
Jan Kara <jack@suse.com>
SUSE Labs, CR

[toc] | [prev] | [next] | [standalone]

#1594487

On Tue, 2017-03-07 at 15:41 +0100, Jan Kara wrote:
> On Mon 06-03-17 09:25:42, James Bottomley wrote:
> > On Mon, 2017-03-06 at 17:13 +0100, Jan Kara wrote:
> > > On Mon 06-03-17 07:44:55, James Bottomley wrote:
> ...
> > > > > Sure. The call trace is:
> > > > > 
> > > > > [   41.919244] ------------[ cut here ]------------
> > > > > [   41.919263] WARNING: CPU: 4 PID: 2335 at
> > > > > drivers/scsi/sd.c:3332
> > > > > sd_shutdown+0x2f/0x100
> > > > > [   41.919268] Modules linked in: scsi_debug(+) netconsole 
> > > > > loop btrfs raid6_pq zlib_deflate lzo_compress xor
> > > > > [   41.919319] CPU: 4 PID: 2335 Comm: modprobe Not tainted 
> > > > > 4.11.0-rc1-xen+ #49
> > > > > [   41.919325] Hardware name: Bochs Bochs, BIOS Bochs
> > > > > 01/01/2011
> > > > > [   41.919331] Call Trace:
> > > > > [   41.919343]  dump_stack+0x8e/0xf0
> > > > > [   41.919354]  __warn+0x116/0x120
> > > > > [   41.919361]  warn_slowpath_null+0x1d/0x20
> > > > > [   41.919368]  sd_shutdown+0x2f/0x100
> > > > > [   41.919374]  sd_remove+0x70/0xd0
> > > > > 
> > > > > *** Here is the unexpected step I guess...
> > > > > 
> > > > > [   41.919383]  driver_probe_device+0xe0/0x4c0
> > > > 
> > > > Exactly.  It's this, I think
> > > > 
> > > > 	bool test_remove =
> > > > IS_ENABLED(CONFIG_DEBUG_TEST_DRIVER_REMOVE)
> > > > &&
> > > > 			   !drv->suppress_bind_attrs;
> > > > 
> > > > You have that config option set.
> > > 
> > > Yes - or better said 0-day testing has it set. Maybe that is not 
> > > a sane default for 0-day tests? The option is explicitely marked 
> > > as "unstable"... Fengguang?
> > > 
> > > > So the drivers base layer is calling ->remove after probe and
> > > > triggering the destruction of the queue.
> > > > 
> > > > What to do about this (apart from nuke such a stupid option) is
> > > > somewhat more problematic.
> > > 
> > > I guess this is between you and Greg :).
> > 
> > Nice try, sport ... you qualify just behind Dan in the "not my 
> > problem" olympic hurdles event.  I'm annoyed because there's no 
> > indication in the log that the driver add behaviour is radically 
> > altered, so I've been staring at the wrong code for weeks. 
> >  However, the unbind/rebind should work, so the real issue is that 
> > your bdi changes (or perhaps something else in block) have induced 
> > a regression in the unbinding of upper layer drivers.  If you're 
> > going to release the bdi in del_gendisk, you have to have some 
> > mechanism for re-acquiring it on re-probe (likely with the same 
> > name) otherwise rebind is broken for every block driver.
> 
> So my patch does not release bdi in del_gendisk(). Bdi has two
> initialization / destruction phases (similarly to request queue). You
> allocate and initialize bdi through bdi_init(), then you call
> bdi_register() to register it (which happens in device_add_disk()). 
> On shutdown you have to first call bdi_unregister() (used to be 
> called from blk_cleanup_queue(), my patch moved it to del_gendisk()). 
> After that the last reference to bdi may be dropped which does final 
> bdi destruction.
> 
> So do I understand correctly that SCSI may call device_add_disk(),
> del_gendisk() repeatedly for the same request queue?

Yes.  The upper drivers (sd, sr, st and sg) follow a device model. 
 They can thus be bound and unbound many times during the lifetime of a
SCSI device.

>  If yes, then indeed I have a bug to fix... But gendisk seems to get 
> allocated from scratch on each probe so we don't call 
> device_add_disk(), del_gendisk() more times on the same disk, right?

Right, gendisk, being a generic representation of a disk is a property
of the upper layer drivers.  We actually cheat and use it in all of
them (including the apparent character ones, they use alloc_disk,
put_disk but not add_disk).  So it has to be freed when the driver is
unbound and reallocated when it is bound.  It's the fundamental entity
which embeds the SCSI upper layer driver lifetime.

> > The fact that the second rebind tried with a different name 
> > indicates that sd_devt_release wasn't called, so some vestige of 
> > the devt remains on the subsequent rebind.
> 
> Yep, I guess that's caused by Dan's patch (commit 0dba1314d4f8 now) 
> which calls put_disk_devt() only in blk_cleanup_queue() which, if I
> understood you correctly, does not get called during unbind-bind 
> cycle? In fact Dan's patch would end up leaking devt's because of 
> repeated device_add_disk() calls for the same request queue...

That's a bit unfortunate.

> > Here's the problem: the queue belongs to SCSI (the lower layer), so 
> > it's not going to change because it doesn't see the release.  The
> > gendisk and its allied stuff belongs to sd so it gets freed and re
> > -created for the same queue.  Something in block is very confused
> > when this happens.
> 
> Yep, I think the binding of request queue to different gendisks is
> something I or Dan did not expect.

OK, so I think we now understand why this is happening ... the question
is what we do about it?  Is it fixable or do we need to go back to
basics?  The fundamental property which got broken by these patches is
the idea of the separation of the lifecycles of the queue and the
gendisk.  The only requirement is that the queue must exist before the
gendisk is created and must be destroyed after it.  This doesn't forbid
there being many gendisk lifetimes over one queue lifetime and this is
what we rely on for the SCSI driver model.  We rarely get called on it
because unbind/rebind of a ULD is rarely done in production (it's
mostly a devtest thing).

James

[toc] | [prev] | [next] | [standalone]

#1594616

On Tue 07-03-17 08:10:29, James Bottomley wrote:
> On Tue, 2017-03-07 at 15:41 +0100, Jan Kara wrote:
> > On Mon 06-03-17 09:25:42, James Bottomley wrote:
> > > On Mon, 2017-03-06 at 17:13 +0100, Jan Kara wrote:
> > > > On Mon 06-03-17 07:44:55, James Bottomley wrote:
> > ...
> > > > > > Sure. The call trace is:
> > > > > > 
> > > > > > [   41.919244] ------------[ cut here ]------------
> > > > > > [   41.919263] WARNING: CPU: 4 PID: 2335 at
> > > > > > drivers/scsi/sd.c:3332
> > > > > > sd_shutdown+0x2f/0x100
> > > > > > [   41.919268] Modules linked in: scsi_debug(+) netconsole 
> > > > > > loop btrfs raid6_pq zlib_deflate lzo_compress xor
> > > > > > [   41.919319] CPU: 4 PID: 2335 Comm: modprobe Not tainted 
> > > > > > 4.11.0-rc1-xen+ #49
> > > > > > [   41.919325] Hardware name: Bochs Bochs, BIOS Bochs
> > > > > > 01/01/2011
> > > > > > [   41.919331] Call Trace:
> > > > > > [   41.919343]  dump_stack+0x8e/0xf0
> > > > > > [   41.919354]  __warn+0x116/0x120
> > > > > > [   41.919361]  warn_slowpath_null+0x1d/0x20
> > > > > > [   41.919368]  sd_shutdown+0x2f/0x100
> > > > > > [   41.919374]  sd_remove+0x70/0xd0
> > > > > > 
> > > > > > *** Here is the unexpected step I guess...
> > > > > > 
> > > > > > [   41.919383]  driver_probe_device+0xe0/0x4c0
> > > > > 
> > > > > Exactly.  It's this, I think
> > > > > 
> > > > > 	bool test_remove =
> > > > > IS_ENABLED(CONFIG_DEBUG_TEST_DRIVER_REMOVE)
> > > > > &&
> > > > > 			   !drv->suppress_bind_attrs;
> > > > > 
> > > > > You have that config option set.
> > > > 
> > > > Yes - or better said 0-day testing has it set. Maybe that is not 
> > > > a sane default for 0-day tests? The option is explicitely marked 
> > > > as "unstable"... Fengguang?
> > > > 
> > > > > So the drivers base layer is calling ->remove after probe and
> > > > > triggering the destruction of the queue.
> > > > > 
> > > > > What to do about this (apart from nuke such a stupid option) is
> > > > > somewhat more problematic.
> > > > 
> > > > I guess this is between you and Greg :).
> > > 
> > > Nice try, sport ... you qualify just behind Dan in the "not my 
> > > problem" olympic hurdles event.  I'm annoyed because there's no 
> > > indication in the log that the driver add behaviour is radically 
> > > altered, so I've been staring at the wrong code for weeks. 
> > >  However, the unbind/rebind should work, so the real issue is that 
> > > your bdi changes (or perhaps something else in block) have induced 
> > > a regression in the unbinding of upper layer drivers.  If you're 
> > > going to release the bdi in del_gendisk, you have to have some 
> > > mechanism for re-acquiring it on re-probe (likely with the same 
> > > name) otherwise rebind is broken for every block driver.
> > 
> > So my patch does not release bdi in del_gendisk(). Bdi has two
> > initialization / destruction phases (similarly to request queue). You
> > allocate and initialize bdi through bdi_init(), then you call
> > bdi_register() to register it (which happens in device_add_disk()). 
> > On shutdown you have to first call bdi_unregister() (used to be 
> > called from blk_cleanup_queue(), my patch moved it to del_gendisk()). 
> > After that the last reference to bdi may be dropped which does final 
> > bdi destruction.
> > 
> > So do I understand correctly that SCSI may call device_add_disk(),
> > del_gendisk() repeatedly for the same request queue?
> 
> Yes.  The upper drivers (sd, sr, st and sg) follow a device model. 
>  They can thus be bound and unbound many times during the lifetime of a
> SCSI device.
> 
> >  If yes, then indeed I have a bug to fix... But gendisk seems to get 
> > allocated from scratch on each probe so we don't call 
> > device_add_disk(), del_gendisk() more times on the same disk, right?
> 
> Right, gendisk, being a generic representation of a disk is a property
> of the upper layer drivers.  We actually cheat and use it in all of
> them (including the apparent character ones, they use alloc_disk,
> put_disk but not add_disk).  So it has to be freed when the driver is
> unbound and reallocated when it is bound.  It's the fundamental entity
> which embeds the SCSI upper layer driver lifetime.
> 
> > > The fact that the second rebind tried with a different name 
> > > indicates that sd_devt_release wasn't called, so some vestige of 
> > > the devt remains on the subsequent rebind.
> > 
> > Yep, I guess that's caused by Dan's patch (commit 0dba1314d4f8 now) 
> > which calls put_disk_devt() only in blk_cleanup_queue() which, if I
> > understood you correctly, does not get called during unbind-bind 
> > cycle? In fact Dan's patch would end up leaking devt's because of 
> > repeated device_add_disk() calls for the same request queue...
> 
> That's a bit unfortunate.
> 
> > > Here's the problem: the queue belongs to SCSI (the lower layer), so 
> > > it's not going to change because it doesn't see the release.  The
> > > gendisk and its allied stuff belongs to sd so it gets freed and re
> > > -created for the same queue.  Something in block is very confused
> > > when this happens.
> > 
> > Yep, I think the binding of request queue to different gendisks is
> > something I or Dan did not expect.
> 
> OK, so I think we now understand why this is happening ... the question
> is what we do about it?  Is it fixable or do we need to go back to
> basics?  The fundamental property which got broken by these patches is
> the idea of the separation of the lifecycles of the queue and the
> gendisk.  The only requirement is that the queue must exist before the
> gendisk is created and must be destroyed after it.  This doesn't forbid
> there being many gendisk lifetimes over one queue lifetime and this is
> what we rely on for the SCSI driver model.  We rarely get called on it
> because unbind/rebind of a ULD is rarely done in production (it's
> mostly a devtest thing).

For now I think it's fixable. Let's see what I'll be able to come up with.
Let me also note that before my patch moving bdi_unregister() to
del_gendisk() (commit 165a5e22fafb), the SCSI driver model was buggy in a
different way - because bdi_unregister() was called only from
blk_cleanup_queue(), we were leaking bdi->owner reference to gendisk by
repeated calls to bdi_register_owner() from device_add_disk() and
thus gendisks were never freed after unbind/bind (I've actually verified
this bug exists with debug messages). Also as a result request queue use
count was steadily increasing with each new gendisk and request queue could
never get freed after unbind / rebind.

My patch silently fixed this leakage but introduced a different set of
problems which I'll try to fix.

								Honza
-- 
Jan Kara <jack@suse.com>
SUSE Labs, CR

[toc] | [prev] | [next] | [standalone]

#1595001

[Multipart message — attachments visible in raw view] — view raw

On Tue 07-03-17 17:26:56, Jan Kara wrote:
> On Tue 07-03-17 08:10:29, James Bottomley wrote:
> > On Tue, 2017-03-07 at 15:41 +0100, Jan Kara wrote:
> > > On Mon 06-03-17 09:25:42, James Bottomley wrote:
> > > > On Mon, 2017-03-06 at 17:13 +0100, Jan Kara wrote:
> > > > > On Mon 06-03-17 07:44:55, James Bottomley wrote:
> > > ...
> > > > > > > Sure. The call trace is:
> > > > > > > 
> > > > > > > [   41.919244] ------------[ cut here ]------------
> > > > > > > [   41.919263] WARNING: CPU: 4 PID: 2335 at
> > > > > > > drivers/scsi/sd.c:3332
> > > > > > > sd_shutdown+0x2f/0x100
> > > > > > > [   41.919268] Modules linked in: scsi_debug(+) netconsole 
> > > > > > > loop btrfs raid6_pq zlib_deflate lzo_compress xor
> > > > > > > [   41.919319] CPU: 4 PID: 2335 Comm: modprobe Not tainted 
> > > > > > > 4.11.0-rc1-xen+ #49
> > > > > > > [   41.919325] Hardware name: Bochs Bochs, BIOS Bochs
> > > > > > > 01/01/2011
> > > > > > > [   41.919331] Call Trace:
> > > > > > > [   41.919343]  dump_stack+0x8e/0xf0
> > > > > > > [   41.919354]  __warn+0x116/0x120
> > > > > > > [   41.919361]  warn_slowpath_null+0x1d/0x20
> > > > > > > [   41.919368]  sd_shutdown+0x2f/0x100
> > > > > > > [   41.919374]  sd_remove+0x70/0xd0
> > > > > > > 
> > > > > > > *** Here is the unexpected step I guess...
> > > > > > > 
> > > > > > > [   41.919383]  driver_probe_device+0xe0/0x4c0
> > > > > > 
> > > > > > Exactly.  It's this, I think
> > > > > > 
> > > > > > 	bool test_remove =
> > > > > > IS_ENABLED(CONFIG_DEBUG_TEST_DRIVER_REMOVE)
> > > > > > &&
> > > > > > 			   !drv->suppress_bind_attrs;
> > > > > > 
> > > > > > You have that config option set.
> > > > > 
> > > > > Yes - or better said 0-day testing has it set. Maybe that is not 
> > > > > a sane default for 0-day tests? The option is explicitely marked 
> > > > > as "unstable"... Fengguang?
> > > > > 
> > > > > > So the drivers base layer is calling ->remove after probe and
> > > > > > triggering the destruction of the queue.
> > > > > > 
> > > > > > What to do about this (apart from nuke such a stupid option) is
> > > > > > somewhat more problematic.
> > > > > 
> > > > > I guess this is between you and Greg :).
> > > > 
> > > > Nice try, sport ... you qualify just behind Dan in the "not my 
> > > > problem" olympic hurdles event.  I'm annoyed because there's no 
> > > > indication in the log that the driver add behaviour is radically 
> > > > altered, so I've been staring at the wrong code for weeks. 
> > > >  However, the unbind/rebind should work, so the real issue is that 
> > > > your bdi changes (or perhaps something else in block) have induced 
> > > > a regression in the unbinding of upper layer drivers.  If you're 
> > > > going to release the bdi in del_gendisk, you have to have some 
> > > > mechanism for re-acquiring it on re-probe (likely with the same 
> > > > name) otherwise rebind is broken for every block driver.
> > > 
> > > So my patch does not release bdi in del_gendisk(). Bdi has two
> > > initialization / destruction phases (similarly to request queue). You
> > > allocate and initialize bdi through bdi_init(), then you call
> > > bdi_register() to register it (which happens in device_add_disk()). 
> > > On shutdown you have to first call bdi_unregister() (used to be 
> > > called from blk_cleanup_queue(), my patch moved it to del_gendisk()). 
> > > After that the last reference to bdi may be dropped which does final 
> > > bdi destruction.
> > > 
> > > So do I understand correctly that SCSI may call device_add_disk(),
> > > del_gendisk() repeatedly for the same request queue?
> > 
> > Yes.  The upper drivers (sd, sr, st and sg) follow a device model. 
> >  They can thus be bound and unbound many times during the lifetime of a
> > SCSI device.
> > 
> > >  If yes, then indeed I have a bug to fix... But gendisk seems to get 
> > > allocated from scratch on each probe so we don't call 
> > > device_add_disk(), del_gendisk() more times on the same disk, right?
> > 
> > Right, gendisk, being a generic representation of a disk is a property
> > of the upper layer drivers.  We actually cheat and use it in all of
> > them (including the apparent character ones, they use alloc_disk,
> > put_disk but not add_disk).  So it has to be freed when the driver is
> > unbound and reallocated when it is bound.  It's the fundamental entity
> > which embeds the SCSI upper layer driver lifetime.
> > 
> > > > The fact that the second rebind tried with a different name 
> > > > indicates that sd_devt_release wasn't called, so some vestige of 
> > > > the devt remains on the subsequent rebind.
> > > 
> > > Yep, I guess that's caused by Dan's patch (commit 0dba1314d4f8 now) 
> > > which calls put_disk_devt() only in blk_cleanup_queue() which, if I
> > > understood you correctly, does not get called during unbind-bind 
> > > cycle? In fact Dan's patch would end up leaking devt's because of 
> > > repeated device_add_disk() calls for the same request queue...
> > 
> > That's a bit unfortunate.
> > 
> > > > Here's the problem: the queue belongs to SCSI (the lower layer), so 
> > > > it's not going to change because it doesn't see the release.  The
> > > > gendisk and its allied stuff belongs to sd so it gets freed and re
> > > > -created for the same queue.  Something in block is very confused
> > > > when this happens.
> > > 
> > > Yep, I think the binding of request queue to different gendisks is
> > > something I or Dan did not expect.
> > 
> > OK, so I think we now understand why this is happening ... the question
> > is what we do about it?  Is it fixable or do we need to go back to
> > basics?  The fundamental property which got broken by these patches is
> > the idea of the separation of the lifecycles of the queue and the
> > gendisk.  The only requirement is that the queue must exist before the
> > gendisk is created and must be destroyed after it.  This doesn't forbid
> > there being many gendisk lifetimes over one queue lifetime and this is
> > what we rely on for the SCSI driver model.  We rarely get called on it
> > because unbind/rebind of a ULD is rarely done in production (it's
> > mostly a devtest thing).
> 
> For now I think it's fixable. Let's see what I'll be able to come up with.
> Let me also note that before my patch moving bdi_unregister() to
> del_gendisk() (commit 165a5e22fafb), the SCSI driver model was buggy in a
> different way - because bdi_unregister() was called only from
> blk_cleanup_queue(), we were leaking bdi->owner reference to gendisk by
> repeated calls to bdi_register_owner() from device_add_disk() and
> thus gendisks were never freed after unbind/bind (I've actually verified
> this bug exists with debug messages). Also as a result request queue use
> count was steadily increasing with each new gendisk and request queue could
> never get freed after unbind / rebind.
> 
> My patch silently fixed this leakage but introduced a different set of
> problems which I'll try to fix.

Attached patch fixes the problem for me. If I also revert commit
0dba1314d4f81115dce711292ec7981d17231064 "scsi, block: fix duplicate bdi
name registration crashes" which is not needed with my
165a5e22fafb127ecb5914e12e8c32a1f0d3f820 "block: Move bdi_unregister() to
del_gendisk()", the device names also do not get incremented and I end up
with 'sda' device (otherwise I end up with sdc).

								Honza
-- 
Jan Kara <jack@suse.com>
SUSE Labs, CR

[toc] | [prev] | [next] | [standalone]

#1593629

On Mon, 2017-03-06 at 16:14 +0100, Jan Kara wrote:
> On Mon 06-03-17 06:35:21, James Bottomley wrote:
> > On Mon, 2017-03-06 at 13:01 +0100, Jan Kara wrote:
> > > On Mon 06-03-17 11:27:33, Jan Kara wrote:
> > > > Hi,
> > > > 
> > > > On Sun 05-03-17 10:21:11, Wu Fengguang wrote:
> > > > > FYI next-20170303 is good while mainline is bad with this
> > > > > error.
> > > > > The attached reproduce-* may help reproduce the issue.
> > > > 
> > > > Thanks for report! So from the stacktrace we are in the path 
> > > > testing removal of a device immediately after it has been
> > > > probed 
> > > > and for some reason bdi_unregister() hangs - likely waiting for
> > > > cgroup-writeback references to drop. Given how early this
> > > > happens 
> > > > my guess is we fail to initialize something but for now I don't
> > > > see 
> > > > how my patch could make a difference. I'm trying to reproduce
> > > > this 
> > > > to be able to debug more...
> > > 
> > > OK, so after some debugging I think this is yet another problem
> > > in 
> > > SCSI initialization / destruction code which my patch only makes 
> > > visible (added relevant maintainers).
> > > 
> > > I can reproduce the problem reliably with enabling:
> > > 
> > > CONFIG_DEBUG_TEST_DRIVER_REMOVE=y
> > > CONFIG_SCSI_DEBUG=m
> > > CONFIG_BLK_CGROUP=y
> > > CONFIG_MEMCG=y
> > > (and thus CONFIG_CGROUP_WRITEBACK=y)
> > > 
> > > then 'modprobe scsi_debug' is all it takes to reproduce hang. 
> > > Relevant kernel messages with some of my debugging added
> > > (attached is 
> > > a patch that adds those debug messages):
> > 
> > This looks to be precisely the same problem Dan Williams was
> > debugging
> > for us.
> > 
> > > [   58.721765] scsi host0: scsi_debug: version 1.86 [20160430]
> > > [   58.721765]   dev_size_mb=8, opts=0x0, submit_queues=1,
> > > statistics=0
> > > [   58.728946] CGWB init ffff88007fbb2000
> > > [   58.730095] Created sdev ffff880078e1a000
> > > [   58.731611] scsi 0:0:0:0: Direct-Access     Linux   
> > >  scsi_debug
> > > 0186 PQ : 0 ANSI: 7
> > > [   58.782246] sd 0:0:0:0: [sda] 16384 512-byte logical blocks:
> > > (8.39
> > > MB/8.00 MiB)
> > > [   58.789687] sd 0:0:0:0: [sda] Write Protect is off
> > > [   58.791140] sd 0:0:0:0: [sda] Mode Sense: 73 00 10 08
> > > [   58.800879] sd 0:0:0:0: [sda] Write cache: enabled, read
> > > cache:
> > > enabled, supports DPO and FUA
> > > [   58.893738] sd 0:0:0:0: [sda] Attached SCSI disk
> > > [   58.896808] Unreg1
> > > [   58.897960] Unreg2
> > > [   58.898637] Unreg3
> > > [   58.899100] CGWB ffff88007fbb2000 usage_cnt: 0
> > > [   58.900004] Unreg4
> > > [   58.904976] sd 0:0:0:0: [sda] Synchronizing SCSI cache
> > 
> > OK, can you put a WARN_ON trace in sd_shutdown and tell us where
> > this
> > is coming from.  For the device to be reused after this we have to
> > be
> > calling sd_shutdown() without going into SDEV_DEL.
> 
> Sure. The call trace is:
> 
> [   41.919244] ------------[ cut here ]------------
> [   41.919263] WARNING: CPU: 4 PID: 2335 at drivers/scsi/sd.c:3332
> sd_shutdown+0x2f/0x100
> [   41.919268] Modules linked in: scsi_debug(+) netconsole loop btrfs
> raid6_pq zlib_deflate lzo_compress xor
> [   41.919319] CPU: 4 PID: 2335 Comm: modprobe Not tainted 4.11.0-rc1
> -xen+ #49
> [   41.919325] Hardware name: Bochs Bochs, BIOS Bochs 01/01/2011
> [   41.919331] Call Trace:
> [   41.919343]  dump_stack+0x8e/0xf0
> [   41.919354]  __warn+0x116/0x120
> [   41.919361]  warn_slowpath_null+0x1d/0x20
> [   41.919368]  sd_shutdown+0x2f/0x100
> [   41.919374]  sd_remove+0x70/0xd0
> 
> *** Here is the unexpected step I guess...
> 
> [   41.919383]  driver_probe_device+0xe0/0x4c0

Exactly.  It's this, I think

	bool test_remove = IS_ENABLED(CONFIG_DEBUG_TEST_DRIVER_REMOVE) &&
			   !drv->suppress_bind_attrs;

You have that config option set.

So the drivers base layer is calling ->remove after probe and
triggering the destruction of the queue.

What to do about this (apart from nuke such a stupid option) is
somewhat more problematic.

James

[toc] | [prev] | [standalone]

Back to top | Article view | linux.kernel

csiph-web