code.ossystems Code Review - openembedded-core.git/blob

   1 From 77e9695b9d5c9ce761dedc193045d9cb64b8e245 Mon Sep 17 00:00:00 2001
   2 From: Arjan van de Ven <arjan@linux.intel.com>
   3 Date: Sat, 13 Sep 2008 09:36:06 -0700
   4 Subject: [PATCH] Add a script to visualize the kernel boot process / time
   5
   6 When optimizing the kernel boot time, it's very valuable to visualize
   7 what is going on at which time. In addition, with the fastboot asynchronous
   8 initcall level, it's very valuable to see which initcall gets run where
   9 and when.
  10
  11 This patch adds a script to turn a dmesg into a SVG graph (that can be
  12 shown with tools such as InkScape, Gimp or Firefox) and a small change
  13 to the initcall code to print the PID of the thread calling the initcall
  14 (so that the script can work out the parallelism).
  15
  16 Signed-off-by: Arjan van de Ven <arjan@linux.intel.com>
  17 ---
  18  init/main.c          |    1
  19  scripts/bootgraph.pl |  138 +++++++++++++++++++++++++++++++++++++++++++++++++++
  20  2 files changed, 139 insertions(+)
  21  create mode 100644 scripts/bootgraph.pl
  22
  23 Index: linux-2.6.27/init/main.c
  24 ===================================================================
  25 --- linux-2.6.27.orig/init/main.c       2008-10-14 17:02:46.000000000 +0200
  26 +++ linux-2.6.27/init/main.c    2008-10-14 17:05:23.000000000 +0200
  27 @@ -709,6 +709,7 @@ int do_one_initcall(initcall_t fn)
  28
  29         if (initcall_debug) {
  30                 printk("calling  %pF\n", fn);
  31 +               printk(" @ %i\n",  task_pid_nr(current));
  32                 t0 = ktime_get();
  33         }
  34
  35 Index: linux-2.6.27/scripts/bootgraph.pl
  36 ===================================================================
  37 --- /dev/null   1970-01-01 00:00:00.000000000 +0000
  38 +++ linux-2.6.27/scripts/bootgraph.pl   2008-10-14 17:03:34.000000000 +0200
  39 @@ -0,0 +1,138 @@
  40 +#!/usr/bin/perl
  41 +
  42 +# Copyright 2008, Intel Corporation
  43 +#
  44 +# This file is part of the Linux kernel
  45 +#
  46 +# This program file is free software; you can redistribute it and/or modify it
  47 +# under the terms of the GNU General Public License as published by the
  48 +# Free Software Foundation; version 2 of the License.
  49 +#
  50 +# This program is distributed in the hope that it will be useful, but WITHOUT
  51 +# ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
  52 +# FITNESS FOR A PARTICULAR PURPOSE.  See the GNU General Public License
  53 +# for more details.
  54 +#
  55 +# You should have received a copy of the GNU General Public License
  56 +# along with this program in a file named COPYING; if not, write to the
  57 +# Free Software Foundation, Inc.,
  58 +# 51 Franklin Street, Fifth Floor,
  59 +# Boston, MA 02110-1301 USA
  60 +#
  61 +# Authors:
  62 +#      Arjan van de Ven <arjan@linux.intel.com>
  63 +
  64 +
  65 +#
  66 +# This script turns a dmesg output into a SVG graphic that shows which
  67 +# functions take how much time. You can view SVG graphics with various
  68 +# programs, including Inkscape, The Gimp and Firefox.
  69 +#
  70 +#
  71 +# For this script to work, the kernel needs to be compiled with the
  72 +# CONFIG_PRINTK_TIME configuration option enabled, and with
  73 +# "initcall_debug" passed on the kernel command line.
  74 +#
  75 +# usage:
  76 +#      dmesg | perl scripts/bootgraph.pl > output.svg
  77 +#
  78 +
  79 +my @rows;
  80 +my %start, %end, %row;
  81 +my $done = 0;
  82 +my $rowcount = 0;
  83 +my $maxtime = 0;
  84 +my $count = 0;
  85 +while (<>) {
  86 +       my $line = $_;
  87 +       if ($line =~ /([0-9\.]+)\] calling  ([a-zA-Z\_]+)\+/) {
  88 +               my $func = $2;
  89 +               if ($done == 0) {
  90 +                       $start{$func} = $1;
  91 +               }
  92 +               $row{$func} = 1;
  93 +               if ($line =~ /\@ ([0-9]+)/) {
  94 +                       my $pid = $1;
  95 +                       if (!defined($rows[$pid])) {
  96 +                               $rowcount = $rowcount + 1;
  97 +                               $rows[$pid] = $rowcount;
  98 +                       }
  99 +                       $row{$func} = $rows[$pid];
 100 +               }
 101 +               $count = $count + 1;
 102 +       }
 103 +
 104 +       if ($line =~ /([0-9\.]+)\] initcall ([a-zA-Z\_]+)\+.*returned/) {
 105 +               if ($done == 0) {
 106 +                       $end{$2} = $1;
 107 +                       $maxtime = $1;
 108 +               }
 109 +       }
 110 +       if ($line =~ /Write protecting the/) {
 111 +               $done = 1;
 112 +       }
 113 +}
 114 +
 115 +if ($count == 0) {
 116 +       print "No data found in the dmesg. Make sure CONFIG_PRINTK_TIME is enabled and\n";
 117 +       print "that initcall_debug is passed on the kernel command line.\n\n";
 118 +       print "Usage: \n";
 119 +       print "      dmesg | perl scripts/bootgraph.pl > output.svg\n\n";
 120 +       exit;
 121 +}
 122 +
 123 +print "<?xml version=\"1.0\" standalone=\"no\"?> \n";
 124 +print "<svg width=\"1000\" height=\"100%\" version=\"1.1\" xmlns=\"http://www.w3.org/2000/svg\">\n";
 125 +
 126 +my @styles;
 127 +
 128 +$styles[0] = "fill:rgb(0,0,255);fill-opacity:0.5;stroke-width:1;stroke:rgb(0,0,0)";
 129 +$styles[1] = "fill:rgb(0,255,0);fill-opacity:0.5;stroke-width:1;stroke:rgb(0,0,0)";
 130 +$styles[2] = "fill:rgb(255,0,20);fill-opacity:0.5;stroke-width:1;stroke:rgb(0,0,0)";
 131 +$styles[3] = "fill:rgb(255,255,20);fill-opacity:0.5;stroke-width:1;stroke:rgb(0,0,0)";
 132 +$styles[4] = "fill:rgb(255,0,255);fill-opacity:0.5;stroke-width:1;stroke:rgb(0,0,0)";
 133 +$styles[5] = "fill:rgb(0,255,255);fill-opacity:0.5;stroke-width:1;stroke:rgb(0,0,0)";
 134 +$styles[6] = "fill:rgb(0,128,255);fill-opacity:0.5;stroke-width:1;stroke:rgb(0,0,0)";
 135 +$styles[7] = "fill:rgb(0,255,128);fill-opacity:0.5;stroke-width:1;stroke:rgb(0,0,0)";
 136 +$styles[8] = "fill:rgb(255,0,128);fill-opacity:0.5;stroke-width:1;stroke:rgb(0,0,0)";
 137 +$styles[9] = "fill:rgb(255,255,128);fill-opacity:0.5;stroke-width:1;stroke:rgb(0,0,0)";
 138 +$styles[10] = "fill:rgb(255,128,255);fill-opacity:0.5;stroke-width:1;stroke:rgb(0,0,0)";
 139 +$styles[11] = "fill:rgb(128,255,255);fill-opacity:0.5;stroke-width:1;stroke:rgb(0,0,0)";
 140 +
 141 +my $mult = 950.0 / $maxtime;
 142 +my $threshold = 0.0500 / $maxtime;
 143 +my $stylecounter = 0;
 144 +while (($key,$value) = each %start) {
 145 +       my $duration = $end{$key} - $start{$key};
 146 +
 147 +       if ($duration >= $threshold) {
 148 +               my $s, $s2, $e, $y;
 149 +               $s = $value * $mult;
 150 +               $s2 = $s + 6;
 151 +               $e = $end{$key} * $mult;
 152 +               $w = $e - $s;
 153 +
 154 +               $y = $row{$key} * 150;
 155 +               $y2 = $y + 4;
 156 +
 157 +               $style = $styles[$stylecounter];
 158 +               $stylecounter = $stylecounter + 1;
 159 +               if ($stylecounter > 11) {
 160 +                       $stylecounter = 0;
 161 +               };
 162 +
 163 +               print "<rect x=\"$s\" width=\"$w\" y=\"$y\" height=\"145\" style=\"$style\"/>\n";
 164 +               print "<text transform=\"translate($s2,$y2) rotate(90)\">$key</text>\n";
 165 +       }
 166 +}
 167 +
 168 +
 169 +# print the time line on top
 170 +my $time = 0.0;
 171 +while ($time < $maxtime) {
 172 +       my $s2 = $time * $mult;
 173 +       print "<text transform=\"translate($s2,89) rotate(90)\">$time</text>\n";
 174 +       $time = $time + 0.1;
 175 +}
 176 +
 177 +print "</svg>\n";