?  search:
summary | log | graphiclog1 | graphiclog2 | commit | commitdiff | tree | refs | edit | fork
blame | history | raw | HEAD
mmc: sh_mmcif: Inform the mmc core about the max busy timeout
[linux/fpc-iii.git] / scripts / analyze_suspend.py
blob93e1fd40f43053e599c3d986dd15fb574ea2fb76
1 #!/usr/bin/python
2 #
3 # Tool for analyzing suspend/resume timing
4 # Copyright (c) 2013, Intel Corporation.
5 #
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.
9 #
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
13 # more details.
14 #
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.
18 #
19 # Authors:
20 # Todd Brandt <todd.e.brandt@linux.intel.com>
21 #
22 # Description:
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.
31 #
32 # The following kernel build options are required:
33 # CONFIG_PM_DEBUG=y
34 # CONFIG_PM_SLEEP_DEBUG=y
35 # CONFIG_FTRACE=y
36 # CONFIG_FUNCTION_TRACER=y
37 # CONFIG_FUNCTION_GRAPH_TRACER=y
38 #
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 ..."
43 #
44
45 # ----------------- LIBRARIES --------------------
46
47 import sys
48 import time
49 import os
50 import string
51 import re
52 import platform
53 from datetime import datetime
54 import struct
55
56 # ----------------- CLASSES --------------------
57
58 # Class: SystemValues
59 # Description:
60 # A global, single-instance container used to
61 # store system values and test parameters
62 class SystemValues:
63 version = 3.0
64 verbose = False
65 testdir = '.'
66 tpath = '/sys/kernel/debug/tracing/'
67 fpdtpath = '/sys/firmware/acpi/tables/FPDT'
68 epath = '/sys/kernel/debug/tracing/events/power/'
69 traceevents = [
70 'suspend_resume',
71 'device_pm_callback_end',
72 'device_pm_callback_start'
73 ]
74 modename = {
75 'freeze': 'Suspend-To-Idle (S0)',
76 'standby': 'Power-On Suspend (S1)',
77 'mem': 'Suspend-to-RAM (S3)',
78 'disk': 'Suspend-to-disk (S4)'
79 }
80 mempath = '/dev/mem'
81 powerfile = '/sys/power/state'
82 suspendmode = 'mem'
83 hostname = 'localhost'
84 prefix = 'test'
85 teststamp = ''
86 dmesgfile = ''
87 ftracefile = ''
88 htmlfile = ''
89 rtcwake = False
90 rtcwaketime = 10
91 rtcpath = ''
92 android = False
93 adb = 'adb'
94 devicefilter = []
95 stamp = 0
96 execcount = 1
97 x2delay = 0
98 usecallgraph = False
99 usetraceevents = False
100 usetraceeventsonly = False
101 notestrun = False
102 altdevname = dict()
103 postresumetime = 0
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>.*)$'
110 def __init__(self):
111 self.hostname = platform.node()
112 if(self.hostname == ''):
113 self.hostname = 'localhost'
114 rtc = "rtc0"
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'):
120 self.rtcpath = rtc
121 def setOutputFile(self):
122 if((self.htmlfile == '') and (self.dmesgfile != '')):
123 m = re.match('(?P<name>.*)_dmesg\.txt$', self.dmesgfile)
124 if(m):
125 self.htmlfile = m.group('name')+'.html'
126 if((self.htmlfile == '') and (self.ftracefile != '')):
127 m = re.match('(?P<name>.*)_ftrace\.txt$', self.ftracefile)
128 if(m):
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]
137 else:
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')
142 if(subdir != "."):
143 self.testdir = subdir+"/"+testtime
144 else:
145 self.testdir = testtime
146 self.teststamp = \
147 '# '+testtime+' '+self.prefix+' '+self.suspendmode+' '+kver
148 self.dmesgfile = \
149 self.testdir+'/'+self.prefix+'_'+self.suspendmode+'_dmesg.txt'
150 self.ftracefile = \
151 self.testdir+'/'+self.prefix+'_'+self.suspendmode+'_ftrace.txt'
152 self.htmlfile = \
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)
163 if(mD and mT):
164 # get the current time from hardware
165 utcoffset = int((datetime.now() - datetime.utcnow()).total_seconds())
166 dt = datetime(\
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
170 else:
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))
175
176 sysvals = SystemValues()
177
178 # Class: DeviceNode
179 # Description:
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()
182 class DeviceNode:
183 name = ''
184 children = 0
185 depth = 0
186 def __init__(self, nodename, nodedepth):
187 self.name = nodename
188 self.children = []
189 self.depth = nodedepth
190
191 # Class: Data
192 # Description:
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:
195 # Data.dmesg {
196 # root structure, started as dmesg & ftrace, but now only ftrace
197 # contents: times for suspend start/end, resume start/end, fwdata
198 # phases {
199 # 10 sequential, non-overlapping phases of S/R
200 # contents: times for phase start/end, order/color data for html
201 # devlist {
202 # device callback or action list for this phase
203 # device {
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
209 # }
210 # }
211 # }
212 # }
213 #
214 class Data:
215 dmesg = {} # root data structure
216 phases = [] # ordered list of phases
217 start = 0.0 # test start
218 end = 0.0 # test end
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
226 testnumber = 0
227 idstr = ''
228 html_device_id = 0
229 stamp = 0
230 outfile = ''
231 def __init__(self, num):
232 idchar = 'abcdefghijklmnopqrstuvwxyz'
233 self.testnumber = num
234 self.idstr = idchar[num]
235 self.dmesgtext = []
236 self.phases = []
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}
258 }
259 self.phases = self.sortedPhases()
260 def getStart(self):
261 return self.dmesg[self.phases[0]]['start']
262 def setStart(self, time):
263 self.start = time
264 self.dmesg[self.phases[0]]['start'] = time
265 def getEnd(self):
266 return self.dmesg[self.phases[-1]]['end']
267 def setEnd(self, time):
268 self.end = 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']
273 for dev in list:
274 d = list[dev]
275 if(d['pid'] == pid and time >= d['start'] and
276 time <= d['end']):
277 return False
278 return True
279 def addIntraDevTraceEvent(self, action, name, pid, time):
280 if(action == 'mutex_lock_try'):
281 color = 'red'
282 elif(action == 'mutex_lock_pass'):
283 color = 'green'
284 elif(action == 'mutex_unlock'):
285 color = 'blue'
286 else:
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']
294 for dev in list:
295 d = list[dev]
296 if(d['pid'] == pid and time >= d['start'] and
297 time <= d['end']):
298 e = TraceEvent(action, name, color, time)
299 if('traceevents' not in d):
300 d['traceevents'] = []
301 d['traceevents'].append(e)
302 return d
303 break
304 return 0
305 def capIntraDevTraceEvent(self, action, name, pid, time):
306 for phase in self.phases:
307 list = self.dmesg[phase]['list']
308 for dev in list:
309 d = list[dev]
310 if(d['pid'] == pid and time >= d['start'] and
311 time <= d['end']):
312 if('traceevents' not in d):
313 return
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
318 e.ready = True
319 break
320 return
321 def trimTimeVal(self, t, t0, dT, left):
322 if left:
323 if(t > t0):
324 if(t - dT < t0):
325 return t0
326 return t - dT
327 else:
328 return t
329 else:
330 if(t < t0 + dT):
331 if(t > t0):
332 return t0 + dT
333 return t + dT
334 else:
335 return t
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)
345 list = p['list']
346 for name in list:
347 d = list[name]
348 d['start'] = self.trimTimeVal(d['start'], t0, dT, left)
349 d['end'] = self.trimTimeVal(d['end'], t0, dT, left)
350 if('ftrace' in d):
351 cg = d['ftrace']
352 cg.start = self.trimTimeVal(cg.start, t0, dT, left)
353 cg.end = self.trimTimeVal(cg.end, t0, dT, left)
354 for line in cg.list:
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)
365 else:
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
371 self.start -= tZero
372 self.end -= tZero
373 for phase in self.phases:
374 p = self.dmesg[phase]
375 p['start'] -= tZero
376 p['end'] -= tZero
377 list = p['list']
378 for name in list:
379 d = list[name]
380 d['start'] -= tZero
381 d['end'] -= tZero
382 if('ftrace' in d):
383 cg = d['ftrace']
384 cg.start -= tZero
385 cg.end -= tZero
386 for line in cg.list:
387 line.time -= tZero
388 if('traceevents' in d):
389 for e in d['traceevents']:
390 e.time -= tZero
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)
396 list = dict()
397 list[devname] = \
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):
405 if(order < 0):
406 order = len(self.phases)
407 for phase in self.phases[order:]:
408 self.dmesg[phase]['order'] += 1
409 if(order > 0):
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
415 list = dict()
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):
421 if(isbegin):
422 self.dmesg[phase]['start'] = ktime
423 else:
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']
431 slist = []
432 tmp = dict()
433 for devname in list:
434 dev = list[devname]
435 tmp[dev['start']] = devname
436 for t in sorted(tmp):
437 slist.append(tmp[t])
438 return slist
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]
444 if(dev['end'] < 0):
445 dev['end'] = end
446 vprint('%s (%s): callback didnt return' % (devname, phase))
447 def deviceFilter(self, devicefilter):
448 # remove all by the relatives of the filter devnames
449 filter = []
450 for phase in self.phases:
451 list = self.dmesg[phase]['list']
452 for name in devicefilter:
453 dev = name
454 while(dev in list):
455 if(dev not in filter):
456 filter.append(dev)
457 dev = list[dev]['par']
458 children = self.deviceDescendants(name, phase)
459 for dev in children:
460 if(dev not in filter):
461 filter.append(dev)
462 for phase in self.phases:
463 list = self.dmesg[phase]['list']
464 rmlist = []
465 for name in list:
466 pid = list[name]['pid']
467 if(name not in filter and pid >= 0):
468 rmlist.append(name)
469 for name in rmlist:
470 del list[name]
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"
477 targetphase = "none"
478 overlap = 0.0
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))
483 if(o > overlap):
484 targetphase = phase
485 overlap = o
486 if targetphase in self.phases:
487 self.newAction(targetphase, name, -1, '', start, end, '')
488 return True
489 return False
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']
495 length = -1.0
496 if(start >= 0 and end >= 0):
497 length = end - start
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):
501 idlist = []
502 list = self.dmesg[phase]['list']
503 for devname in list:
504 if devname in devlist:
505 idlist.append(list[devname]['id'])
506 return idlist
507 def deviceParentID(self, devname, phase):
508 pdev = ''
509 pdevid = ''
510 list = self.dmesg[phase]['list']
511 if devname in list:
512 pdev = list[devname]['par']
513 if pdev in list:
514 return list[pdev]['id']
515 return pdev
516 def deviceChildren(self, devname, phase):
517 devlist = []
518 list = self.dmesg[phase]['list']
519 for child in list:
520 if(list[child]['par'] == devname):
521 devlist.append(child)
522 return devlist
523 def deviceDescendants(self, devname, phase):
524 children = self.deviceChildren(devname, phase)
525 family = children
526 for child in children:
527 family += self.deviceDescendants(child, phase)
528 return family
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)
541 for cname in list:
542 clist = self.deviceChildren(cname, 'resume')
543 cnode = self.masterTopology(cname, clist, depth+1)
544 node.children.append(cnode)
545 return node
546 def printTopology(self, node):
547 html = ''
548 if node.name:
549 info = ''
550 drv = ''
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>'
560 if info:
561 html += '<ul>'+info+'</ul>'
562 html += '</li>'
563 if len(node.children) > 0:
564 html += '<ul>'
565 for cnode in node.children:
566 html += self.printTopology(cnode)
567 html += '</ul>'
568 return html
569 def rootDeviceList(self):
570 # list of devices graphed
571 real = []
572 for phase in self.dmesg:
573 list = self.dmesg[phase]['list']
574 for dev in list:
575 if list[dev]['pid'] >= 0 and dev not in real:
576 real.append(dev)
577 # list of top-most root devices
578 rootlist = []
579 for phase in self.dmesg:
580 list = self.dmesg[phase]['list']
581 for dev in list:
582 pdev = list[dev]['par']
583 if(re.match('[0-9]*-[0-9]*\.[0-9]*[\.0-9]*\:[\.0-9]*$', pdev)):
584 continue
585 if pdev and pdev not in real and pdev not in rootlist:
586 rootlist.append(pdev)
587 return rootlist
588 def deviceTopology(self):
589 rootlist = self.rootDeviceList()
590 master = self.masterTopology('', rootlist, 0)
591 return self.printTopology(master)
592
593 # Class: TraceEvent
594 # Description:
595 # A container for trace event data found in the ftrace file
596 class TraceEvent:
597 ready = False
598 name = ''
599 time = 0.0
600 color = '#FFFFFF'
601 length = 0.0
602 action = ''
603 def __init__(self, a, n, c, t):
604 self.action = a
605 self.name = n
606 self.color = c
607 self.time = t
608
609 # Class: FTraceLine
610 # Description:
611 # A container for a single line of ftrace data. There are six basic types:
612 # callgraph line:
613 # call: " dpm_run_callback() {"
614 # return: " }"
615 # leaf: " dpm_run_callback();"
616 # trace event:
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
620 class FTraceLine:
621 time = 0.0
622 length = 0.0
623 fcall = False
624 freturn = False
625 fevent = False
626 depth = 0
627 name = ''
628 type = ''
629 def __init__(self, t, m, d):
630 self.time = float(t)
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
635 msg = m
636 else:
637 # function_graph format trace event
638 em = re.match('^ *\/\* *(?P<msg>.*) \*\/ *$', m)
639 msg = em.group('msg')
640
641 emm = re.match('^(?P<call>.*?): (?P<msg>.*)', msg)
642 if(emm):
643 self.name = emm.group('msg')
644 self.type = emm.group('call')
645 else:
646 self.name = msg
647 self.fevent = True
648 return
649 # convert the duration to seconds
650 if(d):
651 self.length = float(d)/1000000
652 # the indentation determines the depth
653 match = re.match('^(?P<d> *)(?P<o>.*)$', m)
654 if(not match):
655 return
656 self.depth = self.getDepth(match.group('d'))
657 m = match.group('o')
658 # function return
659 if(m[0] == '}'):
660 self.freturn = True
661 if(len(m) > 1):
662 # includes comment with function name
663 match = re.match('^} *\/\* *(?P<n>.*) *\*\/$', m)
664 if(match):
665 self.name = match.group('n')
666 # function call
667 else:
668 self.fcall = True
669 # function call with children
670 if(m[-1] == '{'):
671 match = re.match('^(?P<n>.*) *\(.*', m)
672 if(match):
673 self.name = match.group('n')
674 # function call with no children (leaf)
675 elif(m[-1] == ';'):
676 self.freturn = True
677 match = re.match('^(?P<n>.*) *\(.*', m)
678 if(match):
679 self.name = match.group('n')
680 # something else (possibly a trace marker)
681 else:
682 self.name = m
683 def getDepth(self, str):
684 return len(str)/2
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))
689 elif(self.freturn):
690 print('%s -- %f (%02d): %s} (%.3f us)' % (dev, self.time, \
691 self.depth, self.name, self.length*1000000))
692 else:
693 print('%s -- %f (%02d): %s() { (%.3f us)' % (dev, self.time, \
694 self.depth, self.name, self.length*1000000))
695
696 # Class: FTraceCallGraph
697 # Description:
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:
703 start = -1.0
704 end = -1.0
705 list = []
706 invalid = False
707 depth = 0
708 def __init__(self):
709 self.start = -1.0
710 self.end = -1.0
711 self.list = []
712 self.depth = 0
713 def setDepth(self, line):
714 if(line.fcall and not line.freturn):
715 line.depth = self.depth
716 self.depth += 1
717 elif(line.freturn and not line.fcall):
718 self.depth -= 1
719 line.depth = self.depth
720 else:
721 line.depth = self.depth
722 def addLine(self, line, match):
723 if(not self.invalid):
724 self.setDepth(line)
725 if(line.depth == 0 and line.freturn):
726 if(self.start < 0):
727 self.start = line.time
728 self.end = line.time
729 self.list.append(line)
730 return True
731 if(self.invalid):
732 return False
733 if(len(self.list) >= 1000000 or self.depth < 0):
734 if(len(self.list) > 0):
735 first = self.list[0]
736 self.list = []
737 self.list.append(first)
738 self.invalid = True
739 if(not match):
740 return False
741 id = 'task %s cpu %s' % (match.group('pid'), match.group('cpu'))
742 window = '(%f - %f)' % (self.start, line.time)
743 if(self.depth < 0):
744 print('Too much data for '+id+\
745 ' (buffer overflow), ignoring this callback')
746 else:
747 print('Too much data for '+id+\
748 ' '+window+', ignoring this callback')
749 return False
750 self.list.append(line)
751 if(self.start < 0):
752 self.start = line.time
753 return False
754 def slice(self, t0, tN):
755 minicg = FTraceCallGraph()
756 count = -1
757 firstdepth = 0
758 for l in self.list:
759 if(l.time < t0 or l.time > tN):
760 continue
761 if(count < 0):
762 if(not l.fcall or l.name == 'dev_driver_string'):
763 continue
764 firstdepth = l.depth
765 count = 0
766 l.depth -= firstdepth
767 minicg.addLine(l, 0)
768 if((count == 0 and l.freturn and l.fcall) or
769 (count > 0 and l.depth <= 0)):
770 break
771 count += 1
772 return minicg
773 def sanityCheck(self):
774 stack = dict()
775 cnt = 0
776 for l in self.list:
777 if(l.fcall and not l.freturn):
778 stack[l.depth] = l
779 cnt += 1
780 elif(l.freturn and not l.fcall):
781 if(l.depth not in stack):
782 return False
783 stack[l.depth].length = l.length
784 stack[l.depth] = 0
785 l.length = 0
786 cnt -= 1
787 if(cnt == 0):
788 return True
789 return False
790 def debugPrint(self, filename):
791 if(filename == 'stdout'):
792 print('[%f - %f]') % (self.start, self.end)
793 for l in self.list:
794 if(l.freturn and l.fcall):
795 print('%f (%02d): %s(); (%.3f us)' % (l.time, \
796 l.depth, l.name, l.length*1000000))
797 elif(l.freturn):
798 print('%f (%02d): %s} (%.3f us)' % (l.time, \
799 l.depth, l.name, l.length*1000000))
800 else:
801 print('%f (%02d): %s() { (%.3f us)' % (l.time, \
802 l.depth, l.name, l.length*1000000))
803 print(' ')
804 else:
805 fp = open(filename, 'w')
806 print(filename)
807 for l in self.list:
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))
811 elif(l.freturn):
812 fp.write('%f (%02d): %s} (%.3f us)\n' % (l.time, \
813 l.depth, l.name, l.length*1000000))
814 else:
815 fp.write('%f (%02d): %s() { (%.3f us)\n' % (l.time, \
816 l.depth, l.name, l.length*1000000))
817 fp.close()
818
819 # Class: Timeline
820 # Description:
821 # A container for a suspend/resume html timeline. In older versions
822 # of the script there were multiple timelines, but in the latest
823 # there is only one.
824 class Timeline:
825 html = {}
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
829 maxrows = 0
830 height = 0
831 def __init__(self):
832 self.html = {
833 'timeline': '',
834 'legend': '',
835 'scale': ''
836 }
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)
842 if(r < 1.0):
843 r = 1.0
844 self.rowH = (100.0 - self.scaleH)/r
845
846 # Class: TestRun
847 # Description:
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.
850 class TestRun:
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\.]*): *'+\
858 '(?P<msg>.*)'
859 ftrace_line_fmt = ftrace_line_fmt_nop
860 cgformat = False
861 ftemp = dict()
862 ttemp = dict()
863 inthepipe = False
864 tracertype = ''
865 data = 0
866 def __init__(self, dataobj):
867 self.data = dataobj
868 self.ftemp = dict()
869 self.ttemp = dict()
870 def isReady(self):
871 if(tracertype == '' or not data):
872 return False
873 return True
874 def setTracerType(self, tracer):
875 self.tracertype = tracer
876 if(tracer == 'function_graph'):
877 self.cgformat = True
878 self.ftrace_line_fmt = self.ftrace_line_fmt_fg
879 elif(tracer == 'nop'):
880 self.ftrace_line_fmt = self.ftrace_line_fmt_nop
881 else:
882 doError('Invalid tracer format: [%s]' % tracer, False)
883
884 # ----------------- FUNCTIONS --------------------
885
886 # Function: vprint
887 # Description:
888 # verbose print (prints only with -verbose option)
889 # Arguments:
890 # msg: the debug/log message to print
891 def vprint(msg):
892 global sysvals
893 if(sysvals.verbose):
894 print(msg)
895
896 # Function: initFtrace
897 # Description:
898 # Configure ftrace to use trace events and/or a callgraph
899 def initFtrace():
900 global sysvals
901
902 tp = sysvals.tpath
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...')
908 # turn trace off
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):
917 # set trace type
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)
929 for e in events:
930 os.system('echo 1 > '+sysvals.epath+e+'/enable')
931 # clear the trace buffer
932 os.system('echo "" > '+tp+'trace')
933
934 # Function: initFtraceAndroid
935 # Description:
936 # Configure ftrace to capture trace events
937 def initFtraceAndroid():
938 global sysvals
939
940 tp = sysvals.tpath
941 if(sysvals.usetraceevents):
942 print('INITIALIZING FTRACE...')
943 # turn trace off
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)
952 for e in events:
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'")
957
958 # Function: verifyFtrace
959 # Description:
960 # Check that ftrace is working on the system
961 # Output:
962 # True or False
963 def verifyFtrace():
964 global sysvals
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
969 tp = sysvals.tpath
970 if(sysvals.usecallgraph):
971 files += [
972 'available_filter_functions',
973 'set_ftrace_filter',
974 'set_graph_function'
975 ]
976 for f in files:
977 if(sysvals.android):
978 out = os.popen(sysvals.adb+' shell ls '+tp+f).read().strip()
979 if(out != tp+f):
980 return False
981 else:
982 if(os.path.exists(tp+f) == False):
983 return False
984 return True
985
986 # Function: parseStamp
987 # Description:
988 # Pull in the stamp comment line from the data file(s),
989 # create the stamp, and add it to the global sysvals object
990 # Arguments:
991 # m: the valid re.match output for the stamp line
992 def parseStamp(m, data):
993 global sysvals
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')),
997 int(m.group('S')))
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
1005
1006 # Function: diffStamp
1007 # Description:
1008 # compare the host, kernel, and mode fields in 3 stamps
1009 # Arguments:
1010 # stamp1: string array with mode, kernel, and host
1011 # stamp2: string array with mode, kernel, and host
1012 # Return:
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']:
1017 return True
1018 if 'kernel' in stamp1 and 'kernel' in stamp2:
1019 if stamp1['kernel'] != stamp2['kernel']:
1020 return True
1021 if 'mode' in stamp1 and 'mode' in stamp2:
1022 if stamp1['mode'] != stamp2['mode']:
1023 return True
1024 return False
1025
1026 # Function: doesTraceLogHaveTraceEvents
1027 # Description:
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():
1032 global sysvals
1033
1034 sysvals.usetraceeventsonly = True
1035 sysvals.usetraceevents = False
1036 for e in sysvals.traceevents:
1037 out = os.popen('cat '+sysvals.ftracefile+' | grep "'+e+': "').read()
1038 if(not out):
1039 sysvals.usetraceeventsonly = False
1040 if(e == 'suspend_resume' and out):
1041 sysvals.usetraceevents = True
1042
1043 # Function: appendIncompleteTraceLog
1044 # Description:
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
1050 # objects provided.
1051 # Arguments:
1052 # testruns: the array of Data objects obtained from parseKernelLog
1053 def appendIncompleteTraceLog(testruns):
1054 global sysvals
1055
1056 # create TestRun vessels for ftrace parsing
1057 testcnt = len(testruns)
1058 testidx = -1
1059 testrun = []
1060 for data in testruns:
1061 testrun.append(TestRun(data))
1062
1063 # extract the callgraph and traceevent data
1064 vprint('Analyzing the ftrace data...')
1065 tf = open(sysvals.ftracefile, 'r')
1066 for line in tf:
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)
1071 if(m):
1072 testidx += 1
1073 parseStamp(m, testrun[testidx].data)
1074 continue
1075 # pull out any firmware data
1076 if(re.match(sysvals.firmwarefmt, line)):
1077 continue
1078 # if we havent found a test time stamp yet keep spinning til we do
1079 if(testidx < 0):
1080 continue
1081 # determine the trace data type (required for further parsing)
1082 m = re.match(sysvals.tracertypefmt, line)
1083 if(m):
1084 tracer = m.group('t')
1085 testrun[testidx].setTracerType(tracer)
1086 continue
1087 # parse only valid lines, if this isnt one move on
1088 m = re.match(testrun[testidx].ftrace_line_fmt, line)
1089 if(not m):
1090 continue
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')
1097 else:
1098 m_param3 = 'traceevent'
1099 if(m_time and m_pid and m_msg):
1100 t = FTraceLine(m_time, m_msg, m_param3)
1101 pid = int(m_pid)
1102 else:
1103 continue
1104 # the line should be a call, return, or event
1105 if(not t.fcall and not t.freturn and not t.fevent):
1106 continue
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
1111 if(t.fevent):
1112 if(t.name == 'SUSPEND START'):
1113 testrun[testidx].inthepipe = True
1114 data.setStart(t.time)
1115 continue
1116 else:
1117 # trace event processing
1118 if(t.fevent):
1119 if(t.name == 'RESUME COMPLETE'):
1120 testrun[testidx].inthepipe = False
1121 data.setEnd(t.time)
1122 if(testidx == testcnt - 1):
1123 break
1124 continue
1125 # general trace events have two types, begin and end
1126 if(re.match('(?P<name>.*) begin$', t.name)):
1127 isbegin = True
1128 elif(re.match('(?P<name>.*) end$', t.name)):
1129 isbegin = False
1130 else:
1131 continue
1132 m = re.match('(?P<name>.*)\[(?P<val>[0-9]*)\] .*', t.name)
1133 if(m):
1134 val = m.group('val')
1135 if val == '0':
1136 name = m.group('name')
1137 else:
1138 name = m.group('name')+'['+val+']'
1139 else:
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):
1144 continue
1145 elif re.match('machine_suspend.*', name):
1146 continue
1147 elif re.match('suspend_enter\[.*', name):
1148 if(not isbegin):
1149 data.dmesg['suspend_prepare']['end'] = t.time
1150 continue
1151 elif re.match('dpm_suspend\[.*', name):
1152 if(not isbegin):
1153 data.dmesg['suspend']['end'] = t.time
1154 continue
1155 elif re.match('dpm_suspend_late\[.*', name):
1156 if(isbegin):
1157 data.dmesg['suspend_late']['start'] = t.time
1158 else:
1159 data.dmesg['suspend_late']['end'] = t.time
1160 continue
1161 elif re.match('dpm_suspend_noirq\[.*', name):
1162 if(isbegin):
1163 data.dmesg['suspend_noirq']['start'] = t.time
1164 else:
1165 data.dmesg['suspend_noirq']['end'] = t.time
1166 continue
1167 elif re.match('dpm_resume_noirq\[.*', name):
1168 if(isbegin):
1169 data.dmesg['resume_machine']['end'] = t.time
1170 data.dmesg['resume_noirq']['start'] = t.time
1171 else:
1172 data.dmesg['resume_noirq']['end'] = t.time
1173 continue
1174 elif re.match('dpm_resume_early\[.*', name):
1175 if(isbegin):
1176 data.dmesg['resume_early']['start'] = t.time
1177 else:
1178 data.dmesg['resume_early']['end'] = t.time
1179 continue
1180 elif re.match('dpm_resume\[.*', name):
1181 if(isbegin):
1182 data.dmesg['resume']['start'] = t.time
1183 else:
1184 data.dmesg['resume']['end'] = t.time
1185 continue
1186 elif re.match('dpm_complete\[.*', name):
1187 if(isbegin):
1188 data.dmesg['resume_complete']['start'] = t.time
1189 else:
1190 data.dmesg['resume_complete']['end'] = t.time
1191 continue
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
1195 if(isbegin):
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})
1201 else:
1202 # finish off matching trace event in ttemp
1203 if(name in testrun[testidx].ttemp):
1204 testrun[testidx].ttemp[name][-1]['end'] = t.time
1205 else:
1206 if(isbegin):
1207 data.addIntraDevTraceEvent('', name, pid, t.time)
1208 else:
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())
1220 tf.close()
1221
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']
1228 end = event['end']
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)
1236
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')
1244 continue
1245 callstart = cg.start
1246 callend = cg.end
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:
1252 dev = list[devname]
1253 if(pid == dev['pid'] and
1254 callstart <= dev['start'] and
1255 callend >= dev['end']):
1256 dev['ftrace'] = cg
1257 break
1258
1259 if(sysvals.verbose):
1260 test.data.printDetails()
1261
1262
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')
1269
1270 # Function: parseTraceLog
1271 # Description:
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
1276 # Output:
1277 # An array of Data objects
1278 def parseTraceLog():
1279 global sysvals
1280
1281 vprint('Analyzing the ftrace data...')
1282 if(os.path.exists(sysvals.ftracefile) == False):
1283 doError('%s doesnt exist' % sysvals.ftracefile, False)
1284
1285 # extract the callgraph and traceevent data
1286 testruns = []
1287 testdata = []
1288 testrun = 0
1289 data = 0
1290 tf = open(sysvals.ftracefile, 'r')
1291 phase = 'suspend_prepare'
1292 for line in tf:
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)
1297 if(m):
1298 data = Data(len(testdata))
1299 testdata.append(data)
1300 testrun = TestRun(data)
1301 testruns.append(testrun)
1302 parseStamp(m, data)
1303 continue
1304 if(not data):
1305 continue
1306 # firmware line: pull out any firmware data
1307 m = re.match(sysvals.firmwarefmt, line)
1308 if(m):
1309 data.fwSuspend = int(m.group('s'))
1310 data.fwResume = int(m.group('r'))
1311 if(data.fwSuspend > 0 or data.fwResume > 0):
1312 data.fwValid = True
1313 continue
1314 # tracer type line: determine the trace data type
1315 m = re.match(sysvals.tracertypefmt, line)
1316 if(m):
1317 tracer = m.group('t')
1318 testrun.setTracerType(tracer)
1319 continue
1320 # post resume time line: did this test run include post-resume data
1321 m = re.match(sysvals.postresumefmt, line)
1322 if(m):
1323 t = int(m.group('t'))
1324 if(t > 0):
1325 sysvals.postresumetime = t
1326 continue
1327 # ftrace line: parse only valid lines
1328 m = re.match(testrun.ftrace_line_fmt, line)
1329 if(not m):
1330 continue
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')
1337 else:
1338 m_param3 = 'traceevent'
1339 if(m_time and m_pid and m_msg):
1340 t = FTraceLine(m_time, m_msg, m_param3)
1341 pid = int(m_pid)
1342 else:
1343 continue
1344 # the line should be a call, return, or event
1345 if(not t.fcall and not t.freturn and not t.fevent):
1346 continue
1347 # only parse the ftrace data during suspend/resume
1348 if(not testrun.inthepipe):
1349 # look for the suspend start marker
1350 if(t.fevent):
1351 if(t.name == 'SUSPEND START'):
1352 testrun.inthepipe = True
1353 data.setStart(t.time)
1354 continue
1355 # trace event processing
1356 if(t.fevent):
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)
1361 else:
1362 testrun.inthepipe = False
1363 data.setEnd(t.time)
1364 continue
1365 if(phase == 'post_resume'):
1366 data.setEnd(t.time)
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)):
1370 isbegin = True
1371 elif(re.match('(?P<name>.*) end$', t.name)):
1372 isbegin = False
1373 else:
1374 continue
1375 m = re.match('(?P<name>.*)\[(?P<val>[0-9]*)\] .*', t.name)
1376 if(m):
1377 val = m.group('val')
1378 if val == '0':
1379 name = m.group('name')
1380 else:
1381 name = m.group('name')+'['+val+']'
1382 else:
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)):
1388 continue
1389 # -- phase changes --
1390 # suspend_prepare start
1391 if(re.match('dpm_prepare\[.*', t.name)):
1392 phase = 'suspend_prepare'
1393 if(not isbegin):
1394 data.dmesg[phase]['end'] = t.time
1395 continue
1396 # suspend start
1397 elif(re.match('dpm_suspend\[.*', t.name)):
1398 phase = 'suspend'
1399 data.setPhase(phase, t.time, isbegin)
1400 continue
1401 # suspend_late start
1402 elif(re.match('dpm_suspend_late\[.*', t.name)):
1403 phase = 'suspend_late'
1404 data.setPhase(phase, t.time, isbegin)
1405 continue
1406 # suspend_noirq start
1407 elif(re.match('dpm_suspend_noirq\[.*', t.name)):
1408 phase = 'suspend_noirq'
1409 data.setPhase(phase, t.time, isbegin)
1410 if(not isbegin):
1411 phase = 'suspend_machine'
1412 data.dmesg[phase]['start'] = t.time
1413 continue
1414 # suspend_machine/resume_machine
1415 elif(re.match('machine_suspend\[.*', t.name)):
1416 if(isbegin):
1417 phase = 'suspend_machine'
1418 data.dmesg[phase]['end'] = t.time
1419 data.tSuspended = t.time
1420 else:
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
1428 continue
1429 # resume_noirq start
1430 elif(re.match('dpm_resume_noirq\[.*', t.name)):
1431 phase = 'resume_noirq'
1432 data.setPhase(phase, t.time, isbegin)
1433 if(isbegin):
1434 data.dmesg['resume_machine']['end'] = t.time
1435 continue
1436 # resume_early start
1437 elif(re.match('dpm_resume_early\[.*', t.name)):
1438 phase = 'resume_early'
1439 data.setPhase(phase, t.time, isbegin)
1440 continue
1441 # resume start
1442 elif(re.match('dpm_resume\[.*', t.name)):
1443 phase = 'resume'
1444 data.setPhase(phase, t.time, isbegin)
1445 continue
1446 # resume complete start
1447 elif(re.match('dpm_complete\[.*', t.name)):
1448 phase = 'resume_complete'
1449 if(isbegin):
1450 data.dmesg[phase]['start'] = t.time
1451 continue
1452
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] = []
1458 if(isbegin):
1459 # create a new list entry
1460 testrun.ttemp[name].append(\
1461 {'begin': t.time, 'end': t.time})
1462 else:
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'],
1470 'end': t.time})
1471 else:
1472 if(isbegin):
1473 data.addIntraDevTraceEvent('', name, pid, t.time)
1474 else:
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>.*), .*',\
1479 t.name);
1480 if(not m):
1481 continue
1482 drv = m.group('drv')
1483 n = m.group('d')
1484 p = m.group('p')
1485 if(n and p):
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);
1490 if(not m):
1491 continue
1492 n = m.group('d')
1493 list = data.dmesg[phase]['list']
1494 if(n in list):
1495 dev = list[n]
1496 dev['length'] = t.time - dev['start']
1497 dev['end'] = t.time
1498 # callgraph processing
1499 elif sysvals.usecallgraph:
1500 # this shouldn't happen, but JIC, ignore callgraph data post-res
1501 if(phase == 'post_resume'):
1502 continue
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())
1511 tf.close()
1512
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']
1519 end = event['end']
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)
1527
1528 # add the callgraph data to the device hierarchy
1529 borderphase = {
1530 'dpm_prepare': 'suspend_prepare',
1531 'dpm_complete': 'resume_complete'
1532 }
1533 for pid in test.ftemp:
1534 for cg in test.ftemp[pid]:
1535 if len(cg.list) < 2:
1536 continue
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')
1541 continue
1542 callstart = cg.start
1543 callend = cg.end
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:
1548 dev = list[devname]
1549 if(pid == dev['pid'] and
1550 callstart <= dev['start'] and
1551 callend >= dev['end']):
1552 dev['ftrace'] = cg.slice(dev['start'], dev['end'])
1553 continue
1554 if(cg.list[0].name != 'dpm_run_callback'):
1555 continue
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:
1561 dev = list[devname]
1562 if(pid == dev['pid'] and
1563 callstart <= dev['start'] and
1564 callend >= dev['end']):
1565 dev['ftrace'] = cg
1566 break
1567
1568 # fill in any missing phases
1569 for data in testdata:
1570 lp = data.phases[0]
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']
1579 data.tLow = 0
1580 if(data.dmesg[p]['end'] < 0):
1581 data.dmesg[p]['end'] = data.dmesg[p]['start']
1582 lp = p
1583
1584 if(len(sysvals.devicefilter) > 0):
1585 data.deviceFilter(sysvals.devicefilter)
1586 data.fixupInitcallsThatDidntReturn()
1587 if(sysvals.verbose):
1588 data.printDetails()
1589
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')
1596 return testdata
1597
1598 # Function: loadKernelLog
1599 # Description:
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
1603 # Output:
1604 # An array of empty Data objects with only their dmesgtext attributes set
1605 def loadKernelLog():
1606 global sysvals
1607
1608 vprint('Analyzing the dmesg data...')
1609 if(os.path.exists(sysvals.dmesgfile) == False):
1610 doError('%s doesnt exist' % sysvals.dmesgfile, False)
1611
1612 # there can be multiple test runs in a single file delineated by stamps
1613 testruns = []
1614 data = 0
1615 lf = open(sysvals.dmesgfile, 'r')
1616 for line in lf:
1617 line = line.replace('\r\n', '')
1618 idx = line.find('[')
1619 if idx > 1:
1620 line = line[idx:]
1621 m = re.match(sysvals.stampfmt, line)
1622 if(m):
1623 if(data):
1624 testruns.append(data)
1625 data = Data(len(testruns))
1626 parseStamp(m, data)
1627 continue
1628 if(not data):
1629 continue
1630 m = re.match(sysvals.firmwarefmt, line)
1631 if(m):
1632 data.fwSuspend = int(m.group('s'))
1633 data.fwResume = int(m.group('r'))
1634 if(data.fwSuspend > 0 or data.fwResume > 0):
1635 data.fwValid = True
1636 continue
1637 m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line)
1638 if(m):
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'
1644 else:
1645 vprint('ignoring dmesg line: %s' % line.replace('\n', ''))
1646 testruns.append(data)
1647 lf.close()
1648
1649 if(not data):
1650 print('ERROR: analyze_suspend header missing from dmesg log')
1651 sys.exit()
1652
1653 # fix lines with same timestamp/function with the call and return swapped
1654 for data in testruns:
1655 last = ''
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
1667 last = line
1668 return testruns
1669
1670 # Function: parseKernelLog
1671 # Description:
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.
1678 # Arguments:
1679 # data: an empty Data object (with dmesgtext) obtained from loadKernelLog
1680 # Output:
1681 # The filled Data object
1682 def parseKernelLog(data):
1683 global sysvals
1684
1685 phase = 'suspend_runtime'
1686
1687 if(data.fwValid):
1688 vprint('Firmware Suspend = %u ns, Firmware Resume = %u ns' % \
1689 (data.fwSuspend, data.fwResume))
1690
1691 # dmesg phase match table
1692 dm = {
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 \.\.\..*',
1704 }
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'
1717
1718 # action table (expected events that occur and show up in dmesg)
1719 at = {
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.*' },
1726 'freeze_tasks': {
1727 'smsg': 'Freezing remaining freezable tasks.*',
1728 'emsg': 'PM: Entering (?P<mode>[a-z,A-Z]*) sleep.*' },
1729 'ACPI prepare': {
1730 'smsg': 'ACPI: Preparing to enter system sleep state.*',
1731 'emsg': 'PM: Saving platform NVS memory.*' },
1732 'PM vns': {
1733 'smsg': 'PM: Saving platform NVS memory.*',
1734 'emsg': 'Disabling non-boot CPUs .*' },
1735 }
1736
1737 t0 = -1.0
1738 cpu_start = -1.0
1739 prevktime = -1.0
1740 actions = dict()
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)
1745 if(m):
1746 val = m.group('ktime')
1747 try:
1748 ktime = float(val)
1749 except:
1750 doWarning('INVALID DMESG LINE: '+\
1751 line.replace('\n', ''), 'dmesg')
1752 continue
1753 msg = m.group('msg')
1754 # initialize data start to first line time
1755 if t0 < 0:
1756 data.setStart(ktime)
1757 t0 = ktime
1758 else:
1759 continue
1760
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
1768
1769 # -- phase changes --
1770 # suspend start
1771 if(re.match(dm['suspend_prepare'], msg)):
1772 phase = 'suspend_prepare'
1773 data.dmesg[phase]['start'] = ktime
1774 data.setStart(ktime)
1775 # suspend start
1776 elif(re.match(dm['suspend'], msg)):
1777 data.dmesg['suspend_prepare']['end'] = ktime
1778 phase = 'suspend'
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
1800 else:
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
1817 # resume start
1818 elif(re.match(dm['resume'], msg)):
1819 data.dmesg['resume_early']['end'] = ktime
1820 phase = 'resume'
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
1827 # post resume start
1828 elif(re.match(dm['post_resume'], msg)):
1829 data.dmesg['resume_complete']['end'] = ktime
1830 data.setEnd(ktime)
1831 phase = 'post_resume'
1832 break
1833
1834 # -- device callbacks --
1835 if(phase in data.phases):
1836 # device init call
1837 if(re.match('calling (?P<f>.*)\+ @ .*, parent: .*', msg)):
1838 sm = re.match('calling (?P<f>.*)\+ @ '+\
1839 '(?P<n>.*), parent: (?P<p>.*)', msg);
1840 f = sm.group('f')
1841 n = sm.group('n')
1842 p = sm.group('p')
1843 if(f and n and p):
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);
1850 f = sm.group('f')
1851 t = sm.group('t')
1852 list = data.dmesg[phase]['list']
1853 if(f in list):
1854 dev = list[f]
1855 dev['length'] = int(t)
1856 dev['end'] = ktime
1857
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
1862 for a in at:
1863 if(re.match(at[a]['smsg'], msg)):
1864 if(a not in actions):
1865 actions[a] = []
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
1872 cpu_start = ktime
1873 elif(re.match('Enabling non-boot CPUs .*', msg)):
1874 # start of first cpu resume
1875 cpu_start = ktime
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):
1881 actions[cpu] = []
1882 actions[cpu].append({'begin': cpu_start, 'end': ktime})
1883 cpu_start = 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):
1889 actions[cpu] = []
1890 actions[cpu].append({'begin': cpu_start, 'end': ktime})
1891 cpu_start = ktime
1892 prevktime = ktime
1893
1894 # fill in any missing phases
1895 lp = data.phases[0]
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']
1907 data.tLow = 0
1908 if(data.dmesg[p]['end'] < 0):
1909 data.dmesg[p]['end'] = data.dmesg[p]['start']
1910 lp = p
1911
1912 # fill in any actions we've found
1913 for name in actions:
1914 for event in actions[name]:
1915 begin = event['begin']
1916 end = event['end']
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
1921 if(end > data.end):
1922 data.setEnd(end)
1923 data.newActionGlobal(name, begin, end)
1924
1925 if(sysvals.verbose):
1926 data.printDetails()
1927 if(len(sysvals.devicefilter) > 0):
1928 data.deviceFilter(sysvals.devicefilter)
1929 data.fixupInitcallsThatDidntReturn()
1930 return True
1931
1932 # Function: setTimelineRows
1933 # Description:
1934 # Organize the timeline entries into the smallest
1935 # number of rows possible, with no entry overlapping
1936 # Arguments:
1937 # list: the list of devices/actions for a single phase
1938 # sortedkeys: cronologically sorted key list to use
1939 # Output:
1940 # The total number of rows needed to display this phase of the timeline
1941 def setTimelineRows(list, sortedkeys):
1942
1943 # clear all rows and set them to undefined
1944 remaining = len(list)
1945 rowdata = dict()
1946 row = 0
1947 for item in list:
1948 list[item]['row'] = -1
1949
1950 # try to pack each row with as many ranges as possible
1951 while(remaining > 0):
1952 if(row not in rowdata):
1953 rowdata[row] = []
1954 for item in sortedkeys:
1955 if(list[item]['row'] < 0):
1956 s = list[item]['start']
1957 e = list[item]['end']
1958 valid = True
1959 for ritem in rowdata[row]:
1960 rs = ritem['start']
1961 re = ritem['end']
1962 if(not (((s <= rs) and (e <= rs)) or
1963 ((s >= re) and (e >= re)))):
1964 valid = False
1965 break
1966 if(valid):
1967 rowdata[row].append(list[item])
1968 list[item]['row'] = row
1969 remaining -= 1
1970 row += 1
1971 return row
1972
1973 # Function: createTimeScale
1974 # Description:
1975 # Create the timescale header for the html timeline
1976 # Arguments:
1977 # t0: start time (suspend begin)
1978 # tMax: end time (resume end)
1979 # tSuspend: time when suspend occurs, i.e. the zero time
1980 # Output:
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'
1985
1986 # set scale for timeline
1987 tTotal = tMax - t0
1988 tS = 0.1
1989 if(tTotal <= 0):
1990 return output
1991 if(tTotal > 4):
1992 tS = 1
1993 if(tSuspended < 0):
1994 for i in range(int(tTotal/tS)+1):
1995 pos = '%0.3f' % (100 - ((float(i)*tS*100)/tTotal))
1996 if(i > 0):
1997 val = '%0.fms' % (float(i)*tS*1000)
1998 else:
1999 val = ''
2000 output += timescale.format(pos, val)
2001 else:
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)):
2009 val = ''
2010 elif(i == divSuspend):
2011 val = 'S/R'
2012 else:
2013 val = '%0.fms' % (float(i-divSuspend)*tS*1000)
2014 output += timescale.format(pos, val)
2015 output += '</div>\n'
2016 return output
2017
2018 # Function: createHTMLSummarySimple
2019 # Description:
2020 # Create summary html file for a series of tests
2021 # Arguments:
2022 # testruns: array of Data objects from parseTraceLog
2023 def createHTMLSummarySimple(testruns, htmlfile):
2024 global sysvals
2025
2026 # print out the basic summary of all the tests
2027 hf = open(htmlfile, 'w')
2028
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'
2047
2048 # group test header
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)
2054
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):
2059 stampcolumns = True
2060 break
2061
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'
2065
2066 # table header
2067 html += '<table class="summary">\n<tr>\n'
2068 html += th.format("Test #")
2069 if stampcolumns:
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")
2077 html += '</tr>\n'
2078
2079 # test data, 1 row per test
2080 sTimeAvg = 0.0
2081 rTimeAvg = 0.0
2082 num = 1
2083 for data in testruns:
2084 # data.end is the end of post_resume
2085 resumeEnd = data.dmesg['resume_complete']['end']
2086 if num % 2 == 1:
2087 html += '<tr class="alt">\n'
2088 else:
2089 html += '<tr>\n'
2090
2091 # test num
2092 html += td.format("test %d" % num)
2093 num += 1
2094 if stampcolumns:
2095 # host name
2096 val = "unknown"
2097 if('host' in data.stamp):
2098 val = data.stamp['host']
2099 html += td.format(val)
2100 # host kernel
2101 val = "unknown"
2102 if('kernel' in data.stamp):
2103 val = data.stamp['kernel']
2104 html += td.format(val)
2105 # suspend mode
2106 val = "unknown"
2107 if('mode' in data.stamp):
2108 val = data.stamp['mode']
2109 html += td.format(val)
2110 # test time
2111 val = "unknown"
2112 if('time' in data.stamp):
2113 val = data.stamp['time']
2114 html += td.format(val)
2115 # suspend time
2116 sTime = (data.tSuspended - data.start)*1000
2117 sTimeAvg += sTime
2118 html += td.format("%3.3f ms" % sTime)
2119 # resume time
2120 rTime = (resumeEnd - data.tResumed)*1000
2121 rTimeAvg += rTime
2122 html += td.format("%3.3f ms" % rTime)
2123 # link to the output html
2124 html += tdlink.format(data.outfile)
2125
2126 html += '</tr>\n'
2127
2128 # last line: test average
2129 if(count > 0):
2130 sTimeAvg /= count
2131 rTimeAvg /= count
2132 html += '<tr class="avg">\n'
2133 html += td.format('Average') # name
2134 if stampcolumns:
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
2142 html += '</tr>\n'
2143
2144 # flush the data to file
2145 hf.write(html+'</table>\n')
2146 hf.write('</body>\n</html>\n')
2147 hf.close()
2148
2149 # Function: createHTML
2150 # Description:
2151 # Create the output html file from the resident test data
2152 # Arguments:
2153 # testruns: array of Data objects from parseKernelLog or parseTraceLog
2154 # Output:
2155 # True if the html file was created, false if it failed
2156 def createHTML(testruns):
2157 global sysvals
2158
2159 for data in testruns:
2160 data.normalizeTime(testruns[-1].tSuspended)
2161
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}">&nbsp;{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>'\
2179 '</tr>\n</table>\n'
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>'\
2184 '</tr>\n</table>\n'
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>'\
2190 '</tr>\n</table>\n'
2191
2192 # device timeline
2193 vprint('Creating Device Timeline...')
2194 devtl = Timeline()
2195
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']
2201 if(tTotal == 0):
2202 print('ERROR: No timeline data')
2203 sys.exit()
2204 if(data.tLow > 0):
2205 low_time = '%.0f'%(data.tLow*1000)
2206 if data.fwValid:
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))
2211 testdesc1 = 'Total'
2212 testdesc2 = ''
2213 if(len(testruns) > 1):
2214 testdesc1 = testdesc2 = textnum[data.testnumber]
2215 testdesc2 += ' '
2216 if(data.tLow == 0):
2217 thtml = html_timetotal.format(suspend_time, \
2218 resume_time, testdesc1)
2219 else:
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)
2231 else:
2232 suspend_time = '%.0f'%((data.tSuspended-data.start)*1000)
2233 resume_time = '%.0f'%((tEnd-data.tSuspended)*1000)
2234 testdesc = 'Kernel'
2235 if(len(testruns) > 1):
2236 testdesc = textnum[data.testnumber]+' '+testdesc
2237 if(data.tLow == 0):
2238 thtml = html_timetotal.format(suspend_time, \
2239 resume_time, testdesc)
2240 else:
2241 thtml = html_timetotal2.format(suspend_time, low_time, \
2242 resume_time, testdesc)
2243 devtl.html['timeline'] += thtml
2244
2245 # time scale for potentially multiple datasets
2246 t0 = testruns[0].start
2247 tMax = testruns[-1].end
2248 tSuspended = testruns[-1].tSuspended
2249 tTotal = tMax - t0
2250
2251 # determine the maximum number of rows we need to draw
2252 timelinerows = 0
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):
2259 timelinerows = rows
2260
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)
2268
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'], '')
2279
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']
2286 for d in phaselist:
2287 name = d
2288 drv = ''
2289 dev = phaselist[d]
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)
2302
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, \
2324 width, e.color, '')
2325
2326 # timeline is finished
2327 devtl.html['timeline'] += '</div>\n</div>\n'
2328
2329 # draw a legend which describes the phases by color
2330 data = testruns[-1]
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, '_', ' &nbsp;')
2337 devtl.html['legend'] += html_legend.format(order, \
2338 data.dmesg[phase]['color'], name)
2339 devtl.html['legend'] += '</div>\n'
2340
2341 hf = open(sysvals.htmlfile, 'w')
2342 thread_height = 0
2343
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)
2391
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']))
2397
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')
2415
2416 # write the ftrace data (callgraph)
2417 data = testruns[-1]
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'
2425 num = 0
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]):
2430 continue
2431 name = 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))
2440 num += 1
2441 for line in cg.list:
2442 if(line.length < 0.000000001):
2443 flen = ''
2444 else:
2445 flen = '<n>(%.3f ms @ %.3f)</n>' % (line.length*1000, \
2446 line.time*1000)
2447 if(line.freturn and line.fcall):
2448 hf.write(html_func_leaf.format(line.name, flen))
2449 elif(line.freturn):
2450 hf.write(html_func_end)
2451 else:
2452 hf.write(html_func_start.format(num, line.name, flen))
2453 num += 1
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')
2459 hf.close()
2460 return True
2461
2462 # Function: addScriptCode
2463 # Description:
2464 # Adds the javascript code to the output html
2465 # Arguments:
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
2478 script_code = \
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'\
2497 ' } else {\n'\
2498 ' zoombox.scrollLeft = 0;\n'\
2499 ' dmesg.style.width = "100%";\n'\
2500 ' }\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'\
2512 ' }\n'\
2513 ' timescale.innerHTML = html;\n'\
2514 ' }\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'\
2519 ' var cpu = -1;\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'\
2528 ' {\n'\
2529 ' dev[i].className = "thread hover";\n'\
2530 ' } else {\n'\
2531 ' dev[i].className = "thread";\n'\
2532 ' }\n'\
2533 ' }\n'\
2534 ' }\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'\
2540 ' }\n'\
2541 ' }\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'\
2548 ' }\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'\
2565 ' else\n'\
2566 ' devtitle.innerHTML = "<t0>"+title+"</t0>";\n'\
2567 ' return name;\n'\
2568 ' }\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'\
2573 ' var cpu = -1;\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'\
2588 ' {\n'\
2589 ' idlist[idlist.length] = dev[i].id;\n'\
2590 ' var tidx = 1;\n'\
2591 ' if(dev[i].id[0] == "a") {\n'\
2592 ' pd = pdata[0];\n'\
2593 ' } else {\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'\
2597 ' tidx = 3;\n'\
2598 ' }\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'\
2605 ' else\n'\
2606 ' total[tidx+1] += pd[pname];\n'\
2607 ' }\n'\
2608 ' }\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'\
2618 ' var fs = 32;\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'\
2624 ' left += w;\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'\
2628 ' } else {\n'\
2629 ' phases[i].style.width = "0%";\n'\
2630 ' phases[i].style.left = left+"%";\n'\
2631 ' }\n'\
2632 ' }\n'\
2633 ' }\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'\
2640 ' } else {\n'\
2641 ' cg[i].style.display = "none";\n'\
2642 ' }\n'\
2643 ' }\n'\
2644 ' }\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'\
2655 ' "</style>"\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'\
2660 ' }\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'\
2675 ' }\n'\
2676 ' zoomTimeline();\n'\
2677 ' });\n'\
2678 '</script>\n'
2679 hf.write(script_code);
2680
2681 # Function: executeSuspend
2682 # Description:
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():
2686 global sysvals
2687
2688 detectUSB(False)
2689 t0 = time.time()*1000
2690 tp = sysvals.tpath
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):
2697 # set trace type
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
2711 time.sleep(0.001)
2712 # start ftrace
2713 if(sysvals.usecallgraph or sysvals.usetraceevents):
2714 print('START TRACING')
2715 os.system('echo 1 > '+tp+'tracing_on')
2716 # initiate suspend
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()
2723 else:
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
2728 pf.close()
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
2736 if(t > 0):
2737 print('Waiting %d seconds for POST-RESUME trace events...' % t)
2738 time.sleep(t)
2739 # stop ftrace
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)
2750
2751 def writeDatafileHeader(filename):
2752 global sysvals
2753
2754 fw = getFPDT(False)
2755 prt = sysvals.postresumetime
2756 fp = open(filename, 'a')
2757 fp.write(sysvals.teststamp+'\n')
2758 if(fw):
2759 fp.write('# fwsuspend %u fwresume %u\n' % (fw[0], fw[1]))
2760 if(prt > 0):
2761 fp.write('# post resume time %u\n' % prt)
2762 fp.close()
2763
2764 # Function: executeAndroidSuspend
2765 # Description:
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():
2770 global sysvals
2771
2772 # check to see if the display is currently off
2773 tp = sysvals.tpath
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
2782 time.sleep(3)
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')
2787 # start ftrace
2788 if(sysvals.usetraceevents):
2789 print('START TRACING')
2790 os.system(sysvals.adb+" shell 'echo 1 > "+tp+"tracing_on'")
2791 # initiate suspend
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
2800 while(True):
2801 check = os.popen(sysvals.adb+\
2802 ' shell pwd 2>/dev/null').read().strip()
2803 if(len(check) > 0):
2804 break
2805 time.sleep(1)
2806 if(sysvals.usetraceevents):
2807 os.system(sysvals.adb+" shell 'echo RESUME COMPLETE > "+tp+\
2808 "trace_marker'")
2809 # return from suspend
2810 print('RESUME COMPLETE')
2811 # stop ftrace
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)
2822
2823 # Function: setUSBDevicesAuto
2824 # Description:
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():
2830 global sysvals
2831
2832 rootCheck()
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))
2843
2844 # Function: yesno
2845 # Description:
2846 # Print out an equivalent Y or N for a set of known parameter values
2847 # Output:
2848 # 'Y', 'N', or ' ' if the value is unknown
2849 def yesno(val):
2850 yesvals = ['auto', 'enabled', 'active', '1']
2851 novals = ['on', 'disabled', 'suspended', 'forbidden', 'unsupported']
2852 if val in yesvals:
2853 return 'Y'
2854 elif val in novals:
2855 return 'N'
2856 return ' '
2857
2858 # Function: ms2nice
2859 # Description:
2860 # Print out a very concise time string in minutes and seconds
2861 # Output:
2862 # The time string, e.g. "1901m16s"
2863 def ms2nice(val):
2864 ms = 0
2865 try:
2866 ms = int(val)
2867 except:
2868 return 0.0
2869 m = ms / 60000
2870 s = (ms / 1000) - (m * 60)
2871 return '%3dm%2ds' % (m, s)
2872
2873 # Function: detectUSB
2874 # Description:
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
2877 # Arguments:
2878 # output: True to output the info to stdout, False otherwise
2879 def detectUSB(output):
2880 global sysvals
2881
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':''}
2890 if(output):
2891 print('LEGEND')
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('---------------------------------------------------------------------------------------------')
2902
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):
2906 for i in field:
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)
2913 else:
2914 sysvals.altdevname[name] = \
2915 '%s:%s [%s]' % (field['idVendor'], \
2916 field['idProduct'], name)
2917 if(output):
2918 for i in power:
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
2923 else:
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'])))
2939
2940 # Function: getModes
2941 # Description:
2942 # Determine the supported power modes on this system
2943 # Output:
2944 # A string list of the available modes
2945 def getModes():
2946 global sysvals
2947 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())
2952 fp.close()
2953 else:
2954 line = os.popen(sysvals.adb+' shell cat '+\
2955 sysvals.powerfile).read().strip()
2956 modes = string.split(line)
2957 return modes
2958
2959 # Function: getFPDT
2960 # Description:
2961 # Read the acpi bios tables and pull out FPDT, the firmware data
2962 # Arguments:
2963 # output: True to output the info to stdout, False otherwise
2964 def getFPDT(output):
2965 global sysvals
2966
2967 rectype = {}
2968 rectype[0] = 'Firmware Basic Boot Performance Record'
2969 rectype[1] = 'S3 Performance Table Record'
2970 prectype = {}
2971 prectype[0] = 'Basic S3 Resume Performance Record'
2972 prectype[1] = 'Basic S3 Suspend Performance Record'
2973
2974 rootCheck()
2975 if(not os.path.exists(sysvals.fpdtpath)):
2976 if(output):
2977 doError('file doesnt exist: %s' % sysvals.fpdtpath, False)
2978 return False
2979 if(not os.access(sysvals.fpdtpath, os.R_OK)):
2980 if(output):
2981 doError('file isnt readable: %s' % sysvals.fpdtpath, False)
2982 return False
2983 if(not os.path.exists(sysvals.mempath)):
2984 if(output):
2985 doError('file doesnt exist: %s' % sysvals.mempath, False)
2986 return False
2987 if(not os.access(sysvals.mempath, os.R_OK)):
2988 if(output):
2989 doError('file isnt readable: %s' % sysvals.mempath, False)
2990 return False
2991
2992 fp = open(sysvals.fpdtpath, 'rb')
2993 buf = fp.read()
2994 fp.close()
2995
2996 if(len(buf) < 36):
2997 if(output):
2998 doError('Invalid FPDT table data, should '+\
2999 'be at least 36 bytes', False)
3000 return False
3001
3002 table = struct.unpack('4sIBB6s8sI4sI', buf[0:36])
3003 if(output):
3004 print('')
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])
3015 print('')
3016
3017 if(table[0] != 'FPDT'):
3018 if(output):
3019 doError('Invalid FPDT table')
3020 return False
3021 if(len(buf) <= 36):
3022 return False
3023 i = 0
3024 fwData = [0, 0]
3025 records = buf[36:]
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):
3030 continue
3031 if(header[1] != 16):
3032 continue
3033 addr = struct.unpack('Q', records[i+8:i+16])[0]
3034 try:
3035 fp.seek(addr)
3036 first = fp.read(8)
3037 except:
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)
3043 if(output):
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'):
3051 if(output):
3052 print('%s (%s)' % (rectype[header[0]], rechead[0]))
3053 j = 0
3054 while(j < len(recdata)):
3055 prechead = struct.unpack('HBB', recdata[j:j+4])
3056 if(prechead[0] not in prectype):
3057 continue
3058 if(prechead[0] == 0):
3059 record = struct.unpack('IIQQ', recdata[j:j+prechead[1]])
3060 fwData[1] = record[2]
3061 if(output):
3062 print(' %s' % prectype[prechead[0]])
3063 print(' Resume Count : %u' % \
3064 record[1])
3065 print(' FullResume : %u ns' % \
3066 record[2])
3067 print(' AverageResume : %u ns' % \
3068 record[3])
3069 elif(prechead[0] == 1):
3070 record = struct.unpack('QQ', recdata[j+4:j+prechead[1]])
3071 fwData[0] = record[1] - record[0]
3072 if(output):
3073 print(' %s' % prectype[prechead[0]])
3074 print(' SuspendStart : %u ns' % \
3075 record[0])
3076 print(' SuspendEnd : %u ns' % \
3077 record[1])
3078 print(' SuspendTime : %u ns' % \
3079 fwData[0])
3080 j += prechead[1]
3081 if(output):
3082 print('')
3083 i += header[1]
3084 fp.close()
3085 return fwData
3086
3087 # Function: statusCheck
3088 # Description:
3089 # Verify that the requested command and options will work, and
3090 # print the results to the terminal
3091 # Output:
3092 # True if the test will work, False if not
3093 def statusCheck():
3094 global sysvals
3095 status = True
3096
3097 if(sysvals.android):
3098 print('Checking the android system ...')
3099 else:
3100 print('Checking this system (%s)...' % platform.node())
3101
3102 # check if adb is connected to a device
3103 if(sysvals.android):
3104 res = 'NO'
3105 out = os.popen(sysvals.adb+' get-state').read().strip()
3106 if(out == 'device'):
3107 res = 'YES'
3108 print(' is android device connected: %s' % res)
3109 if(res != 'YES'):
3110 print(' Please connect the device before using this tool')
3111 return False
3112
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()
3117 if('root' in out):
3118 res = 'YES'
3119 else:
3120 if(os.environ['USER'] == 'root'):
3121 res = 'YES'
3122 print(' have root access: %s' % res)
3123 if(res != 'YES'):
3124 if(sysvals.android):
3125 print(' Try running "adb root" to restart the daemon as root')
3126 else:
3127 print(' Try running this script with sudo')
3128 return False
3129
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):
3136 res = 'YES'
3137 else:
3138 if(os.path.exists(sysvals.powerfile)):
3139 res = 'YES'
3140 print(' is sysfs mounted: %s' % res)
3141 if(res != 'YES'):
3142 return False
3143
3144 # check target mode is a valid mode
3145 res = 'NO'
3146 modes = getModes()
3147 if(sysvals.suspendmode in modes):
3148 res = 'YES'
3149 else:
3150 status = False
3151 print(' is "%s" a valid power mode: %s' % (sysvals.suspendmode, res))
3152 if(res == 'NO'):
3153 print(' valid power modes are: %s' % modes)
3154 print(' please choose one with -m')
3155
3156 # check if the tool can unlock the device
3157 if(sysvals.android):
3158 res = 'YES'
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)
3166
3167 # check if ftrace is available
3168 res = 'NO'
3169 ftgood = verifyFtrace()
3170 if(ftgood):
3171 res = 'YES'
3172 elif(sysvals.usecallgraph):
3173 status = False
3174 print(' is ftrace supported: %s' % res)
3175
3176 # what data source are we using
3177 res = 'DMESG'
3178 if(ftgood):
3179 sysvals.usetraceeventsonly = True
3180 sysvals.usetraceevents = False
3181 for e in sysvals.traceevents:
3182 check = False
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):
3187 check = True
3188 else:
3189 if(os.path.exists(sysvals.epath+e)):
3190 check = True
3191 if(not check):
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)
3200
3201 # check if rtcwake
3202 res = 'NO'
3203 if(sysvals.rtcpath != ''):
3204 res = 'YES'
3205 elif(sysvals.rtcwake):
3206 status = False
3207 print(' is rtcwake supported: %s' % res)
3208
3209 return status
3210
3211 # Function: doError
3212 # Description:
3213 # generic error function for catastrphic failures
3214 # Arguments:
3215 # msg: the error message to print
3216 # help: True if printHelp should be called after, False otherwise
3217 def doError(msg, help):
3218 if(help == True):
3219 printHelp()
3220 print('ERROR: %s\n') % msg
3221 sys.exit()
3222
3223 # Function: doWarning
3224 # Description:
3225 # generic warning function for non-catastrophic anomalies
3226 # Arguments:
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
3231 if(file):
3232 print('/* For a fix, please send this'+\
3233 ' %s file to <todd.e.brandt@intel.com> */' % file)
3234
3235 # Function: rootCheck
3236 # Description:
3237 # quick check to see if we have root access
3238 def rootCheck():
3239 if(os.environ['USER'] != 'root'):
3240 doError('This script must be run as root', False)
3241
3242 # Function: getArgInt
3243 # Description:
3244 # pull out an integer argument from the command line with checks
3245 def getArgInt(name, args, min, max):
3246 try:
3247 arg = args.next()
3248 except:
3249 doError(name+': no argument supplied', True)
3250 try:
3251 val = int(arg)
3252 except:
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)
3256 return val
3257
3258 # Function: rerunTest
3259 # Description:
3260 # generate an output from an existing set of ftrace/dmesg logs
3261 def rerunTest():
3262 global sysvals
3263
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()
3274 else:
3275 testruns = loadKernelLog()
3276 for data in testruns:
3277 parseKernelLog(data)
3278 if(sysvals.ftracefile != ''):
3279 appendIncompleteTraceLog(testruns)
3280 createHTML(testruns)
3281
3282 # Function: runTest
3283 # Description:
3284 # execute a suspend/resume, gather the logs, and generate the output
3285 def runTest(subdir):
3286 global sysvals
3287
3288 # prepare for the test
3289 if(not sysvals.android):
3290 initFtrace()
3291 else:
3292 initFtraceAndroid()
3293 sysvals.initTestOutput(subdir)
3294
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)
3301
3302 # execute the test
3303 if(not sysvals.android):
3304 executeSuspend()
3305 else:
3306 executeAndroidSuspend()
3307
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()
3313 else:
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)
3321
3322 # Function: runSummary
3323 # Description:
3324 # create a summary of tests in a sub-directory
3325 def runSummary(subdir, output):
3326 global sysvals
3327
3328 # get a list of ftrace output files
3329 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))
3334
3335 # process the files in order and get an array of data objects
3336 testruns = []
3337 for file in sorted(files):
3338 if output:
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)
3347 continue
3348 else:
3349 if output:
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()
3354 data = testdata[0]
3355 parseKernelLog(data)
3356 testdata = [data]
3357 appendIncompleteTraceLog(testdata)
3358 else:
3359 if output:
3360 print("\tInput file: %s" % os.path.basename(sysvals.ftracefile))
3361 testdata = parseTraceLog()
3362 data = testdata[0]
3363 data.normalizeTime(data.tSuspended)
3364 link = file.replace(subdir+'/', '').replace('_ftrace.txt', '.html')
3365 data.outfile = link
3366 testruns.append(data)
3367
3368 createHTMLSummarySimple(testruns, subdir+'/summary.html')
3369
3370 # Function: printHelp
3371 # Description:
3372 # print out the help text
3373 def printHelp():
3374 global sysvals
3375 modes = getModes()
3376
3377 print('')
3378 print('AnalyzeSuspend v%.1f' % sysvals.version)
3379 print('Usage: sudo analyze_suspend.py <options>')
3380 print('')
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.')
3389 print('')
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')
3394 print('')
3395 print('Options:')
3396 print(' [general]')
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')
3424 print('')
3425 return True
3426
3427 # ----------------- MAIN --------------------
3428 # exec start (skipped if script is loaded as library)
3429 if __name__ == '__main__':
3430 cmd = ''
3431 cmdarg = ''
3432 multitest = {'run': False, 'count': 0, 'delay': 0}
3433 # loop through the command line arguments
3434 args = iter(sys.argv[1:])
3435 for arg in args:
3436 if(arg == '-m'):
3437 try:
3438 val = args.next()
3439 except:
3440 doError('No mode supplied', True)
3441 sysvals.suspendmode = val
3442 elif(arg == '-adb'):
3443 try:
3444 val = args.next()
3445 except:
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)
3451 try:
3452 check = os.popen(val+' version').read().strip()
3453 except:
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)
3457 sysvals.adb = val
3458 sysvals.android = True
3459 elif(arg == '-x2'):
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)
3469 elif(arg == '-f'):
3470 sysvals.usecallgraph = True
3471 elif(arg == '-modes'):
3472 cmd = 'modes'
3473 elif(arg == '-fpdt'):
3474 cmd = 'fpdt'
3475 elif(arg == '-usbtopo'):
3476 cmd = 'usbtopo'
3477 elif(arg == '-usbauto'):
3478 cmd = 'usbauto'
3479 elif(arg == '-status'):
3480 cmd = 'status'
3481 elif(arg == '-verbose'):
3482 sysvals.verbose = True
3483 elif(arg == '-v'):
3484 print("Version %.1f" % sysvals.version)
3485 sys.exit()
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'):
3494 try:
3495 val = args.next()
3496 except:
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'):
3503 try:
3504 val = args.next()
3505 except:
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'):
3513 try:
3514 val = args.next()
3515 except:
3516 doError('No directory supplied', True)
3517 cmd = 'summary'
3518 cmdarg = val
3519 sysvals.notestrun = True
3520 if(os.path.isdir(val) == False):
3521 doError('%s isnt accesible' % val, False)
3522 elif(arg == '-filter'):
3523 try:
3524 val = args.next()
3525 except:
3526 doError('No devnames supplied', True)
3527 sysvals.setDeviceFilter(val)
3528 elif(arg == '-h'):
3529 printHelp()
3530 sys.exit()
3531 else:
3532 doError('Invalid argument: '+arg, True)
3533
3534 # just run a utility command and exit
3535 if(cmd != ''):
3536 if(cmd == 'status'):
3537 statusCheck()
3538 elif(cmd == 'fpdt'):
3539 if(sysvals.android):
3540 doError('cannot read FPDT on android device', False)
3541 getFPDT(True)
3542 elif(cmd == 'usbtopo'):
3543 if(sysvals.android):
3544 doError('cannot read USB topology '+\
3545 'on an android device', False)
3546 detectUSB(True)
3547 elif(cmd == 'modes'):
3548 modes = getModes()
3549 print modes
3550 elif(cmd == 'usbauto'):
3551 setUSBDevicesAuto()
3552 elif(cmd == 'summary'):
3553 print("Generating a summary of folder \"%s\"" % cmdarg)
3554 runSummary(cmdarg, True)
3555 sys.exit()
3556
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)
3565
3566 # if instructed, re-analyze existing data files
3567 if(sysvals.notestrun):
3568 rerunTest()
3569 sys.exit()
3570
3571 # verify that we can run a test
3572 if(not statusCheck()):
3573 print('Check FAILED, aborting the test run!')
3574 sys.exit()
3575
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')
3580 os.mkdir(subdir)
3581 for i in range(multitest['count']):
3582 if(i != 0):
3583 print('Waiting %d seconds...' % (multitest['delay']))
3584 time.sleep(multitest['delay'])
3585 print('TEST (%d/%d) START' % (i+1, multitest['count']))
3586 runTest(subdir)
3587 print('TEST (%d/%d) COMPLETE' % (i+1, multitest['count']))
3588 runSummary(subdir, False)
3589 else:
3590 # run the test in the current directory
3591 runTest(".")
Linux with added FPC-III support