f1c200快速启动验证研究

shaoxi2010 · 2021-12-23 22:55:54

经过不懈的努力总算把loader给初步调试通了，目前从nand引导启动，测试波形发现上电到boot0运行
示波器发现约200ms，启动到loader后，目前加载kernel 4M 约278ms，解压logo图片使用lz4压缩
读取数据1.2M，解压后2.7M。目前cpu为600M、spinand为100M，使用双线读取，目前看上来spinand读取性能
在14.4M/s左右，解压缩折合为5M/s左右。实际主要还是慢在内核阶段，新编写load加载时间约300ms，
相当于uboot来说相同配置估计有几百ms提升，对整体启动约13s系统而言几乎没变化。时间上电到linux显示logo
用了接近2s左右，还是太慢了。目前内核不压缩在近10M，用空间来换速度差异不大，不知道大神们还有没有优化思路？
日志如下。
[0]Shaoxi2010 f1c loader
[15]DRAM: 64M
[16]MMU:83ffc000
[16]heap:837fc000-83ffbffc
[34] load: dtb ok
[480] decompress: logo ok
[758] load: kernel ok
[758]start kernel!

达克罗德 · 2021-12-24 12:42:52

Linux启动花了13-2=11秒？这也太慢了，start kernel 到进Linux命令行我记得很多网友包括我自己编的都是在1.9s左右

达克罗德 · 2021-12-24 12:46:23

logo太大了，用低位深的bitmap不行吗，或者调色板方式。还可以把背景搞成一个颜色，logo叠在上面，这样只需要一个小logo图片了，背景可以程序填充

shaoxi2010 · 2021-12-24 18:56:49

加logo主要是想验证下是压缩启动划算还是不压缩划算，目前看上去红利很小。

shaoxi2010 · 2022-01-05 23:04:07

