pm-graph: AnalyzeBoot v2.2

- 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>

1 files changed, 146 insertions, 73 deletions

diff --git a/tools/power/pm-graph/bootgraph.py b/tools/power/pm-graph/bootgraph.py
index e83df141a597..abb4c38f029b 100755
--- a/tools/power/pm-graph/bootgraph.py
+++ b/tools/power/pm-graph/bootgraph.py
@@ -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)