possible recursive locking, 2.6.24-rc7

possible recursive locking, 2.6.24-rc7

[Denys Fedoryshchenko]

Hi, got in dmesg
Not sure where to send (there is TCP), so sending netdev@ and kernel@


[159859.491752]
[159859.491755] =============================================
[159859.492021] [ INFO: possible recursive locking detected ]
[159859.492156] 2.6.24-rc7-devel #2
[159859.492284] ---------------------------------------------
[159859.492418] swapper/0 is trying to acquire lock:
[159859.492550]  (&q->lock){++..}, at: [<c01175ff>] __wake_up+0x15/0x42
[159859.492883]
[159859.492884] but task is already holding lock:
[159859.493140]  (&q->lock){++..}, at: [<c01175ff>] __wake_up+0x15/0x42
[159859.493466]
[159859.493467] other info that might help us debug this:
[159859.493726] 5 locks held by swapper/0:
[159859.495687]  #0:  (rcu_read_lock){..--}, at: [<c02dd9af>]
netif_receive_skb+                                                           
                 0x9c/0x3a7
[159859.496141]  #1:  (rcu_read_lock){..--}, at: [<c02f8072>]
ip_local_deliver_f                                                           
                 inish+0x30/0x18d
[159859.496604]  #2:  (slock-AF_INET/1){-+..}, at: [<c0310474>]
tcp_v4_rcv+0x426                                                             
               /0x812
[159859.497104]  #3:  (clock-AF_INET){-.-?}, at: [<c02d7684>]
sock_def_readable+                                                           
                 0x18/0x6e
[159859.497555]  #4:  (&q->lock){++..}, at: [<c01175ff>] __wake_up+0x15/0x42
[159859.497931]
[159859.497932] stack backtrace:
[159859.498185] Pid: 0, comm: swapper Not tainted 2.6.24-rc7-devel #2
[159859.498320]  [<c0105e68>] show_trace_log_lvl+0x1a/0x2f
[159859.498505]  [<c0106810>] show_trace+0x12/0x14
[159859.498690]  [<c0107107>] dump_stack+0x6c/0x72
[159859.498872]  [<c01384c0>] __lock_acquire+0x172/0xb8c
[159859.499057]  [<c01392a7>] lock_acquire+0x5f/0x78
[159859.499239]  [<c03299cf>] _spin_lock_irqsave+0x34/0x44
[159859.499423]  [<c01175ff>] __wake_up+0x15/0x42
[159859.499604]  [<c01869ea>] ep_poll_safewake+0x8e/0xbf
[159859.499787]  [<c01876b3>] ep_poll_callback+0x9f/0xac
[159859.499970]  [<c0115d36>] __wake_up_common+0x32/0x5c
[159859.500154]  [<c011761b>] __wake_up+0x31/0x42
[159859.500335]  [<c02d76ae>] sock_def_readable+0x42/0x6e
[159859.500518]  [<c0309105>] tcp_rcv_established+0x3bc/0x643
[159859.500704]  [<c030e588>] tcp_v4_do_rcv+0x2f/0x325
[159859.500887]  [<c0310817>] tcp_v4_rcv+0x7c9/0x812
[159859.501069]  [<c02f8149>] ip_local_deliver_finish+0x107/0x18d
[159859.501255]  [<c02f854e>] ip_local_deliver+0x72/0x7c
[159859.501438]  [<c02f8023>] ip_rcv_finish+0x2cf/0x2ee
[159859.501623]  [<c02f84b2>] ip_rcv+0x211/0x23b
[159859.501805]  [<c02ddc63>] netif_receive_skb+0x350/0x3a7
[159859.501989]  [<f88f2b6d>] bnx2_poll+0x975/0xb45 [bnx2]
[159859.502177]  [<c02dfdab>] net_rx_action+0x6c/0x116
[159859.502360]  [<c0120ed8>] __do_softirq+0x6f/0xe9
[159859.502543]  [<c0120f8c>] do_softirq+0x3a/0x52
[159859.502728]  [<c012128b>] irq_exit+0x47/0x7b
[159859.502911]  [<c01076af>] do_IRQ+0x81/0x96
[159859.503098]  [<c010586a>] common_interrupt+0x2e/0x34
[159859.503288]  [<c0103434>] mwait_idle+0x12/0x14
[159859.503476]  [<c010353d>] cpu_idle+0x7b/0x95
[159859.503662]  [<c03272c9>] rest_init+0x49/0x4b
[159859.503844]  [<c0449c08>] start_kernel+0x2f9/0x301
[159859.504030]  [<00000000>] 0x0
[159859.504210]  =======================


