_ _ __ _ __ ___ __ _ _ __ __ _ _ __ | |__ | '_ \| '_ ` _ \ _____ / _` | '__/ _` | '_ \| '_ \ | |_) | | | | | |_____| (_| | | | (_| | |_) | | | | | .__/|_| |_| |_| \__, |_| \__,_| .__/|_| |_| |_| |___/ |_| pm-graph: suspend/resume/boot timing analysis tools Version: 5.6 Author: Todd Brandt 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 googlesheet.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 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: _.html raw dmesg output: __dmesg.txt raw ftrace output: __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) [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!