Create usage example #44

littlewhywhat · 2018-05-22T13:34:52Z

create and describe procedure to make some meaningful output

littlewhywhat · 2018-05-22T13:37:06Z

options for extrace:

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.
 --interpret      interpret dump file only

and here is the list of supported categories for android and kernel:

emulator:/ # ./data/extrace --list_categories                                                                                                                                                               
       sched  Scheduling
         irq  IRQ Events
        freq  CPU Frequency
        idle  CPU Idle
        disk  Disk I/O
         mmc  eMMC commands
        sync  Synchronization
   workqueue  Kernel Workqueues
  memreclaim  Kernel Memory Reclaim
  binder_driver  Binder Kernel driver
  binder_lock  Binder global lock trace
     filemap  Page cache
         gfx  Graphics
       input  Input
        view  View System
     webview  WebView
          wm  Window Manager
          am  Activity Manager
          sm  Sync Manager
       audio  Audio
       video  Video
      camera  Camera
         hal  Hardware Modules
         app  Application
         res  Resource Loading
      dalvik  Dalvik VM
          rs  RenderScript
      bionic  Bionic C Library
       power  Power Management
          pm  Package Manager
          ss  System Server
    database  Database
     network  Network

littlewhywhat · 2018-05-22T13:40:25Z

at first we need to collect some information for our future report. We will constantly extend command to involve more parameters.

we need to specify pid and package that we want to trace. Let's choose them from top command output:

 1450 u0_a24   20   0   0% S    26 748408K  95592K  fg com.android.systemui
 1594 radio    20   0   0% S    26 727040K  70000K  fg com.android.phone
 1759 u0_a12   20   0   0% S    10 690324K  45304K  fg android.ext.services
 1801 u0_a14   20   0   0% S    12 703584K  68684K  bg com.android.launcher
 1858 u0_a1    20   0   0% S    17 711252K  60348K  fg android.process.acore
 1928 u0_a53   20   0   0% S    10 686552K  40428K  fg com.android.smspush
 1951 u0_a10   20   0   0% S    13 698404K  54712K  bg android.process.media
 1974 u0_a51   20   0   0% S    10 690664K  42584K  bg com.android.printspooler
 2012 u0_a2    20   0   0% S    11 691696K  46972K  bg com.android.providers.calendar
 2045 u0_a8    10 -10   0% S    15 733480K  93792K  fg com.android.dialer
    1 root     20   0   0% S     1  10448K   1664K  fg /init
 2107 u0_a38   20   0   0% S    12 707152K  50972K  bg com.android.email
 2146 u0_a54   20   0   0% S    11 707596K  55808K  bg com.android.messaging
 2167 u0_a17   20   0   0% S    10 688460K  41000K  bg com.android.onetimeinitializer
 2227 root     20   0   0% S     1   8308K   1772K  fg /system/bin/sh
 2300 u0_a1    20   0   0% S    10 688416K  40752K  bg com.android.calllogbackup
 2448 root     20   0   0% T     1  13284K   4048K  fg ./data/extrace
 2523 root     20   0   0% S     1      0K      0K  fg kworker/0:1
 2537 root     20   0   0% T     1  13284K   4060K  fg ./data/extrace
 2539 root     20   0   0% T     1  13284K   4052K  fg ./data/extrace
 2820 u0_a36   20   0   0% S    10 696144K  43572K  bg com.android.deskclock
 2930 root     20   0   0% R     1   9872K   2116K  fg top
 2066 u0_a31   20   0   0% S    15 698408K  46876K  bg com.android.calendar

let's choose calendar (2066) or dialer (2045)

littlewhywhat · 2018-05-22T13:41:11Z

let's try to get some output specific for calendar:

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

calendar doesn't give any output. Maybe it's better to use dialer for illustration:

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

littlewhywhat · 2018-05-22T13:45:36Z

this is what we get:

 .android.dialer-2045  ( 2045) [000] ...1 34627.408855: tracing_mark_write: B|2045|RV OnBindView
 .android.dialer-2045  ( 2045) [000] ...1 34627.408859: tracing_mark_write: B|2045|onBindViewHolder: 6
 .android.dialer-2045  ( 2045) [000] ...1 34627.409296: tracing_mark_write: E
 .android.dialer-2045  ( 2045) [000] ...1 34627.409298: tracing_mark_write: E
 .android.dialer-2045  ( 2045) [000] ...1 34627.409503: tracing_mark_write: B|2045|RV CreateView
 .android.dialer-2045  ( 2045) [000] ...1 34627.410357: tracing_mark_write: E
 .android.dialer-2045  ( 2045) [000] ...1 34627.410362: tracing_mark_write: B|2045|RV OnBindView
 .android.dialer-2045  ( 2045) [000] ...1 34627.410366: tracing_mark_write: B|2045|onBindViewHolder: 7
 .android.dialer-2045  ( 2045) [000] ...1 34627.410829: tracing_mark_write: E
 .android.dialer-2045  ( 2045) [000] ...1 34627.410831: tracing_mark_write: E

