From patchwork Wed Jul 5 21:42:55 2017 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Todd Brandt X-Patchwork-Id: 9827179 X-Patchwork-Delegate: rjw@sisk.pl Return-Path: Received: from mail.wl.linuxfoundation.org (pdx-wl-mail.web.codeaurora.org [172.30.200.125]) by pdx-korg-patchwork.web.codeaurora.org (Postfix) with ESMTP id 1737A60361 for ; Wed, 5 Jul 2017 21:43:08 +0000 (UTC) Received: from mail.wl.linuxfoundation.org (localhost [127.0.0.1]) by mail.wl.linuxfoundation.org (Postfix) with ESMTP id F158827F95 for ; Wed, 5 Jul 2017 21:43:07 +0000 (UTC) Received: by mail.wl.linuxfoundation.org (Postfix, from userid 486) id E603728501; Wed, 5 Jul 2017 21:43:07 +0000 (UTC) X-Spam-Checker-Version: SpamAssassin 3.3.1 (2010-03-16) on pdx-wl-mail.web.codeaurora.org X-Spam-Level: X-Spam-Status: No, score=-6.9 required=2.0 tests=BAYES_00,RCVD_IN_DNSWL_HI autolearn=ham version=3.3.1 Received: from vger.kernel.org (vger.kernel.org [209.132.180.67]) by mail.wl.linuxfoundation.org (Postfix) with ESMTP id 9358427F95 for ; Wed, 5 Jul 2017 21:43:05 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1752043AbdGEVnE (ORCPT ); Wed, 5 Jul 2017 17:43:04 -0400 Received: from mga09.intel.com ([134.134.136.24]:58554 "EHLO mga09.intel.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1751896AbdGEVnC (ORCPT ); Wed, 5 Jul 2017 17:43:02 -0400 Received: from fmsmga002.fm.intel.com ([10.253.24.26]) by orsmga102.jf.intel.com with ESMTP/TLS/DHE-RSA-AES256-GCM-SHA384; 05 Jul 2017 14:43:00 -0700 X-ExtLoop1: 1 X-IronPort-AV: E=Sophos;i="5.40,313,1496127600"; d="scan'208";a="1190967921" Received: from skerner-mobl.amr.corp.intel.com (HELO technocore.\040none\041) ([10.252.137.126]) by fmsmga002.fm.intel.com with ESMTP; 05 Jul 2017 14:43:00 -0700 From: Todd Brandt To: linux-pm@vger.kernel.org, rafael.j.wysocki@intel.com, rjw@rjwysocki.net Cc: todd.e.brandt@linux.intel.com, todd.e.brandt@intel.com Subject: [PATCH 1/3] pm-graph: AnalyzeSuspend v4.7 Date: Wed, 5 Jul 2017 14:42:55 -0700 Message-Id: <7267bdd45b88058e46331f4f63a03d349f57be2b.1499290431.git.todd.e.brandt@linux.intel.com> X-Mailer: git-send-email 2.11.0 In-Reply-To: References: In-Reply-To: References: Sender: linux-pm-owner@vger.kernel.org Precedence: bulk List-ID: X-Mailing-List: linux-pm@vger.kernel.org X-Virus-Scanned: ClamAV using ClamSMTP - changed -rtcwake parameter to be on & 15 sec by default, to disable rtcwake use: "-rtcwake off" - changed behavior of -o: renames html file on rerun, subdir on new run - changed execution_misalignment error to missing_function_name - add sysinfo to logs and timeline via a custom dmidecode call it supplants dmidecode tool when used as a library call - add -sysinfo command, displays dmidecode values and cpu/mem info - set trace buffer size to lesser of memtotal/2 or 2GB when using callgraph - add support for /sys/power/mem_sleep. if mem_sleep found: mem-shallow=standby, mem-s2idle=freeze, mem-deep=mem - remove redundant javascript - cosmetic changes to html layout Signed-off-by: Todd Brandt --- tools/power/pm-graph/analyze_suspend.py | 534 +++++++++++++++++++++++--------- 1 file changed, 379 insertions(+), 155 deletions(-) diff --git a/tools/power/pm-graph/analyze_suspend.py b/tools/power/pm-graph/analyze_suspend.py index a9206e67fc1f..1b60fe203741 100755 --- a/tools/power/pm-graph/analyze_suspend.py +++ b/tools/power/pm-graph/analyze_suspend.py @@ -68,10 +68,12 @@ from subprocess import call, Popen, PIPE # store system values and test parameters class SystemValues: title = 'SleepGraph' - version = '4.6' + version = '4.7' ansi = False verbose = False - addlogs = False + testlog = True + dmesglog = False + ftracelog = False mindevlen = 0.0 mincglen = 0.0 cgphase = '' @@ -79,10 +81,11 @@ class SystemValues: max_graph_depth = 0 callloopmaxgap = 0.0001 callloopmaxlen = 0.005 + cpucount = 0 + memtotal = 204800 srgap = 0 cgexp = False - outdir = '' - testdir = '.' + testdir = '' tpath = '/sys/kernel/debug/tracing/' fpdtpath = '/sys/firmware/acpi/tables/FPDT' epath = '/sys/kernel/debug/tracing/events/power/' @@ -95,14 +98,17 @@ class SystemValues: testcommand = '' mempath = '/dev/mem' powerfile = '/sys/power/state' + mempowerfile = '/sys/power/mem_sleep' suspendmode = 'mem' + memmode = '' hostname = 'localhost' prefix = 'test' teststamp = '' + sysstamp = '' dmesgstart = 0.0 dmesgfile = '' ftracefile = '' - htmlfile = '' + htmlfile = 'output.html' embedded = False rtcwake = True rtcwaketime = 15 @@ -127,9 +133,6 @@ class SystemValues: devpropfmt = '# Device Properties: .*' tracertypefmt = '# tracer: (?P.*)' firmwarefmt = '# fwsuspend (?P[0-9]*) fwresume (?P[0-9]*)$' - stampfmt = '# suspend-(?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.*)$' tracefuncs = { 'sys_sync': dict(), 'pm_prepare_console': dict(), @@ -218,7 +221,7 @@ class SystemValues: # if this is a phoronix test run, set some default options if('LOG_FILE' in os.environ and 'TEST_RESULTS_IDENTIFIER' in os.environ): self.embedded = True - self.addlogs = True + self.dmesglog = self.ftracelog = True self.htmlfile = os.environ['LOG_FILE'] self.archargs = 'args_'+platform.machine() self.hostname = platform.node() @@ -233,6 +236,13 @@ class SystemValues: 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') + 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') + return False def rootUser(self, fatal=False): if 'USER' in os.environ and os.environ['USER'] == 'root': return True @@ -249,30 +259,60 @@ class SystemValues: args['date'] = n.strftime('%y%m%d') args['time'] = n.strftime('%H%M%S') args['hostname'] = self.hostname - self.outdir = value.format(**args) + return value.format(**args) def setOutputFile(self): - if((self.htmlfile == '') and (self.dmesgfile != '')): + if self.dmesgfile != '': m = re.match('(?P.*)_dmesg\.txt$', self.dmesgfile) if(m): self.htmlfile = m.group('name')+'.html' - if((self.htmlfile == '') and (self.ftracefile != '')): + if self.ftracefile != '': m = re.match('(?P.*)_ftrace\.txt$', self.ftracefile) if(m): self.htmlfile = m.group('name')+'.html' - if(self.htmlfile == ''): - self.htmlfile = 'output.html' - def initTestOutput(self, subdir, testpath=''): + def systemInfo(self, info): + p = c = m = b = '' + if 'baseboard-manufacturer' in info: + m = info['baseboard-manufacturer'] + elif 'system-manufacturer' in info: + m = info['system-manufacturer'] + if 'baseboard-product-name' in info: + p = info['baseboard-product-name'] + elif 'system-product-name' in info: + p = info['system-product-name'] + if 'processor-version' in info: + 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.rootCheck(True) + out = dmidecode(self.mempath, True) + 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)) + 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[0-9]*) *kB', line) + if m: + self.memtotal = int(m.group('sz')) + break + fp.close() + def initTestOutput(self, name): self.prefix = self.hostname v = open('/proc/version', 'r').read().strip() kver = string.split(v)[2] - n = datetime.now() - testtime = n.strftime('suspend-%m%d%y-%H%M%S') - if not testpath: - testpath = n.strftime('suspend-%y%m%d-%H%M%S') - if(subdir != "."): - self.testdir = subdir+"/"+testpath - else: - self.testdir = testpath + fmt = name+'-%m%d%y-%H%M%S' + testtime = datetime.now().strftime(fmt) self.teststamp = \ '# '+testtime+' '+self.prefix+' '+self.suspendmode+' '+kver if(self.embedded): @@ -355,7 +395,7 @@ class SystemValues: continue self.tracefuncs[i] = dict() def getFtraceFilterFunctions(self, current): - rootCheck(True) + self.rootCheck(True) if not current: call('cat '+self.tpath+'available_filter_functions', shell=True) return @@ -453,7 +493,7 @@ class SystemValues: val += '\nr:%s_ret %s $retval\n' % (name, func) return val def addKprobes(self, output=False): - if len(sysvals.kprobes) < 1: + if len(self.kprobes) < 1: return if output: print(' kprobe functions in this kernel:') @@ -525,7 +565,7 @@ class SystemValues: fp.flush() fp.close() except: - pass + return False return True def fgetVal(self, path): file = self.tpath+path @@ -566,9 +606,15 @@ class SystemValues: self.cleanupFtrace() # set the trace clock to global self.fsetVal('global', 'trace_clock') - # set trace buffer to a huge value self.fsetVal('nop', 'current_tracer') - self.fsetVal('131073', 'buffer_size_kb') + # 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') + else: + self.fsetVal('16384', 'buffer_size_kb') # go no further if this is just a status check if testing: return @@ -641,6 +687,15 @@ class SystemValues: if not self.ansi: 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') + 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])) + fp.close() sysvals = SystemValues() suspendmodename = { @@ -1008,6 +1063,12 @@ class Data: else: self.trimTime(self.tSuspended, \ self.tResumed-self.tSuspended, False) + def getTimeValues(self): + sktime = (self.dmesg['suspend_machine']['end'] - \ + self.tKernSus) * 1000 + rktime = (self.dmesg['resume_complete']['end'] - \ + self.dmesg['resume_machine']['start']) * 1000 + return (sktime, rktime) def setPhase(self, phase, ktime, isbegin): if(isbegin): self.dmesg[phase]['start'] = ktime @@ -1517,7 +1578,7 @@ class FTraceCallGraph: prelinedep += 1 last = 0 lasttime = line.time - virtualfname = 'execution_misalignment' + virtualfname = 'missing_function_name' if len(self.list) > 0: last = self.list[-1] lasttime = last.time @@ -1773,24 +1834,30 @@ class Timeline: html_device = '
{6}
\n' html_phase = '
{5}
\n' html_phaselet = '
\n' + html_legend = '
 {2}
\n' def __init__(self, rowheight, scaleheight): self.rowH = rowheight self.scaleH = scaleheight self.html = '' - def createHeader(self, sv, suppress=''): + def createHeader(self, sv): if(not sv.stamp['time']): return self.html += '
%s v%s
' \ % (sv.title, sv.version) - if sv.logmsg and 'log' not in suppress: - self.html += '' - if sv.addlogs and 'dmesg' not in suppress: - self.html += '' - if sv.addlogs and sv.ftracefile and 'ftrace' not in suppress: - self.html += '' + if sv.logmsg and sv.testlog: + self.html += '' + if sv.dmesglog: + self.html += '' + 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: + headline_sysinfo = '
{0} {1} with {2}
\n' + self.html += headline_sysinfo.format(sv.stamp['man'], + sv.stamp['plat'], sv.stamp['cpu']) + # Function: getDeviceRows # Description: # determine how may rows the device funcs will take @@ -1839,7 +1906,7 @@ class Timeline: # devlist: the list of devices/actions in a group of contiguous phases # Output: # The total number of rows needed to display this phase of the timeline - def getPhaseRows(self, devlist, row=0): + def getPhaseRows(self, devlist, row=0, sortby='length'): # clear all rows and set them to undefined remaining = len(devlist) rowdata = dict() @@ -1852,8 +1919,12 @@ class Timeline: if tp not in myphases: myphases.append(tp) dev['row'] = -1 - # sort by length 1st, then name 2nd - sortdict[item] = (float(dev['end']) - float(dev['start']), item.dev['name']) + if sortby == 'start': + # sort by start 1st, then length 2nd + sortdict[item] = (-1*float(dev['start']), float(dev['end']) - float(dev['start'])) + else: + # sort by length 1st, then name 2nd + sortdict[item] = (float(dev['end']) - float(dev['start']), item.dev['name']) if 'src' in dev: dev['devrows'] = self.getDeviceRows(dev['src']) # sort the devlist by length so that large items graph on top @@ -1995,8 +2066,13 @@ class Timeline: # A list of values describing the properties of these test runs class TestProps: stamp = '' + sysinfo = '' 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 .*' ftrace_line_fmt_fg = \ '^ *(?P