Android 日志记录小优化

0 背景现状

APP 当中有这样的场景：记录错误、警告错误日志至本地文本，如用户支付失败、H5 内容加载失败、请求超时、登录失败、json 解析异常等。目前我们的做法，每次写入一个文件，写满 1M，新启一个文件写，最多 3 个文件，3个文件都写满，将最老的文件清空。

为避免多线程竞争文件操作，将写文件、文件上传等都放在一个单线程池中处理。

public void write(final File file, @NonNull final String msg) {
    ThreadUtil.runOnSingleThread(new Runnable() {
        @Override
        public void run() {
            syncWrite(file, msg);
        }
    });
}

private void syncWrite(File file, @NonNull String msg) {
    if (Environment.getExternalStorageState().equals(Environment.MEDIA_MOUNTED)) {
        FileOutputStream fos = null;

        long timestamp = SystemUtil.getCurrentTimeMillis();
        StringBuilder sb = new StringBuilder(4 * 1024);
        String currentTime = StringUtil.formatTime("yyyy-MM-dd HH:mm:ss", timestamp);
        sb.append(StringUtil.add("\n[", currentTime, " utc0000]"));
        sb.append(" ");
        appendTopPageInfo(sb);
        sb.append("  ");
        sb.append(msg);
        sb.append("\n\n");

        try {
            fos = new FileOutputStream(file.getPath(), true);
            fos.write(sb.toString().getBytes());
        } catch (IOException e) {
            e.printStackTrace();
        } finally {
            Disposable.dispose(fos);
        }
    }
}

写测试代码查看性能：

private void test() {
    String msg = "test aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa";

    start = System.currentTimeMillis();
    for (int i=0; i<5000; i++) {
        FeedbackUtil.syncSaveFeedbackLogInfo2File(msg);
    }
    Log.i("JOURNAL", "old cost " + (System.currentTimeMillis() - start));
}

测试代码 0-0

09-14 16:52:43.310 14421-14421/com.netease.yanxuan I/JOURNAL: old cost 2294

测试查看测试结果，可以发现写操作耗时为 2294ms。重新分析上面的写文件操作。一次写文件过程如下：

1. 进程调用库函数向内核发起读文件请求；
2. 内核通过检查进程的文件描述符定位到虚拟文件系统的已打开文件列表表项；
3. 调用该文件可用的系统调用函数 read()
4. read() 函数通过文件表项链接到目录项模块，根据传入的文件路径，在目录项模块中检索，找到该文件的inode；
5. 在 inode 中，通过文件内容偏移量计算出要读取的页；
6. 通过 inode 找到文件对应的 address_space，在 address_space 中查询对应页的页缓存是否存在；
7. 如果页缓存命中，直接把文件内容修改更新在页缓存的页中。写文件就结束了。这时候文件修改位于页缓存，并没有写回到磁盘文件中去。
8. 如果页缓存缺失，那么产生一个页缺失异常，创建一个页缓存页，同时通过 inode 找到文件该页的磁盘地址，读取相应的页填充该缓存页。此时缓存页命中，进行第 7 步；
9. 一个页缓存中的页如果被修改，那么会被标记成脏页。脏页需要写回到磁盘中的文件块。有两种方式可以把脏页写回磁盘：
   • 手动调用 sync() 或者 fsync() 系统调用把脏页写回
   • pdflush进程会定时把脏页写回到磁盘

以上 写过程 摘自 从内核文件系统看文件读写过程

总结以上可以发现有 2 处性能消耗的地方：

1. 以上一次写文件操作，会发生 2 次拷贝操作，用户内存数据拷贝至内核页缓存，内核页缓存写入磁盘；
2. 由于写日志是非常频繁的操作，同时每次写的内容都是很小的，可以理解程序会非常频繁的对同一个文件执行上述的 1 ~ 8 步骤。

而写性能低下导致的问题除了 cpu 占用，更容易导致写日志的线程队列过长，甚至溢出导致丢弃最老的任务，也容易发生进程被杀时，日志的丢失。

1 优化

针对性能消耗 1，如何减少 2 次拷贝操作，我们能想到使用 mmap，通过文件内存映射的方式将 2 次拷贝操作减少至 1 次。

mmap是一种内存映射文件的方法，即将一个文件或者其它对象映射到进程的地址空间，实现文件磁盘地址和进程虚拟地址空间中一段虚拟地址的一一对映关系。
实现这样的映射关系后，进程就可以采用指针的方式读写操作这一段内存，而系统会自动回写脏页面到对应的文件磁盘上，即完成了对文件的操作

摘自 认真分析mmap：是什么 为什么 怎么用

然而根据现在的使用场景，数据写操作虽然频繁，然而每次写的数据量都比较小，同时也不知道下次写是何时会发生，可能 1ms 后就立即触发，也可能 1 分钟后。而 mmap 并不适合小数据的操作，即每次写的时候都创建一次，length 是每次写的小数据长度。

c 方法原型
void *mmap(void *start, size_t length, int prot, int flags, int fd, off_t offset);

java 方法原型
public abstract MappedByteBuffer map(MapMode mode, long position, long size)

查看测试代码：

