| Message ID | 20220707225451.32738-1-todd.e.brandt@intel.com (mailing list archive) |
|---|---|
| State | Mainlined, archived |
| Headers | show |
| Series | pm-graph v5.9 | expand |
On Fri, Jul 8, 2022 at 12:54 AM Todd Brandt <todd.e.brandt@intel.com> wrote: > > bootgraph: > - fix parsing of /proc/version to be much more flexible > - check kernel version to disallow ftrace on anything older than 4.10 > sleepgraph: > - include fix to bugzilla 212761 in case it regresses > - fix for -proc bug: https://github.com/intel/pm-graph/pull/20 > - add -debugtiming arg to get timestamps on prints > - allow use of the netfix tool hosted in the github repo > - read s0ix data from pmc_core for better debug > - include more system data in the output log > - Do a better job testing input files useability > - flag more error data from dmesg in the timeline > - pre-parse the trace log to fix any ordering issues > - add new parser to process dmesg only timelines > - remove superflous sleep(5) in multitest mode > config/custom-timeline-functions.cfg: > - change some names to keep up to date > README: > - new version, small wording changes > > Signed-off-by: Todd Brandt <todd.e.brandt@intel.com> Applied as 5.20 material, thanks! > --- > tools/power/pm-graph/README | 6 +- > tools/power/pm-graph/bootgraph.py | 20 +- > .../config/custom-timeline-functions.cfg | 2 +- > tools/power/pm-graph/sleepgraph.py | 518 ++++++++++++------ > 4 files changed, 360 insertions(+), 186 deletions(-) > > diff --git a/tools/power/pm-graph/README b/tools/power/pm-graph/README > index da468bd510ca..e6020c0d59ec 100644 > --- a/tools/power/pm-graph/README > +++ b/tools/power/pm-graph/README > @@ -6,7 +6,7 @@ > |_| |___/ |_| > > pm-graph: suspend/resume/boot timing analysis tools > - Version: 5.8 > + Version: 5.9 > Author: Todd Brandt <todd.e.brandt@intel.com> > Home Page: https://01.org/pm-graph > > @@ -97,8 +97,8 @@ > (kernel/pre-3.15/enable_trace_events_suspend_resume.patch) > (kernel/pre-3.15/enable_trace_events_device_pm_callback.patch) > > - If you're using a kernel older than 3.15.0, the following > - additional kernel parameters are required: > + If you're using bootgraph, or sleepgraph with a kernel older than 3.15.0, > + the following additional kernel parameters are required: > (e.g. in file /etc/default/grub) > GRUB_CMDLINE_LINUX_DEFAULT="... initcall_debug log_buf_len=32M ..." > > diff --git a/tools/power/pm-graph/bootgraph.py b/tools/power/pm-graph/bootgraph.py > index 2823cd3122f7..f96f50e0c336 100755 > --- a/tools/power/pm-graph/bootgraph.py > +++ b/tools/power/pm-graph/bootgraph.py > @@ -69,22 +69,24 @@ class SystemValues(aslib.SystemValues): > bootloader = 'grub' > blexec = [] > def __init__(self): > - self.hostname = platform.node() > + self.kernel, self.hostname = 'unknown', platform.node() > self.testtime = datetime.now().strftime('%Y-%m-%d_%H:%M:%S') > if os.path.exists('/proc/version'): > fp = open('/proc/version', 'r') > - val = fp.read().strip() > + self.kernel = self.kernelVersion(fp.read().strip()) > fp.close() > - self.kernel = self.kernelVersion(val) > - else: > - self.kernel = 'unknown' > self.testdir = datetime.now().strftime('boot-%y%m%d-%H%M%S') > def kernelVersion(self, msg): > - return msg.split()[2] > + m = re.match('^[Ll]inux *[Vv]ersion *(?P<v>\S*) .*', msg) > + if m: > + return m.group('v') > + return 'unknown' > def checkFtraceKernelVersion(self): > - val = tuple(map(int, self.kernel.split('-')[0].split('.'))) > - if val >= (4, 10, 0): > - return True > + m = re.match('^(?P<x>[0-9]*)\.(?P<y>[0-9]*)\.(?P<z>[0-9]*).*', self.kernel) > + if m: > + val = tuple(map(int, m.groups())) > + if val >= (4, 10, 0): > + return True > return False > def kernelParams(self): > cmdline = 'initcall_debug log_buf_len=32M' > diff --git a/tools/power/pm-graph/config/custom-timeline-functions.cfg b/tools/power/pm-graph/config/custom-timeline-functions.cfg > index 962e5768681c..4f80ad7d7275 100644 > --- a/tools/power/pm-graph/config/custom-timeline-functions.cfg > +++ b/tools/power/pm-graph/config/custom-timeline-functions.cfg > @@ -125,7 +125,7 @@ acpi_suspend_begin: > suspend_console: > acpi_pm_prepare: > syscore_suspend: > -arch_thaw_secondary_cpus_end: > +arch_enable_nonboot_cpus_end: > syscore_resume: > acpi_pm_finish: > resume_console: > diff --git a/tools/power/pm-graph/sleepgraph.py b/tools/power/pm-graph/sleepgraph.py > index ffd50953a024..33981adcdd68 100755 > --- a/tools/power/pm-graph/sleepgraph.py > +++ b/tools/power/pm-graph/sleepgraph.py > @@ -66,8 +66,13 @@ from threading import Thread > from subprocess import call, Popen, PIPE > import base64 > > +debugtiming = False > +mystarttime = time.time() > def pprint(msg): > - print(msg) > + if debugtiming: > + print('[%09.3f] %s' % (time.time()-mystarttime, msg)) > + else: > + print(msg) > sys.stdout.flush() > > def ascii(text): > @@ -81,13 +86,14 @@ def ascii(text): > # store system values and test parameters > class SystemValues: > title = 'SleepGraph' > - version = '5.8' > + version = '5.9' > ansi = False > rs = 0 > display = '' > gzip = False > sync = False > wifi = False > + netfix = False > verbose = False > testlog = True > dmesglog = True > @@ -108,6 +114,7 @@ class SystemValues: > cpucount = 0 > memtotal = 204800 > memfree = 204800 > + osversion = '' > srgap = 0 > cgexp = False > testdir = '' > @@ -116,6 +123,7 @@ class SystemValues: > fpdtpath = '/sys/firmware/acpi/tables/FPDT' > epath = '/sys/kernel/debug/tracing/events/power/' > pmdpath = '/sys/power/pm_debug_messages' > + s0ixpath = '/sys/module/intel_pmc_core/parameters/warn_on_s0ix_failures' > acpipath='/sys/module/acpi/parameters/debug_level' > traceevents = [ > 'suspend_resume', > @@ -156,6 +164,7 @@ class SystemValues: > ftop = False > usetraceevents = False > usetracemarkers = True > + useftrace = True > usekprobes = True > usedevsrc = False > useprocmon = False > @@ -279,10 +288,16 @@ class SystemValues: > 'intel_fbdev_set_suspend': {}, > } > infocmds = [ > + [0, 'sysinfo', 'uname', '-a'], > + [0, 'cpuinfo', 'head', '-7', '/proc/cpuinfo'], > [0, 'kparams', 'cat', '/proc/cmdline'], > [0, 'mcelog', 'mcelog'], > [0, 'pcidevices', 'lspci', '-tv'], > - [0, 'usbdevices', 'lsusb', '-t'], > + [0, 'usbdevices', 'lsusb', '-tv'], > + [0, 'acpidevices', 'sh', '-c', 'ls -l /sys/bus/acpi/devices/*/physical_node'], > + [0, 's0ix_require', 'cat', '/sys/kernel/debug/pmc_core/substate_requirements'], > + [0, 's0ix_debug', 'cat', '/sys/kernel/debug/pmc_core/slp_s0_debug_status'], > + [1, 's0ix_residency', 'cat', '/sys/kernel/debug/pmc_core/slp_s0_residency_usec'], > [1, 'interrupts', 'cat', '/proc/interrupts'], > [1, 'wakeups', 'cat', '/sys/kernel/debug/wakeup_sources'], > [2, 'gpecounts', 'sh', '-c', 'grep -v invalid /sys/firmware/acpi/interrupts/*'], > @@ -358,8 +373,19 @@ class SystemValues: > 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 usable(self, file, ishtml=False): > + if not os.path.exists(file) or os.path.getsize(file) < 1: > + return False > + if ishtml: > + try: > + fp = open(file, 'r') > + res = fp.read(1000) > + fp.close() > + except: > + return False > + if '<html>' not in res: > + return False > + return True > def getExec(self, cmd): > try: > fp = Popen(['which', cmd], stdout=PIPE, stderr=PIPE).stdout > @@ -413,12 +439,16 @@ class SystemValues: > r = info['bios-release-date'] if 'bios-release-date' in info else '' > self.sysstamp = '# sysinfo | man:%s | plat:%s | cpu:%s | bios:%s | biosdate:%s | numcpu:%d | memsz:%d | memfr:%d' % \ > (m, p, c, b, r, self.cpucount, self.memtotal, self.memfree) > + if self.osversion: > + self.sysstamp += ' | os:%s' % self.osversion > def printSystemInfo(self, fatal=False): > self.rootCheck(True) > out = dmidecode(self.mempath, fatal) > if len(out) < 1: > return > fmt = '%-24s: %s' > + if self.osversion: > + print(fmt % ('os-version', self.osversion)) > for name in sorted(out): > print(fmt % (name, out[name])) > print(fmt % ('cpucount', ('%d' % self.cpucount))) > @@ -426,20 +456,25 @@ class SystemValues: > 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() > + if os.path.exists('/proc/cpuinfo'): > + with open('/proc/cpuinfo', 'r') as fp: > + for line in fp: > + if re.match('^processor[ \t]*:[ \t]*[0-9]*', line): > + self.cpucount += 1 > + if os.path.exists('/proc/meminfo'): > + with open('/proc/meminfo', 'r') as fp: > + for line in fp: > + m = re.match('^MemTotal:[ \t]*(?P<sz>[0-9]*) *kB', line) > + if m: > + self.memtotal = int(m.group('sz')) > + m = re.match('^MemFree:[ \t]*(?P<sz>[0-9]*) *kB', line) > + if m: > + self.memfree = int(m.group('sz')) > + if os.path.exists('/etc/os-release'): > + with open('/etc/os-release', 'r') as fp: > + for line in fp: > + if line.startswith('PRETTY_NAME='): > + self.osversion = line[12:].strip().replace('"', '') > def initTestOutput(self, name): > self.prefix = self.hostname > v = open('/proc/version', 'r').read().strip() > @@ -698,6 +733,8 @@ class SystemValues: > return False > return True > def fsetVal(self, val, path): > + if not self.useftrace: > + return False > return self.setVal(val, self.tpath+path) > def getVal(self, file): > res = '' > @@ -711,9 +748,11 @@ class SystemValues: > pass > return res > def fgetVal(self, path): > + if not self.useftrace: > + return '' > return self.getVal(self.tpath+path) > def cleanupFtrace(self): > - if(self.usecallgraph or self.usetraceevents or self.usedevsrc): > + if self.useftrace: > self.fsetVal('0', 'events/kprobes/enable') > self.fsetVal('', 'kprobe_events') > self.fsetVal('1024', 'buffer_size_kb') > @@ -734,13 +773,14 @@ class SystemValues: > return True > return False > def initFtrace(self, quiet=False): > + if not self.useftrace: > + return > if not quiet: > sysvals.printSystemInfo(False) > pprint('INITIALIZING FTRACE...') > # turn trace off > self.fsetVal('0', 'tracing_on') > self.cleanupFtrace() > - self.testVal(self.pmdpath, 'basic', '1') > # set the trace clock to global > self.fsetVal('global', 'trace_clock') > self.fsetVal('nop', 'current_tracer') > @@ -766,6 +806,10 @@ class SystemValues: > # set trace type > self.fsetVal('function_graph', 'current_tracer') > self.fsetVal('', 'set_ftrace_filter') > + # temporary hack to fix https://bugzilla.kernel.org/show_bug.cgi?id=212761 > + fp = open(self.tpath+'set_ftrace_notrace', 'w') > + fp.write('native_queued_spin_lock_slowpath\ndev_driver_string') > + fp.close() > # set trace format options > self.fsetVal('print-parent', 'trace_options') > self.fsetVal('funcgraph-abstime', 'trace_options') > @@ -846,6 +890,8 @@ class SystemValues: > fp.write('# turbostat %s\n' % test['turbo']) > if 'wifi' in test: > fp.write('# wifi %s\n' % test['wifi']) > + if 'netfix' in test: > + fp.write('# netfix %s\n' % test['netfix']) > if test['error'] or len(testdata) > 1: > fp.write('# enter_sleep_error %s\n' % test['error']) > return fp > @@ -865,6 +911,8 @@ class SystemValues: > fp.write('error%s: %s\n' % (n, testdata['error'])) > else: > fp.write('result%s: pass\n' % n) > + if 'mode' in testdata: > + fp.write('mode%s: %s\n' % (n, testdata['mode'])) > for v in ['suspend', 'resume', 'boot', 'lastinit']: > if v in testdata: > fp.write('%s%s: %.3f\n' % (v, n, testdata[v])) > @@ -901,6 +949,8 @@ class SystemValues: > fp.write(text) > fp.close() > def dlog(self, text): > + if not self.dmesgfile: > + return > self.putlog(self.dmesgfile, '# %s\n' % text) > def flog(self, text): > self.putlog(self.ftracefile, text) > @@ -954,34 +1004,31 @@ class SystemValues: > 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 = False > + if os.path.exists(dirname+'/power/async'): > + fp = open(dirname+'/power/async') > + if 'enabled' in fp.read(): > props[dev].isasync = True > + fp.close() > fields = os.listdir(dirname) > - 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) > + for file in ['product', 'name', 'model', 'description', 'id', 'idVendor']: > + if file not in fields: > + continue > + try: > + with open(os.path.join(dirname, file), 'rb') as fp: > + props[dev].altname = ascii(fp.read()) > + except: > + continue > + if file == 'idVendor': > + idv, idp = props[dev].altname.strip(), '' > + try: > + with open(os.path.join(dirname, 'idProduct'), 'rb') as fp: > + idp = ascii(fp.read()).strip() > + except: > + props[dev].altname = '' > + break > + props[dev].altname = '%s:%s' % (idv, idp) > + break > if props[dev].altname: > out = props[dev].altname.strip().replace('\n', ' ')\ > .replace(',', ' ').replace(';', ' ') > @@ -1047,7 +1094,7 @@ class SystemValues: > 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 '' > + dinfo = ('\t%s\n' % before['@']) if '@' in before and len(before) > 1 else '' > prefix = self.commonPrefix(list(before.keys())) > for key in sorted(before): > if key in after and before[key] != after[key]: > @@ -1128,6 +1175,22 @@ class SystemValues: > val = valline[idx] > out.append('%s=%s' % (key, val)) > return '|'.join(out) > + def netfixon(self, net='both'): > + cmd = self.getExec('netfix') > + if not cmd: > + return '' > + fp = Popen([cmd, '-s', net, 'on'], stdout=PIPE, stderr=PIPE).stdout > + out = ascii(fp.read()).strip() > + fp.close() > + return out > + def wifiRepair(self): > + out = self.netfixon('wifi') > + if not out or 'error' in out.lower(): > + return '' > + m = re.match('WIFI \S* ONLINE (?P<action>\S*)', out) > + if not m: > + return 'dead' > + return m.group('action') > def wifiDetails(self, dev): > try: > info = open('/sys/class/net/%s/device/uevent' % dev, 'r').read().strip() > @@ -1144,12 +1207,12 @@ class SystemValues: > except: > return '' > for line in reversed(w.split('\n')): > - m = re.match(' *(?P<dev>.*): (?P<stat>[0-9a-f]*) .*', w.split('\n')[-1]) > + m = re.match(' *(?P<dev>.*): (?P<stat>[0-9a-f]*) .*', line) > if not m or (dev and dev != m.group('dev')): > continue > return m.group('dev') > return '' > - def pollWifi(self, dev, timeout=60): > + def pollWifi(self, dev, timeout=10): > start = time.time() > while (time.time() - start) < timeout: > w = self.checkWifi(dev) > @@ -1157,6 +1220,11 @@ class SystemValues: > return '%s reconnected %.2f' % \ > (self.wifiDetails(dev), max(0, time.time() - start)) > time.sleep(0.01) > + if self.netfix: > + res = self.wifiRepair() > + if res: > + timeout = max(0, time.time() - start) > + return '%s %s %d' % (self.wifiDetails(dev), res, timeout) > return '%s timeout %d' % (self.wifiDetails(dev), timeout) > def errorSummary(self, errinfo, msg): > found = False > @@ -1283,10 +1351,10 @@ 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)' > + 'standby': 'standby (S1)', > + 'freeze': 'freeze (S2idle)', > + 'mem': 'suspend (S3)', > + 'disk': 'hibernate (S4)' > } > > # Class: DevProps > @@ -1376,6 +1444,7 @@ class Data: > 'INVALID' : r'(?i).*\bINVALID\b.*', > 'CRASH' : r'(?i).*\bCRASHED\b.*', > 'TIMEOUT' : r'(?i).*\bTIMEOUT\b.*', > + 'ABORT' : r'(?i).*\bABORT\b.*', > 'IRQ' : r'.*\bgenirq: .*', > 'TASKFAIL': r'.*Freezing of tasks *.*', > 'ACPI' : r'.*\bACPI *(?P<b>[A-Za-z]*) *Error[: ].*', > @@ -1724,9 +1793,9 @@ class Data: > 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)) > + tTry = '%.0f' % (round(self.dmesg[lp]['waking'][1] * 1000)) > else: > - tTry = '-%.3f' % (self.dmesg[lp]['waking'][1] * 1000) > + tTry = '%.3f' % (self.dmesg[lp]['waking'][1] * 1000) > text = '%.0f (%s ms waking %d times)' % (tL * 1000, tTry, tCnt) > else: > text = '%.0f' % (tL * 1000) > @@ -2107,6 +2176,30 @@ class Data: > # set resume complete to end at end marker > if 'resume_complete' in dm: > dm['resume_complete']['end'] = time > + def initcall_debug_call(self, line, quick=False): > + m = re.match('.*(\[ *)(?P<t>[0-9\.]*)(\]) .* (?P<f>.*)\: '+\ > + 'PM: *calling .* @ (?P<n>.*), parent: (?P<p>.*)', line) > + if not m: > + m = re.match('.*(\[ *)(?P<t>[0-9\.]*)(\]) .* (?P<f>.*)\: '+\ > + 'calling .* @ (?P<n>.*), parent: (?P<p>.*)', line) > + if not m: > + m = re.match('.*(\[ *)(?P<t>[0-9\.]*)(\]) calling '+\ > + '(?P<f>.*)\+ @ (?P<n>.*), parent: (?P<p>.*)', line) > + if m: > + return True if quick else m.group('t', 'f', 'n', 'p') > + return False if quick else ('', '', '', '') > + def initcall_debug_return(self, line, quick=False): > + m = re.match('.*(\[ *)(?P<t>[0-9\.]*)(\]) .* (?P<f>.*)\: PM: '+\ > + '.* returned (?P<r>[0-9]*) after (?P<dt>[0-9]*) usecs', line) > + if not m: > + m = re.match('.*(\[ *)(?P<t>[0-9\.]*)(\]) .* (?P<f>.*)\: '+\ > + '.* returned (?P<r>[0-9]*) after (?P<dt>[0-9]*) usecs', line) > + if not m: > + m = re.match('.*(\[ *)(?P<t>[0-9\.]*)(\]) call '+\ > + '(?P<f>.*)\+ returned .* after (?P<dt>.*) usecs', line) > + if m: > + return True if quick else m.group('t', 'f', 'dt') > + return False if quick else ('', '', '') > def debugPrint(self): > for p in self.sortedPhases(): > list = self.dmesg[p]['list'] > @@ -2880,10 +2973,11 @@ class TestProps: > cmdlinefmt = '^# command \| (?P<cmd>.*)' > kparamsfmt = '^# kparams \| (?P<kp>.*)' > devpropfmt = '# Device Properties: .*' > - pinfofmt = '# platform-(?P<val>[a-z,A-Z,0-9]*): (?P<info>.*)' > + pinfofmt = '# platform-(?P<val>[a-z,A-Z,0-9,_]*): (?P<info>.*)' > tracertypefmt = '# tracer: (?P<t>.*)' > firmwarefmt = '# fwsuspend (?P<s>[0-9]*) fwresume (?P<r>[0-9]*)$' > procexecfmt = 'ps - (?P<ps>.*)$' > + procmultifmt = '@(?P<n>[0-9]*)\|(?P<ps>.*)$' > ftrace_line_fmt_fg = \ > '^ *(?P<time>[0-9\.]*) *\| *(?P<cpu>[0-9]*)\)'+\ > ' *(?P<proc>.*)-(?P<pid>[0-9]*) *\|'+\ > @@ -2893,6 +2987,9 @@ class TestProps: > '(?P<flags>\S*) *(?P<time>[0-9\.]*): *'+\ > '(?P<msg>.*)' > machinesuspend = 'machine_suspend\[.*' > + multiproclist = dict() > + multiproctime = 0.0 > + multiproccnt = 0 > def __init__(self): > self.stamp = '' > self.sysinfo = '' > @@ -3063,6 +3160,7 @@ class TestRun: > self.ttemp = dict() > > class ProcessMonitor: > + maxchars = 512 > def __init__(self): > self.proclist = dict() > self.running = False > @@ -3088,19 +3186,23 @@ class ProcessMonitor: > if ujiff > 0 or kjiff > 0: > running[pid] = ujiff + kjiff > process.wait() > - out = '' > + out = [''] > for pid in running: > jiffies = running[pid] > val = self.proclist[pid] > - if out: > - out += ',' > - out += '%s-%s %d' % (val['name'], pid, jiffies) > - return 'ps - '+out > + if len(out[-1]) > self.maxchars: > + out.append('') > + elif len(out[-1]) > 0: > + out[-1] += ',' > + out[-1] += '%s-%s %d' % (val['name'], pid, jiffies) > + if len(out) > 1: > + for line in out: > + sysvals.fsetVal('ps - @%d|%s' % (len(out), line), 'trace_marker') > + else: > + sysvals.fsetVal('ps - %s' % out[0], 'trace_marker') > def processMonitor(self, tid): > while self.running: > - out = self.procstat() > - if out: > - sysvals.fsetVal(out, 'trace_marker') > + self.procstat() > def start(self): > self.thread = Thread(target=self.processMonitor, args=(0,)) > self.running = True > @@ -3144,7 +3246,6 @@ def doesTraceLogHaveTraceEvents(): > > # Function: appendIncompleteTraceLog > # Description: > -# [deprecated for kernel 3.15 or newer] > # Adds callgraph data which lacks trace event data. This is only > # for timelines generated from 3.15 or older > # Arguments: > @@ -3246,6 +3347,61 @@ def appendIncompleteTraceLog(testruns): > dev['ftrace'] = cg > break > > +# Function: loadTraceLog > +# Description: > +# load the ftrace file into memory and fix up any ordering issues > +# Output: > +# TestProps instance and an array of lines in proper order > +def loadTraceLog(): > + tp, data, lines, trace = TestProps(), dict(), [], [] > + tf = sysvals.openlog(sysvals.ftracefile, 'r') > + for line in tf: > + # remove any latent carriage returns > + line = line.replace('\r\n', '') > + if tp.stampInfo(line, sysvals): > + continue > + # ignore all other commented lines > + if line[0] == '#': > + continue > + # ftrace line: parse only valid lines > + m = re.match(tp.ftrace_line_fmt, line) > + if(not m): > + continue > + dur = m.group('dur') if tp.cgformat else 'traceevent' > + info = (m.group('time'), m.group('proc'), m.group('pid'), > + m.group('msg'), dur) > + # group the data by timestamp > + t = float(info[0]) > + if t in data: > + data[t].append(info) > + else: > + data[t] = [info] > + # we only care about trace event ordering > + if (info[3].startswith('suspend_resume:') or \ > + info[3].startswith('tracing_mark_write:')) and t not in trace: > + trace.append(t) > + tf.close() > + for t in sorted(data): > + first, last, blk = [], [], data[t] > + if len(blk) > 1 and t in trace: > + # move certain lines to the start or end of a timestamp block > + for i in range(len(blk)): > + if 'SUSPEND START' in blk[i][3]: > + first.append(i) > + elif re.match('.* timekeeping_freeze.*begin', blk[i][3]): > + last.append(i) > + elif re.match('.* timekeeping_freeze.*end', blk[i][3]): > + first.append(i) > + elif 'RESUME COMPLETE' in blk[i][3]: > + last.append(i) > + if len(first) == 1 and len(last) == 0: > + blk.insert(0, blk.pop(first[0])) > + elif len(last) == 1 and len(first) == 0: > + blk.append(blk.pop(last[0])) > + for info in blk: > + lines.append(info) > + return (tp, lines) > + > # Function: parseTraceLog > # Description: > # Analyze an ftrace log output file generated from this app during > @@ -3271,32 +3427,12 @@ def parseTraceLog(live=False): > > # extract the callgraph and traceevent data > s2idle_enter = hwsus = False > - tp = TestProps() > testruns, testdata = [], [] > testrun, data, limbo = 0, 0, True > - tf = sysvals.openlog(sysvals.ftracefile, 'r') > phase = 'suspend_prepare' > - for line in tf: > - # remove any latent carriage returns > - line = line.replace('\r\n', '') > - if tp.stampInfo(line, sysvals): > - continue > - # ignore all other commented lines > - if line[0] == '#': > - continue > - # ftrace line: parse only valid lines > - m = re.match(tp.ftrace_line_fmt, line) > - if(not m): > - continue > + tp, tf = loadTraceLog() > + for m_time, m_proc, m_pid, m_msg, m_param3 in tf: > # gather the basic message data from the line > - m_time = m.group('time') > - m_proc = m.group('proc') > - m_pid = m.group('pid') > - m_msg = m.group('msg') > - if(tp.cgformat): > - m_param3 = m.group('dur') > - else: > - m_param3 = 'traceevent' > if(m_time and m_pid and m_msg): > t = FTraceLine(m_time, m_msg, m_param3) > pid = int(m_pid) > @@ -3322,14 +3458,29 @@ def parseTraceLog(live=False): > if t.type == 'tracing_mark_write': > m = re.match(tp.procexecfmt, t.name) > if(m): > - proclist = dict() > - for ps in m.group('ps').split(','): > + parts, msg = 1, m.group('ps') > + m = re.match(tp.procmultifmt, msg) > + if(m): > + parts, msg = int(m.group('n')), m.group('ps') > + if tp.multiproccnt == 0: > + tp.multiproctime = t.time > + tp.multiproclist = dict() > + proclist = tp.multiproclist > + tp.multiproccnt += 1 > + else: > + proclist = dict() > + tp.multiproccnt = 0 > + for ps in msg.split(','): > val = ps.split() > - if not val: > + if not val or len(val) != 2: > continue > name = val[0].replace('--', '-') > proclist[name] = int(val[1]) > - data.pstl[t.time] = proclist > + if parts == 1: > + data.pstl[t.time] = proclist > + elif parts == tp.multiproccnt: > + data.pstl[tp.multiproctime] = proclist > + tp.multiproccnt = 0 > continue > # find the end of resume > if(t.endMarker()): > @@ -3545,7 +3696,6 @@ def parseTraceLog(live=False): > testrun.ftemp[key].append(FTraceCallGraph(pid, sysvals)) > if(res == -1): > testrun.ftemp[key][-1].addLine(t) > - tf.close() > if len(testdata) < 1: > sysvals.vprint('WARNING: ftrace start marker is missing') > if data and not data.devicegroups: > @@ -3667,7 +3817,13 @@ def parseTraceLog(live=False): > if p not in data.dmesg: > if not terr: > ph = p if 'machine' in p else lp > - terr = '%s%s failed in %s phase' % (sysvals.suspendmode, tn, ph) > + if p == 'suspend_machine': > + sm = sysvals.suspendmode > + if sm in suspendmodename: > + sm = suspendmodename[sm] > + terr = 'test%s did not enter %s power mode' % (tn, sm) > + else: > + terr = '%s%s failed in %s phase' % (sysvals.suspendmode, tn, ph) > pprint('TEST%s FAILED: %s' % (tn, terr)) > error.append(terr) > if data.tSuspended == 0: > @@ -3708,9 +3864,7 @@ def parseTraceLog(live=False): > > # Function: loadKernelLog > # Description: > -# [deprecated for kernel 3.15.0 or newer] > # load the dmesg file into memory and fix up any ordering issues > -# The dmesg filename is taken from sysvals > # Output: > # An array of empty Data objects with only their dmesgtext attributes set > def loadKernelLog(): > @@ -3736,7 +3890,8 @@ def loadKernelLog(): > if(not m): > continue > msg = m.group("msg") > - if(re.match('PM: Syncing filesystems.*', msg)): > + if re.match('PM: Syncing filesystems.*', msg) or \ > + re.match('PM: suspend entry.*', msg): > if(data): > testruns.append(data) > data = Data(len(testruns)) > @@ -3747,11 +3902,17 @@ def loadKernelLog(): > if(m): > sysvals.stamp['kernel'] = m.group('k') > m = re.match('PM: Preparing system for (?P<m>.*) sleep', msg) > - if(m): > + if not m: > + m = re.match('PM: Preparing system for sleep \((?P<m>.*)\)', msg) > + if m: > sysvals.stamp['mode'] = sysvals.suspendmode = m.group('m') > data.dmesgtext.append(line) > lf.close() > > + if sysvals.suspendmode == 's2idle': > + sysvals.suspendmode = 'freeze' > + elif sysvals.suspendmode == 'deep': > + sysvals.suspendmode = 'mem' > if data: > testruns.append(data) > if len(testruns) < 1: > @@ -3762,12 +3923,9 @@ def loadKernelLog(): > for data in testruns: > last = '' > for line in data.dmesgtext: > - mc = re.match('.*(\[ *)(?P<t>[0-9\.]*)(\]) calling '+\ > - '(?P<f>.*)\+ @ .*, parent: .*', line) > - mr = re.match('.*(\[ *)(?P<t>[0-9\.]*)(\]) call '+\ > - '(?P<f>.*)\+ returned .* after (?P<dt>.*) usecs', last) > - if(mc and mr and (mc.group('t') == mr.group('t')) and > - (mc.group('f') == mr.group('f'))): > + ct, cf, n, p = data.initcall_debug_call(line) > + rt, rf, l = data.initcall_debug_return(last) > + if ct and rt and ct == rt and cf == rf: > i = data.dmesgtext.index(last) > j = data.dmesgtext.index(line) > data.dmesgtext[i] = line > @@ -3777,7 +3935,6 @@ def loadKernelLog(): > > # Function: parseKernelLog > # Description: > -# [deprecated for kernel 3.15.0 or newer] > # Analyse a dmesg log output file generated from this app during > # the execution phase. Create a set of device structures in memory > # for subsequent formatting in the html output file > @@ -3796,30 +3953,30 @@ def parseKernelLog(data): > > # dmesg phase match table > dm = { > - 'suspend_prepare': ['PM: Syncing filesystems.*'], > - 'suspend': ['PM: Entering [a-z]* sleep.*', 'Suspending console.*'], > - 'suspend_late': ['PM: suspend of devices complete after.*'], > - 'suspend_noirq': ['PM: late suspend of devices complete after.*'], > - 'suspend_machine': ['PM: noirq suspend of devices complete after.*'], > - 'resume_machine': ['ACPI: Low-level resume complete.*'], > - 'resume_noirq': ['ACPI: Waking up from system sleep state.*'], > - 'resume_early': ['PM: noirq resume of devices complete after.*'], > - 'resume': ['PM: early resume of devices complete after.*'], > - 'resume_complete': ['PM: resume of devices complete after.*'], > + 'suspend_prepare': ['PM: Syncing filesystems.*', 'PM: suspend entry.*'], > + 'suspend': ['PM: Entering [a-z]* sleep.*', 'Suspending console.*', > + 'PM: Suspending system .*'], > + 'suspend_late': ['PM: suspend of devices complete after.*', > + 'PM: freeze of devices complete after.*'], > + 'suspend_noirq': ['PM: late suspend of devices complete after.*', > + 'PM: late freeze of devices complete after.*'], > + 'suspend_machine': ['PM: suspend-to-idle', > + 'PM: noirq suspend of devices complete after.*', > + 'PM: noirq freeze of devices complete after.*'], > + 'resume_machine': ['PM: Timekeeping suspended for.*', > + 'ACPI: Low-level resume complete.*', > + 'ACPI: resume from mwait', > + 'Suspended for [0-9\.]* seconds'], > + 'resume_noirq': ['PM: resume from suspend-to-idle', > + 'ACPI: Waking up from system sleep state.*'], > + 'resume_early': ['PM: noirq resume of devices complete after.*', > + 'PM: noirq restore of devices complete after.*'], > + 'resume': ['PM: early resume of devices complete after.*', > + 'PM: early restore of devices complete after.*'], > + 'resume_complete': ['PM: resume of devices complete after.*', > + 'PM: restore of devices complete after.*'], > 'post_resume': ['.*Restarting tasks \.\.\..*'], > } > - if(sysvals.suspendmode == 'standby'): > - dm['resume_machine'] = ['PM: Restoring platform NVS memory'] > - elif(sysvals.suspendmode == 'disk'): > - dm['suspend_late'] = ['PM: freeze of devices complete after.*'] > - dm['suspend_noirq'] = ['PM: late freeze of devices complete after.*'] > - dm['suspend_machine'] = ['PM: noirq freeze of devices complete after.*'] > - dm['resume_machine'] = ['PM: Restoring platform NVS memory'] > - dm['resume_early'] = ['PM: noirq restore of devices complete after.*'] > - dm['resume'] = ['PM: early restore of devices complete after.*'] > - dm['resume_complete'] = ['PM: restore of devices complete after.*'] > - elif(sysvals.suspendmode == 'freeze'): > - dm['resume_machine'] = ['ACPI: resume from mwait'] > > # action table (expected events that occur and show up in dmesg) > at = { > @@ -3867,12 +4024,13 @@ def parseKernelLog(data): > for s in dm[p]: > if(re.match(s, msg)): > phasechange, phase = True, p > + dm[p] = [s] > break > > # hack for determining resume_machine end for freeze > if(not sysvals.usetraceevents and sysvals.suspendmode == 'freeze' \ > and phase == 'resume_machine' and \ > - re.match('calling (?P<f>.*)\+ @ .*, parent: .*', msg)): > + data.initcall_debug_call(line, True)): > data.setPhase(phase, ktime, False) > phase = 'resume_noirq' > data.setPhase(phase, ktime, True) > @@ -3945,26 +4103,18 @@ def parseKernelLog(data): > # -- device callbacks -- > if(phase in data.sortedPhases()): > # device init call > - if(re.match('calling (?P<f>.*)\+ @ .*, parent: .*', msg)): > - sm = re.match('calling (?P<f>.*)\+ @ '+\ > - '(?P<n>.*), parent: (?P<p>.*)', msg); > - f = sm.group('f') > - n = sm.group('n') > - p = sm.group('p') > - if(f and n and p): > - data.newAction(phase, f, int(n), p, ktime, -1, '') > - # device init return > - elif(re.match('call (?P<f>.*)\+ returned .* after '+\ > - '(?P<t>.*) usecs', msg)): > - sm = re.match('call (?P<f>.*)\+ returned .* after '+\ > - '(?P<t>.*) usecs(?P<a>.*)', msg); > - f = sm.group('f') > - t = sm.group('t') > - list = data.dmesg[phase]['list'] > - if(f in list): > - dev = list[f] > - dev['length'] = int(t) > - dev['end'] = ktime > + t, f, n, p = data.initcall_debug_call(line) > + if t and f and n and p: > + data.newAction(phase, f, int(n), p, ktime, -1, '') > + else: > + # device init return > + t, f, l = data.initcall_debug_return(line) > + if t and f and l: > + list = data.dmesg[phase]['list'] > + if(f in list): > + dev = list[f] > + dev['length'] = int(l) > + dev['end'] = ktime > > # if trace events are not available, these are better than nothing > if(not sysvals.usetraceevents): > @@ -4006,6 +4156,8 @@ def parseKernelLog(data): > # fill in any missing phases > phasedef = data.phasedef > terr, lp = '', 'suspend_prepare' > + if lp not in data.dmesg: > + doError('dmesg log format has changed, could not find start of suspend') > for p in sorted(phasedef, key=lambda k:phasedef[k]['order']): > if p not in data.dmesg: > if not terr: > @@ -5302,7 +5454,7 @@ def executeSuspend(quiet=False): > sv.dlog('read dmesg') > sv.initdmesg() > # start ftrace > - if(sv.usecallgraph or sv.usetraceevents): > + if sv.useftrace: > if not quiet: > pprint('START TRACING') > sv.dlog('start ftrace tracing') > @@ -5334,8 +5486,7 @@ def executeSuspend(quiet=False): > sv.dlog('enable RTC wake alarm') > sv.rtcWakeAlarmOn() > # start of suspend trace marker > - if(sv.usecallgraph or sv.usetraceevents): > - sv.fsetVal(datetime.now().strftime(sv.tmstart), 'trace_marker') > + sv.fsetVal(datetime.now().strftime(sv.tmstart), 'trace_marker') > # predelay delay > if(count == 1 and sv.predelay > 0): > sv.fsetVal('WAIT %d' % sv.predelay, 'trace_marker') > @@ -5384,11 +5535,17 @@ def executeSuspend(quiet=False): > sv.fsetVal('WAIT END', 'trace_marker') > # return from suspend > pprint('RESUME COMPLETE') > - if(sv.usecallgraph or sv.usetraceevents): > - sv.fsetVal(datetime.now().strftime(sv.tmend), 'trace_marker') > + sv.fsetVal(datetime.now().strftime(sv.tmend), 'trace_marker') > if sv.wifi and wifi: > tdata['wifi'] = sv.pollWifi(wifi) > sv.dlog('wifi check, %s' % tdata['wifi']) > + if sv.netfix: > + netfixout = sv.netfixon('wired') > + elif sv.netfix: > + netfixout = sv.netfixon() > + if sv.netfix and netfixout: > + tdata['netfix'] = netfixout > + sv.dlog('netfix, %s' % tdata['netfix']) > if(sv.suspendmode == 'mem' or sv.suspendmode == 'command'): > sv.dlog('read the ACPI FPDT') > tdata['fw'] = getFPDT(False) > @@ -5396,7 +5553,7 @@ def executeSuspend(quiet=False): > sv.dlog('run the cmdinfo list after') > cmdafter = sv.cmdinfo(False) > # stop ftrace > - if(sv.usecallgraph or sv.usetraceevents): > + if sv.useftrace: > if sv.useprocmon: > sv.dlog('stop the process monitor') > pm.stop() > @@ -5407,7 +5564,7 @@ def executeSuspend(quiet=False): > sysvals.dlog('EXECUTION TRACE END') > sv.getdmesg(testdata) > # grab a copy of the ftrace output > - if(sv.usecallgraph or sv.usetraceevents): > + if sv.useftrace: > if not quiet: > pprint('CAPTURING TRACE') > op = sv.writeDatafileHeader(sv.ftracefile, testdata) > @@ -5838,13 +5995,19 @@ def statusCheck(probecheck=False): > pprint(' please choose one with -m') > > # check if ftrace is available > - res = sysvals.colorText('NO') > - ftgood = sysvals.verifyFtrace() > - if(ftgood): > - res = 'YES' > - elif(sysvals.usecallgraph): > - status = 'ftrace is not properly supported' > - pprint(' is ftrace supported: %s' % res) > + if sysvals.useftrace: > + res = sysvals.colorText('NO') > + sysvals.useftrace = sysvals.verifyFtrace() > + efmt = '"{0}" uses ftrace, and it is not properly supported' > + if sysvals.useftrace: > + res = 'YES' > + elif sysvals.usecallgraph: > + status = efmt.format('-f') > + elif sysvals.usedevsrc: > + status = efmt.format('-dev') > + elif sysvals.useprocmon: > + status = efmt.format('-proc') > + pprint(' is ftrace supported: %s' % res) > > # check if kprobes are available > if sysvals.usekprobes: > @@ -5857,8 +6020,8 @@ def statusCheck(probecheck=False): > pprint(' are kprobes supported: %s' % res) > > # what data source are we using > - res = 'DMESG' > - if(ftgood): > + res = 'DMESG (very limited, ftrace is preferred)' > + if sysvals.useftrace: > sysvals.usetraceevents = True > for e in sysvals.traceevents: > if not os.path.exists(sysvals.epath+e): > @@ -5879,7 +6042,7 @@ def statusCheck(probecheck=False): > pprint(' optional commands this tool may use for info:') > no = sysvals.colorText('MISSING') > yes = sysvals.colorText('FOUND', 32) > - for c in ['turbostat', 'mcelog', 'lspci', 'lsusb']: > + for c in ['turbostat', 'mcelog', 'lspci', 'lsusb', 'netfix']: > if c == 'turbostat': > res = yes if sysvals.haveTurbostat() else no > else: > @@ -5971,7 +6134,7 @@ def processData(live=False, quiet=False): > if not sysvals.stamp: > pprint('ERROR: data does not include the expected stamp') > return (testruns, {'error': 'timeline generation failed'}) > - shown = ['bios', 'biosdate', 'cpu', 'host', 'kernel', 'man', 'memfr', > + shown = ['os', 'bios', 'biosdate', 'cpu', 'host', 'kernel', 'man', 'memfr', > 'memsz', 'mode', 'numcpu', 'plat', 'time', 'wifi'] > sysvals.vprint('System Info:') > for key in sorted(sysvals.stamp): > @@ -6052,6 +6215,8 @@ def runTest(n=0, quiet=False): > if sysvals.display: > ret = sysvals.displayControl('init') > sysvals.dlog('xset display init, ret = %d' % ret) > + sysvals.testVal(sysvals.pmdpath, 'basic', '1') > + sysvals.testVal(sysvals.s0ixpath, 'basic', 'Y') > sysvals.dlog('initialize ftrace') > sysvals.initFtrace(quiet) > > @@ -6145,9 +6310,12 @@ def data_from_html(file, outpath, issues, fulldetail=False): > elist[err[0]] += 1 > for i in elist: > ilist.append('%sx%d' % (i, elist[i]) if elist[i] > 1 else i) > - wifi = find_in_html(html, 'Wifi Resume: ', '</td>') > - if wifi: > - extra['wifi'] = wifi > + line = find_in_html(log, '# wifi ', '\n') > + if line: > + extra['wifi'] = line > + line = find_in_html(log, '# netfix ', '\n') > + if line: > + extra['netfix'] = line > low = find_in_html(html, 'freeze time: <b>', ' ms</b>') > for lowstr in ['waking', '+']: > if not low: > @@ -6243,7 +6411,7 @@ def genHtml(subdir, force=False): > sysvals.ftracefile = file > sysvals.setOutputFile() > if (sysvals.dmesgfile or sysvals.ftracefile) and sysvals.htmlfile and \ > - (force or not sysvals.usable(sysvals.htmlfile)): > + (force or not sysvals.usable(sysvals.htmlfile, True)): > pprint('FTRACE: %s' % sysvals.ftracefile) > if sysvals.dmesgfile: > pprint('DMESG : %s' % sysvals.dmesgfile) > @@ -6533,6 +6701,7 @@ def printHelp(): > ' -skiphtml Run the test and capture the trace logs, but skip the timeline (default: disabled)\n'\ > ' -result fn Export a results table to a text file for parsing.\n'\ > ' -wifi If a wifi connection is available, check that it reconnects after resume.\n'\ > + ' -netfix Use netfix to reset the network in the event it fails to resume.\n'\ > ' [testprep]\n'\ > ' -sync Sync the filesystems before starting the test\n'\ > ' -rs on/off Enable/disable runtime suspend for all devices, restore all after test\n'\ > @@ -6615,6 +6784,8 @@ if __name__ == '__main__': > elif(arg == '-v'): > pprint("Version %s" % sysvals.version) > sys.exit(0) > + elif(arg == '-debugtiming'): > + debugtiming = True > elif(arg == '-x2'): > sysvals.execcount = 2 > elif(arg == '-x2delay'): > @@ -6657,6 +6828,8 @@ if __name__ == '__main__': > sysvals.sync = True > elif(arg == '-wifi'): > sysvals.wifi = True > + elif(arg == '-netfix'): > + sysvals.netfix = True > elif(arg == '-gzip'): > sysvals.gzip = True > elif(arg == '-info'): > @@ -6819,7 +6992,7 @@ if __name__ == '__main__': > sysvals.outdir = val > sysvals.notestrun = True > if(os.path.isdir(val) == False): > - doError('%s is not accessible' % val) > + doError('%s is not accesible' % val) > elif(arg == '-filter'): > try: > val = next(args) > @@ -6942,12 +7115,11 @@ if __name__ == '__main__': > time.sleep(sysvals.multitest['delay']) > fmt = 'suspend-%y%m%d-%H%M%S' > sysvals.testdir = os.path.join(sysvals.outdir, datetime.now().strftime(fmt)) > - ret = runTest(i+1, True) > + ret = runTest(i+1, not sysvals.verbose) > failcnt = 0 if not ret else failcnt + 1 > if sysvals.maxfail > 0 and failcnt >= sysvals.maxfail: > pprint('Maximum fail count of %d reached, aborting multitest' % (sysvals.maxfail)) > break > - time.sleep(5) > sysvals.resetlog() > sysvals.multistat(False, i, finish) > if 'time' in sysvals.multitest and datetime.now() >= finish: > -- > 2.17.1 >
diff --git a/tools/power/pm-graph/README b/tools/power/pm-graph/README index da468bd510ca..e6020c0d59ec 100644 --- a/tools/power/pm-graph/README +++ b/tools/power/pm-graph/README @@ -6,7 +6,7 @@ |_| |___/ |_| pm-graph: suspend/resume/boot timing analysis tools - Version: 5.8 + Version: 5.9 Author: Todd Brandt <todd.e.brandt@intel.com> Home Page: https://01.org/pm-graph @@ -97,8 +97,8 @@ (kernel/pre-3.15/enable_trace_events_suspend_resume.patch) (kernel/pre-3.15/enable_trace_events_device_pm_callback.patch) - If you're using a kernel older than 3.15.0, the following - additional kernel parameters are required: + If you're using bootgraph, or sleepgraph with a kernel older than 3.15.0, + the following additional kernel parameters are required: (e.g. in file /etc/default/grub) GRUB_CMDLINE_LINUX_DEFAULT="... initcall_debug log_buf_len=32M ..." diff --git a/tools/power/pm-graph/bootgraph.py b/tools/power/pm-graph/bootgraph.py index 2823cd3122f7..f96f50e0c336 100755 --- a/tools/power/pm-graph/bootgraph.py +++ b/tools/power/pm-graph/bootgraph.py @@ -69,22 +69,24 @@ class SystemValues(aslib.SystemValues): bootloader = 'grub' blexec = [] def __init__(self): - self.hostname = platform.node() + self.kernel, self.hostname = 'unknown', platform.node() self.testtime = datetime.now().strftime('%Y-%m-%d_%H:%M:%S') if os.path.exists('/proc/version'): fp = open('/proc/version', 'r') - val = fp.read().strip() + self.kernel = self.kernelVersion(fp.read().strip()) fp.close() - self.kernel = self.kernelVersion(val) - else: - self.kernel = 'unknown' self.testdir = datetime.now().strftime('boot-%y%m%d-%H%M%S') def kernelVersion(self, msg): - return msg.split()[2] + m = re.match('^[Ll]inux *[Vv]ersion *(?P<v>\S*) .*', msg) + if m: + return m.group('v') + return 'unknown' def checkFtraceKernelVersion(self): - val = tuple(map(int, self.kernel.split('-')[0].split('.'))) - if val >= (4, 10, 0): - return True + m = re.match('^(?P<x>[0-9]*)\.(?P<y>[0-9]*)\.(?P<z>[0-9]*).*', self.kernel) + if m: + val = tuple(map(int, m.groups())) + if val >= (4, 10, 0): + return True return False def kernelParams(self): cmdline = 'initcall_debug log_buf_len=32M' diff --git a/tools/power/pm-graph/config/custom-timeline-functions.cfg b/tools/power/pm-graph/config/custom-timeline-functions.cfg index 962e5768681c..4f80ad7d7275 100644 --- a/tools/power/pm-graph/config/custom-timeline-functions.cfg +++ b/tools/power/pm-graph/config/custom-timeline-functions.cfg @@ -125,7 +125,7 @@ acpi_suspend_begin: suspend_console: acpi_pm_prepare: syscore_suspend: -arch_thaw_secondary_cpus_end: +arch_enable_nonboot_cpus_end: syscore_resume: acpi_pm_finish: resume_console: diff --git a/tools/power/pm-graph/sleepgraph.py b/tools/power/pm-graph/sleepgraph.py index ffd50953a024..33981adcdd68 100755 --- a/tools/power/pm-graph/sleepgraph.py +++ b/tools/power/pm-graph/sleepgraph.py @@ -66,8 +66,13 @@ from threading import Thread from subprocess import call, Popen, PIPE import base64 +debugtiming = False +mystarttime = time.time() def pprint(msg): - print(msg) + if debugtiming: + print('[%09.3f] %s' % (time.time()-mystarttime, msg)) + else: + print(msg) sys.stdout.flush() def ascii(text): @@ -81,13 +86,14 @@ def ascii(text): # store system values and test parameters class SystemValues: title = 'SleepGraph' - version = '5.8' + version = '5.9' ansi = False rs = 0 display = '' gzip = False sync = False wifi = False + netfix = False verbose = False testlog = True dmesglog = True @@ -108,6 +114,7 @@ class SystemValues: cpucount = 0 memtotal = 204800 memfree = 204800 + osversion = '' srgap = 0 cgexp = False testdir = '' @@ -116,6 +123,7 @@ class SystemValues: fpdtpath = '/sys/firmware/acpi/tables/FPDT' epath = '/sys/kernel/debug/tracing/events/power/' pmdpath = '/sys/power/pm_debug_messages' + s0ixpath = '/sys/module/intel_pmc_core/parameters/warn_on_s0ix_failures' acpipath='/sys/module/acpi/parameters/debug_level' traceevents = [ 'suspend_resume', @@ -156,6 +164,7 @@ class SystemValues: ftop = False usetraceevents = False usetracemarkers = True + useftrace = True usekprobes = True usedevsrc = False useprocmon = False @@ -279,10 +288,16 @@ class SystemValues: 'intel_fbdev_set_suspend': {}, } infocmds = [ + [0, 'sysinfo', 'uname', '-a'], + [0, 'cpuinfo', 'head', '-7', '/proc/cpuinfo'], [0, 'kparams', 'cat', '/proc/cmdline'], [0, 'mcelog', 'mcelog'], [0, 'pcidevices', 'lspci', '-tv'], - [0, 'usbdevices', 'lsusb', '-t'], + [0, 'usbdevices', 'lsusb', '-tv'], + [0, 'acpidevices', 'sh', '-c', 'ls -l /sys/bus/acpi/devices/*/physical_node'], + [0, 's0ix_require', 'cat', '/sys/kernel/debug/pmc_core/substate_requirements'], + [0, 's0ix_debug', 'cat', '/sys/kernel/debug/pmc_core/slp_s0_debug_status'], + [1, 's0ix_residency', 'cat', '/sys/kernel/debug/pmc_core/slp_s0_residency_usec'], [1, 'interrupts', 'cat', '/proc/interrupts'], [1, 'wakeups', 'cat', '/sys/kernel/debug/wakeup_sources'], [2, 'gpecounts', 'sh', '-c', 'grep -v invalid /sys/firmware/acpi/interrupts/*'], @@ -358,8 +373,19 @@ class SystemValues: 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 usable(self, file, ishtml=False): + if not os.path.exists(file) or os.path.getsize(file) < 1: + return False + if ishtml: + try: + fp = open(file, 'r') + res = fp.read(1000) + fp.close() + except: + return False + if '<html>' not in res: + return False + return True def getExec(self, cmd): try: fp = Popen(['which', cmd], stdout=PIPE, stderr=PIPE).stdout @@ -413,12 +439,16 @@ class SystemValues: r = info['bios-release-date'] if 'bios-release-date' in info else '' self.sysstamp = '# sysinfo | man:%s | plat:%s | cpu:%s | bios:%s | biosdate:%s | numcpu:%d | memsz:%d | memfr:%d' % \ (m, p, c, b, r, self.cpucount, self.memtotal, self.memfree) + if self.osversion: + self.sysstamp += ' | os:%s' % self.osversion def printSystemInfo(self, fatal=False): self.rootCheck(True) out = dmidecode(self.mempath, fatal) if len(out) < 1: return fmt = '%-24s: %s' + if self.osversion: + print(fmt % ('os-version', self.osversion)) for name in sorted(out): print(fmt % (name, out[name])) print(fmt % ('cpucount', ('%d' % self.cpucount))) @@ -426,20 +456,25 @@ class SystemValues: 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() + if os.path.exists('/proc/cpuinfo'): + with open('/proc/cpuinfo', 'r') as fp: + for line in fp: + if re.match('^processor[ \t]*:[ \t]*[0-9]*', line): + self.cpucount += 1 + if os.path.exists('/proc/meminfo'): + with open('/proc/meminfo', 'r') as fp: + for line in fp: + m = re.match('^MemTotal:[ \t]*(?P<sz>[0-9]*) *kB', line) + if m: + self.memtotal = int(m.group('sz')) + m = re.match('^MemFree:[ \t]*(?P<sz>[0-9]*) *kB', line) + if m: + self.memfree = int(m.group('sz')) + if os.path.exists('/etc/os-release'): + with open('/etc/os-release', 'r') as fp: + for line in fp: + if line.startswith('PRETTY_NAME='): + self.osversion = line[12:].strip().replace('"', '') def initTestOutput(self, name): self.prefix = self.hostname v = open('/proc/version', 'r').read().strip() @@ -698,6 +733,8 @@ class SystemValues: return False return True def fsetVal(self, val, path): + if not self.useftrace: + return False return self.setVal(val, self.tpath+path) def getVal(self, file): res = '' @@ -711,9 +748,11 @@ class SystemValues: pass return res def fgetVal(self, path): + if not self.useftrace: + return '' return self.getVal(self.tpath+path) def cleanupFtrace(self): - if(self.usecallgraph or self.usetraceevents or self.usedevsrc): + if self.useftrace: self.fsetVal('0', 'events/kprobes/enable') self.fsetVal('', 'kprobe_events') self.fsetVal('1024', 'buffer_size_kb') @@ -734,13 +773,14 @@ class SystemValues: return True return False def initFtrace(self, quiet=False): + if not self.useftrace: + return if not quiet: sysvals.printSystemInfo(False) pprint('INITIALIZING FTRACE...') # turn trace off self.fsetVal('0', 'tracing_on') self.cleanupFtrace() - self.testVal(self.pmdpath, 'basic', '1') # set the trace clock to global self.fsetVal('global', 'trace_clock') self.fsetVal('nop', 'current_tracer') @@ -766,6 +806,10 @@ class SystemValues: # set trace type self.fsetVal('function_graph', 'current_tracer') self.fsetVal('', 'set_ftrace_filter') + # temporary hack to fix https://bugzilla.kernel.org/show_bug.cgi?id=212761 + fp = open(self.tpath+'set_ftrace_notrace', 'w') + fp.write('native_queued_spin_lock_slowpath\ndev_driver_string') + fp.close() # set trace format options self.fsetVal('print-parent', 'trace_options') self.fsetVal('funcgraph-abstime', 'trace_options') @@ -846,6 +890,8 @@ class SystemValues: fp.write('# turbostat %s\n' % test['turbo']) if 'wifi' in test: fp.write('# wifi %s\n' % test['wifi']) + if 'netfix' in test: + fp.write('# netfix %s\n' % test['netfix']) if test['error'] or len(testdata) > 1: fp.write('# enter_sleep_error %s\n' % test['error']) return fp @@ -865,6 +911,8 @@ class SystemValues: fp.write('error%s: %s\n' % (n, testdata['error'])) else: fp.write('result%s: pass\n' % n) + if 'mode' in testdata: + fp.write('mode%s: %s\n' % (n, testdata['mode'])) for v in ['suspend', 'resume', 'boot', 'lastinit']: if v in testdata: fp.write('%s%s: %.3f\n' % (v, n, testdata[v])) @@ -901,6 +949,8 @@ class SystemValues: fp.write(text) fp.close() def dlog(self, text): + if not self.dmesgfile: + return self.putlog(self.dmesgfile, '# %s\n' % text) def flog(self, text): self.putlog(self.ftracefile, text) @@ -954,34 +1004,31 @@ class SystemValues: 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 = False + if os.path.exists(dirname+'/power/async'): + fp = open(dirname+'/power/async') + if 'enabled' in fp.read(): props[dev].isasync = True + fp.close() fields = os.listdir(dirname) - 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) + for file in ['product', 'name', 'model', 'description', 'id', 'idVendor']: + if file not in fields: + continue + try: + with open(os.path.join(dirname, file), 'rb') as fp: + props[dev].altname = ascii(fp.read()) + except: + continue + if file == 'idVendor': + idv, idp = props[dev].altname.strip(), '' + try: + with open(os.path.join(dirname, 'idProduct'), 'rb') as fp: + idp = ascii(fp.read()).strip() + except: + props[dev].altname = '' + break + props[dev].altname = '%s:%s' % (idv, idp) + break if props[dev].altname: out = props[dev].altname.strip().replace('\n', ' ')\ .replace(',', ' ').replace(';', ' ') @@ -1047,7 +1094,7 @@ class SystemValues: 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 '' + dinfo = ('\t%s\n' % before['@']) if '@' in before and len(before) > 1 else '' prefix = self.commonPrefix(list(before.keys())) for key in sorted(before): if key in after and before[key] != after[key]: @@ -1128,6 +1175,22 @@ class SystemValues: val = valline[idx] out.append('%s=%s' % (key, val)) return '|'.join(out) + def netfixon(self, net='both'): + cmd = self.getExec('netfix') + if not cmd: + return '' + fp = Popen([cmd, '-s', net, 'on'], stdout=PIPE, stderr=PIPE).stdout + out = ascii(fp.read()).strip() + fp.close() + return out + def wifiRepair(self): + out = self.netfixon('wifi') + if not out or 'error' in out.lower(): + return '' + m = re.match('WIFI \S* ONLINE (?P<action>\S*)', out) + if not m: + return 'dead' + return m.group('action') def wifiDetails(self, dev): try: info = open('/sys/class/net/%s/device/uevent' % dev, 'r').read().strip() @@ -1144,12 +1207,12 @@ class SystemValues: except: return '' for line in reversed(w.split('\n')): - m = re.match(' *(?P<dev>.*): (?P<stat>[0-9a-f]*) .*', w.split('\n')[-1]) + m = re.match(' *(?P<dev>.*): (?P<stat>[0-9a-f]*) .*', line) if not m or (dev and dev != m.group('dev')): continue return m.group('dev') return '' - def pollWifi(self, dev, timeout=60): + def pollWifi(self, dev, timeout=10): start = time.time() while (time.time() - start) < timeout: w = self.checkWifi(dev) @@ -1157,6 +1220,11 @@ class SystemValues: return '%s reconnected %.2f' % \ (self.wifiDetails(dev), max(0, time.time() - start)) time.sleep(0.01) + if self.netfix: + res = self.wifiRepair() + if res: + timeout = max(0, time.time() - start) + return '%s %s %d' % (self.wifiDetails(dev), res, timeout) return '%s timeout %d' % (self.wifiDetails(dev), timeout) def errorSummary(self, errinfo, msg): found = False @@ -1283,10 +1351,10 @@ 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)' + 'standby': 'standby (S1)', + 'freeze': 'freeze (S2idle)', + 'mem': 'suspend (S3)', + 'disk': 'hibernate (S4)' } # Class: DevProps @@ -1376,6 +1444,7 @@ class Data: 'INVALID' : r'(?i).*\bINVALID\b.*', 'CRASH' : r'(?i).*\bCRASHED\b.*', 'TIMEOUT' : r'(?i).*\bTIMEOUT\b.*', + 'ABORT' : r'(?i).*\bABORT\b.*', 'IRQ' : r'.*\bgenirq: .*', 'TASKFAIL': r'.*Freezing of tasks *.*', 'ACPI' : r'.*\bACPI *(?P<b>[A-Za-z]*) *Error[: ].*', @@ -1724,9 +1793,9 @@ class Data: 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)) + tTry = '%.0f' % (round(self.dmesg[lp]['waking'][1] * 1000)) else: - tTry = '-%.3f' % (self.dmesg[lp]['waking'][1] * 1000) + tTry = '%.3f' % (self.dmesg[lp]['waking'][1] * 1000) text = '%.0f (%s ms waking %d times)' % (tL * 1000, tTry, tCnt) else: text = '%.0f' % (tL * 1000) @@ -2107,6 +2176,30 @@ class Data: # set resume complete to end at end marker if 'resume_complete' in dm: dm['resume_complete']['end'] = time + def initcall_debug_call(self, line, quick=False): + m = re.match('.*(\[ *)(?P<t>[0-9\.]*)(\]) .* (?P<f>.*)\: '+\ + 'PM: *calling .* @ (?P<n>.*), parent: (?P<p>.*)', line) + if not m: + m = re.match('.*(\[ *)(?P<t>[0-9\.]*)(\]) .* (?P<f>.*)\: '+\ + 'calling .* @ (?P<n>.*), parent: (?P<p>.*)', line) + if not m: + m = re.match('.*(\[ *)(?P<t>[0-9\.]*)(\]) calling '+\ + '(?P<f>.*)\+ @ (?P<n>.*), parent: (?P<p>.*)', line) + if m: + return True if quick else m.group('t', 'f', 'n', 'p') + return False if quick else ('', '', '', '') + def initcall_debug_return(self, line, quick=False): + m = re.match('.*(\[ *)(?P<t>[0-9\.]*)(\]) .* (?P<f>.*)\: PM: '+\ + '.* returned (?P<r>[0-9]*) after (?P<dt>[0-9]*) usecs', line) + if not m: + m = re.match('.*(\[ *)(?P<t>[0-9\.]*)(\]) .* (?P<f>.*)\: '+\ + '.* returned (?P<r>[0-9]*) after (?P<dt>[0-9]*) usecs', line) + if not m: + m = re.match('.*(\[ *)(?P<t>[0-9\.]*)(\]) call '+\ + '(?P<f>.*)\+ returned .* after (?P<dt>.*) usecs', line) + if m: + return True if quick else m.group('t', 'f', 'dt') + return False if quick else ('', '', '') def debugPrint(self): for p in self.sortedPhases(): list = self.dmesg[p]['list'] @@ -2880,10 +2973,11 @@ class TestProps: cmdlinefmt = '^# command \| (?P<cmd>.*)' kparamsfmt = '^# kparams \| (?P<kp>.*)' devpropfmt = '# Device Properties: .*' - pinfofmt = '# platform-(?P<val>[a-z,A-Z,0-9]*): (?P<info>.*)' + pinfofmt = '# platform-(?P<val>[a-z,A-Z,0-9,_]*): (?P<info>.*)' tracertypefmt = '# tracer: (?P<t>.*)' firmwarefmt = '# fwsuspend (?P<s>[0-9]*) fwresume (?P<r>[0-9]*)$' procexecfmt = 'ps - (?P<ps>.*)$' + procmultifmt = '@(?P<n>[0-9]*)\|(?P<ps>.*)$' ftrace_line_fmt_fg = \ '^ *(?P<time>[0-9\.]*) *\| *(?P<cpu>[0-9]*)\)'+\ ' *(?P<proc>.*)-(?P<pid>[0-9]*) *\|'+\ @@ -2893,6 +2987,9 @@ class TestProps: '(?P<flags>\S*) *(?P<time>[0-9\.]*): *'+\ '(?P<msg>.*)' machinesuspend = 'machine_suspend\[.*' + multiproclist = dict() + multiproctime = 0.0 + multiproccnt = 0 def __init__(self): self.stamp = '' self.sysinfo = '' @@ -3063,6 +3160,7 @@ class TestRun: self.ttemp = dict() class ProcessMonitor: + maxchars = 512 def __init__(self): self.proclist = dict() self.running = False @@ -3088,19 +3186,23 @@ class ProcessMonitor: if ujiff > 0 or kjiff > 0: running[pid] = ujiff + kjiff process.wait() - out = '' + out = [''] for pid in running: jiffies = running[pid] val = self.proclist[pid] - if out: - out += ',' - out += '%s-%s %d' % (val['name'], pid, jiffies) - return 'ps - '+out + if len(out[-1]) > self.maxchars: + out.append('') + elif len(out[-1]) > 0: + out[-1] += ',' + out[-1] += '%s-%s %d' % (val['name'], pid, jiffies) + if len(out) > 1: + for line in out: + sysvals.fsetVal('ps - @%d|%s' % (len(out), line), 'trace_marker') + else: + sysvals.fsetVal('ps - %s' % out[0], 'trace_marker') def processMonitor(self, tid): while self.running: - out = self.procstat() - if out: - sysvals.fsetVal(out, 'trace_marker') + self.procstat() def start(self): self.thread = Thread(target=self.processMonitor, args=(0,)) self.running = True @@ -3144,7 +3246,6 @@ def doesTraceLogHaveTraceEvents(): # Function: appendIncompleteTraceLog # Description: -# [deprecated for kernel 3.15 or newer] # Adds callgraph data which lacks trace event data. This is only # for timelines generated from 3.15 or older # Arguments: @@ -3246,6 +3347,61 @@ def appendIncompleteTraceLog(testruns): dev['ftrace'] = cg break +# Function: loadTraceLog +# Description: +# load the ftrace file into memory and fix up any ordering issues +# Output: +# TestProps instance and an array of lines in proper order +def loadTraceLog(): + tp, data, lines, trace = TestProps(), dict(), [], [] + tf = sysvals.openlog(sysvals.ftracefile, 'r') + for line in tf: + # remove any latent carriage returns + line = line.replace('\r\n', '') + if tp.stampInfo(line, sysvals): + continue + # ignore all other commented lines + if line[0] == '#': + continue + # ftrace line: parse only valid lines + m = re.match(tp.ftrace_line_fmt, line) + if(not m): + continue + dur = m.group('dur') if tp.cgformat else 'traceevent' + info = (m.group('time'), m.group('proc'), m.group('pid'), + m.group('msg'), dur) + # group the data by timestamp + t = float(info[0]) + if t in data: + data[t].append(info) + else: + data[t] = [info] + # we only care about trace event ordering + if (info[3].startswith('suspend_resume:') or \ + info[3].startswith('tracing_mark_write:')) and t not in trace: + trace.append(t) + tf.close() + for t in sorted(data): + first, last, blk = [], [], data[t] + if len(blk) > 1 and t in trace: + # move certain lines to the start or end of a timestamp block + for i in range(len(blk)): + if 'SUSPEND START' in blk[i][3]: + first.append(i) + elif re.match('.* timekeeping_freeze.*begin', blk[i][3]): + last.append(i) + elif re.match('.* timekeeping_freeze.*end', blk[i][3]): + first.append(i) + elif 'RESUME COMPLETE' in blk[i][3]: + last.append(i) + if len(first) == 1 and len(last) == 0: + blk.insert(0, blk.pop(first[0])) + elif len(last) == 1 and len(first) == 0: + blk.append(blk.pop(last[0])) + for info in blk: + lines.append(info) + return (tp, lines) + # Function: parseTraceLog # Description: # Analyze an ftrace log output file generated from this app during @@ -3271,32 +3427,12 @@ def parseTraceLog(live=False): # extract the callgraph and traceevent data s2idle_enter = hwsus = False - tp = TestProps() testruns, testdata = [], [] testrun, data, limbo = 0, 0, True - tf = sysvals.openlog(sysvals.ftracefile, 'r') phase = 'suspend_prepare' - for line in tf: - # remove any latent carriage returns - line = line.replace('\r\n', '') - if tp.stampInfo(line, sysvals): - continue - # ignore all other commented lines - if line[0] == '#': - continue - # ftrace line: parse only valid lines - m = re.match(tp.ftrace_line_fmt, line) - if(not m): - continue + tp, tf = loadTraceLog() + for m_time, m_proc, m_pid, m_msg, m_param3 in tf: # gather the basic message data from the line - m_time = m.group('time') - m_proc = m.group('proc') - m_pid = m.group('pid') - m_msg = m.group('msg') - if(tp.cgformat): - m_param3 = m.group('dur') - else: - m_param3 = 'traceevent' if(m_time and m_pid and m_msg): t = FTraceLine(m_time, m_msg, m_param3) pid = int(m_pid) @@ -3322,14 +3458,29 @@ def parseTraceLog(live=False): if t.type == 'tracing_mark_write': m = re.match(tp.procexecfmt, t.name) if(m): - proclist = dict() - for ps in m.group('ps').split(','): + parts, msg = 1, m.group('ps') + m = re.match(tp.procmultifmt, msg) + if(m): + parts, msg = int(m.group('n')), m.group('ps') + if tp.multiproccnt == 0: + tp.multiproctime = t.time + tp.multiproclist = dict() + proclist = tp.multiproclist + tp.multiproccnt += 1 + else: + proclist = dict() + tp.multiproccnt = 0 + for ps in msg.split(','): val = ps.split() - if not val: + if not val or len(val) != 2: continue name = val[0].replace('--', '-') proclist[name] = int(val[1]) - data.pstl[t.time] = proclist + if parts == 1: + data.pstl[t.time] = proclist + elif parts == tp.multiproccnt: + data.pstl[tp.multiproctime] = proclist + tp.multiproccnt = 0 continue # find the end of resume if(t.endMarker()): @@ -3545,7 +3696,6 @@ def parseTraceLog(live=False): testrun.ftemp[key].append(FTraceCallGraph(pid, sysvals)) if(res == -1): testrun.ftemp[key][-1].addLine(t) - tf.close() if len(testdata) < 1: sysvals.vprint('WARNING: ftrace start marker is missing') if data and not data.devicegroups: @@ -3667,7 +3817,13 @@ def parseTraceLog(live=False): if p not in data.dmesg: if not terr: ph = p if 'machine' in p else lp - terr = '%s%s failed in %s phase' % (sysvals.suspendmode, tn, ph) + if p == 'suspend_machine': + sm = sysvals.suspendmode + if sm in suspendmodename: + sm = suspendmodename[sm] + terr = 'test%s did not enter %s power mode' % (tn, sm) + else: + terr = '%s%s failed in %s phase' % (sysvals.suspendmode, tn, ph) pprint('TEST%s FAILED: %s' % (tn, terr)) error.append(terr) if data.tSuspended == 0: @@ -3708,9 +3864,7 @@ def parseTraceLog(live=False): # Function: loadKernelLog # Description: -# [deprecated for kernel 3.15.0 or newer] # load the dmesg file into memory and fix up any ordering issues -# The dmesg filename is taken from sysvals # Output: # An array of empty Data objects with only their dmesgtext attributes set def loadKernelLog(): @@ -3736,7 +3890,8 @@ def loadKernelLog(): if(not m): continue msg = m.group("msg") - if(re.match('PM: Syncing filesystems.*', msg)): + if re.match('PM: Syncing filesystems.*', msg) or \ + re.match('PM: suspend entry.*', msg): if(data): testruns.append(data) data = Data(len(testruns)) @@ -3747,11 +3902,17 @@ def loadKernelLog(): if(m): sysvals.stamp['kernel'] = m.group('k') m = re.match('PM: Preparing system for (?P<m>.*) sleep', msg) - if(m): + if not m: + m = re.match('PM: Preparing system for sleep \((?P<m>.*)\)', msg) + if m: sysvals.stamp['mode'] = sysvals.suspendmode = m.group('m') data.dmesgtext.append(line) lf.close() + if sysvals.suspendmode == 's2idle': + sysvals.suspendmode = 'freeze' + elif sysvals.suspendmode == 'deep': + sysvals.suspendmode = 'mem' if data: testruns.append(data) if len(testruns) < 1: @@ -3762,12 +3923,9 @@ def loadKernelLog(): for data in testruns: last = '' for line in data.dmesgtext: - mc = re.match('.*(\[ *)(?P<t>[0-9\.]*)(\]) calling '+\ - '(?P<f>.*)\+ @ .*, parent: .*', line) - mr = re.match('.*(\[ *)(?P<t>[0-9\.]*)(\]) call '+\ - '(?P<f>.*)\+ returned .* after (?P<dt>.*) usecs', last) - if(mc and mr and (mc.group('t') == mr.group('t')) and - (mc.group('f') == mr.group('f'))): + ct, cf, n, p = data.initcall_debug_call(line) + rt, rf, l = data.initcall_debug_return(last) + if ct and rt and ct == rt and cf == rf: i = data.dmesgtext.index(last) j = data.dmesgtext.index(line) data.dmesgtext[i] = line @@ -3777,7 +3935,6 @@ def loadKernelLog(): # Function: parseKernelLog # Description: -# [deprecated for kernel 3.15.0 or newer] # Analyse a dmesg log output file generated from this app during # the execution phase. Create a set of device structures in memory # for subsequent formatting in the html output file @@ -3796,30 +3953,30 @@ def parseKernelLog(data): # dmesg phase match table dm = { - 'suspend_prepare': ['PM: Syncing filesystems.*'], - 'suspend': ['PM: Entering [a-z]* sleep.*', 'Suspending console.*'], - 'suspend_late': ['PM: suspend of devices complete after.*'], - 'suspend_noirq': ['PM: late suspend of devices complete after.*'], - 'suspend_machine': ['PM: noirq suspend of devices complete after.*'], - 'resume_machine': ['ACPI: Low-level resume complete.*'], - 'resume_noirq': ['ACPI: Waking up from system sleep state.*'], - 'resume_early': ['PM: noirq resume of devices complete after.*'], - 'resume': ['PM: early resume of devices complete after.*'], - 'resume_complete': ['PM: resume of devices complete after.*'], + 'suspend_prepare': ['PM: Syncing filesystems.*', 'PM: suspend entry.*'], + 'suspend': ['PM: Entering [a-z]* sleep.*', 'Suspending console.*', + 'PM: Suspending system .*'], + 'suspend_late': ['PM: suspend of devices complete after.*', + 'PM: freeze of devices complete after.*'], + 'suspend_noirq': ['PM: late suspend of devices complete after.*', + 'PM: late freeze of devices complete after.*'], + 'suspend_machine': ['PM: suspend-to-idle', + 'PM: noirq suspend of devices complete after.*', + 'PM: noirq freeze of devices complete after.*'], + 'resume_machine': ['PM: Timekeeping suspended for.*', + 'ACPI: Low-level resume complete.*', + 'ACPI: resume from mwait', + 'Suspended for [0-9\.]* seconds'], + 'resume_noirq': ['PM: resume from suspend-to-idle', + 'ACPI: Waking up from system sleep state.*'], + 'resume_early': ['PM: noirq resume of devices complete after.*', + 'PM: noirq restore of devices complete after.*'], + 'resume': ['PM: early resume of devices complete after.*', + 'PM: early restore of devices complete after.*'], + 'resume_complete': ['PM: resume of devices complete after.*', + 'PM: restore of devices complete after.*'], 'post_resume': ['.*Restarting tasks \.\.\..*'], } - if(sysvals.suspendmode == 'standby'): - dm['resume_machine'] = ['PM: Restoring platform NVS memory'] - elif(sysvals.suspendmode == 'disk'): - dm['suspend_late'] = ['PM: freeze of devices complete after.*'] - dm['suspend_noirq'] = ['PM: late freeze of devices complete after.*'] - dm['suspend_machine'] = ['PM: noirq freeze of devices complete after.*'] - dm['resume_machine'] = ['PM: Restoring platform NVS memory'] - dm['resume_early'] = ['PM: noirq restore of devices complete after.*'] - dm['resume'] = ['PM: early restore of devices complete after.*'] - dm['resume_complete'] = ['PM: restore of devices complete after.*'] - elif(sysvals.suspendmode == 'freeze'): - dm['resume_machine'] = ['ACPI: resume from mwait'] # action table (expected events that occur and show up in dmesg) at = { @@ -3867,12 +4024,13 @@ def parseKernelLog(data): for s in dm[p]: if(re.match(s, msg)): phasechange, phase = True, p + dm[p] = [s] break # hack for determining resume_machine end for freeze if(not sysvals.usetraceevents and sysvals.suspendmode == 'freeze' \ and phase == 'resume_machine' and \ - re.match('calling (?P<f>.*)\+ @ .*, parent: .*', msg)): + data.initcall_debug_call(line, True)): data.setPhase(phase, ktime, False) phase = 'resume_noirq' data.setPhase(phase, ktime, True) @@ -3945,26 +4103,18 @@ def parseKernelLog(data): # -- device callbacks -- if(phase in data.sortedPhases()): # device init call - if(re.match('calling (?P<f>.*)\+ @ .*, parent: .*', msg)): - sm = re.match('calling (?P<f>.*)\+ @ '+\ - '(?P<n>.*), parent: (?P<p>.*)', msg); - f = sm.group('f') - n = sm.group('n') - p = sm.group('p') - if(f and n and p): - data.newAction(phase, f, int(n), p, ktime, -1, '') - # device init return - elif(re.match('call (?P<f>.*)\+ returned .* after '+\ - '(?P<t>.*) usecs', msg)): - sm = re.match('call (?P<f>.*)\+ returned .* after '+\ - '(?P<t>.*) usecs(?P<a>.*)', msg); - f = sm.group('f') - t = sm.group('t') - list = data.dmesg[phase]['list'] - if(f in list): - dev = list[f] - dev['length'] = int(t) - dev['end'] = ktime + t, f, n, p = data.initcall_debug_call(line) + if t and f and n and p: + data.newAction(phase, f, int(n), p, ktime, -1, '') + else: + # device init return + t, f, l = data.initcall_debug_return(line) + if t and f and l: + list = data.dmesg[phase]['list'] + if(f in list): + dev = list[f] + dev['length'] = int(l) + dev['end'] = ktime # if trace events are not available, these are better than nothing if(not sysvals.usetraceevents): @@ -4006,6 +4156,8 @@ def parseKernelLog(data): # fill in any missing phases phasedef = data.phasedef terr, lp = '', 'suspend_prepare' + if lp not in data.dmesg: + doError('dmesg log format has changed, could not find start of suspend') for p in sorted(phasedef, key=lambda k:phasedef[k]['order']): if p not in data.dmesg: if not terr: @@ -5302,7 +5454,7 @@ def executeSuspend(quiet=False): sv.dlog('read dmesg') sv.initdmesg() # start ftrace - if(sv.usecallgraph or sv.usetraceevents): + if sv.useftrace: if not quiet: pprint('START TRACING') sv.dlog('start ftrace tracing') @@ -5334,8 +5486,7 @@ def executeSuspend(quiet=False): sv.dlog('enable RTC wake alarm') sv.rtcWakeAlarmOn() # start of suspend trace marker - if(sv.usecallgraph or sv.usetraceevents): - sv.fsetVal(datetime.now().strftime(sv.tmstart), 'trace_marker') + sv.fsetVal(datetime.now().strftime(sv.tmstart), 'trace_marker') # predelay delay if(count == 1 and sv.predelay > 0): sv.fsetVal('WAIT %d' % sv.predelay, 'trace_marker') @@ -5384,11 +5535,17 @@ def executeSuspend(quiet=False): sv.fsetVal('WAIT END', 'trace_marker') # return from suspend pprint('RESUME COMPLETE') - if(sv.usecallgraph or sv.usetraceevents): - sv.fsetVal(datetime.now().strftime(sv.tmend), 'trace_marker') + sv.fsetVal(datetime.now().strftime(sv.tmend), 'trace_marker') if sv.wifi and wifi: tdata['wifi'] = sv.pollWifi(wifi) sv.dlog('wifi check, %s' % tdata['wifi']) + if sv.netfix: + netfixout = sv.netfixon('wired') + elif sv.netfix: + netfixout = sv.netfixon() + if sv.netfix and netfixout: + tdata['netfix'] = netfixout + sv.dlog('netfix, %s' % tdata['netfix']) if(sv.suspendmode == 'mem' or sv.suspendmode == 'command'): sv.dlog('read the ACPI FPDT') tdata['fw'] = getFPDT(False) @@ -5396,7 +5553,7 @@ def executeSuspend(quiet=False): sv.dlog('run the cmdinfo list after') cmdafter = sv.cmdinfo(False) # stop ftrace - if(sv.usecallgraph or sv.usetraceevents): + if sv.useftrace: if sv.useprocmon: sv.dlog('stop the process monitor') pm.stop() @@ -5407,7 +5564,7 @@ def executeSuspend(quiet=False): sysvals.dlog('EXECUTION TRACE END') sv.getdmesg(testdata) # grab a copy of the ftrace output - if(sv.usecallgraph or sv.usetraceevents): + if sv.useftrace: if not quiet: pprint('CAPTURING TRACE') op = sv.writeDatafileHeader(sv.ftracefile, testdata) @@ -5838,13 +5995,19 @@ def statusCheck(probecheck=False): pprint(' please choose one with -m') # check if ftrace is available - res = sysvals.colorText('NO') - ftgood = sysvals.verifyFtrace() - if(ftgood): - res = 'YES' - elif(sysvals.usecallgraph): - status = 'ftrace is not properly supported' - pprint(' is ftrace supported: %s' % res) + if sysvals.useftrace: + res = sysvals.colorText('NO') + sysvals.useftrace = sysvals.verifyFtrace() + efmt = '"{0}" uses ftrace, and it is not properly supported' + if sysvals.useftrace: + res = 'YES' + elif sysvals.usecallgraph: + status = efmt.format('-f') + elif sysvals.usedevsrc: + status = efmt.format('-dev') + elif sysvals.useprocmon: + status = efmt.format('-proc') + pprint(' is ftrace supported: %s' % res) # check if kprobes are available if sysvals.usekprobes: @@ -5857,8 +6020,8 @@ def statusCheck(probecheck=False): pprint(' are kprobes supported: %s' % res) # what data source are we using - res = 'DMESG' - if(ftgood): + res = 'DMESG (very limited, ftrace is preferred)' + if sysvals.useftrace: sysvals.usetraceevents = True for e in sysvals.traceevents: if not os.path.exists(sysvals.epath+e): @@ -5879,7 +6042,7 @@ def statusCheck(probecheck=False): pprint(' optional commands this tool may use for info:') no = sysvals.colorText('MISSING') yes = sysvals.colorText('FOUND', 32) - for c in ['turbostat', 'mcelog', 'lspci', 'lsusb']: + for c in ['turbostat', 'mcelog', 'lspci', 'lsusb', 'netfix']: if c == 'turbostat': res = yes if sysvals.haveTurbostat() else no else: @@ -5971,7 +6134,7 @@ def processData(live=False, quiet=False): if not sysvals.stamp: pprint('ERROR: data does not include the expected stamp') return (testruns, {'error': 'timeline generation failed'}) - shown = ['bios', 'biosdate', 'cpu', 'host', 'kernel', 'man', 'memfr', + shown = ['os', 'bios', 'biosdate', 'cpu', 'host', 'kernel', 'man', 'memfr', 'memsz', 'mode', 'numcpu', 'plat', 'time', 'wifi'] sysvals.vprint('System Info:') for key in sorted(sysvals.stamp): @@ -6052,6 +6215,8 @@ def runTest(n=0, quiet=False): if sysvals.display: ret = sysvals.displayControl('init') sysvals.dlog('xset display init, ret = %d' % ret) + sysvals.testVal(sysvals.pmdpath, 'basic', '1') + sysvals.testVal(sysvals.s0ixpath, 'basic', 'Y') sysvals.dlog('initialize ftrace') sysvals.initFtrace(quiet) @@ -6145,9 +6310,12 @@ def data_from_html(file, outpath, issues, fulldetail=False): elist[err[0]] += 1 for i in elist: ilist.append('%sx%d' % (i, elist[i]) if elist[i] > 1 else i) - wifi = find_in_html(html, 'Wifi Resume: ', '</td>') - if wifi: - extra['wifi'] = wifi + line = find_in_html(log, '# wifi ', '\n') + if line: + extra['wifi'] = line + line = find_in_html(log, '# netfix ', '\n') + if line: + extra['netfix'] = line low = find_in_html(html, 'freeze time: <b>', ' ms</b>') for lowstr in ['waking', '+']: if not low: @@ -6243,7 +6411,7 @@ def genHtml(subdir, force=False): sysvals.ftracefile = file sysvals.setOutputFile() if (sysvals.dmesgfile or sysvals.ftracefile) and sysvals.htmlfile and \ - (force or not sysvals.usable(sysvals.htmlfile)): + (force or not sysvals.usable(sysvals.htmlfile, True)): pprint('FTRACE: %s' % sysvals.ftracefile) if sysvals.dmesgfile: pprint('DMESG : %s' % sysvals.dmesgfile) @@ -6533,6 +6701,7 @@ def printHelp(): ' -skiphtml Run the test and capture the trace logs, but skip the timeline (default: disabled)\n'\ ' -result fn Export a results table to a text file for parsing.\n'\ ' -wifi If a wifi connection is available, check that it reconnects after resume.\n'\ + ' -netfix Use netfix to reset the network in the event it fails to resume.\n'\ ' [testprep]\n'\ ' -sync Sync the filesystems before starting the test\n'\ ' -rs on/off Enable/disable runtime suspend for all devices, restore all after test\n'\ @@ -6615,6 +6784,8 @@ if __name__ == '__main__': elif(arg == '-v'): pprint("Version %s" % sysvals.version) sys.exit(0) + elif(arg == '-debugtiming'): + debugtiming = True elif(arg == '-x2'): sysvals.execcount = 2 elif(arg == '-x2delay'): @@ -6657,6 +6828,8 @@ if __name__ == '__main__': sysvals.sync = True elif(arg == '-wifi'): sysvals.wifi = True + elif(arg == '-netfix'): + sysvals.netfix = True elif(arg == '-gzip'): sysvals.gzip = True elif(arg == '-info'): @@ -6819,7 +6992,7 @@ if __name__ == '__main__': sysvals.outdir = val sysvals.notestrun = True if(os.path.isdir(val) == False): - doError('%s is not accessible' % val) + doError('%s is not accesible' % val) elif(arg == '-filter'): try: val = next(args) @@ -6942,12 +7115,11 @@ if __name__ == '__main__': time.sleep(sysvals.multitest['delay']) fmt = 'suspend-%y%m%d-%H%M%S' sysvals.testdir = os.path.join(sysvals.outdir, datetime.now().strftime(fmt)) - ret = runTest(i+1, True) + ret = runTest(i+1, not sysvals.verbose) failcnt = 0 if not ret else failcnt + 1 if sysvals.maxfail > 0 and failcnt >= sysvals.maxfail: pprint('Maximum fail count of %d reached, aborting multitest' % (sysvals.maxfail)) break - time.sleep(5) sysvals.resetlog() sysvals.multistat(False, i, finish) if 'time' in sysvals.multitest and datetime.now() >= finish:
bootgraph: - fix parsing of /proc/version to be much more flexible - check kernel version to disallow ftrace on anything older than 4.10 sleepgraph: - include fix to bugzilla 212761 in case it regresses - fix for -proc bug: https://github.com/intel/pm-graph/pull/20 - add -debugtiming arg to get timestamps on prints - allow use of the netfix tool hosted in the github repo - read s0ix data from pmc_core for better debug - include more system data in the output log - Do a better job testing input files useability - flag more error data from dmesg in the timeline - pre-parse the trace log to fix any ordering issues - add new parser to process dmesg only timelines - remove superflous sleep(5) in multitest mode config/custom-timeline-functions.cfg: - change some names to keep up to date README: - new version, small wording changes Signed-off-by: Todd Brandt <todd.e.brandt@intel.com> --- tools/power/pm-graph/README | 6 +- tools/power/pm-graph/bootgraph.py | 20 +- .../config/custom-timeline-functions.cfg | 2 +- tools/power/pm-graph/sleepgraph.py | 518 ++++++++++++------ 4 files changed, 360 insertions(+), 186 deletions(-)