PM / tools: sleepgraph and bootgraph: upgrade to v5.2

+64 -61

tools/power/pm-graph/bootgraph.py

··· 34 34 from subprocess import call, Popen, PIPE 35 35 import sleepgraph as aslib 36 36 37 + def pprint(msg): 38 + print(msg) 39 + sys.stdout.flush() 40 + 37 41 # ----------------- CLASSES -------------------- 38 42 39 43 # Class: SystemValues ··· 161 157 return cmdline 162 158 def manualRebootRequired(self): 163 159 cmdline = self.kernelParams() 164 - print 'To generate a new timeline manually, follow these steps:\n' 165 - print '1. Add the CMDLINE string to your kernel command line.' 166 - print '2. Reboot the system.' 167 - print '3. After reboot, re-run this tool with the same arguments but no command (w/o -reboot or -manual).\n' 168 - print 'CMDLINE="%s"' % cmdline 160 + pprint('To generate a new timeline manually, follow these steps:\n\n'\ 161 + '1. Add the CMDLINE string to your kernel command line.\n'\ 162 + '2. Reboot the system.\n'\ 163 + '3. After reboot, re-run this tool with the same arguments but no command (w/o -reboot or -manual).\n\n'\ 164 + 'CMDLINE="%s"' % cmdline) 169 165 sys.exit() 170 166 def blGrub(self): 171 167 blcmd = '' ··· 435 431 if len(cg.list) < 1 or cg.invalid or (cg.end - cg.start == 0): 436 432 continue 437 433 if(not cg.postProcess()): 438 - print('Sanity check failed for %s-%d' % (proc, pid)) 434 + pprint('Sanity check failed for %s-%d' % (proc, pid)) 439 435 continue 440 436 # match cg data to devices 441 437 devname = data.deviceMatch(pid, cg) ··· 446 442 sysvals.vprint('%s callgraph found for %s %s-%d [%f - %f]' %\ 447 443 (kind, cg.name, proc, pid, cg.start, cg.end)) 448 444 elif len(cg.list) > 1000000: 449 - print 'WARNING: the callgraph found for %s is massive! (%d lines)' %\ 450 - (devname, len(cg.list)) 445 + pprint('WARNING: the callgraph found for %s is massive! (%d lines)' %\ 446 + (devname, len(cg.list))) 451 447 452 448 # Function: retrieveLogs 453 449 # Description: ··· 532 528 tMax = data.end 533 529 tTotal = tMax - t0 534 530 if(tTotal == 0): 535 - print('ERROR: No timeline data') 531 + pprint('ERROR: No timeline data') 536 532 return False 537 533 user_mode = '%.0f'%(data.tUserMode*1000) 538 534 last_init = '%.0f'%(tTotal*1000) ··· 738 734 op.close() 739 735 res = call([cmd, cronfile]) 740 736 except Exception, e: 741 - print 'Exception: %s' % str(e) 737 + pprint('Exception: %s' % str(e)) 742 738 shutil.move(backfile, cronfile) 743 739 res = -1 744 740 if res != 0: ··· 754 750 call(sysvals.blexec, stderr=PIPE, stdout=PIPE, 755 751 env={'PATH': '.:/sbin:/usr/sbin:/usr/bin:/sbin:/bin'}) 756 752 except Exception, e: 757 - print 'Exception: %s\n' % str(e) 753 + pprint('Exception: %s\n' % str(e)) 758 754 return 759 755 # extract the option and create a grub config without it 760 756 sysvals.rootUser(True) ··· 801 797 res = call(sysvals.blexec) 802 798 os.remove(grubfile) 803 799 except Exception, e: 804 - print 'Exception: %s' % str(e) 800 + pprint('Exception: %s' % str(e)) 805 801 res = -1 806 802 # cleanup 807 803 shutil.move(tempfile, grubfile) ··· 825 821 def doError(msg, help=False): 826 822 if help == True: 827 823 printHelp() 828 - print 'ERROR: %s\n' % msg 824 + pprint('ERROR: %s\n' % msg) 829 825 sysvals.outputResult({'error':msg}) 830 826 sys.exit() 831 827 ··· 833 829 # Description: 834 830 # print out the help text 835 831 def printHelp(): 836 - print('') 837 - print('%s v%s' % (sysvals.title, sysvals.version)) 838 - print('Usage: bootgraph <options> <command>') 839 - print('') 840 - print('Description:') 841 - print(' This tool reads in a dmesg log of linux kernel boot and') 842 - print(' creates an html representation of the boot timeline up to') 843 - print(' the start of the init process.') 844 - print('') 845 - print(' If no specific command is given the tool reads the current dmesg') 846 - print(' and/or ftrace log and creates a timeline') 847 - print('') 848 - print(' Generates output files in subdirectory: boot-yymmdd-HHMMSS') 849 - print(' HTML output: <hostname>_boot.html') 850 - print(' raw dmesg output: <hostname>_boot_dmesg.txt') 851 - print(' raw ftrace output: <hostname>_boot_ftrace.txt') 852 - print('') 853 - print('Options:') 854 - print(' -h Print this help text') 855 - print(' -v Print the current tool version') 856 - print(' -verbose Print extra information during execution and analysis') 857 - print(' -addlogs Add the dmesg log to the html output') 858 - print(' -result fn Export a results table to a text file for parsing.') 859 - print(' -o name Overrides the output subdirectory name when running a new test') 860 - print(' default: boot-{date}-{time}') 861 - print(' [advanced]') 862 - print(' -fstat Use ftrace to add function detail and statistics (default: disabled)') 863 - print(' -f/-callgraph Add callgraph detail, can be very large (default: disabled)') 864 - print(' -maxdepth N limit the callgraph data to N call levels (default: 2)') 865 - print(' -mincg ms Discard all callgraphs shorter than ms milliseconds (e.g. 0.001 for us)') 866 - print(' -timeprec N Number of significant digits in timestamps (0:S, 3:ms, [6:us])') 867 - print(' -expandcg pre-expand the callgraph data in the html output (default: disabled)') 868 - print(' -func list Limit ftrace to comma-delimited list of functions (default: do_one_initcall)') 869 - print(' -cgfilter S Filter the callgraph output in the timeline') 870 - print(' -cgskip file Callgraph functions to skip, off to disable (default: cgskip.txt)') 871 - print(' -bl name Use the following boot loader for kernel params (default: grub)') 872 - print(' -reboot Reboot the machine automatically and generate a new timeline') 873 - print(' -manual Show the steps to generate a new timeline manually (used with -reboot)') 874 - print('') 875 - print('Other commands:') 876 - print(' -flistall Print all functions capable of being captured in ftrace') 877 - print(' -sysinfo Print out system info extracted from BIOS') 878 - print(' [redo]') 879 - print(' -dmesg file Create HTML output using dmesg input (used with -ftrace)') 880 - print(' -ftrace file Create HTML output using ftrace input (used with -dmesg)') 881 - print('') 832 + pprint('\n%s v%s\n'\ 833 + 'Usage: bootgraph <options> <command>\n'\ 834 + '\n'\ 835 + 'Description:\n'\ 836 + ' This tool reads in a dmesg log of linux kernel boot and\n'\ 837 + ' creates an html representation of the boot timeline up to\n'\ 838 + ' the start of the init process.\n'\ 839 + '\n'\ 840 + ' If no specific command is given the tool reads the current dmesg\n'\ 841 + ' and/or ftrace log and creates a timeline\n'\ 842 + '\n'\ 843 + ' Generates output files in subdirectory: boot-yymmdd-HHMMSS\n'\ 844 + ' HTML output: <hostname>_boot.html\n'\ 845 + ' raw dmesg output: <hostname>_boot_dmesg.txt\n'\ 846 + ' raw ftrace output: <hostname>_boot_ftrace.txt\n'\ 847 + '\n'\ 848 + 'Options:\n'\ 849 + ' -h Print this help text\n'\ 850 + ' -v Print the current tool version\n'\ 851 + ' -verbose Print extra information during execution and analysis\n'\ 852 + ' -addlogs Add the dmesg log to the html output\n'\ 853 + ' -result fn Export a results table to a text file for parsing.\n'\ 854 + ' -o name Overrides the output subdirectory name when running a new test\n'\ 855 + ' default: boot-{date}-{time}\n'\ 856 + ' [advanced]\n'\ 857 + ' -fstat Use ftrace to add function detail and statistics (default: disabled)\n'\ 858 + ' -f/-callgraph Add callgraph detail, can be very large (default: disabled)\n'\ 859 + ' -maxdepth N limit the callgraph data to N call levels (default: 2)\n'\ 860 + ' -mincg ms Discard all callgraphs shorter than ms milliseconds (e.g. 0.001 for us)\n'\ 861 + ' -timeprec N Number of significant digits in timestamps (0:S, 3:ms, [6:us])\n'\ 862 + ' -expandcg pre-expand the callgraph data in the html output (default: disabled)\n'\ 863 + ' -func list Limit ftrace to comma-delimited list of functions (default: do_one_initcall)\n'\ 864 + ' -cgfilter S Filter the callgraph output in the timeline\n'\ 865 + ' -cgskip file Callgraph functions to skip, off to disable (default: cgskip.txt)\n'\ 866 + ' -bl name Use the following boot loader for kernel params (default: grub)\n'\ 867 + ' -reboot Reboot the machine automatically and generate a new timeline\n'\ 868 + ' -manual Show the steps to generate a new timeline manually (used with -reboot)\n'\ 869 + '\n'\ 870 + 'Other commands:\n'\ 871 + ' -flistall Print all functions capable of being captured in ftrace\n'\ 872 + ' -sysinfo Print out system info extracted from BIOS\n'\ 873 + ' [redo]\n'\ 874 + ' -dmesg file Create HTML output using dmesg input (used with -ftrace)\n'\ 875 + ' -ftrace file Create HTML output using ftrace input (used with -dmesg)\n'\ 876 + '' % (sysvals.title, sysvals.version)) 882 877 return True 883 878 884 879 # ----------------- MAIN -------------------- ··· 898 895 printHelp() 899 896 sys.exit() 900 897 elif(arg == '-v'): 901 - print("Version %s" % sysvals.version) 898 + pprint("Version %s" % sysvals.version) 902 899 sys.exit() 903 900 elif(arg == '-verbose'): 904 901 sysvals.verbose = True ··· 1019 1016 print f 1020 1017 elif cmd == 'checkbl': 1021 1018 sysvals.getBootLoader() 1022 - print 'Boot Loader: %s\n%s' % (sysvals.bootloader, sysvals.blexec) 1019 + pprint('Boot Loader: %s\n%s' % (sysvals.bootloader, sysvals.blexec)) 1023 1020 elif(cmd == 'sysinfo'): 1024 1021 sysvals.printSystemInfo(True) 1025 1022 sys.exit()

