diff options
Diffstat (limited to 'tools')
| -rw-r--r-- | tools/power/pm-graph/README | 552 | ||||
| -rwxr-xr-x | tools/power/pm-graph/bootgraph.py | 8 | ||||
| -rw-r--r-- | tools/power/pm-graph/config/example.cfg | 26 | ||||
| -rw-r--r-- | tools/power/pm-graph/sleepgraph.8 | 16 | ||||
| -rwxr-xr-x | tools/power/pm-graph/sleepgraph.py | 857 |
5 files changed, 1253 insertions, 206 deletions
diff --git a/tools/power/pm-graph/README b/tools/power/pm-graph/README new file mode 100644 index 000000000000..58a5591e3951 --- /dev/null +++ b/tools/power/pm-graph/README @@ -0,0 +1,552 @@ + p m - g r a p h + + pm-graph: suspend/resume/boot timing analysis tools + Version: 5.4 + Author: Todd Brandt <todd.e.brandt@intel.com> + Home Page: https://01.org/pm-graph + + Report bugs/issues at bugzilla.kernel.org Tools/pm-graph + - https://bugzilla.kernel.org/buglist.cgi?component=pm-graph&product=Tools + + Full documentation available online & in man pages + - Getting Started: + https://01.org/pm-graph/documentation/getting-started + + - Config File Format: + https://01.org/pm-graph/documentation/3-config-file-format + + - upstream version in git: + https://github.com/intel/pm-graph/ + + Table of Contents + - Overview + - Setup + - Usage + - Basic Usage + - Dev Mode Usage + - Proc Mode Usage + - Configuration Files + - Usage Examples + - Config File Options + - Custom Timeline Entries + - Adding/Editing Timeline Functions + - Adding/Editing Dev Timeline Source Functions + - Verifying your Custom Functions + - Testing on consumer linux Operating Systems + - Android + +------------------------------------------------------------------ +| OVERVIEW | +------------------------------------------------------------------ + + This tool suite is designed to assist kernel and OS developers in optimizing + their linux stack's suspend/resume & boot time. Using a kernel image built + with a few extra options enabled, the tools will execute a suspend or boot, + and will capture dmesg and ftrace data. This data is transformed into a set of + timelines and a callgraph to give a quick and detailed view of which devices + and kernel processes are taking the most time in suspend/resume & boot. + +------------------------------------------------------------------ +| SETUP | +------------------------------------------------------------------ + + These packages are required to execute the scripts + - python + - python-requests + + Ubuntu: + sudo apt-get install python python-requests + + Fedora: + sudo dnf install python python-requests + + The tools can most easily be installed via git clone and make install + + $> git clone http://github.com/intel/pm-graph.git + $> cd pm-graph + $> sudo make install + $> man sleepgraph ; man bootgraph + + Setup involves some minor kernel configuration + + The following kernel build options are required for all kernels: + CONFIG_DEVMEM=y + CONFIG_PM_DEBUG=y + CONFIG_PM_SLEEP_DEBUG=y + CONFIG_FTRACE=y + CONFIG_FUNCTION_TRACER=y + CONFIG_FUNCTION_GRAPH_TRACER=y + CONFIG_KPROBES=y + CONFIG_KPROBES_ON_FTRACE=y + + In kernel 3.15.0, two patches were upstreamed which enable the + v3.0 behavior. These patches allow the tool to read all the + data from trace events instead of from dmesg. You can enable + this behavior on earlier kernels with these patches: + + (kernel/pre-3.15/enable_trace_events_suspend_resume.patch) + (kernel/pre-3.15/enable_trace_events_device_pm_callback.patch) + + If you're using a kernel older than 3.15.0, the following + additional kernel parameters are required: + (e.g. in file /etc/default/grub) + GRUB_CMDLINE_LINUX_DEFAULT="... initcall_debug log_buf_len=32M ..." + + If you're using a kernel older than 3.11-rc2, the following simple + patch must be applied to enable ftrace data: + in file: kernel/power/suspend.c + in function: int suspend_devices_and_enter(suspend_state_t state) + remove call to "ftrace_stop();" + remove call to "ftrace_start();" + + There is a patch which does this for kernel v3.8.0: + (kernel/pre-3.11-rc2/enable_ftrace_in_suspendresume.patch) + + + +------------------------------------------------------------------ +| USAGE | +------------------------------------------------------------------ + +Basic Usage +___________ + + 1) First configure a kernel using the instructions from the previous sections. + Then build, install, and boot with it. + 2) Open up a terminal window and execute the mode list command: + + %> sudo ./sleepgraph.py -modes + ['freeze', 'mem', 'disk'] + + Execute a test using one of the available power modes, e.g. mem (S3): + + %> sudo ./sleepgraph.py -m mem -rtcwake 15 + + or with a config file + + %> sudo ./sleepgraph.py -config config/suspend.cfg + + When the system comes back you'll see the script finishing up and + creating the output files in the test subdir. It generates output + files in subdirectory: suspend-mmddyy-HHMMSS. The ftrace file can + be used to regenerate the html timeline with different options + + HTML output: <hostname>_<mode>.html + raw dmesg output: <hostname>_<mode>_dmesg.txt + raw ftrace output: <hostname>_<mode>_ftrace.txt + + View the html in firefox or chrome. + + +Dev Mode Usage +______________ + + Developer mode adds information on low level source calls to the timeline. + The tool sets kprobes on all delay and mutex calls to see which devices + are waiting for something and when. It also sets a suite of kprobes on + subsystem dependent calls to better fill out the timeline. + + The tool will also expose kernel threads that don't normally show up in the + timeline. This is useful in discovering dependent threads to get a better + idea of what each device is waiting for. For instance, the scsi_eh thread, + a.k.a. scsi resume error handler, is what each SATA disk device waits for + before it can continue resume. + + The timeline will be much larger if run with dev mode, so it can be useful + to set the -mindev option to clip out any device blocks that are too small + to see easily. The following command will give a nice dev mode run: + + %> sudo ./sleepgraph.py -m mem -rtcwake 15 -mindev 1 -dev + + or with a config file + + %> sudo ./sleepgraph.py -config config/suspend-dev.cfg + + +Proc Mode Usage +_______________ + + Proc mode adds user process info to the timeline. This is done in a manner + similar to the bootchart utility, which graphs init processes and their + execution as the system boots. This tool option does the same thing but for + the period before and after suspend/resume. + + In order to see any process info, there needs to be some delay before or + after resume since processes are frozen in suspend_prepare and thawed in + resume_complete. The predelay and postdelay args allow you to do this. It + can also be useful to run in x2 mode with an x2 delay, this way you can + see process activity before and after resume, and in between two + successive suspend/resumes. + + The command can be run like this: + + %> sudo ./sleepgraph.py -m mem -rtcwake 15 -x2 -x2delay 1000 -predelay 1000 -postdelay 1000 -proc + + or with a config file + + %> sudo ./sleepgraph.py -config config/suspend-proc.cfg + + +------------------------------------------------------------------ +| CONFIGURATION FILES | +------------------------------------------------------------------ + + Since 4.0 we've moved to using config files in lieu of command line options. + The config folder contains a collection of typical use cases. + There are corresponding configs for other power modes: + + Simple suspend/resume with basic timeline (mem/freeze/standby) + config/suspend.cfg + config/freeze.cfg + config/standby.cfg + + Dev mode suspend/resume with dev timeline (mem/freeze/standby) + config/suspend-dev.cfg + config/freeze-dev.cfg + config/standby-dev.cfg + + Simple suspend/resume with timeline and callgraph (mem/freeze/standby) + config/suspend-callgraph.cfg + config/freeze-callgraph.cfg + config/standby-callgraph.cfg + + Sample proc mode x2 run using mem suspend + config/suspend-x2-proc.cfg + + Sample for editing timeline funcs (moves internal functions into config) + config/custom-timeline-functions.cfg + + Sample debug config for serio subsystem + config/debug-serio-suspend.cfg + + +Usage Examples +______________ + + Run a simple mem suspend: + %> sudo ./sleepgraph.py -config config/suspend.cfg + + Run a mem suspend with callgraph data: + %> sudo ./sleepgraph.py -config config/suspend-callgraph.cfg + + Run a mem suspend with dev mode detail: + %> sudo ./sleepgraph.py -config config/suspend-dev.cfg + + +Config File Options +___________________ + + [Settings] + + # Verbosity: print verbose messages (def: false) + verbose: false + + # Suspend Mode: e.g. standby, mem, freeze, disk (def: mem) + mode: mem + + # Output Directory Format: {hostname}, {date}, {time} give current values + output-dir: suspend-{hostname}-{date}-{time} + + # Automatic Wakeup: use rtcwake to wakeup after X seconds (def: infinity) + rtcwake: 15 + + # Add Logs: add the dmesg and ftrace log to the html output (def: false) + addlogs: false + + # Sus/Res Gap: insert a gap between sus & res in the timeline (def: false) + srgap: false + + # Custom Command: Command to execute in lieu of suspend (def: "") + command: echo mem > /sys/power/state + + # Proc mode: graph user processes and cpu usage in the timeline (def: false) + proc: false + + # Dev mode: graph source functions in the timeline (def: false) + dev: false + + # Suspend/Resume x2: run 2 suspend/resumes back to back (def: false) + x2: false + + # x2 Suspend Delay: time delay between the two test runs in ms (def: 0 ms) + x2delay: 0 + + # Pre Suspend Delay: nclude an N ms delay before (1st) suspend (def: 0 ms) + predelay: 0 + + # Post Resume Delay: include an N ms delay after (last) resume (def: 0 ms) + postdelay: 0 + + # Min Device Length: graph only dev callbacks longer than min (def: 0.001 ms) + mindev: 0.001 + + # Callgraph: gather ftrace callgraph data on all timeline events (def: false) + callgraph: false + + # Expand Callgraph: pre-expand the callgraph treeviews in html (def: false) + expandcg: false + + # Min Callgraph Length: show callgraphs only if longer than min (def: 1 ms) + mincg: 1 + + # Timestamp Precision: number of sig digits in timestamps (0:S, [3:ms], 6:us) + timeprec: 3 + + # Device Filter: show only devs whose name/driver includes one of these strings + devicefilter: _cpu_up,_cpu_down,i915,usb + + # Override default timeline entries: + # Do not use the internal default functions for timeline entries (def: false) + # Set this to true if you intend to only use the ones defined in the config + override-timeline-functions: true + + # Override default dev timeline entries: + # Do not use the internal default functions for dev timeline entries (def: false) + # Set this to true if you intend to only use the ones defined in the config + override-dev-timeline-functions: true + + # Call Loop Max Gap (dev mode only) + # merge loops of the same call if each is less than maxgap apart (def: 100us) + callloop-maxgap: 0.0001 + + # Call Loop Max Length (dev mode only) + # merge loops of the same call if each is less than maxlen in length (def: 5ms) + callloop-maxlen: 0.005 + +------------------------------------------------------------------ +| CUSTOM TIMELINE ENTRIES | +------------------------------------------------------------------ + +Adding or Editing Timeline Functions +____________________________________ + + The tool uses an array of function names to fill out empty spaces in the + timeline where device callbacks don't appear. For instance, in suspend_prepare + the tool adds the sys_sync and freeze_processes calls as virtual device blocks + in the timeline to show you where the time is going. These calls should fill + the timeline with contiguous data so that most kernel execution is covered. + + It is possible to add new function calls to the timeline by adding them to + the config. It's also possible to copy the internal timeline functions into + the config so that you can override and edit them. Place them in the + timeline_functions_ARCH section with the name of your architecture appended. + i.e. for x86_64: [timeline_functions_x86_64] + + Use the override-timeline-functions option if you only want to use your + custom calls, or leave it false to append them to the internal ones. + + This section includes a list of functions (set using kprobes) which use both + symbol data and function arg data. The args are pulled directly from the + stack using this architecture's registers and stack formatting. Each entry + can include up to four pieces of info: The function name, a format string, + an argument list, and a color. But only a function name is required. + + For a full example config, see config/custom-timeline-functions.cfg. It pulls + all the internal timeline functions into the config and allows you to edit + them. + + Entry format: + + function: format{fn_arg1}_{fn_arg2} fn_arg1 fn_arg2 ... [color=purple] + + Required Arguments: + + function: The symbol name for the function you want probed, this is the + minimum required for an entry, it will show up as the function + name with no arguments. + + example: _cpu_up: + + Optional Arguments: + + format: The format to display the data on the timeline in. Use braces to + enclose the arg names. + + example: CPU_ON[{cpu}] + + color: The color of the entry block in the timeline. The default color is + transparent, so the entry shares the phase color. The color is an + html color string, either a word, or an RGB. + + example: [color=#CC00CC] + + arglist: A list of arguments from registers/stack addresses. See URL: + https://www.kernel.org/doc/Documentation/trace/kprobetrace.txt + + example: cpu=%di:s32 + + Here is a full example entry. It displays cpu resume calls in the timeline + in orange. They will appear as CPU_ON[0], CPU_ON[1], etc. + + [timeline_functions_x86_64] + _cpu_up: CPU_ON[{cpu}] cpu=%di:s32 [color=orange] + + +Adding or Editing Dev Mode Timeline Source Functions +____________________________________________________ + + In dev mode, the tool uses an array of function names to monitor source + execution within the timeline entries. + + The function calls are displayed inside the main device/call blocks in the + timeline. However, if a function call is not within a main timeline event, + it will spawn an entirely new event named after the caller's kernel thread. + These asynchronous kernel threads will populate in a separate section + beneath the main device/call section. + + The tool has a set of hard coded calls which focus on the most common use + cases: msleep, udelay, schedule_timeout, mutex_lock_slowpath, etc. These are + the functions that add a hardcoded time delay to the suspend/resume path. + The tool also includes some common functions native to important + subsystems: ata, i915, and ACPI, etc. + + It is possible to add new function calls to the dev timeline by adding them + to the config. It's also possible to copy the internal dev timeline + functions into the config so that you can override and edit them. Place them + in the dev_timeline_functions_ARCH section with the name of your architecture + appended. i.e. for x86_64: [dev_timeline_functions_x86_64] + + Use the override-dev-timeline-functions option if you only want to use your + custom calls, or leave it false to append them to the internal ones. + + The format is the same as the timeline_functions_x86_64 section. It's a + list of functions (set using kprobes) which use both symbol data and function + arg data. The args are pulled directly from the stack using this + architecture's registers and stack formatting. Each entry can include up + to four pieces of info: The function name, a format string, an argument list, + and a color. But only the function name is required. + + For a full example config, see config/custom-timeline-functions.cfg. It pulls + all the internal dev timeline functions into the config and allows you to edit + them. + + Here is a full example entry. It displays the ATA port reset calls as + ataN_port_reset in the timeline. This is where most of the SATA disk resume + time goes, so it can be helpful to see the low level call. + + [dev_timeline_functions_x86_64] + ata_eh_recover: ata{port}_port_reset port=+36(%di):s32 [color=#CC00CC] + + +Verifying your custom functions +_______________________________ + + Once you have a set of functions (kprobes) defined, it can be useful to + perform a quick check to see if you formatted them correctly and if the system + actually supports them. To do this, run the tool with your config file + and the -status option. The tool will go through all the kprobes (both + custom and internal if you haven't overridden them) and actually attempts + to set them in ftrace. It will then print out success or fail for you. + + Note that kprobes which don't actually exist in the kernel won't stop the + tool, they just wont show up. + + For example: + + sudo ./sleepgraph.py -config config/custom-timeline-functions.cfg -status + Checking this system (myhostname)... + have root access: YES + is sysfs mounted: YES + is "mem" a valid power mode: YES + is ftrace supported: YES + are kprobes supported: YES + timeline data source: FTRACE (all trace events found) + is rtcwake supported: YES + verifying timeline kprobes work: + _cpu_down: YES + _cpu_up: YES + acpi_pm_finish: YES + acpi_pm_prepare: YES + freeze_kernel_threads: YES + freeze_processes: YES + sys_sync: YES + thaw_processes: YES + verifying dev kprobes work: + __const_udelay: YES + __mutex_lock_slowpath: YES + acpi_os_stall: YES + acpi_ps_parse_aml: YES + intel_opregion_init: NO + intel_opregion_register: NO + intel_opregion_setup: NO + msleep: YES + schedule_timeout: YES + schedule_timeout_uninterruptible: YES + usleep_range: YES + + +------------------------------------------------------------------ +| TESTING ON CONSUMER LINUX OPERATING SYSTEMS | +------------------------------------------------------------------ + +Android +_______ + + The easiest way to execute on an android device is to run the android.sh + script on the device, then pull the ftrace log back to the host and run + sleepgraph.py on it. + + Here are the steps: + + [download and install the tool on the device] + + host%> wget https://raw.githubusercontent.com/intel/pm-graph/master/tools/android.sh + host%> adb connect 192.168.1.6 + host%> adb root + # push the script to a writeable location + host%> adb push android.sh /sdcard/ + + [check whether the tool will run on your device] + + host%> adb shell + dev%> cd /sdcard + dev%> sh android.sh status + host : asus_t100 + kernel : 3.14.0-i386-dirty + modes : freeze mem + rtcwake : supported + ftrace : supported + trace events { + suspend_resume: found + device_pm_callback_end: found + device_pm_callback_start: found + } + # the above is what you see on a system that's properly patched + + [execute the suspend] + + # NOTE: The suspend will only work if the screen isn't timed out, + # so you have to press some keys first to wake it up b4 suspend) + dev%> sh android.sh suspend mem + ------------------------------------ + Suspend/Resume timing test initiated + ------------------------------------ + hostname : asus_t100 + kernel : 3.14.0-i386-dirty + mode : mem + ftrace out : /mnt/shell/emulated/0/ftrace.txt + dmesg out : /mnt/shell/emulated/0/dmesg.txt + log file : /mnt/shell/emulated/0/log.txt + ------------------------------------ + INITIALIZING FTRACE........DONE + STARTING FTRACE + SUSPEND START @ 21:24:02 (rtcwake in 10 seconds) + <adb connection will now terminate> + + [retrieve the data from the device] + + # I find that you have to actually kill the adb process and + # reconnect sometimes in order for the connection to work post-suspend + host%> adb connect 192.168.1.6 + # (required) get the ftrace data, this is the most important piece + host%> adb pull /sdcard/ftrace.txt + # (optional) get the dmesg data, this is for debugging + host%> adb pull /sdcard/dmesg.txt + # (optional) get the log, which just lists some test times for comparison + host%> adb pull /sdcard/log.txt + + [create an output html file using sleepgraph.py] + + host%> sleepgraph.py -ftrace ftrace.txt + + You should now have an output.html with the android data, enjoy! diff --git a/tools/power/pm-graph/bootgraph.py b/tools/power/pm-graph/bootgraph.py index 3d899dd8147a..666bcbda648d 100755 --- a/tools/power/pm-graph/bootgraph.py +++ b/tools/power/pm-graph/bootgraph.py @@ -325,9 +325,9 @@ def parseKernelLog(): if(not sysvals.stamp['kernel']): sysvals.stamp['kernel'] = sysvals.kernelVersion(msg) continue - m = re.match('.* setting system clock to (?P<t>.*) UTC.*', msg) + m = re.match('.* setting system clock to (?P<d>[0-9\-]*)[ A-Z](?P<t>[0-9:]*) UTC.*', msg) if(m): - bt = datetime.strptime(m.group('t'), '%Y-%m-%d %H:%M:%S') + bt = datetime.strptime(m.group('d')+' '+m.group('t'), '%Y-%m-%d %H:%M:%S') bt = bt - timedelta(seconds=int(ktime)) data.boottime = bt.strftime('%Y-%m-%d_%H:%M:%S') sysvals.stamp['time'] = bt.strftime('%B %d %Y, %I:%M:%S %p') @@ -348,7 +348,7 @@ def parseKernelLog(): data.newAction(phase, f, pid, start, ktime, int(r), int(t)) del devtemp[f] continue - if(re.match('^Freeing unused kernel memory.*', msg)): + if(re.match('^Freeing unused kernel .*', msg)): data.tUserMode = ktime data.dmesg['kernel']['end'] = ktime data.dmesg['user']['start'] = ktime @@ -1008,7 +1008,7 @@ if __name__ == '__main__': updateKernelParams() elif cmd == 'flistall': for f in sysvals.getBootFtraceFilterFunctions(): - print f + print(f) elif cmd == 'checkbl': sysvals.getBootLoader() pprint('Boot Loader: %s\n%s' % (sysvals.bootloader, sysvals.blexec)) diff --git a/tools/power/pm-graph/config/example.cfg b/tools/power/pm-graph/config/example.cfg index 05b2efb9bb54..1ef3eb9383fa 100644 --- a/tools/power/pm-graph/config/example.cfg +++ b/tools/power/pm-graph/config/example.cfg @@ -98,12 +98,34 @@ postdelay: 0 # graph only devices longer than min in the timeline (default: 0.001 ms) mindev: 0.001 +# Call Loop Max Gap (dev mode only) +# merge loops of the same call if each is less than maxgap apart (def: 100us) +callloop-maxgap: 0.0001 + +# Call Loop Max Length (dev mode only) +# merge loops of the same call if each is less than maxlen in length (def: 5ms) +callloop-maxlen: 0.005 + +# Override default timeline entries: +# Do not use the internal default functions for timeline entries (def: false) +# Set this to true if you intend to only use the ones defined in the config +override-timeline-functions: true + +# Override default dev timeline entries: +# Do not use the internal default functions for dev timeline entries (def: false) +# Set this to true if you intend to only use the ones defined in the config +override-dev-timeline-functions: true + # ---- Debug Options ---- # Callgraph # gather detailed ftrace callgraph data on all timeline events (default: false) callgraph: false +# Max graph depth +# limit the callgraph trace to this depth (default: 0 = all) +maxdepth: 2 + # Callgraph phase filter # Only enable callgraphs for one phase, i.e. resume_noirq (default: all) cgphase: suspend @@ -131,3 +153,7 @@ timeprec: 6 # Add kprobe functions to the timeline # Add functions to the timeline from a text file (default: no-action) # fadd: file.txt + +# Ftrace buffer size +# Set trace buffer size to N kilo-bytes (default: all of free memory up to 3GB) +# bufsize: 1000 diff --git a/tools/power/pm-graph/sleepgraph.8 b/tools/power/pm-graph/sleepgraph.8 index 24a2e7d0ae63..9648be644d5f 100644 --- a/tools/power/pm-graph/sleepgraph.8 +++ b/tools/power/pm-graph/sleepgraph.8 @@ -53,6 +53,11 @@ disable rtcwake and require a user keypress to resume. Add the dmesg and ftrace logs to the html output. They will be viewable by clicking buttons in the timeline. .TP +\fB-turbostat\fR +Use turbostat to execute the command in freeze mode (default: disabled). This +will provide turbostat output in the log which will tell you which actual +power modes were entered. +.TP \fB-result \fIfile\fR Export a results table to a text file for parsing. .TP @@ -121,6 +126,10 @@ be created in a new subdirectory with a summary page: suspend-xN-{date}-{time}. Use ftrace to create device callgraphs (default: disabled). This can produce very large outputs, i.e. 10MB - 100MB. .TP +\fB-ftop\fR +Use ftrace on the top level call: "suspend_devices_and_enter" only (default: disabled). +This option implies -f and creates a single callgraph covering all of suspend/resume. +.TP \fB-maxdepth \fIlevel\fR limit the callgraph trace depth to \fIlevel\fR (default: 0=all). This is the best way to limit the output size when using callgraphs via -f. @@ -138,8 +147,8 @@ which are barely visible in the timeline. The value is a float: e.g. 0.001 represents 1 us. .TP \fB-cgfilter \fI"func1,func2,..."\fR -Reduce callgraph output in the timeline by limiting it to a list of calls. The -argument can be a single function name or a comma delimited list. +Reduce callgraph output in the timeline by limiting it certain devices. The +argument can be a single device name or a comma delimited list. (default: none) .TP \fB-cgskip \fIfile\fR @@ -183,6 +192,9 @@ Print out the contents of the ACPI Firmware Performance Data Table. \fB-battery\fR Print out battery status and current charge. .TP +\fB-wifi\fR +Print out wifi status and connection details. +.TP \fB-xon/-xoff/-xstandby/-xsuspend\fR Test xset by attempting to switch the display to the given mode. This is the same command which will be issued by \fB-display \fImode\fR. diff --git a/tools/power/pm-graph/sleepgraph.py b/tools/power/pm-graph/sleepgraph.py index d1a88d05e976..4f46a7a1feb6 100755 --- a/tools/power/pm-graph/sleepgraph.py +++ b/tools/power/pm-graph/sleepgraph.py @@ -9,9 +9,9 @@ # # Links: # Home Page -# https://01.org/suspendresume +# https://01.org/pm-graph # Source repo -# git@github.com:01org/pm-graph +# git@github.com:intel/pm-graph # # Description: # This tool is designed to assist kernel and OS developers in optimizing @@ -24,6 +24,7 @@ # viewed in firefox or chrome. # # The following kernel build options are required: +# CONFIG_DEVMEM=y # CONFIG_PM_DEBUG=y # CONFIG_PM_SLEEP_DEBUG=y # CONFIG_FTRACE=y @@ -53,6 +54,7 @@ import ConfigParser import gzip from threading import Thread from subprocess import call, Popen, PIPE +import base64 def pprint(msg): print(msg) @@ -66,7 +68,7 @@ def pprint(msg): # store system values and test parameters class SystemValues: title = 'SleepGraph' - version = '5.2' + version = '5.4' ansi = False rs = 0 display = '' @@ -74,8 +76,9 @@ class SystemValues: sync = False verbose = False testlog = True - dmesglog = False + dmesglog = True ftracelog = False + tstat = False mindevlen = 0.0 mincglen = 0.0 cgphase = '' @@ -99,6 +102,8 @@ class SystemValues: pmdpath = '/sys/power/pm_debug_messages' traceevents = [ 'suspend_resume', + 'wakeup_source_activate', + 'wakeup_source_deactivate', 'device_pm_callback_end', 'device_pm_callback_start' ] @@ -130,6 +135,8 @@ class SystemValues: x2delay = 0 skiphtml = False usecallgraph = False + ftopfunc = 'suspend_devices_and_enter' + ftop = False usetraceevents = False usetracemarkers = True usekprobes = True @@ -158,6 +165,13 @@ class SystemValues: 'acpi_hibernation_leave': {}, 'acpi_pm_freeze': {}, 'acpi_pm_thaw': {}, + 'acpi_s2idle_end': {}, + 'acpi_s2idle_sync': {}, + 'acpi_s2idle_begin': {}, + 'acpi_s2idle_prepare': {}, + 'acpi_s2idle_wake': {}, + 'acpi_s2idle_wakeup': {}, + 'acpi_s2idle_restore': {}, 'hibernate_preallocate_memory': {}, 'create_basic_memory_bitmaps': {}, 'swsusp_write': {}, @@ -191,9 +205,14 @@ class SystemValues: 'usleep_range': { 'args_x86_64': {'min':'%di:s32', 'max':'%si:s32'}, 'ub': 1 }, 'mutex_lock_slowpath': { 'func':'__mutex_lock_slowpath', 'ub': 1 }, 'acpi_os_stall': {'ub': 1}, + 'rt_mutex_slowlock': {'ub': 1}, # ACPI 'acpi_resume_power_resources': {}, - 'acpi_ps_parse_aml': {}, + 'acpi_ps_execute_method': { 'args_x86_64': { + 'fullpath':'+0(+40(%di)):string', + }}, + # mei_me + 'mei_reset': {}, # filesystem 'ext4_sync_fs': {}, # 80211 @@ -242,6 +261,7 @@ class SystemValues: timeformat = '%.3f' cmdline = '%s %s' % \ (os.path.basename(sys.argv[0]), ' '.join(sys.argv[1:])) + kparams = '' sudouser = '' def __init__(self): self.archargs = 'args_'+platform.machine() @@ -320,6 +340,7 @@ class SystemValues: args['date'] = n.strftime('%y%m%d') args['time'] = n.strftime('%H%M%S') args['hostname'] = args['host'] = self.hostname + args['mode'] = self.suspendmode return value.format(**args) def setOutputFile(self): if self.dmesgfile != '': @@ -331,21 +352,28 @@ class SystemValues: if(m): self.htmlfile = m.group('name')+'.html' def systemInfo(self, info): - p = c = m = b = '' + p = m = '' if 'baseboard-manufacturer' in info: m = info['baseboard-manufacturer'] elif 'system-manufacturer' in info: m = info['system-manufacturer'] - if 'baseboard-product-name' in info: - p = info['baseboard-product-name'] - elif 'system-product-name' in info: + if 'system-product-name' in info: p = info['system-product-name'] - if 'processor-version' in info: - c = info['processor-version'] - if 'bios-version' in info: - b = info['bios-version'] - self.sysstamp = '# sysinfo | man:%s | plat:%s | cpu:%s | bios:%s | numcpu:%d | memsz:%d | memfr:%d' % \ - (m, p, c, b, self.cpucount, self.memtotal, self.memfree) + elif 'baseboard-product-name' in info: + p = info['baseboard-product-name'] + if m[:5].lower() == 'intel' and 'baseboard-product-name' in info: + p = info['baseboard-product-name'] + c = info['processor-version'] if 'processor-version' in info else '' + b = info['bios-version'] if 'bios-version' in info else '' + r = info['bios-release-date'] if 'bios-release-date' in info else '' + self.sysstamp = '# sysinfo | man:%s | plat:%s | cpu:%s | bios:%s | biosdate:%s | numcpu:%d | memsz:%d | memfr:%d' % \ + (m, p, c, b, r, self.cpucount, self.memtotal, self.memfree) + try: + kcmd = open('/proc/cmdline', 'r').read().strip() + except: + kcmd = '' + if kcmd: + self.sysstamp += '\n# kparams | %s' % kcmd def printSystemInfo(self, fatal=False): self.rootCheck(True) out = dmidecode(self.mempath, fatal) @@ -353,10 +381,10 @@ class SystemValues: return fmt = '%-24s: %s' for name in sorted(out): - print fmt % (name, out[name]) - print fmt % ('cpucount', ('%d' % self.cpucount)) - print fmt % ('memtotal', ('%d kB' % self.memtotal)) - print fmt % ('memfree', ('%d kB' % self.memfree)) + print(fmt % (name, out[name])) + print(fmt % ('cpucount', ('%d' % self.cpucount))) + print(fmt % ('memtotal', ('%d kB' % self.memtotal))) + print(fmt % ('memfree', ('%d kB' % self.memfree))) def cpuInfo(self): self.cpucount = 0 fp = open('/proc/cpuinfo', 'r') @@ -376,7 +404,7 @@ class SystemValues: def initTestOutput(self, name): self.prefix = self.hostname v = open('/proc/version', 'r').read().strip() - kver = string.split(v)[2] + kver = v.split()[2] fmt = name+'-%m%d%y-%H%M%S' testtime = datetime.now().strftime(fmt) self.teststamp = \ @@ -391,7 +419,7 @@ class SystemValues: self.htmlfile = \ self.testdir+'/'+self.prefix+'_'+self.suspendmode+'.html' if not os.path.isdir(self.testdir): - os.mkdir(self.testdir) + os.makedirs(self.testdir) def getValueList(self, value): out = [] for i in value.split(','): @@ -402,6 +430,12 @@ class SystemValues: self.devicefilter = self.getValueList(value) def setCallgraphFilter(self, value): self.cgfilter = self.getValueList(value) + def skipKprobes(self, value): + for k in self.getValueList(value): + if k in self.tracefuncs: + del self.tracefuncs[k] + if k in self.dev_tracefuncs: + del self.dev_tracefuncs[k] def setCallgraphBlacklist(self, file): self.cgblacklist = self.listFromFile(file) def rtcWakeAlarmOn(self): @@ -471,9 +505,9 @@ class SystemValues: if 'func' in self.tracefuncs[i]: i = self.tracefuncs[i]['func'] if i in master: - print i + print(i) else: - print self.colorText(i) + print(self.colorText(i)) def setFtraceFilterFunctions(self, list): master = self.listFromFile(self.tpath+'available_filter_functions') flist = '' @@ -680,7 +714,8 @@ class SystemValues: if self.bufsize > 0: tgtsize = self.bufsize elif self.usecallgraph or self.usedevsrc: - bmax = (1*1024*1024) if self.suspendmode == 'disk' else (3*1024*1024) + bmax = (1*1024*1024) if self.suspendmode in ['disk', 'command'] \ + else (3*1024*1024) tgtsize = min(self.memfree, bmax) else: tgtsize = 65536 @@ -715,7 +750,10 @@ class SystemValues: cf.append(self.tracefuncs[fn]['func']) else: cf.append(fn) - self.setFtraceFilterFunctions(cf) + if self.ftop: + self.setFtraceFilterFunctions([self.ftopfunc]) + else: + self.setFtraceFilterFunctions(cf) # initialize the kprobe trace elif self.usekprobes: for name in self.tracefuncs: @@ -768,9 +806,21 @@ class SystemValues: fw = test['fw'] if(fw): fp.write('# fwsuspend %u fwresume %u\n' % (fw[0], fw[1])) + if 'mcelog' in test: + fp.write('# mcelog %s\n' % test['mcelog']) + if 'turbo' in test: + fp.write('# turbostat %s\n' % test['turbo']) if 'bat' in test: (a1, c1), (a2, c2) = test['bat'] fp.write('# battery %s %d %s %d\n' % (a1, c1, a2, c2)) + if 'wifi' in test: + wstr = [] + for wifi in test['wifi']: + tmp = [] + for key in sorted(wifi): + tmp.append('%s:%s' % (key, wifi[key])) + wstr.append('|'.join(tmp)) + fp.write('# wifi %s\n' % (','.join(wstr))) if test['error'] or len(testdata) > 1: fp.write('# enter_sleep_error %s\n' % test['error']) return fp @@ -821,6 +871,106 @@ class SystemValues: if isgz: return gzip.open(filename, mode+'b') return open(filename, mode) + def mcelog(self, clear=False): + cmd = self.getExec('mcelog') + if not cmd: + return '' + if clear: + call(cmd+' > /dev/null 2>&1', shell=True) + return '' + fp = Popen([cmd], stdout=PIPE, stderr=PIPE).stdout + out = fp.read().strip() + fp.close() + if not out: + return '' + return base64.b64encode(out.encode('zlib')) + def haveTurbostat(self): + if not self.tstat: + return False + cmd = self.getExec('turbostat') + if not cmd: + return False + fp = Popen([cmd, '-v'], stdout=PIPE, stderr=PIPE).stderr + out = fp.read().strip() + fp.close() + return re.match('turbostat version [0-9\.]* .*', out) + def turbostat(self): + cmd = self.getExec('turbostat') + if not cmd: + return 'missing turbostat executable' + text = [] + fullcmd = '%s -q -S echo freeze > %s' % (cmd, self.powerfile) + fp = Popen(['sh', '-c', fullcmd], stdout=PIPE, stderr=PIPE).stderr + for line in fp: + if re.match('[0-9.]* sec', line): + continue + text.append(line.split()) + fp.close() + if len(text) < 2: + return 'turbostat output format error' + out = [] + for key in text[0]: + values = [] + idx = text[0].index(key) + for line in text[1:]: + if len(line) > idx: + values.append(line[idx]) + out.append('%s=%s' % (key, ','.join(values))) + return '|'.join(out) + def checkWifi(self): + out = dict() + iwcmd, ifcmd = self.getExec('iwconfig'), self.getExec('ifconfig') + if not iwcmd or not ifcmd: + return out + fp = Popen(iwcmd, stdout=PIPE, stderr=PIPE).stdout + for line in fp: + m = re.match('(?P<dev>\S*) .* ESSID:(?P<ess>\S*)', line) + if not m: + continue + out['device'] = m.group('dev') + if '"' in m.group('ess'): + out['essid'] = m.group('ess').strip('"') + break + fp.close() + if 'device' in out: + fp = Popen([ifcmd, out['device']], stdout=PIPE, stderr=PIPE).stdout + for line in fp: + m = re.match('.* inet (?P<ip>[0-9\.]*)', line) + if m: + out['ip'] = m.group('ip') + break + fp.close() + return out + def errorSummary(self, errinfo, msg): + found = False + for entry in errinfo: + if re.match(entry['match'], msg): + entry['count'] += 1 + if self.hostname not in entry['urls']: + entry['urls'][self.hostname] = [self.htmlfile] + elif self.htmlfile not in entry['urls'][self.hostname]: + entry['urls'][self.hostname].append(self.htmlfile) + found = True + break + if found: + return + arr = msg.split() + for j in range(len(arr)): + if re.match('^[0-9,\-\.]*$', arr[j]): + arr[j] = '[0-9,\-\.]*' + else: + arr[j] = arr[j]\ + .replace('\\', '\\\\').replace(']', '\]').replace('[', '\[')\ + .replace('.', '\.').replace('+', '\+').replace('*', '\*')\ + .replace('(', '\(').replace(')', '\)') + mstr = ' '.join(arr) + entry = { + 'line': msg, + 'match': mstr, + 'count': 1, + 'urls': {self.hostname: [self.htmlfile]} + } + errinfo.append(entry) sysvals = SystemValues() switchvalues = ['enable', 'disable', 'on', 'off', 'true', 'false', '1', '0'] @@ -915,7 +1065,14 @@ class Data: 'ERROR' : '.*ERROR.*', 'WARNING' : '.*WARNING.*', 'IRQ' : '.*genirq: .*', - 'TASKFAIL': '.*Freezing of tasks failed.*', + 'TASKFAIL': '.*Freezing of tasks *.*', + 'ACPI' : '.*ACPI *(?P<b>[A-Za-z]*) *Error[: ].*', + 'DEVFAIL' : '.* failed to (?P<b>[a-z]*) async: .*', + 'DISKFULL': '.*No space left on device.*', + 'USBERR' : '.*usb .*device .*, error [0-9-]*', + 'ATAERR' : ' *ata[0-9\.]*: .*failed.*', + 'MEIERR' : ' *mei.*: .*failed.*', + 'TPMERR' : '(?i) *tpm *tpm[0-9]*: .*error.*', } def __init__(self, num): idchar = 'abcdefghij' @@ -933,6 +1090,9 @@ class Data: self.outfile = '' self.kerror = False self.battery = 0 + self.wifi = 0 + self.turbostat = 0 + self.mcelog = 0 self.enterfail = '' self.currphase = '' self.pstl = dict() # process timeline @@ -967,8 +1127,24 @@ class Data: if len(plist) < 1: return '' return plist[-1] + def turbostatInfo(self): + tp = TestProps() + out = {'syslpi':'N/A','pkgpc10':'N/A'} + for line in self.dmesgtext: + m = re.match(tp.tstatfmt, line) + if not m: + continue + for i in m.group('t').split('|'): + if 'SYS%LPI' in i: + out['syslpi'] = i.split('=')[-1]+'%' + elif 'pc10' in i: + out['pkgpc10'] = i.split('=')[-1]+'%' + break + return out def extractErrorInfo(self): - lf = sysvals.openlog(sysvals.dmesgfile, 'r') + lf = self.dmesgtext + if len(self.dmesgtext) < 1 and sysvals.dmesgfile: + lf = sysvals.openlog(sysvals.dmesgfile, 'r') i = 0 list = [] for line in lf: @@ -983,16 +1159,19 @@ class Data: msg = m.group('msg') for err in self.errlist: if re.match(self.errlist[err], msg): - list.append((err, dir, t, i, i)) + list.append((msg, err, dir, t, i, i)) self.kerror = True break - for e in list: - type, dir, t, idx1, idx2 = e + msglist = [] + for msg, type, dir, t, idx1, idx2 in list: + msglist.append(msg) sysvals.vprint('kernel %s found in %s at %f' % (type, dir, t)) self.errorinfo[dir].append((type, t, idx1, idx2)) if self.kerror: sysvals.dmesglog = True - lf.close() + if len(self.dmesgtext) < 1 and sysvals.dmesgfile: + lf.close() + return msglist def setStart(self, time): self.start = time def setEnd(self, time): @@ -2045,7 +2224,7 @@ class FTraceCallGraph: if(data.dmesg[p]['start'] <= self.start and self.start <= data.dmesg[p]['end']): list = data.dmesg[p]['list'] - for devname in list: + for devname in sorted(list, key=lambda k:list[k]['start']): dev = list[devname] if(pid == dev['pid'] and self.start <= dev['start'] and @@ -2350,6 +2529,9 @@ class TestProps: '(?P<H>[0-9]{2})(?P<M>[0-9]{2})(?P<S>[0-9]{2})'+\ ' (?P<host>.*) (?P<mode>.*) (?P<kernel>.*)$' batteryfmt = '^# battery (?P<a1>\w*) (?P<c1>\d*) (?P<a2>\w*) (?P<c2>\d*)' + wififmt = '^# wifi (?P<w>.*)' + tstatfmt = '^# turbostat (?P<t>\S*)' + mcelogfmt = '^# mcelog (?P<m>\S*)' testerrfmt = '^# enter_sleep_error (?P<e>.*)' sysinfofmt = '^# sysinfo .*' cmdlinefmt = '^# command \| (?P<cmd>.*)' @@ -2372,7 +2554,10 @@ class TestProps: self.cmdline = '' self.kparams = '' self.testerror = [] + self.mcelog = [] + self.turbostat = [] self.battery = [] + self.wifi = [] self.fwdata = [] self.ftrace_line_fmt = self.ftrace_line_fmt_nop self.cgformat = False @@ -2386,6 +2571,44 @@ class TestProps: self.ftrace_line_fmt = self.ftrace_line_fmt_nop else: doError('Invalid tracer format: [%s]' % tracer) + def decode(self, data): + try: + out = base64.b64decode(data).decode('zlib') + except: + out = data + return out + def stampInfo(self, line): + if re.match(self.stampfmt, line): + self.stamp = line + return True + elif re.match(self.sysinfofmt, line): + self.sysinfo = line + return True + elif re.match(self.kparamsfmt, line): + self.kparams = line + return True + elif re.match(self.cmdlinefmt, line): + self.cmdline = line + return True + elif re.match(self.mcelogfmt, line): + self.mcelog.append(line) + return True + elif re.match(self.tstatfmt, line): + self.turbostat.append(line) + return True + elif re.match(self.batteryfmt, line): + self.battery.append(line) + return True + elif re.match(self.wififmt, line): + self.wifi.append(line) + return True + elif re.match(self.testerrfmt, line): + self.testerror.append(line) + return True + elif re.match(self.firmwarefmt, line): + self.fwdata.append(line) + return True + return False def parseStamp(self, data, sv): # global test data m = re.match(self.stampfmt, self.stamp) @@ -2428,14 +2651,31 @@ class TestProps: sv.stamp = data.stamp # firmware data if sv.suspendmode == 'mem' and len(self.fwdata) > data.testnumber: - data.fwSuspend, data.fwResume = self.fwdata[data.testnumber] - if(data.fwSuspend > 0 or data.fwResume > 0): - data.fwValid = True + m = re.match(self.firmwarefmt, self.fwdata[data.testnumber]) + if m: + data.fwSuspend, data.fwResume = int(m.group('s')), int(m.group('r')) + if(data.fwSuspend > 0 or data.fwResume > 0): + data.fwValid = True + # mcelog data + if len(self.mcelog) > data.testnumber: + m = re.match(self.mcelogfmt, self.mcelog[data.testnumber]) + if m: + data.mcelog = self.decode(m.group('m')) + # turbostat data + if len(self.turbostat) > data.testnumber: + m = re.match(self.tstatfmt, self.turbostat[data.testnumber]) + if m: + data.turbostat = m.group('t') # battery data if len(self.battery) > data.testnumber: m = re.match(self.batteryfmt, self.battery[data.testnumber]) if m: data.battery = m.groups() + # wifi data + if len(self.wifi) > data.testnumber: + m = re.match(self.wififmt, self.wifi[data.testnumber]) + if m: + data.wifi = m.group('w') # sleep mode enter errors if len(self.testerror) > data.testnumber: m = re.match(self.testerrfmt, self.testerror[data.testnumber]) @@ -2505,9 +2745,9 @@ class ProcessMonitor: # Quickly determine if the ftrace log has all of the trace events, # markers, and/or kprobes required for primary parsing. def doesTraceLogHaveTraceEvents(): - kpcheck = ['_cal: (', '_cpu_down()'] + kpcheck = ['_cal: (', '_ret: ('] techeck = ['suspend_resume', 'device_pm_callback'] - tmcheck = ['tracing_mark_write'] + tmcheck = ['SUSPEND START', 'RESUME COMPLETE'] sysvals.usekprobes = False fp = sysvals.openlog(sysvals.ftracefile, 'r') for line in fp: @@ -2556,21 +2796,7 @@ def appendIncompleteTraceLog(testruns): for line in tf: # remove any latent carriage returns line = line.replace('\r\n', '') - # grab the stamp and sysinfo - if re.match(tp.stampfmt, line): - tp.stamp = line - continue - elif re.match(tp.sysinfofmt, line): - tp.sysinfo = line - continue - elif re.match(tp.cmdlinefmt, line): - tp.cmdline = line - continue - elif re.match(tp.batteryfmt, line): - tp.battery.append(line) - continue - elif re.match(tp.testerrfmt, line): - tp.testerror.append(line) + if tp.stampInfo(line): continue # determine the trace data type (required for further parsing) m = re.match(tp.tracertypefmt, line) @@ -2693,26 +2919,7 @@ def parseTraceLog(live=False): for line in tf: # remove any latent carriage returns line = line.replace('\r\n', '') - # stamp and sysinfo lines - if re.match(tp.stampfmt, line): - tp.stamp = line - continue - elif re.match(tp.sysinfofmt, line): - tp.sysinfo = line - continue - elif re.match(tp.cmdlinefmt, line): - tp.cmdline = line - continue - elif re.match(tp.batteryfmt, line): - tp.battery.append(line) - continue - elif re.match(tp.testerrfmt, line): - tp.testerror.append(line) - continue - # firmware line: pull out any firmware data - m = re.match(tp.firmwarefmt, line) - if(m): - tp.fwdata.append((int(m.group('s')), int(m.group('r')))) + if tp.stampInfo(line): continue # tracer type line: determine the trace data type m = re.match(tp.tracertypefmt, line) @@ -2925,7 +3132,7 @@ def parseTraceLog(live=False): tp.ktemp[key].append({ 'pid': pid, 'begin': t.time, - 'end': t.time, + 'end': -1, 'name': displayname, 'cdata': kprobedata, 'proc': m_proc, @@ -2936,12 +3143,11 @@ def parseTraceLog(live=False): elif(t.freturn): if(key not in tp.ktemp) or len(tp.ktemp[key]) < 1: continue - e = tp.ktemp[key][-1] - if e['begin'] < 0.0 or t.time - e['begin'] < 0.000001: - tp.ktemp[key].pop() - else: - e['end'] = t.time - e['rdata'] = kprobedata + e = next((x for x in reversed(tp.ktemp[key]) if x['end'] < 0), 0) + if not e: + continue + e['end'] = t.time + e['rdata'] = kprobedata # end of kernel resume if(phase != 'suspend_prepare' and kprobename in krescalls): if phase in data.dmesg: @@ -2963,8 +3169,10 @@ def parseTraceLog(live=False): if(res == -1): testrun.ftemp[key][-1].addLine(t) tf.close() + if len(testdata) < 1: + sysvals.vprint('WARNING: ftrace start marker is missing') if data and not data.devicegroups: - sysvals.vprint('WARNING: end marker is missing') + sysvals.vprint('WARNING: ftrace end marker is missing') data.handleEndMarker(t.time) if sysvals.suspendmode == 'command': @@ -3013,9 +3221,11 @@ def parseTraceLog(live=False): name, pid = key if name not in sysvals.tracefuncs: continue + if pid not in data.devpids: + data.devpids.append(pid) for e in tp.ktemp[key]: kb, ke = e['begin'], e['end'] - if kb == ke or tlb > kb or tle <= kb: + if ke - kb < 0.000001 or tlb > kb or tle <= kb: continue color = sysvals.kprobeColor(name) data.newActionGlobal(e['name'], kb, ke, pid, color) @@ -3027,7 +3237,7 @@ def parseTraceLog(live=False): continue for e in tp.ktemp[key]: kb, ke = e['begin'], e['end'] - if kb == ke or tlb > kb or tle <= kb: + if ke - kb < 0.000001 or tlb > kb or tle <= kb: continue data.addDeviceFunctionCall(e['name'], name, e['proc'], pid, kb, ke, e['cdata'], e['rdata']) @@ -3051,7 +3261,7 @@ def parseTraceLog(live=False): if not devname: sortkey = '%f%f%d' % (cg.start, cg.end, pid) sortlist[sortkey] = cg - elif len(cg.list) > 1000000: + elif len(cg.list) > 1000000 and cg.name != sysvals.ftopfunc: sysvals.vprint('WARNING: the callgraph for %s is massive (%d lines)' %\ (devname, len(cg.list))) # create blocks for orphan cg data @@ -3133,25 +3343,7 @@ def loadKernelLog(): idx = line.find('[') if idx > 1: line = line[idx:] - # grab the stamp and sysinfo - if re.match(tp.stampfmt, line): - tp.stamp = line - continue - elif re.match(tp.sysinfofmt, line): - tp.sysinfo = line - continue - elif re.match(tp.cmdlinefmt, line): - tp.cmdline = line - continue - elif re.match(tp.batteryfmt, line): - tp.battery.append(line) - continue - elif re.match(tp.testerrfmt, line): - tp.testerror.append(line) - continue - m = re.match(tp.firmwarefmt, line) - if(m): - tp.fwdata.append((int(m.group('s')), int(m.group('r')))) + if tp.stampInfo(line): continue m = re.match('[ \t]*(\[ *)(?P<ktime>[0-9\.]*)(\]) (?P<msg>.*)', line) if(not m): @@ -3176,7 +3368,7 @@ def loadKernelLog(): if data: testruns.append(data) if len(testruns) < 1: - pprint('ERROR: dmesg log has no suspend/resume data: %s' \ + doError('dmesg log has no suspend/resume data: %s' \ % sysvals.dmesgfile) # fix lines with same timestamp/function with the call and return swapped @@ -3515,6 +3707,8 @@ def addCallgraphs(sv, hf, data): name += ' '+p if('ftrace' in dev): cg = dev['ftrace'] + if cg.name == sv.ftopfunc: + name = 'top level suspend/resume call' num = callgraphHTML(sv, hf, num, cg, name, color, dev['id']) if('ftraces' in dev): @@ -3523,22 +3717,16 @@ def addCallgraphs(sv, hf, data): name+' → '+cg.name, color, dev['id']) hf.write('\n\n </section>\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, title): - # write the html header first (html head, css code, up to body start) - html = '<!DOCTYPE html>\n<html>\n<head>\n\ +def summaryCSS(title, center=True): + tdcenter = 'text-align:center;' if center else '' + out = '<!DOCTYPE html>\n<html>\n<head>\n\ <meta http-equiv="content-type" content="text/html; charset=UTF-8">\n\ - <title>SleepGraph Summary</title>\n\ + <title>'+title+'</title>\n\ <style type=\'text/css\'>\n\ .stamp {width: 100%;text-align:center;background:#888;line-height:30px;color:white;font: 25px Arial;}\n\ - table {width:100%;border-collapse: collapse;}\n\ - .summary {border:1px solid;}\n\ + table {width:100%;border-collapse: collapse;border:1px solid;}\n\ th {border: 1px solid black;background:#222;color:white;}\n\ - td {font: 14px "Times New Roman";text-align: center;}\n\ + td {font: 14px "Times New Roman";'+tdcenter+'}\n\ tr.head td {border: 1px solid black;background:#aaa;}\n\ tr.alt {background-color:#ddd;}\n\ tr.notice {color:red;}\n\ @@ -3547,12 +3735,23 @@ def createHTMLSummarySimple(testruns, htmlfile, title): .maxval {background-color:#FFBBBB;}\n\ .head a {color:#000;text-decoration: none;}\n\ </style>\n</head>\n<body>\n' + return out + +# Function: createHTMLSummarySimple +# Description: +# Create summary html file for a series of tests +# Arguments: +# testruns: array of Data objects from parseTraceLog +def createHTMLSummarySimple(testruns, htmlfile, title): + # write the html header first (html head, css code, up to body start) + html = summaryCSS('Summary - SleepGraph') # extract the test data into list list = dict() - tAvg, tMin, tMax, tMed = [0.0, 0.0], [0.0, 0.0], [0.0, 0.0], [[], []] + tAvg, tMin, tMax, tMed = [0.0, 0.0], [0.0, 0.0], [0.0, 0.0], [dict(), dict()] iMin, iMed, iMax = [0, 0], [0, 0], [0, 0] num = 0 + useturbo = False lastmode = '' cnt = dict() for data in sorted(testruns, key=lambda v:(v['mode'], v['host'], v['kernel'], v['time'])): @@ -3563,27 +3762,35 @@ def createHTMLSummarySimple(testruns, htmlfile, title): for i in range(2): s = sorted(tMed[i]) list[lastmode]['med'][i] = s[int(len(s)/2)] - iMed[i] = tMed[i].index(list[lastmode]['med'][i]) + iMed[i] = tMed[i][list[lastmode]['med'][i]] list[lastmode]['avg'] = [tAvg[0] / num, tAvg[1] / num] list[lastmode]['min'] = tMin list[lastmode]['max'] = tMax list[lastmode]['idx'] = (iMin, iMed, iMax) - tAvg, tMin, tMax, tMed = [0.0, 0.0], [0.0, 0.0], [0.0, 0.0], [[], []] + tAvg, tMin, tMax, tMed = [0.0, 0.0], [0.0, 0.0], [0.0, 0.0], [dict(), dict()] iMin, iMed, iMax = [0, 0], [0, 0], [0, 0] num = 0 + pkgpc10 = syslpi = '' + if 'pkgpc10' in data and 'syslpi' in data: + pkgpc10 = data['pkgpc10'] + syslpi = data['syslpi'] + useturbo = True + res = data['result'] tVal = [float(data['suspend']), float(data['resume'])] list[mode]['data'].append([data['host'], data['kernel'], - data['time'], tVal[0], tVal[1], data['url'], data['result'], + data['time'], tVal[0], tVal[1], data['url'], res, data['issues'], data['sus_worst'], data['sus_worsttime'], - data['res_worst'], data['res_worsttime']]) + data['res_worst'], data['res_worsttime'], pkgpc10, syslpi]) idx = len(list[mode]['data']) - 1 - if data['result'] not in cnt: - cnt[data['result']] = 1 + if res.startswith('fail in'): + res = 'fail' + if res not in cnt: + cnt[res] = 1 else: - cnt[data['result']] += 1 - if data['result'] == 'pass': + cnt[res] += 1 + if res == 'pass': for i in range(2): - tMed[i].append(tVal[i]) + tMed[i][tVal[i]] = idx tAvg[i] += tVal[i] if tMin[i] == 0 or tVal[i] < tMin[i]: iMin[i] = idx @@ -3597,7 +3804,7 @@ def createHTMLSummarySimple(testruns, htmlfile, title): for i in range(2): s = sorted(tMed[i]) list[lastmode]['med'][i] = s[int(len(s)/2)] - iMed[i] = tMed[i].index(list[lastmode]['med'][i]) + iMed[i] = tMed[i][list[lastmode]['med'][i]] list[lastmode]['avg'] = [tAvg[0] / num, tAvg[1] / num] list[lastmode]['min'] = tMin list[lastmode]['max'] = tMax @@ -3613,19 +3820,21 @@ def createHTMLSummarySimple(testruns, htmlfile, title): td = '\t<td>{0}</td>\n' tdh = '\t<td{1}>{0}</td>\n' tdlink = '\t<td><a href="{0}">html</a></td>\n' + colspan = '14' if useturbo else '12' # table header - html += '<table class="summary">\n<tr>\n' + th.format('#') +\ + html += '<table>\n<tr>\n' + th.format('#') +\ th.format('Mode') + th.format('Host') + th.format('Kernel') +\ th.format('Test Time') + th.format('Result') + th.format('Issues') +\ th.format('Suspend') + th.format('Resume') +\ th.format('Worst Suspend Device') + th.format('SD Time') +\ - th.format('Worst Resume Device') + th.format('RD Time') +\ - th.format('Detail') + '</tr>\n' - + th.format('Worst Resume Device') + th.format('RD Time') + if useturbo: + html += th.format('PkgPC10') + th.format('SysLPI') + html += th.format('Detail')+'</tr>\n' # export list into html head = '<tr class="head"><td>{0}</td><td>{1}</td>'+\ - '<td colspan=12 class="sus">Suspend Avg={2} '+\ + '<td colspan='+colspan+' class="sus">Suspend Avg={2} '+\ '<span class=minval><a href="#s{10}min">Min={3}</a></span> '+\ '<span class=medval><a href="#s{10}med">Med={4}</a></span> '+\ '<span class=maxval><a href="#s{10}max">Max={5}</a></span> '+\ @@ -3634,7 +3843,8 @@ def createHTMLSummarySimple(testruns, htmlfile, title): '<span class=medval><a href="#r{10}med">Med={8}</a></span> '+\ '<span class=maxval><a href="#r{10}max">Max={9}</a></span></td>'+\ '</tr>\n' - headnone = '<tr class="head"><td>{0}</td><td>{1}</td><td colspan=12></td></tr>\n' + headnone = '<tr class="head"><td>{0}</td><td>{1}</td><td colspan='+\ + colspan+'></td></tr>\n' for mode in list: # header line for each suspend mode num = 0 @@ -3681,6 +3891,9 @@ def createHTMLSummarySimple(testruns, htmlfile, title): html += td.format('%.3f ms' % d[9]) if d[9] else td.format('') # sus_worst time html += td.format(d[10]) # res_worst html += td.format('%.3f ms' % d[11]) if d[11] else td.format('') # res_worst time + if useturbo: + html += td.format(d[12]) # pkg_pc10 + html += td.format(d[13]) # syslpi html += tdlink.format(d[5]) if d[5] else td.format('') # url html += '</tr>\n' num += 1 @@ -3690,6 +3903,115 @@ def createHTMLSummarySimple(testruns, htmlfile, title): hf.write(html+'</table>\n</body>\n</html>\n') hf.close() +def createHTMLDeviceSummary(testruns, htmlfile, title): + html = summaryCSS('Device Summary - SleepGraph', False) + + # create global device list from all tests + devall = dict() + for data in testruns: + host, url, devlist = data['host'], data['url'], data['devlist'] + for type in devlist: + if type not in devall: + devall[type] = dict() + mdevlist, devlist = devall[type], data['devlist'][type] + for name in devlist: + length = devlist[name] + if name not in mdevlist: + mdevlist[name] = {'name': name, 'host': host, + 'worst': length, 'total': length, 'count': 1, + 'url': url} + else: + if length > mdevlist[name]['worst']: + mdevlist[name]['worst'] = length + mdevlist[name]['url'] = url + mdevlist[name]['host'] = host + mdevlist[name]['total'] += length + mdevlist[name]['count'] += 1 + + # generate the html + th = '\t<th>{0}</th>\n' + td = '\t<td align=center>{0}</td>\n' + tdr = '\t<td align=right>{0}</td>\n' + tdlink = '\t<td align=center><a href="{0}">html</a></td>\n' + limit = 1 + for type in sorted(devall, reverse=True): + num = 0 + devlist = devall[type] + # table header + html += '<div class="stamp">%s (%s devices > %d ms)</div><table>\n' % \ + (title, type.upper(), limit) + html += '<tr>\n' + '<th align=right>Device Name</th>' +\ + th.format('Average Time') + th.format('Count') +\ + th.format('Worst Time') + th.format('Host (worst time)') +\ + th.format('Link (worst time)') + '</tr>\n' + for name in sorted(devlist, key=lambda k:devlist[k]['worst'], reverse=True): + data = devall[type][name] + data['average'] = data['total'] / data['count'] + if data['average'] < limit: + continue + # row classes - alternate row color + rcls = ['alt'] if num % 2 == 1 else [] + html += '<tr class="'+(' '.join(rcls))+'">\n' if len(rcls) > 0 else '<tr>\n' + html += tdr.format(data['name']) # name + html += td.format('%.3f ms' % data['average']) # average + html += td.format(data['count']) # count + html += td.format('%.3f ms' % data['worst']) # worst + html += td.format(data['host']) # host + html += tdlink.format(data['url']) # url + html += '</tr>\n' + num += 1 + html += '</table>\n' + + # flush the data to file + hf = open(htmlfile, 'w') + hf.write(html+'</body>\n</html>\n') + hf.close() + return devall + +def createHTMLIssuesSummary(testruns, issues, htmlfile, title, extra=''): + multihost = len([e for e in issues if len(e['urls']) > 1]) > 0 + html = summaryCSS('Issues Summary - SleepGraph', False) + total = len(testruns) + + # generate the html + th = '\t<th>{0}</th>\n' + td = '\t<td align={0}>{1}</td>\n' + tdlink = '<a href="{1}">{0}</a>' + subtitle = '%d issues' % len(issues) if len(issues) > 0 else 'no issues' + html += '<div class="stamp">%s (%s)</div><table>\n' % (title, subtitle) + html += '<tr>\n' + th.format('Issue') + th.format('Count') + if multihost: + html += th.format('Hosts') + html += th.format('Tests') + th.format('Fail Rate') +\ + th.format('First Instance') + '</tr>\n' + + num = 0 + for e in sorted(issues, key=lambda v:v['count'], reverse=True): + testtotal = 0 + links = [] + for host in sorted(e['urls']): + links.append(tdlink.format(host, e['urls'][host][0])) + testtotal += len(e['urls'][host]) + rate = '%d/%d (%.2f%%)' % (testtotal, total, 100*float(testtotal)/float(total)) + # row classes - alternate row color + rcls = ['alt'] if num % 2 == 1 else [] + html += '<tr class="'+(' '.join(rcls))+'">\n' if len(rcls) > 0 else '<tr>\n' + html += td.format('left', e['line']) # issue + html += td.format('center', e['count']) # count + if multihost: + html += td.format('center', len(e['urls'])) # hosts + html += td.format('center', testtotal) # test count + html += td.format('center', rate) # test rate + html += td.format('center nowrap', '<br>'.join(links)) # links + html += '</tr>\n' + num += 1 + + # flush the data to file + hf = open(htmlfile, 'w') + hf.write(html+'</table>\n'+extra+'</body>\n</html>\n') + hf.close() + return issues + def ordinal(value): suffix = 'th' if value < 10 or value > 19: @@ -3991,7 +4313,7 @@ def createHTML(testruns, testfail): for word in phase.split('_'): id += word[0] order = '%.2f' % ((p['order'] * pdelta) + pmargin) - name = string.replace(phase, '_', ' ') + name = phase.replace('_', ' ') devtl.html += devtl.html_legend.format(order, p['color'], name, id) devtl.html += '</div>\n' @@ -4580,6 +4902,7 @@ def setRuntimeSuspend(before=True): def executeSuspend(): pm = ProcessMonitor() tp = sysvals.tpath + wifi = sysvals.checkWifi() testdata = [] battery = True if getBattery() else False # run these commands to prepare the system for suspend @@ -4613,6 +4936,7 @@ def executeSuspend(): pprint('SUSPEND START') else: pprint('SUSPEND START (press a key to resume)') + sysvals.mcelog(True) bat1 = getBattery() if battery else False # set rtcwake if(sysvals.rtcwake): @@ -4644,13 +4968,23 @@ def executeSuspend(): pf = open(sysvals.diskpowerfile, 'w') pf.write(sysvals.diskmode) pf.close() - pf = open(sysvals.powerfile, 'w') - pf.write(mode) - # execution will pause here - try: - pf.close() - except Exception as e: - tdata['error'] = str(e) + if mode == 'freeze' and sysvals.haveTurbostat(): + # execution will pause here + turbo = sysvals.turbostat() + if '|' in turbo: + tdata['turbo'] = turbo + else: + tdata['error'] = turbo + else: + if sysvals.haveTurbostat(): + sysvals.vprint('WARNING: ignoring turbostat in mode "%s"' % mode) + pf = open(sysvals.powerfile, 'w') + pf.write(mode) + # execution will pause here + try: + pf.close() + except Exception as e: + tdata['error'] = str(e) if(sysvals.rtcwake): sysvals.rtcWakeAlarmOff() # postdelay delay @@ -4664,9 +4998,14 @@ def executeSuspend(): sysvals.fsetVal('RESUME COMPLETE', 'trace_marker') if(sysvals.suspendmode == 'mem' or sysvals.suspendmode == 'command'): tdata['fw'] = getFPDT(False) + mcelog = sysvals.mcelog() + if mcelog: + tdata['mcelog'] = mcelog bat2 = getBattery() if battery else False if battery and bat1 and bat2: tdata['bat'] = (bat1, bat2) + if 'device' in wifi and 'ip' in wifi: + tdata['wifi'] = (wifi, sysvals.checkWifi()) testdata.append(tdata) # stop ftrace if(sysvals.usecallgraph or sysvals.usetraceevents): @@ -4686,6 +5025,7 @@ def executeSuspend(): op.close() sysvals.fsetVal('', 'trace') devProps() + return testdata def readFile(file): if os.path.islink(file): @@ -4772,7 +5112,7 @@ def deviceInfo(output=''): ms2nice(power['runtime_active_time']), \ ms2nice(power['runtime_suspended_time'])) for i in sorted(lines): - print lines[i] + print(lines[i]) return res # Function: devProps @@ -4905,12 +5245,12 @@ def getModes(): modes = [] if(os.path.exists(sysvals.powerfile)): fp = open(sysvals.powerfile, 'r') - modes = string.split(fp.read()) + modes = fp.read().split() fp.close() if(os.path.exists(sysvals.mempowerfile)): deep = False fp = open(sysvals.mempowerfile, 'r') - for m in string.split(fp.read()): + for m in fp.read().split(): memmode = m.strip('[]') if memmode == 'deep': deep = True @@ -4921,7 +5261,7 @@ def getModes(): modes.remove('mem') if('disk' in modes and os.path.exists(sysvals.diskpowerfile)): fp = open(sysvals.diskpowerfile, 'r') - for m in string.split(fp.read()): + for m in fp.read().split(): modes.append('disk-%s' % m.strip('[]')) fp.close() return modes @@ -4984,14 +5324,15 @@ def dmidecode(mempath, fatal=False): continue # read in the memory for scanning - fp = open(mempath, 'rb') try: + fp = open(mempath, 'rb') fp.seek(memaddr) buf = fp.read(memsize) except: if(fatal): doError('DMI table is unreachable, sorry') else: + pprint('WARNING: /dev/mem is not readable, ignoring DMI data') return out fp.close() @@ -5014,14 +5355,15 @@ def dmidecode(mempath, fatal=False): return out # read in the SM or DMI table - fp = open(mempath, 'rb') try: + fp = open(mempath, 'rb') fp.seek(base) buf = fp.read(length) except: if(fatal): doError('DMI table is unreachable, sorry') else: + pprint('WARNING: /dev/mem is not readable, ignoring DMI data') return out fp.close() @@ -5165,7 +5507,11 @@ def getFPDT(output): i = 0 fwData = [0, 0] records = buf[36:] - fp = open(sysvals.mempath, 'rb') + try: + fp = open(sysvals.mempath, 'rb') + except: + pprint('WARNING: /dev/mem is not readable, ignoring the FPDT data') + return False while(i < len(records)): header = struct.unpack('HBB', records[i:i+4]) if(header[0] not in rectype): @@ -5282,13 +5628,14 @@ def statusCheck(probecheck=False): pprint(' is ftrace supported: %s' % res) # check if kprobes are available - res = sysvals.colorText('NO') - sysvals.usekprobes = sysvals.verifyKprobes() - if(sysvals.usekprobes): - res = 'YES' - else: - sysvals.usedevsrc = False - pprint(' are kprobes supported: %s' % res) + if sysvals.usekprobes: + res = sysvals.colorText('NO') + sysvals.usekprobes = sysvals.verifyKprobes() + if(sysvals.usekprobes): + res = 'YES' + else: + sysvals.usedevsrc = False + pprint(' are kprobes supported: %s' % res) # what data source are we using res = 'DMESG' @@ -5376,6 +5723,8 @@ def getArgFloat(name, args, min, max, main=True): def processData(live=False): pprint('PROCESSING DATA') + sysvals.vprint('usetraceevents=%s, usetracemarkers=%s, usekprobes=%s' % \ + (sysvals.usetraceevents, sysvals.usetracemarkers, sysvals.usekprobes)) error = '' if(sysvals.usetraceevents): testruns, error = parseTraceLog(live) @@ -5388,13 +5737,36 @@ def processData(live=False): parseKernelLog(data) if(sysvals.ftracefile and (sysvals.usecallgraph or sysvals.usetraceevents)): appendIncompleteTraceLog(testruns) + sysvals.vprint('System Info:') + for key in sorted(sysvals.stamp): + sysvals.vprint(' %-8s : %s' % (key.upper(), sysvals.stamp[key])) + if sysvals.kparams: + sysvals.vprint('Kparams:\n %s' % sysvals.kparams) sysvals.vprint('Command:\n %s' % sysvals.cmdline) for data in testruns: + if data.mcelog: + sysvals.vprint('MCELOG Data:') + for line in data.mcelog.split('\n'): + sysvals.vprint(' %s' % line) + if data.turbostat: + idx, s = 0, 'Turbostat:\n ' + for val in data.turbostat.split('|'): + idx += len(val) + 1 + if idx >= 80: + idx = 0 + s += '\n ' + s += val + ' ' + sysvals.vprint(s) if data.battery: a1, c1, a2, c2 = data.battery s = 'Battery:\n Before - AC: %s, Charge: %d\n After - AC: %s, Charge: %d' % \ (a1, int(c1), a2, int(c2)) sysvals.vprint(s) + if data.wifi: + w = data.wifi.replace('|', ' ').split(',') + s = 'Wifi:\n Before %s\n After %s' % \ + (w[0], w[1]) + sysvals.vprint(s) data.printDetails() if sysvals.cgdump: for data in testruns: @@ -5418,12 +5790,15 @@ def processData(live=False): # Function: rerunTest # Description: # generate an output from an existing set of ftrace/dmesg logs -def rerunTest(): +def rerunTest(htmlfile=''): if sysvals.ftracefile: doesTraceLogHaveTraceEvents() if not sysvals.dmesgfile and not sysvals.usetraceevents: doError('recreating this html output requires a dmesg file') - sysvals.setOutputFile() + if htmlfile: + sysvals.htmlfile = htmlfile + else: + sysvals.setOutputFile() if os.path.exists(sysvals.htmlfile): if not os.path.isfile(sysvals.htmlfile): doError('a directory already exists with this name: %s' % sysvals.htmlfile) @@ -5442,14 +5817,18 @@ def runTest(n=0): sysvals.initTestOutput('suspend') # execute the test - executeSuspend() + testdata = executeSuspend() sysvals.cleanupFtrace() if sysvals.skiphtml: sysvals.sudoUserchown(sysvals.testdir) return - testruns, stamp = processData(True) - for data in testruns: - del data + if not testdata[0]['error']: + testruns, stamp = processData(True) + for data in testruns: + del data + else: + stamp = testdata[0] + sysvals.sudoUserchown(sysvals.testdir) sysvals.outputResult(stamp, n) if 'error' in stamp: @@ -5479,10 +5858,13 @@ def find_in_html(html, start, end, firstonly=True): return '' return out -def data_from_html(file, outpath, devlist=False): +def data_from_html(file, outpath, issues, fulldetail=False): html = open(file, 'r').read() + sysvals.htmlfile = os.path.relpath(file, outpath) + # extract general info suspend = find_in_html(html, 'Kernel Suspend', 'ms') resume = find_in_html(html, 'Kernel Resume', 'ms') + sysinfo = find_in_html(html, '<div class="stamp sysinfo">', '</div>') line = find_in_html(html, '<div class="stamp">', '</div>') stmp = line.split() if not suspend or not resume or len(stmp) != 8: @@ -5491,6 +5873,7 @@ def data_from_html(file, outpath, devlist=False): dt = datetime.strptime(' '.join(stmp[3:]), '%B %d %Y, %I:%M:%S %p') except: return False + sysvals.hostname = stmp[0] tstr = dt.strftime('%Y/%m/%d %H:%M:%S') error = find_in_html(html, '<table class="testfail"><tr><td>', '</td>') if error: @@ -5501,13 +5884,45 @@ def data_from_html(file, outpath, devlist=False): result = 'fail' else: result = 'pass' + # extract error info ilist = [] - e = find_in_html(html, 'class="err"[\w=":;\.%\- ]*>', '→</div>', False) - for i in list(set(e)): - ilist.append('%sx%d' % (i, e.count(i)) if e.count(i) > 1 else i) + extra = dict() + log = find_in_html(html, '<div id="dmesglog" style="display:none;">', + '</div>').strip() + if log: + d = Data(0) + d.end = 999999999 + d.dmesgtext = log.split('\n') + msglist = d.extractErrorInfo() + for msg in msglist: + sysvals.errorSummary(issues, msg) + if stmp[2] == 'freeze': + extra = d.turbostatInfo() + elist = dict() + for dir in d.errorinfo: + for err in d.errorinfo[dir]: + if err[0] not in elist: + elist[err[0]] = 0 + elist[err[0]] += 1 + for i in elist: + ilist.append('%sx%d' % (i, elist[i]) if elist[i] > 1 else i) low = find_in_html(html, 'freeze time: <b>', ' ms</b>') if low and '|' in low: - ilist.append('FREEZEx%d' % len(low.split('|'))) + issue = 'FREEZEx%d' % len(low.split('|')) + match = [i for i in issues if i['match'] == issue] + if len(match) > 0: + match[0]['count'] += 1 + if sysvals.hostname not in match[0]['urls']: + match[0]['urls'][sysvals.hostname] = [sysvals.htmlfile] + elif sysvals.htmlfile not in match[0]['urls'][sysvals.hostname]: + match[0]['urls'][sysvals.hostname].append(sysvals.htmlfile) + else: + issues.append({ + 'match': issue, 'count': 1, 'line': issue, + 'urls': {sysvals.hostname: [sysvals.htmlfile]}, + }) + ilist.append(issue) + # extract device info devices = dict() for line in html.split('\n'): m = re.match(' *<div id=\"[a,0-9]*\" *title=\"(?P<title>.*)\" class=\"thread.*', line) @@ -5519,82 +5934,98 @@ def data_from_html(file, outpath, devlist=False): name, time, phase = m.group('n'), m.group('t'), m.group('p') if ' async' in name or ' sync' in name: name = ' '.join(name.split(' ')[:-1]) - d = phase.split('_')[0] + if phase.startswith('suspend'): + d = 'suspend' + elif phase.startswith('resume'): + d = 'resume' + else: + continue if d not in devices: devices[d] = dict() if name not in devices[d]: devices[d][name] = 0.0 devices[d][name] += float(time) - worst = {'suspend': {'name':'', 'time': 0.0}, - 'resume': {'name':'', 'time': 0.0}} - for d in devices: - if d not in worst: - worst[d] = dict() - dev = devices[d] - if len(dev.keys()) > 0: + # create worst device info + worst = dict() + for d in ['suspend', 'resume']: + worst[d] = {'name':'', 'time': 0.0} + dev = devices[d] if d in devices else 0 + if dev and len(dev.keys()) > 0: n = sorted(dev, key=dev.get, reverse=True)[0] worst[d]['name'], worst[d]['time'] = n, dev[n] data = { 'mode': stmp[2], 'host': stmp[0], 'kernel': stmp[1], + 'sysinfo': sysinfo, 'time': tstr, 'result': result, 'issues': ' '.join(ilist), 'suspend': suspend, 'resume': resume, + 'devlist': devices, 'sus_worst': worst['suspend']['name'], 'sus_worsttime': worst['suspend']['time'], 'res_worst': worst['resume']['name'], 'res_worsttime': worst['resume']['time'], - 'url': os.path.relpath(file, outpath), + 'url': sysvals.htmlfile, } - if devlist: - data['devlist'] = devices + for key in extra: + data[key] = extra[key] + if fulldetail: + data['funclist'] = find_in_html(html, '<div title="', '" class="traceevent"', False) return data +def genHtml(subdir): + for dirname, dirnames, filenames in os.walk(subdir): + sysvals.dmesgfile = sysvals.ftracefile = sysvals.htmlfile = '' + for filename in filenames: + if(re.match('.*_dmesg.txt', filename)): + sysvals.dmesgfile = os.path.join(dirname, filename) + elif(re.match('.*_ftrace.txt', filename)): + sysvals.ftracefile = os.path.join(dirname, filename) + sysvals.setOutputFile() + if sysvals.ftracefile and sysvals.htmlfile and \ + not os.path.exists(sysvals.htmlfile): + pprint('FTRACE: %s' % sysvals.ftracefile) + if sysvals.dmesgfile: + pprint('DMESG : %s' % sysvals.dmesgfile) + rerunTest() + # Function: runSummary # Description: # create a summary of tests in a sub-directory def runSummary(subdir, local=True, genhtml=False): inpath = os.path.abspath(subdir) outpath = os.path.abspath('.') if local else inpath - pprint('Generating a summary of folder "%s"' % inpath) + pprint('Generating a summary of folder:\n %s' % inpath) if genhtml: - for dirname, dirnames, filenames in os.walk(subdir): - sysvals.dmesgfile = sysvals.ftracefile = sysvals.htmlfile = '' - for filename in filenames: - if(re.match('.*_dmesg.txt', filename)): - sysvals.dmesgfile = os.path.join(dirname, filename) - elif(re.match('.*_ftrace.txt', filename)): - sysvals.ftracefile = os.path.join(dirname, filename) - sysvals.setOutputFile() - if sysvals.ftracefile and sysvals.htmlfile and \ - not os.path.exists(sysvals.htmlfile): - pprint('FTRACE: %s' % sysvals.ftracefile) - if sysvals.dmesgfile: - pprint('DMESG : %s' % sysvals.dmesgfile) - rerunTest() + genHtml(subdir) + issues = [] testruns = [] desc = {'host':[],'mode':[],'kernel':[]} for dirname, dirnames, filenames in os.walk(subdir): for filename in filenames: if(not re.match('.*.html', filename)): continue - data = data_from_html(os.path.join(dirname, filename), outpath) + data = data_from_html(os.path.join(dirname, filename), outpath, issues) if(not data): continue testruns.append(data) for key in desc: if data[key] not in desc[key]: desc[key].append(data[key]) - outfile = os.path.join(outpath, 'summary.html') - pprint('Summary file: %s' % outfile) + pprint('Summary files:') if len(desc['host']) == len(desc['mode']) == len(desc['kernel']) == 1: title = '%s %s %s' % (desc['host'][0], desc['kernel'][0], desc['mode'][0]) else: title = inpath - createHTMLSummarySimple(testruns, outfile, title) + createHTMLSummarySimple(testruns, os.path.join(outpath, 'summary.html'), title) + pprint(' summary.html - tabular list of test data found') + createHTMLDeviceSummary(testruns, os.path.join(outpath, 'summary-devices.html'), title) + pprint(' summary-devices.html - kernel device list sorted by total execution time') + createHTMLIssuesSummary(testruns, issues, os.path.join(outpath, 'summary-issues.html'), title) + pprint(' summary-issues.html - kernel issues found sorted by frequency') # Function: checkArgBool # Description: @@ -5839,6 +6270,7 @@ def printHelp(): ' default: suspend-{date}-{time}\n'\ ' -rtcwake t Wakeup t seconds after suspend, set t to "off" to disable (default: 15)\n'\ ' -addlogs Add the dmesg and ftrace logs to the html output\n'\ + ' -turbostat Use turbostat to execute the command in freeze mode (default: disabled)\n'\ ' -srgap Add a visible gap in the timeline between sus/res (default: disabled)\n'\ ' -skiphtml Run the test and capture the trace logs, but skip the timeline (default: disabled)\n'\ ' -result fn Export a results table to a text file for parsing.\n'\ @@ -5860,6 +6292,7 @@ def printHelp(): ' be created in a new subdirectory with a summary page.\n'\ ' [debug]\n'\ ' -f Use ftrace to create device callgraphs (default: disabled)\n'\ + ' -ftop Use ftrace on the top level call: "%s" (default: disabled)\n'\ ' -maxdepth N limit the callgraph data to N call levels (default: 0=all)\n'\ ' -expandcg pre-expand the callgraph data in the html output (default: disabled)\n'\ ' -fadd file Add functions to be graphed in the timeline from a list in a text file\n'\ @@ -5879,6 +6312,7 @@ def printHelp(): ' -status Test to see if the system is enabled to run this tool\n'\ ' -fpdt Print out the contents of the ACPI Firmware Performance Data Table\n'\ ' -battery Print out battery info (if available)\n'\ + ' -wifi Print out wifi connection info (if wireless-tools and device exists)\n'\ ' -x<mode> Test xset by toggling the given mode (on/off/standby/suspend)\n'\ ' -sysinfo Print out system info extracted from BIOS\n'\ ' -devinfo Print out the pm settings of all devices which support runtime suspend\n'\ @@ -5888,7 +6322,7 @@ def printHelp(): ' [redo]\n'\ ' -ftrace ftracefile Create HTML output using ftrace input (used with -dmesg)\n'\ ' -dmesg dmesgfile Create HTML output using dmesg (used with -ftrace)\n'\ - '' % (sysvals.title, sysvals.version, sysvals.suspendmode)) + '' % (sysvals.title, sysvals.version, sysvals.suspendmode, sysvals.ftopfunc)) return True # ----------------- MAIN -------------------- @@ -5898,7 +6332,7 @@ if __name__ == '__main__': cmd = '' simplecmds = ['-sysinfo', '-modes', '-fpdt', '-flist', '-flistall', '-devinfo', '-status', '-battery', '-xon', '-xoff', '-xstandby', - '-xsuspend', '-xinit', '-xreset', '-xstat'] + '-xsuspend', '-xinit', '-xreset', '-xstat', '-wifi'] if '-f' in sys.argv: sysvals.cgskip = sysvals.configFile('cgskip.txt') # loop through the command line arguments @@ -5930,6 +6364,10 @@ if __name__ == '__main__': sysvals.postdelay = getArgInt('-postdelay', args, 0, 60000) elif(arg == '-f'): sysvals.usecallgraph = True + elif(arg == '-ftop'): + sysvals.usecallgraph = True + sysvals.ftop = True + sysvals.usekprobes = False elif(arg == '-skiphtml'): sysvals.skiphtml = True elif(arg == '-cgdump'): @@ -5940,10 +6378,16 @@ if __name__ == '__main__': genhtml = True elif(arg == '-addlogs'): sysvals.dmesglog = sysvals.ftracelog = True + elif(arg == '-nologs'): + sysvals.dmesglog = sysvals.ftracelog = False elif(arg == '-addlogdmesg'): sysvals.dmesglog = True elif(arg == '-addlogftrace'): sysvals.ftracelog = True + elif(arg == '-turbostat'): + sysvals.tstat = True + if not sysvals.haveTurbostat(): + doError('Turbostat command not found') elif(arg == '-verbose'): sysvals.verbose = True elif(arg == '-proc'): @@ -6013,6 +6457,12 @@ if __name__ == '__main__': except: doError('No callgraph functions supplied', True) sysvals.setCallgraphFilter(val) + elif(arg == '-skipkprobe'): + try: + val = args.next() + except: + doError('No kprobe functions supplied', True) + sysvals.skipKprobes(val) elif(arg == '-cgskip'): try: val = args.next() @@ -6151,7 +6601,7 @@ if __name__ == '__main__': elif(cmd == 'devinfo'): deviceInfo() elif(cmd == 'modes'): - print getModes() + pprint(getModes()) elif(cmd == 'flist'): sysvals.getFtraceFilterFunctions(True) elif(cmd == 'flistall'): @@ -6163,11 +6613,18 @@ if __name__ == '__main__': ret = displayControl(cmd[1:]) elif(cmd == 'xstat'): pprint('Display Status: %s' % displayControl('stat').upper()) + elif(cmd == 'wifi'): + out = sysvals.checkWifi() + if 'device' not in out: + pprint('WIFI interface not found') + else: + for key in sorted(out): + pprint('%6s: %s' % (key.upper(), out[key])) sys.exit(ret) # if instructed, re-analyze existing data files if(sysvals.notestrun): - stamp = rerunTest() + stamp = rerunTest(sysvals.outdir) sysvals.outputResult(stamp) sys.exit(0) @@ -6204,7 +6661,7 @@ if __name__ == '__main__': s = 'suspend-x%d' % sysvals.multitest['count'] sysvals.outdir = datetime.now().strftime(s+'-%y%m%d-%H%M%S') if not os.path.isdir(sysvals.outdir): - os.mkdir(sysvals.outdir) + os.makedirs(sysvals.outdir) for i in range(sysvals.multitest['count']): if(i != 0): pprint('Waiting %d seconds...' % (sysvals.multitest['delay'])) |