（Android系统）android log机制浅析

在android下面debug，最主要的方式就是用logcat抓log了，我们可能有尝试过使用printf来打印，当然结果是不行的，这里有时间就看了一下android平台下log的flow，在此做个笔记以作记录

我们一般使用ALOGD来打印log，所以这里就跟一下ALOGD的flow

system/core/include/log/log.h

system/core/include/log/log.h

#ifndef ALOGD
#define ALOGD(...) ((void)ALOG(LOG_DEBUG, LOG_TAG, __VA_ARGS__))
#endif

#ifndef ALOG
#define ALOG(priority, tag, ...) \
LOG_PRI(ANDROID_##priority, tag, __VA_ARGS__)
#endif

#ifndef LOG_PRI
#define LOG_PRI(priority, tag, ...) \
android_printLog(priority, tag, __VA_ARGS__)
#endif

#define android_printLog(prio, tag, fmt...) \
__android_log_print(prio, tag, fmt)

这里有发现ALOGD其实是一系列宏，最终会调用到 __android_log_print(prio, tag, fmt)，这个函数带三个参数：

1，优先级，这个就是我们平时说的log level，ALOGD的log level是LOG_DEBUG；

2，tag，这个就是我们在code里面指定的LOG_TAG

3，__VA_ARGS__，这个就是我们常见的格式化输入了，也就是说我们ALOGD带的参数可以使用格式化的格式

关于__android_log_print的具体实现如下：

system/core/liblog/logd_write.c

int __android_log_print(int prio, const char *tag, const char *fmt, ...)
{
va_list ap;
char buf[LOG_BUF_SIZE];

va_start(ap, fmt);
vsnprintf(buf, LOG_BUF_SIZE, fmt, ap);
va_end(ap);

return __android_log_write(prio, tag, buf);
}

这里可以看到格式化的输入被转化成buf的字符数组了，然后buf作为第三个参数调用__android_log_write

关于__android_log_write的具体实现如下：

int __android_log_write(int prio, const char *tag, const char *msg)
{
struct iovec vec[3];
log_id_t log_id = LOG_ID_MAIN;
char tmp_tag[32];

if (!tag)
tag = "";

/* XXX: This needs to go! */
if (!strcmp(tag, "HTC_RIL") ||
!strncmp(tag, "RIL", 3) || /* Any log tag with "RIL" as the prefix */
!strncmp(tag, "IMS", 3) || /* Any log tag with "IMS" as the prefix */
!strcmp(tag, "AT") ||
!strcmp(tag, "GSM") ||
!strcmp(tag, "STK") ||
!strcmp(tag, "CDMA") ||
!strcmp(tag, "PHONE") ||
!strcmp(tag, "SMS")) {
log_id = LOG_ID_RADIO;
// Inform third party apps/ril/radio.. to use Rlog or RLOG
snprintf(tmp_tag, sizeof(tmp_tag), "use-Rlog/RLOG-%s", tag);
tag = tmp_tag;
}

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;

return write_to_log(log_id, vec, 3);
}

可以看到priority，tag，msg三个参数分别填充到了iovec的struct中，

iovec是io vetor，与readv和writev相关的一种struct，readv和readv是高级I/O，这里不做深入解释，

大家只需要知道调用者传进来的参数按照固定的格式填充到了iovec中，最后调用write_to_log(log_id, vec, 3);

这里大家可以看一下write_to_log的具体实现：

static int (*write_to_log)(log_id_t, struct iovec *vec, size_t nr) = __write_to_log_init;

可以发现write_to_log是一个函数指针，初始化为__write_to_log_init

但是write_to_log在init的时候被赋值成__write_to_log_kernel

static int __write_to_log_init(log_id_t log_id, struct iovec *vec, size_t nr)
{
#ifdef HAVE_PTHREADS
pthread_mutex_lock(&log_init_lock);
#endif

if (write_to_log == __write_to_log_init) {
log_fds[LOG_ID_MAIN] = log_open("/dev/"LOGGER_LOG_MAIN, O_WRONLY);
log_fds[LOG_ID_RADIO] = log_open("/dev/"LOGGER_LOG_RADIO, O_WRONLY);
log_fds[LOG_ID_EVENTS] = log_open("/dev/"LOGGER_LOG_EVENTS, O_WRONLY);
log_fds[LOG_ID_SYSTEM] = log_open("/dev/"LOGGER_LOG_SYSTEM, O_WRONLY);

write_to_log = __write_to_log_kernel;

我们接下来看一下__write_to_log_kernel的具体实现

static int __write_to_log_kernel(log_id_t log_id, struct iovec *vec, size_t nr)
{
ssize_t ret;
int log_fd;

if (/*(int)log_id >= 0 &&*/ (int)log_id < (int)LOG_ID_MAX) {
log_fd = log_fds[(int)log_id];
} else {
return EBADF;
}

do {
ret = log_writev(log_fd, vec, nr);
} while (ret < 0 && errno == EINTR);

return ret;
}

可以看到是调用了log_writev(log_fd, vec, nr)，这里的三个参数分别是：

1，log_fd，也就是我们ALOGD产生的log所需要写入的fd，这里是/dev/log/main，/dev/log/radio/,dev/log/event,/dev/log/system等文件

2，vec，这个就是包含了priority，tag，msg等信息的iovec，专门供readv和wirtev使用的struct

3：nr，这里应该是vec结构体数组的个数，这里是3个，分别填充了priority，tag，msg

#if FAKE_LOG_DEVICE
// This will be defined when building for the host.
#define log_open(pathname, flags) fakeLogOpen(pathname, flags)
#define log_writev(filedes, vector, count) fakeLogWritev(filedes, vector, count)
#define log_close(filedes) fakeLogClose(filedes)
#else
#define log_open(pathname, flags) open(pathname, (flags) | O_CLOEXEC)
#define log_writev(filedes, vector, count) writev(filedes, vector, count)
#define log_close(filedes) close(filedes)
#endif

看到了吧，这里就是用writev把vec里面填充的内容按固定格式写到log_fd对应的路径了，至此ALOGD所要打印的msg被写入到了/dev/log/main等路径了

接下来我们看一下logcat的flow，为什么在终端输入logcat之后，log信息就会被打印到终端之上

首先我们需要解释下，为什么printf无法打印信息到终端：

system/core/init/init.c

static void open_console()
{
int fd;
if ((fd = open(console_name, O_RDWR)) < 0) {
fd = open("/dev/null", O_RDWR);
}
ioctl(fd, TIOCSCTTY, 0);
dup2(fd, 0);
dup2(fd, 1);
dup2(fd, 2);
close(fd);
}

原来init进程在启动的时候把0,1,2等三个fd都定向到了/dev/null，所以我们printf输出给stdout（也就是fd 1）都丢给了/dev/null，这样子也就不会有信息了

android官方给出的解释如下(system/core/init/readme.txt)：

By default, programs executed by init will drop stdout and stderr into

/dev/null. To help with debugging, you can execute your program via the

Andoird program logwrapper. This will redirect stdout/stderr into the

Android logging system (accessed via logcat).

system/core/logcat/logcat.cpp

先从logcat的main函数走起，首先会遇到一个重要的地方

if (!devices) {
devices = new log_device_t(strdup("/dev/"LOGGER_LOG_MAIN), false, 'm');
android::g_devCount = 1;
int accessmode =
(mode & O_RDONLY) ? R_OK : 0
| (mode & O_WRONLY) ? W_OK : 0;
// only add this if it's available
if (0 == access("/dev/"LOGGER_LOG_SYSTEM, accessmode)) {
devices->next = new log_device_t(strdup("/dev/"LOGGER_LOG_SYSTEM), false, 's');
android::g_devCount++;
}
}

这里我们有发现logcat使用/dev/log/main和/dev/log/system两个路径作为device，这里g_devCount的值是2

接下来会设置output的路径，这里很重要，直接关联到log的输出，我们发现可以输出到STDOUT_FILENO，也可以是系统指定的参数，这个是-f所指定的，关于-f的作用，可以使用help文档确认一下

static void setupOutput()
{

if (g_outputFileName == NULL) {
g_outFD = STDOUT_FILENO;

} else {
struct stat statbuf;

g_outFD = openLogFile (g_outputFileName);

if (g_outFD < 0) {
perror ("couldn't open output file");
exit(-1);
}

fstat(g_outFD, &statbuf);

g_outByteCount = statbuf.st_size;
}
}

一般我们直接使用logcat的时候，g_outFD所对应的输出设备就是我们的终端，这也就是为什么logcat可以把log打印到终端

最后是一个很重要的地方，这里用select的机制去查询/dev/log/main和/dev/log/system两个路径是否有log信息可以打印，

如果有的话就打印到终端，如果没有的话就sleep 5ms，这里的时间是select函数的最后一个参数指定的

static void readLogLines(log_device_t* devices)
{
log_device_t* dev;
int max = 0;
int ret;
int queued_lines = 0;
bool sleep = false;

int result;
fd_set readset;

for (dev=devices; dev; dev = dev->next) {
if (dev->fd > max) {
max = dev->fd;
}
}

while (1) {
do {
timeval timeout = { 0, 5000 /* 5ms */ }; // If we oversleep it's ok, i.e. ignore EINTR.
FD_ZERO(&readset);
for (dev=devices; dev; dev = dev->next) {
FD_SET(dev->fd, &readset);
}
result = select(max + 1, &readset, NULL, NULL, sleep ? NULL : &timeout);
} while (result == -1 && errno == EINTR);

if (result >= 0) {
for (dev=devices; dev; dev = dev->next) {
if (FD_ISSET(dev->fd, &readset)) {
queued_entry_t* entry = new queued_entry_t();
/* NOTE: driver guarantees we read exactly one full entry */
ret = read(dev->fd, entry->buf, LOGGER_ENTRY_MAX_LEN);
if (ret < 0) {
if (errno == EINTR) {
delete entry;
goto next;
}
if (errno == EAGAIN) {
delete entry;
break;
}
perror("logcat read");
exit(EXIT_FAILURE);
}
else if (!ret) {
fprintf(stderr, "read: Unexpected EOF!\n");
exit(EXIT_FAILURE);
}
else if (entry->entry.len != ret - sizeof(struct logger_entry)) {
fprintf(stderr, "read: unexpected length. Expected %d, got %d\n",
entry->entry.len, ret - sizeof(struct logger_entry));
exit(EXIT_FAILURE);

entry->entry.msg[entry->entry.len] = '\0';

dev->enqueue(entry);
++queued_lines;
}
}

if (result == 0) {
// we did our short timeout trick and there's nothing new
// print everything we have and wait for more data
sleep = true;
while (true) {
chooseFirst(devices, &dev);
if (dev == NULL) {
break;
}
if (g_tail_lines == 0 || queued_lines <= g_tail_lines) {
printNextEntry(dev);
} else {
skipNextEntry(dev);
}
--queued_lines;
}

// the caller requested to just dump the log and exit
if (g_nonblock) {
return;
}
} else {
// print all that aren't the last in their list
sleep = false;
while (g_tail_lines == 0 || queued_lines > g_tail_lines) {
chooseFirst(devices, &dev);
if (dev == NULL || dev->queue->next == NULL) {
break;
}
if (g_tail_lines == 0) {
printNextEntry(dev);
} else {
skipNextEntry(dev);
}
--queued_lines;
}
}
}
next:
;
}
}

可以看到在result>0的时候，也就是select在判断/dev/log/main和/dev/log/system两个路径中有任意一个是readable的话，就去执行如下函数

static void printNextEntry(log_device_t* dev) {
maybePrintStart(dev);
if (g_printBinary) {
printBinary(&dev->queue->entry);
} else {
processBuffer(dev, &dev->queue->entry);
}
skipNextEntry(dev);
}

static void skipNextEntry(log_device_t* dev) {
maybePrintStart(dev);
queued_entry_t* entry = dev->queue;
dev->queue = entry->next;
delete entry;
}

这里就会把/dev/log/main或者/dev/log/system中读到的信息（也就是前面用ALOGD存入的信息）打印到g_outFD所对应的设备上，默认的话就是终端

static void maybePrintStart(log_device_t* dev) {
if (!dev->printed) {
dev->printed = true;
if (g_devCount > 1 && !g_printBinary) {
char buf[1024];
snprintf(buf, sizeof(buf), "--------- beginning of %s\n", dev->device);
if (write(g_outFD, buf, strlen(buf)) < 0) {
perror("output error");
exit(-1);
}
}
}
}

到这里logcat的整个流程已经完毕，希望对大家有所帮助