又经过不懈的努力优化了内核IO性能，目前看上去从spinand启动开始到shell差不多1.9S左右。
感觉目前最大的瓶颈就在于这个128M的SPINAND的初始化和UBI扫描时间，做成只读压缩系统应该还能提高部分性能。
不知道大神们还有没有优化思路，目前感觉也就刚达到达神的状态。

 [22-41-17.989]  # 
 [22-41-17.990]  [0]Shaoxi2010 f1c loader
 [22-41-18.017]  [15]DRAM: 64M
 [22-41-18.017]  [16]MMU:83ffc000
 [22-41-18.017]  [16]heap:82ffc000-83ffbffc
 [22-41-18.564]  [575] load: kernel 7528880
 [22-41-18.588]  [596] load: fdt 262144
 [22-41-18.607]  [597]start kernel at 0x80008000 fdt at 0x82ffc000!
 [22-41-18.909]  [    0.278473] musb-sunxi 1c13000.usb: Invalid or missing 'dr_mode' property
 [22-41-19.880]  Starting syslogd: OK
 [22-41-19.949]  Starting klogd: OK
 [22-41-20.164]  Running sysctl: OK
 [22-41-20.216]  Starting mdev... OK
 [22-41-21.135]  modprobe: can't change directory to '4.19.223': No such file or directory
 [22-41-21.258]  Initializing random number generator: OK
 [22-41-21.302]  Saving random seed: OK
 [22-41-21.488]  Starting network: ip: socket: Function not implemented
 [22-41-21.520]  ip: socket: Function not implemented
 [22-41-21.535]  FAIL
 [22-41-21.571]  Starting telnetd: OK
 [22-41-21.698]  
 [22-41-21.723]  Welcome to Tiny200
 [22-41-24.836]  Tiny200 login: root
 [22-41-24.862]  login[114]: root login on 'console'
 [22-41-27.198]  # dmesg 
 [22-41-27.229]  [    0.000000] Booting Linux on physical CPU 0x0
 [22-41-27.246]  [    0.000000] Linux version 4.19.223 (parallels@debian-gnu-linux-10) (gcc version 7.3.1 20180622 (release) [ARM/embedded-7-branch revision 261907] (15:7-2018-q2-6)) #86 Wed Jan 5 22:38:05 CST 2022
 [22-41-27.257]  [    0.000000] CPU: ARM926EJ-S [41069265] revision 5 (ARMv5TEJ), cr=0005317f
 [22-41-27.268]  [    0.000000] CPU: VIVT data cache, VIVT instruction cache
 [22-41-27.268]  [    0.000000] OF: fdt: Machine model: Tiny200
 [22-41-27.268]  [    0.000000] Memory policy: Data cache writeback
 [22-41-27.277]  [    0.000000] On node 0 totalpages: 16384
 [22-41-27.285]  [    0.000000]   Normal zone: 128 pages used for memmap
 [22-41-27.285]  [    0.000000]   Normal zone: 0 pages reserved
 [22-41-27.285]  [    0.000000]   Normal zone: 16384 pages, LIFO batch:3
 [22-41-27.296]  [    0.000000] random: get_random_bytes called from start_kernel+0x7c/0x3dc with crng_init=0
 [22-41-27.303]  [    0.000000] pcpu-alloc: s0 r0 d32768 u32768 alloc=1*32768
 [22-41-27.303]  [    0.000000] pcpu-alloc: [0] 0 
 [22-41-27.312]  [    0.000000] Built 1 zonelists, mobility grouping on.  Total pages: 16256
 [22-41-27.318]  [    0.000000] Kernel command line: console=ttyS1,115200 loglevel=4 root=ubi0 ubi.mtd=4 rootfstype=ubifs cma=16M lpj=598528
 [22-41-27.328]  [    0.000000] Dentry cache hash table entries: 8192 (order: 3, 32768 bytes)
 [22-41-27.335]  [    0.000000] Inode-cache hash table entries: 4096 (order: 2, 16384 bytes)
 [22-41-27.345]  [    0.000000] Memory: 58284K/65536K available (3740K kernel code, 216K rwdata, 1156K rodata, 1024K init, 210K bss, 7252K reserved, 0K cma-reserved)
 [22-41-27.351]  [    0.000000] Virtual kernel memory layout:
 [22-41-27.359]  [    0.000000]     vector  : 0xffff0000 - 0xffff1000   (   4 kB)
 [22-41-27.366]  [    0.000000]     fixmap  : 0xffc00000 - 0xfff00000   (3072 kB)
 [22-41-27.374]  [    0.000000]     vmalloc : 0xc4800000 - 0xff800000   ( 944 MB)
 [22-41-27.374]  [    0.000000]     lowmem  : 0xc0000000 - 0xc4000000   (  64 MB)
 [22-41-27.381]  [    0.000000]     modules : 0xbf000000 - 0xc0000000   (  16 MB)
 [22-41-27.388]  [    0.000000]       .text : 0x(ptrval) - 0x(ptrval)   (4733 kB)
 [22-41-27.395]  [    0.000000]       .init : 0x(ptrval) - 0x(ptrval)   (1024 kB)
 [22-41-27.395]  [    0.000000]       .data : 0x(ptrval) - 0x(ptrval)   ( 217 kB)
 [22-41-27.401]  [    0.000000]        .bss : 0x(ptrval) - 0x(ptrval)   ( 211 kB)
 [22-41-27.408]  [    0.000000] SLUB: HWalign=32, Order=0-3, MinObjects=0, CPUs=1, Nodes=1
 [22-41-27.415]  [    0.000000] NR_IRQS: 16, nr_irqs: 16, preallocated irqs: 16
 [22-41-27.424]  [    0.000041] sched_clock: 32 bits at 24MHz, resolution 41ns, wraps every 89478484971ns
 [22-41-27.430]  [    0.000105] clocksource: timer: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 79635851949 ns
 [22-41-27.437]  [    0.000495] Console: colour dummy device 80x30
 [22-41-27.445]  [    0.000593] Calibrating delay loop (skipped) preset value.. 299.26 BogoMIPS (lpj=598528)
 [22-41-27.452]  [    0.000621] pid_max: default: 32768 minimum: 301
 [22-41-27.459]  [    0.000967] Mount-cache hash table entries: 1024 (order: 0, 4096 bytes)
 [22-41-27.466]  [    0.000989] Mountpoint-cache hash table entries: 1024 (order: 0, 4096 bytes)
 [22-41-27.473]  [    0.001986] CPU: Testing write buffer coherency: ok
 [22-41-27.473]  [    0.003627] Setting up static identity map for 0x80100000 - 0x8010003c
 [22-41-27.481]  [    0.007842] devtmpfs: initialized
 [22-41-27.488]  [    0.013759] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645041785100000 ns
 [22-41-27.496]  [    0.013799] futex hash table entries: 256 (order: -1, 3072 bytes)
 [22-41-27.496]  [    0.013960] pinctrl core: initialized pinctrl subsystem
 [22-41-27.506]  [    0.015996] DMA: preallocated 256 KiB pool for atomic coherent allocations
 [22-41-27.506]  [    0.038346] SCSI subsystem initialized
 [22-41-27.513]  [    0.038635] usbcore: registered new interface driver usbfs
 [22-41-27.520]  [    0.038765] usbcore: registered new interface driver hub
 [22-41-27.528]  [    0.038877] usbcore: registered new device driver usb
 [22-41-27.528]  [    0.039542] Advanced Linux Sound Architecture Driver Initialized.
 [22-41-27.534]  [    0.040408] clocksource: Switched to clocksource timer
 [22-41-27.542]  [    0.062174] NetWinder Floating Point Emulator V0.97 (double precision)
 [22-41-27.550]  [    0.064725] workingset: timestamp_bits=30 max_order=14 bucket_order=0
 [22-41-27.550]  [    0.091463] io scheduler noop registered (default)
 [22-41-27.558]  [    0.091483] io scheduler mq-deadline registered
 [22-41-27.566]  [    0.103702] suniv-pinctrl 1c20800.pinctrl: initialized sunXi PIO driver
 [22-41-27.574]  [    0.126017] Serial: 8250/16550 driver, 8 ports, IRQ sharing disabled
 [22-41-27.574]  [    0.130816] console [ttyS1] disabled
 [22-41-27.583]  [    0.151098] 1c25400.serial: ttyS1 at MMIO 0x1c25400 (irq = 26, base_baud = 6250000) is a 16550A
 [22-41-27.583]  [    0.151227] console [ttyS1] enabled
 [22-41-27.594]  [    0.157964] panel-simple panel: panel supply power not found, using dummy regulator
 [22-41-27.601]  [    0.158153] panel-simple panel: Linked as a consumer to regulator.0
 [22-41-27.609]  [    0.159631] SCSI Media Changer driver v0.25 
 [22-41-27.617]  [    0.160716] sun6i-spinand 1c05000.spi: speed clock 100000000
 [22-41-27.617]  [    0.160743] sun6i-spinand 1c05000.spi: fifo depth 64
 [22-41-27.625]  [    0.161891] 5 fixed-partitions partitions found on MTD device (null)
 [22-41-27.632]  [    0.161911] Creating 5 MTD partitions on "(null)":
 [22-41-27.632]  [    0.161938] 0x000000000000-0x000000080000 : "spl"
 [22-41-27.640]  [    0.163246] 0x000000080000-0x000000180000 : "u-boot"
 [22-41-27.640]  [    0.163941] random: fast init done
 [22-41-27.648]  [    0.165094] 0x000000180000-0x0000001c0000 : "dtb"
 [22-41-27.655]  [    0.166166] 0x0000001c0000-0x0000007c0000 : "kernel"
 [22-41-27.655]  [    0.172125] 0x0000007c0000-0x000007f80000 : "rootfs"
 [22-41-27.655]  [    0.226417] random: crng init done
 [22-41-27.663]  [    0.278046] usbcore: registered new interface driver usb-storage
 [22-41-27.670]  [    0.278473] musb-sunxi 1c13000.usb: Invalid or missing 'dr_mode' property
 [22-41-27.678]  [    0.285422] musb-sunxi: probe of 1c13000.usb failed with error -22
 [22-41-27.685]  [    0.285759] udc-core: couldn't find an available UDC - added [zero] to list of pending drivers
 [22-41-27.693]  [    0.285879] i2c /dev entries driver
 [22-41-27.700]  [    0.288016] input: ns2009_ts as /devices/platform/soc/1c27000.twi/i2c-0/0-0048/input/input0
 [22-41-27.708]  [    0.290071] sunxi-wdt 1c20ca0.watchdog: Watchdog enabled (timeout=16 sec, nowayout=0)
 [22-41-27.716]  [    0.291507] sunxi-mmc 1c0f000.mmc: Linked as a consumer to regulator.1
 [22-41-27.716]  [    0.318203] sunxi-mmc 1c0f000.mmc: initialized, max. request size: 16384 KB
 [22-41-27.725]  [    0.320605] usbcore: registered new interface driver usbhid
 [22-41-27.731]  [    0.320617] usbhid: USB HID core driver
 [22-41-27.739]  [    0.323718] sun4i-codec 1c23c00.codec: ASoC: Failed to create component debugfs directory
 [22-41-27.739]  [    0.327871] sun4i-codec 1c23c00.codec: Codec <-> 1c23c00.codec mapping ok
 [22-41-27.749]  [    0.345837] sun4i-backend 1e60000.display-backend: Couldn't find matching frontend, frontend features disabled
 [22-41-27.760]  [    0.346446] sun4i-drm display-engine: bound 1e60000.display-backend (ops 0xc04dbcc4)
 [22-41-27.767]  [    0.347495] sun4i-drm display-engine: bound 1c0c000.lcd-controller (ops 0xc04dab74)
 [22-41-27.775]  [    0.347520] [drm] Supports vblank timestamp caching Rev 2 (21.10.2013).
 [22-41-27.782]  [    0.347527] [drm] No driver support for vblank timestamp query.
 [22-41-27.782]  [    0.397668] Console: switching to colour frame buffer device 60x34
 [22-41-27.793]  [    0.414385] sun4i-drm display-engine: fb0: DRM emulated frame buffer device
 [22-41-27.800]  [    0.415472] [drm] Initialized sun4i-drm 1.0.0 20150629 for display-engine on minor 0
 [22-41-27.808]  [    0.416570] ubi0: attaching mtd4
 [22-41-27.808]  [    0.659808] ubi0: scanning is finished
 [22-41-27.815]  [    0.670860] ubi0: attached mtd4 (name "rootfs", size 119 MiB)
 [22-41-27.815]  [    0.670883] ubi0: PEB size: 131072 bytes (128 KiB), LEB size: 126976 bytes
 [22-41-27.826]  [    0.670893] ubi0: min./max. I/O unit sizes: 2048/2048, sub-page size 2048
 [22-41-27.833]  [    0.670904] ubi0: VID header offset: 2048 (aligned 2048), data offset: 4096
 [22-41-27.841]  [    0.670913] ubi0: good PEBs: 956, bad PEBs: 2, corrupted PEBs: 0
 [22-41-27.848]  [    0.670923] ubi0: user volume: 1, internal volumes: 1, max. volumes count: 128
 [22-41-27.856]  [    0.670936] ubi0: max/mean erase counter: 2/0, WL threshold: 4096, image sequence number: 1935136571
 [22-41-27.865]  [    0.670946] ubi0: available PEBs: 0, total reserved PEBs: 956, PEBs reserved for bad PEB handling: 38
 [22-41-27.865]  [    0.671300] of_cfs_init
 [22-41-27.873]  [    0.671378] of_cfs_init: OK
 [22-41-27.873]  [    0.671542] ALSA device list:
 [22-41-27.880]  [    0.671555]   #0: F1C100s Audio Codec
 [22-41-27.888]  [    0.673152] ubi0: background thread "ubi_bgt0d" started, PID 53
 [22-41-27.888]  [    0.698797] UBIFS (ubi0:0): recovery needed
 [22-41-27.888]  [    0.741555] UBIFS (ubi0:0): recovery deferred
 [22-41-27.898]  [    0.741775] UBIFS (ubi0:0): UBIFS: mounted UBI device 0, volume 0, name "rootfs", R/O mode
 [22-41-27.909]  [    0.741797] UBIFS (ubi0:0): LEB size: 126976 bytes (124 KiB), min./max. I/O unit sizes: 2048 bytes/2048 bytes
 [22-41-27.916]  [    0.741817] UBIFS (ubi0:0): FS size: 114659328 bytes (109 MiB, 903 LEBs), journal size 9023488 bytes (8 MiB, 72 LEBs)
 [22-41-27.927]  [    0.741827] UBIFS (ubi0:0): reserved for root: 0 bytes (0 KiB)
 [22-41-27.937]  [    0.741846] UBIFS (ubi0:0): media format: w4/r0 (latest is w5/r0), UUID 87713502-C622-4350-A244-286A7160446F, small LPT model
 [22-41-27.944]  [    0.743048] VFS: Mounted root (ubifs filesystem) readonly on device 0:13.
 [22-41-27.944]  [    0.743941] devtmpfs: mounted
 [22-41-27.951]  [    0.748134] Freeing unused kernel memory: 1024K
 [22-41-27.959]  [    0.748250] Run /sbin/init as init process
 [22-41-27.959]  [    0.931684] UBIFS (ubi0:0): completing deferred recovery
 [22-41-27.967]  [    0.956984] UBIFS (ubi0:0): background thread "ubifs_bgt0_0" started, PID 56
 [22-41-27.967]  [    0.962054] UBIFS (ubi0:0): deferred recovery completed

