pm-graph: AnalyzeBoot v2.2
authorTodd E Brandt <todd.e.brandt@linux.intel.com>
Tue, 30 Jan 2018 08:17:19 +0000 (00:17 -0800)
committerRafael J. Wysocki <rafael.j.wysocki@intel.com>
Wed, 21 Feb 2018 22:56:22 +0000 (23:56 +0100)
- add -cgskip option to reduce callgraph output size
- add -cgfilter option to focus on a list of devices
- add -result option for exporting batch test results
- removed all phoronix hooks, use -result to enable batch testing
- changed argument -f to match sleegraph, -f = -callgraph
- use -fstat for function status instead of -f
- add -verbose option to print out timeline stats and kernel options
- include command string and kernel params in timeline output header

Signed-off-by: Todd Brandt <todd.e.brandt@linux.intel.com>
Signed-off-by: Rafael J. Wysocki <rafael.j.wysocki@intel.com>
tools/power/pm-graph/bootgraph.8
tools/power/pm-graph/bootgraph.py

index dbdafcf..64d513f 100644 (file)
@@ -37,6 +37,9 @@ Print the current tool version
 Add the dmesg log to the html output. It will be viewable by
 clicking a button in the timeline.
 .TP
+\fB-result \fIfile\fR
+Export a results table to a text file for parsing.
+.TP
 \fB-o \fIname\fR
 Overrides the output subdirectory name when running a new test.
 Use {date}, {time}, {hostname} for current values.
@@ -44,14 +47,14 @@ Use {date}, {time}, {hostname} for current values.
 e.g. boot-{hostname}-{date}-{time}
 .SS "advanced"
 .TP
-\fB-f\fR
-Use ftrace to add function detail (default: disabled)
-.TP
-\fB-callgraph\fR
+\fB-f or -callgraph\fR
 Use ftrace to create initcall callgraphs (default: disabled). If -func
 is not used there will be one callgraph per initcall. This can produce
 very large outputs, i.e. 10MB - 100MB.
 .TP
+\fB-fstat\fR
+Use ftrace to add function detail (default: disabled)
+.TP
 \fB-maxdepth \fIlevel\fR
 limit the callgraph trace depth to \fIlevel\fR (default: 2). This is
 the best way to limit the output size when using -callgraph.
@@ -67,6 +70,13 @@ Reduce callgraph output in the timeline by limiting it to a list of calls. The
 argument can be a single function name or a comma delimited list.
 (default: none)
 .TP
+\fB-cgskip \fIfile\fR
+Reduce callgraph output in the timeline by skipping over uninteresting
+functions in the trace, e.g. printk or console_unlock. The functions listed
+in this file will show up as empty leaves in the callgraph with only the start/end
+times displayed.
+(default: none)
+.TP
 \fB-timeprec \fIn\fR
 Number of significant digits in timestamps (0:S, 3:ms, [6:us])
 .TP
index e83df14..abb4c38 100755 (executable)
@@ -32,7 +32,7 @@ import platform
 import shutil
 from datetime import datetime, timedelta
 from subprocess import call, Popen, PIPE
-import analyze_suspend as aslib
+import sleepgraph as aslib
 
 # ----------------- CLASSES --------------------
 
@@ -42,23 +42,18 @@ import analyze_suspend as aslib
 #       store system values and test parameters
 class SystemValues(aslib.SystemValues):
        title = 'BootGraph'
-       version = '2.1'
+       version = '2.2'
        hostname = 'localhost'
        testtime = ''
        kernel = ''
        dmesgfile = ''
        ftracefile = ''
        htmlfile = 'bootgraph.html'
-       outfile = ''
        testdir = ''
-       testdirprefix = 'boot'
-       embedded = False
-       testlog = False
-       dmesglog = False
-       ftracelog = False
+       kparams = ''
+       result = ''
        useftrace = False
        usecallgraph = False
-       usedevsrc = True
        suspendmode = 'boot'
        max_graph_depth = 2
        graph_filter = 'do_one_initcall'
