Linux系统启动时间优化

优化系统启动时间 前提（******重点）： （1） 首先要熟悉系统启动流程，以及每个流程中具体所做的事情 （2） 测量系统启动流程中每一步所花费的时间（这个时间需要与最终优化时间进行对比）

A. 分析有没有垃圾代码，重复代码，无用代码，有的话，裁掉--------减轻负担 a. 了解客户需求，分析客户系统中有什么功能，对应哪些模块，对应哪些代码，之后查看系统中包含哪些模块，有哪些没有用到的但是却已然被编译执行了 b. 针对于上一步，裁去客户不需要的功能代码或模块，减少编译时间以及代码执行时间，可以减少系统启动时间 c. 上一步结束之后，确保代码中没有不需要的代码块儿，下面开始精简代码。看有没有重复执行的代码，有的话，去除。 B. 第一步完成之后，此时以确保代码中没有任何无用代码。然后分析有用代码能否优化代码执行时间（怎么优化时间？）-----如:减少函数调用，一行代码能实现的不用多行实现

经过（******重点）： 从整体和部分把握如何优化，怎样优化以及最终优化了多长时间。 A. 测量一下目前客户系统的各个部分启动时间（记录到表格中） a. uboot从开始启动到启动完毕的总时间， b. kernel从开始启动到启动完毕的总时间， c. rootfs从开始挂载到挂载完毕的时间， d. /etc/init.d/rcS脚本从开始执行到结束所花费的时间， e. 客户应用程序从开始执行到正常运行（能出图，能语音通话，算法都已开启，等）所花费的时间 B. 按照以上a,b,c,d,e五步进行逐步分析优化，并统计优化前后的各部分启动时间（记录到表格中） C. B步完成之后，进行整体启动时间对比（记录到表格中） a. 从uboot启动开始到内核启动结束； b. 从uboot启动开始到文件系统挂载完毕； c. 从uboot启动到脚本执行结束（即应用程序执行前） d. 从uboot驱动到程序正常运行

结果（***次重点）： 优化前后对比，总共优化了多长时间，是否达到了要求？ 还有没有遗漏点？ 还能不能继续优化？

启动时间测量 分析开发板uboot启动时间，内核启动时间，文件系统挂载时间，脚本执行时间，客户程序启动到运行时间 （1） uboot启动时间测量 安装工具： sudo apt install python-pip

pip install pyserial

下载抓串口打印工具：https://github.com/tbird20d/grabserial 抓取30s所有串口打印：grabserial -v -d /dev/ttyUSB0 -e 30 -t 抓取30s所有串口打印（从内核打印开始重新计时）：grabserial -v -d /dev/ttyUSB0 -e 30 -t -m “Starting kernel.*”

例： T20X demo板启动打印如下： sc@sc:/mnt/hgfs/VMware-shared/grabserial-master$ sudo grabserial -v -d /dev/ttyUSB0 -e 30 -t Opening serial port /dev/ttyUSB0 115200:8N1:xonxoff=0:rtscts=0 Program set to end in 30 seconds Printing timing information for each line Use Control-C to stop…

root [0.000001 0.000001] root [0.023127 0.023126] Jan 1 00:07:21 login[59]: root login on ‘console’ [0.025601 0.002474] [root@Ingenic-uc1_1:~]# reb reb[root@Ingenic-uc1_1:~]# reboot [3.083853 3.058252] [root@Ingenic-uc1_1:~]# umount: tmpfs busy - remounted read-only [3.088566 0.004713] The system is going down NOW! [3.090272 0.001706] Sent SIGTERM to all processes [4.071921 0.981649] Sent SIGKILL to all processes [4.072971 0.001050] Requesting system reboot[ 446.974607] Restarting system. [5.085524 1.012553] [ 446.977767] Restarting after 4 ms [5.196123 0.110599] [5.196187 0.000064] U-Boot SPL 2013.07-00001-gfd0d8ce-dirty (Sep 23 2019 - 15:12:37) ------bootrom启动开始（spluboot，用来启动uboot） [5.244824 0.048637] pll_init:365 [5.245156 0.000332] l2cache_clk = 337500000 [5.245817 0.000661] pll_cfg.pdiv = 8, pll_cfg.h2div = 4, pll_cfg.h0div = 4, pll_cfg.cdiv = 1, pll_cfg.l2div = 3 [5.251223 0.005406] nf=36 nr = 1 od0 = 1 od1 = 1 [5.253393 0.002170] cppcr is 02404900 [5.254742 0.001349] CPM_CPAPCR 0470890d [5.256169 0.001427] nf=38 nr = 1 od0 = 1 od1 = 1 [5.258236 0.002067] cppcr is 02604900 [5.261038 0.002802] CPM_CPMPCR 04b0890d [5.263143 0.002105] nf=50 nr = 1 od0 = 1 od1 = 1 [5.274870 0.011727] cppcr is 03204900 [5.275408 0.000538] CPM_CPVPCR 0320490d [5.276363 0.000955] cppcr 0x9a794410 [5.277149 0.000786] apll_freq 860160000 [5.277880 0.000731] mpll_freq 900000000 [5.281783 0.003903] vpll_freq = 1200000000 [5.282443 0.000660] ddr sel mpll, cpu sel apll [5.283266 0.000823] ddrfreq 450000000 [5.283838 0.000572] cclk 860160000 [5.284297 0.000459] l2clk 286720000 [5.285058 0.000761] h0clk 225000000 [5.285860 0.000802] h2clk 225000000 [5.290474 0.004614] pclk 112500000 [5.292380 0.001906] DDRC_DLP:0000f003 [5.312872 0.020492] [5.313056 0.000184] [5.313159 0.000103] U-Boot 2013.07-00001-gfd0d8ce-dirty (Sep 23 2019 - 15:12:37) ------bootrom结束，uboot开始 [5.369608 0.056449] [5.369664 0.000056] Board: ISVP (Ingenic XBurst T20 SoC) [5.370647 0.000983] DRAM: 128 MiB [5.370979 0.000332] Top of RAM usable for U-Boot at: 84000000 [5.371922 0.000943] Reserving 441k for U-Boot at: 83f90000 [5.372782 0.000860] Reserving 32784k for malloc() at: 81f8c000 [5.373742 0.000960] Reserving 32 Bytes for Board Info at: 81f8bfe0 [5.375579 0.001837] Reserving 124 Bytes for Global Data at: 81f8bf64 [5.379299 0.003720] Reserving 128k for boot params() at: 81f6bf64 [5.382611 0.003312] Stack Pointer at: 81f6bf48 [5.387050 0.004439] Now running in RAM - U-Boot at: 83f90000 [5.431788 0.044738] MMC: msc: 0 [5.432205 0.000417] the manufacturer c2 [5.462052 0.029847] SF: Detected MX25L128E [5.464575 0.002523] [5.464727 0.000152] *** Warning - bad CRC, using default environment [5.468751 0.004024] [5.468860 0.000109] In: serial [5.470017 0.001157] Out: serial [5.471128 0.001111] Err: serial [5.472088 0.000960] Net: Jz4775-9161 [5.605781 0.133693] Hit any key to stop autoboot: 0 [6.622396 1.016615] the manufacturer c2 ------bootdelay改成0缩短1秒（目前默认为1s） [6.623129 0.000733] SF: Detected MX25L128E [6.624010 0.000881] [6.624049 0.000039] —>probe spend 5 ms [7.070763 0.446714] SF: 2621440 bytes @ 0x40000 Read: OK ------减少sf read的大小（设为0x1A9000，默认为0x280000）之后，read花费了285 ms，缩短138ms时间 [7.071680 0.000917] —>read spend 423 ms [7.072150 0.000470] ## Booting kernel from Legacy Image at 80600000 … [7.073225 0.001075] Image Name: Linux-3.10.14-00001-ga691061-dir [7.074238 0.001013] Image Type: MIPS Linux Kernel Image (lzma compressed) [7.077803 0.003565] Data Size: 1707937 Bytes = 1.6 MiB [7.080631 0.002828] Load Address: 80010000 [7.082392 0.001761] Entry Point: 803b2730 [7.084400 0.002008] Verifying Checksum … OK [7.090625 0.006225] Uncompressing Kernel Image … OK [7.773576 0.682951] [7.773617 0.000041] Starting kernel … ------uboot结束，内核开始 [7.818445 0.044828] [7.818491 0.000046] [ 0.000000] Initializing cgroup subsys cpu [7.820524 0.002033] [ 0.000000] Initializing cgroup subsys cpuacct [7.822716 0.002192] [ 0.000000] Linux version 3.10.14-00001-ga691061-dirty (chsun@4) (gcc version 4.7.2 (Ingenic r2.3.3 2016.12) ) #6 PREEMPT Thu Aug 22 16:31:41 CST 2019 [7.837108 0.014392] [ 0.000000] bootconsole [early0] enabled [7.840300 0.003192] [ 0.000000] CPU0 RESET ERROR PC:801C7524 [7.843422 0.003122] [ 0.000000] [<801c7524>] __delay+0x4/0x10 [7.846576 0.003154] [ 0.000000] CPU0 revision is: 00d00101 (Ingenic Xburst) [7.856991 0.010415] [ 0.000000] FPU revision is: 00b70000 [7.863921 0.006930] [ 0.000000] CCLK:860MHz L2CLK:430Mhz H0CLK:180MHz H2CLK:180Mhz PCLK:90Mhz [7.870445 0.006524] [ 0.000000] Determined physical RAM map: [7.874823 0.004378] [ 0.000000] memory: 004d4000 @ 00010000 (usable) [7.879056 0.004233] [ 0.000000] memory: 0003c000 @ 004e4000 (usable after init) [7.883979 0.004923] [ 0.000000] User-defined physical RAM map: [7.887305 0.003326] [ 0.000000] memory: 06000000 @ 00000000 (usable) [7.898483 0.011178] [ 0.000000] Zone ranges: [7.899352 0.000869] [ 0.000000] Normal [mem 0x00000000-0x05ffffff] [7.903287 0.003935] [ 0.000000] Movable zone start for each node [7.904635 0.001348] [ 0.000000] Early memory node ranges [7.913547 0.008912] [ 0.000000] node 0: [mem 0x00000000-0x05ffffff] [7.915220 0.001673] [ 0.000000] Primary instruction cache 32kB, 8-way, VIPT, linesize 32 bytes. [7.921186 0.005966] [ 0.000000] Primary data cache 32kB, 8-way, VIPT, no aliases, linesize 32 bytes [7.927532 0.006346] [ 0.000000] pls check processor_id[0x00d00101],sc_jz not support! [7.932587 0.005055] [ 0.000000] MIPS secondary cache 128kB, 8-way, linesize 32 bytes. [7.937368 0.004781] [ 0.000000] Built 1 zonelists in Zone order, mobility grouping off. Total pages: 24384 [7.951204 0.013836] [ 0.000000] Kernel command line: console=ttyS1,115200n8 mem=96M@0x0 ispmem=8M@0x6000000 rmem=24M@0x6800000 init=/linuxrc rootfstype=squashfs root=/dev/mtdblock2 rw mtdparts=jz_sfc:256k(boot),2560k(kernel),2048k(root),-(appfs) [7.972102 0.020898] [ 0.000000] PID hash table entries: 512 (order: -1, 2048 bytes) [7.977375 0.005273] [ 0.000000] Dentry cache hash table entries: 16384 (order: 4, 65536 bytes) [7.982887 0.005512] [ 0.000000] Inode-cache hash table entries: 8192 (order: 3, 32768 bytes) [7.995363 0.012476] [ 0.000000] Memory: 91492k/98304k available (3756k kernel code, 6812k reserved, 1185k data, 240k init, 0k highmem) [8.009650 0.014287] [ 0.000000] SLUB: HWalign=32, Order=0-3, MinObjects=0, CPUs=1, Nodes=1 [8.013578 0.003928] [ 0.000000] Preemptible hierarchical RCU implementation. [8.017699 0.004121] [ 0.000000] NR_IRQS:418 [8.019653 0.001954] [ 0.000000] clockevents_config_and_register success. [8.024830 0.005177] [ 0.000024] Calibrating delay loop… 858.52 BogoMIPS (lpj=4292608) [8.121713 0.096883] [ 0.087751] pid_max: default: 32768 minimum: 301 [8.122964 0.001251] [ 0.092738] Mount-cache hash table entries: 512 [8.124077 0.001113] [ 0.097850] Initializing cgroup subsys debug [8.125141 0.001064] [ 0.102112] Initializing cgroup subsys freezer [8.126238 0.001097] [ 0.109136] regulator-dummy: no parameters [8.129906 0.003668] [ 0.113384] NET: Registered protocol family 16 [8.171134 0.041228] [ 0.134098] bio: create slab at 0 [8.172214 0.001080] [ 0.140489] jz-dma jz-dma: JZ SoC DMA initialized [8.173365 0.001151] [ 0.145620] usbcore: registered new interface driver usbfs [8.174700 0.001335] [ 0.151152] usbcore: registered new interface driver hub [8.182694 0.007994] [ 0.156664] usbcore: registered new device driver usb [8.187330 0.004636] [ 0.161887] i2c-gpio i2c-gpio.1: using pins 57 (SDA) and 58 (SCL) [8.192157 0.004827] [ 0.168145] (null): set:224 hold:225 dev=90000000 h=450 l=450 [8.203168 0.011011] [ 0.174168] media: Linux media interface: v0.10 [8.209047 0.005879] [ 0.178745] Linux video capture interface: v2.00 [8.211823 0.002776] [ 0.185514] Switching to clocksource jz_clocksource [8.216712 0.004889] [ 0.191070] jz-dwc2 jz-dwc2: cgu clk gate get error [8.218329 0.001617] [ 0.196059] cfg80211: Calling CRDA to update world regulatory domain [8.227152 0.008823] [ 0.202509] jz-dwc2 jz-dwc2: regulator vbus get error [8.231731 0.004579] [ 0.207565] DWC IN OTG MODE [8.354646 0.122915] [ 0.360852] sft id ===============off [8.375973 0.021327] [ 0.365457] dwc2 dwc2: Keep PHY ON [8.376954 0.000981] [ 0.368828] dwc2 dwc2: Using Buffer DMA mode [8.567374 0.190420] [ 0.573017] dwc2 dwc2: Core Release: 3.00a [8.613266 0.045892] [ 0.577129] dwc2 dwc2: DesignWare USB2.0 High-Speed Host Controller [8.614948 0.001682] [ 0.583484] dwc2 dwc2: new USB bus registered, assigned bus number 1 [8.616509 0.001561] [ 0.590915] hub 1-0:1.0: USB hub found [8.617825 0.001316] [ 0.594657] hub 1-0:1.0: 1 port detected [8.618740 0.000915] [ 0.598744] dwc2 dwc2: DWC2 Host Initialized [8.626616 0.007876] [ 0.603294] NET: Registered protocol family 2 [8.631220 0.004604] [ 0.608241] TCP established hash table entries: 1024 (order: 1, 8192 bytes) [8.637554 0.006334] [ 0.615320] TCP bind hash table entries: 1024 (order: 0, 4096 bytes) [8.642872 0.005318] [ 0.621726] TCP: Hash tables configured (established 1024 bind 1024) [8.663216 0.020344] [ 0.628195] TCP: reno registered [8.664888 0.001672] [ 0.631437] UDP hash table entries: 256 (order: 0, 4096 bytes) [8.667174 0.002286] [ 0.637335] UDP-Lite hash table entries: 256 (order: 0, 4096 bytes) [8.671713 0.004539] [ 0.643987] NET: Registered protocol family 1 [8.678054 0.006341] [ 0.648668] RPC: Registered named UNIX socket transport module. [8.683089 0.005035] [ 0.654671] RPC: Registered udp transport module. [8.686877 0.003788] [ 0.659367] RPC: Registered tcp transport module. [8.690417 0.003540] [ 0.664150] RPC: Registered tcp NFSv4.1 backchannel transport module. [8.711065 0.020648] [ 0.671126] freq_udelay_jiffys[0].max_num = 10 [8.712560 0.001495] [ 0.675554] cpufreq udelay loops_per_jiffy [8.716192 0.003632] [ 0.679983] dwc2 dwc2: ID PIN CHANGED! [8.720868 0.004676] [ 0.683837] init DWC as A_HOST [8.721878 0.001010] [ 0.686885] 12000 59885 59885 [8.722915 0.001037] [ 0.690123] 24000 119771 119771 [8.723986 0.001071] [ 0.693683] 60000 299428 299428 [8.730462 0.006476] [ 0.697051] 120000 598857 598857 [8.733177 0.002715] [ 0.700693] 200000 998095 998095 [8.736209 0.003032] [ 0.704149] 300000 1497142 1497142 [8.739678 0.003469] [ 0.707857] 600000 2994285 2994285 [8.763309 0.023631] [ 0.711588] 792000 3952457 3952457 [8.767260 0.003951] [ 0.715273] 1008000 5030400 5030400 [8.768972 0.001712] [ 0.719069] 1200000 5988571 5988571 [8.775830 0.006858] [ 0.728416] squashfs: version 4.0 (2009/01/31) Phillip Lougher [8.777769 0.001939] [ 0.735355] jffs2: version 2.2. 2001-2006 Red Hat, Inc. [8.779598 0.001829] [ 0.741339] msgmni has been set to 178 [8.780763 0.001165] [ 0.746495] io scheduler noop registered [8.787471 0.006708] [ 0.750547] io scheduler cfq registered (default) [8.791623 0.004152] [ 0.757004] jz-uart.1: ttyS1 at MMIO 0x10031000 (irq = 58) is a uart1 [8.796953 0.005330] [ 0.765300] console [ttyS1] enabled, bootconsole disabled [8.819793 0.022840] [ 0.765300] console [ttyS1] enabled, bootconsole disabled [8.828547 0.008754] [ 0.780634] brd: module loaded [8.829529 0.000982] [ 0.785875] loop: module loaded [8.830514 0.000985] [ 0.789755] zram: Created 2 device(s) … [8.831793 0.001279] [ 0.794227] logger: created 256K log ‘log_main’ [8.833621 0.001828] [ 0.799553] jz SADC driver registeres over! [8.840309 0.006688] [ 0.804990] jz TCU driver register completed [8.844653 0.004344] [ 0.809829] the id code = c22018, the flash name is MX25L12835F [8.849672 0.005019] [ 0.816006] JZ SFC Controller for SFC channel 0 driver register [8.859191 0.009519] [ 0.822168] 4 cmdlinepart partitions found on MTD device jz_sfc [8.871720 0.012529] [ 0.828276] Creating 4 MTD partitions on “jz_sfc”: [8.875236 0.003516] [ 0.833237] 0x000000000000-0x000000040000 : “boot” [8.876783 0.001547] [ 0.838762] 0x000000040000-0x0000002c0000 : “kernel” [8.880631 0.003848] [ 0.844469] 0x0000002c0000-0x0000004c0000 : “root” [8.884920 0.004289] [ 0.849933] 0x0000004c0000-0x000001000000 : “appfs” [8.886790 0.001870] [ 0.855577] SPI NOR MTD LOAD OK [8.893777 0.006987] [ 0.858979] dma dma0chan22: Channel 22 have been requested.(phy id 9,type 0x16 desc a41f3000) [8.903762 0.009985] [ 0.867859] dma dma0chan23: Channel 23 have been requested.(phy id 8,type 0x16 desc a41f6000) [8.914940 0.011178] [ 0.876913] jz-ssi jz-ssi.0: master is unqueued, this is deprecated [8.925161 0.010221] [ 0.883442] JZ SSI Controller for SPI channel 0 driver register [8.931217 0.006056] [ 0.889615] tun: Universal TUN/TAP device driver, 1.6 [8.932802 0.001585] [ 0.894847] tun: © 1999-2004 Max Krasnyansky maxk@qualcomm.com [8.936741 0.003939] [ 0.901347] Bus Mode Reg after reset: 0x00020101, cnt=0 [8.944281 0.007540] [ 0.910680] libphy: jz_mii_bus: probed [8.947348 0.003067] [ 0.914663] =>gmacdev = 0x841f8a00< [8.962354 0.015006] [ 0.920235] =========>gmacdev->MacBase = 0xb34b0000 DmaBase = 0xb34b1000 [8.974947 0.012593] [ 0.927211] Bus Mode Reg after reset: 0x00020101, cnt=0 [8.976617 0.001670] [ 0.934217] jz_mac jz_mac.0: JZ on-chip Ethernet MAC driver, Version 1.0 [8.981030 0.004413] [ 0.941378] usbcore: registered new interface driver zd1201 [8.986576 0.005546] [ 0.947451] jzmmc_v1.2 jzmmc_v1.2.0: vmmc regulator missing [9.042835 0.056259] [ 0.991469] jzmmc_v1.2 jzmmc_v1.2.0: register success! [9.047412 0.004577] [ 0.997123] TCP: cubic registered [9.053456 0.006044] [ 1.000597] NET: Registered protocol family 17 [9.057443 0.003987] [ 1.006194] input: gpio-keys as /devices/platform/gpio-keys/input/input0 [9.064070 0.006627] [ 1.013395] drivers/rtc/hctosys.c: unable to open rtc device (rtc0) [9.069704 0.005634] [ 1.024830] VFS: Mounted root (squashfs filesystem) readonly on device 31:2. [9.082989 0.013285] [ 1.032654] Freeing unused kernel memory: 240K (804e4000 - 80520000) ------内核启动结束，init进程开始启动 [9.665218 0.582229] mdev is ok… [9.804975 0.139757] [ 1.794098] dwc2 dwc2: ++OTG Interrupt: A-Device Timeout Change++ [11.337271 1.532296] [ 3.344926] Bus Mode Reg after reset: 0x00020101, cnt=0 [11.433257 0.095986] [11.433341 0.000084] Ingenic-uc1_1 login: [ 7.930595] libphy: 0:00 - Link is Up - 100/Full ------结束

