btrfs 写入操作在附加到文件时挂起

btrfs 写入操作在附加到文件时挂起

当我按顺序写入大型 (70 TiB) btrfs 文件系统上的文件时,我注意到某些东西导致写入阻塞时间延长 (从几秒到几分钟)。这充其量是不方便的,并且在某些情况下会导致应用程序超时。

我的理解是,btrfs 提交应该在后台进行,不会阻止我的写入,这也是我在大多数情况下连续写入现有文件而没有为其分配新块时看到的情况。如果我以高数据速率写入和扩展文件,它很快就会变得混乱。

我的测试用例很简单dd if=/dev/zero of=/mnt/btrfs/subvolume/testfile,以 150 MB/s 的速度开始写入,主要是弄脏主机页面缓存中的块。文件系统在这里有一些后台活动,这导致了此设备收集的统计数据中出现的读取iostat -xdmt 1

Time:       rrqm/s wrqm/s     r/s     w/s    rMB/s    wMB/s avgrq-sz avgqu-sz   await  svctm  %util
01:09:59 PM 0.00     0.00 3761.00    0.00    14.69     0.00     8.00     0.38    0.10   0.10  38.00
01:10:00 PM 0.00     0.00 2868.00    0.00    11.20     0.00     8.00     0.42    0.15   0.15  41.60
01:10:01 PM 0.00     0.00 4002.00    0.00    15.63     0.00     8.00     0.43    0.11   0.11  42.80
01:10:02 PM 0.00     0.00 3331.00    0.00    13.01     0.00     8.00     0.54    0.16   0.16  54.40
01:10:03 PM 0.00     0.00 2674.00    0.00    10.45     0.00     8.00     0.62    0.23   0.23  62.00
01:10:04 PM 0.00     0.00 2771.00    0.00    10.82     0.00     8.00     0.59    0.21   0.21  58.80
01:10:05 PM 0.00    12.00 3004.00 2744.00    11.73   264.09    98.28     5.80    1.01   0.09  50.80
01:10:06 PM 0.00    24.00 2661.00 1970.00    10.39    92.86    45.66    75.36   16.12   0.16  74.80
01:10:07 PM 0.00     0.00 1556.00  628.00     6.08   171.23   166.27     9.84    4.83   0.33  72.00
01:10:08 PM 0.00     0.00 1298.00    0.00     5.07     0.00     8.00     0.41    0.31   0.27  35.20

到目前为止,一切看起来都很好,01:10:05 的提交已导致约 500 MB 的数据被刷新到磁盘。然而,接下来发生了以下情况:

Time:       rrqm/s wrqm/s     r/s     w/s    rMB/s    wMB/s avgrq-sz avgqu-sz   await  svctm  %util
01:10:09 PM 0.00     0.00 1459.00  115.00     5.70    28.75    44.82     0.62    0.38   0.36  56.80
01:10:10 PM 0.00     8.00  268.00 6816.00     1.05   567.26   164.30   101.84   12.83   0.14  96.80
01:10:11 PM 0.00     4.00    4.00 5396.00     0.02   857.71   325.30   155.78   30.02   0.19 100.40
01:10:12 PM 0.00    16.00   10.00 3179.00     0.04   489.67   314.50   162.47   43.53   0.31 100.00
01:10:13 PM 0.00    13.00    6.00 2785.00     0.02   412.01   302.35   148.54   45.91   0.36 100.00
01:10:14 PM 0.00     8.00    0.00 2745.00     0.00   431.29   321.77   141.90   47.04   0.36 100.00
01:10:15 PM 0.00     9.00   16.00 4235.00     0.06   660.77   318.37   144.02   47.59   0.24 100.00
01:10:16 PM 0.00     8.00   11.00 2771.00     0.04   455.26   335.18   145.08   45.15   0.36 100.00
01:10:17 PM 0.00    18.00   17.00 2688.00     0.07   416.14   315.12   149.61   52.68   0.37 100.00
01:10:18 PM 0.00    15.00   32.00 4133.00     0.12   641.32   315.41   154.58   42.92   0.24 100.00
01:10:19 PM 0.00     3.00   23.00 1921.00     0.09   306.26   322.74   141.80   47.59   0.51 100.00
01:10:20 PM 0.00    10.00   13.00 3553.00     0.05   546.22   313.73   144.95   51.66   0.28 100.00
01:10:21 PM 0.00     6.00   24.00 4623.00     0.09   688.63   303.53   154.29   35.90   0.22 100.00
01:10:22 PM 0.00     8.00   61.00 10151.00     0.24   176.37    35.42   136.80   13.06   0.10 100.00
01:10:23 PM 0.00     0.00   22.00 9858.00     0.09    43.74     9.09   142.66   14.88   0.10 100.00
01:10:24 PM 0.00     0.00    4.00 14740.00     0.02    68.51     9.52   137.17    9.33   0.07 100.00
01:10:25 PM 0.00     0.00    4.00 9070.00     0.02    39.50     8.92   143.02   14.69   0.11 100.00
01:10:26 PM 0.00     0.00    6.00 10659.00     0.02    46.90     9.01   143.00   14.29   0.09 100.00
01:10:27 PM 0.00     0.00    8.00 13098.00     0.03    60.62     9.48   140.74   10.88   0.08 100.00
01:10:28 PM 0.00     0.00    7.00 10284.00     0.03    46.80     9.32   141.98   12.37   0.10 100.00
01:10:29 PM 0.00     0.00    8.00 8562.00     0.03    38.33     9.17   143.43   17.97   0.12 100.00
01:10:30 PM 0.00     0.00    7.00 10996.00     0.03    50.37     9.38   141.34   13.11   0.09 100.00
01:10:31 PM 0.00     0.00    6.00 12012.00     0.02    57.04     9.72   141.58   11.72   0.08 100.00
01:10:32 PM 0.00     0.00    7.00 12666.00     0.03    57.08     9.23   143.91   11.35   0.08 100.00
01:10:33 PM 0.00     0.00    7.00 7741.00     0.03    34.26     9.06   142.60   18.57   0.13 100.00
Time:       rrqm/s wrqm/s     r/s     w/s    rMB/s    wMB/s avgrq-sz avgqu-sz   await  svctm  %util
01:10:34 PM 0.00     0.00    3.00 7262.00     0.01    30.16     8.50   144.23   19.86   0.14 100.00
01:10:35 PM 0.00     0.00    7.00 6518.00     0.03    27.27     8.57   144.97   20.80   0.15 100.00
01:10:36 PM 0.00     0.00    5.00 4828.00     0.02    19.70     8.36   143.86   30.95   0.21 100.00
01:10:37 PM 0.00     0.00    0.00 7858.00     0.00    35.13     9.16   144.19   18.65   0.13 100.00
01:10:38 PM 0.00     0.00    4.00 11041.00     0.02    48.77     9.05   143.72   13.04   0.09 100.00
01:10:39 PM 0.00     0.00   11.00 8409.00     0.04    35.82     8.72   144.18   16.87   0.12 100.00
01:10:40 PM 0.00     0.00 1440.00 1206.00     5.62     5.09     8.29    33.14   14.05   0.29  77.20
01:10:41 PM 0.00     0.00 2464.00    0.00     9.62     0.00     8.00     0.60    0.24   0.24  59.60
01:10:42 PM 0.00     0.00 2230.00  950.00     8.71   259.55   172.77     9.96    1.99   0.18  58.40
01:10:43 PM 0.00     0.00   10.00 3031.00     0.04   827.06   557.02   143.37   47.04   0.33 100.00
01:10:44 PM 0.00     0.00    7.00 1918.00     0.03   523.48   556.96   144.06   73.96   0.52 100.40
01:10:45 PM 0.00     0.00    8.00 2206.00     0.03   601.99   556.89   143.66   64.11   0.45 100.00
01:10:46 PM 0.00     0.00   16.00 2286.00     0.06   623.87   555.09   141.53   61.57   0.43 100.00
01:10:47 PM 0.00     1.00  826.00  533.00     3.23   145.17   223.63    35.18   31.19   0.64  86.80
01:10:48 PM 0.00     0.00 2596.00    0.00    10.14     0.00     8.00     0.64    0.25   0.25  64.00
01:10:49 PM 0.00     0.00 1725.00  570.00     6.74   154.55   143.93     3.89    1.69   0.33  75.60

这相当于队列已满 30 秒,dd同时进程被阻塞。进程仍处于D(不间断的睡眠) 状态,持续整个区块持续时间。

