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
