FAQ: [#6325] After wakeup from mem, underrun may happen with ad1836 on bf537-stamp(2010)

Document created by Aaronwu Employee on Sep 11, 2013
Version 1Show Document
  • View in full screen mode

[#6325] After wakeup from mem, underrun may happen with ad1836 on bf537-stamp

Submitted By: Vivi Li

Open Date

2010-11-01 04:41:51    

Priority:

Low     Assignee:

Bob Liu

Status:

Open     Fixed In Release:

N/A

Found In Release:

2010R1-RC5     Release:

Category:

Drivers     Board:

N/A

Processor:

BF537     Silicon Revision:

Is this bug repeatable?:

Yes     Resolution:

Assigned (Not Start)

Uboot version or rev.:

    Toolchain version or rev.:

trunk

App binary format:

N/A     

Summary: After wakeup from mem, underrun may happen with ad1836 on bf537-stamp

Details:

 

After wakeup from mem, underrun may happen with ad1836 on bf537-stamp, saying "tx dma is already stopped".

This may happens once for months. This should exists in both trunk and branch.

 

Bellow is the log:

--

Linux version 2.6.34.7-ADI-2010R1-svn9290 (test@uclinux50-bf537-ad9960-ad1836) (gcc version 4.3.5 (ADI-2010R1-RC4) ) #6 Sat Oct 30 23:03:05 CST 2010

register early platform devices

bootconsole [early_shadow0] enabled

bootconsole [early_BFuart0] enabled

early printk enabled on early_BFuart0

Limiting kernel memory to 56MB due to anomaly 05000263

Board Memory: 64MB

Kernel Managed Memory: 64MB

Memory map:

  fixedcode = 0x00000400-0x00000490

  text      = 0x00001000-0x00132ed8

  rodata    = 0x00132ed8-0x00197bb8

  bss       = 0x00198000-0x001a8cb4

  data      = 0x001a8cb4-0x001bc000

    stack   = 0x001ba000-0x001bc000

  init      = 0x001bc000-0x008ac000

  available = 0x008ac000-0x03800000

  DMA Zone  = 0x03e00000-0x04000000

Hardware Trace Active and Enabled

Boot Mode: 0

Reset caused by Software reset

Blackfin support (C) 2004-2010 Analog Devices, Inc.

Compiled for ADSP-BF537 Rev 0.2

Blackfin Linux support by http://blackfin.uclinux.org/

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

NOMPU: setting up cplb tables

Instruction Cache Enabled for CPU0

  External memory: cacheable in instruction cache

Data Cache Enabled for CPU0

  External memory: cacheable (write-back) in data cache

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

Kernel command line: root=/dev/mtdblock0 rw ip=10.100.4.50 earlyprintk=serial,uart0,57600 console=ttyBF0,57600 ip=10.100.4.50:10.100.4.174:10.100.4.174:255.255.255.0:bf537-stamp:eth0:off

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

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

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

Memory available: 47896k/65536k RAM, (7104k init code, 1223k kernel code, 549k data, 2048k dma, 6716k reserved)

Hierarchical RCU implementation.

NR_IRQS:138

Configuring Blackfin Priority Driven Interrupts

console [ttyBF0] enabled, bootconsole disabled

console [ttyBF0] enabled, bootconsole disabled

Calibrating delay loop... 993.28 BogoMIPS (lpj=1986560)

Security Framework initialized

Mount-cache hash table entries: 512

Blackfin Scratchpad data SRAM: 4 KB

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

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

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

NET: Registered protocol family 16

Blackfin DMA Controller

stamp_init(): registering device resources

bio: create slab <bio-0> at 0

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

Advanced Linux Sound Architecture Driver Version 1.0.22.1.

Switching to clocksource bfin_cs_cycles

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

UDP hash table entries: 256 (order: 0, 4096 bytes)

UDP-Lite hash table entries: 256 (order: 0, 4096 bytes)

NET: Registered protocol family 1

msgmni has been set to 93

io scheduler noop registered

io scheduler cfq registered (default)

bfin-uart: Blackfin serial driver

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

brd: module loaded

bfin_mii_bus: probed

bfin_mac: attached PHY driver [SMSC LAN83C185] (mii_bus:phy_addr=0:01, irq=-1, mdc_clk=2500000Hz(mdc_div=24)@sclk=125MHz)

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

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

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

ALSA device list:

  No soundcards found.

TCP cubic registered

NET: Registered protocol family 17

rtc-bfin rtc-bfin: setting system clock to 1970-01-14 21:15:36 UTC (1199736)^VIP-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=

dma_alloc_init: dma_page @ 0x028fb000 - 512 pages at 0x03e00000

Freeing unused kernel memory: 7104k freed

                           _____________________________________

        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|            - http://blackfin.uclinux.org/

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

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

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

 

Have a lot of fun...

 

 

BusyBox v1.16.2 (2010-10-30 22:57:16 CST) hush - the humble shell

 

root:/> ^[[6nversion

kernel:    Linux release 2.6.34.7-ADI-2010R1-svn9290, build #6 Sat Oct 30 23:03:05 CST 2010PHY: 0:01 - Link is Up - 100/Full

 

toolchain: bfin-linux-uclibc-gcc release gcc version 4.3.5 (ADI-2010R1-RC4)

user-dist: release svn-9868, build #56 Sat Oct 30 23:01:01 CST 2010

root:/> ^[[6nsuccessful boot attempt

************** STEP 3: Start testing

 

 

root:/> ^[[6nmodprobe snd_ad183x

dma rx:3 tx:4, err irq:45, regs:ffc00800

asoc: AD183X <-> bf5xx-tdm mapping ok

root:/> ^[[6nlsmod

Module                  Size  Used by

snd_ad183x               801  0

snd_soc_bf5xx_tdm       2157  1 snd_ad183x

snd_soc_ad183x          7921  1 snd_ad183x

snd_bf5xx_tdm           1853  1 snd_ad183x

snd_soc_bf5xx_sport     9444  2 snd_soc_bf5xx_tdm,snd_bf5xx_tdm

root:/> ^[[6n

Case 1 ...PASS

 

Case 1 ...PASS

vrec -w -S -b 16 -s 48000 -t 5|vplay

Recording WAVE : 16 bit, Speed 48000 Hz Stereo ...

Playing WAVE : 16 bit, Speed 48000 Hz Stereo ...

root:/> ^[[6n

Case 2 ...PASS

 

Case 2 ...PASS

arecord -t wav -c 2 -f S16_LE -r 48000 -d 5 |aplay

Recording WAVE 'stdin' : Signed 16 bit Little Endian, Rate 48000 Hz, Stereo

Playing WAVE 'stdin' : Signed 16 bit Little Endian, Rate 48000 Hz, Stereo

root:/> ^[[6n

Case 3 ...PASS

 

Case 3 ...PASS

cat /proc/mounts

rootfs / rootfs rw 0 0

proc /proc proc rw,nosuid,nodev,noexec,relatime 0 0

sysfs /sys sysfs rw,nosuid,nodev,noexec,relatime 0 0

mdev /dev tmpfs rw,nosuid,relatime,mode=0755,size=10M 0 0

devpts /dev/pts devpts rw,nosuid,noexec,relatime,mode=600 0 0

var /var ramfs rw,relatime 0 0

tmp /tmp tmpfs rw,nosuid,nodev,relatime 0 0

debugfs /sys/kernel/debug debugfs rw,relatime 0 0

root:/> ^[[6n

Case 4 ...PASS

 

Case 4 ...PASS

ls /sys/power

^[[0;0mpm_async^[[0m  ^[[0;0mstate^[[0m

root:/> ^[[6n

Case 5 ...PASS

root:/> rtcwake -s 15 -m mem

wakeup from "mem" at Wed Jan 14 21:16:25 1970

PM: Syncing filesystems ... done.

Freezing user space processes ... (elapsed 0.01 seconds) done.

Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done.

Suspending console(s) (use no_console_suspend to debug)

PM: suspend of devices complete after 924.074 msecs

PM: late suspend of devices complete after 0.115 msecs

PM: early resume of devices complete after 0.063 msecs

PM: resume of devices complete after 1.162 msecs

Restarting tasks ... done.

root:/> ^[[6n

Case 6 ...PASS

 

Case 6 ...PASS

vrec -w -S -b 16 -s 48000 -t 5|vplay

Recording WAVE : 16 bit, Speed 48000 Hz Stereo ...

Playing WAVE : 16 bit, Speed 48000 Hz Stereo ...

root:/> ^[[6n

Case 7 ...PASS

 

Case 7 ...PASS

arecord -t wav -c 2 -f S16_LE -r 48000 -d 5 |aplay

Recording WAVE 'stdin' : Signed 16 bit Little Endian, Rate 48000 Hz, Stereo

Playing WAVE 'stdin' : Signed 16 bit Little Endian, Rate 48000 Hz, Stereo

root:/> ^[[6n

Case 8 ...PASS

 

Case 8 ...PASS

 

Standby test case 1 round 1 pass

 

 

root:/> rtcwake -s 15 -m mem

wakeup from "mem" at Wed Jan 14 21:17:07 1970

PM: Syncing filesystems ... done.

Freezing user space processes ... (elapsed 0.01 seconds) done.

Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done.

Suspending console(s) (use no_console_suspend to debug)

PM: suspend of devices complete after 923.568 msecs

PM: late suspend of devices complete after 0.114 msecs

PM: early resume of devices complete after 0.063 msecs

PM: resume of devices complete after 1.161 msecs

Restarting tasks ... done.

root:/> ^[[6n

Case 9 ...PASS

 

Case 9 ...PASS

vrec -w -S -b 16 -s 48000 -t 5|vplay

Recording WAVE : 16 bit, Speed 48000 Hz Stereo ...

Playing WAVE : 16 bit, Speed 48000 Hz Stereo ...

root:/> ^[[6n

Case 10 ...PASS

 

Case 10 ...PASS

arecord -t wav -c 2 -f S16_LE -r 48000 -d 5 |aplay

Recording WAVE 'stdin' : Signed 16 bit Little Endian, Rate 48000 Hz, Stereo

Playing WAVE 'stdin' : Signed 16 bit Little Endian, Rate 48000 Hz, Stereo

root:/> ^[[6n

Case 11 ...PASS

 

Case 11 ...PASS

 

Standby test case 1 round 2 pass

 

 

root:/> rtcwake -s 15 -m mem

wakeup from "mem" at Wed Jan 14 21:17:49 1970

PM: Syncing filesystems ... done.

Freezing user space processes ... (elapsed 0.01 seconds) done.

Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done.

Suspending console(s) (use no_console_suspend to debug)

PM: suspend of devices complete after 923.061 msecs

PM: late suspend of devices complete after 0.115 msecs

PM: early resume of devices complete after 0.064 msecs

PM: resume of devices complete after 1.097 msecs

Restarting tasks ... done.

root:/>

Case 12 ...PASS

 

Case 12 ...PASS

^[[6nvrec -w -S -b 16 -s 48000 -t 5|vplay

Recording WAVE : 16 bit, Speed 48000 Hz Stereo ...

Playing WAVE : 16 bit, Speed 48000 Hz Stereo ...

root:/>

Case 13 ...PASS

 

Case 13 ...PASS

^[[6narecord -t wav -c 2 -f S16_LE -r 48000 -d 5 |aplay

Recording WAVE 'stdin' : Signed 16 bit Little Endian, Rate 48000 Hz, Stereo

Playing WAVE 'stdin' : Signed 16 bit Little Endian, Rate 48000 Hz, Stereo

root:/> ^[[6n

Case 14 ...PASS

 

Case 14 ...PASS

 

Standby test case 1 round 3 pass

 

 

root:/> rtcwake -s 15 -m mem

wakeup from "mem" at Wed Jan 14 21:18:31 1970

PM: Syncing filesystems ... done.

Freezing user space processes ... (elapsed 0.01 seconds) done.

Freezing remaining freezable tasks ... (elapsed 0.01 seconds) done.

Suspending console(s) (use no_console_suspend to debug)

PM: suspend of devices complete after 922.547 msecs

PM: late suspend of devices complete after 0.113 msecs

PM: early resume of devices complete after 0.063 msecs

PM: resume of devices complete after 1.095 msecs

Restarting tasks ... done.

root:/> ^[[6n

Case 15 ...PASS

 

Case 15 ...PASS

vrec -w -S -b 16 -s 48000 -t 5|vplay

Recording WAVE : 16 bit, Speed 48000 Hz Stereo ...

Playing WAVE : 16 bit, Speed 48000 Hz Stereo ...

tx dma is already stopped

tx dma is already stopped

tx dma is already stopped

tx dma is already stopped

tx dma is already stopped

tx dma is already stopped

tx dma is already stopped

tx dma is already stopped

tx dma is already stopped

...

--

 

Follow-ups

 

--- angelia wu                                               2010-11-04 06:52:06

This problem will also happen on ad1938 power testing on bf537-stamp.

The different is that  underrun will happen more early on ad1938 power

testing.

the log as follow.

root:/> ^[[6nmodprobe snd_ad193x^M

dma rx:3 tx:4, err irq:45, regs:ffc00800^M

asoc: AD193X <-> bf5xx-tdm mapping ok^M

root:/> ^[[6nlsmod^M

Module                  Size  Used by^M

snd_ad193x               829  0 ^M

snd_soc_ad193x          5641  1 snd_ad193x^M

i2c_core               12456  1 snd_soc_ad193x^M

snd_soc_bf5xx_tdm       2157  1 snd_ad193x^M

snd_bf5xx_tdm           1853  1 snd_ad193x^M

snd_soc_bf5xx_sport     9444  2 snd_soc_bf5xx_tdm,snd_bf5xx_tdm^M

root:/> ^[[

Case 1 ...PASS

 

Case 1 ...PASS

6nvrec -w -S -b 16 -s 48000 -t 5|vplay^M

Recording WAVE : 16 bit, Speed 48000 Hz Stereo ...^M

Playing WAVE : 16 bit, Speed 48000 Hz Stereo ...^M

tx dma is already stopped^M

tx dma is already stopped^M

tx dma is already stopped^M

tx dma is already stopped^M

tx dma is already stopped^M

tx dma is already stopped^M

tx dma is already stopped^M

tx dma is already stopped^M

tx dma is already stopped^M

tx dma is already stopped^M

 

--- Bob Liu                                                  2010-11-16 23:45:56

I found there will be input/output error or hang problem.

root:/> vrec -w -S -b 16 -s 48000 -t 5|vplay

Recording WAVE : 16 bit, Speed 48000 Hz Stereo ...

Playing WAVE : 16 bit, Speed 48000 Hz Stereo ...

snd_pcm_update_hw_ptr0: 6 callbacks suppressed

snd_pcm_update_hw_ptr0: 5 callbacks suppressed

snd_pcm_update_hw_ptr0: 6 callbacks suppressed

/dev/dsp: Input/output error

 

root:/> arecord -t wav -c 2 -f S16_LE -r 48000 -d 5 |aplay

Recording WAVE 'stdin' : Signed 16 bit Little Endian, Rate 48000 Hz, Stereo

Playing WAVE 'stdin' : Signed 16 bit Little Endian, Rate 48000 Hz, Stereo

^CAborted by signal Interrupt...

root:/>

 

--- Bob Liu                                                  2010-11-17 02:10:05

1. The input/output error and hang problem only happen while using sport1, I

need confirm this and maybe submit a new bug.

 

2. To this problem, it's really hard to reproduce, in vivi's test it happens

once after running about one month.  So I gave vivi the attached patch and she

will test it again. 

 

--- Sonic Zhang                                              2010-11-23 05:03:36

Problem 1 on sport1 is not a real bug. It disappears on a good bf537-stamp

board.

 

Underrun is a rare case. So, down priority.

 

--- Cameron Barfield                                         2012-04-17 17:23:41

Is this bug tracker still in use?

 

I have a very similar problem with an AD1981 on a BF537 stamp connected via

SPORT0. I can reproduce the problem daily after, on average, 700 iterations.

 

s10454 Received a request to call 101

s10454 initiating a sip call callee='sip:101@10.0.1.17'

s10455 Contacting sip:101@10.0.1.17

s10455 Connected.

s10455 stopped remote ring

s10455 stopped local ring

s10455 starting higher priority stream 8

sport status error: TUVF

tx dma is already stopped

tx dma is already stopped

tx dma is already stopped

 

The "tx dma" message repeats about 20,000 times until the board

reboots (probably from the watchdog triggering).

 

--- Sonic Zhang                                              2012-04-17 23:29:55

AD1981 is obsolete and no longer supported.

 

 

 

    Files

    Changes

    Commits

    Dependencies

    Duplicates

    Associations

    Tags

 

File Name     File Type     File Size     Posted By

config.power.audio_tdm    application/octet-stream    36895    Vivi Li

ad183x.patch    text/x-patch    917    Bob Liu

Outcomes