[BUG] in 2.6.25-rc3 with 64k page size and SLUB_DEBUG_ON

[BUG] in 2.6.25-rc3 with 64k page size and SLUB_DEBUG_ON

[Jens Osterkamp]

[-- Attachment #1: Type: text/plain, Size: 2735 bytes --]


Hi,

when booting 2.6.25-rc3 on powerpc64 with SLUB_DEBUG_ON and 64k page size, it drops into xmon 
during boot with the following :

Console: colour dummy device 80x25
Dentry cache hash table entries: 262144 (order: 5, 2097152 bytes)
Inode-cache hash table entries: 131072 (order: 4, 1048576 bytes)
freeing bootmem node 0
freeing bootmem node 1
Memory: 2037184k/2097152k available (4864k kernel code, 59968k reserved, 768k data, 419k bss, 384k init)
SLUB: Genslabs=17, HWalign=128, Order=0-2, MinObjects=8, CPUs=4, Nodes=16
Mount-cache hash table entries: 4096
BUG: scheduling while atomic: kthreadd/2/0x00056ef8
Call Trace:
[c00000003c187b68] [c00000000000f140] .show_stack+0x70/0x1bc (unreliable)
[c00000003c187c18] [c000000000052d0c] .__schedule_bug+0x64/0x80
[c00000003c187ca8] [c00000000036fa84] .schedule+0xc4/0x6b0
[c00000003c187d98] [c0000000003702d0] .schedule_timeout+0x3c/0xe8
[c00000003c187e68] [c00000000036f82c] .wait_for_common+0x150/0x22c
[c00000003c187f28] [c000000000074868] .kthreadd+0x12c/0x1f0
[c00000003c187fd8] [c000000000024864] .kernel_thread+0x4c/0x68
------------[ cut here ]------------
kernel BUG at /home/auto/jens/kernels/linux-2.6.25-rc3/kernel/sched.c:4532!
cpu 0x0: Vector: 700 (Program Check) at [c00000003c187bc8]
    pc: c000000000051f8c: .sched_setscheduler+0x5c/0x48c
    lr: c0000000000748b0: .kthreadd+0x174/0x1f0
    sp: c00000003c187e48
   msr: 9000000000029032
  current = 0xc00000007e0808a0
  paca    = 0xc0000000004cf880
    pid   = 2, comm = kthreadd
kernel BUG at /home/auto/jens/kernels/linux-2.6.25-rc3/kernel/sched.c:4532!
enter ? for help
[c00000003c187f28] c0000000000748b0 .kthreadd+0x174/0x1f0
[c00000003c187fd8] c000000000024864 .kernel_thread+0x4c/0x68
0:mon> 

In the code this corresponds to

int sched_setscheduler(struct task_struct *p, int policy,
                       struct sched_param *param)
{
        int retval, oldprio, oldpolicy = -1, on_rq, running;
        unsigned long flags;
        const struct sched_class *prev_class = p->sched_class;
        struct rq *rq;

        /* may grab non-irq protected spin_locks */
        BUG_ON(in_interrupt());
recheck:
        /* double check policy once rq lock held */
        if (policy < 0)
                policy = oldpolicy = p->policy;
        else if (policy != SCHED_FIFO && policy != SCHED_RR &&
                        policy != SCHED_NORMAL && policy != SCHED_BATCH &&
                        policy != SCHED_IDLE)
                return -EINVAL;

With slub_debug=- on the kernel command line, the problem is gone.
With 4k page size the problem also does not occur.

Any ideas on why this occurs and how to debug this further ?

Gruß,
	Jens

[-- Attachment #2: This is a digitally signed message part. --]
[-- Type: application/pgp-signature, Size: 189 bytes --]

Re: [BUG] in 2.6.25-rc3 with 64k page size and SLUB_DEBUG_ON

[Christoph Lameter]

On Thu, 6 Mar 2008, Jens Osterkamp wrote:

> BUG: scheduling while atomic: kthreadd/2/0x00056ef8

Hmmmm... Fallback?

> Call Trace:
> [c00000003c187b68] [c00000000000f140] .show_stack+0x70/0x1bc (unreliable)
> [c00000003c187c18] [c000000000052d0c] .__schedule_bug+0x64/0x80
> [c00000003c187ca8] [c00000000036fa84] .schedule+0xc4/0x6b0
> [c00000003c187d98] [c0000000003702d0] .schedule_timeout+0x3c/0xe8
> [c00000003c187e68] [c00000000036f82c] .wait_for_common+0x150/0x22c
> [c00000003c187f28] [c000000000074868] .kthreadd+0x12c/0x1f0
> [c00000003c187fd8] [c000000000024864] .kernel_thread+0x4c/0x68

But nothing slub wise here...

> With slub_debug=- on the kernel command line, the problem is gone.
> With 4k page size the problem also does not occur.

> Any ideas on why this occurs and how to debug this further ?

Could be the result of fallback under debug?? Looks like there is a hole 
in the fallback logic. But this could be something completely different.

If this is slub related then we may not be reenabling interrupt somewhere 
if debug is on.

diff --git a/mm/slub.c b/mm/slub.c
index 96d63eb..6d0a103 100644
--- a/mm/slub.c
+++ b/mm/slub.c
@@ -1536,8 +1536,14 @@ new_slab:
 	 * That is only possible if certain conditions are met that are being
 	 * checked when a slab is created.
 	 */
-	if (!(gfpflags & __GFP_NORETRY) && (s->flags & __PAGE_ALLOC_FALLBACK))
-		return kmalloc_large(s->objsize, gfpflags);
+	if (!(gfpflags & __GFP_NORETRY) && (s->flags & __PAGE_ALLOC_FALLBACK)) {
+		if (gfpflags & __GFP_WAIT)
+			local_irq_enable();
+		object =  kmalloc_large(s->objsize, gfpflags);
+		if (gfpflags & __GFP_WAIT)
+			local_irq_disable();
+		return object;
+	}
 
 	return NULL;
 debug:

--
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: [BUG] in 2.6.25-rc3 with 64k page size and SLUB_DEBUG_ON

[Jens Osterkamp]

[-- Attachment #1: Type: text/plain, Size: 1919 bytes --]


Hi,

> > Call Trace:
> > [c00000003c187b68] [c00000000000f140] .show_stack+0x70/0x1bc (unreliable)
> > [c00000003c187c18] [c000000000052d0c] .__schedule_bug+0x64/0x80
> > [c00000003c187ca8] [c00000000036fa84] .schedule+0xc4/0x6b0
> > [c00000003c187d98] [c0000000003702d0] .schedule_timeout+0x3c/0xe8
> > [c00000003c187e68] [c00000000036f82c] .wait_for_common+0x150/0x22c
> > [c00000003c187f28] [c000000000074868] .kthreadd+0x12c/0x1f0
> > [c00000003c187fd8] [c000000000024864] .kernel_thread+0x4c/0x68
> 
> But nothing slub wise here...

I had earlier biesected this to the following commit, should have mentioned that,
sorry !

commit f0630fff54a239efbbd89faf6a62da071ef1ff78
Author: Christoph Lameter <clameter@sgi.com>
Date:   Sun Jul 15 23:38:14 2007 -0700

    SLUB: support slub_debug on by default

    [...]

> Could be the result of fallback under debug?? Looks like there is a hole 
> in the fallback logic. But this could be something completely different.

What do you mean by fallback ?

> If this is slub related then we may not be reenabling interrupt somewhere 
> if debug is on.
> 
> diff --git a/mm/slub.c b/mm/slub.c
> index 96d63eb..6d0a103 100644
> --- a/mm/slub.c
> +++ b/mm/slub.c
> @@ -1536,8 +1536,14 @@ new_slab:
>  	 * That is only possible if certain conditions are met that are being
>  	 * checked when a slab is created.
>  	 */
> -	if (!(gfpflags & __GFP_NORETRY) && (s->flags & __PAGE_ALLOC_FALLBACK))
> -		return kmalloc_large(s->objsize, gfpflags);
> +	if (!(gfpflags & __GFP_NORETRY) && (s->flags & __PAGE_ALLOC_FALLBACK)) {
> +		if (gfpflags & __GFP_WAIT)
> +			local_irq_enable();
> +		object =  kmalloc_large(s->objsize, gfpflags);
> +		if (gfpflags & __GFP_WAIT)
> +			local_irq_disable();
> +		return object;
> +	}
>  
>  	return NULL;
>  debug:

I just tried the patch, but the problem is still there...

Gruß,
	Jens

[-- Attachment #2: This is a digitally signed message part. --]
[-- Type: application/pgp-signature, Size: 189 bytes --]

Re: [BUG] in 2.6.25-rc3 with 64k page size and SLUB_DEBUG_ON

[Christoph Lameter]

On Thu, 6 Mar 2008, Jens Osterkamp wrote:

> I had earlier biesected this to the following commit, should have mentioned that,
> sorry !
> 
> commit f0630fff54a239efbbd89faf6a62da071ef1ff78
> Author: Christoph Lameter <clameter@sgi.com>
> Date:   Sun Jul 15 23:38:14 2007 -0700
> 
>     SLUB: support slub_debug on by default
> 
>     [...]

hehehe. So slub debug is off if you do not specify slub_debug on the 
commandline. No surprise there.

> I just tried the patch, but the problem is still there...

Duh. So this is also in 2.6.23 and 2.6.24?

--
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: [BUG] in 2.6.25-rc3 with 64k page size and SLUB_DEBUG_ON

[Jens Osterkamp]

[-- Attachment #1: Type: text/plain, Size: 99 bytes --]


> Duh. So this is also in 2.6.23 and 2.6.24?

Yes, it got in with 2.6.23-rc1.

Gruß,
	Jens

[-- Attachment #2: This is a digitally signed message part. --]
[-- Type: application/pgp-signature, Size: 189 bytes --]

Re: [BUG] in 2.6.25-rc3 with 64k page size and SLUB_DEBUG_ON

[Christoph Lameter]

On Thu, 6 Mar 2008, Jens Osterkamp wrote:

> > Duh. So this is also in 2.6.23 and 2.6.24?
> 
> Yes, it got in with 2.6.23-rc1.

Then check 2.6.22 and specify the boot parameter "slub_debug". Make sure 
to compile the kernel with slub support. Is there any way you could get 
us further information about the problem?

--
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: [BUG] in 2.6.25-rc3 with 64k page size and SLUB_DEBUG_ON

[Pekka Enberg]

Christoph Lameter wrote:
> On Thu, 6 Mar 2008, Jens Osterkamp wrote:
> 
>>> Duh. So this is also in 2.6.23 and 2.6.24?
>> Yes, it got in with 2.6.23-rc1.
> 
> Then check 2.6.22 and specify the boot parameter "slub_debug". Make sure 
> to compile the kernel with slub support. Is there any way you could get 
> us further information about the problem?

You mention slub_debug=- makes the problem go away but can you narrow it 
down to a specific debug option described in Documentation/vm/slub.txt? 
In particular, does disabling slab poisoning or red zoning make the 
problem go away also?

--
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: [BUG] in 2.6.25-rc3 with 64k page size and SLUB_DEBUG_ON

[Pekka Enberg]

Pekka Enberg wrote:
> You mention slub_debug=- makes the problem go away but can you narrow it 
> down to a specific debug option described in Documentation/vm/slub.txt? 
> In particular, does disabling slab poisoning or red zoning make the 
> problem go away also?

The most important thing to check is whether the kernel crashes with 
slub_debug=f. That option enables all the debug paths but doesn't change 
memory layout or contents at all (unlike red-zoning and poisoning).

--
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: [BUG] in 2.6.25-rc3 with 64k page size and SLUB_DEBUG_ON

[Jens Osterkamp]

[-- Attachment #1: Type: text/plain, Size: 347 bytes --]


> You mention slub_debug=- makes the problem go away but can you narrow it 
> down to a specific debug option described in Documentation/vm/slub.txt? 
> In particular, does disabling slab poisoning or red zoning make the 
> problem go away also?

I tried with slub_debug= F,Z,P and U. Only with F the problem is not there.

Gruß,
	Jens

[-- Attachment #2: This is a digitally signed message part. --]
[-- Type: application/pgp-signature, Size: 189 bytes --]

Re: [BUG] in 2.6.25-rc3 with 64k page size and SLUB_DEBUG_ON

[Christoph Lameter]

On Thu, 6 Mar 2008, Jens Osterkamp wrote:

> > You mention slub_debug=- makes the problem go away but can you narrow it 
> > down to a specific debug option described in Documentation/vm/slub.txt? 
> > In particular, does disabling slab poisoning or red zoning make the 
> > problem go away also?
> 
> I tried with slub_debug= F,Z,P and U. Only with F the problem is not there.

Ahh.. That looks like an alignment problem. The other options all add 
data to the object and thus misalign them if no alignment is 
specified.

Seems that powerpc expect an alignment but does not specify it for some data.

You can restrict the debug for certain slabs only. Try some of the arch 
specific slab caches first.

--
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: [BUG] in 2.6.25-rc3 with 64k page size and SLUB_DEBUG_ON

[Pekka Enberg]

Christoph Lameter wrote:
> Ahh.. That looks like an alignment problem. The other options all add 
> data to the object and thus misalign them if no alignment is 
> specified.

And causes buffer overrun? So the crazy preempt count 0x00056ef8 could a 
the lower part of an instruction pointer tracked by SLAB_STORE_USER? So 
does:

   gdb vmlinux
   (gdb) l *c000000000056ef8

translate into any meaningful kernel function?

			Pekka

--
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: [BUG] in 2.6.25-rc3 with 64k page size and SLUB_DEBUG_ON

[Jens Osterkamp]

[-- Attachment #1: Type: text/plain, Size: 654 bytes --]

On Thursday 06 March 2008, Pekka Enberg wrote:
> Christoph Lameter wrote:
> > Ahh.. That looks like an alignment problem. The other options all add 
> > data to the object and thus misalign them if no alignment is 
> > specified.
> 
> And causes buffer overrun? So the crazy preempt count 0x00056ef8 could a 
> the lower part of an instruction pointer tracked by SLAB_STORE_USER? So 
> does:
> 
>    gdb vmlinux
>    (gdb) l *c000000000056ef8
> 
> translate into any meaningful kernel function?

No, it is in the middle of copy_process. But I will try to identify what
we are actually looking at instead of prempt_count.

Gruß,
	Jens

[-- Attachment #2: This is a digitally signed message part. --]
[-- Type: application/pgp-signature, Size: 189 bytes --]

Re: [BUG] in 2.6.25-rc3 with 64k page size and SLUB_DEBUG_ON

[Pekka J Enberg]

On Fri, 7 Mar 2008, Jens Osterkamp wrote:
> > > Ahh.. That looks like an alignment problem. The other options all add 
> > > data to the object and thus misalign them if no alignment is 
> > > specified.
> > 
> > And causes buffer overrun? So the crazy preempt count 0x00056ef8 could a 
> > the lower part of an instruction pointer tracked by SLAB_STORE_USER? So 
> > does:
> > 
> >    gdb vmlinux
> >    (gdb) l *c000000000056ef8
> > 
> > translate into any meaningful kernel function?
> 
> No, it is in the middle of copy_process. But I will try to identify what
> we are actually looking at instead of prempt_count.

But that's expected. It's the call-site of a kmalloc() or 
kmem_cache_alloc() call that stomps on the memory where the 
->preempt_count of struct thread_info is. Is that anywhere near the 
dup_task_struct() call? I don't quite see how that could happen, however, 
alloc_thread_info() uses the page allocator to allocate memory for struct 
thread_info which is AFAICT 8 KB...

It might we worth it to look at other obviously wrong preempt_counts to 
see if you can figure out a pattern of callers stomping on the memory.

			Pekka

--
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: [BUG] in 2.6.25-rc3 with 64k page size and SLUB_DEBUG_ON

[Pekka J Enberg]

On Fri, 7 Mar 2008, Pekka J Enberg wrote:
> It might we worth it to look at other obviously wrong preempt_counts to 
> see if you can figure out a pattern of callers stomping on the memory.

And checking whether disabling debugging for the 'task_struct' cache makes 
the problem go away.

--
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: [BUG] in 2.6.25-rc3 with 64k page size and SLUB_DEBUG_ON

[Jens Osterkamp]

[-- Attachment #1: Type: text/plain, Size: 153 bytes --]


> And checking whether disabling debugging for the 'task_struct' cache makes 
> the problem go away.

No, unfortunately it doesnt.

Gruß,
	Jens

[-- Attachment #2: This is a digitally signed message part. --]
[-- Type: application/pgp-signature, Size: 189 bytes --]

Re: [BUG] in 2.6.25-rc3 with 64k page size and SLUB_DEBUG_ON

[Jens Osterkamp]

[-- Attachment #1: Type: text/plain, Size: 5172 bytes --]

> But that's expected. It's the call-site of a kmalloc() or 
> kmem_cache_alloc() call that stomps on the memory where the 
> ->preempt_count of struct thread_info is. Is that anywhere near the 
> dup_task_struct() call? I don't quite see how that could happen, however, 
> alloc_thread_info() uses the page allocator to allocate memory for struct 
> thread_info which is AFAICT 8 KB...

I compiled the kernel again with debug info and get the following info in the BUG :

BUG: scheduling while atomic: kthreadd/2/0x00056f08
Call Trace:
[c00000007e107b68] [c00000000000f140] .show_stack+0x70/0x1bc (unreliable)
[c00000007e107c18] [c000000000052d1c] .__schedule_bug+0x64/0x80
[c00000007e107ca8] [c00000000036fae4] .schedule+0xc4/0x6b0
[c00000007e107d98] [c000000000370330] .schedule_timeout+0x3c/0xe8
[c00000007e107e68] [c00000000036f88c] .wait_for_common+0x150/0x22c
[c00000007e107f28] [c000000000074878] .kthreadd+0x12c/0x1f0
[c00000007e107fd8] [c000000000024864] .kernel_thread+0x4c/0x68
c00000007e104000
------------[ cut here ]------------
kernel BUG at /home/auto/jens/kernels/linux-2.6.25-rc3/kernel/sched.c:4533!
cpu 0x0: Vector: 700 (Program Check) at [c00000007e107bc8]
    pc: c000000000051f9c: .sched_setscheduler+0x6c/0x49c
    lr: c000000000051f90: .sched_setscheduler+0x60/0x49c
    sp: c00000007e107e48
   msr: 9000000000029032
  current = 0xc00000003c0f08a0
  paca    = 0xc0000000004cf880
    pid   = 2, comm = kthreadd
kernel BUG at /home/auto/jens/kernels/linux-2.6.25-rc3/kernel/sched.c:4533!
enter ? for help
[c00000007e107f28] c0000000000748c0 .kthreadd+0x174/0x1f0
[c00000007e107fd8] c000000000024864 .kernel_thread+0x4c/0x68

gdb shows

(gdb) l *0xc000000000056f08
0xc000000000056f08 is in copy_process (/home/auto/jens/kernels/linux-2.6.25-rc3/include/linux/slub_def.h:209).
204                             struct kmem_cache *s = kmalloc_slab(size);
205
206                             if (!s)
207                                     return ZERO_SIZE_PTR;
208
209                             return kmem_cache_alloc(s, flags);
210                     }
211             }
212             return __kmalloc(size, flags);
213     }

which is in the middle of kmalloc.

registers look as follows

0:mon> r
R00 = 0000000000056f00   R16 = 4000000001400000
R01 = c00000007e107e48   R17 = c0000000003e0ec0
R02 = c000000000583820   R18 = c0000000003df8e0
R03 = 0000000000000015   R19 = 0000000000000000
R04 = 0000000000000001   R20 = 0000000000000000
R05 = 0000000000000001   R21 = c0000000004f53a8
R06 = 0000000000000000   R22 = c00000007e107f98
R07 = 0000000000000001   R23 = c000000000494ca0
R08 = 0000000000000001   R24 = 0000000001894a30
R09 = 0000000000000000   R25 = 0000000000000060
R10 = c0000000005fdac4   R26 = c0000000005f41c0
R11 = c0000000005fdac0   R27 = 0000000000000000
R12 = 0000000000000002   R28 = c00000003c142b20
R13 = c0000000004cf880   R29 = c00000007e104000
R14 = 0000000000000000   R30 = c000000000533f10
R15 = 0000000000000000   R31 = 0000000000000003
pc  = c000000000051f9c .sched_setscheduler+0x6c/0x49c
lr  = c000000000051f90 .sched_setscheduler+0x60/0x49c
msr = 9000000000029032   cr  = 24000028
ctr = c0000000000268ac   xer = 0000000000000000   trap =  700

So stack pointer seems to be at c00000007e104000

Dumping in xmon

c00000007e104000 cccccccccccccccc c00000007e104048  |............~.@H|
				  ^^^
				  looks like a pointer to thread_info ?

c00000007e104010 c000000000056f08 0000000000000000  |......o.........|
                 ^^^
		  link register to jump back to copy_process ?!?

        prepare_to_copy(orig);

        tsk = alloc_task_struct();
c000000000056f00:       7f b6 eb 78     mr      r22,r29
c000000000056f04:       48 07 45 65     bl      c0000000000cb468 <.kmem_cache_alloc>
c000000000056f08:       60 00 00 00     nop
        if (!tsk)
                return NULL;

        ti = alloc_thread_info(tsk);
        if (!ti) {
c000000000056f0c:       7c 7b 1b 79     mr.     r27,r3
c000000000056f10:       40 82 00 14     bne-    c000000000056f24 <.copy_process+0x104>
                free_task_struct(tsk);

c00000007e104020 00000000fffedb3f 0000000000000000  |.......?........|
c00000007e104030 0000000000000000 0000000000000000  |................|

Then next in memory comes thread_info :

c00000007e104040 5a5a5a5a5a5a5a5a c00000003c1408a0  |ZZZZZZZZ....<...|
			   	  ^^^
				  pointer to task_struct

c00000007e104050 c0000000004ede10 0000000000000000  |.....N..........|
		 ^^^		  ^^^ cpu and preempt count
	         default_exec_domain

c00000007e104060 c00000000054e9a8 0000000000000000  |.....T..........|
	  	 ^^^
		  thread_info continued...

c00000007e104070 0000000000000000 0000000000000000  |................|
c00000007e104080 0000000000008000 0000000000000000  |................|

So everything looks shifted/misaligned by 48 bytes, but why ?

> It might we worth it to look at other obviously wrong preempt_counts to 
> see if you can figure out a pattern of callers stomping on the memory.

How can I do that as I am quite early in boot ?

Gruß,
	Jens

[-- Attachment #2: This is a digitally signed message part. --]
[-- Type: application/pgp-signature, Size: 189 bytes --]

Re: [BUG] in 2.6.25-rc3 with 64k page size and SLUB_DEBUG_ON

[Christoph Lameter]

On Fri, 7 Mar 2008, Jens Osterkamp wrote:

> 0xc000000000056f08 is in copy_process (/home/auto/jens/kernels/linux-2.6.25-rc3/include/linux/slub_def.h:209).
> 204                             struct kmem_cache *s = kmalloc_slab(size);
> 205
> 206                             if (!s)
> 207                                     return ZERO_SIZE_PTR;
> 208
> 209                             return kmem_cache_alloc(s, flags);
> 210                     }
> 211             }
> 212             return __kmalloc(size, flags);
> 213     }
> 
> which is in the middle of kmalloc.

Its in the middle of inline code generated within the function that calls 
kmalloc. Its not in kmalloc per se.

Can you figure out what the value of size is here? I suspect we are doing 
a lookup here in kmalloc_caches with an invalid offset.

--
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: [BUG] in 2.6.25-rc3 with 64k page size and SLUB_DEBUG_ON

[Jens Osterkamp]

[-- Attachment #1: Type: text/plain, Size: 1007 bytes --]

On Friday 07 March 2008, Christoph Lameter wrote:
> On Fri, 7 Mar 2008, Jens Osterkamp wrote:
> 
> > 0xc000000000056f08 is in copy_process (/home/auto/jens/kernels/linux-2.6.25-rc3/include/linux/slub_def.h:209).
> > 204                             struct kmem_cache *s = kmalloc_slab(size);
> > 205
> > 206                             if (!s)
> > 207                                     return ZERO_SIZE_PTR;
> > 208
> > 209                             return kmem_cache_alloc(s, flags);
> > 210                     }
> > 211             }
> > 212             return __kmalloc(size, flags);
> > 213     }
> > 
> > which is in the middle of kmalloc.
> 
> Its in the middle of inline code generated within the function that calls 
> kmalloc. Its not in kmalloc per se.
> 
> Can you figure out what the value of size is here? I suspect we are doing 
> a lookup here in kmalloc_caches with an invalid offset.

I added a printk in kmalloc and the size seems to be 0x4000.

Gruß,
	Jens

[-- Attachment #2: This is a digitally signed message part. --]
[-- Type: application/pgp-signature, Size: 189 bytes --]

Re: [BUG] in 2.6.25-rc3 with 64k page size and SLUB_DEBUG_ON

[Christoph Lameter]

On Wed, 12 Mar 2008, Jens Osterkamp wrote:

> I added a printk in kmalloc and the size seems to be 0x4000.

Hmmmm... So kmalloc_index returns 14. This should all be fine.

However, with slub_debug the size of the 16k kmalloc object is 
actually a bit larger than 0x4000. The caller must not expect the object 
to be aligned to a 16kb boundary. Is that the case?

--
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: [BUG] in 2.6.25-rc3 with 64k page size and SLUB_DEBUG_ON

[Jens Osterkamp]

[-- Attachment #1: Type: text/plain, Size: 962 bytes --]

On Thursday 13 March 2008, Christoph Lameter wrote:
> On Wed, 12 Mar 2008, Jens Osterkamp wrote:
> 
> > I added a printk in kmalloc and the size seems to be 0x4000.
> 
> Hmmmm... So kmalloc_index returns 14. This should all be fine.
> 
> However, with slub_debug the size of the 16k kmalloc object is 
> actually a bit larger than 0x4000. The caller must not expect the object 
> to be aligned to a 16kb boundary. Is that the case?

Actually the caller expects exactly that. The kmalloc that I saw was coming
from alloc_thread_info in dup_task_struct. For 4k pages this maps to 
__get_free_pages whereas for 64k pages it maps to kmalloc.
The result of __get_free_pages seem to be aligned and kmalloc (with slub_debug)
of course not. That explains the 4k/64k difference and the crash I am seeing...
but I can't think of a reasonable fix right now as I don't understand the
reason for the difference in the allocation code (yet).

Gruß,
	Jens

[-- Attachment #2: This is a digitally signed message part. --]
[-- Type: application/pgp-signature, Size: 189 bytes --]

Re: [BUG] in 2.6.25-rc3 with 64k page size and SLUB_DEBUG_ON

[Christoph Lameter]

On Tue, 18 Mar 2008, Jens Osterkamp wrote:

> Actually the caller expects exactly that. The kmalloc that I saw was coming
> from alloc_thread_info in dup_task_struct. For 4k pages this maps to 
> __get_free_pages whereas for 64k pages it maps to kmalloc.
> The result of __get_free_pages seem to be aligned and kmalloc (with slub_debug)
> of course not. That explains the 4k/64k difference and the crash I am seeing...
> but I can't think of a reasonable fix right now as I don't understand the
> reason for the difference in the allocation code (yet).

One simple solution is to create a special slab and specify the alignment 
you want. The other is to use the page allocator which also gives you 
guaranteed alignment.

--
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: [BUG] in 2.6.25-rc3 with 64k page size and SLUB_DEBUG_ON

[Pekka Enberg]

On Tue, 18 Mar 2008, Jens Osterkamp wrote:
>  > Actually the caller expects exactly that. The kmalloc that I saw was coming
>  > from alloc_thread_info in dup_task_struct. For 4k pages this maps to
>  > __get_free_pages whereas for 64k pages it maps to kmalloc.
>  > The result of __get_free_pages seem to be aligned and kmalloc (with slub_debug)
>  > of course not. That explains the 4k/64k difference and the crash I am seeing...
>  > but I can't think of a reasonable fix right now as I don't understand the
>  > reason for the difference in the allocation code (yet).

On Tue, Mar 18, 2008 at 7:45 PM, Christoph Lameter <clameter@sgi.com> wrote:
>  One simple solution is to create a special slab and specify the alignment
>  you want. The other is to use the page allocator which also gives you
>  guaranteed alignment.

Btw, there are other architectures that use kmalloc() for
alloc_thread_info() which need to be fixed as well. Using the page
allocator directly is probably the best solution here.

--
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: [BUG] in 2.6.25-rc3 with 64k page size and SLUB_DEBUG_ON

[Jens Osterkamp]

[-- Attachment #1: Type: text/plain, Size: 406 bytes --]


> Ahh.. That looks like an alignment problem. The other options all add 
> data to the object and thus misalign them if no alignment is 
> specified.
> 
> Seems that powerpc expect an alignment but does not specify it for some data.
> 
> You can restrict the debug for certain slabs only. Try some of the arch 
> specific slab caches first.

Ok, I will do that. Thanks so far !

Gruß,
	Jens

[-- Attachment #2: This is a digitally signed message part. --]
[-- Type: application/pgp-signature, Size: 189 bytes --]

Re: [BUG] in 2.6.25-rc3 with 64k page size and SLUB_DEBUG_ON

[Jens Osterkamp]

[-- Attachment #1: Type: text/plain, Size: 538 bytes --]


> Ahh.. That looks like an alignment problem. The other options all add 
> data to the object and thus misalign them if no alignment is 
> specified.
> 
> Seems that powerpc expect an alignment but does not specify it for some data.
> 
> You can restrict the debug for certain slabs only. Try some of the arch 
> specific slab caches first.

I started with rtas_flash_cache, hugepte_cache, spufs_inode_cache, pgd_cache,
pmd_cache and around 20 other that are allocated beforce the crash with no
success yet.

Gruß,
	Jens

[-- Attachment #2: This is a digitally signed message part. --]
[-- Type: application/pgp-signature, Size: 189 bytes --]

Re: [BUG] in 2.6.25-rc3 with 64k page size and SLUB_DEBUG_ON

[Jens Osterkamp]

[-- Attachment #1: Type: text/plain, Size: 2336 bytes --]


> Then check 2.6.22 and specify the boot parameter "slub_debug". Make sure 
> to compile the kernel with slub support. Is there any way you could get 

With 2.6.22, slub on and slub_debug on the command line I get

PID hash table entries: 4096 (order: 12, 32768 bytes)
Console: colour dummy device 80x25
Dentry cache hash table entries: 262144 (order: 5, 2097152 bytes0005416c/2
Call Trace:
[c00000000ff87ce8] [c00000000000f2cc] .show_stack+0x68/0x1b0 (unreliable)
[c00000000ff87d88] [c000000000347d3c] .schedule+0xa4/0x8f0
[c00000000ff87e88] [c0000000003486f4] .wait_for_completion+0xd8/0x174
[c00000000ff87f48] [c000000000071770] .kthreadd+0x124/0x1b8
[c00000000ff87fd8] [c0000000000256f8] .kernel_thread+0x4c/0x68
BUG: scheduling while atomic: kthreadd/0x0005416c/2
Call Trace:
[c00000000ff87da8] [c00000000000f2cc] .show_stack+0x68/0x1b0 (unreliable)
[c00000000ff87e48] [c000000000347d3c] .schedule+0xa4/0x8f0
[c00000000ff87f48] [c0000000000716e0] .kthreadd+0x94/0x1b8
[c00000000ff87fd8] [c0000000000256f8] .kernel_thread+0x4c/0x68
BUG: scheduling while atomic: kthreadd/0x0005416c/2
Call Trace:
[c00000000ff87ce8] [c00000000000f2cc] .show_stack+0x68/0x1b0 (unreliable)
[c00000000ff87d88] [c000000000347d3c] .schedule+0xa4/0x8f0
[c00000000ff87e88] [c0000000003486f4] .wait_for_completion+0xd8/0x174
[c00000000ff87f48] [c000000000071770] .kthreadd+0x124/0x1b8
[c00000000ff87fd8] [c0000000000256f8] .kernel_thread+0x4c/0x68
BUG: scheduling while atomic: kthreadd/0x0183eeb8/4
Call Trace:
[c00000000ff9bf10] [c00000000000f2cc] .show_stack+0x68/0x1b0 (unreliable)
[c00000000ff9bfb0] [c000000000347d3c] .schedule+0xa4/0x8f0
[c00000000ff9c0b0] [c000000000071960] .kthread+0x40/0xc4
[c00000000ff9c140] [c0000000000256f8] .kernel_thread+0x4c/0x68
BUG: scheduling while atomic: kthreadd/0x0005416c/2
Call Trace:
[c00000000ff87da8] [c00000000000f2cc] .show_stack+0x68/0x1b0 (unreliable)
[c00000000ff87e48] [c000000000347d3c] .schedule+0xa4/0x8f0
[c00000000ff87f48] [c0000000000716e0] .kthreadd+0x94/0x1b8
[c00000000ff87fd8] [c0000000000256f8] .kernel_thread+0x4c/0x68

> us further information about the problem?

Sure, what do you need ?

The system is a Cell Blade with 2G memory, hence numa support enabled.
I built the 2.6.22 with cell_defconfig and manually selected SLUB.

Gruß,
	Jens

[-- Attachment #2: This is a digitally signed message part. --]
[-- Type: application/pgp-signature, Size: 189 bytes --]

Re: [BUG] in 2.6.25-rc3 with 64k page size and SLUB_DEBUG_ON

[Pekka Enberg]

Hi,

On Thu, Mar 6, 2008 at 3:47 PM, Jens Osterkamp <Jens.Osterkamp@gmx.de> wrote:
>  when booting 2.6.25-rc3 on powerpc64 with SLUB_DEBUG_ON and 64k page size, it drops into xmon
>  during boot with the following :
>
>  Console: colour dummy device 80x25
>  Dentry cache hash table entries: 262144 (order: 5, 2097152 bytes)
>  Inode-cache hash table entries: 131072 (order: 4, 1048576 bytes)
>  freeing bootmem node 0
>  freeing bootmem node 1
>  Memory: 2037184k/2097152k available (4864k kernel code, 59968k reserved, 768k data, 419k bss, 384k init)
>  SLUB: Genslabs=17, HWalign=128, Order=0-2, MinObjects=8, CPUs=4, Nodes=16
>  Mount-cache hash table entries: 4096
>  BUG: scheduling while atomic: kthreadd/2/0x00056ef8
>  Call Trace:
>  [c00000003c187b68] [c00000000000f140] .show_stack+0x70/0x1bc (unreliable)
>  [c00000003c187c18] [c000000000052d0c] .__schedule_bug+0x64/0x80
>  [c00000003c187ca8] [c00000000036fa84] .schedule+0xc4/0x6b0
>  [c00000003c187d98] [c0000000003702d0] .schedule_timeout+0x3c/0xe8
>  [c00000003c187e68] [c00000000036f82c] .wait_for_common+0x150/0x22c
>  [c00000003c187f28] [c000000000074868] .kthreadd+0x12c/0x1f0
>  [c00000003c187fd8] [c000000000024864] .kernel_thread+0x4c/0x68
>  ------------[ cut here ]------------
>  kernel BUG at /home/auto/jens/kernels/linux-2.6.25-rc3/kernel/sched.c:4532!
>  cpu 0x0: Vector: 700 (Program Check) at [c00000003c187bc8]
>     pc: c000000000051f8c: .sched_setscheduler+0x5c/0x48c
>     lr: c0000000000748b0: .kthreadd+0x174/0x1f0
>     sp: c00000003c187e48
>    msr: 9000000000029032
>   current = 0xc00000007e0808a0
>   paca    = 0xc0000000004cf880
>     pid   = 2, comm = kthreadd
>  kernel BUG at /home/auto/jens/kernels/linux-2.6.25-rc3/kernel/sched.c:4532!
>  enter ? for help
>  [c00000003c187f28] c0000000000748b0 .kthreadd+0x174/0x1f0
>  [c00000003c187fd8] c000000000024864 .kernel_thread+0x4c/0x68
>  0:mon>
>
>  In the code this corresponds to
>
>  int sched_setscheduler(struct task_struct *p, int policy,
>                        struct sched_param *param)
>  {
>         int retval, oldprio, oldpolicy = -1, on_rq, running;
>         unsigned long flags;
>         const struct sched_class *prev_class = p->sched_class;
>         struct rq *rq;
>
>         /* may grab non-irq protected spin_locks */
>         BUG_ON(in_interrupt());
>  recheck:
>         /* double check policy once rq lock held */
>         if (policy < 0)
>                 policy = oldpolicy = p->policy;
>         else if (policy != SCHED_FIFO && policy != SCHED_RR &&
>                         policy != SCHED_NORMAL && policy != SCHED_BATCH &&
>                         policy != SCHED_IDLE)
>                 return -EINVAL;
>
>  With slub_debug=- on the kernel command line, the problem is gone.
>  With 4k page size the problem also does not occur.
>
>  Any ideas on why this occurs and how to debug this further ?

There's no SLUB in the stack traces. Ingo, any suggestions how to debug this?

--
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: [BUG] in 2.6.25-rc3 with 64k page size and SLUB_DEBUG_ON

[Ingo Molnar]

* Pekka Enberg <penberg@cs.helsinki.fi> wrote:

> >  Mount-cache hash table entries: 4096
> >  BUG: scheduling while atomic: kthreadd/2/0x00056ef8
> >  Call Trace:
> >  [c00000003c187b68] [c00000000000f140] .show_stack+0x70/0x1bc (unreliable)
> >  [c00000003c187c18] [c000000000052d0c] .__schedule_bug+0x64/0x80
> >  [c00000003c187ca8] [c00000000036fa84] .schedule+0xc4/0x6b0
> >  [c00000003c187d98] [c0000000003702d0] .schedule_timeout+0x3c/0xe8
> >  [c00000003c187e68] [c00000000036f82c] .wait_for_common+0x150/0x22c
> >  [c00000003c187f28] [c000000000074868] .kthreadd+0x12c/0x1f0
> >  [c00000003c187fd8] [c000000000024864] .kernel_thread+0x4c/0x68
> >  ------------[ cut here ]------------
> >  kernel BUG at /home/auto/jens/kernels/linux-2.6.25-rc3/kernel/sched.c:4532!
> >  cpu 0x0: Vector: 700 (Program Check) at [c00000003c187bc8]
> >     pc: c000000000051f8c: .sched_setscheduler+0x5c/0x48c
> >     lr: c0000000000748b0: .kthreadd+0x174/0x1f0
> >     sp: c00000003c187e48
> >    msr: 9000000000029032
> >   current = 0xc00000007e0808a0
> >   paca    = 0xc0000000004cf880
> >     pid   = 2, comm = kthreadd
> >  kernel BUG at /home/auto/jens/kernels/linux-2.6.25-rc3/kernel/sched.c:4532!
> >  enter ? for help
> >  [c00000003c187f28] c0000000000748b0 .kthreadd+0x174/0x1f0
> >  [c00000003c187fd8] c000000000024864 .kernel_thread+0x4c/0x68
> >  0:mon>
> >
> >  In the code this corresponds to
> >
> >  int sched_setscheduler(struct task_struct *p, int policy,
> >                        struct sched_param *param)
> >  {
> >         int retval, oldprio, oldpolicy = -1, on_rq, running;
> >         unsigned long flags;
> >         const struct sched_class *prev_class = p->sched_class;
> >         struct rq *rq;
> >
> >         /* may grab non-irq protected spin_locks */
> >         BUG_ON(in_interrupt());
> >  recheck:
> >         /* double check policy once rq lock held */
> >         if (policy < 0)
> >                 policy = oldpolicy = p->policy;
> >         else if (policy != SCHED_FIFO && policy != SCHED_RR &&
> >                         policy != SCHED_NORMAL && policy != SCHED_BATCH &&
> >                         policy != SCHED_IDLE)
> >                 return -EINVAL;
> >
> >  With slub_debug=- on the kernel command line, the problem is gone.
> >  With 4k page size the problem also does not occur.
> >
> >  Any ideas on why this occurs and how to debug this further ?
> 
> There's no SLUB in the stack traces. Ingo, any suggestions how to debug this?

hm, no idea - is this powerpc? It seems to have hit a atomicity check 
due to:

> >  BUG: scheduling while atomic: kthreadd/2/0x00056ef8

preempt-count 0x00056ef8 is totally out of whack. Serious memory 
corruption.

	Ingo

--
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>