linux/tools/power/pm-graph

                                                _
    _ __  _ __ ___         __ _ _ __ __ _ _ __ | |__
   | '_ \| '_ ` _ \ _____ / _` | '__/ _` | '_ \| '_ \
   | |_) | | | | | |_____| (_| | | | (_| | |_) | | | |
   | .__/|_| |_| |_|      \__, |_|  \__,_| .__/|_| |_|
   |_|                    |___/          |_|

   pm-graph: suspend/resume/boot timing analysis tools
    Version: 5.10
     Author: Todd Brandt <todd.e.brandt@intel.com>
  Home Page: https://www.intel.com/content/www/us/en/developer/topic-technology/open/pm-graph/overview.html

 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://www.intel.com/content/www/us/en/developer/articles/technical/usage.html

	- Feature Summary:
	  https://www.intel.com/content/www/us/en/developer/topic-technology/open/pm-graph/features.html

	- upstream version in git:
	  git clone 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!