inconsistent lock state on v4.14.20-rt17

inconsistent lock state on v4.14.20-rt17

[Roosen Henri]

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)

Re: inconsistent lock state on v4.14.20-rt17

[Sebastian Andrzej Siewior]

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

Re: inconsistent lock state on v4.14.20-rt17

[bigeasy]

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

Re: inconsistent lock state on v4.14.20-rt17

[Roosen Henri]

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

> 

Re: inconsistent lock state on v4.14.20-rt17

[bigeasy]

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

Re: inconsistent lock state on v4.14.20-rt17

[Roosen Henri]

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

Re: inconsistent lock state on v4.14.20-rt17

[bigeasy]

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

Re: inconsistent lock state on v4.14.20-rt17

[bigeasy]

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

Re: inconsistent lock state on v4.14.20-rt17

[bigeasy]

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

Re: inconsistent lock state on v4.14.20-rt17

[Roosen Henri]

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