Android logcat log丢失

一、log丢失对应方法

1、禁用黑白名单机制

此方法适用log写入频率特别快，logd勉强能够处理，但是在logd 清除旧log的时候处理不及时的情景(通俗讲就是整个系统log刷太快了)。如下指令，重启生效：

setprop persist.logd.filter disable
logcat -p   //小写p

系统默认是default
不想重启，使用：

setprop persist.logd.filter disable
logcat -p
logcat -P ""   //大写P

效果略差

2、利用黑白名单机制

此方法适用log写入频率不是很快，但是还有很多log丢失，log信息中有输出”chatty“相关的信息，说明log被logd特殊对待了，也就是针对性删除。所以此次旧需要添加黑白名单来解决。

设置白名单，log就不会被特殊对待了：

logcat -P uid/pid

设置黑名单，对那些疯狂输出的log进行限制：

logcat -P ~uid/pid

查看黑白名单：

logcat -p

相关的详细解释可以看博客：

链接: android log丢失（一）使用logd丢失log原理.

3、只输出4个以内的log TAG

如果调试只需要查看几个log TAG的话，用这种方式是最简单的。

将所有log输出都禁止(除了下面设置过persist.log.tag.MYTAG V的)，S代表最高等级log，这个系统属性的意思就是只打印S以及比他等级更高的log。

setprop persist.log.tag S

将我自己的log TAG(MYTAG)输出打开，这个系统属性的意思就是MYTAG这个TAG的log，只输出V等级及以上的。V是最小等级。所以MYTAG会畅通无阻的打印。

setprop persist.log.tag.MYTAG V

不过这种系统属性设置的TAG个数有上限，最多4个或者5个。设置完后，logd输出的log就只有上面设置过的这个MYTAG了。

4、通过log等级限制数量

log打印等级有V,D,I,W,E,F,A,P,S依次递增，通过系统属性persist.log.tag可以指定特定等级及以上的log可以打印，如果只需要打印Error以上等级就设置：

setprop persist.log.tag E

如果是Warn等级及以上就设置：

setprop persist.log.tag W

那么特定等级以下的log就不会输出，可以缓和下logd处理压力，降低log丢失的概率。

5、增大LogBuffer缓冲区大小

此方法适用只需要短时间获取log，log总量不多的情况。
设置log buffer缓冲区大小为64M，这个大小默认在2M以内，自己可以更改，最大为256M。第一种是只设置main缓冲区的大小，第二种是把所有缓冲区都设置为64M，如果知道自己打印的是哪个缓冲区，那就单独设，不知道就用第二种把。系统属性设置是在重启后生效，logcat 设置可以立即生效但是重启无效，所以推荐一起打。

setproppersist.logd.size.main 64M
logcat -b main -G 64M

或者

setproppersist.logd.size 64M
logcat -G 64M

设置完后，尽量在缓冲区写满前打印log，可以保证丢失率降低，可以通过以下方式查看这个缓冲区写满了没，会显示常用的几个缓冲区大小及消耗情况：

logcat -g

清除缓冲区数据

logcat -c

6、选择合适的输出源

此方式适合终端需要打印大量log的情况。
我在第三章会讨论到输出终端对log丢失的影响，如果发现cat一个文件，终端输出很慢，那么就要考虑换一个输出方式了。例如：在串口cat 2M大小的文件时，耗时几十秒，改用adb 输出2秒就输出到终端了。那么这个时候选择adb输出会好点。如果终端输出速度跟不上buffer清除的速度，那么当前logcat 进程会被中断，输出错误信息：read: unexpected EOF! 具体第三章有讲。

7、从log输入源头限制

如果觉得每次都要设置系统属性什么的很麻烦，那么可以将log分组管理，当我们调查自己的模块的问题的时候就只打开我们组相关的log，关闭其他log。
在第二章logd框架图中可以看到，log写入到缓冲区logbuffer之前会先经过logdw，socket之前还有logger_write控制，该函数在logger_write.c中实现，logger_write中可以针对各种log进行限制，设计了一套log分组管理，通过logcat 指令打开或者关闭特定组和成员。至于根据什么分组，可以是uid、pid、或者其他自定义的id。