@@ -69,11 +64,6 @@ class SystemValues(aslib.SystemValues):
        bootloader = 'grub'
        blexec = []
        def __init__(self):
-               if('LOG_FILE' in os.environ and 'TEST_RESULTS_IDENTIFIER' in os.environ):
-                       self.embedded = True
-                       self.dmesglog = 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')
                if os.path.exists('/proc/version'):
@@ -148,11 +138,18 @@ class SystemValues(aslib.SystemValues):
                cmdline = '%s -cronjob' % os.path.abspath(sys.argv[0])
                args = iter(sys.argv[1:])
                for arg in args:
-                       if arg in ['-h', '-v', '-cronjob', '-reboot']:
+                       if arg in ['-h', '-v', '-cronjob', '-reboot', '-verbose']:
                                continue
                        elif arg in ['-o', '-dmesg', '-ftrace', '-func']:
                                args.next()
                                continue
+                       elif arg == '-result':
+                               cmdline += ' %s "%s"' % (arg, os.path.abspath(args.next()))
+                               continue
+                       elif arg == '-cgskip':
+                               file = self.configFile(args.next())
+                               cmdline += ' %s "%s"' % (arg, os.path.abspath(file))
+                               continue
                        cmdline += ' '+arg
                if self.graph_filter != 'do_one_initcall':
                        cmdline += ' -func "%s"' % self.graph_filter
@@ -166,14 +163,6 @@ class SystemValues(aslib.SystemValues):
                print '3. After reboot, re-run this tool with the same arguments but no command (w/o -reboot or -manual).\n'
                print 'CMDLINE="%s"' % cmdline
                sys.exit()
-       def getExec(self, cmd):
-               dirlist = ['/sbin', '/bin', '/usr/sbin', '/usr/bin',
-                       '/usr/local/sbin', '/usr/local/bin']
-               for path in dirlist:
-                       cmdfull = os.path.join(path, cmd)
-                       if os.path.exists(cmdfull):
-                               return cmdfull
-               return ''
        def blGrub(self):
                blcmd = ''
                for cmd in ['update-grub', 'grub-mkconfig', 'grub2-mkconfig']:
@@ -199,6 +188,14 @@ class SystemValues(aslib.SystemValues):
                        self.blGrub()
                else:
                        doError('unknown boot loader: %s' % self.bootloader)
+       def writeDatafileHeader(self, filename):
+               self.kparams = open('/proc/cmdline', 'r').read().strip()
+               fp = open(filename, 'w')
+               fp.write(self.teststamp+'\n')
+               fp.write(self.sysstamp+'\n')
+               fp.write('# command | %s\n' % self.cmdline)
+               fp.write('# kparams | %s\n' % self.kparams)
+               fp.close()
 
 sysvals = SystemValues()
 
@@ -249,7 +246,7 @@ class Data(aslib.Data):
                return name
        def deviceMatch(self, pid, cg):
                if cg.end - cg.start == 0:
-                       return True
+                       return ''
                for p in data.phases:
                        list = self.dmesg[p]['list']
                        for devname in list:
@@ -260,14 +257,25 @@ class Data(aslib.Data):
                                        if(cg.start <= dev['start'] and cg.end >= dev['end'] and dev['length'] > 0):
                                                dev['ftrace'] = cg
                                                self.do_one_initcall = True
-                                               return True
+                                               return devname
                                else:
                                        if(cg.start > dev['start'] and cg.end < dev['end']):
                                                if 'ftraces' not in dev:
                                                        dev['ftraces'] = []
                                                dev['ftraces'].append(cg)
