来源：https://zhenbianshu.github.io/继上次排查之后，最近在排查一个问题，用了将近两周的时间。我必须总结一下，今天继续。Jdk的native方法当然不是终点。虽然发现Jdk、docker、操作系统bug的可能性极小，但是在底层检查的时候还是很有可能发现一些常见的配置错误的。为了方便复现，我用JMH写了一个简单的demo，控制速度通过log4j2不断写入日志。将项目打包成jar包，方便到处运行。@BenchmarkMode(Mode.AverageTime)@OutputTimeUnit(TimeUnit.MICROSECONDS)@State(Scope.Benchmark)@Threads(5)publicclassLoggerRunner{publicstaticvoidmain(String[]args)throwsRunnerException{选项options=newOptionsBuilder().include(LoggerRunner.class.getName()).warmupIterations(2).forks(1).measurementIterations(1000).build();新亚军（选项）。运行（）；我怀疑这是因为docker。但是在docker内外运行jar包后发现日志暂停问题很容易重现。而且jdk的版本很多，我准备先查看一下操作系统配置问题。系统调用strace命令已经用了很久了。前不久我也用它来分析shell脚本执行慢的问题（解决问题，不要扩大问题），但我还是不习惯把Java和它联系起来。还好有部门老司机指出，于是用strace分析了一波Java应用。命令和分析普通脚本一样，strace-T-ttt-f-ostrace.logjava-jarlog.jar，-T选项可以打印每次系统调用耗时到系统末尾称呼。当然在排错的时候也可以使用-ppid附加tomcat，虽然会出现很多混乱的系统调用。对比jmh压测用例输出的log4j2.info()方法耗时，发现下图的情况。一次写系统调用耗时147毫秒。显然，问题出在write系统调用上。文件系统结构这时候就需要回忆一下操作系统的知识了。在Linux系统中，一切皆文件，为了给不同的媒体提供抽象接口，在应用层和系统层之间抽象出一个虚拟文件系统层（virtualfilesystem，VFS）。上层应用程序通过systemcall系统调用对虚拟文件系统进行操作，然后反馈给下层硬件层。由于硬盘等介质的运行速度与内存不在一个数量级，为了平衡两者的速度，Linux将文件映射到内存，将硬盘单元块（block）映射到内存中的一页（page）。这样当需要操作文件的时候，直接操作内存就可以了。当缓冲操作达到一定量或达到一定时间后，将变化统一刷新到磁盘。这样有效减少了磁盘操作，应用程序不用等待硬盘操作结束，提高了响应速度。write系统调用会将数据写入内存中的pagecache，标记该页为脏页（dirty）并返回。linux的writeback机制有两种将内存缓冲区的内容刷到磁盘的方法：首先，当应用程序调用write系统调用写入数据时，如果发现pagecache的使用量大于设定的大小，则会主动把内存中的脏页刷到硬盘上。在此期间，所有写系统调用都将被阻塞。当然，系统不会容忍计划外的写阻塞。Linux也会定时启动pdflush线程，判断内存页达到一定比例或者脏页存活时间达到设定时间，将这些脏页刷回磁盘，避免被动刷缓冲区，这个机制就是linux的writeback机制。通过以上基本知识的猜测，write系统调用阻塞的原因有两种可能：pagecache空闲空间不足，触发主动flush，此时所有对该设备的写入都会阻塞。写入过程被其他事务阻塞。首先针对第一种可能：查看系统配置dirty_ratio的大小：20。这个值是pagecache占用可用系统内存（realmem+swap）的最大百分比。我们的内存是32G。如果不启用swap，实际可用的pagecache大小约为6G。另外，pdflush相关的系统配置：系统会每隔vm.dirty_writeback_centisecs（5s）唤醒pdflush线程，当发现脏页比例超过vm.dirty_background_ratio（10%）或脏页存活时间时pages超过vm.dirty_expire_centisecs(30s)，它将Flushdirtypages回磁盘。查看/proc/meminfo中Dirty/Writeback项的变化，比较服务的文件写入速度。结论是数据会被pdflush刷回硬盘，不会触发passiveflush阻塞write系统调用。ext4journalfeaturewrite被屏蔽的原因继续搜索资料。在一篇文章（Whybufferedwritessometimesarestalled）中看到write系统调用可能会阻塞如下：whenthedatawritingdependstotheresultofread。但是日志记录不依赖于读取文件；当写入页面时，其他线程正在调用fsync()等方法来主动刷新脏页。但是由于锁的存在，写日志的时候不会有其他线程操作；ext3/4格式的文件系统在记录journal日志时会阻塞写入。而我们的系统文件格式是ext4。维基百科(https://en.wikipedia.org/wiki...)上的条目也描述了这种可能性。Journaljournal是文件系统保证数据一致性的一种手段。在写入数据之前，记录下接下来的操作步骤。一旦系统断电，恢复时只需读取这些日志并继续操作即可。但是batchjournalcommit是一个事务，writecommit在flush的时候会阻塞。我们可以使用dumpe2fs/dev/disk|grepfeatures查看磁盘支持的特性，其中has_journal表示文件系统支持journal特性。ext4格式的文件系统在挂载时可以选择三种日志记录方式（jouranling、ordered、writeback）中的一种。三种模式具有以下特点：journal：在向文件系统写入数据之前，必须等待metadata和journal被放到磁盘上。ordered：不记录数据的journal，只记录metadata的journal日志，需要保证在其metadatajournalcommit前所有数据都已落盘。当没有添加挂载参数时，ext4使用此模式。writeback：metadatajournalcommit后数据可能会被写入磁盘，这可能会导致系统掉电后旧数据恢复到磁盘。当然我们也可以直接选择禁用journal，使用tune2fs-O^has_journal/dev/disk，只能操作未挂载的磁盘。猜测是因为journal触发了脏页的flush，而脏页的flush导致write被阻塞，所以解决journal问题可以解决接口超时问题。解决方案及压测结果下面是我总结的几个接口超时问题的解决方案：log4j2日志方式改为异步。但是，当系统重新启动时，日志可能会丢失。另外，当异步队列ringbuffer被填满且未被消费后，新的日志会自动使用同步模式。调整系统flushdirtypages的配置，将dirtypagecheck和dirtypageexpirationtime设置的更短（1s以内）。但理论上，它会稍微增加系统负载（未明显观察到）。挂载硬盘时使用data=writeback选项修改journal模式。但是，这可能会导致系统重启后文件中包含已删除的内容。禁用ext4的日志功能。但它可能会导致系统文件不一致。将ext4日志日志迁移到速度更快的磁盘，如ssd、闪存等，操作复杂，维护困难。使用xfs、fat等文件系统格式，特性未知，影响未知。当然，我也对这些方案进行了压测，下面是压测结果。文件系统特性接口超时率ext4（在同一行）0.202%xfs文件系统0.06%页面过期时间和pdflush启动时间设置为0.8s0.017%ext4日志模式为回写0%当挂载时ext4日志特性禁用0%Log4j2使用异步日志0%总结接口超时问题终于告一段落。查了半天，不过解决了也很有成就感。不幸的是，在linux内核代码中没有找到任何证据。160M代码不熟悉分层。程序员还是需要了解一些操作系统知识的，这不仅可以帮助我们在处理这种奇怪的问题时不至于手足无措，而且在做一些业务设计的时候也可以作为参考。熟悉了一些系统工具和命令，脚手架又丰富了。近期热点文章推荐：1.1,000+Java面试题及答案（2021最新版）2.别在满屏的if/else中，试试策略模式，真的很好吃！！3.操！Java中xx≠null的新语法是什么？4、SpringBoot2.5发布，深色模式太炸了！5.《Java开发手册（嵩山版）》最新发布，赶快下载吧！感觉不错，别忘了点赞+转发！
