tcmu と IO スケジューラ

前回、tcmu でブロックデバイスを作ってみたが、思ったより性能が出なかった。 IO completion が遅いのだと思ってスレッド化してみたが、もとより少々遅くなってしまった。

ところがふと、IO スケジューラを確認してみると、cfq スケジューラを使っていることがわかった。 これを deadline に変えてみると性能がかなり上がった。

手元の 4.13 では NBD はデフォルトで blk-mq スケジューラを利用している。 tcmu も blk-mq でベンチマークを取るのがフェアだと思ったので試してみた。

tcmu を提供する lio も scsi ドライバの一種なので、blk-mq を有効にするにはカーネルの起動パラメータに scsi_mod.use_blk_mq=1 をつける必要がある。

この状態で試すと、以下のようになった。

# of fio threads read write
2 270MB/s 270MB/s
4 276MB/s 276MB/s
8 242MB/s 242MB/s

一方、NBD は以下のようになった。

# of fio threads read write
2 282MB/s 282MB/s
4 237MB/s 237MB/s
8 194MB/s 194MB/s

ということでいい感じに性能が出るようになる上に、fio のスレッド数を増やしても割と性能が安定している。 雑なベンチマークではあるが、ようやく tcmu の良いところが見えた。

tcmu でブロックデバイスを作る

tcmu は LIO のバックエンドの一つで、UIO を使って SCSI をコマンドをユーザーランドと通信する。 ドキュメントがかなり詳しく書いているのでわかりやすい。 https://www.kernel.org/doc/Documentation/target/tcmu-design.txt

SCSI コマンドやデータのやり取りは、UIO デバイスmmap したメモリ領域に書き込むことで行う。 このメモリ領域は、メタデータ、コマンドキュー、データ領域にわけられている。 キューにコマンドがエンキューされたことは、UIO デバイスを read または poll することで検知できる。 またコマンドを処理したことをカーネルに伝えるには、UIO デバイスに 4 byte write してやることで実現する。

NBD と違い、SCSI コマンドを解釈する必要があるので実装は面倒くさいが、 カーネルとの通信は mmap した領域に書き込むだけなのでオーバーヘッドが少ないことが予想される。

いつものように rust でメモリバックエンドのデバイスを実装してみた。

github.com

SCSI コマンドは linux がデバイスを動かせる最低限しか実装していない。 それでもかなり面倒くさかったのでデバイスを作る開発者には頭が下がる。

さて、fio でのベンチマークは以下となる。 バージョンやパラメータが以前と異なるが、まあ大きく問題ではないはず。

rw: (g=0): rw=randrw, bs=(R) 4096B-4096B, (W) 4096B-4096B, (T) 4096B-4096B, ioengine=libaio, iodepth=64
...
fio-3.1
Starting 3 processes
rw: Laying out IO files (8 files / total 250MiB)
rw: Laying out IO files (8 files / total 250MiB)
rw: Laying out IO files (8 files / total 250MiB)
Jobs: 3 (f=24): [m(3)][100.0%][r=166MiB/s,w=167MiB/s][r=42.4k,w=42.7k IOPS][eta 00m:00s]
rw: (groupid=0, jobs=3): err= 0: pid=1031: Sun Oct 15 02:40:33 2017
   read: IOPS=50.0k, BW=195MiB/s (205MB/s)(11.5GiB/60020msec)
    slat (nsec): min=1006, max=8783.3k, avg=11616.59, stdev=53570.35
    clat (usec): min=20, max=300906, avg=1902.37, stdev=8166.04
     lat (usec): min=26, max=300908, avg=1914.10, stdev=8167.55
    clat percentiles (usec):
     |  1.00th=[   347],  5.00th=[   486], 10.00th=[   529], 20.00th=[   594],
     | 30.00th=[   668], 40.00th=[   734], 50.00th=[   938], 60.00th=[  1188],
     | 70.00th=[  1729], 80.00th=[  2245], 90.00th=[  2704], 95.00th=[  3032],
     | 99.00th=[  4359], 99.50th=[ 74974], 99.90th=[149947], 99.95th=[160433],
     | 99.99th=[210764]
   bw (  KiB/s): min= 1680, max=150592, per=33.35%, avg=66720.66, stdev=21592.10, samples=360
   iops        : min=  420, max=37648, avg=16680.15, stdev=5398.03, samples=360
  write: IOPS=49.0k, BW=195MiB/s (205MB/s)(11.4GiB/60020msec)
    slat (nsec): min=1489, max=8732.8k, avg=12720.29, stdev=53613.83
    clat (usec): min=9, max=301225, avg=1910.20, stdev=8189.98
     lat (usec): min=24, max=301228, avg=1923.05, stdev=8191.48
    clat percentiles (usec):
     |  1.00th=[   347],  5.00th=[   486], 10.00th=[   529], 20.00th=[   594],
     | 30.00th=[   676], 40.00th=[   734], 50.00th=[   947], 60.00th=[  1188],
     | 70.00th=[  1729], 80.00th=[  2245], 90.00th=[  2704], 95.00th=[  3064],
     | 99.00th=[  4424], 99.50th=[ 74974], 99.90th=[149947], 99.95th=[160433],
     | 99.99th=[210764]
   bw (  KiB/s): min= 1480, max=150488, per=33.35%, avg=66684.45, stdev=21528.53, samples=360
   iops        : min=  370, max=37622, avg=16671.08, stdev=5382.13, samples=360
  lat (usec)   : 10=0.01%, 50=0.01%, 100=0.06%, 250=0.37%, 500=6.07%
  lat (usec)   : 750=34.44%, 1000=12.39%
  lat (msec)   : 2=21.49%, 4=24.07%, 10=0.30%, 20=0.23%, 50=0.07%
  lat (msec)   : 100=0.33%, 250=0.20%, 500=0.01%
  cpu          : usr=4.07%, sys=16.96%, ctx=1419522, majf=0, minf=43
  IO depths    : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.1%, 16=0.1%, 32=0.1%, >=64=100.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.1%, >=64=0.0%
     issued rwt: total=3002198,3000568,0, short=0,0,0, dropped=0,0,0
     latency   : target=0, window=0, percentile=100.00%, depth=64

