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?
> 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
# 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.335910] kworker/4:1 D 0 54 2 0x80000000
[ 709.342887] Workqueue: srp_remove srp_remove_work [ib_srp]
[ 709.349806] Call Trace:
[ 709.353365] __schedule+0x2fa/0xbb0
[ 709.357865] schedule+0x36/0x90
[ 709.361985] async_synchronize_cookie_domain+0x88/0x130
[ 709.368422] ? finish_wait+0x90/0x90
[ 709.373033] async_synchronize_full_domain+0x18/0x20
[ 709.379184] sd_remove+0x4d/0xc0 [sd_mod]
[ 709.384282] device_release_driver_internal+0x160/0x210
[ 709.390752] device_release_driver+0x12/0x20
[ 709.396130] bus_remove_device+0x100/0x180
[ 709.401332] device_del+0x1d8/0x340
[ 709.405823] __scsi_remove_device+0xfc/0x130
[ 709.411221] scsi_forget_host+0x25/0x70
[ 709.416108] scsi_remove_host+0x79/0x120
[ 709.421114] srp_remove_work+0x90/0x1d0 [ib_srp]
[ 709.426867] process_one_work+0x20a/0x660
[ 709.431971] worker_thread+0x3d/0x3b0
[ 709.436655] kthread+0x13a/0x150
[ 709.440872] ? process_one_work+0x660/0x660
[ 709.446133] ? kthread_create_on_node+0x40/0x40
[ 709.451825] ret_from_fork+0x27/0x40
[ 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
[ 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
[ 709.718809] systemd-udevd D 0 1905 463 0x80000106
[ 709.726285] Call Trace:
[ 709.730309] __schedule+0x2fa/0xbb0
[ 709.735462] schedule+0x36/0x90
[ 709.740270] io_schedule+0x16/0x40
[ 709.745369] __lock_page+0x10a/0x140
[ 709.750691] ? page_cache_tree_insert+0x100/0x100
[ 709.757280] truncate_inode_pages_range+0x4ff/0x800
[ 709.764044] ? buffer_exit_cpu_dead+0x70/0x70
[ 709.770285] ? find_next_bit+0xb/0x10
[ 709.775691] ? cpumask_next+0x1a/0x20
[ 709.781089] ? smp_call_function_many+0x1e3/0x230
[ 709.787598] ? on_each_cpu_mask+0x52/0xa0
[ 709.793353] ? mark_buffer_async_write+0x20/0x20
[ 709.799741] ? buffer_exit_cpu_dead+0x70/0x70
[ 709.805888] ? on_each_cpu_cond+0x99/0xe0
[ 709.811636] truncate_inode_pages+0x15/0x20
[ 709.817536] kill_bdev+0x35/0x40
[ 709.822400] __blkdev_put+0x6d/0x1f0
[ 709.827625] blkdev_put+0x4e/0x130
[ 709.832673] blkdev_close+0x25/0x30
[ 709.837779] __fput+0xed/0x1f0
[ 709.842430] ____fput+0xe/0x10
[ 709.847030] task_work_run+0x8b/0xc0
[ 709.852251] do_exit+0x38d/0xc70
[ 709.857046] ? get_signal+0x2f6/0x8c0
[ 709.862347] do_group_exit+0x50/0xd0
[ 709.867515] get_signal+0x2ad/0x8c0
[ 709.872601] do_signal+0x28/0x680
[ 709.877452] ? blkdev_read_iter+0x35/0x40
[ 709.883108] ? __vfs_read+0xcc/0x130
[ 709.888237] ? vfs_read+0xa0/0x150
[ 709.893200] exit_to_usermode_loop+0x5a/0xa0
[ 709.899109] do_syscall_64+0x12e/0x170
[ 709.904475] entry_SYSCALL64_slow_path+0x25/0x25
[ 709.910797] RIP: 0033:0x7f5dc4e32d11
[ 709.915917] RSP: 002b:00007ffeb0b10588 EFLAGS: 00000246 ORIG_RAX:
0000000000000000
[ 709.925589] RAX: fffffffffffffffc RBX: 000056230da84490 RCX: 00007f5dc4e32d11
[ 709.934785] RDX: 0000000000000040 RSI: 000056230da844b8 RDI: 0000000000000007
[ 709.943987] RBP: 000056230dabc3c0 R08: 0000000000000000 R09: 000056230da84490
[ 709.953202] R10: 000000000000006f R11: 0000000000000246 R12: 000000008d530000
[ 709.962419] R13: 000000008d530040 R14: 000056230dabc410 R15: 0000000000000040
