Re: Regression in 3.8-rc1: "BUG: sleeping function called from invalid context"

Re: Regression in 3.8-rc1: "BUG: sleeping function called from invalid context"

[Borislav Petkov]

Top-posting so that the rest can remain untouched.

Right, so AFAICT, something is holding rtnl_mutex (probably some
rtnetlink traffic) and device_rename() is doing kstrdup with
GFP_KERNEL which, among others, has __GFP_WAIT and *that* triggers the
might_sleep_if() check in slab_pre_alloc_hook():

static inline int slab_pre_alloc_hook(struct kmem_cache *s, gfp_t flags)
{
        flags &= gfp_allowed_mask;
        lockdep_trace_alloc(flags);
        might_sleep_if(flags & __GFP_WAIT);		<--- HERE

Adding Christoph and Pekka although the slub.c might_sleep stuff is from
2010. Still, they might have a better idea.

Oh well, let's add netdev while we're at it. :-)

HTH.

On Sat, Dec 22, 2012 at 11:11:53AM -0600, Larry Finger wrote:
> With kernel 3.8-rc1, I get 2 "BUG: sleeping function called from
> invalid context" reports. These have been present got some time in
> the 3.7-git versions and I have tried twice to bisect the problem.
> Both times, I ended up at a merge commit. The most recent found
> commit a11da7d as the bad one, and commit d7460f4 as the last good
> one. I have not had time to make a third try.
> 
> My system is x86_64 running on an HP laptop with a dual-core AMD
> CPU. My configuration file is attached.
> 
> The logged details are as follows:
> 
> [   31.715016] BUG: sleeping function called from invalid context at mm/slub.c:925
> [   31.715022] in_atomic(): 1, irqs_disabled(): 0, pid: 2129, name: udevd
> [   31.715025] 2 locks held by udevd/2129:
> [   31.715028]  #0:  (rtnl_mutex){+.+.+.}, at: [<ffffffff81386382>]
> rtnl_lock+0x12/0x20
> [   31.715041]  #1:  (devnet_rename_seq){+.+.+.}, at:
> [<ffffffff81376033>] dev_change_name+0x43/0x260
> [   31.715053] Pid: 2129, comm: udevd Not tainted 3.8.0-rc1 #56
> [   31.715056] Call Trace:
> [   31.715063]  [<ffffffff81076ca2>] __might_sleep+0x152/0x250
> [   31.715068]  [<ffffffff8114a353>] __kmalloc_track_caller+0x103/0x280
> [   31.715073]  [<ffffffff812d595d>] ? device_rename+0x4d/0xf0
> [   31.715078]  [<ffffffff8111d675>] kstrdup+0x35/0x70
> [   31.715082]  [<ffffffff812d595d>] device_rename+0x4d/0xf0
> [   31.715086]  [<ffffffff813760ca>] dev_change_name+0xda/0x260
> [   31.715091]  [<ffffffff81377f51>] dev_ifsioc+0x241/0x3a0
> [   31.715095]  [<ffffffff81378410>] dev_ioctl+0x360/0x830
> [   31.715101]  [<ffffffff810a54cd>] ? trace_hardirqs_on+0xd/0x10
> [   31.715106]  [<ffffffff8135b711>] sock_do_ioctl.constprop.41+0x41/0x50
> [   31.715109]  [<ffffffff8135b9c6>] sock_ioctl+0x66/0x2b0
> [   31.715115]  [<ffffffff811637b7>] do_vfs_ioctl+0x97/0x580
> [   31.715119]  [<ffffffff8116f27a>] ? fget_light+0x3da/0x4d0
> [   31.715124]  [<ffffffff81422a55>] ? sysret_check+0x22/0x5d
> [   31.715128]  [<ffffffff81163ceb>] sys_ioctl+0x4b/0x90
> [   31.715133]  [<ffffffff8121a69e>] ? trace_hardirqs_on_thunk+0x3a/0x3f
> [   31.715136]  [<ffffffff81422a29>] system_call_fastpath+0x16/0x1b
> [   31.715764] BUG: scheduling while atomic: udevd/2129/0x00000002
> [   31.715768] 2 locks held by udevd/2129:
> [   31.715769]  #0:  (rtnl_mutex){+.+.+.}, at: [<ffffffff81386382>]
> rtnl_lock+0x12/0x20
> [   31.715779]  #1:  (devnet_rename_seq){+.+.+.}, at:
> [<ffffffff81376033>] dev_change_name+0x43/0x260
> [   31.715787] Modules linked in: b43 arc4 rtl8723ae rtlwifi
> mac80211 snd_hda_codec_conexant snd_hda_intel snd_hda_codec cfg80211
> powernow_k8 kvm_amd snd_pcm_oss kvm snd_pcm snd_seq bcma rng_core
> ssb snd_timer mmc_core snd_seq_device pcmcia rfkill snd sr_mod cdrom
> soundcore ehci_pci battery pcmcia_core sg k8temp ac i2c_nforce2
> hwmon forcedeth video snd_page_alloc serio_raw i2c_core joydev wmi
> button ipv6 autofs4 ext4 mbcache jbd2 crc16 ohci_hcd ehci_hcd
> usbcore usb_common thermal processor scsi_dh_rdac scsi_dh_alua
> scsi_dh_emc scsi_dh_hp_sw scsi_dh ata_generic pata_amd
> [   31.715867] Pid: 2129, comm: udevd Not tainted 3.8.0-rc1 #56
> [   31.715868] Call Trace:
> [   31.715874]  [<ffffffff8141987c>] __schedule_bug+0x62/0x70
> [   31.715878]  [<ffffffff81420160>] __schedule+0x730/0xa30
> [   31.715883]  [<ffffffff810a3982>] ? __lock_acquire+0x12d2/0x1c50
> [   31.715888]  [<ffffffff81420744>] schedule+0x24/0x70
> [   31.715893]  [<ffffffff8141dc5c>] schedule_timeout+0x18c/0x2f0
> [   31.715897]  [<ffffffff810a52ac>] ? mark_held_locks+0x8c/0x110
> [   31.715902]  [<ffffffff81421b9b>] ? _raw_spin_unlock_irq+0x2b/0x50
> [   31.715906]  [<ffffffff810a5435>] ? trace_hardirqs_on_caller+0x105/0x190
> [   31.715911]  [<ffffffff810a54cd>] ? trace_hardirqs_on+0xd/0x10
> [   31.715915]  [<ffffffff814205d5>] wait_for_common+0xe5/0x180
> [   31.715919]  [<ffffffff8107d010>] ? try_to_wake_up+0x2d0/0x2d0
> [   31.715924]  [<ffffffff81420718>] wait_for_completion+0x18/0x20
> [   31.715929]  [<ffffffff8105f48c>] call_usermodehelper_exec+0x19c/0x1d0
> [   31.715935]  [<ffffffff8105f592>] call_usermodehelper_fns+0xd2/0x100
> [   31.715941]  [<ffffffff8121211d>] kobject_uevent_env+0x47d/0x4b0
> [   31.715946]  [<ffffffff812110df>] kobject_rename+0x12f/0x140
> [   31.715951]  [<ffffffff812d59db>] device_rename+0xcb/0xf0
> [   31.715955]  [<ffffffff813760ca>] dev_change_name+0xda/0x260
> [   31.715960]  [<ffffffff81377f51>] dev_ifsioc+0x241/0x3a0
> [   31.715965]  [<ffffffff81378410>] dev_ioctl+0x360/0x830
> [   31.715969]  [<ffffffff810a54cd>] ? trace_hardirqs_on+0xd/0x10
> [   31.715974]  [<ffffffff8135b711>] sock_do_ioctl.constprop.41+0x41/0x50
> [   31.715978]  [<ffffffff8135b9c6>] sock_ioctl+0x66/0x2b0
> [   31.715982]  [<ffffffff811637b7>] do_vfs_ioctl+0x97/0x580
> [   31.715987]  [<ffffffff8116f27a>] ? fget_light+0x3da/0x4d0
> [   31.715991]  [<ffffffff81422a55>] ? sysret_check+0x22/0x5d
> [   31.716092]  [<ffffffff81163ceb>] sys_ioctl+0x4b/0x90
> [   31.716097]  [<ffffffff8121a69e>] ? trace_hardirqs_on_thunk+0x3a/0x3f
> [   31.716102]  [<ffffffff81422a29>] system_call_fastpath+0x16/0x1b



