Pepabo Adovent Calender 3日目の記事です。
@udzura です。こないだDuolingoの話をガッツリしてしまったせいで記事に書くネタがなかったんですが、某ruby-jpで話題に出て気になったので当該の内容について調べてみました。
これで妥当な結果が出ているかどうか、適切なやり方かどうかのツッコミをお待ちしております...。
追記
strace は -c オプションのみだとsystem時間のみなので、ファイルシステム操作の全体の時間を計測するには -w オプションが必要だというご指摘がありました！
全体に初稿と比べて計測しなおしています。
環境の準備
ホスト
- VirtualBox上のUbuntu Bionicの kernel 5.0 を利用します。
ゲストコンテナの作成
FROM debian:10-slim
RUN apt install curl strace rsync gnupg2 ruby ruby-dev \
libxml2-dev libxslt-dev zlib1g-dev libsqlite3-dev nodejs && \
gem install bundler && \
( curl -sS https://dl.yarnpkg.com/debian/pubkey.gpg | apt-key add - ) && \
( echo "deb https://dl.yarnpkg.com/debian/ stable main" | tee /etc/apt/sources.list.d/yarn.list ) && \
apt update && \
apt install yarn
ENV RAILS_ENV production
こういう感じのDockerfileを作成します。
以下のようにホストの一部を bind mount した上で、 /app1 /app2 それぞれに全く同じRailsのアプリを構築します。今回は、 rails 6.0.1 で rails new したばかりのものを用意します。
docker run --privileged -ti -v /home/vagrant/app1:/app1 udzura/pepabo-calender-sample bash
こうすると、 /app1 はホストと同じ ext4 ファイルシステム、 /app2 は overlay ファイルシステム、他の条件は同じ環境が作れます。
root@0a78c58c2694:/# stat -f /app1
File: "/app1"
ID: ac226b50631a0a89 Namelen: 255 Type: ext2/ext3 # と表示されてしまう
...
root@0a78c58c2694:/# mount | grep /app1
/dev/sda1 on /app1 type ext4 (rw,relatime)
root@0a78c58c2694:/# stat -f /app2
File: "/app2"
ID: ac226b50631a0a89 Namelen: 255 Type: overlayfs
...
また、gem類はbundler経由で /app$N/vendor/bundle にインストールし同じファイルシステムに存在させます。
計測の手順
事前に、ホスト側のdenrty/inodeキャッシュをすべて破棄します。
sudo sh -c 'echo 3 > /proc/sys/vm/drop_caches'
その上でコンテナ側で以下のコマンドをそれぞれ実施し、 rails runner を起動させ単純な処理を行わせます。
追記: これ以降、初稿と比べて strace の結果はすべて -w オプションを追加して更新しています。
( cd /app1; strace -cfw bin/rails runner 'puts Rails::VERSION::STRING' ) ( cd /app2; strace -cfw bin/rails runner 'puts Rails::VERSION::STRING' )
結果
まず生のstraceの結果を以下に貼ります。
ただ、このままだとタイマースレッドの内部で使われている（ですよね？） poll(2) が支配的なので、ファイルシステムの操作系システムコールに絞ってもう一度測ります。
( cd /app1; strace -cfw -eopen,openat,read,write,close,stat,lstat,access,fstat,fcntl,ioctl,getdents64 bin/rails runner 'puts Rails::VERSION::STRING' ) ( cd /app2; strace -cfw -eopen,openat,read,write,close,stat,lstat,access,fstat,fcntl,ioctl,getdents64 bin/rails runner 'puts Rails::VERSION::STRING' )
ext4
% time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 32.17 1.287973 50 25462 160 lstat 29.44 1.178614 248 4738 4 read 17.74 0.710357 121 5833 1680 openat 5.24 0.209720 50 4157 close 4.76 0.190622 47 4000 fstat 4.68 0.187523 75 2490 350 stat 2.34 0.093868 45 2046 fcntl 2.27 0.090997 44 2030 2026 ioctl 1.34 0.053530 125 428 getdents64 0.01 0.000211 52 4 2 access 0.00 0.000142 47 3 write ------ ----------- ----------- --------- --------- ---------------- 100.00 4.003556 51191 4222 total
overlayfs
% time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 35.27 1.525725 59 25462 160 lstat 26.56 1.149017 242 4735 2 read 16.55 0.716034 122 5833 1680 openat 5.48 0.237068 57 4157 close 5.31 0.229482 57 4000 fstat 4.54 0.196336 78 2490 350 stat 2.50 0.108297 53 2030 2026 ioctl 2.49 0.107764 52 2046 fcntl 1.29 0.055666 130 428 getdents64 0.01 0.000225 56 4 2 access 0.00 0.000084 83 1 write ------ ----------- ----------- --------- --------- ---------------- 100.00 4.325698 51186 4220 total
次が、lstat,openat,read,getdents64(12/4 追記)に絞った 50回 の最大/最小/平均消費時間です。
こういうスクリプト を実行して計測しています。
ext4
------------------------
openat read lstat getdents64
AVG: 0.72845068 1.21160682 1.24938920 0.04721996
MAX: 1.05511000 1.68140700 2.08819100 0.08118800
MIN: 0.45633100 0.94886000 0.17389800 0.02756000
overlayfs
openat read lstat getdents64 AVG: 0.81789664 1.33113000 1.67242892 0.05575284 MAX: 1.20938100 1.84313600 2.71643400 0.08448400 MIN: 0.50309500 1.08326800 0.68068100 0.03279700
overlayfsにおいて若干の上振れが観測できるようです。ただし、かなり幅があります。
これを見ると平均はともかく、ばらつきの傾向も違うようにも予想されるので、回数を増やしてヒストグラムとかにするともっと面白いのかなあなどと思います。
ところで
各種キャッシュがスラブに乗った状態ではあまり差が出ない結果となります。というよりさらにバラついて、ファイルシステムよりヒット率をあげたほうがい良さそうという風になります。
root@0a78c58c2694:/# ( cd /app1; strace -cfw -eopen,openat,read,write,close,stat,lstat,access,fstat,fcntl,ioctl,getdents64 bin/rails runner 'puts Rails::VERSION::STRING' ) strace: Process 3435 attached strace: Process 3436 attached 6.0.1 % time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 49.51 1.445510 56 25462 160 lstat 11.73 0.342558 58 5833 1680 openat 9.89 0.288693 60 4738 4 read 8.12 0.236989 57 4157 close 7.63 0.222684 55 4000 fstat 4.63 0.135284 54 2490 350 stat 4.20 0.122545 59 2046 fcntl 3.44 0.100308 49 2030 2026 ioctl 0.85 0.024687 57 428 getdents64 0.00 0.000092 46 2 write 0.00 0.000085 21 4 2 access ------ ----------- ----------- --------- --------- ---------------- 100.00 2.919436 51190 4222 total
root@0a78c58c2694:/# ( cd /app2; strace -cfw -eopen,openat,read,write,close,stat,lstat,access,fstat,fcntl,ioctl,getdents64 bin/rails runner 'puts Rails::VERSION::STRING' ) strace: Process 3428 attached strace: Process 3429 attached 6.0.1 % time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 49.30 1.378959 54 25462 160 lstat 12.99 0.363430 62 5833 1680 openat 9.63 0.269296 56 4738 4 read 7.58 0.211899 50 4157 close 7.42 0.207520 51 4000 fstat 5.17 0.144577 58 2490 350 stat 3.60 0.100618 49 2046 fcntl 3.53 0.098801 48 2030 2026 ioctl 0.76 0.021386 49 428 getdents64 0.02 0.000439 109 4 2 access 0.00 0.000068 34 2 write ------ ----------- ----------- --------- --------- ---------------- 100.00 2.796993 51190 4222 total
考察
- 前提としてマイクロベンチマークなので参考程度にしかならない
- ~試行回数も少ない~ -> 追記で少し増やした
- それでもopenat, lstat, getdents64などシステムコールによってoverlayfsではオーバーヘッドがある模様？
- 差が少ないものもある
- overlayfsとext4ぐらいの差だと、ファイルシステム側キャッシュの方が影響が大きい
- なので、例えばアプリケーションをKubernetesでいう volume にしてしまうと、ホスト側では同じファイルを見つづけることができると思う（要検証）ので、そういう形で起動時間やパフォーマンスを改善することは考えられそう
非常に大雑把なので書いていて恐ろしくなったんですが、突っ込みください！
明日は @kenchan による M5Stackの中にpixelaの草を出現させる です。
