[uClinux-dev] migration issue scheduling while atomic

[Christian Gieseler]

Hi list,



I ran in another issue while updating our coldfire 5329 board from linux
2.6.25 to linux 3.6.



Romfs is mounted as root and then the system says BUG: scheduling while
atomic: swapper/0/0x00000000 and is finally crashing after some trace
output.

The system is configured to behave a preemptive system (low latency desktop)
but the system also crashes without preemption activated.

Does somebody know in which direction to look and how to tackle this issue?
What is the best way to track it down and fix this?

Let me know if there is more information needed than the boot up messages
below show.

Best Regards

Christian



dBUG> dn

Downloading Image 'image.bin' from 192.168.10.254

TFTP transfer completed

Read 4647940 bytes (9079 blocks)

dBUG> go 0x40020000

Linux version 3.6.11 (christian at cglinux.eks-engel.local) (gcc version 4.6.1
(Sourcery CodeBench Lite 2011.09-23) ) #72 PREEMPT Tue Mar 5 17:32:05 CET
2013





uClinux/COLDFIRE(m532x)

COLDFIRE port done by Greg Ungerer, gerg at snapgear.com

Flat model support (C) 1998,1999 Kenneth Albanowski, D. Jeff Dionne

Built 1 zonelists in Zone order, mobility grouping off. Total pages: 2024

Kernel command line: rootfstype=romfs console=tty1 console=ttyS0,115200
root=/dev/mtdblock0

PID hash table entries: 64 (order: -5, 256 bytes)

Dentry cache hash table entries: 2048 (order: 0, 8192 bytes)

Inode-cache hash table entries: 2048 (order: 0, 8192 bytes)

Memory available: 11392k/16256k RAM, (1736k kernel code, 631k data)

NR_IRQS:256

Calibrating delay loop... HZ=100

15.46 BogoMIPS (lpj=77312)

pid_max: default: 32768 minimum: 301

Mount-cache hash table entries: 1024

NET: Registered protocol family 16

bio: create slab <bio-0> at 0

Switching to clocksource tmr

NET: Registered protocol family 2

TCP established hash table entries: 1024 (order: 0, 8192 bytes)

TCP bind hash table entries: 1024 (order: -1, 4096 bytes)

TCP: Hash tables configured (established 1024 bind 1024)

TCP: reno registered

UDP hash table entries: 512 (order: 0, 8192 bytes)

UDP-Lite hash table entries: 512 (order: 0, 8192 bytes)

NET: Registered protocol family 1

jffs2: version 2.2. (NAND) C 2001-2006 Red Hat, Inc.

ROMFS MTD (C) 2007 Red Hat, Inc.

msgmni has been set to 22

io scheduler noop registered

io scheduler deadline registered

io scheduler cfq registered (default)

ColdFire internal UART serial driver

ttyS0 at MMIO 0xfc060000 (irq = 90) is a ColdFire UART

console [ttyS0] enabled

ttyS1 at MMIO 0xfc064000 (irq = 91) is a ColdFire UART

ttyS2 at MMIO 0xfc068000 (irq = 92) is a ColdFire UART

brd: module loaded

uclinux[mtd]: RAM probe address=0x4026fd40 size=0x22c000

Creating 1 MTD partitions on "RAM":

0x000000000000-0x00000022c000 : "ROMfs"

el5329 flash device: 1000000 at 0

el5329 flash: Found 1 x16 devices at 0x0 in 16-bit bank. Manufacturer ID
0x000001 Chip ID 0x002101

Amd/Fujitsu Extended Query Table at 0x0040

Amd/Fujitsu Extended Query version 1.3.

number of CFI chips: 1

Creating 7 MTD partitions on " el5329 flash":

0x000000000000-0x000000020000 : "vectors"

0x000000020000-0x000000040000 : "user_parameters"

0x000000040000-0x000000060000 : "system_parameters"

0x000000060000-0x000000100000 : "bootloader"

0x000000100000-0x000000700000 : "kernel_partition1"

0x000000700000-0x000000d00000 : "partition2"

0x000000d00000-0x000001000000 : "user_data"

BUG: scheduling while atomic: swapper/0/0x00000000

Modules linked in:

Call Trace: [<401cf054>] __schedule_bug+0x40/0x52

[<401d160e>] __schedule+0x33e/0x3c0

[<401d1bf0>] schedule+0x38/0x54

[<401d1d90>] schedule_preempt_disabled+0x18/0x24

[<401cdd62>] rest_init+0x72/0x82

[<401ced70>] printk+0x0/0x20

[<40252678>] start_kernel+0x2e8/0x2f4

[<400200da>] _exit+0x0/0x6



------------[ cut here ]------------

WARNING: at kernel/rcutiny.c:135 rcu_idle_exit_common.part.8+0x56/0x66()

Current pid: 45 comm: kworker/u:1 / Idle pid: 0 comm: swapper

Modules linked in:

Call Trace: [<400260f8>] warn_slowpath_common+0x50/0x6a

[<40026190>] warn_slowpath_fmt+0x2a/0x32

[<40060474>] rcu_idle_exit_common.part.8+0x56/0x66

[<40060474>] rcu_idle_exit_common.part.8+0x56/0x66

[<400607ea>] rcu_irq_enter+0x62/0x98

[<4002dbf4>] irq_enter+0xa/0x60

[<4002081c>] do_IRQ+0x1c/0x3c

[<400233ea>] inthandler+0x2a/0x34

[<40041e40>] exit_itimers+0x8/0x16e

[<4002b778>] do_exit+0x524/0x888

[<4002be26>] sys_exit+0x0/0x16

[<4003ac12>] wait_for_helper+0x0/0x96

