前言:
因为需要记录下每次的bindercall的code和对应的interfacedecriptor,所以需要分析一下binder_sample日志的原理。特此记录下来。
日志信息:
52004 binder_sample (descriptor|3),(method_num|1|5),(time|1|3),(blocking_package|3),(sample_percent|1|6)
而日志的例子是
05-15 12:47:06.672 10562 20858 20858 I binder_sample: [android.app.IActivityManager,13,940,com.starbucks.cn,100]
参数意义:
参数 | 例子 | 意义 | 备注 |
---|---|---|---|
descriptor | android.app.IActivityManager | 表示被卡住的binder调用对应的interface接口 | |
method_num | 13 | 调用方法的序列号 | |
time | 940 | 被delay的时长 | |
blocking_package | com.starbucks.cn | 从哪个进程发起的调用 | |
sample_percent | 100 | 被卡住的百分比 | 暂时不关注 |
源码信息:
而打印这行log的源码所在位置为:
//android_util_Binder.cpp
static void conditionally_log_binder_call(int64_t start_millis,
IBinder* target, jint code) {
int duration_ms = static_cast<int>(uptimeMillis() - start_millis);//获取到时长
int sample_percent;
if (duration_ms >= 500) {
sample_percent = 100;
} else {
sample_percent = 100 * duration_ms / 500;
if (sample_percent == 0) {
return;
}
if (sample_percent < (random() % 100 + 1)) {
return;
}
}
char process_name[40];
getprocname(getpid(), process_name, sizeof(process_name));//获取到client的进程名
String8 desc(target->getInterfaceDescriptor());//这个地方获取到对应的interface调用接口
char buf[LOGGER_ENTRY_MAX_PAYLOAD];
buf[0] = EVENT_TYPE_LIST;
buf[1] = 5;
char* pos = &buf[2];
char* end = &buf[LOGGER_ENTRY_MAX_PAYLOAD - 1]; // leave room for final \n
if (!push_eventlog_string(&pos, end, desc.string())) return;
if (!push_eventlog_int(&pos, end, code)) return;
if (!push_eventlog_int(&pos, end, duration_ms)) return;
if (!push_eventlog_string(&pos, end, process_name)) return;
if (!push_eventlog_int(&pos, end, sample_percent)) return;
*(pos++) = '\n'; // conventional with EVENT_TYPE_LIST apparently.
android_bWriteLog(LOGTAG_BINDER_OPERATION, buf, pos - buf);//Log写入到日志中。
}
那这个方法是在什么地方调用的呢,通过查找可以知道:
static jboolean android_os_BinderProxy_transact(JNIEnv* env, jobject obj,
jint code, jobject dataObj, jobject replyObj, jint flags) // throws RemoteException
{
.... //省略部分代码
bool time_binder_calls;
int64_t start_millis;
if (kEnableBinderSample) {//
// Only log the binder call duration for things on the Java-level main thread.
// But if we don't
time_binder_calls = should_time_binder_calls();
if (time_binder_calls) {
start_millis = uptimeMillis();
}
}
//printf("Transact from Java code to %p sending: ", target); data->print();
status_t err = target->transact(code, *data, reply, flags);
//if (reply) printf("Transact from Java code to %p received: ", target); reply->print();
if (kEnableBinderSample) {
if (time_binder_calls) {
conditionally_log_binder_call(start_millis, target, code);
}
}
//省略部分代码
}
原来是在proxy代理进行transact的时候进行记录的,注意其中的should_time_binder_calls方法,只会去记录主线程的bindercall。
// We only measure binder call durations to potentially log them if
// we're on the main thread.
static bool should_time_binder_calls() {
return (getpid() == gettid());
}
这里就不过多的去讲binder整个框架了。因为和文章内容无关。需要知道的是,java层的binder都是通过jni的方式来调用的native端,所以在native端的proxy,也就是client进行transact的时候,进行判断,就可以拿到真正的时长信息。
而在其中的code,就是我们上面说到的调用方法的序列号,而对应的接口是如何拿到的呢。
// target->getInterfaceDescriptor()
我们知道,target是server端的binder接口,远端拿到interfacedescriptor其实就是拿到了对应的mdescriptor。 而这个mdescriptor是在
/**
* Convenience method for associating a specific interface with the Binder.
* After calling, queryLocalInterface() will be implemented for you
* to return the given owner IInterface when the corresponding
* descriptor is requested.
*/
public void attachInterface(@Nullable IInterface owner, @Nullable String descriptor) {
mOwner = owner;
mDescriptor = descriptor;
}
而这个方法会填充mDescriptor,而这个方法是在server端初始化的时候就会进行填充的。这个也是binder框架的内容,暂不在讨论范围。
总结:
从上面的分析可以看到,这个log也只是分析到了java层的binder调用,而native层的binder,采用的接口是BBinder和BpBinder,所以,在jni的这里添加的也就只能拿到java层主线程binder调用耗时的一个情况。而且如果添加了这个log也可以看到,需要首先进行一次getInterfaceDescriptor的操作,这个操作本身就是一个binder操作,所以其实是对性能还是有影响的,但是因为是在native层,不涉及复杂逻辑,所以增加的操作也是可以忽略的。