消すだけなのに rm -rf がいっつも長くて待ちきれない問題

rmコマンドで大量のファイルを削除しようとするとjournaldがめっちゃリソース持っていく件
— bokko (@cubicdaiya) 2017年8月3日

今時のファイルシステムはみんなジャーナルもってて何かあったときにそこからリカバリする仕組みになってるので、当たり前といえばそうなんだけども。

（TODO: ここにファイルシステムのツリー＋ジャーナルのポンチ絵を手描きでも何でも描く）

ご本尊のデータのツリーと何らかのWALを1セットで持っておくのはRDBだろうがファイルシステムだろうがそうは変わらない、で、削除についても並行制御をうまくやるために削除フラグをログに入れておいてあとで本尊のデータを整理するというのが基本的な設計になる。そこで私は立ち上がった（TL;DR: 特にオチとかはないです）。

rm -rf が遅いのは人類にとって損失ではないか。もっと速く完了するようにすれば、 rm -rf ~ などをしても一気に全部なくなってしまうのでいっそ未練や修復作業が不要なのではないか
— (๑•̀ㅂ•́)و✧ (@kuenishi) 2017年8月3日

で色々調べてみた結果、結論は既存のファイルシステムはよくできているということだった。何かしら高速化を期待された場合はちょっと次回以降をお待ちいただきたい（調べることが多すぎて飽きたともいう）。

ベースライン測定とか

まず1バイトのコンテンツを持ったファイルを大量に作る。

深さ4幅32なので 32^4 = 1048638 個のファイルが33284のディレクトリの下にできたことになる。論理値でいえば1MBほどだが、ディレクトリやファイルなどのオーバーヘッドの方が大きいだろう。それでもRAMが32GBあるマシンで実験したのでファイル実体のディスクアクセスは全てディスクキャッシュに乗る。おそらくWALの書き込みが支配的になるだろう。で、このファイルとディレクトリを消す方法はざっくりインターネットを調べると簡単なものは3つくらいみつかる。それに一つ我流を追加。

rm(1) を使う方法: "rm -rf " とやるだけ。実はこれがかなりよくできていて速い。
xargs(1) と rm(1) を使って並列化する方法: "ls | xargs -n 1 -P 8 rm -rf" などとやるだけ。rm(1)が速くできている上に並列化されて実時間はかなり速くなる。ただしコンテキストスイッチはまあまあ増える。
find(1) を使う方法: "find -delete" とやるだけ。これで以下が全部消される。いまのところこれが rm(1) よりも速いといわれている。
C++17のstd::experimental::filesystem::remove_allを使う方法

この4つを /usr/bin/time で測ってみる。スペックは家のデスクトップDebianの /dev/sdc1 上に作ったXFSディレクトリである。このためだけに作ってあった。user, sys は秒、realは時:分である。

	user	sys	real	voluntary cs	CPU
rm -rf	0.37	20.42	1:58	5327	17%
xargs	1.05	42.80	0:28	1151757	155%
find	0.52	20.82	1:23	942	25%
prm	4.59	46.35	1:24	1251687	60%

想定の通り最も短時間で前処理が終わるのは xargs(1) を使った方法だった。しかしシングルスレッドで最速だと思われた rm(1) よりも find(1) が速いのは意外だった。そこで strace(1) の結果を比較してみる。これは、さきほどの実験コマンドで /usr/bin/time の代わりに "strace -c -f" とつけてやるだけである。まず rm -rf の結果がこちら

$ strace -c rm -rf tree
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 99.04    0.193423           0   1082401           unlinkat
  0.31    0.000614           0    101475           getdents
  0.25    0.000488           0    304425           fcntl
  0.18    0.000351           0     67650           openat
  0.10    0.000189           0    101481           close
  0.07    0.000133           0     67653           fstat
  0.05    0.000099           0     33825           newfstatat
...

で、find(1) の結果がこちら。