Run status group 0 (all jobs):
   READ: bw=195MiB/s (205MB/s), 195MiB/s-195MiB/s (205MB/s-205MB/s), io=11.5GiB (12.3GB), run=60020-60020msec
  WRITE: bw=195MiB/s (205MB/s), 195MiB/s-195MiB/s (205MB/s-205MB/s), io=11.4GiB (12.3GB), run=60020-60020msec

Disk stats (read/write):
  sdb: ios=2966618/2964788, merge=26473/26652, ticks=4184010/4205964, in_queue=8400100, util=99.91%

これを見ると NBD を使った実装よりも遅いことがわかる。 perf などで調べてみたが、UIO デバイスへの write、すなわち kernel への command completion の通知が重いらしい。

Samples: 31K of event 'cycles:ppp', Event count (approx.): 29291463791
  Children      Self  Command   Shared Object       Symbol
+   71.40%     0.22%  tcmu-mem  [kernel.vmlinux]    [k] entry_SYSCALL_64_fastpath
+   70.75%     0.22%  tcmu-mem  libpthread-2.26.so  [.] __libc_write
+   70.08%     0.08%  tcmu-mem  [kernel.vmlinux]    [k] sys_write
+   69.78%     0.56%  tcmu-mem  [kernel.vmlinux]    [k] vfs_write
+   69.09%     0.24%  tcmu-mem  [kernel.vmlinux]    [k] __vfs_write
+   68.79%     0.58%  tcmu-mem  [uio]               [k] uio_write
+   67.84%     0.20%  tcmu-mem  [target_core_user]  [k] tcmu_irqcontrol
+   56.89%     2.83%  tcmu-mem  [target_core_user]  [k] tcmu_handle_completions
+   31.39%     0.00%  tcmu-mem  [unknown]           [k] 0x0000000000000001
+   22.22%    21.87%  tcmu-mem  libc-2.26.so        [.] __memmove_avx_unaligned_erms
+   21.27%     0.83%  tcmu-mem  [target_core_mod]   [k] target_complete_cmd
+   20.45%     1.52%  tcmu-mem  [kernel.vmlinux]    [k] preempt_schedule
+   20.28%     1.17%  tcmu-mem  [kernel.vmlinux]    [k] ___preempt_schedule
+   19.63%     1.66%  tcmu-mem  [kernel.vmlinux]    [k] try_to_wake_up
+   19.47%     1.28%  tcmu-mem  [kernel.vmlinux]    [k] __schedule
+   19.05%     0.59%  tcmu-mem  [kernel.vmlinux]    [k] queue_work_on
+   18.86%     0.40%  tcmu-mem  [kernel.vmlinux]    [k] preempt_schedule_common
+   17.40%     1.08%  tcmu-mem  [kernel.vmlinux]    [k] _raw_spin_unlock
+   16.96%     1.89%  tcmu-mem  [kernel.vmlinux]    [k] __queue_work
+   15.17%     0.77%  tcmu-mem  [kernel.vmlinux]    [k] insert_work
+   14.36%     0.12%  tcmu-mem  [kernel.vmlinux]    [k] wake_up_process
+   13.08%     4.32%  tcmu-mem  tcmu-mem            [.] tcmu_mem::main

NBD で複数ソケットを使う

NBD では 4.10 から一つのブロックデバイスに対して複数のソケットをアサインすることができるようになった。

github.com

github.com 前回使ったコードを適当に変更して複数ソケットをマルチスレッドでさばくようにした。

また fio で適当に計測してみた。

# of fio threads # of nbd threads ios(r/w)
1 1 8313625/8309306
1 4 9939814/9935338
2 2 12332608/12329740
2 4 10418903/10416638
4 1 10956949/10836467
4 2 10441119/10353829
4 4 8330135/8235491
# of fio threads # of nbd threads type MiB/s
1 1 READ 181MiB/s
1 1 WRITE 180MiB/s
1 4 READ 216MiB/s
1 4 WRITE 216MiB/s
2 2 READ 268MiB/s
2 2 WRITE 268MiB/s
2 4 READ 226MiB/s
2 4 WRITE 226MiB/s
4 1 READ 239MiB/s
4 1 WRITE 239MiB/s
4 2 READ 227MiB/s
4 2 WRITE 227MiB/s
4 4 READ 181MiB/s
4 4 WRITE 182MiB/s

