많은 MCU 펌웨어 개발자들이 임베디드 리눅스 도입을 망설이는 이유가 몇가지 있다.
<1> 임베디드 리눅스의 소프트웨어 구조는 복잡하고 어렵다.
툴체인, 커널, 부트로더, 루트파일 시스템 등등 공부할것이 많아 개발하는데 시간이 많이 필요하다.
따라서 전반적인 개발 기간이 길어지고 이에따른 비용이 높아진다는 것에 동의한다.
그런데 화려한 GUI와 함께 유무선 네트웍이 필요하다면, MCU 보다는 리눅스가 동작하는 MPU 기반의 고성능 장치가 필요할 것이다.
<2> 임베디드 리눅스를 구성하는 하드웨어가 복잡하고 가격이 높다.
CPU는 대부분 BGA 패키지이고, 외부에 DRAM을 추가해 주어야 하고, PMIC도 필요한 경우가 많다.
그러나 800x480 이상의 TFT LCD를 연결하고, 부드럽게 동작하는 GUI를 구현하고 유무선 네트웍이 동작하는 시스템을 MCU기반으로 회로를 구성하면 전체적인 하드웨어 구성 비용은 임베디드 리눅스 시스템과 큰 차이가 나지는 않는다.
저렴한 중국산 MPU/AP의 경우 기능과 성능에 비해 매우 저렴한 제품이 많기 때문이다.
<3> 부팅속도가 상대적으로 많이 느리다.
보통의 임베디드 리눅스는 최소 10초, 길게는 1분 정도의 부팅시간이 필요하지만, MCU로 만든 시스템은 대부분 1초 이내에 프로그램이 동작한다. 응용프로그램까지 4~5초 이내에 동작한다면 임베디드 리눅스를 적용할 수 있는 범위가 좀 더 많아질 것은 분명하다.
이에 일주일 정도 시간을 투자하여 부팅 속도를 개선하기위해 최적화를 해보려고 한다.
현재 FoxNux 보드의 전원이 켜지고 Qt 응용 프로그램이 동작할때 소요되는 시간을 grabserial이라는 프로그램으로 측정해 보았다.
리셋버튼을 누르면서 스탑워치로 측정하면 약 11초 정도에 Qt 앱이 구동됨을 확인하였으나 좀 더 정확한 단계별 시간 분석이 필요하다.
$ grabserial -v -d "/dev/ttyUSB0" -b 115200 -w 8 -p N -s 1 -e 30 -t -m "U-Boot SPL"
Opening serial port /dev/ttyUSB0
115200:8N1:xonxoff=0:rtscts=0
Program will end in 30 seconds
Printing timing information for each line
Matching pattern 'U-Boot SPL' to set base time
Use Control-C to stop...
[0.000001 0.000001]
[0.000371 0.000370] U-Boot SPL 2017.01-rc2 (Jan 13 2020 - 12:39:18)
[0.004600 0.004600] DRAM: 128 MiB
[0.013261 0.008661] Trying to boot from MMC1
[0.320792 0.307531]
[0.320929 0.000137] U-Boot 2017.01-rc2 (Jan 13 2020 - 12:39:18 +0900) Allwinner Technology
[0.326686 0.005757]
[0.326753 0.000067] CPU: Allwinner S3/V3s (SUN8I 1681)
[0.329875 0.003122] Model: FoxNux One
[0.333667 0.003792] DRAM: 128 MiB
[0.368534 0.034867] MMC: SUNXI SD/MMC: 0
[0.456944 0.088410] *** Warning - bad CRC, using default environment
[0.461986 0.005042]
[0.464169 0.002183] Setting up a 1024x600 lcd console (overscan 0x0)
[0.508528 0.044359] dotclock: 51000kHz = 51000kHz: (1 * 3MHz * 102) / 6
[0.568168 0.059640] In: serial@01c28000
[0.569808 0.001640] Out: serial@01c28000
[0.571888 0.002080] Err: serial@01c28000
[0.574141 0.002253]
[0.574264 0.000123]
[0.574347 0.000083] U-Boot 2017.01-rc2 (Jan 13 2020 - 12:39:18 +0900) Allwinner Technology
[0.580093 0.005746]
[0.580154 0.000061] CPU: Allwinner S3/V3s (SUN8I 1681)
[0.583299 0.003145] Model: FoxNux One
[0.585425 0.002126] DRAM: 128 MiB
[0.586170 0.000745] MMC: SUNXI SD/MMC: 0
[0.588508 0.002338] *** Warning - bad CRC, using default environment
[0.593563 0.005055]
[0.593635 0.000072] Setting up a 1024x600 lcd console (overscan 0x0)
[0.597402 0.003767] dotclock: 51000kHz = 51000kHz: (1 * 3MHz * 102) / 6
[0.602339 0.004937] In: serial@01c28000
[0.604701 0.002362] Out: serial@01c28000
[0.607561 0.002860] Err: serial@01c28000
[0.608914 0.001353] Net: phy interface0
[0.612120 0.003206] eth0: ethernet@1c30000
[0.613901 0.001781] starting USB...
[0.615067 0.001166] No controllers found
[0.617544 0.002477] Press SPACE key two times to abort autoboot in 2 seconds
[2.697882 2.080338] switch to partitions #0, OK
[2.699670 0.001788] mmc0 is current device
[3.257504 0.557834] Scanning mmc 0:1...
[3.312277 0.054773] Found U-Boot script /boot.scr
[3.322879 0.010602] reading /boot.scr
[3.337255 0.014376] 436 bytes read in 15 ms (28.3 KiB/s)
[3.340203 0.002948] ## Executing script at 41900000
[3.353011 0.012808] reading zImage
[3.584786 0.231775] 4798096 bytes read in 232 ms (19.7 MiB/s)
[3.598212 0.013426] reading sun8i-s3-foxnux-one.dtb
[3.623153 0.024941] 14138 bytes read in 25 ms (551.8 KiB/s)
[3.626599 0.003446] ## Flattened Device Tree blob at 41800000
[3.629852 0.003253] Booting using the fdt blob at 0x41800000
[3.634230 0.004378] Loading Device Tree to 42df9000, end 42dff739 ... OK
[3.639934 0.005704] Cannot setup simplefb: node not found
[3.646756 0.006822]
[3.646922 0.000166] Starting kernel ...
[3.648302 0.001380]
[4.081073 0.432771] [ 0.000000] Booting Linux on physical CPU 0x0
[4.085533 0.004460] [ 0.000000] Linux version 5.5.0-rc4 (odroider@hardkernel) (gcc version 8.3.0 (GNU Toolchain for the A-profile Architecture 8.3-2019.03 (arm-rel-8.36))) #1 SMP Mon Jan 13 12:39:43 KST 2020
[4.101606 0.016073] [ 0.000000] CPU: ARMv7 Processor [410fc075] revision 5 (ARMv7), cr=10c5387d
[4.112890 0.011284] [ 0.000000] CPU: div instructions available: patching division code
[4.116595 0.003705] [ 0.000000] CPU: PIPT / VIPT nonaliasing data cache, VIPT aliasing instruction cache
[4.123090 0.006495] [ 0.000000] OF: fdt: Machine model: Hardkernel FoxNux One
[4.128350 0.005260] [ 0.000000] Memory policy: Data cache writealloc
[4.132377 0.004027] [ 0.000000] cma: Reserved 16 MiB at 0x47000000
[4.137285 0.004908] [ 0.000000] percpu: Embedded 15 pages/cpu s30604 r8192 d22644 u61440
[4.143292 0.006007] [ 0.000000] Built 1 zonelists, mobility grouping on. Total pages: 32512
[4.149764 0.006472] [ 0.000000] Kernel command line: console=ttyS0,115200 panic=5 rootwait root=/dev/mmcblk0p2 earlyprintk rw
[4.159717 0.009953] [ 0.000000] Dentry cache hash table entries: 16384 (order: 4, 65536 bytes, linear)
[4.167512 0.007795] [ 0.000000] Inode-cache hash table entries: 8192 (order: 3, 32768 bytes, linear)
[4.175741 0.008229] [ 0.000000] mem auto-init: stack:off, heap alloc:off, heap free:off
[4.181228 0.005487] [ 0.000000] Memory: 101428K/131072K available (7168K kernel code, 430K rwdata, 1944K rodata, 1024K init, 251K bss, 13260K reserved, 16384K cma-reserved, 0K highmem)
[4.195699 0.014471] [ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=1, Nodes=1
[4.202039 0.006340] [ 0.000000] rcu: Hierarchical RCU implementation.
[4.207409 0.005370] [ 0.000000] rcu: RCU event tracing is enabled.
[4.212686 0.005277] [ 0.000000] rcu: RCU restricting CPUs from NR_CPUS=8 to nr_cpu_ids=1.
[4.217823 0.005137] [ 0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 10 jiffies.
[4.225832 0.008009] [ 0.000000] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=1
[4.232250 0.006418] [ 0.000000] NR_IRQS: 16, nr_irqs: 16, preallocated irqs: 16
[4.238808 0.006558] [ 0.000000] random: get_random_bytes called from start_kernel+0x2b0/0x440 with crng_init=0
[4.245826 0.007018] [ 0.000000] arch_timer: cp15 timer(s) running at 24.00MHz (virt).
[4.251731 0.005905] [ 0.000000] clocksource: arch_sys_counter: mask: 0xffffffffffffff max_cycles: 0x588fe9dc0, max_idle_ns: 440795202592 ns
[4.262609 0.010878] [ 0.000006] sched_clock: 56 bits at 24MHz, resolution 41ns, wraps every 4398046511097ns
[4.270636 0.008027] [ 0.000017] Switching to timer-based delay loop, resolution 41ns
[4.276542 0.005906] [ 0.000265] clocksource: timer: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 79635851949 ns
[4.285318 0.008776] [ 0.000550] Console: colour dummy device 80x30
[4.290337 0.005019] [ 0.000599] Calibrating delay loop (skipped), value calculated using timer frequency.. 48.00 BogoMIPS (lpj=240000)
[4.300893 0.010556] [ 0.000614] pid_max: default: 32768 minimum: 301
[4.305220 0.004327] [ 0.000763] Mount-cache hash table entries: 1024 (order: 0, 4096 bytes, linear)
[4.317925 0.012705] [ 0.000777] Mountpoint-cache hash table entries: 1024 (order: 0, 4096 bytes, linear)
[4.322353 0.004428] [ 0.001513] CPU: Testing write buffer coherency: ok
[4.325303 0.002950] [ 0.001942] /cpus/cpu@0 missing clock-frequency property
[4.334655 0.009352] [ 0.001963] CPU0: thread -1, cpu 0, socket 0, mpidr 80000000
[4.338207 0.003552] [ 0.002630] Setting up static identity map for 0x40100000 - 0x40100060
[4.343331 0.005124] [ 0.002807] rcu: Hierarchical SRCU implementation.
[4.346699 0.003368] [ 0.003294] smp: Bringing up secondary CPUs ...
[4.351660 0.004961] [ 0.003312] smp: Brought up 1 node, 1 CPU
[4.355406 0.003746] [ 0.003321] SMP: Total of 1 processors activated (48.00 BogoMIPS).
[4.362560 0.007154] [ 0.003327] CPU: All CPU(s) started in SVC mode.
[4.366591 0.004031] [ 0.003866] devtmpfs: initialized
[4.370802 0.004211] [ 0.007404] VFP support v0.3: implementor 41 architecture 2 part 30 variant 7 rev 5
[4.377133 0.006331] [ 0.007694] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
[4.387743 0.010610] [ 0.007721] futex hash table entries: 256 (order: 2, 16384 bytes, linear)
[4.393944 0.006201] [ 0.008424] pinctrl core: initialized pinctrl subsystem
[4.399457 0.005513] [ 0.009077] thermal_sys: Registered thermal governor 'step_wise'
[4.405425 0.005968] [ 0.009636] NET: Registered protocol family 16
[4.410043 0.004618] [ 0.010989] DMA: preallocated 256 KiB pool for atomic coherent allocations
[4.418741 0.008698] [ 0.012115] hw-breakpoint: found 5 (+1 reserved) breakpoint and 4 watchpoint registers.
[4.424296 0.005555] [ 0.012128] hw-breakpoint: maximum watchpoint size is 8 bytes.
[4.430047 0.005751] [ 0.035004] SCSI subsystem initialized
[4.434662 0.004615] [ 0.035238] usbcore: registered new interface driver usbfs
[4.440076 0.005414] [ 0.035289] usbcore: registered new interface driver hub
[4.448467 0.008391] [ 0.035394] usbcore: registered new device driver usb
[4.451431 0.002964] [ 0.035620] mc: Linux media interface: v0.10
[4.454325 0.002894] [ 0.035655] videodev: Linux video capture interface: v2.00
[4.459926 0.005601] [ 0.035721] pps_core: LinuxPPS API ver. 1 registered
[4.465069 0.005143] [ 0.035727] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti <giometti@linux.it>
[4.474088 0.009019] [ 0.035750] PTP clock support registered
[4.477439 0.003351] [ 0.035995] Advanced Linux Sound Architecture Driver Initialized.
[4.484308 0.006869] [ 0.037343] clocksource: Switched to clocksource arch_sys_counter
[4.490466 0.006158] [ 0.047527] NET: Registered protocol family 2
[4.494006 0.003540] [ 0.048100] tcp_listen_portaddr_hash hash table entries: 512 (order: 0, 6144 bytes, linear)
[4.502201 0.008195] [ 0.048134] TCP established hash table entries: 1024 (order: 0, 4096 bytes, linear)
[4.513999 0.011798] [ 0.048169] TCP bind hash table entries: 1024 (order: 1, 8192 bytes, linear)
[4.518429 0.004430] [ 0.048192] TCP: Hash tables configured (established 1024 bind 1024)
[4.523803 0.005374] [ 0.048320] UDP hash table entries: 256 (order: 1, 8192 bytes, linear)
[4.530327 0.006524] [ 0.048362] UDP-Lite hash table entries: 256 (order: 1, 8192 bytes, linear)
[4.537732 0.007405] [ 0.048563] NET: Registered protocol family 1
[4.541317 0.003585] [ 0.049476] RPC: Registered named UNIX socket transport module.
[4.546892 0.005575] [ 0.049495] RPC: Registered udp transport module.
[4.551910 0.005018] [ 0.049501] RPC: Registered tcp transport module.
[4.557264 0.005354] [ 0.049506] RPC: Registered tcp NFSv4.1 backchannel transport module.
[4.563180 0.005916] [ 0.051691] Initialise system trusted keyrings
[4.568206 0.005026] [ 0.052009] workingset: timestamp_bits=30 max_order=15 bucket_order=0
[4.574249 0.006043] [ 0.059521] NFS: Registering the id_resolver key type
[4.580876 0.006627] [ 0.059565] Key type id_resolver registered
[4.584066 0.003190] [ 0.059573] Key type id_legacy registered
[4.588057 0.003991] [ 0.096325] Key type asymmetric registered
[4.593095 0.005038] [ 0.096342] Asymmetric key parser 'x509' registered
[4.596184 0.003089] [ 0.096448] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247)
[4.604076 0.007892] [ 0.096460] io scheduler mq-deadline registered
[4.607941 0.003865] [ 0.096467] io scheduler kyber registered
[4.614798 0.006857] [ 0.097224] sun4i-usb-phy 1c19400.phy: Couldn't request ID GPIO
[4.618981 0.004183] [ 0.101175] sun8i-v3s-pinctrl 1c20800.pinctrl: initialized sunXi PIO driver
[4.630209 0.011228] [ 0.163225] Serial: 8250/16550 driver, 8 ports, IRQ sharing disabled
[4.634610 0.004401] [ 0.166081] printk: console [ttyS0] disabled
[4.637365 0.002755] [ 0.186351] 1c28000.serial: ttyS0 at MMIO 0x1c28000 (irq = 39, base_baud = 1500000) is a U6_16550A
[4.644225 0.006860] [ 0.750579] printk: console [ttyS0] enabled
[4.672860 0.028635] [ 0.778281] 1c28400.serial: ttyS1 at MMIO 0x1c28400 (irq = 40, base_baud = 1500000) is a U6_16550A
[4.703326 0.030466] [ 0.808736] 1c28800.serial: ttyS2 at MMIO 0x1c28800 (irq = 41, base_baud = 1500000) is a U6_16550A
[4.742547 0.039221] [ 0.847951] libphy: Fixed MDIO Bus: probed
[4.746546 0.003999] [ 0.852541] dwmac-sun8i 1c30000.ethernet: IRQ eth_wake_irq not found
[4.752733 0.006187] [ 0.858975] dwmac-sun8i 1c30000.ethernet: IRQ eth_lpi not found
[4.758556 0.005823] [ 0.864994] dwmac-sun8i 1c30000.ethernet: PTP uses main clock
[4.764487 0.005931] [ 0.870820] dwmac-sun8i 1c30000.ethernet: No regulator found
[4.770382 0.005895] [ 0.876958] dwmac-sun8i 1c30000.ethernet: Current syscon value is not the default 148000 (expect 38000)
[4.780488 0.010106] [ 0.886452] dwmac-sun8i 1c30000.ethernet: No HW DMA feature register supported
[4.786908 0.006420] [ 0.893697] dwmac-sun8i 1c30000.ethernet: RX Checksum Offload Engine supported
[4.795233 0.008325] [ 0.900929] dwmac-sun8i 1c30000.ethernet: COE Type 2
[4.799994 0.004761] [ 0.905889] dwmac-sun8i 1c30000.ethernet: TX Checksum insertion supported
[4.806269 0.006275] [ 0.912683] dwmac-sun8i 1c30000.ethernet: Normal descriptors
[4.811961 0.005692] [ 0.918349] dwmac-sun8i 1c30000.ethernet: Chain mode enabled
[4.821048 0.009087] [ 0.924246] libphy: stmmac: probed
[4.826598 0.005550] [ 0.928304] dwmac-sun8i 1c30000.ethernet: Found internal PHY node
[4.830481 0.003883] [ 0.934547] libphy: mdio_mux: probed
[4.832609 0.002128] [ 0.938210] dwmac-sun8i 1c30000.ethernet: Switch mux to internal PHY
[4.838086 0.005477] [ 0.944565] dwmac-sun8i 1c30000.ethernet: Powering internal PHY
[4.845053 0.006967] [ 0.951590] libphy: mdio_mux: probed
[4.849769 0.004716] [ 0.955524] ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver
[4.856026 0.006257] [ 0.962140] ehci-platform: EHCI generic platform driver
[4.861706 0.005680] [ 0.967644] ehci-platform 1c1a000.usb: EHCI Host Controller
[4.867306 0.005600] [ 0.973260] ehci-platform 1c1a000.usb: new USB bus registered, assigned bus number 1
[4.875621 0.008315] [ 0.981401] ehci-platform 1c1a000.usb: irq 28, io mem 0x01c1a000
[4.911921 0.036300] [ 1.017334] ehci-platform 1c1a000.usb: USB 2.0 started, EHCI 1.00
[4.918831 0.006910] [ 1.024386] hub 1-0:1.0: USB hub found
[4.922366 0.003535] [ 1.028327] hub 1-0:1.0: 1 port detected
[4.926614 0.004248] [ 1.032874] ohci_hcd: USB 1.1 'Open' Host Controller (OHCI) Driver
[4.933502 0.006888] [ 1.039160] ohci-platform: OHCI generic platform driver
[4.939190 0.005688] [ 1.044671] ohci-platform 1c1a400.usb: Generic Platform OHCI controller
[4.945580 0.006390] [ 1.051377] ohci-platform 1c1a400.usb: new USB bus registered, assigned bus number 2
[4.953731 0.008151] [ 1.059452] ohci-platform 1c1a400.usb: irq 29, io mem 0x01c1a400
[5.026917 0.073186] [ 1.132304] hub 2-0:1.0: USB hub found
[5.030304 0.003387] [ 1.136126] hub 2-0:1.0: 1 port detected
[5.037870 0.007566] [ 1.143281] usbcore: registered new interface driver usb-storage
[5.044608 0.006738] [ 1.150202] mousedev: PS/2 mouse device common for all mice
[5.050714 0.006106] [ 1.156449] input: 1c22800.lradc as /devices/platform/soc/1c22800.lradc/input/input0
[5.059560 0.008846] [ 1.165609] sun6i-rtc 1c20400.rtc: registered as rtc0
[5.064372 0.004812] [ 1.170746] sun6i-rtc 1c20400.rtc: RTC enabled
[5.069501 0.005129] [ 1.175383] i2c /dev entries driver
[5.193532 0.124031] [ 1.298841] Goodix-TS 0-0014: ID 911, version: 1060
[5.198549 0.005017] [ 1.304591] Goodix-TS 0-0014: Direct firmware load for goodix_911_cfg.bin failed with error -2
[5.225737 0.027188] [ 1.331139] input: Goodix Capacitive TouchScreen as /devices/platform/soc/1c2ac00.i2c/i2c-0/0-0014/input/input1
[5.245024 0.019287] [ 1.350466] random: fast init done
[5.294947 0.049923] [ 1.400240] ov7670 1-0021: chip found @ 0x42 (mv64xxx_i2c adapter)
[5.369783 0.074836] [ 1.475208] usbcore: registered new interface driver uvcvideo
[5.375467 0.005684] [ 1.481024] USB Video Class driver (1.1.1)
[5.380040 0.004573] [ 1.486024] sunxi-wdt 1c20ca0.watchdog: Watchdog enabled (timeout=16 sec, nowayout=0)
[5.415608 0.035568] [ 1.520949] sunxi-mmc 1c0f000.mmc: initialized, max. request size: 16384 KB
[5.447314 0.031706] [ 1.552723] sunxi-mmc 1c10000.mmc: initialized, max. request size: 16384 KB
[5.455435 0.008121] [ 1.561181] usbcore: registered new interface driver usbhid
[5.460723 0.005288] [ 1.566756] usbhid: USB HID core driver
[5.467225 0.006502] [ 1.572722] sun4i-codec 1c22c00.codec: Failed to register our card
[5.474603 0.007378] [ 1.580199] NET: Registered protocol family 17
[5.480709 0.006106] [ 1.584853] Key type dns_resolver registered
[5.483423 0.002714] [ 1.589342] Registering SWP/SWPB emulation handler
[5.489087 0.005664] [ 1.594613] Loading compiled-in X.509 certificates
[5.503760 0.014673] [ 1.609075] sun4i-drm display-engine: bound 1100000.mixer (ops 0xc084c808)
[5.510474 0.006714] [ 1.616504] sun4i-drm display-engine: bound 1c0c000.lcd-controller (ops 0xc0849aec)
[5.518489 0.008015] [ 1.624231] [drm] Supports vblank timestamp caching Rev 2 (21.10.2013).
[5.527471 0.008982] [ 1.630864] [drm] No driver support for vblank timestamp query.
[5.531380 0.003909] [ 1.637745] [drm] Initialized sun4i-drm 1.0.0 20150629 for display-engine on minor 0
[5.858394 0.327014] [ 1.655482] mmc0: host does not support reading read-only switch, assuming write-enable
[5.865382 0.006988] [ 1.658382] mmc0: new high speed SDHC card at address aaaa
[5.870784 0.005402] [ 1.659297] mmcblk0: mmc0:aaaa SA08G 7.40 GiB
[5.875758 0.004974] [ 1.662676] mmcblk0: p1 p2
[5.878465 0.002707] [ 1.946671] Console: switching to colour frame buffer device 128x37
[5.884475 0.006010] [ 1.990802] sun4i-drm display-engine: fb0: sun4i-drmdrmfb frame buffer device
[5.892909 0.008434] [ 1.998722] usb_phy_generic usb_phy_generic.0.auto: usb_phy_generic.0.auto supply vcc not found, using dummy regulator
[5.904693 0.011784] [ 2.010248] musb-hdrc musb-hdrc.1.auto: MUSB HDRC host driver
[5.910422 0.005729] [ 2.016024] musb-hdrc musb-hdrc.1.auto: new USB bus registered, assigned bus number 3
[5.918385 0.007963] [ 2.024932] hub 3-0:1.0: USB hub found
[5.925686 0.007301] [ 2.028854] hub 3-0:1.0: 1 port detected
[5.932156 0.006470] [ 2.034789] debugfs: Directory '1c22c00.codec' with parent 'V3s Audio Codec' already present!
[5.939199 0.007043] [ 2.044696] sun4i-codec 1c22c00.codec: Codec <-> 1c22c00.codec mapping ok
[5.946960 0.007761] [ 2.052949] sun6i-rtc 1c20400.rtc: setting system clock to 1970-01-01T00:03:54 UTC (234)
[5.955347 0.008387] [ 2.061313] cfg80211: Loading compiled-in X.509 certificates for regulatory database
[5.966902 0.011555] [ 2.072353] cfg80211: Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7'
[5.973186 0.006284] [ 2.079115] ALSA device list:
[5.976115 0.002929] [ 2.082090] #0: V3s Audio Codec
[5.979832 0.003717] [ 2.086003] platform regulatory.0: Direct firmware load for regulatory.db failed with error -2
[5.988427 0.008595] [ 2.094729] cfg80211: failed to load regulatory.db
[6.053798 0.065371] [ 2.159190] EXT4-fs (mmcblk0p2): recovery complete
[6.061055 0.007257] [ 2.166564] EXT4-fs (mmcblk0p2): mounted filesystem with ordered data mode. Opts: (null)
[6.068400 0.007345] [ 2.174800] VFS: Mounted root (ext4 filesystem) on device 179:2.
[6.076873 0.008473] [ 2.182446] devtmpfs: mounted
[6.080955 0.004082] [ 2.186597] Freeing unused kernel memory: 1024K
[6.085003 0.004048] [ 2.191350] Run /sbin/init as init process
[6.209525 0.124522] [ 2.314933] EXT4-fs (mmcblk0p2): re-mounted. Opts: (null)
[6.240813 0.031288] swapon: /swap: No such file or directory
[6.276642 0.035829] App Starting..\n
[6.277663 0.001021] App Started..\n
[6.288439 0.010776] Starting syslogd: OK
[6.314765 0.026326] Starting klogd: OK
[6.340877 0.026112] Running sysctl: [ 2.507443] usb 1-1: new high-speed USB device number 2 using ehci-platform
[6.423922 0.083045] OK
[6.464706 0.040784] Initializing random number generator: OK
[6.471580 0.006874] Saving random seed: [ 2.591726] random: dd: uninitialized urandom read (512 bytes read)
[6.494399 0.022819] OK
[6.512123 0.017724] Starting network: [ 2.710421] hub 1-1:1.0: USB hub found
[6.615434 0.103311] OK
[6.615706 0.000272] [ 2.721143] hub 1-1:1.0: 4 ports detected
[6.628035 0.012329] Starting dhcpcd...
[6.812423 0.184388] no interfaces have a carrier
[6.813979 0.001556] forked to background, child pid 151
[6.818023 0.004044] [ 2.923241] dwmac-sun8i 1c30000.ethernet eth0: PHY [0.1:01] driver [Generic PHY]
[6.831173 0.013150] [ 2.936566] dwmac-sun8i 1c30000.ethernet eth0: No Safety Features support found
[6.837901 0.006728] [ 2.944038] dwmac-sun8i 1c30000.ethernet eth0: No MAC Management Counters available
[6.845969 0.008068] [ 2.951741] dwmac-sun8i 1c30000.ethernet eth0: PTP not supported by HW
[6.852041 0.006072] [ 2.958294] dwmac-sun8i 1c30000.ethernet eth0: configuring for phy/mii link mode
[6.874717 0.022676] # [ 2.997126] random: dhcpcd: uninitialized urandom read (120 bytes read)
[6.961966 0.087249] [ 3.067377] usb 1-1.3: new full-speed USB device number 3 using ehci-platform
[7.120451 0.158485] [ 3.225783] input: Logitech USB Receiver as /devices/platform/soc/1c1a000.usb/usb1/1-1/1-1.3/1-1.3:1.0/0003:046D:C52B.0001/input/input2
[7.202687 0.082236] [ 3.308068] hid-generic 0003:046D:C52B.0001: input: USB HID v1.11 Keyboard [Logitech USB Receiver] on usb-1c1a000.usb-1.3/input0
[7.219956 0.017269] [ 3.325240] input: Logitech USB Receiver Mouse as /devices/platform/soc/1c1a000.usb/usb1/1-1/1-1.3/1-1.3:1.1/0003:046D:C52B.0002/input/input3
[7.234259 0.014303] [ 3.339344] input: Logitech USB Receiver Consumer Control as /devices/platform/soc/1c1a000.usb/usb1/1-1/1-1.3/1-1.3:1.1/0003:046D:C52B.0002/input/input4
[7.312511 0.078252] [ 3.417802] input: Logitech USB Receiver System Control as /devices/platform/soc/1c1a000.usb/usb1/1-1/1-1.3/1-1.3:1.1/0003:046D:C52B.0002/input/input5
[7.328529 0.016018] [ 3.431612] hid-generic 0003:046D:C52B.0002: input: USB HID v1.11 Mouse [Logitech USB Receiver] on usb-1c1a000.usb-1.3/input1
[7.342550 0.014021] [ 3.447248] hid-generic 0003:046D:C52B.0003: device has no listeners, quitting
[10.562064 3.219514] [ 6.667356] random: crng init donePower on reset : 0.1초 (가정치)
Boot ROM: 0.1초 (가정치)
SPL: 0.32초
BL2: 0.25초
U-boot: 3.1초 (key input delay 2초와 zImage+dtb 로딩 시간 포함)
Kernel: 2.5초
Init ~ app 실행: 약 4초 정도로 보이는데, 세부적인 측정이 잘 안되고 있다.
"App Started" 메시지는 나왔으나 실제 어플리케이션 시작은 init이 끝나는 2~3초 정도 뒤에나 보이는것 같다.
눈으로 느끼기에는 마지막 message인 "random: crng init done" 출력 직후에 어플이 시작되는것으로 보이므로 이 시점을 어플 구동 포인트로 잡으면 현재 부팅 시간은 10.76초 이다.
가장 쉬운 u-boot의 key input delay 2초를 제거하고 다시 측정해 보니 8.8초 정도로 2초 가까이 단축되었음을 확인 하였다.
[8.683682 3.370143] [ 6.787345] random: crng init done
우분투 미니멀 이미지로 16초였는데, buildroot 적용후 ~11초, 이제는 ~9초까지 줄었다. 그러나 아직 가야할 길이 멀다.
커널 옵션을 몇가지 수정해 보았는데, 0.1~0.2초 정도의 개선이 보인다. 간에 기별도 안온다. 장기전이 될 가능성 높다.
따라서 init 프로세스 시작, rootfs 마운트/리마운트, init 프로세스 마무리, 응용프로그램과 라이브라리 로딩과 시작 구간에서 어떤 일들 때문에 4초씩이나 소요되는지 알아보자. 이 부분에 개선할 것들이 많을것이다.
[3.944666 0.004001] [ 2.071917] Run /sbin/init as init process
[4.065213 0.120547] [ 2.191459] EXT4-fs (mmcblk0p2): re-mounted. Opts: (null)
[4.093417 0.028204] swapon: /swap: No such file or directory
[4.120783 0.027366] App Starting..
[4.121898 0.001115] App Started..
[4.129871 0.007973] Starting syslogd: OK
[4.152148 0.022277] Starting klogd: OK
[4.170755 0.018607] Running sysctl: OK
[4.260339 0.089584] Initializing random number generator: OK
[4.267296 0.006957] Saving random seed: [ 2.398047] usb 1-1: new high-speed USB device number 2 using ehci-platform
[4.288501 0.021205] [ 2.414770] random: dd: uninitialized urandom read (512 bytes read)
[4.296067 0.007566] OK
[4.310970 0.014903] Starting network: OK
[4.404851 0.093881] Starting dhcpcd...
[4.484399 0.079548] [ 2.610761] hub 1-1:1.0: USB hub found
[4.489085 0.004686] [ 2.615816] hub 1-1:1.0: 4 ports detected
[4.596192 0.107107] no interfaces have a carrier
[4.597764 0.001572] forked to background, child pid 145
[4.601859 0.004095] [ 2.727533] dwmac-sun8i 1c30000.ethernet eth0: PHY [0.1:01] driver [Generic PHY]
[4.615711 0.013852] [ 2.742073] dwmac-sun8i 1c30000.ethernet eth0: No Safety Features support found
[4.622230 0.006519] [ 2.749443] dwmac-sun8i 1c30000.ethernet eth0: No MAC Management Counters available
[4.630362 0.008132] [ 2.757126] dwmac-sun8i 1c30000.ethernet eth0: PTP not supported by HW
[4.636474 0.006112] [ 2.763690] dwmac-sun8i 1c30000.ethernet eth0: configuring for phy/mii link mode
[4.656696 0.020222] # [ 2.800994] random: dhcpcd: uninitialized urandom read (120 bytes read)
[6.762060 2.105364] [ 4.888327] dwmac-sun8i 1c30000.ethernet eth0: Link is Up - 100Mbps/Full - flow control rx/tx
[8.561730 1.799670] [ 6.688006] random: crng init done커널 메시지를 보면 커널 부팅 직후 "/sbin/ini"을 호출하는 부분이 있다.
그 시점부터 "App Started" 메시지가 나올때까지는 0.2초도 안된다.
그런데 어찌하여 4초에 가까운 시간 지연이 필요한 것인가!
분석할 수 있는 툴을 찾아보자. (CONFIG_BOOTCHARTD=y)
이부분을 해결하지 못하면 5초 미만 부팅은 물건너간다.
내일도 열심히 해보자.
'임베디드' 카테고리의 다른 글
| 쾌속 부팅 3차 도전 (0) | 2020.01.15 |
|---|---|
| 쾌속 부팅 2차 도전 (0) | 2020.01.14 |
| USB 무선랜 드라이버 구동 (0) | 2020.01.11 |
| SPI 포트 기능 테스트 (3) | 2020.01.11 |
| UART 포트 기능 테스트 (0) | 2020.01.10 |