+1

tools/power/pm-graph/config/cgskip.txt

··· 27 27 # console calls 28 28 printk 29 29 dev_printk 30 + __dev_printk 30 31 console_unlock 31 32 32 33 # memory handling

+2 -2

tools/power/pm-graph/config/custom-timeline-functions.cfg

··· 105 105 # example: [color=#CC00CC] 106 106 # 107 107 # arglist: A list of arguments from registers/stack addresses. See URL: 108 - # https://www.kernel.org/doc/Documentation/trace/kprobetrace.rst 108 + # https://www.kernel.org/doc/Documentation/trace/kprobetrace.txt 109 109 # 110 110 # example: cpu=%di:s32 111 111 # ··· 170 170 # example: [color=#CC00CC] 171 171 # 172 172 # arglist: A list of arguments from registers/stack addresses. See URL: 173 - # https://www.kernel.org/doc/Documentation/trace/kprobetrace.rst 173 + # https://www.kernel.org/doc/Documentation/trace/kprobetrace.txt 174 174 # 175 175 # example: port=+36(%di):s32 176 176 #

+297 -235

tools/power/pm-graph/sleepgraph.py

··· 62 62 from threading import Thread 63 63 from subprocess import call, Popen, PIPE 64 64 65 + def pprint(msg): 66 + print(msg) 67 + sys.stdout.flush() 68 + 65 69 # ----------------- CLASSES -------------------- 66 70 67 71 # Class: SystemValues ··· 74 70 # store system values and test parameters 75 71 class SystemValues: 76 72 title = 'SleepGraph' 77 - version = '5.1' 73 + version = '5.2' 78 74 ansi = False 79 75 rs = 0 80 76 display = '' ··· 115 111 mempath = '/dev/mem' 116 112 powerfile = '/sys/power/state' 117 113 mempowerfile = '/sys/power/mem_sleep' 114 + diskpowerfile = '/sys/power/disk' 118 115 suspendmode = 'mem' 119 116 memmode = '' 117 + diskmode = '' 120 118 hostname = 'localhost' 121 119 prefix = 'test' 122 120 teststamp = '' ··· 145 139 useprocmon = False 146 140 notestrun = False 147 141 cgdump = False 142 + devdump = False 148 143 mixedphaseheight = True 149 144 devprops = dict() 150 145 predelay = 0 ··· 272 265 def vprint(self, msg): 273 266 self.logmsg += msg+'\n' 274 267 if self.verbose or msg.startswith('WARNING:'): 275 - print(msg) 268 + pprint(msg) 276 269 def signalHandler(self, signum, frame): 277 270 if not self.result: 278 271 return ··· 297 290 return True 298 291 if fatal: 299 292 msg = 'This command requires sysfs mount and root access' 300 - print('ERROR: %s\n') % msg 293 + pprint('ERROR: %s\n' % msg) 301 294 self.outputResult({'error':msg}) 302 295 sys.exit(1) 303 296 return False ··· 306 299 return True 307 300 if fatal: 308 301 msg = 'This command must be run as root' 309 - print('ERROR: %s\n') % msg 302 + pprint('ERROR: %s\n' % msg) 310 303 self.outputResult({'error':msg}) 311 304 sys.exit(1) 312 305 return False ··· 567 560 if len(self.kprobes) < 1: 568 561 return 569 562 if output: 570 - print(' kprobe functions in this kernel:') 563 + pprint(' kprobe functions in this kernel:') 571 564 # first test each kprobe 572 565 rejects = [] 573 566 # sort kprobes: trace, ub-dev, custom, dev ··· 589 582 else: 590 583 kpl[2].append(name) 591 584 if output: 592 - print(' %s: %s' % (name, res)) 585 + pprint(' %s: %s' % (name, res)) 593 586 kplist = kpl[0] + kpl[1] + kpl[2] + kpl[3] 594 587 # remove all failed ones from the list 595 588 for name in rejects: ··· 603 596 if output: 604 597 check = self.fgetVal('kprobe_events') 605 598 linesack = (len(check.split('\n')) - 1) / 2 606 - print(' kprobe functions enabled: %d/%d' % (linesack, linesout)) 599 + pprint(' kprobe functions enabled: %d/%d' % (linesack, linesout)) 607 600 self.fsetVal('1', 'events/kprobes/enable') 608 601 def testKprobe(self, kname, kprobe): 609 602 self.fsetVal('0', 'events/kprobes/enable') ··· 671 664 return False 672 665 def initFtrace(self): 673 666 self.printSystemInfo(False) 674 - print('INITIALIZING FTRACE...') 667 + pprint('INITIALIZING FTRACE...') 675 668 # turn trace off 676 669 self.fsetVal('0', 'tracing_on') 677 670 self.cleanupFtrace() ··· 688 681 if self.bufsize > 0: 689 682 tgtsize = self.bufsize 690 683 elif self.usecallgraph or self.usedevsrc: 691 - tgtsize = min(self.memfree, 3*1024*1024) 684 + bmax = (1*1024*1024) if self.suspendmode == 'disk' else (3*1024*1024) 685 + tgtsize = min(self.memfree, bmax) 692 686 else: 693 687 tgtsize = 65536 694 688 while not self.fsetVal('%d' % (tgtsize / cpus), 'buffer_size_kb'): ··· 698 690 if tgtsize < 65536: 699 691 tgtsize = int(self.fgetVal('buffer_size_kb')) * cpus 700 692 break 701 - print 'Setting trace buffers to %d kB (%d kB per cpu)' % (tgtsize, tgtsize/cpus) 693 + pprint('Setting trace buffers to %d kB (%d kB per cpu)' % (tgtsize, tgtsize/cpus)) 702 694 # initialize the callgraph trace 703 695 if(self.usecallgraph): 704 696 # set trace type ··· 731 723 if self.usedevsrc: 732 724 for name in self.dev_tracefuncs: 733 725 self.defaultKprobe(name, self.dev_tracefuncs[name]) 734 - print('INITIALIZING KPROBES...') 726 + pprint('INITIALIZING KPROBES...') 735 727 self.addKprobes(self.verbose) 736 728 if(self.usetraceevents): 737 729 # turn trace events on ··· 854 846 def out(self, dev): 855 847 return '%s,%s,%d;' % (dev, self.altname, self.async) 856 848 def debug(self, dev): 857 - print '%s:\n\taltname = %s\n\t async = %s' % (dev, self.altname, self.async) 849 + pprint('%s:\n\taltname = %s\n\t async = %s' % (dev, self.altname, self.async)) 858 850 def altName(self, dev): 859 851 if not self.altname or self.altname == dev: 860 852 return dev ··· 1225 1217 self.tLow.append('%.0f'%(tL*1000)) 1226 1218 lp = phase 1227 1219 def getTimeValues(self): 1228 - if 'suspend_machine' in self.dmesg: 1229 - sktime = (self.dmesg['suspend_machine']['end'] - \ 1230 - self.tKernSus) * 1000 1231 - else: 1232 - sktime = (self.tSuspended - self.tKernSus) * 1000 1233 - if 'resume_machine' in self.dmesg: 1234 - rktime = (self.tKernRes - \ 1235 - self.dmesg['resume_machine']['start']) * 1000 1236 - else: 1237 - rktime = (self.tKernRes - self.tResumed) * 1000 1220 + sktime = (self.tSuspended - self.tKernSus) * 1000 1221 + rktime = (self.tKernRes - self.tResumed) * 1000 1238 1222 return (sktime, rktime) 1239 1223 def setPhase(self, phase, ktime, isbegin, order=-1): 1240 1224 if(isbegin): ··· 1379 1379 if(list[child]['par'] == devname): 1380 1380 devlist.append(child) 1381 1381 return devlist 1382 + def maxDeviceNameSize(self, phase): 1383 + size = 0 1384 + for name in self.dmesg[phase]['list']: 1385 + if len(name) > size: 1386 + size = len(name) 1387 + return size 1382 1388 def printDetails(self): 1383 1389 sysvals.vprint('Timeline Details:') 1384 1390 sysvals.vprint(' test start: %f' % self.start) 1385 1391 sysvals.vprint('kernel suspend start: %f' % self.tKernSus) 1392 + tS = tR = False 1386 1393 for phase in self.sortedPhases(): 1387 - dc = len(self.dmesg[phase]['list']) 1388 - sysvals.vprint(' %16s: %f - %f (%d devices)' % (phase, \ 1389 - self.dmesg[phase]['start'], self.dmesg[phase]['end'], dc)) 1394 + devlist = self.dmesg[phase]['list'] 1395 + dc, ps, pe = len(devlist), self.dmesg[phase]['start'], self.dmesg[phase]['end'] 1396 + if not tS and ps >= self.tSuspended: 1397 + sysvals.vprint(' machine suspended: %f' % self.tSuspended) 1398 + tS = True 1399 + if not tR and ps >= self.tResumed: 1400 + sysvals.vprint(' machine resumed: %f' % self.tResumed) 1401 + tR = True 1402 + sysvals.vprint('%20s: %f - %f (%d devices)' % (phase, ps, pe, dc)) 1403 + if sysvals.devdump: 1404 + sysvals.vprint(''.join('-' for i in range(80))) 1405 + maxname = '%d' % self.maxDeviceNameSize(phase) 1406 + fmt = '%3d) %'+maxname+'s - %f - %f' 1407 + c = 1 1408 + for name in devlist: 1409 + s = devlist[name]['start'] 1410 + e = devlist[name]['end'] 1411 + sysvals.vprint(fmt % (c, name, s, e)) 1412 + c += 1 1413 + sysvals.vprint(''.join('-' for i in range(80))) 1390 1414 sysvals.vprint(' kernel resume end: %f' % self.tKernRes) 1391 1415 sysvals.vprint(' test end: %f' % self.end) 1392 1416 def deviceChildrenAllPhases(self, devname): ··· 1745 1721 return len(str)/2 1746 1722 def debugPrint(self, info=''): 1747 1723 if self.isLeaf(): 1748 - print(' -- %12.6f (depth=%02d): %s(); (%.3f us) %s' % (self.time, \ 1724 + pprint(' -- %12.6f (depth=%02d): %s(); (%.3f us) %s' % (self.time, \ 1749 1725 self.depth, self.name, self.length*1000000, info)) 1750 1726 elif self.freturn: 1751 - print(' -- %12.6f (depth=%02d): %s} (%.3f us) %s' % (self.time, \ 1727 + pprint(' -- %12.6f (depth=%02d): %s} (%.3f us) %s' % (self.time, \ 1752 1728 self.depth, self.name, self.length*1000000, info)) 1753 1729 else: 1754 - print(' -- %12.6f (depth=%02d): %s() { (%.3f us) %s' % (self.time, \ 1730 + pprint(' -- %12.6f (depth=%02d): %s() { (%.3f us) %s' % (self.time, \ 1755 1731 self.depth, self.name, self.length*1000000, info)) 1756 1732 def startMarker(self): 1757 1733 # Is this the starting line of a suspend? ··· 1892 1868 if warning and ('[make leaf]', line) not in info: 1893 1869 info.append(('', line)) 1894 1870 if warning: 1895 - print 'WARNING: ftrace data missing, corrections made:' 1871 + pprint('WARNING: ftrace data missing, corrections made:') 1896 1872 for i in info: 1897 1873 t, obj = i 1898 1874 if obj: ··· 1952 1928 id = 'task %s' % (self.pid) 1953 1929 window = '(%f - %f)' % (self.start, line.time) 1954 1930 if(self.depth < 0): 1955 - print('Data misalignment for '+id+\ 1931 + pprint('Data misalignment for '+id+\ 1956 1932 ' (buffer overflow), ignoring this callback') 1957 1933 else: 1958 - print('Too much data for '+id+\ 1934 + pprint('Too much data for '+id+\ 1959 1935 ' '+window+', ignoring this callback') 1960 1936 def slice(self, dev): 1961 1937 minicg = FTraceCallGraph(dev['pid'], self.sv) ··· 2008 1984 elif l.isReturn(): 2009 1985 if(l.depth not in stack): 2010 1986 if self.sv.verbose: 2011 - print 'Post Process Error: Depth missing' 1987 + pprint('Post Process Error: Depth missing') 2012 1988 l.debugPrint() 2013 1989 return False 2014 1990 # calculate call length from call/return lines ··· 2025 2001 return True 2026 2002 elif(cnt < 0): 2027 2003 if self.sv.verbose: 2028 - print 'Post Process Error: Depth is less than 0' 2004 + pprint('Post Process Error: Depth is less than 0') 2029 2005 return False 2030 2006 # trace ended before call tree finished 2031 2007 return self.repair(cnt) ··· 2084 2060 phase, myname = out 2085 2061 data.dmesg[phase]['list'][myname]['ftrace'] = self 2086 2062 def debugPrint(self, info=''): 2087 - print('%s pid=%d [%f - %f] %.3f us') % \ 2063 + pprint('%s pid=%d [%f - %f] %.3f us' % \ 2088 2064 (self.name, self.pid, self.start, self.end, 2089 - (self.end - self.start)*1000000) 2065 + (self.end - self.start)*1000000)) 2090 2066 for l in self.list: 2091 2067 if l.isLeaf(): 2092 - print('%f (%02d): %s(); (%.3f us)%s' % (l.time, \ 2068 + pprint('%f (%02d): %s(); (%.3f us)%s' % (l.time, \ 2093 2069 l.depth, l.name, l.length*1000000, info)) 2094 2070 elif l.freturn: 2095 - print('%f (%02d): %s} (%.3f us)%s' % (l.time, \ 2071 + pprint('%f (%02d): %s} (%.3f us)%s' % (l.time, \ 2096 2072 l.depth, l.name, l.length*1000000, info)) 2097 2073 else: 2098 - print('%f (%02d): %s() { (%.3f us)%s' % (l.time, \ 2074 + pprint('%f (%02d): %s() { (%.3f us)%s' % (l.time, \ 2099 2075 l.depth, l.name, l.length*1000000, info)) 2100 - print(' ') 2076 + pprint(' ') 2101 2077 2102 2078 class DevItem: 2103 2079 def __init__(self, test, phase, dev): ··· 2682 2658 doError('%s does not exist' % sysvals.ftracefile) 2683 2659 if not live: 2684 2660 sysvals.setupAllKprobes() 2685 - krescalls = ['pm_notifier_call_chain', 'pm_restore_console'] 2661 + ksuscalls = ['pm_prepare_console'] 2662 + krescalls = ['pm_restore_console'] 2686 2663 tracewatch = [] 2687 2664 if sysvals.usekprobes: 2688 2665 tracewatch += ['sync_filesystems', 'freeze_processes', 'syscore_suspend', ··· 2763 2738 testruns.append(testrun) 2764 2739 tp.parseStamp(data, sysvals) 2765 2740 data.setStart(t.time) 2741 + data.first_suspend_prepare = True 2766 2742 phase = data.setPhase('suspend_prepare', t.time, True) 2767 2743 continue 2768 2744 if(not data): ··· 2823 2797 continue 2824 2798 # suspend_prepare start 2825 2799 elif(re.match('dpm_prepare\[.*', t.name)): 2826 - phase = 'suspend_prepare' 2827 - if not isbegin: 2828 - data.setPhase(phase, t.time, isbegin) 2829 - if isbegin and data.tKernSus == 0: 2830 - data.tKernSus = t.time 2800 + if isbegin and data.first_suspend_prepare: 2801 + data.first_suspend_prepare = False 2802 + if data.tKernSus == 0: 2803 + data.tKernSus = t.time 2804 + continue 2805 + phase = data.setPhase('suspend_prepare', t.time, isbegin) 2831 2806 continue 2832 2807 # suspend start 2833 2808 elif(re.match('dpm_suspend\[.*', t.name)): ··· 2853 2826 else: 2854 2827 phase = data.setPhase('resume_machine', t.time, True) 2855 2828 if(sysvals.suspendmode in ['mem', 'disk']): 2856 - if 'suspend_machine' in data.dmesg: 2857 - data.dmesg['suspend_machine']['end'] = t.time 2829 + susp = phase.replace('resume', 'suspend') 2830 + if susp in data.dmesg: 2831 + data.dmesg[susp]['end'] = t.time 2858 2832 data.tSuspended = t.time 2859 - if data.tResumed == 0: 2860 - data.tResumed = t.time 2833 + data.tResumed = t.time 2861 2834 continue 2862 2835 # resume_noirq start 2863 2836 elif(re.match('dpm_resume_noirq\[.*', t.name)): ··· 2938 2911 'cdata': kprobedata, 2939 2912 'proc': m_proc, 2940 2913 }) 2914 + # start of kernel resume 2915 + if(phase == 'suspend_prepare' and kprobename in ksuscalls): 2916 + data.tKernSus = t.time 2941 2917 elif(t.freturn): 2942 2918 if(key not in tp.ktemp) or len(tp.ktemp[key]) < 1: 2943 2919 continue ··· 2991 2961 # dev source and procmon events can be unreadable with mixed phase height 2992 2962 if sysvals.usedevsrc or sysvals.useprocmon: 2993 2963 sysvals.mixedphaseheight = False 2964 + 2965 + # expand phase boundaries so there are no gaps 2966 + for data in testdata: 2967 + lp = data.sortedPhases()[0] 2968 + for p in data.sortedPhases(): 2969 + if(p != lp and not ('machine' in p and 'machine' in lp)): 2970 + data.dmesg[lp]['end'] = data.dmesg[p]['start'] 2971 + lp = p 2994 2972 2995 2973 for i in range(len(testruns)): 2996 2974 test = testruns[i] ··· 3082 3044 for p in sorted(phasedef, key=lambda k:phasedef[k]['order']): 3083 3045 if p not in data.dmesg: 3084 3046 if not terr: 3085 - print 'TEST%s FAILED: %s failed in %s phase' % (tn, sysvals.suspendmode, lp) 3047 + pprint('TEST%s FAILED: %s failed in %s phase' % (tn, sysvals.suspendmode, lp)) 3086 3048 terr = '%s%s failed in %s phase' % (sysvals.suspendmode, tn, lp) 3087 3049 error.append(terr) 3088 3050 if data.tSuspended == 0: ··· 3093 3055 sysvals.vprint('WARNING: phase "%s" is missing!' % p) 3094 3056 lp = p 3095 3057 if not terr and data.enterfail: 3096 - print 'test%s FAILED: enter %s failed with %s' % (tn, sysvals.suspendmode, data.enterfail) 3058 + pprint('test%s FAILED: enter %s failed with %s' % (tn, sysvals.suspendmode, data.enterfail)) 3097 3059 terr = 'test%s failed to enter %s mode' % (tn, sysvals.suspendmode) 3098 3060 error.append(terr) 3099 - lp = data.sortedPhases()[0] 3100 - for p in data.sortedPhases(): 3101 - if(p != lp and not ('machine' in p and 'machine' in lp)): 3102 - data.dmesg[lp]['end'] = data.dmesg[p]['start'] 3103 - lp = p 3104 3061 if data.tSuspended == 0: 3105 3062 data.tSuspended = data.tKernRes 3106 3063 if data.tResumed == 0: ··· 3184 3151 if data: 3185 3152 testruns.append(data) 3186 3153 if len(testruns) < 1: 3187 - print('ERROR: dmesg log has no suspend/resume data: %s' \ 3154 + pprint('ERROR: dmesg log has no suspend/resume data: %s' \ 3188 3155 % sysvals.dmesgfile) 3189 3156 3190 3157 # fix lines with same timestamp/function with the call and return swapped ··· 3438 3405 for p in sorted(phasedef, key=lambda k:phasedef[k]['order']): 3439 3406 if p not in data.dmesg: 3440 3407 if not terr: 3441 - print 'TEST FAILED: %s failed in %s phase' % (sysvals.suspendmode, lp) 3408 + pprint('TEST FAILED: %s failed in %s phase' % (sysvals.suspendmode, lp)) 3442 3409 terr = '%s failed in %s phase' % (sysvals.suspendmode, lp) 3443 3410 if data.tSuspended == 0: 3444 3411 data.tSuspended = data.dmesg[lp]['end'] ··· 3536 3503 # Create summary html file for a series of tests 3537 3504 # Arguments: 3538 3505 # testruns: array of Data objects from parseTraceLog 3539 - def createHTMLSummarySimple(testruns, htmlfile, folder): 3506 + def createHTMLSummarySimple(testruns, htmlfile, title): 3540 3507 # write the html header first (html head, css code, up to body start) 3541 3508 html = '<!DOCTYPE html>\n<html>\n<head>\n\ 3542 3509 <meta http-equiv="content-type" content="text/html; charset=UTF-8">\n\ ··· 3616 3583 for ilk in sorted(cnt, reverse=True): 3617 3584 if cnt[ilk] > 0: 3618 3585 desc.append('%d %s' % (cnt[ilk], ilk)) 3619 - html += '<div class="stamp">%s (%d tests: %s)</div>\n' % (folder, len(testruns), ', '.join(desc)) 3586 + html += '<div class="stamp">%s (%d tests: %s)</div>\n' % (title, len(testruns), ', '.join(desc)) 3620 3587 th = '\t<th>{0}</th>\n' 3621 3588 td = '\t<td>{0}</td>\n' 3622 3589 tdh = '\t<td{1}>{0}</td>\n' ··· 3718 3685 # True if the html file was created, false if it failed 3719 3686 def createHTML(testruns, testfail): 3720 3687 if len(testruns) < 1: 3721 - print('ERROR: Not enough test data to build a timeline') 3688 + pprint('ERROR: Not enough test data to build a timeline') 3722 3689 return 3723 3690 3724 3691 kerror = False ··· 4568 4535 sv.rstgt, sv.rsval, sv.rsdir = 'on', 'auto', 'enabled' 4569 4536 else: 4570 4537 sv.rstgt, sv.rsval, sv.rsdir = 'auto', 'on', 'disabled' 4571 - print('CONFIGURING RUNTIME SUSPEND...') 4538 + pprint('CONFIGURING RUNTIME SUSPEND...') 4572 4539 sv.rslist = deviceInfo(sv.rstgt) 4573 4540 for i in sv.rslist: 4574 4541 sv.setVal(sv.rsval, i) 4575 - print('runtime suspend %s on all devices (%d changed)' % (sv.rsdir, len(sv.rslist))) 4576 - print('waiting 5 seconds...') 4542 + pprint('runtime suspend %s on all devices (%d changed)' % (sv.rsdir, len(sv.rslist))) 4543 + pprint('waiting 5 seconds...') 4577 4544 time.sleep(5) 4578 4545 else: 4579 4546 # runtime suspend re-enable or re-disable 4580 4547 for i in sv.rslist: 4581 4548 sv.setVal(sv.rstgt, i) 4582 - print('runtime suspend settings restored on %d devices' % len(sv.rslist)) 4549 + pprint('runtime suspend settings restored on %d devices' % len(sv.rslist)) 4583 4550 4584 4551 # Function: executeSuspend 4585 4552 # Description: ··· 4592 4559 battery = True if getBattery() else False 4593 4560 # run these commands to prepare the system for suspend 4594 4561 if sysvals.display: 4595 - print('SET DISPLAY TO %s' % sysvals.display.upper()) 4562 + pprint('SET DISPLAY TO %s' % sysvals.display.upper()) 4596 4563 displayControl(sysvals.display) 4597 4564 time.sleep(1) 4598 4565 if sysvals.sync: 4599 - print('SYNCING FILESYSTEMS') 4566 + pprint('SYNCING FILESYSTEMS') 4600 4567 call('sync', shell=True) 4601 4568 # mark the start point in the kernel ring buffer just as we start 4602 4569 sysvals.initdmesg() 4603 4570 # start ftrace 4604 4571 if(sysvals.usecallgraph or sysvals.usetraceevents): 4605 - print('START TRACING') 4572 + pprint('START TRACING') 4606 4573 sysvals.fsetVal('1', 'tracing_on') 4607 4574 if sysvals.useprocmon: 4608 4575 pm.start() ··· 4615 4582 sysvals.fsetVal('WAIT END', 'trace_marker') 4616 4583 # start message 4617 4584 if sysvals.testcommand != '': 4618 - print('COMMAND START') 4585 + pprint('COMMAND START') 4619 4586 else: 4620 4587 if(sysvals.rtcwake): 4621 - print('SUSPEND START') 4588 + pprint('SUSPEND START') 4622 4589 else: 4623 - print('SUSPEND START (press a key to resume)') 4590 + pprint('SUSPEND START (press a key to resume)') 4624 4591 bat1 = getBattery() if battery else False 4625 4592 # set rtcwake 4626 4593 if(sysvals.rtcwake): 4627 - print('will issue an rtcwake in %d seconds' % sysvals.rtcwaketime) 4594 + pprint('will issue an rtcwake in %d seconds' % sysvals.rtcwaketime) 4628 4595 sysvals.rtcWakeAlarmOn() 4629 4596 # start of suspend trace marker 4630 4597 if(sysvals.usecallgraph or sysvals.usetraceevents): ··· 4647 4614 pf = open(sysvals.mempowerfile, 'w') 4648 4615 pf.write(sysvals.memmode) 4649 4616 pf.close() 4617 + if sysvals.diskmode and os.path.exists(sysvals.diskpowerfile): 4618 + mode = 'disk' 4619 + pf = open(sysvals.diskpowerfile, 'w') 4620 + pf.write(sysvals.diskmode) 4621 + pf.close() 4650 4622 pf = open(sysvals.powerfile, 'w') 4651 4623 pf.write(mode) 4652 4624 # execution will pause here ··· 4667 4629 time.sleep(sysvals.postdelay/1000.0) 4668 4630 sysvals.fsetVal('WAIT END', 'trace_marker') 4669 4631 # return from suspend 4670 - print('RESUME COMPLETE') 4632 + pprint('RESUME COMPLETE') 4671 4633 if(sysvals.usecallgraph or sysvals.usetraceevents): 4672 4634 sysvals.fsetVal('RESUME COMPLETE', 'trace_marker') 4673 4635 if(sysvals.suspendmode == 'mem' or sysvals.suspendmode == 'command'): ··· 4682 4644 pm.stop() 4683 4645 sysvals.fsetVal('0', 'tracing_on') 4684 4646 # grab a copy of the dmesg output 4685 - print('CAPTURING DMESG') 4647 + pprint('CAPTURING DMESG') 4686 4648 sysvals.getdmesg(testdata) 4687 4649 # grab a copy of the ftrace output 4688 4650 if(sysvals.usecallgraph or sysvals.usetraceevents): 4689 - print('CAPTURING TRACE') 4651 + pprint('CAPTURING TRACE') 4690 4652 op = sysvals.writeDatafileHeader(sysvals.ftracefile, testdata) 4691 4653 fp = open(tp+'trace', 'r') 4692 4654 for line in fp: ··· 4730 4692 # a list of USB device names to sysvals for better timeline readability 4731 4693 def deviceInfo(output=''): 4732 4694 if not output: 4733 - print('LEGEND') 4734 - print('---------------------------------------------------------------------------------------------') 4735 - print(' A = async/sync PM queue (A/S) C = runtime active children') 4736 - print(' R = runtime suspend enabled/disabled (E/D) rACTIVE = runtime active (min/sec)') 4737 - print(' S = runtime status active/suspended (A/S) rSUSPEND = runtime suspend (min/sec)') 4738 - print(' U = runtime usage count') 4739 - print('---------------------------------------------------------------------------------------------') 4740 - print('DEVICE NAME A R S U C rACTIVE rSUSPEND') 4741 - print('---------------------------------------------------------------------------------------------') 4695 + pprint('LEGEND\n'\ 4696 + '---------------------------------------------------------------------------------------------\n'\ 4697 + ' A = async/sync PM queue (A/S) C = runtime active children\n'\ 4698 + ' R = runtime suspend enabled/disabled (E/D) rACTIVE = runtime active (min/sec)\n'\ 4699 + ' S = runtime status active/suspended (A/S) rSUSPEND = runtime suspend (min/sec)\n'\ 4700 + ' U = runtime usage count\n'\ 4701 + '---------------------------------------------------------------------------------------------\n'\ 4702 + 'DEVICE NAME A R S U C rACTIVE rSUSPEND\n'\ 4703 + '---------------------------------------------------------------------------------------------') 4742 4704 4743 4705 res = [] 4744 4706 tgtval = 'runtime_status' ··· 4927 4889 fp.close() 4928 4890 if 'mem' in modes and not deep: 4929 4891 modes.remove('mem') 4892 + if('disk' in modes and os.path.exists(sysvals.diskpowerfile)): 4893 + fp = open(sysvals.diskpowerfile, 'r') 4894 + for m in string.split(fp.read()): 4895 + modes.append('disk-%s' % m.strip('[]')) 4896 + fp.close() 4930 4897 return modes 4931 4898 4932 4899 # Function: dmidecode ··· 5080 5037 xset = 'sudo -u %s %s' % (sysvals.sudouser, xset) 5081 5038 if cmd == 'init': 5082 5039 ret = call(xset.format('dpms 0 0 0'), shell=True) 5083 - ret = call(xset.format('s off'), shell=True) 5040 + if not ret: 5041 + ret = call(xset.format('s off'), shell=True) 5084 5042 elif cmd == 'reset': 5085 5043 ret = call(xset.format('s reset'), shell=True) 5086 5044 elif cmd in ['on', 'off', 'standby', 'suspend']: 5087 5045 b4 = displayControl('stat') 5088 5046 ret = call(xset.format('dpms force %s' % cmd), shell=True) 5089 - curr = displayControl('stat') 5090 - sysvals.vprint('Display Switched: %s -> %s' % (b4, curr)) 5091 - if curr != cmd: 5092 - sysvals.vprint('WARNING: Display failed to change to %s' % cmd) 5047 + if not ret: 5048 + curr = displayControl('stat') 5049 + sysvals.vprint('Display Switched: %s -> %s' % (b4, curr)) 5050 + if curr != cmd: 5051 + sysvals.vprint('WARNING: Display failed to change to %s' % cmd) 5052 + if ret: 5053 + sysvals.vprint('WARNING: Display failed to change to %s with xset' % cmd) 5054 + return ret 5093 5055 elif cmd == 'stat': 5094 5056 fp = Popen(xset.format('q').split(' '), stdout=PIPE).stdout 5095 5057 ret = 'unknown' ··· 5150 5102 5151 5103 table = struct.unpack('4sIBB6s8sI4sI', buf[0:36]) 5152 5104 if(output): 5153 - print('') 5154 - print('Firmware Performance Data Table (%s)' % table[0]) 5155 - print(' Signature : %s' % table[0]) 5156 - print(' Table Length : %u' % table[1]) 5157 - print(' Revision : %u' % table[2]) 5158 - print(' Checksum : 0x%x' % table[3]) 5159 - print(' OEM ID : %s' % table[4]) 5160 - print(' OEM Table ID : %s' % table[5]) 5161 - print(' OEM Revision : %u' % table[6]) 5162 - print(' Creator ID : %s' % table[7]) 5163 - print(' Creator Revision : 0x%x' % table[8]) 5164 - print('') 5105 + pprint('\n'\ 5106 + 'Firmware Performance Data Table (%s)\n'\ 5107 + ' Signature : %s\n'\ 5108 + ' Table Length : %u\n'\ 5109 + ' Revision : %u\n'\ 5110 + ' Checksum : 0x%x\n'\ 5111 + ' OEM ID : %s\n'\ 5112 + ' OEM Table ID : %s\n'\ 5113 + ' OEM Revision : %u\n'\ 5114 + ' Creator ID : %s\n'\ 5115 + ' Creator Revision : 0x%x\n'\ 5116 + '' % (table[0], table[0], table[1], table[2], table[3], 5117 + table[4], table[5], table[6], table[7], table[8])) 5165 5118 5166 5119 if(table[0] != 'FPDT'): 5167 5120 if(output): ··· 5188 5139 first = fp.read(8) 5189 5140 except: 5190 5141 if(output): 5191 - print('Bad address 0x%x in %s' % (addr, sysvals.mempath)) 5142 + pprint('Bad address 0x%x in %s' % (addr, sysvals.mempath)) 5192 5143 return [0, 0] 5193 5144 rechead = struct.unpack('4sI', first) 5194 5145 recdata = fp.read(rechead[1]-8) 5195 5146 if(rechead[0] == 'FBPT'): 5196 5147 record = struct.unpack('HBBIQQQQQ', recdata) 5197 5148 if(output): 5198 - print('%s (%s)' % (rectype[header[0]], rechead[0])) 5199 - print(' Reset END : %u ns' % record[4]) 5200 - print(' OS Loader LoadImage Start : %u ns' % record[5]) 5201 - print(' OS Loader StartImage Start : %u ns' % record[6]) 5202 - print(' ExitBootServices Entry : %u ns' % record[7]) 5203 - print(' ExitBootServices Exit : %u ns' % record[8]) 5149 + pprint('%s (%s)\n'\ 5150 + ' Reset END : %u ns\n'\ 5151 + ' OS Loader LoadImage Start : %u ns\n'\ 5152 + ' OS Loader StartImage Start : %u ns\n'\ 5153 + ' ExitBootServices Entry : %u ns\n'\ 5154 + ' ExitBootServices Exit : %u ns'\ 5155 + '' % (rectype[header[0]], rechead[0], record[4], record[5], 5156 + record[6], record[7], record[8])) 5204 5157 elif(rechead[0] == 'S3PT'): 5205 5158 if(output): 5206 - print('%s (%s)' % (rectype[header[0]], rechead[0])) 5159 + pprint('%s (%s)' % (rectype[header[0]], rechead[0])) 5207 5160 j = 0 5208 5161 while(j < len(recdata)): 5209 5162 prechead = struct.unpack('HBB', recdata[j:j+4]) ··· 5215 5164 record = struct.unpack('IIQQ', recdata[j:j+prechead[1]]) 5216 5165 fwData[1] = record[2] 5217 5166 if(output): 5218 - print(' %s' % prectype[prechead[0]]) 5219 - print(' Resume Count : %u' % \ 5220 - record[1]) 5221 - print(' FullResume : %u ns' % \ 5222 - record[2]) 5223 - print(' AverageResume : %u ns' % \ 5224 - record[3]) 5167 + pprint(' %s\n'\ 5168 + ' Resume Count : %u\n'\ 5169 + ' FullResume : %u ns\n'\ 5170 + ' AverageResume : %u ns'\ 5171 + '' % (prectype[prechead[0]], record[1], 5172 + record[2], record[3])) 5225 5173 elif(prechead[0] == 1): 5226 5174 record = struct.unpack('QQ', recdata[j+4:j+prechead[1]]) 5227 5175 fwData[0] = record[1] - record[0] 5228 5176 if(output): 5229 - print(' %s' % prectype[prechead[0]]) 5230 - print(' SuspendStart : %u ns' % \ 5231 - record[0]) 5232 - print(' SuspendEnd : %u ns' % \ 5233 - record[1]) 5234 - print(' SuspendTime : %u ns' % \ 5235 - fwData[0]) 5177 + pprint(' %s\n'\ 5178 + ' SuspendStart : %u ns\n'\ 5179 + ' SuspendEnd : %u ns\n'\ 5180 + ' SuspendTime : %u ns'\ 5181 + '' % (prectype[prechead[0]], record[0], 5182 + record[1], fwData[0])) 5183 + 5236 5184 j += prechead[1] 5237 5185 if(output): 5238 - print('') 5186 + pprint('') 5239 5187 i += header[1] 5240 5188 fp.close() 5241 5189 return fwData ··· 5248 5198 def statusCheck(probecheck=False): 5249 5199 status = '' 5250 5200 5251 - print('Checking this system (%s)...' % platform.node()) 5201 + pprint('Checking this system (%s)...' % platform.node()) 5252 5202 5253 5203 # check we have root access 5254 5204 res = sysvals.colorText('NO (No features of this tool will work!)') 5255 5205 if(sysvals.rootCheck(False)): 5256 5206 res = 'YES' 5257 - print(' have root access: %s' % res) 5207 + pprint(' have root access: %s' % res) 5258 5208 if(res != 'YES'): 5259 - print(' Try running this script with sudo') 5209 + pprint(' Try running this script with sudo') 5260 5210 return 'missing root access' 5261 5211 5262 5212 # check sysfs is mounted 5263 5213 res = sysvals.colorText('NO (No features of this tool will work!)') 5264 5214 if(os.path.exists(sysvals.powerfile)): 5265 5215 res = 'YES' 5266 - print(' is sysfs mounted: %s' % res) 5216 + pprint(' is sysfs mounted: %s' % res) 5267 5217 if(res != 'YES'): 5268 5218 return 'sysfs is missing' 5269 5219 ··· 5275 5225 res = 'YES' 5276 5226 else: 5277 5227 status = '%s mode is not supported' % sysvals.suspendmode 5278 - print(' is "%s" a valid power mode: %s' % (sysvals.suspendmode, res)) 5228 + pprint(' is "%s" a valid power mode: %s' % (sysvals.suspendmode, res)) 5279 5229 if(res == 'NO'): 5280 - print(' valid power modes are: %s' % modes) 5281 - print(' please choose one with -m') 5230 + pprint(' valid power modes are: %s' % modes) 5231 + pprint(' please choose one with -m') 5282 5232 5283 5233 # check if ftrace is available 5284 5234 res = sysvals.colorText('NO') ··· 5287 5237 res = 'YES' 5288 5238 elif(sysvals.usecallgraph): 5289 5239 status = 'ftrace is not properly supported' 5290 - print(' is ftrace supported: %s' % res) 5240 + pprint(' is ftrace supported: %s' % res) 5291 5241 5292 5242 # check if kprobes are available 5293 5243 res = sysvals.colorText('NO') ··· 5296 5246 res = 'YES' 5297 5247 else: 5298 5248 sysvals.usedevsrc = False 5299 - print(' are kprobes supported: %s' % res) 5249 + pprint(' are kprobes supported: %s' % res) 5300 5250 5301 5251 # what data source are we using 5302 5252 res = 'DMESG' ··· 5307 5257 sysvals.usetraceevents = False 5308 5258 if(sysvals.usetraceevents): 5309 5259 res = 'FTRACE (all trace events found)' 5310 - print(' timeline data source: %s' % res) 5260 + pprint(' timeline data source: %s' % res) 5311 5261 5312 5262 # check if rtcwake 5313 5263 res = sysvals.colorText('NO') ··· 5315 5265 res = 'YES' 5316 5266 elif(sysvals.rtcwake): 5317 5267 status = 'rtcwake is not properly supported' 5318 - print(' is rtcwake supported: %s' % res) 5268 + pprint(' is rtcwake supported: %s' % res) 5319 5269 5320 5270 if not probecheck: 5321 5271 return status ··· 5340 5290 def doError(msg, help=False): 5341 5291 if(help == True): 5342 5292 printHelp() 5343 - print('ERROR: %s\n') % msg 5293 + pprint('ERROR: %s\n' % msg) 5344 5294 sysvals.outputResult({'error':msg}) 5345 5295 sys.exit(1) 5346 5296 ··· 5383 5333 return val 5384 5334 5385 5335 def processData(live=False): 5386 - print('PROCESSING DATA') 5336 + pprint('PROCESSING DATA') 5387 5337 error = '' 5388 5338 if(sysvals.usetraceevents): 5389 5339 testruns, error = parseTraceLog(live) ··· 5409 5359 data.debugPrint() 5410 5360 sys.exit(0) 5411 5361 if len(testruns) < 1: 5362 + pprint('ERROR: Not enough test data to build a timeline') 5412 5363 return (testruns, {'error': 'timeline generation failed'}) 5413 5364 sysvals.vprint('Creating the html timeline (%s)...' % sysvals.htmlfile) 5414 5365 createHTML(testruns, error) 5415 - print('DONE') 5366 + pprint('DONE') 5416 5367 data = testruns[0] 5417 5368 stamp = data.stamp 5418 5369 stamp['suspend'], stamp['resume'] = data.getTimeValues() ··· 5567 5516 def runSummary(subdir, local=True, genhtml=False): 5568 5517 inpath = os.path.abspath(subdir) 5569 5518 outpath = os.path.abspath('.') if local else inpath 5570 - print('Generating a summary of folder "%s"' % inpath) 5519 + pprint('Generating a summary of folder "%s"' % inpath) 5571 5520 if genhtml: 5572 5521 for dirname, dirnames, filenames in os.walk(subdir): 5573 5522 sysvals.dmesgfile = sysvals.ftracefile = sysvals.htmlfile = '' ··· 5579 5528 sysvals.setOutputFile() 5580 5529 if sysvals.ftracefile and sysvals.htmlfile and \ 5581 5530 not os.path.exists(sysvals.htmlfile): 5582 - print('FTRACE: %s' % sysvals.ftracefile) 5531 + pprint('FTRACE: %s' % sysvals.ftracefile) 5583 5532 if sysvals.dmesgfile: 5584 - print('DMESG : %s' % sysvals.dmesgfile) 5533 + pprint('DMESG : %s' % sysvals.dmesgfile) 5585 5534 rerunTest() 5586 5535 testruns = [] 5536 + desc = {'host':[],'mode':[],'kernel':[]} 5587 5537 for dirname, dirnames, filenames in os.walk(subdir): 5588 5538 for filename in filenames: 5589 5539 if(not re.match('.*.html', filename)): ··· 5593 5541 if(not data): 5594 5542 continue 5595 5543 testruns.append(data) 5544 + for key in desc: 5545 + if data[key] not in desc[key]: 5546 + desc[key].append(data[key]) 5596 5547 outfile = os.path.join(outpath, 'summary.html') 5597 - print('Summary file: %s' % outfile) 5598 - createHTMLSummarySimple(testruns, outfile, inpath) 5548 + pprint('Summary file: %s' % outfile) 5549 + if len(desc['host']) == len(desc['mode']) == len(desc['kernel']) == 1: 5550 + title = '%s %s %s' % (desc['host'][0], desc['kernel'][0], desc['mode'][0]) 5551 + else: 5552 + title = inpath 5553 + createHTMLSummarySimple(testruns, outfile, title) 5599 5554 5600 5555 # Function: checkArgBool 5601 5556 # Description: ··· 5817 5758 # Description: 5818 5759 # print out the help text 5819 5760 def printHelp(): 5820 - print('') 5821 - print('%s v%s' % (sysvals.title, sysvals.version)) 5822 - print('Usage: sudo sleepgraph <options> <commands>') 5823 - print('') 5824 - print('Description:') 5825 - print(' This tool is designed to assist kernel and OS developers in optimizing') 5826 - print(' their linux stack\'s suspend/resume time. Using a kernel image built') 5827 - print(' with a few extra options enabled, the tool will execute a suspend and') 5828 - print(' capture dmesg and ftrace data until resume is complete. This data is') 5829 - print(' transformed into a device timeline and an optional callgraph to give') 5830 - print(' a detailed view of which devices/subsystems are taking the most') 5831 - print(' time in suspend/resume.') 5832 - print('') 5833 - print(' If no specific command is given, the default behavior is to initiate') 5834 - print(' a suspend/resume and capture the dmesg/ftrace output as an html timeline.') 5835 - print('') 5836 - print(' Generates output files in subdirectory: suspend-yymmdd-HHMMSS') 5837 - print(' HTML output: <hostname>_<mode>.html') 5838 - print(' raw dmesg output: <hostname>_<mode>_dmesg.txt') 5839 - print(' raw ftrace output: <hostname>_<mode>_ftrace.txt') 5840 - print('') 5841 - print('Options:') 5842 - print(' -h Print this help text') 5843 - print(' -v Print the current tool version') 5844 - print(' -config fn Pull arguments and config options from file fn') 5845 - print(' -verbose Print extra information during execution and analysis') 5846 - print(' -m mode Mode to initiate for suspend (default: %s)') % (sysvals.suspendmode) 5847 - print(' -o name Overrides the output subdirectory name when running a new test') 5848 - print(' default: suspend-{date}-{time}') 5849 - print(' -rtcwake t Wakeup t seconds after suspend, set t to "off" to disable (default: 15)') 5850 - print(' -addlogs Add the dmesg and ftrace logs to the html output') 5851 - print(' -srgap Add a visible gap in the timeline between sus/res (default: disabled)') 5852 - print(' -skiphtml Run the test and capture the trace logs, but skip the timeline (default: disabled)') 5853 - print(' -result fn Export a results table to a text file for parsing.') 5854 - print(' [testprep]') 5855 - print(' -sync Sync the filesystems before starting the test') 5856 - print(' -rs on/off Enable/disable runtime suspend for all devices, restore all after test') 5857 - print(' -display m Change the display mode to m for the test (on/off/standby/suspend)') 5858 - print(' [advanced]') 5859 - print(' -gzip Gzip the trace and dmesg logs to save space') 5860 - print(' -cmd {s} Run the timeline over a custom command, e.g. "sync -d"') 5861 - print(' -proc Add usermode process info into the timeline (default: disabled)') 5862 - print(' -dev Add kernel function calls and threads to the timeline (default: disabled)') 5863 - print(' -x2 Run two suspend/resumes back to back (default: disabled)') 5864 - print(' -x2delay t Include t ms delay between multiple test runs (default: 0 ms)') 5865 - print(' -predelay t Include t ms delay before 1st suspend (default: 0 ms)') 5866 - print(' -postdelay t Include t ms delay after last resume (default: 0 ms)') 5867 - print(' -mindev ms Discard all device blocks shorter than ms milliseconds (e.g. 0.001 for us)') 5868 - print(' -multi n d Execute <n> consecutive tests at <d> seconds intervals. The outputs will') 5869 - print(' be created in a new subdirectory with a summary page.') 5870 - print(' [debug]') 5871 - print(' -f Use ftrace to create device callgraphs (default: disabled)') 5872 - print(' -maxdepth N limit the callgraph data to N call levels (default: 0=all)') 5873 - print(' -expandcg pre-expand the callgraph data in the html output (default: disabled)') 5874 - print(' -fadd file Add functions to be graphed in the timeline from a list in a text file') 5875 - print(' -filter "d1,d2,..." Filter out all but this comma-delimited list of device names') 5876 - print(' -mincg ms Discard all callgraphs shorter than ms milliseconds (e.g. 0.001 for us)') 5877 - print(' -cgphase P Only show callgraph data for phase P (e.g. suspend_late)') 5878 - print(' -cgtest N Only show callgraph data for test N (e.g. 0 or 1 in an x2 run)') 5879 - print(' -timeprec N Number of significant digits in timestamps (0:S, [3:ms], 6:us)') 5880 - print(' -cgfilter S Filter the callgraph output in the timeline') 5881 - print(' -cgskip file Callgraph functions to skip, off to disable (default: cgskip.txt)') 5882 - print(' -bufsize N Set trace buffer size to N kilo-bytes (default: all of free memory)') 5883 - print('') 5884 - print('Other commands:') 5885 - print(' -modes List available suspend modes') 5886 - print(' -status Test to see if the system is enabled to run this tool') 5887 - print(' -fpdt Print out the contents of the ACPI Firmware Performance Data Table') 5888 - print(' -battery Print out battery info (if available)') 5889 - print(' -x<mode> Test xset by toggling the given mode (on/off/standby/suspend)') 5890 - print(' -sysinfo Print out system info extracted from BIOS') 5891 - print(' -devinfo Print out the pm settings of all devices which support runtime suspend') 5892 - print(' -flist Print the list of functions currently being captured in ftrace') 5893 - print(' -flistall Print all functions capable of being captured in ftrace') 5894 - print(' -summary dir Create a summary of tests in this dir [-genhtml builds missing html]') 5895 - print(' [redo]') 5896 - print(' -ftrace ftracefile Create HTML output using ftrace input (used with -dmesg)') 5897 - print(' -dmesg dmesgfile Create HTML output using dmesg (used with -ftrace)') 5898 - print('') 5761 + pprint('\n%s v%s\n'\ 5762 + 'Usage: sudo sleepgraph <options> <commands>\n'\ 5763 + '\n'\ 5764 + 'Description:\n'\ 5765 + ' This tool is designed to assist kernel and OS developers in optimizing\n'\ 5766 + ' their linux stack\'s suspend/resume time. Using a kernel image built\n'\ 5767 + ' with a few extra options enabled, the tool will execute a suspend and\n'\ 5768 + ' capture dmesg and ftrace data until resume is complete. This data is\n'\ 5769 + ' transformed into a device timeline and an optional callgraph to give\n'\ 5770 + ' a detailed view of which devices/subsystems are taking the most\n'\ 5771 + ' time in suspend/resume.\n'\ 5772 + '\n'\ 5773 + ' If no specific command is given, the default behavior is to initiate\n'\ 5774 + ' a suspend/resume and capture the dmesg/ftrace output as an html timeline.\n'\ 5775 + '\n'\ 5776 + ' Generates output files in subdirectory: suspend-yymmdd-HHMMSS\n'\ 5777 + ' HTML output: <hostname>_<mode>.html\n'\ 5778 + ' raw dmesg output: <hostname>_<mode>_dmesg.txt\n'\ 5779 + ' raw ftrace output: <hostname>_<mode>_ftrace.txt\n'\ 5780 + '\n'\ 5781 + 'Options:\n'\ 5782 + ' -h Print this help text\n'\ 5783 + ' -v Print the current tool version\n'\ 5784 + ' -config fn Pull arguments and config options from file fn\n'\ 5785 + ' -verbose Print extra information during execution and analysis\n'\ 5786 + ' -m mode Mode to initiate for suspend (default: %s)\n'\ 5787 + ' -o name Overrides the output subdirectory name when running a new test\n'\ 5788 + ' default: suspend-{date}-{time}\n'\ 5789 + ' -rtcwake t Wakeup t seconds after suspend, set t to "off" to disable (default: 15)\n'\ 5790 + ' -addlogs Add the dmesg and ftrace logs to the html output\n'\ 5791 + ' -srgap Add a visible gap in the timeline between sus/res (default: disabled)\n'\ 5792 + ' -skiphtml Run the test and capture the trace logs, but skip the timeline (default: disabled)\n'\ 5793 + ' -result fn Export a results table to a text file for parsing.\n'\ 5794 + ' [testprep]\n'\ 5795 + ' -sync Sync the filesystems before starting the test\n'\ 5796 + ' -rs on/off Enable/disable runtime suspend for all devices, restore all after test\n'\ 5797 + ' -display m Change the display mode to m for the test (on/off/standby/suspend)\n'\ 5798 + ' [advanced]\n'\ 5799 + ' -gzip Gzip the trace and dmesg logs to save space\n'\ 5800 + ' -cmd {s} Run the timeline over a custom command, e.g. "sync -d"\n'\ 5801 + ' -proc Add usermode process info into the timeline (default: disabled)\n'\ 5802 + ' -dev Add kernel function calls and threads to the timeline (default: disabled)\n'\ 5803 + ' -x2 Run two suspend/resumes back to back (default: disabled)\n'\ 5804 + ' -x2delay t Include t ms delay between multiple test runs (default: 0 ms)\n'\ 5805 + ' -predelay t Include t ms delay before 1st suspend (default: 0 ms)\n'\ 5806 + ' -postdelay t Include t ms delay after last resume (default: 0 ms)\n'\ 5807 + ' -mindev ms Discard all device blocks shorter than ms milliseconds (e.g. 0.001 for us)\n'\ 5808 + ' -multi n d Execute <n> consecutive tests at <d> seconds intervals. The outputs will\n'\ 5809 + ' be created in a new subdirectory with a summary page.\n'\ 5810 + ' [debug]\n'\ 5811 + ' -f Use ftrace to create device callgraphs (default: disabled)\n'\ 5812 + ' -maxdepth N limit the callgraph data to N call levels (default: 0=all)\n'\ 5813 + ' -expandcg pre-expand the callgraph data in the html output (default: disabled)\n'\ 5814 + ' -fadd file Add functions to be graphed in the timeline from a list in a text file\n'\ 5815 + ' -filter "d1,d2,..." Filter out all but this comma-delimited list of device names\n'\ 5816 + ' -mincg ms Discard all callgraphs shorter than ms milliseconds (e.g. 0.001 for us)\n'\ 5817 + ' -cgphase P Only show callgraph data for phase P (e.g. suspend_late)\n'\ 5818 + ' -cgtest N Only show callgraph data for test N (e.g. 0 or 1 in an x2 run)\n'\ 5819 + ' -timeprec N Number of significant digits in timestamps (0:S, [3:ms], 6:us)\n'\ 5820 + ' -cgfilter S Filter the callgraph output in the timeline\n'\ 5821 + ' -cgskip file Callgraph functions to skip, off to disable (default: cgskip.txt)\n'\ 5822 + ' -bufsize N Set trace buffer size to N kilo-bytes (default: all of free memory)\n'\ 5823 + ' -devdump Print out all the raw device data for each phase\n'\ 5824 + ' -cgdump Print out all the raw callgraph data\n'\ 5825 + '\n'\ 5826 + 'Other commands:\n'\ 5827 + ' -modes List available suspend modes\n'\ 5828 + ' -status Test to see if the system is enabled to run this tool\n'\ 5829 + ' -fpdt Print out the contents of the ACPI Firmware Performance Data Table\n'\ 5830 + ' -battery Print out battery info (if available)\n'\ 5831 + ' -x<mode> Test xset by toggling the given mode (on/off/standby/suspend)\n'\ 5832 + ' -sysinfo Print out system info extracted from BIOS\n'\ 5833 + ' -devinfo Print out the pm settings of all devices which support runtime suspend\n'\ 5834 + ' -flist Print the list of functions currently being captured in ftrace\n'\ 5835 + ' -flistall Print all functions capable of being captured in ftrace\n'\ 5836 + ' -summary dir Create a summary of tests in this dir [-genhtml builds missing html]\n'\ 5837 + ' [redo]\n'\ 5838 + ' -ftrace ftracefile Create HTML output using ftrace input (used with -dmesg)\n'\ 5839 + ' -dmesg dmesgfile Create HTML output using dmesg (used with -ftrace)\n'\ 5840 + '' % (sysvals.title, sysvals.version, sysvals.suspendmode)) 5899 5841 return True 5900 5842 5901 5843 # ----------------- MAIN -------------------- ··· 5926 5866 printHelp() 5927 5867 sys.exit(0) 5928 5868 elif(arg == '-v'): 5929 - print("Version %s" % sysvals.version) 5869 + pprint("Version %s" % sysvals.version) 5930 5870 sys.exit(0) 5931 5871 elif(arg == '-x2'): 5932 5872 sysvals.execcount = 2 ··· 5942 5882 sysvals.skiphtml = True 5943 5883 elif(arg == '-cgdump'): 5944 5884 sysvals.cgdump = True 5885 + elif(arg == '-devdump'): 5886 + sysvals.devdump = True 5945 5887 elif(arg == '-genhtml'): 5946 5888 genhtml = True 5947 5889 elif(arg == '-addlogs'): ··· 6150 6088 elif(cmd == 'battery'): 6151 6089 out = getBattery() 6152 6090 if out: 6153 - print 'AC Connect : %s\nBattery Charge: %d' % out 6091 + pprint('AC Connect : %s\nBattery Charge: %d' % out) 6154 6092 else: 6155 - print 'no battery found' 6093 + pprint('no battery found') 6156 6094 ret = 1 6157 6095 elif(cmd == 'sysinfo'): 6158 6096 sysvals.printSystemInfo(True) ··· 6170 6108 sysvals.verbose = True 6171 6109 ret = displayControl(cmd[1:]) 6172 6110 elif(cmd == 'xstat'): 6173 - print 'Display Status: %s' % displayControl('stat').upper() 6111 + pprint('Display Status: %s' % displayControl('stat').upper()) 6174 6112 sys.exit(ret) 6175 6113 6176 6114 # if instructed, re-analyze existing data files ··· 6184 6122 if(error): 6185 6123 doError(error) 6186 6124 6187 - # extract mem modes and convert 6125 + # extract mem/disk extra modes and convert 6188 6126 mode = sysvals.suspendmode 6189 - if 'mem' == mode[:3]: 6190 - if '-' in mode: 6191 - memmode = mode.split('-')[-1] 6192 - else: 6193 - memmode = 'deep' 6127 + if mode.startswith('mem'): 6128 + memmode = mode.split('-', 1)[-1] if '-' in mode else 'deep' 6194 6129 if memmode == 'shallow': 6195 6130 mode = 'standby' 6196 6131 elif memmode == 's2idle': ··· 6196 6137 mode = 'mem' 6197 6138 sysvals.memmode = memmode 6198 6139 sysvals.suspendmode = mode 6140 + if mode.startswith('disk-'): 6141 + sysvals.diskmode = mode.split('-', 1)[-1] 6142 + sysvals.suspendmode = 'disk' 6199 6143 6200 6144 sysvals.systemInfo(dmidecode(sysvals.mempath)) 6201 6145 ··· 6215 6153 os.mkdir(sysvals.outdir) 6216 6154 for i in range(sysvals.multitest['count']): 6217 6155 if(i != 0): 6218 - print('Waiting %d seconds...' % (sysvals.multitest['delay'])) 6156 + pprint('Waiting %d seconds...' % (sysvals.multitest['delay'])) 6219 6157 time.sleep(sysvals.multitest['delay']) 6220 - print('TEST (%d/%d) START' % (i+1, sysvals.multitest['count'])) 6158 + pprint('TEST (%d/%d) START' % (i+1, sysvals.multitest['count'])) 6221 6159 fmt = 'suspend-%y%m%d-%H%M%S' 6222 6160 sysvals.testdir = os.path.join(sysvals.outdir, datetime.now().strftime(fmt)) 6223 6161 ret = runTest(i+1) 6224 - print('TEST (%d/%d) COMPLETE' % (i+1, sysvals.multitest['count'])) 6162 + pprint('TEST (%d/%d) COMPLETE' % (i+1, sysvals.multitest['count'])) 6225 6163 sysvals.logmsg = '' 6226 6164 if not sysvals.skiphtml: 6227 6165 runSummary(sysvals.outdir, False, False)