* inconsistent lock state on v4.14.20-rt17
@ 2018-03-06 15:27 Roosen Henri
2018-03-06 18:21 ` Sebastian Andrzej Siewior
0 siblings, 1 reply; 10+ messages in thread
From: Roosen Henri @ 2018-03-06 15:27 UTC (permalink / raw)
To: linux-rt-users
Hi,
Ever since 4.9 we've been chasing random kernel crashes which are
reproducible on RT in SMP on iMX6Q. It happens when the system is
stressed using hackbench, however, only when hackbench is used with
sockets, not when used with pipes.
Lately we've upgraded to v4.14.20-rt17, which doesn't solve the issue,
but instead locks up the kernel. After switching on some Lock-Debugging
we've been able to catch a trace (see below). It would be great if
someone could have a look at it, or guide me in tracing down the root-
cause.
Thanks,
Henri
[18586.277233] ================================
[18586.277236] WARNING: inconsistent lock state
[18586.277245] 4.14.20-rt17-henri-1 #15 Tainted: G W
[18586.277248] --------------------------------
[18586.277253] inconsistent {IN-HARDIRQ-W} -> {HARDIRQ-ON-W} usage.
[18586.277263] hackbench/18985 [HC0[0]:SC0[0]:HE1:SE1] takes:
[18586.277267] (&rq->lock){?...}, at: [<c0992134>]
__schedule+0x128/0x6ac
[18586.277300] {IN-HARDIRQ-W} state was registered at:
[18586.277314] lock_acquire+0x288/0x32c
[18586.277324] _raw_spin_lock+0x48/0x58
[18586.277338] scheduler_tick+0x40/0xb4
[18586.277349] update_process_times+0x38/0x6c
[18586.277359] tick_periodic+0x120/0x148
[18586.277366] tick_handle_periodic+0x2c/0xa0
[18586.277378] twd_handler+0x3c/0x48
[18586.277389] handle_percpu_devid_irq+0x290/0x608
[18586.277395] generic_handle_irq+0x28/0x38
[18586.277402] __handle_domain_irq+0xd4/0xf0
[18586.277409] gic_handle_irq+0x64/0xa8
[18586.277414] __irq_svc+0x70/0xc4
[18586.277420] lock_acquire+0x2a4/0x32c
[18586.277425] lock_acquire+0x2a4/0x32c
[18586.277440] down_write_nested+0x54/0x68
[18586.277453] sget_userns+0x310/0x4f4
[18586.277465] mount_pseudo_xattr+0x68/0x170
[18586.277477] nsfs_mount+0x3c/0x50
[18586.277484] mount_fs+0x24/0xa8
[18586.277490] vfs_kern_mount+0x58/0x118
[18586.277496] kern_mount_data+0x24/0x34
[18586.277507] nsfs_init+0x20/0x58
[18586.277522] start_kernel+0x2f8/0x360
[18586.277528] 0x1000807c
[18586.277532] irq event stamp: 19441
[18586.277542] hardirqs last enabled at (19441): [<c099665c>]
_raw_spin_unlock_irqrestore+0x88/0x90
[18586.277550] hardirqs last disabled at (19440): [<c09962f8>]
_raw_spin_lock_irqsave+0x2c/0x68
[18586.277562] softirqs last enabled at (0): [<c0120c18>]
copy_process.part.5+0x370/0x1a54
[18586.277568] softirqs last disabled at (0): [< (null)>] (null)
[18586.277571]
other info that might help us debug this:
[18586.277574] Possible unsafe locking scenario:
[18586.277576] CPU0
[18586.277578] ----
[18586.277580] lock(&rq->lock);
[18586.277587] <Interrupt>
[18586.277588] lock(&rq->lock);
[18586.277594]
*** DEADLOCK ***
[18586.277599] 2 locks held by hackbench/18985:
[18586.277601] #0: (&u->iolock){+.+.}, at: [<c081de30>]
unix_stream_read_generic+0xb0/0x7e4
[18586.277624] #1: (rcu_read_lock){....}, at: [<c081b73c>]
unix_write_space+0x0/0x2b0
[18586.277640]
stack backtrace:
[18586.277651] CPU: 1 PID: 18985 Comm: hackbench Tainted:
G W 4.14.20-rt17-henri-1 #15
[18586.277654] Hardware name: Freescale i.MX6 Quad/DualLite (Device
Tree)
[18586.277683] [<c0111600>] (unwind_backtrace) from [<c010bfe8>]
(show_stack+0x20/0x24)
[18586.277701] [<c010bfe8>] (show_stack) from [<c097d79c>]
(dump_stack+0x9c/0xd0)
[18586.277714] [<c097d79c>] (dump_stack) from [<c0175424>]
(print_usage_bug+0x1c8/0x2d0)
[18586.277725] [<c0175424>] (print_usage_bug) from [<c0175970>]
(mark_lock+0x444/0x69c)
[18586.277736] [<c0175970>] (mark_lock) from [<c0177114>]
(__lock_acquire+0x23c/0x172c)
[18586.277748] [<c0177114>] (__lock_acquire) from [<c017935c>]
(lock_acquire+0x288/0x32c)
[18586.277759] [<c017935c>] (lock_acquire) from [<c0996150>]
(_raw_spin_lock+0x48/0x58)
[18586.277774] [<c0996150>] (_raw_spin_lock) from [<c0992134>]
(__schedule+0x128/0x6ac)
[18586.277789] [<c0992134>] (__schedule) from [<c09929c0>]
(preempt_schedule_irq+0x5c/0x8c)
[18586.277801] [<c09929c0>] (preempt_schedule_irq) from [<c010cc8c>]
(svc_preempt+0x8/0x2c)
[18586.277815] [<c010cc8c>] (svc_preempt) from [<c0190b60>]
(__rcu_read_unlock+0x40/0x98)
[18586.277829] [<c0190b60>] (__rcu_read_unlock) from [<c081b9a4>]
(unix_write_space+0x268/0x2b0)
[18586.277847] [<c081b9a4>] (unix_write_space) from [<c07643d8>]
(sock_wfree+0x70/0xac)
[18586.277860] [<c07643d8>] (sock_wfree) from [<c081aff0>]
(unix_destruct_scm+0x74/0x7c)
[18586.277876] [<c081aff0>] (unix_destruct_scm) from [<c076a8dc>]
(skb_release_head_state+0x78/0x80)
[18586.277891] [<c076a8dc>] (skb_release_head_state) from [<c076ac28>]
(skb_release_all+0x1c/0x34)
[18586.277905] [<c076ac28>] (skb_release_all) from [<c076ac5c>]
(__kfree_skb+0x1c/0x28)
[18586.277919] [<c076ac5c>] (__kfree_skb) from [<c076b470>]
(consume_skb+0x228/0x2b4)
[18586.277933] [<c076b470>] (consume_skb) from [<c081e3d4>]
(unix_stream_read_generic+0x654/0x7e4)
[18586.277947] [<c081e3d4>] (unix_stream_read_generic) from
[<c081e65c>] (unix_stream_recvmsg+0x5c/0x68)
[18586.277969] [<c081e65c>] (unix_stream_recvmsg) from [<c075f0e0>]
(sock_recvmsg+0x28/0x2c)
[18586.277983] [<c075f0e0>] (sock_recvmsg) from [<c075f174>]
(sock_read_iter+0x90/0xb8)
[18586.277998] [<c075f174>] (sock_read_iter) from [<c02559ec>]
(__vfs_read+0x108/0x12c)
[18586.278010] [<c02559ec>] (__vfs_read) from [<c0255ab0>]
(vfs_read+0xa0/0x10c)
[18586.278021] [<c0255ab0>] (vfs_read) from [<c0255f4c>]
(SyS_read+0x50/0x88)
[18586.278035] [<c0255f4c>] (SyS_read) from [<c01074e0>]
(ret_fast_syscall+0x0/0x28)
^ permalink raw reply [flat|nested] 10+ messages in thread* Re: inconsistent lock state on v4.14.20-rt17 2018-03-06 15:27 inconsistent lock state on v4.14.20-rt17 Roosen Henri @ 2018-03-06 18:21 ` Sebastian Andrzej Siewior [not found] ` <1520411200.1744.11.camel@ginzinger.com> 0 siblings, 1 reply; 10+ messages in thread From: Sebastian Andrzej Siewior @ 2018-03-06 18:21 UTC (permalink / raw) To: Roosen Henri; +Cc: linux-rt-users On 2018-03-06 15:27:33 [+0000], Roosen Henri wrote: > Hi, > > Ever since 4.9 we've been chasing random kernel crashes which are > reproducible on RT in SMP on iMX6Q. It happens when the system is > stressed using hackbench, however, only when hackbench is used with > sockets, not when used with pipes. > > Lately we've upgraded to v4.14.20-rt17, which doesn't solve the issue, > but instead locks up the kernel. After switching on some Lock-Debugging > we've been able to catch a trace (see below). It would be great if > someone could have a look at it, or guide me in tracing down the root- > cause. The backtrace suggests that the rq lock is taken with interrupts disabled and then with interrupts enabled. But based on the call-trace it should be with interrupts disabled in both cases. I do have a imx6q running hackbench on a regular basis and I haven't seen this. Do you see this backtrace on every hackbench invocation or just after some time. The uptime suggest after ~5 hours. Do you have the .config somewhere? > Thanks, > Henri > > [18586.277233] ================================ > [18586.277236] WARNING: inconsistent lock state > [18586.277245] 4.14.20-rt17-henri-1 #15 Tainted: G W > [18586.277248] -------------------------------- > [18586.277253] inconsistent {IN-HARDIRQ-W} -> {HARDIRQ-ON-W} usage. > [18586.277263] hackbench/18985 [HC0[0]:SC0[0]:HE1:SE1] takes: > [18586.277267] (&rq->lock){?...}, at: [<c0992134>] __schedule+0x128/0x6ac > [18586.277300] {IN-HARDIRQ-W} state was registered at: > [18586.277314] lock_acquire+0x288/0x32c > [18586.277324] _raw_spin_lock+0x48/0x58 > [18586.277338] scheduler_tick+0x40/0xb4 > [18586.277349] update_process_times+0x38/0x6c > [18586.277359] tick_periodic+0x120/0x148 > [18586.277366] tick_handle_periodic+0x2c/0xa0 > [18586.277378] twd_handler+0x3c/0x48 > [18586.277389] handle_percpu_devid_irq+0x290/0x608 > [18586.277395] generic_handle_irq+0x28/0x38 > [18586.277402] __handle_domain_irq+0xd4/0xf0 > [18586.277409] gic_handle_irq+0x64/0xa8 > [18586.277414] __irq_svc+0x70/0xc4 > [18586.277420] lock_acquire+0x2a4/0x32c > [18586.277425] lock_acquire+0x2a4/0x32c > [18586.277440] down_write_nested+0x54/0x68 > [18586.277453] sget_userns+0x310/0x4f4 > [18586.277465] mount_pseudo_xattr+0x68/0x170 > [18586.277477] nsfs_mount+0x3c/0x50 > [18586.277484] mount_fs+0x24/0xa8 > [18586.277490] vfs_kern_mount+0x58/0x118 > [18586.277496] kern_mount_data+0x24/0x34 > [18586.277507] nsfs_init+0x20/0x58 > [18586.277522] start_kernel+0x2f8/0x360 > [18586.277528] 0x1000807c > [18586.277532] irq event stamp: 19441 > [18586.277542] hardirqs last enabled at (19441): [<c099665c>] _raw_spin_unlock_irqrestore+0x88/0x90 > [18586.277550] hardirqs last disabled at (19440): [<c09962f8>] _raw_spin_lock_irqsave+0x2c/0x68 > [18586.277562] softirqs last enabled at (0): [<c0120c18>] copy_process.part.5+0x370/0x1a54 > [18586.277568] softirqs last disabled at (0): [< (null)>] (null) > [18586.277571] > other info that might help us debug this: > [18586.277574] Possible unsafe locking scenario: > > [18586.277576] CPU0 > [18586.277578] ---- > [18586.277580] lock(&rq->lock); > [18586.277587] <Interrupt> > [18586.277588] lock(&rq->lock); > [18586.277594] > *** DEADLOCK *** > > [18586.277599] 2 locks held by hackbench/18985: > [18586.277601] #0: (&u->iolock){+.+.}, at: [<c081de30>] unix_stream_read_generic+0xb0/0x7e4 > [18586.277624] #1: (rcu_read_lock){....}, at: [<c081b73c>] unix_write_space+0x0/0x2b0 > [18586.277640] > stack backtrace: > [18586.277651] CPU: 1 PID: 18985 Comm: hackbench Tainted: G W 4.14.20-rt17-henri-1 #15 > [18586.277654] Hardware name: Freescale i.MX6 Quad/DualLite (Device Tree) > [18586.277683] [<c0111600>] (unwind_backtrace) from [<c010bfe8>] (show_stack+0x20/0x24) > [18586.277701] [<c010bfe8>] (show_stack) from [<c097d79c>] (dump_stack+0x9c/0xd0) > [18586.277714] [<c097d79c>] (dump_stack) from [<c0175424>] (print_usage_bug+0x1c8/0x2d0) > [18586.277725] [<c0175424>] (print_usage_bug) from [<c0175970>] (mark_lock+0x444/0x69c) > [18586.277736] [<c0175970>] (mark_lock) from [<c0177114>] (__lock_acquire+0x23c/0x172c) > [18586.277748] [<c0177114>] (__lock_acquire) from [<c017935c>] (lock_acquire+0x288/0x32c) > [18586.277759] [<c017935c>] (lock_acquire) from [<c0996150>] (_raw_spin_lock+0x48/0x58) > [18586.277774] [<c0996150>] (_raw_spin_lock) from [<c0992134>] (__schedule+0x128/0x6ac) > [18586.277789] [<c0992134>] (__schedule) from [<c09929c0>] (preempt_schedule_irq+0x5c/0x8c) > [18586.277801] [<c09929c0>] (preempt_schedule_irq) from [<c010cc8c>] (svc_preempt+0x8/0x2c) > [18586.277815] [<c010cc8c>] (svc_preempt) from [<c0190b60>] (__rcu_read_unlock+0x40/0x98) > [18586.277829] [<c0190b60>] (__rcu_read_unlock) from [<c081b9a4>] (unix_write_space+0x268/0x2b0) > [18586.277847] [<c081b9a4>] (unix_write_space) from [<c07643d8>] (sock_wfree+0x70/0xac) > [18586.277860] [<c07643d8>] (sock_wfree) from [<c081aff0>] (unix_destruct_scm+0x74/0x7c) > [18586.277876] [<c081aff0>] (unix_destruct_scm) from [<c076a8dc>] (skb_release_head_state+0x78/0x80) > [18586.277891] [<c076a8dc>] (skb_release_head_state) from [<c076ac28>] (skb_release_all+0x1c/0x34) > [18586.277905] [<c076ac28>] (skb_release_all) from [<c076ac5c>] (__kfree_skb+0x1c/0x28) > [18586.277919] [<c076ac5c>] (__kfree_skb) from [<c076b470>] (consume_skb+0x228/0x2b4) > [18586.277933] [<c076b470>] (consume_skb) from [<c081e3d4>] (unix_stream_read_generic+0x654/0x7e4) > [18586.277947] [<c081e3d4>] (unix_stream_read_generic) from [<c081e65c>] (unix_stream_recvmsg+0x5c/0x68) > [18586.277969] [<c081e65c>] (unix_stream_recvmsg) from [<c075f0e0>] (sock_recvmsg+0x28/0x2c) > [18586.277983] [<c075f0e0>] (sock_recvmsg) from [<c075f174>] (sock_read_iter+0x90/0xb8) > [18586.277998] [<c075f174>] (sock_read_iter) from [<c02559ec>] (__vfs_read+0x108/0x12c) > [18586.278010] [<c02559ec>] (__vfs_read) from [<c0255ab0>] (vfs_read+0xa0/0x10c) > [18586.278021] [<c0255ab0>] (vfs_read) from [<c0255f4c>] (SyS_read+0x50/0x88) > [18586.278035] [<c0255f4c>] (SyS_read) from [<c01074e0>] Sebastian ^ permalink raw reply [flat|nested] 10+ messages in thread
[parent not found: <1520411200.1744.11.camel@ginzinger.com>]
* Re: inconsistent lock state on v4.14.20-rt17 [not found] ` <1520411200.1744.11.camel@ginzinger.com> @ 2018-03-08 15:57 ` bigeasy 2018-03-08 17:38 ` Roosen Henri 0 siblings, 1 reply; 10+ messages in thread From: bigeasy @ 2018-03-08 15:57 UTC (permalink / raw) To: Roosen Henri; +Cc: linux-rt-users On 2018-03-07 08:26:40 [+0000], Roosen Henri wrote: > > The backtrace suggests that the rq lock is taken with interrupts > > disabled and then with interrupts enabled. But based on the call- > > trace > > it should be with interrupts disabled in both cases. > > I do have a imx6q running hackbench on a regular basis and I haven't > > seen this. Do you see this backtrace on every hackbench invocation or > > just after some time. The uptime suggest after ~5 hours. > > The crashes are not seen at every invocation of hackbench, but > unfortunately after a few hours to after a few weeks. The test is based > on a "dohell.sh" script from the Xenomai project. I kicked a hackbench on a imx6 with your config. Is the backtrace, that you receive from lockdep, always the same or is it different sometimes? Sebastian ^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: inconsistent lock state on v4.14.20-rt17 2018-03-08 15:57 ` bigeasy @ 2018-03-08 17:38 ` Roosen Henri 2018-03-08 18:00 ` bigeasy 0 siblings, 1 reply; 10+ messages in thread From: Roosen Henri @ 2018-03-08 17:38 UTC (permalink / raw) To: bigeasy; +Cc: linux-rt-users On Thu, 2018-03-08 at 16:57 +0100, bigeasy@linutronix.de wrote: > On 2018-03-07 08:26:40 [+0000], Roosen Henri wrote: > > > The backtrace suggests that the rq lock is taken with interrupts > > > disabled and then with interrupts enabled. But based on the call- > > > trace > > > it should be with interrupts disabled in both cases. > > > I do have a imx6q running hackbench on a regular basis and I > > > haven't > > > seen this. Do you see this backtrace on every hackbench > > > invocation or > > > just after some time. The uptime suggest after ~5 hours. > > > > The crashes are not seen at every invocation of hackbench, but > > unfortunately after a few hours to after a few weeks. The test is > > based > > on a "dohell.sh" script from the Xenomai project. > > I kicked a hackbench on a imx6 with your config. Thanks Sebastian for looking into this! > Is the backtrace, that you receive from lockdep, always the same or > is > it different sometimes? It is different each time. So my gut feeling tells me it might be a memory corruption of some kind.. maybe caused by a use after free or so.. I restarted the target yesterday evening and this morning it was frozen without any trace on the terminal. Attaching a JTAG showed different call-stacks than yesterday; Core #2 (trying to print the info to the terminal) and #3 were spinning on a spin-lock, don't understand what core #0 and #1 were doing. Core#0: __vectors_start() at entry-armv.S:1,234 0xffff000c __pabt_svc() at entry-armv.S:319 0xc010cd84 Core#1: __vectors_start() at entry-armv.S:1,234 0xffff000c __pabt_svc() at entry-armv.S:319 0xc010cd84 Core#2: arch_spin_lock() at spinlock.h:77 0xc017bf38 do_raw_spin_lock() at spinlock_debug.c:115 0xc017bf38 __raw_spin_lock() at spinlock_api_smp.h:143 0xc0996158 _raw_spin_lock() at spinlock.c:155 0xc0996158 vprintk_emit() at printk.c:1,804 0xc0183a8c vprintk_default() at printk.c:1,906 0xc0183e8c vprintk_func() at printk_safe.c:382 0xc0185764 printk() at printk.c:1,939 0xc0184fc4 __warn() at panic.c:523 0xc0123754 warn_slowpath_fmt() at panic.c:567 0xc0123870 Core#3: arch_spin_lock() at spinlock.h:77 0xc017bf38 do_raw_spin_lock() at spinlock_debug.c:115 0xc017bf38 __raw_spin_lock() at spinlock_api_smp.h:143 0xc0996158 _raw_spin_lock() at spinlock.c:155 0xc0996158 __task_rq_lock() at core.c:105 0xc015347c rt_mutex_setprio() at core.c:3,792 0xc0157148 rt_mutex_adjust_prio() at rtmutex.c:380 0xc017a100 task_blocks_on_rt_mutex() at rtmutex.c:1,374 0xc017a780 rt_spin_lock_slowlock_locked() at rtmutex.c:1,061 0xc09941ec rt_spin_lock_slowlock() at rtmutex.c:1,116 0xc099445c rt_spin_lock_fastlock() at rtmutex.c:979 0xc09966c4 rt_spin_lock() at rtmutex.c:1,146 0xc09966c4 skb_queue_tail() at skbuff.c:2,915 0xc076eb08 unix_stream_sendmsg() at af_unix.c:1,908 0xc081dcf8 sock_sendmsg_nosec() at socket.c:639 0xc0760214 sock_sendmsg() at socket.c:643 0xc0760214 sock_write_iter() at socket.c:912 0xc07602b8 call_write_iter() at fs.h:1,771 0xc0255c68 new_sync_write() at read_write.c:469 0xc0255c68 __vfs_write() at read_write.c:482 0xc0255c68 vfs_write() at read_write.c:544 0xc0255e2c SYSC_write() at read_write.c:589 0xc0255fd4 SyS_write() at read_write.c:581 0xc0255fd4 0xc01074e0 Most of the times the call-stacks start at SyS_write() or SyS_read() from hackbench. Some things I found out by testing on v4.9: - minimum test to reproduce problem "while true; do hackbench -g 100 -l 1000; done &" - reproducible with "hackbench -T" (threads) - reproducible only on iMX6Q, not (yet) on iMX6S, iMX6D - NOT reproducible with "hackbench -p" (pipes) As that might be pointing towards the streaming unix socketpair hackbench is using from multiple forked processes, I had a look at net/unix/af_unix.c and wondered why unix_stream_sendmsg() doesn't increase the reference count on the "other" socket the same as unix_dgram_sendmsg() does. I don't see a reason why "other" is handled differently in both functions, so it smells fishy to me. But I'm not familiar with the net-code, so maybe you could review if the diff below would make sense: diff --git a/net/unix/af_unix.c b/net/unix/af_unix.c index 7f46bab4ce5c..5f2ca91bc54d 100644 --- a/net/unix/af_unix.c +++ b/net/unix/af_unix.c @@ -1854,7 +1854,7 @@ static int unix_stream_sendmsg(struct socket *sock, struct msghdr *msg, goto out_err; } else { err = -ENOTCONN; - other = unix_peer(sk); + other = unix_peer_get(sk); if (!other) goto out_err; } @@ -1910,7 +1910,7 @@ static int unix_stream_sendmsg(struct socket *sock, struct msghdr *msg, other->sk_data_ready(other); sent += size; } - + sock_put(other); scm_destroy(&scm); return sent; @@ -1923,6 +1923,8 @@ static int unix_stream_sendmsg(struct socket *sock, struct msghdr *msg, send_sig(SIGPIPE, current, 0); err = -EPIPE; out_err: + if (other) + sock_put(other); scm_destroy(&scm); return sent ? : err; } @@ -1934,13 +1936,13 @@ static ssize_t unix_stream_sendpage(struct socket *socket, struct page *page, bool send_sigpipe = false; bool init_scm = true; struct scm_cookie scm; - struct sock *other, *sk = socket->sk; + struct sock *other = NULL, *sk = socket->sk; struct sk_buff *skb, *newskb = NULL, *tail = NULL; if (flags & MSG_OOB) return -EOPNOTSUPP; - other = unix_peer(sk); + other = unix_peer_get(sk); if (!other || sk->sk_state != TCP_ESTABLISHED) return -ENOTCONN; @@ -2027,6 +2029,7 @@ static ssize_t unix_stream_sendpage(struct socket *socket, struct page *page, mutex_unlock(&unix_sk(other)->iolock); other->sk_data_ready(other); + sock_put(other); scm_destroy(&scm); return size; @@ -2038,6 +2041,8 @@ static ssize_t unix_stream_sendpage(struct socket *socket, struct page *page, kfree_skb(newskb); if (send_sigpipe && !(flags & MSG_NOSIGNAL)) send_sig(SIGPIPE, current, 0); + if (other) + sock_put(other); if (!init_scm) scm_destroy(&scm); return err; > Sebastian Thanks, Henri > ^ permalink raw reply related [flat|nested] 10+ messages in thread
* Re: inconsistent lock state on v4.14.20-rt17 2018-03-08 17:38 ` Roosen Henri @ 2018-03-08 18:00 ` bigeasy 2018-03-09 9:47 ` Roosen Henri 0 siblings, 1 reply; 10+ messages in thread From: bigeasy @ 2018-03-08 18:00 UTC (permalink / raw) To: Roosen Henri; +Cc: linux-rt-users On 2018-03-08 17:38:59 [+0000], Roosen Henri wrote: > > Is the backtrace, that you receive from lockdep, always the same or > > is > > it different sometimes? > > It is different each time. So my gut feeling tells me it might be a > memory corruption of some kind.. maybe caused by a use after free or > so.. CONFIG_SLUB_DEBUG_ON should (or could) catch this. > I restarted the target yesterday evening and this morning it was frozen > without any trace on the terminal. Attaching a JTAG showed different > call-stacks than yesterday; Core #2 (trying to print the info to the > terminal) and #3 were spinning on a spin-lock, don't understand what > core #0 and #1 were doing. maybe #0 and #1 are idle but #2 and #3 should make progress. #2 looks like a warning, do you know where it is from or is this everything you get? Unless the warning comes from an atomic context you should see something on the UART. > Most of the times the call-stacks start at SyS_write() or SyS_read() > from hackbench. but what you posted was lockdep complaining about RQ lock. > Some things I found out by testing on v4.9: > - minimum test to reproduce problem "while true; do hackbench -g 100 -l > 1000; done &" > - reproducible with "hackbench -T" (threads) > - reproducible only on iMX6Q, not (yet) on iMX6S, iMX6D > - NOT reproducible with "hackbench -p" (pipes) interesting. > As that might be pointing towards the streaming unix socketpair > hackbench is using from multiple forked processes, I had a look at > net/unix/af_unix.c and wondered why unix_stream_sendmsg() doesn't > increase the reference count on the "other" socket the same as > unix_dgram_sendmsg() does. I don't see a reason why "other" is handled > differently in both functions, so it smells fishy to me. But I'm not > familiar with the net-code, so maybe you could review if the diff below > would make sense: Commit 830a1e5c212f ("[AF_UNIX]: Remove superfluous reference counting in unix_stream_sendmsg") claims that this is not required. But if your patch makes a difference then… > Thanks, > Henri Sebastian ^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: inconsistent lock state on v4.14.20-rt17 2018-03-08 18:00 ` bigeasy @ 2018-03-09 9:47 ` Roosen Henri 2018-03-14 19:55 ` bigeasy 0 siblings, 1 reply; 10+ messages in thread From: Roosen Henri @ 2018-03-09 9:47 UTC (permalink / raw) To: bigeasy; +Cc: linux-rt-users On Thu, 2018-03-08 at 19:00 +0100, bigeasy@linutronix.de wrote: > On 2018-03-08 17:38:59 [+0000], Roosen Henri wrote: > > > Is the backtrace, that you receive from lockdep, always the same > > > or > > > is > > > it different sometimes? > > > > It is different each time. So my gut feeling tells me it might be a > > memory corruption of some kind.. maybe caused by a use after free > > or > > so.. > > CONFIG_SLUB_DEBUG_ON should (or could) catch this. Thanks for pointing that out! I'll enable this for the next test run. If there are more debug options which are of interest to switch on, then please let me know. > > > I restarted the target yesterday evening and this morning it was > > frozen > > without any trace on the terminal. Attaching a JTAG showed > > different > > call-stacks than yesterday; Core #2 (trying to print the info to > > the > > terminal) and #3 were spinning on a spin-lock, don't understand > > what > > core #0 and #1 were doing. > > maybe #0 and #1 are idle but #2 and #3 should make progress. #2 looks > like a warning, do you know where it is from or is this everything > you > get? Unless the warning comes from an atomic context you should see > something on the UART. #2 and #3 were not making progress, they kept on spinning at the arch_spin_lock(). > > > Most of the times the call-stacks start at SyS_write() or > > SyS_read() > > from hackbench. > > but what you posted was lockdep complaining about RQ lock. Well, actually I've reported "since 4.9 we've been chasing random kernel crashes", and the v4.14 now caught an inconsistent lock state. The hope was that the trace for the inconsistent lock state pointed to the root cause of the random kernel crashes. > > > Some things I found out by testing on v4.9: > > - minimum test to reproduce problem "while true; do hackbench -g > > 100 -l > > 1000; done &" > > - reproducible with "hackbench -T" (threads) > > - reproducible only on iMX6Q, not (yet) on iMX6S, iMX6D > > - NOT reproducible with "hackbench -p" (pipes) > > interesting. > > > As that might be pointing towards the streaming unix socketpair > > hackbench is using from multiple forked processes, I had a look at > > net/unix/af_unix.c and wondered why unix_stream_sendmsg() doesn't > > increase the reference count on the "other" socket the same as > > unix_dgram_sendmsg() does. I don't see a reason why "other" is > > handled > > differently in both functions, so it smells fishy to me. But I'm > > not > > familiar with the net-code, so maybe you could review if the diff > > below > > would make sense: > > Commit 830a1e5c212f ("[AF_UNIX]: Remove superfluous reference > counting > in unix_stream_sendmsg") claims that this is not required. But if > your > patch makes a difference then… Okay, I didn't know the refcounting could be safely removed. The overnight test with the change reproduced the inconsistent lock state again, which proves indeed it makes no difference. > > Sebastian Thanks, Henri ^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: inconsistent lock state on v4.14.20-rt17 2018-03-09 9:47 ` Roosen Henri @ 2018-03-14 19:55 ` bigeasy 2018-03-16 10:30 ` bigeasy 0 siblings, 1 reply; 10+ messages in thread From: bigeasy @ 2018-03-14 19:55 UTC (permalink / raw) To: Roosen Henri; +Cc: linux-rt-users On 2018-03-09 09:47:16 [+0000], Roosen Henri wrote: > > maybe #0 and #1 are idle but #2 and #3 should make progress. #2 looks > > like a warning, do you know where it is from or is this everything > > you > > get? Unless the warning comes from an atomic context you should see > > something on the UART. > > #2 and #3 were not making progress, they kept on spinning at the > arch_spin_lock(). It looks like those two are different locks. So someone should own it (and be running) and unlock once done. > > > Some things I found out by testing on v4.9: > > > - minimum test to reproduce problem "while true; do hackbench -g > > > 100 -l > > > 1000; done &" > > > - reproducible with "hackbench -T" (threads) > > > - reproducible only on iMX6Q, not (yet) on iMX6S, iMX6D > > > - NOT reproducible with "hackbench -p" (pipes) |Running in process mode with 100 groups using 40 file descriptors each (== 4000 tasks) |Each sender will pass 1000 messages of 100 bytes |Time: 552.224 |Running in process mode with 100 groups using 40 file descriptors each (== 4000 tasks) |Each sender will pass 1000 messages of 100 bytes |Signal 2 caught, longjmp'ing out! |longjmp'ed out, reaping children |sending SIGTERM to all child processes |signaling 4000 worker threads to terminate |^C^CTime: 476.063 |~# uptime | 19:50:19 up 6 days, 4:11, 1 user, load average: 0.01, 0.01, 0.10 This survived 6 days. It was challenging to cancel hackbench because it was running via ssh in a screen session and I was loosing my network connection due to inactivity… > Thanks, > Henri Sebastian ^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: inconsistent lock state on v4.14.20-rt17 2018-03-14 19:55 ` bigeasy @ 2018-03-16 10:30 ` bigeasy 2018-03-17 21:03 ` bigeasy 0 siblings, 1 reply; 10+ messages in thread From: bigeasy @ 2018-03-16 10:30 UTC (permalink / raw) To: Roosen Henri; +Cc: linux-rt-users On 2018-03-14 20:55:24 [+0100], To Roosen Henri wrote: > This survived 6 days. It was challenging to cancel hackbench because it > was running via ssh in a screen session and I was loosing my network > connection due to inactivity… okay. It may have survived but it managed to trigger this. Trying to make sense to this… > > Thanks, > > Henri Sebastian ^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: inconsistent lock state on v4.14.20-rt17 2018-03-16 10:30 ` bigeasy @ 2018-03-17 21:03 ` bigeasy 2018-03-21 8:31 ` Roosen Henri 0 siblings, 1 reply; 10+ messages in thread From: bigeasy @ 2018-03-17 21:03 UTC (permalink / raw) To: Roosen Henri; +Cc: linux-rt-users On 2018-03-16 11:30:09 [+0100], To Roosen Henri wrote: > On 2018-03-14 20:55:24 [+0100], To Roosen Henri wrote: > > This survived 6 days. It was challenging to cancel hackbench because it > > was running via ssh in a screen session and I was loosing my network > > connection due to inactivity… > > okay. It may have survived but it managed to trigger this. Trying to > make sense to this… So after I traced it down I figured out that you need 6b0ef92fee2a ("rtmutex: Make rt_mutex_futex_unlock() safe for irq-off callsites") https://git.kernel.org/tip/6b0ef92fee2a > > > Thanks, > > > Henri Sebastian ^ permalink raw reply [flat|nested] 10+ messages in thread
* Re: inconsistent lock state on v4.14.20-rt17 2018-03-17 21:03 ` bigeasy @ 2018-03-21 8:31 ` Roosen Henri 0 siblings, 0 replies; 10+ messages in thread From: Roosen Henri @ 2018-03-21 8:31 UTC (permalink / raw) To: bigeasy; +Cc: linux-rt-users Henri Roosen | Entwicklung Software GINZINGER ELECTRONIC SYSTEMS GMBH Tel.: +43 7723 5422 161 Mail: henri.roosen@ginzinger.com Web: www.ginzinger.com On Sat, 2018-03-17 at 22:03 +0100, bigeasy@linutronix.de wrote: > On 2018-03-16 11:30:09 [+0100], To Roosen Henri wrote: > > On 2018-03-14 20:55:24 [+0100], To Roosen Henri wrote: > > > This survived 6 days. It was challenging to cancel hackbench > > > because it > > > was running via ssh in a screen session and I was loosing my > > > network > > > connection due to inactivity… > > > > okay. It may have survived but it managed to trigger this. Trying > > to > > make sense to this… > > So after I traced it down I figured out that you need > 6b0ef92fee2a ("rtmutex: Make rt_mutex_futex_unlock() safe for irq- > off callsites") > https://git.kernel.org/tip/6b0ef92fee2a > Sorry for not being able to reply earlier, I was on a short holiday. Thanks for figuring out the fix! I noticed you released v4.14.28-rt23 which includes the patch. I will give that version a test on our systems. As the inconsistent lock state issue was introduced only in v4.14, this will not be the issue we've seen on v4.9. However, that might have been fixed along the way to v4.14... I will keep you posted on the outcome. > > > > Thanks, > > > > Henri > > Sebastian Thanks, Henri ________________________________________ Ginzinger electronic systems GmbH Gewerbegebiet Pirath 16 4952 Weng im Innkreis www.ginzinger.com Firmenbuchnummer: FN 364958d Firmenbuchgericht: Ried im Innkreis UID-Nr.: ATU66521089 ^ permalink raw reply [flat|nested] 10+ messages in thread
end of thread, other threads:[~2018-03-21 8:31 UTC | newest]
Thread overview: 10+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2018-03-06 15:27 inconsistent lock state on v4.14.20-rt17 Roosen Henri
2018-03-06 18:21 ` Sebastian Andrzej Siewior
[not found] ` <1520411200.1744.11.camel@ginzinger.com>
2018-03-08 15:57 ` bigeasy
2018-03-08 17:38 ` Roosen Henri
2018-03-08 18:00 ` bigeasy
2018-03-09 9:47 ` Roosen Henri
2018-03-14 19:55 ` bigeasy
2018-03-16 10:30 ` bigeasy
2018-03-17 21:03 ` bigeasy
2018-03-21 8:31 ` Roosen Henri
This is an external index of several public inboxes, see mirroring instructions on how to clone and mirror all data and code used by this external index.