定位NFS同步写数据时间慢的问题

#include<linux/fs.h>
#include<linux/types.h>
#include<linux/uio.h>
BEGIN {
    printf("Tracing nfs_file_write execution time... Hit Ctrl-C to end.\n");
}

kprobe:nfs_file_write
{
    $iocb = (struct kiocb *)arg0;
    $file = $iocb->ki_filp;
    $dentry = $file->f_path.dentry;
    $from = (struct iov_iter *)arg1;
    
    
    @filename_ptr[tid] = $dentry->d_name.name;  // 存储文件名指针
    @inode[tid] = $file->f_inode->i_ino;        // 存储 inode
    @write_offset = $iocb->ki_pos;
    @write_length = $from->count;
    @start_time[tid] = nsecs;                   // 记录起始时间
    printf("%s, name:%s, inode:%d, len:%d, offset:%d, time:%llu\n",
    probe,str($dentry->d_name.name),$file->f_inode->i_ino,@write_length,@write_offset,nsecs);
}

kretprobe:nfs_file_write
{
    $duration = nsecs - @start_time[tid];
    $name_ptr = @filename_ptr[tid];
    $ino = @inode[tid];
    
    printf("nfs_file_write - File: %-20s Inode: %-8lu Duration: %-12d ns\n",
        str($name_ptr), $ino, $duration);

    delete(@filename_ptr[tid]);
    delete(@inode[tid]);
    delete(@start_time[tid]);
}

END {
    clear(@filename_ptr);
    clear(@inode);
    clear(@start_time);
}

NFS 的写操作本质上是客户端与服务器之间的 RPC（Remote Procedure Call）通信过程。当你在客户端调用 nfs_file_write 时，NFS 客户端会将操作封装为 RPC 请求，通过 TCP/IP 网络发送到服务器，服务器处理后再返回响应。整个过程涉及多个阶段，任何一个阶段的延迟都可能导致整体写入性能下降。

需要统计4.19内核上同步写操作各个阶段所花的时间，nfsv3挂载选项:

(rw,relatime,sync,vers=3,rsize=262144,wsize=262144,namlen=255,acregmin=0,acregmax=0,acdirmin=0,acdirmax=0,hard,noac,proto=tcp,timeo=600,retrans=2,sec=sys,mountaddr=xx.xx.xx.xx,mountvers=3,mountport=2050,mountproto=tcp,local_lock=none,addr=xx.xx.xx.xx)

NFS 客户端对 sync 挂载选项的处理方式与某些其他文件系统不同（参见 mount(8) 中对通用 sync 与 async 挂载选项的描述）。如果既未指定 sync，也未指定 async（或显式指定了 async），NFS 客户端会将应用程序的写入操作延迟发送到服务器，直到发生以下任一情况：

换言之，在正常情况下，应用程序写入的数据可能不会立即出现在托管该文件的服务器上。

如果在挂载点上指定了 sync 选项，则对该挂载点上的文件进行任何写操作的系统调用都会在返回用户空间之前，将数据刷新到服务器。这能在多个客户端之间提供更强的一致性保障，但会显著降低性能。

应用程序也可使用 O_SYNC 打开标志，在不使用 sync 挂载选项的情况下，对单个文件的写操作强制立即发送到服务器。

代码分析

write
  ksys_write
    vfs_write
      __vfs_write
        new_sync_write
          nfs_file_write
            generic_write_sync // 同步写执行到这里
              vfs_fsync_range
                nfs_file_fsync // file->f_op->fsync
                  filemap_write_and_wait_range
                    __filemap_fdatawrite_range
                      do_writepages
                        nfs_writepages
                          nfs_pageio_complete
                            nfs_pageio_doio
                              nfs_generic_pg_pgios
                                nfs_initiate_pgio
                                  .rpc_message = &msg,
                                  .flags = RPC_TASK_ASYNC // 异步rpc
                                  nfs_initiate_write // hdr->rw_ops->rw_initiate
                                    nfs3_proc_write_setup
                                      msg->rpc_proc = &nfs3_procedures[NFS3PROC_WRITE]
                                  rpc_run_task
                                    rpc_new_task
                                      rpc_init_task
                                    rpc_task_set_rpc_message // 设置tk_msg的值，NFS3PROC_WRITE和task关联上了
                                    rpc_call_start
                                      task->tk_action = call_start
                                    rpc_execute

