Re: [PATCH 0/2] blktests: test ANA base support
On Thu, Jul 26, 2018 at 02:31:32PM -0700, Omar Sandoval wrote: > On Thu, Jul 26, 2018 at 09:35:53AM -0700, James Smart wrote: > > make sure this fix has been picked up in your kernel: > > http://git.infradead.org/nvme.git/commit/6cdefc6e2ad52170f89a8d0e8b1a1339f91834dc > > > > deletes were broken otherwise and have the exact trace below. > > > > -- james > > Thanks, James, that indeed fixes the problem. I'll go ahead and merge > these tests since there's a fix in flight. By "these tests", I mean Chaitanya's tests, Hannes still has some comments to resolve :)
Re: [PATCH 0/2] blktests: test ANA base support
On Thu, Jul 26, 2018 at 09:35:53AM -0700, James Smart wrote: > make sure this fix has been picked up in your kernel: > http://git.infradead.org/nvme.git/commit/6cdefc6e2ad52170f89a8d0e8b1a1339f91834dc > > deletes were broken otherwise and have the exact trace below. > > -- james Thanks, James, that indeed fixes the problem. I'll go ahead and merge these tests since there's a fix in flight.
Re: [PATCH 0/2] blktests: test ANA base support
make sure this fix has been picked up in your kernel:
http://git.infradead.org/nvme.git/commit/6cdefc6e2ad52170f89a8d0e8b1a1339f91834dc
deletes were broken otherwise and have the exact trace below.
-- james
On 7/25/2018 7:01 PM, Chaitanya Kulkarni wrote:
Thanks for the report and correction. I was able to run the test and reproduce
the problem, I also confirm that it is not that consistent.
As I suspected the problem is in the nvme disconnect in the following call
chain:-
nvme_sysfs_delete
nvme_delete_ctrl_sync
nvme_delete_ctrl_work
nvme_remove_namespaces
nvme_ns_remove
nvme_ns_remove
blk_cleanup_queue
blk_freeze_queue
blk_freeze_queue_start
wait_event(q->mq_freeze_wq,
percpu_ref_is_zero(&q->q_usage_counter)); <- Stuck here.
blk_cleanup_queue() that's where it is blocking and then target ctrl is timing out on keep alive.
It will take some time for me to debug and find a fix let's merge this test
once we fix this issue.
How should we go about other tests ? should we merge them and keep this one out
in the nvmeof branch?
Regards,
Chaitanya
From: Omar Sandoval
Sent: Wednesday, July 25, 2018 2:00 PM
To: Chaitanya Kulkarni
Cc: Hannes Reinecke; Omar Sandoval; Christoph Hellwig; Sagi Grimberg; Keith
Busch; linux-n...@lists.infradead.org; linux-block@vger.kernel.org
Subject: Re: [PATCH 0/2] blktests: test ANA base support
On Wed, Jul 25, 2018 at 07:27:35PM +, Chaitanya Kulkarni wrote:
Thanks, Omar.
Tests nvme/014 and nvme/015 had a pretty bad typo that I didn't notice
last time:
dd=/dev/urandom of="/dev/${nvmedev}n1" count=128000 bs=4k
That should be
dd if=/dev/urandom of="/dev/${nvmedev}n1" count=128000 bs=4k status=none
When I fix that (and change the nvme flush call as mentioned before), I
sometimes get a hung task:
[ 273.80] run blktests nvme/015 at 2018-07-25 13:44:11
[ 273.861950] nvmet: adding nsid 1 to subsystem blktests-subsystem-1
[ 273.875014] nvmet: creating controller 1 for subsystem blktests-subsystem-1
for NQN nqn.2014-08.org.nvmexpress:uuid:c5e36fdf-8e4d-4c27-be56-da373db583b2.
[ 273.877457] nvme nvme1: creating 4 I/O queues.
[ 273.879141] nvme nvme1: new ctrl: "blktests-subsystem-1"
[ 276.247708] nvme nvme1: using deprecated NVME_IOCTL_IO_CMD ioctl on the char
device!
[ 276.262835] nvme nvme1: Removing ctrl: NQN "blktests-subsystem-1"
[ 289.755361] nvmet: ctrl 1 keep-alive timer (15 seconds) expired!
[ 289.760579] nvmet: ctrl 1 fatal error occurred!
[ 491.095890] INFO: task kworker/u8:0:7 blocked for more than 120 seconds.
[ 491.104407] Not tainted 4.18.0-rc6 #18
[ 491.108330] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this
message.
[ 491.116521] kworker/u8:0 D 0 7 2 0x8000
[ 491.121754] Workqueue: nvme-delete-wq nvme_delete_ctrl_work [nvme_core]
[ 491.129604] Call Trace:
[ 491.131611] ? __schedule+0x2a1/0x890
[ 491.135112] ? _raw_spin_unlock_irqrestore+0x20/0x40
[ 491.140542] schedule+0x32/0x90
[ 491.142030] blk_mq_freeze_queue_wait+0x41/0xa0
[ 491.144186] ? wait_woken+0x80/0x80
[ 491.145726] blk_cleanup_queue+0x75/0x160
[ 491.150235] nvme_ns_remove+0xf9/0x130 [nvme_core]
[ 491.151910] nvme_remove_namespaces+0x86/0xc0 [nvme_core]
[ 491.153127] nvme_delete_ctrl_work+0x4b/0x80 [nvme_core]
[ 491.154727] process_one_work+0x18c/0x360
[ 491.155428] worker_thread+0x1c6/0x380
[ 491.156160] ? process_one_work+0x360/0x360
[ 491.157493] kthread+0x112/0x130
[ 491.159119] ? kthread_flush_work_fn+0x10/0x10
[ 491.160008] ret_from_fork+0x35/0x40
[ 491.160729] INFO: task nvme:1139 blocked for more than 120 seconds.
[ 491.162416] Not tainted 4.18.0-rc6 #18
[ 491.164348] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this
message.
[ 491.166012] nvme D 0 1139 1072 0x
[ 491.167946] Call Trace:
[ 491.168459] ? __schedule+0x2a1/0x890
[ 491.169312] schedule+0x32/0x90
[ 491.170180] schedule_timeout+0x311/0x4a0
[ 491.171921] ? kernfs_fop_release+0xa0/0xa0
[ 491.172884] wait_for_common+0x1a0/0x1d0
[ 491.173813] ? wake_up_q+0x70/0x70
[ 491.174410] flush_work+0x10e/0x1c0
[ 491.174991] ? flush_workqueue_prep_pwqs+0x130/0x130
[ 491.176113] nvme_delete_ctrl_sync+0x41/0x50 [nvme_core]
[ 491.177969] nvme_sysfs_delete+0x28/0x30 [nvme_core]
[ 491.178632] kernfs_fop_write+0x116/0x190
[ 491.179254] __vfs_write+0x36/0x190
[ 491.179812] vfs_write+0xa9/0x190
[ 491.180344] ksys_write+0x4f/0xb0
[ 491.181056] do_syscall_64+0x5b/0x170
[ 491.181583] entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 491.182311] RIP: 0033:0x7fc04176b9d4
[ 491.182863] Code: Bad RIP value.
[ 491.183650] RSP: 002b:7ffc33bd15a8 EFLAGS: 0246 ORIG_RAX:
0001
[ 491.184622] RAX: ffda RBX: 0004 RCX: 7fc04176b9d4
[ 49
Re: [PATCH 0/2] blktests: test ANA base support
Thanks for the report and correction. I was able to run the test and reproduce
the problem, I also confirm that it is not that consistent.
As I suspected the problem is in the nvme disconnect in the following call
chain:-
nvme_sysfs_delete
nvme_delete_ctrl_sync
nvme_delete_ctrl_work
nvme_remove_namespaces
nvme_ns_remove
nvme_ns_remove
blk_cleanup_queue
blk_freeze_queue
blk_freeze_queue_start
wait_event(q->mq_freeze_wq,
percpu_ref_is_zero(&q->q_usage_counter)); <- Stuck here.
blk_cleanup_queue() that's where it is blocking and then target ctrl is timing
out on keep alive.
It will take some time for me to debug and find a fix let's merge this test
once we fix this issue.
How should we go about other tests ? should we merge them and keep this one out
in the nvmeof branch?
Regards,
Chaitanya
From: Omar Sandoval
Sent: Wednesday, July 25, 2018 2:00 PM
To: Chaitanya Kulkarni
Cc: Hannes Reinecke; Omar Sandoval; Christoph Hellwig; Sagi Grimberg; Keith
Busch; linux-n...@lists.infradead.org; linux-block@vger.kernel.org
Subject: Re: [PATCH 0/2] blktests: test ANA base support
On Wed, Jul 25, 2018 at 07:27:35PM +, Chaitanya Kulkarni wrote:
>
> Thanks, Omar.
Tests nvme/014 and nvme/015 had a pretty bad typo that I didn't notice
last time:
dd=/dev/urandom of="/dev/${nvmedev}n1" count=128000 bs=4k
That should be
dd if=/dev/urandom of="/dev/${nvmedev}n1" count=128000 bs=4k status=none
When I fix that (and change the nvme flush call as mentioned before), I
sometimes get a hung task:
[ 273.80] run blktests nvme/015 at 2018-07-25 13:44:11
[ 273.861950] nvmet: adding nsid 1 to subsystem blktests-subsystem-1
[ 273.875014] nvmet: creating controller 1 for subsystem blktests-subsystem-1
for NQN nqn.2014-08.org.nvmexpress:uuid:c5e36fdf-8e4d-4c27-be56-da373db583b2.
[ 273.877457] nvme nvme1: creating 4 I/O queues.
[ 273.879141] nvme nvme1: new ctrl: "blktests-subsystem-1"
[ 276.247708] nvme nvme1: using deprecated NVME_IOCTL_IO_CMD ioctl on the char
device!
[ 276.262835] nvme nvme1: Removing ctrl: NQN "blktests-subsystem-1"
[ 289.755361] nvmet: ctrl 1 keep-alive timer (15 seconds) expired!
[ 289.760579] nvmet: ctrl 1 fatal error occurred!
[ 491.095890] INFO: task kworker/u8:0:7 blocked for more than 120 seconds.
[ 491.104407] Not tainted 4.18.0-rc6 #18
[ 491.108330] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this
message.
[ 491.116521] kworker/u8:0 D 0 7 2 0x8000
[ 491.121754] Workqueue: nvme-delete-wq nvme_delete_ctrl_work [nvme_core]
[ 491.129604] Call Trace:
[ 491.131611] ? __schedule+0x2a1/0x890
[ 491.135112] ? _raw_spin_unlock_irqrestore+0x20/0x40
[ 491.140542] schedule+0x32/0x90
[ 491.142030] blk_mq_freeze_queue_wait+0x41/0xa0
[ 491.144186] ? wait_woken+0x80/0x80
[ 491.145726] blk_cleanup_queue+0x75/0x160
[ 491.150235] nvme_ns_remove+0xf9/0x130 [nvme_core]
[ 491.151910] nvme_remove_namespaces+0x86/0xc0 [nvme_core]
[ 491.153127] nvme_delete_ctrl_work+0x4b/0x80 [nvme_core]
[ 491.154727] process_one_work+0x18c/0x360
[ 491.155428] worker_thread+0x1c6/0x380
[ 491.156160] ? process_one_work+0x360/0x360
[ 491.157493] kthread+0x112/0x130
[ 491.159119] ? kthread_flush_work_fn+0x10/0x10
[ 491.160008] ret_from_fork+0x35/0x40
[ 491.160729] INFO: task nvme:1139 blocked for more than 120 seconds.
[ 491.162416] Not tainted 4.18.0-rc6 #18
[ 491.164348] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this
message.
[ 491.166012] nvme D 0 1139 1072 0x
[ 491.167946] Call Trace:
[ 491.168459] ? __schedule+0x2a1/0x890
[ 491.169312] schedule+0x32/0x90
[ 491.170180] schedule_timeout+0x311/0x4a0
[ 491.171921] ? kernfs_fop_release+0xa0/0xa0
[ 491.172884] wait_for_common+0x1a0/0x1d0
[ 491.173813] ? wake_up_q+0x70/0x70
[ 491.174410] flush_work+0x10e/0x1c0
[ 491.174991] ? flush_workqueue_prep_pwqs+0x130/0x130
[ 491.176113] nvme_delete_ctrl_sync+0x41/0x50 [nvme_core]
[ 491.177969] nvme_sysfs_delete+0x28/0x30 [nvme_core]
[ 491.178632] kernfs_fop_write+0x116/0x190
[ 491.179254] __vfs_write+0x36/0x190
[ 491.179812] vfs_write+0xa9/0x190
[ 491.180344] ksys_write+0x4f/0xb0
[ 491.181056] do_syscall_64+0x5b/0x170
[ 491.181583] entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 491.182311] RIP: 0033:0x7fc04176b9d4
[ 491.182863] Code: Bad RIP value.
[ 491.183650] RSP: 002b:7ffc33bd15a8 EFLAGS: 0246 ORIG_RAX:
0001
[ 491.184622] RAX: ffda RBX: 0004 RCX: 7fc04176b9d4
[ 491.185606] RDX: 0001 RSI: 55884bd0810a RDI: 0004
[ 491.186719] RBP: R08: R09: 000f
[ 491.187684] R10: R11: 0246 R12:
[ 491.189045] R13: 7ffc33bd2
Re: [PATCH 0/2] blktests: test ANA base support
On Wed, Jul 25, 2018 at 07:27:35PM +, Chaitanya Kulkarni wrote:
>
> Thanks, Omar.
Tests nvme/014 and nvme/015 had a pretty bad typo that I didn't notice
last time:
dd=/dev/urandom of="/dev/${nvmedev}n1" count=128000 bs=4k
That should be
dd if=/dev/urandom of="/dev/${nvmedev}n1" count=128000 bs=4k status=none
When I fix that (and change the nvme flush call as mentioned before), I
sometimes get a hung task:
[ 273.80] run blktests nvme/015 at 2018-07-25 13:44:11
[ 273.861950] nvmet: adding nsid 1 to subsystem blktests-subsystem-1
[ 273.875014] nvmet: creating controller 1 for subsystem blktests-subsystem-1
for NQN nqn.2014-08.org.nvmexpress:uuid:c5e36fdf-8e4d-4c27-be56-da373db583b2.
[ 273.877457] nvme nvme1: creating 4 I/O queues.
[ 273.879141] nvme nvme1: new ctrl: "blktests-subsystem-1"
[ 276.247708] nvme nvme1: using deprecated NVME_IOCTL_IO_CMD ioctl on the char
device!
[ 276.262835] nvme nvme1: Removing ctrl: NQN "blktests-subsystem-1"
[ 289.755361] nvmet: ctrl 1 keep-alive timer (15 seconds) expired!
[ 289.760579] nvmet: ctrl 1 fatal error occurred!
[ 491.095890] INFO: task kworker/u8:0:7 blocked for more than 120 seconds.
[ 491.104407] Not tainted 4.18.0-rc6 #18
[ 491.108330] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this
message.
[ 491.116521] kworker/u8:0D0 7 2 0x8000
[ 491.121754] Workqueue: nvme-delete-wq nvme_delete_ctrl_work [nvme_core]
[ 491.129604] Call Trace:
[ 491.131611] ? __schedule+0x2a1/0x890
[ 491.135112] ? _raw_spin_unlock_irqrestore+0x20/0x40
[ 491.140542] schedule+0x32/0x90
[ 491.142030] blk_mq_freeze_queue_wait+0x41/0xa0
[ 491.144186] ? wait_woken+0x80/0x80
[ 491.145726] blk_cleanup_queue+0x75/0x160
[ 491.150235] nvme_ns_remove+0xf9/0x130 [nvme_core]
[ 491.151910] nvme_remove_namespaces+0x86/0xc0 [nvme_core]
[ 491.153127] nvme_delete_ctrl_work+0x4b/0x80 [nvme_core]
[ 491.154727] process_one_work+0x18c/0x360
[ 491.155428] worker_thread+0x1c6/0x380
[ 491.156160] ? process_one_work+0x360/0x360
[ 491.157493] kthread+0x112/0x130
[ 491.159119] ? kthread_flush_work_fn+0x10/0x10
[ 491.160008] ret_from_fork+0x35/0x40
[ 491.160729] INFO: task nvme:1139 blocked for more than 120 seconds.
[ 491.162416] Not tainted 4.18.0-rc6 #18
[ 491.164348] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this
message.
[ 491.166012] nvmeD0 1139 1072 0x
[ 491.167946] Call Trace:
[ 491.168459] ? __schedule+0x2a1/0x890
[ 491.169312] schedule+0x32/0x90
[ 491.170180] schedule_timeout+0x311/0x4a0
[ 491.171921] ? kernfs_fop_release+0xa0/0xa0
[ 491.172884] wait_for_common+0x1a0/0x1d0
[ 491.173813] ? wake_up_q+0x70/0x70
[ 491.174410] flush_work+0x10e/0x1c0
[ 491.174991] ? flush_workqueue_prep_pwqs+0x130/0x130
[ 491.176113] nvme_delete_ctrl_sync+0x41/0x50 [nvme_core]
[ 491.177969] nvme_sysfs_delete+0x28/0x30 [nvme_core]
[ 491.178632] kernfs_fop_write+0x116/0x190
[ 491.179254] __vfs_write+0x36/0x190
[ 491.179812] vfs_write+0xa9/0x190
[ 491.180344] ksys_write+0x4f/0xb0
[ 491.181056] do_syscall_64+0x5b/0x170
[ 491.181583] entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 491.182311] RIP: 0033:0x7fc04176b9d4
[ 491.182863] Code: Bad RIP value.
[ 491.183650] RSP: 002b:7ffc33bd15a8 EFLAGS: 0246 ORIG_RAX:
0001
[ 491.184622] RAX: ffda RBX: 0004 RCX: 7fc04176b9d4
[ 491.185606] RDX: 0001 RSI: 55884bd0810a RDI: 0004
[ 491.186719] RBP: R08: R09: 000f
[ 491.187684] R10: R11: 0246 R12:
[ 491.189045] R13: 7ffc33bd2c20 R14: 7ffc33bd15f0 R15: 0010
I pushed what I have to https://github.com/osandov/blktests/tree/nvmeof,
can you please take a look?
Re: [PATCH 0/2] blktests: test ANA base support
Thanks, Omar. From: Omar Sandoval Sent: Wednesday, July 25, 2018 12:17 PM To: Chaitanya Kulkarni Cc: Hannes Reinecke; Omar Sandoval; Christoph Hellwig; Sagi Grimberg; Keith Busch; linux-n...@lists.infradead.org; linux-block@vger.kernel.org Subject: Re: [PATCH 0/2] blktests: test ANA base support On Sat, Jul 21, 2018 at 09:23:32PM +, Chaitanya Kulkarni wrote: > Hi Hannes, > > Thanks for the test, this is really helpful, please see my inline comments to > individual patches. > > Also, the test number should be I guess 18, 14-17 testcases are still in the > queue. Yeah, sorry about that, I'll take another look. > Omar, can you please let us know when can you merge the remaining testcases > for NVMeOF > from the first round that I've posted? so we can set the right number for > this. No need to worry about the numbering, I can trivially renumber it here. > > From: linux-block-ow...@vger.kernel.org > on behalf of Hannes Reinecke > Sent: Tuesday, July 17, 2018 6:31 AM > To: Omar Sandoval > Cc: Christoph Hellwig; Sagi Grimberg; Keith Busch; > linux-n...@lists.infradead.org; linux-block@vger.kernel.org; Hannes Reinecke > Subject: [PATCH 0/2] blktests: test ANA base support > > > Hi all, > > here's a small patchset for testing ANA base support. > The test itself requires the ANA patchset from Christoph, plus > the fixes I've sent to the mailing list earlier. > > Hannes Reinecke (2): > blktests: enable ANA support > blktests: add test for ANA state transition > > tests/nvme/014 | 158 > + > tests/nvme/014.out | 17 ++ > tests/nvme/rc | 49 - > 3 files changed, 221 insertions(+), 3 deletions(-) > create mode 100755 tests/nvme/014 > create mode 100644 tests/nvme/014.out > > -- > 2.12.3 > >
Re: [PATCH 0/2] blktests: test ANA base support
On Sat, Jul 21, 2018 at 09:23:32PM +, Chaitanya Kulkarni wrote: > Hi Hannes, > > Thanks for the test, this is really helpful, please see my inline comments to > individual patches. > > Also, the test number should be I guess 18, 14-17 testcases are still in the > queue. Yeah, sorry about that, I'll take another look. > Omar, can you please let us know when can you merge the remaining testcases > for NVMeOF > from the first round that I've posted? so we can set the right number for > this. No need to worry about the numbering, I can trivially renumber it here. > > From: linux-block-ow...@vger.kernel.org > on behalf of Hannes Reinecke > Sent: Tuesday, July 17, 2018 6:31 AM > To: Omar Sandoval > Cc: Christoph Hellwig; Sagi Grimberg; Keith Busch; > linux-n...@lists.infradead.org; linux-block@vger.kernel.org; Hannes Reinecke > Subject: [PATCH 0/2] blktests: test ANA base support > > > Hi all, > > here's a small patchset for testing ANA base support. > The test itself requires the ANA patchset from Christoph, plus > the fixes I've sent to the mailing list earlier. > > Hannes Reinecke (2): > blktests: enable ANA support > blktests: add test for ANA state transition > > tests/nvme/014 | 158 > + > tests/nvme/014.out | 17 ++ > tests/nvme/rc | 49 - > 3 files changed, 221 insertions(+), 3 deletions(-) > create mode 100755 tests/nvme/014 > create mode 100644 tests/nvme/014.out > > -- > 2.12.3 > >
Re: [PATCH 0/2] blktests: test ANA base support
Hi Hannes, Thanks for the test, this is really helpful, please see my inline comments to individual patches. Also, the test number should be I guess 18, 14-17 testcases are still in the queue. Omar, can you please let us know when can you merge the remaining testcases for NVMeOF from the first round that I've posted? so we can set the right number for this. From: linux-block-ow...@vger.kernel.org on behalf of Hannes Reinecke Sent: Tuesday, July 17, 2018 6:31 AM To: Omar Sandoval Cc: Christoph Hellwig; Sagi Grimberg; Keith Busch; linux-n...@lists.infradead.org; linux-block@vger.kernel.org; Hannes Reinecke Subject: [PATCH 0/2] blktests: test ANA base support Hi all, here's a small patchset for testing ANA base support. The test itself requires the ANA patchset from Christoph, plus the fixes I've sent to the mailing list earlier. Hannes Reinecke (2): blktests: enable ANA support blktests: add test for ANA state transition tests/nvme/014 | 158 + tests/nvme/014.out | 17 ++ tests/nvme/rc | 49 - 3 files changed, 221 insertions(+), 3 deletions(-) create mode 100755 tests/nvme/014 create mode 100644 tests/nvme/014.out -- 2.12.3
[PATCH 0/2] blktests: test ANA base support
Hi all, here's a small patchset for testing ANA base support. The test itself requires the ANA patchset from Christoph, plus the fixes I've sent to the mailing list earlier. Hannes Reinecke (2): blktests: enable ANA support blktests: add test for ANA state transition tests/nvme/014 | 158 + tests/nvme/014.out | 17 ++ tests/nvme/rc | 49 - 3 files changed, 221 insertions(+), 3 deletions(-) create mode 100755 tests/nvme/014 create mode 100644 tests/nvme/014.out -- 2.12.3
