iMX53: Hang observed frequently during bootup when USB keyboard/mouse connected to board

[Abhishek Paliwal]

Description:
==========
Board hangs during bootup, observed multiple times and quite consistently.
(Board has USB Mouse and USB keyboard connected. )

Observed less number of times if USB Mouse and keyboard are removed from device.

Reproducible:
===========
Yes, 5/5 time

IMPACT:
========
Can't get started with Android image on iMX53

Steps:
==========
1.Create image on SD card for build: https://android-build.linaro.org/builds/~linaro-android/staging-imx53-11.12-release/#build=2
2. Bootup and check serial logs.
Issue: Bootup fails . Nothing displayed on serial console or monitor.

Remove USB Mose and keyboard and then again reboot - works sometimes.

Hardware:
==========
iMX53 board
USB Mouse and USB keyboard connected
8 GB SD card
VGA out to monitor.

Software:
==========
https://android-build.linaro.org/builds/~linaro-android/staging-imx53-11.12-release/#build=2

Bootup Logs:
======

U-Boot 2011.09 (Dec 05 2011 - 23:51:47)

CPU: Freescale i.MX53 family rev2.1 at 800 MHz
Reset cause: POR
Board: MX53 LOCO with MC34708
I2C: ready
DRAM: 1 GiB
WARNING: Caches not enabled
CPU: Switch CPU clock to 1GHZ OK
DDR: Switch DDR clock to 400MHz OK
MMC: FSL_ESDHC: 0, FSL_ESDHC: 1
*** Warning - bad CRC, using default environment

In: serial
Out: serial
Err: serial
Net: got MAC address from fuse: 00:04:9f:01:dd:80
FEC
Hit any key to stop autoboot: 0
reading boot.scr

421 bytes read
Running bootscript from mmc ...
## Executing script at 70800000
reading uImage

4107784 bytes read
reading uInitrd

163162 bytes read
## Booting kernel from Legacy Image at 70000000 ...
   Image Name: Linux-3.1.0-rc9+
   Image Type: ARM Linux Kernel Image (uncompressed)
   Data Size: 4107720 Bytes = 3.9 MiB
   Load Address: 70008000
   Entry Point: 70008000
   Verifying Checksum ... OK
## Loading init Ramdisk from Legacy Image at 72000000 ...
   Image Name: Android Ramdisk Image
   Image Type: ARM Linux RAMDisk Image (gzip compressed)
   Data Size: 163098 Bytes = 159.3 KiB
   Load Address: 00000000
   Entry Point: 00000000
   Verifying Checksum ... OK
   Loading Kernel Image ... OK
OK

Starting kernel ...