shaoxi2010 · 2022-01-09 22:09:05

经过不懈努力排查，目前能做到3s左右进入QT5的时钟demo。但从目前来看还有比较多的疑惑项。
1. 示波器观察上电到启动bootloader约100ms
2. bootloader解压成Image，引导linux启动花费500ms，排除内核解压逻辑。
3. 进入内核观察dmesg打印，fb初始化大约在350ms
但是仔细比对视频帧发现，其实阶段时间不对。
1. 从上电到fb由白变黑时常大约是2s左右，统计只有不到1s。
2. fb变白到qt起来基本上1s左右，基本符合。

看起来从Image启动到内核计时开始有约解决1s的时间耗在了不知道的地方，不知道这个结论对不对？
不知道大佬们研究过这一段启动时间没有，感觉有点不对劲。
启动日志如下：

 [21-41-23.660]  tiny200 login: 
 [21-41-23.660]  [0]Shaoxi2010 f1c loader
 [21-41-23.684]  [14]DRAM: 64M
 [21-41-23.684]  [16]MMU:83ffc000
 [21-41-23.684]  [16]heap:82ffc000-83ffbffc
 [21-41-23.698]  [39] load: fdt 262144
 [21-41-24.164]  [500] load: kernel 7515276
 [21-41-24.190]  [500]start kernel at 0x80008000 fdt at 0x82ffc800!
 [21-41-25.952]  QFbVtHandler: socketpair() failed (Function not implemented)
 [21-41-27.123]  Starting syslogd: OK
 [21-41-27.154]  Starting klogd: OK
 [21-41-27.247]  Running sysctl: OK
 [21-41-27.271]  Starting mdev... OK
 [21-41-28.280]  modprobe: can't change directory to '/lib/modules': No such file or directory
 [21-41-28.332]  Initializing random number generator: OK
 [21-41-28.353]  Saving random seed: OK
 [21-41-28.429]  Starting network: ip: socket: Function not implemented
 [21-41-28.442]  ip: socket: Function not implemented
 [21-41-28.443]  FAIL
 [21-41-28.553]  
 [21-41-28.568]  Welcome to Tiny200
 [21-41-30.178]  tiny200 login: root
 [21-41-30.197]  login[112]: root login on 'console'
 [21-41-32.904]  # dmesg 
 [21-41-32.923]  [    0.000000] Booting Linux on physical CPU 0x0
 [21-41-32.937]  [    0.000000] Linux version 4.19.223 (parallels@debian-gnu-linux-10) (gcc version 7.3.1 20180622 (release) [ARM/embedded-7-branch revision 261907] (15:7-2018-q2-6)) #102 Sun Jan 9 20:54:06 CST 2022
 [21-41-32.948]  [    0.000000] CPU: ARM926EJ-S [41069265] revision 5 (ARMv5TEJ), cr=0005317f
 [21-41-32.958]  [    0.000000] CPU: VIVT data cache, VIVT instruction cache
 [21-41-32.958]  [    0.000000] OF: fdt: Machine model: Tiny200
 [21-41-32.958]  [    0.000000] Memory policy: Data cache writeback
 [21-41-32.967]  [    0.000000] On node 0 totalpages: 16384
 [21-41-32.975]  [    0.000000]   Normal zone: 128 pages used for memmap
 [21-41-32.975]  [    0.000000]   Normal zone: 0 pages reserved
 [21-41-32.975]  [    0.000000]   Normal zone: 16384 pages, LIFO batch:3
 [21-41-32.986]  [    0.000000] random: get_random_bytes called from start_kernel+0x70/0x35c with crng_init=0
 [21-41-32.993]  [    0.000000] pcpu-alloc: s0 r0 d32768 u32768 alloc=1*32768
 [21-41-32.993]  [    0.000000] pcpu-alloc: [0] 0 
 [21-41-33.003]  [    0.000000] Built 1 zonelists, mobility grouping on.  Total pages: 16256
 [21-41-33.014]  [    0.000000] Kernel command line: console=ttyS1,115200 loglevel=4 root=ubi0 ubi.mtd=4 rootfstype=ubifs ubi.fm_autoconvert=1 cma=16m lpj=598528
 [21-41-33.021]  [    0.000000] Dentry cache hash table entries: 8192 (order: 3, 32768 bytes)
 [21-41-33.029]  [    0.000000] Inode-cache hash table entries: 4096 (order: 2, 16384 bytes)
 [21-41-33.041]  [    0.000000] Memory: 58308K/65536K available (3191K kernel code, 203K rwdata, 1104K rodata, 1024K init, 197K bss, 7228K reserved, 0K cma-reserved)
 [21-41-33.041]  [    0.000000] Virtual kernel memory layout:
 [21-41-33.047]  [    0.000000]     vector  : 0xffff0000 - 0xffff1000   (   4 kB)
 [21-41-33.054]  [    0.000000]     fixmap  : 0xffc00000 - 0xfff00000   (3072 kB)
 [21-41-33.061]  [    0.000000]     vmalloc : 0xc4800000 - 0xff800000   ( 944 MB)
 [21-41-33.067]  [    0.000000]     lowmem  : 0xc0000000 - 0xc4000000   (  64 MB)
 [21-41-33.074]  [    0.000000]     modules : 0xbf000000 - 0xc0000000   (  16 MB)
 [21-41-33.080]  [    0.000000]       .text : 0x(ptrval) - 0x(ptrval)   (4184 kB)
 [21-41-33.087]  [    0.000000]       .init : 0x(ptrval) - 0x(ptrval)   (1024 kB)
 [21-41-33.094]  [    0.000000]       .data : 0x(ptrval) - 0x(ptrval)   ( 204 kB)
 [21-41-33.101]  [    0.000000]        .bss : 0x(ptrval) - 0x(ptrval)   ( 198 kB)
 [21-41-33.108]  [    0.000000] SLUB: HWalign=32, Order=0-3, MinObjects=0, CPUs=1, Nodes=1
 [21-41-33.108]  [    0.000000] NR_IRQS: 16, nr_irqs: 16, preallocated irqs: 16
 [21-41-33.115]  [    0.000044] sched_clock: 32 bits at 24MHz, resolution 41ns, wraps every 89478484971ns
 [21-41-33.126]  [    0.000106] clocksource: timer: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 79635851949 ns
 [21-41-33.133]  [    0.000325] Calibrating delay loop (skipped) preset value.. 299.26 BogoMIPS (lpj=598528)
 [21-41-33.140]  [    0.000357] pid_max: default: 32768 minimum: 301
 [21-41-33.147]  [    0.000698] Mount-cache hash table entries: 1024 (order: 0, 4096 bytes)
 [21-41-33.155]  [    0.000719] Mountpoint-cache hash table entries: 1024 (order: 0, 4096 bytes)
 [21-41-33.155]  [    0.001777] CPU: Testing write buffer coherency: ok
 [21-41-33.163]  [    0.003366] Setting up static identity map for 0x80100000 - 0x8010003c
 [21-41-33.163]  [    0.008529] devtmpfs: initialized
 [21-41-33.174]  [    0.014679] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645041785100000 ns
 [21-41-33.181]  [    0.014719] futex hash table entries: 256 (order: -1, 3072 bytes)
 [21-41-33.188]  [    0.014876] pinctrl core: initialized pinctrl subsystem
 [21-41-33.196]  [    0.017109] DMA: preallocated 256 KiB pool for atomic coherent allocations
 [21-41-33.196]  [    0.036961] SCSI subsystem initialized
 [21-41-33.204]  [    0.037260] usbcore: registered new interface driver usbfs
 [21-41-33.211]  [    0.037378] usbcore: registered new interface driver hub
 [21-41-33.218]  [    0.037489] usbcore: registered new device driver usb
 [21-41-33.218]  [    0.038235] Advanced Linux Sound Architecture Driver Initialized.
 [21-41-33.226]  [    0.039022] clocksource: Switched to clocksource timer
 [21-41-33.234]  [    0.045209] workingset: timestamp_bits=30 max_order=14 bucket_order=0
 [21-41-33.243]  [    0.068338] io scheduler noop registered (default)
 [21-41-33.243]  [    0.068358] io scheduler mq-deadline registered
 [21-41-33.252]  [    0.080202] suniv-pinctrl 1c20800.pinctrl: initialized sunXi PIO driver
 [21-41-33.252]  [    0.101924] Serial: 8250/16550 driver, 8 ports, IRQ sharing disabled
 [21-41-33.260]  [    0.106589] console [ttyS1] disabled
 [21-41-33.267]  [    0.126876] 1c25400.serial: ttyS1 at MMIO 0x1c25400 (irq = 26, base_baud = 6250000) is a 16550A
 [21-41-33.275]  [    0.127076] console [ttyS1] enabled
 [21-41-33.275]  [    0.134453] panel-simple panel: panel supply power not found, using dummy regulator
 [21-41-33.284]  [    0.134659] panel-simple panel: Linked as a consumer to regulator.0
 [21-41-33.291]  [    0.136297] SCSI Media Changer driver v0.25 
 [21-41-33.291]  [    0.137309] sun6i-spinand 1c05000.spi: speed clock 100000000
 [21-41-33.300]  [    0.137335] sun6i-spinand 1c05000.spi: fifo depth 64
 [21-41-33.309]  [    0.138510] 5 fixed-partitions partitions found on MTD device (null)
 [21-41-33.309]  [    0.138529] Creating 5 MTD partitions on "(null)":
 [21-41-33.315]  [    0.138557] 0x000000000000-0x000000080000 : "spl"
 [21-41-33.324]  [    0.139942] 0x000000080000-0x000000180000 : "u-boot"
 [21-41-33.324]  [    0.140742] random: fast init done
 [21-41-33.324]  [    0.141579] 0x000000180000-0x0000001c0000 : "dtb"
 [21-41-33.331]  [    0.142595] 0x0000001c0000-0x0000007c0000 : "kernel"
 [21-41-33.339]  [    0.148596] 0x0000007c0000-0x000007f80000 : "rootfs"
 [21-41-33.339]  [    0.207685] random: crng init done
 [21-41-33.346]  [    0.257719] usbcore: registered new interface driver usb-storage
 [21-41-33.354]  [    0.258511] usb_phy_generic usb_phy_generic.0.auto: usb_phy_generic.0.auto supply vcc not found, using dummy regulator
 [21-41-33.362]  [    0.258709] usb_phy_generic usb_phy_generic.0.auto: Linked as a consumer to regulator.0
 [21-41-33.369]  [    0.271390] musb-hdrc musb-hdrc.1.auto: MUSB HDRC host driver
 [21-41-33.377]  [    0.271462] musb-hdrc musb-hdrc.1.auto: new USB bus registered, assigned bus number 1
 [21-41-33.384]  [    0.273058] hub 1-0:1.0: USB hub found
 [21-41-33.385]  [    0.273189] hub 1-0:1.0: 1 port detected
 [21-41-33.385]  [    0.275200] i2c /dev entries driver
 [21-41-33.396]  [    0.277320] input: ns2009_ts as /devices/platform/soc/1c27000.twi/i2c-0/0-0048/input/input0
 [21-41-33.403]  [    0.279493] sunxi-wdt 1c20ca0.watchdog: Watchdog enabled (timeout=16 sec, nowayout=0)
 [21-41-33.412]  [    0.281031] sunxi-mmc 1c0f000.mmc: Linked as a consumer to regulator.1
 [21-41-33.419]  [    0.307578] sunxi-mmc 1c0f000.mmc: initialized, max. request size: 16384 KB
 [21-41-33.427]  [    0.309895] usbcore: registered new interface driver usbhid
 [21-41-33.427]  [    0.309909] usbhid: USB HID core driver
 [21-41-33.434]  [    0.313210] sun4i-codec 1c23c00.codec: ASoC: Failed to create component debugfs directory
 [21-41-33.443]  [    0.317374] sun4i-codec 1c23c00.codec: Codec <-> 1c23c00.codec mapping ok
 [21-41-33.451]  [    0.335660] sun4i-backend 1e60000.display-backend: Couldn't find matching frontend, frontend features disabled
 [21-41-33.459]  [    0.336298] sun4i-drm display-engine: bound 1e60000.display-backend (ops 0xc044f6d0)
 [21-41-33.468]  [    0.337392] sun4i-drm display-engine: bound 1c0c000.lcd-controller (ops 0xc044e590)
 [21-41-33.477]  [    0.337419] [drm] Supports vblank timestamp caching Rev 2 (21.10.2013).
 [21-41-33.484]  [    0.337425] [drm] No driver support for vblank timestamp query.
 [21-41-33.484]  [    0.339506] sun4i-drm display-engine: fb0: DRM emulated frame buffer device
 [21-41-33.493]  [    0.340442] [drm] Initialized sun4i-drm 1.0.0 20150629 for display-engine on minor 0
 [21-41-33.500]  [    0.341375] ubi0: default fastmap pool size: 45
 [21-41-33.500]  [    0.341392] ubi0: default fastmap WL pool size: 22
 [21-41-33.509]  [    0.341400] ubi0: attaching mtd4
 [21-41-33.509]  [    0.410738] ubi0: attached by fastmap
 [21-41-33.516]  [    0.410757] ubi0: fastmap pool size: 45
 [21-41-33.524]  [    0.410765] ubi0: fastmap WL pool size: 22
 [21-41-33.524]  [    0.422128] ubi0: attached mtd4 (name "rootfs", size 119 MiB)
 [21-41-33.532]  [    0.422150] ubi0: PEB size: 131072 bytes (128 KiB), LEB size: 126976 bytes
 [21-41-33.540]  [    0.422162] ubi0: min./max. I/O unit sizes: 2048/2048, sub-page size 2048
 [21-41-33.547]  [    0.422173] ubi0: VID header offset: 2048 (aligned 2048), data offset: 4096
 [21-41-33.555]  [    0.422182] ubi0: good PEBs: 956, bad PEBs: 2, corrupted PEBs: 0
 [21-41-33.563]  [    0.422193] ubi0: user volume: 1, internal volumes: 1, max. volumes count: 128
 [21-41-33.570]  [    0.422207] ubi0: max/mean erase counter: 4/1, WL threshold: 4096, image sequence number: 1526521727
 [21-41-33.579]  [    0.422219] ubi0: available PEBs: 0, total reserved PEBs: 956, PEBs reserved for bad PEB handling: 38
 [21-41-33.579]  [    0.422589] of_cfs_init
 [21-41-33.579]  [    0.422683] of_cfs_init: OK
 [21-41-33.586]  [    0.422864] ALSA device list:
 [21-41-33.587]  [    0.422879]   #0: F1C100s Audio Codec
 [21-41-33.595]  [    0.424360] ubi0: background thread "ubi_bgt0d" started, PID 54
 [21-41-33.595]  [    0.459605] UBIFS (ubi0:0): recovery needed
 [21-41-33.602]  [    0.497383] UBIFS (ubi0:0): recovery deferred
 [21-41-33.611]  [    0.497594] UBIFS (ubi0:0): UBIFS: mounted UBI device 0, volume 0, name "rootfs", R/O mode
 [21-41-33.618]  [    0.497614] UBIFS (ubi0:0): LEB size: 126976 bytes (124 KiB), min./max. I/O unit sizes: 2048 bytes/2048 bytes
 [21-41-33.627]  [    0.497635] UBIFS (ubi0:0): FS size: 114405376 bytes (109 MiB, 901 LEBs), journal size 9023488 bytes (8 MiB, 72 LEBs)
 [21-41-33.636]  [    0.497644] UBIFS (ubi0:0): reserved for root: 0 bytes (0 KiB)
 [21-41-33.645]  [    0.497664] UBIFS (ubi0:0): media format: w4/r0 (latest is w5/r0), UUID 25CC3243-8C84-41A3-8BD7-5455775BCE75, small LPT model
 [21-41-33.653]  [    0.499196] VFS: Mounted root (ubifs filesystem) readonly on device 0:13.
 [21-41-33.660]  [    0.500304] devtmpfs: mounted
 [21-41-33.667]  [    0.505190] Freeing unused kernel memory: 1024K
 [21-41-33.667]  [    0.505295] Run /sbin/init as init process
 [21-41-33.668]  [    0.621317] UBIFS (ubi0:0): completing deferred recovery
 [21-41-33.680]  [    0.753700] UBIFS (ubi0:0): background thread "ubifs_bgt0_0" started, PID 57
 [21-41-33.680]  [    0.759538] UBIFS (ubi0:0): deferred recovery completed