8、适当增大logdw socket缓冲区大小

如果log峰值写入频率特别快，logd勉强能够处理，但是在logd 清除旧log的时候处理不及时，那么稍微变大logdw socket的缓冲区大小或许可以cover住。但是问题是：目前还不知道能不能设、怎么设😅。

9、更改log buffer缓冲机制

之后我想将buffer缓冲区（双向链表）改成循环链表，然后链表节点的内存提前分配，每次更新用memset节点log信息，再赋值。每个结点（log）分配512byte，如果小了就释放后再重新申请，如果大了就改会512，估计可以减少2/3的内存释放和申请耗时。尽量保证log再写入缓冲区的速度够快。如果写入速度追上logReader，那么直接重置logReader读取位置，不能因为一个logcat进程读取慢了导致所有客户端的log丢失。

10、客户端保存

由于实走的时候log系统有些log是不能全开的，所以难免有时候出问题了但是log不全的情况。这个时候我们一般都是复现来解决问题，但是这样成本特别大。这个时候就经常抱怨log写太少写不全，写多了又影响性能。所以我想是否可以在我们自己的进程里面，提供一个log缓存区，暂时保留一些debug等级及以下的log，这些缓存的log不写入log系统。等到突然有error出现的时候，就把本地缓存的log都写入log系统，这样就能保证在error log出现的时候，log系统也能有详细的debug log输出。

11、logcat 详细操作

详细指令操作可以看我博客：
链接: Android logcat log输出控制.
读者是同事的话可以看这篇，更详细:
Log专题.

二、log丢失原理

传送门: Android log详解.
图片来自与我另一篇博客，收集的五篇博客，以下整个框架都全面的讲解，记得给点赞。

2.1、logd框架

2.2、logbuffer

三、log丢失调查

背景

从车机串口终端打印logcat 输出log时候，发现丢失大量log，/system/bin/logcat后台进程写的log文件也有log丢失。

先给出结论

串口输出log丢失一部分原因是串口读取速度过慢，更换成adb会好点；
终端和写文件丢log，是因为写log速度过快，导致logd做旧数据清除prune的时候来不及处理logdw socket缓冲的log。在buffer写满前log写入速度有上限，在buffer满时，log写入速度上限降低。如果buffer写满前也丢log，那么就只能从写log的源头限制log的输入，如果是在buffer写满后丢log严重，就可以禁用黑白名单，第一章有介绍。

推论

猜测：从串口输出log发现有延时，可能会导致读log速度跟不上写log的速度，在logbuffer达到上限进行清除的时候，猜测丢log的原因就是还没读到log就被清除了。

测试：APP高频写log，串口logcat 打印log。
串口输出log一段时间后，当前logcat 进程被杀死，打印出错误信息 read: unexpected EOF!

原因：在终端打印logcat，如果读取logdr太慢会影响log buffer清除老log，所以kill 该logcat 进程。

测试：关闭其他log输出，打开APP高频写log，过一段时间，停止APP 写log，查看cpu。
top -m查看cpu，发现APP打印log的时候，logd 18%，/system/bin/logcat(后台写文件的进程)25%和APP 25% CPU消耗，当APP 停止写log，logd cpu立马下降到1%以下，而logcat 后台打印到文件的进程的
CPU持续了10几秒，这说明，写文件的logcat进程读取log的速度跟不上logdw写log到缓冲区的速度，这样也可能会导致log读取还没完，logd就刷新log。同时/system/bin/logcat 进程如果被kill还会自动重启，重启后接着读log写文件。

结论：综上，log丢失跟log读取速度有关系。

猜测：读log慢可能是logdr本身读取log buffer数据慢，也可能是logcat 读取logdr再输出到终端慢了。

