Android logd日志简介及典型案例分析

在程序开发过程中,日志打印属于最普遍的操作,是代码调试和验证过程必不可少的手段。在Android开发过程中,我们经常通过Log\Slog等方式写入日志,然后通过对应的logcat命令读取相应的日志信息。具体日志如何写入或者读出,系统代码如何调用,可能也没有深入研究过。本文就通过具体的流程、框架设计、源码分析等讨论下Android日志的读写过程,以及介绍往往遇到日志丢失的场景及典型案例分析。

1、日志接口

日志接口内容,共分为java层、native层、kernel层等。下面就对每个层级的内容分别进行介绍。

1.1 java层调用接口

日志级别分别为VERBOSE、DEBUG、INFO、WARN、ERROR、ASSERT,日志级别依次提升。默认定义了5个buffer缓冲区,分别是main、radio、events、system、crash,对应的ID信息分别为LOG_ID_MAIN、LOG_ID_RADIO、LOG_ID_EVENTS、LOG_ID_SYSTEM、 LOG_ID_CRASH。

1.1.1 日志缓冲区简介

Android日志记录系统守护进程logd维护的一组结构化环形缓冲区,这组可用的缓冲区是固定的,且由系统定义。也可以通过logcat 命令查看如下缓冲区。

radio:查看包含无线装置/电话相关消息的缓冲区,可以调用android.telephony.Rlog打印日志。

events:查看经过解译的二进制系统时间缓冲区信息,类型为events的日志是用来诊断系统问题的。在应用框架提供了android.util.EventLog接口通过liblog动态库往日志驱动程序中写入日志,运行时库提供了宏LOG_EVENT_INT、LOG_EVENT_LONG、LOG_EVENT_FLOAT、LOG_EVENT_STRING用来写入events类型日志。

main:查看主日志缓冲区信息,main日志缓冲区是应用程序唯一可用的日志缓冲区,在应用框架中提供了android.util.Log接口通过liblog动态库往日志驱动程序中写入日志,运行时库提供了LOGV、LOGD、LOGI、LOGW、LOGE等宏用来写入main类型的日志。

system:查看系统缓冲区类型为system的日志,在应用框架提供了android.util.SLog接口通过liblog动态库往日志驱动程序中写入日志,运行时库提供了SLOGV、SLOGD、SLOGI、SLOGW、SLOGE等宏用来写入system类型的日志。

crash:查看崩溃日志缓冲区的日志信息。

1.1.2 命令查看缓冲区日志信息

ogcat -b + 参数查看对应缓冲区内容,具体见如下内容。

all:查看所有缓冲区日志

default:查看main、system、crash三个缓冲区日志信息

比如:logcat -b main用来查看main缓冲区信息;logcat -b main,system用来查看main和system缓冲区信息;logcat -b all 查看所有缓冲区信息。

1.2 native层接口调用

原生系统日志接口封装在liblog.so库中,供native层代码调用。最终通过socket的通信方式将日志写入logd的buffer中。具体调用过程需要引入liblog动态库,然后才能调用如下native层的日志接口__android_log_print,很多内容都封装成ALOGX的接口,具体内容可参考如下所示:

#define ALOGV(...) __android_log_print(ANDROID_LOG_VERBOSE, LOG_TAG, __VA_ARGS__)

#define ALOGD(...) __android_log_print(ANDROID_LOG_DEBUG  , LOG_TAG, __VA_ARGS__)

#define ALOGI(...) __android_log_print(ANDROID_LOG_INFO   , LOG_TAG, __VA_ARGS__)

#define ALOGW(...) __android_log_print(ANDROID_LOG_WARN   , LOG_TAG, __VA_ARGS__)

#define ALOGE(...) __android_log_print(ANDROID_LOG_ERROR  , LOG_TAG, __VA_ARGS__)

1.3 kernel层调用接口

经常使用的接口是printk,具体用法如下:

printk(KERN_INFO "\n");  //KERN_INFO为日志级别,"\n"则为日志信息。

日志级别信息如下:

