diff mbox

kernel BUG at drivers/scsi/qla2xxx/qla_target.c:3643! (or :3319)

Message ID 1501459255.1499.71.camel@haakon3.daterainc.com (mailing list archive)
State New, archived
Headers show

Commit Message

Nicholas A. Bellinger July 31, 2017, midnight UTC 
Hi Lukasz,

On Thu, 2017-07-27 at 17:23 +0200, Łukasz Engel wrote:
> Hello
> 
> I am experiencing problems using LIO FC target with vmware ESX (6.5).
> 
> Thisis the same problem as discussed in 
> https://www.spinics.net/lists/target-devel/msg15670.html
> I've tried 4.11.x (up to 12) and 4.12.3(and also some kernels from 4.9 
> line).
> 
> My setup is 3 ESX 6.5 hosts using FC target storage with 2x QLogic 2460 
> (4gbit) (I also have another storage with QLE-2562 (8gbit)- same problem 
> occurs).
> 
> I am able to reproduce the problem with almost 100%efficiency - 
> generating large i/o load by concurrently resuming many VMs - problem 
> always occurs within minute.
> 
> * on clean4.12.3:
> 
> BUG occurs on almost always first ABORT_TASK issued by vmware:
> 
> [...]
> Jul 27 17:06:40 teststorage [   31.336673] qla2xxx [0000:06:00.0]-ffff:12: qla24xx_do_nack_work create sess success ffff881f80d6dc00
> Jul 27 17:06:40 teststorage [  708.583638] Detected MISCOMPARE for addr: ffff881f8fb15000 buf: ffff881f7a46aa00
> Jul 27 17:06:40 teststorage [  708.583651] Target/iblock: Send MISCOMPARE check condition and sense
> Jul 27 17:06:42 teststorage [  710.627503] ABORT_TASK: Found referenced qla2xxx task_tag: 1168472
> Jul 27 17:06:43 teststorage [  711.454055] ------------[ cut here ]------------
> Jul 27 17:06:43 teststorage [  711.454062] kernel BUG at drivers/scsi/qla2xxx/qla_target.c:3643!
> Jul 27 17:06:43 teststorage [  711.454067] invalid opcode: 0000 [#1] SMP
> Jul 27 17:06:43 teststorage [  711.454070] Modules linked in: 
> tcm_qla2xxx target_core_user uio target_core_pscsi target_core_file 
> target_core_iblock iscsi_target_mod target_core_mod netconsole lm90 vfat 
> fat intel_rapl x86_pkg_temp_thermal coretemp crct10dif_pclmul ses 
> crc32_pclmul enclosure ghash_clmulni_intel scsi_transport_sas iTCO_wdt 
> iTCO_vendor_support lpc_ich i2c_i801 mei_me mei tpm_tis tpm_tis_core tpm 
> nfsd auth_rpcgss nfs_acl lockd grace dm_multipath sunrpc binfmt_misc 
> nouveau video drm_kms_helper ttm raid1 drm qla2xxx igb e1000e mxm_wmi 
> aacraid dca ptp crc32c_intel pps_core scsi_transport_fc i2c_algo_bit wmi
> Jul 27 17:06:43 teststorage [  711.454101] CPU: 3 PID: 209 Comm: kworker/u24:7 Not tainted 4.12.3 #1
> Jul 27 17:06:43 teststorage [  711.454104] Hardware name: ASUS All Series/X99-E WS/USB 3.1, BIOS 3402 11/14/2016
> Jul 27 17:06:43 teststorage [  711.454118] Workqueue: tmr-iblock target_tmr_work [target_core_mod]
> Jul 27 17:06:43 teststorage [  711.454122] task: ffff881f82173b00 task.stack: ffffc9000d770000
> Jul 27 17:06:43 teststorage [  711.454132] RIP: 0010:qlt_free_cmd+0x138/0x150 [qla2xxx]
> Jul 27 17:06:43 teststorage [  711.454135] RSP: 0018:ffffc9000d773d60 EFLAGS: 00010286
> Jul 27 17:06:43 teststorage [  711.454138] RAX: 0000000000000088 RBX: ffff881f8ebb8bf8 RCX: ffffffffa019fade
> Jul 27 17:06:43 teststorage [  711.454142] RDX: 000000000000e074 RSI: ffff881f76fc87c0 RDI: 0000000000004000
> Jul 27 17:06:43 teststorage [  711.454145] RBP: ffffc9000d773d80 R08: ffffffffa018c07c R09: ffff881f8ebb8bf8
> Jul 27 17:06:43 teststorage [  711.454148] R10: ffffea007e076ac0 R11: ffff881f81dab640 R12: ffff881f80d6d800
> Jul 27 17:06:43 teststorage [  711.454151] R13: ffff881f8ebb8c80 R14: 0000000000000286 R15: ffff881f8f5e2000
> Jul 27 17:06:43 teststorage [  711.454155] FS: 0000000000000000(0000) GS:ffff881f9f2c0000(0000) knlGS:0000000000000000
> Jul 27 17:06:43 teststorage [  711.454158] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> Jul 27 17:06:43 teststorage [  711.454161] CR2: 00007fff00782a68 CR3: 0000001f81e33000 CR4: 00000000003406e0
> Jul 27 17:06:43 teststorage [  711.454164] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
> Jul 27 17:06:43 teststorage [  711.454167] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
> Jul 27 17:06:43 teststorage [  711.454170] Call Trace:
> Jul 27 17:06:43 teststorage [  711.454176] tcm_qla2xxx_release_cmd+0x14/0x30 [tcm_qla2xxx]
> Jul 27 17:06:43 teststorage [  711.454183] target_put_sess_cmd+0xce/0x140 [target_core_mod]
> Jul 27 17:06:43 teststorage [  711.454190] core_tmr_abort_task+0x127/0x190 [target_core_mod]
> Jul 27 17:06:43 teststorage [  711.454197] target_tmr_work+0x111/0x120 [target_core_mod]
> Jul 27 17:06:43 teststorage [  711.454203] process_one_work+0x144/0x370
> Jul 27 17:06:43 teststorage [  711.454206] worker_thread+0x4d/0x3c0
> Jul 27 17:06:43 teststorage [  711.454210]  kthread+0x109/0x140
> Jul 27 17:06:43 teststorage [  711.454487]  ? rescuer_thread+0x360/0x360
> Jul 27 17:06:43 teststorage [  711.455029]  ? kthread_park+0x60/0x60
> Jul 27 17:06:43 teststorage [  711.455579] ret_from_fork+0x25/0x30
> Jul 27 17:06:43 teststorage [  711.456122] Code: 7f a6 73 e1 0f b6 83 8c 
> 02 00 00 e9 54 ff ff ff 48 8b bb c0 02 00 00 48 89 de e8 04 fd ff ff 0f 
> b6 83 8c 02 00 00 e9 35 ff ff ff <0f> 0b 48 8b bb 90 02 00 00 e8 8a e2 
> 0a e1 e9 44 ff ff ff 0f 0b
> Jul 27 17:06:43 teststorage [  711.457279] RIP: qlt_free_cmd+0x138/0x150 [qla2xxx] RSP: ffffc9000d773d60
> Jul 27 17:06:43 teststorage [  711.457857] ---[ end trace 99e519b9a5b6591b ]---
> 

Yes, this is most certainly the same bug the patch here addresses:

https://www.spinics.net/lists/target-devel/msg15759.html 

Also, a smaller version of that just went out with your CC' on it here:

qla2xxx: Fix incorrect tcm_qla2xxx_free_cmd use during TMR ABORT (v2)
https://git.kernel.org/pub/scm/linux/kernel/git/nab/target-pending.git/commit/?id=6bcbb3174caa5f1ccc894f8ae077631659d5a629

> 8<-----------
> 
> I have also tried patch from 
> https://www.spinics.net/lists/target-devel/msg15759.html 
> (4db6a8145940d0bbd10265020d681961ce2d3238 - currently not available in 
> git(?))
> 
> The results is - no BUGs, system survives a little longer, but it's a 
> matter of minutes when kworker hangs:
> 
> Jul 26 15:21:33 teststorage [ 3588.629920] ABORT_TASK: Found referenced qla2xxx task_tag: 1202220
> Jul 26 15:21:34 teststorage [ 3589.491615] ABORT_TASK: Sending TMR_FUNCTION_COMPLETE for ref_tag: 1202220
> Jul 26 15:21:34 teststorage [ 3589.491700] ABORT_TASK: Found referenced qla2xxx task_tag: 1202264
> Jul 26 15:25:16 teststorage [ 3810.752583] INFO: task kworker/u24:2:2975 blocked for more than 120 seconds.
> Jul 26 15:25:16 teststorage [ 3810.752672]       Not tainted 4.12.3 #1
> Jul 26 15:25:16 teststorage [ 3810.752749] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> Jul 26 15:25:16 teststorage [ 3810.752831] kworker/u24:2 D    0  2975      2 0x00000080
> Jul 26 15:25:16 teststorage [ 3810.752920] Workqueue: tmr-iblock target_tmr_work [target_core_mod]
> Jul 26 15:25:16 teststorage [ 3810.753006] Call Trace:
> Jul 26 15:25:16 teststorage [ 3810.753207] __schedule+0x285/0x840
> Jul 26 15:25:16 teststorage [ 3810.753410] schedule+0x36/0x80
> Jul 26 15:25:16 teststorage [ 3810.753623] schedule_timeout+0x242/0x2f0
> Jul 26 15:25:16 teststorage [ 3810.753832]  ? radix_tree_lookup+0xd/0x10
> Jul 26 15:25:16 teststorage [ 3810.754046]  ? get_work_pool+0x2d/0x40
> Jul 26 15:25:16 teststorage [ 3810.754263]  ? flush_work+0x14d/0x190
> Jul 26 15:25:16 teststorage [ 3810.754486] wait_for_completion+0x111/0x170
> Jul 26 15:25:16 teststorage [ 3810.754717]  ? wake_up_q+0x80/0x80
> Jul 26 15:25:16 teststorage [ 3810.754949] __transport_wait_for_tasks+0xa7/0x140 [target_core_mod]
> Jul 26 15:25:16 teststorage [ 3810.755189] transport_wait_for_tasks+0x53/0x90 [target_core_mod]
> Jul 26 15:25:16 teststorage [ 3810.755454] core_tmr_abort_task+0x10e/0x190 [target_core_mod]
> Jul 26 15:25:16 teststorage [ 3810.755717] target_tmr_work+0x111/0x120 [target_core_mod]
> Jul 26 15:25:16 teststorage [ 3810.755972] process_one_work+0x144/0x370
> Jul 26 15:25:16 teststorage [ 3810.756236] worker_thread+0x4d/0x3c0
> Jul 26 15:25:16 teststorage [ 3810.756507] kthread+0x109/0x140
> Jul 26 15:25:16 teststorage [ 3810.756785]  ? rescuer_thread+0x360/0x360
> Jul 26 15:25:16 teststorage [ 3810.757060]  ? kthread_park+0x60/0x60
> Jul 26 15:25:16 teststorage [ 3810.757348]  ? do_syscall_64+0x67/0x150
> Jul 26 15:25:16 teststorage [ 3810.757636] ret_from_fork+0x25/0x30
> Jul 26 15:25:16 teststorage [ 3810.757927] NMI backtrace for cpu 3
> Jul 26 15:25:16 teststorage [ 3810.758220] CPU: 3 PID: 107 Comm: khungtaskd Not tainted 4.12.3 #1
> Jul 26 15:25:16 teststorage [ 3810.758530] Hardware name: ASUS All Series/X99-E WS/USB 3.1, BIOS 3402 11/14/2016
> 

This looks almost identical to what Pascal reported.

Namely that target-core is waiting for a particular tag (1202264) during
ABORT_TASK, but the backend never completes it back to target-core.

As with Pascal, please apply the qla2xxx patch above along with the
following debug patch, so we can verify if this is the case:



> 
> (I have also tried 4.13-rc2, but currently I have some other problem 
> with initiating qla2xxx there ("qla2xxx 0000:09:00.0: can't allocate 
> MSI-X affinity masks for 2 vectors"), so I can't use FC target...)
> 
> I am willing to provide more information if needed - It's currently my 
> out-of-production storage and so if anyone can look at this problem I 
> can on my side experiment and play with patches, retest, etc.
> 
> Any help appreciated :)
> 

Also, some more details on what your backend device storage behind
target-core looks like would be helpful.

Physical HBAs, device information, and any MD/RAID/LVM/etc on top..

--
To unsubscribe from this list: send the line "unsubscribe target-devel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Comments

Łukasz Engel July 31, 2017, 3:15 p.m. UTC | #1 
Hi Nicolas,

W dniu 31.07.2017 o 02:00, Nicholas A. Bellinger pisze:
> Hi Lukasz,
>
> On Thu, 2017-07-27 at 17:23 +0200, Łukasz Engel wrote:
>> Hello
>>
>> I am experiencing problems using LIO FC target with vmware ESX (6.5).
>>
>> Thisis the same problem as discussed in
>> https://www.spinics.net/lists/target-devel/msg15670.html
>> I've tried 4.11.x (up to 12) and 4.12.3(and also some kernels from 4.9
>> line).
[...]
>> Yes, this is most certainly the same bug the patch here addresses:
>>
>> https://www.spinics.net/lists/target-devel/msg15759.html
>>
>> Also, a smaller version of that just went out with your CC' on it here:
>>
>> qla2xxx: Fix incorrect tcm_qla2xxx_free_cmd use during TMR ABORT (v2)
>> https://git.kernel.org/pub/scm/linux/kernel/git/nab/target-pending.git/commit/?id=6bcbb3174caa5f1ccc894f8ae077631659d5a629
After applying both patches (in 6bcbb3174caa5f1ccc894f8ae077631659d5a629 
manual adjusting in second chunk was required for 4.12.x - after-match 
is slightly different) - there is no BUG, but hang in kworker instead, 
with all I/Os from FC frozen:

Jul 31 16:27:14 teststorage [   42.897291] qla2xxx 
[0000:06:00.0]-500a:12: LOOP UP detected (4 Gbps).
Jul 31 16:27:16 teststorage [   42.959068] qla2xxx 
[0000:09:00.0]-ffff:11: qla24xx_do_nack_work create sess success 
ffff881f80e29200
Jul 31 16:27:16 teststorage [   44.144811] qla2xxx 
[0000:06:00.0]-ffff:12: qla24xx_do_nack_work create sess success 
ffff881f80e28400
Jul 31 16:27:16 teststorage [   44.230770] qla2xxx 
[0000:06:00.0]-ffff:12: qla24xx_do_nack_work create sess success 
ffff881f8f575a00
Jul 31 16:27:16 teststorage [   44.473650] qla2xxx 
[0000:06:00.0]-ffff:12: qla24xx_do_nack_work create sess success 
ffff881f8f575600
Jul 31 16:27:16 teststorage [   44.520821] qla2xxx 
[0000:06:00.0]-ffff:12: qla24xx_do_nack_work create sess success 
ffff881f8f574400
Jul 31 16:27:16 teststorage [   44.538183] qla2xxx 
[0000:06:00.0]-ffff:12: qla24xx_do_nack_work create sess success 
ffff881f900f3400
Jul 31 16:27:16 teststorage [   44.984052] qla2xxx 
[0000:06:00.0]-ffff:12: qla24xx_do_nack_work create sess success 
ffff881f8f577a00
Jul 31 16:28:54 teststorage [   45.042585] qla2xxx 
[0000:06:00.0]-ffff:12: qla24xx_do_nack_work create sess success 
ffff881f80e28000
Jul 31 16:28:54 teststorage [  142.431045] ABORT_TASK: Found referenced 
qla2xxx task_tag: 1189328
Jul 31 16:28:54 teststorage [  142.431059] ABORT_TASK: Sending 
TMR_TASK_DOES_NOT_EXIST for ref_tag: 1189328
Jul 31 16:28:57 teststorage [  145.632571] ABORT_TASK: Found referenced 
qla2xxx task_tag: 1177932
Jul 31 16:28:57 teststorage [  145.897299] ABORT_TASK: Sending 
TMR_FUNCTION_COMPLETE for ref_tag: 1177932
Jul 31 16:29:00 teststorage [  148.388569] ABORT_TASK: Found referenced 
qla2xxx task_tag: 1164160
Jul 31 16:32:00 teststorage [  328.848344] se_cmd waiting CDB: 0x89 tag: 
1164160 t_state: 5se_cmd_flags: 0x01c80109 transport_state: 0x00000033
Jul 31 16:32:41 teststorage [  369.808484] INFO: task kworker/1:93:2802 
blocked for more than 120 seconds.
Jul 31 16:32:41 teststorage [  369.808493]       Not tainted 4.12.3p1 #3
Jul 31 16:32:41 teststorage [  369.808496] "echo 0 > 
/proc/sys/kernel/hung_task_timeout_secs" disables this message.
Jul 31 16:32:41 teststorage [  369.808499] kworker/1:93    D    0 
2802      2 0x00000080
Jul 31 16:32:41 teststorage [  369.808515] Workqueue: events 
qlt_free_session_done [qla2xxx]
Jul 31 16:32:41 teststorage [  369.808518] Call Trace:
Jul 31 16:32:41 teststorage [  369.808524]  __schedule+0x285/0x840
Jul 31 16:32:41 teststorage [  369.808528]  schedule+0x36/0x80
Jul 31 16:32:41 teststorage [  369.808531] schedule_timeout+0x242/0x2f0
Jul 31 16:32:41 teststorage [  369.808537]  ? ttwu_do_activate+0x77/0x80
Jul 31 16:32:41 teststorage [  369.808540] wait_for_completion+0x111/0x170
Jul 31 16:32:41 teststorage [  369.808544]  ? wake_up_q+0x80/0x80
Jul 31 16:32:41 teststorage [  369.808555] 
target_wait_for_sess_cmds+0x49/0x170 [target_core_mod]
Jul 31 16:32:41 teststorage [  369.808560] 
tcm_qla2xxx_free_session+0x45/0x90 [tcm_qla2xxx]
Jul 31 16:32:41 teststorage [  369.808572] 
qlt_free_session_done+0x109/0x5a0 [qla2xxx]
Jul 31 16:32:41 teststorage [  369.808579]  ? qlt_unreg_sess+0xe7/0xf0 
[qla2xxx]
Jul 31 16:32:41 teststorage [  369.808583]  ? 
tcm_qla2xxx_put_sess+0x3c/0x50 [tcm_qla2xxx]
Jul 31 16:32:41 teststorage [  369.808587] process_one_work+0x144/0x370
Jul 31 16:32:41 teststorage [  369.808591]  worker_thread+0x4d/0x3c0
Jul 31 16:32:41 teststorage [  369.808594]  kthread+0x109/0x140
Jul 31 16:32:41 teststorage [  369.808597]  ? rescuer_thread+0x360/0x360
Jul 31 16:32:41 teststorage [  369.808600]  ? kthread_park+0x60/0x60
Jul 31 16:32:41 teststorage [  369.808720]  ret_from_fork+0x25/0x30
Jul 31 16:32:41 teststorage [  369.809016] NMI backtrace for cpu 3
Jul 31 16:32:41 teststorage [  369.809446] CPU: 3 PID: 107 Comm: 
khungtaskd Not tainted 4.12.3p1 #3
Jul 31 16:32:41 teststorage [  369.809886] Hardware name: ASUS All 
Series/X99-E WS/USB 3.1, BIOS 3402 11/14/2016
Jul 31 16:32:41 teststorage [  369.810326] Call Trace:
Jul 31 16:32:41 teststorage [  369.810764]  dump_stack+0x63/0x8e
Jul 31 16:32:41 teststorage [  369.811190] nmi_cpu_backtrace+0x9b/0xa0
Jul 31 16:32:41 teststorage [  369.811613]  ? 
irq_force_complete_move+0xf0/0xf0
Jul 31 16:32:41 teststorage [  369.812036] 
nmi_trigger_cpumask_backtrace+0x99/0xd0
Jul 31 16:32:41 teststorage [  369.812461] 
arch_trigger_cpumask_backtrace+0x19/0x20
Jul 31 16:32:41 teststorage [  369.812890]  watchdog+0x2c7/0x340
Jul 31 16:32:41 teststorage [  369.813321]  kthread+0x109/0x140
Jul 31 16:32:41 teststorage [  369.813748]  ? 
reset_hung_task_detector+0x20/0x20
Jul 31 16:32:41 teststorage [  369.814171]  ? kthread_park+0x60/0x60
Jul 31 16:32:41 teststorage [  369.814595]  ? kthread_park+0x60/0x60
Jul 31 16:32:41 teststorage [  369.815013]  ret_from_fork+0x25/0x30
Jul 31 16:32:41 teststorage [  369.815428] Sending NMI from CPU 3 to 
CPUs 0-2,4-11:
Jul 31 16:32:41 teststorage [  369.815846] NMI backtrace for cpu 0 
skipped: idling at pc 0xffffffff818b5ac6
Jul 31 16:32:41 teststorage [  369.815946] NMI backtrace for cpu 1 
skipped: idling at pc 0xffffffff818b5ac6
Jul 31 16:32:41 teststorage [  369.816045] NMI backtrace for cpu 2 
skipped: idling at pc 0xffffffff818b5ac6
Jul 31 16:32:41 teststorage [  369.816146] NMI backtrace for cpu 4 
skipped: idling at pc 0xffffffff818b5ac6
Jul 31 16:32:41 teststorage [  369.816247] NMI backtrace for cpu 5 
skipped: idling at pc 0xffffffff818b5ac6
Jul 31 16:32:41 teststorage [  369.816352] NMI backtrace for cpu 6 
skipped: idling at pc 0xffffffff818b5ac6
Jul 31 16:32:41 teststorage [  369.816446] NMI backtrace for cpu 7 
skipped: idling at pc 0xffffffff818b5ac6
Jul 31 16:32:41 teststorage [  369.816547] NMI backtrace for cpu 8 
skipped: idling at pc 0xffffffff818b5ac6
Jul 31 16:32:41 teststorage [  369.816648] NMI backtrace for cpu 9 
skipped: idling at pc 0xffffffff818b5ac6
Jul 31 16:32:41 teststorage [  369.816747] NMI backtrace for cpu 10 
skipped: idling at pc 0xffffffff818b5ac6
Jul 31 16:32:41 teststorage [  369.816851] NMI backtrace for cpu 11 
skipped: idling at pc 0xffffffff818b5ac6
Jul 31 16:32:41 teststorage [  369.816855] Kernel panic - not syncing: 
hung_task: blocked tasks
Jul 31 16:32:41 teststorage [  369.816857] CPU: 3 PID: 107 Comm: 
khungtaskd Not tainted 4.12.3p1 #3
Jul 31 16:32:41 teststorage [  369.816857] Hardware name: ASUS All 
Series/X99-E WS/USB 3.1, BIOS 3402 11/14/2016
Jul 31 16:32:41 teststorage [  369.816857] Call Trace:
Jul 31 16:32:41 teststorage [  369.816859]  dump_stack+0x63/0x8e
Jul 31 16:32:41 teststorage [  369.816861]  panic+0xeb/0x239
Jul 31 16:32:41 teststorage [  369.816863]  watchdog+0x2d5/0x340
Jul 31 16:32:41 teststorage [  369.816864]  kthread+0x109/0x140
Jul 31 16:32:41 teststorage [  369.816864]  ? 
reset_hung_task_detector+0x20/0x20
Jul 31 16:32:41 teststorage [  369.816865]  ? kthread_park+0x60/0x60
Jul 31 16:32:41 teststorage [  369.816866]  ? kthread_park+0x60/0x60
Jul 31 16:32:41 teststorage [  369.816866]  ret_from_fork+0x25/0x30

8<=====

> Also, some more details on what your backend device storage behind
> target-core looks like would be helpful.
>
> Physical HBAs, device information, and any MD/RAID/LVM/etc on top..
>
I have adaptec 7805 HW RAID (6x SAS 600G 15k hdd in RAID0) - exporting 1 
device to system (sdc),
LVM sits on this device and LV (vgtest/test) is used as LIO block 
backstore and is exported to ESXs.
(for system I have separate 2 SATA HDDs in software raid1 + LVM)

[root@TESTSTORAGE ~]# lsblk
NAME                MAJ:MIN RM   SIZE RO TYPE  MOUNTPOINT
sdb                   8:16   0 465,8G  0 disk
└─md126               9:126  0 465,8G  0 raid1
   ├─md126p3         259:2    0   314G  0 md
   │ ├─vgsystem-swap 253:1    0    64G  0 lvm
   │ ├─vgsystem-root 253:0    0   100G  0 lvm   /
   │ └─vgsystem-home 253:3    0   200G  0 lvm   /home
   ├─md126p1         259:0    0   200M  0 md    /boot/efi
   ├─md126p4         259:3    0 150,6G  0 md
   │ └─vgsystem-root 253:0    0   100G  0 lvm   /
   └─md126p2         259:1    0     1G  0 md    /boot
sdc                   8:32   1   3,3T  0 disk
└─vgtest-test       253:2    0   3,3T  0 lvm
sda                   8:0    0 465,8G  0 disk
└─md126               9:126  0 465,8G  0 raid1
   ├─md126p3         259:2    0   314G  0 md
   │ ├─vgsystem-swap 253:1    0    64G  0 lvm
   │ ├─vgsystem-root 253:0    0   100G  0 lvm   /
   │ └─vgsystem-home 253:3    0   200G  0 lvm   /home
   ├─md126p1         259:0    0   200M  0 md    /boot/efi
   ├─md126p4         259:3    0 150,6G  0 md
   │ └─vgsystem-root 253:0    0   100G  0 lvm   /
   └─md126p2         259:1    0     1G  0 md    /boot

8<=========
Nicholas A. Bellinger Aug. 6, 2017, 10:28 p.m. UTC | #2 
Hi Lukasz,

(Adding Pascal CC', as he's been seeing something similar with MD
backend storage)

Thanks alot for the follow up.  Comments below.

On Mon, 2017-07-31 at 17:15 +0200, Łukasz Engel wrote:
> Hi Nicolas,
> 
> W dniu 31.07.2017 o 02:00, Nicholas A. Bellinger pisze:
> > Hi Lukasz,
> >
> > On Thu, 2017-07-27 at 17:23 +0200, Łukasz Engel wrote:
> >> Hello
> >>
> >> I am experiencing problems using LIO FC target with vmware ESX (6.5).
> >>
> >> Thisis the same problem as discussed in
> >> https://www.spinics.net/lists/target-devel/msg15670.html
> >> I've tried 4.11.x (up to 12) and 4.12.3(and also some kernels from 4.9
> >> line).
> [...]
> >> Yes, this is most certainly the same bug the patch here addresses:
> >>
> >> https://www.spinics.net/lists/target-devel/msg15759.html
> >>
> >> Also, a smaller version of that just went out with your CC' on it here:
> >>
> >> qla2xxx: Fix incorrect tcm_qla2xxx_free_cmd use during TMR ABORT (v2)
> >> https://git.kernel.org/pub/scm/linux/kernel/git/nab/target-pending.git/commit/?id=6bcbb3174caa5f1ccc894f8ae077631659d5a629
> After applying both patches (in 6bcbb3174caa5f1ccc894f8ae077631659d5a629 
> manual adjusting in second chunk was required for 4.12.x - after-match 
> is slightly different) - there is no BUG, but hang in kworker instead, 
> with all I/Os from FC frozen:
> 
> Jul 31 16:27:14 teststorage [   42.897291] qla2xxx [0000:06:00.0]-500a:12: LOOP UP detected (4 Gbps).
> Jul 31 16:27:16 teststorage [   42.959068] qla2xxx [0000:09:00.0]-ffff:11: qla24xx_do_nack_work create sess success ffff881f80e29200
> Jul 31 16:27:16 teststorage [   44.144811] qla2xxx [0000:06:00.0]-ffff:12: qla24xx_do_nack_work create sess success ffff881f80e28400
> Jul 31 16:27:16 teststorage [   44.230770] qla2xxx [0000:06:00.0]-ffff:12: qla24xx_do_nack_work create sess success ffff881f8f575a00
> Jul 31 16:27:16 teststorage [   44.473650] qla2xxx [0000:06:00.0]-ffff:12: qla24xx_do_nack_work create sess success ffff881f8f575600
> Jul 31 16:27:16 teststorage [   44.520821] qla2xxx [0000:06:00.0]-ffff:12: qla24xx_do_nack_work create sess success ffff881f8f574400
> Jul 31 16:27:16 teststorage [   44.538183] qla2xxx [0000:06:00.0]-ffff:12: qla24xx_do_nack_work create sess success ffff881f900f3400
> Jul 31 16:27:16 teststorage [   44.984052] qla2xxx [0000:06:00.0]-ffff:12: qla24xx_do_nack_work create sess success ffff881f8f577a00
> Jul 31 16:28:54 teststorage [   45.042585] qla2xxx [0000:06:00.0]-ffff:12: qla24xx_do_nack_work create sess success ffff881f80e28000
> Jul 31 16:28:54 teststorage [  142.431045] ABORT_TASK: Found referenced qla2xxx task_tag: 1189328
> Jul 31 16:28:54 teststorage [  142.431059] ABORT_TASK: Sending TMR_TASK_DOES_NOT_EXIST for ref_tag: 1189328
> Jul 31 16:28:57 teststorage [  145.632571] ABORT_TASK: Found referenced qla2xxx task_tag: 1177932
> Jul 31 16:28:57 teststorage [  145.897299] ABORT_TASK: Sending TMR_FUNCTION_COMPLETE for ref_tag: 1177932
> Jul 31 16:29:00 teststorage [  148.388569] ABORT_TASK: Found referenced qla2xxx task_tag: 1164160
> Jul 31 16:32:00 teststorage [  328.848344] se_cmd waiting CDB: 0x89 tag: 1164160 t_state: 5 se_cmd_flags: 0x01c80109 transport_state: 0x00000033

