问题描述
线上接口响应时间变长，在 skywalking 上查看链路，发现时间普遍都花费在 self duration。针对 okhttp、feign，mysql，redis 这种网络调用，我们都打了点，也就是说时间都耗费在了程序代码中，但是我们的程序代码仅仅做了很简单的实体类转换逻辑，以及打印了一些日志。
问题排查
使用 arthas trace 命令追踪 Service 代码耗时，惊奇地发现时间居然都耗费在了 log#info(）方法中。我们代码中使用了两个 Logback Appender：ConsoleAppender 和 RollingFileAppender，RollingFileAppender 将日志存储到挂载的 nfs 中。继续追踪，定位到 Logback OutputStreamAppender#writeBytes() 方法，发现 this.outputStream.flush() 方法特别慢。
阅读源码得知，Logback 默认采用同步的方式打印日志，OutputStreamAppender（RollingFileAppender 的父类）默认 immediateFlush = true，也就是每次 log event 都会触发一次 flush 操作。
OutputStreamAppender#writeBytes() 方法：
private void writeBytes(byte[] byteArray) throws IOException {
if(byteArray == null || byteArray.length == 0)
return;
lock.lock();
try {
this.outputStream.write(byteArray);
if (immediateFlush) {
this.outputStream.flush();
}
} finally {
lock.unlock();
}
}
使用 fio 命令测试磁盘顺序写入性能，结果为 w256KiB/s, w=2 IOPS，性能非常差（但不太清楚是网络慢还是磁盘性能差）。
解决问题
暂时解决方案：暂时 unmount nfs，将日志打在 pod 自身的磁盘中，问题得到解决。
推荐解决方案：ELK Stack 集中式日志收集系统，程序仅负责将日志输出到 pod tty。
如果一定要将日志文件存盘，尽量挂载本地文件系统，不要挂载网络文件系统，网络是一个极其不稳定的因素。
Logback ConsoleAppender 和 RollingFileAppender 性能优化：
- 将 OutputStreamAppender#immediateFlush 属性设置为 false，不需要每次 log event 都进行 this.outputStream.flush() 操作，前提是容忍部分日志丢失，由操作系统决定 flush 时机，允许一定程度的日志丢失。采用这种做法记得接收操作系统的 kill 信号，在程序停止时调用 Appender 的 stop() 方法，关闭 outputStream 输出流，实现优雅停机，否则可能会丢掉最后一次未 flush 的日志内容。
- 使用 AsyncAppender 装饰其他 FileAppender，采用异步写日志方式，不影响主业务接口性能。OutputStreamAppender#writeBytes 方法中会先执行 lock.lock() 操作，获得锁之后再操作 outputStream，如果在业务线程中同步写日志，可能会因为多线程争抢锁而影响业务线程的并发性能。采用这种做法记得接收操作系统的 kill 信号，在程序停止时调用 Appender 的 stop() 方法，设置合适的 maxFlushTime 等待 Work 线程终止，实现优雅停机，不然会丢失 blockingQueue 中的 log event。
另外一个需要注意的事情：多 pod 副本不要写同一个日志文件，本质上是不同 host 上的不同进程同时写一个文件，很容易出现写丢失等问题。
在同一个 Linux 中的不同进程中，多进程可以使用 O_APPEND 的方式同时写同一文件，这样在每次写入时都会 lseek 到文件末尾进行写入，这是一个原子操作，因此不会产生写丢失问题。
