Re: [PATCH V2 0/2] block: remove unnecessary RESTART

[Ming Lei <ming.lei@redhat.com>]

On Fri, Nov 03, 2017 at 03:23:14PM +0000, Bart Van Assche wrote:
> On Fri, 2017-11-03 at 11:50 +0800, Ming Lei wrote:
> > On Fri, Nov 03, 2017 at 02:42:50AM +0000, Bart Van Assche wrote:
> > > On Fri, 2017-11-03 at 10:12 +0800, Ming Lei wrote:
> > > > [root@ibclient srp-test]# ./run_tests
> > > > modprobe: FATAL: Module target_core_mod is in use.
> > > 
> > > LIO must be unloaded before srp-test software is started.
> > 
> > Yeah, I can make this test kick off after running
> > 'modprobe -fr ib_isert' first, but looks all tests failed without
> > any hang, could you check if that is the expected result?
> > 
> > 	https://pastebin.com/VXe66Jpg
> 
> I see plenty of "... >/sys/.../add_target failed: Connection timed out"
> messages. The srp-test scripts use the loopback functionality of IB ports
> so one or more IB ports must be active. Have you already checked the IB
> ports state, e.g. by running ibv_devinfo?

[root@ibclient ~]# ibv_devinfo
hca_id:	mlx5_1
	transport:			InfiniBand (0)
	fw_ver:				12.20.1010
	node_guid:			7cfe:9003:0072:6ed3
	sys_image_guid:			7cfe:9003:0072:6ed2
	vendor_id:			0x02c9
	vendor_part_id:			4115
	hw_ver:				0x0
	board_id:			MT_2190110032
	phys_port_cnt:			1
		port:	1
			state:			PORT_ACTIVE (4)
			max_mtu:		4096 (5)
			active_mtu:		4096 (5)
			sm_lid:			1
			port_lid:		1
			port_lmc:		0x00
			link_layer:		InfiniBand

hca_id:	mlx5_0
	transport:			InfiniBand (0)
	fw_ver:				12.20.1010
	node_guid:			7cfe:9003:0072:6ed2
	sys_image_guid:			7cfe:9003:0072:6ed2
	vendor_id:			0x02c9
	vendor_part_id:			4115
	hw_ver:				0x0
	board_id:			MT_2190110032
	phys_port_cnt:			1
		port:	1
			state:			PORT_ACTIVE (4)
			max_mtu:		4096 (5)
			active_mtu:		4096 (5)
			sm_lid:			4
			port_lid:		4
			port_lmc:		0x00
			link_layer:		InfiniBand

Forget to mention, there is failure when running 'make' under srp-test
because shellcheck package is missed in RHEL7. Can that be the issue
of test failure? If yes, could you provide a special version of srp-test
which doesn't depend on shellcheck?

> 
> > Also could you provide some output from debugfs when this hang happens?
> > such as:
> > 
> > 	dispatch/busy/.. under hctxN
> 
> This is the output that appears on my test setup if the two patches from
> the patch series "block: remove unnecessary RESTART" are applied:
> 
> # ~bart/software/infiniband/srp-test/run_tests -f xfs -d -e deadline -r 60                             
> Unloaded the ib_srpt kernel module
> Zero-initializing /dev/ram0 ... done
> Zero-initializing /dev/ram1 ... done
> Zero-initializing /dev/disk/by-id/scsi-33333333000004650 ... done
> brw-rw---- 1 root disk 1, 0 Nov  3 08:10 /dev/ram0
> /dev/ram0
> brw-rw---- 1 root disk 1, 1 Nov  3 08:10 /dev/ram1
> /dev/ram1
> lrwxrwxrwx 1 root root 9 Nov  3 08:11 /dev/disk/by-id/scsi-33333333000004650 -> ../../sdi
> /dev/sdi
> Configured SRP target driver
> Running test /home/bart/software/infiniband/srp-test/tests/01 ...
> id_ext=0x0002c90300a02d50,ioc_guid=0x0002c90300a02d50,dgid=fe800000000000000002c90300a02d51,pkey=7fff,service_id=0x0002c90300a02d50, >/sys/class/infiniband_srp/
> srp-mlx4_0-2/add_target failed: Invalid argument
> id_ext=0x0002c90300a02d50,ioc_guid=0x0002c90300a02d50,dgid=fe800000000000000002c90300a02d52,pkey=7fff,service_id=0x0002c90300a02d50, >/sys/class/infiniband_srp/
> srp-mlx4_0-2/add_target failed: Invalid argument
> count_luns(): 3 <> 3
> Error: unloading kernel module ib_srp failed
> Test /home/bart/software/infiniband/srp-test/tests/01 failed
> # cat /sys/module/scsi_mod/parameters/use_blk_mq  
> Y
> # find /sys/kernel/debug/block -name busy | xargs cat