从上述打印可以计算出uboot启动时间=7.818445-5.313159=2.505286秒 优化时间： （1） bootdelay=1改成bootdelay=0（减少1s）,如果还想进入uboot，定义CONFIG_ZERO_BOOTDELAY_CHECK（bootdelay只要不是负数，uboot启动阶段点击任意一个键即可进入uboot） （2） sf read大小0x280000改成0x1A9000（减少138ms） （3） 去除以太网初始化（减少0.151802秒）（注意：uboot中去除这个，内核起来之后eth0也不能用了） （4） Uboot中去除ping，coninfo，echo，loadb，loads，md mm nm mw cp cmp crc，Misc（定时），source，gettime（uboot启动时间为2.453366，相比于2.505286缩短了0.05192秒） （5） 更换image各种压缩格式（gzip，bzip2，lzma（默认格式），lzo） Lzma内核（1668KB）解压缩时间=7.773576-7.090625=0.682951秒 sf read花费423ms Gzip内核（2286KB）解压缩时间=4.257105-4.037348=0.219757秒 sf read花费422ms Bzip2内核（2109KB）解压缩时间= 6.194922- 4.042882=2.15204秒 sf read花费423ms Lzo内核（2535KB）解压缩时间= 4.203953- 4.068349= 0.135604秒 sf read花费422ms 由上面数据可以看出，LZO解压缩时间最快，其次是Gzip，LZMA，BZIP2。 如下排序（解压缩耗时）： Lzo<Gzip< LZMA< BZIP2

（2） 内核启动时间测量 从上述打印可以计算出kernel启动时间=9.082989-7.818491 =1.264498秒 优化时间： （1） 内核添加环境变量lpj=4292608（减少0.08851秒）， （2） 内核添加环境变量quiet（减少约0.638608秒） （3） 去除以太网驱动（大约可减少40ms）------ 目前先不测试，需要网络功能 （4） 客户使用机器里面是否真的需要/proc目录，sysfs文件系统？（已跟客户确认，除了NFS调试阶段需要，release不需要之外，其他的proc，sysfs，tmpfs，JFFS2，squashfs都需要） （5） 内核默认支持很多文件系统，这个也可以裁掉不需要的（同4） （6） RTC，ADC，定时器（TCU），/sys/class/gpio都使用，鼠标键盘不使用（可裁掉）

（3） 根文件系统挂载时间测量 时间比较短，先忽略 从上述打印可以计算出文件系统挂载时间=9.069704-9.064070=0.005634秒

（4） Init进程执行到登录shell 从上述打印可以计算出Init进程执行到登录shell时间=11.433341-9.082989=2.350352秒 优化时间： （1） 裁剪busybox（即init进程） （2）

（5） 脚本执行时间测量（时间包含在Init进程启动中） 脚本主要用来设置系统配置信息（例：环境变量PATH），启动系统服务（守护进程），创建目录（例：proc目录），设置主机名，启动用户脚本，启动登录shell 从上述打印可以计算出脚本执行时间=11.433341-9.665218=1.768123秒 优化时间： （1） 去除telnet进程（未测试）—耗时0.000463秒 （2） 去除挂载/dev/mtdblock3到/system目录（未测试）-----经测试发现此处挂载文件系统耗时最长，消耗了1.670044秒左右的时间 （3） 去除格式化/system目录操作（未测试）—耗时很长，内部包含了第二步操作

（6） 客户程序启动->运行时间测量 Demo板中没有用户程序。。。这一项直接在用户机器上面测试

（7） Bootrom启动时间 从上述打印可以计算出Bootrom启动时间=5.313056-5.196187=0.116869秒

（8） 从SPL uboot开始到login shell出现时间 从上述打印可以计算出SPL uboot开始到login shell时间=11.433341-5.196187=6.237154秒

客户板子启动时间优化 目前客户板子启动时间为： sudo grabserial -v -d /dev/ttyUSB0 -e 60 -t Opening serial port /dev/ttyUSB0 115200:8N1:xonxoff=0:rtscts=0 Program set to end in 60 seconds Printing timing information for each line Use Control-C to stop…

reb [0.000000 0.000000] reb[root@Ling:~]# reboot [0.068467 0.068467] [root@Ling:~]# [2.250282 2.181815] [ 0.000000] Luka Baby [2.251319 0.001037] [ 0.000000] Firmware: 0.0.1 [4.666592 2.415273] [ 0.000000] Kernel: 0.0.1 [4.667817 0.001225] [ 0.000000] Designed with love by Ling Technology [9.710901 5.043084] [9.710990 0.000089] Ling login:

由上述打印可以看出，客户板子目前启动时间=9.710990-2.250282=7.460708秒

客户系统起来之后只有四行打印，然后直接到登录shell，其中间的打印信息已被去除，这无法查看具体每一个步骤的启动时间，需要打开所有串口打印，就如我们的demo板一样。重烧固件，打开所有打印信息。

重新烧录固件后，所有打印信息都放开，如下： sudo grabserial -v -d /dev/ttyUSB0 -e 60 -t [sudo] sc 的密码： Opening serial port /dev/ttyUSB0 115200:8N1:xonxoff=0:rtscts=0 Program set to end in 60 seconds Printing timing information for each line Use Control-C to stop…

