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.
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] =======================
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 <[email protected]>
---
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); \
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 <[email protected]>
> ---
> 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.
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/