• InstrumentedPrintk

TableOfContents

Introduction

"Instrumented printk" is a simple technology which adds some code to the standard kernel printk routine, to output timing data with each message. While crude, this can be used to get an overview of the areas of kernel initialization which take a relatively long time. This feature is used by the Bootup Time Working Group to identify areas of the Linux kernel requiring work to improve bootup time, and to measure the improvements of changes made by the working group.

The technology for this feature consists of a patch and a utility program. The patch alters the printk code in the kernel to emit the timing data.

The utility program is provided as a convenience for rewriting the results in an easier-to-read format. The system normally emits the timing data as a floating point number of seconds (to microsecond resolution) for the time at which the printk started. The utility program can reformat this data to seconds (including a decimal portion) between calls (deltas) and seconds relative to a single specified call. This makes it easier to see the timing for specific segments of kernel code.

Rationale

Other timing instrumentation systems for the kernel exist, and have more advanced features than this. However, this system is very simple and robust. It does not require extra programs, interfaces in proc of sysfs, or even a root filesystem, in order to obtain measurements of bootup time. It's weakness is that you can only see timing information for areas of the kernel which have printks. In order to get per-call timing data, you have to add additional printks to the area of interest. Also, printks can have high overhead themselves when they are output over a serial line.

Downloads

Patch

• Patch for x86 for 2.4.20 kernel: attachment:instrumented_printk.patch

• Patches (arch-neutral) for 2.6.x kernels are on the PatchArchive page.

• Patch for 2.6.11-rc4: attachment:printk-times-3.patch

Utility program

show_delta is a program to read the information from the printk output, and display the time values as delta's between printks, instead of as absolute values.

Here's the program: attachment:show_delta (Please use the one in the scripts directory of the kernel, if using a patch against Linux 2.6.xx or above)

How To Use (2.6 version of patch)

• Apply this patch to your kernel
• Configure your kernel with "Show timing information on printks" turned on.
  • This should on the the "Kernel hacking" menu of the kernel configuration program.
• Compile and boot your kernel
  • You should see extra data at the beginning of each printk line

• Collect the kernel printk data with dmesg

  • save the results to a file, like so:  dmesg >bootup_printks 

  • alternatively, if you are using a serial console, you can capture the kernel printk output to the capture buffer of your terminal program and save it to a file for use later.
• (Optionally) Use show_delta to display the time spent between successive printks
• (Optionally) Instead of configuring the kernel specially for showing timing information, you can use the "time" option on the kernel command line.
• (Optionally) Boot with the "quiet" kernel command line option.
  • If you are using a serial console, it is possible that the speed of the serial connection will interfere with the accuracy of the timing data. In this case you may wish to boot the kernel with the "quiet" option, which will suppress printk output during boot. When this option is used, the kernel messages are still be available after booting with the dmesg command.

How To Use (2.4 version of patch)

• Apply this patch to your kernel
• You MUST set the value for fixed_cpu_khz, in the

  file include/asm-i386/timex.h (in the inline macro highres_timer_ticks_to_timeval) to the correct value for your machine.

  • to find out the correct value for this, run your system (without the patch or with the option turned off), and 'cat /proc/cpuinfo' Use the value from the "cpu MHZ" line, multiplied by 1000 (that is, with the decimal point removed.)
• Configure your kernel with "Configure timing instrumentation in printk" turned on.
  • (This should appear at the bottom of the "General Setup menu of the kernel configuration program.)
• Compile and boot your kernel
  • You should see extra data at the beginning of each printk line

• Collect the kernel printk data with dmesg

  • save the results to a file, like so:  dmesg >bootup_printks 

  • alternatively, if you are using a serial console, you can capture the kernel printk output to the capture buffer of your terminal program and save it to a file for use later.
• (Optionally) Use show_delta to display the time spent between successive printks
• (Optionally) Boot with the "quiet" kernel command line option.
  • If you are using a serial console, it is possible that the speed of the serial connection will interfere with the accuracy of the timing data. In this case you may wish to boot the kernel with the "quiet" option, which will suppress printk output during boot. When this option is used, the kernel messages are still be available after booting with the dmesg command.

Sample Results

Sample Results for dmesg output for 2.6.11-rc4:

• InstrumentedPrintkSample4 - showing truncation of dmesg output

Sample Results for show_delta:

• InstrumentedPrintkSample1 - basic output from show_delta with every line relative to the line previous

• InstrumentedPrintkSample2 - shows output with all lines relative to first line (good for getting the total kernel bootup time)

• InstrumentedPrintkSample3 - shows output relative to a single line in the middle (good for measuring the total time for multi-line items)

Future Work

Here are some ideas for additional work needed on this system:

• should add printks to key areas of the kernel (e.g. before each sub-system and driver init) to aid in finding problem areas