上篇提到抖音 Android 性能优化系列：新一代全能型性能分析工具 Rhea，该工具主要使用了 android atrace 功能，为了能在代码里使用 atrace，同时熟悉该命令行参数。因为之前随便看了一篇 atrace 使用文档，async-dump 命令后面还接着一堆 categories，直接给我看蒙了，还是自己研究吧。
直接 RTFSC，幸好就一个 cpp 文件，还是很简单的。
atrace 用法
usage: atrace [options] [categories...]
options include:
-a appname enable app-level tracing for a comma separated list of cmdlines
-b N use a trace buffer size of N KB
-c trace into a circular buffer
-f filename use the categories written in a file as space-separated
values in a line
-k fname,... trace the listed kernel functions
-n ignore signals
-s N sleep for N seconds before tracing [default 0]
-t N trace for N seconds [defualt 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 stdout 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 stdout.
示例
atrace --list_categories
atrace -a com.example.toy --async_start app binder_lock
atrace --async_dump
atrace --async_stop -o /sdcard/rawtrace.txt
list_categories
列出支持的categories，以下是在某个Android N 设备执行命令时的输出
atrace --list_categories
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
hwui - HWUI
perf - Performance
bionic - Bionic C Library
power - Power Management
pm - Package Manager
ss - System Server
database - Database
sched - CPU Scheduling
freq - CPU Frequency
idle - CPU Idle
load - CPU Load
memreclaim - Kernel Memory Reclaim
binder_driver - Binder Kernel driver
binder_lock - Binder global lock trace
找到 atrace 命令行工具的源码 frameworks/native/cmds/atrace/atrace.cpp
--list_categories参数就是判断代码中 TracingCategory 数组 k_categories[] 的每一项是否支持。
typedef enum { OPT, REQ } requiredness ;
struct TracingCategory {
// The name identifying the category.
const char* name;
// A longer description of the category.
const char* longname;
// The userland tracing tags that the category enables.
uint64_t tags;
// The fname==NULL terminated list of /sys/ files that the category
// enables.
struct {
// Whether the file must be writable in order to enable the tracing
// category.
requiredness required;
// The path to the enable file.
const char* path;
} sysfiles[MAX_SYS_FILES];
};
/* Tracing categories */
static const TracingCategory k_categories[] = {
{ "gfx", "Graphics", ATRACE_TAG_GRAPHICS, { } },
{ "input", "Input", ATRACE_TAG_INPUT, { } },
{ "view", "View System", ATRACE_TAG_VIEW, { } },
{ "webview", "WebView", ATRACE_TAG_WEBVIEW, { } },
{ "wm", "Window Manager", ATRACE_TAG_WINDOW_MANAGER, { } },
{ "am", "Activity Manager", ATRACE_TAG_ACTIVITY_MANAGER, { } },
{ "sm", "Sync Manager", ATRACE_TAG_SYNC_MANAGER, { } },
{ "audio", "Audio", ATRACE_TAG_AUDIO, { } },
{ "video", "Video", ATRACE_TAG_VIDEO, { } },
{ "camera", "Camera", ATRACE_TAG_CAMERA, { } },
{ "hal", "Hardware Modules", ATRACE_TAG_HAL, { } },
{ "app", "Application", ATRACE_TAG_APP, { } },
{ "res", "Resource Loading", ATRACE_TAG_RESOURCES, { } },
{ "dalvik", "Dalvik VM", ATRACE_TAG_DALVIK, { } },
{ "rs", "RenderScript", ATRACE_TAG_RS, { } },
{ "bionic", "Bionic C Library", ATRACE_TAG_BIONIC, { } },
{ "power", "Power Management", ATRACE_TAG_POWER, { } },
{ "pm", "Package Manager", ATRACE_TAG_PACKAGE_MANAGER, { } },
{ "ss", "System Server", ATRACE_TAG_SYSTEM_SERVER, { } },
{ "database", "Database", ATRACE_TAG_DATABASE, { } },
{ k_coreServiceCategory, "Core services", 0, { } },
{ "sched", "CPU Scheduling", 0, {
{ REQ, "/sys/kernel/debug/tracing/events/sched/sched_switch/enable" },
{ REQ, "/sys/kernel/debug/tracing/events/sched/sched_wakeup/enable" },
{ OPT, "/sys/kernel/debug/tracing/events/sched/sched_blocked_reason/enable" },
{ OPT, "/sys/kernel/debug/tracing/events/sched/sched_cpu_hotplug/enable" },
} },
{ "irq", "IRQ Events", 0, {
{ REQ, "/sys/kernel/debug/tracing/events/irq/enable" },
{ OPT, "/sys/kernel/debug/tracing/events/ipi/enable" },
} },
{ "freq", "CPU Frequency", 0, {
{ REQ, "/sys/kernel/debug/tracing/events/power/cpu_frequency/enable" },
{ OPT, "/sys/kernel/debug/tracing/events/power/clock_set_rate/enable" },
{ OPT, "/sys/kernel/debug/tracing/events/power/cpu_frequency_limits/enable" },
} },
{ "membus", "Memory Bus Utilization", 0, {
{ REQ, "/sys/kernel/debug/tracing/events/memory_bus/enable" },
} },
{ "idle", "CPU Idle", 0, {
{ REQ, "/sys/kernel/debug/tracing/events/power/cpu_idle/enable" },
} },
{ "disk", "Disk I/O", 0, {
{ OPT, "/sys/kernel/debug/tracing/events/f2fs/f2fs_sync_file_enter/enable" },
{ OPT, "/sys/kernel/debug/tracing/events/f2fs/f2fs_sync_file_exit/enable" },
{ OPT, "/sys/kernel/debug/tracing/events/f2fs/f2fs_write_begin/enable" },
{ OPT, "/sys/kernel/debug/tracing/events/f2fs/f2fs_write_end/enable" },
{ OPT, "/sys/kernel/debug/tracing/events/ext4/ext4_da_write_begin/enable" },
{ OPT, "/sys/kernel/debug/tracing/events/ext4/ext4_da_write_end/enable" },
{ OPT, "/sys/kernel/debug/tracing/events/ext4/ext4_sync_file_enter/enable" },
{ OPT, "/sys/kernel/debug/tracing/events/ext4/ext4_sync_file_exit/enable" },
{ REQ, "/sys/kernel/debug/tracing/events/block/block_rq_issue/enable" },
{ REQ, "/sys/kernel/debug/tracing/events/block/block_rq_complete/enable" },
} },
{ "mmc", "eMMC commands", 0, {
{ REQ, "/sys/kernel/debug/tracing/events/mmc/enable" },
} },
{ "load", "CPU Load", 0, {
{ REQ, "/sys/kernel/debug/tracing/events/cpufreq_interactive/enable" },
} },
{ "sync", "Synchronization", 0, {
{ REQ, "/sys/kernel/debug/tracing/events/sync/enable" },
} },
{ "workq", "Kernel Workqueues", 0, {
{ REQ, "/sys/kernel/debug/tracing/events/workqueue/enable" },
} },
{ "memreclaim", "Kernel Memory Reclaim", 0, {
{ REQ, "/sys/kernel/debug/tracing/events/vmscan/mm_vmscan_direct_reclaim_begin/enable" },
{ REQ, "/sys/kernel/debug/tracing/events/vmscan/mm_vmscan_direct_reclaim_end/enable" },
{ REQ, "/sys/kernel/debug/tracing/events/vmscan/mm_vmscan_kswapd_wake/enable" },
{ REQ, "/sys/kernel/debug/tracing/events/vmscan/mm_vmscan_kswapd_sleep/enable" },
} },
{ "regulators", "Voltage and Current Regulators", 0, {
{ REQ, "/sys/kernel/debug/tracing/events/regulator/enable" },
} },
{ "binder_driver", "Binder Kernel driver", 0, {
{ REQ, "/sys/kernel/debug/tracing/events/binder/binder_transaction/enable" },
{ REQ, "/sys/kernel/debug/tracing/events/binder/binder_transaction_received/enable" },
} },
{ "binder_lock", "Binder global lock trace", 0, {
{ REQ, "/sys/kernel/debug/tracing/events/binder/binder_lock/enable" },
{ REQ, "/sys/kernel/debug/tracing/events/binder/binder_locked/enable" },
{ REQ, "/sys/kernel/debug/tracing/events/binder/binder_unlock/enable" },
} },
{ "pagecache", "Page cache", 0, {
{ REQ, "/sys/kernel/debug/tracing/events/filemap/enable" },
} },
};
判断逻辑是 tags 不为空或者 sysfiles 数组的每一个 REQ 项里文件可写。
static bool isCategorySupported(const TracingCategory& category)
{
bool ok = category.tags != 0;
for (int i = 0; i < MAX_SYS_FILES; i++) {
const char* path = category.sysfiles[i].path;
bool req = category.sysfiles[i].required == REQ;
if (path != NULL) {
if (req) {
if (!fileIsWritable(path)) {
return false;
} else {
ok = true;
}
} else {
ok |= fileIsWritable(path);
}
}
}
return ok;
}
async-start
--async-start 选项可以异步的打开 atrace，否则将阻塞，直到超时或者主动退出。
-a app_name 可以打开应用的 trace 功能，这样就能使用 sdk 提供的 trace api
命令行最后的就是需要打开的 category
下面直接看 --async-start 相关的代码，关系不大的代码已删减
int main(int argc, char **argv)
{
for (;;) {
int ret;
int option_index = 0;
// 解析命令行参数
ret = getopt_long(argc, argv, "a:b:cf:k:ns:t:zo:",
long_options, &option_index);
if (ret < 0) {
// 解析 category
// 判断是否支持，根据结果设置 g_categoryEnables 数组
for (int i = optind; i < argc; i++) {
setCategoryEnable(argv[i], true))
}
}
switch(ret) {
case 'a':
g_debugAppCmdLine = optarg;
break;
case 0:
if (!strcmp(long_options[option_index].name, "async_start")) {
async = true;
traceStop = false;
traceDump = false;
g_traceOverwrite = true;
}
break;
}
}
// 配置 trace
setUpTrace();
// 开始 trace
startTrace();
// 清除之前的缓存
clearTrace();
// 写入时钟同步的 trace
writeClockSyncMarker();
}
setUpTrace 就是将解析后的命令行参数写入相关文件节点或者设置相关系统属性
static bool setUpTrace()
{
bool ok = true;
// echo 1 > /sys/kernel/debug/tracing/options/overwrite
ok &= setTraceOverwriteEnable(g_traceOverwrite);
// echo 2048 > /sys/kernel/debug/tracing/buffer_size_kb
ok &= setTraceBufferSizeKB(g_traceBufferSizeKB);
// 命令行传递的 category 列表里 tags 不为空的是 app，由源码得知
// #define ATRACE_TAG_APP (1<<12) // 4096
// setprop debug.atrace.tags.enableflags 4096
uint64_t tags = 0;
for (int i = 0; i < NELEM(k_categories); i++) {
if (g_categoryEnables[i]) {
const TracingCategory &c = k_categories[i];
tags |= c.tags;
}
}
ok &= setTagsProperty(tags);
// 应用 trace 相关
// setprop debug.atrace.app_0 com.example.toy
// setprop debug.atrace.app_number 1
std::string packageList(g_debugAppCmdLine);
ok &= setAppCmdlineProperty(packageList.data());
// 命令行传递的 category 列表里 tags 不为空的是 binder_lock，对应的是以下三个节点
// 写入 1 使能 binder lock 相关的节点
// echo 1 > /sys/kernel/debug/tracing/events/binder/binder_lock/enable
// echo 1 > /sys/kernel/debug/tracing/events/binder/binder_locked/enable
// echo 1 > /sys/kernel/debug/tracing/events/binder/binder_unlock/enable
for (int i = 0; i < NELEM(k_categories); i++) {
if (g_categoryEnables[i]) {
const TracingCategory &c = k_categories[i];
for (int j = 0; j < MAX_SYS_FILES; j++) {
const char* path = c.sysfiles[j].path;
bool required = c.sysfiles[j].required == REQ;
if (path != NULL) {
if (fileIsWritable(path)) {
ok &= setKernelOptionEnable(path, true);
}
}
}
}
}
return ok;
}
startTrace 用于打开 trace，当打开后，就能将 log 写入 /sys/kernel/debug/tracing/trace_marker 节点了
static bool startTrace()
{
// echo 1 > /sys/kernel/debug/tracing/tracing_on
return setTracingEnabled(true);
}
async-dump
async-dump 用于从 /sys/kernel/debug/tracing/trace 节点读取所有写入的 trace log
int main(int argc, char **argv)
{
int outFd = STDOUT_FILENO;
dprintf(outFd, "TRACE:\n");
dumpTrace(outFd);
clearTrace();
}
默认是输出控制台，可以通过 -o filename 参数来指定输出文件路径，还能使用 -z 参数进行 zlib 压缩。
这里没用指定路径和压缩，相当于 cat /sys/kernel/debug/tracing/trace 命令
static void dumpTrace(int outFd)
{
int traceFD = open(k_tracePath, O_RDWR);
ssize_t sent = 0;
while ((sent = sendfile(outFd, traceFD, NULL, 64*1024*1024)) > 0);
close(traceFD);
}
async-stop
async-stop 主要是关闭 trace，再 dumpTrace，最后清除 setupTrace 设置的系统属性和将相关的文件节点置 0。
int main(int argc, char **argv)
{
stopTrace();
int outFd = STDOUT_FILENO;
dumpTrace(outFd);
clearTrace();
cleanUpTrace();
}
static void stopTrace()
{
// echo 0 > /sys/kernel/debug/tracing/tracing_on
setTracingEnabled(false);
}
static void cleanUpTrace()
{
// echo 0 > /sys/kernel/debug/tracing/events/binder/binder_lock/enable
// echo 0 > /sys/kernel/debug/tracing/events/binder/binder_locked/enable
// echo 0 > /sys/kernel/debug/tracing/events/binder/binder_unlock/enable
disableKernelTraceEvents();
// setprop debug.atrace.tags.enableflags 0
setTagsProperty(0);
// setprop debug.atrace.app_0 ""
// setprop debug.atrace.app_number ""
clearAppProperties();
// echo 1 > /sys/kernel/debug/tracing/options/overwrite
setTraceOverwriteEnable(true);
// echo 1 > /sys/kernel/debug/tracing/buffer_size_kb
setTraceBufferSizeKB(1);
}
trace log 格式
如果需要使用systrace.py 脚本可视化，需要以 TRACE:\n# tracer: nop\n 开头。
同时每一行的格式需要是
<线程名>-<线程id> <000> ...1 <时间-秒>: tracing_mark_write: <B|E>|<进程id>|<TAG>
时间可以通过以下函数获取，但是观察到有100多 ms 的偏差
float now_in_seconds = systemTime() / 1000000000.0f;
nsecs_t systemTime()
{
struct timespec t;
t.tv_sec = t.tv_nsec = 0;
clock_gettime(CLOCK_MONOTONIC, &t);
return nsecs_t(t.tv_sec)*1000000000LL + t.tv_nsec;
}
这样就可以通过 hook 对 /sys/kernel/debug/tracing/trace_marker 文件的写入，来得到应用的 trace，再补全格式就能给 systrace.py 进行解析了。
trace 示例
TRACE:
# tracer: nop
#
# entries-in-buffer/entries-written: 21/24 #P:1
# enabled events:
# kernel time now: 453985.091953
# UTC time: 2019-07-11 06:34:35.321188
# android time: 2019-07-11 14:34:35.321188
#
# _-----=> irqs-off
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / delay
# TASK-PID CPU# |||| TIMESTAMP FUNCTION
# | | | |||| | |
atrace-4367 [000] ...1 453966.016965: tracing_mark_write: trace_event_clock_sync: parent_ts=453966.187500
atrace-4367 [000] ...1 453966.016978: tracing_mark_write: trace_event_clock_sync: realtime_ts=1562826856246
UICompThread_0-270 [000] ...1 453967.735306: tracing_mark_write: S|240|OVL0-DSI|856112
frame_update_wo-113 [000] ...1 453967.754543: tracing_mark_write: F|113|OVL0-DSI|856112
UICompThread_0-270 [000] ...1 453969.752747: tracing_mark_write: S|240|OVL0-DSI|856113
frame_update_wo-113 [000] ...1 453969.772422: tracing_mark_write: F|113|OVL0-DSI|856113
UICompThread_0-270 [000] ...1 453971.767667: tracing_mark_write: S|240|OVL0-DSI|856114
frame_update_wo-113 [000] ...1 453971.790263: tracing_mark_write: F|113|OVL0-DSI|856114
UICompThread_0-270 [000] ...1 453973.768107: tracing_mark_write: S|240|OVL0-DSI|856115
frame_update_wo-113 [000] ...1 453973.790901: tracing_mark_write: F|113|OVL0-DSI|856115
UICompThread_0-270 [000] ...1 453975.781464: tracing_mark_write: S|240|OVL0-DSI|856116
frame_update_wo-113 [000] ...1 453975.808737: tracing_mark_write: F|113|OVL0-DSI|856116
UICompThread_0-270 [000] ...1 453977.782070: tracing_mark_write: S|240|OVL0-DSI|856117
trace 可视化
将 async-stop 后 dump 出来的原始 trace 文件通过 systrace.py 解析后，就可以在 chrome 浏览器查看了。
systrace.py --from-file=rawtrace -o atrace.html
