Benchmarking boot latency on x86

Gilad Ben-Yossef July 8th, 2008

One of the tasks embedded system developers face is managing boot latency, or the time it takes for a device to become functional after power up.

After all, a set top box that will take more then 60 seconds from the time the “On” button is pressed until the end customer can at least interact with the menus, for example, will most likely be returned to the store for a refund, no matter what feature set it has. When it come to our gadgets, we are all hungry for immediate satisfaction, it seems.

There are many tricks one can employ to to achieve boot time nirvana, but as Knuth taught us, premature optimization is the root of all evil. Therefore, before we turn our efforts to optimize boot latency, we should first try to measure what that boot latency really is and what part of the boot sequence contribute to it, lest we optimize the wrong thing.

Generally speaking, on a x86 (32bit or 64 bit), the boot process of a Linux system is comprised of the following phases and milestones:

  • The power up milestone: when the power is set to on
  • The BIOS phase: which includes the POST (or Power On Self Test), device initialization, running of option ROMs and loading the boot loader form the MBR (or Master Boot Record).
  • The boot loader phase: loading of an operating system kernel and ancillary data (such as Linux initrd or initramfs) into RAM.
  • Kernel initialization phase: initialization of CPU, peripherals and kernel data structures, including the bring up of the non boot cores in the case of a multi-core machine.
  • First user application first line of code milestone: the time when the first line of user application source code is executed.

Unfortunately, measuring the contribution of each of these phases to the overall boot latency is not an easy task to accomplish. At each of the phases different kind of code is executing on the machine: from the 16 bit BIOS code which is part of the machine firmware, via the 16 or 32 bit boot loader code, the 32 bit kernel code and the finally user applications - each of these is executing in a completely different software environment from the other and it is hard to find a common ground to compare the time each phase takes.

Luckily, the x86 architecture provides a useful tool: the TSC (or Time Stamp Clock) register. The TSC register was introduced in the original Intel Pentium CPU and counts the number of clock ticks from the last processor reset. Reading the current value of the TSC register is done using the RDTSC instruction.

Assuming no processor frequency changes (for example via SpeedStep technology) takes place and that we always sample the register of the same core in a multi core environment, both of which are easy to guarantee during the boot phase, the TSC register provides us with an accurate hi-res timer through which we can benchmarks the various phases in the boot process.

Continue Reading »

Linux Network Stack Flow

Tuxology team June 16th, 2008

A wonderful article, describing the control flow and the associated data types of the Linux networking stack of kernel 2.6, written by Arnout Vandecappelle of Mind, is available via the kind folks at the Linux Foundation.

Accompanying the article itself, an elaborate graphic schema of the network stack and data type, is also included. Looks like it will make a great cubicle poster!

The Tuxology Team

Kernel panic messages

Gilad Ben-Yossef May 15th, 2008

It is sometime useful to be able to store the text of kernel panic messages in non volatile memory for postmortem fault analysis, in lieu of big enough storage device or network medium to store or send these message in the field.

The following code examples shows how this can be accomplished.

Some notes and caveats are due: the code does not deal with initializing the non volatile memory, if applicable. To use this example with NOR flash, as an example, code handling flash erasing will need to be added. In addition, this example does not display or clear saved messages and implementing this is left as an exercise to the reader.

Here is the Makefile:

default:
   $(MAKE) -C /lib/modules/`uname -r`/build \
      SUBDIRS=`pwd` modules
 
clean:
  $(MAKE) -C /lib/modules/`uname -r`/build \
      SUBDIRS=`pwd` clean

The simple Kbuild file is:

obj-m := panic_msg.o

And the panic_msg.c is:

#include <linux/kernel.h>
#include <linux/module.h>
#include <linux/moduleparam.h>
#include <linux/notifier.h>
#include <linux/ioport.h>
#include <asm/io.h>
 
#define LOG_PREFIX "panic_msg: "
 
static unsigned long buf_address = 0;
module_param(buf_address, ulong, S_IRUSR);
MODULE_PARM_DESC(buf_address, 
  "The physical address of the panic message buffer.");
 
static unsigned long buf_size = 0;
module_param(buf_size, ulong, S_IRUSR);
MODULE_PARM_DESC(buf_size, 
  "The size in bytes of the panic message buffer.");
 
static unsigned int notifier_priority = INT_MAX;
module_param(notifier_priority, uint, S_IRUSR);
MODULE_PARM_DESC(notifier_priority, 
  "Notifier priority: INT_MAX &gt;= x &gt;= 0.");
 
static char * buf;
 
static int panic_msg_handler(
  struct notifier_block *this, 
  unsigned long event,void *msg)
{
  static unsigned int panic_event_handled = 0;
  unsigned int msg_size = min(strlen(msg), buf_size);
 
  if(!panic_event_handled) {
     panic_event_handled = 1;
     memcpy_toio((char *)msg, buf, msg_size);
  }
  return NOTIFY_OK;
}
 
static struct notifier_block panic_msg_notifier = {
  .notifier_call  = panic_msg_handler,
  .next           = NULL,
  .priority       = INT_MAX
};
 
static int __init panic_msg_init(void)
{
  int ret = 0;
  struct resource * res = NULL;
 
  if((!buf_address) || (!buf_size)) {
    printk(KERN_ERR LOG_PREFIX 
      "Address and size parameters are mandatory.\n", 
      buf_address, buf_size);
    ret = -EINVAL;
    goto error;
  }
 
  panic_msg_notifier.priority = notifier_priority;
 
  res = request_mem_region(buf_address, buf_size, 
    "Panic message handler");
 
  if(!res) {
    printk(KERN_ERR LOG_PREFIX 
      "Failed requesting panic message buffer " \
      "at address  0x%lx of size %ld.\n",
      buf_address, buf_size);
    ret = -EINVAL;
    goto error;
  }
 
  buf = ioremap(buf_address, buf_size);
 
  if(!buf) {
    printk(KERN_ERR LOG_PREFIX 
      "Failed mapping panic msg buf at address" \
      " 0x%lx of size %ld\n", 
      buf_address, buf_size);
    ret = -EINVAL;
    goto error;
  }
 
  if(atomic_notifier_chain_register(
     &panic_notifier_list, &panic_msg_notifier)) {
    printk(KERN_ERR LOG_PREFIX 
      "Failed registering panic message notifier.\n");
    ret = -EINVAL;
    goto error;
  }
 
  printk(KERN_INFO LOG_PREFIX 
   "Panic message buffer handler initialized.\n");
 
  return 0;
 
error:
  if(res) release_mem_region(buf_address, buf_size);
  if(buf) iounmap(buf);
  return ret;
}
 
static void __exit panic_msg_exit(void) {
 
  if(atomic_notifier_chain_unregister(
     &panic_notifier_list, &panic_msg_notifier)) {
    printk(KERN_ERR LOG_PREFIX 
      "Failed removing panic msg buf mapping.\n");
  }
  iounmap(buf);
  release_mem_region(buf_address, buf_size);
 
  printk(KERN_INFO LOG_PREFIX 
     "Panic message buffer handler unloaded.\n");
 
  return;
}
 
module_init(panic_msg_init);
module_exit(panic_msg_exit);
 
MODULE_LICENSE("GPL");
MODULE_AUTHOR("Gilad Ben-Yossef" \
  " <gilad@codefidence.com>");
MODULE_DESCRIPTION("This module stores kernel  " \
   "panic messages in non volatile memory.");

Panic message example kernel module source code

This post originally appeared in the Codefidence Technoblog