之前在添加 io 的 trace 日志时，由于每一次 open、close、read、write 都去打日志，同时会通过 fd 参数去获取真正的文件名（使用 readlink 去读取 /proc/self/fd/<fd>），导致异常卡顿。
优化点之一就是只去记录主线程，毕竟卡顿和主线程关系大点。
同时想到是否可以只记录耗时的 io 操作，但是从 trace 的实现来看，只支持在 io 操作前后各执行一次 begin 和 end 操作才能被 trace-viewer（例如新版 edge 浏览器的 edge://tracing/ 页面）识别，如果不匹配可能根本无法正常解析。
因此希望在 io 操作前去记录开始时间，在执行完成后判断耗时，再去判断是否要写日志，并且 trace-viewer 能正常解析日志。
想要写入的日志格式如下 ：
com.example.toy-29825 [000] ...1 264266.290444: tracing_mark_write: B|29825|@file@open|name=/data/data/xxx;t=1.111
未修改的 trace-viewer 能正常识别 B|<pid>|<msg>|<args> 格式。args 满足 xx=xx;xx=xx 格式时，能被正常解析为一个表格，点击方法的色块时，会展示在下方的 slice 里。
因此可以把 msg 固定为 @file@open 、@file@write 等字符串，然后把耗时填入 args，在解析时，判断 msg 是否以 @file@ 开头，如果符合条件，则从 args 取出耗时，模拟普通的日志去展示。
现在第一步就是去找到 trace-viewer 源码了，它是由 catapult 工程生成的，Systrace 也是。
catapult chromium.googlesource.com/catapult , 源码在 googlesource 上，无法直接访问。
可以将这个工程 import 到 gitlab 或者 github 上，然后再 import 到 gitee 上，然后再 clone 下来，速度还挺快，访问不了或者速度慢的 git 工程都可以这样来下载。
接下来在源码里一番搜索，在 2 个文件发现相关代码。
首先先来看是怎么识别出 android trace 日志的。
// tracing/tracing/extras/importer/linux_perf/ftrace_importer.html
registerDefaultHandlers_() {
this.registerEventHandler('tracing_mark_write',
FTraceImporter.prototype.traceMarkingWriteEvent_.bind(this));
// NB: old-style trace markers; deprecated
this.registerEventHandler('0',
FTraceImporter.prototype.traceMarkingWriteEvent_.bind(this));
// Register dummy clock sync handlers to avoid warnings in the log.
this.registerEventHandler('tracing_mark_write:trace_event_clock_sync',
function() { return true; });
this.registerEventHandler('0:trace_event_clock_sync',
function() { return true; });
},
/**
* Processes a trace_marking_write event.
*/
traceMarkingWriteEvent_(eventName, cpuNumber, pid, ts, eventBase,
threadName) {
// Some profiles end up with a \n\ on the end of each line. Strip it
// before we do the comparisons.
eventBase.details = eventBase.details.replace(/\\n.*$/, '');
const event = /^\s*(\w+):\s*(.*)$/.exec(eventBase.details);
if (!event) {
// Check if the event matches events traced by the Android framework
const tag = eventBase.details.substring(0, 2);
if (tag === 'B|' || tag === 'E' || tag === 'E|' || tag === 'X|' ||
tag === 'C|' || tag === 'S|' || tag === 'F|') {
eventBase.subEventName = 'android';
} else {
return false;
}
} else {
eventBase.subEventName = event[1];
eventBase.details = event[2];
}
const writeEventName = eventName + ':' + eventBase.subEventName;
const handler = this.eventHandlers_[writeEventName];
if (!handler) {
this.model_.importWarning({
type: 'parse_error',
message: 'Unknown trace_marking_write event ' + writeEventName
});
return true;
}
return handler(writeEventName, cpuNumber, pid, ts, eventBase, threadName);
},
可以看到只有特定的 tag，才能被正常识别成 android 的。
下一步就是解析 android trace 日志，这里只看 B 和 E 标签。
// tracing/tracing/extras/importer/linux_perf/android_parser.html
traceMarkWriteAndroidEvent(eventName, cpuNumber, pid, ts,
eventBase) {
const eventData = eventBase.details.split('|');
switch (eventData[0]) {
case 'B': {
const ppid = parseInt(eventData[1]);
const title = eventData[2];
const args = parseArgs(eventData[3]);
let category = eventData[4];
if (category === undefined) category = 'android';
const thread = this.model_.getOrCreateProcess(ppid)
.getOrCreateThread(pid);
thread.name = eventBase.threadName;
if (!thread.sliceGroup.isTimestampValidForBeginOrEnd(ts)) {
this.model_.importWarning({
type: 'parse_error',
message: 'Timestamps are moving backward.'
});
return false;
}
this.ppids_[pid] = ppid;
thread.sliceGroup.beginSlice(category, title, ts, args);
break;
}
case 'E': {
const ppid = this.ppids_[pid];
if (ppid === undefined) {
// Silently ignore unmatched E events.
break;
}
const thread = this.model_.getOrCreateProcess(ppid)
.getOrCreateThread(pid);
if (!thread.sliceGroup.openSliceCount) {
// Silently ignore unmatched E events.
break;
}
const slice = thread.sliceGroup.endSlice(ts);
const args = parseArgs(eventData[3]);
for (const arg in args) {
if (slice.args[arg] !== undefined) {
this.model_.importWarning({
type: 'parse_error',
message: 'Both the B and E events of ' + slice.title +
' provided values for argument ' + arg + '.' +
' The value of the E event will be used.'
});
}
slice.args[arg] = args[arg];
}
break;
}
.....
}
}
一番字符串解析操作之后，执行 thread.sliceGroup.beginSlice(category, title, ts, args) 和 thread.sliceGroup.endSlice(ts)，注意这里的 ts 单位是 ms。
从代码分析来看，可以在解析 B 标签那，去解析自定义的日志。代码修改如下：
--- a/tracing/tracing/extras/importer/linux_perf/android_parser.html
+++ b/tracing/tracing/extras/importer/linux_perf/android_parser.html
@@ -123,7 +123,14 @@ tr.exportTo('tr.e.importer.linux_perf', function() {
}
this.ppids_[pid] = ppid;
- thread.sliceGroup.beginSlice(category, title, ts, args);
+
+ if (title.indexOf("@file@") == 0) {
+ thread.sliceGroup.beginSlice(category, title, ts, args);
+ thread.sliceGroup.endSlice(ts + parseFloat(args['cost']));
+ } else {
+ thread.sliceGroup.beginSlice(category, title, ts, args);
+ }
+
break;
}
接下来就是生成新的 trace-viewer，只需要执行 generate_about_tracing_contents 就能生成了。
cd catapult/tracing/bin
./generate_about_tracing_contents --outdir /share/out
生成了 about_tracing.html 和 about_tracing.js，需要将 about_tracing.js 重命名为 tracing.js，否则打开 about_tracing.html 会出现白屏。
下面来测试一下效果，
TRACE:
# tracer: nop
#
com.example.toy-29825 [000] ...1 264266.290291: tracing_mark_write: B|29825|close socket:[861547]
com.example.toy-29825 [000] ...1 264266.290434: tracing_mark_write: E
com.example.toy-29825 [000] ...1 264266.290444: tracing_mark_write: B|29825|@file@open|name=/data/data/cmdline;cost=1.5678
com.example.toy-29825 [000] ...1 264266.290445: tracing_mark_write: E
com.example.toy-29825 [000] ...1 264266.290877: tracing_mark_write: B|29825|close socket:[862301]
com.example.toy-29825 [000] ...1 264266.290911: tracing_mark_write: E
将上面的 trace 文件使用 systrace.py 转化成 trace.html。
在 edge 浏览器打开 about_tracing.html，并且 trace.html 拖到浏览器中，来查看效果。
大功告成，收工。
