Introduction

"Printk-times" 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.

$/!\$ UPDATE: The patch was incorporated into the mainline kernel as of version 2.6.11! Both the feature, and the utility program are now part of mainline Linux!!

With printk-times turned on, the system 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 shows the time between calls, or it can show the times relative to a specific message. This makes it easier to see the timing for specific segments of kernel code.

Rationale

There are other instrumentation systems for the kernel that 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 more detail for an area of interest, you have to add additional printks to the kernel, and re-compile it. Also, printks themselves may add too much timing overhead to the kernel, particularly when the output is over a serial line (which is very common in embedded configurations).

For a system that provides much more detailed timing information, you may want to use KernelFunctionInstrumentation instead.

Downloads

Patch

Patch for x86 for 2.4.20 kernel: instrumented_printk.patch
Patches (arch-neutral) for 2.6.x kernels are on the PatchArchive page.
Patch for 2.6.11-rc4: printk-times-3.patch

$/!\$ - patch is not needed anymore. Printk-times was incorporated into the mainline Linux kernel as of version 2.6.11.

Utility program

The program show_delta reads the information from printk output, and displays time values as delta's between printks. This helps to more easily find periods of long time between printks. (This is easier than "eye-balling" the dump, looking for jumps in the time.)

Here's the program: show_delta

(Please use the one in the /scripts directory of the kernel, if using a patch against Linux 2.6.11 or above)

How To Use (2.6 version of kernel)

If using a kernel version prior to 2.6.11, apply the appropriate patch to your kernel
When booting the kernel, add the option "time" on the kernel command line
- You should see extra data at the beginning of each printk line
Examine the data while it is displayed, or after booting use the "dmesg" command line.
- (See the "trouble-shooting" section below if you only see some, not all, of the bootup messages)
Collect the kernel printk data with dmesg
- save the results to a file, like so: dmesg >/tmp/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) To see the time spent between successive printks, use the show_delta command.
- scripts/show_delta /tmp/bootup_printks
(Optionally) To avoid the overhead of writing out the kernel messages during bootup, try booting the kernel with the "quiet" kernel command line option.
- If you use a serial console, it is possible for the speed of the serial connection to interfere with the accuracy of the timing data. In this case you may wish to boot the kernel with the "quiet" option, which suppresses printk output during boot. When this option is used, the kernel messages are not printed during bootup, but are still available after booting with
  the dmesg command.
(Optionally) If you want to configure the kernel to always boot with timing information turned on, and/or you want to see timing information for the kernel BEFORE it parses the kernel command line:
- Configure your kernel with "Show timing information on printks" turned on.
  - This option is on the the "Kernel hacking" menu of the kernel configuration program.
- Compile and boot your kernel

runtime control of printk times

Jan Engelhardt supplied a patch against 2.6.17 which allows for runtime control of the printk-times control flag. Here is what he wrote:

{{{Currently, enabling/disabling printk timestamps is only possible through reboot (bootparam) or recompile. I normally do not run with timestamps (since syslog handles that in a good manner), but for measuring small kernel delays (e.g. irq probing - see parport thread) I needed subsecond precision, but then again, just for some minutes rather than all kernel messages to come. The following patch adds a module_param() with which the timestamps can be en-/disabled in a live system through

/sys/modules/printk/parameters/printk_time. }}}