計測したマシンが hyper thread こみで 4 コアなので、fio と nbd のスレッドを同じにしつつ、合計で 4 にするのが一番性能が出るみたいだ。 以前測った lio よりもスループットが出ている。 ついでなので lio でも同じ傾向がないか fio 2 スレッドで試したが、どうにも速度が出ないようだ。

Run status group 0 (all jobs):
   READ: bw=187MiB/s (197MB/s), 187MiB/s-187MiB/s (197MB/s-197MB/s), io=32.9GiB (35.4GB), run=180001-180001msec
  WRITE: bw=187MiB/s (197MB/s), 187MiB/s-187MiB/s (197MB/s-197MB/s), io=32.9GiB (35.4GB), run=180001-180001msec

Disk stats (read/write):
  sdb: ios=8632558/8631694, merge=0/5, ticks=169527/171223, in_queue=334347, util=78.51%

NBD で遊ぶ

LinuxNetwork block device を使ってユーザーランドブロックデバイスを作って遊んでみた。

github.com

バックエンドは単純なメモリを使っているので、前回と同様に fio を使って計測してみた。

rw: (g=0): rw=randrw, bs=(R) 4096B-4096B, (W) 4096B-4096B, (T) 4096B-4096B, ioengine=libaio, iodepth=64
...
fio-2.20
Starting 4 processes
rw: Laying out IO files (8 files / total 250MiB)
rw: Laying out IO files (8 files / total 250MiB)
rw: Laying out IO files (8 files / total 250MiB)
rw: Laying out IO files (8 files / total 250MiB)
Jobs: 4 (f=32): [m(4)][100.0%][r=200MiB/s,w=199MiB/s][r=51.3k,w=50.9k IOPS][eta 00m:00s]
rw: (groupid=0, jobs=4): err= 0: pid=679: Sun Jun 11 06:52:31 2017
   read: IOPS=60.3k, BW=235MiB/s (247MB/s)(41.4GiB/180002msec)
    slat (usec): min=1, max=33650, avg= 9.24, stdev=31.16
    clat (usec): min=0, max=38215, avg=1007.59, stdev=907.35
     lat (usec): min=15, max=45771, avg=1017.25, stdev=918.07
    clat percentiles (usec):
     |  1.00th=[  466],  5.00th=[  540], 10.00th=[  580], 20.00th=[  644],
     | 30.00th=[  692], 40.00th=[  732], 50.00th=[  772], 60.00th=[  812],
     | 70.00th=[  876], 80.00th=[  988], 90.00th=[ 1352], 95.00th=[ 2896],
     | 99.00th=[ 5408], 99.50th=[ 5728], 99.90th=[ 7136], 99.95th=[ 8512],
     | 99.99th=[14272]
   bw (  KiB/s): min=21080, max=167656, per=0.02%, avg=60272.28, stdev=14824.84
  write: IOPS=60.3k, BW=235MiB/s (247MB/s)(41.4GiB/180002msec)
    slat (usec): min=1, max=22476, avg=12.33, stdev=34.13
    clat (usec): min=86, max=46102, avg=3212.60, stdev=2211.13
     lat (usec): min=98, max=46108, avg=3225.39, stdev=2215.15
    clat percentiles (usec):
     |  1.00th=[  548],  5.00th=[  700], 10.00th=[  796], 20.00th=[ 1080],
     | 30.00th=[ 1496], 40.00th=[ 2040], 50.00th=[ 2736], 60.00th=[ 3472],
     | 70.00th=[ 4384], 80.00th=[ 5344], 90.00th=[ 6368], 95.00th=[ 7072],
     | 99.00th=[ 8384], 99.50th=[ 9152], 99.90th=[13504], 99.95th=[16768],
     | 99.99th=[28800]
   bw (  KiB/s): min=21392, max=166912, per=0.02%, avg=60277.15, stdev=14798.88
    lat (usec) : 2=0.01%, 10=0.01%, 20=0.01%, 50=0.01%, 100=0.01%
    lat (usec) : 250=0.01%, 500=1.35%, 750=25.00%, 1000=22.80%
    lat (msec) : 2=17.53%, 4=14.70%, 10=18.43%, 20=0.15%, 50=0.02%
  cpu          : usr=5.31%, sys=19.70%, ctx=38960144, majf=0, minf=50
  IO depths    : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.1%, 16=0.1%, 32=0.1%, >=64=100.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.1%, >=64=0.0%
     issued rwt: total=10848673,10849680,0, short=0,0,0, dropped=0,0,0
     latency   : target=0, window=0, percentile=100.00%, depth=64

Run status group 0 (all jobs):
   READ: bw=235MiB/s (247MB/s), 235MiB/s-235MiB/s (247MB/s-247MB/s), io=41.4GiB (44.4GB), run=180002-180002msec
  WRITE: bw=235MiB/s (247MB/s), 235MiB/s-235MiB/s (247MB/s-247MB/s), io=41.4GiB (44.4GB), run=180002-180002msec

