io_analyzer 

#include <stdio.h>
#include <stdlib.h>
#include <string.h>
#include <unistd.h>
#include <dirent.h>
#include <ctype.h>


#define MAX_PROC 65536
#define TOP 10


typedef struct
{
    unsigned long read_ios;
    unsigned long read_sectors;

    unsigned long write_ios;
    unsigned long write_sectors;

    unsigned long io_ticks;

} DiskStat;



typedef struct
{
    int pid;

    char name[64];

    unsigned long long read_bytes;
    unsigned long long write_bytes;

    unsigned long long read_rate;
    unsigned long long write_rate;

} ProcStat;




/*
 * /proc/diskstats
 *
 * kernel 2.6:
 *
 * major minor name
 * reads completed
 * sectors read
 * writes completed
 * sectors written
 * io_ticks
 *
 */


int read_diskstat(char *disk, DiskStat *ds)
{

    FILE *fp;
    char line[512];

    fp=fopen("/proc/diskstats","r");

    if(!fp)
        return -1;


    while(fgets(line,sizeof(line),fp))
    {

        char name[64];

        unsigned long major;
        unsigned long minor;

        unsigned long rd_ios;
        unsigned long rd_merges;
        unsigned long rd_sec;
        unsigned long rd_time;


        unsigned long wr_ios;
        unsigned long wr_merges;
        unsigned long wr_sec;
        unsigned long wr_time;


        unsigned long io_ticks;
        unsigned long weighted;


        int ret;


        ret=sscanf(line,
        "%lu %lu %s "
        "%lu %lu %lu %lu "
        "%lu %lu %lu %lu "
        "%lu %lu",
        &major,
        &minor,
        name,
        &rd_ios,
        &rd_merges,
        &rd_sec,
        &rd_time,
        &wr_ios,
        &wr_merges,
        &wr_sec,
        &wr_time,
        &io_ticks,
        &weighted);



        if(ret < 13)
            continue;



        if(strcmp(name,disk)==0)
        {

            ds->read_ios=
                rd_ios;


            ds->read_sectors=
                rd_sec;


            ds->write_ios=
                wr_ios;


            ds->write_sectors=
                wr_sec;


            ds->io_ticks=
                io_ticks;


            fclose(fp);

            return 0;
        }

    }


    fclose(fp);

    return -1;
}





int read_proc_io(
int pid,
unsigned long long *r,
unsigned long long *w)
{

    char path[128];

    sprintf(path,
    "/proc/%d/io",
    pid);


    FILE *fp=fopen(path,"r");


    if(!fp)
        return -1;



    char line[256];


    *r=0;
    *w=0;


    while(fgets(line,sizeof(line),fp))
    {

        if(strncmp(line,
            "read_bytes:",
            11)==0)
        {
            sscanf(line+11,"%llu",r);
        }



        if(strncmp(line,
            "write_bytes:",
            12)==0)
        {
            sscanf(line+12,"%llu",w);
        }

    }


    fclose(fp);

    return 0;
}





void get_name(
int pid,
char *name)
{

    char path[128];

    sprintf(path,
    "/proc/%d/comm",
    pid);


    FILE *fp=fopen(path,"r");


    if(fp)
    {

        fgets(name,64,fp);

        name[strcspn(name,"\n")]=0;

        fclose(fp);

    }
    else
    {
        strcpy(name,"?");
    }

}







int scan_proc(
ProcStat *list)
{

    DIR *dir;

    struct dirent *ent;


    int count=0;


    dir=opendir("/proc");


    if(!dir)
        return 0;



    while((ent=readdir(dir)))
    {

        if(!isdigit(ent->d_name[0]))
            continue;



        int pid=atoi(ent->d_name);



        if(pid<=0)
            continue;



        unsigned long long r,w;



        if(read_proc_io(pid,&r,&w)!=0)
            continue;



        list[count].pid=pid;

        list[count].read_bytes=r;

        list[count].write_bytes=w;


        get_name(pid,
        list[count].name);


        count++;


        if(count>=MAX_PROC)
            break;

    }


    closedir(dir);


    return count;

}






int find_old(
ProcStat *old,
int n,
int pid)
{

    int i;


    for(i=0;i<n;i++)
    {
        if(old[i].pid==pid)
            return i;
    }


    return -1;
}







int cmp_write(
const void *a,
const void *b)
{

    ProcStat *x=(ProcStat *)a;
    ProcStat *y=(ProcStat *)b;


    if(y->write_rate >
       x->write_rate)
        return 1;


    if(y->write_rate <
       x->write_rate)
        return -1;


    return 0;

}






