| sleepgraph.py (97318d6427f62b723c89f4150f8f48126ef74961) | sleepgraph.py (0417552730d0b1c30268fd32546914290b7c7ca0) |
|---|---|
| 1#!/usr/bin/env python3 2# SPDX-License-Identifier: GPL-2.0-only 3# 4# Tool for analyzing suspend/resume timing 5# Copyright (c) 2013, Intel Corporation. 6# 7# This program is free software; you can redistribute it and/or modify it 8# under the terms and conditions of the GNU General Public License, --- 72 unchanged lines hidden (view full) --- 81# ----------------- CLASSES -------------------- 82 83# Class: SystemValues 84# Description: 85# A global, single-instance container used to 86# store system values and test parameters 87class SystemValues: 88 title = 'SleepGraph' | 1#!/usr/bin/env python3 2# SPDX-License-Identifier: GPL-2.0-only 3# 4# Tool for analyzing suspend/resume timing 5# Copyright (c) 2013, Intel Corporation. 6# 7# This program is free software; you can redistribute it and/or modify it 8# under the terms and conditions of the GNU General Public License, --- 72 unchanged lines hidden (view full) --- 81# ----------------- CLASSES -------------------- 82 83# Class: SystemValues 84# Description: 85# A global, single-instance container used to 86# store system values and test parameters 87class SystemValues: 88 title = 'SleepGraph' |
| 89 version = '5.10' | 89 version = '5.11' |
| 90 ansi = False 91 rs = 0 92 display = '' 93 gzip = False 94 sync = False 95 wifi = False 96 netfix = False 97 verbose = False --- 197 unchanged lines hidden (view full) --- 295 [0, 'cpuinfo', 'head', '-7', '/proc/cpuinfo'], 296 [0, 'kparams', 'cat', '/proc/cmdline'], 297 [0, 'mcelog', 'mcelog'], 298 [0, 'pcidevices', 'lspci', '-tv'], 299 [0, 'usbdevices', 'lsusb', '-tv'], 300 [0, 'acpidevices', 'sh', '-c', 'ls -l /sys/bus/acpi/devices/*/physical_node'], 301 [0, 's0ix_require', 'cat', '/sys/kernel/debug/pmc_core/substate_requirements'], 302 [0, 's0ix_debug', 'cat', '/sys/kernel/debug/pmc_core/slp_s0_debug_status'], | 90 ansi = False 91 rs = 0 92 display = '' 93 gzip = False 94 sync = False 95 wifi = False 96 netfix = False 97 verbose = False --- 197 unchanged lines hidden (view full) --- 295 [0, 'cpuinfo', 'head', '-7', '/proc/cpuinfo'], 296 [0, 'kparams', 'cat', '/proc/cmdline'], 297 [0, 'mcelog', 'mcelog'], 298 [0, 'pcidevices', 'lspci', '-tv'], 299 [0, 'usbdevices', 'lsusb', '-tv'], 300 [0, 'acpidevices', 'sh', '-c', 'ls -l /sys/bus/acpi/devices/*/physical_node'], 301 [0, 's0ix_require', 'cat', '/sys/kernel/debug/pmc_core/substate_requirements'], 302 [0, 's0ix_debug', 'cat', '/sys/kernel/debug/pmc_core/slp_s0_debug_status'], |
| 303 [0, 'ethtool', 'ethtool', '{ethdev}'], |
|
| 303 [1, 's0ix_residency', 'cat', '/sys/kernel/debug/pmc_core/slp_s0_residency_usec'], 304 [1, 'interrupts', 'cat', '/proc/interrupts'], 305 [1, 'wakeups', 'cat', '/sys/kernel/debug/wakeup_sources'], 306 [2, 'gpecounts', 'sh', '-c', 'grep -v invalid /sys/firmware/acpi/interrupts/*'], 307 [2, 'suspendstats', 'sh', '-c', 'grep -v invalid /sys/power/suspend_stats/*'], 308 [2, 'cpuidle', 'sh', '-c', 'grep -v invalid /sys/devices/system/cpu/cpu*/cpuidle/state*/s2idle/*'], 309 [2, 'battery', 'sh', '-c', 'grep -v invalid /sys/class/power_supply/*/*'], 310 [2, 'thermal', 'sh', '-c', 'grep . /sys/class/thermal/thermal_zone*/temp'], --- 762 unchanged lines hidden (view full) --- 1073 if delim in line: 1074 data = line.split(delim, 1) 1075 num = re.search(r'[\d]+', data[1]) 1076 if format == 2 and num: 1077 out[data[0].strip()] = num.group() 1078 else: 1079 out[data[0].strip()] = data[1] 1080 return out | 304 [1, 's0ix_residency', 'cat', '/sys/kernel/debug/pmc_core/slp_s0_residency_usec'], 305 [1, 'interrupts', 'cat', '/proc/interrupts'], 306 [1, 'wakeups', 'cat', '/sys/kernel/debug/wakeup_sources'], 307 [2, 'gpecounts', 'sh', '-c', 'grep -v invalid /sys/firmware/acpi/interrupts/*'], 308 [2, 'suspendstats', 'sh', '-c', 'grep -v invalid /sys/power/suspend_stats/*'], 309 [2, 'cpuidle', 'sh', '-c', 'grep -v invalid /sys/devices/system/cpu/cpu*/cpuidle/state*/s2idle/*'], 310 [2, 'battery', 'sh', '-c', 'grep -v invalid /sys/class/power_supply/*/*'], 311 [2, 'thermal', 'sh', '-c', 'grep . /sys/class/thermal/thermal_zone*/temp'], --- 762 unchanged lines hidden (view full) --- 1074 if delim in line: 1075 data = line.split(delim, 1) 1076 num = re.search(r'[\d]+', data[1]) 1077 if format == 2 and num: 1078 out[data[0].strip()] = num.group() 1079 else: 1080 out[data[0].strip()] = data[1] 1081 return out |
| 1082 def cmdinfovar(self, arg): 1083 if arg == 'ethdev': 1084 try: 1085 cmd = [self.getExec('ip'), '-4', '-o', '-br', 'addr'] 1086 fp = Popen(cmd, stdout=PIPE, stderr=PIPE).stdout 1087 info = ascii(fp.read()).strip() 1088 fp.close() 1089 except: 1090 return 'iptoolcrash' 1091 for line in info.split('\n'): 1092 if line[0] == 'e' and 'UP' in line: 1093 return line.split()[0] 1094 return 'nodevicefound' 1095 return 'unknown' |
|
| 1081 def cmdinfo(self, begin, debug=False): 1082 out = [] 1083 if begin: 1084 self.cmd1 = dict() 1085 for cargs in self.infocmds: | 1096 def cmdinfo(self, begin, debug=False): 1097 out = [] 1098 if begin: 1099 self.cmd1 = dict() 1100 for cargs in self.infocmds: |
| 1086 delta, name = cargs[0], cargs[1] 1087 cmdline, cmdpath = ' '.join(cargs[2:]), self.getExec(cargs[2]) | 1101 delta, name, args = cargs[0], cargs[1], cargs[2:] 1102 for i in range(len(args)): 1103 if args[i][0] == '{' and args[i][-1] == '}': 1104 args[i] = self.cmdinfovar(args[i][1:-1]) 1105 cmdline, cmdpath = ' '.join(args[0:]), self.getExec(args[0]) |
| 1088 if not cmdpath or (begin and not delta): 1089 continue 1090 self.dlog('[%s]' % cmdline) 1091 try: | 1106 if not cmdpath or (begin and not delta): 1107 continue 1108 self.dlog('[%s]' % cmdline) 1109 try: |
| 1092 fp = Popen([cmdpath]+cargs[3:], stdout=PIPE, stderr=PIPE).stdout | 1110 fp = Popen([cmdpath]+args[1:], stdout=PIPE, stderr=PIPE).stdout |
| 1093 info = ascii(fp.read()).strip() 1094 fp.close() 1095 except: 1096 continue 1097 if not debug and begin: 1098 self.cmd1[name] = self.dictify(info, delta) 1099 elif not debug and delta and name in self.cmd1: 1100 before, after = self.cmd1[name], self.dictify(info, delta) --- 346 unchanged lines hidden (view full) --- 1447 'resume_noirq': {'order': 6, 'color': '#FF9900'}, 1448 'resume_early': {'order': 7, 'color': '#FFCC00'}, 1449 'resume': {'order': 8, 'color': '#FFFF88'}, 1450 'resume_complete': {'order': 9, 'color': '#FFFFCC'}, 1451 } 1452 errlist = { 1453 'HWERROR' : r'.*\[ *Hardware Error *\].*', 1454 'FWBUG' : r'.*\[ *Firmware Bug *\].*', | 1111 info = ascii(fp.read()).strip() 1112 fp.close() 1113 except: 1114 continue 1115 if not debug and begin: 1116 self.cmd1[name] = self.dictify(info, delta) 1117 elif not debug and delta and name in self.cmd1: 1118 before, after = self.cmd1[name], self.dictify(info, delta) --- 346 unchanged lines hidden (view full) --- 1465 'resume_noirq': {'order': 6, 'color': '#FF9900'}, 1466 'resume_early': {'order': 7, 'color': '#FFCC00'}, 1467 'resume': {'order': 8, 'color': '#FFFF88'}, 1468 'resume_complete': {'order': 9, 'color': '#FFFFCC'}, 1469 } 1470 errlist = { 1471 'HWERROR' : r'.*\[ *Hardware Error *\].*', 1472 'FWBUG' : r'.*\[ *Firmware Bug *\].*', |
| 1473 'TASKFAIL': r'.*Freezing .*after *.*', |
|
| 1455 'BUG' : r'(?i).*\bBUG\b.*', 1456 'ERROR' : r'(?i).*\bERROR\b.*', 1457 'WARNING' : r'(?i).*\bWARNING\b.*', 1458 'FAULT' : r'(?i).*\bFAULT\b.*', 1459 'FAIL' : r'(?i).*\bFAILED\b.*', 1460 'INVALID' : r'(?i).*\bINVALID\b.*', 1461 'CRASH' : r'(?i).*\bCRASHED\b.*', 1462 'TIMEOUT' : r'(?i).*\bTIMEOUT\b.*', 1463 'ABORT' : r'(?i).*\bABORT\b.*', 1464 'IRQ' : r'.*\bgenirq: .*', | 1474 'BUG' : r'(?i).*\bBUG\b.*', 1475 'ERROR' : r'(?i).*\bERROR\b.*', 1476 'WARNING' : r'(?i).*\bWARNING\b.*', 1477 'FAULT' : r'(?i).*\bFAULT\b.*', 1478 'FAIL' : r'(?i).*\bFAILED\b.*', 1479 'INVALID' : r'(?i).*\bINVALID\b.*', 1480 'CRASH' : r'(?i).*\bCRASHED\b.*', 1481 'TIMEOUT' : r'(?i).*\bTIMEOUT\b.*', 1482 'ABORT' : r'(?i).*\bABORT\b.*', 1483 'IRQ' : r'.*\bgenirq: .*', |
| 1465 'TASKFAIL': r'.*Freezing .*after *.*', | |
| 1466 'ACPI' : r'.*\bACPI *(?P<b>[A-Za-z]*) *Error[: ].*', 1467 'DISKFULL': r'.*\bNo space left on device.*', 1468 'USBERR' : r'.*usb .*device .*, error [0-9-]*', 1469 'ATAERR' : r' *ata[0-9\.]*: .*failed.*', 1470 'MEIERR' : r' *mei.*: .*failed.*', 1471 'TPMERR' : r'(?i) *tpm *tpm[0-9]*: .*error.*', 1472 } 1473 def __init__(self, num): --- 123 unchanged lines hidden (view full) --- 1597 return True 1598 def sourcePhase(self, start): 1599 for phase in self.sortedPhases(): 1600 if 'machine' in phase: 1601 continue 1602 pend = self.dmesg[phase]['end'] 1603 if start <= pend: 1604 return phase | 1484 'ACPI' : r'.*\bACPI *(?P<b>[A-Za-z]*) *Error[: ].*', 1485 'DISKFULL': r'.*\bNo space left on device.*', 1486 'USBERR' : r'.*usb .*device .*, error [0-9-]*', 1487 'ATAERR' : r' *ata[0-9\.]*: .*failed.*', 1488 'MEIERR' : r' *mei.*: .*failed.*', 1489 'TPMERR' : r'(?i) *tpm *tpm[0-9]*: .*error.*', 1490 } 1491 def __init__(self, num): --- 123 unchanged lines hidden (view full) --- 1615 return True 1616 def sourcePhase(self, start): 1617 for phase in self.sortedPhases(): 1618 if 'machine' in phase: 1619 continue 1620 pend = self.dmesg[phase]['end'] 1621 if start <= pend: 1622 return phase |
| 1605 return 'resume_complete' | 1623 return 'resume_complete' if 'resume_complete' in self.dmesg else '' |
| 1606 def sourceDevice(self, phaselist, start, end, pid, type): 1607 tgtdev = '' 1608 for phase in phaselist: 1609 list = self.dmesg[phase]['list'] 1610 for devname in list: 1611 dev = list[devname] 1612 # pid must match 1613 if dev['pid'] != pid: --- 26 unchanged lines hidden (view full) --- 1640 tgtdev = self.sourceDevice(phases, start, end, pid, 'thread') 1641 # create new thread blocks, expand as new calls are found 1642 if not tgtdev: 1643 if proc == '<...>': 1644 threadname = 'kthread-%d' % (pid) 1645 else: 1646 threadname = '%s-%d' % (proc, pid) 1647 tgtphase = self.sourcePhase(start) | 1624 def sourceDevice(self, phaselist, start, end, pid, type): 1625 tgtdev = '' 1626 for phase in phaselist: 1627 list = self.dmesg[phase]['list'] 1628 for devname in list: 1629 dev = list[devname] 1630 # pid must match 1631 if dev['pid'] != pid: --- 26 unchanged lines hidden (view full) --- 1658 tgtdev = self.sourceDevice(phases, start, end, pid, 'thread') 1659 # create new thread blocks, expand as new calls are found 1660 if not tgtdev: 1661 if proc == '<...>': 1662 threadname = 'kthread-%d' % (pid) 1663 else: 1664 threadname = '%s-%d' % (proc, pid) 1665 tgtphase = self.sourcePhase(start) |
| 1666 if not tgtphase: 1667 return False |
|
| 1648 self.newAction(tgtphase, threadname, pid, '', start, end, '', ' kth', '') 1649 return self.addDeviceFunctionCall(displayname, kprobename, proc, pid, start, end, cdata, rdata) 1650 # this should not happen 1651 if not tgtdev: 1652 sysvals.vprint('[%f - %f] %s-%d %s %s %s' % \ 1653 (start, end, proc, pid, kprobename, cdata, rdata)) 1654 return False 1655 # place the call data inside the src element of the tgtdev --- 174 unchanged lines hidden (view full) --- 1830 if not self.hwstart or not self.hwend: 1831 return 1832 stime = (self.tSuspended - self.start) * 1000000 1833 rtime = (self.end - self.tResumed) * 1000000 1834 hws = self.hwstart + timedelta(microseconds=stime) 1835 hwr = self.hwend - timedelta(microseconds=rtime) 1836 self.tLow.append('%.0f'%((hwr - hws).total_seconds() * 1000)) 1837 def getTimeValues(self): | 1668 self.newAction(tgtphase, threadname, pid, '', start, end, '', ' kth', '') 1669 return self.addDeviceFunctionCall(displayname, kprobename, proc, pid, start, end, cdata, rdata) 1670 # this should not happen 1671 if not tgtdev: 1672 sysvals.vprint('[%f - %f] %s-%d %s %s %s' % \ 1673 (start, end, proc, pid, kprobename, cdata, rdata)) 1674 return False 1675 # place the call data inside the src element of the tgtdev --- 174 unchanged lines hidden (view full) --- 1850 if not self.hwstart or not self.hwend: 1851 return 1852 stime = (self.tSuspended - self.start) * 1000000 1853 rtime = (self.end - self.tResumed) * 1000000 1854 hws = self.hwstart + timedelta(microseconds=stime) 1855 hwr = self.hwend - timedelta(microseconds=rtime) 1856 self.tLow.append('%.0f'%((hwr - hws).total_seconds() * 1000)) 1857 def getTimeValues(self): |
| 1838 sktime = (self.tSuspended - self.tKernSus) * 1000 1839 rktime = (self.tKernRes - self.tResumed) * 1000 1840 return (sktime, rktime) | 1858 s = (self.tSuspended - self.tKernSus) * 1000 1859 r = (self.tKernRes - self.tResumed) * 1000 1860 return (max(s, 0), max(r, 0)) |
| 1841 def setPhase(self, phase, ktime, isbegin, order=-1): 1842 if(isbegin): 1843 # phase start over current phase 1844 if self.currphase: 1845 if 'resume_machine' not in self.currphase: 1846 sysvals.vprint('WARNING: phase %s failed to end' % self.currphase) 1847 self.dmesg[self.currphase]['end'] = ktime 1848 phases = self.dmesg.keys() --- 2107 unchanged lines hidden (view full) --- 3956 'PM: Suspending system .*'], 3957 'suspend_late': ['PM: suspend of devices complete after.*', 3958 'PM: freeze of devices complete after.*'], 3959 'suspend_noirq': ['PM: late suspend of devices complete after.*', 3960 'PM: late freeze of devices complete after.*'], 3961 'suspend_machine': ['PM: suspend-to-idle', 3962 'PM: noirq suspend of devices complete after.*', 3963 'PM: noirq freeze of devices complete after.*'], | 1861 def setPhase(self, phase, ktime, isbegin, order=-1): 1862 if(isbegin): 1863 # phase start over current phase 1864 if self.currphase: 1865 if 'resume_machine' not in self.currphase: 1866 sysvals.vprint('WARNING: phase %s failed to end' % self.currphase) 1867 self.dmesg[self.currphase]['end'] = ktime 1868 phases = self.dmesg.keys() --- 2107 unchanged lines hidden (view full) --- 3976 'PM: Suspending system .*'], 3977 'suspend_late': ['PM: suspend of devices complete after.*', 3978 'PM: freeze of devices complete after.*'], 3979 'suspend_noirq': ['PM: late suspend of devices complete after.*', 3980 'PM: late freeze of devices complete after.*'], 3981 'suspend_machine': ['PM: suspend-to-idle', 3982 'PM: noirq suspend of devices complete after.*', 3983 'PM: noirq freeze of devices complete after.*'], |
| 3964 'resume_machine': ['PM: Timekeeping suspended for.*', | 3984 'resume_machine': ['[PM: ]*Timekeeping suspended for.*', |
| 3965 'ACPI: Low-level resume complete.*', 3966 'ACPI: resume from mwait', 3967 'Suspended for [0-9\.]* seconds'], 3968 'resume_noirq': ['PM: resume from suspend-to-idle', 3969 'ACPI: Waking up from system sleep state.*'], 3970 'resume_early': ['PM: noirq resume of devices complete after.*', 3971 'PM: noirq restore of devices complete after.*'], 3972 'resume': ['PM: early resume of devices complete after.*', 3973 'PM: early restore of devices complete after.*'], 3974 'resume_complete': ['PM: resume of devices complete after.*', 3975 'PM: restore of devices complete after.*'], 3976 'post_resume': ['.*Restarting tasks \.\.\..*'], 3977 } 3978 3979 # action table (expected events that occur and show up in dmesg) 3980 at = { 3981 'sync_filesystems': { | 3985 'ACPI: Low-level resume complete.*', 3986 'ACPI: resume from mwait', 3987 'Suspended for [0-9\.]* seconds'], 3988 'resume_noirq': ['PM: resume from suspend-to-idle', 3989 'ACPI: Waking up from system sleep state.*'], 3990 'resume_early': ['PM: noirq resume of devices complete after.*', 3991 'PM: noirq restore of devices complete after.*'], 3992 'resume': ['PM: early resume of devices complete after.*', 3993 'PM: early restore of devices complete after.*'], 3994 'resume_complete': ['PM: resume of devices complete after.*', 3995 'PM: restore of devices complete after.*'], 3996 'post_resume': ['.*Restarting tasks \.\.\..*'], 3997 } 3998 3999 # action table (expected events that occur and show up in dmesg) 4000 at = { 4001 'sync_filesystems': { |
| 3982 'smsg': 'PM: Syncing filesystems.*', 3983 'emsg': 'PM: Preparing system for mem sleep.*' }, | 4002 'smsg': '.*[Ff]+ilesystems.*', 4003 'emsg': 'PM: Preparing system for[a-z]* sleep.*' }, |
| 3984 'freeze_user_processes': { | 4004 'freeze_user_processes': { |
| 3985 'smsg': 'Freezing user space processes .*', | 4005 'smsg': 'Freezing user space processes.*', |
| 3986 'emsg': 'Freezing remaining freezable tasks.*' }, 3987 'freeze_tasks': { 3988 'smsg': 'Freezing remaining freezable tasks.*', | 4006 'emsg': 'Freezing remaining freezable tasks.*' }, 4007 'freeze_tasks': { 4008 'smsg': 'Freezing remaining freezable tasks.*', |
| 3989 'emsg': 'PM: Entering (?P<mode>[a-z,A-Z]*) sleep.*' }, | 4009 'emsg': 'PM: Suspending system.*' }, |
| 3990 'ACPI prepare': { 3991 'smsg': 'ACPI: Preparing to enter system sleep state.*', 3992 'emsg': 'PM: Saving platform NVS memory.*' }, 3993 'PM vns': { 3994 'smsg': 'PM: Saving platform NVS memory.*', 3995 'emsg': 'Disabling non-boot CPUs .*' }, 3996 } 3997 --- 117 unchanged lines hidden (view full) --- 4115 dev['end'] = ktime 4116 4117 # if trace events are not available, these are better than nothing 4118 if(not sysvals.usetraceevents): 4119 # look for known actions 4120 for a in sorted(at): 4121 if(re.match(at[a]['smsg'], msg)): 4122 if(a not in actions): | 4010 'ACPI prepare': { 4011 'smsg': 'ACPI: Preparing to enter system sleep state.*', 4012 'emsg': 'PM: Saving platform NVS memory.*' }, 4013 'PM vns': { 4014 'smsg': 'PM: Saving platform NVS memory.*', 4015 'emsg': 'Disabling non-boot CPUs .*' }, 4016 } 4017 --- 117 unchanged lines hidden (view full) --- 4135 dev['end'] = ktime 4136 4137 # if trace events are not available, these are better than nothing 4138 if(not sysvals.usetraceevents): 4139 # look for known actions 4140 for a in sorted(at): 4141 if(re.match(at[a]['smsg'], msg)): 4142 if(a not in actions): |
| 4123 actions[a] = [] 4124 actions[a].append({'begin': ktime, 'end': ktime}) | 4143 actions[a] = [{'begin': ktime, 'end': ktime}] |
| 4125 if(re.match(at[a]['emsg'], msg)): | 4144 if(re.match(at[a]['emsg'], msg)): |
| 4126 if(a in actions): | 4145 if(a in actions and actions[a][-1]['begin'] == actions[a][-1]['end']): |
| 4127 actions[a][-1]['end'] = ktime 4128 # now look for CPU on/off events 4129 if(re.match('Disabling non-boot CPUs .*', msg)): 4130 # start of first cpu suspend 4131 cpu_start = ktime 4132 elif(re.match('Enabling non-boot CPUs .*', msg)): 4133 # start of first cpu resume 4134 cpu_start = ktime --- 2999 unchanged lines hidden --- | 4146 actions[a][-1]['end'] = ktime 4147 # now look for CPU on/off events 4148 if(re.match('Disabling non-boot CPUs .*', msg)): 4149 # start of first cpu suspend 4150 cpu_start = ktime 4151 elif(re.match('Enabling non-boot CPUs .*', msg)): 4152 # start of first cpu resume 4153 cpu_start = ktime --- 2999 unchanged lines hidden --- |