--
Denys Fedoryshchenko
Technical Manager
Virtual ISP S.A.L.

Re: possible recursive locking, 2.6.24-rc7

[Peter Zijlstra]

On Sun, 2008-01-13 at 17:51 +0200, Denys Fedoryshchenko wrote:
> Hi, got in dmesg
> Not sure where to send (there is TCP), so sending netdev@ and kernel@

It's epoll, this is a known issue and will be fixed soon. Thanks for
reporting.

> [159859.491752]
> [159859.491755] =============================================
> [159859.492021] [ INFO: possible recursive locking detected ]
> [159859.492156] 2.6.24-rc7-devel #2
> [159859.492284] ---------------------------------------------
> [159859.492418] swapper/0 is trying to acquire lock:
> [159859.492550]  (&q->lock){++..}, at: [<c01175ff>] __wake_up+0x15/0x42
> [159859.492883]
> [159859.492884] but task is already holding lock:
> [159859.493140]  (&q->lock){++..}, at: [<c01175ff>] __wake_up+0x15/0x42
> [159859.493466]
> [159859.493467] other info that might help us debug this:
> [159859.493726] 5 locks held by swapper/0:
> [159859.495687]  #0:  (rcu_read_lock){..--}, at: [<c02dd9af>]
> netif_receive_skb+                                                           
>                  0x9c/0x3a7
> [159859.496141]  #1:  (rcu_read_lock){..--}, at: [<c02f8072>]
> ip_local_deliver_f                                                           
>                  inish+0x30/0x18d
> [159859.496604]  #2:  (slock-AF_INET/1){-+..}, at: [<c0310474>]
> tcp_v4_rcv+0x426                                                             
>                /0x812
> [159859.497104]  #3:  (clock-AF_INET){-.-?}, at: [<c02d7684>]
> sock_def_readable+                                                           
>                  0x18/0x6e
> [159859.497555]  #4:  (&q->lock){++..}, at: [<c01175ff>] __wake_up+0x15/0x42
> [159859.497931]
> [159859.497932] stack backtrace:
> [159859.498185] Pid: 0, comm: swapper Not tainted 2.6.24-rc7-devel #2
> [159859.498320]  [<c0105e68>] show_trace_log_lvl+0x1a/0x2f
> [159859.498505]  [<c0106810>] show_trace+0x12/0x14
> [159859.498690]  [<c0107107>] dump_stack+0x6c/0x72
> [159859.498872]  [<c01384c0>] __lock_acquire+0x172/0xb8c
> [159859.499057]  [<c01392a7>] lock_acquire+0x5f/0x78
> [159859.499239]  [<c03299cf>] _spin_lock_irqsave+0x34/0x44
> [159859.499423]  [<c01175ff>] __wake_up+0x15/0x42
> [159859.499604]  [<c01869ea>] ep_poll_safewake+0x8e/0xbf
> [159859.499787]  [<c01876b3>] ep_poll_callback+0x9f/0xac
> [159859.499970]  [<c0115d36>] __wake_up_common+0x32/0x5c
> [159859.500154]  [<c011761b>] __wake_up+0x31/0x42
> [159859.500335]  [<c02d76ae>] sock_def_readable+0x42/0x6e
> [159859.500518]  [<c0309105>] tcp_rcv_established+0x3bc/0x643
> [159859.500704]  [<c030e588>] tcp_v4_do_rcv+0x2f/0x325
> [159859.500887]  [<c0310817>] tcp_v4_rcv+0x7c9/0x812
> [159859.501069]  [<c02f8149>] ip_local_deliver_finish+0x107/0x18d
> [159859.501255]  [<c02f854e>] ip_local_deliver+0x72/0x7c
> [159859.501438]  [<c02f8023>] ip_rcv_finish+0x2cf/0x2ee
> [159859.501623]  [<c02f84b2>] ip_rcv+0x211/0x23b
> [159859.501805]  [<c02ddc63>] netif_receive_skb+0x350/0x3a7
> [159859.501989]  [<f88f2b6d>] bnx2_poll+0x975/0xb45 [bnx2]
> [159859.502177]  [<c02dfdab>] net_rx_action+0x6c/0x116
> [159859.502360]  [<c0120ed8>] __do_softirq+0x6f/0xe9
> [159859.502543]  [<c0120f8c>] do_softirq+0x3a/0x52
> [159859.502728]  [<c012128b>] irq_exit+0x47/0x7b
> [159859.502911]  [<c01076af>] do_IRQ+0x81/0x96
> [159859.503098]  [<c010586a>] common_interrupt+0x2e/0x34
> [159859.503288]  [<c0103434>] mwait_idle+0x12/0x14
> [159859.503476]  [<c010353d>] cpu_idle+0x7b/0x95
> [159859.503662]  [<c03272c9>] rest_init+0x49/0x4b
> [159859.503844]  [<c0449c08>] start_kernel+0x2f9/0x301
> [159859.504030]  [<00000000>] 0x0
> [159859.504210]  =======================