测试：如果是输出到终端慢，那么要排除是硬件问题，
通过cat 一个文件发现，终端输出很慢，所以定位问题是串口通信问题，串口通信双方协议需要同步，速度受限于波特率，于是，用adb shell输出log来调查，排除硬件带来的问题，通过adb输出，adb输出log速度很快，停止写log，就马上停止输出log了，即使输出速度够了，但还是会有丢log。

猜测：是logcat读logdr的log丢失还是logd从logdw获取数据写入logbuffer过程中丢失log？
测试：打开adb shell，输入 logcat -s MYTAG，打开串口，输入setprop persist.log.tag V打开所有log输出，
logcat -c 清除缓冲区，点击APP打印log，一段时间后再次点击APP停止打印log，同时串口输入setprop persist.log.tag S禁止所有log输出，
串口输入logcat -s MYTAG，此时输出的log是logd保存在logd buffer缓冲区的log，对比adb此时打印出来的log，adb的log代码logcat 实时读取的log，对比两者的log发现无差别，读取log和写入log buffer缓冲区的log完全一致。

结论：adb logcat输出log的时候，不是logcat读logdr的log出问题导致log丢失，而是logd从logdw获取数据写入logbuffer出问题导致的。

猜测：1、logd从logdw获取数据写入logbuffer 并且buffer还没满就存在丢log；2、buffer满了，清除旧log的时候丢log。

测试：通过logcat -G 50M设置了log buffer缓冲区，logcat -c清除之前的log数据，输入setprop persist.log.tag V打开所有log输出，
在buffer还没满之前点击APP每隔一毫秒写10条log，通过adb ：logcat -s MYTAG观察输出的log。还没触发清除机制log不丢失：发现log基本不丢了。

结论：清除log的时候（prune函数），log丢失问题严重。

猜测：清除机制是从老数据里面清除吗？是的话为什么新数据会被清除？

测试：写log写满log buffer缓冲区，触发清除机制，串口输入setprop persist.log.tag S，禁用所有其他log，只输出自己TAG的log： setprop persist.log.tag.MYTAG V。重新打log，持续一段时间，通过adb打印log，可以看的log基本不漏。

猜测：多进程一起写log并触发清除机制log丢失：可能是因为在清除log的时候，多进程写log会导致log写失败。也可能是因为关闭其他log导致写log数量变少。

测试：加快APP写log速度，adb logcat 打印log，发现log丢失挺严重。猜测是不是因为log写的多的pid会被优先删除，尝试加入黑白名单没有什么改善。

结论

写log速度过快，导致logd做旧数据清除prune的时候来不及处理logdw socket缓冲的log。在buffer写满前log写入速度有上限，在buffer满时，log写入速度上限降低。如果buffer写满前也丢log，那么就只能从写log的源头限制log的输入，如果是在buffer写满后丢log严重，就可以禁用黑白名单，第一章有介绍。

测试代码

APP:

public void logOutput(View v
iew) {
        logTest = !logTest;
        Thread mthread = new Thread(new Runnable() {
            @Override
            public  void run(){
                int i = 0;
                while (logTest) {
                    try {
                        Thread.sleep(1);
                    } catch (InterruptedException e) {
                        e.printStackTrace();
                    }
                    Log.e(TAG, " ===================== log test ======================");
                    Log.e(TAG, " log test "+ (++i));
                    Log.e(TAG, " log test "+ (++i));
                    Log.e(TAG, " log test "+ (++i));
                    Log.e(TAG, " log test "+ (++i));
                    Log.e(TAG, " log test "+ (++i));
                    Log.e(TAG, " log test "+ (++i));
                    Log.e(TAG, " log test "+ (++i));
                    Log.e(TAG, " log test "+ (++i));
                    Log.e(TAG, " log test "+ (++i));
                    Log.e(TAG, " log test "+ (++i));
                    if (i > 9999)
                        i = 0;
                }
            }
        });mthread.start();
    }

LogBuffer.cpp：

