• Power up -- when the power is set to on
  
  
• BIOS -- including POST (Power On Self Test), device initialization, running of option ROMs, and loading the bootloader from the MBR (Master Boot Record)
  
  
• Bootloader -- loading an operating system (OS) kernel and ancillary data (such as Linux initrd or initramfs) into RAM
  
  
• Kernel initialization -- including CPU, peripherals, and kernel data structures, as well as bring-up of the non-boot cores in the case of multi-core machines
  
  
• First user application, first line of code -- when the first line of user application source code is executed

#include stdint.h>
 
   inline uint64_t rdtsc() {
       uint32_t lo, hi;
       /*
    * cpuid will serialize the following rdtsc with respect to all other
    * instructions the processor may be handling.
        */
       __asm__ __volatile__ (
         "xorl %%eax, %%eax\n"
         "cpuid\n"
         "rdtsc\n"
         : "=a" (lo), "=d" (hi)
         :
         : "%ebx", "%ecx");
     return (uint64_t)hi << 32 | lo;
   }

#include stdint.h>
#include stdio.h>
 
inline uint64_t rdtsc() {
   ...
}
 
int main(void) {
 
        printf("TSC: %lld\n",  rdtsc());
t1:
        goto t1;
 
        return 0;
}

gcc timestamp.c -static -o timestamp

#include string.h>
#include stdio.h>
#include console.h>
 
inline uint64_t rdtsc() {
...
}
 
int main(int argc, char *argv[])
{
   uint32_t lo, hi;
 
  openconsole(&dev_stdcon_r, &dev_stdcon_w);
 
  printf("TSC: %lld\n", rdtsc());
 
  syslinux_run_command("linux");
 
  return 0;
}

default timestamp.c32

prompt 0

• When the power is turned on, the board firmware runs the BIOS, which initializes the hardware and loads and runs the syslinux bootloader.
  
  
• Syslinux reads the syslinux.cfg file, and according to the commands in it, executes the timestamp.c32 Comboot32 program. Comboot32 prints the current value of the TSC register to the VGA screen and proceeds to instruct syslinux to load the Linux kernel.
  
  
• As the kernel boots, every printk log message sent by it to the kernel log buffer is timestamped, relative to the kernel start time, which is based on the TSC register.
  
  
• Finally, after the kernel initialization has completed, the kernel runs the first user space program. In this case, this is the user program version of the timestamp program, which once again prints the current value of the TSC register and halts.

• The value of the TSC register when the bootloader runs -- By dividing this value by the number of cycles per second (Hertz) of the machine, one can convert this cycle count to the the number of seconds since the CPU reset up to this point.
  
  
• The time it takes the kernel to finish initialization -- Reflecting the PRINTK_TIMES timestamps in the log messages, this value is already represented in seconds, so no conversion is needed.
  
  
• The final TSC register value when the first user code program runs -- Here, too, one should divide the raw cycle count as reported by the TSC register by the number of cycles per second the machine is running at to obtain the number of seconds.

• The latency of the BIOS phase is measured by reading the TSC register at the start of the bootloader code, as recorded by the timestamp.c32 program.
  
  
• The latency of the bootloader actions, including reading the kernel image to RAM and uncompressing the image, can be computed. This is done by subtracting the number of seconds it took the kernel to initialize, as reported by the PRINTK_TIMES feature, from the number of seconds reported by the user-space version of the timestamp program, and the number of seconds recorded at the bootloader launch. In addition, the various timestamps in the log messages throughout the kernel initialization process provide further insight as to the contribution of the various kernel subsystems and device drivers to the overall latency.
  
  
• Finally, the full boot latency -- which is the overall time needed to get the first user program's first line of code running -- is the number of seconds computed from the value of the TSC reported by the user-program version of the timestamp program.

• The value reported from the timestamp.c32 program was 90933051222 cycles. Dividing the number of cycles by the number of cycles per second (1,500,000,000 on this board) gives a BIOS latency of 60.6 seconds. (The BIOS on this particular run wasted a long time scanning the IDE bus.)
  
  
• The timestamp provided by the PRINTK_TIMES feature in the kernel log messages indicated it took the kernel 0.44 seconds to initialize.
  
  
• The user program timestamp reported the first line of code ran at 93907247022 cycles, or 62.6 seconds after CPU reset, which is 2.0 seconds since the bootloader started.

• BIOS boots to Linux in one second
  
• Podcast delves deeper into Linux boot speedups
  
• World's fastest PC BIOS boot?
  
• Fast-booting Linux boards gain secondary bootloader
  
• ARM9 board boots Debian in 0.69 seconds
  
• Quick booting SBC runs Debian Linux
  
• Quick-boot Linux environment makes a splash
  
• Podcast reports on Embedded World 2008