Back to home page

LXR

 
 

    


0001 #!/usr/bin/python
0002 #
0003 # Tool for analyzing suspend/resume timing
0004 # Copyright (c) 2013, Intel Corporation.
0005 #
0006 # This program is free software; you can redistribute it and/or modify it
0007 # under the terms and conditions of the GNU General Public License,
0008 # version 2, as published by the Free Software Foundation.
0009 #
0010 # This program is distributed in the hope it will be useful, but WITHOUT
0011 # ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
0012 # FITNESS FOR A PARTICULAR PURPOSE.  See the GNU General Public License for
0013 # more details.
0014 #
0015 # You should have received a copy of the GNU General Public License along with
0016 # this program; if not, write to the Free Software Foundation, Inc.,
0017 # 51 Franklin St - Fifth Floor, Boston, MA 02110-1301 USA.
0018 #
0019 # Authors:
0020 #    Todd Brandt <todd.e.brandt@linux.intel.com>
0021 #
0022 # Links:
0023 #    Home Page
0024 #      https://01.org/suspendresume
0025 #    Source repo
0026 #      https://github.com/01org/suspendresume
0027 #    Documentation
0028 #      Getting Started
0029 #        https://01.org/suspendresume/documentation/getting-started
0030 #      Command List:
0031 #        https://01.org/suspendresume/documentation/command-list
0032 #
0033 # Description:
0034 #    This tool is designed to assist kernel and OS developers in optimizing
0035 #    their linux stack's suspend/resume time. Using a kernel image built
0036 #    with a few extra options enabled, the tool will execute a suspend and
0037 #    will capture dmesg and ftrace data until resume is complete. This data
0038 #    is transformed into a device timeline and a callgraph to give a quick
0039 #    and detailed view of which devices and callbacks are taking the most
0040 #    time in suspend/resume. The output is a single html file which can be
0041 #    viewed in firefox or chrome.
0042 #
0043 #    The following kernel build options are required:
0044 #        CONFIG_PM_DEBUG=y
0045 #        CONFIG_PM_SLEEP_DEBUG=y
0046 #        CONFIG_FTRACE=y
0047 #        CONFIG_FUNCTION_TRACER=y
0048 #        CONFIG_FUNCTION_GRAPH_TRACER=y
0049 #        CONFIG_KPROBES=y
0050 #        CONFIG_KPROBES_ON_FTRACE=y
0051 #
0052 #    For kernel versions older than 3.15:
0053 #    The following additional kernel parameters are required:
0054 #        (e.g. in file /etc/default/grub)
0055 #        GRUB_CMDLINE_LINUX_DEFAULT="... initcall_debug log_buf_len=16M ..."
0056 #
0057 
0058 # ----------------- LIBRARIES --------------------
0059 
0060 import sys
0061 import time
0062 import os
0063 import string
0064 import re
0065 import platform
0066 from datetime import datetime
0067 import struct
0068 import ConfigParser
0069 
0070 # ----------------- CLASSES --------------------
0071 
0072 # Class: SystemValues
0073 # Description:
0074 #    A global, single-instance container used to
0075 #    store system values and test parameters
0076 class SystemValues:
0077     ansi = False
0078     version = '4.2'
0079     verbose = False
0080     addlogs = False
0081     mindevlen = 0.001
0082     mincglen = 1.0
0083     srgap = 0
0084     cgexp = False
0085     outdir = ''
0086     testdir = '.'
0087     tpath = '/sys/kernel/debug/tracing/'
0088     fpdtpath = '/sys/firmware/acpi/tables/FPDT'
0089     epath = '/sys/kernel/debug/tracing/events/power/'
0090     traceevents = [
0091         'suspend_resume',
0092         'device_pm_callback_end',
0093         'device_pm_callback_start'
0094     ]
0095     testcommand = ''
0096     mempath = '/dev/mem'
0097     powerfile = '/sys/power/state'
0098     suspendmode = 'mem'
0099     hostname = 'localhost'
0100     prefix = 'test'
0101     teststamp = ''
0102     dmesgstart = 0.0
0103     dmesgfile = ''
0104     ftracefile = ''
0105     htmlfile = ''
0106     embedded = False
0107     rtcwake = False
0108     rtcwaketime = 10
0109     rtcpath = ''
0110     devicefilter = []
0111     stamp = 0
0112     execcount = 1
0113     x2delay = 0
0114     usecallgraph = False
0115     usetraceevents = False
0116     usetraceeventsonly = False
0117     usetracemarkers = True
0118     usekprobes = True
0119     usedevsrc = False
0120     notestrun = False
0121     devprops = dict()
0122     postresumetime = 0
0123     devpropfmt = '# Device Properties: .*'
0124     tracertypefmt = '# tracer: (?P<t>.*)'
0125     firmwarefmt = '# fwsuspend (?P<s>[0-9]*) fwresume (?P<r>[0-9]*)$'
0126     postresumefmt = '# post resume time (?P<t>[0-9]*)$'
0127     stampfmt = '# suspend-(?P<m>[0-9]{2})(?P<d>[0-9]{2})(?P<y>[0-9]{2})-'+\
0128                 '(?P<H>[0-9]{2})(?P<M>[0-9]{2})(?P<S>[0-9]{2})'+\
0129                 ' (?P<host>.*) (?P<mode>.*) (?P<kernel>.*)$'
0130     kprobecolor = 'rgba(204,204,204,0.5)'
0131     synccolor = 'rgba(204,204,204,0.5)'
0132     debugfuncs = []
0133     tracefuncs = {
0134         'sys_sync': dict(),
0135         'pm_prepare_console': dict(),
0136         'pm_notifier_call_chain': dict(),
0137         'freeze_processes': dict(),
0138         'freeze_kernel_threads': dict(),
0139         'pm_restrict_gfp_mask': dict(),
0140         'acpi_suspend_begin': dict(),
0141         'suspend_console': dict(),
0142         'acpi_pm_prepare': dict(),
0143         'syscore_suspend': dict(),
0144         'arch_enable_nonboot_cpus_end': dict(),
0145         'syscore_resume': dict(),
0146         'acpi_pm_finish': dict(),
0147         'resume_console': dict(),
0148         'acpi_pm_end': dict(),
0149         'pm_restore_gfp_mask': dict(),
0150         'thaw_processes': dict(),
0151         'pm_restore_console': dict(),
0152         'CPU_OFF': {
0153             'func':'_cpu_down',
0154             'args_x86_64': {'cpu':'%di:s32'},
0155             'format': 'CPU_OFF[{cpu}]',
0156             'mask': 'CPU_.*_DOWN'
0157         },
0158         'CPU_ON': {
0159             'func':'_cpu_up',
0160             'args_x86_64': {'cpu':'%di:s32'},
0161             'format': 'CPU_ON[{cpu}]',
0162             'mask': 'CPU_.*_UP'
0163         },
0164     }
0165     dev_tracefuncs = {
0166         # general wait/delay/sleep
0167         'msleep': { 'args_x86_64': {'time':'%di:s32'} },
0168         'udelay': { 'func':'__const_udelay', 'args_x86_64': {'loops':'%di:s32'} },
0169         'acpi_os_stall': dict(),
0170         # ACPI
0171         'acpi_resume_power_resources': dict(),
0172         'acpi_ps_parse_aml': dict(),
0173         # filesystem
0174         'ext4_sync_fs': dict(),
0175         # ATA
0176         'ata_eh_recover': { 'args_x86_64': {'port':'+36(%di):s32'} },
0177         # i915
0178         'i915_gem_restore_gtt_mappings': dict(),
0179         'intel_opregion_setup': dict(),
0180         'intel_dp_detect': dict(),
0181         'intel_hdmi_detect': dict(),
0182         'intel_opregion_init': dict(),
0183     }
0184     kprobes_postresume = [
0185         {
0186             'name': 'ataportrst',
0187             'func': 'ata_eh_recover',
0188             'args': {'port':'+36(%di):s32'},
0189             'format': 'ata{port}_port_reset',
0190             'mask': 'ata.*_port_reset'
0191         }
0192     ]
0193     kprobes = dict()
0194     timeformat = '%.3f'
0195     def __init__(self):
0196         # if this is a phoronix test run, set some default options
0197         if('LOG_FILE' in os.environ and 'TEST_RESULTS_IDENTIFIER' in os.environ):
0198             self.embedded = True
0199             self.addlogs = True
0200             self.htmlfile = os.environ['LOG_FILE']
0201         self.hostname = platform.node()
0202         if(self.hostname == ''):
0203             self.hostname = 'localhost'
0204         rtc = "rtc0"
0205         if os.path.exists('/dev/rtc'):
0206             rtc = os.readlink('/dev/rtc')
0207         rtc = '/sys/class/rtc/'+rtc
0208         if os.path.exists(rtc) and os.path.exists(rtc+'/date') and \
0209             os.path.exists(rtc+'/time') and os.path.exists(rtc+'/wakealarm'):
0210             self.rtcpath = rtc
0211         if (hasattr(sys.stdout, 'isatty') and sys.stdout.isatty()):
0212             self.ansi = True
0213     def setPrecision(self, num):
0214         if num < 0 or num > 6:
0215             return
0216         self.timeformat = '%.{0}f'.format(num)
0217     def setOutputFile(self):
0218         if((self.htmlfile == '') and (self.dmesgfile != '')):
0219             m = re.match('(?P<name>.*)_dmesg\.txt$', self.dmesgfile)
0220             if(m):
0221                 self.htmlfile = m.group('name')+'.html'
0222         if((self.htmlfile == '') and (self.ftracefile != '')):
0223             m = re.match('(?P<name>.*)_ftrace\.txt$', self.ftracefile)
0224             if(m):
0225                 self.htmlfile = m.group('name')+'.html'
0226         if(self.htmlfile == ''):
0227             self.htmlfile = 'output.html'
0228     def initTestOutput(self, subdir, testpath=''):
0229         self.prefix = self.hostname
0230         v = open('/proc/version', 'r').read().strip()
0231         kver = string.split(v)[2]
0232         n = datetime.now()
0233         testtime = n.strftime('suspend-%m%d%y-%H%M%S')
0234         if not testpath:
0235             testpath = n.strftime('suspend-%y%m%d-%H%M%S')
0236         if(subdir != "."):
0237             self.testdir = subdir+"/"+testpath
0238         else:
0239             self.testdir = testpath
0240         self.teststamp = \
0241             '# '+testtime+' '+self.prefix+' '+self.suspendmode+' '+kver
0242         if(self.embedded):
0243             self.dmesgfile = \
0244                 '/tmp/'+testtime+'_'+self.suspendmode+'_dmesg.txt'
0245             self.ftracefile = \
0246                 '/tmp/'+testtime+'_'+self.suspendmode+'_ftrace.txt'
0247             return
0248         self.dmesgfile = \
0249             self.testdir+'/'+self.prefix+'_'+self.suspendmode+'_dmesg.txt'
0250         self.ftracefile = \
0251             self.testdir+'/'+self.prefix+'_'+self.suspendmode+'_ftrace.txt'
0252         self.htmlfile = \
0253             self.testdir+'/'+self.prefix+'_'+self.suspendmode+'.html'
0254         if not os.path.isdir(self.testdir):
0255             os.mkdir(self.testdir)
0256     def setDeviceFilter(self, devnames):
0257         self.devicefilter = string.split(devnames)
0258     def rtcWakeAlarmOn(self):
0259         os.system('echo 0 > '+self.rtcpath+'/wakealarm')
0260         outD = open(self.rtcpath+'/date', 'r').read().strip()
0261         outT = open(self.rtcpath+'/time', 'r').read().strip()
0262         mD = re.match('^(?P<y>[0-9]*)-(?P<m>[0-9]*)-(?P<d>[0-9]*)', outD)
0263         mT = re.match('^(?P<h>[0-9]*):(?P<m>[0-9]*):(?P<s>[0-9]*)', outT)
0264         if(mD and mT):
0265             # get the current time from hardware
0266             utcoffset = int((datetime.now() - datetime.utcnow()).total_seconds())
0267             dt = datetime(\
0268                 int(mD.group('y')), int(mD.group('m')), int(mD.group('d')),
0269                 int(mT.group('h')), int(mT.group('m')), int(mT.group('s')))
0270             nowtime = int(dt.strftime('%s')) + utcoffset
0271         else:
0272             # if hardware time fails, use the software time
0273             nowtime = int(datetime.now().strftime('%s'))
0274         alarm = nowtime + self.rtcwaketime
0275         os.system('echo %d > %s/wakealarm' % (alarm, self.rtcpath))
0276     def rtcWakeAlarmOff(self):
0277         os.system('echo 0 > %s/wakealarm' % self.rtcpath)
0278     def initdmesg(self):
0279         # get the latest time stamp from the dmesg log
0280         fp = os.popen('dmesg')
0281         ktime = '0'
0282         for line in fp:
0283             line = line.replace('\r\n', '')
0284             idx = line.find('[')
0285             if idx > 1:
0286                 line = line[idx:]
0287             m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line)
0288             if(m):
0289                 ktime = m.group('ktime')
0290         fp.close()
0291         self.dmesgstart = float(ktime)
0292     def getdmesg(self):
0293         # store all new dmesg lines since initdmesg was called
0294         fp = os.popen('dmesg')
0295         op = open(self.dmesgfile, 'a')
0296         for line in fp:
0297             line = line.replace('\r\n', '')
0298             idx = line.find('[')
0299             if idx > 1:
0300                 line = line[idx:]
0301             m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line)
0302             if(not m):
0303                 continue
0304             ktime = float(m.group('ktime'))
0305             if ktime > self.dmesgstart:
0306                 op.write(line)
0307         fp.close()
0308         op.close()
0309     def addFtraceFilterFunctions(self, file):
0310         fp = open(file)
0311         list = fp.read().split('\n')
0312         fp.close()
0313         for i in list:
0314             if len(i) < 2:
0315                 continue
0316             self.tracefuncs[i] = dict()
0317     def getFtraceFilterFunctions(self, current):
0318         rootCheck(True)
0319         if not current:
0320             os.system('cat '+self.tpath+'available_filter_functions')
0321             return
0322         fp = open(self.tpath+'available_filter_functions')
0323         master = fp.read().split('\n')
0324         fp.close()
0325         if len(self.debugfuncs) > 0:
0326             for i in self.debugfuncs:
0327                 if i in master:
0328                     print i
0329                 else:
0330                     print self.colorText(i)
0331         else:
0332             for i in self.tracefuncs:
0333                 if 'func' in self.tracefuncs[i]:
0334                     i = self.tracefuncs[i]['func']
0335                 if i in master:
0336                     print i
0337                 else:
0338                     print self.colorText(i)
0339     def setFtraceFilterFunctions(self, list):
0340         fp = open(self.tpath+'available_filter_functions')
0341         master = fp.read().split('\n')
0342         fp.close()
0343         flist = ''
0344         for i in list:
0345             if i not in master:
0346                 continue
0347             if ' [' in i:
0348                 flist += i.split(' ')[0]+'\n'
0349             else:
0350                 flist += i+'\n'
0351         fp = open(self.tpath+'set_graph_function', 'w')
0352         fp.write(flist)
0353         fp.close()
0354     def kprobeMatch(self, name, target):
0355         if name not in self.kprobes:
0356             return False
0357         if re.match(self.kprobes[name]['mask'], target):
0358             return True
0359         return False
0360     def basicKprobe(self, name):
0361         self.kprobes[name] = {'name': name,'func': name,'args': dict(),'format': name,'mask': name}
0362     def defaultKprobe(self, name, kdata):
0363         k = kdata
0364         for field in ['name', 'format', 'mask', 'func']:
0365             if field not in k:
0366                 k[field] = name
0367         archargs = 'args_'+platform.machine()
0368         if archargs in k:
0369             k['args'] = k[archargs]
0370         else:
0371             k['args'] = dict()
0372             k['format'] = name
0373         self.kprobes[name] = k
0374     def kprobeColor(self, name):
0375         if name not in self.kprobes or 'color' not in self.kprobes[name]:
0376             return ''
0377         return self.kprobes[name]['color']
0378     def kprobeDisplayName(self, name, dataraw):
0379         if name not in self.kprobes:
0380             self.basicKprobe(name)
0381         data = ''
0382         quote=0
0383         # first remvoe any spaces inside quotes, and the quotes
0384         for c in dataraw:
0385             if c == '"':
0386                 quote = (quote + 1) % 2
0387             if quote and c == ' ':
0388                 data += '_'
0389             elif c != '"':
0390                 data += c
0391         fmt, args = self.kprobes[name]['format'], self.kprobes[name]['args']
0392         arglist = dict()
0393         # now process the args
0394         for arg in sorted(args):
0395             arglist[arg] = ''
0396             m = re.match('.* '+arg+'=(?P<arg>.*) ', data);
0397             if m:
0398                 arglist[arg] = m.group('arg')
0399             else:
0400                 m = re.match('.* '+arg+'=(?P<arg>.*)', data);
0401                 if m:
0402                     arglist[arg] = m.group('arg')
0403         out = fmt.format(**arglist)
0404         out = out.replace(' ', '_').replace('"', '')
0405         return out
0406     def kprobeText(self, kprobe):
0407         name, fmt, func, args = kprobe['name'], kprobe['format'], kprobe['func'], kprobe['args']
0408         if re.findall('{(?P<n>[a-z,A-Z,0-9]*)}', func):
0409             doError('Kprobe "%s" has format info in the function name "%s"' % (name, func), False)
0410         for arg in re.findall('{(?P<n>[a-z,A-Z,0-9]*)}', fmt):
0411             if arg not in args:
0412                 doError('Kprobe "%s" is missing argument "%s"' % (name, arg), False)
0413         val = 'p:%s_cal %s' % (name, func)
0414         for i in sorted(args):
0415             val += ' %s=%s' % (i, args[i])
0416         val += '\nr:%s_ret %s $retval\n' % (name, func)
0417         return val
0418     def addKprobes(self):
0419         # first test each kprobe
0420         print('INITIALIZING KPROBES...')
0421         rejects = []
0422         for name in sorted(self.kprobes):
0423             if not self.testKprobe(self.kprobes[name]):
0424                 rejects.append(name)
0425         # remove all failed ones from the list
0426         for name in rejects:
0427             vprint('Skipping KPROBE: %s' % name)
0428             self.kprobes.pop(name)
0429         self.fsetVal('', 'kprobe_events')
0430         kprobeevents = ''
0431         # set the kprobes all at once
0432         for kp in self.kprobes:
0433             val = self.kprobeText(self.kprobes[kp])
0434             vprint('Adding KPROBE: %s\n%s' % (kp, val.strip()))
0435             kprobeevents += self.kprobeText(self.kprobes[kp])
0436         self.fsetVal(kprobeevents, 'kprobe_events')
0437         # verify that the kprobes were set as ordered
0438         check = self.fgetVal('kprobe_events')
0439         linesout = len(kprobeevents.split('\n'))
0440         linesack = len(check.split('\n'))
0441         if linesack < linesout:
0442             # if not, try appending the kprobes 1 by 1
0443             for kp in self.kprobes:
0444                 kprobeevents = self.kprobeText(self.kprobes[kp])
0445                 self.fsetVal(kprobeevents, 'kprobe_events', 'a')
0446         self.fsetVal('1', 'events/kprobes/enable')
0447     def testKprobe(self, kprobe):
0448         kprobeevents = self.kprobeText(kprobe)
0449         if not kprobeevents:
0450             return False
0451         try:
0452             self.fsetVal(kprobeevents, 'kprobe_events')
0453             check = self.fgetVal('kprobe_events')
0454         except:
0455             return False
0456         linesout = len(kprobeevents.split('\n'))
0457         linesack = len(check.split('\n'))
0458         if linesack < linesout:
0459             return False
0460         return True
0461     def fsetVal(self, val, path, mode='w'):
0462         file = self.tpath+path
0463         if not os.path.exists(file):
0464             return False
0465         try:
0466             fp = open(file, mode)
0467             fp.write(val)
0468             fp.close()
0469         except:
0470             pass
0471         return True
0472     def fgetVal(self, path):
0473         file = self.tpath+path
0474         res = ''
0475         if not os.path.exists(file):
0476             return res
0477         try:
0478             fp = open(file, 'r')
0479             res = fp.read()
0480             fp.close()
0481         except:
0482             pass
0483         return res
0484     def cleanupFtrace(self):
0485         if(self.usecallgraph or self.usetraceevents):
0486             self.fsetVal('0', 'events/kprobes/enable')
0487             self.fsetVal('', 'kprobe_events')
0488     def setupAllKprobes(self):
0489         for name in self.tracefuncs:
0490             self.defaultKprobe(name, self.tracefuncs[name])
0491         for name in self.dev_tracefuncs:
0492             self.defaultKprobe(name, self.dev_tracefuncs[name])
0493     def isCallgraphFunc(self, name):
0494         if len(self.debugfuncs) < 1 and self.suspendmode == 'command':
0495             return True
0496         if name in self.debugfuncs:
0497             return True
0498         funclist = []
0499         for i in self.tracefuncs:
0500             if 'func' in self.tracefuncs[i]:
0501                 funclist.append(self.tracefuncs[i]['func'])
0502             else:
0503                 funclist.append(i)
0504         if name in funclist:
0505             return True
0506         return False
0507     def initFtrace(self, testing=False):
0508         tp = self.tpath
0509         print('INITIALIZING FTRACE...')
0510         # turn trace off
0511         self.fsetVal('0', 'tracing_on')
0512         self.cleanupFtrace()
0513         # set the trace clock to global
0514         self.fsetVal('global', 'trace_clock')
0515         # set trace buffer to a huge value
0516         self.fsetVal('nop', 'current_tracer')
0517         self.fsetVal('100000', 'buffer_size_kb')
0518         # go no further if this is just a status check
0519         if testing:
0520             return
0521         if self.usekprobes:
0522             # add tracefunc kprobes so long as were not using full callgraph
0523             if(not self.usecallgraph or len(self.debugfuncs) > 0):
0524                 for name in self.tracefuncs:
0525                     self.defaultKprobe(name, self.tracefuncs[name])
0526                 if self.usedevsrc:
0527                     for name in self.dev_tracefuncs:
0528                         self.defaultKprobe(name, self.dev_tracefuncs[name])
0529             else:
0530                 self.usedevsrc = False
0531             self.addKprobes()
0532         # initialize the callgraph trace, unless this is an x2 run
0533         if(self.usecallgraph):
0534             # set trace type
0535             self.fsetVal('function_graph', 'current_tracer')
0536             self.fsetVal('', 'set_ftrace_filter')
0537             # set trace format options
0538             self.fsetVal('print-parent', 'trace_options')
0539             self.fsetVal('funcgraph-abstime', 'trace_options')
0540             self.fsetVal('funcgraph-cpu', 'trace_options')
0541             self.fsetVal('funcgraph-duration', 'trace_options')
0542             self.fsetVal('funcgraph-proc', 'trace_options')
0543             self.fsetVal('funcgraph-tail', 'trace_options')
0544             self.fsetVal('nofuncgraph-overhead', 'trace_options')
0545             self.fsetVal('context-info', 'trace_options')
0546             self.fsetVal('graph-time', 'trace_options')
0547             self.fsetVal('0', 'max_graph_depth')
0548             if len(self.debugfuncs) > 0:
0549                 self.setFtraceFilterFunctions(self.debugfuncs)
0550             elif self.suspendmode == 'command':
0551                 self.fsetVal('', 'set_graph_function')
0552             else:
0553                 cf = ['dpm_run_callback']
0554                 if(self.usetraceeventsonly):
0555                     cf += ['dpm_prepare', 'dpm_complete']
0556                 for fn in self.tracefuncs:
0557                     if 'func' in self.tracefuncs[fn]:
0558                         cf.append(self.tracefuncs[fn]['func'])
0559                     else:
0560                         cf.append(fn)
0561                 self.setFtraceFilterFunctions(cf)
0562         if(self.usetraceevents):
0563             # turn trace events on
0564             events = iter(self.traceevents)
0565             for e in events:
0566                 self.fsetVal('1', 'events/power/'+e+'/enable')
0567         # clear the trace buffer
0568         self.fsetVal('', 'trace')
0569     def verifyFtrace(self):
0570         # files needed for any trace data
0571         files = ['buffer_size_kb', 'current_tracer', 'trace', 'trace_clock',
0572                  'trace_marker', 'trace_options', 'tracing_on']
0573         # files needed for callgraph trace data
0574         tp = self.tpath
0575         if(self.usecallgraph):
0576             files += [
0577                 'available_filter_functions',
0578                 'set_ftrace_filter',
0579                 'set_graph_function'
0580             ]
0581         for f in files:
0582             if(os.path.exists(tp+f) == False):
0583                 return False
0584         return True
0585     def verifyKprobes(self):
0586         # files needed for kprobes to work
0587         files = ['kprobe_events', 'events']
0588         tp = self.tpath
0589         for f in files:
0590             if(os.path.exists(tp+f) == False):
0591                 return False
0592         return True
0593     def colorText(self, str):
0594         if not self.ansi:
0595             return str
0596         return '\x1B[31;40m'+str+'\x1B[m'
0597 
0598 sysvals = SystemValues()
0599 
0600 # Class: DevProps
0601 # Description:
0602 #    Simple class which holds property values collected
0603 #    for all the devices used in the timeline.
0604 class DevProps:
0605     syspath = ''
0606     altname = ''
0607     async = True
0608     xtraclass = ''
0609     xtrainfo = ''
0610     def out(self, dev):
0611         return '%s,%s,%d;' % (dev, self.altname, self.async)
0612     def debug(self, dev):
0613         print '%s:\n\taltname = %s\n\t  async = %s' % (dev, self.altname, self.async)
0614     def altName(self, dev):
0615         if not self.altname or self.altname == dev:
0616             return dev
0617         return '%s [%s]' % (self.altname, dev)
0618     def xtraClass(self):
0619         if self.xtraclass:
0620             return ' '+self.xtraclass
0621         if not self.async:
0622             return ' sync'
0623         return ''
0624     def xtraInfo(self):
0625         if self.xtraclass:
0626             return ' '+self.xtraclass
0627         if self.async:
0628             return ' async'
0629         return ' sync'
0630 
0631 # Class: DeviceNode
0632 # Description:
0633 #    A container used to create a device hierachy, with a single root node
0634 #    and a tree of child nodes. Used by Data.deviceTopology()
0635 class DeviceNode:
0636     name = ''
0637     children = 0
0638     depth = 0
0639     def __init__(self, nodename, nodedepth):
0640         self.name = nodename
0641         self.children = []
0642         self.depth = nodedepth
0643 
0644 # Class: Data
0645 # Description:
0646 #    The primary container for suspend/resume test data. There is one for
0647 #    each test run. The data is organized into a cronological hierarchy:
0648 #    Data.dmesg {
0649 #       root structure, started as dmesg & ftrace, but now only ftrace
0650 #       contents: times for suspend start/end, resume start/end, fwdata
0651 #       phases {
0652 #           10 sequential, non-overlapping phases of S/R
0653 #           contents: times for phase start/end, order/color data for html
0654 #           devlist {
0655 #               device callback or action list for this phase
0656 #               device {
0657 #                   a single device callback or generic action
0658 #                   contents: start/stop times, pid/cpu/driver info
0659 #                       parents/children, html id for timeline/callgraph
0660 #                       optionally includes an ftrace callgraph
0661 #                       optionally includes intradev trace events
0662 #               }
0663 #           }
0664 #       }
0665 #   }
0666 #
0667 class Data:
0668     dmesg = {}  # root data structure
0669     phases = [] # ordered list of phases
0670     start = 0.0 # test start
0671     end = 0.0   # test end
0672     tSuspended = 0.0 # low-level suspend start
0673     tResumed = 0.0   # low-level resume start
0674     tLow = 0.0       # time spent in low-level suspend (standby/freeze)
0675     fwValid = False  # is firmware data available
0676     fwSuspend = 0    # time spent in firmware suspend
0677     fwResume = 0     # time spent in firmware resume
0678     dmesgtext = []   # dmesg text file in memory
0679     testnumber = 0
0680     idstr = ''
0681     html_device_id = 0
0682     stamp = 0
0683     outfile = ''
0684     dev_ubiquitous = ['msleep', 'udelay']
0685     def __init__(self, num):
0686         idchar = 'abcdefghijklmnopqrstuvwxyz'
0687         self.testnumber = num
0688         self.idstr = idchar[num]
0689         self.dmesgtext = []
0690         self.phases = []
0691         self.dmesg = { # fixed list of 10 phases
0692             'suspend_prepare': {'list': dict(), 'start': -1.0, 'end': -1.0,
0693                                 'row': 0, 'color': '#CCFFCC', 'order': 0},
0694                     'suspend': {'list': dict(), 'start': -1.0, 'end': -1.0,
0695                                 'row': 0, 'color': '#88FF88', 'order': 1},
0696                'suspend_late': {'list': dict(), 'start': -1.0, 'end': -1.0,
0697                                 'row': 0, 'color': '#00AA00', 'order': 2},
0698               'suspend_noirq': {'list': dict(), 'start': -1.0, 'end': -1.0,
0699                                 'row': 0, 'color': '#008888', 'order': 3},
0700             'suspend_machine': {'list': dict(), 'start': -1.0, 'end': -1.0,
0701                                 'row': 0, 'color': '#0000FF', 'order': 4},
0702              'resume_machine': {'list': dict(), 'start': -1.0, 'end': -1.0,
0703                                 'row': 0, 'color': '#FF0000', 'order': 5},
0704                'resume_noirq': {'list': dict(), 'start': -1.0, 'end': -1.0,
0705                                 'row': 0, 'color': '#FF9900', 'order': 6},
0706                'resume_early': {'list': dict(), 'start': -1.0, 'end': -1.0,
0707                                 'row': 0, 'color': '#FFCC00', 'order': 7},
0708                      'resume': {'list': dict(), 'start': -1.0, 'end': -1.0,
0709                                 'row': 0, 'color': '#FFFF88', 'order': 8},
0710             'resume_complete': {'list': dict(), 'start': -1.0, 'end': -1.0,
0711                                 'row': 0, 'color': '#FFFFCC', 'order': 9}
0712         }
0713         self.phases = self.sortedPhases()
0714         self.devicegroups = []
0715         for phase in self.phases:
0716             self.devicegroups.append([phase])
0717     def getStart(self):
0718         return self.dmesg[self.phases[0]]['start']
0719     def setStart(self, time):
0720         self.start = time
0721         self.dmesg[self.phases[0]]['start'] = time
0722     def getEnd(self):
0723         return self.dmesg[self.phases[-1]]['end']
0724     def setEnd(self, time):
0725         self.end = time
0726         self.dmesg[self.phases[-1]]['end'] = time
0727     def isTraceEventOutsideDeviceCalls(self, pid, time):
0728         for phase in self.phases:
0729             list = self.dmesg[phase]['list']
0730             for dev in list:
0731                 d = list[dev]
0732                 if(d['pid'] == pid and time >= d['start'] and
0733                     time < d['end']):
0734                     return False
0735         return True
0736     def targetDevice(self, phaselist, start, end, pid=-1):
0737         tgtdev = ''
0738         for phase in phaselist:
0739             list = self.dmesg[phase]['list']
0740             for devname in list:
0741                 dev = list[devname]
0742                 if(pid >= 0 and dev['pid'] != pid):
0743                     continue
0744                 devS = dev['start']
0745                 devE = dev['end']
0746                 if(start < devS or start >= devE or end <= devS or end > devE):
0747                     continue
0748                 tgtdev = dev
0749                 break
0750         return tgtdev
0751     def addDeviceFunctionCall(self, displayname, kprobename, proc, pid, start, end, cdata, rdata):
0752         machstart = self.dmesg['suspend_machine']['start']
0753         machend = self.dmesg['resume_machine']['end']
0754         tgtdev = self.targetDevice(self.phases, start, end, pid)
0755         if not tgtdev and start >= machstart and end < machend:
0756             # device calls in machine phases should be serial
0757             tgtdev = self.targetDevice(['suspend_machine', 'resume_machine'], start, end)
0758         if not tgtdev:
0759             if 'scsi_eh' in proc:
0760                 self.newActionGlobal(proc, start, end, pid)
0761                 self.addDeviceFunctionCall(displayname, kprobename, proc, pid, start, end, cdata, rdata)
0762             else:
0763                 vprint('IGNORE: %s[%s](%d) [%f - %f] | %s | %s | %s' % (displayname, kprobename,
0764                     pid, start, end, cdata, rdata, proc))
0765             return False
0766         # detail block fits within tgtdev
0767         if('src' not in tgtdev):
0768             tgtdev['src'] = []
0769         title = cdata+' '+rdata
0770         mstr = '\(.*\) *(?P<args>.*) *\((?P<caller>.*)\+.* arg1=(?P<ret>.*)'
0771         m = re.match(mstr, title)
0772         if m:
0773             c = m.group('caller')
0774             a = m.group('args').strip()
0775             r = m.group('ret')
0776             if len(r) > 6:
0777                 r = ''
0778             else:
0779                 r = 'ret=%s ' % r
0780             l = '%0.3fms' % ((end - start) * 1000)
0781             if kprobename in self.dev_ubiquitous:
0782                 title = '%s(%s) <- %s, %s(%s)' % (displayname, a, c, r, l)
0783             else:
0784                 title = '%s(%s) %s(%s)' % (displayname, a, r, l)
0785         e = TraceEvent(title, kprobename, start, end - start)
0786         tgtdev['src'].append(e)
0787         return True
0788     def trimTimeVal(self, t, t0, dT, left):
0789         if left:
0790             if(t > t0):
0791                 if(t - dT < t0):
0792                     return t0
0793                 return t - dT
0794             else:
0795                 return t
0796         else:
0797             if(t < t0 + dT):
0798                 if(t > t0):
0799                     return t0 + dT
0800                 return t + dT
0801             else:
0802                 return t
0803     def trimTime(self, t0, dT, left):
0804         self.tSuspended = self.trimTimeVal(self.tSuspended, t0, dT, left)
0805         self.tResumed = self.trimTimeVal(self.tResumed, t0, dT, left)
0806         self.start = self.trimTimeVal(self.start, t0, dT, left)
0807         self.end = self.trimTimeVal(self.end, t0, dT, left)
0808         for phase in self.phases:
0809             p = self.dmesg[phase]
0810             p['start'] = self.trimTimeVal(p['start'], t0, dT, left)
0811             p['end'] = self.trimTimeVal(p['end'], t0, dT, left)
0812             list = p['list']
0813             for name in list:
0814                 d = list[name]
0815                 d['start'] = self.trimTimeVal(d['start'], t0, dT, left)
0816                 d['end'] = self.trimTimeVal(d['end'], t0, dT, left)
0817                 if('ftrace' in d):
0818                     cg = d['ftrace']
0819                     cg.start = self.trimTimeVal(cg.start, t0, dT, left)
0820                     cg.end = self.trimTimeVal(cg.end, t0, dT, left)
0821                     for line in cg.list:
0822                         line.time = self.trimTimeVal(line.time, t0, dT, left)
0823                 if('src' in d):
0824                     for e in d['src']:
0825                         e.time = self.trimTimeVal(e.time, t0, dT, left)
0826     def normalizeTime(self, tZero):
0827         # trim out any standby or freeze clock time
0828         if(self.tSuspended != self.tResumed):
0829             if(self.tResumed > tZero):
0830                 self.trimTime(self.tSuspended, \
0831                     self.tResumed-self.tSuspended, True)
0832             else:
0833                 self.trimTime(self.tSuspended, \
0834                     self.tResumed-self.tSuspended, False)
0835     def newPhaseWithSingleAction(self, phasename, devname, start, end, color):
0836         for phase in self.phases:
0837             self.dmesg[phase]['order'] += 1
0838         self.html_device_id += 1
0839         devid = '%s%d' % (self.idstr, self.html_device_id)
0840         list = dict()
0841         list[devname] = \
0842             {'start': start, 'end': end, 'pid': 0, 'par': '',
0843             'length': (end-start), 'row': 0, 'id': devid, 'drv': '' };
0844         self.dmesg[phasename] = \
0845             {'list': list, 'start': start, 'end': end,
0846             'row': 0, 'color': color, 'order': 0}
0847         self.phases = self.sortedPhases()
0848     def newPhase(self, phasename, start, end, color, order):
0849         if(order < 0):
0850             order = len(self.phases)
0851         for phase in self.phases[order:]:
0852             self.dmesg[phase]['order'] += 1
0853         if(order > 0):
0854             p = self.phases[order-1]
0855             self.dmesg[p]['end'] = start
0856         if(order < len(self.phases)):
0857             p = self.phases[order]
0858             self.dmesg[p]['start'] = end
0859         list = dict()
0860         self.dmesg[phasename] = \
0861             {'list': list, 'start': start, 'end': end,
0862             'row': 0, 'color': color, 'order': order}
0863         self.phases = self.sortedPhases()
0864         self.devicegroups.append([phasename])
0865     def setPhase(self, phase, ktime, isbegin):
0866         if(isbegin):
0867             self.dmesg[phase]['start'] = ktime
0868         else:
0869             self.dmesg[phase]['end'] = ktime
0870     def dmesgSortVal(self, phase):
0871         return self.dmesg[phase]['order']
0872     def sortedPhases(self):
0873         return sorted(self.dmesg, key=self.dmesgSortVal)
0874     def sortedDevices(self, phase):
0875         list = self.dmesg[phase]['list']
0876         slist = []
0877         tmp = dict()
0878         for devname in list:
0879             dev = list[devname]
0880             tmp[dev['start']] = devname
0881         for t in sorted(tmp):
0882             slist.append(tmp[t])
0883         return slist
0884     def fixupInitcalls(self, phase, end):
0885         # if any calls never returned, clip them at system resume end
0886         phaselist = self.dmesg[phase]['list']
0887         for devname in phaselist:
0888             dev = phaselist[devname]
0889             if(dev['end'] < 0):
0890                 for p in self.phases:
0891                     if self.dmesg[p]['end'] > dev['start']:
0892                         dev['end'] = self.dmesg[p]['end']
0893                         break
0894                 vprint('%s (%s): callback didnt return' % (devname, phase))
0895     def deviceFilter(self, devicefilter):
0896         # remove all by the relatives of the filter devnames
0897         filter = []
0898         for phase in self.phases:
0899             list = self.dmesg[phase]['list']
0900             for name in devicefilter:
0901                 dev = name
0902                 while(dev in list):
0903                     if(dev not in filter):
0904                         filter.append(dev)
0905                     dev = list[dev]['par']
0906                 children = self.deviceDescendants(name, phase)
0907                 for dev in children:
0908                     if(dev not in filter):
0909                         filter.append(dev)
0910         for phase in self.phases:
0911             list = self.dmesg[phase]['list']
0912             rmlist = []
0913             for name in list:
0914                 pid = list[name]['pid']
0915                 if(name not in filter and pid >= 0):
0916                     rmlist.append(name)
0917             for name in rmlist:
0918                 del list[name]
0919     def fixupInitcallsThatDidntReturn(self):
0920         # if any calls never returned, clip them at system resume end
0921         for phase in self.phases:
0922             self.fixupInitcalls(phase, self.getEnd())
0923     def isInsideTimeline(self, start, end):
0924         if(self.start <= start and self.end > start):
0925             return True
0926         return False
0927     def phaseOverlap(self, phases):
0928         rmgroups = []
0929         newgroup = []
0930         for group in self.devicegroups:
0931             for phase in phases:
0932                 if phase not in group:
0933                     continue
0934                 for p in group:
0935                     if p not in newgroup:
0936                         newgroup.append(p)
0937                 if group not in rmgroups:
0938                     rmgroups.append(group)
0939         for group in rmgroups:
0940             self.devicegroups.remove(group)
0941         self.devicegroups.append(newgroup)
0942     def newActionGlobal(self, name, start, end, pid=-1, color=''):
0943         # if event starts before timeline start, expand timeline
0944         if(start < self.start):
0945             self.setStart(start)
0946         # if event ends after timeline end, expand the timeline
0947         if(end > self.end):
0948             self.setEnd(end)
0949         # which phase is this device callback or action "in"
0950         targetphase = "none"
0951         htmlclass = ''
0952         overlap = 0.0
0953         phases = []
0954         for phase in self.phases:
0955             pstart = self.dmesg[phase]['start']
0956             pend = self.dmesg[phase]['end']
0957             o = max(0, min(end, pend) - max(start, pstart))
0958             if o > 0:
0959                 phases.append(phase)
0960             if o > overlap:
0961                 if overlap > 0 and phase == 'post_resume':
0962                     continue
0963                 targetphase = phase
0964                 overlap = o
0965         if pid == -2:
0966             htmlclass = ' bg'
0967         if len(phases) > 1:
0968             htmlclass = ' bg'
0969             self.phaseOverlap(phases)
0970         if targetphase in self.phases:
0971             newname = self.newAction(targetphase, name, pid, '', start, end, '', htmlclass, color)
0972             return (targetphase, newname)
0973         return False
0974     def newAction(self, phase, name, pid, parent, start, end, drv, htmlclass='', color=''):
0975         # new device callback for a specific phase
0976         self.html_device_id += 1
0977         devid = '%s%d' % (self.idstr, self.html_device_id)
0978         list = self.dmesg[phase]['list']
0979         length = -1.0
0980         if(start >= 0 and end >= 0):
0981             length = end - start
0982         if pid == -2:
0983             i = 2
0984             origname = name
0985             while(name in list):
0986                 name = '%s[%d]' % (origname, i)
0987                 i += 1
0988         list[name] = {'start': start, 'end': end, 'pid': pid, 'par': parent,
0989                       'length': length, 'row': 0, 'id': devid, 'drv': drv }
0990         if htmlclass:
0991             list[name]['htmlclass'] = htmlclass
0992         if color:
0993             list[name]['color'] = color
0994         return name
0995     def deviceIDs(self, devlist, phase):
0996         idlist = []
0997         list = self.dmesg[phase]['list']
0998         for devname in list:
0999             if devname in devlist:
1000                 idlist.append(list[devname]['id'])
1001         return idlist
1002     def deviceParentID(self, devname, phase):
1003         pdev = ''
1004         pdevid = ''
1005         list = self.dmesg[phase]['list']
1006         if devname in list:
1007             pdev = list[devname]['par']
1008         if pdev in list:
1009             return list[pdev]['id']
1010         return pdev
1011     def deviceChildren(self, devname, phase):
1012         devlist = []
1013         list = self.dmesg[phase]['list']
1014         for child in list:
1015             if(list[child]['par'] == devname):
1016                 devlist.append(child)
1017         return devlist
1018     def deviceDescendants(self, devname, phase):
1019         children = self.deviceChildren(devname, phase)
1020         family = children
1021         for child in children:
1022             family += self.deviceDescendants(child, phase)
1023         return family
1024     def deviceChildrenIDs(self, devname, phase):
1025         devlist = self.deviceChildren(devname, phase)
1026         return self.deviceIDs(devlist, phase)
1027     def printDetails(self):
1028         vprint('          test start: %f' % self.start)
1029         for phase in self.phases:
1030             dc = len(self.dmesg[phase]['list'])
1031             vprint('    %16s: %f - %f (%d devices)' % (phase, \
1032                 self.dmesg[phase]['start'], self.dmesg[phase]['end'], dc))
1033         vprint('            test end: %f' % self.end)
1034     def deviceChildrenAllPhases(self, devname):
1035         devlist = []
1036         for phase in self.phases:
1037             list = self.deviceChildren(devname, phase)
1038             for dev in list:
1039                 if dev not in devlist:
1040                     devlist.append(dev)
1041         return devlist
1042     def masterTopology(self, name, list, depth):
1043         node = DeviceNode(name, depth)
1044         for cname in list:
1045             # avoid recursions
1046             if name == cname:
1047                 continue
1048             clist = self.deviceChildrenAllPhases(cname)
1049             cnode = self.masterTopology(cname, clist, depth+1)
1050             node.children.append(cnode)
1051         return node
1052     def printTopology(self, node):
1053         html = ''
1054         if node.name:
1055             info = ''
1056             drv = ''
1057             for phase in self.phases:
1058                 list = self.dmesg[phase]['list']
1059                 if node.name in list:
1060                     s = list[node.name]['start']
1061                     e = list[node.name]['end']
1062                     if list[node.name]['drv']:
1063                         drv = ' {'+list[node.name]['drv']+'}'
1064                     info += ('<li>%s: %.3fms</li>' % (phase, (e-s)*1000))
1065             html += '<li><b>'+node.name+drv+'</b>'
1066             if info:
1067                 html += '<ul>'+info+'</ul>'
1068             html += '</li>'
1069         if len(node.children) > 0:
1070             html += '<ul>'
1071             for cnode in node.children:
1072                 html += self.printTopology(cnode)
1073             html += '</ul>'
1074         return html
1075     def rootDeviceList(self):
1076         # list of devices graphed
1077         real = []
1078         for phase in self.dmesg:
1079             list = self.dmesg[phase]['list']
1080             for dev in list:
1081                 if list[dev]['pid'] >= 0 and dev not in real:
1082                     real.append(dev)
1083         # list of top-most root devices
1084         rootlist = []
1085         for phase in self.dmesg:
1086             list = self.dmesg[phase]['list']
1087             for dev in list:
1088                 pdev = list[dev]['par']
1089                 pid = list[dev]['pid']
1090                 if(pid < 0 or re.match('[0-9]*-[0-9]*\.[0-9]*[\.0-9]*\:[\.0-9]*$', pdev)):
1091                     continue
1092                 if pdev and pdev not in real and pdev not in rootlist:
1093                     rootlist.append(pdev)
1094         return rootlist
1095     def deviceTopology(self):
1096         rootlist = self.rootDeviceList()
1097         master = self.masterTopology('', rootlist, 0)
1098         return self.printTopology(master)
1099     def selectTimelineDevices(self, widfmt, tTotal, mindevlen):
1100         # only select devices that will actually show up in html
1101         self.tdevlist = dict()
1102         for phase in self.dmesg:
1103             devlist = []
1104             list = self.dmesg[phase]['list']
1105             for dev in list:
1106                 length = (list[dev]['end'] - list[dev]['start']) * 1000
1107                 width = widfmt % (((list[dev]['end']-list[dev]['start'])*100)/tTotal)
1108                 if width != '0.000000' and length >= mindevlen:
1109                     devlist.append(dev)
1110             self.tdevlist[phase] = devlist
1111 
1112 # Class: TraceEvent
1113 # Description:
1114 #    A container for trace event data found in the ftrace file
1115 class TraceEvent:
1116     text = ''
1117     time = 0.0
1118     length = 0.0
1119     title = ''
1120     row = 0
1121     def __init__(self, a, n, t, l):
1122         self.title = a
1123         self.text = n
1124         self.time = t
1125         self.length = l
1126 
1127 # Class: FTraceLine
1128 # Description:
1129 #    A container for a single line of ftrace data. There are six basic types:
1130 #        callgraph line:
1131 #             call: "  dpm_run_callback() {"
1132 #           return: "  }"
1133 #             leaf: " dpm_run_callback();"
1134 #        trace event:
1135 #            tracing_mark_write: SUSPEND START or RESUME COMPLETE
1136 #            suspend_resume: phase or custom exec block data
1137 #            device_pm_callback: device callback info
1138 class FTraceLine:
1139     time = 0.0
1140     length = 0.0
1141     fcall = False
1142     freturn = False
1143     fevent = False
1144     fkprobe = False
1145     depth = 0
1146     name = ''
1147     type = ''
1148     def __init__(self, t, m='', d=''):
1149         self.time = float(t)
1150         if not m and not d:
1151             return
1152         # is this a trace event
1153         if(d == 'traceevent' or re.match('^ *\/\* *(?P<msg>.*) \*\/ *$', m)):
1154             if(d == 'traceevent'):
1155                 # nop format trace event
1156                 msg = m
1157             else:
1158                 # function_graph format trace event
1159                 em = re.match('^ *\/\* *(?P<msg>.*) \*\/ *$', m)
1160                 msg = em.group('msg')
1161 
1162             emm = re.match('^(?P<call>.*?): (?P<msg>.*)', msg)
1163             if(emm):
1164                 self.name = emm.group('msg')
1165                 self.type = emm.group('call')
1166             else:
1167                 self.name = msg
1168             km = re.match('^(?P<n>.*)_cal$', self.type)
1169             if km:
1170                 self.fcall = True
1171                 self.fkprobe = True
1172                 self.type = km.group('n')
1173                 return
1174             km = re.match('^(?P<n>.*)_ret$', self.type)
1175             if km:
1176                 self.freturn = True
1177                 self.fkprobe = True
1178                 self.type = km.group('n')
1179                 return
1180             self.fevent = True
1181             return
1182         # convert the duration to seconds
1183         if(d):
1184             self.length = float(d)/1000000
1185         # the indentation determines the depth
1186         match = re.match('^(?P<d> *)(?P<o>.*)$', m)
1187         if(not match):
1188             return
1189         self.depth = self.getDepth(match.group('d'))
1190         m = match.group('o')
1191         # function return
1192         if(m[0] == '}'):
1193             self.freturn = True
1194             if(len(m) > 1):
1195                 # includes comment with function name
1196                 match = re.match('^} *\/\* *(?P<n>.*) *\*\/$', m)
1197                 if(match):
1198                     self.name = match.group('n').strip()
1199         # function call
1200         else:
1201             self.fcall = True
1202             # function call with children
1203             if(m[-1] == '{'):
1204                 match = re.match('^(?P<n>.*) *\(.*', m)
1205                 if(match):
1206                     self.name = match.group('n').strip()
1207             # function call with no children (leaf)
1208             elif(m[-1] == ';'):
1209                 self.freturn = True
1210                 match = re.match('^(?P<n>.*) *\(.*', m)
1211                 if(match):
1212                     self.name = match.group('n').strip()
1213             # something else (possibly a trace marker)
1214             else:
1215                 self.name = m
1216     def getDepth(self, str):
1217         return len(str)/2
1218     def debugPrint(self, dev=''):
1219         if(self.freturn and self.fcall):
1220             print('%s -- %f (%02d): %s(); (%.3f us)' % (dev, self.time, \
1221                 self.depth, self.name, self.length*1000000))
1222         elif(self.freturn):
1223             print('%s -- %f (%02d): %s} (%.3f us)' % (dev, self.time, \
1224                 self.depth, self.name, self.length*1000000))
1225         else:
1226             print('%s -- %f (%02d): %s() { (%.3f us)' % (dev, self.time, \
1227                 self.depth, self.name, self.length*1000000))
1228     def startMarker(self):
1229         global sysvals
1230         # Is this the starting line of a suspend?
1231         if not self.fevent:
1232             return False
1233         if sysvals.usetracemarkers:
1234             if(self.name == 'SUSPEND START'):
1235                 return True
1236             return False
1237         else:
1238             if(self.type == 'suspend_resume' and
1239                 re.match('suspend_enter\[.*\] begin', self.name)):
1240                 return True
1241             return False
1242     def endMarker(self):
1243         # Is this the ending line of a resume?
1244         if not self.fevent:
1245             return False
1246         if sysvals.usetracemarkers:
1247             if(self.name == 'RESUME COMPLETE'):
1248                 return True
1249             return False
1250         else:
1251             if(self.type == 'suspend_resume' and
1252                 re.match('thaw_processes\[.*\] end', self.name)):
1253                 return True
1254             return False
1255 
1256 # Class: FTraceCallGraph
1257 # Description:
1258 #    A container for the ftrace callgraph of a single recursive function.
1259 #    This can be a dpm_run_callback, dpm_prepare, or dpm_complete callgraph
1260 #    Each instance is tied to a single device in a single phase, and is
1261 #    comprised of an ordered list of FTraceLine objects
1262 class FTraceCallGraph:
1263     start = -1.0
1264     end = -1.0
1265     list = []
1266     invalid = False
1267     depth = 0
1268     pid = 0
1269     def __init__(self, pid):
1270         self.start = -1.0
1271         self.end = -1.0
1272         self.list = []
1273         self.depth = 0
1274         self.pid = pid
1275     def addLine(self, line, debug=False):
1276         # if this is already invalid, just leave
1277         if(self.invalid):
1278             return False
1279         # invalidate on too much data or bad depth
1280         if(len(self.list) >= 1000000 or self.depth < 0):
1281             self.invalidate(line)
1282             return False
1283         # compare current depth with this lines pre-call depth
1284         prelinedep = line.depth
1285         if(line.freturn and not line.fcall):
1286             prelinedep += 1
1287         last = 0
1288         lasttime = line.time
1289         virtualfname = 'execution_misalignment'
1290         if len(self.list) > 0:
1291             last = self.list[-1]
1292             lasttime = last.time
1293         # handle low misalignments by inserting returns
1294         if prelinedep < self.depth:
1295             if debug and last:
1296                 print '-------- task %d --------' % self.pid
1297                 last.debugPrint()
1298             idx = 0
1299             # add return calls to get the depth down
1300             while prelinedep < self.depth:
1301                 if debug:
1302                     print 'MISALIGN LOW (add returns): C%d - eC%d' % (self.depth, prelinedep)
1303                 self.depth -= 1
1304                 if idx == 0 and last and last.fcall and not last.freturn:
1305                     # special case, turn last call into a leaf
1306                     last.depth = self.depth
1307                     last.freturn = True
1308                     last.length = line.time - last.time
1309                     if debug:
1310                         last.debugPrint()
1311                 else:
1312                     vline = FTraceLine(lasttime)
1313                     vline.depth = self.depth
1314                     vline.name = virtualfname
1315                     vline.freturn = True
1316                     self.list.append(vline)
1317                     if debug:
1318                         vline.debugPrint()
1319                 idx += 1
1320             if debug:
1321                 line.debugPrint()
1322                 print ''
1323         # handle high misalignments by inserting calls
1324         elif prelinedep > self.depth:
1325             if debug and last:
1326                 print '-------- task %d --------' % self.pid
1327                 last.debugPrint()
1328             idx = 0
1329             # add calls to get the depth up
1330             while prelinedep > self.depth:
1331                 if debug:
1332                     print 'MISALIGN HIGH (add calls): C%d - eC%d' % (self.depth, prelinedep)
1333                 if idx == 0 and line.freturn and not line.fcall:
1334                     # special case, turn this return into a leaf
1335                     line.fcall = True
1336                     prelinedep -= 1
1337                 else:
1338                     vline = FTraceLine(lasttime)
1339                     vline.depth = self.depth
1340                     vline.name = virtualfname
1341                     vline.fcall = True
1342                     if debug:
1343                         vline.debugPrint()
1344                     self.list.append(vline)
1345                     self.depth += 1
1346                     if not last:
1347                         self.start = vline.time
1348                 idx += 1
1349             if debug:
1350                 line.debugPrint()
1351                 print ''
1352         # process the call and set the new depth
1353         if(line.fcall and not line.freturn):
1354             self.depth += 1
1355         elif(line.freturn and not line.fcall):
1356             self.depth -= 1
1357         if len(self.list) < 1:
1358             self.start = line.time
1359         self.list.append(line)
1360         if(line.depth == 0 and line.freturn):
1361             if(self.start < 0):
1362                 self.start = line.time
1363             self.end = line.time
1364             if line.fcall:
1365                 self.end += line.length
1366             if self.list[0].name == virtualfname:
1367                 self.invalid = True
1368             return True
1369         return False
1370     def invalidate(self, line):
1371         if(len(self.list) > 0):
1372             first = self.list[0]
1373             self.list = []
1374             self.list.append(first)
1375         self.invalid = True
1376         id = 'task %s' % (self.pid)
1377         window = '(%f - %f)' % (self.start, line.time)
1378         if(self.depth < 0):
1379             vprint('Too much data for '+id+\
1380                 ' (buffer overflow), ignoring this callback')
1381         else:
1382             vprint('Too much data for '+id+\
1383                 ' '+window+', ignoring this callback')
1384     def slice(self, t0, tN):
1385         minicg = FTraceCallGraph(0)
1386         count = -1
1387         firstdepth = 0
1388         for l in self.list:
1389             if(l.time < t0 or l.time > tN):
1390                 continue
1391             if(count < 0):
1392                 if(not l.fcall or l.name == 'dev_driver_string'):
1393                     continue
1394                 firstdepth = l.depth
1395                 count = 0
1396             l.depth -= firstdepth
1397             minicg.addLine(l)
1398             if((count == 0 and l.freturn and l.fcall) or
1399                 (count > 0 and l.depth <= 0)):
1400                 break
1401             count += 1
1402         return minicg
1403     def repair(self, enddepth):
1404         # bring the depth back to 0 with additional returns
1405         fixed = False
1406         last = self.list[-1]
1407         for i in reversed(range(enddepth)):
1408             t = FTraceLine(last.time)
1409             t.depth = i
1410             t.freturn = True
1411             fixed = self.addLine(t)
1412             if fixed:
1413                 self.end = last.time
1414                 return True
1415         return False
1416     def postProcess(self, debug=False):
1417         stack = dict()
1418         cnt = 0
1419         for l in self.list:
1420             if(l.fcall and not l.freturn):
1421                 stack[l.depth] = l
1422                 cnt += 1
1423             elif(l.freturn and not l.fcall):
1424                 if(l.depth not in stack):
1425                     if debug:
1426                         print 'Post Process Error: Depth missing'
1427                         l.debugPrint()
1428                     return False
1429                 # transfer total time from return line to call line
1430                 stack[l.depth].length = l.length
1431                 stack.pop(l.depth)
1432                 l.length = 0
1433                 cnt -= 1
1434         if(cnt == 0):
1435             # trace caught the whole call tree
1436             return True
1437         elif(cnt < 0):
1438             if debug:
1439                 print 'Post Process Error: Depth is less than 0'
1440             return False
1441         # trace ended before call tree finished
1442         return self.repair(cnt)
1443     def deviceMatch(self, pid, data):
1444         found = False
1445         # add the callgraph data to the device hierarchy
1446         borderphase = {
1447             'dpm_prepare': 'suspend_prepare',
1448             'dpm_complete': 'resume_complete'
1449         }
1450         if(self.list[0].name in borderphase):
1451             p = borderphase[self.list[0].name]
1452             list = data.dmesg[p]['list']
1453             for devname in list:
1454                 dev = list[devname]
1455                 if(pid == dev['pid'] and
1456                     self.start <= dev['start'] and
1457                     self.end >= dev['end']):
1458                     dev['ftrace'] = self.slice(dev['start'], dev['end'])
1459                     found = True
1460             return found
1461         for p in data.phases:
1462             if(data.dmesg[p]['start'] <= self.start and
1463                 self.start <= data.dmesg[p]['end']):
1464                 list = data.dmesg[p]['list']
1465                 for devname in list:
1466                     dev = list[devname]
1467                     if(pid == dev['pid'] and
1468                         self.start <= dev['start'] and
1469                         self.end >= dev['end']):
1470                         dev['ftrace'] = self
1471                         found = True
1472                         break
1473                 break
1474         return found
1475     def newActionFromFunction(self, data):
1476         name = self.list[0].name
1477         if name in ['dpm_run_callback', 'dpm_prepare', 'dpm_complete']:
1478             return
1479         fs = self.start
1480         fe = self.end
1481         if fs < data.start or fe > data.end:
1482             return
1483         phase = ''
1484         for p in data.phases:
1485             if(data.dmesg[p]['start'] <= self.start and
1486                 self.start < data.dmesg[p]['end']):
1487                 phase = p
1488                 break
1489         if not phase:
1490             return
1491         out = data.newActionGlobal(name, fs, fe, -2)
1492         if out:
1493             phase, myname = out
1494             data.dmesg[phase]['list'][myname]['ftrace'] = self
1495     def debugPrint(self):
1496         print('[%f - %f] %s (%d)') % (self.start, self.end, self.list[0].name, self.pid)
1497         for l in self.list:
1498             if(l.freturn and l.fcall):
1499                 print('%f (%02d): %s(); (%.3f us)' % (l.time, \
1500                     l.depth, l.name, l.length*1000000))
1501             elif(l.freturn):
1502                 print('%f (%02d): %s} (%.3f us)' % (l.time, \
1503                     l.depth, l.name, l.length*1000000))
1504             else:
1505                 print('%f (%02d): %s() { (%.3f us)' % (l.time, \
1506                     l.depth, l.name, l.length*1000000))
1507         print(' ')
1508 
1509 # Class: Timeline
1510 # Description:
1511 #    A container for a device timeline which calculates
1512 #    all the html properties to display it correctly
1513 class Timeline:
1514     html = {}
1515     height = 0  # total timeline height
1516     scaleH = 20 # timescale (top) row height
1517     rowH = 30   # device row height
1518     bodyH = 0   # body height
1519     rows = 0    # total timeline rows
1520     phases = []
1521     rowmaxlines = dict()
1522     rowcount = dict()
1523     rowheight = dict()
1524     def __init__(self, rowheight):
1525         self.rowH = rowheight
1526         self.html = {
1527             'header': '',
1528             'timeline': '',
1529             'legend': '',
1530         }
1531     # Function: getDeviceRows
1532     # Description:
1533     #    determine how may rows the device funcs will take
1534     # Arguments:
1535     #    rawlist: the list of devices/actions for a single phase
1536     # Output:
1537     #    The total number of rows needed to display this phase of the timeline
1538     def getDeviceRows(self, rawlist):
1539         # clear all rows and set them to undefined
1540         lendict = dict()
1541         for item in rawlist:
1542             item.row = -1
1543             lendict[item] = item.length
1544         list = []
1545         for i in sorted(lendict, key=lendict.get, reverse=True):
1546             list.append(i)
1547         remaining = len(list)
1548         rowdata = dict()
1549         row = 1
1550         # try to pack each row with as many ranges as possible
1551         while(remaining > 0):
1552             if(row not in rowdata):
1553                 rowdata[row] = []
1554             for i in list:
1555                 if(i.row >= 0):
1556                     continue
1557                 s = i.time
1558                 e = i.time + i.length
1559                 valid = True
1560                 for ritem in rowdata[row]:
1561                     rs = ritem.time
1562                     re = ritem.time + ritem.length
1563                     if(not (((s <= rs) and (e <= rs)) or
1564                         ((s >= re) and (e >= re)))):
1565                         valid = False
1566                         break
1567                 if(valid):
1568                     rowdata[row].append(i)
1569                     i.row = row
1570                     remaining -= 1
1571             row += 1
1572         return row
1573     # Function: getPhaseRows
1574     # Description:
1575     #    Organize the timeline entries into the smallest
1576     #    number of rows possible, with no entry overlapping
1577     # Arguments:
1578     #    list: the list of devices/actions for a single phase
1579     #    devlist: string list of device names to use
1580     # Output:
1581     #    The total number of rows needed to display this phase of the timeline
1582     def getPhaseRows(self, dmesg, devlist):
1583         # clear all rows and set them to undefined
1584         remaining = len(devlist)
1585         rowdata = dict()
1586         row = 0
1587         lendict = dict()
1588         myphases = []
1589         for item in devlist:
1590             if item[0] not in self.phases:
1591                 self.phases.append(item[0])
1592             if item[0] not in myphases:
1593                 myphases.append(item[0])
1594                 self.rowmaxlines[item[0]] = dict()
1595                 self.rowheight[item[0]] = dict()
1596             dev = dmesg[item[0]]['list'][item[1]]
1597             dev['row'] = -1
1598             lendict[item] = float(dev['end']) - float(dev['start'])
1599             if 'src' in dev:
1600                 dev['devrows'] = self.getDeviceRows(dev['src'])
1601         lenlist = []
1602         for i in sorted(lendict, key=lendict.get, reverse=True):
1603             lenlist.append(i)
1604         orderedlist = []
1605         for item in lenlist:
1606             dev = dmesg[item[0]]['list'][item[1]]
1607             if dev['pid'] == -2:
1608                 orderedlist.append(item)
1609         for item in lenlist:
1610             if item not in orderedlist:
1611                 orderedlist.append(item)
1612         # try to pack each row with as many ranges as possible
1613         while(remaining > 0):
1614             rowheight = 1
1615             if(row not in rowdata):
1616                 rowdata[row] = []
1617             for item in orderedlist:
1618                 dev = dmesg[item[0]]['list'][item[1]]
1619                 if(dev['row'] < 0):
1620                     s = dev['start']
1621                     e = dev['end']
1622                     valid = True
1623                     for ritem in rowdata[row]:
1624                         rs = ritem['start']
1625                         re = ritem['end']
1626                         if(not (((s <= rs) and (e <= rs)) or
1627                             ((s >= re) and (e >= re)))):
1628                             valid = False
1629                             break
1630                     if(valid):
1631                         rowdata[row].append(dev)
1632                         dev['row'] = row
1633                         remaining -= 1
1634                         if 'devrows' in dev and dev['devrows'] > rowheight:
1635                             rowheight = dev['devrows']
1636             for phase in myphases:
1637                 self.rowmaxlines[phase][row] = rowheight
1638                 self.rowheight[phase][row] = rowheight * self.rowH
1639             row += 1
1640         if(row > self.rows):
1641             self.rows = int(row)
1642         for phase in myphases:
1643             self.rowcount[phase] = row
1644         return row
1645     def phaseRowHeight(self, phase, row):
1646         return self.rowheight[phase][row]
1647     def phaseRowTop(self, phase, row):
1648         top = 0
1649         for i in sorted(self.rowheight[phase]):
1650             if i >= row:
1651                 break
1652             top += self.rowheight[phase][i]
1653         return top
1654     # Function: calcTotalRows
1655     # Description:
1656     #    Calculate the heights and offsets for the header and rows
1657     def calcTotalRows(self):
1658         maxrows = 0
1659         standardphases = []
1660         for phase in self.phases:
1661             total = 0
1662             for i in sorted(self.rowmaxlines[phase]):
1663                 total += self.rowmaxlines[phase][i]
1664             if total > maxrows:
1665                 maxrows = total
1666             if total == self.rowcount[phase]:
1667                 standardphases.append(phase)
1668         self.height = self.scaleH + (maxrows*self.rowH)
1669         self.bodyH = self.height - self.scaleH
1670         for phase in standardphases:
1671             for i in sorted(self.rowheight[phase]):
1672                 self.rowheight[phase][i] = self.bodyH/self.rowcount[phase]
1673     # Function: createTimeScale
1674     # Description:
1675     #    Create the timescale for a timeline block
1676     # Arguments:
1677     #    m0: start time (mode begin)
1678     #    mMax: end time (mode end)
1679     #    tTotal: total timeline time
1680     #    mode: suspend or resume
1681     # Output:
1682     #    The html code needed to display the time scale
1683     def createTimeScale(self, m0, mMax, tTotal, mode):
1684         timescale = '<div class="t" style="right:{0}%">{1}</div>\n'
1685         rline = '<div class="t" style="left:0;border-left:1px solid black;border-right:0;">Resume</div>\n'
1686         output = '<div class="timescale">\n'
1687         # set scale for timeline
1688         mTotal = mMax - m0
1689         tS = 0.1
1690         if(tTotal <= 0):
1691             return output+'</div>\n'
1692         if(tTotal > 4):
1693             tS = 1
1694         divTotal = int(mTotal/tS) + 1
1695         divEdge = (mTotal - tS*(divTotal-1))*100/mTotal
1696         for i in range(divTotal):
1697             htmlline = ''
1698             if(mode == 'resume'):
1699                 pos = '%0.3f' % (100 - ((float(i)*tS*100)/mTotal))
1700                 val = '%0.fms' % (float(i)*tS*1000)
1701                 htmlline = timescale.format(pos, val)
1702                 if(i == 0):
1703                     htmlline = rline
1704             else:
1705                 pos = '%0.3f' % (100 - ((float(i)*tS*100)/mTotal) - divEdge)
1706                 val = '%0.fms' % (float(i-divTotal+1)*tS*1000)
1707                 if(i == divTotal - 1):
1708                     val = 'Suspend'
1709                 htmlline = timescale.format(pos, val)
1710             output += htmlline
1711         output += '</div>\n'
1712         return output
1713 
1714 # Class: TestProps
1715 # Description:
1716 #    A list of values describing the properties of these test runs
1717 class TestProps:
1718     stamp = ''
1719     tracertype = ''
1720     S0i3 = False
1721     fwdata = []
1722     ftrace_line_fmt_fg = \
1723         '^ *(?P<time>[0-9\.]*) *\| *(?P<cpu>[0-9]*)\)'+\
1724         ' *(?P<proc>.*)-(?P<pid>[0-9]*) *\|'+\
1725         '[ +!#\*@$]*(?P<dur>[0-9\.]*) .*\|  (?P<msg>.*)'
1726     ftrace_line_fmt_nop = \
1727         ' *(?P<proc>.*)-(?P<pid>[0-9]*) *\[(?P<cpu>[0-9]*)\] *'+\
1728         '(?P<flags>.{4}) *(?P<time>[0-9\.]*): *'+\
1729         '(?P<msg>.*)'
1730     ftrace_line_fmt = ftrace_line_fmt_nop
1731     cgformat = False
1732     data = 0
1733     ktemp = dict()
1734     def __init__(self):
1735         self.ktemp = dict()
1736     def setTracerType(self, tracer):
1737         self.tracertype = tracer
1738         if(tracer == 'function_graph'):
1739             self.cgformat = True
1740             self.ftrace_line_fmt = self.ftrace_line_fmt_fg
1741         elif(tracer == 'nop'):
1742             self.ftrace_line_fmt = self.ftrace_line_fmt_nop
1743         else:
1744             doError('Invalid tracer format: [%s]' % tracer, False)
1745 
1746 # Class: TestRun
1747 # Description:
1748 #    A container for a suspend/resume test run. This is necessary as
1749 #    there could be more than one, and they need to be separate.
1750 class TestRun:
1751     ftemp = dict()
1752     ttemp = dict()
1753     data = 0
1754     def __init__(self, dataobj):
1755         self.data = dataobj
1756         self.ftemp = dict()
1757         self.ttemp = dict()
1758 
1759 # ----------------- FUNCTIONS --------------------
1760 
1761 # Function: vprint
1762 # Description:
1763 #    verbose print (prints only with -verbose option)
1764 # Arguments:
1765 #    msg: the debug/log message to print
1766 def vprint(msg):
1767     global sysvals
1768     if(sysvals.verbose):
1769         print(msg)
1770 
1771 # Function: parseStamp
1772 # Description:
1773 #    Pull in the stamp comment line from the data file(s),
1774 #    create the stamp, and add it to the global sysvals object
1775 # Arguments:
1776 #    m: the valid re.match output for the stamp line
1777 def parseStamp(line, data):
1778     global sysvals
1779 
1780     m = re.match(sysvals.stampfmt, line)
1781     data.stamp = {'time': '', 'host': '', 'mode': ''}
1782     dt = datetime(int(m.group('y'))+2000, int(m.group('m')),
1783         int(m.group('d')), int(m.group('H')), int(m.group('M')),
1784         int(m.group('S')))
1785     data.stamp['time'] = dt.strftime('%B %d %Y, %I:%M:%S %p')
1786     data.stamp['host'] = m.group('host')
1787     data.stamp['mode'] = m.group('mode')
1788     data.stamp['kernel'] = m.group('kernel')
1789     sysvals.hostname = data.stamp['host']
1790     sysvals.suspendmode = data.stamp['mode']
1791     if not sysvals.stamp:
1792         sysvals.stamp = data.stamp
1793 
1794 # Function: diffStamp
1795 # Description:
1796 #   compare the host, kernel, and mode fields in 3 stamps
1797 # Arguments:
1798 #    stamp1: string array with mode, kernel, and host
1799 #    stamp2: string array with mode, kernel, and host
1800 # Return:
1801 #   True if stamps differ, False if they're the same
1802 def diffStamp(stamp1, stamp2):
1803     if 'host' in stamp1 and 'host' in stamp2:
1804         if stamp1['host'] != stamp2['host']:
1805             return True
1806     if 'kernel' in stamp1 and 'kernel' in stamp2:
1807         if stamp1['kernel'] != stamp2['kernel']:
1808             return True
1809     if 'mode' in stamp1 and 'mode' in stamp2:
1810         if stamp1['mode'] != stamp2['mode']:
1811             return True
1812     return False
1813 
1814 # Function: doesTraceLogHaveTraceEvents
1815 # Description:
1816 #    Quickly determine if the ftrace log has some or all of the trace events
1817 #    required for primary parsing. Set the usetraceevents and/or
1818 #    usetraceeventsonly flags in the global sysvals object
1819 def doesTraceLogHaveTraceEvents():
1820     global sysvals
1821 
1822     # check for kprobes
1823     sysvals.usekprobes = False
1824     out = os.system('grep -q "_cal: (" '+sysvals.ftracefile)
1825     if(out == 0):
1826         sysvals.usekprobes = True
1827     # check for callgraph data on trace event blocks
1828     out = os.system('grep -q "_cpu_down()" '+sysvals.ftracefile)
1829     if(out == 0):
1830         sysvals.usekprobes = True
1831     out = os.popen('head -1 '+sysvals.ftracefile).read().replace('\n', '')
1832     m = re.match(sysvals.stampfmt, out)
1833     if m and m.group('mode') == 'command':
1834         sysvals.usetraceeventsonly = True
1835         sysvals.usetraceevents = True
1836         return
1837     # figure out what level of trace events are supported
1838     sysvals.usetraceeventsonly = True
1839     sysvals.usetraceevents = False
1840     for e in sysvals.traceevents:
1841         out = os.system('grep -q "'+e+': " '+sysvals.ftracefile)
1842         if(out != 0):
1843             sysvals.usetraceeventsonly = False
1844         if(e == 'suspend_resume' and out == 0):
1845             sysvals.usetraceevents = True
1846     # determine is this log is properly formatted
1847     for e in ['SUSPEND START', 'RESUME COMPLETE']:
1848         out = os.system('grep -q "'+e+'" '+sysvals.ftracefile)
1849         if(out != 0):
1850             sysvals.usetracemarkers = False
1851 
1852 # Function: appendIncompleteTraceLog
1853 # Description:
1854 #    [deprecated for kernel 3.15 or newer]
1855 #    Legacy support of ftrace outputs that lack the device_pm_callback
1856 #    and/or suspend_resume trace events. The primary data should be
1857 #    taken from dmesg, and this ftrace is used only for callgraph data
1858 #    or custom actions in the timeline. The data is appended to the Data
1859 #    objects provided.
1860 # Arguments:
1861 #    testruns: the array of Data objects obtained from parseKernelLog
1862 def appendIncompleteTraceLog(testruns):
1863     global sysvals
1864 
1865     # create TestRun vessels for ftrace parsing
1866     testcnt = len(testruns)
1867     testidx = 0
1868     testrun = []
1869     for data in testruns:
1870         testrun.append(TestRun(data))
1871 
1872     # extract the callgraph and traceevent data
1873     vprint('Analyzing the ftrace data...')
1874     tp = TestProps()
1875     tf = open(sysvals.ftracefile, 'r')
1876     data = 0
1877     for line in tf:
1878         # remove any latent carriage returns
1879         line = line.replace('\r\n', '')
1880         # grab the time stamp
1881         m = re.match(sysvals.stampfmt, line)
1882         if(m):
1883             tp.stamp = line
1884             continue
1885         # determine the trace data type (required for further parsing)
1886         m = re.match(sysvals.tracertypefmt, line)
1887         if(m):
1888             tp.setTracerType(m.group('t'))
1889             continue
1890         # device properties line
1891         if(re.match(sysvals.devpropfmt, line)):
1892             devProps(line)
1893             continue
1894         # parse only valid lines, if this is not one move on
1895         m = re.match(tp.ftrace_line_fmt, line)
1896         if(not m):
1897             continue
1898         # gather the basic message data from the line
1899         m_time = m.group('time')
1900         m_pid = m.group('pid')
1901         m_msg = m.group('msg')
1902         if(tp.cgformat):
1903             m_param3 = m.group('dur')
1904         else:
1905             m_param3 = 'traceevent'
1906         if(m_time and m_pid and m_msg):
1907             t = FTraceLine(m_time, m_msg, m_param3)
1908             pid = int(m_pid)
1909         else:
1910             continue
1911         # the line should be a call, return, or event
1912         if(not t.fcall and not t.freturn and not t.fevent):
1913             continue
1914         # look for the suspend start marker
1915         if(t.startMarker()):
1916             data = testrun[testidx].data
1917             parseStamp(tp.stamp, data)
1918             data.setStart(t.time)
1919             continue
1920         if(not data):
1921             continue
1922         # find the end of resume
1923         if(t.endMarker()):
1924             data.setEnd(t.time)
1925             testidx += 1
1926             if(testidx >= testcnt):
1927                 break
1928             continue
1929         # trace event processing
1930         if(t.fevent):
1931             # general trace events have two types, begin and end
1932             if(re.match('(?P<name>.*) begin$', t.name)):
1933                 isbegin = True
1934             elif(re.match('(?P<name>.*) end$', t.name)):
1935                 isbegin = False
1936             else:
1937                 continue
1938             m = re.match('(?P<name>.*)\[(?P<val>[0-9]*)\] .*', t.name)
1939             if(m):
1940                 val = m.group('val')
1941                 if val == '0':
1942                     name = m.group('name')
1943                 else:
1944                     name = m.group('name')+'['+val+']'
1945             else:
1946                 m = re.match('(?P<name>.*) .*', t.name)
1947                 name = m.group('name')
1948             # special processing for trace events
1949             if re.match('dpm_prepare\[.*', name):
1950                 continue
1951             elif re.match('machine_suspend.*', name):
1952                 continue
1953             elif re.match('suspend_enter\[.*', name):
1954                 if(not isbegin):
1955                     data.dmesg['suspend_prepare']['end'] = t.time
1956                 continue
1957             elif re.match('dpm_suspend\[.*', name):
1958                 if(not isbegin):
1959                     data.dmesg['suspend']['end'] = t.time
1960                 continue
1961             elif re.match('dpm_suspend_late\[.*', name):
1962                 if(isbegin):
1963                     data.dmesg['suspend_late']['start'] = t.time
1964                 else:
1965                     data.dmesg['suspend_late']['end'] = t.time
1966                 continue
1967             elif re.match('dpm_suspend_noirq\[.*', name):
1968                 if(isbegin):
1969                     data.dmesg['suspend_noirq']['start'] = t.time
1970                 else:
1971                     data.dmesg['suspend_noirq']['end'] = t.time
1972                 continue
1973             elif re.match('dpm_resume_noirq\[.*', name):
1974                 if(isbegin):
1975                     data.dmesg['resume_machine']['end'] = t.time
1976                     data.dmesg['resume_noirq']['start'] = t.time
1977                 else:
1978                     data.dmesg['resume_noirq']['end'] = t.time
1979                 continue
1980             elif re.match('dpm_resume_early\[.*', name):
1981                 if(isbegin):
1982                     data.dmesg['resume_early']['start'] = t.time
1983                 else:
1984                     data.dmesg['resume_early']['end'] = t.time
1985                 continue
1986             elif re.match('dpm_resume\[.*', name):
1987                 if(isbegin):
1988                     data.dmesg['resume']['start'] = t.time
1989                 else:
1990                     data.dmesg['resume']['end'] = t.time
1991                 continue
1992             elif re.match('dpm_complete\[.*', name):
1993                 if(isbegin):
1994                     data.dmesg['resume_complete']['start'] = t.time
1995                 else:
1996                     data.dmesg['resume_complete']['end'] = t.time
1997                 continue
1998             # skip trace events inside devices calls
1999             if(not data.isTraceEventOutsideDeviceCalls(pid, t.time)):
2000                 continue
2001             # global events (outside device calls) are simply graphed
2002             if(isbegin):
2003                 # store each trace event in ttemp
2004                 if(name not in testrun[testidx].ttemp):
2005                     testrun[testidx].ttemp[name] = []
2006                 testrun[testidx].ttemp[name].append(\
2007                     {'begin': t.time, 'end': t.time})
2008             else:
2009                 # finish off matching trace event in ttemp
2010                 if(name in testrun[testidx].ttemp):
2011                     testrun[testidx].ttemp[name][-1]['end'] = t.time
2012         # call/return processing
2013         elif sysvals.usecallgraph:
2014             # create a callgraph object for the data
2015             if(pid not in testrun[testidx].ftemp):
2016                 testrun[testidx].ftemp[pid] = []
2017                 testrun[testidx].ftemp[pid].append(FTraceCallGraph(pid))
2018             # when the call is finished, see which device matches it
2019             cg = testrun[testidx].ftemp[pid][-1]
2020             if(cg.addLine(t)):
2021                 testrun[testidx].ftemp[pid].append(FTraceCallGraph(pid))
2022     tf.close()
2023 
2024     for test in testrun:
2025         # add the traceevent data to the device hierarchy
2026         if(sysvals.usetraceevents):
2027             for name in test.ttemp:
2028                 for event in test.ttemp[name]:
2029                     test.data.newActionGlobal(name, event['begin'], event['end'])
2030 
2031         # add the callgraph data to the device hierarchy
2032         for pid in test.ftemp:
2033             for cg in test.ftemp[pid]:
2034                 if len(cg.list) < 1 or cg.invalid:
2035                     continue
2036                 if(not cg.postProcess()):
2037                     id = 'task %s cpu %s' % (pid, m.group('cpu'))
2038                     vprint('Sanity check failed for '+\
2039                         id+', ignoring this callback')
2040                     continue
2041                 callstart = cg.start
2042                 callend = cg.end
2043                 for p in test.data.phases:
2044                     if(test.data.dmesg[p]['start'] <= callstart and
2045                         callstart <= test.data.dmesg[p]['end']):
2046                         list = test.data.dmesg[p]['list']
2047                         for devname in list:
2048                             dev = list[devname]
2049                             if(pid == dev['pid'] and
2050                                 callstart <= dev['start'] and
2051                                 callend >= dev['end']):
2052                                 dev['ftrace'] = cg
2053                         break
2054 
2055         if(sysvals.verbose):
2056             test.data.printDetails()
2057 
2058 # Function: parseTraceLog
2059 # Description:
2060 #    Analyze an ftrace log output file generated from this app during
2061 #    the execution phase. Used when the ftrace log is the primary data source
2062 #    and includes the suspend_resume and device_pm_callback trace events
2063 #    The ftrace filename is taken from sysvals
2064 # Output:
2065 #    An array of Data objects
2066 def parseTraceLog():
2067     global sysvals
2068 
2069     vprint('Analyzing the ftrace data...')
2070     if(os.path.exists(sysvals.ftracefile) == False):
2071         doError('%s does not exist' % sysvals.ftracefile, False)
2072 
2073     sysvals.setupAllKprobes()
2074     tracewatch = ['suspend_enter']
2075     if sysvals.usekprobes:
2076         tracewatch += ['sync_filesystems', 'freeze_processes', 'syscore_suspend',
2077             'syscore_resume', 'resume_console', 'thaw_processes', 'CPU_ON', 'CPU_OFF']
2078 
2079     # extract the callgraph and traceevent data
2080     tp = TestProps()
2081     testruns = []
2082     testdata = []
2083     testrun = 0
2084     data = 0
2085     tf = open(sysvals.ftracefile, 'r')
2086     phase = 'suspend_prepare'
2087     for line in tf:
2088         # remove any latent carriage returns
2089         line = line.replace('\r\n', '')
2090         # stamp line: each stamp means a new test run
2091         m = re.match(sysvals.stampfmt, line)
2092         if(m):
2093             tp.stamp = line
2094             continue
2095         # firmware line: pull out any firmware data
2096         m = re.match(sysvals.firmwarefmt, line)
2097         if(m):
2098             tp.fwdata.append((int(m.group('s')), int(m.group('r'))))
2099             continue
2100         # tracer type line: determine the trace data type
2101         m = re.match(sysvals.tracertypefmt, line)
2102         if(m):
2103             tp.setTracerType(m.group('t'))
2104             continue
2105         # post resume time line: did this test run include post-resume data
2106         m = re.match(sysvals.postresumefmt, line)
2107         if(m):
2108             t = int(m.group('t'))
2109             if(t > 0):
2110                 sysvals.postresumetime = t
2111             continue
2112         # device properties line
2113         if(re.match(sysvals.devpropfmt, line)):
2114             devProps(line)
2115             continue
2116         # ftrace line: parse only valid lines
2117         m = re.match(tp.ftrace_line_fmt, line)
2118         if(not m):
2119             continue
2120         # gather the basic message data from the line
2121         m_time = m.group('time')
2122         m_proc = m.group('proc')
2123         m_pid = m.group('pid')
2124         m_msg = m.group('msg')
2125         if(tp.cgformat):
2126             m_param3 = m.group('dur')
2127         else:
2128             m_param3 = 'traceevent'
2129         if(m_time and m_pid and m_msg):
2130             t = FTraceLine(m_time, m_msg, m_param3)
2131             pid = int(m_pid)
2132         else:
2133             continue
2134         # the line should be a call, return, or event
2135         if(not t.fcall and not t.freturn and not t.fevent):
2136             continue
2137         # find the start of suspend
2138         if(t.startMarker()):
2139             phase = 'suspend_prepare'
2140             data = Data(len(testdata))
2141             testdata.append(data)
2142             testrun = TestRun(data)
2143             testruns.append(testrun)
2144             parseStamp(tp.stamp, data)
2145             if len(tp.fwdata) > data.testnumber:
2146                 data.fwSuspend, data.fwResume = tp.fwdata[data.testnumber]
2147                 if(data.fwSuspend > 0 or data.fwResume > 0):
2148                     data.fwValid = True
2149             data.setStart(t.time)
2150             continue
2151         if(not data):
2152             continue
2153         # find the end of resume
2154         if(t.endMarker()):
2155             if(sysvals.usetracemarkers and sysvals.postresumetime > 0):
2156                 phase = 'post_resume'
2157                 data.newPhase(phase, t.time, t.time, '#F0F0F0', -1)
2158             data.setEnd(t.time)
2159             if(not sysvals.usetracemarkers):
2160                 # no trace markers? then quit and be sure to finish recording
2161                 # the event we used to trigger resume end
2162                 if(len(testrun.ttemp['thaw_processes']) > 0):
2163                     # if an entry exists, assume this is its end
2164                     testrun.ttemp['thaw_processes'][-1]['end'] = t.time
2165                 break
2166             continue
2167         # trace event processing
2168         if(t.fevent):
2169             if(phase == 'post_resume'):
2170                 data.setEnd(t.time)
2171             if(t.type == 'suspend_resume'):
2172                 # suspend_resume trace events have two types, begin and end
2173                 if(re.match('(?P<name>.*) begin$', t.name)):
2174                     isbegin = True
2175                 elif(re.match('(?P<name>.*) end$', t.name)):
2176                     isbegin = False
2177                 else:
2178                     continue
2179                 m = re.match('(?P<name>.*)\[(?P<val>[0-9]*)\] .*', t.name)
2180                 if(m):
2181                     val = m.group('val')
2182                     if val == '0':
2183                         name = m.group('name')
2184                     else:
2185                         name = m.group('name')+'['+val+']'
2186                 else:
2187                     m = re.match('(?P<name>.*) .*', t.name)
2188                     name = m.group('name')
2189                 # ignore these events
2190                 if(name.split('[')[0] in tracewatch):
2191                     continue
2192                 # -- phase changes --
2193                 # suspend_prepare start
2194                 if(re.match('dpm_prepare\[.*', t.name)):
2195                     phase = 'suspend_prepare'
2196                     if(not isbegin):
2197                         data.dmesg[phase]['end'] = t.time
2198                     continue
2199                 # suspend start
2200                 elif(re.match('dpm_suspend\[.*', t.name)):
2201                     phase = 'suspend'
2202                     data.setPhase(phase, t.time, isbegin)
2203                     continue
2204                 # suspend_late start
2205                 elif(re.match('dpm_suspend_late\[.*', t.name)):
2206                     phase = 'suspend_late'
2207                     data.setPhase(phase, t.time, isbegin)
2208                     continue
2209                 # suspend_noirq start
2210                 elif(re.match('dpm_suspend_noirq\[.*', t.name)):
2211                     phase = 'suspend_noirq'
2212                     data.setPhase(phase, t.time, isbegin)
2213                     if(not isbegin):
2214                         phase = 'suspend_machine'
2215                         data.dmesg[phase]['start'] = t.time
2216                     continue
2217                 # suspend_machine/resume_machine
2218                 elif(re.match('machine_suspend\[.*', t.name)):
2219                     if(isbegin):
2220                         phase = 'suspend_machine'
2221                         data.dmesg[phase]['end'] = t.time
2222                         data.tSuspended = t.time
2223                     else:
2224                         if(sysvals.suspendmode in ['mem', 'disk'] and not tp.S0i3):
2225                             data.dmesg['suspend_machine']['end'] = t.time
2226                             data.tSuspended = t.time
2227                         phase = 'resume_machine'
2228                         data.dmesg[phase]['start'] = t.time
2229                         data.tResumed = t.time
2230                         data.tLow = data.tResumed - data.tSuspended
2231                     continue
2232                 # acpi_suspend
2233                 elif(re.match('acpi_suspend\[.*', t.name)):
2234                     # acpi_suspend[0] S0i3
2235                     if(re.match('acpi_suspend\[0\] begin', t.name)):
2236                         if(sysvals.suspendmode == 'mem'):
2237                             tp.S0i3 = True
2238                             data.dmesg['suspend_machine']['end'] = t.time
2239                             data.tSuspended = t.time
2240                     continue
2241                 # resume_noirq start
2242                 elif(re.match('dpm_resume_noirq\[.*', t.name)):
2243                     phase = 'resume_noirq'
2244                     data.setPhase(phase, t.time, isbegin)
2245                     if(isbegin):
2246                         data.dmesg['resume_machine']['end'] = t.time
2247                     continue
2248                 # resume_early start
2249                 elif(re.match('dpm_resume_early\[.*', t.name)):
2250                     phase = 'resume_early'
2251                     data.setPhase(phase, t.time, isbegin)
2252                     continue
2253                 # resume start
2254                 elif(re.match('dpm_resume\[.*', t.name)):
2255                     phase = 'resume'
2256                     data.setPhase(phase, t.time, isbegin)
2257                     continue
2258                 # resume complete start
2259                 elif(re.match('dpm_complete\[.*', t.name)):
2260                     phase = 'resume_complete'
2261                     if(isbegin):
2262                         data.dmesg[phase]['start'] = t.time
2263                     continue
2264                 # skip trace events inside devices calls
2265                 if(not data.isTraceEventOutsideDeviceCalls(pid, t.time)):
2266                     continue
2267                 # global events (outside device calls) are graphed
2268                 if(name not in testrun.ttemp):
2269                     testrun.ttemp[name] = []
2270                 if(isbegin):
2271                     # create a new list entry
2272                     testrun.ttemp[name].append(\
2273                         {'begin': t.time, 'end': t.time, 'pid': pid})
2274                 else:
2275                     if(len(testrun.ttemp[name]) > 0):
2276                         # if an entry exists, assume this is its end
2277                         testrun.ttemp[name][-1]['end'] = t.time
2278                     elif(phase == 'post_resume'):
2279                         # post resume events can just have ends
2280                         testrun.ttemp[name].append({
2281                             'begin': data.dmesg[phase]['start'],
2282                             'end': t.time})
2283             # device callback start
2284             elif(t.type == 'device_pm_callback_start'):
2285                 m = re.match('(?P<drv>.*) (?P<d>.*), parent: *(?P<p>.*), .*',\
2286                     t.name);
2287                 if(not m):
2288                     continue
2289                 drv = m.group('drv')
2290                 n = m.group('d')
2291                 p = m.group('p')
2292                 if(n and p):
2293                     data.newAction(phase, n, pid, p, t.time, -1, drv)
2294             # device callback finish
2295             elif(t.type == 'device_pm_callback_end'):
2296                 m = re.match('(?P<drv>.*) (?P<d>.*), err.*', t.name);
2297                 if(not m):
2298                     continue
2299                 n = m.group('d')
2300                 list = data.dmesg[phase]['list']
2301                 if(n in list):
2302                     dev = list[n]
2303                     dev['length'] = t.time - dev['start']
2304                     dev['end'] = t.time
2305         # kprobe event processing
2306         elif(t.fkprobe):
2307             kprobename = t.type
2308             kprobedata = t.name
2309             key = (kprobename, pid)
2310             # displayname is generated from kprobe data
2311             displayname = ''
2312             if(t.fcall):
2313                 displayname = sysvals.kprobeDisplayName(kprobename, kprobedata)
2314                 if not displayname:
2315                     continue
2316                 if(key not in tp.ktemp):
2317                     tp.ktemp[key] = []
2318                 tp.ktemp[key].append({
2319                     'pid': pid,
2320                     'begin': t.time,
2321                     'end': t.time,
2322                     'name': displayname,
2323                     'cdata': kprobedata,
2324                     'proc': m_proc,
2325                 })
2326             elif(t.freturn):
2327                 if(key not in tp.ktemp) or len(tp.ktemp[key]) < 1:
2328                     continue
2329                 e = tp.ktemp[key][-1]
2330                 if e['begin'] < 0.0 or t.time - e['begin'] < 0.000001:
2331                     tp.ktemp[key].pop()
2332                 else:
2333                     e['end'] = t.time
2334                     e['rdata'] = kprobedata
2335         # callgraph processing
2336         elif sysvals.usecallgraph:
2337             # create a callgraph object for the data
2338             key = (m_proc, pid)
2339             if(key not in testrun.ftemp):
2340                 testrun.ftemp[key] = []
2341                 testrun.ftemp[key].append(FTraceCallGraph(pid))
2342             # when the call is finished, see which device matches it
2343             cg = testrun.ftemp[key][-1]
2344             if(cg.addLine(t)):
2345                 testrun.ftemp[key].append(FTraceCallGraph(pid))
2346     tf.close()
2347 
2348     if sysvals.suspendmode == 'command':
2349         for test in testruns:
2350             for p in test.data.phases:
2351                 if p == 'resume_complete':
2352                     test.data.dmesg[p]['start'] = test.data.start
2353                     test.data.dmesg[p]['end'] = test.data.end
2354                 else:
2355                     test.data.dmesg[p]['start'] = test.data.start
2356                     test.data.dmesg[p]['end'] = test.data.start
2357             test.data.tSuspended = test.data.start
2358             test.data.tResumed = test.data.start
2359             test.data.tLow = 0
2360             test.data.fwValid = False
2361 
2362     for test in testruns:
2363         # add the traceevent data to the device hierarchy
2364         if(sysvals.usetraceevents):
2365             # add actual trace funcs
2366             for name in test.ttemp:
2367                 for event in test.ttemp[name]:
2368                     test.data.newActionGlobal(name, event['begin'], event['end'], event['pid'])
2369             # add the kprobe based virtual tracefuncs as actual devices
2370             for key in tp.ktemp:
2371                 name, pid = key
2372                 if name not in sysvals.tracefuncs:
2373                     continue
2374                 for e in tp.ktemp[key]:
2375                     kb, ke = e['begin'], e['end']
2376                     if kb == ke or not test.data.isInsideTimeline(kb, ke):
2377                         continue
2378                     test.data.newActionGlobal(e['name'], kb, ke, pid)
2379             # add config base kprobes and dev kprobes
2380             for key in tp.ktemp:
2381                 name, pid = key
2382                 if name in sysvals.tracefuncs:
2383                     continue
2384                 for e in tp.ktemp[key]:
2385                     kb, ke = e['begin'], e['end']
2386                     if kb == ke or not test.data.isInsideTimeline(kb, ke):
2387                         continue
2388                     color = sysvals.kprobeColor(e['name'])
2389                     if name not in sysvals.dev_tracefuncs:
2390                         # config base kprobe
2391                         test.data.newActionGlobal(e['name'], kb, ke, -2, color)
2392                     elif sysvals.usedevsrc:
2393                         # dev kprobe
2394                         data.addDeviceFunctionCall(e['name'], name, e['proc'], pid, kb,
2395                             ke, e['cdata'], e['rdata'])
2396         if sysvals.usecallgraph:
2397             # add the callgraph data to the device hierarchy
2398             sortlist = dict()
2399             for key in test.ftemp:
2400                 proc, pid = key
2401                 for cg in test.ftemp[key]:
2402                     if len(cg.list) < 1 or cg.invalid:
2403                         continue
2404                     if(not cg.postProcess()):
2405                         id = 'task %s' % (pid)
2406                         vprint('Sanity check failed for '+\
2407                             id+', ignoring this callback')
2408                         continue
2409                     # match cg data to devices
2410                     if sysvals.suspendmode == 'command' or not cg.deviceMatch(pid, test.data):
2411                         sortkey = '%f%f%d' % (cg.start, cg.end, pid)
2412                         sortlist[sortkey] = cg
2413             # create blocks for orphan cg data
2414             for sortkey in sorted(sortlist):
2415                 cg = sortlist[sortkey]
2416                 name = cg.list[0].name
2417                 if sysvals.isCallgraphFunc(name):
2418                     vprint('Callgraph found for task %d: %.3fms, %s' % (cg.pid, (cg.end - cg.start)*1000, name))
2419                     cg.newActionFromFunction(test.data)
2420 
2421     if sysvals.suspendmode == 'command':
2422         if(sysvals.verbose):
2423             for data in testdata:
2424                 data.printDetails()
2425         return testdata
2426 
2427     # fill in any missing phases
2428     for data in testdata:
2429         lp = data.phases[0]
2430         for p in data.phases:
2431             if(data.dmesg[p]['start'] < 0 and data.dmesg[p]['end'] < 0):
2432                 print('WARNING: phase "%s" is missing!' % p)
2433             if(data.dmesg[p]['start'] < 0):
2434                 data.dmesg[p]['start'] = data.dmesg[lp]['end']
2435                 if(p == 'resume_machine'):
2436                     data.tSuspended = data.dmesg[lp]['end']
2437                     data.tResumed = data.dmesg[lp]['end']
2438                     data.tLow = 0
2439             if(data.dmesg[p]['end'] < 0):
2440                 data.dmesg[p]['end'] = data.dmesg[p]['start']
2441             lp = p
2442 
2443         if(len(sysvals.devicefilter) > 0):
2444             data.deviceFilter(sysvals.devicefilter)
2445         data.fixupInitcallsThatDidntReturn()
2446         if(sysvals.verbose):
2447             data.printDetails()
2448 
2449     return testdata
2450 
2451 # Function: loadRawKernelLog
2452 # Description:
2453 #    Load a raw kernel log that wasn't created by this tool, it might be
2454 #    possible to extract a valid suspend/resume log
2455 def loadRawKernelLog(dmesgfile):
2456     global sysvals
2457 
2458     stamp = {'time': '', 'host': '', 'mode': 'mem', 'kernel': ''}
2459     stamp['time'] = datetime.now().strftime('%B %d %Y, %I:%M:%S %p')
2460     stamp['host'] = sysvals.hostname
2461 
2462     testruns = []
2463     data = 0
2464     lf = open(dmesgfile, 'r')
2465     for line in lf:
2466         line = line.replace('\r\n', '')
2467         idx = line.find('[')
2468         if idx > 1:
2469             line = line[idx:]
2470         m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line)
2471         if(not m):
2472             continue
2473         msg = m.group("msg")
2474         m = re.match('PM: Syncing filesystems.*', msg)
2475         if(m):
2476             if(data):
2477                 testruns.append(data)
2478             data = Data(len(testruns))
2479             data.stamp = stamp
2480         if(data):
2481             m = re.match('.* *(?P<k>[0-9]\.[0-9]{2}\.[0-9]-.*) .*', msg)
2482             if(m):
2483                 stamp['kernel'] = m.group('k')
2484             m = re.match('PM: Preparing system for (?P<m>.*) sleep', msg)
2485             if(m):
2486                 stamp['mode'] = m.group('m')
2487             data.dmesgtext.append(line)
2488     if(data):
2489         testruns.append(data)
2490         sysvals.stamp = stamp
2491         sysvals.suspendmode = stamp['mode']
2492     lf.close()
2493     return testruns
2494 
2495 # Function: loadKernelLog
2496 # Description:
2497 #    [deprecated for kernel 3.15.0 or newer]
2498 #    load the dmesg file into memory and fix up any ordering issues
2499 #    The dmesg filename is taken from sysvals
2500 # Output:
2501 #    An array of empty Data objects with only their dmesgtext attributes set
2502 def loadKernelLog():
2503     global sysvals
2504 
2505     vprint('Analyzing the dmesg data...')
2506     if(os.path.exists(sysvals.dmesgfile) == False):
2507         doError('%s does not exist' % sysvals.dmesgfile, False)
2508 
2509     # there can be multiple test runs in a single file
2510     tp = TestProps()
2511     testruns = []
2512     data = 0
2513     lf = open(sysvals.dmesgfile, 'r')
2514     for line in lf:
2515         line = line.replace('\r\n', '')
2516         idx = line.find('[')
2517         if idx > 1:
2518             line = line[idx:]
2519         m = re.match(sysvals.stampfmt, line)
2520         if(m):
2521             tp.stamp = line
2522             continue
2523         m = re.match(sysvals.firmwarefmt, line)
2524         if(m):
2525             tp.fwdata.append((int(m.group('s')), int(m.group('r'))))
2526             continue
2527         m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line)
2528         if(not m):
2529             continue
2530         msg = m.group("msg")
2531         if(re.match('PM: Syncing filesystems.*', msg)):
2532             if(data):
2533                 testruns.append(data)
2534             data = Data(len(testruns))
2535             parseStamp(tp.stamp, data)
2536             if len(tp.fwdata) > data.testnumber:
2537                 data.fwSuspend, data.fwResume = tp.fwdata[data.testnumber]
2538                 if(data.fwSuspend > 0 or data.fwResume > 0):
2539                     data.fwValid = True
2540         if(re.match('ACPI: resume from mwait', msg)):
2541             print('NOTE: This suspend appears to be freeze rather than'+\
2542                 ' %s, it will be treated as such' % sysvals.suspendmode)
2543             sysvals.suspendmode = 'freeze'
2544         if(not data):
2545             continue
2546         data.dmesgtext.append(line)
2547     if(data):
2548         testruns.append(data)
2549     lf.close()
2550 
2551     if(len(testruns) < 1):
2552         # bad log, but see if you can extract something meaningful anyway
2553         testruns = loadRawKernelLog(sysvals.dmesgfile)
2554 
2555     if(len(testruns) < 1):
2556         doError(' dmesg log is completely unreadable: %s' \
2557             % sysvals.dmesgfile, False)
2558 
2559     # fix lines with same timestamp/function with the call and return swapped
2560     for data in testruns:
2561         last = ''
2562         for line in data.dmesgtext:
2563             mc = re.match('.*(\[ *)(?P<t>[0-9\.]*)(\]) calling  '+\
2564                 '(?P<f>.*)\+ @ .*, parent: .*', line)
2565             mr = re.match('.*(\[ *)(?P<t>[0-9\.]*)(\]) call '+\
2566                 '(?P<f>.*)\+ returned .* after (?P<dt>.*) usecs', last)
2567             if(mc and mr and (mc.group('t') == mr.group('t')) and
2568                 (mc.group('f') == mr.group('f'))):
2569                 i = data.dmesgtext.index(last)
2570                 j = data.dmesgtext.index(line)
2571                 data.dmesgtext[i] = line
2572                 data.dmesgtext[j] = last
2573             last = line
2574     return testruns
2575 
2576 # Function: parseKernelLog
2577 # Description:
2578 #    [deprecated for kernel 3.15.0 or newer]
2579 #    Analyse a dmesg log output file generated from this app during
2580 #    the execution phase. Create a set of device structures in memory
2581 #    for subsequent formatting in the html output file
2582 #    This call is only for legacy support on kernels where the ftrace
2583 #    data lacks the suspend_resume or device_pm_callbacks trace events.
2584 # Arguments:
2585 #    data: an empty Data object (with dmesgtext) obtained from loadKernelLog
2586 # Output:
2587 #    The filled Data object
2588 def parseKernelLog(data):
2589     global sysvals
2590 
2591     phase = 'suspend_runtime'
2592 
2593     if(data.fwValid):
2594         vprint('Firmware Suspend = %u ns, Firmware Resume = %u ns' % \
2595             (data.fwSuspend, data.fwResume))
2596 
2597     # dmesg phase match table
2598     dm = {
2599         'suspend_prepare': 'PM: Syncing filesystems.*',
2600                 'suspend': 'PM: Entering [a-z]* sleep.*',
2601            'suspend_late': 'PM: suspend of devices complete after.*',
2602           'suspend_noirq': 'PM: late suspend of devices complete after.*',
2603         'suspend_machine': 'PM: noirq suspend of devices complete after.*',
2604          'resume_machine': 'ACPI: Low-level resume complete.*',
2605            'resume_noirq': 'ACPI: Waking up from system sleep state.*',
2606            'resume_early': 'PM: noirq resume of devices complete after.*',
2607                  'resume': 'PM: early resume of devices complete after.*',
2608         'resume_complete': 'PM: resume of devices complete after.*',
2609             'post_resume': '.*Restarting tasks \.\.\..*',
2610     }
2611     if(sysvals.suspendmode == 'standby'):
2612         dm['resume_machine'] = 'PM: Restoring platform NVS memory'
2613     elif(sysvals.suspendmode == 'disk'):
2614         dm['suspend_late'] = 'PM: freeze of devices complete after.*'
2615         dm['suspend_noirq'] = 'PM: late freeze of devices complete after.*'
2616         dm['suspend_machine'] = 'PM: noirq freeze of devices complete after.*'
2617         dm['resume_machine'] = 'PM: Restoring platform NVS memory'
2618         dm['resume_early'] = 'PM: noirq restore of devices complete after.*'
2619         dm['resume'] = 'PM: early restore of devices complete after.*'
2620         dm['resume_complete'] = 'PM: restore of devices complete after.*'
2621     elif(sysvals.suspendmode == 'freeze'):
2622         dm['resume_machine'] = 'ACPI: resume from mwait'
2623 
2624     # action table (expected events that occur and show up in dmesg)
2625     at = {
2626         'sync_filesystems': {
2627             'smsg': 'PM: Syncing filesystems.*',
2628             'emsg': 'PM: Preparing system for mem sleep.*' },
2629         'freeze_user_processes': {
2630             'smsg': 'Freezing user space processes .*',
2631             'emsg': 'Freezing remaining freezable tasks.*' },
2632         'freeze_tasks': {
2633             'smsg': 'Freezing remaining freezable tasks.*',
2634             'emsg': 'PM: Entering (?P<mode>[a-z,A-Z]*) sleep.*' },
2635         'ACPI prepare': {
2636             'smsg': 'ACPI: Preparing to enter system sleep state.*',
2637             'emsg': 'PM: Saving platform NVS memory.*' },
2638         'PM vns': {
2639             'smsg': 'PM: Saving platform NVS memory.*',
2640             'emsg': 'Disabling non-boot CPUs .*' },
2641     }
2642 
2643     t0 = -1.0
2644     cpu_start = -1.0
2645     prevktime = -1.0
2646     actions = dict()
2647     for line in data.dmesgtext:
2648         # -- preprocessing --
2649         # parse each dmesg line into the time and message
2650         m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line)
2651         if(m):
2652             val = m.group('ktime')
2653             try:
2654                 ktime = float(val)
2655             except:
2656                 doWarning('INVALID DMESG LINE: '+\
2657                     line.replace('\n', ''), 'dmesg')
2658                 continue
2659             msg = m.group('msg')
2660             # initialize data start to first line time
2661             if t0 < 0:
2662                 data.setStart(ktime)
2663                 t0 = ktime
2664         else:
2665             continue
2666 
2667         # hack for determining resume_machine end for freeze
2668         if(not sysvals.usetraceevents and sysvals.suspendmode == 'freeze' \
2669             and phase == 'resume_machine' and \
2670             re.match('calling  (?P<f>.*)\+ @ .*, parent: .*', msg)):
2671             data.dmesg['resume_machine']['end'] = ktime
2672             phase = 'resume_noirq'
2673             data.dmesg[phase]['start'] = ktime
2674 
2675         # -- phase changes --
2676         # suspend start
2677         if(re.match(dm['suspend_prepare'], msg)):
2678             phase = 'suspend_prepare'
2679             data.dmesg[phase]['start'] = ktime
2680             data.setStart(ktime)
2681         # suspend start
2682         elif(re.match(dm['suspend'], msg)):
2683             data.dmesg['suspend_prepare']['end'] = ktime
2684             phase = 'suspend'
2685             data.dmesg[phase]['start'] = ktime
2686         # suspend_late start
2687         elif(re.match(dm['suspend_late'], msg)):
2688             data.dmesg['suspend']['end'] = ktime
2689             phase = 'suspend_late'
2690             data.dmesg[phase]['start'] = ktime
2691         # suspend_noirq start
2692         elif(re.match(dm['suspend_noirq'], msg)):
2693             data.dmesg['suspend_late']['end'] = ktime
2694             phase = 'suspend_noirq'
2695             data.dmesg[phase]['start'] = ktime
2696         # suspend_machine start
2697         elif(re.match(dm['suspend_machine'], msg)):
2698             data.dmesg['suspend_noirq']['end'] = ktime
2699             phase = 'suspend_machine'
2700             data.dmesg[phase]['start'] = ktime
2701         # resume_machine start
2702         elif(re.match(dm['resume_machine'], msg)):
2703             if(sysvals.suspendmode in ['freeze', 'standby']):
2704                 data.tSuspended = prevktime
2705                 data.dmesg['suspend_machine']['end'] = prevktime
2706             else:
2707                 data.tSuspended = ktime
2708                 data.dmesg['suspend_machine']['end'] = ktime
2709             phase = 'resume_machine'
2710             data.tResumed = ktime
2711             data.tLow = data.tResumed - data.tSuspended
2712             data.dmesg[phase]['start'] = ktime
2713         # resume_noirq start
2714         elif(re.match(dm['resume_noirq'], msg)):
2715             data.dmesg['resume_machine']['end'] = ktime
2716             phase = 'resume_noirq'
2717             data.dmesg[phase]['start'] = ktime
2718         # resume_early start
2719         elif(re.match(dm['resume_early'], msg)):
2720             data.dmesg['resume_noirq']['end'] = ktime
2721             phase = 'resume_early'
2722             data.dmesg[phase]['start'] = ktime
2723         # resume start
2724         elif(re.match(dm['resume'], msg)):
2725             data.dmesg['resume_early']['end'] = ktime
2726             phase = 'resume'
2727             data.dmesg[phase]['start'] = ktime
2728         # resume complete start
2729         elif(re.match(dm['resume_complete'], msg)):
2730             data.dmesg['resume']['end'] = ktime
2731             phase = 'resume_complete'
2732             data.dmesg[phase]['start'] = ktime
2733         # post resume start
2734         elif(re.match(dm['post_resume'], msg)):
2735             data.dmesg['resume_complete']['end'] = ktime
2736             data.setEnd(ktime)
2737             phase = 'post_resume'
2738             break
2739 
2740         # -- device callbacks --
2741         if(phase in data.phases):
2742             # device init call
2743             if(re.match('calling  (?P<f>.*)\+ @ .*, parent: .*', msg)):
2744                 sm = re.match('calling  (?P<f>.*)\+ @ '+\
2745                     '(?P<n>.*), parent: (?P<p>.*)', msg);
2746                 f = sm.group('f')
2747                 n = sm.group('n')
2748                 p = sm.group('p')
2749                 if(f and n and p):
2750                     data.newAction(phase, f, int(n), p, ktime, -1, '')
2751             # device init return
2752             elif(re.match('call (?P<f>.*)\+ returned .* after '+\
2753                 '(?P<t>.*) usecs', msg)):
2754                 sm = re.match('call (?P<f>.*)\+ returned .* after '+\
2755                     '(?P<t>.*) usecs(?P<a>.*)', msg);
2756                 f = sm.group('f')
2757                 t = sm.group('t')
2758                 list = data.dmesg[phase]['list']
2759                 if(f in list):
2760                     dev = list[f]
2761                     dev['length'] = int(t)
2762                     dev['end'] = ktime
2763 
2764         # -- non-devicecallback actions --
2765         # if trace events are not available, these are better than nothing
2766         if(not sysvals.usetraceevents):
2767             # look for known actions
2768             for a in at:
2769                 if(re.match(at[a]['smsg'], msg)):
2770                     if(a not in actions):
2771                         actions[a] = []
2772                     actions[a].append({'begin': ktime, 'end': ktime})
2773                 if(re.match(at[a]['emsg'], msg)):
2774                     if(a in actions):
2775                         actions[a][-1]['end'] = ktime
2776             # now look for CPU on/off events
2777             if(re.match('Disabling non-boot CPUs .*', msg)):
2778                 # start of first cpu suspend
2779                 cpu_start = ktime
2780             elif(re.match('Enabling non-boot CPUs .*', msg)):
2781                 # start of first cpu resume
2782                 cpu_start = ktime
2783             elif(re.match('smpboot: CPU (?P<cpu>[0-9]*) is now offline', msg)):
2784                 # end of a cpu suspend, start of the next
2785                 m = re.match('smpboot: CPU (?P<cpu>[0-9]*) is now offline', msg)
2786                 cpu = 'CPU'+m.group('cpu')
2787                 if(cpu not in actions):
2788                     actions[cpu] = []
2789                 actions[cpu].append({'begin': cpu_start, 'end': ktime})
2790                 cpu_start = ktime
2791             elif(re.match('CPU(?P<cpu>[0-9]*) is up', msg)):
2792                 # end of a cpu resume, start of the next
2793                 m = re.match('CPU(?P<cpu>[0-9]*) is up', msg)
2794                 cpu = 'CPU'+m.group('cpu')
2795                 if(cpu not in actions):
2796                     actions[cpu] = []
2797                 actions[cpu].append({'begin': cpu_start, 'end': ktime})
2798                 cpu_start = ktime
2799         prevktime = ktime
2800 
2801     # fill in any missing phases
2802     lp = data.phases[0]
2803     for p in data.phases:
2804         if(data.dmesg[p]['start'] < 0 and data.dmesg[p]['end'] < 0):
2805             print('WARNING: phase "%s" is missing, something went wrong!' % p)
2806             print('    In %s, this dmesg line denotes the start of %s:' % \
2807                 (sysvals.suspendmode, p))
2808             print('        "%s"' % dm[p])
2809         if(data.dmesg[p]['start'] < 0):
2810             data.dmesg[p]['start'] = data.dmesg[lp]['end']
2811             if(p == 'resume_machine'):
2812                 data.tSuspended = data.dmesg[lp]['end']
2813                 data.tResumed = data.dmesg[lp]['end']
2814                 data.tLow = 0
2815         if(data.dmesg[p]['end'] < 0):
2816             data.dmesg[p]['end'] = data.dmesg[p]['start']
2817         lp = p
2818 
2819     # fill in any actions we've found
2820     for name in actions:
2821         for event in actions[name]:
2822             data.newActionGlobal(name, event['begin'], event['end'])
2823 
2824     if(sysvals.verbose):
2825         data.printDetails()
2826     if(len(sysvals.devicefilter) > 0):
2827         data.deviceFilter(sysvals.devicefilter)
2828     data.fixupInitcallsThatDidntReturn()
2829     return True
2830 
2831 # Function: createHTMLSummarySimple
2832 # Description:
2833 #    Create summary html file for a series of tests
2834 # Arguments:
2835 #    testruns: array of Data objects from parseTraceLog
2836 def createHTMLSummarySimple(testruns, htmlfile):
2837     global sysvals
2838 
2839     # print out the basic summary of all the tests
2840     hf = open(htmlfile, 'w')
2841 
2842     # write the html header first (html head, css code, up to body start)
2843     html = '<!DOCTYPE html>\n<html>\n<head>\n\
2844     <meta http-equiv="content-type" content="text/html; charset=UTF-8">\n\
2845     <title>AnalyzeSuspend Summary</title>\n\
2846     <style type=\'text/css\'>\n\
2847         body {overflow-y: scroll;}\n\
2848         .stamp {width: 100%;text-align:center;background-color:#495E09;line-height:30px;color:white;font: 25px Arial;}\n\
2849         table {width:100%;border-collapse: collapse;}\n\
2850         .summary {font: 22px Arial;border:1px solid;}\n\
2851         th {border: 1px solid black;background-color:#A7C942;color:white;}\n\
2852         td {text-align: center;}\n\
2853         tr.alt td {background-color:#EAF2D3;}\n\
2854         tr.avg td {background-color:#BDE34C;}\n\
2855         a:link {color: #90B521;}\n\
2856         a:visited {color: #495E09;}\n\
2857         a:hover {color: #B1DF28;}\n\
2858         a:active {color: #FFFFFF;}\n\
2859     </style>\n</head>\n<body>\n'
2860 
2861     # group test header
2862     count = len(testruns)
2863     headline_stamp = '<div class="stamp">{0} {1} {2} {3} ({4} tests)</div>\n'
2864     html += headline_stamp.format(sysvals.stamp['host'],
2865         sysvals.stamp['kernel'], sysvals.stamp['mode'],
2866         sysvals.stamp['time'], count)
2867 
2868     # check to see if all the tests have the same value
2869     stampcolumns = False
2870     for data in testruns:
2871         if diffStamp(sysvals.stamp, data.stamp):
2872             stampcolumns = True
2873             break
2874 
2875     th = '\t<th>{0}</th>\n'
2876     td = '\t<td>{0}</td>\n'
2877     tdlink = '\t<td><a href="{0}">Click Here</a></td>\n'
2878 
2879     # table header
2880     html += '<table class="summary">\n<tr>\n'
2881     html += th.format("Test #")
2882     if stampcolumns:
2883         html += th.format("Hostname")
2884         html += th.format("Kernel Version")
2885         html += th.format("Suspend Mode")
2886     html += th.format("Test Time")
2887     html += th.format("Suspend Time")
2888     html += th.format("Resume Time")
2889     html += th.format("Detail")
2890     html += '</tr>\n'
2891 
2892     # test data, 1 row per test
2893     sTimeAvg = 0.0
2894     rTimeAvg = 0.0
2895     num = 1
2896     for data in testruns:
2897         # data.end is the end of post_resume
2898         resumeEnd = data.dmesg['resume_complete']['end']
2899         if num % 2 == 1:
2900             html += '<tr class="alt">\n'
2901         else:
2902             html += '<tr>\n'
2903 
2904         # test num
2905         html += td.format("test %d" % num)
2906         num += 1
2907         if stampcolumns:
2908             # host name
2909             val = "unknown"
2910             if('host' in data.stamp):
2911                 val = data.stamp['host']
2912             html += td.format(val)
2913             # host kernel
2914             val = "unknown"
2915             if('kernel' in data.stamp):
2916                 val = data.stamp['kernel']
2917             html += td.format(val)
2918             # suspend mode
2919             val = "unknown"
2920             if('mode' in data.stamp):
2921                 val = data.stamp['mode']
2922             html += td.format(val)
2923         # test time
2924         val = "unknown"
2925         if('time' in data.stamp):
2926             val = data.stamp['time']
2927         html += td.format(val)
2928         # suspend time
2929         sTime = (data.tSuspended - data.start)*1000
2930         sTimeAvg += sTime
2931         html += td.format("%3.3f ms" % sTime)
2932         # resume time
2933         rTime = (resumeEnd - data.tResumed)*1000
2934         rTimeAvg += rTime
2935         html += td.format("%3.3f ms" % rTime)
2936         # link to the output html
2937         html += tdlink.format(data.outfile)
2938 
2939         html += '</tr>\n'
2940 
2941     # last line: test average
2942     if(count > 0):
2943         sTimeAvg /= count
2944         rTimeAvg /= count
2945     html += '<tr class="avg">\n'
2946     html += td.format('Average')    # name
2947     if stampcolumns:
2948         html += td.format('')           # host
2949         html += td.format('')           # kernel
2950         html += td.format('')           # mode
2951     html += td.format('')           # time
2952     html += td.format("%3.3f ms" % sTimeAvg)    # suspend time
2953     html += td.format("%3.3f ms" % rTimeAvg)    # resume time
2954     html += td.format('')           # output link
2955     html += '</tr>\n'
2956 
2957     # flush the data to file
2958     hf.write(html+'</table>\n')
2959     hf.write('</body>\n</html>\n')
2960     hf.close()
2961 
2962 def htmlTitle():
2963     global sysvals
2964     modename = {
2965         'freeze': 'Freeze (S0)',
2966         'standby': 'Standby (S1)',
2967         'mem': 'Suspend (S3)',
2968         'disk': 'Hibernate (S4)'
2969     }
2970     kernel = sysvals.stamp['kernel']
2971     host = sysvals.hostname[0].upper()+sysvals.hostname[1:]
2972     mode = sysvals.suspendmode
2973     if sysvals.suspendmode in modename:
2974         mode = modename[sysvals.suspendmode]
2975     return host+' '+mode+' '+kernel
2976 
2977 def ordinal(value):
2978     suffix = 'th'
2979     if value < 10 or value > 19:
2980         if value % 10 == 1:
2981             suffix = 'st'
2982         elif value % 10 == 2:
2983             suffix = 'nd'
2984         elif value % 10 == 3:
2985             suffix = 'rd'
2986     return '%d%s' % (value, suffix)
2987 
2988 # Function: createHTML
2989 # Description:
2990 #    Create the output html file from the resident test data
2991 # Arguments:
2992 #    testruns: array of Data objects from parseKernelLog or parseTraceLog
2993 # Output:
2994 #    True if the html file was created, false if it failed
2995 def createHTML(testruns):
2996     global sysvals
2997 
2998     if len(testruns) < 1:
2999         print('ERROR: Not enough test data to build a timeline')
3000         return
3001 
3002     for data in testruns:
3003         data.normalizeTime(testruns[-1].tSuspended)
3004 
3005     x2changes = ['', 'absolute']
3006     if len(testruns) > 1:
3007         x2changes = ['1', 'relative']
3008     # html function templates
3009     headline_version = '<div class="version"><a href="https://01.org/suspendresume">AnalyzeSuspend v%s</a></div>' % sysvals.version
3010     headline_stamp = '<div class="stamp">{0} {1} {2} {3}</div>\n'
3011     html_devlist1 = '<button id="devlist1" class="devlist" style="float:left;">Device Detail%s</button>' % x2changes[0]
3012     html_zoombox = '<center><button id="zoomin">ZOOM IN</button><button id="zoomout">ZOOM OUT</button><button id="zoomdef">ZOOM 1:1</button></center>\n'
3013     html_devlist2 = '<button id="devlist2" class="devlist" style="float:right;">Device Detail2</button>\n'
3014     html_timeline = '<div id="dmesgzoombox" class="zoombox">\n<div id="{0}" class="timeline" style="height:{1}px">\n'
3015     html_tblock = '<div id="block{0}" class="tblock" style="left:{1}%;width:{2}%;">\n'
3016     html_device = '<div id="{0}" title="{1}" class="thread{7}" style="left:{2}%;top:{3}px;height:{4}px;width:{5}%;{8}">{6}</div>\n'
3017     html_traceevent = '<div title="{0}" class="traceevent" style="left:{1}%;top:{2}px;height:{3}px;width:{4}%;line-height:{3}px;">{5}</div>\n'
3018     html_phase = '<div class="phase" style="left:{0}%;width:{1}%;top:{2}px;height:{3}px;background-color:{4}">{5}</div>\n'
3019     html_phaselet = '<div id="{0}" class="phaselet" style="left:{1}%;width:{2}%;background-color:{3}"></div>\n'
3020     html_legend = '<div id="p{3}" class="square" style="left:{0}%;background-color:{1}">&nbsp;{2}</div>\n'
3021     html_timetotal = '<table class="time1">\n<tr>'\
3022         '<td class="green">{2} Suspend Time: <b>{0} ms</b></td>'\
3023         '<td class="yellow">{2} Resume Time: <b>{1} ms</b></td>'\
3024         '</tr>\n</table>\n'
3025     html_timetotal2 = '<table class="time1">\n<tr>'\
3026         '<td class="green">{3} Suspend Time: <b>{0} ms</b></td>'\
3027         '<td class="gray">'+sysvals.suspendmode+' time: <b>{1} ms</b></td>'\
3028         '<td class="yellow">{3} Resume Time: <b>{2} ms</b></td>'\
3029         '</tr>\n</table>\n'
3030     html_timetotal3 = '<table class="time1">\n<tr>'\
3031         '<td class="green">Execution Time: <b>{0} ms</b></td>'\
3032         '<td class="yellow">Command: <b>{1}</b></td>'\
3033         '</tr>\n</table>\n'
3034     html_timegroups = '<table class="time2">\n<tr>'\
3035         '<td class="green">{4}Kernel Suspend: {0} ms</td>'\
3036         '<td class="purple">{4}Firmware Suspend: {1} ms</td>'\
3037         '<td class="purple">{4}Firmware Resume: {2} ms</td>'\
3038         '<td class="yellow">{4}Kernel Resume: {3} ms</td>'\
3039         '</tr>\n</table>\n'
3040 
3041     # html format variables
3042     rowheight = 30
3043     devtextS = '14px'
3044     devtextH = '30px'
3045     hoverZ = 'z-index:10;'
3046 
3047     if sysvals.usedevsrc:
3048         hoverZ = ''
3049 
3050     # device timeline
3051     vprint('Creating Device Timeline...')
3052 
3053     devtl = Timeline(rowheight)
3054 
3055     # Generate the header for this timeline
3056     for data in testruns:
3057         tTotal = data.end - data.start
3058         tEnd = data.dmesg['resume_complete']['end']
3059         if(tTotal == 0):
3060             print('ERROR: No timeline data')
3061             sys.exit()
3062         if(data.tLow > 0):
3063             low_time = '%.0f'%(data.tLow*1000)
3064         if sysvals.suspendmode == 'command':
3065             run_time = '%.0f'%((data.end-data.start)*1000)
3066             if sysvals.testcommand:
3067                 testdesc = sysvals.testcommand
3068             else:
3069                 testdesc = 'unknown'
3070             if(len(testruns) > 1):
3071                 testdesc = ordinal(data.testnumber+1)+' '+testdesc
3072             thtml = html_timetotal3.format(run_time, testdesc)
3073             devtl.html['header'] += thtml
3074         elif data.fwValid:
3075             suspend_time = '%.0f'%((data.tSuspended-data.start)*1000 + \
3076                 (data.fwSuspend/1000000.0))
3077             resume_time = '%.0f'%((tEnd-data.tSuspended)*1000 + \
3078                 (data.fwResume/1000000.0))
3079             testdesc1 = 'Total'
3080             testdesc2 = ''
3081             if(len(testruns) > 1):
3082                 testdesc1 = testdesc2 = ordinal(data.testnumber+1)
3083                 testdesc2 += ' '
3084             if(data.tLow == 0):
3085                 thtml = html_timetotal.format(suspend_time, \
3086                     resume_time, testdesc1)
3087             else:
3088                 thtml = html_timetotal2.format(suspend_time, low_time, \
3089                     resume_time, testdesc1)
3090             devtl.html['header'] += thtml
3091             sktime = '%.3f'%((data.dmesg['suspend_machine']['end'] - \
3092                 data.getStart())*1000)
3093             sftime = '%.3f'%(data.fwSuspend / 1000000.0)
3094             rftime = '%.3f'%(data.fwResume / 1000000.0)
3095             rktime = '%.3f'%((data.dmesg['resume_complete']['end'] - \
3096                 data.dmesg['resume_machine']['start'])*1000)
3097             devtl.html['header'] += html_timegroups.format(sktime, \
3098                 sftime, rftime, rktime, testdesc2)
3099         else:
3100             suspend_time = '%.0f'%((data.tSuspended-data.start)*1000)
3101             resume_time = '%.0f'%((tEnd-data.tSuspended)*1000)
3102             testdesc = 'Kernel'
3103             if(len(testruns) > 1):
3104                 testdesc = ordinal(data.testnumber+1)+' '+testdesc
3105             if(data.tLow == 0):
3106                 thtml = html_timetotal.format(suspend_time, \
3107                     resume_time, testdesc)
3108             else:
3109                 thtml = html_timetotal2.format(suspend_time, low_time, \
3110                     resume_time, testdesc)
3111             devtl.html['header'] += thtml
3112 
3113     # time scale for potentially multiple datasets
3114     t0 = testruns[0].start
3115     tMax = testruns[-1].end
3116     tSuspended = testruns[-1].tSuspended
3117     tTotal = tMax - t0
3118 
3119     # determine the maximum number of rows we need to draw
3120     for data in testruns:
3121         data.selectTimelineDevices('%f', tTotal, sysvals.mindevlen)
3122         for group in data.devicegroups:
3123             devlist = []
3124             for phase in group:
3125                 for devname in data.tdevlist[phase]:
3126                     devlist.append((phase,devname))
3127             devtl.getPhaseRows(data.dmesg, devlist)
3128     devtl.calcTotalRows()
3129 
3130     # create bounding box, add buttons
3131     if sysvals.suspendmode != 'command':
3132         devtl.html['timeline'] += html_devlist1
3133         if len(testruns) > 1:
3134             devtl.html['timeline'] += html_devlist2
3135     devtl.html['timeline'] += html_zoombox
3136     devtl.html['timeline'] += html_timeline.format('dmesg', devtl.height)
3137 
3138     # draw the full timeline
3139     phases = {'suspend':[],'resume':[]}
3140     for phase in data.dmesg:
3141         if 'resume' in phase:
3142             phases['resume'].append(phase)
3143         else:
3144             phases['suspend'].append(phase)
3145 
3146     # draw each test run chronologically
3147     for data in testruns:
3148         # if nore than one test, draw a block to represent user mode
3149         if(data.testnumber > 0):
3150             m0 = testruns[data.testnumber-1].end
3151             mMax = testruns[data.testnumber].start
3152             mTotal = mMax - m0
3153             name = 'usermode%d' % data.testnumber
3154             top = '%d' % devtl.scaleH
3155             left = '%f' % (((m0-t0)*100.0)/tTotal)
3156             width = '%f' % ((mTotal*100.0)/tTotal)
3157             title = 'user mode (%0.3f ms) ' % (mTotal*1000)
3158             devtl.html['timeline'] += html_device.format(name, \
3159                 title, left, top, '%d'%devtl.bodyH, width, '', '', '')
3160         # now draw the actual timeline blocks
3161         for dir in phases:
3162             # draw suspend and resume blocks separately
3163             bname = '%s%d' % (dir[0], data.testnumber)
3164             if dir == 'suspend':
3165                 m0 = testruns[data.testnumber].start
3166                 mMax = testruns[data.testnumber].tSuspended
3167                 mTotal = mMax - m0
3168                 left = '%f' % (((m0-t0)*100.0)/tTotal)
3169             else:
3170                 m0 = testruns[data.testnumber].tSuspended
3171                 mMax = testruns[data.testnumber].end
3172                 mTotal = mMax - m0
3173                 left = '%f' % ((((m0-t0)*100.0)+sysvals.srgap/2)/tTotal)
3174             # if a timeline block is 0 length, skip altogether
3175             if mTotal == 0:
3176                 continue
3177             width = '%f' % (((mTotal*100.0)-sysvals.srgap/2)/tTotal)
3178             devtl.html['timeline'] += html_tblock.format(bname, left, width)
3179             for b in sorted(phases[dir]):
3180                 # draw the phase color background
3181                 phase = data.dmesg[b]
3182                 length = phase['end']-phase['start']
3183                 left = '%f' % (((phase['start']-m0)*100.0)/mTotal)
3184                 width = '%f' % ((length*100.0)/mTotal)
3185                 devtl.html['timeline'] += html_phase.format(left, width, \
3186                     '%.3f'%devtl.scaleH, '%.3f'%devtl.bodyH, \
3187                     data.dmesg[b]['color'], '')
3188                 # draw the devices for this phase
3189                 phaselist = data.dmesg[b]['list']
3190                 for d in data.tdevlist[b]:
3191                     name = d
3192                     drv = ''
3193                     dev = phaselist[d]
3194                     xtraclass = ''
3195                     xtrainfo = ''
3196                     xtrastyle = ''
3197                     if 'htmlclass' in dev:
3198                         xtraclass = dev['htmlclass']
3199                         xtrainfo = dev['htmlclass']
3200                     if 'color' in dev:
3201                         xtrastyle = 'background-color:%s;' % dev['color']
3202                     if(d in sysvals.devprops):
3203                         name = sysvals.devprops[d].altName(d)
3204                         xtraclass = sysvals.devprops[d].xtraClass()
3205                         xtrainfo = sysvals.devprops[d].xtraInfo()
3206                     if('drv' in dev and dev['drv']):
3207                         drv = ' {%s}' % dev['drv']
3208                     rowheight = devtl.phaseRowHeight(b, dev['row'])
3209                     rowtop = devtl.phaseRowTop(b, dev['row'])
3210                     top = '%.3f' % (rowtop + devtl.scaleH)
3211                     left = '%f' % (((dev['start']-m0)*100)/mTotal)
3212                     width = '%f' % (((dev['end']-dev['start'])*100)/mTotal)
3213                     length = ' (%0.3f ms) ' % ((dev['end']-dev['start'])*1000)
3214                     if sysvals.suspendmode == 'command':
3215                         title = name+drv+xtrainfo+length+'cmdexec'
3216                     else:
3217                         title = name+drv+xtrainfo+length+b
3218                     devtl.html['timeline'] += html_device.format(dev['id'], \
3219                         title, left, top, '%.3f'%rowheight, width, \
3220                         d+drv, xtraclass, xtrastyle)
3221                     if('src' not in dev):
3222                         continue
3223                     # draw any trace events for this device
3224                     vprint('Debug trace events found for device %s' % d)
3225                     vprint('%20s %20s %10s %8s' % ('title', \
3226                         'name', 'time(ms)', 'length(ms)'))
3227                     for e in dev['src']:
3228                         vprint('%20s %20s %10.3f %8.3f' % (e.title, \
3229                             e.text, e.time*1000, e.length*1000))
3230                         height = devtl.rowH
3231                         top = '%.3f' % (rowtop + devtl.scaleH + (e.row*devtl.rowH))
3232                         left = '%f' % (((e.time-m0)*100)/mTotal)
3233                         width = '%f' % (e.length*100/mTotal)
3234                         color = 'rgba(204,204,204,0.5)'
3235                         devtl.html['timeline'] += \
3236                             html_traceevent.format(e.title, \
3237                                 left, top, '%.3f'%height, \
3238                                 width, e.text)
3239             # draw the time scale, try to make the number of labels readable
3240             devtl.html['timeline'] += devtl.createTimeScale(m0, mMax, tTotal, dir)
3241             devtl.html['timeline'] += '</div>\n'
3242 
3243     # timeline is finished
3244     devtl.html['timeline'] += '</div>\n</div>\n'
3245 
3246     # draw a legend which describes the phases by color
3247     if sysvals.suspendmode != 'command':
3248         data = testruns[-1]
3249         devtl.html['legend'] = '<div class="legend">\n'
3250         pdelta = 100.0/len(data.phases)
3251         pmargin = pdelta / 4.0
3252         for phase in data.phases:
3253             tmp = phase.split('_')
3254             id = tmp[0][0]
3255             if(len(tmp) > 1):
3256                 id += tmp[1][0]
3257             order = '%.2f' % ((data.dmesg[phase]['order'] * pdelta) + pmargin)
3258             name = string.replace(phase, '_', ' &nbsp;')
3259             devtl.html['legend'] += html_legend.format(order, \
3260                 data.dmesg[phase]['color'], name, id)
3261         devtl.html['legend'] += '</div>\n'
3262 
3263     hf = open(sysvals.htmlfile, 'w')
3264 
3265     if not sysvals.cgexp:
3266         cgchk = 'checked'
3267         cgnchk = 'not(:checked)'
3268     else:
3269         cgchk = 'not(:checked)'
3270         cgnchk = 'checked'
3271 
3272     # write the html header first (html head, css code, up to body start)
3273     html_header = '<!DOCTYPE html>\n<html>\n<head>\n\
3274     <meta http-equiv="content-type" content="text/html; charset=UTF-8">\n\
3275     <title>'+htmlTitle()+'</title>\n\
3276     <style type=\'text/css\'>\n\
3277         body {overflow-y:scroll;}\n\
3278         .stamp {width:100%;text-align:center;background-color:gray;line-height:30px;color:white;font:25px Arial;}\n\
3279         .callgraph {margin-top:30px;box-shadow:5px 5px 20px black;}\n\
3280         .callgraph article * {padding-left:28px;}\n\
3281         h1 {color:black;font:bold 30px Times;}\n\
3282         t0 {color:black;font:bold 30px Times;}\n\
3283         t1 {color:black;font:30px Times;}\n\
3284         t2 {color:black;font:25px Times;}\n\
3285         t3 {color:black;font:20px Times;white-space:nowrap;}\n\
3286         t4 {color:black;font:bold 30px Times;line-height:60px;white-space:nowrap;}\n\
3287         cS {color:blue;font:bold 11px Times;}\n\
3288         cR {color:red;font:bold 11px Times;}\n\
3289         table {width:100%;}\n\
3290         .gray {background-color:rgba(80,80,80,0.1);}\n\
3291         .green {background-color:rgba(204,255,204,0.4);}\n\
3292         .purple {background-color:rgba(128,0,128,0.2);}\n\
3293         .yellow {background-color:rgba(255,255,204,0.4);}\n\
3294         .time1 {font:22px Arial;border:1px solid;}\n\
3295         .time2 {font:15px Arial;border-bottom:1px solid;border-left:1px solid;border-right:1px solid;}\n\
3296         td {text-align:center;}\n\
3297         r {color:#500000;font:15px Tahoma;}\n\
3298         n {color:#505050;font:15px Tahoma;}\n\
3299         .tdhl {color:red;}\n\
3300         .hide {display:none;}\n\
3301         .pf {display:none;}\n\
3302         .pf:'+cgchk+' + label {background:url(\'data:image/svg+xml;utf,<?xml version="1.0" standalone="no"?><svg xmlns="http://www.w3.org/2000/svg" height="18" width="18" version="1.1"><circle cx="9" cy="9" r="8" stroke="black" stroke-width="1" fill="white"/><rect x="4" y="8" width="10" height="2" style="fill:black;stroke-width:0"/><rect x="8" y="4" width="2" height="10" style="fill:black;stroke-width:0"/></svg>\') no-repeat left center;}\n\
3303         .pf:'+cgnchk+' ~ label {background:url(\'data:image/svg+xml;utf,<?xml version="1.0" standalone="no"?><svg xmlns="http://www.w3.org/2000/svg" height="18" width="18" version="1.1"><circle cx="9" cy="9" r="8" stroke="black" stroke-width="1" fill="white"/><rect x="4" y="8" width="10" height="2" style="fill:black;stroke-width:0"/></svg>\') no-repeat left center;}\n\
3304         .pf:'+cgchk+' ~ *:not(:nth-child(2)) {display:none;}\n\
3305         .zoombox {position:relative;width:100%;overflow-x:scroll;}\n\
3306         .timeline {position:relative;font-size:14px;cursor:pointer;width:100%; overflow:hidden;background:linear-gradient(#cccccc, white);}\n\
3307         .thread {position:absolute;height:0%;overflow:hidden;line-height:'+devtextH+';font-size:'+devtextS+';border:1px solid;text-align:center;white-space:nowrap;background-color:rgba(204,204,204,0.5);}\n\
3308         .thread.sync {background-color:'+sysvals.synccolor+';}\n\
3309         .thread.bg {background-color:'+sysvals.kprobecolor+';}\n\
3310         .thread:hover {background-color:white;border:1px solid red;'+hoverZ+'}\n\
3311         .hover {background-color:white;border:1px solid red;'+hoverZ+'}\n\
3312         .hover.sync {background-color:white;}\n\
3313         .hover.bg {background-color:white;}\n\
3314         .traceevent {position:absolute;font-size:10px;overflow:hidden;color:black;text-align:center;white-space:nowrap;border-radius:5px;border:1px solid black;background:linear-gradient(to bottom right,rgba(204,204,204,1),rgba(150,150,150,1));}\n\
3315         .traceevent:hover {background:white;}\n\
3316         .phase {position:absolute;overflow:hidden;border:0px;text-align:center;}\n\
3317         .phaselet {position:absolute;overflow:hidden;border:0px;text-align:center;height:100px;font-size:24px;}\n\
3318         .t {z-index:2;position:absolute;pointer-events:none;top:0%;height:100%;border-right:1px solid black;}\n\
3319         .legend {position:relative; width:100%; height:40px; text-align:center;margin-bottom:20px}\n\
3320         .legend .square {position:absolute;cursor:pointer;top:10px; width:0px;height:20px;border:1px solid;padding-left:20px;}\n\
3321         button {height:40px;width:200px;margin-bottom:20px;margin-top:20px;font-size:24px;}\n\
3322         .logbtn {position:relative;float:right;height:25px;width:50px;margin-top:3px;margin-bottom:0;font-size:10px;text-align:center;}\n\
3323         .devlist {position:'+x2changes[1]+';width:190px;}\n\
3324         a:link {color:white;text-decoration:none;}\n\
3325         a:visited {color:white;}\n\
3326         a:hover {color:white;}\n\
3327         a:active {color:white;}\n\
3328         .version {position:relative;float:left;color:white;font-size:10px;line-height:30px;margin-left:10px;}\n\
3329         #devicedetail {height:100px;box-shadow:5px 5px 20px black;}\n\
3330         .tblock {position:absolute;height:100%;}\n\
3331         .bg {z-index:1;}\n\
3332     </style>\n</head>\n<body>\n'
3333 
3334     # no header or css if its embedded
3335     if(sysvals.embedded):
3336         hf.write('pass True tSus %.3f tRes %.3f tLow %.3f fwvalid %s tSus %.3f tRes %.3f\n' %
3337             (data.tSuspended-data.start, data.end-data.tSuspended, data.tLow, data.fwValid, \
3338                 data.fwSuspend/1000000, data.fwResume/1000000))
3339     else:
3340         hf.write(html_header)
3341 
3342     # write the test title and general info header
3343     if(sysvals.stamp['time'] != ""):
3344         hf.write(headline_version)
3345         if sysvals.addlogs and sysvals.dmesgfile:
3346             hf.write('<button id="showdmesg" class="logbtn">dmesg</button>')
3347         if sysvals.addlogs and sysvals.ftracefile:
3348             hf.write('<button id="showftrace" class="logbtn">ftrace</button>')
3349         hf.write(headline_stamp.format(sysvals.stamp['host'],
3350             sysvals.stamp['kernel'], sysvals.stamp['mode'], \
3351                 sysvals.stamp['time']))
3352 
3353     # write the device timeline
3354     hf.write(devtl.html['header'])
3355     hf.write(devtl.html['timeline'])
3356     hf.write(devtl.html['legend'])
3357     hf.write('<div id="devicedetailtitle"></div>\n')
3358     hf.write('<div id="devicedetail" style="display:none;">\n')
3359     # draw the colored boxes for the device detail section
3360     for data in testruns:
3361         hf.write('<div id="devicedetail%d">\n' % data.testnumber)
3362         for b in data.phases:
3363             phase = data.dmesg[b]
3364             length = phase['end']-phase['start']
3365             left = '%.3f' % (((phase['start']-t0)*100.0)/tTotal)
3366             width = '%.3f' % ((length*100.0)/tTotal)
3367             hf.write(html_phaselet.format(b, left, width, \
3368                 data.dmesg[b]['color']))
3369         if sysvals.suspendmode == 'command':
3370             hf.write(html_phaselet.format('cmdexec', '0', '0', \
3371                 data.dmesg['resume_complete']['color']))
3372         hf.write('</div>\n')
3373     hf.write('</div>\n')
3374 
3375     # write the ftrace data (callgraph)
3376     data = testruns[-1]
3377     if(sysvals.usecallgraph and not sysvals.embedded):
3378         hf.write('<section id="callgraphs" class="callgraph">\n')
3379         # write out the ftrace data converted to html
3380         html_func_top = '<article id="{0}" class="atop" style="background-color:{1}">\n<input type="checkbox" class="pf" id="f{2}" checked/><label for="f{2}">{3} {4}</label>\n'
3381         html_func_start = '<article>\n<input type="checkbox" class="pf" id="f{0}" checked/><label for="f{0}">{1} {2}</label>\n'
3382         html_func_end = '</article>\n'
3383         html_func_leaf = '<article>{0} {1}</article>\n'
3384         num = 0
3385         for p in data.phases:
3386             list = data.dmesg[p]['list']
3387             for devname in data.sortedDevices(p):
3388                 if('ftrace' not in list[devname]):
3389                     continue
3390                 devid = list[devname]['id']
3391                 cg = list[devname]['ftrace']
3392                 clen = (cg.end - cg.start) * 1000
3393                 if clen < sysvals.mincglen:
3394                     continue
3395                 fmt = '<r>(%.3f ms @ '+sysvals.timeformat+' to '+sysvals.timeformat+')</r>'
3396                 flen = fmt % (clen, cg.start, cg.end)
3397                 name = devname
3398                 if(devname in sysvals.devprops):
3399                     name = sysvals.devprops[devname].altName(devname)
3400                 if sysvals.suspendmode == 'command':
3401                     ftitle = name
3402                 else:
3403                     ftitle = name+' '+p
3404                 hf.write(html_func_top.format(devid, data.dmesg[p]['color'], \
3405                     num, ftitle, flen))
3406                 num += 1
3407                 for line in cg.list:
3408                     if(line.length < 0.000000001):
3409                         flen = ''
3410                     else:
3411                         fmt = '<n>(%.3f ms @ '+sysvals.timeformat+')</n>'
3412                         flen = fmt % (line.length*1000, line.time)
3413                     if(line.freturn and line.fcall):
3414                         hf.write(html_func_leaf.format(line.name, flen))
3415                     elif(line.freturn):
3416                         hf.write(html_func_end)
3417                     else:
3418                         hf.write(html_func_start.format(num, line.name, flen))
3419                         num += 1
3420                 hf.write(html_func_end)
3421         hf.write('\n\n    </section>\n')
3422 
3423     # add the dmesg log as a hidden div
3424     if sysvals.addlogs and sysvals.dmesgfile:
3425         hf.write('<div id="dmesglog" style="display:none;">\n')
3426         lf = open(sysvals.dmesgfile, 'r')
3427         for line in lf:
3428             hf.write(line)
3429         lf.close()
3430         hf.write('</div>\n')
3431     # add the ftrace log as a hidden div
3432     if sysvals.addlogs and sysvals.ftracefile:
3433         hf.write('<div id="ftracelog" style="display:none;">\n')
3434         lf = open(sysvals.ftracefile, 'r')
3435         for line in lf:
3436             hf.write(line)
3437         lf.close()
3438         hf.write('</div>\n')
3439 
3440     if(not sysvals.embedded):
3441         # write the footer and close
3442         addScriptCode(hf, testruns)
3443         hf.write('</body>\n</html>\n')
3444     else:
3445         # embedded out will be loaded in a page, skip the js
3446         t0 = (testruns[0].start - testruns[-1].tSuspended) * 1000
3447         tMax = (testruns[-1].end - testruns[-1].tSuspended) * 1000
3448         # add js code in a div entry for later evaluation
3449         detail = 'var bounds = [%f,%f];\n' % (t0, tMax)
3450         detail += 'var devtable = [\n'
3451         for data in testruns:
3452             topo = data.deviceTopology()
3453             detail += '\t"%s",\n' % (topo)
3454         detail += '];\n'
3455         hf.write('<div id=customcode style=display:none>\n'+detail+'</div>\n')
3456     hf.close()
3457     return True
3458 
3459 # Function: addScriptCode
3460 # Description:
3461 #    Adds the javascript code to the output html
3462 # Arguments:
3463 #    hf: the open html file pointer
3464 #    testruns: array of Data objects from parseKernelLog or parseTraceLog
3465 def addScriptCode(hf, testruns):
3466     t0 = testruns[0].start * 1000
3467     tMax = testruns[-1].end * 1000
3468     # create an array in javascript memory with the device details
3469     detail = '  var devtable = [];\n'
3470     for data in testruns:
3471         topo = data.deviceTopology()
3472         detail += ' devtable[%d] = "%s";\n' % (data.testnumber, topo)
3473     detail += ' var bounds = [%f,%f];\n' % (t0, tMax)
3474     # add the code which will manipulate the data in the browser
3475     script_code = \
3476     '<script type="text/javascript">\n'+detail+\
3477     '   var resolution = -1;\n'\
3478     '   function redrawTimescale(t0, tMax, tS) {\n'\
3479     '       var rline = \'<div class="t" style="left:0;border-left:1px solid black;border-right:0;"><cR><-R</cR></div>\';\n'\
3480     '       var tTotal = tMax - t0;\n'\
3481     '       var list = document.getElementsByClassName("tblock");\n'\
3482     '       for (var i = 0; i < list.length; i++) {\n'\
3483     '           var timescale = list[i].getElementsByClassName("timescale")[0];\n'\
3484     '           var m0 = t0 + (tTotal*parseFloat(list[i].style.left)/100);\n'\
3485     '           var mTotal = tTotal*parseFloat(list[i].style.width)/100;\n'\
3486     '           var mMax = m0 + mTotal;\n'\
3487     '           var html = "";\n'\
3488     '           var divTotal = Math.floor(mTotal/tS) + 1;\n'\
3489     '           if(divTotal > 1000) continue;\n'\
3490     '           var divEdge = (mTotal - tS*(divTotal-1))*100/mTotal;\n'\
3491     '           var pos = 0.0, val = 0.0;\n'\
3492     '           for (var j = 0; j < divTotal; j++) {\n'\
3493     '               var htmlline = "";\n'\
3494     '               if(list[i].id[5] == "r") {\n'\
3495     '                   pos = 100 - (((j)*tS*100)/mTotal);\n'\
3496     '                   val = (j)*tS;\n'\
3497     '                   htmlline = \'<div class="t" style="right:\'+pos+\'%">\'+val+\'ms</div>\';\n'\
3498     '                   if(j == 0)\n'\
3499     '                       htmlline = rline;\n'\
3500     '               } else {\n'\
3501     '                   pos = 100 - (((j)*tS*100)/mTotal) - divEdge;\n'\
3502     '                   val = (j-divTotal+1)*tS;\n'\
3503     '                   if(j == divTotal - 1)\n'\
3504     '                       htmlline = \'<div class="t" style="right:\'+pos+\'%"><cS>S-></cS></div>\';\n'\
3505     '                   else\n'\
3506     '                       htmlline = \'<div class="t" style="right:\'+pos+\'%">\'+val+\'ms</div>\';\n'\
3507     '               }\n'\
3508     '               html += htmlline;\n'\
3509     '           }\n'\
3510     '           timescale.innerHTML = html;\n'\
3511     '       }\n'\
3512     '   }\n'\
3513     '   function zoomTimeline() {\n'\
3514     '       var dmesg = document.getElementById("dmesg");\n'\
3515     '       var zoombox = document.getElementById("dmesgzoombox");\n'\
3516     '       var val = parseFloat(dmesg.style.width);\n'\
3517     '       var newval = 100;\n'\
3518     '       var sh = window.outerWidth / 2;\n'\
3519     '       if(this.id == "zoomin") {\n'\
3520     '           newval = val * 1.2;\n'\
3521     '           if(newval > 910034) newval = 910034;\n'\
3522     '           dmesg.style.width = newval+"%";\n'\
3523     '           zoombox.scrollLeft = ((zoombox.scrollLeft + sh) * newval / val) - sh;\n'\
3524     '       } else if (this.id == "zoomout") {\n'\
3525     '           newval = val / 1.2;\n'\
3526     '           if(newval < 100) newval = 100;\n'\
3527     '           dmesg.style.width = newval+"%";\n'\
3528     '           zoombox.scrollLeft = ((zoombox.scrollLeft + sh) * newval / val) - sh;\n'\
3529     '       } else {\n'\
3530     '           zoombox.scrollLeft = 0;\n'\
3531     '           dmesg.style.width = "100%";\n'\
3532     '       }\n'\
3533     '       var tS = [10000, 5000, 2000, 1000, 500, 200, 100, 50, 20, 10, 5, 2, 1];\n'\
3534     '       var t0 = bounds[0];\n'\
3535     '       var tMax = bounds[1];\n'\
3536     '       var tTotal = tMax - t0;\n'\
3537     '       var wTotal = tTotal * 100.0 / newval;\n'\
3538     '       var idx = 7*window.innerWidth/1100;\n'\
3539     '       for(var i = 0; (i < tS.length)&&((wTotal / tS[i]) < idx); i++);\n'\
3540     '       if(i >= tS.length) i = tS.length - 1;\n'\
3541     '       if(tS[i] == resolution) return;\n'\
3542     '       resolution = tS[i];\n'\
3543     '       redrawTimescale(t0, tMax, tS[i]);\n'\
3544     '   }\n'\
3545     '   function deviceHover() {\n'\
3546     '       var name = this.title.slice(0, this.title.indexOf(" ("));\n'\
3547     '       var dmesg = document.getElementById("dmesg");\n'\
3548     '       var dev = dmesg.getElementsByClassName("thread");\n'\
3549     '       var cpu = -1;\n'\
3550     '       if(name.match("CPU_ON\[[0-9]*\]"))\n'\
3551     '           cpu = parseInt(name.slice(7));\n'\
3552     '       else if(name.match("CPU_OFF\[[0-9]*\]"))\n'\
3553     '           cpu = parseInt(name.slice(8));\n'\
3554     '       for (var i = 0; i < dev.length; i++) {\n'\
3555     '           dname = dev[i].title.slice(0, dev[i].title.indexOf(" ("));\n'\
3556     '           var cname = dev[i].className.slice(dev[i].className.indexOf("thread"));\n'\
3557     '           if((cpu >= 0 && dname.match("CPU_O[NF]*\\\[*"+cpu+"\\\]")) ||\n'\
3558     '               (name == dname))\n'\
3559     '           {\n'\
3560     '               dev[i].className = "hover "+cname;\n'\
3561     '           } else {\n'\
3562     '               dev[i].className = cname;\n'\
3563     '           }\n'\
3564     '       }\n'\
3565     '   }\n'\
3566     '   function deviceUnhover() {\n'\
3567     '       var dmesg = document.getElementById("dmesg");\n'\
3568     '       var dev = dmesg.getElementsByClassName("thread");\n'\
3569     '       for (var i = 0; i < dev.length; i++) {\n'\
3570     '           dev[i].className = dev[i].className.slice(dev[i].className.indexOf("thread"));\n'\
3571     '       }\n'\
3572     '   }\n'\
3573     '   function deviceTitle(title, total, cpu) {\n'\
3574     '       var prefix = "Total";\n'\
3575     '       if(total.length > 3) {\n'\
3576     '           prefix = "Average";\n'\
3577     '           total[1] = (total[1]+total[3])/2;\n'\
3578     '           total[2] = (total[2]+total[4])/2;\n'\
3579     '       }\n'\
3580     '       var devtitle = document.getElementById("devicedetailtitle");\n'\
3581     '       var name = title.slice(0, title.indexOf(" ("));\n'\
3582     '       if(cpu >= 0) name = "CPU"+cpu;\n'\
3583     '       var driver = "";\n'\
3584     '       var tS = "<t2>(</t2>";\n'\
3585     '       var tR = "<t2>)</t2>";\n'\
3586     '       if(total[1] > 0)\n'\
3587     '           tS = "<t2>("+prefix+" Suspend:</t2><t0> "+total[1].toFixed(3)+" ms</t0> ";\n'\
3588     '       if(total[2] > 0)\n'\
3589     '           tR = " <t2>"+prefix+" Resume:</t2><t0> "+total[2].toFixed(3)+" ms<t2>)</t2></t0>";\n'\
3590     '       var s = title.indexOf("{");\n'\
3591     '       var e = title.indexOf("}");\n'\
3592     '       if((s >= 0) && (e >= 0))\n'\
3593     '           driver = title.slice(s+1, e) + " <t1>@</t1> ";\n'\
3594     '       if(total[1] > 0 && total[2] > 0)\n'\
3595     '           devtitle.innerHTML = "<t0>"+driver+name+"</t0> "+tS+tR;\n'\
3596     '       else\n'\
3597     '           devtitle.innerHTML = "<t0>"+title+"</t0>";\n'\
3598     '       return name;\n'\
3599     '   }\n'\
3600     '   function deviceDetail() {\n'\
3601     '       var devinfo = document.getElementById("devicedetail");\n'\
3602     '       devinfo.style.display = "block";\n'\
3603     '       var name = this.title.slice(0, this.title.indexOf(" ("));\n'\
3604     '       var cpu = -1;\n'\
3605     '       if(name.match("CPU_ON\[[0-9]*\]"))\n'\
3606     '           cpu = parseInt(name.slice(7));\n'\
3607     '       else if(name.match("CPU_OFF\[[0-9]*\]"))\n'\
3608     '           cpu = parseInt(name.slice(8));\n'\
3609     '       var dmesg = document.getElementById("dmesg");\n'\
3610     '       var dev = dmesg.getElementsByClassName("thread");\n'\
3611     '       var idlist = [];\n'\
3612     '       var pdata = [[]];\n'\
3613     '       if(document.getElementById("devicedetail1"))\n'\
3614     '           pdata = [[], []];\n'\
3615     '       var pd = pdata[0];\n'\
3616     '       var total = [0.0, 0.0, 0.0];\n'\
3617     '       for (var i = 0; i < dev.length; i++) {\n'\
3618     '           dname = dev[i].title.slice(0, dev[i].title.indexOf(" ("));\n'\
3619     '           if((cpu >= 0 && dname.match("CPU_O[NF]*\\\[*"+cpu+"\\\]")) ||\n'\
3620     '               (name == dname))\n'\
3621     '           {\n'\
3622     '               idlist[idlist.length] = dev[i].id;\n'\
3623     '               var tidx = 1;\n'\
3624     '               if(dev[i].id[0] == "a") {\n'\
3625     '                   pd = pdata[0];\n'\
3626     '               } else {\n'\
3627     '                   if(pdata.length == 1) pdata[1] = [];\n'\
3628     '                   if(total.length == 3) total[3]=total[4]=0.0;\n'\
3629     '                   pd = pdata[1];\n'\
3630     '                   tidx = 3;\n'\
3631     '               }\n'\
3632     '               var info = dev[i].title.split(" ");\n'\
3633     '               var pname = info[info.length-1];\n'\
3634     '               pd[pname] = parseFloat(info[info.length-3].slice(1));\n'\
3635     '               total[0] += pd[pname];\n'\
3636     '               if(pname.indexOf("suspend") >= 0)\n'\
3637     '                   total[tidx] += pd[pname];\n'\
3638     '               else\n'\
3639     '                   total[tidx+1] += pd[pname];\n'\
3640     '           }\n'\
3641     '       }\n'\
3642     '       var devname = deviceTitle(this.title, total, cpu);\n'\
3643     '       var left = 0.0;\n'\
3644     '       for (var t = 0; t < pdata.length; t++) {\n'\
3645     '           pd = pdata[t];\n'\
3646     '           devinfo = document.getElementById("devicedetail"+t);\n'\
3647     '           var phases = devinfo.getElementsByClassName("phaselet");\n'\
3648     '           for (var i = 0; i < phases.length; i++) {\n'\
3649     '               if(phases[i].id in pd) {\n'\
3650     '                   var w = 100.0*pd[phases[i].id]/total[0];\n'\
3651     '                   var fs = 32;\n'\
3652     '                   if(w < 8) fs = 4*w | 0;\n'\
3653     '                   var fs2 = fs*3/4;\n'\
3654     '                   phases[i].style.width = w+"%";\n'\
3655     '                   phases[i].style.left = left+"%";\n'\
3656     '                   phases[i].title = phases[i].id+" "+pd[phases[i].id]+" ms";\n'\
3657     '                   left += w;\n'\
3658     '                   var time = "<t4 style=\\"font-size:"+fs+"px\\">"+pd[phases[i].id]+" ms<br></t4>";\n'\
3659     '                   var pname = "<t3 style=\\"font-size:"+fs2+"px\\">"+phases[i].id.replace("_", " ")+"</t3>";\n'\
3660     '                   phases[i].innerHTML = time+pname;\n'\
3661     '               } else {\n'\
3662     '                   phases[i].style.width = "0%";\n'\
3663     '                   phases[i].style.left = left+"%";\n'\
3664     '               }\n'\
3665     '           }\n'\
3666     '       }\n'\
3667     '       var cglist = document.getElementById("callgraphs");\n'\
3668     '       if(!cglist) return;\n'\
3669     '       var cg = cglist.getElementsByClassName("atop");\n'\
3670     '       if(cg.length < 10) return;\n'\
3671     '       for (var i = 0; i < cg.length; i++) {\n'\
3672     '           if(idlist.indexOf(cg[i].id) >= 0) {\n'\
3673     '               cg[i].style.display = "block";\n'\
3674     '           } else {\n'\
3675     '               cg[i].style.display = "none";\n'\
3676     '           }\n'\
3677     '       }\n'\
3678     '   }\n'\
3679     '   function devListWindow(e) {\n'\
3680     '       var sx = e.clientX;\n'\
3681     '       if(sx > window.innerWidth - 440)\n'\
3682     '           sx = window.innerWidth - 440;\n'\
3683     '       var cfg="top="+e.screenY+", left="+sx+", width=440, height=720, scrollbars=yes";\n'\
3684     '       var win = window.open("", "_blank", cfg);\n'\
3685     '       if(window.chrome) win.moveBy(sx, 0);\n'\
3686     '       var html = "<title>"+e.target.innerHTML+"</title>"+\n'\
3687     '           "<style type=\\"text/css\\">"+\n'\
3688     '           "   ul {list-style-type:circle;padding-left:10px;margin-left:10px;}"+\n'\
3689     '           "</style>"\n'\
3690     '       var dt = devtable[0];\n'\
3691     '       if(e.target.id != "devlist1")\n'\
3692     '           dt = devtable[1];\n'\
3693     '       win.document.write(html+dt);\n'\
3694     '   }\n'\
3695     '   function logWindow(e) {\n'\
3696     '       var name = e.target.id.slice(4);\n'\
3697     '       var win = window.open();\n'\
3698     '       var log = document.getElementById(name+"log");\n'\
3699     '       var title = "<title>"+document.title.split(" ")[0]+" "+name+" log</title>";\n'\
3700     '       win.document.write(title+"<pre>"+log.innerHTML+"</pre>");\n'\
3701     '       win.document.close();\n'\
3702     '   }\n'\
3703     '   function onClickPhase(e) {\n'\
3704     '   }\n'\
3705     '   window.addEventListener("resize", function () {zoomTimeline();});\n'\
3706     '   window.addEventListener("load", function () {\n'\
3707     '       var dmesg = document.getElementById("dmesg");\n'\
3708     '       dmesg.style.width = "100%"\n'\
3709     '       document.getElementById("zoomin").onclick = zoomTimeline;\n'\
3710     '       document.getElementById("zoomout").onclick = zoomTimeline;\n'\
3711     '       document.getElementById("zoomdef").onclick = zoomTimeline;\n'\
3712     '       var list = document.getElementsByClassName("square");\n'\
3713     '       for (var i = 0; i < list.length; i++)\n'\
3714     '           list[i].onclick = onClickPhase;\n'\
3715     '       var list = document.getElementsByClassName("logbtn");\n'\
3716     '       for (var i = 0; i < list.length; i++)\n'\
3717     '           list[i].onclick = logWindow;\n'\
3718     '       list = document.getElementsByClassName("devlist");\n'\
3719     '       for (var i = 0; i < list.length; i++)\n'\
3720     '           list[i].onclick = devListWindow;\n'\
3721     '       var dev = dmesg.getElementsByClassName("thread");\n'\
3722     '       for (var i = 0; i < dev.length; i++) {\n'\
3723     '           dev[i].onclick = deviceDetail;\n'\
3724     '           dev[i].onmouseover = deviceHover;\n'\
3725     '           dev[i].onmouseout = deviceUnhover;\n'\
3726     '       }\n'\
3727     '       zoomTimeline();\n'\
3728     '   });\n'\
3729     '</script>\n'
3730     hf.write(script_code);
3731 
3732 # Function: executeSuspend
3733 # Description:
3734 #    Execute system suspend through the sysfs interface, then copy the output
3735 #    dmesg and ftrace files to the test output directory.
3736 def executeSuspend():
3737     global sysvals
3738 
3739     t0 = time.time()*1000
3740     tp = sysvals.tpath
3741     fwdata = []
3742     # mark the start point in the kernel ring buffer just as we start
3743     sysvals.initdmesg()
3744     # start ftrace
3745     if(sysvals.usecallgraph or sysvals.usetraceevents):
3746         print('START TRACING')
3747         sysvals.fsetVal('1', 'tracing_on')
3748     # execute however many s/r runs requested
3749     for count in range(1,sysvals.execcount+1):
3750         # if this is test2 and there's a delay, start here
3751         if(count > 1 and sysvals.x2delay > 0):
3752             tN = time.time()*1000
3753             while (tN - t0) < sysvals.x2delay:
3754                 tN = time.time()*1000
3755                 time.sleep(0.001)
3756         # initiate suspend
3757         if(sysvals.usecallgraph or sysvals.usetraceevents):
3758             sysvals.fsetVal('SUSPEND START', 'trace_marker')
3759         if sysvals.suspendmode == 'command':
3760             print('COMMAND START')
3761             if(sysvals.rtcwake):
3762                 print('will issue an rtcwake in %d seconds' % sysvals.rtcwaketime)
3763                 sysvals.rtcWakeAlarmOn()
3764             os.system(sysvals.testcommand)
3765         else:
3766             if(sysvals.rtcwake):
3767                 print('SUSPEND START')
3768                 print('will autoresume in %d seconds' % sysvals.rtcwaketime)
3769                 sysvals.rtcWakeAlarmOn()
3770             else:
3771                 print('SUSPEND START (press a key to resume)')
3772             pf = open(sysvals.powerfile, 'w')
3773             pf.write(sysvals.suspendmode)
3774             # execution will pause here
3775             try:
3776                 pf.close()
3777             except:
3778                 pass
3779         t0 = time.time()*1000
3780         if(sysvals.rtcwake):
3781             sysvals.rtcWakeAlarmOff()
3782         # return from suspend
3783         print('RESUME COMPLETE')
3784         if(sysvals.usecallgraph or sysvals.usetraceevents):
3785             sysvals.fsetVal('RESUME COMPLETE', 'trace_marker')
3786         if(sysvals.suspendmode == 'mem'):
3787             fwdata.append(getFPDT(False))
3788     # look for post resume events after the last test run
3789     t = sysvals.postresumetime
3790     if(t > 0):
3791         print('Waiting %d seconds for POST-RESUME trace events...' % t)
3792         time.sleep(t)
3793     # stop ftrace
3794     if(sysvals.usecallgraph or sysvals.usetraceevents):
3795         sysvals.fsetVal('0', 'tracing_on')
3796         print('CAPTURING TRACE')
3797         writeDatafileHeader(sysvals.ftracefile, fwdata)
3798         os.system('cat '+tp+'trace >> '+sysvals.ftracefile)
3799         sysvals.fsetVal('', 'trace')
3800         devProps()
3801     # grab a copy of the dmesg output
3802     print('CAPTURING DMESG')
3803     writeDatafileHeader(sysvals.dmesgfile, fwdata)
3804     sysvals.getdmesg()
3805 
3806 def writeDatafileHeader(filename, fwdata):
3807     global sysvals
3808 
3809     prt = sysvals.postresumetime
3810     fp = open(filename, 'a')
3811     fp.write(sysvals.teststamp+'\n')
3812     if(sysvals.suspendmode == 'mem'):
3813         for fw in fwdata:
3814             if(fw):
3815                 fp.write('# fwsuspend %u fwresume %u\n' % (fw[0], fw[1]))
3816     if(prt > 0):
3817         fp.write('# post resume time %u\n' % prt)
3818     fp.close()
3819 
3820 # Function: setUSBDevicesAuto
3821 # Description:
3822 #    Set the autosuspend control parameter of all USB devices to auto
3823 #    This can be dangerous, so use at your own risk, most devices are set
3824 #    to always-on since the kernel cant determine if the device can
3825 #    properly autosuspend
3826 def setUSBDevicesAuto():
3827     global sysvals
3828 
3829     rootCheck(True)
3830     for dirname, dirnames, filenames in os.walk('/sys/devices'):
3831         if(re.match('.*/usb[0-9]*.*', dirname) and
3832             'idVendor' in filenames and 'idProduct' in filenames):
3833             os.system('echo auto > %s/power/control' % dirname)
3834             name = dirname.split('/')[-1]
3835             desc = os.popen('cat %s/product 2>/dev/null' % \
3836                 dirname).read().replace('\n', '')
3837             ctrl = os.popen('cat %s/power/control 2>/dev/null' % \
3838                 dirname).read().replace('\n', '')
3839             print('control is %s for %6s: %s' % (ctrl, name, desc))
3840 
3841 # Function: yesno
3842 # Description:
3843 #    Print out an equivalent Y or N for a set of known parameter values
3844 # Output:
3845 #    'Y', 'N', or ' ' if the value is unknown
3846 def yesno(val):
3847     yesvals = ['auto', 'enabled', 'active', '1']
3848     novals = ['on', 'disabled', 'suspended', 'forbidden', 'unsupported']
3849     if val in yesvals:
3850         return 'Y'
3851     elif val in novals:
3852         return 'N'
3853     return ' '
3854 
3855 # Function: ms2nice
3856 # Description:
3857 #    Print out a very concise time string in minutes and seconds
3858 # Output:
3859 #    The time string, e.g. "1901m16s"
3860 def ms2nice(val):
3861     ms = 0
3862     try:
3863         ms = int(val)
3864     except:
3865         return 0.0
3866     m = ms / 60000
3867     s = (ms / 1000) - (m * 60)
3868     return '%3dm%2ds' % (m, s)
3869 
3870 # Function: detectUSB
3871 # Description:
3872 #    Detect all the USB hosts and devices currently connected and add
3873 #    a list of USB device names to sysvals for better timeline readability
3874 def detectUSB():
3875     global sysvals
3876 
3877     field = {'idVendor':'', 'idProduct':'', 'product':'', 'speed':''}
3878     power = {'async':'', 'autosuspend':'', 'autosuspend_delay_ms':'',
3879              'control':'', 'persist':'', 'runtime_enabled':'',
3880              'runtime_status':'', 'runtime_usage':'',
3881             'runtime_active_time':'',
3882             'runtime_suspended_time':'',
3883             'active_duration':'',
3884             'connected_duration':''}
3885 
3886     print('LEGEND')
3887     print('---------------------------------------------------------------------------------------------')
3888     print('  A = async/sync PM queue Y/N                       D = autosuspend delay (seconds)')
3889     print('  S = autosuspend Y/N                         rACTIVE = runtime active (min/sec)')
3890     print('  P = persist across suspend Y/N              rSUSPEN = runtime suspend (min/sec)')
3891     print('  E = runtime suspend enabled/forbidden Y/N    ACTIVE = active duration (min/sec)')
3892     print('  R = runtime status active/suspended Y/N     CONNECT = connected duration (min/sec)')
3893     print('  U = runtime usage count')
3894     print('---------------------------------------------------------------------------------------------')
3895     print('  NAME       ID      DESCRIPTION         SPEED A S P E R U D rACTIVE rSUSPEN  ACTIVE CONNECT')
3896     print('---------------------------------------------------------------------------------------------')
3897 
3898     for dirname, dirnames, filenames in os.walk('/sys/devices'):
3899         if(re.match('.*/usb[0-9]*.*', dirname) and
3900             'idVendor' in filenames and 'idProduct' in filenames):
3901             for i in field:
3902                 field[i] = os.popen('cat %s/%s 2>/dev/null' % \
3903                     (dirname, i)).read().replace('\n', '')
3904             name = dirname.split('/')[-1]
3905             for i in power:
3906                 power[i] = os.popen('cat %s/power/%s 2>/dev/null' % \
3907                     (dirname, i)).read().replace('\n', '')
3908             if(re.match('usb[0-9]*', name)):
3909                 first = '%-8s' % name
3910             else:
3911                 first = '%8s' % name
3912             print('%s [%s:%s] %-20s %-4s %1s %1s %1s %1s %1s %1s %1s %s %s %s %s' % \
3913                 (first, field['idVendor'], field['idProduct'], \
3914                 field['product'][0:20], field['speed'], \
3915                 yesno(power['async']), \
3916                 yesno(power['control']), \
3917                 yesno(power['persist']), \
3918                 yesno(power['runtime_enabled']), \
3919                 yesno(power['runtime_status']), \
3920                 power['runtime_usage'], \
3921                 power['autosuspend'], \
3922                 ms2nice(power['runtime_active_time']), \
3923                 ms2nice(power['runtime_suspended_time']), \
3924                 ms2nice(power['active_duration']), \
3925                 ms2nice(power['connected_duration'])))
3926 
3927 # Function: devProps
3928 # Description:
3929 #    Retrieve a list of properties for all devices in the trace log
3930 def devProps(data=0):
3931     global sysvals
3932     props = dict()
3933 
3934     if data:
3935         idx = data.index(': ') + 2
3936         if idx >= len(data):
3937             return
3938         devlist = data[idx:].split(';')
3939         for dev in devlist:
3940             f = dev.split(',')
3941             if len(f) < 3:
3942                 continue
3943             dev = f[0]
3944             props[dev] = DevProps()
3945             props[dev].altname = f[1]
3946             if int(f[2]):
3947                 props[dev].async = True
3948             else:
3949                 props[dev].async = False
3950             sysvals.devprops = props
3951         if sysvals.suspendmode == 'command' and 'testcommandstring' in props:
3952             sysvals.testcommand = props['testcommandstring'].altname
3953         return
3954 
3955     if(os.path.exists(sysvals.ftracefile) == False):
3956         doError('%s does not exist' % sysvals.ftracefile, False)
3957 
3958     # first get the list of devices we need properties for
3959     msghead = 'Additional data added by AnalyzeSuspend'
3960     alreadystamped = False
3961     tp = TestProps()
3962     tf = open(sysvals.ftracefile, 'r')
3963     for line in tf:
3964         if msghead in line:
3965             alreadystamped = True
3966             continue
3967         # determine the trace data type (required for further parsing)
3968         m = re.match(sysvals.tracertypefmt, line)
3969         if(m):
3970             tp.setTracerType(m.group('t'))
3971             continue
3972         # parse only valid lines, if this is not one move on
3973         m = re.match(tp.ftrace_line_fmt, line)
3974         if(not m or 'device_pm_callback_start' not in line):
3975             continue
3976         m = re.match('.*: (?P<drv>.*) (?P<d>.*), parent: *(?P<p>.*), .*', m.group('msg'));
3977         if(not m):
3978             continue
3979         drv, dev, par = m.group('drv'), m.group('d'), m.group('p')
3980         if dev not in props:
3981             props[dev] = DevProps()
3982     tf.close()
3983 
3984     if not alreadystamped and sysvals.suspendmode == 'command':
3985         out = '#\n# '+msghead+'\n# Device Properties: '
3986         out += 'testcommandstring,%s,0;' % (sysvals.testcommand)
3987         with open(sysvals.ftracefile, 'a') as fp:
3988             fp.write(out+'\n')
3989         sysvals.devprops = props
3990         return
3991 
3992     # now get the syspath for each of our target devices
3993     for dirname, dirnames, filenames in os.walk('/sys/devices'):
3994         if(re.match('.*/power', dirname) and 'async' in filenames):
3995             dev = dirname.split('/')[-2]
3996             if dev in props and (not props[dev].syspath or len(dirname) < len(props[dev].syspath)):
3997                 props[dev].syspath = dirname[:-6]
3998 
3999     # now fill in the properties for our target devices
4000     for dev in props:
4001         dirname = props[dev].syspath
4002         if not dirname or not os.path.exists(dirname):
4003             continue
4004         with open(dirname+'/power/async') as fp:
4005             text = fp.read()
4006             props[dev].async = False
4007             if 'enabled' in text:
4008                 props[dev].async = True
4009         fields = os.listdir(dirname)
4010         if 'product' in fields:
4011             with open(dirname+'/product') as fp:
4012                 props[dev].altname = fp.read()
4013         elif 'name' in fields:
4014             with open(dirname+'/name') as fp:
4015                 props[dev].altname = fp.read()
4016         elif 'model' in fields:
4017             with open(dirname+'/model') as fp:
4018                 props[dev].altname = fp.read()
4019         elif 'description' in fields:
4020             with open(dirname+'/description') as fp:
4021                 props[dev].altname = fp.read()
4022         elif 'id' in fields:
4023             with open(dirname+'/id') as fp:
4024                 props[dev].altname = fp.read()
4025         elif 'idVendor' in fields and 'idProduct' in fields:
4026             idv, idp = '', ''
4027             with open(dirname+'/idVendor') as fp:
4028                 idv = fp.read().strip()
4029             with open(dirname+'/idProduct') as fp:
4030                 idp = fp.read().strip()
4031             props[dev].altname = '%s:%s' % (idv, idp)
4032 
4033         if props[dev].altname:
4034             out = props[dev].altname.strip().replace('\n', ' ')
4035             out = out.replace(',', ' ')
4036             out = out.replace(';', ' ')
4037             props[dev].altname = out
4038 
4039     # and now write the data to the ftrace file
4040     if not alreadystamped:
4041         out = '#\n# '+msghead+'\n# Device Properties: '
4042         for dev in sorted(props):
4043             out += props[dev].out(dev)
4044         with open(sysvals.ftracefile, 'a') as fp:
4045             fp.write(out+'\n')
4046 
4047     sysvals.devprops = props
4048 
4049 # Function: getModes
4050 # Description:
4051 #    Determine the supported power modes on this system
4052 # Output:
4053 #    A string list of the available modes
4054 def getModes():
4055     global sysvals
4056     modes = ''
4057     if(os.path.exists(sysvals.powerfile)):
4058         fp = open(sysvals.powerfile, 'r')
4059         modes = string.split(fp.read())
4060         fp.close()
4061     return modes
4062 
4063 # Function: getFPDT
4064 # Description:
4065 #    Read the acpi bios tables and pull out FPDT, the firmware data
4066 # Arguments:
4067 #    output: True to output the info to stdout, False otherwise
4068 def getFPDT(output):
4069     global sysvals
4070 
4071     rectype = {}
4072     rectype[0] = 'Firmware Basic Boot Performance Record'
4073     rectype[1] = 'S3 Performance Table Record'
4074     prectype = {}
4075     prectype[0] = 'Basic S3 Resume Performance Record'
4076     prectype[1] = 'Basic S3 Suspend Performance Record'
4077 
4078     rootCheck(True)
4079     if(not os.path.exists(sysvals.fpdtpath)):
4080         if(output):
4081             doError('file does not exist: %s' % sysvals.fpdtpath, False)
4082         return False
4083     if(not os.access(sysvals.fpdtpath, os.R_OK)):
4084         if(output):
4085             doError('file is not readable: %s' % sysvals.fpdtpath, False)
4086         return False
4087     if(not os.path.exists(sysvals.mempath)):
4088         if(output):
4089             doError('file does not exist: %s' % sysvals.mempath, False)
4090         return False
4091     if(not os.access(sysvals.mempath, os.R_OK)):
4092         if(output):
4093             doError('file is not readable: %s' % sysvals.mempath, False)
4094         return False
4095 
4096     fp = open(sysvals.fpdtpath, 'rb')
4097     buf = fp.read()
4098     fp.close()
4099 
4100     if(len(buf) < 36):
4101         if(output):
4102             doError('Invalid FPDT table data, should '+\
4103                 'be at least 36 bytes', False)
4104         return False
4105 
4106     table = struct.unpack('4sIBB6s8sI4sI', buf[0:36])
4107     if(output):
4108         print('')
4109         print('Firmware Performance Data Table (%s)' % table[0])
4110         print('                  Signature : %s' % table[0])
4111         print('               Table Length : %u' % table[1])
4112         print('                   Revision : %u' % table[2])
4113         print('                   Checksum : 0x%x' % table[3])
4114         print('                     OEM ID : %s' % table[4])
4115         print('               OEM Table ID : %s' % table[5])
4116         print('               OEM Revision : %u' % table[6])
4117         print('                 Creator ID : %s' % table[7])
4118         print('           Creator Revision : 0x%x' % table[8])
4119         print('')
4120 
4121     if(table[0] != 'FPDT'):
4122         if(output):
4123             doError('Invalid FPDT table')
4124         return False
4125     if(len(buf) <= 36):
4126         return False
4127     i = 0
4128     fwData = [0, 0]
4129     records = buf[36:]
4130     fp = open(sysvals.mempath, 'rb')
4131     while(i < len(records)):
4132         header = struct.unpack('HBB', records[i:i+4])
4133         if(header[0] not in rectype):
4134             i += header[1]
4135             continue
4136         if(header[1] != 16):
4137             i += header[1]
4138             continue
4139         addr = struct.unpack('Q', records[i+8:i+16])[0]
4140         try:
4141             fp.seek(addr)
4142             first = fp.read(8)
4143         except:
4144             if(output):
4145                 print('Bad address 0x%x in %s' % (addr, sysvals.mempath))
4146             return [0, 0]
4147         rechead = struct.unpack('4sI', first)
4148         recdata = fp.read(rechead[1]-8)
4149         if(rechead[0] == 'FBPT'):
4150             record = struct.unpack('HBBIQQQQQ', recdata)
4151             if(output):
4152                 print('%s (%s)' % (rectype[header[0]], rechead[0]))
4153                 print('                  Reset END : %u ns' % record[4])
4154                 print('  OS Loader LoadImage Start : %u ns' % record[5])
4155                 print(' OS Loader StartImage Start : %u ns' % record[6])
4156                 print('     ExitBootServices Entry : %u ns' % record[7])
4157                 print('      ExitBootServices Exit : %u ns' % record[8])
4158         elif(rechead[0] == 'S3PT'):
4159             if(output):
4160                 print('%s (%s)' % (rectype[header[0]], rechead[0]))
4161             j = 0
4162             while(j < len(recdata)):
4163                 prechead = struct.unpack('HBB', recdata[j:j+4])
4164                 if(prechead[0] not in prectype):
4165                     continue
4166                 if(prechead[0] == 0):
4167                     record = struct.unpack('IIQQ', recdata[j:j+prechead[1]])
4168                     fwData[1] = record[2]
4169                     if(output):
4170                         print('    %s' % prectype[prechead[0]])
4171                         print('               Resume Count : %u' % \
4172                             record[1])
4173                         print('                 FullResume : %u ns' % \
4174                             record[2])
4175                         print('              AverageResume : %u ns' % \
4176                             record[3])
4177                 elif(prechead[0] == 1):
4178                     record = struct.unpack('QQ', recdata[j+4:j+prechead[1]])
4179                     fwData[0] = record[1] - record[0]
4180                     if(output):
4181                         print('    %s' % prectype[prechead[0]])
4182                         print('               SuspendStart : %u ns' % \
4183                             record[0])
4184                         print('                 SuspendEnd : %u ns' % \
4185                             record[1])
4186                         print('                SuspendTime : %u ns' % \
4187                             fwData[0])
4188                 j += prechead[1]
4189         if(output):
4190             print('')
4191         i += header[1]
4192     fp.close()
4193     return fwData
4194 
4195 # Function: statusCheck
4196 # Description:
4197 #    Verify that the requested command and options will work, and
4198 #    print the results to the terminal
4199 # Output:
4200 #    True if the test will work, False if not
4201 def statusCheck(probecheck=False):
4202     global sysvals
4203     status = True
4204 
4205     print('Checking this system (%s)...' % platform.node())
4206 
4207     # check we have root access
4208     res = sysvals.colorText('NO (No features of this tool will work!)')
4209     if(rootCheck(False)):
4210         res = 'YES'
4211     print('    have root access: %s' % res)
4212     if(res != 'YES'):
4213         print('    Try running this script with sudo')
4214         return False
4215 
4216     # check sysfs is mounted
4217     res = sysvals.colorText('NO (No features of this tool will work!)')
4218     if(os.path.exists(sysvals.powerfile)):
4219         res = 'YES'
4220     print('    is sysfs mounted: %s' % res)
4221     if(res != 'YES'):
4222         return False
4223 
4224     # check target mode is a valid mode
4225     if sysvals.suspendmode != 'command':
4226         res = sysvals.colorText('NO')
4227         modes = getModes()
4228         if(sysvals.suspendmode in modes):
4229             res = 'YES'
4230         else:
4231             status = False
4232         print('    is "%s" a valid power mode: %s' % (sysvals.suspendmode, res))
4233         if(res == 'NO'):
4234             print('      valid power modes are: %s' % modes)
4235             print('      please choose one with -m')
4236 
4237     # check if ftrace is available
4238     res = sysvals.colorText('NO')
4239     ftgood = sysvals.verifyFtrace()
4240     if(ftgood):
4241         res = 'YES'
4242     elif(sysvals.usecallgraph):
4243         status = False
4244     print('    is ftrace supported: %s' % res)
4245 
4246     # check if kprobes are available
4247     res = sysvals.colorText('NO')
4248     sysvals.usekprobes = sysvals.verifyKprobes()
4249     if(sysvals.usekprobes):
4250         res = 'YES'
4251     else:
4252         sysvals.usedevsrc = False
4253     print('    are kprobes supported: %s' % res)
4254 
4255     # what data source are we using
4256     res = 'DMESG'
4257     if(ftgood):
4258         sysvals.usetraceeventsonly = True
4259         sysvals.usetraceevents = False
4260         for e in sysvals.traceevents:
4261             check = False
4262             if(os.path.exists(sysvals.epath+e)):
4263                 check = True
4264             if(not check):
4265                 sysvals.usetraceeventsonly = False
4266             if(e == 'suspend_resume' and check):
4267                 sysvals.usetraceevents = True
4268         if(sysvals.usetraceevents and sysvals.usetraceeventsonly):
4269             res = 'FTRACE (all trace events found)'
4270         elif(sysvals.usetraceevents):
4271             res = 'DMESG and FTRACE (suspend_resume trace event found)'
4272     print('    timeline data source: %s' % res)
4273 
4274     # check if rtcwake
4275     res = sysvals.colorText('NO')
4276     if(sysvals.rtcpath != ''):
4277         res = 'YES'
4278     elif(sysvals.rtcwake):
4279         status = False
4280     print('    is rtcwake supported: %s' % res)
4281 
4282     if not probecheck:
4283         return status
4284 
4285     if (sysvals.usecallgraph and len(sysvals.debugfuncs) > 0) or len(sysvals.kprobes) > 0:
4286         sysvals.initFtrace(True)
4287 
4288     # verify callgraph debugfuncs
4289     if sysvals.usecallgraph and len(sysvals.debugfuncs) > 0:
4290         print('    verifying these ftrace callgraph functions work:')
4291         sysvals.setFtraceFilterFunctions(sysvals.debugfuncs)
4292         fp = open(sysvals.tpath+'set_graph_function', 'r')
4293         flist = fp.read().split('\n')
4294         fp.close()
4295         for func in sysvals.debugfuncs:
4296             res = sysvals.colorText('NO')
4297             if func in flist:
4298                 res = 'YES'
4299             else:
4300                 for i in flist:
4301                     if ' [' in i and func == i.split(' ')[0]:
4302                         res = 'YES'
4303                         break
4304             print('         %s: %s' % (func, res))
4305 
4306     # verify kprobes
4307     if len(sysvals.kprobes) > 0:
4308         print('    verifying these kprobes work:')
4309         for name in sorted(sysvals.kprobes):
4310             if name in sysvals.tracefuncs:
4311                 continue
4312             res = sysvals.colorText('NO')
4313             if sysvals.testKprobe(sysvals.kprobes[name]):
4314                 res = 'YES'
4315             print('         %s: %s' % (name, res))
4316 
4317     return status
4318 
4319 # Function: doError
4320 # Description:
4321 #    generic error function for catastrphic failures
4322 # Arguments:
4323 #    msg: the error message to print
4324 #    help: True if printHelp should be called after, False otherwise
4325 def doError(msg, help):
4326     if(help == True):
4327         printHelp()
4328     print('ERROR: %s\n') % msg
4329     sys.exit()
4330 
4331 # Function: doWarning
4332 # Description:
4333 #    generic warning function for non-catastrophic anomalies
4334 # Arguments:
4335 #    msg: the warning message to print
4336 #    file: If not empty, a filename to request be sent to the owner for debug
4337 def doWarning(msg, file=''):
4338     print('/* %s */') % msg
4339     if(file):
4340         print('/* For a fix, please send this'+\
4341             ' %s file to <todd.e.brandt@intel.com> */' % file)
4342 
4343 # Function: rootCheck
4344 # Description:
4345 #    quick check to see if we have root access
4346 def rootCheck(fatal):
4347     global sysvals
4348     if(os.access(sysvals.powerfile, os.W_OK)):
4349         return True
4350     if fatal:
4351         doError('This command must be run as root', False)
4352     return False
4353 
4354 # Function: getArgInt
4355 # Description:
4356 #    pull out an integer argument from the command line with checks
4357 def getArgInt(name, args, min, max, main=True):
4358     if main:
4359         try:
4360             arg = args.next()
4361         except:
4362             doError(name+': no argument supplied', True)
4363     else:
4364         arg = args
4365     try:
4366         val = int(arg)
4367     except:
4368         doError(name+': non-integer value given', True)
4369     if(val < min or val > max):
4370         doError(name+': value should be between %d and %d' % (min, max), True)
4371     return val
4372 
4373 # Function: getArgFloat
4374 # Description:
4375 #    pull out a float argument from the command line with checks
4376 def getArgFloat(name, args, min, max, main=True):
4377     if main:
4378         try:
4379             arg = args.next()
4380         except:
4381             doError(name+': no argument supplied', True)
4382     else:
4383         arg = args
4384     try:
4385         val = float(arg)
4386     except:
4387         doError(name+': non-numerical value given', True)
4388     if(val < min or val > max):
4389         doError(name+': value should be between %f and %f' % (min, max), True)
4390     return val
4391 
4392 # Function: rerunTest
4393 # Description:
4394 #    generate an output from an existing set of ftrace/dmesg logs
4395 def rerunTest():
4396     global sysvals
4397 
4398     if(sysvals.ftracefile != ''):
4399         doesTraceLogHaveTraceEvents()
4400     if(sysvals.dmesgfile == '' and not sysvals.usetraceeventsonly):
4401         doError('recreating this html output '+\
4402             'requires a dmesg file', False)
4403     sysvals.setOutputFile()
4404     vprint('Output file: %s' % sysvals.htmlfile)
4405     print('PROCESSING DATA')
4406     if(sysvals.usetraceeventsonly):
4407         testruns = parseTraceLog()
4408     else:
4409         testruns = loadKernelLog()
4410         for data in testruns:
4411             parseKernelLog(data)
4412         if(sysvals.ftracefile != ''):
4413             appendIncompleteTraceLog(testruns)
4414     createHTML(testruns)
4415 
4416 # Function: runTest
4417 # Description:
4418 #    execute a suspend/resume, gather the logs, and generate the output
4419 def runTest(subdir, testpath=''):
4420     global sysvals
4421 
4422     # prepare for the test
4423     sysvals.initFtrace()
4424     sysvals.initTestOutput(subdir, testpath)
4425 
4426     vprint('Output files:\n    %s' % sysvals.dmesgfile)
4427     if(sysvals.usecallgraph or
4428         sysvals.usetraceevents or
4429         sysvals.usetraceeventsonly):
4430         vprint('    %s' % sysvals.ftracefile)
4431     vprint('    %s' % sysvals.htmlfile)
4432 
4433     # execute the test
4434     executeSuspend()
4435     sysvals.cleanupFtrace()
4436 
4437     # analyze the data and create the html output
4438     print('PROCESSING DATA')
4439     if(sysvals.usetraceeventsonly):
4440         # data for kernels 3.15 or newer is entirely in ftrace
4441         testruns = parseTraceLog()
4442     else:
4443         # data for kernels older than 3.15 is primarily in dmesg
4444         testruns = loadKernelLog()
4445         for data in testruns:
4446             parseKernelLog(data)
4447         if(sysvals.usecallgraph or sysvals.usetraceevents):
4448             appendIncompleteTraceLog(testruns)
4449     createHTML(testruns)
4450 
4451 # Function: runSummary
4452 # Description:
4453 #    create a summary of tests in a sub-directory
4454 def runSummary(subdir, output):
4455     global sysvals
4456 
4457     # get a list of ftrace output files
4458     files = []
4459     for dirname, dirnames, filenames in os.walk(subdir):
4460         for filename in filenames:
4461             if(re.match('.*_ftrace.txt', filename)):
4462                 files.append("%s/%s" % (dirname, filename))
4463 
4464     # process the files in order and get an array of data objects
4465     testruns = []
4466     for file in sorted(files):
4467         if output:
4468             print("Test found in %s" % os.path.dirname(file))
4469         sysvals.ftracefile = file
4470         sysvals.dmesgfile = file.replace('_ftrace.txt', '_dmesg.txt')
4471         doesTraceLogHaveTraceEvents()
4472         sysvals.usecallgraph = False
4473         if not sysvals.usetraceeventsonly:
4474             if(not os.path.exists(sysvals.dmesgfile)):
4475                 print("Skipping %s: not a valid test input" % file)
4476                 continue
4477             else:
4478                 if output:
4479                     f = os.path.basename(sysvals.ftracefile)
4480                     d = os.path.basename(sysvals.dmesgfile)
4481                     print("\tInput files: %s and %s" % (f, d))
4482                 testdata = loadKernelLog()
4483                 data = testdata[0]
4484                 parseKernelLog(data)
4485                 testdata = [data]
4486                 appendIncompleteTraceLog(testdata)
4487         else:
4488             if output:
4489                 print("\tInput file: %s" % os.path.basename(sysvals.ftracefile))
4490             testdata = parseTraceLog()
4491             data = testdata[0]
4492         data.normalizeTime(data.tSuspended)
4493         link = file.replace(subdir+'/', '').replace('_ftrace.txt', '.html')
4494         data.outfile = link
4495         testruns.append(data)
4496 
4497     createHTMLSummarySimple(testruns, subdir+'/summary.html')
4498 
4499 # Function: checkArgBool
4500 # Description:
4501 #    check if a boolean string value is true or false
4502 def checkArgBool(value):
4503     yes = ['1', 'true', 'yes', 'on']
4504     if value.lower() in yes:
4505         return True
4506     return False
4507 
4508 # Function: configFromFile
4509 # Description:
4510 #    Configure the script via the info in a config file
4511 def configFromFile(file):
4512     global sysvals
4513     Config = ConfigParser.ConfigParser()
4514 
4515     ignorekprobes = False
4516     Config.read(file)
4517     sections = Config.sections()
4518     if 'Settings' in sections:
4519         for opt in Config.options('Settings'):
4520             value = Config.get('Settings', opt).lower()
4521             if(opt.lower() == 'verbose'):
4522                 sysvals.verbose = checkArgBool(value)
4523             elif(opt.lower() == 'addlogs'):
4524                 sysvals.addlogs = checkArgBool(value)
4525             elif(opt.lower() == 'dev'):
4526                 sysvals.usedevsrc = checkArgBool(value)
4527             elif(opt.lower() == 'ignorekprobes'):
4528                 ignorekprobes = checkArgBool(value)
4529             elif(opt.lower() == 'x2'):
4530                 if checkArgBool(value):
4531                     sysvals.execcount = 2
4532             elif(opt.lower() == 'callgraph'):
4533                 sysvals.usecallgraph = checkArgBool(value)
4534             elif(opt.lower() == 'callgraphfunc'):
4535                 sysvals.debugfuncs = []
4536                 if value:
4537                     value = value.split(',')
4538                 for i in value:
4539                     sysvals.debugfuncs.append(i.strip())
4540             elif(opt.lower() == 'expandcg'):
4541                 sysvals.cgexp = checkArgBool(value)
4542             elif(opt.lower() == 'srgap'):
4543                 if checkArgBool(value):
4544                     sysvals.srgap = 5
4545             elif(opt.lower() == 'mode'):
4546                 sysvals.suspendmode = value
4547             elif(opt.lower() == 'command'):
4548                 sysvals.testcommand = value
4549             elif(opt.lower() == 'x2delay'):
4550                 sysvals.x2delay = getArgInt('-x2delay', value, 0, 60000, False)
4551             elif(opt.lower() == 'postres'):
4552                 sysvals.postresumetime = getArgInt('-postres', value, 0, 3600, False)
4553             elif(opt.lower() == 'rtcwake'):
4554                 sysvals.rtcwake = True
4555                 sysvals.rtcwaketime = getArgInt('-rtcwake', value, 0, 3600, False)
4556             elif(opt.lower() == 'timeprec'):
4557                 sysvals.setPrecision(getArgInt('-timeprec', value, 0, 6, False))
4558             elif(opt.lower() == 'mindev'):
4559                 sysvals.mindevlen = getArgFloat('-mindev', value, 0.0, 10000.0, False)
4560             elif(opt.lower() == 'mincg'):
4561                 sysvals.mincglen = getArgFloat('-mincg', value, 0.0, 10000.0, False)
4562             elif(opt.lower() == 'kprobecolor'):
4563                 try:
4564                     val = int(value, 16)
4565                     sysvals.kprobecolor = '#'+value
4566                 except:
4567                     sysvals.kprobecolor = value
4568             elif(opt.lower() == 'synccolor'):
4569                 try:
4570                     val = int(value, 16)
4571                     sysvals.synccolor = '#'+value
4572                 except:
4573                     sysvals.synccolor = value
4574             elif(opt.lower() == 'output-dir'):
4575                 args = dict()
4576                 n = datetime.now()
4577                 args['date'] = n.strftime('%y%m%d')
4578                 args['time'] = n.strftime('%H%M%S')
4579                 args['hostname'] = sysvals.hostname
4580                 sysvals.outdir = value.format(**args)
4581 
4582     if sysvals.suspendmode == 'command' and not sysvals.testcommand:
4583         doError('No command supplied for mode "command"', False)
4584     if sysvals.usedevsrc and sysvals.usecallgraph:
4585         doError('dev and callgraph cannot both be true', False)
4586     if sysvals.usecallgraph and sysvals.execcount > 1:
4587         doError('-x2 is not compatible with -f', False)
4588 
4589     if ignorekprobes:
4590         return
4591 
4592     kprobes = dict()
4593     archkprobe = 'Kprobe_'+platform.machine()
4594     if archkprobe in sections:
4595         for name in Config.options(archkprobe):
4596             kprobes[name] = Config.get(archkprobe, name)
4597     if 'Kprobe' in sections:
4598         for name in Config.options('Kprobe'):
4599             kprobes[name] = Config.get('Kprobe', name)
4600 
4601     for name in kprobes:
4602         function = name
4603         format = name
4604         color = ''
4605         args = dict()
4606         data = kprobes[name].split()
4607         i = 0
4608         for val in data:
4609             # bracketted strings are special formatting, read them separately
4610             if val[0] == '[' and val[-1] == ']':
4611                 for prop in val[1:-1].split(','):
4612                     p = prop.split('=')
4613                     if p[0] == 'color':
4614                         try:
4615                             color = int(p[1], 16)
4616                             color = '#'+p[1]
4617                         except:
4618                             color = p[1]
4619                 continue
4620             # first real arg should be the format string
4621             if i == 0:
4622                 format = val
4623             # all other args are actual function args
4624             else:
4625                 d = val.split('=')
4626                 args[d[0]] = d[1]
4627             i += 1
4628         if not function or not format:
4629             doError('Invalid kprobe: %s' % name, False)
4630         for arg in re.findall('{(?P<n>[a-z,A-Z,0-9]*)}', format):
4631             if arg not in args:
4632                 doError('Kprobe "%s" is missing argument "%s"' % (name, arg), False)
4633         if name in sysvals.kprobes:
4634             doError('Duplicate kprobe found "%s"' % (name), False)
4635         vprint('Adding KPROBE: %s %s %s %s' % (name, function, format, args))
4636         sysvals.kprobes[name] = {
4637             'name': name,
4638             'func': function,
4639             'format': format,
4640             'args': args,
4641             'mask': re.sub('{(?P<n>[a-z,A-Z,0-9]*)}', '.*', format)
4642         }
4643         if color:
4644             sysvals.kprobes[name]['color'] = color
4645 
4646 # Function: printHelp
4647 # Description:
4648 #    print out the help text
4649 def printHelp():
4650     global sysvals
4651     modes = getModes()
4652 
4653     print('')
4654     print('AnalyzeSuspend v%s' % sysvals.version)
4655     print('Usage: sudo analyze_suspend.py <options>')
4656     print('')
4657     print('Description:')
4658     print('  This tool is designed to assist kernel and OS developers in optimizing')
4659     print('  their linux stack\'s suspend/resume time. Using a kernel image built')
4660     print('  with a few extra options enabled, the tool will execute a suspend and')
4661     print('  capture dmesg and ftrace data until resume is complete. This data is')
4662     print('  transformed into a device timeline and an optional callgraph to give')
4663     print('  a detailed view of which devices/subsystems are taking the most')
4664     print('  time in suspend/resume.')
4665     print('')
4666     print('  Generates output files in subdirectory: suspend-mmddyy-HHMMSS')
4667     print('   HTML output:                    <hostname>_<mode>.html')
4668     print('   raw dmesg output:               <hostname>_<mode>_dmesg.txt')
4669     print('   raw ftrace output:              <hostname>_<mode>_ftrace.txt')
4670     print('')
4671     print('Options:')
4672     print('  [general]')
4673     print('    -h          Print this help text')
4674     print('    -v          Print the current tool version')
4675     print('    -config file Pull arguments and config options from a file')
4676     print('    -verbose    Print extra information during execution and analysis')
4677     print('    -status     Test to see if the system is enabled to run this tool')
4678     print('    -modes      List available suspend modes')
4679     print('    -m mode     Mode to initiate for suspend %s (default: %s)') % (modes, sysvals.suspendmode)
4680     print('    -o subdir   Override the output subdirectory')
4681     print('  [advanced]')
4682     print('    -rtcwake t  Use rtcwake to autoresume after <t> seconds (default: disabled)')
4683     print('    -addlogs    Add the dmesg and ftrace logs to the html output')
4684     print('    -multi n d  Execute <n> consecutive tests at <d> seconds intervals. The outputs will')
4685     print('                be created in a new subdirectory with a summary page.')
4686     print('    -srgap      Add a visible gap in the timeline between sus/res (default: disabled)')
4687     print('    -cmd {s}    Instead of suspend/resume, run a command, e.g. "sync -d"')
4688     print('    -mindev ms  Discard all device blocks shorter than ms milliseconds (e.g. 0.001 for us)')
4689     print('    -mincg  ms  Discard all callgraphs shorter than ms milliseconds (e.g. 0.001 for us)')
4690     print('    -timeprec N Number of significant digits in timestamps (0:S, [3:ms], 6:us)')
4691     print('  [debug]')
4692     print('    -f          Use ftrace to create device callgraphs (default: disabled)')
4693     print('    -expandcg   pre-expand the callgraph data in the html output (default: disabled)')
4694     print('    -flist      Print the list of functions currently being captured in ftrace')
4695     print('    -flistall   Print all functions capable of being captured in ftrace')
4696     print('    -fadd file  Add functions to be graphed in the timeline from a list in a text file')
4697     print('    -filter "d1 d2 ..." Filter out all but this list of device names')
4698     print('    -dev        Display common low level functions in the timeline')
4699     print('  [post-resume task analysis]')
4700     print('    -x2         Run two suspend/resumes back to back (default: disabled)')
4701     print('    -x2delay t  Minimum millisecond delay <t> between the two test runs (default: 0 ms)')
4702     print('    -postres t  Time after resume completion to wait for post-resume events (default: 0 S)')
4703     print('  [utilities]')
4704     print('    -fpdt       Print out the contents of the ACPI Firmware Performance Data Table')
4705     print('    -usbtopo    Print out the current USB topology with power info')
4706     print('    -usbauto    Enable autosuspend for all connected USB devices')
4707     print('  [re-analyze data from previous runs]')
4708     print('    -ftrace ftracefile  Create HTML output using ftrace input')
4709     print('    -dmesg dmesgfile    Create HTML output using dmesg (not needed for kernel >= 3.15)')
4710     print('    -summary directory  Create a summary of all test in this dir')
4711     print('')
4712     return True
4713 
4714 # ----------------- MAIN --------------------
4715 # exec start (skipped if script is loaded as library)
4716 if __name__ == '__main__':
4717     cmd = ''
4718     cmdarg = ''
4719     multitest = {'run': False, 'count': 0, 'delay': 0}
4720     simplecmds = ['-modes', '-fpdt', '-flist', '-flistall', '-usbtopo', '-usbauto', '-status']
4721     # loop through the command line arguments
4722     args = iter(sys.argv[1:])
4723     for arg in args:
4724         if(arg == '-m'):
4725             try:
4726                 val = args.next()
4727             except:
4728                 doError('No mode supplied', True)
4729             if val == 'command' and not sysvals.testcommand:
4730                 doError('No command supplied for mode "command"', True)
4731             sysvals.suspendmode = val
4732         elif(arg in simplecmds):
4733             cmd = arg[1:]
4734         elif(arg == '-h'):
4735             printHelp()
4736             sys.exit()
4737         elif(arg == '-v'):
4738             print("Version %s" % sysvals.version)
4739             sys.exit()
4740         elif(arg == '-x2'):
4741             sysvals.execcount = 2
4742             if(sysvals.usecallgraph):
4743                 doError('-x2 is not compatible with -f', False)
4744         elif(arg == '-x2delay'):
4745             sysvals.x2delay = getArgInt('-x2delay', args, 0, 60000)
4746         elif(arg == '-postres'):
4747             sysvals.postresumetime = getArgInt('-postres', args, 0, 3600)
4748         elif(arg == '-f'):
4749             sysvals.usecallgraph = True
4750             if(sysvals.execcount > 1):
4751                 doError('-x2 is not compatible with -f', False)
4752             if(sysvals.usedevsrc):
4753                 doError('-dev is not compatible with -f', False)
4754         elif(arg == '-addlogs'):
4755             sysvals.addlogs = True
4756         elif(arg == '-verbose'):
4757             sysvals.verbose = True
4758         elif(arg == '-dev'):
4759             sysvals.usedevsrc = True
4760             if(sysvals.usecallgraph):
4761                 doError('-dev is not compatible with -f', False)
4762         elif(arg == '-rtcwake'):
4763             sysvals.rtcwake = True
4764             sysvals.rtcwaketime = getArgInt('-rtcwake', args, 0, 3600)
4765         elif(arg == '-timeprec'):
4766             sysvals.setPrecision(getArgInt('-timeprec', args, 0, 6))
4767         elif(arg == '-mindev'):
4768             sysvals.mindevlen = getArgFloat('-mindev', args, 0.0, 10000.0)
4769         elif(arg == '-mincg'):
4770             sysvals.mincglen = getArgFloat('-mincg', args, 0.0, 10000.0)
4771         elif(arg == '-cmd'):
4772             try:
4773                 val = args.next()
4774             except:
4775                 doError('No command string supplied', True)
4776             sysvals.testcommand = val
4777             sysvals.suspendmode = 'command'
4778         elif(arg == '-expandcg'):
4779             sysvals.cgexp = True
4780         elif(arg == '-srgap'):
4781             sysvals.srgap = 5
4782         elif(arg == '-multi'):
4783             multitest['run'] = True
4784             multitest['count'] = getArgInt('-multi n (exec count)', args, 2, 1000000)
4785             multitest['delay'] = getArgInt('-multi d (delay between tests)', args, 0, 3600)
4786         elif(arg == '-o'):
4787             try:
4788                 val = args.next()
4789             except:
4790                 doError('No subdirectory name supplied', True)
4791             sysvals.outdir = val
4792         elif(arg == '-config'):
4793             try:
4794                 val = args.next()
4795             except:
4796                 doError('No text file supplied', True)
4797             if(os.path.exists(val) == False):
4798                 doError('%s does not exist' % val, False)
4799             configFromFile(val)
4800         elif(arg == '-fadd'):
4801             try:
4802                 val = args.next()
4803             except:
4804                 doError('No text file supplied', True)
4805             if(os.path.exists(val) == False):
4806                 doError('%s does not exist' % val, False)
4807             sysvals.addFtraceFilterFunctions(val)
4808         elif(arg == '-dmesg'):
4809             try:
4810                 val = args.next()
4811             except:
4812                 doError('No dmesg file supplied', True)
4813             sysvals.notestrun = True
4814             sysvals.dmesgfile = val
4815             if(os.path.exists(sysvals.dmesgfile) == False):
4816                 doError('%s does not exist' % sysvals.dmesgfile, False)
4817         elif(arg == '-ftrace'):
4818             try:
4819                 val = args.next()
4820             except:
4821                 doError('No ftrace file supplied', True)
4822             sysvals.notestrun = True
4823             sysvals.ftracefile = val
4824             if(os.path.exists(sysvals.ftracefile) == False):
4825                 doError('%s does not exist' % sysvals.ftracefile, False)
4826         elif(arg == '-summary'):
4827             try:
4828                 val = args.next()
4829             except:
4830                 doError('No directory supplied', True)
4831             cmd = 'summary'
4832             cmdarg = val
4833             sysvals.notestrun = True
4834             if(os.path.isdir(val) == False):
4835                 doError('%s is not accesible' % val, False)
4836         elif(arg == '-filter'):
4837             try:
4838                 val = args.next()
4839             except:
4840                 doError('No devnames supplied', True)
4841             sysvals.setDeviceFilter(val)
4842         else:
4843             doError('Invalid argument: '+arg, True)
4844 
4845     # callgraph size cannot exceed device size
4846     if sysvals.mincglen < sysvals.mindevlen:
4847         sysvals.mincglen = sysvals.mindevlen
4848 
4849     # just run a utility command and exit
4850     if(cmd != ''):
4851         if(cmd == 'status'):
4852             statusCheck(True)
4853         elif(cmd == 'fpdt'):
4854             getFPDT(True)
4855         elif(cmd == 'usbtopo'):
4856             detectUSB()
4857         elif(cmd == 'modes'):
4858             modes = getModes()
4859             print modes
4860         elif(cmd == 'flist'):
4861             sysvals.getFtraceFilterFunctions(True)
4862         elif(cmd == 'flistall'):
4863             sysvals.getFtraceFilterFunctions(False)
4864         elif(cmd == 'usbauto'):
4865             setUSBDevicesAuto()
4866         elif(cmd == 'summary'):
4867             print("Generating a summary of folder \"%s\"" % cmdarg)
4868             runSummary(cmdarg, True)
4869         sys.exit()
4870 
4871     # if instructed, re-analyze existing data files
4872     if(sysvals.notestrun):
4873         rerunTest()
4874         sys.exit()
4875 
4876     # verify that we can run a test
4877     if(not statusCheck()):
4878         print('Check FAILED, aborting the test run!')
4879         sys.exit()
4880 
4881     if multitest['run']:
4882         # run multiple tests in a separate subdirectory
4883         s = 'x%d' % multitest['count']
4884         if not sysvals.outdir:
4885             sysvals.outdir = datetime.now().strftime('suspend-'+s+'-%m%d%y-%H%M%S')
4886         if not os.path.isdir(sysvals.outdir):
4887             os.mkdir(sysvals.outdir)
4888         for i in range(multitest['count']):
4889             if(i != 0):
4890                 print('Waiting %d seconds...' % (multitest['delay']))
4891                 time.sleep(multitest['delay'])
4892             print('TEST (%d/%d) START' % (i+1, multitest['count']))
4893             runTest(sysvals.outdir)
4894             print('TEST (%d/%d) COMPLETE' % (i+1, multitest['count']))
4895         runSummary(sysvals.outdir, False)
4896     else:
4897         # run the test in the current directory
4898         runTest('.', sysvals.outdir)