ローファイ日記

出てくるコード片、ぼくが書いたものは断りがない場合 MIT License としています http://udzura.mit-license.org/

ext4とoverlayfsのシステムコール速度の比較をしようとした

Pepabo Adovent Calender 3日目の記事です。

qiita.com

@udzura です。こないだDuolingoの話をガッツリしてしまったせいで記事に書くネタがなかったんですが、某ruby-jpで話題に出て気になったので当該の内容について調べてみました。

これで妥当な結果が出ているかどうか、適切なやり方かどうかのツッコミをお待ちしております...。

追記

strace は -c オプションのみだとsystem時間のみなので、ファイルシステム操作の全体の時間を計測するには -w オプションが必要だというご指摘がありました!

hiboma.hatenadiary.jp

全体に初稿と比べて計測しなおしています。

環境の準備

ホスト

ゲストコンテナの作成

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の結果を以下に貼ります。

app1.log · GitHub

ただ、このままだとタイマースレッドの内部で使われている(ですよね?) 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の草を出現させる です。