shaoxi2010 · 2022-01-10 22:36:06

掏出了多年未使用的逻辑分析仪，抓了下启动时间。
目前对系统侧面启动优化已经靠近极限，也就只剩下100ms左右的坏快扫描。
通过GPIO对启动整个流程检测确认，以reset上升为起点，用逻辑分析仪器抓波形。
1. spinand上电brom到运行boot0耗时约200ms，难道是我之前打错了？
2. boot0启动解压kernel消耗500ms
3. kernel进入到kernel计时开始40ms左右
4. kernel完成到init开始，500ms
5. fb panle的perpare从kernel启动耗时1.35s，难道是异步的？
6. 剩余时间为应用层耗时

结论：
1. boot的记时与内核记时是准确的，逻辑分析仪抓取
2. 上电到启动到init总共约1.2s左右
3. drm显示不知道为什么会有延迟初始化现象，可能会阻塞qt启动
4. 目前感觉最大的性能瓶颈在CPU和NAND的IO上，可能换NOR会有更好性能
5. 目前主要瓶颈集中在应用层，看起来更换掉QT5应该会有更好的性能

shaoxi2010 · 2022-01-11 11:01:12

排查发现在drm_probe_fbhepler下确实存在panle延迟初始化，但其对启动优化没影响，只是干扰了启动时间判断

