Porting linux to Stellaris Cortex-M3

Porting linux to Stellaris Cortex-M3

[Fernando Endo]

Hello everybody,

I'm currently porting linux to a Stellaris board from TI.
But I'm having some problems with the execution of the Busybox init program.

Some info:
- the toolchain is CodeSourcery lite edition
- I've followed the steps described by Catalin Marinas at
http://www.linux-arm.org/LinuxKernel/LinuxM3
- I'm using my own bootloader, based on the script at the site above
and on informations found on linux/Documents
- I've based the mach-stellaris implementation from realview and mps ones
- the timer, irqs and uart seems to work fine
- the system crashes after calling /init, which is linked with Busybox init
- BUG: scheduling while atomic: init/1/0xffff000a

Any idea?

Best regards,
Fernando Akira Endo

Porting linux to Stellaris Cortex-M3

[Maxin John]

Hi Fernando,

On Mon, Sep 26, 2011 at 11:19 PM, Fernando Endo
<fernando.endo@phiinnovations.com> wrote:
> Hello everybody,
>
> I'm currently porting linux to a Stellaris board from TI.
> But I'm having some problems with the execution of the Busybox init program.
>
> Some info:
> - the toolchain is CodeSourcery lite edition
> - I've followed the steps described by Catalin Marinas at
> http://www.linux-arm.org/LinuxKernel/LinuxM3
> - I'm using my own bootloader, based on the script at the site above
> and on informations found on linux/Documents
> - I've based the mach-stellaris implementation from realview and mps ones
> - the timer, irqs and uart seems to work fine
> - the system crashes after calling /init, which is linked with Busybox init
> - BUG: scheduling while atomic: init/1/0xffff000a

This is the code which corresponds to "scheduling while atomic" bug
(from "kernel/sched.c") :
-----
/*
 * Print scheduling while atomic bug:
 */
static noinline void __schedule_bug(struct task_struct *prev)
{
        struct pt_regs *regs = get_irq_regs();

        printk(KERN_ERR "BUG: scheduling while atomic: %s/%d/0x%08x\n",
                prev->comm, prev->pid, preempt_count());

        debug_show_held_locks(prev);
        print_modules();
        if (irqs_disabled())
                print_irqtrace_events(prev);

        if (regs)
                show_regs(regs);
        else
                dump_stack();
}
----

We hit this bug if we are scheduling when we should not be. ie : if we
call schedule() or sleep() from a driver while in an interrupt handler
or holding a spin-lock, that will trigger this bug. This is because of
a bug present in any of the kernel drivers.  Please share the detailed
logs.

Warm Regards,
Maxin B. John

Porting linux to Stellaris Cortex-M3

[Fernando Endo]

Oh sorry for sendig again, I forgot to include the lists


2011/9/27 Maxin John <arm.maxinbjohn@gmail.com>:
>
> We hit this bug if we are scheduling when we should not be. ie : if we
> call schedule() or sleep() from a driver while in an interrupt handler
> or holding a spin-lock, that will trigger this bug. This is because of
> a bug present in any of the kernel drivers.

Do we call schedule() or sleep() explicitly on a kernel driver, or are
there 'hidden' calls inside some function?
As I had to implement the basic drivers (clock, timer, irq and uart)
so far, I didn't call them explicitly.

>?Please share the detailed logs.

This is the log that I got with printascii bypassing printk:

<5>Linux version 2.6.33-arm1 (fernando at fernando-POS-MIG31AG) (gcc
version 4.5.2 (Sourcery G++ Lite 2011.03-41) ) #127 Tue Sep 27
09:14:21 BRT 2011
CPU: ARMv7-M Processor [412fc230] revision 0 (ARMv?(11)M)
CPU: VIPT nonaliasing data cache, VIPT nonaliasing instruction cache
Machine: Stellaris LM3S9B96
<7>On node 0 totalpages: 2048
<7>free_area_init_node: node 0, pgdat 600de1e0, node_mem_map 600f6000
<7> ?DMA zone: 16 pages used for memmap
<7> ?DMA zone: 0 pages reserved
<7> ?DMA zone: 2032 pages, LIFO batch:0
Built 1 zonelists in Zone order, mobility grouping off. ?Total pages: 2032
<5>Kernel command line: init=/bin/busybox console=ttyS mem=8M
<6>PID hash table entries: 32 (order: -5, 128 bytes)
<6>Dentry cache hash table entries: 1024 (order: 0, 4096 bytes)
<6>Inode-cache hash table entries: 1024 (order: 0, 4096 bytes)
<6>Memory: 8MB = 8MB total
<5>Memory: 7168k/7168k available, 1024k reserved, 0K highmem
<5>Virtual kernel memory layout:
? ?vector ?: 0x00000000 - 0x00001000 ? ( ? 4 kB)
? ?fixmap ?: 0xfff00000 - 0xfffe0000 ? ( 896 kB)
? ?vmalloc : 0x00000000 - 0xffffffff ? (4095 MB)
? ?lowmem ?: 0x60000000 - 0x60800000 ? ( ? 8 MB)
? ?modules : 0x60000000 - 0x60800000 ? ( ? 8 MB)
? ? ?.init : 0x60008000 - 0x6002f000 ? ( 156 kB)
? ? ?.text : 0x6002f000 - 0x600cb000 ? ( 624 kB)
? ? ?.data : 0x600d6000 - 0x600deb40 ? ( ?35 kB)
<6>Hierarchical RCU implementation.
<6>NR_IRQS:54
<6>console [ttyS0] enabled
<6>Calibrating delay loop... <c>3.82 BogoMIPS (lpj=19136)
Mount-cache hash table entries: 512
<6>Switching to clocksource timer3
<6>ttyS0 at MMIO 0x4000c000 (irq = 5) is a LM3S9B96 UARTx Port
<6>Freeing init memory: 156K
<3>BUG: scheduling while atomic: init/1/0xffff0003
[<60032b6d>] (unwind_backtrace+0x1/0x88) from [<600a1379>] (dump_stack+0xd/0x10)
[<600a1379>] (dump_stack+0xd/0x10) from [<60034ea5>] (__schedule_bug+0x35/0x40)
[<60034ea5>] (__schedule_bug+0x35/0x40) from [<600a17b1>] (schedule+0x2d1/0x2f4)
[<600a17b1>] (schedule+0x2d1/0x2f4) from [<6002f791>] (ret_slow_syscall+0x1/0xc)
<4>ptrace: can't handle thumb mode
<3>BUG: scheduling while atomic: init/1/0x60408008
[<60032b6d>] (unwind_backtrace+0x1/0x88) from [<600a1379>] (dump_stack+0xd/0x10)
[<600a1379>] (dump_stack+0xd/0x10) from [<60034ea5>] (__schedule_bug+0x35/0x40)
[<60034ea5>] (__schedule_bug+0x35/0x40) from [<600a17b1>] (schedule+0x2d1/0x2f4)
[<600a17b1>] (schedule+0x2d1/0x2f4) from [<6002f791>] (ret_slow_syscall+0x1/0xc)

