tools/power/pm-graph/README

   1                      p m - g r a p h
   2
   3    pm-graph: suspend/resume/boot timing analysis tools
   4     Version: 5.5
   5      Author: Todd Brandt <todd.e.brandt@intel.com>
   6   Home Page: https://01.org/pm-graph
   7
   8  Report bugs/issues at bugzilla.kernel.org Tools/pm-graph
   9         - https://bugzilla.kernel.org/buglist.cgi?component=pm-graph&product=Tools
  10
  11  Full documentation available online & in man pages
  12         - Getting Started:
  13           https://01.org/pm-graph/documentation/getting-started
  14
  15         - Config File Format:
  16           https://01.org/pm-graph/documentation/3-config-file-format
  17
  18         - upstream version in git:
  19           https://github.com/intel/pm-graph/
  20
  21  Requirements:
  22         - runs with python2 or python3, choice is made by /usr/bin/python link
  23         - python2 now requires python-configparser be installed
  24
  25  Table of Contents
  26         - Overview
  27         - Setup
  28         - Usage
  29                 - Basic Usage
  30                 - Dev Mode Usage
  31                 - Proc Mode Usage
  32         - Configuration Files
  33                 - Usage Examples
  34                 - Config File Options
  35         - Custom Timeline Entries
  36                 - Adding/Editing Timeline Functions
  37                 - Adding/Editing Dev Timeline Source Functions
  38                 - Verifying your Custom Functions
  39         - Testing on consumer linux Operating Systems
  40                 - Android
  41
  42 ------------------------------------------------------------------
  43 |                          OVERVIEW                              |
  44 ------------------------------------------------------------------
  45
  46  This tool suite is designed to assist kernel and OS developers in optimizing
  47  their linux stack's suspend/resume & boot time. Using a kernel image built
  48  with a few extra options enabled, the tools will execute a suspend or boot,
  49  and will capture dmesg and ftrace data. This data is transformed into a set of
  50  timelines and a callgraph to give a quick and detailed view of which devices
  51  and kernel processes are taking the most time in suspend/resume & boot.
  52
  53 ------------------------------------------------------------------
  54 |                            SETUP                               |
  55 ------------------------------------------------------------------
  56
  57     These packages are required to execute the scripts
  58        - python
  59        - python-requests
  60
  61        Ubuntu:
  62           sudo apt-get install python python-requests
  63
  64        Fedora:
  65           sudo dnf install python python-requests
  66
  67     The tools can most easily be installed via git clone and make install
  68
  69     $> git clone http://github.com/intel/pm-graph.git
  70     $> cd pm-graph
  71     $> sudo make install
  72     $> man sleepgraph ; man bootgraph
  73
  74     Setup involves some minor kernel configuration
  75
  76     The following kernel build options are required for all kernels:
  77         CONFIG_DEVMEM=y
  78         CONFIG_PM_DEBUG=y
  79         CONFIG_PM_SLEEP_DEBUG=y
  80         CONFIG_FTRACE=y
  81         CONFIG_FUNCTION_TRACER=y
  82         CONFIG_FUNCTION_GRAPH_TRACER=y
  83         CONFIG_KPROBES=y
  84         CONFIG_KPROBES_ON_FTRACE=y
  85
  86         In kernel 3.15.0, two patches were upstreamed which enable the
  87         v3.0 behavior. These patches allow the tool to read all the
  88         data from trace events instead of from dmesg. You can enable
  89         this behavior on earlier kernels with these patches:
  90
  91         (kernel/pre-3.15/enable_trace_events_suspend_resume.patch)
  92         (kernel/pre-3.15/enable_trace_events_device_pm_callback.patch)
  93
  94         If you're using a kernel older than 3.15.0, the following
  95         additional kernel parameters are required:
  96         (e.g. in file /etc/default/grub)
  97         GRUB_CMDLINE_LINUX_DEFAULT="... initcall_debug log_buf_len=32M ..."
  98
  99         If you're using a kernel older than 3.11-rc2, the following simple
 100                 patch must be applied to enable ftrace data:
 101         in file: kernel/power/suspend.c
 102         in function: int suspend_devices_and_enter(suspend_state_t state)
 103         remove call to "ftrace_stop();"
 104         remove call to "ftrace_start();"
 105
 106         There is a patch which does this for kernel v3.8.0:
 107         (kernel/pre-3.11-rc2/enable_ftrace_in_suspendresume.patch)
 108
 109
 110
 111 ------------------------------------------------------------------
 112 |                            USAGE                               |
 113 ------------------------------------------------------------------
 114
 115 Basic Usage
 116 ___________
 117
 118  1) First configure a kernel using the instructions from the previous sections.
 119     Then build, install, and boot with it.
 120  2) Open up a terminal window and execute the mode list command:
 121
 122         %> sudo ./sleepgraph.py -modes
 123                 ['freeze', 'mem', 'disk']
 124
 125  Execute a test using one of the available power modes, e.g. mem (S3):
 126
 127         %> sudo ./sleepgraph.py -m mem -rtcwake 15
 128
 129                 or with a config file
 130
 131         %> sudo ./sleepgraph.py -config config/suspend.cfg
 132
 133  When the system comes back you'll see the script finishing up and
 134  creating the output files in the test subdir. It generates output
 135  files in subdirectory: suspend-mmddyy-HHMMSS. The ftrace file can
 136  be used to regenerate the html timeline with different options
 137
 138      HTML output:                    <hostname>_<mode>.html
 139      raw dmesg output:               <hostname>_<mode>_dmesg.txt
 140      raw ftrace output:              <hostname>_<mode>_ftrace.txt
 141
 142  View the html in firefox or chrome.
 143
 144
 145 Dev Mode Usage
 146 ______________
 147
 148  Developer mode adds information on low level source calls to the timeline.
 149  The tool sets kprobes on all delay and mutex calls to see which devices
 150  are waiting for something and when. It also sets a suite of kprobes on
 151  subsystem dependent calls to better fill out the timeline.
 152
 153  The tool will also expose kernel threads that don't normally show up in the
 154  timeline. This is useful in discovering dependent threads to get a better
 155  idea of what each device is waiting for. For instance, the scsi_eh thread,
 156  a.k.a. scsi resume error handler, is what each SATA disk device waits for
 157  before it can continue resume.
 158
 159  The timeline will be much larger if run with dev mode, so it can be useful
 160  to set the -mindev option to clip out any device blocks that are too small
 161  to see easily. The following command will give a nice dev mode run:
 162
 163  %> sudo ./sleepgraph.py -m mem -rtcwake 15 -mindev 1 -dev
 164
 165         or with a config file
 166
 167  %> sudo ./sleepgraph.py -config config/suspend-dev.cfg
 168
 169
 170 Proc Mode Usage
 171 _______________
 172
 173  Proc mode adds user process info to the timeline. This is done in a manner
 174  similar to the bootchart utility, which graphs init processes and their
 175  execution as the system boots. This tool option does the same thing but for
 176  the period before and after suspend/resume.
 177
 178  In order to see any process info, there needs to be some delay before or
 179  after resume since processes are frozen in suspend_prepare and thawed in
 180  resume_complete. The predelay and postdelay args allow you to do this. It
 181  can also be useful to run in x2 mode with an x2 delay, this way you can
 182  see process activity before and after resume, and in between two
 183  successive suspend/resumes.
 184
 185  The command can be run like this:
 186
 187  %> sudo ./sleepgraph.py -m mem -rtcwake 15 -x2 -x2delay 1000 -predelay 1000 -postdelay 1000 -proc
 188
 189         or with a config file
 190
 191  %> sudo ./sleepgraph.py -config config/suspend-proc.cfg
 192
 193
 194 ------------------------------------------------------------------
 195 |                    CONFIGURATION FILES                         |
 196 ------------------------------------------------------------------
 197
 198  Since 4.0 we've moved to using config files in lieu of command line options.
 199  The config folder contains a collection of typical use cases.
 200  There are corresponding configs for other power modes:
 201
 202         Simple suspend/resume with basic timeline (mem/freeze/standby)
 203                 config/suspend.cfg
 204                 config/freeze.cfg
 205                 config/standby.cfg
 206
 207         Dev mode suspend/resume with dev timeline (mem/freeze/standby)
 208                 config/suspend-dev.cfg
 209                 config/freeze-dev.cfg
 210                 config/standby-dev.cfg
 211
 212         Simple suspend/resume with timeline and callgraph (mem/freeze/standby)
 213                 config/suspend-callgraph.cfg
 214                 config/freeze-callgraph.cfg
 215                 config/standby-callgraph.cfg
 216
 217         Sample proc mode x2 run using mem suspend
 218                 config/suspend-x2-proc.cfg
 219
 220         Sample for editing timeline funcs (moves internal functions into config)
 221                 config/custom-timeline-functions.cfg
 222
 223         Sample debug config for serio subsystem
 224                 config/debug-serio-suspend.cfg
 225
 226
 227 Usage Examples
 228 ______________
 229
 230  Run a simple mem suspend:
 231  %> sudo ./sleepgraph.py -config config/suspend.cfg
 232
 233  Run a mem suspend with callgraph data:
 234  %> sudo ./sleepgraph.py -config config/suspend-callgraph.cfg
 235
 236  Run a mem suspend with dev mode detail:
 237  %> sudo ./sleepgraph.py -config config/suspend-dev.cfg
 238
 239
 240 Config File Options
 241 ___________________
 242
 243  [Settings]
 244
 245  # Verbosity: print verbose messages (def: false)
 246  verbose: false
 247
 248  # Suspend Mode: e.g. standby, mem, freeze, disk (def: mem)
 249  mode: mem
 250
 251  # Output Directory Format: {hostname}, {date}, {time} give current values
 252  output-dir: suspend-{hostname}-{date}-{time}
 253
 254  # Automatic Wakeup: use rtcwake to wakeup after X seconds (def: infinity)
 255  rtcwake: 15
 256
 257  # Add Logs: add the dmesg and ftrace log to the html output (def: false)
 258  addlogs: false
 259
 260  # Sus/Res Gap: insert a gap between sus & res in the timeline (def: false)
 261  srgap: false
 262
 263  # Custom Command: Command to execute in lieu of suspend (def: "")
 264  command: echo mem > /sys/power/state
 265
 266  # Proc mode: graph user processes and cpu usage in the timeline (def: false)
 267  proc: false
 268
 269  # Dev mode: graph source functions in the timeline (def: false)
 270  dev: false
 271
 272  # Suspend/Resume x2: run 2 suspend/resumes back to back (def: false)
 273  x2: false
 274
 275  # x2 Suspend Delay: time delay between the two test runs in ms (def: 0 ms)
 276  x2delay: 0
 277
 278  # Pre Suspend Delay: nclude an N ms delay before (1st) suspend (def: 0 ms)
 279  predelay: 0
 280
 281  # Post Resume Delay: include an N ms delay after (last) resume (def: 0 ms)
 282  postdelay: 0
 283
 284  # Min Device Length: graph only dev callbacks longer than min (def: 0.001 ms)
 285  mindev: 0.001
 286
 287  # Callgraph: gather ftrace callgraph data on all timeline events (def: false)
 288  callgraph: false
 289
 290  # Expand Callgraph: pre-expand the callgraph treeviews in html (def: false)
 291  expandcg: false
 292
 293  # Min Callgraph Length: show callgraphs only if longer than min (def: 1 ms)
 294  mincg: 1
 295
 296  # Timestamp Precision: number of sig digits in timestamps (0:S, [3:ms], 6:us)
 297  timeprec: 3
 298
 299  # Device Filter: show only devs whose name/driver includes one of these strings
 300  devicefilter: _cpu_up,_cpu_down,i915,usb
 301
 302  # Override default timeline entries:
 303  # Do not use the internal default functions for timeline entries (def: false)
 304  # Set this to true if you intend to only use the ones defined in the config
 305  override-timeline-functions: true
 306
 307  # Override default dev timeline entries:
 308  # Do not use the internal default functions for dev timeline entries (def: false)
 309  # Set this to true if you intend to only use the ones defined in the config
 310  override-dev-timeline-functions: true
 311
 312  # Call Loop Max Gap (dev mode only)
 313  # merge loops of the same call if each is less than maxgap apart (def: 100us)
 314  callloop-maxgap: 0.0001
 315
 316  # Call Loop Max Length (dev mode only)
 317  # merge loops of the same call if each is less than maxlen in length (def: 5ms)
 318  callloop-maxlen: 0.005
 319
 320 ------------------------------------------------------------------
 321 |                   CUSTOM TIMELINE ENTRIES                      |
 322 ------------------------------------------------------------------
 323
 324 Adding or Editing Timeline Functions
 325 ____________________________________
 326
 327  The tool uses an array of function names to fill out empty spaces in the
 328  timeline where device callbacks don't appear. For instance, in suspend_prepare
 329  the tool adds the sys_sync and freeze_processes calls as virtual device blocks
 330  in the timeline to show you where the time is going. These calls should fill
 331  the timeline with contiguous data so that most kernel execution is covered.
 332
 333  It is possible to add new function calls to the timeline by adding them to
 334  the config. It's also possible to copy the internal timeline functions into
 335  the config so that you can override and edit them. Place them in the
 336  timeline_functions_ARCH section with the name of your architecture appended.
 337  i.e. for x86_64: [timeline_functions_x86_64]
 338
 339  Use the override-timeline-functions option if you only want to use your
 340  custom calls, or leave it false to append them to the internal ones.
 341
 342  This section includes a list of functions (set using kprobes) which use both
 343  symbol data and function arg data. The args are pulled directly from the
 344  stack using this architecture's registers and stack formatting. Each entry
 345  can include up to four pieces of info: The function name, a format string,
 346  an argument list, and a color. But only a function name is required.
 347
 348  For a full example config, see config/custom-timeline-functions.cfg. It pulls
 349  all the internal timeline functions into the config and allows you to edit
 350  them.
 351
 352   Entry format:
 353
 354     function: format{fn_arg1}_{fn_arg2} fn_arg1 fn_arg2 ... [color=purple]
 355
 356   Required Arguments:
 357
 358     function: The symbol name for the function you want probed, this is the
 359               minimum required for an entry, it will show up as the function
 360               name with no arguments.
 361
 362         example: _cpu_up:
 363
 364   Optional Arguments:
 365
 366     format: The format to display the data on the timeline in. Use braces to
 367             enclose the arg names.
 368
 369         example: CPU_ON[{cpu}]
 370
 371     color: The color of the entry block in the timeline. The default color is
 372            transparent, so the entry shares the phase color. The color is an
 373            html color string, either a word, or an RGB.
 374
 375         example: [color=#CC00CC]
 376
 377     arglist: A list of arguments from registers/stack addresses. See URL:
 378              https://www.kernel.org/doc/Documentation/trace/kprobetrace.txt
 379
 380         example: cpu=%di:s32
 381
 382  Here is a full example entry. It displays cpu resume calls in the timeline
 383  in orange. They will appear as CPU_ON[0], CPU_ON[1], etc.
 384
 385   [timeline_functions_x86_64]
 386   _cpu_up: CPU_ON[{cpu}] cpu=%di:s32 [color=orange]
 387
 388
 389 Adding or Editing Dev Mode Timeline Source Functions
 390 ____________________________________________________
 391
 392  In dev mode, the tool uses an array of function names to monitor source
 393  execution within the timeline entries.
 394
 395  The function calls are displayed inside the main device/call blocks in the
 396  timeline. However, if a function call is not within a main timeline event,
 397  it will spawn an entirely new event named after the caller's kernel thread.
 398  These asynchronous kernel threads will populate in a separate section
 399  beneath the main device/call section.
 400
 401  The tool has a set of hard coded calls which focus on the most common use
 402  cases: msleep, udelay, schedule_timeout, mutex_lock_slowpath, etc. These are
 403  the functions that add a hardcoded time delay to the suspend/resume path.
 404  The tool also includes some common functions native to important
 405  subsystems: ata, i915, and ACPI, etc.
 406
 407  It is possible to add new function calls to the dev timeline by adding them
 408  to the config. It's also possible to copy the internal dev timeline
 409  functions into the config so that you can override and edit them. Place them
 410  in the dev_timeline_functions_ARCH section with the name of your architecture
 411  appended. i.e. for x86_64: [dev_timeline_functions_x86_64]
 412
 413  Use the override-dev-timeline-functions option if you only want to use your
 414  custom calls, or leave it false to append them to the internal ones.
 415
 416  The format is the same as the timeline_functions_x86_64 section. It's a
 417  list of functions (set using kprobes) which use both symbol data and function
 418  arg data. The args are pulled directly from the stack using this
 419  architecture's registers and stack formatting. Each entry can include up
 420  to four pieces of info: The function name, a format string, an argument list,
 421  and a color. But only the function name is required.
 422
 423  For a full example config, see config/custom-timeline-functions.cfg. It pulls
 424  all the internal dev timeline functions into the config and allows you to edit
 425  them.
 426
 427  Here is a full example entry. It displays the ATA port reset calls as
 428  ataN_port_reset in the timeline. This is where most of the SATA disk resume
 429  time goes, so it can be helpful to see the low level call.
 430
 431   [dev_timeline_functions_x86_64]
 432   ata_eh_recover: ata{port}_port_reset port=+36(%di):s32 [color=#CC00CC]
 433
 434
 435 Verifying your custom functions
 436 _______________________________
 437
 438  Once you have a set of functions (kprobes) defined, it can be useful to
 439  perform a quick check to see if you formatted them correctly and if the system
 440  actually supports them. To do this, run the tool with your config file
 441  and the -status option. The tool will go through all the kprobes (both
 442  custom and internal if you haven't overridden them) and actually attempts
 443  to set them in ftrace. It will then print out success or fail for you.
 444
 445  Note that kprobes which don't actually exist in the kernel won't stop the
 446  tool, they just wont show up.
 447
 448  For example:
 449
 450  sudo ./sleepgraph.py -config config/custom-timeline-functions.cfg -status
 451  Checking this system (myhostname)...
 452     have root access: YES
 453     is sysfs mounted: YES
 454     is "mem" a valid power mode: YES
 455     is ftrace supported: YES
 456     are kprobes supported: YES
 457     timeline data source: FTRACE (all trace events found)
 458     is rtcwake supported: YES
 459     verifying timeline kprobes work:
 460          _cpu_down: YES
 461          _cpu_up: YES
 462          acpi_pm_finish: YES
 463          acpi_pm_prepare: YES
 464          freeze_kernel_threads: YES
 465          freeze_processes: YES
 466          sys_sync: YES
 467          thaw_processes: YES
 468     verifying dev kprobes work:
 469          __const_udelay: YES
 470          __mutex_lock_slowpath: YES
 471          acpi_os_stall: YES
 472          acpi_ps_parse_aml: YES
 473          intel_opregion_init: NO
 474          intel_opregion_register: NO
 475          intel_opregion_setup: NO
 476          msleep: YES
 477          schedule_timeout: YES
 478          schedule_timeout_uninterruptible: YES
 479          usleep_range: YES
 480
 481
 482 ------------------------------------------------------------------
 483 |           TESTING ON CONSUMER LINUX OPERATING SYSTEMS          |
 484 ------------------------------------------------------------------
 485
 486 Android
 487 _______
 488
 489  The easiest way to execute on an android device is to run the android.sh
 490  script on the device, then pull the ftrace log back to the host and run
 491  sleepgraph.py on it.
 492
 493  Here are the steps:
 494
 495  [download and install the tool on the device]
 496
 497         host%> wget https://raw.githubusercontent.com/intel/pm-graph/master/tools/android.sh
 498         host%> adb connect 192.168.1.6
 499         host%> adb root
 500         # push the script to a writeable location
 501         host%> adb push android.sh /sdcard/
 502
 503  [check whether the tool will run on your device]
 504
 505         host%> adb shell
 506         dev%> cd /sdcard
 507         dev%> sh android.sh status
 508                 host    : asus_t100
 509                 kernel  : 3.14.0-i386-dirty
 510                 modes   : freeze mem
 511                 rtcwake : supported
 512                 ftrace  : supported
 513                 trace events {
 514                     suspend_resume: found
 515                     device_pm_callback_end: found
 516                     device_pm_callback_start: found
 517                 }
 518         # the above is what you see on a system that's properly patched
 519
 520  [execute the suspend]
 521
 522         # NOTE: The suspend will only work if the screen isn't timed out,
 523         # so you have to press some keys first to wake it up b4 suspend)
 524         dev%> sh android.sh suspend mem
 525         ------------------------------------
 526         Suspend/Resume timing test initiated
 527         ------------------------------------
 528         hostname   : asus_t100
 529         kernel     : 3.14.0-i386-dirty
 530         mode       : mem
 531         ftrace out : /mnt/shell/emulated/0/ftrace.txt
 532         dmesg out  : /mnt/shell/emulated/0/dmesg.txt
 533         log file   : /mnt/shell/emulated/0/log.txt
 534         ------------------------------------
 535         INITIALIZING FTRACE........DONE
 536         STARTING FTRACE
 537         SUSPEND START @ 21:24:02 (rtcwake in 10 seconds)
 538         <adb connection will now terminate>
 539
 540  [retrieve the data from the device]
 541
 542         # I find that you have to actually kill the adb process and
 543         # reconnect sometimes in order for the connection to work post-suspend
 544         host%> adb connect 192.168.1.6
 545         # (required) get the ftrace data, this is the most important piece
 546         host%> adb pull /sdcard/ftrace.txt
 547         # (optional) get the dmesg data, this is for debugging
 548         host%> adb pull /sdcard/dmesg.txt
 549         # (optional) get the log, which just lists some test times for comparison
 550         host%> adb pull /sdcard/log.txt
 551
 552  [create an output html file using sleepgraph.py]
 553
 554         host%> sleepgraph.py -ftrace ftrace.txt
 555
 556  You should now have an output.html with the android data, enjoy!