From bc167c7de8886f08b3d8266b176eefaa9f22cd80 Mon Sep 17 00:00:00 2001 From: Todd E Brandt Date: Fri, 7 Apr 2017 11:05:35 -0700 Subject: [PATCH] tools: power: pm-graph: AnalyzeSuspend v4.6 Moved from scripts into tools, and updated from 4.5 to 4.6 - Changed the tool title to SleepGraph - Reformatted the code so analyze_suspend can be used as a library - Reorganized all html/js/css handling code to be used by other tools - upgraded the -summary feature to work faster with better readability Signed-off-by: Todd Brandt Signed-off-by: Rafael J. Wysocki --- .../power/pm-graph}/analyze_suspend.py | 916 ++++++++++-------- 1 file changed, 495 insertions(+), 421 deletions(-) rename {scripts => tools/power/pm-graph}/analyze_suspend.py (91%) diff --git a/scripts/analyze_suspend.py b/tools/power/pm-graph/analyze_suspend.py similarity index 91% rename from scripts/analyze_suspend.py rename to tools/power/pm-graph/analyze_suspend.py index 20cdb2bc1dae..a9206e67fc1f 100755 --- a/scripts/analyze_suspend.py +++ b/tools/power/pm-graph/analyze_suspend.py @@ -12,10 +12,6 @@ # FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License for # more details. # -# You should have received a copy of the GNU General Public License along with -# this program; if not, write to the Free Software Foundation, Inc., -# 51 Franklin St - Fifth Floor, Boston, MA 02110-1301 USA. -# # Authors: # Todd Brandt # @@ -23,7 +19,7 @@ # Home Page # https://01.org/suspendresume # Source repo -# https://github.com/01org/suspendresume +# https://github.com/01org/pm-graph # # Description: # This tool is designed to assist kernel and OS developers in optimizing @@ -71,14 +67,16 @@ from subprocess import call, Popen, PIPE # A global, single-instance container used to # store system values and test parameters class SystemValues: + title = 'SleepGraph' + version = '4.6' ansi = False - version = '4.5' verbose = False addlogs = False mindevlen = 0.0 mincglen = 0.0 cgphase = '' cgtest = -1 + max_graph_depth = 0 callloopmaxgap = 0.0001 callloopmaxlen = 0.005 srgap = 0 @@ -106,8 +104,8 @@ class SystemValues: ftracefile = '' htmlfile = '' embedded = False - rtcwake = False - rtcwaketime = 10 + rtcwake = True + rtcwaketime = 15 rtcpath = '' devicefilter = [] stamp = 0 @@ -235,6 +233,12 @@ class SystemValues: self.rtcpath = rtc if (hasattr(sys.stdout, 'isatty') and sys.stdout.isatty()): self.ansi = True + def rootUser(self, fatal=False): + if 'USER' in os.environ and os.environ['USER'] == 'root': + return True + if fatal: + doError('This command must be run as root') + return False def setPrecision(self, num): if num < 0 or num > 6: return @@ -564,7 +568,7 @@ class SystemValues: self.fsetVal('global', 'trace_clock') # set trace buffer to a huge value self.fsetVal('nop', 'current_tracer') - self.fsetVal('100000', 'buffer_size_kb') + self.fsetVal('131073', 'buffer_size_kb') # go no further if this is just a status check if testing: return @@ -583,7 +587,7 @@ class SystemValues: self.fsetVal('nofuncgraph-overhead', 'trace_options') self.fsetVal('context-info', 'trace_options') self.fsetVal('graph-time', 'trace_options') - self.fsetVal('0', 'max_graph_depth') + self.fsetVal('%d' % self.max_graph_depth, 'max_graph_depth') cf = ['dpm_run_callback'] if(self.usetraceeventsonly): cf += ['dpm_prepare', 'dpm_complete'] @@ -639,6 +643,12 @@ class SystemValues: return '\x1B[%d;40m%s\x1B[m' % (color, str) sysvals = SystemValues() +suspendmodename = { + 'freeze': 'Freeze (S0)', + 'standby': 'Standby (S1)', + 'mem': 'Suspend (S3)', + 'disk': 'Hibernate (S4)' +} # Class: DevProps # Description: @@ -1013,6 +1023,8 @@ class Data: tmp = dict() for devname in list: dev = list[devname] + if dev['length'] == 0: + continue tmp[dev['start']] = devname for t in sorted(tmp): slist.append(tmp[t]) @@ -1477,12 +1489,14 @@ class FTraceLine: # Each instance is tied to a single device in a single phase, and is # comprised of an ordered list of FTraceLine objects class FTraceCallGraph: + id = '' start = -1.0 end = -1.0 list = [] invalid = False depth = 0 pid = 0 + name = '' def __init__(self, pid): self.start = -1.0 self.end = -1.0 @@ -1631,9 +1645,17 @@ class FTraceCallGraph: return True return False def postProcess(self, debug=False): + if len(self.list) > 0: + self.name = self.list[0].name stack = dict() cnt = 0 + last = 0 for l in self.list: + # ftrace bug: reported duration is not reliable + # check each leaf and clip it at max possible length + if(last and last.freturn and last.fcall): + if last.length > l.time - last.time: + last.length = l.time - last.time if(l.fcall and not l.freturn): stack[l.depth] = l cnt += 1 @@ -1643,11 +1665,12 @@ class FTraceCallGraph: print 'Post Process Error: Depth missing' l.debugPrint() return False - # transfer total time from return line to call line - stack[l.depth].length = l.length + # calculate call length from call/return lines + stack[l.depth].length = l.time - stack[l.depth].time stack.pop(l.depth) l.length = 0 cnt -= 1 + last = l if(cnt == 0): # trace caught the whole call tree return True @@ -1664,8 +1687,8 @@ class FTraceCallGraph: 'dpm_prepare': 'suspend_prepare', 'dpm_complete': 'resume_complete' } - if(self.list[0].name in borderphase): - p = borderphase[self.list[0].name] + if(self.name in borderphase): + p = borderphase[self.name] list = data.dmesg[p]['list'] for devname in list: dev = list[devname] @@ -1690,7 +1713,7 @@ class FTraceCallGraph: break return found def newActionFromFunction(self, data): - name = self.list[0].name + name = self.name if name in ['dpm_run_callback', 'dpm_prepare', 'dpm_complete']: return fs = self.start @@ -1710,7 +1733,7 @@ class FTraceCallGraph: phase, myname = out data.dmesg[phase]['list'][myname]['ftrace'] = self def debugPrint(self): - print('[%f - %f] %s (%d)') % (self.start, self.end, self.list[0].name, self.pid) + print('[%f - %f] %s (%d)') % (self.start, self.end, self.name, self.pid) for l in self.list: if(l.freturn and l.fcall): print('%f (%02d): %s(); (%.3f us)' % (l.time, \ @@ -1738,7 +1761,7 @@ class DevItem: # A container for a device timeline which calculates # all the html properties to display it correctly class Timeline: - html = {} + html = '' height = 0 # total timeline height scaleH = 20 # timescale (top) row height rowH = 30 # device row height @@ -1746,14 +1769,28 @@ class Timeline: rows = 0 # total timeline rows rowlines = dict() rowheight = dict() + html_tblock = '
\n' + html_device = '
{6}
\n' + html_phase = '
{5}
\n' + html_phaselet = '
\n' def __init__(self, rowheight, scaleheight): self.rowH = rowheight self.scaleH = scaleheight - self.html = { - 'header': '', - 'timeline': '', - 'legend': '', - } + self.html = '' + def createHeader(self, sv, suppress=''): + if(not sv.stamp['time']): + return + self.html += '
%s v%s
' \ + % (sv.title, sv.version) + if sv.logmsg and 'log' not in suppress: + self.html += '' + if sv.addlogs and 'dmesg' not in suppress: + self.html += '' + if sv.addlogs and sv.ftracefile and 'ftrace' not in suppress: + self.html += '' + headline_stamp = '
{0} {1} {2} {3}
\n' + self.html += headline_stamp.format(sv.stamp['host'], sv.stamp['kernel'], + sv.stamp['mode'], sv.stamp['time']) # Function: getDeviceRows # Description: # determine how may rows the device funcs will take @@ -1880,10 +1917,8 @@ class Timeline: break top += self.rowheight[test][phase][i] return top - # Function: calcTotalRows - # Description: - # Calculate the heights and offsets for the header and rows def calcTotalRows(self): + # Calculate the heights and offsets for the header and rows maxrows = 0 standardphases = [] for t in self.rowlines: @@ -1901,6 +1936,20 @@ class Timeline: for t, p in standardphases: for i in sorted(self.rowheight[t][p]): self.rowheight[t][p][i] = self.bodyH/len(self.rowlines[t][p]) + def createZoomBox(self, mode='command', testcount=1): + # Create bounding box, add buttons + html_zoombox = '
\n' + html_timeline = '
\n
\n' + html_devlist1 = '' + html_devlist2 = '\n' + if mode != 'command': + if testcount > 1: + self.html += html_devlist2 + self.html += html_devlist1.format('1') + else: + self.html += html_devlist1.format('') + self.html += html_zoombox + self.html += html_timeline.format('dmesg', self.height) # Function: createTimeScale # Description: # Create the timescale for a timeline block @@ -1913,7 +1962,7 @@ class Timeline: # The html code needed to display the time scale def createTimeScale(self, m0, mMax, tTotal, mode): timescale = '
{1}
\n' - rline = '
Resume
\n' + rline = '
{0}
\n' output = '
\n' # set scale for timeline mTotal = mMax - m0 @@ -1926,21 +1975,20 @@ class Timeline: divEdge = (mTotal - tS*(divTotal-1))*100/mTotal for i in range(divTotal): htmlline = '' - if(mode == 'resume'): - pos = '%0.3f' % (100 - ((float(i)*tS*100)/mTotal)) - val = '%0.fms' % (float(i)*tS*1000) - htmlline = timescale.format(pos, val) - if(i == 0): - htmlline = rline - else: + if(mode == 'suspend'): pos = '%0.3f' % (100 - ((float(i)*tS*100)/mTotal) - divEdge) val = '%0.fms' % (float(i-divTotal+1)*tS*1000) if(i == divTotal - 1): - val = 'Suspend' + val = mode + htmlline = timescale.format(pos, val) + else: + pos = '%0.3f' % (100 - ((float(i)*tS*100)/mTotal)) + val = '%0.fms' % (float(i)*tS*1000) htmlline = timescale.format(pos, val) + if(i == 0): + htmlline = rline.format(mode) output += htmlline - output += '
\n' - return output + self.html += output+'
\n' # Class: TestProps # Description: @@ -2009,7 +2057,7 @@ class ProcessMonitor: val['kern'] = kern if ujiff > 0 or kjiff > 0: running[pid] = ujiff + kjiff - result = process.wait() + process.wait() out = '' for pid in running: jiffies = running[pid] @@ -2071,26 +2119,6 @@ def parseStamp(line, data): if not sysvals.stamp: sysvals.stamp = data.stamp -# Function: diffStamp -# Description: -# compare the host, kernel, and mode fields in 3 stamps -# Arguments: -# stamp1: string array with mode, kernel, and host -# stamp2: string array with mode, kernel, and host -# Return: -# True if stamps differ, False if they're the same -def diffStamp(stamp1, stamp2): - if 'host' in stamp1 and 'host' in stamp2: - if stamp1['host'] != stamp2['host']: - return True - if 'kernel' in stamp1 and 'kernel' in stamp2: - if stamp1['kernel'] != stamp2['kernel']: - return True - if 'mode' in stamp1 and 'mode' in stamp2: - if stamp1['mode'] != stamp2['mode']: - return True - return False - # Function: doesTraceLogHaveTraceEvents # Description: # Quickly determine if the ftrace log has some or all of the trace events @@ -2722,7 +2750,7 @@ def parseTraceLog(): # create blocks for orphan cg data for sortkey in sorted(sortlist): cg = sortlist[sortkey] - name = cg.list[0].name + name = cg.name if sysvals.isCallgraphFunc(name): vprint('Callgraph found for task %d: %.3fms, %s' % (cg.pid, (cg.end - cg.start)*1000, name)) cg.newActionFromFunction(data) @@ -3100,149 +3128,154 @@ def parseKernelLog(data): data.fixupInitcallsThatDidntReturn() return True +def callgraphHTML(sv, hf, num, cg, title, color, devid): + html_func_top = '
\n\n' + html_func_start = '
\n\n' + html_func_end = '
\n' + html_func_leaf = '
{0} {1}
\n' + + cgid = devid + if cg.id: + cgid += cg.id + cglen = (cg.end - cg.start) * 1000 + if cglen < sv.mincglen: + return num + + fmt = '(%.3f ms @ '+sv.timeformat+' to '+sv.timeformat+')' + flen = fmt % (cglen, cg.start, cg.end) + hf.write(html_func_top.format(cgid, color, num, title, flen)) + num += 1 + for line in cg.list: + if(line.length < 0.000000001): + flen = '' + else: + fmt = '(%.3f ms @ '+sv.timeformat+')' + flen = fmt % (line.length*1000, line.time) + if(line.freturn and line.fcall): + hf.write(html_func_leaf.format(line.name, flen)) + elif(line.freturn): + hf.write(html_func_end) + else: + hf.write(html_func_start.format(num, line.name, flen)) + num += 1 + hf.write(html_func_end) + return num + +def addCallgraphs(sv, hf, data): + hf.write('
\n') + # write out the ftrace data converted to html + num = 0 + for p in data.phases: + if sv.cgphase and p != sv.cgphase: + continue + list = data.dmesg[p]['list'] + for devname in data.sortedDevices(p): + dev = list[devname] + color = 'white' + if 'color' in data.dmesg[p]: + color = data.dmesg[p]['color'] + if 'color' in dev: + color = dev['color'] + name = devname + if(devname in sv.devprops): + name = sv.devprops[devname].altName(devname) + if sv.suspendmode in suspendmodename: + name += ' '+p + if('ftrace' in dev): + cg = dev['ftrace'] + num = callgraphHTML(sv, hf, num, cg, + name, color, dev['id']) + if('ftraces' in dev): + for cg in dev['ftraces']: + num = callgraphHTML(sv, hf, num, cg, + name+' → '+cg.name, color, dev['id']) + + hf.write('\n\n
\n') + # Function: createHTMLSummarySimple # Description: # Create summary html file for a series of tests # Arguments: # testruns: array of Data objects from parseTraceLog -def createHTMLSummarySimple(testruns, htmlfile): - # print out the basic summary of all the tests - hf = open(htmlfile, 'w') - +def createHTMLSummarySimple(testruns, htmlfile, folder): # write the html header first (html head, css code, up to body start) html = '\n\n\n\ \n\ - AnalyzeSuspend Summary\n\ + SleepGraph Summary\n\ \n\n\n' # group test header - count = len(testruns) - headline_stamp = '
{0} {1} {2} {3} ({4} tests)
\n' - html += headline_stamp.format(sysvals.stamp['host'], - sysvals.stamp['kernel'], sysvals.stamp['mode'], - sysvals.stamp['time'], count) - - # check to see if all the tests have the same value - stampcolumns = False - for data in testruns: - if diffStamp(sysvals.stamp, data.stamp): - stampcolumns = True - break - + html += '
%s (%d tests)
\n' % (folder, len(testruns)) th = '\t{0}\n' td = '\t{0}\n' - tdlink = '\tClick Here\n' + tdlink = '\thtml\n' # table header - html += '\n\n' - html += th.format("Test #") - if stampcolumns: - html += th.format("Hostname") - html += th.format("Kernel Version") - html += th.format("Suspend Mode") - html += th.format("Test Time") - html += th.format("Suspend Time") - html += th.format("Resume Time") - html += th.format("Detail") - html += '\n' + html += '
\n\n' + th.format('#') +\ + th.format('Mode') + th.format('Host') + th.format('Kernel') +\ + th.format('Test Time') + th.format('Suspend') + th.format('Resume') +\ + th.format('Detail') + '\n' # test data, 1 row per test - sTimeAvg = 0.0 - rTimeAvg = 0.0 - num = 1 - for data in testruns: - # data.end is the end of post_resume - resumeEnd = data.dmesg['resume_complete']['end'] + avg = ''+\ + '\n' + sTimeAvg = rTimeAvg = 0.0 + mode = '' + num = 0 + for data in sorted(testruns, key=lambda v:(v['mode'], v['host'], v['kernel'])): + if mode != data['mode']: + # test average line + if(num > 0): + sTimeAvg /= (num - 1) + rTimeAvg /= (num - 1) + html += avg.format('%d' % (num - 1), mode, + '%3.3f ms' % sTimeAvg, '%3.3f ms' % rTimeAvg) + sTimeAvg = rTimeAvg = 0.0 + mode = data['mode'] + num = 1 + # alternate row color if num % 2 == 1: html += '\n' else: html += '\n' - - # test num - html += td.format("test %d" % num) + html += td.format("%d" % num) num += 1 - if stampcolumns: - # host name - val = "unknown" - if('host' in data.stamp): - val = data.stamp['host'] - html += td.format(val) - # host kernel + # basic info + for item in ['mode', 'host', 'kernel', 'time']: val = "unknown" - if('kernel' in data.stamp): - val = data.stamp['kernel'] + if(item in data): + val = data[item] html += td.format(val) - # suspend mode - val = "unknown" - if('mode' in data.stamp): - val = data.stamp['mode'] - html += td.format(val) - # test time - val = "unknown" - if('time' in data.stamp): - val = data.stamp['time'] - html += td.format(val) # suspend time - sTime = (data.tSuspended - data.start)*1000 + sTime = float(data['suspend']) sTimeAvg += sTime - html += td.format("%3.3f ms" % sTime) + html += td.format('%.3f ms' % sTime) # resume time - rTime = (resumeEnd - data.tResumed)*1000 + rTime = float(data['resume']) rTimeAvg += rTime - html += td.format("%3.3f ms" % rTime) + html += td.format('%.3f ms' % rTime) # link to the output html - html += tdlink.format(data.outfile) - - html += '\n' - - # last line: test average - if(count > 0): - sTimeAvg /= count - rTimeAvg /= count - html += '\n' - html += td.format('Average') # name - if stampcolumns: - html += td.format('') # host - html += td.format('') # kernel - html += td.format('') # mode - html += td.format('') # time - html += td.format("%3.3f ms" % sTimeAvg) # suspend time - html += td.format("%3.3f ms" % rTimeAvg) # resume time - html += td.format('') # output link - html += '\n' + html += tdlink.format(data['url']) + '\n' + # last test average line + if(num > 0): + sTimeAvg /= (num - 1) + rTimeAvg /= (num - 1) + html += avg.format('%d' % (num - 1), mode, + '%3.3f ms' % sTimeAvg, '%3.3f ms' % rTimeAvg) # flush the data to file - hf.write(html+'
Average of {0} {1} tests{2}{3}
\n') - hf.write('\n\n') + hf = open(htmlfile, 'w') + hf.write(html+'\n\n\n') hf.close() -def htmlTitle(): - modename = { - 'freeze': 'Freeze (S0)', - 'standby': 'Standby (S1)', - 'mem': 'Suspend (S3)', - 'disk': 'Hibernate (S4)' - } - kernel = sysvals.stamp['kernel'] - host = sysvals.hostname[0].upper()+sysvals.hostname[1:] - mode = sysvals.suspendmode - if sysvals.suspendmode in modename: - mode = modename[sysvals.suspendmode] - return host+' '+mode+' '+kernel - def ordinal(value): suffix = 'th' if value < 10 or value > 19: @@ -3272,24 +3305,11 @@ def createHTML(testruns): kerror = True data.normalizeTime(testruns[-1].tSuspended) - x2changes = ['', 'absolute'] - if len(testruns) > 1: - x2changes = ['1', 'relative'] # html function templates - headline_version = '
AnalyzeSuspend v%s
' % sysvals.version - headline_stamp = '
{0} {1} {2} {3}
\n' - html_devlist1 = '' % x2changes[0] - html_zoombox = '
\n' - html_devlist2 = '\n' - html_timeline = '
\n
\n' - html_tblock = '
\n' - html_device = '
{6}
\n' html_error = '
ERROR→
\n' html_traceevent = '
{5}
\n' html_cpuexec = '
\n' - html_phase = '
{5}
\n' - html_phaselet = '
\n' - html_legend = '
 {2}
