]>
git.proxmox.com Git - mirror_ubuntu-focal-kernel.git/blob - scripts/analyze_suspend.py
3 # Tool for analyzing suspend/resume timing
4 # Copyright (c) 2013, Intel Corporation.
6 # This program is free software; you can redistribute it and/or modify it
7 # under the terms and conditions of the GNU General Public License,
8 # version 2, as published by the Free Software Foundation.
10 # This program is distributed in the hope it will be useful, but WITHOUT
11 # ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
12 # FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License for
15 # You should have received a copy of the GNU General Public License along with
16 # this program; if not, write to the Free Software Foundation, Inc.,
17 # 51 Franklin St - Fifth Floor, Boston, MA 02110-1301 USA.
20 # Todd Brandt <todd.e.brandt@linux.intel.com>
24 # https://01.org/suspendresume
26 # https://github.com/01org/suspendresume
29 # https://01.org/suspendresume/documentation/getting-started
31 # https://01.org/suspendresume/documentation/command-list
34 # This tool is designed to assist kernel and OS developers in optimizing
35 # their linux stack's suspend/resume time. Using a kernel image built
36 # with a few extra options enabled, the tool will execute a suspend and
37 # will capture dmesg and ftrace data until resume is complete. This data
38 # is transformed into a device timeline and a callgraph to give a quick
39 # and detailed view of which devices and callbacks are taking the most
40 # time in suspend/resume. The output is a single html file which can be
41 # viewed in firefox or chrome.
43 # The following kernel build options are required:
45 # CONFIG_PM_SLEEP_DEBUG=y
47 # CONFIG_FUNCTION_TRACER=y
48 # CONFIG_FUNCTION_GRAPH_TRACER=y
50 # CONFIG_KPROBES_ON_FTRACE=y
52 # For kernel versions older than 3.15:
53 # The following additional kernel parameters are required:
54 # (e.g. in file /etc/default/grub)
55 # GRUB_CMDLINE_LINUX_DEFAULT="... initcall_debug log_buf_len=16M ..."
58 # ----------------- LIBRARIES --------------------
66 from datetime
import datetime
70 # ----------------- CLASSES --------------------
74 # A global, single-instance container used to
75 # store system values and test parameters
87 tpath
= '/sys/kernel/debug/tracing/'
88 fpdtpath
= '/sys/firmware/acpi/tables/FPDT'
89 epath
= '/sys/kernel/debug/tracing/events/power/'
92 'device_pm_callback_end',
93 'device_pm_callback_start'
97 powerfile
= '/sys/power/state'
99 hostname
= 'localhost'
115 usetraceevents
= False
116 usetraceeventsonly
= False
117 usetracemarkers
= True
123 devpropfmt
= '# Device Properties: .*'
124 tracertypefmt
= '# tracer: (?P<t>.*)'
125 firmwarefmt
= '# fwsuspend (?P<s>[0-9]*) fwresume (?P<r>[0-9]*)$'
126 postresumefmt
= '# post resume time (?P<t>[0-9]*)$'
127 stampfmt
= '# suspend-(?P<m>[0-9]{2})(?P<d>[0-9]{2})(?P<y>[0-9]{2})-'+\
128 '(?P<H>[0-9]{2})(?P<M>[0-9]{2})(?P<S>[0-9]{2})'+\
129 ' (?P<host>.*) (?P<mode>.*) (?P<kernel>.*)$'
130 kprobecolor
= 'rgba(204,204,204,0.5)'
131 synccolor
= 'rgba(204,204,204,0.5)'
135 'pm_prepare_console': dict(),
136 'pm_notifier_call_chain': dict(),
137 'freeze_processes': dict(),
138 'freeze_kernel_threads': dict(),
139 'pm_restrict_gfp_mask': dict(),
140 'acpi_suspend_begin': dict(),
141 'suspend_console': dict(),
142 'acpi_pm_prepare': dict(),
143 'syscore_suspend': dict(),
144 'arch_enable_nonboot_cpus_end': dict(),
145 'syscore_resume': dict(),
146 'acpi_pm_finish': dict(),
147 'resume_console': dict(),
148 'acpi_pm_end': dict(),
149 'pm_restore_gfp_mask': dict(),
150 'thaw_processes': dict(),
151 'pm_restore_console': dict(),
154 'args_x86_64': {'cpu':'%di:s32'},
155 'format': 'CPU_OFF[{cpu}]',
156 'mask': 'CPU_.*_DOWN'
160 'args_x86_64': {'cpu':'%di:s32'},
161 'format': 'CPU_ON[{cpu}]',
166 # general wait/delay/sleep
167 'msleep': { 'args_x86_64': {'time':'%di:s32'} },
168 'udelay': { 'func':'__const_udelay', 'args_x86_64': {'loops':'%di:s32'} },
169 'acpi_os_stall': dict(),
171 'acpi_resume_power_resources': dict(),
172 'acpi_ps_parse_aml': dict(),
174 'ext4_sync_fs': dict(),
176 'ata_eh_recover': { 'args_x86_64': {'port':'+36(%di):s32'} },
178 'i915_gem_restore_gtt_mappings': dict(),
179 'intel_opregion_setup': dict(),
180 'intel_dp_detect': dict(),
181 'intel_hdmi_detect': dict(),
182 'intel_opregion_init': dict(),
184 kprobes_postresume
= [
186 'name': 'ataportrst',
187 'func': 'ata_eh_recover',
188 'args': {'port':'+36(%di):s32'},
189 'format': 'ata{port}_port_reset',
190 'mask': 'ata.*_port_reset'
196 # if this is a phoronix test run, set some default options
197 if('LOG_FILE' in os
.environ
and 'TEST_RESULTS_IDENTIFIER' in os
.environ
):
200 self
.htmlfile
= os
.environ
['LOG_FILE']
201 self
.hostname
= platform
.node()
202 if(self
.hostname
== ''):
203 self
.hostname
= 'localhost'
205 if os
.path
.exists('/dev/rtc'):
206 rtc
= os
.readlink('/dev/rtc')
207 rtc
= '/sys/class/rtc/'+rtc
208 if os
.path
.exists(rtc
) and os
.path
.exists(rtc
+'/date') and \
209 os
.path
.exists(rtc
+'/time') and os
.path
.exists(rtc
+'/wakealarm'):
211 if (hasattr(sys
.stdout
, 'isatty') and sys
.stdout
.isatty()):
213 def setPrecision(self
, num
):
214 if num
< 0 or num
> 6:
216 self
.timeformat
= '%.{0}f'.format(num
)
217 def setOutputFile(self
):
218 if((self
.htmlfile
== '') and (self
.dmesgfile
!= '')):
219 m
= re
.match('(?P<name>.*)_dmesg\.txt$', self
.dmesgfile
)
221 self
.htmlfile
= m
.group('name')+'.html'
222 if((self
.htmlfile
== '') and (self
.ftracefile
!= '')):
223 m
= re
.match('(?P<name>.*)_ftrace\.txt$', self
.ftracefile
)
225 self
.htmlfile
= m
.group('name')+'.html'
226 if(self
.htmlfile
== ''):
227 self
.htmlfile
= 'output.html'
228 def initTestOutput(self
, subdir
, testpath
=''):
229 self
.prefix
= self
.hostname
230 v
= open('/proc/version', 'r').read().strip()
231 kver
= string
.split(v
)[2]
233 testtime
= n
.strftime('suspend-%m%d%y-%H%M%S')
235 testpath
= n
.strftime('suspend-%y%m%d-%H%M%S')
237 self
.testdir
= subdir
+"/"+testpath
239 self
.testdir
= testpath
241 '# '+testtime
+' '+self
.prefix
+' '+self
.suspendmode
+' '+kver
244 '/tmp/'+testtime
+'_'+self
.suspendmode
+'_dmesg.txt'
246 '/tmp/'+testtime
+'_'+self
.suspendmode
+'_ftrace.txt'
249 self
.testdir
+'/'+self
.prefix
+'_'+self
.suspendmode
+'_dmesg.txt'
251 self
.testdir
+'/'+self
.prefix
+'_'+self
.suspendmode
+'_ftrace.txt'
253 self
.testdir
+'/'+self
.prefix
+'_'+self
.suspendmode
+'.html'
254 if not os
.path
.isdir(self
.testdir
):
255 os
.mkdir(self
.testdir
)
256 def setDeviceFilter(self
, devnames
):
257 self
.devicefilter
= string
.split(devnames
)
258 def rtcWakeAlarmOn(self
):
259 os
.system('echo 0 > '+self
.rtcpath
+'/wakealarm')
260 outD
= open(self
.rtcpath
+'/date', 'r').read().strip()
261 outT
= open(self
.rtcpath
+'/time', 'r').read().strip()
262 mD
= re
.match('^(?P<y>[0-9]*)-(?P<m>[0-9]*)-(?P<d>[0-9]*)', outD
)
263 mT
= re
.match('^(?P<h>[0-9]*):(?P<m>[0-9]*):(?P<s>[0-9]*)', outT
)
265 # get the current time from hardware
266 utcoffset
= int((datetime
.now() - datetime
.utcnow()).total_seconds())
268 int(mD
.group('y')), int(mD
.group('m')), int(mD
.group('d')),
269 int(mT
.group('h')), int(mT
.group('m')), int(mT
.group('s')))
270 nowtime
= int(dt
.strftime('%s')) + utcoffset
272 # if hardware time fails, use the software time
273 nowtime
= int(datetime
.now().strftime('%s'))
274 alarm
= nowtime
+ self
.rtcwaketime
275 os
.system('echo %d > %s/wakealarm' % (alarm
, self
.rtcpath
))
276 def rtcWakeAlarmOff(self
):
277 os
.system('echo 0 > %s/wakealarm' % self
.rtcpath
)
279 # get the latest time stamp from the dmesg log
280 fp
= os
.popen('dmesg')
283 line
= line
.replace('\r\n', '')
287 m
= re
.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line
)
289 ktime
= m
.group('ktime')
291 self
.dmesgstart
= float(ktime
)
293 # store all new dmesg lines since initdmesg was called
294 fp
= os
.popen('dmesg')
295 op
= open(self
.dmesgfile
, 'a')
297 line
= line
.replace('\r\n', '')
301 m
= re
.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line
)
304 ktime
= float(m
.group('ktime'))
305 if ktime
> self
.dmesgstart
:
309 def addFtraceFilterFunctions(self
, file):
311 list = fp
.read().split('\n')
316 self
.tracefuncs
[i
] = dict()
317 def getFtraceFilterFunctions(self
, current
):
320 os
.system('cat '+self
.tpath
+'available_filter_functions')
322 fp
= open(self
.tpath
+'available_filter_functions')
323 master
= fp
.read().split('\n')
325 if len(self
.debugfuncs
) > 0:
326 for i
in self
.debugfuncs
:
330 print self
.colorText(i
)
332 for i
in self
.tracefuncs
:
333 if 'func' in self
.tracefuncs
[i
]:
334 i
= self
.tracefuncs
[i
]['func']
338 print self
.colorText(i
)
339 def setFtraceFilterFunctions(self
, list):
340 fp
= open(self
.tpath
+'available_filter_functions')
341 master
= fp
.read().split('\n')
348 flist
+= i
.split(' ')[0]+'\n'
351 fp
= open(self
.tpath
+'set_graph_function', 'w')
354 def kprobeMatch(self
, name
, target
):
355 if name
not in self
.kprobes
:
357 if re
.match(self
.kprobes
[name
]['mask'], target
):
360 def basicKprobe(self
, name
):
361 self
.kprobes
[name
] = {'name': name
,'func': name
,'args': dict(),'format': name
,'mask': name
}
362 def defaultKprobe(self
, name
, kdata
):
364 for field
in ['name', 'format', 'mask', 'func']:
367 archargs
= 'args_'+platform
.machine()
369 k
['args'] = k
[archargs
]
373 self
.kprobes
[name
] = k
374 def kprobeColor(self
, name
):
375 if name
not in self
.kprobes
or 'color' not in self
.kprobes
[name
]:
377 return self
.kprobes
[name
]['color']
378 def kprobeDisplayName(self
, name
, dataraw
):
379 if name
not in self
.kprobes
:
380 self
.basicKprobe(name
)
383 # first remvoe any spaces inside quotes, and the quotes
386 quote
= (quote
+ 1) % 2
387 if quote
and c
== ' ':
391 fmt
, args
= self
.kprobes
[name
]['format'], self
.kprobes
[name
]['args']
393 # now process the args
394 for arg
in sorted(args
):
396 m
= re
.match('.* '+arg
+'=(?P<arg>.*) ', data
);
398 arglist
[arg
] = m
.group('arg')
400 m
= re
.match('.* '+arg
+'=(?P<arg>.*)', data
);
402 arglist
[arg
] = m
.group('arg')
403 out
= fmt
.format(**arglist
)
404 out
= out
.replace(' ', '_').replace('"', '')
406 def kprobeText(self
, kprobe
):
407 name
, fmt
, func
, args
= kprobe
['name'], kprobe
['format'], kprobe
['func'], kprobe
['args']
408 if re
.findall('{(?P<n>[a-z,A-Z,0-9]*)}', func
):
409 doError('Kprobe "%s" has format info in the function name "%s"' % (name
, func
), False)
410 for arg
in re
.findall('{(?P<n>[a-z,A-Z,0-9]*)}', fmt
):
412 doError('Kprobe "%s" is missing argument "%s"' % (name
, arg
), False)
413 val
= 'p:%s_cal %s' % (name
, func
)
414 for i
in sorted(args
):
415 val
+= ' %s=%s' % (i
, args
[i
])
416 val
+= '\nr:%s_ret %s $retval\n' % (name
, func
)
418 def addKprobes(self
):
419 # first test each kprobe
420 print('INITIALIZING KPROBES...')
422 for name
in sorted(self
.kprobes
):
423 if not self
.testKprobe(self
.kprobes
[name
]):
425 # remove all failed ones from the list
427 vprint('Skipping KPROBE: %s' % name
)
428 self
.kprobes
.pop(name
)
429 self
.fsetVal('', 'kprobe_events')
431 # set the kprobes all at once
432 for kp
in self
.kprobes
:
433 val
= self
.kprobeText(self
.kprobes
[kp
])
434 vprint('Adding KPROBE: %s\n%s' % (kp
, val
.strip()))
435 kprobeevents
+= self
.kprobeText(self
.kprobes
[kp
])
436 self
.fsetVal(kprobeevents
, 'kprobe_events')
437 # verify that the kprobes were set as ordered
438 check
= self
.fgetVal('kprobe_events')
439 linesout
= len(kprobeevents
.split('\n'))
440 linesack
= len(check
.split('\n'))
441 if linesack
< linesout
:
442 # if not, try appending the kprobes 1 by 1
443 for kp
in self
.kprobes
:
444 kprobeevents
= self
.kprobeText(self
.kprobes
[kp
])
445 self
.fsetVal(kprobeevents
, 'kprobe_events', 'a')
446 self
.fsetVal('1', 'events/kprobes/enable')
447 def testKprobe(self
, kprobe
):
448 kprobeevents
= self
.kprobeText(kprobe
)
452 self
.fsetVal(kprobeevents
, 'kprobe_events')
453 check
= self
.fgetVal('kprobe_events')
456 linesout
= len(kprobeevents
.split('\n'))
457 linesack
= len(check
.split('\n'))
458 if linesack
< linesout
:
461 def fsetVal(self
, val
, path
, mode
='w'):
462 file = self
.tpath
+path
463 if not os
.path
.exists(file):
466 fp
= open(file, mode
)
472 def fgetVal(self
, path
):
473 file = self
.tpath
+path
475 if not os
.path
.exists(file):
484 def cleanupFtrace(self
):
485 if(self
.usecallgraph
or self
.usetraceevents
):
486 self
.fsetVal('0', 'events/kprobes/enable')
487 self
.fsetVal('', 'kprobe_events')
488 def setupAllKprobes(self
):
489 for name
in self
.tracefuncs
:
490 self
.defaultKprobe(name
, self
.tracefuncs
[name
])
491 for name
in self
.dev_tracefuncs
:
492 self
.defaultKprobe(name
, self
.dev_tracefuncs
[name
])
493 def isCallgraphFunc(self
, name
):
494 if len(self
.debugfuncs
) < 1 and self
.suspendmode
== 'command':
496 if name
in self
.debugfuncs
:
499 for i
in self
.tracefuncs
:
500 if 'func' in self
.tracefuncs
[i
]:
501 funclist
.append(self
.tracefuncs
[i
]['func'])
507 def initFtrace(self
, testing
=False):
509 print('INITIALIZING FTRACE...')
511 self
.fsetVal('0', 'tracing_on')
513 # set the trace clock to global
514 self
.fsetVal('global', 'trace_clock')
515 # set trace buffer to a huge value
516 self
.fsetVal('nop', 'current_tracer')
517 self
.fsetVal('100000', 'buffer_size_kb')
518 # go no further if this is just a status check
522 # add tracefunc kprobes so long as were not using full callgraph
523 if(not self
.usecallgraph
or len(self
.debugfuncs
) > 0):
524 for name
in self
.tracefuncs
:
525 self
.defaultKprobe(name
, self
.tracefuncs
[name
])
527 for name
in self
.dev_tracefuncs
:
528 self
.defaultKprobe(name
, self
.dev_tracefuncs
[name
])
530 self
.usedevsrc
= False
532 # initialize the callgraph trace, unless this is an x2 run
533 if(self
.usecallgraph
):
535 self
.fsetVal('function_graph', 'current_tracer')
536 self
.fsetVal('', 'set_ftrace_filter')
537 # set trace format options
538 self
.fsetVal('print-parent', 'trace_options')
539 self
.fsetVal('funcgraph-abstime', 'trace_options')
540 self
.fsetVal('funcgraph-cpu', 'trace_options')
541 self
.fsetVal('funcgraph-duration', 'trace_options')
542 self
.fsetVal('funcgraph-proc', 'trace_options')
543 self
.fsetVal('funcgraph-tail', 'trace_options')
544 self
.fsetVal('nofuncgraph-overhead', 'trace_options')
545 self
.fsetVal('context-info', 'trace_options')
546 self
.fsetVal('graph-time', 'trace_options')
547 self
.fsetVal('0', 'max_graph_depth')
548 if len(self
.debugfuncs
) > 0:
549 self
.setFtraceFilterFunctions(self
.debugfuncs
)
550 elif self
.suspendmode
== 'command':
551 self
.fsetVal('', 'set_graph_function')
553 cf
= ['dpm_run_callback']
554 if(self
.usetraceeventsonly
):
555 cf
+= ['dpm_prepare', 'dpm_complete']
556 for fn
in self
.tracefuncs
:
557 if 'func' in self
.tracefuncs
[fn
]:
558 cf
.append(self
.tracefuncs
[fn
]['func'])
561 self
.setFtraceFilterFunctions(cf
)
562 if(self
.usetraceevents
):
563 # turn trace events on
564 events
= iter(self
.traceevents
)
566 self
.fsetVal('1', 'events/power/'+e
+'/enable')
567 # clear the trace buffer
568 self
.fsetVal('', 'trace')
569 def verifyFtrace(self
):
570 # files needed for any trace data
571 files
= ['buffer_size_kb', 'current_tracer', 'trace', 'trace_clock',
572 'trace_marker', 'trace_options', 'tracing_on']
573 # files needed for callgraph trace data
575 if(self
.usecallgraph
):
577 'available_filter_functions',
582 if(os
.path
.exists(tp
+f
) == False):
585 def verifyKprobes(self
):
586 # files needed for kprobes to work
587 files
= ['kprobe_events', 'events']
590 if(os
.path
.exists(tp
+f
) == False):
593 def colorText(self
, str):
596 return '\x1B[31;40m'+str+'\x1B[m'
598 sysvals
= SystemValues()
602 # Simple class which holds property values collected
603 # for all the devices used in the timeline.
611 return '%s,%s,%d;' % (dev
, self
.altname
, self
.async)
612 def debug(self
, dev
):
613 print '%s:\n\taltname = %s\n\t async = %s' % (dev
, self
.altname
, self
.async)
614 def altName(self
, dev
):
615 if not self
.altname
or self
.altname
== dev
:
617 return '%s [%s]' % (self
.altname
, dev
)
620 return ' '+self
.xtraclass
626 return ' '+self
.xtraclass
633 # A container used to create a device hierachy, with a single root node
634 # and a tree of child nodes. Used by Data.deviceTopology()
639 def __init__(self
, nodename
, nodedepth
):
642 self
.depth
= nodedepth
646 # The primary container for suspend/resume test data. There is one for
647 # each test run. The data is organized into a cronological hierarchy:
649 # root structure, started as dmesg & ftrace, but now only ftrace
650 # contents: times for suspend start/end, resume start/end, fwdata
652 # 10 sequential, non-overlapping phases of S/R
653 # contents: times for phase start/end, order/color data for html
655 # device callback or action list for this phase
657 # a single device callback or generic action
658 # contents: start/stop times, pid/cpu/driver info
659 # parents/children, html id for timeline/callgraph
660 # optionally includes an ftrace callgraph
661 # optionally includes intradev trace events
668 dmesg
= {} # root data structure
669 phases
= [] # ordered list of phases
670 start
= 0.0 # test start
672 tSuspended
= 0.0 # low-level suspend start
673 tResumed
= 0.0 # low-level resume start
674 tLow
= 0.0 # time spent in low-level suspend (standby/freeze)
675 fwValid
= False # is firmware data available
676 fwSuspend
= 0 # time spent in firmware suspend
677 fwResume
= 0 # time spent in firmware resume
678 dmesgtext
= [] # dmesg text file in memory
684 dev_ubiquitous
= ['msleep', 'udelay']
685 def __init__(self
, num
):
686 idchar
= 'abcdefghijklmnopqrstuvwxyz'
687 self
.testnumber
= num
688 self
.idstr
= idchar
[num
]
691 self
.dmesg
= { # fixed list of 10 phases
692 'suspend_prepare': {'list': dict(), 'start': -1.0, 'end': -1.0,
693 'row': 0, 'color': '#CCFFCC', 'order': 0},
694 'suspend': {'list': dict(), 'start': -1.0, 'end': -1.0,
695 'row': 0, 'color': '#88FF88', 'order': 1},
696 'suspend_late': {'list': dict(), 'start': -1.0, 'end': -1.0,
697 'row': 0, 'color': '#00AA00', 'order': 2},
698 'suspend_noirq': {'list': dict(), 'start': -1.0, 'end': -1.0,
699 'row': 0, 'color': '#008888', 'order': 3},
700 'suspend_machine': {'list': dict(), 'start': -1.0, 'end': -1.0,
701 'row': 0, 'color': '#0000FF', 'order': 4},
702 'resume_machine': {'list': dict(), 'start': -1.0, 'end': -1.0,
703 'row': 0, 'color': '#FF0000', 'order': 5},
704 'resume_noirq': {'list': dict(), 'start': -1.0, 'end': -1.0,
705 'row': 0, 'color': '#FF9900', 'order': 6},
706 'resume_early': {'list': dict(), 'start': -1.0, 'end': -1.0,
707 'row': 0, 'color': '#FFCC00', 'order': 7},
708 'resume': {'list': dict(), 'start': -1.0, 'end': -1.0,
709 'row': 0, 'color': '#FFFF88', 'order': 8},
710 'resume_complete': {'list': dict(), 'start': -1.0, 'end': -1.0,
711 'row': 0, 'color': '#FFFFCC', 'order': 9}
713 self
.phases
= self
.sortedPhases()
714 self
.devicegroups
= []
715 for phase
in self
.phases
:
716 self
.devicegroups
.append([phase
])
718 return self
.dmesg
[self
.phases
[0]]['start']
719 def setStart(self
, time
):
721 self
.dmesg
[self
.phases
[0]]['start'] = time
723 return self
.dmesg
[self
.phases
[-1]]['end']
724 def setEnd(self
, time
):
726 self
.dmesg
[self
.phases
[-1]]['end'] = time
727 def isTraceEventOutsideDeviceCalls(self
, pid
, time
):
728 for phase
in self
.phases
:
729 list = self
.dmesg
[phase
]['list']
732 if(d
['pid'] == pid
and time
>= d
['start'] and
736 def targetDevice(self
, phaselist
, start
, end
, pid
=-1):
738 for phase
in phaselist
:
739 list = self
.dmesg
[phase
]['list']
742 if(pid
>= 0 and dev
['pid'] != pid
):
746 if(start
< devS
or start
>= devE
or end
<= devS
or end
> devE
):
751 def addDeviceFunctionCall(self
, displayname
, kprobename
, proc
, pid
, start
, end
, cdata
, rdata
):
752 machstart
= self
.dmesg
['suspend_machine']['start']
753 machend
= self
.dmesg
['resume_machine']['end']
754 tgtdev
= self
.targetDevice(self
.phases
, start
, end
, pid
)
755 if not tgtdev
and start
>= machstart
and end
< machend
:
756 # device calls in machine phases should be serial
757 tgtdev
= self
.targetDevice(['suspend_machine', 'resume_machine'], start
, end
)
759 if 'scsi_eh' in proc
:
760 self
.newActionGlobal(proc
, start
, end
, pid
)
761 self
.addDeviceFunctionCall(displayname
, kprobename
, proc
, pid
, start
, end
, cdata
, rdata
)
763 vprint('IGNORE: %s[%s](%d) [%f - %f] | %s | %s | %s' % (displayname
, kprobename
,
764 pid
, start
, end
, cdata
, rdata
, proc
))
766 # detail block fits within tgtdev
767 if('src' not in tgtdev
):
769 title
= cdata
+' '+rdata
770 mstr
= '\(.*\) *(?P<args>.*) *\((?P<caller>.*)\+.* arg1=(?P<ret>.*)'
771 m
= re
.match(mstr
, title
)
773 c
= m
.group('caller')
774 a
= m
.group('args').strip()
780 l
= '%0.3fms' % ((end
- start
) * 1000)
781 if kprobename
in self
.dev_ubiquitous
:
782 title
= '%s(%s) <- %s, %s(%s)' % (displayname
, a
, c
, r
, l
)
784 title
= '%s(%s) %s(%s)' % (displayname
, a
, r
, l
)
785 e
= TraceEvent(title
, kprobename
, start
, end
- start
)
786 tgtdev
['src'].append(e
)
788 def trimTimeVal(self
, t
, t0
, dT
, left
):
803 def trimTime(self
, t0
, dT
, left
):
804 self
.tSuspended
= self
.trimTimeVal(self
.tSuspended
, t0
, dT
, left
)
805 self
.tResumed
= self
.trimTimeVal(self
.tResumed
, t0
, dT
, left
)
806 self
.start
= self
.trimTimeVal(self
.start
, t0
, dT
, left
)
807 self
.end
= self
.trimTimeVal(self
.end
, t0
, dT
, left
)
808 for phase
in self
.phases
:
809 p
= self
.dmesg
[phase
]
810 p
['start'] = self
.trimTimeVal(p
['start'], t0
, dT
, left
)
811 p
['end'] = self
.trimTimeVal(p
['end'], t0
, dT
, left
)
815 d
['start'] = self
.trimTimeVal(d
['start'], t0
, dT
, left
)
816 d
['end'] = self
.trimTimeVal(d
['end'], t0
, dT
, left
)
819 cg
.start
= self
.trimTimeVal(cg
.start
, t0
, dT
, left
)
820 cg
.end
= self
.trimTimeVal(cg
.end
, t0
, dT
, left
)
822 line
.time
= self
.trimTimeVal(line
.time
, t0
, dT
, left
)
825 e
.time
= self
.trimTimeVal(e
.time
, t0
, dT
, left
)
826 def normalizeTime(self
, tZero
):
827 # trim out any standby or freeze clock time
828 if(self
.tSuspended
!= self
.tResumed
):
829 if(self
.tResumed
> tZero
):
830 self
.trimTime(self
.tSuspended
, \
831 self
.tResumed
-self
.tSuspended
, True)
833 self
.trimTime(self
.tSuspended
, \
834 self
.tResumed
-self
.tSuspended
, False)
835 def newPhaseWithSingleAction(self
, phasename
, devname
, start
, end
, color
):
836 for phase
in self
.phases
:
837 self
.dmesg
[phase
]['order'] += 1
838 self
.html_device_id
+= 1
839 devid
= '%s%d' % (self
.idstr
, self
.html_device_id
)
842 {'start': start
, 'end': end
, 'pid': 0, 'par': '',
843 'length': (end
-start
), 'row': 0, 'id': devid
, 'drv': '' };
844 self
.dmesg
[phasename
] = \
845 {'list': list, 'start': start
, 'end': end
,
846 'row': 0, 'color': color
, 'order': 0}
847 self
.phases
= self
.sortedPhases()
848 def newPhase(self
, phasename
, start
, end
, color
, order
):
850 order
= len(self
.phases
)
851 for phase
in self
.phases
[order
:]:
852 self
.dmesg
[phase
]['order'] += 1
854 p
= self
.phases
[order
-1]
855 self
.dmesg
[p
]['end'] = start
856 if(order
< len(self
.phases
)):
857 p
= self
.phases
[order
]
858 self
.dmesg
[p
]['start'] = end
860 self
.dmesg
[phasename
] = \
861 {'list': list, 'start': start
, 'end': end
,
862 'row': 0, 'color': color
, 'order': order
}
863 self
.phases
= self
.sortedPhases()
864 self
.devicegroups
.append([phasename
])
865 def setPhase(self
, phase
, ktime
, isbegin
):
867 self
.dmesg
[phase
]['start'] = ktime
869 self
.dmesg
[phase
]['end'] = ktime
870 def dmesgSortVal(self
, phase
):
871 return self
.dmesg
[phase
]['order']
872 def sortedPhases(self
):
873 return sorted(self
.dmesg
, key
=self
.dmesgSortVal
)
874 def sortedDevices(self
, phase
):
875 list = self
.dmesg
[phase
]['list']
880 tmp
[dev
['start']] = devname
881 for t
in sorted(tmp
):
884 def fixupInitcalls(self
, phase
, end
):
885 # if any calls never returned, clip them at system resume end
886 phaselist
= self
.dmesg
[phase
]['list']
887 for devname
in phaselist
:
888 dev
= phaselist
[devname
]
890 for p
in self
.phases
:
891 if self
.dmesg
[p
]['end'] > dev
['start']:
892 dev
['end'] = self
.dmesg
[p
]['end']
894 vprint('%s (%s): callback didnt return' % (devname
, phase
))
895 def deviceFilter(self
, devicefilter
):
896 # remove all by the relatives of the filter devnames
898 for phase
in self
.phases
:
899 list = self
.dmesg
[phase
]['list']
900 for name
in devicefilter
:
903 if(dev
not in filter):
905 dev
= list[dev
]['par']
906 children
= self
.deviceDescendants(name
, phase
)
908 if(dev
not in filter):
910 for phase
in self
.phases
:
911 list = self
.dmesg
[phase
]['list']
914 pid
= list[name
]['pid']
915 if(name
not in filter and pid
>= 0):
919 def fixupInitcallsThatDidntReturn(self
):
920 # if any calls never returned, clip them at system resume end
921 for phase
in self
.phases
:
922 self
.fixupInitcalls(phase
, self
.getEnd())
923 def isInsideTimeline(self
, start
, end
):
924 if(self
.start
<= start
and self
.end
> start
):
927 def phaseOverlap(self
, phases
):
930 for group
in self
.devicegroups
:
932 if phase
not in group
:
935 if p
not in newgroup
:
937 if group
not in rmgroups
:
938 rmgroups
.append(group
)
939 for group
in rmgroups
:
940 self
.devicegroups
.remove(group
)
941 self
.devicegroups
.append(newgroup
)
942 def newActionGlobal(self
, name
, start
, end
, pid
=-1, color
=''):
943 # if event starts before timeline start, expand timeline
944 if(start
< self
.start
):
946 # if event ends after timeline end, expand the timeline
949 # which phase is this device callback or action "in"
954 for phase
in self
.phases
:
955 pstart
= self
.dmesg
[phase
]['start']
956 pend
= self
.dmesg
[phase
]['end']
957 o
= max(0, min(end
, pend
) - max(start
, pstart
))
961 if overlap
> 0 and phase
== 'post_resume':
969 self
.phaseOverlap(phases
)
970 if targetphase
in self
.phases
:
971 newname
= self
.newAction(targetphase
, name
, pid
, '', start
, end
, '', htmlclass
, color
)
972 return (targetphase
, newname
)
974 def newAction(self
, phase
, name
, pid
, parent
, start
, end
, drv
, htmlclass
='', color
=''):
975 # new device callback for a specific phase
976 self
.html_device_id
+= 1
977 devid
= '%s%d' % (self
.idstr
, self
.html_device_id
)
978 list = self
.dmesg
[phase
]['list']
980 if(start
>= 0 and end
>= 0):
986 name
= '%s[%d]' % (origname
, i
)
988 list[name
] = {'start': start
, 'end': end
, 'pid': pid
, 'par': parent
,
989 'length': length
, 'row': 0, 'id': devid
, 'drv': drv
}
991 list[name
]['htmlclass'] = htmlclass
993 list[name
]['color'] = color
995 def deviceIDs(self
, devlist
, phase
):
997 list = self
.dmesg
[phase
]['list']
999 if devname
in devlist
:
1000 idlist
.append(list[devname
]['id'])
1002 def deviceParentID(self
, devname
, phase
):
1005 list = self
.dmesg
[phase
]['list']
1007 pdev
= list[devname
]['par']
1009 return list[pdev
]['id']
1011 def deviceChildren(self
, devname
, phase
):
1013 list = self
.dmesg
[phase
]['list']
1015 if(list[child
]['par'] == devname
):
1016 devlist
.append(child
)
1018 def deviceDescendants(self
, devname
, phase
):
1019 children
= self
.deviceChildren(devname
, phase
)
1021 for child
in children
:
1022 family
+= self
.deviceDescendants(child
, phase
)
1024 def deviceChildrenIDs(self
, devname
, phase
):
1025 devlist
= self
.deviceChildren(devname
, phase
)
1026 return self
.deviceIDs(devlist
, phase
)
1027 def printDetails(self
):
1028 vprint(' test start: %f' % self
.start
)
1029 for phase
in self
.phases
:
1030 dc
= len(self
.dmesg
[phase
]['list'])
1031 vprint(' %16s: %f - %f (%d devices)' % (phase
, \
1032 self
.dmesg
[phase
]['start'], self
.dmesg
[phase
]['end'], dc
))
1033 vprint(' test end: %f' % self
.end
)
1034 def deviceChildrenAllPhases(self
, devname
):
1036 for phase
in self
.phases
:
1037 list = self
.deviceChildren(devname
, phase
)
1039 if dev
not in devlist
:
1042 def masterTopology(self
, name
, list, depth
):
1043 node
= DeviceNode(name
, depth
)
1048 clist
= self
.deviceChildrenAllPhases(cname
)
1049 cnode
= self
.masterTopology(cname
, clist
, depth
+1)
1050 node
.children
.append(cnode
)
1052 def printTopology(self
, node
):
1057 for phase
in self
.phases
:
1058 list = self
.dmesg
[phase
]['list']
1059 if node
.name
in list:
1060 s
= list[node
.name
]['start']
1061 e
= list[node
.name
]['end']
1062 if list[node
.name
]['drv']:
1063 drv
= ' {'+list[node
.name
]['drv']+'}'
1064 info
+= ('<li>%s: %.3fms</li>' % (phase
, (e
-s
)*1000))
1065 html
+= '<li><b>'+node
.name
+drv
+'</b>'
1067 html
+= '<ul>'+info
+'</ul>'
1069 if len(node
.children
) > 0:
1071 for cnode
in node
.children
:
1072 html
+= self
.printTopology(cnode
)
1075 def rootDeviceList(self
):
1076 # list of devices graphed
1078 for phase
in self
.dmesg
:
1079 list = self
.dmesg
[phase
]['list']
1081 if list[dev
]['pid'] >= 0 and dev
not in real
:
1083 # list of top-most root devices
1085 for phase
in self
.dmesg
:
1086 list = self
.dmesg
[phase
]['list']
1088 pdev
= list[dev
]['par']
1089 pid
= list[dev
]['pid']
1090 if(pid
< 0 or re
.match('[0-9]*-[0-9]*\.[0-9]*[\.0-9]*\:[\.0-9]*$', pdev
)):
1092 if pdev
and pdev
not in real
and pdev
not in rootlist
:
1093 rootlist
.append(pdev
)
1095 def deviceTopology(self
):
1096 rootlist
= self
.rootDeviceList()
1097 master
= self
.masterTopology('', rootlist
, 0)
1098 return self
.printTopology(master
)
1099 def selectTimelineDevices(self
, widfmt
, tTotal
, mindevlen
):
1100 # only select devices that will actually show up in html
1101 self
.tdevlist
= dict()
1102 for phase
in self
.dmesg
:
1104 list = self
.dmesg
[phase
]['list']
1106 length
= (list[dev
]['end'] - list[dev
]['start']) * 1000
1107 width
= widfmt
% (((list[dev
]['end']-list[dev
]['start'])*100)/tTotal
)
1108 if width
!= '0.000000' and length
>= mindevlen
:
1110 self
.tdevlist
[phase
] = devlist
1114 # A container for trace event data found in the ftrace file
1121 def __init__(self
, a
, n
, t
, l
):
1129 # A container for a single line of ftrace data. There are six basic types:
1131 # call: " dpm_run_callback() {"
1133 # leaf: " dpm_run_callback();"
1135 # tracing_mark_write: SUSPEND START or RESUME COMPLETE
1136 # suspend_resume: phase or custom exec block data
1137 # device_pm_callback: device callback info
1148 def __init__(self
, t
, m
='', d
=''):
1149 self
.time
= float(t
)
1152 # is this a trace event
1153 if(d
== 'traceevent' or re
.match('^ *\/\* *(?P<msg>.*) \*\/ *$', m
)):
1154 if(d
== 'traceevent'):
1155 # nop format trace event
1158 # function_graph format trace event
1159 em
= re
.match('^ *\/\* *(?P<msg>.*) \*\/ *$', m
)
1160 msg
= em
.group('msg')
1162 emm
= re
.match('^(?P<call>.*?): (?P<msg>.*)', msg
)
1164 self
.name
= emm
.group('msg')
1165 self
.type = emm
.group('call')
1168 km
= re
.match('^(?P<n>.*)_cal$', self
.type)
1172 self
.type = km
.group('n')
1174 km
= re
.match('^(?P<n>.*)_ret$', self
.type)
1178 self
.type = km
.group('n')
1182 # convert the duration to seconds
1184 self
.length
= float(d
)/1000000
1185 # the indentation determines the depth
1186 match
= re
.match('^(?P<d> *)(?P<o>.*)$', m
)
1189 self
.depth
= self
.getDepth(match
.group('d'))
1190 m
= match
.group('o')
1195 # includes comment with function name
1196 match
= re
.match('^} *\/\* *(?P<n>.*) *\*\/$', m
)
1198 self
.name
= match
.group('n').strip()
1202 # function call with children
1204 match
= re
.match('^(?P<n>.*) *\(.*', m
)
1206 self
.name
= match
.group('n').strip()
1207 # function call with no children (leaf)
1210 match
= re
.match('^(?P<n>.*) *\(.*', m
)
1212 self
.name
= match
.group('n').strip()
1213 # something else (possibly a trace marker)
1216 def getDepth(self
, str):
1218 def debugPrint(self
, dev
=''):
1219 if(self
.freturn
and self
.fcall
):
1220 print('%s -- %f (%02d): %s(); (%.3f us)' % (dev
, self
.time
, \
1221 self
.depth
, self
.name
, self
.length
*1000000))
1223 print('%s -- %f (%02d): %s} (%.3f us)' % (dev
, self
.time
, \
1224 self
.depth
, self
.name
, self
.length
*1000000))
1226 print('%s -- %f (%02d): %s() { (%.3f us)' % (dev
, self
.time
, \
1227 self
.depth
, self
.name
, self
.length
*1000000))
1228 def startMarker(self
):
1230 # Is this the starting line of a suspend?
1233 if sysvals
.usetracemarkers
:
1234 if(self
.name
== 'SUSPEND START'):
1238 if(self
.type == 'suspend_resume' and
1239 re
.match('suspend_enter\[.*\] begin', self
.name
)):
1242 def endMarker(self
):
1243 # Is this the ending line of a resume?
1246 if sysvals
.usetracemarkers
:
1247 if(self
.name
== 'RESUME COMPLETE'):
1251 if(self
.type == 'suspend_resume' and
1252 re
.match('thaw_processes\[.*\] end', self
.name
)):
1256 # Class: FTraceCallGraph
1258 # A container for the ftrace callgraph of a single recursive function.
1259 # This can be a dpm_run_callback, dpm_prepare, or dpm_complete callgraph
1260 # Each instance is tied to a single device in a single phase, and is
1261 # comprised of an ordered list of FTraceLine objects
1262 class FTraceCallGraph
:
1269 def __init__(self
, pid
):
1275 def addLine(self
, line
, debug
=False):
1276 # if this is already invalid, just leave
1279 # invalidate on too much data or bad depth
1280 if(len(self
.list) >= 1000000 or self
.depth
< 0):
1281 self
.invalidate(line
)
1283 # compare current depth with this lines pre-call depth
1284 prelinedep
= line
.depth
1285 if(line
.freturn
and not line
.fcall
):
1288 lasttime
= line
.time
1289 virtualfname
= 'execution_misalignment'
1290 if len(self
.list) > 0:
1291 last
= self
.list[-1]
1292 lasttime
= last
.time
1293 # handle low misalignments by inserting returns
1294 if prelinedep
< self
.depth
:
1296 print '-------- task %d --------' % self
.pid
1299 # add return calls to get the depth down
1300 while prelinedep
< self
.depth
:
1302 print 'MISALIGN LOW (add returns): C%d - eC%d' % (self
.depth
, prelinedep
)
1304 if idx
== 0 and last
and last
.fcall
and not last
.freturn
:
1305 # special case, turn last call into a leaf
1306 last
.depth
= self
.depth
1308 last
.length
= line
.time
- last
.time
1312 vline
= FTraceLine(lasttime
)
1313 vline
.depth
= self
.depth
1314 vline
.name
= virtualfname
1315 vline
.freturn
= True
1316 self
.list.append(vline
)
1323 # handle high misalignments by inserting calls
1324 elif prelinedep
> self
.depth
:
1326 print '-------- task %d --------' % self
.pid
1329 # add calls to get the depth up
1330 while prelinedep
> self
.depth
:
1332 print 'MISALIGN HIGH (add calls): C%d - eC%d' % (self
.depth
, prelinedep
)
1333 if idx
== 0 and line
.freturn
and not line
.fcall
:
1334 # special case, turn this return into a leaf
1338 vline
= FTraceLine(lasttime
)
1339 vline
.depth
= self
.depth
1340 vline
.name
= virtualfname
1344 self
.list.append(vline
)
1347 self
.start
= vline
.time
1352 # process the call and set the new depth
1353 if(line
.fcall
and not line
.freturn
):
1355 elif(line
.freturn
and not line
.fcall
):
1357 if len(self
.list) < 1:
1358 self
.start
= line
.time
1359 self
.list.append(line
)
1360 if(line
.depth
== 0 and line
.freturn
):
1362 self
.start
= line
.time
1363 self
.end
= line
.time
1365 self
.end
+= line
.length
1366 if self
.list[0].name
== virtualfname
:
1370 def invalidate(self
, line
):
1371 if(len(self
.list) > 0):
1372 first
= self
.list[0]
1374 self
.list.append(first
)
1376 id = 'task %s' % (self
.pid
)
1377 window
= '(%f - %f)' % (self
.start
, line
.time
)
1379 vprint('Too much data for '+id+\
1380 ' (buffer overflow), ignoring this callback')
1382 vprint('Too much data for '+id+\
1383 ' '+window
+', ignoring this callback')
1384 def slice(self
, t0
, tN
):
1385 minicg
= FTraceCallGraph(0)
1389 if(l
.time
< t0
or l
.time
> tN
):
1392 if(not l
.fcall
or l
.name
== 'dev_driver_string'):
1394 firstdepth
= l
.depth
1396 l
.depth
-= firstdepth
1398 if((count
== 0 and l
.freturn
and l
.fcall
) or
1399 (count
> 0 and l
.depth
<= 0)):
1403 def repair(self
, enddepth
):
1404 # bring the depth back to 0 with additional returns
1406 last
= self
.list[-1]
1407 for i
in reversed(range(enddepth
)):
1408 t
= FTraceLine(last
.time
)
1411 fixed
= self
.addLine(t
)
1413 self
.end
= last
.time
1416 def postProcess(self
, debug
=False):
1420 if(l
.fcall
and not l
.freturn
):
1423 elif(l
.freturn
and not l
.fcall
):
1424 if(l
.depth
not in stack
):
1426 print 'Post Process Error: Depth missing'
1429 # transfer total time from return line to call line
1430 stack
[l
.depth
].length
= l
.length
1435 # trace caught the whole call tree
1439 print 'Post Process Error: Depth is less than 0'
1441 # trace ended before call tree finished
1442 return self
.repair(cnt
)
1443 def deviceMatch(self
, pid
, data
):
1445 # add the callgraph data to the device hierarchy
1447 'dpm_prepare': 'suspend_prepare',
1448 'dpm_complete': 'resume_complete'
1450 if(self
.list[0].name
in borderphase
):
1451 p
= borderphase
[self
.list[0].name
]
1452 list = data
.dmesg
[p
]['list']
1453 for devname
in list:
1455 if(pid
== dev
['pid'] and
1456 self
.start
<= dev
['start'] and
1457 self
.end
>= dev
['end']):
1458 dev
['ftrace'] = self
.slice(dev
['start'], dev
['end'])
1461 for p
in data
.phases
:
1462 if(data
.dmesg
[p
]['start'] <= self
.start
and
1463 self
.start
<= data
.dmesg
[p
]['end']):
1464 list = data
.dmesg
[p
]['list']
1465 for devname
in list:
1467 if(pid
== dev
['pid'] and
1468 self
.start
<= dev
['start'] and
1469 self
.end
>= dev
['end']):
1470 dev
['ftrace'] = self
1475 def newActionFromFunction(self
, data
):
1476 name
= self
.list[0].name
1477 if name
in ['dpm_run_callback', 'dpm_prepare', 'dpm_complete']:
1481 if fs
< data
.start
or fe
> data
.end
:
1484 for p
in data
.phases
:
1485 if(data
.dmesg
[p
]['start'] <= self
.start
and
1486 self
.start
< data
.dmesg
[p
]['end']):
1491 out
= data
.newActionGlobal(name
, fs
, fe
, -2)
1494 data
.dmesg
[phase
]['list'][myname
]['ftrace'] = self
1495 def debugPrint(self
):
1496 print('[%f - %f] %s (%d)') % (self
.start
, self
.end
, self
.list[0].name
, self
.pid
)
1498 if(l
.freturn
and l
.fcall
):
1499 print('%f (%02d): %s(); (%.3f us)' % (l
.time
, \
1500 l
.depth
, l
.name
, l
.length
*1000000))
1502 print('%f (%02d): %s} (%.3f us)' % (l
.time
, \
1503 l
.depth
, l
.name
, l
.length
*1000000))
1505 print('%f (%02d): %s() { (%.3f us)' % (l
.time
, \
1506 l
.depth
, l
.name
, l
.length
*1000000))
1511 # A container for a device timeline which calculates
1512 # all the html properties to display it correctly
1515 height
= 0 # total timeline height
1516 scaleH
= 20 # timescale (top) row height
1517 rowH
= 30 # device row height
1518 bodyH
= 0 # body height
1519 rows
= 0 # total timeline rows
1521 rowmaxlines
= dict()
1524 def __init__(self
, rowheight
):
1525 self
.rowH
= rowheight
1531 # Function: getDeviceRows
1533 # determine how may rows the device funcs will take
1535 # rawlist: the list of devices/actions for a single phase
1537 # The total number of rows needed to display this phase of the timeline
1538 def getDeviceRows(self
, rawlist
):
1539 # clear all rows and set them to undefined
1541 for item
in rawlist
:
1543 lendict
[item
] = item
.length
1545 for i
in sorted(lendict
, key
=lendict
.get
, reverse
=True):
1547 remaining
= len(list)
1550 # try to pack each row with as many ranges as possible
1551 while(remaining
> 0):
1552 if(row
not in rowdata
):
1558 e
= i
.time
+ i
.length
1560 for ritem
in rowdata
[row
]:
1562 re
= ritem
.time
+ ritem
.length
1563 if(not (((s
<= rs
) and (e
<= rs
)) or
1564 ((s
>= re
) and (e
>= re
)))):
1568 rowdata
[row
].append(i
)
1573 # Function: getPhaseRows
1575 # Organize the timeline entries into the smallest
1576 # number of rows possible, with no entry overlapping
1578 # list: the list of devices/actions for a single phase
1579 # devlist: string list of device names to use
1581 # The total number of rows needed to display this phase of the timeline
1582 def getPhaseRows(self
, dmesg
, devlist
):
1583 # clear all rows and set them to undefined
1584 remaining
= len(devlist
)
1589 for item
in devlist
:
1590 if item
[0] not in self
.phases
:
1591 self
.phases
.append(item
[0])
1592 if item
[0] not in myphases
:
1593 myphases
.append(item
[0])
1594 self
.rowmaxlines
[item
[0]] = dict()
1595 self
.rowheight
[item
[0]] = dict()
1596 dev
= dmesg
[item
[0]]['list'][item
[1]]
1598 lendict
[item
] = float(dev
['end']) - float(dev
['start'])
1600 dev
['devrows'] = self
.getDeviceRows(dev
['src'])
1602 for i
in sorted(lendict
, key
=lendict
.get
, reverse
=True):
1605 for item
in lenlist
:
1606 dev
= dmesg
[item
[0]]['list'][item
[1]]
1607 if dev
['pid'] == -2:
1608 orderedlist
.append(item
)
1609 for item
in lenlist
:
1610 if item
not in orderedlist
:
1611 orderedlist
.append(item
)
1612 # try to pack each row with as many ranges as possible
1613 while(remaining
> 0):
1615 if(row
not in rowdata
):
1617 for item
in orderedlist
:
1618 dev
= dmesg
[item
[0]]['list'][item
[1]]
1623 for ritem
in rowdata
[row
]:
1626 if(not (((s
<= rs
) and (e
<= rs
)) or
1627 ((s
>= re
) and (e
>= re
)))):
1631 rowdata
[row
].append(dev
)
1634 if 'devrows' in dev
and dev
['devrows'] > rowheight
:
1635 rowheight
= dev
['devrows']
1636 for phase
in myphases
:
1637 self
.rowmaxlines
[phase
][row
] = rowheight
1638 self
.rowheight
[phase
][row
] = rowheight
* self
.rowH
1640 if(row
> self
.rows
):
1641 self
.rows
= int(row
)
1642 for phase
in myphases
:
1643 self
.rowcount
[phase
] = row
1645 def phaseRowHeight(self
, phase
, row
):
1646 return self
.rowheight
[phase
][row
]
1647 def phaseRowTop(self
, phase
, row
):
1649 for i
in sorted(self
.rowheight
[phase
]):
1652 top
+= self
.rowheight
[phase
][i
]
1654 # Function: calcTotalRows
1656 # Calculate the heights and offsets for the header and rows
1657 def calcTotalRows(self
):
1660 for phase
in self
.phases
:
1662 for i
in sorted(self
.rowmaxlines
[phase
]):
1663 total
+= self
.rowmaxlines
[phase
][i
]
1666 if total
== self
.rowcount
[phase
]:
1667 standardphases
.append(phase
)
1668 self
.height
= self
.scaleH
+ (maxrows
*self
.rowH
)
1669 self
.bodyH
= self
.height
- self
.scaleH
1670 for phase
in standardphases
:
1671 for i
in sorted(self
.rowheight
[phase
]):
1672 self
.rowheight
[phase
][i
] = self
.bodyH
/self
.rowcount
[phase
]
1673 # Function: createTimeScale
1675 # Create the timescale for a timeline block
1677 # m0: start time (mode begin)
1678 # mMax: end time (mode end)
1679 # tTotal: total timeline time
1680 # mode: suspend or resume
1682 # The html code needed to display the time scale
1683 def createTimeScale(self
, m0
, mMax
, tTotal
, mode
):
1684 timescale
= '<div class="t" style="right:{0}%">{1}</div>\n'
1685 rline
= '<div class="t" style="left:0;border-left:1px solid black;border-right:0;">Resume</div>\n'
1686 output
= '<div class="timescale">\n'
1687 # set scale for timeline
1691 return output
+'</div>\n'
1694 divTotal
= int(mTotal
/tS
) + 1
1695 divEdge
= (mTotal
- tS
*(divTotal
-1))*100/mTotal
1696 for i
in range(divTotal
):
1698 if(mode
== 'resume'):
1699 pos
= '%0.3f' % (100 - ((float(i
)*tS
*100)/mTotal
))
1700 val
= '%0.fms' % (float(i
)*tS
*1000)
1701 htmlline
= timescale
.format(pos
, val
)
1705 pos
= '%0.3f' % (100 - ((float(i
)*tS
*100)/mTotal
) - divEdge
)
1706 val
= '%0.fms' % (float(i
-divTotal
+1)*tS
*1000)
1707 if(i
== divTotal
- 1):
1709 htmlline
= timescale
.format(pos
, val
)
1711 output
+= '</div>\n'
1716 # A list of values describing the properties of these test runs
1722 ftrace_line_fmt_fg
= \
1723 '^ *(?P<time>[0-9\.]*) *\| *(?P<cpu>[0-9]*)\)'+\
1724 ' *(?P<proc>.*)-(?P<pid>[0-9]*) *\|'+\
1725 '[ +!#\*@$]*(?P<dur>[0-9\.]*) .*\| (?P<msg>.*)'
1726 ftrace_line_fmt_nop
= \
1727 ' *(?P<proc>.*)-(?P<pid>[0-9]*) *\[(?P<cpu>[0-9]*)\] *'+\
1728 '(?P<flags>.{4}) *(?P<time>[0-9\.]*): *'+\
1730 ftrace_line_fmt
= ftrace_line_fmt_nop
1736 def setTracerType(self
, tracer
):
1737 self
.tracertype
= tracer
1738 if(tracer
== 'function_graph'):
1739 self
.cgformat
= True
1740 self
.ftrace_line_fmt
= self
.ftrace_line_fmt_fg
1741 elif(tracer
== 'nop'):
1742 self
.ftrace_line_fmt
= self
.ftrace_line_fmt_nop
1744 doError('Invalid tracer format: [%s]' % tracer
, False)
1748 # A container for a suspend/resume test run. This is necessary as
1749 # there could be more than one, and they need to be separate.
1754 def __init__(self
, dataobj
):
1759 # ----------------- FUNCTIONS --------------------
1763 # verbose print (prints only with -verbose option)
1765 # msg: the debug/log message to print
1768 if(sysvals
.verbose
):
1771 # Function: parseStamp
1773 # Pull in the stamp comment line from the data file(s),
1774 # create the stamp, and add it to the global sysvals object
1776 # m: the valid re.match output for the stamp line
1777 def parseStamp(line
, data
):
1780 m
= re
.match(sysvals
.stampfmt
, line
)
1781 data
.stamp
= {'time': '', 'host': '', 'mode': ''}
1782 dt
= datetime(int(m
.group('y'))+2000, int(m
.group('m')),
1783 int(m
.group('d')), int(m
.group('H')), int(m
.group('M')),
1785 data
.stamp
['time'] = dt
.strftime('%B %d %Y, %I:%M:%S %p')
1786 data
.stamp
['host'] = m
.group('host')
1787 data
.stamp
['mode'] = m
.group('mode')
1788 data
.stamp
['kernel'] = m
.group('kernel')
1789 sysvals
.hostname
= data
.stamp
['host']
1790 sysvals
.suspendmode
= data
.stamp
['mode']
1791 if not sysvals
.stamp
:
1792 sysvals
.stamp
= data
.stamp
1794 # Function: diffStamp
1796 # compare the host, kernel, and mode fields in 3 stamps
1798 # stamp1: string array with mode, kernel, and host
1799 # stamp2: string array with mode, kernel, and host
1801 # True if stamps differ, False if they're the same
1802 def diffStamp(stamp1
, stamp2
):
1803 if 'host' in stamp1
and 'host' in stamp2
:
1804 if stamp1
['host'] != stamp2
['host']:
1806 if 'kernel' in stamp1
and 'kernel' in stamp2
:
1807 if stamp1
['kernel'] != stamp2
['kernel']:
1809 if 'mode' in stamp1
and 'mode' in stamp2
:
1810 if stamp1
['mode'] != stamp2
['mode']:
1814 # Function: doesTraceLogHaveTraceEvents
1816 # Quickly determine if the ftrace log has some or all of the trace events
1817 # required for primary parsing. Set the usetraceevents and/or
1818 # usetraceeventsonly flags in the global sysvals object
1819 def doesTraceLogHaveTraceEvents():
1823 sysvals
.usekprobes
= False
1824 out
= os
.system('grep -q "_cal: (" '+sysvals
.ftracefile
)
1826 sysvals
.usekprobes
= True
1827 # check for callgraph data on trace event blocks
1828 out
= os
.system('grep -q "_cpu_down()" '+sysvals
.ftracefile
)
1830 sysvals
.usekprobes
= True
1831 out
= os
.popen('head -1 '+sysvals
.ftracefile
).read().replace('\n', '')
1832 m
= re
.match(sysvals
.stampfmt
, out
)
1833 if m
and m
.group('mode') == 'command':
1834 sysvals
.usetraceeventsonly
= True
1835 sysvals
.usetraceevents
= True
1837 # figure out what level of trace events are supported
1838 sysvals
.usetraceeventsonly
= True
1839 sysvals
.usetraceevents
= False
1840 for e
in sysvals
.traceevents
:
1841 out
= os
.system('grep -q "'+e
+': " '+sysvals
.ftracefile
)
1843 sysvals
.usetraceeventsonly
= False
1844 if(e
== 'suspend_resume' and out
== 0):
1845 sysvals
.usetraceevents
= True
1846 # determine is this log is properly formatted
1847 for e
in ['SUSPEND START', 'RESUME COMPLETE']:
1848 out
= os
.system('grep -q "'+e
+'" '+sysvals
.ftracefile
)
1850 sysvals
.usetracemarkers
= False
1852 # Function: appendIncompleteTraceLog
1854 # [deprecated for kernel 3.15 or newer]
1855 # Legacy support of ftrace outputs that lack the device_pm_callback
1856 # and/or suspend_resume trace events. The primary data should be
1857 # taken from dmesg, and this ftrace is used only for callgraph data
1858 # or custom actions in the timeline. The data is appended to the Data
1861 # testruns: the array of Data objects obtained from parseKernelLog
1862 def appendIncompleteTraceLog(testruns
):
1865 # create TestRun vessels for ftrace parsing
1866 testcnt
= len(testruns
)
1869 for data
in testruns
:
1870 testrun
.append(TestRun(data
))
1872 # extract the callgraph and traceevent data
1873 vprint('Analyzing the ftrace data...')
1875 tf
= open(sysvals
.ftracefile
, 'r')
1878 # remove any latent carriage returns
1879 line
= line
.replace('\r\n', '')
1880 # grab the time stamp
1881 m
= re
.match(sysvals
.stampfmt
, line
)
1885 # determine the trace data type (required for further parsing)
1886 m
= re
.match(sysvals
.tracertypefmt
, line
)
1888 tp
.setTracerType(m
.group('t'))
1890 # device properties line
1891 if(re
.match(sysvals
.devpropfmt
, line
)):
1894 # parse only valid lines, if this is not one move on
1895 m
= re
.match(tp
.ftrace_line_fmt
, line
)
1898 # gather the basic message data from the line
1899 m_time
= m
.group('time')
1900 m_pid
= m
.group('pid')
1901 m_msg
= m
.group('msg')
1903 m_param3
= m
.group('dur')
1905 m_param3
= 'traceevent'
1906 if(m_time
and m_pid
and m_msg
):
1907 t
= FTraceLine(m_time
, m_msg
, m_param3
)
1911 # the line should be a call, return, or event
1912 if(not t
.fcall
and not t
.freturn
and not t
.fevent
):
1914 # look for the suspend start marker
1915 if(t
.startMarker()):
1916 data
= testrun
[testidx
].data
1917 parseStamp(tp
.stamp
, data
)
1918 data
.setStart(t
.time
)
1922 # find the end of resume
1926 if(testidx
>= testcnt
):
1929 # trace event processing
1931 # general trace events have two types, begin and end
1932 if(re
.match('(?P<name>.*) begin$', t
.name
)):
1934 elif(re
.match('(?P<name>.*) end$', t
.name
)):
1938 m
= re
.match('(?P<name>.*)\[(?P<val>[0-9]*)\] .*', t
.name
)
1940 val
= m
.group('val')
1942 name
= m
.group('name')
1944 name
= m
.group('name')+'['+val
+']'
1946 m
= re
.match('(?P<name>.*) .*', t
.name
)
1947 name
= m
.group('name')
1948 # special processing for trace events
1949 if re
.match('dpm_prepare\[.*', name
):
1951 elif re
.match('machine_suspend.*', name
):
1953 elif re
.match('suspend_enter\[.*', name
):
1955 data
.dmesg
['suspend_prepare']['end'] = t
.time
1957 elif re
.match('dpm_suspend\[.*', name
):
1959 data
.dmesg
['suspend']['end'] = t
.time
1961 elif re
.match('dpm_suspend_late\[.*', name
):
1963 data
.dmesg
['suspend_late']['start'] = t
.time
1965 data
.dmesg
['suspend_late']['end'] = t
.time
1967 elif re
.match('dpm_suspend_noirq\[.*', name
):
1969 data
.dmesg
['suspend_noirq']['start'] = t
.time
1971 data
.dmesg
['suspend_noirq']['end'] = t
.time
1973 elif re
.match('dpm_resume_noirq\[.*', name
):
1975 data
.dmesg
['resume_machine']['end'] = t
.time
1976 data
.dmesg
['resume_noirq']['start'] = t
.time
1978 data
.dmesg
['resume_noirq']['end'] = t
.time
1980 elif re
.match('dpm_resume_early\[.*', name
):
1982 data
.dmesg
['resume_early']['start'] = t
.time
1984 data
.dmesg
['resume_early']['end'] = t
.time
1986 elif re
.match('dpm_resume\[.*', name
):
1988 data
.dmesg
['resume']['start'] = t
.time
1990 data
.dmesg
['resume']['end'] = t
.time
1992 elif re
.match('dpm_complete\[.*', name
):
1994 data
.dmesg
['resume_complete']['start'] = t
.time
1996 data
.dmesg
['resume_complete']['end'] = t
.time
1998 # skip trace events inside devices calls
1999 if(not data
.isTraceEventOutsideDeviceCalls(pid
, t
.time
)):
2001 # global events (outside device calls) are simply graphed
2003 # store each trace event in ttemp
2004 if(name
not in testrun
[testidx
].ttemp
):
2005 testrun
[testidx
].ttemp
[name
] = []
2006 testrun
[testidx
].ttemp
[name
].append(\
2007 {'begin': t
.time
, 'end': t
.time
})
2009 # finish off matching trace event in ttemp
2010 if(name
in testrun
[testidx
].ttemp
):
2011 testrun
[testidx
].ttemp
[name
][-1]['end'] = t
.time
2012 # call/return processing
2013 elif sysvals
.usecallgraph
:
2014 # create a callgraph object for the data
2015 if(pid
not in testrun
[testidx
].ftemp
):
2016 testrun
[testidx
].ftemp
[pid
] = []
2017 testrun
[testidx
].ftemp
[pid
].append(FTraceCallGraph(pid
))
2018 # when the call is finished, see which device matches it
2019 cg
= testrun
[testidx
].ftemp
[pid
][-1]
2021 testrun
[testidx
].ftemp
[pid
].append(FTraceCallGraph(pid
))
2024 for test
in testrun
:
2025 # add the traceevent data to the device hierarchy
2026 if(sysvals
.usetraceevents
):
2027 for name
in test
.ttemp
:
2028 for event
in test
.ttemp
[name
]:
2029 test
.data
.newActionGlobal(name
, event
['begin'], event
['end'])
2031 # add the callgraph data to the device hierarchy
2032 for pid
in test
.ftemp
:
2033 for cg
in test
.ftemp
[pid
]:
2034 if len(cg
.list) < 1 or cg
.invalid
:
2036 if(not cg
.postProcess()):
2037 id = 'task %s cpu %s' % (pid
, m
.group('cpu'))
2038 vprint('Sanity check failed for '+\
2039 id+', ignoring this callback')
2041 callstart
= cg
.start
2043 for p
in test
.data
.phases
:
2044 if(test
.data
.dmesg
[p
]['start'] <= callstart
and
2045 callstart
<= test
.data
.dmesg
[p
]['end']):
2046 list = test
.data
.dmesg
[p
]['list']
2047 for devname
in list:
2049 if(pid
== dev
['pid'] and
2050 callstart
<= dev
['start'] and
2051 callend
>= dev
['end']):
2055 if(sysvals
.verbose
):
2056 test
.data
.printDetails()
2058 # Function: parseTraceLog
2060 # Analyze an ftrace log output file generated from this app during
2061 # the execution phase. Used when the ftrace log is the primary data source
2062 # and includes the suspend_resume and device_pm_callback trace events
2063 # The ftrace filename is taken from sysvals
2065 # An array of Data objects
2066 def parseTraceLog():
2069 vprint('Analyzing the ftrace data...')
2070 if(os
.path
.exists(sysvals
.ftracefile
) == False):
2071 doError('%s does not exist' % sysvals
.ftracefile
, False)
2073 sysvals
.setupAllKprobes()
2074 tracewatch
= ['suspend_enter']
2075 if sysvals
.usekprobes
:
2076 tracewatch
+= ['sync_filesystems', 'freeze_processes', 'syscore_suspend',
2077 'syscore_resume', 'resume_console', 'thaw_processes', 'CPU_ON', 'CPU_OFF']
2079 # extract the callgraph and traceevent data
2085 tf
= open(sysvals
.ftracefile
, 'r')
2086 phase
= 'suspend_prepare'
2088 # remove any latent carriage returns
2089 line
= line
.replace('\r\n', '')
2090 # stamp line: each stamp means a new test run
2091 m
= re
.match(sysvals
.stampfmt
, line
)
2095 # firmware line: pull out any firmware data
2096 m
= re
.match(sysvals
.firmwarefmt
, line
)
2098 tp
.fwdata
.append((int(m
.group('s')), int(m
.group('r'))))
2100 # tracer type line: determine the trace data type
2101 m
= re
.match(sysvals
.tracertypefmt
, line
)
2103 tp
.setTracerType(m
.group('t'))
2105 # post resume time line: did this test run include post-resume data
2106 m
= re
.match(sysvals
.postresumefmt
, line
)
2108 t
= int(m
.group('t'))
2110 sysvals
.postresumetime
= t
2112 # device properties line
2113 if(re
.match(sysvals
.devpropfmt
, line
)):
2116 # ftrace line: parse only valid lines
2117 m
= re
.match(tp
.ftrace_line_fmt
, line
)
2120 # gather the basic message data from the line
2121 m_time
= m
.group('time')
2122 m_proc
= m
.group('proc')
2123 m_pid
= m
.group('pid')
2124 m_msg
= m
.group('msg')
2126 m_param3
= m
.group('dur')
2128 m_param3
= 'traceevent'
2129 if(m_time
and m_pid
and m_msg
):
2130 t
= FTraceLine(m_time
, m_msg
, m_param3
)
2134 # the line should be a call, return, or event
2135 if(not t
.fcall
and not t
.freturn
and not t
.fevent
):
2137 # find the start of suspend
2138 if(t
.startMarker()):
2139 phase
= 'suspend_prepare'
2140 data
= Data(len(testdata
))
2141 testdata
.append(data
)
2142 testrun
= TestRun(data
)
2143 testruns
.append(testrun
)
2144 parseStamp(tp
.stamp
, data
)
2145 if len(tp
.fwdata
) > data
.testnumber
:
2146 data
.fwSuspend
, data
.fwResume
= tp
.fwdata
[data
.testnumber
]
2147 if(data
.fwSuspend
> 0 or data
.fwResume
> 0):
2149 data
.setStart(t
.time
)
2153 # find the end of resume
2155 if(sysvals
.usetracemarkers
and sysvals
.postresumetime
> 0):
2156 phase
= 'post_resume'
2157 data
.newPhase(phase
, t
.time
, t
.time
, '#F0F0F0', -1)
2159 if(not sysvals
.usetracemarkers
):
2160 # no trace markers? then quit and be sure to finish recording
2161 # the event we used to trigger resume end
2162 if(len(testrun
.ttemp
['thaw_processes']) > 0):
2163 # if an entry exists, assume this is its end
2164 testrun
.ttemp
['thaw_processes'][-1]['end'] = t
.time
2167 # trace event processing
2169 if(phase
== 'post_resume'):
2171 if(t
.type == 'suspend_resume'):
2172 # suspend_resume trace events have two types, begin and end
2173 if(re
.match('(?P<name>.*) begin$', t
.name
)):
2175 elif(re
.match('(?P<name>.*) end$', t
.name
)):
2179 m
= re
.match('(?P<name>.*)\[(?P<val>[0-9]*)\] .*', t
.name
)
2181 val
= m
.group('val')
2183 name
= m
.group('name')
2185 name
= m
.group('name')+'['+val
+']'
2187 m
= re
.match('(?P<name>.*) .*', t
.name
)
2188 name
= m
.group('name')
2189 # ignore these events
2190 if(name
.split('[')[0] in tracewatch
):
2192 # -- phase changes --
2193 # suspend_prepare start
2194 if(re
.match('dpm_prepare\[.*', t
.name
)):
2195 phase
= 'suspend_prepare'
2197 data
.dmesg
[phase
]['end'] = t
.time
2200 elif(re
.match('dpm_suspend\[.*', t
.name
)):
2202 data
.setPhase(phase
, t
.time
, isbegin
)
2204 # suspend_late start
2205 elif(re
.match('dpm_suspend_late\[.*', t
.name
)):
2206 phase
= 'suspend_late'
2207 data
.setPhase(phase
, t
.time
, isbegin
)
2209 # suspend_noirq start
2210 elif(re
.match('dpm_suspend_noirq\[.*', t
.name
)):
2211 phase
= 'suspend_noirq'
2212 data
.setPhase(phase
, t
.time
, isbegin
)
2214 phase
= 'suspend_machine'
2215 data
.dmesg
[phase
]['start'] = t
.time
2217 # suspend_machine/resume_machine
2218 elif(re
.match('machine_suspend\[.*', t
.name
)):
2220 phase
= 'suspend_machine'
2221 data
.dmesg
[phase
]['end'] = t
.time
2222 data
.tSuspended
= t
.time
2224 if(sysvals
.suspendmode
in ['mem', 'disk'] and not tp
.S0i3
):
2225 data
.dmesg
['suspend_machine']['end'] = t
.time
2226 data
.tSuspended
= t
.time
2227 phase
= 'resume_machine'
2228 data
.dmesg
[phase
]['start'] = t
.time
2229 data
.tResumed
= t
.time
2230 data
.tLow
= data
.tResumed
- data
.tSuspended
2233 elif(re
.match('acpi_suspend\[.*', t
.name
)):
2234 # acpi_suspend[0] S0i3
2235 if(re
.match('acpi_suspend\[0\] begin', t
.name
)):
2236 if(sysvals
.suspendmode
== 'mem'):
2238 data
.dmesg
['suspend_machine']['end'] = t
.time
2239 data
.tSuspended
= t
.time
2241 # resume_noirq start
2242 elif(re
.match('dpm_resume_noirq\[.*', t
.name
)):
2243 phase
= 'resume_noirq'
2244 data
.setPhase(phase
, t
.time
, isbegin
)
2246 data
.dmesg
['resume_machine']['end'] = t
.time
2248 # resume_early start
2249 elif(re
.match('dpm_resume_early\[.*', t
.name
)):
2250 phase
= 'resume_early'
2251 data
.setPhase(phase
, t
.time
, isbegin
)
2254 elif(re
.match('dpm_resume\[.*', t
.name
)):
2256 data
.setPhase(phase
, t
.time
, isbegin
)
2258 # resume complete start
2259 elif(re
.match('dpm_complete\[.*', t
.name
)):
2260 phase
= 'resume_complete'
2262 data
.dmesg
[phase
]['start'] = t
.time
2264 # skip trace events inside devices calls
2265 if(not data
.isTraceEventOutsideDeviceCalls(pid
, t
.time
)):
2267 # global events (outside device calls) are graphed
2268 if(name
not in testrun
.ttemp
):
2269 testrun
.ttemp
[name
] = []
2271 # create a new list entry
2272 testrun
.ttemp
[name
].append(\
2273 {'begin': t
.time
, 'end': t
.time
, 'pid': pid
})
2275 if(len(testrun
.ttemp
[name
]) > 0):
2276 # if an entry exists, assume this is its end
2277 testrun
.ttemp
[name
][-1]['end'] = t
.time
2278 elif(phase
== 'post_resume'):
2279 # post resume events can just have ends
2280 testrun
.ttemp
[name
].append({
2281 'begin': data
.dmesg
[phase
]['start'],
2283 # device callback start
2284 elif(t
.type == 'device_pm_callback_start'):
2285 m
= re
.match('(?P<drv>.*) (?P<d>.*), parent: *(?P<p>.*), .*',\
2289 drv
= m
.group('drv')
2293 data
.newAction(phase
, n
, pid
, p
, t
.time
, -1, drv
)
2294 # device callback finish
2295 elif(t
.type == 'device_pm_callback_end'):
2296 m
= re
.match('(?P<drv>.*) (?P<d>.*), err.*', t
.name
);
2300 list = data
.dmesg
[phase
]['list']
2303 dev
['length'] = t
.time
- dev
['start']
2305 # kprobe event processing
2309 key
= (kprobename
, pid
)
2310 # displayname is generated from kprobe data
2313 displayname
= sysvals
.kprobeDisplayName(kprobename
, kprobedata
)
2316 if(key
not in tp
.ktemp
):
2318 tp
.ktemp
[key
].append({
2322 'name': displayname
,
2323 'cdata': kprobedata
,
2327 if(key
not in tp
.ktemp
) or len(tp
.ktemp
[key
]) < 1:
2329 e
= tp
.ktemp
[key
][-1]
2330 if e
['begin'] < 0.0 or t
.time
- e
['begin'] < 0.000001:
2334 e
['rdata'] = kprobedata
2335 # callgraph processing
2336 elif sysvals
.usecallgraph
:
2337 # create a callgraph object for the data
2339 if(key
not in testrun
.ftemp
):
2340 testrun
.ftemp
[key
] = []
2341 testrun
.ftemp
[key
].append(FTraceCallGraph(pid
))
2342 # when the call is finished, see which device matches it
2343 cg
= testrun
.ftemp
[key
][-1]
2345 testrun
.ftemp
[key
].append(FTraceCallGraph(pid
))
2348 if sysvals
.suspendmode
== 'command':
2349 for test
in testruns
:
2350 for p
in test
.data
.phases
:
2351 if p
== 'resume_complete':
2352 test
.data
.dmesg
[p
]['start'] = test
.data
.start
2353 test
.data
.dmesg
[p
]['end'] = test
.data
.end
2355 test
.data
.dmesg
[p
]['start'] = test
.data
.start
2356 test
.data
.dmesg
[p
]['end'] = test
.data
.start
2357 test
.data
.tSuspended
= test
.data
.start
2358 test
.data
.tResumed
= test
.data
.start
2360 test
.data
.fwValid
= False
2362 for test
in testruns
:
2363 # add the traceevent data to the device hierarchy
2364 if(sysvals
.usetraceevents
):
2365 # add actual trace funcs
2366 for name
in test
.ttemp
:
2367 for event
in test
.ttemp
[name
]:
2368 test
.data
.newActionGlobal(name
, event
['begin'], event
['end'], event
['pid'])
2369 # add the kprobe based virtual tracefuncs as actual devices
2370 for key
in tp
.ktemp
:
2372 if name
not in sysvals
.tracefuncs
:
2374 for e
in tp
.ktemp
[key
]:
2375 kb
, ke
= e
['begin'], e
['end']
2376 if kb
== ke
or not test
.data
.isInsideTimeline(kb
, ke
):
2378 test
.data
.newActionGlobal(e
['name'], kb
, ke
, pid
)
2379 # add config base kprobes and dev kprobes
2380 for key
in tp
.ktemp
:
2382 if name
in sysvals
.tracefuncs
:
2384 for e
in tp
.ktemp
[key
]:
2385 kb
, ke
= e
['begin'], e
['end']
2386 if kb
== ke
or not test
.data
.isInsideTimeline(kb
, ke
):
2388 color
= sysvals
.kprobeColor(e
['name'])
2389 if name
not in sysvals
.dev_tracefuncs
:
2390 # config base kprobe
2391 test
.data
.newActionGlobal(e
['name'], kb
, ke
, -2, color
)
2392 elif sysvals
.usedevsrc
:
2394 data
.addDeviceFunctionCall(e
['name'], name
, e
['proc'], pid
, kb
,
2395 ke
, e
['cdata'], e
['rdata'])
2396 if sysvals
.usecallgraph
:
2397 # add the callgraph data to the device hierarchy
2399 for key
in test
.ftemp
:
2401 for cg
in test
.ftemp
[key
]:
2402 if len(cg
.list) < 1 or cg
.invalid
:
2404 if(not cg
.postProcess()):
2405 id = 'task %s' % (pid
)
2406 vprint('Sanity check failed for '+\
2407 id+', ignoring this callback')
2409 # match cg data to devices
2410 if sysvals
.suspendmode
== 'command' or not cg
.deviceMatch(pid
, test
.data
):
2411 sortkey
= '%f%f%d' % (cg
.start
, cg
.end
, pid
)
2412 sortlist
[sortkey
] = cg
2413 # create blocks for orphan cg data
2414 for sortkey
in sorted(sortlist
):
2415 cg
= sortlist
[sortkey
]
2416 name
= cg
.list[0].name
2417 if sysvals
.isCallgraphFunc(name
):
2418 vprint('Callgraph found for task %d: %.3fms, %s' % (cg
.pid
, (cg
.end
- cg
.start
)*1000, name
))
2419 cg
.newActionFromFunction(test
.data
)
2421 if sysvals
.suspendmode
== 'command':
2422 if(sysvals
.verbose
):
2423 for data
in testdata
:
2427 # fill in any missing phases
2428 for data
in testdata
:
2430 for p
in data
.phases
:
2431 if(data
.dmesg
[p
]['start'] < 0 and data
.dmesg
[p
]['end'] < 0):
2432 print('WARNING: phase "%s" is missing!' % p
)
2433 if(data
.dmesg
[p
]['start'] < 0):
2434 data
.dmesg
[p
]['start'] = data
.dmesg
[lp
]['end']
2435 if(p
== 'resume_machine'):
2436 data
.tSuspended
= data
.dmesg
[lp
]['end']
2437 data
.tResumed
= data
.dmesg
[lp
]['end']
2439 if(data
.dmesg
[p
]['end'] < 0):
2440 data
.dmesg
[p
]['end'] = data
.dmesg
[p
]['start']
2443 if(len(sysvals
.devicefilter
) > 0):
2444 data
.deviceFilter(sysvals
.devicefilter
)
2445 data
.fixupInitcallsThatDidntReturn()
2446 if(sysvals
.verbose
):
2451 # Function: loadRawKernelLog
2453 # Load a raw kernel log that wasn't created by this tool, it might be
2454 # possible to extract a valid suspend/resume log
2455 def loadRawKernelLog(dmesgfile
):
2458 stamp
= {'time': '', 'host': '', 'mode': 'mem', 'kernel': ''}
2459 stamp
['time'] = datetime
.now().strftime('%B %d %Y, %I:%M:%S %p')
2460 stamp
['host'] = sysvals
.hostname
2464 lf
= open(dmesgfile
, 'r')
2466 line
= line
.replace('\r\n', '')
2467 idx
= line
.find('[')
2470 m
= re
.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line
)
2473 msg
= m
.group("msg")
2474 m
= re
.match('PM: Syncing filesystems.*', msg
)
2477 testruns
.append(data
)
2478 data
= Data(len(testruns
))
2481 m
= re
.match('.* *(?P<k>[0-9]\.[0-9]{2}\.[0-9]-.*) .*', msg
)
2483 stamp
['kernel'] = m
.group('k')
2484 m
= re
.match('PM: Preparing system for (?P<m>.*) sleep', msg
)
2486 stamp
['mode'] = m
.group('m')
2487 data
.dmesgtext
.append(line
)
2489 testruns
.append(data
)
2490 sysvals
.stamp
= stamp
2491 sysvals
.suspendmode
= stamp
['mode']
2495 # Function: loadKernelLog
2497 # [deprecated for kernel 3.15.0 or newer]
2498 # load the dmesg file into memory and fix up any ordering issues
2499 # The dmesg filename is taken from sysvals
2501 # An array of empty Data objects with only their dmesgtext attributes set
2502 def loadKernelLog():
2505 vprint('Analyzing the dmesg data...')
2506 if(os
.path
.exists(sysvals
.dmesgfile
) == False):
2507 doError('%s does not exist' % sysvals
.dmesgfile
, False)
2509 # there can be multiple test runs in a single file
2513 lf
= open(sysvals
.dmesgfile
, 'r')
2515 line
= line
.replace('\r\n', '')
2516 idx
= line
.find('[')
2519 m
= re
.match(sysvals
.stampfmt
, line
)
2523 m
= re
.match(sysvals
.firmwarefmt
, line
)
2525 tp
.fwdata
.append((int(m
.group('s')), int(m
.group('r'))))
2527 m
= re
.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line
)
2530 msg
= m
.group("msg")
2531 if(re
.match('PM: Syncing filesystems.*', msg
)):
2533 testruns
.append(data
)
2534 data
= Data(len(testruns
))
2535 parseStamp(tp
.stamp
, data
)
2536 if len(tp
.fwdata
) > data
.testnumber
:
2537 data
.fwSuspend
, data
.fwResume
= tp
.fwdata
[data
.testnumber
]
2538 if(data
.fwSuspend
> 0 or data
.fwResume
> 0):
2540 if(re
.match('ACPI: resume from mwait', msg
)):
2541 print('NOTE: This suspend appears to be freeze rather than'+\
2542 ' %s, it will be treated as such' % sysvals
.suspendmode
)
2543 sysvals
.suspendmode
= 'freeze'
2546 data
.dmesgtext
.append(line
)
2548 testruns
.append(data
)
2551 if(len(testruns
) < 1):
2552 # bad log, but see if you can extract something meaningful anyway
2553 testruns
= loadRawKernelLog(sysvals
.dmesgfile
)
2555 if(len(testruns
) < 1):
2556 doError(' dmesg log is completely unreadable: %s' \
2557 % sysvals
.dmesgfile
, False)
2559 # fix lines with same timestamp/function with the call and return swapped
2560 for data
in testruns
:
2562 for line
in data
.dmesgtext
:
2563 mc
= re
.match('.*(\[ *)(?P<t>[0-9\.]*)(\]) calling '+\
2564 '(?P<f>.*)\+ @ .*, parent: .*', line
)
2565 mr
= re
.match('.*(\[ *)(?P<t>[0-9\.]*)(\]) call '+\
2566 '(?P<f>.*)\+ returned .* after (?P<dt>.*) usecs', last
)
2567 if(mc
and mr
and (mc
.group('t') == mr
.group('t')) and
2568 (mc
.group('f') == mr
.group('f'))):
2569 i
= data
.dmesgtext
.index(last
)
2570 j
= data
.dmesgtext
.index(line
)
2571 data
.dmesgtext
[i
] = line
2572 data
.dmesgtext
[j
] = last
2576 # Function: parseKernelLog
2578 # [deprecated for kernel 3.15.0 or newer]
2579 # Analyse a dmesg log output file generated from this app during
2580 # the execution phase. Create a set of device structures in memory
2581 # for subsequent formatting in the html output file
2582 # This call is only for legacy support on kernels where the ftrace
2583 # data lacks the suspend_resume or device_pm_callbacks trace events.
2585 # data: an empty Data object (with dmesgtext) obtained from loadKernelLog
2587 # The filled Data object
2588 def parseKernelLog(data
):
2591 phase
= 'suspend_runtime'
2594 vprint('Firmware Suspend = %u ns, Firmware Resume = %u ns' % \
2595 (data
.fwSuspend
, data
.fwResume
))
2597 # dmesg phase match table
2599 'suspend_prepare': 'PM: Syncing filesystems.*',
2600 'suspend': 'PM: Entering [a-z]* sleep.*',
2601 'suspend_late': 'PM: suspend of devices complete after.*',
2602 'suspend_noirq': 'PM: late suspend of devices complete after.*',
2603 'suspend_machine': 'PM: noirq suspend of devices complete after.*',
2604 'resume_machine': 'ACPI: Low-level resume complete.*',
2605 'resume_noirq': 'ACPI: Waking up from system sleep state.*',
2606 'resume_early': 'PM: noirq resume of devices complete after.*',
2607 'resume': 'PM: early resume of devices complete after.*',
2608 'resume_complete': 'PM: resume of devices complete after.*',
2609 'post_resume': '.*Restarting tasks \.\.\..*',
2611 if(sysvals
.suspendmode
== 'standby'):
2612 dm
['resume_machine'] = 'PM: Restoring platform NVS memory'
2613 elif(sysvals
.suspendmode
== 'disk'):
2614 dm
['suspend_late'] = 'PM: freeze of devices complete after.*'
2615 dm
['suspend_noirq'] = 'PM: late freeze of devices complete after.*'
2616 dm
['suspend_machine'] = 'PM: noirq freeze of devices complete after.*'
2617 dm
['resume_machine'] = 'PM: Restoring platform NVS memory'
2618 dm
['resume_early'] = 'PM: noirq restore of devices complete after.*'
2619 dm
['resume'] = 'PM: early restore of devices complete after.*'
2620 dm
['resume_complete'] = 'PM: restore of devices complete after.*'
2621 elif(sysvals
.suspendmode
== 'freeze'):
2622 dm
['resume_machine'] = 'ACPI: resume from mwait'
2624 # action table (expected events that occur and show up in dmesg)
2626 'sync_filesystems': {
2627 'smsg': 'PM: Syncing filesystems.*',
2628 'emsg': 'PM: Preparing system for mem sleep.*' },
2629 'freeze_user_processes': {
2630 'smsg': 'Freezing user space processes .*',
2631 'emsg': 'Freezing remaining freezable tasks.*' },
2633 'smsg': 'Freezing remaining freezable tasks.*',
2634 'emsg': 'PM: Entering (?P<mode>[a-z,A-Z]*) sleep.*' },
2636 'smsg': 'ACPI: Preparing to enter system sleep state.*',
2637 'emsg': 'PM: Saving platform NVS memory.*' },
2639 'smsg': 'PM: Saving platform NVS memory.*',
2640 'emsg': 'Disabling non-boot CPUs .*' },
2647 for line
in data
.dmesgtext
:
2648 # -- preprocessing --
2649 # parse each dmesg line into the time and message
2650 m
= re
.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line
)
2652 val
= m
.group('ktime')
2656 doWarning('INVALID DMESG LINE: '+\
2657 line
.replace('\n', ''), 'dmesg')
2659 msg
= m
.group('msg')
2660 # initialize data start to first line time
2662 data
.setStart(ktime
)
2667 # hack for determining resume_machine end for freeze
2668 if(not sysvals
.usetraceevents
and sysvals
.suspendmode
== 'freeze' \
2669 and phase
== 'resume_machine' and \
2670 re
.match('calling (?P<f>.*)\+ @ .*, parent: .*', msg
)):
2671 data
.dmesg
['resume_machine']['end'] = ktime
2672 phase
= 'resume_noirq'
2673 data
.dmesg
[phase
]['start'] = ktime
2675 # -- phase changes --
2677 if(re
.match(dm
['suspend_prepare'], msg
)):
2678 phase
= 'suspend_prepare'
2679 data
.dmesg
[phase
]['start'] = ktime
2680 data
.setStart(ktime
)
2682 elif(re
.match(dm
['suspend'], msg
)):
2683 data
.dmesg
['suspend_prepare']['end'] = ktime
2685 data
.dmesg
[phase
]['start'] = ktime
2686 # suspend_late start
2687 elif(re
.match(dm
['suspend_late'], msg
)):
2688 data
.dmesg
['suspend']['end'] = ktime
2689 phase
= 'suspend_late'
2690 data
.dmesg
[phase
]['start'] = ktime
2691 # suspend_noirq start
2692 elif(re
.match(dm
['suspend_noirq'], msg
)):
2693 data
.dmesg
['suspend_late']['end'] = ktime
2694 phase
= 'suspend_noirq'
2695 data
.dmesg
[phase
]['start'] = ktime
2696 # suspend_machine start
2697 elif(re
.match(dm
['suspend_machine'], msg
)):
2698 data
.dmesg
['suspend_noirq']['end'] = ktime
2699 phase
= 'suspend_machine'
2700 data
.dmesg
[phase
]['start'] = ktime
2701 # resume_machine start
2702 elif(re
.match(dm
['resume_machine'], msg
)):
2703 if(sysvals
.suspendmode
in ['freeze', 'standby']):
2704 data
.tSuspended
= prevktime
2705 data
.dmesg
['suspend_machine']['end'] = prevktime
2707 data
.tSuspended
= ktime
2708 data
.dmesg
['suspend_machine']['end'] = ktime
2709 phase
= 'resume_machine'
2710 data
.tResumed
= ktime
2711 data
.tLow
= data
.tResumed
- data
.tSuspended
2712 data
.dmesg
[phase
]['start'] = ktime
2713 # resume_noirq start
2714 elif(re
.match(dm
['resume_noirq'], msg
)):
2715 data
.dmesg
['resume_machine']['end'] = ktime
2716 phase
= 'resume_noirq'
2717 data
.dmesg
[phase
]['start'] = ktime
2718 # resume_early start
2719 elif(re
.match(dm
['resume_early'], msg
)):
2720 data
.dmesg
['resume_noirq']['end'] = ktime
2721 phase
= 'resume_early'
2722 data
.dmesg
[phase
]['start'] = ktime
2724 elif(re
.match(dm
['resume'], msg
)):
2725 data
.dmesg
['resume_early']['end'] = ktime
2727 data
.dmesg
[phase
]['start'] = ktime
2728 # resume complete start
2729 elif(re
.match(dm
['resume_complete'], msg
)):
2730 data
.dmesg
['resume']['end'] = ktime
2731 phase
= 'resume_complete'
2732 data
.dmesg
[phase
]['start'] = ktime
2734 elif(re
.match(dm
['post_resume'], msg
)):
2735 data
.dmesg
['resume_complete']['end'] = ktime
2737 phase
= 'post_resume'
2740 # -- device callbacks --
2741 if(phase
in data
.phases
):
2743 if(re
.match('calling (?P<f>.*)\+ @ .*, parent: .*', msg
)):
2744 sm
= re
.match('calling (?P<f>.*)\+ @ '+\
2745 '(?P<n>.*), parent: (?P<p>.*)', msg
);
2750 data
.newAction(phase
, f
, int(n
), p
, ktime
, -1, '')
2751 # device init return
2752 elif(re
.match('call (?P<f>.*)\+ returned .* after '+\
2753 '(?P<t>.*) usecs', msg
)):
2754 sm
= re
.match('call (?P<f>.*)\+ returned .* after '+\
2755 '(?P<t>.*) usecs(?P<a>.*)', msg
);
2758 list = data
.dmesg
[phase
]['list']
2761 dev
['length'] = int(t
)
2764 # -- non-devicecallback actions --
2765 # if trace events are not available, these are better than nothing
2766 if(not sysvals
.usetraceevents
):
2767 # look for known actions
2769 if(re
.match(at
[a
]['smsg'], msg
)):
2770 if(a
not in actions
):
2772 actions
[a
].append({'begin': ktime
, 'end': ktime
})
2773 if(re
.match(at
[a
]['emsg'], msg
)):
2775 actions
[a
][-1]['end'] = ktime
2776 # now look for CPU on/off events
2777 if(re
.match('Disabling non-boot CPUs .*', msg
)):
2778 # start of first cpu suspend
2780 elif(re
.match('Enabling non-boot CPUs .*', msg
)):
2781 # start of first cpu resume
2783 elif(re
.match('smpboot: CPU (?P<cpu>[0-9]*) is now offline', msg
)):
2784 # end of a cpu suspend, start of the next
2785 m
= re
.match('smpboot: CPU (?P<cpu>[0-9]*) is now offline', msg
)
2786 cpu
= 'CPU'+m
.group('cpu')
2787 if(cpu
not in actions
):
2789 actions
[cpu
].append({'begin': cpu_start
, 'end': ktime
})
2791 elif(re
.match('CPU(?P<cpu>[0-9]*) is up', msg
)):
2792 # end of a cpu resume, start of the next
2793 m
= re
.match('CPU(?P<cpu>[0-9]*) is up', msg
)
2794 cpu
= 'CPU'+m
.group('cpu')
2795 if(cpu
not in actions
):
2797 actions
[cpu
].append({'begin': cpu_start
, 'end': ktime
})
2801 # fill in any missing phases
2803 for p
in data
.phases
:
2804 if(data
.dmesg
[p
]['start'] < 0 and data
.dmesg
[p
]['end'] < 0):
2805 print('WARNING: phase "%s" is missing, something went wrong!' % p
)
2806 print(' In %s, this dmesg line denotes the start of %s:' % \
2807 (sysvals
.suspendmode
, p
))
2808 print(' "%s"' % dm
[p
])
2809 if(data
.dmesg
[p
]['start'] < 0):
2810 data
.dmesg
[p
]['start'] = data
.dmesg
[lp
]['end']
2811 if(p
== 'resume_machine'):
2812 data
.tSuspended
= data
.dmesg
[lp
]['end']
2813 data
.tResumed
= data
.dmesg
[lp
]['end']
2815 if(data
.dmesg
[p
]['end'] < 0):
2816 data
.dmesg
[p
]['end'] = data
.dmesg
[p
]['start']
2819 # fill in any actions we've found
2820 for name
in actions
:
2821 for event
in actions
[name
]:
2822 data
.newActionGlobal(name
, event
['begin'], event
['end'])
2824 if(sysvals
.verbose
):
2826 if(len(sysvals
.devicefilter
) > 0):
2827 data
.deviceFilter(sysvals
.devicefilter
)
2828 data
.fixupInitcallsThatDidntReturn()
2831 # Function: createHTMLSummarySimple
2833 # Create summary html file for a series of tests
2835 # testruns: array of Data objects from parseTraceLog
2836 def createHTMLSummarySimple(testruns
, htmlfile
):
2839 # print out the basic summary of all the tests
2840 hf
= open(htmlfile
, 'w')
2842 # write the html header first (html head, css code, up to body start)
2843 html
= '<!DOCTYPE html>\n<html>\n<head>\n\
2844 <meta http-equiv="content-type" content="text/html; charset=UTF-8">\n\
2845 <title>AnalyzeSuspend Summary</title>\n\
2846 <style type=\'text/css\'>\n\
2847 body {overflow-y: scroll;}\n\
2848 .stamp {width: 100%;text-align:center;background-color:#495E09;line-height:30px;color:white;font: 25px Arial;}\n\
2849 table {width:100%;border-collapse: collapse;}\n\
2850 .summary {font: 22px Arial;border:1px solid;}\n\
2851 th {border: 1px solid black;background-color:#A7C942;color:white;}\n\
2852 td {text-align: center;}\n\
2853 tr.alt td {background-color:#EAF2D3;}\n\
2854 tr.avg td {background-color:#BDE34C;}\n\
2855 a:link {color: #90B521;}\n\
2856 a:visited {color: #495E09;}\n\
2857 a:hover {color: #B1DF28;}\n\
2858 a:active {color: #FFFFFF;}\n\
2859 </style>\n</head>\n<body>\n'
2862 count
= len(testruns
)
2863 headline_stamp
= '<div class="stamp">{0} {1} {2} {3} ({4} tests)</div>\n'
2864 html
+= headline_stamp
.format(sysvals
.stamp
['host'],
2865 sysvals
.stamp
['kernel'], sysvals
.stamp
['mode'],
2866 sysvals
.stamp
['time'], count
)
2868 # check to see if all the tests have the same value
2869 stampcolumns
= False
2870 for data
in testruns
:
2871 if diffStamp(sysvals
.stamp
, data
.stamp
):
2875 th
= '\t<th>{0}</th>\n'
2876 td
= '\t<td>{0}</td>\n'
2877 tdlink
= '\t<td><a href="{0}">Click Here</a></td>\n'
2880 html
+= '<table class="summary">\n<tr>\n'
2881 html
+= th
.format("Test #")
2883 html
+= th
.format("Hostname")
2884 html
+= th
.format("Kernel Version")
2885 html
+= th
.format("Suspend Mode")
2886 html
+= th
.format("Test Time")
2887 html
+= th
.format("Suspend Time")
2888 html
+= th
.format("Resume Time")
2889 html
+= th
.format("Detail")
2892 # test data, 1 row per test
2896 for data
in testruns
:
2897 # data.end is the end of post_resume
2898 resumeEnd
= data
.dmesg
['resume_complete']['end']
2900 html
+= '<tr class="alt">\n'
2905 html
+= td
.format("test %d" % num
)
2910 if('host' in data
.stamp
):
2911 val
= data
.stamp
['host']
2912 html
+= td
.format(val
)
2915 if('kernel' in data
.stamp
):
2916 val
= data
.stamp
['kernel']
2917 html
+= td
.format(val
)
2920 if('mode' in data
.stamp
):
2921 val
= data
.stamp
['mode']
2922 html
+= td
.format(val
)
2925 if('time' in data
.stamp
):
2926 val
= data
.stamp
['time']
2927 html
+= td
.format(val
)
2929 sTime
= (data
.tSuspended
- data
.start
)*1000
2931 html
+= td
.format("%3.3f ms" % sTime
)
2933 rTime
= (resumeEnd
- data
.tResumed
)*1000
2935 html
+= td
.format("%3.3f ms" % rTime
)
2936 # link to the output html
2937 html
+= tdlink
.format(data
.outfile
)
2941 # last line: test average
2945 html
+= '<tr class="avg">\n'
2946 html
+= td
.format('Average') # name
2948 html
+= td
.format('') # host
2949 html
+= td
.format('') # kernel
2950 html
+= td
.format('') # mode
2951 html
+= td
.format('') # time
2952 html
+= td
.format("%3.3f ms" % sTimeAvg
) # suspend time
2953 html
+= td
.format("%3.3f ms" % rTimeAvg
) # resume time
2954 html
+= td
.format('') # output link
2957 # flush the data to file
2958 hf
.write(html
+'</table>\n')
2959 hf
.write('</body>\n</html>\n')
2965 'freeze': 'Freeze (S0)',
2966 'standby': 'Standby (S1)',
2967 'mem': 'Suspend (S3)',
2968 'disk': 'Hibernate (S4)'
2970 kernel
= sysvals
.stamp
['kernel']
2971 host
= sysvals
.hostname
[0].upper()+sysvals
.hostname
[1:]
2972 mode
= sysvals
.suspendmode
2973 if sysvals
.suspendmode
in modename
:
2974 mode
= modename
[sysvals
.suspendmode
]
2975 return host
+' '+mode
+' '+kernel
2979 if value
< 10 or value
> 19:
2982 elif value
% 10 == 2:
2984 elif value
% 10 == 3:
2986 return '%d%s' % (value
, suffix
)
2988 # Function: createHTML
2990 # Create the output html file from the resident test data
2992 # testruns: array of Data objects from parseKernelLog or parseTraceLog
2994 # True if the html file was created, false if it failed
2995 def createHTML(testruns
):
2998 if len(testruns
) < 1:
2999 print('ERROR: Not enough test data to build a timeline')
3002 for data
in testruns
:
3003 data
.normalizeTime(testruns
[-1].tSuspended
)
3005 x2changes
= ['', 'absolute']
3006 if len(testruns
) > 1:
3007 x2changes
= ['1', 'relative']
3008 # html function templates
3009 headline_version
= '<div class="version"><a href="https://01.org/suspendresume">AnalyzeSuspend v%s</a></div>' % sysvals
.version
3010 headline_stamp
= '<div class="stamp">{0} {1} {2} {3}</div>\n'
3011 html_devlist1
= '<button id="devlist1" class="devlist" style="float:left;">Device Detail%s</button>' % x2changes
[0]
3012 html_zoombox
= '<center><button id="zoomin">ZOOM IN</button><button id="zoomout">ZOOM OUT</button><button id="zoomdef">ZOOM 1:1</button></center>\n'
3013 html_devlist2
= '<button id="devlist2" class="devlist" style="float:right;">Device Detail2</button>\n'
3014 html_timeline
= '<div id="dmesgzoombox" class="zoombox">\n<div id="{0}" class="timeline" style="height:{1}px">\n'
3015 html_tblock
= '<div id="block{0}" class="tblock" style="left:{1}%;width:{2}%;">\n'
3016 html_device
= '<div id="{0}" title="{1}" class="thread{7}" style="left:{2}%;top:{3}px;height:{4}px;width:{5}%;{8}">{6}</div>\n'
3017 html_traceevent
= '<div title="{0}" class="traceevent" style="left:{1}%;top:{2}px;height:{3}px;width:{4}%;line-height:{3}px;">{5}</div>\n'
3018 html_phase
= '<div class="phase" style="left:{0}%;width:{1}%;top:{2}px;height:{3}px;background-color:{4}">{5}</div>\n'
3019 html_phaselet
= '<div id="{0}" class="phaselet" style="left:{1}%;width:{2}%;background-color:{3}"></div>\n'
3020 html_legend
= '<div id="p{3}" class="square" style="left:{0}%;background-color:{1}"> {2}</div>\n'
3021 html_timetotal
= '<table class="time1">\n<tr>'\
3022 '<td class="green">{2} Suspend Time: <b>{0} ms</b></td>'\
3023 '<td class="yellow">{2} Resume Time: <b>{1} ms</b></td>'\
3025 html_timetotal2
= '<table class="time1">\n<tr>'\
3026 '<td class="green">{3} Suspend Time: <b>{0} ms</b></td>'\
3027 '<td class="gray">'+sysvals
.suspendmode
+' time: <b>{1} ms</b></td>'\
3028 '<td class="yellow">{3} Resume Time: <b>{2} ms</b></td>'\
3030 html_timetotal3
= '<table class="time1">\n<tr>'\
3031 '<td class="green">Execution Time: <b>{0} ms</b></td>'\
3032 '<td class="yellow">Command: <b>{1}</b></td>'\
3034 html_timegroups
= '<table class="time2">\n<tr>'\
3035 '<td class="green">{4}Kernel Suspend: {0} ms</td>'\
3036 '<td class="purple">{4}Firmware Suspend: {1} ms</td>'\
3037 '<td class="purple">{4}Firmware Resume: {2} ms</td>'\
3038 '<td class="yellow">{4}Kernel Resume: {3} ms</td>'\
3041 # html format variables
3045 hoverZ
= 'z-index:10;'
3047 if sysvals
.usedevsrc
:
3051 vprint('Creating Device Timeline...')
3053 devtl
= Timeline(rowheight
)
3055 # Generate the header for this timeline
3056 for data
in testruns
:
3057 tTotal
= data
.end
- data
.start
3058 tEnd
= data
.dmesg
['resume_complete']['end']
3060 print('ERROR: No timeline data')
3063 low_time
= '%.0f'%(data
.tLow
*1000)
3064 if sysvals
.suspendmode
== 'command':
3065 run_time
= '%.0f'%((data
.end
-data
.start
)*1000)
3066 if sysvals
.testcommand
:
3067 testdesc
= sysvals
.testcommand
3069 testdesc
= 'unknown'
3070 if(len(testruns
) > 1):
3071 testdesc
= ordinal(data
.testnumber
+1)+' '+testdesc
3072 thtml
= html_timetotal3
.format(run_time
, testdesc
)
3073 devtl
.html
['header'] += thtml
3075 suspend_time
= '%.0f'%((data
.tSuspended
-data
.start
)*1000 + \
3076 (data
.fwSuspend
/1000000.0))
3077 resume_time
= '%.0f'%((tEnd
-data
.tSuspended
)*1000 + \
3078 (data
.fwResume
/1000000.0))
3081 if(len(testruns
) > 1):
3082 testdesc1
= testdesc2
= ordinal(data
.testnumber
+1)
3085 thtml
= html_timetotal
.format(suspend_time
, \
3086 resume_time
, testdesc1
)
3088 thtml
= html_timetotal2
.format(suspend_time
, low_time
, \
3089 resume_time
, testdesc1
)
3090 devtl
.html
['header'] += thtml
3091 sktime
= '%.3f'%((data
.dmesg
['suspend_machine']['end'] - \
3092 data
.getStart())*1000)
3093 sftime
= '%.3f'%(data
.fwSuspend
/ 1000000.0)
3094 rftime
= '%.3f'%(data
.fwResume
/ 1000000.0)
3095 rktime
= '%.3f'%((data
.dmesg
['resume_complete']['end'] - \
3096 data
.dmesg
['resume_machine']['start'])*1000)
3097 devtl
.html
['header'] += html_timegroups
.format(sktime
, \
3098 sftime
, rftime
, rktime
, testdesc2
)
3100 suspend_time
= '%.0f'%((data
.tSuspended
-data
.start
)*1000)
3101 resume_time
= '%.0f'%((tEnd
-data
.tSuspended
)*1000)
3103 if(len(testruns
) > 1):
3104 testdesc
= ordinal(data
.testnumber
+1)+' '+testdesc
3106 thtml
= html_timetotal
.format(suspend_time
, \
3107 resume_time
, testdesc
)
3109 thtml
= html_timetotal2
.format(suspend_time
, low_time
, \
3110 resume_time
, testdesc
)
3111 devtl
.html
['header'] += thtml
3113 # time scale for potentially multiple datasets
3114 t0
= testruns
[0].start
3115 tMax
= testruns
[-1].end
3116 tSuspended
= testruns
[-1].tSuspended
3119 # determine the maximum number of rows we need to draw
3120 for data
in testruns
:
3121 data
.selectTimelineDevices('%f', tTotal
, sysvals
.mindevlen
)
3122 for group
in data
.devicegroups
:
3125 for devname
in data
.tdevlist
[phase
]:
3126 devlist
.append((phase
,devname
))
3127 devtl
.getPhaseRows(data
.dmesg
, devlist
)
3128 devtl
.calcTotalRows()
3130 # create bounding box, add buttons
3131 if sysvals
.suspendmode
!= 'command':
3132 devtl
.html
['timeline'] += html_devlist1
3133 if len(testruns
) > 1:
3134 devtl
.html
['timeline'] += html_devlist2
3135 devtl
.html
['timeline'] += html_zoombox
3136 devtl
.html
['timeline'] += html_timeline
.format('dmesg', devtl
.height
)
3138 # draw the full timeline
3139 phases
= {'suspend':[],'resume':[]}
3140 for phase
in data
.dmesg
:
3141 if 'resume' in phase
:
3142 phases
['resume'].append(phase
)
3144 phases
['suspend'].append(phase
)
3146 # draw each test run chronologically
3147 for data
in testruns
:
3148 # if nore than one test, draw a block to represent user mode
3149 if(data
.testnumber
> 0):
3150 m0
= testruns
[data
.testnumber
-1].end
3151 mMax
= testruns
[data
.testnumber
].start
3153 name
= 'usermode%d' % data
.testnumber
3154 top
= '%d' % devtl
.scaleH
3155 left
= '%f' % (((m0
-t0
)*100.0)/tTotal
)
3156 width
= '%f' % ((mTotal
*100.0)/tTotal
)
3157 title
= 'user mode (%0.3f ms) ' % (mTotal
*1000)
3158 devtl
.html
['timeline'] += html_device
.format(name
, \
3159 title
, left
, top
, '%d'%devtl
.bodyH
, width
, '', '', '')
3160 # now draw the actual timeline blocks
3162 # draw suspend and resume blocks separately
3163 bname
= '%s%d' % (dir[0], data
.testnumber
)
3164 if dir == 'suspend':
3165 m0
= testruns
[data
.testnumber
].start
3166 mMax
= testruns
[data
.testnumber
].tSuspended
3168 left
= '%f' % (((m0
-t0
)*100.0)/tTotal
)
3170 m0
= testruns
[data
.testnumber
].tSuspended
3171 mMax
= testruns
[data
.testnumber
].end
3173 left
= '%f' % ((((m0
-t0
)*100.0)+sysvals
.srgap
/2)/tTotal
)
3174 # if a timeline block is 0 length, skip altogether
3177 width
= '%f' % (((mTotal
*100.0)-sysvals
.srgap
/2)/tTotal
)
3178 devtl
.html
['timeline'] += html_tblock
.format(bname
, left
, width
)
3179 for b
in sorted(phases
[dir]):
3180 # draw the phase color background
3181 phase
= data
.dmesg
[b
]
3182 length
= phase
['end']-phase
['start']
3183 left
= '%f' % (((phase
['start']-m0
)*100.0)/mTotal
)
3184 width
= '%f' % ((length
*100.0)/mTotal
)
3185 devtl
.html
['timeline'] += html_phase
.format(left
, width
, \
3186 '%.3f'%devtl
.scaleH
, '%.3f'%devtl
.bodyH
, \
3187 data
.dmesg
[b
]['color'], '')
3188 # draw the devices for this phase
3189 phaselist
= data
.dmesg
[b
]['list']
3190 for d
in data
.tdevlist
[b
]:
3197 if 'htmlclass' in dev
:
3198 xtraclass
= dev
['htmlclass']
3199 xtrainfo
= dev
['htmlclass']
3201 xtrastyle
= 'background-color:%s;' % dev
['color']
3202 if(d
in sysvals
.devprops
):
3203 name
= sysvals
.devprops
[d
].altName(d
)
3204 xtraclass
= sysvals
.devprops
[d
].xtraClass()
3205 xtrainfo
= sysvals
.devprops
[d
].xtraInfo()
3206 if('drv' in dev
and dev
['drv']):
3207 drv
= ' {%s}' % dev
['drv']
3208 rowheight
= devtl
.phaseRowHeight(b
, dev
['row'])
3209 rowtop
= devtl
.phaseRowTop(b
, dev
['row'])
3210 top
= '%.3f' % (rowtop
+ devtl
.scaleH
)
3211 left
= '%f' % (((dev
['start']-m0
)*100)/mTotal
)
3212 width
= '%f' % (((dev
['end']-dev
['start'])*100)/mTotal
)
3213 length
= ' (%0.3f ms) ' % ((dev
['end']-dev
['start'])*1000)
3214 if sysvals
.suspendmode
== 'command':
3215 title
= name
+drv
+xtrainfo
+length
+'cmdexec'
3217 title
= name
+drv
+xtrainfo
+length
+b
3218 devtl
.html
['timeline'] += html_device
.format(dev
['id'], \
3219 title
, left
, top
, '%.3f'%rowheight
, width
, \
3220 d
+drv
, xtraclass
, xtrastyle
)
3221 if('src' not in dev
):
3223 # draw any trace events for this device
3224 vprint('Debug trace events found for device %s' % d
)
3225 vprint('%20s %20s %10s %8s' % ('title', \
3226 'name', 'time(ms)', 'length(ms)'))
3227 for e
in dev
['src']:
3228 vprint('%20s %20s %10.3f %8.3f' % (e
.title
, \
3229 e
.text
, e
.time
*1000, e
.length
*1000))
3231 top
= '%.3f' % (rowtop
+ devtl
.scaleH
+ (e
.row
*devtl
.rowH
))
3232 left
= '%f' % (((e
.time
-m0
)*100)/mTotal
)
3233 width
= '%f' % (e
.length
*100/mTotal
)
3234 color
= 'rgba(204,204,204,0.5)'
3235 devtl
.html
['timeline'] += \
3236 html_traceevent
.format(e
.title
, \
3237 left
, top
, '%.3f'%height
, \
3239 # draw the time scale, try to make the number of labels readable
3240 devtl
.html
['timeline'] += devtl
.createTimeScale(m0
, mMax
, tTotal
, dir)
3241 devtl
.html
['timeline'] += '</div>\n'
3243 # timeline is finished
3244 devtl
.html
['timeline'] += '</div>\n</div>\n'
3246 # draw a legend which describes the phases by color
3247 if sysvals
.suspendmode
!= 'command':
3249 devtl
.html
['legend'] = '<div class="legend">\n'
3250 pdelta
= 100.0/len(data
.phases
)
3251 pmargin
= pdelta
/ 4.0
3252 for phase
in data
.phases
:
3253 tmp
= phase
.split('_')
3257 order
= '%.2f' % ((data
.dmesg
[phase
]['order'] * pdelta
) + pmargin
)
3258 name
= string
.replace(phase
, '_', ' ')
3259 devtl
.html
['legend'] += html_legend
.format(order
, \
3260 data
.dmesg
[phase
]['color'], name
, id)
3261 devtl
.html
['legend'] += '</div>\n'
3263 hf
= open(sysvals
.htmlfile
, 'w')
3265 if not sysvals
.cgexp
:
3267 cgnchk
= 'not(:checked)'
3269 cgchk
= 'not(:checked)'
3272 # write the html header first (html head, css code, up to body start)
3273 html_header
= '<!DOCTYPE html>\n<html>\n<head>\n\
3274 <meta http-equiv="content-type" content="text/html; charset=UTF-8">\n\
3275 <title>'+htmlTitle()+'</title>\n\
3276 <style type=\'text/css\'>\n\
3277 body {overflow-y:scroll;}\n\
3278 .stamp {width:100%;text-align:center;background-color:gray;line-height:30px;color:white;font:25px Arial;}\n\
3279 .callgraph {margin-top:30px;box-shadow:5px 5px 20px black;}\n\
3280 .callgraph article * {padding-left:28px;}\n\
3281 h1 {color:black;font:bold 30px Times;}\n\
3282 t0 {color:black;font:bold 30px Times;}\n\
3283 t1 {color:black;font:30px Times;}\n\
3284 t2 {color:black;font:25px Times;}\n\
3285 t3 {color:black;font:20px Times;white-space:nowrap;}\n\
3286 t4 {color:black;font:bold 30px Times;line-height:60px;white-space:nowrap;}\n\
3287 cS {color:blue;font:bold 11px Times;}\n\
3288 cR {color:red;font:bold 11px Times;}\n\
3289 table {width:100%;}\n\
3290 .gray {background-color:rgba(80,80,80,0.1);}\n\
3291 .green {background-color:rgba(204,255,204,0.4);}\n\
3292 .purple {background-color:rgba(128,0,128,0.2);}\n\
3293 .yellow {background-color:rgba(255,255,204,0.4);}\n\
3294 .time1 {font:22px Arial;border:1px solid;}\n\
3295 .time2 {font:15px Arial;border-bottom:1px solid;border-left:1px solid;border-right:1px solid;}\n\
3296 td {text-align:center;}\n\
3297 r {color:#500000;font:15px Tahoma;}\n\
3298 n {color:#505050;font:15px Tahoma;}\n\
3299 .tdhl {color:red;}\n\
3300 .hide {display:none;}\n\
3301 .pf {display:none;}\n\
3302 .pf:'+cgchk
+' + 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\
3303 .pf:'+cgnchk
+' ~ 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\
3304 .pf:'+cgchk
+' ~ *:not(:nth-child(2)) {display:none;}\n\
3305 .zoombox {position:relative;width:100%;overflow-x:scroll;}\n\
3306 .timeline {position:relative;font-size:14px;cursor:pointer;width:100%; overflow:hidden;background:linear-gradient(#cccccc, white);}\n\
3307 .thread {position:absolute;height:0%;overflow:hidden;line-height:'+devtextH
+';font-size:'+devtextS
+';border:1px solid;text-align:center;white-space:nowrap;background-color:rgba(204,204,204,0.5);}\n\
3308 .thread.sync {background-color:'+sysvals
.synccolor
+';}\n\
3309 .thread.bg {background-color:'+sysvals
.kprobecolor
+';}\n\
3310 .thread:hover {background-color:white;border:1px solid red;'+hoverZ
+'}\n\
3311 .hover {background-color:white;border:1px solid red;'+hoverZ
+'}\n\
3312 .hover.sync {background-color:white;}\n\
3313 .hover.bg {background-color:white;}\n\
3314 .traceevent {position:absolute;font-size:10px;overflow:hidden;color:black;text-align:center;white-space:nowrap;border-radius:5px;border:1px solid black;background:linear-gradient(to bottom right,rgba(204,204,204,1),rgba(150,150,150,1));}\n\
3315 .traceevent:hover {background:white;}\n\
3316 .phase {position:absolute;overflow:hidden;border:0px;text-align:center;}\n\
3317 .phaselet {position:absolute;overflow:hidden;border:0px;text-align:center;height:100px;font-size:24px;}\n\
3318 .t {z-index:2;position:absolute;pointer-events:none;top:0%;height:100%;border-right:1px solid black;}\n\
3319 .legend {position:relative; width:100%; height:40px; text-align:center;margin-bottom:20px}\n\
3320 .legend .square {position:absolute;cursor:pointer;top:10px; width:0px;height:20px;border:1px solid;padding-left:20px;}\n\
3321 button {height:40px;width:200px;margin-bottom:20px;margin-top:20px;font-size:24px;}\n\
3322 .logbtn {position:relative;float:right;height:25px;width:50px;margin-top:3px;margin-bottom:0;font-size:10px;text-align:center;}\n\
3323 .devlist {position:'+x2changes
[1]+';width:190px;}\n\
3324 a:link {color:white;text-decoration:none;}\n\
3325 a:visited {color:white;}\n\
3326 a:hover {color:white;}\n\
3327 a:active {color:white;}\n\
3328 .version {position:relative;float:left;color:white;font-size:10px;line-height:30px;margin-left:10px;}\n\
3329 #devicedetail {height:100px;box-shadow:5px 5px 20px black;}\n\
3330 .tblock {position:absolute;height:100%;}\n\
3332 </style>\n</head>\n<body>\n'
3334 # no header or css if its embedded
3335 if(sysvals
.embedded
):
3336 hf
.write('pass True tSus %.3f tRes %.3f tLow %.3f fwvalid %s tSus %.3f tRes %.3f\n' %
3337 (data
.tSuspended
-data
.start
, data
.end
-data
.tSuspended
, data
.tLow
, data
.fwValid
, \
3338 data
.fwSuspend
/1000000, data
.fwResume
/1000000))
3340 hf
.write(html_header
)
3342 # write the test title and general info header
3343 if(sysvals
.stamp
['time'] != ""):
3344 hf
.write(headline_version
)
3345 if sysvals
.addlogs
and sysvals
.dmesgfile
:
3346 hf
.write('<button id="showdmesg" class="logbtn">dmesg</button>')
3347 if sysvals
.addlogs
and sysvals
.ftracefile
:
3348 hf
.write('<button id="showftrace" class="logbtn">ftrace</button>')
3349 hf
.write(headline_stamp
.format(sysvals
.stamp
['host'],
3350 sysvals
.stamp
['kernel'], sysvals
.stamp
['mode'], \
3351 sysvals
.stamp
['time']))
3353 # write the device timeline
3354 hf
.write(devtl
.html
['header'])
3355 hf
.write(devtl
.html
['timeline'])
3356 hf
.write(devtl
.html
['legend'])
3357 hf
.write('<div id="devicedetailtitle"></div>\n')
3358 hf
.write('<div id="devicedetail" style="display:none;">\n')
3359 # draw the colored boxes for the device detail section
3360 for data
in testruns
:
3361 hf
.write('<div id="devicedetail%d">\n' % data
.testnumber
)
3362 for b
in data
.phases
:
3363 phase
= data
.dmesg
[b
]
3364 length
= phase
['end']-phase
['start']
3365 left
= '%.3f' % (((phase
['start']-t0
)*100.0)/tTotal
)
3366 width
= '%.3f' % ((length
*100.0)/tTotal
)
3367 hf
.write(html_phaselet
.format(b
, left
, width
, \
3368 data
.dmesg
[b
]['color']))
3369 if sysvals
.suspendmode
== 'command':
3370 hf
.write(html_phaselet
.format('cmdexec', '0', '0', \
3371 data
.dmesg
['resume_complete']['color']))
3372 hf
.write('</div>\n')
3373 hf
.write('</div>\n')
3375 # write the ftrace data (callgraph)
3377 if(sysvals
.usecallgraph
and not sysvals
.embedded
):
3378 hf
.write('<section id="callgraphs" class="callgraph">\n')
3379 # write out the ftrace data converted to html
3380 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'
3381 html_func_start
= '<article>\n<input type="checkbox" class="pf" id="f{0}" checked/><label for="f{0}">{1} {2}</label>\n'
3382 html_func_end
= '</article>\n'
3383 html_func_leaf
= '<article>{0} {1}</article>\n'
3385 for p
in data
.phases
:
3386 list = data
.dmesg
[p
]['list']
3387 for devname
in data
.sortedDevices(p
):
3388 if('ftrace' not in list[devname
]):
3390 devid
= list[devname
]['id']
3391 cg
= list[devname
]['ftrace']
3392 clen
= (cg
.end
- cg
.start
) * 1000
3393 if clen
< sysvals
.mincglen
:
3395 fmt
= '<r>(%.3f ms @ '+sysvals
.timeformat
+' to '+sysvals
.timeformat
+')</r>'
3396 flen
= fmt
% (clen
, cg
.start
, cg
.end
)
3398 if(devname
in sysvals
.devprops
):
3399 name
= sysvals
.devprops
[devname
].altName(devname
)
3400 if sysvals
.suspendmode
== 'command':
3404 hf
.write(html_func_top
.format(devid
, data
.dmesg
[p
]['color'], \
3407 for line
in cg
.list:
3408 if(line
.length
< 0.000000001):
3411 fmt
= '<n>(%.3f ms @ '+sysvals
.timeformat
+')</n>'
3412 flen
= fmt
% (line
.length
*1000, line
.time
)
3413 if(line
.freturn
and line
.fcall
):
3414 hf
.write(html_func_leaf
.format(line
.name
, flen
))
3416 hf
.write(html_func_end
)
3418 hf
.write(html_func_start
.format(num
, line
.name
, flen
))
3420 hf
.write(html_func_end
)
3421 hf
.write('\n\n </section>\n')
3423 # add the dmesg log as a hidden div
3424 if sysvals
.addlogs
and sysvals
.dmesgfile
:
3425 hf
.write('<div id="dmesglog" style="display:none;">\n')
3426 lf
= open(sysvals
.dmesgfile
, 'r')
3430 hf
.write('</div>\n')
3431 # add the ftrace log as a hidden div
3432 if sysvals
.addlogs
and sysvals
.ftracefile
:
3433 hf
.write('<div id="ftracelog" style="display:none;">\n')
3434 lf
= open(sysvals
.ftracefile
, 'r')
3438 hf
.write('</div>\n')
3440 if(not sysvals
.embedded
):
3441 # write the footer and close
3442 addScriptCode(hf
, testruns
)
3443 hf
.write('</body>\n</html>\n')
3445 # embedded out will be loaded in a page, skip the js
3446 t0
= (testruns
[0].start
- testruns
[-1].tSuspended
) * 1000
3447 tMax
= (testruns
[-1].end
- testruns
[-1].tSuspended
) * 1000
3448 # add js code in a div entry for later evaluation
3449 detail
= 'var bounds = [%f,%f];\n' % (t0
, tMax
)
3450 detail
+= 'var devtable = [\n'
3451 for data
in testruns
:
3452 topo
= data
.deviceTopology()
3453 detail
+= '\t"%s",\n' % (topo
)
3455 hf
.write('<div id=customcode style=display:none>\n'+detail
+'</div>\n')
3459 # Function: addScriptCode
3461 # Adds the javascript code to the output html
3463 # hf: the open html file pointer
3464 # testruns: array of Data objects from parseKernelLog or parseTraceLog
3465 def addScriptCode(hf
, testruns
):
3466 t0
= testruns
[0].start
* 1000
3467 tMax
= testruns
[-1].end
* 1000
3468 # create an array in javascript memory with the device details
3469 detail
= ' var devtable = [];\n'
3470 for data
in testruns
:
3471 topo
= data
.deviceTopology()
3472 detail
+= ' devtable[%d] = "%s";\n' % (data
.testnumber
, topo
)
3473 detail
+= ' var bounds = [%f,%f];\n' % (t0
, tMax
)
3474 # add the code which will manipulate the data in the browser
3476 '<script type="text/javascript">\n'+detail
+\
3477 ' var resolution = -1;\n'\
3478 ' function redrawTimescale(t0, tMax, tS) {\n'\
3479 ' var rline = \'<div class="t" style="left:0;border-left:1px solid black;border-right:0;"><cR><-R</cR></div>\';\n'\
3480 ' var tTotal = tMax - t0;\n'\
3481 ' var list = document.getElementsByClassName("tblock");\n'\
3482 ' for (var i = 0; i < list.length; i++) {\n'\
3483 ' var timescale = list[i].getElementsByClassName("timescale")[0];\n'\
3484 ' var m0 = t0 + (tTotal*parseFloat(list[i].style.left)/100);\n'\
3485 ' var mTotal = tTotal*parseFloat(list[i].style.width)/100;\n'\
3486 ' var mMax = m0 + mTotal;\n'\
3487 ' var html = "";\n'\
3488 ' var divTotal = Math.floor(mTotal/tS) + 1;\n'\
3489 ' if(divTotal > 1000) continue;\n'\
3490 ' var divEdge = (mTotal - tS*(divTotal-1))*100/mTotal;\n'\
3491 ' var pos = 0.0, val = 0.0;\n'\
3492 ' for (var j = 0; j < divTotal; j++) {\n'\
3493 ' var htmlline = "";\n'\
3494 ' if(list[i].id[5] == "r") {\n'\
3495 ' pos = 100 - (((j)*tS*100)/mTotal);\n'\
3497 ' htmlline = \'<div class="t" style="right:\'+pos+\'%">\'+val+\'ms</div>\';\n'\
3499 ' htmlline = rline;\n'\
3501 ' pos = 100 - (((j)*tS*100)/mTotal) - divEdge;\n'\
3502 ' val = (j-divTotal+1)*tS;\n'\
3503 ' if(j == divTotal - 1)\n'\
3504 ' htmlline = \'<div class="t" style="right:\'+pos+\'%"><cS>S-></cS></div>\';\n'\
3506 ' htmlline = \'<div class="t" style="right:\'+pos+\'%">\'+val+\'ms</div>\';\n'\
3508 ' html += htmlline;\n'\
3510 ' timescale.innerHTML = html;\n'\
3513 ' function zoomTimeline() {\n'\
3514 ' var dmesg = document.getElementById("dmesg");\n'\
3515 ' var zoombox = document.getElementById("dmesgzoombox");\n'\
3516 ' var val = parseFloat(dmesg.style.width);\n'\
3517 ' var newval = 100;\n'\
3518 ' var sh = window.outerWidth / 2;\n'\
3519 ' if(this.id == "zoomin") {\n'\
3520 ' newval = val * 1.2;\n'\
3521 ' if(newval > 910034) newval = 910034;\n'\
3522 ' dmesg.style.width = newval+"%";\n'\
3523 ' zoombox.scrollLeft = ((zoombox.scrollLeft + sh) * newval / val) - sh;\n'\
3524 ' } else if (this.id == "zoomout") {\n'\
3525 ' newval = val / 1.2;\n'\
3526 ' if(newval < 100) newval = 100;\n'\
3527 ' dmesg.style.width = newval+"%";\n'\
3528 ' zoombox.scrollLeft = ((zoombox.scrollLeft + sh) * newval / val) - sh;\n'\
3530 ' zoombox.scrollLeft = 0;\n'\
3531 ' dmesg.style.width = "100%";\n'\
3533 ' var tS = [10000, 5000, 2000, 1000, 500, 200, 100, 50, 20, 10, 5, 2, 1];\n'\
3534 ' var t0 = bounds[0];\n'\
3535 ' var tMax = bounds[1];\n'\
3536 ' var tTotal = tMax - t0;\n'\
3537 ' var wTotal = tTotal * 100.0 / newval;\n'\
3538 ' var idx = 7*window.innerWidth/1100;\n'\
3539 ' for(var i = 0; (i < tS.length)&&((wTotal / tS[i]) < idx); i++);\n'\
3540 ' if(i >= tS.length) i = tS.length - 1;\n'\
3541 ' if(tS[i] == resolution) return;\n'\
3542 ' resolution = tS[i];\n'\
3543 ' redrawTimescale(t0, tMax, tS[i]);\n'\
3545 ' function deviceHover() {\n'\
3546 ' var name = this.title.slice(0, this.title.indexOf(" ("));\n'\
3547 ' var dmesg = document.getElementById("dmesg");\n'\
3548 ' var dev = dmesg.getElementsByClassName("thread");\n'\
3550 ' if(name.match("CPU_ON\[[0-9]*\]"))\n'\
3551 ' cpu = parseInt(name.slice(7));\n'\
3552 ' else if(name.match("CPU_OFF\[[0-9]*\]"))\n'\
3553 ' cpu = parseInt(name.slice(8));\n'\
3554 ' for (var i = 0; i < dev.length; i++) {\n'\
3555 ' dname = dev[i].title.slice(0, dev[i].title.indexOf(" ("));\n'\
3556 ' var cname = dev[i].className.slice(dev[i].className.indexOf("thread"));\n'\
3557 ' if((cpu >= 0 && dname.match("CPU_O[NF]*\\\[*"+cpu+"\\\]")) ||\n'\
3558 ' (name == dname))\n'\
3560 ' dev[i].className = "hover "+cname;\n'\
3562 ' dev[i].className = cname;\n'\
3566 ' function deviceUnhover() {\n'\
3567 ' var dmesg = document.getElementById("dmesg");\n'\
3568 ' var dev = dmesg.getElementsByClassName("thread");\n'\
3569 ' for (var i = 0; i < dev.length; i++) {\n'\
3570 ' dev[i].className = dev[i].className.slice(dev[i].className.indexOf("thread"));\n'\
3573 ' function deviceTitle(title, total, cpu) {\n'\
3574 ' var prefix = "Total";\n'\
3575 ' if(total.length > 3) {\n'\
3576 ' prefix = "Average";\n'\
3577 ' total[1] = (total[1]+total[3])/2;\n'\
3578 ' total[2] = (total[2]+total[4])/2;\n'\
3580 ' var devtitle = document.getElementById("devicedetailtitle");\n'\
3581 ' var name = title.slice(0, title.indexOf(" ("));\n'\
3582 ' if(cpu >= 0) name = "CPU"+cpu;\n'\
3583 ' var driver = "";\n'\
3584 ' var tS = "<t2>(</t2>";\n'\
3585 ' var tR = "<t2>)</t2>";\n'\
3586 ' if(total[1] > 0)\n'\
3587 ' tS = "<t2>("+prefix+" Suspend:</t2><t0> "+total[1].toFixed(3)+" ms</t0> ";\n'\
3588 ' if(total[2] > 0)\n'\
3589 ' tR = " <t2>"+prefix+" Resume:</t2><t0> "+total[2].toFixed(3)+" ms<t2>)</t2></t0>";\n'\
3590 ' var s = title.indexOf("{");\n'\
3591 ' var e = title.indexOf("}");\n'\
3592 ' if((s >= 0) && (e >= 0))\n'\
3593 ' driver = title.slice(s+1, e) + " <t1>@</t1> ";\n'\
3594 ' if(total[1] > 0 && total[2] > 0)\n'\
3595 ' devtitle.innerHTML = "<t0>"+driver+name+"</t0> "+tS+tR;\n'\
3597 ' devtitle.innerHTML = "<t0>"+title+"</t0>";\n'\
3600 ' function deviceDetail() {\n'\
3601 ' var devinfo = document.getElementById("devicedetail");\n'\
3602 ' devinfo.style.display = "block";\n'\
3603 ' var name = this.title.slice(0, this.title.indexOf(" ("));\n'\
3605 ' if(name.match("CPU_ON\[[0-9]*\]"))\n'\
3606 ' cpu = parseInt(name.slice(7));\n'\
3607 ' else if(name.match("CPU_OFF\[[0-9]*\]"))\n'\
3608 ' cpu = parseInt(name.slice(8));\n'\
3609 ' var dmesg = document.getElementById("dmesg");\n'\
3610 ' var dev = dmesg.getElementsByClassName("thread");\n'\
3611 ' var idlist = [];\n'\
3612 ' var pdata = [[]];\n'\
3613 ' if(document.getElementById("devicedetail1"))\n'\
3614 ' pdata = [[], []];\n'\
3615 ' var pd = pdata[0];\n'\
3616 ' var total = [0.0, 0.0, 0.0];\n'\
3617 ' for (var i = 0; i < dev.length; i++) {\n'\
3618 ' dname = dev[i].title.slice(0, dev[i].title.indexOf(" ("));\n'\
3619 ' if((cpu >= 0 && dname.match("CPU_O[NF]*\\\[*"+cpu+"\\\]")) ||\n'\
3620 ' (name == dname))\n'\
3622 ' idlist[idlist.length] = dev[i].id;\n'\
3624 ' if(dev[i].id[0] == "a") {\n'\
3625 ' pd = pdata[0];\n'\
3627 ' if(pdata.length == 1) pdata[1] = [];\n'\
3628 ' if(total.length == 3) total[3]=total[4]=0.0;\n'\
3629 ' pd = pdata[1];\n'\
3632 ' var info = dev[i].title.split(" ");\n'\
3633 ' var pname = info[info.length-1];\n'\
3634 ' pd[pname] = parseFloat(info[info.length-3].slice(1));\n'\
3635 ' total[0] += pd[pname];\n'\
3636 ' if(pname.indexOf("suspend") >= 0)\n'\
3637 ' total[tidx] += pd[pname];\n'\
3639 ' total[tidx+1] += pd[pname];\n'\
3642 ' var devname = deviceTitle(this.title, total, cpu);\n'\
3643 ' var left = 0.0;\n'\
3644 ' for (var t = 0; t < pdata.length; t++) {\n'\
3645 ' pd = pdata[t];\n'\
3646 ' devinfo = document.getElementById("devicedetail"+t);\n'\
3647 ' var phases = devinfo.getElementsByClassName("phaselet");\n'\
3648 ' for (var i = 0; i < phases.length; i++) {\n'\
3649 ' if(phases[i].id in pd) {\n'\
3650 ' var w = 100.0*pd[phases[i].id]/total[0];\n'\
3652 ' if(w < 8) fs = 4*w | 0;\n'\
3653 ' var fs2 = fs*3/4;\n'\
3654 ' phases[i].style.width = w+"%";\n'\
3655 ' phases[i].style.left = left+"%";\n'\
3656 ' phases[i].title = phases[i].id+" "+pd[phases[i].id]+" ms";\n'\
3658 ' var time = "<t4 style=\\"font-size:"+fs+"px\\">"+pd[phases[i].id]+" ms<br></t4>";\n'\
3659 ' var pname = "<t3 style=\\"font-size:"+fs2+"px\\">"+phases[i].id.replace("_", " ")+"</t3>";\n'\
3660 ' phases[i].innerHTML = time+pname;\n'\
3662 ' phases[i].style.width = "0%";\n'\
3663 ' phases[i].style.left = left+"%";\n'\
3667 ' var cglist = document.getElementById("callgraphs");\n'\
3668 ' if(!cglist) return;\n'\
3669 ' var cg = cglist.getElementsByClassName("atop");\n'\
3670 ' if(cg.length < 10) return;\n'\
3671 ' for (var i = 0; i < cg.length; i++) {\n'\
3672 ' if(idlist.indexOf(cg[i].id) >= 0) {\n'\
3673 ' cg[i].style.display = "block";\n'\
3675 ' cg[i].style.display = "none";\n'\
3679 ' function devListWindow(e) {\n'\
3680 ' var sx = e.clientX;\n'\
3681 ' if(sx > window.innerWidth - 440)\n'\
3682 ' sx = window.innerWidth - 440;\n'\
3683 ' var cfg="top="+e.screenY+", left="+sx+", width=440, height=720, scrollbars=yes";\n'\
3684 ' var win = window.open("", "_blank", cfg);\n'\
3685 ' if(window.chrome) win.moveBy(sx, 0);\n'\
3686 ' var html = "<title>"+e.target.innerHTML+"</title>"+\n'\
3687 ' "<style type=\\"text/css\\">"+\n'\
3688 ' " ul {list-style-type:circle;padding-left:10px;margin-left:10px;}"+\n'\
3690 ' var dt = devtable[0];\n'\
3691 ' if(e.target.id != "devlist1")\n'\
3692 ' dt = devtable[1];\n'\
3693 ' win.document.write(html+dt);\n'\
3695 ' function logWindow(e) {\n'\
3696 ' var name = e.target.id.slice(4);\n'\
3697 ' var win = window.open();\n'\
3698 ' var log = document.getElementById(name+"log");\n'\
3699 ' var title = "<title>"+document.title.split(" ")[0]+" "+name+" log</title>";\n'\
3700 ' win.document.write(title+"<pre>"+log.innerHTML+"</pre>");\n'\
3701 ' win.document.close();\n'\
3703 ' function onClickPhase(e) {\n'\
3705 ' window.addEventListener("resize", function () {zoomTimeline();});\n'\
3706 ' window.addEventListener("load", function () {\n'\
3707 ' var dmesg = document.getElementById("dmesg");\n'\
3708 ' dmesg.style.width = "100%"\n'\
3709 ' document.getElementById("zoomin").onclick = zoomTimeline;\n'\
3710 ' document.getElementById("zoomout").onclick = zoomTimeline;\n'\
3711 ' document.getElementById("zoomdef").onclick = zoomTimeline;\n'\
3712 ' var list = document.getElementsByClassName("square");\n'\
3713 ' for (var i = 0; i < list.length; i++)\n'\
3714 ' list[i].onclick = onClickPhase;\n'\
3715 ' var list = document.getElementsByClassName("logbtn");\n'\
3716 ' for (var i = 0; i < list.length; i++)\n'\
3717 ' list[i].onclick = logWindow;\n'\
3718 ' list = document.getElementsByClassName("devlist");\n'\
3719 ' for (var i = 0; i < list.length; i++)\n'\
3720 ' list[i].onclick = devListWindow;\n'\
3721 ' var dev = dmesg.getElementsByClassName("thread");\n'\
3722 ' for (var i = 0; i < dev.length; i++) {\n'\
3723 ' dev[i].onclick = deviceDetail;\n'\
3724 ' dev[i].onmouseover = deviceHover;\n'\
3725 ' dev[i].onmouseout = deviceUnhover;\n'\
3727 ' zoomTimeline();\n'\
3730 hf
.write(script_code
);
3732 # Function: executeSuspend
3734 # Execute system suspend through the sysfs interface, then copy the output
3735 # dmesg and ftrace files to the test output directory.
3736 def executeSuspend():
3739 t0
= time
.time()*1000
3742 # mark the start point in the kernel ring buffer just as we start
3745 if(sysvals
.usecallgraph
or sysvals
.usetraceevents
):
3746 print('START TRACING')
3747 sysvals
.fsetVal('1', 'tracing_on')
3748 # execute however many s/r runs requested
3749 for count
in range(1,sysvals
.execcount
+1):
3750 # if this is test2 and there's a delay, start here
3751 if(count
> 1 and sysvals
.x2delay
> 0):
3752 tN
= time
.time()*1000
3753 while (tN
- t0
) < sysvals
.x2delay
:
3754 tN
= time
.time()*1000
3757 if(sysvals
.usecallgraph
or sysvals
.usetraceevents
):
3758 sysvals
.fsetVal('SUSPEND START', 'trace_marker')
3759 if sysvals
.suspendmode
== 'command':
3760 print('COMMAND START')
3761 if(sysvals
.rtcwake
):
3762 print('will issue an rtcwake in %d seconds' % sysvals
.rtcwaketime
)
3763 sysvals
.rtcWakeAlarmOn()
3764 os
.system(sysvals
.testcommand
)
3766 if(sysvals
.rtcwake
):
3767 print('SUSPEND START')
3768 print('will autoresume in %d seconds' % sysvals
.rtcwaketime
)
3769 sysvals
.rtcWakeAlarmOn()
3771 print('SUSPEND START (press a key to resume)')
3772 pf
= open(sysvals
.powerfile
, 'w')
3773 pf
.write(sysvals
.suspendmode
)
3774 # execution will pause here
3779 t0
= time
.time()*1000
3780 if(sysvals
.rtcwake
):
3781 sysvals
.rtcWakeAlarmOff()
3782 # return from suspend
3783 print('RESUME COMPLETE')
3784 if(sysvals
.usecallgraph
or sysvals
.usetraceevents
):
3785 sysvals
.fsetVal('RESUME COMPLETE', 'trace_marker')
3786 if(sysvals
.suspendmode
== 'mem'):
3787 fwdata
.append(getFPDT(False))
3788 # look for post resume events after the last test run
3789 t
= sysvals
.postresumetime
3791 print('Waiting %d seconds for POST-RESUME trace events...' % t
)
3794 if(sysvals
.usecallgraph
or sysvals
.usetraceevents
):
3795 sysvals
.fsetVal('0', 'tracing_on')
3796 print('CAPTURING TRACE')
3797 writeDatafileHeader(sysvals
.ftracefile
, fwdata
)
3798 os
.system('cat '+tp
+'trace >> '+sysvals
.ftracefile
)
3799 sysvals
.fsetVal('', 'trace')
3801 # grab a copy of the dmesg output
3802 print('CAPTURING DMESG')
3803 writeDatafileHeader(sysvals
.dmesgfile
, fwdata
)
3806 def writeDatafileHeader(filename
, fwdata
):
3809 prt
= sysvals
.postresumetime
3810 fp
= open(filename
, 'a')
3811 fp
.write(sysvals
.teststamp
+'\n')
3812 if(sysvals
.suspendmode
== 'mem'):
3815 fp
.write('# fwsuspend %u fwresume %u\n' % (fw
[0], fw
[1]))
3817 fp
.write('# post resume time %u\n' % prt
)
3820 # Function: setUSBDevicesAuto
3822 # Set the autosuspend control parameter of all USB devices to auto
3823 # This can be dangerous, so use at your own risk, most devices are set
3824 # to always-on since the kernel cant determine if the device can
3825 # properly autosuspend
3826 def setUSBDevicesAuto():
3830 for dirname
, dirnames
, filenames
in os
.walk('/sys/devices'):
3831 if(re
.match('.*/usb[0-9]*.*', dirname
) and
3832 'idVendor' in filenames
and 'idProduct' in filenames
):
3833 os
.system('echo auto > %s/power/control' % dirname
)
3834 name
= dirname
.split('/')[-1]
3835 desc
= os
.popen('cat %s/product 2>/dev/null' % \
3836 dirname
).read().replace('\n', '')
3837 ctrl
= os
.popen('cat %s/power/control 2>/dev/null' % \
3838 dirname
).read().replace('\n', '')
3839 print('control is %s for %6s: %s' % (ctrl
, name
, desc
))
3843 # Print out an equivalent Y or N for a set of known parameter values
3845 # 'Y', 'N', or ' ' if the value is unknown
3847 yesvals
= ['auto', 'enabled', 'active', '1']
3848 novals
= ['on', 'disabled', 'suspended', 'forbidden', 'unsupported']
3857 # Print out a very concise time string in minutes and seconds
3859 # The time string, e.g. "1901m16s"
3867 s
= (ms
/ 1000) - (m
* 60)
3868 return '%3dm%2ds' % (m
, s
)
3870 # Function: detectUSB
3872 # Detect all the USB hosts and devices currently connected and add
3873 # a list of USB device names to sysvals for better timeline readability
3877 field
= {'idVendor':'', 'idProduct':'', 'product':'', 'speed':''}
3878 power
= {'async':'', 'autosuspend':'', 'autosuspend_delay_ms':'',
3879 'control':'', 'persist':'', 'runtime_enabled':'',
3880 'runtime_status':'', 'runtime_usage':'',
3881 'runtime_active_time':'',
3882 'runtime_suspended_time':'',
3883 'active_duration':'',
3884 'connected_duration':''}
3887 print('---------------------------------------------------------------------------------------------')
3888 print(' A = async/sync PM queue Y/N D = autosuspend delay (seconds)')
3889 print(' S = autosuspend Y/N rACTIVE = runtime active (min/sec)')
3890 print(' P = persist across suspend Y/N rSUSPEN = runtime suspend (min/sec)')
3891 print(' E = runtime suspend enabled/forbidden Y/N ACTIVE = active duration (min/sec)')
3892 print(' R = runtime status active/suspended Y/N CONNECT = connected duration (min/sec)')
3893 print(' U = runtime usage count')
3894 print('---------------------------------------------------------------------------------------------')
3895 print(' NAME ID DESCRIPTION SPEED A S P E R U D rACTIVE rSUSPEN ACTIVE CONNECT')
3896 print('---------------------------------------------------------------------------------------------')
3898 for dirname
, dirnames
, filenames
in os
.walk('/sys/devices'):
3899 if(re
.match('.*/usb[0-9]*.*', dirname
) and
3900 'idVendor' in filenames
and 'idProduct' in filenames
):
3902 field
[i
] = os
.popen('cat %s/%s 2>/dev/null' % \
3903 (dirname
, i
)).read().replace('\n', '')
3904 name
= dirname
.split('/')[-1]
3906 power
[i
] = os
.popen('cat %s/power/%s 2>/dev/null' % \
3907 (dirname
, i
)).read().replace('\n', '')
3908 if(re
.match('usb[0-9]*', name
)):
3909 first
= '%-8s' % name
3911 first
= '%8s' % name
3912 print('%s [%s:%s] %-20s %-4s %1s %1s %1s %1s %1s %1s %1s %s %s %s %s' % \
3913 (first
, field
['idVendor'], field
['idProduct'], \
3914 field
['product'][0:20], field
['speed'], \
3915 yesno(power
['async']), \
3916 yesno(power
['control']), \
3917 yesno(power
['persist']), \
3918 yesno(power
['runtime_enabled']), \
3919 yesno(power
['runtime_status']), \
3920 power
['runtime_usage'], \
3921 power
['autosuspend'], \
3922 ms2nice(power
['runtime_active_time']), \
3923 ms2nice(power
['runtime_suspended_time']), \
3924 ms2nice(power
['active_duration']), \
3925 ms2nice(power
['connected_duration'])))
3927 # Function: devProps
3929 # Retrieve a list of properties for all devices in the trace log
3930 def devProps(data
=0):
3935 idx
= data
.index(': ') + 2
3936 if idx
>= len(data
):
3938 devlist
= data
[idx
:].split(';')
3944 props
[dev
] = DevProps()
3945 props
[dev
].altname
= f
[1]
3947 props
[dev
].async = True
3949 props
[dev
].async = False
3950 sysvals
.devprops
= props
3951 if sysvals
.suspendmode
== 'command' and 'testcommandstring' in props
:
3952 sysvals
.testcommand
= props
['testcommandstring'].altname
3955 if(os
.path
.exists(sysvals
.ftracefile
) == False):
3956 doError('%s does not exist' % sysvals
.ftracefile
, False)
3958 # first get the list of devices we need properties for
3959 msghead
= 'Additional data added by AnalyzeSuspend'
3960 alreadystamped
= False
3962 tf
= open(sysvals
.ftracefile
, 'r')
3965 alreadystamped
= True
3967 # determine the trace data type (required for further parsing)
3968 m
= re
.match(sysvals
.tracertypefmt
, line
)
3970 tp
.setTracerType(m
.group('t'))
3972 # parse only valid lines, if this is not one move on
3973 m
= re
.match(tp
.ftrace_line_fmt
, line
)
3974 if(not m
or 'device_pm_callback_start' not in line
):
3976 m
= re
.match('.*: (?P<drv>.*) (?P<d>.*), parent: *(?P<p>.*), .*', m
.group('msg'));
3979 drv
, dev
, par
= m
.group('drv'), m
.group('d'), m
.group('p')
3980 if dev
not in props
:
3981 props
[dev
] = DevProps()
3984 if not alreadystamped
and sysvals
.suspendmode
== 'command':
3985 out
= '#\n# '+msghead
+'\n# Device Properties: '
3986 out
+= 'testcommandstring,%s,0;' % (sysvals
.testcommand
)
3987 with
open(sysvals
.ftracefile
, 'a') as fp
:
3989 sysvals
.devprops
= props
3992 # now get the syspath for each of our target devices
3993 for dirname
, dirnames
, filenames
in os
.walk('/sys/devices'):
3994 if(re
.match('.*/power', dirname
) and 'async' in filenames
):
3995 dev
= dirname
.split('/')[-2]
3996 if dev
in props
and (not props
[dev
].syspath
or len(dirname
) < len(props
[dev
].syspath
)):
3997 props
[dev
].syspath
= dirname
[:-6]
3999 # now fill in the properties for our target devices
4001 dirname
= props
[dev
].syspath
4002 if not dirname
or not os
.path
.exists(dirname
):
4004 with
open(dirname
+'/power/async') as fp
:
4006 props
[dev
].async = False
4007 if 'enabled' in text
:
4008 props
[dev
].async = True
4009 fields
= os
.listdir(dirname
)
4010 if 'product' in fields
:
4011 with
open(dirname
+'/product') as fp
:
4012 props
[dev
].altname
= fp
.read()
4013 elif 'name' in fields
:
4014 with
open(dirname
+'/name') as fp
:
4015 props
[dev
].altname
= fp
.read()
4016 elif 'model' in fields
:
4017 with
open(dirname
+'/model') as fp
:
4018 props
[dev
].altname
= fp
.read()
4019 elif 'description' in fields
:
4020 with
open(dirname
+'/description') as fp
:
4021 props
[dev
].altname
= fp
.read()
4022 elif 'id' in fields
:
4023 with
open(dirname
+'/id') as fp
:
4024 props
[dev
].altname
= fp
.read()
4025 elif 'idVendor' in fields
and 'idProduct' in fields
:
4027 with
open(dirname
+'/idVendor') as fp
:
4028 idv
= fp
.read().strip()
4029 with
open(dirname
+'/idProduct') as fp
:
4030 idp
= fp
.read().strip()
4031 props
[dev
].altname
= '%s:%s' % (idv
, idp
)
4033 if props
[dev
].altname
:
4034 out
= props
[dev
].altname
.strip().replace('\n', ' ')
4035 out
= out
.replace(',', ' ')
4036 out
= out
.replace(';', ' ')
4037 props
[dev
].altname
= out
4039 # and now write the data to the ftrace file
4040 if not alreadystamped
:
4041 out
= '#\n# '+msghead
+'\n# Device Properties: '
4042 for dev
in sorted(props
):
4043 out
+= props
[dev
].out(dev
)
4044 with
open(sysvals
.ftracefile
, 'a') as fp
:
4047 sysvals
.devprops
= props
4049 # Function: getModes
4051 # Determine the supported power modes on this system
4053 # A string list of the available modes
4057 if(os
.path
.exists(sysvals
.powerfile
)):
4058 fp
= open(sysvals
.powerfile
, 'r')
4059 modes
= string
.split(fp
.read())
4065 # Read the acpi bios tables and pull out FPDT, the firmware data
4067 # output: True to output the info to stdout, False otherwise
4068 def getFPDT(output
):
4072 rectype
[0] = 'Firmware Basic Boot Performance Record'
4073 rectype
[1] = 'S3 Performance Table Record'
4075 prectype
[0] = 'Basic S3 Resume Performance Record'
4076 prectype
[1] = 'Basic S3 Suspend Performance Record'
4079 if(not os
.path
.exists(sysvals
.fpdtpath
)):
4081 doError('file does not exist: %s' % sysvals
.fpdtpath
, False)
4083 if(not os
.access(sysvals
.fpdtpath
, os
.R_OK
)):
4085 doError('file is not readable: %s' % sysvals
.fpdtpath
, False)
4087 if(not os
.path
.exists(sysvals
.mempath
)):
4089 doError('file does not exist: %s' % sysvals
.mempath
, False)
4091 if(not os
.access(sysvals
.mempath
, os
.R_OK
)):
4093 doError('file is not readable: %s' % sysvals
.mempath
, False)
4096 fp
= open(sysvals
.fpdtpath
, 'rb')
4102 doError('Invalid FPDT table data, should '+\
4103 'be at least 36 bytes', False)
4106 table
= struct
.unpack('4sIBB6s8sI4sI', buf
[0:36])
4109 print('Firmware Performance Data Table (%s)' % table
[0])
4110 print(' Signature : %s' % table
[0])
4111 print(' Table Length : %u' % table
[1])
4112 print(' Revision : %u' % table
[2])
4113 print(' Checksum : 0x%x' % table
[3])
4114 print(' OEM ID : %s' % table
[4])
4115 print(' OEM Table ID : %s' % table
[5])
4116 print(' OEM Revision : %u' % table
[6])
4117 print(' Creator ID : %s' % table
[7])
4118 print(' Creator Revision : 0x%x' % table
[8])
4121 if(table
[0] != 'FPDT'):
4123 doError('Invalid FPDT table')
4130 fp
= open(sysvals
.mempath
, 'rb')
4131 while(i
< len(records
)):
4132 header
= struct
.unpack('HBB', records
[i
:i
+4])
4133 if(header
[0] not in rectype
):
4136 if(header
[1] != 16):
4139 addr
= struct
.unpack('Q', records
[i
+8:i
+16])[0]
4145 print('Bad address 0x%x in %s' % (addr
, sysvals
.mempath
))
4147 rechead
= struct
.unpack('4sI', first
)
4148 recdata
= fp
.read(rechead
[1]-8)
4149 if(rechead
[0] == 'FBPT'):
4150 record
= struct
.unpack('HBBIQQQQQ', recdata
)
4152 print('%s (%s)' % (rectype
[header
[0]], rechead
[0]))
4153 print(' Reset END : %u ns' % record
[4])
4154 print(' OS Loader LoadImage Start : %u ns' % record
[5])
4155 print(' OS Loader StartImage Start : %u ns' % record
[6])
4156 print(' ExitBootServices Entry : %u ns' % record
[7])
4157 print(' ExitBootServices Exit : %u ns' % record
[8])
4158 elif(rechead
[0] == 'S3PT'):
4160 print('%s (%s)' % (rectype
[header
[0]], rechead
[0]))
4162 while(j
< len(recdata
)):
4163 prechead
= struct
.unpack('HBB', recdata
[j
:j
+4])
4164 if(prechead
[0] not in prectype
):
4166 if(prechead
[0] == 0):
4167 record
= struct
.unpack('IIQQ', recdata
[j
:j
+prechead
[1]])
4168 fwData
[1] = record
[2]
4170 print(' %s' % prectype
[prechead
[0]])
4171 print(' Resume Count : %u' % \
4173 print(' FullResume : %u ns' % \
4175 print(' AverageResume : %u ns' % \
4177 elif(prechead
[0] == 1):
4178 record
= struct
.unpack('QQ', recdata
[j
+4:j
+prechead
[1]])
4179 fwData
[0] = record
[1] - record
[0]
4181 print(' %s' % prectype
[prechead
[0]])
4182 print(' SuspendStart : %u ns' % \
4184 print(' SuspendEnd : %u ns' % \
4186 print(' SuspendTime : %u ns' % \
4195 # Function: statusCheck
4197 # Verify that the requested command and options will work, and
4198 # print the results to the terminal
4200 # True if the test will work, False if not
4201 def statusCheck(probecheck
=False):
4205 print('Checking this system (%s)...' % platform
.node())
4207 # check we have root access
4208 res
= sysvals
.colorText('NO (No features of this tool will work!)')
4209 if(rootCheck(False)):
4211 print(' have root access: %s' % res
)
4213 print(' Try running this script with sudo')
4216 # check sysfs is mounted
4217 res
= sysvals
.colorText('NO (No features of this tool will work!)')
4218 if(os
.path
.exists(sysvals
.powerfile
)):
4220 print(' is sysfs mounted: %s' % res
)
4224 # check target mode is a valid mode
4225 if sysvals
.suspendmode
!= 'command':
4226 res
= sysvals
.colorText('NO')
4228 if(sysvals
.suspendmode
in modes
):
4232 print(' is "%s" a valid power mode: %s' % (sysvals
.suspendmode
, res
))
4234 print(' valid power modes are: %s' % modes
)
4235 print(' please choose one with -m')
4237 # check if ftrace is available
4238 res
= sysvals
.colorText('NO')
4239 ftgood
= sysvals
.verifyFtrace()
4242 elif(sysvals
.usecallgraph
):
4244 print(' is ftrace supported: %s' % res
)
4246 # check if kprobes are available
4247 res
= sysvals
.colorText('NO')
4248 sysvals
.usekprobes
= sysvals
.verifyKprobes()
4249 if(sysvals
.usekprobes
):
4252 sysvals
.usedevsrc
= False
4253 print(' are kprobes supported: %s' % res
)
4255 # what data source are we using
4258 sysvals
.usetraceeventsonly
= True
4259 sysvals
.usetraceevents
= False
4260 for e
in sysvals
.traceevents
:
4262 if(os
.path
.exists(sysvals
.epath
+e
)):
4265 sysvals
.usetraceeventsonly
= False
4266 if(e
== 'suspend_resume' and check
):
4267 sysvals
.usetraceevents
= True
4268 if(sysvals
.usetraceevents
and sysvals
.usetraceeventsonly
):
4269 res
= 'FTRACE (all trace events found)'
4270 elif(sysvals
.usetraceevents
):
4271 res
= 'DMESG and FTRACE (suspend_resume trace event found)'
4272 print(' timeline data source: %s' % res
)
4275 res
= sysvals
.colorText('NO')
4276 if(sysvals
.rtcpath
!= ''):
4278 elif(sysvals
.rtcwake
):
4280 print(' is rtcwake supported: %s' % res
)
4285 if (sysvals
.usecallgraph
and len(sysvals
.debugfuncs
) > 0) or len(sysvals
.kprobes
) > 0:
4286 sysvals
.initFtrace(True)
4288 # verify callgraph debugfuncs
4289 if sysvals
.usecallgraph
and len(sysvals
.debugfuncs
) > 0:
4290 print(' verifying these ftrace callgraph functions work:')
4291 sysvals
.setFtraceFilterFunctions(sysvals
.debugfuncs
)
4292 fp
= open(sysvals
.tpath
+'set_graph_function', 'r')
4293 flist
= fp
.read().split('\n')
4295 for func
in sysvals
.debugfuncs
:
4296 res
= sysvals
.colorText('NO')
4301 if ' [' in i
and func
== i
.split(' ')[0]:
4304 print(' %s: %s' % (func
, res
))
4307 if len(sysvals
.kprobes
) > 0:
4308 print(' verifying these kprobes work:')
4309 for name
in sorted(sysvals
.kprobes
):
4310 if name
in sysvals
.tracefuncs
:
4312 res
= sysvals
.colorText('NO')
4313 if sysvals
.testKprobe(sysvals
.kprobes
[name
]):
4315 print(' %s: %s' % (name
, res
))
4321 # generic error function for catastrphic failures
4323 # msg: the error message to print
4324 # help: True if printHelp should be called after, False otherwise
4325 def doError(msg
, help):
4328 print('ERROR: %s\n') % msg
4331 # Function: doWarning
4333 # generic warning function for non-catastrophic anomalies
4335 # msg: the warning message to print
4336 # file: If not empty, a filename to request be sent to the owner for debug
4337 def doWarning(msg
, file=''):
4338 print('/* %s */') % msg
4340 print('/* For a fix, please send this'+\
4341 ' %s file to <todd.e.brandt@intel.com> */' % file)
4343 # Function: rootCheck
4345 # quick check to see if we have root access
4346 def rootCheck(fatal
):
4348 if(os
.access(sysvals
.powerfile
, os
.W_OK
)):
4351 doError('This command must be run as root', False)
4354 # Function: getArgInt
4356 # pull out an integer argument from the command line with checks
4357 def getArgInt(name
, args
, min, max, main
=True):
4362 doError(name
+': no argument supplied', True)
4368 doError(name
+': non-integer value given', True)
4369 if(val
< min or val
> max):
4370 doError(name
+': value should be between %d and %d' % (min, max), True)
4373 # Function: getArgFloat
4375 # pull out a float argument from the command line with checks
4376 def getArgFloat(name
, args
, min, max, main
=True):
4381 doError(name
+': no argument supplied', True)
4387 doError(name
+': non-numerical value given', True)
4388 if(val
< min or val
> max):
4389 doError(name
+': value should be between %f and %f' % (min, max), True)
4392 # Function: rerunTest
4394 # generate an output from an existing set of ftrace/dmesg logs
4398 if(sysvals
.ftracefile
!= ''):
4399 doesTraceLogHaveTraceEvents()
4400 if(sysvals
.dmesgfile
== '' and not sysvals
.usetraceeventsonly
):
4401 doError('recreating this html output '+\
4402 'requires a dmesg file', False)
4403 sysvals
.setOutputFile()
4404 vprint('Output file: %s' % sysvals
.htmlfile
)
4405 print('PROCESSING DATA')
4406 if(sysvals
.usetraceeventsonly
):
4407 testruns
= parseTraceLog()
4409 testruns
= loadKernelLog()
4410 for data
in testruns
:
4411 parseKernelLog(data
)
4412 if(sysvals
.ftracefile
!= ''):
4413 appendIncompleteTraceLog(testruns
)
4414 createHTML(testruns
)
4418 # execute a suspend/resume, gather the logs, and generate the output
4419 def runTest(subdir
, testpath
=''):
4422 # prepare for the test
4423 sysvals
.initFtrace()
4424 sysvals
.initTestOutput(subdir
, testpath
)
4426 vprint('Output files:\n %s' % sysvals
.dmesgfile
)
4427 if(sysvals
.usecallgraph
or
4428 sysvals
.usetraceevents
or
4429 sysvals
.usetraceeventsonly
):
4430 vprint(' %s' % sysvals
.ftracefile
)
4431 vprint(' %s' % sysvals
.htmlfile
)
4435 sysvals
.cleanupFtrace()
4437 # analyze the data and create the html output
4438 print('PROCESSING DATA')
4439 if(sysvals
.usetraceeventsonly
):
4440 # data for kernels 3.15 or newer is entirely in ftrace
4441 testruns
= parseTraceLog()
4443 # data for kernels older than 3.15 is primarily in dmesg
4444 testruns
= loadKernelLog()
4445 for data
in testruns
:
4446 parseKernelLog(data
)
4447 if(sysvals
.usecallgraph
or sysvals
.usetraceevents
):
4448 appendIncompleteTraceLog(testruns
)
4449 createHTML(testruns
)
4451 # Function: runSummary
4453 # create a summary of tests in a sub-directory
4454 def runSummary(subdir
, output
):
4457 # get a list of ftrace output files
4459 for dirname
, dirnames
, filenames
in os
.walk(subdir
):
4460 for filename
in filenames
:
4461 if(re
.match('.*_ftrace.txt', filename
)):
4462 files
.append("%s/%s" % (dirname
, filename
))
4464 # process the files in order and get an array of data objects
4466 for file in sorted(files
):
4468 print("Test found in %s" % os
.path
.dirname(file))
4469 sysvals
.ftracefile
= file
4470 sysvals
.dmesgfile
= file.replace('_ftrace.txt', '_dmesg.txt')
4471 doesTraceLogHaveTraceEvents()
4472 sysvals
.usecallgraph
= False
4473 if not sysvals
.usetraceeventsonly
:
4474 if(not os
.path
.exists(sysvals
.dmesgfile
)):
4475 print("Skipping %s: not a valid test input" % file)
4479 f
= os
.path
.basename(sysvals
.ftracefile
)
4480 d
= os
.path
.basename(sysvals
.dmesgfile
)
4481 print("\tInput files: %s and %s" % (f
, d
))
4482 testdata
= loadKernelLog()
4484 parseKernelLog(data
)
4486 appendIncompleteTraceLog(testdata
)
4489 print("\tInput file: %s" % os
.path
.basename(sysvals
.ftracefile
))
4490 testdata
= parseTraceLog()
4492 data
.normalizeTime(data
.tSuspended
)
4493 link
= file.replace(subdir
+'/', '').replace('_ftrace.txt', '.html')
4495 testruns
.append(data
)
4497 createHTMLSummarySimple(testruns
, subdir
+'/summary.html')
4499 # Function: checkArgBool
4501 # check if a boolean string value is true or false
4502 def checkArgBool(value
):
4503 yes
= ['1', 'true', 'yes', 'on']
4504 if value
.lower() in yes
:
4508 # Function: configFromFile
4510 # Configure the script via the info in a config file
4511 def configFromFile(file):
4513 Config
= ConfigParser
.ConfigParser()
4515 ignorekprobes
= False
4517 sections
= Config
.sections()
4518 if 'Settings' in sections
:
4519 for opt
in Config
.options('Settings'):
4520 value
= Config
.get('Settings', opt
).lower()
4521 if(opt
.lower() == 'verbose'):
4522 sysvals
.verbose
= checkArgBool(value
)
4523 elif(opt
.lower() == 'addlogs'):
4524 sysvals
.addlogs
= checkArgBool(value
)
4525 elif(opt
.lower() == 'dev'):
4526 sysvals
.usedevsrc
= checkArgBool(value
)
4527 elif(opt
.lower() == 'ignorekprobes'):
4528 ignorekprobes
= checkArgBool(value
)
4529 elif(opt
.lower() == 'x2'):
4530 if checkArgBool(value
):
4531 sysvals
.execcount
= 2
4532 elif(opt
.lower() == 'callgraph'):
4533 sysvals
.usecallgraph
= checkArgBool(value
)
4534 elif(opt
.lower() == 'callgraphfunc'):
4535 sysvals
.debugfuncs
= []
4537 value
= value
.split(',')
4539 sysvals
.debugfuncs
.append(i
.strip())
4540 elif(opt
.lower() == 'expandcg'):
4541 sysvals
.cgexp
= checkArgBool(value
)
4542 elif(opt
.lower() == 'srgap'):
4543 if checkArgBool(value
):
4545 elif(opt
.lower() == 'mode'):
4546 sysvals
.suspendmode
= value
4547 elif(opt
.lower() == 'command'):
4548 sysvals
.testcommand
= value
4549 elif(opt
.lower() == 'x2delay'):
4550 sysvals
.x2delay
= getArgInt('-x2delay', value
, 0, 60000, False)
4551 elif(opt
.lower() == 'postres'):
4552 sysvals
.postresumetime
= getArgInt('-postres', value
, 0, 3600, False)
4553 elif(opt
.lower() == 'rtcwake'):
4554 sysvals
.rtcwake
= True
4555 sysvals
.rtcwaketime
= getArgInt('-rtcwake', value
, 0, 3600, False)
4556 elif(opt
.lower() == 'timeprec'):
4557 sysvals
.setPrecision(getArgInt('-timeprec', value
, 0, 6, False))
4558 elif(opt
.lower() == 'mindev'):
4559 sysvals
.mindevlen
= getArgFloat('-mindev', value
, 0.0, 10000.0, False)
4560 elif(opt
.lower() == 'mincg'):
4561 sysvals
.mincglen
= getArgFloat('-mincg', value
, 0.0, 10000.0, False)
4562 elif(opt
.lower() == 'kprobecolor'):
4564 val
= int(value
, 16)
4565 sysvals
.kprobecolor
= '#'+value
4567 sysvals
.kprobecolor
= value
4568 elif(opt
.lower() == 'synccolor'):
4570 val
= int(value
, 16)
4571 sysvals
.synccolor
= '#'+value
4573 sysvals
.synccolor
= value
4574 elif(opt
.lower() == 'output-dir'):
4577 args
['date'] = n
.strftime('%y%m%d')
4578 args
['time'] = n
.strftime('%H%M%S')
4579 args
['hostname'] = sysvals
.hostname
4580 sysvals
.outdir
= value
.format(**args
)
4582 if sysvals
.suspendmode
== 'command' and not sysvals
.testcommand
:
4583 doError('No command supplied for mode "command"', False)
4584 if sysvals
.usedevsrc
and sysvals
.usecallgraph
:
4585 doError('dev and callgraph cannot both be true', False)
4586 if sysvals
.usecallgraph
and sysvals
.execcount
> 1:
4587 doError('-x2 is not compatible with -f', False)
4593 archkprobe
= 'Kprobe_'+platform
.machine()
4594 if archkprobe
in sections
:
4595 for name
in Config
.options(archkprobe
):
4596 kprobes
[name
] = Config
.get(archkprobe
, name
)
4597 if 'Kprobe' in sections
:
4598 for name
in Config
.options('Kprobe'):
4599 kprobes
[name
] = Config
.get('Kprobe', name
)
4601 for name
in kprobes
:
4606 data
= kprobes
[name
].split()
4609 # bracketted strings are special formatting, read them separately
4610 if val
[0] == '[' and val
[-1] == ']':
4611 for prop
in val
[1:-1].split(','):
4615 color
= int(p
[1], 16)
4620 # first real arg should be the format string
4623 # all other args are actual function args
4628 if not function
or not format
:
4629 doError('Invalid kprobe: %s' % name
, False)
4630 for arg
in re
.findall('{(?P<n>[a-z,A-Z,0-9]*)}', format
):
4632 doError('Kprobe "%s" is missing argument "%s"' % (name
, arg
), False)
4633 if name
in sysvals
.kprobes
:
4634 doError('Duplicate kprobe found "%s"' % (name
), False)
4635 vprint('Adding KPROBE: %s %s %s %s' % (name
, function
, format
, args
))
4636 sysvals
.kprobes
[name
] = {
4641 'mask': re
.sub('{(?P<n>[a-z,A-Z,0-9]*)}', '.*', format
)
4644 sysvals
.kprobes
[name
]['color'] = color
4646 # Function: printHelp
4648 # print out the help text
4654 print('AnalyzeSuspend v%s' % sysvals
.version
)
4655 print('Usage: sudo analyze_suspend.py <options>')
4657 print('Description:')
4658 print(' This tool is designed to assist kernel and OS developers in optimizing')
4659 print(' their linux stack\'s suspend/resume time. Using a kernel image built')
4660 print(' with a few extra options enabled, the tool will execute a suspend and')
4661 print(' capture dmesg and ftrace data until resume is complete. This data is')
4662 print(' transformed into a device timeline and an optional callgraph to give')
4663 print(' a detailed view of which devices/subsystems are taking the most')
4664 print(' time in suspend/resume.')
4666 print(' Generates output files in subdirectory: suspend-mmddyy-HHMMSS')
4667 print(' HTML output: <hostname>_<mode>.html')
4668 print(' raw dmesg output: <hostname>_<mode>_dmesg.txt')
4669 print(' raw ftrace output: <hostname>_<mode>_ftrace.txt')
4673 print(' -h Print this help text')
4674 print(' -v Print the current tool version')
4675 print(' -config file Pull arguments and config options from a file')
4676 print(' -verbose Print extra information during execution and analysis')
4677 print(' -status Test to see if the system is enabled to run this tool')
4678 print(' -modes List available suspend modes')
4679 print(' -m mode Mode to initiate for suspend %s (default: %s)') % (modes
, sysvals
.suspendmode
)
4680 print(' -o subdir Override the output subdirectory')
4681 print(' [advanced]')
4682 print(' -rtcwake t Use rtcwake to autoresume after <t> seconds (default: disabled)')
4683 print(' -addlogs Add the dmesg and ftrace logs to the html output')
4684 print(' -multi n d Execute <n> consecutive tests at <d> seconds intervals. The outputs will')
4685 print(' be created in a new subdirectory with a summary page.')
4686 print(' -srgap Add a visible gap in the timeline between sus/res (default: disabled)')
4687 print(' -cmd {s} Instead of suspend/resume, run a command, e.g. "sync -d"')
4688 print(' -mindev ms Discard all device blocks shorter than ms milliseconds (e.g. 0.001 for us)')
4689 print(' -mincg ms Discard all callgraphs shorter than ms milliseconds (e.g. 0.001 for us)')
4690 print(' -timeprec N Number of significant digits in timestamps (0:S, [3:ms], 6:us)')
4692 print(' -f Use ftrace to create device callgraphs (default: disabled)')
4693 print(' -expandcg pre-expand the callgraph data in the html output (default: disabled)')
4694 print(' -flist Print the list of functions currently being captured in ftrace')
4695 print(' -flistall Print all functions capable of being captured in ftrace')
4696 print(' -fadd file Add functions to be graphed in the timeline from a list in a text file')
4697 print(' -filter "d1 d2 ..." Filter out all but this list of device names')
4698 print(' -dev Display common low level functions in the timeline')
4699 print(' [post-resume task analysis]')
4700 print(' -x2 Run two suspend/resumes back to back (default: disabled)')
4701 print(' -x2delay t Minimum millisecond delay <t> between the two test runs (default: 0 ms)')
4702 print(' -postres t Time after resume completion to wait for post-resume events (default: 0 S)')
4703 print(' [utilities]')
4704 print(' -fpdt Print out the contents of the ACPI Firmware Performance Data Table')
4705 print(' -usbtopo Print out the current USB topology with power info')
4706 print(' -usbauto Enable autosuspend for all connected USB devices')
4707 print(' [re-analyze data from previous runs]')
4708 print(' -ftrace ftracefile Create HTML output using ftrace input')
4709 print(' -dmesg dmesgfile Create HTML output using dmesg (not needed for kernel >= 3.15)')
4710 print(' -summary directory Create a summary of all test in this dir')
4714 # ----------------- MAIN --------------------
4715 # exec start (skipped if script is loaded as library)
4716 if __name__
== '__main__':
4719 multitest
= {'run': False, 'count': 0, 'delay': 0}
4720 simplecmds
= ['-modes', '-fpdt', '-flist', '-flistall', '-usbtopo', '-usbauto', '-status']
4721 # loop through the command line arguments
4722 args
= iter(sys
.argv
[1:])
4728 doError('No mode supplied', True)
4729 if val
== 'command' and not sysvals
.testcommand
:
4730 doError('No command supplied for mode "command"', True)
4731 sysvals
.suspendmode
= val
4732 elif(arg
in simplecmds
):
4738 print("Version %s" % sysvals
.version
)
4741 sysvals
.execcount
= 2
4742 if(sysvals
.usecallgraph
):
4743 doError('-x2 is not compatible with -f', False)
4744 elif(arg
== '-x2delay'):
4745 sysvals
.x2delay
= getArgInt('-x2delay', args
, 0, 60000)
4746 elif(arg
== '-postres'):
4747 sysvals
.postresumetime
= getArgInt('-postres', args
, 0, 3600)
4749 sysvals
.usecallgraph
= True
4750 if(sysvals
.execcount
> 1):
4751 doError('-x2 is not compatible with -f', False)
4752 if(sysvals
.usedevsrc
):
4753 doError('-dev is not compatible with -f', False)
4754 elif(arg
== '-addlogs'):
4755 sysvals
.addlogs
= True
4756 elif(arg
== '-verbose'):
4757 sysvals
.verbose
= True
4758 elif(arg
== '-dev'):
4759 sysvals
.usedevsrc
= True
4760 if(sysvals
.usecallgraph
):
4761 doError('-dev is not compatible with -f', False)
4762 elif(arg
== '-rtcwake'):
4763 sysvals
.rtcwake
= True
4764 sysvals
.rtcwaketime
= getArgInt('-rtcwake', args
, 0, 3600)
4765 elif(arg
== '-timeprec'):
4766 sysvals
.setPrecision(getArgInt('-timeprec', args
, 0, 6))
4767 elif(arg
== '-mindev'):
4768 sysvals
.mindevlen
= getArgFloat('-mindev', args
, 0.0, 10000.0)
4769 elif(arg
== '-mincg'):
4770 sysvals
.mincglen
= getArgFloat('-mincg', args
, 0.0, 10000.0)
4771 elif(arg
== '-cmd'):
4775 doError('No command string supplied', True)
4776 sysvals
.testcommand
= val
4777 sysvals
.suspendmode
= 'command'
4778 elif(arg
== '-expandcg'):
4779 sysvals
.cgexp
= True
4780 elif(arg
== '-srgap'):
4782 elif(arg
== '-multi'):
4783 multitest
['run'] = True
4784 multitest
['count'] = getArgInt('-multi n (exec count)', args
, 2, 1000000)
4785 multitest
['delay'] = getArgInt('-multi d (delay between tests)', args
, 0, 3600)
4790 doError('No subdirectory name supplied', True)
4791 sysvals
.outdir
= val
4792 elif(arg
== '-config'):
4796 doError('No text file supplied', True)
4797 if(os
.path
.exists(val
) == False):
4798 doError('%s does not exist' % val
, False)
4800 elif(arg
== '-fadd'):
4804 doError('No text file supplied', True)
4805 if(os
.path
.exists(val
) == False):
4806 doError('%s does not exist' % val
, False)
4807 sysvals
.addFtraceFilterFunctions(val
)
4808 elif(arg
== '-dmesg'):
4812 doError('No dmesg file supplied', True)
4813 sysvals
.notestrun
= True
4814 sysvals
.dmesgfile
= val
4815 if(os
.path
.exists(sysvals
.dmesgfile
) == False):
4816 doError('%s does not exist' % sysvals
.dmesgfile
, False)
4817 elif(arg
== '-ftrace'):
4821 doError('No ftrace file supplied', True)
4822 sysvals
.notestrun
= True
4823 sysvals
.ftracefile
= val
4824 if(os
.path
.exists(sysvals
.ftracefile
) == False):
4825 doError('%s does not exist' % sysvals
.ftracefile
, False)
4826 elif(arg
== '-summary'):
4830 doError('No directory supplied', True)
4833 sysvals
.notestrun
= True
4834 if(os
.path
.isdir(val
) == False):
4835 doError('%s is not accesible' % val
, False)
4836 elif(arg
== '-filter'):
4840 doError('No devnames supplied', True)
4841 sysvals
.setDeviceFilter(val
)
4843 doError('Invalid argument: '+arg
, True)
4845 # callgraph size cannot exceed device size
4846 if sysvals
.mincglen
< sysvals
.mindevlen
:
4847 sysvals
.mincglen
= sysvals
.mindevlen
4849 # just run a utility command and exit
4851 if(cmd
== 'status'):
4853 elif(cmd
== 'fpdt'):
4855 elif(cmd
== 'usbtopo'):
4857 elif(cmd
== 'modes'):
4860 elif(cmd
== 'flist'):
4861 sysvals
.getFtraceFilterFunctions(True)
4862 elif(cmd
== 'flistall'):
4863 sysvals
.getFtraceFilterFunctions(False)
4864 elif(cmd
== 'usbauto'):
4866 elif(cmd
== 'summary'):
4867 print("Generating a summary of folder \"%s\"" % cmdarg
)
4868 runSummary(cmdarg
, True)
4871 # if instructed, re-analyze existing data files
4872 if(sysvals
.notestrun
):
4876 # verify that we can run a test
4877 if(not statusCheck()):
4878 print('Check FAILED, aborting the test run!')
4881 if multitest
['run']:
4882 # run multiple tests in a separate subdirectory
4883 s
= 'x%d' % multitest
['count']
4884 if not sysvals
.outdir
:
4885 sysvals
.outdir
= datetime
.now().strftime('suspend-'+s
+'-%m%d%y-%H%M%S')
4886 if not os
.path
.isdir(sysvals
.outdir
):
4887 os
.mkdir(sysvals
.outdir
)
4888 for i
in range(multitest
['count']):
4890 print('Waiting %d seconds...' % (multitest
['delay']))
4891 time
.sleep(multitest
['delay'])
4892 print('TEST (%d/%d) START' % (i
+1, multitest
['count']))
4893 runTest(sysvals
.outdir
)
4894 print('TEST (%d/%d) COMPLETE' % (i
+1, multitest
['count']))
4895 runSummary(sysvals
.outdir
, False)
4897 # run the test in the current directory
4898 runTest('.', sysvals
.outdir
)