[0.000001 0.000001] [ 189.976074] RTL871X: nolinked power save enter reb [2.014713 2.014712] reb[root@Ling:~]# reboot [2.067506 0.052793] [root@Ling:~]# umount: can’t remount /dev/mmcblk0p9 read-only[ 192.063953] EXT4-fs (mmcblk0p4): re-mounted. Opts: (null) [2.099196 0.031690] [2.118003 0.018807] umount: /dev/mmcblk0p4 busy - remounted read-only [2.127359 0.009356] umount: can’t remount /dev/mmcblk0p3 read-only [2.134924 0.007565] umount: sysfs busy - remounted read-only [2.149471 0.014547] umount: tmpfs busy - remounted read-only [2.150380 0.000909] umount: tmpfs busy - remounted read-only [2.153227 0.002847] umonly [2.153856 0.000629] [ 192.120407] RTL871X: ERhandler: down SdioXmitBufSema fail! [2.158307 0.004451] The system is going down NOW! [2.160457 0.002150] Sent SIGTERM to all processes [2.167521 0.007064] [ 192.133581] RTL871X: rtw_cmd_thread(wlan0) _rtw_down_sema(&pcmdpriv->cmd_queue_sema) return _FAIL, break [2.201816 0.034295] [ 192.148955]Sent SIGKILL to all processes [3.219640 1.017824] Requesting system reboot [4.216612 0.996972] [ 194.193290] codec_codec_ctl: set CODEC_TURN_OFF… [4.220022 0.003410] [ 194.198309] codec_codec_ctl: set CODEC_SHUTDOWN… [4.226520 0.006498] [ 194.203326] mmc0: card aaaa removed [4.250358 0.023838] [ 194.226701] Restarting system. [4.252980 0.002622] [ 194.229872] Restarting after 4 ms [4.368878 0.115898] [4.368941 0.000063] [ 0.000000] Luka Baby [4.369484 0.000543] [ 0.000000] Firmware: 0.0.1 [4.372267 0.002783] [4.372294 0.000027] U-Boot SPL 2013.07-g233baa7-dirty (Oct 24 2019 - 20:53:27) [4.387493 0.015199] pll_init:365 [4.387894 0.000401] l2cache_clk = 375000000 [4.388678 0.000784] pll_cfg.pdiv = 8, pll_cfg.h2div = 4, pll_cfg.h0div = 4, pll_cfg.cdiv = 1, pll_cfg.l2div = 3 [4.418443 0.029765] nf=36 nr = 1 od0 = 1 od1 = 1 [4.419063 0.000620] cppcr is 02404900 [4.419466 0.000403] CPM_CPAPCR 0470890d [4.428978 0.009512] nf=42 nr = 1 od0 = 1 o0320490d [4.429791 0.000813] cppcr 0x9a794410 [4.430156 0.000365] ap00000000 [4.450178 0.020022] ddr sel mpll, cpu sel apll [4.450780 0.000602] ddrfreq 500000000 [4.451164 0.000384] cclk [4.505315 0.054151] [4.505350 0.000035] U-Boot 2013.07-g233baa7-dirty (Oct 24 2019 - 20:53:27) [4.506855 0.001505] [4.506884 0.000029] Board: ISVP (Ingenic XBurst T20 SoC) [4.508087 0.001203] DRAM: 128 MiB [4.515373 0.007286] Top of RAM u 436k for U-Boot at: 83f90000 [4.516744 0.001371] Reserving 32784k for malloc() at: 81f8c000 [4.518047 0.001303] Reserving 32 Bytes for Board Info at: 81f8bfe0 [4.519428 0.001381] Reserving 124 Bytes for Global Data at: 81f8bf64 [4.541805 0.022377] Reserving 128k for boot params() at: 81f6bf64 [4.550043 0.008238] Stack Pointer at: 81f6bf48 [4.551203 0.001160] Now runnMMC: msc: 0 [4.613330 0.062127] the manufacturer c2 [4.615992 0.002662] SF: Detected MX25L128E [4.617787 0.001795] [4.620887 0.003100] *** Warning - bad CRC, using default environment [4.626704 0.005817] [4.626812 0.000108] In: serial [4.628567 0.001755] Out: serial [4.629638 0.001071] Err: serial [4.631253 0.001615] Net: Jz4775-9161 [4.782385 0.151132] Hit any key to stop autoboot: 0 [5.786299 1.003914] the manufacturer c2 [5.786868 0.000569] SF: Detected MX25L128E [5.790133 0.003265] [5.790198 0.000065] —>probe spend 4 ms [6.170554 0.380356] SF: 2621440 bytes @ 0x40000 Read: OK [6.173515 0.002961] —>read spend 381 ms [6.174041 0.000526] ## Booting kernel from Legacy Image at 80600000 … [6.191723 0.017682] Image Name: Linux-3.10.14 [6.192845 0.001122] Image Type: MIPS Linux Kernel Image (lzma compressed) [6.194883 0.002038] Data Size: 1785645 Bytes = 1.7 MiB [6.196341 0.001458] Load oint: 803e50e0 [6.197253 0.000912] Verifying Checksum … OK [6.220767 0.023514] Uncompressing Kernel Image … OK

[6.943339 0.722572] [6.943374 0.000035] Starting kernel … [6.943918 0.000544] [6.943947 0.000029] [ 0.000000] Initializing cgroup subsys cpu [6.949629 0.005682] [ 0.000000] Initializing cgroup subsys cpuacct [6.957364 0.007735] [ 0.000000] Kernel: 0.0.1 [6.961732 0.004368] [ 0.000000] Designed with love by Ling Technology [6.966813 0.005081] [ 0.000000] Linux version 3.10.14 (yinjl@YINJL) (gcc version 4.7.2 (Ingenic r2.3.3 2016.12) ) #2 PREEMPT Thu Oct 24 21:21:45 CST 2019 [6.986804 0.019991] [ 0.000000] bootconsole [early0] enabled [6.988324 0.001520] [ 0.000000] CPU0 RESET ERROR PC:802196E4 [6.991321 0.002997] [ 0.000000] [<802196e4>] __delay+0x4/0x10 [6.999224 0.007903] [ 0.000000] CPU0 revision is: 00d00101 (Ingenic Xburst) [7.004868 0.005644] [ 0.000000] FPU revision is: 00b70000 [7.009351 0.004483] [ 0.000000] CCLK:860MHz L2CLK:430Mhz H0CLK:200MHz H2CLK:200Mhz PCLK:100Mhz [7.015531 0.006180] [ 0.000000] Determined physical RAM map: [7.018846 0.003315] [ 0.000000] memory: 0050b000 @ 00010000 (usable) [7.065643 0.046797] [ 0.000000] memory: 00035000 @ 0051b000 (usable after init) [7.067532 0.001889] [ 0.000000] User-defined physical RAM map: [7.068876 0.001344] [ 0.000000] memory: 07200000 @ 00000000 (usable) [7.070518 0.001642] [ 0.000000] Zone ranges: [7.071305 0.000787] [ 0.000000] Normal [mem 0x00pls check processor_id[0x00d00101],sc_jz not support! [7.073874 0.002569] [ 0.000000] MIPS secondary cache 128kB, 8-way, linesize 32 bytes. [7.080563 0.006689] [ 0.000000] Built 1 zonelists in Zone order, mobility grouping off. Total pages: 28956 [7.086308 0.005745] [ 0.000000] Kernel command line: console=ttyS1,115200n8 mem=114M@0x0 ispmem=4M@0x7200000 rmem=10M@0x7600000 init=/linuxrc rootfstype=squashfs root=/dev/mtdblock2 rw mtdparts=jz_sfc:256k(boot),2560k(kernel),4096k(root),9344k(appfs),-(attr) rootdelay=1 [7.111154 0.024846] [ 0.000000] PID hash table entries: 512 (order: -1, 2048 bytes) [7.117055 0.005901] [ 0.000000] Dentry cache hash table entries: 16384 (order: 4, 65536 bytes) [7.131729 0.014674] [ 0.000000] Inode-cache hash table entries: 8192 (order: 3, 32768 bytes) [7.136258 0.004529] [ 0.000000] Memory: 109736k/116736k available (3960k kernel code, 7000k reserved, 1199k data, 212k init, 0k highmem) [7.145936 0.009678] [ 0.000000] SLUB: HWalign=32, Order=0-3, MinObjects=0, CPUs=1, Nodes=1 [7.153270 0.007334] [ 0.000000] Preemptible hierarchical RCU implementation. [7.162079 0.008809] [ 0.000000] NR_IRQS:418 [7.164935 0.002856] [ 0.000000] clockevents_config_and_register success. [7.171223 0.006288] [ 0.000024] Calibrating delay loop… 858.52 BogoMIPS (lpj=4292608) [7.255810 0.084587] [ 0.087752] pid_max: default: 32768 minimum: 301 [7.262188 0.006378] [ 0.092737] Mount-cache hash table entries: 512 [7.269956 0.007768] [ 0.097831] Initializing cgroup subsys debug [7.274913 0.004957] [ 0.102092] Initializing cgroup subsys freezer [7.279070 0.004157] [ 0.109098] regulator-dummy: no parameters [7.292815 0.013745] [ 0.113340] NET: Registered protocol family 16 [7.304571 0.011756] [ 0.133977] bio: create slab at 0 [7.310359 0.005788] [ 0.140366] jz-dma jz-dma: JZ SoC DMA initialized [7.316752 0.006393] [ 0.145606] i2c-gpio i2c-gpio.1: using pins 57 (SDA) and 58 (SCL) [7.324205 0.007453] [ 0.151792] (null): set:249 hold:250 dev=100000000 h=500 l=500 [7.329499 0.005294] [ 0.157928] media: Linux media interface: v0.10 [7.339489 0.009990] [ 0.162489] Linux video capture interface: v2.00 [7.342809 0.003320] [ 0.169264] Switching to clocksource jz_clocksource [7.344870 0.002061] [ 0.174817] jz-dwc2 jz-dwc2: cgu clk gate get error [7.349763 0.004893] [ 0.179804] cfg80211: Calling CRDA to update world regulatory domain [7.360456 0.010693] [ 0.186262] DWC IN DEVICE ONLY MODE [7.363650 0.003194] [ 0.190293] sft id ==================== 1 [7.514254 0.150604] [ 0.344252] dwc2 dwc2: Dynamic Power Control [7.517411 0.003157] [ 0.348506] dwc2 dwc2: Using Buffer DMA mode [7.722599 0.205188] [ 0.552682] dwc2 dwc2: Core Release: 3.00a [7.725994 0.003395] [ 0.557042] Suspend otg by shutdown dwc cotroller and phy [7.736613 0.010619] [ 0.562439] DIS PHY [7.739293 0.002680] [ 0.564767] Resume otg by reinit dwc controller and phy [7.746858 0.007565] [ 0.570004] DWC IN DEVICE ONLY MODE [7.751566 0.004708] [ 0.574182] dwc2 dwc2: enter dwc2_gadget_plug_change:2589: plugin = 1 pullup_on = 0 suspend = 0 [7.763913 0.012347] [ 0.583212] NET: Registered protocol family 2 [7.769612 0.005699] [ 0.588182] TCP established hash table entries: 1024 (order: 1, 8192 bytes) [7.776222 0.006610] [ 0.595258] TCP bind hash table entries: 1024 (order: 0, 4096 bytes) [7.785538 0.009316] [ 0.6 0.608148] TCP: reno registered [7.789013 0.003475] [ 0.611346] UDP hash table entries: 256 (order: 0, 4096 bytes) [7.794087 0.005074] [ 0.617303] UDP-Lite hash table entries: 256 (order: 0, 4096 bytes) [7.799733 0.005646] [ 0.623902] NET: Registered protocol family 1 [7.803258 0.003525] [ 0.628622] RPC: Registered named UNIX socket transport module. [7.814461 0.011203] [ 0.634628] RPC: Registered udp transport module. [7.818787 0.004326] [ 0.639323] RPC: Registered tcp transport module. [7.820239 0.001452] [ 0.644091] RPC: Registered tcp NFSv4.1 backchannel transport module. [7.826019 0.005780] [ 0.651078] freq_udelay_jiffys[0].max_num = 10 [7.829040 0.003021] [ 0.655547] cpufreq udelay loops_per_jiffy [7.838363 0.009323] [ 0.659922] 12000 59885 59885 [7.842004 0.003641] [ 0.663188] 24000 119771 119771 [7.844895 0.002891] [ 0.666645] 60000 299428 299428 [7.847857 0.002962] [ 0.670075] 120000 598857 598857 [7.850737 0.002880] [ 0.673607] 200000 998095 998095 [7.853705 0.002968] [ 0.677188] 300000 1497142 1497142 [7.856601 0.002896] [ 0.680847] 600000 2994285 2994285 [7.859442 0.002841] [ 0.684573] 792000 3952457 3952457 [7.868981 0.009539] [ 0.688264] 1008000 5030400 5030400 [7.874015 0.005034] [ 0.692060] 1200000 5988571 5988571 [7.875289 0.001274] [ 0.702183] squashfs: version 4.0 (2009/01/31) Phillip Lougher [7.880826 0.005537] [ 0.709127] jffs2: version 2.2. 2001-2006 Red Hat, Inc. [7.885454 0.004628] [ 0.715117] msgmni has been set to 214 [7.891568 0.006114] [ 0.720250] io scheduler noop registered [7.897183 0.005615] [ 0.724293] io scheduler cfq registered (default) [7.900961 0.003778] [ 0.730745] jz-uart.0: ttyS0 at MMIO 0x10030000 (irq = 59) is a uart0 [7.907193 0.006232] [ 0.737457] jz-uart.1: ttyS1 at MMIO 0x10031000 (irq = 58) is a uart1 [7.915808 0.008615] [ 0.745689] console [ttyS1] enabled, bootconsole disabled [7.928924 0.013116] [ 0.745689] console [ttyS1] enabled, bootconsole disabled [7.931024 0.002100] [ 0.760892] brd: module loaded [7.937197 0.006173] [ 0.766265] loop: module loaded [7.940985 0.003788] [ 0.770177] zram: Created 2 device(s) … [7.946746 0.005761] [ 0.774525] logger: created 256K log ‘log_main’ [7.950481 0.003735] [ 0.779557] jz SADC driver registeres over! [7.953910 0.003429] [ 0.784303] input: aux0BAT as /devices/virtual/input/input0 [7.960166 0.006256] [ 0.790364] input: aux1VOLUME as /devices/virtual/input/input1 [7.973419 0.013253] [ 0.796937] the id code = c22018, the flash name is MX25L12835F [7.976799 0.003380] [ 0.803081] JZ SFC Controller for SFC channel 0 driver register [7.980229 0.003430] [ 0.809271] 5 cmdlinepart partitions found on MTD device jz_sfc [7.985174 0.004945] [ 0.815421] Creating 5 MTD partitions on “jz_sfc”: [7.996169 0.010995] [ 0.820389] 0x000000000000-0x000000040000 : “boot” [8.000954 0.004785] [ 0.825944] 0x000000040000-0x0000002c0000 : “kernel” [8.004917 0.003963] [ 0.831603] 0x0000002c0000-0x0000006c0000 : “root” [8.008792 0.003875] [ 0.837157] 0x0000006c0000-0x000000fe0000 : “appfs” [8.013388 0.004596] [ 0.842753] 0x000000fe0000-0x000001000000 : “attr” [8.025361 0.011973] [ 0.848338] SPI NOR MTD LOAD OK [8.026331 0.000970] [ 0.851656] tun: Universal TUN/TAP device driver, 1.6 [8.029654 0.003323] [ 0.856938] tun: © 1999-2004 Max Krasnyansky maxk@qualcomm.com [8.034601 0.004947] [ 0.863601] g_serial gadget: Gadget Serial v2.4 [8.037632 0.003031] [ 0.868342] g_serial gadget: g_serial ready [8.047780 0.010148] [ 0.873059] jz-rtc jz-rtc.0: rtc core: registered jz-rtc as rtc0 [8.054291 0.006511] [ 0.882709] input: bma250 as /devices/virtual/input/input2 [8.059383 0.005092] [ 0.888888] jzmmc_v1.2 jzmmc_v1.2.0: vmmc regulator missing [8.076686 0.017303] [ 0.904191] jzmmc_v1.2 jzmmc_v1.2.0: card inserted, state=0 [8.104335 0.027649] [ 0.934193] jzmmc_v1.2 jzmmc_v1.2.0: register success! [8.109070 0.004735] [ 0.939585] jzmmc_v1.2 jzmmc_v1.2.1: vmmc regulator missing [8.154275 0.045205] [ 0.984289] jzmmc_v1.2 jzmmc_v1.2.1: register success! [8.159329 0.005054] [ 0.989953] TCP: cubic registered [8.163454 0.004125] [ 0.993392] NET: Registered protocol family 17 [8.169278 0.005824] [ 0.999815] jz-rtc jz-rtc.0: setting system clock to 2018-06-01 00:05:55 UTC (1527811555) [8.186227 0.016949] [ 1.010356] Waiting 1sec before mounting root device… [9.159573 0.973346] [ 1.989686] wait stable.[246][cgu_msc0] [9.162944 0.003371] [ 1.993716] mmc0: new high speed SDHC card at address aaaa [9.170173 0.007229] [ 1.999757] mmcblk0: mmc0:aaaa SS08G 7.40 GiB [9.181051 0.010878] [ 2.010918] Alternate GPT is invalid, using primary GPT. [9.187939 0.006888] [ 2.016554] mmcblk0: p1 p2 p3 p4 p5 p6 p7 p8 p9 [9.198427 0.010488] [ 2.028524] VFS: Mounted root (squashfs filesystem) readonly on device 31:2. [9.205110 0.006683] [ 2.036288] Freeing unused kernel memory: 212K (8051b000 - 80550000) [10.401134 1.196024] [ 3.231428] EXT4-fs (mmcblk0p3): recovery complete [10.406170 0.005036] [ 3.237896] EXT4-fs (mmcblk0p3): mounted filesystem with ordered data mode. Opts: (null) [10.598413 0.192243] [ 3.428645] EXT4-fs (mmcblk0p4): mounted filesystem without journal. Opts: (null) [10.649535 0.051122] [ 3.479148] EXT4-fs (mmcblk0p8): mounted filesystem with ordered data mode. Opts: (null) [10.830032 0.180497] [ 3.658804] EXT4-fs (mmcblk0p9): recovery complete [10.837644 0.007612] [ 3.667863] EXT4-fs (mmcblk0p9): mounted filesystem with ordered data mode. Opts: (null) [11.305857 0.468213] [ 4.136162] RTL871X: module init start [11.308997 0.003140] [ 4.140060] RTL871X: rtl8189fs v4.3.24.11_26052.20180108 [11.323879 0.014882] [ 4.151329] RTL871X: build time: Oct 24 2019 21:22:04 [11.331184 0.007305] [ 4.156996] wlan power on [11.344534 0.013350] [ 4.174688] RTL871X: module init ret=0 [11.389954 0.045420] [ 4.219963] mmc1: card claims to support voltages below the defined range. These will be ignored. [11.417969 0.028015] [ 4.248236] mmc1: new SDIO card at address 0001 [11.496349 0.078380] [ 4.321260] RTL871X: HW EFUSE [11.501464 0.005115] [ 4.327248] RTL871X: hal_com_config_channel_plan chplan:0x20[ 4.473604] register all isp device successfully! [11.659830 0.158366] [ 4.490025] @@@@ tx-isp-probe ok @@@@@ [11.718315 0.058485] [ 4.548608] RTL871X: rtw_regsty_chk_target_tx_power_valid return _FALSE for band:0, path:0, rs:0, t:-1 [11.750917 0.032602] [ 4.581070] RTL871X: rtw_ndev_init(wlan0) if1 mac_addr=18:bb:26:7e:eb:c8 [11.814079 0.063162] [ 4.644494] jz_codec_register: probe() successful! [12.164266 0.350187] [ 4.994576] dma dma0chan24: Channel 24 have been requested.(phy id 7,type 0x06 desc a4e0c000) [12.181910 0.017644] [ 5.003838] dma dma0chan25: Channel 25 have been requested.(phy id 6,type 0x06 desc a4de500 [12.520288 0.338378] We will protect: [resetmonitor] [12.603869 0.083581] We will protect: [luka] [12.653444 0.049575] We will protect: [ota] [12.692185 0.038741] We will protect: [lvolume] [12.743105 0.050920] [12.743197 0.000092] Ling login: [ 8.154198] codec_set_device: set device: speaker…