[<4002be3c>] do_group_exit+0x0/0xf8

[<400232d8>] system_call+0x48/0x86

[<4003ac12>] wait_for_helper+0x0/0x96

[<40020a90>] kernel_thread+0x3a/0x42



---[ end trace 6786da2dfad7182c ]---

------------[ cut here ]------------

WARNING: at kernel/rcutiny.c:75
rcu_idle_enter_common.isra.9.part.10+0x6c/0x88()

Current pid: 45 comm: kworker/u:1 / Idle pid: 0 comm: swapper

Modules linked in:

Call Trace: [<400260f8>] warn_slowpath_common+0x50/0x6a

[<40026190>] warn_slowpath_fmt+0x2a/0x32

[<40060922>] rcu_idle_enter_common.isra.9.part.10+0x6c/0x88

[<40060922>] rcu_idle_enter_common.isra.9.part.10+0x6c/0x88

[<4006098c>] rcu_irq_exit+0x4e/0x98

[<4002dc7c>] irq_exit+0x32/0x60

[<4002082c>] do_IRQ+0x2c/0x3c

[<400233ea>] inthandler+0x2a/0x34

[<40041e40>] exit_itimers+0x8/0x16e

[<4002b778>] do_exit+0x524/0x888

[<4002be26>] sys_exit+0x0/0x16

[<4003ac12>] wait_for_helper+0x0/0x96

[<4002be3c>] do_group_exit+0x0/0xf8

[<400232d8>] system_call+0x48/0x86

[<4003ac12>] wait_for_helper+0x0/0x96

[<40020a90>] kernel_thread+0x3a/0x42



---[ end trace 6786da2dfad7182d ]---

libphy: fec_enet_mii_bus: probed

TCP: cubic registered

NET: Registered protocol family 17

Name=/dev/root, fs=romfs, flags=32769, data=0

VFS: Mounted root (romfs filesystem) readonly on device 31:0.

Freeing unused kernel memory: 64k freed (0x40252000 - 0x40260000)

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mailman.uclinux.org/pipermail/uclinux-dev/attachments/20130305/c3ec7b52/attachment.html>

[Luis Alves]

Hi,

With preemption disabled, you shouldn't see that message.
In your current kernel config, under "Kernel hacking" what is the
state of the "Sleep inside atomic section checking" option?

Regards,
Luis


On Tue, Mar 5, 2013 at 5:00 PM, Christian Gieseler

