Linux/AM3358: Delay between starting kernel and first log print

Ugnius Subacius

Part Number: AM3358

Tool/software: Linux

Hi,

I am running a custom board with am3358 processor and using processor SDK 03.03.

I am optimising the boot time and something that jumps out to me at the moment is the time delay after booting from nand is printed and first kernel print.

It is more than 2 seconds. That time is longer than time spent loading everything from NAND to RAM.

Could anyone explain what is happening during that time?

Kind regards,

Ugnius

over 7 years ago

0 Steve Kipisz over 7 years ago

TI__Genius 15510 points

Hello,
I am looking at this.

Steve K.

0 Steve Kipisz over 7 years ago in reply to Steve Kipisz

TI__Genius 15510 points

Can you attach the full log?

Thanks,
Steve K.

0 Ugnius Subacius over 7 years ago in reply to Steve Kipisz

Expert 1180 points

Hi Steve,

Here is the full log.

I checked it booting from SD card and NAND using Falcon mode.

In all cases it took long time between printing "Starting kernel ..." and the first message from the kernel.

e31034fac832d29ed8584666c1337702343_code-editor-fs">Fullscreen com/cfs-filesystemfile/__key/communityserver-discussions-components-files/791/sd-boot-log.txt?_=636558415920000000" sd boot log.txt">sd boot log.txt com/cfs-filesystemfile/__key/communityserver-discussions-components-files/791/sd-boot-log.txt?_=636558415920000000" sd boot log.txt">Download 34fac832d29ed8584666c1337702343_code-editor" width:1230px;margin:0px;" Mar 01 14:57:04.878 2018] U-Boot SPL 2016.05-gf4c49fc-dirty (Mar 01 2018 - 14:45:48) 2018] Trying to boot from NAND 2018] The Expected Linux image was not found. Please check your NAND configuration. 2018] Trying to start u-boot now... 2018] U-Boot 2016.05-gf4c49fc-dirty (Mar 01 2018 - 14:45:48 +0000) : AM335X-GP rev 2.1 2018] Model: TI AM335x EVM-SK Watchdog enabled 256 MiB 1024 MiB OMAP SD/MMC: 0, OMAP SD/MMC: 1 2018] Card did not respond to voltage select! 2018] ** Bad device mmc 0 ** 2018] Using default environment 2018] <ethaddr> not set. Validating first E-fuse MAC 2018] Warning: usb_ether MAC addresses don't match: 2018] Address in SROM is de:ad:be:ef:00:01 2018] Address in environment is 04:a3:16:fb:e7:1c 2018] eth0: usb_ether 2018] Press SPACE to abort autoboot in 3 seconds 2018] Card did not respond to voltage select! 2018] Card did not respond to voltage select! 2018] Card did not respond to voltage select! 2018] Card did not respond to voltage select! 2018] Card did not respond to voltage select! 2018] Card did not respond to voltage select! 2018] Card did not respond to voltage select! 2018] Card did not respond to voltage select! 2018] Booting from nand ... 2018] NAND read: device 0 offset 0x6c0000, size 0x40000 262144 bytes read: OK 2018] NAND read: device 0 offset 0x2c0000, size 0x400000 4194304 bytes read: OK 2018] Kernel image @ 0x82000000 [ 0x000000 - 0x30b4f0 ] 2018] ## Flattened Device Tree blob at 88000000 Booting using the fdt blob at 0x88000000 Loading Device Tree to 8ef19000, end 8ef25b49 ... OK 2018] Starting kernel ... 0.000000] Booting Linux on physical CPU 0x0 0.000000] Initializing cgroup subsys cpu 0.000000] Initializing cgroup subsys cpuacct 0.000000] Linux version 4.4.41-rt50-g968d071ce9(gcc version 5.3.1 20160113 (Linaro GCC 5.3-2016.02) ) #130 PREEMPT RT Thu Mar 1 03:10:19 PST 2018 0.000000] CPU: ARMv7 Processor [413fc082] revision 2 (ARMv7), cr=10c5387d 0.000000] CPU: PIPT / VIPT nonaliasing data cache, VIPT aliasing instruction cache 0.000000] Machine model: TI AM335x EVM-SK 0.000000] cma: Reserved 48 MiB at 0x8b800000 0.000000] Memory policy: Data cache writeback 0.000000] CPU: All CPU(s) started in SVC mode. 0.000000] AM335X ES2.1 (sgx neon ) 0.000000] Built 1 zonelists in Zone order, mobility grouping on. Total pages: 64960 0.000000] Kernel command line: console=ttyO0,115200n8 consoleblank=0 root=ubi0:rootfs rw ubi.mtd=NAND.file-system rootfstype=ubifs rootwait=1 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: 200556K/262144K available (5835K kernel code, 314K rwdata, 2196K rodata, 932K init, 302K bss, 12436K reserved, 49152K cma-reserved, 0K highmem) 0.000000] Virtual kernel memory layout: 0.000000] vector : 0xffff0000 - 0xffff1000 ( 4 kB) 0.000000] fixmap : 0xffc00000 - 0xfff00000 (3072 kB) 0.000000] vmalloc : 0xd0800000 - 0xff800000 ( 752 MB) 0.000000] lowmem : 0xc0000000 - 0xd0000000 ( 256 MB) 0.000000] pkmap : 0xbfe00000 - 0xc0000000 ( 2 MB) 0.000000] modules : 0xbf000000 - 0xbfe00000 ( 14 MB) 0.000000] .text : 0xc0008000 - 0xc07e003c (8033 kB) 0.000000] .init : 0xc07e1000 - 0xc08ca000 ( 932 kB) 0.000000] .data : 0xc08ca000 - 0xc09189a0 ( 315 kB) 0.000000] .bss : 0xc09189a0 - 0xc0964240 ( 303 kB) 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=1, Nodes=1 0.000000] Preemptible hierarchical RCU implementation. 0.000000] RCU kthread priority: 1. 0.000000] NR_IRQS:16 nr_irqs:16 16 0.000000] IRQ: Found an INTC at 0xfa200000 (revision 5.0) with 128 interrupts 0.000000] OMAP clockevent source: timer2 at 24000000 Hz 0.000012] sched_clock: 32 bits at 24MHz, resolution 41ns, wraps every 89478484971ns 0.000024] clocksource: timer1: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 79635851949 ns 0.000029] OMAP clocksource: timer1 at 24000000 Hz 0.000172] clocksource_probe: no matching clocksources found 0.000337] Console: colour dummy device 80x30 0.000475] WARNING: Your 'console=ttyO0' has been replaced by 'ttyS0' 0.000477] This ensures that you still see kernel messages. Please 0.000479] update your kernel commandline. 0.089245] Calibrating delay loop... 996.14 BogoMIPS (lpj=4980736) 0.089250] pid_max: default: 32768 minimum: 301 0.089367] Mount-cache hash table entries: 1024 (order: 0, 4096 bytes) 0.089372] Mountpoint-cache hash table entries: 1024 (order: 0, 4096 bytes) 0.090052] Initializing cgroup subsys io 0.090072] Initializing cgroup subsys memory 0.090106] Initializing cgroup subsys devices 0.090116] Initializing cgroup subsys freezer 0.090127] Initializing cgroup subsys perf_event 0.090133] Initializing cgroup subsys pids 0.090202] CPU: Testing write buffer coherency: ok 0.090568] Setting up static identity map for 0x80008200 - 0x80008260 0.092886] devtmpfs: initialized 0.104014] VFP support v0.3: implementor 41 architecture 3 part 30 variant c rev 3 0.116978] omap_hwmod: debugss: _wait_target_disable failed 0.171545] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns 0.175374] pinctrl core: initialized pinctrl subsystem 0.176666] NET: Registered protocol family 16 0.178812] DMA: preallocated 256 KiB pool for atomic coherent allocations 0.184017] OMAP GPIO hardware version 0.1 0.191023] omap-gpmc 50000000.gpmc: could not find pctldev for node /ocp/l4_wkup@44c00000/scm@210000/pinmux@800/nandflash_pins_s0, deferring probe 0.193317] hw-breakpoint: debug architecture 0x4 unsupported. 0.227057] edma 49000000.edma: TI EDMA DMA engine driver 0.231103] omap_i2c 44e0b000.i2c: could not find pctldev for node /ocp/l4_wkup@44c00000/scm@210000/pinmux@800/pinmux_i2c0_pins, deferring probe 0.231228] media: Linux media interface: v0.10 0.231286] Linux video capture interface: v2.00 0.231340] pps_core: LinuxPPS API ver. 1 registered 0.231347] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti <giometti@linux.it> 0.231373] PTP clock support registered 0.231425] EDAC MC: Ver: 3.0.0 0.232547] omap-mailbox 480c8000.mailbox: omap mailbox rev 0x400 0.232801] Advanced Linux Sound Architecture Driver Initialized. 0.233635] clocksource: Switched to clocksource timer1 0.243857] NET: Registered protocol family 2 0.244649] TCP established hash table entries: 2048 (order: 1, 8192 bytes) 0.244692] TCP bind hash table entries: 2048 (order: 3, 49152 bytes) 0.244774] TCP: Hash tables configured (established 2048 bind 2048) 0.244857] UDP hash table entries: 256 (order: 2, 16384 bytes) 0.244889] UDP-Lite hash table entries: 256 (order: 2, 16384 bytes) 0.245066] NET: Registered protocol family 1 0.245953] hw perfevents: enabled with armv7_cortex_a8 PMU driver, 5 counters available 0.247791] futex hash table entries: 256 (order: 1, 8192 bytes) 0.255136] squashfs: version 4.0 (2009/01/31) Phillip Lougher 0.255405] ntfs: driver 2.1.32 [Flags: R/O]. 0.265525] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 250) 0.265556] io scheduler noop registered 0.265567] io scheduler deadline registered 0.265815] io scheduler cfq registered (default) 0.266914] pinctrl-single 44e10800.pinmux: 142 pins at pa f9e10800 size 568 0.269793] backlight supply power not found, using dummy regulator 0.271207] Serial: 8250/16550 driver, 2 ports, IRQ sharing disabled 0.272709] 44e09000.serial: ttyS0 at MMIO 0x44e09000 (irq = 158, base_baud = 3000000) is a 8250 0.843857] console [ttyS0] enabled 0.848263] [drm] Initialized drm 1.1.0 20060810 0.853969] panel panel: found backlight 0.859323] [drm] Supports vblank timestamp caching Rev 2 (21.10.2013). 0.865980] [drm] No driver support for vblank timestamp query. 0.896693] Console: switching to colour frame buffer device 60x40 0.909640] tilcdc 4830e000.lcdc: fb0: frame buffer device 0.943961] [drm] Initialized tilcdc 1.0.0 20121205 on minor 0 0.956844] loop: module loaded 0.962627] spidev spi1.0: buggy DT: spidev listed directly in DT 0.968773] ------------[ cut here ]------------ 0.973427] WARNING: CPU: 0 PID: 1 at drivers/spi/spidev.c:725 spidev_probe+0x1e0/0x1fc() 0.981638] Modules linked in: 0.984722] CPU: 0 PID: 1 Comm: swapper Not tainted 4.4.41-rt50-g968d071ce9 #130 0.992146] Hardware name: Generic AM33XX (Flattened Device Tree) 0.998261] Backtrace: 1.000745] [<c00134b4>] (dump_backtrace) from [<c00136b0>] (show_stack+0x18/0x1c) 1.008345] r7:c03e1e60 r6:000002d5 r5:00000009 r4:00000000 1.014068] [<c0013698>] (show_stack) from [<c025d470>] (dump_stack+0x24/0x28) 1.021330] [<c025d44c>] (dump_stack) from [<c003174c>] (warn_slowpath_common+0x88/0xb4) 1.029459] [<c00316c4>] (warn_slowpath_common) from [<c003181c>] (warn_slowpath_null+0x24/0x2c) 1.038289] r8:c0905984 r7:00000000 r6:cf251400 r5:00000000 r4:cf251400 1.045051] [<c00317f8>] (warn_slowpath_null) from [<c03e1e60>] (spidev_probe+0x1e0/0x1fc) 1.053366] [<c03e1c80>] (spidev_probe) from [<c03ded6c>] (spi_drv_probe+0x84/0xb0) 1.061053] r8:c0905984 r7:00000000 r6:c0905974 r5:00000000 r4:cf251400 1.067824] [<c03dece8>] (spi_drv_probe) from [<c03907e4>] (driver_probe_device+0x204/0x300) 1.076296] r7:00000000 r6:c0952c24 r5:c0952c14 r4:cf251400 1.082005] [<c03905e0>] (driver_probe_device) from [<c0390a04>] (__device_attach_driver+0x8c/0xb4) 1.091112] r9:00000000 r8:c0952bd0 r7:00000001 r6:cf251400 r5:cf047c48 r4:c0905984 1.098923] [<c0390978>] (__device_attach_driver) from [<c038eb14>] (bus_for_each_drv+0x68/0x9c) 1.107742] r7:00000001 r6:c0390978 r5:cf047c48 r4:00000000 1.113452] [<c038eaac>] (bus_for_each_drv) from [<c0390538>] (__device_attach+0xb8/0x11c) 1.121748] r6:cf251434 r5:cf251400 r4:cf251400 1.126405] [<c0390480>] (__device_attach) from [<c0390a78>] (device_initial_probe+0x14/0x18) 1.134962] r7:00000000 r6:c0905454 r5:cf251400 r4:cf251408 1.140670] [<c0390a64>] (device_initial_probe) from [<c038fa60>] (bus_probe_device+0x8c/0x94) 1.149322] [<c038f9d4>] (bus_probe_device) from [<c038dbe0>] (device_add+0x3ec/0x574) 1.157269] r7:00000000 r6:cf251400 r5:cf251000 r4:cf251408 1.162979] [<c038d7f4>] (device_add) from [<c03df520>] (spi_add_device+0xa8/0x140) 1.170665] r10:cf25119a r9:cf138010 r8:cfd971b4 r7:cf138010 r6:cf251000 r5:00000000 1.178557] r4:cf251400 1.181106] [<c03df478>] (spi_add_device) from [<c03df9b0>] (of_register_spi_device+0x22c/0x2f4) 1.189925] r7:cf251000 r6:cfd974fc r5:cf251400 r4:00000000 1.195633] [<c03df784>] (of_register_spi_device) from [<c03e0f24>] (spi_register_master+0x2e4/0x4c8) 1.204890] r7:c077f380 r6:00000000 r5:cfd974fc r4:cf251000 1.210597] [<c03e0c40>] (spi_register_master) from [<c03e1148>] (devm_spi_register_master+0x40/0x78) 1.219852] r10:cf25119a r9:c077f840 r8:cf251000 r7:cf138010 r6:cf251000 r5:cf23ac10 1.227744] r4:00000000 1.230297] [<c03e1108>] (devm_spi_register_master) from [<c03e4820>] (omap2_mcspi_probe+0x2d4/0x34c) 1.239553] r7:cf138010 r6:cf251000 r5:cf251328 r4:00000000 1.245268] [<c03e454c>] (omap2_mcspi_probe) from [<c0391f44>] (platform_drv_probe+0x54/0xb8) 1.253825] r10:00000000 r9:00000000 r8:c09059d8 r7:fffffdfb r6:c09059d8 r5:cf138010 1.261715] r4:cf138010 1.264268] [<c0391ef0>] (platform_drv_probe) from [<c03907e4>] (driver_probe_device+0x204/0x300) 1.273174] r7:00000000 r6:c0952c24 r5:c0952c14 r4:cf138010 1.278885] [<c03905e0>] (driver_probe_device) from [<c0390974>] (__driver_attach+0x94/0x98) 1.287356] r9:c07e1600 r8:0000007b r7:00000000 r6:cf138044 r5:c09059d8 r4:cf138010 1.295164] [<c03908e0>] (__driver_attach) from [<c038ea54>] (bus_for_each_dev+0x70/0xa4) 1.303373] r7:00000000 r6:c03908e0 r5:c09059d8 r4:00000000 1.309081] [<c038e9e4>] (bus_for_each_dev) from [<c03900d4>] (driver_attach+0x24/0x28) 1.317116] r6:c08ff8e0 r5:cf23db00 r4:c09059d8 1.321770] [<c03900b0>] (driver_attach) from [<c038fd1c>] (bus_add_driver+0x1a8/0x220) 1.329811] [<c038fb74>] (bus_add_driver) from [<c0390e94>] (driver_register+0x80/0x100) 1.337934] r7:cf23a800 r6:c08ceca0 r5:c0803cb4 r4:c09059d8 1.343650] [<c0390e14>] (driver_register) from [<c0391e6c>] (__platform_driver_register+0x48/0x50) 1.352732] r5:c0803cb4 r4:c08ff8e0 1.356341] [<c0391e24>] (__platform_driver_register) from [<c0803cd0>] (omap2_mcspi_driver_init+0x1c/0x20) 1.366119] r5:c0803cb4 r4:c08ceca0 1.369725] [<c0803cb4>] (omap2_mcspi_driver_init) from [<c00096d4>] (do_one_initcall+0x98/0x1e4) 1.378653] [<c000963c>] (do_one_initcall) from [<c07e1e88>] (kernel_init_freeable+0x138/0x1cc) 1.387386] r10:00000007 r9:c07e1600 r8:0000007b r7:c0813830 r6:c08c8098 r5:c09189c0 1.395278] r4:c09189c0 1.397839] [<c07e1d50>] (kernel_init_freeable) from [<c05b56c8>] (kernel_init+0x18/0xe8) 1.406050] r10:00000000 r9:00000000 r8:00000000 r7:00000000 r6:00000000 r5:c05b56b0 1.413938] r4:c09189c0 1.416491] [<c05b56b0>] (kernel_init) from [<c000fa80>] (ret_from_fork+0x14/0x34) 1.424091] r5:c05b56b0 r4:00000000 1.427687] ---[ end trace 0000000000000001 ]--- 1.433893] libphy: Fixed MDIO Bus: probed 1.439500] i2c /dev entries driver 1.444180] omap_hsmmc 48060000.mmc: Got CD GPIO 1.454405] NET: Registered protocol family 10 1.460166] sit: IPv6 over IPv4 tunneling driver 1.465655] NET: Registered protocol family 17 1.470197] Key type dns_resolver registered 1.474722] omap_voltage_late_init: Voltage driver support not added 1.484160] omap-gpmc 50000000.gpmc: GPMC revision 6.0 1.489344] gpmc_mem_init: disabling cs 0 mapped at 0x0-0x1000000 1.497051] nand: device found, Manufacturer ID: 0x2c, Chip ID: 0xd3 1.503434] nand: Micron MT29F8G08ABACAWP 1.507466] nand: 1024 MiB, SLC, erase size: 256 KiB, page size: 4096, OOB size: 224 1.515271] using OMAP_ECC_BCH16_CODE_HW ECC scheme 1.520227] 1 ofpart partitions found on MTD device 8000000.nand 1.526261] Creating 1 MTD partitions on "8000000.nand": 1.531601] 0x000000700000-0x000019700000 : "NAND.file-system" 1.593998] tps65910 0-002d: No interrupt support, no core IRQ 1.655659] input: pixcir_ts as /devices/platform/ocp/44e0b000.i2c/i2c-0/0-0055/input/input0 1.665010] vaux2: supplied by vbat 1.668879] omap_i2c 44e0b000.i2c: bus 0 rev0.11 at 100 kHz 1.675199] omap_hsmmc 48060000.mmc: Got CD GPIO 1.680406] vmmc: supplied by vbat 1.729661] asoc-simple-card sound: tlv320aic3x-hifi <-> 4803c000.mcasp mapping ok 1.740776] ubi0: attaching mtd0 2.473363] ubi0: scanning is finished 2.485599] ubi0: attached mtd0 (name "NAND.file-system", size 400 MiB) 2.492264] ubi0: PEB size: 262144 bytes (256 KiB), LEB size: 258048 bytes 2.499170] ubi0: min./max. I/O unit sizes: 4096/4096, sub-page size 1024 2.505990] ubi0: VID header offset: 1024 (aligned 1024), data offset: 4096 2.512980] ubi0: good PEBs: 1600, bad PEBs: 0, corrupted PEBs: 0 2.519098] ubi0: user volume: 1, internal volumes: 1, max. volumes count: 128 2.526352] ubi0: max/mean erase counter: 1/0, WL threshold: 4096, image sequence number: 1012321058 2.535524] ubi0: available PEBs: 0, total reserved PEBs: 1600, PEBs reserved for bad PEB handling: 80 2.544878] ubi0: background thread "ubi_bgt0d" started, PID 80 2.555445] lis3_reg: disabling 2.559255] ALSA device list: 2.562238] #0: AM335x-EVMSK 2.573770] UBIFS (ubi0:0): background thread "ubifs_bgt0_0" started, PID 82 2.631505] UBIFS (ubi0:0): recovery needed 2.769853] UBIFS (ubi0:0): recovery completed 2.774480] UBIFS (ubi0:0): UBIFS: mounted UBI device 0, volume 0, name "rootfs" 2.781913] UBIFS (ubi0:0): LEB size: 258048 bytes (252 KiB), min./max. I/O unit sizes: 4096 bytes/4096 bytes 2.791873] UBIFS (ubi0:0): FS size: 388620288 bytes (370 MiB, 1506 LEBs), journal size 9420800 bytes (8 MiB, 37 LEBs) 2.802614] UBIFS (ubi0:0): reserved for root: 0 bytes (0 KiB) 2.808479] UBIFS (ubi0:0): media format: w4/r0 (latest is w4/r0), UUID 4499737A-03BF-479A-9BCB-DFD98CC94C94, small LPT model 2.821754] VFS: Mounted root (ubifs filesystem) on device 0:14. 2.829230] devtmpfs: mounted 2.833386] Freeing unused kernel memory: 932K (c07e1000 - c08ca000) 3.117131] systemd[1]: System time before build time, advancing clock. 3.233384] random: systemd: uninitialized urandom read (16 bytes read, 8 bits of entropy available) 3.268721] random: systemd: uninitialized urandom read (16 bytes read, 8 bits of entropy available) 3.286988] systemd[1]: systemd 229 running in system mode. (+PAM -AUDIT -SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP -LIBCRYPTSETUP -GCRYPT -GNUTLS +ACL +XZ -LZ4 -SECCOMP +BLKID -ELFUTILS +KMOD -IDN) 3.306883] systemd[1]: Detected architecture arm. 2018] Welcome to Arago 2016.12! 3.336360] systemd[1]: Set hostname to <am335x-evm>. 3.568079] random: systemd-sysv-ge: uninitialized urandom read (16 bytes read, 8 bits of entropy available) 3.614748] random: systemd-sysv-ge: uninitialized urandom read (16 bytes read, 8 bits of entropy available) 3.703772] random: systemd: uninitialized urandom read (16 bytes read, 8 bits of entropy available) 3.713275] random: systemd: uninitialized urandom read (16 bytes read, 8 bits of entropy available) 3.811894] random: systemd: uninitialized urandom read (16 bytes read, 9 bits of entropy available) 3.821919] random: systemd: uninitialized urandom read (16 bytes read, 9 bits of entropy available) 3.904778] random: systemd: uninitialized urandom read (16 bytes read, 9 bits of entropy available) 3.941059] random: systemd: uninitialized urandom read (16 bytes read, 9 bits of entropy available) 4.109177] systemd[1]: Created slice System Slice. OK ] Created slice System Slice. 4.135344] systemd[1]: Created slice system-serial\x2dgetty.slice. OK ] Created slice system-serial\x2dgetty.slice. 4.166396] systemd[1]: systemd-journald.socket: Socket service systemd-journald.service not loaded, refusing. 4.176547] systemd[1]: Failed to listen on Journal Socket. 2018] [FAILED] Failed to listen on Journal Socket. 2018] See 'systemctl status systemd-journald.socket' for details. 4.227349] systemd[1]: Reached target Timers. OK ] Reached target Timers. 4.258823] systemd[1]: Reached target Slices. OK ] Reached target Slices. 4.292157] systemd[1]: Started Forward Password Requests to Wall Directory Watch. OK ] Started Forward Password Requests to Wall Directory Watch. 4.335369] systemd[1]: Listening on udev Kernel Socket. OK ] Listening on udev Kernel Socket. 4.364591] systemd[1]: Started Dispatch Password Requests to Console Directory Watch. OK ] Started Dispatch Password Requests to Console Directory Watch. 4.394145] systemd[1]: Reached target Paths. OK ] Reached target Paths. 4.422369] systemd[1]: Starting Apply Kernel Variables... Starting Apply Kernel Variables... 4.459357] systemd[1]: Mounting /media/ram... Mounting /media/ram... 4.496883] systemd[1]: Listening on udev Control Socket. OK ] Listening on udev Control Socket. 4.532050] systemd[1]: Starting udev Coldplug all Devices... Starting udev Coldplug all Devices... 4.586862] systemd[1]: Starting udev Kernel Device Manager... Starting udev Kernel Device Manager... 4.665653] systemd[1]: systemd-journald-dev-log.socket: Socket service systemd-journald.service not loaded, refusing. 4.698332] systemd[1]: Failed to listen on Journal Socket (/dev/log). 2018] [FAILED] Failed to listen on Journal Socket (/dev/log). 2018] See 'systemctl status systemd-journald-dev-log.socket' for details. 4.799059] systemd[1]: Mounted /media/ram. OK ] Mounted /media/ram. 4.846418] systemd[1]: Started Apply Kernel Variables. OK ] Started Apply Kernel Variables. 5.204572] systemd[1]: Started udev Kernel Device Manager. OK ] Started udev Kernel Device Manager. 5.837921] systemd[1]: Reached target Local File Systems. OK ] Reached target Local File Systems. 5.917405] systemd[1]: Started udev Coldplug all Devices. OK ] Started udev Coldplug all Devices. 6.146625] systemd[1]: Found device /dev/ttyS0. 6.167937] 47401300.usb-phy supply vcc not found, using dummy regulator OK ] Found device /dev/ttyS0. 6.249125] systemd[1]: Created slice system-systemd\x2dbacklight.slice. 6.285094] omap_wdt: OMAP Watchdog Timer Rev 0x01: initial timeout 60 sec OK ] Created slice system-systemd\x2dbacklight.slice. 6.379991] systemd[1]: Starting Load/Save Screen Backlight Brightness of backlight:backlight... Starting Load/Save Screen Backlight...htness of backlight:backlight... 6.708517] systemd[1]: Started Load/Save Screen Backlight Brightness of backlight:backlight. OK ] Started Load/Save Screen Backlight Brightness of backlight:backlight. 6.972990] [drm] Initialized pvr 1.14.3699939 20110701 on minor 1 7.052138] systemd[1]: Reached target System Initialization. OK ] Reached target System Initialization. 7.124379] systemd[1]: dbus.socket: Socket service dbus.service not loaded, refusing. 7.132434] systemd[1]: Failed to listen on D-Bus System Message Bus Socket. 2018] [FAILED] Failed to listen on D-Bus System Message Bus Socket. 2018] See 'systemctl status dbus.socket' for details. 7.267087] systemd[1]: Reached target Sockets. OK ] Reached target Sockets. 7.342960] systemd[1]: Reached target Basic System. OK ] Reached target Basic System. 7.451582] systemd[1]: Started Serial Getty on ttyS0. OK ] Started Serial Getty on ttyS0. 7.504782] systemd[1]: Reached target Login Prompts. OK ] Reached target Login Prompts. 7.608488] systemd[1]: Starting rc.pvr.service... Starting rc.pvr.service... 7.855747] systemd-udevd[135]: Process '/usr/sbin/alsactl restore 0' failed with exit code 99. 8.462975] usbcore: registered new interface driver usbfs 8.480656] usbcore: registered new interface driver hub 8.490683] usbcore: registered new device driver usb 8.495272] PVR_K: UM DDK-(3699939) and KM DDK-(3699939) match. [ OK ] 8.588497] musb-hdrc musb-hdrc.0.auto: MUSB HDRC host driver 8.603944] musb-hdrc musb-hdrc.0.auto: new USB bus registered, assigned bus number 1 8.631289] hub 1-0:1.0: USB hub found 8.643968] hub 1-0:1.0: 1 port detected 8.724637] systemd[1]: Started rc.pvr.service. OK ] Started rc.pvr.service. 8.779230] systemd[1]: Starting init script... Starting init script... 10.513367] Console: switching to colour dummy device 80x30 10.690828] systemd[1]: Started init script. OK ] Started init script. 10.735713] systemd[1]: Reached target Multi-User System. OK ] Reached target Multi-User System. 10.774523] systemd[1]: Reached target Graphical Interface. OK ] Reached target Graphical Interface. 10.805202] systemd[1]: Startup finished in 3.043s (kernel) + 7.757s (userspace) = 10.800s. _____ _ _ _ |___ ___ ___ ___ | _ |___ ___ |_|___ ___| |_ | _| .'| . | . | | __| _| . | | | -_| _| _| 2018] |__|__|_| |__,|_ |___| |__| |_| |___|_| |___|___|_| |___| |___| 2018] Arago Project http://arago-project.org am335x-evm ttyS0 2018] Arago 2016.12 am335x-evm ttyS0 2018] am335x-evm login: = j('#fragment-1a84591e31034fac832d29ed8584666c1337702343_code-editor-fs'); t-1a84591e31034fac832d29ed8584666c1337702343_code-editor'); function(){ CodeEditor('fullscreen')) { CodeEditor('fullscreen', false); CodeEditor('fullscreen', true);

