[syslinux] Measuring boot time

Mon Oct 5 13:36:17 PDT 2015

Hi
Some time ago I wrote this mailing list about some extra time that it takes for my system to boot and I don't know where it came from.I'm using a custom BIOS which loads at 1 second and now I've found out that it takes for the bootloader and OS an extra 1 second to load when keyboard is disconnected.I got from the BIOS engineer the following explanation and steps to take:
In syslinux make sure that it doesn’t use the KBC at all. KBC functions will timeout when a KBC is not present. GATEA20 (address line A20 wrap around 8086 compatibility gate) must not be controlled by KBC as first option. No menu stuff or something needing keyboard should be used.

The GATEA20 should be enabled as follows:

1) Test if A20 is already enabled. If enabled goto 7.
2) Do BIOS int 0x15 function 0x2401 to enable GATEA20.
3) Test if A20 is enabled. If enabled go to 7.
4) Do port 0x92 (FASTA20) enable.
5) Test if A20 is enabled. If enabled go to 7.
6) Error!!
7) A20 is enabled. Done.However, I'm not sure what's the best way to do that.I've seen that there is GATEA20 related code only in GPXE branch but I'm not using GPXE.Any suggestions?
Best regards,Tal

      From: Gene Cumm <gene.cumm at gmail.com>
 To: Tal Lubko <tallubko at yahoo.com> 
Cc: "syslinux at zytor.com" <syslinux at zytor.com> 
 Sent: Saturday, July 18, 2015 2:13 PM
 Subject: Re: [syslinux] Measuring boot time

On Fri, Jul 17, 2015 at 11:57 PM, Tal Lubko <tallubko at yahoo.com> wrote:
> Hi Gene
>
>
> It took me some time to check all the things you've asked.
> Hope you still remember the case...
>
> 1) Compiling SYSLINUX with -j1 didn't help.
>
> The first error message I get is about missing header file.
> I'll try to play a little bit with it to make it compile.

1) I'd suggest using 4.07 or git branch syslinux-4.xx (commit ID d12243b).
2) Sounds like either a missing library or a newer version of gcc (or
some other compile-related binary) that's becoming more picky.

> 2) The 3-character mode that the version/copyright banner displays is EDD.
> What determines the it? BIOS?

Essentially, yes.  If the BIOS presents certain BIOS EDD calls as
valid, they're used.

> What affect does it have on the system?

The potential of fetching multiple sectors simultaneously and using
larger disks.

> 3) I'm not using any virtualization layer.
> Why do you ask that?

How do you get such precise timing?  Measuring anything under a second
(and almost certainly under a decisecond) requires technological
assistance.