Post by Christian Gieseler
Hi list,
I ran in another issue while updating our coldfire 5329 board from linux
2.6.25 to linux 3.6.
Romfs is mounted as root and then the system says BUG: scheduling while
atomic: swapper/0/0x00000000 and is finally crashing after some trace
output.
The system is configured to behave a preemptive system (low latency desktop)
but the system also crashes without preemption activated.
Does somebody know in which direction to look and how to tackle this issue?
What is the best way to track it down and fix this?
Let me know if there is more information needed than the boot up messages
below show.
Best Regards
Christian
dBUG> dn
Downloading Image 'image.bin' from 192.168.10.254
TFTP transfer completed
Read 4647940 bytes (9079 blocks)
dBUG> go 0x40020000
Linux version 3.6.11 (christian at cglinux.eks-engel.local) (gcc version 4.6.1
(Sourcery CodeBench Lite 2011.09-23) ) #72 PREEMPT Tue Mar 5 17:32:05 CET
2013
uClinux/COLDFIRE(m532x)
COLDFIRE port done by Greg Ungerer, gerg at snapgear.com
Flat model support (C) 1998,1999 Kenneth Albanowski, D. Jeff Dionne
Built 1 zonelists in Zone order, mobility grouping off. Total pages: 2024
Kernel command line: rootfstype=romfs console=tty1 console=ttyS0,115200
root=/dev/mtdblock0
PID hash table entries: 64 (order: -5, 256 bytes)
Dentry cache hash table entries: 2048 (order: 0, 8192 bytes)
Inode-cache hash table entries: 2048 (order: 0, 8192 bytes)
Memory available: 11392k/16256k RAM, (1736k kernel code, 631k data)
NR_IRQS:256
Calibrating delay loop... HZ=100
15.46 BogoMIPS (lpj=77312)
pid_max: default: 32768 minimum: 301
Mount-cache hash table entries: 1024
NET: Registered protocol family 16
bio: create slab <bio-0> at 0
Switching to clocksource tmr
NET: Registered protocol family 2
TCP established hash table entries: 1024 (order: 0, 8192 bytes)
TCP bind hash table entries: 1024 (order: -1, 4096 bytes)
TCP: Hash tables configured (established 1024 bind 1024)
TCP: reno registered
UDP hash table entries: 512 (order: 0, 8192 bytes)
UDP-Lite hash table entries: 512 (order: 0, 8192 bytes)
NET: Registered protocol family 1
jffs2: version 2.2. (NAND) ? 2001-2006 Red Hat, Inc.
ROMFS MTD (C) 2007 Red Hat, Inc.
msgmni has been set to 22
io scheduler noop registered
io scheduler deadline registered
io scheduler cfq registered (default)
ColdFire internal UART serial driver
ttyS0 at MMIO 0xfc060000 (irq = 90) is a ColdFire UART
console [ttyS0] enabled
ttyS1 at MMIO 0xfc064000 (irq = 91) is a ColdFire UART
ttyS2 at MMIO 0xfc068000 (irq = 92) is a ColdFire UART
brd: module loaded
uclinux[mtd]: RAM probe address=0x4026fd40 size=0x22c000
0x000000000000-0x00000022c000 : "ROMfs"
el5329 flash device: 1000000 at 0
el5329 flash: Found 1 x16 devices at 0x0 in 16-bit bank. Manufacturer ID
0x000001 Chip ID 0x002101
Amd/Fujitsu Extended Query Table at 0x0040
Amd/Fujitsu Extended Query version 1.3.
number of CFI chips: 1
0x000000000000-0x000000020000 : "vectors"
0x000000020000-0x000000040000 : "user_parameters"
0x000000040000-0x000000060000 : "system_parameters"
0x000000060000-0x000000100000 : "bootloader"
0x000000100000-0x000000700000 : "kernel_partition1"
0x000000700000-0x000000d00000 : "partition2"
0x000000d00000-0x000001000000 : "user_data"
BUG: scheduling while atomic: swapper/0/0x00000000
Call Trace: [<401cf054>] __schedule_bug+0x40/0x52
[<401d160e>] __schedule+0x33e/0x3c0
[<401d1bf0>] schedule+0x38/0x54
[<401d1d90>] schedule_preempt_disabled+0x18/0x24
[<401cdd62>] rest_init+0x72/0x82
[<401ced70>] printk+0x0/0x20
[<40252678>] start_kernel+0x2e8/0x2f4
[<400200da>] _exit+0x0/0x6
------------[ cut here ]------------
WARNING: at kernel/rcutiny.c:135 rcu_idle_exit_common.part.8+0x56/0x66()
Current pid: 45 comm: kworker/u:1 / Idle pid: 0 comm: swapper
Call Trace: [<400260f8>] warn_slowpath_common+0x50/0x6a
[<40026190>] warn_slowpath_fmt+0x2a/0x32
[<40060474>] rcu_idle_exit_common.part.8+0x56/0x66
[<40060474>] rcu_idle_exit_common.part.8+0x56/0x66
[<400607ea>] rcu_irq_enter+0x62/0x98
[<4002dbf4>] irq_enter+0xa/0x60
[<4002081c>] do_IRQ+0x1c/0x3c
[<400233ea>] inthandler+0x2a/0x34
[<40041e40>] exit_itimers+0x8/0x16e
[<4002b778>] do_exit+0x524/0x888
[<4002be26>] sys_exit+0x0/0x16
[<4003ac12>] wait_for_helper+0x0/0x96
[<4002be3c>] do_group_exit+0x0/0xf8
[<400232d8>] system_call+0x48/0x86
[<4003ac12>] wait_for_helper+0x0/0x96
[<40020a90>] kernel_thread+0x3a/0x42
---[ end trace 6786da2dfad7182c ]---
------------[ cut here ]------------
WARNING: at kernel/rcutiny.c:75
rcu_idle_enter_common.isra.9.part.10+0x6c/0x88()
Current pid: 45 comm: kworker/u:1 / Idle pid: 0 comm: swapper
Call Trace: [<400260f8>] warn_slowpath_common+0x50/0x6a
[<40026190>] warn_slowpath_fmt+0x2a/0x32
[<40060922>] rcu_idle_enter_common.isra.9.part.10+0x6c/0x88
[<40060922>] rcu_idle_enter_common.isra.9.part.10+0x6c/0x88
[<4006098c>] rcu_irq_exit+0x4e/0x98
[<4002dc7c>] irq_exit+0x32/0x60
[<4002082c>] do_IRQ+0x2c/0x3c
[<400233ea>] inthandler+0x2a/0x34
[<40041e40>] exit_itimers+0x8/0x16e
[<4002b778>] do_exit+0x524/0x888
[<4002be26>] sys_exit+0x0/0x16
[<4003ac12>] wait_for_helper+0x0/0x96
[<4002be3c>] do_group_exit+0x0/0xf8
[<400232d8>] system_call+0x48/0x86
[<4003ac12>] wait_for_helper+0x0/0x96
[<40020a90>] kernel_thread+0x3a/0x42
---[ end trace 6786da2dfad7182d ]---
libphy: fec_enet_mii_bus: probed
TCP: cubic registered
NET: Registered protocol family 17
Name=/dev/root, fs=romfs, flags=32769, data=0
VFS: Mounted root (romfs filesystem) readonly on device 31:0.
Freeing unused kernel memory: 64k freed (0x40252000 - 0x40260000)
_______________________________________________
uClinux-dev mailing list
uClinux-dev at uclinux.org
http://mailman.uclinux.org/mailman/listinfo/uclinux-dev
This message was resent by uclinux-dev at uclinux.org
http://mailman.uclinux.org/mailman/options/uclinux-dev

[Christian Gieseler]

Hi Luis,

Yes you are right i was generalizing too much. With preemption disabled The
Boot Trace with preemption disabled does not show the scheduling while
atomic, but shows a lot of other output with "*** ILLEGAL INSTRUCTION ***
FORMAT=4" and kernel panic in the end.

The "Sleep inside atomic section checking" option was disabled. If it is
enabled it gives a slightly longer trace (see below). But still I am not
really sure how to tackle this. As we need preemption in the end it seems
better to me to debug with preemption enabled. Or is it easier to get the
kernel running first switch on preemption afterwards to separate possible
issues?

Regards
Christian

Bootup with "Sleep inside atomic section checking" enabled:

BUG: scheduling while atomic: swapper/0/0x00000000
Modules linked in:
Call Trace: [<401d04b4>] __schedule_bug+0x40/0x52
[<401d2b0c>] __schedule+0x33e/0x3c0
[<401d3104>] schedule+0x38/0x54
[<401d32a4>] schedule_preempt_disabled+0x18/0x24
[<401cf1c2>] rest_init+0x72/0x82
[<401d01d0>] printk+0x0/0x20
[<40252678>] start_kernel+0x2e8/0x2f4
[<400200da>] _exit+0x0/0x6