Perfect.  This is very helpful to understand state of the I/O triggering
ESX host ABORTs, and that blocks waiting for completion from backend
storage.

Here's what the above debug translates to:

CDB: 0x89 = COMPARE_AND_WRITE (eg: VAAI AtomicTestandSet)
t_state: 5 = TRANSPORT_PROCESSING

se_cmd_flags: 0x01c80109 =

   SCF_SUPPORTED_SAM_OPCODE | SCF_SCSI_DATA_CDB | SCF_SE_LUN_CMD |
   SCF_COMPARE_AND_WRITE | SCF_ACK_KREF | SCF_USE_CPUID | SCF_TASK_ATTR_SET

transport_state: 0x00000033 =

   CMD_T_ABORTED | CMD_T_ACTIVE | CMD_T_SENT | CMD_T_STOP

Note COMPARE_AND_WRITE wrt to backend I/O consists of two phases.  First
phase is a READ and comparison against the first part of the received
buffer.  If the comparison matches, then the second phase sends a WRITE
with the second part of the received buffer to complete the update.

So according to the above output, the first phase of COMPARE_AND_WRITE
dispatched the READ into backend storage.  The READ did not complete,
and subsequently ESX sent an ABORT_TASK for it (tag: 1164160).  The
ABORT_TASK successfully found the I/O still outstanding to backend
storage, and blocks waiting for it to complete..

