Linux上IO性能问题的故障排除实践

# 引言

在诸如grafana、Nightingale等监控工具盛行的今天，软件开发工程师仍然需要具备面向操作系统维度的性能指标以及终端排查的思想沉淀，确保在日常工程开发和极端环境下都具备足够力道的系统调优能力。而本文将从一个经典的并发IO读写性能引发的用户应用延迟升高的故障深入演示一下传统性能瓶颈分析和排查的手段，希望对你有所启发。

我是 SharkChili ，Java 开发者，Java Guide 开源项目维护者。欢迎关注我的公众号：写代码的SharkChili，也欢迎您了解我的开源项目 mini-redis：https://github.com/shark-ctrl/mini-redis (opens new window)。

为方便与读者交流，现已创建读者群。关注下方公众号获取我的联系方式，添加时备注加群即可加入。

我是 SharkChili ，Java 开发者，Java Guide 开源项目维护者。欢迎关注我的公众号：写代码的SharkChili，也欢迎您了解我的开源项目 mini-redis：https://github.com/shark-ctrl/mini-redis。

为方便与读者交流，现已创建读者群。关注上方公众号获取我的联系方式，添加时备注加群即可加入。

# 背景说明

为了更好地复现本次故障，笔者也用Java写了一个多线程执行文件数据读写的程序，对应入口核心代码段如下：

/**
 * 启动磁盘I/O操作以模拟高I/O负载
 * 通过创建多个I/O任务线程来模拟高磁盘I/O负载
 */
private static void startDiskIOOperations() {
    log.info("开始高I/O磁盘操作...");
    log.info("在另一个终端中运行 'iostat -x 1' 来监控磁盘利用率。");

    // 创建固定线程数的线程池
    executor = Executors.newFixedThreadPool(NUM_THREADS);

    // 提交多个任务以连续写入磁盘
    for (int i = 0; i < NUM_THREADS; i++) {
        executor.submit(new IOTask(i));
    }

    log.info("磁盘I/O操作已启动，使用 {} 个线程", NUM_THREADS);
}

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20

与之对应IOTask的逻辑也非常简单频繁大批量读写文件，完成后再清空，模拟并发场景下频繁的大文件读写操作：

/**
 * 执行连续写入操作以模拟高I/O的任务
 * 该类负责执行磁盘I/O操作，通过不断写入和清空文件来模拟高I/O负载
 */
static class IOTask implements Runnable {
    private final int taskId;

    public IOTask(int taskId) {
        this.taskId = taskId;
    }

    @Override
    public void run() {
        // 每个线程写入自己的临时文件
        String filename = "/tmp/disk_io_test_" + taskId + ".tmp";

        try (FileOutputStream fos = new FileOutputStream(filename)) {
            log.info("线程-{} 正在写入 {}", taskId, filename);

            // 连续将数据写入文件并在每次写入后清空文件
            while (!Thread.currentThread().isInterrupted()) {
                performDiskIOOperation(fos, taskId);
                ThreadUtil.sleep(500);
            }
        } catch (IOException e) {
            log.error("线程-{} 发生错误: {}", taskId, e.getMessage());
        }
    }
}

/**
 * 执行磁盘I/O操作：写入指定大小的数据然后清空文件
 * 该方法会连续写入数据到文件，然后清空文件内容，用于模拟高I/O负载
 * @param fos 文件输出流
 * @param taskId 任务ID
 * @throws IOException IO异常
 */
private static void performDiskIOOperation(FileOutputStream fos, int taskId) throws IOException {
    long startTime = System.currentTimeMillis();

    // 写入数据（分块写入）
    long bytesWritten = 0;
    while (bytesWritten < WRITE_SIZE) {
        fos.write(DATA);
        bytesWritten += DATA.length;
    }
    fos.flush(); // 强制写入磁盘

    // 清空文件内容
    fos.getChannel().truncate(0);
    long endTime = System.currentTimeMillis();

    // 打印本次操作的耗时
    log.info("线程-{} 完成一次写入和清空操作，耗时: {} ms", taskId, (endTime - startTime));
}

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55

# 详解Linux系统IO性能问题排查通用步骤

# 检查服务器负载

当我们认为存在IO瓶颈时，首先要做的就是基于top指令查看当前服务器wa即CPU等待IO任务完成的占比，一般情况下20%以下算是一个比较合理的正常阈值，超过30%-40%则表明系统可能存在严重的IO瓶颈。以笔者的服务器为例，可以看到wa的值远大于正常范围，说明当前CPU基本处于等待IO任务完成的情况：

Tasks:  34 total,   1 running,  33 sleeping,   0 stopped,   0 zombie
%Cpu0  :  0.5 us,  2.6 sy,  0.0 ni,  5.3 id, 90.5 wa,  0.0 hi,  1.1 si,  0.0 st 
%Cpu1  :  0.0 us,  2.2 sy,  0.0 ni, 24.9 id, 72.4 wa,  0.0 hi,  0.5 si,  0.0 st 
%Cpu2  :  1.1 us,  0.6 sy,  0.0 ni,  0.6 id, 97.7 wa,  0.0 hi,  0.0 si,  0.0 st 
%Cpu3  :  0.5 us,  2.7 sy,  0.0 ni, 16.8 id, 80.0 wa,  0.0 hi,  0.0 si,  0.0 st 
%Cpu4  :  0.6 us,  1.7 sy,  0.0 ni,  0.0 id, 97.8 wa,  0.0 hi,  0.0 si,  0.0 st 
%Cpu5  :  0.0 us,  3.9 sy,  0.0 ni, 18.8 id, 77.3 wa,  0.0 hi,  0.0 si,  0.0 st

