* [PATCH 1/5] scripts: AnalyzeSuspend v4.2 part1
2016-07-14 21:09 [PATCH 0/5] scripts: AnalyzeSuspend v4.2 Todd Brandt
@ 2016-07-14 21:09 ` Todd Brandt
2016-07-14 21:09 ` [PATCH 2/5] scripts: AnalyzeSuspend v4.2 part2 Todd Brandt
` (4 subsequent siblings)
5 siblings, 0 replies; 9+ messages in thread
From: Todd Brandt @ 2016-07-14 21:09 UTC (permalink / raw)
To: linux-pm; +Cc: rjw, rafael.j.wysocki, todd.e.brandt, Todd Brandt
Signed-off-by: Todd Brandt <todd.e.brandt@linux.intel.com>
---
scripts/analyze_suspend.py | 753 ++++++++++++++++++++++++++++++++++++++-------
1 file changed, 643 insertions(+), 110 deletions(-)
diff --git a/scripts/analyze_suspend.py b/scripts/analyze_suspend.py
index 93e1fd4..813681f 100755
--- a/scripts/analyze_suspend.py
+++ b/scripts/analyze_suspend.py
@@ -19,6 +19,17 @@
# Authors:
# Todd Brandt <todd.e.brandt@linux.intel.com>
#
+# Links:
+# Home Page
+# https://01.org/suspendresume
+# Source repo
+# https://github.com/01org/suspendresume
+# Documentation
+# Getting Started
+# https://01.org/suspendresume/documentation/getting-started
+# Command List:
+# https://01.org/suspendresume/documentation/command-list
+#
# Description:
# This tool is designed to assist kernel and OS developers in optimizing
# their linux stack's suspend/resume time. Using a kernel image built
@@ -35,6 +46,8 @@
# CONFIG_FTRACE=y
# CONFIG_FUNCTION_TRACER=y
# CONFIG_FUNCTION_GRAPH_TRACER=y
+# CONFIG_KPROBES=y
+# CONFIG_KPROBES_ON_FTRACE=y
#
# For kernel versions older than 3.15:
# The following additional kernel parameters are required:
@@ -52,6 +65,7 @@ import re
import platform
from datetime import datetime
import struct
+import ConfigParser
# ----------------- CLASSES --------------------
@@ -60,8 +74,15 @@ import struct
# A global, single-instance container used to
# store system values and test parameters
class SystemValues:
- version = 3.0
+ ansi = False
+ version = '4.2'
verbose = False
+ addlogs = False
+ mindevlen = 0.001
+ mincglen = 1.0
+ srgap = 0
+ cgexp = False
+ outdir = ''
testdir = '.'
tpath = '/sys/kernel/debug/tracing/'
fpdtpath = '/sys/firmware/acpi/tables/FPDT'
@@ -71,26 +92,21 @@ class SystemValues:
'device_pm_callback_end',
'device_pm_callback_start'
]
- modename = {
- 'freeze': 'Suspend-To-Idle (S0)',
- 'standby': 'Power-On Suspend (S1)',
- 'mem': 'Suspend-to-RAM (S3)',
- 'disk': 'Suspend-to-disk (S4)'
- }
+ testcommand = ''
mempath = '/dev/mem'
powerfile = '/sys/power/state'
suspendmode = 'mem'
hostname = 'localhost'
prefix = 'test'
teststamp = ''
+ dmesgstart = 0.0
dmesgfile = ''
ftracefile = ''
htmlfile = ''
+ embedded = False
rtcwake = False
rtcwaketime = 10
rtcpath = ''
- android = False
- adb = 'adb'
devicefilter = []
stamp = 0
execcount = 1
@@ -98,16 +114,90 @@ class SystemValues:
usecallgraph = False
usetraceevents = False
usetraceeventsonly = False
+ usetracemarkers = True
+ usekprobes = True
+ usedevsrc = False
notestrun = False
- altdevname = dict()
+ devprops = dict()
postresumetime = 0
+ devpropfmt = '# Device Properties: .*'
tracertypefmt = '# tracer: (?P<t>.*)'
firmwarefmt = '# fwsuspend (?P<s>[0-9]*) fwresume (?P<r>[0-9]*)$'
postresumefmt = '# post resume time (?P<t>[0-9]*)$'
stampfmt = '# suspend-(?P<m>[0-9]{2})(?P<d>[0-9]{2})(?P<y>[0-9]{2})-'+\
'(?P<H>[0-9]{2})(?P<M>[0-9]{2})(?P<S>[0-9]{2})'+\
' (?P<host>.*) (?P<mode>.*) (?P<kernel>.*)$'
+ kprobecolor = 'rgba(204,204,204,0.5)'
+ synccolor = 'rgba(204,204,204,0.5)'
+ debugfuncs = []
+ tracefuncs = {
+ 'sys_sync': dict(),
+ 'pm_prepare_console': dict(),
+ 'pm_notifier_call_chain': dict(),
+ 'freeze_processes': dict(),
+ 'freeze_kernel_threads': dict(),
+ 'pm_restrict_gfp_mask': dict(),
+ 'acpi_suspend_begin': dict(),
+ 'suspend_console': dict(),
+ 'acpi_pm_prepare': dict(),
+ 'syscore_suspend': dict(),
+ 'arch_enable_nonboot_cpus_end': dict(),
+ 'syscore_resume': dict(),
+ 'acpi_pm_finish': dict(),
+ 'resume_console': dict(),
+ 'acpi_pm_end': dict(),
+ 'pm_restore_gfp_mask': dict(),
+ 'thaw_processes': dict(),
+ 'pm_restore_console': dict(),
+ 'CPU_OFF': {
+ 'func':'_cpu_down',
+ 'args_x86_64': {'cpu':'%di:s32'},
+ 'format': 'CPU_OFF[{cpu}]',
+ 'mask': 'CPU_.*_DOWN'
+ },
+ 'CPU_ON': {
+ 'func':'_cpu_up',
+ 'args_x86_64': {'cpu':'%di:s32'},
+ 'format': 'CPU_ON[{cpu}]',
+ 'mask': 'CPU_.*_UP'
+ },
+ }
+ dev_tracefuncs = {
+ # general wait/delay/sleep
+ 'msleep': { 'args_x86_64': {'time':'%di:s32'} },
+ 'udelay': { 'func':'__const_udelay', 'args_x86_64': {'loops':'%di:s32'} },
+ 'acpi_os_stall': dict(),
+ # ACPI
+ 'acpi_resume_power_resources': dict(),
+ 'acpi_ps_parse_aml': dict(),
+ # filesystem
+ 'ext4_sync_fs': dict(),
+ # ATA
+ 'ata_eh_recover': { 'args_x86_64': {'port':'+36(%di):s32'} },
+ # i915
+ 'i915_gem_restore_gtt_mappings': dict(),
+ 'intel_opregion_setup': dict(),
+ 'intel_dp_detect': dict(),
+ 'intel_hdmi_detect': dict(),
+ 'intel_opregion_init': dict(),
+ }
+ kprobes_postresume = [
+ {
+ 'name': 'ataportrst',
+ 'func': 'ata_eh_recover',
+ 'args': {'port':'+36(%di):s32'},
+ 'format': 'ata{port}_port_reset',
+ 'mask': 'ata.*_port_reset'
+ }
+ ]
+ kprobes = dict()
+ timeformat = '%.3f'
def __init__(self):
+ # if this is a phoronix test run, set some default options
+ if('LOG_FILE' in os.environ and 'TEST_RESULTS_IDENTIFIER' in os.environ):
+ self.embedded = True
+ self.addlogs = True
+ self.htmlfile = os.environ['LOG_FILE']
self.hostname = platform.node()
if(self.hostname == ''):
self.hostname = 'localhost'
@@ -118,6 +208,12 @@ class SystemValues:
if os.path.exists(rtc) and os.path.exists(rtc+'/date') and \
os.path.exists(rtc+'/time') and os.path.exists(rtc+'/wakealarm'):
self.rtcpath = rtc
+ if (hasattr(sys.stdout, 'isatty') and sys.stdout.isatty()):
+ self.ansi = True
+ def setPrecision(self, num):
+ if num < 0 or num > 6:
+ return
+ self.timeformat = '%.{0}f'.format(num)
def setOutputFile(self):
if((self.htmlfile == '') and (self.dmesgfile != '')):
m = re.match('(?P<name>.*)_dmesg\.txt$', self.dmesgfile)
@@ -129,32 +225,37 @@ class SystemValues:
self.htmlfile = m.group('name')+'.html'
if(self.htmlfile == ''):
self.htmlfile = 'output.html'
- def initTestOutput(self, subdir):
- if(not self.android):
- self.prefix = self.hostname
- v = open('/proc/version', 'r').read().strip()
- kver = string.split(v)[2]
- else:
- self.prefix = 'android'
- v = os.popen(self.adb+' shell cat /proc/version').read().strip()
- kver = string.split(v)[2]
- testtime = datetime.now().strftime('suspend-%m%d%y-%H%M%S')
+ def initTestOutput(self, subdir, testpath=''):
+ self.prefix = self.hostname
+ v = open('/proc/version', 'r').read().strip()
+ kver = string.split(v)[2]
+ n = datetime.now()
+ testtime = n.strftime('suspend-%m%d%y-%H%M%S')
+ if not testpath:
+ testpath = n.strftime('suspend-%y%m%d-%H%M%S')
if(subdir != "."):
- self.testdir = subdir+"/"+testtime
+ self.testdir = subdir+"/"+testpath
else:
- self.testdir = testtime
+ self.testdir = testpath
self.teststamp = \
'# '+testtime+' '+self.prefix+' '+self.suspendmode+' '+kver
+ if(self.embedded):
+ self.dmesgfile = \
+ '/tmp/'+testtime+'_'+self.suspendmode+'_dmesg.txt'
+ self.ftracefile = \
+ '/tmp/'+testtime+'_'+self.suspendmode+'_ftrace.txt'
+ return
self.dmesgfile = \
self.testdir+'/'+self.prefix+'_'+self.suspendmode+'_dmesg.txt'
self.ftracefile = \
self.testdir+'/'+self.prefix+'_'+self.suspendmode+'_ftrace.txt'
self.htmlfile = \
self.testdir+'/'+self.prefix+'_'+self.suspendmode+'.html'
- os.mkdir(self.testdir)
+ if not os.path.isdir(self.testdir):
+ os.mkdir(self.testdir)
def setDeviceFilter(self, devnames):
self.devicefilter = string.split(devnames)
- def rtcWakeAlarm(self):
+ def rtcWakeAlarmOn(self):
os.system('echo 0 > '+self.rtcpath+'/wakealarm')
outD = open(self.rtcpath+'/date', 'r').read().strip()
outT = open(self.rtcpath+'/time', 'r').read().strip()
@@ -172,9 +273,361 @@ class SystemValues:
nowtime = int(datetime.now().strftime('%s'))
alarm = nowtime + self.rtcwaketime
os.system('echo %d > %s/wakealarm' % (alarm, self.rtcpath))
+ def rtcWakeAlarmOff(self):
+ os.system('echo 0 > %s/wakealarm' % self.rtcpath)
+ def initdmesg(self):
+ # get the latest time stamp from the dmesg log
+ fp = os.popen('dmesg')
+ ktime = '0'
+ for line in fp:
+ line = line.replace('\r\n', '')
+ idx = line.find('[')
+ if idx > 1:
+ line = line[idx:]
+ m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line)
+ if(m):
+ ktime = m.group('ktime')
+ fp.close()
+ self.dmesgstart = float(ktime)
+ def getdmesg(self):
+ # store all new dmesg lines since initdmesg was called
+ fp = os.popen('dmesg')
+ op = open(self.dmesgfile, 'a')
+ for line in fp:
+ line = line.replace('\r\n', '')
+ idx = line.find('[')
+ if idx > 1:
+ line = line[idx:]
+ m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line)
+ if(not m):
+ continue
+ ktime = float(m.group('ktime'))
+ if ktime > self.dmesgstart:
+ op.write(line)
+ fp.close()
+ op.close()
+ def addFtraceFilterFunctions(self, file):
+ fp = open(file)
+ list = fp.read().split('\n')
+ fp.close()
+ for i in list:
+ if len(i) < 2:
+ continue
+ self.tracefuncs[i] = dict()
+ def getFtraceFilterFunctions(self, current):
+ rootCheck(True)
+ if not current:
+ os.system('cat '+self.tpath+'available_filter_functions')
+ return
+ fp = open(self.tpath+'available_filter_functions')
+ master = fp.read().split('\n')
+ fp.close()
+ if len(self.debugfuncs) > 0:
+ for i in self.debugfuncs:
+ if i in master:
+ print i
+ else:
+ print self.colorText(i)
+ else:
+ for i in self.tracefuncs:
+ if 'func' in self.tracefuncs[i]:
+ i = self.tracefuncs[i]['func']
+ if i in master:
+ print i
+ else:
+ print self.colorText(i)
+ def setFtraceFilterFunctions(self, list):
+ fp = open(self.tpath+'available_filter_functions')
+ master = fp.read().split('\n')
+ fp.close()
+ flist = ''
+ for i in list:
+ if i not in master:
+ continue
+ if ' [' in i:
+ flist += i.split(' ')[0]+'\n'
+ else:
+ flist += i+'\n'
+ fp = open(self.tpath+'set_graph_function', 'w')
+ fp.write(flist)
+ fp.close()
+ def kprobeMatch(self, name, target):
+ if name not in self.kprobes:
+ return False
+ if re.match(self.kprobes[name]['mask'], target):
+ return True
+ return False
+ def basicKprobe(self, name):
+ self.kprobes[name] = {'name': name,'func': name,'args': dict(),'format': name,'mask': name}
+ def defaultKprobe(self, name, kdata):
+ k = kdata
+ for field in ['name', 'format', 'mask', 'func']:
+ if field not in k:
+ k[field] = name
+ archargs = 'args_'+platform.machine()
+ if archargs in k:
+ k['args'] = k[archargs]
+ else:
+ k['args'] = dict()
+ k['format'] = name
+ self.kprobes[name] = k
+ def kprobeColor(self, name):
+ if name not in self.kprobes or 'color' not in self.kprobes[name]:
+ return ''
+ return self.kprobes[name]['color']
+ def kprobeDisplayName(self, name, dataraw):
+ if name not in self.kprobes:
+ self.basicKprobe(name)
+ data = ''
+ quote=0
+ # first remvoe any spaces inside quotes, and the quotes
+ for c in dataraw:
+ if c == '"':
+ quote = (quote + 1) % 2
+ if quote and c == ' ':
+ data += '_'
+ elif c != '"':
+ data += c
+ fmt, args = self.kprobes[name]['format'], self.kprobes[name]['args']
+ arglist = dict()
+ # now process the args
+ for arg in sorted(args):
+ arglist[arg] = ''
+ m = re.match('.* '+arg+'=(?P<arg>.*) ', data);
+ if m:
+ arglist[arg] = m.group('arg')
+ else:
+ m = re.match('.* '+arg+'=(?P<arg>.*)', data);
+ if m:
+ arglist[arg] = m.group('arg')
+ out = fmt.format(**arglist)
+ out = out.replace(' ', '_').replace('"', '')
+ return out
+ def kprobeText(self, kprobe):
+ name, fmt, func, args = kprobe['name'], kprobe['format'], kprobe['func'], kprobe['args']
+ if re.findall('{(?P<n>[a-z,A-Z,0-9]*)}', func):
+ doError('Kprobe "%s" has format info in the function name "%s"' % (name, func), False)
+ for arg in re.findall('{(?P<n>[a-z,A-Z,0-9]*)}', fmt):
+ if arg not in args:
+ doError('Kprobe "%s" is missing argument "%s"' % (name, arg), False)
+ val = 'p:%s_cal %s' % (name, func)
+ for i in sorted(args):
+ val += ' %s=%s' % (i, args[i])
+ val += '\nr:%s_ret %s $retval\n' % (name, func)
+ return val
+ def addKprobes(self):
+ # first test each kprobe
+ print('INITIALIZING KPROBES...')
+ rejects = []
+ for name in sorted(self.kprobes):
+ if not self.testKprobe(self.kprobes[name]):
+ rejects.append(name)
+ # remove all failed ones from the list
+ for name in rejects:
+ vprint('Skipping KPROBE: %s' % name)
+ self.kprobes.pop(name)
+ self.fsetVal('', 'kprobe_events')
+ kprobeevents = ''
+ # set the kprobes all at once
+ for kp in self.kprobes:
+ val = self.kprobeText(self.kprobes[kp])
+ vprint('Adding KPROBE: %s\n%s' % (kp, val.strip()))
+ kprobeevents += self.kprobeText(self.kprobes[kp])
+ self.fsetVal(kprobeevents, 'kprobe_events')
+ # verify that the kprobes were set as ordered
+ check = self.fgetVal('kprobe_events')
+ linesout = len(kprobeevents.split('\n'))
+ linesack = len(check.split('\n'))
+ if linesack < linesout:
+ # if not, try appending the kprobes 1 by 1
+ for kp in self.kprobes:
+ kprobeevents = self.kprobeText(self.kprobes[kp])
+ self.fsetVal(kprobeevents, 'kprobe_events', 'a')
+ self.fsetVal('1', 'events/kprobes/enable')
+ def testKprobe(self, kprobe):
+ kprobeevents = self.kprobeText(kprobe)
+ if not kprobeevents:
+ return False
+ try:
+ self.fsetVal(kprobeevents, 'kprobe_events')
+ check = self.fgetVal('kprobe_events')
+ except:
+ return False
+ linesout = len(kprobeevents.split('\n'))
+ linesack = len(check.split('\n'))
+ if linesack < linesout:
+ return False
+ return True
+ def fsetVal(self, val, path, mode='w'):
+ file = self.tpath+path
+ if not os.path.exists(file):
+ return False
+ try:
+ fp = open(file, mode)
+ fp.write(val)
+ fp.close()
+ except:
+ pass
+ return True
+ def fgetVal(self, path):
+ file = self.tpath+path
+ res = ''
+ if not os.path.exists(file):
+ return res
+ try:
+ fp = open(file, 'r')
+ res = fp.read()
+ fp.close()
+ except:
+ pass
+ return res
+ def cleanupFtrace(self):
+ if(self.usecallgraph or self.usetraceevents):
+ self.fsetVal('0', 'events/kprobes/enable')
+ self.fsetVal('', 'kprobe_events')
+ def setupAllKprobes(self):
+ for name in self.tracefuncs:
+ self.defaultKprobe(name, self.tracefuncs[name])
+ for name in self.dev_tracefuncs:
+ self.defaultKprobe(name, self.dev_tracefuncs[name])
+ def isCallgraphFunc(self, name):
+ if len(self.debugfuncs) < 1 and self.suspendmode == 'command':
+ return True
+ if name in self.debugfuncs:
+ return True
+ funclist = []
+ for i in self.tracefuncs:
+ if 'func' in self.tracefuncs[i]:
+ funclist.append(self.tracefuncs[i]['func'])
+ else:
+ funclist.append(i)
+ if name in funclist:
+ return True
+ return False
+ def initFtrace(self, testing=False):
+ tp = self.tpath
+ print('INITIALIZING FTRACE...')
+ # turn trace off
+ self.fsetVal('0', 'tracing_on')
+ self.cleanupFtrace()
+ # set the trace clock to global
+ self.fsetVal('global', 'trace_clock')
+ # set trace buffer to a huge value
+ self.fsetVal('nop', 'current_tracer')
+ self.fsetVal('100000', 'buffer_size_kb')
+ # go no further if this is just a status check
+ if testing:
+ return
+ if self.usekprobes:
+ # add tracefunc kprobes so long as were not using full callgraph
+ if(not self.usecallgraph or len(self.debugfuncs) > 0):
+ for name in self.tracefuncs:
+ self.defaultKprobe(name, self.tracefuncs[name])
+ if self.usedevsrc:
+ for name in self.dev_tracefuncs:
+ self.defaultKprobe(name, self.dev_tracefuncs[name])
+ else:
+ self.usedevsrc = False
+ self.addKprobes()
+ # initialize the callgraph trace, unless this is an x2 run
+ if(self.usecallgraph):
+ # set trace type
+ self.fsetVal('function_graph', 'current_tracer')
+ self.fsetVal('', 'set_ftrace_filter')
+ # set trace format options
+ self.fsetVal('print-parent', 'trace_options')
+ self.fsetVal('funcgraph-abstime', 'trace_options')
+ self.fsetVal('funcgraph-cpu', 'trace_options')
+ self.fsetVal('funcgraph-duration', 'trace_options')
+ self.fsetVal('funcgraph-proc', 'trace_options')
+ self.fsetVal('funcgraph-tail', 'trace_options')
+ self.fsetVal('nofuncgraph-overhead', 'trace_options')
+ self.fsetVal('context-info', 'trace_options')
+ self.fsetVal('graph-time', 'trace_options')
+ self.fsetVal('0', 'max_graph_depth')
+ if len(self.debugfuncs) > 0:
+ self.setFtraceFilterFunctions(self.debugfuncs)
+ elif self.suspendmode == 'command':
+ self.fsetVal('', 'set_graph_function')
+ else:
+ cf = ['dpm_run_callback']
+ if(self.usetraceeventsonly):
+ cf += ['dpm_prepare', 'dpm_complete']
+ for fn in self.tracefuncs:
+ if 'func' in self.tracefuncs[fn]:
+ cf.append(self.tracefuncs[fn]['func'])
+ else:
+ cf.append(fn)
+ self.setFtraceFilterFunctions(cf)
+ if(self.usetraceevents):
+ # turn trace events on
+ events = iter(self.traceevents)
+ for e in events:
+ self.fsetVal('1', 'events/power/'+e+'/enable')
+ # clear the trace buffer
+ self.fsetVal('', 'trace')
+ def verifyFtrace(self):
+ # files needed for any trace data
+ files = ['buffer_size_kb', 'current_tracer', 'trace', 'trace_clock',
+ 'trace_marker', 'trace_options', 'tracing_on']
+ # files needed for callgraph trace data
+ tp = self.tpath
+ if(self.usecallgraph):
+ files += [
+ 'available_filter_functions',
+ 'set_ftrace_filter',
+ 'set_graph_function'
+ ]
+ for f in files:
+ if(os.path.exists(tp+f) == False):
+ return False
+ return True
+ def verifyKprobes(self):
+ # files needed for kprobes to work
+ files = ['kprobe_events', 'events']
+ tp = self.tpath
+ for f in files:
+ if(os.path.exists(tp+f) == False):
+ return False
+ return True
+ def colorText(self, str):
+ if not self.ansi:
+ return str
+ return '\x1B[31;40m'+str+'\x1B[m'
sysvals = SystemValues()
+# Class: DevProps
+# Description:
+# Simple class which holds property values collected
+# for all the devices used in the timeline.
+class DevProps:
+ syspath = ''
+ altname = ''
+ async = True
+ xtraclass = ''
+ xtrainfo = ''
+ def out(self, dev):
+ return '%s,%s,%d;' % (dev, self.altname, self.async)
+ def debug(self, dev):
+ print '%s:\n\taltname = %s\n\t async = %s' % (dev, self.altname, self.async)
+ def altName(self, dev):
+ if not self.altname or self.altname == dev:
+ return dev
+ return '%s [%s]' % (self.altname, dev)
+ def xtraClass(self):
+ if self.xtraclass:
+ return ' '+self.xtraclass
+ if not self.async:
+ return ' sync'
+ return ''
+ def xtraInfo(self):
+ if self.xtraclass:
+ return ' '+self.xtraclass
+ if self.async:
+ return ' async'
+ return ' sync'
+
# Class: DeviceNode
# Description:
# A container used to create a device hierachy, with a single root node
@@ -228,6 +681,7 @@ class Data:
html_device_id = 0
stamp = 0
outfile = ''
+ dev_ubiquitous = ['msleep', 'udelay']
def __init__(self, num):
idchar = 'abcdefghijklmnopqrstuvwxyz'
self.testnumber = num
@@ -257,6 +711,9 @@ class Data:
'row': 0, 'color': '#FFFFCC', 'order': 9}
}
self.phases = self.sortedPhases()
+ self.devicegroups = []
+ for phase in self.phases:
+ self.devicegroups.append([phase])
def getStart(self):
return self.dmesg[self.phases[0]]['start']
def setStart(self, time):
@@ -273,51 +730,61 @@ class Data:
for dev in list:
d = list[dev]
if(d['pid'] == pid and time >= d['start'] and
- time <= d['end']):
+ time < d['end']):
return False
return True
- def addIntraDevTraceEvent(self, action, name, pid, time):
- if(action == 'mutex_lock_try'):
- color = 'red'
- elif(action == 'mutex_lock_pass'):
- color = 'green'
- elif(action == 'mutex_unlock'):
- color = 'blue'
- else:
- # create separate colors based on the name
- v1 = len(name)*10 % 256
- v2 = string.count(name, 'e')*100 % 256
- v3 = ord(name[0])*20 % 256
- color = '#%06X' % ((v1*0x10000) + (v2*0x100) + v3)
- for phase in self.phases:
- list = self.dmesg[phase]['list']
- for dev in list:
- d = list[dev]
- if(d['pid'] == pid and time >= d['start'] and
- time <= d['end']):
- e = TraceEvent(action, name, color, time)
- if('traceevents' not in d):
- d['traceevents'] = []
- d['traceevents'].append(e)
- return d
- break
- return 0
- def capIntraDevTraceEvent(self, action, name, pid, time):
- for phase in self.phases:
+ def targetDevice(self, phaselist, start, end, pid=-1):
+ tgtdev = ''
+ for phase in phaselist:
list = self.dmesg[phase]['list']
- for dev in list:
- d = list[dev]
- if(d['pid'] == pid and time >= d['start'] and
- time <= d['end']):
- if('traceevents' not in d):
- return
- for e in d['traceevents']:
- if(e.action == action and
- e.name == name and not e.ready):
- e.length = time - e.time
- e.ready = True
- break
- return
+ for devname in list:
+ dev = list[devname]
+ if(pid >= 0 and dev['pid'] != pid):
+ continue
+ devS = dev['start']
+ devE = dev['end']
+ if(start < devS or start >= devE or end <= devS or end > devE):
+ continue
+ tgtdev = dev
+ break
+ return tgtdev
+ def addDeviceFunctionCall(self, displayname, kprobename, proc, pid, start, end, cdata, rdata):
+ machstart = self.dmesg['suspend_machine']['start']
+ machend = self.dmesg['resume_machine']['end']
+ tgtdev = self.targetDevice(self.phases, start, end, pid)
+ if not tgtdev and start >= machstart and end < machend:
+ # device calls in machine phases should be serial
+ tgtdev = self.targetDevice(['suspend_machine', 'resume_machine'], start, end)
+ if not tgtdev:
+ if 'scsi_eh' in proc:
+ self.newActionGlobal(proc, start, end, pid)
+ self.addDeviceFunctionCall(displayname, kprobename, proc, pid, start, end, cdata, rdata)
+ else:
+ vprint('IGNORE: %s[%s](%d) [%f - %f] | %s | %s | %s' % (displayname, kprobename,
+ pid, start, end, cdata, rdata, proc))
+ return False
+ # detail block fits within tgtdev
+ if('src' not in tgtdev):
+ tgtdev['src'] = []
+ title = cdata+' '+rdata
+ mstr = '\(.*\) *(?P<args>.*) *\((?P<caller>.*)\+.* arg1=(?P<ret>.*)'
+ m = re.match(mstr, title)
+ if m:
+ c = m.group('caller')
+ a = m.group('args').strip()
+ r = m.group('ret')
+ if len(r) > 6:
+ r = ''
+ else:
+ r = 'ret=%s ' % r
+ l = '%0.3fms' % ((end - start) * 1000)
+ if kprobename in self.dev_ubiquitous:
+ title = '%s(%s) <- %s, %s(%s)' % (displayname, a, c, r, l)
+ else:
+ title = '%s(%s) %s(%s)' % (displayname, a, r, l)
+ e = TraceEvent(title, kprobename, start, end - start)
+ tgtdev['src'].append(e)
+ return True
def trimTimeVal(self, t, t0, dT, left):
if left:
if(t > t0):
@@ -353,11 +820,11 @@ class Data:
cg.end = self.trimTimeVal(cg.end, t0, dT, left)
for line in cg.list:
line.time = self.trimTimeVal(line.time, t0, dT, left)
- if('traceevents' in d):
- for e in d['traceevents']:
+ if('src' in d):
+ for e in d['src']:
e.time = self.trimTimeVal(e.time, t0, dT, left)
def normalizeTime(self, tZero):
- # first trim out any standby or freeze clock time
+ # trim out any standby or freeze clock time
if(self.tSuspended != self.tResumed):
if(self.tResumed > tZero):
self.trimTime(self.tSuspended, \
@@ -365,29 +832,6 @@ class Data:
else:
self.trimTime(self.tSuspended, \
self.tResumed-self.tSuspended, False)
- # shift the timeline so that tZero is the new 0
- self.tSuspended -= tZero
- self.tResumed -= tZero
- self.start -= tZero
- self.end -= tZero
- for phase in self.phases:
- p = self.dmesg[phase]
- p['start'] -= tZero
- p['end'] -= tZero
- list = p['list']
- for name in list:
- d = list[name]
- d['start'] -= tZero
- d['end'] -= tZero
- if('ftrace' in d):
- cg = d['ftrace']
- cg.start -= tZero
- cg.end -= tZero
- for line in cg.list:
- line.time -= tZero
- if('traceevents' in d):
- for e in d['traceevents']:
- e.time -= tZero
def newPhaseWithSingleAction(self, phasename, devname, start, end, color):
for phase in self.phases:
self.dmesg[phase]['order'] += 1
@@ -417,6 +861,7 @@ class Data:
{'list': list, 'start': start, 'end': end,
'row': 0, 'color': color, 'order': order}
self.phases = self.sortedPhases()
+ self.devicegroups.append([phasename])
def setPhase(self, phase, ktime, isbegin):
if(isbegin):
self.dmesg[phase]['start'] = ktime
@@ -442,7 +887,10 @@ class Data:
for devname in phaselist:
dev = phaselist[devname]
if(dev['end'] < 0):
- dev['end'] = end
+ for p in self.phases:
+ if self.dmesg[p]['end'] > dev['start']:
+ dev['end'] = self.dmesg[p]['end']
+ break
vprint('%s (%s): callback didnt return' % (devname, phase))
def deviceFilter(self, devicefilter):
# remove all by the relatives of the filter devnames
@@ -472,22 +920,58 @@ class Data:
# if any calls never returned, clip them at system resume end
for phase in self.phases:
self.fixupInitcalls(phase, self.getEnd())
- def newActionGlobal(self, name, start, end):
+ def isInsideTimeline(self, start, end):
+ if(self.start <= start and self.end > start):
+ return True
+ return False
+ def phaseOverlap(self, phases):
+ rmgroups = []
+ newgroup = []
+ for group in self.devicegroups:
+ for phase in phases:
+ if phase not in group:
+ continue
+ for p in group:
+ if p not in newgroup:
+ newgroup.append(p)
+ if group not in rmgroups:
+ rmgroups.append(group)
+ for group in rmgroups:
+ self.devicegroups.remove(group)
+ self.devicegroups.append(newgroup)
+ def newActionGlobal(self, name, start, end, pid=-1, color=''):
+ # if event starts before timeline start, expand timeline
+ if(start < self.start):
+ self.setStart(start)
+ # if event ends after timeline end, expand the timeline
+ if(end > self.end):
+ self.setEnd(end)
# which phase is this device callback or action "in"
targetphase = "none"
+ htmlclass = ''
overlap = 0.0
+ phases = []
for phase in self.phases:
pstart = self.dmesg[phase]['start']
pend = self.dmesg[phase]['end']
o = max(0, min(end, pend) - max(start, pstart))
- if(o > overlap):
+ if o > 0:
+ phases.append(phase)
+ if o > overlap:
+ if overlap > 0 and phase == 'post_resume':
+ continue
targetphase = phase
overlap = o
+ if pid == -2:
+ htmlclass = ' bg'
+ if len(phases) > 1:
+ htmlclass = ' bg'
+ self.phaseOverlap(phases)
if targetphase in self.phases:
- self.newAction(targetphase, name, -1, '', start, end, '')
- return True
+ newname = self.newAction(targetphase, name, pid, '', start, end, '', htmlclass, color)
+ return (targetphase, newname)
return False
- def newAction(self, phase, name, pid, parent, start, end, drv):
+ def newAction(self, phase, name, pid, parent, start, end, drv, htmlclass='', color=''):
# new device callback for a specific phase
self.html_device_id += 1
devid = '%s%d' % (self.idstr, self.html_device_id)
@@ -495,8 +979,19 @@ class Data:
length = -1.0
if(start >= 0 and end >= 0):
length = end - start
+ if pid == -2:
+ i = 2
+ origname = name
+ while(name in list):
+ name = '%s[%d]' % (origname, i)
+ i += 1
list[name] = {'start': start, 'end': end, 'pid': pid, 'par': parent,
'length': length, 'row': 0, 'id': devid, 'drv': drv }
+ if htmlclass:
+ list[name]['htmlclass'] = htmlclass
+ if color:
+ list[name]['color'] = color
+ return name
def deviceIDs(self, devlist, phase):
idlist = []
list = self.dmesg[phase]['list']
@@ -536,10 +1031,21 @@ class Data:
vprint(' %16s: %f - %f (%d devices)' % (phase, \
self.dmesg[phase]['start'], self.dmesg[phase]['end'], dc))
vprint(' test end: %f' % self.end)
+ def deviceChildrenAllPhases(self, devname):
+ devlist = []
+ for phase in self.phases:
+ list = self.deviceChildren(devname, phase)
+ for dev in list:
+ if dev not in devlist:
+ devlist.append(dev)
+ return devlist
def masterTopology(self, name, list, depth):
node = DeviceNode(name, depth)
for cname in list:
- clist = self.deviceChildren(cname, 'resume')
+ # avoid recursions
+ if name == cname:
+ continue
+ clist = self.deviceChildrenAllPhases(cname)
cnode = self.masterTopology(cname, clist, depth+1)
node.children.append(cnode)
return node
@@ -580,7 +1086,8 @@ class Data:
list = self.dmesg[phase]['list']
for dev in list:
pdev = list[dev]['par']
- if(re.match('[0-9]*-[0-9]*\.[0-9]*[\.0-9]*\:[\.0-9]*$', pdev)):
+ pid = list[dev]['pid']
+ if(pid < 0 or re.match('[0-9]*-[0-9]*\.[0-9]*[\.0-9]*\:[\.0-9]*$', pdev)):
continue
if pdev and pdev not in real and pdev not in rootlist:
rootlist.append(pdev)
@@ -589,22 +1096,33 @@ class Data:
rootlist = self.rootDeviceList()
master = self.masterTopology('', rootlist, 0)
return self.printTopology(master)
+ def selectTimelineDevices(self, widfmt, tTotal, mindevlen):
+ # only select devices that will actually show up in html
+ self.tdevlist = dict()
+ for phase in self.dmesg:
+ devlist = []
+ list = self.dmesg[phase]['list']
+ for dev in list:
+ length = (list[dev]['end'] - list[dev]['start']) * 1000
+ width = widfmt % (((list[dev]['end']-list[dev]['start'])*100)/tTotal)
+ if width != '0.000000' and length >= mindevlen:
+ devlist.append(dev)
+ self.tdevlist[phase] = devlist
# Class: TraceEvent
# Description:
# A container for trace event data found in the ftrace file
class TraceEvent:
- ready = False
- name = ''
+ text = ''
time = 0.0
- color = '#FFFFFF'
length = 0.0
- action = ''
- def __init__(self, a, n, c, t):
- self.action = a
- self.name = n
- self.color = c
+ title = ''
+ row = 0
+ def __init__(self, a, n, t, l):
+ self.title = a
+ self.text = n
self.time = t
+ self.length = l
# Class: FTraceLine
# Description:
@@ -623,11 +1141,14 @@ class FTraceLine:
fcall = False
freturn = False
fevent = False
+ fkprobe = False
depth = 0
name = ''
type = ''
- def __init__(self, t, m, d):
+ def __init__(self, t, m='', d=''):
self.time = float(t)
+ if not m and not d:
+ return
# is this a trace event
if(d == 'traceevent' or re.match('^ *\/\* *(?P<msg>.*) \*\/ *$', m)):
if(d == 'traceevent'):
@@ -644,6 +1165,18 @@ class FTraceLine:
self.type = emm.group('call')
else:
self.name = msg
+ km = re.match('^(?P<n>.*)_cal$', self.type)
+ if km:
+ self.fcall = True
+ self.fkprobe = True
+ self.type = km.group('n')
+ return
+ km = re.match('^(?P<n>.*)_ret$', self.type)
+ if km:
+ self.freturn = True
+ self.fkprobe = True
+ self.type = km.group('n')
+ return
self.fevent = True
return
# convert the duration to seconds
@@ -662,7 +1195,7 @@ class FTraceLine:
# includes comment with function name
match = re.match('^} *\/\* *(?P<n>.*) *\*\/$', m)
if(match):
- self.name = match.group('n')
+ self.name = match.group('n').strip()
# function call
else:
self.fcall = True
--
2.1.4
^ permalink raw reply related [flat|nested] 9+ messages in thread* [PATCH 2/5] scripts: AnalyzeSuspend v4.2 part2
2016-07-14 21:09 [PATCH 0/5] scripts: AnalyzeSuspend v4.2 Todd Brandt
2016-07-14 21:09 ` [PATCH 1/5] scripts: AnalyzeSuspend v4.2 part1 Todd Brandt
@ 2016-07-14 21:09 ` Todd Brandt
2016-07-14 21:09 ` [PATCH 3/5] scripts: AnalyzeSuspend v4.2 part3 Todd Brandt
` (3 subsequent siblings)
5 siblings, 0 replies; 9+ messages in thread
From: Todd Brandt @ 2016-07-14 21:09 UTC (permalink / raw)
To: linux-pm; +Cc: rjw, rafael.j.wysocki, todd.e.brandt, Todd Brandt
Signed-off-by: Todd Brandt <todd.e.brandt@linux.intel.com>
---
scripts/analyze_suspend.py | 911 +++++++++++++++++++++++++++++----------------
1 file changed, 590 insertions(+), 321 deletions(-)
diff --git a/scripts/analyze_suspend.py b/scripts/analyze_suspend.py
index 813681f..bc782f7 100755
--- a/scripts/analyze_suspend.py
+++ b/scripts/analyze_suspend.py
@@ -1203,19 +1203,19 @@ class FTraceLine:
if(m[-1] == '{'):
match = re.match('^(?P<n>.*) *\(.*', m)
if(match):
- self.name = match.group('n')
+ self.name = match.group('n').strip()
# function call with no children (leaf)
elif(m[-1] == ';'):
self.freturn = True
match = re.match('^(?P<n>.*) *\(.*', m)
if(match):
- self.name = match.group('n')
+ self.name = match.group('n').strip()
# something else (possibly a trace marker)
else:
self.name = m
def getDepth(self, str):
return len(str)/2
- def debugPrint(self, dev):
+ def debugPrint(self, dev=''):
if(self.freturn and self.fcall):
print('%s -- %f (%02d): %s(); (%.3f us)' % (dev, self.time, \
self.depth, self.name, self.length*1000000))
@@ -1225,6 +1225,33 @@ class FTraceLine:
else:
print('%s -- %f (%02d): %s() { (%.3f us)' % (dev, self.time, \
self.depth, self.name, self.length*1000000))
+ def startMarker(self):
+ global sysvals
+ # Is this the starting line of a suspend?
+ if not self.fevent:
+ return False
+ if sysvals.usetracemarkers:
+ if(self.name == 'SUSPEND START'):
+ return True
+ return False
+ else:
+ if(self.type == 'suspend_resume' and
+ re.match('suspend_enter\[.*\] begin', self.name)):
+ return True
+ return False
+ def endMarker(self):
+ # Is this the ending line of a resume?
+ if not self.fevent:
+ return False
+ if sysvals.usetracemarkers:
+ if(self.name == 'RESUME COMPLETE'):
+ return True
+ return False
+ else:
+ if(self.type == 'suspend_resume' and
+ re.match('thaw_processes\[.*\] end', self.name)):
+ return True
+ return False
# Class: FTraceCallGraph
# Description:
@@ -1238,54 +1265,124 @@ class FTraceCallGraph:
list = []
invalid = False
depth = 0
- def __init__(self):
+ pid = 0
+ def __init__(self, pid):
self.start = -1.0
self.end = -1.0
self.list = []
self.depth = 0
- def setDepth(self, line):
+ self.pid = pid
+ def addLine(self, line, debug=False):
+ # if this is already invalid, just leave
+ if(self.invalid):
+ return False
+ # invalidate on too much data or bad depth
+ if(len(self.list) >= 1000000 or self.depth < 0):
+ self.invalidate(line)
+ return False
+ # compare current depth with this lines pre-call depth
+ prelinedep = line.depth
+ if(line.freturn and not line.fcall):
+ prelinedep += 1
+ last = 0
+ lasttime = line.time
+ virtualfname = 'execution_misalignment'
+ if len(self.list) > 0:
+ last = self.list[-1]
+ lasttime = last.time
+ # handle low misalignments by inserting returns
+ if prelinedep < self.depth:
+ if debug and last:
+ print '-------- task %d --------' % self.pid
+ last.debugPrint()
+ idx = 0
+ # add return calls to get the depth down
+ while prelinedep < self.depth:
+ if debug:
+ print 'MISALIGN LOW (add returns): C%d - eC%d' % (self.depth, prelinedep)
+ self.depth -= 1
+ if idx == 0 and last and last.fcall and not last.freturn:
+ # special case, turn last call into a leaf
+ last.depth = self.depth
+ last.freturn = True
+ last.length = line.time - last.time
+ if debug:
+ last.debugPrint()
+ else:
+ vline = FTraceLine(lasttime)
+ vline.depth = self.depth
+ vline.name = virtualfname
+ vline.freturn = True
+ self.list.append(vline)
+ if debug:
+ vline.debugPrint()
+ idx += 1
+ if debug:
+ line.debugPrint()
+ print ''
+ # handle high misalignments by inserting calls
+ elif prelinedep > self.depth:
+ if debug and last:
+ print '-------- task %d --------' % self.pid
+ last.debugPrint()
+ idx = 0
+ # add calls to get the depth up
+ while prelinedep > self.depth:
+ if debug:
+ print 'MISALIGN HIGH (add calls): C%d - eC%d' % (self.depth, prelinedep)
+ if idx == 0 and line.freturn and not line.fcall:
+ # special case, turn this return into a leaf
+ line.fcall = True
+ prelinedep -= 1
+ else:
+ vline = FTraceLine(lasttime)
+ vline.depth = self.depth
+ vline.name = virtualfname
+ vline.fcall = True
+ if debug:
+ vline.debugPrint()
+ self.list.append(vline)
+ self.depth += 1
+ if not last:
+ self.start = vline.time
+ idx += 1
+ if debug:
+ line.debugPrint()
+ print ''
+ # process the call and set the new depth
if(line.fcall and not line.freturn):
- line.depth = self.depth
self.depth += 1
elif(line.freturn and not line.fcall):
self.depth -= 1
- line.depth = self.depth
- else:
- line.depth = self.depth
- def addLine(self, line, match):
- if(not self.invalid):
- self.setDepth(line)
+ if len(self.list) < 1:
+ self.start = line.time
+ self.list.append(line)
if(line.depth == 0 and line.freturn):
if(self.start < 0):
self.start = line.time
self.end = line.time
- self.list.append(line)
+ if line.fcall:
+ self.end += line.length
+ if self.list[0].name == virtualfname:
+ self.invalid = True
return True
- if(self.invalid):
- return False
- if(len(self.list) >= 1000000 or self.depth < 0):
- if(len(self.list) > 0):
- first = self.list[0]
- self.list = []
- self.list.append(first)
- self.invalid = True
- if(not match):
- return False
- id = 'task %s cpu %s' % (match.group('pid'), match.group('cpu'))
- window = '(%f - %f)' % (self.start, line.time)
- if(self.depth < 0):
- print('Too much data for '+id+\
- ' (buffer overflow), ignoring this callback')
- else:
- print('Too much data for '+id+\
- ' '+window+', ignoring this callback')
- return False
- self.list.append(line)
- if(self.start < 0):
- self.start = line.time
return False
+ def invalidate(self, line):
+ if(len(self.list) > 0):
+ first = self.list[0]
+ self.list = []
+ self.list.append(first)
+ self.invalid = True
+ id = 'task %s' % (self.pid)
+ window = '(%f - %f)' % (self.start, line.time)
+ if(self.depth < 0):
+ vprint('Too much data for '+id+\
+ ' (buffer overflow), ignoring this callback')
+ else:
+ vprint('Too much data for '+id+\
+ ' '+window+', ignoring this callback')
def slice(self, t0, tN):
- minicg = FTraceCallGraph()
+ minicg = FTraceCallGraph(0)
count = -1
firstdepth = 0
for l in self.list:
@@ -1297,13 +1394,26 @@ class FTraceCallGraph:
firstdepth = l.depth
count = 0
l.depth -= firstdepth
- minicg.addLine(l, 0)
+ minicg.addLine(l)
if((count == 0 and l.freturn and l.fcall) or
(count > 0 and l.depth <= 0)):
break
count += 1
return minicg
- def sanityCheck(self):
+ def repair(self, enddepth):
+ # bring the depth back to 0 with additional returns
+ fixed = False
+ last = self.list[-1]
+ for i in reversed(range(enddepth)):
+ t = FTraceLine(last.time)
+ t.depth = i
+ t.freturn = True
+ fixed = self.addLine(t)
+ if fixed:
+ self.end = last.time
+ return True
+ return False
+ def postProcess(self, debug=False):
stack = dict()
cnt = 0
for l in self.list:
@@ -1312,98 +1422,317 @@ class FTraceCallGraph:
cnt += 1
elif(l.freturn and not l.fcall):
if(l.depth not in stack):
+ if debug:
+ print 'Post Process Error: Depth missing'
+ l.debugPrint()
return False
+ # transfer total time from return line to call line
stack[l.depth].length = l.length
- stack[l.depth] = 0
+ stack.pop(l.depth)
l.length = 0
cnt -= 1
if(cnt == 0):
+ # trace caught the whole call tree
return True
- return False
- def debugPrint(self, filename):
- if(filename == 'stdout'):
- print('[%f - %f]') % (self.start, self.end)
- for l in self.list:
- if(l.freturn and l.fcall):
- print('%f (%02d): %s(); (%.3f us)' % (l.time, \
- l.depth, l.name, l.length*1000000))
- elif(l.freturn):
- print('%f (%02d): %s} (%.3f us)' % (l.time, \
- l.depth, l.name, l.length*1000000))
- else:
- print('%f (%02d): %s() { (%.3f us)' % (l.time, \
- l.depth, l.name, l.length*1000000))
- print(' ')
- else:
- fp = open(filename, 'w')
- print(filename)
- for l in self.list:
- if(l.freturn and l.fcall):
- fp.write('%f (%02d): %s(); (%.3f us)\n' % (l.time, \
- l.depth, l.name, l.length*1000000))
- elif(l.freturn):
- fp.write('%f (%02d): %s} (%.3f us)\n' % (l.time, \
- l.depth, l.name, l.length*1000000))
- else:
- fp.write('%f (%02d): %s() { (%.3f us)\n' % (l.time, \
- l.depth, l.name, l.length*1000000))
- fp.close()
+ elif(cnt < 0):
+ if debug:
+ print 'Post Process Error: Depth is less than 0'
+ return False
+ # trace ended before call tree finished
+ return self.repair(cnt)
+ def deviceMatch(self, pid, data):
+ found = False
+ # add the callgraph data to the device hierarchy
+ borderphase = {
+ 'dpm_prepare': 'suspend_prepare',
+ 'dpm_complete': 'resume_complete'
+ }
+ if(self.list[0].name in borderphase):
+ p = borderphase[self.list[0].name]
+ list = data.dmesg[p]['list']
+ for devname in list:
+ dev = list[devname]
+ if(pid == dev['pid'] and
+ self.start <= dev['start'] and
+ self.end >= dev['end']):
+ dev['ftrace'] = self.slice(dev['start'], dev['end'])
+ found = True
+ return found
+ for p in data.phases:
+ if(data.dmesg[p]['start'] <= self.start and
+ self.start <= data.dmesg[p]['end']):
+ list = data.dmesg[p]['list']
+ for devname in list:
+ dev = list[devname]
+ if(pid == dev['pid'] and
+ self.start <= dev['start'] and
+ self.end >= dev['end']):
+ dev['ftrace'] = self
+ found = True
+ break
+ break
+ return found
+ def newActionFromFunction(self, data):
+ name = self.list[0].name
+ if name in ['dpm_run_callback', 'dpm_prepare', 'dpm_complete']:
+ return
+ fs = self.start
+ fe = self.end
+ if fs < data.start or fe > data.end:
+ return
+ phase = ''
+ for p in data.phases:
+ if(data.dmesg[p]['start'] <= self.start and
+ self.start < data.dmesg[p]['end']):
+ phase = p
+ break
+ if not phase:
+ return
+ out = data.newActionGlobal(name, fs, fe, -2)
+ if out:
+ phase, myname = out
+ data.dmesg[phase]['list'][myname]['ftrace'] = self
+ def debugPrint(self):
+ print('[%f - %f] %s (%d)') % (self.start, self.end, self.list[0].name, self.pid)
+ for l in self.list:
+ if(l.freturn and l.fcall):
+ print('%f (%02d): %s(); (%.3f us)' % (l.time, \
+ l.depth, l.name, l.length*1000000))
+ elif(l.freturn):
+ print('%f (%02d): %s} (%.3f us)' % (l.time, \
+ l.depth, l.name, l.length*1000000))
+ else:
+ print('%f (%02d): %s() { (%.3f us)' % (l.time, \
+ l.depth, l.name, l.length*1000000))
+ print(' ')
# Class: Timeline
# Description:
-# A container for a suspend/resume html timeline. In older versions
-# of the script there were multiple timelines, but in the latest
-# there is only one.
+# A container for a device timeline which calculates
+# all the html properties to display it correctly
class Timeline:
html = {}
- scaleH = 0.0 # height of the row as a percent of the timeline height
- rowH = 0.0 # height of each row in percent of the timeline height
- row_height_pixels = 30
- maxrows = 0
- height = 0
- def __init__(self):
+ height = 0 # total timeline height
+ scaleH = 20 # timescale (top) row height
+ rowH = 30 # device row height
+ bodyH = 0 # body height
+ rows = 0 # total timeline rows
+ phases = []
+ rowmaxlines = dict()
+ rowcount = dict()
+ rowheight = dict()
+ def __init__(self, rowheight):
+ self.rowH = rowheight
self.html = {
+ 'header': '',
'timeline': '',
'legend': '',
- 'scale': ''
}
- def setRows(self, rows):
- self.maxrows = int(rows)
- self.scaleH = 100.0/float(self.maxrows)
- self.height = self.maxrows*self.row_height_pixels
- r = float(self.maxrows - 1)
- if(r < 1.0):
- r = 1.0
- self.rowH = (100.0 - self.scaleH)/r
+ # Function: getDeviceRows
+ # Description:
+ # determine how may rows the device funcs will take
+ # Arguments:
+ # rawlist: the list of devices/actions for a single phase
+ # Output:
+ # The total number of rows needed to display this phase of the timeline
+ def getDeviceRows(self, rawlist):
+ # clear all rows and set them to undefined
+ lendict = dict()
+ for item in rawlist:
+ item.row = -1
+ lendict[item] = item.length
+ list = []
+ for i in sorted(lendict, key=lendict.get, reverse=True):
+ list.append(i)
+ remaining = len(list)
+ rowdata = dict()
+ row = 1
+ # try to pack each row with as many ranges as possible
+ while(remaining > 0):
+ if(row not in rowdata):
+ rowdata[row] = []
+ for i in list:
+ if(i.row >= 0):
+ continue
+ s = i.time
+ e = i.time + i.length
+ valid = True
+ for ritem in rowdata[row]:
+ rs = ritem.time
+ re = ritem.time + ritem.length
+ if(not (((s <= rs) and (e <= rs)) or
+ ((s >= re) and (e >= re)))):
+ valid = False
+ break
+ if(valid):
+ rowdata[row].append(i)
+ i.row = row
+ remaining -= 1
+ row += 1
+ return row
+ # Function: getPhaseRows
+ # Description:
+ # Organize the timeline entries into the smallest
+ # number of rows possible, with no entry overlapping
+ # Arguments:
+ # list: the list of devices/actions for a single phase
+ # devlist: string list of device names to use
+ # Output:
+ # The total number of rows needed to display this phase of the timeline
+ def getPhaseRows(self, dmesg, devlist):
+ # clear all rows and set them to undefined
+ remaining = len(devlist)
+ rowdata = dict()
+ row = 0
+ lendict = dict()
+ myphases = []
+ for item in devlist:
+ if item[0] not in self.phases:
+ self.phases.append(item[0])
+ if item[0] not in myphases:
+ myphases.append(item[0])
+ self.rowmaxlines[item[0]] = dict()
+ self.rowheight[item[0]] = dict()
+ dev = dmesg[item[0]]['list'][item[1]]
+ dev['row'] = -1
+ lendict[item] = float(dev['end']) - float(dev['start'])
+ if 'src' in dev:
+ dev['devrows'] = self.getDeviceRows(dev['src'])
+ lenlist = []
+ for i in sorted(lendict, key=lendict.get, reverse=True):
+ lenlist.append(i)
+ orderedlist = []
+ for item in lenlist:
+ dev = dmesg[item[0]]['list'][item[1]]
+ if dev['pid'] == -2:
+ orderedlist.append(item)
+ for item in lenlist:
+ if item not in orderedlist:
+ orderedlist.append(item)
+ # try to pack each row with as many ranges as possible
+ while(remaining > 0):
+ rowheight = 1
+ if(row not in rowdata):
+ rowdata[row] = []
+ for item in orderedlist:
+ dev = dmesg[item[0]]['list'][item[1]]
+ if(dev['row'] < 0):
+ s = dev['start']
+ e = dev['end']
+ valid = True
+ for ritem in rowdata[row]:
+ rs = ritem['start']
+ re = ritem['end']
+ if(not (((s <= rs) and (e <= rs)) or
+ ((s >= re) and (e >= re)))):
+ valid = False
+ break
+ if(valid):
+ rowdata[row].append(dev)
+ dev['row'] = row
+ remaining -= 1
+ if 'devrows' in dev and dev['devrows'] > rowheight:
+ rowheight = dev['devrows']
+ for phase in myphases:
+ self.rowmaxlines[phase][row] = rowheight
+ self.rowheight[phase][row] = rowheight * self.rowH
+ row += 1
+ if(row > self.rows):
+ self.rows = int(row)
+ for phase in myphases:
+ self.rowcount[phase] = row
+ return row
+ def phaseRowHeight(self, phase, row):
+ return self.rowheight[phase][row]
+ def phaseRowTop(self, phase, row):
+ top = 0
+ for i in sorted(self.rowheight[phase]):
+ if i >= row:
+ break
+ top += self.rowheight[phase][i]
+ return top
+ # Function: calcTotalRows
+ # Description:
+ # Calculate the heights and offsets for the header and rows
+ def calcTotalRows(self):
+ maxrows = 0
+ standardphases = []
+ for phase in self.phases:
+ total = 0
+ for i in sorted(self.rowmaxlines[phase]):
+ total += self.rowmaxlines[phase][i]
+ if total > maxrows:
+ maxrows = total
+ if total == self.rowcount[phase]:
+ standardphases.append(phase)
+ self.height = self.scaleH + (maxrows*self.rowH)
+ self.bodyH = self.height - self.scaleH
+ for phase in standardphases:
+ for i in sorted(self.rowheight[phase]):
+ self.rowheight[phase][i] = self.bodyH/self.rowcount[phase]
+ # Function: createTimeScale
+ # Description:
+ # Create the timescale for a timeline block
+ # Arguments:
+ # m0: start time (mode begin)
+ # mMax: end time (mode end)
+ # tTotal: total timeline time
+ # mode: suspend or resume
+ # Output:
+ # The html code needed to display the time scale
+ def createTimeScale(self, m0, mMax, tTotal, mode):
+ timescale = '<div class="t" style="right:{0}%">{1}</div>\n'
+ rline = '<div class="t" style="left:0;border-left:1px solid black;border-right:0;">Resume</div>\n'
+ output = '<div class="timescale">\n'
+ # set scale for timeline
+ mTotal = mMax - m0
+ tS = 0.1
+ if(tTotal <= 0):
+ return output+'</div>\n'
+ if(tTotal > 4):
+ tS = 1
+ divTotal = int(mTotal/tS) + 1
+ divEdge = (mTotal - tS*(divTotal-1))*100/mTotal
+ for i in range(divTotal):
+ htmlline = ''
+ if(mode == 'resume'):
+ pos = '%0.3f' % (100 - ((float(i)*tS*100)/mTotal))
+ val = '%0.fms' % (float(i)*tS*1000)
+ htmlline = timescale.format(pos, val)
+ if(i == 0):
+ htmlline = rline
+ else:
+ pos = '%0.3f' % (100 - ((float(i)*tS*100)/mTotal) - divEdge)
+ val = '%0.fms' % (float(i-divTotal+1)*tS*1000)
+ if(i == divTotal - 1):
+ val = 'Suspend'
+ htmlline = timescale.format(pos, val)
+ output += htmlline
+ output += '</div>\n'
+ return output
-# Class: TestRun
+# Class: TestProps
# Description:
-# A container for a suspend/resume test run. This is necessary as
-# there could be more than one, and they need to be separate.
-class TestRun:
+# A list of values describing the properties of these test runs
+class TestProps:
+ stamp = ''
+ tracertype = ''
+ S0i3 = False
+ fwdata = []
ftrace_line_fmt_fg = \
'^ *(?P<time>[0-9\.]*) *\| *(?P<cpu>[0-9]*)\)'+\
' *(?P<proc>.*)-(?P<pid>[0-9]*) *\|'+\
- '[ +!]*(?P<dur>[0-9\.]*) .*\| (?P<msg>.*)'
+ '[ +!#\*@$]*(?P<dur>[0-9\.]*) .*\| (?P<msg>.*)'
ftrace_line_fmt_nop = \
' *(?P<proc>.*)-(?P<pid>[0-9]*) *\[(?P<cpu>[0-9]*)\] *'+\
'(?P<flags>.{4}) *(?P<time>[0-9\.]*): *'+\
'(?P<msg>.*)'
ftrace_line_fmt = ftrace_line_fmt_nop
cgformat = False
- ftemp = dict()
- ttemp = dict()
- inthepipe = False
- tracertype = ''
data = 0
- def __init__(self, dataobj):
- self.data = dataobj
- self.ftemp = dict()
- self.ttemp = dict()
- def isReady(self):
- if(tracertype == '' or not data):
- return False
- return True
+ ktemp = dict()
+ def __init__(self):
+ self.ktemp = dict()
def setTracerType(self, tracer):
self.tracertype = tracer
if(tracer == 'function_graph'):
@@ -1414,6 +1743,19 @@ class TestRun:
else:
doError('Invalid tracer format: [%s]' % tracer, False)
+# Class: TestRun
+# Description:
+# A container for a suspend/resume test run. This is necessary as
+# there could be more than one, and they need to be separate.
+class TestRun:
+ ftemp = dict()
+ ttemp = dict()
+ data = 0
+ def __init__(self, dataobj):
+ self.data = dataobj
+ self.ftemp = dict()
+ self.ttemp = dict()
+
# ----------------- FUNCTIONS --------------------
# Function: vprint
@@ -1426,104 +1768,16 @@ def vprint(msg):
if(sysvals.verbose):
print(msg)
-# Function: initFtrace
-# Description:
-# Configure ftrace to use trace events and/or a callgraph
-def initFtrace():
- global sysvals
-
- tp = sysvals.tpath
- cf = 'dpm_run_callback'
- if(sysvals.usetraceeventsonly):
- cf = '-e dpm_prepare -e dpm_complete -e dpm_run_callback'
- if(sysvals.usecallgraph or sysvals.usetraceevents):
- print('INITIALIZING FTRACE...')
- # turn trace off
- os.system('echo 0 > '+tp+'tracing_on')
- # set the trace clock to global
- os.system('echo global > '+tp+'trace_clock')
- # set trace buffer to a huge value
- os.system('echo nop > '+tp+'current_tracer')
- os.system('echo 100000 > '+tp+'buffer_size_kb')
- # initialize the callgraph trace, unless this is an x2 run
- if(sysvals.usecallgraph and sysvals.execcount == 1):
- # set trace type
- os.system('echo function_graph > '+tp+'current_tracer')
- os.system('echo "" > '+tp+'set_ftrace_filter')
- # set trace format options
- os.system('echo funcgraph-abstime > '+tp+'trace_options')
- os.system('echo funcgraph-proc > '+tp+'trace_options')
- # focus only on device suspend and resume
- os.system('cat '+tp+'available_filter_functions | grep '+\
- cf+' > '+tp+'set_graph_function')
- if(sysvals.usetraceevents):
- # turn trace events on
- events = iter(sysvals.traceevents)
- for e in events:
- os.system('echo 1 > '+sysvals.epath+e+'/enable')
- # clear the trace buffer
- os.system('echo "" > '+tp+'trace')
-
-# Function: initFtraceAndroid
-# Description:
-# Configure ftrace to capture trace events
-def initFtraceAndroid():
- global sysvals
-
- tp = sysvals.tpath
- if(sysvals.usetraceevents):
- print('INITIALIZING FTRACE...')
- # turn trace off
- os.system(sysvals.adb+" shell 'echo 0 > "+tp+"tracing_on'")
- # set the trace clock to global
- os.system(sysvals.adb+" shell 'echo global > "+tp+"trace_clock'")
- # set trace buffer to a huge value
- os.system(sysvals.adb+" shell 'echo nop > "+tp+"current_tracer'")
- os.system(sysvals.adb+" shell 'echo 10000 > "+tp+"buffer_size_kb'")
- # turn trace events on
- events = iter(sysvals.traceevents)
- for e in events:
- os.system(sysvals.adb+" shell 'echo 1 > "+\
- sysvals.epath+e+"/enable'")
- # clear the trace buffer
- os.system(sysvals.adb+" shell 'echo \"\" > "+tp+"trace'")
-
-# Function: verifyFtrace
-# Description:
-# Check that ftrace is working on the system
-# Output:
-# True or False
-def verifyFtrace():
- global sysvals
- # files needed for any trace data
- files = ['buffer_size_kb', 'current_tracer', 'trace', 'trace_clock',
- 'trace_marker', 'trace_options', 'tracing_on']
- # files needed for callgraph trace data
- tp = sysvals.tpath
- if(sysvals.usecallgraph):
- files += [
- 'available_filter_functions',
- 'set_ftrace_filter',
- 'set_graph_function'
- ]
- for f in files:
- if(sysvals.android):
- out = os.popen(sysvals.adb+' shell ls '+tp+f).read().strip()
- if(out != tp+f):
- return False
- else:
- if(os.path.exists(tp+f) == False):
- return False
- return True
-
# Function: parseStamp
# Description:
# Pull in the stamp comment line from the data file(s),
# create the stamp, and add it to the global sysvals object
# Arguments:
# m: the valid re.match output for the stamp line
-def parseStamp(m, data):
+def parseStamp(line, data):
global sysvals
+
+ m = re.match(sysvals.stampfmt, line)
data.stamp = {'time': '', 'host': '', 'mode': ''}
dt = datetime(int(m.group('y'))+2000, int(m.group('m')),
int(m.group('d')), int(m.group('H')), int(m.group('M')),
@@ -1532,6 +1786,7 @@ def parseStamp(m, data):
data.stamp['host'] = m.group('host')
data.stamp['mode'] = m.group('mode')
data.stamp['kernel'] = m.group('kernel')
+ sysvals.hostname = data.stamp['host']
sysvals.suspendmode = data.stamp['mode']
if not sysvals.stamp:
sysvals.stamp = data.stamp
@@ -1564,14 +1819,35 @@ def diffStamp(stamp1, stamp2):
def doesTraceLogHaveTraceEvents():
global sysvals
+ # check for kprobes
+ sysvals.usekprobes = False
+ out = os.system('grep -q "_cal: (" '+sysvals.ftracefile)
+ if(out == 0):
+ sysvals.usekprobes = True
+ # check for callgraph data on trace event blocks
+ out = os.system('grep -q "_cpu_down()" '+sysvals.ftracefile)
+ if(out == 0):
+ sysvals.usekprobes = True
+ out = os.popen('head -1 '+sysvals.ftracefile).read().replace('\n', '')
+ m = re.match(sysvals.stampfmt, out)
+ if m and m.group('mode') == 'command':
+ sysvals.usetraceeventsonly = True
+ sysvals.usetraceevents = True
+ return
+ # figure out what level of trace events are supported
sysvals.usetraceeventsonly = True
sysvals.usetraceevents = False
for e in sysvals.traceevents:
- out = os.popen('cat '+sysvals.ftracefile+' | grep "'+e+': "').read()
- if(not out):
+ out = os.system('grep -q "'+e+': " '+sysvals.ftracefile)
+ if(out != 0):
sysvals.usetraceeventsonly = False
- if(e == 'suspend_resume' and out):
+ if(e == 'suspend_resume' and out == 0):
sysvals.usetraceevents = True
+ # determine is this log is properly formatted
+ for e in ['SUSPEND START', 'RESUME COMPLETE']:
+ out = os.system('grep -q "'+e+'" '+sysvals.ftracefile)
+ if(out != 0):
+ sysvals.usetracemarkers = False
# Function: appendIncompleteTraceLog
# Description:
@@ -1588,44 +1864,42 @@ def appendIncompleteTraceLog(testruns):
# create TestRun vessels for ftrace parsing
testcnt = len(testruns)
- testidx = -1
+ testidx = 0
testrun = []
for data in testruns:
testrun.append(TestRun(data))
# extract the callgraph and traceevent data
vprint('Analyzing the ftrace data...')
+ tp = TestProps()
tf = open(sysvals.ftracefile, 'r')
+ data = 0
for line in tf:
# remove any latent carriage returns
line = line.replace('\r\n', '')
- # grab the time stamp first (signifies the start of the test run)
+ # grab the time stamp
m = re.match(sysvals.stampfmt, line)
if(m):
- testidx += 1
- parseStamp(m, testrun[testidx].data)
- continue
- # pull out any firmware data
- if(re.match(sysvals.firmwarefmt, line)):
- continue
- # if we havent found a test time stamp yet keep spinning til we do
- if(testidx < 0):
+ tp.stamp = line
continue
# determine the trace data type (required for further parsing)
m = re.match(sysvals.tracertypefmt, line)
if(m):
- tracer = m.group('t')
- testrun[testidx].setTracerType(tracer)
+ tp.setTracerType(m.group('t'))
+ continue
+ # device properties line
+ if(re.match(sysvals.devpropfmt, line)):
+ devProps(line)
continue
- # parse only valid lines, if this isnt one move on
- m = re.match(testrun[testidx].ftrace_line_fmt, line)
+ # parse only valid lines, if this is not one move on
+ m = re.match(tp.ftrace_line_fmt, line)
if(not m):
continue
# gather the basic message data from the line
m_time = m.group('time')
m_pid = m.group('pid')
m_msg = m.group('msg')
- if(testrun[testidx].cgformat):
+ if(tp.cgformat):
m_param3 = m.group('dur')
else:
m_param3 = 'traceevent'
@@ -1637,119 +1911,114 @@ def appendIncompleteTraceLog(testruns):
# the line should be a call, return, or event
if(not t.fcall and not t.freturn and not t.fevent):
continue
- # only parse the ftrace data during suspend/resume
- data = testrun[testidx].data
- if(not testrun[testidx].inthepipe):
- # look for the suspend start marker
- if(t.fevent):
- if(t.name == 'SUSPEND START'):
- testrun[testidx].inthepipe = True
- data.setStart(t.time)
+ # look for the suspend start marker
+ if(t.startMarker()):
+ data = testrun[testidx].data
+ parseStamp(tp.stamp, data)
+ data.setStart(t.time)
+ continue
+ if(not data):
+ continue
+ # find the end of resume
+ if(t.endMarker()):
+ data.setEnd(t.time)
+ testidx += 1
+ if(testidx >= testcnt):
+ break
+ continue
+ # trace event processing
+ if(t.fevent):
+ # general trace events have two types, begin and end
+ if(re.match('(?P<name>.*) begin$', t.name)):
+ isbegin = True
+ elif(re.match('(?P<name>.*) end$', t.name)):
+ isbegin = False
+ else:
continue
- else:
- # trace event processing
- if(t.fevent):
- if(t.name == 'RESUME COMPLETE'):
- testrun[testidx].inthepipe = False
- data.setEnd(t.time)
- if(testidx == testcnt - 1):
- break
- continue
- # general trace events have two types, begin and end
- if(re.match('(?P<name>.*) begin$', t.name)):
- isbegin = True
- elif(re.match('(?P<name>.*) end$', t.name)):
- isbegin = False
+ m = re.match('(?P<name>.*)\[(?P<val>[0-9]*)\] .*', t.name)
+ if(m):
+ val = m.group('val')
+ if val == '0':
+ name = m.group('name')
else:
- continue
- m = re.match('(?P<name>.*)\[(?P<val>[0-9]*)\] .*', t.name)
- if(m):
- val = m.group('val')
- if val == '0':
- name = m.group('name')
- else:
- name = m.group('name')+'['+val+']'
+ name = m.group('name')+'['+val+']'
+ else:
+ m = re.match('(?P<name>.*) .*', t.name)
+ name = m.group('name')
+ # special processing for trace events
+ if re.match('dpm_prepare\[.*', name):
+ continue
+ elif re.match('machine_suspend.*', name):
+ continue
+ elif re.match('suspend_enter\[.*', name):
+ if(not isbegin):
+ data.dmesg['suspend_prepare']['end'] = t.time
+ continue
+ elif re.match('dpm_suspend\[.*', name):
+ if(not isbegin):
+ data.dmesg['suspend']['end'] = t.time
+ continue
+ elif re.match('dpm_suspend_late\[.*', name):
+ if(isbegin):
+ data.dmesg['suspend_late']['start'] = t.time
else:
- m = re.match('(?P<name>.*) .*', t.name)
- name = m.group('name')
- # special processing for trace events
- if re.match('dpm_prepare\[.*', name):
- continue
- elif re.match('machine_suspend.*', name):
- continue
- elif re.match('suspend_enter\[.*', name):
- if(not isbegin):
- data.dmesg['suspend_prepare']['end'] = t.time
- continue
- elif re.match('dpm_suspend\[.*', name):
- if(not isbegin):
- data.dmesg['suspend']['end'] = t.time
- continue
- elif re.match('dpm_suspend_late\[.*', name):
- if(isbegin):
- data.dmesg['suspend_late']['start'] = t.time
- else:
- data.dmesg['suspend_late']['end'] = t.time
- continue
- elif re.match('dpm_suspend_noirq\[.*', name):
- if(isbegin):
- data.dmesg['suspend_noirq']['start'] = t.time
- else:
- data.dmesg['suspend_noirq']['end'] = t.time
- continue
- elif re.match('dpm_resume_noirq\[.*', name):
- if(isbegin):
- data.dmesg['resume_machine']['end'] = t.time
- data.dmesg['resume_noirq']['start'] = t.time
- else:
- data.dmesg['resume_noirq']['end'] = t.time
- continue
- elif re.match('dpm_resume_early\[.*', name):
- if(isbegin):
- data.dmesg['resume_early']['start'] = t.time
- else:
- data.dmesg['resume_early']['end'] = t.time
- continue
- elif re.match('dpm_resume\[.*', name):
- if(isbegin):
- data.dmesg['resume']['start'] = t.time
- else:
- data.dmesg['resume']['end'] = t.time
- continue
- elif re.match('dpm_complete\[.*', name):
- if(isbegin):
- data.dmesg['resume_complete']['start'] = t.time
- else:
- data.dmesg['resume_complete']['end'] = t.time
- continue
- # is this trace event outside of the devices calls
- if(data.isTraceEventOutsideDeviceCalls(pid, t.time)):
- # global events (outside device calls) are simply graphed
- if(isbegin):
- # store each trace event in ttemp
- if(name not in testrun[testidx].ttemp):
- testrun[testidx].ttemp[name] = []
- testrun[testidx].ttemp[name].append(\
- {'begin': t.time, 'end': t.time})
- else:
- # finish off matching trace event in ttemp
- if(name in testrun[testidx].ttemp):
- testrun[testidx].ttemp[name][-1]['end'] = t.time
+ data.dmesg['suspend_late']['end'] = t.time
+ continue
+ elif re.match('dpm_suspend_noirq\[.*', name):
+ if(isbegin):
+ data.dmesg['suspend_noirq']['start'] = t.time
else:
- if(isbegin):
- data.addIntraDevTraceEvent('', name, pid, t.time)
- else:
- data.capIntraDevTraceEvent('', name, pid, t.time)
- # call/return processing
- elif sysvals.usecallgraph:
- # create a callgraph object for the data
- if(pid not in testrun[testidx].ftemp):
- testrun[testidx].ftemp[pid] = []
- testrun[testidx].ftemp[pid].append(FTraceCallGraph())
- # when the call is finished, see which device matches it
- cg = testrun[testidx].ftemp[pid][-1]
- if(cg.addLine(t, m)):
- testrun[testidx].ftemp[pid].append(FTraceCallGraph())
+ data.dmesg['suspend_noirq']['end'] = t.time
+ continue
+ elif re.match('dpm_resume_noirq\[.*', name):
+ if(isbegin):
+ data.dmesg['resume_machine']['end'] = t.time
+ data.dmesg['resume_noirq']['start'] = t.time
+ else:
+ data.dmesg['resume_noirq']['end'] = t.time
+ continue
+ elif re.match('dpm_resume_early\[.*', name):
+ if(isbegin):
+ data.dmesg['resume_early']['start'] = t.time
+ else:
+ data.dmesg['resume_early']['end'] = t.time
+ continue
+ elif re.match('dpm_resume\[.*', name):
+ if(isbegin):
+ data.dmesg['resume']['start'] = t.time
+ else:
+ data.dmesg['resume']['end'] = t.time
+ continue
+ elif re.match('dpm_complete\[.*', name):
+ if(isbegin):
+ data.dmesg['resume_complete']['start'] = t.time
+ else:
+ data.dmesg['resume_complete']['end'] = t.time
+ continue
+ # skip trace events inside devices calls
+ if(not data.isTraceEventOutsideDeviceCalls(pid, t.time)):
+ continue
+ # global events (outside device calls) are simply graphed
+ if(isbegin):
+ # store each trace event in ttemp
+ if(name not in testrun[testidx].ttemp):
+ testrun[testidx].ttemp[name] = []
+ testrun[testidx].ttemp[name].append(\
+ {'begin': t.time, 'end': t.time})
+ else:
+ # finish off matching trace event in ttemp
+ if(name in testrun[testidx].ttemp):
+ testrun[testidx].ttemp[name][-1]['end'] = t.time
+ # call/return processing
+ elif sysvals.usecallgraph:
+ # create a callgraph object for the data
+ if(pid not in testrun[testidx].ftemp):
+ testrun[testidx].ftemp[pid] = []
+ testrun[testidx].ftemp[pid].append(FTraceCallGraph(pid))
+ # when the call is finished, see which device matches it
+ cg = testrun[testidx].ftemp[pid][-1]
+ if(cg.addLine(t)):
+ testrun[testidx].ftemp[pid].append(FTraceCallGraph(pid))
tf.close()
for test in testrun:
--
2.1.4
^ permalink raw reply related [flat|nested] 9+ messages in thread* [PATCH 3/5] scripts: AnalyzeSuspend v4.2 part3
2016-07-14 21:09 [PATCH 0/5] scripts: AnalyzeSuspend v4.2 Todd Brandt
2016-07-14 21:09 ` [PATCH 1/5] scripts: AnalyzeSuspend v4.2 part1 Todd Brandt
2016-07-14 21:09 ` [PATCH 2/5] scripts: AnalyzeSuspend v4.2 part2 Todd Brandt
@ 2016-07-14 21:09 ` Todd Brandt
2016-07-14 21:09 ` [PATCH 4/5] scripts: AnalyzeSuspend v4.2 part4 Todd Brandt
` (2 subsequent siblings)
5 siblings, 0 replies; 9+ messages in thread
From: Todd Brandt @ 2016-07-14 21:09 UTC (permalink / raw)
To: linux-pm; +Cc: rjw, rafael.j.wysocki, todd.e.brandt, Todd Brandt
Signed-off-by: Todd Brandt <todd.e.brandt@linux.intel.com>
---
scripts/analyze_suspend.py | 906 ++++++++++++++++++++++++++-------------------
1 file changed, 530 insertions(+), 376 deletions(-)
diff --git a/scripts/analyze_suspend.py b/scripts/analyze_suspend.py
index bc782f7..c9c477e 100755
--- a/scripts/analyze_suspend.py
+++ b/scripts/analyze_suspend.py
@@ -2026,20 +2026,14 @@ def appendIncompleteTraceLog(testruns):
if(sysvals.usetraceevents):
for name in test.ttemp:
for event in test.ttemp[name]:
- begin = event['begin']
- end = event['end']
- # if event starts before timeline start, expand timeline
- if(begin < test.data.start):
- test.data.setStart(begin)
- # if event ends after timeline end, expand the timeline
- if(end > test.data.end):
- test.data.setEnd(end)
- test.data.newActionGlobal(name, begin, end)
+ test.data.newActionGlobal(name, event['begin'], event['end'])
# add the callgraph data to the device hierarchy
for pid in test.ftemp:
for cg in test.ftemp[pid]:
- if(not cg.sanityCheck()):
+ if len(cg.list) < 1 or cg.invalid:
+ continue
+ if(not cg.postProcess()):
id = 'task %s cpu %s' % (pid, m.group('cpu'))
vprint('Sanity check failed for '+\
id+', ignoring this callback')
@@ -2061,14 +2055,6 @@ def appendIncompleteTraceLog(testruns):
if(sysvals.verbose):
test.data.printDetails()
-
- # add the time in between the tests as a new phase so we can see it
- if(len(testruns) > 1):
- t1e = testruns[0].getEnd()
- t2s = testruns[-1].getStart()
- testruns[-1].newPhaseWithSingleAction('user mode', \
- 'user mode', t1e, t2s, '#FF9966')
-
# Function: parseTraceLog
# Description:
# Analyze an ftrace log output file generated from this app during
@@ -2082,9 +2068,16 @@ def parseTraceLog():
vprint('Analyzing the ftrace data...')
if(os.path.exists(sysvals.ftracefile) == False):
- doError('%s doesnt exist' % sysvals.ftracefile, False)
+ doError('%s does not exist' % sysvals.ftracefile, False)
+
+ sysvals.setupAllKprobes()
+ tracewatch = ['suspend_enter']
+ if sysvals.usekprobes:
+ tracewatch += ['sync_filesystems', 'freeze_processes', 'syscore_suspend',
+ 'syscore_resume', 'resume_console', 'thaw_processes', 'CPU_ON', 'CPU_OFF']
# extract the callgraph and traceevent data
+ tp = TestProps()
testruns = []
testdata = []
testrun = 0
@@ -2097,27 +2090,17 @@ def parseTraceLog():
# stamp line: each stamp means a new test run
m = re.match(sysvals.stampfmt, line)
if(m):
- data = Data(len(testdata))
- testdata.append(data)
- testrun = TestRun(data)
- testruns.append(testrun)
- parseStamp(m, data)
- continue
- if(not data):
+ tp.stamp = line
continue
# firmware line: pull out any firmware data
m = re.match(sysvals.firmwarefmt, line)
if(m):
- data.fwSuspend = int(m.group('s'))
- data.fwResume = int(m.group('r'))
- if(data.fwSuspend > 0 or data.fwResume > 0):
- data.fwValid = True
+ tp.fwdata.append((int(m.group('s')), int(m.group('r'))))
continue
# tracer type line: determine the trace data type
m = re.match(sysvals.tracertypefmt, line)
if(m):
- tracer = m.group('t')
- testrun.setTracerType(tracer)
+ tp.setTracerType(m.group('t'))
continue
# post resume time line: did this test run include post-resume data
m = re.match(sysvals.postresumefmt, line)
@@ -2126,15 +2109,20 @@ def parseTraceLog():
if(t > 0):
sysvals.postresumetime = t
continue
+ # device properties line
+ if(re.match(sysvals.devpropfmt, line)):
+ devProps(line)
+ continue
# ftrace line: parse only valid lines
- m = re.match(testrun.ftrace_line_fmt, line)
+ m = re.match(tp.ftrace_line_fmt, line)
if(not m):
continue
# gather the basic message data from the line
m_time = m.group('time')
+ m_proc = m.group('proc')
m_pid = m.group('pid')
m_msg = m.group('msg')
- if(testrun.cgformat):
+ if(tp.cgformat):
m_param3 = m.group('dur')
else:
m_param3 = 'traceevent'
@@ -2146,24 +2134,38 @@ def parseTraceLog():
# the line should be a call, return, or event
if(not t.fcall and not t.freturn and not t.fevent):
continue
- # only parse the ftrace data during suspend/resume
- if(not testrun.inthepipe):
- # look for the suspend start marker
- if(t.fevent):
- if(t.name == 'SUSPEND START'):
- testrun.inthepipe = True
- data.setStart(t.time)
+ # find the start of suspend
+ if(t.startMarker()):
+ phase = 'suspend_prepare'
+ data = Data(len(testdata))
+ testdata.append(data)
+ testrun = TestRun(data)
+ testruns.append(testrun)
+ parseStamp(tp.stamp, data)
+ if len(tp.fwdata) > data.testnumber:
+ data.fwSuspend, data.fwResume = tp.fwdata[data.testnumber]
+ if(data.fwSuspend > 0 or data.fwResume > 0):
+ data.fwValid = True
+ data.setStart(t.time)
+ continue
+ if(not data):
+ continue
+ # find the end of resume
+ if(t.endMarker()):
+ if(sysvals.usetracemarkers and sysvals.postresumetime > 0):
+ phase = 'post_resume'
+ data.newPhase(phase, t.time, t.time, '#F0F0F0', -1)
+ data.setEnd(t.time)
+ if(not sysvals.usetracemarkers):
+ # no trace markers? then quit and be sure to finish recording
+ # the event we used to trigger resume end
+ if(len(testrun.ttemp['thaw_processes']) > 0):
+ # if an entry exists, assume this is its end
+ testrun.ttemp['thaw_processes'][-1]['end'] = t.time
+ break
continue
# trace event processing
if(t.fevent):
- if(t.name == 'RESUME COMPLETE'):
- if(sysvals.postresumetime > 0):
- phase = 'post_resume'
- data.newPhase(phase, t.time, t.time, '#FF9966', -1)
- else:
- testrun.inthepipe = False
- data.setEnd(t.time)
- continue
if(phase == 'post_resume'):
data.setEnd(t.time)
if(t.type == 'suspend_resume'):
@@ -2185,8 +2187,7 @@ def parseTraceLog():
m = re.match('(?P<name>.*) .*', t.name)
name = m.group('name')
# ignore these events
- if(re.match('acpi_suspend\[.*', t.name) or
- re.match('suspend_enter\[.*', name)):
+ if(name.split('[')[0] in tracewatch):
continue
# -- phase changes --
# suspend_prepare start
@@ -2220,7 +2221,7 @@ def parseTraceLog():
data.dmesg[phase]['end'] = t.time
data.tSuspended = t.time
else:
- if(sysvals.suspendmode in ['mem', 'disk']):
+ if(sysvals.suspendmode in ['mem', 'disk'] and not tp.S0i3):
data.dmesg['suspend_machine']['end'] = t.time
data.tSuspended = t.time
phase = 'resume_machine'
@@ -2228,6 +2229,15 @@ def parseTraceLog():
data.tResumed = t.time
data.tLow = data.tResumed - data.tSuspended
continue
+ # acpi_suspend
+ elif(re.match('acpi_suspend\[.*', t.name)):
+ # acpi_suspend[0] S0i3
+ if(re.match('acpi_suspend\[0\] begin', t.name)):
+ if(sysvals.suspendmode == 'mem'):
+ tp.S0i3 = True
+ data.dmesg['suspend_machine']['end'] = t.time
+ data.tSuspended = t.time
+ continue
# resume_noirq start
elif(re.match('dpm_resume_noirq\[.*', t.name)):
phase = 'resume_noirq'
@@ -2251,30 +2261,25 @@ def parseTraceLog():
if(isbegin):
data.dmesg[phase]['start'] = t.time
continue
-
- # is this trace event outside of the devices calls
- if(data.isTraceEventOutsideDeviceCalls(pid, t.time)):
- # global events (outside device calls) are simply graphed
- if(name not in testrun.ttemp):
- testrun.ttemp[name] = []
- if(isbegin):
- # create a new list entry
- testrun.ttemp[name].append(\
- {'begin': t.time, 'end': t.time})
- else:
- if(len(testrun.ttemp[name]) > 0):
- # if an antry exists, assume this is its end
- testrun.ttemp[name][-1]['end'] = t.time
- elif(phase == 'post_resume'):
- # post resume events can just have ends
- testrun.ttemp[name].append({
- 'begin': data.dmesg[phase]['start'],
- 'end': t.time})
+ # skip trace events inside devices calls
+ if(not data.isTraceEventOutsideDeviceCalls(pid, t.time)):
+ continue
+ # global events (outside device calls) are graphed
+ if(name not in testrun.ttemp):
+ testrun.ttemp[name] = []
+ if(isbegin):
+ # create a new list entry
+ testrun.ttemp[name].append(\
+ {'begin': t.time, 'end': t.time, 'pid': pid})
else:
- if(isbegin):
- data.addIntraDevTraceEvent('', name, pid, t.time)
- else:
- data.capIntraDevTraceEvent('', name, pid, t.time)
+ if(len(testrun.ttemp[name]) > 0):
+ # if an entry exists, assume this is its end
+ testrun.ttemp[name][-1]['end'] = t.time
+ elif(phase == 'post_resume'):
+ # post resume events can just have ends
+ testrun.ttemp[name].append({
+ 'begin': data.dmesg[phase]['start'],
+ 'end': t.time})
# device callback start
elif(t.type == 'device_pm_callback_start'):
m = re.match('(?P<drv>.*) (?P<d>.*), parent: *(?P<p>.*), .*',\
@@ -2297,75 +2302,127 @@ def parseTraceLog():
dev = list[n]
dev['length'] = t.time - dev['start']
dev['end'] = t.time
+ # kprobe event processing
+ elif(t.fkprobe):
+ kprobename = t.type
+ kprobedata = t.name
+ key = (kprobename, pid)
+ # displayname is generated from kprobe data
+ displayname = ''
+ if(t.fcall):
+ displayname = sysvals.kprobeDisplayName(kprobename, kprobedata)
+ if not displayname:
+ continue
+ if(key not in tp.ktemp):
+ tp.ktemp[key] = []
+ tp.ktemp[key].append({
+ 'pid': pid,
+ 'begin': t.time,
+ 'end': t.time,
+ 'name': displayname,
+ 'cdata': kprobedata,
+ 'proc': m_proc,
+ })
+ elif(t.freturn):
+ if(key not in tp.ktemp) or len(tp.ktemp[key]) < 1:
+ continue
+ e = tp.ktemp[key][-1]
+ if e['begin'] < 0.0 or t.time - e['begin'] < 0.000001:
+ tp.ktemp[key].pop()
+ else:
+ e['end'] = t.time
+ e['rdata'] = kprobedata
# callgraph processing
elif sysvals.usecallgraph:
- # this shouldn't happen, but JIC, ignore callgraph data post-res
- if(phase == 'post_resume'):
- continue
# create a callgraph object for the data
- if(pid not in testrun.ftemp):
- testrun.ftemp[pid] = []
- testrun.ftemp[pid].append(FTraceCallGraph())
+ key = (m_proc, pid)
+ if(key not in testrun.ftemp):
+ testrun.ftemp[key] = []
+ testrun.ftemp[key].append(FTraceCallGraph(pid))
# when the call is finished, see which device matches it
- cg = testrun.ftemp[pid][-1]
- if(cg.addLine(t, m)):
- testrun.ftemp[pid].append(FTraceCallGraph())
+ cg = testrun.ftemp[key][-1]
+ if(cg.addLine(t)):
+ testrun.ftemp[key].append(FTraceCallGraph(pid))
tf.close()
+ if sysvals.suspendmode == 'command':
+ for test in testruns:
+ for p in test.data.phases:
+ if p == 'resume_complete':
+ test.data.dmesg[p]['start'] = test.data.start
+ test.data.dmesg[p]['end'] = test.data.end
+ else:
+ test.data.dmesg[p]['start'] = test.data.start
+ test.data.dmesg[p]['end'] = test.data.start
+ test.data.tSuspended = test.data.start
+ test.data.tResumed = test.data.start
+ test.data.tLow = 0
+ test.data.fwValid = False
+
for test in testruns:
# add the traceevent data to the device hierarchy
if(sysvals.usetraceevents):
+ # add actual trace funcs
for name in test.ttemp:
for event in test.ttemp[name]:
- begin = event['begin']
- end = event['end']
- # if event starts before timeline start, expand timeline
- if(begin < test.data.start):
- test.data.setStart(begin)
- # if event ends after timeline end, expand the timeline
- if(end > test.data.end):
- test.data.setEnd(end)
- test.data.newActionGlobal(name, begin, end)
-
- # add the callgraph data to the device hierarchy
- borderphase = {
- 'dpm_prepare': 'suspend_prepare',
- 'dpm_complete': 'resume_complete'
- }
- for pid in test.ftemp:
- for cg in test.ftemp[pid]:
- if len(cg.list) < 2:
- continue
- if(not cg.sanityCheck()):
- id = 'task %s cpu %s' % (pid, m.group('cpu'))
- vprint('Sanity check failed for '+\
- id+', ignoring this callback')
- continue
- callstart = cg.start
- callend = cg.end
- if(cg.list[0].name in borderphase):
- p = borderphase[cg.list[0].name]
- list = test.data.dmesg[p]['list']
- for devname in list:
- dev = list[devname]
- if(pid == dev['pid'] and
- callstart <= dev['start'] and
- callend >= dev['end']):
- dev['ftrace'] = cg.slice(dev['start'], dev['end'])
+ test.data.newActionGlobal(name, event['begin'], event['end'], event['pid'])
+ # add the kprobe based virtual tracefuncs as actual devices
+ for key in tp.ktemp:
+ name, pid = key
+ if name not in sysvals.tracefuncs:
continue
- if(cg.list[0].name != 'dpm_run_callback'):
+ for e in tp.ktemp[key]:
+ kb, ke = e['begin'], e['end']
+ if kb == ke or not test.data.isInsideTimeline(kb, ke):
+ continue
+ test.data.newActionGlobal(e['name'], kb, ke, pid)
+ # add config base kprobes and dev kprobes
+ for key in tp.ktemp:
+ name, pid = key
+ if name in sysvals.tracefuncs:
continue
- for p in test.data.phases:
- if(test.data.dmesg[p]['start'] <= callstart and
- callstart <= test.data.dmesg[p]['end']):
- list = test.data.dmesg[p]['list']
- for devname in list:
- dev = list[devname]
- if(pid == dev['pid'] and
- callstart <= dev['start'] and
- callend >= dev['end']):
- dev['ftrace'] = cg
- break
+ for e in tp.ktemp[key]:
+ kb, ke = e['begin'], e['end']
+ if kb == ke or not test.data.isInsideTimeline(kb, ke):
+ continue
+ color = sysvals.kprobeColor(e['name'])
+ if name not in sysvals.dev_tracefuncs:
+ # config base kprobe
+ test.data.newActionGlobal(e['name'], kb, ke, -2, color)
+ elif sysvals.usedevsrc:
+ # dev kprobe
+ data.addDeviceFunctionCall(e['name'], name, e['proc'], pid, kb,
+ ke, e['cdata'], e['rdata'])
+ if sysvals.usecallgraph:
+ # add the callgraph data to the device hierarchy
+ sortlist = dict()
+ for key in test.ftemp:
+ proc, pid = key
+ for cg in test.ftemp[key]:
+ if len(cg.list) < 1 or cg.invalid:
+ continue
+ if(not cg.postProcess()):
+ id = 'task %s' % (pid)
+ vprint('Sanity check failed for '+\
+ id+', ignoring this callback')
+ continue
+ # match cg data to devices
+ if sysvals.suspendmode == 'command' or not cg.deviceMatch(pid, test.data):
+ sortkey = '%f%f%d' % (cg.start, cg.end, pid)
+ sortlist[sortkey] = cg
+ # create blocks for orphan cg data
+ for sortkey in sorted(sortlist):
+ cg = sortlist[sortkey]
+ name = cg.list[0].name
+ if sysvals.isCallgraphFunc(name):
+ vprint('Callgraph found for task %d: %.3fms, %s' % (cg.pid, (cg.end - cg.start)*1000, name))
+ cg.newActionFromFunction(test.data)
+
+ if sysvals.suspendmode == 'command':
+ if(sysvals.verbose):
+ for data in testdata:
+ data.printDetails()
+ return testdata
# fill in any missing phases
for data in testdata:
@@ -2389,14 +2446,52 @@ def parseTraceLog():
if(sysvals.verbose):
data.printDetails()
- # add the time in between the tests as a new phase so we can see it
- if(len(testdata) > 1):
- t1e = testdata[0].getEnd()
- t2s = testdata[-1].getStart()
- testdata[-1].newPhaseWithSingleAction('user mode', \
- 'user mode', t1e, t2s, '#FF9966')
return testdata
+# Function: loadRawKernelLog
+# Description:
+# Load a raw kernel log that wasn't created by this tool, it might be
+# possible to extract a valid suspend/resume log
+def loadRawKernelLog(dmesgfile):
+ global sysvals
+
+ stamp = {'time': '', 'host': '', 'mode': 'mem', 'kernel': ''}
+ stamp['time'] = datetime.now().strftime('%B %d %Y, %I:%M:%S %p')
+ stamp['host'] = sysvals.hostname
+
+ testruns = []
+ data = 0
+ lf = open(dmesgfile, 'r')
+ for line in lf:
+ line = line.replace('\r\n', '')
+ idx = line.find('[')
+ if idx > 1:
+ line = line[idx:]
+ m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line)
+ if(not m):
+ continue
+ msg = m.group("msg")
+ m = re.match('PM: Syncing filesystems.*', msg)
+ if(m):
+ if(data):
+ testruns.append(data)
+ data = Data(len(testruns))
+ data.stamp = stamp
+ if(data):
+ m = re.match('.* *(?P<k>[0-9]\.[0-9]{2}\.[0-9]-.*) .*', msg)
+ if(m):
+ stamp['kernel'] = m.group('k')
+ m = re.match('PM: Preparing system for (?P<m>.*) sleep', msg)
+ if(m):
+ stamp['mode'] = m.group('m')
+ data.dmesgtext.append(line)
+ if(data):
+ testruns.append(data)
+ sysvals.stamp = stamp
+ sysvals.suspendmode = stamp['mode']
+ lf.close()
+ return testruns
+
# Function: loadKernelLog
# Description:
# [deprecated for kernel 3.15.0 or newer]
@@ -2409,9 +2504,10 @@ def loadKernelLog():
vprint('Analyzing the dmesg data...')
if(os.path.exists(sysvals.dmesgfile) == False):
- doError('%s doesnt exist' % sysvals.dmesgfile, False)
+ doError('%s does not exist' % sysvals.dmesgfile, False)
- # there can be multiple test runs in a single file delineated by stamps
+ # there can be multiple test runs in a single file
+ tp = TestProps()
testruns = []
data = 0
lf = open(sysvals.dmesgfile, 'r')
@@ -2422,35 +2518,43 @@ def loadKernelLog():
line = line[idx:]
m = re.match(sysvals.stampfmt, line)
if(m):
- if(data):
- testruns.append(data)
- data = Data(len(testruns))
- parseStamp(m, data)
- continue
- if(not data):
+ tp.stamp = line
continue
m = re.match(sysvals.firmwarefmt, line)
if(m):
- data.fwSuspend = int(m.group('s'))
- data.fwResume = int(m.group('r'))
- if(data.fwSuspend > 0 or data.fwResume > 0):
- data.fwValid = True
+ tp.fwdata.append((int(m.group('s')), int(m.group('r'))))
continue
m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line)
- if(m):
- data.dmesgtext.append(line)
- if(re.match('ACPI: resume from mwait', m.group('msg'))):
- print('NOTE: This suspend appears to be freeze rather than'+\
- ' %s, it will be treated as such' % sysvals.suspendmode)
- sysvals.suspendmode = 'freeze'
- else:
- vprint('ignoring dmesg line: %s' % line.replace('\n', ''))
- testruns.append(data)
+ if(not m):
+ continue
+ msg = m.group("msg")
+ if(re.match('PM: Syncing filesystems.*', msg)):
+ if(data):
+ testruns.append(data)
+ data = Data(len(testruns))
+ parseStamp(tp.stamp, data)
+ if len(tp.fwdata) > data.testnumber:
+ data.fwSuspend, data.fwResume = tp.fwdata[data.testnumber]
+ if(data.fwSuspend > 0 or data.fwResume > 0):
+ data.fwValid = True
+ if(re.match('ACPI: resume from mwait', msg)):
+ print('NOTE: This suspend appears to be freeze rather than'+\
+ ' %s, it will be treated as such' % sysvals.suspendmode)
+ sysvals.suspendmode = 'freeze'
+ if(not data):
+ continue
+ data.dmesgtext.append(line)
+ if(data):
+ testruns.append(data)
lf.close()
- if(not data):
- print('ERROR: analyze_suspend header missing from dmesg log')
- sys.exit()
+ if(len(testruns) < 1):
+ # bad log, but see if you can extract something meaningful anyway
+ testruns = loadRawKernelLog(sysvals.dmesgfile)
+
+ if(len(testruns) < 1):
+ doError(' dmesg log is completely unreadable: %s' \
+ % sysvals.dmesgfile, False)
# fix lines with same timestamp/function with the call and return swapped
for data in testruns:
@@ -2667,7 +2771,8 @@ def parseKernelLog(data):
actions[a] = []
actions[a].append({'begin': ktime, 'end': ktime})
if(re.match(at[a]['emsg'], msg)):
- actions[a][-1]['end'] = ktime
+ if(a in actions):
+ actions[a][-1]['end'] = ktime
# now look for CPU on/off events
if(re.match('Disabling non-boot CPUs .*', msg)):
# start of first cpu suspend
@@ -2714,15 +2819,7 @@ def parseKernelLog(data):
# fill in any actions we've found
for name in actions:
for event in actions[name]:
- begin = event['begin']
- end = event['end']
- # if event starts before timeline start, expand timeline
- if(begin < data.start):
- data.setStart(begin)
- # if event ends after timeline end, expand the timeline
- if(end > data.end):
- data.setEnd(end)
- data.newActionGlobal(name, begin, end)
+ data.newActionGlobal(name, event['begin'], event['end'])
if(sysvals.verbose):
data.printDetails()
@@ -2731,92 +2828,6 @@ def parseKernelLog(data):
data.fixupInitcallsThatDidntReturn()
return True
-# Function: setTimelineRows
-# Description:
-# Organize the timeline entries into the smallest
-# number of rows possible, with no entry overlapping
-# Arguments:
-# list: the list of devices/actions for a single phase
-# sortedkeys: cronologically sorted key list to use
-# Output:
-# The total number of rows needed to display this phase of the timeline
-def setTimelineRows(list, sortedkeys):
-
- # clear all rows and set them to undefined
- remaining = len(list)
- rowdata = dict()
- row = 0
- for item in list:
- list[item]['row'] = -1
-
- # try to pack each row with as many ranges as possible
- while(remaining > 0):
- if(row not in rowdata):
- rowdata[row] = []
- for item in sortedkeys:
- if(list[item]['row'] < 0):
- s = list[item]['start']
- e = list[item]['end']
- valid = True
- for ritem in rowdata[row]:
- rs = ritem['start']
- re = ritem['end']
- if(not (((s <= rs) and (e <= rs)) or
- ((s >= re) and (e >= re)))):
- valid = False
- break
- if(valid):
- rowdata[row].append(list[item])
- list[item]['row'] = row
- remaining -= 1
- row += 1
- return row
-
-# Function: createTimeScale
-# Description:
-# Create the timescale header for the html timeline
-# Arguments:
-# t0: start time (suspend begin)
-# tMax: end time (resume end)
-# tSuspend: time when suspend occurs, i.e. the zero time
-# Output:
-# The html code needed to display the time scale
-def createTimeScale(t0, tMax, tSuspended):
- timescale = '<div class="t" style="right:{0}%">{1}</div>\n'
- output = '<div id="timescale">\n'
-
- # set scale for timeline
- tTotal = tMax - t0
- tS = 0.1
- if(tTotal <= 0):
- return output
- if(tTotal > 4):
- tS = 1
- if(tSuspended < 0):
- for i in range(int(tTotal/tS)+1):
- pos = '%0.3f' % (100 - ((float(i)*tS*100)/tTotal))
- if(i > 0):
- val = '%0.fms' % (float(i)*tS*1000)
- else:
- val = ''
- output += timescale.format(pos, val)
- else:
- tSuspend = tSuspended - t0
- divTotal = int(tTotal/tS) + 1
- divSuspend = int(tSuspend/tS)
- s0 = (tSuspend - tS*divSuspend)*100/tTotal
- for i in range(divTotal):
- pos = '%0.3f' % (100 - ((float(i)*tS*100)/tTotal) - s0)
- if((i == 0) and (s0 < 3)):
- val = ''
- elif(i == divSuspend):
- val = 'S/R'
- else:
- val = '%0.fms' % (float(i-divSuspend)*tS*1000)
- output += timescale.format(pos, val)
- output += '</div>\n'
- return output
-
# Function: createHTMLSummarySimple
# Description:
# Create summary html file for a series of tests
@@ -2948,6 +2959,32 @@ def createHTMLSummarySimple(testruns, htmlfile):
hf.write('</body>\n</html>\n')
hf.close()
+def htmlTitle():
+ global sysvals
+ modename = {
+ 'freeze': 'Freeze (S0)',
+ 'standby': 'Standby (S1)',
+ 'mem': 'Suspend (S3)',
+ 'disk': 'Hibernate (S4)'
+ }
+ kernel = sysvals.stamp['kernel']
+ host = sysvals.hostname[0].upper()+sysvals.hostname[1:]
+ mode = sysvals.suspendmode
+ if sysvals.suspendmode in modename:
+ mode = modename[sysvals.suspendmode]
+ return host+' '+mode+' '+kernel
+
+def ordinal(value):
+ suffix = 'th'
+ if value < 10 or value > 19:
+ if value % 10 == 1:
+ suffix = 'st'
+ elif value % 10 == 2:
+ suffix = 'nd'
+ elif value % 10 == 3:
+ suffix = 'rd'
+ return '%d%s' % (value, suffix)
+
# Function: createHTML
# Description:
# Create the output html file from the resident test data
@@ -2958,6 +2995,10 @@ def createHTMLSummarySimple(testruns, htmlfile):
def createHTML(testruns):
global sysvals
+ if len(testruns) < 1:
+ print('ERROR: Not enough test data to build a timeline')
+ return
+
for data in testruns:
data.normalizeTime(testruns[-1].tSuspended)
@@ -2965,16 +3006,18 @@ def createHTML(testruns):
if len(testruns) > 1:
x2changes = ['1', 'relative']
# html function templates
+ headline_version = '<div class="version"><a href="https://01.org/suspendresume">AnalyzeSuspend v%s</a></div>' % sysvals.version
headline_stamp = '<div class="stamp">{0} {1} {2} {3}</div>\n'
html_devlist1 = '<button id="devlist1" class="devlist" style="float:left;">Device Detail%s</button>' % x2changes[0]
html_zoombox = '<center><button id="zoomin">ZOOM IN</button><button id="zoomout">ZOOM OUT</button><button id="zoomdef">ZOOM 1:1</button></center>\n'
html_devlist2 = '<button id="devlist2" class="devlist" style="float:right;">Device Detail2</button>\n'
html_timeline = '<div id="dmesgzoombox" class="zoombox">\n<div id="{0}" class="timeline" style="height:{1}px">\n'
- html_device = '<div id="{0}" title="{1}" class="thread" style="left:{2}%;top:{3}%;height:{4}%;width:{5}%;">{6}</div>\n'
- html_traceevent = '<div title="{0}" class="traceevent" style="left:{1}%;top:{2}%;height:{3}%;width:{4}%;border:1px solid {5};background-color:{5}">{6}</div>\n'
- html_phase = '<div class="phase" style="left:{0}%;width:{1}%;top:{2}%;height:{3}%;background-color:{4}">{5}</div>\n'
+ html_tblock = '<div id="block{0}" class="tblock" style="left:{1}%;width:{2}%;">\n'
+ 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'
+ 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'
+ html_phase = '<div class="phase" style="left:{0}%;width:{1}%;top:{2}px;height:{3}px;background-color:{4}">{5}</div>\n'
html_phaselet = '<div id="{0}" class="phaselet" style="left:{1}%;width:{2}%;background-color:{3}"></div>\n'
- html_legend = '<div class="square" style="left:{0}%;background-color:{1}"> {2}</div>\n'
+ html_legend = '<div id="p{3}" class="square" style="left:{0}%;background-color:{1}"> {2}</div>\n'
html_timetotal = '<table class="time1">\n<tr>'\
'<td class="green">{2} Suspend Time: <b>{0} ms</b></td>'\
'<td class="yellow">{2} Resume Time: <b>{1} ms</b></td>'\
@@ -2984,6 +3027,10 @@ def createHTML(testruns):
'<td class="gray">'+sysvals.suspendmode+' time: <b>{1} ms</b></td>'\
'<td class="yellow">{3} Resume Time: <b>{2} ms</b></td>'\
'</tr>\n</table>\n'
+ html_timetotal3 = '<table class="time1">\n<tr>'\
+ '<td class="green">Execution Time: <b>{0} ms</b></td>'\
+ '<td class="yellow">Command: <b>{1}</b></td>'\
+ '</tr>\n</table>\n'
html_timegroups = '<table class="time2">\n<tr>'\
'<td class="green">{4}Kernel Suspend: {0} ms</td>'\
'<td class="purple">{4}Firmware Suspend: {1} ms</td>'\
@@ -2991,12 +3038,21 @@ def createHTML(testruns):
'<td class="yellow">{4}Kernel Resume: {3} ms</td>'\
'</tr>\n</table>\n'
+ # html format variables
+ rowheight = 30
+ devtextS = '14px'
+ devtextH = '30px'
+ hoverZ = 'z-index:10;'
+
+ if sysvals.usedevsrc:
+ hoverZ = ''
+
# device timeline
vprint('Creating Device Timeline...')
- devtl = Timeline()
+
+ devtl = Timeline(rowheight)
# Generate the header for this timeline
- textnum = ['First', 'Second']
for data in testruns:
tTotal = data.end - data.start
tEnd = data.dmesg['resume_complete']['end']
@@ -3005,7 +3061,17 @@ def createHTML(testruns):
sys.exit()
if(data.tLow > 0):
low_time = '%.0f'%(data.tLow*1000)
- if data.fwValid:
+ if sysvals.suspendmode == 'command':
+ run_time = '%.0f'%((data.end-data.start)*1000)
+ if sysvals.testcommand:
+ testdesc = sysvals.testcommand
+ else:
+ testdesc = 'unknown'
+ if(len(testruns) > 1):
+ testdesc = ordinal(data.testnumber+1)+' '+testdesc
+ thtml = html_timetotal3.format(run_time, testdesc)
+ devtl.html['header'] += thtml
+ elif data.fwValid:
suspend_time = '%.0f'%((data.tSuspended-data.start)*1000 + \
(data.fwSuspend/1000000.0))
resume_time = '%.0f'%((tEnd-data.tSuspended)*1000 + \
@@ -3013,7 +3079,7 @@ def createHTML(testruns):
testdesc1 = 'Total'
testdesc2 = ''
if(len(testruns) > 1):
- testdesc1 = testdesc2 = textnum[data.testnumber]
+ testdesc1 = testdesc2 = ordinal(data.testnumber+1)
testdesc2 += ' '
if(data.tLow == 0):
thtml = html_timetotal.format(suspend_time, \
@@ -3021,28 +3087,28 @@ def createHTML(testruns):
else:
thtml = html_timetotal2.format(suspend_time, low_time, \
resume_time, testdesc1)
- devtl.html['timeline'] += thtml
+ devtl.html['header'] += thtml
sktime = '%.3f'%((data.dmesg['suspend_machine']['end'] - \
data.getStart())*1000)
sftime = '%.3f'%(data.fwSuspend / 1000000.0)
rftime = '%.3f'%(data.fwResume / 1000000.0)
- rktime = '%.3f'%((data.getEnd() - \
+ rktime = '%.3f'%((data.dmesg['resume_complete']['end'] - \
data.dmesg['resume_machine']['start'])*1000)
- devtl.html['timeline'] += html_timegroups.format(sktime, \
+ devtl.html['header'] += html_timegroups.format(sktime, \
sftime, rftime, rktime, testdesc2)
else:
suspend_time = '%.0f'%((data.tSuspended-data.start)*1000)
resume_time = '%.0f'%((tEnd-data.tSuspended)*1000)
testdesc = 'Kernel'
if(len(testruns) > 1):
- testdesc = textnum[data.testnumber]+' '+testdesc
+ testdesc = ordinal(data.testnumber+1)+' '+testdesc
if(data.tLow == 0):
thtml = html_timetotal.format(suspend_time, \
resume_time, testdesc)
else:
thtml = html_timetotal2.format(suspend_time, low_time, \
resume_time, testdesc)
- devtl.html['timeline'] += thtml
+ devtl.html['header'] += thtml
# time scale for potentially multiple datasets
t0 = testruns[0].start
@@ -3051,153 +3117,241 @@ def createHTML(testruns):
tTotal = tMax - t0
# determine the maximum number of rows we need to draw
- timelinerows = 0
for data in testruns:
- for phase in data.dmesg:
- list = data.dmesg[phase]['list']
- rows = setTimelineRows(list, list)
- data.dmesg[phase]['row'] = rows
- if(rows > timelinerows):
- timelinerows = rows
-
- # calculate the timeline height and create bounding box, add buttons
- devtl.setRows(timelinerows + 1)
- devtl.html['timeline'] += html_devlist1
- if len(testruns) > 1:
- devtl.html['timeline'] += html_devlist2
+ data.selectTimelineDevices('%f', tTotal, sysvals.mindevlen)
+ for group in data.devicegroups:
+ devlist = []
+ for phase in group:
+ for devname in data.tdevlist[phase]:
+ devlist.append((phase,devname))
+ devtl.getPhaseRows(data.dmesg, devlist)
+ devtl.calcTotalRows()
+
+ # create bounding box, add buttons
+ if sysvals.suspendmode != 'command':
+ devtl.html['timeline'] += html_devlist1
+ if len(testruns) > 1:
+ devtl.html['timeline'] += html_devlist2
devtl.html['timeline'] += html_zoombox
devtl.html['timeline'] += html_timeline.format('dmesg', devtl.height)
- # draw the colored boxes for each of the phases
- for data in testruns:
- for b in data.dmesg:
- phase = data.dmesg[b]
- length = phase['end']-phase['start']
- left = '%.3f' % (((phase['start']-t0)*100.0)/tTotal)
- width = '%.3f' % ((length*100.0)/tTotal)
- devtl.html['timeline'] += html_phase.format(left, width, \
- '%.3f'%devtl.scaleH, '%.3f'%(100-devtl.scaleH), \
- data.dmesg[b]['color'], '')
+ # draw the full timeline
+ phases = {'suspend':[],'resume':[]}
+ for phase in data.dmesg:
+ if 'resume' in phase:
+ phases['resume'].append(phase)
+ else:
+ phases['suspend'].append(phase)
- # draw the time scale, try to make the number of labels readable
- devtl.html['scale'] = createTimeScale(t0, tMax, tSuspended)
- devtl.html['timeline'] += devtl.html['scale']
+ # draw each test run chronologically
for data in testruns:
- for b in data.dmesg:
- phaselist = data.dmesg[b]['list']
- for d in phaselist:
- name = d
- drv = ''
- dev = phaselist[d]
- if(d in sysvals.altdevname):
- name = sysvals.altdevname[d]
- if('drv' in dev and dev['drv']):
- drv = ' {%s}' % dev['drv']
- height = (100.0 - devtl.scaleH)/data.dmesg[b]['row']
- top = '%.3f' % ((dev['row']*height) + devtl.scaleH)
- left = '%.3f' % (((dev['start']-t0)*100)/tTotal)
- width = '%.3f' % (((dev['end']-dev['start'])*100)/tTotal)
- length = ' (%0.3f ms) ' % ((dev['end']-dev['start'])*1000)
- color = 'rgba(204,204,204,0.5)'
- devtl.html['timeline'] += html_device.format(dev['id'], \
- d+drv+length+b, left, top, '%.3f'%height, width, name+drv)
-
- # draw any trace events found
- for data in testruns:
- for b in data.dmesg:
- phaselist = data.dmesg[b]['list']
- for name in phaselist:
- dev = phaselist[name]
- if('traceevents' in dev):
- vprint('Debug trace events found for device %s' % name)
- vprint('%20s %20s %10s %8s' % ('action', \
+ # if nore than one test, draw a block to represent user mode
+ if(data.testnumber > 0):
+ m0 = testruns[data.testnumber-1].end
+ mMax = testruns[data.testnumber].start
+ mTotal = mMax - m0
+ name = 'usermode%d' % data.testnumber
+ top = '%d' % devtl.scaleH
+ left = '%f' % (((m0-t0)*100.0)/tTotal)
+ width = '%f' % ((mTotal*100.0)/tTotal)
+ title = 'user mode (%0.3f ms) ' % (mTotal*1000)
+ devtl.html['timeline'] += html_device.format(name, \
+ title, left, top, '%d'%devtl.bodyH, width, '', '', '')
+ # now draw the actual timeline blocks
+ for dir in phases:
+ # draw suspend and resume blocks separately
+ bname = '%s%d' % (dir[0], data.testnumber)
+ if dir == 'suspend':
+ m0 = testruns[data.testnumber].start
+ mMax = testruns[data.testnumber].tSuspended
+ mTotal = mMax - m0
+ left = '%f' % (((m0-t0)*100.0)/tTotal)
+ else:
+ m0 = testruns[data.testnumber].tSuspended
+ mMax = testruns[data.testnumber].end
+ mTotal = mMax - m0
+ left = '%f' % ((((m0-t0)*100.0)+sysvals.srgap/2)/tTotal)
+ # if a timeline block is 0 length, skip altogether
+ if mTotal == 0:
+ continue
+ width = '%f' % (((mTotal*100.0)-sysvals.srgap/2)/tTotal)
+ devtl.html['timeline'] += html_tblock.format(bname, left, width)
+ for b in sorted(phases[dir]):
+ # draw the phase color background
+ phase = data.dmesg[b]
+ length = phase['end']-phase['start']
+ left = '%f' % (((phase['start']-m0)*100.0)/mTotal)
+ width = '%f' % ((length*100.0)/mTotal)
+ devtl.html['timeline'] += html_phase.format(left, width, \
+ '%.3f'%devtl.scaleH, '%.3f'%devtl.bodyH, \
+ data.dmesg[b]['color'], '')
+ # draw the devices for this phase
+ phaselist = data.dmesg[b]['list']
+ for d in data.tdevlist[b]:
+ name = d
+ drv = ''
+ dev = phaselist[d]
+ xtraclass = ''
+ xtrainfo = ''
+ xtrastyle = ''
+ if 'htmlclass' in dev:
+ xtraclass = dev['htmlclass']
+ xtrainfo = dev['htmlclass']
+ if 'color' in dev:
+ xtrastyle = 'background-color:%s;' % dev['color']
+ if(d in sysvals.devprops):
+ name = sysvals.devprops[d].altName(d)
+ xtraclass = sysvals.devprops[d].xtraClass()
+ xtrainfo = sysvals.devprops[d].xtraInfo()
+ if('drv' in dev and dev['drv']):
+ drv = ' {%s}' % dev['drv']
+ rowheight = devtl.phaseRowHeight(b, dev['row'])
+ rowtop = devtl.phaseRowTop(b, dev['row'])
+ top = '%.3f' % (rowtop + devtl.scaleH)
+ left = '%f' % (((dev['start']-m0)*100)/mTotal)
+ width = '%f' % (((dev['end']-dev['start'])*100)/mTotal)
+ length = ' (%0.3f ms) ' % ((dev['end']-dev['start'])*1000)
+ if sysvals.suspendmode == 'command':
+ title = name+drv+xtrainfo+length+'cmdexec'
+ else:
+ title = name+drv+xtrainfo+length+b
+ devtl.html['timeline'] += html_device.format(dev['id'], \
+ title, left, top, '%.3f'%rowheight, width, \
+ d+drv, xtraclass, xtrastyle)
+ if('src' not in dev):
+ continue
+ # draw any trace events for this device
+ vprint('Debug trace events found for device %s' % d)
+ vprint('%20s %20s %10s %8s' % ('title', \
'name', 'time(ms)', 'length(ms)'))
- for e in dev['traceevents']:
- vprint('%20s %20s %10.3f %8.3f' % (e.action, \
- e.name, e.time*1000, e.length*1000))
- height = (100.0 - devtl.scaleH)/data.dmesg[b]['row']
- top = '%.3f' % ((dev['row']*height) + devtl.scaleH)
- left = '%.3f' % (((e.time-t0)*100)/tTotal)
- width = '%.3f' % (e.length*100/tTotal)
+ for e in dev['src']:
+ vprint('%20s %20s %10.3f %8.3f' % (e.title, \
+ e.text, e.time*1000, e.length*1000))
+ height = devtl.rowH
+ top = '%.3f' % (rowtop + devtl.scaleH + (e.row*devtl.rowH))
+ left = '%f' % (((e.time-m0)*100)/mTotal)
+ width = '%f' % (e.length*100/mTotal)
color = 'rgba(204,204,204,0.5)'
devtl.html['timeline'] += \
- html_traceevent.format(e.action+' '+e.name, \
+ html_traceevent.format(e.title, \
left, top, '%.3f'%height, \
- width, e.color, '')
+ width, e.text)
+ # draw the time scale, try to make the number of labels readable
+ devtl.html['timeline'] += devtl.createTimeScale(m0, mMax, tTotal, dir)
+ devtl.html['timeline'] += '</div>\n'
# timeline is finished
devtl.html['timeline'] += '</div>\n</div>\n'
# draw a legend which describes the phases by color
- data = testruns[-1]
- devtl.html['legend'] = '<div class="legend">\n'
- pdelta = 100.0/len(data.phases)
- pmargin = pdelta / 4.0
- for phase in data.phases:
- order = '%.2f' % ((data.dmesg[phase]['order'] * pdelta) + pmargin)
- name = string.replace(phase, '_', ' ')
- devtl.html['legend'] += html_legend.format(order, \
- data.dmesg[phase]['color'], name)
- devtl.html['legend'] += '</div>\n'
+ if sysvals.suspendmode != 'command':
+ data = testruns[-1]
+ devtl.html['legend'] = '<div class="legend">\n'
+ pdelta = 100.0/len(data.phases)
+ pmargin = pdelta / 4.0
+ for phase in data.phases:
+ tmp = phase.split('_')
+ id = tmp[0][0]
+ if(len(tmp) > 1):
+ id += tmp[1][0]
+ order = '%.2f' % ((data.dmesg[phase]['order'] * pdelta) + pmargin)
+ name = string.replace(phase, '_', ' ')
+ devtl.html['legend'] += html_legend.format(order, \
+ data.dmesg[phase]['color'], name, id)
+ devtl.html['legend'] += '</div>\n'
hf = open(sysvals.htmlfile, 'w')
- thread_height = 0
+
+ if not sysvals.cgexp:
+ cgchk = 'checked'
+ cgnchk = 'not(:checked)'
+ else:
+ cgchk = 'not(:checked)'
+ cgnchk = 'checked'
# write the html header first (html head, css code, up to body start)
html_header = '<!DOCTYPE html>\n<html>\n<head>\n\
<meta http-equiv="content-type" content="text/html; charset=UTF-8">\n\
- <title>AnalyzeSuspend</title>\n\
+ <title>'+htmlTitle()+'</title>\n\
<style type=\'text/css\'>\n\
- body {overflow-y: scroll;}\n\
- .stamp {width: 100%;text-align:center;background-color:gray;line-height:30px;color:white;font: 25px Arial;}\n\
- .callgraph {margin-top: 30px;box-shadow: 5px 5px 20px black;}\n\
- .callgraph article * {padding-left: 28px;}\n\
- h1 {color:black;font: bold 30px Times;}\n\
- t0 {color:black;font: bold 30px Times;}\n\
- t1 {color:black;font: 30px Times;}\n\
- t2 {color:black;font: 25px Times;}\n\
- t3 {color:black;font: 20px Times;white-space:nowrap;}\n\
- t4 {color:black;font: bold 30px Times;line-height:60px;white-space:nowrap;}\n\
+ body {overflow-y:scroll;}\n\
+ .stamp {width:100%;text-align:center;background-color:gray;line-height:30px;color:white;font:25px Arial;}\n\
+ .callgraph {margin-top:30px;box-shadow:5px 5px 20px black;}\n\
+ .callgraph article * {padding-left:28px;}\n\
+ h1 {color:black;font:bold 30px Times;}\n\
+ t0 {color:black;font:bold 30px Times;}\n\
+ t1 {color:black;font:30px Times;}\n\
+ t2 {color:black;font:25px Times;}\n\
+ t3 {color:black;font:20px Times;white-space:nowrap;}\n\
+ t4 {color:black;font:bold 30px Times;line-height:60px;white-space:nowrap;}\n\
+ cS {color:blue;font:bold 11px Times;}\n\
+ cR {color:red;font:bold 11px Times;}\n\
table {width:100%;}\n\
.gray {background-color:rgba(80,80,80,0.1);}\n\
.green {background-color:rgba(204,255,204,0.4);}\n\
.purple {background-color:rgba(128,0,128,0.2);}\n\
.yellow {background-color:rgba(255,255,204,0.4);}\n\
- .time1 {font: 22px Arial;border:1px solid;}\n\
- .time2 {font: 15px Arial;border-bottom:1px solid;border-left:1px solid;border-right:1px solid;}\n\
- td {text-align: center;}\n\
+ .time1 {font:22px Arial;border:1px solid;}\n\
+ .time2 {font:15px Arial;border-bottom:1px solid;border-left:1px solid;border-right:1px solid;}\n\
+ td {text-align:center;}\n\
r {color:#500000;font:15px Tahoma;}\n\
n {color:#505050;font:15px Tahoma;}\n\
- .tdhl {color: red;}\n\
- .hide {display: none;}\n\
- .pf {display: none;}\n\
- .pf:checked + 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\
- .pf:not(:checked) ~ 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\
- .pf:checked ~ *:not(:nth-child(2)) {display: none;}\n\
- .zoombox {position: relative; width: 100%; overflow-x: scroll;}\n\
- .timeline {position: relative; font-size: 14px;cursor: pointer;width: 100%; overflow: hidden; background-color:#dddddd;}\n\
- .thread {position: absolute; height: '+'%.3f'%thread_height+'%; overflow: hidden; line-height: 30px; border:1px solid;text-align:center;white-space:nowrap;background-color:rgba(204,204,204,0.5);}\n\
- .thread:hover {background-color:white;border:1px solid red;z-index:10;}\n\
- .hover {background-color:white;border:1px solid red;z-index:10;}\n\
- .traceevent {position: absolute;opacity: 0.3;height: '+'%.3f'%thread_height+'%;width:0;overflow:hidden;line-height:30px;text-align:center;white-space:nowrap;}\n\
- .phase {position: absolute;overflow: hidden;border:0px;text-align:center;}\n\
+ .tdhl {color:red;}\n\
+ .hide {display:none;}\n\
+ .pf {display:none;}\n\
+ .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\
+ .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\
+ .pf:'+cgchk+' ~ *:not(:nth-child(2)) {display:none;}\n\
+ .zoombox {position:relative;width:100%;overflow-x:scroll;}\n\
+ .timeline {position:relative;font-size:14px;cursor:pointer;width:100%; overflow:hidden;background:linear-gradient(#cccccc, white);}\n\
+ .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\
+ .thread.sync {background-color:'+sysvals.synccolor+';}\n\
+ .thread.bg {background-color:'+sysvals.kprobecolor+';}\n\
+ .thread:hover {background-color:white;border:1px solid red;'+hoverZ+'}\n\
+ .hover {background-color:white;border:1px solid red;'+hoverZ+'}\n\
+ .hover.sync {background-color:white;}\n\
+ .hover.bg {background-color:white;}\n\
+ .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\
+ .traceevent:hover {background:white;}\n\
+ .phase {position:absolute;overflow:hidden;border:0px;text-align:center;}\n\
.phaselet {position:absolute;overflow:hidden;border:0px;text-align:center;height:100px;font-size:24px;}\n\
- .t {position:absolute;top:0%;height:100%;border-right:1px solid black;}\n\
- .legend {position: relative; width: 100%; height: 40px; text-align: center;margin-bottom:20px}\n\
- .legend .square {position:absolute;top:10px; width: 0px;height: 20px;border:1px solid;padding-left:20px;}\n\
+ .t {z-index:2;position:absolute;pointer-events:none;top:0%;height:100%;border-right:1px solid black;}\n\
+ .legend {position:relative; width:100%; height:40px; text-align:center;margin-bottom:20px}\n\
+ .legend .square {position:absolute;cursor:pointer;top:10px; width:0px;height:20px;border:1px solid;padding-left:20px;}\n\
button {height:40px;width:200px;margin-bottom:20px;margin-top:20px;font-size:24px;}\n\
+ .logbtn {position:relative;float:right;height:25px;width:50px;margin-top:3px;margin-bottom:0;font-size:10px;text-align:center;}\n\
.devlist {position:'+x2changes[1]+';width:190px;}\n\
- #devicedetail {height:100px;box-shadow: 5px 5px 20px black;}\n\
+ a:link {color:white;text-decoration:none;}\n\
+ a:visited {color:white;}\n\
+ a:hover {color:white;}\n\
+ a:active {color:white;}\n\
+ .version {position:relative;float:left;color:white;font-size:10px;line-height:30px;margin-left:10px;}\n\
+ #devicedetail {height:100px;box-shadow:5px 5px 20px black;}\n\
+ .tblock {position:absolute;height:100%;}\n\
+ .bg {z-index:1;}\n\
</style>\n</head>\n<body>\n'
- hf.write(html_header)
+
+ # no header or css if its embedded
+ if(sysvals.embedded):
+ hf.write('pass True tSus %.3f tRes %.3f tLow %.3f fwvalid %s tSus %.3f tRes %.3f\n' %
+ (data.tSuspended-data.start, data.end-data.tSuspended, data.tLow, data.fwValid, \
+ data.fwSuspend/1000000, data.fwResume/1000000))
+ else:
+ hf.write(html_header)
# write the test title and general info header
if(sysvals.stamp['time'] != ""):
+ hf.write(headline_version)
+ if sysvals.addlogs and sysvals.dmesgfile:
+ hf.write('<button id="showdmesg" class="logbtn">dmesg</button>')
+ if sysvals.addlogs and sysvals.ftracefile:
+ hf.write('<button id="showftrace" class="logbtn">ftrace</button>')
hf.write(headline_stamp.format(sysvals.stamp['host'],
sysvals.stamp['kernel'], sysvals.stamp['mode'], \
sysvals.stamp['time']))
# write the device timeline
+ hf.write(devtl.html['header'])
hf.write(devtl.html['timeline'])
hf.write(devtl.html['legend'])
hf.write('<div id="devicedetailtitle"></div>\n')
--
2.1.4
^ permalink raw reply related [flat|nested] 9+ messages in thread* [PATCH 4/5] scripts: AnalyzeSuspend v4.2 part4
2016-07-14 21:09 [PATCH 0/5] scripts: AnalyzeSuspend v4.2 Todd Brandt
` (2 preceding siblings ...)
2016-07-14 21:09 ` [PATCH 3/5] scripts: AnalyzeSuspend v4.2 part3 Todd Brandt
@ 2016-07-14 21:09 ` Todd Brandt
2016-07-14 21:09 ` [PATCH 5/5] scripts: AnalyzeSuspend v4.2 part5 Todd Brandt
2016-07-14 21:22 ` [PATCH 0/5] scripts: AnalyzeSuspend v4.2 Rafael J. Wysocki
5 siblings, 0 replies; 9+ messages in thread
From: Todd Brandt @ 2016-07-14 21:09 UTC (permalink / raw)
To: linux-pm; +Cc: rjw, rafael.j.wysocki, todd.e.brandt, Todd Brandt
Signed-off-by: Todd Brandt <todd.e.brandt@linux.intel.com>
---
scripts/analyze_suspend.py | 715 +++++++++++++++++++++++++++------------------
1 file changed, 437 insertions(+), 278 deletions(-)
diff --git a/scripts/analyze_suspend.py b/scripts/analyze_suspend.py
index c9c477e..b93bb07 100755
--- a/scripts/analyze_suspend.py
+++ b/scripts/analyze_suspend.py
@@ -3366,12 +3366,15 @@ def createHTML(testruns):
width = '%.3f' % ((length*100.0)/tTotal)
hf.write(html_phaselet.format(b, left, width, \
data.dmesg[b]['color']))
+ if sysvals.suspendmode == 'command':
+ hf.write(html_phaselet.format('cmdexec', '0', '0', \
+ data.dmesg['resume_complete']['color']))
hf.write('</div>\n')
hf.write('</div>\n')
# write the ftrace data (callgraph)
data = testruns[-1]
- if(sysvals.usecallgraph):
+ if(sysvals.usecallgraph and not sysvals.embedded):
hf.write('<section id="callgraphs" class="callgraph">\n')
# write out the ftrace data converted to html
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'
@@ -3384,22 +3387,29 @@ def createHTML(testruns):
for devname in data.sortedDevices(p):
if('ftrace' not in list[devname]):
continue
- name = devname
- if(devname in sysvals.altdevname):
- name = sysvals.altdevname[devname]
devid = list[devname]['id']
cg = list[devname]['ftrace']
- flen = '<r>(%.3f ms @ %.3f to %.3f)</r>' % \
- ((cg.end - cg.start)*1000, cg.start*1000, cg.end*1000)
+ clen = (cg.end - cg.start) * 1000
+ if clen < sysvals.mincglen:
+ continue
+ fmt = '<r>(%.3f ms @ '+sysvals.timeformat+' to '+sysvals.timeformat+')</r>'
+ flen = fmt % (clen, cg.start, cg.end)
+ name = devname
+ if(devname in sysvals.devprops):
+ name = sysvals.devprops[devname].altName(devname)
+ if sysvals.suspendmode == 'command':
+ ftitle = name
+ else:
+ ftitle = name+' '+p
hf.write(html_func_top.format(devid, data.dmesg[p]['color'], \
- num, name+' '+p, flen))
+ num, ftitle, flen))
num += 1
for line in cg.list:
if(line.length < 0.000000001):
flen = ''
else:
- flen = '<n>(%.3f ms @ %.3f)</n>' % (line.length*1000, \
- line.time*1000)
+ fmt = '<n>(%.3f ms @ '+sysvals.timeformat+')</n>'
+ flen = fmt % (line.length*1000, line.time)
if(line.freturn and line.fcall):
hf.write(html_func_leaf.format(line.name, flen))
elif(line.freturn):
@@ -3409,9 +3419,40 @@ def createHTML(testruns):
num += 1
hf.write(html_func_end)
hf.write('\n\n </section>\n')
- # write the footer and close
- addScriptCode(hf, testruns)
- hf.write('</body>\n</html>\n')
+
+ # add the dmesg log as a hidden div
+ if sysvals.addlogs and sysvals.dmesgfile:
+ hf.write('<div id="dmesglog" style="display:none;">\n')
+ lf = open(sysvals.dmesgfile, 'r')
+ for line in lf:
+ hf.write(line)
+ lf.close()
+ hf.write('</div>\n')
+ # add the ftrace log as a hidden div
+ if sysvals.addlogs and sysvals.ftracefile:
+ hf.write('<div id="ftracelog" style="display:none;">\n')
+ lf = open(sysvals.ftracefile, 'r')
+ for line in lf:
+ hf.write(line)
+ lf.close()
+ hf.write('</div>\n')
+
+ if(not sysvals.embedded):
+ # write the footer and close
+ addScriptCode(hf, testruns)
+ hf.write('</body>\n</html>\n')
+ else:
+ # embedded out will be loaded in a page, skip the js
+ t0 = (testruns[0].start - testruns[-1].tSuspended) * 1000
+ tMax = (testruns[-1].end - testruns[-1].tSuspended) * 1000
+ # add js code in a div entry for later evaluation
+ detail = 'var bounds = [%f,%f];\n' % (t0, tMax)
+ detail += 'var devtable = [\n'
+ for data in testruns:
+ topo = data.deviceTopology()
+ detail += '\t"%s",\n' % (topo)
+ detail += '];\n'
+ hf.write('<div id=customcode style=display:none>\n'+detail+'</div>\n')
hf.close()
return True
@@ -3422,8 +3463,8 @@ def createHTML(testruns):
# hf: the open html file pointer
# testruns: array of Data objects from parseKernelLog or parseTraceLog
def addScriptCode(hf, testruns):
- t0 = (testruns[0].start - testruns[-1].tSuspended) * 1000
- tMax = (testruns[-1].end - testruns[-1].tSuspended) * 1000
+ t0 = testruns[0].start * 1000
+ tMax = testruns[-1].end * 1000
# create an array in javascript memory with the device details
detail = ' var devtable = [];\n'
for data in testruns:
@@ -3433,8 +3474,43 @@ def addScriptCode(hf, testruns):
# add the code which will manipulate the data in the browser
script_code = \
'<script type="text/javascript">\n'+detail+\
+ ' var resolution = -1;\n'\
+ ' function redrawTimescale(t0, tMax, tS) {\n'\
+ ' var rline = \'<div class="t" style="left:0;border-left:1px solid black;border-right:0;"><cR><-R</cR></div>\';\n'\
+ ' var tTotal = tMax - t0;\n'\
+ ' var list = document.getElementsByClassName("tblock");\n'\
+ ' for (var i = 0; i < list.length; i++) {\n'\
+ ' var timescale = list[i].getElementsByClassName("timescale")[0];\n'\
+ ' var m0 = t0 + (tTotal*parseFloat(list[i].style.left)/100);\n'\
+ ' var mTotal = tTotal*parseFloat(list[i].style.width)/100;\n'\
+ ' var mMax = m0 + mTotal;\n'\
+ ' var html = "";\n'\
+ ' var divTotal = Math.floor(mTotal/tS) + 1;\n'\
+ ' if(divTotal > 1000) continue;\n'\
+ ' var divEdge = (mTotal - tS*(divTotal-1))*100/mTotal;\n'\
+ ' var pos = 0.0, val = 0.0;\n'\
+ ' for (var j = 0; j < divTotal; j++) {\n'\
+ ' var htmlline = "";\n'\
+ ' if(list[i].id[5] == "r") {\n'\
+ ' pos = 100 - (((j)*tS*100)/mTotal);\n'\
+ ' val = (j)*tS;\n'\
+ ' htmlline = \'<div class="t" style="right:\'+pos+\'%">\'+val+\'ms</div>\';\n'\
+ ' if(j == 0)\n'\
+ ' htmlline = rline;\n'\
+ ' } else {\n'\
+ ' pos = 100 - (((j)*tS*100)/mTotal) - divEdge;\n'\
+ ' val = (j-divTotal+1)*tS;\n'\
+ ' if(j == divTotal - 1)\n'\
+ ' htmlline = \'<div class="t" style="right:\'+pos+\'%"><cS>S-></cS></div>\';\n'\
+ ' else\n'\
+ ' htmlline = \'<div class="t" style="right:\'+pos+\'%">\'+val+\'ms</div>\';\n'\
+ ' }\n'\
+ ' html += htmlline;\n'\
+ ' }\n'\
+ ' timescale.innerHTML = html;\n'\
+ ' }\n'\
+ ' }\n'\
' function zoomTimeline() {\n'\
- ' var timescale = document.getElementById("timescale");\n'\
' var dmesg = document.getElementById("dmesg");\n'\
' var zoombox = document.getElementById("dmesgzoombox");\n'\
' var val = parseFloat(dmesg.style.width);\n'\
@@ -3442,7 +3518,7 @@ def addScriptCode(hf, testruns):
' var sh = window.outerWidth / 2;\n'\
' if(this.id == "zoomin") {\n'\
' newval = val * 1.2;\n'\
- ' if(newval > 40000) newval = 40000;\n'\
+ ' if(newval > 910034) newval = 910034;\n'\
' dmesg.style.width = newval+"%";\n'\
' zoombox.scrollLeft = ((zoombox.scrollLeft + sh) * newval / val) - sh;\n'\
' } else if (this.id == "zoomout") {\n'\
@@ -3454,19 +3530,17 @@ def addScriptCode(hf, testruns):
' zoombox.scrollLeft = 0;\n'\
' dmesg.style.width = "100%";\n'\
' }\n'\
- ' var html = "";\n'\
+ ' var tS = [10000, 5000, 2000, 1000, 500, 200, 100, 50, 20, 10, 5, 2, 1];\n'\
' var t0 = bounds[0];\n'\
' var tMax = bounds[1];\n'\
' var tTotal = tMax - t0;\n'\
' var wTotal = tTotal * 100.0 / newval;\n'\
- ' for(var tS = 1000; (wTotal / tS) < 3; tS /= 10);\n'\
- ' if(tS < 1) tS = 1;\n'\
- ' for(var s = ((t0 / tS)|0) * tS; s < tMax; s += tS) {\n'\
- ' var pos = (tMax - s) * 100.0 / tTotal;\n'\
- ' var name = (s == 0)?"S/R":(s+"ms");\n'\
- ' html += "<div class=\\"t\\" style=\\"right:"+pos+"%\\">"+name+"</div>";\n'\
- ' }\n'\
- ' timescale.innerHTML = html;\n'\
+ ' var idx = 7*window.innerWidth/1100;\n'\
+ ' for(var i = 0; (i < tS.length)&&((wTotal / tS[i]) < idx); i++);\n'\
+ ' if(i >= tS.length) i = tS.length - 1;\n'\
+ ' if(tS[i] == resolution) return;\n'\
+ ' resolution = tS[i];\n'\
+ ' redrawTimescale(t0, tMax, tS[i]);\n'\
' }\n'\
' function deviceHover() {\n'\
' var name = this.title.slice(0, this.title.indexOf(" ("));\n'\
@@ -3479,12 +3553,13 @@ def addScriptCode(hf, testruns):
' cpu = parseInt(name.slice(8));\n'\
' for (var i = 0; i < dev.length; i++) {\n'\
' dname = dev[i].title.slice(0, dev[i].title.indexOf(" ("));\n'\
+ ' var cname = dev[i].className.slice(dev[i].className.indexOf("thread"));\n'\
' if((cpu >= 0 && dname.match("CPU_O[NF]*\\\[*"+cpu+"\\\]")) ||\n'\
' (name == dname))\n'\
' {\n'\
- ' dev[i].className = "thread hover";\n'\
+ ' dev[i].className = "hover "+cname;\n'\
' } else {\n'\
- ' dev[i].className = "thread";\n'\
+ ' dev[i].className = cname;\n'\
' }\n'\
' }\n'\
' }\n'\
@@ -3492,7 +3567,7 @@ def addScriptCode(hf, testruns):
' var dmesg = document.getElementById("dmesg");\n'\
' var dev = dmesg.getElementsByClassName("thread");\n'\
' for (var i = 0; i < dev.length; i++) {\n'\
- ' dev[i].className = "thread";\n'\
+ ' dev[i].className = dev[i].className.slice(dev[i].className.indexOf("thread"));\n'\
' }\n'\
' }\n'\
' function deviceTitle(title, total, cpu) {\n'\
@@ -3503,7 +3578,7 @@ def addScriptCode(hf, testruns):
' total[2] = (total[2]+total[4])/2;\n'\
' }\n'\
' var devtitle = document.getElementById("devicedetailtitle");\n'\
- ' var name = title.slice(0, title.indexOf(" "));\n'\
+ ' var name = title.slice(0, title.indexOf(" ("));\n'\
' if(cpu >= 0) name = "CPU"+cpu;\n'\
' var driver = "";\n'\
' var tS = "<t2>(</t2>";\n'\
@@ -3535,6 +3610,8 @@ def addScriptCode(hf, testruns):
' var dev = dmesg.getElementsByClassName("thread");\n'\
' var idlist = [];\n'\
' var pdata = [[]];\n'\
+ ' if(document.getElementById("devicedetail1"))\n'\
+ ' pdata = [[], []];\n'\
' var pd = pdata[0];\n'\
' var total = [0.0, 0.0, 0.0];\n'\
' for (var i = 0; i < dev.length; i++) {\n'\
@@ -3590,6 +3667,7 @@ def addScriptCode(hf, testruns):
' var cglist = document.getElementById("callgraphs");\n'\
' if(!cglist) return;\n'\
' var cg = cglist.getElementsByClassName("atop");\n'\
+ ' if(cg.length < 10) return;\n'\
' for (var i = 0; i < cg.length; i++) {\n'\
' if(idlist.indexOf(cg[i].id) >= 0) {\n'\
' cg[i].style.display = "block";\n'\
@@ -3614,15 +3692,32 @@ def addScriptCode(hf, testruns):
' dt = devtable[1];\n'\
' win.document.write(html+dt);\n'\
' }\n'\
+ ' function logWindow(e) {\n'\
+ ' var name = e.target.id.slice(4);\n'\
+ ' var win = window.open();\n'\
+ ' var log = document.getElementById(name+"log");\n'\
+ ' var title = "<title>"+document.title.split(" ")[0]+" "+name+" log</title>";\n'\
+ ' win.document.write(title+"<pre>"+log.innerHTML+"</pre>");\n'\
+ ' win.document.close();\n'\
+ ' }\n'\
+ ' function onClickPhase(e) {\n'\
+ ' }\n'\
+ ' window.addEventListener("resize", function () {zoomTimeline();});\n'\
' window.addEventListener("load", function () {\n'\
' var dmesg = document.getElementById("dmesg");\n'\
' dmesg.style.width = "100%"\n'\
' document.getElementById("zoomin").onclick = zoomTimeline;\n'\
' document.getElementById("zoomout").onclick = zoomTimeline;\n'\
' document.getElementById("zoomdef").onclick = zoomTimeline;\n'\
- ' var devlist = document.getElementsByClassName("devlist");\n'\
- ' for (var i = 0; i < devlist.length; i++)\n'\
- ' devlist[i].onclick = devListWindow;\n'\
+ ' var list = document.getElementsByClassName("square");\n'\
+ ' for (var i = 0; i < list.length; i++)\n'\
+ ' list[i].onclick = onClickPhase;\n'\
+ ' var list = document.getElementsByClassName("logbtn");\n'\
+ ' for (var i = 0; i < list.length; i++)\n'\
+ ' list[i].onclick = logWindow;\n'\
+ ' list = document.getElementsByClassName("devlist");\n'\
+ ' for (var i = 0; i < list.length; i++)\n'\
+ ' list[i].onclick = devListWindow;\n'\
' var dev = dmesg.getElementsByClassName("thread");\n'\
' for (var i = 0; i < dev.length; i++) {\n'\
' dev[i].onclick = deviceDetail;\n'\
@@ -3641,141 +3736,87 @@ def addScriptCode(hf, testruns):
def executeSuspend():
global sysvals
- detectUSB(False)
t0 = time.time()*1000
tp = sysvals.tpath
+ fwdata = []
+ # mark the start point in the kernel ring buffer just as we start
+ sysvals.initdmesg()
+ # start ftrace
+ if(sysvals.usecallgraph or sysvals.usetraceevents):
+ print('START TRACING')
+ sysvals.fsetVal('1', 'tracing_on')
# execute however many s/r runs requested
for count in range(1,sysvals.execcount+1):
- # clear the kernel ring buffer just as we start
- os.system('dmesg -C')
- # enable callgraph ftrace only for the second run
- if(sysvals.usecallgraph and count == 2):
- # set trace type
- os.system('echo function_graph > '+tp+'current_tracer')
- os.system('echo "" > '+tp+'set_ftrace_filter')
- # set trace format options
- os.system('echo funcgraph-abstime > '+tp+'trace_options')
- os.system('echo funcgraph-proc > '+tp+'trace_options')
- # focus only on device suspend and resume
- os.system('cat '+tp+'available_filter_functions | '+\
- 'grep dpm_run_callback > '+tp+'set_graph_function')
# if this is test2 and there's a delay, start here
if(count > 1 and sysvals.x2delay > 0):
tN = time.time()*1000
while (tN - t0) < sysvals.x2delay:
tN = time.time()*1000
time.sleep(0.001)
- # start ftrace
- if(sysvals.usecallgraph or sysvals.usetraceevents):
- print('START TRACING')
- os.system('echo 1 > '+tp+'tracing_on')
# initiate suspend
if(sysvals.usecallgraph or sysvals.usetraceevents):
- os.system('echo SUSPEND START > '+tp+'trace_marker')
- if(sysvals.rtcwake):
- print('SUSPEND START')
- print('will autoresume in %d seconds' % sysvals.rtcwaketime)
- sysvals.rtcWakeAlarm()
+ sysvals.fsetVal('SUSPEND START', 'trace_marker')
+ if sysvals.suspendmode == 'command':
+ print('COMMAND START')
+ if(sysvals.rtcwake):
+ print('will issue an rtcwake in %d seconds' % sysvals.rtcwaketime)
+ sysvals.rtcWakeAlarmOn()
+ os.system(sysvals.testcommand)
else:
- print('SUSPEND START (press a key to resume)')
- pf = open(sysvals.powerfile, 'w')
- pf.write(sysvals.suspendmode)
- # execution will pause here
- pf.close()
+ if(sysvals.rtcwake):
+ print('SUSPEND START')
+ print('will autoresume in %d seconds' % sysvals.rtcwaketime)
+ sysvals.rtcWakeAlarmOn()
+ else:
+ print('SUSPEND START (press a key to resume)')
+ pf = open(sysvals.powerfile, 'w')
+ pf.write(sysvals.suspendmode)
+ # execution will pause here
+ try:
+ pf.close()
+ except:
+ pass
t0 = time.time()*1000
+ if(sysvals.rtcwake):
+ sysvals.rtcWakeAlarmOff()
# return from suspend
print('RESUME COMPLETE')
if(sysvals.usecallgraph or sysvals.usetraceevents):
- os.system('echo RESUME COMPLETE > '+tp+'trace_marker')
- # see if there's firmware timing data to be had
- t = sysvals.postresumetime
- if(t > 0):
- print('Waiting %d seconds for POST-RESUME trace events...' % t)
- time.sleep(t)
- # stop ftrace
- if(sysvals.usecallgraph or sysvals.usetraceevents):
- os.system('echo 0 > '+tp+'tracing_on')
- print('CAPTURING TRACE')
- writeDatafileHeader(sysvals.ftracefile)
- os.system('cat '+tp+'trace >> '+sysvals.ftracefile)
- os.system('echo "" > '+tp+'trace')
- # grab a copy of the dmesg output
- print('CAPTURING DMESG')
- writeDatafileHeader(sysvals.dmesgfile)
- os.system('dmesg -c >> '+sysvals.dmesgfile)
-
-def writeDatafileHeader(filename):
+ sysvals.fsetVal('RESUME COMPLETE', 'trace_marker')
+ if(sysvals.suspendmode == 'mem'):
+ fwdata.append(getFPDT(False))
+ # look for post resume events after the last test run
+ t = sysvals.postresumetime
+ if(t > 0):
+ print('Waiting %d seconds for POST-RESUME trace events...' % t)
+ time.sleep(t)
+ # stop ftrace
+ if(sysvals.usecallgraph or sysvals.usetraceevents):
+ sysvals.fsetVal('0', 'tracing_on')
+ print('CAPTURING TRACE')
+ writeDatafileHeader(sysvals.ftracefile, fwdata)
+ os.system('cat '+tp+'trace >> '+sysvals.ftracefile)
+ sysvals.fsetVal('', 'trace')
+ devProps()
+ # grab a copy of the dmesg output
+ print('CAPTURING DMESG')
+ writeDatafileHeader(sysvals.dmesgfile, fwdata)
+ sysvals.getdmesg()
+
+def writeDatafileHeader(filename, fwdata):
global sysvals
- fw = getFPDT(False)
prt = sysvals.postresumetime
fp = open(filename, 'a')
fp.write(sysvals.teststamp+'\n')
- if(fw):
- fp.write('# fwsuspend %u fwresume %u\n' % (fw[0], fw[1]))
+ if(sysvals.suspendmode == 'mem'):
+ for fw in fwdata:
+ if(fw):
+ fp.write('# fwsuspend %u fwresume %u\n' % (fw[0], fw[1]))
if(prt > 0):
fp.write('# post resume time %u\n' % prt)
fp.close()
-# Function: executeAndroidSuspend
-# Description:
-# Execute system suspend through the sysfs interface
-# on a remote android device, then transfer the output
-# dmesg and ftrace files to the local output directory.
-def executeAndroidSuspend():
- global sysvals
-
- # check to see if the display is currently off
- tp = sysvals.tpath
- out = os.popen(sysvals.adb+\
- ' shell dumpsys power | grep mScreenOn').read().strip()
- # if so we need to turn it on so we can issue a new suspend
- if(out.endswith('false')):
- print('Waking the device up for the test...')
- # send the KEYPAD_POWER keyevent to wake it up
- os.system(sysvals.adb+' shell input keyevent 26')
- # wait a few seconds so the user can see the device wake up
- time.sleep(3)
- # execute however many s/r runs requested
- for count in range(1,sysvals.execcount+1):
- # clear the kernel ring buffer just as we start
- os.system(sysvals.adb+' shell dmesg -c > /dev/null 2>&1')
- # start ftrace
- if(sysvals.usetraceevents):
- print('START TRACING')
- os.system(sysvals.adb+" shell 'echo 1 > "+tp+"tracing_on'")
- # initiate suspend
- for count in range(1,sysvals.execcount+1):
- if(sysvals.usetraceevents):
- os.system(sysvals.adb+\
- " shell 'echo SUSPEND START > "+tp+"trace_marker'")
- print('SUSPEND START (press a key on the device to resume)')
- os.system(sysvals.adb+" shell 'echo "+sysvals.suspendmode+\
- " > "+sysvals.powerfile+"'")
- # execution will pause here, then adb will exit
- while(True):
- check = os.popen(sysvals.adb+\
- ' shell pwd 2>/dev/null').read().strip()
- if(len(check) > 0):
- break
- time.sleep(1)
- if(sysvals.usetraceevents):
- os.system(sysvals.adb+" shell 'echo RESUME COMPLETE > "+tp+\
- "trace_marker'")
- # return from suspend
- print('RESUME COMPLETE')
- # stop ftrace
- if(sysvals.usetraceevents):
- os.system(sysvals.adb+" shell 'echo 0 > "+tp+"tracing_on'")
- print('CAPTURING TRACE')
- os.system('echo "'+sysvals.teststamp+'" > '+sysvals.ftracefile)
- os.system(sysvals.adb+' shell cat '+tp+\
- 'trace >> '+sysvals.ftracefile)
- # grab a copy of the dmesg output
- print('CAPTURING DMESG')
- os.system('echo "'+sysvals.teststamp+'" > '+sysvals.dmesgfile)
- os.system(sysvals.adb+' shell dmesg >> '+sysvals.dmesgfile)
-
# Function: setUSBDevicesAuto
# Description:
# Set the autosuspend control parameter of all USB devices to auto
@@ -3785,7 +3826,7 @@ def executeAndroidSuspend():
def setUSBDevicesAuto():
global sysvals
- rootCheck()
+ rootCheck(True)
for dirname, dirnames, filenames in os.walk('/sys/devices'):
if(re.match('.*/usb[0-9]*.*', dirname) and
'idVendor' in filenames and 'idProduct' in filenames):
@@ -3830,9 +3871,7 @@ def ms2nice(val):
# Description:
# Detect all the USB hosts and devices currently connected and add
# a list of USB device names to sysvals for better timeline readability
-# Arguments:
-# output: True to output the info to stdout, False otherwise
-def detectUSB(output):
+def detectUSB():
global sysvals
field = {'idVendor':'', 'idProduct':'', 'product':'', 'speed':''}
@@ -3843,18 +3882,18 @@ def detectUSB(output):
'runtime_suspended_time':'',
'active_duration':'',
'connected_duration':''}
- if(output):
- print('LEGEND')
- print('---------------------------------------------------------------------------------------------')
- print(' A = async/sync PM queue Y/N D = autosuspend delay (seconds)')
- print(' S = autosuspend Y/N rACTIVE = runtime active (min/sec)')
- print(' P = persist across suspend Y/N rSUSPEN = runtime suspend (min/sec)')
- print(' E = runtime suspend enabled/forbidden Y/N ACTIVE = active duration (min/sec)')
- print(' R = runtime status active/suspended Y/N CONNECT = connected duration (min/sec)')
- print(' U = runtime usage count')
- print('---------------------------------------------------------------------------------------------')
- print(' NAME ID DESCRIPTION SPEED A S P E R U D rACTIVE rSUSPEN ACTIVE CONNECT')
- print('---------------------------------------------------------------------------------------------')
+
+ print('LEGEND')
+ print('---------------------------------------------------------------------------------------------')
+ print(' A = async/sync PM queue Y/N D = autosuspend delay (seconds)')
+ print(' S = autosuspend Y/N rACTIVE = runtime active (min/sec)')
+ print(' P = persist across suspend Y/N rSUSPEN = runtime suspend (min/sec)')
+ print(' E = runtime suspend enabled/forbidden Y/N ACTIVE = active duration (min/sec)')
+ print(' R = runtime status active/suspended Y/N CONNECT = connected duration (min/sec)')
+ print(' U = runtime usage count')
+ print('---------------------------------------------------------------------------------------------')
+ print(' NAME ID DESCRIPTION SPEED A S P E R U D rACTIVE rSUSPEN ACTIVE CONNECT')
+ print('---------------------------------------------------------------------------------------------')
for dirname, dirnames, filenames in os.walk('/sys/devices'):
if(re.match('.*/usb[0-9]*.*', dirname) and
@@ -3863,35 +3902,149 @@ def detectUSB(output):
field[i] = os.popen('cat %s/%s 2>/dev/null' % \
(dirname, i)).read().replace('\n', '')
name = dirname.split('/')[-1]
- if(len(field['product']) > 0):
- sysvals.altdevname[name] = \
- '%s [%s]' % (field['product'], name)
+ for i in power:
+ power[i] = os.popen('cat %s/power/%s 2>/dev/null' % \
+ (dirname, i)).read().replace('\n', '')
+ if(re.match('usb[0-9]*', name)):
+ first = '%-8s' % name
else:
- sysvals.altdevname[name] = \
- '%s:%s [%s]' % (field['idVendor'], \
- field['idProduct'], name)
- if(output):
- for i in power:
- power[i] = os.popen('cat %s/power/%s 2>/dev/null' % \
- (dirname, i)).read().replace('\n', '')
- if(re.match('usb[0-9]*', name)):
- first = '%-8s' % name
- else:
- first = '%8s' % name
- print('%s [%s:%s] %-20s %-4s %1s %1s %1s %1s %1s %1s %1s %s %s %s %s' % \
- (first, field['idVendor'], field['idProduct'], \
- field['product'][0:20], field['speed'], \
- yesno(power['async']), \
- yesno(power['control']), \
- yesno(power['persist']), \
- yesno(power['runtime_enabled']), \
- yesno(power['runtime_status']), \
- power['runtime_usage'], \
- power['autosuspend'], \
- ms2nice(power['runtime_active_time']), \
- ms2nice(power['runtime_suspended_time']), \
- ms2nice(power['active_duration']), \
- ms2nice(power['connected_duration'])))
+ first = '%8s' % name
+ print('%s [%s:%s] %-20s %-4s %1s %1s %1s %1s %1s %1s %1s %s %s %s %s' % \
+ (first, field['idVendor'], field['idProduct'], \
+ field['product'][0:20], field['speed'], \
+ yesno(power['async']), \
+ yesno(power['control']), \
+ yesno(power['persist']), \
+ yesno(power['runtime_enabled']), \
+ yesno(power['runtime_status']), \
+ power['runtime_usage'], \
+ power['autosuspend'], \
+ ms2nice(power['runtime_active_time']), \
+ ms2nice(power['runtime_suspended_time']), \
+ ms2nice(power['active_duration']), \
+ ms2nice(power['connected_duration'])))
+
+# Function: devProps
+# Description:
+# Retrieve a list of properties for all devices in the trace log
+def devProps(data=0):
+ global sysvals
+ props = dict()
+
+ if data:
+ idx = data.index(': ') + 2
+ if idx >= len(data):
+ return
+ devlist = data[idx:].split(';')
+ for dev in devlist:
+ f = dev.split(',')
+ if len(f) < 3:
+ continue
+ dev = f[0]
+ props[dev] = DevProps()
+ props[dev].altname = f[1]
+ if int(f[2]):
+ props[dev].async = True
+ else:
+ props[dev].async = False
+ sysvals.devprops = props
+ if sysvals.suspendmode == 'command' and 'testcommandstring' in props:
+ sysvals.testcommand = props['testcommandstring'].altname
+ return
+
+ if(os.path.exists(sysvals.ftracefile) == False):
+ doError('%s does not exist' % sysvals.ftracefile, False)
+
+ # first get the list of devices we need properties for
+ msghead = 'Additional data added by AnalyzeSuspend'
+ alreadystamped = False
+ tp = TestProps()
+ tf = open(sysvals.ftracefile, 'r')
+ for line in tf:
+ if msghead in line:
+ alreadystamped = True
+ continue
+ # determine the trace data type (required for further parsing)
+ m = re.match(sysvals.tracertypefmt, line)
+ if(m):
+ tp.setTracerType(m.group('t'))
+ continue
+ # parse only valid lines, if this is not one move on
+ m = re.match(tp.ftrace_line_fmt, line)
+ if(not m or 'device_pm_callback_start' not in line):
+ continue
+ m = re.match('.*: (?P<drv>.*) (?P<d>.*), parent: *(?P<p>.*), .*', m.group('msg'));
+ if(not m):
+ continue
+ drv, dev, par = m.group('drv'), m.group('d'), m.group('p')
+ if dev not in props:
+ props[dev] = DevProps()
+ tf.close()
+
+ if not alreadystamped and sysvals.suspendmode == 'command':
+ out = '#\n# '+msghead+'\n# Device Properties: '
+ out += 'testcommandstring,%s,0;' % (sysvals.testcommand)
+ with open(sysvals.ftracefile, 'a') as fp:
+ fp.write(out+'\n')
+ sysvals.devprops = props
+ return
+
+ # now get the syspath for each of our target devices
+ for dirname, dirnames, filenames in os.walk('/sys/devices'):
+ if(re.match('.*/power', dirname) and 'async' in filenames):
+ dev = dirname.split('/')[-2]
+ if dev in props and (not props[dev].syspath or len(dirname) < len(props[dev].syspath)):
+ props[dev].syspath = dirname[:-6]
+
+ # now fill in the properties for our target devices
+ for dev in props:
+ dirname = props[dev].syspath
+ if not dirname or not os.path.exists(dirname):
+ continue
+ with open(dirname+'/power/async') as fp:
+ text = fp.read()
+ props[dev].async = False
+ if 'enabled' in text:
+ props[dev].async = True
+ fields = os.listdir(dirname)
+ if 'product' in fields:
+ with open(dirname+'/product') as fp:
+ props[dev].altname = fp.read()
+ elif 'name' in fields:
+ with open(dirname+'/name') as fp:
+ props[dev].altname = fp.read()
+ elif 'model' in fields:
+ with open(dirname+'/model') as fp:
+ props[dev].altname = fp.read()
+ elif 'description' in fields:
+ with open(dirname+'/description') as fp:
+ props[dev].altname = fp.read()
+ elif 'id' in fields:
+ with open(dirname+'/id') as fp:
+ props[dev].altname = fp.read()
+ elif 'idVendor' in fields and 'idProduct' in fields:
+ idv, idp = '', ''
+ with open(dirname+'/idVendor') as fp:
+ idv = fp.read().strip()
+ with open(dirname+'/idProduct') as fp:
+ idp = fp.read().strip()
+ props[dev].altname = '%s:%s' % (idv, idp)
+
+ if props[dev].altname:
+ out = props[dev].altname.strip().replace('\n', ' ')
+ out = out.replace(',', ' ')
+ out = out.replace(';', ' ')
+ props[dev].altname = out
+
+ # and now write the data to the ftrace file
+ if not alreadystamped:
+ out = '#\n# '+msghead+'\n# Device Properties: '
+ for dev in sorted(props):
+ out += props[dev].out(dev)
+ with open(sysvals.ftracefile, 'a') as fp:
+ fp.write(out+'\n')
+
+ sysvals.devprops = props
# Function: getModes
# Description:
@@ -3901,15 +4054,10 @@ def detectUSB(output):
def getModes():
global sysvals
modes = ''
- if(not sysvals.android):
- if(os.path.exists(sysvals.powerfile)):
- fp = open(sysvals.powerfile, 'r')
- modes = string.split(fp.read())
- fp.close()
- else:
- line = os.popen(sysvals.adb+' shell cat '+\
- sysvals.powerfile).read().strip()
- modes = string.split(line)
+ if(os.path.exists(sysvals.powerfile)):
+ fp = open(sysvals.powerfile, 'r')
+ modes = string.split(fp.read())
+ fp.close()
return modes
# Function: getFPDT
@@ -3927,22 +4075,22 @@ def getFPDT(output):
prectype[0] = 'Basic S3 Resume Performance Record'
prectype[1] = 'Basic S3 Suspend Performance Record'
- rootCheck()
+ rootCheck(True)
if(not os.path.exists(sysvals.fpdtpath)):
if(output):
- doError('file doesnt exist: %s' % sysvals.fpdtpath, False)
+ doError('file does not exist: %s' % sysvals.fpdtpath, False)
return False
if(not os.access(sysvals.fpdtpath, os.R_OK)):
if(output):
- doError('file isnt readable: %s' % sysvals.fpdtpath, False)
+ doError('file is not readable: %s' % sysvals.fpdtpath, False)
return False
if(not os.path.exists(sysvals.mempath)):
if(output):
- doError('file doesnt exist: %s' % sysvals.mempath, False)
+ doError('file does not exist: %s' % sysvals.mempath, False)
return False
if(not os.access(sysvals.mempath, os.R_OK)):
if(output):
- doError('file isnt readable: %s' % sysvals.mempath, False)
+ doError('file is not readable: %s' % sysvals.mempath, False)
return False
fp = open(sysvals.fpdtpath, 'rb')
@@ -3983,15 +4131,19 @@ def getFPDT(output):
while(i < len(records)):
header = struct.unpack('HBB', records[i:i+4])
if(header[0] not in rectype):
+ i += header[1]
continue
if(header[1] != 16):
+ i += header[1]
continue
addr = struct.unpack('Q', records[i+8:i+16])[0]
try:
fp.seek(addr)
first = fp.read(8)
except:
- doError('Bad address 0x%x in %s' % (addr, sysvals.mempath), False)
+ if(output):
+ print('Bad address 0x%x in %s' % (addr, sysvals.mempath))
+ return [0, 0]
rechead = struct.unpack('4sI', first)
recdata = fp.read(rechead[1]-8)
if(rechead[0] == 'FBPT'):
@@ -4046,89 +4198,60 @@ def getFPDT(output):
# print the results to the terminal
# Output:
# True if the test will work, False if not
-def statusCheck():
+def statusCheck(probecheck=False):
global sysvals
status = True
- if(sysvals.android):
- print('Checking the android system ...')
- else:
- print('Checking this system (%s)...' % platform.node())
-
- # check if adb is connected to a device
- if(sysvals.android):
- res = 'NO'
- out = os.popen(sysvals.adb+' get-state').read().strip()
- if(out == 'device'):
- res = 'YES'
- print(' is android device connected: %s' % res)
- if(res != 'YES'):
- print(' Please connect the device before using this tool')
- return False
+ print('Checking this system (%s)...' % platform.node())
# check we have root access
- res = 'NO (No features of this tool will work!)'
- if(sysvals.android):
- out = os.popen(sysvals.adb+' shell id').read().strip()
- if('root' in out):
- res = 'YES'
- else:
- if(os.environ['USER'] == 'root'):
- res = 'YES'
+ res = sysvals.colorText('NO (No features of this tool will work!)')
+ if(rootCheck(False)):
+ res = 'YES'
print(' have root access: %s' % res)
if(res != 'YES'):
- if(sysvals.android):
- print(' Try running "adb root" to restart the daemon as root')
- else:
- print(' Try running this script with sudo')
+ print(' Try running this script with sudo')
return False
# check sysfs is mounted
- res = 'NO (No features of this tool will work!)'
- if(sysvals.android):
- out = os.popen(sysvals.adb+' shell ls '+\
- sysvals.powerfile).read().strip()
- if(out == sysvals.powerfile):
- res = 'YES'
- else:
- if(os.path.exists(sysvals.powerfile)):
- res = 'YES'
+ res = sysvals.colorText('NO (No features of this tool will work!)')
+ if(os.path.exists(sysvals.powerfile)):
+ res = 'YES'
print(' is sysfs mounted: %s' % res)
if(res != 'YES'):
return False
# check target mode is a valid mode
- res = 'NO'
- modes = getModes()
- if(sysvals.suspendmode in modes):
- res = 'YES'
- else:
- status = False
- print(' is "%s" a valid power mode: %s' % (sysvals.suspendmode, res))
- if(res == 'NO'):
- print(' valid power modes are: %s' % modes)
- print(' please choose one with -m')
-
- # check if the tool can unlock the device
- if(sysvals.android):
- res = 'YES'
- out1 = os.popen(sysvals.adb+\
- ' shell dumpsys power | grep mScreenOn').read().strip()
- out2 = os.popen(sysvals.adb+\
- ' shell input').read().strip()
- if(not out1.startswith('mScreenOn') or not out2.startswith('usage')):
- res = 'NO (wake the android device up before running the test)'
- print(' can I unlock the screen: %s' % res)
+ if sysvals.suspendmode != 'command':
+ res = sysvals.colorText('NO')
+ modes = getModes()
+ if(sysvals.suspendmode in modes):
+ res = 'YES'
+ else:
+ status = False
+ print(' is "%s" a valid power mode: %s' % (sysvals.suspendmode, res))
+ if(res == 'NO'):
+ print(' valid power modes are: %s' % modes)
+ print(' please choose one with -m')
# check if ftrace is available
- res = 'NO'
- ftgood = verifyFtrace()
+ res = sysvals.colorText('NO')
+ ftgood = sysvals.verifyFtrace()
if(ftgood):
res = 'YES'
elif(sysvals.usecallgraph):
status = False
print(' is ftrace supported: %s' % res)
+ # check if kprobes are available
+ res = sysvals.colorText('NO')
+ sysvals.usekprobes = sysvals.verifyKprobes()
+ if(sysvals.usekprobes):
+ res = 'YES'
+ else:
+ sysvals.usedevsrc = False
+ print(' are kprobes supported: %s' % res)
+
# what data source are we using
res = 'DMESG'
if(ftgood):
@@ -4136,14 +4259,8 @@ def statusCheck():
sysvals.usetraceevents = False
for e in sysvals.traceevents:
check = False
- if(sysvals.android):
- out = os.popen(sysvals.adb+' shell ls -d '+\
- sysvals.epath+e).read().strip()
- if(out == sysvals.epath+e):
- check = True
- else:
- if(os.path.exists(sysvals.epath+e)):
- check = True
+ if(os.path.exists(sysvals.epath+e)):
+ check = True
if(not check):
sysvals.usetraceeventsonly = False
if(e == 'suspend_resume' and check):
@@ -4155,13 +4272,48 @@ def statusCheck():
print(' timeline data source: %s' % res)
# check if rtcwake
- res = 'NO'
+ res = sysvals.colorText('NO')
if(sysvals.rtcpath != ''):
res = 'YES'
elif(sysvals.rtcwake):
status = False
print(' is rtcwake supported: %s' % res)
+ if not probecheck:
+ return status
+
+ if (sysvals.usecallgraph and len(sysvals.debugfuncs) > 0) or len(sysvals.kprobes) > 0:
+ sysvals.initFtrace(True)
+
+ # verify callgraph debugfuncs
+ if sysvals.usecallgraph and len(sysvals.debugfuncs) > 0:
+ print(' verifying these ftrace callgraph functions work:')
+ sysvals.setFtraceFilterFunctions(sysvals.debugfuncs)
+ fp = open(sysvals.tpath+'set_graph_function', 'r')
+ flist = fp.read().split('\n')
+ fp.close()
+ for func in sysvals.debugfuncs:
+ res = sysvals.colorText('NO')
+ if func in flist:
+ res = 'YES'
+ else:
+ for i in flist:
+ if ' [' in i and func == i.split(' ')[0]:
+ res = 'YES'
+ break
+ print(' %s: %s' % (func, res))
+
+ # verify kprobes
+ if len(sysvals.kprobes) > 0:
+ print(' verifying these kprobes work:')
+ for name in sorted(sysvals.kprobes):
+ if name in sysvals.tracefuncs:
+ continue
+ res = sysvals.colorText('NO')
+ if sysvals.testKprobe(sysvals.kprobes[name]):
+ res = 'YES'
+ print(' %s: %s' % (name, res))
+
return status
# Function: doError
@@ -4182,7 +4334,7 @@ def doError(msg, help):
# Arguments:
# msg: the warning message to print
# file: If not empty, a filename to request be sent to the owner for debug
-def doWarning(msg, file):
+def doWarning(msg, file=''):
print('/* %s */') % msg
if(file):
print('/* For a fix, please send this'+\
@@ -4191,18 +4343,25 @@ def doWarning(msg, file):
# Function: rootCheck
# Description:
# quick check to see if we have root access
-def rootCheck():
- if(os.environ['USER'] != 'root'):
- doError('This script must be run as root', False)
+def rootCheck(fatal):
+ global sysvals
+ if(os.access(sysvals.powerfile, os.W_OK)):
+ return True
+ if fatal:
+ doError('This command must be run as root', False)
+ return False
# Function: getArgInt
# Description:
# pull out an integer argument from the command line with checks
-def getArgInt(name, args, min, max):
- try:
- arg = args.next()
- except:
- doError(name+': no argument supplied', True)
+def getArgInt(name, args, min, max, main=True):
+ if main:
+ try:
+ arg = args.next()
+ except:
+ doError(name+': no argument supplied', True)
+ else:
+ arg = args
try:
val = int(arg)
except:
--
2.1.4
^ permalink raw reply related [flat|nested] 9+ messages in thread* [PATCH 5/5] scripts: AnalyzeSuspend v4.2 part5
2016-07-14 21:09 [PATCH 0/5] scripts: AnalyzeSuspend v4.2 Todd Brandt
` (3 preceding siblings ...)
2016-07-14 21:09 ` [PATCH 4/5] scripts: AnalyzeSuspend v4.2 part4 Todd Brandt
@ 2016-07-14 21:09 ` Todd Brandt
2016-07-14 21:22 ` [PATCH 0/5] scripts: AnalyzeSuspend v4.2 Rafael J. Wysocki
5 siblings, 0 replies; 9+ messages in thread
From: Todd Brandt @ 2016-07-14 21:09 UTC (permalink / raw)
To: linux-pm; +Cc: rjw, rafael.j.wysocki, todd.e.brandt, Todd Brandt
Signed-off-by: Todd Brandt <todd.e.brandt@linux.intel.com>
---
scripts/analyze_suspend.py | 356 ++++++++++++++++++++++++++++++++++-----------
1 file changed, 274 insertions(+), 82 deletions(-)
diff --git a/scripts/analyze_suspend.py b/scripts/analyze_suspend.py
index b93bb07..a0ba48f 100755
--- a/scripts/analyze_suspend.py
+++ b/scripts/analyze_suspend.py
@@ -4370,6 +4370,25 @@ def getArgInt(name, args, min, max, main=True):
doError(name+': value should be between %d and %d' % (min, max), True)
return val
+# Function: getArgFloat
+# Description:
+# pull out a float argument from the command line with checks
+def getArgFloat(name, args, min, max, main=True):
+ if main:
+ try:
+ arg = args.next()
+ except:
+ doError(name+': no argument supplied', True)
+ else:
+ arg = args
+ try:
+ val = float(arg)
+ except:
+ doError(name+': non-numerical value given', True)
+ if(val < min or val > max):
+ doError(name+': value should be between %f and %f' % (min, max), True)
+ return val
+
# Function: rerunTest
# Description:
# generate an output from an existing set of ftrace/dmesg logs
@@ -4397,15 +4416,12 @@ def rerunTest():
# Function: runTest
# Description:
# execute a suspend/resume, gather the logs, and generate the output
-def runTest(subdir):
+def runTest(subdir, testpath=''):
global sysvals
# prepare for the test
- if(not sysvals.android):
- initFtrace()
- else:
- initFtraceAndroid()
- sysvals.initTestOutput(subdir)
+ sysvals.initFtrace()
+ sysvals.initTestOutput(subdir, testpath)
vprint('Output files:\n %s' % sysvals.dmesgfile)
if(sysvals.usecallgraph or
@@ -4415,10 +4431,8 @@ def runTest(subdir):
vprint(' %s' % sysvals.htmlfile)
# execute the test
- if(not sysvals.android):
- executeSuspend()
- else:
- executeAndroidSuspend()
+ executeSuspend()
+ sysvals.cleanupFtrace()
# analyze the data and create the html output
print('PROCESSING DATA')
@@ -4482,6 +4496,153 @@ def runSummary(subdir, output):
createHTMLSummarySimple(testruns, subdir+'/summary.html')
+# Function: checkArgBool
+# Description:
+# check if a boolean string value is true or false
+def checkArgBool(value):
+ yes = ['1', 'true', 'yes', 'on']
+ if value.lower() in yes:
+ return True
+ return False
+
+# Function: configFromFile
+# Description:
+# Configure the script via the info in a config file
+def configFromFile(file):
+ global sysvals
+ Config = ConfigParser.ConfigParser()
+
+ ignorekprobes = False
+ Config.read(file)
+ sections = Config.sections()
+ if 'Settings' in sections:
+ for opt in Config.options('Settings'):
+ value = Config.get('Settings', opt).lower()
+ if(opt.lower() == 'verbose'):
+ sysvals.verbose = checkArgBool(value)
+ elif(opt.lower() == 'addlogs'):
+ sysvals.addlogs = checkArgBool(value)
+ elif(opt.lower() == 'dev'):
+ sysvals.usedevsrc = checkArgBool(value)
+ elif(opt.lower() == 'ignorekprobes'):
+ ignorekprobes = checkArgBool(value)
+ elif(opt.lower() == 'x2'):
+ if checkArgBool(value):
+ sysvals.execcount = 2
+ elif(opt.lower() == 'callgraph'):
+ sysvals.usecallgraph = checkArgBool(value)
+ elif(opt.lower() == 'callgraphfunc'):
+ sysvals.debugfuncs = []
+ if value:
+ value = value.split(',')
+ for i in value:
+ sysvals.debugfuncs.append(i.strip())
+ elif(opt.lower() == 'expandcg'):
+ sysvals.cgexp = checkArgBool(value)
+ elif(opt.lower() == 'srgap'):
+ if checkArgBool(value):
+ sysvals.srgap = 5
+ elif(opt.lower() == 'mode'):
+ sysvals.suspendmode = value
+ elif(opt.lower() == 'command'):
+ sysvals.testcommand = value
+ elif(opt.lower() == 'x2delay'):
+ sysvals.x2delay = getArgInt('-x2delay', value, 0, 60000, False)
+ elif(opt.lower() == 'postres'):
+ sysvals.postresumetime = getArgInt('-postres', value, 0, 3600, False)
+ elif(opt.lower() == 'rtcwake'):
+ sysvals.rtcwake = True
+ sysvals.rtcwaketime = getArgInt('-rtcwake', value, 0, 3600, False)
+ elif(opt.lower() == 'timeprec'):
+ sysvals.setPrecision(getArgInt('-timeprec', value, 0, 6, False))
+ elif(opt.lower() == 'mindev'):
+ sysvals.mindevlen = getArgFloat('-mindev', value, 0.0, 10000.0, False)
+ elif(opt.lower() == 'mincg'):
+ sysvals.mincglen = getArgFloat('-mincg', value, 0.0, 10000.0, False)
+ elif(opt.lower() == 'kprobecolor'):
+ try:
+ val = int(value, 16)
+ sysvals.kprobecolor = '#'+value
+ except:
+ sysvals.kprobecolor = value
+ elif(opt.lower() == 'synccolor'):
+ try:
+ val = int(value, 16)
+ sysvals.synccolor = '#'+value
+ except:
+ sysvals.synccolor = value
+ elif(opt.lower() == 'output-dir'):
+ args = dict()
+ n = datetime.now()
+ args['date'] = n.strftime('%y%m%d')
+ args['time'] = n.strftime('%H%M%S')
+ args['hostname'] = sysvals.hostname
+ sysvals.outdir = value.format(**args)
+
+ if sysvals.suspendmode == 'command' and not sysvals.testcommand:
+ doError('No command supplied for mode "command"', False)
+ if sysvals.usedevsrc and sysvals.usecallgraph:
+ doError('dev and callgraph cannot both be true', False)
+ if sysvals.usecallgraph and sysvals.execcount > 1:
+ doError('-x2 is not compatible with -f', False)
+
+ if ignorekprobes:
+ return
+
+ kprobes = dict()
+ archkprobe = 'Kprobe_'+platform.machine()
+ if archkprobe in sections:
+ for name in Config.options(archkprobe):
+ kprobes[name] = Config.get(archkprobe, name)
+ if 'Kprobe' in sections:
+ for name in Config.options('Kprobe'):
+ kprobes[name] = Config.get('Kprobe', name)
+
+ for name in kprobes:
+ function = name
+ format = name
+ color = ''
+ args = dict()
+ data = kprobes[name].split()
+ i = 0
+ for val in data:
+ # bracketted strings are special formatting, read them separately
+ if val[0] == '[' and val[-1] == ']':
+ for prop in val[1:-1].split(','):
+ p = prop.split('=')
+ if p[0] == 'color':
+ try:
+ color = int(p[1], 16)
+ color = '#'+p[1]
+ except:
+ color = p[1]
+ continue
+ # first real arg should be the format string
+ if i == 0:
+ format = val
+ # all other args are actual function args
+ else:
+ d = val.split('=')
+ args[d[0]] = d[1]
+ i += 1
+ if not function or not format:
+ doError('Invalid kprobe: %s' % name, False)
+ for arg in re.findall('{(?P<n>[a-z,A-Z,0-9]*)}', format):
+ if arg not in args:
+ doError('Kprobe "%s" is missing argument "%s"' % (name, arg), False)
+ if name in sysvals.kprobes:
+ doError('Duplicate kprobe found "%s"' % (name), False)
+ vprint('Adding KPROBE: %s %s %s %s' % (name, function, format, args))
+ sysvals.kprobes[name] = {
+ 'name': name,
+ 'func': function,
+ 'format': format,
+ 'args': args,
+ 'mask': re.sub('{(?P<n>[a-z,A-Z,0-9]*)}', '.*', format)
+ }
+ if color:
+ sysvals.kprobes[name]['color'] = color
+
# Function: printHelp
# Description:
# print out the help text
@@ -4490,7 +4651,7 @@ def printHelp():
modes = getModes()
print('')
- print('AnalyzeSuspend v%.1f' % sysvals.version)
+ print('AnalyzeSuspend v%s' % sysvals.version)
print('Usage: sudo analyze_suspend.py <options>')
print('')
print('Description:')
@@ -4511,27 +4672,38 @@ def printHelp():
print(' [general]')
print(' -h Print this help text')
print(' -v Print the current tool version')
+ print(' -config file Pull arguments and config options from a file')
print(' -verbose Print extra information during execution and analysis')
print(' -status Test to see if the system is enabled to run this tool')
print(' -modes List available suspend modes')
print(' -m mode Mode to initiate for suspend %s (default: %s)') % (modes, sysvals.suspendmode)
- print(' -rtcwake t Use rtcwake to autoresume after <t> seconds (default: disabled)')
+ print(' -o subdir Override the output subdirectory')
print(' [advanced]')
+ print(' -rtcwake t Use rtcwake to autoresume after <t> seconds (default: disabled)')
+ print(' -addlogs Add the dmesg and ftrace logs to the html output')
+ print(' -multi n d Execute <n> consecutive tests at <d> seconds intervals. The outputs will')
+ print(' be created in a new subdirectory with a summary page.')
+ print(' -srgap Add a visible gap in the timeline between sus/res (default: disabled)')
+ print(' -cmd {s} Instead of suspend/resume, run a command, e.g. "sync -d"')
+ print(' -mindev ms Discard all device blocks shorter than ms milliseconds (e.g. 0.001 for us)')
+ print(' -mincg ms Discard all callgraphs shorter than ms milliseconds (e.g. 0.001 for us)')
+ print(' -timeprec N Number of significant digits in timestamps (0:S, [3:ms], 6:us)')
+ print(' [debug]')
print(' -f Use ftrace to create device callgraphs (default: disabled)')
- print(' -filter "d1 d2 ..." Filter out all but this list of dev names')
+ print(' -expandcg pre-expand the callgraph data in the html output (default: disabled)')
+ print(' -flist Print the list of functions currently being captured in ftrace')
+ print(' -flistall Print all functions capable of being captured in ftrace')
+ print(' -fadd file Add functions to be graphed in the timeline from a list in a text file')
+ print(' -filter "d1 d2 ..." Filter out all but this list of device names')
+ print(' -dev Display common low level functions in the timeline')
+ print(' [post-resume task analysis]')
print(' -x2 Run two suspend/resumes back to back (default: disabled)')
print(' -x2delay t Minimum millisecond delay <t> between the two test runs (default: 0 ms)')
print(' -postres t Time after resume completion to wait for post-resume events (default: 0 S)')
- print(' -multi n d Execute <n> consecutive tests at <d> seconds intervals. The outputs will')
- print(' be created in a new subdirectory with a summary page.')
print(' [utilities]')
print(' -fpdt Print out the contents of the ACPI Firmware Performance Data Table')
print(' -usbtopo Print out the current USB topology with power info')
print(' -usbauto Enable autosuspend for all connected USB devices')
- print(' [android testing]')
- print(' -adb binary Use the given adb binary to run the test on an android device.')
- print(' The device should already be connected and with root access.')
- print(' Commands will be executed on the device using "adb shell"')
print(' [re-analyze data from previous runs]')
print(' -ftrace ftracefile Create HTML output using ftrace input')
print(' -dmesg dmesgfile Create HTML output using dmesg (not needed for kernel >= 3.15)')
@@ -4545,6 +4717,7 @@ if __name__ == '__main__':
cmd = ''
cmdarg = ''
multitest = {'run': False, 'count': 0, 'delay': 0}
+ simplecmds = ['-modes', '-fpdt', '-flist', '-flistall', '-usbtopo', '-usbauto', '-status']
# loop through the command line arguments
args = iter(sys.argv[1:])
for arg in args:
@@ -4553,58 +4726,85 @@ if __name__ == '__main__':
val = args.next()
except:
doError('No mode supplied', True)
+ if val == 'command' and not sysvals.testcommand:
+ doError('No command supplied for mode "command"', True)
sysvals.suspendmode = val
- elif(arg == '-adb'):
- try:
- val = args.next()
- except:
- doError('No adb binary supplied', True)
- if(not os.path.exists(val)):
- doError('file doesnt exist: %s' % val, False)
- if(not os.access(val, os.X_OK)):
- doError('file isnt executable: %s' % val, False)
- try:
- check = os.popen(val+' version').read().strip()
- except:
- doError('adb version failed to execute', False)
- if(not re.match('Android Debug Bridge .*', check)):
- doError('adb version failed to execute', False)
- sysvals.adb = val
- sysvals.android = True
+ elif(arg in simplecmds):
+ cmd = arg[1:]
+ elif(arg == '-h'):
+ printHelp()
+ sys.exit()
+ elif(arg == '-v'):
+ print("Version %s" % sysvals.version)
+ sys.exit()
elif(arg == '-x2'):
- if(sysvals.postresumetime > 0):
- doError('-x2 is not compatible with -postres', False)
sysvals.execcount = 2
+ if(sysvals.usecallgraph):
+ doError('-x2 is not compatible with -f', False)
elif(arg == '-x2delay'):
sysvals.x2delay = getArgInt('-x2delay', args, 0, 60000)
elif(arg == '-postres'):
- if(sysvals.execcount != 1):
- doError('-x2 is not compatible with -postres', False)
sysvals.postresumetime = getArgInt('-postres', args, 0, 3600)
elif(arg == '-f'):
sysvals.usecallgraph = True
- elif(arg == '-modes'):
- cmd = 'modes'
- elif(arg == '-fpdt'):
- cmd = 'fpdt'
- elif(arg == '-usbtopo'):
- cmd = 'usbtopo'
- elif(arg == '-usbauto'):
- cmd = 'usbauto'
- elif(arg == '-status'):
- cmd = 'status'
+ if(sysvals.execcount > 1):
+ doError('-x2 is not compatible with -f', False)
+ if(sysvals.usedevsrc):
+ doError('-dev is not compatible with -f', False)
+ elif(arg == '-addlogs'):
+ sysvals.addlogs = True
elif(arg == '-verbose'):
sysvals.verbose = True
- elif(arg == '-v'):
- print("Version %.1f" % sysvals.version)
- sys.exit()
+ elif(arg == '-dev'):
+ sysvals.usedevsrc = True
+ if(sysvals.usecallgraph):
+ doError('-dev is not compatible with -f', False)
elif(arg == '-rtcwake'):
sysvals.rtcwake = True
sysvals.rtcwaketime = getArgInt('-rtcwake', args, 0, 3600)
+ elif(arg == '-timeprec'):
+ sysvals.setPrecision(getArgInt('-timeprec', args, 0, 6))
+ elif(arg == '-mindev'):
+ sysvals.mindevlen = getArgFloat('-mindev', args, 0.0, 10000.0)
+ elif(arg == '-mincg'):
+ sysvals.mincglen = getArgFloat('-mincg', args, 0.0, 10000.0)
+ elif(arg == '-cmd'):
+ try:
+ val = args.next()
+ except:
+ doError('No command string supplied', True)
+ sysvals.testcommand = val
+ sysvals.suspendmode = 'command'
+ elif(arg == '-expandcg'):
+ sysvals.cgexp = True
+ elif(arg == '-srgap'):
+ sysvals.srgap = 5
elif(arg == '-multi'):
multitest['run'] = True
multitest['count'] = getArgInt('-multi n (exec count)', args, 2, 1000000)
multitest['delay'] = getArgInt('-multi d (delay between tests)', args, 0, 3600)
+ elif(arg == '-o'):
+ try:
+ val = args.next()
+ except:
+ doError('No subdirectory name supplied', True)
+ sysvals.outdir = val
+ elif(arg == '-config'):
+ try:
+ val = args.next()
+ except:
+ doError('No text file supplied', True)
+ if(os.path.exists(val) == False):
+ doError('%s does not exist' % val, False)
+ configFromFile(val)
+ elif(arg == '-fadd'):
+ try:
+ val = args.next()
+ except:
+ doError('No text file supplied', True)
+ if(os.path.exists(val) == False):
+ doError('%s does not exist' % val, False)
+ sysvals.addFtraceFilterFunctions(val)
elif(arg == '-dmesg'):
try:
val = args.next()
@@ -4613,17 +4813,16 @@ if __name__ == '__main__':
sysvals.notestrun = True
sysvals.dmesgfile = val
if(os.path.exists(sysvals.dmesgfile) == False):
- doError('%s doesnt exist' % sysvals.dmesgfile, False)
+ doError('%s does not exist' % sysvals.dmesgfile, False)
elif(arg == '-ftrace'):
try:
val = args.next()
except:
doError('No ftrace file supplied', True)
sysvals.notestrun = True
- sysvals.usecallgraph = True
sysvals.ftracefile = val
if(os.path.exists(sysvals.ftracefile) == False):
- doError('%s doesnt exist' % sysvals.ftracefile, False)
+ doError('%s does not exist' % sysvals.ftracefile, False)
elif(arg == '-summary'):
try:
val = args.next()
@@ -4633,35 +4832,35 @@ if __name__ == '__main__':
cmdarg = val
sysvals.notestrun = True
if(os.path.isdir(val) == False):
- doError('%s isnt accesible' % val, False)
+ doError('%s is not accesible' % val, False)
elif(arg == '-filter'):
try:
val = args.next()
except:
doError('No devnames supplied', True)
sysvals.setDeviceFilter(val)
- elif(arg == '-h'):
- printHelp()
- sys.exit()
else:
doError('Invalid argument: '+arg, True)
+ # callgraph size cannot exceed device size
+ if sysvals.mincglen < sysvals.mindevlen:
+ sysvals.mincglen = sysvals.mindevlen
+
# just run a utility command and exit
if(cmd != ''):
if(cmd == 'status'):
- statusCheck()
+ statusCheck(True)
elif(cmd == 'fpdt'):
- if(sysvals.android):
- doError('cannot read FPDT on android device', False)
getFPDT(True)
elif(cmd == 'usbtopo'):
- if(sysvals.android):
- doError('cannot read USB topology '+\
- 'on an android device', False)
- detectUSB(True)
+ detectUSB()
elif(cmd == 'modes'):
modes = getModes()
print modes
+ elif(cmd == 'flist'):
+ sysvals.getFtraceFilterFunctions(True)
+ elif(cmd == 'flistall'):
+ sysvals.getFtraceFilterFunctions(False)
elif(cmd == 'usbauto'):
setUSBDevicesAuto()
elif(cmd == 'summary'):
@@ -4669,15 +4868,6 @@ if __name__ == '__main__':
runSummary(cmdarg, True)
sys.exit()
- # run test on android device
- if(sysvals.android):
- if(sysvals.usecallgraph):
- doError('ftrace (-f) is not yet supported '+\
- 'in the android kernel', False)
- if(sysvals.notestrun):
- doError('cannot analyze test files on the '+\
- 'android device', False)
-
# if instructed, re-analyze existing data files
if(sysvals.notestrun):
rerunTest()
@@ -4689,18 +4879,20 @@ if __name__ == '__main__':
sys.exit()
if multitest['run']:
- # run multiple tests in a separte subdirectory
+ # run multiple tests in a separate subdirectory
s = 'x%d' % multitest['count']
- subdir = datetime.now().strftime('suspend-'+s+'-%m%d%y-%H%M%S')
- os.mkdir(subdir)
+ if not sysvals.outdir:
+ sysvals.outdir = datetime.now().strftime('suspend-'+s+'-%m%d%y-%H%M%S')
+ if not os.path.isdir(sysvals.outdir):
+ os.mkdir(sysvals.outdir)
for i in range(multitest['count']):
if(i != 0):
print('Waiting %d seconds...' % (multitest['delay']))
time.sleep(multitest['delay'])
print('TEST (%d/%d) START' % (i+1, multitest['count']))
- runTest(subdir)
+ runTest(sysvals.outdir)
print('TEST (%d/%d) COMPLETE' % (i+1, multitest['count']))
- runSummary(subdir, False)
+ runSummary(sysvals.outdir, False)
else:
# run the test in the current directory
- runTest(".")
+ runTest('.', sysvals.outdir)
--
2.1.4
^ permalink raw reply related [flat|nested] 9+ messages in thread* Re: [PATCH 0/5] scripts: AnalyzeSuspend v4.2
2016-07-14 21:09 [PATCH 0/5] scripts: AnalyzeSuspend v4.2 Todd Brandt
` (4 preceding siblings ...)
2016-07-14 21:09 ` [PATCH 5/5] scripts: AnalyzeSuspend v4.2 part5 Todd Brandt
@ 2016-07-14 21:22 ` Rafael J. Wysocki
2016-07-14 21:33 ` Todd Brandt
5 siblings, 1 reply; 9+ messages in thread
From: Rafael J. Wysocki @ 2016-07-14 21:22 UTC (permalink / raw)
To: Todd Brandt; +Cc: Linux PM, Rafael J. Wysocki, Rafael Wysocki, todd.e.brandt
On Thu, Jul 14, 2016 at 11:09 PM, Todd Brandt
<todd.e.brandt@linux.intel.com> wrote:
> AnalyzeSuspend v4.2
>
> kprobe support for function tracing
> config file support in lieu of command line options
> advanced callgraph support for function debug
> dev mode for monitoring common sources of delay, e.g. msleep, udelay
> many bug fixes and formatting upgrades
>
> Todd Brandt (5):
> AnalyzeSuspend v4.2 part1
> AnalyzeSuspend v4.2 part2
> AnalyzeSuspend v4.2 part3
> AnalyzeSuspend v4.2 part4
> AnalyzeSuspend v4.2 part5
>
> scripts/analyze_suspend.py | 3641 ++++++++++++++++++++++++++++++--------------
> 1 file changed, 2474 insertions(+), 1167 deletions(-)
>
> --
Can you please tell me what specifically goes into each of the patches?
Thanks,
Rafael
^ permalink raw reply [flat|nested] 9+ messages in thread* Re: [PATCH 0/5] scripts: AnalyzeSuspend v4.2
2016-07-14 21:22 ` [PATCH 0/5] scripts: AnalyzeSuspend v4.2 Rafael J. Wysocki
@ 2016-07-14 21:33 ` Todd Brandt
2016-07-14 21:37 ` Rafael J. Wysocki
0 siblings, 1 reply; 9+ messages in thread
From: Todd Brandt @ 2016-07-14 21:33 UTC (permalink / raw)
To: Rafael J. Wysocki
Cc: Linux PM, Rafael J. Wysocki, Rafael Wysocki, todd.e.brandt
On Thu, 2016-07-14 at 23:22 +0200, Rafael J. Wysocki wrote:
> On Thu, Jul 14, 2016 at 11:09 PM, Todd Brandt
> <todd.e.brandt@linux.intel.com> wrote:
> > AnalyzeSuspend v4.2
> >
> > kprobe support for function tracing
> > config file support in lieu of command line options
> > advanced callgraph support for function debug
> > dev mode for monitoring common sources of delay, e.g. msleep, udelay
> > many bug fixes and formatting upgrades
> >
> > Todd Brandt (5):
> > AnalyzeSuspend v4.2 part1
> > AnalyzeSuspend v4.2 part2
> > AnalyzeSuspend v4.2 part3
> > AnalyzeSuspend v4.2 part4
> > AnalyzeSuspend v4.2 part5
> >
> > scripts/analyze_suspend.py | 3641 ++++++++++++++++++++++++++++++--------------
> > 1 file changed, 2474 insertions(+), 1167 deletions(-)
> >
> > --
>
> Can you please tell me what specifically goes into each of the patches?
It's just a 5 way splitdiff on the original patch, it seems it was too
large to be accepted on the mailing list as a single patch, so I broke
it into 5 ~1000 line pieces. The patch is just meant to upgrade the
kernel analyze_suspend version from 3.0 to 4.2.
Someone suggested that I do a pull request, but I don't want the
analyze_suspend git log included in the kernel git log, so I'm just
describing the changes by version number in the kernel git log.
When you include the patch just set it to be a single commit message.
>
> Thanks,
> Rafael
^ permalink raw reply [flat|nested] 9+ messages in thread
* Re: [PATCH 0/5] scripts: AnalyzeSuspend v4.2
2016-07-14 21:33 ` Todd Brandt
@ 2016-07-14 21:37 ` Rafael J. Wysocki
0 siblings, 0 replies; 9+ messages in thread
From: Rafael J. Wysocki @ 2016-07-14 21:37 UTC (permalink / raw)
To: Todd Brandt
Cc: Rafael J. Wysocki, Linux PM, Rafael J. Wysocki, Rafael Wysocki,
todd.e.brandt
On Thu, Jul 14, 2016 at 11:33 PM, Todd Brandt
<todd.e.brandt@linux.intel.com> wrote:
> On Thu, 2016-07-14 at 23:22 +0200, Rafael J. Wysocki wrote:
>> On Thu, Jul 14, 2016 at 11:09 PM, Todd Brandt
>> <todd.e.brandt@linux.intel.com> wrote:
>> > AnalyzeSuspend v4.2
>> >
>> > kprobe support for function tracing
>> > config file support in lieu of command line options
>> > advanced callgraph support for function debug
>> > dev mode for monitoring common sources of delay, e.g. msleep, udelay
>> > many bug fixes and formatting upgrades
>> >
>> > Todd Brandt (5):
>> > AnalyzeSuspend v4.2 part1
>> > AnalyzeSuspend v4.2 part2
>> > AnalyzeSuspend v4.2 part3
>> > AnalyzeSuspend v4.2 part4
>> > AnalyzeSuspend v4.2 part5
>> >
>> > scripts/analyze_suspend.py | 3641 ++++++++++++++++++++++++++++++--------------
>> > 1 file changed, 2474 insertions(+), 1167 deletions(-)
>> >
>> > --
>>
>> Can you please tell me what specifically goes into each of the patches?
>
> It's just a 5 way splitdiff on the original patch, it seems it was too
> large to be accepted on the mailing list as a single patch, so I broke
> it into 5 ~1000 line pieces. The patch is just meant to upgrade the
> kernel analyze_suspend version from 3.0 to 4.2.
>
> Someone suggested that I do a pull request, but I don't want the
> analyze_suspend git log included in the kernel git log, so I'm just
> describing the changes by version number in the kernel git log.
>
> When you include the patch just set it to be a single commit message.
OK
I'll fold the 5 into one patch, then.
Thanks!
^ permalink raw reply [flat|nested] 9+ messages in thread