The debug printing 'se_cmd waiting ..' message shows every 180 seconds,
so it's clear I/O completion from backend storage is not happening back
to IBLOCK -> target-core for an extended amount of time.

Btw, I've been simulating this same scenario by delaying backend storage
I/O completion, and thus far once the first phase READ of
COMPARE_AND_WRITE eventually returns back to IBLOCK -> target-core, then
ABORT_TASK is able to complete and everything else continues to function
as expected.

That said, thus far the evidence is pointing to a backend device issue,
where that first READ phase of the COMPARE_AND_WRITE is (never..?)
completed back to IBLOCK -> target-core.

More below on how to verify this.

> Jul 31 16:32:41 teststorage [  369.808484] INFO: task kworker/1:93:2802  blocked for more than 120 seconds.
> Jul 31 16:32:41 teststorage [  369.808493]       Not tainted 4.12.3p1 #3
> Jul 31 16:32:41 teststorage [  369.808496] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> Jul 31 16:32:41 teststorage [  369.808499] kworker/1:93    D    0 2802      2 0x00000080
> Jul 31 16:32:41 teststorage [  369.808515] Workqueue: events qlt_free_session_done [qla2xxx]
> Jul 31 16:32:41 teststorage [  369.808518] Call Trace:
> Jul 31 16:32:41 teststorage [  369.808524]  __schedule+0x285/0x840
> Jul 31 16:32:41 teststorage [  369.808528]  schedule+0x36/0x80
> Jul 31 16:32:41 teststorage [  369.808531] schedule_timeout+0x242/0x2f0
> Jul 31 16:32:41 teststorage [  369.808537]  ? ttwu_do_activate+0x77/0x80
> Jul 31 16:32:41 teststorage [  369.808540] wait_for_completion+0x111/0x170
> Jul 31 16:32:41 teststorage [  369.808544]  ? wake_up_q+0x80/0x80
> Jul 31 16:32:41 teststorage [  369.808555] target_wait_for_sess_cmds+0x49/0x170 [target_core_mod]
> Jul 31 16:32:41 teststorage [  369.808560] tcm_qla2xxx_free_session+0x45/0x90 [tcm_qla2xxx]
> Jul 31 16:32:41 teststorage [  369.808572] qlt_free_session_done+0x109/0x5a0 [qla2xxx]
> Jul 31 16:32:41 teststorage [  369.808579]  ? qlt_unreg_sess+0xe7/0xf0 [qla2xxx]
> Jul 31 16:32:41 teststorage [  369.808583]  ? tcm_qla2xxx_put_sess+0x3c/0x50 [tcm_qla2xxx]
> Jul 31 16:32:41 teststorage [  369.808587] process_one_work+0x144/0x370
> Jul 31 16:32:41 teststorage [  369.808591]  worker_thread+0x4d/0x3c0
> Jul 31 16:32:41 teststorage [  369.808594]  kthread+0x109/0x140
> Jul 31 16:32:41 teststorage [  369.808597]  ? rescuer_thread+0x360/0x360
> Jul 31 16:32:41 teststorage [  369.808600]  ? kthread_park+0x60/0x60
> Jul 31 16:32:41 teststorage [  369.808720]  ret_from_fork+0x25/0x30
> Jul 31 16:32:41 teststorage [  369.809016] NMI backtrace for cpu 3
> Jul 31 16:32:41 teststorage [  369.809446] CPU: 3 PID: 107 Comm: khungtaskd Not tainted 4.12.3p1 #3
> Jul 31 16:32:41 teststorage [  369.809886] Hardware name: ASUS All Series/X99-E WS/USB 3.1, BIOS 3402 11/14/2016
> Jul 31 16:32:41 teststorage [  369.810326] Call Trace:
> Jul 31 16:32:41 teststorage [  369.810764]  dump_stack+0x63/0x8e
> Jul 31 16:32:41 teststorage [  369.811190] nmi_cpu_backtrace+0x9b/0xa0
> Jul 31 16:32:41 teststorage [  369.811613]  ? irq_force_complete_move+0xf0/0xf0
> Jul 31 16:32:41 teststorage [  369.812036] nmi_trigger_cpumask_backtrace+0x99/0xd0
> Jul 31 16:32:41 teststorage [  369.812461] arch_trigger_cpumask_backtrace+0x19/0x20
> Jul 31 16:32:41 teststorage [  369.812890]  watchdog+0x2c7/0x340
> Jul 31 16:32:41 teststorage [  369.813321]  kthread+0x109/0x140
> Jul 31 16:32:41 teststorage [  369.813748]  ? reset_hung_task_detector+0x20/0x20
> Jul 31 16:32:41 teststorage [  369.814171]  ? kthread_park+0x60/0x60
> Jul 31 16:32:41 teststorage [  369.814595]  ? kthread_park+0x60/0x60
> Jul 31 16:32:41 teststorage [  369.815013]  ret_from_fork+0x25/0x30
> Jul 31 16:32:41 teststorage [  369.815428] Sending NMI from CPU 3 to CPUs 0-2,4-11:
> Jul 31 16:32:41 teststorage [  369.815846] NMI backtrace for cpu 0 skipped: idling at pc 0xffffffff818b5ac6
> Jul 31 16:32:41 teststorage [  369.815946] NMI backtrace for cpu 1 skipped: idling at pc 0xffffffff818b5ac6
> Jul 31 16:32:41 teststorage [  369.816045] NMI backtrace for cpu 2 skipped: idling at pc 0xffffffff818b5ac6
> Jul 31 16:32:41 teststorage [  369.816146] NMI backtrace for cpu 4 skipped: idling at pc 0xffffffff818b5ac6
> Jul 31 16:32:41 teststorage [  369.816247] NMI backtrace for cpu 5 skipped: idling at pc 0xffffffff818b5ac6
> Jul 31 16:32:41 teststorage [  369.816352] NMI backtrace for cpu 6 skipped: idling at pc 0xffffffff818b5ac6
> Jul 31 16:32:41 teststorage [  369.816446] NMI backtrace for cpu 7 skipped: idling at pc 0xffffffff818b5ac6
> Jul 31 16:32:41 teststorage [  369.816547] NMI backtrace for cpu 8 skipped: idling at pc 0xffffffff818b5ac6
> Jul 31 16:32:41 teststorage [  369.816648] NMI backtrace for cpu 9 skipped: idling at pc 0xffffffff818b5ac6
> Jul 31 16:32:41 teststorage [  369.816747] NMI backtrace for cpu 10 skipped: idling at pc 0xffffffff818b5ac6
> Jul 31 16:32:41 teststorage [  369.816851] NMI backtrace for cpu 11 skipped: idling at pc 0xffffffff818b5ac6
> Jul 31 16:32:41 teststorage [  369.816855] Kernel panic - not syncing: hung_task: blocked tasks
> Jul 31 16:32:41 teststorage [  369.816857] CPU: 3 PID: 107 Comm: khungtaskd Not tainted 4.12.3p1 #3
> Jul 31 16:32:41 teststorage [  369.816857] Hardware name: ASUS All Series/X99-E WS/USB 3.1, BIOS 3402 11/14/2016
> Jul 31 16:32:41 teststorage [  369.816857] Call Trace:
> Jul 31 16:32:41 teststorage [  369.816859]  dump_stack+0x63/0x8e
> Jul 31 16:32:41 teststorage [  369.816861]  panic+0xeb/0x239
> Jul 31 16:32:41 teststorage [  369.816863]  watchdog+0x2d5/0x340
> Jul 31 16:32:41 teststorage [  369.816864]  kthread+0x109/0x140
> Jul 31 16:32:41 teststorage [  369.816864]  ? reset_hung_task_detector+0x20/0x20
> Jul 31 16:32:41 teststorage [  369.816865]  ? kthread_park+0x60/0x60
> Jul 31 16:32:41 teststorage [  369.816866]  ? kthread_park+0x60/0x60
> Jul 31 16:32:41 teststorage [  369.816866]  ret_from_fork+0x25/0x30
> 

