测量和分析 Linux 内核启动时间

by falcon of TinyLab.org 2014/01/06

Introduction

eLinux.org/Boot_Time have collected lots of resources such as measurement, analysis, human factors, initialization techniques, and reduction techniques, we don’t want to repeat them.

In this article, we will introduce how to measure the boot-up time of Linux kernel and draw it in a more visual graph.

Linux kernel does provide a tool: scripts/bootgraph.pl to draw the time cost of the initcalls, but:

• It can not draw the time cost of the other parts, only initcalls
• The output graph is not that helpful to find out the time-cost parts

Measure the boot-up time of Linux kernel

First off, please make sure initcall_debug and printk.time=1 passed on the Linux kernel command line.

After kernel boot, dump out the kernel printk log with timestamps into a dmesg.log file:

$ dmesg > dmesg.log

To get a full printk log, please make sure the printk buffer is big enough via increasing the CONFIG_LOG_BUF_SHIFT to a bigger value.

Draw the Boot-up Time

Draw it with scripts/bootgraph.pl

By default, we can use scripts/bootgraph.pl to draw the data:

$ cat dmesg.log | perl bootgraph.pl > bootgraph.svg

See an example of bootgraph.svg.

As we can see, the output is not that friendly:

• The name of the initcalls are output vertically, can not be read comfortably
• Can not easily find out the difference among some similar ‘rectangles’

Note: if the printk is hacked by you, please modify the script to make sure it can parse the printk log normally:

diff --git a/scripts/bootgraph.pl b/scripts/bootgraph.pl
index b78fca9..bd3f07c 100644
--- a/scripts/bootgraph.pl
+++ b/scripts/bootgraph.pl
@@ -51,7 +51,7 @@ my %pidctr;

 while (<>) {
        my $line = $_;
-       if ($line =~ /([0-9\.]+)\] calling  ([a-zA-Z0-9\_\.]+)\+/) {
+       if ($line =~ /([0-9\.]+)\].*calling  ([a-zA-Z0-9\_\.]+)\+/) {
                my $func = $2;
                if ($done == 0) {
                        $start{$func} = $1;
@@ -66,7 +66,7 @@ while (<>) {
                $count = $count + 1;
        }

-       if ($line =~ /([0-9\.]+)\] async_waiting @ ([0-9]+)/) {
+       if ($line =~ /([0-9\.]+)\].*async_waiting @ ([0-9]+)/) {
                my $pid = $2;
                my $func;
                if (!defined($pidctr{$pid})) {
@@ -87,14 +87,14 @@ while (<>) {
                $count = $count + 1;
        }

-       if ($line =~ /([0-9\.]+)\] initcall ([a-zA-Z0-9\_\.]+)\+.*returned/) {
+       if ($line =~ /([0-9\.]+)\].*initcall ([a-zA-Z0-9\_\.]+)\+.*returned/) {
                if ($done == 0) {
                        $end{$2} = $1;
                        $maxtime = $1;
                }
        }

-       if ($line =~ /([0-9\.]+)\] async_continuing @ ([0-9]+)/) {
+       if ($line =~ /([0-9\.]+)\].*async_continuing @ ([0-9]+)/) {
                my $pid = $2;
                my $func =  "wait_" . $pid . "_" . $pidctr{$pid};
                $end{$func} = $1;

Draw it with Flame Graph

The Flame Graph do output the functions vertically, but to draw the boot-up time, the data format must be converted to the one supported by Flame Graph at first, its data format looks like:

a;b;c;d; 10
a;b;e 20
f 30
g 90

Based on bootgraph.pl, we write a dmesg-initcalls.pl to convert the data format:

$ cat dmesg.log | perl dmesg-initcall.pl > boot-initcall.log
$ head -5 boot-initcall.log
s3c_fb_init 0.091
s5p_mipi_dsi_register 0.319
pl330_driver_init 0.019
s3c24xx_serial_modinit 4.706
PVRCore_Init 0.077

Now, draw it with Flame Graph:

$ git clone https://github.com/brendangregg/FlameGraph.git
$ cd FlameGraph
$ cat boot-initcall.log | ./FlameGraph/flamegraph.pl > linux-boot-flamegraph.svg

Take a look at linux-boot-flamegraph.svg.

As we can see, it not only highlight the time-consuming initcalls, but also give an interactive interface.

But it is also not that friendly to compare different initcalls.

Draw it with gnuplot

gnuplot is a famous plotting program, it can be used to do mathematical statistics, so, we can also use it to draw the above boot-initcall.log.

First off, install gnuplot-x11:

$ sudo apt-get install gnuplot-x11

Second, prepare a gnuplot script linux-boot.gnuplot:

set terminal svg size 800,300 fsize 4
set output 'linux-boot-gnuplot.svg'
set style data histograms
set style histogram clustered gap 1 title offset character 0, 0, 0
set style fill solid 0.4 border
set xtics rotate by -45
set boxwidth 0.9 absolute
plot './boot-initcall.log' using 2:xticlabels(1)

Third, draw with the above script:

$ gnuplot < linux-boot.gnuplot

After that, the linux-boot-gnuplot.svg is available.

is available

It looks better for it shows the time consuming initcalls obviously, but unfortunately, it is not interactively.

Draw it with TinyDraw/histogram.sh

To make a better output, based on Frame Graph, Bootgraph,pl and gnuplot, we write a new histogram.sh tool in our TinyDraw project.

To draw it, we can simply run:

$ git clone https://github.com/tinyclub/tinydraw.git
$ ./tinydraw/histogram/histogram.sh boot-initcall.log > linux-boot-histogram.svg

Take a look at linux-boot-histogram.svg.

Conclusion

Based on the above practice, we found out, to draw the data in two row format: [string, value], the histogram is a better graph.

Our TinyDraw/histogram can draw such data in an interactive SVG graph.

TinyDraw/histogram is scalable, you can use it to draw the data generated by dmesg.sh and bootprof.sh. We will add a convert script of Grabserial later.

To use it to draw the other similar data, you must refer to the above dmesg.sh or bootprof.sh to convert the original data to the “two row data” format.

• [string, value]:

a 10
b 20
f 30
g 90

Or

• [value, string]:

10 a
20 b
30 f
90 g

If the string have spaces, please use the [value, string] format.