[#4820] stack info will show up 2 mins after run oprofile test

Submitted By: Vivi Li

Open Date

2009-01-19 03:55:33 Close Date

2009-03-02 05:36:26

Priority:

Medium Assignee:

Graf Yang

Status:

Closed Fixed In Release:

N/A

Found In Release:

N/A Release:

Category:

N/A Board:

N/A

Processor:

ALL Silicon Revision:

Is this bug repeatable?:

Yes Resolution:

Rejected

Uboot version or rev.:

Toolchain version or rev.:

gcc4.1-2008_Dec_12

App binary format:

N/A

Summary: stack info will show up 2 mins after run oprofile test

Details:

Run oprofile test, stack info will show up after 2 mins.

Bellow is the log:

Linux version 2.6.28-ADI-2009R1-pre-svn6027 (test@107-local) (gcc version 4.1.2 (ADI svn)) #351 Mon9

console [early_BFuart0] enabled

early printk enabled on early_BFuart0

Warning: limiting memory to 56MB due to hardware anomaly 05000263

Board Memory: 64MB

Kernel Managed Memory: 64MB

Memory map:

fixedcode = 0x00000400-0x00000490

text = 0x00001000-0x0010d3d0

rodata = 0x0010d3d0-0x00160380

bss = 0x00160380-0x0016ef08

data = 0x0016ef08-0x00180000

stack = 0x0017e000-0x00180000

init = 0x00180000-0x00eeb000

available = 0x00eeb000-0x037ff000

DMA Zone = 0x03f00000-0x04000000

Hardware Trace Active and Enabled

Boot Mode: 0

Compiled for ADSP-BF537 Rev 0.2

Blackfin Linux support by blackfin.uclinux.org/

Processor Speed: 500 MHz core clock and 100 MHz System Clock

NOMPU: setting up cplb tables

Instruction Cache Enabled for CPU0

Data Cache Enabled for CPU0 (write-through)

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

Kernel command line: root=/dev/mtdblock0 rw earlyprintk=serial,uart0,57600 console=ttyBF0,57600 ip=f

Configuring Blackfin Priority Driven Interrupts

PID hash table entries: 256 (order: 8, 1024 bytes)

console handover: boot [early_BFuart0] -> real [ttyBF0]

Dentry cache hash table entries: 8192 (order: 3, 32768 bytes)

Inode-cache hash table entries: 4096 (order: 2, 16384 bytes)

Memory available: 41484k/65536k RAM, (13740k init code, 1072k kernel code, 460k data, 1024k dma, 77)

Calibrating delay loop... 995.32 BogoMIPS (lpj=1990656)

Security Framework initialized

Mount-cache hash table entries: 512

Blackfin Scratchpad data SRAM: 4 KB

Blackfin L1 Data A SRAM: 16 KB (15 KB free)

Blackfin L1 Data B SRAM: 16 KB (16 KB free)

Blackfin L1 Instruction SRAM: 48 KB (41 KB free)

PDA for CPU0 reserved at 00161468

net_namespace: 288 bytes

NET: Registered protocol family 16

Blackfin GPIO Controller

Blackfin DMA Controller

stamp_init(): registering device resources

NET: Registered protocol family 2

IP route cache hash table entries: 1024 (order: 0, 4096 bytes)

TCP established hash table entries: 2048 (order: 2, 16384 bytes)

TCP bind hash table entries: 2048 (order: 1, 8192 bytes)

TCP: Hash tables configured (established 2048 bind 2048)

TCP reno registered

NET: Registered protocol family 1

msgmni has been set to 81

io scheduler noop registered

io scheduler anticipatory registered (default)

io scheduler cfq registered

Serial: Blackfin serial driver

bfin-uart.1: ttyBF0 at MMIO 0xffc00400 (irq = 18) is a BFIN-UART

brd: module loaded

bfin_mac_mdio: probed

bfin_mac: attached PHY driver [SMSC LAN83C185] (mii_bus:phy_addr=0:01, irq=-1, mdc_clk=2500000Hz(md)

bfin_mac bfin_mac.0: Blackfin on-chip Ethernet MAC driver, Version 1.1

bfin-spi bfin-spi.0: Blackfin on-chip SPI Controller Driver, Version 1.0, regs_base@ffc00500, dma c7

rtc-bfin rtc-bfin: rtc core: registered rtc-bfin as rtc0

bfin-wdt: initialized: timeout=20 sec (nowayout=0)

oprofile: using timer interrupt.

TCP cubic registered

NET: Registered protocol family 17

rtc-bfin rtc-bfin: setting system clock to 1970-01-01 03:20:37 UTC (12037)

IP-Config: Complete:

device=eth0, addr=10.100.4.50, mask=255.255.255.0, gw=10.100.4.174,

host=bf537-stamp, domain=, nis-domain=(none),

bootserver=10.100.4.174, rootserver=10.100.4.174, rootpath=

Freeing unused kernel memory: 13740k freed

dma_alloc_init: dma_page @ 0x00ee7000 - 256 pages at 0x03f00000

_____________________________________

a8888b. / Welcome to the uClinux distribution \

d888888b. / _ _ \

8P"YP"Y88 / | | |_| __ __ (TM) |

8|o||o|88 _____/ | | _ ____ _ _ \ \/ / |

8' .88 \ | | | | _ \| | | | \ / |

8`._.' Y8. \ | |__ | | | | | |_| | / \ |

d/ `8b. \ \____||_|_| |_|\____|/_/\_\ |

dP . Y8b. \ For embedded processors including |

d8:' " `::88b \ the Analog Devices Blackfin /

d8" 'Y88b \___________________________________/

:8P ' :888

8a. : _a88P For further information, check out:

._/"Yaa_: .| 88P| - blackfin.uclinux.org/

\ YP" `| 8P `. - docs.blackfin.uclinux.org/

/ \.___.d| .' - www.uclinux.org/

`--..__)8888P`._.' jgs/a:f - www.analog.com/blackfin

Have a lot of fun...

BusyBox v1.13.2 (2009-01-19 11:36:02 CST) built-in shell (msh)

Enter 'help' for a list of built-in commands.

root:/> PHY: 0:01 - Link is Up - 100/Full

root:/>

root:/> /usr/bin/bfin_opcontrol --init

root:/> /usr/bin/bfin_opcontrol --start-daemon &

Using 2.6+ OProfile kernel interface.

Reading module info.

Using log file /var/lib/oprofile/oprofiled.log

164

root:/> /usr/bin/bfin_opcontrol --start

root:/> /usr/bin/bfin_opcontrol --dump

root:/>

root:/> /usr/bin/opreport -l

CPU: CPU with timer interrupt, speed 500 MHz (estimated)

Profiling through timer interrupt

warning: /bin/busybox is not in a usable binary format.

warning: could not check that the binary file /vmlinux has not been modified since the profile was .

samples % app name symbol name

2 50.0000 busybox (no symbols)

1 25.0000 vmlinux _bfin_get_addr_from_rp

1 25.0000 vmlinux _calc_reloc

root:/> INFO: task oprofiled:165 blocked for more than 120 seconds.

"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.

oprofiled D ffa008c8 0 165 1

Stack info:

SP: [0x02773db8] <0x02773db8> /* kernel dynamic memory */

FP: (0x02773dd4)

Memory from 0x02773db0 to 02774000

02773db0: 037c598c 001629ec [02729060] 037c5960 0378a0a0 027291e0 001629ec 00000002

02773dd0: 02772000 (02773df4)<ffa0145e> 02773e2c <0003e700> 00000000 <0010c298> 02772000

02773df0: 02772000 (02773e6c)<0010c298> 02772000 02772000 02773eac 7fffffff 00000000

02773e10: 00000002 00170490 003d08bd 02773e48 <0000ac06> 02773e44 <0010c078> 0378a6a0

02773e30: 7fffffff 00000000 00000000 <0010c100> 02772000 7fffffff 00000000 02773e80

02773e50:<0000dc14> 001629ec 00000001 0378a0a0 0000afe4 02773eb0 02773eb0 (00000000)

02773e70:<0000f0a6> 0378a6a0 00004000 000000a6 02772000 00000000 00000000 00000000

02773e90: 037f32a0 00cbddf4 02773f24 00000000 00000000 00000000 00000000 00000000

02773eb0: 02773e64 02773e64 00000000 00cbde00 <00001638> ffa000e0 000000be 00cbdf18

02773ed0: 00000000 ffffe000 00000004 00ca07c8 0003f958 <0003f816> 037ea5c0 00000000

02773ef0: 00000000 00000000 <ffa000ec><ffa00804><ffa00804> 0003f7b0 <ffa00804> 00cac7d8

02773f10: 00cac7d8 00cbddb8 00d80ff4 00ca07c8 00000004 00ca8052 00008000 00000000

02773f30: 00000000 02774000 00ca8052 00ca8052 <00ca07a0><ffa00d6c> 02003025 00ca315d

02773f50: 00caaadd 00ca3158 00caaadc 00000000 00000000 00000000 00000000 00000000

02773f70: 00000000 00000000 00000000 00000000 00cbd9a8 00000000 00000000 00000000

02773f90: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 19000000

02773fb0: 00cbcb55 00cbddf4 00cbde00 00cb39bc 00cb39b4 00cbdf18 00d80008 00000400

02773fd0: 000000be 00cb3720 02766004 00000004 00ca07c8 00d80ff4 00000000 00000001

02773ff0: 00000000 00000000 000000be 00000006 0378a6a0

Return addresses in stack:

frame 1 : <0xffa0145e> { _schedule + 0x19e }

address : <0x0003e700> { _kmem_cache_alloc + 0x54 }

address : <0x0010c298> { _schedule_timeout + 0x70 }

frame 2 : <0x0010c298> { _schedule_timeout + 0x70 }

address : <0x0000ac06> { _enqueue_task_fair + 0x36 }

address : <0x0010c078> { __cond_resched + 0x34 }

address : <0x0010c100> { _wait_for_common + 0x84 }

address : <0x0000dc14> { _wake_up_new_task + 0x84 }

frame 3 : <0x0000f0a6> { _do_fork + 0x10a }

address : <0x00001638> { _bfin_vfork + 0x18 }

address : <0x0003f816> { _sys_close + 0x66 }

address : <0xffa000ec> { _sys_vfork + 0xc }

address : <0xffa00804> { _system_call + 0x68 }

address : <0x00ca07a0> [ /usr/bin/oprofiled + 0x7a0 ]

address : <0xffa00d6c> { _evt_system_call + 0x64 }

INFO: task oprofiled:166 blocked for more than 120 seconds.

"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.

oprofiled D ffa008c8 0 166 165

Stack info:

SP: [0x02775db8] <0x02775db8> /* kernel dynamic memory */

FP: (0x02775dd4)

Memory from 0x02775db0 to 02776000

02775db0: 0378a3cc 001629ec [02729de0] 0378a3a0 0378a6a0 027291e0 001629ec 00000002

02775dd0: 02774000 (02775df4)<ffa0145e> 02775e2c <0003e700> 00000000 <0010c298> 02774000

02775df0: 02774000 (02775e6c)<0010c298> 02774000 02774000 02775eac 7fffffff 00000000

02775e10: 00000002 00170490 003d08bd 02775e48 <0000ac06> 02775e44 <0010c078> 037af640

02775e30: 7fffffff 00000000 00000000 <0010c100> 02774000 7fffffff 00000000 <0000dc14>

02775e50: 001629ec 037af640 00000001 0378a6a0 0000afe4 02775eb0 02775eb0 (00000000)

02775e70:<0000f0a6> 037af640 00004000 000000a7 02774000 00000000 00000000 00000000

02775e90: 00000000 00cbddf4 02775f24 00000000 00000000 00000000 00000000 00000000

02775eb0: 02775e64 02775e64 00000000 00cbde00 <00001638> ffa000e0 000000be 00cbdf18

02775ed0: 00000000 ffffe000 00000004 00ca07c8 <0001b12e><0001b134> 0378a6a0 00000000

02775ef0: 00000000 00000000 <ffa000ec><ffa00804> 0001b0cc 00000000 <ffa00804> 027291e0

02775f10: 027291e0 001629ec 00d80ff4 00ca07c8 00000004 00ca8052 00008000 00000000

02775f30: 00000000 02776000 00ca8052 00ca8052 <00ca07a0><ffa00d6c> 02003004 00ca315d

02775f50: 00caaadd 00ca3158 00caaadc 00000000 00000000 00000000 00000000 00000000

02775f70: 00000000 00000000 00000000 00000000 00cbd9a8 00000000 00000000 00000000

02775f90: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 19000000

02775fb0: 00cbcb55 00cbddf4 00cbde00 00cb39bc 00cb39b4 00cbdf18 00d80008 00000400

02775fd0: 000000be 00cb3720 02766004 00000004 00ca07c8 00d80ff4 00000000 00000001

02775ff0: 000000a6 000000a6 000000be 00000006 037af640

Return addresses in stack:

frame 1 : <0xffa0145e> { _schedule + 0x19e }

address : <0x0003e700> { _kmem_cache_alloc + 0x54 }

address : <0x0010c298> { _schedule_timeout + 0x70 }

frame 2 : <0x0010c298> { _schedule_timeout + 0x70 }

address : <0x0000ac06> { _enqueue_task_fair + 0x36 }

address : <0x0010c078> { __cond_resched + 0x34 }

address : <0x0010c100> { _wait_for_common + 0x84 }

address : <0x0000dc14> { _wake_up_new_task + 0x84 }

frame 3 : <0x0000f0a6> { _do_fork + 0x10a }

address : <0x00001638> { _bfin_vfork + 0x18 }

address : <0x0001b12e> { _sys_setsid + 0x62 }

address : <0x0001b134> { _sys_setsid + 0x68 }

address : <0xffa000ec> { _sys_vfork + 0xc }

address : <0xffa00804> { _system_call + 0x68 }

address : <0x00ca07a0> [ /usr/bin/oprofiled + 0x7a0 ]

address : <0xffa00d6c> { _evt_system_call + 0x64 }

Follow-ups

--- Graf Yang 2009-02-04 04:50:10

Not be afraid of it. It not a bug.

Daemon oprofiled always wait on reading the sample buffer, and it may take a

long time until the sample buffer is full.

When opened CONFIG_DETECT_SOFTLOCKUP, the stack info will be dumped.

Try "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" to disable

it.

Files

Changes

Commits

Dependencies

Duplicates

Associations