Create usage example

[littlewhywhat]

emulator #./data/extrace
usage: ./data/extrace [options]
options include:
  -a app_package  enable app-level tracing for a comma
                  separated list of package names
  -b N            use a trace buffer size of N KB
  -c              trace into a circular buffer
  -d aname,...    trace the listed android categories
  -e kname,...    trace the listed kernel categories
  -f filename     use the categories written in a file as space-separated
                    values in a line
  -p N            period of memory measurement
  -m N            number of periods to pass
  -pids N,...     PIDs to take memory measurement of
  -minCpu N       minimal CPU usage that should trace record have to display to user
  -minUss N       minimal Uss that should a trace record have to be displayed to user
  -n              ignore signals
  -s N            sleep for N seconds before tracing [default 0]
  -t N            trace for N seconds [default 5]
  -z              compress the trace dump
  --async_start   start circular trace and return immediatly
  --async_dump    dump the current contents of circular trace buffer
  --async_stop    stop tracing and dump the current contents of circular
                    trace buffer
  --stream        stream trace to outstream as it enters the trace buffer
                    Note: this can take significant CPU time, and is best
                    used for measuring things that are not affected by
                    CPU performance, like pagecache usage.
  --list_categories
                  list the available tracing categories
 -o filename      write the trace to the specified file instead
                    of outstream.
 --acore          add core services.

[littlewhywhat]

Using emulator, let's try to get some trace events specifically from com.android.dialer application package by starting the following command:

./data/extrace -a com.android.dialer -t 10 2>/dev/null 

and interacting with dialer application in some way.

[littlewhywhat]

it doesn't output anything because of #36. However, if fixed this is a sample of output:

<...>-2045  (-----) [000] ...1   831.982360: tracing_mark_write: B|2045|DialtactsActivity onResume
<...>-2045  (-----) [000] ...1   831.984003: tracing_mark_write: E
<...>-2045  (-----) [000] ...1   831.984016: tracing_mark_write: B|2045|ListsFragment onResume
<...>-2045  (-----) [000] ...1   831.986657: tracing_mark_write: E
<...>-2045  (-----) [000] ...1   831.986668: tracing_mark_write: B|2045|SpeedDialFragment onResume
<...>-2045  (-----) [000] ...1   831.986928: tracing_mark_write: E
<...>-2045  (-----) [000] ...1   831.990852: tracing_mark_write: B|2045|DialpadFragment onResume
<...>-2045  (-----) [000] ...1   831.995592: tracing_mark_write: E
<...>-2045  (-----) [000] ...1   832.035598: tracing_mark_write: B|2045|RV OnLayout
<...>-2045  (-----) [000] ...1   832.035783: tracing_mark_write: B|2045|RV OnBindView
<...>-2045  (-----) [000] ...1   832.035789: tracing_mark_write: B|2045|onBindViewHolder: 0

[littlewhywhat]

now to get cpu usage it's necessary to see switches of processes. Therefore, let's give an option of kernel category sched that includes kernel tracepoint sched_switch

./data/extrace -a com.android.dialer -e sched -t 10 2>/dev/null  

[littlewhywhat]

now we can see things similar to these:

.android.dialer-2045  ( 2045) [000] ...1  1500.925775: tracing_mark_write: B|2045|showFragment - tag_callcard_fragment
.android.dialer-2045  ( 2045) [000] ...1  1500.925862: tracing_mark_write: B|2045|CallCardFragment onCreate
.android.dialer-2045  ( 2045) [000] dNh5  1500.928193: sched_wakeup: comm=SensorService pid=1343 prio=89 success=1 target_cpu=000
.android.dialer-2045  ( 2045) [000] d..3  1500.928201: sched_switch: prev_comm=.android.dialer prev_pid=2045 prev_prio=110 prev_state=R ==> next_comm=SensorService next_pid=1343 next_prio=89
  SensorService-1343  ( 1311) [000] d..5  1500.928245: sched_wakeup: comm=android.ui pid=1326 prio=118 success=1 target_cpu=000
  SensorService-1343  ( 1311) [000] d..3  1500.928264: sched_switch: prev_comm=SensorService prev_pid=1343 prev_prio=89 prev_state=S ==> next_comm=android.ui next_pid=1326 next_prio=118