Btw, it looks like this system is running with:

   CONFIG_BOOTPARAM_HUNG_TASK_PANIC_VALUE=1

which triggers a crash as soon as any hung task is detected.

I'd recommend to set to this '0' for now, to monitor what's going on
while hung tasks are occurring.

Also, this can be set at boot time via hung_task_panic=0.

> 8<=====
> 
> > Also, some more details on what your backend device storage behind
> > target-core looks like would be helpful.
> >
> > Physical HBAs, device information, and any MD/RAID/LVM/etc on top..
> >
> I have adaptec 7805 HW RAID (6x SAS 600G 15k hdd in RAID0) - exporting 1 
> device to system (sdc),
> LVM sits on this device and LV (vgtest/test) is used as LIO block 
> backstore and is exported to ESXs.
> (for system I have separate 2 SATA HDDs in software raid1 + LVM)
> 
> [root@TESTSTORAGE ~]# lsblk
> NAME                MAJ:MIN RM   SIZE RO TYPE  MOUNTPOINT
> sdb                   8:16   0 465,8G  0 disk
> └─md126               9:126  0 465,8G  0 raid1
>    ├─md126p3         259:2    0   314G  0 md
>    │ ├─vgsystem-swap 253:1    0    64G  0 lvm
>    │ ├─vgsystem-root 253:0    0   100G  0 lvm   /
>    │ └─vgsystem-home 253:3    0   200G  0 lvm   /home
>    ├─md126p1         259:0    0   200M  0 md    /boot/efi
>    ├─md126p4         259:3    0 150,6G  0 md
>    │ └─vgsystem-root 253:0    0   100G  0 lvm   /
>    └─md126p2         259:1    0     1G  0 md    /boot
> sdc                   8:32   1   3,3T  0 disk
> └─vgtest-test       253:2    0   3,3T  0 lvm
> sda                   8:0    0 465,8G  0 disk
> └─md126               9:126  0 465,8G  0 raid1
>    ├─md126p3         259:2    0   314G  0 md
>    │ ├─vgsystem-swap 253:1    0    64G  0 lvm
>    │ ├─vgsystem-root 253:0    0   100G  0 lvm   /
>    │ └─vgsystem-home 253:3    0   200G  0 lvm   /home
>    ├─md126p1         259:0    0   200M  0 md    /boot/efi
>    ├─md126p4         259:3    0 150,6G  0 md
>    │ └─vgsystem-root 253:0    0   100G  0 lvm   /
>    └─md126p2         259:1    0     1G  0 md    /boot
> 
> 8<=========
> 