Uncompressing Linux... done, booting the kernel.
[ 0.000000] Initializing cgroup subsys cpuset
[ 0.000000] Linux version 3.1.0-rc9+ (jenkins-build@ip-10-6-151-211) (gcc version 4.5.2 (Ubuntu/Linaro 4.5.2-8ubuntu3) ) #1 PREEMPT Tue Dec 6 00:27:54 UTC 2011
[ 0.000000] CPU: ARMv7 Processor [412fc085] revision 5 (ARMv7), cr=10c5387f
[ 0.000000] CPU: VIPT nonaliasing data cache, VIPT aliasing instruction cache
[ 0.000000] Machine: Freescale MX53 LOCO Board
[ 0.000000] Memory policy: ECC disabled, Data cache writeback
[ 0.000000] Built 1 zonelists in Zone order, mobility grouping on. Total pages: 242688
[ 0.000000] Kernel command line: console=tty0 console=ttymxc0,115200n8 rootwait ro earlyprintk rootdelay=1 fixrtc nocompcache di1_primary tve init=/init androidboot.console=ttymxc0
[ 0.000000]
[ 0.000000] PID hash table entries: 2048 (order: 1, 8192 bytes)
[ 0.000000] Dentry cache hash table entries: 65536 (order: 6, 262144 bytes)
[ 0.000000] Inode-cache hash table entries: 32768 (order: 5, 131072 bytes)
[ 0.000000] Memory: 512MB 448MB = 960MB total
[ 0.000000] Memory: 958760k/958760k available, 89816k reserved, 458752K highmem
[ 0.000000] Virtual kernel memory layout:
[ 0.000000] vector : 0xffff0000 - 0xffff1000 ( 4 kB)
[ 0.000000] fixmap : 0xfff00000 - 0xfffe0000 ( 896 kB)
[ 0.000000] DMA : 0xf7e00000 - 0xffe00000 ( 128 MB)
[ 0.000000] vmalloc : 0xe0800000 - 0xf4000000 ( 312 MB)
[ 0.000000] lowmem : 0xc0000000 - 0xe0000000 ( 512 MB)
[ 0.000000] pkmap : 0xbfe00000 - 0xc0000000 ( 2 MB)
[ 0.000000] modules : 0xbf000000 - 0xbfe00000 ( 14 MB)
[ 0.000000] .text : 0xc0008000 - 0xc07c8300 (7937 kB)
[ 0.000000] .init : 0xc07c9000 - 0xc0818000 ( 316 kB)
[ 0.000000] .data : 0xc0818000 - 0xc087a7b0 ( 394 kB)
[ 0.000000] .bss : 0xc087a7d4 - 0xc0f11870 (6749 kB)
[ 0.000000] Preemptible hierarchical RCU implementation.
[ 0.000000] NR_IRQS:400
[ 0.000000] TrustZone Interrupt Controller (TZIC) initialized
[ 0.000000] sched_clock: 32 bits at 8MHz, resolution 125ns, wraps every 536870ms
[ 0.000000] Console: colour dummy device 80x30
[ 0.000000] console [tty0] enabled
[ 0.000000] ram_console: buffer (null), invalid size 0, datasize 4294967284
[ 0.000000] Lock dependency validator: Copyright (c) 2006 Red Hat, Inc., Ingo Molnar
[ 0.000000] ... MAX_LOCKDEP_SUBCLASSES: 8
[ 0.000000] ... MAX_LOCK_DEPTH: 48
[ 0.000000] ... MAX_LOCKDEP_KEYS: 8191
[ 0.000000] ... CLASSHASH_SIZE: 4096
[ 0.000000] ... MAX_LOCKDEP_ENTRIES: 16384
[ 0.000000] ... MAX_LOCKDEP_CHAINS: 32768
[ 0.000000] ... CHAINHASH_SIZE: 16384
[ 0.000000] memory used by lock dependency info: 3695 kB
[ 0.000000] per task-struct memory footprint: 1152 bytes
[ 0.004023] Calibrating delay loop... 996.14 BogoMIPS (lpj=4980736)
[ 0.090676] pid_max: default: 32768 minimum: 301
[ 0.091445] Security Framework initialized
[ 0.091776] Mount-cache hash table entries: 512
[ 0.098058] CPU: Testing write buffer coherency: ok
[ 0.098382] ftrace: allocating 21160 entries in 63 pages
[ 0.126601] hw perfevents: enabled with ARMv7 Cortex-A8 PMU driver, 5 counters available
[ 0.133068] devtmpfs: initialized
[ 0.154103] print_constraints: dummy:
[ 0.157604] NET: Registered protocol family 16
[ 0.260631] hw-breakpoint: debug architecture 0x4 unsupported.
[ 0.263427] IMX usb wakeup probe
[ 0.264627] IMX usb wakeup probe
[ 0.449381] bio: create slab <bio-0> at 0
[ 0.464045] SCSI subsystem initialized
[ 0.473849] usbcore: registered new interface driver usbfs
[ 0.476162] usbcore: registered new interface driver hub
[ 0.477914] usbcore: registered new device driver usb
[ 0.495895] print_constraints: VDDA: 3200 mV
[ 0.513397] print_constraints: DA9052_LDO1: 600 <--> 1800 mV at 1300 mV normal
[ 0.516061] print_constraints: DA9052_LDO2: 600 <--> 1800 mV at 1300 mV normal
[ 0.519344] print_constraints: DA9052_LDO3: 1725 <--> 3300 mV at 3300 mV normal
[ 0.522042] print_constraints: DA9052_LDO4: 1725 <--> 3300 mV at 2775 mV normal
[ 0.524827] print_constraints: DA9052_LDO5: 1200 <--> 3600 mV at 1300 mV normal
[ 0.527538] print_constraints: DA9052_LDO6: 1200 <--> 3600 mV at 1300 mV normal
[ 0.530887] print_constraints: DA9052_LDO7: 1200 <--> 3600 mV at 2750 mV normal
[ 0.533623] print_constraints: DA9052_LDO8: 1200 <--> 3600 mV at 1800 mV normal
[ 0.536356] print_constraints: DA9052_LDO9: 1250 <--> 3650 mV at 1500 mV normal
[ 0.539457] print_constraints: DA9052_LDO10: 1200 <--> 3600 mV at 1300 mV normal
[ 0.542192] print_constraints: DA9052_BUCK_CORE: 500 <--> 2075 mV at 1250 mV normal
[ 0.545002] print_constraints: DA9052_BUCK_PRO: 500 <--> 2075 mV at 1350 mV normal
[ 0.547981] print_constraints: DA9052_BUCK_MEM: 925 <--> 2500 mV at 1500 mV normal
[ 0.551103] print_constraints: DA9052_BUCK_PERI: 925 <--> 2500 mV at 2475 mV normal
[ 0.589102] imx-ipuv3 imx-ipuv3.0: IPU DMFC NORMAL mode: 1(0~1), 5B(4,5), 5F(6,7)
[ 0.597976] Advanced Linux Sound Architecture Driver Version 1.0.24.
[ 0.604901] NetLabel: Initializing
[ 0.604975] NetLabel: domain hash size = 128
[ 0.605009] NetLabel: protocols = UNLABELED CIPSOv4
[ 0.605669] NetLabel: unlabeled traffic allowed by default
[ 0.605886] Switching to clocksource mxc_timer1
[ 0.609218] Switched to NOHz mode on CPU #0
[ 0.851338] NET: Registered protocol family 2
[ 0.852417] IP route cache hash table entries: 16384 (order: 4, 65536 bytes)
[ 0.855402] TCP established hash table entries: 65536 (order: 7, 524288 bytes)
[ 0.857799] TCP bind hash table entries: 65536 (order: 9, 2359296 bytes)
[ 0.887402] TCP: Hash tables configured (established 65536 bind 65536)
[ 0.887671] TCP reno registered
[ 0.887770] UDP hash table entries: 256 (order: 2, 20480 bytes)
[ 0.888073] UDP-Lite hash table entries: 256 (order: 2, 20480 bytes)
[ 0.889346] NET: Registered protocol family 1
[ 0.891765] RPC: Registered named UNIX socket transport module.
[ 0.891849] RPC: Registered udp transport module.
[ 0.891884] RPC: Registered tcp transport module.
[ 0.891915] RPC: Registered tcp NFSv4.1 backchannel transport module.
[ 0.893324] Trying to unpack rootfs image as initramfs...
[ 0.913731] Freeing initrd memory: 156K
[ 0.916242] Bus freq driver module loaded
[ 0.917534] sdram autogating driver module loaded
[ 0.918212] i.MXC CPU frequency driver
[ 0.921523] DVFS driver module loaded
[ 0.924928] audit: initializing netlink socket (disabled)
[ 0.925503] type=2000 audit(0.880:1): initialized
[ 1.005479] Kprobe smoke test started
[ 1.025123] Kprobe smoke test passed successfully
[ 1.057084] highmem bounce pool size: 64 pages
[ 1.060672] ashmem: initialized
[ 1.067768] JFFS2 version 2.2. (NAND) (SUMMARY) © 2001-2006 Red Hat, Inc.
[ 1.071838] Btrfs loaded
[ 1.072008] msgmni has been set to 976
[ 1.080241] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 252)
[ 1.080556] io scheduler noop registered
[ 1.080621] io scheduler deadline registered
[ 1.080976] io scheduler cfq registered (default)
[ 1.088875] mxc_sdc_fb mxc_sdc_fb.0: register mxc display driver hdmi
[ 1.127056] sii902x 1-0039: cound not find device
[ 1.131843] mxc_sdc_fb mxc_sdc_fb.0: register mxc display driver failed with -22
[ 1.132085] mxc_sdc_fb: probe of mxc_sdc_fb.0 failed with error -22
[ 1.132278] mxc_sdc_fb mxc_sdc_fb.1: register mxc display driver vga
[ 1.132673] _regulator_get: get() with no identifier
[ 1.134800] imx-ipuv3 imx-ipuv3.0: Channel already disabled 9
[ 1.134834] imx-ipuv3 imx-ipuv3.0: Channel already uninitialized 9
[ 1.166194] imx-ipuv3 imx-ipuv3.0: IPU DMFC DP HIGH RESOLUTION: 1(0,1), 5B(2~5), 5F(6,7)
[ 1.222516] Console: switching to colour frame buffer device 128x48
[ 1.228823] imx-ipuv3 imx-ipuv3.0: Channel already disabled 10
[ 1.228859] imx-ipuv3 imx-ipuv3.0: Channel already uninitialized 10
[ 1.235291] imx-sdma imx35-sdma: loaded firmware 1.0
[ 1.283690] imx-sdma imx35-sdma: initialized
[ 1.287433] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled
[ 1.368198] Serial: IMX driver
[ 1.369108] imx21-uart.0: ttymxc0 at MMIO 0x53fbc000 (irq = 31) is a IMX
[ 2.116522] console [ttymxc0] enabled
[ 2.205802] brd: module loaded
[ 2.247464] loop: module loaded
[ 2.252422] Android kernel panic handler initialized (bind=kpanic)
[ 2.269999] mtdoops: mtd device (mtddev=name/number) must be supplied
[ 2.290209] FEC Ethernet Driver
[ 2.308923] fec_enet_mii_bus: probed
[ 2.323295] usbcore: registered new interface driver asix
[ 2.332876] usbcore: registered new interface driver cdc_ether
[ 2.343100] usbcore: registered new interface driver smsc95xx
[ 2.353029] usbcore: registered new interface driver net1080
[ 2.362867] usbcore: registered new interface driver cdc_subset
[ 2.372896] usbcore: registered new interface driver zaurus
[ 2.381557] cdc_ncm: 04-Aug-2011
[ 2.388606] usbcore: registered new interface driver cdc_ncm
[ 2.400751] ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver
[ 2.516118] fsl-ehci fsl-ehci.1: Freescale On-Chip EHCI Host Controller
[ 2.530830] fsl-ehci fsl-ehci.1: new USB bus registered, assigned bus number 1
[ 2.566211] fsl-ehci fsl-ehci.1: irq 14, io base 0x53f80200
[ 2.586187] fsl-ehci fsl-ehci.1: USB 2.0 started, EHCI 1.00
[ 2.596689] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002
[ 2.606242] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[ 2.616254] usb usb1: Product: Freescale On-Chip EHCI Host Controller
[ 2.625301] usb usb1: Manufacturer: Linux 3.1.0-rc9+ ehci_hcd
[ 2.633708] usb usb1: SerialNumber: fsl-ehci.1
[ 2.649194] hub 1-0:1.0: USB hub found
[ 2.655836] hub 1-0:1.0: 1 port detected