------------[ cut here ]------------
WARNING: at kernel/rcutiny.c:135 rcu_idle_exit_common.part.7+0x56/0x66()
Current pid: 45 comm: kworker/u:1 / Idle pid: 0 comm: swapper
Modules linked in:
Call Trace: [<4002610c>] warn_slowpath_common+0x50/0x6a
[<4004665a>] hrtimer_try_to_cancel+0x0/0xbc
[<400261a4>] warn_slowpath_fmt+0x2a/0x32
[<400606be>] rcu_idle_exit_common.part.7+0x56/0x66
[<400606be>] rcu_idle_exit_common.part.7+0x56/0x66
[<40060a34>] rcu_irq_enter+0x62/0x98
[<4002dc52>] irq_enter+0xa/0x60
[<4002081c>] do_IRQ+0x1c/0x3c
[<400233ea>] inthandler+0x2a/0x34
[<4004665a>] hrtimer_try_to_cancel+0x0/0xbc
[<40046668>] hrtimer_try_to_cancel+0xe/0xbc
[<4004672a>] hrtimer_cancel+0x14/0x30
[<4002b79a>] do_exit+0x51a/0x888
[<4002be52>] sys_exit+0x0/0x16
[<4003ac72>] wait_for_helper+0x0/0x96
[<4002be68>] do_group_exit+0x0/0xf8
[<400232d8>] system_call+0x48/0x86
[<4003ac72>] wait_for_helper+0x0/0x96
[<40020a90>] kernel_thread+0x3a/0x42

---[ end trace d05fe4c5ce0089d4 ]---
------------[ cut here ]------------
WARNING: at kernel/rcutiny.c:75
rcu_idle_enter_common.isra.8.part.9+0x6c/0x88()
Current pid: 45 comm: kworker/u:1 / Idle pid: 0 comm: swapper
Modules linked in:
Call Trace: [<4002610c>] warn_slowpath_common+0x50/0x6a
[<400261a4>] warn_slowpath_fmt+0x2a/0x32
[<40060b6c>] rcu_idle_enter_common.isra.8.part.9+0x6c/0x88
[<40060b6c>] rcu_idle_enter_common.isra.8.part.9+0x6c/0x88
[<4004665a>] hrtimer_try_to_cancel+0x0/0xbc
[<40060bd6>] rcu_irq_exit+0x4e/0x98
[<4002dcda>] irq_exit+0x32/0x60
[<4002082c>] do_IRQ+0x2c/0x3c
[<400233ea>] inthandler+0x2a/0x34
[<4004665a>] hrtimer_try_to_cancel+0x0/0xbc
[<40046668>] hrtimer_try_to_cancel+0xe/0xbc
[<4004672a>] hrtimer_cancel+0x14/0x30
[<4002b79a>] do_exit+0x51a/0x888
[<4002be52>] sys_exit+0x0/0x16
[<4003ac72>] wait_for_helper+0x0/0x96
[<4002be68>] do_group_exit+0x0/0xf8
[<400232d8>] system_call+0x48/0x86
[<4003ac72>] wait_for_helper+0x0/0x96
[<40020a90>] kernel_thread+0x3a/0x42

---[ end trace d05fe4c5ce0089d5 ]---
libphy: fec_enet_mii_bus: probed
TCP: cubic registered
NET: Registered protocol family 17
VFS: Mounted root (romfs filesystem) readonly on device 31:0.
Freeing unused kernel memory: 64k freed (0x40252000 - 0x40260000)



-----Original Message-----
From: uclinux-dev-bounces at uclinux.org
[mailto:uclinux-dev-bounces at uclinux.org] On Behalf Of Luis Alves
Sent: Tuesday, March 05, 2013 6:19 PM
To: uClinux development list
Subject: Re: [uClinux-dev] migration issue scheduling while atomic

Hi,

With preemption disabled, you shouldn't see that message.
In your current kernel config, under "Kernel hacking" what is the state of
the "Sleep inside atomic section checking" option?

Regards,
Luis


On Tue, Mar 5, 2013 at 5:00 PM, Christian Gieseler