//================添加的代码================
static void testlog(const char* Fmt, ...)
{
    va_list ap;
    char TempStr[512];
    va_start(ap,Fmt);
    vsprintf(TempStr,Fmt,ap);
    va_end(ap);
    char TempStrOut[512];
    snprintf(TempStrOut, 512, "[%d] %s\n", getpid(), TempStr);

    // write to file
    FILE * fp;
    fp=fopen("/extdata/testlog.txt","a+");
    if (NULL != fp)
    {
        fwrite(TempStrOut,strlen(TempStrOut),1,fp);
        fclose(fp);
    }
}
static int pruneCount = 0;
static clock_t prunetime = 0;
static int logCount = 0;
static clock_t allpruneresume = 0;
static clock_t logwritetime = 0;
static clock_t logstart = 0;
//==========================================


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 ((log_id >= LOG_ID_MAX) || (log_id < 0)) {
        return -EINVAL;
    }
    //================添加的代码================
    clock_t logwritestart = clock();
    if (logCount == 0) {
        logstart = clock();
    }
    //=======================================
    
    LogBufferElement *elem = new LogBufferElement(log_id, realtime,
                                                  uid, pid, tid, msg, len);
    if (log_id != LOG_ID_SECURITY) {
        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)) {
            // Log traffic received to total
            pthread_mutex_lock(&mLogElementsLock);
            stats.add(elem);
            stats.subtract(elem);
            pthread_mutex_unlock(&mLogElementsLock);
            delete elem;
            return -EACCES;
        }
    }

    pthread_mutex_lock(&mLogElementsLock);

    // Insert elements in time sorted order if possible
    //  NB: if end is region locked, place element at end of list
    LogBufferElementCollection::iterator it = mLogElements.end();
    LogBufferElementCollection::iterator last = it;
    while (last != mLogElements.begin()) {
        --it;
        if ((*it)->getRealTime() <= realtime) {
            break;
        }
        last = it;
    }

    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 times = mTimes.begin();
        while(times != mTimes.end()) {
            LogTimeEntry *entry = (*times);
            if (entry->owned_Locked()) {
                if (!entry->mNonBlock) {
                    end_always = true;
                    break;
                }
                if (!end_set || (end <= entry->mEnd)) {
                    end = entry->mEnd;
                    end_set = true;
                }
            }
            times++;
        }

        if (end_always
                || (end_set && (end >= (*last)->getSequence()))) {
            mLogElements.push_back(elem);
        } else {
            mLogElements.insert(last,elem);
        }

        LogTimeEntry::unlock();
    }

    stats.add(elem);
    
	//================改动代码位置================
    clock_t prunestart = clock();
    maybePrune(log_id);
    clock_t pruneend = clock();

    clock_t logwriteend = pruneend;
    logwritetime += (logwriteend - logwritestart);
    allpruneresume += (pruneend - prunestart);
    pthread_mutex_unlock(&mLogElementsLock);
    logCount++;
    if (logCount > 999) {
        clock_t logend = clock();
        testlog("all resume time : %ld, allpruneresume resume : %ld, logwritetime : %ld", (logend - logstart), allpruneresume, logwritetime);
        logCount = 0;
        allpruneresume = 0;
        logwritetime = 0;
    }
    //========================================
    return len;
}

// 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;
        }
        //================改动代码位置================
        clock_t prunebegin = clock();
        prune(id, pruneRows);
        clock_t prunestop = clock();
        if (pruneCount == 0) {
            prunetime = 0;
        }
        prunetime += (prunestop - prunebegin);
        pruneCount++;
        if (pruneCount > 99) {
            testlog("prune resume time : %ld", prunetime);
            pruneCount = 0;
        }
        //=========================================
    }
}

测试log及结论

背景

[176] prune resume time :打印是log清除函数prune执行100次的耗时，单位是微秒。
all resume time ：代表100条log写入log buffer缓冲区的总时间，包括中间没log输入的时间。
allpruneresume resume : 代表函数maybePrune执行1000次耗时，可能真正执行prune次数才几次。
logwritetime：已经从logdw读出来的log写入到logbuffer耗费的时间，是1000条累计的时间，包含中途prune。

1、将黑白名单打开