Can you check 'dispatch' file, hctx state, tags and sched_tags?
And see where is the IO not dispatched?

> # dmesg -c >/dev/null; echo w > /proc/sysrq-trigger; dmesg
> [  709.321750] sysrq: SysRq : Show Blocked State
> [  709.327906]   task                        PC stack   pid father
...
> [  709.456602] kworker/u66:6   D    0   341      2 0x80000000
> [  709.463371] Workqueue: events_unbound async_run_entry_fn
> [  709.469919] Call Trace:
> [  709.473325]  __schedule+0x2fa/0xbb0
> [  709.477850]  ? trace_hardirqs_on_caller+0xfb/0x190
> [  709.483847]  schedule+0x36/0x90
> [  709.487982]  schedule_timeout+0x22c/0x570
> [  709.493115]  ? call_timer_fn+0x330/0x330
> [  709.498133]  ? wait_for_completion_io_timeout+0xf7/0x180
> [  709.504732]  io_schedule_timeout+0x1e/0x50
> [  709.509938]  ? io_schedule_timeout+0x1e/0x50
> [  709.515413]  wait_for_completion_io_timeout+0x11f/0x180
> [  709.521920]  ? wake_up_q+0x80/0x80
> [  709.526376]  blk_execute_rq+0x86/0xc0
> [  709.531135]  scsi_execute+0xdb/0x1f0
> [  709.536336]  sd_revalidate_disk+0xed/0x1c70 [sd_mod]
> [  709.543281]  sd_probe_async+0xc3/0x1d0 [sd_mod]
> [  709.549524]  async_run_entry_fn+0x38/0x160
> [  709.555503]  process_one_work+0x20a/0x660
> [  709.561299]  worker_thread+0x3d/0x3b0
> [  709.566688]  kthread+0x13a/0x150
> [  709.571613]  ? process_one_work+0x660/0x660
> [  709.577561]  ? kthread_create_on_node+0x40/0x40
> [  709.583910]  ret_from_fork+0x27/0x40

Looks hang in scsi_execute().

> [  709.589174] kworker/5:2     D    0   386      2 0x80000000
> [  709.596616] Workqueue: kaluad alua_rtpg_work [scsi_dh_alua]
> [  709.604130] Call Trace:
> [  709.608096]  __schedule+0x2fa/0xbb0
> [  709.613265]  ? trace_hardirqs_on_caller+0xfb/0x190
> [  709.619879]  schedule+0x36/0x90
> [  709.624684]  schedule_timeout+0x22c/0x570
> [  709.630437]  ? call_timer_fn+0x330/0x330
> [  709.636059]  ? wait_for_completion_io_timeout+0xf7/0x180
> [  709.643270]  io_schedule_timeout+0x1e/0x50
> [  709.649083]  ? io_schedule_timeout+0x1e/0x50
> [  709.655159]  wait_for_completion_io_timeout+0x11f/0x180
> [  709.662284]  ? wake_up_q+0x80/0x80
> [  709.667334]  blk_execute_rq+0x86/0xc0
> [  709.672705]  scsi_execute+0xdb/0x1f0
> [  709.677938]  alua_rtpg_work+0x2b3/0xe8a [scsi_dh_alua]
> [  709.684983]  process_one_work+0x20a/0x660
> [  709.690759]  worker_thread+0x3d/0x3b0
> [  709.696107]  kthread+0x13a/0x150
> [  709.700986]  ? process_one_work+0x660/0x660
> [  709.706920]  ? kthread_create_on_node+0x40/0x40
> [  709.713316]  ret_from_fork+0x27/0x40

Same with above.

-- 
Ming