Re: locking api self-test hanging

On Sun, 3 Feb 2008 15:02:46 -0800 Andrew Morton [off-list ref] wrote:

With current mainline I'm getting intermittent hangs here:

	http://userweb.kernel.org/~akpm/p2033590.jpg

with this config:

	http://userweb.kernel.org/~akpm/config-sony.txt

on the Vaio.  Sometimes it boots (then hits another different hang),
sometimes it gets stuck there.

The second hang is in kobject_uevent_init().  All that function does is call
netlink_kernel_create().

These things make bisecting all the other bugs rather hard.

On Sun, 3 Feb 2008 15:07:44 -0800 Andrew Morton [off-list ref] wrote:

On Sun, 3 Feb 2008 15:02:46 -0800 Andrew Morton [off-list ref] wrote:

quoted

With current mainline I'm getting intermittent hangs here:

	http://userweb.kernel.org/~akpm/p2033590.jpg

with this config:

	http://userweb.kernel.org/~akpm/config-sony.txt

on the Vaio.  Sometimes it boots (then hits another different hang),
sometimes it gets stuck there.

CONFIG_DEBUG_LOCKING_API_SELFTESTS=n fixed that up.

The second hang is in kobject_uevent_init().  All that function does is call
netlink_kernel_create().

And I've fully bisected this hang twice and both times came up with

commit 33f807ba0d9259e7c75c7a2ce8bd2787e5b540c7
Author: Stephen Hemminger [off-list ref]
Date:   Mon Nov 19 19:24:52 2007 -0800

    [NETPOLL]: Kill NETPOLL_RX_DROP, set but never tested.

which is stupid because that patch doesn't do anything.

However I am using netconsole-over-e100 and the hang does go away when I
disable netconsole on the kernel boot command line.

I'd say it's some timing thing in netpoll/netconsole/napi/etc.

On Mon, 4 Feb 2008 04:43:04 -0800 Andrew Morton [off-list ref] wrote:

On Sun, 3 Feb 2008 15:07:44 -0800 Andrew Morton [off-list ref] wrote:

quoted

On Sun, 3 Feb 2008 15:02:46 -0800 Andrew Morton [off-list ref] wrote:

quoted

With current mainline I'm getting intermittent hangs here:

	http://userweb.kernel.org/~akpm/p2033590.jpg

with this config:

	http://userweb.kernel.org/~akpm/config-sony.txt

on the Vaio.  Sometimes it boots (then hits another different hang),
sometimes it gets stuck there.

CONFIG_DEBUG_LOCKING_API_SELFTESTS=n fixed that up.

quoted

The second hang is in kobject_uevent_init().  All that function does is call
netlink_kernel_create().

And I've fully bisected this hang twice and both times came up with

commit 33f807ba0d9259e7c75c7a2ce8bd2787e5b540c7
Author: Stephen Hemminger [off-list ref]
Date:   Mon Nov 19 19:24:52 2007 -0800

    [NETPOLL]: Kill NETPOLL_RX_DROP, set but never tested.

which is stupid because that patch doesn't do anything.

However I am using netconsole-over-e100 and the hang does go away when I
disable netconsole on the kernel boot command line.

After disabling both CONFIG_DEBUG_LOCKING_API_SELFTESTS and netconsole
(using current mainline) I get a login prompt, and also...

