1#!/usr/bin/perl 2 3# Copyright 2008, Intel Corporation 4# 5# This file is part of the Linux kernel 6# 7# This program file is free software; you can redistribute it and/or modify it 8# under the terms of the GNU General Public License as published by the 9# Free Software Foundation; version 2 of the License. 10# 11# This program is distributed in the hope that it will be useful, but WITHOUT 12# ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or 13# FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License 14# for more details. 15# 16# You should have received a copy of the GNU General Public License 17# along with this program in a file named COPYING; if not, write to the 18# Free Software Foundation, Inc., 19# 51 Franklin Street, Fifth Floor, 20# Boston, MA 02110-1301 USA 21# 22# Authors: 23# Arjan van de Ven <arjan@linux.intel.com> 24 25 26# 27# This script turns a dmesg output into a SVG graphic that shows which 28# functions take how much time. You can view SVG graphics with various 29# programs, including Inkscape, The Gimp and Firefox. 30# 31# 32# For this script to work, the kernel needs to be compiled with the 33# CONFIG_PRINTK_TIME configuration option enabled, and with 34# "initcall_debug" passed on the kernel command line. 35# 36# usage: 37# dmesg | perl scripts/bootgraph.pl > output.svg 38# 39 40use strict; 41use Getopt::Long; 42my $header = 0; 43 44sub help { 45 my $text = << "EOM"; 46Usage: 471) dmesg | perl scripts/bootgraph.pl [OPTION] > output.svg 482) perl scripts/bootgraph.pl -h 49 50Options: 51 -header Insert kernel version and date 52EOM 53 my $std=shift; 54 if ($std == 1) { 55 print STDERR $text; 56 } else { 57 print $text; 58 } 59 exit; 60} 61 62GetOptions( 63 'h|help' =>\&help, 64 'header' =>\$header 65); 66 67my %start; 68my %end; 69my %type; 70my $done = 0; 71my $maxtime = 0; 72my $firsttime = 99999; 73my $count = 0; 74my %pids; 75my %pidctr; 76 77my $headerstep = 20; 78my $xheader = 15; 79my $yheader = 25; 80my $cyheader = 0; 81 82while (<>) { 83 my $line = $_; 84 if ($line =~ /([0-9\.]+)\] calling ([a-zA-Z0-9\_\.]+)\+/) { 85 my $func = $2; 86 if ($done == 0) { 87 $start{$func} = $1; 88 $type{$func} = 0; 89 if ($1 < $firsttime) { 90 $firsttime = $1; 91 } 92 } 93 if ($line =~ /\@ ([0-9]+)/) { 94 $pids{$func} = $1; 95 } 96 $count = $count + 1; 97 } 98 99 if ($line =~ /([0-9\.]+)\] async_waiting @ ([0-9]+)/) { 100 my $pid = $2; 101 my $func; 102 if (!defined($pidctr{$pid})) { 103 $func = "wait_" . $pid . "_1"; 104 $pidctr{$pid} = 1; 105 } else { 106 $pidctr{$pid} = $pidctr{$pid} + 1; 107 $func = "wait_" . $pid . "_" . $pidctr{$pid}; 108 } 109 if ($done == 0) { 110 $start{$func} = $1; 111 $type{$func} = 1; 112 if ($1 < $firsttime) { 113 $firsttime = $1; 114 } 115 } 116 $pids{$func} = $pid; 117 $count = $count + 1; 118 } 119 120 if ($line =~ /([0-9\.]+)\] initcall ([a-zA-Z0-9\_\.]+)\+.*returned/) { 121 if ($done == 0) { 122 $end{$2} = $1; 123 $maxtime = $1; 124 } 125 } 126 127 if ($line =~ /([0-9\.]+)\] async_continuing @ ([0-9]+)/) { 128 my $pid = $2; 129 my $func = "wait_" . $pid . "_" . $pidctr{$pid}; 130 $end{$func} = $1; 131 $maxtime = $1; 132 } 133 if ($line =~ /Write protecting the/) { 134 $done = 1; 135 } 136 if ($line =~ /Freeing unused kernel memory/) { 137 $done = 1; 138 } 139} 140 141if ($count == 0) { 142 print STDERR <<END; 143No data found in the dmesg. Make sure that 'printk.time=1' and 144'initcall_debug' are passed on the kernel command line. 145END 146 help(1); 147 exit 1; 148} 149 150print "<?xml version=\"1.0\" standalone=\"no\"?> \n"; 151print "<svg width=\"2000\" height=\"100%\" version=\"1.1\" xmlns=\"http://www.w3.org/2000/svg\">\n"; 152 153 154if ($header) { 155 my $version = `uname -a`; 156 my $date = `date`; 157 print "<text transform=\"translate($xheader,$yheader)\">Kernel version: $version</text>\n"; 158 $cyheader = $yheader+$headerstep; 159 print "<text transform=\"translate($xheader,$cyheader)\">Date: $date</text>\n"; 160} 161 162my @styles; 163 164$styles[0] = "fill:rgb(0,0,255);fill-opacity:0.5;stroke-width:1;stroke:rgb(0,0,0)"; 165$styles[1] = "fill:rgb(0,255,0);fill-opacity:0.5;stroke-width:1;stroke:rgb(0,0,0)"; 166$styles[2] = "fill:rgb(255,0,20);fill-opacity:0.5;stroke-width:1;stroke:rgb(0,0,0)"; 167$styles[3] = "fill:rgb(255,255,20);fill-opacity:0.5;stroke-width:1;stroke:rgb(0,0,0)"; 168$styles[4] = "fill:rgb(255,0,255);fill-opacity:0.5;stroke-width:1;stroke:rgb(0,0,0)"; 169$styles[5] = "fill:rgb(0,255,255);fill-opacity:0.5;stroke-width:1;stroke:rgb(0,0,0)"; 170$styles[6] = "fill:rgb(0,128,255);fill-opacity:0.5;stroke-width:1;stroke:rgb(0,0,0)"; 171$styles[7] = "fill:rgb(0,255,128);fill-opacity:0.5;stroke-width:1;stroke:rgb(0,0,0)"; 172$styles[8] = "fill:rgb(255,0,128);fill-opacity:0.5;stroke-width:1;stroke:rgb(0,0,0)"; 173$styles[9] = "fill:rgb(255,255,128);fill-opacity:0.5;stroke-width:1;stroke:rgb(0,0,0)"; 174$styles[10] = "fill:rgb(255,128,255);fill-opacity:0.5;stroke-width:1;stroke:rgb(0,0,0)"; 175$styles[11] = "fill:rgb(128,255,255);fill-opacity:0.5;stroke-width:1;stroke:rgb(0,0,0)"; 176 177my $style_wait = "fill:rgb(128,128,128);fill-opacity:0.5;stroke-width:0;stroke:rgb(0,0,0)"; 178 179my $mult = 1950.0 / ($maxtime - $firsttime); 180my $threshold2 = ($maxtime - $firsttime) / 120.0; 181my $threshold = $threshold2/10; 182my $stylecounter = 0; 183my %rows; 184my $rowscount = 1; 185my @initcalls = sort { $start{$a} <=> $start{$b} } keys(%start); 186 187foreach my $key (@initcalls) { 188 my $duration = $end{$key} - $start{$key}; 189 190 if ($duration >= $threshold) { 191 my ($s, $s2, $s3, $e, $w, $y, $y2, $style); 192 my $pid = $pids{$key}; 193 194 if (!defined($rows{$pid})) { 195 $rows{$pid} = $rowscount; 196 $rowscount = $rowscount + 1; 197 } 198 $s = ($start{$key} - $firsttime) * $mult; 199 $s2 = $s + 6; 200 $s3 = $s + 1; 201 $e = ($end{$key} - $firsttime) * $mult; 202 $w = $e - $s; 203 204 $y = $rows{$pid} * 150; 205 $y2 = $y + 4; 206 207 $style = $styles[$stylecounter]; 208 $stylecounter = $stylecounter + 1; 209 if ($stylecounter > 11) { 210 $stylecounter = 0; 211 }; 212 213 if ($type{$key} == 1) { 214 $y = $y + 15; 215 print "<rect x=\"$s\" width=\"$w\" y=\"$y\" height=\"115\" style=\"$style_wait\"/>\n"; 216 } else { 217 print "<rect x=\"$s\" width=\"$w\" y=\"$y\" height=\"145\" style=\"$style\"/>\n"; 218 if ($duration >= $threshold2) { 219 print "<text transform=\"translate($s2,$y2) rotate(90)\">$key</text>\n"; 220 } else { 221 print "<text transform=\"translate($s3,$y2) rotate(90)\" font-size=\"3pt\">$key</text>\n"; 222 } 223 } 224 } 225} 226 227 228# print the time line on top 229my $time = $firsttime; 230my $step = ($maxtime - $firsttime) / 15; 231while ($time < $maxtime) { 232 my $s3 = ($time - $firsttime) * $mult; 233 my $tm = int($time * 100) / 100.0; 234 print "<text transform=\"translate($s3,89) rotate(90)\">$tm</text>\n"; 235 $time = $time + $step; 236} 237 238print "</svg>\n"; 239