Post by Christian Gieseler
Hi list,
I ran in another issue while updating our coldfire 5329 board from linux
2.6.25 to linux 3.6.
Romfs is mounted as root and then the system says BUG: scheduling while
atomic: swapper/0/0x00000000 and is finally crashing after some trace
output.
The system is configured to behave a preemptive system (low latency
desktop) but the system also crashes without preemption activated.
Does somebody know in which direction to look and how to tackle this issue?
What is the best way to track it down and fix this?
Let me know if there is more information needed than the boot up
messages below show.
Best Regards
Christian
dBUG> dn
Downloading Image 'image.bin' from 192.168.10.254
TFTP transfer completed
Read 4647940 bytes (9079 blocks)
dBUG> go 0x40020000
Linux version 3.6.11 (christian at cglinux.eks-engel.local) (gcc version
4.6.1 (Sourcery CodeBench Lite 2011.09-23) ) #72 PREEMPT Tue Mar 5
17:32:05 CET
2013
uClinux/COLDFIRE(m532x)
COLDFIRE port done by Greg Ungerer, gerg at snapgear.com
Flat model support (C) 1998,1999 Kenneth Albanowski, D. Jeff Dionne
Built 1 zonelists in Zone order, mobility grouping off. Total pages: 2024
Kernel command line: rootfstype=romfs console=tty1
console=ttyS0,115200
root=/dev/mtdblock0
PID hash table entries: 64 (order: -5, 256 bytes)
Dentry cache hash table entries: 2048 (order: 0, 8192 bytes)
Inode-cache hash table entries: 2048 (order: 0, 8192 bytes)
Memory available: 11392k/16256k RAM, (1736k kernel code, 631k data)
NR_IRQS:256
Calibrating delay loop... HZ=100
15.46 BogoMIPS (lpj=77312)
pid_max: default: 32768 minimum: 301
Mount-cache hash table entries: 1024
NET: Registered protocol family 16
bio: create slab <bio-0> at 0
Switching to clocksource tmr
NET: Registered protocol family 2
TCP established hash table entries: 1024 (order: 0, 8192 bytes)
TCP bind hash table entries: 1024 (order: -1, 4096 bytes)
TCP: Hash tables configured (established 1024 bind 1024)
TCP: reno registered
UDP hash table entries: 512 (order: 0, 8192 bytes)
UDP-Lite hash table entries: 512 (order: 0, 8192 bytes)
NET: Registered protocol family 1
jffs2: version 2.2. (NAND) C 2001-2006 Red Hat, Inc.
ROMFS MTD (C) 2007 Red Hat, Inc.
msgmni has been set to 22
io scheduler noop registered
io scheduler deadline registered
io scheduler cfq registered (default)
ColdFire internal UART serial driver
ttyS0 at MMIO 0xfc060000 (irq = 90) is a ColdFire UART
console [ttyS0] enabled
ttyS1 at MMIO 0xfc064000 (irq = 91) is a ColdFire UART
ttyS2 at MMIO 0xfc068000 (irq = 92) is a ColdFire UART
brd: module loaded
uclinux[mtd]: RAM probe address=0x4026fd40 size=0x22c000
0x000000000000-0x00000022c000 : "ROMfs"
el5329 flash device: 1000000 at 0
el5329 flash: Found 1 x16 devices at 0x0 in 16-bit bank. Manufacturer ID
0x000001 Chip ID 0x002101
Amd/Fujitsu Extended Query Table at 0x0040
Amd/Fujitsu Extended Query version 1.3.
number of CFI chips: 1
0x000000000000-0x000000020000 : "vectors"
0x000000020000-0x000000040000 : "user_parameters"
0x000000040000-0x000000060000 : "system_parameters"
0x000000060000-0x000000100000 : "bootloader"
0x000000100000-0x000000700000 : "kernel_partition1"
0x000000700000-0x000000d00000 : "partition2"
0x000000d00000-0x000001000000 : "user_data"
BUG: scheduling while atomic: swapper/0/0x00000000
Call Trace: [<401cf054>] __schedule_bug+0x40/0x52
[<401d160e>] __schedule+0x33e/0x3c0
[<401d1bf0>] schedule+0x38/0x54
[<401d1d90>] schedule_preempt_disabled+0x18/0x24
[<401cdd62>] rest_init+0x72/0x82
[<401ced70>] printk+0x0/0x20
[<40252678>] start_kernel+0x2e8/0x2f4
[<400200da>] _exit+0x0/0x6
------------[ cut here ]------------
WARNING: at kernel/rcutiny.c:135
rcu_idle_exit_common.part.8+0x56/0x66()
Current pid: 45 comm: kworker/u:1 / Idle pid: 0 comm: swapper
Call Trace: [<400260f8>] warn_slowpath_common+0x50/0x6a
[<40026190>] warn_slowpath_fmt+0x2a/0x32
[<40060474>] rcu_idle_exit_common.part.8+0x56/0x66
[<40060474>] rcu_idle_exit_common.part.8+0x56/0x66
[<400607ea>] rcu_irq_enter+0x62/0x98
[<4002dbf4>] irq_enter+0xa/0x60
[<4002081c>] do_IRQ+0x1c/0x3c
[<400233ea>] inthandler+0x2a/0x34
[<40041e40>] exit_itimers+0x8/0x16e
[<4002b778>] do_exit+0x524/0x888
[<4002be26>] sys_exit+0x0/0x16
[<4003ac12>] wait_for_helper+0x0/0x96
[<4002be3c>] do_group_exit+0x0/0xf8
[<400232d8>] system_call+0x48/0x86
[<4003ac12>] wait_for_helper+0x0/0x96
[<40020a90>] kernel_thread+0x3a/0x42
---[ end trace 6786da2dfad7182c ]---
------------[ cut here ]------------
WARNING: at kernel/rcutiny.c:75
rcu_idle_enter_common.isra.9.part.10+0x6c/0x88()
Current pid: 45 comm: kworker/u:1 / Idle pid: 0 comm: swapper
Call Trace: [<400260f8>] warn_slowpath_common+0x50/0x6a
[<40026190>] warn_slowpath_fmt+0x2a/0x32
[<40060922>] rcu_idle_enter_common.isra.9.part.10+0x6c/0x88
[<40060922>] rcu_idle_enter_common.isra.9.part.10+0x6c/0x88
[<4006098c>] rcu_irq_exit+0x4e/0x98
[<4002dc7c>] irq_exit+0x32/0x60
[<4002082c>] do_IRQ+0x2c/0x3c
[<400233ea>] inthandler+0x2a/0x34
[<40041e40>] exit_itimers+0x8/0x16e
[<4002b778>] do_exit+0x524/0x888
[<4002be26>] sys_exit+0x0/0x16
[<4003ac12>] wait_for_helper+0x0/0x96
[<4002be3c>] do_group_exit+0x0/0xf8
[<400232d8>] system_call+0x48/0x86
[<4003ac12>] wait_for_helper+0x0/0x96
[<40020a90>] kernel_thread+0x3a/0x42
---[ end trace 6786da2dfad7182d ]---
libphy: fec_enet_mii_bus: probed
TCP: cubic registered
NET: Registered protocol family 17
Name=/dev/root, fs=romfs, flags=32769, data=0
VFS: Mounted root (romfs filesystem) readonly on device 31:0.
Freeing unused kernel memory: 64k freed (0x40252000 - 0x40260000)
_______________________________________________
uClinux-dev mailing list
uClinux-dev at uclinux.org
http://mailman.uclinux.org/mailman/listinfo/uclinux-dev
http://mailman.uclinux.org/mailman/options/uclinux-dev