Unhandled exception: IPSR = 00000003 LR = fffffff1
CPU: 0 ? ?Not tainted ?(2.6.33-arm1 #127)
PC is at account_user_time+0x4/0x60
LR is at account_process_tick+0x4d/0x58
pc : [<60038168>] ? ?lr : [<60038389>] ? ?psr: 01000223
sp : 60418038 ?ip : 000002cc ?fp : 00000000
r10: 01000000 ?r9 : 604d1f36 ?r8 : 00000013
r7 : 6041803c ?r6 : 068e7780 ?r5 : 00000001 ?r4 : ffafdad5
r3 : ffafdad5 ?r2 : 00000001 ?r1 : 00000001 ?r0 : ffafdad5

Att,
Fernando Akira Endo

Porting linux to Stellaris Cortex-M3

[Russell King - ARM Linux]

On Tue, Sep 27, 2011 at 09:54:18AM -0300, Fernando Endo wrote:
> This is the log that I got with printascii bypassing printk:
> 
> <5>Linux version 2.6.33-arm1 (fernando at fernando-POS-MIG31AG) (gcc
> version 4.5.2 (Sourcery G++ Lite 2011.03-41) ) #127 Tue Sep 27
> 09:14:21 BRT 2011
> CPU: ARMv7-M Processor [412fc230] revision 0 (ARMv?(11)M)
> CPU: VIPT nonaliasing data cache, VIPT nonaliasing instruction cache
> Machine: Stellaris LM3S9B96
> <7>On node 0 totalpages: 2048
> <7>free_area_init_node: node 0, pgdat 600de1e0, node_mem_map 600f6000
> <7> ?DMA zone: 16 pages used for memmap
> <7> ?DMA zone: 0 pages reserved
> <7> ?DMA zone: 2032 pages, LIFO batch:0
> Built 1 zonelists in Zone order, mobility grouping off. ?Total pages: 2032
> <5>Kernel command line: init=/bin/busybox console=ttyS mem=8M
> <6>PID hash table entries: 32 (order: -5, 128 bytes)
> <6>Dentry cache hash table entries: 1024 (order: 0, 4096 bytes)
> <6>Inode-cache hash table entries: 1024 (order: 0, 4096 bytes)
> <6>Memory: 8MB = 8MB total
> <5>Memory: 7168k/7168k available, 1024k reserved, 0K highmem
> <5>Virtual kernel memory layout:
> ? ?vector ?: 0x00000000 - 0x00001000 ? ( ? 4 kB)
> ? ?fixmap ?: 0xfff00000 - 0xfffe0000 ? ( 896 kB)
> ? ?vmalloc : 0x00000000 - 0xffffffff ? (4095 MB)
> ? ?lowmem ?: 0x60000000 - 0x60800000 ? ( ? 8 MB)
> ? ?modules : 0x60000000 - 0x60800000 ? ( ? 8 MB)
> ? ? ?.init : 0x60008000 - 0x6002f000 ? ( 156 kB)
> ? ? ?.text : 0x6002f000 - 0x600cb000 ? ( 624 kB)
> ? ? ?.data : 0x600d6000 - 0x600deb40 ? ( ?35 kB)
> <6>Hierarchical RCU implementation.
> <6>NR_IRQS:54
> <6>console [ttyS0] enabled
> <6>Calibrating delay loop... <c>3.82 BogoMIPS (lpj=19136)
> Mount-cache hash table entries: 512
> <6>Switching to clocksource timer3
> <6>ttyS0 at MMIO 0x4000c000 (irq = 5) is a LM3S9B96 UARTx Port
> <6>Freeing init memory: 156K
> <3>BUG: scheduling while atomic: init/1/0xffff0003
> [<60032b6d>] (unwind_backtrace+0x1/0x88) from [<600a1379>] (dump_stack+0xd/0x10)
> [<600a1379>] (dump_stack+0xd/0x10) from [<60034ea5>] (__schedule_bug+0x35/0x40)
> [<60034ea5>] (__schedule_bug+0x35/0x40) from [<600a17b1>] (schedule+0x2d1/0x2f4)
> [<600a17b1>] (schedule+0x2d1/0x2f4) from [<6002f791>] (ret_slow_syscall+0x1/0xc)

Hmm, this doesn't look good.  What this is showing is that it's the
call to schedule() in the code dealing with returning to userspace.
The preempt count shouldn't be this wrong here - it suggests that
something is returning with wrong preempt status.

The problem is it's not possible at this point to work out from the
information you've supplied whether it's a data abort, prefetch abort,
or SWI (SVC) call (and actually we don't have any tracking of that.)

If I had to guess I'd suggest that there was something fishy with
the IRQ handling - but without knowing what mods you've made to the
stock kernel, that's about as much speculation that I can give.

Porting linux to Stellaris Cortex-M3

[Fernando Endo]

2011/9/27 Russell King - ARM Linux <linux@arm.linux.org.uk>:
> On Tue, Sep 27, 2011 at 09:54:18AM -0300, Fernando Endo wrote:
>> This is the log that I got with printascii bypassing printk:
>>
>> <5>Linux version 2.6.33-arm1 (fernando at fernando-POS-MIG31AG) (gcc
>> version 4.5.2 (Sourcery G++ Lite 2011.03-41) ) #127 Tue Sep 27
>> 09:14:21 BRT 2011
>> CPU: ARMv7-M Processor [412fc230] revision 0 (ARMv?(11)M)
>> CPU: VIPT nonaliasing data cache, VIPT nonaliasing instruction cache
>> Machine: Stellaris LM3S9B96
>> <7>On node 0 totalpages: 2048
>> <7>free_area_init_node: node 0, pgdat 600de1e0, node_mem_map 600f6000
>> <7> ?DMA zone: 16 pages used for memmap
>> <7> ?DMA zone: 0 pages reserved
>> <7> ?DMA zone: 2032 pages, LIFO batch:0
>> Built 1 zonelists in Zone order, mobility grouping off. ?Total pages: 2032
>> <5>Kernel command line: init=/bin/busybox console=ttyS mem=8M
>> <6>PID hash table entries: 32 (order: -5, 128 bytes)
>> <6>Dentry cache hash table entries: 1024 (order: 0, 4096 bytes)
>> <6>Inode-cache hash table entries: 1024 (order: 0, 4096 bytes)
>> <6>Memory: 8MB = 8MB total
>> <5>Memory: 7168k/7168k available, 1024k reserved, 0K highmem
>> <5>Virtual kernel memory layout:
>> ? ?vector ?: 0x00000000 - 0x00001000 ? ( ? 4 kB)
>> ? ?fixmap ?: 0xfff00000 - 0xfffe0000 ? ( 896 kB)
>> ? ?vmalloc : 0x00000000 - 0xffffffff ? (4095 MB)
>> ? ?lowmem ?: 0x60000000 - 0x60800000 ? ( ? 8 MB)
>> ? ?modules : 0x60000000 - 0x60800000 ? ( ? 8 MB)
>> ? ? ?.init : 0x60008000 - 0x6002f000 ? ( 156 kB)
>> ? ? ?.text : 0x6002f000 - 0x600cb000 ? ( 624 kB)
>> ? ? ?.data : 0x600d6000 - 0x600deb40 ? ( ?35 kB)
>> <6>Hierarchical RCU implementation.
>> <6>NR_IRQS:54
>> <6>console [ttyS0] enabled
>> <6>Calibrating delay loop... <c>3.82 BogoMIPS (lpj=19136)
>> Mount-cache hash table entries: 512
>> <6>Switching to clocksource timer3
>> <6>ttyS0 at MMIO 0x4000c000 (irq = 5) is a LM3S9B96 UARTx Port
>> <6>Freeing init memory: 156K
>> <3>BUG: scheduling while atomic: init/1/0xffff0003
>> [<60032b6d>] (unwind_backtrace+0x1/0x88) from [<600a1379>] (dump_stack+0xd/0x10)
>> [<600a1379>] (dump_stack+0xd/0x10) from [<60034ea5>] (__schedule_bug+0x35/0x40)
>> [<60034ea5>] (__schedule_bug+0x35/0x40) from [<600a17b1>] (schedule+0x2d1/0x2f4)
>> [<600a17b1>] (schedule+0x2d1/0x2f4) from [<6002f791>] (ret_slow_syscall+0x1/0xc)
>
> Hmm, this doesn't look good. ?What this is showing is that it's the
> call to schedule() in the code dealing with returning to userspace.
> The preempt count shouldn't be this wrong here - it suggests that
> something is returning with wrong preempt status.
>
> The problem is it's not possible at this point to work out from the
> information you've supplied whether it's a data abort, prefetch abort,
> or SWI (SVC) call (and actually we don't have any tracking of that.)
>
> If I had to guess I'd suggest that there was something fishy with
> the IRQ handling - but without knowing what mods you've made to the
> stock kernel, that's about as much speculation that I can give.
>

Hello again, now I have good news!

Our port is working fine, we got the linux prompt today.
I don't know exactly the influence of the changes I've done, but just
to help people facing the same situation:

(... after crazy attempts)
1) I was using "for" instructions inside a /init test program to make
a led blink
2) I've replaced them by sleep(1), then things seemed to be much
better, no more crashes
3) As sleep(1) didn't take 1s, I fixed that
4) I've started debugging printf, as suggests busybox.net/FAQ.html#init
5) Finally, after finding and fixing a bug on my uart_isr, I was able
to see printf messages
   (I didn't know that the kernel may use uart interruptions after
switching to the user space)
6) The prompt came after creating init scripts read by Busybox

