Android内存优化（二）系统进程之logd的native memory优化_native logd

最近的测试发现，C1 logd进程内存占用比Mate9 logd进程内存占用大很多，详细数据如下：
内存最大值（KB） 内存最小值（KB） 内存平均值（KB）
C1 39794 21985 39353
Mate9 2804 2565 2719

怀疑有native内存泄露，或者内存老化问题出现，于是做了针对性的Native内存泄露测试，发现跑两个小时的固定场景，很容易出现下面这段trace

Begin trace
size 4111590 count:49857 parentcnt:51505
0x00008c0c debug_malloc bionic/libc/malloc_debug/malloc_debug.cpp:310 /system/lib64/libc_malloc_debug.so
0x00083070 operator new(unsigned long) external/libcxxabi/src/cxa_new_delete.cpp:44 (discriminator 1) /system/lib64/libc++.so 
0x0000ac4c LogBufferElement system/core/logd/LogBufferElement.cpp:47 /system/bin/logd 
0x00007498 LogBuffer::log(log_id, log_time, unsigned int, int, int, char const*, unsigned short) system/core/logd/LogBuffer.cpp:209 (discriminator 3) /system/bin/logd 
0x00006168 LogListener::onDataAvailable(SocketClient*) system/core/logd/LogListener.cpp:112 (discriminator 1) /system/bin/logd 
0x00004200 SocketListener::runListener() system/core/libsysutils/src/SocketListener.cpp:245 /system/lib64/libsysutils.so 
0x00003cf8 SocketListener::threadStart(void*) system/core/libsysutils/src/SocketListener.cpp:147 /system/lib64/libsysutils.so 
0x00075c54 __pthread_start(void*) bionic/libc/bionic/pthread_create.cpp:198 (discriminator 1) /system/lib64/libc.so 
0x0001e0fc __start_thread bionic/libc/bionic/clone.cpp:41 (discriminator 1) /system/lib64/libc.so 
0xfffffffffffffffc ??? ??? ??? 
End Trace
Begin trace
size 2920176 count:52146 parentcnt:53794
0x00008c0c debug_malloc bionic/libc/malloc_debug/malloc_debug.cpp:310 /system/lib64/libc_malloc_debug.so
0x00083070 operator new(unsigned long) external/libcxxabi/src/cxa_new_delete.cpp:44 (discriminator 1) /system/lib64/libc++.so 
0x00007474 LogBuffer::log(log_id, log_time, unsigned int, int, int, char const*, unsigned short) system/core/logd/LogBuffer.cpp:209 (discriminator 1) /system/bin/logd 
0x00006168 LogListener::onDataAvailable(SocketClient*) system/core/logd/LogListener.cpp:112 (discriminator 1) /system/bin/logd 
0x00004200 SocketListener::runListener() system/core/libsysutils/src/SocketListener.cpp:245 /system/lib64/libsysutils.so 
0x00003cf8 SocketListener::threadStart(void*) system/core/libsysutils/src/SocketListener.cpp:147 /system/lib64/libsysutils.so 
0x00075c54 __pthread_start(void*) bionic/libc/bionic/pthread_create.cpp:198 (discriminator 1) /system/lib64/libc.so 
0x0001e0fc __start_thread bionic/libc/bionic/clone.cpp:41 (discriminator 1) /system/lib64/libc.so 
0xfffffffffffffffc ??? ??? ??? 
End Trace
Begin trace
size 1249464 count:52061 parentcnt:53709
0x00008c0c debug_malloc bionic/libc/malloc_debug/malloc_debug.cpp:310 /system/lib64/libc_malloc_debug.so
0x00083070 operator new(unsigned long) external/libcxxabi/src/cxa_new_delete.cpp:44 (discriminator 1) /system/lib64/libc++.so 
0x000075f4 std::_1::_allocate(unsigned long) external/libcxx/include/new:168 /system/bin/logd 
0x00006168 LogListener::onDataAvailable(SocketClient*) system/core/logd/LogListener.cpp:112 (discriminator 1) /system/bin/logd 
0x00004200 SocketListener::runListener() system/core/libsysutils/src/SocketListener.cpp:245 /system/lib64/libsysutils.so 
0x00003cf8 SocketListener::threadStart(void*) system/core/libsysutils/src/SocketListener.cpp:147 /system/lib64/libsysutils.so 
0x00075c54 __pthread_start(void*) bionic/libc/bionic/pthread_create.cpp:198 (discriminator 1) /system/lib64/libc.so 
0x0001e0fc __start_thread bionic/libc/bionic/clone.cpp:41 (discriminator 1) /system/lib64/libc.so 
0xfffffffffffffffc ??? ??? ??? 
End Trace
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37

从上面的backtrace看，主要描述的是Logd如何处理客户端的log过程，以Java层的Log.d（smg）举例，主要执行流程：

Log.java d()​->Log.java println_native()->android_util_Log.cpp android_util_Log_println_native()->logger_write.c __android_log_buf_write​()->logger_write.c write_to_log() -> logger_write.c __write_to_log_init​() -> logger_write.c​ __write_to_log_initialize()​ -> logger_write.c __write_to_log_daemon​() 从逻辑看，就是往socket不断的写log，写给谁呢？在__write_to_log_initialize()​ ​方法中会调用 config_write.c __android_log_config_write​(),初始化logdLoggerWrite​，从logd_write.c中可以看出，logdLoggerWrite​是个socket，
strcpy(un.sun_path, “/dev/socket/logdw”);
往socket里面写了，谁会去处理呢？
logd进程启动的源码中可知，LogListener​ listens on /dev/socket/logdw for client​，可见下面源码
// LogListener listens on /dev/socket/logdw for client
// initiated log messages. New log entries are added to LogBuffer
// and LogReader is notified to send updates to connected clients.

