Re: iscsi_trx going into D state

Nicholas A. Bellinger
2016-10-29T22:29:50Z

Hi Robert,

On Wed, 2016-10-19 at 10:41 -0600, Robert LeBlanc wrote:
> Nicholas,
>
> I didn't have high hopes for the patch because we were not seeing
> TMR_ABORT_TASK (or 'abort') in dmesg or /var/log/messages, but it
> seemed to help regardless. Our clients finally OOMed from the hung
> sessions, so we are having to reboot them and we will do some more
> testing. We haven't put the updated kernel on our clients yet. Our
> clients have iSCSI root disks so I'm not sure if we can get a vmcore
> on those, but we will do what we can to get you a vmcore from the
> target if it happens again.
>

Just checking in to see if you've observed further issues with
iser-target ports, and/or able to generate a crashdump with v4.4.y..?

> As far as our configuration: It is a superMicro box with 6 SAMSUNG
> MZ7LM3T8HCJM-00005 SSDs. Two are for root and four are in mdadm
> RAID-10 for exporting via iSCSI/iSER. We have ZFS on top of the
> RAID-10 for checksum and snapshots only and we export ZVols to the
> clients (one or more per VM on the client). We do not persist the
> export info (targetcli saveconfig), but regenerate it from scripts.
> The client receives two or more of these exports and puts them in a
> RAID-1 device. The exports are served by iSER one one port and also by
> normal iSCSI on a different port for compatibility, but not normally
> used. If you need more info about the config, please let me know. It
> was kind of a vague request so I'm not sure what exactly is important
> to you.

Thanks for the extra details of your hardware + user-space
configuration.