int main(int argc,char **argv)
{


    if(argc!=2)
    {
        printf(
        "usage: %s sda\n",
        argv[0]);

        return 0;
    }


    char disk[64];

    strcpy(disk,argv[1]);



    ProcStat *old_proc;
    ProcStat *new_proc;



    old_proc=
    calloc(MAX_PROC,sizeof(ProcStat));


    new_proc=
    calloc(MAX_PROC,sizeof(ProcStat));



    if(!old_proc ||
       !new_proc)
    {
        perror("calloc");

        return -1;
    }



    DiskStat old_disk;
    DiskStat new_disk;



    read_diskstat(
        disk,
        &old_disk);



    int old_num=
        scan_proc(old_proc);




    while(1)
    {


        sleep(1);



        read_diskstat(
            disk,
            &new_disk);



        int new_num=
            scan_proc(new_proc);



        printf("\033[2J");



        printf(
        "DISK %s\n\n",
        disk);



        unsigned long rd_ios=
        new_disk.read_ios-
        old_disk.read_ios;



        unsigned long wr_ios=
        new_disk.write_ios-
        old_disk.write_ios;



        unsigned long rd_kb=
        (new_disk.read_sectors-
        old_disk.read_sectors)/2;



        unsigned long wr_kb=
        (new_disk.write_sectors-
        old_disk.write_sectors)/2;



        printf(
        "READ : %lu KB/s  IOPS=%lu\n",
        rd_kb,
        rd_ios);



        printf(
        "WRITE: %lu KB/s  IOPS=%lu\n",
        wr_kb,
        wr_ios);



        if(rd_ios+wr_ios)
        {

            printf(
            "AVG IO SIZE: %lu KB\n",
            (rd_kb+wr_kb)/
            (rd_ios+wr_ios));

        }



        printf(
        "UTIL: %lu%%\n\n",
        new_disk.io_ticks-
        old_disk.io_ticks);



        int i;


        for(i=0;i<new_num;i++)
        {

            int pos=
            find_old(
                old_proc,
                old_num,
                new_proc[i].pid);



            if(pos>=0)
            {

                new_proc[i].read_rate=
                new_proc[i].read_bytes-
                old_proc[pos].read_bytes;



                new_proc[i].write_rate=
                new_proc[i].write_bytes-
                old_proc[pos].write_bytes;

            }

        }



        qsort(
            new_proc,
            new_num,
            sizeof(ProcStat),
            cmp_write);



        printf(
        "TOP WRITE PROCESS\n");


        printf(
        "%-8s %-20s %-12s\n",
        "PID",
        "COMMAND",
        "KB/s");



        int show=0;


        for(i=0;
            i<new_num && show<TOP;
            i++)
        {

            if(new_proc[i].write_rate)
            {

                printf(
                "%-8d %-20s %-12llu\n",
                new_proc[i].pid,
                new_proc[i].name,
                new_proc[i].write_rate/1024);


                show++;

            }

        }



        memcpy(
            old_proc,
            new_proc,
            sizeof(ProcStat)*new_num);



        old_num=new_num;


        old_disk=new_disk;

    }



    free(old_proc);
    free(new_proc);


    return 0;

}

 

 

image

 

 

image

 

ps -eLo pid,tid,stat,wchan:40 --no-headers |
while read pid tid stat wchan; do
    comm=$(cat /proc/$pid/comm 2>/dev/null)
    [ -z "$comm" ] && continue

    # xxx/数字 -> xxx
    case "$comm" in
        */[0-9]*)
            base="${comm%/*}"
            suffix="${comm##*/}"

            case "$suffix" in
                ''|*[!0-9]*)
                    ;;
                *)
                    comm="$base"
                    ;;
            esac
            ;;
    esac

    printf '%s|%s|%s\n' "$comm" "${stat:0:1}" "$wchan"
done |
awk -F'|' '
{
    cnt[$1,$2,$3]++
}
END {
    for (k in cnt) {
        split(k,a,SUBSEP)
        printf "%s|%s|%s|%d\n", a[1],a[2],a[3],cnt[k]
    }
}' |
sort -t'|' -k4,4nr -k1,1 -k2,2 -k3,3 |
awk -F'|' '
BEGIN {
    last=""

    printf "%-40s %-5s %-40s %10s\n",
           "COMMAND","STAT","WCHAN","THREADS"

    printf "%-40s %-5s %-40s %10s\n",
           "----------------------------------------",
           "-----",
           "----------------------------------------",
           "----------"
}
{
    if ($1 != last) {
        if (last != "")
            printf "\n"
        last=$1
    }

    printf "%-40s %-5s %-40s %10d\n",
           $1,$2,$3,$4
}'

　　

image

 

ps -eL -o pid,tid,ppid,state,wchan:30,comm,cmd --no-headers | awk '$4=="R" || $4=="D"'

image

 

io分析

Linux 硬盘 IO 平均服务时间分析与内核级验证