-                                               return True
-               return False
+                                               return devname
+               return ''
+       def printDetails(self):
+               sysvals.vprint('Timeline Details:')
+               sysvals.vprint('          Host: %s' % sysvals.hostname)
+               sysvals.vprint('        Kernel: %s' % sysvals.kernel)
+               sysvals.vprint('     Test time: %s' % sysvals.testtime)
+               sysvals.vprint('     Boot time: %s' % self.boottime)
+               for phase in self.phases:
+                       dc = len(self.dmesg[phase]['list'])
+                       sysvals.vprint('%9s mode: %.3f - %.3f (%d initcalls)' % (phase,
+                               self.dmesg[phase]['start']*1000,
+                               self.dmesg[phase]['end']*1000, dc))
 
 # ----------------- FUNCTIONS --------------------
 
@@ -275,6 +283,8 @@ class Data(aslib.Data):
 # Description:
 #       parse a kernel log for boot data
 def parseKernelLog():
+       sysvals.vprint('Analyzing the dmesg data (%s)...' % \
+               os.path.basename(sysvals.dmesgfile))
        phase = 'kernel'
        data = Data(0)
        data.dmesg['kernel']['start'] = data.start = ktime = 0.0
@@ -298,6 +308,12 @@ def parseKernelLog():
                elif re.match(tp.sysinfofmt, line):
                        tp.sysinfo = line
                        continue
+               elif re.match(tp.cmdlinefmt, line):
+                       tp.cmdline = line
+                       continue
+               elif re.match(tp.kparamsfmt, line):
+                       tp.kparams = line
+                       continue
                idx = line.find('[')
                if idx > 1:
                        line = line[idx:]
@@ -353,6 +369,17 @@ def parseKernelLog():
 # Description:
 #       Check if trace is available and copy to a temp file
 def parseTraceLog(data):
+       sysvals.vprint('Analyzing the ftrace data (%s)...' % \
+               os.path.basename(sysvals.ftracefile))
+       # if available, calculate cgfilter allowable ranges
+       cgfilter = []
+       if len(sysvals.cgfilter) > 0:
+               for p in data.phases:
+                       list = data.dmesg[p]['list']
+                       for i in sysvals.cgfilter:
+                               if i in list:
+                                       cgfilter.append([list[i]['start']-0.0001,
+                                               list[i]['end']+0.0001])
        # parse the trace log
        ftemp = dict()
        tp = aslib.TestProps()
@@ -366,7 +393,16 @@ def parseTraceLog(data):
                        continue
                m_time, m_proc, m_pid, m_msg, m_dur = \
                        m.group('time', 'proc', 'pid', 'msg', 'dur')
-               if float(m_time) > data.end:
+               t = float(m_time)
+               if len(cgfilter) > 0:
+                       allow = False
+                       for r in cgfilter:
+                               if t >= r[0] and t < r[1]:
+                                       allow = True
+                                       break
+                       if not allow:
+                               continue
+               if t > data.end:
                        break
                if(m_time and m_pid and m_msg):
                        t = aslib.FTraceLine(m_time, m_msg, m_dur)
@@ -378,24 +414,36 @@ def parseTraceLog(data):
                key = (m_proc, pid)
                if(key not in ftemp):
                        ftemp[key] = []
-                       ftemp[key].append(aslib.FTraceCallGraph(pid))
+                       ftemp[key].append(aslib.FTraceCallGraph(pid, sysvals))
                cg = ftemp[key][-1]
-               if(cg.addLine(t)):
-                       ftemp[key].append(aslib.FTraceCallGraph(pid))
+               res = cg.addLine(t)
+               if(res != 0):
+                       ftemp[key].append(aslib.FTraceCallGraph(pid, sysvals))
+               if(res == -1):
+                       ftemp[key][-1].addLine(t)
+
        tf.close()
 
        # add the callgraph data to the device hierarchy
        for key in ftemp:
                proc, pid = key
                for cg in ftemp[key]:
-                       if len(cg.list) < 1 or cg.invalid:
+                       if len(cg.list) < 1 or cg.invalid or (cg.end - cg.start == 0):
                                continue
                        if(not cg.postProcess()):
                                print('Sanity check failed for %s-%d' % (proc, pid))
                                continue
                        # match cg data to devices