Re: possible recursive locking, 2.6.24-rc7

[Peter Zijlstra]

On Sun, 2008-01-13 at 17:22 +0100, Peter Zijlstra wrote:
> On Sun, 2008-01-13 at 17:51 +0200, Denys Fedoryshchenko wrote:
> > Hi, got in dmesg
> > Not sure where to send (there is TCP), so sending netdev@ and kernel@
> 
> It's epoll, this is a known issue and will be fixed soon. Thanks for
> reporting.

If its easy for you to reproduce, would you mind giving the following
patch a spin?

---

Subject: lockdep: annotate epoll

On Sat, 2008-01-05 at 13:35 -0800, Davide Libenzi wrote:

> I remember I talked with Arjan about this time ago. Basically, since 1) 
> you can drop an epoll fd inside another epoll fd 2) callback-based wakeups 
> are used, you can see a wake_up() from inside another wake_up(), but they 
> will never refer to the same lock instance.
> Think about:
> 
> 	dfd = socket(...);
> 	efd1 = epoll_create();
> 	efd2 = epoll_create();
> 	epoll_ctl(efd1, EPOLL_CTL_ADD, dfd, ...);
> 	epoll_ctl(efd2, EPOLL_CTL_ADD, efd1, ...);
> 
> When a packet arrives to the device underneath "dfd", the net code will 
> issue a wake_up() on its poll wake list. Epoll (efd1) has installed a 
> callback wakeup entry on that queue, and the wake_up() performed by the 
> "dfd" net code will end up in ep_poll_callback(). At this point epoll 
> (efd1) notices that it may have some event ready, so it needs to wake up 
> the waiters on its poll wait list (efd2). So it calls ep_poll_safewake() 
> that ends up in another wake_up(), after having checked about the 
> recursion constraints. That are, no more than EP_MAX_POLLWAKE_NESTS, to 
> avoid stack blasting. Never hit the same queue, to avoid loops like:
> 
> 	epoll_ctl(efd2, EPOLL_CTL_ADD, efd1, ...);
> 	epoll_ctl(efd3, EPOLL_CTL_ADD, efd2, ...);
> 	epoll_ctl(efd4, EPOLL_CTL_ADD, efd3, ...);
> 	epoll_ctl(efd1, EPOLL_CTL_ADD, efd4, ...);
> 
> The code "if (tncur->wq == wq || ..." prevents re-entering the same 
> queue/lock.

Since the epoll code is very careful to not nest same instance locks
allow the recursion.

