Android Log机制的原理学习

应用程序的运行与维护，离不开日志。APP开发者们有很多选择，例如微信的xlog（高可靠性高性能的运行期日志组件）等，同样也离不开原生的日志机制支持。所以我们从原生Android Log机制开始学起：

一. Android Log机制（基于Android P原生代码）

APP打印日志，最简单的是使用Log类（android.util.Log），如下例子：

import android.util.Log;

public class MainActivity extends Activity {
    @Override
    protected void onCreate(Bundle savedInstanceState) {
           super.onCreate(savedInstanceState);
           setContentView(R.layout.activity_main);
 
           Log.d("kevintest", "onCreate");
    }
    // ...
}

APP运行，进入页面后，通过adb logcat命令，会看到有一行日志打印出：


1. 日志类型有5类


2. 上述类型中，LOG_ID_MAIN、LOG_ID_RADIO、LOG_ID_SYSTEM的优先级有6种

一般使用时，级别值越高，打印的日志越重要，从变量字面意思也可理解。Google官方文档中有这样的建议：VERBOSE日志只建议用于开发调试的版本，不能被编译入其他版本，如release版本；DEBUG日志可用于release版本产品，但默认不会打印；INFO、WARN、ERROR日志建议在release版本中使用与保存。手机中一般默认的日志打印级别是INFO（包括INFO、WARN、ERROR），可参考：开发者选项-选择日志级别


3. 原生代码分析

首先我们重点看下android.util.Log类：
Log类定义较简单，无父类，final修饰，不可继承。构造函数是private，不可实例化。举例，APP调用Log.v方法打印VERBOSE日志时，其方法实现是：

public static int v(String tag, String msg) {
       return println_native(LOG_ID_MAIN, VERBOSE, tag, msg);
}

其中关键的方法是println_native，方法实现位于：frameworks/base/core/jni/android_util_Log.cpp，传入的三个参数分别是：LOG_ID_MAIN（类型），VERBOSE（级别），tag（标签），msg（日志信息），实现如下：

static jint android_util_Log_println_native(JNIEnv* env, jobject clazz,
        jint bufID, jint priority, jstring tagObj, jstring msgObj) {
    // ...
    int res = __android_log_buf_write(bufID, (android_LogPriority)priority, tag, msg);
    // ...
    return res;
}

继续调用__android_log_buf_write方法，方法定义：system/core/liblog/include/android/log.h，实现：system/core/liblog/logger_write.c，其中核心部分：

注意：其他一些系统模块，例如debuggered等C++代码都会直接封装or调用__android_log_buf_write来打印日志

LIBLOG_ABI_PUBLIC int __android_log_buf_write(int bufID, int prio,
                                              const char* tag, const char* msg) {
     struct iovec vec[3];
     // ......
     vec[0].iov_base = (unsigned char*)&prio;      // 例如通过Log.v调用过来，这里是2（VERBOSE）
     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(bufID, vec, 3);
}

继续调用write_to_log方法，实现：system/core/liblog/logger_write.c，其中核心部分：

注意：第一次真正执行的方法是：__write_to_log_init，初始化后write_to_log的的方法实现变为：__write_to_log_daemon。详细参见__write_to_log_init的方法实现

static int __write_to_log_init(log_id_t, struct iovec* vec, size_t nr);
static int (*write_to_log)(log_id_t, struct iovec* vec,
                           size_t nr) = __write_to_log_init;
// ...
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();
        if (ret < 0) {
            __android_log_unlock();
            if (!list_empty(&__android_log_persist_write)) {
                __write_to_log_daemon(log_id, vec, nr);
            }
           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) {
    // ...
}

继续调用__write_to_log_daemon方法，实现：system/core/liblog/logger_write.c，其中核心部分：

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;
        }
   }
   // ...
}



下一步是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
//...

例如adb shell连接手机，通过ss -pl查看socket连接：

进程启动后，入口方法：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);
}

首先看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));
    }
    // ...
}

继续看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方法，大致思路是：
a. 支持黑/白名单（详见LogWhiteBlackList.cpp，uid + pid。注意：adb logcat -P可设置），白名单中不裁剪
b. 优先裁剪黑名单、打印日志最多的uid，system uid中打印日志最多的pid

至此一次完整的：APP调用Log.v方法打印VERBOSE日志，调用执行过程完毕！



二. Logcat命令行工具

官方定义：

Logcat 是一个命令行工具，用于转储系统消息日志，包括设备抛出错误时的堆栈轨迹，以及从您的应用中使用 Log 类写入的消息。

常用命令：

代码位置：system/core/logcat/，可执行文件位于：/system/bin/logcat，每次执行adb shell logcat命令后，系统会新起一个logcat进程，用来处理命令，父进程是adbd进程。adb shell logcat命令退出后，进程退出。

