_
_ __ _ __ ___ __ _ _ __ __ _ _ __ | |__
| '_ \| '_ ` _ \ _____ / _` | '__/ _` | '_ \| '_ \
| |_) | | | | | |_____| (_| | | | (_| | |_) | | | |
| .__/|_| |_| |_| \__, |_| \__,_| .__/|_| |_|
|_| |___/ |_|
pm-graph: suspend/resume/boot timing analysis tools
Version: 5.9
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
- Endurance Testing
- Usage Examples
- 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 |
------------------------------------------------------------------
Package Requirements
- runs with python2 or python3, choice is made by /usr/bin/python link
- python
- python-configparser (for python2 sleepgraph)
- python-requests (for stresstester.py)
- linux-tools-common (for turbostat usage in sleepgraph)
Ubuntu:
sudo apt-get install python python-configparser python-requests linux-tools-common
Fedora:
sudo dnf install python python-configparser python-requests linux-tools-common
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 bootgraph, or sleepgraph with 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
------------------------------------------------------------------
| ENDURANCE TESTING |
------------------------------------------------------------------
The best way to gauge the health of a system is to run a series of
suspend/resumes over an extended period and analyze the behavior. This can be
accomplished with sleepgraph's -multi argument. You specify two numbers: the
number of tests to run OR the duration in days, hours, or minutes, and the
delay in seconds between them. For instance, -multi 20 5: execute 20 tests with
a 5 second delay between each, or -multi 24h 0: execute tests over a 24 hour
period with no delay between tests. You can include any other options you like
to generate the data you want. It's most useful to collect dev mode timelines
as the kprobes don't alter the performance much and you get more insight.
On completion, the output folder contains a series of folders for the
individual test data and a set of summary pages in the root. The summary.html
file is a tabular list of the tests with relevant info and links. The
summary-issue.html and summary-devices.html files include data taken from
all tests on kernel issues and device performance. The folder looks like this:
suspend-xN-{date}-{time}:
summary.html
summary-issues.html
summary-devices.html
suspend-{date}-{time} (1)
suspend-{date}-{time} (2)
...
These are the relevant arguments to use for testing:
-m mode
Mode to initiate for suspend e.g. mem, freeze, standby (default: mem).
-rtcwake t
Use rtcwake to autoresume after t seconds (default: 15).
-gzip (optional)
Gzip the trace and dmesg logs to save space. The tool can also read in
gzipped logs for processing. This reduces the multitest folder size.
-dev (optional)
Add kernel source calls and threads to the timeline (default: disabled).
-multi n d
Execute n consecutive tests at d seconds intervals. The outputs will be
created in a new subdirectory: suspend-xN-{date}-{time}. When the multitest
run is done, the -summary command is called automatically to create summary
html files for all the data (unless you use -skiphtml). -skiphtml will
speed up the testing by not creating timelines or summary html files. You
can then run the tool again at a later time with -summary and -genhtml to
create the timelines.
-skiphtml (optional)
Run the test and capture the trace logs, but skip the timeline and summary
html generation. This can greatly speed up overall testing. You can then
copy the data to a faster host machine and run -summary -genhtml to
generate the timelines and summary.
These are the relevant commands to use after testing is complete:
-summary indir
Generate or regenerate the summary for a -multi test run. Creates three
files: summary.html, summary-issues.html, and summary-devices.html in the
current folder. summary.html is a table of tests with relevant info sorted
by kernel/host/mode, and links to the test html files. summary-issues.html
is a list of kernel issues found in dmesg from all the tests.
summary-devices.html is a list of devices and times from all the tests.
-genhtml
Used with -summary to regenerate any missing html timelines from their
dmesg and ftrace logs. This will require a significant amount of time if
there are thousands of tests.
Usage Examples
_______________
A multitest is initiated like this:
%> sudo ./sleepgraph.py -m mem -rtcwake 10 -dev -gzip -multi 2000 0
or you can skip timeline generation in order to speed things up
%> sudo ./sleepgraph.py -m mem -rtcwake 10 -dev -gzip -multi 2000 0 -skiphtml
The tool will produce an output folder with all the test subfolders inside.
Each test subfolder contains the dmesg/ftrace logs and/or the html timeline
depending on whether you used the -skiphtml option. The root folder contains
the summary.html files.
The summary for an existing multitest is generated like this:
%> cd suspend-x2000-{date}-{time}
%> sleepgraph.py -summary .
or if you need to generate the html timelines you can use -genhtml
%> cd suspend-xN-{date}-{time}
%> sleepgraph.py -summary . -genhtml
------------------------------------------------------------------
| 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!
b3f6c43d00