Re: [LKP] [lkp] [mm] e7c1db75fe: BUG:sleeping_function_called_from_invalid_context_at_mm/page_alloc.c

2016-11-29 Thread Fengguang Wu 

Hi Paul,

Attached is the new dmesg.

On Wed, Nov 30, 2016 at 05:39:50AM +0800, Ye Xiaolong wrote:

On 11/29, Paul E. McKenney wrote:

On Tue, Nov 29, 2016 at 05:21:19PM +, Sudeep Holla wrote:

On Sun, Nov 27, 2016 at 6:16 PM, kernel test robot
 wrote:
>
> FYI, we noticed the following commit:
>
> commit e7c1db75fed821a961ce1ca2b602b08e75de0cd8 ("mm: Prevent 
__alloc_pages_nodemask() RCU CPU stall warnings")
> https://git.kernel.org/pub/scm/linux/kernel/git/paulmck/linux-rcu.git rcu/next
>
> in testcase: boot
>
> on test machine: qemu-system-x86_64 -enable-kvm -cpu Nehalem -smp 2 -m 1G
>
> caused below changes:
>
[...]

> [8.953192] BUG: sleeping function called from invalid context at 
mm/page_alloc.c:3746
> [8.956353] in_atomic(): 1, irqs_disabled(): 1, pid: 0, name: swapper/0

I am observing similar BUG/backtrace even on ARM64 platform.


Does the (untested) patch below help?

Thanx, Paul


Hi, Paul

I applied your patch on top of 2d66ccc "mm:
Prevent__alloc_pages_nodemask() RCU CPU stall warnings"(e7c1db7 turns to
2d66ccc in rcu/next branch now), here is the comparison of 6 times
testing, seems the BUG persists.

b70fa84d2eeef5f6be25633a2b is the commit id of commit "rcu: Allow
boot-time useof cond_resched_rcu_qs()"

testcase/path_params/tbox_group/run: boot/1/vm-vp-1G

2d66cccd73436ac9  b70fa84d2eeef5f6be25633a2b
  --
 6:60%   6:6 
dmesg.BUG:sleeping_function_called_from_invalid_context_at_mm/page_alloc.c


The new dmesg looks like this:

[6.505611] Write protecting the kernel read-only data: 14336k
[6.507798] Freeing unused kernel memory: 544K (880001978000 - 
880001a0)
[6.515634] Freeing unused kernel memory: 240K (880001dc4000 - 
880001e0)
[6.524713] BUG: sleeping function called from invalid context at 
mm/page_alloc.c:3746
[6.527327] in_atomic(): 0, irqs_disabled(): 1, pid: 1, name: init
[6.528891] CPU: 1 PID: 1 Comm: init Not tainted 4.9.0-rc1-00048-gb70fa84 #1
[6.530604] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 
Debian-1.8.2-1 04/01/2014
[6.533255]  c9197b48 81472609 8800296a 
02201200
[6.538069]  c9197b60 810a85a3 8800364bc080 
c9197bf0
[6.542821]  81190dce 8800296a 8800296a 
8800296a
[6.548618] Call Trace:
[6.550675]  [] dump_stack+0x63/0x8a
[6.554180]  [] ___might_sleep+0xd3/0x120
[6.556720]  [] __alloc_pages_nodemask+0x23e/0x300
[6.560427]  [] alloc_pages_current+0x95/0x140
[6.564063]  [] new_slab+0x3c0/0x5a0
[6.566516]  [] ___slab_alloc+0x3a0/0x4b0
[6.570114]  [] ? anon_vma_clone+0x63/0x1c0
[6.572672]  [] ? alloc_set_pte+0x4f2/0x610
[6.576273]  [] ? anon_vma_clone+0x63/0x1c0
[6.578824]  [] __slab_alloc+0x20/0x40
[6.582348]  [] kmem_cache_alloc+0x17f/0x1c0
[6.585971]  [] anon_vma_clone+0x63/0x1c0
[6.588487]  [] ? __split_vma+0x5c/0x1e0
[6.592159]  [] __split_vma+0xc4/0x1e0
[6.594746]  [] split_vma+0x24/0x30
[6.598248]  [] mprotect_fixup+0x21c/0x270
[6.601130]  [] do_mprotect_pkey+0x20c/0x300
[6.602739]  [] SyS_mprotect+0x13/0x20
[6.604328]  [] entry_SYSCALL_64_fastpath+0x1a/0xa9
SELinux:  Could not open policy file <= /etc/selinux/targeted/policy/policy.30: 
 No such file or directory