==============

[Abhishek Paliwal (abhishek-paliwal)]

Also observed on : https://android-build.linaro.org/builds/~linaro-android/staging-imx53-11.12-release/#build=7

[Abhishek Paliwal (abhishek-paliwal)]

Also observed with Ubuntu images:

http://snapshots.linaro.org/oneiric/linaro-o-ubuntu-desktop/20111220/0/images/tar/linaro-o-ubuntu-desktop-tar-20111220-0.tar.gz
http://snapshots.linaro.org/oneiric/lt-mx5-oneiric/20111220/0/images/hwpack/hwpack_linaro-lt-mx5_20111220-0_armel_supported.tar.gz

[Abhishek Paliwal (abhishek-paliwal)]

Also observed on Android ICS images:
https://android-build.linaro.org/builds/~linaro-android/staging-imx53/#build=135

[Abhishek Paliwal (abhishek-paliwal)]

Frequent hangs while bootup observed with build:
https://android-build.linaro.org/builds/~linaro-android/staging-imx53-12.01-release/#build=2

[Botao (botao-sun)]

The boot works well on 12.01 RC build:

https://android-build.linaro.org/builds/~linaro-android/staging-imx53-12.01-release/#build=6

[Abhishek Paliwal (abhishek-paliwal)]

Also observed on:
https://android-build.linaro.org/builds/~linaro-android/imx53-ics-gcc46-freescalelt-stable-open-12.03-release/#build=1

