⭐⭐⭐ Spring Boot 项目实战	⭐⭐⭐ Spring Cloud 项目实战
《Dubbo 实现原理与源码解析 —— 精品合集》	《Netty 实现原理与源码解析 —— 精品合集》
《Spring 实现原理与源码解析 —— 精品合集》	《MyBatis 实现原理与源码解析 —— 精品合集》
《Spring MVC 实现原理与源码解析 —— 精品合集》	《数据库实体设计合集》
《Spring Boot 实现原理与源码解析 —— 精品合集》	《Java 面试题 + Java 学习指南》

摘要: 原创出处 zhenbianshu.github.io/ 「zhenbianshu」欢迎转载，保留摘要，谢谢！

🙂🙂🙂关注**微信公众号：【芋道源码】**有福利：

RocketMQ / MyCAT / Sharding-JDBC 所有源码分析文章列表

RocketMQ / MyCAT / Sharding-JDBC 中文注释源码 GitHub 地址

您对于源码的疑问每条留言都将得到认真回复。甚至不知道如何读源码也可以请教噢。

新的源码解析文章实时收到通知。每周更新一篇左右。

认真的源码交流微信群。

接着上次的接口超时排查，这次排查接口超时原因，鬼知道我经历了什么，最终查到是因为 journal 导致 write 系统调用被阻塞进而导致超时后，总感觉证据还不够充分，没有一个完美的交待。而且 leader 还想着让我把问题排查过程分享给同事们，这让我更加不安，担心搞错了方向。

在以往的博客中，我的问题结论总是确定的，如果是推论的话，我会显式注明。现在的情况让我有点犯难，推论说出去担心误导了别人，而内核层的事，我只知道基本理论，有关此问题的结论还没有。

于是，我只好再次踏上查这个问题的征程。

打印进程内核栈

回到问题的原点，对于此问题，我能确定的资料只有稳定复现的环境和不知道什么时候会触发 write system call 延迟的 jar 包。

考虑到 write system call 被阻塞可长达几百 ms，我想我能抓出当前进程的内核栈来看一下 write system call 此时被阻塞在什么位置。

具体步骤为：

多个线程不便于抓内核栈，先将程序修改为单线程定量写入。
使用 jar 包启动一个进程，使用 ps 拿到进程号。
再通过 top -H -p pid 拿到占用 cpu、内存等资源最多的线程 ID，或使用 strace 启动，查看其输出里正在写入的线程 ID。
使用 watch 命令搭配 pstack 或 cat /proc/pid/stack 不停打印进程内核栈。具体命令为 watch -n 0.1 "date +%s >> stack.log;cat /proc/pid/stack >> stack.log"
找到 write system call 被阻塞时的时间戳，在 stack.log 里查看当时的进程内核栈。

可稳定收集到 write system call 被阻塞时，进程内核栈为：

[<ffffffff812e31f4>] call_rwsem_down_read_failed+0x14/0x30
       [<ffffffffa0195854>] ext4_da_get_block_prep+0x1a4/0x4b0 [ext4]
       [<ffffffff811fbe17>] __block_write_begin+0x1a7/0x490
       [<ffffffffa019b71c>] ext4_da_write_begin+0x15c/0x340 [ext4]
       [<ffffffff8115685e>] generic_file_buffered_write+0x11e/0x290
       [<ffffffff811589c5>] __generic_file_aio_write+0x1d5/0x3e0
       [<ffffffff81158c2d>] generic_file_aio_write+0x5d/0xc0
       [<ffffffffa0190b75>] ext4_file_write+0xb5/0x460 [ext4]
       [<ffffffff811c64cd>] do_sync_write+0x8d/0xd0
       [<ffffffff811c6c6d>] vfs_write+0xbd/0x1e0
       [<ffffffff811c76b8>] SyS_write+0x58/0xb0
       [<ffffffff81614a29>] system_call_fastpath+0x16/0x1b
       [<ffffffffffffffff>] 0xffffffffffffffff

内核栈分析

write system call 阻塞位置

通过内核栈函数关键字找到了 OenHan 大神的博客，读写信号量与实时进程阻塞挂死问题这篇文章描述的问题虽然跟我遇到的问题不同，但进程内核栈的分析对我很有启发。为了便于分析内核函数，我 clone 了一份 linux 3.10.0 的源码，在本地查看。

搜索源码可以证实，栈顶的汇编函数 ENTRY call_rwsem_down_read_failed 会调用 rwsem_down_read_failed(), 而此函数会一直阻塞在获取 inode 的锁。

struct rw_semaphore __sched *rwsem_down_read_failed(struct rw_semaphore *sem) {
        .....
        /* wait to be given the lock */
        while (true) {
        set_task_state(tsk, TASK_UNINTERRUPTIBLE);
        if (!waiter.task)
        break;
        schedule();
        }

        tsk->state = TASK_RUNNING;

        return sem;
        }

延迟分配