-- 
Regards/Gruss,
    Boris.

Sent from a fat crate under my desk. Formatting is fine.
--

Re: Regression in 3.8-rc1: "BUG: sleeping function called from invalid context"

[Eric Dumazet]

On Sat, 2012-12-22 at 19:02 +0100, Borislav Petkov wrote:
> Top-posting so that the rest can remain untouched.
> 
> Right, so AFAICT, something is holding rtnl_mutex (probably some
> rtnetlink traffic) and device_rename() is doing kstrdup with
> GFP_KERNEL which, among others, has __GFP_WAIT and *that* triggers the
> might_sleep_if() check in slab_pre_alloc_hook():
> 
> static inline int slab_pre_alloc_hook(struct kmem_cache *s, gfp_t flags)
> {
>         flags &= gfp_allowed_mask;
>         lockdep_trace_alloc(flags);
>         might_sleep_if(flags & __GFP_WAIT);		<--- HERE
> 
> Adding Christoph and Pekka although the slub.c might_sleep stuff is from
> 2010. Still, they might have a better idea.
> 
> Oh well, let's add netdev while we're at it. :-)

RTNL is a mutex, its perfectly valid to use GFP_KERNEL while holding a
mutex.

As replied before your mail, fix for the problem is already in David
tree.

http://git.kernel.org/?p=linux/kernel/git/davem/net.git;a=commitdiff;h=30e6c9fa93cf3dbc7cc6df1d748ad25e4264545a