就阻塞/延迟时间可能有很大差异而言,这并不像我希望的那样清晰地重现。这里发生了什么?我该如何解决阻塞问题?

环境

SLES 11 SP3。安装选项:/dev/sdb1 on /mnt/btrfs type btrfs (rw,noatime,thread_pool=16)。我nodatacow也尝试使用安装,但dd继续播放睡美人与我一起。

$ uname -a
Linux host-1 3.0.101-0.47.71-default #1 SMP Thu Nov 12 12:22:22 UTC 2015 (b5b212e) x86_64 x86_64 x86_64 GNU/Linux

# cat /sys/bus/scsi/devices/*/queue_depth
256
256
256

BTRFS 分布在一个 72 TiB 的磁盘上,该磁盘是 LSI MPT RAID(MegaRAID 2208,带 1 GB FBWC)的 RAID-60 VD,这不是我的根文件系统,不用于任何系统内部活动(交换、日志、转储等)。

该平台硬件是单 CPU E5-2620(无 NUMA),配备 64 GB RAM。

编辑

我的实际用例是 Windows 客户端通过 Samba (3.6.3) 将数据写入动态扩展的 vhdx(虚拟磁盘)文件,但其行为与 基本相同dd- 随着块写入 vhdx 虚拟磁盘,文件正在快速且连续地增长。它也会像dd

我对此做了一些额外的故障排除,重点关注D状态中的进程。在那里我注意到,许多与 btrfs 相关的内核线程D与 Samba 一起卡住了。由于我无法使用附加到内核线程,我尝试使用中输出strace的信息。这应该告诉我哪个函数导致进程/线程在 中等待:wchanpsD

while true; do ps -eo pid,stat,pcpu,nwchan,wchan=WIDE-WCHAN-COLUMN -o args | awk -v date="$(date +%r)" '$2 ~ /D/ {  print date " " $4 " " $5  " " $6 }'; sleep 0.2; done

实际操作如下。
这里,常规的 30 秒提交开始:

11:15:11 AM     /usr/sbin/smbd  lock_page
11:15:11 AM     [flush-btrfs-1] -
11:15:12 AM     /usr/sbin/smbd  lock_page
11:15:12 AM     [flush-btrfs-1] -
11:15:12 AM     [btrfs-endio-wri]       wait_on_page_lock
11:15:12 AM     /usr/sbin/smbd  lock_page
11:15:12 AM     [flush-btrfs-1] -
11:15:12 AM     [btrfs-submit-1]        get_request_wait
11:15:12 AM     /usr/sbin/smbd  lock_page
11:15:12 AM     /usr/sbin/smbd  lock_page
11:15:12 AM     [flush-btrfs-1] -
11:15:12 AM     [btrfs-submit-1]        get_request_wait
11:15:12 AM     [btrfs-transacti]       wait_on_page_lock
11:15:12 AM     /usr/sbin/smbd  lock_page
11:15:12 AM     [flush-btrfs-1] lock_page
11:15:13 AM     [btrfs-transacti]       wait_on_page_lock
11:15:13 AM     /usr/sbin/smbd  lock_page
11:15:13 AM     [flush-btrfs-1] lock_page
11:15:13 AM     [btrfs-transacti]       wait_on_page_lock
11:15:13 AM     /usr/sbin/smbd  lock_page
11:15:13 AM     [flush-btrfs-1] lock_page
11:15:13 AM     [btrfs-transacti]       wait_on_page_lock
11:15:13 AM     /usr/sbin/smbd  -
11:15:13 AM     [btrfs-transacti]       wait_on_page_lock
11:15:13 AM     /usr/sbin/smbd  lock_page
11:15:13 AM     [btrfs-transacti]       wait_on_page_lock
11:15:13 AM     /usr/sbin/smbd  lock_page

此时,它似乎已完成。iostat -xdmt运行确认 11:15:13 之后没有任何内容写入磁盘:

01/07/2016 11:15:11 AM
Device:         rrqm/s   wrqm/s     r/s     w/s    rMB/s    wMB/s avgrq-sz avgqu-sz   await  svctm  %util
sdb               0.00     0.00 3437.00    0.00    13.43     0.00     8.00     0.50    0.15   0.15  50.40
01/07/2016 11:15:12 AM
sdb               0.00     0.00 1056.00 4475.00     4.12  1221.39   453.78    58.13    9.59   0.16  87.60
01/07/2016 11:15:13 AM
sdb               0.00     0.00 1477.00 1082.00     5.77   293.28   239.33    55.36   23.63   0.36  91.20
01/07/2016 11:15:14 AM
sdb               0.00     0.00 2846.00    0.00    11.12     0.00     8.00     0.89    0.32   0.24  68.80
01/07/2016 11:15:15 AM
sdb               0.00     0.00 1591.00    0.00     6.21     0.00     8.00     0.64    0.40   0.34  54.40

然后,在 11:15:17 左右,写入过程被永久阻止,并且不再响应,直到 11:15:29 左右:

11:15:14 AM     /usr/sbin/smbd  -
11:15:14 AM     /usr/sbin/smbd  lock_page
11:15:14 AM     /usr/sbin/smbd  lock_page
11:15:14 AM     /usr/sbin/smbd  lock_page
11:15:15 AM     /usr/sbin/smbd  lock_page
11:15:15 AM     [btrfs-transacti]       wait_on_page_lock
11:15:15 AM     /usr/sbin/smbd  lock_page
11:15:16 AM     /usr/sbin/smbd  lock_page
11:15:16 AM     /usr/sbin/smbd  lock_page
11:15:17 AM     /usr/sbin/smbd  lock_page
11:15:17 AM     [btrfs-transacti]       get_request_wait
11:15:17 AM     /usr/sbin/smbd  get_request_wait
11:15:17 AM     [btrfs-transacti]       get_request_wait
11:15:17 AM     /usr/sbin/smbd  get_request_wait
11:15:17 AM     [btrfs-transacti]       get_request_wait
11:15:17 AM     /usr/sbin/smbd  lock_page
11:15:18 AM     [btrfs-transacti]       get_request_wait
11:15:18 AM     /usr/sbin/smbd  lock_page
11:15:18 AM     /usr/sbin/smbd  lock_page
11:15:18 AM     [btrfs-transacti]       get_request_wait
11:15:18 AM     /usr/sbin/smbd  lock_page
11:15:18 AM     [btrfs-transacti]       get_request_wait
11:15:18 AM     /usr/sbin/smbd  lock_page
11:15:18 AM     [btrfs-transacti]       get_request_wait
11:15:18 AM     /usr/sbin/smbd  lock_page
11:15:19 AM     [btrfs-transacti]       get_request_wait
11:15:19 AM     /usr/sbin/smbd  lock_page
11:15:19 AM     [btrfs-transacti]       get_request_wait
11:15:19 AM     /usr/sbin/smbd  lock_page
11:15:19 AM     [btrfs-transacti]       get_request_wait
11:15:19 AM     /usr/sbin/smbd  lock_page
11:15:19 AM     [btrfs-transacti]       get_request_wait
11:15:19 AM     /usr/sbin/smbd  lock_page
11:15:19 AM     [btrfs-transacti]       get_request_wait
11:15:19 AM     /usr/sbin/smbd  lock_page
11:15:20 AM     /usr/sbin/smbd  lock_page
11:15:20 AM     [btrfs-transacti]       get_request_wait
11:15:20 AM     /usr/sbin/smbd  lock_page
11:15:20 AM     [btrfs-transacti]       get_request_wait
11:15:20 AM     /usr/sbin/smbd  lock_page
11:15:20 AM     [btrfs-transacti]       get_request_wait
11:15:20 AM     /usr/sbin/smbd  lock_page
11:15:20 AM     [btrfs-transacti]       get_request_wait
11:15:20 AM     /usr/sbin/smbd  lock_page
11:15:21 AM     [btrfs-transacti]       get_request_wait
11:15:21 AM     /usr/sbin/smbd  lock_page
11:15:21 AM     [btrfs-transacti]       get_request_wait
11:15:21 AM     /usr/sbin/smbd  lock_page
11:15:21 AM     [btrfs-transacti]       get_request_wait
11:15:21 AM     /usr/sbin/smbd  lock_page
11:15:21 AM     [btrfs-transacti]       get_request_wait
11:15:21 AM     /usr/sbin/smbd  lock_page
11:15:22 AM     [btrfs-transacti]       get_request_wait
11:15:22 AM     /usr/sbin/smbd  lock_page
11:15:22 AM     [btrfs-transacti]       get_request_wait
11:15:22 AM     /usr/sbin/smbd  lock_page
11:15:22 AM     [btrfs-transacti]       get_request_wait
11:15:22 AM     /usr/sbin/smbd  lock_page
11:15:22 AM     [btrfs-transacti]       get_request_wait
11:15:22 AM     /usr/sbin/smbd  lock_page
11:15:22 AM     [btrfs-transacti]       get_request_wait
11:15:22 AM     /usr/sbin/smbd  lock_page
11:15:23 AM     [btrfs-transacti]       get_request_wait
11:15:23 AM     /usr/sbin/smbd  lock_page
11:15:23 AM     [btrfs-transacti]       get_request_wait
11:15:23 AM     /usr/sbin/smbd  lock_page
11:15:23 AM     [btrfs-transacti]       get_request_wait
11:15:23 AM     /usr/sbin/smbd  lock_page
11:15:23 AM     [btrfs-transacti]       get_request_wait
11:15:23 AM     /usr/sbin/smbd  lock_page
11:15:23 AM     [btrfs-transacti]       get_request_wait
11:15:23 AM     /usr/sbin/smbd  lock_page
11:15:24 AM     [btrfs-transacti]       get_request_wait
11:15:24 AM     /usr/sbin/smbd  lock_page
11:15:24 AM     [btrfs-transacti]       get_request_wait
11:15:24 AM     /usr/sbin/smbd  lock_page
11:15:24 AM     /usr/sbin/smbd  lock_page
11:15:24 AM     [btrfs-transacti]       get_request_wait
11:15:24 AM     /usr/sbin/smbd  get_request_wait
11:15:24 AM     [btrfs-transacti]       get_request_wait
11:15:24 AM     /usr/sbin/smbd  lock_page
11:15:25 AM     [btrfs-transacti]       get_request_wait
11:15:25 AM     /usr/sbin/smbd  lock_page
11:15:25 AM     [btrfs-transacti]       get_request_wait
11:15:25 AM     /usr/sbin/smbd  lock_page
11:15:25 AM     [btrfs-transacti]       get_request_wait
11:15:25 AM     /usr/sbin/smbd  lock_page
11:15:25 AM     [btrfs-transacti]       get_request_wait
11:15:25 AM     /usr/sbin/smbd  lock_page
11:15:26 AM     [btrfs-transacti]       get_request_wait
11:15:26 AM     /usr/sbin/smbd  lock_page
11:15:26 AM     [btrfs-transacti]       get_request_wait
11:15:26 AM     /usr/sbin/smbd  lock_page
11:15:26 AM     [btrfs-transacti]       get_request_wait
11:15:26 AM     /usr/sbin/smbd  lock_page
11:15:26 AM     [btrfs-transacti]       get_request_wait
11:15:26 AM     /usr/sbin/smbd  lock_page
11:15:26 AM     [btrfs-transacti]       get_request_wait
11:15:26 AM     /usr/sbin/smbd  lock_page
11:15:27 AM     [btrfs-transacti]       get_request_wait
11:15:27 AM     /usr/sbin/smbd  lock_page
11:15:27 AM     [btrfs-transacti]       get_request_wait
11:15:27 AM     /usr/sbin/smbd  lock_page
11:15:27 AM     [btrfs-transacti]       get_request_wait
11:15:27 AM     /usr/sbin/smbd  lock_page
11:15:27 AM     [btrfs-transacti]       get_request_wait
11:15:27 AM     /usr/sbin/smbd  lock_page
11:15:27 AM     [btrfs-transacti]       get_request_wait
11:15:27 AM     /usr/sbin/smbd  lock_page
11:15:28 AM     [btrfs-transacti]       get_request_wait
11:15:28 AM     /usr/sbin/smbd  lock_page
11:15:28 AM     [btrfs-transacti]       get_request_wait
11:15:28 AM     /usr/sbin/smbd  lock_page
11:15:28 AM     [btrfs-transacti]       get_request_wait
11:15:28 AM     /usr/sbin/smbd  lock_page
11:15:28 AM     [btrfs-transacti]       get_request_wait
11:15:28 AM     /usr/sbin/smbd  lock_page
11:15:29 AM     [btrfs-transacti]       get_request_wait
11:15:29 AM     /usr/sbin/smbd  lock_page
11:15:29 AM     [btrfs-transacti]       get_request_wait
11:15:29 AM     /usr/sbin/smbd  lock_page
11:15:29 AM     [btrfs-transacti]       get_request_wait
11:15:29 AM     /usr/sbin/smbd  lock_page
11:15:29 AM     [btrfs-transacti]       get_request_wait
11:15:29 AM     /usr/sbin/smbd  lock_page
11:15:29 AM     [btrfs-transacti]       get_request_wait
11:15:29 AM     /usr/sbin/smbd  lock_page
11:15:30 AM     /usr/sbin/smbd  lock_page
11:15:30 AM     /usr/sbin/smbd  lock_page
11:15:30 AM     /usr/sbin/smbd  lock_page
11:15:30 AM     /usr/sbin/smbd  lock_page