_______________________________________________
uClinux-dev mailing list
uClinux-dev at uclinux.org
http://mailman.uclinux.org/mailman/listinfo/uclinux-dev
This message was resent by uclinux-dev at uclinux.org To unsubscribe see:
http://mailman.uclinux.org/mailman/options/uclinux-dev

[Luis Alves]

Hi,

I'm not an expert on this but I've lost some time not long ago trying
to understand what was causing that bug message "scheduling while
atomic".

My 'short' story:

I was trying to trace an issue that I had on my board, so I've enabled
the check for 'sleep inside atomic' and I got the spam of 'scheduling
while atomic' messages.

Without thinking much, I remembered that the gcc toolchain I use
doesn't have atomic builtins (it has only been added in gcc-4.7.x for
the m68k)
so I switched back to the old gcc-4.2.4 toolchain that uses the old
m68k ABI (later I realized that kernel has its own code for atomic
access), but to my surprise the 'scheduling while atomic' spam was
fixed with gcc-4.2.4.

After loosing a lot of time comparing the asm from kernel generated
with gcc-4.2.4 and gcc-4.5.1, I found nothing that explained the spam.
I still don't know what the hell is going on with both gcc's (but is
definitively related to it).
Maybe something related to memory barriers has changed (or broken ?).


Anyway... Digging in the kernel sources and reading some stuff, I
concluded that "Sleep inside atomic section checking" doesn't make
sense since the m68k arch doesn't support SMP or preemption.

From what I could understand this check looks for scheduling inside

spinlocks (that should disable preemption).
In my case, since I don't have preemption enabled in the first place,
then spinlocks do absolutely nothing (the ones that don't disable
irqs).

I never bothered again with this, since my kernel works fine and the
issue that made me enabled this stupid check, is fixed now.

I'm using the latest kernel from Greg m68knommu git (3.8 last time I
checked) and my board is based on a dusty (and the father of all)
68000 cpu, not coldfire.


TLDR:
Searching in the arch/m68k tree I did find some traces of preemption
code for coldfire but it seems to be incomplete.
Googling also gives me some threads that mention the 'unfinished'
preemption support for coldfires.


Regards,
Luis


On Wed, Mar 6, 2013 at 8:18 AM, Christian Gieseler

Hi Luis,
Yes you are right i was generalizing too much. With preemption disabled The
Boot Trace with preemption disabled does not show the scheduling while
atomic, but shows a lot of other output with "*** ILLEGAL INSTRUCTION ***
FORMAT=4" and kernel panic in the end.
The "Sleep inside atomic section checking" option was disabled. If it is
enabled it gives a slightly longer trace (see below). But still I am not
really sure how to tackle this. As we need preemption in the end it seems
better to me to debug with preemption enabled. Or is it easier to get the
kernel running first switch on preemption afterwards to separate possible
issues?
Regards
Christian
BUG: scheduling while atomic: swapper/0/0x00000000
Call Trace: [<401d04b4>] __schedule_bug+0x40/0x52
[<401d2b0c>] __schedule+0x33e/0x3c0
[<401d3104>] schedule+0x38/0x54
[<401d32a4>] schedule_preempt_disabled+0x18/0x24
[<401cf1c2>] rest_init+0x72/0x82
[<401d01d0>] printk+0x0/0x20
[<40252678>] start_kernel+0x2e8/0x2f4
[<400200da>] _exit+0x0/0x6
------------[ cut here ]------------
WARNING: at kernel/rcutiny.c:135 rcu_idle_exit_common.part.7+0x56/0x66()
Current pid: 45 comm: kworker/u:1 / Idle pid: 0 comm: swapper
Call Trace: [<4002610c>] warn_slowpath_common+0x50/0x6a
[<4004665a>] hrtimer_try_to_cancel+0x0/0xbc
[<400261a4>] warn_slowpath_fmt+0x2a/0x32
[<400606be>] rcu_idle_exit_common.part.7+0x56/0x66
[<400606be>] rcu_idle_exit_common.part.7+0x56/0x66
[<40060a34>] rcu_irq_enter+0x62/0x98
[<4002dc52>] irq_enter+0xa/0x60
[<4002081c>] do_IRQ+0x1c/0x3c
[<400233ea>] inthandler+0x2a/0x34
[<4004665a>] hrtimer_try_to_cancel+0x0/0xbc
[<40046668>] hrtimer_try_to_cancel+0xe/0xbc
[<4004672a>] hrtimer_cancel+0x14/0x30
[<4002b79a>] do_exit+0x51a/0x888
[<4002be52>] sys_exit+0x0/0x16
[<4003ac72>] wait_for_helper+0x0/0x96
[<4002be68>] do_group_exit+0x0/0xf8
[<400232d8>] system_call+0x48/0x86
[<4003ac72>] wait_for_helper+0x0/0x96
[<40020a90>] kernel_thread+0x3a/0x42
---[ end trace d05fe4c5ce0089d4 ]---
------------[ cut here ]------------
WARNING: at kernel/rcutiny.c:75
rcu_idle_enter_common.isra.8.part.9+0x6c/0x88()
Current pid: 45 comm: kworker/u:1 / Idle pid: 0 comm: swapper
Call Trace: [<4002610c>] warn_slowpath_common+0x50/0x6a
[<400261a4>] warn_slowpath_fmt+0x2a/0x32
[<40060b6c>] rcu_idle_enter_common.isra.8.part.9+0x6c/0x88
[<40060b6c>] rcu_idle_enter_common.isra.8.part.9+0x6c/0x88
[<4004665a>] hrtimer_try_to_cancel+0x0/0xbc
[<40060bd6>] rcu_irq_exit+0x4e/0x98
[<4002dcda>] irq_exit+0x32/0x60
[<4002082c>] do_IRQ+0x2c/0x3c
[<400233ea>] inthandler+0x2a/0x34
[<4004665a>] hrtimer_try_to_cancel+0x0/0xbc
[<40046668>] hrtimer_try_to_cancel+0xe/0xbc
[<4004672a>] hrtimer_cancel+0x14/0x30
[<4002b79a>] do_exit+0x51a/0x888
[<4002be52>] sys_exit+0x0/0x16
[<4003ac72>] wait_for_helper+0x0/0x96
[<4002be68>] do_group_exit+0x0/0xf8
[<400232d8>] system_call+0x48/0x86
[<4003ac72>] wait_for_helper+0x0/0x96
[<40020a90>] kernel_thread+0x3a/0x42
---[ end trace d05fe4c5ce0089d5 ]---
libphy: fec_enet_mii_bus: probed
TCP: cubic registered
NET: Registered protocol family 17
VFS: Mounted root (romfs filesystem) readonly on device 31:0.
Freeing unused kernel memory: 64k freed (0x40252000 - 0x40260000)
-----Original Message-----
From: uclinux-dev-bounces at uclinux.org
[mailto:uclinux-dev-bounces at uclinux.org] On Behalf Of Luis Alves
Sent: Tuesday, March 05, 2013 6:19 PM
To: uClinux development list
Subject: Re: [uClinux-dev] migration issue scheduling while atomic
Hi,
With preemption disabled, you shouldn't see that message.
In your current kernel config, under "Kernel hacking" what is the state of
the "Sleep inside atomic section checking" option?
Regards,
Luis
On Tue, Mar 5, 2013 at 5:00 PM, Christian Gieseler