kernel日志级别分别是:KERN_EMERG,KERN_ALERT,KERN_CRIT,KERN_ERR,KERN_WARNING,KERN_NOTICE,KERN_INFO,KERN_DEBUG

原生代码kern_levels.h中定义如下

#define KERN_EMERGKERN_SOH "0"/* system is unusable */

#define KERN_ALERTKERN_SOH "1"/* action must be taken immediately */

#define KERN_CRITKERN_SOH "2"/* critical conditions */

#define KERN_ERRKERN_SOH "3"/* error conditions */

#define KERN_WARNINGKERN_SOH "4"/* warning conditions */

#define KERN_NOTICEKERN_SOH "5"/* normal but significant condition */

#define KERN_INFOKERN_SOH "6"/* informational */

#define KERN_DEBUGKERN_SOH "7"/* debug-level messages */

日志输出到/proc/kmsg节点,用户可以通过cat节点信息获取kernel日志信息。

2、logd守护进程

2.1 整体设计架构

2.1.1 logd架构设计图

架构设计图内容简介如下:

logd启动过程还存在其他内容,比如LogStatistics :是日志统计模块,默认开启统计数据较少,仅能以 pid/uid 维度统计打印日志的数量。

整体日志打印过程:用户调用java层接口,通过JNI调用走到native层(native层接口调用直接加载liblog调用接口输入日志),加载liblog动态库,通过socket通信将日志写入和读取,最终输出到对应的文件或者控制台。

2.1.2 命令查看logd进程内容

2.1.2.1 logd进程内容如下图所示:

2.1.2.2 logd线程内容简介

2.2 logd启动内容

logd作为native service,系统启动过程通过读取rc文件来启动,相关的属性定义在如下logd.rc文件中。

2.2.1 logd启动过程

logd启动后会存在三个用来服务日志系统的socket:分别是

/dev/socket/logd、/dev/socket/logdr、/dev/socket/logdw。

2.2.2 日志打印buffer缓冲区

如下代码中的参数LOG_ID_MAIN:代表buffer缓冲区,DEBUG:代表日志级别。java层调用和native层调用存在轻微差异,很容易进行辨别。native的级别和buffer比较全面,大家可以通过源码参考下。具体的日志buffer缓冲区及日志等级,见下图所示。

/XXX/frameworks/base/core/java/android/util/Log.java

/**

 * Send a {@link #DEBUG} log message.

* @param tag Used to identify the source of a log message.  It usually identifies

*        the class or activity where the log call occurs.

* @param msg The message you would like logged.

* @return A positive value if the message was loggable (see {@link #isLoggable}).

*/

public static int d(@Nullable String tag, @NonNull String msg) {

    return println_native(LOG_ID_MAIN, DEBUG, tag, msg);

}

2.2.3 Android日志与logd交互过程

2.2.3.1 Android日志传递给logd

Android app层或framework层,通过调用Log/Slog/Rlog中d方法打印日志,通过JNI会调用到native层android_util_Log_println_native接口,具体见下图内容。

接下来具体调用流程如下:

/XXX/system/logging/liblog/logger_write.cpp

__android_log_buf_write

  -->__android_log_write_log_message

     -->get_logger_function()

        -->__android_log_logd_logger

           -->write_to_log

              -->LogdWrite

最终写到 “/dev/socket/logdw”中,此时logd中的LogListener会监测到存在log信息需要写入,待log保存到buffer中后,再通知LogReader将新保存的log传递给logcat等

socket信息如下

// Note that it is safe to call connect() multiple times on DGRAM Unix domain sockets, so this

// function is used to reconnect to logd without requiring a new socket.

static void LogdConnect(int sock) {

sockaddr_un un = {};

un.sun_family = AF_UNIX;

    strcpy(un.sun_path, "/dev/socket/logdw");

    TEMP_FAILURE_RETRY(connect(sock, reinterpret_cast(&un), sizeof(sockaddr_un)));

}

2.2.3.2 logd中的log保存过程

具体代码路径如/XXX/system/logging/logd/main.cpp,从文件的main函数中可以看到,logd执行过程中创建了LogBuffer,LogReader,LogListener和CommandListener四个对象,上文有详细介绍,本节暂且不予解释,详情见2.3.1.2节内容。

