Filesystem Information

Revision as of 21:24, 13 December 2006 by Wmat (Talk | contribs)

Jump to: navigation, search

Boot Time with various file systems

Noboru Wakabayashi of Hitachi provided the following report.

On the OMAP Innovator he built the following file systems:

  • CRAMFS with XIP
  • JFFS2
  • ext2 over RAM disk

He measured the time to initialize these file systems by logic analyzer. This was done by modifying the busybox init program to make LED turn on red. When innovator power on, the LED lights up green. So the time from the light turning from green to red was measured. Also, he measured the time using KFI (from start_kernel() to to_usrspace()).

Results are shown in the following table. (The result is average of 10 trials for each configuration.)

Configuration/Filesystem logic analyzer(sec) KFI(usec)
CRAMFS* 3.638850 842789.1
CRAMFS with XIP 2.788076 764141.3
CRAMFS with XIP and PLPJ 2.583988 551735.5
ROMFS 3.510876 839078.2
JFFS2* 4.822642 1241068.4(log full)
ext2 over RAM disk cannot measure 2952081.6(log full)
  • JFFS2: JFFS2 required much time at first boot time, so he measured from the 2nd starting.
  • CRAMFS: At first, he also measured the time with CONFIG_KFI by logic analyzer. The result is 4.324660 sec. It costs more than without CONFIG_KFI. So, he measured file systems without CONFIG_KFI when he used logic analyzer.

The attached zip file has the kfi logfiles for these different tests: no zip found:

Next he remeasured the time to initialize "CRAMFS with XIP and PLPJ" using the "quiet" option. The result is 280676 usec from start_kernel() to to_userspace(). The above result is 551735.5 usec.The time is reduced about 50%.

The following table shows output from 'kd' on the kfi logfile.

output from 'kd' on the kfi logfile
Function Count Time Average Local Max-sub Ms count
do_basic_setup 1 114068 114068 509 do_initcalls 1
mem_init 1 110376 110376 490 free_all_bootmem_node 1
free_all_bootmem_node 1 109378 109378 12 free_all_bootmem_core 1
free_all_bootmem_core 1 109366 109366 109366 0
schedule 10 84482 8448 34 do_schedule 10
do_schedule 10 84448 8444 574 switch_to 9
do_initcalls 1 84159 84159 3831 device_init 1
switch_to 9 83874 9319 83874 - 0
register_proc_table 22 39161 1780 13079 register_proc_table 18
device_register 11 22297 2027 415 device_add 11
device_add 11 21882 1989 1439 kobject_add 11
device_init 1 20633 20633 30 net_dev_init 1
tifb_init 1 18759 18759 844 register_framebuffer 1
register_framebuffer 1 13092 13092 88 take_over_console 1
take_over_console 1 13004 13004 819 redraw_screen 1
kobject_add 15 12996 866 738 create_dir 15
setup_arch 1 12542 12542 131 paging_init 1
paging_init 1 12411 12411 386 free_area_init_node 1
create_dir 15 12258 817 3625 populate_dir 9
free_area_init_node 1 12025 12025 30 free_area_init_core 1
free_area_init_core 1 11995 11995 7496 __alloc_bootmem_node 1
rs_init 1 11794 11794 377 printk 3
inet_init 1 11696 11696 1718 ip_init 1
redraw_screen 2 11247 5623 871 do_update_region 1
printk 18 10870 603 10870 - 0
net_dev_init 1 10334 10334 3102 ethif_probe 1

Probe times for various file systems

As part of work supported by Sony/Matsushita, Todd Poynor got the following numbers using KFI on a 200MHz IBM 405GP "Walnut" evaluation board with a 100MHz core bus and 33MHz PCI bus. A Seagate Barracuda ATA IV 60GB disk drive is cabled to one of the two IDE interfaces on a Promise Ultra66 PCI-IDE bridge card (PDC20262 chipset). All of the drivers for PCI, IDE, PCI-IDE disk, and EXT2 filesystem are built into the kernel.

Boot execution time of IDE/PCI-IDE/MS-DOS partition drivers: 262 msecs. This includes the time to probe and identify the IDE drive device and read the disk partition information from the drive. We booted the kernel with option hdf=none to turn off the slave device on interface ide2, so that it would not be probed. We also modified the kernel to turn off probes of the second IDE interface on the Promise card. (This was prior to fixing the "ide<x>=noprobe" option bug. If you don't turn off probing the second empty IDE interface then probling takes 1.3 seconds on both a PPC 405GP and a MIPS ITE8172!)

About 250 msecs of the time is spent during the bus probe in repeated calls to ide_delay_50ms() during probe and drive identification, which busywaits (in order to let the IDE controller make progress before polling for status or to allow previous operations to complete). Reading capacity info, etc. also blocks using a wait_for_completion(). The MSDOS partition code also locks pages, which can call schedule() to wait for locks.

If the IDE drivers are made modules for delayed initialization, allowing concurrent module initialization with application execution, then kernel preemption is turned off for about 252 msecs during init of the ide-probe-mod module, which could significantly interfere with real-time response of other threads. (This was verified using the CONFIG_PREEMPT_TIMES feature that gives preemption lock times in /proc/latencytimes, which is also supported in the CELF kernel.) Because the Big Kernel Lock (BKL) is held during module initialization, preemption is disabled while the module init routines runs and uses busywait calls, but preemption is allowed when CPU-yielding wait calls are employed (the linux scheduler drops and reacquires the BKL in this case).

So we changed the ide_delay_50ms() busywaits to call schedule_timeout() instead (this is also in the CELF kernel; select CONFIG_IDE_PREEMPT), resulting in a 9.68 msec maximum preempt off time. Note that if you're not using modules but are instead building the drivers statically into the kernel, then the CPU-yielding calls do add some amount of time to the total execution time due to context-switch overhead, etc.

My coworker Dave Singleton also did some analysis and improvement of IDE on the MIPS ITE8172 (again for Sony/Matsushita). He found that with his 7200RPM Maxtor drive, he could reduce the 50ms probe delays to 1ms with no problem. With this, plus some context switch removal and the other optimizations given above, the following boot times were observed, by filesystem type:

{{{ ext2: 167 milliseconds ext3: 457 milliseconds xfs: 236 milliseconds }}}

He explains: "Both EXT3 and XFS file systems cause a log replay at boot/mount time. To improve this time the log recovery feature was by passed in the case of XFS. The log was not replayed and the root file system was mounted readonly. The first init script after booting remounted the root file system readwrite and replayed the log to ensure file system integrity. No such changes were made to EXT3, which is the reason it had the slowest boot times of all 3 file system types."