Post by Christian Gieseler
Hi list,
I ran in another issue while updating our coldfire 5329 board from linux
2.6.25 to linux 3.6.
Romfs is mounted as root and then the system says BUG: scheduling while
atomic: swapper/0/0x00000000 and is finally crashing after some trace
output.
The system is configured to behave a preemptive system (low latency
desktop) but the system also crashes without preemption activated.
Does somebody know in which direction to look and how to tackle this

issue?

Post by Christian Gieseler
What is the best way to track it down and fix this?
Let me know if there is more information needed than the boot up
messages below show.
Best Regards
Christian
dBUG> dn
Downloading Image 'image.bin' from 192.168.10.254
TFTP transfer completed
Read 4647940 bytes (9079 blocks)
dBUG> go 0x40020000
Linux version 3.6.11 (christian at cglinux.eks-engel.local) (gcc version
4.6.1 (Sourcery CodeBench Lite 2011.09-23) ) #72 PREEMPT Tue Mar 5
17:32:05 CET
2013
uClinux/COLDFIRE(m532x)
COLDFIRE port done by Greg Ungerer, gerg at snapgear.com
Flat model support (C) 1998,1999 Kenneth Albanowski, D. Jeff Dionne
Built 1 zonelists in Zone order, mobility grouping off. Total pages: 2024
Kernel command line: rootfstype=romfs console=tty1
console=ttyS0,115200
root=/dev/mtdblock0
PID hash table entries: 64 (order: -5, 256 bytes)
Dentry cache hash table entries: 2048 (order: 0, 8192 bytes)
Inode-cache hash table entries: 2048 (order: 0, 8192 bytes)
Memory available: 11392k/16256k RAM, (1736k kernel code, 631k data)
NR_IRQS:256
Calibrating delay loop... HZ=100
15.46 BogoMIPS (lpj=77312)
pid_max: default: 32768 minimum: 301
Mount-cache hash table entries: 1024
NET: Registered protocol family 16
bio: create slab <bio-0> at 0
Switching to clocksource tmr
NET: Registered protocol family 2
TCP established hash table entries: 1024 (order: 0, 8192 bytes)
TCP bind hash table entries: 1024 (order: -1, 4096 bytes)
TCP: Hash tables configured (established 1024 bind 1024)
TCP: reno registered
UDP hash table entries: 512 (order: 0, 8192 bytes)
UDP-Lite hash table entries: 512 (order: 0, 8192 bytes)
NET: Registered protocol family 1
jffs2: version 2.2. (NAND) C 2001-2006 Red Hat, Inc.
ROMFS MTD (C) 2007 Red Hat, Inc.
msgmni has been set to 22
io scheduler noop registered
io scheduler deadline registered
io scheduler cfq registered (default)
ColdFire internal UART serial driver
ttyS0 at MMIO 0xfc060000 (irq = 90) is a ColdFire UART
console [ttyS0] enabled
ttyS1 at MMIO 0xfc064000 (irq = 91) is a ColdFire UART
ttyS2 at MMIO 0xfc068000 (irq = 92) is a ColdFire UART
brd: module loaded
uclinux[mtd]: RAM probe address=0x4026fd40 size=0x22c000
0x000000000000-0x00000022c000 : "ROMfs"
el5329 flash device: 1000000 at 0
el5329 flash: Found 1 x16 devices at 0x0 in 16-bit bank. Manufacturer ID
0x000001 Chip ID 0x002101
Amd/Fujitsu Extended Query Table at 0x0040
Amd/Fujitsu Extended Query version 1.3.
number of CFI chips: 1
0x000000000000-0x000000020000 : "vectors"
0x000000020000-0x000000040000 : "user_parameters"
0x000000040000-0x000000060000 : "system_parameters"
0x000000060000-0x000000100000 : "bootloader"
0x000000100000-0x000000700000 : "kernel_partition1"
0x000000700000-0x000000d00000 : "partition2"
0x000000d00000-0x000001000000 : "user_data"
BUG: scheduling while atomic: swapper/0/0x00000000
Call Trace: [<401cf054>] __schedule_bug+0x40/0x52
[<401d160e>] __schedule+0x33e/0x3c0
[<401d1bf0>] schedule+0x38/0x54
[<401d1d90>] schedule_preempt_disabled+0x18/0x24
[<401cdd62>] rest_init+0x72/0x82
[<401ced70>] printk+0x0/0x20
[<40252678>] start_kernel+0x2e8/0x2f4
[<400200da>] _exit+0x0/0x6
------------[ cut here ]------------
WARNING: at kernel/rcutiny.c:135
rcu_idle_exit_common.part.8+0x56/0x66()
Current pid: 45 comm: kworker/u:1 / Idle pid: 0 comm: swapper
Call Trace: [<400260f8>] warn_slowpath_common+0x50/0x6a
[<40026190>] warn_slowpath_fmt+0x2a/0x32
[<40060474>] rcu_idle_exit_common.part.8+0x56/0x66
[<40060474>] rcu_idle_exit_common.part.8+0x56/0x66
[<400607ea>] rcu_irq_enter+0x62/0x98
[<4002dbf4>] irq_enter+0xa/0x60
[<4002081c>] do_IRQ+0x1c/0x3c
[<400233ea>] inthandler+0x2a/0x34
[<40041e40>] exit_itimers+0x8/0x16e
[<4002b778>] do_exit+0x524/0x888
[<4002be26>] sys_exit+0x0/0x16
[<4003ac12>] wait_for_helper+0x0/0x96
[<4002be3c>] do_group_exit+0x0/0xf8
[<400232d8>] system_call+0x48/0x86
[<4003ac12>] wait_for_helper+0x0/0x96
[<40020a90>] kernel_thread+0x3a/0x42
---[ end trace 6786da2dfad7182c ]---
------------[ cut here ]------------
WARNING: at kernel/rcutiny.c:75
rcu_idle_enter_common.isra.9.part.10+0x6c/0x88()
Current pid: 45 comm: kworker/u:1 / Idle pid: 0 comm: swapper
Call Trace: [<400260f8>] warn_slowpath_common+0x50/0x6a
[<40026190>] warn_slowpath_fmt+0x2a/0x32
[<40060922>] rcu_idle_enter_common.isra.9.part.10+0x6c/0x88
[<40060922>] rcu_idle_enter_common.isra.9.part.10+0x6c/0x88
[<4006098c>] rcu_irq_exit+0x4e/0x98
[<4002dc7c>] irq_exit+0x32/0x60
[<4002082c>] do_IRQ+0x2c/0x3c
[<400233ea>] inthandler+0x2a/0x34
[<40041e40>] exit_itimers+0x8/0x16e
[<4002b778>] do_exit+0x524/0x888
[<4002be26>] sys_exit+0x0/0x16
[<4003ac12>] wait_for_helper+0x0/0x96
[<4002be3c>] do_group_exit+0x0/0xf8
[<400232d8>] system_call+0x48/0x86
[<4003ac12>] wait_for_helper+0x0/0x96
[<40020a90>] kernel_thread+0x3a/0x42
---[ end trace 6786da2dfad7182d ]---
libphy: fec_enet_mii_bus: probed
TCP: cubic registered
NET: Registered protocol family 17
Name=/dev/root, fs=romfs, flags=32769, data=0
VFS: Mounted root (romfs filesystem) readonly on device 31:0.
Freeing unused kernel memory: 64k freed (0x40252000 - 0x40260000)
_______________________________________________
uClinux-dev mailing list
uClinux-dev at uclinux.org
http://mailman.uclinux.org/mailman/listinfo/uclinux-dev
http://mailman.uclinux.org/mailman/options/uclinux-dev

