Re: New fast(?)-boot results on ARM

Dirk Behme
2009-08-18T15:32:21Z

Sascha Hauer wrote:
> On Fri, Aug 14, 2009 at 07:02:28PM +0200, Robert Schwebel wrote:
>> Hi,
>>
>> On Thu, Aug 13, 2009 at 05:33:26PM +0200, Robert Schwebel wrote:
>>> On Thu, Aug 13, 2009 at 08:28:26AM -0700, Arjan van de Ven wrote:
>>>>> That's bad :-) So there is no room for improvement any more in our
>>>>> ARM boot sequences ...
>>>> on x86 we're doing pretty well ;-)
>>> On i.MX27 (400 MHz ARM926EJ-S) we currently need 7 s, measured from
>>> power-on through the kernel up to "starting init". This is with
>>>
>>> - no delay in u-boot-v2
>>> - rootfs on NAND (UBIFS)
>>> - quiet
>>> - precalculated loops-per-jiffy
>>> - zImage kernel instead of uImage
>> Here's a little video of our demo system booting:
>> http://www.youtube.com/watch?v=xDbUnNsj0cI
>>
>> As you can see there, it needs about 15 s from the release of the reset button
>> up to the moment where the application shows it's Qt 4.5.2 based GUI (which is
>> when we fade over from the initial framebuffer to the final one, in order to
>> hide the qt application startup noise).
>>
>> And below is the boot log (after turning "quiet" off again). The numbers are
>> the timestamp and the delta to the last timestamp, measured on the controlling
>> PC by looking at the serial console output. The ptx_ts script starts when the
>> regexp was found, so the numbers start basically in the moment when u-boot-v2
>> has initialized the system up to the point where we can see something.
>>
>> Result:
>>
>> - 2.4 s up from u-boot to the end of "Uncompressing Linux"
>> - 300 ms until ubifs initialization starts
>> - 3.7 s for ubifs, until "mounted root"
>>
>> So we basically have 7 s for the kernel. The rest is userspace, which hasn't
>> seen much optimization yet, other than trying to start the GUI application as
>> early as possible, while doing all other init stuff in parallel. Adding "quiet"
>> brings us another 300 ms.
>>
>> That's factor 70 away from the 110 ms boot time Tim has talked about some days
>> ago (and he measured on an ARM cpu which had almost half the speed of this
>> one), and I'm wondering what we can do to improve the boot time.
>>
>> Robert
>>
>> rsc@thebe:~$ microcom | ptx_ts "U-Boot 2.0.0-rc9"
>> [ 13.522625] < 0.043189>
>> [ 13.546627] < 0.024002> OSELAS(R)-phyCORE-trunk (PTXdist-1.99.svn/2009-08-06T08:37:25+0200)
>> [ 13.558613] < 0.011986>
>> [ 13.690643] < 0.132030> _ ____ ___ ____ _____
>> [ 13.690731] < 0.000088> _ __ | |__ _ _ / ___/ _ \| _ \| ____|
>> [ 13.698595] < 0.007864> | '_ \| '_ \| | | | | | | | | |_) | _|
>> [ 13.698654] < 0.000059> | |_) | | | | |_| | |__| |_| | _ <| |___
>> [ 13.702581] < 0.003927> | .__/|_| |_|\__, |\____\___/|_| \_\_____|
>> [ 13.706573] < 0.003992> |_| |___/
>> [ 13.706622] < 0.000049>
>> [ 13.725043] < 0.018421>
>> [ 14.742608] < 1.017565>
>
> I made some changes suggested in this thread:
>
> - enable MMU in the bootloader
> - use assembler optimized memcpy/memset in the bootloader
> - start an uncompressed image
> - disable IP autoconfiguration in the Kernel
> - use lpj= command line parameter
> - use static device nodes instead of udev
> - skip some init scripts
> - made the kernel smaller (I do not have both configs handy, so I do not
> know what exactly I changed)
>
> Already looks much better:
>
> [ 0.000005] < 0.000005> U-Boot 2.0.0-rc10-00241-g3f10fe9-dirty (Aug 18 2009 - 13:29:25)
> [ 0.000026] < 0.000021>
> [ 0.000041] < 0.000015> Board: Phytec phyCORE-i.MX27
> [ 0.000054] < 0.000013> cfi_probe: cfi_flash base: 0xc0000000 size: 0x02000000
> [ 0.000067] < 0.000013> NAND device: Manufacturer ID: 0x20, Chip ID: 0x36 (ST Micro NAND 64MiB 1,8V 8-bit)
> [ 0.000080] < 0.000013> imxfb@imxfb0: i.MX Framebuffer driver
> [ 0.000092] < 0.000012> dma_alloc: 0xa6f56e40 0x10000000
> [ 0.000105] < 0.000013> dma_alloc: 0xa6f57088 0x10000000
> [ 0.000118] < 0.000013> dev_protect: currently broken
> [ 0.000129] < 0.000011> Using environment in NOR Flash
> [ 0.000141] < 0.000012> initialising PLLs
> [ 0.128972] < 0.128831> Malloc space: 0xa6f00000 -> 0xa7f00000 (size 16 MB)
> [ 0.128995] < 0.000023> Stack space : 0xa6ef8000 -> 0xa6f00000 (size 32 kB)
> [ 0.129008] < 0.000013> running /env/bin/init...
> [ 0.224963] < 0.095955>
> [ 0.224984] < 0.000021> Hit any key to stop autoboot: 0
> [ 0.224999] < 0.000015> copy
> [ 0.592964] < 0.367965> done
> [ 0.652010] < 0.059046> Linux version 2.6.31-rc4-00004-g05786f8-dirty (sha@octopus) (gcc version 4.3.2 (OSELAS.Toolchain-1.99.3) ) #206 PREEMPT Tue Aug 18 14:08:51 CEST 2009

