aboutsummaryrefslogtreecommitdiffstats
path: root/tools/power/pm-graph/sleepgraph.py
diff options
context:
space:
mode:
authorTodd Brandt <todd.e.brandt@linux.intel.com>2018-10-08 18:56:31 -0400
committerRafael J. Wysocki <rafael.j.wysocki@intel.com>2018-10-09 03:27:33 -0400
commit5484f0334439701900121a107709c461215cadb6 (patch)
tree8fea56173f8252d0eb801771c567ace532a776b9 /tools/power/pm-graph/sleepgraph.py
parent0238df646e6224016a45505d2c111a24669ebe21 (diff)
PM / tools: sleepgraph: first batch of v5.2 changes
general: - add battery charge data before and after test - remove special s0i3 handling - remove melding of dmesg & ftrace data in old kernels, use one only - updates to various kprobes in trace (ksys_sync, etc) - enable pm_debug_messages during the test - instrument more subsystems with dev functions (phy0) error handling: - return codes for tool show the status of the test run - 0: success, 1: general error (no timeline), 2: fail (suspend aborted) - monitor output of /sys/power/state, mark as failure if exception occurs - add signal handler when using -result to catch tool exceptions display control - add -x commands for testing xset with mode settings and status - allow display setting to on, off, suspend, standby - add display mode change info to the log, along with a warning on fail s2idle (freeze) - remove fixed 10-phase dependency, allow any phase order & any count - multiple phase occurences show as phase_nameN e.g. suspend_noirq3 - if multiple freezes occur, print multiple time values in header summary: - add new columns to summary output: issues, worst suspend/resume devices - worst device: includes summation of all phases of suspend or resume - issues: includes WARNING/ERROR/BUG from dmesg log, and other issues - s2idle: multiple freezes show as FREEZExN in the issues column Signed-off-by: Todd Brandt <todd.e.brandt@linux.intel.com> Signed-off-by: Rafael J. Wysocki <rafael.j.wysocki@intel.com>
Diffstat (limited to 'tools/power/pm-graph/sleepgraph.py')
-rwxr-xr-xtools/power/pm-graph/sleepgraph.py1378
1 files changed, 748 insertions, 630 deletions
diff --git a/tools/power/pm-graph/sleepgraph.py b/tools/power/pm-graph/sleepgraph.py
index 0c760478f7d7..343e8000d9ca 100755
--- a/tools/power/pm-graph/sleepgraph.py
+++ b/tools/power/pm-graph/sleepgraph.py
@@ -54,6 +54,7 @@ import os
54import string 54import string
55import re 55import re
56import platform 56import platform
57import signal
57from datetime import datetime 58from datetime import datetime
58import struct 59import struct
59import ConfigParser 60import ConfigParser
@@ -72,7 +73,7 @@ class SystemValues:
72 version = '5.1' 73 version = '5.1'
73 ansi = False 74 ansi = False
74 rs = 0 75 rs = 0
75 display = 0 76 display = ''
76 gzip = False 77 gzip = False
77 sync = False 78 sync = False
78 verbose = False 79 verbose = False
@@ -99,6 +100,7 @@ class SystemValues:
99 tpath = '/sys/kernel/debug/tracing/' 100 tpath = '/sys/kernel/debug/tracing/'
100 fpdtpath = '/sys/firmware/acpi/tables/FPDT' 101 fpdtpath = '/sys/firmware/acpi/tables/FPDT'
101 epath = '/sys/kernel/debug/tracing/events/power/' 102 epath = '/sys/kernel/debug/tracing/events/power/'
103 pmdpath = '/sys/power/pm_debug_messages'
102 traceevents = [ 104 traceevents = [
103 'suspend_resume', 105 'suspend_resume',
104 'device_pm_callback_end', 106 'device_pm_callback_end',
@@ -141,12 +143,10 @@ class SystemValues:
141 devprops = dict() 143 devprops = dict()
142 predelay = 0 144 predelay = 0
143 postdelay = 0 145 postdelay = 0
144 procexecfmt = 'ps - (?P<ps>.*)$' 146 pmdebug = ''
145 devpropfmt = '# Device Properties: .*'
146 tracertypefmt = '# tracer: (?P<t>.*)'
147 firmwarefmt = '# fwsuspend (?P<s>[0-9]*) fwresume (?P<r>[0-9]*)$'
148 tracefuncs = { 147 tracefuncs = {
149 'sys_sync': {}, 148 'sys_sync': {},
149 'ksys_sync': {},
150 '__pm_notifier_call_chain': {}, 150 '__pm_notifier_call_chain': {},
151 'pm_prepare_console': {}, 151 'pm_prepare_console': {},
152 'pm_notifier_call_chain': {}, 152 'pm_notifier_call_chain': {},
@@ -187,7 +187,6 @@ class SystemValues:
187 dev_tracefuncs = { 187 dev_tracefuncs = {
188 # general wait/delay/sleep 188 # general wait/delay/sleep
189 'msleep': { 'args_x86_64': {'time':'%di:s32'}, 'ub': 1 }, 189 'msleep': { 'args_x86_64': {'time':'%di:s32'}, 'ub': 1 },
190 'schedule_timeout_uninterruptible': { 'args_x86_64': {'timeout':'%di:s32'}, 'ub': 1 },
191 'schedule_timeout': { 'args_x86_64': {'timeout':'%di:s32'}, 'ub': 1 }, 190 'schedule_timeout': { 'args_x86_64': {'timeout':'%di:s32'}, 'ub': 1 },
192 'udelay': { 'func':'__const_udelay', 'args_x86_64': {'loops':'%di:s32'}, 'ub': 1 }, 191 'udelay': { 'func':'__const_udelay', 'args_x86_64': {'loops':'%di:s32'}, 'ub': 1 },
193 'usleep_range': { 'args_x86_64': {'min':'%di:s32', 'max':'%si:s32'}, 'ub': 1 }, 192 'usleep_range': { 'args_x86_64': {'min':'%di:s32', 'max':'%si:s32'}, 'ub': 1 },
@@ -199,6 +198,9 @@ class SystemValues:
199 # filesystem 198 # filesystem
200 'ext4_sync_fs': {}, 199 'ext4_sync_fs': {},
201 # 80211 200 # 80211
201 'ath10k_bmi_read_memory': { 'args_x86_64': {'length':'%cx:s32'} },
202 'ath10k_bmi_write_memory': { 'args_x86_64': {'length':'%cx:s32'} },
203 'ath10k_bmi_fast_download': { 'args_x86_64': {'length':'%cx:s32'} },
202 'iwlagn_mac_start': {}, 204 'iwlagn_mac_start': {},
203 'iwlagn_alloc_bcast_station': {}, 205 'iwlagn_alloc_bcast_station': {},
204 'iwl_trans_pcie_start_hw': {}, 206 'iwl_trans_pcie_start_hw': {},
@@ -241,6 +243,7 @@ class SystemValues:
241 timeformat = '%.3f' 243 timeformat = '%.3f'
242 cmdline = '%s %s' % \ 244 cmdline = '%s %s' % \
243 (os.path.basename(sys.argv[0]), ' '.join(sys.argv[1:])) 245 (os.path.basename(sys.argv[0]), ' '.join(sys.argv[1:]))
246 sudouser = ''
244 def __init__(self): 247 def __init__(self):
245 self.archargs = 'args_'+platform.machine() 248 self.archargs = 'args_'+platform.machine()
246 self.hostname = platform.node() 249 self.hostname = platform.node()
@@ -256,10 +259,32 @@ class SystemValues:
256 if (hasattr(sys.stdout, 'isatty') and sys.stdout.isatty()): 259 if (hasattr(sys.stdout, 'isatty') and sys.stdout.isatty()):
257 self.ansi = True 260 self.ansi = True
258 self.testdir = datetime.now().strftime('suspend-%y%m%d-%H%M%S') 261 self.testdir = datetime.now().strftime('suspend-%y%m%d-%H%M%S')
262 if os.getuid() == 0 and 'SUDO_USER' in os.environ and \
263 os.environ['SUDO_USER']:
264 self.sudouser = os.environ['SUDO_USER']
259 def vprint(self, msg): 265 def vprint(self, msg):
260 self.logmsg += msg+'\n' 266 self.logmsg += msg+'\n'
261 if(self.verbose): 267 if self.verbose or msg.startswith('WARNING:'):
262 print(msg) 268 print(msg)
269 def signalHandler(self, signum, frame):
270 if not self.result:
271 return
272 signame = self.signames[signum] if signum in self.signames else 'UNKNOWN'
273 msg = 'Signal %s caused a tool exit, line %d' % (signame, frame.f_lineno)
274 sysvals.outputResult({'error':msg})
275 sys.exit(3)
276 def signalHandlerInit(self):
277 capture = ['BUS', 'SYS', 'XCPU', 'XFSZ', 'PWR', 'HUP', 'INT', 'QUIT',
278 'ILL', 'ABRT', 'FPE', 'SEGV', 'TERM', 'TSTP']
279 self.signames = dict()
280 for i in capture:
281 s = 'SIG'+i
282 try:
283 signum = getattr(signal, s)
284 signal.signal(signum, self.signalHandler)
285 except:
286 continue
287 self.signames[signum] = s
263 def rootCheck(self, fatal=True): 288 def rootCheck(self, fatal=True):
264 if(os.access(self.powerfile, os.W_OK)): 289 if(os.access(self.powerfile, os.W_OK)):
265 return True 290 return True
@@ -267,7 +292,7 @@ class SystemValues:
267 msg = 'This command requires sysfs mount and root access' 292 msg = 'This command requires sysfs mount and root access'
268 print('ERROR: %s\n') % msg 293 print('ERROR: %s\n') % msg
269 self.outputResult({'error':msg}) 294 self.outputResult({'error':msg})
270 sys.exit() 295 sys.exit(1)
271 return False 296 return False
272 def rootUser(self, fatal=False): 297 def rootUser(self, fatal=False):
273 if 'USER' in os.environ and os.environ['USER'] == 'root': 298 if 'USER' in os.environ and os.environ['USER'] == 'root':
@@ -276,7 +301,7 @@ class SystemValues:
276 msg = 'This command must be run as root' 301 msg = 'This command must be run as root'
277 print('ERROR: %s\n') % msg 302 print('ERROR: %s\n') % msg
278 self.outputResult({'error':msg}) 303 self.outputResult({'error':msg})
279 sys.exit() 304 sys.exit(1)
280 return False 305 return False
281 def getExec(self, cmd): 306 def getExec(self, cmd):
282 dirlist = ['/sbin', '/bin', '/usr/sbin', '/usr/bin', 307 dirlist = ['/sbin', '/bin', '/usr/sbin', '/usr/bin',
@@ -406,8 +431,8 @@ class SystemValues:
406 ktime = m.group('ktime') 431 ktime = m.group('ktime')
407 fp.close() 432 fp.close()
408 self.dmesgstart = float(ktime) 433 self.dmesgstart = float(ktime)
409 def getdmesg(self, fwdata=[]): 434 def getdmesg(self, testdata):
410 op = self.writeDatafileHeader(sysvals.dmesgfile, fwdata) 435 op = self.writeDatafileHeader(sysvals.dmesgfile, testdata)
411 # store all new dmesg lines since initdmesg was called 436 # store all new dmesg lines since initdmesg was called
412 fp = Popen('dmesg', stdout=PIPE).stdout 437 fp = Popen('dmesg', stdout=PIPE).stdout
413 for line in fp: 438 for line in fp:
@@ -619,6 +644,8 @@ class SystemValues:
619 self.fsetVal('0', 'events/kprobes/enable') 644 self.fsetVal('0', 'events/kprobes/enable')
620 self.fsetVal('', 'kprobe_events') 645 self.fsetVal('', 'kprobe_events')
621 self.fsetVal('1024', 'buffer_size_kb') 646 self.fsetVal('1024', 'buffer_size_kb')
647 if self.pmdebug:
648 self.setVal(self.pmdebug, self.pmdpath)
622 def setupAllKprobes(self): 649 def setupAllKprobes(self):
623 for name in self.tracefuncs: 650 for name in self.tracefuncs:
624 self.defaultKprobe(name, self.tracefuncs[name]) 651 self.defaultKprobe(name, self.tracefuncs[name])
@@ -641,6 +668,11 @@ class SystemValues:
641 # turn trace off 668 # turn trace off
642 self.fsetVal('0', 'tracing_on') 669 self.fsetVal('0', 'tracing_on')
643 self.cleanupFtrace() 670 self.cleanupFtrace()
671 # pm debug messages
672 pv = self.getVal(self.pmdpath)
673 if pv != '1':
674 self.setVal('1', self.pmdpath)
675 self.pmdebug = pv
644 # set the trace clock to global 676 # set the trace clock to global
645 self.fsetVal('global', 'trace_clock') 677 self.fsetVal('global', 'trace_clock')
646 self.fsetVal('nop', 'current_tracer') 678 self.fsetVal('nop', 'current_tracer')
@@ -728,19 +760,24 @@ class SystemValues:
728 if not self.ansi: 760 if not self.ansi:
729 return str 761 return str
730 return '\x1B[%d;40m%s\x1B[m' % (color, str) 762 return '\x1B[%d;40m%s\x1B[m' % (color, str)
731 def writeDatafileHeader(self, filename, fwdata=[]): 763 def writeDatafileHeader(self, filename, testdata):
732 fp = self.openlog(filename, 'w') 764 fp = self.openlog(filename, 'w')
733 fp.write('%s\n%s\n# command | %s\n' % (self.teststamp, self.sysstamp, self.cmdline)) 765 fp.write('%s\n%s\n# command | %s\n' % (self.teststamp, self.sysstamp, self.cmdline))
734 if(self.suspendmode == 'mem' or self.suspendmode == 'command'): 766 for test in testdata:
735 for fw in fwdata: 767 if 'fw' in test:
768 fw = test['fw']
736 if(fw): 769 if(fw):
737 fp.write('# fwsuspend %u fwresume %u\n' % (fw[0], fw[1])) 770 fp.write('# fwsuspend %u fwresume %u\n' % (fw[0], fw[1]))
771 if 'bat' in test:
772 (a1, c1), (a2, c2) = test['bat']
773 fp.write('# battery %s %d %s %d\n' % (a1, c1, a2, c2))
774 if test['error'] or len(testdata) > 1:
775 fp.write('# enter_sleep_error %s\n' % test['error'])
738 return fp 776 return fp
739 def sudouser(self, dir): 777 def sudoUserchown(self, dir):
740 if os.path.exists(dir) and os.getuid() == 0 and \ 778 if os.path.exists(dir) and self.sudouser:
741 'SUDO_USER' in os.environ:
742 cmd = 'chown -R {0}:{0} {1} > /dev/null 2>&1' 779 cmd = 'chown -R {0}:{0} {1} > /dev/null 2>&1'
743 call(cmd.format(os.environ['SUDO_USER'], dir), shell=True) 780 call(cmd.format(self.sudouser, dir), shell=True)
744 def outputResult(self, testdata, num=0): 781 def outputResult(self, testdata, num=0):
745 if not self.result: 782 if not self.result:
746 return 783 return
@@ -762,7 +799,7 @@ class SystemValues:
762 if 'bugurl' in testdata: 799 if 'bugurl' in testdata:
763 fp.write('url%s: %s\n' % (n, testdata['bugurl'])) 800 fp.write('url%s: %s\n' % (n, testdata['bugurl']))
764 fp.close() 801 fp.close()
765 self.sudouser(self.result) 802 self.sudoUserchown(self.result)
766 def configFile(self, file): 803 def configFile(self, file):
767 dir = os.path.dirname(os.path.realpath(__file__)) 804 dir = os.path.dirname(os.path.realpath(__file__))
768 if os.path.exists(file): 805 if os.path.exists(file):
@@ -800,11 +837,12 @@ suspendmodename = {
800# Simple class which holds property values collected 837# Simple class which holds property values collected
801# for all the devices used in the timeline. 838# for all the devices used in the timeline.
802class DevProps: 839class DevProps:
803 syspath = '' 840 def __init__(self):
804 altname = '' 841 self.syspath = ''
805 async = True 842 self.altname = ''
806 xtraclass = '' 843 self.async = True
807 xtrainfo = '' 844 self.xtraclass = ''
845 self.xtrainfo = ''
808 def out(self, dev): 846 def out(self, dev):
809 return '%s,%s,%d;' % (dev, self.altname, self.async) 847 return '%s,%s,%d;' % (dev, self.altname, self.async)
810 def debug(self, dev): 848 def debug(self, dev):
@@ -831,9 +869,6 @@ class DevProps:
831# A container used to create a device hierachy, with a single root node 869# A container used to create a device hierachy, with a single root node
832# and a tree of child nodes. Used by Data.deviceTopology() 870# and a tree of child nodes. Used by Data.deviceTopology()
833class DeviceNode: 871class DeviceNode:
834 name = ''
835 children = 0
836 depth = 0
837 def __init__(self, nodename, nodedepth): 872 def __init__(self, nodename, nodedepth):
838 self.name = nodename 873 self.name = nodename
839 self.children = [] 874 self.children = []
@@ -861,71 +896,78 @@ class DeviceNode:
861# } 896# }
862# 897#
863class Data: 898class Data:
864 dmesg = {} # root data structure 899 phasedef = {
865 phases = [] # ordered list of phases 900 'suspend_prepare': {'order': 0, 'color': '#CCFFCC'},
866 start = 0.0 # test start 901 'suspend': {'order': 1, 'color': '#88FF88'},
867 end = 0.0 # test end 902 'suspend_late': {'order': 2, 'color': '#00AA00'},
868 tSuspended = 0.0 # low-level suspend start 903 'suspend_noirq': {'order': 3, 'color': '#008888'},
869 tResumed = 0.0 # low-level resume start 904 'suspend_machine': {'order': 4, 'color': '#0000FF'},
870 tKernSus = 0.0 # kernel level suspend start 905 'resume_machine': {'order': 5, 'color': '#FF0000'},
871 tKernRes = 0.0 # kernel level resume end 906 'resume_noirq': {'order': 6, 'color': '#FF9900'},
872 tLow = 0.0 # time spent in low-level suspend (standby/freeze) 907 'resume_early': {'order': 7, 'color': '#FFCC00'},
873 fwValid = False # is firmware data available 908 'resume': {'order': 8, 'color': '#FFFF88'},
874 fwSuspend = 0 # time spent in firmware suspend 909 'resume_complete': {'order': 9, 'color': '#FFFFCC'},
875 fwResume = 0 # time spent in firmware resume 910 }
876 dmesgtext = [] # dmesg text file in memory 911 errlist = {
877 pstl = 0 # process timeline 912 'HWERROR' : '.*\[ *Hardware Error *\].*',
878 testnumber = 0 913 'FWBUG' : '.*\[ *Firmware Bug *\].*',
879 idstr = '' 914 'BUG' : '.*BUG.*',
880 html_device_id = 0 915 'ERROR' : '.*ERROR.*',
881 stamp = 0 916 'WARNING' : '.*WARNING.*',
882 outfile = '' 917 'IRQ' : '.*genirq: .*',
883 devpids = [] 918 'TASKFAIL': '.*Freezing of tasks failed.*',
884 kerror = False 919 }
885 def __init__(self, num): 920 def __init__(self, num):
886 idchar = 'abcdefghij' 921 idchar = 'abcdefghij'
887 self.pstl = dict() 922 self.start = 0.0 # test start
923 self.end = 0.0 # test end
924 self.tSuspended = 0.0 # low-level suspend start
925 self.tResumed = 0.0 # low-level resume start
926 self.tKernSus = 0.0 # kernel level suspend start
927 self.tKernRes = 0.0 # kernel level resume end
928 self.fwValid = False # is firmware data available
929 self.fwSuspend = 0 # time spent in firmware suspend
930 self.fwResume = 0 # time spent in firmware resume
931 self.html_device_id = 0
932 self.stamp = 0
933 self.outfile = ''
934 self.kerror = False
935 self.battery = 0
936 self.enterfail = ''
937 self.currphase = ''
938 self.pstl = dict() # process timeline
888 self.testnumber = num 939 self.testnumber = num
889 self.idstr = idchar[num] 940 self.idstr = idchar[num]
890 self.dmesgtext = [] 941 self.dmesgtext = [] # dmesg text file in memory
891 self.phases = [] 942 self.dmesg = dict() # root data structure
892 self.dmesg = { # fixed list of 10 phases 943 self.errorinfo = {'suspend':[],'resume':[]}
893 'suspend_prepare': {'list': dict(), 'start': -1.0, 'end': -1.0, 944 self.tLow = [] # time spent in low-level suspends (standby/freeze)
894 'row': 0, 'color': '#CCFFCC', 'order': 0}, 945 self.devpids = []
895 'suspend': {'list': dict(), 'start': -1.0, 'end': -1.0, 946 self.devicegroups = 0
896 'row': 0, 'color': '#88FF88', 'order': 1}, 947 def sortedPhases(self):
897 'suspend_late': {'list': dict(), 'start': -1.0, 'end': -1.0, 948 return sorted(self.dmesg, key=lambda k:self.dmesg[k]['order'])
898 'row': 0, 'color': '#00AA00', 'order': 2}, 949 def initDevicegroups(self):
899 'suspend_noirq': {'list': dict(), 'start': -1.0, 'end': -1.0, 950 # called when phases are all finished being added
900 'row': 0, 'color': '#008888', 'order': 3}, 951 for phase in self.dmesg.keys():
901 'suspend_machine': {'list': dict(), 'start': -1.0, 'end': -1.0, 952 if '*' in phase:
902 'row': 0, 'color': '#0000FF', 'order': 4}, 953 p = phase.split('*')
903 'resume_machine': {'list': dict(), 'start': -1.0, 'end': -1.0, 954 pnew = '%s%d' % (p[0], len(p))
904 'row': 0, 'color': '#FF0000', 'order': 5}, 955 self.dmesg[pnew] = self.dmesg.pop(phase)
905 'resume_noirq': {'list': dict(), 'start': -1.0, 'end': -1.0,
906 'row': 0, 'color': '#FF9900', 'order': 6},
907 'resume_early': {'list': dict(), 'start': -1.0, 'end': -1.0,
908 'row': 0, 'color': '#FFCC00', 'order': 7},
909 'resume': {'list': dict(), 'start': -1.0, 'end': -1.0,
910 'row': 0, 'color': '#FFFF88', 'order': 8},
911 'resume_complete': {'list': dict(), 'start': -1.0, 'end': -1.0,
912 'row': 0, 'color': '#FFFFCC', 'order': 9}
913 }
914 self.phases = self.sortedPhases()
915 self.devicegroups = [] 956 self.devicegroups = []
916 for phase in self.phases: 957 for phase in self.sortedPhases():
917 self.devicegroups.append([phase]) 958 self.devicegroups.append([phase])
918 self.errorinfo = {'suspend':[],'resume':[]} 959 def nextPhase(self, phase, offset):
960 order = self.dmesg[phase]['order'] + offset
961 for p in self.dmesg:
962 if self.dmesg[p]['order'] == order:
963 return p
964 return ''
965 def lastPhase(self):
966 plist = self.sortedPhases()
967 if len(plist) < 1:
968 return ''
969 return plist[-1]
919 def extractErrorInfo(self): 970 def extractErrorInfo(self):
920 elist = {
921 'HWERROR' : '.*\[ *Hardware Error *\].*',
922 'FWBUG' : '.*\[ *Firmware Bug *\].*',
923 'BUG' : '.*BUG.*',
924 'ERROR' : '.*ERROR.*',
925 'WARNING' : '.*WARNING.*',
926 'IRQ' : '.*genirq: .*',
927 'TASKFAIL': '.*Freezing of tasks failed.*',
928 }
929 lf = sysvals.openlog(sysvals.dmesgfile, 'r') 971 lf = sysvals.openlog(sysvals.dmesgfile, 'r')
930 i = 0 972 i = 0
931 list = [] 973 list = []
@@ -939,8 +981,8 @@ class Data:
939 continue 981 continue
940 dir = 'suspend' if t < self.tSuspended else 'resume' 982 dir = 'suspend' if t < self.tSuspended else 'resume'
941 msg = m.group('msg') 983 msg = m.group('msg')
942 for err in elist: 984 for err in self.errlist:
943 if re.match(elist[err], msg): 985 if re.match(self.errlist[err], msg):
944 list.append((err, dir, t, i, i)) 986 list.append((err, dir, t, i, i))
945 self.kerror = True 987 self.kerror = True
946 break 988 break
@@ -956,7 +998,7 @@ class Data:
956 def setEnd(self, time): 998 def setEnd(self, time):
957 self.end = time 999 self.end = time
958 def isTraceEventOutsideDeviceCalls(self, pid, time): 1000 def isTraceEventOutsideDeviceCalls(self, pid, time):
959 for phase in self.phases: 1001 for phase in self.sortedPhases():
960 list = self.dmesg[phase]['list'] 1002 list = self.dmesg[phase]['list']
961 for dev in list: 1003 for dev in list:
962 d = list[dev] 1004 d = list[dev]
@@ -964,16 +1006,10 @@ class Data:
964 time < d['end']): 1006 time < d['end']):
965 return False 1007 return False
966 return True 1008 return True
967 def phaseCollision(self, phase, isbegin, line):
968 key = 'end'
969 if isbegin:
970 key = 'start'
971 if self.dmesg[phase][key] >= 0:
972 sysvals.vprint('IGNORE: %s' % line.strip())
973 return True
974 return False
975 def sourcePhase(self, start): 1009 def sourcePhase(self, start):
976 for phase in self.phases: 1010 for phase in self.sortedPhases():
1011 if 'machine' in phase:
1012 continue
977 pend = self.dmesg[phase]['end'] 1013 pend = self.dmesg[phase]['end']
978 if start <= pend: 1014 if start <= pend:
979 return phase 1015 return phase
@@ -1004,14 +1040,15 @@ class Data:
1004 return tgtdev 1040 return tgtdev
1005 def addDeviceFunctionCall(self, displayname, kprobename, proc, pid, start, end, cdata, rdata): 1041 def addDeviceFunctionCall(self, displayname, kprobename, proc, pid, start, end, cdata, rdata):
1006 # try to place the call in a device 1042 # try to place the call in a device
1007 tgtdev = self.sourceDevice(self.phases, start, end, pid, 'device') 1043 phases = self.sortedPhases()
1044 tgtdev = self.sourceDevice(phases, start, end, pid, 'device')
1008 # calls with device pids that occur outside device bounds are dropped 1045 # calls with device pids that occur outside device bounds are dropped
1009 # TODO: include these somehow 1046 # TODO: include these somehow
1010 if not tgtdev and pid in self.devpids: 1047 if not tgtdev and pid in self.devpids:
1011 return False 1048 return False
1012 # try to place the call in a thread 1049 # try to place the call in a thread
1013 if not tgtdev: 1050 if not tgtdev:
1014 tgtdev = self.sourceDevice(self.phases, start, end, pid, 'thread') 1051 tgtdev = self.sourceDevice(phases, start, end, pid, 'thread')
1015 # create new thread blocks, expand as new calls are found 1052 # create new thread blocks, expand as new calls are found
1016 if not tgtdev: 1053 if not tgtdev:
1017 if proc == '<...>': 1054 if proc == '<...>':
@@ -1053,7 +1090,7 @@ class Data:
1053 def overflowDevices(self): 1090 def overflowDevices(self):
1054 # get a list of devices that extend beyond the end of this test run 1091 # get a list of devices that extend beyond the end of this test run
1055 devlist = [] 1092 devlist = []
1056 for phase in self.phases: 1093 for phase in self.sortedPhases():
1057 list = self.dmesg[phase]['list'] 1094 list = self.dmesg[phase]['list']
1058 for devname in list: 1095 for devname in list:
1059 dev = list[devname] 1096 dev = list[devname]
@@ -1064,7 +1101,7 @@ class Data:
1064 # merge any devices that overlap devlist 1101 # merge any devices that overlap devlist
1065 for dev in devlist: 1102 for dev in devlist:
1066 devname = dev['name'] 1103 devname = dev['name']
1067 for phase in self.phases: 1104 for phase in self.sortedPhases():
1068 list = self.dmesg[phase]['list'] 1105 list = self.dmesg[phase]['list']
1069 if devname not in list: 1106 if devname not in list:
1070 continue 1107 continue
@@ -1079,7 +1116,7 @@ class Data:
1079 del list[devname] 1116 del list[devname]
1080 def usurpTouchingThread(self, name, dev): 1117 def usurpTouchingThread(self, name, dev):
1081 # the caller test has priority of this thread, give it to him 1118 # the caller test has priority of this thread, give it to him
1082 for phase in self.phases: 1119 for phase in self.sortedPhases():
1083 list = self.dmesg[phase]['list'] 1120 list = self.dmesg[phase]['list']
1084 if name in list: 1121 if name in list:
1085 tdev = list[name] 1122 tdev = list[name]
@@ -1093,7 +1130,7 @@ class Data:
1093 break 1130 break
1094 def stitchTouchingThreads(self, testlist): 1131 def stitchTouchingThreads(self, testlist):
1095 # merge any threads between tests that touch 1132 # merge any threads between tests that touch
1096 for phase in self.phases: 1133 for phase in self.sortedPhases():
1097 list = self.dmesg[phase]['list'] 1134 list = self.dmesg[phase]['list']
1098 for devname in list: 1135 for devname in list:
1099 dev = list[devname] 1136 dev = list[devname]
@@ -1103,7 +1140,7 @@ class Data:
1103 data.usurpTouchingThread(devname, dev) 1140 data.usurpTouchingThread(devname, dev)
1104 def optimizeDevSrc(self): 1141 def optimizeDevSrc(self):
1105 # merge any src call loops to reduce timeline size 1142 # merge any src call loops to reduce timeline size
1106 for phase in self.phases: 1143 for phase in self.sortedPhases():
1107 list = self.dmesg[phase]['list'] 1144 list = self.dmesg[phase]['list']
1108 for dev in list: 1145 for dev in list:
1109 if 'src' not in list[dev]: 1146 if 'src' not in list[dev]:
@@ -1141,7 +1178,7 @@ class Data:
1141 self.tKernSus = self.trimTimeVal(self.tKernSus, t0, dT, left) 1178 self.tKernSus = self.trimTimeVal(self.tKernSus, t0, dT, left)
1142 self.tKernRes = self.trimTimeVal(self.tKernRes, t0, dT, left) 1179 self.tKernRes = self.trimTimeVal(self.tKernRes, t0, dT, left)
1143 self.end = self.trimTimeVal(self.end, t0, dT, left) 1180 self.end = self.trimTimeVal(self.end, t0, dT, left)
1144 for phase in self.phases: 1181 for phase in self.sortedPhases():
1145 p = self.dmesg[phase] 1182 p = self.dmesg[phase]
1146 p['start'] = self.trimTimeVal(p['start'], t0, dT, left) 1183 p['start'] = self.trimTimeVal(p['start'], t0, dT, left)
1147 p['end'] = self.trimTimeVal(p['end'], t0, dT, left) 1184 p['end'] = self.trimTimeVal(p['end'], t0, dT, left)
@@ -1150,6 +1187,7 @@ class Data:
1150 d = list[name] 1187 d = list[name]
1151 d['start'] = self.trimTimeVal(d['start'], t0, dT, left) 1188 d['start'] = self.trimTimeVal(d['start'], t0, dT, left)
1152 d['end'] = self.trimTimeVal(d['end'], t0, dT, left) 1189 d['end'] = self.trimTimeVal(d['end'], t0, dT, left)
1190 d['length'] = d['end'] - d['start']
1153 if('ftrace' in d): 1191 if('ftrace' in d):
1154 cg = d['ftrace'] 1192 cg = d['ftrace']
1155 cg.start = self.trimTimeVal(cg.start, t0, dT, left) 1193 cg.start = self.trimTimeVal(cg.start, t0, dT, left)
@@ -1166,30 +1204,59 @@ class Data:
1166 tm = self.trimTimeVal(tm, t0, dT, left) 1204 tm = self.trimTimeVal(tm, t0, dT, left)
1167 list.append((type, tm, idx1, idx2)) 1205 list.append((type, tm, idx1, idx2))
1168 self.errorinfo[dir] = list 1206 self.errorinfo[dir] = list
1169 def normalizeTime(self, tZero): 1207 def trimFreezeTime(self, tZero):
1170 # trim out any standby or freeze clock time 1208 # trim out any standby or freeze clock time
1171 if(self.tSuspended != self.tResumed): 1209 lp = ''
1172 if(self.tResumed > tZero): 1210 for phase in self.sortedPhases():
1173 self.trimTime(self.tSuspended, \ 1211 if 'resume_machine' in phase and 'suspend_machine' in lp:
1174 self.tResumed-self.tSuspended, True) 1212 tS, tR = self.dmesg[lp]['end'], self.dmesg[phase]['start']
1175 else: 1213 tL = tR - tS
1176 self.trimTime(self.tSuspended, \ 1214 if tL > 0:
1177 self.tResumed-self.tSuspended, False) 1215 left = True if tR > tZero else False
1216 self.trimTime(tS, tL, left)
1217 self.tLow.append('%.0f'%(tL*1000))
1218 lp = phase
1178 def getTimeValues(self): 1219 def getTimeValues(self):
1179 sktime = (self.dmesg['suspend_machine']['end'] - \ 1220 if 'suspend_machine' in self.dmesg:
1180 self.tKernSus) * 1000 1221 sktime = (self.dmesg['suspend_machine']['end'] - \
1181 rktime = (self.dmesg['resume_complete']['end'] - \ 1222 self.tKernSus) * 1000
1182 self.dmesg['resume_machine']['start']) * 1000 1223 else:
1224 sktime = (self.tSuspended - self.tKernSus) * 1000
1225 if 'resume_machine' in self.dmesg:
1226 rktime = (self.tKernRes - \
1227 self.dmesg['resume_machine']['start']) * 1000
1228 else:
1229 rktime = (self.tKernRes - self.tResumed) * 1000
1183 return (sktime, rktime) 1230 return (sktime, rktime)
1184 def setPhase(self, phase, ktime, isbegin): 1231 def setPhase(self, phase, ktime, isbegin, order=-1):
1185 if(isbegin): 1232 if(isbegin):
1233 # phase start over current phase
1234 if self.currphase:
1235 if 'resume_machine' not in self.currphase:
1236 sysvals.vprint('WARNING: phase %s failed to end' % self.currphase)
1237 self.dmesg[self.currphase]['end'] = ktime
1238 phases = self.dmesg.keys()
1239 color = self.phasedef[phase]['color']
1240 count = len(phases) if order < 0 else order
1241 # create unique name for every new phase
1242 while phase in phases:
1243 phase += '*'
1244 self.dmesg[phase] = {'list': dict(), 'start': -1.0, 'end': -1.0,
1245 'row': 0, 'color': color, 'order': count}
1186 self.dmesg[phase]['start'] = ktime 1246 self.dmesg[phase]['start'] = ktime
1247 self.currphase = phase
1187 else: 1248 else:
1249 # phase end without a start
1250 if phase not in self.currphase:
1251 if self.currphase:
1252 sysvals.vprint('WARNING: %s ended instead of %s, ftrace corruption?' % (phase, self.currphase))
1253 else:
1254 sysvals.vprint('WARNING: %s ended without a start, ftrace corruption?' % phase)
1255 return phase
1256 phase = self.currphase
1188 self.dmesg[phase]['end'] = ktime 1257 self.dmesg[phase]['end'] = ktime
1189 def dmesgSortVal(self, phase): 1258 self.currphase = ''
1190 return self.dmesg[phase]['order'] 1259 return phase
1191 def sortedPhases(self):
1192 return sorted(self.dmesg, key=self.dmesgSortVal)
1193 def sortedDevices(self, phase): 1260 def sortedDevices(self, phase):
1194 list = self.dmesg[phase]['list'] 1261 list = self.dmesg[phase]['list']
1195 slist = [] 1262 slist = []
@@ -1208,13 +1275,13 @@ class Data:
1208 for devname in phaselist: 1275 for devname in phaselist:
1209 dev = phaselist[devname] 1276 dev = phaselist[devname]
1210 if(dev['end'] < 0): 1277 if(dev['end'] < 0):
1211 for p in self.phases: 1278 for p in self.sortedPhases():
1212 if self.dmesg[p]['end'] > dev['start']: 1279 if self.dmesg[p]['end'] > dev['start']:
1213 dev['end'] = self.dmesg[p]['end'] 1280 dev['end'] = self.dmesg[p]['end']
1214 break 1281 break
1215 sysvals.vprint('%s (%s): callback didnt return' % (devname, phase)) 1282 sysvals.vprint('%s (%s): callback didnt return' % (devname, phase))
1216 def deviceFilter(self, devicefilter): 1283 def deviceFilter(self, devicefilter):
1217 for phase in self.phases: 1284 for phase in self.sortedPhases():
1218 list = self.dmesg[phase]['list'] 1285 list = self.dmesg[phase]['list']
1219 rmlist = [] 1286 rmlist = []
1220 for name in list: 1287 for name in list:
@@ -1229,7 +1296,7 @@ class Data:
1229 del list[name] 1296 del list[name]
1230 def fixupInitcallsThatDidntReturn(self): 1297 def fixupInitcallsThatDidntReturn(self):
1231 # if any calls never returned, clip them at system resume end 1298 # if any calls never returned, clip them at system resume end
1232 for phase in self.phases: 1299 for phase in self.sortedPhases():
1233 self.fixupInitcalls(phase) 1300 self.fixupInitcalls(phase)
1234 def phaseOverlap(self, phases): 1301 def phaseOverlap(self, phases):
1235 rmgroups = [] 1302 rmgroups = []
@@ -1248,17 +1315,18 @@ class Data:
1248 self.devicegroups.append(newgroup) 1315 self.devicegroups.append(newgroup)
1249 def newActionGlobal(self, name, start, end, pid=-1, color=''): 1316 def newActionGlobal(self, name, start, end, pid=-1, color=''):
1250 # which phase is this device callback or action in 1317 # which phase is this device callback or action in
1318 phases = self.sortedPhases()
1251 targetphase = 'none' 1319 targetphase = 'none'
1252 htmlclass = '' 1320 htmlclass = ''
1253 overlap = 0.0 1321 overlap = 0.0
1254 phases = [] 1322 myphases = []
1255 for phase in self.phases: 1323 for phase in phases:
1256 pstart = self.dmesg[phase]['start'] 1324 pstart = self.dmesg[phase]['start']
1257 pend = self.dmesg[phase]['end'] 1325 pend = self.dmesg[phase]['end']
1258 # see if the action overlaps this phase 1326 # see if the action overlaps this phase
1259 o = max(0, min(end, pend) - max(start, pstart)) 1327 o = max(0, min(end, pend) - max(start, pstart))
1260 if o > 0: 1328 if o > 0:
1261 phases.append(phase) 1329 myphases.append(phase)
1262 # set the target phase to the one that overlaps most 1330 # set the target phase to the one that overlaps most
1263 if o > overlap: 1331 if o > overlap:
1264 if overlap > 0 and phase == 'post_resume': 1332 if overlap > 0 and phase == 'post_resume':
@@ -1267,19 +1335,19 @@ class Data:
1267 overlap = o 1335 overlap = o
1268 # if no target phase was found, pin it to the edge 1336 # if no target phase was found, pin it to the edge
1269 if targetphase == 'none': 1337 if targetphase == 'none':
1270 p0start = self.dmesg[self.phases[0]]['start'] 1338 p0start = self.dmesg[phases[0]]['start']
1271 if start <= p0start: 1339 if start <= p0start:
1272 targetphase = self.phases[0] 1340 targetphase = phases[0]
1273 else: 1341 else:
1274 targetphase = self.phases[-1] 1342 targetphase = phases[-1]
1275 if pid == -2: 1343 if pid == -2:
1276 htmlclass = ' bg' 1344 htmlclass = ' bg'
1277 elif pid == -3: 1345 elif pid == -3:
1278 htmlclass = ' ps' 1346 htmlclass = ' ps'
1279 if len(phases) > 1: 1347 if len(myphases) > 1:
1280 htmlclass = ' bg' 1348 htmlclass = ' bg'
1281 self.phaseOverlap(phases) 1349 self.phaseOverlap(myphases)
1282 if targetphase in self.phases: 1350 if targetphase in phases:
1283 newname = self.newAction(targetphase, name, pid, '', start, end, '', htmlclass, color) 1351 newname = self.newAction(targetphase, name, pid, '', start, end, '', htmlclass, color)
1284 return (targetphase, newname) 1352 return (targetphase, newname)
1285 return False 1353 return False
@@ -1315,7 +1383,7 @@ class Data:
1315 sysvals.vprint('Timeline Details:') 1383 sysvals.vprint('Timeline Details:')
1316 sysvals.vprint(' test start: %f' % self.start) 1384 sysvals.vprint(' test start: %f' % self.start)
1317 sysvals.vprint('kernel suspend start: %f' % self.tKernSus) 1385 sysvals.vprint('kernel suspend start: %f' % self.tKernSus)
1318 for phase in self.phases: 1386 for phase in self.sortedPhases():
1319 dc = len(self.dmesg[phase]['list']) 1387 dc = len(self.dmesg[phase]['list'])
1320 sysvals.vprint(' %16s: %f - %f (%d devices)' % (phase, \ 1388 sysvals.vprint(' %16s: %f - %f (%d devices)' % (phase, \
1321 self.dmesg[phase]['start'], self.dmesg[phase]['end'], dc)) 1389 self.dmesg[phase]['start'], self.dmesg[phase]['end'], dc))
@@ -1323,7 +1391,7 @@ class Data:
1323 sysvals.vprint(' test end: %f' % self.end) 1391 sysvals.vprint(' test end: %f' % self.end)
1324 def deviceChildrenAllPhases(self, devname): 1392 def deviceChildrenAllPhases(self, devname):
1325 devlist = [] 1393 devlist = []
1326 for phase in self.phases: 1394 for phase in self.sortedPhases():
1327 list = self.deviceChildren(devname, phase) 1395 list = self.deviceChildren(devname, phase)
1328 for dev in list: 1396 for dev in list:
1329 if dev not in devlist: 1397 if dev not in devlist:
@@ -1344,7 +1412,7 @@ class Data:
1344 if node.name: 1412 if node.name:
1345 info = '' 1413 info = ''
1346 drv = '' 1414 drv = ''
1347 for phase in self.phases: 1415 for phase in self.sortedPhases():
1348 list = self.dmesg[phase]['list'] 1416 list = self.dmesg[phase]['list']
1349 if node.name in list: 1417 if node.name in list:
1350 s = list[node.name]['start'] 1418 s = list[node.name]['start']
@@ -1478,8 +1546,29 @@ class Data:
1478 c = self.addProcessUsageEvent(ps, tres) 1546 c = self.addProcessUsageEvent(ps, tres)
1479 if c > 0: 1547 if c > 0:
1480 sysvals.vprint('%25s (res): %d' % (ps, c)) 1548 sysvals.vprint('%25s (res): %d' % (ps, c))
1549 def handleEndMarker(self, time):
1550 dm = self.dmesg
1551 self.setEnd(time)
1552 self.initDevicegroups()
1553 # give suspend_prepare an end if needed
1554 if 'suspend_prepare' in dm and dm['suspend_prepare']['end'] < 0:
1555 dm['suspend_prepare']['end'] = time
1556 # assume resume machine ends at next phase start
1557 if 'resume_machine' in dm and dm['resume_machine']['end'] < 0:
1558 np = self.nextPhase('resume_machine', 1)
1559 if np:
1560 dm['resume_machine']['end'] = dm[np]['start']
1561 # if kernel resume end not found, assume its the end marker
1562 if self.tKernRes == 0.0:
1563 self.tKernRes = time
1564 # if kernel suspend start not found, assume its the end marker
1565 if self.tKernSus == 0.0:
1566 self.tKernSus = time
1567 # set resume complete to end at end marker
1568 if 'resume_complete' in dm:
1569 dm['resume_complete']['end'] = time
1481 def debugPrint(self): 1570 def debugPrint(self):
1482 for p in self.phases: 1571 for p in self.sortedPhases():
1483 list = self.dmesg[p]['list'] 1572 list = self.dmesg[p]['list']
1484 for devname in list: 1573 for devname in list:
1485 dev = list[devname] 1574 dev = list[devname]
@@ -1490,9 +1579,9 @@ class Data:
1490# Description: 1579# Description:
1491# A container for kprobe function data we want in the dev timeline 1580# A container for kprobe function data we want in the dev timeline
1492class DevFunction: 1581class DevFunction:
1493 row = 0
1494 count = 1
1495 def __init__(self, name, args, caller, ret, start, end, u, proc, pid, color): 1582 def __init__(self, name, args, caller, ret, start, end, u, proc, pid, color):
1583 self.row = 0
1584 self.count = 1
1496 self.name = name 1585 self.name = name
1497 self.args = args 1586 self.args = args
1498 self.caller = caller 1587 self.caller = caller
@@ -1546,16 +1635,15 @@ class DevFunction:
1546# suspend_resume: phase or custom exec block data 1635# suspend_resume: phase or custom exec block data
1547# device_pm_callback: device callback info 1636# device_pm_callback: device callback info
1548class FTraceLine: 1637class FTraceLine:
1549 time = 0.0
1550 length = 0.0
1551 fcall = False
1552 freturn = False
1553 fevent = False
1554 fkprobe = False
1555 depth = 0
1556 name = ''
1557 type = ''
1558 def __init__(self, t, m='', d=''): 1638 def __init__(self, t, m='', d=''):
1639 self.length = 0.0
1640 self.fcall = False
1641 self.freturn = False
1642 self.fevent = False
1643 self.fkprobe = False
1644 self.depth = 0
1645 self.name = ''
1646 self.type = ''
1559 self.time = float(t) 1647 self.time = float(t)
1560 if not m and not d: 1648 if not m and not d:
1561 return 1649 return
@@ -1675,19 +1763,13 @@ class FTraceLine:
1675# Each instance is tied to a single device in a single phase, and is 1763# Each instance is tied to a single device in a single phase, and is
1676# comprised of an ordered list of FTraceLine objects 1764# comprised of an ordered list of FTraceLine objects
1677class FTraceCallGraph: 1765class FTraceCallGraph:
1678 id = ''
1679 start = -1.0
1680 end = -1.0
1681 list = []
1682 invalid = False
1683 depth = 0
1684 pid = 0
1685 name = ''
1686 partial = False
1687 vfname = 'missing_function_name' 1766 vfname = 'missing_function_name'
1688 ignore = False
1689 sv = 0
1690 def __init__(self, pid, sv): 1767 def __init__(self, pid, sv):
1768 self.id = ''
1769 self.invalid = False
1770 self.name = ''
1771 self.partial = False
1772 self.ignore = False
1691 self.start = -1.0 1773 self.start = -1.0
1692 self.end = -1.0 1774 self.end = -1.0
1693 self.list = [] 1775 self.list = []
@@ -1943,7 +2025,7 @@ class FTraceCallGraph:
1943 dev['ftrace'] = cg 2025 dev['ftrace'] = cg
1944 found = devname 2026 found = devname
1945 return found 2027 return found
1946 for p in data.phases: 2028 for p in data.sortedPhases():
1947 if(data.dmesg[p]['start'] <= self.start and 2029 if(data.dmesg[p]['start'] <= self.start and
1948 self.start <= data.dmesg[p]['end']): 2030 self.start <= data.dmesg[p]['end']):
1949 list = data.dmesg[p]['list'] 2031 list = data.dmesg[p]['list']
@@ -1966,7 +2048,7 @@ class FTraceCallGraph:
1966 if fs < data.start or fe > data.end: 2048 if fs < data.start or fe > data.end:
1967 return 2049 return
1968 phase = '' 2050 phase = ''
1969 for p in data.phases: 2051 for p in data.sortedPhases():
1970 if(data.dmesg[p]['start'] <= self.start and 2052 if(data.dmesg[p]['start'] <= self.start and
1971 self.start < data.dmesg[p]['end']): 2053 self.start < data.dmesg[p]['end']):
1972 phase = p 2054 phase = p
@@ -2008,23 +2090,20 @@ class DevItem:
2008# A container for a device timeline which calculates 2090# A container for a device timeline which calculates
2009# all the html properties to display it correctly 2091# all the html properties to display it correctly
2010class Timeline: 2092class Timeline:
2011 html = ''
2012 height = 0 # total timeline height
2013 scaleH = 20 # timescale (top) row height
2014 rowH = 30 # device row height
2015 bodyH = 0 # body height
2016 rows = 0 # total timeline rows
2017 rowlines = dict()
2018 rowheight = dict()
2019 html_tblock = '<div id="block{0}" class="tblock" style="left:{1}%;width:{2}%;"><div class="tback" style="height:{3}px"></div>\n' 2093 html_tblock = '<div id="block{0}" class="tblock" style="left:{1}%;width:{2}%;"><div class="tback" style="height:{3}px"></div>\n'
2020 html_device = '<div id="{0}" title="{1}" class="thread{7}" style="left:{2}%;top:{3}px;height:{4}px;width:{5}%;{8}">{6}</div>\n' 2094 html_device = '<div id="{0}" title="{1}" class="thread{7}" style="left:{2}%;top:{3}px;height:{4}px;width:{5}%;{8}">{6}</div>\n'
2021 html_phase = '<div class="phase" style="left:{0}%;width:{1}%;top:{2}px;height:{3}px;background:{4}">{5}</div>\n' 2095 html_phase = '<div class="phase" style="left:{0}%;width:{1}%;top:{2}px;height:{3}px;background:{4}">{5}</div>\n'
2022 html_phaselet = '<div id="{0}" class="phaselet" style="left:{1}%;width:{2}%;background:{3}"></div>\n' 2096 html_phaselet = '<div id="{0}" class="phaselet" style="left:{1}%;width:{2}%;background:{3}"></div>\n'
2023 html_legend = '<div id="p{3}" class="square" style="left:{0}%;background:{1}">&nbsp;{2}</div>\n' 2097 html_legend = '<div id="p{3}" class="square" style="left:{0}%;background:{1}">&nbsp;{2}</div>\n'
2024 def __init__(self, rowheight, scaleheight): 2098 def __init__(self, rowheight, scaleheight):
2025 self.rowH = rowheight
2026 self.scaleH = scaleheight
2027 self.html = '' 2099 self.html = ''
2100 self.height = 0 # total timeline height
2101 self.scaleH = scaleheight # timescale (top) row height
2102 self.rowH = rowheight # device row height
2103 self.bodyH = 0 # body height
2104 self.rows = 0 # total timeline rows
2105 self.rowlines = dict()
2106 self.rowheight = dict()
2028 def createHeader(self, sv, stamp): 2107 def createHeader(self, sv, stamp):
2029 if(not stamp['time']): 2108 if(not stamp['time']):
2030 return 2109 return
@@ -2251,18 +2330,18 @@ class Timeline:
2251# Description: 2330# Description:
2252# A list of values describing the properties of these test runs 2331# A list of values describing the properties of these test runs
2253class TestProps: 2332class TestProps:
2254 stamp = ''
2255 sysinfo = ''
2256 cmdline = ''
2257 kparams = ''
2258 S0i3 = False
2259 fwdata = []
2260 stampfmt = '# [a-z]*-(?P<m>[0-9]{2})(?P<d>[0-9]{2})(?P<y>[0-9]{2})-'+\ 2333 stampfmt = '# [a-z]*-(?P<m>[0-9]{2})(?P<d>[0-9]{2})(?P<y>[0-9]{2})-'+\
2261 '(?P<H>[0-9]{2})(?P<M>[0-9]{2})(?P<S>[0-9]{2})'+\ 2334 '(?P<H>[0-9]{2})(?P<M>[0-9]{2})(?P<S>[0-9]{2})'+\
2262 ' (?P<host>.*) (?P<mode>.*) (?P<kernel>.*)$' 2335 ' (?P<host>.*) (?P<mode>.*) (?P<kernel>.*)$'
2336 batteryfmt = '^# battery (?P<a1>\w*) (?P<c1>\d*) (?P<a2>\w*) (?P<c2>\d*)'
2337 testerrfmt = '^# enter_sleep_error (?P<e>.*)'
2263 sysinfofmt = '^# sysinfo .*' 2338 sysinfofmt = '^# sysinfo .*'
2264 cmdlinefmt = '^# command \| (?P<cmd>.*)' 2339 cmdlinefmt = '^# command \| (?P<cmd>.*)'
2265 kparamsfmt = '^# kparams \| (?P<kp>.*)' 2340 kparamsfmt = '^# kparams \| (?P<kp>.*)'
2341 devpropfmt = '# Device Properties: .*'
2342 tracertypefmt = '# tracer: (?P<t>.*)'
2343 firmwarefmt = '# fwsuspend (?P<s>[0-9]*) fwresume (?P<r>[0-9]*)$'
2344 procexecfmt = 'ps - (?P<ps>.*)$'
2266 ftrace_line_fmt_fg = \ 2345 ftrace_line_fmt_fg = \
2267 '^ *(?P<time>[0-9\.]*) *\| *(?P<cpu>[0-9]*)\)'+\ 2346 '^ *(?P<time>[0-9\.]*) *\| *(?P<cpu>[0-9]*)\)'+\
2268 ' *(?P<proc>.*)-(?P<pid>[0-9]*) *\|'+\ 2347 ' *(?P<proc>.*)-(?P<pid>[0-9]*) *\|'+\
@@ -2271,11 +2350,17 @@ class TestProps:
2271 ' *(?P<proc>.*)-(?P<pid>[0-9]*) *\[(?P<cpu>[0-9]*)\] *'+\ 2350 ' *(?P<proc>.*)-(?P<pid>[0-9]*) *\[(?P<cpu>[0-9]*)\] *'+\
2272 '(?P<flags>.{4}) *(?P<time>[0-9\.]*): *'+\ 2351 '(?P<flags>.{4}) *(?P<time>[0-9\.]*): *'+\
2273 '(?P<msg>.*)' 2352 '(?P<msg>.*)'
2274 ftrace_line_fmt = ftrace_line_fmt_nop
2275 cgformat = False
2276 data = 0
2277 ktemp = dict()
2278 def __init__(self): 2353 def __init__(self):
2354 self.stamp = ''
2355 self.sysinfo = ''
2356 self.cmdline = ''
2357 self.kparams = ''
2358 self.testerror = []
2359 self.battery = []
2360 self.fwdata = []
2361 self.ftrace_line_fmt = self.ftrace_line_fmt_nop
2362 self.cgformat = False
2363 self.data = 0
2279 self.ktemp = dict() 2364 self.ktemp = dict()
2280 def setTracerType(self, tracer): 2365 def setTracerType(self, tracer):
2281 if(tracer == 'function_graph'): 2366 if(tracer == 'function_graph'):
@@ -2286,6 +2371,7 @@ class TestProps:
2286 else: 2371 else:
2287 doError('Invalid tracer format: [%s]' % tracer) 2372 doError('Invalid tracer format: [%s]' % tracer)
2288 def parseStamp(self, data, sv): 2373 def parseStamp(self, data, sv):
2374 # global test data
2289 m = re.match(self.stampfmt, self.stamp) 2375 m = re.match(self.stampfmt, self.stamp)
2290 data.stamp = {'time': '', 'host': '', 'mode': ''} 2376 data.stamp = {'time': '', 'host': '', 'mode': ''}
2291 dt = datetime(int(m.group('y'))+2000, int(m.group('m')), 2377 dt = datetime(int(m.group('y'))+2000, int(m.group('m')),
@@ -2324,23 +2410,36 @@ class TestProps:
2324 sv.kparams = m.group('kp') 2410 sv.kparams = m.group('kp')
2325 if not sv.stamp: 2411 if not sv.stamp:
2326 sv.stamp = data.stamp 2412 sv.stamp = data.stamp
2413 # firmware data
2414 if sv.suspendmode == 'mem' and len(self.fwdata) > data.testnumber:
2415 data.fwSuspend, data.fwResume = self.fwdata[data.testnumber]
2416 if(data.fwSuspend > 0 or data.fwResume > 0):
2417 data.fwValid = True
2418 # battery data
2419 if len(self.battery) > data.testnumber:
2420 m = re.match(self.batteryfmt, self.battery[data.testnumber])
2421 if m:
2422 data.battery = m.groups()
2423 # sleep mode enter errors
2424 if len(self.testerror) > data.testnumber:
2425 m = re.match(self.testerrfmt, self.testerror[data.testnumber])
2426 if m:
2427 data.enterfail = m.group('e')
2327 2428
2328# Class: TestRun 2429# Class: TestRun
2329# Description: 2430# Description:
2330# A container for a suspend/resume test run. This is necessary as 2431# A container for a suspend/resume test run. This is necessary as
2331# there could be more than one, and they need to be separate. 2432# there could be more than one, and they need to be separate.
2332class TestRun: 2433class TestRun:
2333 ftemp = dict()
2334 ttemp = dict()
2335 data = 0
2336 def __init__(self, dataobj): 2434 def __init__(self, dataobj):
2337 self.data = dataobj 2435 self.data = dataobj
2338 self.ftemp = dict() 2436 self.ftemp = dict()
2339 self.ttemp = dict() 2437 self.ttemp = dict()
2340 2438
2341class ProcessMonitor: 2439class ProcessMonitor:
2342 proclist = dict() 2440 def __init__(self):
2343 running = False 2441 self.proclist = dict()
2442 self.running = False
2344 def procstat(self): 2443 def procstat(self):
2345 c = ['cat /proc/[1-9]*/stat 2>/dev/null'] 2444 c = ['cat /proc/[1-9]*/stat 2>/dev/null']
2346 process = Popen(c, shell=True, stdout=PIPE) 2445 process = Popen(c, shell=True, stdout=PIPE)
@@ -2391,8 +2490,8 @@ class ProcessMonitor:
2391# markers, and/or kprobes required for primary parsing. 2490# markers, and/or kprobes required for primary parsing.
2392def doesTraceLogHaveTraceEvents(): 2491def doesTraceLogHaveTraceEvents():
2393 kpcheck = ['_cal: (', '_cpu_down()'] 2492 kpcheck = ['_cal: (', '_cpu_down()']
2394 techeck = ['suspend_resume'] 2493 techeck = ['suspend_resume', 'device_pm_callback']
2395 tmcheck = ['SUSPEND START', 'RESUME COMPLETE'] 2494 tmcheck = ['tracing_mark_write']
2396 sysvals.usekprobes = False 2495 sysvals.usekprobes = False
2397 fp = sysvals.openlog(sysvals.ftracefile, 'r') 2496 fp = sysvals.openlog(sysvals.ftracefile, 'r')
2398 for line in fp: 2497 for line in fp:
@@ -2414,23 +2513,14 @@ def doesTraceLogHaveTraceEvents():
2414 check.remove(i) 2513 check.remove(i)
2415 tmcheck = check 2514 tmcheck = check
2416 fp.close() 2515 fp.close()
2417 if len(techeck) == 0: 2516 sysvals.usetraceevents = True if len(techeck) < 2 else False
2418 sysvals.usetraceevents = True 2517 sysvals.usetracemarkers = True if len(tmcheck) == 0 else False
2419 else:
2420 sysvals.usetraceevents = False
2421 if len(tmcheck) == 0:
2422 sysvals.usetracemarkers = True
2423 else:
2424 sysvals.usetracemarkers = False
2425 2518
2426# Function: appendIncompleteTraceLog 2519# Function: appendIncompleteTraceLog
2427# Description: 2520# Description:
2428# [deprecated for kernel 3.15 or newer] 2521# [deprecated for kernel 3.15 or newer]
2429# Legacy support of ftrace outputs that lack the device_pm_callback 2522# Adds callgraph data which lacks trace event data. This is only
2430# and/or suspend_resume trace events. The primary data should be 2523# for timelines generated from 3.15 or older
2431# taken from dmesg, and this ftrace is used only for callgraph data
2432# or custom actions in the timeline. The data is appended to the Data
2433# objects provided.
2434# Arguments: 2524# Arguments:
2435# testruns: the array of Data objects obtained from parseKernelLog 2525# testruns: the array of Data objects obtained from parseKernelLog
2436def appendIncompleteTraceLog(testruns): 2526def appendIncompleteTraceLog(testruns):
@@ -2460,13 +2550,19 @@ def appendIncompleteTraceLog(testruns):
2460 elif re.match(tp.cmdlinefmt, line): 2550 elif re.match(tp.cmdlinefmt, line):
2461 tp.cmdline = line 2551 tp.cmdline = line
2462 continue 2552 continue
2553 elif re.match(tp.batteryfmt, line):
2554 tp.battery.append(line)
2555 continue
2556 elif re.match(tp.testerrfmt, line):
2557 tp.testerror.append(line)
2558 continue
2463 # determine the trace data type (required for further parsing) 2559 # determine the trace data type (required for further parsing)
2464 m = re.match(sysvals.tracertypefmt, line) 2560 m = re.match(tp.tracertypefmt, line)
2465 if(m): 2561 if(m):
2466 tp.setTracerType(m.group('t')) 2562 tp.setTracerType(m.group('t'))
2467 continue 2563 continue
2468 # device properties line 2564 # device properties line
2469 if(re.match(sysvals.devpropfmt, line)): 2565 if(re.match(tp.devpropfmt, line)):
2470 devProps(line) 2566 devProps(line)
2471 continue 2567 continue
2472 # parse only valid lines, if this is not one move on 2568 # parse only valid lines, if this is not one move on
@@ -2506,87 +2602,7 @@ def appendIncompleteTraceLog(testruns):
2506 continue 2602 continue
2507 # trace event processing 2603 # trace event processing
2508 if(t.fevent): 2604 if(t.fevent):
2509 # general trace events have two types, begin and end 2605 continue
2510 if(re.match('(?P<name>.*) begin$', t.name)):
2511 isbegin = True
2512 elif(re.match('(?P<name>.*) end$', t.name)):
2513 isbegin = False
2514 else:
2515 continue
2516 m = re.match('(?P<name>.*)\[(?P<val>[0-9]*)\] .*', t.name)
2517 if(m):
2518 val = m.group('val')
2519 if val == '0':
2520 name = m.group('name')
2521 else:
2522 name = m.group('name')+'['+val+']'
2523 else:
2524 m = re.match('(?P<name>.*) .*', t.name)
2525 name = m.group('name')
2526 # special processing for trace events
2527 if re.match('dpm_prepare\[.*', name):
2528 continue
2529 elif re.match('machine_suspend.*', name):
2530 continue
2531 elif re.match('suspend_enter\[.*', name):
2532 if(not isbegin):
2533 data.dmesg['suspend_prepare']['end'] = t.time
2534 continue
2535 elif re.match('dpm_suspend\[.*', name):
2536 if(not isbegin):
2537 data.dmesg['suspend']['end'] = t.time
2538 continue
2539 elif re.match('dpm_suspend_late\[.*', name):
2540 if(isbegin):
2541 data.dmesg['suspend_late']['start'] = t.time
2542 else:
2543 data.dmesg['suspend_late']['end'] = t.time
2544 continue
2545 elif re.match('dpm_suspend_noirq\[.*', name):
2546 if(isbegin):
2547 data.dmesg['suspend_noirq']['start'] = t.time
2548 else:
2549 data.dmesg['suspend_noirq']['end'] = t.time
2550 continue
2551 elif re.match('dpm_resume_noirq\[.*', name):
2552 if(isbegin):
2553 data.dmesg['resume_machine']['end'] = t.time
2554 data.dmesg['resume_noirq']['start'] = t.time
2555 else:
2556 data.dmesg['resume_noirq']['end'] = t.time
2557 continue
2558 elif re.match('dpm_resume_early\[.*', name):
2559 if(isbegin):
2560 data.dmesg['resume_early']['start'] = t.time
2561 else:
2562 data.dmesg['resume_early']['end'] = t.time
2563 continue
2564 elif re.match('dpm_resume\[.*', name):
2565 if(isbegin):
2566 data.dmesg['resume']['start'] = t.time
2567 else:
2568 data.dmesg['resume']['end'] = t.time
2569 continue
2570 elif re.match('dpm_complete\[.*', name):
2571 if(isbegin):
2572 data.dmesg['resume_complete']['start'] = t.time
2573 else:
2574 data.dmesg['resume_complete']['end'] = t.time
2575 continue
2576 # skip trace events inside devices calls
2577 if(not data.isTraceEventOutsideDeviceCalls(pid, t.time)):
2578 continue
2579 # global events (outside device calls) are simply graphed
2580 if(isbegin):
2581 # store each trace event in ttemp
2582 if(name not in testrun[testidx].ttemp):
2583 testrun[testidx].ttemp[name] = []
2584 testrun[testidx].ttemp[name].append(\
2585 {'begin': t.time, 'end': t.time})
2586 else:
2587 # finish off matching trace event in ttemp
2588 if(name in testrun[testidx].ttemp):
2589 testrun[testidx].ttemp[name][-1]['end'] = t.time
2590 # call/return processing 2606 # call/return processing
2591 elif sysvals.usecallgraph: 2607 elif sysvals.usecallgraph:
2592 # create a callgraph object for the data 2608 # create a callgraph object for the data
@@ -2603,12 +2619,6 @@ def appendIncompleteTraceLog(testruns):
2603 tf.close() 2619 tf.close()
2604 2620
2605 for test in testrun: 2621 for test in testrun:
2606 # add the traceevent data to the device hierarchy
2607 if(sysvals.usetraceevents):
2608 for name in test.ttemp:
2609 for event in test.ttemp[name]:
2610 test.data.newActionGlobal(name, event['begin'], event['end'])
2611
2612 # add the callgraph data to the device hierarchy 2622 # add the callgraph data to the device hierarchy
2613 for pid in test.ftemp: 2623 for pid in test.ftemp:
2614 for cg in test.ftemp[pid]: 2624 for cg in test.ftemp[pid]:
@@ -2621,7 +2631,7 @@ def appendIncompleteTraceLog(testruns):
2621 continue 2631 continue
2622 callstart = cg.start 2632 callstart = cg.start
2623 callend = cg.end 2633 callend = cg.end
2624 for p in test.data.phases: 2634 for p in test.data.sortedPhases():
2625 if(test.data.dmesg[p]['start'] <= callstart and 2635 if(test.data.dmesg[p]['start'] <= callstart and
2626 callstart <= test.data.dmesg[p]['end']): 2636 callstart <= test.data.dmesg[p]['end']):
2627 list = test.data.dmesg[p]['list'] 2637 list = test.data.dmesg[p]['list']
@@ -2648,10 +2658,12 @@ def parseTraceLog(live=False):
2648 doError('%s does not exist' % sysvals.ftracefile) 2658 doError('%s does not exist' % sysvals.ftracefile)
2649 if not live: 2659 if not live:
2650 sysvals.setupAllKprobes() 2660 sysvals.setupAllKprobes()
2661 krescalls = ['pm_notifier_call_chain', 'pm_restore_console']
2651 tracewatch = [] 2662 tracewatch = []
2652 if sysvals.usekprobes: 2663 if sysvals.usekprobes:
2653 tracewatch += ['sync_filesystems', 'freeze_processes', 'syscore_suspend', 2664 tracewatch += ['sync_filesystems', 'freeze_processes', 'syscore_suspend',
2654 'syscore_resume', 'resume_console', 'thaw_processes', 'CPU_ON', 'CPU_OFF'] 2665 'syscore_resume', 'resume_console', 'thaw_processes', 'CPU_ON',
2666 'CPU_OFF', 'timekeeping_freeze', 'acpi_suspend']
2655 2667
2656 # extract the callgraph and traceevent data 2668 # extract the callgraph and traceevent data
2657 tp = TestProps() 2669 tp = TestProps()
@@ -2674,18 +2686,24 @@ def parseTraceLog(live=False):
2674 elif re.match(tp.cmdlinefmt, line): 2686 elif re.match(tp.cmdlinefmt, line):
2675 tp.cmdline = line 2687 tp.cmdline = line
2676 continue 2688 continue
2689 elif re.match(tp.batteryfmt, line):
2690 tp.battery.append(line)
2691 continue
2692 elif re.match(tp.testerrfmt, line):
2693 tp.testerror.append(line)
2694 continue
2677 # firmware line: pull out any firmware data 2695 # firmware line: pull out any firmware data
2678 m = re.match(sysvals.firmwarefmt, line) 2696 m = re.match(tp.firmwarefmt, line)
2679 if(m): 2697 if(m):
2680 tp.fwdata.append((int(m.group('s')), int(m.group('r')))) 2698 tp.fwdata.append((int(m.group('s')), int(m.group('r'))))
2681 continue 2699 continue
2682 # tracer type line: determine the trace data type 2700 # tracer type line: determine the trace data type
2683 m = re.match(sysvals.tracertypefmt, line) 2701 m = re.match(tp.tracertypefmt, line)
2684 if(m): 2702 if(m):
2685 tp.setTracerType(m.group('t')) 2703 tp.setTracerType(m.group('t'))
2686 continue 2704 continue
2687 # device properties line 2705 # device properties line
2688 if(re.match(sysvals.devpropfmt, line)): 2706 if(re.match(tp.devpropfmt, line)):
2689 devProps(line) 2707 devProps(line)
2690 continue 2708 continue
2691 # ignore all other commented lines 2709 # ignore all other commented lines
@@ -2714,20 +2732,19 @@ def parseTraceLog(live=False):
2714 continue 2732 continue
2715 # find the start of suspend 2733 # find the start of suspend
2716 if(t.startMarker()): 2734 if(t.startMarker()):
2717 phase = 'suspend_prepare'
2718 data = Data(len(testdata)) 2735 data = Data(len(testdata))
2719 testdata.append(data) 2736 testdata.append(data)
2720 testrun = TestRun(data) 2737 testrun = TestRun(data)
2721 testruns.append(testrun) 2738 testruns.append(testrun)
2722 tp.parseStamp(data, sysvals) 2739 tp.parseStamp(data, sysvals)
2723 data.setStart(t.time) 2740 data.setStart(t.time)
2724 data.tKernSus = t.time 2741 phase = data.setPhase('suspend_prepare', t.time, True)
2725 continue 2742 continue
2726 if(not data): 2743 if(not data):
2727 continue 2744 continue
2728 # process cpu exec line 2745 # process cpu exec line
2729 if t.type == 'tracing_mark_write': 2746 if t.type == 'tracing_mark_write':
2730 m = re.match(sysvals.procexecfmt, t.name) 2747 m = re.match(tp.procexecfmt, t.name)
2731 if(m): 2748 if(m):
2732 proclist = dict() 2749 proclist = dict()
2733 for ps in m.group('ps').split(','): 2750 for ps in m.group('ps').split(','):
@@ -2740,28 +2757,17 @@ def parseTraceLog(live=False):
2740 continue 2757 continue
2741 # find the end of resume 2758 # find the end of resume
2742 if(t.endMarker()): 2759 if(t.endMarker()):
2743 data.setEnd(t.time) 2760 data.handleEndMarker(t.time)
2744 if data.tKernRes == 0.0:
2745 data.tKernRes = t.time
2746 if data.dmesg['resume_complete']['end'] < 0:
2747 data.dmesg['resume_complete']['end'] = t.time
2748 if sysvals.suspendmode == 'mem' and len(tp.fwdata) > data.testnumber:
2749 data.fwSuspend, data.fwResume = tp.fwdata[data.testnumber]
2750 if(data.tSuspended != 0 and data.tResumed != 0 and \
2751 (data.fwSuspend > 0 or data.fwResume > 0)):
2752 data.fwValid = True
2753 if(not sysvals.usetracemarkers): 2761 if(not sysvals.usetracemarkers):
2754 # no trace markers? then quit and be sure to finish recording 2762 # no trace markers? then quit and be sure to finish recording
2755 # the event we used to trigger resume end 2763 # the event we used to trigger resume end
2756 if(len(testrun.ttemp['thaw_processes']) > 0): 2764 if('thaw_processes' in testrun.ttemp and len(testrun.ttemp['thaw_processes']) > 0):
2757 # if an entry exists, assume this is its end 2765 # if an entry exists, assume this is its end
2758 testrun.ttemp['thaw_processes'][-1]['end'] = t.time 2766 testrun.ttemp['thaw_processes'][-1]['end'] = t.time
2759 break 2767 break
2760 continue 2768 continue
2761 # trace event processing 2769 # trace event processing
2762 if(t.fevent): 2770 if(t.fevent):
2763 if(phase == 'post_resume'):
2764 data.setEnd(t.time)
2765 if(t.type == 'suspend_resume'): 2771 if(t.type == 'suspend_resume'):
2766 # suspend_resume trace events have two types, begin and end 2772 # suspend_resume trace events have two types, begin and end
2767 if(re.match('(?P<name>.*) begin$', t.name)): 2773 if(re.match('(?P<name>.*) begin$', t.name)):
@@ -2786,86 +2792,61 @@ def parseTraceLog(live=False):
2786 # -- phase changes -- 2792 # -- phase changes --
2787 # start of kernel suspend 2793 # start of kernel suspend
2788 if(re.match('suspend_enter\[.*', t.name)): 2794 if(re.match('suspend_enter\[.*', t.name)):
2789 if(isbegin and data.start == data.tKernSus): 2795 if(isbegin):
2790 data.dmesg[phase]['start'] = t.time
2791 data.tKernSus = t.time 2796 data.tKernSus = t.time
2792 continue 2797 continue
2793 # suspend_prepare start 2798 # suspend_prepare start
2794 elif(re.match('dpm_prepare\[.*', t.name)): 2799 elif(re.match('dpm_prepare\[.*', t.name)):
2795 phase = 'suspend_prepare' 2800 phase = 'suspend_prepare'
2796 if(not isbegin): 2801 if not isbegin:
2797 data.dmesg[phase]['end'] = t.time 2802 data.setPhase(phase, t.time, isbegin)
2798 if data.dmesg[phase]['start'] < 0: 2803 if isbegin and data.tKernSus == 0:
2799 data.dmesg[phase]['start'] = data.start 2804 data.tKernSus = t.time
2800 continue 2805 continue
2801 # suspend start 2806 # suspend start
2802 elif(re.match('dpm_suspend\[.*', t.name)): 2807 elif(re.match('dpm_suspend\[.*', t.name)):
2803 phase = 'suspend' 2808 phase = data.setPhase('suspend', t.time, isbegin)
2804 data.setPhase(phase, t.time, isbegin)
2805 continue 2809 continue
2806 # suspend_late start 2810 # suspend_late start
2807 elif(re.match('dpm_suspend_late\[.*', t.name)): 2811 elif(re.match('dpm_suspend_late\[.*', t.name)):
2808 phase = 'suspend_late' 2812 phase = data.setPhase('suspend_late', t.time, isbegin)
2809 data.setPhase(phase, t.time, isbegin)
2810 continue 2813 continue
2811 # suspend_noirq start 2814 # suspend_noirq start
2812 elif(re.match('dpm_suspend_noirq\[.*', t.name)): 2815 elif(re.match('dpm_suspend_noirq\[.*', t.name)):
2813 if data.phaseCollision('suspend_noirq', isbegin, line): 2816 phase = data.setPhase('suspend_noirq', t.time, isbegin)
2814 continue
2815 phase = 'suspend_noirq'
2816 data.setPhase(phase, t.time, isbegin)
2817 if(not isbegin):
2818 phase = 'suspend_machine'
2819 data.dmesg[phase]['start'] = t.time
2820 continue 2817 continue
2821 # suspend_machine/resume_machine 2818 # suspend_machine/resume_machine
2822 elif(re.match('machine_suspend\[.*', t.name)): 2819 elif(re.match('machine_suspend\[.*', t.name)):
2823 if(isbegin): 2820 if(isbegin):
2824 phase = 'suspend_machine' 2821 lp = data.lastPhase()
2825 data.dmesg[phase]['end'] = t.time 2822 phase = data.setPhase('suspend_machine', data.dmesg[lp]['end'], True)
2826 data.tSuspended = t.time 2823 data.setPhase(phase, t.time, False)
2827 else: 2824 if data.tSuspended == 0:
2828 if(sysvals.suspendmode in ['mem', 'disk'] and not tp.S0i3):
2829 data.dmesg['suspend_machine']['end'] = t.time
2830 data.tSuspended = t.time 2825 data.tSuspended = t.time
2831 phase = 'resume_machine' 2826 else:
2832 data.dmesg[phase]['start'] = t.time 2827 phase = data.setPhase('resume_machine', t.time, True)
2833 data.tResumed = t.time 2828 if(sysvals.suspendmode in ['mem', 'disk']):
2834 data.tLow = data.tResumed - data.tSuspended 2829 if 'suspend_machine' in data.dmesg:
2835 continue 2830 data.dmesg['suspend_machine']['end'] = t.time
2836 # acpi_suspend
2837 elif(re.match('acpi_suspend\[.*', t.name)):
2838 # acpi_suspend[0] S0i3
2839 if(re.match('acpi_suspend\[0\] begin', t.name)):
2840 if(sysvals.suspendmode == 'mem'):
2841 tp.S0i3 = True
2842 data.dmesg['suspend_machine']['end'] = t.time
2843 data.tSuspended = t.time 2831 data.tSuspended = t.time
2832 if data.tResumed == 0:
2833 data.tResumed = t.time
2844 continue 2834 continue
2845 # resume_noirq start 2835 # resume_noirq start
2846 elif(re.match('dpm_resume_noirq\[.*', t.name)): 2836 elif(re.match('dpm_resume_noirq\[.*', t.name)):
2847 if data.phaseCollision('resume_noirq', isbegin, line): 2837 phase = data.setPhase('resume_noirq', t.time, isbegin)
2848 continue
2849 phase = 'resume_noirq'
2850 data.setPhase(phase, t.time, isbegin)
2851 if(isbegin):
2852 data.dmesg['resume_machine']['end'] = t.time
2853 continue 2838 continue
2854 # resume_early start 2839 # resume_early start
2855 elif(re.match('dpm_resume_early\[.*', t.name)): 2840 elif(re.match('dpm_resume_early\[.*', t.name)):
2856 phase = 'resume_early' 2841 phase = data.setPhase('resume_early', t.time, isbegin)
2857 data.setPhase(phase, t.time, isbegin)
2858 continue 2842 continue
2859 # resume start 2843 # resume start
2860 elif(re.match('dpm_resume\[.*', t.name)): 2844 elif(re.match('dpm_resume\[.*', t.name)):
2861 phase = 'resume' 2845 phase = data.setPhase('resume', t.time, isbegin)
2862 data.setPhase(phase, t.time, isbegin)
2863 continue 2846 continue
2864 # resume complete start 2847 # resume complete start
2865 elif(re.match('dpm_complete\[.*', t.name)): 2848 elif(re.match('dpm_complete\[.*', t.name)):
2866 phase = 'resume_complete' 2849 phase = data.setPhase('resume_complete', t.time, isbegin)
2867 if(isbegin):
2868 data.dmesg[phase]['start'] = t.time
2869 continue 2850 continue
2870 # skip trace events inside devices calls 2851 # skip trace events inside devices calls
2871 if(not data.isTraceEventOutsideDeviceCalls(pid, t.time)): 2852 if(not data.isTraceEventOutsideDeviceCalls(pid, t.time)):
@@ -2881,13 +2862,10 @@ def parseTraceLog(live=False):
2881 if(len(testrun.ttemp[name]) > 0): 2862 if(len(testrun.ttemp[name]) > 0):
2882 # if an entry exists, assume this is its end 2863 # if an entry exists, assume this is its end
2883 testrun.ttemp[name][-1]['end'] = t.time 2864 testrun.ttemp[name][-1]['end'] = t.time
2884 elif(phase == 'post_resume'):
2885 # post resume events can just have ends
2886 testrun.ttemp[name].append({
2887 'begin': data.dmesg[phase]['start'],
2888 'end': t.time})
2889 # device callback start 2865 # device callback start
2890 elif(t.type == 'device_pm_callback_start'): 2866 elif(t.type == 'device_pm_callback_start'):
2867 if phase not in data.dmesg:
2868 continue
2891 m = re.match('(?P<drv>.*) (?P<d>.*), parent: *(?P<p>.*), .*',\ 2869 m = re.match('(?P<drv>.*) (?P<d>.*), parent: *(?P<p>.*), .*',\
2892 t.name); 2870 t.name);
2893 if(not m): 2871 if(not m):
@@ -2901,6 +2879,8 @@ def parseTraceLog(live=False):
2901 data.devpids.append(pid) 2879 data.devpids.append(pid)
2902 # device callback finish 2880 # device callback finish
2903 elif(t.type == 'device_pm_callback_end'): 2881 elif(t.type == 'device_pm_callback_end'):
2882 if phase not in data.dmesg:
2883 continue
2904 m = re.match('(?P<drv>.*) (?P<d>.*), err.*', t.name); 2884 m = re.match('(?P<drv>.*) (?P<d>.*), err.*', t.name);
2905 if(not m): 2885 if(not m):
2906 continue 2886 continue
@@ -2941,9 +2921,9 @@ def parseTraceLog(live=False):
2941 e['end'] = t.time 2921 e['end'] = t.time
2942 e['rdata'] = kprobedata 2922 e['rdata'] = kprobedata
2943 # end of kernel resume 2923 # end of kernel resume
2944 if(kprobename == 'pm_notifier_call_chain' or \ 2924 if(phase != 'suspend_prepare' and kprobename in krescalls):
2945 kprobename == 'pm_restore_console'): 2925 if phase in data.dmesg:
2946 data.dmesg[phase]['end'] = t.time 2926 data.dmesg[phase]['end'] = t.time
2947 data.tKernRes = t.time 2927 data.tKernRes = t.time
2948 2928
2949 # callgraph processing 2929 # callgraph processing
@@ -2961,10 +2941,13 @@ def parseTraceLog(live=False):
2961 if(res == -1): 2941 if(res == -1):
2962 testrun.ftemp[key][-1].addLine(t) 2942 testrun.ftemp[key][-1].addLine(t)
2963 tf.close() 2943 tf.close()
2944 if data and not data.devicegroups:
2945 sysvals.vprint('WARNING: end marker is missing')
2946 data.handleEndMarker(t.time)
2964 2947
2965 if sysvals.suspendmode == 'command': 2948 if sysvals.suspendmode == 'command':
2966 for test in testruns: 2949 for test in testruns:
2967 for p in test.data.phases: 2950 for p in test.data.sortedPhases():
2968 if p == 'suspend_prepare': 2951 if p == 'suspend_prepare':
2969 test.data.dmesg[p]['start'] = test.data.start 2952 test.data.dmesg[p]['start'] = test.data.start
2970 test.data.dmesg[p]['end'] = test.data.end 2953 test.data.dmesg[p]['end'] = test.data.end
@@ -2973,7 +2956,6 @@ def parseTraceLog(live=False):
2973 test.data.dmesg[p]['end'] = test.data.end 2956 test.data.dmesg[p]['end'] = test.data.end
2974 test.data.tSuspended = test.data.end 2957 test.data.tSuspended = test.data.end
2975 test.data.tResumed = test.data.end 2958 test.data.tResumed = test.data.end
2976 test.data.tLow = 0
2977 test.data.fwValid = False 2959 test.data.fwValid = False
2978 2960
2979 # dev source and procmon events can be unreadable with mixed phase height 2961 # dev source and procmon events can be unreadable with mixed phase height
@@ -3040,8 +3022,8 @@ def parseTraceLog(live=False):
3040 sortkey = '%f%f%d' % (cg.start, cg.end, pid) 3022 sortkey = '%f%f%d' % (cg.start, cg.end, pid)
3041 sortlist[sortkey] = cg 3023 sortlist[sortkey] = cg
3042 elif len(cg.list) > 1000000: 3024 elif len(cg.list) > 1000000:
3043 print 'WARNING: the callgraph for %s is massive (%d lines)' %\ 3025 sysvals.vprint('WARNING: the callgraph for %s is massive (%d lines)' %\
3044 (devname, len(cg.list)) 3026 (devname, len(cg.list)))
3045 # create blocks for orphan cg data 3027 # create blocks for orphan cg data
3046 for sortkey in sorted(sortlist): 3028 for sortkey in sorted(sortlist):
3047 cg = sortlist[sortkey] 3029 cg = sortlist[sortkey]
@@ -3057,25 +3039,34 @@ def parseTraceLog(live=False):
3057 for data in testdata: 3039 for data in testdata:
3058 tn = '' if len(testdata) == 1 else ('%d' % (data.testnumber + 1)) 3040 tn = '' if len(testdata) == 1 else ('%d' % (data.testnumber + 1))
3059 terr = '' 3041 terr = ''
3060 lp = data.phases[0] 3042 phasedef = data.phasedef
3061 for p in data.phases: 3043 lp = 'suspend_prepare'
3062 if(data.dmesg[p]['start'] < 0 and data.dmesg[p]['end'] < 0): 3044 for p in sorted(phasedef, key=lambda k:phasedef[k]['order']):
3045 if p not in data.dmesg:
3063 if not terr: 3046 if not terr:
3064 print 'TEST%s FAILED: %s failed in %s phase' % (tn, sysvals.suspendmode, lp) 3047 print 'TEST%s FAILED: %s failed in %s phase' % (tn, sysvals.suspendmode, lp)
3065 terr = '%s%s failed in %s phase' % (sysvals.suspendmode, tn, lp) 3048 terr = '%s%s failed in %s phase' % (sysvals.suspendmode, tn, lp)
3066 error.append(terr) 3049 error.append(terr)
3050 if data.tSuspended == 0:
3051 data.tSuspended = data.dmesg[lp]['end']
3052 if data.tResumed == 0:
3053 data.tResumed = data.dmesg[lp]['end']
3054 data.fwValid = False
3067 sysvals.vprint('WARNING: phase "%s" is missing!' % p) 3055 sysvals.vprint('WARNING: phase "%s" is missing!' % p)
3068 if(data.dmesg[p]['start'] < 0): 3056 lp = p
3069 data.dmesg[p]['start'] = data.dmesg[lp]['end'] 3057 if not terr and data.enterfail:
3070 if(p == 'resume_machine'): 3058 print 'test%s FAILED: enter %s failed with %s' % (tn, sysvals.suspendmode, data.enterfail)
3071 data.tSuspended = data.dmesg[lp]['end'] 3059 terr = 'test%s failed to enter %s mode' % (tn, sysvals.suspendmode)
3072 data.tResumed = data.dmesg[lp]['end'] 3060 error.append(terr)
3073 data.tLow = 0 3061 lp = data.sortedPhases()[0]
3074 if(data.dmesg[p]['end'] < 0): 3062 for p in data.sortedPhases():
3075 data.dmesg[p]['end'] = data.dmesg[p]['start']
3076 if(p != lp and not ('machine' in p and 'machine' in lp)): 3063 if(p != lp and not ('machine' in p and 'machine' in lp)):
3077 data.dmesg[lp]['end'] = data.dmesg[p]['start'] 3064 data.dmesg[lp]['end'] = data.dmesg[p]['start']
3078 lp = p 3065 lp = p
3066 if data.tSuspended == 0:
3067 data.tSuspended = data.tKernRes
3068 if data.tResumed == 0:
3069 data.tResumed = data.tSuspended
3079 3070
3080 if(len(sysvals.devicefilter) > 0): 3071 if(len(sysvals.devicefilter) > 0):
3081 data.deviceFilter(sysvals.devicefilter) 3072 data.deviceFilter(sysvals.devicefilter)
@@ -3127,7 +3118,13 @@ def loadKernelLog():
3127 elif re.match(tp.cmdlinefmt, line): 3118 elif re.match(tp.cmdlinefmt, line):
3128 tp.cmdline = line 3119 tp.cmdline = line
3129 continue 3120 continue
3130 m = re.match(sysvals.firmwarefmt, line) 3121 elif re.match(tp.batteryfmt, line):
3122 tp.battery.append(line)
3123 continue
3124 elif re.match(tp.testerrfmt, line):
3125 tp.testerror.append(line)
3126 continue
3127 m = re.match(tp.firmwarefmt, line)
3131 if(m): 3128 if(m):
3132 tp.fwdata.append((int(m.group('s')), int(m.group('r')))) 3129 tp.fwdata.append((int(m.group('s')), int(m.group('r'))))
3133 continue 3130 continue
@@ -3140,10 +3137,6 @@ def loadKernelLog():
3140 testruns.append(data) 3137 testruns.append(data)
3141 data = Data(len(testruns)) 3138 data = Data(len(testruns))
3142 tp.parseStamp(data, sysvals) 3139 tp.parseStamp(data, sysvals)
3143 if len(tp.fwdata) > data.testnumber:
3144 data.fwSuspend, data.fwResume = tp.fwdata[data.testnumber]
3145 if(data.fwSuspend > 0 or data.fwResume > 0):
3146 data.fwValid = True
3147 if(not data): 3140 if(not data):
3148 continue 3141 continue
3149 m = re.match('.* *(?P<k>[0-9]\.[0-9]{2}\.[0-9]-.*) .*', msg) 3142 m = re.match('.* *(?P<k>[0-9]\.[0-9]{2}\.[0-9]-.*) .*', msg)
@@ -3199,30 +3192,30 @@ def parseKernelLog(data):
3199 3192
3200 # dmesg phase match table 3193 # dmesg phase match table
3201 dm = { 3194 dm = {
3202 'suspend_prepare': 'PM: Syncing filesystems.*', 3195 'suspend_prepare': ['PM: Syncing filesystems.*'],
3203 'suspend': 'PM: Entering [a-z]* sleep.*', 3196 'suspend': ['PM: Entering [a-z]* sleep.*', 'Suspending console.*'],
3204 'suspend_late': 'PM: suspend of devices complete after.*', 3197 'suspend_late': ['PM: suspend of devices complete after.*'],
3205 'suspend_noirq': 'PM: late suspend of devices complete after.*', 3198 'suspend_noirq': ['PM: late suspend of devices complete after.*'],
3206 'suspend_machine': 'PM: noirq suspend of devices complete after.*', 3199 'suspend_machine': ['PM: noirq suspend of devices complete after.*'],
3207 'resume_machine': 'ACPI: Low-level resume complete.*', 3200 'resume_machine': ['ACPI: Low-level resume complete.*'],
3208 'resume_noirq': 'ACPI: Waking up from system sleep state.*', 3201 'resume_noirq': ['ACPI: Waking up from system sleep state.*'],
3209 'resume_early': 'PM: noirq resume of devices complete after.*', 3202 'resume_early': ['PM: noirq resume of devices complete after.*'],
3210 'resume': 'PM: early resume of devices complete after.*', 3203 'resume': ['PM: early resume of devices complete after.*'],
3211 'resume_complete': 'PM: resume of devices complete after.*', 3204 'resume_complete': ['PM: resume of devices complete after.*'],
3212 'post_resume': '.*Restarting tasks \.\.\..*', 3205 'post_resume': ['.*Restarting tasks \.\.\..*'],
3213 } 3206 }
3214 if(sysvals.suspendmode == 'standby'): 3207 if(sysvals.suspendmode == 'standby'):
3215 dm['resume_machine'] = 'PM: Restoring platform NVS memory' 3208 dm['resume_machine'] = ['PM: Restoring platform NVS memory']
3216 elif(sysvals.suspendmode == 'disk'): 3209 elif(sysvals.suspendmode == 'disk'):
3217 dm['suspend_late'] = 'PM: freeze of devices complete after.*' 3210 dm['suspend_late'] = ['PM: freeze of devices complete after.*']
3218 dm['suspend_noirq'] = 'PM: late freeze of devices complete after.*' 3211 dm['suspend_noirq'] = ['PM: late freeze of devices complete after.*']
3219 dm['suspend_machine'] = 'PM: noirq freeze of devices complete after.*' 3212 dm['suspend_machine'] = ['PM: noirq freeze of devices complete after.*']
3220 dm['resume_machine'] = 'PM: Restoring platform NVS memory' 3213 dm['resume_machine'] = ['PM: Restoring platform NVS memory']
3221 dm['resume_early'] = 'PM: noirq restore of devices complete after.*' 3214 dm['resume_early'] = ['PM: noirq restore of devices complete after.*']
3222 dm['resume'] = 'PM: early restore of devices complete after.*' 3215 dm['resume'] = ['PM: early restore of devices complete after.*']
3223 dm['resume_complete'] = 'PM: restore of devices complete after.*' 3216 dm['resume_complete'] = ['PM: restore of devices complete after.*']
3224 elif(sysvals.suspendmode == 'freeze'): 3217 elif(sysvals.suspendmode == 'freeze'):
3225 dm['resume_machine'] = 'ACPI: resume from mwait' 3218 dm['resume_machine'] = ['ACPI: resume from mwait']
3226 3219
3227 # action table (expected events that occur and show up in dmesg) 3220 # action table (expected events that occur and show up in dmesg)
3228 at = { 3221 at = {
@@ -3264,81 +3257,89 @@ def parseKernelLog(data):
3264 else: 3257 else:
3265 continue 3258 continue
3266 3259
3260 # check for a phase change line
3261 phasechange = False
3262 for p in dm:
3263 for s in dm[p]:
3264 if(re.match(s, msg)):
3265 phasechange, phase = True, p
3266 break
3267
3267 # hack for determining resume_machine end for freeze 3268 # hack for determining resume_machine end for freeze
3268 if(not sysvals.usetraceevents and sysvals.suspendmode == 'freeze' \ 3269 if(not sysvals.usetraceevents and sysvals.suspendmode == 'freeze' \
3269 and phase == 'resume_machine' and \ 3270 and phase == 'resume_machine' and \
3270 re.match('calling (?P<f>.*)\+ @ .*, parent: .*', msg)): 3271 re.match('calling (?P<f>.*)\+ @ .*, parent: .*', msg)):
3271 data.dmesg['resume_machine']['end'] = ktime 3272 data.setPhase(phase, ktime, False)
3272 phase = 'resume_noirq' 3273 phase = 'resume_noirq'
3273 data.dmesg[phase]['start'] = ktime 3274 data.setPhase(phase, ktime, True)
3274 3275
3275 # suspend start 3276 if phasechange:
3276 if(re.match(dm['suspend_prepare'], msg)): 3277 if phase == 'suspend_prepare':
3277 phase = 'suspend_prepare' 3278 data.setPhase(phase, ktime, True)
3278 data.dmesg[phase]['start'] = ktime 3279 data.setStart(ktime)
3279 data.setStart(ktime) 3280 data.tKernSus = ktime
3280 data.tKernSus = ktime 3281 elif phase == 'suspend':
3281 # suspend start 3282 lp = data.lastPhase()
3282 elif(re.match(dm['suspend'], msg)): 3283 if lp:
3283 data.dmesg['suspend_prepare']['end'] = ktime 3284 data.setPhase(lp, ktime, False)
3284 phase = 'suspend' 3285 data.setPhase(phase, ktime, True)
3285 data.dmesg[phase]['start'] = ktime 3286 elif phase == 'suspend_late':
3286 # suspend_late start 3287 lp = data.lastPhase()
3287 elif(re.match(dm['suspend_late'], msg)): 3288 if lp:
3288 data.dmesg['suspend']['end'] = ktime 3289 data.setPhase(lp, ktime, False)
3289 phase = 'suspend_late' 3290 data.setPhase(phase, ktime, True)
3290 data.dmesg[phase]['start'] = ktime 3291 elif phase == 'suspend_noirq':
3291 # suspend_noirq start 3292 lp = data.lastPhase()
3292 elif(re.match(dm['suspend_noirq'], msg)): 3293 if lp:
3293 data.dmesg['suspend_late']['end'] = ktime 3294 data.setPhase(lp, ktime, False)
3294 phase = 'suspend_noirq' 3295 data.setPhase(phase, ktime, True)
3295 data.dmesg[phase]['start'] = ktime 3296 elif phase == 'suspend_machine':
3296 # suspend_machine start 3297 lp = data.lastPhase()
3297 elif(re.match(dm['suspend_machine'], msg)): 3298 if lp:
3298 data.dmesg['suspend_noirq']['end'] = ktime 3299 data.setPhase(lp, ktime, False)
3299 phase = 'suspend_machine' 3300 data.setPhase(phase, ktime, True)
3300 data.dmesg[phase]['start'] = ktime 3301 elif phase == 'resume_machine':
3301 # resume_machine start 3302 lp = data.lastPhase()
3302 elif(re.match(dm['resume_machine'], msg)): 3303 if(sysvals.suspendmode in ['freeze', 'standby']):
3303 if(sysvals.suspendmode in ['freeze', 'standby']): 3304 data.tSuspended = prevktime
3304 data.tSuspended = prevktime 3305 if lp:
3305 data.dmesg['suspend_machine']['end'] = prevktime 3306 data.setPhase(lp, prevktime, False)
3306 else: 3307 else:
3307 data.tSuspended = ktime 3308 data.tSuspended = ktime
3308 data.dmesg['suspend_machine']['end'] = ktime 3309 if lp:
3309 phase = 'resume_machine' 3310 data.setPhase(lp, prevktime, False)
3310 data.tResumed = ktime 3311 data.tResumed = ktime
3311 data.tLow = data.tResumed - data.tSuspended 3312 data.setPhase(phase, ktime, True)
3312 data.dmesg[phase]['start'] = ktime 3313 elif phase == 'resume_noirq':
3313 # resume_noirq start 3314 lp = data.lastPhase()
3314 elif(re.match(dm['resume_noirq'], msg)): 3315 if lp:
3315 data.dmesg['resume_machine']['end'] = ktime 3316 data.setPhase(lp, ktime, False)
3316 phase = 'resume_noirq' 3317 data.setPhase(phase, ktime, True)
3317 data.dmesg[phase]['start'] = ktime 3318 elif phase == 'resume_early':
3318 # resume_early start 3319 lp = data.lastPhase()
3319 elif(re.match(dm['resume_early'], msg)): 3320 if lp:
3320 data.dmesg['resume_noirq']['end'] = ktime 3321 data.setPhase(lp, ktime, False)
3321 phase = 'resume_early' 3322 data.setPhase(phase, ktime, True)
3322 data.dmesg[phase]['start'] = ktime 3323 elif phase == 'resume':
3323 # resume start 3324 lp = data.lastPhase()
3324 elif(re.match(dm['resume'], msg)): 3325 if lp:
3325 data.dmesg['resume_early']['end'] = ktime 3326 data.setPhase(lp, ktime, False)
3326 phase = 'resume' 3327 data.setPhase(phase, ktime, True)
3327 data.dmesg[phase]['start'] = ktime 3328 elif phase == 'resume_complete':
3328 # resume complete start 3329 lp = data.lastPhase()
3329 elif(re.match(dm['resume_complete'], msg)): 3330 if lp:
3330 data.dmesg['resume']['end'] = ktime 3331 data.setPhase(lp, ktime, False)
3331 phase = 'resume_complete' 3332 data.setPhase(phase, ktime, True)
3332 data.dmesg[phase]['start'] = ktime 3333 elif phase == 'post_resume':
3333 # post resume start 3334 lp = data.lastPhase()
3334 elif(re.match(dm['post_resume'], msg)): 3335 if lp:
3335 data.dmesg['resume_complete']['end'] = ktime 3336 data.setPhase(lp, ktime, False)
3336 data.setEnd(ktime) 3337 data.setEnd(ktime)
3337 data.tKernRes = ktime 3338 data.tKernRes = ktime
3338 break 3339 break
3339 3340
3340 # -- device callbacks -- 3341 # -- device callbacks --
3341 if(phase in data.phases): 3342 if(phase in data.sortedPhases()):
3342 # device init call 3343 # device init call
3343 if(re.match('calling (?P<f>.*)\+ @ .*, parent: .*', msg)): 3344 if(re.match('calling (?P<f>.*)\+ @ .*, parent: .*', msg)):
3344 sm = re.match('calling (?P<f>.*)\+ @ '+\ 3345 sm = re.match('calling (?P<f>.*)\+ @ '+\
@@ -3396,24 +3397,31 @@ def parseKernelLog(data):
3396 actions[cpu].append({'begin': cpu_start, 'end': ktime}) 3397 actions[cpu].append({'begin': cpu_start, 'end': ktime})
3397 cpu_start = ktime 3398 cpu_start = ktime
3398 prevktime = ktime 3399 prevktime = ktime
3400 data.initDevicegroups()
3399 3401
3400 # fill in any missing phases 3402 # fill in any missing phases
3401 lp = data.phases[0] 3403 phasedef = data.phasedef
3402 for p in data.phases: 3404 terr, lp = '', 'suspend_prepare'
3403 if(data.dmesg[p]['start'] < 0 and data.dmesg[p]['end'] < 0): 3405 for p in sorted(phasedef, key=lambda k:phasedef[k]['order']):
3404 print('WARNING: phase "%s" is missing, something went wrong!' % p) 3406 if p not in data.dmesg:
3405 print(' In %s, this dmesg line denotes the start of %s:' % \ 3407 if not terr:
3406 (sysvals.suspendmode, p)) 3408 print 'TEST FAILED: %s failed in %s phase' % (sysvals.suspendmode, lp)
3407 print(' "%s"' % dm[p]) 3409 terr = '%s failed in %s phase' % (sysvals.suspendmode, lp)
3408 if(data.dmesg[p]['start'] < 0): 3410 if data.tSuspended == 0:
3409 data.dmesg[p]['start'] = data.dmesg[lp]['end'] 3411 data.tSuspended = data.dmesg[lp]['end']
3410 if(p == 'resume_machine'): 3412 if data.tResumed == 0:
3411 data.tSuspended = data.dmesg[lp]['end'] 3413 data.tResumed = data.dmesg[lp]['end']
3412 data.tResumed = data.dmesg[lp]['end'] 3414 sysvals.vprint('WARNING: phase "%s" is missing!' % p)
3413 data.tLow = 0 3415 lp = p
3414 if(data.dmesg[p]['end'] < 0): 3416 lp = data.sortedPhases()[0]
3415 data.dmesg[p]['end'] = data.dmesg[p]['start'] 3417 for p in data.sortedPhases():
3418 if(p != lp and not ('machine' in p and 'machine' in lp)):
3419 data.dmesg[lp]['end'] = data.dmesg[p]['start']
3416 lp = p 3420 lp = p
3421 if data.tSuspended == 0:
3422 data.tSuspended = data.tKernRes
3423 if data.tResumed == 0:
3424 data.tResumed = data.tSuspended
3417 3425
3418 # fill in any actions we've found 3426 # fill in any actions we've found
3419 for name in actions: 3427 for name in actions:
@@ -3462,7 +3470,7 @@ def addCallgraphs(sv, hf, data):
3462 hf.write('<section id="callgraphs" class="callgraph">\n') 3470 hf.write('<section id="callgraphs" class="callgraph">\n')
3463 # write out the ftrace data converted to html 3471 # write out the ftrace data converted to html
3464 num = 0 3472 num = 0
3465 for p in data.phases: 3473 for p in data.sortedPhases():
3466 if sv.cgphase and p != sv.cgphase: 3474 if sv.cgphase and p != sv.cgphase:
3467 continue 3475 continue
3468 list = data.dmesg[p]['list'] 3476 list = data.dmesg[p]['list']
@@ -3505,7 +3513,7 @@ def createHTMLSummarySimple(testruns, htmlfile, folder):
3505 table {width:100%;border-collapse: collapse;}\n\ 3513 table {width:100%;border-collapse: collapse;}\n\
3506 .summary {border:1px solid;}\n\ 3514 .summary {border:1px solid;}\n\
3507 th {border: 1px solid black;background:#222;color:white;}\n\ 3515 th {border: 1px solid black;background:#222;color:white;}\n\
3508 td {font: 16px "Times New Roman";text-align: center;}\n\ 3516 td {font: 14px "Times New Roman";text-align: center;}\n\
3509 tr.head td {border: 1px solid black;background:#aaa;}\n\ 3517 tr.head td {border: 1px solid black;background:#aaa;}\n\
3510 tr.alt {background-color:#ddd;}\n\ 3518 tr.alt {background-color:#ddd;}\n\
3511 tr.notice {color:red;}\n\ 3519 tr.notice {color:red;}\n\
@@ -3521,7 +3529,7 @@ def createHTMLSummarySimple(testruns, htmlfile, folder):
3521 iMin, iMed, iMax = [0, 0], [0, 0], [0, 0] 3529 iMin, iMed, iMax = [0, 0], [0, 0], [0, 0]
3522 num = 0 3530 num = 0
3523 lastmode = '' 3531 lastmode = ''
3524 cnt = {'pass':0, 'fail':0, 'hang':0} 3532 cnt = dict()
3525 for data in sorted(testruns, key=lambda v:(v['mode'], v['host'], v['kernel'], v['time'])): 3533 for data in sorted(testruns, key=lambda v:(v['mode'], v['host'], v['kernel'], v['time'])):
3526 mode = data['mode'] 3534 mode = data['mode']
3527 if mode not in list: 3535 if mode not in list:
@@ -3541,10 +3549,14 @@ def createHTMLSummarySimple(testruns, htmlfile, folder):
3541 tVal = [float(data['suspend']), float(data['resume'])] 3549 tVal = [float(data['suspend']), float(data['resume'])]
3542 list[mode]['data'].append([data['host'], data['kernel'], 3550 list[mode]['data'].append([data['host'], data['kernel'],
3543 data['time'], tVal[0], tVal[1], data['url'], data['result'], 3551 data['time'], tVal[0], tVal[1], data['url'], data['result'],
3544 data['issues']]) 3552 data['issues'], data['sus_worst'], data['sus_worsttime'],
3553 data['res_worst'], data['res_worsttime']])
3545 idx = len(list[mode]['data']) - 1 3554 idx = len(list[mode]['data']) - 1
3555 if data['result'] not in cnt:
3556 cnt[data['result']] = 1
3557 else:
3558 cnt[data['result']] += 1
3546 if data['result'] == 'pass': 3559 if data['result'] == 'pass':
3547 cnt['pass'] += 1
3548 for i in range(2): 3560 for i in range(2):
3549 tMed[i].append(tVal[i]) 3561 tMed[i].append(tVal[i])
3550 tAvg[i] += tVal[i] 3562 tAvg[i] += tVal[i]
@@ -3555,10 +3567,6 @@ def createHTMLSummarySimple(testruns, htmlfile, folder):
3555 iMax[i] = idx 3567 iMax[i] = idx
3556 tMax[i] = tVal[i] 3568 tMax[i] = tVal[i]
3557 num += 1 3569 num += 1
3558 elif data['result'] == 'hang':
3559 cnt['hang'] += 1
3560 elif data['result'] == 'fail':
3561 cnt['fail'] += 1
3562 lastmode = mode 3570 lastmode = mode
3563 if lastmode and num > 0: 3571 if lastmode and num > 0:
3564 for i in range(2): 3572 for i in range(2):
@@ -3585,11 +3593,14 @@ def createHTMLSummarySimple(testruns, htmlfile, folder):
3585 html += '<table class="summary">\n<tr>\n' + th.format('#') +\ 3593 html += '<table class="summary">\n<tr>\n' + th.format('#') +\
3586 th.format('Mode') + th.format('Host') + th.format('Kernel') +\ 3594 th.format('Mode') + th.format('Host') + th.format('Kernel') +\
3587 th.format('Test Time') + th.format('Result') + th.format('Issues') +\ 3595 th.format('Test Time') + th.format('Result') + th.format('Issues') +\
3588 th.format('Suspend') + th.format('Resume') + th.format('Detail') + '</tr>\n' 3596 th.format('Suspend') + th.format('Resume') +\
3597 th.format('Worst Suspend Device') + th.format('SD Time') +\
3598 th.format('Worst Resume Device') + th.format('RD Time') +\
3599 th.format('Detail') + '</tr>\n'
3589 3600
3590 # export list into html 3601 # export list into html
3591 head = '<tr class="head"><td>{0}</td><td>{1}</td>'+\ 3602 head = '<tr class="head"><td>{0}</td><td>{1}</td>'+\
3592 '<td colspan=8 class="sus">Suspend Avg={2} '+\ 3603 '<td colspan=12 class="sus">Suspend Avg={2} '+\
3593 '<span class=minval><a href="#s{10}min">Min={3}</a></span> '+\ 3604 '<span class=minval><a href="#s{10}min">Min={3}</a></span> '+\
3594 '<span class=medval><a href="#s{10}med">Med={4}</a></span> '+\ 3605 '<span class=medval><a href="#s{10}med">Med={4}</a></span> '+\
3595 '<span class=maxval><a href="#s{10}max">Max={5}</a></span> '+\ 3606 '<span class=maxval><a href="#s{10}max">Max={5}</a></span> '+\
@@ -3598,7 +3609,7 @@ def createHTMLSummarySimple(testruns, htmlfile, folder):
3598 '<span class=medval><a href="#r{10}med">Med={8}</a></span> '+\ 3609 '<span class=medval><a href="#r{10}med">Med={8}</a></span> '+\
3599 '<span class=maxval><a href="#r{10}max">Max={9}</a></span></td>'+\ 3610 '<span class=maxval><a href="#r{10}max">Max={9}</a></span></td>'+\
3600 '</tr>\n' 3611 '</tr>\n'
3601 headnone = '<tr class="head"><td>{0}</td><td>{1}</td><td colspan=8></td></tr>\n' 3612 headnone = '<tr class="head"><td>{0}</td><td>{1}</td><td colspan=12></td></tr>\n'
3602 for mode in list: 3613 for mode in list:
3603 # header line for each suspend mode 3614 # header line for each suspend mode
3604 num = 0 3615 num = 0
@@ -3641,6 +3652,10 @@ def createHTMLSummarySimple(testruns, htmlfile, folder):
3641 html += td.format(d[7]) # issues 3652 html += td.format(d[7]) # issues
3642 html += tdh.format('%.3f ms' % d[3], tHigh[0]) if d[3] else td.format('') # suspend 3653 html += tdh.format('%.3f ms' % d[3], tHigh[0]) if d[3] else td.format('') # suspend
3643 html += tdh.format('%.3f ms' % d[4], tHigh[1]) if d[4] else td.format('') # resume 3654 html += tdh.format('%.3f ms' % d[4], tHigh[1]) if d[4] else td.format('') # resume
3655 html += td.format(d[8]) # sus_worst
3656 html += td.format('%.3f ms' % d[9]) if d[9] else td.format('') # sus_worst time
3657 html += td.format(d[10]) # res_worst
3658 html += td.format('%.3f ms' % d[11]) if d[11] else td.format('') # res_worst time
3644 html += tdlink.format(d[5]) if d[5] else td.format('') # url 3659 html += tdlink.format(d[5]) if d[5] else td.format('') # url
3645 html += '</tr>\n' 3660 html += '</tr>\n'
3646 num += 1 3661 num += 1
@@ -3677,7 +3692,8 @@ def createHTML(testruns, testfail):
3677 for data in testruns: 3692 for data in testruns:
3678 if data.kerror: 3693 if data.kerror:
3679 kerror = True 3694 kerror = True
3680 data.normalizeTime(testruns[-1].tSuspended) 3695 if(sysvals.suspendmode in ['freeze', 'standby']):
3696 data.trimFreezeTime(testruns[-1].tSuspended)
3681 3697
3682 # html function templates 3698 # html function templates
3683 html_error = '<div id="{1}" title="kernel error/warning" class="err" style="right:{0}%">{2}&rarr;</div>\n' 3699 html_error = '<div id="{1}" title="kernel error/warning" class="err" style="right:{0}%">{2}&rarr;</div>\n'
@@ -3721,8 +3737,8 @@ def createHTML(testruns, testfail):
3721 sktime, rktime = data.getTimeValues() 3737 sktime, rktime = data.getTimeValues()
3722 if(tTotal == 0): 3738 if(tTotal == 0):
3723 doError('No timeline data') 3739 doError('No timeline data')
3724 if(data.tLow > 0): 3740 if(len(data.tLow) > 0):
3725 low_time = '%.0f'%(data.tLow*1000) 3741 low_time = '|'.join(data.tLow)
3726 if sysvals.suspendmode == 'command': 3742 if sysvals.suspendmode == 'command':
3727 run_time = '%.0f'%((data.end-data.start)*1000) 3743 run_time = '%.0f'%((data.end-data.start)*1000)
3728 if sysvals.testcommand: 3744 if sysvals.testcommand:
@@ -3743,7 +3759,7 @@ def createHTML(testruns, testfail):
3743 if(len(testruns) > 1): 3759 if(len(testruns) > 1):
3744 testdesc1 = testdesc2 = ordinal(data.testnumber+1) 3760 testdesc1 = testdesc2 = ordinal(data.testnumber+1)
3745 testdesc2 += ' ' 3761 testdesc2 += ' '
3746 if(data.tLow == 0): 3762 if(len(data.tLow) == 0):
3747 thtml = html_timetotal.format(suspend_time, \ 3763 thtml = html_timetotal.format(suspend_time, \
3748 resume_time, testdesc1, stitle, rtitle) 3764 resume_time, testdesc1, stitle, rtitle)
3749 else: 3765 else:
@@ -3762,7 +3778,7 @@ def createHTML(testruns, testfail):
3762 rtitle = 'time from firmware mode to return from kernel enter_state(%s) [kernel time only]' % sysvals.suspendmode 3778 rtitle = 'time from firmware mode to return from kernel enter_state(%s) [kernel time only]' % sysvals.suspendmode
3763 if(len(testruns) > 1): 3779 if(len(testruns) > 1):
3764 testdesc = ordinal(data.testnumber+1)+' '+testdesc 3780 testdesc = ordinal(data.testnumber+1)+' '+testdesc
3765 if(data.tLow == 0): 3781 if(len(data.tLow) == 0):
3766 thtml = html_timetotal.format(suspend_time, \ 3782 thtml = html_timetotal.format(suspend_time, \
3767 resume_time, testdesc, stitle, rtitle) 3783 resume_time, testdesc, stitle, rtitle)
3768 else: 3784 else:
@@ -3820,15 +3836,14 @@ def createHTML(testruns, testfail):
3820 3836
3821 # draw the full timeline 3837 # draw the full timeline
3822 devtl.createZoomBox(sysvals.suspendmode, len(testruns)) 3838 devtl.createZoomBox(sysvals.suspendmode, len(testruns))
3823 phases = {'suspend':[],'resume':[]}
3824 for phase in data.dmesg:
3825 if 'resume' in phase:
3826 phases['resume'].append(phase)
3827 else:
3828 phases['suspend'].append(phase)
3829
3830 # draw each test run chronologically
3831 for data in testruns: 3839 for data in testruns:
3840 # draw each test run and block chronologically
3841 phases = {'suspend':[],'resume':[]}
3842 for phase in data.sortedPhases():
3843 if data.dmesg[phase]['start'] >= data.tSuspended:
3844 phases['resume'].append(phase)
3845 else:
3846 phases['suspend'].append(phase)
3832 # now draw the actual timeline blocks 3847 # now draw the actual timeline blocks
3833 for dir in phases: 3848 for dir in phases:
3834 # draw suspend and resume blocks separately 3849 # draw suspend and resume blocks separately
@@ -3850,7 +3865,7 @@ def createHTML(testruns, testfail):
3850 continue 3865 continue
3851 width = '%f' % (((mTotal*100.0)-sysvals.srgap/2)/tTotal) 3866 width = '%f' % (((mTotal*100.0)-sysvals.srgap/2)/tTotal)
3852 devtl.html += devtl.html_tblock.format(bname, left, width, devtl.scaleH) 3867 devtl.html += devtl.html_tblock.format(bname, left, width, devtl.scaleH)
3853 for b in sorted(phases[dir]): 3868 for b in phases[dir]:
3854 # draw the phase color background 3869 # draw the phase color background
3855 phase = data.dmesg[b] 3870 phase = data.dmesg[b]
3856 length = phase['end']-phase['start'] 3871 length = phase['end']-phase['start']
@@ -3865,7 +3880,7 @@ def createHTML(testruns, testfail):
3865 id = '%d_%d' % (idx1, idx2) 3880 id = '%d_%d' % (idx1, idx2)
3866 right = '%f' % (((mMax-t)*100.0)/mTotal) 3881 right = '%f' % (((mMax-t)*100.0)/mTotal)
3867 devtl.html += html_error.format(right, id, type) 3882 devtl.html += html_error.format(right, id, type)
3868 for b in sorted(phases[dir]): 3883 for b in phases[dir]:
3869 # draw the devices for this phase 3884 # draw the devices for this phase
3870 phaselist = data.dmesg[b]['list'] 3885 phaselist = data.dmesg[b]['list']
3871 for d in data.tdevlist[b]: 3886 for d in data.tdevlist[b]:
@@ -3942,19 +3957,17 @@ def createHTML(testruns, testfail):
3942 3957
3943 # draw a legend which describes the phases by color 3958 # draw a legend which describes the phases by color
3944 if sysvals.suspendmode != 'command': 3959 if sysvals.suspendmode != 'command':
3945 data = testruns[-1] 3960 phasedef = testruns[-1].phasedef
3946 devtl.html += '<div class="legend">\n' 3961 devtl.html += '<div class="legend">\n'
3947 pdelta = 100.0/len(data.phases) 3962 pdelta = 100.0/len(phasedef.keys())
3948 pmargin = pdelta / 4.0 3963 pmargin = pdelta / 4.0
3949 for phase in data.phases: 3964 for phase in sorted(phasedef, key=lambda k:phasedef[k]['order']):
3950 tmp = phase.split('_') 3965 id, p = '', phasedef[phase]
3951 id = tmp[0][0] 3966 for word in phase.split('_'):
3952 if(len(tmp) > 1): 3967 id += word[0]
3953 id += tmp[1][0] 3968 order = '%.2f' % ((p['order'] * pdelta) + pmargin)
3954 order = '%.2f' % ((data.dmesg[phase]['order'] * pdelta) + pmargin)
3955 name = string.replace(phase, '_', ' &nbsp;') 3969 name = string.replace(phase, '_', ' &nbsp;')
3956 devtl.html += devtl.html_legend.format(order, \ 3970 devtl.html += devtl.html_legend.format(order, p['color'], name, id)
3957 data.dmesg[phase]['color'], name, id)
3958 devtl.html += '</div>\n' 3971 devtl.html += '</div>\n'
3959 3972
3960 hf = open(sysvals.htmlfile, 'w') 3973 hf = open(sysvals.htmlfile, 'w')
@@ -3970,7 +3983,7 @@ def createHTML(testruns, testfail):
3970 pscolor = 'linear-gradient(to top left, #ccc, #eee)' 3983 pscolor = 'linear-gradient(to top left, #ccc, #eee)'
3971 hf.write(devtl.html_phaselet.format('pre_suspend_process', \ 3984 hf.write(devtl.html_phaselet.format('pre_suspend_process', \
3972 '0', '0', pscolor)) 3985 '0', '0', pscolor))
3973 for b in data.phases: 3986 for b in data.sortedPhases():
3974 phase = data.dmesg[b] 3987 phase = data.dmesg[b]
3975 length = phase['end']-phase['start'] 3988 length = phase['end']-phase['start']
3976 left = '%.3f' % (((phase['start']-t0)*100.0)/tTotal) 3989 left = '%.3f' % (((phase['start']-t0)*100.0)/tTotal)
@@ -4542,16 +4555,12 @@ def setRuntimeSuspend(before=True):
4542def executeSuspend(): 4555def executeSuspend():
4543 pm = ProcessMonitor() 4556 pm = ProcessMonitor()
4544 tp = sysvals.tpath 4557 tp = sysvals.tpath
4545 fwdata = [] 4558 testdata = []
4559 battery = True if getBattery() else False
4546 # run these commands to prepare the system for suspend 4560 # run these commands to prepare the system for suspend
4547 if sysvals.display: 4561 if sysvals.display:
4548 if sysvals.display > 0: 4562 print('SET DISPLAY TO %s' % sysvals.display.upper())
4549 print('TURN DISPLAY ON') 4563 displayControl(sysvals.display)
4550 call('xset -d :0.0 dpms force suspend', shell=True)
4551 call('xset -d :0.0 dpms force on', shell=True)
4552 else:
4553 print('TURN DISPLAY OFF')
4554 call('xset -d :0.0 dpms force suspend', shell=True)
4555 time.sleep(1) 4564 time.sleep(1)
4556 if sysvals.sync: 4565 if sysvals.sync:
4557 print('SYNCING FILESYSTEMS') 4566 print('SYNCING FILESYSTEMS')
@@ -4579,6 +4588,7 @@ def executeSuspend():
4579 print('SUSPEND START') 4588 print('SUSPEND START')
4580 else: 4589 else:
4581 print('SUSPEND START (press a key to resume)') 4590 print('SUSPEND START (press a key to resume)')
4591 bat1 = getBattery() if battery else False
4582 # set rtcwake 4592 # set rtcwake
4583 if(sysvals.rtcwake): 4593 if(sysvals.rtcwake):
4584 print('will issue an rtcwake in %d seconds' % sysvals.rtcwaketime) 4594 print('will issue an rtcwake in %d seconds' % sysvals.rtcwaketime)
@@ -4592,8 +4602,11 @@ def executeSuspend():
4592 time.sleep(sysvals.predelay/1000.0) 4602 time.sleep(sysvals.predelay/1000.0)
4593 sysvals.fsetVal('WAIT END', 'trace_marker') 4603 sysvals.fsetVal('WAIT END', 'trace_marker')
4594 # initiate suspend or command 4604 # initiate suspend or command
4605 tdata = {'error': ''}
4595 if sysvals.testcommand != '': 4606 if sysvals.testcommand != '':
4596 call(sysvals.testcommand+' 2>&1', shell=True); 4607 res = call(sysvals.testcommand+' 2>&1', shell=True);
4608 if res != 0:
4609 tdata['error'] = 'cmd returned %d' % res
4597 else: 4610 else:
4598 mode = sysvals.suspendmode 4611 mode = sysvals.suspendmode
4599 if sysvals.memmode and os.path.exists(sysvals.mempowerfile): 4612 if sysvals.memmode and os.path.exists(sysvals.mempowerfile):
@@ -4606,8 +4619,8 @@ def executeSuspend():
4606 # execution will pause here 4619 # execution will pause here
4607 try: 4620 try:
4608 pf.close() 4621 pf.close()
4609 except: 4622 except Exception as e:
4610 pass 4623 tdata['error'] = str(e)
4611 if(sysvals.rtcwake): 4624 if(sysvals.rtcwake):
4612 sysvals.rtcWakeAlarmOff() 4625 sysvals.rtcWakeAlarmOff()
4613 # postdelay delay 4626 # postdelay delay
@@ -4620,23 +4633,29 @@ def executeSuspend():
4620 if(sysvals.usecallgraph or sysvals.usetraceevents): 4633 if(sysvals.usecallgraph or sysvals.usetraceevents):
4621 sysvals.fsetVal('RESUME COMPLETE', 'trace_marker') 4634 sysvals.fsetVal('RESUME COMPLETE', 'trace_marker')
4622 if(sysvals.suspendmode == 'mem' or sysvals.suspendmode == 'command'): 4635 if(sysvals.suspendmode == 'mem' or sysvals.suspendmode == 'command'):
4623 fwdata.append(getFPDT(False)) 4636 tdata['fw'] = getFPDT(False)
4637 bat2 = getBattery() if battery else False
4638 if battery and bat1 and bat2:
4639 tdata['bat'] = (bat1, bat2)
4640 testdata.append(tdata)
4624 # stop ftrace 4641 # stop ftrace
4625 if(sysvals.usecallgraph or sysvals.usetraceevents): 4642 if(sysvals.usecallgraph or sysvals.usetraceevents):
4626 if sysvals.useprocmon: 4643 if sysvals.useprocmon:
4627 pm.stop() 4644 pm.stop()
4628 sysvals.fsetVal('0', 'tracing_on') 4645 sysvals.fsetVal('0', 'tracing_on')
4646 # grab a copy of the dmesg output
4647 print('CAPTURING DMESG')
4648 sysvals.getdmesg(testdata)
4649 # grab a copy of the ftrace output
4650 if(sysvals.usecallgraph or sysvals.usetraceevents):
4629 print('CAPTURING TRACE') 4651 print('CAPTURING TRACE')
4630 op = sysvals.writeDatafileHeader(sysvals.ftracefile, fwdata) 4652 op = sysvals.writeDatafileHeader(sysvals.ftracefile, testdata)
4631 fp = open(tp+'trace', 'r') 4653 fp = open(tp+'trace', 'r')
4632 for line in fp: 4654 for line in fp:
4633 op.write(line) 4655 op.write(line)
4634 op.close() 4656 op.close()
4635 sysvals.fsetVal('', 'trace') 4657 sysvals.fsetVal('', 'trace')
4636 devProps() 4658 devProps()
4637 # grab a copy of the dmesg output
4638 print('CAPTURING DMESG')
4639 sysvals.getdmesg(fwdata)
4640 4659
4641def readFile(file): 4660def readFile(file):
4642 if os.path.islink(file): 4661 if os.path.islink(file):
@@ -4766,7 +4785,7 @@ def devProps(data=0):
4766 alreadystamped = True 4785 alreadystamped = True
4767 continue 4786 continue
4768 # determine the trace data type (required for further parsing) 4787 # determine the trace data type (required for further parsing)
4769 m = re.match(sysvals.tracertypefmt, line) 4788 m = re.match(tp.tracertypefmt, line)
4770 if(m): 4789 if(m):
4771 tp.setTracerType(m.group('t')) 4790 tp.setTracerType(m.group('t'))
4772 continue 4791 continue
@@ -4994,8 +5013,9 @@ def dmidecode(mempath, fatal=False):
4994 return out 5013 return out
4995 5014
4996def getBattery(): 5015def getBattery():
4997 p = '/sys/class/power_supply' 5016 p, charge, bat = '/sys/class/power_supply', 0, {}
4998 bat = dict() 5017 if not os.path.exists(p):
5018 return False
4999 for d in os.listdir(p): 5019 for d in os.listdir(p):
5000 type = sysvals.getVal(os.path.join(p, d, 'type')).strip().lower() 5020 type = sysvals.getVal(os.path.join(p, d, 'type')).strip().lower()
5001 if type != 'battery': 5021 if type != 'battery':
@@ -5003,15 +5023,42 @@ def getBattery():
5003 for v in ['status', 'energy_now', 'capacity_now']: 5023 for v in ['status', 'energy_now', 'capacity_now']:
5004 bat[v] = sysvals.getVal(os.path.join(p, d, v)).strip().lower() 5024 bat[v] = sysvals.getVal(os.path.join(p, d, v)).strip().lower()
5005 break 5025 break
5006 ac = True 5026 if 'status' not in bat:
5007 if 'status' in bat and 'discharging' in bat['status']: 5027 return False
5008 ac = False 5028 ac = False if 'discharging' in bat['status'] else True
5009 charge = 0
5010 for v in ['energy_now', 'capacity_now']: 5029 for v in ['energy_now', 'capacity_now']:
5011 if v in bat and bat[v]: 5030 if v in bat and bat[v]:
5012 charge = int(bat[v]) 5031 charge = int(bat[v])
5013 return (ac, charge) 5032 return (ac, charge)
5014 5033
5034def displayControl(cmd):
5035 xset, ret = 'xset -d :0.0 {0}', 0
5036 if sysvals.sudouser:
5037 xset = 'sudo -u %s %s' % (sysvals.sudouser, xset)
5038 if cmd == 'init':
5039 ret = call(xset.format('dpms 0 0 0'), shell=True)
5040 ret = call(xset.format('s off'), shell=True)
5041 elif cmd == 'reset':
5042 ret = call(xset.format('s reset'), shell=True)
5043 elif cmd in ['on', 'off', 'standby', 'suspend']:
5044 b4 = displayControl('stat')
5045 ret = call(xset.format('dpms force %s' % cmd), shell=True)
5046 curr = displayControl('stat')
5047 sysvals.vprint('Display Switched: %s -> %s' % (b4, curr))
5048 if curr != cmd:
5049 sysvals.vprint('WARNING: Display failed to change to %s' % cmd)
5050 elif cmd == 'stat':
5051 fp = Popen(xset.format('q').split(' '), stdout=PIPE).stdout
5052 ret = 'unknown'
5053 for line in fp:
5054 m = re.match('[\s]*Monitor is (?P<m>.*)', line)
5055 if(m and len(m.group('m')) >= 2):
5056 out = m.group('m').lower()
5057 ret = out[3:] if out[0:2] == 'in' else out
5058 break
5059 fp.close()
5060 return ret
5061
5015# Function: getFPDT 5062# Function: getFPDT
5016# Description: 5063# Description:
5017# Read the acpi bios tables and pull out FPDT, the firmware data 5064# Read the acpi bios tables and pull out FPDT, the firmware data
@@ -5149,7 +5196,7 @@ def getFPDT(output):
5149# Output: 5196# Output:
5150# True if the test will work, False if not 5197# True if the test will work, False if not
5151def statusCheck(probecheck=False): 5198def statusCheck(probecheck=False):
5152 status = True 5199 status = ''
5153 5200
5154 print('Checking this system (%s)...' % platform.node()) 5201 print('Checking this system (%s)...' % platform.node())
5155 5202
@@ -5160,7 +5207,7 @@ def statusCheck(probecheck=False):
5160 print(' have root access: %s' % res) 5207 print(' have root access: %s' % res)
5161 if(res != 'YES'): 5208 if(res != 'YES'):
5162 print(' Try running this script with sudo') 5209 print(' Try running this script with sudo')
5163 return False 5210 return 'missing root access'
5164 5211
5165 # check sysfs is mounted 5212 # check sysfs is mounted
5166 res = sysvals.colorText('NO (No features of this tool will work!)') 5213 res = sysvals.colorText('NO (No features of this tool will work!)')
@@ -5168,7 +5215,7 @@ def statusCheck(probecheck=False):
5168 res = 'YES' 5215 res = 'YES'
5169 print(' is sysfs mounted: %s' % res) 5216 print(' is sysfs mounted: %s' % res)
5170 if(res != 'YES'): 5217 if(res != 'YES'):
5171 return False 5218 return 'sysfs is missing'
5172 5219
5173 # check target mode is a valid mode 5220 # check target mode is a valid mode
5174 if sysvals.suspendmode != 'command': 5221 if sysvals.suspendmode != 'command':
@@ -5177,7 +5224,7 @@ def statusCheck(probecheck=False):
5177 if(sysvals.suspendmode in modes): 5224 if(sysvals.suspendmode in modes):
5178 res = 'YES' 5225 res = 'YES'
5179 else: 5226 else:
5180 status = False 5227 status = '%s mode is not supported' % sysvals.suspendmode
5181 print(' is "%s" a valid power mode: %s' % (sysvals.suspendmode, res)) 5228 print(' is "%s" a valid power mode: %s' % (sysvals.suspendmode, res))
5182 if(res == 'NO'): 5229 if(res == 'NO'):
5183 print(' valid power modes are: %s' % modes) 5230 print(' valid power modes are: %s' % modes)
@@ -5189,7 +5236,7 @@ def statusCheck(probecheck=False):
5189 if(ftgood): 5236 if(ftgood):
5190 res = 'YES' 5237 res = 'YES'
5191 elif(sysvals.usecallgraph): 5238 elif(sysvals.usecallgraph):
5192 status = False 5239 status = 'ftrace is not properly supported'
5193 print(' is ftrace supported: %s' % res) 5240 print(' is ftrace supported: %s' % res)
5194 5241
5195 # check if kprobes are available 5242 # check if kprobes are available
@@ -5217,7 +5264,7 @@ def statusCheck(probecheck=False):
5217 if(sysvals.rtcpath != ''): 5264 if(sysvals.rtcpath != ''):
5218 res = 'YES' 5265 res = 'YES'
5219 elif(sysvals.rtcwake): 5266 elif(sysvals.rtcwake):
5220 status = False 5267 status = 'rtcwake is not properly supported'
5221 print(' is rtcwake supported: %s' % res) 5268 print(' is rtcwake supported: %s' % res)
5222 5269
5223 if not probecheck: 5270 if not probecheck:
@@ -5245,7 +5292,7 @@ def doError(msg, help=False):
5245 printHelp() 5292 printHelp()
5246 print('ERROR: %s\n') % msg 5293 print('ERROR: %s\n') % msg
5247 sysvals.outputResult({'error':msg}) 5294 sysvals.outputResult({'error':msg})
5248 sys.exit() 5295 sys.exit(1)
5249 5296
5250# Function: getArgInt 5297# Function: getArgInt
5251# Description: 5298# Description:
@@ -5301,11 +5348,16 @@ def processData(live=False):
5301 appendIncompleteTraceLog(testruns) 5348 appendIncompleteTraceLog(testruns)
5302 sysvals.vprint('Command:\n %s' % sysvals.cmdline) 5349 sysvals.vprint('Command:\n %s' % sysvals.cmdline)
5303 for data in testruns: 5350 for data in testruns:
5351 if data.battery:
5352 a1, c1, a2, c2 = data.battery
5353 s = 'Battery:\n Before - AC: %s, Charge: %d\n After - AC: %s, Charge: %d' % \
5354 (a1, int(c1), a2, int(c2))
5355 sysvals.vprint(s)
5304 data.printDetails() 5356 data.printDetails()
5305 if sysvals.cgdump: 5357 if sysvals.cgdump:
5306 for data in testruns: 5358 for data in testruns:
5307 data.debugPrint() 5359 data.debugPrint()
5308 sys.exit() 5360 sys.exit(0)
5309 if len(testruns) < 1: 5361 if len(testruns) < 1:
5310 return (testruns, {'error': 'timeline generation failed'}) 5362 return (testruns, {'error': 'timeline generation failed'})
5311 sysvals.vprint('Creating the html timeline (%s)...' % sysvals.htmlfile) 5363 sysvals.vprint('Creating the html timeline (%s)...' % sysvals.htmlfile)
@@ -5335,6 +5387,7 @@ def rerunTest():
5335 elif not os.access(sysvals.htmlfile, os.W_OK): 5387 elif not os.access(sysvals.htmlfile, os.W_OK):
5336 doError('missing permission to write to %s' % sysvals.htmlfile) 5388 doError('missing permission to write to %s' % sysvals.htmlfile)
5337 testruns, stamp = processData(False) 5389 testruns, stamp = processData(False)
5390 sysvals.logmsg = ''
5338 return stamp 5391 return stamp
5339 5392
5340# Function: runTest 5393# Function: runTest
@@ -5349,13 +5402,16 @@ def runTest(n=0):
5349 executeSuspend() 5402 executeSuspend()
5350 sysvals.cleanupFtrace() 5403 sysvals.cleanupFtrace()
5351 if sysvals.skiphtml: 5404 if sysvals.skiphtml:
5352 sysvals.sudouser(sysvals.testdir) 5405 sysvals.sudoUserchown(sysvals.testdir)
5353 return 5406 return
5354 testruns, stamp = processData(True) 5407 testruns, stamp = processData(True)
5355 for data in testruns: 5408 for data in testruns:
5356 del data 5409 del data
5357 sysvals.sudouser(sysvals.testdir) 5410 sysvals.sudoUserchown(sysvals.testdir)
5358 sysvals.outputResult(stamp, n) 5411 sysvals.outputResult(stamp, n)
5412 if 'error' in stamp:
5413 return 2
5414 return 0
5359 5415
5360def find_in_html(html, start, end, firstonly=True): 5416def find_in_html(html, start, end, firstonly=True):
5361 n, out = 0, [] 5417 n, out = 0, []
@@ -5380,14 +5436,86 @@ def find_in_html(html, start, end, firstonly=True):
5380 return '' 5436 return ''
5381 return out 5437 return out
5382 5438
5439def data_from_html(file, outpath, devlist=False):
5440 html = open(file, 'r').read()
5441 suspend = find_in_html(html, 'Kernel Suspend', 'ms')
5442 resume = find_in_html(html, 'Kernel Resume', 'ms')
5443 line = find_in_html(html, '<div class="stamp">', '</div>')
5444 stmp = line.split()
5445 if not suspend or not resume or len(stmp) != 8:
5446 return False
5447 try:
5448 dt = datetime.strptime(' '.join(stmp[3:]), '%B %d %Y, %I:%M:%S %p')
5449 except:
5450 return False
5451 tstr = dt.strftime('%Y/%m/%d %H:%M:%S')
5452 error = find_in_html(html, '<table class="testfail"><tr><td>', '</td>')
5453 if error:
5454 m = re.match('[a-z]* failed in (?P<p>[a-z0-9_]*) phase', error)
5455 if m:
5456 result = 'fail in %s' % m.group('p')
5457 else:
5458 result = 'fail'
5459 else:
5460 result = 'pass'
5461 ilist = []
5462 e = find_in_html(html, 'class="err"[\w=":;\.%\- ]*>', '&rarr;</div>', False)
5463 for i in list(set(e)):
5464 ilist.append('%sx%d' % (i, e.count(i)) if e.count(i) > 1 else i)
5465 low = find_in_html(html, 'freeze time: <b>', ' ms</b>')
5466 if low and '|' in low:
5467 ilist.append('FREEZEx%d' % len(low.split('|')))
5468 devices = dict()
5469 for line in html.split('\n'):
5470 m = re.match(' *<div id=\"[a,0-9]*\" *title=\"(?P<title>.*)\" class=\"thread.*', line)
5471 if not m or 'thread kth' in line or 'thread sec' in line:
5472 continue
5473 m = re.match('(?P<n>.*) \((?P<t>[0-9,\.]*) ms\) (?P<p>.*)', m.group('title'))
5474 if not m:
5475 continue
5476 name, time, phase = m.group('n'), m.group('t'), m.group('p')
5477 if ' async' in name or ' sync' in name:
5478 name = ' '.join(name.split(' ')[:-1])
5479 d = phase.split('_')[0]
5480 if d not in devices:
5481 devices[d] = dict()
5482 if name not in devices[d]:
5483 devices[d][name] = 0.0
5484 devices[d][name] += float(time)
5485 worst = {'suspend': {'name':'', 'time': 0.0},
5486 'resume': {'name':'', 'time': 0.0}}
5487 for d in devices:
5488 if d not in worst:
5489 worst[d] = dict()
5490 dev = devices[d]
5491 if len(dev.keys()) > 0:
5492 n = sorted(dev, key=dev.get, reverse=True)[0]
5493 worst[d]['name'], worst[d]['time'] = n, dev[n]
5494 data = {
5495 'mode': stmp[2],
5496 'host': stmp[0],
5497 'kernel': stmp[1],
5498 'time': tstr,
5499 'result': result,
5500 'issues': ' '.join(ilist),
5501 'suspend': suspend,
5502 'resume': resume,
5503 'sus_worst': worst['suspend']['name'],
5504 'sus_worsttime': worst['suspend']['time'],
5505 'res_worst': worst['resume']['name'],
5506 'res_worsttime': worst['resume']['time'],
5507 'url': os.path.relpath(file, outpath),
5508 }
5509 if devlist:
5510 data['devlist'] = devices
5511 return data
5512
5383# Function: runSummary 5513# Function: runSummary
5384# Description: 5514# Description:
5385# create a summary of tests in a sub-directory 5515# create a summary of tests in a sub-directory
5386def runSummary(subdir, local=True, genhtml=False): 5516def runSummary(subdir, local=True, genhtml=False):
5387 inpath = os.path.abspath(subdir) 5517 inpath = os.path.abspath(subdir)
5388 outpath = inpath 5518 outpath = os.path.abspath('.') if local else inpath
5389 if local:
5390 outpath = os.path.abspath('.')
5391 print('Generating a summary of folder "%s"' % inpath) 5519 print('Generating a summary of folder "%s"' % inpath)
5392 if genhtml: 5520 if genhtml:
5393 for dirname, dirnames, filenames in os.walk(subdir): 5521 for dirname, dirnames, filenames in os.walk(subdir):
@@ -5409,36 +5537,9 @@ def runSummary(subdir, local=True, genhtml=False):
5409 for filename in filenames: 5537 for filename in filenames:
5410 if(not re.match('.*.html', filename)): 5538 if(not re.match('.*.html', filename)):
5411 continue 5539 continue
5412 file = os.path.join(dirname, filename) 5540 data = data_from_html(os.path.join(dirname, filename), outpath)
5413 html = open(file, 'r').read() 5541 if(not data):
5414 suspend = find_in_html(html, 'Kernel Suspend', 'ms')
5415 resume = find_in_html(html, 'Kernel Resume', 'ms')
5416 line = find_in_html(html, '<div class="stamp">', '</div>')
5417 stmp = line.split()
5418 if not suspend or not resume or len(stmp) != 8:
5419 continue 5542 continue
5420 try:
5421 dt = datetime.strptime(' '.join(stmp[3:]), '%B %d %Y, %I:%M:%S %p')
5422 except:
5423 continue
5424 tstr = dt.strftime('%Y/%m/%d %H:%M:%S')
5425 error = find_in_html(html, '<table class="testfail"><tr><td>', '</td>')
5426 result = 'fail' if error else 'pass'
5427 ilist = []
5428 e = find_in_html(html, 'class="err"[\w=":;\.%\- ]*>', '&rarr;</div>', False)
5429 for i in list(set(e)):
5430 ilist.append('%sx%d' % (i, e.count(i)) if e.count(i) > 1 else i)
5431 data = {
5432 'mode': stmp[2],
5433 'host': stmp[0],
5434 'kernel': stmp[1],
5435 'time': tstr,
5436 'result': result,
5437 'issues': ','.join(ilist),
5438 'suspend': suspend,
5439 'resume': resume,
5440 'url': os.path.relpath(file, outpath),
5441 }
5442 testruns.append(data) 5543 testruns.append(data)
5443 outfile = os.path.join(outpath, 'summary.html') 5544 outfile = os.path.join(outpath, 'summary.html')
5444 print('Summary file: %s' % outfile) 5545 print('Summary file: %s' % outfile)
@@ -5499,13 +5600,10 @@ def configFromFile(file):
5499 else: 5600 else:
5500 doError('invalid value --> (%s: %s), use "enable/disable"' % (option, value), True) 5601 doError('invalid value --> (%s: %s), use "enable/disable"' % (option, value), True)
5501 elif(option == 'display'): 5602 elif(option == 'display'):
5502 if value in switchvalues: 5603 disopt = ['on', 'off', 'standby', 'suspend']
5503 if value in switchoff: 5604 if value not in disopt:
5504 sysvals.display = -1 5605 doError('invalid value --> (%s: %s), use %s' % (option, value, disopt), True)
5505 else: 5606 sysvals.display = value
5506 sysvals.display = 1
5507 else:
5508 doError('invalid value --> (%s: %s), use "on/off"' % (option, value), True)
5509 elif(option == 'gzip'): 5607 elif(option == 'gzip'):
5510 sysvals.gzip = checkArgBool(option, value) 5608 sysvals.gzip = checkArgBool(option, value)
5511 elif(option == 'cgfilter'): 5609 elif(option == 'cgfilter'):
@@ -5521,9 +5619,9 @@ def configFromFile(file):
5521 sysvals.cgtest = getArgInt('cgtest', value, 0, 1, False) 5619 sysvals.cgtest = getArgInt('cgtest', value, 0, 1, False)
5522 elif(option == 'cgphase'): 5620 elif(option == 'cgphase'):
5523 d = Data(0) 5621 d = Data(0)
5524 if value not in d.phases: 5622 if value not in d.sortedPhases():
5525 doError('invalid phase --> (%s: %s), valid phases are %s'\ 5623 doError('invalid phase --> (%s: %s), valid phases are %s'\
5526 % (option, value, d.phases), True) 5624 % (option, value, d.sortedPhases()), True)
5527 sysvals.cgphase = value 5625 sysvals.cgphase = value
5528 elif(option == 'fadd'): 5626 elif(option == 'fadd'):
5529 file = sysvals.configFile(value) 5627 file = sysvals.configFile(value)
@@ -5697,7 +5795,7 @@ def printHelp():
5697 print(' [testprep]') 5795 print(' [testprep]')
5698 print(' -sync Sync the filesystems before starting the test') 5796 print(' -sync Sync the filesystems before starting the test')
5699 print(' -rs on/off Enable/disable runtime suspend for all devices, restore all after test') 5797 print(' -rs on/off Enable/disable runtime suspend for all devices, restore all after test')
5700 print(' -display on/off Turn the display on or off for the test') 5798 print(' -display m Change the display mode to m for the test (on/off/standby/suspend)')
5701 print(' [advanced]') 5799 print(' [advanced]')
5702 print(' -gzip Gzip the trace and dmesg logs to save space') 5800 print(' -gzip Gzip the trace and dmesg logs to save space')
5703 print(' -cmd {s} Run the timeline over a custom command, e.g. "sync -d"') 5801 print(' -cmd {s} Run the timeline over a custom command, e.g. "sync -d"')
@@ -5729,6 +5827,7 @@ def printHelp():
5729 print(' -status Test to see if the system is enabled to run this tool') 5827 print(' -status Test to see if the system is enabled to run this tool')
5730 print(' -fpdt Print out the contents of the ACPI Firmware Performance Data Table') 5828 print(' -fpdt Print out the contents of the ACPI Firmware Performance Data Table')
5731 print(' -battery Print out battery info (if available)') 5829 print(' -battery Print out battery info (if available)')
5830 print(' -x<mode> Test xset by toggling the given mode (on/off/standby/suspend)')
5732 print(' -sysinfo Print out system info extracted from BIOS') 5831 print(' -sysinfo Print out system info extracted from BIOS')
5733 print(' -devinfo Print out the pm settings of all devices which support runtime suspend') 5832 print(' -devinfo Print out the pm settings of all devices which support runtime suspend')
5734 print(' -flist Print the list of functions currently being captured in ftrace') 5833 print(' -flist Print the list of functions currently being captured in ftrace')
@@ -5745,7 +5844,9 @@ def printHelp():
5745if __name__ == '__main__': 5844if __name__ == '__main__':
5746 genhtml = False 5845 genhtml = False
5747 cmd = '' 5846 cmd = ''
5748 simplecmds = ['-sysinfo', '-modes', '-fpdt', '-flist', '-flistall', '-devinfo', '-status', '-battery'] 5847 simplecmds = ['-sysinfo', '-modes', '-fpdt', '-flist', '-flistall',
5848 '-devinfo', '-status', '-battery', '-xon', '-xoff', '-xstandby',
5849 '-xsuspend', '-xinit', '-xreset', '-xstat']
5749 if '-f' in sys.argv: 5850 if '-f' in sys.argv:
5750 sysvals.cgskip = sysvals.configFile('cgskip.txt') 5851 sysvals.cgskip = sysvals.configFile('cgskip.txt')
5751 # loop through the command line arguments 5852 # loop through the command line arguments
@@ -5763,10 +5864,10 @@ if __name__ == '__main__':
5763 cmd = arg[1:] 5864 cmd = arg[1:]
5764 elif(arg == '-h'): 5865 elif(arg == '-h'):
5765 printHelp() 5866 printHelp()
5766 sys.exit() 5867 sys.exit(0)
5767 elif(arg == '-v'): 5868 elif(arg == '-v'):
5768 print("Version %s" % sysvals.version) 5869 print("Version %s" % sysvals.version)
5769 sys.exit() 5870 sys.exit(0)
5770 elif(arg == '-x2'): 5871 elif(arg == '-x2'):
5771 sysvals.execcount = 2 5872 sysvals.execcount = 2
5772 elif(arg == '-x2delay'): 5873 elif(arg == '-x2delay'):
@@ -5785,6 +5886,10 @@ if __name__ == '__main__':
5785 genhtml = True 5886 genhtml = True
5786 elif(arg == '-addlogs'): 5887 elif(arg == '-addlogs'):
5787 sysvals.dmesglog = sysvals.ftracelog = True 5888 sysvals.dmesglog = sysvals.ftracelog = True
5889 elif(arg == '-addlogdmesg'):
5890 sysvals.dmesglog = True
5891 elif(arg == '-addlogftrace'):
5892 sysvals.ftracelog = True
5788 elif(arg == '-verbose'): 5893 elif(arg == '-verbose'):
5789 sysvals.verbose = True 5894 sysvals.verbose = True
5790 elif(arg == '-proc'): 5895 elif(arg == '-proc'):
@@ -5811,14 +5916,11 @@ if __name__ == '__main__':
5811 try: 5916 try:
5812 val = args.next() 5917 val = args.next()
5813 except: 5918 except:
5814 doError('-display requires "on" or "off"', True) 5919 doError('-display requires an mode value', True)
5815 if val.lower() in switchvalues: 5920 disopt = ['on', 'off', 'standby', 'suspend']
5816 if val.lower() in switchoff: 5921 if val.lower() not in disopt:
5817 sysvals.display = -1 5922 doError('valid display mode values are %s' % disopt, True)
5818 else: 5923 sysvals.display = val.lower()
5819 sysvals.display = 1
5820 else:
5821 doError('invalid option: %s, use "on/off"' % val, True)
5822 elif(arg == '-maxdepth'): 5924 elif(arg == '-maxdepth'):
5823 sysvals.max_graph_depth = getArgInt('-maxdepth', args, 0, 1000) 5925 sysvals.max_graph_depth = getArgInt('-maxdepth', args, 0, 1000)
5824 elif(arg == '-rtcwake'): 5926 elif(arg == '-rtcwake'):
@@ -5847,9 +5949,9 @@ if __name__ == '__main__':
5847 except: 5949 except:
5848 doError('No phase name supplied', True) 5950 doError('No phase name supplied', True)
5849 d = Data(0) 5951 d = Data(0)
5850 if val not in d.phases: 5952 if val not in d.phasedef:
5851 doError('invalid phase --> (%s: %s), valid phases are %s'\ 5953 doError('invalid phase --> (%s: %s), valid phases are %s'\
5852 % (arg, val, d.phases), True) 5954 % (arg, val, d.phasedef.keys()), True)
5853 sysvals.cgphase = val 5955 sysvals.cgphase = val
5854 elif(arg == '-cgfilter'): 5956 elif(arg == '-cgfilter'):
5855 try: 5957 try:
@@ -5951,6 +6053,7 @@ if __name__ == '__main__':
5951 except: 6053 except:
5952 doError('No result file supplied', True) 6054 doError('No result file supplied', True)
5953 sysvals.result = val 6055 sysvals.result = val
6056 sysvals.signalHandlerInit()
5954 else: 6057 else:
5955 doError('Invalid argument: '+arg, True) 6058 doError('Invalid argument: '+arg, True)
5956 6059
@@ -5975,12 +6078,20 @@ if __name__ == '__main__':
5975 6078
5976 # just run a utility command and exit 6079 # just run a utility command and exit
5977 if(cmd != ''): 6080 if(cmd != ''):
6081 ret = 0
5978 if(cmd == 'status'): 6082 if(cmd == 'status'):
5979 statusCheck(True) 6083 if not statusCheck(True):
6084 ret = 1
5980 elif(cmd == 'fpdt'): 6085 elif(cmd == 'fpdt'):
5981 getFPDT(True) 6086 if not getFPDT(True):
6087 ret = 1
5982 elif(cmd == 'battery'): 6088 elif(cmd == 'battery'):
5983 print 'AC Connect: %s\nCharge: %d' % getBattery() 6089 out = getBattery()
6090 if out:
6091 print 'AC Connect : %s\nBattery Charge: %d' % out
6092 else:
6093 print 'no battery found'
6094 ret = 1
5984 elif(cmd == 'sysinfo'): 6095 elif(cmd == 'sysinfo'):
5985 sysvals.printSystemInfo(True) 6096 sysvals.printSystemInfo(True)
5986 elif(cmd == 'devinfo'): 6097 elif(cmd == 'devinfo'):
@@ -5993,17 +6104,23 @@ if __name__ == '__main__':
5993 sysvals.getFtraceFilterFunctions(False) 6104 sysvals.getFtraceFilterFunctions(False)
5994 elif(cmd == 'summary'): 6105 elif(cmd == 'summary'):
5995 runSummary(sysvals.outdir, True, genhtml) 6106 runSummary(sysvals.outdir, True, genhtml)
5996 sys.exit() 6107 elif(cmd in ['xon', 'xoff', 'xstandby', 'xsuspend', 'xinit', 'xreset']):
6108 sysvals.verbose = True
6109 ret = displayControl(cmd[1:])
6110 elif(cmd == 'xstat'):
6111 print 'Display Status: %s' % displayControl('stat').upper()
6112 sys.exit(ret)
5997 6113
5998 # if instructed, re-analyze existing data files 6114 # if instructed, re-analyze existing data files
5999 if(sysvals.notestrun): 6115 if(sysvals.notestrun):
6000 stamp = rerunTest() 6116 stamp = rerunTest()
6001 sysvals.outputResult(stamp) 6117 sysvals.outputResult(stamp)
6002 sys.exit() 6118 sys.exit(0)
6003 6119
6004 # verify that we can run a test 6120 # verify that we can run a test
6005 if(not statusCheck()): 6121 error = statusCheck()
6006 doError('Check FAILED, aborting the test run!') 6122 if(error):
6123 doError(error)
6007 6124
6008 # extract mem modes and convert 6125 # extract mem modes and convert
6009 mode = sysvals.suspendmode 6126 mode = sysvals.suspendmode
@@ -6025,8 +6142,8 @@ if __name__ == '__main__':
6025 6142
6026 setRuntimeSuspend(True) 6143 setRuntimeSuspend(True)
6027 if sysvals.display: 6144 if sysvals.display:
6028 call('xset -d :0.0 dpms 0 0 0', shell=True) 6145 displayControl('init')
6029 call('xset -d :0.0 s off', shell=True) 6146 ret = 0
6030 if sysvals.multitest['run']: 6147 if sysvals.multitest['run']:
6031 # run multiple tests in a separate subdirectory 6148 # run multiple tests in a separate subdirectory
6032 if not sysvals.outdir: 6149 if not sysvals.outdir:
@@ -6041,17 +6158,18 @@ if __name__ == '__main__':
6041 print('TEST (%d/%d) START' % (i+1, sysvals.multitest['count'])) 6158 print('TEST (%d/%d) START' % (i+1, sysvals.multitest['count']))
6042 fmt = 'suspend-%y%m%d-%H%M%S' 6159 fmt = 'suspend-%y%m%d-%H%M%S'
6043 sysvals.testdir = os.path.join(sysvals.outdir, datetime.now().strftime(fmt)) 6160 sysvals.testdir = os.path.join(sysvals.outdir, datetime.now().strftime(fmt))
6044 runTest(i+1) 6161 ret = runTest(i+1)
6045 print('TEST (%d/%d) COMPLETE' % (i+1, sysvals.multitest['count'])) 6162 print('TEST (%d/%d) COMPLETE' % (i+1, sysvals.multitest['count']))
6046 sysvals.logmsg = '' 6163 sysvals.logmsg = ''
6047 if not sysvals.skiphtml: 6164 if not sysvals.skiphtml:
6048 runSummary(sysvals.outdir, False, False) 6165 runSummary(sysvals.outdir, False, False)
6049 sysvals.sudouser(sysvals.outdir) 6166 sysvals.sudoUserchown(sysvals.outdir)
6050 else: 6167 else:
6051 if sysvals.outdir: 6168 if sysvals.outdir:
6052 sysvals.testdir = sysvals.outdir 6169 sysvals.testdir = sysvals.outdir
6053 # run the test in the current directory 6170 # run the test in the current directory
6054 runTest() 6171 ret = runTest()
6055 if sysvals.display: 6172 if sysvals.display:
6056 call('xset -d :0.0 s reset', shell=True) 6173 displayControl('reset')
6057 setRuntimeSuspend(False) 6174 setRuntimeSuspend(False)
6175 sys.exit(ret)
generated by cgit v1.2.2 (git 2.25.0) at 2025-04-25 13:39:05 -0400