> 4) Can you point me to the kernel jump point in SYSLINUX?
> I'm checking about kernel rootfs decompression stage.
>
> 5) I'll post the "slow" BIOS boot time next time although SYSLINUX 6.03 gets stuck when working with the "slow" BIOS.
> With 4.05 the "slow" BIOS works fine but I have problems compiling it...
>
> Thanks again for your help,
> Tal
>
>
>
>
> ----- Original Message -----
> From: Gene Cumm <gene.cumm at gmail.com>
> To: Tal Lubko <tallubko at yahoo.com>
> Cc: "syslinux at zytor.com" <syslinux at zytor.com>
> Sent: Sunday, July 12, 2015 2:43 PM
> Subject: Re: [syslinux] Measuring boot time
>
> On Sun, Jul 12, 2015 at 3:35 AM, Tal Lubko <tallubko at yahoo.com> wrote:
>> Hi Gene
>>
>>
>> Thanks again for your help.
>> I'm using SYSLINUX 4.05 distributed by Ubuntu.
>>
>> For debugging I'm using SYSLINUX 6.03 because for some reason if I build SYSLINUX 4.05 from sources I get many compilation errors.
>
> If you make anything more than -j 1, you're probably hitting
> dependency errors in com32/Makefile.  These should be resolved now in
> 6.
>
>> SYSLINUX is installed on eMMC storage (along with Linux).
>> I don't see the 3-character mode banner display. How can I check it?
>
> It'll say SYSLINUX 6.03, with a complex version string, a 3-character
> mode ("CHS" or "EDD") and the copyright.  If your config obscures it,
> that's the issue.  DEFAULT should point to a real LABEL (not a menu or
> a LABEL for a menu), comment out the UI line and I'd suggest "PROMPT
> 0" with a reasonable (or no) TIMEOUT (measured in 1/10s of a second).
>
>> So I've added some timing prints to SYSLINUX 6.03 and got the following results:
>> bootloader start                  1179.140 ms
>> before loadfile                    1180.320 ms
>> after loadfile                    1454.250 ms
>> before bios_do_shuffle_and_boot    1465.795 ms
>> kernl_start (main.c)              2298.054 ms
>
> I'm presuming this is with some virtualization layer?
>
>> The Linux image size is around 10 MByte.
>> You can see that the time that it takes to read it is around 280 ms.
>> It is slow compared to reading it from Linux but it doesn't what take the vast boot time.
>> You can see that the vast boot time part is between bios_do_shuffle_and_boot and kernel start.
>
> Another two points to add would be the final jump to the kernel in the
> shuffle/boot and the initial kernel entry point (which is probably the
> decompression code).
>
>> As far as I could see, from this stage on SYSLINUX code is assembly which I'm less familiar with so it is harder for me to debug.
>>
>> Can you describe what SYSLINUX does from this stage on?
>> Do you have any assumption what can take so much time?
>
> Exactly what it says, moving things in RAM (shuffling), setting up
> some basic handoff structures, removing itself from the timer
> interrupt and booting.  I believe kernel_start is after the
> decompression is complete.  You'll probably want the other timing
> points added.
>
>> I'd like to remind you that if I use slower BIOS "bios_do_shuffle_and_boot" is called later BUT the duration from it to kernel_start is shorter.
>
> If you want to compare, it'd be nice if you could post times on both.
>
>
>> ________________________________
>> From: Gene Cumm <gene.cumm at gmail.com>
>> To: Tal Lubko <tallubko at yahoo.com>
>> Cc: "syslinux at zytor.com" <syslinux at zytor.com>
>> Sent: Wednesday, July 8, 2015 4:54 PM
>> Subject: Re: [syslinux] Measuring boot time
>>
>>
>> On Wed, Jul 8, 2015 at 12:47 AM, Tal Lubko <tallubko at yahoo.com> wrote:
>>> Hi Gene
>>>
>>> Thanks for your reply.
>>> I'm trying to breakdown overall system boot time and to understand each
>>> component duration.
>>> My linux image is a ~10 MB bzImage file with the rootfs cpio'ed inside.
>>>
>>> I also have 2 BIOS images:
>>> - some general purpose BIOS
>>> - a custom BIOS which loads real quick
>>>
>>> I'm using TSC to measure time. I'm not sure it's the best way (I've read
>>> about CPU's synchronization problems with it) but I'm not sure how to do it
>>> otherwise.
>>
>> Syslinux is essentially a single-core single-thread application.
>> Unless your BIOS uses other cores for some BIOS function calls, they
>> shouldn't matter.
>>
>>> I've added the following TSC reads at:
>>> 1) the begining of a custom c32 module which later calls
>>> "syslinux_run_command"
>>> 2) the begining of "start_kernel" function
>>> 3) end of kernel load
>>>
>>> As far as I understand the duration between 1 to 2 is bootloader time (am I
>>> wrong?).
>>
>> That sounds reasonable.  Time to fetch kernel and iniitrd payload(s)
>> plus set it all up.
>>
>>> Using the custom BIOS:
>>> - it takes ~1.1 seconds for bootloader to finish
>>> - it takes ~0.9 seconds for Linux to finish
>>>
>>> Using the general purpose BIOS:
>>> - it takes ~0.45 seconds for bootloader to finish
>>> - it takes ~0.9 seconds for Linux to finish
>>>
>>> Of course that the overall boot time with the general purpose BIOS is much
>>> longer than with the custom BIOS (the custom BIOS is intended to cut down
>>> boot time).
>>>
>>> So I'm trying to understand:
>>> - Where does the extra bootloader time go when using the custom BIOS?
>>
>> Any of various sources though most likely your custom BIOS is just
>> slower at its disk access.
>>
>>> - Is there a mechanisem built into syslinux code which can help solve this
>>> mystery?
>>
>> There's not any mechanism that I know of aside from using cptime.c32
>> to time how long it takes for the files to be loaded or enabling some
>> of the debug functionality (with debug.c32 to the screen or a
>> recompile to output to a serial port at IO port 3F8h at 115200 8n1).
>>
>> There are some obvious questions that are yet unanswered:
>>
>> 1) What version?  Where did it come from?
>>
>> 2) Where is it installed?  SYSLINUX on a hard drive or perhaps
>> installed to a USB drive of some sort?  Some USB BIOSs are horribly
>> slow.  Perhaps ISOLINUX on a CD or hybridized to a hard drive or USB
>> drive?
>>
>> 3) If SYSLINUX, what 3-character mode does the version/copyright
>> banner display, CHS or EDD?
>>
>>
>>
>>
>> --
>> -Gene
>>
>>> ________________________________
>>> From: Gene Cumm <gene.cumm at gmail.com>
>>> To: Tal Lubko <tallubko at yahoo.com>
>>> Cc: "syslinux at zytor.com" <syslinux at zytor.com>
>>> Sent: Wednesday, July 8, 2015 4:45 AM
>>> Subject: Re: [syslinux] Measuring boot time
>>>
>>> On Mon, Jul 6, 2015 at 1:01 PM, Tal Lubko via Syslinux
>>>
>>>
>>>
>>> <syslinux at zytor.com> wrote:
>>>> Hello Everyone
>>>> I'd like to know what's the best way to measure syslinux functions
>>>> duration.I know how to measure overall time (from syslinux start), but is
>>>> there an easy way to break it down?
>>>
>>>
>>> What do you mean?  How long it takes to load individual files along
>>> the way from initial start to the kernel handoff?  cptime.c32 might
>>> offer a way to get some answers there.
>>>
>>> Do you mean how long individual function calls take?  That sounds like
>>> a non-trivial question if this is the case.
>
>
>
>
> --
> -Gene

-- 
-Gene