Disk stats (read/write):
  nbd0: ios=10809774/10679800, merge=28452/159229, ticks=7736680/30982613, in_queue=38873356, util=100.00%

かなり適当な実装だけど、lio の blk-mq を使わない場合と同じぐらいは速度が出ているみたいだ。 新しめのカーネルだとデバイスに対して複数ソケットが割り当てられるので、次はスレッド化してどうなるか確認してみる。 実装には rust を使った。 rust いいよ、rust。

loopback block device で遊ぶ

linux にはいろんな仮想ブロックデバイスが存在して、ものによっては機能がかぶっていたりする。 今回は、ファイルをブロックデバイスとして見せる、loopback block device で遊んでみた。

まずは伝統的な loop モジュールによるもの。 arch で使うには modprobe loop が必要だった。 あとは、losetup /dev/loop0 /tmp/disk とかして使う。

もう一つは、lio を使う方法。 lio は iSCSI の実装として有名だけど、データのストア先が backstore として、またデータ入出力のインターフェースとして fabric module (または frontend)が提供されている。 backstore として block device を指定することもできるし、ファイルを指定することもできる。 fabric module には通常 iSCSI を指定して iSCSI target としてエクスポートするが、tcm_loop を使うことで、 backstore を通常の SCSIバイスとしてローカルマシンに見せることができる。 ここで backstore をファイルにして frontend を tcm_loop とすることで loopback block device として使える。

lio を使うには arch では targetcli-fb を AUR からインストールする。

あとは targetcli を root で起動してポチポチしていけば良い。

cd /backstores/fileio
create name=disk file_or_dev=/tmp/disk
cd /loopback
create
cd ***
cd luns
create /backstores/fileio/disk
exit

これで /dev/sdb とかが生えてくる。

さて、fio で簡単に2つの実装をテストしてみた。 設定は以下。

[rw]
size=250M
readwrite=randrw
nrfiles=8
ioengine=libaio
iodepth=16
direct=1
overwrite=1
runtime=180
time_based
numjobs=4
group_reporting

バックストア先のファイルは 1.5G で tmpfs 上に乗せている。 したがって、純粋にそれぞれの実装によるオーバーヘッドだけが見えるはず。 ファイルシステムには xfs を使った。

結果は以下。

  • loop
rw: (g=0): rw=randrw, bs=(R) 4096B-4096B, (W) 4096B-4096B, (T) 4096B-4096B, ioengine=libaio, iodepth=16
...
fio-2.20
Starting 4 processes
rw: Laying out IO files (8 files / total 250MiB)
rw: Laying out IO files (8 files / total 250MiB)
rw: Laying out IO files (8 files / total 250MiB)
rw: Laying out IO files (8 files / total 250MiB)
Jobs: 4 (f=32): [m(4)][100.0%][r=442MiB/s,w=442MiB/s][r=113k,w=113k IOPS][eta 00m:00s]
rw: (groupid=0, jobs=4): err= 0: pid=2200: Sun Jun  4 01:16:32 2017
   read: IOPS=122k, BW=478MiB/s (501MB/s)(83.0GiB/180001msec)
    slat (usec): min=1, max=20022, avg= 4.76, stdev=50.93
    clat (usec): min=0, max=26792, avg=248.51, stdev=254.66
     lat (usec): min=4, max=26795, avg=253.46, stdev=259.78
    clat percentiles (usec):
     |  1.00th=[   41],  5.00th=[   88], 10.00th=[  151], 20.00th=[  203],
     | 30.00th=[  241], 40.00th=[  255], 50.00th=[  262], 60.00th=[  270],
     | 70.00th=[  278], 80.00th=[  286], 90.00th=[  294], 95.00th=[  302],
     | 99.00th=[  322], 99.50th=[  330], 99.90th=[  510], 99.95th=[10048],
     | 99.99th=[10176]
   bw (  KiB/s): min=105520, max=206152, per=0.02%, avg=122299.23, stdev=17817.78
  write: IOPS=122k, BW=478MiB/s (501MB/s)(83.0GiB/180001msec)
    slat (usec): min=1, max=20050, avg= 6.49, stdev=53.88
    clat (usec): min=0, max=29928, avg=260.77, stdev=274.08
     lat (usec): min=10, max=29937, avg=267.45, stdev=279.42
    clat percentiles (usec):
     |  1.00th=[   87],  5.00th=[   98], 10.00th=[  187], 20.00th=[  213],
     | 30.00th=[  245], 40.00th=[  258], 50.00th=[  266], 60.00th=[  274],
     | 70.00th=[  278], 80.00th=[  286], 90.00th=[  298], 95.00th=[  310],
     | 99.00th=[  498], 99.50th=[  596], 99.90th=[ 1480], 99.95th=[10048],
     | 99.99th=[10176]
   bw (  KiB/s): min=107472, max=206120, per=0.02%, avg=122354.26, stdev=17781.92
    lat (usec) : 2=0.01%, 4=0.01%, 10=0.05%, 20=0.11%, 50=0.54%
    lat (usec) : 100=5.80%, 250=28.75%, 500=64.21%, 750=0.41%, 1000=0.04%
    lat (msec) : 2=0.02%, 4=0.01%, 10=0.01%, 20=0.05%, 50=0.01%
  cpu          : usr=12.74%, sys=40.54%, ctx=18171368, majf=0, minf=43
  IO depths    : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.1%, 16=100.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.1%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued rwt: total=22007682,22017735,0, short=0,0,0, dropped=0,0,0
     latency   : target=0, window=0, percentile=100.00%, depth=16

