Printk Times

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. Its 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 Kernel Function Instrumentation instead.

Patches

 * Patch for x86 for 2.4.20 kernel: [[Media:instrumented_printk.patch|instrumented_printk.patch]]
 * Patches (arch-neutral) for 2.6.x kernels are on the Patch Archive page.
 * Patch for 2.6.11-rc4: [[Media:printk-times-3.patch|printk-times-3.patch]]

- patch is no longer needed. 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: attachment:show_delta

(Please use the one in the  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
 * save the results to a file, like so:
 * 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  command.
 * (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   command.
 * 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   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/module/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).  Notethat you must also specify a larger buffer read size with "dmesg", with the '-s' option.
 * ex:
 * 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  (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  save the results to a file, like so:
 * 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 :
 * Printk Times Sample1 - basic output from show_delta with every line relative to the line previous
 * Printk Times Sample2 - shows output with all lines relative to first line (good for getting the total kernel bootup time)
 * Printk Times Sample3 - 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:
 * Printk Times Sample4 - 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: attachment: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