-                       if not data.deviceMatch(pid, cg):
-                               print ' BAD: %s %s-%d [%f - %f]' % (cg.name, proc, pid, cg.start, cg.end)
+                       devname = data.deviceMatch(pid, cg)
+                       if not devname:
+                               kind = 'Orphan'
+                               if cg.partial:
+                                       kind = 'Partial'
+                               sysvals.vprint('%s callgraph found for %s %s-%d [%f - %f]' %\
+                                       (kind, cg.name, proc, pid, cg.start, cg.end))
+                       elif len(cg.list) > 1000000:
+                               print 'WARNING: the callgraph found for %s is massive! (%d lines)' %\
+                                       (devname, len(cg.list))
 
 # Function: retrieveLogs
 # Description:
@@ -473,7 +521,7 @@ def createBootGraph(data):
        devtl = aslib.Timeline(100, 20)
 
        # write the test title and general info header
-       devtl.createHeader(sysvals)
+       devtl.createHeader(sysvals, sysvals.stamp)
 
        # Generate the header for this timeline
        t0 = data.start
@@ -574,12 +622,9 @@ def createBootGraph(data):
                        data.dmesg[phase]['color'], phase+'_mode', phase[0])
        devtl.html += '</div>\n'
 
-       if(sysvals.outfile == sysvals.htmlfile):
-               hf = open(sysvals.htmlfile, 'a')
-       else:
-               hf = open(sysvals.htmlfile, 'w')
+       hf = open(sysvals.htmlfile, 'w')
 