[6.609407] systemd[1]: RTC configured in localtime, applying delta of 480 
minutes to system time.
[6.637736] random: fast init done
[6.693275] ip_tables: (C) 2000-2006 Netfilter Core Team
...
[7.553423] NFS: Registering the id_resolver key type
[7.555204] Key type id_resolver registered
[7.557629] Key type id_legacy registered
[7.570901] scsi 1:0:0:0: Attached scsi generic sg0 type 5
[7.572947] BUG: sleeping function called from invalid context at 
mm/page_alloc.c:3746
[7.575717] in_atomic(): 1, irqs_disabled(): 0, pid: 251, name: modprobe
[7.577496] CPU: 1 PID: 251 Comm: modprobe Tainted: GW   
4.9.0-rc1-00048-gb70fa84 #1
[7.585286] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 
Debian-1.8.2-1 04/01/2014
[7.593093]  c95e3b78 81472609 88003f33c900 
02000200
[7.597043]  c95e3b90 810a85a3 8800364bc080 
c95e3c20
[7.599790]  81190dce 88003f33c900 88003f33c900 
88003f33c900
[7.608630] Call Trace:
[7.609787]  [] dump_stack+0x63/0x8a
[7.611366]  [] ___might_sleep+0xd3/0x120
[7.614373]  [] __alloc_pages_nodemask+0x23e/0x300
[7.622141]  [] alloc_pages_current+0x95/0x140
[7.623754]  [] __get_free_pages+0xe/0x40
[7.625323]  [] __tlb_remove_page_size+0x53/0x90
[7.627086]  [] unmap_page_range+0x6cb/0x910
[7.628647]  [] ? release_pages+0x2fc/0x390
[7.630242]  [] unmap_single_vma+0x7d/0xe0
[7.631725]  []

Re: [LKP] [lkp] [mm] e7c1db75fe: BUG:sleeping_function_called_from_invalid_context_at_mm/page_alloc.c

2016-11-29 Thread Fengguang Wu 

Hi Paul,

Attached is the new dmesg.

On Wed, Nov 30, 2016 at 05:39:50AM +0800, Ye Xiaolong wrote:

On 11/29, Paul E. McKenney wrote:

On Tue, Nov 29, 2016 at 05:21:19PM +, Sudeep Holla wrote:

On Sun, Nov 27, 2016 at 6:16 PM, kernel test robot
 wrote:
>
> FYI, we noticed the following commit:
>
> commit e7c1db75fed821a961ce1ca2b602b08e75de0cd8 ("mm: Prevent 
__alloc_pages_nodemask() RCU CPU stall warnings")
> https://git.kernel.org/pub/scm/linux/kernel/git/paulmck/linux-rcu.git rcu/next
>
> in testcase: boot
>
> on test machine: qemu-system-x86_64 -enable-kvm -cpu Nehalem -smp 2 -m 1G
>
> caused below changes:
>
[...]

> [8.953192] BUG: sleeping function called from invalid context at 
mm/page_alloc.c:3746
> [8.956353] in_atomic(): 1, irqs_disabled(): 1, pid: 0, name: swapper/0

I am observing similar BUG/backtrace even on ARM64 platform.


Does the (untested) patch below help?

Thanx, Paul


Hi, Paul

I applied your patch on top of 2d66ccc "mm:
Prevent__alloc_pages_nodemask() RCU CPU stall warnings"(e7c1db7 turns to
2d66ccc in rcu/next branch now), here is the comparison of 6 times
testing, seems the BUG persists.

b70fa84d2eeef5f6be25633a2b is the commit id of commit "rcu: Allow
boot-time useof cond_resched_rcu_qs()"

testcase/path_params/tbox_group/run: boot/1/vm-vp-1G

2d66cccd73436ac9  b70fa84d2eeef5f6be25633a2b
  --
 6:60%   6:6 
dmesg.BUG:sleeping_function_called_from_invalid_context_at_mm/page_alloc.c


