summaryrefslogtreecommitdiffstats
path: root/tools/power/pm-graph
diff options
context:
space:
mode:
authorRafael J. Wysocki <rafael.j.wysocki@intel.com>2019-06-13 11:06:21 +0200
committerRafael J. Wysocki <rafael.j.wysocki@intel.com>2019-06-13 11:06:21 +0200
commitd382084f77b0b4c3eb594cfec893d116c21fb034 (patch)
tree02ed7b4ba4f90e458a303c483ce055e7414918a8 /tools/power/pm-graph
parentMerge tag 'linux-cpupower-5.2-rc6' of git://git.kernel.org/pub/scm/linux/kern... (diff)
parentAdd README and update pm-graph and sleepgraph docs (diff)
downloadlinux-d382084f77b0b4c3eb594cfec893d116c21fb034.tar.xz
linux-d382084f77b0b4c3eb594cfec893d116c21fb034.zip
Merge back earlier pm-tools material for v5.3.
Diffstat (limited to 'tools/power/pm-graph')
-rw-r--r--tools/power/pm-graph/README552
-rwxr-xr-xtools/power/pm-graph/bootgraph.py8
-rw-r--r--tools/power/pm-graph/config/example.cfg26
-rw-r--r--tools/power/pm-graph/sleepgraph.816
-rwxr-xr-xtools/power/pm-graph/sleepgraph.py857
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+' &rarr; '+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, '_', ' &nbsp;')
+ name = phase.replace('_', ' &nbsp;')
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=":;\.%\- ]*>', '&rarr;</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']))