Commit eee77a8a authored by Rafael J. Wysocki's avatar Rafael J. Wysocki
Browse files

Merge branch 'pm-tools'

* pm-tools:
  tools/power/x86: Debug utility for intel_pstate driver
  AnalyzeSuspend: fix drag and zoom bug in javascript
  scripts: analyze_suspend.py: Update to upstream v4.5
  scripts: analyze_suspend.py: Update to upstream v4.4
  scripts: analyze_suspend.py: Update to upstream v4.3
parents fccddb25 48385dd7
......@@ -24,11 +24,6 @@
# 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
......@@ -66,6 +61,8 @@ import platform
from datetime import datetime
import struct
import ConfigParser
from threading import Thread
from subprocess import call, Popen, PIPE
# ----------------- CLASSES --------------------
......@@ -75,11 +72,15 @@ import ConfigParser
# store system values and test parameters
class SystemValues:
ansi = False
version = '4.2'
version = '4.5'
verbose = False
addlogs = False
mindevlen = 0.001
mincglen = 1.0
mindevlen = 0.0
mincglen = 0.0
cgphase = ''
cgtest = -1
callloopmaxgap = 0.0001
callloopmaxlen = 0.005
srgap = 0
cgexp = False
outdir = ''
......@@ -92,6 +93,7 @@ class SystemValues:
'device_pm_callback_end',
'device_pm_callback_start'
]
logmsg = ''
testcommand = ''
mempath = '/dev/mem'
powerfile = '/sys/power/state'
......@@ -117,19 +119,19 @@ class SystemValues:
usetracemarkers = True
usekprobes = True
usedevsrc = False
useprocmon = False
notestrun = False
mixedphaseheight = True
devprops = dict()
postresumetime = 0
predelay = 0
postdelay = 0
procexecfmt = 'ps - (?P<ps>.*)$'
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(),
......@@ -152,44 +154,66 @@ class SystemValues:
'CPU_OFF': {
'func':'_cpu_down',
'args_x86_64': {'cpu':'%di:s32'},
'format': 'CPU_OFF[{cpu}]',
'mask': 'CPU_.*_DOWN'
'format': 'CPU_OFF[{cpu}]'
},
'CPU_ON': {
'func':'_cpu_up',
'args_x86_64': {'cpu':'%di:s32'},
'format': 'CPU_ON[{cpu}]',
'mask': 'CPU_.*_UP'
'format': 'CPU_ON[{cpu}]'
},
}
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(),
'msleep': { 'args_x86_64': {'time':'%di:s32'}, 'ub': 1 },
'schedule_timeout_uninterruptible': { 'args_x86_64': {'timeout':'%di:s32'}, 'ub': 1 },
'schedule_timeout': { 'args_x86_64': {'timeout':'%di:s32'}, 'ub': 1 },
'udelay': { 'func':'__const_udelay', 'args_x86_64': {'loops':'%di:s32'}, 'ub': 1 },
'usleep_range': { 'args_x86_64': {'min':'%di:s32', 'max':'%si:s32'}, 'ub': 1 },
'mutex_lock_slowpath': { 'func':'__mutex_lock_slowpath', 'ub': 1 },
'acpi_os_stall': {'ub': 1},
# ACPI
'acpi_resume_power_resources': dict(),
'acpi_ps_parse_aml': dict(),
# filesystem
'ext4_sync_fs': dict(),
# 80211
'iwlagn_mac_start': dict(),
'iwlagn_alloc_bcast_station': dict(),
'iwl_trans_pcie_start_hw': dict(),
'iwl_trans_pcie_start_fw': dict(),
'iwl_run_init_ucode': dict(),
'iwl_load_ucode_wait_alive': dict(),
'iwl_alive_start': dict(),
'iwlagn_mac_stop': dict(),
'iwlagn_mac_suspend': dict(),
'iwlagn_mac_resume': dict(),
'iwlagn_mac_add_interface': dict(),
'iwlagn_mac_remove_interface': dict(),
'iwlagn_mac_change_interface': dict(),
'iwlagn_mac_config': dict(),
'iwlagn_configure_filter': dict(),
'iwlagn_mac_hw_scan': dict(),
'iwlagn_bss_info_changed': dict(),
'iwlagn_mac_channel_switch': dict(),
'iwlagn_mac_flush': dict(),
# ATA
'ata_eh_recover': { 'args_x86_64': {'port':'+36(%di):s32'} },
# i915
'i915_gem_restore_gtt_mappings': dict(),
'i915_gem_resume': dict(),
'i915_restore_state': dict(),
'intel_opregion_setup': dict(),
'g4x_pre_enable_dp': dict(),
'vlv_pre_enable_dp': dict(),
'chv_pre_enable_dp': dict(),
'g4x_enable_dp': dict(),
'vlv_enable_dp': dict(),
'intel_hpd_init': dict(),
'intel_opregion_register': dict(),
'intel_dp_detect': dict(),
'intel_hdmi_detect': dict(),
'intel_opregion_init': dict(),
'intel_fbdev_set_suspend': 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):
......@@ -198,6 +222,7 @@ class SystemValues:
self.embedded = True
self.addlogs = True
self.htmlfile = os.environ['LOG_FILE']
self.archargs = 'args_'+platform.machine()
self.hostname = platform.node()
if(self.hostname == ''):
self.hostname = 'localhost'
......@@ -214,6 +239,13 @@ class SystemValues:
if num < 0 or num > 6:
return
self.timeformat = '%.{0}f'.format(num)
def setOutputFolder(self, value):
args = dict()
n = datetime.now()
args['date'] = n.strftime('%y%m%d')
args['time'] = n.strftime('%H%M%S')
args['hostname'] = self.hostname
self.outdir = value.format(**args)
def setOutputFile(self):
if((self.htmlfile == '') and (self.dmesgfile != '')):
m = re.match('(?P<name>.*)_dmesg\.txt$', self.dmesgfile)
......@@ -253,10 +285,14 @@ class SystemValues:
self.testdir+'/'+self.prefix+'_'+self.suspendmode+'.html'
if not os.path.isdir(self.testdir):
os.mkdir(self.testdir)
def setDeviceFilter(self, devnames):
self.devicefilter = string.split(devnames)
def setDeviceFilter(self, value):
self.devicefilter = []
if value:
value = value.split(',')
for i in value:
self.devicefilter.append(i.strip())
def rtcWakeAlarmOn(self):
os.system('echo 0 > '+self.rtcpath+'/wakealarm')
call('echo 0 > '+self.rtcpath+'/wakealarm', shell=True)
outD = open(self.rtcpath+'/date', 'r').read().strip()
outT = open(self.rtcpath+'/time', 'r').read().strip()
mD = re.match('^(?P<y>[0-9]*)-(?P<m>[0-9]*)-(?P<d>[0-9]*)', outD)
......@@ -272,12 +308,12 @@ class SystemValues:
# if hardware time fails, use the software time
nowtime = int(datetime.now().strftime('%s'))
alarm = nowtime + self.rtcwaketime
os.system('echo %d > %s/wakealarm' % (alarm, self.rtcpath))
call('echo %d > %s/wakealarm' % (alarm, self.rtcpath), shell=True)
def rtcWakeAlarmOff(self):
os.system('echo 0 > %s/wakealarm' % self.rtcpath)
call('echo 0 > %s/wakealarm' % self.rtcpath, shell=True)
def initdmesg(self):
# get the latest time stamp from the dmesg log
fp = os.popen('dmesg')
fp = Popen('dmesg', stdout=PIPE).stdout
ktime = '0'
for line in fp:
line = line.replace('\r\n', '')
......@@ -291,7 +327,7 @@ class SystemValues:
self.dmesgstart = float(ktime)
def getdmesg(self):
# store all new dmesg lines since initdmesg was called
fp = os.popen('dmesg')
fp = Popen('dmesg', stdout=PIPE).stdout
op = open(self.dmesgfile, 'a')
for line in fp:
line = line.replace('\r\n', '')
......@@ -317,25 +353,18 @@ class SystemValues:
def getFtraceFilterFunctions(self, current):
rootCheck(True)
if not current:
os.system('cat '+self.tpath+'available_filter_functions')
call('cat '+self.tpath+'available_filter_functions', shell=True)
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)
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')
......@@ -351,22 +380,15 @@ class SystemValues:
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}
self.kprobes[name] = {'name': name,'func': name,'args': dict(),'format': name}
def defaultKprobe(self, name, kdata):
k = kdata
for field in ['name', 'format', 'mask', 'func']:
for field in ['name', 'format', 'func']:
if field not in k:
k[field] = name
archargs = 'args_'+platform.machine()
if archargs in k:
k['args'] = k[archargs]
if self.archargs in k:
k['args'] = k[self.archargs]
else:
k['args'] = dict()
k['format'] = name
......@@ -403,49 +425,80 @@ class SystemValues:
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']
def kprobeText(self, kname, kprobe):
name = fmt = func = kname
args = dict()
if 'name' in kprobe:
name = kprobe['name']
if 'format' in kprobe:
fmt = kprobe['format']
if 'func' in kprobe:
func = kprobe['func']
if self.archargs in kprobe:
args = kprobe[self.archargs]
if 'args' in kprobe:
args = 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)
doError('Kprobe "%s" has format info in the function name "%s"' % (name, func))
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)
doError('Kprobe "%s" is missing argument "%s"' % (name, arg))
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):
def addKprobes(self, output=False):
if len(sysvals.kprobes) < 1:
return
if output:
print(' kprobe functions in this kernel:')
# first test each kprobe
print('INITIALIZING KPROBES...')
rejects = []
# sort kprobes: trace, ub-dev, custom, dev
kpl = [[], [], [], []]
for name in sorted(self.kprobes):
if not self.testKprobe(self.kprobes[name]):
res = self.colorText('YES', 32)
if not self.testKprobe(name, self.kprobes[name]):
res = self.colorText('NO')
rejects.append(name)
else:
if name in self.tracefuncs:
kpl[0].append(name)
elif name in self.dev_tracefuncs:
if 'ub' in self.dev_tracefuncs[name]:
kpl[1].append(name)
else:
kpl[3].append(name)
else:
kpl[2].append(name)
if output:
print(' %s: %s' % (name, res))
kplist = kpl[0] + kpl[1] + kpl[2] + kpl[3]
# remove all failed ones from the list
for name in rejects:
vprint('Skipping KPROBE: %s' % name)
self.kprobes.pop(name)
# set the kprobes all at once
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])
for kp in kplist:
kprobeevents += self.kprobeText(kp, 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')
linesout = len(kprobeevents.split('\n')) - 1
linesack = len(check.split('\n')) - 1
if output:
res = '%d/%d' % (linesack, linesout)
if linesack < linesout:
res = self.colorText(res, 31)
else:
res = self.colorText(res, 32)
print(' working kprobe functions enabled: %s' % res)
self.fsetVal('1', 'events/kprobes/enable')
def testKprobe(self, kprobe):
kprobeevents = self.kprobeText(kprobe)
def testKprobe(self, kname, kprobe):
self.fsetVal('0', 'events/kprobes/enable')
kprobeevents = self.kprobeText(kname, kprobe)
if not kprobeevents:
return False
try:
......@@ -463,8 +516,9 @@ class SystemValues:
if not os.path.exists(file):
return False
try:
fp = open(file, mode)
fp = open(file, mode, 0)
fp.write(val)
fp.flush()
fp.close()
except:
pass
......@@ -491,21 +545,17 @@ class SystemValues:
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:
if len(self.tracefuncs) < 1 and self.suspendmode == 'command':
return True
funclist = []
for i in self.tracefuncs:
if 'func' in self.tracefuncs[i]:
funclist.append(self.tracefuncs[i]['func'])
f = self.tracefuncs[i]['func']
else:
funclist.append(i)
if name in funclist:
return True
f = i
if name == f:
return True
return False
def initFtrace(self, testing=False):
tp = self.tpath
print('INITIALIZING FTRACE...')
# turn trace off
self.fsetVal('0', 'tracing_on')
......@@ -518,18 +568,7 @@ class SystemValues:
# 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
# initialize the callgraph trace
if(self.usecallgraph):
# set trace type
self.fsetVal('function_graph', 'current_tracer')
......@@ -545,20 +584,24 @@ class SystemValues:
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)
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)
# initialize the kprobe trace
elif self.usekprobes:
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])
print('INITIALIZING KPROBES...')
self.addKprobes(self.verbose)
if(self.usetraceevents):
# turn trace events on
events = iter(self.traceevents)
......@@ -590,10 +633,10 @@ class SystemValues:
if(os.path.exists(tp+f) == False):
return False
return True
def colorText(self, str):
def colorText(self, str, color=31):
if not self.ansi:
return str
return '\x1B[31;40m'+str+'\x1B[m'
return '\x1B[%d;40m%s\x1B[m' % (color, str)
sysvals = SystemValues()
......@@ -625,8 +668,8 @@ class DevProps:
if self.xtraclass:
return ' '+self.xtraclass
if self.async:
return ' async'
return ' sync'
return ' async_device'
return ' sync_device'
# Class: DeviceNode
# Description:
......@@ -646,8 +689,6 @@ class DeviceNode:
# The primary container for suspend/resume test data. There is one for
# each test run. The data is organized into a cronological hierarchy:
# Data.dmesg {
# root structure, started as dmesg & ftrace, but now only ftrace
# contents: times for suspend start/end, resume start/end, fwdata
# phases {
# 10 sequential, non-overlapping phases of S/R
# contents: times for phase start/end, order/color data for html
......@@ -658,7 +699,7 @@ class DeviceNode:
# contents: start/stop times, pid/cpu/driver info
# parents/children, html id for timeline/callgraph
# optionally includes an ftrace callgraph
# optionally includes intradev trace events
# optionally includes dev/ps data
# }
# }
# }
......@@ -671,19 +712,24 @@ class Data:
end = 0.0 # test end
tSuspended = 0.0 # low-level suspend start
tResumed = 0.0 # low-level resume start
tKernSus = 0.0 # kernel level suspend start
tKernRes = 0.0 # kernel level resume end
tLow = 0.0 # time spent in low-level suspend (standby/freeze)
fwValid = False # is firmware data available
fwSuspend = 0 # time spent in firmware suspend
fwResume = 0 # time spent in firmware resume
dmesgtext = [] # dmesg text file in memory
pstl = 0 # process timeline
testnumber = 0
idstr = ''
html_device_id = 0
stamp = 0
outfile = ''
dev_ubiquitous = ['msleep', 'udelay']
devpids = []
kerror = False
def __init__(self, num):
idchar = 'abcdefghijklmnopqrstuvwxyz'
idchar = 'abcdefghij'
self.pstl = dict()
self.testnumber = num
self.idstr = idchar[num]
self.dmesgtext = []
......@@ -714,16 +760,39 @@ class Data:
self.devicegroups = []
for phase in self.phases:
self.devicegroups.append([phase])
def getStart(self):
return self.dmesg[self.phases[0]]['start']
self.errorinfo = {'suspend':[],'resume':[]}
def extractErrorInfo(self, dmesg):
error = ''
tm = 0.0
for i in range(len(dmesg)):
if 'Call Trace:' in dmesg[i]:
m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) .*', dmesg[i])
if not m:
continue
tm = float(m.group('ktime'))
if tm < self.start or tm > self.end:
continue
for j in range(i-10, i+1):
error += dmesg[j]
continue
if error:
m = re.match('[ \t]*\[ *[0-9\.]*\] \[\<[0-9a-fA-F]*\>\] .*', dmesg[i])
if m:
error += dmesg[i]
else:
if tm < self.tSuspended:
dir = 'suspend'
else:
dir = 'resume'
error = error.replace('<', '&lt').replace('>', '&gt')
vprint('kernel error found in %s at %f' % (dir, tm))
self.errorinfo[dir].append((tm, error))
self.kerror = True
error = ''
def setStart(self, time):
self.start = time
self.dmesg[self.phases[0]]['start'] = time
def getEnd(self):
return self.dmesg[self.phases[-1]]['end']
def setEnd(self, time):
self.end = time
self.dmesg[self.phases[-1]]['end'] = time
def isTraceEventOutsideDeviceCalls(self, pid, time):
for phase in self.phases:
list = self.dmesg[phase]['list']
......@@ -733,39 +802,67 @@ class Data:
time < d['end']):
return False
return True
def targetDevice(self, phaselist, start, end, pid=-1):
def sourcePhase(self, start):
for phase in self.phases:
pend = self.dmesg[phase]['end']
if start <= pend:
return phase
return 'resume_complete'
def sourceDevice(self, phaselist, start, end, pid, type):
tgtdev = ''
for phase in phaselist:
list = self.dmesg[phase]['list']
for devname in list:
dev = list[devname]
if(pid >= 0 and dev['pid'] != pid):
# pid must match
if dev['pid'] != pid:
continue
devS = dev['start']
devE = dev['end']
if(start < devS or start >= devE or end <= devS or end > devE):
continue
if type == 'device':