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