应用复现
接着上文 从应用到内核查接口超时（上） 继续排查导致接口超时的原因。
转载随意，文章会持续修订，请注明来源地址：https://zhenbianshu.github.io 。
Jdk 的 native 方法当然不是终点，虽然发现 Jdk、docker、操作系统 Bug 的可能性极小，但再往底层查却很可能发现一些常见的配置错误。
为了便于复现，我用 JMH 写了一个简单的 demo，控制速度不断地通过 log4j2 写入日志。将项目打包成 jar 包，就可以很方便地在各处运行了。
@BenchmarkMode(Mode.AverageTime) @OutputTimeUnit(TimeUnit.MICROSECONDS) @State(Scope.Benchmark) @Threads(5) public class LoggerRunner { public static void main(String[] args) throws RunnerException { Options options = new OptionsBuilder() .include(LoggerRunner.class.getName()) .warmupIterations(2) .forks(1) .measurementIterations(1000) .build(); new Runner(options).run(); } } 我比较怀疑是 docker 的原因。但是在 docker 内外运行了 jar 包却发现都能很简单地复现日志停顿问题。而 jdk 版本众多，我准备首先排查操作系统配置问题。
系统调用
strace 命令很早就使用过，不久前还用它分析过 shell 脚本执行慢的问题( 解决问题，别扩展问题)，但我还是不太习惯把 Java 和它联系起来，幸好有部门的老司机指点，于是就使用 strace 分析了一波 Java 应用。
命令跟分析普通脚本一样， strace -T -ttt -f -o strace.log java -jar log.jar， -T 选项可以将每一个系统调用的耗时打印到系统调用的结尾。当然排查时使用 -p pid 附加到 tomcat 上也是可以的，虽然会有很多容易混淆的系统调用。
对比 jmh 压测用例输出的 log4j2.info() 方法耗时，发现了下图中的状况。
一次 write 系统调用竟然消耗了 147ms，很明显地，问题出在 write 系统调用上。
文件系统
结构
这时候就要好好回想一下操作系统的知识了。
在 linux 系统中，万物皆文件，而为了给不同的介质提供一种抽象的接口，在应用层和系统层之间，抽象了一个虚拟文件系统层（virtual file system, VFS）。上层的应用程序通过 系统调用 system call 操作虚拟文件系统，进而反馈到下层的硬件层。
由于硬盘等介质操作速度与内存不在同一个数量级上，为了平衡两者之间的速度，linux 便把文件映射到内存中，将硬盘单位块(block)对应到内存中的一个 页(page)上。这样，当需要操作文件时，直接操作内存就可以了。当缓冲区操作达到一定量或到达一定的时间后，再将变更统一刷到磁盘上。这样便有效地减少了磁盘操作，应用也不必等待硬盘操作结束，响应速度得到了提升。
而 write 系统调用会将数据写到内存中的 page cache，将 page 标记为 脏页(dirty) 后返回。
linux 的 writeback 机制
对于将内存缓冲区的内容刷到磁盘上，则有两种方式：
首先，应用程序在调用 write 系统调用写入数据时，如果发现 page cache 的使用量大于了设定的大小，便会主动将内存中的脏页刷到硬盘上。在此期间，所有的 write 系统调用都会被阻塞。
系统当然不会容忍不定时的 write 阻塞，linux 还会定时启动 pdflush 线程，判断内存页达到一定的比例或脏页存活时间达到设定的时间，将这些脏页刷回到磁盘上，以避免被动刷缓冲区，这种机制就是 linux 的 writeback 机制。
猜测
了解了以上基础知识，那么对于 write 系统调用为什么会被阻塞，提出了两种可能：
- page cache 可用空间不足，导致触发了主动的 flush，此时会阻塞所有对此 device 的 write。
- 写入过程被其他事务阻塞。
首先对于第一种可能： 查看系统配置 dirty_ratio 的大小： 20。此值是 page cache 占用系统可用内存(real mem + swap)的最大百分比， 我们的内存为 32G，没有启用 swap，则实际可用的 page cache 大小约为 6G。
另外，与 pdflush 相关的系统配置：系统会每 vm.dirty_writeback_centisecs (5s) 唤醒一次 pdflush 线程， 发现脏页比例超过 vm.dirty_background_ratio (10%) 或 脏页存活时间超过 vm.dirty_expire_centisecs(30s) 时，会将脏页刷回硬盘。
查看 /proc/meminfo 内 Dirty/Writeback 项的变化，并对比服务的文件写入速度，结论是数据会被 pdflush 刷回到硬盘，不会触发被动 flush 以阻塞 write 系统调用。