[    5.181668] SELinux: policy loaded with handle_unknown=deny
[    5.183315] type=1403 audit(1202100038.157:3): policy loaded auid=4294967295 ses=4294967295
[    5.822073] SELinux: initialized (dev usbfs, type usbfs), uses genfs_contexts
[    7.819146] ------------[ cut here ]------------
[    7.819146] WARNING: at kernel/lockdep.c:2033 trace_hardirqs_on+0x9b/0x10d()
[    7.819146] Modules linked in: generic ext3 jbd ide_disk ide_core
[    7.819146] Pid: 399, comm: hwclock Not tainted 2.6.24 #4
[    7.819146]  [<c011d140>] warn_on_slowpath+0x41/0x51
[    7.819146]  [<c01364a9>] ? lock_release_holdtime+0x50/0x56
[    7.819146]  [<c013770c>] ? check_usage_forwards+0x19/0x3b
[    7.819146]  [<c01390c4>] ? __lock_acquire+0xac3/0xb0b
[    7.819146]  [<c0108c98>] ? native_sched_clock+0x8b/0x9f
[    7.819146]  [<c01364a9>] ? lock_release_holdtime+0x50/0x56
[    7.819146]  [<c030ca6c>] ? _spin_unlock_irq+0x22/0x42
[    7.819146]  [<c013848b>] trace_hardirqs_on+0x9b/0x10d
[    7.819146]  [<c030ca6c>] _spin_unlock_irq+0x22/0x42
[    7.819146]  [<c011481e>] hpet_rtc_interrupt+0xdf/0x290
[    7.819146]  [<c014ea90>] handle_IRQ_event+0x1a/0x46
[    7.819146]  [<c014f8ea>] handle_edge_irq+0xbe/0xff
[    7.819146]  [<c0106e08>] do_IRQ+0x6d/0x84
[    7.819146]  [<c0105596>] common_interrupt+0x2e/0x34
[    7.819146]  [<c013007b>] ? ktime_get_ts+0x8/0x3f
[    7.819146]  [<c0139420>] ? lock_release+0x167/0x16f
[    7.819146]  [<c017974a>] ? core_sys_select+0x2c/0x327
[    7.819146]  [<c0179792>] core_sys_select+0x74/0x327
[    7.819146]  [<c0108c98>] ? native_sched_clock+0x8b/0x9f
[    7.819146]  [<c01364a9>] ? lock_release_holdtime+0x50/0x56
[    7.819146]  [<c030ca6c>] ? _spin_unlock_irq+0x22/0x42
[    7.819146]  [<c01384d6>] ? trace_hardirqs_on+0xe6/0x10d
[    7.819146]  [<c030ca77>] ? _spin_unlock_irq+0x2d/0x42
[    7.819146]  [<c023b437>] ? rtc_do_ioctl+0x11b/0x677
[    7.819146]  [<c01c487e>] ? inode_has_perm+0x5e/0x68
[    7.819146]  [<c01364a9>] ? lock_release_holdtime+0x50/0x56
[    7.819146]  [<c0108c98>] ? native_sched_clock+0x8b/0x9f
[    7.819146]  [<c01c490b>] ? file_has_perm+0x83/0x8c
[    7.819146]  [<c023ba08>] ? rtc_ioctl+0xf/0x11
[    7.819146]  [<c017898d>] ? do_ioctl+0x55/0x67
[    7.819146]  [<c0179d15>] sys_select+0x93/0x163
[    7.819146]  [<c0104b39>] ? sysenter_past_esp+0x9a/0xa5
[    7.819146]  [<c0104afe>] sysenter_past_esp+0x5f/0xa5
[    7.819146]  =======================
[    7.819146] ---[ end trace 96540ca301ffb84c ]---
[    7.819210] rtc: lost 6 interrupts
[    7.870668] type=1400 audit(1202128840.794:4): avc:  denied  { audit_write } for  pid=399 comm="hwclock" capability=29 scontext=system_u:system_r:hwclock_t:s0 tcontext=system_u:system_r:hwclock_t:s0 tclass=capability
[    9.538866] input: PC Speaker as /class/input/input5

Because hpet_rtc_interrupt()'s call to get_rtc_time() ends up
resolving to include/asm-generic/rtc.h's (hilariously inlined)
get_rtc_time(), which does spin_unlock_irq() from hard IRQ context.

That warning in lockdep.c should have a comment explaining to readers under
which circumstances it will trigger, and what they did wrong.  In fact if
I've interpreted it correctly I don't see why it's a DEBUG_LOCKS_WARN_ON
thing at all?  It should be a first-class lockdep warning?

The obvious patch fixes it:

--- a/include/asm-generic/rtc.h~a
+++ a/include/asm-generic/rtc.h

@@ -35,10 +35,11 @@
 static inline unsigned char rtc_is_updating(void)
 {
 	unsigned char uip;
+	unsigned long flags;
 
-	spin_lock_irq(&rtc_lock);
+	spin_lock_irqsave(&rtc_lock, flags);
 	uip = (CMOS_READ(RTC_FREQ_SELECT) & RTC_UIP);
-	spin_unlock_irq(&rtc_lock);
+	spin_unlock_irqrestore(&rtc_lock, flags);
 	return uip;
 }
 