shaoxi2010 · 2022-01-12 00:19:27

去掉QT后有明显的提升，目前上电到启动可以做到在2s显示画面。
耗时一个月总算达到理想值了，真不容易啊。

 [00-10-26.876]  [0]Shaoxi2010 f1c loader
 [00-10-26.894]  [14]DRAM: 64M
 [00-10-26.894]  [16]MMU:83ffc000
 [00-10-26.894]  [16]heap:82ffc000-83ffbffc
 [00-10-26.915]  [39] load: fdt 262144
 [00-10-27.382]  [501] load: kernel 7515276
 [00-10-27.387]  [501]start kernel at 0x80008000 fdt at 0x82ffc800!
 [00-10-28.302]  The framebuffer device was opened successfully.
 [00-10-28.328]  480x272, 16bpp
 [00-10-28.334]  The framebuffer device was mapped to memory successfully.
 [00-10-30.313]  Starting syslogd: OK
 [00-10-30.348]  Starting klogd: OK
 [00-10-30.449]  Running sysctl: OK
 [00-10-30.474]  Starting mdev... OK
 [00-10-31.539]  modprobe: can't change directory to '/lib/modules': No such file or directory
 [00-10-31.595]  Initializing random number generator: OK
 [00-10-31.618]  Saving random seed: OK
 [00-10-31.700]  Starting network: ip: socket: Function not implemented
 [00-10-31.714]  ip: socket: Function not implemented
 [00-10-31.714]  FAIL
 [00-10-31.824]  
 [00-10-31.829]  Welcome to Tiny200

