优化系统启动时间
前提（******重点）：
（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);}
#endifmessage(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_SELINUXif (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），如下所示（本人感觉这个图标没什么意思）：

驱动优化

1. 精细化内核各部分启动时间，并形成图
   需要在内核命令行中添加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。
   此处可根据具体系统需求来决定是否保留或者裁去，如果保留的话，可以考虑是否可以优化，或者将驱动拿出来不在内核中加载而在脚本中进行加载，不耽误系统启动时间。

2. 除了上述的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秒）

未完待续。。。。。。