3 # Tool for analyzing suspend/resume timing
4 # Copyright (c) 2013, Intel Corporation.
6 # This program is free software; you can redistribute it and/or modify it
7 # under the terms and conditions of the GNU General Public License,
8 # version 2, as published by the Free Software Foundation.
10 # This program is distributed in the hope it will be useful, but WITHOUT
11 # ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
12 # FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License for
15 # You should have received a copy of the GNU General Public License along with
16 # this program; if not, write to the Free Software Foundation, Inc.,
17 # 51 Franklin St - Fifth Floor, Boston, MA 02110-1301 USA.
20 # Todd Brandt <todd.e.brandt@linux.intel.com>
23 # This tool is designed to assist kernel and OS developers in optimizing
24 # their linux stack's suspend/resume time. Using a kernel image built
25 # with a few extra options enabled, the tool will execute a suspend and
26 # will capture dmesg and ftrace data until resume is complete. This data
27 # is transformed into a device timeline and a callgraph to give a quick
28 # and detailed view of which devices and callbacks are taking the most
29 # time in suspend/resume. The output is a single html file which can be
30 # viewed in firefox or chrome.
32 # The following kernel build options are required:
34 # CONFIG_PM_SLEEP_DEBUG=y
36 # CONFIG_FUNCTION_TRACER=y
37 # CONFIG_FUNCTION_GRAPH_TRACER=y
39 # For kernel versions older than 3.15:
40 # The following additional kernel parameters are required:
41 # (e.g. in file /etc/default/grub)
42 # GRUB_CMDLINE_LINUX_DEFAULT="... initcall_debug log_buf_len=16M ..."
45 # ----------------- LIBRARIES --------------------
53 from datetime import datetime
56 # ----------------- CLASSES --------------------
60 # A global, single-instance container used to
61 # store system values and test parameters
66 tpath = '/sys/kernel/debug/tracing/'
67 fpdtpath = '/sys/firmware/acpi/tables/FPDT'
68 epath = '/sys/kernel/debug/tracing/events/power/'
71 'device_pm_callback_end',
72 'device_pm_callback_start'
75 'freeze': 'Suspend-To-Idle (S0)',
76 'standby': 'Power-On Suspend (S1)',
77 'mem': 'Suspend-to-RAM (S3)',
78 'disk': 'Suspend-to-disk (S4)'
81 powerfile = '/sys/power/state'
83 hostname = 'localhost'
99 usetraceevents = False
100 usetraceeventsonly = False
104 tracertypefmt = '# tracer: (?P<t>.*)'
105 firmwarefmt = '# fwsuspend (?P<s>[0-9]*) fwresume (?P<r>[0-9]*)$'
106 postresumefmt = '# post resume time (?P<t>[0-9]*)$'
107 stampfmt = '# suspend-(?P<m>[0-9]{2})(?P<d>[0-9]{2})(?P<y>[0-9]{2})-'+\
108 '(?P<H>[0-9]{2})(?P<M>[0-9]{2})(?P<S>[0-9]{2})'+\
109 ' (?P<host>.*) (?P<mode>.*) (?P<kernel>.*)$'
111 self.hostname = platform.node()
112 if(self.hostname == ''):
113 self.hostname = 'localhost'
115 if os.path.exists('/dev/rtc'):
116 rtc = os.readlink('/dev/rtc')
117 rtc = '/sys/class/rtc/'+rtc
118 if os.path.exists(rtc) and os.path.exists(rtc+'/date') and \
119 os.path.exists(rtc+'/time') and os.path.exists(rtc+'/wakealarm'):
121 def setOutputFile(self):
122 if((self.htmlfile == '') and (self.dmesgfile != '')):
123 m = re.match('(?P<name>.*)_dmesg\.txt$', self.dmesgfile)
125 self.htmlfile = m.group('name')+'.html'
126 if((self.htmlfile == '') and (self.ftracefile != '')):
127 m = re.match('(?P<name>.*)_ftrace\.txt$', self.ftracefile)
129 self.htmlfile = m.group('name')+'.html'
130 if(self.htmlfile == ''):
131 self.htmlfile = 'output.html'
132 def initTestOutput(self, subdir):
133 if(not self.android):
134 self.prefix = self.hostname
135 v = open('/proc/version', 'r').read().strip()
136 kver = string.split(v)[2]
138 self.prefix = 'android'
139 v = os.popen(self.adb+' shell cat /proc/version').read().strip()
140 kver = string.split(v)[2]
141 testtime = datetime.now().strftime('suspend-%m%d%y-%H%M%S')
143 self.testdir = subdir+"/"+testtime
145 self.testdir = testtime
147 '# '+testtime+' '+self.prefix+' '+self.suspendmode+' '+kver
149 self.testdir+'/'+self.prefix+'_'+self.suspendmode+'_dmesg.txt'
151 self.testdir+'/'+self.prefix+'_'+self.suspendmode+'_ftrace.txt'
153 self.testdir+'/'+self.prefix+'_'+self.suspendmode+'.html'
154 os.mkdir(self.testdir)
155 def setDeviceFilter(self, devnames):
156 self.devicefilter = string.split(devnames)
157 def rtcWakeAlarm(self):
158 os.system('echo 0 > '+self.rtcpath+'/wakealarm')
159 outD = open(self.rtcpath+'/date', 'r').read().strip()
160 outT = open(self.rtcpath+'/time', 'r').read().strip()
161 mD = re.match('^(?P<y>[0-9]*)-(?P<m>[0-9]*)-(?P<d>[0-9]*)', outD)
162 mT = re.match('^(?P<h>[0-9]*):(?P<m>[0-9]*):(?P<s>[0-9]*)', outT)
164 # get the current time from hardware
165 utcoffset = int((datetime.now() - datetime.utcnow()).total_seconds())
167 int(mD.group('y')), int(mD.group('m')), int(mD.group('d')),
168 int(mT.group('h')), int(mT.group('m')), int(mT.group('s')))
169 nowtime = int(dt.strftime('%s')) + utcoffset
171 # if hardware time fails, use the software time
172 nowtime = int(datetime.now().strftime('%s'))
173 alarm = nowtime + self.rtcwaketime
174 os.system('echo %d > %s/wakealarm' % (alarm, self.rtcpath))
176 sysvals = SystemValues()
180 # A container used to create a device hierachy, with a single root node
181 # and a tree of child nodes. Used by Data.deviceTopology()
186 def __init__(self, nodename, nodedepth):
189 self.depth = nodedepth
193 # The primary container for suspend/resume test data. There is one for
194 # each test run. The data is organized into a cronological hierarchy:
196 # root structure, started as dmesg & ftrace, but now only ftrace
197 # contents: times for suspend start/end, resume start/end, fwdata
199 # 10 sequential, non-overlapping phases of S/R
200 # contents: times for phase start/end, order/color data for html
202 # device callback or action list for this phase
204 # a single device callback or generic action
205 # contents: start/stop times, pid/cpu/driver info
206 # parents/children, html id for timeline/callgraph
207 # optionally includes an ftrace callgraph
208 # optionally includes intradev trace events
215 dmesg = {} # root data structure
216 phases = [] # ordered list of phases
217 start = 0.0 # test start
219 tSuspended = 0.0 # low-level suspend start
220 tResumed = 0.0 # low-level resume start
221 tLow = 0.0 # time spent in low-level suspend (standby/freeze)
222 fwValid = False # is firmware data available
223 fwSuspend = 0 # time spent in firmware suspend
224 fwResume = 0 # time spent in firmware resume
225 dmesgtext = [] # dmesg text file in memory
231 def __init__(self, num):
232 idchar = 'abcdefghijklmnopqrstuvwxyz'
233 self.testnumber = num
234 self.idstr = idchar[num]
237 self.dmesg = { # fixed list of 10 phases
238 'suspend_prepare': {'list': dict(), 'start': -1.0, 'end': -1.0,
239 'row': 0, 'color': '#CCFFCC', 'order': 0},
240 'suspend': {'list': dict(), 'start': -1.0, 'end': -1.0,
241 'row': 0, 'color': '#88FF88', 'order': 1},
242 'suspend_late': {'list': dict(), 'start': -1.0, 'end': -1.0,
243 'row': 0, 'color': '#00AA00', 'order': 2},
244 'suspend_noirq': {'list': dict(), 'start': -1.0, 'end': -1.0,
245 'row': 0, 'color': '#008888', 'order': 3},
246 'suspend_machine': {'list': dict(), 'start': -1.0, 'end': -1.0,
247 'row': 0, 'color': '#0000FF', 'order': 4},
248 'resume_machine': {'list': dict(), 'start': -1.0, 'end': -1.0,
249 'row': 0, 'color': '#FF0000', 'order': 5},
250 'resume_noirq': {'list': dict(), 'start': -1.0, 'end': -1.0,
251 'row': 0, 'color': '#FF9900', 'order': 6},
252 'resume_early': {'list': dict(), 'start': -1.0, 'end': -1.0,
253 'row': 0, 'color': '#FFCC00', 'order': 7},
254 'resume': {'list': dict(), 'start': -1.0, 'end': -1.0,
255 'row': 0, 'color': '#FFFF88', 'order': 8},
256 'resume_complete': {'list': dict(), 'start': -1.0, 'end': -1.0,
257 'row': 0, 'color': '#FFFFCC', 'order': 9}
259 self.phases = self.sortedPhases()
261 return self.dmesg[self.phases[0]]['start']
262 def setStart(self, time):
264 self.dmesg[self.phases[0]]['start'] = time
266 return self.dmesg[self.phases[-1]]['end']
267 def setEnd(self, time):
269 self.dmesg[self.phases[-1]]['end'] = time
270 def isTraceEventOutsideDeviceCalls(self, pid, time):
271 for phase in self.phases:
272 list = self.dmesg[phase]['list']
275 if(d['pid'] == pid and time >= d['start'] and
279 def addIntraDevTraceEvent(self, action, name, pid, time):
280 if(action == 'mutex_lock_try'):
282 elif(action == 'mutex_lock_pass'):
284 elif(action == 'mutex_unlock'):
287 # create separate colors based on the name
288 v1 = len(name)*10 % 256
289 v2 = string.count(name, 'e')*100 % 256
290 v3 = ord(name[0])*20 % 256
291 color = '#%06X' % ((v1*0x10000) + (v2*0x100) + v3)
292 for phase in self.phases:
293 list = self.dmesg[phase]['list']
296 if(d['pid'] == pid and time >= d['start'] and
298 e = TraceEvent(action, name, color, time)
299 if('traceevents' not in d):
300 d['traceevents'] = []
301 d['traceevents'].append(e)
305 def capIntraDevTraceEvent(self, action, name, pid, time):
306 for phase in self.phases:
307 list = self.dmesg[phase]['list']
310 if(d['pid'] == pid and time >= d['start'] and
312 if('traceevents' not in d):
314 for e in d['traceevents']:
315 if(e.action == action and
316 e.name == name and not e.ready):
317 e.length = time - e.time
321 def trimTimeVal(self, t, t0, dT, left):
336 def trimTime(self, t0, dT, left):
337 self.tSuspended = self.trimTimeVal(self.tSuspended, t0, dT, left)
338 self.tResumed = self.trimTimeVal(self.tResumed, t0, dT, left)
339 self.start = self.trimTimeVal(self.start, t0, dT, left)
340 self.end = self.trimTimeVal(self.end, t0, dT, left)
341 for phase in self.phases:
342 p = self.dmesg[phase]
343 p['start'] = self.trimTimeVal(p['start'], t0, dT, left)
344 p['end'] = self.trimTimeVal(p['end'], t0, dT, left)
348 d['start'] = self.trimTimeVal(d['start'], t0, dT, left)
349 d['end'] = self.trimTimeVal(d['end'], t0, dT, left)
352 cg.start = self.trimTimeVal(cg.start, t0, dT, left)
353 cg.end = self.trimTimeVal(cg.end, t0, dT, left)
355 line.time = self.trimTimeVal(line.time, t0, dT, left)
356 if('traceevents' in d):
357 for e in d['traceevents']:
358 e.time = self.trimTimeVal(e.time, t0, dT, left)
359 def normalizeTime(self, tZero):
360 # first trim out any standby or freeze clock time
361 if(self.tSuspended != self.tResumed):
362 if(self.tResumed > tZero):
363 self.trimTime(self.tSuspended, \
364 self.tResumed-self.tSuspended, True)
366 self.trimTime(self.tSuspended, \
367 self.tResumed-self.tSuspended, False)
368 # shift the timeline so that tZero is the new 0
369 self.tSuspended -= tZero
370 self.tResumed -= tZero
373 for phase in self.phases:
374 p = self.dmesg[phase]
388 if('traceevents' in d):
389 for e in d['traceevents']:
391 def newPhaseWithSingleAction(self, phasename, devname, start, end, color):
392 for phase in self.phases:
393 self.dmesg[phase]['order'] += 1
394 self.html_device_id += 1
395 devid = '%s%d' % (self.idstr, self.html_device_id)
398 {'start': start, 'end': end, 'pid': 0, 'par': '',
399 'length': (end-start), 'row': 0, 'id': devid, 'drv': '' };
400 self.dmesg[phasename] = \
401 {'list': list, 'start': start, 'end': end,
402 'row': 0, 'color': color, 'order': 0}
403 self.phases = self.sortedPhases()
404 def newPhase(self, phasename, start, end, color, order):
406 order = len(self.phases)
407 for phase in self.phases[order:]:
408 self.dmesg[phase]['order'] += 1
410 p = self.phases[order-1]
411 self.dmesg[p]['end'] = start
412 if(order < len(self.phases)):
413 p = self.phases[order]
414 self.dmesg[p]['start'] = end
416 self.dmesg[phasename] = \
417 {'list': list, 'start': start, 'end': end,
418 'row': 0, 'color': color, 'order': order}
419 self.phases = self.sortedPhases()
420 def setPhase(self, phase, ktime, isbegin):
422 self.dmesg[phase]['start'] = ktime
424 self.dmesg[phase]['end'] = ktime
425 def dmesgSortVal(self, phase):
426 return self.dmesg[phase]['order']
427 def sortedPhases(self):
428 return sorted(self.dmesg, key=self.dmesgSortVal)
429 def sortedDevices(self, phase):
430 list = self.dmesg[phase]['list']
435 tmp[dev['start']] = devname
436 for t in sorted(tmp):
439 def fixupInitcalls(self, phase, end):
440 # if any calls never returned, clip them at system resume end
441 phaselist = self.dmesg[phase]['list']
442 for devname in phaselist:
443 dev = phaselist[devname]
446 vprint('%s (%s): callback didnt return' % (devname, phase))
447 def deviceFilter(self, devicefilter):
448 # remove all by the relatives of the filter devnames
450 for phase in self.phases:
451 list = self.dmesg[phase]['list']
452 for name in devicefilter:
455 if(dev not in filter):
457 dev = list[dev]['par']
458 children = self.deviceDescendants(name, phase)
460 if(dev not in filter):
462 for phase in self.phases:
463 list = self.dmesg[phase]['list']
466 pid = list[name]['pid']
467 if(name not in filter and pid >= 0):
471 def fixupInitcallsThatDidntReturn(self):
472 # if any calls never returned, clip them at system resume end
473 for phase in self.phases:
474 self.fixupInitcalls(phase, self.getEnd())
475 def newActionGlobal(self, name, start, end):
476 # which phase is this device callback or action "in"
479 for phase in self.phases:
480 pstart = self.dmesg[phase]['start']
481 pend = self.dmesg[phase]['end']
482 o = max(0, min(end, pend) - max(start, pstart))
486 if targetphase in self.phases:
487 self.newAction(targetphase, name, -1, '', start, end, '')
490 def newAction(self, phase, name, pid, parent, start, end, drv):
491 # new device callback for a specific phase
492 self.html_device_id += 1
493 devid = '%s%d' % (self.idstr, self.html_device_id)
494 list = self.dmesg[phase]['list']
496 if(start >= 0 and end >= 0):
498 list[name] = {'start': start, 'end': end, 'pid': pid, 'par': parent,
499 'length': length, 'row': 0, 'id': devid, 'drv': drv }
500 def deviceIDs(self, devlist, phase):
502 list = self.dmesg[phase]['list']
504 if devname in devlist:
505 idlist.append(list[devname]['id'])
507 def deviceParentID(self, devname, phase):
510 list = self.dmesg[phase]['list']
512 pdev = list[devname]['par']
514 return list[pdev]['id']
516 def deviceChildren(self, devname, phase):
518 list = self.dmesg[phase]['list']
520 if(list[child]['par'] == devname):
521 devlist.append(child)
523 def deviceDescendants(self, devname, phase):
524 children = self.deviceChildren(devname, phase)
526 for child in children:
527 family += self.deviceDescendants(child, phase)
529 def deviceChildrenIDs(self, devname, phase):
530 devlist = self.deviceChildren(devname, phase)
531 return self.deviceIDs(devlist, phase)
532 def printDetails(self):
533 vprint(' test start: %f' % self.start)
534 for phase in self.phases:
535 dc = len(self.dmesg[phase]['list'])
536 vprint(' %16s: %f - %f (%d devices)' % (phase, \
537 self.dmesg[phase]['start'], self.dmesg[phase]['end'], dc))
538 vprint(' test end: %f' % self.end)
539 def masterTopology(self, name, list, depth):
540 node = DeviceNode(name, depth)
542 clist = self.deviceChildren(cname, 'resume')
543 cnode = self.masterTopology(cname, clist, depth+1)
544 node.children.append(cnode)
546 def printTopology(self, node):
551 for phase in self.phases:
552 list = self.dmesg[phase]['list']
553 if node.name in list:
554 s = list[node.name]['start']
555 e = list[node.name]['end']
556 if list[node.name]['drv']:
557 drv = ' {'+list[node.name]['drv']+'}'
558 info += ('<li>%s: %.3fms</li>' % (phase, (e-s)*1000))
559 html += '<li><b>'+node.name+drv+'</b>'
561 html += '<ul>'+info+'</ul>'
563 if len(node.children) > 0:
565 for cnode in node.children:
566 html += self.printTopology(cnode)
569 def rootDeviceList(self):
570 # list of devices graphed
572 for phase in self.dmesg:
573 list = self.dmesg[phase]['list']
575 if list[dev]['pid'] >= 0 and dev not in real:
577 # list of top-most root devices
579 for phase in self.dmesg:
580 list = self.dmesg[phase]['list']
582 pdev = list[dev]['par']
583 if(re.match('[0-9]*-[0-9]*\.[0-9]*[\.0-9]*\:[\.0-9]*$', pdev)):
585 if pdev and pdev not in real and pdev not in rootlist:
586 rootlist.append(pdev)
588 def deviceTopology(self):
589 rootlist = self.rootDeviceList()
590 master = self.masterTopology('', rootlist, 0)
591 return self.printTopology(master)
595 # A container for trace event data found in the ftrace file
603 def __init__(self, a, n, c, t):
611 # A container for a single line of ftrace data. There are six basic types:
613 # call: " dpm_run_callback() {"
615 # leaf: " dpm_run_callback();"
617 # tracing_mark_write: SUSPEND START or RESUME COMPLETE
618 # suspend_resume: phase or custom exec block data
619 # device_pm_callback: device callback info
629 def __init__(self, t, m, d):
631 # is this a trace event
632 if(d == 'traceevent' or re.match('^ *\/\* *(?P<msg>.*) \*\/ *$', m)):
633 if(d == 'traceevent'):
634 # nop format trace event
637 # function_graph format trace event
638 em = re.match('^ *\/\* *(?P<msg>.*) \*\/ *$', m)
639 msg = em.group('msg')
641 emm = re.match('^(?P<call>.*?): (?P<msg>.*)', msg)
643 self.name = emm.group('msg')
644 self.type = emm.group('call')
649 # convert the duration to seconds
651 self.length = float(d)/1000000
652 # the indentation determines the depth
653 match = re.match('^(?P<d> *)(?P<o>.*)$', m)
656 self.depth = self.getDepth(match.group('d'))
662 # includes comment with function name
663 match = re.match('^} *\/\* *(?P<n>.*) *\*\/$', m)
665 self.name = match.group('n')
669 # function call with children
671 match = re.match('^(?P<n>.*) *\(.*', m)
673 self.name = match.group('n')
674 # function call with no children (leaf)
677 match = re.match('^(?P<n>.*) *\(.*', m)
679 self.name = match.group('n')
680 # something else (possibly a trace marker)
683 def getDepth(self, str):
685 def debugPrint(self, dev):
686 if(self.freturn and self.fcall):
687 print('%s -- %f (%02d): %s(); (%.3f us)' % (dev, self.time, \
688 self.depth, self.name, self.length*1000000))
690 print('%s -- %f (%02d): %s} (%.3f us)' % (dev, self.time, \
691 self.depth, self.name, self.length*1000000))
693 print('%s -- %f (%02d): %s() { (%.3f us)' % (dev, self.time, \
694 self.depth, self.name, self.length*1000000))
696 # Class: FTraceCallGraph
698 # A container for the ftrace callgraph of a single recursive function.
699 # This can be a dpm_run_callback, dpm_prepare, or dpm_complete callgraph
700 # Each instance is tied to a single device in a single phase, and is
701 # comprised of an ordered list of FTraceLine objects
702 class FTraceCallGraph:
713 def setDepth(self, line):
714 if(line.fcall and not line.freturn):
715 line.depth = self.depth
717 elif(line.freturn and not line.fcall):
719 line.depth = self.depth
721 line.depth = self.depth
722 def addLine(self, line, match):
723 if(not self.invalid):
725 if(line.depth == 0 and line.freturn):
727 self.start = line.time
729 self.list.append(line)
733 if(len(self.list) >= 1000000 or self.depth < 0):
734 if(len(self.list) > 0):
737 self.list.append(first)
741 id = 'task %s cpu %s' % (match.group('pid'), match.group('cpu'))
742 window = '(%f - %f)' % (self.start, line.time)
744 print('Too much data for '+id+\
745 ' (buffer overflow), ignoring this callback')
747 print('Too much data for '+id+\
748 ' '+window+', ignoring this callback')
750 self.list.append(line)
752 self.start = line.time
754 def slice(self, t0, tN):
755 minicg = FTraceCallGraph()
759 if(l.time < t0 or l.time > tN):
762 if(not l.fcall or l.name == 'dev_driver_string'):
766 l.depth -= firstdepth
768 if((count == 0 and l.freturn and l.fcall) or
769 (count > 0 and l.depth <= 0)):
773 def sanityCheck(self):
777 if(l.fcall and not l.freturn):
780 elif(l.freturn and not l.fcall):
781 if(l.depth not in stack):
783 stack[l.depth].length = l.length
790 def debugPrint(self, filename):
791 if(filename == 'stdout'):
792 print('[%f - %f]') % (self.start, self.end)
794 if(l.freturn and l.fcall):
795 print('%f (%02d): %s(); (%.3f us)' % (l.time, \
796 l.depth, l.name, l.length*1000000))
798 print('%f (%02d): %s} (%.3f us)' % (l.time, \
799 l.depth, l.name, l.length*1000000))
801 print('%f (%02d): %s() { (%.3f us)' % (l.time, \
802 l.depth, l.name, l.length*1000000))
805 fp = open(filename, 'w')
808 if(l.freturn and l.fcall):
809 fp.write('%f (%02d): %s(); (%.3f us)\n' % (l.time, \
810 l.depth, l.name, l.length*1000000))
812 fp.write('%f (%02d): %s} (%.3f us)\n' % (l.time, \
813 l.depth, l.name, l.length*1000000))
815 fp.write('%f (%02d): %s() { (%.3f us)\n' % (l.time, \
816 l.depth, l.name, l.length*1000000))
821 # A container for a suspend/resume html timeline. In older versions
822 # of the script there were multiple timelines, but in the latest
826 scaleH = 0.0 # height of the row as a percent of the timeline height
827 rowH = 0.0 # height of each row in percent of the timeline height
828 row_height_pixels = 30
837 def setRows(self, rows):
838 self.maxrows = int(rows)
839 self.scaleH = 100.0/float(self.maxrows)
840 self.height = self.maxrows*self.row_height_pixels
841 r = float(self.maxrows - 1)
844 self.rowH = (100.0 - self.scaleH)/r
848 # A container for a suspend/resume test run. This is necessary as
849 # there could be more than one, and they need to be separate.
851 ftrace_line_fmt_fg = \
852 '^ *(?P<time>[0-9\.]*) *\| *(?P<cpu>[0-9]*)\)'+\
853 ' *(?P<proc>.*)-(?P<pid>[0-9]*) *\|'+\
854 '[ +!]*(?P<dur>[0-9\.]*) .*\| (?P<msg>.*)'
855 ftrace_line_fmt_nop = \
856 ' *(?P<proc>.*)-(?P<pid>[0-9]*) *\[(?P<cpu>[0-9]*)\] *'+\
857 '(?P<flags>.{4}) *(?P<time>[0-9\.]*): *'+\
859 ftrace_line_fmt = ftrace_line_fmt_nop
866 def __init__(self, dataobj):
871 if(tracertype == '' or not data):
874 def setTracerType(self, tracer):
875 self.tracertype = tracer
876 if(tracer == 'function_graph'):
878 self.ftrace_line_fmt = self.ftrace_line_fmt_fg
879 elif(tracer == 'nop'):
880 self.ftrace_line_fmt = self.ftrace_line_fmt_nop
882 doError('Invalid tracer format: [%s]' % tracer, False)
884 # ----------------- FUNCTIONS --------------------
888 # verbose print (prints only with -verbose option)
890 # msg: the debug/log message to print
896 # Function: initFtrace
898 # Configure ftrace to use trace events and/or a callgraph
903 cf = 'dpm_run_callback'
904 if(sysvals.usetraceeventsonly):
905 cf = '-e dpm_prepare -e dpm_complete -e dpm_run_callback'
906 if(sysvals.usecallgraph or sysvals.usetraceevents):
907 print('INITIALIZING FTRACE...')
909 os.system('echo 0 > '+tp+'tracing_on')
910 # set the trace clock to global
911 os.system('echo global > '+tp+'trace_clock')
912 # set trace buffer to a huge value
913 os.system('echo nop > '+tp+'current_tracer')
914 os.system('echo 100000 > '+tp+'buffer_size_kb')
915 # initialize the callgraph trace, unless this is an x2 run
916 if(sysvals.usecallgraph and sysvals.execcount == 1):
918 os.system('echo function_graph > '+tp+'current_tracer')
919 os.system('echo "" > '+tp+'set_ftrace_filter')
920 # set trace format options
921 os.system('echo funcgraph-abstime > '+tp+'trace_options')
922 os.system('echo funcgraph-proc > '+tp+'trace_options')
923 # focus only on device suspend and resume
924 os.system('cat '+tp+'available_filter_functions | grep '+\
925 cf+' > '+tp+'set_graph_function')
926 if(sysvals.usetraceevents):
927 # turn trace events on
928 events = iter(sysvals.traceevents)
930 os.system('echo 1 > '+sysvals.epath+e+'/enable')
931 # clear the trace buffer
932 os.system('echo "" > '+tp+'trace')
934 # Function: initFtraceAndroid
936 # Configure ftrace to capture trace events
937 def initFtraceAndroid():
941 if(sysvals.usetraceevents):
942 print('INITIALIZING FTRACE...')
944 os.system(sysvals.adb+" shell 'echo 0 > "+tp+"tracing_on'")
945 # set the trace clock to global
946 os.system(sysvals.adb+" shell 'echo global > "+tp+"trace_clock'")
947 # set trace buffer to a huge value
948 os.system(sysvals.adb+" shell 'echo nop > "+tp+"current_tracer'")
949 os.system(sysvals.adb+" shell 'echo 10000 > "+tp+"buffer_size_kb'")
950 # turn trace events on
951 events = iter(sysvals.traceevents)
953 os.system(sysvals.adb+" shell 'echo 1 > "+\
954 sysvals.epath+e+"/enable'")
955 # clear the trace buffer
956 os.system(sysvals.adb+" shell 'echo \"\" > "+tp+"trace'")
958 # Function: verifyFtrace
960 # Check that ftrace is working on the system
965 # files needed for any trace data
966 files = ['buffer_size_kb', 'current_tracer', 'trace', 'trace_clock',
967 'trace_marker', 'trace_options', 'tracing_on']
968 # files needed for callgraph trace data
970 if(sysvals.usecallgraph):
972 'available_filter_functions',
978 out = os.popen(sysvals.adb+' shell ls '+tp+f).read().strip()
982 if(os.path.exists(tp+f) == False):
986 # Function: parseStamp
988 # Pull in the stamp comment line from the data file(s),
989 # create the stamp, and add it to the global sysvals object
991 # m: the valid re.match output for the stamp line
992 def parseStamp(m, data):
994 data.stamp = {'time': '', 'host': '', 'mode': ''}
995 dt = datetime(int(m.group('y'))+2000, int(m.group('m')),
996 int(m.group('d')), int(m.group('H')), int(m.group('M')),
998 data.stamp['time'] = dt.strftime('%B %d %Y, %I:%M:%S %p')
999 data.stamp['host'] = m.group('host')
1000 data.stamp['mode'] = m.group('mode')
1001 data.stamp['kernel'] = m.group('kernel')
1002 sysvals.suspendmode = data.stamp['mode']
1003 if not sysvals.stamp:
1004 sysvals.stamp = data.stamp
1006 # Function: diffStamp
1008 # compare the host, kernel, and mode fields in 3 stamps
1010 # stamp1: string array with mode, kernel, and host
1011 # stamp2: string array with mode, kernel, and host
1013 # True if stamps differ, False if they're the same
1014 def diffStamp(stamp1, stamp2):
1015 if 'host' in stamp1 and 'host' in stamp2:
1016 if stamp1['host'] != stamp2['host']:
1018 if 'kernel' in stamp1 and 'kernel' in stamp2:
1019 if stamp1['kernel'] != stamp2['kernel']:
1021 if 'mode' in stamp1 and 'mode' in stamp2:
1022 if stamp1['mode'] != stamp2['mode']:
1026 # Function: doesTraceLogHaveTraceEvents
1028 # Quickly determine if the ftrace log has some or all of the trace events
1029 # required for primary parsing. Set the usetraceevents and/or
1030 # usetraceeventsonly flags in the global sysvals object
1031 def doesTraceLogHaveTraceEvents():
1034 sysvals.usetraceeventsonly = True
1035 sysvals.usetraceevents = False
1036 for e in sysvals.traceevents:
1037 out = os.popen('cat '+sysvals.ftracefile+' | grep "'+e+': "').read()
1039 sysvals.usetraceeventsonly = False
1040 if(e == 'suspend_resume' and out):
1041 sysvals.usetraceevents = True
1043 # Function: appendIncompleteTraceLog
1045 # [deprecated for kernel 3.15 or newer]
1046 # Legacy support of ftrace outputs that lack the device_pm_callback
1047 # and/or suspend_resume trace events. The primary data should be
1048 # taken from dmesg, and this ftrace is used only for callgraph data
1049 # or custom actions in the timeline. The data is appended to the Data
1052 # testruns: the array of Data objects obtained from parseKernelLog
1053 def appendIncompleteTraceLog(testruns):
1056 # create TestRun vessels for ftrace parsing
1057 testcnt = len(testruns)
1060 for data in testruns:
1061 testrun.append(TestRun(data))
1063 # extract the callgraph and traceevent data
1064 vprint('Analyzing the ftrace data...')
1065 tf = open(sysvals.ftracefile, 'r')
1067 # remove any latent carriage returns
1068 line = line.replace('\r\n', '')
1069 # grab the time stamp first (signifies the start of the test run)
1070 m = re.match(sysvals.stampfmt, line)
1073 parseStamp(m, testrun[testidx].data)
1075 # pull out any firmware data
1076 if(re.match(sysvals.firmwarefmt, line)):
1078 # if we havent found a test time stamp yet keep spinning til we do
1081 # determine the trace data type (required for further parsing)
1082 m = re.match(sysvals.tracertypefmt, line)
1084 tracer = m.group('t')
1085 testrun[testidx].setTracerType(tracer)
1087 # parse only valid lines, if this isnt one move on
1088 m = re.match(testrun[testidx].ftrace_line_fmt, line)
1091 # gather the basic message data from the line
1092 m_time = m.group('time')
1093 m_pid = m.group('pid')
1094 m_msg = m.group('msg')
1095 if(testrun[testidx].cgformat):
1096 m_param3 = m.group('dur')
1098 m_param3 = 'traceevent'
1099 if(m_time and m_pid and m_msg):
1100 t = FTraceLine(m_time, m_msg, m_param3)
1104 # the line should be a call, return, or event
1105 if(not t.fcall and not t.freturn and not t.fevent):
1107 # only parse the ftrace data during suspend/resume
1108 data = testrun[testidx].data
1109 if(not testrun[testidx].inthepipe):
1110 # look for the suspend start marker
1112 if(t.name == 'SUSPEND START'):
1113 testrun[testidx].inthepipe = True
1114 data.setStart(t.time)
1117 # trace event processing
1119 if(t.name == 'RESUME COMPLETE'):
1120 testrun[testidx].inthepipe = False
1122 if(testidx == testcnt - 1):
1125 # general trace events have two types, begin and end
1126 if(re.match('(?P<name>.*) begin$', t.name)):
1128 elif(re.match('(?P<name>.*) end$', t.name)):
1132 m = re.match('(?P<name>.*)\[(?P<val>[0-9]*)\] .*', t.name)
1134 val = m.group('val')
1136 name = m.group('name')
1138 name = m.group('name')+'['+val+']'
1140 m = re.match('(?P<name>.*) .*', t.name)
1141 name = m.group('name')
1142 # special processing for trace events
1143 if re.match('dpm_prepare\[.*', name):
1145 elif re.match('machine_suspend.*', name):
1147 elif re.match('suspend_enter\[.*', name):
1149 data.dmesg['suspend_prepare']['end'] = t.time
1151 elif re.match('dpm_suspend\[.*', name):
1153 data.dmesg['suspend']['end'] = t.time
1155 elif re.match('dpm_suspend_late\[.*', name):
1157 data.dmesg['suspend_late']['start'] = t.time
1159 data.dmesg['suspend_late']['end'] = t.time
1161 elif re.match('dpm_suspend_noirq\[.*', name):
1163 data.dmesg['suspend_noirq']['start'] = t.time
1165 data.dmesg['suspend_noirq']['end'] = t.time
1167 elif re.match('dpm_resume_noirq\[.*', name):
1169 data.dmesg['resume_machine']['end'] = t.time
1170 data.dmesg['resume_noirq']['start'] = t.time
1172 data.dmesg['resume_noirq']['end'] = t.time
1174 elif re.match('dpm_resume_early\[.*', name):
1176 data.dmesg['resume_early']['start'] = t.time
1178 data.dmesg['resume_early']['end'] = t.time
1180 elif re.match('dpm_resume\[.*', name):
1182 data.dmesg['resume']['start'] = t.time
1184 data.dmesg['resume']['end'] = t.time
1186 elif re.match('dpm_complete\[.*', name):
1188 data.dmesg['resume_complete']['start'] = t.time
1190 data.dmesg['resume_complete']['end'] = t.time
1192 # is this trace event outside of the devices calls
1193 if(data.isTraceEventOutsideDeviceCalls(pid, t.time)):
1194 # global events (outside device calls) are simply graphed
1196 # store each trace event in ttemp
1197 if(name not in testrun[testidx].ttemp):
1198 testrun[testidx].ttemp[name] = []
1199 testrun[testidx].ttemp[name].append(\
1200 {'begin': t.time, 'end': t.time})
1202 # finish off matching trace event in ttemp
1203 if(name in testrun[testidx].ttemp):
1204 testrun[testidx].ttemp[name][-1]['end'] = t.time
1207 data.addIntraDevTraceEvent('', name, pid, t.time)
1209 data.capIntraDevTraceEvent('', name, pid, t.time)
1210 # call/return processing
1211 elif sysvals.usecallgraph:
1212 # create a callgraph object for the data
1213 if(pid not in testrun[testidx].ftemp):
1214 testrun[testidx].ftemp[pid] = []
1215 testrun[testidx].ftemp[pid].append(FTraceCallGraph())
1216 # when the call is finished, see which device matches it
1217 cg = testrun[testidx].ftemp[pid][-1]
1218 if(cg.addLine(t, m)):
1219 testrun[testidx].ftemp[pid].append(FTraceCallGraph())
1222 for test in testrun:
1223 # add the traceevent data to the device hierarchy
1224 if(sysvals.usetraceevents):
1225 for name in test.ttemp:
1226 for event in test.ttemp[name]:
1227 begin = event['begin']
1229 # if event starts before timeline start, expand timeline
1230 if(begin < test.data.start):
1231 test.data.setStart(begin)
1232 # if event ends after timeline end, expand the timeline
1233 if(end > test.data.end):
1234 test.data.setEnd(end)
1235 test.data.newActionGlobal(name, begin, end)
1237 # add the callgraph data to the device hierarchy
1238 for pid in test.ftemp:
1239 for cg in test.ftemp[pid]:
1240 if(not cg.sanityCheck()):
1241 id = 'task %s cpu %s' % (pid, m.group('cpu'))
1242 vprint('Sanity check failed for '+\
1243 id+', ignoring this callback')
1245 callstart = cg.start
1247 for p in test.data.phases:
1248 if(test.data.dmesg[p]['start'] <= callstart and
1249 callstart <= test.data.dmesg[p]['end']):
1250 list = test.data.dmesg[p]['list']
1251 for devname in list:
1253 if(pid == dev['pid'] and
1254 callstart <= dev['start'] and
1255 callend >= dev['end']):
1259 if(sysvals.verbose):
1260 test.data.printDetails()
1263 # add the time in between the tests as a new phase so we can see it
1264 if(len(testruns) > 1):
1265 t1e = testruns[0].getEnd()
1266 t2s = testruns[-1].getStart()
1267 testruns[-1].newPhaseWithSingleAction('user mode', \
1268 'user mode', t1e, t2s, '#FF9966')
1270 # Function: parseTraceLog
1272 # Analyze an ftrace log output file generated from this app during
1273 # the execution phase. Used when the ftrace log is the primary data source
1274 # and includes the suspend_resume and device_pm_callback trace events
1275 # The ftrace filename is taken from sysvals
1277 # An array of Data objects
1278 def parseTraceLog():
1281 vprint('Analyzing the ftrace data...')
1282 if(os.path.exists(sysvals.ftracefile) == False):
1283 doError('%s doesnt exist' % sysvals.ftracefile, False)
1285 # extract the callgraph and traceevent data
1290 tf = open(sysvals.ftracefile, 'r')
1291 phase = 'suspend_prepare'
1293 # remove any latent carriage returns
1294 line = line.replace('\r\n', '')
1295 # stamp line: each stamp means a new test run
1296 m = re.match(sysvals.stampfmt, line)
1298 data = Data(len(testdata))
1299 testdata.append(data)
1300 testrun = TestRun(data)
1301 testruns.append(testrun)
1306 # firmware line: pull out any firmware data
1307 m = re.match(sysvals.firmwarefmt, line)
1309 data.fwSuspend = int(m.group('s'))
1310 data.fwResume = int(m.group('r'))
1311 if(data.fwSuspend > 0 or data.fwResume > 0):
1314 # tracer type line: determine the trace data type
1315 m = re.match(sysvals.tracertypefmt, line)
1317 tracer = m.group('t')
1318 testrun.setTracerType(tracer)
1320 # post resume time line: did this test run include post-resume data
1321 m = re.match(sysvals.postresumefmt, line)
1323 t = int(m.group('t'))
1325 sysvals.postresumetime = t
1327 # ftrace line: parse only valid lines
1328 m = re.match(testrun.ftrace_line_fmt, line)
1331 # gather the basic message data from the line
1332 m_time = m.group('time')
1333 m_pid = m.group('pid')
1334 m_msg = m.group('msg')
1335 if(testrun.cgformat):
1336 m_param3 = m.group('dur')
1338 m_param3 = 'traceevent'
1339 if(m_time and m_pid and m_msg):
1340 t = FTraceLine(m_time, m_msg, m_param3)
1344 # the line should be a call, return, or event
1345 if(not t.fcall and not t.freturn and not t.fevent):
1347 # only parse the ftrace data during suspend/resume
1348 if(not testrun.inthepipe):
1349 # look for the suspend start marker
1351 if(t.name == 'SUSPEND START'):
1352 testrun.inthepipe = True
1353 data.setStart(t.time)
1355 # trace event processing
1357 if(t.name == 'RESUME COMPLETE'):
1358 if(sysvals.postresumetime > 0):
1359 phase = 'post_resume'
1360 data.newPhase(phase, t.time, t.time, '#FF9966', -1)
1362 testrun.inthepipe = False
1365 if(phase == 'post_resume'):
1367 if(t.type == 'suspend_resume'):
1368 # suspend_resume trace events have two types, begin and end
1369 if(re.match('(?P<name>.*) begin$', t.name)):
1371 elif(re.match('(?P<name>.*) end$', t.name)):
1375 m = re.match('(?P<name>.*)\[(?P<val>[0-9]*)\] .*', t.name)
1377 val = m.group('val')
1379 name = m.group('name')
1381 name = m.group('name')+'['+val+']'
1383 m = re.match('(?P<name>.*) .*', t.name)
1384 name = m.group('name')
1385 # ignore these events
1386 if(re.match('acpi_suspend\[.*', t.name) or
1387 re.match('suspend_enter\[.*', name)):
1389 # -- phase changes --
1390 # suspend_prepare start
1391 if(re.match('dpm_prepare\[.*', t.name)):
1392 phase = 'suspend_prepare'
1394 data.dmesg[phase]['end'] = t.time
1397 elif(re.match('dpm_suspend\[.*', t.name)):
1399 data.setPhase(phase, t.time, isbegin)
1401 # suspend_late start
1402 elif(re.match('dpm_suspend_late\[.*', t.name)):
1403 phase = 'suspend_late'
1404 data.setPhase(phase, t.time, isbegin)
1406 # suspend_noirq start
1407 elif(re.match('dpm_suspend_noirq\[.*', t.name)):
1408 phase = 'suspend_noirq'
1409 data.setPhase(phase, t.time, isbegin)
1411 phase = 'suspend_machine'
1412 data.dmesg[phase]['start'] = t.time
1414 # suspend_machine/resume_machine
1415 elif(re.match('machine_suspend\[.*', t.name)):
1417 phase = 'suspend_machine'
1418 data.dmesg[phase]['end'] = t.time
1419 data.tSuspended = t.time
1421 if(sysvals.suspendmode in ['mem', 'disk']):
1422 data.dmesg['suspend_machine']['end'] = t.time
1423 data.tSuspended = t.time
1424 phase = 'resume_machine'
1425 data.dmesg[phase]['start'] = t.time
1426 data.tResumed = t.time
1427 data.tLow = data.tResumed - data.tSuspended
1429 # resume_noirq start
1430 elif(re.match('dpm_resume_noirq\[.*', t.name)):
1431 phase = 'resume_noirq'
1432 data.setPhase(phase, t.time, isbegin)
1434 data.dmesg['resume_machine']['end'] = t.time
1436 # resume_early start
1437 elif(re.match('dpm_resume_early\[.*', t.name)):
1438 phase = 'resume_early'
1439 data.setPhase(phase, t.time, isbegin)
1442 elif(re.match('dpm_resume\[.*', t.name)):
1444 data.setPhase(phase, t.time, isbegin)
1446 # resume complete start
1447 elif(re.match('dpm_complete\[.*', t.name)):
1448 phase = 'resume_complete'
1450 data.dmesg[phase]['start'] = t.time
1453 # is this trace event outside of the devices calls
1454 if(data.isTraceEventOutsideDeviceCalls(pid, t.time)):
1455 # global events (outside device calls) are simply graphed
1456 if(name not in testrun.ttemp):
1457 testrun.ttemp[name] = []
1459 # create a new list entry
1460 testrun.ttemp[name].append(\
1461 {'begin': t.time, 'end': t.time})
1463 if(len(testrun.ttemp[name]) > 0):
1464 # if an antry exists, assume this is its end
1465 testrun.ttemp[name][-1]['end'] = t.time
1466 elif(phase == 'post_resume'):
1467 # post resume events can just have ends
1468 testrun.ttemp[name].append({
1469 'begin': data.dmesg[phase]['start'],
1473 data.addIntraDevTraceEvent('', name, pid, t.time)
1475 data.capIntraDevTraceEvent('', name, pid, t.time)
1476 # device callback start
1477 elif(t.type == 'device_pm_callback_start'):
1478 m = re.match('(?P<drv>.*) (?P<d>.*), parent: *(?P<p>.*), .*',\
1482 drv = m.group('drv')
1486 data.newAction(phase, n, pid, p, t.time, -1, drv)
1487 # device callback finish
1488 elif(t.type == 'device_pm_callback_end'):
1489 m = re.match('(?P<drv>.*) (?P<d>.*), err.*', t.name);
1493 list = data.dmesg[phase]['list']
1496 dev['length'] = t.time - dev['start']
1498 # callgraph processing
1499 elif sysvals.usecallgraph:
1500 # this shouldn't happen, but JIC, ignore callgraph data post-res
1501 if(phase == 'post_resume'):
1503 # create a callgraph object for the data
1504 if(pid not in testrun.ftemp):
1505 testrun.ftemp[pid] = []
1506 testrun.ftemp[pid].append(FTraceCallGraph())
1507 # when the call is finished, see which device matches it
1508 cg = testrun.ftemp[pid][-1]
1509 if(cg.addLine(t, m)):
1510 testrun.ftemp[pid].append(FTraceCallGraph())
1513 for test in testruns:
1514 # add the traceevent data to the device hierarchy
1515 if(sysvals.usetraceevents):
1516 for name in test.ttemp:
1517 for event in test.ttemp[name]:
1518 begin = event['begin']
1520 # if event starts before timeline start, expand timeline
1521 if(begin < test.data.start):
1522 test.data.setStart(begin)
1523 # if event ends after timeline end, expand the timeline
1524 if(end > test.data.end):
1525 test.data.setEnd(end)
1526 test.data.newActionGlobal(name, begin, end)
1528 # add the callgraph data to the device hierarchy
1530 'dpm_prepare': 'suspend_prepare',
1531 'dpm_complete': 'resume_complete'
1533 for pid in test.ftemp:
1534 for cg in test.ftemp[pid]:
1535 if len(cg.list) < 2:
1537 if(not cg.sanityCheck()):
1538 id = 'task %s cpu %s' % (pid, m.group('cpu'))
1539 vprint('Sanity check failed for '+\
1540 id+', ignoring this callback')
1542 callstart = cg.start
1544 if(cg.list[0].name in borderphase):
1545 p = borderphase[cg.list[0].name]
1546 list = test.data.dmesg[p]['list']
1547 for devname in list:
1549 if(pid == dev['pid'] and
1550 callstart <= dev['start'] and
1551 callend >= dev['end']):
1552 dev['ftrace'] = cg.slice(dev['start'], dev['end'])
1554 if(cg.list[0].name != 'dpm_run_callback'):
1556 for p in test.data.phases:
1557 if(test.data.dmesg[p]['start'] <= callstart and
1558 callstart <= test.data.dmesg[p]['end']):
1559 list = test.data.dmesg[p]['list']
1560 for devname in list:
1562 if(pid == dev['pid'] and
1563 callstart <= dev['start'] and
1564 callend >= dev['end']):
1568 # fill in any missing phases
1569 for data in testdata:
1571 for p in data.phases:
1572 if(data.dmesg[p]['start'] < 0 and data.dmesg[p]['end'] < 0):
1573 print('WARNING: phase "%s" is missing!' % p)
1574 if(data.dmesg[p]['start'] < 0):
1575 data.dmesg[p]['start'] = data.dmesg[lp]['end']
1576 if(p == 'resume_machine'):
1577 data.tSuspended = data.dmesg[lp]['end']
1578 data.tResumed = data.dmesg[lp]['end']
1580 if(data.dmesg[p]['end'] < 0):
1581 data.dmesg[p]['end'] = data.dmesg[p]['start']
1584 if(len(sysvals.devicefilter) > 0):
1585 data.deviceFilter(sysvals.devicefilter)
1586 data.fixupInitcallsThatDidntReturn()
1587 if(sysvals.verbose):
1590 # add the time in between the tests as a new phase so we can see it
1591 if(len(testdata) > 1):
1592 t1e = testdata[0].getEnd()
1593 t2s = testdata[-1].getStart()
1594 testdata[-1].newPhaseWithSingleAction('user mode', \
1595 'user mode', t1e, t2s, '#FF9966')
1598 # Function: loadKernelLog
1600 # [deprecated for kernel 3.15.0 or newer]
1601 # load the dmesg file into memory and fix up any ordering issues
1602 # The dmesg filename is taken from sysvals
1604 # An array of empty Data objects with only their dmesgtext attributes set
1605 def loadKernelLog():
1608 vprint('Analyzing the dmesg data...')
1609 if(os.path.exists(sysvals.dmesgfile) == False):
1610 doError('%s doesnt exist' % sysvals.dmesgfile, False)
1612 # there can be multiple test runs in a single file delineated by stamps
1615 lf = open(sysvals.dmesgfile, 'r')
1617 line = line.replace('\r\n', '')
1618 idx = line.find('[')
1621 m = re.match(sysvals.stampfmt, line)
1624 testruns.append(data)
1625 data = Data(len(testruns))
1630 m = re.match(sysvals.firmwarefmt, line)
1632 data.fwSuspend = int(m.group('s'))
1633 data.fwResume = int(m.group('r'))
1634 if(data.fwSuspend > 0 or data.fwResume > 0):
1637 m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line)
1639 data.dmesgtext.append(line)
1640 if(re.match('ACPI: resume from mwait', m.group('msg'))):
1641 print('NOTE: This suspend appears to be freeze rather than'+\
1642 ' %s, it will be treated as such' % sysvals.suspendmode)
1643 sysvals.suspendmode = 'freeze'
1645 vprint('ignoring dmesg line: %s' % line.replace('\n', ''))
1646 testruns.append(data)
1650 print('ERROR: analyze_suspend header missing from dmesg log')
1653 # fix lines with same timestamp/function with the call and return swapped
1654 for data in testruns:
1656 for line in data.dmesgtext:
1657 mc = re.match('.*(\[ *)(?P<t>[0-9\.]*)(\]) calling '+\
1658 '(?P<f>.*)\+ @ .*, parent: .*', line)
1659 mr = re.match('.*(\[ *)(?P<t>[0-9\.]*)(\]) call '+\
1660 '(?P<f>.*)\+ returned .* after (?P<dt>.*) usecs', last)
1661 if(mc and mr and (mc.group('t') == mr.group('t')) and
1662 (mc.group('f') == mr.group('f'))):
1663 i = data.dmesgtext.index(last)
1664 j = data.dmesgtext.index(line)
1665 data.dmesgtext[i] = line
1666 data.dmesgtext[j] = last
1670 # Function: parseKernelLog
1672 # [deprecated for kernel 3.15.0 or newer]
1673 # Analyse a dmesg log output file generated from this app during
1674 # the execution phase. Create a set of device structures in memory
1675 # for subsequent formatting in the html output file
1676 # This call is only for legacy support on kernels where the ftrace
1677 # data lacks the suspend_resume or device_pm_callbacks trace events.
1679 # data: an empty Data object (with dmesgtext) obtained from loadKernelLog
1681 # The filled Data object
1682 def parseKernelLog(data):
1685 phase = 'suspend_runtime'
1688 vprint('Firmware Suspend = %u ns, Firmware Resume = %u ns' % \
1689 (data.fwSuspend, data.fwResume))
1691 # dmesg phase match table
1693 'suspend_prepare': 'PM: Syncing filesystems.*',
1694 'suspend': 'PM: Entering [a-z]* sleep.*',
1695 'suspend_late': 'PM: suspend of devices complete after.*',
1696 'suspend_noirq': 'PM: late suspend of devices complete after.*',
1697 'suspend_machine': 'PM: noirq suspend of devices complete after.*',
1698 'resume_machine': 'ACPI: Low-level resume complete.*',
1699 'resume_noirq': 'ACPI: Waking up from system sleep state.*',
1700 'resume_early': 'PM: noirq resume of devices complete after.*',
1701 'resume': 'PM: early resume of devices complete after.*',
1702 'resume_complete': 'PM: resume of devices complete after.*',
1703 'post_resume': '.*Restarting tasks \.\.\..*',
1705 if(sysvals.suspendmode == 'standby'):
1706 dm['resume_machine'] = 'PM: Restoring platform NVS memory'
1707 elif(sysvals.suspendmode == 'disk'):
1708 dm['suspend_late'] = 'PM: freeze of devices complete after.*'
1709 dm['suspend_noirq'] = 'PM: late freeze of devices complete after.*'
1710 dm['suspend_machine'] = 'PM: noirq freeze of devices complete after.*'
1711 dm['resume_machine'] = 'PM: Restoring platform NVS memory'
1712 dm['resume_early'] = 'PM: noirq restore of devices complete after.*'
1713 dm['resume'] = 'PM: early restore of devices complete after.*'
1714 dm['resume_complete'] = 'PM: restore of devices complete after.*'
1715 elif(sysvals.suspendmode == 'freeze'):
1716 dm['resume_machine'] = 'ACPI: resume from mwait'
1718 # action table (expected events that occur and show up in dmesg)
1720 'sync_filesystems': {
1721 'smsg': 'PM: Syncing filesystems.*',
1722 'emsg': 'PM: Preparing system for mem sleep.*' },
1723 'freeze_user_processes': {
1724 'smsg': 'Freezing user space processes .*',
1725 'emsg': 'Freezing remaining freezable tasks.*' },
1727 'smsg': 'Freezing remaining freezable tasks.*',
1728 'emsg': 'PM: Entering (?P<mode>[a-z,A-Z]*) sleep.*' },
1730 'smsg': 'ACPI: Preparing to enter system sleep state.*',
1731 'emsg': 'PM: Saving platform NVS memory.*' },
1733 'smsg': 'PM: Saving platform NVS memory.*',
1734 'emsg': 'Disabling non-boot CPUs .*' },
1741 for line in data.dmesgtext:
1742 # -- preprocessing --
1743 # parse each dmesg line into the time and message
1744 m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line)
1746 val = m.group('ktime')
1750 doWarning('INVALID DMESG LINE: '+\
1751 line.replace('\n', ''), 'dmesg')
1753 msg = m.group('msg')
1754 # initialize data start to first line time
1756 data.setStart(ktime)
1761 # hack for determining resume_machine end for freeze
1762 if(not sysvals.usetraceevents and sysvals.suspendmode == 'freeze' \
1763 and phase == 'resume_machine' and \
1764 re.match('calling (?P<f>.*)\+ @ .*, parent: .*', msg)):
1765 data.dmesg['resume_machine']['end'] = ktime
1766 phase = 'resume_noirq'
1767 data.dmesg[phase]['start'] = ktime
1769 # -- phase changes --
1771 if(re.match(dm['suspend_prepare'], msg)):
1772 phase = 'suspend_prepare'
1773 data.dmesg[phase]['start'] = ktime
1774 data.setStart(ktime)
1776 elif(re.match(dm['suspend'], msg)):
1777 data.dmesg['suspend_prepare']['end'] = ktime
1779 data.dmesg[phase]['start'] = ktime
1780 # suspend_late start
1781 elif(re.match(dm['suspend_late'], msg)):
1782 data.dmesg['suspend']['end'] = ktime
1783 phase = 'suspend_late'
1784 data.dmesg[phase]['start'] = ktime
1785 # suspend_noirq start
1786 elif(re.match(dm['suspend_noirq'], msg)):
1787 data.dmesg['suspend_late']['end'] = ktime
1788 phase = 'suspend_noirq'
1789 data.dmesg[phase]['start'] = ktime
1790 # suspend_machine start
1791 elif(re.match(dm['suspend_machine'], msg)):
1792 data.dmesg['suspend_noirq']['end'] = ktime
1793 phase = 'suspend_machine'
1794 data.dmesg[phase]['start'] = ktime
1795 # resume_machine start
1796 elif(re.match(dm['resume_machine'], msg)):
1797 if(sysvals.suspendmode in ['freeze', 'standby']):
1798 data.tSuspended = prevktime
1799 data.dmesg['suspend_machine']['end'] = prevktime
1801 data.tSuspended = ktime
1802 data.dmesg['suspend_machine']['end'] = ktime
1803 phase = 'resume_machine'
1804 data.tResumed = ktime
1805 data.tLow = data.tResumed - data.tSuspended
1806 data.dmesg[phase]['start'] = ktime
1807 # resume_noirq start
1808 elif(re.match(dm['resume_noirq'], msg)):
1809 data.dmesg['resume_machine']['end'] = ktime
1810 phase = 'resume_noirq'
1811 data.dmesg[phase]['start'] = ktime
1812 # resume_early start
1813 elif(re.match(dm['resume_early'], msg)):
1814 data.dmesg['resume_noirq']['end'] = ktime
1815 phase = 'resume_early'
1816 data.dmesg[phase]['start'] = ktime
1818 elif(re.match(dm['resume'], msg)):
1819 data.dmesg['resume_early']['end'] = ktime
1821 data.dmesg[phase]['start'] = ktime
1822 # resume complete start
1823 elif(re.match(dm['resume_complete'], msg)):
1824 data.dmesg['resume']['end'] = ktime
1825 phase = 'resume_complete'
1826 data.dmesg[phase]['start'] = ktime
1828 elif(re.match(dm['post_resume'], msg)):
1829 data.dmesg['resume_complete']['end'] = ktime
1831 phase = 'post_resume'
1834 # -- device callbacks --
1835 if(phase in data.phases):
1837 if(re.match('calling (?P<f>.*)\+ @ .*, parent: .*', msg)):
1838 sm = re.match('calling (?P<f>.*)\+ @ '+\
1839 '(?P<n>.*), parent: (?P<p>.*)', msg);
1844 data.newAction(phase, f, int(n), p, ktime, -1, '')
1845 # device init return
1846 elif(re.match('call (?P<f>.*)\+ returned .* after '+\
1847 '(?P<t>.*) usecs', msg)):
1848 sm = re.match('call (?P<f>.*)\+ returned .* after '+\
1849 '(?P<t>.*) usecs(?P<a>.*)', msg);
1852 list = data.dmesg[phase]['list']
1855 dev['length'] = int(t)
1858 # -- non-devicecallback actions --
1859 # if trace events are not available, these are better than nothing
1860 if(not sysvals.usetraceevents):
1861 # look for known actions
1863 if(re.match(at[a]['smsg'], msg)):
1864 if(a not in actions):
1866 actions[a].append({'begin': ktime, 'end': ktime})
1867 if(re.match(at[a]['emsg'], msg)):
1868 actions[a][-1]['end'] = ktime
1869 # now look for CPU on/off events
1870 if(re.match('Disabling non-boot CPUs .*', msg)):
1871 # start of first cpu suspend
1873 elif(re.match('Enabling non-boot CPUs .*', msg)):
1874 # start of first cpu resume
1876 elif(re.match('smpboot: CPU (?P<cpu>[0-9]*) is now offline', msg)):
1877 # end of a cpu suspend, start of the next
1878 m = re.match('smpboot: CPU (?P<cpu>[0-9]*) is now offline', msg)
1879 cpu = 'CPU'+m.group('cpu')
1880 if(cpu not in actions):
1882 actions[cpu].append({'begin': cpu_start, 'end': ktime})
1884 elif(re.match('CPU(?P<cpu>[0-9]*) is up', msg)):
1885 # end of a cpu resume, start of the next
1886 m = re.match('CPU(?P<cpu>[0-9]*) is up', msg)
1887 cpu = 'CPU'+m.group('cpu')
1888 if(cpu not in actions):
1890 actions[cpu].append({'begin': cpu_start, 'end': ktime})
1894 # fill in any missing phases
1896 for p in data.phases:
1897 if(data.dmesg[p]['start'] < 0 and data.dmesg[p]['end'] < 0):
1898 print('WARNING: phase "%s" is missing, something went wrong!' % p)
1899 print(' In %s, this dmesg line denotes the start of %s:' % \
1900 (sysvals.suspendmode, p))
1901 print(' "%s"' % dm[p])
1902 if(data.dmesg[p]['start'] < 0):
1903 data.dmesg[p]['start'] = data.dmesg[lp]['end']
1904 if(p == 'resume_machine'):
1905 data.tSuspended = data.dmesg[lp]['end']
1906 data.tResumed = data.dmesg[lp]['end']
1908 if(data.dmesg[p]['end'] < 0):
1909 data.dmesg[p]['end'] = data.dmesg[p]['start']
1912 # fill in any actions we've found
1913 for name in actions:
1914 for event in actions[name]:
1915 begin = event['begin']
1917 # if event starts before timeline start, expand timeline
1918 if(begin < data.start):
1919 data.setStart(begin)
1920 # if event ends after timeline end, expand the timeline
1923 data.newActionGlobal(name, begin, end)
1925 if(sysvals.verbose):
1927 if(len(sysvals.devicefilter) > 0):
1928 data.deviceFilter(sysvals.devicefilter)
1929 data.fixupInitcallsThatDidntReturn()
1932 # Function: setTimelineRows
1934 # Organize the timeline entries into the smallest
1935 # number of rows possible, with no entry overlapping
1937 # list: the list of devices/actions for a single phase
1938 # sortedkeys: cronologically sorted key list to use
1940 # The total number of rows needed to display this phase of the timeline
1941 def setTimelineRows(list, sortedkeys):
1943 # clear all rows and set them to undefined
1944 remaining = len(list)
1948 list[item]['row'] = -1
1950 # try to pack each row with as many ranges as possible
1951 while(remaining > 0):
1952 if(row not in rowdata):
1954 for item in sortedkeys:
1955 if(list[item]['row'] < 0):
1956 s = list[item]['start']
1957 e = list[item]['end']
1959 for ritem in rowdata[row]:
1962 if(not (((s <= rs) and (e <= rs)) or
1963 ((s >= re) and (e >= re)))):
1967 rowdata[row].append(list[item])
1968 list[item]['row'] = row
1973 # Function: createTimeScale
1975 # Create the timescale header for the html timeline
1977 # t0: start time (suspend begin)
1978 # tMax: end time (resume end)
1979 # tSuspend: time when suspend occurs, i.e. the zero time
1981 # The html code needed to display the time scale
1982 def createTimeScale(t0, tMax, tSuspended):
1983 timescale = '<div class="t" style="right:{0}%">{1}</div>\n'
1984 output = '<div id="timescale">\n'
1986 # set scale for timeline
1994 for i in range(int(tTotal/tS)+1):
1995 pos = '%0.3f' % (100 - ((float(i)*tS*100)/tTotal))
1997 val = '%0.fms' % (float(i)*tS*1000)
2000 output += timescale.format(pos, val)
2002 tSuspend = tSuspended - t0
2003 divTotal = int(tTotal/tS) + 1
2004 divSuspend = int(tSuspend/tS)
2005 s0 = (tSuspend - tS*divSuspend)*100/tTotal
2006 for i in range(divTotal):
2007 pos = '%0.3f' % (100 - ((float(i)*tS*100)/tTotal) - s0)
2008 if((i == 0) and (s0 < 3)):
2010 elif(i == divSuspend):
2013 val = '%0.fms' % (float(i-divSuspend)*tS*1000)
2014 output += timescale.format(pos, val)
2015 output += '</div>\n'
2018 # Function: createHTMLSummarySimple
2020 # Create summary html file for a series of tests
2022 # testruns: array of Data objects from parseTraceLog
2023 def createHTMLSummarySimple(testruns, htmlfile):
2026 # print out the basic summary of all the tests
2027 hf = open(htmlfile, 'w')
2029 # write the html header first (html head, css code, up to body start)
2030 html = '<!DOCTYPE html>\n<html>\n<head>\n\
2031 <meta http-equiv="content-type" content="text/html; charset=UTF-8">\n\
2032 <title>AnalyzeSuspend Summary</title>\n\
2033 <style type=\'text/css\'>\n\
2034 body {overflow-y: scroll;}\n\
2035 .stamp {width: 100%;text-align:center;background-color:#495E09;line-height:30px;color:white;font: 25px Arial;}\n\
2036 table {width:100%;border-collapse: collapse;}\n\
2037 .summary {font: 22px Arial;border:1px solid;}\n\
2038 th {border: 1px solid black;background-color:#A7C942;color:white;}\n\
2039 td {text-align: center;}\n\
2040 tr.alt td {background-color:#EAF2D3;}\n\
2041 tr.avg td {background-color:#BDE34C;}\n\
2042 a:link {color: #90B521;}\n\
2043 a:visited {color: #495E09;}\n\
2044 a:hover {color: #B1DF28;}\n\
2045 a:active {color: #FFFFFF;}\n\
2046 </style>\n</head>\n<body>\n'
2049 count = len(testruns)
2050 headline_stamp = '<div class="stamp">{0} {1} {2} {3} ({4} tests)</div>\n'
2051 html += headline_stamp.format(sysvals.stamp['host'],
2052 sysvals.stamp['kernel'], sysvals.stamp['mode'],
2053 sysvals.stamp['time'], count)
2055 # check to see if all the tests have the same value
2056 stampcolumns = False
2057 for data in testruns:
2058 if diffStamp(sysvals.stamp, data.stamp):
2062 th = '\t<th>{0}</th>\n'
2063 td = '\t<td>{0}</td>\n'
2064 tdlink = '\t<td><a href="{0}">Click Here</a></td>\n'
2067 html += '<table class="summary">\n<tr>\n'
2068 html += th.format("Test #")
2070 html += th.format("Hostname")
2071 html += th.format("Kernel Version")
2072 html += th.format("Suspend Mode")
2073 html += th.format("Test Time")
2074 html += th.format("Suspend Time")
2075 html += th.format("Resume Time")
2076 html += th.format("Detail")
2079 # test data, 1 row per test
2083 for data in testruns:
2084 # data.end is the end of post_resume
2085 resumeEnd = data.dmesg['resume_complete']['end']
2087 html += '<tr class="alt">\n'
2092 html += td.format("test %d" % num)
2097 if('host' in data.stamp):
2098 val = data.stamp['host']
2099 html += td.format(val)
2102 if('kernel' in data.stamp):
2103 val = data.stamp['kernel']
2104 html += td.format(val)
2107 if('mode' in data.stamp):
2108 val = data.stamp['mode']
2109 html += td.format(val)
2112 if('time' in data.stamp):
2113 val = data.stamp['time']
2114 html += td.format(val)
2116 sTime = (data.tSuspended - data.start)*1000
2118 html += td.format("%3.3f ms" % sTime)
2120 rTime = (resumeEnd - data.tResumed)*1000
2122 html += td.format("%3.3f ms" % rTime)
2123 # link to the output html
2124 html += tdlink.format(data.outfile)
2128 # last line: test average
2132 html += '<tr class="avg">\n'
2133 html += td.format('Average') # name
2135 html += td.format('') # host
2136 html += td.format('') # kernel
2137 html += td.format('') # mode
2138 html += td.format('') # time
2139 html += td.format("%3.3f ms" % sTimeAvg) # suspend time
2140 html += td.format("%3.3f ms" % rTimeAvg) # resume time
2141 html += td.format('') # output link
2144 # flush the data to file
2145 hf.write(html+'</table>\n')
2146 hf.write('</body>\n</html>\n')
2149 # Function: createHTML
2151 # Create the output html file from the resident test data
2153 # testruns: array of Data objects from parseKernelLog or parseTraceLog
2155 # True if the html file was created, false if it failed
2156 def createHTML(testruns):
2159 for data in testruns:
2160 data.normalizeTime(testruns[-1].tSuspended)
2162 x2changes = ['', 'absolute']
2163 if len(testruns) > 1:
2164 x2changes = ['1', 'relative']
2165 # html function templates
2166 headline_stamp = '<div class="stamp">{0} {1} {2} {3}</div>\n'
2167 html_devlist1 = '<button id="devlist1" class="devlist" style="float:left;">Device Detail%s</button>' % x2changes[0]
2168 html_zoombox = '<center><button id="zoomin">ZOOM IN</button><button id="zoomout">ZOOM OUT</button><button id="zoomdef">ZOOM 1:1</button></center>\n'
2169 html_devlist2 = '<button id="devlist2" class="devlist" style="float:right;">Device Detail2</button>\n'
2170 html_timeline = '<div id="dmesgzoombox" class="zoombox">\n<div id="{0}" class="timeline" style="height:{1}px">\n'
2171 html_device = '<div id="{0}" title="{1}" class="thread" style="left:{2}%;top:{3}%;height:{4}%;width:{5}%;">{6}</div>\n'
2172 html_traceevent = '<div title="{0}" class="traceevent" style="left:{1}%;top:{2}%;height:{3}%;width:{4}%;border:1px solid {5};background-color:{5}">{6}</div>\n'
2173 html_phase = '<div class="phase" style="left:{0}%;width:{1}%;top:{2}%;height:{3}%;background-color:{4}">{5}</div>\n'
2174 html_phaselet = '<div id="{0}" class="phaselet" style="left:{1}%;width:{2}%;background-color:{3}"></div>\n'
2175 html_legend = '<div class="square" style="left:{0}%;background-color:{1}"> {2}</div>\n'
2176 html_timetotal = '<table class="time1">\n<tr>'\
2177 '<td class="green">{2} Suspend Time: <b>{0} ms</b></td>'\
2178 '<td class="yellow">{2} Resume Time: <b>{1} ms</b></td>'\
2180 html_timetotal2 = '<table class="time1">\n<tr>'\
2181 '<td class="green">{3} Suspend Time: <b>{0} ms</b></td>'\
2182 '<td class="gray">'+sysvals.suspendmode+' time: <b>{1} ms</b></td>'\
2183 '<td class="yellow">{3} Resume Time: <b>{2} ms</b></td>'\
2185 html_timegroups = '<table class="time2">\n<tr>'\
2186 '<td class="green">{4}Kernel Suspend: {0} ms</td>'\
2187 '<td class="purple">{4}Firmware Suspend: {1} ms</td>'\
2188 '<td class="purple">{4}Firmware Resume: {2} ms</td>'\
2189 '<td class="yellow">{4}Kernel Resume: {3} ms</td>'\
2193 vprint('Creating Device Timeline...')
2196 # Generate the header for this timeline
2197 textnum = ['First', 'Second']
2198 for data in testruns:
2199 tTotal = data.end - data.start
2200 tEnd = data.dmesg['resume_complete']['end']
2202 print('ERROR: No timeline data')
2205 low_time = '%.0f'%(data.tLow*1000)
2207 suspend_time = '%.0f'%((data.tSuspended-data.start)*1000 + \
2208 (data.fwSuspend/1000000.0))
2209 resume_time = '%.0f'%((tEnd-data.tSuspended)*1000 + \
2210 (data.fwResume/1000000.0))
2213 if(len(testruns) > 1):
2214 testdesc1 = testdesc2 = textnum[data.testnumber]
2217 thtml = html_timetotal.format(suspend_time, \
2218 resume_time, testdesc1)
2220 thtml = html_timetotal2.format(suspend_time, low_time, \
2221 resume_time, testdesc1)
2222 devtl.html['timeline'] += thtml
2223 sktime = '%.3f'%((data.dmesg['suspend_machine']['end'] - \
2224 data.getStart())*1000)
2225 sftime = '%.3f'%(data.fwSuspend / 1000000.0)
2226 rftime = '%.3f'%(data.fwResume / 1000000.0)
2227 rktime = '%.3f'%((data.getEnd() - \
2228 data.dmesg['resume_machine']['start'])*1000)
2229 devtl.html['timeline'] += html_timegroups.format(sktime, \
2230 sftime, rftime, rktime, testdesc2)
2232 suspend_time = '%.0f'%((data.tSuspended-data.start)*1000)
2233 resume_time = '%.0f'%((tEnd-data.tSuspended)*1000)
2235 if(len(testruns) > 1):
2236 testdesc = textnum[data.testnumber]+' '+testdesc
2238 thtml = html_timetotal.format(suspend_time, \
2239 resume_time, testdesc)
2241 thtml = html_timetotal2.format(suspend_time, low_time, \
2242 resume_time, testdesc)
2243 devtl.html['timeline'] += thtml
2245 # time scale for potentially multiple datasets
2246 t0 = testruns[0].start
2247 tMax = testruns[-1].end
2248 tSuspended = testruns[-1].tSuspended
2251 # determine the maximum number of rows we need to draw
2253 for data in testruns:
2254 for phase in data.dmesg:
2255 list = data.dmesg[phase]['list']
2256 rows = setTimelineRows(list, list)
2257 data.dmesg[phase]['row'] = rows
2258 if(rows > timelinerows):
2261 # calculate the timeline height and create bounding box, add buttons
2262 devtl.setRows(timelinerows + 1)
2263 devtl.html['timeline'] += html_devlist1
2264 if len(testruns) > 1:
2265 devtl.html['timeline'] += html_devlist2
2266 devtl.html['timeline'] += html_zoombox
2267 devtl.html['timeline'] += html_timeline.format('dmesg', devtl.height)
2269 # draw the colored boxes for each of the phases
2270 for data in testruns:
2271 for b in data.dmesg:
2272 phase = data.dmesg[b]
2273 length = phase['end']-phase['start']
2274 left = '%.3f' % (((phase['start']-t0)*100.0)/tTotal)
2275 width = '%.3f' % ((length*100.0)/tTotal)
2276 devtl.html['timeline'] += html_phase.format(left, width, \
2277 '%.3f'%devtl.scaleH, '%.3f'%(100-devtl.scaleH), \
2278 data.dmesg[b]['color'], '')
2280 # draw the time scale, try to make the number of labels readable
2281 devtl.html['scale'] = createTimeScale(t0, tMax, tSuspended)
2282 devtl.html['timeline'] += devtl.html['scale']
2283 for data in testruns:
2284 for b in data.dmesg:
2285 phaselist = data.dmesg[b]['list']
2290 if(d in sysvals.altdevname):
2291 name = sysvals.altdevname[d]
2292 if('drv' in dev and dev['drv']):
2293 drv = ' {%s}' % dev['drv']
2294 height = (100.0 - devtl.scaleH)/data.dmesg[b]['row']
2295 top = '%.3f' % ((dev['row']*height) + devtl.scaleH)
2296 left = '%.3f' % (((dev['start']-t0)*100)/tTotal)
2297 width = '%.3f' % (((dev['end']-dev['start'])*100)/tTotal)
2298 length = ' (%0.3f ms) ' % ((dev['end']-dev['start'])*1000)
2299 color = 'rgba(204,204,204,0.5)'
2300 devtl.html['timeline'] += html_device.format(dev['id'], \
2301 d+drv+length+b, left, top, '%.3f'%height, width, name+drv)
2303 # draw any trace events found
2304 for data in testruns:
2305 for b in data.dmesg:
2306 phaselist = data.dmesg[b]['list']
2307 for name in phaselist:
2308 dev = phaselist[name]
2309 if('traceevents' in dev):
2310 vprint('Debug trace events found for device %s' % name)
2311 vprint('%20s %20s %10s %8s' % ('action', \
2312 'name', 'time(ms)', 'length(ms)'))
2313 for e in dev['traceevents']:
2314 vprint('%20s %20s %10.3f %8.3f' % (e.action, \
2315 e.name, e.time*1000, e.length*1000))
2316 height = (100.0 - devtl.scaleH)/data.dmesg[b]['row']
2317 top = '%.3f' % ((dev['row']*height) + devtl.scaleH)
2318 left = '%.3f' % (((e.time-t0)*100)/tTotal)
2319 width = '%.3f' % (e.length*100/tTotal)
2320 color = 'rgba(204,204,204,0.5)'
2321 devtl.html['timeline'] += \
2322 html_traceevent.format(e.action+' '+e.name, \
2323 left, top, '%.3f'%height, \
2326 # timeline is finished
2327 devtl.html['timeline'] += '</div>\n</div>\n'
2329 # draw a legend which describes the phases by color
2331 devtl.html['legend'] = '<div class="legend">\n'
2332 pdelta = 100.0/len(data.phases)
2333 pmargin = pdelta / 4.0
2334 for phase in data.phases:
2335 order = '%.2f' % ((data.dmesg[phase]['order'] * pdelta) + pmargin)
2336 name = string.replace(phase, '_', ' ')
2337 devtl.html['legend'] += html_legend.format(order, \
2338 data.dmesg[phase]['color'], name)
2339 devtl.html['legend'] += '</div>\n'
2341 hf = open(sysvals.htmlfile, 'w')
2344 # write the html header first (html head, css code, up to body start)
2345 html_header = '<!DOCTYPE html>\n<html>\n<head>\n\
2346 <meta http-equiv="content-type" content="text/html; charset=UTF-8">\n\
2347 <title>AnalyzeSuspend</title>\n\
2348 <style type=\'text/css\'>\n\
2349 body {overflow-y: scroll;}\n\
2350 .stamp {width: 100%;text-align:center;background-color:gray;line-height:30px;color:white;font: 25px Arial;}\n\
2351 .callgraph {margin-top: 30px;box-shadow: 5px 5px 20px black;}\n\
2352 .callgraph article * {padding-left: 28px;}\n\
2353 h1 {color:black;font: bold 30px Times;}\n\
2354 t0 {color:black;font: bold 30px Times;}\n\
2355 t1 {color:black;font: 30px Times;}\n\
2356 t2 {color:black;font: 25px Times;}\n\
2357 t3 {color:black;font: 20px Times;white-space:nowrap;}\n\
2358 t4 {color:black;font: bold 30px Times;line-height:60px;white-space:nowrap;}\n\
2359 table {width:100%;}\n\
2360 .gray {background-color:rgba(80,80,80,0.1);}\n\
2361 .green {background-color:rgba(204,255,204,0.4);}\n\
2362 .purple {background-color:rgba(128,0,128,0.2);}\n\
2363 .yellow {background-color:rgba(255,255,204,0.4);}\n\
2364 .time1 {font: 22px Arial;border:1px solid;}\n\
2365 .time2 {font: 15px Arial;border-bottom:1px solid;border-left:1px solid;border-right:1px solid;}\n\
2366 td {text-align: center;}\n\
2367 r {color:#500000;font:15px Tahoma;}\n\
2368 n {color:#505050;font:15px Tahoma;}\n\
2369 .tdhl {color: red;}\n\
2370 .hide {display: none;}\n\
2371 .pf {display: none;}\n\
2372 .pf:checked + label {background: url(\'data:image/svg+xml;utf,<?xml version="1.0" standalone="no"?><svg xmlns="http://www.w3.org/2000/svg" height="18" width="18" version="1.1"><circle cx="9" cy="9" r="8" stroke="black" stroke-width="1" fill="white"/><rect x="4" y="8" width="10" height="2" style="fill:black;stroke-width:0"/><rect x="8" y="4" width="2" height="10" style="fill:black;stroke-width:0"/></svg>\') no-repeat left center;}\n\
2373 .pf:not(:checked) ~ label {background: url(\'data:image/svg+xml;utf,<?xml version="1.0" standalone="no"?><svg xmlns="http://www.w3.org/2000/svg" height="18" width="18" version="1.1"><circle cx="9" cy="9" r="8" stroke="black" stroke-width="1" fill="white"/><rect x="4" y="8" width="10" height="2" style="fill:black;stroke-width:0"/></svg>\') no-repeat left center;}\n\
2374 .pf:checked ~ *:not(:nth-child(2)) {display: none;}\n\
2375 .zoombox {position: relative; width: 100%; overflow-x: scroll;}\n\
2376 .timeline {position: relative; font-size: 14px;cursor: pointer;width: 100%; overflow: hidden; background-color:#dddddd;}\n\
2377 .thread {position: absolute; height: '+'%.3f'%thread_height+'%; overflow: hidden; line-height: 30px; border:1px solid;text-align:center;white-space:nowrap;background-color:rgba(204,204,204,0.5);}\n\
2378 .thread:hover {background-color:white;border:1px solid red;z-index:10;}\n\
2379 .hover {background-color:white;border:1px solid red;z-index:10;}\n\
2380 .traceevent {position: absolute;opacity: 0.3;height: '+'%.3f'%thread_height+'%;width:0;overflow:hidden;line-height:30px;text-align:center;white-space:nowrap;}\n\
2381 .phase {position: absolute;overflow: hidden;border:0px;text-align:center;}\n\
2382 .phaselet {position:absolute;overflow:hidden;border:0px;text-align:center;height:100px;font-size:24px;}\n\
2383 .t {position:absolute;top:0%;height:100%;border-right:1px solid black;}\n\
2384 .legend {position: relative; width: 100%; height: 40px; text-align: center;margin-bottom:20px}\n\
2385 .legend .square {position:absolute;top:10px; width: 0px;height: 20px;border:1px solid;padding-left:20px;}\n\
2386 button {height:40px;width:200px;margin-bottom:20px;margin-top:20px;font-size:24px;}\n\
2387 .devlist {position:'+x2changes[1]+';width:190px;}\n\
2388 #devicedetail {height:100px;box-shadow: 5px 5px 20px black;}\n\
2389 </style>\n</head>\n<body>\n'
2390 hf.write(html_header)
2392 # write the test title and general info header
2393 if(sysvals.stamp['time'] != ""):
2394 hf.write(headline_stamp.format(sysvals.stamp['host'],
2395 sysvals.stamp['kernel'], sysvals.stamp['mode'], \
2396 sysvals.stamp['time']))
2398 # write the device timeline
2399 hf.write(devtl.html['timeline'])
2400 hf.write(devtl.html['legend'])
2401 hf.write('<div id="devicedetailtitle"></div>\n')
2402 hf.write('<div id="devicedetail" style="display:none;">\n')
2403 # draw the colored boxes for the device detail section
2404 for data in testruns:
2405 hf.write('<div id="devicedetail%d">\n' % data.testnumber)
2406 for b in data.phases:
2407 phase = data.dmesg[b]
2408 length = phase['end']-phase['start']
2409 left = '%.3f' % (((phase['start']-t0)*100.0)/tTotal)
2410 width = '%.3f' % ((length*100.0)/tTotal)
2411 hf.write(html_phaselet.format(b, left, width, \
2412 data.dmesg[b]['color']))
2413 hf.write('</div>\n')
2414 hf.write('</div>\n')
2416 # write the ftrace data (callgraph)
2418 if(sysvals.usecallgraph):
2419 hf.write('<section id="callgraphs" class="callgraph">\n')
2420 # write out the ftrace data converted to html
2421 html_func_top = '<article id="{0}" class="atop" style="background-color:{1}">\n<input type="checkbox" class="pf" id="f{2}" checked/><label for="f{2}">{3} {4}</label>\n'
2422 html_func_start = '<article>\n<input type="checkbox" class="pf" id="f{0}" checked/><label for="f{0}">{1} {2}</label>\n'
2423 html_func_end = '</article>\n'
2424 html_func_leaf = '<article>{0} {1}</article>\n'
2426 for p in data.phases:
2427 list = data.dmesg[p]['list']
2428 for devname in data.sortedDevices(p):
2429 if('ftrace' not in list[devname]):
2432 if(devname in sysvals.altdevname):
2433 name = sysvals.altdevname[devname]
2434 devid = list[devname]['id']
2435 cg = list[devname]['ftrace']
2436 flen = '<r>(%.3f ms @ %.3f to %.3f)</r>' % \
2437 ((cg.end - cg.start)*1000, cg.start*1000, cg.end*1000)
2438 hf.write(html_func_top.format(devid, data.dmesg[p]['color'], \
2439 num, name+' '+p, flen))
2441 for line in cg.list:
2442 if(line.length < 0.000000001):
2445 flen = '<n>(%.3f ms @ %.3f)</n>' % (line.length*1000, \
2447 if(line.freturn and line.fcall):
2448 hf.write(html_func_leaf.format(line.name, flen))
2450 hf.write(html_func_end)
2452 hf.write(html_func_start.format(num, line.name, flen))
2454 hf.write(html_func_end)
2455 hf.write('\n\n </section>\n')
2456 # write the footer and close
2457 addScriptCode(hf, testruns)
2458 hf.write('</body>\n</html>\n')
2462 # Function: addScriptCode
2464 # Adds the javascript code to the output html
2466 # hf: the open html file pointer
2467 # testruns: array of Data objects from parseKernelLog or parseTraceLog
2468 def addScriptCode(hf, testruns):
2469 t0 = (testruns[0].start - testruns[-1].tSuspended) * 1000
2470 tMax = (testruns[-1].end - testruns[-1].tSuspended) * 1000
2471 # create an array in javascript memory with the device details
2472 detail = ' var devtable = [];\n'
2473 for data in testruns:
2474 topo = data.deviceTopology()
2475 detail += ' devtable[%d] = "%s";\n' % (data.testnumber, topo)
2476 detail += ' var bounds = [%f,%f];\n' % (t0, tMax)
2477 # add the code which will manipulate the data in the browser
2479 '<script type="text/javascript">\n'+detail+\
2480 ' function zoomTimeline() {\n'\
2481 ' var timescale = document.getElementById("timescale");\n'\
2482 ' var dmesg = document.getElementById("dmesg");\n'\
2483 ' var zoombox = document.getElementById("dmesgzoombox");\n'\
2484 ' var val = parseFloat(dmesg.style.width);\n'\
2485 ' var newval = 100;\n'\
2486 ' var sh = window.outerWidth / 2;\n'\
2487 ' if(this.id == "zoomin") {\n'\
2488 ' newval = val * 1.2;\n'\
2489 ' if(newval > 40000) newval = 40000;\n'\
2490 ' dmesg.style.width = newval+"%";\n'\
2491 ' zoombox.scrollLeft = ((zoombox.scrollLeft + sh) * newval / val) - sh;\n'\
2492 ' } else if (this.id == "zoomout") {\n'\
2493 ' newval = val / 1.2;\n'\
2494 ' if(newval < 100) newval = 100;\n'\
2495 ' dmesg.style.width = newval+"%";\n'\
2496 ' zoombox.scrollLeft = ((zoombox.scrollLeft + sh) * newval / val) - sh;\n'\
2498 ' zoombox.scrollLeft = 0;\n'\
2499 ' dmesg.style.width = "100%";\n'\
2501 ' var html = "";\n'\
2502 ' var t0 = bounds[0];\n'\
2503 ' var tMax = bounds[1];\n'\
2504 ' var tTotal = tMax - t0;\n'\
2505 ' var wTotal = tTotal * 100.0 / newval;\n'\
2506 ' for(var tS = 1000; (wTotal / tS) < 3; tS /= 10);\n'\
2507 ' if(tS < 1) tS = 1;\n'\
2508 ' for(var s = ((t0 / tS)|0) * tS; s < tMax; s += tS) {\n'\
2509 ' var pos = (tMax - s) * 100.0 / tTotal;\n'\
2510 ' var name = (s == 0)?"S/R":(s+"ms");\n'\
2511 ' html += "<div class=\\"t\\" style=\\"right:"+pos+"%\\">"+name+"</div>";\n'\
2513 ' timescale.innerHTML = html;\n'\
2515 ' function deviceHover() {\n'\
2516 ' var name = this.title.slice(0, this.title.indexOf(" ("));\n'\
2517 ' var dmesg = document.getElementById("dmesg");\n'\
2518 ' var dev = dmesg.getElementsByClassName("thread");\n'\
2520 ' if(name.match("CPU_ON\[[0-9]*\]"))\n'\
2521 ' cpu = parseInt(name.slice(7));\n'\
2522 ' else if(name.match("CPU_OFF\[[0-9]*\]"))\n'\
2523 ' cpu = parseInt(name.slice(8));\n'\
2524 ' for (var i = 0; i < dev.length; i++) {\n'\
2525 ' dname = dev[i].title.slice(0, dev[i].title.indexOf(" ("));\n'\
2526 ' if((cpu >= 0 && dname.match("CPU_O[NF]*\\\[*"+cpu+"\\\]")) ||\n'\
2527 ' (name == dname))\n'\
2529 ' dev[i].className = "thread hover";\n'\
2531 ' dev[i].className = "thread";\n'\
2535 ' function deviceUnhover() {\n'\
2536 ' var dmesg = document.getElementById("dmesg");\n'\
2537 ' var dev = dmesg.getElementsByClassName("thread");\n'\
2538 ' for (var i = 0; i < dev.length; i++) {\n'\
2539 ' dev[i].className = "thread";\n'\
2542 ' function deviceTitle(title, total, cpu) {\n'\
2543 ' var prefix = "Total";\n'\
2544 ' if(total.length > 3) {\n'\
2545 ' prefix = "Average";\n'\
2546 ' total[1] = (total[1]+total[3])/2;\n'\
2547 ' total[2] = (total[2]+total[4])/2;\n'\
2549 ' var devtitle = document.getElementById("devicedetailtitle");\n'\
2550 ' var name = title.slice(0, title.indexOf(" "));\n'\
2551 ' if(cpu >= 0) name = "CPU"+cpu;\n'\
2552 ' var driver = "";\n'\
2553 ' var tS = "<t2>(</t2>";\n'\
2554 ' var tR = "<t2>)</t2>";\n'\
2555 ' if(total[1] > 0)\n'\
2556 ' tS = "<t2>("+prefix+" Suspend:</t2><t0> "+total[1].toFixed(3)+" ms</t0> ";\n'\
2557 ' if(total[2] > 0)\n'\
2558 ' tR = " <t2>"+prefix+" Resume:</t2><t0> "+total[2].toFixed(3)+" ms<t2>)</t2></t0>";\n'\
2559 ' var s = title.indexOf("{");\n'\
2560 ' var e = title.indexOf("}");\n'\
2561 ' if((s >= 0) && (e >= 0))\n'\
2562 ' driver = title.slice(s+1, e) + " <t1>@</t1> ";\n'\
2563 ' if(total[1] > 0 && total[2] > 0)\n'\
2564 ' devtitle.innerHTML = "<t0>"+driver+name+"</t0> "+tS+tR;\n'\
2566 ' devtitle.innerHTML = "<t0>"+title+"</t0>";\n'\
2569 ' function deviceDetail() {\n'\
2570 ' var devinfo = document.getElementById("devicedetail");\n'\
2571 ' devinfo.style.display = "block";\n'\
2572 ' var name = this.title.slice(0, this.title.indexOf(" ("));\n'\
2574 ' if(name.match("CPU_ON\[[0-9]*\]"))\n'\
2575 ' cpu = parseInt(name.slice(7));\n'\
2576 ' else if(name.match("CPU_OFF\[[0-9]*\]"))\n'\
2577 ' cpu = parseInt(name.slice(8));\n'\
2578 ' var dmesg = document.getElementById("dmesg");\n'\
2579 ' var dev = dmesg.getElementsByClassName("thread");\n'\
2580 ' var idlist = [];\n'\
2581 ' var pdata = [[]];\n'\
2582 ' var pd = pdata[0];\n'\
2583 ' var total = [0.0, 0.0, 0.0];\n'\
2584 ' for (var i = 0; i < dev.length; i++) {\n'\
2585 ' dname = dev[i].title.slice(0, dev[i].title.indexOf(" ("));\n'\
2586 ' if((cpu >= 0 && dname.match("CPU_O[NF]*\\\[*"+cpu+"\\\]")) ||\n'\
2587 ' (name == dname))\n'\
2589 ' idlist[idlist.length] = dev[i].id;\n'\
2591 ' if(dev[i].id[0] == "a") {\n'\
2592 ' pd = pdata[0];\n'\
2594 ' if(pdata.length == 1) pdata[1] = [];\n'\
2595 ' if(total.length == 3) total[3]=total[4]=0.0;\n'\
2596 ' pd = pdata[1];\n'\
2599 ' var info = dev[i].title.split(" ");\n'\
2600 ' var pname = info[info.length-1];\n'\
2601 ' pd[pname] = parseFloat(info[info.length-3].slice(1));\n'\
2602 ' total[0] += pd[pname];\n'\
2603 ' if(pname.indexOf("suspend") >= 0)\n'\
2604 ' total[tidx] += pd[pname];\n'\
2606 ' total[tidx+1] += pd[pname];\n'\
2609 ' var devname = deviceTitle(this.title, total, cpu);\n'\
2610 ' var left = 0.0;\n'\
2611 ' for (var t = 0; t < pdata.length; t++) {\n'\
2612 ' pd = pdata[t];\n'\
2613 ' devinfo = document.getElementById("devicedetail"+t);\n'\
2614 ' var phases = devinfo.getElementsByClassName("phaselet");\n'\
2615 ' for (var i = 0; i < phases.length; i++) {\n'\
2616 ' if(phases[i].id in pd) {\n'\
2617 ' var w = 100.0*pd[phases[i].id]/total[0];\n'\
2619 ' if(w < 8) fs = 4*w | 0;\n'\
2620 ' var fs2 = fs*3/4;\n'\
2621 ' phases[i].style.width = w+"%";\n'\
2622 ' phases[i].style.left = left+"%";\n'\
2623 ' phases[i].title = phases[i].id+" "+pd[phases[i].id]+" ms";\n'\
2625 ' var time = "<t4 style=\\"font-size:"+fs+"px\\">"+pd[phases[i].id]+" ms<br></t4>";\n'\
2626 ' var pname = "<t3 style=\\"font-size:"+fs2+"px\\">"+phases[i].id.replace("_", " ")+"</t3>";\n'\
2627 ' phases[i].innerHTML = time+pname;\n'\
2629 ' phases[i].style.width = "0%";\n'\
2630 ' phases[i].style.left = left+"%";\n'\
2634 ' var cglist = document.getElementById("callgraphs");\n'\
2635 ' if(!cglist) return;\n'\
2636 ' var cg = cglist.getElementsByClassName("atop");\n'\
2637 ' for (var i = 0; i < cg.length; i++) {\n'\
2638 ' if(idlist.indexOf(cg[i].id) >= 0) {\n'\
2639 ' cg[i].style.display = "block";\n'\
2641 ' cg[i].style.display = "none";\n'\
2645 ' function devListWindow(e) {\n'\
2646 ' var sx = e.clientX;\n'\
2647 ' if(sx > window.innerWidth - 440)\n'\
2648 ' sx = window.innerWidth - 440;\n'\
2649 ' var cfg="top="+e.screenY+", left="+sx+", width=440, height=720, scrollbars=yes";\n'\
2650 ' var win = window.open("", "_blank", cfg);\n'\
2651 ' if(window.chrome) win.moveBy(sx, 0);\n'\
2652 ' var html = "<title>"+e.target.innerHTML+"</title>"+\n'\
2653 ' "<style type=\\"text/css\\">"+\n'\
2654 ' " ul {list-style-type:circle;padding-left:10px;margin-left:10px;}"+\n'\
2656 ' var dt = devtable[0];\n'\
2657 ' if(e.target.id != "devlist1")\n'\
2658 ' dt = devtable[1];\n'\
2659 ' win.document.write(html+dt);\n'\
2661 ' window.addEventListener("load", function () {\n'\
2662 ' var dmesg = document.getElementById("dmesg");\n'\
2663 ' dmesg.style.width = "100%"\n'\
2664 ' document.getElementById("zoomin").onclick = zoomTimeline;\n'\
2665 ' document.getElementById("zoomout").onclick = zoomTimeline;\n'\
2666 ' document.getElementById("zoomdef").onclick = zoomTimeline;\n'\
2667 ' var devlist = document.getElementsByClassName("devlist");\n'\
2668 ' for (var i = 0; i < devlist.length; i++)\n'\
2669 ' devlist[i].onclick = devListWindow;\n'\
2670 ' var dev = dmesg.getElementsByClassName("thread");\n'\
2671 ' for (var i = 0; i < dev.length; i++) {\n'\
2672 ' dev[i].onclick = deviceDetail;\n'\
2673 ' dev[i].onmouseover = deviceHover;\n'\
2674 ' dev[i].onmouseout = deviceUnhover;\n'\
2676 ' zoomTimeline();\n'\
2679 hf.write(script_code);
2681 # Function: executeSuspend
2683 # Execute system suspend through the sysfs interface, then copy the output
2684 # dmesg and ftrace files to the test output directory.
2685 def executeSuspend():
2689 t0 = time.time()*1000
2691 # execute however many s/r runs requested
2692 for count in range(1,sysvals.execcount+1):
2693 # clear the kernel ring buffer just as we start
2694 os.system('dmesg -C')
2695 # enable callgraph ftrace only for the second run
2696 if(sysvals.usecallgraph and count == 2):
2698 os.system('echo function_graph > '+tp+'current_tracer')
2699 os.system('echo "" > '+tp+'set_ftrace_filter')
2700 # set trace format options
2701 os.system('echo funcgraph-abstime > '+tp+'trace_options')
2702 os.system('echo funcgraph-proc > '+tp+'trace_options')
2703 # focus only on device suspend and resume
2704 os.system('cat '+tp+'available_filter_functions | '+\
2705 'grep dpm_run_callback > '+tp+'set_graph_function')
2706 # if this is test2 and there's a delay, start here
2707 if(count > 1 and sysvals.x2delay > 0):
2708 tN = time.time()*1000
2709 while (tN - t0) < sysvals.x2delay:
2710 tN = time.time()*1000
2713 if(sysvals.usecallgraph or sysvals.usetraceevents):
2714 print('START TRACING')
2715 os.system('echo 1 > '+tp+'tracing_on')
2717 if(sysvals.usecallgraph or sysvals.usetraceevents):
2718 os.system('echo SUSPEND START > '+tp+'trace_marker')
2719 if(sysvals.rtcwake):
2720 print('SUSPEND START')
2721 print('will autoresume in %d seconds' % sysvals.rtcwaketime)
2722 sysvals.rtcWakeAlarm()
2724 print('SUSPEND START (press a key to resume)')
2725 pf = open(sysvals.powerfile, 'w')
2726 pf.write(sysvals.suspendmode)
2727 # execution will pause here
2729 t0 = time.time()*1000
2730 # return from suspend
2731 print('RESUME COMPLETE')
2732 if(sysvals.usecallgraph or sysvals.usetraceevents):
2733 os.system('echo RESUME COMPLETE > '+tp+'trace_marker')
2734 # see if there's firmware timing data to be had
2735 t = sysvals.postresumetime
2737 print('Waiting %d seconds for POST-RESUME trace events...' % t)
2740 if(sysvals.usecallgraph or sysvals.usetraceevents):
2741 os.system('echo 0 > '+tp+'tracing_on')
2742 print('CAPTURING TRACE')
2743 writeDatafileHeader(sysvals.ftracefile)
2744 os.system('cat '+tp+'trace >> '+sysvals.ftracefile)
2745 os.system('echo "" > '+tp+'trace')
2746 # grab a copy of the dmesg output
2747 print('CAPTURING DMESG')
2748 writeDatafileHeader(sysvals.dmesgfile)
2749 os.system('dmesg -c >> '+sysvals.dmesgfile)
2751 def writeDatafileHeader(filename):
2755 prt = sysvals.postresumetime
2756 fp = open(filename, 'a')
2757 fp.write(sysvals.teststamp+'\n')
2759 fp.write('# fwsuspend %u fwresume %u\n' % (fw[0], fw[1]))
2761 fp.write('# post resume time %u\n' % prt)
2764 # Function: executeAndroidSuspend
2766 # Execute system suspend through the sysfs interface
2767 # on a remote android device, then transfer the output
2768 # dmesg and ftrace files to the local output directory.
2769 def executeAndroidSuspend():
2772 # check to see if the display is currently off
2774 out = os.popen(sysvals.adb+\
2775 ' shell dumpsys power | grep mScreenOn').read().strip()
2776 # if so we need to turn it on so we can issue a new suspend
2777 if(out.endswith('false')):
2778 print('Waking the device up for the test...')
2779 # send the KEYPAD_POWER keyevent to wake it up
2780 os.system(sysvals.adb+' shell input keyevent 26')
2781 # wait a few seconds so the user can see the device wake up
2783 # execute however many s/r runs requested
2784 for count in range(1,sysvals.execcount+1):
2785 # clear the kernel ring buffer just as we start
2786 os.system(sysvals.adb+' shell dmesg -c > /dev/null 2>&1')
2788 if(sysvals.usetraceevents):
2789 print('START TRACING')
2790 os.system(sysvals.adb+" shell 'echo 1 > "+tp+"tracing_on'")
2792 for count in range(1,sysvals.execcount+1):
2793 if(sysvals.usetraceevents):
2794 os.system(sysvals.adb+\
2795 " shell 'echo SUSPEND START > "+tp+"trace_marker'")
2796 print('SUSPEND START (press a key on the device to resume)')
2797 os.system(sysvals.adb+" shell 'echo "+sysvals.suspendmode+\
2798 " > "+sysvals.powerfile+"'")
2799 # execution will pause here, then adb will exit
2801 check = os.popen(sysvals.adb+\
2802 ' shell pwd 2>/dev/null').read().strip()
2806 if(sysvals.usetraceevents):
2807 os.system(sysvals.adb+" shell 'echo RESUME COMPLETE > "+tp+\
2809 # return from suspend
2810 print('RESUME COMPLETE')
2812 if(sysvals.usetraceevents):
2813 os.system(sysvals.adb+" shell 'echo 0 > "+tp+"tracing_on'")
2814 print('CAPTURING TRACE')
2815 os.system('echo "'+sysvals.teststamp+'" > '+sysvals.ftracefile)
2816 os.system(sysvals.adb+' shell cat '+tp+\
2817 'trace >> '+sysvals.ftracefile)
2818 # grab a copy of the dmesg output
2819 print('CAPTURING DMESG')
2820 os.system('echo "'+sysvals.teststamp+'" > '+sysvals.dmesgfile)
2821 os.system(sysvals.adb+' shell dmesg >> '+sysvals.dmesgfile)
2823 # Function: setUSBDevicesAuto
2825 # Set the autosuspend control parameter of all USB devices to auto
2826 # This can be dangerous, so use at your own risk, most devices are set
2827 # to always-on since the kernel cant determine if the device can
2828 # properly autosuspend
2829 def setUSBDevicesAuto():
2833 for dirname, dirnames, filenames in os.walk('/sys/devices'):
2834 if(re.match('.*/usb[0-9]*.*', dirname) and
2835 'idVendor' in filenames and 'idProduct' in filenames):
2836 os.system('echo auto > %s/power/control' % dirname)
2837 name = dirname.split('/')[-1]
2838 desc = os.popen('cat %s/product 2>/dev/null' % \
2839 dirname).read().replace('\n', '')
2840 ctrl = os.popen('cat %s/power/control 2>/dev/null' % \
2841 dirname).read().replace('\n', '')
2842 print('control is %s for %6s: %s' % (ctrl, name, desc))
2846 # Print out an equivalent Y or N for a set of known parameter values
2848 # 'Y', 'N', or ' ' if the value is unknown
2850 yesvals = ['auto', 'enabled', 'active', '1']
2851 novals = ['on', 'disabled', 'suspended', 'forbidden', 'unsupported']
2860 # Print out a very concise time string in minutes and seconds
2862 # The time string, e.g. "1901m16s"
2870 s = (ms / 1000) - (m * 60)
2871 return '%3dm%2ds' % (m, s)
2873 # Function: detectUSB
2875 # Detect all the USB hosts and devices currently connected and add
2876 # a list of USB device names to sysvals for better timeline readability
2878 # output: True to output the info to stdout, False otherwise
2879 def detectUSB(output):
2882 field = {'idVendor':'', 'idProduct':'', 'product':'', 'speed':''}
2883 power = {'async':'', 'autosuspend':'', 'autosuspend_delay_ms':'',
2884 'control':'', 'persist':'', 'runtime_enabled':'',
2885 'runtime_status':'', 'runtime_usage':'',
2886 'runtime_active_time':'',
2887 'runtime_suspended_time':'',
2888 'active_duration':'',
2889 'connected_duration':''}
2892 print('---------------------------------------------------------------------------------------------')
2893 print(' A = async/sync PM queue Y/N D = autosuspend delay (seconds)')
2894 print(' S = autosuspend Y/N rACTIVE = runtime active (min/sec)')
2895 print(' P = persist across suspend Y/N rSUSPEN = runtime suspend (min/sec)')
2896 print(' E = runtime suspend enabled/forbidden Y/N ACTIVE = active duration (min/sec)')
2897 print(' R = runtime status active/suspended Y/N CONNECT = connected duration (min/sec)')
2898 print(' U = runtime usage count')
2899 print('---------------------------------------------------------------------------------------------')
2900 print(' NAME ID DESCRIPTION SPEED A S P E R U D rACTIVE rSUSPEN ACTIVE CONNECT')
2901 print('---------------------------------------------------------------------------------------------')
2903 for dirname, dirnames, filenames in os.walk('/sys/devices'):
2904 if(re.match('.*/usb[0-9]*.*', dirname) and
2905 'idVendor' in filenames and 'idProduct' in filenames):
2907 field[i] = os.popen('cat %s/%s 2>/dev/null' % \
2908 (dirname, i)).read().replace('\n', '')
2909 name = dirname.split('/')[-1]
2910 if(len(field['product']) > 0):
2911 sysvals.altdevname[name] = \
2912 '%s [%s]' % (field['product'], name)
2914 sysvals.altdevname[name] = \
2915 '%s:%s [%s]' % (field['idVendor'], \
2916 field['idProduct'], name)
2919 power[i] = os.popen('cat %s/power/%s 2>/dev/null' % \
2920 (dirname, i)).read().replace('\n', '')
2921 if(re.match('usb[0-9]*', name)):
2922 first = '%-8s' % name
2924 first = '%8s' % name
2925 print('%s [%s:%s] %-20s %-4s %1s %1s %1s %1s %1s %1s %1s %s %s %s %s' % \
2926 (first, field['idVendor'], field['idProduct'], \
2927 field['product'][0:20], field['speed'], \
2928 yesno(power['async']), \
2929 yesno(power['control']), \
2930 yesno(power['persist']), \
2931 yesno(power['runtime_enabled']), \
2932 yesno(power['runtime_status']), \
2933 power['runtime_usage'], \
2934 power['autosuspend'], \
2935 ms2nice(power['runtime_active_time']), \
2936 ms2nice(power['runtime_suspended_time']), \
2937 ms2nice(power['active_duration']), \
2938 ms2nice(power['connected_duration'])))
2940 # Function: getModes
2942 # Determine the supported power modes on this system
2944 # A string list of the available modes
2948 if(not sysvals.android):
2949 if(os.path.exists(sysvals.powerfile)):
2950 fp = open(sysvals.powerfile, 'r')
2951 modes = string.split(fp.read())
2954 line = os.popen(sysvals.adb+' shell cat '+\
2955 sysvals.powerfile).read().strip()
2956 modes = string.split(line)
2961 # Read the acpi bios tables and pull out FPDT, the firmware data
2963 # output: True to output the info to stdout, False otherwise
2964 def getFPDT(output):
2968 rectype[0] = 'Firmware Basic Boot Performance Record'
2969 rectype[1] = 'S3 Performance Table Record'
2971 prectype[0] = 'Basic S3 Resume Performance Record'
2972 prectype[1] = 'Basic S3 Suspend Performance Record'
2975 if(not os.path.exists(sysvals.fpdtpath)):
2977 doError('file doesnt exist: %s' % sysvals.fpdtpath, False)
2979 if(not os.access(sysvals.fpdtpath, os.R_OK)):
2981 doError('file isnt readable: %s' % sysvals.fpdtpath, False)
2983 if(not os.path.exists(sysvals.mempath)):
2985 doError('file doesnt exist: %s' % sysvals.mempath, False)
2987 if(not os.access(sysvals.mempath, os.R_OK)):
2989 doError('file isnt readable: %s' % sysvals.mempath, False)
2992 fp = open(sysvals.fpdtpath, 'rb')
2998 doError('Invalid FPDT table data, should '+\
2999 'be at least 36 bytes', False)
3002 table = struct.unpack('4sIBB6s8sI4sI', buf[0:36])
3005 print('Firmware Performance Data Table (%s)' % table[0])
3006 print(' Signature : %s' % table[0])
3007 print(' Table Length : %u' % table[1])
3008 print(' Revision : %u' % table[2])
3009 print(' Checksum : 0x%x' % table[3])
3010 print(' OEM ID : %s' % table[4])
3011 print(' OEM Table ID : %s' % table[5])
3012 print(' OEM Revision : %u' % table[6])
3013 print(' Creator ID : %s' % table[7])
3014 print(' Creator Revision : 0x%x' % table[8])
3017 if(table[0] != 'FPDT'):
3019 doError('Invalid FPDT table')
3026 fp = open(sysvals.mempath, 'rb')
3027 while(i < len(records)):
3028 header = struct.unpack('HBB', records[i:i+4])
3029 if(header[0] not in rectype):
3031 if(header[1] != 16):
3033 addr = struct.unpack('Q', records[i+8:i+16])[0]
3038 doError('Bad address 0x%x in %s' % (addr, sysvals.mempath), False)
3039 rechead = struct.unpack('4sI', first)
3040 recdata = fp.read(rechead[1]-8)
3041 if(rechead[0] == 'FBPT'):
3042 record = struct.unpack('HBBIQQQQQ', recdata)
3044 print('%s (%s)' % (rectype[header[0]], rechead[0]))
3045 print(' Reset END : %u ns' % record[4])
3046 print(' OS Loader LoadImage Start : %u ns' % record[5])
3047 print(' OS Loader StartImage Start : %u ns' % record[6])
3048 print(' ExitBootServices Entry : %u ns' % record[7])
3049 print(' ExitBootServices Exit : %u ns' % record[8])
3050 elif(rechead[0] == 'S3PT'):
3052 print('%s (%s)' % (rectype[header[0]], rechead[0]))
3054 while(j < len(recdata)):
3055 prechead = struct.unpack('HBB', recdata[j:j+4])
3056 if(prechead[0] not in prectype):
3058 if(prechead[0] == 0):
3059 record = struct.unpack('IIQQ', recdata[j:j+prechead[1]])
3060 fwData[1] = record[2]
3062 print(' %s' % prectype[prechead[0]])
3063 print(' Resume Count : %u' % \
3065 print(' FullResume : %u ns' % \
3067 print(' AverageResume : %u ns' % \
3069 elif(prechead[0] == 1):
3070 record = struct.unpack('QQ', recdata[j+4:j+prechead[1]])
3071 fwData[0] = record[1] - record[0]
3073 print(' %s' % prectype[prechead[0]])
3074 print(' SuspendStart : %u ns' % \
3076 print(' SuspendEnd : %u ns' % \
3078 print(' SuspendTime : %u ns' % \
3087 # Function: statusCheck
3089 # Verify that the requested command and options will work, and
3090 # print the results to the terminal
3092 # True if the test will work, False if not
3097 if(sysvals.android):
3098 print('Checking the android system ...')
3100 print('Checking this system (%s)...' % platform.node())
3102 # check if adb is connected to a device
3103 if(sysvals.android):
3105 out = os.popen(sysvals.adb+' get-state').read().strip()
3106 if(out == 'device'):
3108 print(' is android device connected: %s' % res)
3110 print(' Please connect the device before using this tool')
3113 # check we have root access
3114 res = 'NO (No features of this tool will work!)'
3115 if(sysvals.android):
3116 out = os.popen(sysvals.adb+' shell id').read().strip()
3120 if(os.environ['USER'] == 'root'):
3122 print(' have root access: %s' % res)
3124 if(sysvals.android):
3125 print(' Try running "adb root" to restart the daemon as root')
3127 print(' Try running this script with sudo')
3130 # check sysfs is mounted
3131 res = 'NO (No features of this tool will work!)'
3132 if(sysvals.android):
3133 out = os.popen(sysvals.adb+' shell ls '+\
3134 sysvals.powerfile).read().strip()
3135 if(out == sysvals.powerfile):
3138 if(os.path.exists(sysvals.powerfile)):
3140 print(' is sysfs mounted: %s' % res)
3144 # check target mode is a valid mode
3147 if(sysvals.suspendmode in modes):
3151 print(' is "%s" a valid power mode: %s' % (sysvals.suspendmode, res))
3153 print(' valid power modes are: %s' % modes)
3154 print(' please choose one with -m')
3156 # check if the tool can unlock the device
3157 if(sysvals.android):
3159 out1 = os.popen(sysvals.adb+\
3160 ' shell dumpsys power | grep mScreenOn').read().strip()
3161 out2 = os.popen(sysvals.adb+\
3162 ' shell input').read().strip()
3163 if(not out1.startswith('mScreenOn') or not out2.startswith('usage')):
3164 res = 'NO (wake the android device up before running the test)'
3165 print(' can I unlock the screen: %s' % res)
3167 # check if ftrace is available
3169 ftgood = verifyFtrace()
3172 elif(sysvals.usecallgraph):
3174 print(' is ftrace supported: %s' % res)
3176 # what data source are we using
3179 sysvals.usetraceeventsonly = True
3180 sysvals.usetraceevents = False
3181 for e in sysvals.traceevents:
3183 if(sysvals.android):
3184 out = os.popen(sysvals.adb+' shell ls -d '+\
3185 sysvals.epath+e).read().strip()
3186 if(out == sysvals.epath+e):
3189 if(os.path.exists(sysvals.epath+e)):
3192 sysvals.usetraceeventsonly = False
3193 if(e == 'suspend_resume' and check):
3194 sysvals.usetraceevents = True
3195 if(sysvals.usetraceevents and sysvals.usetraceeventsonly):
3196 res = 'FTRACE (all trace events found)'
3197 elif(sysvals.usetraceevents):
3198 res = 'DMESG and FTRACE (suspend_resume trace event found)'
3199 print(' timeline data source: %s' % res)
3203 if(sysvals.rtcpath != ''):
3205 elif(sysvals.rtcwake):
3207 print(' is rtcwake supported: %s' % res)
3213 # generic error function for catastrphic failures
3215 # msg: the error message to print
3216 # help: True if printHelp should be called after, False otherwise
3217 def doError(msg, help):
3220 print('ERROR: %s\n') % msg
3223 # Function: doWarning
3225 # generic warning function for non-catastrophic anomalies
3227 # msg: the warning message to print
3228 # file: If not empty, a filename to request be sent to the owner for debug
3229 def doWarning(msg, file):
3230 print('/* %s */') % msg
3232 print('/* For a fix, please send this'+\
3233 ' %s file to <todd.e.brandt@intel.com> */' % file)
3235 # Function: rootCheck
3237 # quick check to see if we have root access
3239 if(os.environ['USER'] != 'root'):
3240 doError('This script must be run as root', False)
3242 # Function: getArgInt
3244 # pull out an integer argument from the command line with checks
3245 def getArgInt(name, args, min, max):
3249 doError(name+': no argument supplied', True)
3253 doError(name+': non-integer value given', True)
3254 if(val < min or val > max):
3255 doError(name+': value should be between %d and %d' % (min, max), True)
3258 # Function: rerunTest
3260 # generate an output from an existing set of ftrace/dmesg logs
3264 if(sysvals.ftracefile != ''):
3265 doesTraceLogHaveTraceEvents()
3266 if(sysvals.dmesgfile == '' and not sysvals.usetraceeventsonly):
3267 doError('recreating this html output '+\
3268 'requires a dmesg file', False)
3269 sysvals.setOutputFile()
3270 vprint('Output file: %s' % sysvals.htmlfile)
3271 print('PROCESSING DATA')
3272 if(sysvals.usetraceeventsonly):
3273 testruns = parseTraceLog()
3275 testruns = loadKernelLog()
3276 for data in testruns:
3277 parseKernelLog(data)
3278 if(sysvals.ftracefile != ''):
3279 appendIncompleteTraceLog(testruns)
3280 createHTML(testruns)
3284 # execute a suspend/resume, gather the logs, and generate the output
3285 def runTest(subdir):
3288 # prepare for the test
3289 if(not sysvals.android):
3293 sysvals.initTestOutput(subdir)
3295 vprint('Output files:\n %s' % sysvals.dmesgfile)
3296 if(sysvals.usecallgraph or
3297 sysvals.usetraceevents or
3298 sysvals.usetraceeventsonly):
3299 vprint(' %s' % sysvals.ftracefile)
3300 vprint(' %s' % sysvals.htmlfile)
3303 if(not sysvals.android):
3306 executeAndroidSuspend()
3308 # analyze the data and create the html output
3309 print('PROCESSING DATA')
3310 if(sysvals.usetraceeventsonly):
3311 # data for kernels 3.15 or newer is entirely in ftrace
3312 testruns = parseTraceLog()
3314 # data for kernels older than 3.15 is primarily in dmesg
3315 testruns = loadKernelLog()
3316 for data in testruns:
3317 parseKernelLog(data)
3318 if(sysvals.usecallgraph or sysvals.usetraceevents):
3319 appendIncompleteTraceLog(testruns)
3320 createHTML(testruns)
3322 # Function: runSummary
3324 # create a summary of tests in a sub-directory
3325 def runSummary(subdir, output):
3328 # get a list of ftrace output files
3330 for dirname, dirnames, filenames in os.walk(subdir):
3331 for filename in filenames:
3332 if(re.match('.*_ftrace.txt', filename)):
3333 files.append("%s/%s" % (dirname, filename))
3335 # process the files in order and get an array of data objects
3337 for file in sorted(files):
3339 print("Test found in %s" % os.path.dirname(file))
3340 sysvals.ftracefile = file
3341 sysvals.dmesgfile = file.replace('_ftrace.txt', '_dmesg.txt')
3342 doesTraceLogHaveTraceEvents()
3343 sysvals.usecallgraph = False
3344 if not sysvals.usetraceeventsonly:
3345 if(not os.path.exists(sysvals.dmesgfile)):
3346 print("Skipping %s: not a valid test input" % file)
3350 f = os.path.basename(sysvals.ftracefile)
3351 d = os.path.basename(sysvals.dmesgfile)
3352 print("\tInput files: %s and %s" % (f, d))
3353 testdata = loadKernelLog()
3355 parseKernelLog(data)
3357 appendIncompleteTraceLog(testdata)
3360 print("\tInput file: %s" % os.path.basename(sysvals.ftracefile))
3361 testdata = parseTraceLog()
3363 data.normalizeTime(data.tSuspended)
3364 link = file.replace(subdir+'/', '').replace('_ftrace.txt', '.html')
3366 testruns.append(data)
3368 createHTMLSummarySimple(testruns, subdir+'/summary.html')
3370 # Function: printHelp
3372 # print out the help text
3378 print('AnalyzeSuspend v%.1f' % sysvals.version)
3379 print('Usage: sudo analyze_suspend.py <options>')
3381 print('Description:')
3382 print(' This tool is designed to assist kernel and OS developers in optimizing')
3383 print(' their linux stack\'s suspend/resume time. Using a kernel image built')
3384 print(' with a few extra options enabled, the tool will execute a suspend and')
3385 print(' capture dmesg and ftrace data until resume is complete. This data is')
3386 print(' transformed into a device timeline and an optional callgraph to give')
3387 print(' a detailed view of which devices/subsystems are taking the most')
3388 print(' time in suspend/resume.')
3390 print(' Generates output files in subdirectory: suspend-mmddyy-HHMMSS')
3391 print(' HTML output: <hostname>_<mode>.html')
3392 print(' raw dmesg output: <hostname>_<mode>_dmesg.txt')
3393 print(' raw ftrace output: <hostname>_<mode>_ftrace.txt')
3397 print(' -h Print this help text')
3398 print(' -v Print the current tool version')
3399 print(' -verbose Print extra information during execution and analysis')
3400 print(' -status Test to see if the system is enabled to run this tool')
3401 print(' -modes List available suspend modes')
3402 print(' -m mode Mode to initiate for suspend %s (default: %s)') % (modes, sysvals.suspendmode)
3403 print(' -rtcwake t Use rtcwake to autoresume after <t> seconds (default: disabled)')
3404 print(' [advanced]')
3405 print(' -f Use ftrace to create device callgraphs (default: disabled)')
3406 print(' -filter "d1 d2 ..." Filter out all but this list of dev names')
3407 print(' -x2 Run two suspend/resumes back to back (default: disabled)')
3408 print(' -x2delay t Minimum millisecond delay <t> between the two test runs (default: 0 ms)')
3409 print(' -postres t Time after resume completion to wait for post-resume events (default: 0 S)')
3410 print(' -multi n d Execute <n> consecutive tests at <d> seconds intervals. The outputs will')
3411 print(' be created in a new subdirectory with a summary page.')
3412 print(' [utilities]')
3413 print(' -fpdt Print out the contents of the ACPI Firmware Performance Data Table')
3414 print(' -usbtopo Print out the current USB topology with power info')
3415 print(' -usbauto Enable autosuspend for all connected USB devices')
3416 print(' [android testing]')
3417 print(' -adb binary Use the given adb binary to run the test on an android device.')
3418 print(' The device should already be connected and with root access.')
3419 print(' Commands will be executed on the device using "adb shell"')
3420 print(' [re-analyze data from previous runs]')
3421 print(' -ftrace ftracefile Create HTML output using ftrace input')
3422 print(' -dmesg dmesgfile Create HTML output using dmesg (not needed for kernel >= 3.15)')
3423 print(' -summary directory Create a summary of all test in this dir')
3427 # ----------------- MAIN --------------------
3428 # exec start (skipped if script is loaded as library)
3429 if __name__ == '__main__':
3432 multitest = {'run': False, 'count': 0, 'delay': 0}
3433 # loop through the command line arguments
3434 args = iter(sys.argv[1:])
3440 doError('No mode supplied', True)
3441 sysvals.suspendmode = val
3442 elif(arg == '-adb'):
3446 doError('No adb binary supplied', True)
3447 if(not os.path.exists(val)):
3448 doError('file doesnt exist: %s' % val, False)
3449 if(not os.access(val, os.X_OK)):
3450 doError('file isnt executable: %s' % val, False)
3452 check = os.popen(val+' version').read().strip()
3454 doError('adb version failed to execute', False)
3455 if(not re.match('Android Debug Bridge .*', check)):
3456 doError('adb version failed to execute', False)
3458 sysvals.android = True
3460 if(sysvals.postresumetime > 0):
3461 doError('-x2 is not compatible with -postres', False)
3462 sysvals.execcount = 2
3463 elif(arg == '-x2delay'):
3464 sysvals.x2delay = getArgInt('-x2delay', args, 0, 60000)
3465 elif(arg == '-postres'):
3466 if(sysvals.execcount != 1):
3467 doError('-x2 is not compatible with -postres', False)
3468 sysvals.postresumetime = getArgInt('-postres', args, 0, 3600)
3470 sysvals.usecallgraph = True
3471 elif(arg == '-modes'):
3473 elif(arg == '-fpdt'):
3475 elif(arg == '-usbtopo'):
3477 elif(arg == '-usbauto'):
3479 elif(arg == '-status'):
3481 elif(arg == '-verbose'):
3482 sysvals.verbose = True
3484 print("Version %.1f" % sysvals.version)
3486 elif(arg == '-rtcwake'):
3487 sysvals.rtcwake = True
3488 sysvals.rtcwaketime = getArgInt('-rtcwake', args, 0, 3600)
3489 elif(arg == '-multi'):
3490 multitest['run'] = True
3491 multitest['count'] = getArgInt('-multi n (exec count)', args, 2, 1000000)
3492 multitest['delay'] = getArgInt('-multi d (delay between tests)', args, 0, 3600)
3493 elif(arg == '-dmesg'):
3497 doError('No dmesg file supplied', True)
3498 sysvals.notestrun = True
3499 sysvals.dmesgfile = val
3500 if(os.path.exists(sysvals.dmesgfile) == False):
3501 doError('%s doesnt exist' % sysvals.dmesgfile, False)
3502 elif(arg == '-ftrace'):
3506 doError('No ftrace file supplied', True)
3507 sysvals.notestrun = True
3508 sysvals.usecallgraph = True
3509 sysvals.ftracefile = val
3510 if(os.path.exists(sysvals.ftracefile) == False):
3511 doError('%s doesnt exist' % sysvals.ftracefile, False)
3512 elif(arg == '-summary'):
3516 doError('No directory supplied', True)
3519 sysvals.notestrun = True
3520 if(os.path.isdir(val) == False):
3521 doError('%s isnt accesible' % val, False)
3522 elif(arg == '-filter'):
3526 doError('No devnames supplied', True)
3527 sysvals.setDeviceFilter(val)
3532 doError('Invalid argument: '+arg, True)
3534 # just run a utility command and exit
3536 if(cmd == 'status'):
3538 elif(cmd == 'fpdt'):
3539 if(sysvals.android):
3540 doError('cannot read FPDT on android device', False)
3542 elif(cmd == 'usbtopo'):
3543 if(sysvals.android):
3544 doError('cannot read USB topology '+\
3545 'on an android device', False)
3547 elif(cmd == 'modes'):
3550 elif(cmd == 'usbauto'):
3552 elif(cmd == 'summary'):
3553 print("Generating a summary of folder \"%s\"" % cmdarg)
3554 runSummary(cmdarg, True)
3557 # run test on android device
3558 if(sysvals.android):
3559 if(sysvals.usecallgraph):
3560 doError('ftrace (-f) is not yet supported '+\
3561 'in the android kernel', False)
3562 if(sysvals.notestrun):
3563 doError('cannot analyze test files on the '+\
3564 'android device', False)
3566 # if instructed, re-analyze existing data files
3567 if(sysvals.notestrun):
3571 # verify that we can run a test
3572 if(not statusCheck()):
3573 print('Check FAILED, aborting the test run!')
3576 if multitest['run']:
3577 # run multiple tests in a separte subdirectory
3578 s = 'x%d' % multitest['count']
3579 subdir = datetime.now().strftime('suspend-'+s+'-%m%d%y-%H%M%S')
3581 for i in range(multitest['count']):
3583 print('Waiting %d seconds...' % (multitest['delay']))
3584 time.sleep(multitest['delay'])
3585 print('TEST (%d/%d) START' % (i+1, multitest['count']))
3587 print('TEST (%d/%d) COMPLETE' % (i+1, multitest['count']))
3588 runSummary(subdir, False)
3590 # run the test in the current directory