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

CRAMFS with XIP

ROMFS

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: kfi-results-omap-filesystems.zip

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:

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."