android:/extdata # tail testlog.txt
[176] all resume time : 543852, allpruneresume resume : 426074, logwritetime : 471033
[176] all resume time : 594086, allpruneresume resume : 475526, logwritetime : 512641
[176] all resume time : 150276, allpruneresume resume : 57077, logwritetime : 88331
[176] all resume time : 233904, allpruneresume resume : 121620, logwritetime : 166092
[176] all resume time : 198230, allpruneresume resume : 97918, logwritetime : 129028
[176] all resume time : 144251, allpruneresume resume : 60325, logwritetime : 90435
[176] prune resume time : 8886358
[176] all resume time : 436879, allpruneresume resume : 327605, logwritetime : 366816
[176] all resume time : 539390, allpruneresume resume : 432241, logwritetime : 474123
[176] all resume time : 444469, allpruneresume resume : 344111, logwritetime : 375882

结论：
"prune resume time : 8886358" 可以看出
prune 100 次8,886,358微妙左右，也就是大约8秒，一次prune大约80毫秒。
写log 1000次 100毫秒到1000毫秒不等，写log的函数log被调用1000次总时间：200毫秒到500毫秒不等，不稳定。
以上这时间都是包含prune耗时，结合下面这个case可以看出是prune耗时为主导。
打开黑名白单机制，会导致prune函数耗时成倍增加，如果log写入频率太高，建议关掉该功能，关闭方法在第一章中有讲。

2、打开黑白名单机制，在log buffer还没写满之前的log

android:/extdata # tail testlog.txt
[176] all resume time : 88435, allpruneresume resume : 12808, logwritetime : 33576
[176] all resume time : 91954, allpruneresume resume : 15697, logwritetime : 45291
[176] all resume time : 71216, allpruneresume resume : 8611, logwritetime : 26949
[176] all resume time : 81364, allpruneresume resume : 10433, logwritetime : 35252
[176] all resume time : 90761, allpruneresume resume : 20137, logwritetime : 44694
[176] all resume time : 83991, allpruneresume resume : 11977, logwritetime : 40034
[176] all resume time : 88383, allpruneresume resume : 16353, logwritetime : 45590
[176] all resume time : 87763, allpruneresume resume : 16809, logwritetime : 43496
[176] all resume time : 88888, allpruneresume resume : 15471, logwritetime : 43280
[176] all resume time : 82900, allpruneresume resume : 12511, logwritetime : 33443

结论：
黑白名单主要影响数据清除prune的性能，buffer写满触发的prune机制对log写入的速度机会没影响，
只会影响写入的log是否完全，prune期间会存在log丢失，因为读取logdw的通信方式是socket dgram，该socket在logd.rc中创建。

3、禁止黑白名单

180] all resume time : 101859, allpruneresume resume : 11024, logwritetime : 33945
[180] all resume time : 112175, allpruneresume resume : 15201, logwritetime : 40457
[180] all resume time : 92527, allpruneresume resume : 12008, logwritetime : 37288
[180] all resume time : 97057, allpruneresume resume : 10153, logwritetime : 31556
[180] all resume time : 106217, allpruneresume resume : 15655, logwritetime : 40745
[180] prune resume time : 62075
[180] all resume time : 104501, allpruneresume resume : 12354, logwritetime : 37464
[180] all resume time : 108981, allpruneresume resume : 13220, logwritetime : 38710
[180] all resume time : 109788, allpruneresume resume : 14088, logwritetime : 39484
[180] all resume time : 107229, allpruneresume resume : 11189, logwritetime : 35685

结论：
prune(log清除) 100 次60毫秒左右
写log到log buffer缓冲区1000 次 50毫秒左右
写log 1000次总时间：100毫秒左右，耗时比较稳定

4、提高写log速度

发现log buffer没写满前也会丢log，猜测是log写太快了吗？
将APP写log频率调到最大，测试：

