Open littlewhywhat opened 6 years ago
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
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)
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
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.
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
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
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
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
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
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.
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
unfortunately CPU didn't go more than 2 % in this example, so command above will make blank output.
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.
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 |
---------------------------------------------------------------------------------------
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
create and describe procedure to make some meaningful output