On Mon, Jun 06, 2016 at 03:11:18PM +0300, Nikolay Borisov wrote: > > > On 06/06/2016 02:51 PM, Erez Shitrit wrote: > > Hi Nikolay > > > > What was the scenario? (Do you have a way to reproduce that?) > > I have no way of reliably reproducing that, but I have experienced > misteryous hangs in the ipoib stack e.g. > > https://marc.info/?l=linux-rdma&m=145915284709901 > > when the connection to the infiniband network is lost. Unfortunately I > cannot even figure out where to being debugging this ;( > > As a matter of fact I currently have one server which complains: > > ib0: transmit timeout: latency 139718550 msecs > ib0: queue stopped 1, tx_head 242, tx_tail 114 What i can tell from our experience is that this issue is not new, we have it with older kernels (<3). Also, not sure it is an issue with HCA vendor as we see it with CX3. This is a very slippery bug which we find it hard to reproduce. > > yet, "iblinkinfo" can show all the nodes in the infiniband network. > > > Which IB card are you using? > > ibstat > CA 'qib0' > CA type: InfiniPath_QLE7342 > Number of ports: 2 > Firmware version: > Hardware version: 2 > Node GUID: 0x001175000077b918 > System image GUID: 0x001175000077b918 > Port 1: > State: Active > Physical state: LinkUp > Rate: 40 > Base lid: 68 > LMC: 0 > SM lid: 61 > Capability mask: 0x07610868 > Port GUID: 0x001175000077b918 > Link layer: InfiniBand > > > > > > > Thanks, Erez > > > > On Mon, Jun 6, 2016 at 12:09 PM, Nikolay Borisov <kernel@xxxxxxxx> wrote: > >> Hello, > >> > >> [Tejun, I have cc'ed you since I'm not familiar with the internals of > >> the workqueue code and cannot comment whether the the mcast_task was > >> queued or and whether there were any tasks in the workqueue based on the > >> structures I've presented below, could you please comment on that?] > >> > >> I've been running an infiniband network on 4.4.10 and recently due to > >> the infiniband failing (I presume) and having the following in my logs: > >> > >> [128340.462147] ib0: transmit timeout: latency 45014865 msecs > >> [128340.462151] ib0: queue stopped 1, tx_head 711, tx_tail 583 > >> [128341.461122] ib0: transmit timeout: latency 45015864 msecs > >> [128341.461126] ib0: queue stopped 1, tx_head 711, tx_tail 583 > >> [128342.461053] ib0: transmit timeout: latency 45016864 msecs > >> [128342.461056] ib0: queue stopped 1, tx_head 711, tx_tail 583 > >> > >> I had various commands hang due to rtnl_lock being held by an ip > >> command, trying to shutdown the infiniband interface: > >> > >> PID: 30572 TASK: ffff881bb6bf6e00 CPU: 15 COMMAND: "ip" > >> #0 [ffff88027f50b390] __schedule at ffffffff81631421 > >> #1 [ffff88027f50b430] schedule at ffffffff81631cc7 > >> #2 [ffff88027f50b450] schedule_timeout at ffffffff81634c89 > >> #3 [ffff88027f50b4e0] wait_for_completion at ffffffff81632d73 > >> #4 [ffff88027f50b550] flush_workqueue at ffffffff8106c761 > >> #5 [ffff88027f50b620] ipoib_mcast_stop_thread at ffffffffa02e0bf2 [ib_ipoib] > >> #6 [ffff88027f50b650] ipoib_ib_dev_down at ffffffffa02de7d6 [ib_ipoib] > >> #7 [ffff88027f50b670] ipoib_stop at ffffffffa02dc208 [ib_ipoib] > >> #8 [ffff88027f50b6a0] __dev_close_many at ffffffff81562692 > >> #9 [ffff88027f50b6c0] __dev_close at ffffffff81562716 > >> #10 [ffff88027f50b6f0] __dev_change_flags at ffffffff815630fc > >> #11 [ffff88027f50b730] dev_change_flags at ffffffff81563207 > >> #12 [ffff88027f50b760] do_setlink at ffffffff81576f5f > >> #13 [ffff88027f50b860] rtnl_newlink at ffffffff81578afb > >> #14 [ffff88027f50bb10] rtnetlink_rcv_msg at ffffffff81577ae5 > >> #15 [ffff88027f50bb90] netlink_rcv_skb at ffffffff8159a373 > >> #16 [ffff88027f50bbc0] rtnetlink_rcv at ffffffff81577bb5 > >> #17 [ffff88027f50bbe0] netlink_unicast at ffffffff81599e98 > >> #18 [ffff88027f50bc40] netlink_sendmsg at ffffffff8159aabe > >> #19 [ffff88027f50bd00] sock_sendmsg at ffffffff81548ce9 > >> #20 [ffff88027f50bd20] ___sys_sendmsg at ffffffff8154ae78 > >> #21 [ffff88027f50beb0] __sys_sendmsg at ffffffff8154b059 > >> #22 [ffff88027f50bf40] sys_sendmsg at ffffffff8154b0a9 > >> #23 [ffff88027f50bf50] entry_SYSCALL_64_fastpath at ffffffff81635c57 > >> > >> > >> So clearly ipoib_mcast_stop_thread has hung on trying to stop the > >> multicast thread. Here is the state of the ipoib_wq: > >> > >> struct workqueue_struct { > >> pwqs = { > >> next = 0xffff883ff1196770, > >> prev = 0xffff883ff1196770 > >> }, > >> list = { > >> next = 0xffff883fef5bea10, > >> prev = 0xffff883fef201010 > >> }, > >> mutex = { > >> count = { > >> counter = 1 > >> }, > >> wait_lock = { > >> { > >> rlock = { > >> raw_lock = { > >> val = { > >> counter = 0 > >> } > >> } > >> } > >> } > >> }, > >> wait_list = { > >> next = 0xffff883fef200c28, > >> prev = 0xffff883fef200c28 > >> }, > >> owner = 0x0, > >> osq = { > >> tail = { > >> counter = 0 > >> } > >> } > >> }, > >> work_color = 1, > >> flush_color = 0, > >> nr_pwqs_to_flush = { > >> counter = 1 > >> }, > >> first_flusher = 0xffff88027f50b568, > >> flusher_queue = { > >> next = 0xffff883fef200c60, > >> prev = 0xffff883fef200c60 > >> }, > >> flusher_overflow = { > >> next = 0xffff883fef200c70, > >> prev = 0xffff883fef200c70 > >> }, > >> maydays = { > >> next = 0xffff883fef200c80, > >> prev = 0xffff883fef200c80 > >> }, > >> rescuer = 0xffff883feb073680, > >> nr_drainers = 0, > >> saved_max_active = 1, > >> unbound_attrs = 0xffff883fef2b5c20, > >> dfl_pwq = 0xffff883ff1196700, > >> wq_dev = 0x0, > >> name = > >> "ipoib_wq\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000", > >> rcu = { > >> next = 0x0, > >> func = 0x0 > >> }, > >> flags = 131082, > >> cpu_pwqs = 0x0, > >> > >> Also the state of the mcast_task member: > >> > >> crash> struct ipoib_dev_priv.mcast_task ffff883fed6ec700 > >> mcast_task = { > >> work = { > >> data = { > >> counter = 3072 > >> }, > >> entry = { > >> next = 0xffff883fed6ec888, > >> prev = 0xffff883fed6ec888 > >> }, > >> func = 0xffffffffa02e1220 <ipoib_mcast_join_task> > >> }, > >> timer = { > >> entry = { > >> next = 0x0, > >> pprev = 0x0 > >> }, > >> expires = 0, > >> function = 0xffffffff8106dd20 <delayed_work_timer_fn>, > >> data = 18446612406880618624, > >> flags = 2097164, > >> slack = -1 > >> }, > >> wq = 0x0, > >> cpu = 0 > >> } > >> > >> > >> flush_workqueue is essentially waiting on > >> wait_for_completion(&this_flusher.done) in flush_workqueue, which > >> apparently never returned. I'm assuming this is due to the general > >> unavailability of the infiniband network. However, I think it's wrong, > >> in case of infiniband being down, the whole server to be rendered > >> unresponsive, due to rtnl_lock being held. Do you think it is possible > >> to rework this code to prevent it hanging in case the workqueue cannot > >> be flushed? Furthermore, do you think it's feasible to put code in > >> ipoib_mcast_join_task to detect such situations and not re-arm itself > >> and then use cancel_delayed_work_sync ? > >> -- > >> To unsubscribe from this list: send the line "unsubscribe linux-rdma" in > >> the body of a message to majordomo@xxxxxxxxxxxxxxx > >> More majordomo info at http://vger.kernel.org/majordomo-info.html > -- > To unsubscribe from this list: send the line "unsubscribe linux-rdma" in > the body of a message to majordomo@xxxxxxxxxxxxxxx > More majordomo info at http://vger.kernel.org/majordomo-info.html -- To unsubscribe from this list: send the line "unsubscribe linux-rdma" in the body of a message to majordomo@xxxxxxxxxxxxxxx More majordomo info at http://vger.kernel.org/majordomo-info.html