I think the first one was somehow messing the user space...

Att,
Fernando Akira Endo

Porting linux to Stellaris Cortex-M3

[Catalin Marinas]

On Mon, Sep 26, 2011 at 09:19:39PM +0100, Fernando Endo wrote:
> I'm currently porting linux to a Stellaris board from TI.
> But I'm having some problems with the execution of the Busybox init program.
> 
> Some info:
> - the toolchain is CodeSourcery lite edition
> - I've followed the steps described by Catalin Marinas at
> http://www.linux-arm.org/LinuxKernel/LinuxM3
> - I'm using my own bootloader, based on the script at the site above
> and on informations found on linux/Documents
> - I've based the mach-stellaris implementation from realview and mps ones
> - the timer, irqs and uart seems to work fine
> - the system crashes after calling /init, which is linked with Busybox init
> - BUG: scheduling while atomic: init/1/0xffff000a

Did you get any backtrace?

-- 
Catalin

Porting linux to Stellaris Cortex-M3

[Russell King - ARM Linux]

On Mon, Sep 26, 2011 at 05:19:39PM -0300, Fernando Endo wrote:
> - BUG: scheduling while atomic: init/1/0xffff000a

The last figure is the preempt count.  This is made up from:

 * - bits 0-7 are the preemption count (max preemption depth: 256)
 * - bits 8-15 are the softirq count (max # of softirqs: 256)
 * - bits 16-25 are the hardirq count (max # of nested hardirqs: 1024)
 * - bit 26 is the NMI_MASK
 * - bit 28 is the PREEMPT_ACTIVE flag

That seems to be saying that preemption has been disabled 10 times.
The upper 16-bits being all-ones seems to be rather insane - maybe
there's an additional __irq_exit() or irq_exit() call somewhere in
one of your code paths.

Porting linux to Stellaris Cortex-M3

[Catalin Marinas]

On Tue, Sep 27, 2011 at 10:29:06AM +0100, Russell King - ARM Linux wrote:
> On Mon, Sep 26, 2011 at 05:19:39PM -0300, Fernando Endo wrote:
> > - BUG: scheduling while atomic: init/1/0xffff000a
> 
> The last figure is the preempt count.  This is made up from:
> 
>  * - bits 0-7 are the preemption count (max preemption depth: 256)
>  * - bits 8-15 are the softirq count (max # of softirqs: 256)
>  * - bits 16-25 are the hardirq count (max # of nested hardirqs: 1024)
>  * - bit 26 is the NMI_MASK
>  * - bit 28 is the PREEMPT_ACTIVE flag
> 
> That seems to be saying that preemption has been disabled 10 times.
> The upper 16-bits being all-ones seems to be rather insane - maybe
> there's an additional __irq_exit() or irq_exit() call somewhere in
> one of your code paths.

Fernando, do you have CONFIG_PREEMPT enabled in your kernel? That's not
currently possible with my Cortex-M3 port (see the "Exception handling"
section in the M3 wiki page for an explanation).

-- 
Catalin

Porting linux to Stellaris Cortex-M3

[Fernando Endo]

2011/9/27 Catalin Marinas <catalin.marinas@arm.com>:
> On Tue, Sep 27, 2011 at 10:29:06AM +0100, Russell King - ARM Linux wrote:
>> On Mon, Sep 26, 2011 at 05:19:39PM -0300, Fernando Endo wrote:
>> > - BUG: scheduling while atomic: init/1/0xffff000a
>>
>> The last figure is the preempt count. ?This is made up from:
>>
>> ?* - bits 0-7 are the preemption count (max preemption depth: 256)
>> ?* - bits 8-15 are the softirq count (max # of softirqs: 256)
>> ?* - bits 16-25 are the hardirq count (max # of nested hardirqs: 1024)
>> ?* - bit 26 is the NMI_MASK
>> ?* - bit 28 is the PREEMPT_ACTIVE flag
>>
>> That seems to be saying that preemption has been disabled 10 times.
>> The upper 16-bits being all-ones seems to be rather insane - maybe
>> there's an additional __irq_exit() or irq_exit() call somewhere in
>> one of your code paths.
>
> Fernando, do you have CONFIG_PREEMPT enabled in your kernel? That's not
> currently possible with my Cortex-M3 port (see the "Exception handling"
> section in the M3 wiki page for an explanation).

I set CONFIG_PREEMPT_NONE after having this bug, my .config is
attached if you want to have a look
Thank you both for the advices, I'll take a look

Att,
Fernando Akira Endo
-------------- next part --------------
A non-text attachment was scrubbed...
Name: config
Type: application/octet-stream
Size: 4715 bytes
Desc: not available
URL: <http://lists.infradead.org/pipermail/linux-arm-kernel/attachments/20110927/1db6d40f/attachment.obj>