The new dmesg looks like this:

[6.505611] Write protecting the kernel read-only data: 14336k
[6.507798] Freeing unused kernel memory: 544K (880001978000 - 
880001a0)
[6.515634] Freeing unused kernel memory: 240K (880001dc4000 - 
880001e0)
[6.524713] BUG: sleeping function called from invalid context at 
mm/page_alloc.c:3746
[6.527327] in_atomic(): 0, irqs_disabled(): 1, pid: 1, name: init
[6.528891] CPU: 1 PID: 1 Comm: init Not tainted 4.9.0-rc1-00048-gb70fa84 #1
[6.530604] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 
Debian-1.8.2-1 04/01/2014
[6.533255]  c9197b48 81472609 8800296a 
02201200
[6.538069]  c9197b60 810a85a3 8800364bc080 
c9197bf0
[6.542821]  81190dce 8800296a 8800296a 
8800296a
[6.548618] Call Trace:
[6.550675]  [] dump_stack+0x63/0x8a
[6.554180]  [] ___might_sleep+0xd3/0x120
[6.556720]  [] __alloc_pages_nodemask+0x23e/0x300
[6.560427]  [] alloc_pages_current+0x95/0x140
[6.564063]  [] new_slab+0x3c0/0x5a0
[6.566516]  [] ___slab_alloc+0x3a0/0x4b0
[6.570114]  [] ? anon_vma_clone+0x63/0x1c0
[6.572672]  [] ? alloc_set_pte+0x4f2/0x610
[6.576273]  [] ? anon_vma_clone+0x63/0x1c0
[6.578824]  [] __slab_alloc+0x20/0x40
[6.582348]  [] kmem_cache_alloc+0x17f/0x1c0
[6.585971]  [] anon_vma_clone+0x63/0x1c0
[6.588487]  [] ? __split_vma+0x5c/0x1e0
[6.592159]  [] __split_vma+0xc4/0x1e0
[6.594746]  [] split_vma+0x24/0x30
[6.598248]  [] mprotect_fixup+0x21c/0x270
[6.601130]  [] do_mprotect_pkey+0x20c/0x300
[6.602739]  [] SyS_mprotect+0x13/0x20
[6.604328]  [] entry_SYSCALL_64_fastpath+0x1a/0xa9
SELinux:  Could not open policy file <= /etc/selinux/targeted/policy/policy.30: 
 No such file or directory
[6.609407] systemd[1]: RTC configured in localtime, applying delta of 480 
minutes to system time.
[6.637736] random: fast init done
[6.693275] ip_tables: (C) 2000-2006 Netfilter Core Team
...
[7.553423] NFS: Registering the id_resolver key type
[7.555204] Key type id_resolver registered
[7.557629] Key type id_legacy registered
[7.570901] scsi 1:0:0:0: Attached scsi generic sg0 type 5
[7.572947] BUG: sleeping function called from invalid context at 
mm/page_alloc.c:3746
[7.575717] in_atomic(): 1, irqs_disabled(): 0, pid: 251, name: modprobe
[7.577496] CPU: 1 PID: 251 Comm: modprobe Tainted: GW   
4.9.0-rc1-00048-gb70fa84 #1
[7.585286] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 
Debian-1.8.2-1 04/01/2014
[7.593093]  c95e3b78 81472609 88003f33c900 
02000200
[7.597043]  c95e3b90 810a85a3 8800364bc080 
c95e3c20
[7.599790]  81190dce 88003f33c900 88003f33c900 
88003f33c900
[7.608630] Call Trace:
[7.609787]  [] dump_stack+0x63/0x8a
[7.611366]  [] ___might_sleep+0xd3/0x120
[7.614373]  [] __alloc_pages_nodemask+0x23e/0x300
[7.622141]  [] alloc_pages_current+0x95/0x140
[7.623754]  [] __get_free_pages+0xe/0x40
[7.625323]  [] __tlb_remove_page_size+0x53/0x90
[7.627086]  [] unmap_page_range+0x6cb/0x910
[7.628647]  [] ? release_pages+0x2fc/0x390
[7.630242]  [] unmap_single_vma+0x7d/0xe0
[7.631725]  [] unmap_vmas+0x51/0xa0
[