$ strace -f -c  find tree -delete
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 99.10    0.190004           0   1082401           unlinkat
  0.24    0.000469           0     67650           getdents
  0.23    0.000436           0    304426           fcntl
  0.13    0.000258           0     33825           openat
  0.13    0.000241           0     67650           newfstatat
  0.12    0.000235           0    135311           close
  0.04    0.000086           0     33834           fstat
...

xargs(1) の結果は rm -rf のものとそう変わらなくて（xargsのwait4(2) が必然的に待ち合わせなのでほとんどの時間を占めている）、30分違ったのはどうしてかなあというところではある。また、99%の時間を使っているはずの unlinkat(2) のシステムコールですら 0.19秒で、wallclock time には全く追いつかない。strace(1) のマニュアルを見ると"On Linux, this attempts to show system time (CPU time spent running in the kernel) independent of wall clock time." と書かれていて、system time が出てもよさそうなもんであるが…という謎に当たる。 xargs(1) で並列化した rm が速くて自作で並列化した prm.cc がどうして遅いのかは

$ strace -f -c /home/kuenishi/path/to/prm tree
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 85.01   57.128000     2197231        26         6 futex
 10.46    7.032312           6   1082401     33825 unlink
  2.21    1.484577          22     67652           getdents
  1.90    1.278376           1   2164802           lstat
  0.33    0.219737           6     33825           rmdir
  0.03    0.019788           1     33832           open
  0.03    0.017729           1     33832           close
  0.02    0.016686           0     33833           fstat
...

としてみればわかるように、 unlink(2) がちょうどディレクトリの個数だけ失敗していて、さらに lstat(2) も大量に呼ばれていることから、ああこの辺だなあとすぐに想像がつく。余談なので深くは追わないが、実際に GCC のSTL実装では簡単にポータブルに作ることを意識していて性能とかそういうことは微塵もなさそう。

このベースライン測定で分かるのは以下

シングルスレッドで動くものだとざっくり1.5 ~ 2時間、マルチスレッドで速く動くものなら30分くらいかかる
システムコールの使い方が下手だとそもそも並列化の恩恵つきでも赤字
どうやら unlinkat(2) をちゃんと使うと速いらしい
userとsysを全部足してもwallclockに追いつかないので、どこで時間が溶けているのか分からない

プロファイル（on CPU）

さてここからが本番である。strace(1)をしても何で時間が溶けているのかよくわからない。こりゃ、削除を速くするとかそれ以前に謎が多いゾ…？という話である。CPUインテンシブなジョブではないので、ふつうのプロファイリングをしてもダメだろうなあというのが容易に想像できる。そこで我らがperf(1)先生の登場だ。perf先生のすごいところは動作中のプロセスもアタッチして覗けるところなのだが、バッチプログラム相手だともっと簡単に起動できる。

実際の測定は簡単で、

$ sudo perf record -F 99 -a -g -- rm -rf tree
$ sudo perf script > out.perf

などとすれば、秒間99のレートでプロセスのスタックをすっぱ抜いてチェックできる。それをこうして…

$ ./stackcollapse-perf.pl out.perf > out.folded
$ ./flamegraph.pl out.folded > out-rm-single.svg
$ firefox out-rm-single.svg

こうじゃ！

f:id:kuenishi:20171006182347p:plain

"rm -rf tree" の代わりに "ls | xargs -P 8 rm -rf" でやったやつもあるよ！

f:id:kuenishi:20171006182505p:plain

どちらの図もほとんどの時間を unlinkat(2) が使っていることが分かる。これは strace の結果とも矛盾しない。で、そのなかでも "vfs_unlink" と "xfs_fs_destroy_inode" がものすごく時間を使っていることがわかる。ちょっとだけLinuxのコードを読んだのだけど、中で沢山ロックをとって、スピンロックも沢山あって、それから inode エントリを書き換えたりして、それをジャーナルに流している？っぽい処理が沢山ある。それから kthread の方で "xlog_iodone" がCPUを使っていることもわかる。しかしながら CPU使用率が 17% しかない（ perf は実行中のプロセスに対してしかスタックをぶち抜かない）ので、これでは全体の実行時間の 17% くらいしか説明できない。

