Date:   Thu, 8 Jun 2017 07:01:08 +0000
From:   Feng Feng24 Liu <liufeng24@...ovo.com>
To:     "linux-kernel@...r.kernel.org" <linux-kernel@...r.kernel.org>,
        "linux-rt-users@...r.kernel.org" <linux-rt-users@...r.kernel.org>,
        "rostedt@...dmis.org" <rostedt@...dmis.org>,
        "tmac@...com" <tmac@...com>
CC:     Tong Tong3 Li <litong3@...ovo.com>
Subject: RE: kernel BUG at kernel/locking/rtmutex.c:1027

Hi,  T Makphaibulchoke & Steve
	I found that you discuss about " kernel BUG at kernel/locking/rtmutex.c:997 " at 
	https://groups.google.com/forum/#!topic/fa.linux.kernel/aV2peeXs71E
	
	Could you help to give some advice? 
	Our kernel version is:  kernel4.4.6-rt14
	Whether our problem ,which I describe above, is the same problem as " kernel BUG at kernel/locking/rtmutex.c:997"?  
	And why is the patch "[PATCH 3.14.25-rt22 1/2] rtmutex Real-Time Linux: Fixing kernel BUG at kernel/locking/rtmutex.c:997!" not apply to the upsteam or rt-patches? 
	
	Thanks a lot

Thanks
Feng

