本文已参与「新人创作礼」活动,一起开启掘金创作之路。
1. 概述
无论是Android系统开发,还是应用开发,都离不开log,Androd上层采用logcat输出log。因此我们这次基于Android源码9.0,解读logd的日志记录过程。
代码路径:
frameworks/base/core/java/android/util/
- Log.java
- Slog.java
- EventLog.java
frameworks/base/core/jni/android_util_Log.cpp
/system/core/logcat/logcat.cpp
/system/core/liblog/logger_write.c
/system/core/liblog/uio.c
/system/core/liblog/properties.c
/system/core/logd/
- main.cpp
- LogBuffer.cpp
- LogStatistics.cpp
/system/core/libsysutils/src/SocketListener.cpp
logcat命令说明
可通过adb命令直接输出指定的log:
logcat -b events // 输出指定buffer的log
logcat -s "ActivityManager"
logcat -L //上次重启时的log
logcat -f [filename] //将log保存到指定文件
logcat -g //缓冲区大小
logcat -S //统计log信息
-b 默认是指-b main -b system -b crash,当然一可以指定其他参数,或者直接指定all。
2. log函数使用
2.1 Java层
默认定义了5个Buffer缓冲区,如下:
ID | 名称 | 使用方式 |
---|---|---|
LOG_ID_MAIN | main | Log.i |
LOG_ID_RADIO | radio | Rlog.i |
LOG_ID_EVENTS | events | EventLog.writeEvent |
LOG_ID_SYSTEM | system | Slog.i |
LOG_ID_CRASH | crash | - |
log级别:
级别 | 对应值 | 使用场景 |
---|---|---|
VERBOSE | 2 | 冗长信息 |
DEBUG | 3 | 调试信息 |
INFO | 4 | 普通信息 |
WARN | 5 | 警告信息 |
ERROR | 6 | 错误信息 |
ASSERT | 7 | 普通但重要的信息 |
2.2 Kernel层
Linux Kernel最常使用的是printk,用法如下:
//第一个参数是级别, 第二个是具体log内容
printk(KERN_INFO x);
日志级别的定义位于kernel/include/linux/printk.h文件,如下:
级别 | 对应值 | 使用场景 |
---|---|---|
KERN_EMERG | <0> | 系统不可用状态 |
KERN_ALERT | <1> | 警报信息,必须立即采取信息 |
KERN_CRIT | <2> | 严重错误信息 |
KERN_ERR | <3> | 错误信息 |
KERN_WARNING | <4> | 警告信息 |
KERN_NOTICE | <5> | 普通但重要的信息 |
KERN_INFO | <6> | 普通信息 |
KERN_DEBUG | <7> | 调试信息 |
日志输出到文件/proc/kmsg,可通过cat /proc/kmsg来获取内核log信息。
cat /proc/sys/kernel/printk
3. 原理分析
3.1 Log.i
[-> android/util/Log.java]
首先我们重点看下android.util.Log类: Log类定义较简单,无父类,final修饰,不可继承。构造函数是private,不可实例化。
public static int i(String tag, String msg) {
// [见小节3.2]
return println_native(LOG_ID_MAIN, INFO, tag, msg);
}
Log.java中的方法都是输出到main buffer, 其中println_native是Native方法, 通过JNI调用如下方法。
3.2 println_native
[-> android_util_Log.cpp] 传入的三个参数分别是:LOG_ID_MAIN(类型),INFO(级别),tag(标签),msg(日志信息),实现如下:
/*
* In class android.util.Log:
* public static native int println_native(int buffer, int priority, String tag, String msg)
*/
static jint android_util_Log_println_native(JNIEnv* env, jobject clazz,
jint bufID, jint priority, jstring tagObj, jstring msgObj)
{
const char* tag = NULL;
const char* msg = NULL;
...
//获取log标签和内容
if (tagObj != NULL)
tag = env->GetStringUTFChars(tagObj, NULL);
msg = env->GetStringUTFChars(msgObj, NULL);
// [见小节3.3]
int res = __android_log_buf_write(bufID, (android_LogPriority)priority, tag, msg);
if (tag != NULL)
env->ReleaseStringUTFChars(tagObj, tag);
env->ReleaseStringUTFChars(msgObj, msg);
return res;
}
3.3 __android_log_buf_write
[-> logger_write.c]
注意:第一次真正执行的方法是:__write_to_log_init,初始化后write_to_log的的方法实现变为:__write_to_log_daemon。详细参见__write_to_log_init的方法实现
LIBLOG_ABI_PUBLIC int __android_log_buf_write(int bufID, int prio,
const char* tag, const char* msg) {
struct iovec vec[3];
char tmp_tag[32];
if (!tag) tag = "";
/* XXX: This needs to go! */
if (bufID != LOG_ID_RADIO) {
switch (tag[0]) {
case 'H':
if (strcmp(tag + 1, "HTC_RIL" + 1)) break;
goto inform;
case 'R':
/* Any log tag with "RIL" as the prefix */
if (strncmp(tag + 1, "RIL" + 1, strlen("RIL") - 1)) break;
goto inform;
case 'Q':
/* Any log tag with "QC_RIL" as the prefix */
if (strncmp(tag + 1, "QC_RIL" + 1, strlen("QC_RIL") - 1)) break;
goto inform;
case 'I':
/* Any log tag with "IMS" as the prefix */
if (strncmp(tag + 1, "IMS" + 1, strlen("IMS") - 1)) break;
goto inform;
case 'A':
if (strcmp(tag + 1, "AT" + 1)) break;
goto inform;
case 'G':
if (strcmp(tag + 1, "GSM" + 1)) break;
goto inform;
case 'S':
if (strcmp(tag + 1, "STK" + 1) && strcmp(tag + 1, "SMS" + 1)) break;
goto inform;
case 'C':
if (strcmp(tag + 1, "CDMA" + 1)) break;
goto inform;
case 'P':
if (strcmp(tag + 1, "PHONE" + 1)) break;
/* FALLTHRU */
inform:
bufID = LOG_ID_RADIO;
//满足以上条件的tag,则默认输出到radio缓冲区,并修改相应的tags
snprintf(tmp_tag, sizeof(tmp_tag), "use-Rlog/RLOG-%s", tag);
tag = tmp_tag;
/* FALLTHRU */
default:
break;
}
}
#if __BIONIC__
if (prio == ANDROID_LOG_FATAL) {
android_set_abort_message(msg);
}
#endif
vec[0].iov_base = (unsigned char*)&prio;
vec[0].iov_len = 1;
vec[1].iov_base = (void*)tag;
vec[1].iov_len = strlen(tag) + 1;
vec[2].iov_base = (void*)msg;
vec[2].iov_len = strlen(msg) + 1;
// [见小节3.4]
return write_to_log(bufID, vec, 3);
}
- 对于满足特殊条件的tag,则会输出到LOG_ID_RADIO缓冲区;
- vec数组依次记录着log的级别,tag, msg.
其中write_to_log函数指针指向__write_to_log_init
static int (*write_to_log)(log_id_t, struct iovec* vec,
size_t nr) = __write_to_log_init;
3.4 write_to_log
[-> logger_write.c]
static int __write_to_log_init(log_id_t log_id, struct iovec* vec, size_t nr) {
int ret, save_errno = errno;
__android_log_lock();// 加锁
if (write_to_log == __write_to_log_init) {
ret = __write_to_log_initialize();//执行log初始化
if (ret < 0) {
__android_log_unlock();
if (!list_empty(&__android_log_persist_write)) {
__write_to_log_daemon(log_id, vec, nr);//【见小节3.5】
}
errno = save_errno;
return ret;
}
write_to_log = __write_to_log_daemon;
}
__android_log_unlock();// 去锁
ret = write_to_log(log_id, vec, nr);
errno = save_errno;
return ret;
}
首先会执行初始化方法__write_to_log_initialize,作用是:为集合__android_log_transport_write设置各类writer,例如logdLoggerWrite,pmsgLoggerWrite等,然后依次调用writer的open方法,例如logdLoggerWrite#logdOpen方法,如果打开失败,则关闭。
logdLoggerWrite#logdOpen方法,代码位置:system/core/liblog/logd_writer.c,其实现是:
/* log_init_lock assumed */
static int logdOpen() {
// ...
int sock = TEMP_FAILURE_RETRY(
socket(PF_UNIX, SOCK_DGRAM | SOCK_CLOEXEC | SOCK_NONBLOCK, 0)); // 注意:SOCK_DGRAM代表着UDP通信,SOCK_NONBLOCK非阻塞式(效率高)
// ...
strcpy(un.sun_path, "/dev/socket/logdw");
if (TEMP_FAILURE_RETRY(connect(sock, (struct sockaddr*)&un,
sizeof(struct sockaddr_un))) < 0) {
// ...
}
接下来进入真正写log的方法.
3.5 __write_to_log_daemon
static int __write_to_log_daemon(log_id_t log_id, struct iovec* vec, size_t nr) {
struct android_log_transport_write* node;
int ret, save_errno;
struct timespec ts;
size_t len, i;
// ...
clock_gettime(android_log_clockid(), &ts); // 获得日志时间戳
if (log_id == LOG_ID_SECURITY) {
// ...
} else if (log_id == LOG_ID_EVENTS || log_id == LOG_ID_STATS) {
// ...
} else {
/* Validate the incoming tag, tag content can not split across iovec */
char prio = ANDROID_LOG_VERBOSE;
const char* tag = vec[0].iov_base;
// ...
// 变量prio存储vec[0].iov_base,例如2(VERBOSE),tag存储vec[1].iov_base
if (!__android_log_is_loggable_len(prio, tag, len - 1, ANDROID_LOG_VERBOSE)) { //如果当前打印的log级别低于系统设置的级别,会直接返回,不会打印。默认是:ANDROID_LOG_VERBOSE(2),系统设置的级别来自于属性:persist.log.tag 或 log.tag
errno = save_errno;
return -EPERM;
}
}
//....
// 以下是核心方法实现
write_transport_for_each(node, &__android_log_transport_write) {
if (node->logMask & i) {
ssize_t retval;
retval = (*node->write)(log_id, &ts, vec, nr);
if (ret >= 0) {
ret = retval;
}
}
}
write_transport_for_each(node, &__android_log_persist_write) {
if (node->logMask & i) {
(void)(*node->write)(log_id, &ts, vec, nr);
}
}
errno = save_errno;
return ret;
}
在上面会看到将循环调用所有writer的write方法来传输日志,举个例子logdLoggerWrite的write方法(之前已调用其logdOpen方法:建立Socket连接,path:/dev/socket/logdw):
static int logdWrite(log_id_t logId, struct timespec* ts, struct iovec* vec,
size_t nr) {
// ...
/*
* The write below could be lost, but will never block.
*
* ENOTCONN occurs if logd has died.
* ENOENT occurs if logd is not running and socket is missing.
* ECONNREFUSED occurs if we can not reconnect to logd.
* EAGAIN occurs if logd is overloaded.
*/
if (sock < 0) {
ret = sock;
} else {
ret = TEMP_FAILURE_RETRY(writev(sock, newVec, i)); // 通过socket写数据
if (ret < 0) {
ret = -errno;
}
}
// ...
}
3.6 小节
一句话总结就是Log.i()最终是通过调用write()向logd守护进程的socket(“/dev/socket/logdw”)端写入需要打印的日志信息。 接下来再来看logd的工作过程。
4. logd守护进程
下一步是Logd的逻辑分析,即接收到socket通信传输后的数据,该如何处理: logd是由init进程所启动的守护进程,启动代码参考:system/core/rootdir/init.rc。Logd进程启动时创建3个Socket通道,用于进程间通信,代码实现:system/core/logd/logd.rc,如下:
service logd /system/bin/logd
socket logd stream 0666 logd logd
socket logdr seqpacket 0666 logd logd
socket logdw dgram+passcred 0222 logd logd
file /proc/kmsg r
file /dev/kmsg w
user logd
group logd system package_info readproc
writepid /dev/cpuset/system-background/tasks
//...
我们可以通过ss -pl查看socket连接:
4.1 main()
[-> /system/core/logd/main.cpp]
进程启动后,入口方法:system/core/logd/main.cpp,其中入口的main方法实现不复杂,主要创建LogBuffer,然后启动5个listener,一般重要的是前三个:LogReader,LogListener,CommandListener,全部继承于SocketListener(system/core/libsysutils),另外还有2个listener:LogAudit(监听NETLINK_AUDIT,与selinux有关),LogKlog,这里不做深究。
int main(int argc, char* argv[]) {
// ...
// LogBuffer,作用:存储所有的日志信息
logBuf = new LogBuffer(times);
// LogReader监听Socket(/dev/socket/logdr),作用:当客户端连接logd后,LogReader将LogBuffer中的日志写给客户端。线程名:logd.reader,通过prctl(PR_SET_NAME, "logd.reader");设定
LogReader* reader = new LogReader(logBuf);
if (reader->startListener()) {
exit(1);
}
// LogListener监听Socket(/dev/socket/logdw),作用:接收传来的日志信息,写入LogBuffer;同时LogReader将新的日志传给已连接的客户端。线程名:logd.writer
LogListener* swl = new LogListener(logBuf, reader);
if (swl->startListener(600)) {
exit(1);
}
//CommandListener监听Socket(/dev/socket/logd),作用:接收发来的命令。线程名:logd.control
CommandListener* cl = new CommandListener(logBuf, reader, swl);
if (cl->startListener()) {
exit(1);
}
// ...
exit(0);
}
该方法功能:
- LogReader: 监听/dev/socket/logdr, 当client连接上则将buffer信息写入client. 所对应线程名”logd.reader”
- LogListener: 监听/dev/socket/logdw, 新日志添加到LogBuffer, 并且LogReader发送更新给已连接的client. 所对应线程名”logd.writer”
- CommandListener: 监听/dev/socket/logd, 处理logd管理命令. 所对应线程名”logd.control”
- LogAudit: 所对应线程名”logd.auditd”
- LogKlog: 所对应线程名”logd.klogd”
- 入口reinit_thread_start: 所对应线程名”logd.daemon”
另外,ANDROID_SOCKET_NAMESPACE_RESERVED代表位于/dev/socket名字空间。 通过adb命令,可以看到logd进程有几个子线程。
接下来,继续回到前面log输出过程,接下来进入logd的LogListener处理过程,如下
4.2 LogListener.cpp
首先看LogListener,当有对端进程通过Socket传递过来数据后,onDataAvailable方法被调用,其中主要是解析数据、调用LogBuffer->log方法存储日志信息,调用LogReader→notifyNewLog方法通知有新的日志信息,以便发送给其客户端。如下:
bool LogListener::onDataAvailable(SocketClient* cli) {
// ...
// 1. 调用LogBuffer->log方法存储日志信息
int res = logbuf->log(
logId, header->realtime, cred->uid, cred->pid, header->tid, msg,
((size_t)n <= USHRT_MAX) ? (unsigned short)n : USHRT_MAX);
// 2. 调用LogReader→notifyNewLog方法通知有新的日志信息,以便发送给其客户端
if (res > 0 && reader != nullptr) {
reader->notifyNewLog(static_cast<log_mask_t>(1 << logId));
}
// ...
}
4.3 LogBuffer.cpp
继续看LogBuffer的log方法,代码位置:system/core/logd/LogBuffer.cpp
int LogBuffer::log(log_id_t log_id, log_time realtime, uid_t uid, pid_t pid,
pid_t tid, const char* msg, unsigned short len) {
// ...
// 低于当前设定的日志优先级,返回
if (!__android_log_is_loggable_len(prio, tag, tag_len,
ANDROID_LOG_VERBOSE)) {
// Log traffic received to total
wrlock();
stats.addTotal(elem);
unlock();
delete elem;
return -EACCES;
}
// 调用重载的log方法
log(elem);
unlock();
return len;
}
继续看log方法,主要作用是通过比对新进日志信息的时间,将其插入到正确的存储位置。所有日志存储在mLogElements变量中,其类型是:typedef std::list<LogBufferElement*>
void LogBuffer::log(LogBufferElement* elem) {
// 插入正确位置,逻辑相对复杂,摘取其中关键一段
do {
last = it;
if (__predict_false(it == mLogElements.begin())) {
break;
}
--it;
} while (((*it)->getRealTime() > elem->getRealTime()) && (!end_set || (end <= (*it)->getRealTime())));
mLogElements.insert(last, elem);
}
// ...
stats.add(elem); // 初步看做一些统计工作,例如通过数组,统计不同类型日志的打印次数,不同类型日志的字符串总长度等,并且将日志信息以uid, pid, tid, tag等为单位,保存elem信息至不同的hashtable中
maybePrune(elem->getLogId());
}
其中maybePrune方法的作用很重要,当不同类型的log日志size超过最大限制时,会触发对已保存日志信息的裁剪,一次裁剪量约为10%:
void LogBuffer::maybePrune(log_id_t id) {
size_t sizes = stats.sizes(id); // 来自LogStatistics->mSizes[id]变量的值,统计不同日志类型的当前日志长度(msg)
unsigned long maxSize = log_buffer_size(id); // 取不同日志类型的日志长度最大值
if (sizes > maxSize) {
size_t sizeOver = sizes - ((maxSize * 9) / 10);
size_t elements = stats.realElements(id);
size_t minElements = elements / 100;
if (minElements < minPrune) { // minPrune值是4
minElements = minPrune; // minElements默认是全部日志元素数的百分之一,最小值是4
}
unsigned long pruneRows = elements * sizeOver / sizes; // 需要裁剪的元素个数,最小值是4个,最大值是256个,正常是总元素的比例:1 - (maxSize/sizes)* 0.9 = 约等于10%
if (pruneRows < minElements) {
pruneRows = minElements;
}
if (pruneRows > maxPrune) { // maxPrune值是256
pruneRows = maxPrune;
}
prune(id, pruneRows); // 如果日志存储已越界,则最终走到prune裁剪函数中处理,pruneRows是需要裁剪的元素个数
}
}
重要备注:不同日志类型的日志长度最大值,由上到下取值顺序: persist.logd.size.* // 例如:persist.logd.size.main、persist.logd.size.radio、persist.logd.size.events、persist.logd.size.system、persist.logd.size.crash、persist.logd.size.stats、persist.logd.size.security、persist.logd.size.kernel ro.logd.size.* // 例如:ro.logd.size.main、ro.logd.size.radio、ro.logd.size.events、ro.logd.size.system、ro.logd.size.crash、ro.logd.size.stats、ro.logd.size.security、ro.logd.size.kernel persist.logd.size // 设置APP:开发者选项-日志记录器缓冲区大小,默认256K ro.logd.size LOG_BUFFER_MIN_SIZE // 64K,条件是如果ro.config.low_ram是true,表示低内存手机 LOG_BUFFER_SIZE // 256K
另外可以用adb logcat -g命令查看缓冲区大小 具体执行的prune裁剪方法这里没有深究,感兴趣的同学可以看下system/core/logd/LogBuffer.cpp#prune方法,大致思路是:
- 支持黑/白名单(详见LogWhiteBlackList.cpp,uid + pid。注意:adb logcat -P可设置),白名单中不裁剪
- 优先裁剪黑名单、打印日志最多的uid,system uid中打印日志最多的pid
至此一次完整的:APP调用Log.v方法打印VERBOSE日志,调用执行过程完毕!