Run status group 0 (all jobs):
   READ: bw=478MiB/s (501MB/s), 478MiB/s-478MiB/s (501MB/s-501MB/s), io=83.0GiB (90.1GB), run=180001-180001msec
  WRITE: bw=478MiB/s (501MB/s), 478MiB/s-478MiB/s (501MB/s-501MB/s), io=83.0GiB (90.2GB), run=180001-180001msec

Disk stats (read/write):
  loop0: ios=21995434/22005502, merge=0/0, ticks=5134440/5127490, in_queue=10299120, util=100.00%
  • lio
rw: (g=0): rw=randrw, bs=(R) 4096B-4096B, (W) 4096B-4096B, (T) 4096B-4096B, ioengine=libaio, iodepth=16
...
fio-2.20
Starting 4 processes
rw: Laying out IO files (8 files / total 250MiB)
rw: Laying out IO files (8 files / total 250MiB)
rw: Laying out IO files (8 files / total 250MiB)
rw: Laying out IO files (8 files / total 250MiB)
Jobs: 4 (f=32): [m(4)][100.0%][r=179MiB/s,w=179MiB/s][r=45.9k,w=45.8k IOPS][eta 00m:00s]
rw: (groupid=0, jobs=4): err= 0: pid=7267: Sun Jun  4 01:31:19 2017
   read: IOPS=53.6k, BW=210MiB/s (220MB/s)(36.8GiB/180001msec)
    slat (usec): min=1, max=19641, avg=32.46, stdev=21.93
    clat (usec): min=3, max=873729, avg=561.32, stdev=1187.46
     lat (usec): min=12, max=873734, avg=594.14, stdev=1187.82
    clat percentiles (usec):
     |  1.00th=[  438],  5.00th=[  454], 10.00th=[  462], 20.00th=[  486],
     | 30.00th=[  556], 40.00th=[  564], 50.00th=[  572], 60.00th=[  580],
     | 70.00th=[  588], 80.00th=[  596], 90.00th=[  620], 95.00th=[  652],
     | 99.00th=[  692], 99.50th=[  708], 99.90th=[ 1048], 99.95th=[ 1400],
     | 99.99th=[ 5088]
   bw (  KiB/s): min=19544, max=114648, per=0.02%, avg=53734.31, stdev=6185.94
  write: IOPS=53.6k, BW=210MiB/s (220MB/s)(36.8GiB/180001msec)
    slat (usec): min=2, max=18805, avg=35.23, stdev=26.63
    clat (usec): min=2, max=873700, avg=559.72, stdev=1189.48
     lat (usec): min=22, max=873706, avg=595.30, stdev=1189.95
    clat percentiles (usec):
     |  1.00th=[  438],  5.00th=[  454], 10.00th=[  462], 20.00th=[  486],
     | 30.00th=[  548], 40.00th=[  564], 50.00th=[  572], 60.00th=[  572],
     | 70.00th=[  588], 80.00th=[  596], 90.00th=[  620], 95.00th=[  652],
     | 99.00th=[  692], 99.50th=[  708], 99.90th=[ 1048], 99.95th=[ 1400],
     | 99.99th=[ 4960]
   bw (  KiB/s): min=20088, max=112888, per=0.02%, avg=53746.07, stdev=6192.19
    lat (usec) : 4=0.01%, 10=0.01%, 20=0.01%, 50=0.01%, 100=0.02%
    lat (usec) : 250=0.15%, 500=22.32%, 750=77.30%, 1000=0.09%
    lat (msec) : 2=0.09%, 4=0.01%, 10=0.01%, 20=0.01%, 50=0.01%
    lat (msec) : 100=0.01%, 250=0.01%, 1000=0.01%
  cpu          : usr=7.29%, sys=45.40%, ctx=19322396, majf=0, minf=52
  IO depths    : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.1%, 16=100.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.1%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued rwt: total=9654368,9656263,0, short=0,0,0, dropped=0,0,0
     latency   : target=0, window=0, percentile=100.00%, depth=16

Run status group 0 (all jobs):
   READ: bw=210MiB/s (220MB/s), 210MiB/s-210MiB/s (220MB/s-220MB/s), io=36.8GiB (39.5GB), run=180001-180001msec
  WRITE: bw=210MiB/s (220MB/s), 210MiB/s-210MiB/s (220MB/s-220MB/s), io=36.8GiB (39.6GB), run=180001-180001msec

Disk stats (read/write):
  sdb: ios=9647282/9649318, merge=2/9, ticks=221083/231767, in_queue=428717, util=96.83%

理由は追えていないが、loop のほうが lio に倍以上 IOPS 出ていて面白い。 マシンは、Sony Corporation SVP1121A1J/VAIO, BIOS R1045V7 を使った。 kernel は 4.11.3-1-ARCH。


