mm: slub: gpf in deactivate_slab

mm: slub: gpf in deactivate_slab

[Sasha Levin]

Hi all,

While fuzzing with trinity inside a KVM tools guest running latest -next kernel I've stumbled
on the following spew:

[  241.916559] BUG: unable to handle kernel paging request at ffff880029aa5e58
[  241.917961] IP: [<ffffffff812c5fa3>] deactivate_slab+0x103/0x560
[  241.919439] PGD 88f9067 PUD 88fa067 PMD 102fd35067 PTE 8000000029aa5060
[  241.920339] Oops: 0000 [#1] PREEMPT SMP DEBUG_PAGEALLOC
[  241.920339] Dumping ftrace buffer:
[  241.920339]    (ftrace buffer empty)
[  241.920339] Modules linked in:
[  241.920339] CPU: 17 PID: 9910 Comm: trinity-c183 Tainted: G        W    3.14.0-rc6-next-20140311-sasha-00009-g6c028cd-dirty #146
[  241.920339] task: ffff88090eb68000 ti: ffff88090eb70000 task.ti: ffff88090eb70000
[  241.920339] RIP: 0010:[<ffffffff812c5fa3>]  [<ffffffff812c5fa3>] deactivate_slab+0x103/0x560
[  241.920339] RSP: 0018:ffff88090eb71c18  EFLAGS: 00010082
[  241.920339] RAX: 0000000000000418 RBX: ffff880229ae2010 RCX: 0000000180170017
[  241.920339] RDX: 0000000000000000 RSI: ffffffff812c5f52 RDI: ffffffff812c5e29
[  241.920339] RBP: ffff88090eb71d28 R08: ffff880229ae2010 R09: 0000000000000080
[  241.920339] R10: ffff880229ae2ed0 R11: 0000000000000000 R12: ffffea0008a6b800
[  241.920339] R13: ffff88012b4da580 R14: ffff880029aa5a40 R15: ffff880229ae2010
[  241.920339] FS:  00007fb615415700(0000) GS:ffff88022ba00000(0000) knlGS:0000000000000000
[  241.920339] CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
[  241.920339] CR2: ffff880029aa5e58 CR3: 000000090eb4a000 CR4: 00000000000006a0
[  241.920339] DR0: 0000000000005bf2 DR1: 0000000000000000 DR2: 0000000000000000
[  241.920339] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000070602
[  241.920339] Stack:
[  241.920339]  ffffffff856e37ab ffffffff84486272 0000000000000000 000000002b405600
[  241.920339]  ffff88090eb71c58 ffff88090eb70000 0000000000000011 ffff88022ba03fc0
[  241.920339]  ffff88090eb71cb8 000000000000000f ffff88022b405600 ffff880029aa5a40
[  241.920339] Call Trace:
[  241.920339]  [<ffffffff84486272>] ? preempt_count_sub+0xe2/0x120
[  241.920339]  [<ffffffff8130f151>] ? alloc_inode+0x41/0xa0
[  241.954886]  [<ffffffff8130f151>] ? alloc_inode+0x41/0xa0
[  241.954886]  [<ffffffff8130f151>] ? alloc_inode+0x41/0xa0
[  241.954886]  [<ffffffff812c36eb>] ? set_track+0xab/0x100
[  241.954886]  [<ffffffff812c731f>] __slab_alloc+0x42f/0x4d0
[  241.954886]  [<ffffffff81073e6d>] ? sched_clock+0x1d/0x30
[  241.954886]  [<ffffffff8130f151>] ? alloc_inode+0x41/0xa0
[  241.961624]  [<ffffffff812c870f>] kmem_cache_alloc+0x12f/0x2e0
[  241.961624]  [<ffffffff8130f151>] ? alloc_inode+0x41/0xa0
[  241.961624]  [<ffffffff8130f151>] alloc_inode+0x41/0xa0
[  241.961624]  [<ffffffff8130f1cb>] new_inode_pseudo+0x1b/0x70
[  241.961624]  [<ffffffff812f985c>] get_pipe_inode+0x1c/0xf0
[  241.961624]  [<ffffffff812f995c>] create_pipe_files+0x2c/0x170
[  241.961624]  [<ffffffff812f9ae1>] __do_pipe_flags+0x41/0xf0
[  241.961624]  [<ffffffff812f9bbb>] SyS_pipe2+0x2b/0xb0
[  241.961624]  [<ffffffff8448b3b1>] ? tracesys+0x7e/0xe2
[  241.961624]  [<ffffffff8448b410>] tracesys+0xdd/0xe2
[  241.972975] Code: 4d 85 f6 75 8b eb 45 90 4d 85 f6 75 13 49 8b 5c 24 10 45 31 ff 0f 1f 00 eb 32 66 0f 1f 44 00 00 4c 89 b5 48 ff ff ff 49 63 45 20 <49> 8b 0c 06 48 85 c9 74 10 4d 89 f7 49 8b 54 24 10 49 89 ce e9
[  241.972975] RIP  [<ffffffff812c5fa3>] deactivate_slab+0x103/0x560
[  241.972975]  RSP <ffff88090eb71c18>
[  241.972975] CR2: ffff880029aa5e58


Thanks,
Sasha

--
To unsubscribe, send a message with 'unsubscribe linux-mm' in
the body to majordomo@kvack.org.  For more info on Linux MM,
see: http://www.linux-mm.org/ .
Don't email: <a href=mailto:"dont@kvack.org"> email@kvack.org </a>

Re: mm: slub: gpf in deactivate_slab

[Sasha Levin]

On 03/12/2014 12:25 PM, Sasha Levin wrote:
> Hi all,
>
> While fuzzing with trinity inside a KVM tools guest running latest -next kernel I've stumbled
> on the following spew:
>
> [  241.916559] BUG: unable to handle kernel paging request at ffff880029aa5e58
> [  241.917961] IP: [<ffffffff812c5fa3>] deactivate_slab+0x103/0x560
> [  241.919439] PGD 88f9067 PUD 88fa067 PMD 102fd35067 PTE 8000000029aa5060
> [  241.920339] Oops: 0000 [#1] PREEMPT SMP DEBUG_PAGEALLOC
> [  241.920339] Dumping ftrace buffer:
> [  241.920339]    (ftrace buffer empty)
> [  241.920339] Modules linked in:
> [  241.920339] CPU: 17 PID: 9910 Comm: trinity-c183 Tainted: G        W    3.14.0-rc6-next-20140311-sasha-00009-g6c028cd-dirty #146
> [  241.920339] task: ffff88090eb68000 ti: ffff88090eb70000 task.ti: ffff88090eb70000
> [  241.920339] RIP: 0010:[<ffffffff812c5fa3>]  [<ffffffff812c5fa3>] deactivate_slab+0x103/0x560
> [  241.920339] RSP: 0018:ffff88090eb71c18  EFLAGS: 00010082
> [  241.920339] RAX: 0000000000000418 RBX: ffff880229ae2010 RCX: 0000000180170017
> [  241.920339] RDX: 0000000000000000 RSI: ffffffff812c5f52 RDI: ffffffff812c5e29
> [  241.920339] RBP: ffff88090eb71d28 R08: ffff880229ae2010 R09: 0000000000000080
> [  241.920339] R10: ffff880229ae2ed0 R11: 0000000000000000 R12: ffffea0008a6b800
> [  241.920339] R13: ffff88012b4da580 R14: ffff880029aa5a40 R15: ffff880229ae2010
> [  241.920339] FS:  00007fb615415700(0000) GS:ffff88022ba00000(0000) knlGS:0000000000000000
> [  241.920339] CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
> [  241.920339] CR2: ffff880029aa5e58 CR3: 000000090eb4a000 CR4: 00000000000006a0
> [  241.920339] DR0: 0000000000005bf2 DR1: 0000000000000000 DR2: 0000000000000000
> [  241.920339] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000070602
> [  241.920339] Stack:
> [  241.920339]  ffffffff856e37ab ffffffff84486272 0000000000000000 000000002b405600
> [  241.920339]  ffff88090eb71c58 ffff88090eb70000 0000000000000011 ffff88022ba03fc0
> [  241.920339]  ffff88090eb71cb8 000000000000000f ffff88022b405600 ffff880029aa5a40
> [  241.920339] Call Trace:
> [  241.920339]  [<ffffffff84486272>] ? preempt_count_sub+0xe2/0x120
> [  241.920339]  [<ffffffff8130f151>] ? alloc_inode+0x41/0xa0
> [  241.954886]  [<ffffffff8130f151>] ? alloc_inode+0x41/0xa0
> [  241.954886]  [<ffffffff8130f151>] ? alloc_inode+0x41/0xa0
> [  241.954886]  [<ffffffff812c36eb>] ? set_track+0xab/0x100
> [  241.954886]  [<ffffffff812c731f>] __slab_alloc+0x42f/0x4d0
> [  241.954886]  [<ffffffff81073e6d>] ? sched_clock+0x1d/0x30
> [  241.954886]  [<ffffffff8130f151>] ? alloc_inode+0x41/0xa0
> [  241.961624]  [<ffffffff812c870f>] kmem_cache_alloc+0x12f/0x2e0
> [  241.961624]  [<ffffffff8130f151>] ? alloc_inode+0x41/0xa0
> [  241.961624]  [<ffffffff8130f151>] alloc_inode+0x41/0xa0
> [  241.961624]  [<ffffffff8130f1cb>] new_inode_pseudo+0x1b/0x70
> [  241.961624]  [<ffffffff812f985c>] get_pipe_inode+0x1c/0xf0
> [  241.961624]  [<ffffffff812f995c>] create_pipe_files+0x2c/0x170
> [  241.961624]  [<ffffffff812f9ae1>] __do_pipe_flags+0x41/0xf0
> [  241.961624]  [<ffffffff812f9bbb>] SyS_pipe2+0x2b/0xb0
> [  241.961624]  [<ffffffff8448b3b1>] ? tracesys+0x7e/0xe2
> [  241.961624]  [<ffffffff8448b410>] tracesys+0xdd/0xe2
> [  241.972975] Code: 4d 85 f6 75 8b eb 45 90 4d 85 f6 75 13 49 8b 5c 24 10 45 31 ff 0f 1f 00 eb 32 66 0f 1f 44 00 00 4c 89 b5 48 ff ff ff 49 63 45 20 <49> 8b 0c 06 48 85 c9 74 10 4d 89 f7 49 8b 54 24 10 49 89 ce e9
> [  241.972975] RIP  [<ffffffff812c5fa3>] deactivate_slab+0x103/0x560
> [  241.972975]  RSP <ffff88090eb71c18>
> [  241.972975] CR2: ffff880029aa5e58

I have a lead on this. Consider the following:

   kmem_cache_alloc
	__slab_alloc
		local_irq_save()
		deactivate_slab
			__cmpxchg_double_slab
				slab_unlock
					__bit_spin_unlock
						preempt_enable
		[ Page Fault ]

With this trace, it manifests as a "BUG: sleeping function called from invalid
context at arch/x86/mm/fault.c" on a might_sleep() in the page fault handler
(which is an issue on it's own), but I suspect it's also the cause of the trace
above - preemption enabled and a race that removed the page.

Could someone confirm please?


Thanks,
Sasha

--
To unsubscribe, send a message with 'unsubscribe linux-mm' in
the body to majordomo@kvack.org.  For more info on Linux MM,
see: http://www.linux-mm.org/ .
Don't email: <a href=mailto:"dont@kvack.org"> email@kvack.org </a>

Re: mm: slub: gpf in deactivate_slab

[Christoph Lameter]

On Tue, 25 Mar 2014, Sasha Levin wrote:

> I have a lead on this. Consider the following:
>
>   kmem_cache_alloc
> 	__slab_alloc
> 		local_irq_save()
> 		deactivate_slab
> 			__cmpxchg_double_slab
> 				slab_unlock
> 					__bit_spin_unlock
> 						preempt_enable
> 		[ Page Fault ]
>
> With this trace, it manifests as a "BUG: sleeping function called from invalid
> context at arch/x86/mm/fault.c" on a might_sleep() in the page fault handler
> (which is an issue on it's own), but I suspect it's also the cause of the
> trace
> above - preemption enabled and a race that removed the page.
>
> Could someone confirm please?

The preempt count is incremented earlier in bit_spin_lock so the
preempt_enable() should not do anything.

--
To unsubscribe, send a message with 'unsubscribe linux-mm' in
the body to majordomo@kvack.org.  For more info on Linux MM,
see: http://www.linux-mm.org/ .
Don't email: <a href=mailto:"dont@kvack.org"> email@kvack.org </a>

Re: mm: slub: gpf in deactivate_slab

[Michal Hocko]

On Tue 25-03-14 11:54:43, Sasha Levin wrote:
> On 03/12/2014 12:25 PM, Sasha Levin wrote:
> >Hi all,
> >
> >While fuzzing with trinity inside a KVM tools guest running latest -next kernel I've stumbled
> >on the following spew:
> >
> >[  241.916559] BUG: unable to handle kernel paging request at ffff880029aa5e58
> >[  241.917961] IP: [<ffffffff812c5fa3>] deactivate_slab+0x103/0x560
> >[  241.919439] PGD 88f9067 PUD 88fa067 PMD 102fd35067 PTE 8000000029aa5060
> >[  241.920339] Oops: 0000 [#1] PREEMPT SMP DEBUG_PAGEALLOC
> >[  241.920339] Dumping ftrace buffer:
> >[  241.920339]    (ftrace buffer empty)
> >[  241.920339] Modules linked in:
> >[  241.920339] CPU: 17 PID: 9910 Comm: trinity-c183 Tainted: G        W    3.14.0-rc6-next-20140311-sasha-00009-g6c028cd-dirty #146
> >[  241.920339] task: ffff88090eb68000 ti: ffff88090eb70000 task.ti: ffff88090eb70000
> >[  241.920339] RIP: 0010:[<ffffffff812c5fa3>]  [<ffffffff812c5fa3>] deactivate_slab+0x103/0x560
> >[  241.920339] RSP: 0018:ffff88090eb71c18  EFLAGS: 00010082
> >[  241.920339] RAX: 0000000000000418 RBX: ffff880229ae2010 RCX: 0000000180170017
> >[  241.920339] RDX: 0000000000000000 RSI: ffffffff812c5f52 RDI: ffffffff812c5e29
> >[  241.920339] RBP: ffff88090eb71d28 R08: ffff880229ae2010 R09: 0000000000000080
> >[  241.920339] R10: ffff880229ae2ed0 R11: 0000000000000000 R12: ffffea0008a6b800
> >[  241.920339] R13: ffff88012b4da580 R14: ffff880029aa5a40 R15: ffff880229ae2010
> >[  241.920339] FS:  00007fb615415700(0000) GS:ffff88022ba00000(0000) knlGS:0000000000000000
> >[  241.920339] CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
> >[  241.920339] CR2: ffff880029aa5e58 CR3: 000000090eb4a000 CR4: 00000000000006a0
> >[  241.920339] DR0: 0000000000005bf2 DR1: 0000000000000000 DR2: 0000000000000000
> >[  241.920339] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000070602
> >[  241.920339] Stack:
> >[  241.920339]  ffffffff856e37ab ffffffff84486272 0000000000000000 000000002b405600
> >[  241.920339]  ffff88090eb71c58 ffff88090eb70000 0000000000000011 ffff88022ba03fc0
> >[  241.920339]  ffff88090eb71cb8 000000000000000f ffff88022b405600 ffff880029aa5a40
> >[  241.920339] Call Trace:
> >[  241.920339]  [<ffffffff84486272>] ? preempt_count_sub+0xe2/0x120
> >[  241.920339]  [<ffffffff8130f151>] ? alloc_inode+0x41/0xa0
> >[  241.954886]  [<ffffffff8130f151>] ? alloc_inode+0x41/0xa0
> >[  241.954886]  [<ffffffff8130f151>] ? alloc_inode+0x41/0xa0
> >[  241.954886]  [<ffffffff812c36eb>] ? set_track+0xab/0x100
> >[  241.954886]  [<ffffffff812c731f>] __slab_alloc+0x42f/0x4d0
> >[  241.954886]  [<ffffffff81073e6d>] ? sched_clock+0x1d/0x30
> >[  241.954886]  [<ffffffff8130f151>] ? alloc_inode+0x41/0xa0
> >[  241.961624]  [<ffffffff812c870f>] kmem_cache_alloc+0x12f/0x2e0
> >[  241.961624]  [<ffffffff8130f151>] ? alloc_inode+0x41/0xa0
> >[  241.961624]  [<ffffffff8130f151>] alloc_inode+0x41/0xa0
> >[  241.961624]  [<ffffffff8130f1cb>] new_inode_pseudo+0x1b/0x70
> >[  241.961624]  [<ffffffff812f985c>] get_pipe_inode+0x1c/0xf0
> >[  241.961624]  [<ffffffff812f995c>] create_pipe_files+0x2c/0x170
> >[  241.961624]  [<ffffffff812f9ae1>] __do_pipe_flags+0x41/0xf0
> >[  241.961624]  [<ffffffff812f9bbb>] SyS_pipe2+0x2b/0xb0
> >[  241.961624]  [<ffffffff8448b3b1>] ? tracesys+0x7e/0xe2
> >[  241.961624]  [<ffffffff8448b410>] tracesys+0xdd/0xe2
> >[  241.972975] Code: 4d 85 f6 75 8b eb 45 90 4d 85 f6 75 13 49 8b 5c 24 10 45 31 ff 0f 1f 00 eb 32 66 0f 1f 44 00 00 4c 89 b5 48 ff ff ff 49 63 45 20 <49> 8b 0c 06 48 85 c9 74 10 4d 89 f7 49 8b 54 24 10 49 89 ce e9
> >[  241.972975] RIP  [<ffffffff812c5fa3>] deactivate_slab+0x103/0x560
> >[  241.972975]  RSP <ffff88090eb71c18>
> >[  241.972975] CR2: ffff880029aa5e58
> 
> I have a lead on this. Consider the following:
> 
>   kmem_cache_alloc
> 	__slab_alloc
> 		local_irq_save()
> 		deactivate_slab
> 			__cmpxchg_double_slab
> 				slab_unlock
> 					__bit_spin_unlock
> 						preempt_enable
> 		[ Page Fault ]
> 
> With this trace, it manifests as a "BUG: sleeping function called from invalid
> context at arch/x86/mm/fault.c" on a might_sleep() in the page fault handler
> (which is an issue on it's own), but I suspect it's also the cause of the trace
> above - preemption enabled and a race that removed the page.
> 
> Could someone confirm please?

You are right. The function even does VM_BUG_ON(!irqs_disabled())...
Unfortunatelly we do not seem to have an _irq alternative of the bit
spinlock.
Not sure what to do about it. Christoph? 

Btw. it seems to go way back to 3.1 (1d07171c5e58e).
-- 
Michal Hocko
SUSE Labs

--
To unsubscribe, send a message with 'unsubscribe linux-mm' in
the body to majordomo@kvack.org.  For more info on Linux MM,
see: http://www.linux-mm.org/ .
Don't email: <a href=mailto:"dont@kvack.org"> email@kvack.org </a>

Re: mm: slub: gpf in deactivate_slab

[Christoph Lameter]

On Tue, 25 Mar 2014, Michal Hocko wrote:

> You are right. The function even does VM_BUG_ON(!irqs_disabled())...
> Unfortunatelly we do not seem to have an _irq alternative of the bit
> spinlock.
> Not sure what to do about it. Christoph?
>
> Btw. it seems to go way back to 3.1 (1d07171c5e58e).

Well there is a preempt_enable() (bit_spin_lock) and a preempt_disable()
bit_spin_unlock() within a piece of code where irqs are disabled.

Is that a problem? Has been there for a long time.

--
To unsubscribe, send a message with 'unsubscribe linux-mm' in
the body to majordomo@kvack.org.  For more info on Linux MM,
see: http://www.linux-mm.org/ .
Don't email: <a href=mailto:"dont@kvack.org"> email@kvack.org </a>

Re: mm: slub: gpf in deactivate_slab

[Sasha Levin]

On 03/25/2014 01:06 PM, Christoph Lameter wrote:
> On Tue, 25 Mar 2014, Michal Hocko wrote:
>
>> You are right. The function even does VM_BUG_ON(!irqs_disabled())...
>> Unfortunatelly we do not seem to have an _irq alternative of the bit
>> spinlock.
>> Not sure what to do about it. Christoph?
>>
>> Btw. it seems to go way back to 3.1 (1d07171c5e58e).
>
> Well there is a preempt_enable() (bit_spin_lock) and a preempt_disable()
> bit_spin_unlock() within a piece of code where irqs are disabled.
>
> Is that a problem? Has been there for a long time.

So here's the full trace. There's obviously something wrong here since we
pagefault inside the section that was supposed to be running with irqs disabled
and I don't see another cause besides this.

The unreliable entries in the stack trace also somewhat suggest that the
fault is with the code I've pointed out.


[  584.145271] BUG: sleeping function called from invalid context at arch/x86/mm/fault.c:1167
[  584.148787] in_atomic(): 0, irqs_disabled(): 1, pid: 10089, name: trinity-c42
[  584.150413] 1 lock held by trinity-c42/10089:
[  584.151834]  #0:  (&mm->mmap_sem){++++++}, at: [<ffffffff8450aec3>] __do_page_fault+0x2e3/0x630
[  584.151834] irq event stamp: 33318
[  584.151834] hardirqs last  enabled at (33317): [<ffffffff81282f15>] context_tracking_user_exit+0x1b5/0x260
[  584.151834] hardirqs last disabled at (33318): [<ffffffff844b10d6>] __slab_alloc+0x41/0x637
[  584.151834] softirqs last  enabled at (33070): [<ffffffff81161a3e>] __do_softirq+0x3fe/0x560
[  584.151834] softirqs last disabled at (33065): [<ffffffff81161f7c>] irq_exit+0x6c/0x170
[  584.151834] CPU: 42 PID: 10089 Comm: trinity-c42 Tainted: G        W     3.14.0-rc7-next-20140324-sasha-00015-g2fee858-dirty #271
[  584.151834]  ffff8800bc043000 ffff8800bc06f9c8 ffffffff844baf42 0000000000000001
[  584.151834]  0000000000000000 ffff8800bc06f9f8 ffffffff81197ee1 ffffffff8450aec3
[  584.151834]  0000000000000028 ffff8800bc06fb68 0000000000000a94 ffff8800bc06fb08
[  584.151834] Call Trace:
[  584.151834]  [<ffffffff844baf42>] dump_stack+0x4f/0x7c
[  584.151834]  [<ffffffff81197ee1>] __might_sleep+0x221/0x240
[  584.151834]  [<ffffffff8450aec3>] ? __do_page_fault+0x2e3/0x630
[  584.151834]  [<ffffffff8450af0b>] __do_page_fault+0x32b/0x630
[  584.151834]  [<ffffffff8107aab5>] ? sched_clock+0x15/0x20
[  584.151834]  [<ffffffff811a2295>] ? sched_clock_local+0x25/0xa0
[  584.151834]  [<ffffffff811a2578>] ? sched_clock_cpu+0xa8/0xf0
[  584.151834]  [<ffffffff81282f07>] ? context_tracking_user_exit+0x1a7/0x260
[  584.151834]  [<ffffffff81b37063>] ? __this_cpu_preempt_check+0x13/0x20
[  584.151834]  [<ffffffff811c0664>] ? trace_hardirqs_off_caller+0x174/0x1a0
[  584.151834]  [<ffffffff8450b25e>] do_page_fault+0x4e/0xa0
[  584.151834]  [<ffffffff8450a775>] do_async_page_fault+0x35/0x100
[  584.151834]  [<ffffffff845073d8>] async_page_fault+0x28/0x30
[  584.151834]  [<ffffffff812e60e8>] ? deactivate_slab+0xc8/0x620
[  584.151834]  [<ffffffff812e5f70>] ? __cmpxchg_double_slab.isra.26+0x120/0x1d0
[  584.151834]  [<ffffffff812e611b>] ? deactivate_slab+0xfb/0x620
[  584.151834]  [<ffffffff812e60e8>] ? deactivate_slab+0xc8/0x620
[  584.151834]  [<ffffffff84506345>] ? _raw_spin_unlock+0x35/0x60
[  584.151834]  [<ffffffff8132c5e1>] ? alloc_inode+0x41/0xa0
[  584.151834]  [<ffffffff8132c5e1>] ? alloc_inode+0x41/0xa0
[  584.151834]  [<ffffffff81b37087>] ? debug_smp_processor_id+0x17/0x20
[  584.151834]  [<ffffffff812e3676>] ? set_track+0x96/0x180
[  584.151834]  [<ffffffff812e35ce>] ? init_object+0x6e/0x80
[  584.151834]  [<ffffffff844b15f9>] __slab_alloc+0x564/0x637
[  584.151834]  [<ffffffff810b9b24>] ? kvm_clock_read+0x24/0x40
[  584.151834]  [<ffffffff8132c5e1>] ? alloc_inode+0x41/0xa0
[  584.151834]  [<ffffffff8119b041>] ? get_parent_ip+0x11/0x50
[  584.151834]  [<ffffffff812e7ddc>] kmem_cache_alloc+0x12c/0x3b0
[  584.151834]  [<ffffffff8132c5e1>] ? alloc_inode+0x41/0xa0
[  584.151834]  [<ffffffff811a3288>] ? vtime_account_user+0x98/0xb0
[  584.151834]  [<ffffffff8132c5e1>] alloc_inode+0x41/0xa0
[  584.151834]  [<ffffffff8132e4fa>] new_inode_pseudo+0x1a/0x70
[  584.151834]  [<ffffffff8131837a>] create_pipe_files+0x2a/0x220
[  584.151834]  [<ffffffff811c28f4>] ? trace_hardirqs_on_caller+0x1f4/0x290
[  584.151834]  [<ffffffff813185b5>] __do_pipe_flags+0x45/0xe0
[  584.151834]  [<ffffffff81318770>] SyS_pipe+0x20/0xb0
[  584.151834]  [<ffffffff84510975>] ? tracesys+0x7e/0xe6
[  584.151834]  [<ffffffff845109d8>] tracesys+0xe1/0xe6

It was also followed by a straightforward NULL ptr deref in deactivate_slab():

[  584.151834] BUG: unable to handle kernel NULL pointer dereference at 0000000000000a94
[  584.151834] IP: [<ffffffff812e611b>] deactivate_slab+0xfb/0x620
[  584.223982] PGD bc06c067 PUD bc06d067 PMD 0
[  584.223982] Oops: 0000 [#1] PREEMPT SMP DEBUG_PAGEALLOC
[  584.223982] Dumping ftrace buffer:
[  584.223982]    (ftrace buffer empty)
[  584.223982] Modules linked in:
[  584.223982] CPU: 42 PID: 10089 Comm: trinity-c42 Tainted: G        W     3.14.0-rc7-next-20140324-sasha-00015-g2fee858-dirty #271
[  584.223982] task: ffff8800bc043000 ti: ffff8800bc06e000 task.ti: ffff8800bc06e000
[  584.223982] RIP: 0010:[<ffffffff812e611b>]  [<ffffffff812e611b>] deactivate_slab+0xfb/0x620
[  584.223982] RSP: 0018:ffff8800bc06fc18  EFLAGS: 00010006
[  584.223982] RAX: 0000000000000410 RBX: ffffea002bb04200 RCX: 0000000180180016
[  584.223982] RDX: 0000000000000001 RSI: ffffffff812e60e8 RDI: ffffffff812e5f70
[  584.223982] RBP: ffff8800bc06fd08 R08: ffffea0023ac6000 R09: 0000000000000080
[  584.223982] R10: ffff880aec108408 R11: 0000000000000001 R12: ffffea0023ac6000
[  584.223982] R13: ffff880a6c520000 R14: 0000000000000684 R15: 0000000000000684
[  584.223982] FS:  00007feaa0845700(0000) GS:ffff880aecc00000(0000) knlGS:0000000000000000
[  584.223982] CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
[  584.223982] CR2: 0000000000000a94 CR3: 00000000bc06b000 CR4: 00000000000006a0
[  584.223982] DR0: 0000000000698000 DR1: 0000000000698000 DR2: 0000000000000000
[  584.223982] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000d9060a
[  584.223982] Stack:
[  584.223982]  ffff8800bc043000 0000002a8450b958 ffff8800bc06e000 ffff8800bc06fc78
[  584.223982]  00000000bc06fc58 ffffffff84506345 ffff88000000000f ffff880aec805600
[  584.223982]  ffffffff8132c5e1 0000000000000082 ffff880aec108418 0000000180180015
[  584.223982] Call Trace:
[  584.223982]  [<ffffffff84506345>] ? _raw_spin_unlock+0x35/0x60
[  584.223982]  [<ffffffff8132c5e1>] ? alloc_inode+0x41/0xa0
[  584.223982]  [<ffffffff8132c5e1>] ? alloc_inode+0x41/0xa0
[  584.223982]  [<ffffffff81b37087>] ? debug_smp_processor_id+0x17/0x20
[  584.223982]  [<ffffffff812e3676>] ? set_track+0x96/0x180
[  584.223982]  [<ffffffff812e35ce>] ? init_object+0x6e/0x80
[  584.223982]  [<ffffffff844b15f9>] __slab_alloc+0x564/0x637
[  584.223982]  [<ffffffff810b9b24>] ? kvm_clock_read+0x24/0x40
[  584.223982]  [<ffffffff8132c5e1>] ? alloc_inode+0x41/0xa0
[  584.223982]  [<ffffffff8119b041>] ? get_parent_ip+0x11/0x50
[  584.223982]  [<ffffffff812e7ddc>] kmem_cache_alloc+0x12c/0x3b0
[  584.223982]  [<ffffffff8132c5e1>] ? alloc_inode+0x41/0xa0
[  584.223982]  [<ffffffff811a3288>] ? vtime_account_user+0x98/0xb0
[  584.223982]  [<ffffffff8132c5e1>] alloc_inode+0x41/0xa0
[  584.223982]  [<ffffffff8132e4fa>] new_inode_pseudo+0x1a/0x70
[  584.223982]  [<ffffffff8131837a>] create_pipe_files+0x2a/0x220
[  584.223982]  [<ffffffff811c28f4>] ? trace_hardirqs_on_caller+0x1f4/0x290
[  584.223982]  [<ffffffff813185b5>] __do_pipe_flags+0x45/0xe0
[  584.223982]  [<ffffffff81318770>] SyS_pipe+0x20/0xb0
[  584.223982]  [<ffffffff84510975>] ? tracesys+0x7e/0xe6
[  584.223982]  [<ffffffff845109d8>] tracesys+0xe1/0xe6
[  584.223982] Code: 49 63 45 20 eb b2 66 2e 0f 1f 84 00 00 00 00 00 4d 85 f6 75 0b 4c 8b 63 10 45 31 ff eb 22 66 90 49 63 45 20 4d 89 f7 4c 8b 63 10 <49> 8b 14 06 48 85 d2 74 0c 49 89 d6 e9 7c ff ff ff 0f 1f 40 00
[  584.223982] RIP  [<ffffffff812e611b>] deactivate_slab+0xfb/0x620
[  584.223982]  RSP <ffff8800bc06fc18>
[  584.223982] CR2: 0000000000000a94


Thanks,
Sasha

--
To unsubscribe, send a message with 'unsubscribe linux-mm' in
the body to majordomo@kvack.org.  For more info on Linux MM,
see: http://www.linux-mm.org/ .
Don't email: <a href=mailto:"dont@kvack.org"> email@kvack.org </a>

Re: mm: slub: gpf in deactivate_slab

[Michal Hocko]

On Tue 25-03-14 12:06:36, Christoph Lameter wrote:
> On Tue, 25 Mar 2014, Michal Hocko wrote:
> 
> > You are right. The function even does VM_BUG_ON(!irqs_disabled())...
> > Unfortunatelly we do not seem to have an _irq alternative of the bit
> > spinlock.
> > Not sure what to do about it. Christoph?
> >
> > Btw. it seems to go way back to 3.1 (1d07171c5e58e).
> 
> Well there is a preempt_enable() (bit_spin_lock) and a preempt_disable()
> bit_spin_unlock() within a piece of code where irqs are disabled.
> 
> Is that a problem? Has been there for a long time.

It is because preempt_enable calls __preempt_schedule when the preempt
count drops down to 0. You would need to call preempt_disable before you
disable interrupts or use an irq safe bit spin unlock which doesn't
enabled preemption unconditionally.
 

-- 
Michal Hocko
SUSE Labs

--
To unsubscribe, send a message with 'unsubscribe linux-mm' in
the body to majordomo@kvack.org.  For more info on Linux MM,
see: http://www.linux-mm.org/ .
Don't email: <a href=mailto:"dont@kvack.org"> email@kvack.org </a>

Re: mm: slub: gpf in deactivate_slab

[Michal Hocko]

On Tue 25-03-14 10:56:34, Michal Hocko wrote:
> On Tue 25-03-14 12:06:36, Christoph Lameter wrote:
> > On Tue, 25 Mar 2014, Michal Hocko wrote:
> > 
> > > You are right. The function even does VM_BUG_ON(!irqs_disabled())...
> > > Unfortunatelly we do not seem to have an _irq alternative of the bit
> > > spinlock.
> > > Not sure what to do about it. Christoph?
> > >
> > > Btw. it seems to go way back to 3.1 (1d07171c5e58e).
> > 
> > Well there is a preempt_enable() (bit_spin_lock) and a preempt_disable()
> > bit_spin_unlock() within a piece of code where irqs are disabled.
> > 
> > Is that a problem? Has been there for a long time.
> 
> It is because preempt_enable calls __preempt_schedule when the preempt
> count drops down to 0. You would need to call preempt_disable before you
> disable interrupts or use an irq safe bit spin unlock which doesn't
> enabled preemption unconditionally.

Hmm, now that I am looking into the code more closely it seems that
preempt_schedule bails out when interrupts are disabled.
-- 
Michal Hocko
SUSE Labs

--
To unsubscribe, send a message with 'unsubscribe linux-mm' in
the body to majordomo@kvack.org.  For more info on Linux MM,
see: http://www.linux-mm.org/ .
Don't email: <a href=mailto:"dont@kvack.org"> email@kvack.org </a>

Re: mm: slub: gpf in deactivate_slab

[Christoph Lameter]

On Tue, 25 Mar 2014, Sasha Levin wrote:

> So here's the full trace. There's obviously something wrong here since we
> pagefault inside the section that was supposed to be running with irqs
> disabled
> and I don't see another cause besides this.
>
> The unreliable entries in the stack trace also somewhat suggest that the
> fault is with the code I've pointed out.

Looks like there was some invalid data fed to the function and the page
fault with interrupts disabled is the result of following and invalid
pointer.

Is there more context information available? What are the options set for
the cache that the operation was performed on?


--
To unsubscribe, send a message with 'unsubscribe linux-mm' in
the body to majordomo@kvack.org.  For more info on Linux MM,
see: http://www.linux-mm.org/ .
Don't email: <a href=mailto:"dont@kvack.org"> email@kvack.org </a>

Re: mm: slub: gpf in deactivate_slab

[Sasha Levin]

On 03/25/2014 02:10 PM, Christoph Lameter wrote:
> On Tue, 25 Mar 2014, Sasha Levin wrote:
>
>> So here's the full trace. There's obviously something wrong here since we
>> pagefault inside the section that was supposed to be running with irqs
>> disabled
>> and I don't see another cause besides this.
>>
>> The unreliable entries in the stack trace also somewhat suggest that the
>> fault is with the code I've pointed out.
>
> Looks like there was some invalid data fed to the function and the page
> fault with interrupts disabled is the result of following and invalid
> pointer.
>
> Is there more context information available? What are the options set for
> the cache that the operation was performed on?

It seems like it's a regular allocation from the inode_cachep kmem_cache:

	inode = kmem_cache_alloc(inode_cachep, GFP_KERNEL);

I'm not sure if there's anything special about this cache, codewise it's
created as follows:


         inode_cachep = kmem_cache_create("inode_cache",
                                          sizeof(struct inode),
                                          0,
                                          (SLAB_RECLAIM_ACCOUNT|SLAB_PANIC|
                                          SLAB_MEM_SPREAD),
                                          init_once);


I'd be happy to dig up any other info required, I'm just not too sure
what you mean by options for the cache?


Thanks,
Sasha

--
To unsubscribe, send a message with 'unsubscribe linux-mm' in
the body to majordomo@kvack.org.  For more info on Linux MM,
see: http://www.linux-mm.org/ .
Don't email: <a href=mailto:"dont@kvack.org"> email@kvack.org </a>

Re: mm: slub: gpf in deactivate_slab

[Christoph Lameter]

On Tue, 25 Mar 2014, Sasha Levin wrote:

> I'm not sure if there's anything special about this cache, codewise it's
> created as follows:
>
>
>         inode_cachep = kmem_cache_create("inode_cache",
>                                          sizeof(struct inode),
>                                          0,
>                                          (SLAB_RECLAIM_ACCOUNT|SLAB_PANIC|
>                                          SLAB_MEM_SPREAD),
>                                          init_once);
>
>
> I'd be happy to dig up any other info required, I'm just not too sure
> what you mean by options for the cache?

Slab parameters can be change in /sys/kernel/slab/inode. Any debug
parameters active? More information about what was actually going on when
the gpf occured?

--
To unsubscribe, send a message with 'unsubscribe linux-mm' in
the body to majordomo@kvack.org.  For more info on Linux MM,
see: http://www.linux-mm.org/ .
Don't email: <a href=mailto:"dont@kvack.org"> email@kvack.org </a>

Re: mm: slub: gpf in deactivate_slab

[Sasha Levin]

On 03/26/2014 11:43 AM, Christoph Lameter wrote:
> On Tue, 25 Mar 2014, Sasha Levin wrote:
> 
>> I'm not sure if there's anything special about this cache, codewise it's
>> created as follows:
>>
>>
>>         inode_cachep = kmem_cache_create("inode_cache",
>>                                          sizeof(struct inode),
>>                                          0,
>>                                          (SLAB_RECLAIM_ACCOUNT|SLAB_PANIC|
>>                                          SLAB_MEM_SPREAD),
>>                                          init_once);
>>
>>
>> I'd be happy to dig up any other info required, I'm just not too sure
>> what you mean by options for the cache?
> 
> Slab parameters can be change in /sys/kernel/slab/inode. Any debug
> parameters active? More information about what was actually going on when
> the gpf occured?

Unfortunately I've been unable to reproduce the issue to get more debug info
out of it. However, I've hit something that seems to be somewhat similar
to that:

[ 1035.176692] BUG: unable to handle kernel paging request at ffff8801377e4000
[ 1035.177893] IP: memset (arch/x86/lib/memset_64.S:105)
[ 1035.178651] PGD 3d91c067 PUD 102f7ff067 PMD 102f643067 PTE 80000001377e4060
[ 1035.179740] Oops: 0002 [#1] PREEMPT SMP DEBUG_PAGEALLOC
[ 1035.180063] Dumping ftrace buffer:
[ 1035.180063]    (ftrace buffer empty)
[ 1035.180063] Modules linked in:
[ 1035.180063] CPU: 2 PID: 27857 Comm: modprobe Not tainted 3.14.0-next-20140403-sasha-00019-g7474aa9-dirty #376
[ 1035.180063] task: ffff8800a1918000 ti: ffff8800a4650000 task.ti: ffff8800a4650000
[ 1035.180063] RIP: memset (arch/x86/lib/memset_64.S:105)
[ 1035.180063] RSP: 0018:ffff8800a4651b60  EFLAGS: 00010046
[ 1035.180063] RAX: bbbbbbbbbbbbbbbb RBX: ffff88007d852ec0 RCX: 0000000000000000
[ 1035.180063] RDX: 0000000000000008 RSI: 00000000000000bb RDI: ffff8801377e4000
[ 1035.180063] RBP: ffff8800a4651b88 R08: 0000000000000001 R09: 0000000000000000
[ 1035.180063] R10: ffff8801377e4000 R11: ffffffffffffffce R12: ffff8801377e3000
[ 1035.180063] R13: 00000000000000bb R14: ffff8801377e3000 R15: ffffffffffffffff
[ 1035.180063] FS:  00007f2e098d6700(0000) GS:ffff8801abc00000(0000) knlGS:0000000000000000
[ 1035.180063] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 1035.180063] CR2: ffff8801377e4000 CR3: 000000061feec000 CR4: 00000000000006a0
[ 1035.193166] DR0: 0000000000696000 DR1: 0000000000000000 DR2: 0000000000000000
[ 1035.193166] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000600
[ 1035.193166] Stack:
[ 1035.193166]  ffffffffb62dabee ffff8800a4651b78 ffff88007d852ec0 ffff8801377e3000
[ 1035.193166]  ffffea0004ddf8c0 ffff8800a4651ba8 ffffffffb62db1c0 ffff88007d852ec0
[ 1035.193166]  ffff8801377e3000 ffff8800a4651be8 ffffffffb62dd1a6 ffff8800a4651bd8
[ 1035.193166] Call Trace:
[ 1035.193166] ? init_object (mm/slub.c:679)
[ 1035.193166] setup_object.isra.34 (mm/slub.c:1071 mm/slub.c:1399)
[ 1035.193166] new_slab (mm/slub.c:286 mm/slub.c:1439)
[ 1035.193166] __slab_alloc (mm/slub.c:2203 mm/slub.c:2363)
[ 1035.193166] ? kmem_cache_alloc (mm/slub.c:2469 mm/slub.c:2480 mm/slub.c:2485)
[ 1035.193166] ? getname_flags (fs/namei.c:145)
[ 1035.193166] ? get_parent_ip (kernel/sched/core.c:2472)
[ 1035.193166] kmem_cache_alloc (mm/slub.c:2469 mm/slub.c:2480 mm/slub.c:2485)
[ 1035.193166] ? getname_flags (fs/namei.c:145)
[ 1035.193166] getname_flags (fs/namei.c:145)
[ 1035.193166] user_path_at_empty (fs/namei.c:2121)
[ 1035.193166] ? kvm_clock_read (arch/x86/include/asm/preempt.h:90 arch/x86/kernel/kvmclock.c:86)
[ 1035.193166] ? sched_clock (arch/x86/include/asm/paravirt.h:192 arch/x86/kernel/tsc.c:305)
[ 1035.193166] ? sched_clock_local (kernel/sched/clock.c:214)
[ 1035.193166] ? vtime_account_user (kernel/sched/cputime.c:687)
[ 1035.193166] ? debug_smp_processor_id (lib/smp_processor_id.c:57)
[ 1035.193166] ? put_lock_stats.isra.12 (arch/x86/include/asm/preempt.h:98 kernel/locking/lockdep.c:254)
[ 1035.193166] user_path_at (fs/namei.c:2137)
[ 1035.193166] vfs_fstatat (fs/stat.c:107)
[ 1035.193166] ? context_tracking_user_exit (arch/x86/include/asm/paravirt.h:809 (discriminator 2) kernel/context_tracking.c:182 (discriminator 2))
[ 1035.193166] vfs_stat (fs/stat.c:124)
[ 1035.193166] SYSC_newstat (fs/stat.c:272)
[ 1035.193166] ? trace_hardirqs_on (kernel/locking/lockdep.c:2607)
[ 1035.193166] ? syscall_trace_enter (include/linux/context_tracking.h:27 arch/x86/kernel/ptrace.c:1461)
[ 1035.193166] ? tracesys (arch/x86/kernel/entry_64.S:738)
[ 1035.193166] SyS_newstat (fs/stat.c:267)
[ 1035.193166] tracesys (arch/x86/kernel/entry_64.S:749)
[ 1035.193166] Code: 89 47 28 48 89 47 30 48 89 47 38 48 8d 7f 40 75 d8 0f 1f 84 00 00 00 00 00 89 d1 83 e1 38 74 14 c1 e9 03 66 0f 1f 44 00 00 ff c9 <48> 89 07 48 8d 7f 08 75 f5 83 e2 07 74 0a ff ca 88 07 48 8d 7f
[ 1035.193166] RIP memset (arch/x86/lib/memset_64.S:105)
[ 1035.193166]  RSP <ffff8800a4651b60>
[ 1035.193166] CR2: ffff8801377e4000


Thanks,
Sasha

--
To unsubscribe, send a message with 'unsubscribe linux-mm' in
the body to majordomo@kvack.org.  For more info on Linux MM,
see: http://www.linux-mm.org/ .
Don't email: <a href=mailto:"dont@kvack.org"> email@kvack.org </a>

Re: mm: slub: gpf in deactivate_slab

[Christoph Lameter]

On Sat, 5 Apr 2014, Sasha Levin wrote:

> Unfortunately I've been unable to reproduce the issue to get more debug info
> out of it. However, I've hit something that seems to be somewhat similar
> to that:

Could you jsut run with "slub_debug" on the kernel command line to get us
more diagnostics? Could be memory corruption.

--
To unsubscribe, send a message with 'unsubscribe linux-mm' in
the body to majordomo@kvack.org.  For more info on Linux MM,
see: http://www.linux-mm.org/ .
Don't email: <a href=mailto:"dont@kvack.org"> email@kvack.org </a>

Re: mm: slub: gpf in deactivate_slab

[Sasha Levin]

On 04/07/2014 01:13 PM, Christoph Lameter wrote:
> On Sat, 5 Apr 2014, Sasha Levin wrote:
> 
>> Unfortunately I've been unable to reproduce the issue to get more debug info
>> out of it. However, I've hit something that seems to be somewhat similar
>> to that:
> 
> Could you jsut run with "slub_debug" on the kernel command line to get us
> more diagnostics? Could be memory corruption.

I was running it with "slub_debug=FZPU" when I reported both errors,
there was no other information beyond the traces in the log.


Thanks,
Sasha

--
To unsubscribe, send a message with 'unsubscribe linux-mm' in
the body to majordomo@kvack.org.  For more info on Linux MM,
see: http://www.linux-mm.org/ .
Don't email: <a href=mailto:"dont@kvack.org"> email@kvack.org </a>

Re: mm: slub: gpf in deactivate_slab

[Christoph Lameter]

On Sat, 5 Apr 2014, Sasha Levin wrote:

> [ 1035.193166] Call Trace:
> [ 1035.193166] ? init_object (mm/slub.c:679)
> [ 1035.193166] setup_object.isra.34 (mm/slub.c:1071 mm/slub.c:1399)
> [ 1035.193166] new_slab (mm/slub.c:286 mm/slub.c:1439)
> [ 1035.193166] __slab_alloc (mm/slub.c:2203 mm/slub.c:2363)
> [ 1035.193166] ? kmem_cache_alloc (mm/slub.c:2469 mm/slub.c:2480 mm/slub.c:2485)


Ok so the story here is that slub decided it needed a new slab and
requested memory from the page allocator.

setup_object() tries to write to the page which fails.

Could the page allocator have delivered a reference to a page struct that
creates an invalid address?

The code that fails is:

 page = allocate_slab(s,
                flags & (GFP_RECLAIM_MASK | GFP_CONSTRAINT_MASK), node);
        if (!page)
                goto out;

--- So we got a page from teh page allocator

        order = compound_order(page);
        inc_slabs_node(s, page_to_nid(page), page->objects);
        memcg_bind_pages(s, order);
        page->slab_cache = s;
        __SetPageSlab(page);

-- Writing to the page struct works.

        if (page->pfmemalloc)
                SetPageSlabPfmemalloc(page);

        start = page_address(page);

        if (unlikely(s->flags & SLAB_POISON))
                memset(start, POISON_INUSE, PAGE_SIZE << order);


--- This should have triggered since we write to the page but maybe this
	slab has a ctor set and therefore no poisining is possible.

        last = start;
        for_each_object(p, s, start, page->objects) {
                setup_object(s, page, last);

*** This is where the write access to the page fails.

                set_freepointer(s, last, p);
                last = p;
        }
        setup_object(s, page, last);

--
To unsubscribe, send a message with 'unsubscribe linux-mm' in
the body to majordomo@kvack.org.  For more info on Linux MM,
see: http://www.linux-mm.org/ .
Don't email: <a href=mailto:"dont@kvack.org"> email@kvack.org </a>