>-----Original Message-----
>From: Feng Feng24 Liu
>Sent: Tuesday, June 06, 2017 11:18 PM
>To: 'linux-kernel@...r.kernel.org'; 'linux-rt-users@...r.kernel.org';
>'rostedt@...dmis.org'
>Cc: Tong Tong3 Li
>Subject: kernel BUG at kernel/locking/rtmutex.c:1027
>
>Dear RT experts,
>
>I upgrate our kernel from kernel-3.10 to kernel4.4.6-rt14 in our environment.  But
>the RT kernel alway report deadlock.
>
>I added the following debugging statement:
>
>diff --git a/kernel/locking/rtmutex.c b/kernel/locking/rtmutex.c index
>6c40660..e979aa9 100644
>--- a/kernel/locking/rtmutex.c
>+++ b/kernel/locking/rtmutex.c
>@@ -994,6 +994,10 @@ static void  noinline __sched
>rt_spin_lock_slowlock(struct rt_mutex *lock)
>        pi_unlock(&self->pi_lock);
>
>        ret = task_blocks_on_rt_mutex(lock, &waiter, self, 0);
>+        if (unlikely(ret)) {
>+          debug_rt_mutex_print_deadlock(&waiter);
>+        }
>+
>        BUG_ON(ret);
>
>        for (;;) {
>
>And the result is:
>
>Following is the dmesg of the RT kernel:
>[51893.656645] ============================================
>[51893.656645] [ BUG: circular locking deadlock detected! ] [51893.656646] Not
>tainted [51893.656646] --------------------------------------------
>[51893.656647] gmond/9537 is deadlocking current task gmetad/4455
>[51893.656647] [51893.656648] [51893.656648] 1) gmetad/4455 is trying to acquire
>this lock:
>[51893.656649]  [ffff88023fc8d340] {&(&base->lock)->lock} [51893.656650]
>[51893.656650] 2) gmond/9537 is blocked on this lock:
>[51893.656650]  [ffff880030fe6c08] {&(&(sk)->sk_lock.slock)->lock}
>[51893.656651] .. ->owner: ffff8800b9c2bc01
>[51893.656652] .. held by:            gmetad: 4455 [ffff8800b9c2bc00, 120]
>[51893.656653]
>[51893.656653] gmond/9537's [blocked] stackdump:
>[51893.656653]
>[51893.656655]  ffff8802157f7b28 ffff880216278c00 ffff880014c1c800
>ffff8802157f8000 [51893.656656]  0000000000000000 ffff880014c1c800
>ffff8800b9c2bc00 ffff880030fe6c08 [51893.656657]  ffff8802157f7b48
>ffffffff81a7ae07 ffff8802157f7c30 0000000000000282 [51893.656658] Call Trace:
>[51893.656665]  [<ffffffff81a7ae07>] preempt_schedule_irq+0x57/0xc0
>[51893.656668]  [<ffffffff81a7e93b>] do_preempt_schedule_irq+0x5/0x7
>[51893.656670]  [<ffffffff81a7c294>] ? rt_spin_lock_slowlock+0x2e4/0x3a0
>[51893.656672]  [<ffffffff81a7c27f>] ? rt_spin_lock_slowlock+0x2cf/0x3a0
>[51893.656674]  [<ffffffff81a7d93f>] rt_spin_lock+0x1f/0x30 [51893.656678]
>[<ffffffff81866fc3>] lock_sock_nested+0x23/0x60 [51893.656680]
>[<ffffffff818de576>] tcp_sendmsg+0x26/0xad0 [51893.656683]
>[<ffffffff8190872f>] inet_sendmsg+0x7f/0xb0 [51893.656685]
>[<ffffffff81864558>] sock_sendmsg+0x38/0x50 [51893.656686]
>[<ffffffff818645eb>] sock_write_iter+0x7b/0xd0 [51893.656690]
>[<ffffffff811a986d>] __vfs_write+0xad/0xe0 [51893.656692]  [<ffffffff811a9e71>]
>vfs_write+0xa1/0x180 [51893.656694]  [<ffffffff811aab19>] SyS_write+0x49/0xb0
>[51893.656695]  [<ffffffff8114392d>] ? context_tracking_enter+0x1d/0x30
>[51893.656697]  [<ffffffff81a7de2e>] entry_SYSCALL_64_fastpath+0x12/0x71
>[51893.656698]
>[51893.656698] gmetad/4455's [current] stackdump:
>[51893.656698]
>[51893.656700] CPU: 2 PID: 4455 Comm: gmetad Not tainted 4.4.6-thinkcloud-nfv
>#1 [51893.656701] Hardware name: Red Hat KVM, BIOS 0.5.1 01/01/2011
>[51893.656702]  0000000000000000 ffff8800ba207618 ffffffff8140113e
>ffff8800ba207688 [51893.656703]  ffff880014c1c800 ffff8800ba207650
>ffffffff810a2f5e ffff8800ba207688 [51893.656704]  0000000000000286
>ffff8800b9c2bc00 000000000000d340 ffff88023fc8d340 [51893.656705] Call Trace:
>[51893.656707]  [<ffffffff8140113e>] dump_stack+0x65/0x87 [51893.656710]
>[<ffffffff810a2f5e>] debug_rt_mutex_print_deadlock+0x15e/0x180
>[51893.656712]  [<ffffffff81a7c322>] rt_spin_lock_slowlock+0x372/0x3a0
>[51893.656715]  [<ffffffff818d27a9>] ? ip_finish_output+0x139/0x1f0
>[51893.656717]  [<ffffffff81a7d93f>] rt_spin_lock+0x1f/0x30 [51893.656720]
>[<ffffffff810c2078>] lock_timer_base.isra.33+0x58/0x70 [51893.656722]
>[<ffffffff810c456b>] mod_timer+0x7b/0x210 [51893.656724]  [<ffffffff81867758>]
>sk_reset_timer+0x18/0x30 [51893.656725]  [<ffffffff818e5e4b>]
>tcp_rearm_rto+0x6b/0xb0 [51893.656727]  [<ffffffff818e9583>]
>tcp_event_new_data_sent+0x83/0x90 [51893.656729]  [<ffffffff818eb344>]
>tcp_write_xmit+0x174/0xe90 [51893.656730]  [<ffffffff818ec2b1>]
>__tcp_push_pending_frames+0x31/0xa0
>[51893.656732]  [<ffffffff818e79e7>] tcp_rcv_established+0x227/0x770
>[51893.656733]  [<ffffffff818f20bc>] tcp_v4_do_rcv+0x10c/0x230 [51893.656734]
>[<ffffffff818f32e9>] tcp_v4_rcv+0x8a9/0xa10 [51893.656737]  [<ffffffff818ce20c>]
>ip_local_deliver_finish+0x9c/0x240
>[51893.656738]  [<ffffffff818ce5bd>] ip_local_deliver+0xbd/0xd0 [51893.656740]
>[<ffffffff818ce170>] ? ip_rcv_finish+0x310/0x310 [51893.656741]
>[<ffffffff818cdedd>] ip_rcv_finish+0x7d/0x310 [51893.656743]
>[<ffffffff818ce8b8>] ip_rcv+0x2e8/0x420 [51893.656744]  [<ffffffff818cde60>] ?
>inet_del_offload+0x40/0x40 [51893.656747]  [<ffffffff8187fd1c>]
>__netif_receive_skb_core+0x37c/0xa20
>[51893.656748]  [<ffffffff818d3c00>] ? ip_output+0x80/0xc0 [51893.656750]
>[<ffffffff818d3302>] ? __ip_local_out+0x62/0xe0 [51893.656751]
>[<ffffffff818d2670>] ? ip_fragment.constprop.50+0x80/0x80
>[51893.656752]  [<ffffffff818803dd>] __netif_receive_skb+0x1d/0x60
>[51893.656754]  [<ffffffff818812ea>] process_backlog+0xba/0x1c0 [51893.656755]
>[<ffffffff818808c5>] net_rx_action+0x175/0x3a0 [51893.656759]
>[<ffffffff8106621b>] do_current_softirqs+0x20b/0x420 [51893.656761]
>[<ffffffff81066490>] __local_bh_enable+0x60/0x80 [51893.656762]
>[<ffffffff81868798>] release_sock+0x128/0x170 [51893.656764]
>[<ffffffff818dc7b6>] tcp_recvmsg+0x2f6/0xb90 [51893.656765]
>[<ffffffff81084d33>] ? preempt_count_add+0xa3/0xc0 [51893.656767]
>[<ffffffff81a7d590>] ? _raw_spin_unlock_irqrestore+0x20/0x50
>[51893.656768]  [<ffffffff819088e0>] inet_recvmsg+0x90/0xb0 [51893.656769]
>[<ffffffff8186417b>] sock_recvmsg+0x3b/0x50 [51893.656770]
>[<ffffffff81864218>] sock_read_iter+0x88/0xd0 [51893.656772]
>[<ffffffff811a978a>] __vfs_read+0xaa/0xe0 [51893.656774]  [<ffffffff811a9d42>]
>vfs_read+0x82/0x110 [51893.656775]  [<ffffffff811aaa69>] SyS_read+0x49/0xb0
>[51893.656776]  [<ffffffff8114392d>] ? context_tracking_enter+0x1d/0x30
>[51893.656778]  [<ffffffff81a7de2e>] entry_SYSCALL_64_fastpath+0x12/0x71
>[51893.656778] [ turning off deadlock detection.Please report this trace. ]
>[51893.656778] [51893.656796] ------------[ cut here ]------------ [51893.656796]
>kernel BUG at kernel/locking/rtmutex.c:1027!
>[51893.656798] invalid opcode: 0000 [#1] PREEMPT SMP [51893.656822] Modules
>linked in: xt_REDIRECT nf_nat_redirect xt_nat xt_mark ip6table_raw
>ip6table_mangle ip6table_filter ip6_tables xt_connmark 8021q garp mrp veth
>openvswitch xt_CHECKSUM iptable_mangle xt_tcpudp xt_multiport xt_conntrack
>iptable_filter xt_CT iptable_raw ipt_MASQUERADE nf_nat_masquerade_ipv4
>xt_comment iptable_nat nf_nat_ipv4 nf_nat kvm_intel kvm irqbypass
>crct10dif_pclmul crc32_pclmul aesni_intel aes_x86_64 glue_helper lrw ablk_helper
>cryptd snd_hda_codec_generic snd_hda_intel snd_hda_codec input_leds
>snd_hwdep snd_hda_core led_class tpm_tis nf_conntrack_ipv6 nf_defrag_ipv6
>nf_conntrack_ipv4 nf_defrag_ipv4 ip_tables x_tables raid1 serio_raw pata_acpi
>[last unloaded: ipmi_msghandler] [51893.656824] CPU: 2 PID: 4455 Comm: gmetad
>Not tainted 4.4.6-thinkcloud-nfv #1 [51893.656824] Hardware name: Red Hat KVM,
>BIOS 0.5.1 01/01/2011 [51893.656825] task: ffff8800b9c2bc00 ti: ffff8800ba204000
>task.ti: ffff8800ba204000 [51893.656828] RIP: 0010:[<ffffffff81a7c322>]
>[<ffffffff81a7c322>] rt_spin_lock_slowlock+0x372/0x3a0 [51893.656829] RSP:
>0018:ffff8800ba207660  EFLAGS: 00010086 [51893.656830] RAX: 000000000000003d
>RBX: ffff8800ba207688 RCX: 0000000000000000 [51893.656831] RDX:
>0000000000000002 RSI: ffffffff81c89168 RDI: ffffffff81cb316f [51893.656832] RBP:
>ffff8800ba207718 R08: 000000000000015c R09: ffffffff8211a7e5 [51893.656832] R10:
>000000000000f698 R11: 0000000000000000 R12: 0000000000000286 [51893.656833]
>R13: ffff8800b9c2bc00 R14: 000000000000d340 R15: ffff88023fc8d340 [51893.656835]
>FS:  00007f05d85ca700(0000) GS:ffff88023fd00000(0000) knlGS:0000000000000000
>[51893.656836] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033 [51893.656841]
>CR2: 0000000004595ff0 CR3: 00000000b9835000 CR4: 00000000000006e0
>[51893.656845] Stack:
>[51893.656847]  010000000000ffff 0000000000000000 ffff8800ba2076b0
>ffffffff818d27a9 [51893.656849]  ffff8800b9c2c2e8 0000000000000001
>0000000000000000 0000000000000000 [51893.656851]  ffff8800ba2076a0
>0000000000000000 0000000000000000 ffff8800b9c2bc00 [51893.656851] Call Trace:
>[51893.656854]  [<ffffffff818d27a9>] ? ip_finish_output+0x139/0x1f0
>[51893.656857]  [<ffffffff81a7d93f>] rt_spin_lock+0x1f/0x30 [51893.656859]
>[<ffffffff810c2078>] lock_timer_base.isra.33+0x58/0x70 [51893.656861]
>[<ffffffff810c456b>] mod_timer+0x7b/0x210 [51893.656863]  [<ffffffff81867758>]
>sk_reset_timer+0x18/0x30 [51893.656864]  [<ffffffff818e5e4b>]
>tcp_rearm_rto+0x6b/0xb0 [51893.656865]  [<ffffffff818e9583>]
>tcp_event_new_data_sent+0x83/0x90 [51893.656867]  [<ffffffff818eb344>]
>tcp_write_xmit+0x174/0xe90 [51893.656869]  [<ffffffff818ec2b1>]
>__tcp_push_pending_frames+0x31/0xa0
>[51893.656870]  [<ffffffff818e79e7>] tcp_rcv_established+0x227/0x770
>[51893.656871]  [<ffffffff818f20bc>] tcp_v4_do_rcv+0x10c/0x230 [51893.656872]
>[<ffffffff818f32e9>] tcp_v4_rcv+0x8a9/0xa10 [51893.656874]  [<ffffffff818ce20c>]
>ip_local_deliver_finish+0x9c/0x240
>[51893.656875]  [<ffffffff818ce5bd>] ip_local_deliver+0xbd/0xd0 [51893.656877]
>[<ffffffff818ce170>] ? ip_rcv_finish+0x310/0x310 [51893.656878]
>[<ffffffff818cdedd>] ip_rcv_finish+0x7d/0x310 [51893.656880]
>[<ffffffff818ce8b8>] ip_rcv+0x2e8/0x420 [51893.656881]  [<ffffffff818cde60>] ?
>inet_del_offload+0x40/0x40 [51893.656883]  [<ffffffff8187fd1c>]
>__netif_receive_skb_core+0x37c/0xa20
>[51893.656884]  [<ffffffff818d3c00>] ? ip_output+0x80/0xc0 [51893.656886]
>[<ffffffff818d3302>] ? __ip_local_out+0x62/0xe0 [51893.656887]
>[<ffffffff818d2670>] ? ip_fragment.constprop.50+0x80/0x80
>[51893.656889]  [<ffffffff818803dd>] __netif_receive_skb+0x1d/0x60
>[51893.656890]  [<ffffffff818812ea>] process_backlog+0xba/0x1c0 [51893.656891]
>[<ffffffff818808c5>] net_rx_action+0x175/0x3a0 [51893.656893]
>[<ffffffff8106621b>] do_current_softirqs+0x20b/0x420 [51893.656895]
>[<ffffffff81066490>] __local_bh_enable+0x60/0x80 [51893.656897]
>[<ffffffff81868798>] release_sock+0x128/0x170 [51893.656898]
>[<ffffffff818dc7b6>] tcp_recvmsg+0x2f6/0xb90 [51893.656899]
>[<ffffffff81084d33>] ? preempt_count_add+0xa3/0xc0 [51893.656901]
>[<ffffffff81a7d590>] ? _raw_spin_unlock_irqrestore+0x20/0x50
>[51893.656902]  [<ffffffff819088e0>] inet_recvmsg+0x90/0xb0 [51893.656903]
>[<ffffffff8186417b>] sock_recvmsg+0x3b/0x50 [51893.656905]
>[<ffffffff81864218>] sock_read_iter+0x88/0xd0 [51893.656906]
>[<ffffffff811a978a>] __vfs_read+0xaa/0xe0 [51893.656908]  [<ffffffff811a9d42>]
>vfs_read+0x82/0x110 [51893.656909]  [<ffffffff811aaa69>] SyS_read+0x49/0xb0
>[51893.656911]  [<ffffffff8114392d>] ? context_tracking_enter+0x1d/0x30
>[51893.656912]  [<ffffffff81a7de2e>] entry_SYSCALL_64_fastpath+0x12/0x71
>[51893.656925] Code: 4d 58 ff e9 3e fe ff ff 0f 0b 49 8b 57 18 e9 22 fd ff ff 89 c6 48 c7
>c7 a0 ba c7 81 31 c0 e8 27 83 6c ff 48 89 df e8 de 6a 62 ff <0f> 0b 0f 0b e8 c5 57 62 ff
>e8 d0 4c 58 ff e9 6c fd ff ff 0f 0b [51893.656927] RIP  [<ffffffff81a7c322>]
>rt_spin_lock_slowlock+0x372/0x3a0 [51893.656927]  RSP <ffff8800ba207660>
>
>I find there is a discuss at:
>	https://groups.google.com/forum/#!topic/fa.linux.kernel/aV2peeXs71E
>Whether it is the same problem as above?  And why is these correction not apply
>into rtmutex.c(4.4.6-rt14)?
>Is this a defect which need to be fix?
>
>Thanks
>Feng

Powered by blists - more mailing lists