-       # add the css if this is not an embedded run
+       # add the css
        extra = '\
                .c1 {background:rgba(209,0,0,0.4);}\n\
                .c2 {background:rgba(255,102,34,0.4);}\n\
@@ -597,8 +642,7 @@ def createBootGraph(data):
                .fstat td {text-align:left;width:35px;}\n\
                .srccall {position:absolute;font-size:10px;z-index:7;overflow:hidden;color:black;text-align:center;white-space:nowrap;border-radius:5px;border:1px solid black;background:linear-gradient(to bottom right,#CCC,#969696);}\n\
                .srccall:hover {color:white;font-weight:bold;border:1px solid white;}\n'
-       if(not sysvals.embedded):
-               aslib.addCSS(hf, sysvals, 1, False, extra)
+       aslib.addCSS(hf, sysvals, 1, False, extra)
 
        # write the device timeline
        hf.write(devtl.html)
@@ -631,6 +675,9 @@ def createBootGraph(data):
        if(sysvals.usecallgraph):
                aslib.addCallgraphs(sysvals, hf, data)
 
+       # add the test log as a hidden div
+       if sysvals.testlog and sysvals.logmsg:
+               hf.write('<div id="testlog" style="display:none;">\n'+sysvals.logmsg+'</div>\n')
        # add the dmesg log as a hidden div
        if sysvals.dmesglog:
                hf.write('<div id="dmesglog" style="display:none;">\n')
@@ -639,14 +686,9 @@ def createBootGraph(data):
                        hf.write(line)
                hf.write('</div>\n')
 
-       if(not sysvals.embedded):
-               # write the footer and close
-               aslib.addScriptCode(hf, [data])
-               hf.write('</body>\n</html>\n')
-       else:
-               # embedded out will be loaded in a page, skip the js
-               hf.write('<div id=bounds style=display:none>%f,%f</div>' % \
-                       (data.start*1000, data.end*1000))
+       # write the footer and close
+       aslib.addScriptCode(hf, [data])
+       hf.write('</body>\n</html>\n')
        hf.close()
        return True
 
@@ -780,6 +822,7 @@ def doError(msg, help=False):
        if help == True:
                printHelp()
        print 'ERROR: %s\n' % msg
+       sysvals.outputResult({'error':msg})
        sys.exit()
 
 # Function: printHelp
@@ -806,18 +849,21 @@ def printHelp():
        print('Options:')
        print('  -h            Print this help text')
        print('  -v            Print the current tool version')
+       print('  -verbose      Print extra information during execution and analysis')
        print('  -addlogs      Add the dmesg log to the html output')
+       print('  -result fn    Export a results table to a text file for parsing.')
        print('  -o name       Overrides the output subdirectory name when running a new test')
        print('                default: boot-{date}-{time}')
        print(' [advanced]')
-       print('  -f            Use ftrace to add function detail (default: disabled)')
-       print('  -callgraph    Add callgraph detail, can be very large (default: disabled)')
+       print('  -fstat        Use ftrace to add function detail and statistics (default: disabled)')
+       print('  -f/-callgraph Add callgraph detail, can be very large (default: disabled)')
        print('  -maxdepth N   limit the callgraph data to N call levels (default: 2)')
        print('  -mincg ms     Discard all callgraphs shorter than ms milliseconds (e.g. 0.001 for us)')
        print('  -timeprec N   Number of significant digits in timestamps (0:S, 3:ms, [6:us])')
        print('  -expandcg     pre-expand the callgraph data in the html output (default: disabled)')
        print('  -func list    Limit ftrace to comma-delimited list of functions (default: do_one_initcall)')
        print('  -cgfilter S   Filter the callgraph output in the timeline')
+       print('  -cgskip file  Callgraph functions to skip, off to disable (default: cgskip.txt)')
        print('  -bl name      Use the following boot loader for kernel params (default: grub)')
        print('  -reboot       Reboot the machine automatically and generate a new timeline')
        print('  -manual       Show the steps to generate a new timeline manually (used with -reboot)')
@@ -837,8 +883,13 @@ if __name__ == '__main__':
        # loop through the command line arguments
        cmd = ''
        testrun = True
+       switchoff = ['disable', 'off', 'false', '0']
        simplecmds = ['-sysinfo', '-kpupdate', '-flistall', '-checkbl']
+       cgskip = ''
+       if '-f' in sys.argv:
+               cgskip = sysvals.configFile('cgskip.txt')
        args = iter(sys.argv[1:])
+       mdset = False
        for arg in args:
                if(arg == '-h'):
                        printHelp()
@@ -846,13 +897,17 @@ if __name__ == '__main__':
                elif(arg == '-v'):
                        print("Version %s" % sysvals.version)
                        sys.exit()
+               elif(arg == '-verbose'):
+                       sysvals.verbose = True
                elif(arg in simplecmds):
                        cmd = arg[1:]
-               elif(arg == '-f'):
+               elif(arg == '-fstat'):
                        sysvals.useftrace = True
-               elif(arg == '-callgraph'):
+               elif(arg == '-callgraph' or arg == '-f'):
                        sysvals.useftrace = True
                        sysvals.usecallgraph = True
+               elif(arg == '-cgdump'):
+                       sysvals.cgdump = True
                elif(arg == '-mincg'):
                        sysvals.mincglen = aslib.getArgFloat('-mincg', args, 0.0, 10000.0)
                elif(arg == '-cgfilter'):
@@ -860,7 +915,18 @@ if __name__ == '__main__':
                                val = args.next()
                        except:
                                doError('No callgraph functions supplied', True)
-                       sysvals.setDeviceFilter(val)
+                       sysvals.setCallgraphFilter(val)
+               elif(arg == '-cgskip'):
+                       try:
+                               val = args.next()
+                       except:
+                               doError('No file supplied', True)
+                       if val.lower() in switchoff:
+                               cgskip = ''
+                       else:
+                               cgskip = sysvals.configFile(val)
+                               if(not cgskip):
+                                       doError('%s does not exist' % cgskip)
                elif(arg == '-bl'):
                        try:
                                val = args.next()
@@ -872,6 +938,7 @@ if __name__ == '__main__':
                elif(arg == '-timeprec'):
                        sysvals.setPrecision(aslib.getArgInt('-timeprec', args, 0, 6))
                elif(arg == '-maxdepth'):
+                       mdset = True
                        sysvals.max_graph_depth = aslib.getArgInt('-maxdepth', args, 0, 1000)
                elif(arg == '-func'):
                        try:
@@ -902,8 +969,6 @@ if __name__ == '__main__':
                                doError('No dmesg file supplied', True)
                        if(os.path.exists(val) == False):
                                doError('%s does not exist' % val)
-                       if(sysvals.htmlfile == val or sysvals.outfile == val):
-                               doError('Output filename collision')
                        testrun = False
                        sysvals.dmesgfile = val
                elif(arg == '-o'):
@@ -912,6 +977,12 @@ if __name__ == '__main__':
                        except:
                                doError('No subdirectory name supplied', True)
                        sysvals.testdir = sysvals.setOutputFolder(val)
+               elif(arg == '-result'):
+                       try:
+                               val = args.next()
+                       except:
+                               doError('No result file supplied', True)
+                       sysvals.result = val
                elif(arg == '-reboot'):
                        sysvals.reboot = True
                elif(arg == '-manual'):
@@ -947,7 +1018,7 @@ if __name__ == '__main__':
                        sysvals.getBootLoader()
                        print 'Boot Loader: %s\n%s' % (sysvals.bootloader, sysvals.blexec)
                elif(cmd == 'sysinfo'):
-                       sysvals.printSystemInfo()
+                       sysvals.printSystemInfo(True)
                sys.exit()
 
        # reboot: update grub, setup a cronjob, and reboot
@@ -963,6 +1034,10 @@ if __name__ == '__main__':
                        sysvals.manualRebootRequired()
                sys.exit()
 
+       if sysvals.usecallgraph and cgskip:
+               sysvals.vprint('Using cgskip file: %s' % cgskip)
+               sysvals.setCallgraphBlacklist(cgskip)
+
        # cronjob: remove the cronjob, grub changes, and disable ftrace
        if sysvals.iscronjob:
                updateCron(True)
@@ -980,29 +1055,23 @@ if __name__ == '__main__':
 
        # process the log data
        if sysvals.dmesgfile:
+               if not mdset:
+                       sysvals.max_graph_depth = 0
                data = parseKernelLog()
                if(not data.valid):
                        doError('No initcall data found in %s' % sysvals.dmesgfile)
                if sysvals.useftrace and sysvals.ftracefile:
                        parseTraceLog(data)
+               if sysvals.cgdump:
+                       data.debugPrint()
+                       sys.exit()
        else:
                doError('dmesg file required')
 
-       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('Usermode start: %.3f' % (data.tUserMode * 1000))
-       print('Last Init Call: %.3f' % (data.end * 1000))
-
-       # handle embedded output logs
-       if(sysvals.outfile and sysvals.embedded):
-               fp = open(sysvals.outfile, 'w')
-               fp.write('pass %s initstart %.3f end %.3f boot %s\n' %
-                       (data.valid, data.tUserMode*1000, data.end*1000, data.boottime))
-               fp.close()
-
+       sysvals.vprint('Creating the html timeline (%s)...' % sysvals.htmlfile)
+       sysvals.vprint('Command:\n    %s' % sysvals.cmdline)
+       sysvals.vprint('Kernel parameters:\n    %s' % sysvals.kparams)
+       data.printDetails()
        createBootGraph(data)
 
        # if running as root, change output dir owner to sudo_user
@@ -1010,3 +1079,7 @@ if __name__ == '__main__':
                os.getuid() == 0 and 'SUDO_USER' in os.environ:
                cmd = 'chown -R {0}:{0} {1} > /dev/null 2>&1'
                call(cmd.format(os.environ['SUDO_USER'], sysvals.testdir), shell=True)
+
+       sysvals.stamp['boot'] = (data.tUserMode - data.start) * 1000
+       sysvals.stamp['lastinit'] = data.end * 1000
+       sysvals.outputResult(sysvals.stamp)