protected void test() {

    String content = "aaaaaaaaaaaassssdfsfasfsdsdfsegwegegwgs";

    long start = System.currentTimeMillis();
    oldWrite(content);
    Log.i("TEST", "old: " + (System.currentTimeMillis() - start));

    start = System.currentTimeMillis();
    newWrite1(content);
    Log.i("TEST", "new1: " + (System.currentTimeMillis() - start));
    
    start = System.currentTimeMillis();
    newWrite(content);
    Log.i("TEST", "new: " + (System.currentTimeMillis() - start));
}

private void oldWrite(String content) {
    String path = StorageUtil.getWritePath("oldwrite.txt", StorageType.TYPE_FILE);

    for (int i = 0; i < 1000; i++) {
        File file = new File(path);
        FileOutputStream os = null;
        try {
            os = new FileOutputStream(file, true);
            os.write(content.getBytes());
        } catch (IOException e) {
            Log.e("TEST", "old: " + e.toString());
        } finally {
            Disposable.dispose(os);
        }
    }
}

private void newWrite(String content) {
    String path = StorageUtil.getWritePath("newwrite.txt", StorageType.TYPE_FILE);
    File file = new File(path);

    RandomAccessFile raf = null;
    try {
        raf = new RandomAccessFile(file, "rw");
        MappedByteBuffer buff = raf.getChannel().map(FileChannel.MapMode.READ_WRITE, 0, 1024 * 1024);
        for (int i = 0; i < 1000; i++) {
            buff.put(content.getBytes());
        }
        buff.force();
        buff.flip();
    } catch (Exception e) {
        Log.e("TEST", "new: " + e.toString());
    } finally {
        Disposable.dispose(raf);
    }
}

private void newWrite1(String content) {
    String path = StorageUtil.getWritePath("newwrite1.txt", StorageType.TYPE_FILE);
    File file = new File(path);

    for (int i = 0; i < 1000; i++) {
        RandomAccessFile raf = null;
        try {
            raf = new RandomAccessFile(file, "rw");
            byte[] bytes = content.getBytes();
            MappedByteBuffer buff = raf.getChannel().map(FileChannel.MapMode.READ_WRITE, raf.length(), bytes.length);
            buff.put(content.getBytes());

            buff.force();
            buff.flip();
        } catch (Exception e) {
            Log.e("TEST", "new: " + e.toString());
        } finally {
            Disposable.dispose(raf);
        }
    }
}

测试代码 1-0

查看测试结果：

09-14 18:06:47.205 7311-7311/com.netease.yanxuan I/TEST: old: 129
09-14 18:06:50.899 7311-7311/com.netease.yanxuan I/TEST: new1: 3694
09-14 18:06:47.076 7311-7311/com.netease.yanxuan I/TEST: new: 27

由上我们可以发现，执行 1000 次字符串写，mmap 执行一次大数据写性能最好，普通文件写操作要慢 4 倍多，而 mmap 执行多次小数据写则性能会差很多。

查看文件可以发现，一次性 mmap 1M 的文件，但仅写入 40K 左右的数据，最后文件大小还是 1M

Alt pic

写入生成的文件

Alt pic

1M 文件的内容

针对以上情况，一种解决方法是使用内存缓存，业务层写日志时并不是立马写入文件，而是写入内存缓存中，等内存缓存到达一定大小，或者定期轮训触发写操作。虽然能很好的优化写性能问题，同时可以根据内存缓存的大小，可以按需写入文件，不会出现文件有无效数据的情况。然而内存缓存的延迟写入，在进程被杀的情况下，极大的增加了丢日志的情况。

所以这里采用另外的思路，构建写消息队列，并且发送 10ms 延迟关闭 buff 消息，保证在频繁写操作下，文件描述符不会被频繁关闭和打开，同时 10ms 内无写操作时，能及时关闭文件描述符，避免内存泄露。另外为准确确认文件大小，在文件头 4 个字节写入文件内容的真实大小。

Alt pic

日志文件

Alt pic

写日志流程

同最初的测试代码，写日志 5000 次到日志文件

private void test() {
    String msg = "test aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa";

    start = System.currentTimeMillis();
    for (int i=0; i<5000; i++) {
        FeedbackUtil.syncSaveLogInfo2File(msg);
    }
    Log.i("JOURNAL", "old cost " + (System.currentTimeMillis() - start));
    
    start = System.currentTimeMillis();
    for (int i = 0; i < 5000; i++) {
        NewFeedbackUtil.syncSaveLogInfo2File(msg);
    }
    Log.i("JOURNAL", "new cost " + (System.currentTimeMillis() - start));
}

测试代码 1-1

09-15 09:09:46.744 4450-4450/com.netease.yanxuan I/JOURNAL: old cost 2319
09-15 09:09:44.425 4450-4450/com.netease.yanxuan I/JOURNAL: new cost 1285

最后能发现日志写提升 80%，至于相比测试代码 1-0 的性能提升 4 倍，为何会差这么多，是因为除了纯粹的写之外，真实日志代码中需要获取额外的日志信息，如时间、当前页面信息等，同时优化的日志文件严格控制了应用层设置的文件上限，而老的日志写并没有严格控制上限。