android

Android logd日志原理

Posted by Gityuan on January 27, 2018

基于Android源码6.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/logd_write.c
/system/core/liblog/uio.c

/system/core/logd/
    - main.cpp
    - LogBuffer.cpp
    - LogStatistics.cpp
/system/core/libsysutils/src/SocketListener.cpp

一. 概述

无论是Android系统开发，还是应用开发，都离不开log，Androd上层采用logcat输出log。

1.1 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.

二. 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

2.4 buffer大小

LogBuffer.cpp

可知 radio = 4M, 其他都为2M.

三. 原理分析

3.1 Log.i

[-> android/util/Log.java]

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]

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

[-> logd_write.c]

int __android_log_buf_write(int bufID, int prio, const char *tag, const char *msg)
{
    struct iovec vec[3];
    char tmp_tag[32];
    ...

    if ((bufID != LOG_ID_RADIO) &&
         (!strcmp(tag, "HTC_RIL") ||
        !strncmp(tag, "RIL", 3) || // RIL为前缀
        !strncmp(tag, "IMS", 3) || // IMS为前缀
        !strcmp(tag, "AT") ||
        !strcmp(tag, "GSM") ||
        !strcmp(tag, "STK") ||
        !strcmp(tag, "CDMA") ||
        !strcmp(tag, "PHONE") ||
        !strcmp(tag, "SMS"))) {
            bufID = LOG_ID_RADIO;
            //满足以上条件的tag，则默认输出到radio缓冲区，并修改相应的tags
            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;
    // [见小节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

[-> logd_write.c]

static int __write_to_log_init(log_id_t log_id, struct iovec *vec, size_t nr)
{
    ...
    if (write_to_log == __write_to_log_init) {
        int ret;
        ret = __write_to_log_initialize(); //执行log初始化【见小节3.4.1】
        if (ret < 0) {
            if (pstore_fd >= 0) {
                __write_to_log_daemon(log_id, vec, nr); //【见小节3.5】
            }
            return ret;
        }
        write_to_log = __write_to_log_daemon;
    }
    ...
    return write_to_log(log_id, vec, nr);
}

3.4.1 __write_to_log_initialize

static int __write_to_log_initialize()
{
    int i, ret = 0;
    if (pstore_fd < 0) {
        //打开pstore文件, 用于panic时记录上次重启前的log
        pstore_fd = TEMP_FAILURE_RETRY(open("/dev/pmsg0", O_WRONLY));
    }

    if (logd_fd < 0) { //首次执行logd_fd = -1
        // 初始化socket
        i = TEMP_FAILURE_RETRY(socket(PF_UNIX, SOCK_DGRAM | SOCK_CLOEXEC, 0));
        if (i < 0) {
            ret = -errno;
        //设置为非阻塞模式
        } else if (TEMP_FAILURE_RETRY(fcntl(i, F_SETFL, O_NONBLOCK)) < 0) {
            ret = -errno;
            close(i);
        } else {
            struct sockaddr_un un;
            memset(&un, 0, sizeof(struct sockaddr_un));
            un.sun_family = AF_UNIX;
            strcpy(un.sun_path, "/dev/socket/logdw"); // socket通道
            // 连接该socket
            if (TEMP_FAILURE_RETRY(connect(i, (struct sockaddr *)&un,
                                           sizeof(struct sockaddr_un))) < 0) {
                ret = -errno;
                close(i);
            } else {
                logd_fd = i; // 将新打开的socket的文件描述符赋予该logd_fd.
            }
        }
    }
    return ret;
}

该方法主要功能:

  1. 打开pstore文件, 用于panic时记录上次重启前的log; (只打开一次);
  2. 初始化并连接socket (“/dev/socket/logdw”), 设置为非阻塞模式;
  3. 将socket的文件描述符赋予该logd_fd.

接下来进入真正写log的方法.

3.5 __write_to_log_daemon

static int __write_to_log_daemon(log_id_t log_id, struct iovec *vec, size_t nr)
{
    ssize_t ret;
    ...
    static const unsigned header_length = 2;
    struct iovec newVec[nr + header_length];
    android_log_header_t header;
    android_pmsg_log_header_t pmsg_header;
    struct timespec ts;
    size_t i, payload_size;
    static uid_t last_uid = AID_ROOT;
    static pid_t last_pid = (pid_t) -1;
    static atomic_int_fast32_t dropped;
    ...

    if (last_uid == AID_ROOT) {
        last_uid = getuid(); //获取uid
    }
    if (last_pid == (pid_t) -1) {
        last_pid = getpid(); //获取pid
    }

    clock_gettime(CLOCK_REALTIME, &ts); //获取realtime

    pmsg_header.magic = LOGGER_MAGIC;
    pmsg_header.len = sizeof(pmsg_header) + sizeof(header);
    pmsg_header.uid = last_uid;
    pmsg_header.pid = last_pid;

    header.tid = gettid(); //获取tid
    header.realtime.tv_sec = ts.tv_sec;
    header.realtime.tv_nsec = ts.tv_nsec;

    newVec[0].iov_base   = (unsigned char *) &pmsg_header;
    newVec[0].iov_len    = sizeof(pmsg_header);
    newVec[1].iov_base   = (unsigned char *) &header;
    newVec[1].iov_len    = sizeof(header);

    if (logd_fd > 0) {
        int32_t snapshot = atomic_exchange_explicit(&dropped, 0, memory_order_relaxed);
        if (snapshot) {
            android_log_event_int_t buffer;

            header.id = LOG_ID_EVENTS;
            buffer.header.tag = htole32(LIBLOG_LOG_TAG);
            buffer.payload.type = EVENT_TYPE_INT;
            buffer.payload.data = htole32(snapshot);

            newVec[2].iov_base = &buffer;
            newVec[2].iov_len  = sizeof(buffer);
            ret = TEMP_FAILURE_RETRY(writev(logd_fd, newVec + 1, 2));
            if (ret != (ssize_t)(sizeof(header) + sizeof(buffer))) {
                atomic_fetch_add_explicit(&dropped, snapshot, memory_order_relaxed);
            }
        }
    }
    header.id = log_id;

    for (payload_size = 0, i = header_length; i < nr + header_length; i++) {
        newVec[i].iov_base = vec[i - header_length].iov_base;
        payload_size += newVec[i].iov_len = vec[i - header_length].iov_len;
        // 限制每条log最大为4076b
        if (payload_size > LOGGER_ENTRY_MAX_PAYLOAD) {
            newVec[i].iov_len -= payload_size - LOGGER_ENTRY_MAX_PAYLOAD;
            if (newVec[i].iov_len) {
                ++i;
            }
            payload_size = LOGGER_ENTRY_MAX_PAYLOAD;
            break;
        }
    }
    pmsg_header.len += payload_size;

    if (pstore_fd >= 0) {
        //写入pstore
        TEMP_FAILURE_RETRY(writev(pstore_fd, newVec, i));
    }
    ...

    // 写入logd[见小节3.6]
    ret = TEMP_FAILURE_RETRY(writev(logd_fd, newVec + 1, i - 1));
    ...
    if (ret > (ssize_t)sizeof(header)) {
        ret -= sizeof(header);
    } else if (ret == -EAGAIN) {
        atomic_fetch_add_explicit(&dropped, 1, memory_order_relaxed);
    }
    return ret;
}

该方法的主要功能, 准备log相关的信息:

  • pid
  • uid
  • tid
  • realtime
  • msg

3.6 writev

[-> uio.c]

int  writev( int  fd, const struct iovec*  vecs, int  count )
{
    int   total = 0;
    for ( ; count > 0; count--, vecs++ ) {
        const char*  buf = vecs->iov_base;
        int          len = vecs->iov_len;

        while (len > 0) {
            //将数据写入fd
            int  ret = write( fd, buf, len );
            ...
            total += ret;
            buf   += ret;
            len   -= ret;
        }
    }
Exit:
    return total;
}

3.7 小节

一句话总结就是Log.i()最终是通过调用write()向logd守护进程的socket(“/dev/socket/logdw”)端写入需要打印的日志信息。 接下来再来看logd的工作过程。

四. logd守护进程

logd是由init进程所启动的守护进程

service logd /system/bin/logd
    class core
    socket logd stream 0666 logd logd
    socket logdr seqpacket 0666 logd logd
    socket logdw dgram 0222 logd logd
    group root system

创建3个socket通道,用于进程间通信.

4.1 main()

[-> /system/core/logd/main.cpp]

int main(int argc, char *argv[]) {
    int fdPmesg = -1;
    bool klogd = true;
    if (klogd) {
        //以只读方式 打开内核log的/proc/kmsg
        fdPmesg = open("/proc/kmsg", O_RDONLY | O_NDELAY);
    }
    //以读写方式打开/dev/kmsg
    fdDmesg = open("/dev/kmsg", O_WRONLY);

    //处理reinit命令
    if ((argc > 1) && argv[1] && !strcmp(argv[1], "--reinit")) {
        int sock = TEMP_FAILURE_RETRY(socket_local_client("logd",
                        ANDROID_SOCKET_NAMESPACE_RESERVED,SOCK_STREAM));
        ...
        static const char reinit[] = "reinit";
        //写入"reinit"
        ssize_t ret = TEMP_FAILURE_RETRY(write(sock, reinit, sizeof(reinit)));
        ...

        struct pollfd p;
        memset(&p, 0, sizeof(p));
        p.fd = sock;
        p.events = POLLIN;
        ret = TEMP_FAILURE_RETRY(poll(&p, 1, 100)); //进入poll轮询
        ...

        static const char success[] = "success";
        char buffer[sizeof(success) - 1];
        memset(buffer, 0, sizeof(buffer));
        //读取数据,保存到buffer
        ret = TEMP_FAILURE_RETRY(read(sock, buffer, sizeof(buffer)));
        ...
        //比较读取的数据是否为"success"
        return strncmp(buffer, success, sizeof(success) - 1) != 0;
    }

    sem_init(&reinit, 0, 0);
    sem_init(&uidName, 0, 0);
    sem_init(&sem_name, 0, 1);
    pthread_attr_t attr;
    if (!pthread_attr_init(&attr)) {
        ...
        if (!pthread_attr_setdetachstate(&attr, PTHREAD_CREATE_DETACHED)) {
            pthread_t thread;
            reinit_running = true;
            //创建线程"logd.daemon", 该线程入口函数reinit_thread_start()
            if (pthread_create(&thread, &attr, reinit_thread_start, NULL)) {
                reinit_running = false;
            }
        }
        pthread_attr_destroy(&attr);
    }
    ...

    LastLogTimes *times = new LastLogTimes();

    //创建LogBuffer对象
    logBuf = new LogBuffer(times);

    signal(SIGHUP, reinit_signal_handler);

    if (property_get_bool_svelte("logd.statistics")) {
        logBuf->enableStatistics();
    }

    //监听/dev/socket/logdr, 当client连接上则将buffer信息写入client.
    LogReader *reader = new LogReader(logBuf);
    if (reader->startListener()) {
        exit(1);
    }

    //监听/dev/socket/logdw, 新日志添加到LogBuffer, 并且LogReader发送更新给已连接的client
    LogListener *swl = new LogListener(logBuf, reader);
    if (swl->startListener(300)) {
        exit(1);
    }

    //监听/dev/socket/logd, 处理logd管理命令
    CommandListener *cl = new CommandListener(logBuf, reader, swl);
    if (cl->startListener()) {
        exit(1);
    }

    bool auditd = property_get_bool("logd.auditd", true);

    LogAudit *al = NULL;
    if (auditd) {
        bool dmesg = property_get_bool("logd.auditd.dmesg", true);
        al = new LogAudit(logBuf, reader, dmesg ? fdDmesg : -1);
    }

    LogKlog *kl = NULL;
    if (klogd) {
        kl = new LogKlog(logBuf, reader, fdDmesg, fdPmesg, al != NULL);
    }

    readDmesg(al, kl);

    if (kl && kl->startListener()) {
        delete kl;
    }

    if (al && al->startListener()) {
        delete al;
    }

    TEMP_FAILURE_RETRY(pause());

    exit(0);
}

该方法功能:

  1. LogReader: 监听/dev/socket/logdr, 当client连接上则将buffer信息写入client. 所对应线程名”logd.reader”
  2. LogListener: 监听/dev/socket/logdw, 新日志添加到LogBuffer, 并且LogReader发送更新给已连接的client. 所对应线程名”logd.writer”
  3. CommandListener: 监听/dev/socket/logd, 处理logd管理命令. 所对应线程名”logd.control”
  4. LogAudit: 所对应线程名”logd.auditd”
  5. LogKlog: 所对应线程名”logd.klogd”
  6. 入口reinit_thread_start: 所对应线程名”logd.daemon”
  7. LogTimeEntry::threadStart: 所对应线程名”ogd.reader.per”

另外, ANDROID_SOCKET_NAMESPACE_RESERVED代表位于/dev/socket名字空间。 通过adb命令, 可以看到logd进程有9个子线程。

logd      381   1     21880  9132  sigsuspend 7f8301fdac S /system/bin/logd
system    382   381   21880  9132  futex_wait 7f82fcf9c4 S logd.daemon
logd      383   381   21880  9132  poll_sched 7f8301fd1c S logd.reader
logd      384   381   21880  9132  poll_sched 7f8301fd1c S logd.writer
logd      385   381   21880  9132  poll_sched 7f8301fd1c S logd.control
logd      392   381   21880  9132  poll_sched 7f8301fd1c S logd.klogd
logd      393   381   21880  9132  poll_sched 7f8301fd1c S logd.auditd
logd      3716  381   21880  9132  futex_wait 7f82fcf9c4 S logd.reader.per
logd      4329  381   21880  9132  futex_wait 7f82fcf9c4 S logd.reader.per
logd      5224  381   21880  9132  futex_wait 7f82fcf9c4 S logd.reader.per

接下来, 继续回到前面log输出过程, 接下来进入logd的LogListener处理过程, 如下:

4.2 LogListener

[-> LogListener.cpp]

int main(int argc, char *argv[]) {
    ...
    logBuf = new LogBuffer(times); //[见小节4.2.1]
    LogListener *swl = new LogListener(logBuf, reader); //[见小节4.2.2]
    if (swl->startListener(300)) { //[见小节4.3]
        exit(1);
    }
    ...
}

4.2.1 LogBuffer.init

[-> LogBuffer.cpp]

void LogBuffer::init() {
    static const char global_tuneable[] = "persist.logd.size";
    static const char global_default[] = "ro.logd.size";
    //获取buffer默认大小
    unsigned long default_size = property_get_size(global_tuneable);
    if (!default_size) {
        default_size = property_get_size(global_default);
    }

    log_id_for_each(i) {
        char key[PROP_NAME_MAX];

        snprintf(key, sizeof(key), "%s.%s",
                 global_tuneable, android_log_id_to_name(i));
        unsigned long property_size = property_get_size(key);

        if (!property_size) {
            snprintf(key, sizeof(key), "%s.%s",
                     global_default, android_log_id_to_name(i));
            //比如获取的是persist.logd.size.system所对应的值
            property_size = property_get_size(key);
        }

        if (!property_size) {
            property_size = default_size;
        }

        if (!property_size) {
            //此值为256k
            property_size = LOG_BUFFER_SIZE;
        }

        if (setSize(i, property_size)) {
            //此值为64k
            setSize(i, LOG_BUFFER_MIN_SIZE);
        }
    }
}

buffer大小设置的优先级顺序为:

  1. persist.logd.size.xxx; 比如persist.logd.size.system;
  2. persist.logd.size;
  3. ro.logd.size;
  4. LOG_BUFFER_SIZE, 即256k;
  5. LOG_BUFFER_MIN_SIZE, 即64k。

4.2.2 LogListener

[-> LogListener.cpp]

LogListener::LogListener(LogBuffer *buf, LogReader *reader) :
        SocketListener(getLogSocket(), false),
        logbuf(buf),
        reader(reader) {
}

此处getLogSocket()过程创建logdw的服务端,并监听客户端消息.

4.2.3 SocketListener

SocketListener::SocketListener(int socketFd, bool listen) {
    init(NULL, socketFd, listen, false);
}

void SocketListener::init(const char *socketName, int socketFd, bool listen, bool useCmdNum) {
    mListen = listen; // mListen=false
    mSocketName = socketName;
    mSock = socketFd;
    mUseCmdNum = useCmdNum;
    pthread_mutex_init(&mClientsLock, NULL);
    mClients = new SocketClientCollection();
}

SocketListener对象创建完成，则开始执行SocketListener来监听socket请求。

4.3 startListener

[-> SocketListener.cpp]

int SocketListener::startListener() {
    return startListener(4);
}

int SocketListener::startListener(int backlog) {
    if (!mSocketName && mSock == -1) {
        ...
    } else if (mSocketName) {
        if ((mSock = android_get_control_socket(mSocketName)) < 0) {
            ...
        }
        fcntl(mSock, F_SETFD, FD_CLOEXEC);
    }

    if (mListen && listen(mSock, backlog) < 0) {
        return -1;
    } else if (!mListen)
        mClients->push_back(new SocketClient(mSock, false, mUseCmdNum));

    if (pipe(mCtrlPipe)) {
        return -1;
    }

    //创建线程[见小节4.4]
    if (pthread_create(&mThread, NULL, SocketListener::threadStart, this)) {
        return -1;
    }

    return 0;
}

通过调用pthread_create创建完线程，在新创建的线程中执行threadStart()过程。

4.4 threadStart

[-> SocketListener.cpp]

void *SocketListener::threadStart(void *obj) {
    SocketListener *me = reinterpret_cast<SocketListener *>(obj);
    me->runListener(); //[见小节4.5]
    pthread_exit(NULL);
    return NULL;
}

4.5 runListener

[-> SocketListener.cpp]

void SocketListener::runListener() {
    SocketClientCollection pendingList;
    while(1) {
        ...
        while (!pendingList.empty()) {
            it = pendingList.begin(); //找到第一个即将要处理的客户端
            SocketClient* c = *it;
            pendingList.erase(it);
            if (!onDataAvailable(c)) { //处理该消息[见小节4.6]
                release(c, false);
            }
            c->decRef();
        }
    }
}

4.6 onDataAvailable

[-> LogListener.cpp]

bool LogListener::onDataAvailable(SocketClient *cli) {
    static bool name_set;
    if (!name_set) {
        prctl(PR_SET_NAME, "logd.writer");
        name_set = true;
    }

    char buffer[sizeof_log_id_t + sizeof(uint16_t) + sizeof(log_time)
        + LOGGER_ENTRY_MAX_PAYLOAD];
    struct iovec iov = { buffer, sizeof(buffer) };
    memset(buffer, 0, sizeof(buffer));

    char control[CMSG_SPACE(sizeof(struct ucred))];
    struct msghdr hdr = {
        NULL,
        0,
        &iov, //记录buffer地址指针
        1,
        control,
        sizeof(control),
        0,
    };

    int socket = cli->getSocket();
     //通过socket接收消息,保存到hdr,其n代表消息长度
    ssize_t n = recvmsg(socket, &hdr, 0);
    ...

    struct ucred *cred = NULL;
    struct cmsghdr *cmsg = CMSG_FIRSTHDR(&hdr);
    //获取ucred信息
    while (cmsg != NULL) {
        if (cmsg->cmsg_level == SOL_SOCKET
                && cmsg->cmsg_type  == SCM_CREDENTIALS) {
            cred = (struct ucred *)CMSG_DATA(cmsg);
            break;
        }
        cmsg = CMSG_NXTHDR(&hdr, cmsg);
    }
    if (cred == NULL) {
        return false;
    }
    ...

    //获取android_log_header_t结构体指针
    android_log_header_t *header = reinterpret_cast<android_log_header_t *>(buffer);
    if (header->id >= LOG_ID_MAX || header->id == LOG_ID_KERNEL) {
        return false;
    }
    char *msg = ((char *)buffer) + sizeof(android_log_header_t);
    n -= sizeof(android_log_header_t);

    //[见小节4.7]
    if (logbuf->log((log_id_t)header->id, header->realtime,
            cred->uid, cred->pid, header->tid, msg,
            ((size_t) n <= USHRT_MAX) ? (unsigned short) n : USHRT_MAX) >= 0) {
        //[见小节4.8]
        reader->notifyNewLog();
    }
    return true;
}

LogBuffer.log()的参数说明:

  • android_log_header_t提供 log_id, realtime, tid
  • ucred提供 uid, pid.
  • msghdr提供 msg

4.7 LogBuffer.log

[-> 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) {
    ...
    //创建一条log信息
    LogBufferElement *elem = new LogBufferElement(log_id, realtime,
                                                  uid, pid, tid, msg, len);
    int prio = ANDROID_LOG_INFO;
    const char *tag = NULL;
    if (log_id == LOG_ID_EVENTS) {
        tag = android::tagToName(elem->getTag());
    } else {
        prio = *msg;
        tag = msg + 1;
    }
    if (!__android_log_is_loggable(prio, tag, ANDROID_LOG_VERBOSE)) {
        pthread_mutex_lock(&mLogElementsLock);
        stats.add(elem); //对于不运行输出log的状态下, 只统计log信息, 记录log本身
        stats.subtract(elem);
        pthread_mutex_unlock(&mLogElementsLock);
        delete elem;
        return -EACCES;
    }
    pthread_mutex_lock(&mLogElementsLock);
    LogBufferElementCollection::iterator it = mLogElements.end();
    LogBufferElementCollection::iterator last = it;
    //根据时间排序,找到应该插入的点
    while (last != mLogElements.begin()) {
        --it;
        if ((*it)->getRealTime() <= realtime) {
            break;
        }
        last = it;
    }

    //将log信息插入合适的位置
    if (last == mLogElements.end()) {
        mLogElements.push_back(elem);
    } else {
        uint64_t end = 1;
        bool end_set = false;
        bool end_always = false;

        LogTimeEntry::lock();
        LastLogTimes::iterator t = mTimes.begin();
        while(t != mTimes.end()) {
            LogTimeEntry *entry = (*t);
            if (entry->owned_Locked()) {
                if (!entry->mNonBlock) {
                    end_always = true;
                    break;
                }
                if (!end_set || (end <= entry->mEnd)) {
                    end = entry->mEnd;
                    end_set = true;
                }
            }
            t++;
        }
        if (end_always|| (end_set && (end >= (*last)->getSequence()))) {
            mLogElements.push_back(elem);
        } else {
            mLogElements.insert(last,elem);
        }
        LogTimeEntry::unlock();
    }

    stats.add(elem);  //[4.7.1]
    maybePrune(log_id); //[4.7.2]
    pthread_mutex_unlock(&mLogElementsLock);
    return len;
}

4.7.1 stats.add

[-> LogStatistics.cpp]

void LogStatistics::add(LogBufferElement *e) {
    log_id_t log_id = e->getLogId();
    unsigned short size = e->getMsgLen();
    mSizes[log_id] += size; //对应的buffer所使用大小增加
    ++mElements[log_id]; //对应的buffer中log记录加1;

    mSizesTotal[log_id] += size;
    ++mElementsTotal[log_id];

    if (log_id == LOG_ID_KERNEL) {
        return;
    }

    //以uid为单位, 添加到uidTable表格
    uidTable[log_id].add(e->getUid(), e);

    if (!enable) {
        return;
    }

    pidTable.add(e->getPid(), e);
    tidTable.add(e->getTid(), e);

    uint32_t tag = e->getTag();
    if (tag) {
        tagTable.add(tag, e);
    }
}

将log信息分别记录到uidTable, pidTable, tidTable, tagTable.

4.7.2 maybePrune

[-> LogBuffer.cpp]

void LogBuffer::maybePrune(log_id_t id) {
    size_t sizes = stats.sizes(id); //log占用内存大小
    unsigned long maxSize = log_buffer_size(id); //最大上限,比如2M
    if (sizes > maxSize) {
        size_t sizeOver = sizes - ((maxSize * 9) / 10); //超出90%的部分大小
        size_t elements = stats.realElements(id); // 真实的log行数
        size_t minElements = elements / 100; // 真实的log行数的1%行

        //minPrune = 4, 保证1%的log行数>=4
        if (minElements < minPrune) {
            minElements = minPrune;
        }
        unsigned long pruneRows = elements * sizeOver / sizes;
        if (pruneRows < minElements) { //保证>= 1%的log行数
            pruneRows = minElements;
        }

        //maxPrune = 256, 保证pruneRows<=256;
        if (pruneRows > maxPrune) {
            pruneRows = maxPrune;
        }
        prune(id, pruneRows); //[见小节4.7.3]
    }
}

假设某个buffer的大小为2M:

pruneRows = elements * sizeOver / sizes
          = elements * (1 - 0.9*(maxSize/sizes))
          = elements * (1 - 1.8/sizes);

其中elements代表的是当前buffer的log总行数;sizes代表对的是当前buffer的log总大小。

这就意味着某个buffer中的log行数越多，或者log占用内存越大，则需要裁剪的日志行数越多。每次裁剪日志行数等于总行数的10%，并且需要大于等于4行，且不超过256行。

4.7.3 prune

[-> LogBuffer.cpp]

bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
    LogTimeEntry *oldest = NULL;
    bool busy = false;
    bool clearAll = pruneRows == ULONG_MAX;

    LogTimeEntry::lock();

    LastLogTimes::iterator times = mTimes.begin();
    while(times != mTimes.end()) {
        LogTimeEntry *entry = (*times);
        if (entry->owned_Locked() && entry->isWatching(id)
                && (!oldest ||
                    (oldest->mStart > entry->mStart) ||
                    ((oldest->mStart == entry->mStart) &&
                     (entry->mTimeout.tv_sec || entry->mTimeout.tv_nsec)))) {
            oldest = entry;
        }
        times++;
    }

    LogBufferElementCollection::iterator it;

    if (caller_uid != AID_ROOT) {
        it = mLastSet[id] ? mLast[id] : mLogElements.begin();
        while (it != mLogElements.end()) {
            LogBufferElement *element = *it;

            if ((element->getLogId() != id) || (element->getUid() != caller_uid)) {
                ++it;
                continue;
            }

            if (!mLastSet[id] || ((*mLast[id])->getLogId() != id)) {
                mLast[id] = it;
                mLastSet[id] = true;
            }

            if (oldest && (oldest->mStart <= element->getSequence())) {
                busy = true;
                if (oldest->mTimeout.tv_sec || oldest->mTimeout.tv_nsec) {
                    oldest->triggerReader_Locked();
                } else {
                    oldest->triggerSkip_Locked(id, pruneRows);
                }
                break;
            }

            it = erase(it);
            pruneRows--;
        }
        LogTimeEntry::unlock();
        return busy;
    }

    //修剪 log最多的内容: 黑名单, uid, system uid的pid
    bool hasBlacklist = (id != LOG_ID_SECURITY) && mPrune.naughty();
    while (!clearAll && (pruneRows > 0)) {
        uid_t worst = (uid_t) -1;
        size_t worst_sizes = 0;
        size_t second_worst_sizes = 0;
        pid_t worstPid = 0;

        if (worstUidEnabledForLogid(id) && mPrune.worstUidEnabled()) {
            {   
                std::unique_ptr<const UidEntry *[]> sorted = stats.sort(
                    AID_ROOT, (pid_t)0, 2, id);

                if (sorted.get() && sorted[0] && sorted[1]) {
                    worst_sizes = sorted[0]->getSizes();
                    //buffer总大小的1/8为阈值
                    size_t threshold = log_buffer_size(id) / 8;
                    if ((worst_sizes > threshold)
                            && (worst_sizes > (10 * sorted[0]->getDropped()))) {
                        worst = sorted[0]->getKey();
                        second_worst_sizes = sorted[1]->getSizes();
                        if (second_worst_sizes < threshold) {
                            second_worst_sizes = threshold;
                        }
                    }
                }
            }

            if ((worst == AID_SYSTEM) && mPrune.worstPidOfSystemEnabled()) {
                // 对于system_server进程,根据pid来决策
                std::unique_ptr<const PidEntry *[]> sorted = stats.sort(
                    worst, (pid_t)0, 2, id, worst);
                if (sorted.get() && sorted[0] && sorted[1]) {
                    worstPid = sorted[0]->getKey(); //最糟糕的pid
                    second_worst_sizes = worst_sizes
                                       - sorted[0]->getSizes()
                                       + sorted[1]->getSizes();
                }
            }
        }

        if ((worst == (uid_t) -1) && !hasBlacklist) {
            break;
        }

        bool kick = false;
        bool leading = true;
        it = mLastSet[id] ? mLast[id] : mLogElements.begin();
        bool gc = pruneRows <= 1;
        if (!gc && (worst != (uid_t) -1)) {
            {   
                LogBufferIteratorMap::iterator found = mLastWorstUid[id].find(worst);
                if ((found != mLastWorstUid[id].end())
                        && (found->second != mLogElements.end())) {
                    leading = false;
                    it = found->second;
                }
            }
            if (worstPid) {
                // begin scope for pid worst found iterator
                LogBufferPidIteratorMap::iterator found
                    = mLastWorstPidOfSystem[id].find(worstPid);
                if ((found != mLastWorstPidOfSystem[id].end())
                        && (found->second != mLogElements.end())) {
                    leading = false;
                    it = found->second;
                }
            }
        }
        static const timespec too_old = {
            EXPIRE_HOUR_THRESHOLD * 60 * 60, 0
        };
        LogBufferElementCollection::iterator lastt;
        lastt = mLogElements.end();
        --lastt;
        LogBufferElementLast last;
        while (it != mLogElements.end()) {
            LogBufferElement *element = *it;

            if (oldest && (oldest->mStart <= element->getSequence())) {
                busy = true;
                if (oldest->mTimeout.tv_sec || oldest->mTimeout.tv_nsec) {
                    oldest->triggerReader_Locked();
                }
                break;
            }

            if (element->getLogId() != id) {
                ++it;
                continue;
            }

            if (leading && (!mLastSet[id] || ((*mLast[id])->getLogId() != id))) {
                mLast[id] = it;
                mLastSet[id] = true;
            }

            unsigned short dropped = element->getDropped();

            // remove any leading drops
            if (leading && dropped) {
                it = erase(it);
                continue;
            }

            if (dropped && last.coalesce(element, dropped)) {
                it = erase(it, true);
                continue;
            }

            if (hasBlacklist && mPrune.naughty(element)) {
                last.clear(element);
                it = erase(it);
                if (dropped) {
                    continue;
                }

                pruneRows--;
                if (pruneRows == 0) {
                    break;
                }

                if (element->getUid() == worst) {
                    kick = true;
                    if (worst_sizes < second_worst_sizes) {
                        break;
                    }
                    worst_sizes -= element->getMsgLen();
                }
                continue;
            }

            if ((element->getRealTime() < ((*lastt)->getRealTime() - too_old))
                    || (element->getRealTime() > (*lastt)->getRealTime())) {
                break;
            }

            if (dropped) {
                last.add(element);
                if (worstPid
                        && ((!gc && (element->getPid() == worstPid))
                            || (mLastWorstPidOfSystem[id].find(element->getPid())
                                == mLastWorstPidOfSystem[id].end()))) {
                    mLastWorstPidOfSystem[id][element->getUid()] = it;
                }
                if ((!gc && !worstPid && (element->getUid() == worst))
                        || (mLastWorstUid[id].find(element->getUid())
                            == mLastWorstUid[id].end())) {
                    mLastWorstUid[id][element->getUid()] = it;
                }
                ++it;
                continue;
            }

            if ((element->getUid() != worst)
                    || (worstPid && (element->getPid() != worstPid))) {
                leading = false;
                last.clear(element);
                ++it;
                continue;
            }

            pruneRows--;
            if (pruneRows == 0) {
                break;
            }

            kick = true;

            unsigned short len = element->getMsgLen();

            // do not create any leading drops
            if (leading) {
                it = erase(it);
            } else {
                stats.drop(element);
                element->setDropped(1);
                if (last.coalesce(element, 1)) {
                    it = erase(it, true);
                } else {
                    last.add(element);
                    if (worstPid && (!gc
                                || (mLastWorstPidOfSystem[id].find(worstPid)
                                    == mLastWorstPidOfSystem[id].end()))) {
                        mLastWorstPidOfSystem[id][worstPid] = it;
                    }
                    if ((!gc && !worstPid) || (mLastWorstUid[id].find(worst)
                                == mLastWorstUid[id].end())) {
                        mLastWorstUid[id][worst] = it;
                    }
                    ++it;
                }
            }
            if (worst_sizes < second_worst_sizes) {
                break;
            }
            worst_sizes -= len;
        }
        last.clear();

        if (!kick || !mPrune.worstUidEnabled()) {
            break; // the following loop will ask bad clients to skip/drop
        }
    }

    bool whitelist = false;
    bool hasWhitelist = (id != LOG_ID_SECURITY) && mPrune.nice() && !clearAll;
    it = mLastSet[id] ? mLast[id] : mLogElements.begin();
    while((pruneRows > 0) && (it != mLogElements.end())) {
        LogBufferElement *element = *it;

        if (element->getLogId() != id) {
            it++;
            continue;
        }

        if (!mLastSet[id] || ((*mLast[id])->getLogId() != id)) {
            mLast[id] = it;
            mLastSet[id] = true;
        }

        if (oldest && (oldest->mStart <= element->getSequence())) {
            busy = true;
            if (whitelist) {
                break;
            }

            if (stats.sizes(id) > (2 * log_buffer_size(id))) {
                // kick a misbehaving log reader client off the island
                oldest->release_Locked();
            } else if (oldest->mTimeout.tv_sec || oldest->mTimeout.tv_nsec) {
                oldest->triggerReader_Locked();
            } else {
                oldest->triggerSkip_Locked(id, pruneRows);
            }
            break;
        }

        if (hasWhitelist && !element->getDropped() && mPrune.nice(element)) {
            // WhiteListed
            whitelist = true;
            it++;
            continue;
        }

        it = erase(it);
        pruneRows--;
    }

    // Do not save the whitelist if we are reader range limited
    if (whitelist && (pruneRows > 0)) {
        it = mLastSet[id] ? mLast[id] : mLogElements.begin();
        while((it != mLogElements.end()) && (pruneRows > 0)) {
            LogBufferElement *element = *it;

            if (element->getLogId() != id) {
                ++it;
                continue;
            }

            if (!mLastSet[id] || ((*mLast[id])->getLogId() != id)) {
                mLast[id] = it;
                mLastSet[id] = true;
            }

            if (oldest && (oldest->mStart <= element->getSequence())) {
                busy = true;
                if (stats.sizes(id) > (2 * log_buffer_size(id))) {
                    // kick a misbehaving log reader client off the island
                    oldest->release_Locked();
                } else if (oldest->mTimeout.tv_sec || oldest->mTimeout.tv_nsec) {
                    oldest->triggerReader_Locked();
                } else {
                    oldest->triggerSkip_Locked(id, pruneRows);
                }
                break;
            }

            it = erase(it);
            pruneRows--;
        }
    }

    LogTimeEntry::unlock();

    return (pruneRows > 0) && busy;
}

在PruneList::init()过程会完成黑白名单.

日志裁剪功能说明：

  1. 裁剪黑名单以及log打印最多的那个uid, 以及system uid中打印日志最多的pid进程中的日志;
  2. 白名单的不删除

4.8 小节

每一行log记录为LogBufferElement，logd的执行调用链如下

SocketListener::runListener()
    LogListener.onDataAvailable
        LogBuffer::log
            LogBuffer::maybePrune
        LogReader::notifyNewLog
            SocketListener::runOnEachSocket
            FlushCommand::runSocketCommand

五. 总结

当日志输出过于频繁或者日志占用内存过大时，会有日志裁剪的动作：每次裁剪日志行数等于总行数的10%，并且需要大于等于4行，且不超过256行，优先裁剪黑名单以及log打印最多的那个uid, 以及system uid中打印日志最多的pid进程中的日志，也可以设置不裁剪的白名单。

buffer大小设置的优先级顺序为:

  1. persist.logd.size.xxx; 比如persist.logd.size.system;
  2. persist.logd.size;
  3. ro.logd.size;
  4. LOG_BUFFER_SIZE, 即256k;
  5. LOG_BUFFER_MIN_SIZE, 即64k。

参数说明：

属性名 类型 默认值 含义
logd.auditd bool true 启动selinux审核守护进程
logd.auditd.dmesg bool true selinux审核信息发送到dmesg log
logd.klogd bool depends 启动klogd守护进程
logd.statistics bool depends 使能logcat -S statistics
persist.logd.logpersistd string   启用logpersist守护进程
persist.logd.size number 256K 所有日志缓存区大小的默认大小
persist.logd.size.main number 256K main日志缓存区大小
persist.logd.size.system number 256K system日志缓存区大小
persist.logd.size.radio number 256K radio日志缓存区大小
persist.logd.size.event number 256K event日志缓存区大小
persist.logd.size.crash number 256K crash日志缓存区大小

例如: setprop persist.logd.size.system 2m来调整日志缓存区大小。

微信公众号 Gityuan | 微博 weibo.com/gityuan | 博客 留言区交流
CATALOG
    标签
    android 组件系列 else debug 权限 web tool java performance app algorithm 进程系列 虚拟机 memory jvm linux binder ipc handler process power 系统启动 AMS PMS 自学编程 stability 组件 art graphic NativeDebug 实战案例 flutter