[Bernhard Rosenkraenzer (berolinux)]

I suspect this is triggered by minor board differences (or connected devices?), given it works most of the time for me and botao (comment#5) and frequently hangs for Abhishek.

[Zach Pfeffer (pfefferz)]

I see https://android-build.linaro.org/builds/~linaro-android/imx53-ics-gcc47-freescalelt-stable-open-12.05-release/#build=2 boot on the second try. I have a mouse, keyboard, network, VGA and Serial-to-USB plugged in. When I booted up the unit, it hung in the black screen, but the log didn't indicate that it had crashed. This boot is recorded in minicom_imx53_boothangs.txt. I rebooted the unit and recorded minicom_imx53_booted.txt.

[Zach Pfeffer (pfefferz)]

Boot hung.

[Zach Pfeffer (pfefferz)]

Boot succeeded.

[Botao (botao-sun)]

On build:

https://android-build.linaro.org/builds/~linaro-android/imx53-ics-gcc47-freescalelt-stable-open-12.05-release/#build=2

I got the boot issue, refer to attachment to get the snapshot, and I also paste the console output here:

###############################################

Uncompressing Linux... done, booting the kernel.
[ 0.000000] Initializing cgroup subsys cpuset
[ 0.000000] Linux version 3.1r May 7 06:16:47 UTC 2012
[ 0.000000] CPU: ARMv7 Processor [412fc085] revision 5 (ARMv7), cr=10c53
[ 0.000000] CPU: VIPT nonaliasing data cache, VIPT aliasing instruction cache
[ 0.000000] Machine: Freescale MX53 LOCO 0.000000] Memory policy: ECC disk
[ 0.000000] Built 1 zonelists in Zone order, ity grouping on. Total pages: 8
[ 0.000000] Kernel command line: console=ttymxc0,115200n8 rootwait rarlyprin
[ 0.000000 0.000000] PID hash table entries: 2048 (order: 1, 8192 bytes)
[ 0.000000] Dentry cache hash table enies: 65536 (order: 6, 262144 bytes)
[ 0.000000] Inode-cache hash table entries: 32768 (order: 5, 131072 bytes
                                                                            [ l
[ 0.000000] Memory: 958700k/958700k available, 89876k reser000 ( 4 kB)
[ 0.000000] fixmap : 0xfff00000 - 0xfffe0000 ( 896 kB)
[ 0.000000] DMA : 0xfe00000 - 0xffe00000 ( 128 MB)
[ 0.000000] vmalloc : 0xe0800000 - 0xf4000000 ( 312 MB)
[ 0.000000 lowmem : 0xc0000000 - 0xe0000000 ( 512 MB)
[ 0.000000] pkmap : 0xbfe00000 - 0xc0000000 ( 2 MB) 0.000000] )
[ 0.000000] .text : 0xc0008000 - 0xcd3dd8 (7984 kB)
[ 0.000000] .init : 0xc07d4000 - 0xc0821000 ( 308 kB)
[ 0.000000] .data :xc0822000 - 0xc08821b0 ( 385 kB)
[ 0.000000] .bss : 0xc08821d4 - 0xc0f192b0 (6749 kB)
[ 0.000000reemptible hierarchical RCU implementation.
[ 0.000000] NR_IRQS:400
[ 0.000000] TrustZone Interrupt Contoller (TZIC) initialized
[ 0.000000] sched_clock: 32 bits at 8MHz, resolution 125ns, wraps every 5368s
[ 0.000000] Console: colour dummy device 80x30
[ 0.000000] ram_console: buffer (null), invalid size 0, datasie 4294967284
[ 0.000000] Lock dependency validator: Copyright (c) 2006 Red Hat, Inc., Ingr
[ 0.0000] ... MAX_LOCKDEP_SUBCLASSES: 8
[ 0.000000] ... MAX_LOCK_DEPTH: 48
[ 0.000000] ... MAX_LOCKDEKEYS: 8191
[ 0.000000] ... CLASSHASH_SIZE: 4096
[ 0.000000] ... MAX_LOCKDEP_ENTRIES: 1684
[ 0.000000] ... MAX_LOCKDEP_CHAINS: 32768
[ 0.000000] ... CHAINHASH_SIZE: 16384 ...

[Botao (botao-sun)]

Above information comes from a boot up with a USB mouse attached and an Ethernet cable plugged in. And after I reset the board, it even can't boot up with any display on my monitor. Therefore, I plugged out the USB mouse and reset the board again, then the display came out but I finally got the same snapshot as I attached previously.

I have checked the MD5SUM of the packages I downloaded, and they all matched. The version of Linaro Image Tool I used is 514. However, even that "Encryption Unsuccessful" continuously showed up, I still can enter the serial console and do something, such like run "busybox top".

Then I re-flashed my SD card and tried again, this time, I got another frozen screen - refer to attachment, and the console output is here:
##############################################
Welcome to minicom 2.4

OPTIONS: I18n
Compiled on Jun 3 2010, 13:48:00.
Port /dev/ttyUSB0

Press CTRL-A Z for help on special keys

U-Boot 2012.04.01 (May 07 2012 - 05:30:13)

Board: MX53 LOCO
I2C: ready
DRAM: 1 GiB
WARNING: Caches not enabled
MMC: FSL_SDHC: 0, FSL_SDHC: 1
*** Warning - bad CRC, using default environment

In: serial
Out: serial
Err: serial
CPU: Freescale i.MX53 family rev2.1 at 1000 MHz
Reset cause: POR
Net: FEC
Hit any key to stop autoboot: 0
reading boot.scr

408 bytes read
Running bootscript from mmc ...
## Executing script at 70800000
reading uImage

4115936 bytes read
reading uInitrd

190252 bytes read
## Booting kernel from Legacy Image at 70000000 ...
   Image Name: Linux-3.1.0-rc9+
   Image Type: ARM Linux Kernel Image (uncompressed)
   Data Size: 4115872 Bytes = 3.9 MiB
   Load Address: 70008000
   Entry Point: 70008000
   Verifying Checksum ... OK
## Loading init Ramdisk from Legacy Image at 72000000 ....

[Botao (botao-sun)]

After above frozen screen shows, then I plugged USB keyboard, and press F1, the board finally can enter the main screen. According to above experience, although the board finally came to the UI display, I don't think this image is OK for the end users.

[Botao (botao-sun)]

On build:

https://android-build.linaro.org/builds/~linaro-android/imx53-ics-gcc47-freescalelt-stable-open-12.05-release/#build=3

Even there is no any USB device plugged in before system boot, the system is still not easy to enter the main screen. If finally got a black screen or frozen screen, press power key to try. I did once, and it entered main screen.

[Botao (botao-sun)]

For iMX53, on build:

https://android-build.linaro.org/builds/~linaro-android/imx53-ics-gcc47-freescalelt-stable-open-12.05-release/#build=4

At the first boot up after SD card flashing, I get this error - "Launcher is not responding." And I find the a process named "surfaceflinger" occupys most of CPU time:

  PID PPID USER STAT VSZ %VSZ CPU %CPU COMMAND
 1088 1 system S 40988 4.2 0 83.8 /system/bin/surfaceflinger