N516 bootchart
Analysis of boot log.
Pre-bootloader
Can't really do anything here. 0.2s
22:47:36.394225356 O: NAND Secondary Program Loader 22:47:36.399734437 O: 22:47:36.584854062 O: Starting U-Boot ... 22:47:36.586644443 O: 22:47:36.588659154 O:
Bootloader
8.2s! That's quite long.
- 3.36s Screen initialization
- 1.77s UBI initialization
- 1.08s Kernel load / decompression / boot
- 0.94s Bootsplash load / display
- 1.05s Various
22:47:36.591169320 O: U-Boot 2009.03 (Oct 07 2009 - 12:53:14) 22:47:36.592952647 O: 22:47:36.600527214 O: Board: Hanvon n516 e-book (CPU Speed 336 MHz) 22:47:36.604431831 O: DRAM: 64 MB 22:47:36.613778061 O: Flash: 0 kB 22:47:36.645120453 O: NAND: 512 MiB 22:47:36.650142321 O: NAND initialized 22:47:36.652417400 O: env_relocate[233] offset = 0x3df8000 22:47:36.660553420 O: env_relocate[251] malloced ENV at 83cd9190 22:47:36.843796397 O: env relocated 22:47:37.412369633 O: Creating 1 MTD partitions on "NAND 512MiB 3,3V 8-bit": 22:47:37.417731348 O: 0x00100000-0x20000000 : "mtd=1" 22:47:37.423616385 O: UBI: attaching mtd0 to ubi0 22:47:37.432066272 O: UBI: physical eraseblock size: 131072 bytes (128 KiB) 22:47:37.446550866 O: UBI: logical eraseblock size: 129024 bytes 22:47:37.451808938 O: UBI: smallest flash I/O unit: 2048 22:47:37.459616077 O: UBI: sub-page size: 512 22:47:37.467651876 O: UBI: VID header offset: 512 (aligned 512) 22:47:37.472952690 O: UBI: data offset: 2048 22:47:39.104424083 O: UBI: attached mtd0 to ubi0 22:47:39.110067537 O: UBI: MTD device name: "mtd=1" 22:47:39.119567000 O: UBI: MTD device size: 2211149572 MiB 22:47:39.124884086 O: UBI: number of good PEBs: 4086 22:47:39.132157916 O: UBI: number of bad PEBs: 2 22:47:39.142593111 O: UBI: max. allowed volumes: 128 22:47:39.148071111 O: UBI: wear-leveling threshold: 4096 22:47:39.153370039 O: UBI: number of internal volumes: 1 22:47:39.158864802 O: UBI: number of user volumes: 6 22:47:39.166016548 O: UBI: available PEBs: 6 22:47:39.171529959 O: UBI: total number of reserved PEBs: 4080 22:47:39.183289833 O: UBI: number of PEBs reserved for bad PEB handling: 40 22:47:39.188801008 O: UBI: max/mean erase counter: 57/6 22:47:39.200265663 O: Volume waveforms found at volume id 1 22:47:39.205617180 O: read 65536 bytes from volume 1 to 83cf95a0(buf address) - screen flickers, initialization 22:47:42.563954756 O: devices initialized 22:47:42.569498338 O: In: serial 22:47:42.575914029 O: Out: serial 22:47:42.581627884 O: Err: lcd 22:47:42.586761009 O: console initialized 22:47:42.591986603 O: Initialization of MMC 22:47:42.594239683 O: JZ_MMC: 0 22:47:42.596318928 O: Hit any key to stop autoboot: 0 22:47:42.763960203 O: Volume bootsplash found at volume id 2 22:47:42.772096293 O: read 0 bytes from volume 2 to 80600000(buf address) 22:47:42.779119882 O: Read [516096] bytes -- bootsplash appears 22:47:43.699924900 O: Volume kernel found at volume id 4 22:47:43.708142005 O: read 0 bytes from volume 4 to 80600000(buf address) 22:47:43.713330862 O: Read [3225600] bytes 22:47:44.167947727 O: ## Booting kernel from Legacy Image at 80600000 ... 22:47:44.175661766 O: Image Name: Linux-2.6.29-n516 22:47:44.187683545 O: Image Type: MIPS Linux Kernel Image (gzip compressed) 22:47:44.193940764 O: Data Size: 1801496 Bytes = 1.7 MB 22:47:44.205092949 O: Load Address: 80010000 22:47:44.210265395 O: Entry Point: 800144b0 22:47:44.272277467 O: Verifying Checksum ... OK 22:47:44.776658885 O: Uncompressing Kernel Image ... OK 22:47:44.778372161 O:
Kernel
Tolerable. 3.43s here.
- 1.81s UBI initialization
- 0.24s NAND initialization
- 0.21s UBIFS mount
- 1.17s Various
22:47:44.783393888 O: Starting kernel ... 22:47:44.788548384 O: 22:47:44.831673911 O: [ 0.000000] Linux version 2.6.29-n516 (pbuilder@ab) (gcc version 4.3.2 (Debian 4.3.2-1.ip2) ) #1 Mon Nov 16 04:11:15 UTC 2009 22:47:44.840172827 O: [ 0.000000] CPU revision is: 0ad0024f (Ingenic JZRISC) 22:47:44.859614196 O: [ 0.000000] CPU clock: 336MHz, System clock: 112MHz, Peripheral clock: 112MHz, Memory clock: 112MHz 22:47:44.865543092 O: [ 0.000000] JZ4740 N516 board setup 22:47:44.879758726 O: [ 0.000000] Determined physical RAM map: 22:47:44.887775178 O: [ 0.000000] memory: 04000000 @ 00000000 (usable) 22:47:44.893049801 O: [ 0.000000] User-defined physical RAM map: 22:47:44.899748139 O: [ 0.000000] memory: 04000000 @ 00000000 (usable) 22:47:44.905216083 O: [ 0.000000] Zone PFN ranges: 22:47:44.913387373 O: [ 0.000000] DMA 0x00000000 -> 0x00001000 22:47:44.924593057 O: [ 0.000000] Normal 0x00001000 -> 0x00004000 22:47:44.929658855 O: [ 0.000000] Movable zone start PFN for each node 22:47:44.941264173 O: [ 0.000000] early_node_map[1] active PFN ranges 22:47:44.951127439 O: [ 0.000000] 0: 0x00000000 -> 0x00004000 22:47:44.971647648 O: [ 0.000000] Built 1 zonelists in Zone order, mobility grouping on. Total pages: 16256 22:47:45.010239917 O: [ 0.000000] Kernel command line: mem=64M console=ttyS0,57600n8 ip=off rootfstype=ubifs root=ubi:rootfs ubi.mtd=UBI rw mtdparts=jz4740-nand:1M@0(uboot)ro,-@1M(UBI) n516-lpc.batt_level=6 22:47:45.016095481 O: [ 0.000000] Primary instruction cache 16kB, VIPT, 4-way, linesize 32 bytes. 22:47:45.031700957 O: [ 0.000000] Primary data cache 16kB, 4-way, VIPT, no aliases, linesize 32 bytes 22:47:45.046344019 O: [ 0.000000] PID hash table entries: 256 (order: 8, 1024 bytes) 22:47:45.051944941 O: [42949372.970000] Console: colour dummy device 80x25 22:47:45.057800853 O: [42949372.970000] console [ttyS0] enabled 22:47:45.075800907 O: [42949372.980000] Dentry cache hash table entries: 8192 (order: 3, 32768 bytes) 22:47:45.084090508 O: [42949372.990000] Inode-cache hash table entries: 4096 (order: 2, 16384 bytes) 22:47:45.120247478 O: [42949373.020000] Memory: 60684k/65536k available (3032k kernel code, 4832k reserved, 773k data, 136k init, 0k highmem) 22:47:45.360149248 O: [42949373.030000] Calibrating delay loop... 335.05 BogoMIPS (lpj=1675264) 22:47:45.372006761 O: [42949373.270000] Mount-cache hash table entries: 512 22:47:45.393897184 O: [42949373.300000] net_namespace: 296 bytes 22:47:45.404385389 O: [42949373.310000] NET: Registered protocol family 16 22:47:45.452259984 O: [42949373.350000] bio: create slab <bio-0> at 0 22:47:45.481499947 O: [42949373.380000] NET: Registered protocol family 2 22:47:45.496328789 O: [42949373.390000] IP route cache hash table entries: 1024 (order: 0, 4096 bytes) 22:47:45.509149344 O: [42949373.400000] TCP established hash table entries: 2048 (order: 2, 16384 bytes) 22:47:45.527660916 O: [42949373.410000] TCP bind hash table entries: 2048 (order: 1, 8192 bytes) 22:47:45.536153407 O: [42949373.420000] TCP: Hash tables configured (established 2048 bind 2048) 22:47:45.544229853 O: [42949373.430000] TCP reno registered 22:47:45.551670254 O: [42949373.430000] NET: Registered protocol family 1 22:47:45.567813577 O: [42949373.440000] Total 4MB memory at 0x3000000 was reserved for IPU 22:47:45.575619668 O: [42949373.450000] Power Management for JZ 22:47:45.588108895 O: [42949373.460000] msgmni has been set to 118 22:47:45.610082288 O: [42949373.480000] alg: No test for stdrng (krng) 22:47:45.615577051 O: [42949373.490000] io scheduler noop registered 22:47:45.631650043 O: [42949373.500000] io scheduler anticipatory registered (default) 22:47:45.637196487 O: [42949373.510000] io scheduler deadline registered 22:47:45.644128514 O: [42949373.520000] io scheduler cfq registered 22:47:45.720183495 O: [42949373.590000] Serial: 8250/16550 driver, 2 ports, IRQ sharing disabled 22:47:45.735639161 O: [42949373.600000] serial8250: ttyS0 at MMIO 0x0 (irq = 9) is a 16550A 22:47:45.748195436 O: [42949373.610000] serial8250: ttyS1 at MMIO 0x0 (irq = 8) is a 16550A 22:47:45.767653564 O: [42949373.620000] NAND device: Manufacturer ID: 0x20, Chip ID: 0xdc (ST Micro NAND 512MiB 3,3V 8-bit) 22:47:45.775625666 O: [42949373.630000] Scanning device for bad blocks 22:47:45.887698922 O: [42949373.730000] Bad eraseblock 2697 at 0x000015120000 22:47:45.939839629 O: [42949373.790000] Bad eraseblock 3863 at 0x00001e2e0000 22:47:45.960162047 O: [42949373.810000] 2 cmdlinepart partitions found on MTD device jz4740-nand 22:47:45.971758424 O: [42949373.820000] Creating 2 MTD partitions on "jz4740-nand": 22:47:45.983694161 O: [42949373.830000] 0x000000000000-0x000000100000 : "uboot" 22:47:45.995507395 O: [42949373.840000] 0x000000100000-0x000020000000 : "UBI" 22:47:46.012030446 O: [42949373.860000] UBI: attaching mtd1 to ubi0 22:47:46.023873432 O: [42949373.870000] UBI: physical eraseblock size: 131072 bytes (128 KiB) 22:47:46.039610000 O: [42949373.880000] UBI: logical eraseblock size: 129024 bytes 22:47:46.045579334 O: [42949373.890000] UBI: smallest flash I/O unit: 2048 22:47:46.055701222 O: [42949373.900000] UBI: sub-page size: 512 22:47:46.071567903 O: [42949373.910000] UBI: VID header offset: 512 (aligned 512) 22:47:46.082441841 O: [42949373.920000] UBI: data offset: 2048 22:47:47.691945529 O: [42949375.530000] UBI: attached mtd1 to ubi0 22:47:47.700163752 O: [42949375.540000] UBI: MTD device name: "UBI" 22:47:47.712011696 O: [42949375.550000] UBI: MTD device size: 511 MiB 22:47:47.728304690 O: [42949375.560000] UBI: number of good PEBs: 4086 22:47:47.733658583 O: [42949375.570000] UBI: number of bad PEBs: 2 22:47:47.739358959 O: [42949375.580000] UBI: max. allowed volumes: 128 22:47:47.751655216 O: [42949375.590000] UBI: wear-leveling threshold: 256 22:47:47.760052093 O: [42949375.600000] UBI: number of internal volumes: 1 22:47:47.768101929 O: [42949375.610000] UBI: number of user volumes: 6 22:47:47.779716535 O: [42949375.620000] UBI: available PEBs: 6 22:47:47.788182207 O: [42949375.630000] UBI: total number of reserved PEBs: 4080 22:47:47.803723150 O: [42949375.640000] UBI: number of PEBs reserved for bad PEB handling: 40 22:47:47.809335176 O: [42949375.650000] UBI: max/mean erase counter: 57/6 22:47:47.823645446 O: [42949375.660000] UBI: background thread "ubi_bgt0d" started, PID 220 22:47:47.836190826 O: [42949375.670000] jz-rtc jz-rtc: rtc core: registered jz as rtc0 22:47:47.843625571 O: [42949375.680000] JzSOC onchip RTC has been installed 22:47:47.860199047 O: [42949375.690000] jz_i2c jz_i2c.0: JZ47xx i2c bus driver. 22:47:47.865441822 O: [42949375.700000] n516_lpc_probe 22:47:47.880094035 O: [42949375.710000] input: n516-keys as /class/input/input0 22:47:47.896205022 O: [42949375.720000] JzSOC Watchdog Timer: timer margin 60 sec 22:47:47.907515957 O: [42949375.740000] JZ SD/MMC card driver registered 22:47:47.928623529 O: [42949375.760000] Registered led device: led:blue 22:47:47.946042923 O: [42949375.770000] TCP cubic registered 22:47:47.951442563 O: [42949375.780000] NET: Registered protocol family 17 22:47:47.959582845 O: [42949375.790000] RPC: Registered udp transport module. 22:47:47.968030987 O: [42949375.800000] RPC: Registered tcp transport module. 22:47:47.992114148 O: [42949375.820000] jz-rtc jz-rtc: setting system clock to 1970-01-01 00:00:11 UTC (11) 22:47:48.116222800 O: [42949375.940000] UBIFS: mounted UBI device 0, volume 5, name "rootfs" 22:47:48.136116738 O: [42949375.950000] UBIFS: file system size: 126572544 bytes (123606 KiB, 120 MiB, 981 LEBs) 22:47:48.150462485 O: [42949375.960000] UBIFS: journal size: 9033728 bytes (8822 KiB, 8 MiB, 71 LEBs) 22:47:48.159634950 O: [42949375.970000] UBIFS: media format: 4 (latest is 4) 22:47:48.168161033 O: [42949375.980000] UBIFS: default compressor: lzo 22:47:48.180070088 O: [42949375.990000] UBIFS: reserved for root: 0 bytes (0 KiB) 22:47:48.202238476 O: [42949376.000000] VFS: Mounted root (ubifs filesystem) on device 253:6. 22:47:48.211534490 O: [42949376.020000] Freeing unused kernel memory: 136k freed
Userspace
15s. Big room for improvement here.
- 6.70s GUI apps startup
22:47:48.247705428 O: [42949376.050000] mmc0: new high speed SDHC card at address 3182 22:47:48.271831888 O: [42949376.080000] mmcblk0: mmc0:3182 3g-3g-3g-3g-3g- 7.42 GiB 22:47:48.285901904 O: [42949376.090000] mmcblk0: p1 init started: BusyBox v1.15.2 (2009-10-14 00:57:23 UTC) starting pid 252, tty '': '/etc/init.d/rcS' 22:47:48.930995676 O: esplash: can't open '/dev/fb1': No such file or directory 22:47:48.948180475 O: Starting autosuspend: ok. 22:47:48.991605623 O: esplash: can't open '/dev/fb1': No such file or directory 22:47:49.831126552 O: [42949377.630000] FAT: utf8 is not a recommended IO charset for FAT filesystems, filesystem will be case sensitive! 22:47:49.847830633 O: mount: mounting /dev/mmcblk0 on /media/sd failed: Invalid argument 22:47:49.870099735 O: killall: madshelf: no process killed 22:47:50.019878351 O: [42949377.810000] FAT: utf8 is not a recommended IO charset for FAT filesystems, filesystem will be case sensitive! 22:47:50.495872783 O: killall: madshelf: no process killed 22:47:51.763913542 O: esplash: can't open '/dev/fb1': No such file or directory 22:47:51.769656730 O: Loading kernel modules 22:47:51.780164700 O: lm75 22:47:51.867805804 O: [42949379.660000] lm75 0-0048: hwmon0: sensor 'lm75a' 22:47:51.902011061 O: snd-soc-n516 22:47:52.859857584 O: [42949380.650000] No device for DAI jz4740-i2s 22:47:53.011962049 O: [42949380.800000] No device for DAI JZCODEC 22:47:53.144274053 O: [42949380.930000] asoc: JZCODEC <-> jz4740-i2s mapping ok 22:47:53.211638408 O: jz4740_udc 22:47:53.303895946 O: [42949381.100000] JZ4740 USB Device Controller 22:47:53.312066329 O: [42949381.100000] version: 13-Mar-2008 22:47:53.392253897 O: Done loading modules 22:47:53.515829036 O: esplash: can't open '/dev/fb1': No such file or directory 22:47:53.695760693 O: esplash: can't open '/dev/fb1': No such file or directory 22:47:54.039899613 O: Loading metronomefb module... [42949381.830000] jzlcd use 1 framebuffer: 22:47:54.048056098 O: [42949381.840000] jzlcd fb[0] phys addr =0x03e00000 22:47:54.059539052 O: [42949381.850000] LCDC: PixClock:16000000 LcdClock:42000000 22:47:54.163755649 O: [42949381.950000] fb0: jz-lcd frame buffer device, using 1024K of video memory 22:47:54.244264273 O: [42949382.030000] metronomefb metronomefb: firmware: requesting metronome.wbf 22:47:54.642443026 O: [42949382.430000] metronomefb metronomefb: fb1: Metronome frame buffer device, using 472K of video memory 22:47:54.680186370 O: done. 22:47:54.735773879 O: Starting metronome temperature daemon: metronometempd. 22:47:54.944416179 O: Cleaning up ifupdown...done. 22:47:55.004347407 O: Checking all file systems... 22:47:55.056241157 O: Mounting local filesystems... 22:47:55.103643132 O: [42949382.880000] FAT: utf8 is not a recommended IO charset for FAT filesystems, filesystem will be case sensitive! 22:47:55.367751061 O: Cleaning /tmp /var/run /var/lock. 22:47:55.628418072 O: Setting up networking...done. 22:47:55.727807372 O: Configuring network interfaces 22:47:55.893556026 O: ifconfig: SIOCGIFFLAGS: No such device 22:47:55.941971049 O: ifconfig: SIOCSIFADDR: No such device 22:47:55.964819347 O: route: SIOCADDRT: No such device 22:47:55.968973297 O: failed. 22:47:56.195852829 O: Initializing random number generator... done. 22:47:56.267839557 O: Setting up X server socket directory /tmp/.X11-unix...ok 22:47:56.291625890 O: Setting up ICE socket directory /tmp/.ICE-unix...ok 22:47:56.607979857 O: Starting Dropbear SSH server: dropbear. 22:47:56.640950388 O: Starting nulldm: ok. starting pid 730, tty '': '/bin/sh' 22:47:56.840139730 O: /bin/sh: can't access tty; job control turned off 22:48:03.239951221 O: / # [42949391.010000] PM: Syncing filesystems ... done. 22:48:03.252188531 O: [42949391.030000] Freezing user space processes ... (elapsed 0.00 seconds) done. 22:48:03.323822498 O: [42949391.040000] Freezing remaining freezable tasks ... (elapsed 0.05 seconds) done. 22:48:03.336088024 O: [42949391.110000] Suspending console(s) (use no_console_suspend to debug)