_______________________________________________
uClinux-dev mailing list
uClinux-dev at uclinux.org
http://mailman.uclinux.org/mailman/listinfo/uclinux-dev
http://mailman.uclinux.org/mailman/options/uclinux-dev
_______________________________________________
uClinux-dev mailing list
uClinux-dev at uclinux.org
http://mailman.uclinux.org/mailman/listinfo/uclinux-dev
This message was resent by uclinux-dev at uclinux.org
http://mailman.uclinux.org/mailman/options/uclinux-dev

[Geert Uytterhoeven]

Post by Luis Alves
Anyway... Digging in the kernel sources and reading some stuff, I
concluded that "Sleep inside atomic section checking" doesn't make
sense since the m68k arch doesn't support SMP or preemption.
From what I could understand this check looks for scheduling inside
spinlocks (that should disable preemption).
In my case, since I don't have preemption enabled in the first place,
then spinlocks do absolutely nothing (the ones that don't disable
irqs).

Isn't this message also printed while scheduling with interrupts disabled?

Gr{oetje,eeting}s,

Geert

--
Geert Uytterhoeven -- There's lots of Linux beyond ia32 -- geert at linux-m68k.org

In personal conversations with technical people, I call myself a hacker. But
when I'm talking to journalists I just say "programmer" or something like that.
-- Linus Torvalds