From 700abc90f07b7f60e512c5d5b7cb33bdc207e47c Mon Sep 17 00:00:00 2001 From: Todd E Brandt Date: Tue, 30 Jan 2018 00:17:20 -0800 Subject: pm-graph: AnalyzeSuspend v5.0 - add -cgskip option to reduce callgraph output size - add -cgfilter option to focus on a list of devices - add -result option for exporting batch test results - removed all phoronix hooks, use -result to enable batch testing - change -usbtopo to -devinfo, now prints all devices - add -gzip option to read/write logs in gz format - add -bufsize option to manually control ftrace buffer size - add -sync option to run filesystem sync prior to test - add -display option to enable/disable the display prior to test - add -rs option to enable/disable runtime suspend on all devices for test - add installed config files to search path - add kernel error/warning links into the timeline - fix callgraph trace to better handle interrupts - include command string and kernel params in timeline output header Signed-off-by: Todd Brandt Signed-off-by: Rafael J. Wysocki --- tools/power/pm-graph/sleepgraph.8 | 47 +- tools/power/pm-graph/sleepgraph.py | 1625 ++++++++++++++++++++++-------------- 2 files changed, 1053 insertions(+), 619 deletions(-) (limited to 'tools/power/pm-graph') diff --git a/tools/power/pm-graph/sleepgraph.8 b/tools/power/pm-graph/sleepgraph.8 index fbe7bd3eae8e..18baaf6300c9 100644 --- a/tools/power/pm-graph/sleepgraph.8 +++ b/tools/power/pm-graph/sleepgraph.8 @@ -52,9 +52,32 @@ disable rtcwake and require a user keypress to resume. \fB-addlogs\fR Add the dmesg and ftrace logs to the html output. They will be viewable by clicking buttons in the timeline. +.TP +\fB-result \fIfile\fR +Export a results table to a text file for parsing. +.TP +\fB-sync\fR +Sync the filesystems before starting the test. This reduces the size of +the sys_sync call which happens in the suspend_prepare phase. +.TP +\fB-rs \fIenable/disable\fR +During test, enable/disable runtime suspend for all devices. The test is delayed +by 5 seconds to allow runtime suspend changes to occur. The settings are restored +after the test is complete. +.TP +\fB-display \fIon/off\fR +Turn the display on or off for the test using the xset command. This helps +maintain the consistecy of test data for better comparison. +.TP +\fB-skiphtml\fR +Run the test and capture the trace logs, but skip the timeline generation. .SS "advanced" .TP +\fB-gzip\fR +Gzip the trace and dmesg logs to save space. The tool can also read in gzipped +logs for processing. +.TP \fB-cmd \fIstr\fR Run the timeline over a custom suspend command, e.g. pm-suspend. By default the tool forces suspend via /sys/power/state so this allows testing over @@ -114,6 +137,18 @@ This reduces the html file size as there can be many tiny callgraphs which are barely visible in the timeline. The value is a float: e.g. 0.001 represents 1 us. .TP +\fB-cgfilter \fI"func1,func2,..."\fR +Reduce callgraph output in the timeline by limiting it to a list of calls. The +argument can be a single function name or a comma delimited list. +(default: none) +.TP +\fB-cgskip \fIfile\fR +Reduce callgraph timeline size by skipping over uninteresting functions +in the trace, e.g. printk or console_unlock. The functions listed +in this file will show up as empty leaves in the callgraph with only the start/end +times displayed. cgskip.txt is used automatically if found in the path, so +use "off" to disable completely (default: cgskip.txt) +.TP \fB-cgphase \fIp\fR Only show callgraph data for phase \fIp\fR (e.g. suspend_late). .TP @@ -122,6 +157,9 @@ In an x2 run, only show callgraph data for test \fIn\fR (e.g. 0 or 1). .TP \fB-timeprec \fIn\fR Number of significant digits in timestamps (0:S, [3:ms], 6:us). +.TP +\fB-bufsize \fIN\fR +Set trace buffer size to N kilo-bytes (default: all of free memory up to 3GB) .SH COMMANDS .TP @@ -144,11 +182,8 @@ Print out the contents of the ACPI Firmware Performance Data Table. \fB-sysinfo\fR Print out system info extracted from BIOS. Reads /dev/mem directly instead of going through dmidecode. .TP -\fB-usbtopo\fR -Print out the current USB topology with power info. -.TP -\fB-usbauto\fR -Enable autosuspend for all connected USB devices. +\fB-devinfo\fR +Print out the pm settings of all devices which support runtime suspend. .TP \fB-flist\fR Print the list of ftrace functions currently being captured. Functions @@ -198,7 +233,7 @@ Execute a mem suspend with a 15 second wakeup. Include the logs in the html. .PP Execute a standby with a 15 second wakeup. Change the output folder name. .IP -\f(CW$ sudo sleepgraph -m standby -rtcwake 15 -o "standby-{hostname}-{date}-{time}"\fR +\f(CW$ sudo sleepgraph -m standby -rtcwake 15 -o "standby-{host}-{date}-{time}"\fR .PP Execute a freeze with no wakeup (require keypress). Change output folder name. .IP diff --git a/tools/power/pm-graph/sleepgraph.py b/tools/power/pm-graph/sleepgraph.py index 1b60fe203741..266409fb27ae 100755 --- a/tools/power/pm-graph/sleepgraph.py +++ b/tools/power/pm-graph/sleepgraph.py @@ -19,7 +19,7 @@ # Home Page # https://01.org/suspendresume # Source repo -# https://github.com/01org/pm-graph +# git@github.com:01org/pm-graph # # Description: # This tool is designed to assist kernel and OS developers in optimizing @@ -57,6 +57,7 @@ import platform from datetime import datetime import struct import ConfigParser +import gzip from threading import Thread from subprocess import call, Popen, PIPE @@ -68,8 +69,12 @@ from subprocess import call, Popen, PIPE # store system values and test parameters class SystemValues: title = 'SleepGraph' - version = '4.7' + version = '5.0' ansi = False + rs = 0 + display = 0 + gzip = False + sync = False verbose = False testlog = True dmesglog = False @@ -78,14 +83,19 @@ class SystemValues: mincglen = 0.0 cgphase = '' cgtest = -1 + cgskip = '' + multitest = {'run': False, 'count': 0, '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/' @@ -109,22 +119,24 @@ class SystemValues: dmesgfile = '' ftracefile = '' htmlfile = 'output.html' - embedded = False + result = '' rtcwake = True rtcwaketime = 15 rtcpath = '' devicefilter = [] + cgfilter = [] stamp = 0 execcount = 1 x2delay = 0 + skiphtml = False usecallgraph = False usetraceevents = False - usetraceeventsonly = False usetracemarkers = True usekprobes = True usedevsrc = False useprocmon = False notestrun = False + cgdump = False mixedphaseheight = True devprops = dict() predelay = 0 @@ -134,24 +146,33 @@ class SystemValues: tracertypefmt = '# tracer: (?P.*)' firmwarefmt = '# fwsuspend (?P[0-9]*) fwresume (?P[0-9]*)$' tracefuncs = { - 'sys_sync': dict(), - 'pm_prepare_console': dict(), - 'pm_notifier_call_chain': dict(), - 'freeze_processes': dict(), - 'freeze_kernel_threads': dict(), - 'pm_restrict_gfp_mask': dict(), - 'acpi_suspend_begin': dict(), - 'suspend_console': dict(), - 'acpi_pm_prepare': dict(), - 'syscore_suspend': dict(), - 'arch_enable_nonboot_cpus_end': dict(), - 'syscore_resume': dict(), - 'acpi_pm_finish': dict(), - 'resume_console': dict(), - 'acpi_pm_end': dict(), - 'pm_restore_gfp_mask': dict(), - 'thaw_processes': dict(), - 'pm_restore_console': dict(), + 'sys_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': {}, + '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'}, @@ -173,56 +194,54 @@ class SystemValues: 'mutex_lock_slowpath': { 'func':'__mutex_lock_slowpath', 'ub': 1 }, 'acpi_os_stall': {'ub': 1}, # ACPI - 'acpi_resume_power_resources': dict(), - 'acpi_ps_parse_aml': dict(), + 'acpi_resume_power_resources': {}, + 'acpi_ps_parse_aml': {}, # filesystem - 'ext4_sync_fs': dict(), + 'ext4_sync_fs': {}, # 80211 - 'iwlagn_mac_start': dict(), - 'iwlagn_alloc_bcast_station': dict(), - 'iwl_trans_pcie_start_hw': dict(), - 'iwl_trans_pcie_start_fw': dict(), - 'iwl_run_init_ucode': dict(), - 'iwl_load_ucode_wait_alive': dict(), - 'iwl_alive_start': dict(), - 'iwlagn_mac_stop': dict(), - 'iwlagn_mac_suspend': dict(), - 'iwlagn_mac_resume': dict(), - 'iwlagn_mac_add_interface': dict(), - 'iwlagn_mac_remove_interface': dict(), - 'iwlagn_mac_change_interface': dict(), - 'iwlagn_mac_config': dict(), - 'iwlagn_configure_filter': dict(), - 'iwlagn_mac_hw_scan': dict(), - 'iwlagn_bss_info_changed': dict(), - 'iwlagn_mac_channel_switch': dict(), - 'iwlagn_mac_flush': dict(), + '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': dict(), - 'i915_restore_state': dict(), - 'intel_opregion_setup': dict(), - 'g4x_pre_enable_dp': dict(), - 'vlv_pre_enable_dp': dict(), - 'chv_pre_enable_dp': dict(), - 'g4x_enable_dp': dict(), - 'vlv_enable_dp': dict(), - 'intel_hpd_init': dict(), - 'intel_opregion_register': dict(), - 'intel_dp_detect': dict(), - 'intel_hdmi_detect': dict(), - 'intel_opregion_init': dict(), - 'intel_fbdev_set_suspend': dict(), + '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': {}, } + cgblacklist = [] kprobes = dict() timeformat = '%.3f' + cmdline = '%s %s' % \ + (os.path.basename(sys.argv[0]), string.join(sys.argv[1:], ' ')) def __init__(self): - # if this is a phoronix test run, set some default options - if('LOG_FILE' in os.environ and 'TEST_RESULTS_IDENTIFIER' in os.environ): - self.embedded = True - self.dmesglog = self.ftracelog = True - self.htmlfile = os.environ['LOG_FILE'] self.archargs = 'args_'+platform.machine() self.hostname = platform.node() if(self.hostname == ''): @@ -237,18 +256,36 @@ class SystemValues: if (hasattr(sys.stdout, 'isatty') and sys.stdout.isatty()): self.ansi = True self.testdir = datetime.now().strftime('suspend-%y%m%d-%H%M%S') + def vprint(self, msg): + self.logmsg += msg+'\n' + if(self.verbose): + print(msg) def rootCheck(self, fatal=True): if(os.access(self.powerfile, os.W_OK)): return True if fatal: - doError('This command requires sysfs mount and root access') + msg = 'This command requires sysfs mount and root access' + print('ERROR: %s\n') % msg + self.outputResult({'error':msg}) + sys.exit() return False def rootUser(self, fatal=False): if 'USER' in os.environ and os.environ['USER'] == 'root': return True if fatal: - doError('This command must be run as root') + msg = 'This command must be run as root' + print('ERROR: %s\n') % msg + self.outputResult({'error':msg}) + sys.exit() return False + def getExec(self, cmd): + dirlist = ['/sbin', '/bin', '/usr/sbin', '/usr/bin', + '/usr/local/sbin', '/usr/local/bin'] + for path in dirlist: + cmdfull = os.path.join(path, cmd) + if os.path.exists(cmdfull): + return cmdfull + return '' def setPrecision(self, num): if num < 0 or num > 6: return @@ -258,15 +295,15 @@ class SystemValues: n = datetime.now() args['date'] = n.strftime('%y%m%d') args['time'] = n.strftime('%H%M%S') - args['hostname'] = self.hostname + args['hostname'] = args['host'] = self.hostname return value.format(**args) def setOutputFile(self): if self.dmesgfile != '': - m = re.match('(?P.*)_dmesg\.txt$', self.dmesgfile) + m = re.match('(?P.*)_dmesg\.txt.*', self.dmesgfile) if(m): self.htmlfile = m.group('name')+'.html' if self.ftracefile != '': - m = re.match('(?P.*)_ftrace\.txt$', self.ftracefile) + m = re.match('(?P.*)_ftrace\.txt.*', self.ftracefile) if(m): self.htmlfile = m.group('name')+'.html' def systemInfo(self, info): @@ -283,16 +320,19 @@ class SystemValues: c = info['processor-version'] if 'bios-version' in info: b = info['bios-version'] - self.sysstamp = '# sysinfo | man:%s | plat:%s | cpu:%s | bios:%s | numcpu:%d | memsz:%d' % \ - (m, p, c, b, self.cpucount, self.memtotal) - def printSystemInfo(self): + self.sysstamp = '# sysinfo | man:%s | plat:%s | cpu:%s | bios:%s | numcpu:%d | memsz:%d | memfr:%d' % \ + (m, p, c, b, self.cpucount, self.memtotal, self.memfree) + def printSystemInfo(self, fatal=False): self.rootCheck(True) - out = dmidecode(self.mempath, 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') @@ -305,7 +345,9 @@ class SystemValues: m = re.match('^MemTotal:[ \t]*(?P[0-9]*) *kB', line) if m: self.memtotal = int(m.group('sz')) - break + m = re.match('^MemFree:[ \t]*(?P[0-9]*) *kB', line) + if m: + self.memfree = int(m.group('sz')) fp.close() def initTestOutput(self, name): self.prefix = self.hostname @@ -315,39 +357,34 @@ class SystemValues: testtime = datetime.now().strftime(fmt) self.teststamp = \ '# '+testtime+' '+self.prefix+' '+self.suspendmode+' '+kver - if(self.embedded): - self.dmesgfile = \ - '/tmp/'+testtime+'_'+self.suspendmode+'_dmesg.txt' - self.ftracefile = \ - '/tmp/'+testtime+'_'+self.suspendmode+'_ftrace.txt' - return + ext = '' + if self.gzip: + ext = '.gz' self.dmesgfile = \ - self.testdir+'/'+self.prefix+'_'+self.suspendmode+'_dmesg.txt' + self.testdir+'/'+self.prefix+'_'+self.suspendmode+'_dmesg.txt'+ext self.ftracefile = \ - self.testdir+'/'+self.prefix+'_'+self.suspendmode+'_ftrace.txt' + 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.mkdir(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 = [] - if value: - value = value.split(',') - for i in value: - self.devicefilter.append(i.strip()) + self.devicefilter = self.getValueList(value) + def setCallgraphFilter(self, value): + self.cgfilter = self.getValueList(value) + def setCallgraphBlacklist(self, file): + self.cgblacklist = self.listFromFile(file) def rtcWakeAlarmOn(self): call('echo 0 > '+self.rtcpath+'/wakealarm', shell=True) - outD = open(self.rtcpath+'/date', 'r').read().strip() - outT = open(self.rtcpath+'/time', 'r').read().strip() - mD = re.match('^(?P[0-9]*)-(?P[0-9]*)-(?P[0-9]*)', outD) - mT = re.match('^(?P[0-9]*):(?P[0-9]*):(?P[0-9]*)', outT) - if(mD and mT): - # get the current time from hardware - utcoffset = int((datetime.now() - datetime.utcnow()).total_seconds()) - dt = datetime(\ - int(mD.group('y')), int(mD.group('m')), int(mD.group('d')), - int(mT.group('h')), int(mT.group('m')), int(mT.group('s'))) - nowtime = int(dt.strftime('%s')) + utcoffset + 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')) @@ -369,10 +406,10 @@ class SystemValues: ktime = m.group('ktime') fp.close() self.dmesgstart = float(ktime) - def getdmesg(self): + def getdmesg(self, fwdata=[]): + op = self.writeDatafileHeader(sysvals.dmesgfile, fwdata) # store all new dmesg lines since initdmesg was called fp = Popen('dmesg', stdout=PIPE).stdout - op = open(self.dmesgfile, 'a') for line in fp: line = line.replace('\r\n', '') idx = line.find('[') @@ -386,11 +423,17 @@ class SystemValues: op.write(line) fp.close() op.close() - def addFtraceFilterFunctions(self, file): + def listFromFile(self, file): + list = [] fp = open(file) - list = fp.read().split('\n') + for i in fp.read().split('\n'): + i = i.strip() + if i and i[0] != '#': + list.append(i) fp.close() - for i in list: + return list + def addFtraceFilterFunctions(self, file): + for i in self.listFromFile(file): if len(i) < 2: continue self.tracefuncs[i] = dict() @@ -399,9 +442,7 @@ class SystemValues: if not current: call('cat '+self.tpath+'available_filter_functions', shell=True) return - fp = open(self.tpath+'available_filter_functions') - master = fp.read().split('\n') - fp.close() + master = self.listFromFile(self.tpath+'available_filter_functions') for i in self.tracefuncs: if 'func' in self.tracefuncs[i]: i = self.tracefuncs[i]['func'] @@ -410,9 +451,7 @@ class SystemValues: else: print self.colorText(i) def setFtraceFilterFunctions(self, list): - fp = open(self.tpath+'available_filter_functions') - master = fp.read().split('\n') - fp.close() + master = self.listFromFile(self.tpath+'available_filter_functions') flist = '' for i in list: if i not in master: @@ -501,6 +540,7 @@ class SystemValues: 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]): @@ -528,17 +568,10 @@ class SystemValues: for kp in kplist: kprobeevents += self.kprobeText(kp, self.kprobes[kp]) self.fsetVal(kprobeevents, 'kprobe_events') - # verify that the kprobes were set as ordered - check = self.fgetVal('kprobe_events') - linesout = len(kprobeevents.split('\n')) - 1 - linesack = len(check.split('\n')) - 1 if output: - res = '%d/%d' % (linesack, linesout) - if linesack < linesout: - res = self.colorText(res, 31) - else: - res = self.colorText(res, 32) - print(' working kprobe functions enabled: %s' % res) + check = self.fgetVal('kprobe_events') + linesack = (len(check.split('\n')) - 1) / 2 + print(' kprobe functions enabled: %d/%d' % (linesack, linesout)) self.fsetVal('1', 'events/kprobes/enable') def testKprobe(self, kname, kprobe): self.fsetVal('0', 'events/kprobes/enable') @@ -555,8 +588,7 @@ class SystemValues: if linesack < linesout: return False return True - def fsetVal(self, val, path, mode='w'): - file = self.tpath+path + def setVal(self, val, file, mode='w'): if not os.path.exists(file): return False try: @@ -567,8 +599,9 @@ class SystemValues: except: return False return True - def fgetVal(self, path): - file = self.tpath+path + def fsetVal(self, val, path, mode='w'): + return self.setVal(val, self.tpath+path, mode) + def getVal(self, file): res = '' if not os.path.exists(file): return res @@ -579,10 +612,13 @@ class SystemValues: except: pass return res + def fgetVal(self, path): + return self.getVal(self.tpath+path) def cleanupFtrace(self): - if(self.usecallgraph or self.usetraceevents): + 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]) @@ -599,7 +635,8 @@ class SystemValues: if name == f: return True return False - def initFtrace(self, testing=False): + def initFtrace(self): + self.printSystemInfo(False) print('INITIALIZING FTRACE...') # turn trace off self.fsetVal('0', 'tracing_on') @@ -607,17 +644,21 @@ class SystemValues: # set the trace clock to global self.fsetVal('global', 'trace_clock') self.fsetVal('nop', 'current_tracer') - # set trace buffer to a huge value - if self.usecallgraph or self.usedevsrc: - tgtsize = min(self.memtotal / 2, 2*1024*1024) - maxbuf = '%d' % (tgtsize / max(1, self.cpucount)) - if self.cpucount < 1 or not self.fsetVal(maxbuf, 'buffer_size_kb'): - self.fsetVal('131072', 'buffer_size_kb') + # 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: + tgtsize = min(self.memfree, 3*1024*1024) else: - self.fsetVal('16384', 'buffer_size_kb') - # go no further if this is just a status check - if testing: - return + 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 + print 'Setting trace buffers to %d kB (%d kB per cpu)' % (tgtsize, tgtsize/cpus) # initialize the callgraph trace if(self.usecallgraph): # set trace type @@ -635,7 +676,7 @@ class SystemValues: self.fsetVal('graph-time', 'trace_options') self.fsetVal('%d' % self.max_graph_depth, 'max_graph_depth') cf = ['dpm_run_callback'] - if(self.usetraceeventsonly): + if(self.usetraceevents): cf += ['dpm_prepare', 'dpm_complete'] for fn in self.tracefuncs: if 'func' in self.tracefuncs[fn]: @@ -688,16 +729,65 @@ class SystemValues: return str return '\x1B[%d;40m%s\x1B[m' % (color, str) def writeDatafileHeader(self, filename, fwdata=[]): - fp = open(filename, 'w') - fp.write(self.teststamp+'\n') - fp.write(self.sysstamp+'\n') + fp = self.openlog(filename, 'w') + fp.write('%s\n%s\n# command | %s\n' % (self.teststamp, self.sysstamp, self.cmdline)) if(self.suspendmode == 'mem' or self.suspendmode == 'command'): for fw in fwdata: if(fw): fp.write('# fwsuspend %u fwresume %u\n' % (fw[0], fw[1])) + return fp + def sudouser(self, dir): + if os.path.exists(dir) and os.getuid() == 0 and \ + 'SUDO_USER' in os.environ: + cmd = 'chown -R {0}:{0} {1} > /dev/null 2>&1' + call(cmd.format(os.environ['SUDO_USER'], 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.sudouser(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+'b') as fp: + test = fp.read(64) + isgz = True + except: + isgz = False + if isgz: + return gzip.open(filename, mode+'b') + return open(filename, mode) sysvals = SystemValues() +switchvalues = ['enable', 'disable', 'on', 'off', 'true', 'false', '1', '0'] +switchoff = ['disable', 'off', 'false', '0'] suspendmodename = { 'freeze': 'Freeze (S0)', 'standby': 'Standby (S1)', @@ -826,34 +916,65 @@ class Data: for phase in self.phases: self.devicegroups.append([phase]) self.errorinfo = {'suspend':[],'resume':[]} - def extractErrorInfo(self, dmesg): - error = '' - tm = 0.0 - for i in range(len(dmesg)): - if 'Call Trace:' in dmesg[i]: - m = re.match('[ \t]*(\[ *)(?P[0-9\.]*)(\]) .*', dmesg[i]) - if not m: - continue - tm = float(m.group('ktime')) - if tm < self.start or tm > self.end: - continue - for j in range(i-10, i+1): - error += dmesg[j] + def extractErrorInfo(self): + lf = sysvals.openlog(sysvals.dmesgfile, 'r') + i = 0 + list = [] + # sl = start line, et = error time, el = error line + type = 'ERROR' + sl = et = el = -1 + for line in lf: + i += 1 + m = re.match('[ \t]*(\[ *)(?P[0-9\.]*)(\]) (?P.*)', line) + if not m: continue - if error: - m = re.match('[ \t]*\[ *[0-9\.]*\] \[\<[0-9a-fA-F]*\>\] .*', dmesg[i]) - if m: - error += dmesg[i] - else: - if tm < self.tSuspended: - dir = 'suspend' - else: - dir = 'resume' - error = error.replace('<', '<').replace('>', '>') - vprint('kernel error found in %s at %f' % (dir, tm)) - self.errorinfo[dir].append((tm, error)) + t = float(m.group('ktime')) + if t < self.start or t > self.end: + continue + if t < self.tSuspended: + dir = 'suspend' + else: + dir = 'resume' + msg = m.group('msg') + if re.match('-*\[ *cut here *\]-*', msg): + type = 'WARNING' + sl = i + elif re.match('genirq: .*', msg): + type = 'IRQ' + sl = i + elif re.match('BUG: .*', msg) or re.match('kernel BUG .*', msg): + type = 'BUG' + sl = i + elif re.match('-*\[ *end trace .*\]-*', msg) or \ + re.match('R13: .*', msg): + if et >= 0 and sl >= 0: + list.append((type, dir, et, sl, i)) self.kerror = True - error = '' + sl = et = el = -1 + type = 'ERROR' + elif 'Call Trace:' in msg: + if el >= 0 and et >= 0: + list.append((type, dir, et, el, el)) + self.kerror = True + et, el = t, i + if sl < 0 or type == 'BUG': + slval = i + if sl >= 0: + slval = sl + list.append((type, dir, et, slval, i)) + self.kerror = True + sl = et = el = -1 + type = 'ERROR' + if el >= 0 and et >= 0: + list.append((type, dir, et, el, el)) + self.kerror = True + for e in list: + type, dir, t, idx1, idx2 = e + sysvals.vprint('kernel %s found in %s at %f' % (type, dir, t)) + self.errorinfo[dir].append((type, t, idx1, idx2)) + if self.kerror: + sysvals.dmesglog = True + lf.close() def setStart(self, time): self.start = time def setEnd(self, time): @@ -867,6 +988,14 @@ class Data: time < d['end']): return False return True + def phaseCollision(self, phase, isbegin, line): + key = 'end' + if isbegin: + key = 'start' + if self.dmesg[phase][key] >= 0: + sysvals.vprint('IGNORE: %s' % line.strip()) + return True + return False def sourcePhase(self, start): for phase in self.phases: pend = self.dmesg[phase]['end'] @@ -918,7 +1047,7 @@ class Data: return self.addDeviceFunctionCall(displayname, kprobename, proc, pid, start, end, cdata, rdata) # this should not happen if not tgtdev: - vprint('[%f - %f] %s-%d %s %s %s' % \ + 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 @@ -1054,6 +1183,13 @@ class Data: if('src' in d): for e in d['src']: e.time = self.trimTimeVal(e.time, t0, dT, left) + 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 normalizeTime(self, tZero): # trim out any standby or freeze clock time if(self.tSuspended != self.tResumed): @@ -1100,7 +1236,7 @@ class Data: if self.dmesg[p]['end'] > dev['start']: dev['end'] = self.dmesg[p]['end'] break - vprint('%s (%s): callback didnt return' % (devname, phase)) + sysvals.vprint('%s (%s): callback didnt return' % (devname, phase)) def deviceFilter(self, devicefilter): for phase in self.phases: list = self.dmesg[phase]['list'] @@ -1200,15 +1336,15 @@ class Data: devlist.append(child) return devlist def printDetails(self): - vprint('Timeline Details:') - vprint(' test start: %f' % self.start) - vprint('kernel suspend start: %f' % self.tKernSus) + sysvals.vprint('Timeline Details:') + sysvals.vprint(' test start: %f' % self.start) + sysvals.vprint('kernel suspend start: %f' % self.tKernSus) for phase in self.phases: dc = len(self.dmesg[phase]['list']) - vprint(' %16s: %f - %f (%d devices)' % (phase, \ + sysvals.vprint(' %16s: %f - %f (%d devices)' % (phase, \ self.dmesg[phase]['start'], self.dmesg[phase]['end'], dc)) - vprint(' kernel resume end: %f' % self.tKernRes) - vprint(' test end: %f' % self.end) + sysvals.vprint(' kernel resume end: %f' % self.tKernRes) + sysvals.vprint(' test end: %f' % self.end) def deviceChildrenAllPhases(self, devname): devlist = [] for phase in self.phases: @@ -1358,14 +1494,21 @@ class Data: tres.append(t) # process the events for suspend and resume if len(proclist) > 0: - vprint('Process Execution:') + sysvals.vprint('Process Execution:') for ps in proclist: c = self.addProcessUsageEvent(ps, tsus) if c > 0: - vprint('%25s (sus): %d' % (ps, c)) + sysvals.vprint('%25s (sus): %d' % (ps, c)) c = self.addProcessUsageEvent(ps, tres) if c > 0: - vprint('%25s (res): %d' % (ps, c)) + sysvals.vprint('%25s (res): %d' % (ps, c)) + def debugPrint(self): + for p in self.phases: + list = self.dmesg[p]['list'] + for devname in list: + dev = list[devname] + if 'ftrace' in dev: + dev['ftrace'].debugPrint(' [%s]' % devname) # Class: DevFunction # Description: @@ -1504,18 +1647,24 @@ class FTraceLine: # 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, dev=''): - if(self.freturn and self.fcall): - print('%s -- %f (%02d): %s(); (%.3f us)' % (dev, self.time, \ - self.depth, self.name, self.length*1000000)) - elif(self.freturn): - print('%s -- %f (%02d): %s} (%.3f us)' % (dev, self.time, \ - self.depth, self.name, self.length*1000000)) + def debugPrint(self, info=''): + if self.isLeaf(): + print(' -- %12.6f (depth=%02d): %s(); (%.3f us) %s' % (self.time, \ + self.depth, self.name, self.length*1000000, info)) + elif self.freturn: + print(' -- %12.6f (depth=%02d): %s} (%.3f us) %s' % (self.time, \ + self.depth, self.name, self.length*1000000, info)) else: - print('%s -- %f (%02d): %s() { (%.3f us)' % (dev, self.time, \ - self.depth, self.name, self.length*1000000)) + print(' -- %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: @@ -1558,107 +1707,160 @@ class FTraceCallGraph: depth = 0 pid = 0 name = '' - def __init__(self, pid): + partial = False + vfname = 'missing_function_name' + ignore = False + sv = 0 + def __init__(self, pid, sv): self.start = -1.0 self.end = -1.0 self.list = [] self.depth = 0 self.pid = pid - def addLine(self, line, debug=False): + self.sv = sv + def addLine(self, line): # if this is already invalid, just leave if(self.invalid): - return False - # invalidate on too much data or bad depth - if(len(self.list) >= 1000000 or self.depth < 0): + if(line.depth == 0 and line.freturn): + return 1 + return 0 + # invalidate on bad depth + if(self.depth < 0): self.invalidate(line) - return False + 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.freturn and not line.fcall): + if line.isReturn(): prelinedep += 1 last = 0 lasttime = line.time - virtualfname = 'missing_function_name' if len(self.list) > 0: last = self.list[-1] lasttime = last.time + if last.isLeaf(): + lasttime += last.length # handle low misalignments by inserting returns - if prelinedep < self.depth: - if debug and last: - print '-------- task %d --------' % self.pid - last.debugPrint() + 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: - if debug: - print 'MISALIGN LOW (add returns): C%d - eC%d' % (self.depth, prelinedep) self.depth -= 1 - if idx == 0 and last and last.fcall and not last.freturn: + 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 debug: - last.debugPrint() + if warning: + info.append(('[make leaf]', last)) else: vline = FTraceLine(lasttime) vline.depth = self.depth - vline.name = virtualfname + vline.name = self.vfname vline.freturn = True self.list.append(vline) - if debug: - vline.debugPrint() + if warning: + if idx == 0: + info.append(('', last)) + info.append(('[add return]', vline)) idx += 1 - if debug: - line.debugPrint() - print '' + if warning: + info.append(('', line)) # handle high misalignments by inserting calls - elif prelinedep > self.depth: - if debug and last: - print '-------- task %d --------' % self.pid - last.debugPrint() + elif mismatch > 0: idx = 0 + if warning: + info.append(('', last)) # add calls to get the depth up while prelinedep > self.depth: - if debug: - print 'MISALIGN HIGH (add calls): C%d - eC%d' % (self.depth, prelinedep) - if idx == 0 and line.freturn and not line.fcall: + 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 = virtualfname + vline.name = self.vfname vline.fcall = True - if debug: - vline.debugPrint() self.list.append(vline) self.depth += 1 if not last: self.start = vline.time + if warning: + info.append(('[add call]', vline)) idx += 1 - if debug: - line.debugPrint() - print '' + if warning and ('[make leaf]', line) not in info: + info.append(('', line)) + if warning: + print '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 - if(line.fcall and not line.freturn): - self.depth += 1 - elif(line.freturn and not line.fcall): + 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 - self.list.append(line) + # 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 == virtualfname: + if self.list[0].name == self.vfname: self.invalid = True - return True - return False + if res == -1: + self.partial = True + return res + return 0 def invalidate(self, line): if(len(self.list) > 0): first = self.list[0] @@ -1668,29 +1870,30 @@ class FTraceCallGraph: id = 'task %s' % (self.pid) window = '(%f - %f)' % (self.start, line.time) if(self.depth < 0): - vprint('Too much data for '+id+\ + print('Data misalignment for '+id+\ ' (buffer overflow), ignoring this callback') else: - vprint('Too much data for '+id+\ + print('Too much data for '+id+\ ' '+window+', ignoring this callback') - def slice(self, t0, tN): - minicg = FTraceCallGraph(0) - count = -1 - firstdepth = 0 + 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 < t0 or l.time > tN): + if(l.time < dev['start'] or l.time > dev['end']): continue - if(count < 0): - if(not l.fcall or l.name == 'dev_driver_string'): - continue - firstdepth = l.depth - count = 0 - l.depth -= firstdepth - minicg.addLine(l) - if((count == 0 and l.freturn and l.fcall) or - (count > 0 and l.depth <= 0)): + 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 - count += 1 + 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 @@ -1701,11 +1904,11 @@ class FTraceCallGraph: t.depth = i t.freturn = True fixed = self.addLine(t) - if fixed: + if fixed != 0: self.end = last.time return True return False - def postProcess(self, debug=False): + def postProcess(self): if len(self.list) > 0: self.name = self.list[0].name stack = dict() @@ -1714,20 +1917,23 @@ class FTraceCallGraph: 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.freturn and last.fcall): + if last and last.isLeaf(): if last.length > l.time - last.time: last.length = l.time - last.time - if(l.fcall and not l.freturn): + if l.isCall(): stack[l.depth] = l cnt += 1 - elif(l.freturn and not l.fcall): + elif l.isReturn(): if(l.depth not in stack): - if debug: + if self.sv.verbose: print 'Post Process Error: Depth missing' l.debugPrint() return False # calculate call length from call/return lines - stack[l.depth].length = l.time - stack[l.depth].time + 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 @@ -1736,13 +1942,13 @@ class FTraceCallGraph: # trace caught the whole call tree return True elif(cnt < 0): - if debug: + if self.sv.verbose: print 'Post Process Error: Depth is less than 0' return False # trace ended before call tree finished return self.repair(cnt) def deviceMatch(self, pid, data): - found = False + found = '' # add the callgraph data to the device hierarchy borderphase = { 'dpm_prepare': 'suspend_prepare', @@ -1756,8 +1962,10 @@ class FTraceCallGraph: if(pid == dev['pid'] and self.start <= dev['start'] and self.end >= dev['end']): - dev['ftrace'] = self.slice(dev['start'], dev['end']) - found = True + cg = self.slice(dev) + if cg: + dev['ftrace'] = cg + found = devname return found for p in data.phases: if(data.dmesg[p]['start'] <= self.start and @@ -1769,7 +1977,7 @@ class FTraceCallGraph: self.start <= dev['start'] and self.end >= dev['end']): dev['ftrace'] = self - found = True + found = devname break break return found @@ -1793,18 +2001,20 @@ class FTraceCallGraph: if out: phase, myname = out data.dmesg[phase]['list'][myname]['ftrace'] = self - def debugPrint(self): - print('[%f - %f] %s (%d)') % (self.start, self.end, self.name, self.pid) + def debugPrint(self, info=''): + print('%s pid=%d [%f - %f] %.3f us') % \ + (self.name, self.pid, self.start, self.end, + (self.end - self.start)*1000000) for l in self.list: - if(l.freturn and l.fcall): - print('%f (%02d): %s(); (%.3f us)' % (l.time, \ - l.depth, l.name, l.length*1000000)) - elif(l.freturn): - print('%f (%02d): %s} (%.3f us)' % (l.time, \ - l.depth, l.name, l.length*1000000)) + if l.isLeaf(): + print('%f (%02d): %s(); (%.3f us)%s' % (l.time, \ + l.depth, l.name, l.length*1000000, info)) + elif l.freturn: + print('%f (%02d): %s} (%.3f us)%s' % (l.time, \ + l.depth, l.name, l.length*1000000, info)) else: - print('%f (%02d): %s() { (%.3f us)' % (l.time, \ - l.depth, l.name, l.length*1000000)) + print('%f (%02d): %s() { (%.3f us)%s' % (l.time, \ + l.depth, l.name, l.length*1000000, info)) print(' ') class DevItem: @@ -1839,8 +2049,8 @@ class Timeline: self.rowH = rowheight self.scaleH = scaleheight self.html = '' - def createHeader(self, sv): - if(not sv.stamp['time']): + def createHeader(self, sv, stamp): + if(not stamp['time']): return self.html += '
%s v%s
' \ % (sv.title, sv.version) @@ -1851,12 +2061,12 @@ class Timeline: if sv.ftracelog: self.html += '' headline_stamp = '
{0} {1} {2} {3}
\n' - self.html += headline_stamp.format(sv.stamp['host'], sv.stamp['kernel'], - sv.stamp['mode'], sv.stamp['time']) - if 'man' in sv.stamp and 'plat' in sv.stamp and 'cpu' in sv.stamp: + self.html += headline_stamp.format(stamp['host'], stamp['kernel'], + stamp['mode'], stamp['time']) + if 'man' in stamp and 'plat' in stamp and 'cpu' in stamp and \ + stamp['man'] and stamp['plat'] and stamp['cpu']: headline_sysinfo = '
{0} {1} with {2}
\n' - self.html += headline_sysinfo.format(sv.stamp['man'], - sv.stamp['plat'], sv.stamp['cpu']) + self.html += headline_sysinfo.format(stamp['man'], stamp['plat'], stamp['cpu']) # Function: getDeviceRows # Description: @@ -2067,12 +2277,16 @@ class Timeline: class TestProps: stamp = '' sysinfo = '' + cmdline = '' + kparams = '' S0i3 = False fwdata = [] stampfmt = '# [a-z]*-(?P[0-9]{2})(?P[0-9]{2})(?P[0-9]{2})-'+\ '(?P[0-9]{2})(?P[0-9]{2})(?P[0-9]{2})'+\ ' (?P.*) (?P.*) (?P.*)$' sysinfofmt = '^# sysinfo .*' + cmdlinefmt = '^# command \| (?P.*)' + kparamsfmt = '^# kparams \| (?P.*)' ftrace_line_fmt_fg = \ '^ *(?P