On Thu, Nov 02, 2017 at 03:57:05PM +0000, Bart Van Assche wrote:

On Wed, 2017-11-01 at 08:21 -0600, Jens Axboe wrote:

quoted

Fixed that up, and applied these two patches as well.

Hello Jens,

Recently I noticed that a test system sporadically hangs during boot (Dell
PowerEdge R720 that boots from a hard disk connected to a MegaRAID SAS adapter)
and also that srp-tests systematically hangs. Reverting the two patches from
this series fixes both issues. I'm not sure there is another solution than
reverting the two patches from this series.

Then we need to find the root cause, instead of using sort of workaround
as before.

For SCSI, the restart is always run from scsi_end_request(), and this
kind of restart from all hctx isn't necessary at all.

Bart.


BTW, the following appeared in the kernel log when I tried to run srp-tests
against a kernel with the two patches from this series applied:

INFO: task kworker/19:1:209 blocked for more than 480 seconds.
INFO: task kworker/19:1:209 blocked for more than 480 seconds.
      Tainted: G        W       4.14.0-rc7-dbg+ #1
      Tainted: G        W       4.14.0-rc7-dbg+ #1
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
kworker/19:1    D    0   209      2 0x80000000
kworker/19:1    D    0   209      2 0x80000000
Workqueue: srp_remove srp_remove_work [ib_srp]
Workqueue: srp_remove srp_remove_work [ib_srp]
Call Trace:
Call Trace:
 __schedule+0x2fa/0xbb0
 __schedule+0x2fa/0xbb0
 schedule+0x36/0x90
 schedule+0x36/0x90
 async_synchronize_cookie_domain+0x88/0x130
 async_synchronize_cookie_domain+0x88/0x130
 ? finish_wait+0x90/0x90
 ? finish_wait+0x90/0x90
 async_synchronize_full_domain+0x18/0x20
 async_synchronize_full_domain+0x18/0x20
 sd_remove+0x4d/0xc0 [sd_mod]
 sd_remove+0x4d/0xc0 [sd_mod]
 device_release_driver_internal+0x160/0x210
 device_release_driver_internal+0x160/0x210
 device_release_driver+0x12/0x20
 device_release_driver+0x12/0x20
 bus_remove_device+0x100/0x180
 bus_remove_device+0x100/0x180
 device_del+0x1d8/0x340
 device_del+0x1d8/0x340
 __scsi_remove_device+0xfc/0x130
 __scsi_remove_device+0xfc/0x130
 scsi_forget_host+0x25/0x70
 scsi_forget_host+0x25/0x70
 scsi_remove_host+0x79/0x120
 scsi_remove_host+0x79/0x120
 srp_remove_work+0x90/0x1d0 [ib_srp]
 srp_remove_work+0x90/0x1d0 [ib_srp]
 process_one_work+0x20a/0x660
 process_one_work+0x20a/0x660
 worker_thread+0x3d/0x3b0
 worker_thread+0x3d/0x3b0
 kthread+0x13a/0x150
 kthread+0x13a/0x150
 ? process_one_work+0x660/0x660
 ? process_one_work+0x660/0x660
 ? kthread_create_on_node+0x40/0x40
 ? kthread_create_on_node+0x40/0x40
 ret_from_fork+0x27/0x40
 ret_from_fork+0x27/0x40

Showing all locks held in the system:

Showing all locks held in the system:
1 lock held by khungtaskd/170:
1 lock held by khungtaskd/170:
 #0:  (tasklist_lock){.+.+}, at: [<ffffffff810c125d>] debug_show_all_locks+0x3d/0x1a0
 #0:  (tasklist_lock){.+.+}, at: [<ffffffff810c125d>] debug_show_all_locks+0x3d/0x1a0
4 locks held by kworker/19:1/209:
4 locks held by kworker/19:1/209:
 #0:  ("%s"("srp_remove")){+.+.}, at: [<ffffffff81083b85>] process_one_work+0x195/0x660
 #0:  ("%s"("srp_remove")){+.+.}, at: [<ffffffff81083b85>] process_one_work+0x195/0x660
 #1:  ((&target->remove_work)){+.+.}, at: [<ffffffff81083b85>] process_one_work+0x195/0x660
 #1:  ((&target->remove_work)){+.+.}, at: [<ffffffff81083b85>] process_one_work+0x195/0x660
 #2:  (&shost->scan_mutex){+.+.}, at: [<ffffffff814807bf>] scsi_remove_host+0x1f/0x120
 #2:  (&shost->scan_mutex){+.+.}, at: [<ffffffff814807bf>] scsi_remove_host+0x1f/0x120
 #3:  (&dev->mutex){....}, at: [<ffffffff814501a9>] device_release_driver_internal+0x39/0x210
 #3:  (&dev->mutex){....}, at: [<ffffffff814501a9>] device_release_driver_internal+0x39/0x210
2 locks held by kworker/u66:0/1927:
2 locks held by kworker/u66:0/1927:
 #0:  ("events_unbound"){+.+.}, at: [<ffffffff81083b85>] process_one_work+0x195/0x660
 #0:  ("events_unbound"){+.+.}, at: [<ffffffff81083b85>] process_one_work+0x195/0x660
 #1:  ((&entry->work)){+.+.}, at: [<ffffffff81083b85>] process_one_work+0x195/0x660
 #1:  ((&entry->work)){+.+.}, at: [<ffffffff81083b85>] process_one_work+0x195/0x660