プロファイル (off CPU)

で、IO待ちのプロセスのスタックを抜くにはperfでは不足で、Linuxの eBPF というのを使う。iovisorという便利なツールキットがあるので、そいつをさくっと入れる。

# echo "deb [trusted=yes] https://repo.iovisor.org/apt/xenial xenial-nightly main" >> /etc/apt/sources.list.d/iovisor.list
# apt update
# apt install bcc-tools

これは特定にCPUを見てくれるとかはしなくて、OS内のプロセスで特定の状態にいるやつを拾ってくる。状態一覧はカーネルのヘッダをみると

$ grep TASK_ /usr/src/linux-headers-4.9.0-3-common/include/linux/sched.h  | grep define
#define TASK_RUNNING            0
#define TASK_INTERRUPTIBLE      1
#define TASK_UNINTERRUPTIBLE    2
#define __TASK_STOPPED          4
#define __TASK_TRACED           8
#define TASK_DEAD               64
#define TASK_WAKEKILL           128
#define TASK_WAKING             256
#define TASK_PARKED             512
#define TASK_NOLOAD             1024
#define TASK_NEW                2048
#define TASK_STATE_MAX          4096

などとなっているので、IO待ちの TASK_INTERRUPTIBLE をみるために

$ /usr/share/bcc/tools/offcputime -f 20 --state 2 > out.offcpustack

と仕掛けておく。別のコンソールで素早く

$ time ./coreutils-8.26/src/rm -rf tree

として、コマンドが返ってきたら offcputime もさくっととめる。こいつをグラフにするには

$ ./flamegraph.pl --color=io < out.offcpustack > offcpu-2a.svg

などとすると、こんな感じで

f:id:kuenishi:20171006184650p:plain

TASK_INTERRUPTIBLE状態のプロセスのスタックを秒間20で覗いたときの集計結果を見ることができる。でもカーネル分からないのでウ～ン…となっちゃうけど、やっぱり "xlog_write" という名前からしてXFSのジャーナル書くところで時間を食っているように見えなくもない（心眼）。これは負荷がないときと比較しないといけないんだろうなーと思ったけど、なぜか僕のメモはここで途絶えている。カーネルスレッドって誰が起動してるんだろね…

結論

perfやiovisorを使ってon-CPUとoff-CPUのFlameGraphを描いてみた
XFSやrm(1)はよくできている
それはそれとして unlinkat(2) のシステムコールに縛られたファイルシステムはインターフェースからして改善の余地があるのではないか

想像するに、rm で消しに行ったけどシステムコールから返ってくるには何らかの待ち（おそらくはXFSのジャーナルにwrite）をしないといけないのだけど、それは非同期でやっているので on-CPU のグラフには出てこないし、 off-CPU のグラフのどこに出てくるかをちゃんと調べないとよくわからない。Kernel tracing は難しい。第二部に続く（かもしれない）。

UNIX Filesystems: Evolution, Design, and Implementation (Veritas)

作者: Steve D. Pate
出版社/メーカー: John Wiley & Sons
発売日: 2003/01/03
メディア: ペーパーバック
クリック: 2回
この商品を含むブログ (2件) を見る

おまけ: 環境構築

manpagesを入れる

$ sudo apt install man-db

perfなどのツールを入れる

$ sudo apt-get install linux-perf strace build-essential perf-tools-unstable
$ sudo perf test

これで（ほとんど）全ての項目がOkになるようにしておくこと。

デバッグシンボルつきの rm(1) を作る

$ apt-get source coreutils
$ cd coreutils-x.yy
$ CFLAGS="-g3" ./configure
$ make -j8
$ src/rm -h