分析代码可知：在使用nfs sync操作的时候，nfs调用rpc层有一个属性是设置结构体msg下的rpc_proc的值，然后再经过rpc_task_set_rpc_message将tk_msg设置，这样在过滤写操作的时候，就可以通过判断tk_msg->msg->rpc_proc是否等于NFS3PROC_WRITE,来过滤其他操作，只保留写操作。

对函数进行修改后，最后运行脚本bpftrace nfs_write.bt,然后用nfs挂载文件，进行nfs的写入，脚本会打印出如下类似的信息。下面是两次nfs同步写操作时间慢的打印信息。然后运行trace_nfs_write.sh就可以将time数据转换成我们可读的时间戳。与wireshark的XID进行时间对比。

kprobe:nfs_file_write, name:xxxx inode:1697123520 len:354    offset:132777   time:39290423881392412
call_transmit start - XID:0xedc0ad03 OP:GETATTR      time:39290423881405002
call_transmit start - XID:0xedc0ad03 OP:GETATTR      time:39290423982453372
call_transmit start - XID:0xeec0ad03 OP:WRITE        time:39290423982494112
call_transmit start - XID:0xeec0ad03 OP:WRITE        time:39290424084932650
nfs_file_write - File: xxxx Inode: 1697123520 Duration: 0 s 203 ms 592 μs 488 ns

kprobe:nfs_file_write, name:xxxx inode:1697123520 len:353    offset:140530   time:39290435940709314
call_transmit start - XID:0xfac1ad03 OP:GETATTR      time:39290435940720794
call_transmit start - XID:0xfac1ad03 OP:GETATTR      time:39290436041499632
call_transmit start - XID:0xfbc1ad03 OP:WRITE        time:39290436041541542
call_transmit start - XID:0xfbc1ad03 OP:WRITE        time:39290436149645344
nfs_file_write - File: xxxx Inode: 1697123520 Duration: 0 s 209 ms 7 μs 571 ns

上述部分打印的信息，就可以看到RPC层的XID、OP；文件的inode 、长度、偏移量，以及调用时间。 - RPC的XID：事务唯一标识符，用于关联同一 RPC 请求的所有事件 - RPC的OP：RPC 操作类型，区分不同操作类型的性能特征

call_transmit -> call_decode : 104ms
nfs_file_write -> rpc_execute : 100ms

耗时请求高是因为需要先调去nfs_file_write中的getattr，去获取文件属性，然后继续去查看nfs_file_write的调用栈:

nfs_file_write
  nfs_revalidate_file_size
    __nfs_revalidate_inode
      NFS_PROTO(inode)->getattr //这里调用了getattr
  nfs_revalidate_mapping
    __nfs_revalidate_inode
      NFS_PROTO(inode)->getattr //这里调用了getattr
  generic_write_sync // 同步写执行到这里
    vfs_fsync_range
      nfs_file_fsync // file->f_op->fsync
        filemap_write_and_wait_range
          __filemap_fdatawrite_range
            do_writepages
              nfs_writepages
                nfs_pageio_complete
                  nfs_pageio_doio
                    nfs_generic_pg_pgios
                      nfs_initiate_pgio
                        .rpc_message = &msg,
                        .flags = RPC_TASK_ASYNC // 异步rpc
                        nfs_initiate_write // hdr->rw_ops->rw_initiate

根据数据分析得出结论：用户态写文件时间长是由于nfs服务器回复慢导致的。

定位NFS同步写数据时间慢的问题

定位NFS同步写数据时间慢的问题

nfs_write.bt脚本代码

代码分析