1. 问题现象

通过 iostat 查看 /dev/sdb，发现硬盘平均服务时间约：

2.6 ms

为了进一步从 Linux 内核 Block Layer 验证实际 IO 延迟，又采用两种方式进行分析：

方法一：blktrace + btt

sudo blktrace -d /dev/sdb -o sdb

sudo btt \
    -i sdb.blktrace.* \
    -X > sdb_avg_latency_raw.txt

随后使用 Python 对 btt 输出进行分析：

Analysis saved to sdb_avg_latency_analysis.txt

Average Service Time: 64.982 ms
Maximum Service Time: 522.675 ms

结果与 iostat 的：

Average Service Time ≈ 2.6 ms

存在明显差异。

2. 需要首先明确：几个时间不是同一个概念

Linux Block Layer 中，一个 IO 请求大致经历：

应用程序
   |
   v
文件系统
   |
   v
Block Layer
   |
   | Q
   v
Request Queue
   |
   | D / Issue
   v
设备驱动 / HBA
   |
   v
磁盘 / RAID / SAN
   |
   | C
   v
Complete

因此可以拆成：

Q -------------------------------> C
|                                  |
|<--------- Q2C ------------------>|
         |
         D
         |
         |<------ D2C ------------>|

其中：

指标含义
Q Request Queue
D Dispatch / Issue
C Complete
Q2D 请求进入队列后等待 Dispatch 的时间
D2C Dispatch 到 Complete 的时间
Q2C 从 Queue 到 Complete 的总时间

因此：

不能直接把任意一个 btt/Python 算出来的时间称为“硬盘物理服务时间”。

3. iostat 的 2.6 ms

例如：

iostat -x 1

可能看到：

Device            r/s    w/s    await    avgqu-sz    %util
sdb               ...    ...     2.60       ...       ...

其中 await 是从 IO 请求进入 Block IO 路径到完成所经历的平均时间。

它并不等价于：

磁盘盘片实际寻道时间

也不单纯等价于：

device D2C

所以需要结合 Block Layer trace 进一步确认。

4. 使用 blktrace 获取内核 Block Layer Trace

4.1 开始采集

针对 /dev/sdb：

sudo blktrace -d /dev/sdb -o sdb

采集过程中保持业务 IO。

例如：

iostat -x 1

观察：

sdb

采集完成后停止 blktrace。

4.2 使用 btt 分析

执行：

sudo btt \
    -i sdb.blktrace.* \
    -X > sdb_avg_latency_raw.txt

查看：

less sdb_avg_latency_raw.txt

重点关注：

Q2C
Q2D
D2C

5. 为什么 Python 得到 64.982 ms

Python 当前分析结果：

Analysis saved to sdb_avg_latency_analysis.txt

Average Service Time: 64.982 ms
Maximum Service Time: 522.675 ms

这个结果首先需要确认 Python 使用的是哪个时间字段。

例如，如果计算的是：

Q → C

那么：

Average Service Time

实际上更准确应该叫：

Average Request Latency

或者：

Average Q2C Latency

而不是直接叫：

Average Disk Service Time

因为：

Q2C
=
Queue Wait
+
Device/Driver Processing
+
Completion

6. 正确的分析方法

应该把时间拆开：

Q → D
D → C
Q → C

分别计算：

Q2D

Queue Wait

代表：

IO 在 Block Layer / Request Queue 中等待

D2C

Service / Device Latency

代表：

Request 被 Dispatch 后
直到 Complete

Q2C

Total Request Latency

代表：

IO 从进入 Block Layer
到完成的整个时间

7. 两种典型情况

情况一：Q2C 很高，但是 D2C 很低

例如：

iostat await    = 2.6 ms

Q2C             = 65 ms
D2C             = 2.6 ms
Q2D             = 62 ms

那么：

65 ms
+-------------------------------+
| Queue Wait       | Device     |
| ~62 ms           | ~2.6 ms    |
+-------------------------------+
                  D            C

此时不能认为：

磁盘平均服务时间 65 ms。

更准确的结论是：

IO 主要耗时在 Block Layer 请求排队，而不是设备实际处理。

需要进一步检查：

iostat -x 1

重点：

avgqu-sz
await
%util

以及：

cat /sys/block/sdb/queue/nr_requests

8. 情况二：Q2C 和 D2C 都接近 65 ms

例如：

iostat await    = 2.6 ms

Q2C             = 65 ms
D2C             = 64 ms

这种情况就明显异常。

说明 IO 已经进入设备处理阶段，但：

D → C

仍然需要几十毫秒。

此时需要继续向下排查：

/dev/sdb
    |
    v
Block Layer
    |
    v
Device Driver
    |
    v
HBA
    |
    v
RAID
    |
    v