LogListener *swl = new LogListener(logBuf, reader);
LogListener是SocketListener类型，初始化完成后会runListener​，当socket中有信息时，执行流：
SocketListener::runListener​() -> LogListener::onDataAvailable​() -> LogBuffer::log()
在LogBuffer::log()方法中，new LogBufferElement​，（这部分就跟上面的backtrace对应上了），并将其添加至LogBufferElementCollection​中，在LogBufferElement​构造方法中，会根据msg信息new char[]，将信息存在LogBuffer～
存起来的Log，什么时候会消费呢？
在代码中，调用LogBuffer::erase()会释放，从单词意思也能猜到，这个方法什么时候调用呢？
LogBuffer::maybePrune() -> LogBuffer::prune() -> LogBuffer::erase()​
而LogBuffer::maybePrune()​调用，只有在 LogBuffer::log()​，也就是说，上面的Java层调用Log.d()就可以触发这个逻辑，触发的条件在LogBuffer::maybePrune()​方法中

// Prune at most 10% of the log entries or maxPrune, whichever is less.
//
// mLogElementsLock must be held when this function is called.
void LogBuffer::maybePrune(log_id_t id) {
    size_t sizes = stats.sizes(id);
    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) {
            minElements = minPrune;
        }
        unsigned long pruneRows = elements * sizeOver / sizes;
        if (pruneRows < minElements) {
            pruneRows = minElements;
        }
        if (pruneRows > maxPrune) {
            pruneRows = maxPrune;
        }
        prune(id, pruneRows);
    }
}
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23

从代码可知，当对应的LogBuffer size超过了maxSize​，进行裁剪log，释放一部分LogBufferElement​～其实到这可以看出，logd是log池，只有池子满了，才会主动释放一部分内存
系统中有多少LogBuffer呢？最大值又是多少呢？
LogBuffer::init()方法中，会对LogBuffer初始化，从初始化的过程看，有7个LogBuffer，分别是：

​static const char *LOG_NAME[LOG_ID_MAX] = {
    [LOG_ID_MAIN] = "main",
    [LOG_ID_RADIO] = "radio",
    [LOG_ID_EVENTS] = "events",
    [LOG_ID_SYSTEM] = "system",
    [LOG_ID_CRASH] = "crash",
    [LOG_ID_SECURITY] = "security",
    [LOG_ID_KERNEL] = "kernel",
};
1
2
3
4
5
6
7
8
9

根据系统属性设置maxsize，从C1上看下跟logd相关的属性：
设置逻辑贴代码比较多，直接看一个说明文档的注释：
persist.logd.size number ro Global default size of the buffer for
all log ids at initial startup, at
runtime use: logcat -b all -G
ro.logd.size number svelte default for persist.logd.size. Larger
platform default sizes than 256KB are
known to not scale well under log spam
pressure. Address the spam first,
resist increasing the log buffer.
persist.logd.size. number ro Size of the buffer for log
ro.logd.size. number svelte default for persist.logd.size.
初始化过程执行完，每个LogBuffer的最大值如下：
main:2M
radio:4M
events:2M
system:4M
crash:1M
security:2M
kernel:2M

如果每个LogBuffer都填满，所有LogBuffer内存占用近20MB，再加上分配内存的中间开销，占用内存可能会非常大～

再来看下Mate9的logd相关设置：
Mate9没有设置LogBuffer的大小，如果不设置，LogBuffer大小使用默认值，即256KB
如果将C1的logd相关属性和Mate9保持一致后，测试结果如下：
内存最大值(KB) 内存最小值(KB) 内存平均值(KB)
C1 修改版 7894 4877 6610
Mate9 2804 2565 2719
​修改LogBuffer后的效果比较明显，内存值会下降很多，但同样会带来log丢失的问题。也就是 LogBuffer::prune()方法带来的问题
裁剪的主要逻辑：先删黑名单和Log数最多的UID对应的Log，而且先删oldest的log，如果仍不满足，再根据白名单的配置，白名单的不删除，其他都删除，直到满足条件

LogBuffer最大值意味着存放log信息的多少，比如我们生成bugreport时，会dumpstate，取system log，event log，radio log等信息，
LogBuffer比较小的话，取出来的信息会相对少一些，可能会对开发解问题造成影响。
也就说，改动前会看到2个小时前的event log，system log，改动配置后可能就会看到近20分钟的event log，system log

看一下实际情况，跑了几个小时的场景后，一台C1是16号开发版包，logd内存：46614K​，一个C1是修改logd后的开发版包，logd内存6794K，
抓取两个C1的bugreport
11-16开发版第一个bugreport
system log起始时间 event log起始时间 radio起始时间
15:00-17:52 15:20-17:52 10:27-17:5​2
11-16开发版第一个bugreport
system log起始时间 event log起始时间 radio起始时间
15:00-18:07 15:21-18:07 10:27-18:07
修改logd属性的11-16号开发版第一个bugreport
system log起始时间 event log起始时间 radio起始时间
17:26-17:53 17:33-17:53 15:48-17:53
修改logd属性的11-16号开发版第二个bugreport
system log起始时间 event log起始时间 radio起始时间
17:26-18:07 17:41-18:07 16:03-18：07
从数据可以看出，未做修改的版本system log会记录4个小时左右，event log会记录3个半小时左右，radio会记录7个半小时，而修改logd属性的版本system log会记录30分钟左右，
event log会记录20分钟左右，radio会记录2个小时，整体比未做修改的版本时间要短，符合预期

开发版上log比较多，如果是稳定版，由于log少情况会好一些～从数据看，也是可以接受

因此，建议将RAM较小的外发版机型，将LogBuffer size调小，或者直接调至256KB，将内存影响降至最低～