关于java:一次接口超时排查花费了我两个星期

起源：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 零碎调用。

ext4 的 journal 个性

write 被阻塞的起因

持续搜寻材料，在一篇文章 (Why buffered writes are sometimes stalled) 中看到 write 零碎调用被阻塞有以下可能：

• 要写入的数据依赖读取的后果时。但记录日志不依赖读文件；
• wirte page 时有别的线程在调用 fsync() 等被动 flush 脏页的办法。但因为锁的存在，log 在写入时不会有其余的线程操作；
• 格局为 ext3/4 的文件系统在记录 journal log 时会阻塞 write。而咱们的零碎文件格式为 ext4。维基百科上的一个条目（https://en.wikipedia.org/wiki…）也形容了这种可能。

journal

journal 是 文件系统保证数据一致性的一种伎俩，在写入数据前，将行将进行的各个操作步骤记录下来，一旦零碎掉电，复原时读取这些日志持续操作就能够了。但批量的 journal commit 是一个事务，flush 时会阻塞 write 的提交。

咱们能够应用 dumpe2fs /dev/disk | grep features 查看磁盘反对的个性，其中有 has_journal 代表文件系统反对 journal 个性。

ext4 格局的文件系统在挂载时能够抉择 (jouranling、ordered、writeback) 三种之一的 journal 记录模式。

三种模式别离有以下个性：

• journal：在将数据写入文件系统前，必须期待 metadata 和 journal 曾经落盘了。
• ordered：不记录数据的 journal，只记录 metadata 的 journal 日志，且须要保障所有数据在其 metadata journal 被 commit 之前落盘。ext4 在不增加挂载参数时应用此模式。
• writeback: 数据可能在 metadata journal 被提交之后落盘，可能导致旧数据在零碎掉电后复原到磁盘中。

当然，咱们也能够抉择间接禁用 journal，应用 tune2fs -O ^has_journal /dev/disk，只能操作未被挂载的磁盘。

猜想因为 journal 触发了脏页落盘，而脏页落盘导致 write 被阻塞，所以解决 journal 问题就能够解决接口超时问题。

解决方案与压测后果

以下是我总结的几个接口超时问题的解决方案：

1. log4j2 日志模式改异步。但有可能会在零碎重启时失落日志，另外在异步队列 ringbuffer 被填满未生产后，新日志会主动应用同步模式。
2. 调整零碎刷脏页的配置，将查看脏页和脏页过期工夫设置得更短(1s 以内)。但实践上会稍微晋升零碎负载（未显著察看到）。
3. 挂载硬盘时应用 data=writeback 选项批改 journal 模式。但可能导致系统重启后文件蕴含已删除的内容。
4. 禁用 ext4 的 journal 个性。但可能会导致系统文件的不统一。
5. 把 ext4 的 journal 日志迁徙到更快的磁盘上，如 ssd、闪存等。操作简单，不易保护。
6. 应用 xfs、fat 等 文件系统格局。个性不理解，影响不可知。

当然，对于这几种计划，我也做了压测，以下是压测的后果。

小结

接口超时问题总算是告一段落，查了很久，不过解决它之后也十分有成就感。遗憾的是没有在 linux 内核代码中找到证据，160M 的代码，分层也不相熟，切实是无从查起，心愿当前有机会能缓缓接触吧。

程序员还是要懂些操作系统常识的，不仅帮咱们在应答这种诡异的问题时不至于大刀阔斧，也能够在做一些业务设计时能有所参考。

又相熟了一些零碎工具和命令，脚手架上又丰盛了。

近期热文举荐：

1.1,000+ 道 Java 面试题及答案整顿(2021 最新版)

2. 别在再满屏的 if/ else 了，试试策略模式，真香！！

3. 卧槽！Java 中的 xx ≠ null 是什么新语法？

4.Spring Boot 2.5 重磅公布，光明模式太炸了！

5.《Java 开发手册（嵩山版）》最新公布，速速下载！

感觉不错，别忘了顺手点赞 + 转发哦！