661 lines · plain
1 _2 _ __ _ __ ___ __ _ _ __ __ _ _ __ | |__3 | '_ \| '_ ` _ \ _____ / _` | '__/ _` | '_ \| '_ \4 | |_) | | | | | |_____| (_| | | | (_| | |_) | | | |5 | .__/|_| |_| |_| \__, |_| \__,_| .__/|_| |_|6 |_| |___/ |_|7 8 pm-graph: suspend/resume/boot timing analysis tools9 Version: 5.1110 Author: Todd Brandt <todd.e.brandt@intel.com>11 Home Page: https://www.intel.com/content/www/us/en/developer/topic-technology/open/pm-graph/overview.html12 13 Report bugs/issues at bugzilla.kernel.org Tools/pm-graph14 - https://bugzilla.kernel.org/buglist.cgi?component=pm-graph&product=Tools15 16 Full documentation available online & in man pages17 - Getting Started:18 https://www.intel.com/content/www/us/en/developer/articles/technical/usage.html19 20 - Feature Summary:21 https://www.intel.com/content/www/us/en/developer/topic-technology/open/pm-graph/features.html22 23 - upstream version in git:24 git clone https://github.com/intel/pm-graph/25 26 Table of Contents27 - Overview28 - Setup29 - Usage30 - Basic Usage31 - Dev Mode Usage32 - Proc Mode Usage33 - Endurance Testing34 - Usage Examples35 - Configuration Files36 - Usage Examples37 - Config File Options38 - Custom Timeline Entries39 - Adding/Editing Timeline Functions40 - Adding/Editing Dev Timeline Source Functions41 - Verifying your Custom Functions42 - Testing on consumer linux Operating Systems43 - Android44 45------------------------------------------------------------------46| OVERVIEW |47------------------------------------------------------------------48 49 This tool suite is designed to assist kernel and OS developers in optimizing50 their linux stack's suspend/resume & boot time. Using a kernel image built51 with a few extra options enabled, the tools will execute a suspend or boot,52 and will capture dmesg and ftrace data. This data is transformed into a set of53 timelines and a callgraph to give a quick and detailed view of which devices54 and kernel processes are taking the most time in suspend/resume & boot.55 56------------------------------------------------------------------57| SETUP |58------------------------------------------------------------------59 60 Package Requirements61 - runs with python2 or python3, choice is made by /usr/bin/python link62 - python63 - python-configparser (for python2 sleepgraph)64 - python-requests (for stresstester.py)65 - linux-tools-common (for turbostat usage in sleepgraph)66 67 Ubuntu:68 sudo apt-get install python python-configparser python-requests linux-tools-common69 70 Fedora:71 sudo dnf install python python-configparser python-requests linux-tools-common72 73 The tools can most easily be installed via git clone and make install74 75 $> git clone http://github.com/intel/pm-graph.git76 $> cd pm-graph77 $> sudo make install78 $> man sleepgraph ; man bootgraph79 80 Setup involves some minor kernel configuration81 82 The following kernel build options are required for all kernels:83 CONFIG_DEVMEM=y84 CONFIG_PM_DEBUG=y85 CONFIG_PM_SLEEP_DEBUG=y86 CONFIG_FTRACE=y87 CONFIG_FUNCTION_TRACER=y88 CONFIG_FUNCTION_GRAPH_TRACER=y89 CONFIG_KPROBES=y90 CONFIG_KPROBES_ON_FTRACE=y91 92 In kernel 3.15.0, two patches were upstreamed which enable the93 v3.0 behavior. These patches allow the tool to read all the94 data from trace events instead of from dmesg. You can enable95 this behavior on earlier kernels with these patches:96 97 (kernel/pre-3.15/enable_trace_events_suspend_resume.patch)98 (kernel/pre-3.15/enable_trace_events_device_pm_callback.patch)99 100 If you're using bootgraph, or sleepgraph with a kernel older than 3.15.0,101 the following additional kernel parameters are required:102 (e.g. in file /etc/default/grub)103 GRUB_CMDLINE_LINUX_DEFAULT="... initcall_debug log_buf_len=32M ..."104 105 If you're using a kernel older than 3.11-rc2, the following simple106 patch must be applied to enable ftrace data:107 in file: kernel/power/suspend.c108 in function: int suspend_devices_and_enter(suspend_state_t state)109 remove call to "ftrace_stop();"110 remove call to "ftrace_start();"111 112 There is a patch which does this for kernel v3.8.0:113 (kernel/pre-3.11-rc2/enable_ftrace_in_suspendresume.patch)114 115 116 117------------------------------------------------------------------118| USAGE |119------------------------------------------------------------------120 121Basic Usage122___________123 124 1) First configure a kernel using the instructions from the previous sections.125 Then build, install, and boot with it.126 2) Open up a terminal window and execute the mode list command:127 128 %> sudo ./sleepgraph.py -modes129 ['freeze', 'mem', 'disk']130 131 Execute a test using one of the available power modes, e.g. mem (S3):132 133 %> sudo ./sleepgraph.py -m mem -rtcwake 15134 135 or with a config file136 137 %> sudo ./sleepgraph.py -config config/suspend.cfg138 139 When the system comes back you'll see the script finishing up and140 creating the output files in the test subdir. It generates output141 files in subdirectory: suspend-mmddyy-HHMMSS. The ftrace file can142 be used to regenerate the html timeline with different options143 144 HTML output: <hostname>_<mode>.html145 raw dmesg output: <hostname>_<mode>_dmesg.txt146 raw ftrace output: <hostname>_<mode>_ftrace.txt147 148 View the html in firefox or chrome.149 150 151Dev Mode Usage152______________153 154 Developer mode adds information on low level source calls to the timeline.155 The tool sets kprobes on all delay and mutex calls to see which devices156 are waiting for something and when. It also sets a suite of kprobes on157 subsystem dependent calls to better fill out the timeline.158 159 The tool will also expose kernel threads that don't normally show up in the160 timeline. This is useful in discovering dependent threads to get a better161 idea of what each device is waiting for. For instance, the scsi_eh thread,162 a.k.a. scsi resume error handler, is what each SATA disk device waits for163 before it can continue resume.164 165 The timeline will be much larger if run with dev mode, so it can be useful166 to set the -mindev option to clip out any device blocks that are too small167 to see easily. The following command will give a nice dev mode run:168 169 %> sudo ./sleepgraph.py -m mem -rtcwake 15 -mindev 1 -dev170 171 or with a config file172 173 %> sudo ./sleepgraph.py -config config/suspend-dev.cfg174 175 176Proc Mode Usage177_______________178 179 Proc mode adds user process info to the timeline. This is done in a manner180 similar to the bootchart utility, which graphs init processes and their181 execution as the system boots. This tool option does the same thing but for182 the period before and after suspend/resume.183 184 In order to see any process info, there needs to be some delay before or185 after resume since processes are frozen in suspend_prepare and thawed in186 resume_complete. The predelay and postdelay args allow you to do this. It187 can also be useful to run in x2 mode with an x2 delay, this way you can188 see process activity before and after resume, and in between two189 successive suspend/resumes.190 191 The command can be run like this:192 193 %> sudo ./sleepgraph.py -m mem -rtcwake 15 -x2 -x2delay 1000 -predelay 1000 -postdelay 1000 -proc194 195 or with a config file196 197 %> sudo ./sleepgraph.py -config config/suspend-proc.cfg198 199------------------------------------------------------------------200| ENDURANCE TESTING |201------------------------------------------------------------------202 203 The best way to gauge the health of a system is to run a series of204 suspend/resumes over an extended period and analyze the behavior. This can be205 accomplished with sleepgraph's -multi argument. You specify two numbers: the206 number of tests to run OR the duration in days, hours, or minutes, and the207 delay in seconds between them. For instance, -multi 20 5: execute 20 tests with208 a 5 second delay between each, or -multi 24h 0: execute tests over a 24 hour209 period with no delay between tests. You can include any other options you like210 to generate the data you want. It's most useful to collect dev mode timelines211 as the kprobes don't alter the performance much and you get more insight.212 213 On completion, the output folder contains a series of folders for the214 individual test data and a set of summary pages in the root. The summary.html215 file is a tabular list of the tests with relevant info and links. The216 summary-issue.html and summary-devices.html files include data taken from217 all tests on kernel issues and device performance. The folder looks like this:218 219 suspend-xN-{date}-{time}:220 summary.html221 summary-issues.html222 summary-devices.html223 suspend-{date}-{time} (1)224 suspend-{date}-{time} (2)225 ...226 227 These are the relevant arguments to use for testing:228 229 -m mode230 Mode to initiate for suspend e.g. mem, freeze, standby (default: mem).231 232 -rtcwake t233 Use rtcwake to autoresume after t seconds (default: 15).234 235 -gzip (optional)236 Gzip the trace and dmesg logs to save space. The tool can also read in237 gzipped logs for processing. This reduces the multitest folder size.238 239 -dev (optional)240 Add kernel source calls and threads to the timeline (default: disabled).241 242 -multi n d243 Execute n consecutive tests at d seconds intervals. The outputs will be244 created in a new subdirectory: suspend-xN-{date}-{time}. When the multitest245 run is done, the -summary command is called automatically to create summary246 html files for all the data (unless you use -skiphtml). -skiphtml will247 speed up the testing by not creating timelines or summary html files. You248 can then run the tool again at a later time with -summary and -genhtml to249 create the timelines.250 251 -skiphtml (optional)252 Run the test and capture the trace logs, but skip the timeline and summary253 html generation. This can greatly speed up overall testing. You can then254 copy the data to a faster host machine and run -summary -genhtml to255 generate the timelines and summary.256 257 These are the relevant commands to use after testing is complete:258 259 -summary indir260 Generate or regenerate the summary for a -multi test run. Creates three261 files: summary.html, summary-issues.html, and summary-devices.html in the262 current folder. summary.html is a table of tests with relevant info sorted263 by kernel/host/mode, and links to the test html files. summary-issues.html264 is a list of kernel issues found in dmesg from all the tests.265 summary-devices.html is a list of devices and times from all the tests.266 267 -genhtml268 Used with -summary to regenerate any missing html timelines from their269 dmesg and ftrace logs. This will require a significant amount of time if270 there are thousands of tests.271 272Usage Examples273_______________274 275 A multitest is initiated like this:276 277 %> sudo ./sleepgraph.py -m mem -rtcwake 10 -dev -gzip -multi 2000 0278 279 or you can skip timeline generation in order to speed things up280 281 %> sudo ./sleepgraph.py -m mem -rtcwake 10 -dev -gzip -multi 2000 0 -skiphtml282 283 The tool will produce an output folder with all the test subfolders inside.284 Each test subfolder contains the dmesg/ftrace logs and/or the html timeline285 depending on whether you used the -skiphtml option. The root folder contains286 the summary.html files.287 288 The summary for an existing multitest is generated like this:289 290 %> cd suspend-x2000-{date}-{time}291 %> sleepgraph.py -summary .292 293 or if you need to generate the html timelines you can use -genhtml294 295 %> cd suspend-xN-{date}-{time}296 %> sleepgraph.py -summary . -genhtml297 298------------------------------------------------------------------299| CONFIGURATION FILES |300------------------------------------------------------------------301 302 Since 4.0 we've moved to using config files in lieu of command line options.303 The config folder contains a collection of typical use cases.304 There are corresponding configs for other power modes:305 306 Simple suspend/resume with basic timeline (mem/freeze/standby)307 config/suspend.cfg308 config/freeze.cfg309 config/standby.cfg310 311 Dev mode suspend/resume with dev timeline (mem/freeze/standby)312 config/suspend-dev.cfg313 config/freeze-dev.cfg314 config/standby-dev.cfg315 316 Simple suspend/resume with timeline and callgraph (mem/freeze/standby)317 config/suspend-callgraph.cfg318 config/freeze-callgraph.cfg319 config/standby-callgraph.cfg320 321 Sample proc mode x2 run using mem suspend322 config/suspend-x2-proc.cfg323 324 Sample for editing timeline funcs (moves internal functions into config)325 config/custom-timeline-functions.cfg326 327 Sample debug config for serio subsystem328 config/debug-serio-suspend.cfg329 330 331Usage Examples332______________333 334 Run a simple mem suspend:335 %> sudo ./sleepgraph.py -config config/suspend.cfg336 337 Run a mem suspend with callgraph data:338 %> sudo ./sleepgraph.py -config config/suspend-callgraph.cfg339 340 Run a mem suspend with dev mode detail:341 %> sudo ./sleepgraph.py -config config/suspend-dev.cfg342 343 344Config File Options345___________________346 347 [Settings]348 349 # Verbosity: print verbose messages (def: false)350 verbose: false351 352 # Suspend Mode: e.g. standby, mem, freeze, disk (def: mem)353 mode: mem354 355 # Output Directory Format: {hostname}, {date}, {time} give current values356 output-dir: suspend-{hostname}-{date}-{time}357 358 # Automatic Wakeup: use rtcwake to wakeup after X seconds (def: infinity)359 rtcwake: 15360 361 # Add Logs: add the dmesg and ftrace log to the html output (def: false)362 addlogs: false363 364 # Sus/Res Gap: insert a gap between sus & res in the timeline (def: false)365 srgap: false366 367 # Custom Command: Command to execute in lieu of suspend (def: "")368 command: echo mem > /sys/power/state369 370 # Proc mode: graph user processes and cpu usage in the timeline (def: false)371 proc: false372 373 # Dev mode: graph source functions in the timeline (def: false)374 dev: false375 376 # Suspend/Resume x2: run 2 suspend/resumes back to back (def: false)377 x2: false378 379 # x2 Suspend Delay: time delay between the two test runs in ms (def: 0 ms)380 x2delay: 0381 382 # Pre Suspend Delay: nclude an N ms delay before (1st) suspend (def: 0 ms)383 predelay: 0384 385 # Post Resume Delay: include an N ms delay after (last) resume (def: 0 ms)386 postdelay: 0387 388 # Min Device Length: graph only dev callbacks longer than min (def: 0.001 ms)389 mindev: 0.001390 391 # Callgraph: gather ftrace callgraph data on all timeline events (def: false)392 callgraph: false393 394 # Expand Callgraph: pre-expand the callgraph treeviews in html (def: false)395 expandcg: false396 397 # Min Callgraph Length: show callgraphs only if longer than min (def: 1 ms)398 mincg: 1399 400 # Timestamp Precision: number of sig digits in timestamps (0:S, [3:ms], 6:us)401 timeprec: 3402 403 # Device Filter: show only devs whose name/driver includes one of these strings404 devicefilter: _cpu_up,_cpu_down,i915,usb405 406 # Override default timeline entries:407 # Do not use the internal default functions for timeline entries (def: false)408 # Set this to true if you intend to only use the ones defined in the config409 override-timeline-functions: true410 411 # Override default dev timeline entries:412 # Do not use the internal default functions for dev timeline entries (def: false)413 # Set this to true if you intend to only use the ones defined in the config414 override-dev-timeline-functions: true415 416 # Call Loop Max Gap (dev mode only)417 # merge loops of the same call if each is less than maxgap apart (def: 100us)418 callloop-maxgap: 0.0001419 420 # Call Loop Max Length (dev mode only)421 # merge loops of the same call if each is less than maxlen in length (def: 5ms)422 callloop-maxlen: 0.005423 424------------------------------------------------------------------425| CUSTOM TIMELINE ENTRIES |426------------------------------------------------------------------427 428Adding or Editing Timeline Functions429____________________________________430 431 The tool uses an array of function names to fill out empty spaces in the432 timeline where device callbacks don't appear. For instance, in suspend_prepare433 the tool adds the sys_sync and freeze_processes calls as virtual device blocks434 in the timeline to show you where the time is going. These calls should fill435 the timeline with contiguous data so that most kernel execution is covered.436 437 It is possible to add new function calls to the timeline by adding them to438 the config. It's also possible to copy the internal timeline functions into439 the config so that you can override and edit them. Place them in the440 timeline_functions_ARCH section with the name of your architecture appended.441 i.e. for x86_64: [timeline_functions_x86_64]442 443 Use the override-timeline-functions option if you only want to use your444 custom calls, or leave it false to append them to the internal ones.445 446 This section includes a list of functions (set using kprobes) which use both447 symbol data and function arg data. The args are pulled directly from the448 stack using this architecture's registers and stack formatting. Each entry449 can include up to four pieces of info: The function name, a format string,450 an argument list, and a color. But only a function name is required.451 452 For a full example config, see config/custom-timeline-functions.cfg. It pulls453 all the internal timeline functions into the config and allows you to edit454 them.455 456 Entry format:457 458 function: format{fn_arg1}_{fn_arg2} fn_arg1 fn_arg2 ... [color=purple]459 460 Required Arguments:461 462 function: The symbol name for the function you want probed, this is the463 minimum required for an entry, it will show up as the function464 name with no arguments.465 466 example: _cpu_up:467 468 Optional Arguments:469 470 format: The format to display the data on the timeline in. Use braces to471 enclose the arg names.472 473 example: CPU_ON[{cpu}]474 475 color: The color of the entry block in the timeline. The default color is476 transparent, so the entry shares the phase color. The color is an477 html color string, either a word, or an RGB.478 479 example: [color=#CC00CC]480 481 arglist: A list of arguments from registers/stack addresses. See URL:482 https://www.kernel.org/doc/Documentation/trace/kprobetrace.txt483 484 example: cpu=%di:s32485 486 Here is a full example entry. It displays cpu resume calls in the timeline487 in orange. They will appear as CPU_ON[0], CPU_ON[1], etc.488 489 [timeline_functions_x86_64]490 _cpu_up: CPU_ON[{cpu}] cpu=%di:s32 [color=orange]491 492 493Adding or Editing Dev Mode Timeline Source Functions494____________________________________________________495 496 In dev mode, the tool uses an array of function names to monitor source497 execution within the timeline entries.498 499 The function calls are displayed inside the main device/call blocks in the500 timeline. However, if a function call is not within a main timeline event,501 it will spawn an entirely new event named after the caller's kernel thread.502 These asynchronous kernel threads will populate in a separate section503 beneath the main device/call section.504 505 The tool has a set of hard coded calls which focus on the most common use506 cases: msleep, udelay, schedule_timeout, mutex_lock_slowpath, etc. These are507 the functions that add a hardcoded time delay to the suspend/resume path.508 The tool also includes some common functions native to important509 subsystems: ata, i915, and ACPI, etc.510 511 It is possible to add new function calls to the dev timeline by adding them512 to the config. It's also possible to copy the internal dev timeline513 functions into the config so that you can override and edit them. Place them514 in the dev_timeline_functions_ARCH section with the name of your architecture515 appended. i.e. for x86_64: [dev_timeline_functions_x86_64]516 517 Use the override-dev-timeline-functions option if you only want to use your518 custom calls, or leave it false to append them to the internal ones.519 520 The format is the same as the timeline_functions_x86_64 section. It's a521 list of functions (set using kprobes) which use both symbol data and function522 arg data. The args are pulled directly from the stack using this523 architecture's registers and stack formatting. Each entry can include up524 to four pieces of info: The function name, a format string, an argument list,525 and a color. But only the function name is required.526 527 For a full example config, see config/custom-timeline-functions.cfg. It pulls528 all the internal dev timeline functions into the config and allows you to edit529 them.530 531 Here is a full example entry. It displays the ATA port reset calls as532 ataN_port_reset in the timeline. This is where most of the SATA disk resume533 time goes, so it can be helpful to see the low level call.534 535 [dev_timeline_functions_x86_64]536 ata_eh_recover: ata{port}_port_reset port=+36(%di):s32 [color=#CC00CC]537 538 539Verifying your custom functions540_______________________________541 542 Once you have a set of functions (kprobes) defined, it can be useful to543 perform a quick check to see if you formatted them correctly and if the system544 actually supports them. To do this, run the tool with your config file545 and the -status option. The tool will go through all the kprobes (both546 custom and internal if you haven't overridden them) and actually attempts547 to set them in ftrace. It will then print out success or fail for you.548 549 Note that kprobes which don't actually exist in the kernel won't stop the550 tool, they just wont show up.551 552 For example:553 554 sudo ./sleepgraph.py -config config/custom-timeline-functions.cfg -status555 Checking this system (myhostname)...556 have root access: YES557 is sysfs mounted: YES558 is "mem" a valid power mode: YES559 is ftrace supported: YES560 are kprobes supported: YES561 timeline data source: FTRACE (all trace events found)562 is rtcwake supported: YES563 verifying timeline kprobes work:564 _cpu_down: YES565 _cpu_up: YES566 acpi_pm_finish: YES567 acpi_pm_prepare: YES568 freeze_kernel_threads: YES569 freeze_processes: YES570 sys_sync: YES571 thaw_processes: YES572 verifying dev kprobes work:573 __const_udelay: YES574 __mutex_lock_slowpath: YES575 acpi_os_stall: YES576 acpi_ps_parse_aml: YES577 intel_opregion_init: NO578 intel_opregion_register: NO579 intel_opregion_setup: NO580 msleep: YES581 schedule_timeout: YES582 schedule_timeout_uninterruptible: YES583 usleep_range: YES584 585 586------------------------------------------------------------------587| TESTING ON CONSUMER LINUX OPERATING SYSTEMS |588------------------------------------------------------------------589 590Android591_______592 593 The easiest way to execute on an android device is to run the android.sh594 script on the device, then pull the ftrace log back to the host and run595 sleepgraph.py on it.596 597 Here are the steps:598 599 [download and install the tool on the device]600 601 host%> wget https://raw.githubusercontent.com/intel/pm-graph/master/tools/android.sh602 host%> adb connect 192.168.1.6603 host%> adb root604 # push the script to a writeable location605 host%> adb push android.sh /sdcard/606 607 [check whether the tool will run on your device]608 609 host%> adb shell610 dev%> cd /sdcard611 dev%> sh android.sh status612 host : asus_t100613 kernel : 3.14.0-i386-dirty614 modes : freeze mem615 rtcwake : supported616 ftrace : supported617 trace events {618 suspend_resume: found619 device_pm_callback_end: found620 device_pm_callback_start: found621 }622 # the above is what you see on a system that's properly patched623 624 [execute the suspend]625 626 # NOTE: The suspend will only work if the screen isn't timed out,627 # so you have to press some keys first to wake it up b4 suspend)628 dev%> sh android.sh suspend mem629 ------------------------------------630 Suspend/Resume timing test initiated631 ------------------------------------632 hostname : asus_t100633 kernel : 3.14.0-i386-dirty634 mode : mem635 ftrace out : /mnt/shell/emulated/0/ftrace.txt636 dmesg out : /mnt/shell/emulated/0/dmesg.txt637 log file : /mnt/shell/emulated/0/log.txt638 ------------------------------------639 INITIALIZING FTRACE........DONE640 STARTING FTRACE641 SUSPEND START @ 21:24:02 (rtcwake in 10 seconds)642 <adb connection will now terminate>643 644 [retrieve the data from the device]645 646 # I find that you have to actually kill the adb process and647 # reconnect sometimes in order for the connection to work post-suspend648 host%> adb connect 192.168.1.6649 # (required) get the ftrace data, this is the most important piece650 host%> adb pull /sdcard/ftrace.txt651 # (optional) get the dmesg data, this is for debugging652 host%> adb pull /sdcard/dmesg.txt653 # (optional) get the log, which just lists some test times for comparison654 host%> adb pull /sdcard/log.txt655 656 [create an output html file using sleepgraph.py]657 658 host%> sleepgraph.py -ftrace ftrace.txt659 660 You should now have an output.html with the android data, enjoy!661