（1） 系统启动总时间 系统启动到登录shell提示符出现耗时时间=12.743197-4.368941=8.374256秒 相比之前只有四行打印的启动时间7.460708秒，提高了0.913548（8.374256-7.460708）秒，这些缩短的时间，是由于客户把打印去除的原因。看来对于嵌入式系统来说，去除系统启动过程中的打印信息也是节省时间的利器（嵌入式系统CPU主频低，DDR内存少，资源能节约就节约，串口打印能不打印就不打印）。

（2） Bootrom启动时间 4.505315-4.372294=0.133021秒（此处不优化）

（3） Uboot启动时间 6.943339-4.505350=2.437989秒 主要占用时间点为： A. 网络初始化（耗时=4.782385-4.631253=0.151132秒） B. Uboot倒计时（耗时5.786299-4.782385=1.003914秒） C. Sf read FLASH（耗时381ms） D. 解压缩内核（耗时=6.943339-6.220767=0.722572秒） 优化时间： A． 去除网络初始化 B． 去除uboot倒计时 C． 缩短读flash大小（接近于内核大小） D． 更换不同内核压缩格式，均衡读flash所花费的时间，选择最少时间 默认压缩格式lzma（内核大小1785645Bytes=1744kB），sf read耗时 381ms（读取整个分区0x280000），解压缩到Starting kernel耗时0.722572秒（6.943339-6.220767） Gzip（内核大小2407KB）格式sf read 耗时381ms（读取整个分区0x280000），解压缩到Starting kernel耗时0.185267秒（3.177270-2.992003） Bzip2（内核大小2225KB）格式sf read 耗时381ms（读取整个分区0x280000），解压缩到Starting kernel耗时2.20876秒（20.737595-18.528835） Lzo （内核大小2670KB）格式sf read 耗时399ms（读取整个分区0x2A0000），解压缩到Starting kernel耗时0.118062秒（3.148085-3.030023） 有上述时间统计可以看出： a． 内核大小：Lzo>Gzip>Bzip2>lzma b． 解压缩时间：lzo<Gzip<lzma<Bzip2（对应于客户板子使用lzo格式内核刚好可以充分利用16Mflash大小）

综上所述，在uboot中去除网络初始化，去除uboot倒计时，使用lzo压缩格式内核，将kernel分区从原来的2560KB扩大到2688KB，虽然由于内核变大导致分区变大，读取flash大小也变多，浪费时间更长，但是lzo格式内核解压缩时间到启动内核非常短，与其他格式内核相比，算上读取flash的时间，同样可以缩短启动内核时间。 LZO格式内核+去除网络初始化+去除uboot倒计时之后，uboot启动时间=3.148085-2.432726=0.715359秒（相比于最开始的启动时间2.437989秒，缩短了1.72263秒）

（4） Kernel启动时间 9.205110-6.943374=2.261736秒 主要占用时间点为： A. Lpj计算（耗时=7.255810-7.171223=0.084587秒） B. USB初始化（耗时=7.722599-7.363650=0.358949秒） C. TF卡检测卡是否插入和初始化（耗时=8.154275-8.076686=0.077589秒） D. 等待cgu_msc0时钟稳定（耗时=9.159573-8.186227=0.973346秒），此处延时是因为kernel command line中设置的rootdelay=1才会延时1s 优化时间： A． 去除lpj计算 B． 去除rootdelay延时1s C． …….

综上所述，内核启动时间为1.171274秒（4.289844- 3.118570），相较于之前2.261736秒，缩短了1.090462秒（2.261736-1.171274） 结合上述uboot优化和内和优化，重新启动系统查看打印，再次统计时间如下 ： SPL uboot启动到内核结束耗时=4.289844-2.278716=2.011128秒 联合uboot缩短的时间，此时系统启动从SPL uboot到login 提示符总共耗时=7.729039-2.278716=5.450323秒，相较于最开始时间8.374256秒缩短了2.923933秒（8.374256-5.450323） 从脚本启动开始到结束耗时=7.680797-5.187470=2.493327秒

（5） Init进程启动到登录shell时间 12.743197-9.205110=3.538087秒 Init进程启动到脚本开始执行耗时=12.923191-12.037766=0.885425秒（精准计算，见如下打印） 主要占用时间点为（60%以上的时间都是脚本运行时间）： A. TF卡挂载分区以及与卡相关的其他操作（例如：修复SD卡）（总耗时=10.837644-9.205110-0.582229=1.050305秒，0.582229是根据demo板计算出来的从init进程开始到执行脚本所花费的时间） 精细化计时，从挂载jffs2开始到挂载mmcblk0p9分区结束总耗时= 13.557774- 13.107746=0.450028秒 a． jffs2挂载时间=13.197600-13.107746=0.089854秒 b． mmcblk0p3挂载时间=13.248850-13.198540=0.05031秒 c． mmcblk0p3与mmcblk0p4挂载之间syslogd -s 5120 -b 3和klogd耗时= 13.386577- 13.248850=0.137727秒 d． mmcblk0p4挂载时间=13.444782-13.386577=0.058205秒 e． mmcblk0p8挂载时间=13.492989-13.445362=0.047627秒 f． mmcblk0p9挂载时间=13.557774-13.493559=0.064215秒 B. WIFI驱动未完全执行完成加载过程（耗时=11.750917-11.305857=0.44506秒） Wifi驱动打印层次不齐，此处不予计算，但是wifi驱动加载确实比较耗时 C. Isp驱动，sensor驱动加载 a． isp驱动加载耗时=14.408429-14.055615=0.352814秒 b． 驱动加载耗时=14.498596-14.408429=0.090167秒 D. Audio驱动加载过程（耗时=12.181910-11.814079=0.367831秒） 精准计时=14.902143-14.498596=0.403547秒 E. 驱动执行完毕之后的余下部分（包括：应用程序启动，GPIO申请，sensor使能等）（耗时=12.743105-12.181910=0.561195秒） a． gpio申请和sensor使能耗时=14.921494-14.902143=0.019351秒 b． 应用程序启动耗时=15.392134-14.921494=0.47064秒

（6） 脚本启动时间（目录文件创建，驱动加载，配置信息加载，文件系统挂载，应用程序启动等） 精准时间计算=15.434692-12.923191=2.511501秒 主要占用时间点为： A. TF卡挂载分区以及与卡相关的其他操作（例如：修复SD卡）（总耗时=10.837644-9.205110-0.582229=1.050305秒，0.582229是根据demo板计算出来的从init进程开始到执行脚本所花费的时间） 精细化计时，从挂载jffs2开始到挂载mmcblk0p9分区结束总耗时= 13.557774- 13.107746=0.450028秒 g． jffs2挂载时间=13.197600-13.107746=0.089854秒 h． mmcblk0p3挂载时间=13.248850-13.198540=0.05031秒 i． mmcblk0p3与mmcblk0p4挂载之间syslogd -s 5120 -b 3和klogd耗时= 13.386577- 13.248850=0.137727秒 j． mmcblk0p4挂载时间=13.444782-13.386577=0.058205秒 k． mmcblk0p8挂载时间=13.492989-13.445362=0.047627秒 l． mmcblk0p9挂载时间=13.557774-13.493559=0.064215秒

B. WIFI驱动未完全执行完成加载过程（耗时=11.750917-11.305857=0.44506秒） C. Isp驱动和sensor驱动加载 isp驱动加载耗时=14.408429-14.055615=0.352814秒 sensor驱动加载耗时=14.498596-14.408429=0.090167秒 D. Audio驱动加载过程（耗时=12.181910-11.814079=0.367831秒） 精准计时=14.902143-14.498596=0.403547秒 E. 应用程序启动过程（耗时=12.743105-12.520288=0.222817秒） gpio申请和sensor使能耗时=14.921494-14.902143=0.019351秒 应用程序启动耗时=15.392134-14.921494=0.47064秒

[12.037766 0.007329] [ 2.036269] Freeing unused kernel memory: 212K (8051b000 - 80550000) [12.923191 0.885425] script start… [13.107746 0.184555] mount jffs2… [13.197600 0.089854] mount jffs2 over… [13.198540 0.000940] mount mmcblk0p3… [13.228984 0.030444] [ 3.233041] EXT4-fs (mmcblk0p3): recovery complete [13.234156 0.005172] [ 3.239477] EXT4-fs (mmcblk0p3): mounted filesystem with ordered data mode. Opts: (null) [13.248850 0.014694] mount mmcblk0p3 over… [13.386577 0.137727] mount mmcblk0p4… [13.421113 0.034536] [ 3.425721] EXT4-fs (mmcblk0p4): mounted filesystem without journal. Opts: (null) [13.444782 0.023669] mount mmcblk0p4 over… [13.445362 0.000580] mount mmcblk0p8… [13.471470 0.026108] [ 3.476058] EXT4-fs (mmcblk0p8): mounted filesystem with ordered data mode. Opts: (null) [13.492989 0.021519] mount mmcblk0p8 over… [13.493559 0.000570] mount mmcblk0p9… [13.534143 0.040584] [ 3.538737] EXT4-fs (mmcblk0p9): recovery complete [13.538579 0.004436] [ 3.544767] EXT4-fs (mmcblk0p9): mounted filesystem with ordered data mode. Opts: (null) [13.557774 0.019195] mount mmcblk0p9 over… [13.563701 0.005927] wifi probe… [14.014253 0.450552] [ 4.018845] RTL871X: module init start [14.018508 0.004255] [ 4.022741] RTL871X: rtl8189fs v4.3.24.11_26052.20180108 [14.030018 0.011510] [ 4.034028] RTL871X: build time: Oct 24 2019 21:22:04 [14.040342 0.010324] [ 4.039695] wlan power on [14.050483 0.010141] [ 4.054690] RTL871X: module init ret=0 [14.055615 0.005132] isp probe… [14.095260 0.039645] [ 4.099965] mmc1: card claims to support voltages below the defined range. These will be ignored. [14.123590 0.028330] [ 4.128277] mmc1: new SDIO card at address 0001 [14.187884 0.064294] [ 4.192612] RTL871X: HW EFUSE [14.200402 0.012518] [ 4.204274] RTL871X: hal_com_config_channel_plan chplan:0x20 [14.369810 0.169408] [ 4.374388] RTL871X: rtw_regsty_chk_target_tx_power_valid return _FALSE for band:0, path:0, rs:0, t:-1 [14.389070 0.019260] [ 4.384899] register all isp device successfully! [14.398147 0.009077] [ 4.402470] @@@@ tx-isp-probe ok @@@@@ [14.408429 0.010282] sensor probe… [14.419073 0.010644] [ 4.423798] RTL871X: rtw_ndev_init(wlan0) if1 mac_addr=18:bb:26:7e:eb:c8 [14.498596 0.079523] audio probe… [14.515066 0.016470] [ 4.519820] jz_codec_register: probe() successful! [14.869909 0.354843] [ 4.874583] dma dma0chan24: Channel 24 have been requested.(phy id 7,type 0x06 desc a4b71000) [14.885056 0.015147] [ 4.883843] dma dma0chan25: Channel 25 have been requested.(phy id 6,type 0x06 desc a4d28000) [14.902143 0.017087] gpio… [14.921494 0.019351] reset app… [15.226278 0.304784] We will protect: [resetmonitor] [15.315268 0.088990] We will protect: [luka] [15.353970 0.038702] We will protect: [ota] [15.391361 0.037391] We will protect: [lvolume] [15.392134 0.000773] script end… [15.434635 0.042501] [15.434692 0.000057] Ling login:

（7） 应用程序启动到正常运行时间

T31平台启动时间优化

之前T20X平台的优化可以全部平移到T31平台上面（uboot优化，kernel优化），现在看一下通过串口打印可以发现init进程启动到脚本启动也需要一段时间（几百毫秒），T20X平台系统启动时可以明显观察到这里会卡一下，所以着重看一下这里是否能优化，现在平移到T31平台，研究一下init进程启动都干了什么以及主要耗时都做了什么工作。 Init进程又名busybox，嵌入式开发版中的所使用到的系统命令（cp，ls等）实质都是执行busybox，ls –l可以看到这些命令都是被连接到busybox，内核启动结束之后通过读取命令行中init=/linuxrc或者执行/bin/init，/sbin/init来执行init进程，此时从内核切换到了用户空间。要看init进程启动到脚本执行只需要下载busybox源码，查看init_main函数即可。 Busybox编译类似于内核编译，也是make configs/XXX生成默认配置（即.config文件），然后可以手动make menuconfig进行配置或者裁剪，最后使用make –j8进行编译，然后在当前目录中会生成busybox，再把这个文件放到文件系统/bin中即可（其他的可执行文件都已被链接到busybox）。下面开始分析： 首先，T31平台启动串口打印如下（T31平台CPU频率为1392MHZ，DDR频率为750MHZ，相比于T20平台CPU频率864MHZ，DDR频率500MHZ有所提升）： （1） make isvp_uclibc_defconfig sudo ./grabserial -v -d /dev/ttyUSB0 -e 60 -t Opening serial port /dev/ttyUSB0 115200:8N1:xonxoff=0:rtscts=0 Program set to end in 60 seconds Printing timing information for each line Use Control-C to stop…

reb [0.000000 0.000000] reb[root@Ingenic-uc1_1:~]# reboot [0.033073 0.033073] [root@Ingenic-uc1_1:~]# umount: tmpfs busy - remounted read-only [0.037013 0.003940] The system is going down NOW! [0.039096 0.002083] Sent SIGTERM to all processes [1.023563 0.984467] Sent SIGKILL to all processes [1.024866 0.001303] Requesting system reboot[ 104.493298] Restarting system. [2.015118 0.990252] [ 104.496453] Restarting after 4 ms [2.094115 0.078997] [2.094177 0.000062] U-Boot SPL 2013.07-00004-g2b4e917-dirty (Sep 19 2019 - 14:40:29) [2.144437 0.050260] Timer init [2.144695 0.000258] CLK stop [2.144899 0.000204] PLL init [2.145150 0.000251] pll_init:366 [2.145434 0.000284] pll_cfg.pdiv = 10, pll_cfg.h2div = 5, pll_cfg.h0div = 5, pll_cfg.cdiv = 1, pll_cfg.l2div = 2 [2.151871 0.006437] nf=116 nr = 1 od0 = 1 od1 = 2 [2.153898 0.002027] cppcr is 07405100 [2.155102 0.001204] CPM_CPAPCR 0740510d [2.156369 0.001267] nf=126 nr = 1 od0 = 1 od1 = 2 [2.158311 0.001942] cppcr is 07e05100 [2.159486 0.001175] CPM_CPMPCR 07d0510d [2.160744 0.001258] nf=100 nr = 1 od0 = 1 od1 = 2 [2.170475 0.009731] cppcr is 06405100 [2.170980 0.000505] CPM_CPVPCR 0640510d [2.171552 0.000572] cppcr 0x9a7b5510 [2.172020 0.000468] apll_freq 1392000000 [2.172637 0.000617] mpll_freq 1500000000 [2.174401 0.001764] vpll_freq = 1200000000 [2.179713 0.005312] ddr sel mpll, cpu sel apll [2.185248 0.005535] ddrfreq 750000000 [2.186980 0.001732] cclk 1392000000 [2.188398 0.001418] l2clk 696000000 [2.189592 0.001194] h0clk 300000000 [2.190880 0.001288] h2clk 300000000 [2.191944 0.001064] pclk 150000000 [2.193028 0.001084] CLK init [2.193639 0.000611] SDRAM init [2.194467 0.000828] sdram init start [2.195628 0.001161] ddr_inno_phy_init …! [2.218658 0.023030] phy reg = 0x00000000, CL = 0x00000007 [2.219470 0.000812] ddr_inno_phy_init …! 11: 00000004 [2.220269 0.000799] ddr_inno_phy_init …! 22: 00000006 [2.220987 0.000718] ddr_inno_phy_init …! 33: 00000006 [2.221832 0.000845] REG_DDR_LMR: 00008210 [2.225959 0.004127] REG_DDR_LMR: 00000310 [2.227606 0.001647] REG_DDR_LMR: 00006110 [2.229011 0.001405] REG_DDR_LMR, MR0: 01c30010 [2.230839 0.001828] REG_DDR_LMR: 00000018 [2.232477 0.001638] T31_c0: 00000003 [2.233644 0.001167] T31_0x5: 00000007 [2.234827 0.001183] T31_0x15: 0000000c [2.236034 0.001207] T31_0x4: 00000040 [2.237426 0.001392] T31_0x14: 00000002 [2.238695 0.001269] INNO_TRAINING_CTRL 1: 000000a1 [2.240767 0.002072] INNO_TRAINING_CTRL 2: 000000a1 [2.242767 0.002000] T31_cc: 00000003 [2.243922 0.001155] INNO_TRAINING_CTRL 3: 000000a0 [2.264216 0.020294] T31_118: 0000003c [2.264618 0.000402] T31_158: 0000003c [2.264999 0.000381] T31_190: 0000001d [2.265616 0.000617] T31_194: 0000001a [2.266407 0.000791] jz-04 : 0x00000050 [2.268978 0.002571] jz-08 : 0x000000a0 [2.270591 0.001613] jz-28 : 0x00000024 [2.272519 0.001928] DDR PHY init OK [2.274263 0.001744] INNO_DQ_WIDTH :00000003 [2.276188 0.001925] INNO_PLL_FBDIV :00000014 [2.278020 0.001832] INNO_PLL_PDIV :00000005 [2.279923 0.001903] INNO_MEM_CFG :00000050 [2.281708 0.001785] INNO_PLL_CTRL :00000018 [2.283602 0.001894] INNO_CHANNEL_EN :0000000d [2.285242 0.001640] INNO_CWL :00000006 [2.286917 0.001675] INNO_CL :00000007 [2.288590 0.001673] DDR Controller init [2.289893 0.001303] DDRC_STATUS 0x80000001 [2.299425 0.009532] DDRC_CFG 0x0aec8a42 [2.300856 0.001431] DDRC_CTRL 0x0000891c [2.307878 0.007022] DDRC_LMR 0x00000000 [2.309155 0.001277] DDRC_DLP 0x00000000 [2.313022 0.003867] DDRC_TIMING1 0x06100c06 [2.316101 0.003079] DDRC_TIMING2 0x041d0b07 [2.318568 0.002467] DDRC_TIMING3 0x210b0627 [2.320615 0.002047] DDRC_TIMING4 0x3c250043 [2.322617 0.002002] DDRC_TIMING5 0xff070405 [2.324680 0.002063] DDRC_TIMING6 0x80220505 [2.326952 0.002272] DDRC_REFCNT 0x00b64903 [2.329753 0.002801] DDRC_MMAP0 0x000020f8 [2.342381 0.012628] DDRC_MMAP1 0x00002800 [2.346155 0.003774] DDRC_REMAP1 0x03020100 [2.347591 0.001436] DDRC_REMAP2 0x07060504 [2.352276 0.004685] DDRC_REMAP3 0x0b0a0908 [2.353171 0.000895] DDRC_REMAP4 0x0f0e0d0c [2.354002 0.000831] DDRC_REMAP5 0x13121110 [2.355167 0.001165] DDRC_AUTOSR_EN 0x00000000 [2.356981 0.001814] sdram init finished [2.361903 0.004922] SDRAM init ok [2.362869 0.000966] board_init_r [2.412544 0.049675] image entry point: 0x80100000 [2.413377 0.000833] [2.413418 0.000041] [2.413443 0.000025] U-Boot 2013.07-00004-g2b4e917-dirty (Sep 19 2019 - 14:40:29) [2.414990 0.001547] [2.415018 0.000028] Board: ISVP (Ingenic XBurst T31 SoC) [2.415836 0.000818] DRAM: 128 MiB [2.416378 0.000542] Top of RAM usable for U-Boot at: 84000000 [2.417399 0.001021] Reserving 443k for U-Boot at: 83f90000 [2.418487 0.001088] Reserving 32784k for malloc() at: 81f8c000 [2.421252 0.002765] Reserving 32 Bytes for Board Info at: 81f8bfe0 [2.424243 0.002991] Reserving 124 Bytes for Global Data at: 81f8bf64 [2.434808 0.010565] Reserving 128k for boot params() at: 81f6bf64 [2.436119 0.001311] Stack Pointer at: 81f6bf48 [2.436910 0.000791] Now running in RAM - U-Boot at: 83f90000 [2.493823 0.056913] MMC: msc: 0 [2.494278 0.000455] the manufacturer c2 [2.494698 0.000420] SF: Detected MX25L128E [2.495257 0.000559] [2.495283 0.000026] *** Warning - bad CRC, using default environment [2.496344 0.001061] [2.496373 0.000029] In: serial [2.496663 0.000290] Out: serial [2.496951 0.000288] Err: serial [2.497275 0.000324] Net: ====>phy 0:0x243-0xc54 found [2.637608 0.140333] Jz4775-9161 [2.637909 0.000301] Hit any key to stop autoboot: 0 [3.644446 1.006537] the manufacturer c2 [3.644925 0.000479] SF: Detected MX25L128E [3.645560 0.000635] [3.645588 0.000028] —>probe spend 5 ms [4.527994 0.882406] SF: 2621440 bytes @ 0x40000 Read: OK [4.528823 0.000829] —>read spend 842 ms [4.529297 0.000474] ## Booting kernel from Legacy Image at 80600000 … [4.530374 0.001077] Image Name: Linux-3.10.14__isvp_swan_1.0__ [4.531351 0.000977] Image Type: MIPS Linux Kernel Image (lzma compressed) [4.532555 0.001204] Data Size: 1693750 Bytes = 1.6 MiB [4.533391 0.000836] Load Address: 80010000 [4.533914 0.000523] Entry Point: 803aaa80 [4.535029 0.001115] Verifying Checksum … OK [4.536984 0.001955] Uncompressing Kernel Image … OK [4.959488 0.422504] [4.959518 0.000030] Starting kernel … [4.959940 0.000422] [5.003990 0.044050] [ 0.000000] Initializing cgroup subsys cpu [5.005858 0.001868] [ 0.000000] Initializing cgroup subsys cpuacct [5.010058 0.004200] [ 0.000000] Linux version 3.10.14__isvp_swan_1.0__ (chsun@4) (gcc version 4.7.2 (Ingenic r2.3.3 2016.12) ) #41 PREEMPT Wed Sep 4 11:14:31 CST 2019 [5.022041 0.011983] [ 0.000000] bootconsole [early0] enabled [5.024992 0.002951] [ 0.000000] CPU0 RESET ERROR PC:801C7B80 [5.035348 0.010356] [ 0.000000] [<801c7b80>] __delay+0x0/0x10 [5.036751 0.001403] [ 0.000000] CPU0 revision is: 00d00100 (Ingenic Xburst) [5.040776 0.004025] [ 0.000000] FPU revision is: 00b70000 [5.041967 0.001191] [ 0.000000] cgu_get_rate, parent = 1392000000, rate = 0, m = 0, n = 0, reg val = 0x081000ff [5.054119 0.012152] [ 0.000000] cgu_get_rate, parent = 1392000000, rate = 0, m = 0, n = 0, reg val = 0x081000ff [5.060976 0.006857] [ 0.000000] CCLK:1392MHz L2CLK:696Mhz H0CLK:250MHz H2CLK:250Mhz PCLK:125Mhz [5.066084 0.005108] [ 0.000000] Determined physical RAM map: [5.068876 0.002792] [ 0.000000] memory: 004c6000 @ 00010000 (usable) [5.072369 0.003493] [ 0.000000] memory: 0003a000 @ 004d6000 (usable after init) [5.083469 0.011100] [ 0.000000] User-defined physical RAM map: [5.086879 0.003410] [ 0.000000] memory: 04000000 @ 00000000 (usable) [5.096346 0.009467] [ 0.000000] Zone ranges: [5.098192 0.001846] [ 0.000000] Normal [mem 0x00000000-0x03ffffff] [5.102073 0.003881] [ 0.000000] Movable zone start for each node [5.105178 0.003105] [ 0.000000] Early memory node ranges [5.109540 0.004362] [ 0.000000] node 0: [mem 0x00000000-0x03ffffff] [5.113133 0.003593] [ 0.000000] Primary instruction cache 32kB, 8-way, VIPT, linesize 32 bytes. [5.127057 0.013924] [ 0.000000] Primary data cache 32kB, 8-way, VIPT, no aliases, linesize 32 bytes [5.130443 0.003386] [ 0.000000] pls check processor_id[0x00d00100],sc_jz not support! [5.138499 0.008056] [ 0.000000] MIPS secondary cache 128kB, 8-way, linesize 32 bytes. [5.147875 0.009376] [ 0.000000] Built 1 zonelists in Zone order, mobility grouping off. Total pages: 16256 [5.155480 0.007605] [ 0.000000] Kernel command line: console=ttyS1,115200n8 mem=64M@0x0 rmem=64M@0x4000000 init=/linuxrc rootfstype=squashfs root=/dev/mtdblock2 rw mtdparts=jz_sfc:256k(boot),2560k(kernel),2048k(root),-(appfs) [5.176591 0.021111] [ 0.000000] PID hash table entries: 256 (order: -2, 1024 bytes) [5.183358 0.006767] [ 0.000000] Dentry cache hash table entries: 8192 (order: 3, 32768 bytes) [5.195767 0.012409] [ 0.000000] Inode-cache hash table entries: 4096 (order: 2, 16384 bytes) [5.197358 0.001591] [ 0.000000] Memory: 59348k/65536k available (3725k kernel code, 6188k reserved, 1159k data, 232k init, 0k highmem) [5.204221 0.006863] [ 0.000000] SLUB: HWalign=32, Order=0-3, MinObjects=0, CPUs=1, Nodes=1 [5.209519 0.005298] [ 0.000000] Preemptible hierarchical RCU implementation. [5.213475 0.003956] [ 0.000000] NR_IRQS:358 [5.222524 0.009049] [ 0.000000] clockevents_config_and_register success. [5.226691 0.004167] [ 0.000014] Calibrating delay loop… 1391.00 BogoMIPS (lpj=6955008) [5.322996 0.096305] [ 0.087833] pid_max: default: 32768 minimum: 301 [5.324034 0.001038] [ 0.092690] Mount-cache hash table entries: 512 [5.325039 0.001005] [ 0.097609] Initializing cgroup subsys debug [5.327770 0.002731] [ 0.101864] Initializing cgroup subsys freezer [5.330880 0.003110] [ 0.107990] regulator-dummy: no parameters [5.335244 0.004364] [ 0.112176] NET: Registered protocol family 16 [5.340094 0.004850] [ 0.126329] bio: create slab at 0 [5.351781 0.011687] [ 0.131768] jz-dma jz-dma: JZ SoC DMA initialized [5.353203 0.001422] [ 0.136746] usbcore: registered new interface driver usbfs [5.368006 0.014803] [ 0.142256] usbcore: registered new interface driver hub [5.369307 0.001301] [ 0.147728] usbcore: registered new device driver usb [5.371292 0.001985] [ 0.152882] (null): set:311 hold:312 dev=125000000 h=625 l=625 [5.375689 0.004397] [ 0.159007] (null): set:311 hold:312 dev=125000000 h=625 l=625 [5.380555 0.004866] [ 0.165092] media: Linux media interface: v0.10 [5.383867 0.003312] [ 0.169637] Linux video capture interface: v2.00 [5.387155 0.003288] [ 0.175663] Switching to clocksource jz_clocksource [5.399339 0.012184] [ 0.180980] jz-dwc2 jz-dwc2: cgu clk gate get error [5.406876 0.007537] [ 0.185926] cfg80211: Calling CRDA to update world regulatory domain [5.417687 0.010811] [ 0.192353] DWC IN OTG MODE [5.420730 0.003043] [ 0.195744] dwc2 dwc2: Keep PHY ON [5.423559 0.002829] [ 0.199107] dwc2 dwc2: Using Buffer DMA mode [5.428262 0.004703] [ 0.203455] dwc2 dwc2: Core Release: 3.00a [5.431385 0.003123] [ 0.207624] dwc2 dwc2: DesignWare USB2.0 High-Speed Host Controller [5.436109 0.004724] [ 0.213965] dwc2 dwc2: new USB bus registered, assigned bus number 1 [5.450791 0.014682] [ 0.221009] hub 1-0:1.0: USB hub found [5.451971 0.001180] [ 0.224744] hub 1-0:1.0: 1 port detected [5.453156 0.001185] [ 0.228781] dwc2 dwc2: DWC2 Host Initialized [5.457489 0.004333] [ 0.233218] NET: Registered protocol family 2 [5.458506 0.001017] [ 0.237947] TCP established hash table entries: 512 (order: 0, 4096 bytes) [5.460029 0.001523] [ 0.244896] TCP bind hash table entries: 512 (order: -1, 2048 bytes) [5.461684 0.001655] [ 0.251308] TCP: Hash tables configured (established 512 bind 512) [5.470345 0.008661] [ 0.257600] TCP: reno registered [5.473316 0.002971] [ 0.260846] UDP hash table entries: 256 (order: 0, 4096 bytes) [5.478492 0.005176] [ 0.266753] UDP-Lite hash table entries: 256 (order: 0, 4096 bytes) [5.484656 0.006164] [ 0.273294] NET: Registered protocol family 1 [5.501436 0.016780] [ 0.277860] RPC: Registered named UNIX socket transport module. [5.508703 0.007267] [ 0.283838] RPC: Registered udp transport module. [5.510137 0.001434] [ 0.288554] RPC: Registered tcp transport module. [5.511620 0.001483] [ 0.293332] RPC: Registered tcp NFSv4.1 backchannel transport module. [5.513592 0.001972] [ 0.300124] freq_udelay_jiffys[0].max_num = 10 [5.519246 0.005654] [ 0.304575] cpufreq udelay loops_per_jiffy [5.522580 0.003334] [ 0.308971] dwc2 dwc2: ID PIN CHANGED! [5.525214 0.002634] [ 0.312814] 12000 59956 59956 [5.527736 0.002522] [ 0.316026] 24000 119913 119913 [5.530144 0.002408] [ 0.319470] 60000 299784 299784 [5.555012 0.024868] [ 0.322994] 120000 599569 599569 [5.556081 0.001069] [ 0.326446] 200000 999282 999282 [5.557127 0.001046] [ 0.329977] 300000 1498924 1498924 [5.558250 0.001123] [ 0.333757] 600000 2997848 2997848 [5.563629 0.005379] [ 0.337394] 792000 3957159 3957159 [5.564728 0.001099] [ 0.341118] 1008000 5036385 5036385 [5.566242 0.001514] [ 0.344898] 1200000 5995696 5995696 [5.573111 0.006869] [ 0.352356] squashfs: version 4.0 (2009/01/31) Phillip Lougher [5.577672 0.004561] [ 0.358840] jffs2: version 2.2. 2001-2006 Red Hat, Inc. [5.582056 0.004384] [ 0.364653] msgmni has been set to 115 [5.585144 0.003088] [ 0.369287] io scheduler noop registered [5.607493 0.022349] [ 0.373288] io scheduler cfq registered (default) [5.608910 0.001417] [ 0.379044] jz-uart.1: ttyS1 at MMIO 0x10031000 (irq = 58) is a uart1 [5.618501 0.009591] [ 0.386649] console [ttyS1] enabled, bootconsole disabled [5.620375 0.001874] [ 0.386649] console [ttyS1] enabled, bootconsole disabled [5.622010 0.001635] [ 0.400300] brd: module loaded [5.622939 0.000929] [ 0.404922] loop: module loaded [5.624967 0.002028] [ 0.408586] zram: Created 2 device(s) … [5.632088 0.007121] [ 0.412883] logger: created 256K log ‘log_main’ [5.636589 0.004501] [ 0.417964] jz TCU driver register completed [5.649032 0.012443] [ 0.422822] the id code = c22018, the flash name is MX25L12835F [5.653469 0.004437] [ 0.428935] JZ SFC Controller for SFC channel 0 driver register [5.664299 0.010830] [ 0.435094] 4 cmdlinepart partitions found on MTD device jz_sfc [5.671236 0.006937] [ 0.441211] Creating 4 MTD partitions on “jz_sfc”: [5.672743 0.001507] [ 0.446155] 0x000000000000-0x000000040000 : “boot” [5.674199 0.001456] [ 0.451518] 0x000000040000-0x0000002c0000 : “kernel” [5.678073 0.003874] [ 0.456968] 0x0000002c0000-0x0000004c0000 : “root” [5.680104 0.002031] [ 0.462312] 0x0000004c0000-0x000001000000 : “appfs” [5.688253 0.008149] [ 0.467686] SPI NOR MTD LOAD OK [5.702864 0.014611] [ 0.471014] tun: Universal TUN/TAP device driver, 1.6 [5.709194 0.006330] [ 0.476224] tun: © 1999-2004 Max Krasnyansky maxk@qualcomm.com [5.720332 0.011138] [ 0.482686] Bus Mode Reg after reset: 0x00020101, cnt=0 [5.722020 0.001688] [ 0.491224] libphy: jz_mii_bus: probed [5.725622 0.003602] [ 0.495151] =>gmacdev = 0x805f0c00<========== [5.729959 0.004337] [ 0.500758] =========>gmacdev->MacBase = 0xb34b0000 DmaBase = 0xb34b1000 [5.738210 0.008251] [ 0.507672] Bus Mode Reg after reset: 0x00020101, cnt=0 [5.743550 0.005340] [ 0.514478] jz_mac jz_mac.0: JZ on-chip Ethernet MAC driver, Version 1.0 [5.749440 0.005890] [ 0.521551] usbcore: registered new interface driver zd1201 [5.755128 0.005688] [ 0.527506] jzmmc_v1.2 jzmmc_v1.2.0: vmmc regulator missing [5.760347 0.005219] [ 0.540574] jzmmc_v1.2 jzmmc_v1.2.0: card inserted, state=0 [5.771777 0.011430] [ 0.570559] jzmmc_v1.2 jzmmc_v1.2.0: register success! [5.808252 0.036475] [ 0.576080] TCP: cubic registered [5.809002 0.000750] [ 0.579500] NET: Registered protocol family 17 [5.811408 0.002406] [ 0.584722] input: gpio-keys as /devices/platform/gpio-keys/input/input0 [5.819944 0.008536] [ 0.591832] drivers/rtc/hctosys.c: unable to open rtc device (rtc0) [5.821871 0.001927] [ 0.602016] VFS: Mounted root (squashfs filesystem) readonly on device 31:2. [5.827260 0.005389] [ 0.609624] Freeing unused kernel memory: 232K (804d6000 - 80510000) [6.127542 0.300282] script start now … [6.207491 0.079949] mdev is ok… [7.821245 1.613754] script start end … [7.933214 0.111969] [7.933273 0.000059] Ingenic-uc1_1 login: 由上述打印可知，init进程启动开始到脚本开始执行耗时=6.127542-5.827260=0.300282秒，相较于T20平台时间有所减少