Bug was added in commit c91f6df2db4972d3cc983e6988b9abf1ad02f5f9 :

http://git.kernel.org/?p=linux/kernel/git/davem/net.git;a=commit;h=c91f6df2db4972d3cc983e6988b9abf1ad02f5f9


Thanks

Re: Regression in 3.8-rc1: "BUG: sleeping function called from invalid context"

[Borislav Petkov]

On Sat, Dec 22, 2012 at 10:10:28AM -0800, Eric Dumazet wrote:
> RTNL is a mutex, its perfectly valid to use GFP_KERNEL while holding a
> mutex.

Right, sorry. The check fires because we have preemption disabled.

> As replied before your mail, fix for the problem is already in David
> tree.

Yep, saw that after hitting send.

-- 
Regards/Gruss,
    Boris.

Sent from a fat crate under my desk. Formatting is fine.
--

Re: Regression in 3.8-rc1: "BUG: sleeping function called from invalid context"

[Larry Finger]

On 12/22/2012 12:30 PM, Borislav Petkov wrote:
> On Sat, Dec 22, 2012 at 10:10:28AM -0800, Eric Dumazet wrote:
>> RTNL is a mutex, its perfectly valid to use GFP_KERNEL while holding a
>> mutex.
>
> Right, sorry. The check fires because we have preemption disabled.
>
>> As replied before your mail, fix for the problem is already in David
>> tree.
>
> Yep, saw that after hitting send.

Eric and Borislav,

The patch does fix my problem. I expect that it will be in mainline by -rc2.

Thanks,

Larry

Re: Regression in 3.8-rc1: "BUG: sleeping function called from invalid context"

[David Miller]

From: Borislav Petkov <bp@alien8.de>
Date: Sat, 22 Dec 2012 19:02:47 +0100

> Top-posting so that the rest can remain untouched.

This bug is fixed in the 'net' tree already by commit:

>From 30e6c9fa93cf3dbc7cc6df1d748ad25e4264545a Mon Sep 17 00:00:00 2001
From: Eric Dumazet <edumazet@google.com>
Date: Thu, 20 Dec 2012 17:25:08 +0000
Subject: [PATCH 04/10] net: devnet_rename_seq should be a seqcount

Using a seqlock for devnet_rename_seq is not a good idea,
as device_rename() can sleep.

As we hold RTNL, we dont need a protection for writers,
and only need a seqcount so that readers can catch a change done
by a writer.

Bug added in commit c91f6df2db4972d3 (sockopt: Change getsockopt() of
SO_BINDTODEVICE to return an interface name)

Reported-by: Dave Jones <davej@redhat.com>
Signed-off-by: Eric Dumazet <edumazet@google.com>
Cc: Brian Haley <brian.haley@hp.com>
Signed-off-by: David S. Miller <davem@davemloft.net>
---
 include/linux/netdevice.h |  2 +-
 net/core/dev.c            | 18 +++++++++---------
 net/core/sock.c           |  4 ++--
 3 files changed, 12 insertions(+), 12 deletions(-)

diff --git a/include/linux/netdevice.h b/include/linux/netdevice.h
index 02e0f6b..c599e47 100644
--- a/include/linux/netdevice.h
+++ b/include/linux/netdevice.h
@@ -1576,7 +1576,7 @@ extern int call_netdevice_notifiers(unsigned long val, struct net_device *dev);
 
 extern rwlock_t				dev_base_lock;		/* Device list lock */
 