So, this are ~0.6 s in boot loader and kernel copy until kernel
starts, correct?

What's the size of the uncompressed kernel copied here?

Best regards

Dirk

Btw.: I tried to summarize some hints given in this thread in

http://elinux.org/Boot_Time#Boot_time_check_list

Please feel free to add and correct stuff!

> [ 0.652030] < 0.000020> CPU: ARM926EJ-S [41069264] revision 4 (ARMv5TEJ), cr=00053177
> [ 0.652044] < 0.000014> CPU: VIVT data cache, VIVT instruction cache
> [ 0.652057] < 0.000013> Machine: phyCORE-i.MX27
> [ 0.652069] < 0.000012> Memory policy: ECC disabled, Data cache writeback
> [ 0.652082] < 0.000013> Built 1 zonelists in Zone order, mobility grouping on. Total pages: 32512
> [ 0.706012] < 0.053930> Kernel command line: console=ttymxc0,115200 earlyprintk lpj=995328 mt9v022.sensor_type=color ip=192.168.23.197:192.168.23.2:192.168.23.2:255.255.0.0::: ubi.mtd=7 root=ubi0:root rootfstype=ubifs mtdparts="physmap-flash.0:256k(uboot)ro,128k(ubootenv),3M(kernel),-(root);mxc_nand:256k(uboot)ro,128k(ubootenv),3M(kernel),-(root)"
> [ 0.706034] < 0.000022> console [earlyser0] enabled
> [ 0.706049] < 0.000015> Unknown boot option `mt9v022.sensor_type=color': ignoring
> [ 0.706062] < 0.000013> PID hash table entries: 512 (order: 9, 2048 bytes)
> [ 0.706075] < 0.000013> Dentry cache hash table entries: 16384 (order: 4, 65536 bytes)
> [ 0.706087] < 0.000012> Inode-cache hash table entries: 8192 (order: 3, 32768 bytes)
> [ 0.755997] < 0.049910> Memory: 128MB = 128MB total
> [ 0.756016] < 0.000019> Memory: 127004KB available (2404K code, 205K data, 80K init, 0K highmem)
> [ 0.756030] < 0.000014> NR_IRQS:272
> [ 0.756042] < 0.000012> MXC GPIO hardware
> [ 0.756055] < 0.000013> MXC IRQ initialized
> [ 0.756067] < 0.000012> Console: colour dummy device 80x30
> [ 0.756079] < 0.000012> Calibrating delay loop (skipped) preset value.. 199.06 BogoMIPS (lpj=995328)
> [ 0.756092] < 0.000013> Mount-cache hash table entries: 512
> [ 0.756104] < 0.000012> CPU: Testing write buffer coherency: ok
> [ 0.771968] < 0.015864> NET: Registered protocol family 16
> [ 0.803967] < 0.031999> bio: create slab <bio-0> at 0
> [ 0.869007] < 0.065040> NET: Registered protocol family 2
> [ 0.869025] < 0.000018> IP route cache hash table entries: 1024 (order: 0, 4096 bytes)
> [ 0.869040] < 0.000015> TCP established hash table entries: 4096 (order: 3, 32768 bytes)
> [ 0.869053] < 0.000013> TCP bind hash table entries: 4096 (order: 2, 16384 bytes)
> [ 0.869066] < 0.000013> TCP: Hash tables configured (established 4096 bind 4096)
> [ 0.869078] < 0.000012> TCP reno registered
> [ 0.869090] < 0.000012> NET: Registered protocol family 1
> [ 0.869103] < 0.000013> msgmni has been set to 248
> [ 0.869115] < 0.000012> io scheduler noop registered (default)
> [ 0.869127] < 0.000012> i.MX Framebuffer driver
> [ 0.884970] < 0.015843> Console: switching to colour frame buffer device 30x40
> [ 0.974022] < 0.089052> Serial: IMX driver
> [ 0.974127] < 0.000105> Platform driver 'imx-uart' needs updating - please use dev_pm_ops
> [ 0.974217] < 0.000090> imx-uart.0: ttymxc0 at MMIO 0x1000a000 (irq = 20) is a IMX
> [ 0.974306] < 0.000089> console handover: boot [earlyser0] -> real [ttymxc0]
> [ 0.974392] < 0.000086> imx-uart.1: ttymxc1 at MMIO 0x1000b000 (irq = 19) is a IMX
> [ 0.974481] < 0.000089> imx-uart.2: ttymxc2 at MMIO 0x1000c000 (irq = 18) is a IMX
> [ 0.974569] < 0.000088> FEC Ethernet Driver
> [ 0.974651] < 0.000082> Platform driver 'fec' needs updating - please use dev_pm_ops
> [ 0.974737] < 0.000086> fec: PHY @ 0x0, ID 0x00221613 -- KS8721BL
> [ 1.019018] < 0.044281> physmap platform flash device: 02000000 at c0000000
> [ 1.019118] < 0.000100> physmap-flash.0: Found 1 x16 devices at 0x0 in 16-bit bank
> [ 1.019207] < 0.000089> Intel/Sharp Extended Query Table at 0x010A
> [ 1.019293] < 0.000086> Intel/Sharp Extended Query Table at 0x010A
> [ 1.019377] < 0.000084> Intel/Sharp Extended Query Table at 0x010A
> [ 1.019460] < 0.000083> Intel/Sharp Extended Query Table at 0x010A
> [ 1.019544] < 0.000084> Intel/Sharp Extended Query Table at 0x010A
> [ 1.019627] < 0.000083> Using buffer write method
> [ 1.019714] < 0.000087> Using auto-unlock on power-up/resume
> [ 1.019797] < 0.000083> cfi_cmdset_0001: Erase suspend on write enabled
> [ 1.019881] < 0.000084> 4 cmdlinepart partitions found on MTD device physmap-flash.0
> [ 1.082018] < 0.062137> Creating 4 MTD partitions on "physmap-flash.0":
> [ 1.082112] < 0.000094> 0x000000000000-0x000000040000 : "uboot"
> [ 1.082199] < 0.000087> 0x000000040000-0x000000060000 : "ubootenv"
> [ 1.082287] < 0.000088> 0x000000060000-0x000000360000 : "kernel"
> [ 1.082371] < 0.000084> 0x000000360000-0x000002000000 : "root"
> [ 1.082453] < 0.000082> NAND device: Manufacturer ID: 0x20, Chip ID: 0x36 (ST Micro NAND 64MiB 1,8V 8-bit)
> [ 1.082543] < 0.000090> RedBoot partition parsing not available
> [ 1.082627] < 0.000084> 4 cmdlinepart partitions found on MTD device mxc_nand
> [ 1.082715] < 0.000088> Creating 4 MTD partitions on "mxc_nand":
> [ 1.082798] < 0.000083> 0x000000000000-0x000000040000 : "uboot"
> [ 1.082882] < 0.000084> 0x000000040000-0x000000060000 : "ubootenv"
> [ 1.097976] < 0.015094> 0x000000060000-0x000000360000 : "kernel"
> [ 1.113978] < 0.016002> 0x000000360000-0x000004000000 : "root"
> [ 1.425012] < 0.311034> UBI: attaching mtd7 to ubi0
> [ 1.425043] < 0.000031> UBI: physical eraseblock size: 16384 bytes (16 KiB)
> [ 1.425057] < 0.000014> UBI: logical eraseblock size: 15360 bytes
> [ 1.425071] < 0.000014> UBI: smallest flash I/O unit: 512
> [ 1.425083] < 0.000012> UBI: VID header offset: 512 (aligned 512)
> [ 1.425096] < 0.000013> UBI: data offset: 1024
> [ 3.008058] < 1.582962> UBI: attached mtd7 to ubi0
> [ 3.008090] < 0.000032> UBI: MTD device name: "root"
> [ 3.008105] < 0.000015> UBI: MTD device size: 60 MiB
> [ 3.008119] < 0.000014> UBI: number of good PEBs: 3880
> [ 3.008132] < 0.000013> UBI: number of bad PEBs: 0
> [ 3.008145] < 0.000013> UBI: max. allowed volumes: 89
> [ 3.008159] < 0.000014> UBI: wear-leveling threshold: 4096
> [ 3.008172] < 0.000013> UBI: number of internal volumes: 1
> [ 3.008185] < 0.000013> UBI: number of user volumes: 1
> [ 3.008199] < 0.000014> UBI: available PEBs: 0
> [ 3.008212] < 0.000013> UBI: total number of reserved PEBs: 3880
> [ 3.008226] < 0.000014> UBI: number of PEBs reserved for bad PEB handling: 38
> [ 3.051029] < 0.042803> UBI: max/mean erase counter: 2/0
> [ 3.051052] < 0.000023> UBI: image sequence number: 0
> [ 3.051066] < 0.000014> UBI: background thread "ubi_bgt0d" started, PID 218
> [ 3.051081] < 0.000015> i2c /dev entries driver
> [ 3.051094] < 0.000013> rtc-pcf8563 1-0051: chip found, driver version 0.4.3
> [ 3.051108] < 0.000014> rtc-pcf8563 1-0051: rtc core: registered rtc-pcf8563 as rtc0
> [ 3.051122] < 0.000014> Driver for 1-wire Dallas network protocol.
> [ 3.148042] < 0.096920> i.MX SDHC driver
> [ 3.148067] < 0.000025> mxc-mmc: probe of mxc-mmc.1 failed with error -16
> [ 3.148082] < 0.000015> TCP cubic registered
> [ 3.148095] < 0.000013> NET: Registered protocol family 17
> [ 3.148107] < 0.000012> RPC: Registered udp transport module.
> [ 3.148119] < 0.000012> RPC: Registered tcp transport module.
> [ 3.148132] < 0.000013> rtc-pcf8563 1-0051: low voltage detected, date/time is not reliable.
> [ 3.148145] < 0.000013> rtc-pcf8563 1-0051: retrieved date/time is not valid.
> [ 3.148157] < 0.000012> rtc-pcf8563 1-0051: hctosys: invalid date/time
> [ 3.148170] < 0.000013> UBIFS: recovery needed
> [ 3.211043] < 0.062873> UBIFS: recovery completed
> [ 3.211064] < 0.000021> UBIFS: mounted UBI device 0, volume 1, name "root"
> [ 3.211080] < 0.000016> UBIFS: file system size: 58490880 bytes (57120 KiB, 55 MiB, 3808 LEBs)
> [ 3.211093] < 0.000013> UBIFS: journal size: 7741440 bytes (7560 KiB, 7 MiB, 504 LEBs)
> [ 3.211105] < 0.000012> UBIFS: media format: w4/r0 (latest is w4/r0)
> [ 3.211118] < 0.000013> UBIFS: default compressor: lzo
> [ 3.211130] < 0.000012> UBIFS: reserved for root: 0 bytes (0 KiB)
> [ 3.211143] < 0.000013> VFS: Mounted root (ubifs filesystem) on device 0:12.
> [ 3.211155] < 0.000012> Freeing init memory: 80K
> init started: BusyBox v1.13.4 (2009-08-06 08:30:14 CEST)
> [ 3.514007] < 0.159993> mounting filesystems...done.
> [ 3.546005] < 0.031998> running rc.d services...
> [ 3.626007] < 0.080002> syslogd starting
> [ 3.786013] < 0.160006> Starting telnetd...
> [ 3.962014] < 0.176001> starting network interfaces...
> [ 4.818032] < 0.856018> eth0: config: auto-negotiation on, 100FDX, 100HDX, 10FDX, 10HDX.
> [ 5.058038] < 0.240006> ip: cannot find device "can0"
> [ 5.250040] < 0.192002> ip: SIOCGIFFLAGS: No such device
> [ 5.298033] < 0.047993>
> [ 5.336039] < 0.038006> OSELAS(R)-phyCORE-trunk (PTXdist-1.99.svn/2009-08-06T08:37:25+0200)
> [ 5.368028] < 0.031989>
> [ 5.840066] < 0.472038> _ ____ ___ ____ _____
> [ 5.840090] < 0.000024> _ __ | |__ _ _ / ___/ _ \| _ \| ____|
> [ 5.840104] < 0.000014> | '_ \| '_ \| | | | | | | | | |_) | _|
> [ 5.840116] < 0.000012> | |_) | | | | |_| | |__| |_| | _ <| |___
> [ 5.840129] < 0.000013> | .__/|_| |_|\__, |\____\___/|_| \_\_____|
> [ 5.840141] < 0.000012> |_| |___/
> [ 5.840154] < 0.000013>
>
> Sascha
>