Android 日志打印频率过高排查的一些技巧

最近项目快到 sop 阶段了，看到最近的一个新的任务，提示应用打印频率每秒超过 100 行/秒，需要优化一下。

那这样看起来需要删减一点日志，是不是先要找一下我们的应用打印了多少。

当然如果项目是自己维护的，那肯定是知道哪个地方调用高，打印的日志，那如果需要处理多个模块，不是自己的，那只能分析日志了不是。

所以我们应该有几个步骤要走：

找到应用的对应进程。
过滤出对应进程的所有日志。
统计每秒的日志打印数是否满足。
针对性的考虑是否需要删除或者保留。

一、找到应用的对应进程。

拿到所有的日志文件，考虑到应用有可能有异常的情况会重启，我们在通过应用名过滤包名的时候需要看下是否在所有的时候对应 pid 都是一个。

可以用命令行，先用 grep 过滤关键包名，再用含有 pid 的输出作为第二次过滤。

因为我们系统会隔段时间 dumpCpu, 这里会打印出应用和 pid 信息，这里就用的 pid ，如果不是的话，可以先不第二次过滤，看看搜索结果中有没有含 pid 的关键字再进行过滤。

因为一般开发都是使用 Linux 或者 Mac ，这里命令应该是一样的，如果是 Windows 的话可以转成对应的命令。

在日志目录中开启命令行。

# package 和 pid 需要换成对应的关键字
grep -rn "<package>" | grep <pid>

-r 代表遍历文件

-n 代表显示行数

| 为管道，代表将搜索结果转给下一个命令使用

比如我处理的第一个应用是行车记录仪，一般名字是 dvr。

那我就可以用

grep -rn "com.xxx.dvr" | grep pid

这样从结果中大致看看是否是相同 pid ，如果是那该日志期间是没有重启过，如果是多个的话，说明应用可能有点不稳定呀，可以选取时间长的几个 pid 进行处理。

二、过滤出对应进程的所有日志。

找到了 pid ，那我们过滤下 pid 日志导出，这里需要看每个系统中关于日志打印的格式，我们是这样的。

