（Android系統）android log機制淺析

標籤：des   android   style   class   blog   code   

在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 availableif (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的整個流程已經完畢，希望對大家有所協助