simpleperf/README.md

   1 # Introduction of simpleperf
   2 ## What is simpleperf
   3 Simpleperf is a native profiling tool for Android. Its command-line interface
   4 supports broadly the same options as the linux-tools perf, but also supports
   5 various Android-specific improvements.
   6
   7 Simpleperf is part of the Android Open Source Project. The source code is at
   8 https://android.googlesource.com/platform/system/extras/+/master/simpleperf/.
   9 Bugs and feature requests can be submitted at
  10 http://github.com/android-ndk/ndk/issues.
  11
  12 ## How simpleperf works
  13 Modern CPUs have a hardware component called the performance monitoring unit
  14 (PMU). The PMU has several hardware counters, counting events like how many cpu
  15 cycles have happened, how many instructions have executed, or how many cache
  16 misses have happened.
  17
  18 The Linux kernel wraps these hardware counters into hardware perf events. In
  19 addition, the Linux kernel also provides hardware independent software events
  20 and tracepoint events. The Linux kernel exposes all this to userspace via the
  21 perf_event_open system call, which simpleperf uses.
  22
  23 Simpleperf has three main functions: stat, record and report.
  24
  25 The stat command gives a summary of how many events have happened in the
  26 profiled processes in a time period. Here’s how it works:
  27 1. Given user options, simpleperf enables profiling by making a system call to
  28 linux kernel.
  29 2. Linux kernel enables counters while scheduling on the profiled processes.
  30 3. After profiling, simpleperf reads counters from linux kernel, and reports a
  31 counter summary.
  32
  33 The record command records samples of the profiled process in a time period.
  34 Here’s how it works:
  35 1. Given user options, simpleperf enables profiling by making a system call to
  36 linux kernel.
  37 2. Simpleperf creates mapped buffers between simpleperf and linux kernel.
  38 3. Linux kernel enable counters while scheduling on the profiled processes.
  39 4. Each time a given number of events happen, linux kernel dumps a sample to a
  40 mapped buffer.
  41 5. Simpleperf reads samples from the mapped buffers and generates perf.data.
  42
  43 The report command reads a "perf.data" file and any shared libraries used by
  44 the profiled processes, and outputs a report showing where the time was spent.
  45
  46 ## Main simpleperf commands
  47 Simpleperf supports several subcommands, including list, stat, record, report.
  48 Each subcommand supports different options. This section only covers the most
  49 important subcommands and options. To see all subcommands and options,
  50 use --help.
  51
  52     # List all subcommands.
  53     $simpleperf --help
  54
  55     # Print help message for record subcommand.
  56     $simpleperf record --help
  57
  58 ### simpleperf list
  59 simpleperf list is used to list all events available on the device. Different
  60 devices may support different events because of differences in hardware and
  61 kernel.
  62
  63     $simpleperf list
  64     List of hw-cache events:
  65       branch-loads
  66       ...
  67     List of hardware events:
  68       cpu-cycles
  69       instructions
  70       ...
  71     List of software events:
  72       cpu-clock
  73       task-clock
  74       ...
  75
  76 ### simpleperf stat
  77 simpleperf stat is used to get a raw event counter information of the profiled program
  78 or system-wide. By passing options, we can select which events to use, which
  79 processes/threads to monitor, how long to monitor and the print interval.
  80 Below is an example.
  81
  82     # Stat using default events (cpu-cycles,instructions,...), and monitor
  83     # process 7394 for 10 seconds.
  84     $simpleperf stat -p 7394 --duration 10
  85     Performance counter statistics:
  86
  87      1,320,496,145  cpu-cycles         # 0.131736 GHz                     (100%)
  88        510,426,028  instructions       # 2.587047 cycles per instruction  (100%)
  89          4,692,338  branch-misses      # 468.118 K/sec                    (100%)
  90     886.008130(ms)  task-clock         # 0.088390 cpus used               (100%)
  91                753  context-switches   # 75.121 /sec                      (100%)
  92                870  page-faults        # 86.793 /sec                      (100%)
  93
  94     Total test time: 10.023829 seconds.
  95
  96 #### Select events
  97 We can select which events to use via -e option. Below are examples:
  98
  99     # Stat event cpu-cycles.
 100     $simpleperf stat -e cpu-cycles -p 11904 --duration 10
 101
 102     # Stat event cache-references and cache-misses.
 103     $simpleperf stat -e cache-references,cache-misses -p 11904 --duration 10
 104
 105 When running the stat command, if the number of hardware events is larger than
 106 the number of hardware counters available in the PMU, the kernel shares hardware
 107 counters between events, so each event is only monitored for part of the total
 108 time. In the example below, there is a percentage at the end of each row,
 109 showing the percentage of the total time that each event was actually monitored.
 110
 111     # Stat using event cache-references, cache-references:u,....
 112     $simpleperf stat -p 7394 -e     cache-references,cache-references:u,cache-references:k,cache-misses,cache-misses:u,cache-misses:k,instructions --duration 1
 113     Performance counter statistics:
 114
 115     4,331,018  cache-references     # 4.861 M/sec    (87%)
 116     3,064,089  cache-references:u   # 3.439 M/sec    (87%)
 117     1,364,959  cache-references:k   # 1.532 M/sec    (87%)
 118        91,721  cache-misses         # 102.918 K/sec  (87%)
 119        45,735  cache-misses:u       # 51.327 K/sec   (87%)
 120        38,447  cache-misses:k       # 43.131 K/sec   (87%)
 121     9,688,515  instructions         # 10.561 M/sec   (89%)
 122
 123     Total test time: 1.026802 seconds.
 124
 125 In the example above, each event is monitored about 87% of the total time. But
 126 there is no guarantee that any pair of events are always monitored at the same
 127 time. If we want to have some events monitored at the same time, we can use
 128 --group option. Below is an example.
 129
 130     # Stat using event cache-references, cache-references:u,....
 131     $simpleperf stat -p 7394 --group cache-references,cache-misses --group cache-references:u,cache-misses:u --group cache-references:k,cache-misses:k -e instructions --duration 1
 132     Performance counter statistics:
 133
 134     3,638,900  cache-references     # 4.786 M/sec          (74%)
 135        65,171  cache-misses         # 1.790953% miss rate  (74%)
 136     2,390,433  cache-references:u   # 3.153 M/sec          (74%)
 137        32,280  cache-misses:u       # 1.350383% miss rate  (74%)
 138       879,035  cache-references:k   # 1.251 M/sec          (68%)
 139        30,303  cache-misses:k       # 3.447303% miss rate  (68%)
 140     8,921,161  instructions         # 10.070 M/sec         (86%)
 141
 142     Total test time: 1.029843 seconds.
 143
 144 #### Select target to monitor
 145 We can select which processes or threads to monitor via -p option or -t option.
 146 Monitoring a process is the same as monitoring all threads in the process.
 147 Simpleperf can also fork a child process to run the new command and then monitor
 148 the child process. Below are examples.
 149
 150     # Stat process 11904 and 11905.
 151     $simpleperf stat -p 11904,11905 --duration 10
 152
 153     # Stat thread 11904 and 11905.
 154     $simpleperf stat -t 11904,11905 --duration 10
 155
 156     # Start a child process running `ls`, and stat it.
 157     $simpleperf stat ls
 158
 159 #### Decide how long to monitor
 160 When monitoring existing threads, we can use --duration option to decide how long
 161 to monitor. When monitoring a child process running a new command, simpleperf
 162 monitors until the child process ends. In this case, we can use Ctrl-C to stop monitoring
 163 at any time. Below are examples.
 164
 165     # Stat process 11904 for 10 seconds.
 166     $simpleperf stat -p 11904 --duration 10
 167
 168     # Stat until the child process running `ls` finishes.
 169     $simpleperf stat ls
 170
 171     # Stop monitoring using Ctrl-C.
 172     $simpleperf stat -p 11904 --duration 10
 173     ^C
 174
 175 #### Decide the print interval
 176 When monitoring perf counters, we can also use --interval option to decide the print
 177 interval. Below are examples.
 178
 179     # Print stat for process 11904 every 300ms.
 180     $simpleperf stat -p 11904 --duration 10 --interval 300
 181     # Stop by using Ctrl-C.
 182     ^C
 183
 184     # Print system wide stat at interval of 300ms for 10 seconds (rooted device only).
 185     # system wide profiling needs root privilege
 186     $su 0 simpleperf stat -a --duration 10 --interval 300
 187
 188 #### Display counters in systrace
 189 simpleperf can also work with systrace to dump counters in the collected trace.
 190 Below is an example to do a system wide stat
 191
 192     # capture instructions (kernel only) and cache misses with interval of 300 milliseconds for 15 seconds
 193     $su 0 simpleperf stat -e instructions:k,cache-misses -a --interval 300 --duration 15
 194     # on host launch systrace to collect trace for 10 seconds
 195     (HOST)$external/chromium-trace/systrace.py --time=10 -o new.html sched gfx view
 196     # open the collected new.html in browser and perf counters will be shown up
 197
 198 ### simpleperf record
 199 simpleperf record is used to dump records of the profiled program. By passing
 200 options, we can select which events to use, which processes/threads to monitor,
 201 what frequency to dump records, how long to monitor, and where to store records.
 202
 203     # Record on process 7394 for 10 seconds, using default event (cpu-cycles),
 204     # using default sample frequency (4000 samples per second), writing records
 205     # to perf.data.
 206     $simpleperf record -p 7394 --duration 10
 207     simpleperf I 07-11 21:44:11 17522 17522 cmd_record.cpp:316] Samples recorded: 21430. Samples lost: 0.
 208
 209 #### Select events
 210 In most cases, the cpu-cycles event is used to evaluate consumed cpu time.
 211 As a hardware event, it is both accurate and efficient. We can also use other
 212 events via -e option. Below is an example.
 213
 214     # Record using event instructions.
 215     $simpleperf record -e instructions -p 11904 --duration 10
 216
 217 #### Select target to monitor
 218 The way to select target in record command is similar to that in stat command.
 219 Below are examples.
 220
 221     # Record process 11904 and 11905.
 222     $simpleperf record -p 11904,11905 --duration 10
 223
 224     # Record thread 11904 and 11905.
 225     $simpleperf record -t 11904,11905 --duration 10
 226
 227     # Record a child process running `ls`.
 228     $simpleperf record ls
 229
 230 #### Set the frequency to record
 231 We can set the frequency to dump records via the -f or -c options. For example,
 232 -f 4000 means dumping approximately 4000 records every second when the monitored
 233 thread runs. If a monitored thread runs 0.2s in one second (it can be preempted
 234 or blocked in other times), simpleperf dumps about 4000 * 0.2 / 1.0 = 800
 235 records every second. Another way is using -c option. For example, -c 10000
 236 means dumping one record whenever 10000 events happen. Below are examples.
 237
 238     # Record with sample frequency 1000: sample 1000 times every second running.
 239     $simpleperf record -f 1000 -p 11904,11905 --duration 10
 240
 241     # Record with sample period 100000: sample 1 time every 100000 events.
 242     $simpleperf record -c 100000 -t 11904,11905 --duration 10
 243
 244 #### Decide how long to monitor
 245 The way to decide how long to monitor in record command is similar to that in
 246 stat command. Below are examples.
 247
 248     # Record process 11904 for 10 seconds.
 249     $simpleperf record -p 11904 --duration 10
 250
 251     # Record until the child process running `ls` finishes.
 252     $simpleperf record ls
 253
 254     # Stop monitoring using Ctrl-C.
 255     $simpleperf record -p 11904 --duration 10
 256     ^C
 257
 258 #### Set the path to store records
 259 By default, simpleperf stores records in perf.data in current directory. We can
 260 use -o option to set the path to store records. Below is an example.
 261
 262     # Write records to data/perf2.data.
 263     $simpleperf record -p 11904 -o data/perf2.data --duration 10
 264
 265 ### simpleperf report
 266 simpleperf report is used to report based on perf.data generated by simpleperf
 267 record command. Report command groups records into different sample entries,
 268 sorts sample entries based on how many events each sample entry contains, and
 269 prints out each sample entry. By passing options, we can select where to find
 270 perf.data and executable binaries used by the monitored program, filter out
 271 uninteresting records, and decide how to group records.
 272
 273 Below is an example. Records are grouped into 4 sample entries, each entry is
 274 a row. There are several columns, each column shows piece of information
 275 belonging to a sample entry. The first column is Overhead, which shows the
 276 percentage of events inside current sample entry in total events. As the
 277 perf event is cpu-cycles, the overhead can be seen as the percentage of cpu
 278 time used in each function.
 279
 280     # Reports perf.data, using only records sampled in libsudo-game-jni.so,
 281     # grouping records using thread name(comm), process id(pid), thread id(tid),
 282     # function name(symbol), and showing sample count for each row.
 283     $simpleperf report --dsos /data/app/com.example.sudogame-2/lib/arm64/libsudo-game-jni.so --sort comm,pid,tid,symbol -n
 284     Cmdline: /data/data/com.example.sudogame/simpleperf record -p 7394 --duration 10
 285     Arch: arm64
 286     Event: cpu-cycles (type 0, config 0)
 287     Samples: 28235
 288     Event count: 546356211
 289
 290     Overhead  Sample  Command    Pid   Tid   Symbol
 291     59.25%    16680   sudogame  7394  7394  checkValid(Board const&, int, int)
 292     20.42%    5620    sudogame  7394  7394  canFindSolution_r(Board&, int, int)
 293     13.82%    4088    sudogame  7394  7394  randomBlock_r(Board&, int, int, int, int, int)
 294     6.24%     1756    sudogame  7394  7394  @plt
 295
 296 #### Set the path to read records
 297 By default, simpleperf reads perf.data in current directory. We can use -i
 298 option to select another file to read records.
 299
 300     $simpleperf report -i data/perf2.data
 301
 302 #### Set the path to find executable binaries
 303 If reporting function symbols, simpleperf needs to read executable binaries
 304 used by the monitored processes to get symbol table and debug information. By
 305 default, the paths are the executable binaries used by monitored processes while
 306 recording. However, these binaries may not exist when reporting or not contain
 307 symbol table and debug information. So we can use --symfs to redirect the paths.
 308 Below is an example.
 309
 310     $simpleperf report
 311     # In this case, when simpleperf wants to read executable binary /A/b,
 312     # it reads file in /A/b.
 313
 314     $simpleperf report --symfs /debug_dir
 315     # In this case, when simpleperf wants to read executable binary /A/b,
 316     # it prefers file in /debug_dir/A/b to file in /A/b.
 317
 318 #### Filter records
 319 When reporting, it happens that not all records are of interest. Simpleperf
 320 supports five filters to select records of interest. Below are examples.
 321
 322     # Report records in threads having name sudogame.
 323     $simpleperf report --comms sudogame
 324
 325     # Report records in process 7394 or 7395
 326     $simpleperf report --pids 7394,7395
 327
 328     # Report records in thread 7394 or 7395.
 329     $simpleperf report --tids 7394,7395
 330
 331     # Report records in libsudo-game-jni.so.
 332     $simpleperf report --dsos /data/app/com.example.sudogame-2/lib/arm64/libsudo-game-jni.so
 333
 334     # Report records in function checkValid or canFindSolution_r.
 335     $simpleperf report --symbols "checkValid(Board const&, int, int);canFindSolution_r(Board&, int, int)"
 336
 337 #### Decide how to group records into sample entries
 338 Simpleperf uses --sort option to decide how to group sample entries. Below are
 339 examples.
 340
 341     # Group records based on their process id: records having the same process
 342     # id are in the same sample entry.
 343     $simpleperf report --sort pid
 344
 345     # Group records based on their thread id and thread comm: records having
 346     # the same thread id and thread name are in the same sample entry.
 347     $simpleperf report --sort tid,comm
 348
 349     # Group records based on their binary and function: records in the same
 350     # binary and function are in the same sample entry.
 351     $simpleperf report --sort dso,symbol
 352
 353     # Default option: --sort comm,pid,tid,dso,symbol. Group records in the same
 354     # thread, and belong to the same function in the same binary.
 355     $simpleperf report
 356
 357 ## Features of simpleperf
 358 Simpleperf works similar to linux-tools-perf, but it has following improvements:
 359 1. Aware of Android environment. Simpleperf handles some Android specific
 360 situations when profiling. For example, it can profile embedded shared libraries
 361 in apk, read symbol table and debug information from .gnu_debugdata section. If
 362 possible, it gives suggestions when facing errors, like how to disable
 363 perf_harden to enable profiling.
 364 2. Support unwinding while recording. If we want to use -g option to record and
 365 report call-graph of a program, we need to dump user stack and register set in
 366 each record, and then unwind the stack to find the call chain. Simpleperf
 367 supports unwinding while recording, so it doesn’t need to store user stack in
 368 perf.data. So we can profile for a longer time with limited space on device.
 369 3. Build in static binaries. Simpleperf is a static binary, so it doesn’t need
 370 supporting shared libraries to run. It means there is no limitation of Android
 371 version that simpleperf can run on, although some devices don’t support
 372 profiling.
 373
 374 # Steps to profile native libraries
 375 After introducing simpleperf, this section uses a simple example to show how to
 376 profile jni native libraries on Android using simpleperf. The example profiles
 377 an app called com.example.sudogame, which uses a jni native library
 378 sudo-game-jni.so. We focus on sudo-game-jni.so, not the java code or system
 379 libraries.
 380
 381 ## 1. Run debug version of the app on device
 382 We need to run debug version of the app, because we can’t use *run-as* for non
 383 debuggable apps.
 384
 385 ## 2. Download simpleperf to the app’s directory
 386 Use *uname* to find the architecture on device
 387
 388     $adb shell uname -m
 389     aarch64
 390
 391 "aarch64" means we should download arm64 version of simpleperf to device.
 392
 393     $adb push device/arm64/simpleperf /data/local/tmp
 394     $adb shell run-as com.example.sudogame cp /data/local/tmp/simpleperf .
 395     $adb shell run-as com.example.sudogame chmod a+x simpleperf
 396     $adb shell run-as com.example.sudogame ls -l
 397     -rwxrwxrwx 1 u0_a90 u0_a90 3059208 2016-01-01 10:40 simpleperf
 398
 399 Note that some apps use arm native libraries even on arm64 devices (We can
 400 verify this by checking /proc/<process\_id\_of\_app>/maps). In that case, we
 401 should use arm/simpleperf instead of arm64/simpleperf.
 402
 403 ## 3. Enable profiling
 404 Android devices may disable profiling by default, and we need to enable
 405 profiling.
 406
 407     $adb shell setprop security.perf_harden 0
 408
 409 ## 4. Find the target process/thread to record
 410
 411     # Use `ps` to get process id of sudogame.
 412     $adb shell ps  | grep sudogame
 413     u0_a102   15869 545   1629824 76888 SyS_epoll_ 0000000000 S com.example.sudogame
 414
 415     # Use `ps -t` to get thread ids of process 15869.
 416     # If this doesn’t work, you can try `ps -eT`.
 417     $adb shell ps -t  | grep 15869
 418     u0_a102   15869 545   1629824 76888 SyS_epoll_ 0000000000 S com.example.sudogame
 419     u0_a102   15874 15869 1629824 76888 futex_wait 0000000000 S Jit thread pool
 420     ...
 421
 422 ## 5. Record perf.data
 423
 424     # Record process 15869 for 30s, and use the app while recording it.
 425     $adb shell run-as com.example.sudogame ./simpleperf record -p 15869 --duration 30
 426     simpleperf W 07-12 20:00:33 16022 16022 environment.cpp:485] failed to read /proc/sys/kernel/kptr_restrict: Permission denied
 427     simpleperf I 07-12 20:01:03 16022 16022 cmd_record.cpp:315] Samples recorded: 81445. Samples lost: 0.
 428
 429     $adb shell run-as com.example.sudogame ls -lh perf.data
 430     -rw-rw-rw- 1 u0_a102 u0_a102 4.3M 2016-07-12 20:01 perf.data
 431
 432 Now we have recorded perf.data with 81445 records. There is a warning about
 433 failing to read kptr_restrict. It doesn’t matter in our case, but is a notification that we
 434 can’t read kernel symbol addresses.
 435
 436 ## 6. Report perf.data
 437 Below are several examples reporting on device.
 438
 439 ### Report samples in different binaries
 440
 441     # Report how samples distribute on different binaries.
 442     $adb shell run-as com.example.sudogame ./simpleperf report -n --sort dso
 443     simpleperf W 07-12 19:15:10 11389 11389 dso.cpp:309] Symbol addresses in /proc/kallsyms are all zero. `echo 0 >/proc/sys/kernel/kptr_restrict` if possible.
 444     Cmdline: /data/data/com.example.sudogame/simpleperf record -p 15869 --duration 30
 445     Arch: arm64
 446     Event: cpu-cycles (type 0, config 0)
 447     Samples: 81445
 448     Event count: 34263925309
 449
 450     Overhead  Sample  Shared Object
 451     75.31%    58231   [kernel.kallsyms]
 452     8.44%     6845    /system/lib64/libc.so
 453     4.30%     4667    /vendor/lib64/egl/libGLESv2_adreno.so
 454     2.30%     2433    /system/lib64/libhwui.so
 455     1.88%     1952    /system/lib64/libart.so
 456     1.88%     1967    /system/framework/arm64/boot-framework.oat
 457     1.59%     1218    /system/lib64/libcutils.so
 458     0.69%     728     /system/lib64/libskia.so
 459     0.63%     489     /data/app/com.example.sudogame-2/lib/arm64/libsudo-game-jni.so
 460     0.34%     312     /system/lib64/libart-compiler.so
 461     ...
 462
 463 According to the report above, most time is spent in kernel, and
 464 libsudo-game-jni.so costs only 0.63% by itself. It seems libsudo-game-jni.so
 465 can’t be the bottleneck. However, it is possible we didn’t record long enough
 466 to hit the hot spot, or code in libsudo-game-jni.so calls other libraries
 467 consuming most time.
 468
 469 ### Report samples in different functions
 470
 471     # Report how samples distribute inside libsudo-game-jni.so.
 472     $adb shell run-as com.example.sudogame ./simpleperf report -n --dsos /data/app/com.example.sudogame-2/lib/arm64/libsudo-game-jni.so --sort symbol
 473     ...
 474     Overhead  Sample  Symbol
 475     94.45%    461     unknown
 476     5.22%     26      @plt
 477     0.20%     1       Java_com_example_sudogame_GameModel_findConflictPairs
 478     0.14%     1       Java_com_example_sudogame_GameModel_canFindSolution
 479
 480 In the report above, most samples belong to unknown symbol. It is because the
 481 libsudo-game-jni.so used on device doesn’t contain symbol table. We need to
 482 download shared library with symbol table to device. In android studio 2.1.2,
 483 the binary with symbol table is in
 484 [app_dir]/app/build/intermediates/binaries/debug/obj/arm64-v8a (for amr64).
 485
 486     # Make a proper directory to download binary to device. This directory
 487     # should be the same as the directory of
 488     # /data/app/com.example.sudogame-2/lib/arm64/libsudo-game-jni.so.
 489     $adb shell run-as com.example.sudogame mkdir -p data/app/com.example.sudogame-2/lib/arm64
 490     # Download binary with symbol table.
 491     $adb push [app_dir]/app/build/intermediates/binaries/debug/obj/arm64-v8a/libsudo-game-jni.so /data/local/tmp
 492     $adb shell run-as com.example.sudogame cp /data/local/tmp/libsudo-game-jni.so data/app/com.example.sudogame-2/lib/arm64
 493
 494     # Report how samples distribute inside libsudo-game-jni.so with debug binary
 495     # support.
 496     $adb shell run-as com.example.sudogame ./simpleperf report -n --dsos /data/app/com.example.sudogame-2/lib/arm64/libsudo-game-jni.so --sort symbol --symfs .
 497     ...
 498     Overhead  Sample  Symbol
 499     71.08%    347     checkValid(Board const&, int, int)
 500     15.13%    74      randomBlock_r(Board&, int, int, int, int, int)
 501     7.94%     38      canFindSolution_r(Board&, int, int)
 502     5.22%     26      @plt
 503     0.30%     2       randomBoard(Board&)
 504     0.20%     1       Java_com_example_sudogame_GameModel_findConflictPairs
 505     0.14%     1       Java_com_example_sudogame_GameModel_canFindSolution
 506
 507 With the help of debug version of libsudo-game-jni.so, the report above shows that most
 508 time in libsudo-game-jni.so is spent in function checkValid. So now we can look
 509 into it further.
 510
 511 ### Report samples in one function
 512
 513     # Report how samples distribute inside checkValid() function.
 514     # adb shell command can’t pass ‘(‘ in arguments, so we run the command
 515     # inside `adb shell`.
 516     $adb shell
 517     device$ run-as com.example.sudogame ./simpleperf report -n --symbols "checkValid(Board const&, int, int)" --sort vaddr_in_file --symfs .
 518     ...
 519     Overhead  Sample  VaddrInFile
 520     14.90%    50      0x24d8
 521     8.48%     29      0x251c
 522     5.52%     19      0x2468
 523     ...
 524
 525 The report above shows samples hitting different places inside function
 526 checkValid(). By using objdump to disassemble libsudo-game-jni.so, we can find
 527 which are the hottest instructions in checkValid() function.
 528
 529     # Disassemble libsudo-game-jni.so.
 530     $aarch64-linux-android-objdump -d -S -l libsudo-game-jni.so >libsudo-game-jni.asm
 531
 532 ## 7. Record and report call graph
 533 ### What is a call graph
 534 A call graph is a tree showing function call relations. For example, a program
 535 starts at main() function, and main() calls functionOne() and functionTwo(),
 536 and functionOne() calls functionTwo() and functionThree(). Then the call graph
 537 is as below.
 538
 539     main() -> functionOne()
 540           |    |
 541           |    |-> functionTwo()
 542           |    |
 543           |     ->  functionThree()
 544            -> functionTwo()
 545
 546 ### Record dwarf based call graph
 547 To generate call graph, simpleperf needs to generate call chain for each record.
 548 Simpleperf requests kernel to dump user stack and user register set for each
 549 record, then it backtraces the user stack to find the function call chain. To
 550 parse the call chain, it needs support of dwarf call frame information, which
 551 usually resides in .eh_frame or .debug_frame section of the binary.  So we need
 552 to use --symfs to point out where is libsudo-game-jni.so with debug information.
 553
 554     # Record thread 11546 for 30s, use the app while recording it.
 555     $adb shell run-as com.example.sudogame ./simpleperf record -t 11546 -g --symfs . --duration 30
 556     simpleperf I 01-01 07:13:08  9415  9415 cmd_record.cpp:336] Samples recorded: 65279. Samples lost: 16740.
 557     simpleperf W 01-01 07:13:08  9415  9415 cmd_record.cpp:343] Lost 20.4099% of samples, consider increasing mmap_pages(-m), or decreasing sample frequency(-f), or increasing sample period(-c).
 558
 559     $adb shell run-as com.example.sudogame ls -lh perf.data
 560     -rw-rw-rw- 1 u0_a96 u0_a96 8.3M 2016-01-01 08:49 perf.data
 561
 562 Note that kernel can’t dump user stack >= 64K, so the dwarf based call graph
 563 doesn’t contain call chains consuming >= 64K stack. So avoiding allocating
 564 large memory on stack is a good way to improve dwarf based call graph.
 565
 566 ### Record stack frame based call graph
 567 Another way to generate call graph is to rely on the kernel parsing the call
 568 chain for each record. To make it possible, kernel has to be able to identify
 569 the stack frame of each function call. This is not always possible, because
 570 compilers can optimize away stack frames, or use a stack frame style not
 571 recognized by the kernel. So how well it works depends.
 572
 573     # Record thread 11546 for 30s, use the app while recording it.
 574     $adb shell run-as com.example.sudogame ./simpleperf record -t 11546 --call-graph fp --symfs . --duration 30
 575     simpleperf W 01-02 05:43:24 23277 23277 environment.cpp:485] failed to read /proc/sys/kernel/kptr_restrict: Permission denied
 576     simpleperf I 01-02 05:43:54 23277 23277 cmd_record.cpp:323] Samples recorded: 95023. Samples lost: 0.
 577
 578     $adb shell run-as com.example.sudogame ls -lh perf.data
 579     -rw-rw-rw- 1 u0_a96 u0_a96 39M 2016-01-02 05:43 perf.data
 580
 581 ### Report call graph
 582 #### Report call graph on device
 583     # Report call graph.
 584     $adb shell run-as com.example.sudogame ./simpleperf report -n -g --symfs .
 585     Cmdline: /data/data/com.example.sudogame/simpleperf record -t 11546 -g --symfs . -f 1000 --duration 30
 586     Arch: arm64
 587     Event: cpu-cycles (type 0, config 0)
 588     Samples: 23840
 589     Event count: 41301992088
 590
 591     Children  Self    Sample  Command          Pid    Tid    Shared Object                                                   Symbol
 592     97.98%    0.69%   162     xample.sudogame  11546  11546  /data/app/com.example.sudogame-1/lib/arm64/libsudo-game-jni.so  checkValid(Board const&, int, int)
 593        |
 594        -- checkValid(Board const&, int, int)
 595           |
 596           |--99.95%-- __android_log_print
 597           |           |
 598           |           |--92.19%-- __android_log_buf_write
 599           |           |           |
 600           |           |           |--73.50%-- libcutils.so[+1120c]
 601     ...
 602
 603 #### Report call graph in callee mode
 604 Call graph can be shown in two modes. One is caller mode, showing how functions
 605 call others. The other is callee mode, showing how functions are called by
 606 others. We can use  *-g callee* option to show call graph in callee mode.
 607
 608     # Report call graph.
 609     $host/simpleperf report -n -g callee --symfs .
 610     Cmdline: /data/data/com.example.sudogame/simpleperf record -t 11546 -g --symfs . -f 1000 --duration 30
 611     Arch: arm64
 612     Event: cpu-cycles (type 0, config 0)
 613     Samples: 23840
 614     Event count: 41301992088
 615
 616     Children  Self    Sample  Command          Pid    Tid    Shared Object                                                   Symbol
 617     97.58%    0.21%   48      xample.sudogame  11546  11546  /system/lib64/liblog.so                                         __android_log_print
 618        |
 619        -- __android_log_print
 620           |
 621           |--99.70%-- checkValid(Board const&, int, int)
 622           |           |
 623           |           |--99.31%-- canFindSolution_r(Board&, int, int)
 624     ...
 625
 626 #### Report using report.py
 627 The call graph generated by simpleperf report may be hard to read in text mode.
 628 Simpleperf provides a python script showing GUI of call graph.
 629 It can be used as below.
 630
 631     # Show call graph in GUI.
 632     $adb shell run-as com.example.sudogame ./simpleperf report -n -g --symfs . >perf.report
 633     $python report.py perf.report
 634
 635 # Steps to profile java code on rooted devices
 636 Simpleperf only supports profiling native instructions in binaries in ELF
 637 format. If the java code is executed by interpreter, or with jit cache, it
 638 can’t be profiled by simpleperf. As Android supports Ahead-of-time compilation,
 639 it can compile java bytecode into native instructions. We currently need root
 640 privilege to force Android fully compiling java code into native instructions
 641 in ELF binaries with debug information (this could be fixed by a
 642 profileable=”true” in AndroidManifest that causes PackageManager to pass -g to
 643 dex2oat). We also need root privilege to read compiled native binaries
 644 (because installd writes them to a directory whose uid/gid is system:install).
 645 So profiling java code can currently only be done on rooted devices.
 646
 647 ## 1. Fully compile java code into native instructions
 648 ### On Android N
 649
 650     # Restart adb as root. It needs root privilege to setprop below.
 651     $adb root
 652     # Set the property to compile with debug information.
 653     $adb shell setprop dalvik.vm.dex2oat-flags -g
 654
 655     # Fully compile the app instead of using interpreter or jit.
 656     $adb shell cmd package compile -f -m speed com.example.sudogame
 657
 658     # Restart the app on device.
 659
 660 ### On Android M
 661
 662     # Restart adb as root. It needs root privilege to setprop below.
 663     $adb root
 664     # Set the property to compile with debug information.
 665     $adb shell setprop dalvik.vm.dex2oat-flags -g
 666
 667     # Reinstall the app.
 668     $adb install -r app-debug.apk
 669
 670 ### On Android L
 671
 672     # Restart adb as root. It needs root privilege to setprop below.
 673     $adb root
 674     # Set the property to compile with debug information.
 675     $adb shell setprop dalvik.vm.dex2oat-flags --include-debug-symbols
 676
 677     # Reinstall the app.
 678     $adb install -r app-debug.apk
 679
 680 ## 2. Record perf.data
 681
 682     # Change to the app’s data directory.
 683     $ adb root && adb shell
 684     device# cd `run-as com.example.sudogame pwd`
 685
 686     # Record as root as simpleperf needs to read the generated native binary.
 687     device#./simpleperf record -t 25636 -g --symfs . -f 1000 --duration 30
 688     simpleperf I 01-02 07:18:20 27182 27182 cmd_record.cpp:323] Samples recorded: 23552. Samples lost: 39.
 689
 690     device#ls -lh perf.data
 691     -rw-rw-rw- 1 root root 11M 2016-01-02 07:18 perf.data
 692
 693 ## 3. Report perf.data
 694     # Report how samples distribute on different binaries.
 695     device#./simpleperf report -n --sort dso
 696     Cmdline: /data/data/com.example.sudogame/simpleperf record -t 25636 -g --symfs . -f 1000 --duration 30
 697     Arch: arm64
 698     Event: cpu-cycles (type 0, config 0)
 699     Samples: 23552
 700     Event count: 40662494587
 701
 702     Overhead  Sample  Shared Object
 703     85.73%    20042   [kernel.kallsyms]
 704     9.41%     2198    /system/lib64/libc.so
 705     2.29%     535     /system/lib64/libcutils.so
 706     0.95%     222     /data/app/com.example.sudogame-1/lib/arm64/libsudo-game-jni.so
 707     ...
 708     0.04%     16      /system/lib64/libandroid_runtime.so
 709     0.03%     10      /data/app/com.example.sudogame-1/oat/arm64/base.odex
 710     ...
 711
 712 As in the report above, there are samples in
 713 /data/app/com.example.sudogame-1/oat/arm64/base.odex, which is the native binary
 714 compiled from java code.
 715
 716     # Report call graph.
 717     device#./simpleperf report -n -g --symfs .
 718     Cmdline: /data/data/com.example.sudogame/simpleperf record -t 25636 -g --symfs . -f 1000 --duration 30
 719     Arch: arm64
 720     Event: cpu-cycles (type 0, config 0)
 721     Samples: 23552
 722     Event count: 40662494587
 723
 724     Children  Self    Sample  Command          Pid    Tid    Shared Object                                                   Symbol
 725     98.32%    0.00%   1       xample.sudogame  25636  25636  /data/app/com.example.sudogame-1/oat/arm64/base.odex            void com.example.sudogame.GameModel.reInit()
 726        |
 727        -- void com.example.sudogame.GameModel.reInit()
 728           |
 729           |--98.98%-- boolean com.example.sudogame.GameModel.canFindSolution(int[][])
 730           |           Java_com_example_sudogame_GameModel_canFindSolution
 731           |           |
 732           |           |--99.93%-- canFindSolution(Board&)
 733     ...
 734
 735 As in the report above, reInit() and canFindSolution() are java
 736 functions.