| #!/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 |
| |
| def pprint(msg): |
| 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.8' |
| ansi = False |
| rs = 0 |
| display = '' |
| gzip = False |
| sync = False |
| wifi = False |
| verbose = False |
| testlog = True |
| dmesglog = True |
| ftracelog = False |
| acpidebug = True |
| tstat = True |
| 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 |
| 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' |
| 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 |
| 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 = { |
| '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, 'kparams', 'cat', '/proc/cmdline'], |
| [0, 'mcelog', 'mcelog'], |
| [0, 'pcidevices', 'lspci', '-tv'], |
| [0, 'usbdevices', 'lsusb', '-t'], |
| [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/*/*'], |
| ] |
| 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): |
| return (os.path.exists(file) and os.path.getsize(file) > 0) |
| 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) |
| def printSystemInfo(self, fatal=False): |
| self.rootCheck(True) |
| out = dmidecode(self.mempath, fatal) |
| if len(out) < 1: |
| return |
| fmt = '%-24s: %s' |
| 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 |
| fp = open('/proc/cpuinfo', 'r') |
| for line in fp: |
| if re.match('^processor[ \t]*:[ \t]*[0-9]*', line): |
| self.cpucount += 1 |
| fp.close() |
| fp = open('/proc/meminfo', 'r') |
| 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')) |
| fp.close() |
| 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): |
| 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): |
| return self.getVal(self.tpath+path) |
| def cleanupFtrace(self): |
| if(self.usecallgraph or self.usetraceevents or self.usedevsrc): |
| 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 quiet: |
| sysvals.printSystemInfo(False) |
| pprint('INITIALIZING FTRACE...') |
| # turn trace off |
| self.fsetVal('0', 'tracing_on') |
| self.cleanupFtrace() |
| self.testVal(self.pmdpath, 'basic', '1') |
| # 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') |
| # 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 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) |
| 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): |
| 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 |
| with open(dirname+'/power/async') as fp: |
| text = fp.read() |
| props[dev].isasync = False |
| if 'enabled' in text: |
| props[dev].isasync = True |
| fields = os.listdir(dirname) |
| if 'product' in fields: |
| with open(dirname+'/product', 'rb') as fp: |
| props[dev].altname = ascii(fp.read()) |
| elif 'name' in fields: |
| with open(dirname+'/name', 'rb') as fp: |
| props[dev].altname = ascii(fp.read()) |
| elif 'model' in fields: |
| with open(dirname+'/model', 'rb') as fp: |
| props[dev].altname = ascii(fp.read()) |
| elif 'description' in fields: |
| with open(dirname+'/description', 'rb') as fp: |
| props[dev].altname = ascii(fp.read()) |
| elif 'id' in fields: |
| with open(dirname+'/id', 'rb') as fp: |
| props[dev].altname = ascii(fp.read()) |
| elif 'idVendor' in fields and 'idProduct' in fields: |
| idv, idp = '', '' |
| with open(dirname+'/idVendor', 'rb') as fp: |
| idv = ascii(fp.read()).strip() |
| with open(dirname+'/idProduct', 'rb') as fp: |
| idp = ascii(fp.read()).strip() |
| props[dev].altname = '%s:%s' % (idv, idp) |
| 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 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 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): |
| 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] |
| out.append('%s=%s' % (key, val)) |
| return '|'.join(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]*) .*', w.split('\n')[-1]) |
| if not m or (dev and dev != m.group('dev')): |
| continue |
| return m.group('dev') |
| return '' |
| def pollWifi(self, dev, timeout=60): |
| 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)) |
| |
| sysvals = SystemValues() |
| switchvalues = ['enable', 'disable', 'on', 'off', 'true', 'false', '1', '0'] |
| switchoff = ['disable', 'off', 'false', '0'] |
| suspendmodename = { |
| 'freeze': 'Freeze (S0)', |
| 'standby': 'Standby (S1)', |
| '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.*', |
| '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 |
| 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 |
| if ubiquitous and c in dtf and 'ub' in dtf[c]: |
| 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 |
| 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 |
| maxC = 0 |
| tlast = 0 |
| start = -1 |
| end = -1 |
| for t in sorted(times): |
| if tlast == 0: |
| tlast = t |
| continue |
| if name in self.pstl[t]: |
| if start == -1 or tlast < start: |
| start = tlast |
| if end == -1 or t > end: |
| end = t |
| tlast = t |
| if start == -1 or end == -1: |
| return 0 |
| # add a new action for this process and get the object |
| out = self.newActionGlobal(name, start, end, -3) |
| if not out: |
| return 0 |
| phase, devname = out |
| dev = self.dmesg[phase]['list'][devname] |
| # get the cpu exec data |
| tlast = 0 |
| clast = 0 |
| cpuexec = dict() |
| for t in sorted(times): |
| if tlast == 0 or t <= start or t > end: |
| tlast = t |
| continue |
| list = self.pstl[t] |
| c = 0 |
| if name in list: |
| c = list[name] |
| if c > maxC: |
| maxC = c |
| if c != clast: |
| key = (tlast, t) |
| cpuexec[key] = c |
| tlast = t |
| clast = c |
| dev['cpuexec'] = cpuexec |
| return maxC |
| def createProcessUsageEvents(self): |
| # get an array of process names |
| proclist = [] |
| for t in sorted(self.pstl): |
| pslist = self.pstl[t] |
| for ps in sorted(pslist): |
| if ps not in proclist: |
| proclist.append(ps) |
| # get a list of data points for suspend and resume |
| tsus = [] |
| tres = [] |
| for t in sorted(self.pstl): |
| if t < self.tSuspended: |
| tsus.append(t) |
| else: |
| tres.append(t) |
| # process the events for suspend and resume |
| if len(proclist) > 0: |
| sysvals.vprint('Process Execution:') |
| for ps in proclist: |
| c = self.addProcessUsageEvent(ps, tsus) |
| if c > 0: |
| sysvals.vprint('%25s (sus): %d' % (ps, c)) |
| c = self.addProcessUsageEvent(ps, tres) |
| if c > 0: |
| sysvals.vprint('%25s (res): %d' % (ps, c)) |
| 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 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 |
| if mismatch < 0 and self.list[-1].depth == 0 and self.list[-1].freturn: |
| line = self.list[-1] |
| skipadd = True |
| res = -1 |
| if not skipadd: |
| self.list.append(line) |
| if(line.depth == 0 and line.freturn): |
| if(self.start < 0): |
| self.start = line.time |
| self.end = line.time |
| if line.fcall: |
| self.end += line.length |
| if self.list[0].name == self.vfname: |
| self.invalid = True |
| if res == -1: |
| self.partial = True |
| return res |
| return 0 |
| 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): |
| pprint('Data misalignment for '+id+\ |
| ' (buffer overflow), ignoring this callback') |
| else: |
| pprint('Too much data for '+id+\ |
| ' '+window+', ignoring this callback') |
| def slice(self, dev): |
| minicg = FTraceCallGraph(dev['pid'], self.sv) |
| minicg.name = self.name |
| mydepth = -1 |
| good = False |
| for l in self.list: |
| if(l.time < dev['start'] or l.time > dev['end']): |
| continue |
| if mydepth < 0: |
| if l.name == 'mutex_lock' and l.freturn: |
| mydepth = l.depth |
| continue |
| elif l.depth == mydepth and l.name == 'mutex_unlock' and l.fcall: |
| good = True |
| break |
| l.depth -= mydepth |
| minicg.addLine(l) |
| if not good or len(minicg.list) < 1: |
| return 0 |
| return minicg |
| 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 != 0: |
| self.end = last.time |
| return True |
| return False |
| def postProcess(self): |
| if len(self.list) > 0: |
| self.name = self.list[0].name |
| stack = dict() |
| cnt = 0 |
| last = 0 |
| for l in self.list: |
| # ftrace bug: reported duration is not reliable |
| # check each leaf and clip it at max possible length |
| if last and last.isLeaf(): |
| if last.length > l.time - last.time: |
| last.length = l.time - last.time |
| if l.isCall(): |
| stack[l.depth] = l |
| cnt += 1 |
| elif l.isReturn(): |
| if(l.depth not in stack): |
| if self.sv.verbose: |
| pprint('Post Process Error: Depth missing') |
| l.debugPrint() |
| return False |
| # calculate call length from call/return lines |
| cl = stack[l.depth] |
| cl.length = l.time - cl.time |
| if cl.name == self.vfname: |
| cl.name = l.name |
| stack.pop(l.depth) |
| l.length = 0 |
| cnt -= 1 |
| last = l |
| if(cnt == 0): |
| # trace caught the whole call tree |
| return True |
| elif(cnt < 0): |
| if self.sv.verbose: |
| pprint('Post Process Error: Depth is less than 0') |
| return False |
|