The patch is applied in 2.6.18-rc3 (Linus' tree) so it should show up in 2.6.18.

Trouble-shooting

Not all kernel messages are displayed by dmesg
- The printk-times feature adds a number of bytes at the beginning of each printk message. The default kernel message buffer size may not be sufficient to hold all the messages with this additional overhead. You can increase the kernel message buffer size when compiling the kernel, by adjusting the "Kernel Log buffer size" (found on the "General Setup" menu). Note that you must also specify a larger buffer read size with "dmesg", with the '-s' option.
  - ex: dmesg -s 128000 >/tmp/bootup_printks
Resolution of timings is very bad.
- Printk-time uses the routine sched_clock() in the kernel. On some platforms, sched_clock() only has a resolution of 1 jiffy (which may be 10 milliseconds or longer). This means that you will only see the time increment at this resolution, giving imprecise results for printk-times. To correct this problem, the best solution is to implement a good sched_clock() routine for your platform. Sched_clock() returns a 64-bit value which is nanoseconds since some event (usually either since machine power-on, or since time_init() was called.) Many embedded processors have a clock or timer on the System-On-Chip which can provide a good resolution clock source for sched_clock(). It is best if the clock can provide resolution better than 1 microsecond. Note that this only requires a clock running at 1 MHz to achieve this resolution.
Machine hangs when printk-times is compiled ON.
- You may experience a panic, hang-up, or some other problem with printk-times turned on. I have seen problems caused by calls to sched_clock() too early in boot sequence. Some platforms don't support calling sched_clock() before memory, interrupts or other architecture-specific items are initialized. (The 'i386' arch is OK, since it's sched_clock() by default uses the TSC, which does not need any prior setup.) In case you have problems on your platform, you may need to adjust the sched_clock() function to return 0 until it is safe to begin operation (usually until after time_init() completes.)

Customizing the printk times clock

Somewhere between 2.6.11 and 2.6.14, the printk routine was modified to use printk_clock() instead of sched_clock() directly. This means that you can override printk_clock() on your platform to use a custom timestamp source different from the one used by sched_clock() (Or, you can avoid calling sched_clock() until it is ready - say, after time_init()).

How To Use (2.4 version of kernel)

Apply the 2.4-based 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 show_delta:

PrintkTimesSample1 - basic output from show_delta with every line relative to the line previous
PrintkTimesSample2 - shows output with all lines relative to first line (good for getting the total kernel bootup time)
PrintkTimesSample3 - shows output relative to a single line in the middle (good for measuring the total time for multi-line items)

Sample Results for dmesg output for 2.6.11-rc4:

PrintkTimesSample4 - showing truncation of dmesg output

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

initcall-times

Matt Mackall provided a patch which measures times for the initialization of each driver. He described it like this:

Here's another tool for looking at boot-up times. It times just the initcalls and is enabled by putting 'initcall_debug' on the command line.

Here is the patch: initcalls-times.patch

Here are Tim Bird's results on an OSK board: {{{/ # dmesg | grep elapsed | sort -r -n | head -20

initcall elapsed 4.371399s - ip_auto_config+0x0/0x2d0() initcall elapsed 0.569714s - serial8250_init+0x0/0xe8() initcall elapsed 0.284381s - ohci_hcd_omap_init+0x0/0x68() initcall elapsed 0.280125s - inet_init+0x0/0x1c4() initcall elapsed 0.259520s - tty_init+0x0/0x1f4() initcall elapsed 0.218823s - omapfb_init+0x0/0xb0() initcall elapsed 0.073477s - smc_init+0x0/0x44() initcall elapsed 0.042453s - loop_init+0x0/0x324() initcall elapsed 0.034427s - init_sunrpc+0x0/0x74() initcall elapsed 0.029502s - net_olddevs_init+0x0/0x60() initcall elapsed 0.026582s - init_nfs_fs+0x0/0xb4() initcall elapsed 0.019380s - cfq_init+0x0/0x64() initcall elapsed 0.017892s - i2c_dev_init+0x0/0xb8() initcall elapsed 0.017575s - rand_initialize+0x0/0x14c() initcall elapsed 0.014053s - deadline_init+0x0/0x94() initcall elapsed 0.013225s - af_unix_init+0x0/0xbc() initcall elapsed 0.012830s - omap_kp_init+0x0/0x17c() initcall elapsed 0.012528s - mousedev_init+0x0/0xbc() initcall elapsed 0.012048s - as_init+0x0/0xa0() initcall elapsed 0.011371s - journal_init+0x0/0x40()

}}}