追記

ramdisk backstore を使ってみた。 ほぼ fileio と変わらないので、lio 自体で律速されているようだ。

rw: (g=0): rw=randrw, bs=(R) 4096B-4096B, (W) 4096B-4096B, (T) 4096B-4096B, ioengine=libaio, iodepth=16                                                                                        
...                                            
fio-2.20                                       
Starting 4 processes                           
rw: Laying out IO files (8 files / total 250MiB)                                               
rw: Laying out IO files (8 files / total 250MiB)                                               
rw: Laying out IO files (8 files / total 250MiB)                                               
rw: Laying out IO files (8 files / total 250MiB)                                               
Jobs: 4 (f=32): [m(4)][100.0%][r=191MiB/s,w=193MiB/s][r=48.9k,w=49.3k IOPS][eta 00m:00s]       
rw: (groupid=0, jobs=4): err= 0: pid=627: Sun Jun  4 03:37:05 2017                             
   read: IOPS=57.7k, BW=225MiB/s (236MB/s)(39.6GiB/180001msec)                                 
    slat (usec): min=3, max=12337, avg=30.54, stdev=19.99                                      
    clat (usec): min=3, max=12778, avg=521.58, stdev=98.27                                     
     lat (usec): min=38, max=12805, avg=552.46, stdev=101.85                                   
    clat percentiles (usec):                   
     |  1.00th=[  426],  5.00th=[  430], 10.00th=[  434], 20.00th=[  442],                     
     | 30.00th=[  524], 40.00th=[  532], 50.00th=[  532], 60.00th=[  532],                     
     | 70.00th=[  540], 80.00th=[  556], 90.00th=[  572], 95.00th=[  604],                     
     | 99.00th=[  628], 99.50th=[  636], 99.90th=[  732], 99.95th=[ 1096],                     
     | 99.99th=[ 2320]                         
   bw (  KiB/s): min=47520, max=70648, per=0.02%, avg=57715.31, stdev=5761.57                  
  write: IOPS=57.7k, BW=225MiB/s (236MB/s)(39.6GiB/180001msec)                                 
    slat (usec): min=3, max=10906, avg=32.38, stdev=23.06                                      
    clat (usec): min=3, max=12780, avg=520.53, stdev=101.82                                    
     lat (usec): min=39, max=12804, avg=553.25, stdev=106.00                                   
    clat percentiles (usec):                   
     |  1.00th=[  426],  5.00th=[  430], 10.00th=[  434], 20.00th=[  442],                     
     | 30.00th=[  524], 40.00th=[  532], 50.00th=[  532], 60.00th=[  532],                     
     | 70.00th=[  540], 80.00th=[  556], 90.00th=[  564], 95.00th=[  604],                     
     | 99.00th=[  628], 99.50th=[  636], 99.90th=[  732], 99.95th=[ 1112],                     
     | 99.99th=[ 3120]                         
   bw (  KiB/s): min=47432, max=70792, per=0.02%, avg=57724.14, stdev=5769.25                  
    lat (usec) : 4=0.01%, 50=0.01%, 100=0.01%, 250=0.01%, 500=23.08%                           
    lat (usec) : 750=76.82%, 1000=0.04%        
    lat (msec) : 2=0.05%, 4=0.01%, 10=0.01%, 20=0.01%                                          
  cpu          : usr=7.49%, sys=46.22%, ctx=20795324, majf=0, minf=52                          
  IO depths    : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.1%, 16=100.0%, 32=0.0%, >=64=0.0%                 
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%                
     complete  : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.1%, 32=0.0%, 64=0.0%, >=64=0.0%                
     issued rwt: total=10383664,10385405,0, short=0,0,0, dropped=0,0,0                         
     latency   : target=0, window=0, percentile=100.00%, depth=16                              

Run status group 0 (all jobs):                 
   READ: bw=225MiB/s (236MB/s), 225MiB/s-225MiB/s (236MB/s-236MB/s), io=39.6GiB (42.5GB), run=180001-180001msec                                                                                
  WRITE: bw=225MiB/s (236MB/s), 225MiB/s-225MiB/s (236MB/s-236MB/s), io=39.6GiB (42.5GB), run=180001-180001msec                                                                                

Disk stats (read/write):                       
  sdb: ios=10377752/10379508, merge=0/7, ticks=196560/194066, in_queue=371003, util=100.00%    

perf top で様子を見てみた。 この感じだとロックコンテンションが性能に影響を与えているようだ。

  • loop