> Thanks for helping us with this,
> Robert LeBlanc
>
> When we have problems, we usually see this in the logs:
> Oct 17 08:57:50 prv-0-12-sanstack kernel: iSCSI Login timeout on
> Network Portal 0.0.0.0:3260
> Oct 17 08:57:50 prv-0-12-sanstack kernel: Unexpected ret: -104 send data 48
> Oct 17 08:57:50 prv-0-12-sanstack kernel: tx_data returned -32, expecting 48.
> Oct 17 08:57:50 prv-0-12-sanstack kernel: iSCSI Login negotiation failed.
>
> I found some backtraces in the logs, not sure if this is helpful, this
> is before your patch (your patch booted at Oct 18 10:36:59):
> Oct 17 15:43:12 prv-0-12-sanstack kernel: INFO: rcu_sched
> self-detected stall on CPU
> Oct 17 15:43:12 prv-0-12-sanstack kernel: #0115-...: (41725 ticks this
> GP) idle=b59/140000000000001/0 softirq=535/535 fqs=30992
> Oct 17 15:43:12 prv-0-12-sanstack kernel: #011 (t=42006 jiffies g=1550
> c=1549 q=0)
> Oct 17 15:43:12 prv-0-12-sanstack kernel: Task dump for CPU 5:
> Oct 17 15:43:12 prv-0-12-sanstack kernel: kworker/u68:2 R running
> task 0 17967 2 0x00000008
> Oct 17 15:43:12 prv-0-12-sanstack kernel: Workqueue: isert_comp_wq
> isert_cq_work [ib_isert]
> Oct 17 15:43:12 prv-0-12-sanstack kernel: ffff883f4c0dca80
> 00000000af8ca7a4 ffff883f7fb43da8 ffffffff810ac83f
> Oct 17 15:43:12 prv-0-12-sanstack kernel: 0000000000000005
> ffffffff81adb680 ffff883f7fb43dc0 ffffffff810af179
> Oct 17 15:43:12 prv-0-12-sanstack kernel: 0000000000000006
> ffff883f7fb43df0 ffffffff810e1c10 ffff883f7fb57b80
> Oct 17 15:43:12 prv-0-12-sanstack kernel: Call Trace:
> Oct 17 15:43:12 prv-0-12-sanstack kernel: <IRQ> [<ffffffff810ac83f>]
> sched_show_task+0xaf/0x110
> Oct 17 15:43:12 prv-0-12-sanstack kernel: [<ffffffff810af179>]
> dump_cpu_task+0x39/0x40
> Oct 17 15:43:12 prv-0-12-sanstack kernel: [<ffffffff810e1c10>]
> rcu_dump_cpu_stacks+0x80/0xb0
> Oct 17 15:43:12 prv-0-12-sanstack kernel: [<ffffffff810e6040>]
> rcu_check_callbacks+0x540/0x820
> Oct 17 15:43:12 prv-0-12-sanstack kernel: [<ffffffff810afd51>] ?
> account_system_time+0x81/0x110
> Oct 17 15:43:12 prv-0-12-sanstack kernel: [<ffffffff810fa9a0>] ?
> tick_sched_do_timer+0x50/0x50
> Oct 17 15:43:12 prv-0-12-sanstack kernel: [<ffffffff810eb4d9>]
> update_process_times+0x39/0x60
> Oct 17 15:43:12 prv-0-12-sanstack kernel: [<ffffffff810fa755>]
> tick_sched_handle.isra.17+0x25/0x60
> Oct 17 15:43:12 prv-0-12-sanstack kernel: [<ffffffff810fa9dd>]
> tick_sched_timer+0x3d/0x70
> Oct 17 15:43:12 prv-0-12-sanstack kernel: [<ffffffff810ec0c2>]
> __hrtimer_run_queues+0x102/0x290
> Oct 17 15:43:12 prv-0-12-sanstack kernel: [<ffffffff810ec5a8>]
> hrtimer_interrupt+0xa8/0x1a0
> Oct 17 15:43:12 prv-0-12-sanstack kernel: [<ffffffff81052c65>]
> local_apic_timer_interrupt+0x35/0x60
> Oct 17 15:43:12 prv-0-12-sanstack kernel: [<ffffffff8172343d>]
> smp_apic_timer_interrupt+0x3d/0x50
> Oct 17 15:43:12 prv-0-12-sanstack kernel: [<ffffffff817216f7>]
> apic_timer_interrupt+0x87/0x90
> Oct 17 15:43:12 prv-0-12-sanstack kernel: <EOI> [<ffffffff810d70fe>]
> ? console_unlock+0x41e/0x4e0
> Oct 17 15:43:12 prv-0-12-sanstack kernel: [<ffffffff810d74bc>]
> vprintk_emit+0x2fc/0x500
> Oct 17 15:43:12 prv-0-12-sanstack kernel: [<ffffffff810d783f>]
> vprintk_default+0x1f/0x30
> Oct 17 15:43:12 prv-0-12-sanstack kernel: [<ffffffff81174c2a>] printk+0x5d/0x74
> Oct 17 15:43:12 prv-0-12-sanstack kernel: [<ffffffff814bc351>]
> transport_lookup_cmd_lun+0x1d1/0x200
> Oct 17 15:43:12 prv-0-12-sanstack kernel: [<ffffffff814edcf0>]
> iscsit_setup_scsi_cmd+0x230/0x540
> Oct 17 15:43:12 prv-0-12-sanstack kernel: [<ffffffffa0890bf3>]
> isert_rx_do_work+0x3f3/0x7f0 [ib_isert]
> Oct 17 15:43:12 prv-0-12-sanstack kernel: [<ffffffffa0891174>]
> isert_cq_work+0x184/0x770 [ib_isert]
> Oct 17 15:43:12 prv-0-12-sanstack kernel: [<ffffffff8109734f>]
> process_one_work+0x14f/0x400
> Oct 17 15:43:12 prv-0-12-sanstack kernel: [<ffffffff81097bc4>]
> worker_thread+0x114/0x470
> Oct 17 15:43:12 prv-0-12-sanstack kernel: [<ffffffff8171c55a>] ?
> __schedule+0x34a/0x7f0
> Oct 17 15:43:12 prv-0-12-sanstack kernel: [<ffffffff81097ab0>] ?
> rescuer_thread+0x310/0x310
> Oct 17 15:43:12 prv-0-12-sanstack kernel: [<ffffffff8109d708>] kthread+0xd8/0xf0
> Oct 17 15:43:12 prv-0-12-sanstack kernel: [<ffffffff8109d630>] ?
> kthread_park+0x60/0x60
> Oct 17 15:43:12 prv-0-12-sanstack kernel: [<ffffffff81720c8f>]
> ret_from_fork+0x3f/0x70
> Oct 17 15:43:12 prv-0-12-sanstack kernel: [<ffffffff8109d630>] ?
> kthread_park+0x60/0x60
>
> Oct 17 16:34:03 prv-0-12-sanstack kernel: INFO: rcu_sched
> self-detected stall on CPU
> Oct 17 16:34:03 prv-0-12-sanstack kernel: #01128-...: (5999 ticks this
> GP) idle=2f9/140000000000001/0 softirq=457/457 fqs=4830
> Oct 17 16:34:03 prv-0-12-sanstack kernel: #011 (t=6000 jiffies g=3546
> c=3545 q=0)
> Oct 17 16:34:03 prv-0-12-sanstack kernel: Task dump for CPU 28:
> Oct 17 16:34:03 prv-0-12-sanstack kernel: iscsi_np R running
> task 0 16597 2 0x0000000c
> Oct 17 16:34:03 prv-0-12-sanstack kernel: ffff887f40350000
> 00000000b98a67bb ffff887f7f503da8 ffffffff810ac8ff
> Oct 17 16:34:03 prv-0-12-sanstack kernel: 000000000000001c
> ffffffff81adb680 ffff887f7f503dc0 ffffffff810af239
> Oct 17 16:34:03 prv-0-12-sanstack kernel: 000000000000001d
> ffff887f7f503df0 ffffffff810e1cd0 ffff887f7f517b80
> Oct 17 16:34:03 prv-0-12-sanstack kernel: Call Trace:
> Oct 17 16:34:03 prv-0-12-sanstack kernel: <IRQ> [<ffffffff810ac8ff>]
> sched_show_task+0xaf/0x110
> Oct 17 16:34:03 prv-0-12-sanstack kernel: [<ffffffff810af239>]
> dump_cpu_task+0x39/0x40
> Oct 17 16:34:03 prv-0-12-sanstack kernel: [<ffffffff810e1cd0>]
> rcu_dump_cpu_stacks+0x80/0xb0
> Oct 17 16:34:03 prv-0-12-sanstack kernel: [<ffffffff810e6100>]
> rcu_check_callbacks+0x540/0x820
> Oct 17 16:34:03 prv-0-12-sanstack kernel: [<ffffffff810afe11>] ?
> account_system_time+0x81/0x110
> Oct 17 16:34:03 prv-0-12-sanstack kernel: [<ffffffff810faa60>] ?
> tick_sched_do_timer+0x50/0x50
> Oct 17 16:34:03 prv-0-12-sanstack kernel: [<ffffffff810eb599>]
> update_process_times+0x39/0x60
> Oct 17 16:34:03 prv-0-12-sanstack kernel: [<ffffffff810fa815>]
> tick_sched_handle.isra.17+0x25/0x60
> Oct 17 16:34:03 prv-0-12-sanstack kernel: [<ffffffff810faa9d>]
> tick_sched_timer+0x3d/0x70
> Oct 17 16:34:03 prv-0-12-sanstack kernel: [<ffffffff810ec182>]
> __hrtimer_run_queues+0x102/0x290
> Oct 17 16:34:03 prv-0-12-sanstack kernel: [<ffffffff810ec668>]
> hrtimer_interrupt+0xa8/0x1a0
> Oct 17 16:34:03 prv-0-12-sanstack kernel: [<ffffffff81052c65>]
> local_apic_timer_interrupt+0x35/0x60
> Oct 17 16:34:03 prv-0-12-sanstack kernel: [<ffffffff81723cbd>]
> smp_apic_timer_interrupt+0x3d/0x50
> Oct 17 16:34:03 prv-0-12-sanstack kernel: [<ffffffff81721f77>]
> apic_timer_interrupt+0x87/0x90
> Oct 17 16:34:03 prv-0-12-sanstack kernel: <EOI> [<ffffffff810d71be>]
> ? console_unlock+0x41e/0x4e0
> Oct 17 16:34:03 prv-0-12-sanstack kernel: [<ffffffff810d757c>]
> vprintk_emit+0x2fc/0x500
> Oct 17 16:34:03 prv-0-12-sanstack kernel: [<ffffffff810d78ff>]
> vprintk_default+0x1f/0x30
> Oct 17 16:34:03 prv-0-12-sanstack kernel: [<ffffffff81174dde>] printk+0x5d/0x74
> Oct 17 16:34:03 prv-0-12-sanstack kernel: [<ffffffff814e71ad>]
> iscsi_target_locate_portal+0x62d/0x6f0
> Oct 17 16:34:03 prv-0-12-sanstack kernel: [<ffffffff814e5100>]
> iscsi_target_login_thread+0x6f0/0xfc0
> Oct 17 16:34:03 prv-0-12-sanstack kernel: [<ffffffff814e4a10>] ?
> iscsi_target_login_sess_out+0x250/0x250
> Oct 17 16:34:03 prv-0-12-sanstack kernel: [<ffffffff8109d7c8>] kthread+0xd8/0xf0
> Oct 17 16:34:03 prv-0-12-sanstack kernel: [<ffffffff8109d6f0>] ?
> kthread_park+0x60/0x60
> Oct 17 16:34:03 prv-0-12-sanstack kernel: [<ffffffff8172150f>]
> ret_from_fork+0x3f/0x70
> Oct 17 16:34:03 prv-0-12-sanstack kernel: [<ffffffff8109d6f0>] ?
> kthread_park+0x60/0x60
>
> I don't think this one is related, but it happened a couple of times:
> Oct 17 11:46:52 prv-0-12-sanstack kernel: INFO: rcu_sched
> self-detected stall on CPU
> Oct 17 11:46:52 prv-0-12-sanstack kernel: #01119-...: (5999 ticks this
> GP) idle=727/140000000000001/0 softirq=1346/1346 fqs=4990
> Oct 17 11:46:52 prv-0-12-sanstack kernel: #011 (t=6000 jiffies g=4295
> c=4294 q=0)
> Oct 17 11:46:52 prv-0-12-sanstack kernel: Task dump for CPU 19:
> Oct 17 11:46:52 prv-0-12-sanstack kernel: kworker/19:1 R running
> task 0 301 2 0x00000008
> Oct 17 11:46:52 prv-0-12-sanstack kernel: Workqueue:
> events_power_efficient fb_flashcursor
> Oct 17 11:46:52 prv-0-12-sanstack kernel: ffff883f6009ca80
> 00000000010a7cdd ffff883f7fcc3da8 ffffffff810ac8ff
> Oct 17 11:46:52 prv-0-12-sanstack kernel: 0000000000000013
> ffffffff81adb680 ffff883f7fcc3dc0 ffffffff810af239
> Oct 17 11:46:52 prv-0-12-sanstack kernel: 0000000000000014
> ffff883f7fcc3df0 ffffffff810e1cd0 ffff883f7fcd7b80
> Oct 17 11:46:52 prv-0-12-sanstack kernel: Call Trace:
> Oct 17 11:46:52 prv-0-12-sanstack kernel: <IRQ> [<ffffffff810ac8ff>]
> sched_show_task+0xaf/0x110
> Oct 17 11:46:52 prv-0-12-sanstack kernel: [<ffffffff810af239>]
> dump_cpu_task+0x39/0x40
> Oct 17 11:46:52 prv-0-12-sanstack kernel: [<ffffffff810e1cd0>]
> rcu_dump_cpu_stacks+0x80/0xb0
> Oct 17 11:46:52 prv-0-12-sanstack kernel: [<ffffffff810e6100>]
> rcu_check_callbacks+0x540/0x820
> Oct 17 11:46:52 prv-0-12-sanstack kernel: [<ffffffff810afe11>] ?
> account_system_time+0x81/0x110
> Oct 17 11:46:52 prv-0-12-sanstack kernel: [<ffffffff810faa60>] ?
> tick_sched_do_timer+0x50/0x50
> Oct 17 11:46:52 prv-0-12-sanstack kernel: [<ffffffff810eb599>]
> update_process_times+0x39/0x60
> Oct 17 11:46:52 prv-0-12-sanstack kernel: [<ffffffff810fa815>]
> tick_sched_handle.isra.17+0x25/0x60
> Oct 17 11:46:52 prv-0-12-sanstack kernel: [<ffffffff810faa9d>]
> tick_sched_timer+0x3d/0x70
> Oct 17 11:46:52 prv-0-12-sanstack kernel: [<ffffffff810ec182>]
> __hrtimer_run_queues+0x102/0x290
> Oct 17 11:46:52 prv-0-12-sanstack kernel: [<ffffffff810ec668>]
> hrtimer_interrupt+0xa8/0x1a0
> Oct 17 11:46:52 prv-0-12-sanstack kernel: [<ffffffff81052c65>]
> local_apic_timer_interrupt+0x35/0x60
> Oct 17 11:46:52 prv-0-12-sanstack kernel: [<ffffffff81723cbd>]
> smp_apic_timer_interrupt+0x3d/0x50
> Oct 17 11:46:52 prv-0-12-sanstack kernel: [<ffffffff81721f77>]
> apic_timer_interrupt+0x87/0x90
> Oct 17 11:46:52 prv-0-12-sanstack kernel: <EOI> [<ffffffff810d71be>]
> ? console_unlock+0x41e/0x4e0
> Oct 17 11:46:52 prv-0-12-sanstack kernel: [<ffffffff813866ad>]
> fb_flashcursor+0x5d/0x140
> Oct 17 11:46:52 prv-0-12-sanstack kernel: [<ffffffff8138bc00>] ?
> bit_clear+0x110/0x110
> Oct 17 11:46:52 prv-0-12-sanstack kernel: [<ffffffff8109740f>]
> process_one_work+0x14f/0x400
> Oct 17 11:46:52 prv-0-12-sanstack kernel: [<ffffffff81097c84>]
> worker_thread+0x114/0x470
> Oct 17 11:46:52 prv-0-12-sanstack kernel: [<ffffffff8171cdda>] ?
> __schedule+0x34a/0x7f0
> Oct 17 11:46:52 prv-0-12-sanstack kernel: [<ffffffff81097b70>] ?
> rescuer_thread+0x310/0x310
> Oct 17 11:46:52 prv-0-12-sanstack kernel: [<ffffffff8109d7c8>] kthread+0xd8/0xf0
> Oct 17 11:46:52 prv-0-12-sanstack kernel: [<ffffffff8109d6f0>] ?
> kthread_park+0x60/0x60
> Oct 17 11:46:52 prv-0-12-sanstack kernel: [<ffffffff8172150f>]
> ret_from_fork+0x3f/0x70
> Oct 17 11:46:52 prv-0-12-sanstack kernel: [<ffffffff8109d6f0>] ?
> kthread_park+0x60/0x60

RCU self-detected schedule stalls typically mean some code is
monopolizing execution on a specific CPU for an extended period of time
(eg: endless loop), preventing normal RCU grace-period callbacks from
running in a timely manner.

It's hard to tell without more log context and/or crashdump what was
going on here.