Hi,
tipc_nametbl_withdraw() triggers the softlockup as it tries to grab
nametbl_lock twice if the node triggered a TIPC_NOTIFY_LINK_DOWN event
while its is running. The erroneous call chain is:
tipc_nametbl_withdraw() Grab nametbl_lock
tipc_named_process_backlog()
tipc_update_nametbl()
if (dtype == WITHDRAWAL) tipc_node_unsubscribe()
tipc_node_write_unlock()
if (flags & TIPC_NOTIFY_LINK_DOWN) tipc_nametbl_withdraw()
spin_lock_bh(&tn->nametbl_lock); << Soft Lockup >>
Three callers which can cause this under module exit:
Case1:
tipc_exit_net()
tipc_nametbl_withdraw() Grab nametbl_lock
Case2:
tipc_server_stop()
tipc_conn_kref_release
tipc_sock_release
sock_release()
tipc_release()
tipc_sk_withdraw()
tipc_nametbl_withdraw()
Case3:
tipc_server_stop()
tipc_conn_kref_release()
kernel_bind()
tipc_bind()
tipc_sk_withdraw()
tipc_nametbl_withdraw()
I will work on a solution for this.
What kind of test were you performing when this occurred (linkup/down)?
Do you read link statistics periodically in your tests?
/Partha
On 11/21/2016 05:30 AM, John Thompson wrote:
> Hi Partha,
>
> I was doing some some more testing today and have still observed the
> problem (contrary to what I had emailed earlier).
>
> Here is the kernel dump.
>
> <0>NMI watchdog: BUG: soft lockup - CPU#0 stuck for 22s! [Pluggable
> Serve:2221]
> <6>Modules linked in: tipc jitterentropy_rng echainiv drbg
> platform_driver(O)
> <6>CPU: 0 PID: 2221 Comm: Pluggable Serve Tainted: P O
> <6>task: ae54ced0 ti: aec42000 task.ti: aec42000
> <6>NIP: 8069257c LR: c13ebf50 CTR: 80692540
> <6>REGS: aec43ad0 TRAP: 0901 Tainted: P O
> <6>MSR: 00029002 <CE,EE,ME> CR: 48002444 XER: 00000000
> <6>
> <6>GPR00: c13ea408 aec43b80 ae54ced0 a624690c 00000000 a6271d84 a39a60cc
> fffffffd
> <6>GPR08: aeefbbc8 00000001 00000001 00000004 80692540
> <6>NIP [8069257c] _raw_spin_lock_bh+0x3c/0x70
> <6>LR [c13ebf50] tipc_nametbl_unsubscribe+0x50/0x120 [tipc]
> <6>Call Trace:
> <6>[aec43b80] [800fa258] check_object+0xc8/0x270 (unreliable)
> <6>[aec43ba0] [c13ea408] tipc_named_reinit+0xf8/0x820 [tipc]
> <6>[aec43bb0] [c13ea6c0] tipc_named_reinit+0x3b0/0x820 [tipc]
> <6>[aec43bd0] [c13f7bbc] tipc_nl_publ_dump+0x50c/0xed0 [tipc]
> <6>[aec43c00] [c13f865c] tipc_conn_sendmsg+0xdc/0x170 [tipc]
> <6>[aec43c30] [c13eacbc] tipc_subscrp_report_overlap+0xbc/0xd0 [tipc]
> <6>[aec43c70] [c13eb27c] tipc_topsrv_stop+0x45c/0x4f0 [tipc]
> <6>[aec43ca0] [c13eb7a8] tipc_nametbl_remove_publ+0x58/0x110 [tipc]
> <6>[aec43cd0] [c13ebc68] tipc_nametbl_withdraw+0x68/0x140 [tipc]
> <6>[aec43d00] [c13f3c34] tipc_nl_node_dump_link+0x1904/0x45d0 [tipc]
> <6>[aec43d30] [c13f4848] tipc_nl_node_dump_link+0x2518/0x45d0 [tipc]
TIPC_CMD_SHOW_LINK_STATS or TIPC_NL_LINK_GET
> <6>[aec43d70] [804f29e0] sock_release+0x30/0xf0
> <6>[aec43d80] [804f2ab4] sock_close+0x14/0x30
> <6>[aec43d90] [80105844] __fput+0x94/0x200
> <6>[aec43db0] [8003dca4] task_work_run+0xd4/0x100
> <6>[aec43dd0] [80023620] do_exit+0x280/0x980
> <6>[aec43e10] [80024c48] do_group_exit+0x48/0xb0
> <6>[aec43e30] [80030344] get_signal+0x244/0x4f0
> <6>[aec43e80] [80007734] do_signal+0x34/0x1c0
> <6>[aec43f30] [800079a8] do_notify_resume+0x68/0x80
> <6>[aec43f40] [8000fa1c] do_user_signal+0x74/0xc4
> <6>--- interrupt: c00 at 0xf4f3d08
> <6> LR = 0xf4f3ce8
> <6>Instruction dump:
> <6>912a0008 39400001 7d201828 2c090000 40820010 7d40192d 40a2fff0 7c2004ac
> <6>2f890000 4dbe0020 7c210b78 81230000 <2f890000> 40befff4 7c421378
> 7d201828
> <0>Kernel panic - not syncing: softlockup: hung tasks
> <6>CPU: 0 PID: 2221 Comm: Pluggable Serve Tainted: P O L
> <6>Call Trace:
> <6>[aec43930] [80694e20] dump_stack+0x84/0xb0 (unreliable)
> <6>[aec43940] [80692ca8] panic+0xd8/0x214
> <6>[aec439a0] [800a0258] watchdog_timer_fn+0x2d8/0x2e0
> <6>[aec439f0] [8007ae58] __hrtimer_run_queues+0x118/0x1d0
> <6>[aec43a30] [8007b608] hrtimer_interrupt+0xd8/0x270
> <6>[aec43a80] [8000983c] __timer_interrupt+0xac/0x1b0
> <6>[aec43aa0] [80009b70] timer_interrupt+0xb0/0xe0
> <6>[aec43ac0] [8000f450] ret_from_except+0x0/0x18
> <6>--- interrupt: 901 at _raw_spin_lock_bh+0x3c/0x70
> <6> LR = tipc_nametbl_unsubscribe+0x50/0x120 [tipc]
> <6>[aec43b80] [800fa258] check_object+0xc8/0x270 (unreliable)
> <6>[aec43ba0] [c13ea408] tipc_named_reinit+0xf8/0x820 [tipc]
> <6>[aec43bb0] [c13ea6c0] tipc_named_reinit+0x3b0/0x820 [tipc]
> <6>[aec43bd0] [c13f7bbc] tipc_nl_publ_dump+0x50c/0xed0 [tipc]
> <6>[aec43c00] [c13f865c] tipc_conn_sendmsg+0xdc/0x170 [tipc]
> <6>[aec43c30] [c13eacbc] tipc_subscrp_report_overlap+0xbc/0xd0 [tipc]
> <6>[aec43c70] [c13eb27c] tipc_topsrv_stop+0x45c/0x4f0 [tipc]
> <6>[aec43ca0] [c13eb7a8] tipc_nametbl_remove_publ+0x58/0x110 [tipc]
> <6>[aec43cd0] [c13ebc68] tipc_nametbl_withdraw+0x68/0x140 [tipc]
> <6>[aec43d00] [c13f3c34] tipc_nl_node_dump_link+0x1904/0x45d0 [tipc]
> <6>[aec43d30] [c13f4848] tipc_nl_node_dump_link+0x2518/0x45d0 [tipc]
> <6>[aec43d70] [804f29e0] sock_release+0x30/0xf0
> <6>[aec43d80] [804f2ab4] sock_close+0x14/0x30
> <6>[aec43d90] [80105844] __fput+0x94/0x200
> <6>[aec43db0] [8003dca4] task_work_run+0xd4/0x100
> <6>[aec43dd0] [80023620] do_exit+0x280/0x980
> <6>[aec43e10] [80024c48] do_group_exit+0x48/0xb0
> <6>[aec43e30] [80030344] get_signal+0x244/0x4f0
> <6>[aec43e80] [80007734] do_signal+0x34/0x1c0
> <6>[aec43f30] [800079a8] do_notify_resume+0x68/0x80
> <6>[aec43f40] [8000fa1c] do_user_signal+0x74/0xc4
> <6>--- interrupt: c00 at 0xf4f3d08
> <6> LR = 0xf4f3ce8
>
>
> On Mon, Nov 21, 2016 at 9:59 AM, John Thompson <[email protected]
> <mailto:[email protected]>> wrote:
>
> Hi Partha,
>
> In my testing over the weekend the patch performed well - I didn't
> see any kernel dumps due to this issue.
>
> Thanks for the quick response.
> JT
>
>
> On Fri, Nov 18, 2016 at 10:34 AM, John Thompson
> <[email protected] <mailto:[email protected]>> wrote:
>
> Hi,
>
> I will be able to have some test results by the start of next
> week on the first patch.
>
> Regards,
> JT
>
>
> On Thu, Nov 17, 2016 at 11:27 PM, Ying Xue
> <[email protected] <mailto:[email protected]>> wrote:
>
> On 11/17/2016 07:04 AM, John Thompson wrote:
>
> Hi Partha / Ying,
>
> I will try out the patch and let you know how it goes.
> I also note about providing the other CPU core dumps -
> in one of my cases I
> didn't have them but in others I did but
> they were interleaved and so were difficult to interpret.
>
>
> Thanks, it's unnecessary for us to collect more logs as its
> soft lockup scenario should be just what Partha described.
>
> Regards,
> Ying
>
>
>
> Thanks for getting a patch together so quickly.
>
> JT
>
> On Wed, Nov 16, 2016 at 10:23 PM, Parthasarathy Bhuvaragan <
> [email protected]
> <mailto:[email protected]>> wrote:
>
> Hi Ying / John,
>
> The soft lock is the call chain of
> tipc_nametbl_withdraw(), when it
> performs the tipc_conn_kref_release() as it tries to
> grab nametbl_lock
> again while holding it already.
>
> tipc_nametbl_withdraw
> spin_lock_bh(&tn->nametbl_lock);
> tipc_nametbl_remove_publ
> spin_lock_bh(&seq->lock);
> tipc_nameseq_remove_publ
> tipc_subscrp_report_overlap
> tipc_subscrp_send_event
> tipc_conn_sendmsg
>
> << Here, the (test_bit(CF_CONNECTED, &con->flags))
> Fails, leading to the
> else case where do do a conn_put() and that triggers
> the cleanup as
> refcount reached 0. Leading the call chain below : >>
> tipc_conn_kref_release
> tipc_sock_release
> tipc_conn_release
> tipc_subscrb_delete
> tipc_subscrp_delete
> tipc_nametbl_unsubscribe
> spin_lock_bh(&tn->nametbl_lock);
> << !! Soft Lockup >>
>
> One cause is that tipc_exit_net() calls first calls
> tipc_topsrv_stop() and
> then tipc_nametbl_withdraw() in scope of
> tipc_net_stop().
>
> The above chain will only occur in a narrow window
> for a given connection:
> CPU#1:
> tipc_nametbl_withdraw() manages to perform
> tipc_conn_lookup() and steps
> the refcount to 2, while in CPU#2 the following occurs:
> CPU#2:
> tipc_server_stop() calls tipc_close_conn(con). This
> performs a conn_put()
> decrementing refcount to 1.
> Now, CPU#1 continues and detects that the connection
> is not CF_CONNECTED
> and does a conn_put(), triggering the release callback.
>
> Before commit 333f796235a527, the above wont happen.
>
> /Partha
>
>
> On 11/15/2016 04:11 PM, Xue, Ying wrote:
>
> Hi John,
>
> Regarding the stack trace you provided below, I
> get the two potential
> call chains:
>
> tipc_nametbl_withdraw
> spin_lock_bh(&tn->nametbl_lock);
> tipc_nametbl_remove_publ
> spin_lock_bh(&seq->lock);
> tipc_nameseq_remove_publ
> tipc_subscrp_report_overlap
> tipc_subscrp_send_event
> tipc_conn_sendmsg
> spin_lock_bh(&con->outqueue_lock);
> list_add_tail(&e->list,
> &con->outqueue);
>
>
> tipc_topsrv_stop
> tipc_server_stop
> tipc_close_conn
> kernel_sock_shutdown
> tipc_subscrb_delete
> spin_lock_bh(&subscriber->lock);
> tipc_nametbl_unsubscribe(sub);
> spin_lock_bh(&tn->nametbl_lock);
>
> Although I suspect this is a revert lock issue
> leading to the soft
> lockup, I am still unable to understand which
> lock together with
> nametbl_lock is taken reversely on the two
> different paths above.
> However, you just gave us the log printed on
> CPU#2, but the logs
> outputted by other cores are also important. So
> if possible, please share
> them with us.
>
> By the way, I agree with you, and it seems that
> commit 333f796235a527 is
> related to the soft lockup.
>
> Regards,
> Ying
>
> -----Original Message-----
> From: John Thompson [mailto:[email protected]
> <mailto:[email protected]>]
> Sent: Tuesday, November 15, 2016 8:01 AM
> To: [email protected]
> <mailto:[email protected]>
> Subject: [tipc-discussion] v4.7: soft lockup
> when releasing a socket
>
> Hi,
>
> I am seeing an occasional kernel soft lockup. I
> have TIPC v4.7 and the
> kernel dump occurs when the system is going down
> for a reboot.
>
> The kernel dump is:
>
> <0>NMI watchdog: BUG: soft lockup - CPU#2 stuck
> for 23s! [exfx:1474]
> <6>Modules linked in: tipc jitterentropy_rng
> echainiv drbg
> platform_driver(O) ipifwd(PO)
> ...
> <6>
> <6>GPR00: c15333e8 a4e0fb80 a4ee3600 a51748ac
> 00000000 ae475024 a537feec
> fffffffd
> <6>GPR08: a2197408 00000001 00000001 00000004
> 80691c00 <6>NIP [80691c40]
> _raw_spin_lock_bh+0x40/0x70 <6>LR [c1534f30]
> tipc_nametbl_unsubscribe+0x50/0x120
> [tipc] <6>Call Trace:
> <6>[a4e0fba0] [c15333e8]
> tipc_named_reinit+0xf8/0x820 [tipc]
> <6>[a4e0fbb0] [c15336a0]
> tipc_named_reinit+0x3b0/0x820 [tipc] <6>[a4e0fbd0]
> [c1540bac] tipc_nl_publ_dump+0x50c/0xed0 [tipc]
> <6>[a4e0fc00] [c154164c]
> tipc_conn_sendmsg+0xdc/0x170 [tipc]
> <6>[a4e0fc30] [c1533c9c]
> tipc_subscrp_report_overlap+0xbc/0xd0 [tipc]
> <6>[a4e0fc70] [c153425c]
> tipc_topsrv_stop+0x45c/0x4f0 [tipc]
> <6>[a4e0fca0] [c1534788]
> tipc_nametbl_remove_publ+0x58/0x110 [tipc]
> <6>[a4e0fcd0] [c1534c48]
> tipc_nametbl_withdraw+0x68/0x140 [tipc]
> <6>[a4e0fd00] [c153cc24]
> tipc_nl_node_dump_link+0x1904/0x45d0 [tipc]
> <6>[a4e0fd30] [c153d838]
> tipc_nl_node_dump_link+0x2518/0x45d0 [tipc]
> <6>[a4e0fd70] [804f2870]
> sock_release+0x30/0xf0 <6>[a4e0fd80] [804f2944]
> sock_close+0x14/0x30
> <6>[a4e0fd90] [80105844] __fput+0x94/0x200
> <6>[a4e0fdb0] [8003dca4]
> task_work_run+0xd4/0x100 <6>[a4e0fdd0]
> [80023620] do_exit+0x280/0x980
> <6>[a4e0fe10] [80024c48] do_group_exit+0x48/0xb0
> <6>[a4e0fe30] [80030344]
> get_signal+0x244/0x4f0 <6>[a4e0fe80] [80007734]
> do_signal+0x34/0x1c0
> <6>[a4e0ff30] [800079a8]
> do_notify_resume+0x68/0x80 <6>[a4e0ff40]
> [8000fa1c] do_user_signal+0x74/0xc4
>
>
> From the stack dump it looks like
> tipc_named_reinit is trying to
>
>
> acquire nametbl_lock.
>
> From looking at the call chain I can see that
> tipc_conn_sendmsg can
>
>
> send up calling conn_put
>
> which will go on and call the tipc_named_reinit
> via tipc_sock_release.
>
> As tipc_nametbl_withdraw (from the stack dump)
> has already acquired the
> nametbl_lock, tipc_named_reinit
>
> cannot get it and so the process hangs.
>
>
> The call to tipc_sock_release (added in Commit
> 333f796235a527
>
> <http://git.atlnz.lc/cgit/cgit.cgi/upstream_imports/linux-
>
> <http://git.atlnz.lc/cgit/cgit.cgi/upstream_imports/linux->
>
> stable.git/commit/?id=333f796235a52727db7e0a13888045f3aa3d5335>)
> seems to have changed the behaviour
>
> such that it tries to do a lot more when
> shutting the connection down.
>
>
> If there is other information I can provide
> please let me know.
>
> Regards,
>
> John
>
> ------------------------------------------------------------
> ------------------
> _______________________________________________
> tipc-discussion mailing list
> [email protected]
> <mailto:[email protected]>
>
> https://lists.sourceforge.net/lists/listinfo/tipc-discussion
>
> <https://lists.sourceforge.net/lists/listinfo/tipc-discussion>
>
> ------------------------------------------------------------
> ------------------
> _______________________________________________
> tipc-discussion mailing list
> [email protected]
> <mailto:[email protected]>
>
> https://lists.sourceforge.net/lists/listinfo/tipc-discussion
>
> <https://lists.sourceforge.net/lists/listinfo/tipc-discussion>
>
>
>
>
> ------------------------------------------------------------------------------
> _______________________________________________
> tipc-discussion mailing list
> [email protected]
> <mailto:[email protected]>
> https://lists.sourceforge.net/lists/listinfo/tipc-discussion
> <https://lists.sourceforge.net/lists/listinfo/tipc-discussion>
>
>
>
>
>
------------------------------------------------------------------------------
_______________________________________________
tipc-discussion mailing list
[email protected]
https://lists.sourceforge.net/lists/listinfo/tipc-discussion