Signed-off-by: Peter Zijlstra <a.p.zijlstra@chello.nl>
---
 fs/eventpoll.c       |    2 +-
 include/linux/wait.h |   16 ++++++++++++++++
 2 files changed, 17 insertions(+), 1 deletion(-)

Index: linux-2.6/fs/eventpoll.c
===================================================================
--- linux-2.6.orig/fs/eventpoll.c
+++ linux-2.6/fs/eventpoll.c
@@ -353,7 +353,7 @@ static void ep_poll_safewake(struct poll
 	spin_unlock_irqrestore(&psw->lock, flags);
 
 	/* Do really wake up now */
-	wake_up(wq);
+	wake_up_nested(wq, 1 + wake_nests);
 
 	/* Remove the current task from the list */
 	spin_lock_irqsave(&psw->lock, flags);
Index: linux-2.6/include/linux/wait.h
===================================================================
--- linux-2.6.orig/include/linux/wait.h
+++ linux-2.6/include/linux/wait.h
@@ -161,6 +161,22 @@ wait_queue_head_t *FASTCALL(bit_waitqueu
 #define	wake_up_locked(x)		__wake_up_locked((x), TASK_UNINTERRUPTIBLE | TASK_INTERRUPTIBLE)
 #define wake_up_interruptible_sync(x)   __wake_up_sync((x),TASK_INTERRUPTIBLE, 1)
 
+#ifdef CONFIG_DEBUG_LOCK_ALLOC
+/*
+ * macro to avoid include hell
+ */
+#define wake_up_nested(x, s)						\
+do {									\
+	unsigned long flags;						\
+									\
+	spin_lock_irqsave_nested(&(x)->lock, flags, (s));		\
+	wake_up_locked(x); 						\
+	spin_unlock_irqrestore(&(x)->lock, flags);			\
+} while (0)
+#else
+#define wake_up_nested(x, s)		wake_up(x)
+#endif
+
 #define __wait_event(wq, condition) 					\
 do {									\
 	DEFINE_WAIT(__wait);						\

Re: possible recursive locking, 2.6.24-rc7

[Denys Fedoryshchenko]

I cannot reproduce, it is happened with rtorrent just randomly. But i will
patch and keep watching.

On Sun, 13 Jan 2008 19:44:26 +0100, Peter Zijlstra wrote
> On Sun, 2008-01-13 at 17:22 +0100, Peter Zijlstra wrote:
> > On Sun, 2008-01-13 at 17:51 +0200, Denys Fedoryshchenko wrote:
> > > Hi, got in dmesg
> > > Not sure where to send (there is TCP), so sending netdev@ and kernel@
> > 
> > It's epoll, this is a known issue and will be fixed soon. Thanks for
> > reporting.
> 
> If its easy for you to reproduce, would you mind giving the following
> patch a spin?
> 
> ---
> 
> Subject: lockdep: annotate epoll
> 
> On Sat, 2008-01-05 at 13:35 -0800, Davide Libenzi wrote:
> 
> > I remember I talked with Arjan about this time ago. Basically, since 1) 
> > you can drop an epoll fd inside another epoll fd 2) callback-based wakeups 
> > are used, you can see a wake_up() from inside another wake_up(), but they 
> > will never refer to the same lock instance.
> > Think about:
> > 
> > 	dfd = socket(...);
> > 	efd1 = epoll_create();
> > 	efd2 = epoll_create();
> > 	epoll_ctl(efd1, EPOLL_CTL_ADD, dfd, ...);
> > 	epoll_ctl(efd2, EPOLL_CTL_ADD, efd1, ...);
> > 
> > When a packet arrives to the device underneath "dfd", the net code will 
> > issue a wake_up() on its poll wake list. Epoll (efd1) has installed a 
> > callback wakeup entry on that queue, and the wake_up() performed by the 
> > "dfd" net code will end up in ep_poll_callback(). At this point epoll 
> > (efd1) notices that it may have some event ready, so it needs to wake up 
> > the waiters on its poll wait list (efd2). So it calls ep_poll_safewake() 
> > that ends up in another wake_up(), after having checked about the 
> > recursion constraints. That are, no more than EP_MAX_POLLWAKE_NESTS, to 
> > avoid stack blasting. Never hit the same queue, to avoid loops like:
> > 
> > 	epoll_ctl(efd2, EPOLL_CTL_ADD, efd1, ...);
> > 	epoll_ctl(efd3, EPOLL_CTL_ADD, efd2, ...);
> > 	epoll_ctl(efd4, EPOLL_CTL_ADD, efd3, ...);
> > 	epoll_ctl(efd1, EPOLL_CTL_ADD, efd4, ...);
> > 
> > The code "if (tncur->wq == wq || ..." prevents re-entering the same 
> > queue/lock.
> 
> Since the epoll code is very careful to not nest same instance locks
> allow the recursion.
> 
> Signed-off-by: Peter Zijlstra <a.p.zijlstra@chello.nl>
> ---
>  fs/eventpoll.c       |    2 +-
>  include/linux/wait.h |   16 ++++++++++++++++
>  2 files changed, 17 insertions(+), 1 deletion(-)
> 
> Index: linux-2.6/fs/eventpoll.c
> ===================================================================
> --- linux-2.6.orig/fs/eventpoll.c
> +++ linux-2.6/fs/eventpoll.c
> @@ -353,7 +353,7 @@ static void ep_poll_safewake(struct poll
>  	spin_unlock_irqrestore(&psw->lock, flags);
> 
>  	/* Do really wake up now */
> -	wake_up(wq);
> +	wake_up_nested(wq, 1 + wake_nests);
> 
>  	/* Remove the current task from the list */
>  	spin_lock_irqsave(&psw->lock, flags);
> Index: linux-2.6/include/linux/wait.h
> ===================================================================
> --- linux-2.6.orig/include/linux/wait.h
> +++ linux-2.6/include/linux/wait.h
> @@ -161,6 +161,22 @@ wait_queue_head_t *FASTCALL(bit_waitqueu
>  #define	wake_up_locked(x)		__wake_up_locked((x),
>  TASK_UNINTERRUPTIBLE | TASK_INTERRUPTIBLE) #define 
> wake_up_interruptible_sync(x)   __wake_up_sync((x),
> TASK_INTERRUPTIBLE, 1)
> 
> +#ifdef CONFIG_DEBUG_LOCK_ALLOC
> +/*
> + * macro to avoid include hell
> + */
> +#define wake_up_nested(x, s)						\
> +do {									\
> +	unsigned long flags;						\
> +									\
> +	spin_lock_irqsave_nested(&(x)->lock, flags, (s));		\
> +	wake_up_locked(x); 						\
> +	spin_unlock_irqrestore(&(x)->lock, flags);			\
> +} while (0)
> +#else
> +#define wake_up_nested(x, s)		wake_up(x)
> +#endif
> +
>  #define __wait_event(wq, condition) 					\
>  do {									\
>  	DEFINE_WAIT(__wait);						\


--
Denys Fedoryshchenko
Technical Manager
Virtual ISP S.A.L.

Re: possible recursive locking, 2.6.24-rc7

[Stefan Richter]

Denys Fedoryshchenko wrote:
> I cannot reproduce, it is happened with rtorrent just randomly. But i will
> patch and keep watching.
> 
> On Sun, 13 Jan 2008 19:44:26 +0100, Peter Zijlstra wrote
>> On Sun, 2008-01-13 at 17:22 +0100, Peter Zijlstra wrote:
>> > It's epoll, this is a known issue and will be fixed soon. Thanks for
>> > reporting.
>> 
>> If its easy for you to reproduce, would you mind giving the following
>> patch a spin?

I may have a way to trigger another epoll "recursive-locking" trace at
will with current firewire development code.  Will try the annotation
patch when I have time.
https://bugzilla.redhat.com/show_bug.cgi?id=323411
http://marc.info/?l=linux1394-devel&m=120006699425902
-- 
Stefan Richter
-=====-==--- ---= -===-
http://arcgraph.de/sr/