2 locks held by kworker/5:0/2047:
2 locks held by kworker/5:0/2047:
 #0:  ("kaluad"){+.+.}, at: [<ffffffff81083b85>] process_one_work+0x195/0x660
 #0:  ("kaluad"){+.+.}, at: [<ffffffff81083b85>] process_one_work+0x195/0x660
 #1:  ((&(&pg->rtpg_work)->work)){+.+.}, at: [<ffffffff81083b85>] process_one_work+0x195/0x660
 #1:  ((&(&pg->rtpg_work)->work)){+.+.}, at: [<ffffffff81083b85>] process_one_work+0x195/0x660


=============================================

=============================================

INFO: task kworker/19:1:209 blocked for more than 480 seconds.
INFO: task kworker/19:1:209 blocked for more than 480 seconds.
      Tainted: G        W       4.14.0-rc7-dbg+ #1
      Tainted: G        W       4.14.0-rc7-dbg+ #1
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
kworker/19:1    D    0   209      2 0x80000000
kworker/19:1    D    0   209      2 0x80000000
Workqueue: srp_remove srp_remove_work [ib_srp]
Workqueue: srp_remove srp_remove_work [ib_srp]
Call Trace:
Call Trace:
 __schedule+0x2fa/0xbb0
 __schedule+0x2fa/0xbb0
 schedule+0x36/0x90
 schedule+0x36/0x90
 async_synchronize_cookie_domain+0x88/0x130
 async_synchronize_cookie_domain+0x88/0x130
 ? finish_wait+0x90/0x90
 ? finish_wait+0x90/0x90
 async_synchronize_full_domain+0x18/0x20
 async_synchronize_full_domain+0x18/0x20
 sd_remove+0x4d/0xc0 [sd_mod]
 sd_remove+0x4d/0xc0 [sd_mod]
 device_release_driver_internal+0x160/0x210
 device_release_driver_internal+0x160/0x210
 device_release_driver+0x12/0x20
 device_release_driver+0x12/0x20
 bus_remove_device+0x100/0x180
 bus_remove_device+0x100/0x180
 device_del+0x1d8/0x340
 device_del+0x1d8/0x340
 __scsi_remove_device+0xfc/0x130
 __scsi_remove_device+0xfc/0x130
 scsi_forget_host+0x25/0x70
 scsi_forget_host+0x25/0x70
 scsi_remove_host+0x79/0x120
 scsi_remove_host+0x79/0x120
 srp_remove_work+0x90/0x1d0 [ib_srp]
 srp_remove_work+0x90/0x1d0 [ib_srp]
 process_one_work+0x20a/0x660
 process_one_work+0x20a/0x660
 worker_thread+0x3d/0x3b0
 worker_thread+0x3d/0x3b0
 kthread+0x13a/0x150
 kthread+0x13a/0x150
 ? process_one_work+0x660/0x660
 ? process_one_work+0x660/0x660
 ? kthread_create_on_node+0x40/0x40
 ? kthread_create_on_node+0x40/0x40
 ret_from_fork+0x27/0x40
 ret_from_fork+0x27/0x40

Showing all locks held in the system:

Showing all locks held in the system:
1 lock held by khungtaskd/170:
1 lock held by khungtaskd/170:
 #0:  (tasklist_lock){.+.+}, at: [<ffffffff810c125d>] debug_show_all_locks+0x3d/0x1a0
 #0:  (tasklist_lock){.+.+}, at: [<ffffffff810c125d>] debug_show_all_locks+0x3d/0x1a0
4 locks held by kworker/19:1/209:
4 locks held by kworker/19:1/209:
 #0:  ("%s"("srp_remove")){+.+.}, at: [<ffffffff81083b85>] process_one_work+0x195/0x660
 #0:  ("%s"("srp_remove")){+.+.}, at: [<ffffffff81083b85>] process_one_work+0x195/0x660
 #1:  ((&target->remove_work)){+.+.}, at: [<ffffffff81083b85>] process_one_work+0x195/0x660
 #1:  ((&target->remove_work)){+.+.}, at: [<ffffffff81083b85>] process_one_work+0x195/0x660
 #2:  (&shost->scan_mutex){+.+.}, at: [<ffffffff814807bf>] scsi_remove_host+0x1f/0x120
 #2:  (&shost->scan_mutex){+.+.}, at: [<ffffffff814807bf>] scsi_remove_host+0x1f/0x120
 #3:  (&dev->mutex){....}, at: [<ffffffff814501a9>] device_release_driver_internal+0x39/0x210
 #3:  (&dev->mutex){....}, at: [<ffffffff814501a9>] device_release_driver_internal+0x39/0x210
2 locks held by kworker/u66:0/1927:
2 locks held by kworker/u66:0/1927:
 #0:  ("events_unbound"){+.+.}, at: [<ffffffff81083b85>] process_one_work+0x195/0x660
 #0:  ("events_unbound"){+.+.}, at: [<ffffffff81083b85>] process_one_work+0x195/0x660
 #1:  ((&entry->work)){+.+.}, at: [<ffffffff81083b85>] process_one_work+0x195/0x660
 #1:  ((&entry->work)){+.+.}, at: [<ffffffff81083b85>] process_one_work+0x195/0x660
2 locks held by kworker/5:0/2047:
2 locks held by kworker/5:0/2047:
 #0:  ("kaluad"){+.+.}, at: [<ffffffff81083b85>] process_one_work+0x195/0x660
 #0:  ("kaluad"){+.+.}, at: [<ffffffff81083b85>] process_one_work+0x195/0x660
 #1:  ((&(&pg->rtpg_work)->work)){+.+.}, at: [<ffffffff81083b85>] process_one_work+0x195/0x660
 #1:  ((&(&pg->rtpg_work)->work)){+.+.}, at: [<ffffffff81083b85>] process_one_work+0x195/0x660


=============================================

=============================================

-- 
Ming