接下来创建LogListener的对象,开启一个线程“logd.writer”监听数据,具体过程见下图。

HandleData()

-->logbuf_->Log

新建一个LogBufferElement对象,实现log的保存.

2.2.3.3 logcat获取logd日志

/XXX/system/logging/logcat/logcat.cpp

int main(int argc, char** argv) {

Logcat logcat;

return logcat.Run(argc, argv);

}

具体的logcat命令参数解析在Run函数中执行。

android_logger_list_read接下来的调用过程如下:

android_logger_list_read

-->LogdRead //打开logdr,并通过socket获取log

-->logdOpen

logd的main函数中有开启LogReader监听

// LogReader listens on /dev/socket/logdr. When a client

// connects, log entries in the LogBuffer are written to the client.

LogReader* reader = new LogReader(log_buffer, &reader_list);

if (reader->startListener()) {

  return EXIT_FAILURE;

}

LogReader继承自SocketListener,如果socket监听到数据,则执行onDataAvailable函数进行处理。

最后加入read_list_中:

最终通过ProcessBuffer输出日志内容,打印log_msg日志到界面或者fd文件中。具体内容包括:处理日志buffer内容、回滚打印日志内容等。

2.3 kernel日志写入logd介绍

通过logcat命令获取kernel日志比较特殊,故作为一个例子进行梳理。

2.3.1 整体流程

2.3.2 命令打印kernel日志

通过logcat -b kernel获取kernel日志,依赖于如下属性值,具体查看源码xxx/system/logging/logd/main.cpp中有体现。

2.3.3 详细总结流程

2.3.3.1 logd的日志流程

2.3.3.2 监听kernel log

2.3.3.3 SocketListener关于onDataAvailable的回调

2.3.3.4 日志写入LOG_ID_KERNEL buffer中

2.3.3.4 kernel日志buffer的流程

此流程细节内容,建议辅助查看源码分析。

3、logcat命令介绍

具体的参数使用可以通过命令查看,或者查看具体的源码,当然直接查看命令较为方便。

3.1 logcat帮助命令

3.2 日志等级:

3.3 查看缓冲区buffer:

logbuffer默认设置在LogSize.h文件中

命命令查看buffer如下:

3.4 命令抓取日志

logcat -b main -b system -b crash -r 1024 -n 5 -f android.log -v threadtime

-b:加载可供查看的缓冲区的日志

-b main:抓取main缓冲区的日志;

-b system:抓取system缓冲区的日志;

-b crash:抓取crash缓冲区的日志;

-r:每次输出多大日志文件后进行轮替

-r 1024:代表每份文件日志最大size为1024KB,也就是1M

-n:日志输出最大数目,最多是n+1份

-n 5:日志文件输出最多5+1=6份

-f:logcat日志内容保存的位置

-f android.log:日志输出文件目录

-v:设置日志消息输出格式

-v:threadtime 显示日期,调用时间,优先级,标记,以及发出消息的线程的pid和tid信息

如上命令抓取日志流程如下,具体查看logcat.cpp的源码

直到停止日志打印操作,则结束日志输出文件的流程。

3.5 具体命令操作展示

建议参考如下命令,在终端设备模拟练习。

4、典型案例分析

下面针对一些典型场景缺通用日志(android/kernel)的问题,一一列举如下,希望可以让大家关注到缺日志的真实原因。如下问题也提醒各位工程师:  谨慎添加日志,不要随意添加,否则即容易造成自己的日志缺失也会导致其他业务模块丢失日志。

通用日志丢失目前有如下情况会出现:

(1) liblog通过socket传输日志时失败,此时在event日志中会记录类似上图中tag=liblog的埋点。具体见4.1、4.2节内容。

(2) 其它进程通过socket读取logd的日志时,此时由于日志打印速度过快,读取速度跟不上写入速度,造成了部分历史日志被丢弃的情况,此时在event日志中会记录tag=chatty的埋点。此种情况遇到较少。

