Blog 透过bcc来观察程序io慢的问题

透过bcc来观察程序io慢的问题

Open jason--liu opened this issue 3 years ago • 0 comments

如下的测试代码

#include <stdio.h>
#include <stdlib.h>
#include <string.h>
#include <fcntl.h>
#include <unistd.h>
#include <time.h>

#define NSEC_PER_SEC 1000000000UL

static unsigned long long get_time_ns(void)
{
    struct timespec ts;

    clock_gettime (CLOCK_MONOTONIC, &ts);
    return ts.tv_sec*NSEC_PER_SEC+ts.tv_nsec;
}

int main (void)
{
    const char *msg="hello all\n";
    unsigned long long start;
    int fd,sz,msg_len;

    fd=open("./foo.txt", O_WRONLY|O_CREAT|O_TRUNC,0644);
    if(fd<0){
        perror("open");
        return -1;
    }

    msg_len=strlen(msg);
    while(1){
        start=get_time_ns();

        sz=write(fd,msg,msg_len);

        if(sz!=msg_len){
            perror("write");
        }
        if(fsync(fd)<0){
            perror("fsync");
        }

        printf("delta: %fms\n", (get_time_ns()-start)/1000000.0);
        sleep(1);
    }
    close(fd);
}

计算fsync和write的时间差，正常情况下，时延很小。

delta: 1.491949ms
delta: 1.980143ms
delta: 1.003565ms
delta: 1.082275ms
delta: 1.302799ms
delta: 1.374948ms

现在，我们来搞点事情，利用bcc工具的inject。

sudo inject-bpfcc kmalloc 'ext4_init_io_end(struct inode *inode, gfp_t flags) ({u32 pid=bpf_get_current_pid_tgid();pid==22999;})'

再来看下时间差的打印输出，

delta: 3026.751302ms
delta: 3032.068533ms
delta: 3032.143192ms
delta: 3027.712298ms
delta: 3044.315558ms
delta: 3035.296457ms
delta: 2579.914649ms
delta: 3035.437960ms
delta: 1752.364492ms

明显变慢了非常多，如果我们想排查哪里慢，该怎么办呢？

首先，我们抓取下block层和io调度器相关延时分布，使用biolatency

Tracing block device I/O... Hit Ctrl-C to end.
^C
     usecs               : count     distribution
         0 -> 1          : 0        |                                        |
         2 -> 3          : 0        |                                        |
         4 -> 7          : 0        |                                        |
         8 -> 15         : 0        |                                        |
        16 -> 31         : 0        |                                        |
        32 -> 63         : 65       |*******                                 |
        64 -> 127        : 204      |**********************                  |
       128 -> 255        : 363      |****************************************|
       256 -> 511        : 228      |*************************               |

可以发现block层和io调度相关并不慢。

如果block层不慢，那么会不会是文件系统层慢呢？可以使用ext4slower看下。

TIME     COMM           PID    T BYTES   OFF_KB   LAT(ms) FILENAME
13:58:23 a.out          22999  S 0       0        3040.04 foo.txt
13:58:27 a.out          22999  S 0       0        3035.43 foo.txt
13:58:31 a.out          22999  S 0       0        3047.49 foo.txt
13:58:35 a.out          22999  S 0       0        3027.56 foo.txt
13:58:39 a.out          22999  S 0       0        3051.87 foo.txt
13:58:43 a.out          22999  S 0       0        2532.39 foo.txt

ext4slower默认trace超过10ms的IO，从上面可以看到在文件系统层的确发现了慢IO

另外，从ps命令看到a.out正在D state，说明正在等什么重要资源。可以通过sudo offcputime-bpfcc -p 22999 -K查看进程在等什么。

    b'finish_task_switch'
    b'schedule'
    b'schedule_timeout'
    b'io_schedule_timeout'
    b'congestion_wait'
    b'do_writepages'
    b'__filemap_fdatawrite_range'
    b'file_write_and_wait_range'
    b'ext4_sync_file'
    b'vfs_fsync_range'
    b'do_fsync'
    b'__x64_sys_fsync'
    b'do_syscall_64'
    b'entry_SYSCALL_64_after_hwframe'

可以看到在do_writepages里面拥塞等待了；结合do_writepage代码看下。

