blob: cfe343306e08c0348de9d7a3ae5e18c65c8c62d9 [file] [log] [blame]
#!/usr/bin/env python3
# SPDX-License-Identifier: GPL-2.0-only
#
# Tool for analyzing suspend/resume timing
# Copyright (c) 2013, Intel Corporation.
#
# This program is free software; you can redistribute it and/or modify it
# under the terms and conditions of the GNU General Public License,
# version 2, as published by the Free Software Foundation.
#
# This program is distributed in the hope it will be useful, but WITHOUT
# ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
# FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License for
# more details.
#
# Authors:
# Todd Brandt <todd.e.brandt@linux.intel.com>
#
# Links:
# Home Page
# https://01.org/pm-graph
# Source repo
# git@github.com:intel/pm-graph
#
# 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
# with a few extra options enabled, the tool will execute a suspend and
# will capture dmesg and ftrace data until resume is complete. This data
# is transformed into a device timeline and a callgraph to give a quick
# and detailed view of which devices and callbacks are taking the most
# time in suspend/resume. The output is a single html file which can be
# viewed in firefox or chrome.
#
# The following kernel build options are required:
# CONFIG_DEVMEM=y
# CONFIG_PM_DEBUG=y
# CONFIG_PM_SLEEP_DEBUG=y
# 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:
# (e.g. in file /etc/default/grub)
# GRUB_CMDLINE_LINUX_DEFAULT="... initcall_debug log_buf_len=16M ..."
#
# ----------------- LIBRARIES --------------------
import sys
import time
import os
import string
import re
import platform
import signal
import codecs
from datetime import datetime, timedelta
import struct
import configparser
import gzip
from threading import Thread
from subprocess import call, Popen, PIPE
import base64
debugtiming = False
mystarttime = time.time()
def pprint(msg):
if debugtiming:
print('[%09.3f] %s' % (time.time()-mystarttime, msg))
else:
print(msg)
sys.stdout.flush()
def ascii(text):
return text.decode('ascii', 'ignore')
# ----------------- CLASSES --------------------
# Class: SystemValues
# Description:
# A global, single-instance container used to
# store system values and test parameters
class SystemValues:
title = 'SleepGraph'
version = '5.10'
ansi = False
rs = 0
display = ''
gzip = False
sync = False
wifi = False
netfix = False
verbose = False
testlog = True
dmesglog = True
ftracelog = False
acpidebug = True
tstat = True
wifitrace = False
mindevlen = 0.0001
mincglen = 0.0
cgphase = ''
cgtest = -1
cgskip = ''
maxfail = 0
multitest = {'run': False, 'count': 1000000, 'delay': 0}
max_graph_depth = 0
callloopmaxgap = 0.0001
callloopmaxlen = 0.005
bufsize = 0
cpucount = 0
memtotal = 204800
memfree = 204800
osversion = ''
srgap = 0
cgexp = False
testdir = ''
outdir = ''
tpath = '/sys/kernel/debug/tracing/'
fpdtpath = '/sys/firmware/acpi/tables/FPDT'
epath = '/sys/kernel/debug/tracing/events/power/'
pmdpath = '/sys/power/pm_debug_messages'
s0ixpath = '/sys/module/intel_pmc_core/parameters/warn_on_s0ix_failures'
s0ixres = '/sys/devices/system/cpu/cpuidle/low_power_idle_system_residency_us'
acpipath='/sys/module/acpi/parameters/debug_level'
traceevents = [
'suspend_resume',
'wakeup_source_activate',
'wakeup_source_deactivate',
'device_pm_callback_end',
'device_pm_callback_start'
]
logmsg = ''
testcommand = ''
mempath = '/dev/mem'
powerfile = '/sys/power/state'
mempowerfile = '/sys/power/mem_sleep'
diskpowerfile = '/sys/power/disk'
suspendmode = 'mem'
memmode = ''
diskmode = ''
hostname = 'localhost'
prefix = 'test'
teststamp = ''
sysstamp = ''
dmesgstart = 0.0
dmesgfile = ''
ftracefile = ''
htmlfile = 'output.html'
result = ''
rtcwake = True
rtcwaketime = 15
rtcpath = ''
devicefilter = []
cgfilter = []
stamp = 0
execcount = 1
x2delay = 0
skiphtml = False
usecallgraph = False
ftopfunc = 'pm_suspend'
ftop = False
usetraceevents = False
usetracemarkers = True
useftrace = True
usekprobes = True
usedevsrc = False
useprocmon = False
notestrun = False
cgdump = False
devdump = False
mixedphaseheight = True
devprops = dict()
cfgdef = dict()
platinfo = []
predelay = 0
postdelay = 0
tmstart = 'SUSPEND START %Y%m%d-%H:%M:%S.%f'
tmend = 'RESUME COMPLETE %Y%m%d-%H:%M:%S.%f'
tracefuncs = {
'async_synchronize_full': {},
'sys_sync': {},
'ksys_sync': {},
'__pm_notifier_call_chain': {},
'pm_prepare_console': {},
'pm_notifier_call_chain': {},
'freeze_processes': {},
'freeze_kernel_threads': {},
'pm_restrict_gfp_mask': {},
'acpi_suspend_begin': {},
'acpi_hibernation_begin': {},
'acpi_hibernation_enter': {},
'acpi_hibernation_leave': {},
'acpi_pm_freeze': {},
'acpi_pm_thaw': {},
'acpi_s2idle_end': {},
'acpi_s2idle_sync': {},
'acpi_s2idle_begin': {},
'acpi_s2idle_prepare': {},
'acpi_s2idle_prepare_late': {},
'acpi_s2idle_wake': {},
'acpi_s2idle_wakeup': {},
'acpi_s2idle_restore': {},
'acpi_s2idle_restore_early': {},
'hibernate_preallocate_memory': {},
'create_basic_memory_bitmaps': {},
'swsusp_write': {},
'suspend_console': {},
'acpi_pm_prepare': {},
'syscore_suspend': {},
'arch_enable_nonboot_cpus_end': {},
'syscore_resume': {},
'acpi_pm_finish': {},
'resume_console': {},
'acpi_pm_end': {},
'pm_restore_gfp_mask': {},
'thaw_processes': {},
'pm_restore_console': {},
'CPU_OFF': {
'func':'_cpu_down',
'args_x86_64': {'cpu':'%di:s32'},
'format': 'CPU_OFF[{cpu}]'
},
'CPU_ON': {
'func':'_cpu_up',
'args_x86_64': {'cpu':'%di:s32'},
'format': 'CPU_ON[{cpu}]'
},
}
dev_tracefuncs = {
# general wait/delay/sleep
'msleep': { 'args_x86_64': {'time':'%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},
'rt_mutex_slowlock': {'ub': 1},
# ACPI
'acpi_resume_power_resources': {},
'acpi_ps_execute_method': { 'args_x86_64': {
'fullpath':'+0(+40(%di)):string',
}},
# mei_me
'mei_reset': {},
# filesystem
'ext4_sync_fs': {},
# 80211
'ath10k_bmi_read_memory': { 'args_x86_64': {'length':'%cx:s32'} },
'ath10k_bmi_write_memory': { 'args_x86_64': {'length':'%cx:s32'} },
'ath10k_bmi_fast_download': { 'args_x86_64': {'length':'%cx:s32'} },
'iwlagn_mac_start': {},
'iwlagn_alloc_bcast_station': {},
'iwl_trans_pcie_start_hw': {},
'iwl_trans_pcie_start_fw': {},
'iwl_run_init_ucode': {},
'iwl_load_ucode_wait_alive': {},
'iwl_alive_start': {},
'iwlagn_mac_stop': {},
'iwlagn_mac_suspend': {},
'iwlagn_mac_resume': {},
'iwlagn_mac_add_interface': {},
'iwlagn_mac_remove_interface': {},
'iwlagn_mac_change_interface': {},
'iwlagn_mac_config': {},
'iwlagn_configure_filter': {},
'iwlagn_mac_hw_scan': {},
'iwlagn_bss_info_changed': {},
'iwlagn_mac_channel_switch': {},
'iwlagn_mac_flush': {},
# ATA
'ata_eh_recover': { 'args_x86_64': {'port':'+36(%di):s32'} },
# i915
'i915_gem_resume': {},
'i915_restore_state': {},
'intel_opregion_setup': {},
'g4x_pre_enable_dp': {},
'vlv_pre_enable_dp': {},
'chv_pre_enable_dp': {},
'g4x_enable_dp': {},
'vlv_enable_dp': {},
'intel_hpd_init': {},
'intel_opregion_register': {},
'intel_dp_detect': {},
'intel_hdmi_detect': {},
'intel_opregion_init': {},
'intel_fbdev_set_suspend': {},
}
infocmds = [
[0, 'sysinfo', 'uname', '-a'],
[0, 'cpuinfo', 'head', '-7', '/proc/cpuinfo'],
[0, 'kparams', 'cat', '/proc/cmdline'],
[0, 'mcelog', 'mcelog'],
[0, 'pcidevices', 'lspci', '-tv'],
[0, 'usbdevices', 'lsusb', '-tv'],
[0, 'acpidevices', 'sh', '-c', 'ls -l /sys/bus/acpi/devices/*/physical_node'],
[0, 's0ix_require', 'cat', '/sys/kernel/debug/pmc_core/substate_requirements'],
[0, 's0ix_debug', 'cat', '/sys/kernel/debug/pmc_core/slp_s0_debug_status'],
[1, 's0ix_residency', 'cat', '/sys/kernel/debug/pmc_core/slp_s0_residency_usec'],
[1, 'interrupts', 'cat', '/proc/interrupts'],
[1, 'wakeups', 'cat', '/sys/kernel/debug/wakeup_sources'],
[2, 'gpecounts', 'sh', '-c', 'grep -v invalid /sys/firmware/acpi/interrupts/*'],
[2, 'suspendstats', 'sh', '-c', 'grep -v invalid /sys/power/suspend_stats/*'],
[2, 'cpuidle', 'sh', '-c', 'grep -v invalid /sys/devices/system/cpu/cpu*/cpuidle/state*/s2idle/*'],
[2, 'battery', 'sh', '-c', 'grep -v invalid /sys/class/power_supply/*/*'],
[2, 'thermal', 'sh', '-c', 'grep . /sys/class/thermal/thermal_zone*/temp'],
]
cgblacklist = []
kprobes = dict()
timeformat = '%.3f'
cmdline = '%s %s' % \
(os.path.basename(sys.argv[0]), ' '.join(sys.argv[1:]))
sudouser = ''
def __init__(self):
self.archargs = 'args_'+platform.machine()
self.hostname = platform.node()
if(self.hostname == ''):
self.hostname = 'localhost'
rtc = "rtc0"
if os.path.exists('/dev/rtc'):
rtc = os.readlink('/dev/rtc')
rtc = '/sys/class/rtc/'+rtc
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
self.testdir = datetime.now().strftime('suspend-%y%m%d-%H%M%S')
if os.getuid() == 0 and 'SUDO_USER' in os.environ and \
os.environ['SUDO_USER']:
self.sudouser = os.environ['SUDO_USER']
def resetlog(self):
self.logmsg = ''
self.platinfo = []
def vprint(self, msg):
self.logmsg += msg+'\n'
if self.verbose or msg.startswith('WARNING:'):
pprint(msg)
def signalHandler(self, signum, frame):
if not self.result:
return
signame = self.signames[signum] if signum in self.signames else 'UNKNOWN'
msg = 'Signal %s caused a tool exit, line %d' % (signame, frame.f_lineno)
self.outputResult({'error':msg})
sys.exit(3)
def signalHandlerInit(self):
capture = ['BUS', 'SYS', 'XCPU', 'XFSZ', 'PWR', 'HUP', 'INT', 'QUIT',
'ILL', 'ABRT', 'FPE', 'SEGV', 'TERM']
self.signames = dict()
for i in capture:
s = 'SIG'+i
try:
signum = getattr(signal, s)
signal.signal(signum, self.signalHandler)
except:
continue
self.signames[signum] = s
def rootCheck(self, fatal=True):
if(os.access(self.powerfile, os.W_OK)):
return True
if fatal:
msg = 'This command requires sysfs mount and root access'
pprint('ERROR: %s\n' % msg)
self.outputResult({'error':msg})
sys.exit(1)
return False
def rootUser(self, fatal=False):
if 'USER' in os.environ and os.environ['USER'] == 'root':
return True
if fatal:
msg = 'This command must be run as root'
pprint('ERROR: %s\n' % msg)
self.outputResult({'error':msg})
sys.exit(1)
return False
def usable(self, file, ishtml=False):
if not os.path.exists(file) or os.path.getsize(file) < 1:
return False
if ishtml:
try:
fp = open(file, 'r')
res = fp.read(1000)
fp.close()
except:
return False
if '<html>' not in res:
return False
return True
def getExec(self, cmd):
try:
fp = Popen(['which', cmd], stdout=PIPE, stderr=PIPE).stdout
out = ascii(fp.read()).strip()
fp.close()
except:
out = ''
if out:
return out
for path in ['/sbin', '/bin', '/usr/sbin', '/usr/bin',
'/usr/local/sbin', '/usr/local/bin']:
cmdfull = os.path.join(path, cmd)
if os.path.exists(cmdfull):
return cmdfull
return out
def setPrecision(self, num):
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'] = args['host'] = self.hostname
args['mode'] = self.suspendmode
return value.format(**args)
def setOutputFile(self):
if self.dmesgfile != '':
m = re.match('(?P<name>.*)_dmesg\.txt.*', self.dmesgfile)
if(m):
self.htmlfile = m.group('name')+'.html'
if self.ftracefile != '':
m = re.match('(?P<name>.*)_ftrace\.txt.*', self.ftracefile)
if(m):
self.htmlfile = m.group('name')+'.html'
def systemInfo(self, info):
p = m = ''
if 'baseboard-manufacturer' in info:
m = info['baseboard-manufacturer']
elif 'system-manufacturer' in info:
m = info['system-manufacturer']
if 'system-product-name' in info:
p = info['system-product-name']
elif 'baseboard-product-name' in info:
p = info['baseboard-product-name']
if m[:5].lower() == 'intel' and 'baseboard-product-name' in info:
p = info['baseboard-product-name']
c = info['processor-version'] if 'processor-version' in info else ''
b = info['bios-version'] if 'bios-version' in info else ''
r = info['bios-release-date'] if 'bios-release-date' in info else ''
self.sysstamp = '# sysinfo | man:%s | plat:%s | cpu:%s | bios:%s | biosdate:%s | numcpu:%d | memsz:%d | memfr:%d' % \
(m, p, c, b, r, self.cpucount, self.memtotal, self.memfree)
if self.osversion:
self.sysstamp += ' | os:%s' % self.osversion
def printSystemInfo(self, fatal=False):
self.rootCheck(True)
out = dmidecode(self.mempath, fatal)
if len(out) < 1:
return
fmt = '%-24s: %s'
if self.osversion:
print(fmt % ('os-version', self.osversion))
for name in sorted(out):
print(fmt % (name, out[name]))
print(fmt % ('cpucount', ('%d' % self.cpucount)))
print(fmt % ('memtotal', ('%d kB' % self.memtotal)))
print(fmt % ('memfree', ('%d kB' % self.memfree)))
def cpuInfo(self):
self.cpucount = 0
if os.path.exists('/proc/cpuinfo'):
with open('/proc/cpuinfo', 'r') as fp:
for line in fp:
if re.match('^processor[ \t]*:[ \t]*[0-9]*', line):
self.cpucount += 1
if os.path.exists('/proc/meminfo'):
with open('/proc/meminfo', 'r') as fp:
for line in fp:
m = re.match('^MemTotal:[ \t]*(?P<sz>[0-9]*) *kB', line)
if m:
self.memtotal = int(m.group('sz'))
m = re.match('^MemFree:[ \t]*(?P<sz>[0-9]*) *kB', line)
if m:
self.memfree = int(m.group('sz'))
if os.path.exists('/etc/os-release'):
with open('/etc/os-release', 'r') as fp:
for line in fp:
if line.startswith('PRETTY_NAME='):
self.osversion = line[12:].strip().replace('"', '')
def initTestOutput(self, name):
self.prefix = self.hostname
v = open('/proc/version', 'r').read().strip()
kver = v.split()[2]
fmt = name+'-%m%d%y-%H%M%S'
testtime = datetime.now().strftime(fmt)
self.teststamp = \
'# '+testtime+' '+self.prefix+' '+self.suspendmode+' '+kver
ext = ''
if self.gzip:
ext = '.gz'
self.dmesgfile = \
self.testdir+'/'+self.prefix+'_'+self.suspendmode+'_dmesg.txt'+ext
self.ftracefile = \
self.testdir+'/'+self.prefix+'_'+self.suspendmode+'_ftrace.txt'+ext
self.htmlfile = \
self.testdir+'/'+self.prefix+'_'+self.suspendmode+'.html'
if not os.path.isdir(self.testdir):
os.makedirs(self.testdir)
self.sudoUserchown(self.testdir)
def getValueList(self, value):
out = []
for i in value.split(','):
if i.strip():
out.append(i.strip())
return out
def setDeviceFilter(self, value):
self.devicefilter = self.getValueList(value)
def setCallgraphFilter(self, value):
self.cgfilter = self.getValueList(value)
def skipKprobes(self, value):
for k in self.getValueList(value):
if k in self.tracefuncs:
del self.tracefuncs[k]
if k in self.dev_tracefuncs:
del self.dev_tracefuncs[k]
def setCallgraphBlacklist(self, file):
self.cgblacklist = self.listFromFile(file)
def rtcWakeAlarmOn(self):
call('echo 0 > '+self.rtcpath+'/wakealarm', shell=True)
nowtime = open(self.rtcpath+'/since_epoch', 'r').read().strip()
if nowtime:
nowtime = int(nowtime)
else:
# if hardware time fails, use the software time
nowtime = int(datetime.now().strftime('%s'))
alarm = nowtime + self.rtcwaketime
call('echo %d > %s/wakealarm' % (alarm, self.rtcpath), shell=True)
def rtcWakeAlarmOff(self):
call('echo 0 > %s/wakealarm' % self.rtcpath, shell=True)
def initdmesg(self):
# get the latest time stamp from the dmesg log
lines = Popen('dmesg', stdout=PIPE).stdout.readlines()
ktime = '0'
for line in reversed(lines):
line = ascii(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')
break
self.dmesgstart = float(ktime)
def getdmesg(self, testdata):
op = self.writeDatafileHeader(self.dmesgfile, testdata)
# store all new dmesg lines since initdmesg was called
fp = Popen('dmesg', stdout=PIPE).stdout
for line in fp:
line = ascii(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 listFromFile(self, file):
list = []
fp = open(file)
for i in fp.read().split('\n'):
i = i.strip()
if i and i[0] != '#':
list.append(i)
fp.close()
return list
def addFtraceFilterFunctions(self, file):
for i in self.listFromFile(file):
if len(i) < 2:
continue
self.tracefuncs[i] = dict()
def getFtraceFilterFunctions(self, current):
self.rootCheck(True)
if not current:
call('cat '+self.tpath+'available_filter_functions', shell=True)
return
master = self.listFromFile(self.tpath+'available_filter_functions')
for i in sorted(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):
master = self.listFromFile(self.tpath+'available_filter_functions')
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 basicKprobe(self, name):
self.kprobes[name] = {'name': name,'func': name,'args': dict(),'format': name}
def defaultKprobe(self, name, kdata):
k = kdata
for field in ['name', 'format', 'func']:
if field not in k:
k[field] = name
if self.archargs in k:
k['args'] = k[self.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, 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))
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))
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, output=False):
if len(self.kprobes) < 1:
return
if output:
pprint(' kprobe functions in this kernel:')
# first test each kprobe
rejects = []
# sort kprobes: trace, ub-dev, custom, dev
kpl = [[], [], [], []]
linesout = len(self.kprobes)
for name in sorted(self.kprobes):
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:
pprint(' %s: %s' % (name, res))
kplist = kpl[0] + kpl[1] + kpl[2] + kpl[3]
# remove all failed ones from the list
for name in rejects:
self.kprobes.pop(name)
# set the kprobes all at once
self.fsetVal('', 'kprobe_events')
kprobeevents = ''
for kp in kplist:
kprobeevents += self.kprobeText(kp, self.kprobes[kp])
self.fsetVal(kprobeevents, 'kprobe_events')
if output:
check = self.fgetVal('kprobe_events')
linesack = (len(check.split('\n')) - 1) // 2
pprint(' kprobe functions enabled: %d/%d' % (linesack, linesout))
self.fsetVal('1', 'events/kprobes/enable')
def testKprobe(self, kname, kprobe):
self.fsetVal('0', 'events/kprobes/enable')
kprobeevents = self.kprobeText(kname, 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 setVal(self, val, file):
if not os.path.exists(file):
return False
try:
fp = open(file, 'wb', 0)
fp.write(val.encode())
fp.flush()
fp.close()
except:
return False
return True
def fsetVal(self, val, path):
if not self.useftrace:
return False
return self.setVal(val, self.tpath+path)
def getVal(self, file):
res = ''
if not os.path.exists(file):
return res
try:
fp = open(file, 'r')
res = fp.read()
fp.close()
except:
pass
return res
def fgetVal(self, path):
if not self.useftrace:
return ''
return self.getVal(self.tpath+path)
def cleanupFtrace(self):
if self.useftrace:
self.fsetVal('0', 'events/kprobes/enable')
self.fsetVal('', 'kprobe_events')
self.fsetVal('1024', 'buffer_size_kb')
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.tracefuncs) < 1 and self.suspendmode == 'command':
return True
for i in self.tracefuncs:
if 'func' in self.tracefuncs[i]:
f = self.tracefuncs[i]['func']
else:
f = i
if name == f:
return True
return False
def initFtrace(self, quiet=False):
if not self.useftrace:
return
if not quiet:
sysvals.printSystemInfo(False)
pprint('INITIALIZING FTRACE')
# turn trace off
self.fsetVal('0', 'tracing_on')
self.cleanupFtrace()
# set the trace clock to global
self.fsetVal('global', 'trace_clock')
self.fsetVal('nop', 'current_tracer')
# set trace buffer to an appropriate value
cpus = max(1, self.cpucount)
if self.bufsize > 0:
tgtsize = self.bufsize
elif self.usecallgraph or self.usedevsrc:
bmax = (1*1024*1024) if self.suspendmode in ['disk', 'command'] \
else (3*1024*1024)
tgtsize = min(self.memfree, bmax)
else:
tgtsize = 65536
while not self.fsetVal('%d' % (tgtsize // cpus), 'buffer_size_kb'):
# if the size failed to set, lower it and keep trying
tgtsize -= 65536
if tgtsize < 65536:
tgtsize = int(self.fgetVal('buffer_size_kb')) * cpus
break
self.vprint('Setting trace buffers to %d kB (%d kB per cpu)' % (tgtsize, tgtsize/cpus))
# initialize the callgraph trace
if(self.usecallgraph):
# set trace type
self.fsetVal('function_graph', 'current_tracer')
self.fsetVal('', 'set_ftrace_filter')
# temporary hack to fix https://bugzilla.kernel.org/show_bug.cgi?id=212761
fp = open(self.tpath+'set_ftrace_notrace', 'w')
fp.write('native_queued_spin_lock_slowpath\ndev_driver_string')
fp.close()
# 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('%d' % self.max_graph_depth, 'max_graph_depth')
cf = ['dpm_run_callback']
if(self.usetraceevents):
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)
if self.ftop:
self.setFtraceFilterFunctions([self.ftopfunc])
else:
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])
if not quiet:
pprint('INITIALIZING KPROBES')
self.addKprobes(self.verbose)
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, color=31):
if not self.ansi:
return str
return '\x1B[%d;40m%s\x1B[m' % (color, str)
def writeDatafileHeader(self, filename, testdata):
fp = self.openlog(filename, 'w')
fp.write('%s\n%s\n# command | %s\n' % (self.teststamp, self.sysstamp, self.cmdline))
for test in testdata:
if 'fw' in test:
fw = test['fw']
if(fw):
fp.write('# fwsuspend %u fwresume %u\n' % (fw[0], fw[1]))
if 'turbo' in test:
fp.write('# turbostat %s\n' % test['turbo'])
if 'wifi' in test:
fp.write('# wifi %s\n' % test['wifi'])
if 'netfix' in test:
fp.write('# netfix %s\n' % test['netfix'])
if test['error'] or len(testdata) > 1:
fp.write('# enter_sleep_error %s\n' % test['error'])
return fp
def sudoUserchown(self, dir):
if os.path.exists(dir) and self.sudouser:
cmd = 'chown -R {0}:{0} {1} > /dev/null 2>&1'
call(cmd.format(self.sudouser, dir), shell=True)
def outputResult(self, testdata, num=0):
if not self.result:
return
n = ''
if num > 0:
n = '%d' % num
fp = open(self.result, 'a')
if 'error' in testdata:
fp.write('result%s: fail\n' % n)
fp.write('error%s: %s\n' % (n, testdata['error']))
else:
fp.write('result%s: pass\n' % n)
if 'mode' in testdata:
fp.write('mode%s: %s\n' % (n, testdata['mode']))
for v in ['suspend', 'resume', 'boot', 'lastinit']:
if v in testdata:
fp.write('%s%s: %.3f\n' % (v, n, testdata[v]))
for v in ['fwsuspend', 'fwresume']:
if v in testdata:
fp.write('%s%s: %.3f\n' % (v, n, testdata[v] / 1000000.0))
if 'bugurl' in testdata:
fp.write('url%s: %s\n' % (n, testdata['bugurl']))
fp.close()
self.sudoUserchown(self.result)
def configFile(self, file):
dir = os.path.dirname(os.path.realpath(__file__))
if os.path.exists(file):
return file
elif os.path.exists(dir+'/'+file):
return dir+'/'+file
elif os.path.exists(dir+'/config/'+file):
return dir+'/config/'+file
return ''
def openlog(self, filename, mode):
isgz = self.gzip
if mode == 'r':
try:
with gzip.open(filename, mode+'t') as fp:
test = fp.read(64)
isgz = True
except:
isgz = False
if isgz:
return gzip.open(filename, mode+'t')
return open(filename, mode)
def putlog(self, filename, text):
with self.openlog(filename, 'a') as fp:
fp.write(text)
fp.close()
def dlog(self, text):
if not self.dmesgfile:
return
self.putlog(self.dmesgfile, '# %s\n' % text)
def flog(self, text):
self.putlog(self.ftracefile, text)
def b64unzip(self, data):
try:
out = codecs.decode(base64.b64decode(data), 'zlib').decode()
except:
out = data
return out
def b64zip(self, data):
out = base64.b64encode(codecs.encode(data.encode(), 'zlib')).decode()
return out
def platforminfo(self, cmdafter):
# add platform info on to a completed ftrace file
if not os.path.exists(self.ftracefile):
return False
footer = '#\n'
# add test command string line if need be
if self.suspendmode == 'command' and self.testcommand:
footer += '# platform-testcmd: %s\n' % (self.testcommand)
# get a list of target devices from the ftrace file
props = dict()
tp = TestProps()
tf = self.openlog(self.ftracefile, 'r')
for line in tf:
if tp.stampInfo(line, self):
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
dev = m.group('d')
if dev not in props:
props[dev] = DevProps()
tf.close()
# now get the syspath for each target device
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 sorted(props):
dirname = props[dev].syspath
if not dirname or not os.path.exists(dirname):
continue
props[dev].isasync = False
if os.path.exists(dirname+'/power/async'):
fp = open(dirname+'/power/async')
if 'enabled' in fp.read():
props[dev].isasync = True
fp.close()
fields = os.listdir(dirname)
for file in ['product', 'name', 'model', 'description', 'id', 'idVendor']:
if file not in fields:
continue
try:
with open(os.path.join(dirname, file), 'rb') as fp:
props[dev].altname = ascii(fp.read())
except:
continue
if file == 'idVendor':
idv, idp = props[dev].altname.strip(), ''
try:
with open(os.path.join(dirname, 'idProduct'), 'rb') as fp:
idp = ascii(fp.read()).strip()
except:
props[dev].altname = ''
break
props[dev].altname = '%s:%s' % (idv, idp)
break
if props[dev].altname:
out = props[dev].altname.strip().replace('\n', ' ')\
.replace(',', ' ').replace(';', ' ')
props[dev].altname = out
# add a devinfo line to the bottom of ftrace
out = ''
for dev in sorted(props):
out += props[dev].out(dev)
footer += '# platform-devinfo: %s\n' % self.b64zip(out)
# add a line for each of these commands with their outputs
for name, cmdline, info in cmdafter:
footer += '# platform-%s: %s | %s\n' % (name, cmdline, self.b64zip(info))
self.flog(footer)
return True
def commonPrefix(self, list):
if len(list) < 2:
return ''
prefix = list[0]
for s in list[1:]:
while s[:len(prefix)] != prefix and prefix:
prefix = prefix[:len(prefix)-1]
if not prefix:
break
if '/' in prefix and prefix[-1] != '/':
prefix = prefix[0:prefix.rfind('/')+1]
return prefix
def dictify(self, text, format):
out = dict()
header = True if format == 1 else False
delim = ' ' if format == 1 else ':'
for line in text.split('\n'):
if header:
header, out['@'] = False, line
continue
line = line.strip()
if delim in line:
data = line.split(delim, 1)
num = re.search(r'[\d]+', data[1])
if format == 2 and num:
out[data[0].strip()] = num.group()
else:
out[data[0].strip()] = data[1]
return out
def cmdinfo(self, begin, debug=False):
out = []
if begin:
self.cmd1 = dict()
for cargs in self.infocmds:
delta, name = cargs[0], cargs[1]
cmdline, cmdpath = ' '.join(cargs[2:]), self.getExec(cargs[2])
if not cmdpath or (begin and not delta):
continue
self.dlog('[%s]' % cmdline)
try:
fp = Popen([cmdpath]+cargs[3:], stdout=PIPE, stderr=PIPE).stdout
info = ascii(fp.read()).strip()
fp.close()
except:
continue
if not debug and begin:
self.cmd1[name] = self.dictify(info, delta)
elif not debug and delta and name in self.cmd1:
before, after = self.cmd1[name], self.dictify(info, delta)
dinfo = ('\t%s\n' % before['@']) if '@' in before and len(before) > 1 else ''
prefix = self.commonPrefix(list(before.keys()))
for key in sorted(before):
if key in after and before[key] != after[key]:
title = key.replace(prefix, '')
if delta == 2:
dinfo += '\t%s : %s -> %s\n' % \
(title, before[key].strip(), after[key].strip())
else:
dinfo += '%10s (start) : %s\n%10s (after) : %s\n' % \
(title, before[key], title, after[key])
dinfo = '\tnothing changed' if not dinfo else dinfo.rstrip()
out.append((name, cmdline, dinfo))
else:
out.append((name, cmdline, '\tnothing' if not info else info))
return out
def testVal(self, file, fmt='basic', value=''):
if file == 'restoreall':
for f in self.cfgdef:
if os.path.exists(f):
fp = open(f, 'w')
fp.write(self.cfgdef[f])
fp.close()
self.cfgdef = dict()
elif value and os.path.exists(file):
fp = open(file, 'r+')
if fmt == 'radio':
m = re.match('.*\[(?P<v>.*)\].*', fp.read())
if m:
self.cfgdef[file] = m.group('v')
elif fmt == 'acpi':
line = fp.read().strip().split('\n')[-1]
m = re.match('.* (?P<v>[0-9A-Fx]*) .*', line)
if m:
self.cfgdef[file] = m.group('v')
else:
self.cfgdef[file] = fp.read().strip()
fp.write(value)
fp.close()
def s0ixSupport(self):
if not os.path.exists(self.s0ixres) or not os.path.exists(self.mempowerfile):
return False
fp = open(sysvals.mempowerfile, 'r')
data = fp.read().strip()
fp.close()
if '[s2idle]' in data:
return True
return False
def haveTurbostat(self):
if not self.tstat:
return False
cmd = self.getExec('turbostat')
if not cmd:
return False
fp = Popen([cmd, '-v'], stdout=PIPE, stderr=PIPE).stderr
out = ascii(fp.read()).strip()
fp.close()
if re.match('turbostat version .*', out):
self.vprint(out)
return True
return False
def turbostat(self, s0ixready):
cmd = self.getExec('turbostat')
rawout = keyline = valline = ''
fullcmd = '%s -q -S echo freeze > %s' % (cmd, self.powerfile)
fp = Popen(['sh', '-c', fullcmd], stdout=PIPE, stderr=PIPE).stderr
for line in fp:
line = ascii(line)
rawout += line
if keyline and valline:
continue
if re.match('(?i)Avg_MHz.*', line):
keyline = line.strip().split()
elif keyline:
valline = line.strip().split()
fp.close()
if not keyline or not valline or len(keyline) != len(valline):
errmsg = 'unrecognized turbostat output:\n'+rawout.strip()
self.vprint(errmsg)
if not self.verbose:
pprint(errmsg)
return ''
if self.verbose:
pprint(rawout.strip())
out = []
for key in keyline:
idx = keyline.index(key)
val = valline[idx]
if key == 'SYS%LPI' and not s0ixready and re.match('^[0\.]*$', val):
continue
out.append('%s=%s' % (key, val))
return '|'.join(out)
def netfixon(self, net='both'):
cmd = self.getExec('netfix')
if not cmd:
return ''
fp = Popen([cmd, '-s', net, 'on'], stdout=PIPE, stderr=PIPE).stdout
out = ascii(fp.read()).strip()
fp.close()
return out
def wifiDetails(self, dev):
try:
info = open('/sys/class/net/%s/device/uevent' % dev, 'r').read().strip()
except:
return dev
vals = [dev]
for prop in info.split('\n'):
if prop.startswith('DRIVER=') or prop.startswith('PCI_ID='):
vals.append(prop.split('=')[-1])
return ':'.join(vals)
def checkWifi(self, dev=''):
try:
w = open('/proc/net/wireless', 'r').read().strip()
except:
return ''
for line in reversed(w.split('\n')):
m = re.match(' *(?P<dev>.*): (?P<stat>[0-9a-f]*) .*', line)
if not m or (dev and dev != m.group('dev')):
continue
return m.group('dev')
return ''
def pollWifi(self, dev, timeout=10):
start = time.time()
while (time.time() - start) < timeout:
w = self.checkWifi(dev)
if w:
return '%s reconnected %.2f' % \
(self.wifiDetails(dev), max(0, time.time() - start))
time.sleep(0.01)
return '%s timeout %d' % (self.wifiDetails(dev), timeout)
def errorSummary(self, errinfo, msg):
found = False
for entry in errinfo:
if re.match(entry['match'], msg):
entry['count'] += 1
if self.hostname not in entry['urls']:
entry['urls'][self.hostname] = [self.htmlfile]
elif self.htmlfile not in entry['urls'][self.hostname]:
entry['urls'][self.hostname].append(self.htmlfile)
found = True
break
if found:
return
arr = msg.split()
for j in range(len(arr)):
if re.match('^[0-9,\-\.]*$', arr[j]):
arr[j] = '[0-9,\-\.]*'
else:
arr[j] = arr[j]\
.replace('\\', '\\\\').replace(']', '\]').replace('[', '\[')\
.replace('.', '\.').replace('+', '\+').replace('*', '\*')\
.replace('(', '\(').replace(')', '\)').replace('}', '\}')\
.replace('{', '\{')
mstr = ' *'.join(arr)
entry = {
'line': msg,
'match': mstr,
'count': 1,
'urls': {self.hostname: [self.htmlfile]}
}
errinfo.append(entry)
def multistat(self, start, idx, finish):
if 'time' in self.multitest:
id = '%d Duration=%dmin' % (idx+1, self.multitest['time'])
else:
id = '%d/%d' % (idx+1, self.multitest['count'])
t = time.time()
if 'start' not in self.multitest:
self.multitest['start'] = self.multitest['last'] = t
self.multitest['total'] = 0.0
pprint('TEST (%s) START' % id)
return
dt = t - self.multitest['last']
if not start:
if idx == 0 and self.multitest['delay'] > 0:
self.multitest['total'] += self.multitest['delay']
pprint('TEST (%s) COMPLETE -- Duration %.1fs' % (id, dt))
return
self.multitest['total'] += dt
self.multitest['last'] = t
avg = self.multitest['total'] / idx
if 'time' in self.multitest:
left = finish - datetime.now()
left -= timedelta(microseconds=left.microseconds)
else:
left = timedelta(seconds=((self.multitest['count'] - idx) * int(avg)))
pprint('TEST (%s) START - Avg Duration %.1fs, Time left %s' % \
(id, avg, str(left)))
def multiinit(self, c, d):
sz, unit = 'count', 'm'
if c.endswith('d') or c.endswith('h') or c.endswith('m'):
sz, unit, c = 'time', c[-1], c[:-1]
self.multitest['run'] = True
self.multitest[sz] = getArgInt('multi: n d (exec count)', c, 1, 1000000, False)
self.multitest['delay'] = getArgInt('multi: n d (delay between tests)', d, 0, 3600, False)
if unit == 'd':
self.multitest[sz] *= 1440
elif unit == 'h':
self.multitest[sz] *= 60
def displayControl(self, cmd):
xset, ret = 'timeout 10 xset -d :0.0 {0}', 0
if self.sudouser:
xset = 'sudo -u %s %s' % (self.sudouser, xset)
if cmd == 'init':
ret = call(xset.format('dpms 0 0 0'), shell=True)
if not ret:
ret = call(xset.format('s off'), shell=True)
elif cmd == 'reset':
ret = call(xset.format('s reset'), shell=True)
elif cmd in ['on', 'off', 'standby', 'suspend']:
b4 = self.displayControl('stat')
ret = call(xset.format('dpms force %s' % cmd), shell=True)
if not ret:
curr = self.displayControl('stat')
self.vprint('Display Switched: %s -> %s' % (b4, curr))
if curr != cmd:
self.vprint('WARNING: Display failed to change to %s' % cmd)
if ret:
self.vprint('WARNING: Display failed to change to %s with xset' % cmd)
return ret
elif cmd == 'stat':
fp = Popen(xset.format('q').split(' '), stdout=PIPE).stdout
ret = 'unknown'
for line in fp:
m = re.match('[\s]*Monitor is (?P<m>.*)', ascii(line))
if(m and len(m.group('m')) >= 2):
out = m.group('m').lower()
ret = out[3:] if out[0:2] == 'in' else out
break
fp.close()
return ret
def setRuntimeSuspend(self, before=True):
if before:
# runtime suspend disable or enable
if self.rs > 0:
self.rstgt, self.rsval, self.rsdir = 'on', 'auto', 'enabled'
else:
self.rstgt, self.rsval, self.rsdir = 'auto', 'on', 'disabled'
pprint('CONFIGURING RUNTIME SUSPEND...')
self.rslist = deviceInfo(self.rstgt)
for i in self.rslist:
self.setVal(self.rsval, i)
pprint('runtime suspend %s on all devices (%d changed)' % (self.rsdir, len(self.rslist)))
pprint('waiting 5 seconds...')
time.sleep(5)
else:
# runtime suspend re-enable or re-disable
for i in self.rslist:
self.setVal(self.rstgt, i)
pprint('runtime suspend settings restored on %d devices' % len(self.rslist))
def start(self, pm):
if self.useftrace:
self.dlog('start ftrace tracing')
self.fsetVal('1', 'tracing_on')
if self.useprocmon:
self.dlog('start the process monitor')
pm.start()
def stop(self, pm):
if self.useftrace:
if self.useprocmon:
self.dlog('stop the process monitor')
pm.stop()
self.dlog('stop ftrace tracing')
self.fsetVal('0', 'tracing_on')
sysvals = SystemValues()
switchvalues = ['enable', 'disable', 'on', 'off', 'true', 'false', '1', '0']
switchoff = ['disable', 'off', 'false', '0']
suspendmodename = {
'standby': 'standby (S1)',
'freeze': 'freeze (S2idle)',
'mem': 'suspend (S3)',
'disk': 'hibernate (S4)'
}
# Class: DevProps
# Description:
# Simple class which holds property values collected
# for all the devices used in the timeline.
class DevProps:
def __init__(self):
self.syspath = ''
self.altname = ''
self.isasync = True
self.xtraclass = ''
self.xtrainfo = ''
def out(self, dev):
return '%s,%s,%d;' % (dev, self.altname, self.isasync)
def debug(self, dev):
pprint('%s:\n\taltname = %s\n\t async = %s' % (dev, self.altname, self.isasync))
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.isasync:
return ' sync'
return ''
def xtraInfo(self):
if self.xtraclass:
return ' '+self.xtraclass
if self.isasync:
return ' (async)'
return ' (sync)'
# Class: DeviceNode
# Description:
# A container used to create a device hierachy, with a single root node
# and a tree of child nodes. Used by Data.deviceTopology()
class DeviceNode:
def __init__(self, nodename, nodedepth):
self.name = nodename
self.children = []
self.depth = nodedepth
# Class: Data
# Description:
# 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 {
# phases {
# 10 sequential, non-overlapping phases of S/R
# contents: times for phase start/end, order/color data for html
# devlist {
# device callback or action list for this phase
# device {
# a single device callback or generic action
# contents: start/stop times, pid/cpu/driver info
# parents/children, html id for timeline/callgraph
# optionally includes an ftrace callgraph
# optionally includes dev/ps data
# }
# }
# }
# }
#
class Data:
phasedef = {
'suspend_prepare': {'order': 0, 'color': '#CCFFCC'},
'suspend': {'order': 1, 'color': '#88FF88'},
'suspend_late': {'order': 2, 'color': '#00AA00'},
'suspend_noirq': {'order': 3, 'color': '#008888'},
'suspend_machine': {'order': 4, 'color': '#0000FF'},
'resume_machine': {'order': 5, 'color': '#FF0000'},
'resume_noirq': {'order': 6, 'color': '#FF9900'},
'resume_early': {'order': 7, 'color': '#FFCC00'},
'resume': {'order': 8, 'color': '#FFFF88'},
'resume_complete': {'order': 9, 'color': '#FFFFCC'},
}
errlist = {
'HWERROR' : r'.*\[ *Hardware Error *\].*',
'FWBUG' : r'.*\[ *Firmware Bug *\].*',
'BUG' : r'(?i).*\bBUG\b.*',
'ERROR' : r'(?i).*\bERROR\b.*',
'WARNING' : r'(?i).*\bWARNING\b.*',
'FAULT' : r'(?i).*\bFAULT\b.*',
'FAIL' : r'(?i).*\bFAILED\b.*',
'INVALID' : r'(?i).*\bINVALID\b.*',
'CRASH' : r'(?i).*\bCRASHED\b.*',
'TIMEOUT' : r'(?i).*\bTIMEOUT\b.*',
'ABORT' : r'(?i).*\bABORT\b.*',
'IRQ' : r'.*\bgenirq: .*',
'TASKFAIL': r'.*Freezing of tasks *.*',
'ACPI' : r'.*\bACPI *(?P<b>[A-Za-z]*) *Error[: ].*',
'DISKFULL': r'.*\bNo space left on device.*',
'USBERR' : r'.*usb .*device .*, error [0-9-]*',
'ATAERR' : r' *ata[0-9\.]*: .*failed.*',
'MEIERR' : r' *mei.*: .*failed.*',
'TPMERR' : r'(?i) *tpm *tpm[0-9]*: .*error.*',
}
def __init__(self, num):
idchar = 'abcdefghij'
self.start = 0.0 # test start
self.end = 0.0 # test end
self.hwstart = 0 # rtc test start
self.hwend = 0 # rtc test end
self.tSuspended = 0.0 # low-level suspend start
self.tResumed = 0.0 # low-level resume start
self.tKernSus = 0.0 # kernel level suspend start
self.tKernRes = 0.0 # kernel level resume end
self.fwValid = False # is firmware data available
self.fwSuspend = 0 # time spent in firmware suspend
self.fwResume = 0 # time spent in firmware resume
self.html_device_id = 0
self.stamp = 0
self.outfile = ''
self.kerror = False
self.wifi = dict()
self.turbostat = 0
self.enterfail = ''
self.currphase = ''
self.pstl = dict() # process timeline
self.testnumber = num
self.idstr = idchar[num]
self.dmesgtext = [] # dmesg text file in memory
self.dmesg = dict() # root data structure
self.errorinfo = {'suspend':[],'resume':[]}
self.tLow = [] # time spent in low-level suspends (standby/freeze)
self.devpids = []
self.devicegroups = 0
def sortedPhases(self):
return sorted(self.dmesg, key=lambda k:self.dmesg[k]['order'])
def initDevicegroups(self):
# called when phases are all finished being added
for phase in sorted(self.dmesg.keys()):
if '*' in phase:
p = phase.split('*')
pnew = '%s%d' % (p[0], len(p))
self.dmesg[pnew] = self.dmesg.pop(phase)
self.devicegroups = []
for phase in self.sortedPhases():
self.devicegroups.append([phase])
def nextPhase(self, phase, offset):
order = self.dmesg[phase]['order'] + offset
for p in self.dmesg:
if self.dmesg[p]['order'] == order:
return p
return ''
def lastPhase(self, depth=1):
plist = self.sortedPhases()
if len(plist) < depth:
return ''
return plist[-1*depth]
def turbostatInfo(self):
tp = TestProps()
out = {'syslpi':'N/A','pkgpc10':'N/A'}
for line in self.dmesgtext:
m = re.match(tp.tstatfmt, line)
if not m:
continue
for i in m.group('t').split('|'):
if 'SYS%LPI' in i:
out['syslpi'] = i.split('=')[-1]+'%'
elif 'pc10' in i:
out['pkgpc10'] = i.split('=')[-1]+'%'
break
return out
def extractErrorInfo(self):
lf = self.dmesgtext
if len(self.dmesgtext) < 1 and sysvals.dmesgfile:
lf = sysvals.openlog(sysvals.dmesgfile, 'r')
i = 0
tp = TestProps()
list = []
for line in lf:
i += 1
if tp.stampInfo(line, sysvals):
continue
m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line)
if not m:
continue
t = float(m.group('ktime'))
if t < self.start or t > self.end:
continue
dir = 'suspend' if t < self.tSuspended else 'resume'
msg = m.group('msg')
if re.match('capability: warning: .*', msg):
continue
for err in self.errlist:
if re.match(self.errlist[err], msg):
list.append((msg, err, dir, t, i, i))
self.kerror = True
break
tp.msglist = []
for msg, type, dir, t, idx1, idx2 in list:
tp.msglist.append(msg)
self.errorinfo[dir].append((type, t, idx1, idx2))
if self.kerror:
sysvals.dmesglog = True
if len(self.dmesgtext) < 1 and sysvals.dmesgfile:
lf.close()
return tp
def setStart(self, time, msg=''):
self.start = time
if msg:
try:
self.hwstart = datetime.strptime(msg, sysvals.tmstart)
except:
self.hwstart = 0
def setEnd(self, time, msg=''):
self.end = time
if msg:
try:
self.hwend = datetime.strptime(msg, sysvals.tmend)
except:
self.hwend = 0
def isTraceEventOutsideDeviceCalls(self, pid, time):
for phase in self.sortedPhases():
list = self.dmesg[phase]['list']
for dev in list:
d = list[dev]
if(d['pid'] == pid and time >= d['start'] and
time < d['end']):
return False
return True
def sourcePhase(self, start):
for phase in self.sortedPhases():
if 'machine' in phase:
continue
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]
# pid must match
if dev['pid'] != pid:
continue
devS = dev['start']
devE = dev['end']
if type == 'device':
# device target event is entirely inside the source boundary
if(start < devS or start >= devE or end <= devS or end > devE):
continue
elif type == 'thread':
# thread target event will expand the source boundary
if start < devS:
dev['start'] = start
if end > devE:
dev['end'] = end
tgtdev = dev
break
return tgtdev
def addDeviceFunctionCall(self, displayname, kprobename, proc, pid, start, end, cdata, rdata):
# try to place the call in a device
phases = self.sortedPhases()
tgtdev = self.sourceDevice(phases, start, end, pid, 'device')
# calls with device pids that occur outside device bounds are dropped
# TODO: include these somehow
if not tgtdev and pid in self.devpids:
return False
# try to place the call in a thread
if not tgtdev:
tgtdev = self.sourceDevice(phases, start, end, pid, 'thread')
# create new thread blocks, expand as new calls are found
if not tgtdev:
if proc == '<...>':
threadname = 'kthread-%d' % (pid)
else:
threadname = '%s-%d' % (proc, pid)
tgtphase = self.sourcePhase(start)
self.newAction(tgtphase, threadname, pid, '', start, end, '', ' kth', '')
return self.addDeviceFunctionCall(displayname, kprobename, proc, pid, start, end, cdata, rdata)
# this should not happen
if not tgtdev:
sysvals.vprint('[%f - %f] %s-%d %s %s %s' % \
(start, end, proc, pid, kprobename, cdata, rdata))
return False
# place the call data inside the src element of the tgtdev
if('src' not in tgtdev):
tgtdev['src'] = []
dtf = sysvals.dev_tracefuncs
ubiquitous = False
if kprobename in dtf and 'ub' in dtf[kprobename]:
ubiquitous = True
mc = re.match('\(.*\) *(?P<args>.*)', cdata)
mr = re.match('\((?P<caller>\S*).* arg1=(?P<ret>.*)', rdata)
if mc and mr:
c = mr.group('caller').split('+')[0]
a = mc.group('args').strip()
r = mr.group('ret')
if len(r) > 6:
r = ''
else:
r = 'ret=%s ' % r
if ubiquitous and c in dtf and 'ub' in dtf[c]:
return False
else:
return False
color = sysvals.kprobeColor(kprobename)
e = DevFunction(displayname, a, c, r, start, end, ubiquitous, proc, pid, color)
tgtdev['src'].append(e)
return True
def overflowDevices(self):
# get a list of devices that extend beyond the end of this test run
devlist = []
for phase in self.sortedPhases():
list = self.dmesg[phase]['list']
for devname in list:
dev = list[devname]
if dev['end'] > self.end:
devlist.append(dev)
return devlist
def mergeOverlapDevices(self, devlist):
# merge any devices that overlap devlist
for dev in devlist:
devname = dev['name']
for phase in self.sortedPhases():
list = self.dmesg[phase]['list']
if devname not in list:
continue
tdev = list[devname]
o = min(dev['end'], tdev['end']) - max(dev['start'], tdev['start'])
if o <= 0:
continue
dev['end'] = tdev['end']
if 'src' not in dev or 'src' not in tdev:
continue
dev['src'] += tdev['src']
del list[devname]
def usurpTouchingThread(self, name, dev):
# the caller test has priority of this thread, give it to him
for phase in self.sortedPhases():
list = self.dmesg[phase]['list']
if name in list:
tdev = list[name]
if tdev['start'] - dev['end'] < 0.1:
dev['end'] = tdev['end']
if 'src' not in dev:
dev['src'] = []
if 'src' in tdev:
dev['src'] += tdev['src']
del list[name]
break
def stitchTouchingThreads(self, testlist):
# merge any threads between tests that touch
for phase in self.sortedPhases():
list = self.dmesg[phase]['list']
for devname in list:
dev = list[devname]
if 'htmlclass' not in dev or 'kth' not in dev['htmlclass']:
continue
for data in testlist:
data.usurpTouchingThread(devname, dev)
def optimizeDevSrc(self):
# merge any src call loops to reduce timeline size
for phase in self.sortedPhases():
list = self.dmesg[phase]['list']
for dev in list:
if 'src' not in list[dev]:
continue
src = list[dev]['src']
p = 0
for e in sorted(src, key=lambda event: event.time):
if not p or not e.repeat(p):
p = e
continue
# e is another iteration of p, move it into p
p.end = e.end
p.length = p.end - p.time
p.count += 1
src.remove(e)
def trimTimeVal(self, t, t0, dT, left):
if left:
if(t > t0):
if(t - dT < t0):
return t0
return t - dT
else:
return t
else:
if(t < t0 + dT):
if(t > t0):
return t0 + dT
return t + dT
else:
return t
def trimTime(self, t0, dT, left):
self.tSuspended = self.trimTimeVal(self.tSuspended, t0, dT, left)
self.tResumed = self.trimTimeVal(self.tResumed, t0, dT, left)
self.start = self.trimTimeVal(self.start, t0, dT, left)
self.tKernSus = self.trimTimeVal(self.tKernSus, t0, dT, left)
self.tKernRes = self.trimTimeVal(self.tKernRes, t0, dT, left)
self.end = self.trimTimeVal(self.end, t0, dT, left)
for phase in self.sortedPhases():
p = self.dmesg[phase]
p['start'] = self.trimTimeVal(p['start'], t0, dT, left)
p['end'] = self.trimTimeVal(p['end'], t0, dT, left)
list = p['list']
for name in list:
d = list[name]
d['start'] = self.trimTimeVal(d['start'], t0, dT, left)
d['end'] = self.trimTimeVal(d['end'], t0, dT, left)
d['length'] = d['end'] - d['start']
if('ftrace' in d):
cg = d['ftrace']
cg.start = self.trimTimeVal(cg.start, t0, dT, left)
cg.end = self.trimTimeVal(cg.end, t0, dT, left)
for line in cg.list:
line.time = self.trimTimeVal(line.time, t0, dT, left)
if('src' in d):
for e in d['src']:
e.time = self.trimTimeVal(e.time, t0, dT, left)
e.end = self.trimTimeVal(e.end, t0, dT, left)
e.length = e.end - e.time
if('cpuexec' in d):
cpuexec = dict()
for e in d['cpuexec']:
c0, cN = e
c0 = self.trimTimeVal(c0, t0, dT, left)
cN = self.trimTimeVal(cN, t0, dT, left)
cpuexec[(c0, cN)] = d['cpuexec'][e]
d['cpuexec'] = cpuexec
for dir in ['suspend', 'resume']:
list = []
for e in self.errorinfo[dir]:
type, tm, idx1, idx2 = e
tm = self.trimTimeVal(tm, t0, dT, left)
list.append((type, tm, idx1, idx2))
self.errorinfo[dir] = list
def trimFreezeTime(self, tZero):
# trim out any standby or freeze clock time
lp = ''
for phase in self.sortedPhases():
if 'resume_machine' in phase and 'suspend_machine' in lp:
tS, tR = self.dmesg[lp]['end'], self.dmesg[phase]['start']
tL = tR - tS
if tL <= 0:
continue
left = True if tR > tZero else False
self.trimTime(tS, tL, left)
if 'waking' in self.dmesg[lp]:
tCnt = self.dmesg[lp]['waking'][0]
if self.dmesg[lp]['waking'][1] >= 0.001:
tTry = '%.0f' % (round(self.dmesg[lp]['waking'][1] * 1000))
else:
tTry = '%.3f' % (self.dmesg[lp]['waking'][1] * 1000)
text = '%.0f (%s ms waking %d times)' % (tL * 1000, tTry, tCnt)
else:
text = '%.0f' % (tL * 1000)
self.tLow.append(text)
lp = phase
def getMemTime(self):
if not self.hwstart or not self.hwend:
return
stime = (self.tSuspended - self.start) * 1000000
rtime = (self.end - self.tResumed) * 1000000
hws = self.hwstart + timedelta(microseconds=stime)
hwr = self.hwend - timedelta(microseconds=rtime)
self.tLow.append('%.0f'%((hwr - hws).total_seconds() * 1000))
def getTimeValues(self):
sktime = (self.tSuspended - self.tKernSus) * 1000
rktime = (self.tKernRes - self.tResumed) * 1000
return (sktime, rktime)
def setPhase(self, phase, ktime, isbegin, order=-1):
if(isbegin):
# phase start over current phase
if self.currphase:
if 'resume_machine' not in self.currphase:
sysvals.vprint('WARNING: phase %s failed to end' % self.currphase)
self.dmesg[self.currphase]['end'] = ktime
phases = self.dmesg.keys()
color = self.phasedef[phase]['color']
count = len(phases) if order < 0 else order
# create unique name for every new phase
while phase in phases:
phase += '*'
self.dmesg[phase] = {'list': dict(), 'start': -1.0, 'end': -1.0,
'row': 0, 'color': color, 'order': count}
self.dmesg[phase]['start'] = ktime
self.currphase = phase
else:
# phase end without a start
if phase not in self.currphase:
if self.currphase:
sysvals.vprint('WARNING: %s ended instead of %s, ftrace corruption?' % (phase, self.currphase))
else:
sysvals.vprint('WARNING: %s ended without a start, ftrace corruption?' % phase)
return phase
phase = self.currphase
self.dmesg[phase]['end'] = ktime
self.currphase = ''
return phase
def sortedDevices(self, phase):
list = self.dmesg[phase]['list']
return sorted(list, key=lambda k:list[k]['start'])
def fixupInitcalls(self, phase):
# if any calls never returned, clip them at system resume end
phaselist = self.dmesg[phase]['list']
for devname in phaselist:
dev = phaselist[devname]
if(dev['end'] < 0):
for p in self.sortedPhases():
if self.dmesg[p]['end'] > dev['start']:
dev['end'] = self.dmesg[p]['end']
break
sysvals.vprint('%s (%s): callback didnt return' % (devname, phase))
def deviceFilter(self, devicefilter):
for phase in self.sortedPhases():
list = self.dmesg[phase]['list']
rmlist = []
for name in list:
keep = False
for filter in devicefilter:
if filter in name or \
('drv' in list[name] and filter in list[name]['drv']):
keep = True
if not keep:
rmlist.append(name)
for name in rmlist:
del list[name]
def fixupInitcallsThatDidntReturn(self):
# if any calls never returned, clip them at system resume end
for phase in self.sortedPhases():
self.fixupInitcalls(phase)
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=''):
# which phase is this device callback or action in
phases = self.sortedPhases()
targetphase = 'none'
htmlclass = ''
overlap = 0.0
myphases = []
for phase in phases:
pstart = self.dmesg[phase]['start']
pend = self.dmesg[phase]['end']
# see if the action overlaps this phase
o = max(0, min(end, pend) - max(start, pstart))
if o > 0:
myphases.append(phase)
# set the target phase to the one that overlaps most
if o > overlap:
if overlap > 0 and phase == 'post_resume':
continue
targetphase = phase
overlap = o
# if no target phase was found, pin it to the edge
if targetphase == 'none':
p0start = self.dmesg[phases[0]]['start']
if start <= p0start:
targetphase = phases[0]
else:
targetphase = phases[-1]
if pid == -2:
htmlclass = ' bg'
elif pid == -3:
htmlclass = ' ps'
if len(myphases) > 1:
htmlclass = ' bg'
self.phaseOverlap(myphases)
if targetphase in phases:
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, htmlclass='', color=''):
# new device callback for a specific phase
self.html_device_id += 1
devid = '%s%d' % (self.idstr, self.html_device_id)
list = self.dmesg[phase]['list']
length = -1.0
if(start >= 0 and end >= 0):
length = end - start
if pid == -2 or name not in sysvals.tracefuncs.keys():
i = 2
origname = name
while(name in list):
name = '%s[%d]' % (origname, i)
i += 1
list[name] = {'name': 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 findDevice(self, phase, name):
list = self.dmesg[phase]['list']
mydev = ''
for devname in sorted(list):
if name == devname or re.match('^%s\[(?P<num>[0-9]*)\]$' % name, devname):
mydev = devname
if mydev:
return list[mydev]
return False
def deviceChildren(self, devname, phase):
devlist = []
list = self.dmesg[phase]['list']
for child in list:
if(list[child]['par'] == devname):
devlist.append(child)
return devlist
def maxDeviceNameSize(self, phase):
size = 0
for name in self.dmesg[phase]['list']:
if len(name) > size:
size = len(name)
return size
def printDetails(self):
sysvals.vprint('Timeline Details:')
sysvals.vprint(' test start: %f' % self.start)
sysvals.vprint('kernel suspend start: %f' % self.tKernSus)
tS = tR = False
for phase in self.sortedPhases():
devlist = self.dmesg[phase]['list']
dc, ps, pe = len(devlist), self.dmesg[phase]['start'], self.dmesg[phase]['end']
if not tS and ps >= self.tSuspended:
sysvals.vprint(' machine suspended: %f' % self.tSuspended)
tS = True
if not tR and ps >= self.tResumed:
sysvals.vprint(' machine resumed: %f' % self.tResumed)
tR = True
sysvals.vprint('%20s: %f - %f (%d devices)' % (phase, ps, pe, dc))
if sysvals.devdump:
sysvals.vprint(''.join('-' for i in range(80)))
maxname = '%d' % self.maxDeviceNameSize(phase)
fmt = '%3d) %'+maxname+'s - %f - %f'
c = 1
for name in sorted(devlist):
s = devlist[name]['start']
e = devlist[name]['end']
sysvals.vprint(fmt % (c, name, s, e))
c += 1
sysvals.vprint(''.join('-' for i in range(80)))
sysvals.vprint(' kernel resume end: %f' % self.tKernRes)
sysvals.vprint(' test end: %f' % self.end)
def deviceChildrenAllPhases(self, devname):
devlist = []
for phase in self.sortedPhases():
list = self.deviceChildren(devname, phase)
for dev in sorted(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:
# avoid recursions
if name == cname:
continue
clist = self.deviceChildrenAllPhases(cname)
cnode = self.masterTopology(cname, clist, depth+1)
node.children.append(cnode)
return node
def printTopology(self, node):
html = ''
if node.name:
info = ''
drv = ''
for phase in self.sortedPhases():
list = self.dmesg[phase]['list']
if node.name in list:
s = list[node.name]['start']
e = list[node.name]['end']
if list[node.name]['drv']:
drv = ' {'+list[node.name]['drv']+'}'
info += ('<li>%s: %.3fms</li>' % (phase, (e-s)*1000))
html += '<li><b>'+node.name+drv+'</b>'
if info:
html += '<ul>'+info+'</ul>'
html += '</li>'
if len(node.children) > 0:
html += '<ul>'
for cnode in node.children:
html += self.printTopology(cnode)
html += '</ul>'
return html
def rootDeviceList(self):
# list of devices graphed
real = []
for phase in self.sortedPhases():
list = self.dmesg[phase]['list']
for dev in sorted(list):
if list[dev]['pid'] >= 0 and dev not in real:
real.append(dev)
# list of top-most root devices
rootlist = []
for phase in self.sortedPhases():
list = self.dmesg[phase]['list']
for dev in sorted(list):
pdev = list[dev]['par']
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)
return rootlist
def deviceTopology(self):
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 length >= mindevlen:
devlist.append(dev)
self.tdevlist[phase] = devlist
def addHorizontalDivider(self, devname, devend):
phase = 'suspend_prepare'
self.newAction(phase, devname, -2, '', \
self.start, devend, '', ' sec', '')
if phase not in self.tdevlist:
self.tdevlist[phase] = []
self.tdevlist[phase].append(devname)
d = DevItem(0, phase, self.dmesg[phase]['list'][devname])
return d
def addProcessUsageEvent(self, name, times):
# get the start and end times for this process
cpuexec = dict()
tlast = start = end = -1
for t in sorted(times):
if tlast < 0:
tlast = t
continue
if name in self.pstl[t] and self.pstl[t][name] > 0:
if start < 0:
start = tlast
end, key = t, (tlast, t)
maxj = (t - tlast) * 1024.0
cpuexec[key] = min(1.0, float(self.pstl[t][name]) / maxj)
tlast = t
if start < 0 or end < 0:
return
# add a new action for this process and get the object
out = self.newActionGlobal(name, start, end, -3)
if out:
phase, devname = out
dev = self.dmesg[phase]['list'][devname]
dev['cpuexec'] = cpuexec
def createProcessUsageEvents(self):
# get an array of process names and times
proclist = {'sus': dict(), 'res': dict()}
tdata = {'sus': [], 'res': []}
for t in sorted(self.pstl):
dir = 'sus' if t < self.tSuspended else 'res'
for ps in sorted(self.pstl[t]):
if ps not in proclist[dir]:
proclist[dir][ps] = 0
tdata[dir].append(t)
# process the events for suspend and resume
if len(proclist['sus']) > 0 or len(proclist['res']) > 0:
sysvals.vprint('Process Execution:')
for dir in ['sus', 'res']:
for ps in sorted(proclist[dir]):
self.addProcessUsageEvent(ps, tdata[dir])
def handleEndMarker(self, time, msg=''):
dm = self.dmesg
self.setEnd(time, msg)
self.initDevicegroups()
# give suspend_prepare an end if needed
if 'suspend_prepare' in dm and dm['suspend_prepare']['end'] < 0:
dm['suspend_prepare']['end'] = time
# assume resume machine ends at next phase start
if 'resume_machine' in dm and dm['resume_machine']['end'] < 0:
np = self.nextPhase('resume_machine', 1)
if np:
dm['resume_machine']['end'] = dm[np]['start']
# if kernel resume end not found, assume its the end marker
if self.tKernRes == 0.0:
self.tKernRes = time
# if kernel suspend start not found, assume its the end marker
if self.tKernSus == 0.0:
self.tKernSus = time
# set resume complete to end at end marker
if 'resume_complete' in dm:
dm['resume_complete']['end'] = time
def initcall_debug_call(self, line, quick=False):
m = re.match('.*(\[ *)(?P<t>[0-9\.]*)(\]) .* (?P<f>.*)\: '+\
'PM: *calling .* @ (?P<n>.*), parent: (?P<p>.*)', line)
if not m:
m = re.match('.*(\[ *)(?P<t>[0-9\.]*)(\]) .* (?P<f>.*)\: '+\
'calling .* @ (?P<n>.*), parent: (?P<p>.*)', line)
if not m:
m = re.match('.*(\[ *)(?P<t>[0-9\.]*)(\]) calling '+\
'(?P<f>.*)\+ @ (?P<n>.*), parent: (?P<p>.*)', line)
if m:
return True if quick else m.group('t', 'f', 'n', 'p')
return False if quick else ('', '', '', '')
def initcall_debug_return(self, line, quick=False):
m = re.match('.*(\[ *)(?P<t>[0-9\.]*)(\]) .* (?P<f>.*)\: PM: '+\
'.* returned (?P<r>[0-9]*) after (?P<dt>[0-9]*) usecs', line)
if not m:
m = re.match('.*(\[ *)(?P<t>[0-9\.]*)(\]) .* (?P<f>.*)\: '+\
'.* returned (?P<r>[0-9]*) after (?P<dt>[0-9]*) usecs', line)
if not m:
m = re.match('.*(\[ *)(?P<t>[0-9\.]*)(\]) call '+\
'(?P<f>.*)\+ returned .* after (?P<dt>.*) usecs', line)
if m:
return True if quick else m.group('t', 'f', 'dt')
return False if quick else ('', '', '')
def debugPrint(self):
for p in self.sortedPhases():
list = self.dmesg[p]['list']
for devname in sorted(list):
dev = list[devname]
if 'ftrace' in dev:
dev['ftrace'].debugPrint(' [%s]' % devname)
# Class: DevFunction
# Description:
# A container for kprobe function data we want in the dev timeline
class DevFunction:
def __init__(self, name, args, caller, ret, start, end, u, proc, pid, color):
self.row = 0
self.count = 1
self.name = name
self.args = args
self.caller = caller
self.ret = ret
self.time = start
self.length = end - start
self.end = end
self.ubiquitous = u
self.proc = proc
self.pid = pid
self.color = color
def title(self):
cnt = ''
if self.count > 1:
cnt = '(x%d)' % self.count
l = '%0.3fms' % (self.length * 1000)
if self.ubiquitous:
title = '%s(%s)%s <- %s, %s(%s)' % \
(self.name, self.args, cnt, self.caller, self.ret, l)
else:
title = '%s(%s) %s%s(%s)' % (self.name, self.args, self.ret, cnt, l)
return title.replace('"', '')
def text(self):
if self.count > 1:
text = '%s(x%d)' % (self.name, self.count)
else:
text = self.name
return text
def repeat(self, tgt):
# is the tgt call just a repeat of this call (e.g. are we in a loop)
dt = self.time - tgt.end
# only combine calls if -all- attributes are identical
if tgt.caller == self.caller and \
tgt.name == self.name and tgt.args == self.args and \
tgt.proc == self.proc and tgt.pid == self.pid and \
tgt.ret == self.ret and dt >= 0 and \
dt <= sysvals.callloopmaxgap and \
self.length < sysvals.callloopmaxlen:
return True
return False
# Class: FTraceLine
# Description:
# A container for a single line of ftrace data. There are six basic types:
# callgraph line:
# call: " dpm_run_callback() {"
# return: " }"
# leaf: " dpm_run_callback();"
# trace event:
# tracing_mark_write: SUSPEND START or RESUME COMPLETE
# suspend_resume: phase or custom exec block data
# device_pm_callback: device callback info
class FTraceLine:
def __init__(self, t, m='', d=''):
self.length = 0.0
self.fcall = False
self.freturn = False
self.fevent = False
self.fkprobe = False
self.depth = 0
self.name = ''
self.type = ''
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'):
# nop format trace event
msg = m
else:
# function_graph format trace event
em = re.match('^ *\/\* *(?P<msg>.*) \*\/ *$', m)
msg = em.group('msg')
emm = re.match('^(?P<call>.*?): (?P<msg>.*)', msg)
if(emm):
self.name = emm.group('msg')
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
if(d):
self.length = float(d)/1000000
# the indentation determines the depth
match = re.match('^(?P<d> *)(?P<o>.*)$', m)
if(not match):
return
self.depth = self.getDepth(match.group('d'))
m = match.group('o')
# function return
if(m[0] == '}'):
self.freturn = True
if(len(m) > 1):
# includes comment with function name
match = re.match('^} *\/\* *(?P<n>.*) *\*\/$', m)
if(match):
self.name = match.group('n').strip()
# function call
else:
self.fcall = True
# function call with children
if(m[-1] == '{'):
match = re.match('^(?P<n>.*) *\(.*', m)
if(match):
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').strip()
# something else (possibly a trace marker)
else:
self.name = m
def isCall(self):
return self.fcall and not self.freturn
def isReturn(self):
return self.freturn and not self.fcall
def isLeaf(self):
return self.fcall and self.freturn
def getDepth(self, str):
return len(str)/2
def debugPrint(self, info=''):
if self.isLeaf():
pprint(' -- %12.6f (depth=%02d): %s(); (%.3f us) %s' % (self.time, \
self.depth, self.name, self.length*1000000, info))
elif self.freturn:
pprint(' -- %12.6f (depth=%02d): %s} (%.3f us) %s' % (self.time, \
self.depth, self.name, self.length*1000000, info))
else:
pprint(' -- %12.6f (depth=%02d): %s() { (%.3f us) %s' % (self.time, \
self.depth, self.name, self.length*1000000, info))
def startMarker(self):
# Is this the starting line of a suspend?
if not self.fevent:
return False
if sysvals.usetracemarkers:
if(self.name.startswith('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.startswith('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:
# A container for the ftrace callgraph of a single recursive function.
# This can be a dpm_run_callback, dpm_prepare, or dpm_complete callgraph
# Each instance is tied to a single device in a single phase, and is
# comprised of an ordered list of FTraceLine objects
class FTraceCallGraph:
vfname = 'missing_function_name'
def __init__(self, pid, sv):
self.id = ''
self.invalid = False
self.name = ''
self.partial = False
self.ignore = False
self.start = -1.0
self.end = -1.0
self.list = []
self.depth = 0
self.pid = pid
self.sv = sv
def addLine(self, line):
# if this is already invalid, just leave
if(self.invalid):
if(line.depth == 0 and line.freturn):
return 1
return 0
# invalidate on bad depth
if(self.depth < 0):
self.invalidate(line)
return 0
# ignore data til we return to the current depth
if self.ignore:
if line.depth > self.depth:
return 0
else:
self.list[-1].freturn = True
self.list[-1].length = line.time - self.list[-1].time
self.ignore = False
# if this is a return at self.depth, no more work is needed
if line.depth == self.depth and line.isReturn():
if line.depth == 0:
self.end = line.time
return 1
return 0
# compare current depth with this lines pre-call depth
prelinedep = line.depth
if line.isReturn():
prelinedep += 1
last = 0
lasttime = line.time
if len(self.list) > 0:
last = self.list[-1]
lasttime = last.time
if last.isLeaf():
lasttime += last.length
# handle low misalignments by inserting returns
mismatch = prelinedep - self.depth
warning = self.sv.verbose and abs(mismatch) > 1
info = []
if mismatch < 0:
idx = 0
# add return calls to get the depth down
while prelinedep < self.depth:
self.depth -= 1
if idx == 0 and last and last.isCall():
# special case, turn last call into a leaf
last.depth = self.depth
last.freturn = True
last.length = line.time - last.time
if warning:
info.append(('[make leaf]', last))
else:
vline = FTraceLine(lasttime)
vline.depth = self.depth
vline.name = self.vfname
vline.freturn = True
self.list.append(vline)
if warning:
if idx == 0:
info.append(('', last))
info.append(('[add return]', vline))
idx += 1
if warning:
info.append(('', line))
# handle high misalignments by inserting calls
elif mismatch > 0:
idx = 0
if warning:
info.append(('', last))
# add calls to get the depth up
while prelinedep > self.depth:
if idx == 0 and line.isReturn():
# special case, turn this return into a leaf
line.fcall = True
prelinedep -= 1
if warning:
info.append(('[make leaf]', line))
else:
vline = FTraceLine(lasttime)
vline.depth = self.depth
vline.name = self.vfname
vline.fcall = True
self.list.append(vline)
self.depth += 1
if not last:
self.start = vline.time
if warning:
info.append(('[add call]', vline))
idx += 1
if warning and ('[make leaf]', line) not in info:
info.append(('', line))
if warning:
pprint('WARNING: ftrace data missing, corrections made:')
for i in info:
t, obj = i
if obj:
obj.debugPrint(t)
# process the call and set the new depth
skipadd = False
md = self.sv.max_graph_depth
if line.isCall():
# ignore blacklisted/overdepth funcs
if (md and self.depth >= md - 1) or (line.name in self.sv.cgblacklist):
self.ignore = True
else:
self.depth += 1
elif line.isReturn():
self.depth -= 1
# remove blacklisted/overdepth/empty funcs that slipped through
if (last and last.isCall() and last.depth == line.depth) or \
(md and last and last.depth >= md) or \
(line.name in self.sv.cgblacklist):
while len(self.list) > 0 and self.list[-1].depth > line.depth:
self.list.pop(-1)
if len(self.list) == 0:
self.invalid = True
return 1
self.list[-1].freturn = True
self.list[-1].length = line.time - self.list[-1].time
self.list[-1].name = line.name
skipadd = True
if len(self.list) < 1:
self.start = line.time
# check for a mismatch that returned all the way to callgraph end
res = 1