0 Ugnius Subacius over 7 years ago in reply to Steve Kipisz

Expert 1180 points

Do you have any idea of what might cause such a long time between prints?

0 Steve Kipisz over 7 years ago in reply to Ugnius Subacius

TI__Genius 15510 points

I am looking at it.

Steve K.

0 Steve Kipisz over 7 years ago in reply to Steve Kipisz

TI__Genius 15510 points

From u-boot can you dump CM_CLKSEL_DPLL_MPU (0x44e0042c)? I'd like to know the ARM speed.

Also, the printf to the serial console will add time.

Steve K.

0 Ugnius Subacius over 7 years ago in reply to Steve Kipisz

Expert 1180 points

Hi Steve,

=> md 0x44e0042c
44e0042c: 0003e817 00000000 00000001 00000000 ................

It is sitting there for over a second without any prints, so it should not be any delay because of print.

U-boot already loaded everything into ram and jumped to kernel.

I would expect first kernel print straight away.

Is there anything kernel has to do before making first print?

Kind regards,

Ugnius

0 Praneeth Bajjuri over 7 years ago in reply to Ugnius Subacius

TI__Expert 6266 points

ugnius,

couple of questions.

1. are you using compressed kernel image (zImage) or uncompressed one (Image).

2. default boot is configured at lzma (size optimized).

