From mboxrd@z Thu Jan 1 00:00:00 1970 From: Todd Brandt Subject: [PATCH RESEND] AnalyzeBoot v1.1 Date: Thu, 9 Feb 2017 13:14:51 -0800 Message-ID: <1486674891-20882-1-git-send-email-todd.e.brandt@linux.intel.com> Return-path: Received: from mga06.intel.com ([134.134.136.31]:24274 "EHLO mga06.intel.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S932651AbdBIVSD (ORCPT ); Thu, 9 Feb 2017 16:18:03 -0500 Sender: linux-pm-owner@vger.kernel.org List-Id: linux-pm@vger.kernel.org To: linux-pm@vger.kernel.org Cc: todd.e.brandt@intel.com, rjw@rjwysocki.net, rafael.j.wysocki@intel.com, Todd Brandt This tool reads in a dmesg log of linux kernel boot and creates an html representation of the boot timeline up to the start of the init process. It's basically an html version of boograph.pl. If no arguments are given the tool reads the local dmesg log and outputs bootgraph.html. Signed-off-by: Todd Brandt --- scripts/analyze_boot.py | 832 ++++++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 832 insertions(+) create mode 100755 scripts/analyze_boot.py diff --git a/scripts/analyze_boot.py b/scripts/analyze_boot.py new file mode 100755 index 0000000..f928bd3 --- /dev/null +++ b/scripts/analyze_boot.py @@ -0,0 +1,832 @@ +#!/usr/bin/python +# +# Tool for analyzing boot timing +# Copyright (c) 2013, Intel Corporation. +# +# This program is free software; you can redistribute it and/or modify it +# under the terms and conditions of the GNU General Public License, +# version 2, as published by the Free Software Foundation. +# +# This program is distributed in the hope it will be useful, but WITHOUT +# ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or +# FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License for +# more details. +# +# You should have received a copy of the GNU General Public License along with +# this program; if not, write to the Free Software Foundation, Inc., +# 51 Franklin St - Fifth Floor, Boston, MA 02110-1301 USA. +# +# Authors: +# Todd Brandt +# +# Description: +# This tool is designed to assist kernel and OS developers in optimizing +# their linux stack's boot time. It creates an html representation of +# the kernel boot timeline up to the start of the init process. +# +# The following additional kernel parameters are required: +# (e.g. in file /etc/default/grub) +# GRUB_CMDLINE_LINUX_DEFAULT="... initcall_debug log_buf_len=16M ..." +# + +# ----------------- LIBRARIES -------------------- + +import sys +import time +import os +import string +import re +import platform +from datetime import datetime, timedelta +from subprocess import Popen, PIPE + +# ----------------- CLASSES -------------------- + +# Class: SystemValues +# Description: +# A global, single-instance container used to +# store system values and test parameters +class SystemValues: + version = 1.1 + hostname = 'localhost' + testtime = '' + kernel = '' + dmesgfile = '' + htmlfile = 'bootgraph.html' + outfile = '' + phoronix = False + addlogs = False + def __init__(self): + if('LOG_FILE' in os.environ and 'TEST_RESULTS_IDENTIFIER' in os.environ): + self.phoronix = True + self.addlogs = True + self.outfile = os.environ['LOG_FILE'] + self.htmlfile = os.environ['LOG_FILE'] + self.hostname = platform.node() + self.testtime = datetime.now().strftime('%Y-%m-%d_%H:%M:%S') + fp = open('/proc/version', 'r') + val = fp.read().strip() + fp.close() + self.kernel = self.kernelVersion(val) + def kernelVersion(self, msg): + return msg.split()[2] +sysvals = SystemValues() + +# Class: Data +# Description: +# The primary container for test data. +class Data: + dmesg = {} # root data structure + start = 0.0 # test start + end = 0.0 # test end + dmesgtext = [] # dmesg text file in memory + testnumber = 0 + idstr = '' + html_device_id = 0 + stamp = 0 + valid = False + initstart = 0.0 + boottime = '' + def __init__(self, num): + idchar = 'abcde' + self.testnumber = num + self.idstr = idchar[num] + self.dmesgtext = [] + self.dmesg = { + 'boot': {'list': dict(), 'start': -1.0, 'end': -1.0, 'row': 0} + } + def newAction(self, phase, name, pid, parent, start, end, drv): + # new device callback for a specific phase + self.html_device_id += 1 + devid = '%s%d' % (self.idstr, self.html_device_id) + list = self.dmesg[phase]['list'] + length = -1.0 + if(start >= 0 and end >= 0): + length = end - start + list[name] = {'start': start, 'end': end, 'pid': pid, 'par': parent, + 'length': length, 'row': 0, 'id': devid, 'drv': drv } + +# Class: Timeline +# Description: +# A container for a device timeline which calculates +# all the html properties to display it correctly +class Timeline: + html = {} + height = 0 # total timeline height + scaleH = 20 # timescale (top) row height + rowH = 30 # device row height + bodyH = 0 # body height + rows = 0 # total timeline rows + def __init__(self): + self.html = { + 'header': '', + 'timeline': '', + 'legend': '', + 'scale': '' + } + # Function: calcTotalRows + # Description: + # Calculate the heights and offsets for the header and rows + def calcTotalRows(self): + self.height = self.scaleH + (self.rows*self.rowH) + self.bodyH = self.height - self.scaleH + # Function: getPhaseRows + # Description: + # Organize the timeline entries into the smallest + # number of rows possible, with no entry overlapping + # Arguments: + # list: the list of devices/actions for a single phase + # sortedkeys: cronologically sorted key list to use + # Output: + # The total number of rows needed to display this phase of the timeline + def getPhaseRows(self, list, sortedkeys): + # clear all rows and set them to undefined + remaining = len(list) + rowdata = dict() + row = 0 + for item in list: + list[item]['row'] = -1 + # try to pack each row with as many ranges as possible + while(remaining > 0): + if(row not in rowdata): + rowdata[row] = [] + for item in sortedkeys: + if(list[item]['row'] < 0): + s = list[item]['start'] + e = list[item]['end'] + valid = True + for ritem in rowdata[row]: + rs = ritem['start'] + rn = ritem['end'] + if(not (((s <= rs) and (e <= rs)) or + ((s >= rn) and (e >= rn)))): + valid = False + break + if(valid): + rowdata[row].append(list[item]) + list[item]['row'] = row + remaining -= 1 + row += 1 + if(row > self.rows): + self.rows = int(row) + return row + # Function: createTimeScale + # Description: + # Create the timescale header for the html timeline + # Arguments: + # t0: start time + # tMax: end time + # Output: + # The html code needed to display the time scale + def createTimeScale(self, t0, tMax): + timescale = '
{1}
\n' + output = '
\n' + # set scale for timeline + tTotal = tMax - t0 + tS = 0.1 + if(tTotal <= 0): + return output + if(tTotal > 4): + tS = 1 + divTotal = int(tTotal/tS) + 1 + for i in range(divTotal): + pos = '%0.3f' % (100 - ((float(i)*tS*100)/tTotal)) + if(i == 0): + val = '' + else: + val = '%0.fms' % (float(i)*tS*1000) + output += timescale.format(pos, val) + output += '
\n' + self.html['scale'] = output + +# ----------------- FUNCTIONS -------------------- + +# Function: loadKernelLog +# Description: +# Load a raw kernel log from dmesg +def loadKernelLog(): + data = Data(0) + data.dmesg['boot']['start'] = data.start = ktime = 0.0 + data.stamp = { + 'time': datetime.now().strftime('%B %d %Y, %I:%M:%S %p'), + 'host': sysvals.hostname, + 'mode': 'boot', 'kernel': ''} + + if(sysvals.dmesgfile): + lf = open(sysvals.dmesgfile, 'r') + else: + lf = Popen('dmesg', stdout=PIPE).stdout + for line in lf: + line = line.replace('\r\n', '') + idx = line.find('[') + if idx > 1: + line = line[idx:] + m = re.match('[ \t]*(\[ *)(?P[0-9\.]*)(\]) (?P.*)', line) + if(not m): + continue + ktime = float(m.group('ktime')) + if(ktime > 120): + break + msg = m.group('msg') + data.end = data.initstart = ktime + data.dmesgtext.append(line) + if(ktime == 0.0 and re.match('^Linux version .*', msg)): + if(not data.stamp['kernel']): + data.stamp['kernel'] = sysvals.kernelVersion(msg) + continue + m = re.match('.* setting system clock to (?P.*) UTC.*', msg) + if(m): + utc = int((datetime.now() - datetime.utcnow()).total_seconds()) + bt = datetime.strptime(m.group('t'), '%Y-%m-%d %H:%M:%S') + bt = bt - timedelta(seconds=int(ktime)-utc) + data.boottime = bt.strftime('%Y-%m-%d_%H:%M:%S') + data.stamp['time'] = bt.strftime('%B %d %Y, %I:%M:%S %p') + continue + m = re.match('^calling *(?P.*)\+.*', msg) + if(m): + data.valid = True + f = m.group('f') + data.newAction('boot', f, 0, '', ktime, -1, '') + continue + m = re.match('^initcall *(?P.*)\+.*', msg) + if(m): + f = m.group('f') + list = data.dmesg['boot']['list'] + if(f in list): + dev = list[f] + dev['end'] = ktime + data.end = ktime + continue + if(re.match('^Freeing unused kernel memory.*', msg)): + break + + data.dmesg['boot']['end'] = data.end + lf.close() + return data + +# Function: colorForName +# Description: +# Generate a repeatable color from a list for a given name +def colorForName(name, list): + i = 0 + total = 0 + count = len(list) + while i < len(name): + total += ord(name[i]) + i += 1 + return list[total % count] + +# Function: createBootGraph +# Description: +# Create the output html file from the resident test data +# Arguments: +# testruns: array of Data objects from parseKernelLog or parseTraceLog +# Output: +# True if the html file was created, false if it failed +def createBootGraph(data, embedded): + # html function templates + headline_version = '
AnalyzeBoot v%s
' % sysvals.version + headline_stamp = '
{0} {1} {2} {3}
\n' + html_zoombox = '
\n' + html_timeline = '
\n
\n' + html_device = '
{6}
\n' + html_phase = '
{5}
\n' + html_phaselet = '
\n' + html_timetotal = '\n'\ + ''\ + '\n
Time from Kernel Boot to start of User Mode: {0} ms
\n' + + # device timeline + devtl = Timeline() + devtl.rowH = 100 + + # Generate the header for this timeline + t0 = data.start + tMax = data.end + tTotal = tMax - t0 + if(tTotal == 0): + print('ERROR: No timeline data') + return False + boot_time = '%.0f'%(tTotal*1000) + devtl.html['timeline'] += html_timetotal.format(boot_time) + + # determine the maximum number of rows we need to draw + phase = 'boot' + list = data.dmesg[phase]['list'] + data.dmesg[phase]['row'] = devtl.getPhaseRows(list, list) + devtl.calcTotalRows() + + # create bounding box, add buttons + devtl.html['timeline'] += html_zoombox + devtl.html['timeline'] += html_timeline.format('dmesg', devtl.height) + + # draw the colored boxes for each of the phases + boot = data.dmesg[phase] + length = boot['end']-boot['start'] + left = '%.3f' % (((boot['start']-t0)*100.0)/tTotal) + width = '%.3f' % ((length*100.0)/tTotal) + devtl.html['timeline'] += html_phase.format('0', '100', \ + '%.3f'%devtl.scaleH, '%.3f'%devtl.bodyH, \ + 'white', '') + + # draw the time scale, try to make the number of labels readable + devtl.createTimeScale(t0, tMax) + devtl.html['timeline'] += devtl.html['scale'] + + # draw the device timeline + phaselist = data.dmesg[phase]['list'] + color = ['c1', 'c2', 'c3', 'c4', 'c5', + 'c6', 'c7', 'c8', 'c9', 'c10'] + for d in phaselist: + name = d + c = colorForName(name, color) + dev = phaselist[d] + height = devtl.bodyH/data.dmesg[phase]['row'] + top = '%.3f' % ((dev['row']*height) + devtl.scaleH) + left = '%.3f' % (((dev['start']-t0)*100)/tTotal) + width = '%.3f' % (((dev['end']-dev['start'])*100)/tTotal) + length = ' (%0.3f ms) ' % ((dev['end']-dev['start'])*1000) + devtl.html['timeline'] += html_device.format(dev['id'], \ + d+length+'kernel_mode', left, top, '%.3f'%height, width, name, ' '+c) + + # timeline is finished + devtl.html['timeline'] += '
\n
\n' + + if(sysvals.outfile == sysvals.htmlfile): + hf = open(sysvals.htmlfile, 'a') + else: + hf = open(sysvals.htmlfile, 'w') + + # write the html header first (html head, css code, up to body start) + html_header = '\n\n\n\ + \n\ + Boot Graph\n\ + \n\n\n' + + # no header or css if its embedded + if(not embedded): + hf.write(html_header) + + # write the test title and general info header + if(data.stamp['time'] != ""): + hf.write(headline_version) + if sysvals.addlogs: + hf.write('') + hf.write(headline_stamp.format(data.stamp['host'], + data.stamp['kernel'], 'boot', \ + data.stamp['time'])) + + # write the device timeline + hf.write(devtl.html['timeline']) + + # draw the colored boxes for the device detail section + hf.write('
\n') + hf.write('\n') + + # add the dmesg log as a hidden div + if sysvals.addlogs: + hf.write('\n') + + if(not embedded): + # write the footer and close + addScriptCode(hf, [data]) + hf.write('\n\n') + else: + # embedded out will be loaded in a page, skip the js + hf.write('' % \ + (data.start*1000, data.initstart*1000)) + hf.close() + return True + +# Function: addScriptCode +# Description: +# Adds the javascript code to the output html +# Arguments: +# hf: the open html file pointer +# testruns: array of Data objects from parseKernelLog or parseTraceLog +def addScriptCode(hf, testruns): + t0 = testruns[0].start * 1000 + tMax = testruns[-1].end * 1000 + # create an array in javascript memory with the device details + detail = ' var devtable = [];\n' + detail += ' var bounds = [%f,%f];\n' % (t0, tMax) + # add the code which will manipulate the data in the browser + script_code = \ + script_code = \ + '\n' + hf.write(script_code); + +# Function: doError +# Description: +# generic error function for catastrphic failures +# Arguments: +# msg: the error message to print +# help: True if printHelp should be called after, False otherwise +def doError(msg, help=False): + if(help == True): + printHelp() + print('ERROR: %s\n') % msg + sys.exit() + +# Function: printHelp +# Description: +# print out the help text +def printHelp(): + print('') + print('AnalyzeBoot v%.1f' % sysvals.version) + print('Usage: analyze_boot.py ') + print('') + print('Description:') + print(' This tool reads in a dmesg log of linux kernel boot and') + print(' creates an html representation of the boot timeline up to') + print(' the start of the init process.') + print(' If no arguments are given the tool reads the host dmesg log') + print(' and outputs bootgraph.html') + print('') + print('Options:') + print(' -h Print this help text') + print(' -v Print the current tool version') + print(' -dmesg dmesgfile Load a stored dmesg file') + print(' -html file Html timeline name (default: bootgraph.html)') + print(' -addlogs Add the dmesg log to the html output') + print('') + return True + +# ----------------- MAIN -------------------- +# exec start (skipped if script is loaded as library) +if __name__ == '__main__': + # loop through the command line arguments + args = iter(sys.argv[1:]) + for arg in args: + if(arg == '-h'): + printHelp() + sys.exit() + elif(arg == '-v'): + print("Version %.1f" % sysvals.version) + sys.exit() + elif(arg == '-addlogs'): + sysvals.addlogs = True + elif(arg == '-dmesg'): + try: + val = args.next() + except: + doError('No dmesg file supplied', True) + if(os.path.exists(val) == False): + doError('%s doesnt exist' % val) + if(sysvals.htmlfile == val or sysvals.outfile == val): + doError('Output filename collision') + sysvals.dmesgfile = val + elif(arg == '-html'): + try: + val = args.next() + except: + doError('No HTML filename supplied', True) + if(sysvals.dmesgfile == val): + doError('Output filename collision') + sysvals.htmlfile = val + else: + doError('Invalid argument: '+arg, True) + + data = loadKernelLog() + if(sysvals.outfile and sysvals.phoronix): + fp = open(sysvals.outfile, 'w') + fp.write('pass %s initstart %.3f end %.3f boot %s\n' % + (data.valid, data.initstart*1000, data.end*1000, data.boottime)) + fp.close() + if(not data.valid): + if sysvals.dmesgfile: + doError('No initcall data found in %s' % sysvals.dmesgfile) + else: + doError('No initcall data found, is initcall_debug enabled?') + + print(' Host: %s' % sysvals.hostname) + print(' Test time: %s' % sysvals.testtime) + print(' Boot time: %s' % data.boottime) + print('Kernel Version: %s' % sysvals.kernel) + print(' Kernel start: %.3f' % (data.start * 1000)) + print(' init start: %.3f' % (data.initstart * 1000)) + + createBootGraph(data, sysvals.phoronix) -- 2.1.4