知道了 write system call 阻塞的位置，还要查它会什么会阻塞在这里。这时，栈顶的函数名 call_rwsem_down_read_failed 让我觉得很奇怪，这不是 “write” system call 么，为什么会 down_read_failed？

直接搜索这个函数没有什么资料，但向栈底方向，再搜索其他函数就有了线索了，原来这是在做系统磁盘块的准备，于是就牵扯出了 ext4 的 delayed allocation 特性。

延迟分配(delayed allocation)：ext4 文件系统在应用程序调用 write system call 时并不为缓存页面分配对应的物理磁盘块，当文件的缓存页面真正要被刷新至磁盘中时，才会为所有未分配物理磁盘块的页面缓存分配尽量连续的磁盘块。

这一特性，可以避免磁盘的碎片化，也可以避免存活时间极短文件的磁盘块分配，能很大提升系统文件 I/O 性能。

而在 write 向内存页时，就需要查询这些内存页是否已经分配了磁盘块，然后给未分配的脏页打上延迟分配的标签（写入的详细过程可以查看 ext4 的延迟分配）。此时需要获取此 inode 的读锁，若出现锁冲突，write system call 便会 hang 住。

在挂载磁盘时使用 -o nodelalloc 选项禁用掉延迟分配特性后再进行测试，发现 write system call 被阻塞的情况确实消失了，证明问题确定跟延迟分配有关。

不算结论的结论

寻找写锁

知道了 write system call 阻塞在获取读锁，那么一定是内核里有哪些地方持有了写锁。

ipcs 命令可以查看系统内核此时的进程间通信设施的状态，它打印的项目包括消息列表(-q)、共享内存(-m)和信号量(-q)的信息，用 ipcs -q 打印内核栈的函数查看 write system call 被阻塞时的信号量，却没有输出任何信息。仔细想了一下发现其写锁 i_data_sem 是一把读写锁，而信号量是一种 非0即1 的PV量，虽然名字里带有 sem，可它并不是用信号量实现的。

perf lock 可以用来分析系统内核的锁信息，但要使用它需要重新编译内核，添加 CONFIG_LOCKDEP、CONFIG_LOCK_STAT 选项。先不说我们测试机的重启需要建提案等两天，编译完能不能启动得来我真的没有信心，第一次试图使用 perf 分析 linux 性能问题就这么折戟了。

转变方法

问题又卡住了，这时我也没有太多办法了，现在开始研究 linux 文件系统源码是来不及了，但我还可以问。

在 stackOverflow 上问没人理我：how metadata journal stalls write system call?，追着 OenHan 问了几次也没有什么结论：Linux内核写文件流程。

虽然自己没法测试 upstream linux，还是在 kernel bugzilla 上发了个帖子：ext4 journal stalls write system call。终于有内核大佬回复我：在 ext4_map_blocks() 函数中进行磁盘块分配时内核会持有写锁。

查看了源码里的函数详情，证实了这一结论：

/*
 * The ext4_map_blocks() function tries to look up the requested blocks,
 * and returns if the blocks are already mapped.
 *
 * Otherwise it takes the write lock of the i_data_sem and allocate blocks
 * and store the allocated blocks in the result buffer head and mark it
 * mapped.
 */
int ext4_map_blocks(handle_t *handle, struct inode *inode,
        struct ext4_map_blocks *map, int flags)
        {
        .....
        /*
         * New blocks allocate and/or writing to uninitialized extent
         * will possibly result in updating i_data, so we take
         * the write lock of i_data_sem, and call get_blocks()
         * with create == 1 flag.
         */
        down_write((&EXT4_I(inode)->i_data_sem));
        .....
        }

但又是哪里引用了 ext4_map_blocks() 函数，长时间获取了写锁呢？再追问时大佬已经颇有些无奈了，linux 3.10.0 的 release 已经是 5年 前了，当时肯定也有一堆 bug 和缺陷，到现在已经发生了很大变动，追查这个问题可能并没有很大的意义了，我只好识趣停止了。

推论

其实再向下查这个问题对我来说也没有太大意义了，缺少对源码理解的积累，再看太多的资料也没有什么收益。就如向建筑师向小孩子讲建筑设计，知道窗子要朝南，大门要靠近电梯这些知识并无意义，不了解建筑设计的原则，只专注于一些自己可以推导出来的理论点，根本没办法吸收到其中精髓。

那么只好走到最后一步，根据查到的资料和测试现象对问题原因做出推论，虽然没有直接证据，但肯定跟这些因素有关。

在 ext4 文件系统下，默认为 ordered journal 模式，所以写 metadata journal 可能会迫使脏页刷盘，而在 ext4 启用 delayed allocation 特性时，脏页可能在落盘时发现没有分配对应的磁盘块而分配磁盘块。在脏页太多的情况下，分配磁盘块慢时会持有 inode 的写锁时间过长，阻塞了 write 系统调用。

小结

追求知识的每一步或多或少都有其中意义，查这个问题就陌使我读了很多外语文献，也了解了一部分文件系统设计思想。

芋道源码 —— 纯源码解析博客

超神了！因为一次接口超时，我一路排查到了内核代码