这在数据中反映iostats为具有高 avgqu-sz 的写入负载:

Device:         rrqm/s   wrqm/s     r/s     w/s    rMB/s    wMB/s avgrq-sz avgqu-sz   await  svctm  %util
11:15:16 AM
sdb               0.00     0.00 3865.00    0.00    15.10     0.00     8.00     0.46    0.12   0.11  43.20
11:15:17 AM
sdb               0.00     0.00  706.00 9021.00     2.76   116.05    25.01    62.22    6.13   0.10  95.60
11:15:18 AM
sdb               0.00     0.00   13.00 7344.00     0.05    32.70     9.12   141.22   19.35   0.14 100.00
11:15:19 AM
sdb               0.00     0.00   12.00 6219.00     0.05    25.79     8.49   142.56   22.29   0.16 100.00
11:15:20 AM
sdb               0.00     0.00   17.00 4987.00     0.07    20.30     8.34   144.62   29.01   0.20 100.00
11:15:21 AM
sdb               0.00     0.00    2.00 5965.00     0.01    24.98     8.58   143.66   24.63   0.17 100.00
11:15:22 AM
sdb               0.00     0.00    0.00 8145.00     0.00    39.87    10.03   143.13   17.25   0.12 100.00
11:15:23 AM
sdb               0.00     0.00    3.00 4371.00     0.01    18.66     8.74   143.18   32.77   0.23 100.00
11:15:24 AM
sdb               0.00     0.00    2.00 4142.00     0.01    17.32     8.56   144.14   34.99   0.24 100.00
11:15:25 AM
sdb               0.00     0.00    4.00 5014.00     0.02    20.66     8.44   142.62   28.58   0.20 100.00
11:15:26 AM
sdb               0.00     0.00    2.00 4321.00     0.01    17.68     8.38   146.49   33.98   0.23 100.00
11:15:27 AM
sdb               0.00     0.00    0.00 5741.00     0.00    25.59     9.13   145.61   25.26   0.17 100.00
11:15:28 AM
sdb               0.00     0.00    6.00 6775.00     0.02    28.79     8.70   145.66   21.69   0.15 100.00
11:15:29 AM
sdb               0.00     0.00    8.00 9546.00     0.03    43.75     9.38   141.55   14.60   0.10 100.00
11:15:30 AM
sdb               0.00     0.00  544.00 5247.00     2.12    24.03     9.25    73.91   13.26   0.16  92.00
11:15:31 AM
sdb               0.00     0.00 2294.00    0.00     8.96     0.00     8.00     0.62    0.27   0.27  62.40

查看 get_request_wait 的含义时,我偶然发现“理解 Linux 内核”其中也涵盖了 I/O 调度程序,并指出:

在负载非常重和磁盘活动频繁的情况下,请求描述符的数量可能会成为瓶颈。空闲描述符的缺乏可能会迫使进程等待,直到正在进行的数据传输终止。因此,等待队列用于对等待空闲请求元素的进程进行排队。尝试get_request_wait()获取空闲请求描述符并如果未找到任何内容,则将当前进程置于等待队列中的休眠状态

(重点是我的)

我尝试调整 /sys/block/sdb/queue/nr_requests 中的值,将其从 128 增加到 4096。这使我在 iotop 中获得了更长的队列大小值(~4k),但总体情况保持不变:许多小(8K)IO 写入操作在较长时间内以大约相同的速率(4K-12K IOPS)阻止对文件的进一步写入。

相关内容