Samples: 838K of event 'cycles', Event count (approx.): 110568441611
Overhead  Shared Object                  Symbol
   3.79%  [kernel]                       [k] memcpy_erms
   2.08%  fio                            [.] get_io_u
   1.79%  [kernel]                       [k] __radix_tree_lookup
   1.74%  [kernel]                       [k] _raw_spin_lock
   1.25%  [kernel]                       [k] __sched_text_start
   1.20%  [kernel]                       [k] _raw_spin_lock_irqsave
   1.16%  [kernel]                       [k] kmem_cache_alloc
   1.03%  [kernel]                       [k] sbitmap_get
   1.00%  fio                            [.] io_u_queued_complete
   1.00%  [loop]                         [k] loop_queue_work
   0.89%  fio                            [.] fio_gettime
   0.86%  [kernel]                       [k] iomap_dio_bio_end_io
   0.85%  [kernel]                       [k] do_io_submit
   0.84%  [kernel]                       [k] aio_complete
   0.83%  [kernel]                       [k] __slab_free
   0.76%  [kernel]                       [k] enqueue_entity
   0.76%  [kernel]                       [k] find_get_entry
   0.75%  [kernel]                       [k] __fget
   0.75%  [kernel]                       [k] gup_pte_range
   0.74%  [kernel]                       [k] __switch_to
   0.70%  [kernel]                       [k] iomap_dio_actor
   0.69%  [kernel]                       [k] dequeue_entity
   0.68%  [kernel]                       [k] _raw_spin_unlock_irqrestore
   0.67%  [kernel]                       [k] set_next_entity
  • lio
Samples: 850K of event 'cycles', Event count (approx.): 183184369456
Overhead  Shared Object                            Symbol
  18.53%  [kernel]                                 [k] native_queued_spin_lock_slowpath
   2.10%  [kernel]                                 [k] _raw_spin_lock_irqsave
   1.90%  [kernel]                                 [k] memcpy_erms
   1.22%  [kernel]                                 [k] _raw_spin_unlock_irqrestore
   0.96%  [kernel]                                 [k] __sched_text_start
   0.88%  [kernel]                                 [k] read_tsc
   0.88%  [kernel]                                 [k] _raw_spin_lock
   0.73%  [kernel]                                 [k] __radix_tree_lookup
   0.72%  [kernel]                                 [k] kmem_cache_alloc
   0.68%  zsh                                      [.] execbuiltin
   0.67%  [kernel]                                 [k] _raw_spin_lock_irq
   0.65%  [kernel]                                 [k] enqueue_entity
   0.63%  [kernel]                                 [k] __percpu_counter_add
   0.63%  [kernel]                                 [k] set_next_entity
   0.63%  [kernel]                                 [k] ktime_get
   0.61%  [kernel]                                 [k] dequeue_entity
   0.60%  [kernel]                                 [k] __switch_to
   0.59%  zsh                                      [.] bin_read
   0.59%  zsh                                      [.] bin_print
   0.59%  [kernel]                                 [k] update_curr
   0.57%  [kernel]                                 [k] _mix_pool_bytes
   0.55%  [kernel]                                 [k] kmem_cache_free
   0.55%  [kernel]                                 [k] cfq_completed_request
   0.53%  [kernel]                                 [k] pick_next_task_fair

blk-mq を有効にしたら少し改善した。 loop はデフォルトで mq を使っていた。

cat /sys/block/loop0/queue/scheduler 
[mq-deadline] none
rw: (g=0): rw=randrw, bs=(R) 4096B-4096B, (W) 4096B-4096B, (T) 4096B-4096B, ioengine=libaio, iodepth=16
...
fio-2.20
Starting 4 processes
rw: Laying out IO files (8 files / total 250MiB)
rw: Laying out IO files (8 files / total 250MiB)
rw: Laying out IO files (8 files / total 250MiB)
rw: Laying out IO files (8 files / total 250MiB)
Jobs: 4 (f=32): [m(4)][100.0%][r=320MiB/s,w=320MiB/s][r=81.8k,w=81.8k IOPS][eta 00m:00s]
rw: (groupid=0, jobs=4): err= 0: pid=685: Sun Jun  4 05:06:29 2017
   read: IOPS=90.7k, BW=354MiB/s (372MB/s)(62.3GiB/180002msec)
    slat (usec): min=2, max=10340, avg=17.83, stdev=18.18
    clat (usec): min=1, max=10751, avg=331.24, stdev=82.57
     lat (usec): min=13, max=10770, avg=349.35, stdev=85.77
    clat percentiles (usec):
     |  1.00th=[  239],  5.00th=[  251], 10.00th=[  258], 20.00th=[  278],
     | 30.00th=[  318], 40.00th=[  330], 50.00th=[  342], 60.00th=[  354],
     | 70.00th=[  362], 80.00th=[  370], 90.00th=[  382], 95.00th=[  390],
     | 99.00th=[  406], 99.50th=[  414], 99.90th=[  442], 99.95th=[  532],
     | 99.99th=[ 1544]
   bw (  KiB/s): min=77056, max=118824, per=0.02%, avg=90792.63, stdev=12202.74
  write: IOPS=90.8k, BW=355MiB/s (372MB/s)(62.3GiB/180002msec)
    slat (usec): min=3, max=10087, avg=20.06, stdev=16.31
    clat (usec): min=3, max=10749, avg=331.87, stdev=84.35
     lat (usec): min=14, max=10773, avg=352.20, stdev=87.32
    clat percentiles (usec):
     |  1.00th=[  241],  5.00th=[  251], 10.00th=[  258], 20.00th=[  278],
     | 30.00th=[  318], 40.00th=[  330], 50.00th=[  342], 60.00th=[  354],
     | 70.00th=[  362], 80.00th=[  370], 90.00th=[  382], 95.00th=[  390],
     | 99.00th=[  406], 99.50th=[  414], 99.90th=[  442], 99.95th=[  548],
     | 99.99th=[ 1544]
   bw (  KiB/s): min=76792, max=118288, per=0.02%, avg=90829.20, stdev=12165.43
    lat (usec) : 2=0.01%, 4=0.01%, 10=0.01%, 20=0.01%, 50=0.01%
    lat (usec) : 100=0.01%, 250=4.06%, 500=95.88%, 750=0.03%, 1000=0.01%
    lat (msec) : 2=0.02%, 4=0.01%, 10=0.01%, 20=0.01%
  cpu          : usr=12.31%, sys=45.85%, ctx=31964284, majf=0, minf=46
  IO depths    : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.1%, 16=100.0%, 32=0.0%, >=64=0.0%
     submit    : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
     complete  : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.1%, 32=0.0%, 64=0.0%, >=64=0.0%
     issued rwt: total=16331936,16338526,0, short=0,0,0, dropped=0,0,0
     latency   : target=0, window=0, percentile=100.00%, depth=16