-extern seqlock_t	devnet_rename_seq;	/* Device rename lock */
+extern seqcount_t	devnet_rename_seq;	/* Device rename seq */
 
 
 #define for_each_netdev(net, d)		\
diff --git a/net/core/dev.c b/net/core/dev.c
index d0cbc93..515473e 100644
--- a/net/core/dev.c
+++ b/net/core/dev.c
@@ -203,7 +203,7 @@ static struct list_head offload_base __read_mostly;
 DEFINE_RWLOCK(dev_base_lock);
 EXPORT_SYMBOL(dev_base_lock);
 
-DEFINE_SEQLOCK(devnet_rename_seq);
+seqcount_t devnet_rename_seq;
 
 static inline void dev_base_seq_inc(struct net *net)
 {
@@ -1093,10 +1093,10 @@ int dev_change_name(struct net_device *dev, const char *newname)
 	if (dev->flags & IFF_UP)
 		return -EBUSY;
 
-	write_seqlock(&devnet_rename_seq);
+	write_seqcount_begin(&devnet_rename_seq);
 
 	if (strncmp(newname, dev->name, IFNAMSIZ) == 0) {
-		write_sequnlock(&devnet_rename_seq);
+		write_seqcount_end(&devnet_rename_seq);
 		return 0;
 	}
 
@@ -1104,7 +1104,7 @@ int dev_change_name(struct net_device *dev, const char *newname)
 
 	err = dev_get_valid_name(net, dev, newname);
 	if (err < 0) {
-		write_sequnlock(&devnet_rename_seq);
+		write_seqcount_end(&devnet_rename_seq);
 		return err;
 	}
 
@@ -1112,11 +1112,11 @@ rollback:
 	ret = device_rename(&dev->dev, dev->name);
 	if (ret) {
 		memcpy(dev->name, oldname, IFNAMSIZ);
-		write_sequnlock(&devnet_rename_seq);
+		write_seqcount_end(&devnet_rename_seq);
 		return ret;
 	}
 
-	write_sequnlock(&devnet_rename_seq);
+	write_seqcount_end(&devnet_rename_seq);
 
 	write_lock_bh(&dev_base_lock);
 	hlist_del_rcu(&dev->name_hlist);
@@ -1135,7 +1135,7 @@ rollback:
 		/* err >= 0 after dev_alloc_name() or stores the first errno */
 		if (err >= 0) {
 			err = ret;
-			write_seqlock(&devnet_rename_seq);
+			write_seqcount_begin(&devnet_rename_seq);
 			memcpy(dev->name, oldname, IFNAMSIZ);
 			goto rollback;
 		} else {
@@ -4180,7 +4180,7 @@ static int dev_ifname(struct net *net, struct ifreq __user *arg)
 		return -EFAULT;
 
 retry:
-	seq = read_seqbegin(&devnet_rename_seq);
+	seq = read_seqcount_begin(&devnet_rename_seq);
 	rcu_read_lock();
 	dev = dev_get_by_index_rcu(net, ifr.ifr_ifindex);
 	if (!dev) {
@@ -4190,7 +4190,7 @@ retry:
 
 	strcpy(ifr.ifr_name, dev->name);
 	rcu_read_unlock();
-	if (read_seqretry(&devnet_rename_seq, seq))
+	if (read_seqcount_retry(&devnet_rename_seq, seq))
 		goto retry;
 
 	if (copy_to_user(arg, &ifr, sizeof(struct ifreq)))
diff --git a/net/core/sock.c b/net/core/sock.c
index a692ef4..bc131d4 100644
--- a/net/core/sock.c
+++ b/net/core/sock.c
@@ -583,7 +583,7 @@ static int sock_getbindtodevice(struct sock *sk, char __user *optval,
 		goto out;
 
 retry:
-	seq = read_seqbegin(&devnet_rename_seq);
+	seq = read_seqcount_begin(&devnet_rename_seq);
 	rcu_read_lock();
 	dev = dev_get_by_index_rcu(net, sk->sk_bound_dev_if);
 	ret = -ENODEV;
@@ -594,7 +594,7 @@ retry:
 
 	strcpy(devname, dev->name);
 	rcu_read_unlock();
-	if (read_seqretry(&devnet_rename_seq, seq))
+	if (read_seqcount_retry(&devnet_rename_seq, seq))
 		goto retry;
 
 	len = strlen(devname) + 1;
-- 
1.7.11.7