2 minute pause in MMC boot

I have an important hint as to what is going on.  If I plug the ethernet cable into my EVM, then the MMC boot works without a delay.  The boot log is posted below.  I have done a side by side comparison of the boot log, and the important line is bolded below (and copied here):

[ 4.853477] PHY: 0:00 - Link is Up - 100/Full       (I get this when it works without a delay)

So it seems that there is an enormous timeout on the Ethernet connection that blocks the kernel bootup.  Hopefully there is a kernel command line or build option that won't do this?  I cannot rely on this Ethernet connection being present in our final product.

Thanks for any advice!

reading uImage

3061584 bytes read
## Booting kernel from Legacy Image at 80007fc0 ...
Image Name: Linux-3.2.0
Image Type: ARM Linux Kernel Image (uncompressed)
Data Size: 3061520 Bytes = 2.9 MiB
Load Address: 80008000
Entry Point: 80008000
Verifying Checksum ... OK
XIP Kernel Image ... OK
OK

Starting kernel ...

Uncompressing Linux... done, booting the kernel.
[ 0.000000] CPU: ARMv7 Processor [413fc082] revision 2 (ARMv7), cr=10c53c7d
[ 0.000000] CPU: PIPT / VIPT nonaliasing data cache, VIPT aliasing instruction cache
[ 0.000000] Machine: am335xevm
[ 0.000000] Memory policy: ECC disabled, Data cache writeback
[ 0.000000] AM335X ES1.0 (sgx neon )
[ 0.000000] Built 1 zonelists in Zone order, mobility grouping on. Total pages: 65024
[ 0.000000] Kernel command line: console=ttyO0,115200n8 root=/dev/mmcblk0p2 rw rootfstype=ext3 rootwait ip=static
[ 0.000000] PID hash table entries: 1024 (order: 0, 4096 bytes)
[ 0.000000] Dentry cache hash table entries: 32768 (order: 5, 131072 bytes)
[ 0.000000] Inode-cache hash table entries: 16384 (order: 4, 65536 bytes)
[ 0.000000] Memory: 256MB = 256MB total
[ 0.000000] Memory: 253468k/253468k available, 8676k reserved, 0K highmem
[ 0.000000] Virtual kernel memory layout:
[ 0.000000] vector : 0xffff0000 - 0xffff1000 ( 4 kB)
[ 0.000000] fixmap : 0xfff00000 - 0xfffe0000 ( 896 kB)
[ 0.000000] vmalloc : 0xd0800000 - 0xff000000 ( 744 MB)
[ 0.000000] lowmem : 0xc0000000 - 0xd0000000 ( 256 MB)
[ 0.000000] modules : 0xbf000000 - 0xc0000000 ( 16 MB)
[ 0.000000] .text : 0xc0008000 - 0xc0575000 (5556 kB)
[ 0.000000] .init : 0xc0575000 - 0xc05b2000 ( 244 kB)
[ 0.000000] .data : 0xc05b2000 - 0xc060fb18 ( 375 kB)
[ 0.000000] .bss : 0xc060fb3c - 0xc063c7e4 ( 180 kB)
[ 0.000000] NR_IRQS:396
[ 0.000000] IRQ: Found an INTC at 0xfa200000 (revision 5.0) with 128 interrupts
[ 0.000000] Total of 128 interrupts on 1 active controller
[ 0.000000] OMAP clockevent source: GPTIMER2 at 24000000 Hz
[ 0.000000] omap_dm_timer_switch_src: Switching to HW default clocksource(sys_clkin_ck) for timer1, this may impact timekeeping in low power state
[ 0.000000] OMAP clocksource: GPTIMER1 at 24000000 Hz
[ 0.000000] sched_clock: 32 bits at 24MHz, resolution 41ns, wraps every 178956ms
[ 0.000000] Console: colour dummy device 80x30
[ 0.000192] Calibrating delay loop... 718.02 BogoMIPS (lpj=3590144)
[ 0.057157] pid_max: default: 32768 minimum: 301
[ 0.057285] Security Framework initialized
[ 0.057394] Mount-cache hash table entries: 512
[ 0.057774] CPU: Testing write buffer coherency: ok
[ 0.077762] omap_hwmod: gfx: failed to hardreset
[ 0.094017] omap_hwmod: pruss: failed to hardreset
[ 0.095137] print_constraints: dummy:
[ 0.095497] NET: Registered protocol family 16
[ 0.097694] OMAP GPIO hardware version 0.1
[ 0.100297] omap_mux_init: Add partition: #1: core, flags: 0
[ 0.102503] omap_i2c.1: alias fck already exists
[ 0.103415] omap2_mcspi.1: alias fck already exists
[ 0.103632] omap2_mcspi.2: alias fck already exists
[ 0.103891] edma.0: alias fck already exists
[ 0.103913] edma.0: alias fck already exists
[ 0.103932] edma.0: alias fck already exists
[ 0.128731] bio: create slab <bio-0> at 0
[ 0.130907] SCSI subsystem initialized
[ 0.132535] usbcore: registered new interface driver usbfs
[ 0.132851] usbcore: registered new interface driver hub
[ 0.133060] usbcore: registered new device driver usb
[ 0.133207] musb-ti81xx musb-ti81xx: musb0, board_mode=0x13, plat_mode=0x3
[ 0.133492] musb-ti81xx musb-ti81xx: musb1, board_mode=0x13, plat_mode=0x1
[ 0.147230] omap_i2c omap_i2c.1: bus 1 rev2.4.0 at 100 kHz
[ 0.149113] tps65910 1-002d: JTAGREVNUM 0x0
[ 0.151510] print_constraints: VRTC:
[ 0.152971] print_constraints: VIO: at 1800 mV
[ 0.155287] print_constraints: VDD1: 600 <--> 1500 mV at 1262 mV normal
[ 0.157619] print_constraints: VDD2: 600 <--> 1500 mV at 1137 mV normal
[ 0.158624] print_constraints: VDD3: 5000 mV
[ 0.160040] print_constraints: VDIG1: at 1800 mV
[ 0.161469] print_constraints: VDIG2: at 1800 mV
[ 0.162884] print_constraints: VPLL: at 1800 mV
[ 0.164312] print_constraints: VDAC: at 1800 mV
[ 0.165728] print_constraints: VAUX1: at 1800 mV
[ 0.167186] print_constraints: VAUX2: at 3300 mV
[ 0.168616] print_constraints: VAUX33: at 3300 mV
[ 0.170048] print_constraints: VMMC: at 3300 mV
[ 0.170553] tps65910 1-002d: No interrupt support, no core IRQ
[ 0.171472] Advanced Linux Sound Architecture Driver Version 1.0.24.
[ 0.172622] Switching to clocksource gp timer
[ 0.188250] musb-hdrc: version 6.0, ?dma?, otg (peripheral+host)
[ 0.188431] musb-hdrc musb-hdrc.0: dma type: pio
[ 0.189291] musb-hdrc musb-hdrc.0: USB OTG mode controller at d081c000 using PIO, IRQ 18
[ 0.189454] musb-hdrc musb-hdrc.1: dma type: pio
[ 0.189860] musb-hdrc musb-hdrc.1: MUSB HDRC host driver
[ 0.189935] musb-hdrc musb-hdrc.1: new USB bus registered, assigned bus number 1
[ 0.190070] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002
[ 0.190085] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[ 0.190099] usb usb1: Product: MUSB HDRC host driver
[ 0.190110] usb usb1: Manufacturer: Linux 3.2.0 musb-hcd
[ 0.190120] usb usb1: SerialNumber: musb-hdrc.1
[ 0.190910] hub 1-0:1.0: USB hub found
[ 0.190943] hub 1-0:1.0: 1 port detected
[ 0.191475] musb-hdrc musb-hdrc.1: USB Host mode controller at d081e800 using PIO, IRQ 19
[ 0.191909] NET: Registered protocol family 2
[ 0.192104] IP route cache hash table entries: 2048 (order: 1, 8192 bytes)
[ 0.192424] TCP established hash table entries: 8192 (order: 4, 65536 bytes)
[ 0.192581] TCP bind hash table entries: 8192 (order: 3, 32768 bytes)
[ 0.192746] TCP: Hash tables configured (established 8192 bind 8192)
[ 0.192759] TCP reno registered
[ 0.192774] UDP hash table entries: 256 (order: 0, 4096 bytes)
[ 0.192798] UDP-Lite hash table entries: 256 (order: 0, 4096 bytes)
[ 0.192986] NET: Registered protocol family 1
[ 0.193246] RPC: Registered named UNIX socket transport module.
[ 0.193260] RPC: Registered udp transport module.
[ 0.193269] RPC: Registered tcp transport module.
[ 0.193278] RPC: Registered tcp NFSv4.1 backchannel transport module.
[ 0.193526] NetWinder Floating Point Emulator V0.97 (double precision)
[ 0.205700] VFS: Disk quotas dquot_6.5.2
[ 0.205774] Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
[ 0.206334] msgmni has been set to 495
[ 0.207085] io scheduler noop registered
[ 0.207100] io scheduler deadline registered
[ 0.207164] io scheduler cfq registered (default)
[ 0.210961] omap_uart.0: ttyO0 at MMIO 0x44e09000 (irq = 72) is a OMAP UART0
[ 0.829929] console [ttyO0] enabled
[ 0.834225] omap_uart.1: ttyO1 at MMIO 0x48022000 (irq = 73) is a OMAP UART1
[ 0.842027] omap_uart.2: ttyO2 at MMIO 0x48024000 (irq = 74) is a OMAP UART2
[ 0.849843] omap_uart.3: ttyO3 at MMIO 0x481a6000 (irq = 44) is a OMAP UART3
[ 0.857647] omap_uart.4: ttyO4 at MMIO 0x481a8000 (irq = 45) is a OMAP UART4
[ 0.865425] omap_uart.5: ttyO5 at MMIO 0x481aa000 (irq = 46) is a OMAP UART5
[ 0.882472] brd: module loaded
[ 0.890649] loop: module loaded
[ 0.894172] i2c-core: driver [tsl2550] using legacy suspend method
[ 0.900618] i2c-core: driver [tsl2550] using legacy resume method
[ 0.907058] at24 1-0051: 32768 byte 24c256 EEPROM, writable, 64 bytes/write
[ 0.920968] Detected a daughter card on AM335x EVM..
[ 0.925978] Unknown CPLD version found, falling back to 1.0A
[ 0.932096] at24 1-0050: 32768 byte 24c256 EEPROM, writable, 64 bytes/write
[ 0.947263] Board name: A33515BB
[ 0.950626] Board version: 1.2A
[ 0.953909] SKU: SKU#01
[ 0.956986] The board is general purpose EVM in profile 0
[ 0.962614] Found invalid GP EVM revision, falling back to Rev1.1A
[ 0.969373] da8xx_lcdc.0: alias fck already exists
[ 0.975194] da8xx_lcdc da8xx_lcdc.0: GLCD: Found TFC_S9700RTWV35TR_01B panel
[ 0.998807] Console: switching to colour frame buffer device 100x30
[ 1.014233] TSC connected to beta GP EVM
[ 1.019659] omap-gpmc omap-gpmc: GPMC revision 6.0
[ 1.024706] Registering NAND on CS0
[ 1.029058] omap_i2c.2: alias fck already exists
[ 1.052837] omap_i2c omap_i2c.2: bus 2 rev2.4.0 at 100 kHz
[ 1.059517] tsl2550 2-0039: standard operating mode
[ 1.065333] tsl2550 2-0039: support ver. 1.2 enabled
[ 1.070928] davinci-mcasp.1: alias fck already exists
[ 1.076785] omap_hsmmc.0: alias fck already exists
[ 1.082185] omap_hsmmc.2: alias fck already exists
[ 1.087584] Configure Bluetooth Enable pin...
[ 1.093384] _regulator_get: 2-0018 supply Vdd not found, using dummy regulator
[ 1.100992] _regulator_get: 2-0018 supply Vdd_IO not found, using dummy regulator
[ 1.129447] lis3lv02d: 8 bits 3DLH sensor found
[ 1.223099] input: ST LIS3LV02DL Accelerometer as /devices/platform/lis3lv02d/input/input0
[ 1.233993] mtdoops: mtd device (mtddev=name/number) must be supplied
[ 1.241302] omap2-nand driver initializing
[ 1.245929] ONFI flash detected
[ 1.249327] ONFI param page 0 valid
[ 1.252991] NAND device: Manufacturer ID: 0x2c, Chip ID: 0xda (Micron MT29F2G08ABAEAWP)
[ 1.261580] Creating 8 MTD partitions on "omap2-nand.0":
[ 1.267154] 0x000000000000-0x000000020000 : "SPL"
[ 1.273632] 0x000000020000-0x000000040000 : "SPL.backup1"
[ 1.280588] 0x000000040000-0x000000060000 : "SPL.backup2"
[ 1.287486] 0x000000060000-0x000000080000 : "SPL.backup3"
[ 1.294395] 0x000000080000-0x000000260000 : "U-Boot"
[ 1.301538] 0x000000260000-0x000000280000 : "U-Boot Env"
[ 1.308386] 0x000000280000-0x000000780000 : "Kernel"
[ 1.316895] 0x000000780000-0x000010000000 : "File System"
[ 1.426874] OneNAND driver initializing
[ 1.432318] CAN device driver interface
[ 1.436369] CAN bus driver for Bosch D_CAN controller 1.0
[ 1.492685] davinci_mdio davinci_mdio.0: davinci mdio revision 1.6
[ 1.499139] davinci_mdio davinci_mdio.0: detected phy mask fffffffe
[ 1.506337] davinci_mdio.0: probed
[ 1.509889] davinci_mdio davinci_mdio.0: phy[0]: device 0:00, driver unknown
[ 1.517606] usbcore: registered new interface driver zd1201
[ 1.523633] usbcore: registered new interface driver cdc_ether
[ 1.529869] usbcore: registered new interface driver cdc_eem
[ 1.535948] usbcore: registered new interface driver dm9601
[ 1.541804] cdc_ncm: 04-Aug-2011
[ 1.545360] usbcore: registered new interface driver cdc_ncm
[ 1.551269] Initializing USB Mass Storage driver...
[ 1.556597] usbcore: registered new interface driver usb-storage
[ 1.562877] USB Mass Storage support registered.
[ 1.568160] mousedev: PS/2 mouse device common for all mice
[ 1.574952] input: matrix-keypad as /devices/platform/matrix-keypad/input/input1
[ 1.584136] input: ti-tsc-adcc as /devices/platform/omap/tsc/input/input2
[ 1.592596] omap_rtc omap_rtc: rtc core: registered omap_rtc as rtc0
[ 1.599476] i2c /dev entries driver
[ 1.603748] Linux video capture interface: v2.00
[ 1.608893] usbcore: registered new interface driver uvcvideo
[ 1.614911] USB Video Class driver (1.1.1)
[ 1.620068] lm75 2-0048: hwmon0: sensor 'tmp275'
[ 1.627726] OMAP Watchdog Timer Rev 0x01: initial timeout 60 sec
[ 1.636301] cpuidle: using governor ladder
[ 1.641053] cpuidle: using governor menu
[ 1.650917] usbcore: registered new interface driver usbhid
[ 1.656775] usbhid: USB HID core driver
[ 1.661361] usbcore: registered new interface driver snd-usb-audio
[ 1.669960] _regulator_get: 2-001b supply IOVDD not found, using dummy regulator
[ 1.677775] _regulator_get: 2-001b supply DVDD not found, using dummy regulator
[ 1.685476] _regulator_get: 2-001b supply AVDD not found, using dummy regulator
[ 1.693156] _regulator_get: 2-001b supply DRVDD not found, using dummy regulator
[ 1.703802] asoc: tlv320aic3x-hifi <-> davinci-mcasp.1 mapping ok
[ 1.711580] ALSA device list:
[ 1.714766] #0: AM335X EVM
[ 1.717766] oprofile: hardware counters not available
[ 1.723040] oprofile: using timer interrupt.
[ 1.727517] nf_conntrack version 0.5.0 (3960 buckets, 15840 max)
[ 1.734316] ip_tables: (C) 2000-2006 Netfilter Core Team
[ 1.739975] TCP cubic registered
[ 1.743377] NET: Registered protocol family 17
[ 1.748024] can: controller area network core (rev 20090105 abi 8)
[ 1.754573] NET: Registered protocol family 29
[ 1.759207] can: raw protocol (rev 20090105)
[ 1.763674] can: broadcast manager protocol (rev 20090105 t)
[ 1.769613] Registering the dns_resolver key type
[ 1.774613] VFP support v0.3: implementor 41 architecture 3 part 30 variant c rev 3
[ 1.782614] ThumbEE CPU extension supported.
[ 1.787153] mux: Failed to setup hwmod io irq -22
[ 1.792732] Power Management for AM33XX family
[ 1.797584] Trying to load am335x-pm-firmware.bin (60 secs timeout)
[ 1.804256] Copied the M3 firmware to UMEM
[ 1.808543] omap_hwmod: wkup_m3: wkup_m3: hwmod data error: OMAP4 does not support st_shift
[ 1.825922] clock: disabling unused clocks to save power
[ 1.833690] Detected MACID=d4:94:a1:52:35:5f
[ 1.843496] input: gpio-keys as /devices/platform/gpio-keys/input/input3
[ 1.851106] omap_rtc omap_rtc: setting system clock to 2000-01-01 00:00:01 UTC (946684801)
[ 1.862500]
[ 1.862506] CPSW phy found : id is : 0x4dd074
[ 1.869394] PHY 0:01 not found
[ 1.963300] mmc0: new high speed SDHC card at address 534e
[ 1.969732] mmcblk0: mmc0:534e SD16G 14.9 GiB
[ 1.976401] mmcblk0: p1 p2
[ 2.087201] mmc1: card claims to support voltages below the defined range. These will be ignored.
[ 2.106174] mmc1: queuing unknown CIS tuple 0x91 (3 bytes)
[ 2.112762] mmc1: new SDIO card at address 0001
[ 4.853477] PHY: 0:00 - Link is Up - 100/Full
[ 4.882686] IP-Config: Guessing netmask 255.255.0.0
[ 4.887954] IP-Config: Complete:
[ 4.891317] device=eth0, addr=133.0.0.0, mask=255.255.0.0, gw=255.255.255.255,
[ 4.899070] host=133.0.0.0, domain=, nis-domain=(none),
[ 4.904981] bootserver=255.255.255.255, rootserver=255.255.255.255, rootpath=
[ 9.390643] kjournald starting. Commit interval 5 seconds
[ 9.608082] EXT3-fs (mmcblk0p2): using internal journal
[ 9.613559] EXT3-fs (mmcblk0p2): recovery complete
[ 9.828465] EXT3-fs (mmcblk0p2): mounted filesystem with ordered data mode
[ 9.835715] VFS: Mounted root (ext3 filesystem) on device 179:2.
[ 9.842381] Freeing init memory: 244K
INIT: version 2.86 booting
Please wait: booting...
Starting udev
[ 10.363173] udevd (707): /proc/707/oom_adj is deprecated, please use /proc/707/oom_score_adj instead.
[ 11.624876] Disabling lock debugging due to kernel taint
[ 11.643322] cfg80211: Calling CRDA to update world regulatory domain
[ 14.802590] cfg80211: World regulatory domain updated:
[ 14.808063] cfg80211: (start_freq - end_freq @ bandwidth), (max_antenna_gain, max_eirp)
[ 14.816790] cfg80211: (2402000 KHz - 2472000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
[ 14.825061] cfg80211: (2457000 KHz - 2482000 KHz @ 20000 KHz), (300 mBi, 2000 mBm)
[ 14.833338] cfg80211: (2474000 KHz - 2494000 KHz @ 20000 KHz), (300 mBi, 2000 mBm)
[ 14.841597] cfg80211: (5170000 KHz - 5250000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
[ 14.849868] cfg80211: (5735000 KHz - 5835000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
[ 15.914487] wl1271: loaded
[ 16.041158] alignment: ignoring faults is unsafe on this CPU. Defaulting to fixup mode.
Remounting root file system...
Caching udev devnodes
logger: mount: special device /dev/sda1 does not exist
logger: mount: special device /dev/sdb1 does not exist
ALSA: Restoring mixer settings...
No state is present for card EVM
Configuring network interfaces... Found hardware: "AM335X_EVM" "" "" "" ""
Hardware is initialized using a generic method
No state is present for card EVM
[ 22.378006]
[ 22.378017] CPSW phy found : id is : 0x4dd074
[ 22.384957] PHY 0:01 not found
eth0 no wireless extensions.

udhcpc (v1.13.2) started
Sending discover...
[ 24.373639] PHY: 0:00 - Link is Up - 100/Full
Sending discover...
Sending select for 192.168.1.133...
Lease of 192.168.1.133 obtained, lease time 86400
adding dns 192.168.1.254
done.
Setting up IP spoofing protection: rp_filter.
Wed Apr 11 08:27:00 UTC 2012
INIT: Entering runlevel: 5
Starting system message bus: dbus.
Starting Hardware abstraction layer hald
Starting Dropbear SSH server: dropbear.
Starting telnet daemon.
Starting network benchmark server: netserver.
Starting syslogd/klogd: done
Starting thttpd.
Starting PVR
Usage: insmod filename [args]
Could not find pvrsrvkm driver
Starting Lighttpd Web Server: lighttpd.
Starting avahi daemon...
2012-04-11 08:27:01: (log.c.166) server started

You need to select a boot sequence that does not have Ethernet boot before MMC boot.

Please refer to the Booting section in the AM335x TRM.

The SYSBOOT[4:0] inputs select the boot sequence on the rising edge of PWRONRSTn.

Regards,
Paul

Can you try these simple tests?

1. Set  a static ip and pass it using boot args and see the delay.

2. Use an Ethernet cross cable to connect to your PC directly and run a DHCP server on your PC and see the delay.

3. Use cross cable and try static IP at both ends and see the delay?

Hi Paul

Thanks for the suggestion.  I experimented with the boot mode using the switches on the EVM, but it does not make a difference to this problem.  I am using boot mode 0x10111, which does not include EMAC at all, but the problem persists.

Also, note that chip's bootloader (which is what SYSBOOT affects) seems to work fine, without any delay.  MLO/u-boot load from MMC without any delay.  This delay problem is occuring when the linux kernel is booting.

Hi Renjith

Thanks for the ideas.  I have experimented with passing DHCP and static IP addresses to the kernel.  Answers are

1. static IP, Ethernet cable connected: no delay
2. static IP, Ethernet cable not connected: 2 minute delay
3. DHCP, cable connected to DHCP server: short (2-3 second) delay while waiting for DHCP response
4. DHCP, cable not connected to DHCP server: 2 minute delay

So it seems the key factor is actually having the Ethernet cable attached to the EVM.

One further observation: if I plug the Ethernet cable in to the Ethernet port at any time while it is waiting, then the boot sequence immediately continues.  e.g.,

[ 1.869435] PHY 0:01 not found
[ 1.963208] mmc0: new high speed SDHC card at address 534e
[ 1.969658] mmcblk0: mmc0:534e SD16G 14.9 GiB
[ 1.976325] mmcblk0: p1 p2
[ 2.087118] mmc1: card claims to support voltages below the defined range. These will be ignored.
[ 2.106091] mmc1: queuing unknown CIS tuple 0x91 (3 bytes)
[ 2.112680] mmc1: new SDIO card at address 0001

Plug cable in...and immediately get:

[ 12.853392] PHY: 0:00 - Link is Up - 100/Full
[ 12.882599] IP-Config: Guessing netmask 255.255.0.0
[ 12.887878] IP-Config: Complete:
[ 12.891242] device=eth0, addr=133.0.0.0, mask=255.255.0.0, gw=255.255.255.255,
[ 12.898991] host=133.0.0.0, domain=, nis-domain=(none),
[ 12.904905] bootserver=255.255.255.255, rootserver=255.255.255.255, rootpath=

I think its waiting for Ethernet link to be up and I'm just guessing that there might be some kind of timeout. 

Yes, I agree.  It seems like the kernel is waiting for the Ethernet link...but I really don't know why it would be doing so or how to prevent it.  Any ideas are welcome!

We need to have a deeper look into the Ethernet driver. You can try to enable debug prints inside the emac driver and also enable kernel time stamps and then verify the functions that is taking more time. I guess that will be the simplest method to debug this.

Glad that its fixed. Can you mark this post as answered if you think so?