Hi,
There is an other branch where softlockup for nametbl_lock occurs.
tipc_named_rcv() Grabs nametbl_lock
tipc_update_nametbl() (publish/withdraw)
tipc_node_subscribe()/unsubscribe()
tipc_node_write_unlock()
<< lockup occurs if it needs to process NODE UP/DOWN LINK
UP/DOWN, as it grabs nametbl_lock again >>
/Partha
On 11/21/2016 01:04 PM, Parthasarathy Bhuvaragan wrote:
> 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 <thompa....@gmail.com
>> <mailto:thompa....@gmail.com>> 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
>> <thompa....@gmail.com <mailto:thompa....@gmail.com>> 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
>> <ying....@windriver.com <mailto:ying....@windriver.com>> 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 <
>> parthasarathy.bhuvara...@ericsson.com
>> <mailto:parthasarathy.bhuvara...@ericsson.com>> 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:thompa....@gmail.com
>> <mailto:thompa....@gmail.com>]
>> Sent: Tuesday, November 15, 2016 8:01 AM
>> To: tipc-discussion@lists.sourceforge.net
>> <mailto:tipc-discussion@lists.sourceforge.net>
>> 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
>> tipc-discussion@lists.sourceforge.net
>> <mailto:tipc-discussion@lists.sourceforge.net>
>>
>> https://lists.sourceforge.net/lists/listinfo/tipc-discussion
>>
>> <https://lists.sourceforge.net/lists/listinfo/tipc-discussion>
>>
>> ------------------------------------------------------------
>> ------------------
>> _______________________________________________
>> tipc-discussion mailing list
>> tipc-discussion@lists.sourceforge.net
>> <mailto:tipc-discussion@lists.sourceforge.net>
>>
>> https://lists.sourceforge.net/lists/listinfo/tipc-discussion
>>
>> <https://lists.sourceforge.net/lists/listinfo/tipc-discussion>
>>
>>
>>
>>
>> ------------------------------------------------------------------------------
>> _______________________________________________
>> tipc-discussion mailing list
>> tipc-discussion@lists.sourceforge.net
>> <mailto:tipc-discussion@lists.sourceforge.net>
>> https://lists.sourceforge.net/lists/listinfo/tipc-discussion
>>
>> <https://lists.sourceforge.net/lists/listinfo/tipc-discussion>
>>
>>
>>
>>
>>
>
> ------------------------------------------------------------------------------
> _______________________________________________
> tipc-discussion mailing list
> tipc-discussion@lists.sourceforge.net
> https://lists.sourceforge.net/lists/listinfo/tipc-discussion
>
------------------------------------------------------------------------------
_______________________________________________
tipc-discussion mailing list
tipc-discussion@lists.sourceforge.net
https://lists.sourceforge.net/lists/listinfo/tipc-discussion