OK, the vgtest-test LVM is backed by a single SCSI device (sdc), there
is a simple test to see if the SCSI device is holding onto I/Os.

Once the hung task triggers, check out:

   chead /sys/block/sdc/inflight

This will show how many I/Os are outstanding to the underlying SCSI
device.

IIRC, md and lvm devices don't use 'inflight' counters, so this is only
useful for verifying the number of I/Os outstanding to the underlying
SCSI device.  So if it's possible, I'd recommend verifying with the raw
SCSI device with BLOCK export as well, to isolate if it's something
specific to LVM that's causing I/Os not to be completed.

Thanks again for your detailed bug-report.

--
To unsubscribe from this list: send the line "unsubscribe target-devel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html
Łukasz Engel Aug. 8, 2017, 9 p.m. UTC | #3 
Hi Nicolas,


W dniu 07.08.2017 o 00:28, Nicholas A. Bellinger pisze:
> Hi Lukasz,
>
> (Adding Pascal CC', as he's been seeing something similar with MD
> backend storage)
>
> Thanks alot for the follow up.  Comments below.
>
> On Mon, 2017-07-31 at 17:15 +0200, Łukasz Engel wrote:
>> Hi Nicolas,
>>
>> W dniu 31.07.2017 o 02:00, Nicholas A. Bellinger pisze:
[...]
>> Jul 31 16:28:54 teststorage [ 142.431045] ABORT_TASK: Found 
>> referenced qla2xxx task_tag: 1189328
>> Jul 31 16:28:54 teststorage [  142.431059] ABORT_TASK: Sending TMR_TASK_DOES_NOT_EXIST for ref_tag: 1189328
>> Jul 31 16:28:57 teststorage [  145.632571] ABORT_TASK: Found referenced qla2xxx task_tag: 1177932
>> Jul 31 16:28:57 teststorage [  145.897299] ABORT_TASK: Sending TMR_FUNCTION_COMPLETE for ref_tag: 1177932
>> Jul 31 16:29:00 teststorage [  148.388569] ABORT_TASK: Found referenced qla2xxx task_tag: 1164160
>> Jul 31 16:32:00 teststorage [  328.848344] se_cmd waiting CDB: 0x89 tag: 1164160 t_state: 5 se_cmd_flags: 0x01c80109 transport_state: 0x00000033
> Perfect.  This is very helpful to understand state of the I/O triggering
> ESX host ABORTs, and that blocks waiting for completion from backend
> storage.
>
> Here's what the above debug translates to:
>
> CDB: 0x89 = COMPARE_AND_WRITE (eg: VAAI AtomicTestandSet)
> t_state: 5 = TRANSPORT_PROCESSING
>
> se_cmd_flags: 0x01c80109 =
>
>     SCF_SUPPORTED_SAM_OPCODE | SCF_SCSI_DATA_CDB | SCF_SE_LUN_CMD |
>     SCF_COMPARE_AND_WRITE | SCF_ACK_KREF | SCF_USE_CPUID | SCF_TASK_ATTR_SET
>
> transport_state: 0x00000033 =
>
>     CMD_T_ABORTED | CMD_T_ACTIVE | CMD_T_SENT | CMD_T_STOP
>
> Note COMPARE_AND_WRITE wrt to backend I/O consists of two phases.  First
> phase is a READ and comparison against the first part of the received
> buffer.  If the comparison matches, then the second phase sends a WRITE
> with the second part of the received buffer to complete the update.
>
> So according to the above output, the first phase of COMPARE_AND_WRITE
> dispatched the READ into backend storage.  The READ did not complete,
> and subsequently ESX sent an ABORT_TASK for it (tag: 1164160).  The
> ABORT_TASK successfully found the I/O still outstanding to backend
> storage, and blocks waiting for it to complete..
>
> The debug printing 'se_cmd waiting ..' message shows every 180 seconds,
> so it's clear I/O completion from backend storage is not happening back
> to IBLOCK -> target-core for an extended amount of time.
>
> Btw, I've been simulating this same scenario by delaying backend storage
> I/O completion, and thus far once the first phase READ of
> COMPARE_AND_WRITE eventually returns back to IBLOCK -> target-core, then
> ABORT_TASK is able to complete and everything else continues to function
> as expected.
>
> That said, thus far the evidence is pointing to a backend device issue,
> where that first READ phase of the COMPARE_AND_WRITE is (never..?)
> completed back to IBLOCK -> target-core.
>
> More below on how to verify this.
[...]
> Btw, it looks like this system is running with:
>
>     CONFIG_BOOTPARAM_HUNG_TASK_PANIC_VALUE=1
>
> which triggers a crash as soon as any hung task is detected.
>
> I'd recommend to set to this '0' for now, to monitor what's going on
> while hung tasks are occurring.
>
> Also, this can be set at boot time via hung_task_panic=0.
Yes, it was planned. Of course for checking "after hung-task" situation 
I've disabled this now...