[176] all resume time : 91661, allpruneresume resume : 16719, logwritetime : 39946
[176] all resume time : 90255, allpruneresume resume : 15178, logwritetime : 37439
[176] all resume time : 110888, allpruneresume resume : 14666, logwritetime : 47220
[176] prune resume time : 73657
[176] all resume time : 88207, allpruneresume resume : 12527, logwritetime : 34249
[176] all resume time : 103181, allpruneresume resume : 13321, logwritetime : 45082
[176] all resume time : 108988, allpruneresume resume : 18327, logwritetime : 48805
[176] all resume time : 98747, allpruneresume resume : 14599, logwritetime : 47853
[176] all resume time : 84013, allpruneresume resume : 11434, logwritetime : 34716
[176] all resume time : 84054, allpruneresume resume : 9264, logwritetime : 32327

结论：	
测试结果跟之前格一毫秒发送10条log差不多，说明已经到极限了，后台还有其他log也在打印。
all resume time可以看出：
1000条log，写入总耗时为100毫秒左右，一条log0.1毫秒，所以1秒能写一万条log，大概一秒写1M，如果打开黑名单机制，性能降低5倍左右。

总结

1、关闭黑名单时，1000条log，写入总耗时为100毫秒左右，一条log0.1毫秒，所以1秒能写一万条log，一条log大约0.1K，大概一秒写1M，做一次log清除prune会阻塞0.6毫秒，大概是写6条log的时间，大概是6*0.1K = 0.6K，socket udp接收缓冲区通过"cat /proc/sys/net/core/rmem_default"查看:

cat /proc/sys/net/core/rmem_default
163840

远大于0.6K，所以禁用黑名单，在读取速度快于写入速度情况下，prune对log影响不大。

2、打开黑白名单机制时，log清除函数prune耗时成倍增加，大约一次prune需要阻塞80毫秒，期间socket接收缓冲区更新大约800条log，大约80K，在socket缓冲区可以接收范围，不过通过上面测试log发现prune耗时很不稳定，而且如果原本读取速度就跟不上写入速度的话，80毫秒prune会加剧log丢失。所以在log写入频率较高时，建议关闭黑白名单，setprop persist.logd.filter disable。

四、logd性能观测方法

4.1、代码方式

由于本身就是是在log系统中调试，通过logd打印调查信息不太合适，所以就通过写文件的形式输出调试信息，同时为了保证对logd性能影响最小，尽量累计输出。

static void testlog(const char* Fmt, ...)
{
    va_list ap;
    char TempStr[512];
    va_start(ap,Fmt);
    vsprintf(TempStr,Fmt,ap);
    va_end(ap);
    char TempStrOut[512];
    snprintf(TempStrOut, 512, "[%d] %s\n", getpid(), TempStr);

    // write to file
    FILE * fp;
    fp=fopen("/extdata/testlog.txt","a+");
    if (NULL != fp)
    {
        fwrite(TempStrOut,strlen(TempStrOut),1,fp);
        fclose(fp);
    }
}

4.2、现有工具

1、logdw写入速度：

logcat -G 40M 设置logbuffer大小，logcat -c 清除缓冲区log，打开所有log输出，点击APP最快速度输出log。隔一秒在终端输入logcat -g查看main缓冲区log的消耗大小，可以看到log每秒写入log buffer缓冲区的数量，在缓冲区达到最大值的90%前，应该是现有log写入的最大速度了。

2、后台logcat 写log文件速度：

ps |grep logcat 可以看到一个/system/bin/logcat 进程在后台运行，该进程就是init.rc中启动的后台logcat 进程，负责将log写入磁盘文件。setprop persist.log.tag S关闭所有log输出，删除所有log文件，点击APP最大速度写log，开启log输出setprop persist.log.tag V，看log文件生成速度可以估计log文件写入的最大速度。

3、adb 或者串口读取log速度：

logcat -c清除所有log，logcat -G 64M 设置log buffer缓冲区大小，终端输入logcat -s MYTAG，点击APP最大速度写log，保持一段时间后点击APP停止写log，查看终端log输出情况，如果终端log输出马上停止，那么说logdr读取log buffer速度能跟得上 logd 读取logdw 速度也就是写log到缓冲区的速度。