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. SYSLINUX is installed on eMMC storage (along with Linux). I don't see the 3-character mode banner display. How can I check it? 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 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. 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? 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. Thanks, 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: 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.
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 msI'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
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. 2) The 3-character mode that the version/copyright banner displays is EDD. What determines the it? BIOS? What affect does it have on the system? 3) I'm not using any virtualization layer. Why do you ask that? 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 msI'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