kekemuyu · 2022-01-12 09:11:14

2s进ui太牛了，是用的spi falsh吗？

shaoxi2010 · 2022-01-12 09:53:49

kekemuyu 说：

2s进ui太牛了，是用的spi falsh吗？

是的，Tiny200自带的兆易spinand。不过目前目前整个rootfs也就十多M,感觉换nor应该更划算点吧。

ubuntu · 2022-01-12 09:59:48

shaoxi2010 说：

kekemuyu 说：
2s进ui太牛了，是用的spi falsh吗？
是的，Tiny200自带的兆易spinand。不过目前目前整个rootfs也就十多M,感觉换nor应该更划算点吧。

楼主牛人！可以提供一个烧录固件体验一下吗？

kekemuyu · 2022-01-12 10:34:16

@shaoxi2010
nor比nand慢很多吧

shaoxi2010 · 2022-01-12 11:17:29

kekemuyu 说：

@shaoxi2010
nor比nand慢很多吧

因为目前看起来nor和nand都支持双线读模式，而nor的读操作省掉了loadpage和waitstatus
每2k就可以少发几个指令，可以少调度少IO，按道理应该更加明显，当然我没片子没测试过。
仅理论推断。

shaoxi2010 · 2022-01-12 11:31:13

ubuntu 说：