int do_writepages(struct address_space *mapping, struct writeback_control *wbc)
{
	int ret;

	if (wbc->nr_to_write <= 0)
		return 0;
	while (1) {
		if (mapping->a_ops->writepages)
			ret = mapping->a_ops->writepages(mapping, wbc);
		else
			ret = generic_writepages(mapping, wbc);
		if ((ret != -ENOMEM) || (wbc->sync_mode != WB_SYNC_ALL))  //说明这里条件不满足，没有break
			break;
		cond_resched();    // 这里拥塞等待，并把进程设置为D state
		congestion_wait(BLK_RW_ASYNC, HZ/50);
	}
	return ret;
}

可以通过bcc的trace工具来确认下。 sudo trace-bpfcc 'r::ext4_writepages "ret=%d" retval'

 PID     TID     COMM            FUNC             -
22999   22999   a.out           ext4_writepages  ret=-12
22999   22999   a.out           ext4_writepages  ret=-12
22999   22999   a.out           ext4_writepages  ret=-12
22999   22999   a.out           ext4_writepages  ret=-12
22999   22999   a.out           ext4_writepages  ret=-12
22999   22999   a.out           ext4_writepages  ret=-12
22999   22999   a.out           ext4_writepages  ret=-12
22999   22999   a.out           ext4_writepages  ret=-12
22999   22999   a.out           ext4_writepages  ret=-12
23015   23031   single          ext4_writepages  ret=0
22999   22999   a.out           ext4_writepages  ret=0

可以看到的确返回了-12，即ENOMEM；再来看下sync_mode

sudo trace-bpfcc 't:ext4:ext4_writepages "sync_mode=%d" args->sync_mode'
PID     TID     COMM            FUNC             -
22999   22999   a.out           ext4_writepages  sync_mode=1
22999   22999   a.out           ext4_writepages  sync_mode=1
22999   22999   a.out           ext4_writepages  sync_mode=1
22999   22999   a.out           ext4_writepages  sync_mode=1
...

这里需要对页面回写流程有点背景，才知道哪里有event，所以if条件的两个条件都满足了，然后就进入拥塞等待了。

到这里，为什么会出现ENOMEM，聪明的你可能已经猜到了，就是我们一开始搞的小动作。导致在ext4_writepage里返回 ENOMEM.

另外你可能有个疑问，进程既然是D了，那么应该无限等下面，那么为什么文件里面还是有内容呢？其实这是因为内核线程在定期flush cache，周期性回写文件内容。

	if (wbc->nr_to_write <= 0)
		return 0;

do_writepages里如果没有需要写的脏页，直接返回。如何确定有内核线程在周期性回写呢？ sudo trace-bpfcc 'do_writepages "mapping=%lx", args1' -K

22999   22999   a.out           do_writepages    mapping=0xffff9ca8145bc298
        b'do_writepages+0x1 [kernel]'
        b'file_write_and_wait_range+0x74 [kernel]'
        b'ext4_sync_file+0xf5 [kernel]'
        b'vfs_fsync_range+0x49 [kernel]'
        b'do_fsync+0x3d [kernel]'
        b'__x64_sys_fsync+0x14 [kernel]'
        b'do_syscall_64+0x49 [kernel]'
        b'entry_SYSCALL_64_after_hwframe+0x44 [kernel]'

21541   21541   kworker/u8:1    do_writepages    mapping=0xffff9ca8145bc298
        b'do_writepages+0x1 [kernel]'
        b'writeback_sb_inodes+0x22d [kernel]'
        b'__writeback_inodes_wb+0x56 [kernel]'
        b'wb_writeback+0x20c [kernel]'
        b'wb_workfn+0x388 [kernel]'
        b'process_one_work+0x1e8 [kernel]'
        b'worker_thread+0x4d [kernel]'
        b'kthread+0x114 [kernel]'
        b'ret_from_fork+0x22 [kernel]'

可以看到kworker的maping和a.out的mapping是一个，说明他们回写的是一个脏页。

当我们把inject停掉后，发现程序io恢复正常了。

delta: 2579.914649ms
delta: 3035.437960ms
delta: 1752.364492ms
delta: 1.491949ms
delta: 1.980143ms
delta: 1.003565ms
delta: 1.082275ms
delta: 1.302799ms
delta: 1.374948ms

小结: bcc提供了很多实用的工具，本例只用到了几种，个人感觉使用起来很方便，特别是inject有点厉害，能直接修改函数返回值，需要多多使用，才能熟练掌握。

bcc官网: https://github.com/iovisor/bcc

Jun 07 '21 11:06 jason--liu

Blog Blog copied to clipboard

透过bcc来观察程序io慢的问题

Blog
Blog copied to clipboard