09-30 15:12:55.895790  3142  3142 E DvrApplication: [ (DvrApplication.java:282)#onVolumeStateChanged ]vol: VolumeInfo{public:8,17}:

所以过滤的话，就用 grep 过滤出 3142 就行。

因为我们日志会打印的秒后面位数比较多，所以可能出现秒也有 3142 的情况，grep 时可以在前后带一个空格。

grep -rn " 3142 " > filterLogs.lg

> 为重定向符号，这里的意思就是，把过滤出的内容原本应该在命令行打印出的信息导出到一个新的文件。

filterLogs.lg 日志文件名，自己可以取一个简单的。

这样我们就拿到了一个过滤 pid 后的文件内容，但是当我打开的时候发现，grep 之后的内容有点问题。

第一是有文件名，这样后续不太方便统计时间戳。
第二是时间， -rn 是乱序遍历的。

那首先是解决第一个问题，这个简单，搜了一下 grep 的用法，使用 -h 可以隐藏文件名，Easy。

第二个问题，我发现日志文件是有序的，但是遍历了不行，这里我开始先想的是不是要排序一下，但是问了下 chagpt 怎么顺序遍历，让我 ls 给 grep 过滤，我一试，发现真是个天才。ls 默认升序排列。

改良版的命令。

grep -h " 3142 " $(ls) > filterLogs.lg

-h 代表隐藏文件名

$(ls) 代表执行 ls 命令，这里是作为了输出文件名给 ls 使用。可以理解为 shell 中的函数执行格式。

可有的那个有朋友会问了，那这里是一个 pid ，如果是多个怎么办，你说有没有一种可能 grep 支持正则，这里就作为小作业啦。

三、统计每秒的日志打印数是否满足。

既然拿到了过滤好的日志，那是不是可以看看哪些时候在一秒内打印频率比较高。

当然有些是肉眼比较好看出来的，有些就不太好看，那怎么能够统一下这个数据呢，你应该想到了，可以问问 chatGPT，当然我已经帮你问了。

awk '{print substr($0, 1, 18)}' filterLogs.log | sort | uniq -c > nums.log

awk 为文字处理工具。

substr($0, 1, 18) 为处理当前行，提取前 18 个字符

sort 就是对结果排序

uniq -c 统计相同的时间，然后 +1.

虽然这个答案很完美，但是当我把一行日志给了 chatGPT 时，还给我说前 18 个字符，手动改了一下只需要前 14 个字符就可以了。

当然每家的日志格式不一样，这里就需要单独处理一下，拿到的结果就像这样，很完美。

      4 09-30 15:14:53.4 09-30 15:15:03.4 09-30 15:15:13.3 09-30 15:15:19.4 09-30 15:15:23.37 09-30 15:15:32.31 09-30 15:15:33.4 09-30 15:15:43.1 09-30 15:15:47.1 09-30 15:15:48.3 09-30 15:15:49.4 09-30 15:15:53.

这里一下就清晰看到有没有问题，如果不符合，你也有依据给该任务关一个无效。

如果有问题，可以通过对应的时间很快定位到需要处理的时间，排查该时间段是因为什么原因在一秒内打印了很多日志。

当你用了几次脚本后发现好用是好用，但是如果日志少，一两眼就能看到哪一秒超过100。

但是如果日志很长，随眼一晃，发现没有，但是又不放心，搜索吧，不好搜 > 100 这个条件，自己检查，那眼睛都要看瞎，所以还是需要加一个标记。

awk '{print substr($0, 1, 14)}' <logPath> | sort | uniq -c | awk '{if ($1 > 100) {print $0, " <-- more than 100"} else {print $0}}' > nums.log

前面部分是一样的，logPath 换成自己的日志路径。

后面部分代表对比对一列是否大于 100 ，大于在最后输出一个标记，这样结果输出我们可以直接搜索这个关键字。

四、针对性的考虑是否需要删除或者保留。

到了这里接下来就是排查自己的代码，哪些日志需要留下来分析，那些需要删除。肯定是自己项目的分析了，这里记一下我这里碰到一个例子。

用这个方法处理了几个应用，以为顺顺利利就可以完成的时候，还是出了意外，发现了一个目标。

请添加图片描述

顺着时间看过去。

在这里插入图片描述

发现是项目用了 FFmpeg 代码。

再定位到代码中的使用场景，原来是用它来抽取封面。

    private static int extractFrames(String videoPath, String outputDirectory) {//"1"表示第一帧String[] cmd = new String[]{"-y", "-i", videoPath,"-vframes", "1", "-s", "244x184", outputDirectory};int returnCode = FFmpeg.execute(cmd);MLog.e(TAG, "returnCode: " + returnCode);return returnCode;}

那这个这么减少日志呢，我先是搜了下 FFmpeg 这个类有没有对应的方法，搜了一圈源码没有看到。

在网上搜了下呢，有答案，但是这个 jar 包里面没有对应的方法，看了下版本，有点小差异，但是按理说不应该有这儿大的差异。

我又找有没有 Config 之类的配置类，有，但是没有直接调用的，连构造函数都是 private 。

在这里插入图片描述

就当我还在想要 FFmpeg 是怎么用这个 Config 类时，我才注意到，原来这个方法就是执行 FFmpeg 命令。

熟悉 Linux 一些工具的对应命令就知道，很多都会有 -q 的设置，代表安静，不输出内容。

FFmpeg 这么流行的框架，那肯定也有会对应的方法。

果然有个 -loglevel 可以调整输出日志的等级，那我直接加在 extractFrames 中就可以了，稍微改下，这里的话问了下 gpt 的顺序，有些参数的执行还是有顺序的匹配问题。

    private static int extractFrames(String videoPath, String outputDirectory) {//"1"表示第一帧String[] cmd = new String[]{"-y", "-loglevel", "error", "-i", videoPath,"-vframes", "1", "-s", "244x184", outputDirectory};int returnCode = FFmpeg.execute(cmd);MLog.e(TAG, "returnCode: " + returnCode);return returnCode;}

重新运行应用，验证 OK。

是不是觉得 Linux 这些命令还挺好用的呢。

在这里插入图片描述