shaoxi2010 说：
kekemuyu 说：
2s进ui太牛了，是用的spi falsh吗？
是的，Tiny200自带的兆易spinand。不过目前目前整个rootfs也就十多M,感觉换nor应该更划算点吧。
楼主牛人！可以提供一个烧录固件体验一下吗？

目前打算自己用，抱歉。如果你也想做优化我可以提供思路。

mengxp · 2022-04-06 10:58:20

我这 spi nor 测试 dread qread dma 性能都是 16MB/s 左右和楼主差不多。
但是我想这块肯定有点问题，dual和quad速度不应该一样，应该是倍数关系。
另外性能应该不止这些。按100MHz时钟算，dread qread读应该有 25MB/s 或 50MB/s。

mengxp · 2022-04-07 13:38:00

调整了dma burst length qread速度达到24MB/s 但距离 50MB/s 仍然遥远。

shaoxi2010 · 2022-04-07 14:53:17

f1c不是说控制器没有quad模式么

mengxp · 2022-04-07 15:33:52

shaoxi2010 说：

f1c不是说控制器没有quad模式么

我用的r328

mengxp · 2022-04-07 22:16:03

逻辑分析仪分析，每隔一个字节，每隔一个burst，都会有停顿，不会优化了，感觉没什么能优化的了。应该是DMA和FIFO的问题，
频率计看了下，100M SPI频率，频率计测1秒周期得等效工作频率是 ~44MHz

