30 seconds to start wifi, it is a long time for some situation.
Why does it take so long time to boost. Let’s check!

Now, prepare a firmware, better compile from source code, so we can easily cut off kernel of Linux.

I am using 20190914.bin firmware.

First try, remove all boot up module from system.

1. mv /etc/init.d /etc/init.d.bak
2. mv /etc/modules.d /etc/modules.d.bak
3. mkdir /etc/init.d
4. mkdir /etc/modules.d

Now reboot, you will get this log, looks like it is able to startup around 9 seconds.


Starting kernel ...

[    0.000000] Linux version 4.14.131 (vonger@Vongers-MacBook-Pro-2.local) (gcc version 7.3.0 (OpenWrt GCC 7.3.0 r7808-ef686b7292)) #0 Thu Jun 27 12:18:52 2019
[    0.000000] Board has DDR2
[    0.000000] Analog PMU set to hw control
[    0.000000] Digital PMU set to hw control
[    0.000000] SoC Type: MediaTek MT7628AN ver:1 eco:2
[    0.000000] bootconsole [early0] enabled
[    0.000000] CPU0 revision is: 00019655 (MIPS 24KEc)
[    0.000000] MIPS: machine is VoCore2
[    0.000000] Determined physical RAM map:
[    0.000000]  memory: 08000000 @ 00000000 (usable)
[    0.000000] Initrd not found or empty - disabling initrd
[    0.000000] Primary instruction cache 64kB, VIPT, 4-way, linesize 32 bytes.
[    0.000000] Primary data cache 32kB, 4-way, PIPT, no aliases, linesize 32 bytes
[    0.000000] Zone ranges:
[    0.000000]   Normal   [mem 0x0000000000000000-0x0000000007ffffff]
[    0.000000] Movable zone start for each node
[    0.000000] Early memory node ranges
[    0.000000]   node   0: [mem 0x0000000000000000-0x0000000007ffffff]
[    0.000000] Initmem setup node 0 [mem 0x0000000000000000-0x0000000007ffffff]
[    0.000000] random: get_random_bytes called from start_kernel+0x90/0x478 with crng_init=0
[    0.000000] Built 1 zonelists, mobility grouping on.  Total pages: 32512
[    0.000000] Kernel command line: console=ttyS2,115200 console=tty0 fbcon=rotate:3 rootfstype=squashfs,jffs2
[    0.000000] PID hash table entries: 512 (order: -1, 2048 bytes)
[    0.000000] Dentry cache hash table entries: 16384 (order: 4, 65536 bytes)
[    0.000000] Inode-cache hash table entries: 8192 (order: 3, 32768 bytes)
[    0.000000] Writing ErrCtl register=00016cbe
[    0.000000] Readback ErrCtl register=00016cbe
[    0.000000] Memory: 125136K/131072K available (3295K kernel code, 176K rwdata, 816K rodata, 184K init, 210K bss, 5936K reserved, 0K cma-reserved)
[    0.000000] SLUB: HWalign=32, Order=0-3, MinObjects=0, CPUs=1, Nodes=1
[    0.000000] NR_IRQS: 256
[    0.000000] intc: using register map from devicetree
[    0.000000] CPU Clock: 580MHz
[    0.000000] timer_probe: no matching timers found
[    0.000000] clocksource: MIPS: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 6590553264 ns
[    0.000011] sched_clock: 32 bits at 290MHz, resolution 3ns, wraps every 7405115902ns
[    0.008031] Console: colour dummy device 80x25
[    0.012460] console [tty0] enabled
[    0.015887] bootconsole [early0] disabled
[    0.000000] Linux version 4.14.131 (vonger@Vongers-MacBook-Pro-2.local) (gcc version 7.3.0 (OpenWrt GCC 7.3.0 r7808-ef686b7292)) #0 Thu Jun 27 12:18:52 2019
[    0.000000] Board has DDR2
[    0.000000] Analog PMU set to hw control
[    0.000000] Digital PMU set to hw control
[    0.000000] SoC Type: MediaTek MT7628AN ver:1 eco:2
[    0.000000] bootconsole [early0] enabled
[    0.000000] CPU0 revision is: 00019655 (MIPS 24KEc)
[    0.000000] MIPS: machine is VoCore2
[    0.000000] Determined physical RAM map:
[    0.000000]  memory: 08000000 @ 00000000 (usable)
[    0.000000] Initrd not found or empty - disabling initrd
[    0.000000] Primary instruction cache 64kB, VIPT, 4-way, linesize 32 bytes.
[    0.000000] Primary data cache 32kB, 4-way, PIPT, no aliases, linesize 32 bytes
[    0.000000] Zone ranges:
[    0.000000]   Normal   [mem 0x0000000000000000-0x0000000007ffffff]
[    0.000000] Movable zone start for each node
[    0.000000] Early memory node ranges
[    0.000000]   node   0: [mem 0x0000000000000000-0x0000000007ffffff]
[    0.000000] Initmem setup node 0 [mem 0x0000000000000000-0x0000000007ffffff]
[    0.000000] random: get_random_bytes called from start_kernel+0x90/0x478 with crng_init=0
[    0.000000] Built 1 zonelists, mobility grouping on.  Total pages: 32512
[    0.000000] Kernel command line: console=ttyS2,115200 console=tty0 fbcon=rotate:3 rootfstype=squashfs,jffs2
[    0.000000] PID hash table entries: 512 (order: -1, 2048 bytes)
[    0.000000] Dentry cache hash table entries: 16384 (order: 4, 65536 bytes)
[    0.000000] Inode-cache hash table entries: 8192 (order: 3, 32768 bytes)
[    0.000000] Writing ErrCtl register=00016cbe
[    0.000000] Readback ErrCtl register=00016cbe
[    0.000000] Memory: 125136K/131072K available (3295K kernel code, 176K rwdata, 816K rodata, 184K init, 210K bss, 5936K reserved, 0K cma-reserved)
[    0.000000] SLUB: HWalign=32, Order=0-3, MinObjects=0, CPUs=1, Nodes=1
[    0.000000] NR_IRQS: 256
[    0.000000] intc: using register map from devicetree
[    0.000000] CPU Clock: 580MHz
[    0.000000] timer_probe: no matching timers found
[    0.000000] clocksource: MIPS: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 6590553264 ns
[    0.000011] sched_clock: 32 bits at 290MHz, resolution 3ns, wraps every 7405115902ns
[    0.008031] Console: colour dummy device 80x25
[    0.012460] console [tty0] enabled
[    0.015887] bootconsole [early0] disabled
[    0.019985] Calibrating delay loop... 385.84 BogoMIPS (lpj=1929216)
[    0.079986] pid_max: default: 32768 minimum: 301
[    0.080256] Mount-cache hash table entries: 1024 (order: 0, 4096 bytes)
[    0.080289] Mountpoint-cache hash table entries: 1024 (order: 0, 4096 bytes)
[    0.086071] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
[    0.086134] futex hash table entries: 256 (order: -1, 3072 bytes)
[    0.086275] pinctrl core: initialized pinctrl subsystem
[    0.086858] NET: Registered protocol family 16
[    0.117626] mt7621_gpio 10000600.gpio: registering 32 gpios
[    0.117933] mt7621_gpio 10000600.gpio: registering 32 gpios
[    0.118181] mt7621_gpio 10000600.gpio: registering 32 gpios
[    0.122205] clocksource: Switched to clocksource MIPS
[    0.129577] NET: Registered protocol family 2
[    0.130562] TCP established hash table entries: 1024 (order: 0, 4096 bytes)
[    0.130628] TCP bind hash table entries: 1024 (order: 0, 4096 bytes)
[    0.130676] TCP: Hash tables configured (established 1024 bind 1024)
[    0.130874] UDP hash table entries: 256 (order: 0, 4096 bytes)
[    0.130931] UDP-Lite hash table entries: 256 (order: 0, 4096 bytes)
[    0.131236] NET: Registered protocol family 1
[    0.147182] Crashlog allocated RAM at address 0x3f00000
[    0.148548] workingset: timestamp_bits=30 max_order=15 bucket_order=0
[    0.154546] squashfs: version 4.0 (2009/01/31) Phillip Lougher
[    0.154646] jffs2: version 2.2 (NAND) (SUMMARY) (LZMA) (RTIME) (CMODE_PRIORITY) (c) 2001-2006 Red Hat, Inc.
[    0.165214] io scheduler noop registered
[    0.165319] io scheduler deadline registered (default)
[    0.166334] Serial: 8250/16550 driver, 3 ports, IRQ sharing disabled
[    0.167733] 10000c00.uartlite: ttyS0 at MMIO 0x10000c00 (irq = 28, base_baud = 2500000) is a 16550A
[    0.168556] 10000d00.uart1: ttyS1 at MMIO 0x10000d00 (irq = 29, base_baud = 2500000) is a 16550A
[    0.169347] 10000e00.uart2: ttyS2 at MMIO 0x10000e00 (irq = 30, base_baud = 2500000) is a 16550A
[    0.575929] console [ttyS2] enabled
[    0.580140] cacheinfo: Failed to find cpu0 device node
[    0.585466] cacheinfo: Unable to detect cache hierarchy for CPU 0
[    0.592524] spi-mt7621 10000b00.spi: sys_freq: 193333333
[    0.602293] m25p80 spi0.0: gd25q128 (16384 Kbytes)
[    0.607306] 4 fixed-partitions partitions found on MTD device spi0.0
[    0.613836] Creating 4 MTD partitions on "spi0.0":
[    0.618760] 0x000000000000-0x000000030000 : "u-boot"
[    0.624825] 0x000000030000-0x000000040000 : "u-boot-env"
[    0.631139] 0x000000040000-0x000000050000 : "factory"
[    0.637312] 0x000000050000-0x000001000000 : "firmware"
[    0.714902] 2 uimage-fw partitions found on MTD device firmware
[    0.721015] 0x000000050000-0x0000001b241c : "kernel"
[    0.727045] 0x0000001b241c-0x000001000000 : "rootfs"
[    0.733053] mtd: device 5 (rootfs) set to be root filesystem
[    0.740445] 1 squashfs-split partitions found on MTD device rootfs
[    0.746881] 0x000000380000-0x000001000000 : "rootfs_data"
[    0.754141] libphy: Fixed MDIO Bus: probed
[    0.768547] rt3050-esw 10110000.esw: link changed 0x00
[    0.777025] mtk_soc_eth 10100000.ethernet eth0: mediatek frame engine at 0xb0100000, irq 5
[    0.786704] NET: Registered protocol family 17
[    0.791363] 8021q: 802.1Q VLAN Support v1.8
[    0.807897] VFS: Mounted root (squashfs filesystem) readonly on device 31:5.
[    0.816223] Freeing unused kernel memory: 184K
[    0.820806] This architecture does not have kernel memory protection.
[    2.100970] init: Console is alive
[    2.104845] init: - watchdog -
[    2.362212] random: fast init done
[    2.883744] kmodloader: loading kernel modules from /etc/modules-boot.d/*
[    2.965047] kmodloader: done loading kernel modules from /etc/modules-boot.d/*
[    2.974500] init: - preinit -
[    4.114342] rt3050-esw 10110000.esw: link changed 0x00
[    7.649323] jffs2: notice: (412) jffs2_build_xattr_subsystem: complete building xattr subsystem, 10 of xdatum (2 unchecked, 7 orphan) and 78 of xref (4 dead, 43 orphan) found.
[    7.667350] mount_root: switching to jffs2 overlay
[    7.692257] overlayfs: upper fs does not support tmpfile.
[    7.705332] urandom-seed: Seed file not found (/etc/urandom.seed)
[    7.909840] procd: - early -
[    7.913758] procd: - watchdog -
[    8.630091] procd: - watchdog -
[    8.633709] procd: - ubus -
[    8.867640] random: ubusd: uninitialized urandom read (4 bytes read)
[    9.024867] random: ubusd: uninitialized urandom read (4 bytes read)
[    9.031955] random: ubusd: uninitialized urandom read (4 bytes read)
[    9.039617] procd: - init -
Please press Enter to activate this console.

9s is still too long, because we did not load wifi driver yet, wifi driver is pretty big and slow…

From begin to 0.82s, everything seems fast and pretty, but after that, at 2.1s, init runs, suddenly, it becomes very slow, we can find an obviously time span at 2.1s, 4.1s and 7.6s.

Emm, why?

I have some guesses:

1. it is because SPI load something from flash and SPI is slow(busy wait, no dma, check my blog about SPI). Once the file system like jffs2 is doing some dirty job, it will slow down the boot.
2. some unknown drivers load by init takes too much time, slow down the boot speed.

As I know, even the driver as big as mt7628.ko(wifi driver), won’t take more than two seconds to load, so it must be something nasty at its boot time.

OpenWrt drivers mostly are port from ralink SDK, they just work but not optimize to the best(maybe ralink is too poor to hire engineer work on this…), so I should have some space to optimize the code. 🙂

My target is to make it boot into 5s, with wifi into 10s.
To be continue…