（2） make isvp_uclibc_mini_defconfig sudo ./grabserial -v -d /dev/ttyUSB0 -e 60 -t Opening serial port /dev/ttyUSB0 115200:8N1:xonxoff=0:rtscts=0 Program set to end in 60 seconds Printing timing information for each line Use Control-C to stop…

reb [0.000001 0.000001] reb[root@Ingenic-uc1_1:t31]# reboot [0.034525 0.034524] [root@Ingenic-uc1_1:t31]# umount: 193.169.4.92:/nfs busy - remounted read-only [0.040035 0.005510] umount: tmpfs busy - remounted read-only [0.044329 0.004294] The system is going down NOW! [0.047024 0.002695] Sent SIGTERM to all processes [1.024603 0.977579] Sent SIGKILL to all processes [1.025776 0.001173] Requesting system reboot[ 746.717075] Restarting system. [2.031322 1.005546] [ 746.720230] Restarting after 4 ms [2.143774 0.112452] [2.143840 0.000066] U-Boot SPL 2013.07-00004-g2b4e917-dirty (Sep 19 2019 - 14:40:29) [2.145347 0.001507] Timer init [2.145626 0.000279] CLK stop [2.145854 0.000228] PLL init [2.146082 0.000228] pll_init:366 [2.146418 0.000336] pll_cfg.pdiv = 10, pll_cfg.h2div = 5, pll_cfg.h0div = 5, pll_cfg.cdiv = 1, pll_cfg.l2div = 2 [2.150951 0.004533] nf=116 nr = 1 od0 = 1 od1 = 2 [2.152847 0.001896] cppcr is 07405100 [2.154063 0.001216] CPM_CPAPCR 0740510d [2.155316 0.001253] nf=126 nr = 1 od0 = 1 od1 = 2 [2.157334 0.002018] cppcr is 07e05100 [2.161964 0.004630] CPM_CPMPCR 07d0510d [2.163327 0.001363] nf=100 nr = 1 od0 = 1 od1 = 2 [2.165376 0.002049] cppcr is 06405100 [2.166521 0.001145] CPM_CPVPCR 0640510d [2.167796 0.001275] cppcr 0x9a7b5510 [2.168865 0.001069] apll_freq 1392000000 [2.170365 0.001500] mpll_freq 1500000000 [2.183829 0.013464] vpll_freq = 1200000000 [2.184903 0.001074] ddr sel mpll, cpu sel apll [2.186128 0.001225] ddrfreq 750000000 [2.186975 0.000847] cclk 1392000000 [2.191932 0.004957] l2clk 696000000 [2.192433 0.000501] h0clk 300000000 [2.192885 0.000452] h2clk 300000000 [2.193334 0.000449] pclk 150000000 [2.193804 0.000470] CLK init [2.194068 0.000264] SDRAM init [2.194406 0.000338] sdram init start [2.194879 0.000473] ddr_inno_phy_init …! [2.221020 0.026141] phy reg = 0x00000000, CL = 0x00000007 [2.221879 0.000859] ddr_inno_phy_init …! 11: 00000004 [2.222642 0.000763] ddr_inno_phy_init …! 22: 00000006 [2.223422 0.000780] ddr_inno_phy_init …! 33: 00000006 [2.224142 0.000720] REG_DDR_LMR: 00008210 [2.224608 0.000466] REG_DDR_LMR: 00000310 [2.225058 0.000450] REG_DDR_LMR: 00006110 [2.225523 0.000465] REG_DDR_LMR, MR0: 01c30010 [2.226066 0.000543] REG_DDR_LMR: 00000018 [2.226532 0.000466] T31_c0: 00000003 [2.226883 0.000351] T31_0x5: 00000007 [2.227255 0.000372] T31_0x15: 0000000c [2.236039 0.008784] T31_0x4: 00000040 [2.236625 0.000586] T31_0x14: 00000002 [2.237162 0.000537] INNO_TRAINING_CTRL 1: 000000a1 [2.241218 0.004056] INNO_TRAINING_CTRL 2: 000000a1 [2.242675 0.001457] T31_cc: 00000003 [2.244324 0.001649] INNO_TRAINING_CTRL 3: 000000a0 [2.265178 0.020854] T31_118: 0000003c [2.267074 0.001896] T31_158: 0000003c [2.268297 0.001223] T31_190: 0000001d [2.269617 0.001320] T31_194: 0000001a [2.270895 0.001278] jz-04 : 0x00000050 [2.272254 0.001359] jz-08 : 0x000000a0 [2.273665 0.001411] jz-28 : 0x00000024 [2.274982 0.001317] DDR PHY init OK [2.283880 0.008898] INNO_DQ_WIDTH :00000003 [2.284624 0.000744] INNO_PLL_FBDIV :00000014 [2.285342 0.000718] INNO_PLL_PDIV :00000005 [2.286223 0.000881] INNO_MEM_CFG :00000050 [2.287626 0.001403] INNO_PLL_CTRL :00000018 [2.289190 0.001564] INNO_CHANNEL_EN :0000000d [2.290560 0.001370] INNO_CWL :00000006 [2.295621 0.005061] INNO_CL :00000007 [2.297369 0.001748] DDR Controller init [2.299477 0.002108] DDRC_STATUS 0x80000001 [2.301519 0.002042] DDRC_CFG 0x0aec8a42 [2.304104 0.002585] DDRC_CTRL 0x0000891c [2.310062 0.005958] DDRC_LMR 0x00000000 [2.312131 0.002069] DDRC_DLP 0x00000000 [2.314669 0.002538] DDRC_TIMING1 0x06100c06 [2.316712 0.002043] DDRC_TIMING2 0x041d0b07 [2.318685 0.001973] DDRC_TIMING3 0x210b0627 [2.328106 0.009421] DDRC_TIMING4 0x3c250043 [2.328991 0.000885] DDRC_TIMING5 0xff070405 [2.329894 0.000903] DDRC_TIMING6 0x80220505 [2.334140 0.004246] DDRC_REFCNT 0x00b64903 [2.335190 0.001050] DDRC_MMAP0 0x000020f8 [2.336064 0.000874] DDRC_MMAP1 0x00002800 [2.337868 0.001804] DDRC_REMAP1 0x03020100 [2.344469 0.006601] DDRC_REMAP2 0x07060504 [2.347638 0.003169] DDRC_REMAP3 0x0b0a0908 [2.349812 0.002174] DDRC_REMAP4 0x0f0e0d0c [2.351974 0.002162] DDRC_REMAP5 0x13121110 [2.354431 0.002457] DDRC_AUTOSR_EN 0x00000000 [2.356832 0.002401] sdram init finished [2.358128 0.001296] SDRAM init ok [2.359051 0.000923] board_init_r [2.414740 0.055689] image entry point: 0x80100000 [2.415948 0.001208] [2.416010 0.000062] [2.416051 0.000041] U-Boot 2013.07-00004-g2b4e917-dirty (Sep 19 2019 - 14:40:29) [2.417827 0.001776] [2.417851 0.000024] Board: ISVP (Ingenic XBurst T31 SoC) [2.418618 0.000767] DRAM: 128 MiB [2.418921 0.000303] Top of RAM usable for U-Boot at: 84000000 [2.420739 0.001818] Reserving 443k for U-Boot at: 83f90000 [2.424095 0.003356] Reserving 32784k for malloc() at: 81f8c000 [2.428070 0.003975] Reserving 32 Bytes for Board Info at: 81f8bfe0 [2.436051 0.007981] Reserving 124 Bytes for Global Data at: 81f8bf64 [2.439279 0.003228] Reserving 128k for boot params() at: 81f6bf64 [2.442587 0.003308] Stack Pointer at: 81f6bf48 [2.451701 0.009114] Now running in RAM - U-Boot at: 83f90000 [2.495846 0.044145] MMC: msc: 0 [2.496194 0.000348] the manufacturer c2 [2.496625 0.000431] SF: Detected MX25L128E [2.497136 0.000511] [2.497159 0.000023] *** Warning - bad CRC, using default environment [2.498155 0.000996] [2.498179 0.000024] In: serial [2.498488 0.000309] Out: serial [2.498773 0.000285] Err: serial [2.499057 0.000284] Net: ====>phy 0:0x243-0xc54 found [2.639765 0.140708] Jz4775-9161 [2.640089 0.000324] Hit any key to stop autoboot: 0 [3.662444 1.022355] the manufacturer c2 [3.662894 0.000450] SF: Detected MX25L128E [3.663405 0.000511] [3.663429 0.000024] —>probe spend 5 ms [4.530205 0.866776] SF: 2621440 bytes @ 0x40000 Read: OK [4.531049 0.000844] —>read spend 842 ms [4.531509 0.000460] ## Booting kernel from Legacy Image at 80600000 … [4.532682 0.001173] Image Name: Linux-3.10.14__isvp_swan_1.0__ [4.533689 0.001007] Image Type: MIPS Linux Kernel Image (lzma compressed) [4.534909 0.001220] Data Size: 1693750 Bytes = 1.6 MiB [4.536135 0.001226] Load Address: 80010000 [4.537899 0.001764] Entry Point: 803aaa80 [4.539554 0.001655] Verifying Checksum … OK [4.548704 0.009150] Uncompressing Kernel Image … OK [4.961785 0.413081] [4.961821 0.000036] Starting kernel … [4.962319 0.000498] [5.006407 0.044088] [ 0.000000] Initializing cgroup subsys cpu [5.007635 0.001228] [ 0.000000] Initializing cgroup subsys cpuacct [5.013182 0.005547] [ 0.000000] Linux version 3.10.14__isvp_swan_1.0__ (chsun@4) (gcc version 4.7.2 (Ingenic r2.3.3 2016.12) ) #41 PREEMPT Wed Sep 4 11:14:31 CST 2019 [5.025218 0.012036] [ 0.000000] bootconsole [early0] enabled [5.029008 0.003790] [ 0.000000] CPU0 RESET ERROR PC:801C7B84 [5.039947 0.010939] [ 0.000000] [<801c7b84>] __delay+0x4/0x10 [5.041358 0.001411] [ 0.000000] CPU0 revision is: 00d00100 (Ingenic Xburst) [5.046630 0.005272] [ 0.000000] FPU revision is: 00b70000 [5.047805 0.001175] [ 0.000000] cgu_get_rate, parent = 1392000000, rate = 0, m = 0, n = 0, reg val = 0x081000ff [5.060231 0.012426] [ 0.000000] cgu_get_rate, parent = 1392000000, rate = 0, m = 0, n = 0, reg val = 0x081000ff [5.067365 0.007134] [ 0.000000] CCLK:1392MHz L2CLK:696Mhz H0CLK:250MHz H2CLK:250Mhz PCLK:125Mhz [5.072553 0.005188] [ 0.000000] Determined physical RAM map: [5.075373 0.002820] [ 0.000000] memory: 004c6000 @ 00010000 (usable) [5.084745 0.009372] [ 0.000000] memory: 0003a000 @ 004d6000 (usable after init) [5.089011 0.004266] [ 0.000000] User-defined physical RAM map: [5.090375 0.001364] [ 0.000000] memory: 04000000 @ 00000000 (usable) [5.101212 0.010837] [ 0.000000] Zone ranges: [5.104268 0.003056] [ 0.000000] Normal [mem 0x00000000-0x03ffffff] [5.108598 0.004330] [ 0.000000] Movable zone start for each node [5.111758 0.003160] [ 0.000000] Early memory node ranges [5.114351 0.002593] [ 0.000000] node 0: [mem 0x00000000-0x03ffffff] [5.117900 0.003549] [ 0.000000] Primary instruction cache 32kB, 8-way, VIPT, linesize 32 bytes. [5.122933 0.005033] [ 0.000000] Primary data cache 32kB, 8-way, VIPT, no aliases, linesize 32 bytes [5.133906 0.010973] [ 0.000000] pls check processor_id[0x00d00100],sc_jz not support! [5.140330 0.006424] [ 0.000000] MIPS secondary cache 128kB, 8-way, linesize 32 bytes. [5.142937 0.002607] [ 0.000000] Built 1 zonelists in Zone order, mobility grouping off. Total pages: 16256 [5.152957 0.010020] [ 0.000000] Kernel command line: console=ttyS1,115200n8 mem=64M@0x0 rmem=64M@0x4000000 init=/linuxrc rootfstype=squashfs root=/dev/mtdblock2 rw mtdparts=jz_sfc:256k(boot),2560k(kernel),2048k(root),-(appfs) [5.166790 0.013833] [ 0.000000] PID hash table entries: 256 (order: -2, 1024 bytes) [5.180155 0.013365] [ 0.000000] Dentry cache hash table entries: 8192 (order: 3, 32768 bytes) [5.198194 0.018039] [ 0.000000] Inode-cache hash table entries: 4096 (order: 2, 16384 bytes) [5.200575 0.002381] [ 0.000000] Memory: 59348k/65536k available (3725k kernel code, 6188k reserved, 1159k data, 232k init, 0k highmem) [5.208249 0.007674] [ 0.000000] SLUB: HWalign=32, Order=0-3, MinObjects=0, CPUs=1, Nodes=1 [5.212882 0.004633] [ 0.000000] Preemptible hierarchical RCU implementation. [5.224592 0.011710] [ 0.000000] NR_IRQS:358 [5.225348 0.000756] [ 0.000000] clockevents_config_and_register success. [5.231782 0.006434] [ 0.000015] Calibrating delay loop… 1391.00 BogoMIPS (lpj=6955008) [5.325370 0.093588] [ 0.087833] pid_max: default: 32768 minimum: 301 [5.326416 0.001046] [ 0.092690] Mount-cache hash table entries: 512 [5.327428 0.001012] [ 0.097609] Initializing cgroup subsys debug [5.330170 0.002742] [ 0.101865] Initializing cgroup subsys freezer [5.333264 0.003094] [ 0.107990] regulator-dummy: no parameters [5.336119 0.002855] [ 0.112176] NET: Registered protocol family 16 [5.343001 0.006882] [ 0.126327] bio: create slab at 0 [5.345948 0.002947] [ 0.131768] jz-dma jz-dma: JZ SoC DMA initialized [5.350144 0.004196] [ 0.136747] usbcore: registered new interface driver usbfs [5.370583 0.020439] [ 0.142258] usbcore: registered new interface driver hub [5.372329 0.001746] [ 0.147730] usbcore: registered new device driver usb [5.377694 0.005365] [ 0.152884] (null): set:311 hold:312 dev=125000000 h=625 l=625 [5.383138 0.005444] [ 0.159011] (null): set:311 hold:312 dev=125000000 h=625 l=625 [5.388048 0.004910] [ 0.165096] media: Linux media interface: v0.10 [5.391335 0.003287] [ 0.169640] Linux video capture interface: v2.00 [5.394632 0.003297] [ 0.175664] Switching to clocksource jz_clocksource [5.404496 0.009864] [ 0.180979] jz-dwc2 jz-dwc2: cgu clk gate get error [5.412668 0.008172] [ 0.185924] cfg80211: Calling CRDA to update world regulatory domain [5.416636 0.003968] [ 0.192352] DWC IN OTG MODE [5.417566 0.000930] [ 0.195743] dwc2 dwc2: Keep PHY ON [5.418384 0.000818] [ 0.199107] dwc2 dwc2: Using Buffer DMA mode [5.419686 0.001302] [ 0.203455] dwc2 dwc2: Core Release: 3.00a [5.426345 0.006659] [ 0.207624] dwc2 dwc2: DesignWare USB2.0 High-Speed Host Controller [5.431616 0.005271] [ 0.213964] dwc2 dwc2: new USB bus registered, assigned bus number 1 [5.436783 0.005167] [ 0.221009] hub 1-0:1.0: USB hub found [5.439418 0.002635] [ 0.224746] hub 1-0:1.0: 1 port detected [5.442272 0.002854] [ 0.228784] dwc2 dwc2: DWC2 Host Initialized [5.459832 0.017560] [ 0.233220] NET: Registered protocol family 2 [5.462078 0.002246] [ 0.237950] TCP established hash table entries: 512 (order: 0, 4096 bytes) [5.463701 0.001623] [ 0.244900] TCP bind hash table entries: 512 (order: -1, 2048 bytes) [5.471104 0.007403] [ 0.251310] TCP: Hash tables configured (established 512 bind 512) [5.475601 0.004497] [ 0.257602] TCP: reno registered [5.478092 0.002491] [ 0.260849] UDP hash table entries: 256 (order: 0, 4096 bytes) [5.482958 0.004866] [ 0.266756] UDP-Lite hash table entries: 256 (order: 0, 4096 bytes) [5.496259 0.013301] [ 0.273297] NET: Registered protocol family 1 [5.504203 0.007944] [ 0.277864] RPC: Registered named UNIX socket transport module. [5.507066 0.002863] [ 0.283842] RPC: Registered udp transport module. [5.511989 0.004923] [ 0.288558] RPC: Registered tcp transport module. [5.516447 0.004458] [ 0.293335] RPC: Registered tcp NFSv4.1 backchannel transport module. [5.521667 0.005220] [ 0.300128] freq_udelay_jiffys[0].max_num = 10 [5.524956 0.003289] [ 0.304579] cpufreq udelay loops_per_jiffy [5.528034 0.003078] [ 0.308975] dwc2 dwc2: ID PIN CHANGED! [5.530630 0.002596] [ 0.312818] 12000 59956 59956 [5.540307 0.009677] [ 0.316030] 24000 119913 119913 [5.541416 0.001109] [ 0.319474] 60000 299784 299784 [5.553303 0.011887] [ 0.322999] 120000 599569 599569 [5.554166 0.000863] [ 0.326451] 200000 999282 999282 [5.555072 0.000906] [ 0.329982] 300000 1498924 1498924 [5.557937 0.002865] [ 0.333761] 600000 2997848 2997848 [5.560842 0.002905] [ 0.337398] 792000 3957159 3957159 [5.564057 0.003215] [ 0.341123] 1008000 5036385 5036385 [5.566700 0.002643] [ 0.344903] 1200000 5995696 5995696 [5.570476 0.003776] [ 0.352364] squashfs: version 4.0 (2009/01/31) Phillip Lougher [5.575066 0.004590] [ 0.358849] jffs2: version 2.2. 2001-2006 Red Hat, Inc. [5.578886 0.003820] [ 0.364662] msgmni has been set to 115 [5.590305 0.011419] [ 0.369298] io scheduler noop registered [5.604923 0.014618] [ 0.373300] io scheduler cfq registered (default) [5.606081 0.001158] [ 0.379054] jz-uart.1: ttyS1 at MMIO 0x10031000 (irq = 58) is a uart1 [5.607572 0.001491] [ 0.386659] console [ttyS1] enabled, bootconsole disabled [5.612116 0.004544] [ 0.386659] console [ttyS1] enabled, bootconsole disabled [5.616029 0.003913] [ 0.400310] brd: module loaded [5.618991 0.002962] [ 0.404935] loop: module loaded [5.621870 0.002879] [ 0.408600] zram: Created 2 device(s) … [5.632080 0.010210] [ 0.412898] logger: created 256K log ‘log_main’ [5.633492 0.001412] [ 0.417978] jz TCU driver register completed [5.651334 0.017842] [ 0.422835] the id code = c22018, the flash name is MX25L12835F [5.656764 0.005430] [ 0.428948] JZ SFC Controller for SFC channel 0 driver register [5.661173 0.004409] [ 0.435107] 4 cmdlinepart partitions found on MTD device jz_sfc [5.665523 0.004350] [ 0.441224] Creating 4 MTD partitions on “jz_sfc”: [5.669280 0.003757] [ 0.446167] 0x000000000000-0x000000040000 : “boot” [5.680363 0.011083] [ 0.451529] 0x000000040000-0x0000002c0000 : “kernel” [5.681900 0.001537] [ 0.456982] 0x0000002c0000-0x0000004c0000 : “root” [5.688680 0.006780] [ 0.462323] 0x0000004c0000-0x000001000000 : “appfs” [5.690292 0.001612] [ 0.467694] SPI NOR MTD LOAD OK [5.700816 0.010524] [ 0.471022] tun: Universal TUN/TAP device driver, 1.6 [5.702038 0.001222] [ 0.476233] tun: © 1999-2004 Max Krasnyansky maxk@qualcomm.com [5.703486 0.001448] [ 0.482695] Bus Mode Reg after reset: 0x00020101, cnt=0 [5.706887 0.003401] [ 0.491226] libphy: jz_mii_bus: probed [5.709818 0.002931] [ 0.495152] =>gmacdev = 0x805f0c00<========== [5.713758 0.003940] [ 0.500758] =========>gmacdev->MacBase = 0xb34b0000 DmaBase = 0xb34b1000 [5.774486 0.060728] [ 0.507672] Bus Mode Reg after reset: 0x00020101, cnt=0 [5.776192 0.001706] [ 0.514480] jz_mac jz_mac.0: JZ on-chip Ethernet MAC driver, Version 1.0 [5.778539 0.002347] [ 0.521553] usbcore: registered new interface driver zd1201 [5.780500 0.001961] [ 0.527507] jzmmc_v1.2 jzmmc_v1.2.0: vmmc regulator missing [5.782498 0.001998] [ 0.540575] jzmmc_v1.2 jzmmc_v1.2.0: card inserted, state=0 [5.784258 0.001760] [ 0.570561] jzmmc_v1.2 jzmmc_v1.2.0: register success! [5.813101 0.028843] [ 0.576081] TCP: cubic registered [5.813902 0.000801] [ 0.579501] NET: Registered protocol family 17 [5.814956 0.001054] [ 0.584726] input: gpio-keys as /devices/platform/gpio-keys/input/input0 [5.823069 0.008113] [ 0.591836] drivers/rtc/hctosys.c: unable to open rtc device (rtc0) [5.825226 0.002157] [ 0.601942] VFS: Mounted root (squashfs filesystem) readonly on device 31:2. [5.827607 0.002381] [ 0.609544] Freeing unused kernel memory: 232K (804d6000 - 80510000) [6.097730 0.270123] script start now … [6.177770 0.080040] mdev is ok… [7.775538 1.597768] script start end … [7.887567 0.112029] [7.887626 0.000059] Ingenic-uc1_1 login: 由上述打印可知，mini配置的busybox init进程启动到脚本开始执行耗时=6.097730-5.827607=0.270123秒，相较于正常配置0.300282秒缩短了0.030159秒