what happens to that boot stage if you change kernel config to LZ4 (change in ti_config_fragments/baseport.cfg) and build/boot.

0 Ugnius Subacius over 7 years ago in reply to Praneeth Bajjuri

Expert 1180 points

Hi Praneeth,

I am using zImage. I will try to do what you suggested and use Image. Will let you know how that goes.

Also I want to eventually run from NAND using Falcon mode, which uses Uimage.
I tried generating Uimage from zImage using mkimage.
Does that mean my Uimage was compressed?

Is it possible to use falcon mode with a not compressed image?

kind regards,
Ugnius

0 Ugnius Subacius over 7 years ago

Expert 1180 points

Hi,

Looks like Praneeth was correct, the excess time is spent zImage un-compressing itself. I thought there would be print saying when it starts if that was the case, which is why I thought there was something wrong going on.

I could not confirm this booting from SD card as it fails boot with Image(instead of zImage) saying wrong zImage magic. I am not sure how to change the expected format when booting from MMC.

Booting from nand in Falcon mode however expects Uimage. So I generated Uimage using Image instead of zImage.
Comparing the falcon boot timings the uncompressed Uimage takes longer to load to ram, but kernel prints without time delay after SPL jumps to it.
Compressed Uimage takes quicker to load to ram but there is time delay between jump to kernel and kernel print.
I think this confirms that the time is spent un-compressing image.

All in all using uncompressed image is 500 ms quicker when booting in falcon mode.

Thank you Steve and Praneeth for your help.

Kind regards,
Ugnius

0 Praneeth Bajjuri over 7 years ago in reply to Ugnius Subacius

TI__Expert 6266 points

some of the factors effect the boot time for the area you are trying to optimize
-- Boot media (NAND/SD/something else) throughput
-- MPU speed

Glad to hear that you were able to save some boot time and proceed ahead with your experimentation .

In anycase, There should be various resources available in http://processors.wiki.ti.com to optimize boot time. feel free to explore and try opitmizing on your custom board.

Hope it helps.

Processors

Processors forum

Linux/AM3358: Delay between starting kernel and first log print