\n' + html_legend = '
 {2}
\n' html_timetotal = '\n'\ ''\ ''\ @@ -3311,20 +3331,18 @@ def createHTML(testruns): '\n
{2} Suspend Time: {0} ms{2} Resume Time: {1} ms
\n' # html format variables - hoverZ = 'z-index:8;' - if sysvals.usedevsrc: - hoverZ = '' scaleH = 20 - scaleTH = 20 if kerror: scaleH = 40 - scaleTH = 60 # device timeline vprint('Creating Device Timeline...') devtl = Timeline(30, scaleH) + # write the test title and general info header + devtl.createHeader(sysvals) + # Generate the header for this timeline for data in testruns: tTotal = data.end - data.start @@ -3346,7 +3364,7 @@ def createHTML(testruns): if(len(testruns) > 1): testdesc = ordinal(data.testnumber+1)+' '+testdesc thtml = html_timetotal3.format(run_time, testdesc) - devtl.html['header'] += thtml + devtl.html += thtml elif data.fwValid: suspend_time = '%.0f'%(sktime + (data.fwSuspend/1000000.0)) resume_time = '%.0f'%(rktime + (data.fwResume/1000000.0)) @@ -3363,10 +3381,10 @@ def createHTML(testruns): else: thtml = html_timetotal2.format(suspend_time, low_time, \ resume_time, testdesc1, stitle, rtitle) - devtl.html['header'] += thtml + devtl.html += thtml sftime = '%.3f'%(data.fwSuspend / 1000000.0) rftime = '%.3f'%(data.fwResume / 1000000.0) - devtl.html['header'] += html_timegroups.format('%.3f'%sktime, \ + devtl.html += html_timegroups.format('%.3f'%sktime, \ sftime, rftime, '%.3f'%rktime, testdesc2, sysvals.suspendmode) else: suspend_time = '%.3f' % sktime @@ -3382,7 +3400,7 @@ def createHTML(testruns): else: thtml = html_timetotal2.format(suspend_time, low_time, \ resume_time, testdesc, stitle, rtitle) - devtl.html['header'] += thtml + devtl.html += thtml # time scale for potentially multiple datasets t0 = testruns[0].start @@ -3429,15 +3447,8 @@ def createHTML(testruns): devtl.getPhaseRows(threadlist, devtl.rows) devtl.calcTotalRows() - # create bounding box, add buttons - if sysvals.suspendmode != 'command': - devtl.html['timeline'] += html_devlist1 - if len(testruns) > 1: - devtl.html['timeline'] += html_devlist2 - devtl.html['timeline'] += html_zoombox - devtl.html['timeline'] += html_timeline.format('dmesg', devtl.height) - # draw the full timeline + devtl.createZoomBox(sysvals.suspendmode, len(testruns)) phases = {'suspend':[],'resume':[]} for phase in data.dmesg: if 'resume' in phase: @@ -3452,37 +3463,36 @@ def createHTML(testruns): # draw suspend and resume blocks separately bname = '%s%d' % (dir[0], data.testnumber) if dir == 'suspend': - m0 = testruns[data.testnumber].start - mMax = testruns[data.testnumber].tSuspended - mTotal = mMax - m0 + m0 = data.start + mMax = data.tSuspended left = '%f' % (((m0-t0)*100.0)/tTotal) else: - m0 = testruns[data.testnumber].tSuspended - mMax = testruns[data.testnumber].end + m0 = data.tSuspended + mMax = data.end # in an x2 run, remove any gap between blocks if len(testruns) > 1 and data.testnumber == 0: mMax = testruns[1].start - mTotal = mMax - m0 left = '%f' % ((((m0-t0)*100.0)+sysvals.srgap/2)/tTotal) + mTotal = mMax - m0 # if a timeline block is 0 length, skip altogether if mTotal == 0: continue width = '%f' % (((mTotal*100.0)-sysvals.srgap/2)/tTotal) - devtl.html['timeline'] += html_tblock.format(bname, left, width, devtl.scaleH) + devtl.html += devtl.html_tblock.format(bname, left, width, devtl.scaleH) for b in sorted(phases[dir]): # draw the phase color background phase = data.dmesg[b] length = phase['end']-phase['start'] left = '%f' % (((phase['start']-m0)*100.0)/mTotal) width = '%f' % ((length*100.0)/mTotal) - devtl.html['timeline'] += html_phase.format(left, width, \ + devtl.html += devtl.html_phase.format(left, width, \ '%.3f'%devtl.scaleH, '%.3f'%devtl.bodyH, \ data.dmesg[b]['color'], '') for e in data.errorinfo[dir]: # draw red lines for any kernel errors found t, err = e right = '%f' % (((mMax-t)*100.0)/mTotal) - devtl.html['timeline'] += html_error.format(right, err) + devtl.html += html_error.format(right, err) for b in sorted(phases[dir]): # draw the devices for this phase phaselist = data.dmesg[b]['list'] @@ -3496,7 +3506,7 @@ def createHTML(testruns): if 'htmlclass' in dev: xtraclass = dev['htmlclass'] if 'color' in dev: - xtrastyle = 'background-color:%s;' % dev['color'] + xtrastyle = 'background:%s;' % dev['color'] if(d in sysvals.devprops): name = sysvals.devprops[d].altName(d) xtraclass = sysvals.devprops[d].xtraClass() @@ -3521,7 +3531,7 @@ def createHTML(testruns): title += 'post_resume_process' else: title += b - devtl.html['timeline'] += html_device.format(dev['id'], \ + devtl.html += devtl.html_device.format(dev['id'], \ title, left, top, '%.3f'%rowheight, width, \ d+drv, xtraclass, xtrastyle) if('cpuexec' in dev): @@ -3535,7 +3545,7 @@ def createHTML(testruns): left = '%f' % (((start-m0)*100)/mTotal) width = '%f' % ((end-start)*100/mTotal) color = 'rgba(255, 0, 0, %f)' % j - devtl.html['timeline'] += \ + devtl.html += \ html_cpuexec.format(left, top, height, width, color) if('src' not in dev): continue @@ -3548,20 +3558,20 @@ def createHTML(testruns): xtrastyle = '' if e.color: xtrastyle = 'background:%s;' % e.color - devtl.html['timeline'] += \ + devtl.html += \ html_traceevent.format(e.title(), \ left, top, height, width, e.text(), '', xtrastyle) # draw the time scale, try to make the number of labels readable - devtl.html['timeline'] += devtl.createTimeScale(m0, mMax, tTotal, dir) - devtl.html['timeline'] += '
\n' + devtl.createTimeScale(m0, mMax, tTotal, dir) + devtl.html += '
\n' # timeline is finished - devtl.html['timeline'] += '
\n
\n' + devtl.html += '
\n\n' # draw a legend which describes the phases by color if sysvals.suspendmode != 'command': data = testruns[-1] - devtl.html['legend'] = '
\n' + devtl.html += '
\n' pdelta = 100.0/len(data.phases) pmargin = pdelta / 4.0 for phase in data.phases: @@ -3571,127 +3581,41 @@ def createHTML(testruns): id += tmp[1][0] order = '%.2f' % ((data.dmesg[phase]['order'] * pdelta) + pmargin) name = string.replace(phase, '_', '  ') - devtl.html['legend'] += html_legend.format(order, \ + devtl.html += html_legend.format(order, \ data.dmesg[phase]['color'], name, id) - devtl.html['legend'] += '
\n' + devtl.html += '
\n' hf = open(sysvals.htmlfile, 'w') - if not sysvals.cgexp: - cgchk = 'checked' - cgnchk = 'not(:checked)' - else: - cgchk = 'not(:checked)' - cgnchk = 'checked' - - # write the html header first (html head, css code, up to body start) - html_header = '\n\n\n\ - \n\ - '+htmlTitle()+'\n\ - \n\n\n' - # no header or css if its embedded if(sysvals.embedded): hf.write('pass True tSus %.3f tRes %.3f tLow %.3f fwvalid %s tSus %.3f tRes %.3f\n' % (data.tSuspended-data.start, data.end-data.tSuspended, data.tLow, data.fwValid, \ data.fwSuspend/1000000, data.fwResume/1000000)) else: - hf.write(html_header) - - # write the test title and general info header - if(sysvals.stamp['time'] != ""): - hf.write(headline_version) - if sysvals.logmsg: - hf.write('') - if sysvals.addlogs and sysvals.dmesgfile: - hf.write('') - if sysvals.addlogs and sysvals.ftracefile: - hf.write('') - hf.write(headline_stamp.format(sysvals.stamp['host'], - sysvals.stamp['kernel'], sysvals.stamp['mode'], \ - sysvals.stamp['time'])) + addCSS(hf, sysvals, len(testruns), kerror) # write the device timeline - hf.write(devtl.html['header']) - hf.write(devtl.html['timeline']) - hf.write(devtl.html['legend']) + hf.write(devtl.html) hf.write('
\n') hf.write('\n') @@ -3701,52 +3625,7 @@ def createHTML(testruns): else: data = testruns[-1] if(sysvals.usecallgraph and not sysvals.embedded): - hf.write('
\n') - # write out the ftrace data converted to html - html_func_top = '
\n\n' - html_func_start = '
\n\n' - html_func_end = '
\n' - html_func_leaf = '
{0} {1}
\n' - num = 0 - for p in data.phases: - if sysvals.cgphase and p != sysvals.cgphase: - continue - list = data.dmesg[p]['list'] - for devname in data.sortedDevices(p): - if('ftrace' not in list[devname]): - continue - devid = list[devname]['id'] - cg = list[devname]['ftrace'] - clen = (cg.end - cg.start) * 1000 - if clen < sysvals.mincglen: - continue - fmt = '(%.3f ms @ '+sysvals.timeformat+' to '+sysvals.timeformat+')' - flen = fmt % (clen, cg.start, cg.end) - name = devname - if(devname in sysvals.devprops): - name = sysvals.devprops[devname].altName(devname) - if sysvals.suspendmode == 'command': - ftitle = name - else: - ftitle = name+' '+p - hf.write(html_func_top.format(devid, data.dmesg[p]['color'], \ - num, ftitle, flen)) - num += 1 - for line in cg.list: - if(line.length < 0.000000001): - flen = '' - else: - fmt = '(%.3f ms @ '+sysvals.timeformat+')' - flen = fmt % (line.length*1000, line.time) - if(line.freturn and line.fcall): - hf.write(html_func_leaf.format(line.name, flen)) - elif(line.freturn): - hf.write(html_func_end) - else: - hf.write(html_func_start.format(num, line.name, flen)) - num += 1 - hf.write(html_func_end) - hf.write('\n\n
\n') + addCallgraphs(sysvals, hf, data) # add the test log as a hidden div if sysvals.logmsg: @@ -3788,6 +3667,100 @@ def createHTML(testruns): hf.close() return True +def addCSS(hf, sv, testcount=1, kerror=False, extra=''): + kernel = sv.stamp['kernel'] + host = sv.hostname[0].upper()+sv.hostname[1:] + mode = sv.suspendmode + if sv.suspendmode in suspendmodename: + mode = suspendmodename[sv.suspendmode] + title = host+' '+mode+' '+kernel + + # various format changes by flags + cgchk = 'checked' + cgnchk = 'not(:checked)' + if sv.cgexp: + cgchk = 'not(:checked)' + cgnchk = 'checked' + + hoverZ = 'z-index:8;' + if sv.usedevsrc: + hoverZ = '' + + devlistpos = 'absolute' + if testcount > 1: + devlistpos = 'relative' + + scaleTH = 20 + if kerror: + scaleTH = 60 + + # write the html header first (html head, css code, up to body start) + html_header = '\n\n\n\ + \n\ + '+title+'\n\ + \n\n\n' + hf.write(html_header) + # Function: addScriptCode # Description: # Adds the javascript code to the output html @@ -3809,7 +3782,7 @@ def addScriptCode(hf, testruns): ' var resolution = -1;\n'\ ' var dragval = [0, 0];\n'\ ' function redrawTimescale(t0, tMax, tS) {\n'\ - ' var rline = \'
←R
\';\n'\ + ' var rline = \'
\';\n'\ ' var tTotal = tMax - t0;\n'\ ' var list = document.getElementsByClassName("tblock");\n'\ ' for (var i = 0; i < list.length; i++) {\n'\ @@ -3824,19 +3797,23 @@ def addScriptCode(hf, testruns): ' var pos = 0.0, val = 0.0;\n'\ ' for (var j = 0; j < divTotal; j++) {\n'\ ' var htmlline = "";\n'\ - ' if(list[i].id[5] == "r") {\n'\ - ' pos = 100 - (((j)*tS*100)/mTotal);\n'\ - ' val = (j)*tS;\n'\ - ' htmlline = \'
\'+val+\'ms
\';\n'\ - ' if(j == 0)\n'\ - ' htmlline = rline;\n'\ - ' } else {\n'\ + ' var mode = list[i].id[5];\n'\ + ' if(mode == "s") {\n'\ ' pos = 100 - (((j)*tS*100)/mTotal) - divEdge;\n'\ ' val = (j-divTotal+1)*tS;\n'\ ' if(j == divTotal - 1)\n'\ ' htmlline = \'
S→
\';\n'\ ' else\n'\ ' htmlline = \'
\'+val+\'ms
\';\n'\ + ' } else {\n'\ + ' pos = 100 - (((j)*tS*100)/mTotal);\n'\ + ' val = (j)*tS;\n'\ + ' htmlline = \'
\'+val+\'ms
\';\n'\ + ' if(j == 0)\n'\ + ' if(mode == "r")\n'\ + ' htmlline = rline+"←R
";\n'\ + ' else\n'\ + ' htmlline = rline+"0ms";\n'\ ' }\n'\ ' html += htmlline;\n'\ ' }\n'\ @@ -4002,12 +3979,80 @@ def addScriptCode(hf, testruns): ' }\n'\ ' }\n'\ ' }\n'\ + ' if(typeof devstats !== \'undefined\')\n'\ + ' callDetail(this.id, this.title);\n'\ ' var cglist = document.getElementById("callgraphs");\n'\ ' if(!cglist) return;\n'\ ' var cg = cglist.getElementsByClassName("atop");\n'\ ' if(cg.length < 10) return;\n'\ ' for (var i = 0; i < cg.length; i++) {\n'\ - ' if(idlist.indexOf(cg[i].id) >= 0) {\n'\ + ' cgid = cg[i].id.split("x")[0]\n'\ + ' if(idlist.indexOf(cgid) >= 0) {\n'\ + ' cg[i].style.display = "block";\n'\ + ' } else {\n'\ + ' cg[i].style.display = "none";\n'\ + ' }\n'\ + ' }\n'\ + ' }\n'\ + ' function callDetail(devid, devtitle) {\n'\ + ' if(!(devid in devstats) || devstats[devid].length < 1)\n'\ + ' return;\n'\ + ' var list = devstats[devid];\n'\ + ' var tmp = devtitle.split(" ");\n'\ + ' var name = tmp[0], phase = tmp[tmp.length-1];\n'\ + ' var dd = document.getElementById(phase);\n'\ + ' var total = parseFloat(tmp[1].slice(1));\n'\ + ' var mlist = [];\n'\ + ' var maxlen = 0;\n'\ + ' var info = []\n'\ + ' for(var i in list) {\n'\ + ' if(list[i][0] == "@") {\n'\ + ' info = list[i].split("|");\n'\ + ' continue;\n'\ + ' }\n'\ + ' var tmp = list[i].split("|");\n'\ + ' var t = parseFloat(tmp[0]), f = tmp[1], c = parseInt(tmp[2]);\n'\ + ' var p = (t*100.0/total).toFixed(2);\n'\ + ' mlist[mlist.length] = [f, c, t.toFixed(2), p+"%"];\n'\ + ' if(f.length > maxlen)\n'\ + ' maxlen = f.length;\n'\ + ' }\n'\ + ' var pad = 5;\n'\ + ' if(mlist.length == 0) pad = 30;\n'\ + ' var html = \'
\'+name+\':\';\n'\ + ' if(info.length > 2)\n'\ + ' html += " start="+info[1]+", end="+info[2]+"";\n'\ + ' if(info.length > 3)\n'\ + ' html += ", length(w/o overhead)="+info[3]+" ms";\n'\ + ' if(info.length > 4)\n'\ + ' html += ", return="+info[4]+"";\n'\ + ' html += "
";\n'\ + ' if(mlist.length > 0) {\n'\ + ' html += \'\';\n'\ + ' for(var i in mlist)\n'\ + ' html += "";\n'\ + ' html += "";\n'\ + ' for(var i in mlist)\n'\ + ' html += "";\n'\ + ' html += "";\n'\ + ' for(var i in mlist)\n'\ + ' html += "";\n'\ + ' html += "";\n'\ + ' for(var i in mlist)\n'\ + ' html += "";\n'\ + ' html += "
Function"+mlist[i][0]+"
Calls"+mlist[i][1]+"
Time(ms)"+mlist[i][2]+"
Percent"+mlist[i][3]+"
";\n'\ + ' }\n'\ + ' dd.innerHTML = html;\n'\ + ' var height = (maxlen*5)+100;\n'\ + ' dd.style.height = height+"px";\n'\ + ' document.getElementById("devicedetail").style.height = height+"px";\n'\ + ' }\n'\ + ' function callSelect() {\n'\ + ' var cglist = document.getElementById("callgraphs");\n'\ + ' if(!cglist) return;\n'\ + ' var cg = cglist.getElementsByClassName("atop");\n'\ + ' for (var i = 0; i < cg.length; i++) {\n'\ + ' if(this.id == cg[i].id) {\n'\ ' cg[i].style.display = "block";\n'\ ' } else {\n'\ ' cg[i].style.display = "none";\n'\ @@ -4093,6 +4138,9 @@ def addScriptCode(hf, testruns): ' dev[i].onmouseover = deviceHover;\n'\ ' dev[i].onmouseout = deviceUnhover;\n'\ ' }\n'\ + ' var dev = dmesg.getElementsByClassName("srccall");\n'\ + ' for (var i = 0; i < dev.length; i++)\n'\ + ' dev[i].onclick = callSelect;\n'\ ' zoomTimeline();\n'\ ' });\n'\ '\n' @@ -4675,7 +4723,7 @@ def rootCheck(fatal): if(os.access(sysvals.powerfile, os.W_OK)): return True if fatal: - doError('This command must be run as root') + doError('This command requires sysfs mount and root access') return False # Function: getArgInt @@ -4767,51 +4815,62 @@ def runTest(subdir, testpath=''): cmd = 'chown -R {0}:{0} {1} > /dev/null 2>&1' call(cmd.format(os.environ['SUDO_USER'], sysvals.testdir), shell=True) +def find_in_html(html, strs, div=False): + for str in strs: + l = len(str) + i = html.find(str) + if i >= 0: + break + if i < 0: + return '' + if not div: + return re.search(r'[-+]?\d*\.\d+|\d+', html[i+l:i+l+50]).group() + n = html[i+l:].find('') + if n < 0: + return '' + return html[i+l:i+l+n] + # Function: runSummary # Description: # create a summary of tests in a sub-directory -def runSummary(subdir, output): - # get a list of ftrace output files - files = [] +def runSummary(subdir, local=True): + inpath = os.path.abspath(subdir) + outpath = inpath + if local: + outpath = os.path.abspath('.') + print('Generating a summary of folder "%s"' % inpath) + testruns = [] for dirname, dirnames, filenames in os.walk(subdir): for filename in filenames: - if(re.match('.*_ftrace.txt', filename)): - files.append("%s/%s" % (dirname, filename)) - - # process the files in order and get an array of data objects - testruns = [] - for file in sorted(files): - if output: - print("Test found in %s" % os.path.dirname(file)) - sysvals.ftracefile = file - sysvals.dmesgfile = file.replace('_ftrace.txt', '_dmesg.txt') - doesTraceLogHaveTraceEvents() - sysvals.usecallgraph = False - if not sysvals.usetraceeventsonly: - if(not os.path.exists(sysvals.dmesgfile)): - print("Skipping %s: not a valid test input" % file) + if(not re.match('.*.html', filename)): continue - else: - if output: - f = os.path.basename(sysvals.ftracefile) - d = os.path.basename(sysvals.dmesgfile) - print("\tInput files: %s and %s" % (f, d)) - testdata = loadKernelLog() - data = testdata[0] - parseKernelLog(data) - testdata = [data] - appendIncompleteTraceLog(testdata) - else: - if output: - print("\tInput file: %s" % os.path.basename(sysvals.ftracefile)) - testdata = parseTraceLog() - data = testdata[0] - data.normalizeTime(data.tSuspended) - link = file.replace(subdir+'/', '').replace('_ftrace.txt', '.html') - data.outfile = link - testruns.append(data) - - createHTMLSummarySimple(testruns, subdir+'/summary.html') + file = os.path.join(dirname, filename) + html = open(file, 'r').read(10000) + suspend = find_in_html(html, + ['Kernel Suspend: ', 'Kernel Suspend Time: ']) + resume = find_in_html(html, + ['Kernel Resume: ', 'Kernel Resume Time: ']) + line = find_in_html(html, ['
'], True) + stmp = line.split() + if not suspend or not resume or len(stmp) < 4: + continue + data = { + 'host': stmp[0], + 'kernel': stmp[1], + 'mode': stmp[2], + 'time': string.join(stmp[3:], ' '), + 'suspend': suspend, + 'resume': resume, + 'url': os.path.relpath(file, outpath), + } + if len(stmp) == 7: + data['kernel'] = 'unknown' + data['mode'] = stmp[1] + data['time'] = string.join(stmp[2:], ' ') + testruns.append(data) + outfile = os.path.join(outpath, 'summary.html') + print('Summary file: %s' % outfile) + createHTMLSummarySimple(testruns, outfile, inpath) # Function: checkArgBool # Description: @@ -4869,9 +4928,14 @@ def configFromFile(file): sysvals.predelay = getArgInt('-predelay', value, 0, 60000, False) elif(opt.lower() == 'postdelay'): sysvals.postdelay = getArgInt('-postdelay', value, 0, 60000, False) + elif(opt.lower() == 'maxdepth'): + sysvals.max_graph_depth = getArgInt('-maxdepth', value, 0, 1000, False) elif(opt.lower() == 'rtcwake'): - sysvals.rtcwake = True - sysvals.rtcwaketime = getArgInt('-rtcwake', value, 0, 3600, False) + if value.lower() == 'off': + sysvals.rtcwake = False + else: + sysvals.rtcwake = True + sysvals.rtcwaketime = getArgInt('-rtcwake', value, 0, 3600, False) elif(opt.lower() == 'timeprec'): sysvals.setPrecision(getArgInt('-timeprec', value, 0, 6, False)) elif(opt.lower() == 'mindev'): @@ -4969,8 +5033,8 @@ def printHelp(): modes = getModes() print('') - print('AnalyzeSuspend v%s' % sysvals.version) - print('Usage: sudo analyze_suspend.py ') + print('%s v%s' % (sysvals.title, sysvals.version)) + print('Usage: sudo sleepgraph ') print('') print('Description:') print(' This tool is designed to assist kernel and OS developers in optimizing') @@ -4981,22 +5045,22 @@ def printHelp(): print(' a detailed view of which devices/subsystems are taking the most') print(' time in suspend/resume.') print('') + print(' If no specific command is given, the default behavior is to initiate') + print(' a suspend/resume and capture the dmesg/ftrace output as an html timeline.') + print('') print(' Generates output files in subdirectory: suspend-mmddyy-HHMMSS') print(' HTML output: _.html') print(' raw dmesg output: __dmesg.txt') print(' raw ftrace output: __ftrace.txt') print('') print('Options:') - print(' [general]') print(' -h Print this help text') print(' -v Print the current tool version') print(' -config fn Pull arguments and config options from file fn') print(' -verbose Print extra information during execution and analysis') - print(' -status Test to see if the system is enabled to run this tool') - print(' -modes List available suspend modes') print(' -m mode Mode to initiate for suspend %s (default: %s)') % (modes, sysvals.suspendmode) print(' -o subdir Override the output subdirectory') - print(' -rtcwake t Use rtcwake to autoresume after seconds (default: disabled)') + print(' -rtcwake t Wakeup t seconds after suspend, set t to "off" to disable (default: 15)') print(' -addlogs Add the dmesg and ftrace logs to the html output') print(' -srgap Add a visible gap in the timeline between sus/res (default: disabled)') print(' [advanced]') @@ -5012,23 +5076,25 @@ def printHelp(): print(' be created in a new subdirectory with a summary page.') print(' [debug]') print(' -f Use ftrace to create device callgraphs (default: disabled)') + print(' -maxdepth N limit the callgraph data to N call levels (default: 0=all)') print(' -expandcg pre-expand the callgraph data in the html output (default: disabled)') - print(' -flist Print the list of functions currently being captured in ftrace') - print(' -flistall Print all functions capable of being captured in ftrace') print(' -fadd file Add functions to be graphed in the timeline from a list in a text file') print(' -filter "d1,d2,..." Filter out all but this comma-delimited list of device names') print(' -mincg ms Discard all callgraphs shorter than ms milliseconds (e.g. 0.001 for us)') print(' -cgphase P Only show callgraph data for phase P (e.g. suspend_late)') print(' -cgtest N Only show callgraph data for test N (e.g. 0 or 1 in an x2 run)') print(' -timeprec N Number of significant digits in timestamps (0:S, [3:ms], 6:us)') - print(' [utilities]') + print(' [commands]') + print(' -ftrace ftracefile Create HTML output using ftrace input (used with -dmesg)') + print(' -dmesg dmesgfile Create HTML output using dmesg (used with -ftrace)') + print(' -summary directory Create a summary of all test in this dir') + print(' -modes List available suspend modes') + print(' -status Test to see if the system is enabled to run this tool') print(' -fpdt Print out the contents of the ACPI Firmware Performance Data Table') print(' -usbtopo Print out the current USB topology with power info') print(' -usbauto Enable autosuspend for all connected USB devices') - print(' [re-analyze data from previous runs]') - print(' -ftrace ftracefile Create HTML output using ftrace input') - print(' -dmesg dmesgfile Create HTML output using dmesg (not needed for kernel >= 3.15)') - print(' -summary directory Create a summary of all test in this dir') + print(' -flist Print the list of functions currently being captured in ftrace') + print(' -flistall Print all functions capable of being captured in ftrace') print('') return True @@ -5076,9 +5142,18 @@ if __name__ == '__main__': sysvals.useprocmon = True elif(arg == '-dev'): sysvals.usedevsrc = True + elif(arg == '-maxdepth'): + sysvals.max_graph_depth = getArgInt('-maxdepth', args, 0, 1000) elif(arg == '-rtcwake'): - sysvals.rtcwake = True - sysvals.rtcwaketime = getArgInt('-rtcwake', args, 0, 3600) + try: + val = args.next() + except: + doError('No rtcwake time supplied', True) + if val.lower() == 'off': + sysvals.rtcwake = False + else: + sysvals.rtcwake = True + sysvals.rtcwaketime = getArgInt('-rtcwake', val, 0, 3600, False) elif(arg == '-timeprec'): sysvals.setPrecision(getArgInt('-timeprec', args, 0, 6)) elif(arg == '-mindev'): @@ -5201,7 +5276,6 @@ if __name__ == '__main__': elif(cmd == 'usbauto'): setUSBDevicesAuto() elif(cmd == 'summary'): - print("Generating a summary of folder \"%s\"" % cmdarg) runSummary(cmdarg, True) sys.exit() -- 2.20.1