[littlewhywhat]

let's add memory measurements and imply more friendly output.

We will specify pids for dialer and SensorService as 2045 and 1343. Period will be 1ms or 1000000ns and number of periods will be 1000 for ~25s of trace. (period here is a sleep between measurements and as measurements records take time, overall time of trace is Trace = (Period + measurementTime) * numberOfPeriods). It's necessary also to specify output file - for example, /data/out. Output will be very long for this command. It's better to store result in a file by direction of output

./data/extrace -a com.android.dialer -e sched -t 10 -p 1000000 -m 1000 -pids 2045,1343 -o /data/out 2>/dev/null > /data/after_out

[littlewhywhat]

Example of output:

---------------------------------------------------------------------------------------
 | 2045|onBindViewHolder: 6
---------------------------------------------------------------------------------------
 |  1343 |   0 % |  783228K |  125480K |   72107K |   63060K |  3928317006 | SLEEPING |
---------------------------------------------------------------------------------------
 | 2045|RV CreateView
---------------------------------------------------------------------------------------
 |  1343 |   0 % |  783228K |  125480K |   72107K |   63060K |  3928319100 | SLEEPING |
---------------------------------------------------------------------------------------
 | 2045|RV OnBindView
---------------------------------------------------------------------------------------
 |  1343 |   0 % |  783228K |  125480K |   72107K |   63060K |  3928319106 | SLEEPING |
---------------------------------------------------------------------------------------
 | 2045|onBindViewHolder: 7
---------------------------------------------------------------------------------------
 |  1343 |   0 % |  783228K |  125560K |   72189K |   63144K |  3928337821 | SLEEPING |
---------------------------------------------------------------------------------------
 | MemTrace
--------------------------------------------------------------------------------------- 
 |  1343 |   0 % |  783228K |  125560K |   72189K |   63144K |  3928342621 |    AWAKE |
---------------------------------------------------------------------------------------
 | SchedWakeup
---------------------------------------------------------------------------------------

While CPU Usage is not really comprehensive, it's possible to see that 3rd column from right (USS - unique set size) has increase in value after another event of onBindViewHolder in 2045.

[littlewhywhat]

Here this OnBindView is more illustrative:

---------------------------------------------------------------------------------------
 | 2045|RV OnBindView
---------------------------------------------------------------------------------------
 |  2045 |   3 % |  733804K |   93472K |   39352K |   31312K |  3928319106 |  RUNNING |
---------------------------------------------------------------------------------------
 | 2045|onBindViewHolder: 7
---------------------------------------------------------------------------------------
 |  2045 |   3 % |  733804K |   93472K |   39352K |   31312K |  3928320098 | SLEEPING |
---------------------------------------------------------------------------------------
 | SchedSwitch
---------------------------------------------------------------------------------------
 |  2045 |   3 % |  733804K |   93472K |   39352K |   31312K |  3928320123 |    AWAKE |
---------------------------------------------------------------------------------------

You can see that something like 1000 K were added with OnBindView

[littlewhywhat]

Let's output only records with CPU usage bigger than 10%:

./data/extrace --interpret -pids 2045,1343 -o /data/out -minCPU 10 2>/dev/null > /data/after_out_cpu

[littlewhywhat]

There are only switch process events with this value of CPU usage

[littlewhywhat]

Once you apply CPU usage filter you can apply also memory filter to see if there was some change in memory

[littlewhywhat]

There is only one event and that means that memory didn't increase during these records

Sequence of events for PID = 2045
 *   PID | CPU  |     VSS  |     RSS  |     PSS  |     USS  |   TIMESTAMP |    STATE |
---------------------------------------------------------------------------------------
 |  2045 |  20 % |  733804K |   93868K |   39750K |   31712K |  3922162031 | SLEEPING |
---------------------------------------------------------------------------------------
 | SchedSwitch
---------------------------------------------------------------------------------------