logcat进程启动时入口在logcat_main.cpp#main()方法，其中核心android_logcat_run_command方法中调用__logcat方法来解析命令参数，最终通过Socket发送给logd处理等，例如clear命令会通过发送给logd的CommandListener类（logd.control线程）来处理。



三. 参考资料

  1. https://developer.android.com/reference/android/util/Log

  2. https://developer.android.com/studio/command-line/logcat?hl=zh_cn，logcat命令行工具

  3. https://developer.android.com/studio/debug/am-logcat，使用logcat写入和查看日志

  4. http://gityuan.com/2018/01/27/android-log/，Android logd日志原理

  5. https://developer.android.com/studio/command-line/logcat





作者：kevin song，2019.10.14于南京建邺区

©著作权归作者所有,转载或内容合作请联系作者
  • 人面猴
    序言：七十年代末，一起剥皮案震惊了整个滨河市，随后出现的几起案子，更是在滨河造成了极大的恐慌，老刑警刘岩，带你破解...
    沈念sama阅读 212,080评论 6赞 493
  • 死咒
    序言：滨河连续发生了三起死亡事件，死亡现场离奇诡异，居然都是意外死亡，警方通过查阅死者的电脑和手机，发现死者居然都...
    沈念sama阅读 90,422评论 3赞 385
  • 救了他两次的神仙让他今天三更去死
    文/潘晓璐 我一进店门，熙熙楼的掌柜王于贵愁眉苦脸地迎上来，“玉大人，你说我怎么就摊上这事。” “怎么了？”我有些...
    开封第一讲书人阅读 157,630评论 0赞 348
  • 道士缉凶录：失踪的卖姜人
    文/不坏的土叔 我叫张陵，是天一观的道长。 经常有香客问我，道长，这世上最难降的妖魔是什么？ 我笑而不...
    开封第一讲书人阅读 56,554评论 1赞 284
  • 港岛之恋（遗憾婚礼）
    正文 为了忘掉前任，我火速办了婚礼，结果婚礼上，老公的妹妹穿的比我还像新娘。我一直安慰自己，他们只是感情好，可当我...
    茶点故事阅读 65,662评论 6赞 386
  • 恶毒庶女顶嫁案：这布局不是一般人想出来的
    文/花漫 我一把揭开白布。 她就那样静静地躺着，像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上，一...
    开封第一讲书人阅读 49,856评论 1赞 290
  • 城市分裂传说
    那天，我揣着相机与录音，去河边找鬼。 笑死，一个胖子当着我的面吹牛，可吹牛的内容都是我干的。 我是一名探鬼主播，决...
    沈念sama阅读 39,014评论 3赞 408
  • 双鸳鸯连环套：你想象不到人心有多黑
    文/苍兰香墨 我猛地睁开眼，长吁一口气：“原来是场噩梦啊……” “哼！你这毒妇竟也来了？” 一声冷哼从身侧响起，我...
    开封第一讲书人阅读 37,752评论 0赞 268
  • 万荣杀人案实录
    序言：老挝万荣一对情侣失踪，失踪者是张志新（化名）和其女友刘颖，没想到半个月后，有当地人在树林里发现了一具尸体，经...
    沈念sama阅读 44,212评论 1赞 303
  • 护林员之死
    正文 独居荒郊野岭守林人离奇死亡，尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 36,541评论 2赞 327
  • 白月光启示录
    正文 我和宋清朗相恋三年，在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 38,687评论 1赞 341
  • 活死人
    序言：一个原本活蹦乱跳的男人离奇死亡，死状恐怖，灵堂内的尸体忽然破棺而出，到底是诈尸还是另有隐情，我是刑警宁泽，带...
    沈念sama阅读 34,347评论 4赞 331
  • 日本核电站爆炸内幕
    正文 年R本政府宣布，位于F岛的核电站，受9级特大地震影响，放射性物质发生泄漏。R本人自食恶果不足惜，却给世界环境...
    茶点故事阅读 39,973评论 3赞 315
  • 男人毒药：我在死后第九天来索命
    文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹，春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 30,777评论 0赞 21
  • 一桩弑父案，背后竟有这般阴谋
    文/苍兰香墨 我抬头看了看天上的太阳。三九已至，却和暖如春，着一层夹袄步出监牢的瞬间，已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 32,006评论 1赞 266
  • 情欲美人皮
    我被黑心中介骗来泰国打工， 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留，地道东北人。 一个月前我还...
    沈念sama阅读 46,406评论 2赞 360
  • 代替公主和亲
    正文 我出身青楼，却偏偏与公主长得像，于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子，可洞房花烛夜当晚...
    茶点故事阅读 43,576评论 2赞 349

推荐阅读更多精彩内容