>
>>> Also, some more details on what your backend device storage behind
>>> target-core looks like would be helpful.
>>>
>>> Physical HBAs, device information, and any MD/RAID/LVM/etc on top..
>>>
>> I have adaptec 7805 HW RAID (6x SAS 600G 15k hdd in RAID0) - exporting 1
>> device to system (sdc),
>> LVM sits on this device and LV (vgtest/test) is used as LIO block
>> backstore and is exported to ESXs.
>> (for system I have separate 2 SATA HDDs in software raid1 + LVM)
[...]
>> OK, the vgtest-test LVM is backed by a single SCSI device (sdc), there
>> is a simple test to see if the SCSI device is holding onto I/Os.
>>
>> Once the hung task triggers, check out:
>>
>>     chead /sys/block/sdc/inflight
>>
>> This will show how many I/Os are outstanding to the underlying SCSI
>> device.
>>
>> IIRC, md and lvm devices don't use 'inflight' counters, so this is only
>> useful for verifying the number of I/Os outstanding to the underlying
>> SCSI device.  So if it's possible, I'd recommend verifying with the raw
>> SCSI device with BLOCK export as well, to isolate if it's something
>> specific to LVM that's causing I/Os not to be completed.
>>
>> Thanks again for your detailed bug-report.
>>
I re-run my test without LVM (sdc directly exported as target's backstore).
Result is the same as with LVM - kworker blocked waiting for i/o 
completion, with identical "se_cmd waiting" report (excluding tag value 
of course). (My personal feeling is it took a little longer to block 
than with lvm)
I checked inflight counters for sdc - There were some non-zero values 
during i/o activity (as excected) and in final state (when "se_cmd 
waiting ..." or hung task is reported) there are zeros there.

Tomorrow I plan to retest using different sas controller which I have on 
shelf (LSI).
We will see if it's replicable in that configuration, but as Pascal got 
this for quite different setup than mine I expect to got similar results.

Personally for me (If I properly understand your description) it looks 
like in some situation i/o completion notification for read part of TAS 
operation "got lost" somewhere in block/target layer. (And then timeout 
for operation kicks in esx and it sends ABORT_TASK for this operation)


(BTW - I saw some non-zero values also for dm-* inflight counters during 
i/o activity, so it looks lvm currently (4.12) provide inflight  stats )

I will let you know tomorrow abount my findings
Łukasz Engel Aug. 9, 2017, 2:57 p.m. UTC | #4 
Hi Nicolas,

W dniu 08.08.2017 o 23:00, Łukasz Engel pisze:
> Hi Nicolas,
>
>
[...]
> Tomorrow I plan to retest using different sas controller which I have 
> on shelf (LSI).
> We will see if it's replicable in that configuration, but as Pascal 
> got this for quite different setup than mine I expect to got similar 
> results.
>
> Personally for me (If I properly understand your description) it looks 
> like in some situation i/o completion notification for read part of 
> TAS operation "got lost" somewhere in block/target layer. (And then 
> timeout for operation kicks in esx and it sends ABORT_TASK for this 
> operation)
>
>
> (BTW - I saw some non-zero values also for dm-* inflight counters 
> during i/o activity, so it looks lvm currently (4.12) provide 
> inflight  stats )
>
> I will let you know tomorrow abount my findings
>

With LSI controller (HW RAID0 built on same 6 HDDs ), without LVM - same 
results:

Aug  9 15:49:32 TESTSTORAGE kernel: Detected MISCOMPARE for addr: 
ffff881f901e0000 buf: ffff881f83c5c800
Aug  9 15:49:32 TESTSTORAGE kernel: Target/iblock: Send MISCOMPARE check 
condition and sense
Aug  9 15:49:32 TESTSTORAGE kernel: Detected MISCOMPARE for addr: 
ffff881f83e57000 buf: ffff881f83c5c800
Aug  9 15:49:32 TESTSTORAGE kernel: Target/iblock: Send MISCOMPARE check 
condition and sense
Aug  9 15:49:32 TESTSTORAGE kernel: Detected MISCOMPARE for addr: 
ffff881f7ee51000 buf: ffff881f83c5c800
Aug  9 15:49:32 TESTSTORAGE kernel: Target/iblock: Send MISCOMPARE check 
condition and sense
Aug  9 15:49:32 TESTSTORAGE kernel: Detected MISCOMPARE for addr: 
ffff881f81745000 buf: ffff881f83c5c800
Aug  9 15:49:32 TESTSTORAGE kernel: Target/iblock: Send MISCOMPARE check 
condition and sense
Aug  9 15:49:33 TESTSTORAGE kernel: Detected MISCOMPARE for addr: 
ffff881f7ef99000 buf: ffff881f83c5c800
Aug  9 15:49:33 TESTSTORAGE kernel: Target/iblock: Send MISCOMPARE check 
condition and sense
Aug  9 15:49:33 TESTSTORAGE kernel: Detected MISCOMPARE for addr: 
ffff881f7e56a000 buf: ffff881f83c5c800
Aug  9 15:49:33 TESTSTORAGE kernel: Target/iblock: Send MISCOMPARE check 
condition and sense
Aug  9 15:49:33 TESTSTORAGE kernel: Detected MISCOMPARE for addr: 
ffff881f7edf1000 buf: ffff881f83c5c800
Aug  9 15:49:33 TESTSTORAGE kernel: Target/iblock: Send MISCOMPARE check 
condition and sense
Aug  9 15:49:33 TESTSTORAGE kernel: Detected MISCOMPARE for addr: 
ffff881f8faaa000 buf: ffff881f83c5c800
Aug  9 15:49:33 TESTSTORAGE kernel: Target/iblock: Send MISCOMPARE check 
condition and sense
Aug  9 15:49:37 TESTSTORAGE kernel: Detected MISCOMPARE for addr: 
ffff881f815d1000 buf: ffff881f83c5fa00
Aug  9 15:49:37 TESTSTORAGE kernel: Target/iblock: Send MISCOMPARE check 
condition and sense
Aug  9 15:49:37 TESTSTORAGE kernel: Detected MISCOMPARE for addr: 
ffff881f8146e000 buf: ffff881f83c5f200
Aug  9 15:49:37 TESTSTORAGE kernel: Target/iblock: Send MISCOMPARE check 
condition and sense
Aug  9 15:49:37 TESTSTORAGE kernel: ABORT_TASK: Found referenced qla2xxx 
task_tag: 1138156
Aug  9 15:49:37 TESTSTORAGE kernel: ABORT_TASK: Sending 
TMR_TASK_DOES_NOT_EXIST for ref_tag: 1138156
Aug  9 15:49:37 TESTSTORAGE kernel: ABORT_TASK: Found referenced qla2xxx 
task_tag: 1138200
Aug  9 15:49:37 TESTSTORAGE kernel: ABORT_TASK: Sending 
TMR_TASK_DOES_NOT_EXIST for ref_tag: 1138200
Aug  9 15:49:50 TESTSTORAGE kernel: ABORT_TASK: Found referenced qla2xxx 
task_tag: 1193992
Aug  9 15:49:52 TESTSTORAGE kernel: ABORT_TASK: Sending 
TMR_FUNCTION_COMPLETE for ref_tag: 1193992
Aug  9 15:49:52 TESTSTORAGE kernel: ABORT_TASK: Found referenced qla2xxx 
task_tag: 1194036
Aug  9 15:49:57 TESTSTORAGE kernel: TARGET_CORE[qla2xxx]: Detected 
NON_EXISTENT_LUN Access for 0x00000001
Aug  9 15:49:57 TESTSTORAGE kernel: TARGET_CORE[qla2xxx]: Detected 
NON_EXISTENT_LUN Access for 0x00000002
[...] <probably periodic LUN scan issued by esx>
Aug  9 15:49:57 TESTSTORAGE kernel: TARGET_CORE[qla2xxx]: Detected 
NON_EXISTENT_LUN Access for 0x000000ff
Aug  9 15:52:09 TESTSTORAGE kernel: INFO: task kworker/u24:0:3001 
blocked for more than 120 seconds.
Aug  9 15:52:09 TESTSTORAGE kernel:      Not tainted 4.12.3p1 #3
Aug  9 15:52:09 TESTSTORAGE kernel: "echo 0 > 
/proc/sys/kernel/hung_task_timeout_secs" disables this message.
Aug  9 15:52:09 TESTSTORAGE kernel: kworker/u24:0   D    0 3001      2 
0x00000080
Aug  9 15:52:09 TESTSTORAGE kernel: Workqueue: tmr-iblock 
target_tmr_work [target_core_mod]
Aug  9 15:52:09 TESTSTORAGE kernel: Call Trace:
Aug  9 15:52:09 TESTSTORAGE kernel: __schedule+0x285/0x840
Aug  9 15:52:09 TESTSTORAGE kernel: schedule+0x36/0x80
Aug  9 15:52:09 TESTSTORAGE kernel: schedule_timeout+0x173/0x2f0
Aug  9 15:52:09 TESTSTORAGE kernel: ? call_timer_fn+0x140/0x140
Aug  9 15:52:09 TESTSTORAGE kernel: ? get_work_pool+0x2d/0x40
Aug  9 15:52:09 TESTSTORAGE kernel: wait_for_completion_timeout+0x12c/0x190
Aug  9 15:52:09 TESTSTORAGE kernel: ? wake_up_q+0x80/0x80
Aug  9 15:52:09 TESTSTORAGE kernel: 
__transport_wait_for_tasks+0xd9/0x1b0 [target_core_mod]
Aug  9 15:52:09 TESTSTORAGE kernel: transport_wait_for_tasks+0x53/0x90 
[target_core_mod]
Aug  9 15:52:09 TESTSTORAGE kernel: core_tmr_abort_task+0x10e/0x190 
[target_core_mod]
Aug  9 15:52:09 TESTSTORAGE kernel: target_tmr_work+0x111/0x120 
[target_core_mod]
Aug  9 15:52:09 TESTSTORAGE kernel: process_one_work+0x144/0x370
Aug  9 15:52:09 TESTSTORAGE kernel: worker_thread+0x4d/0x3c0
Aug  9 15:52:09 TESTSTORAGE kernel: kthread+0x109/0x140
Aug  9 15:52:09 TESTSTORAGE kernel: ? rescuer_thread+0x360/0x360
Aug  9 15:52:09 TESTSTORAGE kernel: ? kthread_park+0x60/0x60
Aug  9 15:52:09 TESTSTORAGE kernel: ret_from_fork+0x25/0x30
Aug  9 15:52:54 TESTSTORAGE kernel: se_cmd waiting CDB: 0x89 tag: 
1194036 t_state: 5se_cmd_flags: 0x01c80109 transport_state: 0x00000033

At this point inflight counters for sdc are "0 0".
Later there are more "hung task" notifications, but probably they are 
result of the thirst one...

Aug  9 15:54:12 TESTSTORAGE kernel: INFO: task kworker/1:75:3172 blocked 
for more than 120 seconds.
Aug  9 15:54:12 TESTSTORAGE kernel:      Not tainted 4.12.3p1 #3
Aug  9 15:54:12 TESTSTORAGE kernel: "echo 0 > 
/proc/sys/kernel/hung_task_timeout_secs" disables this message.
Aug  9 15:54:12 TESTSTORAGE kernel: kworker/1:75    D    0 3172      2 
0x00000080
Aug  9 15:54:12 TESTSTORAGE kernel: Workqueue: events 
qlt_free_session_done [qla2xxx]
Aug  9 15:54:12 TESTSTORAGE kernel: Call Trace:
Aug  9 15:54:12 TESTSTORAGE kernel: __schedule+0x285/0x840
Aug  9 15:54:12 TESTSTORAGE kernel: schedule+0x36/0x80
Aug  9 15:54:12 TESTSTORAGE kernel: schedule_timeout+0x242/0x2f0
Aug  9 15:54:12 TESTSTORAGE kernel: ? ttwu_do_activate+0x77/0x80
Aug  9 15:54:12 TESTSTORAGE kernel: wait_for_completion+0x111/0x170
Aug  9 15:54:12 TESTSTORAGE kernel: ? wake_up_q+0x80/0x80
Aug  9 15:54:12 TESTSTORAGE kernel: target_wait_for_sess_cmds+0x49/0x170 
[target_core_mod]
Aug  9 15:54:12 TESTSTORAGE kernel: tcm_qla2xxx_free_session+0x45/0x90 
[tcm_qla2xxx]
Aug  9 15:54:12 TESTSTORAGE kernel: qlt_free_session_done+0x109/0x5a0 
[qla2xxx]
Aug  9 15:54:12 TESTSTORAGE kernel: ? qlt_unreg_sess+0xe7/0xf0 [qla2xxx]
Aug  9 15:54:12 TESTSTORAGE kernel: ? tcm_qla2xxx_put_sess+0x3c/0x50 
[tcm_qla2xxx]
Aug  9 15:54:12 TESTSTORAGE kernel: process_one_work+0x144/0x370
Aug  9 15:54:12 TESTSTORAGE kernel: worker_thread+0x4d/0x3c0
Aug  9 15:54:12 TESTSTORAGE kernel: kthread+0x109/0x140
Aug  9 15:54:12 TESTSTORAGE kernel: ? rescuer_thread+0x360/0x360
Aug  9 15:54:12 TESTSTORAGE kernel: ? kthread_park+0x60/0x60
Aug  9 15:54:12 TESTSTORAGE kernel: ret_from_fork+0x25/0x30
Aug  9 15:54:12 TESTSTORAGE kernel: INFO: task kworker/1:82:3184 blocked 
for more than 120 seconds.
Aug  9 15:54:12 TESTSTORAGE kernel:      Not tainted 4.12.3p1 #3
Aug  9 15:54:12 TESTSTORAGE kernel: "echo 0 > 
/proc/sys/kernel/hung_task_timeout_secs" disables this message.
Aug  9 15:54:12 TESTSTORAGE kernel: kworker/1:82    D    0 3184      2 
0x00000080
Aug  9 15:54:12 TESTSTORAGE kernel: Workqueue: events 
qlt_free_session_done [qla2xxx]
Aug  9 15:54:12 TESTSTORAGE kernel: Call Trace:
Aug  9 15:54:12 TESTSTORAGE kernel: __schedule+0x285/0x840
Aug  9 15:54:12 TESTSTORAGE kernel: schedule+0x36/0x80
Aug  9 15:54:12 TESTSTORAGE kernel: schedule_timeout+0x242/0x2f0
Aug  9 15:54:12 TESTSTORAGE kernel: ? ttwu_do_activate+0x77/0x80
Aug  9 15:54:12 TESTSTORAGE kernel: wait_for_completion+0x111/0x170
Aug  9 15:54:12 TESTSTORAGE kernel: ? wake_up_q+0x80/0x80
Aug  9 15:54:12 TESTSTORAGE kernel: target_wait_for_sess_cmds+0x49/0x170 
[target_core_mod]
Aug  9 15:54:12 TESTSTORAGE kernel: tcm_qla2xxx_free_session+0x45/0x90 
[tcm_qla2xxx]
Aug  9 15:54:12 TESTSTORAGE kernel: qlt_free_session_done+0x109/0x5a0 
[qla2xxx]
Aug  9 15:54:12 TESTSTORAGE kernel: ? qlt_unreg_sess+0xe7/0xf0 [qla2xxx]
Aug  9 15:54:12 TESTSTORAGE kernel: ? tcm_qla2xxx_put_sess+0x3c/0x50 
[tcm_qla2xxx]
Aug  9 15:54:12 TESTSTORAGE kernel: process_one_work+0x144/0x370
Aug  9 15:54:12 TESTSTORAGE kernel: worker_thread+0x4d/0x3c0
Aug  9 15:54:12 TESTSTORAGE kernel: kthread+0x109/0x140
Aug  9 15:54:12 TESTSTORAGE kernel: ? rescuer_thread+0x360/0x360
Aug  9 15:54:12 TESTSTORAGE kernel: ? kthread_park+0x60/0x60
Aug  9 15:54:12 TESTSTORAGE kernel: ret_from_fork+0x25/0x30
diff mbox

Patch

diff --git a/drivers/target/target_core_transport.c b/drivers/target/target_core_transport.c
index 0197635..0bd8c64 100644
--- a/drivers/target/target_core_transport.c
+++ b/drivers/target/target_core_transport.c
@@ -2827,7 +2827,13 @@  void transport_clear_lun_ref(struct se_lun *lun)
 
        spin_unlock_irqrestore(&cmd->t_state_lock, *flags);
 
-       wait_for_completion(&cmd->t_transport_stop_comp);
+       while (!wait_for_completion_timeout(&cmd->t_transport_stop_comp,
+                                           180 * HZ)) {
+               pr_warn_ratelimited("se_cmd waiting CDB: 0x%02x tag: %llu t_state: %d"
+                       "se_cmd_flags: 0x%08x transport_state: 0x%08x\n",
+                       cmd->t_task_cdb[0], cmd->tag, cmd->t_state,
+                       cmd->se_cmd_flags, cmd->transport_state);
+       }
 
        spin_lock_irqsave(&cmd->t_state_lock, *flags);
        cmd->transport_state &= ~(CMD_T_ACTIVE | CMD_T_STOP);