this records are provided by atrace. Application just uses some properties to turn this logging on.

littlewhywhat · 2018-05-22T13:50:14Z

let's add also sched kernel category that is necessary for CPU usage calculations:

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

littlewhywhat · 2018-05-22T13:51:40Z

now we get a lot of records from kernel using ftrace about changes of process state. this information also includes our processes:

  surfaceflinger-1036  ( 1036) [000] d..3 35043.265729: sched_switch: prev_comm=surfaceflinger prev_pid=1036 prev_prio=98 prev_state=D ==> next_comm=rcu_preempt next_pid=7 next_prio=120
     rcu_preempt-7     (    7) [000] d..3 35043.265731: sched_switch: prev_comm=rcu_preempt prev_pid=7 prev_prio=120 prev_state=S ==> next_comm=EventThread next_pid=1084 next_prio=111
     EventThread-1084  ( 1036) [000] d..5 35043.265736: sched_wakeup: comm=.android.dialer pid=2045 prio=110 success=1 target_cpu=000
     EventThread-1084  ( 1036) [000] d..3 35043.265738: sched_switch: prev_comm=EventThread prev_pid=1084 prev_prio=111 prev_state=S ==> next_comm=.android.dialer next_pid=2045 next_prio=110
 .android.dialer-2045  ( 2045) [000] d..3 35043.265782: sched_switch: prev_comm=.android.dialer prev_pid=2045 prev_prio=110 prev_state=S ==> next_comm=swapper next_pid=0 next_prio=120
          <idle>-0     (-----) [000] dNh6 35043.265783: sched_wakeup: comm=AudioOut_D pid=1065 prio=101 success=1 target_cpu=000

littlewhywhat · 2018-05-22T13:57:12Z

now let's try what kind of events could be get from, for example, view and am while we will interact with dialer.

./data/extrace -d view,am -t 10 2>/dev/null

littlewhywhat · 2018-05-22T13:59:34Z

we get some more interesting android events:

 .android.dialer-2045  ( 2045) [000] ...1 35519.665306: tracing_mark_write: B|2045|Choreographer#doFrame
 .android.dialer-2045  ( 2045) [000] ...1 35519.665316: tracing_mark_write: B|2045|input
 .android.dialer-2045  ( 2045) [000] ...1 35519.665325: tracing_mark_write: E
 .android.dialer-2045  ( 2045) [000] ...1 35519.665328: tracing_mark_write: B|2045|animation
 .android.dialer-2045  ( 2045) [000] ...1 35519.665444: tracing_mark_write: E
 .android.dialer-2045  ( 2045) [000] ...1 35519.665449: tracing_mark_write: B|2045|traversal
 .android.dialer-2045  ( 2045) [000] ...1 35519.665481: tracing_mark_write: B|2045|draw

littlewhywhat · 2018-05-22T14:02:54Z

let's add memory measurements and as it is our last extension for now, we will save trace output to file /data/out.

We will specify pid for dialer 2045.
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 could be nice to reserve more memory for buffer.

./data/extrace -d view,am -a com.android.dialer -e sched -p 1000000 -m 1000 -pids 2045 -o /data/out 2>/dev/null

littlewhywhat · 2018-05-22T14:07:56Z

the above command also outputs first interpretation (parsing of trace records):

---------------------------------------------------------------------------------------
 |  2045 |   2 % |  735816K |   94448K |   38816K |   30892K | 35786965899 |  RUNNING |
---------------------------------------------------------------------------------------
 | 2045|buildDrawingCache/SW Layer for FrameLayout
---------------------------------------------------------------------------------------
 |  2045 |   2 % |  735816K |   94448K |   38816K |   30892K | 35786966083 | SLEEPING |
---------------------------------------------------------------------------------------
 | SchedSwitch
---------------------------------------------------------------------------------------
 |  2045 |   2 % |  735816K |   94448K |   38816K |   30892K | 35786966116 |    AWAKE |
---------------------------------------------------------------------------------------
 | SchedWakeup
---------------------------------------------------------------------------------------
 |  2045 |   2 % |  735816K |   94448K |   38816K |   30892K | 35786966942 |  RUNNING |
---------------------------------------------------------------------------------------
 | SchedSwitch
---------------------------------------------------------------------------------------
 |  2045 |   2 % |  735816K |   94448K |   38816K |   30892K | 35786966963 |  RUNNING |
---------------------------------------------------------------------------------------
 | 2045|commit
---------------------------------------------------------------------------------------
 |  2045 |   2 % |  735816K |   94448K |   38816K |   30892K | 35786966982 | SLEEPING |
---------------------------------------------------------------------------------------
 | SchedSwitch
