aboutsummaryrefslogtreecommitdiffstats
path: root/tools
diff options
context:
space:
mode:
Diffstat (limited to 'tools')
-rw-r--r--tools/power/pm-graph/Makefile28
-rwxr-xr-xtools/power/pm-graph/analyze_boot.py824
-rwxr-xr-xtools/power/pm-graph/analyze_suspend.py5309
-rw-r--r--tools/power/pm-graph/bootgraph.8132
-rw-r--r--tools/power/pm-graph/sleepgraph.8243
-rwxr-xr-xtools/power/x86/intel_pstate_tracer/intel_pstate_tracer.py17
6 files changed, 6553 insertions, 0 deletions
diff --git a/tools/power/pm-graph/Makefile b/tools/power/pm-graph/Makefile
new file mode 100644
index 000000000000..4d0ccc89e6c6
--- /dev/null
+++ b/tools/power/pm-graph/Makefile
@@ -0,0 +1,28 @@
1PREFIX ?= /usr
2DESTDIR ?=
3
4all:
5 @echo "Nothing to build"
6
7install :
8 install -d $(DESTDIR)$(PREFIX)/lib/pm-graph
9 install analyze_suspend.py $(DESTDIR)$(PREFIX)/lib/pm-graph
10 install analyze_boot.py $(DESTDIR)$(PREFIX)/lib/pm-graph
11
12 ln -s $(DESTDIR)$(PREFIX)/lib/pm-graph/analyze_boot.py $(DESTDIR)$(PREFIX)/bin/bootgraph
13 ln -s $(DESTDIR)$(PREFIX)/lib/pm-graph/analyze_suspend.py $(DESTDIR)$(PREFIX)/bin/sleepgraph
14
15 install -d $(DESTDIR)$(PREFIX)/share/man/man8
16 install bootgraph.8 $(DESTDIR)$(PREFIX)/share/man/man8
17 install sleepgraph.8 $(DESTDIR)$(PREFIX)/share/man/man8
18
19uninstall :
20 rm $(DESTDIR)$(PREFIX)/share/man/man8/bootgraph.8
21 rm $(DESTDIR)$(PREFIX)/share/man/man8/sleepgraph.8
22
23 rm $(DESTDIR)$(PREFIX)/bin/bootgraph
24 rm $(DESTDIR)$(PREFIX)/bin/sleepgraph
25
26 rm $(DESTDIR)$(PREFIX)/lib/pm-graph/analyze_boot.py
27 rm $(DESTDIR)$(PREFIX)/lib/pm-graph/analyze_suspend.py
28 rmdir $(DESTDIR)$(PREFIX)/lib/pm-graph
diff --git a/tools/power/pm-graph/analyze_boot.py b/tools/power/pm-graph/analyze_boot.py
new file mode 100755
index 000000000000..3e1dcbbf1adc
--- /dev/null
+++ b/tools/power/pm-graph/analyze_boot.py
@@ -0,0 +1,824 @@
1#!/usr/bin/python
2#
3# Tool for analyzing boot timing
4# Copyright (c) 2013, Intel Corporation.
5#
6# This program is free software; you can redistribute it and/or modify it
7# under the terms and conditions of the GNU General Public License,
8# version 2, as published by the Free Software Foundation.
9#
10# This program is distributed in the hope it will be useful, but WITHOUT
11# ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
12# FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License for
13# more details.
14#
15# Authors:
16# Todd Brandt <todd.e.brandt@linux.intel.com>
17#
18# Description:
19# This tool is designed to assist kernel and OS developers in optimizing
20# their linux stack's boot time. It creates an html representation of
21# the kernel boot timeline up to the start of the init process.
22#
23
24# ----------------- LIBRARIES --------------------
25
26import sys
27import time
28import os
29import string
30import re
31import platform
32import shutil
33from datetime import datetime, timedelta
34from subprocess import call, Popen, PIPE
35import analyze_suspend as aslib
36
37# ----------------- CLASSES --------------------
38
39# Class: SystemValues
40# Description:
41# A global, single-instance container used to
42# store system values and test parameters
43class SystemValues(aslib.SystemValues):
44 title = 'BootGraph'
45 version = 2.0
46 hostname = 'localhost'
47 testtime = ''
48 kernel = ''
49 dmesgfile = ''
50 ftracefile = ''
51 htmlfile = 'bootgraph.html'
52 outfile = ''
53 phoronix = False
54 addlogs = False
55 useftrace = False
56 usedevsrc = True
57 suspendmode = 'boot'
58 max_graph_depth = 2
59 graph_filter = 'do_one_initcall'
60 reboot = False
61 manual = False
62 iscronjob = False
63 timeformat = '%.6f'
64 def __init__(self):
65 if('LOG_FILE' in os.environ and 'TEST_RESULTS_IDENTIFIER' in os.environ):
66 self.phoronix = True
67 self.addlogs = True
68 self.outfile = os.environ['LOG_FILE']
69 self.htmlfile = os.environ['LOG_FILE']
70 self.hostname = platform.node()
71 self.testtime = datetime.now().strftime('%Y-%m-%d_%H:%M:%S')
72 if os.path.exists('/proc/version'):
73 fp = open('/proc/version', 'r')
74 val = fp.read().strip()
75 fp.close()
76 self.kernel = self.kernelVersion(val)
77 else:
78 self.kernel = 'unknown'
79 def kernelVersion(self, msg):
80 return msg.split()[2]
81 def kernelParams(self):
82 cmdline = 'initcall_debug log_buf_len=32M'
83 if self.useftrace:
84 cmdline += ' trace_buf_size=128M trace_clock=global '\
85 'trace_options=nooverwrite,funcgraph-abstime,funcgraph-cpu,'\
86 'funcgraph-duration,funcgraph-proc,funcgraph-tail,'\
87 'nofuncgraph-overhead,context-info,graph-time '\
88 'ftrace=function_graph '\
89 'ftrace_graph_max_depth=%d '\
90 'ftrace_graph_filter=%s' % \
91 (self.max_graph_depth, self.graph_filter)
92 return cmdline
93 def setGraphFilter(self, val):
94 fp = open(self.tpath+'available_filter_functions')
95 master = fp.read().split('\n')
96 fp.close()
97 for i in val.split(','):
98 func = i.strip()
99 if func not in master:
100 doError('function "%s" not available for ftrace' % func)
101 self.graph_filter = val
102 def cronjobCmdString(self):
103 cmdline = '%s -cronjob' % os.path.abspath(sys.argv[0])
104 args = iter(sys.argv[1:])
105 for arg in args:
106 if arg in ['-h', '-v', '-cronjob', '-reboot']:
107 continue
108 elif arg in ['-o', '-dmesg', '-ftrace', '-filter']:
109 args.next()
110 continue
111 cmdline += ' '+arg
112 if self.graph_filter != 'do_one_initcall':
113 cmdline += ' -filter "%s"' % self.graph_filter
114 cmdline += ' -o "%s"' % os.path.abspath(self.htmlfile)
115 return cmdline
116 def manualRebootRequired(self):
117 cmdline = self.kernelParams()
118 print 'To generate a new timeline manually, follow these steps:\n'
119 print '1. Add the CMDLINE string to your kernel command line.'
120 print '2. Reboot the system.'
121 print '3. After reboot, re-run this tool with the same arguments but no command (w/o -reboot or -manual).\n'
122 print 'CMDLINE="%s"' % cmdline
123 sys.exit()
124
125sysvals = SystemValues()
126
127# Class: Data
128# Description:
129# The primary container for test data.
130class Data(aslib.Data):
131 dmesg = {} # root data structure
132 start = 0.0 # test start
133 end = 0.0 # test end
134 dmesgtext = [] # dmesg text file in memory
135 testnumber = 0
136 idstr = ''
137 html_device_id = 0
138 valid = False
139 initstart = 0.0
140 boottime = ''
141 phases = ['boot']
142 do_one_initcall = False
143 def __init__(self, num):
144 self.testnumber = num
145 self.idstr = 'a'
146 self.dmesgtext = []
147 self.dmesg = {
148 'boot': {'list': dict(), 'start': -1.0, 'end': -1.0, 'row': 0, 'color': '#dddddd'}
149 }
150 def deviceTopology(self):
151 return ''
152 def newAction(self, phase, name, start, end, ret, ulen):
153 # new device callback for a specific phase
154 self.html_device_id += 1
155 devid = '%s%d' % (self.idstr, self.html_device_id)
156 list = self.dmesg[phase]['list']
157 length = -1.0
158 if(start >= 0 and end >= 0):
159 length = end - start
160 i = 2
161 origname = name
162 while(name in list):
163 name = '%s[%d]' % (origname, i)
164 i += 1
165 list[name] = {'name': name, 'start': start, 'end': end,
166 'pid': 0, 'length': length, 'row': 0, 'id': devid,
167 'ret': ret, 'ulen': ulen }
168 return name
169 def deviceMatch(self, cg):
170 if cg.end - cg.start == 0:
171 return True
172 list = self.dmesg['boot']['list']
173 for devname in list:
174 dev = list[devname]
175 if cg.name == 'do_one_initcall':
176 if(cg.start <= dev['start'] and cg.end >= dev['end'] and dev['length'] > 0):
177 dev['ftrace'] = cg
178 self.do_one_initcall = True
179 return True
180 else:
181 if(cg.start > dev['start'] and cg.end < dev['end']):
182 if 'ftraces' not in dev:
183 dev['ftraces'] = []
184 dev['ftraces'].append(cg)
185 return True
186 return False
187
188# ----------------- FUNCTIONS --------------------
189
190# Function: loadKernelLog
191# Description:
192# Load a raw kernel log from dmesg
193def loadKernelLog():
194 data = Data(0)
195 data.dmesg['boot']['start'] = data.start = ktime = 0.0
196 sysvals.stamp = {
197 'time': datetime.now().strftime('%B %d %Y, %I:%M:%S %p'),
198 'host': sysvals.hostname,
199 'mode': 'boot', 'kernel': ''}
200
201 devtemp = dict()
202 if(sysvals.dmesgfile):
203 lf = open(sysvals.dmesgfile, 'r')
204 else:
205 lf = Popen('dmesg', stdout=PIPE).stdout
206 for line in lf:
207 line = line.replace('\r\n', '')
208 idx = line.find('[')
209 if idx > 1:
210 line = line[idx:]
211 m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line)
212 if(not m):
213 continue
214 ktime = float(m.group('ktime'))
215 if(ktime > 120):
216 break
217 msg = m.group('msg')
218 data.end = data.initstart = ktime
219 data.dmesgtext.append(line)
220 if(ktime == 0.0 and re.match('^Linux version .*', msg)):
221 if(not sysvals.stamp['kernel']):
222 sysvals.stamp['kernel'] = sysvals.kernelVersion(msg)
223 continue
224 m = re.match('.* setting system clock to (?P<t>.*) UTC.*', msg)
225 if(m):
226 bt = datetime.strptime(m.group('t'), '%Y-%m-%d %H:%M:%S')
227 bt = bt - timedelta(seconds=int(ktime))
228 data.boottime = bt.strftime('%Y-%m-%d_%H:%M:%S')
229 sysvals.stamp['time'] = bt.strftime('%B %d %Y, %I:%M:%S %p')
230 continue
231 m = re.match('^calling *(?P<f>.*)\+.*', msg)
232 if(m):
233 devtemp[m.group('f')] = ktime
234 continue
235 m = re.match('^initcall *(?P<f>.*)\+.* returned (?P<r>.*) after (?P<t>.*) usecs', msg)
236 if(m):
237 data.valid = True
238 f, r, t = m.group('f', 'r', 't')
239 if(f in devtemp):
240 data.newAction('boot', f, devtemp[f], ktime, int(r), int(t))
241 data.end = ktime
242 del devtemp[f]
243 continue
244 if(re.match('^Freeing unused kernel memory.*', msg)):
245 break
246
247 data.dmesg['boot']['end'] = data.end
248 lf.close()
249 return data
250
251# Function: loadTraceLog
252# Description:
253# Check if trace is available and copy to a temp file
254def loadTraceLog(data):
255 # load the data to a temp file if none given
256 if not sysvals.ftracefile:
257 lib = aslib.sysvals
258 aslib.rootCheck(True)
259 if not lib.verifyFtrace():
260 doError('ftrace not available')
261 if lib.fgetVal('current_tracer').strip() != 'function_graph':
262 doError('ftrace not configured for a boot callgraph')
263 sysvals.ftracefile = '/tmp/boot_ftrace.%s.txt' % os.getpid()
264 call('cat '+lib.tpath+'trace > '+sysvals.ftracefile, shell=True)
265 if not sysvals.ftracefile:
266 doError('No trace data available')
267
268 # parse the trace log
269 ftemp = dict()
270 tp = aslib.TestProps()
271 tp.setTracerType('function_graph')
272 tf = open(sysvals.ftracefile, 'r')
273 for line in tf:
274 if line[0] == '#':
275 continue
276 m = re.match(tp.ftrace_line_fmt, line.strip())
277 if(not m):
278 continue
279 m_time, m_proc, m_pid, m_msg, m_dur = \
280 m.group('time', 'proc', 'pid', 'msg', 'dur')
281 if float(m_time) > data.end:
282 break
283 if(m_time and m_pid and m_msg):
284 t = aslib.FTraceLine(m_time, m_msg, m_dur)
285 pid = int(m_pid)
286 else:
287 continue
288 if t.fevent or t.fkprobe:
289 continue
290 key = (m_proc, pid)
291 if(key not in ftemp):
292 ftemp[key] = []
293 ftemp[key].append(aslib.FTraceCallGraph(pid))
294 cg = ftemp[key][-1]
295 if(cg.addLine(t)):
296 ftemp[key].append(aslib.FTraceCallGraph(pid))
297 tf.close()
298
299 # add the callgraph data to the device hierarchy
300 for key in ftemp:
301 proc, pid = key
302 for cg in ftemp[key]:
303 if len(cg.list) < 1 or cg.invalid:
304 continue
305 if(not cg.postProcess()):
306 print('Sanity check failed for %s-%d' % (proc, pid))
307 continue
308 # match cg data to devices
309 if not data.deviceMatch(cg):
310 print ' BAD: %s %s-%d [%f - %f]' % (cg.name, proc, pid, cg.start, cg.end)
311
312# Function: colorForName
313# Description:
314# Generate a repeatable color from a list for a given name
315def colorForName(name):
316 list = [
317 ('c1', '#ec9999'),
318 ('c2', '#ffc1a6'),
319 ('c3', '#fff0a6'),
320 ('c4', '#adf199'),
321 ('c5', '#9fadea'),
322 ('c6', '#a699c1'),
323 ('c7', '#ad99b4'),
324 ('c8', '#eaffea'),
325 ('c9', '#dcecfb'),
326 ('c10', '#ffffea')
327 ]
328 i = 0
329 total = 0
330 count = len(list)
331 while i < len(name):
332 total += ord(name[i])
333 i += 1
334 return list[total % count]
335
336def cgOverview(cg, minlen):
337 stats = dict()
338 large = []
339 for l in cg.list:
340 if l.fcall and l.depth == 1:
341 if l.length >= minlen:
342 large.append(l)
343 if l.name not in stats:
344 stats[l.name] = [0, 0.0]
345 stats[l.name][0] += (l.length * 1000.0)
346 stats[l.name][1] += 1
347 return (large, stats)
348
349# Function: createBootGraph
350# Description:
351# Create the output html file from the resident test data
352# Arguments:
353# testruns: array of Data objects from parseKernelLog or parseTraceLog
354# Output:
355# True if the html file was created, false if it failed
356def createBootGraph(data, embedded):
357 # html function templates
358 html_srccall = '<div id={6} title="{5}" class="srccall" style="left:{1}%;top:{2}px;height:{3}px;width:{4}%;line-height:{3}px;">{0}</div>\n'
359 html_timetotal = '<table class="time1">\n<tr>'\
360 '<td class="blue">Time from Kernel Boot to start of User Mode: <b>{0} ms</b></td>'\
361 '</tr>\n</table>\n'
362
363 # device timeline
364 devtl = aslib.Timeline(100, 20)
365
366 # write the test title and general info header
367 devtl.createHeader(sysvals, 'noftrace')
368
369 # Generate the header for this timeline
370 t0 = data.start
371 tMax = data.end
372 tTotal = tMax - t0
373 if(tTotal == 0):
374 print('ERROR: No timeline data')
375 return False
376 boot_time = '%.0f'%(tTotal*1000)
377 devtl.html += html_timetotal.format(boot_time)
378
379 # determine the maximum number of rows we need to draw
380 phase = 'boot'
381 list = data.dmesg[phase]['list']
382 devlist = []
383 for devname in list:
384 d = aslib.DevItem(0, phase, list[devname])
385 devlist.append(d)
386 devtl.getPhaseRows(devlist)
387 devtl.calcTotalRows()
388
389 # draw the timeline background
390 devtl.createZoomBox()
391 boot = data.dmesg[phase]
392 length = boot['end']-boot['start']
393 left = '%.3f' % (((boot['start']-t0)*100.0)/tTotal)
394 width = '%.3f' % ((length*100.0)/tTotal)
395 devtl.html += devtl.html_tblock.format(phase, left, width, devtl.scaleH)
396 devtl.html += devtl.html_phase.format('0', '100', \
397 '%.3f'%devtl.scaleH, '%.3f'%devtl.bodyH, \
398 'white', '')
399
400 # draw the device timeline
401 num = 0
402 devstats = dict()
403 for devname in sorted(list):
404 cls, color = colorForName(devname)
405 dev = list[devname]
406 info = '@|%.3f|%.3f|%.3f|%d' % (dev['start']*1000.0, dev['end']*1000.0,
407 dev['ulen']/1000.0, dev['ret'])
408 devstats[dev['id']] = {'info':info}
409 dev['color'] = color
410 height = devtl.phaseRowHeight(0, phase, dev['row'])
411 top = '%.6f' % ((dev['row']*height) + devtl.scaleH)
412 left = '%.6f' % (((dev['start']-t0)*100)/tTotal)
413 width = '%.6f' % (((dev['end']-dev['start'])*100)/tTotal)
414 length = ' (%0.3f ms) ' % ((dev['end']-dev['start'])*1000)
415 devtl.html += devtl.html_device.format(dev['id'],
416 devname+length+'kernel_mode', left, top, '%.3f'%height,
417 width, devname, ' '+cls, '')
418 rowtop = devtl.phaseRowTop(0, phase, dev['row'])
419 height = '%.6f' % (devtl.rowH / 2)
420 top = '%.6f' % (rowtop + devtl.scaleH + (devtl.rowH / 2))
421 if data.do_one_initcall:
422 if('ftrace' not in dev):
423 continue
424 cg = dev['ftrace']
425 large, stats = cgOverview(cg, 0.001)
426 devstats[dev['id']]['fstat'] = stats
427 for l in large:
428 left = '%f' % (((l.time-t0)*100)/tTotal)
429 width = '%f' % (l.length*100/tTotal)
430 title = '%s (%0.3fms)' % (l.name, l.length * 1000.0)
431 devtl.html += html_srccall.format(l.name, left,
432 top, height, width, title, 'x%d'%num)
433 num += 1
434 continue
435 if('ftraces' not in dev):
436 continue
437 for cg in dev['ftraces']:
438 left = '%f' % (((cg.start-t0)*100)/tTotal)
439 width = '%f' % ((cg.end-cg.start)*100/tTotal)
440 cglen = (cg.end - cg.start) * 1000.0
441 title = '%s (%0.3fms)' % (cg.name, cglen)
442 cg.id = 'x%d' % num
443 devtl.html += html_srccall.format(cg.name, left,
444 top, height, width, title, dev['id']+cg.id)
445 num += 1
446
447 # draw the time scale, try to make the number of labels readable
448 devtl.createTimeScale(t0, tMax, tTotal, phase)
449 devtl.html += '</div>\n'
450
451 # timeline is finished
452 devtl.html += '</div>\n</div>\n'
453
454 if(sysvals.outfile == sysvals.htmlfile):
455 hf = open(sysvals.htmlfile, 'a')
456 else:
457 hf = open(sysvals.htmlfile, 'w')
458
459 # add the css if this is not an embedded run
460 extra = '\
461 .c1 {background:rgba(209,0,0,0.4);}\n\
462 .c2 {background:rgba(255,102,34,0.4);}\n\
463 .c3 {background:rgba(255,218,33,0.4);}\n\
464 .c4 {background:rgba(51,221,0,0.4);}\n\
465 .c5 {background:rgba(17,51,204,0.4);}\n\
466 .c6 {background:rgba(34,0,102,0.4);}\n\
467 .c7 {background:rgba(51,0,68,0.4);}\n\
468 .c8 {background:rgba(204,255,204,0.4);}\n\
469 .c9 {background:rgba(169,208,245,0.4);}\n\
470 .c10 {background:rgba(255,255,204,0.4);}\n\
471 .vt {transform:rotate(-60deg);transform-origin:0 0;}\n\
472 table.fstat {table-layout:fixed;padding:150px 15px 0 0;font-size:10px;column-width:30px;}\n\
473 .fstat th {width:55px;}\n\
474 .fstat td {text-align:left;width:35px;}\n\
475 .srccall {position:absolute;font-size:10px;z-index:7;overflow:hidden;color:black;text-align:center;white-space:nowrap;border-radius:5px;border:1px solid black;background:linear-gradient(to bottom right,#CCC,#969696);}\n\
476 .srccall:hover {color:white;font-weight:bold;border:1px solid white;}\n'
477 if(not embedded):
478 aslib.addCSS(hf, sysvals, 1, False, extra)
479
480 # write the device timeline
481 hf.write(devtl.html)
482
483 # add boot specific html
484 statinfo = 'var devstats = {\n'
485 for n in sorted(devstats):
486 statinfo += '\t"%s": [\n\t\t"%s",\n' % (n, devstats[n]['info'])
487 if 'fstat' in devstats[n]:
488 funcs = devstats[n]['fstat']
489 for f in sorted(funcs, key=funcs.get, reverse=True):
490 if funcs[f][0] < 0.01 and len(funcs) > 10:
491 break
492 statinfo += '\t\t"%f|%s|%d",\n' % (funcs[f][0], f, funcs[f][1])
493 statinfo += '\t],\n'
494 statinfo += '};\n'
495 html = \
496 '<div id="devicedetailtitle"></div>\n'\
497 '<div id="devicedetail" style="display:none;">\n'\
498 '<div id="devicedetail0">\n'\
499 '<div id="kernel_mode" class="phaselet" style="left:0%;width:100%;background:#DDDDDD"></div>\n'\
500 '</div>\n</div>\n'\
501 '<script type="text/javascript">\n'+statinfo+\
502 '</script>\n'
503 hf.write(html)
504
505 # add the callgraph html
506 if(sysvals.usecallgraph):
507 aslib.addCallgraphs(sysvals, hf, data)
508
509 # add the dmesg log as a hidden div
510 if sysvals.addlogs:
511 hf.write('<div id="dmesglog" style="display:none;">\n')
512 for line in data.dmesgtext:
513 line = line.replace('<', '&lt').replace('>', '&gt')
514 hf.write(line)
515 hf.write('</div>\n')
516
517 if(not embedded):
518 # write the footer and close
519 aslib.addScriptCode(hf, [data])
520 hf.write('</body>\n</html>\n')
521 else:
522 # embedded out will be loaded in a page, skip the js
523 hf.write('<div id=bounds style=display:none>%f,%f</div>' % \
524 (data.start*1000, data.initstart*1000))
525 hf.close()
526 return True
527
528# Function: updateCron
529# Description:
530# (restore=False) Set the tool to run automatically on reboot
531# (restore=True) Restore the original crontab
532def updateCron(restore=False):
533 if not restore:
534 sysvals.rootUser(True)
535 crondir = '/var/spool/cron/crontabs/'
536 cronfile = crondir+'root'
537 backfile = crondir+'root-analyze_boot-backup'
538 if not os.path.exists(crondir):
539 doError('%s not found' % crondir)
540 out = Popen(['which', 'crontab'], stdout=PIPE).stdout.read()
541 if not out:
542 doError('crontab not found')
543 # on restore: move the backup cron back into place
544 if restore:
545 if os.path.exists(backfile):
546 shutil.move(backfile, cronfile)
547 return
548 # backup current cron and install new one with reboot
549 if os.path.exists(cronfile):
550 shutil.move(cronfile, backfile)
551 else:
552 fp = open(backfile, 'w')
553 fp.close()
554 res = -1
555 try:
556 fp = open(backfile, 'r')
557 op = open(cronfile, 'w')
558 for line in fp:
559 if '@reboot' not in line:
560 op.write(line)
561 continue
562 fp.close()
563 op.write('@reboot python %s\n' % sysvals.cronjobCmdString())
564 op.close()
565 res = call('crontab %s' % cronfile, shell=True)
566 except Exception, e:
567 print 'Exception: %s' % str(e)
568 shutil.move(backfile, cronfile)
569 res = -1
570 if res != 0:
571 doError('crontab failed')
572
573# Function: updateGrub
574# Description:
575# update grub.cfg for all kernels with our parameters
576def updateGrub(restore=False):
577 # call update-grub on restore
578 if restore:
579 try:
580 call(['update-grub'], stderr=PIPE, stdout=PIPE,
581 env={'PATH': '.:/sbin:/usr/sbin:/usr/bin:/sbin:/bin'})
582 except Exception, e:
583 print 'Exception: %s\n' % str(e)
584 return
585 # verify we can do this
586 sysvals.rootUser(True)
587 grubfile = '/etc/default/grub'
588 if not os.path.exists(grubfile):
589 print 'ERROR: Unable to set the kernel parameters via grub.\n'
590 sysvals.manualRebootRequired()
591 out = Popen(['which', 'update-grub'], stdout=PIPE).stdout.read()
592 if not out:
593 print 'ERROR: Unable to set the kernel parameters via grub.\n'
594 sysvals.manualRebootRequired()
595
596 # extract the option and create a grub config without it
597 tgtopt = 'GRUB_CMDLINE_LINUX_DEFAULT'
598 cmdline = ''
599 tempfile = '/etc/default/grub.analyze_boot'
600 shutil.move(grubfile, tempfile)
601 res = -1
602 try:
603 fp = open(tempfile, 'r')
604 op = open(grubfile, 'w')
605 cont = False
606 for line in fp:
607 line = line.strip()
608 if len(line) == 0 or line[0] == '#':
609 continue
610 opt = line.split('=')[0].strip()
611 if opt == tgtopt:
612 cmdline = line.split('=', 1)[1].strip('\\')
613 if line[-1] == '\\':
614 cont = True
615 elif cont:
616 cmdline += line.strip('\\')
617 if line[-1] != '\\':
618 cont = False
619 else:
620 op.write('%s\n' % line)
621 fp.close()
622 # if the target option value is in quotes, strip them
623 sp = '"'
624 val = cmdline.strip()
625 if val[0] == '\'' or val[0] == '"':
626 sp = val[0]
627 val = val.strip(sp)
628 cmdline = val
629 # append our cmd line options
630 if len(cmdline) > 0:
631 cmdline += ' '
632 cmdline += sysvals.kernelParams()
633 # write out the updated target option
634 op.write('\n%s=%s%s%s\n' % (tgtopt, sp, cmdline, sp))
635 op.close()
636 res = call('update-grub')
637 os.remove(grubfile)
638 except Exception, e:
639 print 'Exception: %s' % str(e)
640 res = -1
641 # cleanup
642 shutil.move(tempfile, grubfile)
643 if res != 0:
644 doError('update-grub failed')
645
646# Function: doError
647# Description:
648# generic error function for catastrphic failures
649# Arguments:
650# msg: the error message to print
651# help: True if printHelp should be called after, False otherwise
652def doError(msg, help=False):
653 if help == True:
654 printHelp()
655 print 'ERROR: %s\n' % msg
656 sys.exit()
657
658# Function: printHelp
659# Description:
660# print out the help text
661def printHelp():
662 print('')
663 print('%s v%.1f' % (sysvals.title, sysvals.version))
664 print('Usage: bootgraph <options> <command>')
665 print('')
666 print('Description:')
667 print(' This tool reads in a dmesg log of linux kernel boot and')
668 print(' creates an html representation of the boot timeline up to')
669 print(' the start of the init process.')
670 print('')
671 print(' If no specific command is given the tool reads the current dmesg')
672 print(' and/or ftrace log and outputs bootgraph.html')
673 print('')
674 print('Options:')
675 print(' -h Print this help text')
676 print(' -v Print the current tool version')
677 print(' -addlogs Add the dmesg log to the html output')
678 print(' -o file Html timeline name (default: bootgraph.html)')
679 print(' [advanced]')
680 print(' -f Use ftrace to add function detail (default: disabled)')
681 print(' -callgraph Add callgraph detail, can be very large (default: disabled)')
682 print(' -maxdepth N limit the callgraph data to N call levels (default: 2)')
683 print(' -mincg ms Discard all callgraphs shorter than ms milliseconds (e.g. 0.001 for us)')
684 print(' -timeprec N Number of significant digits in timestamps (0:S, 3:ms, [6:us])')
685 print(' -expandcg pre-expand the callgraph data in the html output (default: disabled)')
686 print(' -filter list Limit ftrace to comma-delimited list of functions (default: do_one_initcall)')
687 print(' [commands]')
688 print(' -reboot Reboot the machine automatically and generate a new timeline')
689 print(' -manual Show the requirements to generate a new timeline manually')
690 print(' -dmesg file Load a stored dmesg file (used with -ftrace)')
691 print(' -ftrace file Load a stored ftrace file (used with -dmesg)')
692 print(' -flistall Print all functions capable of being captured in ftrace')
693 print('')
694 return True
695
696# ----------------- MAIN --------------------
697# exec start (skipped if script is loaded as library)
698if __name__ == '__main__':
699 # loop through the command line arguments
700 cmd = ''
701 simplecmds = ['-updategrub', '-flistall']
702 args = iter(sys.argv[1:])
703 for arg in args:
704 if(arg == '-h'):
705 printHelp()
706 sys.exit()
707 elif(arg == '-v'):
708 print("Version %.1f" % sysvals.version)
709 sys.exit()
710 elif(arg in simplecmds):
711 cmd = arg[1:]
712 elif(arg == '-f'):
713 sysvals.useftrace = True
714 elif(arg == '-callgraph'):
715 sysvals.useftrace = True
716 sysvals.usecallgraph = True
717 elif(arg == '-mincg'):
718 sysvals.mincglen = aslib.getArgFloat('-mincg', args, 0.0, 10000.0)
719 elif(arg == '-timeprec'):
720 sysvals.setPrecision(aslib.getArgInt('-timeprec', args, 0, 6))
721 elif(arg == '-maxdepth'):
722 sysvals.max_graph_depth = aslib.getArgInt('-maxdepth', args, 0, 1000)
723 elif(arg == '-filter'):
724 try:
725 val = args.next()
726 except:
727 doError('No filter functions supplied', True)
728 aslib.rootCheck(True)
729 sysvals.setGraphFilter(val)
730 elif(arg == '-ftrace'):
731 try:
732 val = args.next()
733 except:
734 doError('No ftrace file supplied', True)
735 if(os.path.exists(val) == False):
736 doError('%s does not exist' % val)
737 sysvals.ftracefile = val
738 elif(arg == '-addlogs'):
739 sysvals.addlogs = True
740 elif(arg == '-expandcg'):
741 sysvals.cgexp = True
742 elif(arg == '-dmesg'):
743 try:
744 val = args.next()
745 except:
746 doError('No dmesg file supplied', True)
747 if(os.path.exists(val) == False):
748 doError('%s does not exist' % val)
749 if(sysvals.htmlfile == val or sysvals.outfile == val):
750 doError('Output filename collision')
751 sysvals.dmesgfile = val
752 elif(arg == '-o'):
753 try:
754 val = args.next()
755 except:
756 doError('No HTML filename supplied', True)
757 if(sysvals.dmesgfile == val or sysvals.ftracefile == val):
758 doError('Output filename collision')
759 sysvals.htmlfile = val
760 elif(arg == '-reboot'):
761 if sysvals.iscronjob:
762 doError('-reboot and -cronjob are incompatible')
763 sysvals.reboot = True
764 elif(arg == '-manual'):
765 sysvals.reboot = True
766 sysvals.manual = True
767 # remaining options are only for cron job use
768 elif(arg == '-cronjob'):
769 sysvals.iscronjob = True
770 if sysvals.reboot:
771 doError('-reboot and -cronjob are incompatible')
772 else:
773 doError('Invalid argument: '+arg, True)
774
775 if cmd != '':
776 if cmd == 'updategrub':
777 updateGrub()
778 elif cmd == 'flistall':
779 sysvals.getFtraceFilterFunctions(False)
780 sys.exit()
781
782 # update grub, setup a cronjob, and reboot
783 if sysvals.reboot:
784 if not sysvals.manual:
785 updateGrub()
786 updateCron()
787 call('reboot')
788 else:
789 sysvals.manualRebootRequired()
790 sys.exit()
791
792 # disable the cronjob
793 if sysvals.iscronjob:
794 updateCron(True)
795 updateGrub(True)
796
797 data = loadKernelLog()
798 if sysvals.useftrace:
799 loadTraceLog(data)
800 if sysvals.iscronjob:
801 try:
802 sysvals.fsetVal('0', 'tracing_on')
803 except:
804 pass
805
806 if(sysvals.outfile and sysvals.phoronix):
807 fp = open(sysvals.outfile, 'w')
808 fp.write('pass %s initstart %.3f end %.3f boot %s\n' %
809 (data.valid, data.initstart*1000, data.end*1000, data.boottime))
810 fp.close()
811 if(not data.valid):
812 if sysvals.dmesgfile:
813 doError('No initcall data found in %s' % sysvals.dmesgfile)
814 else:
815 doError('No initcall data found, is initcall_debug enabled?')
816
817 print(' Host: %s' % sysvals.hostname)
818 print(' Test time: %s' % sysvals.testtime)
819 print(' Boot time: %s' % data.boottime)
820 print('Kernel Version: %s' % sysvals.kernel)
821 print(' Kernel start: %.3f' % (data.start * 1000))
822 print(' init start: %.3f' % (data.initstart * 1000))
823
824 createBootGraph(data, sysvals.phoronix)
diff --git a/tools/power/pm-graph/analyze_suspend.py b/tools/power/pm-graph/analyze_suspend.py
new file mode 100755
index 000000000000..a9206e67fc1f
--- /dev/null
+++ b/tools/power/pm-graph/analyze_suspend.py
@@ -0,0 +1,5309 @@
1#!/usr/bin/python
2#
3# Tool for analyzing suspend/resume timing
4# Copyright (c) 2013, Intel Corporation.
5#
6# This program is free software; you can redistribute it and/or modify it
7# under the terms and conditions of the GNU General Public License,
8# version 2, as published by the Free Software Foundation.
9#
10# This program is distributed in the hope it will be useful, but WITHOUT
11# ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
12# FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License for
13# more details.
14#
15# Authors:
16# Todd Brandt <todd.e.brandt@linux.intel.com>
17#
18# Links:
19# Home Page
20# https://01.org/suspendresume
21# Source repo
22# https://github.com/01org/pm-graph
23#
24# Description:
25# This tool is designed to assist kernel and OS developers in optimizing
26# their linux stack's suspend/resume time. Using a kernel image built
27# with a few extra options enabled, the tool will execute a suspend and
28# will capture dmesg and ftrace data until resume is complete. This data
29# is transformed into a device timeline and a callgraph to give a quick
30# and detailed view of which devices and callbacks are taking the most
31# time in suspend/resume. The output is a single html file which can be
32# viewed in firefox or chrome.
33#
34# The following kernel build options are required:
35# CONFIG_PM_DEBUG=y
36# CONFIG_PM_SLEEP_DEBUG=y
37# CONFIG_FTRACE=y
38# CONFIG_FUNCTION_TRACER=y
39# CONFIG_FUNCTION_GRAPH_TRACER=y
40# CONFIG_KPROBES=y
41# CONFIG_KPROBES_ON_FTRACE=y
42#
43# For kernel versions older than 3.15:
44# The following additional kernel parameters are required:
45# (e.g. in file /etc/default/grub)
46# GRUB_CMDLINE_LINUX_DEFAULT="... initcall_debug log_buf_len=16M ..."
47#
48
49# ----------------- LIBRARIES --------------------
50
51import sys
52import time
53import os
54import string
55import re
56import platform
57from datetime import datetime
58import struct
59import ConfigParser
60from threading import Thread
61from subprocess import call, Popen, PIPE
62
63# ----------------- CLASSES --------------------
64
65# Class: SystemValues
66# Description:
67# A global, single-instance container used to
68# store system values and test parameters
69class SystemValues:
70 title = 'SleepGraph'
71 version = '4.6'
72 ansi = False
73 verbose = False
74 addlogs = False
75 mindevlen = 0.0
76 mincglen = 0.0
77 cgphase = ''
78 cgtest = -1
79 max_graph_depth = 0
80 callloopmaxgap = 0.0001
81 callloopmaxlen = 0.005
82 srgap = 0
83 cgexp = False
84 outdir = ''
85 testdir = '.'
86 tpath = '/sys/kernel/debug/tracing/'
87 fpdtpath = '/sys/firmware/acpi/tables/FPDT'
88 epath = '/sys/kernel/debug/tracing/events/power/'
89 traceevents = [
90 'suspend_resume',
91 'device_pm_callback_end',
92 'device_pm_callback_start'
93 ]
94 logmsg = ''
95 testcommand = ''
96 mempath = '/dev/mem'
97 powerfile = '/sys/power/state'
98 suspendmode = 'mem'
99 hostname = 'localhost'
100 prefix = 'test'
101 teststamp = ''
102 dmesgstart = 0.0
103 dmesgfile = ''
104 ftracefile = ''
105 htmlfile = ''
106 embedded = False
107 rtcwake = True
108 rtcwaketime = 15
109 rtcpath = ''
110 devicefilter = []
111 stamp = 0
112 execcount = 1
113 x2delay = 0
114 usecallgraph = False
115 usetraceevents = False
116 usetraceeventsonly = False
117 usetracemarkers = True
118 usekprobes = True
119 usedevsrc = False
120 useprocmon = False
121 notestrun = False
122 mixedphaseheight = True
123 devprops = dict()
124 predelay = 0
125 postdelay = 0
126 procexecfmt = 'ps - (?P<ps>.*)$'
127 devpropfmt = '# Device Properties: .*'
128 tracertypefmt = '# tracer: (?P<t>.*)'
129 firmwarefmt = '# fwsuspend (?P<s>[0-9]*) fwresume (?P<r>[0-9]*)$'
130 stampfmt = '# suspend-(?P<m>[0-9]{2})(?P<d>[0-9]{2})(?P<y>[0-9]{2})-'+\
131 '(?P<H>[0-9]{2})(?P<M>[0-9]{2})(?P<S>[0-9]{2})'+\
132 ' (?P<host>.*) (?P<mode>.*) (?P<kernel>.*)$'
133 tracefuncs = {
134 'sys_sync': dict(),
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(),
152 'CPU_OFF': {
153 'func':'_cpu_down',
154 'args_x86_64': {'cpu':'%di:s32'},
155 'format': 'CPU_OFF[{cpu}]'
156 },
157 'CPU_ON': {
158 'func':'_cpu_up',
159 'args_x86_64': {'cpu':'%di:s32'},
160 'format': 'CPU_ON[{cpu}]'
161 },
162 }
163 dev_tracefuncs = {
164 # general wait/delay/sleep
165 'msleep': { 'args_x86_64': {'time':'%di:s32'}, 'ub': 1 },
166 'schedule_timeout_uninterruptible': { 'args_x86_64': {'timeout':'%di:s32'}, 'ub': 1 },
167 'schedule_timeout': { 'args_x86_64': {'timeout':'%di:s32'}, 'ub': 1 },
168 'udelay': { 'func':'__const_udelay', 'args_x86_64': {'loops':'%di:s32'}, 'ub': 1 },
169 'usleep_range': { 'args_x86_64': {'min':'%di:s32', 'max':'%si:s32'}, 'ub': 1 },
170 'mutex_lock_slowpath': { 'func':'__mutex_lock_slowpath', 'ub': 1 },
171 'acpi_os_stall': {'ub': 1},
172 # ACPI
173 'acpi_resume_power_resources': dict(),
174 'acpi_ps_parse_aml': dict(),
175 # filesystem
176 'ext4_sync_fs': dict(),
177 # 80211
178 'iwlagn_mac_start': dict(),
179 'iwlagn_alloc_bcast_station': dict(),
180 'iwl_trans_pcie_start_hw': dict(),
181 'iwl_trans_pcie_start_fw': dict(),
182 'iwl_run_init_ucode': dict(),
183 'iwl_load_ucode_wait_alive': dict(),
184 'iwl_alive_start': dict(),
185 'iwlagn_mac_stop': dict(),
186 'iwlagn_mac_suspend': dict(),
187 'iwlagn_mac_resume': dict(),
188 'iwlagn_mac_add_interface': dict(),
189 'iwlagn_mac_remove_interface': dict(),
190 'iwlagn_mac_change_interface': dict(),
191 'iwlagn_mac_config': dict(),
192 'iwlagn_configure_filter': dict(),
193 'iwlagn_mac_hw_scan': dict(),
194 'iwlagn_bss_info_changed': dict(),
195 'iwlagn_mac_channel_switch': dict(),
196 'iwlagn_mac_flush': dict(),
197 # ATA
198 'ata_eh_recover': { 'args_x86_64': {'port':'+36(%di):s32'} },
199 # i915
200 'i915_gem_resume': dict(),
201 'i915_restore_state': dict(),
202 'intel_opregion_setup': dict(),
203 'g4x_pre_enable_dp': dict(),
204 'vlv_pre_enable_dp': dict(),
205 'chv_pre_enable_dp': dict(),
206 'g4x_enable_dp': dict(),
207 'vlv_enable_dp': dict(),
208 'intel_hpd_init': dict(),
209 'intel_opregion_register': dict(),
210 'intel_dp_detect': dict(),
211 'intel_hdmi_detect': dict(),
212 'intel_opregion_init': dict(),
213 'intel_fbdev_set_suspend': dict(),
214 }
215 kprobes = dict()
216 timeformat = '%.3f'
217 def __init__(self):
218 # if this is a phoronix test run, set some default options
219 if('LOG_FILE' in os.environ and 'TEST_RESULTS_IDENTIFIER' in os.environ):
220 self.embedded = True
221 self.addlogs = True
222 self.htmlfile = os.environ['LOG_FILE']
223 self.archargs = 'args_'+platform.machine()
224 self.hostname = platform.node()
225 if(self.hostname == ''):
226 self.hostname = 'localhost'
227 rtc = "rtc0"
228 if os.path.exists('/dev/rtc'):
229 rtc = os.readlink('/dev/rtc')
230 rtc = '/sys/class/rtc/'+rtc
231 if os.path.exists(rtc) and os.path.exists(rtc+'/date') and \
232 os.path.exists(rtc+'/time') and os.path.exists(rtc+'/wakealarm'):
233 self.rtcpath = rtc
234 if (hasattr(sys.stdout, 'isatty') and sys.stdout.isatty()):
235 self.ansi = True
236 def rootUser(self, fatal=False):
237 if 'USER' in os.environ and os.environ['USER'] == 'root':
238 return True
239 if fatal:
240 doError('This command must be run as root')
241 return False
242 def setPrecision(self, num):
243 if num < 0 or num > 6:
244 return
245 self.timeformat = '%.{0}f'.format(num)
246 def setOutputFolder(self, value):
247 args = dict()
248 n = datetime.now()
249 args['date'] = n.strftime('%y%m%d')
250 args['time'] = n.strftime('%H%M%S')
251 args['hostname'] = self.hostname
252 self.outdir = value.format(**args)
253 def setOutputFile(self):
254 if((self.htmlfile == '') and (self.dmesgfile != '')):
255 m = re.match('(?P<name>.*)_dmesg\.txt$', self.dmesgfile)
256 if(m):
257 self.htmlfile = m.group('name')+'.html'
258 if((self.htmlfile == '') and (self.ftracefile != '')):
259 m = re.match('(?P<name>.*)_ftrace\.txt$', self.ftracefile)
260 if(m):
261 self.htmlfile = m.group('name')+'.html'
262 if(self.htmlfile == ''):
263 self.htmlfile = 'output.html'
264 def initTestOutput(self, subdir, testpath=''):
265 self.prefix = self.hostname
266 v = open('/proc/version', 'r').read().strip()
267 kver = string.split(v)[2]
268 n = datetime.now()
269 testtime = n.strftime('suspend-%m%d%y-%H%M%S')
270 if not testpath:
271 testpath = n.strftime('suspend-%y%m%d-%H%M%S')
272 if(subdir != "."):
273 self.testdir = subdir+"/"+testpath
274 else:
275 self.testdir = testpath
276 self.teststamp = \
277 '# '+testtime+' '+self.prefix+' '+self.suspendmode+' '+kver
278 if(self.embedded):
279 self.dmesgfile = \
280 '/tmp/'+testtime+'_'+self.suspendmode+'_dmesg.txt'
281 self.ftracefile = \
282 '/tmp/'+testtime+'_'+self.suspendmode+'_ftrace.txt'
283 return
284 self.dmesgfile = \
285 self.testdir+'/'+self.prefix+'_'+self.suspendmode+'_dmesg.txt'
286 self.ftracefile = \
287 self.testdir+'/'+self.prefix+'_'+self.suspendmode+'_ftrace.txt'
288 self.htmlfile = \
289 self.testdir+'/'+self.prefix+'_'+self.suspendmode+'.html'
290 if not os.path.isdir(self.testdir):
291 os.mkdir(self.testdir)
292 def setDeviceFilter(self, value):
293 self.devicefilter = []
294 if value:
295 value = value.split(',')
296 for i in value:
297 self.devicefilter.append(i.strip())
298 def rtcWakeAlarmOn(self):
299 call('echo 0 > '+self.rtcpath+'/wakealarm', shell=True)
300 outD = open(self.rtcpath+'/date', 'r').read().strip()
301 outT = open(self.rtcpath+'/time', 'r').read().strip()
302 mD = re.match('^(?P<y>[0-9]*)-(?P<m>[0-9]*)-(?P<d>[0-9]*)', outD)
303 mT = re.match('^(?P<h>[0-9]*):(?P<m>[0-9]*):(?P<s>[0-9]*)', outT)
304 if(mD and mT):
305 # get the current time from hardware
306 utcoffset = int((datetime.now() - datetime.utcnow()).total_seconds())
307 dt = datetime(\
308 int(mD.group('y')), int(mD.group('m')), int(mD.group('d')),
309 int(mT.group('h')), int(mT.group('m')), int(mT.group('s')))
310 nowtime = int(dt.strftime('%s')) + utcoffset
311 else:
312 # if hardware time fails, use the software time
313 nowtime = int(datetime.now().strftime('%s'))
314 alarm = nowtime + self.rtcwaketime
315 call('echo %d > %s/wakealarm' % (alarm, self.rtcpath), shell=True)
316 def rtcWakeAlarmOff(self):
317 call('echo 0 > %s/wakealarm' % self.rtcpath, shell=True)
318 def initdmesg(self):
319 # get the latest time stamp from the dmesg log
320 fp = Popen('dmesg', stdout=PIPE).stdout
321 ktime = '0'
322 for line in fp:
323 line = line.replace('\r\n', '')
324 idx = line.find('[')
325 if idx > 1:
326 line = line[idx:]
327 m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line)
328 if(m):
329 ktime = m.group('ktime')
330 fp.close()
331 self.dmesgstart = float(ktime)
332 def getdmesg(self):
333 # store all new dmesg lines since initdmesg was called
334 fp = Popen('dmesg', stdout=PIPE).stdout
335 op = open(self.dmesgfile, 'a')
336 for line in fp:
337 line = line.replace('\r\n', '')
338 idx = line.find('[')
339 if idx > 1:
340 line = line[idx:]
341 m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line)
342 if(not m):
343 continue
344 ktime = float(m.group('ktime'))
345 if ktime > self.dmesgstart:
346 op.write(line)
347 fp.close()
348 op.close()
349 def addFtraceFilterFunctions(self, file):
350 fp = open(file)
351 list = fp.read().split('\n')
352 fp.close()
353 for i in list:
354 if len(i) < 2:
355 continue
356 self.tracefuncs[i] = dict()
357 def getFtraceFilterFunctions(self, current):
358 rootCheck(True)
359 if not current:
360 call('cat '+self.tpath+'available_filter_functions', shell=True)
361 return
362 fp = open(self.tpath+'available_filter_functions')
363 master = fp.read().split('\n')
364 fp.close()
365 for i in self.tracefuncs:
366 if 'func' in self.tracefuncs[i]:
367 i = self.tracefuncs[i]['func']
368 if i in master:
369 print i
370 else:
371 print self.colorText(i)
372 def setFtraceFilterFunctions(self, list):
373 fp = open(self.tpath+'available_filter_functions')
374 master = fp.read().split('\n')
375 fp.close()
376 flist = ''
377 for i in list:
378 if i not in master:
379 continue
380 if ' [' in i:
381 flist += i.split(' ')[0]+'\n'
382 else:
383 flist += i+'\n'
384 fp = open(self.tpath+'set_graph_function', 'w')
385 fp.write(flist)
386 fp.close()
387 def basicKprobe(self, name):
388 self.kprobes[name] = {'name': name,'func': name,'args': dict(),'format': name}
389 def defaultKprobe(self, name, kdata):
390 k = kdata
391 for field in ['name', 'format', 'func']:
392 if field not in k:
393 k[field] = name
394 if self.archargs in k:
395 k['args'] = k[self.archargs]
396 else:
397 k['args'] = dict()
398 k['format'] = name
399 self.kprobes[name] = k
400 def kprobeColor(self, name):
401 if name not in self.kprobes or 'color' not in self.kprobes[name]:
402 return ''
403 return self.kprobes[name]['color']
404 def kprobeDisplayName(self, name, dataraw):
405 if name not in self.kprobes:
406 self.basicKprobe(name)
407 data = ''
408 quote=0
409 # first remvoe any spaces inside quotes, and the quotes
410 for c in dataraw:
411 if c == '"':
412 quote = (quote + 1) % 2
413 if quote and c == ' ':
414 data += '_'
415 elif c != '"':
416 data += c
417 fmt, args = self.kprobes[name]['format'], self.kprobes[name]['args']
418 arglist = dict()
419 # now process the args
420 for arg in sorted(args):
421 arglist[arg] = ''
422 m = re.match('.* '+arg+'=(?P<arg>.*) ', data);
423 if m:
424 arglist[arg] = m.group('arg')
425 else:
426 m = re.match('.* '+arg+'=(?P<arg>.*)', data);
427 if m:
428 arglist[arg] = m.group('arg')
429 out = fmt.format(**arglist)
430 out = out.replace(' ', '_').replace('"', '')
431 return out
432 def kprobeText(self, kname, kprobe):
433 name = fmt = func = kname
434 args = dict()
435 if 'name' in kprobe:
436 name = kprobe['name']
437 if 'format' in kprobe:
438 fmt = kprobe['format']
439 if 'func' in kprobe:
440 func = kprobe['func']
441 if self.archargs in kprobe:
442 args = kprobe[self.archargs]
443 if 'args' in kprobe:
444 args = kprobe['args']
445 if re.findall('{(?P<n>[a-z,A-Z,0-9]*)}', func):
446 doError('Kprobe "%s" has format info in the function name "%s"' % (name, func))
447 for arg in re.findall('{(?P<n>[a-z,A-Z,0-9]*)}', fmt):
448 if arg not in args:
449 doError('Kprobe "%s" is missing argument "%s"' % (name, arg))
450 val = 'p:%s_cal %s' % (name, func)
451 for i in sorted(args):
452 val += ' %s=%s' % (i, args[i])
453 val += '\nr:%s_ret %s $retval\n' % (name, func)
454 return val
455 def addKprobes(self, output=False):
456 if len(sysvals.kprobes) < 1:
457 return
458 if output:
459 print(' kprobe functions in this kernel:')
460 # first test each kprobe
461 rejects = []
462 # sort kprobes: trace, ub-dev, custom, dev
463 kpl = [[], [], [], []]
464 for name in sorted(self.kprobes):
465 res = self.colorText('YES', 32)
466 if not self.testKprobe(name, self.kprobes[name]):
467 res = self.colorText('NO')
468 rejects.append(name)
469 else:
470 if name in self.tracefuncs:
471 kpl[0].append(name)
472 elif name in self.dev_tracefuncs:
473 if 'ub' in self.dev_tracefuncs[name]:
474 kpl[1].append(name)
475 else:
476 kpl[3].append(name)
477 else:
478 kpl[2].append(name)
479 if output:
480 print(' %s: %s' % (name, res))
481 kplist = kpl[0] + kpl[1] + kpl[2] + kpl[3]
482 # remove all failed ones from the list
483 for name in rejects:
484 self.kprobes.pop(name)
485 # set the kprobes all at once
486 self.fsetVal('', 'kprobe_events')
487 kprobeevents = ''
488 for kp in kplist:
489 kprobeevents += self.kprobeText(kp, self.kprobes[kp])
490 self.fsetVal(kprobeevents, 'kprobe_events')
491 # verify that the kprobes were set as ordered
492 check = self.fgetVal('kprobe_events')
493 linesout = len(kprobeevents.split('\n')) - 1
494 linesack = len(check.split('\n')) - 1
495 if output:
496 res = '%d/%d' % (linesack, linesout)
497 if linesack < linesout:
498 res = self.colorText(res, 31)
499 else:
500 res = self.colorText(res, 32)
501 print(' working kprobe functions enabled: %s' % res)
502 self.fsetVal('1', 'events/kprobes/enable')
503 def testKprobe(self, kname, kprobe):
504 self.fsetVal('0', 'events/kprobes/enable')
505 kprobeevents = self.kprobeText(kname, kprobe)
506 if not kprobeevents:
507 return False
508 try:
509 self.fsetVal(kprobeevents, 'kprobe_events')
510 check = self.fgetVal('kprobe_events')
511 except:
512 return False
513 linesout = len(kprobeevents.split('\n'))
514 linesack = len(check.split('\n'))
515 if linesack < linesout:
516 return False
517 return True
518 def fsetVal(self, val, path, mode='w'):
519 file = self.tpath+path
520 if not os.path.exists(file):
521 return False
522 try:
523 fp = open(file, mode, 0)
524 fp.write(val)
525 fp.flush()
526 fp.close()
527 except:
528 pass
529 return True
530 def fgetVal(self, path):
531 file = self.tpath+path
532 res = ''
533 if not os.path.exists(file):
534 return res
535 try:
536 fp = open(file, 'r')
537 res = fp.read()
538 fp.close()
539 except:
540 pass
541 return res
542 def cleanupFtrace(self):
543 if(self.usecallgraph or self.usetraceevents):
544 self.fsetVal('0', 'events/kprobes/enable')
545 self.fsetVal('', 'kprobe_events')
546 def setupAllKprobes(self):
547 for name in self.tracefuncs:
548 self.defaultKprobe(name, self.tracefuncs[name])
549 for name in self.dev_tracefuncs:
550 self.defaultKprobe(name, self.dev_tracefuncs[name])
551 def isCallgraphFunc(self, name):
552 if len(self.tracefuncs) < 1 and self.suspendmode == 'command':
553 return True
554 for i in self.tracefuncs:
555 if 'func' in self.tracefuncs[i]:
556 f = self.tracefuncs[i]['func']
557 else:
558 f = i
559 if name == f:
560 return True
561 return False
562 def initFtrace(self, testing=False):
563 print('INITIALIZING FTRACE...')
564 # turn trace off
565 self.fsetVal('0', 'tracing_on')
566 self.cleanupFtrace()
567 # set the trace clock to global
568 self.fsetVal('global', 'trace_clock')
569 # set trace buffer to a huge value
570 self.fsetVal('nop', 'current_tracer')
571 self.fsetVal('131073', 'buffer_size_kb')
572 # go no further if this is just a status check
573 if testing:
574 return
575 # initialize the callgraph trace
576 if(self.usecallgraph):
577 # set trace type
578 self.fsetVal('function_graph', 'current_tracer')
579 self.fsetVal('', 'set_ftrace_filter')
580 # set trace format options
581 self.fsetVal('print-parent', 'trace_options')
582 self.fsetVal('funcgraph-abstime', 'trace_options')
583 self.fsetVal('funcgraph-cpu', 'trace_options')
584 self.fsetVal('funcgraph-duration', 'trace_options')
585 self.fsetVal('funcgraph-proc', 'trace_options')
586 self.fsetVal('funcgraph-tail', 'trace_options')
587 self.fsetVal('nofuncgraph-overhead', 'trace_options')
588 self.fsetVal('context-info', 'trace_options')
589 self.fsetVal('graph-time', 'trace_options')
590 self.fsetVal('%d' % self.max_graph_depth, 'max_graph_depth')
591 cf = ['dpm_run_callback']
592 if(self.usetraceeventsonly):
593 cf += ['dpm_prepare', 'dpm_complete']
594 for fn in self.tracefuncs:
595 if 'func' in self.tracefuncs[fn]:
596 cf.append(self.tracefuncs[fn]['func'])
597 else:
598 cf.append(fn)
599 self.setFtraceFilterFunctions(cf)
600 # initialize the kprobe trace
601 elif self.usekprobes:
602 for name in self.tracefuncs:
603 self.defaultKprobe(name, self.tracefuncs[name])
604 if self.usedevsrc:
605 for name in self.dev_tracefuncs:
606 self.defaultKprobe(name, self.dev_tracefuncs[name])
607 print('INITIALIZING KPROBES...')
608 self.addKprobes(self.verbose)
609 if(self.usetraceevents):
610 # turn trace events on
611 events = iter(self.traceevents)
612 for e in events:
613 self.fsetVal('1', 'events/power/'+e+'/enable')
614 # clear the trace buffer
615 self.fsetVal('', 'trace')
616 def verifyFtrace(self):
617 # files needed for any trace data
618 files = ['buffer_size_kb', 'current_tracer', 'trace', 'trace_clock',
619 'trace_marker', 'trace_options', 'tracing_on']
620 # files needed for callgraph trace data
621 tp = self.tpath
622 if(self.usecallgraph):
623 files += [
624 'available_filter_functions',
625 'set_ftrace_filter',
626 'set_graph_function'
627 ]
628 for f in files:
629 if(os.path.exists(tp+f) == False):
630 return False
631 return True
632 def verifyKprobes(self):
633 # files needed for kprobes to work
634 files = ['kprobe_events', 'events']
635 tp = self.tpath
636 for f in files:
637 if(os.path.exists(tp+f) == False):
638 return False
639 return True
640 def colorText(self, str, color=31):
641 if not self.ansi:
642 return str
643 return '\x1B[%d;40m%s\x1B[m' % (color, str)
644
645sysvals = SystemValues()
646suspendmodename = {
647 'freeze': 'Freeze (S0)',
648 'standby': 'Standby (S1)',
649 'mem': 'Suspend (S3)',
650 'disk': 'Hibernate (S4)'
651}
652
653# Class: DevProps
654# Description:
655# Simple class which holds property values collected
656# for all the devices used in the timeline.
657class DevProps:
658 syspath = ''
659 altname = ''
660 async = True
661 xtraclass = ''
662 xtrainfo = ''
663 def out(self, dev):
664 return '%s,%s,%d;' % (dev, self.altname, self.async)
665 def debug(self, dev):
666 print '%s:\n\taltname = %s\n\t async = %s' % (dev, self.altname, self.async)
667 def altName(self, dev):
668 if not self.altname or self.altname == dev:
669 return dev
670 return '%s [%s]' % (self.altname, dev)
671 def xtraClass(self):
672 if self.xtraclass:
673 return ' '+self.xtraclass
674 if not self.async:
675 return ' sync'
676 return ''
677 def xtraInfo(self):
678 if self.xtraclass:
679 return ' '+self.xtraclass
680 if self.async:
681 return ' async_device'
682 return ' sync_device'
683
684# Class: DeviceNode
685# Description:
686# A container used to create a device hierachy, with a single root node
687# and a tree of child nodes. Used by Data.deviceTopology()
688class DeviceNode:
689 name = ''
690 children = 0
691 depth = 0
692 def __init__(self, nodename, nodedepth):
693 self.name = nodename
694 self.children = []
695 self.depth = nodedepth
696
697# Class: Data
698# Description:
699# The primary container for suspend/resume test data. There is one for
700# each test run. The data is organized into a cronological hierarchy:
701# Data.dmesg {
702# phases {
703# 10 sequential, non-overlapping phases of S/R
704# contents: times for phase start/end, order/color data for html
705# devlist {
706# device callback or action list for this phase
707# device {
708# a single device callback or generic action
709# contents: start/stop times, pid/cpu/driver info
710# parents/children, html id for timeline/callgraph
711# optionally includes an ftrace callgraph
712# optionally includes dev/ps data
713# }
714# }
715# }
716# }
717#
718class Data:
719 dmesg = {} # root data structure
720 phases = [] # ordered list of phases
721 start = 0.0 # test start
722 end = 0.0 # test end
723 tSuspended = 0.0 # low-level suspend start
724 tResumed = 0.0 # low-level resume start
725 tKernSus = 0.0 # kernel level suspend start
726 tKernRes = 0.0 # kernel level resume end
727 tLow = 0.0 # time spent in low-level suspend (standby/freeze)
728 fwValid = False # is firmware data available
729 fwSuspend = 0 # time spent in firmware suspend
730 fwResume = 0 # time spent in firmware resume
731 dmesgtext = [] # dmesg text file in memory
732 pstl = 0 # process timeline
733 testnumber = 0
734 idstr = ''
735 html_device_id = 0
736 stamp = 0
737 outfile = ''
738 devpids = []
739 kerror = False
740 def __init__(self, num):
741 idchar = 'abcdefghij'
742 self.pstl = dict()
743 self.testnumber = num
744 self.idstr = idchar[num]
745 self.dmesgtext = []
746 self.phases = []
747 self.dmesg = { # fixed list of 10 phases
748 'suspend_prepare': {'list': dict(), 'start': -1.0, 'end': -1.0,
749 'row': 0, 'color': '#CCFFCC', 'order': 0},
750 'suspend': {'list': dict(), 'start': -1.0, 'end': -1.0,
751 'row': 0, 'color': '#88FF88', 'order': 1},
752 'suspend_late': {'list': dict(), 'start': -1.0, 'end': -1.0,
753 'row': 0, 'color': '#00AA00', 'order': 2},
754 'suspend_noirq': {'list': dict(), 'start': -1.0, 'end': -1.0,
755 'row': 0, 'color': '#008888', 'order': 3},
756 'suspend_machine': {'list': dict(), 'start': -1.0, 'end': -1.0,
757 'row': 0, 'color': '#0000FF', 'order': 4},
758 'resume_machine': {'list': dict(), 'start': -1.0, 'end': -1.0,
759 'row': 0, 'color': '#FF0000', 'order': 5},
760 'resume_noirq': {'list': dict(), 'start': -1.0, 'end': -1.0,
761 'row': 0, 'color': '#FF9900', 'order': 6},
762 'resume_early': {'list': dict(), 'start': -1.0, 'end': -1.0,
763 'row': 0, 'color': '#FFCC00', 'order': 7},
764 'resume': {'list': dict(), 'start': -1.0, 'end': -1.0,
765 'row': 0, 'color': '#FFFF88', 'order': 8},
766 'resume_complete': {'list': dict(), 'start': -1.0, 'end': -1.0,
767 'row': 0, 'color': '#FFFFCC', 'order': 9}
768 }
769 self.phases = self.sortedPhases()
770 self.devicegroups = []
771 for phase in self.phases:
772 self.devicegroups.append([phase])
773 self.errorinfo = {'suspend':[],'resume':[]}
774 def extractErrorInfo(self, dmesg):
775 error = ''
776 tm = 0.0
777 for i in range(len(dmesg)):
778 if 'Call Trace:' in dmesg[i]:
779 m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) .*', dmesg[i])
780 if not m:
781 continue
782 tm = float(m.group('ktime'))
783 if tm < self.start or tm > self.end:
784 continue
785 for j in range(i-10, i+1):
786 error += dmesg[j]
787 continue
788 if error:
789 m = re.match('[ \t]*\[ *[0-9\.]*\] \[\<[0-9a-fA-F]*\>\] .*', dmesg[i])
790 if m:
791 error += dmesg[i]
792 else:
793 if tm < self.tSuspended:
794 dir = 'suspend'
795 else:
796 dir = 'resume'
797 error = error.replace('<', '&lt').replace('>', '&gt')
798 vprint('kernel error found in %s at %f' % (dir, tm))
799 self.errorinfo[dir].append((tm, error))
800 self.kerror = True
801 error = ''
802 def setStart(self, time):
803 self.start = time
804 def setEnd(self, time):
805 self.end = time
806 def isTraceEventOutsideDeviceCalls(self, pid, time):
807 for phase in self.phases:
808 list = self.dmesg[phase]['list']
809 for dev in list:
810 d = list[dev]
811 if(d['pid'] == pid and time >= d['start'] and
812 time < d['end']):
813 return False
814 return True
815 def sourcePhase(self, start):
816 for phase in self.phases:
817 pend = self.dmesg[phase]['end']
818 if start <= pend:
819 return phase
820 return 'resume_complete'
821 def sourceDevice(self, phaselist, start, end, pid, type):
822 tgtdev = ''
823 for phase in phaselist:
824 list = self.dmesg[phase]['list']
825 for devname in list:
826 dev = list[devname]
827 # pid must match
828 if dev['pid'] != pid:
829 continue
830 devS = dev['start']
831 devE = dev['end']
832 if type == 'device':
833 # device target event is entirely inside the source boundary
834 if(start < devS or start >= devE or end <= devS or end > devE):
835 continue
836 elif type == 'thread':
837 # thread target event will expand the source boundary
838 if start < devS:
839 dev['start'] = start
840 if end > devE:
841 dev['end'] = end
842 tgtdev = dev
843 break
844 return tgtdev
845 def addDeviceFunctionCall(self, displayname, kprobename, proc, pid, start, end, cdata, rdata):
846 # try to place the call in a device
847 tgtdev = self.sourceDevice(self.phases, start, end, pid, 'device')
848 # calls with device pids that occur outside device bounds are dropped
849 # TODO: include these somehow
850 if not tgtdev and pid in self.devpids:
851 return False
852 # try to place the call in a thread
853 if not tgtdev:
854 tgtdev = self.sourceDevice(self.phases, start, end, pid, 'thread')
855 # create new thread blocks, expand as new calls are found
856 if not tgtdev:
857 if proc == '<...>':
858 threadname = 'kthread-%d' % (pid)
859 else:
860 threadname = '%s-%d' % (proc, pid)
861 tgtphase = self.sourcePhase(start)
862 self.newAction(tgtphase, threadname, pid, '', start, end, '', ' kth', '')
863 return self.addDeviceFunctionCall(displayname, kprobename, proc, pid, start, end, cdata, rdata)
864 # this should not happen
865 if not tgtdev:
866 vprint('[%f - %f] %s-%d %s %s %s' % \
867 (start, end, proc, pid, kprobename, cdata, rdata))
868 return False
869 # place the call data inside the src element of the tgtdev
870 if('src' not in tgtdev):
871 tgtdev['src'] = []
872 dtf = sysvals.dev_tracefuncs
873 ubiquitous = False
874 if kprobename in dtf and 'ub' in dtf[kprobename]:
875 ubiquitous = True
876 title = cdata+' '+rdata
877 mstr = '\(.*\) *(?P<args>.*) *\((?P<caller>.*)\+.* arg1=(?P<ret>.*)'
878 m = re.match(mstr, title)
879 if m:
880 c = m.group('caller')
881 a = m.group('args').strip()
882 r = m.group('ret')
883 if len(r) > 6:
884 r = ''
885 else:
886 r = 'ret=%s ' % r
887 if ubiquitous and c in dtf and 'ub' in dtf[c]:
888 return False
889 color = sysvals.kprobeColor(kprobename)
890 e = DevFunction(displayname, a, c, r, start, end, ubiquitous, proc, pid, color)
891 tgtdev['src'].append(e)
892 return True
893 def overflowDevices(self):
894 # get a list of devices that extend beyond the end of this test run
895 devlist = []
896 for phase in self.phases:
897 list = self.dmesg[phase]['list']
898 for devname in list:
899 dev = list[devname]
900 if dev['end'] > self.end:
901 devlist.append(dev)
902 return devlist
903 def mergeOverlapDevices(self, devlist):
904 # merge any devices that overlap devlist
905 for dev in devlist:
906 devname = dev['name']
907 for phase in self.phases:
908 list = self.dmesg[phase]['list']
909 if devname not in list:
910 continue
911 tdev = list[devname]
912 o = min(dev['end'], tdev['end']) - max(dev['start'], tdev['start'])
913 if o <= 0:
914 continue
915 dev['end'] = tdev['end']
916 if 'src' not in dev or 'src' not in tdev:
917 continue
918 dev['src'] += tdev['src']
919 del list[devname]
920 def usurpTouchingThread(self, name, dev):
921 # the caller test has priority of this thread, give it to him
922 for phase in self.phases:
923 list = self.dmesg[phase]['list']
924 if name in list:
925 tdev = list[name]
926 if tdev['start'] - dev['end'] < 0.1:
927 dev['end'] = tdev['end']
928 if 'src' not in dev:
929 dev['src'] = []
930 if 'src' in tdev:
931 dev['src'] += tdev['src']
932 del list[name]
933 break
934 def stitchTouchingThreads(self, testlist):
935 # merge any threads between tests that touch
936 for phase in self.phases:
937 list = self.dmesg[phase]['list']
938 for devname in list:
939 dev = list[devname]
940 if 'htmlclass' not in dev or 'kth' not in dev['htmlclass']:
941 continue
942 for data in testlist:
943 data.usurpTouchingThread(devname, dev)
944 def optimizeDevSrc(self):
945 # merge any src call loops to reduce timeline size
946 for phase in self.phases:
947 list = self.dmesg[phase]['list']
948 for dev in list:
949 if 'src' not in list[dev]:
950 continue
951 src = list[dev]['src']
952 p = 0
953 for e in sorted(src, key=lambda event: event.time):
954 if not p or not e.repeat(p):
955 p = e
956 continue
957 # e is another iteration of p, move it into p
958 p.end = e.end
959 p.length = p.end - p.time
960 p.count += 1
961 src.remove(e)
962 def trimTimeVal(self, t, t0, dT, left):
963 if left:
964 if(t > t0):
965 if(t - dT < t0):
966 return t0
967 return t - dT
968 else:
969 return t
970 else:
971 if(t < t0 + dT):
972 if(t > t0):
973 return t0 + dT
974 return t + dT
975 else:
976 return t
977 def trimTime(self, t0, dT, left):
978 self.tSuspended = self.trimTimeVal(self.tSuspended, t0, dT, left)
979 self.tResumed = self.trimTimeVal(self.tResumed, t0, dT, left)
980 self.start = self.trimTimeVal(self.start, t0, dT, left)
981 self.tKernSus = self.trimTimeVal(self.tKernSus, t0, dT, left)
982 self.tKernRes = self.trimTimeVal(self.tKernRes, t0, dT, left)
983 self.end = self.trimTimeVal(self.end, t0, dT, left)
984 for phase in self.phases:
985 p = self.dmesg[phase]
986 p['start'] = self.trimTimeVal(p['start'], t0, dT, left)
987 p['end'] = self.trimTimeVal(p['end'], t0, dT, left)
988 list = p['list']
989 for name in list:
990 d = list[name]
991 d['start'] = self.trimTimeVal(d['start'], t0, dT, left)
992 d['end'] = self.trimTimeVal(d['end'], t0, dT, left)
993 if('ftrace' in d):
994 cg = d['ftrace']
995 cg.start = self.trimTimeVal(cg.start, t0, dT, left)
996 cg.end = self.trimTimeVal(cg.end, t0, dT, left)
997 for line in cg.list:
998 line.time = self.trimTimeVal(line.time, t0, dT, left)
999 if('src' in d):
1000 for e in d['src']:
1001 e.time = self.trimTimeVal(e.time, t0, dT, left)
1002 def normalizeTime(self, tZero):
1003 # trim out any standby or freeze clock time
1004 if(self.tSuspended != self.tResumed):
1005 if(self.tResumed > tZero):
1006 self.trimTime(self.tSuspended, \
1007 self.tResumed-self.tSuspended, True)
1008 else:
1009 self.trimTime(self.tSuspended, \
1010 self.tResumed-self.tSuspended, False)
1011 def setPhase(self, phase, ktime, isbegin):
1012 if(isbegin):
1013 self.dmesg[phase]['start'] = ktime
1014 else:
1015 self.dmesg[phase]['end'] = ktime
1016 def dmesgSortVal(self, phase):
1017 return self.dmesg[phase]['order']
1018 def sortedPhases(self):
1019 return sorted(self.dmesg, key=self.dmesgSortVal)
1020 def sortedDevices(self, phase):
1021 list = self.dmesg[phase]['list']
1022 slist = []
1023 tmp = dict()
1024 for devname in list:
1025 dev = list[devname]
1026 if dev['length'] == 0:
1027 continue
1028 tmp[dev['start']] = devname
1029 for t in sorted(tmp):
1030 slist.append(tmp[t])
1031 return slist
1032 def fixupInitcalls(self, phase):
1033 # if any calls never returned, clip them at system resume end
1034 phaselist = self.dmesg[phase]['list']
1035 for devname in phaselist:
1036 dev = phaselist[devname]
1037 if(dev['end'] < 0):
1038 for p in self.phases:
1039 if self.dmesg[p]['end'] > dev['start']:
1040 dev['end'] = self.dmesg[p]['end']
1041 break
1042 vprint('%s (%s): callback didnt return' % (devname, phase))
1043 def deviceFilter(self, devicefilter):
1044 for phase in self.phases:
1045 list = self.dmesg[phase]['list']
1046 rmlist = []
1047 for name in list:
1048 keep = False
1049 for filter in devicefilter:
1050 if filter in name or \
1051 ('drv' in list[name] and filter in list[name]['drv']):
1052 keep = True
1053 if not keep:
1054 rmlist.append(name)
1055 for name in rmlist:
1056 del list[name]
1057 def fixupInitcallsThatDidntReturn(self):
1058 # if any calls never returned, clip them at system resume end
1059 for phase in self.phases:
1060 self.fixupInitcalls(phase)
1061 def phaseOverlap(self, phases):
1062 rmgroups = []
1063 newgroup = []
1064 for group in self.devicegroups:
1065 for phase in phases:
1066 if phase not in group:
1067 continue
1068 for p in group:
1069 if p not in newgroup:
1070 newgroup.append(p)
1071 if group not in rmgroups:
1072 rmgroups.append(group)
1073 for group in rmgroups:
1074 self.devicegroups.remove(group)
1075 self.devicegroups.append(newgroup)
1076 def newActionGlobal(self, name, start, end, pid=-1, color=''):
1077 # which phase is this device callback or action in
1078 targetphase = 'none'
1079 htmlclass = ''
1080 overlap = 0.0
1081 phases = []
1082 for phase in self.phases:
1083 pstart = self.dmesg[phase]['start']
1084 pend = self.dmesg[phase]['end']
1085 # see if the action overlaps this phase
1086 o = max(0, min(end, pend) - max(start, pstart))
1087 if o > 0:
1088 phases.append(phase)
1089 # set the target phase to the one that overlaps most
1090 if o > overlap:
1091 if overlap > 0 and phase == 'post_resume':
1092 continue
1093 targetphase = phase
1094 overlap = o
1095 # if no target phase was found, pin it to the edge
1096 if targetphase == 'none':
1097 p0start = self.dmesg[self.phases[0]]['start']
1098 if start <= p0start:
1099 targetphase = self.phases[0]
1100 else:
1101 targetphase = self.phases[-1]
1102 if pid == -2:
1103 htmlclass = ' bg'
1104 elif pid == -3:
1105 htmlclass = ' ps'
1106 if len(phases) > 1:
1107 htmlclass = ' bg'
1108 self.phaseOverlap(phases)
1109 if targetphase in self.phases:
1110 newname = self.newAction(targetphase, name, pid, '', start, end, '', htmlclass, color)
1111 return (targetphase, newname)
1112 return False
1113 def newAction(self, phase, name, pid, parent, start, end, drv, htmlclass='', color=''):
1114 # new device callback for a specific phase
1115 self.html_device_id += 1
1116 devid = '%s%d' % (self.idstr, self.html_device_id)
1117 list = self.dmesg[phase]['list']
1118 length = -1.0
1119 if(start >= 0 and end >= 0):
1120 length = end - start
1121 if pid == -2:
1122 i = 2
1123 origname = name
1124 while(name in list):
1125 name = '%s[%d]' % (origname, i)
1126 i += 1
1127 list[name] = {'name': name, 'start': start, 'end': end, 'pid': pid,
1128 'par': parent, 'length': length, 'row': 0, 'id': devid, 'drv': drv }
1129 if htmlclass:
1130 list[name]['htmlclass'] = htmlclass
1131 if color:
1132 list[name]['color'] = color
1133 return name
1134 def deviceChildren(self, devname, phase):
1135 devlist = []
1136 list = self.dmesg[phase]['list']
1137 for child in list:
1138 if(list[child]['par'] == devname):
1139 devlist.append(child)
1140 return devlist
1141 def printDetails(self):
1142 vprint('Timeline Details:')
1143 vprint(' test start: %f' % self.start)
1144 vprint('kernel suspend start: %f' % self.tKernSus)
1145 for phase in self.phases:
1146 dc = len(self.dmesg[phase]['list'])
1147 vprint(' %16s: %f - %f (%d devices)' % (phase, \
1148 self.dmesg[phase]['start'], self.dmesg[phase]['end'], dc))
1149 vprint(' kernel resume end: %f' % self.tKernRes)
1150 vprint(' test end: %f' % self.end)
1151 def deviceChildrenAllPhases(self, devname):
1152 devlist = []
1153 for phase in self.phases:
1154 list = self.deviceChildren(devname, phase)
1155 for dev in list:
1156 if dev not in devlist:
1157 devlist.append(dev)
1158 return devlist
1159 def masterTopology(self, name, list, depth):
1160 node = DeviceNode(name, depth)
1161 for cname in list:
1162 # avoid recursions
1163 if name == cname:
1164 continue
1165 clist = self.deviceChildrenAllPhases(cname)
1166 cnode = self.masterTopology(cname, clist, depth+1)
1167 node.children.append(cnode)
1168 return node
1169 def printTopology(self, node):
1170 html = ''
1171 if node.name:
1172 info = ''
1173 drv = ''
1174 for phase in self.phases:
1175 list = self.dmesg[phase]['list']
1176 if node.name in list:
1177 s = list[node.name]['start']
1178 e = list[node.name]['end']
1179 if list[node.name]['drv']:
1180 drv = ' {'+list[node.name]['drv']+'}'
1181 info += ('<li>%s: %.3fms</li>' % (phase, (e-s)*1000))
1182 html += '<li><b>'+node.name+drv+'</b>'
1183 if info:
1184 html += '<ul>'+info+'</ul>'
1185 html += '</li>'
1186 if len(node.children) > 0:
1187 html += '<ul>'
1188 for cnode in node.children:
1189 html += self.printTopology(cnode)
1190 html += '</ul>'
1191 return html
1192 def rootDeviceList(self):
1193 # list of devices graphed
1194 real = []
1195 for phase in self.dmesg:
1196 list = self.dmesg[phase]['list']
1197 for dev in list:
1198 if list[dev]['pid'] >= 0 and dev not in real:
1199 real.append(dev)
1200 # list of top-most root devices
1201 rootlist = []
1202 for phase in self.dmesg:
1203 list = self.dmesg[phase]['list']
1204 for dev in list:
1205 pdev = list[dev]['par']
1206 pid = list[dev]['pid']
1207 if(pid < 0 or re.match('[0-9]*-[0-9]*\.[0-9]*[\.0-9]*\:[\.0-9]*$', pdev)):
1208 continue
1209 if pdev and pdev not in real and pdev not in rootlist:
1210 rootlist.append(pdev)
1211 return rootlist
1212 def deviceTopology(self):
1213 rootlist = self.rootDeviceList()
1214 master = self.masterTopology('', rootlist, 0)
1215 return self.printTopology(master)
1216 def selectTimelineDevices(self, widfmt, tTotal, mindevlen):
1217 # only select devices that will actually show up in html
1218 self.tdevlist = dict()
1219 for phase in self.dmesg:
1220 devlist = []
1221 list = self.dmesg[phase]['list']
1222 for dev in list:
1223 length = (list[dev]['end'] - list[dev]['start']) * 1000
1224 width = widfmt % (((list[dev]['end']-list[dev]['start'])*100)/tTotal)
1225 if width != '0.000000' and length >= mindevlen:
1226 devlist.append(dev)
1227 self.tdevlist[phase] = devlist
1228 def addHorizontalDivider(self, devname, devend):
1229 phase = 'suspend_prepare'
1230 self.newAction(phase, devname, -2, '', \
1231 self.start, devend, '', ' sec', '')
1232 if phase not in self.tdevlist:
1233 self.tdevlist[phase] = []
1234 self.tdevlist[phase].append(devname)
1235 d = DevItem(0, phase, self.dmesg[phase]['list'][devname])
1236 return d
1237 def addProcessUsageEvent(self, name, times):
1238 # get the start and end times for this process
1239 maxC = 0
1240 tlast = 0
1241 start = -1
1242 end = -1
1243 for t in sorted(times):
1244 if tlast == 0:
1245 tlast = t
1246 continue
1247 if name in self.pstl[t]:
1248 if start == -1 or tlast < start:
1249 start = tlast
1250 if end == -1 or t > end:
1251 end = t
1252 tlast = t
1253 if start == -1 or end == -1:
1254 return 0
1255 # add a new action for this process and get the object
1256 out = self.newActionGlobal(name, start, end, -3)
1257 if not out:
1258 return 0
1259 phase, devname = out
1260 dev = self.dmesg[phase]['list'][devname]
1261 # get the cpu exec data
1262 tlast = 0
1263 clast = 0
1264 cpuexec = dict()
1265 for t in sorted(times):
1266 if tlast == 0 or t <= start or t > end:
1267 tlast = t
1268 continue
1269 list = self.pstl[t]
1270 c = 0
1271 if name in list:
1272 c = list[name]
1273 if c > maxC:
1274 maxC = c
1275 if c != clast:
1276 key = (tlast, t)
1277 cpuexec[key] = c
1278 tlast = t
1279 clast = c
1280 dev['cpuexec'] = cpuexec
1281 return maxC
1282 def createProcessUsageEvents(self):
1283 # get an array of process names
1284 proclist = []
1285 for t in self.pstl:
1286 pslist = self.pstl[t]
1287 for ps in pslist:
1288 if ps not in proclist:
1289 proclist.append(ps)
1290 # get a list of data points for suspend and resume
1291 tsus = []
1292 tres = []
1293 for t in sorted(self.pstl):
1294 if t < self.tSuspended:
1295 tsus.append(t)
1296 else:
1297 tres.append(t)
1298 # process the events for suspend and resume
1299 if len(proclist) > 0:
1300 vprint('Process Execution:')
1301 for ps in proclist:
1302 c = self.addProcessUsageEvent(ps, tsus)
1303 if c > 0:
1304 vprint('%25s (sus): %d' % (ps, c))
1305 c = self.addProcessUsageEvent(ps, tres)
1306 if c > 0:
1307 vprint('%25s (res): %d' % (ps, c))
1308
1309# Class: DevFunction
1310# Description:
1311# A container for kprobe function data we want in the dev timeline
1312class DevFunction:
1313 row = 0
1314 count = 1
1315 def __init__(self, name, args, caller, ret, start, end, u, proc, pid, color):
1316 self.name = name
1317 self.args = args
1318 self.caller = caller
1319 self.ret = ret
1320 self.time = start
1321 self.length = end - start
1322 self.end = end
1323 self.ubiquitous = u
1324 self.proc = proc
1325 self.pid = pid
1326 self.color = color
1327 def title(self):
1328 cnt = ''
1329 if self.count > 1:
1330 cnt = '(x%d)' % self.count
1331 l = '%0.3fms' % (self.length * 1000)
1332 if self.ubiquitous:
1333 title = '%s(%s)%s <- %s, %s(%s)' % \
1334 (self.name, self.args, cnt, self.caller, self.ret, l)
1335 else:
1336 title = '%s(%s) %s%s(%s)' % (self.name, self.args, self.ret, cnt, l)
1337 return title.replace('"', '')
1338 def text(self):
1339 if self.count > 1:
1340 text = '%s(x%d)' % (self.name, self.count)
1341 else:
1342 text = self.name
1343 return text
1344 def repeat(self, tgt):
1345 # is the tgt call just a repeat of this call (e.g. are we in a loop)
1346 dt = self.time - tgt.end
1347 # only combine calls if -all- attributes are identical
1348 if tgt.caller == self.caller and \
1349 tgt.name == self.name and tgt.args == self.args and \
1350 tgt.proc == self.proc and tgt.pid == self.pid and \
1351 tgt.ret == self.ret and dt >= 0 and \
1352 dt <= sysvals.callloopmaxgap and \
1353 self.length < sysvals.callloopmaxlen:
1354 return True
1355 return False
1356
1357# Class: FTraceLine
1358# Description:
1359# A container for a single line of ftrace data. There are six basic types:
1360# callgraph line:
1361# call: " dpm_run_callback() {"
1362# return: " }"
1363# leaf: " dpm_run_callback();"
1364# trace event:
1365# tracing_mark_write: SUSPEND START or RESUME COMPLETE
1366# suspend_resume: phase or custom exec block data
1367# device_pm_callback: device callback info
1368class FTraceLine:
1369 time = 0.0
1370 length = 0.0
1371 fcall = False
1372 freturn = False
1373 fevent = False
1374 fkprobe = False
1375 depth = 0
1376 name = ''
1377 type = ''
1378 def __init__(self, t, m='', d=''):
1379 self.time = float(t)
1380 if not m and not d:
1381 return
1382 # is this a trace event
1383 if(d == 'traceevent' or re.match('^ *\/\* *(?P<msg>.*) \*\/ *$', m)):
1384 if(d == 'traceevent'):
1385 # nop format trace event
1386 msg = m
1387 else:
1388 # function_graph format trace event
1389 em = re.match('^ *\/\* *(?P<msg>.*) \*\/ *$', m)
1390 msg = em.group('msg')
1391
1392 emm = re.match('^(?P<call>.*?): (?P<msg>.*)', msg)
1393 if(emm):
1394 self.name = emm.group('msg')
1395 self.type = emm.group('call')
1396 else:
1397 self.name = msg
1398 km = re.match('^(?P<n>.*)_cal$', self.type)
1399 if km:
1400 self.fcall = True
1401 self.fkprobe = True
1402 self.type = km.group('n')
1403 return
1404 km = re.match('^(?P<n>.*)_ret$', self.type)
1405 if km:
1406 self.freturn = True
1407 self.fkprobe = True
1408 self.type = km.group('n')
1409 return
1410 self.fevent = True
1411 return
1412 # convert the duration to seconds
1413 if(d):
1414 self.length = float(d)/1000000
1415 # the indentation determines the depth
1416 match = re.match('^(?P<d> *)(?P<o>.*)$', m)
1417 if(not match):
1418 return
1419 self.depth = self.getDepth(match.group('d'))
1420 m = match.group('o')
1421 # function return
1422 if(m[0] == '}'):
1423 self.freturn = True
1424 if(len(m) > 1):
1425 # includes comment with function name
1426 match = re.match('^} *\/\* *(?P<n>.*) *\*\/$', m)
1427 if(match):
1428 self.name = match.group('n').strip()
1429 # function call
1430 else:
1431 self.fcall = True
1432 # function call with children
1433 if(m[-1] == '{'):
1434 match = re.match('^(?P<n>.*) *\(.*', m)
1435 if(match):
1436 self.name = match.group('n').strip()
1437 # function call with no children (leaf)
1438 elif(m[-1] == ';'):
1439 self.freturn = True
1440 match = re.match('^(?P<n>.*) *\(.*', m)
1441 if(match):
1442 self.name = match.group('n').strip()
1443 # something else (possibly a trace marker)
1444 else:
1445 self.name = m
1446 def getDepth(self, str):
1447 return len(str)/2
1448 def debugPrint(self, dev=''):
1449 if(self.freturn and self.fcall):
1450 print('%s -- %f (%02d): %s(); (%.3f us)' % (dev, self.time, \
1451 self.depth, self.name, self.length*1000000))
1452 elif(self.freturn):
1453 print('%s -- %f (%02d): %s} (%.3f us)' % (dev, self.time, \
1454 self.depth, self.name, self.length*1000000))
1455 else:
1456 print('%s -- %f (%02d): %s() { (%.3f us)' % (dev, self.time, \
1457 self.depth, self.name, self.length*1000000))
1458 def startMarker(self):
1459 # Is this the starting line of a suspend?
1460 if not self.fevent:
1461 return False
1462 if sysvals.usetracemarkers:
1463 if(self.name == 'SUSPEND START'):
1464 return True
1465 return False
1466 else:
1467 if(self.type == 'suspend_resume' and
1468 re.match('suspend_enter\[.*\] begin', self.name)):
1469 return True
1470 return False
1471 def endMarker(self):
1472 # Is this the ending line of a resume?
1473 if not self.fevent:
1474 return False
1475 if sysvals.usetracemarkers:
1476 if(self.name == 'RESUME COMPLETE'):
1477 return True
1478 return False
1479 else:
1480 if(self.type == 'suspend_resume' and
1481 re.match('thaw_processes\[.*\] end', self.name)):
1482 return True
1483 return False
1484
1485# Class: FTraceCallGraph
1486# Description:
1487# A container for the ftrace callgraph of a single recursive function.
1488# This can be a dpm_run_callback, dpm_prepare, or dpm_complete callgraph
1489# Each instance is tied to a single device in a single phase, and is
1490# comprised of an ordered list of FTraceLine objects
1491class FTraceCallGraph:
1492 id = ''
1493 start = -1.0
1494 end = -1.0
1495 list = []
1496 invalid = False
1497 depth = 0
1498 pid = 0
1499 name = ''
1500 def __init__(self, pid):
1501 self.start = -1.0
1502 self.end = -1.0
1503 self.list = []
1504 self.depth = 0
1505 self.pid = pid
1506 def addLine(self, line, debug=False):
1507 # if this is already invalid, just leave
1508 if(self.invalid):
1509 return False
1510 # invalidate on too much data or bad depth
1511 if(len(self.list) >= 1000000 or self.depth < 0):
1512 self.invalidate(line)
1513 return False
1514 # compare current depth with this lines pre-call depth
1515 prelinedep = line.depth
1516 if(line.freturn and not line.fcall):
1517 prelinedep += 1
1518 last = 0
1519 lasttime = line.time
1520 virtualfname = 'execution_misalignment'
1521 if len(self.list) > 0:
1522 last = self.list[-1]
1523 lasttime = last.time
1524 # handle low misalignments by inserting returns
1525 if prelinedep < self.depth:
1526 if debug and last:
1527 print '-------- task %d --------' % self.pid
1528 last.debugPrint()
1529 idx = 0
1530 # add return calls to get the depth down
1531 while prelinedep < self.depth:
1532 if debug:
1533 print 'MISALIGN LOW (add returns): C%d - eC%d' % (self.depth, prelinedep)
1534 self.depth -= 1
1535 if idx == 0 and last and last.fcall and not last.freturn:
1536 # special case, turn last call into a leaf
1537 last.depth = self.depth
1538 last.freturn = True
1539 last.length = line.time - last.time
1540 if debug:
1541 last.debugPrint()
1542 else:
1543 vline = FTraceLine(lasttime)
1544 vline.depth = self.depth
1545 vline.name = virtualfname
1546 vline.freturn = True
1547 self.list.append(vline)
1548 if debug:
1549 vline.debugPrint()
1550 idx += 1
1551 if debug:
1552 line.debugPrint()
1553 print ''
1554 # handle high misalignments by inserting calls
1555 elif prelinedep > self.depth:
1556 if debug and last:
1557 print '-------- task %d --------' % self.pid
1558 last.debugPrint()
1559 idx = 0
1560 # add calls to get the depth up
1561 while prelinedep > self.depth:
1562 if debug:
1563 print 'MISALIGN HIGH (add calls): C%d - eC%d' % (self.depth, prelinedep)
1564 if idx == 0 and line.freturn and not line.fcall:
1565 # special case, turn this return into a leaf
1566 line.fcall = True
1567 prelinedep -= 1
1568 else:
1569 vline = FTraceLine(lasttime)
1570 vline.depth = self.depth
1571 vline.name = virtualfname
1572 vline.fcall = True
1573 if debug:
1574 vline.debugPrint()
1575 self.list.append(vline)
1576 self.depth += 1
1577 if not last:
1578 self.start = vline.time
1579 idx += 1
1580 if debug:
1581 line.debugPrint()
1582 print ''
1583 # process the call and set the new depth
1584 if(line.fcall and not line.freturn):
1585 self.depth += 1
1586 elif(line.freturn and not line.fcall):
1587 self.depth -= 1
1588 if len(self.list) < 1:
1589 self.start = line.time
1590 self.list.append(line)
1591 if(line.depth == 0 and line.freturn):
1592 if(self.start < 0):
1593 self.start = line.time
1594 self.end = line.time
1595 if line.fcall:
1596 self.end += line.length
1597 if self.list[0].name == virtualfname:
1598 self.invalid = True
1599 return True
1600 return False
1601 def invalidate(self, line):
1602 if(len(self.list) > 0):
1603 first = self.list[0]
1604 self.list = []
1605 self.list.append(first)
1606 self.invalid = True
1607 id = 'task %s' % (self.pid)
1608 window = '(%f - %f)' % (self.start, line.time)
1609 if(self.depth < 0):
1610 vprint('Too much data for '+id+\
1611 ' (buffer overflow), ignoring this callback')
1612 else:
1613 vprint('Too much data for '+id+\
1614 ' '+window+', ignoring this callback')
1615 def slice(self, t0, tN):
1616 minicg = FTraceCallGraph(0)
1617 count = -1
1618 firstdepth = 0
1619 for l in self.list:
1620 if(l.time < t0 or l.time > tN):
1621 continue
1622 if(count < 0):
1623 if(not l.fcall or l.name == 'dev_driver_string'):
1624 continue
1625 firstdepth = l.depth
1626 count = 0
1627 l.depth -= firstdepth
1628 minicg.addLine(l)
1629 if((count == 0 and l.freturn and l.fcall) or
1630 (count > 0 and l.depth <= 0)):
1631 break
1632 count += 1
1633 return minicg
1634 def repair(self, enddepth):
1635 # bring the depth back to 0 with additional returns
1636 fixed = False
1637 last = self.list[-1]
1638 for i in reversed(range(enddepth)):
1639 t = FTraceLine(last.time)
1640 t.depth = i
1641 t.freturn = True
1642 fixed = self.addLine(t)
1643 if fixed:
1644 self.end = last.time
1645 return True
1646 return False
1647 def postProcess(self, debug=False):
1648 if len(self.list) > 0:
1649 self.name = self.list[0].name
1650 stack = dict()
1651 cnt = 0
1652 last = 0
1653 for l in self.list:
1654 # ftrace bug: reported duration is not reliable
1655 # check each leaf and clip it at max possible length
1656 if(last and last.freturn and last.fcall):
1657 if last.length > l.time - last.time:
1658 last.length = l.time - last.time
1659 if(l.fcall and not l.freturn):
1660 stack[l.depth] = l
1661 cnt += 1
1662 elif(l.freturn and not l.fcall):
1663 if(l.depth not in stack):
1664 if debug:
1665 print 'Post Process Error: Depth missing'
1666 l.debugPrint()
1667 return False
1668 # calculate call length from call/return lines
1669 stack[l.depth].length = l.time - stack[l.depth].time
1670 stack.pop(l.depth)
1671 l.length = 0
1672 cnt -= 1
1673 last = l
1674 if(cnt == 0):
1675 # trace caught the whole call tree
1676 return True
1677 elif(cnt < 0):
1678 if debug:
1679 print 'Post Process Error: Depth is less than 0'
1680 return False
1681 # trace ended before call tree finished
1682 return self.repair(cnt)
1683 def deviceMatch(self, pid, data):
1684 found = False
1685 # add the callgraph data to the device hierarchy
1686 borderphase = {
1687 'dpm_prepare': 'suspend_prepare',
1688 'dpm_complete': 'resume_complete'
1689 }
1690 if(self.name in borderphase):
1691 p = borderphase[self.name]
1692 list = data.dmesg[p]['list']
1693 for devname in list:
1694 dev = list[devname]
1695 if(pid == dev['pid'] and
1696 self.start <= dev['start'] and
1697 self.end >= dev['end']):
1698 dev['ftrace'] = self.slice(dev['start'], dev['end'])
1699 found = True
1700 return found
1701 for p in data.phases:
1702 if(data.dmesg[p]['start'] <= self.start and
1703 self.start <= data.dmesg[p]['end']):
1704 list = data.dmesg[p]['list']
1705 for devname in list:
1706 dev = list[devname]
1707 if(pid == dev['pid'] and
1708 self.start <= dev['start'] and
1709 self.end >= dev['end']):
1710 dev['ftrace'] = self
1711 found = True
1712 break
1713 break
1714 return found
1715 def newActionFromFunction(self, data):
1716 name = self.name
1717 if name in ['dpm_run_callback', 'dpm_prepare', 'dpm_complete']:
1718 return
1719 fs = self.start
1720 fe = self.end
1721 if fs < data.start or fe > data.end:
1722 return
1723 phase = ''
1724 for p in data.phases:
1725 if(data.dmesg[p]['start'] <= self.start and
1726 self.start < data.dmesg[p]['end']):
1727 phase = p
1728 break
1729 if not phase:
1730 return
1731 out = data.newActionGlobal(name, fs, fe, -2)
1732 if out:
1733 phase, myname = out
1734 data.dmesg[phase]['list'][myname]['ftrace'] = self
1735 def debugPrint(self):
1736 print('[%f - %f] %s (%d)') % (self.start, self.end, self.name, self.pid)
1737 for l in self.list:
1738 if(l.freturn and l.fcall):
1739 print('%f (%02d): %s(); (%.3f us)' % (l.time, \
1740 l.depth, l.name, l.length*1000000))
1741 elif(l.freturn):
1742 print('%f (%02d): %s} (%.3f us)' % (l.time, \
1743 l.depth, l.name, l.length*1000000))
1744 else:
1745 print('%f (%02d): %s() { (%.3f us)' % (l.time, \
1746 l.depth, l.name, l.length*1000000))
1747 print(' ')
1748
1749class DevItem:
1750 def __init__(self, test, phase, dev):
1751 self.test = test
1752 self.phase = phase
1753 self.dev = dev
1754 def isa(self, cls):
1755 if 'htmlclass' in self.dev and cls in self.dev['htmlclass']:
1756 return True
1757 return False
1758
1759# Class: Timeline
1760# Description:
1761# A container for a device timeline which calculates
1762# all the html properties to display it correctly
1763class Timeline:
1764 html = ''
1765 height = 0 # total timeline height
1766 scaleH = 20 # timescale (top) row height
1767 rowH = 30 # device row height
1768 bodyH = 0 # body height
1769 rows = 0 # total timeline rows
1770 rowlines = dict()
1771 rowheight = dict()
1772 html_tblock = '<div id="block{0}" class="tblock" style="left:{1}%;width:{2}%;"><div class="tback" style="height:{3}px"></div>\n'
1773 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'
1774 html_phase = '<div class="phase" style="left:{0}%;width:{1}%;top:{2}px;height:{3}px;background:{4}">{5}</div>\n'
1775 html_phaselet = '<div id="{0}" class="phaselet" style="left:{1}%;width:{2}%;background:{3}"></div>\n'
1776 def __init__(self, rowheight, scaleheight):
1777 self.rowH = rowheight
1778 self.scaleH = scaleheight
1779 self.html = ''
1780 def createHeader(self, sv, suppress=''):
1781 if(not sv.stamp['time']):
1782 return
1783 self.html += '<div class="version"><a href="https://01.org/suspendresume">%s v%s</a></div>' \
1784 % (sv.title, sv.version)
1785 if sv.logmsg and 'log' not in suppress:
1786 self.html += '<button id="showtest" class="logbtn">log</button>'
1787 if sv.addlogs and 'dmesg' not in suppress:
1788 self.html += '<button id="showdmesg" class="logbtn">dmesg</button>'
1789 if sv.addlogs and sv.ftracefile and 'ftrace' not in suppress:
1790 self.html += '<button id="showftrace" class="logbtn">ftrace</button>'
1791 headline_stamp = '<div class="stamp">{0} {1} {2} {3}</div>\n'
1792 self.html += headline_stamp.format(sv.stamp['host'], sv.stamp['kernel'],
1793 sv.stamp['mode'], sv.stamp['time'])
1794 # Function: getDeviceRows
1795 # Description:
1796 # determine how may rows the device funcs will take
1797 # Arguments:
1798 # rawlist: the list of devices/actions for a single phase
1799 # Output:
1800 # The total number of rows needed to display this phase of the timeline
1801 def getDeviceRows(self, rawlist):
1802 # clear all rows and set them to undefined
1803 sortdict = dict()
1804 for item in rawlist:
1805 item.row = -1
1806 sortdict[item] = item.length
1807 sortlist = sorted(sortdict, key=sortdict.get, reverse=True)
1808 remaining = len(sortlist)
1809 rowdata = dict()
1810 row = 1
1811 # try to pack each row with as many ranges as possible
1812 while(remaining > 0):
1813 if(row not in rowdata):
1814 rowdata[row] = []
1815 for i in sortlist:
1816 if(i.row >= 0):
1817 continue
1818 s = i.time
1819 e = i.time + i.length
1820 valid = True
1821 for ritem in rowdata[row]:
1822 rs = ritem.time
1823 re = ritem.time + ritem.length
1824 if(not (((s <= rs) and (e <= rs)) or
1825 ((s >= re) and (e >= re)))):
1826 valid = False
1827 break
1828 if(valid):
1829 rowdata[row].append(i)
1830 i.row = row
1831 remaining -= 1
1832 row += 1
1833 return row
1834 # Function: getPhaseRows
1835 # Description:
1836 # Organize the timeline entries into the smallest
1837 # number of rows possible, with no entry overlapping
1838 # Arguments:
1839 # devlist: the list of devices/actions in a group of contiguous phases
1840 # Output:
1841 # The total number of rows needed to display this phase of the timeline
1842 def getPhaseRows(self, devlist, row=0):
1843 # clear all rows and set them to undefined
1844 remaining = len(devlist)
1845 rowdata = dict()
1846 sortdict = dict()
1847 myphases = []
1848 # initialize all device rows to -1 and calculate devrows
1849 for item in devlist:
1850 dev = item.dev
1851 tp = (item.test, item.phase)
1852 if tp not in myphases:
1853 myphases.append(tp)
1854 dev['row'] = -1
1855 # sort by length 1st, then name 2nd
1856 sortdict[item] = (float(dev['end']) - float(dev['start']), item.dev['name'])
1857 if 'src' in dev:
1858 dev['devrows'] = self.getDeviceRows(dev['src'])
1859 # sort the devlist by length so that large items graph on top
1860 sortlist = sorted(sortdict, key=sortdict.get, reverse=True)
1861 orderedlist = []
1862 for item in sortlist:
1863 if item.dev['pid'] == -2:
1864 orderedlist.append(item)
1865 for item in sortlist:
1866 if item not in orderedlist:
1867 orderedlist.append(item)
1868 # try to pack each row with as many devices as possible
1869 while(remaining > 0):
1870 rowheight = 1
1871 if(row not in rowdata):
1872 rowdata[row] = []
1873 for item in orderedlist:
1874 dev = item.dev
1875 if(dev['row'] < 0):
1876 s = dev['start']
1877 e = dev['end']
1878 valid = True
1879 for ritem in rowdata[row]:
1880 rs = ritem.dev['start']
1881 re = ritem.dev['end']
1882 if(not (((s <= rs) and (e <= rs)) or
1883 ((s >= re) and (e >= re)))):
1884 valid = False
1885 break
1886 if(valid):
1887 rowdata[row].append(item)
1888 dev['row'] = row
1889 remaining -= 1
1890 if 'devrows' in dev and dev['devrows'] > rowheight:
1891 rowheight = dev['devrows']
1892 for t, p in myphases:
1893 if t not in self.rowlines or t not in self.rowheight:
1894 self.rowlines[t] = dict()
1895 self.rowheight[t] = dict()
1896 if p not in self.rowlines[t] or p not in self.rowheight[t]:
1897 self.rowlines[t][p] = dict()
1898 self.rowheight[t][p] = dict()
1899 rh = self.rowH
1900 # section headers should use a different row height
1901 if len(rowdata[row]) == 1 and \
1902 'htmlclass' in rowdata[row][0].dev and \
1903 'sec' in rowdata[row][0].dev['htmlclass']:
1904 rh = 15
1905 self.rowlines[t][p][row] = rowheight
1906 self.rowheight[t][p][row] = rowheight * rh
1907 row += 1
1908 if(row > self.rows):
1909 self.rows = int(row)
1910 return row
1911 def phaseRowHeight(self, test, phase, row):
1912 return self.rowheight[test][phase][row]
1913 def phaseRowTop(self, test, phase, row):
1914 top = 0
1915 for i in sorted(self.rowheight[test][phase]):
1916 if i >= row:
1917 break
1918 top += self.rowheight[test][phase][i]
1919 return top
1920 def calcTotalRows(self):
1921 # Calculate the heights and offsets for the header and rows
1922 maxrows = 0
1923 standardphases = []
1924 for t in self.rowlines:
1925 for p in self.rowlines[t]:
1926 total = 0
1927 for i in sorted(self.rowlines[t][p]):
1928 total += self.rowlines[t][p][i]
1929 if total > maxrows:
1930 maxrows = total
1931 if total == len(self.rowlines[t][p]):
1932 standardphases.append((t, p))
1933 self.height = self.scaleH + (maxrows*self.rowH)
1934 self.bodyH = self.height - self.scaleH
1935 # if there is 1 line per row, draw them the standard way
1936 for t, p in standardphases:
1937 for i in sorted(self.rowheight[t][p]):
1938 self.rowheight[t][p][i] = self.bodyH/len(self.rowlines[t][p])
1939 def createZoomBox(self, mode='command', testcount=1):
1940 # Create bounding box, add buttons
1941 html_zoombox = '<center><button id="zoomin">ZOOM IN +</button><button id="zoomout">ZOOM OUT -</button><button id="zoomdef">ZOOM 1:1</button></center>\n'
1942 html_timeline = '<div id="dmesgzoombox" class="zoombox">\n<div id="{0}" class="timeline" style="height:{1}px">\n'
1943 html_devlist1 = '<button id="devlist1" class="devlist" style="float:left;">Device Detail{0}</button>'
1944 html_devlist2 = '<button id="devlist2" class="devlist" style="float:right;">Device Detail2</button>\n'
1945 if mode != 'command':
1946 if testcount > 1:
1947 self.html += html_devlist2
1948 self.html += html_devlist1.format('1')
1949 else:
1950 self.html += html_devlist1.format('')
1951 self.html += html_zoombox
1952 self.html += html_timeline.format('dmesg', self.height)
1953 # Function: createTimeScale
1954 # Description:
1955 # Create the timescale for a timeline block
1956 # Arguments:
1957 # m0: start time (mode begin)
1958 # mMax: end time (mode end)
1959 # tTotal: total timeline time
1960 # mode: suspend or resume
1961 # Output:
1962 # The html code needed to display the time scale
1963 def createTimeScale(self, m0, mMax, tTotal, mode):
1964 timescale = '<div class="t" style="right:{0}%">{1}</div>\n'
1965 rline = '<div class="t" style="left:0;border-left:1px solid black;border-right:0;">{0}</div>\n'
1966 output = '<div class="timescale">\n'
1967 # set scale for timeline
1968 mTotal = mMax - m0
1969 tS = 0.1
1970 if(tTotal <= 0):
1971 return output+'</div>\n'
1972 if(tTotal > 4):
1973 tS = 1
1974 divTotal = int(mTotal/tS) + 1
1975 divEdge = (mTotal - tS*(divTotal-1))*100/mTotal
1976 for i in range(divTotal):
1977 htmlline = ''
1978 if(mode == 'suspend'):
1979 pos = '%0.3f' % (100 - ((float(i)*tS*100)/mTotal) - divEdge)
1980 val = '%0.fms' % (float(i-divTotal+1)*tS*1000)
1981 if(i == divTotal - 1):
1982 val = mode
1983 htmlline = timescale.format(pos, val)
1984 else:
1985 pos = '%0.3f' % (100 - ((float(i)*tS*100)/mTotal))
1986 val = '%0.fms' % (float(i)*tS*1000)
1987 htmlline = timescale.format(pos, val)
1988 if(i == 0):
1989 htmlline = rline.format(mode)
1990 output += htmlline
1991 self.html += output+'</div>\n'
1992
1993# Class: TestProps
1994# Description:
1995# A list of values describing the properties of these test runs
1996class TestProps:
1997 stamp = ''
1998 S0i3 = False
1999 fwdata = []
2000 ftrace_line_fmt_fg = \
2001 '^ *(?P<time>[0-9\.]*) *\| *(?P<cpu>[0-9]*)\)'+\
2002 ' *(?P<proc>.*)-(?P<pid>[0-9]*) *\|'+\
2003 '[ +!#\*@$]*(?P<dur>[0-9\.]*) .*\| (?P<msg>.*)'
2004 ftrace_line_fmt_nop = \
2005 ' *(?P<proc>.*)-(?P<pid>[0-9]*) *\[(?P<cpu>[0-9]*)\] *'+\
2006 '(?P<flags>.{4}) *(?P<time>[0-9\.]*): *'+\
2007 '(?P<msg>.*)'
2008 ftrace_line_fmt = ftrace_line_fmt_nop
2009 cgformat = False
2010 data = 0
2011 ktemp = dict()
2012 def __init__(self):
2013 self.ktemp = dict()
2014 def setTracerType(self, tracer):
2015 if(tracer == 'function_graph'):
2016 self.cgformat = True
2017 self.ftrace_line_fmt = self.ftrace_line_fmt_fg
2018 elif(tracer == 'nop'):
2019 self.ftrace_line_fmt = self.ftrace_line_fmt_nop
2020 else:
2021 doError('Invalid tracer format: [%s]' % tracer)
2022
2023# Class: TestRun
2024# Description:
2025# A container for a suspend/resume test run. This is necessary as
2026# there could be more than one, and they need to be separate.
2027class TestRun:
2028 ftemp = dict()
2029 ttemp = dict()
2030 data = 0
2031 def __init__(self, dataobj):
2032 self.data = dataobj
2033 self.ftemp = dict()
2034 self.ttemp = dict()
2035
2036class ProcessMonitor:
2037 proclist = dict()
2038 running = False
2039 def procstat(self):
2040 c = ['cat /proc/[1-9]*/stat 2>/dev/null']
2041 process = Popen(c, shell=True, stdout=PIPE)
2042 running = dict()
2043 for line in process.stdout:
2044 data = line.split()
2045 pid = data[0]
2046 name = re.sub('[()]', '', data[1])
2047 user = int(data[13])
2048 kern = int(data[14])
2049 kjiff = ujiff = 0
2050 if pid not in self.proclist:
2051 self.proclist[pid] = {'name' : name, 'user' : user, 'kern' : kern}
2052 else:
2053 val = self.proclist[pid]
2054 ujiff = user - val['user']
2055 kjiff = kern - val['kern']
2056 val['user'] = user
2057 val['kern'] = kern
2058 if ujiff > 0 or kjiff > 0:
2059 running[pid] = ujiff + kjiff
2060 process.wait()
2061 out = ''
2062 for pid in running:
2063 jiffies = running[pid]
2064 val = self.proclist[pid]
2065 if out:
2066 out += ','
2067 out += '%s-%s %d' % (val['name'], pid, jiffies)
2068 return 'ps - '+out
2069 def processMonitor(self, tid):
2070 while self.running:
2071 out = self.procstat()
2072 if out:
2073 sysvals.fsetVal(out, 'trace_marker')
2074 def start(self):
2075 self.thread = Thread(target=self.processMonitor, args=(0,))
2076 self.running = True
2077 self.thread.start()
2078 def stop(self):
2079 self.running = False
2080
2081# ----------------- FUNCTIONS --------------------
2082
2083# Function: vprint
2084# Description:
2085# verbose print (prints only with -verbose option)
2086# Arguments:
2087# msg: the debug/log message to print
2088def vprint(msg):
2089 sysvals.logmsg += msg+'\n'
2090 if(sysvals.verbose):
2091 print(msg)
2092
2093# Function: parseStamp
2094# Description:
2095# Pull in the stamp comment line from the data file(s),
2096# create the stamp, and add it to the global sysvals object
2097# Arguments:
2098# m: the valid re.match output for the stamp line
2099def parseStamp(line, data):
2100 m = re.match(sysvals.stampfmt, line)
2101 data.stamp = {'time': '', 'host': '', 'mode': ''}
2102 dt = datetime(int(m.group('y'))+2000, int(m.group('m')),
2103 int(m.group('d')), int(m.group('H')), int(m.group('M')),
2104 int(m.group('S')))
2105 data.stamp['time'] = dt.strftime('%B %d %Y, %I:%M:%S %p')
2106 data.stamp['host'] = m.group('host')
2107 data.stamp['mode'] = m.group('mode')
2108 data.stamp['kernel'] = m.group('kernel')
2109 sysvals.hostname = data.stamp['host']
2110 sysvals.suspendmode = data.stamp['mode']
2111 if sysvals.suspendmode == 'command' and sysvals.ftracefile != '':
2112 modes = ['on', 'freeze', 'standby', 'mem']
2113 out = Popen(['grep', 'suspend_enter', sysvals.ftracefile],
2114 stderr=PIPE, stdout=PIPE).stdout.read()
2115 m = re.match('.* suspend_enter\[(?P<mode>.*)\]', out)
2116 if m and m.group('mode') in ['1', '2', '3']:
2117 sysvals.suspendmode = modes[int(m.group('mode'))]
2118 data.stamp['mode'] = sysvals.suspendmode
2119 if not sysvals.stamp:
2120 sysvals.stamp = data.stamp
2121
2122# Function: doesTraceLogHaveTraceEvents
2123# Description:
2124# Quickly determine if the ftrace log has some or all of the trace events
2125# required for primary parsing. Set the usetraceevents and/or
2126# usetraceeventsonly flags in the global sysvals object
2127def doesTraceLogHaveTraceEvents():
2128 # check for kprobes
2129 sysvals.usekprobes = False
2130 out = call('grep -q "_cal: (" '+sysvals.ftracefile, shell=True)
2131 if(out == 0):
2132 sysvals.usekprobes = True
2133 # check for callgraph data on trace event blocks
2134 out = call('grep -q "_cpu_down()" '+sysvals.ftracefile, shell=True)
2135 if(out == 0):
2136 sysvals.usekprobes = True
2137 out = Popen(['head', '-1', sysvals.ftracefile],
2138 stderr=PIPE, stdout=PIPE).stdout.read().replace('\n', '')
2139 m = re.match(sysvals.stampfmt, out)
2140 if m and m.group('mode') == 'command':
2141 sysvals.usetraceeventsonly = True
2142 sysvals.usetraceevents = True
2143 return
2144 # figure out what level of trace events are supported
2145 sysvals.usetraceeventsonly = True
2146 sysvals.usetraceevents = False
2147 for e in sysvals.traceevents:
2148 out = call('grep -q "'+e+': " '+sysvals.ftracefile, shell=True)
2149 if(out != 0):
2150 sysvals.usetraceeventsonly = False
2151 if(e == 'suspend_resume' and out == 0):
2152 sysvals.usetraceevents = True
2153 # determine is this log is properly formatted
2154 for e in ['SUSPEND START', 'RESUME COMPLETE']:
2155 out = call('grep -q "'+e+'" '+sysvals.ftracefile, shell=True)
2156 if(out != 0):
2157 sysvals.usetracemarkers = False
2158
2159# Function: appendIncompleteTraceLog
2160# Description:
2161# [deprecated for kernel 3.15 or newer]
2162# Legacy support of ftrace outputs that lack the device_pm_callback
2163# and/or suspend_resume trace events. The primary data should be
2164# taken from dmesg, and this ftrace is used only for callgraph data
2165# or custom actions in the timeline. The data is appended to the Data
2166# objects provided.
2167# Arguments:
2168# testruns: the array of Data objects obtained from parseKernelLog
2169def appendIncompleteTraceLog(testruns):
2170 # create TestRun vessels for ftrace parsing
2171 testcnt = len(testruns)
2172 testidx = 0
2173 testrun = []
2174 for data in testruns:
2175 testrun.append(TestRun(data))
2176
2177 # extract the callgraph and traceevent data
2178 vprint('Analyzing the ftrace data...')
2179 tp = TestProps()
2180 tf = open(sysvals.ftracefile, 'r')
2181 data = 0
2182 for line in tf:
2183 # remove any latent carriage returns
2184 line = line.replace('\r\n', '')
2185 # grab the time stamp
2186 m = re.match(sysvals.stampfmt, line)
2187 if(m):
2188 tp.stamp = line
2189 continue
2190 # determine the trace data type (required for further parsing)
2191 m = re.match(sysvals.tracertypefmt, line)
2192 if(m):
2193 tp.setTracerType(m.group('t'))
2194 continue
2195 # device properties line
2196 if(re.match(sysvals.devpropfmt, line)):
2197 devProps(line)
2198 continue
2199 # parse only valid lines, if this is not one move on
2200 m = re.match(tp.ftrace_line_fmt, line)
2201 if(not m):
2202 continue
2203 # gather the basic message data from the line
2204 m_time = m.group('time')
2205 m_pid = m.group('pid')
2206 m_msg = m.group('msg')
2207 if(tp.cgformat):
2208 m_param3 = m.group('dur')
2209 else:
2210 m_param3 = 'traceevent'
2211 if(m_time and m_pid and m_msg):
2212 t = FTraceLine(m_time, m_msg, m_param3)
2213 pid = int(m_pid)
2214 else:
2215 continue
2216 # the line should be a call, return, or event
2217 if(not t.fcall and not t.freturn and not t.fevent):
2218 continue
2219 # look for the suspend start marker
2220 if(t.startMarker()):
2221 data = testrun[testidx].data
2222 parseStamp(tp.stamp, data)
2223 data.setStart(t.time)
2224 continue
2225 if(not data):
2226 continue
2227 # find the end of resume
2228 if(t.endMarker()):
2229 data.setEnd(t.time)
2230 testidx += 1
2231 if(testidx >= testcnt):
2232 break
2233 continue
2234 # trace event processing
2235 if(t.fevent):
2236 # general trace events have two types, begin and end
2237 if(re.match('(?P<name>.*) begin$', t.name)):
2238 isbegin = True
2239 elif(re.match('(?P<name>.*) end$', t.name)):
2240 isbegin = False
2241 else:
2242 continue
2243 m = re.match('(?P<name>.*)\[(?P<val>[0-9]*)\] .*', t.name)
2244 if(m):
2245 val = m.group('val')
2246 if val == '0':
2247 name = m.group('name')
2248 else:
2249 name = m.group('name')+'['+val+']'
2250 else:
2251 m = re.match('(?P<name>.*) .*', t.name)
2252 name = m.group('name')
2253 # special processing for trace events
2254 if re.match('dpm_prepare\[.*', name):
2255 continue
2256 elif re.match('machine_suspend.*', name):
2257 continue
2258 elif re.match('suspend_enter\[.*', name):
2259 if(not isbegin):
2260 data.dmesg['suspend_prepare']['end'] = t.time
2261 continue
2262 elif re.match('dpm_suspend\[.*', name):
2263 if(not isbegin):
2264 data.dmesg['suspend']['end'] = t.time
2265 continue
2266 elif re.match('dpm_suspend_late\[.*', name):
2267 if(isbegin):
2268 data.dmesg['suspend_late']['start'] = t.time
2269 else:
2270 data.dmesg['suspend_late']['end'] = t.time
2271 continue
2272 elif re.match('dpm_suspend_noirq\[.*', name):
2273 if(isbegin):
2274 data.dmesg['suspend_noirq']['start'] = t.time
2275 else:
2276 data.dmesg['suspend_noirq']['end'] = t.time
2277 continue
2278 elif re.match('dpm_resume_noirq\[.*', name):
2279 if(isbegin):
2280 data.dmesg['resume_machine']['end'] = t.time
2281 data.dmesg['resume_noirq']['start'] = t.time
2282 else:
2283 data.dmesg['resume_noirq']['end'] = t.time
2284 continue
2285 elif re.match('dpm_resume_early\[.*', name):
2286 if(isbegin):
2287 data.dmesg['resume_early']['start'] = t.time
2288 else:
2289 data.dmesg['resume_early']['end'] = t.time
2290 continue
2291 elif re.match('dpm_resume\[.*', name):
2292 if(isbegin):
2293 data.dmesg['resume']['start'] = t.time
2294 else:
2295 data.dmesg['resume']['end'] = t.time
2296 continue
2297 elif re.match('dpm_complete\[.*', name):
2298 if(isbegin):
2299 data.dmesg['resume_complete']['start'] = t.time
2300 else:
2301 data.dmesg['resume_complete']['end'] = t.time
2302 continue
2303 # skip trace events inside devices calls
2304 if(not data.isTraceEventOutsideDeviceCalls(pid, t.time)):
2305 continue
2306 # global events (outside device calls) are simply graphed
2307 if(isbegin):
2308 # store each trace event in ttemp
2309 if(name not in testrun[testidx].ttemp):
2310 testrun[testidx].ttemp[name] = []
2311 testrun[testidx].ttemp[name].append(\
2312 {'begin': t.time, 'end': t.time})
2313 else:
2314 # finish off matching trace event in ttemp
2315 if(name in testrun[testidx].ttemp):
2316 testrun[testidx].ttemp[name][-1]['end'] = t.time
2317 # call/return processing
2318 elif sysvals.usecallgraph:
2319 # create a callgraph object for the data
2320 if(pid not in testrun[testidx].ftemp):
2321 testrun[testidx].ftemp[pid] = []
2322 testrun[testidx].ftemp[pid].append(FTraceCallGraph(pid))
2323 # when the call is finished, see which device matches it
2324 cg = testrun[testidx].ftemp[pid][-1]
2325 if(cg.addLine(t)):
2326 testrun[testidx].ftemp[pid].append(FTraceCallGraph(pid))
2327 tf.close()
2328
2329 for test in testrun:
2330 # add the traceevent data to the device hierarchy
2331 if(sysvals.usetraceevents):
2332 for name in test.ttemp:
2333 for event in test.ttemp[name]:
2334 test.data.newActionGlobal(name, event['begin'], event['end'])
2335
2336 # add the callgraph data to the device hierarchy
2337 for pid in test.ftemp:
2338 for cg in test.ftemp[pid]:
2339 if len(cg.list) < 1 or cg.invalid:
2340 continue
2341 if(not cg.postProcess()):
2342 id = 'task %s cpu %s' % (pid, m.group('cpu'))
2343 vprint('Sanity check failed for '+\
2344 id+', ignoring this callback')
2345 continue
2346 callstart = cg.start
2347 callend = cg.end
2348 for p in test.data.phases:
2349 if(test.data.dmesg[p]['start'] <= callstart and
2350 callstart <= test.data.dmesg[p]['end']):
2351 list = test.data.dmesg[p]['list']
2352 for devname in list:
2353 dev = list[devname]
2354 if(pid == dev['pid'] and
2355 callstart <= dev['start'] and
2356 callend >= dev['end']):
2357 dev['ftrace'] = cg
2358 break
2359
2360 test.data.printDetails()
2361
2362# Function: parseTraceLog
2363# Description:
2364# Analyze an ftrace log output file generated from this app during
2365# the execution phase. Used when the ftrace log is the primary data source
2366# and includes the suspend_resume and device_pm_callback trace events
2367# The ftrace filename is taken from sysvals
2368# Output:
2369# An array of Data objects
2370def parseTraceLog():
2371 vprint('Analyzing the ftrace data...')
2372 if(os.path.exists(sysvals.ftracefile) == False):
2373 doError('%s does not exist' % sysvals.ftracefile)
2374
2375 sysvals.setupAllKprobes()
2376 tracewatch = []
2377 if sysvals.usekprobes:
2378 tracewatch += ['sync_filesystems', 'freeze_processes', 'syscore_suspend',
2379 'syscore_resume', 'resume_console', 'thaw_processes', 'CPU_ON', 'CPU_OFF']
2380
2381 # extract the callgraph and traceevent data
2382 tp = TestProps()
2383 testruns = []
2384 testdata = []
2385 testrun = 0
2386 data = 0
2387 tf = open(sysvals.ftracefile, 'r')
2388 phase = 'suspend_prepare'
2389 for line in tf:
2390 # remove any latent carriage returns
2391 line = line.replace('\r\n', '')
2392 # stamp line: each stamp means a new test run
2393 m = re.match(sysvals.stampfmt, line)
2394 if(m):
2395 tp.stamp = line
2396 continue
2397 # firmware line: pull out any firmware data
2398 m = re.match(sysvals.firmwarefmt, line)
2399 if(m):
2400 tp.fwdata.append((int(m.group('s')), int(m.group('r'))))
2401 continue
2402 # tracer type line: determine the trace data type
2403 m = re.match(sysvals.tracertypefmt, line)
2404 if(m):
2405 tp.setTracerType(m.group('t'))
2406 continue
2407 # device properties line
2408 if(re.match(sysvals.devpropfmt, line)):
2409 devProps(line)
2410 continue
2411 # ignore all other commented lines
2412 if line[0] == '#':
2413 continue
2414 # ftrace line: parse only valid lines
2415 m = re.match(tp.ftrace_line_fmt, line)
2416 if(not m):
2417 continue
2418 # gather the basic message data from the line
2419 m_time = m.group('time')
2420 m_proc = m.group('proc')
2421 m_pid = m.group('pid')
2422 m_msg = m.group('msg')
2423 if(tp.cgformat):
2424 m_param3 = m.group('dur')
2425 else:
2426 m_param3 = 'traceevent'
2427 if(m_time and m_pid and m_msg):
2428 t = FTraceLine(m_time, m_msg, m_param3)
2429 pid = int(m_pid)
2430 else:
2431 continue
2432 # the line should be a call, return, or event
2433 if(not t.fcall and not t.freturn and not t.fevent):
2434 continue
2435 # find the start of suspend
2436 if(t.startMarker()):
2437 phase = 'suspend_prepare'
2438 data = Data(len(testdata))
2439 testdata.append(data)
2440 testrun = TestRun(data)
2441 testruns.append(testrun)
2442 parseStamp(tp.stamp, data)
2443 data.setStart(t.time)
2444 data.tKernSus = t.time
2445 continue
2446 if(not data):
2447 continue
2448 # process cpu exec line
2449 if t.type == 'tracing_mark_write':
2450 m = re.match(sysvals.procexecfmt, t.name)
2451 if(m):
2452 proclist = dict()
2453 for ps in m.group('ps').split(','):
2454 val = ps.split()
2455 if not val:
2456 continue
2457 name = val[0].replace('--', '-')
2458 proclist[name] = int(val[1])
2459 data.pstl[t.time] = proclist
2460 continue
2461 # find the end of resume
2462 if(t.endMarker()):
2463 data.setEnd(t.time)
2464 if data.tKernRes == 0.0:
2465 data.tKernRes = t.time
2466 if data.dmesg['resume_complete']['end'] < 0:
2467 data.dmesg['resume_complete']['end'] = t.time
2468 if sysvals.suspendmode == 'mem' and len(tp.fwdata) > data.testnumber:
2469 data.fwSuspend, data.fwResume = tp.fwdata[data.testnumber]
2470 if(data.tSuspended != 0 and data.tResumed != 0 and \
2471 (data.fwSuspend > 0 or data.fwResume > 0)):
2472 data.fwValid = True
2473 if(not sysvals.usetracemarkers):
2474 # no trace markers? then quit and be sure to finish recording
2475 # the event we used to trigger resume end
2476 if(len(testrun.ttemp['thaw_processes']) > 0):
2477 # if an entry exists, assume this is its end
2478 testrun.ttemp['thaw_processes'][-1]['end'] = t.time
2479 break
2480 continue
2481 # trace event processing
2482 if(t.fevent):
2483 if(phase == 'post_resume'):
2484 data.setEnd(t.time)
2485 if(t.type == 'suspend_resume'):
2486 # suspend_resume trace events have two types, begin and end
2487 if(re.match('(?P<name>.*) begin$', t.name)):
2488 isbegin = True
2489 elif(re.match('(?P<name>.*) end$', t.name)):
2490 isbegin = False
2491 else:
2492 continue
2493 m = re.match('(?P<name>.*)\[(?P<val>[0-9]*)\] .*', t.name)
2494 if(m):
2495 val = m.group('val')
2496 if val == '0':
2497 name = m.group('name')
2498 else:
2499 name = m.group('name')+'['+val+']'
2500 else:
2501 m = re.match('(?P<name>.*) .*', t.name)
2502 name = m.group('name')
2503 # ignore these events
2504 if(name.split('[')[0] in tracewatch):
2505 continue
2506 # -- phase changes --
2507 # start of kernel suspend
2508 if(re.match('suspend_enter\[.*', t.name)):
2509 if(isbegin):
2510 data.dmesg[phase]['start'] = t.time
2511 data.tKernSus = t.time
2512 continue
2513 # suspend_prepare start
2514 elif(re.match('dpm_prepare\[.*', t.name)):
2515 phase = 'suspend_prepare'
2516 if(not isbegin):
2517 data.dmesg[phase]['end'] = t.time
2518 continue
2519 # suspend start
2520 elif(re.match('dpm_suspend\[.*', t.name)):
2521 phase = 'suspend'
2522 data.setPhase(phase, t.time, isbegin)
2523 continue
2524 # suspend_late start
2525 elif(re.match('dpm_suspend_late\[.*', t.name)):
2526 phase = 'suspend_late'
2527 data.setPhase(phase, t.time, isbegin)
2528 continue
2529 # suspend_noirq start
2530 elif(re.match('dpm_suspend_noirq\[.*', t.name)):
2531 phase = 'suspend_noirq'
2532 data.setPhase(phase, t.time, isbegin)
2533 if(not isbegin):
2534 phase = 'suspend_machine'
2535 data.dmesg[phase]['start'] = t.time
2536 continue
2537 # suspend_machine/resume_machine
2538 elif(re.match('machine_suspend\[.*', t.name)):
2539 if(isbegin):
2540 phase = 'suspend_machine'
2541 data.dmesg[phase]['end'] = t.time
2542 data.tSuspended = t.time
2543 else:
2544 if(sysvals.suspendmode in ['mem', 'disk'] and not tp.S0i3):
2545 data.dmesg['suspend_machine']['end'] = t.time
2546 data.tSuspended = t.time
2547 phase = 'resume_machine'
2548 data.dmesg[phase]['start'] = t.time
2549 data.tResumed = t.time
2550 data.tLow = data.tResumed - data.tSuspended
2551 continue
2552 # acpi_suspend
2553 elif(re.match('acpi_suspend\[.*', t.name)):
2554 # acpi_suspend[0] S0i3
2555 if(re.match('acpi_suspend\[0\] begin', t.name)):
2556 if(sysvals.suspendmode == 'mem'):
2557 tp.S0i3 = True
2558 data.dmesg['suspend_machine']['end'] = t.time
2559 data.tSuspended = t.time
2560 continue
2561 # resume_noirq start
2562 elif(re.match('dpm_resume_noirq\[.*', t.name)):
2563 phase = 'resume_noirq'
2564 data.setPhase(phase, t.time, isbegin)
2565 if(isbegin):
2566 data.dmesg['resume_machine']['end'] = t.time
2567 continue
2568 # resume_early start
2569 elif(re.match('dpm_resume_early\[.*', t.name)):
2570 phase = 'resume_early'
2571 data.setPhase(phase, t.time, isbegin)
2572 continue
2573 # resume start
2574 elif(re.match('dpm_resume\[.*', t.name)):
2575 phase = 'resume'
2576 data.setPhase(phase, t.time, isbegin)
2577 continue
2578 # resume complete start
2579 elif(re.match('dpm_complete\[.*', t.name)):
2580 phase = 'resume_complete'
2581 if(isbegin):
2582 data.dmesg[phase]['start'] = t.time
2583 continue
2584 # skip trace events inside devices calls
2585 if(not data.isTraceEventOutsideDeviceCalls(pid, t.time)):
2586 continue
2587 # global events (outside device calls) are graphed
2588 if(name not in testrun.ttemp):
2589 testrun.ttemp[name] = []
2590 if(isbegin):
2591 # create a new list entry
2592 testrun.ttemp[name].append(\
2593 {'begin': t.time, 'end': t.time, 'pid': pid})
2594 else:
2595 if(len(testrun.ttemp[name]) > 0):
2596 # if an entry exists, assume this is its end
2597 testrun.ttemp[name][-1]['end'] = t.time
2598 elif(phase == 'post_resume'):
2599 # post resume events can just have ends
2600 testrun.ttemp[name].append({
2601 'begin': data.dmesg[phase]['start'],
2602 'end': t.time})
2603 # device callback start
2604 elif(t.type == 'device_pm_callback_start'):
2605 m = re.match('(?P<drv>.*) (?P<d>.*), parent: *(?P<p>.*), .*',\
2606 t.name);
2607 if(not m):
2608 continue
2609 drv = m.group('drv')
2610 n = m.group('d')
2611 p = m.group('p')
2612 if(n and p):
2613 data.newAction(phase, n, pid, p, t.time, -1, drv)
2614 if pid not in data.devpids:
2615 data.devpids.append(pid)
2616 # device callback finish
2617 elif(t.type == 'device_pm_callback_end'):
2618 m = re.match('(?P<drv>.*) (?P<d>.*), err.*', t.name);
2619 if(not m):
2620 continue
2621 n = m.group('d')
2622 list = data.dmesg[phase]['list']
2623 if(n in list):
2624 dev = list[n]
2625 dev['length'] = t.time - dev['start']
2626 dev['end'] = t.time
2627 # kprobe event processing
2628 elif(t.fkprobe):
2629 kprobename = t.type
2630 kprobedata = t.name
2631 key = (kprobename, pid)
2632 # displayname is generated from kprobe data
2633 displayname = ''
2634 if(t.fcall):
2635 displayname = sysvals.kprobeDisplayName(kprobename, kprobedata)
2636 if not displayname:
2637 continue
2638 if(key not in tp.ktemp):
2639 tp.ktemp[key] = []
2640 tp.ktemp[key].append({
2641 'pid': pid,
2642 'begin': t.time,
2643 'end': t.time,
2644 'name': displayname,
2645 'cdata': kprobedata,
2646 'proc': m_proc,
2647 })
2648 elif(t.freturn):
2649 if(key not in tp.ktemp) or len(tp.ktemp[key]) < 1:
2650 continue
2651 e = tp.ktemp[key][-1]
2652 if e['begin'] < 0.0 or t.time - e['begin'] < 0.000001:
2653 tp.ktemp[key].pop()
2654 else:
2655 e['end'] = t.time
2656 e['rdata'] = kprobedata
2657 # end of kernel resume
2658 if(kprobename == 'pm_notifier_call_chain' or \
2659 kprobename == 'pm_restore_console'):
2660 data.dmesg[phase]['end'] = t.time
2661 data.tKernRes = t.time
2662
2663 # callgraph processing
2664 elif sysvals.usecallgraph:
2665 # create a callgraph object for the data
2666 key = (m_proc, pid)
2667 if(key not in testrun.ftemp):
2668 testrun.ftemp[key] = []
2669 testrun.ftemp[key].append(FTraceCallGraph(pid))
2670 # when the call is finished, see which device matches it
2671 cg = testrun.ftemp[key][-1]
2672 if(cg.addLine(t)):
2673 testrun.ftemp[key].append(FTraceCallGraph(pid))
2674 tf.close()
2675
2676 if sysvals.suspendmode == 'command':
2677 for test in testruns:
2678 for p in test.data.phases:
2679 if p == 'suspend_prepare':
2680 test.data.dmesg[p]['start'] = test.data.start
2681 test.data.dmesg[p]['end'] = test.data.end
2682 else:
2683 test.data.dmesg[p]['start'] = test.data.end
2684 test.data.dmesg[p]['end'] = test.data.end
2685 test.data.tSuspended = test.data.end
2686 test.data.tResumed = test.data.end
2687 test.data.tLow = 0
2688 test.data.fwValid = False
2689
2690 # dev source and procmon events can be unreadable with mixed phase height
2691 if sysvals.usedevsrc or sysvals.useprocmon:
2692 sysvals.mixedphaseheight = False
2693
2694 for i in range(len(testruns)):
2695 test = testruns[i]
2696 data = test.data
2697 # find the total time range for this test (begin, end)
2698 tlb, tle = data.start, data.end
2699 if i < len(testruns) - 1:
2700 tle = testruns[i+1].data.start
2701 # add the process usage data to the timeline
2702 if sysvals.useprocmon:
2703 data.createProcessUsageEvents()
2704 # add the traceevent data to the device hierarchy
2705 if(sysvals.usetraceevents):
2706 # add actual trace funcs
2707 for name in test.ttemp:
2708 for event in test.ttemp[name]:
2709 data.newActionGlobal(name, event['begin'], event['end'], event['pid'])
2710 # add the kprobe based virtual tracefuncs as actual devices
2711 for key in tp.ktemp:
2712 name, pid = key
2713 if name not in sysvals.tracefuncs:
2714 continue
2715 for e in tp.ktemp[key]:
2716 kb, ke = e['begin'], e['end']
2717 if kb == ke or tlb > kb or tle <= kb:
2718 continue
2719 color = sysvals.kprobeColor(name)
2720 data.newActionGlobal(e['name'], kb, ke, pid, color)
2721 # add config base kprobes and dev kprobes
2722 if sysvals.usedevsrc:
2723 for key in tp.ktemp:
2724 name, pid = key
2725 if name in sysvals.tracefuncs or name not in sysvals.dev_tracefuncs:
2726 continue
2727 for e in tp.ktemp[key]:
2728 kb, ke = e['begin'], e['end']
2729 if kb == ke or tlb > kb or tle <= kb:
2730 continue
2731 data.addDeviceFunctionCall(e['name'], name, e['proc'], pid, kb,
2732 ke, e['cdata'], e['rdata'])
2733 if sysvals.usecallgraph:
2734 # add the callgraph data to the device hierarchy
2735 sortlist = dict()
2736 for key in test.ftemp:
2737 proc, pid = key
2738 for cg in test.ftemp[key]:
2739 if len(cg.list) < 1 or cg.invalid:
2740 continue
2741 if(not cg.postProcess()):
2742 id = 'task %s' % (pid)
2743 vprint('Sanity check failed for '+\
2744 id+', ignoring this callback')
2745 continue
2746 # match cg data to devices
2747 if sysvals.suspendmode == 'command' or not cg.deviceMatch(pid, data):
2748 sortkey = '%f%f%d' % (cg.start, cg.end, pid)
2749 sortlist[sortkey] = cg
2750 # create blocks for orphan cg data
2751 for sortkey in sorted(sortlist):
2752 cg = sortlist[sortkey]
2753 name = cg.name
2754 if sysvals.isCallgraphFunc(name):
2755 vprint('Callgraph found for task %d: %.3fms, %s' % (cg.pid, (cg.end - cg.start)*1000, name))
2756 cg.newActionFromFunction(data)
2757
2758 if sysvals.suspendmode == 'command':
2759 for data in testdata:
2760 data.printDetails()
2761 return testdata
2762
2763 # fill in any missing phases
2764 for data in testdata:
2765 lp = data.phases[0]
2766 for p in data.phases:
2767 if(data.dmesg[p]['start'] < 0 and data.dmesg[p]['end'] < 0):
2768 vprint('WARNING: phase "%s" is missing!' % p)
2769 if(data.dmesg[p]['start'] < 0):
2770 data.dmesg[p]['start'] = data.dmesg[lp]['end']
2771 if(p == 'resume_machine'):
2772 data.tSuspended = data.dmesg[lp]['end']
2773 data.tResumed = data.dmesg[lp]['end']
2774 data.tLow = 0
2775 if(data.dmesg[p]['end'] < 0):
2776 data.dmesg[p]['end'] = data.dmesg[p]['start']
2777 if(p != lp and not ('machine' in p and 'machine' in lp)):
2778 data.dmesg[lp]['end'] = data.dmesg[p]['start']
2779 lp = p
2780
2781 if(len(sysvals.devicefilter) > 0):
2782 data.deviceFilter(sysvals.devicefilter)
2783 data.fixupInitcallsThatDidntReturn()
2784 if sysvals.usedevsrc:
2785 data.optimizeDevSrc()
2786 data.printDetails()
2787
2788 # x2: merge any overlapping devices between test runs
2789 if sysvals.usedevsrc and len(testdata) > 1:
2790 tc = len(testdata)
2791 for i in range(tc - 1):
2792 devlist = testdata[i].overflowDevices()
2793 for j in range(i + 1, tc):
2794 testdata[j].mergeOverlapDevices(devlist)
2795 testdata[0].stitchTouchingThreads(testdata[1:])
2796 return testdata
2797
2798# Function: loadKernelLog
2799# Description:
2800# [deprecated for kernel 3.15.0 or newer]
2801# load the dmesg file into memory and fix up any ordering issues
2802# The dmesg filename is taken from sysvals
2803# Output:
2804# An array of empty Data objects with only their dmesgtext attributes set
2805def loadKernelLog(justtext=False):
2806 vprint('Analyzing the dmesg data...')
2807 if(os.path.exists(sysvals.dmesgfile) == False):
2808 doError('%s does not exist' % sysvals.dmesgfile)
2809
2810 if justtext:
2811 dmesgtext = []
2812 # there can be multiple test runs in a single file
2813 tp = TestProps()
2814 tp.stamp = datetime.now().strftime('# suspend-%m%d%y-%H%M%S localhost mem unknown')
2815 testruns = []
2816 data = 0
2817 lf = open(sysvals.dmesgfile, 'r')
2818 for line in lf:
2819 line = line.replace('\r\n', '')
2820 idx = line.find('[')
2821 if idx > 1:
2822 line = line[idx:]
2823 m = re.match(sysvals.stampfmt, line)
2824 if(m):
2825 tp.stamp = line
2826 continue
2827 m = re.match(sysvals.firmwarefmt, line)
2828 if(m):
2829 tp.fwdata.append((int(m.group('s')), int(m.group('r'))))
2830 continue
2831 m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line)
2832 if(not m):
2833 continue
2834 msg = m.group("msg")
2835 if justtext:
2836 dmesgtext.append(line)
2837 continue
2838 if(re.match('PM: Syncing filesystems.*', msg)):
2839 if(data):
2840 testruns.append(data)
2841 data = Data(len(testruns))
2842 parseStamp(tp.stamp, data)
2843 if len(tp.fwdata) > data.testnumber:
2844 data.fwSuspend, data.fwResume = tp.fwdata[data.testnumber]
2845 if(data.fwSuspend > 0 or data.fwResume > 0):
2846 data.fwValid = True
2847 if(not data):
2848 continue
2849 m = re.match('.* *(?P<k>[0-9]\.[0-9]{2}\.[0-9]-.*) .*', msg)
2850 if(m):
2851 sysvals.stamp['kernel'] = m.group('k')
2852 m = re.match('PM: Preparing system for (?P<m>.*) sleep', msg)
2853 if(m):
2854 sysvals.stamp['mode'] = sysvals.suspendmode = m.group('m')
2855 data.dmesgtext.append(line)
2856 lf.close()
2857
2858 if justtext:
2859 return dmesgtext
2860 if data:
2861 testruns.append(data)
2862 if len(testruns) < 1:
2863 doError(' dmesg log has no suspend/resume data: %s' \
2864 % sysvals.dmesgfile)
2865
2866 # fix lines with same timestamp/function with the call and return swapped
2867 for data in testruns:
2868 last = ''
2869 for line in data.dmesgtext:
2870 mc = re.match('.*(\[ *)(?P<t>[0-9\.]*)(\]) calling '+\
2871 '(?P<f>.*)\+ @ .*, parent: .*', line)
2872 mr = re.match('.*(\[ *)(?P<t>[0-9\.]*)(\]) call '+\
2873 '(?P<f>.*)\+ returned .* after (?P<dt>.*) usecs', last)
2874 if(mc and mr and (mc.group('t') == mr.group('t')) and
2875 (mc.group('f') == mr.group('f'))):
2876 i = data.dmesgtext.index(last)
2877 j = data.dmesgtext.index(line)
2878 data.dmesgtext[i] = line
2879 data.dmesgtext[j] = last
2880 last = line
2881 return testruns
2882
2883# Function: parseKernelLog
2884# Description:
2885# [deprecated for kernel 3.15.0 or newer]
2886# Analyse a dmesg log output file generated from this app during
2887# the execution phase. Create a set of device structures in memory
2888# for subsequent formatting in the html output file
2889# This call is only for legacy support on kernels where the ftrace
2890# data lacks the suspend_resume or device_pm_callbacks trace events.
2891# Arguments:
2892# data: an empty Data object (with dmesgtext) obtained from loadKernelLog
2893# Output:
2894# The filled Data object
2895def parseKernelLog(data):
2896 phase = 'suspend_runtime'
2897
2898 if(data.fwValid):
2899 vprint('Firmware Suspend = %u ns, Firmware Resume = %u ns' % \
2900 (data.fwSuspend, data.fwResume))
2901
2902 # dmesg phase match table
2903 dm = {
2904 'suspend_prepare': 'PM: Syncing filesystems.*',
2905 'suspend': 'PM: Entering [a-z]* sleep.*',
2906 'suspend_late': 'PM: suspend of devices complete after.*',
2907 'suspend_noirq': 'PM: late suspend of devices complete after.*',
2908 'suspend_machine': 'PM: noirq suspend of devices complete after.*',
2909 'resume_machine': 'ACPI: Low-level resume complete.*',
2910 'resume_noirq': 'ACPI: Waking up from system sleep state.*',
2911 'resume_early': 'PM: noirq resume of devices complete after.*',
2912 'resume': 'PM: early resume of devices complete after.*',
2913 'resume_complete': 'PM: resume of devices complete after.*',
2914 'post_resume': '.*Restarting tasks \.\.\..*',
2915 }
2916 if(sysvals.suspendmode == 'standby'):
2917 dm['resume_machine'] = 'PM: Restoring platform NVS memory'
2918 elif(sysvals.suspendmode == 'disk'):
2919 dm['suspend_late'] = 'PM: freeze of devices complete after.*'
2920 dm['suspend_noirq'] = 'PM: late freeze of devices complete after.*'
2921 dm['suspend_machine'] = 'PM: noirq freeze of devices complete after.*'
2922 dm['resume_machine'] = 'PM: Restoring platform NVS memory'
2923 dm['resume_early'] = 'PM: noirq restore of devices complete after.*'
2924 dm['resume'] = 'PM: early restore of devices complete after.*'
2925 dm['resume_complete'] = 'PM: restore of devices complete after.*'
2926 elif(sysvals.suspendmode == 'freeze'):
2927 dm['resume_machine'] = 'ACPI: resume from mwait'
2928
2929 # action table (expected events that occur and show up in dmesg)
2930 at = {
2931 'sync_filesystems': {
2932 'smsg': 'PM: Syncing filesystems.*',
2933 'emsg': 'PM: Preparing system for mem sleep.*' },
2934 'freeze_user_processes': {
2935 'smsg': 'Freezing user space processes .*',
2936 'emsg': 'Freezing remaining freezable tasks.*' },
2937 'freeze_tasks': {
2938 'smsg': 'Freezing remaining freezable tasks.*',
2939 'emsg': 'PM: Entering (?P<mode>[a-z,A-Z]*) sleep.*' },
2940 'ACPI prepare': {
2941 'smsg': 'ACPI: Preparing to enter system sleep state.*',
2942 'emsg': 'PM: Saving platform NVS memory.*' },
2943 'PM vns': {
2944 'smsg': 'PM: Saving platform NVS memory.*',
2945 'emsg': 'Disabling non-boot CPUs .*' },
2946 }
2947
2948 t0 = -1.0
2949 cpu_start = -1.0
2950 prevktime = -1.0
2951 actions = dict()
2952 for line in data.dmesgtext:
2953 # parse each dmesg line into the time and message
2954 m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line)
2955 if(m):
2956 val = m.group('ktime')
2957 try:
2958 ktime = float(val)
2959 except:
2960 continue
2961 msg = m.group('msg')
2962 # initialize data start to first line time
2963 if t0 < 0:
2964 data.setStart(ktime)
2965 t0 = ktime
2966 else:
2967 continue
2968
2969 # hack for determining resume_machine end for freeze
2970 if(not sysvals.usetraceevents and sysvals.suspendmode == 'freeze' \
2971 and phase == 'resume_machine' and \
2972 re.match('calling (?P<f>.*)\+ @ .*, parent: .*', msg)):
2973 data.dmesg['resume_machine']['end'] = ktime
2974 phase = 'resume_noirq'
2975 data.dmesg[phase]['start'] = ktime
2976
2977 # suspend start
2978 if(re.match(dm['suspend_prepare'], msg)):
2979 phase = 'suspend_prepare'
2980 data.dmesg[phase]['start'] = ktime
2981 data.setStart(ktime)
2982 data.tKernSus = ktime
2983 # suspend start
2984 elif(re.match(dm['suspend'], msg)):
2985 data.dmesg['suspend_prepare']['end'] = ktime
2986 phase = 'suspend'
2987 data.dmesg[phase]['start'] = ktime
2988 # suspend_late start
2989 elif(re.match(dm['suspend_late'], msg)):
2990 data.dmesg['suspend']['end'] = ktime
2991 phase = 'suspend_late'
2992 data.dmesg[phase]['start'] = ktime
2993 # suspend_noirq start
2994 elif(re.match(dm['suspend_noirq'], msg)):
2995 data.dmesg['suspend_late']['end'] = ktime
2996 phase = 'suspend_noirq'
2997 data.dmesg[phase]['start'] = ktime
2998 # suspend_machine start
2999 elif(re.match(dm['suspend_machine'], msg)):
3000 data.dmesg['suspend_noirq']['end'] = ktime
3001 phase = 'suspend_machine'
3002 data.dmesg[phase]['start'] = ktime
3003 # resume_machine start
3004 elif(re.match(dm['resume_machine'], msg)):
3005 if(sysvals.suspendmode in ['freeze', 'standby']):
3006 data.tSuspended = prevktime
3007 data.dmesg['suspend_machine']['end'] = prevktime
3008 else:
3009 data.tSuspended = ktime
3010 data.dmesg['suspend_machine']['end'] = ktime
3011 phase = 'resume_machine'
3012 data.tResumed = ktime
3013 data.tLow = data.tResumed - data.tSuspended
3014 data.dmesg[phase]['start'] = ktime
3015 # resume_noirq start
3016 elif(re.match(dm['resume_noirq'], msg)):
3017 data.dmesg['resume_machine']['end'] = ktime
3018 phase = 'resume_noirq'
3019 data.dmesg[phase]['start'] = ktime
3020 # resume_early start
3021 elif(re.match(dm['resume_early'], msg)):
3022 data.dmesg['resume_noirq']['end'] = ktime
3023 phase = 'resume_early'
3024 data.dmesg[phase]['start'] = ktime
3025 # resume start
3026 elif(re.match(dm['resume'], msg)):
3027 data.dmesg['resume_early']['end'] = ktime
3028 phase = 'resume'
3029 data.dmesg[phase]['start'] = ktime
3030 # resume complete start
3031 elif(re.match(dm['resume_complete'], msg)):
3032 data.dmesg['resume']['end'] = ktime
3033 phase = 'resume_complete'
3034 data.dmesg[phase]['start'] = ktime
3035 # post resume start
3036 elif(re.match(dm['post_resume'], msg)):
3037 data.dmesg['resume_complete']['end'] = ktime
3038 data.setEnd(ktime)
3039 data.tKernRes = ktime
3040 break
3041
3042 # -- device callbacks --
3043 if(phase in data.phases):
3044 # device init call
3045 if(re.match('calling (?P<f>.*)\+ @ .*, parent: .*', msg)):
3046 sm = re.match('calling (?P<f>.*)\+ @ '+\
3047 '(?P<n>.*), parent: (?P<p>.*)', msg);
3048 f = sm.group('f')
3049 n = sm.group('n')
3050 p = sm.group('p')
3051 if(f and n and p):
3052 data.newAction(phase, f, int(n), p, ktime, -1, '')
3053 # device init return
3054 elif(re.match('call (?P<f>.*)\+ returned .* after '+\
3055 '(?P<t>.*) usecs', msg)):
3056 sm = re.match('call (?P<f>.*)\+ returned .* after '+\
3057 '(?P<t>.*) usecs(?P<a>.*)', msg);
3058 f = sm.group('f')
3059 t = sm.group('t')
3060 list = data.dmesg[phase]['list']
3061 if(f in list):
3062 dev = list[f]
3063 dev['length'] = int(t)
3064 dev['end'] = ktime
3065
3066 # if trace events are not available, these are better than nothing
3067 if(not sysvals.usetraceevents):
3068 # look for known actions
3069 for a in at:
3070 if(re.match(at[a]['smsg'], msg)):
3071 if(a not in actions):
3072 actions[a] = []
3073 actions[a].append({'begin': ktime, 'end': ktime})
3074 if(re.match(at[a]['emsg'], msg)):
3075 if(a in actions):
3076 actions[a][-1]['end'] = ktime
3077 # now look for CPU on/off events
3078 if(re.match('Disabling non-boot CPUs .*', msg)):
3079 # start of first cpu suspend
3080 cpu_start = ktime
3081 elif(re.match('Enabling non-boot CPUs .*', msg)):
3082 # start of first cpu resume
3083 cpu_start = ktime
3084 elif(re.match('smpboot: CPU (?P<cpu>[0-9]*) is now offline', msg)):
3085 # end of a cpu suspend, start of the next
3086 m = re.match('smpboot: CPU (?P<cpu>[0-9]*) is now offline', msg)
3087 cpu = 'CPU'+m.group('cpu')
3088 if(cpu not in actions):
3089 actions[cpu] = []
3090 actions[cpu].append({'begin': cpu_start, 'end': ktime})
3091 cpu_start = ktime
3092 elif(re.match('CPU(?P<cpu>[0-9]*) is up', msg)):
3093 # end of a cpu resume, start of the next
3094 m = re.match('CPU(?P<cpu>[0-9]*) is up', msg)
3095 cpu = 'CPU'+m.group('cpu')
3096 if(cpu not in actions):
3097 actions[cpu] = []
3098 actions[cpu].append({'begin': cpu_start, 'end': ktime})
3099 cpu_start = ktime
3100 prevktime = ktime
3101
3102 # fill in any missing phases
3103 lp = data.phases[0]
3104 for p in data.phases:
3105 if(data.dmesg[p]['start'] < 0 and data.dmesg[p]['end'] < 0):
3106 print('WARNING: phase "%s" is missing, something went wrong!' % p)
3107 print(' In %s, this dmesg line denotes the start of %s:' % \
3108 (sysvals.suspendmode, p))
3109 print(' "%s"' % dm[p])
3110 if(data.dmesg[p]['start'] < 0):
3111 data.dmesg[p]['start'] = data.dmesg[lp]['end']
3112 if(p == 'resume_machine'):
3113 data.tSuspended = data.dmesg[lp]['end']
3114 data.tResumed = data.dmesg[lp]['end']
3115 data.tLow = 0
3116 if(data.dmesg[p]['end'] < 0):
3117 data.dmesg[p]['end'] = data.dmesg[p]['start']
3118 lp = p
3119
3120 # fill in any actions we've found
3121 for name in actions:
3122 for event in actions[name]:
3123 data.newActionGlobal(name, event['begin'], event['end'])
3124
3125 data.printDetails()
3126 if(len(sysvals.devicefilter) > 0):
3127 data.deviceFilter(sysvals.devicefilter)
3128 data.fixupInitcallsThatDidntReturn()
3129 return True
3130
3131def callgraphHTML(sv, hf, num, cg, title, color, devid):
3132 html_func_top = '<article id="{0}" class="atop" style="background:{1}">\n<input type="checkbox" class="pf" id="f{2}" checked/><label for="f{2}">{3} {4}</label>\n'
3133 html_func_start = '<article>\n<input type="checkbox" class="pf" id="f{0}" checked/><label for="f{0}">{1} {2}</label>\n'
3134 html_func_end = '</article>\n'
3135 html_func_leaf = '<article>{0} {1}</article>\n'
3136
3137 cgid = devid
3138 if cg.id:
3139 cgid += cg.id
3140 cglen = (cg.end - cg.start) * 1000
3141 if cglen < sv.mincglen:
3142 return num
3143
3144 fmt = '<r>(%.3f ms @ '+sv.timeformat+' to '+sv.timeformat+')</r>'
3145 flen = fmt % (cglen, cg.start, cg.end)
3146 hf.write(html_func_top.format(cgid, color, num, title, flen))
3147 num += 1
3148 for line in cg.list:
3149 if(line.length < 0.000000001):
3150 flen = ''
3151 else:
3152 fmt = '<n>(%.3f ms @ '+sv.timeformat+')</n>'
3153 flen = fmt % (line.length*1000, line.time)
3154 if(line.freturn and line.fcall):
3155 hf.write(html_func_leaf.format(line.name, flen))
3156 elif(line.freturn):
3157 hf.write(html_func_end)
3158 else:
3159 hf.write(html_func_start.format(num, line.name, flen))
3160 num += 1
3161 hf.write(html_func_end)
3162 return num
3163
3164def addCallgraphs(sv, hf, data):
3165 hf.write('<section id="callgraphs" class="callgraph">\n')
3166 # write out the ftrace data converted to html
3167 num = 0
3168 for p in data.phases:
3169 if sv.cgphase and p != sv.cgphase:
3170 continue
3171 list = data.dmesg[p]['list']
3172 for devname in data.sortedDevices(p):
3173 dev = list[devname]
3174 color = 'white'
3175 if 'color' in data.dmesg[p]:
3176 color = data.dmesg[p]['color']
3177 if 'color' in dev:
3178 color = dev['color']
3179 name = devname
3180 if(devname in sv.devprops):
3181 name = sv.devprops[devname].altName(devname)
3182 if sv.suspendmode in suspendmodename:
3183 name += ' '+p
3184 if('ftrace' in dev):
3185 cg = dev['ftrace']
3186 num = callgraphHTML(sv, hf, num, cg,
3187 name, color, dev['id'])
3188 if('ftraces' in dev):
3189 for cg in dev['ftraces']:
3190 num = callgraphHTML(sv, hf, num, cg,
3191 name+' &rarr; '+cg.name, color, dev['id'])
3192
3193 hf.write('\n\n </section>\n')
3194
3195# Function: createHTMLSummarySimple
3196# Description:
3197# Create summary html file for a series of tests
3198# Arguments:
3199# testruns: array of Data objects from parseTraceLog
3200def createHTMLSummarySimple(testruns, htmlfile, folder):
3201 # write the html header first (html head, css code, up to body start)
3202 html = '<!DOCTYPE html>\n<html>\n<head>\n\
3203 <meta http-equiv="content-type" content="text/html; charset=UTF-8">\n\
3204 <title>SleepGraph Summary</title>\n\
3205 <style type=\'text/css\'>\n\
3206 .stamp {width: 100%;text-align:center;background:#888;line-height:30px;color:white;font: 25px Arial;}\n\
3207 table {width:100%;border-collapse: collapse;}\n\
3208 .summary {border:1px solid;}\n\
3209 th {border: 1px solid black;background:#222;color:white;}\n\
3210 td {font: 16px "Times New Roman";text-align: center;}\n\
3211 tr.alt td {background:#ddd;}\n\
3212 tr.avg td {background:#aaa;}\n\
3213 </style>\n</head>\n<body>\n'
3214
3215 # group test header
3216 html += '<div class="stamp">%s (%d tests)</div>\n' % (folder, len(testruns))
3217 th = '\t<th>{0}</th>\n'
3218 td = '\t<td>{0}</td>\n'
3219 tdlink = '\t<td><a href="{0}">html</a></td>\n'
3220
3221 # table header
3222 html += '<table class="summary">\n<tr>\n' + th.format('#') +\
3223 th.format('Mode') + th.format('Host') + th.format('Kernel') +\
3224 th.format('Test Time') + th.format('Suspend') + th.format('Resume') +\
3225 th.format('Detail') + '</tr>\n'
3226
3227 # test data, 1 row per test
3228 avg = '<tr class="avg"><td></td><td></td><td></td><td></td>'+\
3229 '<td>Average of {0} {1} tests</td><td>{2}</td><td>{3}</td><td></td></tr>\n'
3230 sTimeAvg = rTimeAvg = 0.0
3231 mode = ''
3232 num = 0
3233 for data in sorted(testruns, key=lambda v:(v['mode'], v['host'], v['kernel'])):
3234 if mode != data['mode']:
3235 # test average line
3236 if(num > 0):
3237 sTimeAvg /= (num - 1)
3238 rTimeAvg /= (num - 1)
3239 html += avg.format('%d' % (num - 1), mode,
3240 '%3.3f ms' % sTimeAvg, '%3.3f ms' % rTimeAvg)
3241 sTimeAvg = rTimeAvg = 0.0
3242 mode = data['mode']
3243 num = 1
3244 # alternate row color
3245 if num % 2 == 1:
3246 html += '<tr class="alt">\n'
3247 else:
3248 html += '<tr>\n'
3249 html += td.format("%d" % num)
3250 num += 1
3251 # basic info
3252 for item in ['mode', 'host', 'kernel', 'time']:
3253 val = "unknown"
3254 if(item in data):
3255 val = data[item]
3256 html += td.format(val)
3257 # suspend time
3258 sTime = float(data['suspend'])
3259 sTimeAvg += sTime
3260 html += td.format('%.3f ms' % sTime)
3261 # resume time
3262 rTime = float(data['resume'])
3263 rTimeAvg += rTime
3264 html += td.format('%.3f ms' % rTime)
3265 # link to the output html
3266 html += tdlink.format(data['url']) + '</tr>\n'
3267 # last test average line
3268 if(num > 0):
3269 sTimeAvg /= (num - 1)
3270 rTimeAvg /= (num - 1)
3271 html += avg.format('%d' % (num - 1), mode,
3272 '%3.3f ms' % sTimeAvg, '%3.3f ms' % rTimeAvg)
3273
3274 # flush the data to file
3275 hf = open(htmlfile, 'w')
3276 hf.write(html+'</table>\n</body>\n</html>\n')
3277 hf.close()
3278
3279def ordinal(value):
3280 suffix = 'th'
3281 if value < 10 or value > 19:
3282 if value % 10 == 1:
3283 suffix = 'st'
3284 elif value % 10 == 2:
3285 suffix = 'nd'
3286 elif value % 10 == 3:
3287 suffix = 'rd'
3288 return '%d%s' % (value, suffix)
3289
3290# Function: createHTML
3291# Description:
3292# Create the output html file from the resident test data
3293# Arguments:
3294# testruns: array of Data objects from parseKernelLog or parseTraceLog
3295# Output:
3296# True if the html file was created, false if it failed
3297def createHTML(testruns):
3298 if len(testruns) < 1:
3299 print('ERROR: Not enough test data to build a timeline')
3300 return
3301
3302 kerror = False
3303 for data in testruns:
3304 if data.kerror:
3305 kerror = True
3306 data.normalizeTime(testruns[-1].tSuspended)
3307
3308 # html function templates
3309 html_error = '<div id="{1}" title="kernel error/warning" class="err" style="right:{0}%">ERROR&rarr;</div>\n'
3310 html_traceevent = '<div title="{0}" class="traceevent{6}" style="left:{1}%;top:{2}px;height:{3}px;width:{4}%;line-height:{3}px;{7}">{5}</div>\n'
3311 html_cpuexec = '<div class="jiffie" style="left:{0}%;top:{1}px;height:{2}px;width:{3}%;background:{4};"></div>\n'
3312 html_legend = '<div id="p{3}" class="square" style="left:{0}%;background:{1}">&nbsp;{2}</div>\n'
3313 html_timetotal = '<table class="time1">\n<tr>'\
3314 '<td class="green" title="{3}">{2} Suspend Time: <b>{0} ms</b></td>'\
3315 '<td class="yellow" title="{4}">{2} Resume Time: <b>{1} ms</b></td>'\
3316 '</tr>\n</table>\n'
3317 html_timetotal2 = '<table class="time1">\n<tr>'\
3318 '<td class="green" title="{4}">{3} Suspend Time: <b>{0} ms</b></td>'\
3319 '<td class="gray" title="time spent in low-power mode with clock running">'+sysvals.suspendmode+' time: <b>{1} ms</b></td>'\
3320 '<td class="yellow" title="{5}">{3} Resume Time: <b>{2} ms</b></td>'\
3321 '</tr>\n</table>\n'
3322 html_timetotal3 = '<table class="time1">\n<tr>'\
3323 '<td class="green">Execution Time: <b>{0} ms</b></td>'\
3324 '<td class="yellow">Command: <b>{1}</b></td>'\
3325 '</tr>\n</table>\n'
3326 html_timegroups = '<table class="time2">\n<tr>'\
3327 '<td class="green" title="time from kernel enter_state({5}) to firmware mode [kernel time only]">{4}Kernel Suspend: {0} ms</td>'\
3328 '<td class="purple">{4}Firmware Suspend: {1} ms</td>'\
3329 '<td class="purple">{4}Firmware Resume: {2} ms</td>'\
3330 '<td class="yellow" title="time from firmware mode to return from kernel enter_state({5}) [kernel time only]">{4}Kernel Resume: {3} ms</td>'\
3331 '</tr>\n</table>\n'
3332
3333 # html format variables
3334 scaleH = 20
3335 if kerror:
3336 scaleH = 40
3337
3338 # device timeline
3339 vprint('Creating Device Timeline...')
3340
3341 devtl = Timeline(30, scaleH)
3342
3343 # write the test title and general info header
3344 devtl.createHeader(sysvals)
3345
3346 # Generate the header for this timeline
3347 for data in testruns:
3348 tTotal = data.end - data.start
3349 sktime = (data.dmesg['suspend_machine']['end'] - \
3350 data.tKernSus) * 1000
3351 rktime = (data.dmesg['resume_complete']['end'] - \
3352 data.dmesg['resume_machine']['start']) * 1000
3353 if(tTotal == 0):
3354 print('ERROR: No timeline data')
3355 sys.exit()
3356 if(data.tLow > 0):
3357 low_time = '%.0f'%(data.tLow*1000)
3358 if sysvals.suspendmode == 'command':
3359 run_time = '%.0f'%((data.end-data.start)*1000)
3360 if sysvals.testcommand:
3361 testdesc = sysvals.testcommand
3362 else:
3363 testdesc = 'unknown'
3364 if(len(testruns) > 1):
3365 testdesc = ordinal(data.testnumber+1)+' '+testdesc
3366 thtml = html_timetotal3.format(run_time, testdesc)
3367 devtl.html += thtml
3368 elif data.fwValid:
3369 suspend_time = '%.0f'%(sktime + (data.fwSuspend/1000000.0))
3370 resume_time = '%.0f'%(rktime + (data.fwResume/1000000.0))
3371 testdesc1 = 'Total'
3372 testdesc2 = ''
3373 stitle = 'time from kernel enter_state(%s) to low-power mode [kernel & firmware time]' % sysvals.suspendmode
3374 rtitle = 'time from low-power mode to return from kernel enter_state(%s) [firmware & kernel time]' % sysvals.suspendmode
3375 if(len(testruns) > 1):
3376 testdesc1 = testdesc2 = ordinal(data.testnumber+1)
3377 testdesc2 += ' '
3378 if(data.tLow == 0):
3379 thtml = html_timetotal.format(suspend_time, \
3380 resume_time, testdesc1, stitle, rtitle)
3381 else:
3382 thtml = html_timetotal2.format(suspend_time, low_time, \
3383 resume_time, testdesc1, stitle, rtitle)
3384 devtl.html += thtml
3385 sftime = '%.3f'%(data.fwSuspend / 1000000.0)
3386 rftime = '%.3f'%(data.fwResume / 1000000.0)
3387 devtl.html += html_timegroups.format('%.3f'%sktime, \
3388 sftime, rftime, '%.3f'%rktime, testdesc2, sysvals.suspendmode)
3389 else:
3390 suspend_time = '%.3f' % sktime
3391 resume_time = '%.3f' % rktime
3392 testdesc = 'Kernel'
3393 stitle = 'time from kernel enter_state(%s) to firmware mode [kernel time only]' % sysvals.suspendmode
3394 rtitle = 'time from firmware mode to return from kernel enter_state(%s) [kernel time only]' % sysvals.suspendmode
3395 if(len(testruns) > 1):
3396 testdesc = ordinal(data.testnumber+1)+' '+testdesc
3397 if(data.tLow == 0):
3398 thtml = html_timetotal.format(suspend_time, \
3399 resume_time, testdesc, stitle, rtitle)
3400 else:
3401 thtml = html_timetotal2.format(suspend_time, low_time, \
3402 resume_time, testdesc, stitle, rtitle)
3403 devtl.html += thtml
3404
3405 # time scale for potentially multiple datasets
3406 t0 = testruns[0].start
3407 tMax = testruns[-1].end
3408 tTotal = tMax - t0
3409
3410 # determine the maximum number of rows we need to draw
3411 fulllist = []
3412 threadlist = []
3413 pscnt = 0
3414 devcnt = 0
3415 for data in testruns:
3416 data.selectTimelineDevices('%f', tTotal, sysvals.mindevlen)
3417 for group in data.devicegroups:
3418 devlist = []
3419 for phase in group:
3420 for devname in data.tdevlist[phase]:
3421 d = DevItem(data.testnumber, phase, data.dmesg[phase]['list'][devname])
3422 devlist.append(d)
3423 if d.isa('kth'):
3424 threadlist.append(d)
3425 else:
3426 if d.isa('ps'):
3427 pscnt += 1
3428 else:
3429 devcnt += 1
3430 fulllist.append(d)
3431 if sysvals.mixedphaseheight:
3432 devtl.getPhaseRows(devlist)
3433 if not sysvals.mixedphaseheight:
3434 if len(threadlist) > 0 and len(fulllist) > 0:
3435 if pscnt > 0 and devcnt > 0:
3436 msg = 'user processes & device pm callbacks'
3437 elif pscnt > 0:
3438 msg = 'user processes'
3439 else:
3440 msg = 'device pm callbacks'
3441 d = testruns[0].addHorizontalDivider(msg, testruns[-1].end)
3442 fulllist.insert(0, d)
3443 devtl.getPhaseRows(fulllist)
3444 if len(threadlist) > 0:
3445 d = testruns[0].addHorizontalDivider('asynchronous kernel threads', testruns[-1].end)
3446 threadlist.insert(0, d)
3447 devtl.getPhaseRows(threadlist, devtl.rows)
3448 devtl.calcTotalRows()
3449
3450 # draw the full timeline
3451 devtl.createZoomBox(sysvals.suspendmode, len(testruns))
3452 phases = {'suspend':[],'resume':[]}
3453 for phase in data.dmesg:
3454 if 'resume' in phase:
3455 phases['resume'].append(phase)
3456 else:
3457 phases['suspend'].append(phase)
3458
3459 # draw each test run chronologically
3460 for data in testruns:
3461 # now draw the actual timeline blocks
3462 for dir in phases:
3463 # draw suspend and resume blocks separately
3464 bname = '%s%d' % (dir[0], data.testnumber)
3465 if dir == 'suspend':
3466 m0 = data.start
3467 mMax = data.tSuspended
3468 left = '%f' % (((m0-t0)*100.0)/tTotal)
3469 else:
3470 m0 = data.tSuspended
3471 mMax = data.end
3472 # in an x2 run, remove any gap between blocks
3473 if len(testruns) > 1 and data.testnumber == 0:
3474 mMax = testruns[1].start
3475 left = '%f' % ((((m0-t0)*100.0)+sysvals.srgap/2)/tTotal)
3476 mTotal = mMax - m0
3477 # if a timeline block is 0 length, skip altogether
3478 if mTotal == 0:
3479 continue
3480 width = '%f' % (((mTotal*100.0)-sysvals.srgap/2)/tTotal)
3481 devtl.html += devtl.html_tblock.format(bname, left, width, devtl.scaleH)
3482 for b in sorted(phases[dir]):
3483 # draw the phase color background
3484 phase = data.dmesg[b]
3485 length = phase['end']-phase['start']
3486 left = '%f' % (((phase['start']-m0)*100.0)/mTotal)
3487 width = '%f' % ((length*100.0)/mTotal)
3488 devtl.html += devtl.html_phase.format(left, width, \
3489 '%.3f'%devtl.scaleH, '%.3f'%devtl.bodyH, \
3490 data.dmesg[b]['color'], '')
3491 for e in data.errorinfo[dir]:
3492 # draw red lines for any kernel errors found
3493 t, err = e
3494 right = '%f' % (((mMax-t)*100.0)/mTotal)
3495 devtl.html += html_error.format(right, err)
3496 for b in sorted(phases[dir]):
3497 # draw the devices for this phase
3498 phaselist = data.dmesg[b]['list']
3499 for d in data.tdevlist[b]:
3500 name = d
3501 drv = ''
3502 dev = phaselist[d]
3503 xtraclass = ''
3504 xtrainfo = ''
3505 xtrastyle = ''
3506 if 'htmlclass' in dev:
3507 xtraclass = dev['htmlclass']
3508 if 'color' in dev:
3509 xtrastyle = 'background:%s;' % dev['color']
3510 if(d in sysvals.devprops):
3511 name = sysvals.devprops[d].altName(d)
3512 xtraclass = sysvals.devprops[d].xtraClass()
3513 xtrainfo = sysvals.devprops[d].xtraInfo()
3514 elif xtraclass == ' kth':
3515 xtrainfo = ' kernel_thread'
3516 if('drv' in dev and dev['drv']):
3517 drv = ' {%s}' % dev['drv']
3518 rowheight = devtl.phaseRowHeight(data.testnumber, b, dev['row'])
3519 rowtop = devtl.phaseRowTop(data.testnumber, b, dev['row'])
3520 top = '%.3f' % (rowtop + devtl.scaleH)
3521 left = '%f' % (((dev['start']-m0)*100)/mTotal)
3522 width = '%f' % (((dev['end']-dev['start'])*100)/mTotal)
3523 length = ' (%0.3f ms) ' % ((dev['end']-dev['start'])*1000)
3524 title = name+drv+xtrainfo+length
3525 if sysvals.suspendmode == 'command':
3526 title += sysvals.testcommand
3527 elif xtraclass == ' ps':
3528 if 'suspend' in b:
3529 title += 'pre_suspend_process'
3530 else:
3531 title += 'post_resume_process'
3532 else:
3533 title += b
3534 devtl.html += devtl.html_device.format(dev['id'], \
3535 title, left, top, '%.3f'%rowheight, width, \
3536 d+drv, xtraclass, xtrastyle)
3537 if('cpuexec' in dev):
3538 for t in sorted(dev['cpuexec']):
3539 start, end = t
3540 j = float(dev['cpuexec'][t]) / 5
3541 if j > 1.0:
3542 j = 1.0
3543 height = '%.3f' % (rowheight/3)
3544 top = '%.3f' % (rowtop + devtl.scaleH + 2*rowheight/3)
3545 left = '%f' % (((start-m0)*100)/mTotal)
3546 width = '%f' % ((end-start)*100/mTotal)
3547 color = 'rgba(255, 0, 0, %f)' % j
3548 devtl.html += \
3549 html_cpuexec.format(left, top, height, width, color)
3550 if('src' not in dev):
3551 continue
3552 # draw any trace events for this device
3553 for e in dev['src']:
3554 height = '%.3f' % devtl.rowH
3555 top = '%.3f' % (rowtop + devtl.scaleH + (e.row*devtl.rowH))
3556 left = '%f' % (((e.time-m0)*100)/mTotal)
3557 width = '%f' % (e.length*100/mTotal)
3558 xtrastyle = ''
3559 if e.color:
3560 xtrastyle = 'background:%s;' % e.color
3561 devtl.html += \
3562 html_traceevent.format(e.title(), \
3563 left, top, height, width, e.text(), '', xtrastyle)
3564 # draw the time scale, try to make the number of labels readable
3565 devtl.createTimeScale(m0, mMax, tTotal, dir)
3566 devtl.html += '</div>\n'
3567
3568 # timeline is finished
3569 devtl.html += '</div>\n</div>\n'
3570
3571 # draw a legend which describes the phases by color
3572 if sysvals.suspendmode != 'command':
3573 data = testruns[-1]
3574 devtl.html += '<div class="legend">\n'
3575 pdelta = 100.0/len(data.phases)
3576 pmargin = pdelta / 4.0
3577 for phase in data.phases:
3578 tmp = phase.split('_')
3579 id = tmp[0][0]
3580 if(len(tmp) > 1):
3581 id += tmp[1][0]
3582 order = '%.2f' % ((data.dmesg[phase]['order'] * pdelta) + pmargin)
3583 name = string.replace(phase, '_', ' &nbsp;')
3584 devtl.html += html_legend.format(order, \
3585 data.dmesg[phase]['color'], name, id)
3586 devtl.html += '</div>\n'
3587
3588 hf = open(sysvals.htmlfile, 'w')
3589
3590 # no header or css if its embedded
3591 if(sysvals.embedded):
3592 hf.write('pass True tSus %.3f tRes %.3f tLow %.3f fwvalid %s tSus %.3f tRes %.3f\n' %
3593 (data.tSuspended-data.start, data.end-data.tSuspended, data.tLow, data.fwValid, \
3594 data.fwSuspend/1000000, data.fwResume/1000000))
3595 else:
3596 addCSS(hf, sysvals, len(testruns), kerror)
3597
3598 # write the device timeline
3599 hf.write(devtl.html)
3600 hf.write('<div id="devicedetailtitle"></div>\n')
3601 hf.write('<div id="devicedetail" style="display:none;">\n')
3602 # draw the colored boxes for the device detail section
3603 for data in testruns:
3604 hf.write('<div id="devicedetail%d">\n' % data.testnumber)
3605 pscolor = 'linear-gradient(to top left, #ccc, #eee)'
3606 hf.write(devtl.html_phaselet.format('pre_suspend_process', \
3607 '0', '0', pscolor))
3608 for b in data.phases:
3609 phase = data.dmesg[b]
3610 length = phase['end']-phase['start']
3611 left = '%.3f' % (((phase['start']-t0)*100.0)/tTotal)
3612 width = '%.3f' % ((length*100.0)/tTotal)
3613 hf.write(devtl.html_phaselet.format(b, left, width, \
3614 data.dmesg[b]['color']))
3615 hf.write(devtl.html_phaselet.format('post_resume_process', \
3616 '0', '0', pscolor))
3617 if sysvals.suspendmode == 'command':
3618 hf.write(devtl.html_phaselet.format('cmdexec', '0', '0', pscolor))
3619 hf.write('</div>\n')
3620 hf.write('</div>\n')
3621
3622 # write the ftrace data (callgraph)
3623 if sysvals.cgtest >= 0 and len(testruns) > sysvals.cgtest:
3624 data = testruns[sysvals.cgtest]
3625 else:
3626 data = testruns[-1]
3627 if(sysvals.usecallgraph and not sysvals.embedded):
3628 addCallgraphs(sysvals, hf, data)
3629
3630 # add the test log as a hidden div
3631 if sysvals.logmsg:
3632 hf.write('<div id="testlog" style="display:none;">\n'+sysvals.logmsg+'</div>\n')
3633 # add the dmesg log as a hidden div
3634 if sysvals.addlogs and sysvals.dmesgfile:
3635 hf.write('<div id="dmesglog" style="display:none;">\n')
3636 lf = open(sysvals.dmesgfile, 'r')
3637 for line in lf:
3638 line = line.replace('<', '&lt').replace('>', '&gt')
3639 hf.write(line)
3640 lf.close()
3641 hf.write('</div>\n')
3642 # add the ftrace log as a hidden div
3643 if sysvals.addlogs and sysvals.ftracefile:
3644 hf.write('<div id="ftracelog" style="display:none;">\n')
3645 lf = open(sysvals.ftracefile, 'r')
3646 for line in lf:
3647 hf.write(line)
3648 lf.close()
3649 hf.write('</div>\n')
3650
3651 if(not sysvals.embedded):
3652 # write the footer and close
3653 addScriptCode(hf, testruns)
3654 hf.write('</body>\n</html>\n')
3655 else:
3656 # embedded out will be loaded in a page, skip the js
3657 t0 = (testruns[0].start - testruns[-1].tSuspended) * 1000
3658 tMax = (testruns[-1].end - testruns[-1].tSuspended) * 1000
3659 # add js code in a div entry for later evaluation
3660 detail = 'var bounds = [%f,%f];\n' % (t0, tMax)
3661 detail += 'var devtable = [\n'
3662 for data in testruns:
3663 topo = data.deviceTopology()
3664 detail += '\t"%s",\n' % (topo)
3665 detail += '];\n'
3666 hf.write('<div id=customcode style=display:none>\n'+detail+'</div>\n')
3667 hf.close()
3668 return True
3669
3670def addCSS(hf, sv, testcount=1, kerror=False, extra=''):
3671 kernel = sv.stamp['kernel']
3672 host = sv.hostname[0].upper()+sv.hostname[1:]
3673 mode = sv.suspendmode
3674 if sv.suspendmode in suspendmodename:
3675 mode = suspendmodename[sv.suspendmode]
3676 title = host+' '+mode+' '+kernel
3677
3678 # various format changes by flags
3679 cgchk = 'checked'
3680 cgnchk = 'not(:checked)'
3681 if sv.cgexp:
3682 cgchk = 'not(:checked)'
3683 cgnchk = 'checked'
3684
3685 hoverZ = 'z-index:8;'
3686 if sv.usedevsrc:
3687 hoverZ = ''
3688
3689 devlistpos = 'absolute'
3690 if testcount > 1:
3691 devlistpos = 'relative'
3692
3693 scaleTH = 20
3694 if kerror:
3695 scaleTH = 60
3696
3697 # write the html header first (html head, css code, up to body start)
3698 html_header = '<!DOCTYPE html>\n<html>\n<head>\n\
3699 <meta http-equiv="content-type" content="text/html; charset=UTF-8">\n\
3700 <title>'+title+'</title>\n\
3701 <style type=\'text/css\'>\n\
3702 body {overflow-y:scroll;}\n\
3703 .stamp {width:100%;text-align:center;background:gray;line-height:30px;color:white;font:25px Arial;}\n\
3704 .callgraph {margin-top:30px;box-shadow:5px 5px 20px black;}\n\
3705 .callgraph article * {padding-left:28px;}\n\
3706 h1 {color:black;font:bold 30px Times;}\n\
3707 t0 {color:black;font:bold 30px Times;}\n\
3708 t1 {color:black;font:30px Times;}\n\
3709 t2 {color:black;font:25px Times;}\n\
3710 t3 {color:black;font:20px Times;white-space:nowrap;}\n\
3711 t4 {color:black;font:bold 30px Times;line-height:60px;white-space:nowrap;}\n\
3712 cS {font:bold 13px Times;}\n\
3713 table {width:100%;}\n\
3714 .gray {background:rgba(80,80,80,0.1);}\n\
3715 .green {background:rgba(204,255,204,0.4);}\n\
3716 .purple {background:rgba(128,0,128,0.2);}\n\
3717 .yellow {background:rgba(255,255,204,0.4);}\n\
3718 .blue {background:rgba(169,208,245,0.4);}\n\
3719 .time1 {font:22px Arial;border:1px solid;}\n\
3720 .time2 {font:15px Arial;border-bottom:1px solid;border-left:1px solid;border-right:1px solid;}\n\
3721 td {text-align:center;}\n\
3722 r {color:#500000;font:15px Tahoma;}\n\
3723 n {color:#505050;font:15px Tahoma;}\n\
3724 .tdhl {color:red;}\n\
3725 .hide {display:none;}\n\
3726 .pf {display:none;}\n\
3727 .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\
3728 .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\
3729 .pf:'+cgchk+' ~ *:not(:nth-child(2)) {display:none;}\n\
3730 .zoombox {position:relative;width:100%;overflow-x:scroll;-webkit-user-select:none;-moz-user-select:none;user-select:none;}\n\
3731 .timeline {position:relative;font-size:14px;cursor:pointer;width:100%; overflow:hidden;background:linear-gradient(#cccccc, white);}\n\
3732 .thread {position:absolute;height:0%;overflow:hidden;z-index:7;line-height:30px;font-size:14px;border:1px solid;text-align:center;white-space:nowrap;}\n\
3733 .thread.ps {border-radius:3px;background:linear-gradient(to top, #ccc, #eee);}\n\
3734 .thread:hover {background:white;border:1px solid red;'+hoverZ+'}\n\
3735 .thread.sec,.thread.sec:hover {background:black;border:0;color:white;line-height:15px;font-size:10px;}\n\
3736 .hover {background:white;border:1px solid red;'+hoverZ+'}\n\
3737 .hover.sync {background:white;}\n\
3738 .hover.bg,.hover.kth,.hover.sync,.hover.ps {background:white;}\n\
3739 .jiffie {position:absolute;pointer-events: none;z-index:8;}\n\
3740 .traceevent {position:absolute;font-size:10px;z-index:7;overflow:hidden;color:black;text-align:center;white-space:nowrap;border-radius:5px;border:1px solid black;background:linear-gradient(to bottom right,#CCC,#969696);}\n\
3741 .traceevent:hover {color:white;font-weight:bold;border:1px solid white;}\n\
3742 .phase {position:absolute;overflow:hidden;border:0px;text-align:center;}\n\
3743 .phaselet {float:left;overflow:hidden;border:0px;text-align:center;min-height:100px;font-size:24px;}\n\
3744 .t {position:absolute;line-height:'+('%d'%scaleTH)+'px;pointer-events:none;top:0;height:100%;border-right:1px solid black;z-index:6;}\n\
3745 .err {position:absolute;top:0%;height:100%;border-right:3px solid red;color:red;font:bold 14px Times;line-height:18px;}\n\
3746 .legend {position:relative; width:100%; height:40px; text-align:center;margin-bottom:20px}\n\
3747 .legend .square {position:absolute;cursor:pointer;top:10px; width:0px;height:20px;border:1px solid;padding-left:20px;}\n\
3748 button {height:40px;width:200px;margin-bottom:20px;margin-top:20px;font-size:24px;}\n\
3749 .logbtn {position:relative;float:right;height:25px;width:50px;margin-top:3px;margin-bottom:0;font-size:10px;text-align:center;}\n\
3750 .devlist {position:'+devlistpos+';width:190px;}\n\
3751 a:link {color:white;text-decoration:none;}\n\
3752 a:visited {color:white;}\n\
3753 a:hover {color:white;}\n\
3754 a:active {color:white;}\n\
3755 .version {position:relative;float:left;color:white;font-size:10px;line-height:30px;margin-left:10px;}\n\
3756 #devicedetail {min-height:100px;box-shadow:5px 5px 20px black;}\n\
3757 .tblock {position:absolute;height:100%;background:#ddd;}\n\
3758 .tback {position:absolute;width:100%;background:linear-gradient(#ccc, #ddd);}\n\
3759 .bg {z-index:1;}\n\
3760'+extra+'\
3761 </style>\n</head>\n<body>\n'
3762 hf.write(html_header)
3763
3764# Function: addScriptCode
3765# Description:
3766# Adds the javascript code to the output html
3767# Arguments:
3768# hf: the open html file pointer
3769# testruns: array of Data objects from parseKernelLog or parseTraceLog
3770def addScriptCode(hf, testruns):
3771 t0 = testruns[0].start * 1000
3772 tMax = testruns[-1].end * 1000
3773 # create an array in javascript memory with the device details
3774 detail = ' var devtable = [];\n'
3775 for data in testruns:
3776 topo = data.deviceTopology()
3777 detail += ' devtable[%d] = "%s";\n' % (data.testnumber, topo)
3778 detail += ' var bounds = [%f,%f];\n' % (t0, tMax)
3779 # add the code which will manipulate the data in the browser
3780 script_code = \
3781 '<script type="text/javascript">\n'+detail+\
3782 ' var resolution = -1;\n'\
3783 ' var dragval = [0, 0];\n'\
3784 ' function redrawTimescale(t0, tMax, tS) {\n'\
3785 ' var rline = \'<div class="t" style="left:0;border-left:1px solid black;border-right:0;">\';\n'\
3786 ' var tTotal = tMax - t0;\n'\
3787 ' var list = document.getElementsByClassName("tblock");\n'\
3788 ' for (var i = 0; i < list.length; i++) {\n'\
3789 ' var timescale = list[i].getElementsByClassName("timescale")[0];\n'\
3790 ' var m0 = t0 + (tTotal*parseFloat(list[i].style.left)/100);\n'\
3791 ' var mTotal = tTotal*parseFloat(list[i].style.width)/100;\n'\
3792 ' var mMax = m0 + mTotal;\n'\
3793 ' var html = "";\n'\
3794 ' var divTotal = Math.floor(mTotal/tS) + 1;\n'\
3795 ' if(divTotal > 1000) continue;\n'\
3796 ' var divEdge = (mTotal - tS*(divTotal-1))*100/mTotal;\n'\
3797 ' var pos = 0.0, val = 0.0;\n'\
3798 ' for (var j = 0; j < divTotal; j++) {\n'\
3799 ' var htmlline = "";\n'\
3800 ' var mode = list[i].id[5];\n'\
3801 ' if(mode == "s") {\n'\
3802 ' pos = 100 - (((j)*tS*100)/mTotal) - divEdge;\n'\
3803 ' val = (j-divTotal+1)*tS;\n'\
3804 ' if(j == divTotal - 1)\n'\
3805 ' htmlline = \'<div class="t" style="right:\'+pos+\'%"><cS>S&rarr;</cS></div>\';\n'\
3806 ' else\n'\
3807 ' htmlline = \'<div class="t" style="right:\'+pos+\'%">\'+val+\'ms</div>\';\n'\
3808 ' } else {\n'\
3809 ' pos = 100 - (((j)*tS*100)/mTotal);\n'\
3810 ' val = (j)*tS;\n'\
3811 ' htmlline = \'<div class="t" style="right:\'+pos+\'%">\'+val+\'ms</div>\';\n'\
3812 ' if(j == 0)\n'\
3813 ' if(mode == "r")\n'\
3814 ' htmlline = rline+"<cS>&larr;R</cS></div>";\n'\
3815 ' else\n'\
3816 ' htmlline = rline+"<cS>0ms</div>";\n'\
3817 ' }\n'\
3818 ' html += htmlline;\n'\
3819 ' }\n'\
3820 ' timescale.innerHTML = html;\n'\
3821 ' }\n'\
3822 ' }\n'\
3823 ' function zoomTimeline() {\n'\
3824 ' var dmesg = document.getElementById("dmesg");\n'\
3825 ' var zoombox = document.getElementById("dmesgzoombox");\n'\
3826 ' var left = zoombox.scrollLeft;\n'\
3827 ' var val = parseFloat(dmesg.style.width);\n'\
3828 ' var newval = 100;\n'\
3829 ' var sh = window.outerWidth / 2;\n'\
3830 ' if(this.id == "zoomin") {\n'\
3831 ' newval = val * 1.2;\n'\
3832 ' if(newval > 910034) newval = 910034;\n'\
3833 ' dmesg.style.width = newval+"%";\n'\
3834 ' zoombox.scrollLeft = ((left + sh) * newval / val) - sh;\n'\
3835 ' } else if (this.id == "zoomout") {\n'\
3836 ' newval = val / 1.2;\n'\
3837 ' if(newval < 100) newval = 100;\n'\
3838 ' dmesg.style.width = newval+"%";\n'\
3839 ' zoombox.scrollLeft = ((left + sh) * newval / val) - sh;\n'\
3840 ' } else {\n'\
3841 ' zoombox.scrollLeft = 0;\n'\
3842 ' dmesg.style.width = "100%";\n'\
3843 ' }\n'\
3844 ' var tS = [10000, 5000, 2000, 1000, 500, 200, 100, 50, 20, 10, 5, 2, 1];\n'\
3845 ' var t0 = bounds[0];\n'\
3846 ' var tMax = bounds[1];\n'\
3847 ' var tTotal = tMax - t0;\n'\
3848 ' var wTotal = tTotal * 100.0 / newval;\n'\
3849 ' var idx = 7*window.innerWidth/1100;\n'\
3850 ' for(var i = 0; (i < tS.length)&&((wTotal / tS[i]) < idx); i++);\n'\
3851 ' if(i >= tS.length) i = tS.length - 1;\n'\
3852 ' if(tS[i] == resolution) return;\n'\
3853 ' resolution = tS[i];\n'\
3854 ' redrawTimescale(t0, tMax, tS[i]);\n'\
3855 ' }\n'\
3856 ' function deviceName(title) {\n'\
3857 ' var name = title.slice(0, title.indexOf(" ("));\n'\
3858 ' return name;\n'\
3859 ' }\n'\
3860 ' function deviceHover() {\n'\
3861 ' var name = deviceName(this.title);\n'\
3862 ' var dmesg = document.getElementById("dmesg");\n'\
3863 ' var dev = dmesg.getElementsByClassName("thread");\n'\
3864 ' var cpu = -1;\n'\
3865 ' if(name.match("CPU_ON\[[0-9]*\]"))\n'\
3866 ' cpu = parseInt(name.slice(7));\n'\
3867 ' else if(name.match("CPU_OFF\[[0-9]*\]"))\n'\
3868 ' cpu = parseInt(name.slice(8));\n'\
3869 ' for (var i = 0; i < dev.length; i++) {\n'\
3870 ' dname = deviceName(dev[i].title);\n'\
3871 ' var cname = dev[i].className.slice(dev[i].className.indexOf("thread"));\n'\
3872 ' if((cpu >= 0 && dname.match("CPU_O[NF]*\\\[*"+cpu+"\\\]")) ||\n'\
3873 ' (name == dname))\n'\
3874 ' {\n'\
3875 ' dev[i].className = "hover "+cname;\n'\
3876 ' } else {\n'\
3877 ' dev[i].className = cname;\n'\
3878 ' }\n'\
3879 ' }\n'\
3880 ' }\n'\
3881 ' function deviceUnhover() {\n'\
3882 ' var dmesg = document.getElementById("dmesg");\n'\
3883 ' var dev = dmesg.getElementsByClassName("thread");\n'\
3884 ' for (var i = 0; i < dev.length; i++) {\n'\
3885 ' dev[i].className = dev[i].className.slice(dev[i].className.indexOf("thread"));\n'\
3886 ' }\n'\
3887 ' }\n'\
3888 ' function deviceTitle(title, total, cpu) {\n'\
3889 ' var prefix = "Total";\n'\
3890 ' if(total.length > 3) {\n'\
3891 ' prefix = "Average";\n'\
3892 ' total[1] = (total[1]+total[3])/2;\n'\
3893 ' total[2] = (total[2]+total[4])/2;\n'\
3894 ' }\n'\
3895 ' var devtitle = document.getElementById("devicedetailtitle");\n'\
3896 ' var name = deviceName(title);\n'\
3897 ' if(cpu >= 0) name = "CPU"+cpu;\n'\
3898 ' var driver = "";\n'\
3899 ' var tS = "<t2>(</t2>";\n'\
3900 ' var tR = "<t2>)</t2>";\n'\
3901 ' if(total[1] > 0)\n'\
3902 ' tS = "<t2>("+prefix+" Suspend:</t2><t0> "+total[1].toFixed(3)+" ms</t0> ";\n'\
3903 ' if(total[2] > 0)\n'\
3904 ' tR = " <t2>"+prefix+" Resume:</t2><t0> "+total[2].toFixed(3)+" ms<t2>)</t2></t0>";\n'\
3905 ' var s = title.indexOf("{");\n'\
3906 ' var e = title.indexOf("}");\n'\
3907 ' if((s >= 0) && (e >= 0))\n'\
3908 ' driver = title.slice(s+1, e) + " <t1>@</t1> ";\n'\
3909 ' if(total[1] > 0 && total[2] > 0)\n'\
3910 ' devtitle.innerHTML = "<t0>"+driver+name+"</t0> "+tS+tR;\n'\
3911 ' else\n'\
3912 ' devtitle.innerHTML = "<t0>"+title+"</t0>";\n'\
3913 ' return name;\n'\
3914 ' }\n'\
3915 ' function deviceDetail() {\n'\
3916 ' var devinfo = document.getElementById("devicedetail");\n'\
3917 ' devinfo.style.display = "block";\n'\
3918 ' var name = deviceName(this.title);\n'\
3919 ' var cpu = -1;\n'\
3920 ' if(name.match("CPU_ON\[[0-9]*\]"))\n'\
3921 ' cpu = parseInt(name.slice(7));\n'\
3922 ' else if(name.match("CPU_OFF\[[0-9]*\]"))\n'\
3923 ' cpu = parseInt(name.slice(8));\n'\
3924 ' var dmesg = document.getElementById("dmesg");\n'\
3925 ' var dev = dmesg.getElementsByClassName("thread");\n'\
3926 ' var idlist = [];\n'\
3927 ' var pdata = [[]];\n'\
3928 ' if(document.getElementById("devicedetail1"))\n'\
3929 ' pdata = [[], []];\n'\
3930 ' var pd = pdata[0];\n'\
3931 ' var total = [0.0, 0.0, 0.0];\n'\
3932 ' for (var i = 0; i < dev.length; i++) {\n'\
3933 ' dname = deviceName(dev[i].title);\n'\
3934 ' if((cpu >= 0 && dname.match("CPU_O[NF]*\\\[*"+cpu+"\\\]")) ||\n'\
3935 ' (name == dname))\n'\
3936 ' {\n'\
3937 ' idlist[idlist.length] = dev[i].id;\n'\
3938 ' var tidx = 1;\n'\
3939 ' if(dev[i].id[0] == "a") {\n'\
3940 ' pd = pdata[0];\n'\
3941 ' } else {\n'\
3942 ' if(pdata.length == 1) pdata[1] = [];\n'\
3943 ' if(total.length == 3) total[3]=total[4]=0.0;\n'\
3944 ' pd = pdata[1];\n'\
3945 ' tidx = 3;\n'\
3946 ' }\n'\
3947 ' var info = dev[i].title.split(" ");\n'\
3948 ' var pname = info[info.length-1];\n'\
3949 ' pd[pname] = parseFloat(info[info.length-3].slice(1));\n'\
3950 ' total[0] += pd[pname];\n'\
3951 ' if(pname.indexOf("suspend") >= 0)\n'\
3952 ' total[tidx] += pd[pname];\n'\
3953 ' else\n'\
3954 ' total[tidx+1] += pd[pname];\n'\
3955 ' }\n'\
3956 ' }\n'\
3957 ' var devname = deviceTitle(this.title, total, cpu);\n'\
3958 ' var left = 0.0;\n'\
3959 ' for (var t = 0; t < pdata.length; t++) {\n'\
3960 ' pd = pdata[t];\n'\
3961 ' devinfo = document.getElementById("devicedetail"+t);\n'\
3962 ' var phases = devinfo.getElementsByClassName("phaselet");\n'\
3963 ' for (var i = 0; i < phases.length; i++) {\n'\
3964 ' if(phases[i].id in pd) {\n'\
3965 ' var w = 100.0*pd[phases[i].id]/total[0];\n'\
3966 ' var fs = 32;\n'\
3967 ' if(w < 8) fs = 4*w | 0;\n'\
3968 ' var fs2 = fs*3/4;\n'\
3969 ' phases[i].style.width = w+"%";\n'\
3970 ' phases[i].style.left = left+"%";\n'\
3971 ' phases[i].title = phases[i].id+" "+pd[phases[i].id]+" ms";\n'\
3972 ' left += w;\n'\
3973 ' var time = "<t4 style=\\"font-size:"+fs+"px\\">"+pd[phases[i].id]+" ms<br></t4>";\n'\
3974 ' var pname = "<t3 style=\\"font-size:"+fs2+"px\\">"+phases[i].id.replace(new RegExp("_", "g"), " ")+"</t3>";\n'\
3975 ' phases[i].innerHTML = time+pname;\n'\
3976 ' } else {\n'\
3977 ' phases[i].style.width = "0%";\n'\
3978 ' phases[i].style.left = left+"%";\n'\
3979 ' }\n'\
3980 ' }\n'\
3981 ' }\n'\
3982 ' if(typeof devstats !== \'undefined\')\n'\
3983 ' callDetail(this.id, this.title);\n'\
3984 ' var cglist = document.getElementById("callgraphs");\n'\
3985 ' if(!cglist) return;\n'\
3986 ' var cg = cglist.getElementsByClassName("atop");\n'\
3987 ' if(cg.length < 10) return;\n'\
3988 ' for (var i = 0; i < cg.length; i++) {\n'\
3989 ' cgid = cg[i].id.split("x")[0]\n'\
3990 ' if(idlist.indexOf(cgid) >= 0) {\n'\
3991 ' cg[i].style.display = "block";\n'\
3992 ' } else {\n'\
3993 ' cg[i].style.display = "none";\n'\
3994 ' }\n'\
3995 ' }\n'\
3996 ' }\n'\
3997 ' function callDetail(devid, devtitle) {\n'\
3998 ' if(!(devid in devstats) || devstats[devid].length < 1)\n'\
3999 ' return;\n'\
4000 ' var list = devstats[devid];\n'\
4001 ' var tmp = devtitle.split(" ");\n'\
4002 ' var name = tmp[0], phase = tmp[tmp.length-1];\n'\
4003 ' var dd = document.getElementById(phase);\n'\
4004 ' var total = parseFloat(tmp[1].slice(1));\n'\
4005 ' var mlist = [];\n'\
4006 ' var maxlen = 0;\n'\
4007 ' var info = []\n'\
4008 ' for(var i in list) {\n'\
4009 ' if(list[i][0] == "@") {\n'\
4010 ' info = list[i].split("|");\n'\
4011 ' continue;\n'\
4012 ' }\n'\
4013 ' var tmp = list[i].split("|");\n'\
4014 ' var t = parseFloat(tmp[0]), f = tmp[1], c = parseInt(tmp[2]);\n'\
4015 ' var p = (t*100.0/total).toFixed(2);\n'\
4016 ' mlist[mlist.length] = [f, c, t.toFixed(2), p+"%"];\n'\
4017 ' if(f.length > maxlen)\n'\
4018 ' maxlen = f.length;\n'\
4019 ' }\n'\
4020 ' var pad = 5;\n'\
4021 ' if(mlist.length == 0) pad = 30;\n'\
4022 ' var html = \'<div style="padding-top:\'+pad+\'px"><t3> <b>\'+name+\':</b>\';\n'\
4023 ' if(info.length > 2)\n'\
4024 ' html += " start=<b>"+info[1]+"</b>, end=<b>"+info[2]+"</b>";\n'\
4025 ' if(info.length > 3)\n'\
4026 ' html += ", length<i>(w/o overhead)</i>=<b>"+info[3]+" ms</b>";\n'\
4027 ' if(info.length > 4)\n'\
4028 ' html += ", return=<b>"+info[4]+"</b>";\n'\
4029 ' html += "</t3></div>";\n'\
4030 ' if(mlist.length > 0) {\n'\
4031 ' html += \'<table class=fstat style="padding-top:\'+(maxlen*5)+\'px;"><tr><th>Function</th>\';\n'\
4032 ' for(var i in mlist)\n'\
4033 ' html += "<td class=vt>"+mlist[i][0]+"</td>";\n'\
4034 ' html += "</tr><tr><th>Calls</th>";\n'\
4035 ' for(var i in mlist)\n'\
4036 ' html += "<td>"+mlist[i][1]+"</td>";\n'\
4037 ' html += "</tr><tr><th>Time(ms)</th>";\n'\
4038 ' for(var i in mlist)\n'\
4039 ' html += "<td>"+mlist[i][2]+"</td>";\n'\
4040 ' html += "</tr><tr><th>Percent</th>";\n'\
4041 ' for(var i in mlist)\n'\
4042 ' html += "<td>"+mlist[i][3]+"</td>";\n'\
4043 ' html += "</tr></table>";\n'\
4044 ' }\n'\
4045 ' dd.innerHTML = html;\n'\
4046 ' var height = (maxlen*5)+100;\n'\
4047 ' dd.style.height = height+"px";\n'\
4048 ' document.getElementById("devicedetail").style.height = height+"px";\n'\
4049 ' }\n'\
4050 ' function callSelect() {\n'\
4051 ' var cglist = document.getElementById("callgraphs");\n'\
4052 ' if(!cglist) return;\n'\
4053 ' var cg = cglist.getElementsByClassName("atop");\n'\
4054 ' for (var i = 0; i < cg.length; i++) {\n'\
4055 ' if(this.id == cg[i].id) {\n'\
4056 ' cg[i].style.display = "block";\n'\
4057 ' } else {\n'\
4058 ' cg[i].style.display = "none";\n'\
4059 ' }\n'\
4060 ' }\n'\
4061 ' }\n'\
4062 ' function devListWindow(e) {\n'\
4063 ' var win = window.open();\n'\
4064 ' var html = "<title>"+e.target.innerHTML+"</title>"+\n'\
4065 ' "<style type=\\"text/css\\">"+\n'\
4066 ' " ul {list-style-type:circle;padding-left:10px;margin-left:10px;}"+\n'\
4067 ' "</style>"\n'\
4068 ' var dt = devtable[0];\n'\
4069 ' if(e.target.id != "devlist1")\n'\
4070 ' dt = devtable[1];\n'\
4071 ' win.document.write(html+dt);\n'\
4072 ' }\n'\
4073 ' function errWindow() {\n'\
4074 ' var text = this.id;\n'\
4075 ' var win = window.open();\n'\
4076 ' win.document.write("<pre>"+text+"</pre>");\n'\
4077 ' win.document.close();\n'\
4078 ' }\n'\
4079 ' function logWindow(e) {\n'\
4080 ' var name = e.target.id.slice(4);\n'\
4081 ' var win = window.open();\n'\
4082 ' var log = document.getElementById(name+"log");\n'\
4083 ' var title = "<title>"+document.title.split(" ")[0]+" "+name+" log</title>";\n'\
4084 ' win.document.write(title+"<pre>"+log.innerHTML+"</pre>");\n'\
4085 ' win.document.close();\n'\
4086 ' }\n'\
4087 ' function onClickPhase(e) {\n'\
4088 ' }\n'\
4089 ' function onMouseDown(e) {\n'\
4090 ' dragval[0] = e.clientX;\n'\
4091 ' dragval[1] = document.getElementById("dmesgzoombox").scrollLeft;\n'\
4092 ' document.onmousemove = onMouseMove;\n'\
4093 ' }\n'\
4094 ' function onMouseMove(e) {\n'\
4095 ' var zoombox = document.getElementById("dmesgzoombox");\n'\
4096 ' zoombox.scrollLeft = dragval[1] + dragval[0] - e.clientX;\n'\
4097 ' }\n'\
4098 ' function onMouseUp(e) {\n'\
4099 ' document.onmousemove = null;\n'\
4100 ' }\n'\
4101 ' function onKeyPress(e) {\n'\
4102 ' var c = e.charCode;\n'\
4103 ' if(c != 42 && c != 43 && c != 45) return;\n'\
4104 ' var click = document.createEvent("Events");\n'\
4105 ' click.initEvent("click", true, false);\n'\
4106 ' if(c == 43) \n'\
4107 ' document.getElementById("zoomin").dispatchEvent(click);\n'\
4108 ' else if(c == 45)\n'\
4109 ' document.getElementById("zoomout").dispatchEvent(click);\n'\
4110 ' else if(c == 42)\n'\
4111 ' document.getElementById("zoomdef").dispatchEvent(click);\n'\
4112 ' }\n'\
4113 ' window.addEventListener("resize", function () {zoomTimeline();});\n'\
4114 ' window.addEventListener("load", function () {\n'\
4115 ' var dmesg = document.getElementById("dmesg");\n'\
4116 ' dmesg.style.width = "100%"\n'\
4117 ' dmesg.onmousedown = onMouseDown;\n'\
4118 ' document.onmouseup = onMouseUp;\n'\
4119 ' document.onkeypress = onKeyPress;\n'\
4120 ' document.getElementById("zoomin").onclick = zoomTimeline;\n'\
4121 ' document.getElementById("zoomout").onclick = zoomTimeline;\n'\
4122 ' document.getElementById("zoomdef").onclick = zoomTimeline;\n'\
4123 ' var list = document.getElementsByClassName("square");\n'\
4124 ' for (var i = 0; i < list.length; i++)\n'\
4125 ' list[i].onclick = onClickPhase;\n'\
4126 ' var list = document.getElementsByClassName("err");\n'\
4127 ' for (var i = 0; i < list.length; i++)\n'\
4128 ' list[i].onclick = errWindow;\n'\
4129 ' var list = document.getElementsByClassName("logbtn");\n'\
4130 ' for (var i = 0; i < list.length; i++)\n'\
4131 ' list[i].onclick = logWindow;\n'\
4132 ' list = document.getElementsByClassName("devlist");\n'\
4133 ' for (var i = 0; i < list.length; i++)\n'\
4134 ' list[i].onclick = devListWindow;\n'\
4135 ' var dev = dmesg.getElementsByClassName("thread");\n'\
4136 ' for (var i = 0; i < dev.length; i++) {\n'\
4137 ' dev[i].onclick = deviceDetail;\n'\
4138 ' dev[i].onmouseover = deviceHover;\n'\
4139 ' dev[i].onmouseout = deviceUnhover;\n'\
4140 ' }\n'\
4141 ' var dev = dmesg.getElementsByClassName("srccall");\n'\
4142 ' for (var i = 0; i < dev.length; i++)\n'\
4143 ' dev[i].onclick = callSelect;\n'\
4144 ' zoomTimeline();\n'\
4145 ' });\n'\
4146 '</script>\n'
4147 hf.write(script_code);
4148
4149# Function: executeSuspend
4150# Description:
4151# Execute system suspend through the sysfs interface, then copy the output
4152# dmesg and ftrace files to the test output directory.
4153def executeSuspend():
4154 pm = ProcessMonitor()
4155 tp = sysvals.tpath
4156 fwdata = []
4157 # mark the start point in the kernel ring buffer just as we start
4158 sysvals.initdmesg()
4159 # start ftrace
4160 if(sysvals.usecallgraph or sysvals.usetraceevents):
4161 print('START TRACING')
4162 sysvals.fsetVal('1', 'tracing_on')
4163 if sysvals.useprocmon:
4164 pm.start()
4165 # execute however many s/r runs requested
4166 for count in range(1,sysvals.execcount+1):
4167 # x2delay in between test runs
4168 if(count > 1 and sysvals.x2delay > 0):
4169 sysvals.fsetVal('WAIT %d' % sysvals.x2delay, 'trace_marker')
4170 time.sleep(sysvals.x2delay/1000.0)
4171 sysvals.fsetVal('WAIT END', 'trace_marker')
4172 # start message
4173 if sysvals.testcommand != '':
4174 print('COMMAND START')
4175 else:
4176 if(sysvals.rtcwake):
4177 print('SUSPEND START')
4178 else:
4179 print('SUSPEND START (press a key to resume)')
4180 # set rtcwake
4181 if(sysvals.rtcwake):
4182 print('will issue an rtcwake in %d seconds' % sysvals.rtcwaketime)
4183 sysvals.rtcWakeAlarmOn()
4184 # start of suspend trace marker
4185 if(sysvals.usecallgraph or sysvals.usetraceevents):
4186 sysvals.fsetVal('SUSPEND START', 'trace_marker')
4187 # predelay delay
4188 if(count == 1 and sysvals.predelay > 0):
4189 sysvals.fsetVal('WAIT %d' % sysvals.predelay, 'trace_marker')
4190 time.sleep(sysvals.predelay/1000.0)
4191 sysvals.fsetVal('WAIT END', 'trace_marker')
4192 # initiate suspend or command
4193 if sysvals.testcommand != '':
4194 call(sysvals.testcommand+' 2>&1', shell=True);
4195 else:
4196 pf = open(sysvals.powerfile, 'w')
4197 pf.write(sysvals.suspendmode)
4198 # execution will pause here
4199 try:
4200 pf.close()
4201 except:
4202 pass
4203 if(sysvals.rtcwake):
4204 sysvals.rtcWakeAlarmOff()
4205 # postdelay delay
4206 if(count == sysvals.execcount and sysvals.postdelay > 0):
4207 sysvals.fsetVal('WAIT %d' % sysvals.postdelay, 'trace_marker')
4208 time.sleep(sysvals.postdelay/1000.0)
4209 sysvals.fsetVal('WAIT END', 'trace_marker')
4210 # return from suspend
4211 print('RESUME COMPLETE')
4212 if(sysvals.usecallgraph or sysvals.usetraceevents):
4213 sysvals.fsetVal('RESUME COMPLETE', 'trace_marker')
4214 if(sysvals.suspendmode == 'mem' or sysvals.suspendmode == 'command'):
4215 fwdata.append(getFPDT(False))
4216 # stop ftrace
4217 if(sysvals.usecallgraph or sysvals.usetraceevents):
4218 if sysvals.useprocmon:
4219 pm.stop()
4220 sysvals.fsetVal('0', 'tracing_on')
4221 print('CAPTURING TRACE')
4222 writeDatafileHeader(sysvals.ftracefile, fwdata)
4223 call('cat '+tp+'trace >> '+sysvals.ftracefile, shell=True)
4224 sysvals.fsetVal('', 'trace')
4225 devProps()
4226 # grab a copy of the dmesg output
4227 print('CAPTURING DMESG')
4228 writeDatafileHeader(sysvals.dmesgfile, fwdata)
4229 sysvals.getdmesg()
4230
4231def writeDatafileHeader(filename, fwdata):
4232 fp = open(filename, 'a')
4233 fp.write(sysvals.teststamp+'\n')
4234 if(sysvals.suspendmode == 'mem' or sysvals.suspendmode == 'command'):
4235 for fw in fwdata:
4236 if(fw):
4237 fp.write('# fwsuspend %u fwresume %u\n' % (fw[0], fw[1]))
4238 fp.close()
4239
4240# Function: setUSBDevicesAuto
4241# Description:
4242# Set the autosuspend control parameter of all USB devices to auto
4243# This can be dangerous, so use at your own risk, most devices are set
4244# to always-on since the kernel cant determine if the device can
4245# properly autosuspend
4246def setUSBDevicesAuto():
4247 rootCheck(True)
4248 for dirname, dirnames, filenames in os.walk('/sys/devices'):
4249 if(re.match('.*/usb[0-9]*.*', dirname) and
4250 'idVendor' in filenames and 'idProduct' in filenames):
4251 call('echo auto > %s/power/control' % dirname, shell=True)
4252 name = dirname.split('/')[-1]
4253 desc = Popen(['cat', '%s/product' % dirname],
4254 stderr=PIPE, stdout=PIPE).stdout.read().replace('\n', '')
4255 ctrl = Popen(['cat', '%s/power/control' % dirname],
4256 stderr=PIPE, stdout=PIPE).stdout.read().replace('\n', '')
4257 print('control is %s for %6s: %s' % (ctrl, name, desc))
4258
4259# Function: yesno
4260# Description:
4261# Print out an equivalent Y or N for a set of known parameter values
4262# Output:
4263# 'Y', 'N', or ' ' if the value is unknown
4264def yesno(val):
4265 yesvals = ['auto', 'enabled', 'active', '1']
4266 novals = ['on', 'disabled', 'suspended', 'forbidden', 'unsupported']
4267 if val in yesvals:
4268 return 'Y'
4269 elif val in novals:
4270 return 'N'
4271 return ' '
4272
4273# Function: ms2nice
4274# Description:
4275# Print out a very concise time string in minutes and seconds
4276# Output:
4277# The time string, e.g. "1901m16s"
4278def ms2nice(val):
4279 ms = 0
4280 try:
4281 ms = int(val)
4282 except:
4283 return 0.0
4284 m = ms / 60000
4285 s = (ms / 1000) - (m * 60)
4286 return '%3dm%2ds' % (m, s)
4287
4288# Function: detectUSB
4289# Description:
4290# Detect all the USB hosts and devices currently connected and add
4291# a list of USB device names to sysvals for better timeline readability
4292def detectUSB():
4293 field = {'idVendor':'', 'idProduct':'', 'product':'', 'speed':''}
4294 power = {'async':'', 'autosuspend':'', 'autosuspend_delay_ms':'',
4295 'control':'', 'persist':'', 'runtime_enabled':'',
4296 'runtime_status':'', 'runtime_usage':'',
4297 'runtime_active_time':'',
4298 'runtime_suspended_time':'',
4299 'active_duration':'',
4300 'connected_duration':''}
4301
4302 print('LEGEND')
4303 print('---------------------------------------------------------------------------------------------')
4304 print(' A = async/sync PM queue Y/N D = autosuspend delay (seconds)')
4305 print(' S = autosuspend Y/N rACTIVE = runtime active (min/sec)')
4306 print(' P = persist across suspend Y/N rSUSPEN = runtime suspend (min/sec)')
4307 print(' E = runtime suspend enabled/forbidden Y/N ACTIVE = active duration (min/sec)')
4308 print(' R = runtime status active/suspended Y/N CONNECT = connected duration (min/sec)')
4309 print(' U = runtime usage count')
4310 print('---------------------------------------------------------------------------------------------')
4311 print(' NAME ID DESCRIPTION SPEED A S P E R U D rACTIVE rSUSPEN ACTIVE CONNECT')
4312 print('---------------------------------------------------------------------------------------------')
4313
4314 for dirname, dirnames, filenames in os.walk('/sys/devices'):
4315 if(re.match('.*/usb[0-9]*.*', dirname) and
4316 'idVendor' in filenames and 'idProduct' in filenames):
4317 for i in field:
4318 field[i] = Popen(['cat', '%s/%s' % (dirname, i)],
4319 stderr=PIPE, stdout=PIPE).stdout.read().replace('\n', '')
4320 name = dirname.split('/')[-1]
4321 for i in power:
4322 power[i] = Popen(['cat', '%s/power/%s' % (dirname, i)],
4323 stderr=PIPE, stdout=PIPE).stdout.read().replace('\n', '')
4324 if(re.match('usb[0-9]*', name)):
4325 first = '%-8s' % name
4326 else:
4327 first = '%8s' % name
4328 print('%s [%s:%s] %-20s %-4s %1s %1s %1s %1s %1s %1s %1s %s %s %s %s' % \
4329 (first, field['idVendor'], field['idProduct'], \
4330 field['product'][0:20], field['speed'], \
4331 yesno(power['async']), \
4332 yesno(power['control']), \
4333 yesno(power['persist']), \
4334 yesno(power['runtime_enabled']), \
4335 yesno(power['runtime_status']), \
4336 power['runtime_usage'], \
4337 power['autosuspend'], \
4338 ms2nice(power['runtime_active_time']), \
4339 ms2nice(power['runtime_suspended_time']), \
4340 ms2nice(power['active_duration']), \
4341 ms2nice(power['connected_duration'])))
4342
4343# Function: devProps
4344# Description:
4345# Retrieve a list of properties for all devices in the trace log
4346def devProps(data=0):
4347 props = dict()
4348
4349 if data:
4350 idx = data.index(': ') + 2
4351 if idx >= len(data):
4352 return
4353 devlist = data[idx:].split(';')
4354 for dev in devlist:
4355 f = dev.split(',')
4356 if len(f) < 3:
4357 continue
4358 dev = f[0]
4359 props[dev] = DevProps()
4360 props[dev].altname = f[1]
4361 if int(f[2]):
4362 props[dev].async = True
4363 else:
4364 props[dev].async = False
4365 sysvals.devprops = props
4366 if sysvals.suspendmode == 'command' and 'testcommandstring' in props:
4367 sysvals.testcommand = props['testcommandstring'].altname
4368 return
4369
4370 if(os.path.exists(sysvals.ftracefile) == False):
4371 doError('%s does not exist' % sysvals.ftracefile)
4372
4373 # first get the list of devices we need properties for
4374 msghead = 'Additional data added by AnalyzeSuspend'
4375 alreadystamped = False
4376 tp = TestProps()
4377 tf = open(sysvals.ftracefile, 'r')
4378 for line in tf:
4379 if msghead in line:
4380 alreadystamped = True
4381 continue
4382 # determine the trace data type (required for further parsing)
4383 m = re.match(sysvals.tracertypefmt, line)
4384 if(m):
4385 tp.setTracerType(m.group('t'))
4386 continue
4387 # parse only valid lines, if this is not one move on
4388 m = re.match(tp.ftrace_line_fmt, line)
4389 if(not m or 'device_pm_callback_start' not in line):
4390 continue
4391 m = re.match('.*: (?P<drv>.*) (?P<d>.*), parent: *(?P<p>.*), .*', m.group('msg'));
4392 if(not m):
4393 continue
4394 dev = m.group('d')
4395 if dev not in props:
4396 props[dev] = DevProps()
4397 tf.close()
4398
4399 if not alreadystamped and sysvals.suspendmode == 'command':
4400 out = '#\n# '+msghead+'\n# Device Properties: '
4401 out += 'testcommandstring,%s,0;' % (sysvals.testcommand)
4402 with open(sysvals.ftracefile, 'a') as fp:
4403 fp.write(out+'\n')
4404 sysvals.devprops = props
4405 return
4406
4407 # now get the syspath for each of our target devices
4408 for dirname, dirnames, filenames in os.walk('/sys/devices'):
4409 if(re.match('.*/power', dirname) and 'async' in filenames):
4410 dev = dirname.split('/')[-2]
4411 if dev in props and (not props[dev].syspath or len(dirname) < len(props[dev].syspath)):
4412 props[dev].syspath = dirname[:-6]
4413
4414 # now fill in the properties for our target devices
4415 for dev in props:
4416 dirname = props[dev].syspath
4417 if not dirname or not os.path.exists(dirname):
4418 continue
4419 with open(dirname+'/power/async') as fp:
4420 text = fp.read()
4421 props[dev].async = False
4422 if 'enabled' in text:
4423 props[dev].async = True
4424 fields = os.listdir(dirname)
4425 if 'product' in fields:
4426 with open(dirname+'/product') as fp:
4427 props[dev].altname = fp.read()
4428 elif 'name' in fields:
4429 with open(dirname+'/name') as fp:
4430 props[dev].altname = fp.read()
4431 elif 'model' in fields:
4432 with open(dirname+'/model') as fp:
4433 props[dev].altname = fp.read()
4434 elif 'description' in fields:
4435 with open(dirname+'/description') as fp:
4436 props[dev].altname = fp.read()
4437 elif 'id' in fields:
4438 with open(dirname+'/id') as fp:
4439 props[dev].altname = fp.read()
4440 elif 'idVendor' in fields and 'idProduct' in fields:
4441 idv, idp = '', ''
4442 with open(dirname+'/idVendor') as fp:
4443 idv = fp.read().strip()
4444 with open(dirname+'/idProduct') as fp:
4445 idp = fp.read().strip()
4446 props[dev].altname = '%s:%s' % (idv, idp)
4447
4448 if props[dev].altname:
4449 out = props[dev].altname.strip().replace('\n', ' ')
4450 out = out.replace(',', ' ')
4451 out = out.replace(';', ' ')
4452 props[dev].altname = out
4453
4454 # and now write the data to the ftrace file
4455 if not alreadystamped:
4456 out = '#\n# '+msghead+'\n# Device Properties: '
4457 for dev in sorted(props):
4458 out += props[dev].out(dev)
4459 with open(sysvals.ftracefile, 'a') as fp:
4460 fp.write(out+'\n')
4461
4462 sysvals.devprops = props
4463
4464# Function: getModes
4465# Description:
4466# Determine the supported power modes on this system
4467# Output:
4468# A string list of the available modes
4469def getModes():
4470 modes = ''
4471 if(os.path.exists(sysvals.powerfile)):
4472 fp = open(sysvals.powerfile, 'r')
4473 modes = string.split(fp.read())
4474 fp.close()
4475 return modes
4476
4477# Function: getFPDT
4478# Description:
4479# Read the acpi bios tables and pull out FPDT, the firmware data
4480# Arguments:
4481# output: True to output the info to stdout, False otherwise
4482def getFPDT(output):
4483 rectype = {}
4484 rectype[0] = 'Firmware Basic Boot Performance Record'
4485 rectype[1] = 'S3 Performance Table Record'
4486 prectype = {}
4487 prectype[0] = 'Basic S3 Resume Performance Record'
4488 prectype[1] = 'Basic S3 Suspend Performance Record'
4489
4490 rootCheck(True)
4491 if(not os.path.exists(sysvals.fpdtpath)):
4492 if(output):
4493 doError('file does not exist: %s' % sysvals.fpdtpath)
4494 return False
4495 if(not os.access(sysvals.fpdtpath, os.R_OK)):
4496 if(output):
4497 doError('file is not readable: %s' % sysvals.fpdtpath)
4498 return False
4499 if(not os.path.exists(sysvals.mempath)):
4500 if(output):
4501 doError('file does not exist: %s' % sysvals.mempath)
4502 return False
4503 if(not os.access(sysvals.mempath, os.R_OK)):
4504 if(output):
4505 doError('file is not readable: %s' % sysvals.mempath)
4506 return False
4507
4508 fp = open(sysvals.fpdtpath, 'rb')
4509 buf = fp.read()
4510 fp.close()
4511
4512 if(len(buf) < 36):
4513 if(output):
4514 doError('Invalid FPDT table data, should '+\
4515 'be at least 36 bytes')
4516 return False
4517
4518 table = struct.unpack('4sIBB6s8sI4sI', buf[0:36])
4519 if(output):
4520 print('')
4521 print('Firmware Performance Data Table (%s)' % table[0])
4522 print(' Signature : %s' % table[0])
4523 print(' Table Length : %u' % table[1])
4524 print(' Revision : %u' % table[2])
4525 print(' Checksum : 0x%x' % table[3])
4526 print(' OEM ID : %s' % table[4])
4527 print(' OEM Table ID : %s' % table[5])
4528 print(' OEM Revision : %u' % table[6])
4529 print(' Creator ID : %s' % table[7])
4530 print(' Creator Revision : 0x%x' % table[8])
4531 print('')
4532
4533 if(table[0] != 'FPDT'):
4534 if(output):
4535 doError('Invalid FPDT table')
4536 return False
4537 if(len(buf) <= 36):
4538 return False
4539 i = 0
4540 fwData = [0, 0]
4541 records = buf[36:]
4542 fp = open(sysvals.mempath, 'rb')
4543 while(i < len(records)):
4544 header = struct.unpack('HBB', records[i:i+4])
4545 if(header[0] not in rectype):
4546 i += header[1]
4547 continue
4548 if(header[1] != 16):
4549 i += header[1]
4550 continue
4551 addr = struct.unpack('Q', records[i+8:i+16])[0]
4552 try:
4553 fp.seek(addr)
4554 first = fp.read(8)
4555 except:
4556 if(output):
4557 print('Bad address 0x%x in %s' % (addr, sysvals.mempath))
4558 return [0, 0]
4559 rechead = struct.unpack('4sI', first)
4560 recdata = fp.read(rechead[1]-8)
4561 if(rechead[0] == 'FBPT'):
4562 record = struct.unpack('HBBIQQQQQ', recdata)
4563 if(output):
4564 print('%s (%s)' % (rectype[header[0]], rechead[0]))
4565 print(' Reset END : %u ns' % record[4])
4566 print(' OS Loader LoadImage Start : %u ns' % record[5])
4567 print(' OS Loader StartImage Start : %u ns' % record[6])
4568 print(' ExitBootServices Entry : %u ns' % record[7])
4569 print(' ExitBootServices Exit : %u ns' % record[8])
4570 elif(rechead[0] == 'S3PT'):
4571 if(output):
4572 print('%s (%s)' % (rectype[header[0]], rechead[0]))
4573 j = 0
4574 while(j < len(recdata)):
4575 prechead = struct.unpack('HBB', recdata[j:j+4])
4576 if(prechead[0] not in prectype):
4577 continue
4578 if(prechead[0] == 0):
4579 record = struct.unpack('IIQQ', recdata[j:j+prechead[1]])
4580 fwData[1] = record[2]
4581 if(output):
4582 print(' %s' % prectype[prechead[0]])
4583 print(' Resume Count : %u' % \
4584 record[1])
4585 print(' FullResume : %u ns' % \
4586 record[2])
4587 print(' AverageResume : %u ns' % \
4588 record[3])
4589 elif(prechead[0] == 1):
4590 record = struct.unpack('QQ', recdata[j+4:j+prechead[1]])
4591 fwData[0] = record[1] - record[0]
4592 if(output):
4593 print(' %s' % prectype[prechead[0]])
4594 print(' SuspendStart : %u ns' % \
4595 record[0])
4596 print(' SuspendEnd : %u ns' % \
4597 record[1])
4598 print(' SuspendTime : %u ns' % \
4599 fwData[0])
4600 j += prechead[1]
4601 if(output):
4602 print('')
4603 i += header[1]
4604 fp.close()
4605 return fwData
4606
4607# Function: statusCheck
4608# Description:
4609# Verify that the requested command and options will work, and
4610# print the results to the terminal
4611# Output:
4612# True if the test will work, False if not
4613def statusCheck(probecheck=False):
4614 status = True
4615
4616 print('Checking this system (%s)...' % platform.node())
4617
4618 # check we have root access
4619 res = sysvals.colorText('NO (No features of this tool will work!)')
4620 if(rootCheck(False)):
4621 res = 'YES'
4622 print(' have root access: %s' % res)
4623 if(res != 'YES'):
4624 print(' Try running this script with sudo')
4625 return False
4626
4627 # check sysfs is mounted
4628 res = sysvals.colorText('NO (No features of this tool will work!)')
4629 if(os.path.exists(sysvals.powerfile)):
4630 res = 'YES'
4631 print(' is sysfs mounted: %s' % res)
4632 if(res != 'YES'):
4633 return False
4634
4635 # check target mode is a valid mode
4636 if sysvals.suspendmode != 'command':
4637 res = sysvals.colorText('NO')
4638 modes = getModes()
4639 if(sysvals.suspendmode in modes):
4640 res = 'YES'
4641 else:
4642 status = False
4643 print(' is "%s" a valid power mode: %s' % (sysvals.suspendmode, res))
4644 if(res == 'NO'):
4645 print(' valid power modes are: %s' % modes)
4646 print(' please choose one with -m')
4647
4648 # check if ftrace is available
4649 res = sysvals.colorText('NO')
4650 ftgood = sysvals.verifyFtrace()
4651 if(ftgood):
4652 res = 'YES'
4653 elif(sysvals.usecallgraph):
4654 status = False
4655 print(' is ftrace supported: %s' % res)
4656
4657 # check if kprobes are available
4658 res = sysvals.colorText('NO')
4659 sysvals.usekprobes = sysvals.verifyKprobes()
4660 if(sysvals.usekprobes):
4661 res = 'YES'
4662 else:
4663 sysvals.usedevsrc = False
4664 print(' are kprobes supported: %s' % res)
4665
4666 # what data source are we using
4667 res = 'DMESG'
4668 if(ftgood):
4669 sysvals.usetraceeventsonly = True
4670 sysvals.usetraceevents = False
4671 for e in sysvals.traceevents:
4672 check = False
4673 if(os.path.exists(sysvals.epath+e)):
4674 check = True
4675 if(not check):
4676 sysvals.usetraceeventsonly = False
4677 if(e == 'suspend_resume' and check):
4678 sysvals.usetraceevents = True
4679 if(sysvals.usetraceevents and sysvals.usetraceeventsonly):
4680 res = 'FTRACE (all trace events found)'
4681 elif(sysvals.usetraceevents):
4682 res = 'DMESG and FTRACE (suspend_resume trace event found)'
4683 print(' timeline data source: %s' % res)
4684
4685 # check if rtcwake
4686 res = sysvals.colorText('NO')
4687 if(sysvals.rtcpath != ''):
4688 res = 'YES'
4689 elif(sysvals.rtcwake):
4690 status = False
4691 print(' is rtcwake supported: %s' % res)
4692
4693 if not probecheck:
4694 return status
4695
4696 # verify kprobes
4697 if sysvals.usekprobes:
4698 for name in sysvals.tracefuncs:
4699 sysvals.defaultKprobe(name, sysvals.tracefuncs[name])
4700 if sysvals.usedevsrc:
4701 for name in sysvals.dev_tracefuncs:
4702 sysvals.defaultKprobe(name, sysvals.dev_tracefuncs[name])
4703 sysvals.addKprobes(True)
4704
4705 return status
4706
4707# Function: doError
4708# Description:
4709# generic error function for catastrphic failures
4710# Arguments:
4711# msg: the error message to print
4712# help: True if printHelp should be called after, False otherwise
4713def doError(msg, help=False):
4714 if(help == True):
4715 printHelp()
4716 print('ERROR: %s\n') % msg
4717 sys.exit()
4718
4719# Function: rootCheck
4720# Description:
4721# quick check to see if we have root access
4722def rootCheck(fatal):
4723 if(os.access(sysvals.powerfile, os.W_OK)):
4724 return True
4725 if fatal:
4726 doError('This command requires sysfs mount and root access')
4727 return False
4728
4729# Function: getArgInt
4730# Description:
4731# pull out an integer argument from the command line with checks
4732def getArgInt(name, args, min, max, main=True):
4733 if main:
4734 try:
4735 arg = args.next()
4736 except:
4737 doError(name+': no argument supplied', True)
4738 else:
4739 arg = args
4740 try:
4741 val = int(arg)
4742 except:
4743 doError(name+': non-integer value given', True)
4744 if(val < min or val > max):
4745 doError(name+': value should be between %d and %d' % (min, max), True)
4746 return val
4747
4748# Function: getArgFloat
4749# Description:
4750# pull out a float argument from the command line with checks
4751def getArgFloat(name, args, min, max, main=True):
4752 if main:
4753 try:
4754 arg = args.next()
4755 except:
4756 doError(name+': no argument supplied', True)
4757 else:
4758 arg = args
4759 try:
4760 val = float(arg)
4761 except:
4762 doError(name+': non-numerical value given', True)
4763 if(val < min or val > max):
4764 doError(name+': value should be between %f and %f' % (min, max), True)
4765 return val
4766
4767def processData():
4768 print('PROCESSING DATA')
4769 if(sysvals.usetraceeventsonly):
4770 testruns = parseTraceLog()
4771 if sysvals.dmesgfile:
4772 dmesgtext = loadKernelLog(True)
4773 for data in testruns:
4774 data.extractErrorInfo(dmesgtext)
4775 else:
4776 testruns = loadKernelLog()
4777 for data in testruns:
4778 parseKernelLog(data)
4779 if(sysvals.ftracefile and (sysvals.usecallgraph or sysvals.usetraceevents)):
4780 appendIncompleteTraceLog(testruns)
4781 createHTML(testruns)
4782
4783# Function: rerunTest
4784# Description:
4785# generate an output from an existing set of ftrace/dmesg logs
4786def rerunTest():
4787 if sysvals.ftracefile:
4788 doesTraceLogHaveTraceEvents()
4789 if not sysvals.dmesgfile and not sysvals.usetraceeventsonly:
4790 doError('recreating this html output requires a dmesg file')
4791 sysvals.setOutputFile()
4792 vprint('Output file: %s' % sysvals.htmlfile)
4793 if(os.path.exists(sysvals.htmlfile) and not os.access(sysvals.htmlfile, os.W_OK)):
4794 doError('missing permission to write to %s' % sysvals.htmlfile)
4795 processData()
4796
4797# Function: runTest
4798# Description:
4799# execute a suspend/resume, gather the logs, and generate the output
4800def runTest(subdir, testpath=''):
4801 # prepare for the test
4802 sysvals.initFtrace()
4803 sysvals.initTestOutput(subdir, testpath)
4804 vprint('Output files:\n\t%s\n\t%s\n\t%s' % \
4805 (sysvals.dmesgfile, sysvals.ftracefile, sysvals.htmlfile))
4806
4807 # execute the test
4808 executeSuspend()
4809 sysvals.cleanupFtrace()
4810 processData()
4811
4812 # if running as root, change output dir owner to sudo_user
4813 if os.path.isdir(sysvals.testdir) and os.getuid() == 0 and \
4814 'SUDO_USER' in os.environ:
4815 cmd = 'chown -R {0}:{0} {1} > /dev/null 2>&1'
4816 call(cmd.format(os.environ['SUDO_USER'], sysvals.testdir), shell=True)
4817
4818def find_in_html(html, strs, div=False):
4819 for str in strs:
4820 l = len(str)
4821 i = html.find(str)
4822 if i >= 0:
4823 break
4824 if i < 0:
4825 return ''
4826 if not div:
4827 return re.search(r'[-+]?\d*\.\d+|\d+', html[i+l:i+l+50]).group()
4828 n = html[i+l:].find('</div>')
4829 if n < 0:
4830 return ''
4831 return html[i+l:i+l+n]
4832
4833# Function: runSummary
4834# Description:
4835# create a summary of tests in a sub-directory
4836def runSummary(subdir, local=True):
4837 inpath = os.path.abspath(subdir)
4838 outpath = inpath
4839 if local:
4840 outpath = os.path.abspath('.')
4841 print('Generating a summary of folder "%s"' % inpath)
4842 testruns = []
4843 for dirname, dirnames, filenames in os.walk(subdir):
4844 for filename in filenames:
4845 if(not re.match('.*.html', filename)):
4846 continue
4847 file = os.path.join(dirname, filename)
4848 html = open(file, 'r').read(10000)
4849 suspend = find_in_html(html,
4850 ['Kernel Suspend: ', 'Kernel Suspend Time: '])
4851 resume = find_in_html(html,
4852 ['Kernel Resume: ', 'Kernel Resume Time: '])
4853 line = find_in_html(html, ['<div class="stamp">'], True)
4854 stmp = line.split()
4855 if not suspend or not resume or len(stmp) < 4:
4856 continue
4857 data = {
4858 'host': stmp[0],
4859 'kernel': stmp[1],
4860 'mode': stmp[2],
4861 'time': string.join(stmp[3:], ' '),
4862 'suspend': suspend,
4863 'resume': resume,
4864 'url': os.path.relpath(file, outpath),
4865 }
4866 if len(stmp) == 7:
4867 data['kernel'] = 'unknown'
4868 data['mode'] = stmp[1]
4869 data['time'] = string.join(stmp[2:], ' ')
4870 testruns.append(data)
4871 outfile = os.path.join(outpath, 'summary.html')
4872 print('Summary file: %s' % outfile)
4873 createHTMLSummarySimple(testruns, outfile, inpath)
4874
4875# Function: checkArgBool
4876# Description:
4877# check if a boolean string value is true or false
4878def checkArgBool(value):
4879 yes = ['1', 'true', 'yes', 'on']
4880 if value.lower() in yes:
4881 return True
4882 return False
4883
4884# Function: configFromFile
4885# Description:
4886# Configure the script via the info in a config file
4887def configFromFile(file):
4888 Config = ConfigParser.ConfigParser()
4889
4890 Config.read(file)
4891 sections = Config.sections()
4892 overridekprobes = False
4893 overridedevkprobes = False
4894 if 'Settings' in sections:
4895 for opt in Config.options('Settings'):
4896 value = Config.get('Settings', opt).lower()
4897 if(opt.lower() == 'verbose'):
4898 sysvals.verbose = checkArgBool(value)
4899 elif(opt.lower() == 'addlogs'):
4900 sysvals.addlogs = checkArgBool(value)
4901 elif(opt.lower() == 'dev'):
4902 sysvals.usedevsrc = checkArgBool(value)
4903 elif(opt.lower() == 'proc'):
4904 sysvals.useprocmon = checkArgBool(value)
4905 elif(opt.lower() == 'x2'):
4906 if checkArgBool(value):
4907 sysvals.execcount = 2
4908 elif(opt.lower() == 'callgraph'):
4909 sysvals.usecallgraph = checkArgBool(value)
4910 elif(opt.lower() == 'override-timeline-functions'):
4911 overridekprobes = checkArgBool(value)
4912 elif(opt.lower() == 'override-dev-timeline-functions'):
4913 overridedevkprobes = checkArgBool(value)
4914 elif(opt.lower() == 'devicefilter'):
4915 sysvals.setDeviceFilter(value)
4916 elif(opt.lower() == 'expandcg'):
4917 sysvals.cgexp = checkArgBool(value)
4918 elif(opt.lower() == 'srgap'):
4919 if checkArgBool(value):
4920 sysvals.srgap = 5
4921 elif(opt.lower() == 'mode'):
4922 sysvals.suspendmode = value
4923 elif(opt.lower() == 'command'):
4924 sysvals.testcommand = value
4925 elif(opt.lower() == 'x2delay'):
4926 sysvals.x2delay = getArgInt('-x2delay', value, 0, 60000, False)
4927 elif(opt.lower() == 'predelay'):
4928 sysvals.predelay = getArgInt('-predelay', value, 0, 60000, False)
4929 elif(opt.lower() == 'postdelay'):
4930 sysvals.postdelay = getArgInt('-postdelay', value, 0, 60000, False)
4931 elif(opt.lower() == 'maxdepth'):
4932 sysvals.max_graph_depth = getArgInt('-maxdepth', value, 0, 1000, False)
4933 elif(opt.lower() == 'rtcwake'):
4934 if value.lower() == 'off':
4935 sysvals.rtcwake = False
4936 else:
4937 sysvals.rtcwake = True
4938 sysvals.rtcwaketime = getArgInt('-rtcwake', value, 0, 3600, False)
4939 elif(opt.lower() == 'timeprec'):
4940 sysvals.setPrecision(getArgInt('-timeprec', value, 0, 6, False))
4941 elif(opt.lower() == 'mindev'):
4942 sysvals.mindevlen = getArgFloat('-mindev', value, 0.0, 10000.0, False)
4943 elif(opt.lower() == 'callloop-maxgap'):
4944 sysvals.callloopmaxgap = getArgFloat('-callloop-maxgap', value, 0.0, 1.0, False)
4945 elif(opt.lower() == 'callloop-maxlen'):
4946 sysvals.callloopmaxgap = getArgFloat('-callloop-maxlen', value, 0.0, 1.0, False)
4947 elif(opt.lower() == 'mincg'):
4948 sysvals.mincglen = getArgFloat('-mincg', value, 0.0, 10000.0, False)
4949 elif(opt.lower() == 'output-dir'):
4950 sysvals.setOutputFolder(value)
4951
4952 if sysvals.suspendmode == 'command' and not sysvals.testcommand:
4953 doError('No command supplied for mode "command"')
4954
4955 # compatibility errors
4956 if sysvals.usedevsrc and sysvals.usecallgraph:
4957 doError('-dev is not compatible with -f')
4958 if sysvals.usecallgraph and sysvals.useprocmon:
4959 doError('-proc is not compatible with -f')
4960
4961 if overridekprobes:
4962 sysvals.tracefuncs = dict()
4963 if overridedevkprobes:
4964 sysvals.dev_tracefuncs = dict()
4965
4966 kprobes = dict()
4967 kprobesec = 'dev_timeline_functions_'+platform.machine()
4968 if kprobesec in sections:
4969 for name in Config.options(kprobesec):
4970 text = Config.get(kprobesec, name)
4971 kprobes[name] = (text, True)
4972 kprobesec = 'timeline_functions_'+platform.machine()
4973 if kprobesec in sections:
4974 for name in Config.options(kprobesec):
4975 if name in kprobes:
4976 doError('Duplicate timeline function found "%s"' % (name))
4977 text = Config.get(kprobesec, name)
4978 kprobes[name] = (text, False)
4979
4980 for name in kprobes:
4981 function = name
4982 format = name
4983 color = ''
4984 args = dict()
4985 text, dev = kprobes[name]
4986 data = text.split()
4987 i = 0
4988 for val in data:
4989 # bracketted strings are special formatting, read them separately
4990 if val[0] == '[' and val[-1] == ']':
4991 for prop in val[1:-1].split(','):
4992 p = prop.split('=')
4993 if p[0] == 'color':
4994 try:
4995 color = int(p[1], 16)
4996 color = '#'+p[1]
4997 except:
4998 color = p[1]
4999 continue
5000 # first real arg should be the format string
5001 if i == 0:
5002 format = val
5003 # all other args are actual function args
5004 else:
5005 d = val.split('=')
5006 args[d[0]] = d[1]
5007 i += 1
5008 if not function or not format:
5009 doError('Invalid kprobe: %s' % name)
5010 for arg in re.findall('{(?P<n>[a-z,A-Z,0-9]*)}', format):
5011 if arg not in args:
5012 doError('Kprobe "%s" is missing argument "%s"' % (name, arg))
5013 if (dev and name in sysvals.dev_tracefuncs) or (not dev and name in sysvals.tracefuncs):
5014 doError('Duplicate timeline function found "%s"' % (name))
5015
5016 kp = {
5017 'name': name,
5018 'func': function,
5019 'format': format,
5020 sysvals.archargs: args
5021 }
5022 if color:
5023 kp['color'] = color
5024 if dev:
5025 sysvals.dev_tracefuncs[name] = kp
5026 else:
5027 sysvals.tracefuncs[name] = kp
5028
5029# Function: printHelp
5030# Description:
5031# print out the help text
5032def printHelp():
5033 modes = getModes()
5034
5035 print('')
5036 print('%s v%s' % (sysvals.title, sysvals.version))
5037 print('Usage: sudo sleepgraph <options> <commands>')
5038 print('')
5039 print('Description:')
5040 print(' This tool is designed to assist kernel and OS developers in optimizing')
5041 print(' their linux stack\'s suspend/resume time. Using a kernel image built')
5042 print(' with a few extra options enabled, the tool will execute a suspend and')
5043 print(' capture dmesg and ftrace data until resume is complete. This data is')
5044 print(' transformed into a device timeline and an optional callgraph to give')
5045 print(' a detailed view of which devices/subsystems are taking the most')
5046 print(' time in suspend/resume.')
5047 print('')
5048 print(' If no specific command is given, the default behavior is to initiate')
5049 print(' a suspend/resume and capture the dmesg/ftrace output as an html timeline.')
5050 print('')
5051 print(' Generates output files in subdirectory: suspend-mmddyy-HHMMSS')
5052 print(' HTML output: <hostname>_<mode>.html')
5053 print(' raw dmesg output: <hostname>_<mode>_dmesg.txt')
5054 print(' raw ftrace output: <hostname>_<mode>_ftrace.txt')
5055 print('')
5056 print('Options:')
5057 print(' -h Print this help text')
5058 print(' -v Print the current tool version')
5059 print(' -config fn Pull arguments and config options from file fn')
5060 print(' -verbose Print extra information during execution and analysis')
5061 print(' -m mode Mode to initiate for suspend %s (default: %s)') % (modes, sysvals.suspendmode)
5062 print(' -o subdir Override the output subdirectory')
5063 print(' -rtcwake t Wakeup t seconds after suspend, set t to "off" to disable (default: 15)')
5064 print(' -addlogs Add the dmesg and ftrace logs to the html output')
5065 print(' -srgap Add a visible gap in the timeline between sus/res (default: disabled)')
5066 print(' [advanced]')
5067 print(' -cmd {s} Run the timeline over a custom command, e.g. "sync -d"')
5068 print(' -proc Add usermode process info into the timeline (default: disabled)')
5069 print(' -dev Add kernel function calls and threads to the timeline (default: disabled)')
5070 print(' -x2 Run two suspend/resumes back to back (default: disabled)')
5071 print(' -x2delay t Include t ms delay between multiple test runs (default: 0 ms)')
5072 print(' -predelay t Include t ms delay before 1st suspend (default: 0 ms)')
5073 print(' -postdelay t Include t ms delay after last resume (default: 0 ms)')
5074 print(' -mindev ms Discard all device blocks shorter than ms milliseconds (e.g. 0.001 for us)')
5075 print(' -multi n d Execute <n> consecutive tests at <d> seconds intervals. The outputs will')
5076 print(' be created in a new subdirectory with a summary page.')
5077 print(' [debug]')
5078 print(' -f Use ftrace to create device callgraphs (default: disabled)')
5079 print(' -maxdepth N limit the callgraph data to N call levels (default: 0=all)')
5080 print(' -expandcg pre-expand the callgraph data in the html output (default: disabled)')
5081 print(' -fadd file Add functions to be graphed in the timeline from a list in a text file')
5082 print(' -filter "d1,d2,..." Filter out all but this comma-delimited list of device names')
5083 print(' -mincg ms Discard all callgraphs shorter than ms milliseconds (e.g. 0.001 for us)')
5084 print(' -cgphase P Only show callgraph data for phase P (e.g. suspend_late)')
5085 print(' -cgtest N Only show callgraph data for test N (e.g. 0 or 1 in an x2 run)')
5086 print(' -timeprec N Number of significant digits in timestamps (0:S, [3:ms], 6:us)')
5087 print(' [commands]')
5088 print(' -ftrace ftracefile Create HTML output using ftrace input (used with -dmesg)')
5089 print(' -dmesg dmesgfile Create HTML output using dmesg (used with -ftrace)')
5090 print(' -summary directory Create a summary of all test in this dir')
5091 print(' -modes List available suspend modes')
5092 print(' -status Test to see if the system is enabled to run this tool')
5093 print(' -fpdt Print out the contents of the ACPI Firmware Performance Data Table')
5094 print(' -usbtopo Print out the current USB topology with power info')
5095 print(' -usbauto Enable autosuspend for all connected USB devices')
5096 print(' -flist Print the list of functions currently being captured in ftrace')
5097 print(' -flistall Print all functions capable of being captured in ftrace')
5098 print('')
5099 return True
5100
5101# ----------------- MAIN --------------------
5102# exec start (skipped if script is loaded as library)
5103if __name__ == '__main__':
5104 cmd = ''
5105 cmdarg = ''
5106 multitest = {'run': False, 'count': 0, 'delay': 0}
5107 simplecmds = ['-modes', '-fpdt', '-flist', '-flistall', '-usbtopo', '-usbauto', '-status']
5108 # loop through the command line arguments
5109 args = iter(sys.argv[1:])
5110 for arg in args:
5111 if(arg == '-m'):
5112 try:
5113 val = args.next()
5114 except:
5115 doError('No mode supplied', True)
5116 if val == 'command' and not sysvals.testcommand:
5117 doError('No command supplied for mode "command"', True)
5118 sysvals.suspendmode = val
5119 elif(arg in simplecmds):
5120 cmd = arg[1:]
5121 elif(arg == '-h'):
5122 printHelp()
5123 sys.exit()
5124 elif(arg == '-v'):
5125 print("Version %s" % sysvals.version)
5126 sys.exit()
5127 elif(arg == '-x2'):
5128 sysvals.execcount = 2
5129 elif(arg == '-x2delay'):
5130 sysvals.x2delay = getArgInt('-x2delay', args, 0, 60000)
5131 elif(arg == '-predelay'):
5132 sysvals.predelay = getArgInt('-predelay', args, 0, 60000)
5133 elif(arg == '-postdelay'):
5134 sysvals.postdelay = getArgInt('-postdelay', args, 0, 60000)
5135 elif(arg == '-f'):
5136 sysvals.usecallgraph = True
5137 elif(arg == '-addlogs'):
5138 sysvals.addlogs = True
5139 elif(arg == '-verbose'):
5140 sysvals.verbose = True
5141 elif(arg == '-proc'):
5142 sysvals.useprocmon = True
5143 elif(arg == '-dev'):
5144 sysvals.usedevsrc = True
5145 elif(arg == '-maxdepth'):
5146 sysvals.max_graph_depth = getArgInt('-maxdepth', args, 0, 1000)
5147 elif(arg == '-rtcwake'):
5148 try:
5149 val = args.next()
5150 except:
5151 doError('No rtcwake time supplied', True)
5152 if val.lower() == 'off':
5153 sysvals.rtcwake = False
5154 else:
5155 sysvals.rtcwake = True
5156 sysvals.rtcwaketime = getArgInt('-rtcwake', val, 0, 3600, False)
5157 elif(arg == '-timeprec'):
5158 sysvals.setPrecision(getArgInt('-timeprec', args, 0, 6))
5159 elif(arg == '-mindev'):
5160 sysvals.mindevlen = getArgFloat('-mindev', args, 0.0, 10000.0)
5161 elif(arg == '-mincg'):
5162 sysvals.mincglen = getArgFloat('-mincg', args, 0.0, 10000.0)
5163 elif(arg == '-cgtest'):
5164 sysvals.cgtest = getArgInt('-cgtest', args, 0, 1)
5165 elif(arg == '-cgphase'):
5166 try:
5167 val = args.next()
5168 except:
5169 doError('No phase name supplied', True)
5170 d = Data(0)
5171 if val not in d.phases:
5172 doError('Invalid phase, valid phaess are %s' % d.phases, True)
5173 sysvals.cgphase = val
5174 elif(arg == '-callloop-maxgap'):
5175 sysvals.callloopmaxgap = getArgFloat('-callloop-maxgap', args, 0.0, 1.0)
5176 elif(arg == '-callloop-maxlen'):
5177 sysvals.callloopmaxlen = getArgFloat('-callloop-maxlen', args, 0.0, 1.0)
5178 elif(arg == '-cmd'):
5179 try:
5180 val = args.next()
5181 except:
5182 doError('No command string supplied', True)
5183 sysvals.testcommand = val
5184 sysvals.suspendmode = 'command'
5185 elif(arg == '-expandcg'):
5186 sysvals.cgexp = True
5187 elif(arg == '-srgap'):
5188 sysvals.srgap = 5
5189 elif(arg == '-multi'):
5190 multitest['run'] = True
5191 multitest['count'] = getArgInt('-multi n (exec count)', args, 2, 1000000)
5192 multitest['delay'] = getArgInt('-multi d (delay between tests)', args, 0, 3600)
5193 elif(arg == '-o'):
5194 try:
5195 val = args.next()
5196 except:
5197 doError('No subdirectory name supplied', True)
5198 sysvals.setOutputFolder(val)
5199 elif(arg == '-config'):
5200 try:
5201 val = args.next()
5202 except:
5203 doError('No text file supplied', True)
5204 if(os.path.exists(val) == False):
5205 doError('%s does not exist' % val)
5206 configFromFile(val)
5207 elif(arg == '-fadd'):
5208 try:
5209 val = args.next()
5210 except:
5211 doError('No text file supplied', True)
5212 if(os.path.exists(val) == False):
5213 doError('%s does not exist' % val)
5214 sysvals.addFtraceFilterFunctions(val)
5215 elif(arg == '-dmesg'):
5216 try:
5217 val = args.next()
5218 except:
5219 doError('No dmesg file supplied', True)
5220 sysvals.notestrun = True
5221 sysvals.dmesgfile = val
5222 if(os.path.exists(sysvals.dmesgfile) == False):
5223 doError('%s does not exist' % sysvals.dmesgfile)
5224 elif(arg == '-ftrace'):
5225 try:
5226 val = args.next()
5227 except:
5228 doError('No ftrace file supplied', True)
5229 sysvals.notestrun = True
5230 sysvals.ftracefile = val
5231 if(os.path.exists(sysvals.ftracefile) == False):
5232 doError('%s does not exist' % sysvals.ftracefile)
5233 elif(arg == '-summary'):
5234 try:
5235 val = args.next()
5236 except:
5237 doError('No directory supplied', True)
5238 cmd = 'summary'
5239 cmdarg = val
5240 sysvals.notestrun = True
5241 if(os.path.isdir(val) == False):
5242 doError('%s is not accesible' % val)
5243 elif(arg == '-filter'):
5244 try:
5245 val = args.next()
5246 except:
5247 doError('No devnames supplied', True)
5248 sysvals.setDeviceFilter(val)
5249 else:
5250 doError('Invalid argument: '+arg, True)
5251
5252 # compatibility errors
5253 if(sysvals.usecallgraph and sysvals.usedevsrc):
5254 doError('-dev is not compatible with -f')
5255 if(sysvals.usecallgraph and sysvals.useprocmon):
5256 doError('-proc is not compatible with -f')
5257
5258 # callgraph size cannot exceed device size
5259 if sysvals.mincglen < sysvals.mindevlen:
5260 sysvals.mincglen = sysvals.mindevlen
5261
5262 # just run a utility command and exit
5263 if(cmd != ''):
5264 if(cmd == 'status'):
5265 statusCheck(True)
5266 elif(cmd == 'fpdt'):
5267 getFPDT(True)
5268 elif(cmd == 'usbtopo'):
5269 detectUSB()
5270 elif(cmd == 'modes'):
5271 print getModes()
5272 elif(cmd == 'flist'):
5273 sysvals.getFtraceFilterFunctions(True)
5274 elif(cmd == 'flistall'):
5275 sysvals.getFtraceFilterFunctions(False)
5276 elif(cmd == 'usbauto'):
5277 setUSBDevicesAuto()
5278 elif(cmd == 'summary'):
5279 runSummary(cmdarg, True)
5280 sys.exit()
5281
5282 # if instructed, re-analyze existing data files
5283 if(sysvals.notestrun):
5284 rerunTest()
5285 sys.exit()
5286
5287 # verify that we can run a test
5288 if(not statusCheck()):
5289 print('Check FAILED, aborting the test run!')
5290 sys.exit()
5291
5292 if multitest['run']:
5293 # run multiple tests in a separate subdirectory
5294 s = 'x%d' % multitest['count']
5295 if not sysvals.outdir:
5296 sysvals.outdir = datetime.now().strftime('suspend-'+s+'-%m%d%y-%H%M%S')
5297 if not os.path.isdir(sysvals.outdir):
5298 os.mkdir(sysvals.outdir)
5299 for i in range(multitest['count']):
5300 if(i != 0):
5301 print('Waiting %d seconds...' % (multitest['delay']))
5302 time.sleep(multitest['delay'])
5303 print('TEST (%d/%d) START' % (i+1, multitest['count']))
5304 runTest(sysvals.outdir)
5305 print('TEST (%d/%d) COMPLETE' % (i+1, multitest['count']))
5306 runSummary(sysvals.outdir, False)
5307 else:
5308 # run the test in the current directory
5309 runTest('.', sysvals.outdir)
diff --git a/tools/power/pm-graph/bootgraph.8 b/tools/power/pm-graph/bootgraph.8
new file mode 100644
index 000000000000..55272a67b0e7
--- /dev/null
+++ b/tools/power/pm-graph/bootgraph.8
@@ -0,0 +1,132 @@
1.TH BOOTGRAPH 8
2.SH NAME
3bootgraph \- Kernel boot timing analysis
4.SH SYNOPSIS
5.ft B
6.B bootgraph
7.RB [ OPTIONS ]
8.RB [ COMMAND ]
9.SH DESCRIPTION
10\fBbootgraph \fP reads the dmesg log from kernel boot and
11creates an html representation of the initcall timeline up to the start
12of the init process.
13.PP
14If no specific command is given, the tool reads the current dmesg log and
15outputs bootgraph.html.
16.PP
17The tool can also augment the timeline with ftrace data on custom target
18functions as well as full trace callgraphs.
19.SH OPTIONS
20.TP
21\fB-h\fR
22Print this help text
23.TP
24\fB-v\fR
25Print the current tool version
26.TP
27\fB-addlogs\fR
28Add the dmesg log to the html output. It will be viewable by
29clicking a button in the timeline.
30.TP
31\fB-o \fIfile\fR
32Override the HTML output filename (default: bootgraph.html)
33.SS "Ftrace Debug"
34.TP
35\fB-f\fR
36Use ftrace to add function detail (default: disabled)
37.TP
38\fB-callgraph\fR
39Use ftrace to create initcall callgraphs (default: disabled). If -filter
40is not used there will be one callgraph per initcall. This can produce
41very large outputs, i.e. 10MB - 100MB.
42.TP
43\fB-maxdepth \fIlevel\fR
44limit the callgraph trace depth to \fIlevel\fR (default: 2). This is
45the best way to limit the output size when using -callgraph.
46.TP
47\fB-mincg \fIt\fR
48Discard all callgraphs shorter than \fIt\fR milliseconds (default: 0=all).
49This reduces the html file size as there can be many tiny callgraphs
50which are barely visible in the timeline.
51The value is a float: e.g. 0.001 represents 1 us.
52.TP
53\fB-timeprec \fIn\fR
54Number of significant digits in timestamps (0:S, 3:ms, [6:us])
55.TP
56\fB-expandcg\fR
57pre-expand the callgraph data in the html output (default: disabled)
58.TP
59\fB-filter \fI"func1,func2,..."\fR
60Instead of tracing each initcall, trace a custom list of functions (default: do_one_initcall)
61
62.SH COMMANDS
63.TP
64\fB-reboot\fR
65Reboot the machine and generate a new timeline automatically. Works in 4 steps.
66 1. updates grub with the required kernel parameters
67 2. installs a cron job which re-runs the tool after reboot
68 3. reboots the system
69 4. after startup, extracts the data and generates the timeline
70.TP
71\fB-manual\fR
72Show the requirements to generate a new timeline manually. Requires 3 steps.
73 1. append the string to the kernel command line via your native boot manager.
74 2. reboot the system
75 3. after startup, re-run the tool with the same arguments and no command
76.TP
77\fB-dmesg \fIfile\fR
78Create HTML output from an existing dmesg file.
79.TP
80\fB-ftrace \fIfile\fR
81Create HTML output from an existing ftrace file (used with -dmesg).
82.TP
83\fB-flistall\fR
84Print all ftrace functions capable of being captured. These are all the
85possible values you can add to trace via the -filter argument.
86
87.SH EXAMPLES
88Create a timeline using the current dmesg log.
89.IP
90\f(CW$ bootgraph\fR
91.PP
92Create a timeline using the current dmesg and ftrace log.
93.IP
94\f(CW$ bootgraph -callgraph\fR
95.PP
96Create a timeline using the current dmesg, add the log to the html and change the name.
97.IP
98\f(CW$ bootgraph -addlogs -o myboot.html\fR
99.PP
100Capture a new boot timeline by automatically rebooting the machine.
101.IP
102\f(CW$ sudo bootgraph -reboot -addlogs -o latestboot.html\fR
103.PP
104Capture a new boot timeline with function trace data.
105.IP
106\f(CW$ sudo bootgraph -reboot -f\fR
107.PP
108Capture a new boot timeline with trace & callgraph data. Skip callgraphs smaller than 5ms.
109.IP
110\f(CW$ sudo bootgraph -reboot -callgraph -mincg 5\fR
111.PP
112Capture a new boot timeline with callgraph data over custom functions.
113.IP
114\f(CW$ sudo bootgraph -reboot -callgraph -filter "acpi_ps_parse_aml,msleep"\fR
115.PP
116Capture a brand new boot timeline with manual reboot.
117.IP
118\f(CW$ sudo bootgraph -callgraph -manual\fR
119.IP
120\f(CW$ vi /etc/default/grub # add the CMDLINE string to your kernel params\fR
121.IP
122\f(CW$ sudo reboot # reboot the machine\fR
123.IP
124\f(CW$ sudo bootgraph -callgraph # re-run the tool after restart\fR
125.PP
126
127.SH "SEE ALSO"
128dmesg(1), update-grub(8), crontab(1), reboot(8)
129.PP
130.SH AUTHOR
131.nf
132Written by Todd Brandt <todd.e.brandt@linux.intel.com>
diff --git a/tools/power/pm-graph/sleepgraph.8 b/tools/power/pm-graph/sleepgraph.8
new file mode 100644
index 000000000000..610e72ebbc06
--- /dev/null
+++ b/tools/power/pm-graph/sleepgraph.8
@@ -0,0 +1,243 @@
1.TH SLEEPGRAPH 8
2.SH NAME
3sleepgraph \- Suspend/Resume timing analysis
4.SH SYNOPSIS
5.ft B
6.B sleepgraph
7.RB [ OPTIONS ]
8.RB [ COMMAND ]
9.SH DESCRIPTION
10\fBsleepgraph \fP is designed to assist kernel and OS developers
11in optimizing their linux stack's suspend/resume time. Using a kernel
12image built with a few extra options enabled, the tool will execute a
13suspend and capture dmesg and ftrace data until resume is complete.
14This data is transformed into a device timeline and an optional
15callgraph to give a detailed view of which devices/subsystems are
16taking the most time in suspend/resume.
17.PP
18If no specific command is given, the default behavior is to initiate
19a suspend/resume.
20.PP
21Generates output files in subdirectory: suspend-yymmdd-HHMMSS
22 html timeline : <hostname>_<mode>.html
23 raw dmesg file : <hostname>_<mode>_dmesg.txt
24 raw ftrace file : <hostname>_<mode>_ftrace.txt
25.SH OPTIONS
26.TP
27\fB-h\fR
28Print the help text.
29.TP
30\fB-v\fR
31Print the current tool version.
32.TP
33\fB-verbose\fR
34Print extra information during execution and analysis.
35.TP
36\fB-config \fIfile\fR
37Pull arguments and config options from a file.
38.TP
39\fB-m \fImode\fR
40Mode to initiate for suspend e.g. standby, freeze, mem (default: mem).
41.TP
42\fB-o \fIsubdir\fR
43Override the output subdirectory. Use {date}, {time}, {hostname} for current values.
44.sp
45e.g. suspend-{hostname}-{date}-{time}
46.TP
47\fB-rtcwake \fIt\fR | off
48Use rtcwake to autoresume after \fIt\fR seconds (default: 15). Set t to "off" to
49disable rtcwake and require a user keypress to resume.
50.TP
51\fB-addlogs\fR
52Add the dmesg and ftrace logs to the html output. They will be viewable by
53clicking buttons in the timeline.
54
55.SS "Advanced"
56.TP
57\fB-cmd \fIstr\fR
58Run the timeline over a custom suspend command, e.g. pm-suspend. By default
59the tool forces suspend via /sys/power/state so this allows testing over
60an OS's official suspend method. The output file will change to
61hostname_command.html and will autodetect which suspend mode was triggered.
62.TP
63\fB-filter \fI"d1,d2,..."\fR
64Filter out all but these device callbacks. These strings can be device names
65or module names. e.g. 0000:00:02.0, ata5, i915, usb, etc.
66.TP
67\fB-mindev \fIt\fR
68Discard all device callbacks shorter than \fIt\fR milliseconds (default: 0.0).
69This reduces the html file size as there can be many tiny callbacks which are barely
70visible. The value is a float: e.g. 0.001 represents 1 us.
71.TP
72\fB-proc\fR
73Add usermode process info into the timeline (default: disabled).
74.TP
75\fB-dev\fR
76Add kernel source calls and threads to the timeline (default: disabled).
77.TP
78\fB-x2\fR
79Run two suspend/resumes back to back (default: disabled).
80.TP
81\fB-x2delay \fIt\fR
82Include \fIt\fR ms delay between multiple test runs (default: 0 ms).
83.TP
84\fB-predelay \fIt\fR
85Include \fIt\fR ms delay before 1st suspend (default: 0 ms).
86.TP
87\fB-postdelay \fIt\fR
88Include \fIt\fR ms delay after last resume (default: 0 ms).
89.TP
90\fB-multi \fIn d\fR
91Execute \fIn\fR consecutive tests at \fId\fR seconds intervals. The outputs will
92be created in a new subdirectory with a summary page: suspend-xN-{date}-{time}.
93
94.SS "Ftrace Debug"
95.TP
96\fB-f\fR
97Use ftrace to create device callgraphs (default: disabled). This can produce
98very large outputs, i.e. 10MB - 100MB.
99.TP
100\fB-maxdepth \fIlevel\fR
101limit the callgraph trace depth to \fIlevel\fR (default: 0=all). This is
102the best way to limit the output size when using callgraphs via -f.
103.TP
104\fB-expandcg\fR
105pre-expand the callgraph data in the html output (default: disabled)
106.TP
107\fB-fadd \fIfile\fR
108Add functions to be graphed in the timeline from a list in a text file
109.TP
110\fB-mincg \fIt\fR
111Discard all callgraphs shorter than \fIt\fR milliseconds (default: 0.0).
112This reduces the html file size as there can be many tiny callgraphs
113which are barely visible in the timeline.
114The value is a float: e.g. 0.001 represents 1 us.
115.TP
116\fB-cgphase \fIp\fR
117Only show callgraph data for phase \fIp\fR (e.g. suspend_late).
118.TP
119\fB-cgtest \fIn\fR
120In an x2 run, only show callgraph data for test \fIn\fR (e.g. 0 or 1).
121.TP
122\fB-timeprec \fIn\fR
123Number of significant digits in timestamps (0:S, [3:ms], 6:us).
124
125.SH COMMANDS
126.TP
127\fB-ftrace \fIfile\fR
128Create HTML output from an existing ftrace file.
129.TP
130\fB-dmesg \fIfile\fR
131Create HTML output from an existing dmesg file.
132.TP
133\fB-summary \fIindir\fR
134Create a summary page of all tests in \fIindir\fR. Creates summary.html
135in the current folder. The output page is a table of tests with
136suspend and resume values sorted by suspend mode, host, and kernel.
137Includes test averages by mode and links to the test html files.
138.TP
139\fB-modes\fR
140List available suspend modes.
141.TP
142\fB-status\fR
143Test to see if the system is able to run this tool. Use this along
144with any options you intend to use to see if they will work.
145.TP
146\fB-fpdt\fR
147Print out the contents of the ACPI Firmware Performance Data Table.
148.TP
149\fB-usbtopo\fR
150Print out the current USB topology with power info.
151.TP
152\fB-usbauto\fR
153Enable autosuspend for all connected USB devices.
154.TP
155\fB-flist\fR
156Print the list of ftrace functions currently being captured. Functions
157that are not available as symbols in the current kernel are shown in red.
158By default, the tool traces a list of important suspend/resume functions
159in order to better fill out the timeline. If the user has added their own
160with -fadd they will also be checked.
161.TP
162\fB-flistall\fR
163Print all ftrace functions capable of being captured. These are all the
164possible values you can add to trace via the -fadd argument.
165
166.SH EXAMPLES
167.SS "Simple Commands"
168Check which suspend modes are currently supported.
169.IP
170\f(CW$ sleepgraph -modes\fR
171.PP
172Read the Firmware Performance Data Table (FPDT)
173.IP
174\f(CW$ sudo sleepgraph -fpdt\fR
175.PP
176Print out the current USB power topology
177.IP
178\f(CW$ sleepgraph -usbtopo
179.PP
180Verify that you can run a command with a set of arguments
181.IP
182\f(CW$ sudo sleepgraph -f -rtcwake 30 -status
183.PP
184Generate a summary of all timelines in a particular folder.
185.IP
186\f(CW$ sleepgraph -summary ~/workspace/myresults/\fR
187.PP
188Re-generate the html output from a previous run's dmesg and ftrace log.
189.IP
190\f(CW$ sleepgraph -dmesg myhost_mem_dmesg.txt -ftrace myhost_mem_ftrace.txt\fR
191.PP
192
193.SS "Capturing Simple Timelines"
194Execute a mem suspend with a 15 second wakeup. Include the logs in the html.
195.IP
196\f(CW$ sudo sleepgraph -rtcwake 15 -addlogs\fR
197.PP
198Execute a standby with a 15 second wakeup. Change the output folder name.
199.IP
200\f(CW$ sudo sleepgraph -m standby -rtcwake 15 -o "standby-{hostname}-{date}-{time}"\fR
201.PP
202Execute a freeze with no wakeup (require keypress). Change output folder name.
203.IP
204\f(CW$ sudo sleepgraph -m freeze -rtcwake off -o "freeze-{hostname}-{date}-{time}"\fR
205.PP
206
207.SS "Capturing Advanced Timelines"
208Execute a suspend & include dev mode source calls, limit callbacks to 5ms or larger.
209.IP
210\f(CW$ sudo sleepgraph -m mem -rtcwake 15 -dev -mindev 5\fR
211.PP
212Run two suspends back to back, include a 500ms delay before, after, and in between runs.
213.IP
214\f(CW$ sudo sleepgraph -m mem -rtcwake 15 -x2 -predelay 500 -x2delay 500 -postdelay 500\fR
215.PP
216Do a batch run of 10 freezes with 30 seconds delay between runs.
217.IP
218\f(CW$ sudo sleepgraph -m freeze -rtcwake 15 -multi 10 30\fR
219.PP
220Execute a suspend using a custom command.
221.IP
222\f(CW$ sudo sleepgraph -cmd "echo mem > /sys/power/state" -rtcwake 15\fR
223.PP
224
225
226.SS "Capturing Timelines with Callgraph Data"
227Add device callgraphs. Limit the trace depth and only show callgraphs 10ms or larger.
228.IP
229\f(CW$ sudo sleepgraph -m mem -rtcwake 15 -f -maxdepth 5 -mincg 10\fR
230.PP
231Capture a full callgraph across all suspend, then filter the html by a single phase.
232.IP
233\f(CW$ sudo sleepgraph -m mem -rtcwake 15 -f\fR
234.IP
235\f(CW$ sleepgraph -dmesg host_mem_dmesg.txt -ftrace host_mem_ftrace.txt -f -cgphase resume
236.PP
237
238.SH "SEE ALSO"
239dmesg(1)
240.PP
241.SH AUTHOR
242.nf
243Written by Todd Brandt <todd.e.brandt@linux.intel.com>
diff --git a/tools/power/x86/intel_pstate_tracer/intel_pstate_tracer.py b/tools/power/x86/intel_pstate_tracer/intel_pstate_tracer.py
index fd706ac0f347..0b24dd9d01ff 100755
--- a/tools/power/x86/intel_pstate_tracer/intel_pstate_tracer.py
+++ b/tools/power/x86/intel_pstate_tracer/intel_pstate_tracer.py
@@ -353,6 +353,14 @@ def split_csv():
353 os.system('grep -m 1 common_cpu cpu.csv > cpu{:0>3}.csv'.format(index)) 353 os.system('grep -m 1 common_cpu cpu.csv > cpu{:0>3}.csv'.format(index))
354 os.system('grep CPU_{:0>3} cpu.csv >> cpu{:0>3}.csv'.format(index, index)) 354 os.system('grep CPU_{:0>3} cpu.csv >> cpu{:0>3}.csv'.format(index, index))
355 355
356def fix_ownership(path):
357 """Change the owner of the file to SUDO_UID, if required"""
358
359 uid = os.environ.get('SUDO_UID')
360 gid = os.environ.get('SUDO_GID')
361 if uid is not None:
362 os.chown(path, int(uid), int(gid))
363
356def cleanup_data_files(): 364def cleanup_data_files():
357 """ clean up existing data files """ 365 """ clean up existing data files """
358 366
@@ -518,12 +526,16 @@ else:
518 526
519if not os.path.exists('results'): 527if not os.path.exists('results'):
520 os.mkdir('results') 528 os.mkdir('results')
529 # The regular user needs to own the directory, not root.
530 fix_ownership('results')
521 531
522os.chdir('results') 532os.chdir('results')
523if os.path.exists(testname): 533if os.path.exists(testname):
524 print('The test name directory already exists. Please provide a unique test name. Test re-run not supported, yet.') 534 print('The test name directory already exists. Please provide a unique test name. Test re-run not supported, yet.')
525 sys.exit() 535 sys.exit()
526os.mkdir(testname) 536os.mkdir(testname)
537# The regular user needs to own the directory, not root.
538fix_ownership(testname)
527os.chdir(testname) 539os.chdir(testname)
528 540
529# Temporary (or perhaps not) 541# Temporary (or perhaps not)
@@ -566,4 +578,9 @@ plot_scaled_cpu()
566plot_boost_cpu() 578plot_boost_cpu()
567plot_ghz_cpu() 579plot_ghz_cpu()
568 580
581# It is preferrable, but not necessary, that the regular user owns the files, not root.
582for root, dirs, files in os.walk('.'):
583 for f in files:
584 fix_ownership(f)
585
569os.chdir('../../') 586os.chdir('../../')
generated by cgit v1.2.2 (git 2.25.0) at 2025-10-13 08:58:18 -0400