[syslinux] Measuring boot time

[Gene Cumm]

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