---------------------------------------------------------------------------------------
 |  2045 |   2 % |  735816K |   93860K |   38228K |   30304K | 35786972701 | SLEEPING |
---------------------------------------------------------------------------------------
 | MemTrace
---------------------------------------------------------------------------------------

here we can see that process was running dureing build of DrawingCache and then went to sleep for a bit of time. Then again woke up to commit and again went to sleep releasing some memory.

littlewhywhat · 2018-05-22T14:10:32Z

now it's possible to filter created output using this command, for example, to show only high cpu usage:

./data/extrace --interpret -pids 2045 -o /data/out -minCpu 3

littlewhywhat · 2018-05-22T14:14:50Z

unfortunately CPU didn't go more than 2 % in this example, so command above will make blank output.

littlewhywhat · 2018-05-22T14:18:59Z

last thing that we could try is to use memory limit for Uss or Unique set size as so:

./data/extrace --interpret -pids 2045 -o /data/out -minUss 10

this command will take first record with memory and based on it find records that have at least 10 K gain.

littlewhywhat · 2018-05-22T14:20:45Z

we get some records even for 100 K. For example, like that:

---------------------------------------------------------------------------------------
 | 1311|com.android.server.wm.WindowManagerService$H: #41
---------------------------------------------------------------------------------------
 |  2045 |   2 % |  735816K |   94448K |   38816K |   30892K | 35786956284 | SLEEPING |
---------------------------------------------------------------------------------------
 | 1311|com.android.server.policy.PhoneWindowManager$PolicyHandler: com.android.server.policy.PhoneWindowManager$21
---------------------------------------------------------------------------------------
 |  2045 |   2 % |  735816K |   94448K |   38816K |   30892K | 35786956651 |    AWAKE |
---------------------------------------------------------------------------------------
 | SchedWakeup
---------------------------------------------------------------------------------------
 |  2045 |   2 % |  735816K |   94448K |   38816K |   30892K | 35786956731 |    AWAKE |
---------------------------------------------------------------------------------------
 | 1311|android.view.Choreographer$FrameHandler: #1
---------------------------------------------------------------------------------------
 |  2045 |   2 % |  735816K |   94448K |   38816K |   30892K | 35786956759 |  RUNNING |
---------------------------------------------------------------------------------------

littlewhywhat · 2018-05-22T14:23:19Z

by increasing memory limit constantly it's possible to find out that maximum was 344:

./data/extrace --interpret -pids 2045 -o /data/out -minUss 344

littlewhywhat added the thesis label May 22, 2018

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Create usage example #44

Create usage example #44

littlewhywhat commented May 22, 2018 •

edited

Loading

littlewhywhat commented May 22, 2018 •

edited

Loading

littlewhywhat commented May 22, 2018 •

edited

Loading

littlewhywhat commented May 22, 2018 •

edited

Loading

littlewhywhat commented May 22, 2018

littlewhywhat commented May 22, 2018 •

edited

Loading

littlewhywhat commented May 22, 2018 •

edited

Loading

littlewhywhat commented May 22, 2018 •

edited

Loading

littlewhywhat commented May 22, 2018

littlewhywhat commented May 22, 2018

littlewhywhat commented May 22, 2018

littlewhywhat commented May 22, 2018 •

edited

Loading

littlewhywhat commented May 22, 2018

littlewhywhat commented May 22, 2018

littlewhywhat commented May 22, 2018

littlewhywhat commented May 22, 2018

Create usage example #44

Create usage example #44

Comments

littlewhywhat commented May 22, 2018 • edited Loading

littlewhywhat commented May 22, 2018 • edited Loading

littlewhywhat commented May 22, 2018 • edited Loading

littlewhywhat commented May 22, 2018 • edited Loading

littlewhywhat commented May 22, 2018

littlewhywhat commented May 22, 2018 • edited Loading

littlewhywhat commented May 22, 2018 • edited Loading

littlewhywhat commented May 22, 2018 • edited Loading

littlewhywhat commented May 22, 2018

littlewhywhat commented May 22, 2018

littlewhywhat commented May 22, 2018

littlewhywhat commented May 22, 2018 • edited Loading

littlewhywhat commented May 22, 2018

littlewhywhat commented May 22, 2018

littlewhywhat commented May 22, 2018

littlewhywhat commented May 22, 2018

littlewhywhat commented May 22, 2018 •

edited

Loading

littlewhywhat commented May 22, 2018 •

edited

Loading

littlewhywhat commented May 22, 2018 •

edited

Loading

littlewhywhat commented May 22, 2018 •

edited

Loading

littlewhywhat commented May 22, 2018 •

edited

Loading

littlewhywhat commented May 22, 2018 •

edited

Loading

littlewhywhat commented May 22, 2018 •

edited

Loading

littlewhywhat commented May 22, 2018 •

edited

Loading