Run status group 0 (all jobs):
   READ: bw=354MiB/s (372MB/s), 354MiB/s-354MiB/s (372MB/s-372MB/s), io=62.3GiB (66.9GB), run=180002-180002msec
  WRITE: bw=355MiB/s (372MB/s), 355MiB/s-355MiB/s (372MB/s-372MB/s), io=62.3GiB (66.9GB), run=180002-180002msec

Disk stats (read/write):
  sdb: ios=16331311/16337886, merge=0/8, ticks=180867/176570, in_queue=413730, util=93.08%

EdgeRouter PoE の復旧

EdgeRouter の SNMP が取れなくなっていたので、ログを見たら IO エラーが出ていたので USB フラッシュが死んだらしい。 ネットワークは生きていたので、再起動とかはしないで、代替の USB フラッシュドライブとシリアルケーブルを購入しておいた。 購入した USB フラッシュは、SanDisk の SDCZ33-016G-J57。どうも相性問題があるらしくフォーラムから動きそうなフラッシュを購入したが結果としては、相性問題に当たってしまった。

公式のレスキュー方法は以下にあるが、TFTP を使ったりしてちょっと面倒くさい。 https://help.ubnt.com/hc/en-us/articles/204959514-EdgeRouter-Last-resort-recovery-of-failed-EdgeOS-device

ソースコードは以下にあって、やっていることは適当にパーティション作って、公式の tar からファイルをコピーすれば良いらしい。 https://github.com/vyos/emrk

パーティションは、msdos で作って、1st primary を fat32 で1セクタから150MB、2nd を ext3 でディスクいっぱいに設定した。 デフォルトでは1900MBになっていて謎だが、特に問題なく動いている。

後は、vmlinux.64{,.md5} を1stに、squashfs.img{,md5}を2ndにコピーして、version ファイルと writable ディレクトリとして w を作っておけば良い。

さて、これで動いてくれると嬉しかったのだが、USB フラッシュを挿入して起動したところ、シリアル経由でブートを覗いていたら、USB フラッシュが認識できずにブートに失敗していた。

ワークアラウンドは u-boot で usb reset をブート前にすれば良い。

https://community.ubnt.com/t5/EdgeMAX/New-U-Boot-image-for-better-USB-drive-compatibility/td-p/850744

シリアル経由で、u-boot を設定する。

setenv oldbootcmd '[copy from bootcmd]'
setenv bootcmd 'sleep 10;usb reset;sleep 10;$(oldbootcmd)'
saveenv

これで復旧完了。

bindgen を使って rust binding を生成する

Rust は C API をゼロオーバーヘッドで呼び出せたりして便利なんだけど、当然バインディングは行わないといけない。 crates.io を探せばおおよそのものは見つかるけど、見つからなかったり、見つかっても古かったりして更新したいときがある。

そんなときは、bindgen (https://github.com/Yamakaky/rust-bindgen) をつかってヘッダーファイルから生成すると便利。 ただし Yamakaky の方は Clang 3.9 に対応していなくて実行するとエラーが出たりする。 手元の環境は Arch Linux で Clang が 3.9 なので残念ながらうまく行かなかった。

一方、Servo の方に fork があって (https://github.com/servo/rust-bindgen) そちらは 3.9 に対応している。 ただし Yamakaky の方と微妙に使い勝手が違う。具体的には --match オプションがない。 (でも --whitelist-* オプションがないから実は困らない気がしてきた。)

そんなわけで、Clang 3.8 をいれて bindgen をビルドする方法を書いておく。

LLVM/CLang のオフィシャルページから 3.8.1 の llvm と clang のソースをダウンロードして、 手順通り (https://clang.llvm.org/get_started.html) にビルドする。 llvm の tools/clang に clang のソースを展開して、configure && make で OK。

あとは llvm のビルドディレクトリに lib/libclang.so ができるのでそいつを指定して以下を実行。

$ LIBCLANG_PATH=$BUILD/lib/ cargo install bindgen

あとはライブラリパスを指定して、bindgen が実行できる。

$ LD_LIBRARY_PATH=$BUILD/lib/ ~/.cargo/bin/bindgen foo.h > foo.rs