(3) logd buffer中日志内存超过buffer大小了,则会按照每次裁剪日志的行数等于日志总行数的10%,并且会大于等于4行,小于256行。环形buffer大小超过了,会不断循环裁剪。

(4) 文件存储问题,导致日志内容无法落盘至日志文件。具体见4.3节内容。

(5) 低内存查杀日志进程,导致日志内容无法落盘。具体见4.4节内容。

日志丢失的问题可能不止以上原因,基本分析思路是首先了解问题发生场景及时间点,然后通过日志抓取和落盘场景进行分析,参考业务日志打印频率、logd的状态(logd的cpu负载、运行状态)、系统的异常状态(严重低内存、整机CPU负载高、文件系统异常、温度过高限频限核)等综合原因,得出问题分析结论。往往日志缺失和系统状态联系较为紧密,所以分析此类问题,就要具备开阔的视野,能够及时联想到有关整机各个状态,推测和佐证自己的分析原因和得出的结论。具体分析过程,也可以参考思维导图。

下面针对以上内容,列举如下几个典型案例,仅供大家参考。

4.1 业务日志输出频率太高

(1) events日志出现大量丢弃日志打印

(2) 查看android日志,发现sensor日志打印量非常大,基本达到刷屏的程度

(3) android日志输出频率达4229条/秒,日志输出频率非常大,sensor日志打印处于top1,达到2418条/s。

总结:sensor日志打印频率太高,超过了socket的处理能力,不能及时处理只能先行丢掉。故导致部分日志丢失。

4.2 整机负载高

(1) 输出的日志出现大量的日志丢失内容

(2) 查看日志打印频率,发现日志输出频率较低

(3) 查看systrace发现整机负载高达90%以上,logd一直处于runanble状态,整机温度也较高导致触发了限频限核。

总结:logd一直处于runnable状态,导致logd无法获得cpu时间片执行日志操作,容易出现socket通信失败,故导致部分日志丢失。

4.3 存储异常导致

(1) 查看日志发现mmap异常

(2) 由于没有过多日志打印,故本地使用adb logcat抓取日志分析

总结:文件存储出现问题,日志无法输出到对应的文件中,日志信息无法得到落盘,故出现日志内容大量丢失。

4.4 低内存导致

(1) 日志文件为空

(2) kernel日志中发现打印日志进程被杀

(3) 查看内存,已经处于低内存状态

总结:低内存导致日志进程被杀,出现日志文件无对应的日志信息落盘,故出现日志内容丢失。

还有其他原因,欢迎大家补充交流!

5、资源消耗问题

打印日志是非常消耗资源的,原因可概括如下:

(1) 跨进程通信的消耗:日志信息通过 socket 发送给 logd,存在跨进程通信的消耗;

(2) 内存消耗:logd 中维持对应的buffer,存在相应RAM的消耗,往往低存储机器在低内存过程表现尤为突出;

(3) CPU资源消耗:logd中ring buffer会经常进行 pruneLogs操作,进行删减日志,会耗费一定的CPU资源;业务日志打印太多容易导致logd在一段时间出现cpu负载非常高的现象;

(4) IO消耗:在应用程序中 ,创建后台线程保存日志信息,这会导致应用或者整机卡顿。

(5) 功耗消耗:往往业务日志打印较多,导致logd的cpu负载非常高,直观表现就是发热和续航恶化。

(6) 性能消耗:日志打印过多,也容易导致界面操作卡顿,从而表现出整机性能方面的消耗。

所以,规劝大家在打印日志过程一定要注意。在正式版本中,一定要规范日志打印,要有系统资源消耗及整机性能的意识。最好建立自己模块的故障检测能力,平时做到少量日志打印,遇到故障可以适当增加日志打印。

文中有些不对的内容,也欢迎大家及时指正,期待与您一块成长!

参考文档:

https://www.jianshu.com/p/4b08af887fb7

https://blog.csdn.net/mafei852213034/article/details/117780317

手机投屏之WFD简介

ARM NEON在矩阵&向量计算中的加速

OPPO在CLK大会上公布可编程内核技术,引领安卓流畅体验升级

长按关注内核工匠微信

Linux内核黑科技| 技术文章| 精选教程