SAN / NAS / Storage Backend

如果是虚拟机，还需要增加：

Guest OS
    |
    v
virtio / SCSI
    |
    v
QEMU
    |
    v
Host Block Layer
    |
    v
Backend Storage

9. 最大 522.675 ms 的意义

当前 Python 得到：

Average Service Time : 64.982 ms
Maximum Service Time : 522.675 ms

最大值达到：

522.675 ms

比平均值高很多。

因此不能只看：

Average

必须进一步统计：

P50
P90
P95
P99
P99.9
MAX

因为平均值可能掩盖少量严重慢 IO。

例如：

P50    2.5 ms
P95    5 ms
P99    30 ms
MAX    522 ms

与：

P50    60 ms
P95    100 ms
P99    200 ms
MAX    522 ms

完全是两种问题。

10. 使用 perf 从内核 Tracepoint 再验证

除了 blktrace，可以直接使用 Linux perf 的 Block Layer tracepoint。

采集：

sudo perf record \
    -e block:block_rq_issue,block:block_rq_complete \
    -a \
    -o perf.data

采集完成后：

sudo perf script \
    -i perf.data > perf_events.txt

然后 Python 分析：

block_rq_issue
        |
        | request ID
        |
        v
block_rq_complete

计算：

Latency =
complete_timestamp -
issue_timestamp

这可以直接得到：

Request Issue → Complete

延迟。

11. perf 分析的关键

不能简单按照：

issue[0] -> complete[0]
issue[1] -> complete[1]

进行匹配。

因为真实 Block IO 是并发的：

issue A
issue B
issue C

complete B
complete A
complete C

所以 Python 必须根据 request 的唯一标识进行关联。

至少需要结合：

request ID
sector
bytes
operation
timestamp

进行匹配。

否则高并发 IO 环境下可能得到错误的平均服务时间。

12. 推荐的 Python 输出

最终分析结果建议统一输出：

===== BLOCK IO LATENCY =====

Device       : /dev/sdb

IO Count     : 100000

Q2C:
    Average  : 2.60 ms
    P50      : 2.10 ms
    P95      : 4.20 ms
    P99      : 8.60 ms
    P99.9    : 35.20 ms
    Max      : 522.67 ms

Q2D:
    Average  : 0.30 ms
    P50      : 0.10 ms
    P95      : 0.80 ms
    P99      : 2.10 ms
    Max      : 60.00 ms

D2C:
    Average  : 2.30 ms
    P50      : 2.00 ms
    P95      : 3.80 ms
    P99      : 7.90 ms
    Max      : 500.00 ms

这样才能明确：

Q2C = Q2D + D2C

大致判断：

Q2D 高
    ↓
队列 / 调度 / IO 堵塞

D2C 高
    ↓
设备 / 驱动 / RAID / SAN / 后端存储

P99 / MAX 高
    ↓
存在长尾 IO

13. 最终建议的验证链路

针对当前：

iostat
Average = 2.6 ms

Python
Average = 64.982 ms
Maximum = 522.675 ms

建议按照下面顺序验证：

                 /dev/sdb
                    |
                    v
              iostat -x 1
                    |
          +---------+---------+
          |                   |
        await              avgqu-sz
          |                   |
          +---------+---------+
                    |
                    v
             blktrace / btt
                    |
          +---------+---------+
          |         |         |
         Q2D       D2C       Q2C
          |         |         |
          +---------+---------+
                    |
                    v
             perf tracepoint
                    |
          issue → complete
                    |
                    v
               Python
                    |
        +-----------+-----------+
        |           |           |
       P50         P99         MAX

14. 当前结论

目前仅凭：

iostat = 2.6 ms
blktrace/Python = 64.982 ms
MAX = 522.675 ms

还不能得出“硬盘实际平均服务时间是 64.982 ms”的结论。

首先要确认 Python 计算的到底是：

Q2C

还是：

D2C

这是当前问题的核心。

判断标准

D2C ≈ 2.6 ms
Q2C ≈ 65 ms

→ 主要是排队/调度等待。

D2C ≈ 65 ms
Q2C ≈ 65 ms

→ 主要是设备/驱动/存储后端处理慢。

D2C ≈ 2.6 ms
P99/MAX 很高

→ 平均 IO 正常，但存在明显的长尾 IO。

因此，下一步最关键的是把 sdb_avg_latency_raw.txt 中的 Q2D、D2C、Q2C 三项拿出来，同时用 perf 的 block_rq_issue → block_rq_complete 做交叉验证。这样才能确定这 64.982 ms 到底发生在 Linux IO 队列，还是发生在真正的设备/存储服务阶段。

posted on 2026-08-25 11:38  小镇-做题家  阅读(3)  评论(0)    收藏  举报

导航