Extremely slow boot on Nano SD since recent update. **solved**

[staze]

Not sure which update did it, but a reboot now takes like 10 minutes.

Here's my dmesg output

Code: Select all

[    0.000000] Linux version 4.9.73 (boris@develop) (gcc version 5.5.0 (OpenWrt GCC 5.5.0 r5669-a367645) ) #0 Tue Jan 2 16:22:19 2018
[    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] On node 0 totalpages: 32768
[    0.000000] free_area_init_node: node 0, pgdat 803f7174, node_mem_map 81000020
[    0.000000]   Normal zone: 256 pages used for memmap
[    0.000000]   Normal zone: 0 pages reserved
[    0.000000]   Normal zone: 32768 pages, LIFO batch:7
[    0.000000] pcpu-alloc: s0 r0 d32768 u32768 alloc=1*32768
[    0.000000] pcpu-alloc: [0] 0 
[    0.000000] Built 1 zonelists in Zone order, mobility grouping on.  Total pages: 32512
[    0.000000] Kernel command line: console=ttyS2,115200 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=0007cc70
[    0.000000] Readback ErrCtl register=0007cc70
[    0.000000] Memory: 125420K/131072K available (3149K kernel code, 159K rwdata, 756K rodata, 152K init, 209K bss, 5652K 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] clocksource_probe: no matching clocksources found
[    0.000000] clocksource: MIPS: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 6590553264 ns
[    0.000012] sched_clock: 32 bits at 290MHz, resolution 3ns, wraps every 7405115902ns
[    0.007527] Calibrating delay loop... 385.84 BogoMIPS (lpj=1929216)
[    0.070044] pid_max: default: 32768 minimum: 301
[    0.074636] Mount-cache hash table entries: 1024 (order: 0, 4096 bytes)
[    0.080976] Mountpoint-cache hash table entries: 1024 (order: 0, 4096 bytes)
[    0.093978] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
[    0.103467] futex hash table entries: 256 (order: -1, 3072 bytes)
[    0.109395] pinctrl core: initialized pinctrl subsystem
[    0.115086] NET: Registered protocol family 16
[    0.141781] mt7621_gpio 10000600.gpio: registering 32 gpios
[    0.147508] mt7621_gpio 10000600.gpio: registering 32 gpios
[    0.153047] mt7621_gpio 10000600.gpio: registering 32 gpios
[    0.162353] clocksource: Switched to clocksource MIPS
[    0.168496] NET: Registered protocol family 2
[    0.173558] TCP established hash table entries: 1024 (order: 0, 4096 bytes)
[    0.180249] TCP bind hash table entries: 1024 (order: 0, 4096 bytes)
[    0.186435] TCP: Hash tables configured (established 1024 bind 1024)
[    0.192633] UDP hash table entries: 256 (order: 0, 4096 bytes)
[    0.198231] UDP-Lite hash table entries: 256 (order: 0, 4096 bytes)
[    0.204581] NET: Registered protocol family 1
[    0.208754] PCI: CLS 0 bytes, default 32
[    0.211727] Crashlog allocated RAM at address 0x3f00000
[    0.217924] workingset: timestamp_bits=30 max_order=15 bucket_order=0
[    0.232472] squashfs: version 4.0 (2009/01/31) Phillip Lougher
[    0.238046] jffs2: version 2.2 (NAND) (SUMMARY) (LZMA) (RTIME) (CMODE_PRIORITY) (c) 2001-2006 Red Hat, Inc.
[    0.256138] io scheduler noop registered
[    0.259869] io scheduler deadline registered (default)
[    0.265779] Serial: 8250/16550 driver, 3 ports, IRQ sharing disabled
[    0.273169] 10000c00.uartlite: ttyS0 at MMIO 0x10000c00 (irq = 28, base_baud = 2500000) is a 16550A
[    0.282430] 10000d00.uart1: ttyS1 at MMIO 0x10000d00 (irq = 29, base_baud = 2500000) is a 16550A
[    0.291400] 10000e00.uart2: ttyS2 at MMIO 0x10000e00 (irq = 30, base_baud = 2500000) is a 16550A
[    0.299923] console [ttyS2] enabled
[    0.306916] bootconsole [early0] disabled
[    0.316306] spi-mt7621 10000b00.spi: sys_freq: 193333333
[    0.327539] m25p80 spi32766.0: using chunked io (size=32)
[    0.333092] m25p80 spi32766.0: gd25q128 (16384 Kbytes)
[    0.338331] 4 ofpart partitions found on MTD device spi32766.0
[    0.344253] Creating 4 MTD partitions on "spi32766.0":
[    0.349473] 0x000000000000-0x000000030000 : "u-boot"
[    0.356283] 0x000000030000-0x000000040000 : "u-boot-env"
[    0.363580] 0x000000040000-0x000000050000 : "factory"
[    0.370518] 0x000000050000-0x000001000000 : "firmware"
[    0.451090] 2 uimage-fw partitions found on MTD device firmware
[    0.457138] 0x000000050000-0x00000019b0c4 : "kernel"
[    0.463829] 0x00000019b0c4-0x000001000000 : "rootfs"
[    0.470662] mtd: device 5 (rootfs) set to be root filesystem
[    0.477027] 1 squashfs-split partitions found on MTD device rootfs
[    0.483359] 0x000000770000-0x000001000000 : "rootfs_data"
[    0.491135] libphy: Fixed MDIO Bus: probed
[    0.505744] rt3050-esw 10110000.esw: link changed 0x00
[    0.512638] mtk_soc_eth 10100000.ethernet eth0: mediatek frame engine at 0xb0100000, irq 5
[    0.522682] NET: Registered protocol family 10
[    0.530257] NET: Registered protocol family 17
[    0.534904] 8021q: 802.1Q VLAN Support v1.8
[    0.551052] VFS: Mounted root (squashfs filesystem) readonly on device 31:5.
[    0.559099] Freeing unused kernel memory: 152K
[    0.563636] This architecture does not have kernel memory protection.
[    1.710363] init: Console is alive
[    1.714141] init: - watchdog -
[    2.201495] random: fast init done
[    3.927715] kmodloader: loading kernel modules from /etc/modules-boot.d/*
[    4.180230] usbcore: registered new interface driver usbfs
[    4.185981] usbcore: registered new interface driver hub
[    4.191482] usbcore: registered new device driver usb
[    4.228419] ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver
[    4.244244] SCSI subsystem initialized
[    4.253318] ehci-platform: EHCI generic platform driver
[    4.268955] phy phy-10120000.usbphy.0: remote usb device wakeup disabled
[    4.275769] phy phy-10120000.usbphy.0: UTMI 16bit 30MHz
[    4.281095] ehci-platform 101c0000.ehci: EHCI Host Controller
[    4.286982] ehci-platform 101c0000.ehci: new USB bus registered, assigned bus number 1
[    4.295159] ehci-platform 101c0000.ehci: irq 26, io mem 0x101c0000
[    4.322396] ehci-platform 101c0000.ehci: USB 2.0 started, EHCI 1.00
[    4.329806] hub 1-0:1.0: USB hub found
[    4.334080] hub 1-0:1.0: 1 port detected
[    4.342639] ohci_hcd: USB 1.1 'Open' Host Controller (OHCI) Driver
[    4.350426] ohci-platform: OHCI generic platform driver
[    4.356069] ohci-platform 101c1000.ohci: Generic Platform OHCI controller
[    4.363036] ohci-platform 101c1000.ohci: new USB bus registered, assigned bus number 2
[    4.371163] ohci-platform 101c1000.ohci: irq 26, io mem 0x101c1000
[    4.447432] hub 2-0:1.0: USB hub found
[    4.451650] hub 2-0:1.0: 1 port detected
[    4.468567] MTK MSDC device init.
[    4.532523] mtk-sd: MediaTek MT6575 MSDC Driver
[    4.543337] sdhci: Secure Digital Host Controller Interface driver
[    4.549638] sdhci: Copyright(c) Pierre Ossman
[    4.555675] sdhci-pltfm: SDHCI platform and OF driver helper
[    4.567467] usbcore: registered new interface driver usb-storage
[    4.579117] kmodloader: done loading kernel modules from /etc/modules-boot.d/*
[    4.597017] init: - preinit -
[    4.623340] mmc0: new high speed SD card at address 59b4
[    4.638677] mmcblk0: mmc0:59b4 AF UD 1.77 GiB 
[    4.648727]  mmcblk0: p1
[    6.305159] rt3050-esw 10110000.esw: link changed 0x00
[    9.640086] mount_root: loading kmods from internal overlay
[    9.684089] kmodloader: loading kernel modules from //etc/modules-boot.d/*
[    9.693268] kmodloader: done loading kernel modules from //etc/modules-boot.d/*
[   11.662800] jffs2: notice: (391) jffs2_build_xattr_subsystem: complete building xattr subsystem, 0 of xdatum (0 unchecked, 0 orphan) and 0 of xref (0 dead, 0 orphan) found.
[   11.679191] block: attempting to load /tmp/jffs_cfg/upper/etc/config/fstab
[   11.694192] block: extroot: not configured
[   11.960748] jffs2: notice: (388) jffs2_build_xattr_subsystem: complete building xattr subsystem, 0 of xdatum (0 unchecked, 0 orphan) and 0 of xref (0 dead, 0 orphan) found.
[   11.978179] mount_root: loading kmods from internal overlay
[   12.060839] kmodloader: loading kernel modules from /tmp/overlay/upper/etc/modules-boot.d/*
[   12.074059] kmodloader: done loading kernel modules from /tmp/overlay/upper/etc/modules-boot.d/*
[   13.572025] block: attempting to load /tmp/jffs_cfg/upper/etc/config/fstab
[   13.582981] block: extroot: not configured
[   13.588413] mount_root: switching to jffs2 overlay
[   13.640535] urandom-seed: Seeding with /etc/urandom.seed
[   13.807916] procd: - early -
[   13.810945] procd: - watchdog -
[   14.877844] procd: - watchdog -
[   14.881279] procd: - ubus -
[   15.093388] procd: - init -
[   16.476293] kmodloader: loading kernel modules from /etc/modules.d/*
[   16.624310] ip6_tables: (C) 2000-2006 Netfilter Core Team
[   16.694581] hidraw: raw HID events driver (C) Jiri Kosina
[   16.725906] ip_tables: (C) 2000-2006 Netfilter Core Team
[   18.242202] nf_conntrack version 0.5.0 (2048 buckets, 8192 max)
[   18.400575] usbcore: registered new interface driver usbhid
[   18.406320] usbhid: USB HID core driver
[   18.434212] usbcore: registered new interface driver usbserial
[   18.440235] usbcore: registered new interface driver usbserial_generic
[   18.447029] usbserial: USB Serial support registered for generic
[   18.581729] xt_time: kernel timezone is -0000
[   18.588776] usbcore: registered new interface driver ch341
[   18.594543] usbserial: USB Serial support registered for ch341-uart
[   18.604911] usbcore: registered new interface driver cp210x
[   18.610687] usbserial: USB Serial support registered for cp210x
[   18.631488] usbcore: registered new interface driver ftdi_sio
[   18.637530] usbserial: USB Serial support registered for FTDI USB Serial Device
[   18.661586] usbcore: registered new interface driver pl2303
[   18.667440] usbserial: USB Serial support registered for pl2303
[   18.693200] PPP generic driver version 2.4.2
[   18.700380] NET: Registered protocol family 24
[   18.710389] usbcore: registered new interface driver option
[   18.716256] usbserial: USB Serial support registered for GSM modem (1-port)
[   18.748890] kmodloader: done loading kernel modules from /etc/modules.d/*
[   32.310715] rt28xx_init, status=0
[   42.459823] start /root/start.sh
[   49.743976] random: crng init done
[   59.096386] tmpfs size set to 80000k
[   59.116780] tmpfs                    78.1M      1.4M     76.8M   2% /tmp
[   59.259760] EXT4-fs (mmcblk0p1): couldn't mount as ext3 due to feature incompatibilities
[   59.270122] EXT4-fs (mmcblk0p1): couldn't mount as ext2 due to feature incompatibilities
[   60.013548] EXT4-fs (mmcblk0p1): recovery complete
[   60.023621] EXT4-fs (mmcblk0p1): mounted filesystem with ordered data mode. Opts: (null)
[   60.109024] EXT4-fs (mmcblk0p1): mounted filesystem with ordered data mode. Opts: (null)
[   60.781435] EXT4-fs (mmcblk0p1): couldn't mount as ext3 due to feature incompatibilities
[   60.791580] EXT4-fs (mmcblk0p1): couldn't mount as ext2 due to feature incompatibilities
[   60.820012] EXT4-fs (mmcblk0p1): mounted filesystem with ordered data mode. Opts: (null)
[  966.813093] extract meteobridge archive
[  971.301834] meteobridge archive extracted
[  971.317556] done /root/start.sh
[  971.326936] start /home/setup.sh
[  971.695975] EXT4-fs (mmcblk0p1): re-mounted. Opts: stripe=2,data=ordered,commit=60,max_batch_time=1000000,min_batch_time=1000000,errors=remount-ro
[  998.896864] min_free_kbytes set to 4096
[ 1004.327237] done /home/setup.sh

Looks like it's the "extract meteobridge archive". Is this something that used to be done in the background post-boot, or is there something else going on?

Thanks!

[admin]

Do you have any delays on boot defined? Can be done on "System - Admin" tab.

[staze]

Nope. None of that.

[staze]

Anything else I can look for regarding this issue? Or info I can provide to figure out why it's happening? It's a little disconcerting when it takes over 15 minutes to boot.

[admin]

As delay is during loading file from Meteobridge server in the Internet it may be a weak WiFi connection?

If you give me your MAC, I can look up in the server logs what happened to the download process in your case. Strange thing is that others are not impacted to my knowledge.

[staze]

MAC is B8:D8:12:60:42:35

Happy to look at other stuff. Wifi _shouldn't_ be an issue, but then again, I have seen this one connecting to the wrong AP for the last few months so maybe it is.

[staze]

Is there any chance the wifi stack has changed on the Nano recently? it seems to _really_ want to connect to AP that's further away, on channel 1, vs AP that's literally 6ft away on channel 6.

May be AP firmware too... trying to figure that out.

[staze]

So, this is looking like an issue with the wifi stack on the Nano. It seems like it might be looking for the SSID starting on channel 1, and once it finds it, no matter how bad it is, it sticks to that... even though there's a much stronger/better signal on channel 6. Do we know if this behavior changed with a recent update (like, since Nov/December)?

[staze]

Ah ha... wonder if this is it.

/etc/wireless/mt7628/init

Looks like you're looking for ap channel up top when setting up the temporary AP (when there's no wifi)

Code: Select all

SSID="meteobridge-`ifconfig eth0 | grep HWaddr | awk '{print $5}' | tr -d ':'`"
if [ -f /root/apchannel ]
then
  CHA="`cat /root/apchannel`"
else
  CHA=6
fi

that file, "/root/apchannel" is just "1".

Looks like this is set during boot doing a site survey... wonder if it might be better to run this task nightly so the meteobridge can roam to best signal? I just ran it manually /etc/wireless/mt7628/init and it immediately flipped over to channel 6 (which is the correct ap).

Code: Select all

root@MeteoBridge:/etc/wireless/mt7628# ./init
PASS: meteobridge
ra0 rebuilt
set to channel 6

Before

Code: Select all

root@MeteoBridge:/etc/wireless/mt7628# iwpriv ra0 get_site_survey
ra0       get_site_survey:
Ch  SSID                             BSSID               Security               Siganl(%)W-Mode  ExtCH  NT WPS DPID
1   Net670                           7c:9a:54:d4:21:db   WPA2PSK/AES            34       11b/g/n NONE   In YES     
5   chlwifi                          e8:9c:25:03:73:c0   WPA2PSK/AES            52       11b/g/n NONE   In YES     
6   HOME-2.4                         a8:97:cd:35:1e:5a   WPA2PSK/AES            44       11b/g/n NONE   In YES     
6                                    b6:97:cd:35:1e:5a   WPA1WPA2/AES           18       11b/g/n NONE   In  NO     
6                                    ae:97:cd:35:1e:5a   WPA2PSK/AES            18       11b/g/n NONE   In  NO     
1   Ringo-IoT                        fa:e2:c6:a8:dd:7d   NONE                   0        11b/g/n NONE   In  NO     
1   Ringo-IoT                        de:b3:70:65:9b:08   WPA2PSK/AES            0        11b/g/n NONE   In  NO  

After

Code: Select all

root@MeteoBridge:/etc/wireless/mt7628# iwpriv ra0 get_site_survey
ra0       get_site_survey:
Ch  SSID                             BSSID               Security               Siganl(%)W-Mode  ExtCH  NT WPS DPID
1   Ringo-IoT                        de:b3:70:65:9b:08   WPA2PSK/AES            7        11b/g/n NONE   In  NO     
3   BJs Place                        ce:9e:43:80:23:45   WPA2PSK/AES            18       11b/g/n NONE   In YES     
6   Ringo                            ac:8b:a9:31:f0:ee   WPA2PSK/TKIPAES        44       11b/g/n NONE   In  NO     
6   Ringo-IoT                        b2:8b:a9:31:f0:ee   WPA2PSK/AES            50       11b/g/n NONE   In  NO     
6                                    b6:97:cd:35:1e:5a   WPA1WPA2/AES           15       11b/g/n NONE   In  NO     
6                                    ba:97:cd:35:1e:5a   WPA2PSK/AES            15       11b/g/n NONE   In  NO     
6                                    ae:97:cd:35:1e:5a   WPA2PSK/AES            15       11b/g/n NONE   In  NO     
11  Ringo                            f4:e2:c6:a8:dd:7d   WPA2PSK/TKIPAES        29       11b/g/n NONE   In  NO     
11  Ringo-IoT                        fa:e2:c6:a8:dd:7d   WPA2PSK/AES            29       11b/g/n NONE   In  NO  

[admin]

As no one is having this problem, it looks like you messed up something in the setup. As you are often working on the shell and are rather experimental, this is the most obvious reason. Your idea that the NANO takes the first channel it can see the SSID on is a nice assumption, but false.