Init进程工作分析： 直接贴代码：

int init_main(int argc UNUSED_PARAM, char **argv) { message(L_LOG | L_CONSOLE, "init main start..."); if (argv[1] && strcmp(argv[1], "-q") == 0) { return kill(1, SIGHUP); }/* 参数解析*/ #if DEBUG_SEGV_HANDLER { struct sigaction sa; memset(&sa, 0, sizeof(sa)); sa.sa_sigaction = handle_sigsegv; sa.sa_flags = SA_SIGINFO; sigaction(SIGSEGV, &sa, NULL); sigaction(SIGILL, &sa, NULL); sigaction(SIGFPE, &sa, NULL); sigaction(SIGBUS, &sa, NULL); } #endif message(L_LOG | L_CONSOLE, "DEBUG_INIT 1..."); if (!DEBUG_INIT) { /* Expect to be invoked as init with PID=1 or be invoked as linuxrc */ if (getpid() != 1 && (!ENABLE_FEATURE_INITRD || applet_name[0] != 'l') /* not linuxrc? */ ) { bb_error_msg_and_die("must be run as PID 1"); } #ifdef RB_DISABLE_CAD /* Turn off rebooting via CTL-ALT-DEL - we get a * SIGINT on CAD so we can shut things down gracefully... */ reboot(RB_DISABLE_CAD); /* misnomer */ #endif } message(L_LOG | L_CONSOLE, "DEBUG_INIT 1 end..."); /* If, say, xmalloc would ever die, we don't want to oops kernel * by exiting. * NB: we set die_sleep *after* PID 1 check and bb_show_usage. * Otherwise, for example, "init u" ("please rexec yourself" * command for sysvinit) will show help text (which isn't too bad), * *and sleep forever* (which is bad!) */ die_sleep = 30 * 24*60*60; /* Figure out where the default console should be */ message(L_LOG | L_CONSOLE, "console init..."); console_init(); /*控制台初始化，指定标准输入，标准输出，标准错误*/ set_sane_term(); xchdir("/"); setsid(); message(L_LOG | L_CONSOLE, "console init end..."); /* Make sure environs is set to something sane */ putenv((char *) "HOME=/"); /* 环境变量设置*/ putenv((char *) bb_PATH_root_path); putenv((char *) "SHELL=/bin/sh"); putenv((char *) "USER=root"); /* needed? why? */ if (argv[1]) xsetenv("RUNLEVEL", argv[1]); #if !ENABLE_FEATURE_EXTRA_QUIET /* Hello world */ message(L_CONSOLE | L_LOG, "init started: %s", bb_banner); #endif #if 0 /* It's 2013, does anyone really still depend on this? */ /* If you do, consider adding swapon to sysinot actions then! */ /* struct sysinfo is linux-specific */ #ifdef __linux__ /* Make sure there is enough memory to do something useful. */ /*if (ENABLE_SWAPONOFF) - WRONG: we may have non-bbox swapon*/ { struct sysinfo info; if (sysinfo(&info) == 0 && (info.mem_unit ? info.mem_unit : 1) * (long long)info.totalram < 1024*1024 ) { message(L_CONSOLE, "Low memory, forcing swapon"); /* swapon -a requires /proc typically */ new_init_action(SYSINIT, "mount -t proc proc /proc", ""); /* Try to turn on swap */ new_init_action(SYSINIT, "swapon -a", ""); run_actions(SYSINIT); /* wait and removing */ } } #endif #endif /* Check if we are supposed to be in single user mode */ message(L_LOG | L_CONSOLE, "parse inittab..."); if (argv[1] && (strcmp(argv[1], "single") == 0 || strcmp(argv[1], "-s") == 0 || LONE_CHAR(argv[1], '1')) ) { /* ??? shouldn't we set RUNLEVEL="b" here? */ /* Start a shell on console */ new_init_action(RESPAWN, bb_default_login_shell, ""); } else { /* Not in single user mode - see what inittab says */ /* NOTE that if CONFIG_FEATURE_USE_INITTAB is NOT defined, * then parse_inittab() simply adds in some default * actions (i.e., INIT_SCRIPT and a pair * of "askfirst" shells) */ parse_inittab(); /* 解析inittab文件*/ } message(L_LOG | L_CONSOLE, "parse inittab end..."); #if ENABLE_SELINUX if (getenv("SELINUX_INIT") == NULL) { int enforce = 0; putenv((char*)"SELINUX_INIT=YES"); if (selinux_init_load_policy(&enforce) == 0) { BB_EXECVP(argv[0], argv); } else if (enforce > 0) { /* SELinux in enforcing mode but load_policy failed */ message(L_CONSOLE, "can't load SELinux Policy. " "Machine is in enforcing mode. Halting now."); return EXIT_FAILURE; } } #endif /* Make the command line just say "init" - thats all, nothing else */ strncpy(argv[0], "init", strlen(argv[0])); /* Wipe argv[1]-argv[N] so they don't clutter the ps listing */ while (*++argv) nuke_str(*argv); /* Set up signal handlers */ message(L_LOG | L_CONSOLE, "setup signal..."); if (!DEBUG_INIT) { struct sigaction sa; bb_signals(0 + (1 << SIGPWR) /* halt */ + (1 << SIGUSR1) /* halt */ + (1 << SIGTERM) /* reboot */ + (1 << SIGUSR2) /* poweroff */ , halt_reboot_pwoff); signal(SIGQUIT, restart_handler); /* re-exec another init */ /* Stop handler must allow only SIGCONT inside itself */ memset(&sa, 0, sizeof(sa)); sigfillset(&sa.sa_mask); sigdelset(&sa.sa_mask, SIGCONT); sa.sa_handler = stop_handler; /* NB: sa_flags doesn't have SA_RESTART. * It must be able to interrupt wait(). */ sigaction_set(SIGTSTP, &sa); /* pause */ /* Does not work as intended, at least in 2.6.20. * SIGSTOP is simply ignored by init: */ sigaction_set(SIGSTOP, &sa); /* pause */ /* SIGINT (Ctrl-Alt-Del) must interrupt wait(), * setting handler without SA_RESTART flag. */ bb_signals_recursive_norestart((1 << SIGINT), record_signo); }/* 设置信号量处理函数*/ message(L_LOG | L_CONSOLE, "setup signal end..."); /* Set up "reread /etc/inittab" handler. * Handler is set up without SA_RESTART, it will interrupt syscalls. */ if (!DEBUG_INIT && ENABLE_FEATURE_USE_INITTAB) bb_signals_recursive_norestart((1 << SIGHUP), record_signo); /* Now run everything that needs to be run */ /* First run the sysinit command */ message(L_LOG | L_CONSOLE, "SYSINIT..."); run_actions(SYSINIT); /* 执行SYSINIT 中的所有action*/ check_delayed_sigs(); /* Next run anything that wants to block */ message(L_LOG | L_CONSOLE, "WAIT..."); run_actions(WAIT); /* 执行WAIT 中的所有action*/ check_delayed_sigs(); /* Next run anything to be run only once */ message(L_LOG | L_CONSOLE, "ONCE..."); run_actions(ONCE); /* 执行ONCE中的所有action*/ /* Now run the looping stuff for the rest of forever. */ message(L_LOG | L_CONSOLE, "while forever..."); while (1) { int maybe_WNOHANG; maybe_WNOHANG = check_delayed_sigs(); /* (Re)run the respawn/askfirst stuff */ run_actions(RESPAWN | ASKFIRST); maybe_WNOHANG |= check_delayed_sigs(); /* Don't consume all CPU time - sleep a bit */ sleep(1); maybe_WNOHANG |= check_delayed_sigs(); /* Wait for any child process(es) to exit. * * If check_delayed_sigs above reported that a signal * was caught, wait will be nonblocking. This ensures * that if SIGHUP has reloaded inittab, respawn and askfirst * actions will not be delayed until next child death. */ if (maybe_WNOHANG) maybe_WNOHANG = WNOHANG; while (1) { pid_t wpid; struct init_action *a; /* If signals happen _in_ the wait, they interrupt it, * bb_signals_recursive_norestart set them up that way */ wpid = waitpid(-1, NULL, maybe_WNOHANG); if (wpid <= 0) break; a = mark_terminated(wpid); if (a) { message(L_LOG, "process '%s' (pid %d) exited. " "Scheduling for restart.", a->command, wpid); } /* See if anyone else is waiting to be reaped */ maybe_WNOHANG = WNOHANG; } } /* while (1) */ }

此部分代码执行耗时时间很短，主要是内核调用init进程消耗时间比较长（耗时0.212973秒），启动打印如下： [5.804647 0.007388] [ 0.609620] Freeing unused kernel memory: 232K (804d6000 - 80510000) [6.017620 0.212973] init main start… [6.018137 0.000517] DEBUG_INIT 1… [6.018512 0.000375] DEBUG_INIT 1 end… [6.044334 0.025822] console init… [6.045223 0.000889] console init end… [6.046536 0.001313] parse inittab… [6.053362 0.006826] parse inittab end… [6.054837 0.001475] setup signal… [6.055761 0.000924] setup signal end… [6.056878 0.001117] SYSINIT… [6.091618 0.034740] script start now … [6.171507 0.079889] mdev is ok… [7.800492 1.628985] script start end … [7.801103 0.000611] WAIT… [7.801383 0.000280] ONCE… [7.801607 0.000224] while forever… [7.912563 0.110956] [7.912644 0.000081] Ingenic-uc1_1 login:

init进程开始之后各部分耗时时间可以通过bootchat图表展示出来，通过在内核命令行bootargs中添加init=/sbin/bootchartd即可，之后系统启动之后，在/var/log/bootlog.tgz文件即可进行查看（笔者第一次系统启动之后并没有生成bootlog.tgz文件，因为tar命令没有-z选项，bootchart中使用压缩命令tar -zcf进行的文件压缩，所以笔者修改了busybox中的bootchart代码中的压缩指令（bootchart_main函数），改成了tar -cf就可以了，然后替换原先的busybox重新生成新文件系统，在烧录进系统文件系统分区中重启系统即可即可），将此文件拷贝到ubuntu机器上面通过运行：./pybootchartgui.py /mnt/hgfs/VMware-shared/bootlog.tgz即可产生图标（由于是busybox产生的log，不能用ubuntu系统中的pybootchartgui.py生成图标，需要下载git clone https://github.com/xrmx/bootchart.git，在这之前也要：sudo apt-get install bootchart），如下所示（本人感觉这个图标没什么意思）：

驱动优化

精细化内核各部分启动时间，并形成图 需要在内核命令行中添加initcall_debug loglevel=8，之后重启内核，进入文件系统之后，dmesg > bootlog.txt，将bootlog.txt拷贝到主机的kernel目录下，执行：cat bootlog.txt | perl scripts/bootgraph.pl > boot.svg 在浏览器中查看boot.svg 如下： 可以看到内核启动过程中，耗时最长的为：dwc2_jz_init，inet_init，init_clk_proc，jz_efuse_init，jz_sfc_init，jz_mac_init，jzmmc_init。 此处可根据具体系统需求来决定是否保留或者裁去，如果保留的话，可以考虑是否可以优化，或者将驱动拿出来不在内核中加载而在脚本中进行加载，不耽误系统启动时间。

除了上述的usb驱动，mmc驱动耗时之外（系统需要usb和SD，无法去除），还有WIFI驱动，ISP驱动（400ms左右），AUDIO驱动（400ms左右）也比较消耗时间，下面开始重点研究上述驱动如何进行优化 （1） 内核initcall延时加载 参考如下介绍，针对于linux 内核版本3.10,2.6.26（27,28）

Deferred_initcall介绍和使用： https://elinux.org/Deferred_Initcalls （2） 音频驱动优化 寄存器的每一步配置都会延时10ms，这大大增加了CODEC驱动加载流程，而且录放音流程里面每次启动也需要消耗几百毫秒的时间（测试发现录音流程使能消耗0.458264秒，放音流程使能消耗0.244484秒，将延时从10ms减少到20us之后，再次测试发现录音流程耗时0.008839秒，放音流程耗时0.019310，大大减少了应用程序的启动时间），同理，CODEC的POWER-UP流程之中把延时都配置为20us，也缩短了加载驱动的时间（正常加载驱动耗时0.409308秒，缩短时间之后为0.253209秒）

未完待续。。。。。。