@@ -46,6 +47,8 @@ static inline unsigned int get_rtc_time(
 {
 	unsigned long uip_watchdog = jiffies;
 	unsigned char ctrl;
+	unsigned long flags;
+
 #ifdef CONFIG_MACH_DECSTATION
 	unsigned int real_year;
 #endif

@@ -72,7 +75,7 @@ static inline unsigned int get_rtc_time(
 	 * RTC has RTC_DAY_OF_WEEK, we ignore it, as it is only updated
 	 * by the RTC when initially set to a non-zero value.
 	 */
-	spin_lock_irq(&rtc_lock);
+	spin_lock_irqsave(&rtc_lock, flags);
 	time->tm_sec = CMOS_READ(RTC_SECONDS);
 	time->tm_min = CMOS_READ(RTC_MINUTES);
 	time->tm_hour = CMOS_READ(RTC_HOURS);

@@ -83,7 +86,7 @@ static inline unsigned int get_rtc_time(
 	real_year = CMOS_READ(RTC_DEC_YEAR);
 #endif
 	ctrl = CMOS_READ(RTC_CONTROL);
-	spin_unlock_irq(&rtc_lock);
+	spin_unlock_irqrestore(&rtc_lock, flags);
 
 	if (!(ctrl & RTC_DM_BINARY) || RTC_ALWAYS_BCD)
 	{

_


but that code really needs help.

Bernhard, I believe the checklist items in Documentation/SubmitChecklist
would have prevented this at the source.


ObProcessObservation: afacit the offending commit went mailing list ->
git-x86 -> mainline in about three days flat, a week after the merge
window had opened.

On Mon, 2008-02-04 at 05:04 -0800, Andrew Morton wrote:

After disabling both CONFIG_DEBUG_LOCKING_API_SELFTESTS and netconsole
(using current mainline) I get a login prompt, and also...

[    7.819146] WARNING: at kernel/lockdep.c:2033 trace_hardirqs_on+0x9b/0x10d()

That warning in lockdep.c should have a comment explaining to readers under
which circumstances it will trigger, and what they did wrong.  In fact if
I've interpreted it correctly I don't see why it's a DEBUG_LOCKS_WARN_ON
thing at all?  It should be a first-class lockdep warning?

Agreed, I'll make lockdep print a nice error.

* Andrew Morton [off-list ref] [2008-02-04 14:04]:

but that code really needs help.

Using spin_lock_irqsave() is what rtc_get_rtc_time() does which was
used before I changed to get_rtc_time() does. So it should be ok. I
missed that difference. However, I agree with you the whole RTC
"emulation" per HPET is a bit unclean. However, I have too little
experience in this code area to come up with a proper redesign. I just
ported it from the old RTC to the new RTC module interface.

Bernhard, I believe the checklist items in Documentation/SubmitChecklist
would have prevented this at the source.

Yes. I must admit that I didn't know that document. I used
checkpatch.pl, but that's of course only for coding style. I'll try to
follow the points in SubmitChecklist in future.



        Bernhard

On Mon, 4 Feb 2008 04:43:04 -0800 Andrew Morton [off-list ref] wrote:

On Sun, 3 Feb 2008 15:07:44 -0800 Andrew Morton [off-list ref] wrote:

quoted

On Sun, 3 Feb 2008 15:02:46 -0800 Andrew Morton [off-list ref] wrote:

quoted

With current mainline I'm getting intermittent hangs here:

	http://userweb.kernel.org/~akpm/p2033590.jpg

with this config:

	http://userweb.kernel.org/~akpm/config-sony.txt

on the Vaio.  Sometimes it boots (then hits another different hang),
sometimes it gets stuck there.

CONFIG_DEBUG_LOCKING_API_SELFTESTS=n fixed that up.

quoted

The second hang is in kobject_uevent_init().  All that function does is call
netlink_kernel_create().

And I've fully bisected this hang twice and both times came up with

commit 33f807ba0d9259e7c75c7a2ce8bd2787e5b540c7
Author: Stephen Hemminger [off-list ref]
Date:   Mon Nov 19 19:24:52 2007 -0800

    [NETPOLL]: Kill NETPOLL_RX_DROP, set but never tested.

which is stupid because that patch doesn't do anything.

However I am using netconsole-over-e100 and the hang does go away when I
disable netconsole on the kernel boot command line.

I'd say it's some timing thing in netpoll/netconsole/napi/etc.

I expect the locking API self-tests are innocent - the netconsole lockup
happened to strike during the locking API tests and fooled me.  When I
disabled those tests, the netconsole lockup struck later on.  

On Mon, 4 Feb 2008 04:43:04 -0800 Andrew Morton [off-list ref] wrote:

On Sun, 3 Feb 2008 15:07:44 -0800 Andrew Morton [off-list ref] wrote:

quoted

On Sun, 3 Feb 2008 15:02:46 -0800 Andrew Morton [off-list ref] wrote:

quoted

With current mainline I'm getting intermittent hangs here:

	http://userweb.kernel.org/~akpm/p2033590.jpg

with this config:

	http://userweb.kernel.org/~akpm/config-sony.txt

on the Vaio.  Sometimes it boots (then hits another different hang),
sometimes it gets stuck there.

CONFIG_DEBUG_LOCKING_API_SELFTESTS=n fixed that up.

quoted

The second hang is in kobject_uevent_init().  All that function does is call
netlink_kernel_create().

And I've fully bisected this hang twice and both times came up with

commit 33f807ba0d9259e7c75c7a2ce8bd2787e5b540c7
Author: Stephen Hemminger [off-list ref]
Date:   Mon Nov 19 19:24:52 2007 -0800

    [NETPOLL]: Kill NETPOLL_RX_DROP, set but never tested.

which is stupid because that patch doesn't do anything.

However I am using netconsole-over-e100 and the hang does go away when I
disable netconsole on the kernel boot command line.

I'd say it's some timing thing in netpoll/netconsole/napi/etc.

I'm seeing this netconsole hang on a second machine now.  Current
mainline.  It also has e100.  This one is SMP ancient PIII.

Config: http://userweb.kernel.org/~akpm/config-vmm.txt

On Wed, 6 Feb 2008 00:34:12 -0800 Andrew Morton [off-list ref] wrote:

On Mon, 4 Feb 2008 04:43:04 -0800 Andrew Morton [off-list ref] wrote:

quoted

On Sun, 3 Feb 2008 15:07:44 -0800 Andrew Morton [off-list ref] wrote:

quoted

On Sun, 3 Feb 2008 15:02:46 -0800 Andrew Morton [off-list ref] wrote:

quoted

With current mainline I'm getting intermittent hangs here:

	http://userweb.kernel.org/~akpm/p2033590.jpg

with this config:

	http://userweb.kernel.org/~akpm/config-sony.txt

on the Vaio.  Sometimes it boots (then hits another different hang),
sometimes it gets stuck there.

CONFIG_DEBUG_LOCKING_API_SELFTESTS=n fixed that up.

quoted

The second hang is in kobject_uevent_init().  All that function does is call
netlink_kernel_create().

And I've fully bisected this hang twice and both times came up with

commit 33f807ba0d9259e7c75c7a2ce8bd2787e5b540c7
Author: Stephen Hemminger [off-list ref]
Date:   Mon Nov 19 19:24:52 2007 -0800

    [NETPOLL]: Kill NETPOLL_RX_DROP, set but never tested.

which is stupid because that patch doesn't do anything.

However I am using netconsole-over-e100 and the hang does go away when I
disable netconsole on the kernel boot command line.

I'd say it's some timing thing in netpoll/netconsole/napi/etc.

I'm seeing this netconsole hang on a second machine now.  Current
mainline.  It also has e100.  This one is SMP ancient PIII.

Config: http://userweb.kernel.org/~akpm/config-vmm.txt

I can reproduce this on a third machine: the t61p laptop: dual x86_64 with
e1000.

It seems to need quite a lot of printk activity to make it happen.  Turning
on initcall_debug is a suitable way of triggering it.

On Wed, 6 Feb 2008 01:16:43 -0800 Andrew Morton [off-list ref] wrote:

On Wed, 6 Feb 2008 00:34:12 -0800 Andrew Morton [off-list ref] wrote:

quoted

On Mon, 4 Feb 2008 04:43:04 -0800 Andrew Morton [off-list ref] wrote:

quoted

On Sun, 3 Feb 2008 15:07:44 -0800 Andrew Morton [off-list ref] wrote:

quoted

On Sun, 3 Feb 2008 15:02:46 -0800 Andrew Morton [off-list ref] wrote:

quoted

With current mainline I'm getting intermittent hangs here:

	http://userweb.kernel.org/~akpm/p2033590.jpg

with this config:

	http://userweb.kernel.org/~akpm/config-sony.txt

on the Vaio.  Sometimes it boots (then hits another different hang),
sometimes it gets stuck there.

CONFIG_DEBUG_LOCKING_API_SELFTESTS=n fixed that up.

quoted

The second hang is in kobject_uevent_init().  All that function does is call
netlink_kernel_create().

And I've fully bisected this hang twice and both times came up with

commit 33f807ba0d9259e7c75c7a2ce8bd2787e5b540c7
Author: Stephen Hemminger [off-list ref]
Date:   Mon Nov 19 19:24:52 2007 -0800

    [NETPOLL]: Kill NETPOLL_RX_DROP, set but never tested.

which is stupid because that patch doesn't do anything.

However I am using netconsole-over-e100 and the hang does go away when I
disable netconsole on the kernel boot command line.

I'd say it's some timing thing in netpoll/netconsole/napi/etc.

I'm seeing this netconsole hang on a second machine now.  Current
mainline.  It also has e100.  This one is SMP ancient PIII.

Config: http://userweb.kernel.org/~akpm/config-vmm.txt

I can reproduce this on a third machine: the t61p laptop: dual x86_64 with
e1000.

It seems to need quite a lot of printk activity to make it happen.  Turning
on initcall_debug is a suitable way of triggering it.

This netconsole regression is still present in current mainline.  Rafael,
can you please add it to the list?

It's strange that I can hit it on three separate machines with e100 and e1000
yet nobody else has reported it (afaik).  Is nobody using netconsole?

* Andrew Morton [off-list ref] wrote:

This netconsole regression is still present in current mainline.  
Rafael, can you please add it to the list?

It's strange that I can hit it on three separate machines with e100 
and e1000 yet nobody else has reported it (afaik).  Is nobody using 
netconsole?

i'd suggest the patch below, to mark it broken.

	Ingo

---
 drivers/net/Kconfig |    2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

Index: linux/drivers/net/Kconfig
===================================================================

--- linux.orig/drivers/net/Kconfig
+++ linux/drivers/net/Kconfig

@@ -3109,7 +3109,7 @@ config NET_FC
 
 config NETCONSOLE
 	tristate "Network console logging support (EXPERIMENTAL)"
-	depends on EXPERIMENTAL
+	depends on EXPERIMENTAL && BROKEN
 	---help---
 	If you want to log kernel messages over the network, enable this.
 	See <file:Documentation/networking/netconsole.txt> for details.

On Tue, 4 Mar 2008 09:06:44 +0100 Ingo Molnar wrote:

* Andrew Morton [off-list ref] wrote:

quoted

This netconsole regression is still present in current mainline.  
Rafael, can you please add it to the list?

It's strange that I can hit it on three separate machines with e100 
and e1000 yet nobody else has reported it (afaik).  Is nobody using 
netconsole?

Sorry, I don't read 100% of any mailing list.

I use netconsole on my automated testing systems daily or at
least as often as there is a linus (-git) or -mm release.
It's still working for me, but I'm not using an e100[0] driver,
I'm using a Broadcom.

---
~Randy

From: Ingo Molnar <redacted>
Date: Tue, 4 Mar 2008 09:06:44 +0100

i'd suggest the patch below, to mark it broken.

Why bother when we know what the bug is and can fix it? :-)

commit d9452e9f81e997cbd0c9bface8d2c2a4b064cc3e
Author: David S. Miller [off-list ref]
Date:   Tue Mar 4 12:28:49 2008 -0800

    [NETPOLL]: Revert two bogus cleanups that broke netconsole.
    
    Based upon a report by Andrew Morton and code analysis done
    by Jarek Poplawski.
    
    This reverts 33f807ba0d9259e7c75c7a2ce8bd2787e5b540c7 ("[NETPOLL]:
    Kill NETPOLL_RX_DROP, set but never tested.")  and
    c7b6ea24b43afb5749cb704e143df19d70e23dea ("[NETPOLL]: Don't need
    rx_flags.").
    
    The rx_flags did get tested for zero vs. non-zero and therefore we do
    need those tests and that code which sets NETPOLL_RX_DROP et al.
    
    Signed-off-by: David S. Miller [off-list ref]

diff --git a/include/linux/netpoll.h b/include/linux/netpoll.h
index a0525a1..e3d7959 100644
--- a/include/linux/netpoll.h
+++ b/include/linux/netpoll.h

@@ -25,6 +25,7 @@ struct netpoll {
 
 struct netpoll_info {
 	atomic_t refcnt;
+	int rx_flags;
 	spinlock_t rx_lock;
 	struct netpoll *rx_np; /* netpoll that registered an rx_hook */
 	struct sk_buff_head arp_tx; /* list of arp requests to reply to */

@@ -50,12 +51,12 @@ static inline int netpoll_rx(struct sk_buff *skb)
 	unsigned long flags;
 	int ret = 0;
 
-	if (!npinfo || !npinfo->rx_np)
+	if (!npinfo || (!npinfo->rx_np && !npinfo->rx_flags))
 		return 0;
 
 	spin_lock_irqsave(&npinfo->rx_lock, flags);
-	/* check rx_np again with the lock held */
-	if (npinfo->rx_np && __netpoll_rx(skb))
+	/* check rx_flags again with the lock held */
+	if (npinfo->rx_flags && __netpoll_rx(skb))
 		ret = 1;
 	spin_unlock_irqrestore(&npinfo->rx_lock, flags);
 

diff --git a/net/core/netpoll.c b/net/core/netpoll.c
index 6faa128..4b7e756 100644
--- a/net/core/netpoll.c
+++ b/net/core/netpoll.c

@@ -39,6 +39,8 @@ static struct sk_buff_head skb_pool;
 static atomic_t trapped;
 
 #define USEC_PER_POLL	50
+#define NETPOLL_RX_ENABLED  1
+#define NETPOLL_RX_DROP     2
 
 #define MAX_SKB_SIZE \
 		(MAX_UDP_CHUNK + sizeof(struct udphdr) + \

@@ -126,11 +128,13 @@ static int poll_one_napi(struct netpoll_info *npinfo,
 	if (!test_bit(NAPI_STATE_SCHED, &napi->state))
 		return budget;
 
+	npinfo->rx_flags |= NETPOLL_RX_DROP;
 	atomic_inc(&trapped);
 
 	work = napi->poll(napi, budget);
 
 	atomic_dec(&trapped);
+	npinfo->rx_flags &= ~NETPOLL_RX_DROP;
 
 	return budget - work;
 }

@@ -472,7 +476,7 @@ int __netpoll_rx(struct sk_buff *skb)
 	if (skb->dev->type != ARPHRD_ETHER)
 		goto out;
 
-	/* if receive ARP during middle of NAPI poll, then queue */
+	/* check if netpoll clients need ARP */
 	if (skb->protocol == htons(ETH_P_ARP) &&
 	    atomic_read(&trapped)) {
 		skb_queue_tail(&npi->arp_tx, skb);

@@ -534,9 +538,6 @@ int __netpoll_rx(struct sk_buff *skb)
 	return 1;
 
 out:
-	/* If packet received while already in poll then just
-	 * silently drop.
-	 */
 	if (atomic_read(&trapped)) {
 		kfree_skb(skb);
 		return 1;

@@ -675,6 +676,7 @@ int netpoll_setup(struct netpoll *np)
 			goto release;
 		}
 
+		npinfo->rx_flags = 0;
 		npinfo->rx_np = NULL;
 
 		spin_lock_init(&npinfo->rx_lock);

@@ -756,6 +758,7 @@ int netpoll_setup(struct netpoll *np)
 
 	if (np->rx_hook) {
 		spin_lock_irqsave(&npinfo->rx_lock, flags);
+		npinfo->rx_flags |= NETPOLL_RX_ENABLED;
 		npinfo->rx_np = np;
 		spin_unlock_irqrestore(&npinfo->rx_lock, flags);
 	}

@@ -797,6 +800,7 @@ void netpoll_cleanup(struct netpoll *np)
 			if (npinfo->rx_np == np) {
 				spin_lock_irqsave(&npinfo->rx_lock, flags);
 				npinfo->rx_np = NULL;
+				npinfo->rx_flags &= ~NETPOLL_RX_ENABLED;
 				spin_unlock_irqrestore(&npinfo->rx_lock, flags);
 			}
 

* David Miller [off-list ref] wrote:

From: Ingo Molnar <redacted>
Date: Tue, 4 Mar 2008 09:06:44 +0100

quoted

i'd suggest the patch below, to mark it broken.

Why bother when we know what the bug is and can fix it? :-)

music to my ears :-)

	Ingo

On 04-03-2008 06:05, Andrew Morton wrote:
...

quoted

quoted

quoted

And I've fully bisected this hang twice and both times came up with

commit 33f807ba0d9259e7c75c7a2ce8bd2787e5b540c7
Author: Stephen Hemminger [off-list ref]
Date:   Mon Nov 19 19:24:52 2007 -0800

    [NETPOLL]: Kill NETPOLL_RX_DROP, set but never tested.

which is stupid because that patch doesn't do anything.

...or maybe apparently doesn't do anything?

@@ -128,13 +127,11 @@ static int poll_one_napi(struct netpoll_info *npinfo,
        if (!test_bit(NAPI_STATE_SCHED, &napi->state))
                return budget;
 
-       npinfo->rx_flags |= NETPOLL_RX_DROP;

But in a next patch we can see:

@@ -51,12 +50,12 @@ static inline int netpoll_rx(struct sk_buff *skb)
        unsigned long flags;
        int ret = 0;
 
-       if (!npinfo || (!npinfo->rx_np && !npinfo->rx_flags))
+       if (!npinfo || !npinfo->rx_np)

So, it seems rx_flags could have been tested here for NETPOLL_RX_DROP
yet?

Regards,
Jarek P.

On Tue, 4 Mar 2008 08:40:24 +0000 Jarek Poplawski [off-list ref] wrote:

Oh damn.  I bisected this three times and the second two times both landed on
this:


commit 33f807ba0d9259e7c75c7a2ce8bd2787e5b540c7
Author: Stephen Hemminger [off-list ref]
Date:   Mon Nov 19 19:24:52 2007 -0800

    [NETPOLL]: Kill NETPOLL_RX_DROP, set but never tested.
    
    Signed-off-by: Stephen Hemminger [off-list ref]
    Signed-off-by: David S. Miller [off-list ref]

diff --git a/net/core/netpoll.c b/net/core/netpoll.c
index cf6acd3..9e3aea0 100644
--- a/net/core/netpoll.c
+++ b/net/core/netpoll.c

@@ -40,7 +40,6 @@ static atomic_t trapped;
 
 #define USEC_PER_POLL	50
 #define NETPOLL_RX_ENABLED  1
-#define NETPOLL_RX_DROP     2
 
 #define MAX_SKB_SIZE \
 		(MAX_UDP_CHUNK + sizeof(struct udphdr) + \

@@ -128,13 +127,11 @@ static int poll_one_napi(struct netpoll_info *npinfo,
 	if (!test_bit(NAPI_STATE_SCHED, &napi->state))
 		return budget;
 
-	npinfo->rx_flags |= NETPOLL_RX_DROP;
 	atomic_inc(&trapped);
 
 	work = napi->poll(napi, budget);
 
 	atomic_dec(&trapped);
-	npinfo->rx_flags &= ~NETPOLL_RX_DROP;
 
 	return budget - work;
 }

@@ -475,7 +472,7 @@ int __netpoll_rx(struct sk_buff *skb)
 	if (skb->dev->type != ARPHRD_ETHER)
 		goto out;
 
-	/* check if netpoll clients need ARP */
+	/* if receive ARP during middle of NAPI poll, then queue */
 	if (skb->protocol == htons(ETH_P_ARP) &&
 	    atomic_read(&trapped)) {
 		skb_queue_tail(&npi->arp_tx, skb);

@@ -537,6 +534,9 @@ int __netpoll_rx(struct sk_buff *skb)
 	return 1;
 
 out:
+	/* If packet received while already in poll then just
+	 * silently drop.
+	 */
 	if (atomic_read(&trapped)) {
 		kfree_skb(skb);
 		return 1;

and I stupidly assumed that it couldn't be this commit because it was a
no-op.  I didn't think to look for an _impicit_ test of NETPOLL_RX_DROP
such as the one above.  That's pretty poor style IMO :(


That bisecting took me several hours and at the time I hoped that it would
receive a more-than-zero response.  btw.

On Tue, 4 Mar 2008 01:10:50 -0800
Andrew Morton [off-list ref] wrote:

Mia culpa, individual tests of the netconsole when I did the patch worked.
But obviously didn't stress it enough or trigger that drop code.

Plus, I didn't believe the bisect.

From: Stephen Hemminger <redacted>
Date: Tue, 4 Mar 2008 07:51:37 -0800

On Tue, 4 Mar 2008 01:10:50 -0800
Andrew Morton [off-list ref] wrote:

quoted

That bisecting took me several hours and at the time I hoped that it would
receive a more-than-zero response.  btw.

Mia culpa, individual tests of the netconsole when I did the patch worked.
But obviously didn't stress it enough or trigger that drop code.

Plus, I didn't believe the bisect.

At least Jarek figured it out in the end :-)  I'll revert
these two changesets like so:

commit d9452e9f81e997cbd0c9bface8d2c2a4b064cc3e
Author: David S. Miller [off-list ref]
Date:   Tue Mar 4 12:28:49 2008 -0800

    [NETPOLL]: Revert two bogus cleanups that broke netconsole.
    
    Based upon a report by Andrew Morton and code analysis done
    by Jarek Poplawski.
    
    This reverts 33f807ba0d9259e7c75c7a2ce8bd2787e5b540c7 ("[NETPOLL]:
    Kill NETPOLL_RX_DROP, set but never tested.")  and
    c7b6ea24b43afb5749cb704e143df19d70e23dea ("[NETPOLL]: Don't need
    rx_flags.").
    
    The rx_flags did get tested for zero vs. non-zero and therefore we do
    need those tests and that code which sets NETPOLL_RX_DROP et al.
    
    Signed-off-by: David S. Miller [off-list ref]

diff --git a/include/linux/netpoll.h b/include/linux/netpoll.h
index a0525a1..e3d7959 100644
--- a/include/linux/netpoll.h
+++ b/include/linux/netpoll.h

@@ -25,6 +25,7 @@ struct netpoll {
 
 struct netpoll_info {
 	atomic_t refcnt;
+	int rx_flags;
 	spinlock_t rx_lock;
 	struct netpoll *rx_np; /* netpoll that registered an rx_hook */
 	struct sk_buff_head arp_tx; /* list of arp requests to reply to */

@@ -50,12 +51,12 @@ static inline int netpoll_rx(struct sk_buff *skb)
 	unsigned long flags;
 	int ret = 0;
 
-	if (!npinfo || !npinfo->rx_np)
+	if (!npinfo || (!npinfo->rx_np && !npinfo->rx_flags))
 		return 0;
 
 	spin_lock_irqsave(&npinfo->rx_lock, flags);
-	/* check rx_np again with the lock held */
-	if (npinfo->rx_np && __netpoll_rx(skb))
+	/* check rx_flags again with the lock held */
+	if (npinfo->rx_flags && __netpoll_rx(skb))
 		ret = 1;
 	spin_unlock_irqrestore(&npinfo->rx_lock, flags);
 

diff --git a/net/core/netpoll.c b/net/core/netpoll.c
index 6faa128..4b7e756 100644
--- a/net/core/netpoll.c
+++ b/net/core/netpoll.c

@@ -39,6 +39,8 @@ static struct sk_buff_head skb_pool;
 static atomic_t trapped;
 
 #define USEC_PER_POLL	50
+#define NETPOLL_RX_ENABLED  1
+#define NETPOLL_RX_DROP     2
 
 #define MAX_SKB_SIZE \
 		(MAX_UDP_CHUNK + sizeof(struct udphdr) + \

@@ -126,11 +128,13 @@ static int poll_one_napi(struct netpoll_info *npinfo,
 	if (!test_bit(NAPI_STATE_SCHED, &napi->state))
 		return budget;
 
+	npinfo->rx_flags |= NETPOLL_RX_DROP;
 	atomic_inc(&trapped);
 
 	work = napi->poll(napi, budget);
 
 	atomic_dec(&trapped);
+	npinfo->rx_flags &= ~NETPOLL_RX_DROP;
 
 	return budget - work;
 }

@@ -472,7 +476,7 @@ int __netpoll_rx(struct sk_buff *skb)
 	if (skb->dev->type != ARPHRD_ETHER)
 		goto out;
 
-	/* if receive ARP during middle of NAPI poll, then queue */
+	/* check if netpoll clients need ARP */
 	if (skb->protocol == htons(ETH_P_ARP) &&
 	    atomic_read(&trapped)) {
 		skb_queue_tail(&npi->arp_tx, skb);

@@ -534,9 +538,6 @@ int __netpoll_rx(struct sk_buff *skb)
 	return 1;
 
 out:
-	/* If packet received while already in poll then just
-	 * silently drop.
-	 */
 	if (atomic_read(&trapped)) {
 		kfree_skb(skb);
 		return 1;

@@ -675,6 +676,7 @@ int netpoll_setup(struct netpoll *np)
 			goto release;
 		}
 
+		npinfo->rx_flags = 0;
 		npinfo->rx_np = NULL;
 
 		spin_lock_init(&npinfo->rx_lock);

@@ -756,6 +758,7 @@ int netpoll_setup(struct netpoll *np)
 
 	if (np->rx_hook) {
 		spin_lock_irqsave(&npinfo->rx_lock, flags);
+		npinfo->rx_flags |= NETPOLL_RX_ENABLED;
 		npinfo->rx_np = np;
 		spin_unlock_irqrestore(&npinfo->rx_lock, flags);
 	}

@@ -797,6 +800,7 @@ void netpoll_cleanup(struct netpoll *np)
 			if (npinfo->rx_np == np) {
 				spin_lock_irqsave(&npinfo->rx_lock, flags);
 				npinfo->rx_np = NULL;
+				npinfo->rx_flags &= ~NETPOLL_RX_ENABLED;
 				spin_unlock_irqrestore(&npinfo->rx_lock, flags);
 			}
 

On Tue, 04 Mar 2008 12:30:00 -0800 (PST) David Miller [off-list ref] wrote:

    [NETPOLL]: Revert two bogus cleanups that broke netconsole.

Seems OK now, thanks.

From: Andrew Morton <akpm@linux-foundation.org>
Date: Wed, 5 Mar 2008 00:23:38 -0800

On Tue, 04 Mar 2008 12:30:00 -0800 (PST) David Miller [off-list ref] wrote:

quoted

    [NETPOLL]: Revert two bogus cleanups that broke netconsole.

Seems OK now, thanks.

Great, thanks for testing.

On Mon, Mar 03, 2008 at 09:05:40PM -0800, Andrew Morton wrote:

On Wed, 6 Feb 2008 01:16:43 -0800 Andrew Morton [off-list ref] wrote:

quoted

On Wed, 6 Feb 2008 00:34:12 -0800 Andrew Morton [off-list ref] wrote:

quoted

On Mon, 4 Feb 2008 04:43:04 -0800 Andrew Morton [off-list ref] wrote:

quoted

On Sun, 3 Feb 2008 15:07:44 -0800 Andrew Morton [off-list ref] wrote:

quoted

On Sun, 3 Feb 2008 15:02:46 -0800 Andrew Morton [off-list ref] wrote:

quoted

With current mainline I'm getting intermittent hangs here:

	http://userweb.kernel.org/~akpm/p2033590.jpg

with this config:

	http://userweb.kernel.org/~akpm/config-sony.txt

on the Vaio.  Sometimes it boots (then hits another different hang),
sometimes it gets stuck there.

CONFIG_DEBUG_LOCKING_API_SELFTESTS=n fixed that up.

quoted

The second hang is in kobject_uevent_init().  All that function does is call
netlink_kernel_create().

And I've fully bisected this hang twice and both times came up with

commit 33f807ba0d9259e7c75c7a2ce8bd2787e5b540c7
Author: Stephen Hemminger [off-list ref]
Date:   Mon Nov 19 19:24:52 2007 -0800

    [NETPOLL]: Kill NETPOLL_RX_DROP, set but never tested.

which is stupid because that patch doesn't do anything.

However I am using netconsole-over-e100 and the hang does go away when I
disable netconsole on the kernel boot command line.

I'd say it's some timing thing in netpoll/netconsole/napi/etc.

I'm seeing this netconsole hang on a second machine now.  Current
mainline.  It also has e100.  This one is SMP ancient PIII.

Config: http://userweb.kernel.org/~akpm/config-vmm.txt

I can reproduce this on a third machine: the t61p laptop: dual x86_64 with
e1000.

It seems to need quite a lot of printk activity to make it happen.  Turning
on initcall_debug is a suitable way of triggering it.

I've seen it once too. But I thought it had something to do with this:
http://lkml.org/lkml/2008/3/2/91

This netconsole regression is still present in current mainline.  Rafael,
can you please add it to the list?

It's strange that I can hit it on three separate machines with e100 and e1000
yet nobody else has reported it (afaik).  Is nobody using netconsole?

ps: I don't have any e100* card