1
2
3
4
5
6
7

# 查看IO使用率

明确系统存在IO性能瓶颈的情况下，我们就需要更进一步定位问题，以笔者为例，一般会执行iostat指令，如下所示，大意为：

-x：显示更多扩展信息（包括设备利用率、等待时间等）
每1秒输出1次，持续输出

iostat -x 1

输出结果如下，对应的比这也针对这些指标的阈值进行一些简单的说明：

关键指标解读：

%util：设备利用率，接近100%表示设备繁忙，可能存在IO瓶颈
r_await 和 w_await：平均读写请求等待时间，数值越高说明IO响应越慢
aqu-sz：平均请求队列大小，数值较大说明IO请求堆积严重
await：平均服务时间（读写等待时间之和）

avg-cpu:  %user   %nice %system %iowait  %steal   %idle
           0.0%    0.0%    1.0%   78.2%    0.0%   20.8%

Device            r/s     rMB/s   rrqm/s  %rrqm r_await rareq-sz    w/s     wMB/s   wrqm/s  %wrqm w_await wareq-sz    d/s     dMB/s   drqm/s  %drqm d_await dareq-sz  f_await  aqu-sz  %util
sda            0.00      0.00     0.00   0.00    0.00     0.00  0.00      0.00     0.00   0.00    0.00     0.00  0.00      0.00     0.00   0.00    0.00     0.00    0.00    0.00   0.00
sdb            0.00      0.00     0.00   0.00    0.00     0.00  0.00      0.00     0.00   0.00    0.00     0.00  0.00      0.00     0.00   0.00    0.00     0.00    0.00    0.00   0.00
sdc            0.00      0.00     0.00   0.00    0.00     0.00  0.00      0.00     0.00   0.00    0.00     0.00  0.00      0.00     0.00   0.00    0.00     0.00    0.00    0.00   0.00
sdd            4.00      0.04     0.00   0.00  122.25    10.24 171.00    190.81     1.00   0.58 3884.17     1.12  0.00      0.00     0.00   0.00    0.00     0.00    0.00  664.68 100.00

1
2
3
4
5
6
7
8

结合我们实际监控到的指标来看，对应sdd盘使用率%util（IO利用率）飙到100%且iowait达到了78.2%，很明显这块磁盘存在一些异常IO读写任务：

# 明确定位IO进程

基于上述过程我们已经明确sdd盘存在IO异常，此时我们就可以通过iotop来查看具体进程了，需要补充的是iotop默认是没有安装的，读者可以参考网上教程自行安装，以笔者的Ubuntu系统为例，对应的安装指令为：

sudo apt install iotop

最后键入sudo iotop -o查看正在执行IO操作的进程，对应输出结果如下，对应字段含义分别是：

Total DISK READ: 总磁盘读
Total DISK WRITE: 总磁盘写
Current DISK READ: 瞬时磁盘读
Current DISK WRITE: 瞬时磁盘写
TID：线程号
PRIO：io进程优先级
USER：进程所属用户
DISK READ ：该线程读取速率
DISK WRITE：该线程写入速率
COMMAND：执行线程的命令(对应java进程启动指令)

此时就可以非常明确地看到笔者Java进程对应执行异常IO操作的线程和读写速率了，可以看到笔者的大量进程都存在写入操作，占用大量磁盘写入带宽：

Total DISK READ:         0.00 B/s | Total DISK WRITE:       142.99 M/s
Current DISK READ:      11.92 K/s | Current DISK WRITE:     336.21 M/s
    TID  PRIO  USER     DISK READ DISK WRITE>    COMMAND                                                                                              
3253712 be/4 sharkchi    0.00 B/s   18.26 M/s java -jar web-cache-1.0.jar --app.startup.method=1 [pool-2-thread-3]
3253713 be/4 sharkchi    0.00 B/s   18.26 M/s java -jar web-cache-1.0.jar --app.startup.method=1 [pool-2-thread-4]
3253711 be/4 sharkchi    0.00 B/s   18.25 M/s java -jar web-cache-1.0.jar --app.startup.method=1 [pool-2-thread-2]
3253715 be/4 sharkchi    0.00 B/s   18.25 M/s java -jar web-cache-1.0.jar --app.startup.method=1 [pool-2-thread-6]
3253714 be/4 sharkchi    0.00 B/s   18.24 M/s java -jar web-cache-1.0.jar --app.startup.method=1 [pool-2-thread-5]
3253710 be/4 sharkchi    0.00 B/s   17.50 M/s java -jar web-cache-1.0.jar --app.startup.method=1 [pool-2-thread-1]
3253717 be/4 sharkchi    0.00 B/s   17.50 M/s java -jar web-cache-1.0.jar --app.startup.method=1 [pool-2-thread-8]
3253716 be/4 sharkchi    0.00 B/s   16.74 M/s java -jar web-cache-1.0.jar --app.startup.method=1 [pool-2-thread-7]