Hi,
I wrote a script that can be used on a host machine to read from the serial port and output timing information on each line received. It also tries to adjust for time spent by the target machine actually generating the serial reports. The script is attached if anyone wants to use it (it requires python and the pyserial package).
The results are interesting.
On my epia-cn machine, it takes coreboot-v2 8.7 seconds to launch SeaBIOS. It looks like about 4 seconds is lost due to a reboot half-way through the startup - I'm guessing a watchdog timer is kicking in. As to why it takes so long to boot - maybe rom caching is off?
SeaBIOS takes 1.5 seconds (from startup to OS launch) - after subtracting the 2.5 seconds spent waiting at the boot menu.
The biggest SeaBIOS time consumers:
500ms - initializing the ps2 port / keyboard
425ms - scanning for option roms
260ms - initializing ATA drives
200ms - running the via vga rom
-Kevin
On Sat, Apr 18, 2009 at 09:14:06PM -0400, Kevin O'Connor wrote:
On my epia-cn machine, it takes coreboot-v2 8.7 seconds to launch SeaBIOS. It looks like about 4 seconds is lost due to a reboot half-way through the startup - I'm guessing a watchdog timer is kicking in. As to why it takes so long to boot - maybe rom caching is off?
Nope - looks like calibrate_tsc is taking 2.9 seconds to calibrate:
00.608: Jumping to coreboot. 00.609: coreboot-2.0.0-epiacn Sat Apr 18 21:34:47 EDT 2009 booting... 00.612: Calibrating delay loop... 03.530: end 12e0a2189, start 292b71b4 03.532: 32-bit delta 4173 03.533: calibrate_tsc 32-bit result is 4173 03.534: clocks_per_usec: 4173 03.536: Enumerating buses...
-Kevin
Kevin O'Connor wrote:
I wrote a script that can be used on a host machine to read from the serial port and output timing information on each line received.
After stty I've used tai64n for this. I then wrote taidelta to show the time difference between tai64n output lines.
http://cr.yp.to/daemontools/tai64n.html
No web for taidelta yet, but I'll give out source.
It also tries to adjust for time spent by the target machine actually generating the serial reports. The script is attached if anyone wants to use it (it requires python and the pyserial package).
I like that it's very simple!
Kevin O'Connor wrote:
Nope - looks like calibrate_tsc is taking 2.9 seconds to calibrate:
Look for a really long option with TSC in the name. It's set for epia-m. We added it in Hamburg to control how to initialize timers. I think you're getting the slower method.
//Peter
On Sat, Apr 18, 2009 at 09:40:56PM -0400, Kevin O'Connor wrote:
On Sat, Apr 18, 2009 at 09:14:06PM -0400, Kevin O'Connor wrote:
On my epia-cn machine, it takes coreboot-v2 8.7 seconds to launch SeaBIOS. It looks like about 4 seconds is lost due to a reboot half-way through the startup - I'm guessing a watchdog timer is kicking in. As to why it takes so long to boot - maybe rom caching is off?
Nope - looks like calibrate_tsc is taking 2.9 seconds to calibrate:
00.608: Jumping to coreboot. 00.609: coreboot-2.0.0-epiacn Sat Apr 18 21:34:47 EDT 2009 booting... 00.612: Calibrating delay loop...
If I add the following to Config.lb:
option CONFIG_TSC_X86RDTSC_CALIBRATE_WITH_TIMER2=1
then the problem goes away - coreboot takes only 1.8 seconds.
The weird thing is that:
default CONFIG_TSC_X86RDTSC_CALIBRATE_WITH_TIMER2 = 1
is already in the epia-cn Options.lb file. Perhaps the 'default' line in src/cpu/x86/tsc/Config.lb is overriding it?
-Kevin (dreams of Kconfig)
On 19.04.2009 04:23, Kevin O'Connor wrote:
On Sat, Apr 18, 2009 at 09:40:56PM -0400, Kevin O'Connor wrote:
On Sat, Apr 18, 2009 at 09:14:06PM -0400, Kevin O'Connor wrote:
On my epia-cn machine, it takes coreboot-v2 8.7 seconds to launch SeaBIOS. It looks like about 4 seconds is lost due to a reboot half-way through the startup - I'm guessing a watchdog timer is kicking in. As to why it takes so long to boot - maybe rom caching is off?
Nope - looks like calibrate_tsc is taking 2.9 seconds to calibrate:
00.608: Jumping to coreboot. 00.609: coreboot-2.0.0-epiacn Sat Apr 18 21:34:47 EDT 2009 booting... 00.612: Calibrating delay loop...
If I add the following to Config.lb:
option CONFIG_TSC_X86RDTSC_CALIBRATE_WITH_TIMER2=1
then the problem goes away - coreboot takes only 1.8 seconds.
Still, 1.8 seconds can surely be trimmed down further. Our early startup code has some variants performing totally nonsensical operations which easily account for 200 ms or more. (One variant does nothing except switch CAR on, fill the cache slowly, switch CAR off again and hope that CAR works although it is switched off.) The big problem here is that early startup is considered magic and the accumulated cruft is legendary.
Regards, Carl-Daniel
On Sun, Apr 19, 2009 at 11:40:07AM +0200, Carl-Daniel Hailfinger wrote:
On 19.04.2009 04:23, Kevin O'Connor wrote:
then the problem goes away - coreboot takes only 1.8 seconds.
Still, 1.8 seconds can surely be trimmed down further. Our early startup code has some variants performing totally nonsensical operations which easily account for 200 ms or more. (One variant does nothing except switch CAR on, fill the cache slowly, switch CAR off again and hope that CAR works although it is switched off.) The big problem here is that early startup is considered magic and the accumulated cruft is legendary.
That was with debugging on. The timing script adjusts the numbers with the cost of waiting for the serial port, but it doesn't account for all the costs of generating the reports.
With debugging off, it looks like coreboot-v2 takes 1.2 seconds. Of that the 400ms for keyboard init looks to be the biggest time consumer. (Yes - both SeaBIOS and coreboot are initializing the keyboard.)
-Kevin
On Sat, Apr 18, 2009 at 09:14:06PM -0400, Kevin O'Connor wrote:
The biggest SeaBIOS time consumers:
[...]
425ms - scanning for option roms
I tracked this one down - it's the cost of CBFS and reading the flash. Of the 425ms, 90ms is spent copying the via vga rom. The remaining time is spent doing CBFS searches - there are 18 pci devices on this machine and for each one SeaBIOS scans CBFS for "pciVVVV,DDDD.rom". Because none of these files were actually present, SeaBIOS ended up walking all the flash freespace each time. All those flash accesses add up.
260ms - initializing ATA drives
I wonder if I can skip the ATA reset on the first boot - the device should have just gone through a hw reset anyway...
-Kevin
On L, 2009-04-18 at 23:05 -0400, Kevin O'Connor wrote:
On Sat, Apr 18, 2009 at 09:14:06PM -0400, Kevin O'Connor wrote:
The biggest SeaBIOS time consumers:
[...]
425ms - scanning for option roms
I tracked this one down - it's the cost of CBFS and reading the flash. Of the 425ms, 90ms is spent copying the via vga rom. The remaining time is spent doing CBFS searches - there are 18 pci devices on this machine and for each one SeaBIOS scans CBFS for "pciVVVV,DDDD.rom". Because none of these files were actually present, SeaBIOS ended up walking all the flash freespace each time. All those flash accesses add up.
Is there no zero-fill with cbfs? With LAR if I don't zero-fill (add a dummy entry to fill up the remaining space, the content is actually 0xFF's despite the term) it will also walk all the flash free space. Observing roughly 1 sec vs 4 sec boot times with and without zero-fill - I need to make a proper measurement, and this kind of tools that you and Peter have written were exactly what I was missing for doing that!
In coreboot-v3 there's a Kconfig option to zero-fill, but as I have to manually add the Geode VSA blob, I have that disabled and do it manually as described in http://www.coreboot.org/Artec_Group_DBE62 However I don't think zero-fill was even the default option in v3.
Maybe you can do zero-fill entry for cbfs too similarly. I believe Carl-Daniel mentioned CBFS doesn't fix that problem either and shares the gotcha with LAR at the moment still.
Regards, Mart Raudsepp
260ms - initializing ATA drives
I wonder if I can skip the ATA reset on the first boot - the device should have just gone through a hw reset anyway...
-Kevin
On 19.04.2009 07:02, Mart Raudsepp wrote:
On L, 2009-04-18 at 23:05 -0400, Kevin O'Connor wrote:
On Sat, Apr 18, 2009 at 09:14:06PM -0400, Kevin O'Connor wrote:
The biggest SeaBIOS time consumers:
[...]
425ms - scanning for option roms
I tracked this one down - it's the cost of CBFS and reading the flash. Of the 425ms, 90ms is spent copying the via vga rom. The remaining time is spent doing CBFS searches - there are 18 pci devices on this machine and for each one SeaBIOS scans CBFS for "pciVVVV,DDDD.rom". Because none of these files were actually present, SeaBIOS ended up walking all the flash freespace each time. All those flash accesses add up.
Is there no zero-fill with cbfs? With LAR if I don't zero-fill (add a dummy entry to fill up the remaining space, the content is actually 0xFF's despite the term) it will also walk all the flash free space. Observing roughly 1 sec vs 4 sec boot times with and without zero-fill - I need to make a proper measurement, and this kind of tools that you and Peter have written were exactly what I was missing for doing that!
In coreboot-v3 there's a Kconfig option to zero-fill, but as I have to manually add the Geode VSA blob, I have that disabled and do it manually as described in http://www.coreboot.org/Artec_Group_DBE62 However I don't think zero-fill was even the default option in v3.
Maybe you can do zero-fill entry for cbfs too similarly.
Not yet.
I believe Carl-Daniel mentioned CBFS doesn't fix that problem either and shares the gotcha with LAR at the moment still.
Replace CBFS with zerofilled LAR and the problem will go away without having to code another feature.
Regards, Carl-Daniel
On 19.04.2009 05:05, Kevin O'Connor wrote:
On Sat, Apr 18, 2009 at 09:14:06PM -0400, Kevin O'Connor wrote:
The biggest SeaBIOS time consumers:
[...]
425ms - scanning for option roms
I tracked this one down - it's the cost of CBFS and reading the flash. Of the 425ms, 90ms is spent copying the via vga rom. The remaining time is spent doing CBFS searches - there are 18 pci devices on this machine and for each one SeaBIOS scans CBFS for "pciVVVV,DDDD.rom". Because none of these files were actually present, SeaBIOS ended up walking all the flash freespace each time. All those flash accesses add up.
And again we see that we'd be better off with LAR instead of CBFS. Every single problem we solved with LAR has to be solved again with CBFS. This time, it's zerofill (the feature which makes sure you don't have to walk all the free space).
260ms - initializing ATA drives
I wonder if I can skip the ATA reset on the first boot - the device should have just gone through a hw reset anyway...
In theory, this can be skipped, but you have to wait until the disks are ready.
Regards, Carl-Daniel
On Sat, 18 Apr 2009, Kevin O'Connor wrote:
[..]
260ms - initializing ATA drives
200ms - running the via vga rom
Does initializing ATA drives include a delay for motor spin-up? If so, perhaps the code could be split: Minimal initialization, start motor. Running the via vga rom. Completion of ATA drive initialiation.
Just a thought. Russ
On Sat, Apr 18, 2009 at 09:21:24PM -0700, Russell Whitaker wrote:
On Sat, 18 Apr 2009, Kevin O'Connor wrote:
260ms - initializing ATA drives
200ms - running the via vga rom
Does initializing ATA drives include a delay for motor spin-up?
SeaBIOS does wait for drives to spinup (it was just recently added). However, the above timings were not limited by drive spinup (in the above, coreboot took so long that the drivers were already ready by the time SeaBIOS ran). On this test machine, drive spinup can take 5+ seconds. Ironically, after fixing the delay that coreboot takes, the overall bootup time hasn't improved, because the delay just moved to spinup. :-) A reset does go much faster though, and the VGA reset is much more prompt.
The 260ms is the cost of issuing an ATA reset command and waiting for the drive to acknowledge it.
If so, perhaps the code could be split: Minimal initialization, start motor. Running the via vga rom. Completion of ATA drive initialiation.
Just a thought.
It's a good idea, but it's complex to implement. One of the gains to putting Linux in the flash is that Linux can do true multithreaded initialization of many of the devices. SeaBIOS doesn't have this infrastructure.
-Kevin
-
Carl-Daniel Hailfinger -
Kevin O'Connor -
Mart Raudsepp -
Peter Stuge -
Russell Whitaker