实际跑代码测试速率 ~22.1MB/s

4MB cost 181ms
4MB 64KB slice cost 183ms
4MB 128KB slice cost 183ms
4MB 256KB slice cost 182ms
4MB 512KB slice cost 182ms

最近编辑记录 mengxp (2022-04-07 22:16:31)

kakatoo · 2022-04-29 15:32:42

楼主和各位大神能提供下快速启动的完整的思路吗？

shaoxi2010 · 2022-04-29 17:48:20

我这边就简单说下大致思路吧，我感觉就是分析-验证不断重复优化就完了。
1. 常规优化部分，比如关闭uboot的delay、关闭不必要的串口打印、关闭不必要的功能，先看看基本情况。
2. 还不理想就统计各个阶段的时常，先找到消耗最大的问题点，再去排查影响。比如：
a）boot阶段的spi性能很差，也没有开启dma使用双线模式
b）内核解压缩阶段，受CPU和内存性能gzip本身就很慢但lzo压缩会快很多
c）内核启动阶段，通过初始化时间上看，spinand坏块扫描消耗很大，ubi挂载也比较慢
d）程序启动阶段，分析是卡在IO上还是卡在CPU上
3. 根据性能问题点去针对性修改，
a) boot阶段直接重写，打开cache并使用双线spi驱动加载，再使用lz4进行提前解压缩，权衡spi读取速度和解压缩速度提高空间利用率，约14M/s
b) 针对主线spinand内核架构多次的buffer，重写了spinand驱动，避免访问2字节也读一页，命令多次重发，多次memcpy，IO提升到8M/s
c) 针对ubi层级慢，使用快速挂载减少扫描，选择压缩模式到lzo，得到最佳权衡性能
d）对应用进行裁减，减少load的数量级，比如使用musl的libc，去除掉C++功能，排查调度器，将CPU尽量让给UI程序，选择一些小的UI框架提升也挺大的

hameyou · 2024-08-16 18:32:55

优化 f1c200s启动时间

WhyCan Forum(哇酷开发者社区)

楼主 # 2021-12-23 22:55:54 分享评论

f1c200快速启动验证研究

#1 2021-12-24 12:42:52 分享评论

Re: f1c200快速启动验证研究

#2 2021-12-24 12:46:23 分享评论

Re: f1c200快速启动验证研究

楼主 #3 2021-12-24 18:56:49 分享评论

Re: f1c200快速启动验证研究

楼主 #4 2022-01-05 23:04:07 分享评论

Re: f1c200快速启动验证研究

楼主 #5 2022-01-09 22:09:05 分享评论

Re: f1c200快速启动验证研究

楼主 #6 2022-01-10 22:36:06 分享评论

Re: f1c200快速启动验证研究

楼主 #7 2022-01-11 11:01:12 分享评论

Re: f1c200快速启动验证研究

楼主 #8 2022-01-12 00:19:27 分享评论

Re: f1c200快速启动验证研究

#9 2022-01-12 09:11:14 分享评论

Re: f1c200快速启动验证研究

楼主 #10 2022-01-12 09:53:49 分享评论

Re: f1c200快速启动验证研究

#11 2022-01-12 09:59:48 分享评论

Re: f1c200快速启动验证研究

#12 2022-01-12 10:34:16 分享评论

Re: f1c200快速启动验证研究

楼主 #13 2022-01-12 11:17:29 分享评论

Re: f1c200快速启动验证研究

楼主 #14 2022-01-12 11:31:13 分享评论

Re: f1c200快速启动验证研究

#15 2022-04-06 10:58:20 分享评论

Re: f1c200快速启动验证研究

#16 2022-04-07 13:38:00 分享评论

Re: f1c200快速启动验证研究

楼主 #17 2022-04-07 14:53:17 分享评论

Re: f1c200快速启动验证研究

#18 2022-04-07 15:33:52 分享评论

Re: f1c200快速启动验证研究

#19 2022-04-07 22:16:03 分享评论

Re: f1c200快速启动验证研究

#21 2022-04-29 15:32:42 分享评论

Re: f1c200快速启动验证研究

楼主 #22 2022-04-29 17:48:20 分享评论

Re: f1c200快速启动验证研究

#24 2024-08-16 18:32:55 分享评论

Re: f1c200快速启动验证研究

页脚